[kamailio/kamailio] ndb_reids module in event_route[tcp:closed] route block error: "no redis context for server" (Issue #3768)
### Description The process of using kamailio prompts the following error： ERROR: ndb_redis [redis_client.c:963]: redisc_exec(): no redis context for server: srvN
I did not encounter similar errors in version 5.4.8, and there were no similar errors in other routing blocks. Suspect that the new core version has unknown logical issues with the routing block of the module in event_route.
<!-- Explain what you did, what you expected to happen, and what actually happened. -->
#### Log Messages
<!-- Check the syslog file and if there are relevant log messages printed by Kamailio, add them next, or attach to issue, or provide a link to download them (e.g., to a pastebin site). -->
``` 2024-02-26T03:39:11.161557654Z 51(97) DEBUG: <core> [core/tcp_read.c:280]: tcp_read_data(): EOF on connection 0x7f24539006a0 (state: 0, flags: c018) - FD 24, bytes 0, rd-flags 10000 ([12.0.1.6]:22827 -> [12.0.1.6]:5060)51(97) DEBUG: <core> [core/tcp_read.c:343]: tcp_read(): read 0 bytes: 2024-02-26T03:39:11.161563494Z 2024-02-26T03:39:11.161567864Z 51(97) DEBUG: <core> [core/tcp_read.c:1532]: tcp_read_req(): read= 0 bytes, parsed=0, state=0, error=1 2024-02-26T03:39:11.161574144Z 51(97) DEBUG: <core> [core/tcp_read.c:1534]: tcp_read_req(): last char=0x00, parsed msg= 2024-02-26T03:39:11.161579134Z 2024-02-26T03:39:11.161584594Z 51(97) DEBUG: <core> [core/tcp_read.c:1544]: tcp_read_req(): EOF 2024-02-26T03:39:11.161598914Z 51(97) DEBUG: <core> [core/io_wait.h:598]: io_watch_del(): DBG: io_watch_del (0x563e1ce29740, 24, -1, 0x10) fd_no=2 called 2024-02-26T03:39:11.161604494Z 51(97) DEBUG: <core> [core/tcp_read.c:1927]: handle_io(): removing from list 0x7f24539006a0 id 1 fd 24, state 2, flags c018, main fd 132, refcnt 2 ([12.0.1.6]:22827 -> [12.0.1.6]:5060) 2024-02-26T03:39:11.161610294Z 51(97) DEBUG: <core> [core/tcp_read.c:1702]: release_tcpconn(): releasing con 0x7f24539006a0, state -1, fd=24, id=1 ([12.0.1.6]:22827 -> [12.0.1.6]:5060) 2024-02-26T03:39:11.161615934Z 51(97) DEBUG: <core> [core/tcp_read.c:1705]: release_tcpconn(): extra_data (nil) 2024-02-26T03:39:11.162263374Z 83(129) DEBUG: <core> [core/tcp_main.c:3747]: handle_tcp_child(): reader response= 7f24539006a0, -1 from 0 2024-02-26T03:39:11.162286594Z 83(129) DEBUG: <core> [core/tcp_main.c:3671]: tcp_emit_closed_event(): TCP closed event creation triggered (reason: 0) 2024-02-26T03:39:11.162293034Z 83(129) DEBUG: tcpops [tcpops.c:311]: tcpops_handle_tcp_closed(): received TCP closed event 2024-02-26T03:39:11.162299134Z 83(129) DEBUG: tcpops [tcpops.c:261]: tcpops_tcp_closed_run_route(): event reason id: 0 rt: 1 2024-02-26T03:39:11.162304234Z 83(129) ERROR: tcpops [tcpops.c:278]: tcpops_tcp_closed_run_route(): run_top_route() before tev->id: 1 2024-02-26T03:39:11.162311444Z 83(129) DEBUG: <core> [core/tcp_main.c:1713]: _tcpconn_find(): 1 port 0 2024-02-26T03:39:11.162316784Z 83(129) DEBUG: <core> [core/tcp_main.c:1721]: _tcpconn_find(): c=0x7f24539006a0, c->id=1, port=22827 2024-02-26T03:39:11.162322944Z 83(129) DEBUG: <core> [core/ip_addr.c:577]: print_ip(): ip=12.0.1.6 2024-02-26T03:39:11.162328584Z 83(129) DEBUG: <core> [core/tcp_main.c:1725]: _tcpconn_find(): found connection by id: 1 2024-02-26T03:39:11.162333764Z 83(129) DEBUG: <core> [core/tcp_main.c:1713]: _tcpconn_find(): 1 port 0 2024-02-26T03:39:11.162338674Z 83(129) DEBUG: <core> [core/tcp_main.c:1721]: _tcpconn_find(): c=0x7f24539006a0, c->id=1, port=22827 2024-02-26T03:39:11.162343764Z 83(129) DEBUG: <core> [core/ip_addr.c:577]: print_ip(): ip=12.0.1.6 2024-02-26T03:39:11.162349254Z 83(129) DEBUG: <core> [core/tcp_main.c:1725]: _tcpconn_find(): found connection by id: 1 2024-02-26T03:39:11.162355494Z 83(129) DEBUG: <core> [core/pvapi.c:1418]: pv_printf_mode(): final buffer length 101 2024-02-26T03:39:11.162360924Z 83(129) ERROR: <script>: tcp connection closed conid: (1), tcp(conid): 1, Ri: 12.0.1.185, Rp: 5060 , si: 12.0.1.6 , sp: 22827 2024-02-26T03:39:11.162375744Z 83(129) DEBUG: <core> [core/tcp_main.c:1713]: _tcpconn_find(): 1 port 0 2024-02-26T03:39:11.162381944Z 83(129) DEBUG: <core> [core/tcp_main.c:1721]: _tcpconn_find(): c=0x7f24539006a0, c->id=1, port=22827 2024-02-26T03:39:11.162388024Z 83(129) DEBUG: <core> [core/ip_addr.c:577]: print_ip(): ip=12.0.1.6 2024-02-26T03:39:11.162395164Z 83(129) DEBUG: <core> [core/tcp_main.c:1725]: _tcpconn_find(): found connection by id: 1 2024-02-26T03:39:11.162400884Z 83(129) DEBUG: <core> [core/tcp_main.c:1713]: _tcpconn_find(): 1 port 0 2024-02-26T03:39:11.162406634Z 83(129) DEBUG: <core> [core/tcp_main.c:1721]: _tcpconn_find(): c=0x7f24539006a0, c->id=1, port=22827 2024-02-26T03:39:11.162412284Z 83(129) DEBUG: <core> [core/ip_addr.c:577]: print_ip(): ip=12.0.1.6 2024-02-26T03:39:11.162417034Z 83(129) DEBUG: <core> [core/tcp_main.c:1725]: _tcpconn_find(): found connection by id: 1 2024-02-26T03:39:11.162422294Z 83(129) DEBUG: <core> [core/pvapi.c:1418]: pv_printf_mode(): final buffer length 27 2024-02-26T03:39:11.162427844Z 83(129) ERROR: <script>: tcp connection closed (1) 2024-02-26T03:39:11.162433574Z 83(129) DEBUG: <core> [core/tcp_main.c:1713]: _tcpconn_find(): 1 port 0 2024-02-26T03:39:11.162439254Z 83(129) DEBUG: <core> [core/tcp_main.c:1721]: _tcpconn_find(): c=0x7f24539006a0, c->id=1, port=22827 2024-02-26T03:39:11.162444184Z 83(129) DEBUG: <core> [core/ip_addr.c:577]: print_ip(): ip=12.0.1.6 2024-02-26T03:39:11.162449324Z 83(129) DEBUG: <core> [core/tcp_main.c:1725]: _tcpconn_find(): found connection by id: 1 2024-02-26T03:39:11.162454724Z 83(129) DEBUG: <core> [core/pvapi.c:1418]: pv_printf_mode(): final buffer length 1 2024-02-26T03:39:11.162460094Z 83(129) DEBUG: <core> [core/pvapi.c:1418]: pv_printf_mode(): final buffer length 52 2024-02-26T03:39:11.162466084Z 83(129) DEBUG: <core> [core/tcp_main.c:1713]: _tcpconn_find(): 1 port 0 2024-02-26T03:39:11.162471724Z 83(129) DEBUG: <core> [core/tcp_main.c:1721]: _tcpconn_find(): c=0x7f24539006a0, c->id=1, port=22827 2024-02-26T03:39:11.162477324Z 83(129) DEBUG: <core> [core/ip_addr.c:577]: print_ip(): ip=12.0.1.6 2024-02-26T03:39:11.162482144Z 83(129) DEBUG: <core> [core/tcp_main.c:1725]: _tcpconn_find(): found connection by id: 1 2024-02-26T03:39:11.162487154Z 83(129) DEBUG: <core> [core/pvapi.c:1418]: pv_printf_mode(): final buffer length 52 2024-02-26T03:39:11.162501164Z 83(129) DEBUG: ndb_redis [redis_client.c:399]: redisc_get_server(): Hash 2100282857 (srvN) 2024-02-26T03:39:11.162508124Z 83(129) DEBUG: ndb_redis [redis_client.c:402]: redisc_get_server(): Entry 2694209461 (12.0.1.9:7469), rsrv->ctxRedis = (nil) 2024-02-26T03:39:11.162514104Z 83(129) DEBUG: ndb_redis [redis_client.c:402]: redisc_get_server(): Entry 2694209462 (12.0.1.8:7469), rsrv->ctxRedis = (nil) 2024-02-26T03:39:11.162520554Z 83(129) DEBUG: ndb_redis [redis_client.c:402]: redisc_get_server(): Entry 2694209448 (12.0.1.7:7469), rsrv->ctxRedis = (nil) 2024-02-26T03:39:11.162526404Z 83(129) DEBUG: ndb_redis [redis_client.c:402]: redisc_get_server(): Entry 2694210133 (12.0.1.9:7369), rsrv->ctxRedis = (nil) 2024-02-26T03:39:11.162532034Z 83(129) DEBUG: ndb_redis [redis_client.c:402]: redisc_get_server(): Entry 2694210134 (12.0.1.8:7369), rsrv->ctxRedis = (nil) 2024-02-26T03:39:11.162537324Z 83(129) DEBUG: ndb_redis [redis_client.c:402]: redisc_get_server(): Entry 2694210120 (12.0.1.7:7369), rsrv->ctxRedis = (nil) 2024-02-26T03:39:11.162542824Z 83(129) DEBUG: ndb_redis [redis_client.c:402]: redisc_get_server(): Entry 2100282854 (srvM), rsrv->ctxRedis = (nil) 2024-02-26T03:39:11.162548064Z 83(129) DEBUG: ndb_redis [redis_client.c:402]: redisc_get_server(): Entry 2100282857 (srvN), rsrv->ctxRedis = (nil) 2024-02-26T03:39:11.162554074Z 83(129) DEBUG: ndb_redis [redis_client.c:402]: redisc_get_server(): Entry 2100306023 (srvTPS), rsrv->ctxRedis = (nil) 2024-02-26T03:39:11.162559184Z 83(129) DEBUG: ndb_redis [redis_client.c:408]: redisc_get_server(): Entry 2694209461 (12.0.1.9:7469), rsrv->ctxRedis = (nil) 2024-02-26T03:39:11.162564524Z 83(129) DEBUG: ndb_redis [redis_client.c:408]: redisc_get_server(): Entry 2694209462 (12.0.1.8:7469), rsrv->ctxRedis = (nil) 2024-02-26T03:39:11.162569904Z 83(129) DEBUG: ndb_redis [redis_client.c:408]: redisc_get_server(): Entry 2694209448 (12.0.1.7:7469), rsrv->ctxRedis = (nil) 2024-02-26T03:39:11.162575334Z 83(129) DEBUG: ndb_redis [redis_client.c:408]: redisc_get_server(): Entry 2694210133 (12.0.1.9:7369), rsrv->ctxRedis = (nil) 2024-02-26T03:39:11.162580154Z 83(129) DEBUG: ndb_redis [redis_client.c:408]: redisc_get_server(): Entry 2694210134 (12.0.1.8:7369), rsrv->ctxRedis = (nil) 2024-02-26T03:39:11.162585964Z 83(129) DEBUG: ndb_redis [redis_client.c:408]: redisc_get_server(): Entry 2694210120 (12.0.1.7:7369), rsrv->ctxRedis = (nil) 2024-02-26T03:39:11.162592294Z 83(129) DEBUG: ndb_redis [redis_client.c:408]: redisc_get_server(): Entry 2100282854 (srvM), rsrv->ctxRedis = (nil) 2024-02-26T03:39:11.162597644Z 83(129) DEBUG: ndb_redis [redis_client.c:408]: redisc_get_server(): Entry 2100282857 (srvN), rsrv->ctxRedis = (nil) 2024-02-26T03:39:11.162611324Z 83(129) DEBUG: ndb_redis [redis_client.c:413]: redisc_get_server(): Using entry 2100282857 (srvN) 2024-02-26T03:39:11.162617084Z 83(129) DEBUG: ndb_redis [redis_client.c:960]: redisc_exec(): rsrv->ctxRedis = (nil) 2024-02-26T03:39:11.162622004Z 83(129) ERROR: ndb_redis [redis_client.c:963]: redisc_exec(): no redis context for server: srvN 2024-02-26T03:39:11.162627834Z 83(129) ERROR: tcpops [tcpops.c:280]: tcpops_tcp_closed_run_route(): run_top_route() after tev->id: 1 2024-02-26T03:39:11.162633294Z 83(129) DEBUG: <core> [core/tcp_main.c:3904]: handle_tcp_child(): case CONN_EOF tcp_emit_closed_event before 5
```
#### 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). -->
``` 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");
if($conid ne $null) { xlog("L_ERR", "$proto connection closed ($conid)\n"); route(TCPEVENT); } }
route[TCPEVENT] { if(redis_cmd("srvN", "get %s", "$conid", "r")) { ..... } }
#redis module config loadmodule "ndb_redis" modparam("ndb_redis", "cluster", 1) modparam("ndb_redis", "allow_dynamic_nodes", 1) modparam("ndb_redis", "server", "name=srvN;addr=NDB_N_REDIS_CLUSTER_MAINADDR;port=NDB_N_REDIS_CLUSTER_MAINPORT;pass=NDB_REDIS_PASSWORD") modparam("ndb_redis", "server", "name=srvM;addr=NDB_M_REDIS_CLUSTER_MAINADDR;port=NDB_M_REDIS_CLUSTER_MAINPORT;pass=NDB_REDIS_PASSWORD")
modparam("ndb_redis", "server", "name=12.0.1.7:7369;addr=12.0.1.7;port=7369;pass=NDB_REDIS_PASSWORD") modparam("ndb_redis", "server", "name=12.0.1.8:7369;addr=12.0.1.8;port=7369;pass=NDB_REDIS_PASSWORD") modparam("ndb_redis", "server", "name=12.0.1.9:7369;addr=12.0.1.9;port=7369;pass=NDB_REDIS_PASSWORD")
modparam("ndb_redis", "server", "name=12.0.1.7:7469;addr=12.0.1.7;port=7469;pass=NDB_REDIS_PASSWORD") modparam("ndb_redis", "server", "name=12.0.1.8:7469;addr=12.0.1.8;port=7469;pass=NDB_REDIS_PASSWORD") modparam("ndb_redis", "server", "name=12.0.1.9:7469;addr=12.0.1.9;port=7469;pass=NDB_REDIS_PASSWORD")
```
* **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 `lsb_release -a` and `uname -a`) -->
``` 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 ```
My guess is that the event route is executed by tcp-main process and that one has never had the connection to redis, as I looked at the code, it is like that since 2011 or so. Probably what is newer is the log error message.
Therefore the question is whether it actually worked to use redis_cmd() in that event rate (it did what it was supposed to do), or it was just no error log message, but the command didn't work?
Kamailio version 5.4.8 can be used normally. I have checked the logs and found that each process successfully initialized the variable, and no other errors were found. I also did not see any other normal business processes that set rsrv ->ctxRedis=NULL. All processes are only released when the program exits. Also, I saw from netstat that all TCP links are in an established state. ``` ... 2024-02-26T06:51:05.272902281Z 77(123) DEBUG: ndb_redis [redis_client.c:231]: redisc_init(): rsrv->ctxRedis = 0x5613031c1af0 2024-02-26T06:51:05.272906511Z 81(127) DEBUG: ndb_redis [redis_client.c:227]: redisc_init(): Connecting to 12.0.1.7:7369 2024-02-26T06:51:05.272919041Z 82(128) DEBUG: ndb_redis [redis_client.c:231]: redisc_init(): rsrv->ctxRedis = 0x5613031c12b0 2024-02-26T06:51:05.272933851Z 78(124) DEBUG: ndb_redis [redis_client.c:231]: redisc_init(): rsrv->ctxRedis = 0x5613031c4de0 2024-02-26T06:51:05.272963411Z 77(123) DEBUG: ndb_redis [redis_client.c:227]: redisc_init(): Connecting to 12.0.1.7:7369 2024-02-26T06:51:05.285328567Z 81(127) DEBUG: ndb_redis [redis_client.c:231]: redisc_init(): rsrv->ctxRedis = 0x5613031c2840 2024-02-26T06:51:05.285574157Z 82(128) DEBUG: ndb_redis [redis_client.c:227]: redisc_init(): Connecting to 12.0.1.7:7469 2024-02-26T06:51:05.285588327Z 80(126) DEBUG: ndb_redis [redis_client.c:227]: redisc_init(): Connecting to 12.0.1.8:7369 2024-02-26T06:51:05.285595027Z 82(128) DEBUG: ndb_redis [redis_client.c:231]: redisc_init(): rsrv->ctxRedis = 0x5613031c3d10 2024-02-26T06:51:05.285717157Z 81(127) DEBUG: ndb_redis [redis_client.c:227]: redisc_init(): Connecting to 12.0.1.7:7369 2024-02-26T06:51:05.285721697Z 82(128) DEBUG: ndb_redis [redis_client.c:227]: redisc_init(): Connecting to 12.0.1.9:7369 2024-02-26T06:51:05.285726187Z 78(124) DEBUG: ndb_redis [redis_client.c:227]: redisc_init(): Connecting to 12.0.1.8:7469 2024-02-26T06:51:05.285729947Z 82(128) DEBUG: ndb_redis [redis_client.c:231]: redisc_init(): rsrv->ctxRedis = 0x5613031c3390 2024-02-26T06:51:05.285735627Z 81(127) DEBUG: ndb_redis [redis_client.c:231]: redisc_init(): rsrv->ctxRedis = 0x5613031c4ad0 2024-02-26T06:51:05.285739987Z 80(126) DEBUG: ndb_redis [redis_client.c:231]: redisc_init(): rsrv->ctxRedis = 0x5613031c2b10 2024-02-26T06:51:05.285747267Z 75(121) DEBUG: ndb_redis [redis_client.c:227]: redisc_init(): Connecting to 12.0.1.8:7369 2024-02-26T06:51:05.285761797Z 82(128) DEBUG: ndb_redis [redis_client.c:227]: redisc_init(): Connecting to 12.0.1.8:7369 2024-02-26T06:51:05.285783837Z 82(128) DEBUG: ndb_redis [redis_client.c:231]: redisc_init(): rsrv->ctxRedis = 0x5613031c2b10 2024-02-26T06:51:05.285787687Z 82(128) DEBUG: ndb_redis [redis_client.c:227]: redisc_init(): Connecting to 12.0.1.7:7369 2024-02-26T06:51:05.285791427Z 82(128) DEBUG: ndb_redis [redis_client.c:231]: redisc_init(): rsrv->ctxRedis = 0x5613031c2e80 2024-02-26T06:51:05.285799057Z 82(128) DEBUG: ndb_redis [redis_client.c:227]: redisc_init(): Connecting to 12.0.1.7:7469 2024-02-26T06:51:05.285806657Z 77(123) DEBUG: ndb_redis [redis_client.c:231]: redisc_init(): rsrv->ctxRedis = 0x5613031c2840 2024-02-26T06:51:05.285813597Z 82(128) DEBUG: ndb_redis [redis_client.c:231]: redisc_init(): rsrv->ctxRedis = 0x5613031c1af0 2024-02-26T06:51:05.285817647Z 78(124) DEBUG: ndb_redis [redis_client.c:231]: redisc_init(): rsrv->ctxRedis = 0x5613031c12b0 2024-02-26T06:51:05.285897427Z 82(128) DEBUG: ndb_redis [redis_client.c:227]: redisc_init(): Connecting to 12.0.1.7:7369 2024-02-26T06:51:05.285906537Z 82(128) DEBUG: ndb_redis [redis_client.c:231]: redisc_init(): rsrv->ctxRedis = 0x5613031c2840 2024-02-26T06:51:05.285911297Z 82(128) DEBUG: ndb_redis [redis_client.c:227]: redisc_init(): Connecting to 12.0.1.7:7369 2024-02-26T06:51:05.285917977Z 82(128) DEBUG: ndb_redis [redis_client.c:231]: redisc_init(): rsrv->ctxRedis = 0x5613031c4ad0 2024-02-26T06:51:05.308957137Z 75(121) DEBUG: ndb_redis [redis_client.c:231]: redisc_init(): rsrv->ctxRedis = 0x5613031c2b10 2024-02-26T06:51:05.309168218Z 80(126) DEBUG: ndb_redis [redis_client.c:227]: redisc_init(): Connecting to 12.0.1.7:7369 2024-02-26T06:51:05.309183338Z 80(126) DEBUG: ndb_redis [redis_client.c:231]: redisc_init(): rsrv->ctxRedis = 0x5613031c2e80 2024-02-26T06:51:05.309187808Z 75(121) DEBUG: ndb_redis [redis_client.c:227]: redisc_init(): Connecting to 12.0.1.7:7369 2024-02-26T06:51:05.309192678Z 77(123) DEBUG: ndb_redis [redis_client.c:227]: redisc_init(): Connecting to 12.0.1.7:7369 2024-02-26T06:51:05.309198708Z 78(124) DEBUG: ndb_redis [redis_client.c:227]: redisc_init(): Connecting to 12.0.1.7:7469 2024-02-26T06:51:05.309203128Z 77(123) DEBUG: ndb_redis [redis_client.c:231]: redisc_init(): rsrv->ctxRedis = 0x5613031c4ad0 2024-02-26T06:51:05.309208338Z 75(121) DEBUG: ndb_redis [redis_client.c:231]: redisc_init(): rsrv->ctxRedis = 0x5613031c2e80 2024-02-26T06:51:05.309212358Z 78(124) DEBUG: ndb_redis [redis_client.c:231]: redisc_init(): rsrv->ctxRedis = 0x5613031c3d10 2024-02-26T06:51:05.309329668Z 75(121) DEBUG: ndb_redis [redis_client.c:227]: redisc_init(): Connecting to 12.0.1.7:7469 2024-02-26T06:51:05.309335838Z 75(121) DEBUG: ndb_redis [redis_client.c:231]: redisc_init(): rsrv->ctxRedis = 0x5613031c1af0 2024-02-26T06:51:05.309339958Z 75(121) DEBUG: ndb_redis [redis_client.c:227]: redisc_init(): Connecting to 12.0.1.7:7369 2024-02-26T06:51:05.309345148Z 75(121) DEBUG: ndb_redis [redis_client.c:231]: redisc_init(): rsrv->ctxRedis = 0x5613031c2840 2024-02-26T06:51:05.309349318Z 75(121) DEBUG: ndb_redis [redis_client.c:227]: redisc_init(): Connecting to 12.0.1.7:7369 2024-02-26T06:51:05.309354228Z 75(121) DEBUG: ndb_redis [redis_client.c:231]: redisc_init(): rsrv->ctxRedis = 0x5613031c4ad0 2024-02-26T06:51:05.309385778Z 80(126) DEBUG: ndb_redis [redis_client.c:227]: redisc_init(): Connecting to 12.0.1.7:7469 2024-02-26T06:51:05.309390028Z 80(126) DEBUG: ndb_redis [redis_client.c:231]: redisc_init(): rsrv->ctxRedis = 0x5613031c1af0 2024-02-26T06:51:05.309395598Z 80(126) DEBUG: ndb_redis [redis_client.c:227]: redisc_init(): Connecting to 12.0.1.7:7369 2024-02-26T06:51:05.309416238Z 80(126) DEBUG: ndb_redis [redis_client.c:231]: redisc_init(): rsrv->ctxRedis = 0x5613031c2840 2024-02-26T06:51:05.309421298Z 80(126) DEBUG: ndb_redis [redis_client.c:227]: redisc_init(): Connecting to 12.0.1.7:7369 2024-02-26T06:51:05.309425378Z 80(126) DEBUG: ndb_redis [redis_client.c:231]: redisc_init(): rsrv->ctxRedis = 0x5613031c4ad0 2024-02-26T06:51:05.309442258Z 78(124) DEBUG: ndb_redis [redis_client.c:227]: redisc_init(): Connecting to 12.0.1.9:7369 2024-02-26T06:51:05.320999073Z 78(124) DEBUG: ndb_redis [redis_client.c:231]: redisc_init(): rsrv->ctxRedis = 0x5613031c3390 2024-02-26T06:51:05.332643058Z 78(124) DEBUG: ndb_redis [redis_client.c:227]: redisc_init(): Connecting to 12.0.1.8:7369 2024-02-26T06:51:05.336555480Z 78(124) DEBUG: ndb_redis [redis_client.c:231]: redisc_init(): rsrv->ctxRedis = 0x5613031c2b10 2024-02-26T06:51:05.337678340Z 78(124) DEBUG: ndb_redis [redis_client.c:227]: redisc_init(): Connecting to 12.0.1.7:7369 2024-02-26T06:51:05.345606164Z 78(124) DEBUG: ndb_redis [redis_client.c:231]: redisc_init(): rsrv->ctxRedis = 0x5613031c2e80 2024-02-26T06:51:05.345698304Z 78(124) DEBUG: ndb_redis [redis_client.c:227]: redisc_init(): Connecting to 12.0.1.7:7469 2024-02-26T06:51:05.345709604Z 78(124) DEBUG: ndb_redis [redis_client.c:231]: redisc_init(): rsrv->ctxRedis = 0x5613031c1af0 2024-02-26T06:51:05.345714844Z 78(124) DEBUG: ndb_redis [redis_client.c:227]: redisc_init(): Connecting to 12.0.1.7:7369 2024-02-26T06:51:05.345719144Z 78(124) DEBUG: ndb_redis [redis_client.c:231]: redisc_init(): rsrv->ctxRedis = 0x5613031c2840 2024-02-26T06:51:05.345723774Z 78(124) DEBUG: ndb_redis [redis_client.c:227]: redisc_init(): Connecting to 12.0.1.7:7369 2024-02-26T06:51:05.345791794Z 78(124) DEBUG: ndb_redis [redis_client.c:231]: redisc_init(): rsrv->ctxRedis = 0x5613031c4ad0 2024-02-26T06:51:05.408166382Z 1(47) DEBUG: ndb_redis [redis_client.c:227]: redisc_init(): Connecting to 12.0.1.9:7469 2024-02-26T06:51:05.408690623Z 1(47) DEBUG: ndb_redis [redis_client.c:231]: redisc_init(): rsrv->ctxRedis = 0x5613031c4de0 2024-02-26T06:51:05.409249123Z 1(47) DEBUG: ndb_redis [redis_client.c:227]: redisc_init(): Connecting to 12.0.1.8:7469 2024-02-26T06:51:05.409404343Z 1(47) DEBUG: ndb_redis [redis_client.c:231]: redisc_init(): rsrv->ctxRedis = 0x5613031c12b0 2024-02-26T06:51:05.409708683Z 1(47) DEBUG: ndb_redis [redis_client.c:227]: redisc_init(): Connecting to 12.0.1.7:7469 2024-02-26T06:51:05.409854203Z 1(47) DEBUG: ndb_redis [redis_client.c:231]: redisc_init(): rsrv->ctxRedis = 0x5613031c3d10 2024-02-26T06:51:05.410137103Z 1(47) DEBUG: ndb_redis [redis_client.c:227]: redisc_init(): Connecting to 12.0.1.9:7369 2024-02-26T06:51:05.410291773Z 1(47) DEBUG: ndb_redis [redis_client.c:231]: redisc_init(): rsrv->ctxRedis = 0x5613031c3390 2024-02-26T06:51:05.410691894Z 1(47) DEBUG: ndb_redis [redis_client.c:227]: redisc_init(): Connecting to 12.0.1.8:7369 2024-02-26T06:51:05.410901694Z 1(47) DEBUG: ndb_redis [redis_client.c:231]: redisc_init(): rsrv->ctxRedis = 0x5613031c2b10 2024-02-26T06:51:05.411303174Z 1(47) DEBUG: ndb_redis [redis_client.c:227]: redisc_init(): Connecting to 12.0.1.7:7369 2024-02-26T06:51:05.411450584Z 1(47) DEBUG: ndb_redis [redis_client.c:231]: redisc_init(): rsrv->ctxRedis = 0x5613031c2e80 2024-02-26T06:51:05.411740424Z 1(47) DEBUG: ndb_redis [redis_client.c:227]: redisc_init(): Connecting to 12.0.1.7:7469 2024-02-26T06:51:05.411870844Z 1(47) DEBUG: ndb_redis [redis_client.c:231]: redisc_init(): rsrv->ctxRedis = 0x5613031c1af0 2024-02-26T06:51:05.412134044Z 1(47) DEBUG: ndb_redis [redis_client.c:227]: redisc_init(): Connecting to 12.0.1.7:7369 2024-02-26T06:51:05.412336694Z 1(47) DEBUG: ndb_redis [redis_client.c:231]: redisc_init(): rsrv->ctxRedis = 0x5613031c2840 2024-02-26T06:51:05.412625645Z 1(47) DEBUG: ndb_redis [redis_client.c:227]: redisc_init(): Connecting to 12.0.1.7:7369 2024-02-26T06:51:05.412802495Z 1(47) DEBUG: ndb_redis [redis_client.c:231]: redisc_init(): rsrv->ctxRedis = 0x5613031c4a ...
... netstat -anp|grep 7369 result: tcp 0 0 12.0.1.185:43654 12.0.1.7:7369 ESTABLISHED 233801/kamailio tcp 0 0 12.0.1.185:44398 12.0.1.7:7369 ESTABLISHED 233834/kamailio tcp 0 0 12.0.1.185:45222 12.0.1.7:7369 ESTABLISHED 233861/kamailio tcp 0 0 12.0.1.185:55608 12.0.1.9:7369 ESTABLISHED 233804/kamailio tcp 0 0 12.0.1.185:43972 12.0.1.7:7369 ESTABLISHED 233816/kamailio tcp 0 0 12.0.1.185:45162 12.0.1.7:7369 ESTABLISHED 233860/kamailio tcp 0 0 12.0.1.185:44838 12.0.1.7:7369 ESTABLISHED 233851/kamailio tcp 0 0 12.0.1.185:45186 12.0.1.8:7369 ESTABLISHED 233838/kamailio tcp 0 0 12.0.1.185:56020 12.0.1.9:7369 ESTABLISHED 233846/kamailio tcp 0 0 12.0.1.185:44000 12.0.1.7:7369 ESTABLISHED 233812/kamailio tcp 0 0 12.0.1.185:55894 12.0.1.9:7369 ESTABLISHED 233836/kamailio tcp 0 0 12.0.1.185:55834 12.0.1.9:7369 ESTABLISHED 233831/kamailio tcp 0 0 12.0.1.185:44626 12.0.1.7:7369 ESTABLISHED 233837/kamailio tcp 0 0 12.0.1.185:44886 12.0.1.7:7369 ESTABLISHED 233845/kamailio tcp 0 0 12.0.1.185:44896 12.0.1.8:7369 ESTABLISHED 233812/kamailio tcp 0 0 12.0.1.185:44254 12.0.1.7:7369 ESTABLISHED 233831/kamailio tcp 0 0 12.0.1.185:56178 12.0.1.9:7369 ESTABLISHED 233866/kamailio tcp 0 0 12.0.1.185:45478 12.0.1.7:7369 ESTABLISHED 233864/kamailio tcp 0 0 12.0.1.185:44012 12.0.1.7:7369 ESTABLISHED 233818/kamailio tcp 0 0 12.0.1.185:44648 12.0.1.7:7369 ESTABLISHED 233834/kamailio tcp 0 0 12.0.1.185:44700 12.0.1.7:7369 ESTABLISHED 233842/kamailio tcp 0 0 12.0.1.185:55698 12.0.1.9:7369 ESTABLISHED 233812/kamailio tcp 0 0 12.0.1.185:55842 12.0.1.9:7369 ESTABLISHED 233833/kamailio tcp 0 0 12.0.1.185:44712 12.0.1.7:7369 ESTABLISHED 233840/kamailio tcp 0 0 12.0.1.185:45258 12.0.1.8:7369 ESTABLISHED 233858/kamailio tcp 0 0 12.0.1.185:56038 12.0.1.9:7369 ESTABLISHED 233851/kamailio tcp 0 0 12.0.1.185:56218 12.0.1.9:7369 ESTABLISHED 233871/kamailio tcp 0 0 12.0.1.185:43886 12.0.1.7:7369 ESTABLISHED 233807/kamailio tcp 0 0 12.0.1.185:43576 12.0.1.7:7369 ESTABLISHED 233798/kamailio tcp 0 0 12.0.1.185:44292 12.0.1.7:7369 ESTABLISHED 233820/kamailio tcp 0 0 12.0.1.185:55986 12.0.1.9:7369 ESTABLISHED 233843/kamailio tcp 0 0 12.0.1.185:44964 12.0.1.8:7369 ESTABLISHED 233817/kamailio tcp 0 0 12.0.1.185:44894 12.0.1.7:7369 ESTABLISHED 233848/kamailio tcp 0 0 12.0.1.185:44706 12.0.1.8:7369 ESTABLISHED 233792/kamailio tcp 0 0 12.0.1.185:44106 12.0.1.7:7369 ESTABLISHED 233824/kamailio tcp 0 0 12.0.1.185:44370 12.0.1.7:7369 ESTABLISHED 233837/kamailio tcp 0 0 12.0.1.185:45224 12.0.1.8:7369 ESTABLISHED 233845/kamailio tcp 0 0 12.0.1.185:45356 12.0.1.8:7369 ESTABLISHED 233860/kamailio tcp 0 0 12.0.1.185:44334 12.0.1.7:7369 ESTABLISHED 233833/kamailio tcp 0 0 12.0.1.185:45508 12.0.1.7:7369 ESTABLISHED 233867/kamailio .... ```
Can you also provide the output of "kamctl ps" for the same instance from where you get the logs?
I suspect that there may be compatibility issues between the new version of the TCP model and the old ndd_redis module during module initialization. I suspect that the processing logic triggered by this event occurred in the main process, which did not initialize the relevant context. I have attempted to modify the following code：
··· file:ndb_redis/ndb_redis_mod.c 151 if(rank == PROC_INIT || rank == PROC_MAIN || rank == PROC_TCP_MAIN) modify: 151 if(rank == PROC_INIT || rank == PROC_MAIN ) ···
Based on the above tests, it can be basically determined that the event_route event was triggered in the TCP main process, rather than in the expected child process, which is also the reason why it cannot obtain the context normally. I'm not sure if this handling is reasonable and won't cause any other problems, but it can indeed run normally. Is there any other better way? I speculate that the related issues should be quite common, whether it is better to solve them from the framework level rather than the module itself. And all operations are handled by the main process, and its performance is also worrying.
That's exactly the code I looked at and said that is there from like 2011, therefore questioning if it really worked differently in 5.4.x vs 5.7.x. The log message might not have been there, but the condition was. If I haven't missed any related commit, it is no major difference in the internal TCP design between 5.4 and 5.7.
Anyhow, I will commit an update to initialise the ndb context for tcp-main and look to see if it is needed for the main attendant as well.
I pushed a commit to git master branch, can you try with it and see if works as expected?
hi，After my testing, the new modifications ran smoothly and the results met expectations. However, during the testing process, I discovered a new issue where I was unable to obtain $conid in the event_route [tcp: timeout] routing block. After analyzing, it was found that the find_conn method in the tcp_main. c file returned directly when it determined that the status of conn was BAD, and the relevant connection information was not successfully obtained. Given the relative proofreading of this issue, I will attempt to use the relevant logic from version 5.4.8 to rollback, mainly by removing the tcp_mait_closed_event call from the tcp_main. c file and adding this function call to the relevant code in tcp_read. c. After modification and testing, all issues disappeared, and the desired parameters could be obtained and executed normally within each close event. After observation, the relevant code should be executed in the child process, which does not have any impact on the main process. I think it is more reasonable. All the related functions of the new version have been placed in the main process for global management. The advantage is that the management is convenient and there will be no omissions. However, the disadvantage is that the main process does too much, and all the objects in the child processes need to have copies in the main process to be called normally. The main process is too cumbersome, and I don't think it's a good design. I haven't thought of a better solution for this while, The occupancy time can only be reverted back to the old version mode, which is currently more practical.
The tcp_read.c code does not cover all cases when the connection can be closed, only when that happens during reading operations. But not on lifetime expiration and some other events -- that was the reason to move the execution of the event route for closed event in the tcp-main, because it is the process that destroys it, even when the close is detected on-read.
I don't think the solution is to go back to the older approach, but find a way to share the connection structure, because it is not yet destroyed when event route is executed, just no longer in the hash table.
Btw, I pushed some code after my previous comment, trying to make it more flexible to work with both cases: connection found active or connection just available for the event_route before destroying it.
Regarding the fact that the main-tcp can be occupied too long, that is a matter of what you do in the event route. If you know that is going to be some lengthly action with network i/o, then delegate it to another worker with mqueue+rtimer or async modules. Similar problems can happen for lengthy actions used in failure-route (blocking timer process) or even for sip worker processes.
Anyhow, you are welcome to propose enhancements as PRs, they will be reviewed and merged if they improve things.
This issue is stale because it has been open 6 weeks with no activity. Remove stale label or comment or this will be closed in 2 weeks.
Closed #3768 as not planned.
-
Daniel-Constantin Mierla -
github-actions[bot]
-
liangbaolin