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

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

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

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.

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












192.168.120.151 - Yeti address
192.168.120.56 - Zoiper Softphone

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

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

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

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--++--

formatting

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

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)

, 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?

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.

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

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

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

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

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.

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