### Description During the process of using version 5.7.4 of Kamailio, I found that the $conid cannot be correctly obtained in the TCP: closed routing block of the TCP module event_route. I am certain that it is normal in version 5.4.8. ### Troubleshooting ``` pv [pv_core.c:2725]: pv_get_tcpconn_id() ``` #### Reproduction The test scenario initiated a register registration process for me, and after completing the disconnection of the TCP connection, triggered this event. #### Log Messages <!-- The following are the main debug logs for testing, and I have added some of them myself. --> ``` 2024-02-26T01:35:55.902002512Z 52(98) DEBUG: <core> [core/receive.c:635]: receive_msg(): cleaning up 2024-02-26T01:35:55.902034482Z 52(98) DEBUG: <core> [core/tcp_read.c:280]: tcp_read_data(): EOF on connection 0x7f99a1546a80 (state: 0, flags: c018) - FD 24, bytes 0, rd-flags 10000 ([12.0.1.6]:15821 -> [12.0.1.6]:5060)52(98) DEBUG: <core> [core/tcp_read.c:343]: tcp_read(): read 0 bytes: 2024-02-26T01:35:55.902051542Z 2024-02-26T01:35:55.902058282Z 52(98) DEBUG: <core> [core/tcp_read.c:1532]: tcp_read_req(): read= 0 bytes, parsed=0, state=0, error=1 2024-02-26T01:35:55.902063282Z 52(98) DEBUG: <core> [core/tcp_read.c:1534]: tcp_read_req(): last char=0x00, parsed msg= 2024-02-26T01:35:55.902069402Z 2024-02-26T01:35:55.902074032Z 52(98) DEBUG: <core> [core/tcp_read.c:1544]: tcp_read_req(): EOF 2024-02-26T01:35:55.902101372Z 52(98) DEBUG: <core> [core/io_wait.h:598]: io_watch_del(): DBG: io_watch_del (0x559e8a029740, 24, -1, 0x10) fd_no=2 called 2024-02-26T01:35:55.902153162Z 52(98) DEBUG: <core> [core/tcp_read.c:1927]: handle_io(): removing from list 0x7f99a1546a80 id 2 fd 24, state 2, flags c018, main fd 134, refcnt 2 ([12.0.1.6]:15821 -> [12.0.1.6]:5060) 2024-02-26T01:35:55.902168112Z 52(98) DEBUG: <core> [core/tcp_read.c:1702]: release_tcpconn(): releasing con 0x7f99a1546a80, state -1, fd=24, id=2 ([12.0.1.6]:15821 -> [12.0.1.6]:5060) 2024-02-26T01:35:55.902173372Z 52(98) DEBUG: <core> [core/tcp_read.c:1705]: release_tcpconn(): extra_data (nil) 2024-02-26T01:35:55.902208402Z 83(129) DEBUG: <core> [core/tcp_main.c:3747]: handle_tcp_child(): reader response= 7f99a1546a80, -1 from 1 2024-02-26T01:35:55.902224742Z 83(129) DEBUG: <core> [core/tcp_main.c:3904]: handle_tcp_child(): case CONN_EOF tcp_emit_closed_event before 5 2024-02-26T01:35:55.902229802Z 83(129) DEBUG: <core> [core/tcp_main.c:3671]: tcp_emit_closed_event(): TCP closed event creation triggered (reason: 0) 2024-02-26T01:35:55.902318572Z 83(129) DEBUG: tcpops [tcpops.c:311]: tcpops_handle_tcp_closed(): received TCP closed event 2024-02-26T01:35:55.902331352Z 83(129) DEBUG: tcpops [tcpops.c:261]: tcpops_tcp_closed_run_route(): event reason id: 0 rt: 1 2024-02-26T01:35:55.902335132Z 83(129) ERROR: tcpops [tcpops.c:278]: tcpops_tcp_closed_run_route(): run_top_route() before tev->id: 2 2024-02-26T01:35:55.902480972Z 83(129) DEBUG: <core> [core/tcp_main.c:1713]: _tcpconn_find(): 2 port 0 2024-02-26T01:35:55.902493872Z 83(129) DEBUG: pv [pv_core.c:2725]: pv_get_tcpconn_id(): no conid 2024-02-26T01:35:55.902498762Z 83(129) DEBUG: pv [pv_core.c:2726]: pv_get_tcpconn_id(): msg->rcv.proto_reserved1: 2 2024-02-26T01:35:55.902503592Z 83(129) DEBUG: <core> [core/tcp_main.c:1713]: _tcpconn_find(): 2 port 0 2024-02-26T01:35:55.902508262Z 83(129) DEBUG: <core> [core/pvapi.c:1418]: pv_printf_mode(): final buffer length 111 2024-02-26T01:35:55.902513422Z 83(129) ERROR: <script>: tcp connection closed conid: (<null>), tcp(conid): <null>, Ri: 12.0.1.185, Rp: 5060 , si: 12.0.1.6 , sp: 15821 2024-02-26T01:35:55.902607692Z 83(129) DEBUG: <core> [core/tcp_main.c:1713]: _tcpconn_find(): 2 port 0 2024-02-26T01:35:55.902625622Z 83(129) DEBUG: pv [pv_core.c:2725]: pv_get_tcpconn_id(): no conid 2024-02-26T01:35:55.902630672Z 83(129) DEBUG: pv [pv_core.c:2726]: pv_get_tcpconn_id(): msg->rcv.proto_reserved1: 2 2024-02-26T01:35:55.902635822Z 83(129) ERROR: tcpops [tcpops.c:280]: tcpops_tcp_closed_run_route(): run_top_route() after tev->id: 2 2024-02-26T01:35:58.777642759Z 41(87) DEBUG: ims_dialog [dlg_handlers.c:2026]: print_all_dlgs(): ********************41(87) DEBUG: ims_dialog [dlg_handlers.c:2027]: print_all_dlgs(): printing 65536 dialogs ``` #### 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). --> ``` my test script block event_route[tcp:closed] { xlog("L_ERR", "$proto connection closed conid: ($conid), tcp(conid): $tcp(conid), Ri: $Ri, Rp: $Rp , si: $si , sp: $sp\n"); } file: src/modules/pv/pv_core.c int pv_get_tcpconn_id(struct sip_msg *msg, pv_param_t *param, pv_value_t *res) { ... if((con = tcpconn_get(msg->rcv.proto_reserved1, 0, 0, 0, 0)) == NULL) // return false { LM_DBG("no conid\n"); //additional custom log LM_DBG("msg->rcv.proto_reserved1: %d\n",msg->rcv.proto_reserved1); return pv_get_null(msg, param, res); } .... } file: src/core/tcp_main.c struct tcp_connection *tcpconn_lookup(int id, struct ip_addr *ip, int port, union sockaddr_union *local_addr, int try_local_port, ticks_t timeout) { ... if(unlikely(c == NULL)) { c = _tcpconn_find(id, ip, port, &local_ip, local_port); // retrun c == null } ... } struct tcp_connection *_tcpconn_find( int id, struct ip_addr *ip, int port, struct ip_addr *l_ip, int l_port) { ... if(likely(id)) { hash = tcp_id_hash(id); for(c = tcpconn_id_hash[hash]; c; c = c->id_next) { //tcpconn_id_hash find c is null #ifdef EXTRA_DEBUG LM_DBG("c=%p, c->id=%d, port=%d\n", c, c->id, c->rcv.src_port); print_ip("ip=", &c->rcv.src_ip, "\n"); #endif .... } inline static int tcpconn_try_unhash(struct tcp_connection *tcpconn) { ... _tcpconn_detach(tcpconn); //executed ... lock_release(&tcpconn->write_lock); ... } static inline void _tcpconn_detach(struct tcp_connection *c) { ... tcpconn_listrm(tcpconn_id_hash[c->id_hash], c, id_next, id_prev); //remove c ... } ``` ### Possible Solutions <!-- Based on the log: 2024-02-26T01:35:55.902229802Z 83(129) DEBUG: <core> [core/tcp_main.c:3671]: tcp_emit_closed_event(): TCP closed event creation triggered (reason: 0) 2024-02-26T01:35:55.902224742Z 83(129) DEBUG: <core> [core/tcp_main.c:3904]: handle_tcp_child(): case CONN_EOF tcp_emit_closed_event before 5 locate the relevant code: before: tcp_emit_closed_event(tcpconn); if(tcpconn_try_unhash(tcpconn)) tcpconn_put(tcpconn); LM_DBG("case CONN_EOF tcp_emit_closed_event before 5\n"); // custom log tcp_emit_closed_event(tcpconn); tcpconn_put_destroy(tcpconn); /* deref & delete if refcnt==0 */ try fix: after: tcp_emit_closed_event(tcpconn); //change execute order,trigger first and erase later if(tcpconn_try_unhash(tcpconn)) tcpconn_put(tcpconn); LM_DBG("case CONN_EOF tcp_emit_closed_event before 5\n"); // custom log //tcp_emit_closed_event(tcpconn); // tcpconn_put_destroy(tcpconn); /* deref & delete if refcnt==0 */ I'm not sure if this change will cause any other issues, but the close event can be triggered normally during runtime, and other events should have similar issues that require adjusting the order. Is there any other better solution? --> ### Additional Information * **Kamailio Version** - output of `kamailio -v` ``` version: kamailio 5.7.4 (x86_64/linux) 9920d9-dirty flags: , EXTRA_DEBUGUSE_TCP, USE_TLS, USE_SCTP, TLS_HOOKS, USE_RAW_SOCKS, DISABLE_NAGLE, USE_MCAST, DNS_IP_HACK, SHM_MMAP, PKG_MALLOC, MEM_JOIN_FREE, 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_BLOCKLIST, HAVE_RESOLV_RES, TLS_PTHREAD_MUTEX_SHARED ADAPTIVE_WAIT_LOOPS 1024, MAX_RECV_BUFFER_SIZE 262144, MAX_URI_SIZE 1024, BUF_SIZE 65535, DEFAULT PKG_SIZE 8MB poll method support: poll, epoll_lt, epoll_et, sigio_rt, select. id: 9920d9 -dirty compiled on 09:59:52 Feb 26 2024 with gcc 7.5.0 ``` -- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/3767 You are receiving this because you are subscribed to this thread. Message ID: &lt;kamailio/kamailio/issues/3767(a)github.com&gt;