search

kamailio / kamailio

Kamailio - The Open Source SIP Server for large VoIP and real-time communication platforms -
https://www.kamailio.org
Other
2.19k stars 921 forks source link

ndb_redis: Error when receiving 'MOVED' response from redis-cluster with TLS #3894

Closed uv-2722 closed 5 days ago

uv-2722 commented 2 weeks ago

Description

Hello, I am using ndb_redis module with TLS and redis-cluster. kamailio connects to the cluster endpoint when getting data, gets a 'MOVED' response and prints below error, it does not get data from the new host.

Troubleshooting

I have verified that I can connect to the cluster endpoint and the host in 'MOVED' using redis-cli on the system that kamailio is running on. I tried to connect to a self hosted cluster without TLS, it works as expected. It also works as expected with TLS and a single redis host.

Reproduction

Connect to a redis-cluster over TLS

Log Messages

2024-06-25T20:48:53.626708963Z 2024-06-25 20:48:53.626584  3(17) NOTICE: {Kam 192.168.20.4 503874790_98536808 1 753067 INVITE}ndb_redis [redis_client.c:437]: redisc_get_server(): Hash 31807 (ra)
2024-06-25T20:48:53.626710053Z 2024-06-25 20:48:53.626600  3(17) DEBUG: {Kam 192.168.20.4 503874790_98536808 1 753067 INVITE}ndb_redis [redis_client.c:440]: redisc_get_server(): Entry 31807 (ra)
2024-06-25T20:48:53.626711073Z 2024-06-25 20:48:53.626636  3(17) NOTICE: {Kam 192.168.20.4 503874790_98536808 1 753067 INVITE}ndb_redis [redis_client.c:444]: redisc_get_server(): Using entry 31807 (ra)
2024-06-25T20:48:53.626712073Z 2024-06-25 20:48:53.626651  3(17) DEBUG: {Kam 192.168.20.4 503874790_98536808 1 753067 INVITE}ndb_redis [redis_client.c:1030]: redisc_exec(): rsrv->ctxRedis = 0x556b4456dc20
2024-06-25T20:48:53.626713073Z 2024-06-25 20:48:53.626667  3(17) DEBUG: {Kam 192.168.20.4 503874790_98536808 1 753067 INVITE}ndb_redis [redis_client.c:1036]: redisc_exec(): rsrv->ctxRedis = 0x556b4456dc20
2024-06-25T20:48:53.626810463Z 2024-06-25 20:48:53.626762  3(17) DEBUG: {Kam 192.168.20.4 503874790_98536808 1 753067 INVITE}ndb_redis [redis_client.c:896]: check_cluster_reply(): Redis replied: "MOVED 3667 testdbredis-masked-hostname.00000000001110000000.130-characters-long.00000000000011111111100000000.availability-zone.amazonaws.com:6379"
2024-06-25T20:48:53.626811523Z 2024-06-25 20:48:53.626777  3(17) DEBUG: {Kam 192.168.20.4 503874790_98536808 1 753067 INVITE}ndb_redis [redis_client.c:904]: check_cluster_reply(): Port "6379" [4] => 6379
2024-06-25T20:48:53.626816413Z 2024-06-25 20:48:53.626793  3(17) DEBUG: {Kam 192.168.20.4 503874790_98536808 1 753067 INVITE}ndb_redis [redis_client.c:914]: check_cluster_reply(): Host "testdbredis-masked-hostname.00000000001110000000.130-characters-long.00000000000011111111100000000.availability-zone.amazonaws.com" [130]
2024-06-25T20:48:53.626846113Z 2024-06-25 20:48:53.626810  3(17) NOTICE: {Kam 192.168.20.4 503874790_98536808 1 753067 INVITE}ndb_redis [redis_client.c:925]: check_cluster_reply(): Name of new connection: testdbredis-masked-hostname.00000000001110000000.130-characters-long.00000000000011111111100000000.
2024-06-25T20:48:53.626851443Z 2024-06-25 20:48:53.626827  3(17) NOTICE: {Kam 192.168.20.4 503874790_98536808 1 753067 INVITE}ndb_redis [redis_client.c:437]: redisc_get_server(): Hash 968070864 (testdbredis-masked-hostname.00000000001110000000.130-characters-long.00000000000011111111100000000.)
2024-06-25T20:48:53.626896173Z 2024-06-25 20:48:53.626844  3(17) DEBUG: {Kam 192.168.20.4 503874790_98536808 1 753067 INVITE}ndb_redis [redis_client.c:440]: redisc_get_server(): Entry 31807 (ra)
2024-06-25T20:48:53.626897503Z 2024-06-25 20:48:53.626861  3(17) NOTICE: {Kam 192.168.20.4 503874790_98536808 1 753067 INVITE}ndb_redis [redis_client.c:450]: redisc_get_server(): No entry found.
2024-06-25T20:48:53.626955363Z 2024-06-25 20:48:53.626877  3(17) ERROR: {Kam 192.168.20.4 503874790_98536808 1 753067 INVITE}ndb_redis [redis_client.c:947]: check_cluster_reply(): failed to print server spec string
2024-06-25T20:48:53.626957263Z 2024-06-25 20:48:53.626893  3(17) DEBUG: {Kam 192.168.20.4 503874790_98536808 1 753067 INVITE}ndb_redis [redis_client.c:1115]: redisc_exec(): rpl->rplRedis->type:6
2024-06-25T20:48:53.626958443Z 2024-06-25 20:48:53.626908  3(17) ERROR: {Kam 192.168.20.4 503874790_98536808 1 753067 INVITE}ndb_redis [redis_client.c:1117]: redisc_exec(): Redis error:MOVED 3667 testdbredis-masked-hostname.00000000001110000000.130-characters-long.00000000000011111111100000000.availability-zone.amazonaws.com:6379

