[Home]

Summary:ASTERISK-09273: Asterisk crashes with error "Unable to masquerade"
Reporter:Benny Amorsen (amorsen)Labels:
Date Opened:2007-04-17 03:58:58Date Closed:2011-06-07 14:00:44
Priority:CriticalRegression?No
Status:Closed/CompleteComponents:Core/General
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) output.txt
Description:A masquerade which fails with "Unable to answer" results in a second masquerade. The second masquerade fails with "Unable to masquerade". A moment later, channel.c says "Unable to find channel in list" and asterisk crashes.

****** ADDITIONAL INFORMATION ******

Apr 17 10:26:37 DEBUG[6225] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '202554de78bff0495d31a741103620c5@10.0.1.100' Request 102: Found
Apr 17 10:26:37 DEBUG[6225] chan_sip.c: Stopping retransmission on '3c267009c832-6h8cxylylouo@snom320-00041324770B' of Request 108: Match Found
Apr 17 10:26:37 DEBUG[6225] chan_sip.c: Stopping retransmission on '3c267009ecd1-khe83hlwby9t@snom320-00041324421C' of Request 186: Match Found
Apr 17 10:26:37 DEBUG[6225] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '202554de78bff0495d31a741103620c5@10.0.1.100' Request 102: Found
Apr 17 10:26:38 DEBUG[6225] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '202554de78bff0495d31a741103620c5@10.0.1.100' Request 102: Found
Apr 17 10:26:38 DEBUG[6225] chan_sip.c: Auto destroying call 'f0cca65-c881e413@10.0.67.108'
Apr 17 10:26:39 DEBUG[6225] chan_sip.c: Setting NAT on RTP to 0
Apr 17 10:26:40 DEBUG[6225] chan_sip.c: Stopping retransmission on '3c267bb0ea60-jaq7ry6jbapj@snom320-00041324770B' of Response 1: Match Found
Apr 17 10:26:40 DEBUG[6225] res_config_mysql.c: MySQL RealTime: Everything is fine.
Apr 17 10:26:40 DEBUG[6225] res_config_mysql.c: MySQL RealTime: Update SQL: UPDATE bolia_sip SET ipaddr = '10.0.67.140', port = '2051', regseconds = '1176798460', username = '96', fullcontact = 'sip:96@10.0.67.140:2051;line=soouk6vp' WHERE name = '96'
Apr 17 10:26:40 DEBUG[6225] res_config_mysql.c: MySQL RealTime: Updated 1 rows on table: bolia_sip
Apr 17 10:26:40 DEBUG[6225] chan_sip.c: Auto destroying call '33609472-4de758dc@10.0.29.180'
Apr 17 10:26:40 DEBUG[6225] chan_sip.c: Auto destroying call 'b19a1fc6-1cd12625@10.0.67.118'
Apr 17 10:26:40 DEBUG[6225] chan_sip.c: Auto destroying call 'fee39974-218f47c2@10.0.29.180'
Apr 17 10:26:40 DEBUG[6225] chan_sip.c: Auto destroying call 'b76063fc-bc51bedc@10.0.29.109'
Apr 17 10:26:40 DEBUG[6225] chan_sip.c: Auto destroying call 'bc6c496e-2418c874@10.0.37.107'
Apr 17 10:26:40 DEBUG[6225] chan_sip.c: Auto destroying call 'abed994e-bc94ba1a@10.0.29.181'
Apr 17 10:26:40 DEBUG[6225] chan_sip.c: Setting NAT on RTP to 0
Apr 17 10:26:40 DEBUG[6225] chan_sip.c: Checking SIP call limits for device 77
Apr 17 10:26:40 DEBUG[6225] chan_sip.c: build_route: Contact hop: <sip:77@10.0.67.144:2051;line=pwtyhvs5>;flow-id=1
Apr 17 10:26:40 DEBUG[6225] channel.c: Planning to masquerade channel SIP/77-0a2a4e30 into the structure of SIP/78-0a30d198
Apr 17 10:26:40 DEBUG[6225] channel.c: Done planning to masquerade channel SIP/77-0a2a4e30 into the structure of SIP/78-0a30d198
Apr 17 10:26:40 WARNING[6225] res_features.c: Unable to answer 'SIP/77-0a2a4e30'
Apr 17 10:26:40 DEBUG[6225] channel.c: Planning to masquerade channel SIP/77-0a2a4e30 into the structure of SIP/78-0a30d198
Apr 17 10:26:40 WARNING[6225] channel.c: SIP/77-0a2a4e30 is already going to masquerade as SIP/78-0a30d198
Apr 17 10:26:40 WARNING[6225] res_features.c: Unable to masquerade 'SIP/77-0a2a4e30' into 'SIP/78-0a30d198'
Apr 17 10:26:40 NOTICE[6225] chan_sip.c: Nothing to pick up
Apr 17 10:26:40 WARNING[6225] channel.c: Unable to find channel in list
Comments:By: Eduard M. (callmewind) 2007-04-23 11:24:28

