[sr-dev] [kamailio/kamailio] [uac.reg_keep_callid] attempts to refresh registration reusing Call-ID fail with timeout (#931)

Peter Colberg notifications at github.com
Mon Jan 16 02:34:10 CET 2017 

I am testing commit 1dc6da87180a01f21554f2e857ec280814ba05e5 compiled from source on Debian unstable/amd64.

When the parameter [uac.reg_keep_callid](http://www.kamailio.org/docs/modules/devel/modules/uac.html#uac.p.reg-keep-callid) is enabled to refresh registrations reusing the same Call-Id, attempts to update the registration fail with a timeout [`uac_reg_tm_callback(): got sip response 408 while registering`], which causes kamailio to subsequently register (successfully) using a new Call-Id.

This is the first registration after starting kamilio. Note how the `From:` header contains a `tag=`.
```
U 2017/01/15 18:57:18.338380 1.2.3.4:5060 -> 5.6.7.8:5060
REGISTER sip:sip.example.org SIP/2.0.
Via: SIP/2.0/UDP 1.2.3.4;branch=z9hG4bKc4d5.b35f6627000000000000000000000000.0.
To: <sip:11111111 at sip.example.org>.
From: <sip:11111111 at sip.example.org>;tag=533cb9e91f4b999cf76861cbb9ed54ed-48c9.
CSeq: 10 REGISTER.
Call-ID: 705a8b605d872669-5747 at 127.0.0.1.
Max-Forwards: 70.
Content-Length: 0.
User-Agent: kamailio (5.0.0-pre0 (x86_64/linux)).
Contact: <sip:12345678 at 1.2.3.4:5060>.
Expires: 600.

U 2017/01/15 18:57:18.436734 5.6.7.8:5060 -> 1.2.3.4:5060
SIP/2.0 401 Unauthorized.
Via: SIP/2.0/UDP 1.2.3.4;branch=z9hG4bKc4d5.b35f6627000000000000000000000000.0;received=1.2.3.4;rport=5060.
From: <sip:11111111 at sip.example.org>;tag=533cb9e91f4b999cf76861cbb9ed54ed-48c9.
To: <sip:11111111 at sip.example.org>;tag=as4c52c89f.
Call-ID: 705a8b605d872669-5747 at 127.0.0.1.
CSeq: 10 REGISTER.
Server: example.org.
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE.
Supported: replaces, timer.
WWW-Authenticate: Digest algorithm=MD5, realm="sip.example.org", nonce="7cdc4b7e".
Content-Length: 0.

U 2017/01/15 18:57:18.438460 1.2.3.4:5060 -> 5.6.7.8:5060
REGISTER sip:sip.example.org SIP/2.0.
Via: SIP/2.0/UDP 1.2.3.4;branch=z9hG4bKd4d5.73d1add4000000000000000000000000.0.
To: <sip:11111111 at sip.example.org>.
From: <sip:11111111 at sip.example.org>;tag=533cb9e91f4b999cf76861cbb9ed54ed-48c9.
CSeq: 11 REGISTER.
Call-ID: 705a8b605d872669-5747 at 127.0.0.1.
Max-Forwards: 70.
Content-Length: 0.
User-Agent: kamailio (5.0.0-pre0 (x86_64/linux)).
Contact: <sip:12345678 at 1.2.3.4:5060>.
Expires: 600.
Authorization: Digest username="11111111", realm="sip.example.org", nonce="7cdc4b7e", uri="sip:sip.example.org", response="30f31eaf139730e8f54e043a53ddbc1e", algorithm=MD5.

U 2017/01/15 18:57:18.537370 5.6.7.8:5060 -> 1.2.3.4:5060
SIP/2.0 200 OK.
Via: SIP/2.0/UDP 1.2.3.4;branch=z9hG4bKd4d5.73d1add4000000000000000000000000.0;received=1.2.3.4;rport=5060.
From: <sip:11111111 at sip.example.org>;tag=533cb9e91f4b999cf76861cbb9ed54ed-48c9.
To: <sip:11111111 at sip.example.org>;tag=as4c52c89f.
Call-ID: 705a8b605d872669-5747 at 127.0.0.1.
CSeq: 11 REGISTER.
Server: example.org.
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE.
Supported: replaces, timer.
Expires: 600.
Contact: <sip:12345678 at 1.2.3.4:5060>;expires=600.
Date: Sun, 15 Jan 2017 23:57:18 GMT.
Content-Length: 0.
```

After 9 minutes (or 1 minute before expiry), kamilio attempts to update the registration, sending out 10 requests of which none is answered by the upstream provider. Note how the `From:` header is missing the above `tag=`. I suspect that the incomplete `From:` is the reason the upstream provider is not answering.
```
U 2017/01/15 19:06:18.850555 1.2.3.4:5060 -> 5.6.7.8:5060
REGISTER sip:sip.example.org SIP/2.0.
Via: SIP/2.0/UDP 1.2.3.4;branch=z9hG4bKa4d5.c4f157d1000000000000000000000000.0.
To: <sip:11111111 at sip.example.org>.
From: <sip:11111111 at sip.example.org>.
CSeq: 12 REGISTER.
Call-ID: 705a8b605d872669-5747 at 127.0.0.1.
Max-Forwards: 70.
Content-Length: 0.
User-Agent: kamailio (5.0.0-pre0 (x86_64/linux)).
Contact: <sip:12345678 at 1.2.3.4:5060>.
Expires: 600.

U 2017/01/15 19:06:19.313086 1.2.3.4:5060 -> 5.6.7.8:5060
REGISTER sip:sip.example.org SIP/2.0.
Same headers as above.

U 2017/01/15 19:06:20.312741 1.2.3.4:5060 -> 5.6.7.8:5060
REGISTER sip:sip.example.org SIP/2.0.
Same headers as above.

U 2017/01/15 19:06:22.312706 1.2.3.4:5060 -> 5.6.7.8:5060
REGISTER sip:sip.example.org SIP/2.0.
Same headers as above.

U 2017/01/15 19:06:26.312796 1.2.3.4:5060 -> 5.6.7.8:5060
REGISTER sip:sip.example.org SIP/2.0.
Same headers as above.

U 2017/01/15 19:06:30.312725 1.2.3.4:5060 -> 5.6.7.8:5060
REGISTER sip:sip.example.org SIP/2.0.
Same headers as above.

U 2017/01/15 19:06:34.312725 1.2.3.4:5060 -> 5.6.7.8:5060
REGISTER sip:sip.example.org SIP/2.0.
Same headers as above.

U 2017/01/15 19:06:38.312711 1.2.3.4:5060 -> 5.6.7.8:5060
REGISTER sip:sip.example.org SIP/2.0.
Same headers as above.

U 2017/01/15 19:06:42.312710 1.2.3.4:5060 -> 5.6.7.8:5060
REGISTER sip:sip.example.org SIP/2.0.
Same headers as above.

U 2017/01/15 19:06:46.312701 1.2.3.4:5060 -> 5.6.7.8:5060
REGISTER sip:sip.example.org SIP/2.0.
Same headers as above.
```

Each registration attempt coincides with a log entry by the dialog module:
```
Jan 15 19:06:18 ERROR: dialog [dlg_handlers.c:676]: pre_match_parse(): failed to get From header
Jan 15 19:06:19 ERROR: dialog [dlg_handlers.c:676]: pre_match_parse(): failed to get From header
Jan 15 19:06:20 ERROR: dialog [dlg_handlers.c:676]: pre_match_parse(): failed to get From header
Jan 15 19:06:22 ERROR: dialog [dlg_handlers.c:676]: pre_match_parse(): failed to get From header
Jan 15 19:06:26 ERROR: dialog [dlg_handlers.c:676]: pre_match_parse(): failed to get From header
Jan 15 19:06:30 ERROR: dialog [dlg_handlers.c:676]: pre_match_parse(): failed to get From header
Jan 15 19:06:34 ERROR: dialog [dlg_handlers.c:676]: pre_match_parse(): failed to get From header
Jan 15 19:06:38 ERROR: dialog [dlg_handlers.c:676]: pre_match_parse(): failed to get From header
Jan 15 19:06:42 ERROR: dialog [dlg_handlers.c:676]: pre_match_parse(): failed to get From header
Jan 15 19:06:46 ERROR: dialog [dlg_handlers.c:676]: pre_match_parse(): failed to get From header
Jan 15 19:06:48 ERROR: uac [uac_reg.c:1031]: uac_reg_tm_callback(): got sip response 408 while registering [12345678]
```

After a minute kamilio successfully registers using a new Call-id and a `From:` with `tag=`.
```
U 2017/01/15 19:07:18.977094 1.2.3.4:5060 -> 5.6.7.8:5060
REGISTER sip:sip.example.org SIP/2.0.
Via: SIP/2.0/UDP 1.2.3.4;branch=z9hG4bKbfc5.0afdd3d1000000000000000000000000.0.
To: <sip:11111111 at sip.example.org>.
From: <sip:11111111 at sip.example.org>;tag=533cb9e91f4b999cf76861cbb9ed54ed-acbf.
CSeq: 10 REGISTER.
Call-ID: 705a8b605d87266a-5747 at 127.0.0.1.
Max-Forwards: 70.
Content-Length: 0.
User-Agent: kamailio (5.0.0-pre0 (x86_64/linux)).
Contact: <sip:12345678 at 1.2.3.4:5060>.
Expires: 600.

U 2017/01/15 19:07:19.075665 5.6.7.8:5060 -> 1.2.3.4:5060
SIP/2.0 401 Unauthorized.
Via: SIP/2.0/UDP 1.2.3.4;branch=z9hG4bKbfc5.0afdd3d1000000000000000000000000.0;received=1.2.3.4;rport=5060.
From: <sip:11111111 at sip.example.org>;tag=533cb9e91f4b999cf76861cbb9ed54ed-acbf.
To: <sip:11111111 at sip.example.org>;tag=as76317b94.
Call-ID: 705a8b605d87266a-5747 at 127.0.0.1.
CSeq: 10 REGISTER.
Server: example.org.
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE.
Supported: replaces, timer.
WWW-Authenticate: Digest algorithm=MD5, realm="sip.example.org", nonce="3e3a497f".
Content-Length: 0.

U 2017/01/15 19:07:19.077029 1.2.3.4:5060 -> 5.6.7.8:5060
REGISTER sip:sip.example.org SIP/2.0.
Via: SIP/2.0/UDP 1.2.3.4;branch=z9hG4bKcfc5.78f00452000000000000000000000000.0.
To: <sip:11111111 at sip.example.org>.
From: <sip:11111111 at sip.example.org>;tag=533cb9e91f4b999cf76861cbb9ed54ed-acbf.
CSeq: 11 REGISTER.
Call-ID: 705a8b605d87266a-5747 at 127.0.0.1.
Max-Forwards: 70.
Content-Length: 0.
User-Agent: kamailio (5.0.0-pre0 (x86_64/linux)).
Contact: <sip:12345678 at 1.2.3.4:5060>.
Expires: 600.
Authorization: Digest username="11111111", realm="sip.example.org", nonce="3e3a497f", uri="sip:sip.example.org", response="21534c252e323cd1da8b44d5d8830743", algorithm=MD5.

U 2017/01/15 19:07:19.176499 5.6.7.8:5060 -> 1.2.3.4:5060
SIP/2.0 200 OK.
Via: SIP/2.0/UDP 1.2.3.4;branch=z9hG4bKcfc5.78f00452000000000000000000000000.0;received=1.2.3.4;rport=5060.
From: <sip:11111111 at sip.example.org>;tag=533cb9e91f4b999cf76861cbb9ed54ed-acbf.
To: <sip:11111111 at sip.example.org>;tag=as76317b94.
Call-ID: 705a8b605d87266a-5747 at 127.0.0.1.
CSeq: 11 REGISTER.
Server: example.org.
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE.
Supported: replaces, timer.
Expires: 600.
Contact: <sip:12345678 at 1.2.3.4:5060>;expires=600.
Date: Mon, 16 Jan 2017 00:07:19 GMT.
Content-Length: 0.
```

` /etc/kamailio/kamailio.cfg`
```
#!KAMAILIO

debug=3

loadmodule "kex.so"
loadmodule "corex.so"
loadmodule "tm.so"
loadmodule "tmx.so"
loadmodule "sl.so"
loadmodule "rr.so"
loadmodule "pv.so"
loadmodule "db_text.so"
loadmodule "dialog.so"
loadmodule "uac.so"

#!define DBURL "text:///etc/kamailio/dbtext"

modparam("rr", "append_fromtag", 1)
modparam("dialog", "dlg_flag", 4)
modparam("dialog", "track_cseq_updates", 1)
modparam("uac", "restore_dlg", 1)
modparam("uac", "reg_db_url", DBURL)
modparam("uac", "reg_timer_interval", 60)
modparam("uac", "reg_retry_interval", 60)
modparam("uac", "reg_contact_addr", "1.2.3.4:5060")
modparam("uac", "reg_keep_callid", 1)

request_route {
	exit;
}
```

`/etc/kamailio/dbtext/uacreg`
```
l_uuid(string) l_username(string) l_domain(string) r_username(string) r_domain(string) realm(string) auth_username(string) auth_password(string) auth_proxy(string) expires(int) flags(int) reg_delay(int) 
12345678:user:domain.local:11111111:sip.example.org:sip.example.org:11111111:XXXXXXXXXXXXXXXX:sip\:sip.example.org:600:0:0
```

-- 
You are receiving this because you are subscribed to this thread.
Reply to this email directly or view it on GitHub:
https://github.com/kamailio/kamailio/issues/931
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.sip-router.org/pipermail/sr-dev/attachments/20170115/451621dd/attachment-0001.html>

More information about the sr-dev mailing list