Additional Information

version: kamailio 5.8.1 (x86_64/linux) 384843
flags: USE_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_SEND_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: 384843 
compiled on 19:05:30 Jun 25 2024 with gcc 12.2.0

Debian 12

Kamailio config snippet

loadmodule "ndb_redis.so"
.
.
# ----- ndb_redis params -----
modparam("ndb_redis", "server", "name=ra;addr=cluster.testdbredis-masked-hostname.0000000011111111100000.availability-zone.amazonaws.com;port=6379;tls=1")
modparam("ndb_redis", "init_without_redis", 1)
modparam("ndb_redis", "cluster", 1)
modparam("ndb_redis", "allow_dynamic_nodes", 1)
modparam("ndb_redis", "ca_path", "/etc/ssl/certs")
modparam("ndb_redis", "debug", 1)
.
.
redis_cmd("ra", "HMGET usr_preferences:entry::%s:%s blocked", "$rU", "$fU", "r");
if($redis(r=>value[0]) == 1) {
.
}
miconda commented 5 days ago

The local buffers used to build the new server spec after the MOVED were not large enough for the address returned. I increased the size, which should be now for any decently large server address. The commit is in master branch, it will be backported soon.

I am closing this one, should there be still problems, comment to reopen.

uv-2722 commented 5 days ago

Hello, Thank you for looking into this!

I installed and tested the latest master branch, I am getting the below errors. I have verified that the host in the MOVED response is up, has the needed data and can connect to it from the system kamailio is running on. Kamailio is running with log level 3 (debug), please let me know how to provide more information for troubleshooting. 

