[kamailio/kamailio] CANCEL msg results in "500 cancel error" because of "duplicate From header" error (#2572)
3 Dec
2020
3 Dec
'20
5:21 a.m.
### 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
```
--
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
3 Dec
3 Dec
9:31 a.m.
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.
--
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#issuecomment-737697320
11:59 a.m.
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>
```
--
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#issuecomment-737763022
3:21 p.m.
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.
--
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#issuecomment-737909798
6 Dec
6 Dec
3:07 a.m.
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
```
--
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#issuecomment-739433782
7 Dec
7 Dec
4:07 p.m.
Thanks for reporting back! The commit will be backported.
--
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#issuecomment-739907151
4:07 p.m.
Closed #2572.
--
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#event-4079538184
1447
days inactive
1451
days old
6 comments
2 participants
participants (2)
-
Daniel-Constantin Mierla -
Justin LaVelle