dmq_usrloc replication results in garbled AOR's on client nodes #237

00Asgaroth00 · 2015-07-07T15:00:03Z

Hi,

I have come accross an issue whereby when I replicate registration information to client nodes on the dmq bus, the AOR's of the client nodes for that replication event are garbled.

I am running the release version of kamailio v4.3.0 with the following 3 patches applied:

https://github.com/kamailio/kamailio/commit/894796f6f1fa2d2778ace5c56f58d204ea06efc2.patch
https://github.com/kamailio/kamailio/commit/039231a3b61c00fe36e868417144daa9f04936ba.patch
https://github.com/kamailio/kamailio/commit/733fd5daf74963b152a2964f9eea1a6fff91858a.patch

# kamailio -V
version: kamailio 4.3.0 (x86_64/linux) c6aa95
flags: STATS: Off, USE_TCP, USE_TLS, TLS_HOOKS, USE_RAW_SOCKS, DISABLE_NAGLE, USE_MCAST, DNS_IP_HACK, SHM_MEM, SHM_MMAP, PKG_MALLOC, F_MALLOC, DBG_F_MALLOC, USE_FUTEX, FAST_LOCK-ADAPTIVE_WAIT, USE_DNS_CACHE, USE_DNS_FAILOVER, USE_NAPTR, USE_DST_BLACKLIST, HAVE_RESOLV_RES
ADAPTIVE_WAIT_LOOPS=1024, MAX_RECV_BUFFER_SIZE 262144, MAX_LISTEN 16, MAX_URI_SIZE 1024, BUF_SIZE 65535, DEFAULT PKG_SIZE 8MB
poll method support: poll, epoll_lt, epoll_et, sigio_rt, select.
id: c6aa95 
compiled on 15:27:56 Jul  7 2015 with gcc 4.4.7

Here is a sipgrep trace of the messaging of the UAC registering and the corresponding KDMQ messages sent to the 2 client nodes on the DMQ bus:

U 2015/07/07 15:35:33.103946 10.7.0.109:5060 -> 10.7.0.173:5060

REGISTER sip:subscriber_domain;transport=UDP SIP/2.0.
Via: SIP/2.0/UDP 10.7.0.109;branch=z9hG4bK6c8.182de67239d973bafe4e581e6574d8a2.0.
Via: SIP/2.0/UDP 192.168.1.238:54270;rport=57937;received=212.2.160.202;branch=z9hG4bK-524287-1---6ab5bde6fb54f05f.
Max-Forwards: 69.
Contact: <sip:subscriber_name@192.168.1.238:54270;alias=212.2.160.202~57937~1;rinstance=f07ae8c64e7a1962;transport=UDP>.
To: <sip:subscriber_name@subscriber_domain;transport=UDP>.
From: <sip:subscriber_name@subscriber_domain;transport=UDP>;tag=06548a73.
Call-ID: iwGubUeCiNBMYcFqL4Kf4g...
CSeq: 1 REGISTER.
Expires: 110.
Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE.
Supported: replaces, norefersub, extended-refer, timer, outbound, path, X-cisco-serviceuri.
User-Agent: Z 3.7.30891 r30851.
Allow-Events: presence, kpml.
Content-Length: 0.
Path: <sip:10.7.0.109;lr;received=sip:212.2.160.202:57937>.
.

U 2015/07/07 15:35:33.104583 10.7.0.173:5060 -> 10.7.0.109:5060

SIP/2.0 401 Unauthorized.
Via: SIP/2.0/UDP 10.7.0.109;branch=z9hG4bK6c8.182de67239d973bafe4e581e6574d8a2.0.
Via: SIP/2.0/UDP 192.168.1.238:54270;rport=57937;received=212.2.160.202;branch=z9hG4bK-524287-1---6ab5bde6fb54f05f.
To: <sip:subscriber_name@subscriber_domain;transport=UDP>;tag=a55e8da2dec08a1e8faf1efe616c4a58.1527.
From: <sip:subscriber_name@subscriber_domain;transport=UDP>;tag=06548a73.
Call-ID: iwGubUeCiNBMYcFqL4Kf4g...
CSeq: 1 REGISTER.
WWW-Authenticate: Digest realm="subscriber_domain", nonce="VZvk4VWb47UOTbXkF6UTXuGtMmOr1krjmNayRoRwfIGueG5nlHEkwEmw7rOA", qop="auth".
Server: reg01.
Content-Length: 0.
.

