SEMS ERROR: error/unexpected reply from redis: 'Too many registrations

rabbani · November 20, 2019, 10:34am

Hi Dmitry,

Separate topic with logs

sems[698]: [752/core/AmThread.cpp:92] INFO: Thread 139977719162624 is starting
sems[698]: [753/core/AmThread.cpp:92] INFO: Thread 139977718109952 is starting
sems[698]: [753/core/sip/tcp_base_trsp.cpp:1009] INFO: Started SIP server thread
sems[698]: [751/core/AmThread.cpp:92] INFO: Thread 139977720215296 is starting
sems[698]: [750/core/AmThread.cpp:92] INFO: Thread 139977721267968 is starting
sems[698]: [750/core/sip/udp_trsp.cpp:426] INFO: Started SIP server UDP transport
sems[698]: [749/core/AmThread.cpp:92] INFO: Thread 139977722320640 is starting
sems[698]: [749/core/sip/udp_trsp.cpp:426] INFO: Started SIP server UDP transport
sems[698]: [748/core/AmThread.cpp:92] INFO: Thread 139977723373312 is starting
sems[698]: [734/yeti:alarms.cpp:65] INFO: ALARM 0 [management database connections error] CLEARED
sems[698]: [734/yeti:db/PgConnectionPool.cpp:310] WARNING: PCP: : All sql connected.
sems[698]: [728/yeti:resources/ResourceCache.cpp:306] ERROR: get connection can’t get connection from write redis pool. retry every 1s
sems[698]: [728/yeti:resources/ResourceCache.cpp:364] INFO: resources initialized
sems[698]: [724/yeti:yeti.cpp:541] ERROR: error/unexpected reply from redis: ‘Too many registrations’
sems[698]: [724/yeti:yeti.cpp:541] ERROR: error/unexpected reply from redis: ‘Too many registrations’
sems[698]: [724/yeti:yeti.cpp:541] ERROR: error/unexpected reply from redis: ‘Too many registrations’
sems[698]: [724/yeti:yeti.cpp:541] ERROR: error/unexpected reply from redis: ‘Too many registrations’
sems[698]: [724/yeti:yeti.cpp:541] ERROR: error/unexpected reply from redis: ‘Too many registrations’
sems[698]: [704/yeti:SBCCallLeg.cpp:790] ERROR: unexpected contact_arg||path_arg type. skip entry
sems[698]: [704/yeti:SBCCallLeg.cpp:790] ERROR: unexpected contact_arg||path_arg type. skip entry
sems[698]: [704/yeti:SBCCallLeg.cpp:790] ERROR: unexpected contact_arg||path_arg type. skip entry
sems[698]: [704/yeti:SBCCallLeg.cpp:790] ERROR: unexpected contact_arg||path_arg type. skip entry
sems[698]: [704/yeti:SBCCallLeg.cpp:790] ERROR: unexpected contact_arg||path_arg type. skip entry
sems[698]: [704/yeti:SBCCallLeg.cpp:790] ERROR: unexpected contact_arg||path_arg type. skip entry
sems[698]: [704/yeti:SBCCallLeg.cpp:790] ERROR: unexpected contact_arg||path_arg type. skip entry
sems[698]: [704/yeti:SBCCallLeg.cpp:790] ERROR: unexpected contact_arg||path_arg type. skip entry
sems[698]: [704/yeti:SBCCallLeg.cpp:790] ERROR: unexpected contact_arg||path_arg type. skip entry
sems[698]: [704/yeti:SBCCallLeg.cpp:790] ERROR: unexpected contact_arg||path_arg type. skip entry

I had to flushall redis and restart sems and kamilio to get it back to working

dmitry.s · November 20, 2019, 7:58pm

looks like you are trying register more then 10 aors with for same username/password

rabbani · November 20, 2019, 10:37pm

Also when this happened I was also looking at the sngrep for sip traces and I found that bulk of OPTION requests from either directions, Is there a way to set the limits or flush them from the web-ui instead of doing it from then redis-cli.

dmitry.s · November 20, 2019, 11:25pm

OPTIONS should not cause such error. Could you capture incoming REGISTERs?

rabbani · November 21, 2019, 4:51am

192.168.120.151 - Yeti address
192.168.120.56 - Zoiper Softphone

rabbani · November 21, 2019, 4:55am

redis-cli>flushall

