[Asterisk-Users] "Got clone lock for masquerade" crash

[Benny Amorsen]

Several times asterisk has crashed with this message:

Dec 12 09:17:09 DEBUG[6792] chan_sip.c: Setting NAT on RTP to 0
Dec 12 09:17:09 DEBUG[6792] chan_sip.c: Checking SIP call limits for device
Dec 12 09:17:09 DEBUG[6792] chan_sip.c: build_route: Contact hop: <sip:56635399 at 172.31.0.8>
Dec 12 09:17:09 DEBUG[6781] channel.c: Avoiding initial deadlock for 'SIP/172.31.0.8-b7402a60'
Dec 12 09:17:09 VERBOSE[12050] logger.c:     -- Executing Set("SIP/172.31.0.8-b7402a60", "GROUP()=active_calls") in new stack
Dec 12 09:17:09 DEBUG[12050] pbx.c: Function result is '1'
Dec 12 09:17:09 DEBUG[12050] pbx.c: Expression result is '0'
Dec 12 09:17:09 VERBOSE[12050] logger.c:     -- Executing GotoIf("SIP/172.31.0.8-b7402a60", "0?106") in new stack
Dec 12 09:17:09 DEBUG[12050] pbx.c: Not taking any branch
Dec 12 09:17:09 VERBOSE[12050] logger.c:     -- Executing Dial("SIP/172.31.0.8-b7402a60", "SIP/703|30|t") in new stack
Dec 12 09:17:09 DEBUG[12050] chan_sip.c: Setting NAT on RTP to 0
Dec 12 09:17:09 DEBUG[12050] chan_sip.c: Outgoing Call for 703
Dec 12 09:17:09 VERBOSE[12050] logger.c:     -- Called 703
Dec 12 09:17:09 DEBUG[6792] chan_sip.c: Acked pending invite 102
Dec 12 09:17:09 DEBUG[6792] chan_sip.c: Stopping retransmission on '2e70354975d986574403e4340769c4a5 at 10.0.1.37' of Request 102: Match Found
Dec 12 09:17:09 VERBOSE[6792] logger.c:     -- Got SIP response 302 "Moved Temporarily" back from 10.0.13.73
Dec 12 09:17:09 DEBUG[6792] chan_sip.c: Found 302 Redirect to extension '6011111'
Dec 12 09:17:09 VERBOSE[12050] logger.c:     -- Now forwarding SIP/172.31.0.8-b7402a60 to 'Local/6011111 at do_dial' (thanks to SIP/703-7e11)
Dec 12 09:17:09 DEBUG[12050] chan_sip.c: update_call_counter(703) - decrement call limit counter
Dec 12 09:17:09 VERBOSE[12052] logger.c:     -- Executing Set("Local/6011111 at do_dial-9b9f,2", "GROUP()=active_calls") in new stack
Dec 12 09:17:09 DEBUG[12052] pbx.c: Function result is '2'
Dec 12 09:17:09 DEBUG[12052] pbx.c: Expression result is '0'
Dec 12 09:17:09 VERBOSE[12052] logger.c:     -- Executing GotoIf("Local/6011111 at do_dial-9b9f,2", "0?106") in new stack
Dec 12 09:17:09 DEBUG[12052] pbx.c: Not taking any branch
Dec 12 09:17:09 VERBOSE[12052] logger.c:     -- Executing Set("Local/6011111 at do_dial-9b9f,2", "CALLERID(all)=Foo <12345678>") in new stack
Dec 12 09:17:09 VERBOSE[12052] logger.c:     -- Executing Dial("Local/6011111 at do_dial-9b9f,2", "SIP/6011111 at lpbx01") in new stack
Dec 12 09:17:09 DEBUG[12052] chan_sip.c: Setting NAT on RTP to 0
Dec 12 09:17:09 DEBUG[12052] chan_sip.c: Outgoing Call for 6011111
Dec 12 09:17:09 VERBOSE[12052] logger.c:     -- Called 6011111 at lpbx01
Dec 12 09:17:09 DEBUG[6792] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '3be553f97980682632d627901f126462 at 10.0.1.37' Request 102: Found
Dec 12 09:17:09 DEBUG[6792] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '3be553f97980682632d627901f126462 at 10.0.1.37' Request 102: Found
Dec 12 09:17:09 VERBOSE[12052] logger.c:     -- SIP/lpbx01-3fa5 is making progress passing it to Local/6011111 at do_dial-9b9f,2
Dec 12 09:17:09 VERBOSE[12050] logger.c:     -- Local/6011111 at do_dial-9b9f,1 is making progress passing it to SIP/172.31.0.8-b7402a60
Dec 12 09:17:13 DEBUG[6792] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '3be553f97980682632d627901f126462 at 10.0.1.37' Request 102: Found
Dec 12 09:17:13 VERBOSE[12052] logger.c:     -- SIP/lpbx01-3fa5 is ringing
Dec 12 09:17:13 VERBOSE[12050] logger.c:     -- Local/6011111 at do_dial-9b9f,1 is ringing
Dec 12 09:17:17 DEBUG[6792] chan_sip.c: Acked pending invite 102
Dec 12 09:17:17 DEBUG[6792] chan_sip.c: Stopping retransmission on '3be553f97980682632d627901f126462 at 10.0.1.37' of Request 102: Match Found
Dec 12 09:17:17 DEBUG[6792] chan_sip.c: build_route: Contact hop: <sip:6011111 at 172.31.0.8>
Dec 12 09:17:17 VERBOSE[12052] logger.c:     -- SIP/lpbx01-3fa5 answered Local/6011111 at do_dial-9b9f,2
Dec 12 09:17:17 VERBOSE[12050] logger.c:     -- Local/6011111 at do_dial-9b9f,1 stopped sounds
Dec 12 09:17:17 VERBOSE[12050] logger.c:     -- Local/6011111 at do_dial-9b9f,1 answered SIP/172.31.0.8-b7402a60
Dec 12 09:17:17 DEBUG[6781] channel.c: Avoiding initial deadlock for 'SIP/172.31.0.8-b7402a60'
Dec 12 09:17:17 DEBUG[6792] chan_sip.c: Stopping retransmission on '431e26547924cdae252f47024fba9bb3 at 172.31.0.8' of Response 102: Match Found
Dec 12 09:17:17 DEBUG[12050] channel.c: Planning to masquerade channel SIP/172.31.0.8-b7402a60 into the structure of Local/6011111 at do_dial-9b9f,2
Dec 12 09:17:17 DEBUG[12050] channel.c: Done planning to masquerade channel SIP/172.31.0.8-b7402a60 into the structure of Local/6011111 at do_dial-9b9f,2
Dec 12 09:17:17 DEBUG[12050] chan_local.c: Not posting to queue since already masked on 'Local/6011111 at do_dial-9b9f,1'
Dec 12 09:17:17 DEBUG[12052] channel.c: Got clone lock for masquerade on 'SIP/172.31.0.8-b7402a60' at 0xb7401dc4


The 60111111 and the 12345678 numbers are fake, the rest of the log is
genuine. After this the log ends because asterisk is dead. Each time
asterisk crashed, the "Got clone lock for masquerade" appeared as the
last log entry -- and the log entry never appeared without a crash.

The crash originally happened with 1.2.0 but has recurred several
times after upgrading to 1.2.1.


/Benny