Possible bug with track_cseq_updates set in dialog

[scfcplummy]

Hi,

When setting "track_cseq_updates" in dialog module, the ReINVITE that should be initiated with uac_auth() is never sent. Without "track_cseq_updates" set to 0, the reINVITE does take place.

In the log I can see dialog doing the cseq update:

Sep 20 07:54:57 sbc /usr/local/sbin/kamailio[35746]: DEBUG: dialog [dlg_cseq.c:129]: dlg_cseq_update(): initiating cseq updates Sep 20 07:54:57 sbc /usr/local/sbin/kamailio[35746]: DEBUG: dialog [dlg_hash.c:690]: dlg_lookup(): ref dlg 0x7fc2b265f4f0 with 1 -> 2 Sep 20 07:54:57 sbc /usr/local/sbin/kamailio[35746]: DEBUG: dialog [dlg_hash.c:692]: dlg_lookup(): dialog id=4263 found on entry 1771 Sep 20 07:54:57 sbc /usr/local/sbin/kamailio[35746]: DEBUG: dialog [dlg_var.c:250]: print_lists(): Internal var-list ((nil)): Sep 20 07:54:57 sbc /usr/local/sbin/kamailio[35746]: DEBUG: dialog [dlg_var.c:260]: print_lists(): Dialog var-list (0x7fc2b265f2d8): Sep 20 07:54:57 sbc /usr/local/sbin/kamailio[35746]: DEBUG: dialog [dlg_var.c:262]: print_lists(): cseq_diff=1 (flags 1) Sep 20 07:54:57 sbc /usr/local/sbin/kamailio[35746]: DEBUG: dialog [dlg_cseq.c:176]: dlg_cseq_update(): adding auth cseq header value: 5136

but quickly followed by these errors:

Sep 20 07:54:57 sbc /usr/local/sbin/kamailio[35746]: ERROR: [msg_translator.c:417]: clen_builder(): no message body found (missing crlf?) Sep 20 07:54:57 sbc /usr/local/sbin/kamailio[35746]: ERROR: [msg_translator.c:1963]: build_req_buf_from_sip_req(): Error while adjusting Content-Length Sep 20 07:54:57 sbc /usr/local/sbin/kamailio[35746]: ERROR: tm [t_fwd.c:462]: prepare_new_uac(): could not build request Sep 20 07:54:57 sbc /usr/local/sbin/kamailio[35746]: ERROR: tm [t_fwd.c:1723]: t_forward_nonack(): ERROR: t_forward_nonack: failure to add branches Sep 20 07:54:57 sbc /usr/local/sbin/kamailio[35746]: ERROR: tm [tm.c:1415]: _w_t_relay_to(): ERROR: w_t_relay_to: t_relay_to failed

Kamailio was built from kamailio-4.4.3 source downloaded from here:

https://www.kamailio.org/pub/kamailio/latest/src/

Version information:

version: kamailio 4.4.3 (x86_64/linux) 5a2195 flags: STATS: Off, USE_TCP, USE_TLS, USE_SCTP, TLS_HOOKS, USE_RAW_SOCKS, DISABLE_NAGLE, USE_MCAST, DNS_IP_HACK, SHM_MEM, SHM_MMAP, PKG_MALLOC, Q_MALLOC, F_MALLOC, TLSF_MALLOC, DBG_SR_MEMORY, 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: 5a2195 compiled on 08:46:12 Sep 16 2016 with gcc 5.4.0

Many thanks

[miconda]

Can you make all log messages available from the moment the re-INVITE is received to the end, when error messages are printed? I need to see in which stage these errors appear.

[scfcplummy]

kamailio-dialog-log.txt

That's the full log during the call on debug 3.

Many thanks

[miconda]

Is this the right call scenario? From logs, the 401 seems to be sent out and also a CANCEL appears in the logs. I haven't spotted the re-INVITE either. Maybe you can grab both pcap and log messages at the same time and send them to me.

[scfcplummy]

OK, so the call flow is an INVITE from TCP side is sent to Kamailio, an INVITE is relayed to a UDP SIP server. The UDP SIP server replies with a 401. There is a failure route to handle the 401 and perform uac_auth()