flushall is temporarily fixing it but we still see heaps of OPTIONS from Yeti to Softphone and also i could also see Yeti sending OPTIONS to Yeti

dmitry.s · November 21, 2019, 9:04am

do you have pcap trace? screenshots is pretty useless. sems log with loglevel=3 also could be useful.

rabbani · November 21, 2019, 11:31pm

unfortunately no and also it is intermittent and i will try to get you tcptump when it happens next time or try to replicate it again

rabbani · January 17, 2020, 12:11pm

hi Dmitry, I had to put this ticket on hold … but I have managed to get some sems logs for this ticket. apparently, sems is sending out way too many OPTION requests to a single aor record in a very short interval. Logs below for your reference

1.1.1.1 - PC1 Public IP (Inactive)
1.1.1.2 - PC2 Public IP (Active)
2.2.2.2 - LB IP
2.2.2.3 - SEMS IP


Jan 17 22:55:31 sems1 sems[9987]: [10013/core/sip/udp_trsp.cpp:288] DEBUG: send msg via UDP from 2.2.2.3:7000 to 192.168.120.67:5060#012--++--#012OPTIONS sip:61811111111@192.168.120.67:5060;rinstance=95dc6a4d3a53ea84;transport=UDP SIP/2.0#015#012Via: SIP/2.0/UDP 2.2.2.3:7000;branch=z9hG4bK82xTGa3x;rport#015#012From: sip:61811111111@192.168.120.67:5060;rinstance=95dc6a4d3a53ea84;transport=UDP;tag=registrar#015#012To: sip:61811111111@192.168.120.67:5060;rinstance=95dc6a4d3a53ea84;transport=UDP#015#012CSeq: 10 OPTIONS#015#012Call-ID: 8-52114B97-5E21A0B30005B9DB-C6297700#015#012Max-Forwards: 70#015#012User-Agent: SBC 1.8.34-5#015#012Contact: <sip:2.2.2.3:7000;transport=udp>#015#012Content-Length: 0#015#012#015#012--++--
Jan 17 22:55:31 sems1 sems[9987]: [10027/core/sip/udp_trsp.cpp:362] DEBUG: vv M [|] u recvd msg via UDP from 2.2.2.2:5060 vv#012--++--#012SIP/2.0 408 Request Timeout#015#012Via: SIP/2.0/UDP 2.2.2.3:7000;branch=z9hG4bK2qqrqaBz;rport=11000;received=2.2.2.3#015#012From: sip:61811111111@1.1.1.1:1839;rinstance=465b316d54c82405;transport=UDP;tag=registrar#015#012To: sip:61811111111@1.1.1.1:1839;rinstance=465b316d54c82405;transport=UDP;tag=1b21055f14005339d2c7494a35d9a8a4-400d#015#012CSeq: 10 OPTIONS#015#012Call-ID: 8-744F097C-5E21A0B3000220B5-C6297700#015#012Content-Length: 0#015#012#015#012--++--
Jan 17 22:55:31 sems1 sems[9987]: [10013/core/sip/udp_trsp.cpp:288] DEBUG: send msg via UDP from 2.2.2.3:7000 to 192.168.120.67:5060#012--++--#012OPTIONS sip:61811111111@192.168.120.67:5060;rinstance=71829ee685b75ba8;transport=UDP SIP/2.0#015#012Via: SIP/2.0/UDP 2.2.2.3:7000;branch=z9hG4bKNQvjfaGl;rport#015#012From: sip:61811111111@192.168.120.67:5060;rinstance=71829ee685b75ba8;transport=UDP;tag=registrar#015#012To: sip:61811111111@192.168.120.67:5060;rinstance=71829ee685b75ba8;transport=UDP#015#012CSeq: 10 OPTIONS#015#012Call-ID: 8-385AD3F3-5E21A0B30006DB70-C6297700#015#012Max-Forwards: 70#015#012User-Agent: SBC 1.8.34-5#015#012Contact: <sip:2.2.2.3:7000;transport=udp>#015#012Content-Length: 0#015#012#015#012--++--
Jan 17 22:55:31 sems1 sems[9987]: [10013/core/sip/udp_trsp.cpp:288] DEBUG: send msg via UDP from 2.2.2.3:7000 to 2.2.2.2:5060#012--++--#012OPTIONS sip:61811111111@1.1.1.1:1844;rinstance=4c2f65e0234bf901;transport=UDP SIP/2.0#015#012Via: SIP/2.0/UDP 2.2.2.3:7000;branch=z9hG4bKLNP34a77;rport#015#012From: sip:61811111111@1.1.1.1:1844;rinstance=4c2f65e0234bf901;transport=UDP;tag=registrar#015#012To: sip:61811111111@1.1.1.1:1844;rinstance=4c2f65e0234bf901;transport=UDP#015#012CSeq: 10 OPTIONS#015#012Call-ID: 8-3A610252-5E21A0B30006E0F2-C6297700#015#012Route: <sip:2.2.2.2;lr;received=sip:1.1.1.1:1844;r2=on>,<sip:2.2.2.2;lr;received=sip:1.1.1.1:1844;r2=on>#015#012Max-Forwards: 70#015#012User-Agent: SBC 1.8.34-5#015#012Contact: <sip:2.2.2.3:7000;transport=udp>#015#012Content-Length: 0#015#012#015#012--++--
Jan 17 22:55:31 sems1 sems[9987]: [10013/core/sip/udp_trsp.cpp:288] DEBUG: send msg via UDP from 2.2.2.3:7000 to 2.2.2.2:5060#012--++--#012OPTIONS sip:61811111111@1.1.1.1:1844;rinstance=a358a41959160cdb;transport=UDP SIP/2.0#015#012Via: SIP/2.0/UDP 2.2.2.3:7000;branch=z9hG4bKmGGrqas8;rport#015#012From: sip:61811111111@1.1.1.1:1844;rinstance=a358a41959160cdb;transport=UDP;tag=registrar#015#012To: sip:61811111111@1.1.1.1:1844;rinstance=a358a41959160cdb;transport=UDP#015#012CSeq: 10 OPTIONS#015#012Call-ID: 8-29D51CC9-5E21A0B30006E2A7-C6297700#015#012Route: <sip:2.2.2.2;lr;received=sip:1.1.1.1:1844;r2=on>,<sip:2.2.2.2;lr;received=sip:1.1.1.1:1844;r2=on>#015#012Max-Forwards: 70#015#012User-Agent: SBC 1.8.34-5#015#012Contact: <sip:2.2.2.3:7000;transport=udp>#015#012Content-Length: 0#015#012#015#012--++--
Jan 17 22:55:31 sems1 sems[9987]: [10013/core/sip/udp_trsp.cpp:288] DEBUG: send msg via UDP from 2.2.2.3:7000 to 2.2.2.2:5060#012--++--#012OPTIONS sip:61811111111@1.1.1.1:1839;rinstance=a407a9cfe9f90358;transport=UDP SIP/2.0#015#012Via: SIP/2.0/UDP 2.2.2.3:7000;branch=z9hG4bKlhYRta9a;rport#015#012From: sip:61811111111@1.1.1.1:1839;rinstance=a407a9cfe9f90358;transport=UDP;tag=registrar#015#012To: sip:61811111111@1.1.1.1:1839;rinstance=a407a9cfe9f90358;transport=UDP#015#012CSeq: 10 OPTIONS#015#012Call-ID: 8-067DD426-5E21A0B30006E45F-C6297700#015#012Route: <sip:2.2.2.2;lr;received=sip:1.1.1.1:1839;r2=on>,<sip:2.2.2.2;lr;received=sip:1.1.1.1:1839;r2=on>#015#012Max-Forwards: 70#015#012User-Agent: SBC 1.8.34-5#015#012Contact: <sip:2.2.2.3:7000;transport=udp>#015#012Content-Length: 0#015#012#015#012--++--
Jan 17 22:55:31 sems1 sems[9987]: [10013/core/sip/udp_trsp.cpp:288] DEBUG: send msg via UDP from 2.2.2.3:7000 to 2.2.2.2:5060#012--++--#012OPTIONS sip:61811111111@1.1.1.2:5060;rinstance=1850b6b73d5f058e;transport=UDP SIP/2.0#015#012Via: SIP/2.0/UDP 2.2.2.3:7000;branch=z9hG4bKLkRR1ak7;rport#015#012From: sip:61811111111@1.1.1.2:5060;rinstance=1850b6b73d5f058e;transport=UDP;tag=registrar#015#012To: sip:61811111111@1.1.1.2:5060;rinstance=1850b6b73d5f058e;transport=UDP#015#012CSeq: 10 OPTIONS#015#012Call-ID: 8-36F35128-5E21A0B30006E619-C6297700#015#012Route: <sip:2.2.2.2;lr;received=sip:1.1.1.2:5060;r2=on>,<sip:2.2.2.2;lr;received=sip:1.1.1.2:5060;r2=on>#015#012Max-Forwards: 70#015#012User-Agent: SBC 1.8.34-5#015#012Contact: <sip:2.2.2.3:7000;transport=udp>#015#012Content-Length: 0#015#012#015#012--++--
Jan 17 22:55:31 sems1 sems[9987]: [10013/core/sip/udp_trsp.cpp:288] DEBUG: send msg via UDP from 2.2.2.3:7000 to 192.168.120.67:5060#012--++--#012OPTIONS sip:61811111111@192.168.120.67:5060;rinstance=db8dacf68d2166a5;transport=UDP SIP/2.0#015#012Via: SIP/2.0/UDP 2.2.2.3:7000;branch=z9hG4bKHcAGZaDW;rport#015#012From: sip:61811111111@192.168.120.67:5060;rinstance=db8dacf68d2166a5;transport=UDP;tag=registrar#015#012To: sip:61811111111@192.168.120.67:5060;rinstance=db8dacf68d2166a5;transport=UDP#015#012CSeq: 10 OPTIONS#015#012Call-ID: 8-6312E3BB-5E21A0B30006E7E6-C6297700#015#012Max-Forwards: 70#015#012User-Agent: SBC 1.8.34-5#015#012Contact: <sip:2.2.2.3:7000;transport=udp>#015#012Content-Length: 0#015#012#015#012--++--
Jan 17 22:55:31 sems1 sems[9987]: [10013/core/sip/udp_trsp.cpp:288] DEBUG: send msg via UDP from 2.2.2.3:7000 to 2.2.2.2:5060#012--++--#012OPTIONS sip:61811111111@1.1.1.1:1839;rinstance=6253a006915a2566;transport=UDP SIP/2.0#015#012Via: SIP/2.0/UDP 2.2.2.3:7000;branch=z9hG4bKLf1Cna6W;rport#015#012From: sip:61811111111@1.1.1.1:1839;rinstance=6253a006915a2566;transport=UDP;tag=registrar#015#012To: sip:61811111111@1.1.1.1:1839;rinstance=6253a006915a2566;transport=UDP#015#012CSeq: 10 OPTIONS#015#012Call-ID: 8-0B925E7E-5E21A0B30008092F-C6297700#015#012Route: <sip:2.2.2.2;lr;received=sip:1.1.1.1:1839;r2=on>,<sip:2.2.2.2;lr;received=sip:1.1.1.1:1839;r2=on>#015#012Max-Forwards: 70#015#012User-Agent: SBC 1.8.34-5#015#012Contact: <sip:2.2.2.3:7000;transport=udp>#015#012Content-Length: 0#015#012#015#012--++--
Jan 17 22:55:31 sems1 sems[9987]: [10013/core/sip/udp_trsp.cpp:288] DEBUG: send msg via UDP from 2.2.2.3:7000 to 2.2.2.2:5060#012--++--#012OPTIONS sip:61811111111@1.1.1.1:1839;rinstance=8d3d8ae569eb7b47;transport=UDP SIP/2.0#015#012Via: SIP/2.0/UDP 2.2.2.3:7000;branch=z9hG4bKAJyXbas1;rport#015#012From: sip:61811111111@1.1.1.1:1839;rinstance=8d3d8ae569eb7b47;transport=UDP;tag=registrar#015#012To: sip:61811111111@1.1.1.1:1839;rinstance=8d3d8ae569eb7b47;transport=UDP#015#012CSeq: 10 OPTIONS#015#012Call-ID: 8-6C748C33-5E21A0B300080AE9-C6297700#015#012Route: <sip:2.2.2.2;lr;received=sip:1.1.1.1:1839;r2=on>,<sip:2.2.2.2;lr;received=sip:1.1.1.1:1839;r2=on>#015#012Max-Forwards: 70#015#012User-Agent: SBC 1.8.34-5#015#012Contact: <sip:2.2.2.3:7000;transport=udp>#015#012Content-Length: 0#015#012#015#012--++--
Jan 17 22:55:31 sems1 sems[9987]: [10013/core/sip/udp_trsp.cpp:288] DEBUG: send msg via UDP from 2.2.2.3:7000 to 192.168.120.67:5060#012--++--#012OPTIONS sip:61811111111@192.168.120.67:5060;rinstance=be965871f06f1210;transport=UDP SIP/2.0#015#012Via: SIP/2.0/UDP 2.2.2.3:7000;branch=z9hG4bKbexGZawN;rport#015#012From: sip:61811111111@192.168.120.67:5060;rinstance=be965871f06f1210;transport=UDP;tag=registrar#015#012To: sip:61811111111@192.168.120.67:5060;rinstance=be965871f06f1210;transport=UDP#015#012CSeq: 10 OPTIONS#015#012Call-ID: 8-7EB710B7-5E21A0B300080CB1-C6297700#015#012Max-Forwards: 70#015#012User-Agent: SBC 1.8.34-5#015#012Contact: <sip:2.2.2.3:7000;transport=udp>#015#012Content-Length: 0#015#012#015#012--++--

