[sr-dev] [kamailio/kamailio] CANCEL msg results in "500 cancel error" because of "duplicate From header" error (#2572)

Justin LaVelle notifications at github.com
Thu Dec 3 03:21:45 CET 2020


### 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 at bf96cc.domain.com>;tag=8FUg427jU6pva
```
>From header from CANCEL that works fine
```
f:"Reseda Ca"<sip:+18185144209 at 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 at 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 at 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 at 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 at 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 at bf96cc.domain.com>;tag=8FUg427jU6pva
t:<sip:john.webrtc at 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
```


-- 
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/2572
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.kamailio.org/pipermail/sr-dev/attachments/20201202/7f1ae09c/attachment-0001.htm>


More information about the sr-dev mailing list