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

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

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

Additional Information

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, view it on GitHub, or unsubscribe.
You are receiving this because you are subscribed to this thread.Message ID: <kamailio/kamailio/issues/3767@github.com>