The TCP side does not handle authentication, so the configuration is for Kamailio to authenticate the INVITE for the UDP side on behalf of the TCP side.

When track_cseq_updates is set, something goes wrong with the failure route because the 401 gets relayed back to the TCP side rather than being handled in the failure route. (Hence there is no reINVITE, which is the problem)

Without the track_cseq_updates param set, it works as expected - just without the Cseq being incremented.

The CANCEL is just ending the call on the client (TCP side).

[miconda]

OK -- apparently we use different meaning/terminology for re-INVITE -- it is commonly used for an INVITE that is sent after the call is established, but you used here for the retry of sending the initial INVITE with the credentials.

I pushed a patch, try with master branch and if all ok I will backport. It might be that the helper header was not added at the right position, which it is tried to be fixed with the patch.

[scfcplummy]

Agreed, I used poor terminology - Apologies for that.

I've tried with the master branch but unfortunately I have the same results as before.

Log from new build:

kamailio-dialog-20092016.txt

Version output:

version: kamailio 5.0.0-dev6 (x86_64/linux) flags: STATS: Off, USE_TCP, USE_TLS, USE_SCTP, TLS_HOOKS, USE_RAW_SOCKS, DISABLE_NAGLE, USE_MCAST, DNS_IP_HACK, SHM_MEM, SHM_MMAP, PKG_MALLOC, Q_MALLOC, F_MALLOC, TLSF_MALLOC, DBG_SR_MEMORY, 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: unknown compiled on 11:06:13 Sep 20 2016 with gcc 5.4.0

Many thanks

[ovoshlook]

looks like kamailio dont unerstand that he need handle 407 request At my side i see that kamailio dont stops 407 request and resend it without any handling I use asterisk->kamailio-provider scheme

At this scheme kamailio must stops proxy of get 407/401 and then make another invite with www-auth header

But it proxies 407 to asterisk back. and give errors above.

if (t_check_status("401|407")){ xlog("L_INFO", "Reply from provider on failure: $tU"); xlog("L_ERR","401/407 - Unauthorized. ($ci .) ($rm) from ($fu) (IP:$si:$sp) to ($Ri:$Rp). Must be authorized with digest Auth.");

    if (uac_auth()) {
        xlog("L_INFO", "CSeq diff: $dlg_var(cseq_diff)");
        t_relay();
    } else {
        xlog("L_INFO", "UAC_AUTH(): credentials not found");
    }
    t_relay();
}

[miconda]

I pushed a patch to print the sip message when the error occurs to see if it is something wrong with it. Test again with the latest master branch and provide the log messages along with the pcap file having the sip traffic.

[scfcplummy]

log and pcap:

20092016-1300-kamailio-pcap_log.zip

kamailio -v version: kamailio 5.0.0-dev6 (x86_64/linux) 1ed9c2-dirty flags: STATS: Off, USE_TCP, USE_TLS, USE_SCTP, TLS_HOOKS, USE_RAW_SOCKS, DISABLE_NAGLE, USE_MCAST, DNS_IP_HACK, SHM_MEM, SHM_MMAP, PKG_MALLOC, Q_MALLOC, F_MALLOC, TLSF_MALLOC, DBG_SR_MEMORY, 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: 1ed9c2 -dirty compiled on 12:49:31 Sep 20 2016 with gcc 5.4.0

Many thanks

[ovoshlook]

Hi. are there any updates?

[miconda]

I tried to reproduce but didn't get those errors. I used pjsua and all looked good, the cseq was incremented for ack, bye ... Anyhow, I found a double-free error which might have a side effect.

Can you try again with latest master or 4.4 branch?

[scfcplummy]

For more information, if I downgraded to 4.4.2 this particular problem is fixed. So it must have been introduced in 4.4.3

I'll update when I've grabbed the latest master.

[miconda]

4.4.2 had problems with retransmissions (see closed items in this bug tracker), which was aimed to be fixed with 4.4.3, but although it was confirmed to work by the reporter, apparently it introduced other regressions.

[scfcplummy]

I've cloned and compiled the latest:

