[sr-dev] Crash bug freeing To headers
Daniel-Constantin Mierla
miconda at gmail.com
Tue Aug 27 14:47:39 CEST 2013
Hello,
can you try this patch?
-
http://git.sip-router.org/cgi-bin/gitweb.cgi/sip-router/?a=commit;h=14835f89fc2b761f73a0caad67d229ec3fedba29
One reason for such crash could be double-free, which could eventually
happen because the pointer to params was not reset after freeing the list.
Cheers,
Daniel
On 8/27/13 12:17 PM, Alex Balashov wrote:
> (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 at 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 at 192.13.219.87>;tag=c00080a-13c4-521c7390-2e862c51-6c96b554
> To: <sip:16504578199 at 55.177.31.199:5060>
> Call-ID:
> CXC-72-6a0635d8-c00080a-13c4-521c7390-2e862c51-7eeb3166 at 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 at 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 at 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 at 192.13.219.87>;tag=c00080a-13c4-521c7390-2e862c51-6c96b554
> To: <sip:16504578199 at 55.177.31.199:5060>;tag=d3516ef5fa
> Call-ID:
> CXC-72-6a0635d8-c00080a-13c4-521c7390-2e862c51-7eeb3166 at 192.13.219.87
> CSeq: 1 INVITE
> Contact: <sip:5282797646 at 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.. at .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..}.. at .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....... at ..<A.,....y........ACK
> sip:16504578199 at 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....... at ..3A.,....y........INVITE
> sip:16504578199 at 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..}.. at .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....... at ..:A.,....y........ACK
> sip:16504578199 at 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....... at ..1A.,....y........INVITE
> sip:16504578199 at 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..}.. at .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....... at ..8A.,....y........ACK
> sip:16504578199 at 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....... at ../A.,....y........INVITE
> sip:16504578199 at 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..}.. at .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....... at ..6A.,....y........ACK
> sip:16504578199 at 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....... at ..1A.,....y........INVITE
> sip:16504578199 at 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.. at .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.. at .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....... at ..7A.,....y........ACK
> sip:16504578199 at 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....... at ../A.,....y........INVITE
> sip:16504578199 at 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.. at .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....... at ..5A.,....y........ACK
> sip:16504578199 at 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....... at ..-A.,....y........INVITE
> sip:16504578199 at 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.. at .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.... .. at ..3A.,....y........ACK
> sip:16504578199 at 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.. at .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....... at ..1A.,....y........ACK
> sip:16504578199 at 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....... at ..$A.,....y........INVITE
> sip:16504578199 at 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.. at .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..}.. at .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
> .. at ..-A.,....y........ACK
> sip:16504578199 at 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....... at .."A.,....y........INVITE
> sip:16504578199 at 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..}.. at .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....... at ..+A.,....y........ACK
> sip:16504578199 at 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....... at .. A.,....y........INVITE
> sip:16504578199 at 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..}.. at .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....... at ..)A.,....y........ACK
> sip:16504578199 at 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....... at ...A.,....y........INVITE
> sip:16504578199 at 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..}.. at .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....... at ..'A.,....y........ACK
> sip:16504578199 at 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....... at ...A.,....y........INVITE
> sip:16504578199 at 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.. at .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..}.. at .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....... at ..$A.,....y........ACK
> sip:16504578199 at 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....... at ...A.,....y........INVITE
> sip:16504578199 at 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..}.. at .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....... at .."A.,....y........ACK
> sip:16504578199 at 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....... at ...A.,....y........INVITE
> sip:16504578199 at 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..}.. at .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....... at .. A.,....y........ACK
> sip:16504578199 at 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....... at ...A.,....y........INVITE
> sip:16504578199 at 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..}.. at .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....... at ...A.,....y........ACK
> sip:16504578199 at 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....... at ...A.,....y........INVITE
> sip:16504578199 at 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.. at .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.. at .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....... at ...A.,....y........ACK
> sip:16504578199 at 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....... at ...A.,....y........INVITE
> sip:16504578199 at 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.. at .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....... at ...A.,....y........ACK
> sip:16504578199 at 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.... .. at ...A.,....y........INVITE
> sip:16504578199 at 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.. at .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....!.. at ...A.,....y........ACK
> sip:16504578199 at 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....".. at ...A.,....y........INVITE
> sip:16504578199 at 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.. at .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....#.. at ...A.,....y........ACK
> sip:16504578199 at 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....$.. at ..
> --
> 05:39:08.139841 IP 195.105.225.111.5060 > 55.177.31.199.5060: SIP,
> length: 594
> E..n.. at .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..... at .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....%.. at ...A.,....y........ACK
> sip:16504578199 at 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....&.. at ...A.,....y........INVITE
> sip:16504578199 at 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..... at .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....'.. at ...A.,....y........ACK
> sip:16504578199 at 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....(.. at ...A.,....y........INVITE
> sip:16504578199 at 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..... at .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....).. at ...A.,....y........ACK
> sip:16504578199 at 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....*.. at ...A.,....y........INVITE
> sip:16504578199 at 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..... at .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 at 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 at 208.94.157.10>;tag=c00070a-13c4-521c67f1-3b3bc7c-
> 3af08849\r\nTo:
> <sip:16504578199 at 55.177.31.199:5060>;tag=3af8238437\r\nCall-ID: CXC-408-
> 6bb35b50-c00070a-13c4-521c67f1-3b3bc7c-3c339c13 at 208.94.157.10\r\nCSeq: 1
> INVITE\r\nContact:
> <sip:5282797646 at 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 at 208.94.157.10>;tag=c00070a-13c4-521c67f1-
> 3b3bc7c-3af08849\r\nTo:
> <sip:16504578199 at 55.177.31.199:5060>;tag=3af8238437\r\nCall-ID: CXC-408-
> 6bb35b50-c00070a-13c4-521c67f1-3b3bc7c-3c339c13 at 208.94.157.10\r\nCSeq: 1
> INVITE\r\nContact:
> <sip:5282797646 at 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 at 55.177.31.199:5060>;tag=3af8238437\r\nCall-ID: CXC-408-
> 6bb35b50-c00070a-13c4-521c67f1-3b3bc7c-3c339c13 at 208.94.157.10\r\nCSeq: 1
> INVITE\r\nContact:
> <sip:5282797646 at 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
>
--
Daniel-Constantin Mierla - http://www.asipto.com
http://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 -
More information about the sr-dev
mailing list