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

16 Jan 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-c...) 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@sip.example.org.
From: sip:11111111@sip.example.org;tag=533cb9e91f4b999cf76861cbb9ed54ed-48c9.
CSeq: 10 REGISTER.
Call-ID: 705a8b605d872669-5747@127.0.0.1.
Max-Forwards: 70.
Content-Length: 0.
User-Agent: kamailio (5.0.0-pre0 (x86_64/linux)).
Contact: sip:12345678@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@sip.example.org;tag=533cb9e91f4b999cf76861cbb9ed54ed-48c9.
To: sip:11111111@sip.example.org;tag=as4c52c89f.
Call-ID: 705a8b605d872669-5747@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@sip.example.org.
From: sip:11111111@sip.example.org;tag=533cb9e91f4b999cf76861cbb9ed54ed-48c9.
CSeq: 11 REGISTER.
Call-ID: 705a8b605d872669-5747@127.0.0.1.
Max-Forwards: 70.
Content-Length: 0.
User-Agent: kamailio (5.0.0-pre0 (x86_64/linux)).
Contact: sip:12345678@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@sip.example.org;tag=533cb9e91f4b999cf76861cbb9ed54ed-48c9.
To: sip:11111111@sip.example.org;tag=as4c52c89f.
Call-ID: 705a8b605d872669-5747@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@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@sip.example.org.
From: sip:11111111@sip.example.org.
CSeq: 12 REGISTER.
Call-ID: 705a8b605d872669-5747@127.0.0.1.
Max-Forwards: 70.
Content-Length: 0.
User-Agent: kamailio (5.0.0-pre0 (x86_64/linux)).
Contact: sip:12345678@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@sip.example.org.
From: sip:11111111@sip.example.org;tag=533cb9e91f4b999cf76861cbb9ed54ed-acbf.
CSeq: 10 REGISTER.
Call-ID: 705a8b605d87266a-5747@127.0.0.1.
Max-Forwards: 70.
Content-Length: 0.
User-Agent: kamailio (5.0.0-pre0 (x86_64/linux)).
Contact: sip:12345678@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@sip.example.org;tag=533cb9e91f4b999cf76861cbb9ed54ed-acbf.
To: sip:11111111@sip.example.org;tag=as76317b94.
Call-ID: 705a8b605d87266a-5747@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@sip.example.org.
From: sip:11111111@sip.example.org;tag=533cb9e91f4b999cf76861cbb9ed54ed-acbf.
CSeq: 11 REGISTER.
Call-ID: 705a8b605d87266a-5747@127.0.0.1.
Max-Forwards: 70.
Content-Length: 0.
User-Agent: kamailio (5.0.0-pre0 (x86_64/linux)).
Contact: sip:12345678@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@sip.example.org;tag=533cb9e91f4b999cf76861cbb9ed54ed-acbf.
To: sip:11111111@sip.example.org;tag=as76317b94.
Call-ID: 705a8b605d87266a-5747@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@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