dmitry.s · January 17, 2020, 12:49pm

formatting

dmitry.s · January 25, 2020, 4:52pm

As I see from your logs sems sent OPTIONS to different URI so this is not single aor

rabbani · January 27, 2020, 11:47pm

Thanks, Dmitry, yes that is the issue. our Yeti platform has 1x AoR record only (since the username is same) but the AoR was used with different source IP addresses/locations (sip client behind nat) to SIP Register with the registrar (hence the different contact/URI address) but somehow, based on previous source ip addresses (that no longer exists) sems is still trying to send OPTIONS. For Eg:

sip:61811111111@1.1.1.1:1839 (IP: 1.1.1.1 no longer exists)
sip:61811111111@1.1.1.2:5060 (IP: 1.1.1.2 exists)

Is it normal for Sems to send OPTION to those IP Addresses that no longer exist or SIP Client that are not registered? as I have checked the 127.0.0.1:6379> keys '*' result (empty list or set)

dmitry.s · January 28, 2020, 9:09am

, based on previous source ip addresses (that no longer exists)

Could you explain what do you mean under “no longer exists”? Was it deregistered by client or registration was expired?

rabbani · January 28, 2020, 10:12pm

Change in location of the SIP Client. For Eg:
SIP client location A IP: 1.1.1.1
SIP client location B IP: 1.1.1.2

