### Description
I tried using the Kamailio as a sip capture node, with TCP and captagent sending data to it using HEP3 protocol
#### Reproduction
send sip traffic to the Kamailio node over tcp - hep3
#### SIP Traffic
<!-- If the issue is exposed by processing specific SIP messages, grab them with ngrep or save in a pcap file, then add them next, or attach to issue, or provide a link to download them (e.g., to a pastebin site). -->
``` T 10.62.232.8:59218 -> 172.17.0.2:9060 [AP] HEP3..................................... Y...... . ................ .........
.......
"./.......myhep.....SOPTIONS sip:34.222.33.444:5060 SIP/2.0. Via: SIP/2.0/UDP 34.222.33.444:5060;branch=z9hG4bKadc3.94894fb2.0. To: sip:34.222.33.444:5060. From: sip:dispatcher@localhost;tag=8176c6985887ae1fa077926d61f38185-6330. CSeq: 14 OPTIONS. Call-ID: 524281af251ad3ae-5781@10.62.232.8. Max-Forwards: 70. Content-Length: 0. User-Agent: user. .
ERROR MSG:
############### 8(16359) ERROR: <core> [core/tcp_read.c:1391]: tcp_read_req(): bad request, state=7, error=4 buf: HEP3� parsed: HEP3� ```
### Additional Information
* **Kamailio Version** - output of `kamailio -v`
``` version: kamailio 5.1.0-dev8 (x86_64/linux) flags: STATS: Off, USE_TCP, USE_TLS, USE_SCTP, TLS_HOOKS, DISABLE_NAGLE, USE_MCAST, DNS_IP_HACK, SHM_MEM, SHM_MMAP, PKG_MALLOC, Q_MALLOC, F_MALLOC, TLSF_MALLOC, DBG_SR_MEMORY, USE_FUTEX, FAST_LOCK-ADAPTIVE_WAIT, USE_DNS_CACHE, USE_DNS_FAILOVER, USE_NAPTR, USE_DST_BLACKLIST, HAVE_RESOLV_RES ADAPTIVE_WAIT_LOOPS=1024, MAX_RECV_BUFFER_SIZE 262144, MAX_LISTEN 16, MAX_URI_SIZE 1024, BUF_SIZE 65535, DEFAULT PKG_SIZE 8MB poll method support: poll, epoll_lt, epoll_et, sigio_rt, select. id: unknown compiled on 15:58:15 Nov 1 2017 with gcc 4.9.2 ```
* **Operating System**:
<!-- Details about the operating system, the type: Linux (e.g.,: Debian 8.4, Ubuntu 16.04, CentOS 7.1, ...), MacOS, xBSD, Solaris, ...; Kernel details (output of `uname -a`) -->
``` Linux 15e97661fc7f 4.9.43-17.39.amzn1.x86_64 #1 SMP Fri Sep 15 23:39:41 UTC 2017 x86_64 GNU/Linux ```
I saw it on the master branch updated to 1/11/2017 I also saw it was addressed before, but it still doesn't seem to work for me, am I missing something?
https://github.com/kamailio/kamailio/issues/599
Have you set the nonsip hook parameter for sipcapture module and the event route as show in:
* https://github.com/kamailio/kamailio/commit/4e789387f8cfe72fa9e8d43f9963033d...
Hi, thanks for the prompt reply. Yes I have as far as I can tell:
`#new event sipcapture socket modparam("sipcapture", "nonsip_hook", 1)
...
event_route[sipcapture:request] {
xlog("HEP Request!\n"); xlog("received sipcapture request from $si:$sp\n"); xlog("HEP VERSION $hep(version) request from $si:$sp\n"); xlog("HEP CHUNK Source IP $hep(0x002) request from $si:$sp\n");
#Is it SIP ? if($hep(0x00b) == 1) {
#Do parsing internal return 1; } else { #If report lets proceed here with payload xlog("HEP CHUNK PAYLOAD $hep(0x00f) request from $si:$sp\n"); return 0; } }`
Did I miss anything?
Can you try with latest master branch, you have to add in kamailio.cfg:
``` tcp_accept_hep3=1 ``` I pushed a patch few hours ago.
Hey, thanks again but it seems that the parser doesn't recognize the key:
0(26767) CRITICAL: <core> [core/cfg.y:3434]: yyerror_at(): parse error in config file /etc/kamailio/kamailio.cfg, line 45, column 16: syntax error
0(26767) CRITICAL: <core> [core/cfg.y:3434]: yyerror_at(): parse error in config file /etc/kamailio/kamailio.cfg, line 45, column 16: unknown config variable 0(26767) CRITICAL: <core> [core/cfg.y:3434]: yyerror_at(): parse error in config file /etc/kamailio/kamailio.cfg, line 45, column 17: ERROR: bad config file (3 errors)
The push on github failed and I haven't checked that terminal before I left. I did it now, can you fetch master again and try?
I tried right now, with the branch set to master and updated. My config global params: ``` ####### Global Parameters #########
debug=1 log_stderror=no
memdbg=5 memlog=5
log_facility=LOG_LOCAL1
fork=yes children=8 tcp_children=5
/* uncomment the next line to disable TCP (default on) */ #disable_tcp=yes
/* IP and port for HEP capturing) */ listen=HOMER_LISTEN_PROTO:HOMER_LISTEN_IF:HOMER_LISTEN_PORT
#Max loops max_while_loops=100
tcp_accept_hep3=1 ```
The error: ``` 7(4964) ERROR: <core> [core/tcp_read.c:1493]: tcp_read_req(): bad request, state=7, error=4 buf: HEP3� parsed: HEP3� ```
Command I am using to run Kamailio: ``` kamailio -P /var/run/kamailio.pid -f /etc/kamailio/kamailio.cfg -DD -E -e ```
The issue I am experiencing seems to persist =/
Can you fetch again latest master, reinstall, set `debug=3` in `kamailio.cfg` and do another test? I just pushed a patch to print more log messages when hep3 packet is received. After doing the test, grab and past here all the messages printed by kamailio when hep3 is received.
``` 10(10188) DEBUG: <core> [core/ip_addr.c:229]: print_ip(): tcpconn_new: new tcp connection: 10.62.232.8 10(10188) DEBUG: <core> [core/tcp_main.c:999]: tcpconn_new(): on port 43128, type 2 10(10188) DEBUG: <core> [core/tcp_main.c:1309]: tcpconn_add(): hashes: 802:943:141, 7 10(10188) DEBUG: <core> [core/io_wait.h:380]: io_watch_add(): DBG: io_watch_add(0xa47840, 20, 2, 0x7f343760d0e0), fd_no=15 10(10188) DEBUG: <core> [core/io_wait.h:602]: io_watch_del(): DBG: io_watch_del (0xa47840, 20, -1, 0x0) fd_no=16 called 10(10188) DEBUG: <core> [core/tcp_main.c:4196]: handle_tcpconn_ev(): sending to child, events 1 10(10188) DEBUG: <core> [core/tcp_main.c:3878]: send2child(): selected tcp worker 1 6(10184) for activity on [tcp:0.0.0.0:9060], 0x7f343760d0e0 6(10184) DEBUG: <core> [core/tcp_read.c:1726]: handle_io(): received n=8 con=0x7f343760d0e0, fd=7 6(10184) DEBUG: <core> [core/tcp_read.c:1276]: tcp_read_hep3(): not HEP3 packet header 6(10184) DEBUG: <core> [core/tcp_read.c:565]: tcp_read_headers(): no clen, p=A 6(10184) ERROR: <core> [core/tcp_read.c:1504]: tcp_read_req(): bad request, state=7, error=4 buf: HEP3� parsed: HEP3� 6(10184) DEBUG: <core> [core/tcp_read.c:1512]: tcp_read_req(): received from: port 43128 6(10184) DEBUG: <core> [core/ip_addr.c:229]: print_ip(): received from: ip10.62.232.8 6(10184) DEBUG: <core> [core/tcp_read.c:1650]: release_tcpconn(): releasing con 0x7f343760d0e0, state -2, fd=7, id=7 ([10.62.232.8]:43128 -> [10.62.232.8]:9060) 6(10184) DEBUG: <core> [core/tcp_read.c:1651]: release_tcpconn(): extra_data (nil) 10(10188) DEBUG: <core> [core/tcp_main.c:3308]: handle_tcp_child(): reader response= 7f343760d0e0, -2 from 1 #### T 10.62.232.8:43128 -> 172.17.0.2:9060 [AP] HEP3......................................Y...........'. ........................>........4F........myhep.....OOP TIONS sip:52.70.156.9:5060 SIP/2.0..Via: SIP/2.0/UDP 34. 233.227.234:5060;branch=z9hG4bK670c.13ed4eb6.0..To: sip: 52.70.156.9:5060..From: sip:dispatcher@localhost;tag=8 176c6985887ae1fa077926d61f38185-b1f6..CSeq: 14 OPTIONS.. Call-ID: 524281af2520c1c5-5778@10.62.232.8..Max-Forwards : 70..Content-Length: 0..User-Agent: Vonage.... #### T 10.62.232.8:43128 -> 172.17.0.2:9060 [AP] HEP3......................................Y...........7# ........................>........"./.......myhep.....SOP TIONS sip:34.235.47.156:5060 SIP/2.0..Via: SIP/2.0/UDP 3 4.233.227.234:5060;branch=z9hG4bKd2f8.4376da97.0..To: si p:34.235.47.156:5060..From: sip:dispatcher@localhost;t ag=8176c6985887ae1fa077926d61f38185-f478..CSeq: 14 OPTIO NS..Call-ID: 524281af2520c194-5778@10.62.232.8..Max-Forw ards: 70..Content-Length: 0..User-Agent: Vonage.... ## T 10.62.232.8:43128 -> 172.17.0.2:9060 [A] HEP3......................................Y...........71 ........................>........"./.......myhep.....SOP TIONS sip:34.235.47.149:5060 SIP/2.0..Via: SIP/2.0/UDP 3 4.233.227.234:5060;branch=z9hG4bKb2f8.1b34cf63.0..To: si p:34.235.47.149:5060..From: sip:dispatcher@localhost;t ag=8176c6985887ae1fa077926d61f38185-09e7..CSeq: 14 OPTIO NS..Call-ID: 524281af2520c196-5778@10.62.232.8..Max-Forw ards: 70..Content-Length: 0..User-Agent: Vonage....HEP3. .....................................Y...........75..... ...................>........4.l.......myhep.....SOPTIONS sip:52.21.108.193:5060 SIP/2.0..Via: SIP/2.0/UDP 34.233 .227.234:5060;branch=z9hG4bKc2f8.1727f1b7.0..To: sip:52. 21.108.193:5060..From: sip:dispatcher@localhost;tag=81 76c6985887ae1fa077926d61f38185-7768..CSeq: 14 OPTIONS..C all-ID: 524281af2520c197-5778@10.62.232.8..Max-Forwards: 70..Content-Length: 0..User-Agent: Vonage....HEP3...... ................................Y...........79.......... ..............>........"..0......myhep.....SOPTIONS sip: 34.192.249.48:5060 SIP/2.0..Via: SIP/2.0/UDP 34.233.227. 234:5060;branch=z9hG4bK96f8.6a99ee14.0..To: sip:34.192.2 49.48:5060..From: sip:dispatcher@localhost;tag=8176c69 85887ae1fa077926d61f38185-fb1b..CSeq: 14 OPTIONS..Call-I D: 524281af2520c19b-5778@10.62.232.8..Max-Forwards: 70.. Content-Length: 0..User-Agent: Vonage....HEP3........... ...........................Y...........7=............... .........>........4.l.......myhep.....UOPTIONS ```
It appears that attempting to match the first chars with `HEP3` fail. I pushed another patch to print what's there. Can you pull master and try again?
``` 6(15351) DEBUG: <core> [core/tcp_read.c:1513]: tcp_read_req(): received from: port 38054 6(15351) DEBUG: <core> [core/ip_addr.c:229]: print_ip(): received from: ip10.62.232.8 6(15351) DEBUG: <core> [core/tcp_read.c:1651]: release_tcpconn(): releasing con 0x7f6a2f5890e0, state -2, fd=7, id=2 ([10.62.232.8]:38054 -> [10.62.232.8]:9060) 6(15351) DEBUG: <core> [core/tcp_read.c:1652]: release_tcpconn(): extra_data (nil) 10(15357) DEBUG: <core> [core/tcp_main.c:3308]: handle_tcp_child(): reader response= 7f6a2f5890e0, -2 from 1 10(15357) DEBUG: <core> [core/ip_addr.c:229]: print_ip(): tcpconn_new: new tcp connection: 10.62.232.8 10(15357) DEBUG: <core> [core/tcp_main.c:999]: tcpconn_new(): on port 38056, type 2 10(15357) DEBUG: <core> [core/tcp_main.c:1309]: tcpconn_add(): hashes: 3979:3846:3108, 3 10(15357) DEBUG: <core> [core/io_wait.h:380]: io_watch_add(): DBG: io_watch_add(0xa47bc0, 20, 2, 0x7f6a2f5890e0), fd_no=15 10(15357) DEBUG: <core> [core/io_wait.h:602]: io_watch_del(): DBG: io_watch_del (0xa47bc0, 20, -1, 0x0) fd_no=16 called 10(15357) DEBUG: <core> [core/tcp_main.c:4196]: handle_tcpconn_ev(): sending to child, events 1 10(15357) DEBUG: <core> [core/tcp_main.c:3878]: send2child(): selected tcp worker 2 7(15353) for activity on [tcp:0.0.0.0:9060], 0x7f6a2f5890e0 7(15353) DEBUG: <core> [core/tcp_read.c:1727]: handle_io(): received n=8 con=0x7f6a2f5890e0, fd=7 7(15353) DEBUG: <core> [core/tcp_read.c:1277]: tcp_read_hep3(): not HEP3 packet header (443): H E P 3 / 48 45 50 33 7(15353) DEBUG: <core> [core/tcp_read.c:565]: tcp_read_headers(): no clen, p=A ```
Ahh, a trivial mistake in the condition matching `HEP3` that I haven't noticed before. A patch for it was pushed. Can you try again?
The patch fixed the problem! +1 Though there seems to be the following error: ``` 8(20574) ERROR: <core> [core/tcp_read.c:1534]: tcp_read_req(): content length not present or unparsable ``` which makes sense because after the word HEP3 there are only dots
You have to set:
``` tcp_accept_no_cl=yes ```
Do you get everything working (handling properly HEP3 packets over tcp)?
Looks like it, I don't see the data being added to the DB on port 3306, have to further debug it. Thanks for the fix and for your time. ``` event_route[sipcapture:request] {
xlog("HEP Request!\n"); xlog("received sipcapture request from $si:$sp\n"); xlog("HEP VERSION $hep(version) request from $si:$sp\n"); xlog("HEP CHUNK Source IP $hep(0x002) request from $si:$sp\n");
#Is it SIP ? if($hep(0x00b) == 1) {
#Do parsing internal return 1; } else { #If report lets proceed here with payload xlog("HEP CHUNK PAYLOAD $hep(0x00f) request from $si:$sp\n"); return 0; } } ``` Those log lines produce an "error" log, kind of misleading
Looking at the code done for UDP HEP3 traffic, it required a follow up after the execution of the event_route. I just pushed a patch for doing it also for tcp. Can you test again?
Works as expected
Closed #1294.
OK, thanks for testing!