(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/
Module: sip-router
Branch: master
Commit: 949e1f3c3e1f1afa02c696403399a093905c3f0a
URL: http://git.sip-router.org/cgi-bin/gitweb.cgi/sip-router/?a=commit;h=949e1f3…
Author: Daniel-Constantin Mierla <miconda(a)gmail.com>
Committer: Daniel-Constantin Mierla <miconda(a)gmail.com>
Date: Thu Sep 19 15:45:43 2013 +0200
parser: refactored a bit sip_msg_t struct for extra fields needed per process
- a new structure to keep cached decoded flow for outbound, previously
was declared inline
- easier to reset it for shm clone and tm faked environment
- new fields that are needed inside the sip_msg_t but not cloned in shm,
must be added in the msg_ldata_t structure, accessible via ldv field
---
parser/msg_parser.c | 11 +++++++++++
parser/msg_parser.h | 25 +++++++++++++++++++++----
2 files changed, 32 insertions(+), 4 deletions(-)
diff --git a/parser/msg_parser.c b/parser/msg_parser.c
index 02ad583..1631401 100644
--- a/parser/msg_parser.c
+++ b/parser/msg_parser.c
@@ -734,6 +734,7 @@ void free_sip_msg(struct sip_msg* const msg)
if (msg->add_rm) free_lump_list(msg->add_rm);
if (msg->body_lumps) free_lump_list(msg->body_lumps);
if (msg->reply_lump) free_reply_lump(msg->reply_lump);
+ msg_ldata_reset(msg);
/* don't free anymore -- now a pointer to a static buffer */
# ifdef DYN_BUF
pkg_free(msg->buf);
@@ -952,6 +953,16 @@ void reset_ua(struct sip_msg* const msg)
msg->location_ua.len = 0;
}
+/**
+ * reset content of msg->ldv (msg_ldata_t structure)
+ */
+void msg_ldata_reset(sip_msg_t *msg)
+{
+ if(msg==NULL)
+ return;
+ memset(&msg->ldv, 0, sizeof(msg_ldata_t));
+}
+
hdr_field_t* get_hdr(const sip_msg_t* const msg, const enum _hdr_types_t ht)
{
diff --git a/parser/msg_parser.h b/parser/msg_parser.h
index 08b76ed..d6df9b3 100644
--- a/parser/msg_parser.h
+++ b/parser/msg_parser.h
@@ -253,6 +253,19 @@ typedef struct msg_body {
/* pre-declaration, to include sys/time.h in .c */
struct timeval;
+/* structure for cached decoded flow for outbound */
+typedef struct ocd_flow {
+ int decoded;
+ struct receive_info rcv;
+} ocd_flow_t;
+
+/* structure holding fields that don't have to be cloned in shm
+ * - its content is memset'ed to in shm clone
+ * - add to msg_ldata_reset() if a field uses dynamic memory */
+typedef struct msg_ldata {
+ ocd_flow_t flow;
+} msg_ldata_t;
+
/*! \brief The SIP message */
typedef struct sip_msg {
unsigned int id; /*!< message id, unique/process*/
@@ -363,10 +376,9 @@ typedef struct sip_msg {
str ruid;
str location_ua;
- struct {
- int decoded;
- struct receive_info rcv;
- } flow;
+ /* structure with fields that are needed for local processing
+ * - not cloned to shm, reset to 0 in the clone */
+ msg_ldata_t ldv;
/* IMPORTANT: when adding new fields in this structure (sip_msg_t),
* be sure it is freed in free_sip_msg() and it is cloned or reset
@@ -514,4 +526,9 @@ int msg_ctx_id_match(const sip_msg_t* const msg, const msg_ctx_id_t* const mid);
*/
int msg_set_time(sip_msg_t* const msg);
+/**
+ * reset content of msg->ldv (msg_ldata_t structure)
+ */
+void msg_ldata_reset(sip_msg_t*);
+
#endif
Module: sip-router
Branch: master
Commit: 10cc1dd7a3f4481c677022e7ff0da87f004077f0
URL: http://git.sip-router.org/cgi-bin/gitweb.cgi/sip-router/?a=commit;h=10cc1dd…
Author: Daniel-Constantin Mierla <miconda(a)gmail.com>
Committer: Daniel-Constantin Mierla <miconda(a)gmail.com>
Date: Thu Sep 19 15:12:29 2013 +0200
parser: added note about new fields in sip_msg_t
---
parser/msg_parser.h | 6 ++++++
1 files changed, 6 insertions(+), 0 deletions(-)
diff --git a/parser/msg_parser.h b/parser/msg_parser.h
index 5d481e0..08b76ed 100644
--- a/parser/msg_parser.h
+++ b/parser/msg_parser.h
@@ -367,6 +367,12 @@ typedef struct sip_msg {
int decoded;
struct receive_info rcv;
} flow;
+
+ /* IMPORTANT: when adding new fields in this structure (sip_msg_t),
+ * be sure it is freed in free_sip_msg() and it is cloned or reset
+ * to shm structure for transaction - see sip_msg_clone.c. In tm
+ * module, take care of these fields for faked environemt used for
+ * runing failure handlers - see modules/tm/t_reply.c */
} sip_msg_t;
/*! \brief pointer to a fakes message which was never received ;
THIS IS AN AUTOMATED MESSAGE, DO NOT REPLY.
Víctor Seva has taken ownership of the following task:
FS#346 - avpops: use xavp semantic on second parameter
More information can be found at the following URL:
https://sip-router.org/tracker/index.php?do=details&task_id=346
You are receiving this message because you have requested it from the Flyspray bugtracking system. If you did not expect this message or don't want to receive mails in future, you can change your notification settings at the URL shown above.
Hello,
some (not so) recently fields added to sip_msg_t structure were not
handled properly. These are instance (added by Juha), ruid, location_ua
(added by Crocodile patches), so I explicitely put to repicients the
people working with them to check my changes I did for fixing some
related issues.
The issues:
1) sip_msg_t is cloned in shm for transaction. So each new field added
to this structure has to be handled in the function that clones to shm,
otherwise their values will stay referencing to pkg. Then, same fields
have to be handled in tm when running sip failure handlers -- there a
faked environment and sip msg structure are created from shm back to pkg.
2) if the new fields allocate memory, the free sip msg function has to
clean that, otherwise will be a memory leak
The reason writing here is that for 1) I didn't clone the values in shm,
just reset the pointers to NULL (same is done for path vector). But if
you need these values to be in transaction, then you have to clone them.
What I did fixes a crash when trying to use lookup() in failure route --
because these fields are set, when the new values have a lower lenght,
it will just write in buffer, which is invalid as either the pkg pointer
was freed or the failure route is executed in another process (resulting
in writing at inappropriate addresses in current process). My assumption
was that no one used these fields from transaction, because would have
reported a crash as well, thus I didn't clone and set them to NULL.
Cheers,
Daniel
--
Daniel-Constantin Mierla - http://www.asipto.comhttp://twitter.com/#!/miconda - http://www.linkedin.com/in/miconda
Kamailio Advanced Trainings - Berlin, Oct 21-24; Miami, Nov 11-13, 2013
- more details about Kamailio trainings at http://www.asipto.com -