Core generated by Kamailio when a bad char is found in header #1687

joelsdc · 2018-10-24T22:40:17Z

Description

Kamailio dies complaining about a bad char in some header. I can say that I just updated from the nightly-devel apt repo, this problem never happened in latest v5.1 release.

Troubleshooting

Reproduction

I don't know how to reproduce yet.

Debugging Data

BT-FULL_core.kamailio.3329.1540415468.txt
BT-FULL_core.kamailio.3330.1540415471.txt
BT-FULL_core.kamailio.3331.1540415467.txt
BT-FULL_core.kamailio.3333.1540415469.txt
INFO-LOCALS_core.kamailio.3329.1540415468.txt
INFO-LOCALS_core.kamailio.3330.1540415471.txt
INFO-LOCALS_core.kamailio.3331.1540415467.txt
INFO-LOCALS_core.kamailio.3333.1540415469.txt
LIST_core.kamailio.3329.1540415468.txt
LIST_core.kamailio.3330.1540415471.txt
LIST_core.kamailio.3331.1540415467.txt
LIST_core.kamailio.3333.1540415469.txt

Log Messages

The relevant log lines are:

Oct 24 16:11:11 sbc01 sbc[3330]: ERROR: <core> [core/parser/parse_addr_spec.c:718]: parse_addr_spec(): unexpected char [<] in status 6: ["910609864" <sip:;:929] .
Oct 24 16:11:11 sbc01 sbc[3330]: ERROR: <core> [core/parser/msg_parser.c:164]: get_hdr_field(): bad to header
Oct 24 16:11:11 sbc01 sbc[3330]: ERROR: <core> [core/parser/msg_parser.c:337]: parse_headers(): bad header field [To: "910609864" <sip:;:929<>64@138.99.136.3>;tag=as664d068c#015#012Call-ID: 032f010653fed9170365045a4e1002]
Oct 24 16:11:11 sbc01 sbc[3330]: ERROR: <core> [core/parser/parse_addr_spec.c:718]: parse_addr_spec(): unexpected char [<] in status 6: ["910609864" <sip:;:929] .
Oct 24 16:11:11 sbc01 sbc[3330]: ERROR: <core> [core/parser/msg_parser.c:164]: get_hdr_field(): bad to header
Oct 24 16:11:11 sbc01 sbc[3330]: ERROR: <core> [core/parser/msg_parser.c:337]: parse_headers(): bad header field [To: "910609864" <sip:;:929<>64@138.99.136.3>;tag=as664d068c#015#012Call-ID: 032f010653fed9170365045a4e1002]
Oct 24 16:11:11 sbc01 sbc[3330]: ERROR: <core> [core/parser/parse_addr_spec.c:718]: parse_addr_spec(): unexpected char [<] in status 6: ["910609864" <sip:;:929] .
Oct 24 16:11:11 sbc01 sbc[3330]: ERROR: <core> [core/parser/msg_parser.c:164]: get_hdr_field(): bad to header
Oct 24 16:11:11 sbc01 sbc[3330]: ERROR: <core> [core/parser/msg_parser.c:337]: parse_headers(): bad header field [To: "910609864" <sip:;:929<>64@138.99.136.3>;tag=as664d068c#015#012Call-ID: 032f010653fed9170365045a4e1002]
Oct 24 16:11:11 sbc01 sbc[3330]: ERROR: pv [pv_core.c:1892]: pv_get_hdr(): error parsing headers
Oct 24 16:11:11 sbc01 sbc[3330]: ERROR: <core> [core/parser/parse_addr_spec.c:718]: parse_addr_spec(): unexpected char [<] in status 6: ["910609864" <sip:;:929] .
Oct 24 16:11:11 sbc01 sbc[3330]: ERROR: <core> [core/parser/msg_parser.c:164]: get_hdr_field(): bad to header
Oct 24 16:11:11 sbc01 sbc[3330]: ERROR: <core> [core/parser/msg_parser.c:337]: parse_headers(): bad header field [To: "910609864" <sip:;:929<>64@138.99.136.3>;tag=as664d068c#015#012Call-ID: 032f010653fed9170365045a4e1002]
Oct 24 16:11:11 sbc01 sbc[3330]: ERROR: pv [pv_core.c:704]: pv_get_callid(): cannot parse Call-Id header

SIP Traffic

I have enabled a mirror server to capture all traffic, once the problem happens again I will be able to update this issue with SIP traffic.

Possible Solutions

Additional Information

Kamailio Version - output of kamailio -v

root@sbc01:/var/tmp# kamailio -v
version: kamailio 5.2.0-pre1 (x86_64/linux)
flags: STATS: Off, USE_TCP, USE_TLS, USE_SCTP, TLS_HOOKS, USE_RAW_SOCKS, DISABLE_NAGLE, USE_MCAST, DNS_IP_HACK, SHM_MEM, 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 6.3.0
root@sbc01:/var/tmp#

Operating System:

root@sbc01:/var/tmp# uname -a
Linux sbc01 4.9.0-8-amd64 #1 SMP Debian 4.9.110-3+deb9u6 (2018-10-08) x86_64 GNU/Linux
root@sbc01:/var/tmp#

root@sbc01:/var/tmp# lsb_release -a
No LSB modules are available.
Distributor ID:	Debian
Description:	Debian GNU/Linux 9.5 (stretch)
Release:	9.5
Codename:	stretch
root@sbc01:/var/tmp#

The text was updated successfully, but these errors were encountered:

joelsdc · 2018-10-24T22:45:39Z

To add a more specific version as 5.2.0-pre1 doesn't say much...:

root@sbc01:/var/tmp# dpkg -l | grep kam
ii  kamailio                        5.2.0~pre1+0~20181020005754.1238+stretch amd64        very fast, dynamic and configurable SIP server
ii  kamailio-dbg:amd64              5.2.0~pre1+0~20181020005754.1238+stretch amd64        very fast and configurable SIP server [debug symbols]
ii  kamailio-extra-modules:amd64    5.2.0~pre1+0~20181020005754.1238+stretch amd64        Extra modules for the Kamailio SIP Server
ii  kamailio-geoip2-modules:amd64   5.2.0~pre1+0~20181020005754.1238+stretch amd64        The geoip2 module for the Kamailio SIP Server
ii  kamailio-mysql-modules:amd64    5.2.0~pre1+0~20181020005754.1238+stretch amd64        MySQL database connectivity module for Kamailio
ii  kamailio-outbound-modules:amd64 5.2.0~pre1+0~20181020005754.1238+stretch amd64        SIP Outbound module for the Kamailio SIP server
ii  kamailio-phonenum-modules:amd64 5.2.0~pre1+0~20181020005754.1238+stretch amd64        phonenum modules for the Kamailio SIP server
ii  kamailio-utils-modules:amd64    5.2.0~pre1+0~20181020005754.1238+stretch amd64        Utility functions for the Kamailio SIP server
root@sbc01:/var/tmp#

- GH #1687

miconda · 2018-10-25T05:12:44Z

The first two backtraces led to a function related to a new feature added in 5.2, respectively statistics for replies per method. The issue was accessing CSeq header fields without any checks if the header was properly parsed. I pushed a commit for it, referenced above. You can try with latest master and see if now all ok.

joelsdc · 2018-10-25T16:45:06Z

Hi @miconda, I've just deployed K with this patch, I'll let you know if this happens again.

Out of curiosity, if I wanted to test with the nightly builds, how can I know if for example:

5.2.0~pre1+0~20181025005757.1239+stretch deb package contains commit 5e76302?

Maybe I should open a separate ticket as feature request to add the id of latest commit to the output of kamailio -V command?

Thanks!

henningw · 2018-10-25T19:48:59Z

One idea: execute kamailio -V, this should output the build revision "id:". Then you can see e.g. with git log if this revision already contains your wanted commit.

joelsdc · 2018-10-25T21:03:57Z

Yeah this is my bad, it was there all the time, and only because you said so now I actually see it:

root@sbc02:~# kamailio -V
version: kamailio 5.2.0-pre1 (x86_64/linux) 2ecf60-dirty
flags: STATS: Off, USE_TCP, USE_TLS, USE_SCTP, TLS_HOOKS, USE_RAW_SOCKS, DISABLE_NAGLE, USE_MCAST, DNS_IP_HACK, SHM_MEM, 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: 2ecf60 -dirty
compiled with gcc 6.3.0
root@sbc02:~#

Commit --> 2ecf60

Thanks @henningw

kamailio-sync · 2018-10-26T01:34:36Z

Isn't "sip:;:929<>64@138.99.136.3" in the To header what's making it fail?

…

On Thu, Oct 25, 2018, 22:05 Joel Serrano ***@***.***> wrote: Closed #1687 <#1687>. — You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub <#1687 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AF36ZTx5k_vZi4fa0c4qEQAhUmCj0hawks5uoidagaJpZM4X5L1n> . _______________________________________________ Kamailio (SER) - Development Mailing List ***@***.*** https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-dev

joelsdc · 2018-10-26T16:59:53Z

From the logs I also thought it was something in the To: header but I don't know how to read the backtraces :(

joelsdc · 2018-10-26T17:00:16Z

Reopening for now!

joelsdc · 2018-10-26T17:08:21Z

BTW, @henningw:

If I build myself kamailio I have the commit id in kamailio -V

But from nightly-deb packages it's not available:

DEB install:

root@sbc01:~# kamailio -V
version: kamailio 5.2.0-pre1 (x86_64/linux)
flags: STATS: Off, USE_TCP, USE_TLS, USE_SCTP, TLS_HOOKS, USE_RAW_SOCKS, DISABLE_NAGLE, USE_MCAST, DNS_IP_HACK, SHM_MEM, 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 6.3.0
root@sbc01:~#

Source install:

root@sbc02:~# kamailio -V
version: kamailio 5.2.0-pre1 (x86_64/linux) 2ecf60-dirty
flags: STATS: Off, USE_TCP, USE_TLS, USE_SCTP, TLS_HOOKS, USE_RAW_SOCKS, DISABLE_NAGLE, USE_MCAST, DNS_IP_HACK, SHM_MEM, 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: 2ecf60 -dirty
compiled with gcc 6.3.0
root@sbc02:~#

!!!! Note the 2ecf60-dirty !!!

I guess I wasn't going crazy after all! 😄

miconda · 2018-10-26T17:19:12Z

@joelsdc - did you get any new crash after the commit I did? Even the error message is related to To header, the issue was not checking if the CSeq is parsed. The core tries to parse the mandatory headers like To, Call-ID, CSeq, ... if one is broken, parsing stops there.

Unless you got new crash with the commit, there is no reason to open this issue. In general, a log message may or may not be related to a crash, the gdb backtrace shows where the crash happens. Otherwise you would apply a logic that if memory manager prints "no more memory", then it is a bug inside it, not in the code using it.

joelsdc · 2018-10-26T17:40:04Z

@miconda kamailio has not died since the patch. Let's keep this issue closed then, if something happens I'll open a new one with new backtraces.

Sorry for the confusion. 👍

miconda added a commit that referenced this issue Oct 25, 2018

kex: safety check for accessing CSeq in per method stats

5e76302

- GH #1687

joelsdc closed this as completed Oct 25, 2018

joelsdc reopened this Oct 26, 2018

joelsdc closed this as completed Oct 26, 2018

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Core generated by Kamailio when a bad char is found in header #1687

Core generated by Kamailio when a bad char is found in header #1687

joelsdc commented Oct 24, 2018 •

edited

joelsdc commented Oct 24, 2018

miconda commented Oct 25, 2018

joelsdc commented Oct 25, 2018 •

edited

henningw commented Oct 25, 2018

joelsdc commented Oct 25, 2018

kamailio-sync commented Oct 26, 2018 via email

joelsdc commented Oct 26, 2018

joelsdc commented Oct 26, 2018

joelsdc commented Oct 26, 2018

miconda commented Oct 26, 2018

joelsdc commented Oct 26, 2018

Core generated by Kamailio when a bad char is found in header #1687

Core generated by Kamailio when a bad char is found in header #1687

Comments

joelsdc commented Oct 24, 2018 • edited

Description

Troubleshooting

Reproduction

Debugging Data

Log Messages

SIP Traffic

Possible Solutions

Additional Information

joelsdc commented Oct 24, 2018

miconda commented Oct 25, 2018

joelsdc commented Oct 25, 2018 • edited

henningw commented Oct 25, 2018

joelsdc commented Oct 25, 2018

kamailio-sync commented Oct 26, 2018 via email

joelsdc commented Oct 26, 2018

joelsdc commented Oct 26, 2018

joelsdc commented Oct 26, 2018

miconda commented Oct 26, 2018

joelsdc commented Oct 26, 2018

joelsdc commented Oct 24, 2018 •

edited

joelsdc commented Oct 25, 2018 •

edited