27 Aug
2013
27 Aug
'13
12:17 p.m.
(Sorry for the long post. Unfortunately, not all bugs are simple.)
I've got a crash bug that occurs when freeing To header parameters when
freeing a SIP message. It only occurs in certain circumstances. I can
reproduce the circumstances on my side consistently, but I suspect it
would be difficult for someone else to reproduce them independently.
Those circumstances are:
1. A Kamailio registrar routes an inbound call from the PSTN to a user
using a Snom One PBX using serial forking across two different bindings
(two different AOR domains) that come from two different registrars
(going into the same database).
2. The PBX sends back a 480 Temporarily Unavailable message to Kamailio
in response to every INVITE, on all branches, all the time.
3. It takes several attempts (usually 5-10) of calling that PBX to get
to Kamailio crash.
4. It only happens when the initial INVITE is processed using a
particular sequence of routes in the route script. There is nothing
unusual about the routes themselves, and I've eliminated all the side
effects and dependencies I can. It just doesn't happen when I have the
call zig through those routes as opposed to those routes. That suggests
package memory corruption that is tripped over by a particular
conjuncture of circumstances.
Here is the 480 Temporarily Unavailable message sent by the PBX. IPs
and numbers have been redacted for customer privacy, but the string
lengths are the same:
Here's the INVITE we're sending to the PBX:
INVITE sip:16504578199@184.178.234.121:5060;transport=udp;line=eccbc87e
SIP/2.0
Record-Route:
<sip:55.177.31.199;lr=on;ftag=c00080a-13c4-521c7390-2e862c51-6c96b554;vsf=AAAAAB0GDg4NDQUCBwd3A3AKHgEaFwUbCBsIHjEwOjUwNjA7aXN1cC1vbGk9MA--;dlgcor=5af.3bb>
From:
<sip:6784841111@192.13.219.87>;tag=c00080a-13c4-521c7390-2e862c51-6c96b554
To: <sip:16504578199@55.177.31.199:5060>
Call-ID:
CXC-72-6a0635d8-c00080a-13c4-521c7390-2e862c51-7eeb3166(a)192.13.219.87
CSeq: 1 INVITE
Via: SIP/2.0/UDP 55.177.31.199;branch=z9hG4bKcdfc.af721dd5.1
Via: SIP/2.0/UDP
192.13.219.87:5060;branch=z9hG4bK-3290-521c7390-2e862c51-3a62fcfd
Max-Forwards: 32
Content-Disposition: session;handling=required
Contact:
<sip:+16784841111@192.13.219.87:5060;isup-oli=0;maddr=192.13.219.87;transport=udp>
Content-Type: application/sdp
Content-Length: 274
Privacy: off
P-Asserted-Identity: "Unavailable" <sip:+16784841111@192.13.219.87>
v=0
o=Acme_UAS 0 1 IN IP4 175.154.21.89
s=SIP Media Capabilities
c=IN IP4 12.131.2.144
t=0 0
m=audio 6698 RTP/AVP 0 18 101
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:18 annexb=no
a=fmtp:101 0-15
a=maxptime:30
a=sendrecv
And here's the 480 Temporarily Unavailable we get back every time we do,
on both branches. Nothing about it looks unusual to me:
SIP/2.0 480 Temporarily Unavailable
Via: SIP/2.0/UDP 55.177.31.199;branch=z9hG4bKcdfc.af721dd5.0
Via: SIP/2.0/UDP
192.13.219.87:5060;branch=z9hG4bK-3290-521c7390-2e862c51-3a62fcfd
Record-Route:
<sip:55.177.31.199;lr=on;ftag=c00080a-13c4-521c7390-2e862c51-6c96b554;vsf=AAAAAB0GDg4NDQUCBwd3A3AKHgEaFwUbCBsIHjEwOjUwNjA7aXN1cC1vbGk9MA--;dlgcor=5af.3bb>
From:
<sip:6784841111@192.13.219.87>;tag=c00080a-13c4-521c7390-2e862c51-6c96b554
To: <sip:16504578199@55.177.31.199:5060>;tag=d3516ef5fa
Call-ID:
CXC-72-6a0635d8-c00080a-13c4-521c7390-2e862c51-7eeb3166(a)192.13.219.87
CSeq: 1 INVITE
Contact: <sip:5282797646@195.105.225.111:5060;transport=udp>
Supported: 100rel, replaces, norefersub
Allow-Events: refer
Allow: INVITE, ACK, CANCEL, BYE, REFER, PRACK, INFO, UPDATE
Accept: application/sdp
User-Agent: snomONE/4.5.1.1107 Zeta Perseids
Content-Length: 0
But when this happens a few times, Kamailio crashes:
05:38:24.317781 IP 195.105.225.111.5060 > 55.177.31.199.5060: SIP,
length: 592
E..l..@.4.2....yA.,......X..SIP/2.0 100 Trying
--
05:38:24.333573 IP 195.105.225.111.5060 > 55.177.31.199.5060: SIP,
length: 865
E..}..@.4.1....yA.,......i.$SIP/2.0 480 Temporarily Unavailable
--
05:38:24.333767 IP 55.177.31.199.5060 > 195.105.225.111.5060: SIP,
length: 411
E.......@..<A.,....y........ACK
sip:16504578199@195.105.225.111:5060;transport=udp;line=c81e728d SIP/2.0
--
05:38:24.335593 IP 55.177.31.199.5060 > 195.105.225.111.5060: SIP,
length: 1187
E.......@..3A.,....y........INVITE
sip:16504578199@195.105.225.111:5060;transport=udp;line=eccbc87e SIP/2.0
--
05:38:24.385873 IP 195.105.225.111.5060 > 55.177.31.199.5060: SIP,
length: 865
E..}..@.4.1....yA.,......i.$SIP/2.0 480 Temporarily Unavailable
--
05:38:24.386126 IP 55.177.31.199.5060 > 195.105.225.111.5060: SIP,
length: 411
E.......@..:A.,....y........ACK
sip:16504578199@195.105.225.111:5060;transport=udp;line=c81e728d SIP/2.0
--
05:38:24.831672 IP 55.177.31.199.5060 > 195.105.225.111.5060: SIP,
length: 1187
E.......@..1A.,....y........INVITE
sip:16504578199@195.105.225.111:5060;transport=udp;line=eccbc87e SIP/2.0
--
05:38:24.877627 IP 195.105.225.111.5060 > 55.177.31.199.5060: SIP,
length: 865
E..}..@.4.1....yA.,......i.$SIP/2.0 480 Temporarily Unavailable
--
05:38:24.877933 IP 55.177.31.199.5060 > 195.105.225.111.5060: SIP,
length: 411
E.......@..8A.,....y........ACK
sip:16504578199@195.105.225.111:5060;transport=udp;line=c81e728d SIP/2.0
--
05:38:25.831617 IP 55.177.31.199.5060 > 195.105.225.111.5060: SIP,
length: 1187
E.......@../A.,....y........INVITE
sip:16504578199@195.105.225.111:5060;transport=udp;line=eccbc87e SIP/2.0
--
05:38:25.881560 IP 195.105.225.111.5060 > 55.177.31.199.5060: SIP,
length: 865
E..}..@.4.1....yA.,......i.$SIP/2.0 480 Temporarily Unavailable
--
05:38:25.881731 IP 55.177.31.199.5060 > 195.105.225.111.5060: SIP,
length: 411
E.......@..6A.,....y........ACK
sip:16504578199@195.105.225.111:5060;transport=udp;line=c81e728d SIP/2.0
--
05:38:32.219484 IP 55.177.31.199.5060 > 195.105.225.111.5060: SIP,
length: 1183
E.......@..1A.,....y........INVITE
sip:16504578199@195.105.225.111:5060;transport=udp;line=c81e728d SIP/2.0
--
05:38:32.270568 IP 195.105.225.111.5060 > 55.177.31.199.5060: SIP,
length: 588
E..h..@.4.2....yA.,......T..SIP/2.0 100 Trying
--
05:38:32.289120 IP 195.105.225.111.5060 > 55.177.31.199.5060: SIP,
length: 861
E..y..@.4.1....yA.,......e.7SIP/2.0 480 Temporarily Unavailable
--
05:38:32.289284 IP 55.177.31.199.5060 > 195.105.225.111.5060: SIP,
length: 408
E.......@..7A.,....y........ACK
sip:16504578199@195.105.225.111:5060;transport=udp;line=c81e728d SIP/2.0
--
05:38:32.291180 IP 55.177.31.199.5060 > 195.105.225.111.5060: SIP,
length: 1183
E.......@../A.,....y........INVITE
sip:16504578199@195.105.225.111:5060;transport=udp;line=eccbc87e SIP/2.0
--
05:38:32.340763 IP 195.105.225.111.5060 > 55.177.31.199.5060: SIP,
length: 861
E..y..@.4.1....yA.,......e.7SIP/2.0 480 Temporarily Unavailable
--
05:38:32.340986 IP 55.177.31.199.5060 > 195.105.225.111.5060: SIP,
length: 408
E.......@..5A.,....y........ACK
sip:16504578199@195.105.225.111:5060;transport=udp;line=c81e728d SIP/2.0
--
05:38:32.769133 IP 55.177.31.199.5060 > 195.105.225.111.5060: SIP,
length: 1183
E.......@..-A.,....y........INVITE
sip:16504578199@195.105.225.111:5060;transport=udp;line=eccbc87e SIP/2.0
--
05:38:32.814851 IP 195.105.225.111.5060 > 55.177.31.199.5060: SIP,
length: 861
E..y..@.4.1....yA.,......e.7SIP/2.0 480 Temporarily Unavailable
--
05:38:32.814993 IP 55.177.31.199.5060 > 195.105.225.111.5060: SIP,
length: 408
E.... ..@..3A.,....y........ACK
sip:16504578199@195.105.225.111:5060;transport=udp;line=c81e728d SIP/2.0
--
05:38:33.769113 IP 55.177.31.199.5060 > 195.105.225.111.5060: SIP,
length: 1183
E....
--
05:38:33.815374 IP 195.105.225.111.5060 > 55.177.31.199.5060: SIP,
length: 861
E..y..@.4.1....yA.,......e.7SIP/2.0 480 Temporarily Unavailable
--
05:38:33.815600 IP 55.177.31.199.5060 > 195.105.225.111.5060: SIP,
length: 408
E.......@..1A.,....y........ACK
sip:16504578199@195.105.225.111:5060;transport=udp;line=c81e728d SIP/2.0
--
05:38:42.371141 IP 55.177.31.199.5060 > 195.105.225.111.5060: SIP,
length: 1188
E.......@..$A.,....y........INVITE
sip:16504578199@195.105.225.111:5060;transport=udp;line=c81e728d SIP/2.0
--
05:38:42.422190 IP 195.105.225.111.5060 > 55.177.31.199.5060: SIP,
length: 592
E..l..@.4.2....yA.,......X.jSIP/2.0 100 Trying
--
05:38:42.438849 IP 195.105.225.111.5060 > 55.177.31.199.5060: SIP,
length: 865
E..}..@.4.1....yA.,......iE SIP/2.0 480 Temporarily Unavailable
--
05:38:42.439005 IP 55.177.31.199.5060 > 195.105.225.111.5060: SIP,
length: 410
..@..-A.,....y........ACK
sip:16504578199@195.105.225.111:5060;transport=udp;line=c81e728d SIP/2.0
--
05:38:42.440373 IP 55.177.31.199.5060 > 195.105.225.111.5060: SIP,
length: 1188
E.......@.."A.,....y........INVITE
sip:16504578199@195.105.225.111:5060;transport=udp;line=eccbc87e SIP/2.0
--
05:38:42.490261 IP 195.105.225.111.5060 > 55.177.31.199.5060: SIP,
length: 865
E..}..@.4.1....yA.,......iE SIP/2.0 480 Temporarily Unavailable
--
05:38:42.490348 IP 55.177.31.199.5060 > 195.105.225.111.5060: SIP,
length: 410
E.......@..+A.,....y........ACK
sip:16504578199@195.105.225.111:5060;transport=udp;line=c81e728d SIP/2.0
--
05:38:42.894122 IP 55.177.31.199.5060 > 195.105.225.111.5060: SIP,
length: 1188
E.......@.. A.,....y........INVITE
sip:16504578199@195.105.225.111:5060;transport=udp;line=eccbc87e SIP/2.0
--
05:38:42.940323 IP 195.105.225.111.5060 > 55.177.31.199.5060: SIP,
length: 865
E..}..@.4.1....yA.,......iE SIP/2.0 480 Temporarily Unavailable
--
05:38:42.940562 IP 55.177.31.199.5060 > 195.105.225.111.5060: SIP,
length: 410
E.......@..)A.,....y........ACK
sip:16504578199@195.105.225.111:5060;transport=udp;line=c81e728d SIP/2.0
--
05:38:43.894116 IP 55.177.31.199.5060 > 195.105.225.111.5060: SIP,
length: 1188
E.......@...A.,....y........INVITE
sip:16504578199@195.105.225.111:5060;transport=udp;line=eccbc87e SIP/2.0
--
05:38:43.940482 IP 195.105.225.111.5060 > 55.177.31.199.5060: SIP,
length: 865
E..}..@.4.1....yA.,......iE SIP/2.0 480 Temporarily Unavailable
--
05:38:43.940604 IP 55.177.31.199.5060 > 195.105.225.111.5060: SIP,
length: 410
E.......@..'A.,....y........ACK
sip:16504578199@195.105.225.111:5060;transport=udp;line=c81e728d SIP/2.0
--
05:38:50.261551 IP 55.177.31.199.5060 > 195.105.225.111.5060: SIP,
length: 1188
E.......@...A.,....y........INVITE
sip:16504578199@195.105.225.111:5060;transport=udp;line=c81e728d SIP/2.0
--
05:38:50.313509 IP 195.105.225.111.5060 > 55.177.31.199.5060: SIP,
length: 592
E..l..@.4.2....yA.,......X..SIP/2.0 100 Trying
--
05:38:50.329411 IP 195.105.225.111.5060 > 55.177.31.199.5060: SIP,
length: 865
E..}..@.4.1....yA.,......i..SIP/2.0 480 Temporarily Unavailable
--
05:38:50.329584 IP 55.177.31.199.5060 > 195.105.225.111.5060: SIP,
length: 411
E.......@..$A.,....y........ACK
sip:16504578199@195.105.225.111:5060;transport=udp;line=c81e728d SIP/2.0
--
05:38:50.331250 IP 55.177.31.199.5060 > 195.105.225.111.5060: SIP,
length: 1188
E.......@...A.,....y........INVITE
sip:16504578199@195.105.225.111:5060;transport=udp;line=eccbc87e SIP/2.0
--
05:38:50.379415 IP 195.105.225.111.5060 > 55.177.31.199.5060: SIP,
length: 865
E..}..@.4.1....yA.,......i..SIP/2.0 480 Temporarily Unavailable
--
05:38:50.379584 IP 55.177.31.199.5060 > 195.105.225.111.5060: SIP,
length: 411
E.......@.."A.,....y........ACK
sip:16504578199@195.105.225.111:5060;transport=udp;line=c81e728d SIP/2.0
--
05:38:50.769124 IP 55.177.31.199.5060 > 195.105.225.111.5060: SIP,
length: 1188
E.......@...A.,....y........INVITE
sip:16504578199@195.105.225.111:5060;transport=udp;line=eccbc87e SIP/2.0
--
05:38:50.817797 IP 195.105.225.111.5060 > 55.177.31.199.5060: SIP,
length: 865
E..}..@.4.1....yA.,......i..SIP/2.0 480 Temporarily Unavailable
--
05:38:50.817936 IP 55.177.31.199.5060 > 195.105.225.111.5060: SIP,
length: 411
E.......@.. A.,....y........ACK
sip:16504578199@195.105.225.111:5060;transport=udp;line=c81e728d SIP/2.0
--
05:38:51.769119 IP 55.177.31.199.5060 > 195.105.225.111.5060: SIP,
length: 1188
E.......@...A.,....y........INVITE
sip:16504578199@195.105.225.111:5060;transport=udp;line=eccbc87e SIP/2.0
--
05:38:51.815689 IP 195.105.225.111.5060 > 55.177.31.199.5060: SIP,
length: 865
E..}..@.4.1....yA.,......i..SIP/2.0 480 Temporarily Unavailable
--
05:38:51.815844 IP 55.177.31.199.5060 > 195.105.225.111.5060: SIP,
length: 411
E.......@...A.,....y........ACK
sip:16504578199@195.105.225.111:5060;transport=udp;line=c81e728d SIP/2.0
--
05:39:00.197890 IP 55.177.31.199.5060 > 195.105.225.111.5060: SIP,
length: 1182
E.......@...A.,....y........INVITE
sip:16504578199@195.105.225.111:5060;transport=udp;line=c81e728d SIP/2.0
--
05:39:00.248713 IP 195.105.225.111.5060 > 55.177.31.199.5060: SIP,
length: 586
E..f..@.4.2....yA.,......RD_SIP/2.0 100 Trying
--
05:39:00.264983 IP 195.105.225.111.5060 > 55.177.31.199.5060: SIP,
length: 859
E..w..@.4.1....yA.,......c-.SIP/2.0 480 Temporarily Unavailable
--
05:39:00.265140 IP 55.177.31.199.5060 > 195.105.225.111.5060: SIP,
length: 408
E.......@...A.,....y........ACK
sip:16504578199@195.105.225.111:5060;transport=udp;line=c81e728d SIP/2.0
--
05:39:00.266675 IP 55.177.31.199.5060 > 195.105.225.111.5060: SIP,
length: 1182
E.......@...A.,....y........INVITE
sip:16504578199@195.105.225.111:5060;transport=udp;line=eccbc87e SIP/2.0
--
05:39:00.317151 IP 195.105.225.111.5060 > 55.177.31.199.5060: SIP,
length: 859
E..w..@.4.1....yA.,......c-.SIP/2.0 480 Temporarily Unavailable
--
05:39:00.317285 IP 55.177.31.199.5060 > 195.105.225.111.5060: SIP,
length: 408
E.......@...A.,....y........ACK
sip:16504578199@195.105.225.111:5060;transport=udp;line=c81e728d SIP/2.0
--
05:39:00.706627 IP 55.177.31.199.5060 > 195.105.225.111.5060: SIP,
length: 1182
E.... ..@...A.,....y........INVITE
sip:16504578199@195.105.225.111:5060;transport=udp;line=eccbc87e SIP/2.0
--
05:39:00.752906 IP 195.105.225.111.5060 > 55.177.31.199.5060: SIP,
length: 859
E..w..@.4.1....yA.,......c-.SIP/2.0 480 Temporarily Unavailable
--
05:39:00.753054 IP 55.177.31.199.5060 > 195.105.225.111.5060: SIP,
length: 408
E....!..@...A.,....y........ACK
sip:16504578199@195.105.225.111:5060;transport=udp;line=c81e728d SIP/2.0
--
05:39:01.706639 IP 55.177.31.199.5060 > 195.105.225.111.5060: SIP,
length: 1182
E...."..@...A.,....y........INVITE
sip:16504578199@195.105.225.111:5060;transport=udp;line=eccbc87e SIP/2.0
--
05:39:01.753036 IP 195.105.225.111.5060 > 55.177.31.199.5060: SIP,
length: 859
E..w..@.4.1....yA.,......c-.SIP/2.0 480 Temporarily Unavailable
--
05:39:01.753198 IP 55.177.31.199.5060 > 195.105.225.111.5060: SIP,
length: 408
E....#..@...A.,....y........ACK
sip:16504578199@195.105.225.111:5060;transport=udp;line=c81e728d SIP/2.0
--
05:39:08.088801 IP 55.177.31.199.5060 > 195.105.225.111.5060: SIP,
length: 1190
E....$..@..
--
05:39:08.139841 IP 195.105.225.111.5060 > 55.177.31.199.5060: SIP,
length: 594
E..n..@.4.2....yA.,......ZhVSIP/2.0 100 Trying
--
05:39:08.156036 IP 195.105.225.111.5060 > 55.177.31.199.5060: SIP,
length: 867
E.....@.4.1....yA.,......k4.SIP/2.0 480 Temporarily Unavailable
--
05:39:08.156222 IP 55.177.31.199.5060 > 195.105.225.111.5060: SIP,
length: 412
E....%..@...A.,....y........ACK
sip:16504578199@195.105.225.111:5060;transport=udp;line=c81e728d SIP/2.0
--
05:39:08.157697 IP 55.177.31.199.5060 > 195.105.225.111.5060: SIP,
length: 1190
E....&..@...A.,....y........INVITE
sip:16504578199@195.105.225.111:5060;transport=udp;line=eccbc87e SIP/2.0
--
05:39:08.208158 IP 195.105.225.111.5060 > 55.177.31.199.5060: SIP,
length: 867
E.....@.4.1....yA.,......k4.SIP/2.0 480 Temporarily Unavailable
--
05:39:08.208282 IP 55.177.31.199.5060 > 195.105.225.111.5060: SIP,
length: 412
E....'..@...A.,....y........ACK
sip:16504578199@195.105.225.111:5060;transport=udp;line=c81e728d SIP/2.0
--
05:39:08.644104 IP 55.177.31.199.5060 > 195.105.225.111.5060: SIP,
length: 1190
E....(..@...A.,....y........INVITE
sip:16504578199@195.105.225.111:5060;transport=udp;line=eccbc87e SIP/2.0
--
05:39:08.690068 IP 195.105.225.111.5060 > 55.177.31.199.5060: SIP,
length: 867
E.....@.4.1....yA.,......k4.SIP/2.0 480 Temporarily Unavailable
--
05:39:08.690212 IP 55.177.31.199.5060 > 195.105.225.111.5060: SIP,
length: 412
E....)..@...A.,....y........ACK
sip:16504578199@195.105.225.111:5060;transport=udp;line=c81e728d SIP/2.0
--
05:39:09.644112 IP 55.177.31.199.5060 > 195.105.225.111.5060: SIP,
length: 1190
E....*..@...A.,....y........INVITE
sip:16504578199@195.105.225.111:5060;transport=udp;line=eccbc87e SIP/2.0
--
05:39:09.690201 IP 195.105.225.111.5060 > 55.177.31.199.5060: SIP,
length: 867
E.....@.4.1....yA.,......k4.SIP/2.0 480 Temporarily Unavailable
--
05:39:09.690374 IP 55.177.31.199.5060 > 195.105.225.111.5060: SIP,
length: 412
A.,....y........ACK
sip:16504578199@195.105.225.111:5060;transport=udp;line=c81e728d SIP/2.0
Anyway, my core dumps were showing me qm_*() free errors. To get at the
problem, I disabled loop unrolling, removed -09 and added the GDB debug
flags (-ggdb*) to the compile flags. When I do that, I get one of these
two call stacks--mostly the first, and occasionally the second:
#0 0x000000000055dc2e in free_to_params (tb=0x7fcb38f5f750)
at parser/parse_to.c:827
#1 0x000000000055dc75 in free_to (tb=0x7fcb38f5f750) at
parser/parse_to.c:836
#2 0x000000000053d9df in clean_hdr_field (hf=0x7fcb38f5fb50)
at parser/hf.c:169
#3 0x000000000053db49 in free_hdr_field_lst (hf=0x7fcb38f590e0)
at parser/hf.c:223
#4 0x0000000000542330 in free_sip_msg (msg=0x7fcb38f5edf0)
at parser/msg_parser.c:729
#5 0x000000000049d9cb in receive_msg (
buf=0x905580 "SIP/2.0 480 Temporarily Unavailable\r\nVia:
SIP/2.0/UDP 55.177.31.199;branch=z9hG4bK818c.b6308b63.0\r\nVia:
SIP/2.0/UDP 192.13.219.87:5060;branch=z9hG4bK-28db-521c65ea-2e50da5e-
8f9ae0d\r\nRecord-Route: <sip"..., len=864,
rcv_info=0x7fff2bcad950) at receive.c:294
#6 0x000000000052f5cd in udp_rcv_loop () at udp_server.c:557
#7 0x0000000000467de2 in main_loop () at main.c:1638
#8 0x000000000046ad8b in main (argc=13, argv=0x7fff2bcadc88) at
main.c:2566
----
#0 0x00000000005394e9 in qm_detach_free (qm=0x7f25c3037010,
frag=0x7f25c3256af0) at mem/q_malloc.c:266
#1 0x0000000000539744 in qm_malloc (qm=0x7f25c3037010, size=960)
at mem/q_malloc.c:386
#2 0x00000000004bba49 in rval_new_empty (extra_size=102) at
rvalue.c:236
#3 0x00000000004bbabb in rval_new_str (s=0x7fffbad95460, extra_size=80)
at rvalue.c:260
#4 0x00000000004be1b3 in rval_convert (h=0x7fffbad972a0,
msg=0x7f25c2587920,
type=RV_STR, v=0x7f25c3182ee8, c=0x7fffbad95620) at rvalue.c:1321
#5 0x00000000004bf657 in rval_str_lop2 (h=0x7fffbad972a0,
msg=0x7f25c2587920,
res=0x7fffbad95ac8, op=RVE_EQ_OP, l=0x7f25c3182ee8,
c1=0x7fffbad95620,
r=0x7f25c3183668, c2=0x0) at rvalue.c:1752
#6 0x00000000004c028d in rval_expr_eval_int (h=0x7fffbad972a0,
msg=0x7f25c2587920, res=0x7fffbad95ac8, rve=0x7f25c3183d40)
at rvalue.c:2058
#7 0x0000000000418d5a in do_action (h=0x7fffbad972a0, a=0x7f25c3185190,
msg=0x7f25c2587920) at action.c:1050
#8 0x0000000000421aa7 in run_actions (h=0x7fffbad972a0,
a=0x7f25c3182d40,
msg=0x7f25c2587920) at action.c:1573
#9 0x000000000042047f in do_action (h=0x7fffbad972a0, a=0x7f25c3185530,
msg=0x7f25c2587920) at action.c:1374
#10 0x0000000000421aa7 in run_actions (h=0x7fffbad972a0,
a=0x7f25c317a2a0,
msg=0x7f25c2587920) at action.c:1573
#11 0x0000000000418fa2 in do_action (h=0x7fffbad972a0, a=0x7f25c318ac10,
msg=0x7f25c2587920) at action.c:1065
#12 0x0000000000421aa7 in run_actions (h=0x7fffbad972a0,
a=0x7f25c318ac10,
---Type <return> to continue, or q <return> to quit---
msg=0x7f25c2587920) at action.c:1573
#13 0x0000000000418ffb in do_action (h=0x7fffbad972a0, a=0x7f25c318ad10,
msg=0x7f25c2587920) at action.c:1069
#14 0x0000000000421aa7 in run_actions (h=0x7fffbad972a0,
a=0x7f25c3163930,
msg=0x7f25c2587920) at action.c:1573
#15 0x0000000000416f3a in do_action (h=0x7fffbad972a0, a=0x7f25c3194fc0,
msg=0x7f25c2587920) at action.c:690
#16 0x0000000000421aa7 in run_actions (h=0x7fffbad972a0,
a=0x7f25c318eaf0,
msg=0x7f25c2587920) at action.c:1573
#17 0x0000000000422231 in run_top_route (a=0x7f25c318eaf0,
msg=0x7f25c2587920,
c=0x0) at action.c:1658
#18 0x00007f25c233b220 in run_failure_handlers (t=0x7f24be53b2a0,
rpl=0x7f25c32554b0, code=480, extra_flags=64) at t_reply.c:1024
#19 0x00007f25c233c39b in t_should_relay_response (Trans=0x7f24be53b2a0,
new_code=480, branch=0, should_store=0x7fffbad97580,
should_relay=0x7fffbad97584, cancel_data=0x7fffbad97790,
reply=0x7f25c32554b0) at t_reply.c:1300
#20 0x00007f25c233dec4 in relay_reply (t=0x7f24be53b2a0,
p_msg=0x7f25c32554b0,
branch=0, msg_status=480, cancel_data=0x7fffbad97790,
do_put_on_wait=1)
at t_reply.c:1703
#21 0x00007f25c2340f46 in reply_received (p_msg=0x7f25c32554b0)
at t_reply.c:2370
#22 0x0000000000458861 in do_forward_reply (msg=0x7f25c32554b0, mode=0)
at forward.c:799
#23 0x00000000004590d0 in forward_reply (msg=0x7f25c32554b0) at
forward.c:882
#24 0x000000000049d8a4 in receive_msg (
---Type <return> to continue, or q <return> to quit---
buf=0x905580 "SIP/2.0 480 Temporarily Unavailable\r\nVia:
SIP/2.0/UDP 55.177.31.199;branch=z9hG4bK0c.2611fa52.0\r\nVia:
SIP/2.0/UDP 192.13.219.87:5060;branch=z9hG4bK-293c-521c669b-2e538ce5-
7bec16be\r\nRecord-Route: <sip:"..., len=863,
rcv_info=0x7fffbad97af0) at receive.c:270
#25 0x000000000052f5cd in udp_rcv_loop () at udp_server.c:557
#26 0x0000000000467de2 in main_loop () at main.c:1638
#27 0x000000000046ad8b in main (argc=13, argv=0x7fffbad97e28) at
main.c:2566
But, 90% of the time, it's the first one. The second one shows up only
occasionally. Sometimes, this variant appears:
#0 0x0000000000538d7a in qm_insert_free (qm=0x7f069c7a6010,
frag=0x7f069c9c57e0) at mem/q_malloc.c:182
#1 0x0000000000539c3d in qm_free (qm=0x7f069c7a6010, p=0x7f069c9c57f0)
at mem/q_malloc.c:527
#2 0x000000000055dc4c in free_to_params (tb=0x7f069c9c73a0)
at parser/parse_to.c:828
#3 0x000000000055dc75 in free_to (tb=0x7f069c9c73a0) at
parser/parse_to.c:836
#4 0x000000000053d8d5 in clean_hdr_field (hf=0x7f069c7d7da0)
at parser/hf.c:113
#5 0x000000000053db49 in free_hdr_field_lst (hf=0x7f069c7d6340)
at parser/hf.c:223
#6 0x0000000000542330 in free_sip_msg (msg=0x7f069c9c44b0)
at parser/msg_parser.c:729
#7 0x000000000049d9cb in receive_msg (
buf=0x905580 "SIP/2.0 480 Temporarily Unavailable\r\nVia:
SIP/2.0/UDP 55.177.31.199;branch=z9hG4bKeb96.24a5718.0\r\nVia:
SIP/2.0/UDP 208.94.157.10:5060;branch=z9hG4bK-368a-521c67f1-3b3bc7c-
5366754e\r\nRecord-Route: <sip:55.177.31.199;lr=on;ftag=c00070a-13c4-
521c67f1-3b3bc7c-
3af08849;vsf=AAAAAB0GDg4NDQUCBwd3A3AKHgEaFwUbBhsGHjEwOjUwNjA7aXN1cC1vbGk
9MA--;dlgcor=789.3d01>\r\nFrom:
<sip:6784841111@208.94.157.10>;tag=c00070a-13c4-521c67f1-3b3bc7c-
3af08849\r\nTo:
<sip:16504578199@55.177.31.199:5060>;tag=3af8238437\r\nCall-ID: CXC-408-
6bb35b50-c00070a-13c4-521c67f1-3b3bc7c-3c339c13(a)208.94.157.10\r\nCSeq: 1
INVITE\r\nContact:
<sip:5282797646@195.105.225.111:5060;transport=udp>\r\nSupported:
100rel, replaces, norefersub\r\nAllow-Events: refer\r\nAllow: INVITE,
ACK, CANCEL, BYE, REFER, PRACK, INFO, UPDATE\r\nAccept:
application/sdp\r\nUser-Agent: snomONE/4.5.1.1107 Zeta
Perseids\r\nContent-Length: 0\r\n\r\n", len=862,
rcv_info=0x7fff87c23070)
So, I focused on the first one. The crash is on pkg_free() in this loop
in parser/parse_to.c:
void free_to_params(struct to_body* const tb)
{
struct to_param *tp=tb->param_lst;
struct to_param *foo;
while (tp){
foo = tp->next;
pkg_free(tp);
tp=foo;
}
}
Removing the pkg_free() definitely eliminates the crash. Or, at least,
I haven't been able to get the proxy to crash in that scenario.
In poking at the values of the to_body,
(gdb) frame 2
#2 0x000000000055dc4c in free_to_params (tb=0x7f069c9c73a0)
at parser/parse_to.c:828
828 pkg_free(tp);
(gdb) print tb
$30 = (struct to_body * const) 0x7f069c9c73a0
(gdb) print tb->uri->s
$31 = 0x9056e6 "sip:6784841111@208.94.157.10>;tag=c00070a-13c4-521c67f1-
3b3bc7c-3af08849\r\nTo:
<sip:16504578199@55.177.31.199:5060>;tag=3af8238437\r\nCall-ID: CXC-408-
6bb35b50-c00070a-13c4-521c67f1-3b3bc7c-3c339c13(a)208.94.157.10\r\nCSeq: 1
INVITE\r\nContact:
<sip:5282797646@195.105.225.111:5060;transport=udp>\r\nSupported:
100rel, replaces, norefersub\r\nAllow-Events: refer\r\nAllow: INVITE,
ACK, CANCEL, BYE, REFER, PRACK, INFO, UPDATE\r\nAccept:
application/sdp\r\nUser-Agent: snomONE/4.5.1.1107 Zeta
Perseids\r\nContent-Length: 0\r\n\r\n"
(gdb) print tb->param_lst
$32 = (struct to_param *) 0x7f069c9c57f0
(gdb) print tb->param_lst->next
$33 = (struct to_param *) 0x0
(gdb) print tb->param_lst->value
$34 = {
s = 0x905708 "c00070a-13c4-521c67f1-3b3bc7c-3af08849\r\nTo:
<sip:16504578199@55.177.31.199:5060>;tag=3af8238437\r\nCall-ID: CXC-408-
6bb35b50-c00070a-13c4-521c67f1-3b3bc7c-3c339c13(a)208.94.157.10\r\nCSeq: 1
INVITE\r\nContact:
<sip:5282797646@195.105.225.111:5060;transport=udp>\r\nSupported:
100rel, replaces, norefersub\r\nAllow-Events: refer\r\nAllow: INVITE,
ACK, CANCEL, BYE, REFER, PRACK, INFO, UPDATE\r\nAccept:
application/sdp\r\nUser-Agent: snomONE/4.5.1.1107 Zeta
Perseids\r\nContent-Length: 0\r\n\r\n", len = 38}
(gdb) print tb->param_lst->name
$35 = {s = 0x3e653834323335 <Address 0x3e653834323335 out of bounds>,
len = 3}
I eventually noticed that I can't seem to get at the 'name' value in the
first (and only) parameter list node:
(gdb) print tb->param_lst->name
$35 = {s = 0x3e653834323335 <Address 0x3e653834323335 out of bounds>,
len = 3}
I guess that should be 'tag', right? It's the only parameter,
unsurprisingly:
(gdb) print tb->param_lst->next
$33 = (struct to_param *) 0x0
Anyway, I can also say that accessing the pointer into the message
buffer to which it corresponds crashes it, but only for that 480 -- not
for any other SIP message that comes through the proxy:
while (tp){
foo = tp->next;
LM_ERR("Freeing up the hinterland: <%s>\n",
tp->name.s);
pkg_free(tp);
tp=foo;
}
(gdb) where
#0 0x0000003dbae480ac in vfprintf () from /lib64/libc.so.6
#1 0x0000003dbaee4fe0 in __vsyslog_chk () from /lib64/libc.so.6
#2 0x0000003dbaee5210 in syslog () from /lib64/libc.so.6
#3 0x000000000055dd47 in free_to_params (tb=0x7fc1def09610)
So, I really get the sense that there's something wrong with that 480
that's corrupting memory. Is that an accurate conclusion? If so, what
it could be, and what's the next step to try to diagnose further?
Thank you!
-- Alex
--
Alex Balashov - Principal
Evariste Systems LLC
235 E Ponce de Leon Ave
Suite 106
Decatur, GA 30030
United States
Tel: +1-678-954-0670
Web: http://www.evaristesys.com/, http://www.alexbalashov.com/