U 2015/07/07 15:35:33.148675 10.7.0.109:5060 -> 10.7.0.173:5060

REGISTER sip:subscriber_domain;transport=UDP SIP/2.0.
Via: SIP/2.0/UDP 10.7.0.109;branch=z9hG4bK3c8.fdc7855158bceefc94eb231cfd28c710.0.
Via: SIP/2.0/UDP 192.168.1.238:54270;rport=57937;received=212.2.160.202;branch=z9hG4bK-524287-1---7ce5e69b3282c0a4.
Max-Forwards: 69.
Contact: <sip:subscriber_name@192.168.1.238:54270;alias=212.2.160.202~57937~1;rinstance=f07ae8c64e7a1962;transport=UDP>.
To: <sip:subscriber_name@subscriber_domain;transport=UDP>.
From: <sip:subscriber_name@subscriber_domain;transport=UDP>;tag=06548a73.
Call-ID: iwGubUeCiNBMYcFqL4Kf4g...
CSeq: 2 REGISTER.
Expires: 110.
Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE.
Supported: replaces, norefersub, extended-refer, timer, outbound, path, X-cisco-serviceuri.
User-Agent: Z 3.7.30891 r30851.
Authorization: Digest username="subscriber_name",realm="subscriber_domain",nonce="VZvk4VWb47UOTbXkF6UTXuGtMmOr1krjmNayRoRwfIGueG5nlHEkwEmw7rOA",uri="sip:subscriber_domain;transport=UDP",response="0f65399a35348e73d88fe8fccdff972f",cnonce="acef54d83f88bc6174ef900d1c202aee",nc=00000001,qop=auth,algorithm=MD5.
Allow-Events: presence, kpml.
Content-Length: 0.
Path: <sip:10.7.0.109;lr;received=sip:212.2.160.202:57937>.
.

Unknown METHOD: KDMQ

U 2015/07/07 15:35:33.151528 10.6.0.173:5060 -> 10.6.0.175:5060

KDMQ sip:usrloc@10.6.0.175:5060 SIP/2.0.
Via: SIP/2.0/UDP 10.6.0.173;branch=z9hG4bK9cbc.6c89b871000000000000000000000000.0.
To: <sip:usrloc@10.6.0.175:5060>.
From: <sip:usrloc@10.6.0.173:5060>;tag=390c95c339281829d3cea6f43c8512cb-0295.
CSeq: 10 KDMQ.
Call-ID: 7f7531821a1befa0-18771@10.6.0.173.
Content-Length: 499.
User-Agent: kamailio (reg01).
Max-Forwards: 1.
Content-Type: application/json.
.
{"action":1,"aor":"subscriber_name@subscriber_domain","ruid":"uloc-559bdf82-4953-b","c":"sip:subscriber_name@192.168.1.238:54270;alias=212.2.160.202~57937~1;rinstance=f07ae8c64e7a1962;transport=UDP","received":"sip:212.2.160.202:57937","path":"<sip:10.7.0.109;lr;received=sip:212.2.160.202:57937>","callid":"iwGubUeCiNBMYcFqL4Kf4g..","user_agent":"Z 3.7.30891 r30851","instance":"","expires":1436279846,"cseq":2,"flags":0,"cflags":64,"q":-1,"last_modified":1436279733,"methods":5087,"reg_id":0}
Unknown METHOD: KDMQ

U 2015/07/07 15:35:33.151629 10.6.0.173:5060 -> 10.6.0.174:5060

KDMQ sip:usrloc@10.6.0.174:5060 SIP/2.0.
Via: SIP/2.0/UDP 10.6.0.173;branch=z9hG4bKacbc.8ccb40f3000000000000000000000000.0.
To: <sip:usrloc@10.6.0.174:5060>.
From: <sip:usrloc@10.6.0.173:5060>;tag=390c95c339281829d3cea6f43c8512cb-7c1a.
CSeq: 10 KDMQ.
Call-ID: 7f7531821a1befa1-18771@10.6.0.173.
Content-Length: 499.
User-Agent: kamailio (reg01).
Max-Forwards: 1.
Content-Type: application/json.
.
{"action":1,"aor":"subscriber_name@subscriber_domain","ruid":"uloc-559bdf82-4953-b","c":"sip:subscriber_name@192.168.1.238:54270;alias=212.2.160.202~57937~1;rinstance=f07ae8c64e7a1962;transport=UDP","received":"sip:212.2.160.202:57937","path":"<sip:10.7.0.109;lr;received=sip:212.2.160.202:57937>","callid":"iwGubUeCiNBMYcFqL4Kf4g..","user_agent":"Z 3.7.30891 r30851","instance":"","expires":1436279846,"cseq":2,"flags":0,"cflags":64,"q":-1,"last_modified":1436279733,"methods":5087,"reg_id":0}