Scenario A:
The SIP client de-registered from Location A and registered in Location B, Therefore, the Public address has changed and the location A IP is no longer active.

Scenario B:
The SIP client is on a network whose public and private ip is dynamic

Scenario C: (Limited but still exists)
The SIP client with multiple registrations therefore, same username registered with different public and private IP addresses.

rabbani · January 30, 2020, 2:44am

Out of curiosity, I have disabled the sip gateway with Dynamin AoR but sems is still sending OPTIONS packets, is that expected behavior? I would imagine if a SIP Gateway is disabled from Yeti, it is pretty unnecessary to send Option even for NAT handling or keepalive purpose.

redis-cli
127.0.0.1:6379> keys ‘*’
(empty list or set)

yeti-cli:13> yeti.show.registrations

Took 0.0010 seconds

dmitry.s · January 30, 2020, 8:17am

Yeti will send OPTIONS until registration expired or remote gateway removed it.

rabbani · January 30, 2020, 10:28pm

well in that case, it sums up this topic mostly but I would suggest to find a way to debug why OPTION is sent when sip client is deregistered or even expired

dmitry.s · January 30, 2020, 11:08pm

Way to debug is pretty simple - we just need pcap with register, unregister and related options, as I asked before.

rabbani · January 30, 2020, 11:44pm

No worries, I will have the pcap available to you soon. sorry about the delay, we are trying to check and test all our configs just to be sure we have our setup right before we send out the data for you to analyse.

FYI, Since we have Master-Slaves Redis server setup per POP, I found keeping slaves in a read-only mode avoids SEMS directly writing SIP REGISTER key values into multiple redis-server slaves as loadbalancer is used to round robin SIP traffic.

Previously, we had in redis.conf slave-read-only no which caused a lots of inconsistent value. We changed it to slave-read-only yes things are looking much better now. I’m not sure, but it seems in yeti-management (system.cfg), there is no fail over config in case master redis-server service is stopped/failed.

dmitry.s · February 1, 2020, 8:24am

Right configured SEMS will not write anything to slave database so slave-read-only should not change anything.