I can confirm this bug with asterisk 1.2.17
By: Eduard M. (callmewind) 2007-04-25 05:01:07

More info:
We are using Asterisk Manager API + Asterisk Java in order to control the flow of the calls in the dial plan. Specifically, when we receive some user events, we use SetVar and Redirect actions.
Now we are trying to delay these actions 200ms after whe receive the events and Asterisk *at the moment* is not crashing.
Amorsen, do you use Manager API or AGI scripts?
By: Benny Amorsen (amorsen) 2007-04-25 08:25:32

We only use the manager interface to check how many channels are open (nagios with check_asterisk.pl). I don't think the issue I reported is related to the manager interface.
By: Joshua C. Colp (jcolp) 2007-06-06 19:45:51

If this is still an issue can you please attach a backtrace of where it is crashing?
By: Eduard M. (callmewind) 2007-06-18 06:00:48

There is the backtrace generated.
Relevant messages in /var/log/asterisk/messages:
Jun 18 12:37:35 WARNING[29703] chan_sip.c: Unknown SDP media type in offer: video 10702 RTP/AVP 34 31
Jun 18 12:37:38 WARNING[29744] channel.c: SIP/1002-081ce030 is already going to masquerade as Local/s@originate-b079,1

In my case, I have a program connected to manager and waiting UserEvents. The relevant part of extensions.conf is:
[message]
exten => s,1,UserEvent(PlayMessageStart| message: ${MESSAGE})
exten => s,n,Playback(${MESSAGE})
exten => s,n,UserEvent(PlayMessageEnd| message: ${MESSAGE})
exten => s,n,Goto(wait|s|1)

When I want to play some message, I use redirect action to this extension. In the test program, I'm redirecting to message|s|1 every time I get the PlayMessageEnd event, and  ${MESSAGE} is tt-monkeys, so the monkeys are always in a loop :). Then asterisk crashed with 3 sip phones doing this loop.
By: Joshua C. Colp (jcolp) 2007-06-18 08:32:05

Callmewind: I suspect your issue is that you are using chan_local and at the exact time you are trying to redirect a channel away chan_local is optimizing itself out of the path, which is done using masquerades. If you add /n to the end of your Local/ usage does it perform better?
By: Russell Bryant (russell) 2007-06-18 18:23:19

Also, please update to Asterisk 1.2.19 and try again.  I made a change in this release which should prevent this type of crash from happening.
By: Eduard M. (callmewind) 2007-06-19 10:12:19

Ok, now I'm trying to use the local channel with /n. Now I can't remember, but I chose to use without it for some reason..
At the moment asterisk seems stable, but I want to test it a bit more before totally confirming. If there is some problem, I will try first with 1.2.19.
By: Russell Bryant (russell) 2007-06-19 11:35:25

Perfect.  Thank you for the update!
By: Joshua C. Colp (jcolp) 2007-07-02 09:33:17

It has been over a week now and no negative replies. If this is still an issue after trying our suggestions please feel free to reopen.
By: Benny Amorsen (amorsen) 2007-07-04 05:54:55

I'm sorry to report this, but the issue reoccurred in asterisk 1.2.19. Notice that the problem I reported most likely differs from what Callmewind reported. We do not use the Local channel, all calls involved were using plain SIP.

Messages in the log:

Jul  4 12:20:26 DEBUG[492] res_config_mysql.c: MySQL RealTime: Everything is fine.
Jul  4 12:20:26 DEBUG[492] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM skanlog_sip WHERE name = '172.31.0.8'
Jul  4 12:20:26 DEBUG[579] chan_sip.c: Stopping retransmission on '593272e77deb85d86667be2b6b9dcdd0@10.10.9.164' of Request 102: Match Found
Jul  4 12:20:27 DEBUG[579] chan_sip.c: Setting NAT on RTP to 0
Jul  4 12:20:27 DEBUG[579] chan_sip.c: Auto destroying call '3c2671603345-idm41mcl1mk4@snom320-00041327139E'
Jul  4 12:20:27 DEBUG[579] chan_sip.c: Stopping retransmission on '3c44bc90ea60-s1j7qpc07r80@snom320-0004132713A4' of Response 1: Match Found
Jul  4 12:20:28 DEBUG[579] chan_sip.c: Auto destroying call '3c26700cecd1-zi9arbj9x7b8@snom320-00041327139F'
Jul  4 12:20:28 DEBUG[579] chan_sip.c: Auto destroying call '3c26700c35b6-nyxxjoaax0ht@snom320-0004132713A2'
Jul  4 12:20:28 DEBUG[579] chan_sip.c: Setting NAT on RTP to 0
Jul  4 12:20:28 DEBUG[579] chan_sip.c: Checking SIP call limits for device 300
Jul  4 12:20:28 DEBUG[579] chan_sip.c: build_route: Contact hop: <sip:300@10.0.136.185:2051;line=dovd7jxk>;flow-id=1
Jul  4 12:20:28 DEBUG[492] channel.c: Avoiding initial deadlock for 'SIP/300-083ff5d0'
Jul  4 12:20:28 DEBUG[579] channel.c: Planning to masquerade channel SIP/300-083ff5d0 into the structure of SIP/303-084ac760
Jul  4 12:20:28 DEBUG[579] channel.c: Done planning to masquerade channel SIP/300-083ff5d0 into the structure of SIP/303-084ac760
Jul  4 12:20:28 WARNING[579] res_features.c: Unable to answer 'SIP/300-083ff5d0'
Jul  4 12:20:28 DEBUG[579] channel.c: Planning to masquerade channel SIP/300-083ff5d0 into the structure of SIP/303-084ac760
Jul  4 12:20:28 WARNING[579] channel.c: SIP/300-083ff5d0 is already going to masquerade as SIP/303-084ac760
Jul  4 12:20:28 WARNING[579] res_features.c: Unable to masquerade 'SIP/300-083ff5d0' into 'SIP/303-084ac760'
Jul  4 12:20:28 NOTICE[579] chan_sip.c: Nothing to pick up
Jul  4 12:20:28 DEBUG[21137] channel.c: Got clone lock for masquerade on 'SIP/300-083ff5d0' at 0x842d114
Jul  4 12:20:28 DEBUG[21137] chan_sip.c: update_call_counter(303) - decrement call limit counter
Jul  4 12:20:28 DEBUG[21137] chan_sip.c: Acked pending invite 102
Jul  4 12:20:28 DEBUG[21137] chan_sip.c: Stopping retransmission on '0a7506076ae30e0a506555151574f0a6@10.10.9.164' of Request 102: Match Found
Jul  4 12:20:28 DEBUG[21137] channel.c: Putting channel SIP/300-083ff5d0 in 4/4 formats
Jul  4 12:20:28 DEBUG[21137] channel.c: Destroying channel clone 'SIP/303-084ac760<ZOMBIE>'
Jul  4 12:20:28 DEBUG[21137] channel.c: Done Masquerading SIP/300-083ff5d0 (4)
Jul  4 12:20:28 DEBUG[22283] sched.c: Request to schedule in the past?!?!

After that, no more messages until asterisk was restarted.
By: Joshua C. Colp (jcolp) 2007-07-05 08:17:23

Something was happening though to cause the masquerade to happen, like an attended call transfer. What exactly was going on, right down to the order of things...
By: Benny Amorsen (amorsen) 2007-07-05 09:34:27

It's true that something caused the masquerade. The failure occurred on a customer's PBX, so all I have to go by is the log files. From the log, I would imagine that it was a transfer from one SIP phone to another. It is a bit inconvenient that such events are not logged, even at DEBUG.
By: Joshua C. Colp (jcolp) 2007-09-11 08:58:51

This issue is being suspended because 1.2 is no longer receiving bug fixes. If the issue still exists under 1.4 please reopen with all the latest info.