### 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: <kamailio/kamailio/issues/3...@github.com>_______________________________________________
Kamailio (SER) - Development Mailing List
To unsubscribe send an email to sr-dev-le...@lists.kamailio.org