U 2015/07/07 15:35:33.151750 10.7.0.173:5060 -> 10.7.0.109:5060

SIP/2.0 200 OK.
Via: SIP/2.0/UDP 10.7.0.109;branch=z9hG4bK3c8.fdc7855158bceefc94eb231cfd28c710.0.
Via: SIP/2.0/UDP 192.168.1.238:54270;rport=57937;received=212.2.160.202;branch=z9hG4bK-524287-1---7ce5e69b3282c0a4.
To: <sip:subscriber_name@subscriber_domain;transport=UDP>;tag=a55e8da2dec08a1e8faf1efe616c4a58.2d89.
From: <sip:subscriber_name@subscriber_domain;transport=UDP>;tag=06548a73.
Call-ID: iwGubUeCiNBMYcFqL4Kf4g...
CSeq: 2 REGISTER.
Contact: <sip:subscriber_name@192.168.1.238:54270;alias=212.2.160.202~57937~1;rinstance=f07ae8c64e7a1962;transport=UDP>;expires=113;received="sip:212.2.160.202:57937".
Server: reg01.
Content-Length: 0.
.

Here is the output of "kamctl ul show" on the node that the UAC registered on:

[reg01]#  kamctl ul show        
Domain:: location table=1024 records=1 max_slot=1
        AOR:: subscriber_name@subscriber_domain
                Contact:: sip:subscriber_name@192.168.1.238:54270;alias=212.2.160.202~57937~1;rinstance=f07ae8c64e7a1962;transport=UDP Q=
                        Expires:: 22
                        Callid:: iwGubUeCiNBMYcFqL4Kf4g..
                        Cseq:: 2
                        User-agent:: Z 3.7.30891 r30851
                        Received:: sip:212.2.160.202:57937
                        Path:: <sip:10.7.0.109;lr;received=sip:212.2.160.202:57937>
                        State:: CS_NEW
                        Flags:: 0
                        Cflag:: 64
                        Socket:: udp:10.7.0.173:5060
                        Methods:: 5087
                        Ruid:: uloc-559bdf82-4953-b
                        Reg-Id:: 0
                        Last-Keepalive:: 1436279733
                        Last-Modified:: 1436279733

And here is the output of "kamctl ul show" on the two client nodes on the bus:

[reg02]# kamctl ul show
Domain:: location table=1024 records=1 max_slot=1
        AOR:: À.e�

[reg03]# kamctl ul show
Domain:: location table=1024 records=1 max_slot=1
        AOR:: Àn"�

My dmq related parameter settings are as follows:

# grep -i dmq module_definitions.cfg 
loadmodule "dmq.so"
loadmodule "dmq_usrloc.so"
# ----- dmq params -----
modparam("dmq", "server_address", DMQ_ADDRESS)
modparam("dmq", "notification_address", "sip:sip-registrars:5060")
modparam("dmq", "multi_notify", 1)
modparam("dmq", "num_workers", 4)
# ----- dmq_usrloc params -----
modparam("dmq_usrloc", "enable", 1)

The "sip-registrars" host/domain name resolves to the following 3 addresses (via DNS):

10.6.0.173
10.6.0.174
10.6.0.175

I am getting the following nathelper errors in the logs of the client nodes too, I presume, because of the garbeld AOR:

Jul  7 15:35:45 reg02 /usr/sbin/kamailio[5466]: ERROR: <core> [parser/parse_rr.c:71]: do_parse_rr_body(): parse_rr(): Error while parsing name-addr ()
Jul  7 15:35:45 reg02 /usr/sbin/kamailio[5466]: ERROR: <core> [parser/parse_rr.c:454]: get_path_dst_uri(): failed to parse Path body
Jul  7 15:35:45 reg02 /usr/sbin/kamailio[5466]: ERROR: nathelper [nathelper.c:2147]: nh_timer(): failed to get dst_uri for Path
Jul  7 15:35:45 reg02 /usr/sbin/kamailio[5466]: ERROR: <core> [parser/parse_rr.c:71]: do_parse_rr_body(): parse_rr(): Error while parsing name-addr ()
Jul  7 15:35:45 reg02 /usr/sbin/kamailio[5466]: ERROR: <core> [parser/parse_rr.c:454]: get_path_dst_uri(): failed to parse Path body
Jul  7 15:35:45 reg02 /usr/sbin/kamailio[5466]: ERROR: nathelper [nathelper.c:2147]: nh_timer(): failed to get dst_uri for Path