2024-07-05T17:43:30.226948916Z 2024-07-05 17:43:30.226089  3(16) NOTICE: {Kam 192.168.20.4 191391185_65481742 1 706329 INVITE}ndb_redis [redis_client.c:437]: redisc_get_server(): Hash 31807 (ra)
2024-07-05T17:43:30.226949946Z 2024-07-05 17:43:30.226104  3(16) DEBUG: {Kam 192.168.20.4 191391185_65481742 1 706329 INVITE}ndb_redis [redis_client.c:440]: redisc_get_server(): Entry 31807 (ra)
2024-07-05T17:43:30.226951136Z 2024-07-05 17:43:30.226120  3(16) NOTICE: {Kam 192.168.20.4 191391185_65481742 1 706329 INVITE}ndb_redis [redis_client.c:444]: redisc_get_server(): Using entry 31807 (ra)
2024-07-05T17:43:30.226952166Z 2024-07-05 17:43:30.226136  3(16) DEBUG: {Kam 192.168.20.4 191391185_65481742 1 706329 INVITE}ndb_redis [redis_client.c:1031]: redisc_exec(): rsrv->ctxRedis = 0x5589e7200c80
2024-07-05T17:43:30.226953146Z 2024-07-05 17:43:30.226151  3(16) DEBUG: {Kam 192.168.20.4 191391185_65481742 1 706329 INVITE}ndb_redis [redis_client.c:1037]: redisc_exec(): rsrv->ctxRedis = 0x5589e7200c80
2024-07-05T17:43:30.226954236Z 2024-07-05 17:43:30.226167  3(16) DEBUG: {Kam 192.168.20.4 191391185_65481742 1 706329 INVITE}ndb_redis [redis_client.c:896]: check_cluster_reply(): Redis replied: "MOVED 3667 testdbredis-masked-hostname.00000000001110000000.130-characters-long.00000000000011111111100000000.availability-zone.amazonaws.com:6379"
2024-07-05T17:43:30.226955306Z 2024-07-05 17:43:30.226182  3(16) DEBUG: {Kam 192.168.20.4 191391185_65481742 1 706329 INVITE}ndb_redis [redis_client.c:904]: check_cluster_reply(): Port "6379" [4] => 6379
2024-07-05T17:43:30.226956296Z 2024-07-05 17:43:30.226197  3(16) DEBUG: {Kam 192.168.20.4 191391185_65481742 1 706329 INVITE}ndb_redis [redis_client.c:914]: check_cluster_reply(): Host "testdbredis-masked-hostname.00000000001110000000.130-characters-long.00000000000011111111100000000.availability-zone.amazonaws.com [130]
2024-07-05T17:43:30.226957366Z 2024-07-05 17:43:30.226213  3(16) NOTICE: {Kam 192.168.20.4 191391185_65481742 1 706329 INVITE}ndb_redis [redis_client.c:925]: check_cluster_reply(): Name of new connection: testdbredis-masked-hostname.00000000001110000000.130-characters-long.00000000000011111111100000000.availability-zone.amazonaws.com:6379
2024-07-05T17:43:30.226958386Z 2024-07-05 17:43:30.226240  3(16) NOTICE: {Kam 192.168.20.4 191391185_65481742 1 706329 INVITE}ndb_redis [redis_client.c:437]: redisc_get_server(): Hash 307573284 (testdbredis-masked-hostname.00000000001110000000.130-characters-long.00000000000011111111100000000.availability-zone.amazonaws.com:6379)
2024-07-05T17:43:30.226959406Z 2024-07-05 17:43:30.226256  3(16) DEBUG: {Kam 192.168.20.4 191391185_65481742 1 706329 INVITE}ndb_redis [redis_client.c:440]: redisc_get_server(): Entry 31807 (ra)
2024-07-05T17:43:30.226960846Z 2024-07-05 17:43:30.226271  3(16) NOTICE: {Kam 192.168.20.4 191391185_65481742 1 706329 INVITE}ndb_redis [redis_client.c:450]: redisc_get_server(): No entry found.
2024-07-05T17:43:30.226962046Z 2024-07-05 17:43:30.226286  3(16) NOTICE: {Kam 192.168.20.4 191391185_65481742 1 706329 INVITE}ndb_redis [redis_client.c:437]: redisc_get_server(): Hash 307573284 (testdbredis-masked-hostname.00000000001110000000.130-characters-long.00000000000011111111100000000.availability-zone.amazonaws.com:6379)
2024-07-05T17:43:30.226963076Z 2024-07-05 17:43:30.226302  3(16) DEBUG: {Kam 192.168.20.4 191391185_65481742 1 706329 INVITE}ndb_redis [redis_client.c:440]: redisc_get_server(): Entry 307573284 (testdbredis-masked-hostname.00000000001110000000.130-characters-long.00000000000011111111100000000.availability-zone.amazonaws.com:6379)
2024-07-05T17:43:30.226964116Z 2024-07-05 17:43:30.226318  3(16) NOTICE: {Kam 192.168.20.4 191391185_65481742 1 706329 INVITE}ndb_redis [redis_client.c:444]: redisc_get_server(): Using entry 307573284 (testdbredis-masked-hostname.00000000001110000000.130-characters-long.00000000000011111111100000000.availability-zone.amazonaws.com:6379)
2024-07-05T17:43:30.226965146Z 2024-07-05 17:43:30.226333  3(16) DEBUG: {Kam 192.168.20.4 191391185_65481742 1 706329 INVITE}ndb_redis [redis_client.c:593]: redisc_reconnect_server(): rsrv->ctxRedis = (nil)
2024-07-05T17:43:30.227843477Z 2024-07-05 17:43:30.227772  3(16) DEBUG: {Kam 192.168.20.4 191391185_65481742 1 706329 INVITE}ndb_redis [redis_client.c:626]: redisc_reconnect_server(): rsrv->ctxRedis = 0x5589e7239650
2024-07-05T17:43:31.247855886Z 2024-07-05 17:43:31.247646  3(16) ERROR: {Kam 192.168.20.4 191391185_65481742 1 706329 INVITE}ndb_redis [redis_client.c:652]: redisc_reconnect_server(): error communicating with redis server [testdbredis-masked-hostname.00000000001110000000.130-characters-long.00000000000011111111100000000.availability-zone.amazonaws.com:6379] (testdbredis-masked-hostname.00000000001110000000.130-characters-long.00000000000011111111100000000.availability-zone.amazonaws.com:6379/0): Resource temporarily unavailable
2024-07-05T17:43:31.247875406Z 2024-07-05 17:43:31.247744  3(16) ERROR: {Kam 192.168.20.4 191391185_65481742 1 706329 INVITE}ndb_redis [redis_client.c:661]: redisc_reconnect_server(): failed to connect to redis server [testdbredis-masked-hostname.00000000001110000000.130-characters-long.00000000000011111111100000000.availability-zone.amazonaws.com:6379] (testdbredis-masked-hostname.00000000001110000000.130-characters-long.00000000000011111111100000000.availability-zone.amazonaws.com:6379/0)
2024-07-05T17:43:31.247877256Z 2024-07-05 17:43:31.247761  3(16) ERROR: {Kam 192.168.20.4 191391185_65481742 1 706329 INVITE}ndb_redis [redis_client.c:973]: check_cluster_reply(): failed connecting to the new server with name: testdbredis-masked-hostname.00000000001110000000.130-characters-long.00000000000011111111100000000.availability-zone.amazonaws.com:6379
2024-07-05T17:43:31.248049406Z 2024-07-05 17:43:31.247777  3(16) DEBUG: {Kam 192.168.20.4 191391185_65481742 1 706329 INVITE}ndb_redis [redis_client.c:1116]: redisc_exec(): rpl->rplRedis->type:6
2024-07-05T17:43:31.248052246Z 2024-07-05 17:43:31.247793  3(16) ERROR: {Kam 192.168.20.4 191391185_65481742 1 706329 INVITE}ndb_redis [redis_client.c:1118]: redisc_exec(): Redis error:MOVED 3667 testdbredis-masked-hostname.00000000001110000000.130-characters-long.00000000000011111111100000000.availability-zone.amazonaws.com:6379
uv-2722 commented 6 hours ago

The issue didn't go to open state after the above comment, can this be re-opened?