CANCEL msg results in "500 cancel error" because of "duplicate From header" error

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

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

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

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

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

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, view it on GitHub, or unsubscribe.