Jul  7 15:35:58 reg03 /usr/sbin/kamailio[28790]: ERROR: <core> [parser/parse_rr.c:71]: do_parse_rr_body(): parse_rr(): Error while parsing name-addr ()
Jul  7 15:35:58 reg03 /usr/sbin/kamailio[28790]: ERROR: <core> [parser/parse_rr.c:454]: get_path_dst_uri(): failed to parse Path body
Jul  7 15:35:58 reg03 /usr/sbin/kamailio[28790]: ERROR: nathelper [nathelper.c:2147]: nh_timer(): failed to get dst_uri for Path
Jul  7 15:35:58 reg03 /usr/sbin/kamailio[28790]: ERROR: <core> [parser/parse_rr.c:71]: do_parse_rr_body(): parse_rr(): Error while parsing name-addr ()
Jul  7 15:35:58 reg03 /usr/sbin/kamailio[28790]: ERROR: <core> [parser/parse_rr.c:454]: get_path_dst_uri(): failed to parse Path body
Jul  7 15:35:58 reg03 /usr/sbin/kamailio[28790]: ERROR: nathelper [nathelper.c:2147]: nh_timer(): failed to get dst_uri for Path
Jul  7 15:35:58 reg03 /usr/sbin/kamailio[28790]: ERROR: <core> [parser/parse_rr.c:71]: do_parse_rr_body(): parse_rr(): Error while parsing name-addr ()
Jul  7 15:35:58 reg03 /usr/sbin/kamailio[28790]: ERROR: <core> [parser/parse_rr.c:454]: get_path_dst_uri(): failed to parse Path body
Jul  7 15:35:58 reg03 /usr/sbin/kamailio[28790]: ERROR: nathelper [nathelper.c:2147]: nh_timer(): failed to get dst_uri for Path

Please let me know if you require any further info from me.

The text was updated successfully, but these errors were encountered:

00Asgaroth00 · 2015-07-14T09:47:42Z

Hi, any thoughts wrt to this issue, could it be be related to a missing module being loaded?

charlesrchance · 2015-07-14T10:35:20Z

Hi, I'll have some time later today to look at it but it's unlikely to be a missing module.

00Asgaroth00 · 2015-07-14T11:11:47Z

Thanks Charles, let me know if you need anything from me.

charlesrchance · 2015-07-14T22:16:43Z

Hi, I have just committed the below patch - can you confirm the issue is resolved?

99f7d67

Cheers,
Charles

pwarnold · 2015-07-15T06:51:40Z

Thanks Charles, I can confirm that 99f7d67 fixes this issue.

00Asgaroth00 · 2015-07-15T07:46:25Z

Hi Charles, thanks for taking a look, unfortunately I'm away for a couple days, I should be able to confirm on Saturday/Sunday.

charlesrchance · 2015-07-16T19:43:06Z

Hi,

It seems 99f7d67 has fixed the issue and has been confirmed elsewhere.

Please feel free to reopen if your tests show otherwise.

Cheers,
Charles

pwarnold mentioned this issue Jul 15, 2015

Crash on start up synchronisation with dmq_usrloc #244

Closed

charlesrchance closed this as completed Jul 16, 2015

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

dmq_usrloc replication results in garbled AOR's on client nodes #237

dmq_usrloc replication results in garbled AOR's on client nodes #237

00Asgaroth00 commented Jul 7, 2015

00Asgaroth00 commented Jul 14, 2015

charlesrchance commented Jul 14, 2015

00Asgaroth00 commented Jul 14, 2015

charlesrchance commented Jul 14, 2015

pwarnold commented Jul 15, 2015

00Asgaroth00 commented Jul 15, 2015

charlesrchance commented Jul 16, 2015

dmq_usrloc replication results in garbled AOR's on client nodes #237

dmq_usrloc replication results in garbled AOR's on client nodes #237

Comments

00Asgaroth00 commented Jul 7, 2015

00Asgaroth00 commented Jul 14, 2015

charlesrchance commented Jul 14, 2015

00Asgaroth00 commented Jul 14, 2015

charlesrchance commented Jul 14, 2015

pwarnold commented Jul 15, 2015

00Asgaroth00 commented Jul 15, 2015

charlesrchance commented Jul 16, 2015