kamailio -v
version: kamailio 5.0.0-dev6 (x86_64/linux) 276ccc-dirty
flags: STATS: Off, USE_TCP, USE_TLS, USE_SCTP, TLS_HOOKS, USE_RAW_SOCKS, DISABLE_NAGLE, USE_MCAST, DNS_IP_HACK, SHM_MEM, SHM_MMAP, PKG_MALLOC, Q_MALLOC, F_MALLOC, TLSF_MALLOC, DBG_SR_MEMORY, 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: 276ccc -dirty
compiled on 10:07:00 Sep 29 2016 with gcc 5.4.0

But I still get the same issue:

Sep 29 10:14:43 sbc /usr/local/sbin/kamailio[47154]: ERROR: <core> [msg_translator.c:418]: clen_builder(): no message body found (missing crlf?) [[INVITE sip:+447580842258@sbc1.o365.voice.redcentric;user=phone SIP/2.0#015#012FROM: "Peter Pulham"<sip:+441132214578@o365.redcentric.training;user=phone>;epid=4BE95AECD5;tag=7d6f29c5a0#015#012TO: <sip:+447580842258@sbc1.o365.voice.redcentric;user=phone>#015#012CSEQ: 17068 INVITE#015#012CALL-ID: f7b8ef80-c45d-45dc-ac79-9cc38d054238#015#012MAX-FORWARDS: 69#015#012VIA: SIP/2.0/TCP 192.168.4.153:57850;branch=z9hG4bKfe6465#015#012CONTACT: <sip:MediationServer.o365.voice.redcentric:5068;transport=Tcp;maddr=192.168.4.153;ms-opaque=7d1538e1e699b871>#015#012CONTENT-LENGTH: 342#015#012SUPPORTED: 100rel#015#012USER-AGENT: RTCC/6.0.0.0 MediationServer#015#012CONTENT-TYPE: application/sdp#015#012ALLOW: ACK#015#012P-ASSERTED-IDENTITY: "Peter Pulham"<sip:peter.pulham@o365.redcentric.training>,<tel:+441132214578>#015#012Privacy: id#015#012Allow: CANCEL,BYE,INVITE,PRACK,UPDATE#015#012#015#012v=0#015#012o=- 61 1 IN IP4 192.168.4.153#015#012s=session#015#012c=IN IP4 192.168.4.153#015#012b=CT:1000#015#012t=0 0#015#012m=audio 51284 RTP/AVP 97 101 13 0 8#015#012c=IN IP4 192.168.4.153#015#012a=rtcp:51285#015#012a=label:Audio#015#012a=sendrecv#015#012a=rtpmap:97 RED/8000#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-16#015#012a=rtpmap:13 CN/8000#015#012a=rtpmap:0 PCMU/8000#015#012a=rtpmap:8 PCMA/8000#015#012a=ptime:20#015#012]]
Sep 29 10:14:43 sbc /usr/local/sbin/kamailio[47154]: ERROR: <core> [msg_translator.c:1965]: build_req_buf_from_sip_req(): Error while adjusting Content-Length
Sep 29 10:14:43 sbc /usr/local/sbin/kamailio[47154]: ERROR: tm [t_fwd.c:476]: prepare_new_uac(): could not build request
Sep 29 10:14:43 sbc /usr/local/sbin/kamailio[47154]: ERROR: tm [t_fwd.c:1741]: t_forward_nonack(): ERROR: t_forward_nonack: failure to add branches
Sep 29 10:14:43 sbc /usr/local/sbin/kamailio[47154]: ERROR: tm [tm.c:1426]: _w_t_relay_to(): t_forward_noack failed

Many thanks

[miconda]

I guess it is correlated to other parts of the configuration file you use, because it works fine for me with a config based on kamailio-basic.cfg.

Can you send a stripped down (or full) version of kamailio.cfg that can be used to reproduce the issue?

[scfcplummy]

kam.cfg.txt

Thats my full config with the !#defines and !#subst taken out.

[miconda]

Still not able to reproduce, can you send me full log with debug=3 in kamailio.cfg for processing from initial INVITE until the error messages are printed?

[miconda]

Should be fixed, see #819.