[kamailio/kamailio] CANCEL msg results in "500 cancel error" because of "duplicate From header" error (#2572)
### CANCEL msg results in "500 cancel error" because of "duplicate From header" error
<!-- Explain what you did, what you expected to happen, and what actually happened. -->
Cancelling a call before it's answered sometimes results in a "500 cancel error" response and the far end not getting a cancel msg. The from header seems to be wrongly detected as being duplicated. This issue does not exist in version 5.2.8 or 5.1.10, does exist in 5.3.7 and 5.4.2.
From header from CANCEL that generates the error
``` f:"user 1002"sip:+1002@bf96cc.domain.com;tag=8FUg427jU6pva ```
From header from CANCEL that works fine
``` f:"Reseda Ca"sip:+18185144209@bf96cc.domain.com;tag=cm0KBFB1Fag7r ```
#### Log Messages
<!-- Check the syslog file and if there are relevant log messages printed by Kamailio, add them next, or attach to issue, or provide a link to download them (e.g., to a pastebin site). -->
``` Dec 3 01:03:43 kam3-lax /usr/sbin/kamailio[2451]: DEBUG: <core> [core/parser/msg_parser.c:610]: parse_msg(): SIP Request: Dec 3 01:03:43 kam3-lax /usr/sbin/kamailio[2451]: DEBUG: <core> [core/parser/msg_parser.c:612]: parse_msg(): method: <CANCEL> Dec 3 01:03:43 kam3-lax /usr/sbin/kamailio[2451]: DEBUG: <core> [core/parser/msg_parser.c:614]: parse_msg(): uri: sip:john.webrtc@bf96cc.domain.com Dec 3 01:03:43 kam3-lax /usr/sbin/kamailio[2451]: DEBUG: <core> [core/parser/msg_parser.c:616]: parse_msg(): version: <SIP/2.0> Dec 3 01:03:43 kam3-lax /usr/sbin/kamailio[2451]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 235, <rport> = <n/a>; state=6 Dec 3 01:03:43 kam3-lax /usr/sbin/kamailio[2451]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bKSg9eBr2tSDU5c>; state=16 Dec 3 01:03:43 kam3-lax /usr/sbin/kamailio[2451]: DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5 Dec 3 01:03:43 kam3-lax /usr/sbin/kamailio[2451]: DEBUG: <core> [core/parser/msg_parser.c:498]: parse_headers(): Via found, flags=2 Dec 3 01:03:43 kam3-lax /usr/sbin/kamailio[2451]: DEBUG: <core> [core/parser/msg_parser.c:500]: parse_headers(): this is the first via Dec 3 01:03:43 kam3-lax /usr/sbin/kamailio[2451]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=10 Dec 3 01:03:43 kam3-lax /usr/sbin/kamailio[2451]: DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <t> [41]; uri=[sip:john.webrtc@bf96cc.domain.com] Dec 3 01:03:43 kam3-lax /usr/sbin/kamailio[2451]: DEBUG: <core> [core/parser/msg_parser.c:174]: get_hdr_field(): to body (41)[sip:john.webrtc@bf96cc.domain.com#015#012], to tag (0)[] Dec 3 01:03:43 kam3-lax /usr/sbin/kamailio[2451]: DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <28924918> <CANCEL> Dec 3 01:03:43 kam3-lax /usr/sbin/kamailio[2451]: DEBUG: <core> [core/receive.c:319]: receive_msg(): --- received sip message - request - call-id: [39d19e18-afa6-1239-1dba-ea02c604123e] - cseq: [28924918 CANCEL] Dec 3 01:03:43 kam3-lax /usr/sbin/kamailio[2451]: DEBUG: <core> [core/parser/msg_parser.c:185]: get_hdr_field(): content_length=0 Dec 3 01:03:43 kam3-lax /usr/sbin/kamailio[2451]: DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header Dec 3 01:03:43 kam3-lax /usr/sbin/kamailio[2451]: DEBUG: {1 28924918 CANCEL 39d19e18-afa6-1239-1dba-ea02c604123e} <core> [core/receive.c:379]: receive_msg(): preparing to run routing scripts... Dec 3 01:03:43 kam3-lax /usr/sbin/kamailio[2451]: DEBUG: {1 28924918 CANCEL 39d19e18-afa6-1239-1dba-ea02c604123e} pv [pv_core.c:1073]: pv_get_useragent(): no User-Agent header Dec 3 01:03:43 kam3-lax /usr/sbin/kamailio[2451]: DEBUG: {1 28924918 CANCEL 39d19e18-afa6-1239-1dba-ea02c604123e} maxfwd [mf_funcs.c:74]: is_maxfwd_present(): value = 68 Dec 3 01:03:43 kam3-lax /usr/sbin/kamailio[2451]: DEBUG: {1 28924918 CANCEL 39d19e18-afa6-1239-1dba-ea02c604123e} tm [t_lookup.c:727]: t_lookupOriginalT(): searching on hash entry 19365 Dec 3 01:03:43 kam3-lax /usr/sbin/kamailio[2451]: DEBUG: {1 28924918 CANCEL 39d19e18-afa6-1239-1dba-ea02c604123e} tm [t_lookup.c:439]: matching_3261(): RFC3261 transaction matched, tid=Sg9eBr2tSDU5c Dec 3 01:03:43 kam3-lax /usr/sbin/kamailio[2451]: DEBUG: {1 28924918 CANCEL 39d19e18-afa6-1239-1dba-ea02c604123e} tm [t_lookup.c:823]: t_lookupOriginalT(): canceled transaction found (0x7f742bb6d000)! Dec 3 01:03:43 kam3-lax /usr/sbin/kamailio[2451]: DEBUG: {1 28924918 CANCEL 39d19e18-afa6-1239-1dba-ea02c604123e} tm [t_lookup.c:826]: t_lookupOriginalT(): found - lookup completed Dec 3 01:03:43 kam3-lax /usr/sbin/kamailio[2451]: DEBUG: {1 28924918 CANCEL 39d19e18-afa6-1239-1dba-ea02c604123e} tm [tm.c:1220]: ki_t_lookup_cancel_flags(): lookup_original: t_lookupOriginalT returned: 0x7f742bb6d000 Dec 3 01:03:43 kam3-lax /usr/sbin/kamailio[2451]: DEBUG: {1 28924918 CANCEL 39d19e18-afa6-1239-1dba-ea02c604123e} tm [t_lookup.c:1328]: t_newtran(): msg (0x7f74318090e8) id=97/2451 global id=96/2451 T start=0xffffffffffffffff Dec 3 01:03:43 kam3-lax /usr/sbin/kamailio[2451]: DEBUG: {1 28924918 CANCEL 39d19e18-afa6-1239-1dba-ea02c604123e} tm [t_lookup.c:497]: t_lookup_request(): start searching: hash=19365, isACK=0 Dec 3 01:03:43 kam3-lax /usr/sbin/kamailio[2451]: DEBUG: {1 28924918 CANCEL 39d19e18-afa6-1239-1dba-ea02c604123e} tm [t_lookup.c:455]: matching_3261(): RFC3261 transaction matching failed - via branch [z9hG4bKSg9eBr2tSDU5c] Dec 3 01:03:43 kam3-lax /usr/sbin/kamailio[2451]: DEBUG: {1 28924918 CANCEL 39d19e18-afa6-1239-1dba-ea02c604123e} tm [t_lookup.c:675]: t_lookup_request(): no transaction found Dec 3 01:03:43 kam3-lax /usr/sbin/kamailio[2451]: DEBUG: {1 28924918 CANCEL 39d19e18-afa6-1239-1dba-ea02c604123e} <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=N53jU220NtrFH Dec 3 01:03:43 kam3-lax /usr/sbin/kamailio[2451]: DEBUG: {1 28924918 CANCEL 39d19e18-afa6-1239-1dba-ea02c604123e} <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29 Dec 3 01:03:43 kam3-lax /usr/sbin/kamailio[2451]: DEBUG: {1 28924918 CANCEL 39d19e18-afa6-1239-1dba-ea02c604123e} <core> [core/crypto/md5utils.c:67]: MD5StringArray(): MD5 calculated: 3c5f13a67a8cbfe1028669836f4291d4 Dec 3 01:03:43 kam3-lax /usr/sbin/kamailio[2451]: DEBUG: {1 28924918 CANCEL 39d19e18-afa6-1239-1dba-ea02c604123e} tm [t_lookup.c:727]: t_lookupOriginalT(): searching on hash entry 19365 Dec 3 01:03:43 kam3-lax /usr/sbin/kamailio[2451]: DEBUG: {1 28924918 CANCEL 39d19e18-afa6-1239-1dba-ea02c604123e} tm [t_lookup.c:430]: matching_3261(): matched skip method - s:0x2 t:0x2 m:0x2 - continue searching Dec 3 01:03:43 kam3-lax /usr/sbin/kamailio[2451]: DEBUG: {1 28924918 CANCEL 39d19e18-afa6-1239-1dba-ea02c604123e} tm [t_lookup.c:439]: matching_3261(): RFC3261 transaction matched, tid=Sg9eBr2tSDU5c Dec 3 01:03:43 kam3-lax /usr/sbin/kamailio[2451]: DEBUG: {1 28924918 CANCEL 39d19e18-afa6-1239-1dba-ea02c604123e} tm [t_lookup.c:823]: t_lookupOriginalT(): canceled transaction found (0x7f742bb6d000)! Dec 3 01:03:43 kam3-lax /usr/sbin/kamailio[2451]: DEBUG: {1 28924918 CANCEL 39d19e18-afa6-1239-1dba-ea02c604123e} tm [t_lookup.c:826]: t_lookupOriginalT(): found - lookup completed Dec 3 01:03:43 kam3-lax /usr/sbin/kamailio[2451]: DEBUG: {1 28924918 CANCEL 39d19e18-afa6-1239-1dba-ea02c604123e} tm [t_msgbuilder.c:412]: build_local_reparse(): duplicate From header Dec 3 01:03:43 kam3-lax /usr/sbin/kamailio[2451]: ERROR: {1 28924918 CANCEL 39d19e18-afa6-1239-1dba-ea02c604123e} tm [t_msgbuilder.c:531]: build_local_reparse(): cannot build CANCEL request Dec 3 01:03:43 kam3-lax /usr/sbin/kamailio[2451]: ERROR: {1 28924918 CANCEL 39d19e18-afa6-1239-1dba-ea02c604123e} tm [t_cancel.c:297]: cancel_branch(): attempt to build a CANCEL failed Dec 3 01:03:43 kam3-lax /usr/sbin/kamailio[2451]: ERROR: {1 28924918 CANCEL 39d19e18-afa6-1239-1dba-ea02c604123e} tm [t_fwd.c:1434]: e2e_cancel(): cancel error Dec 3 01:03:43 kam3-lax /usr/sbin/kamailio[2451]: DEBUG: {1 28924918 CANCEL 39d19e18-afa6-1239-1dba-ea02c604123e} tm [t_reply.c:1761]: cleanup_uac_timers(): RETR/FR timers reset Dec 3 01:03:43 kam3-lax /usr/sbin/kamailio[2451]: DEBUG: {1 28924918 CANCEL 39d19e18-afa6-1239-1dba-ea02c604123e} tm [t_reply.c:633]: _reply_light(): reply sent out - buf=0x7f74317ec440: SIP/2.0 500 cancel e... shmem=0x7f742bb77260: SIP/2.0 500 cancel e Dec 3 01:03:43 kam3-lax /usr/sbin/kamailio[2451]: DEBUG: {1 28924918 CANCEL 39d19e18-afa6-1239-1dba-ea02c604123e} tm [t_reply.c:644]: _reply_light(): finished Dec 3 01:03:43 kam3-lax /usr/sbin/kamailio[2451]: DEBUG: {1 28924918 CANCEL 39d19e18-afa6-1239-1dba-ea02c604123e} tm [t_funcs.c:376]: t_relay_to(): new transaction forwarded Dec 3 01:03:43 kam3-lax /usr/sbin/kamailio[2451]: DEBUG: {1 28924918 CANCEL 39d19e18-afa6-1239-1dba-ea02c604123e} <core> [core/receive.c:437]: receive_msg(): request-route executed in: 1125 usec Dec 3 01:03:43 kam3-lax /usr/sbin/kamailio[2451]: DEBUG: {1 28924918 CANCEL 39d19e18-afa6-1239-1dba-ea02c604123e} <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Dec 3 01:03:43 kam3-lax /usr/sbin/kamailio[2451]: message repeated 5 times: [ DEBUG: {1 28924918 CANCEL 39d19e18-afa6-1239-1dba-ea02c604123e} <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)] Dec 3 01:03:43 kam3-lax /usr/sbin/kamailio[2451]: DEBUG: {1 28924918 CANCEL 39d19e18-afa6-1239-1dba-ea02c604123e} <core> [core/xavp.c:539]: xavp_destroy_list(): destroying xavp list (nil) Dec 3 01:03:43 kam3-lax /usr/sbin/kamailio[2451]: message repeated 2 times: [ DEBUG: {1 28924918 CANCEL 39d19e18-afa6-1239-1dba-ea02c604123e} <core> [core/xavp.c:539]: xavp_destroy_list(): destroying xavp list (nil)] Dec 3 01:03:43 kam3-lax /usr/sbin/kamailio[2451]: DEBUG: {1 28924918 CANCEL 39d19e18-afa6-1239-1dba-ea02c604123e} <core> [core/receive.c:528]: receive_msg(): cleaning up ```
#### SIP Traffic
<!-- If the issue is exposed by processing specific SIP messages, grab them with ngrep or save in a pcap file, then add them next, or attach to issue, or provide a link to download them (e.g., to a pastebin site). -->
``` CANCEL sip:john.webrtc@bf96cc.domain.com SIP/2.0 v:SIP/2.0/UDP a.b.c.d:5081;rport;branch=z9hG4bKgZ5FU4aUKXjXm Route:sip:kam3.rtp.lax.domain.net:5060 Max-Forwards:68 f:"user 1002"sip:+1002@bf96cc.domain.com;tag=8FUg427jU6pva t:sip:john.webrtc@bf96cc.domain.com i:98fa8010-afa4-1239-1dba-ea02c604123e CSeq:28924569 CANCEL Reason:SIP;cause=487;text="ORIGINATOR_CANCEL" l:0 ```
### Possible Solutions
<!-- If you found a solution or workaround for the issue, describe it. Ideally, provide a pull request with a fix. -->
I found that Kamailio versions 5.2.10 and 5.2.8 do not have this issue, so for now have downgraded to 5.2.8.
### Additional Information
* **Kamailio Version** - output of `kamailio -v`
``` version: kamailio 5.4.2 (x86_64/linux) flags: USE_TCP, USE_TLS, USE_SCTP, TLS_HOOKS, USE_RAW_SOCKS, DISABLE_NAGLE, USE_MCAST, DNS_IP_HACK, 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_URI_SIZE 1024, BUF_SIZE 65535, DEFAULT PKG_SIZE 8MB poll method support: poll, epoll_lt, epoll_et, sigio_rt, select. id: unknown compiled with gcc 5.4.0 ```
* **Operating System**: Ubuntu 16.04.7 LTS
<!-- Details about the operating system, the type: Linux (e.g.,: Debian 8.4, Ubuntu 16.04, CentOS 7.1, ...), MacOS, xBSD, Solaris, ...; Kernel details (output of `uname -a`) -->
``` Linux kam3-lax 4.4.0-194-generic #226-Ubuntu SMP Wed Oct 21 10:19:36 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux ```
The error message should happen when corresponding outgoing INVITE was with 2 From headers. Can you check that?
Otherwise the code seems to be ok in terms of detecting duplicated From header in the outgoing INVITE.
Ok I found the issue with the INVITE, it doesn't have multiple "From" headers. But it does have a "From-Person:12345" header that we use to track the customer id that initiated the call. So that explains why calls from a PSTN source didn't have the issue.
I tried a change to our system to change the header from "From-Person" to "Src-Person" and it that works fine on 5.4.2 no more duplicate From header error the Callee gets the CANCEL msg just fine.
So Kamailio is maybe doing a "starts with" type match when finding the "From" header then as of 5.3? Is that correct? We've had this header in place for years now an only with this upgrade have the error. Is Kamailio behaving properly here? I've searched but couldn't find anything in that would suggest headers starting with "From" to be not allowed.
Here is the original INVITE ( From-Person header is second to last ) ``` INVITE sip:john.webrtc@bf96cc.domain.com SIP/2.0 v:SIP/2.0/UDP a.b.c.d:5081;rport;branch=z9hG4bKgZ5FU4aUKXjXm Route:sip:kam3.rtp.lax.domain.net:5060 Max-Forwards:68 f:"user 1002"sip:+1002@bf96cc.domain.com;tag=8FUg427jU6pva t:sip:john.webrtc@bf96cc.domain.com i:98fa8010-afa4-1239-1dba-ea02c604123e CSeq:28924569 INVITE m:sip:mod_sofia@206.15.136.103:5081 User-Agent:fs Allow:INVITE,ACK,BYE,CANCEL,OPTIONS,MESSAGE,INFO,UPDATE,REGISTER,REFER,NOTIFY,PUBLISH,SUBSCRIBE k:timer,path,replaces u:talk,hold,conference,presence,as-feature-event,dialog,line-seize,call-info,sla,include-session-description,presence.winfo,message-summary,refer c:application/sdp Content-Disposition:session l:482 From-Person:12345 Remote-Party-ID:"user 1002"sip:+1002@bf96cc.domain.com;party=calling;screen=yes;privacy=off
<SDP DATA> ```
The newer versions introduced a check to avoid double headers in locally generated CANCEL or ACK, so you hit that and revealed an issue on tm module internal lightweight parser that tries to identify only the headers that have to be propagated from INVITE to CANCEL in this case. Prior the commit referenced above, the tm lightweight parser was indeed matching some headers on prefix.
Can you test with master branch or with the patch referenced above and see if it works fine by using `From-Person` header? If yes, then I will backport to stable branches.
Thank you. I built from master, and can verify that this error no longer occurs on cancel with the "From-Person" header.
``` version: kamailio 5.5.0-dev3 (x86_64/linux) a2eff9 flags: USE_TCP, USE_TLS, USE_SCTP, TLS_HOOKS, USE_RAW_SOCKS, DISABLE_NAGLE, USE_MCAST, DNS_IP_HACK, 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_BLOCKLIST, HAVE_RESOLV_RES, TLS_PTHREAD_MUTEX_SHARED ADAPTIVE_WAIT_LOOPS 1024, MAX_RECV_BUFFER_SIZE 262144, MAX_URI_SIZE 1024, BUF_SIZE 65535, DEFAULT PKG_SIZE 8MB poll method support: poll, epoll_lt, epoll_et, sigio_rt, select. id: a2eff9 compiled on 22:09:44 Dec 5 2020 with gcc 8.3.0 ```
Thanks for reporting back! The commit will be backported.
Closed #2572.
-
Daniel-Constantin Mierla -
Justin LaVelle