Based on comment:
https://github.com/kamailio/kamailio/issues/171#issuecomment-418175840
I gave event_route [tcp:closed] a try:
event_route [tcp:closed] { # Handle TCP connection close xlog("L_INFO", "$proto connection closed ($conid)\n"); }
Nothing comes to syslog when I quit my baresip UA that according to wireshark closes its TCP connection after un-registration (fin - fin - ack).
I have not set closed_event param, because according to README, it defaults to 1.
Can you list the tcp connections via rpc and see if the one you expect to be closed is still listed there?
I haven't added the feature and not used it so far, but it might be the cleanup timer routing for tcp connections that trigger the event route.
Cheers, Daniel
On 04.09.18 11:07, Juha Heinanen wrote:
Based on comment:
https://github.com/kamailio/kamailio/issues/171#issuecomment-418175840
I gave event_route [tcp:closed] a try:
event_route [tcp:closed] { # Handle TCP connection close xlog("L_INFO", "$proto connection closed ($conid)\n"); }
Nothing comes to syslog when I quit my baresip UA that according to wireshark closes its TCP connection after un-registration (fin - fin - ack).
I have not set closed_event param, because according to README, it defaults to 1.
Kamailio (SER) - Users Mailing List sr-users@lists.kamailio.org https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
On 04.09.18 11:41, Juha Heinanen wrote:
Daniel-Constantin Mierla writes:
Can you list the tcp connections via rpc and see if the one you expect to be closed is still listed there?
core.tcp_list after quiting baresip shows that the tcp connection has been removed, i.e., is not anymore in the list
Can you test with latest master and debug=3, then send all debug messages from tcp connect to disconnect?
I just pushed a commit to add debug messages that can help troubleshoot if the execution of relevant code in tcpops happens or not.
Cheers, Daniel
Daniel-Constantin Mierla writes:
Can you test with latest master and debug=3, then send all debug messages from tcp connect to disconnect?
Below is the debug. First REGISTER comes at 13:13:26 and un-REGISTER at 13:13:29 followed by tcp connection close.
-- Juha
Sep 4 13:13:26 char /usr/bin/sip-proxy[15893]: DEBUG: <core> [core/ip_addr.c:229]: print_ip(): tcpconn_new: new tcp connection: 192.168.43.107 Sep 4 13:13:26 char /usr/bin/sip-proxy[15893]: DEBUG: <core> [core/tcp_main.c:999]: tcpconn_new(): on port 43822, type 2 Sep 4 13:13:26 char /usr/bin/sip-proxy[15893]: DEBUG: <core> [core/tcp_main.c:1305]: tcpconn_add(): hashes: 23:2680:2459, 4 Sep 4 13:13:26 char /usr/bin/sip-proxy[15893]: DEBUG: <core> [core/io_wait.h:380]: io_watch_add(): DBG: io_watch_add(0x55561b5d2d40, 69, 2, 0x7f64144e38b0), fd_no=57 Sep 4 13:13:26 char /usr/bin/sip-proxy[15893]: DEBUG: <core> [core/io_wait.h:602]: io_watch_del(): DBG: io_watch_del (0x55561b5d2d40, 69, -1, 0x0) fd_no=58 called Sep 4 13:13:26 char /usr/bin/sip-proxy[15893]: DEBUG: <core> [core/tcp_main.c:4196]: handle_tcpconn_ev(): sending to child, events 1 Sep 4 13:13:26 char /usr/bin/sip-proxy[15893]: DEBUG: <core> [core/tcp_main.c:3847]: send2child(): checking per-socket generic workers (15845/27..15874/34) [tcp:192.168.43.107:5060] Sep 4 13:13:26 char /usr/bin/sip-proxy[15893]: DEBUG: <core> [core/tcp_main.c:3875]: send2child(): selected tcp worker 0 27(15845) for activity on [tcp:192.168.43.107:5060], 0x7f64144e38b0 Sep 4 13:13:26 char /usr/bin/sip-proxy[15845]: DEBUG: <core> [core/tcp_read.c:1740]: handle_io(): received n=8 con=0x7f64144e38b0, fd=12 Sep 4 13:13:26 char /usr/bin/sip-proxy[15845]: DEBUG: <core> [core/tcp_read.c:1540]: tcp_read_req(): content-length=0 Sep 4 13:13:26 char /usr/bin/sip-proxy[15845]: DEBUG: <core> [core/receive.c:232]: receive_msg(): --- received sip message - request - call-id: [b89bf3310da039ee] - cseq: [59445 REGISTER] Sep 4 13:13:26 char /usr/bin/sip-proxy[15845]: DEBUG: <core> [core/receive.c:287]: receive_msg(): preparing to run routing scripts... Sep 4 13:13:26 char /usr/bin/sip-proxy[15845]: DEBUG: <core> [core/tcp_main.c:2225]: tcpconn_send_put(): send from reader (15845 (27)), reusing fd Sep 4 13:13:26 char /usr/bin/sip-proxy[15845]: DEBUG: <core> [core/tcp_main.c:2460]: tcpconn_do_send(): sending... Sep 4 13:13:26 char /usr/bin/sip-proxy[15845]: DEBUG: <core> [core/tcp_main.c:2494]: tcpconn_do_send(): after real write: c= 0x7f64144e38b0 n=519 fd=12 Sep 4 13:13:26 char /usr/bin/sip-proxy[15845]: DEBUG: <core> [core/tcp_main.c:2495]: tcpconn_do_send(): buf=#012SIP/2.0 401 Unauthorized ... Sep 4 13:13:26 char /usr/bin/sip-proxy[15845]: DEBUG: <core> [core/receive.c:449]: receive_msg(): cleaning up Sep 4 13:13:26 char /usr/bin/sip-proxy[15845]: DEBUG: <core> [core/io_wait.h:380]: io_watch_add(): DBG: io_watch_add(0x55561b61bf40, 12, 2, 0x7f64144e38b0), fd_no=1 Sep 4 13:13:29 char /usr/bin/sip-proxy[15845]: DEBUG: <core> [core/tcp_read.c:1540]: tcp_read_req(): content-length=0 Sep 4 13:13:29 char /usr/bin/sip-proxy[15845]: DEBUG: <core> [core/receive.c:232]: receive_msg(): --- received sip message - request - call-id: [b89bf3310da039ee] - cseq: [59447 REGISTER] Sep 4 13:13:29 char /usr/bin/sip-proxy[15845]: DEBUG: <core> [core/socket_info.c:559]: grep_sock_info(): checking if host==us: 14==14 && [192.168.43.107] == [192.168.43.107] Sep 4 13:13:29 char /usr/bin/sip-proxy[15845]: DEBUG: <core> [core/socket_info.c:566]: grep_sock_info(): checking if port 5060 (advertise 0) matches port 5060 Sep 4 13:13:29 char /usr/bin/sip-proxy[15845]: DEBUG: <core> [core/tcp_main.c:2225]: tcpconn_send_put(): send from reader (15845 (27)), reusing fd Sep 4 13:13:29 char /usr/bin/sip-proxy[15845]: DEBUG: <core> [core/tcp_main.c:2460]: tcpconn_do_send(): sending... Sep 4 13:13:29 char /usr/bin/sip-proxy[15845]: DEBUG: <core> [core/tcp_main.c:2494]: tcpconn_do_send(): after real write: c= 0x7f64144e38b0 n=417 fd=12 Sep 4 13:13:29 char /usr/bin/sip-proxy[15845]: DEBUG: <core> [core/tcp_main.c:2495]: tcpconn_do_send(): buf=#012SIP/2.0 200 OK ... Sep 4 13:13:29 char /usr/bin/sip-proxy[15845]: DEBUG: <core> [core/receive.c:449]: receive_msg(): cleaning up Sep 4 13:13:29 char /usr/bin/sip-proxy[15845]: DEBUG: <core> [core/tcp_read.c:198]: tcp_emit_closed_event(): TCP closed event creation triggered (reason: 0) Sep 4 13:13:29 char /usr/bin/sip-proxy[15845]: DEBUG: <core> [core/tcp_read.c:206]: tcp_emit_closed_event(): no callback registering for handling TCP closed event Sep 4 13:13:29 char /usr/bin/sip-proxy[15845]: DEBUG: <core> [core/tcp_read.c:315]: tcp_read_data(): EOF on 0x7f64144e38b0, FD 12 ([192.168.43.107]:43822 -> Sep 4 13:13:29 char /usr/bin/sip-proxy[15845]: DEBUG: <core> [core/tcp_read.c:316]: tcp_read_data(): -> [192.168.43.107]:5060) Sep 4 13:13:29 char /usr/bin/sip-proxy[15845]: DEBUG: <core> [core/tcp_read.c:1507]: tcp_read_req(): EOF Sep 4 13:13:29 char /usr/bin/sip-proxy[15845]: DEBUG: <core> [core/io_wait.h:602]: io_watch_del(): DBG: io_watch_del (0x55561b61bf40, 12, -1, 0x10) fd_no=2 called Sep 4 13:13:29 char /usr/bin/sip-proxy[15845]: DEBUG: <core> [core/tcp_read.c:1661]: release_tcpconn(): releasing con 0x7f64144e38b0, state -1, fd=12, id=4 ([192.168.43.107]:43822 -> [192.168.43.107]:5060) Sep 4 13:13:29 char /usr/bin/sip-proxy[15845]: DEBUG: <core> [core/tcp_read.c:1665]: release_tcpconn(): extra_data (nil) Sep 4 13:13:29 char /usr/bin/sip-proxy[15893]: DEBUG: <core> [core/tcp_main.c:3307]: handle_tcp_child(): reader response= 7f64144e38b0, -1 from 0
I had not loaded tcpops module. Should work after that. How about checking that all event routes in config have corresponding modules loaded?
-- Juha
I loaded tcpops module but still nothing to syslog from:
event_route [tcp:close]
Debug (below) now shows this:
Sep 4 14:07:52 char /usr/bin/sip-proxy[6487]: DEBUG: tcpops [tcpops.c:233]: tcpops_handle_tcp_closed(): received TCP closed event Sep 4 14:07:52 char /usr/bin/sip-proxy[6487]: DEBUG: tcpops [tcpops.c:207]: tcpops_tcp_closed_run_route(): event reason id: 0 rt: 10
-- Juha
----------------------
Sep 4 14:07:41 char /usr/bin/sip-proxy[6487]: DEBUG: <core> [core/tcp_main.c:2225]: tcpconn_send_put(): send from reader (6487 (27)), reusing fd Sep 4 14:07:41 char /usr/bin/sip-proxy[6487]: DEBUG: <core> [core/tcp_main.c:2460]: tcpconn_do_send(): sending... Sep 4 14:07:41 char /usr/bin/sip-proxy[6487]: DEBUG: <core> [core/tcp_main.c:2494]: tcpconn_do_send(): after real write: c= 0x7f7fad11ed00 n=779 fd=12 Sep 4 14:07:41 char /usr/bin/sip-proxy[6487]: DEBUG: <core> [core/tcp_main.c:2495]: tcpconn_do_send(): buf=#012SIP/2.0 200 OK ... Sep 4 14:07:41 char /usr/bin/sip-proxy[6487]: DEBUG: <core> [core/receive.c:345]: receive_msg(): request-route executed in: 90073 usec Sep 4 14:07:41 char /usr/bin/sip-proxy[6487]: DEBUG: <core> [core/receive.c:449]: receive_msg(): cleaning up Sep 4 14:07:47 char /usr/bin/sip-proxy[6487]: DEBUG: <core> [core/io_wait.h:602]: io_watch_del(): DBG: io_watch_del (0x558dca3d4f40, 12, -1, 0x10) fd_no=2 called Sep 4 14:07:47 char /usr/bin/sip-proxy[6487]: DEBUG: <core> [core/tcp_read.c:1661]: release_tcpconn(): releasing con 0x7f7fad11ed00, state 1, fd=12, id=4 ([192.168.43.107]:44522 -> [192.168.43.107]:5060) Sep 4 14:07:47 char /usr/bin/sip-proxy[6487]: DEBUG: <core> [core/tcp_read.c:1665]: release_tcpconn(): extra_data (nil) Sep 4 14:07:47 char /usr/bin/sip-proxy[6529]: DEBUG: <core> [core/tcp_main.c:3307]: handle_tcp_child(): reader response= 7f7fad11ed00, 1 from 0 Sep 4 14:07:47 char /usr/bin/sip-proxy[6529]: DEBUG: <core> [core/io_wait.h:380]: io_watch_add(): DBG: io_watch_add(0x558dca38bd40, 68, 2, 0x7f7fad11ed00), fd_no=56 Sep 4 14:07:47 char /usr/bin/sip-proxy[6529]: DEBUG: <core> [core/tcp_main.c:3434]: handle_tcp_child(): CONN_RELEASE 0x7f7fad11ed00 refcnt= 1 Sep 4 14:07:52 char /usr/bin/sip-proxy[6529]: DEBUG: <core> [core/io_wait.h:602]: io_watch_del(): DBG: io_watch_del (0x558dca38bd40, 68, -1, 0x0) fd_no=57 called Sep 4 14:07:52 char /usr/bin/sip-proxy[6529]: DEBUG: <core> [core/tcp_main.c:4196]: handle_tcpconn_ev(): sending to child, events 2001 Sep 4 14:07:52 char /usr/bin/sip-proxy[6529]: DEBUG: <core> [core/tcp_main.c:3847]: send2child(): checking per-socket generic workers (6487/27..6507/34) [tcp:192.168.43.107:5060] Sep 4 14:07:52 char /usr/bin/sip-proxy[6529]: DEBUG: <core> [core/tcp_main.c:3875]: send2child(): selected tcp worker 0 27(6487) for activity on [tcp:192.168.43.107:5060], 0x7f7fad11ed00 Sep 4 14:07:52 char /usr/bin/sip-proxy[6487]: DEBUG: <core> [core/tcp_read.c:1740]: handle_io(): received n=8 con=0x7f7fad11ed00, fd=12 Sep 4 14:07:52 char /usr/bin/sip-proxy[6487]: DEBUG: <core> [core/tcp_read.c:198]: tcp_emit_closed_event(): TCP closed event creation triggered (reason: 0) Sep 4 14:07:52 char /usr/bin/sip-proxy[6487]: DEBUG: tcpops [tcpops.c:233]: tcpops_handle_tcp_closed(): received TCP closed event Sep 4 14:07:52 char /usr/bin/sip-proxy[6487]: DEBUG: tcpops [tcpops.c:207]: tcpops_tcp_closed_run_route(): event reason id: 0 rt: 10 Sep 4 14:07:52 char /usr/bin/sip-proxy[6487]: DEBUG: <core> [core/action.c:1554]: run_actions(): null action list (rec_level=1) Sep 4 14:07:52 char /usr/bin/sip-proxy[6487]: DEBUG: <core> [core/tcp_read.c:315]: tcp_read_data(): EOF on 0x7f7fad11ed00, FD 12 ([192.168.43.107]:44522 -> Sep 4 14:07:52 char /usr/bin/sip-proxy[6487]: DEBUG: <core> [core/tcp_read.c:316]: tcp_read_data(): -> [192.168.43.107]:5060) Sep 4 14:07:52 char /usr/bin/sip-proxy[6487]: DEBUG: <core> [core/tcp_read.c:1507]: tcp_read_req(): EOF Sep 4 14:07:52 char /usr/bin/sip-proxy[6487]: DEBUG: <core> [core/tcp_read.c:1661]: release_tcpconn(): releasing con 0x7f7fad11ed00, state -1, fd=12, id=4 ([192.168.43.107]:44522 -> [192.168.43.107]:5060) Sep 4 14:07:52 char /usr/bin/sip-proxy[6487]: DEBUG: <core> [core/tcp_read.c:1665]: release_tcpconn(): extra_data (nil) Sep 4 14:07:52 char /usr/bin/sip-proxy[6529]: DEBUG: <core> [core/tcp_main.c:3307]: handle_tcp_child(): reader response= 7f7fad11ed00, -1 from 0
On 04.09.18 13:23, Juha Heinanen wrote:
Juha Heinanen writes:
I loaded tcpops module but still nothing to syslog from:
event_route [tcp:close]
I had typo in above: should be closed instead of close.
This again shows that it would be nice if it would be checked that each event_route has a home.
The event_route was defined for the specific case where its name can be anything and it is a matter of modules to execute some as they need.
The interpreter which is defined in core has no clue about what names can be there. The modules cannot complain if they do not find some event_route blocks that they expect to execute, because if the event route is not found, then there should be noting executed.
Being open source, of course anything is "possible", but how to do it and its complexity may require some consistent analysis to see if affects the flexibility and then expecting relevant development effort to go in each module dealing with event_route blocks.
Cheers, Daniel
Daniel-Constantin Mierla writes:
The event_route was defined for the specific case where its name can be anything and it is a matter of modules to execute some as they need.
The interpreter which is defined in core has no clue about what names can be there. The modules cannot complain if they do not find some event_route blocks that they expect to execute, because if the event route is not found, then there should be noting executed.
Well, kamailio does not start if config includes call of a function defined in a module that is not loaded.
Similarly, modules could register their event routes at load, which would allow the interpreter to detect unknown event routes.
It may be too late to fix this, since too many modules already exists that define event routes.
-- Juha
On 04.09.18 15:46, Juha Heinanen wrote:
Daniel-Constantin Mierla writes:
The event_route was defined for the specific case where its name can be anything and it is a matter of modules to execute some as they need.
The interpreter which is defined in core has no clue about what names can be there. The modules cannot complain if they do not find some event_route blocks that they expect to execute, because if the event route is not found, then there should be noting executed.
Well, kamailio does not start if config includes call of a function defined in a module that is not loaded.
Similarly, modules could register their event routes at load, which would allow the interpreter to detect unknown event routes.
It may be too late to fix this, since too many modules already exists that define event routes.
The difference here is that event_route blocks are only defined, not executed from other route blocks.
You can also define a route[name] that is not executed in another blocks with route(name) and there is nothing happening, because the route block can be executed also from inside the c code with a value that can be built at runtime. One can also execute a route with a variable, like route($var(name)), so there can be no enforcement when a route block that is not executed statically to stop kamailio start up process.
You can eventually start adding to each module to rise errors if ithey don't find the expected event_routes, but must be a modparam, because the behaviour is not to execute event_route blocks if they are not defined. Something like: if modparam is set and event_route blocks are not found, rise error. Given that many modules can execute many event_route blocks in various cases, the modparam has to allow combinations of when to rise error based on what is expected to execute and what is defined...
Again, with open source there are always solutions, but someone has to invest time and find the balance between benefits, complexity and penalties to performances (in this case would be start up time, which might not be that critical). Personally I do not see major benefits to invest a lot if time to update all those modules and take care of all possible documentation just to cover mistyping cases, but if someone whats to do it, merging such features can be considered if there is no major negative impact and they do not change current behaviour.
Cheers, Daniel
Cheers, Daniel
-
Daniel-Constantin Mierla -
Juha Heinanen