<p></p>
<h3>CANCEL msg results in "500 cancel error" because of "duplicate From header" error</h3>

<p>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.</p>
<p>From header from CANCEL that generates the error</p>
<pre><code>f:"user 1002"<sip:+1002@bf96cc.domain.com>;tag=8FUg427jU6pva
</code></pre>
<p>From header from CANCEL that works fine</p>
<pre><code>f:"Reseda Ca"<sip:+18185144209@bf96cc.domain.com>;tag=cm0KBFB1Fag7r
</code></pre>
<h4>Log Messages</h4>

<pre><code>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
</code></pre>
<h4>SIP Traffic</h4>

<pre><code>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
</code></pre>
<h3>Possible Solutions</h3>

<p>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.</p>
<h3>Additional Information</h3>
<ul>
<li><strong>Kamailio Version</strong> - output of <code>kamailio -v</code></li>
</ul>
<pre><code>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
</code></pre>
<ul>
<li><strong>Operating System</strong>: Ubuntu 16.04.7 LTS</li>
</ul>

<pre><code>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
</code></pre>

<p style="font-size:small;-webkit-text-size-adjust:none;color:#666;">—<br />You are receiving this because you are subscribed to this thread.<br />Reply to this email directly, <a href="https://github.com/kamailio/kamailio/issues/2572">view it on GitHub</a>, or <a href="https://github.com/notifications/unsubscribe-auth/ABO7UZNIZXLXAR5T6OIALHLSS3Y3TANCNFSM4ULKO6OQ">unsubscribe</a>.<img src="https://github.com/notifications/beacon/ABO7UZNA23RNYYO3H2BM2YLSS3Y3TA5CNFSM4ULKO6O2YY3PNVWWK3TUL52HS4DFUVEXG43VMWVGG33NNVSW45C7NFSM4LIL6OTQ.gif" height="1" width="1" alt="" /></p>
<script type="application/ld+json">[
{
"@context": "http://schema.org",
"@type": "EmailMessage",
"potentialAction": {
"@type": "ViewAction",
"target": "https://github.com/kamailio/kamailio/issues/2572",
"url": "https://github.com/kamailio/kamailio/issues/2572",
"name": "View Issue"
},
"description": "View this Issue on GitHub",
"publisher": {
"@type": "Organization",
"name": "GitHub",
"url": "https://github.com"
}
}
]</script>