[asterisk-dev] Asterisk crash on Park with applicationmap

Alistair Cunningham acunningham at integrics.com
Fri May 5 04:00:05 MST 2006 

Asterisk 1.2.6 and 1.2.7.1 consistently crash if you have the following 
in features.conf:

[general]
parkext => *7
parkpos => 701-799

[applicationmap]
park_caller => **,callee,Park
park_called => **,caller,Park

Then in a Perl FastAGI script do $agi->set_variable( 
'__DYNAMIC_FEATURES', 'park_caller#park_called' ); then have the caller 
press ** during the call. They hear the 701, then hang up, and Asterisk 
crashes within a second of them hanging up. I'm not sure if this is 
relevant or not:

May  5 11:38:50 WARNING[12862]: pbx.c:2354 __ast_pbx_run: Channel 
'SIP/212.248.181.59-0841ae38' sent into invalid extension '701' in 
context 'parkedcalls', but no invalid handler

A "show dialplan" gives, amongst other things:

[ Context 'parkedcalls' created by 'res_features' ]
   '*7' =>           1. Park() 
[res_features]

Is this a known problem? Shall I open a mantis ticket?



Asterisk debug:

     -- Zap/32-1 answered SIP/212.248.181.59-08414df0
May  5 11:38:26 DEBUG[12848]: channel.c:2348 set_format: Set channel 
SIP/212.248.181.59-08414df0 to read format slin
May  5 11:38:26 DEBUG[12848]: channel.c:2348 set_format: Set channel 
Zap/32-1 to write format slin
May  5 11:38:26 DEBUG[12848]: channel.c:2348 set_format: Set channel 
Zap/32-1 to read format slin
May  5 11:38:26 DEBUG[12848]: channel.c:2348 set_format: Set channel 
SIP/212.248.181.59-08414df0 to write format slin
May  5 11:38:26 DEBUG[12848]: chan_sip.c:2527 sip_answer: 
sip_answer(SIP/212.248.181.59-08414df0)
May  5 11:38:26 DEBUG[12772]: devicestate.c:187 do_state_change: 
Changing state for Zap/32 - state 2 (In use)
May  5 11:38:26 DEBUG[12857]: app_queue.c:471 changethread: Device 
'Zap/32' changed to state '2' (In use)
May  5 11:38:26 DEBUG[12772]: chan_sip.c:11502 sip_devicestate: Checking 
device state for peer 212.248.181.59
May  5 11:38:26 DEBUG[12772]: devicestate.c:187 do_state_change: 
Changing state for SIP/212.248.181.59 - state 2 (In use)
May  5 11:38:26 DEBUG[12858]: app_queue.c:471 changethread: Device 
'SIP/212.248.181.59' changed to state '2' (In use)
May  5 11:38:26 DEBUG[12786]: chan_sip.c:3169 find_call: = Found Their 
Call ID: 3c3a0b48d1f6-avmx7p0i1mw3 at 212-248-181-34 Their Tag ulh6ppw5km 
Our tag: as6637b91c
May  5 11:38:26 DEBUG[12786]: chan_sip.c:10980 handle_request: **** 
Received ACK (6) - Command in SIP ACK
May  5 11:38:26 DEBUG[12786]: chan_sip.c:1394 __sip_ack: Stopping 
retransmission on '3c3a0b48d1f6-avmx7p0i1mw3 at 212-248-181-34' of Response 
2: Match Found
May  5 11:38:26 DEBUG[12848]: chan_zap.c:4712 my_zt_write: Write 
returned -1 (Resource temporarily unavailable) on channel 32
May  5 11:38:26 DEBUG[12848]: chan_zap.c:4712 my_zt_write: Write 
returned -1 (Resource temporarily unavailable) on channel 32
May  5 11:38:29 DEBUG[12848]: rtp.c:192 send_dtmf: Sending dtmf: 42 (*), 
at 212.248.181.34
May  5 11:38:29 DEBUG[12848]: channel.c:3293 ast_generic_bridge: Got 
DTMF on channel (SIP/212.248.181.59-08414df0)
May  5 11:38:29 DEBUG[12848]: channel.c:3540 ast_channel_bridge: Bridge 
stops bridging channels SIP/212.248.181.59-08414df0 and Zap/32-1
May  5 11:38:29 DEBUG[12848]: res_features.c:992 ast_feature_interpret: 
Feature interpret: chan=SIP/212.248.181.59-08414df0, peer=Zap/32-1, 
sense=1, features=0
May  5 11:38:29 DEBUG[12848]: res_features.c:1465 ast_bridge_call: Set 
time limit to 500
May  5 11:38:29 DEBUG[12848]: rtp.c:192 send_dtmf: Sending dtmf: 42 (*), 
at 212.248.181.34
May  5 11:38:29 DEBUG[12848]: channel.c:3293 ast_generic_bridge: Got 
DTMF on channel (SIP/212.248.181.59-08414df0)
May  5 11:38:29 DEBUG[12848]: channel.c:3540 ast_channel_bridge: Bridge 
stops bridging channels SIP/212.248.181.59-08414df0 and Zap/32-1
May  5 11:38:29 DEBUG[12848]: res_features.c:992 ast_feature_interpret: 
Feature interpret: chan=SIP/212.248.181.59-08414df0, peer=Zap/32-1, 
sense=1, features=0
     --  Feature Found: park_caller exten: park_caller
   == Parked SIP/212.248.181.59-08414df0 on 701. Will timeout back to 
extension [ipoffice] s, 1 in 45 seconds
May  5 11:38:30 DEBUG[12848]: pbx.c:4872 ast_add_extension2: Added 
extension '701' priority 1 to parkedcalls
May  5 11:38:30 DEBUG[12848]: channel.c:2348 set_format: Set channel 
SIP/212.248.181.59-08414df0 to write format gsm
May  5 11:38:30 DEBUG[12848]: channel.c:1711 ast_settimeout: Scheduling 
timer at 160 sample intervals
     -- Playing 'digits/7' (language 'en')
May  5 11:38:30 DEBUG[12848]: rtp.c:1249 ast_rtp_raw_write: Difference 
is 8208, ms is 1056
May  5 11:38:31 DEBUG[12848]: channel.c:1711 ast_settimeout: Scheduling 
timer at 0 sample intervals
May  5 11:38:31 DEBUG[12848]: channel.c:1711 ast_settimeout: Scheduling 
timer at 0 sample intervals
May  5 11:38:31 DEBUG[12848]: channel.c:2348 set_format: Set channel 
SIP/212.248.181.59-08414df0 to write format slin
May  5 11:38:31 DEBUG[12848]: channel.c:2348 set_format: Set channel 
SIP/212.248.181.59-08414df0 to write format gsm
May  5 11:38:31 DEBUG[12848]: channel.c:1711 ast_settimeout: Scheduling 
timer at 160 sample intervals
     -- Playing 'digits/0' (language 'en')
May  5 11:38:32 DEBUG[12848]: channel.c:1711 ast_settimeout: Scheduling 
timer at 0 sample intervals
May  5 11:38:32 DEBUG[12848]: channel.c:1711 ast_settimeout: Scheduling 
timer at 0 sample intervals
May  5 11:38:32 DEBUG[12848]: channel.c:2348 set_format: Set channel 
SIP/212.248.181.59-08414df0 to write format slin
May  5 11:38:32 DEBUG[12848]: channel.c:2348 set_format: Set channel 
SIP/212.248.181.59-08414df0 to write format gsm
May  5 11:38:32 DEBUG[12848]: channel.c:1711 ast_settimeout: Scheduling 
timer at 160 sample intervals
     -- Playing 'digits/1' (language 'en')
May  5 11:38:32 DEBUG[12848]: channel.c:1711 ast_settimeout: Scheduling 
timer at 0 sample intervals
May  5 11:38:32 DEBUG[12848]: channel.c:1711 ast_settimeout: Scheduling 
timer at 0 sample intervals
May  5 11:38:32 DEBUG[12848]: channel.c:2348 set_format: Set channel 
SIP/212.248.181.59-08414df0 to write format slin
May  5 11:38:32 DEBUG[12848]: channel.c:2348 set_format: Set channel 
SIP/212.248.181.59-08414df0 to write format slin
     -- Started music on hold, class 'default', on channel 
'SIP/212.248.181.59-08414df0'
May  5 11:38:32 DEBUG[12848]: channel.c:1711 ast_settimeout: Scheduling 
timer at 160 sample intervals
May  5 11:38:33 DEBUG[12848]: channel.c:1973 ast_read: Generator got 
voice, switching to phase locked mode
May  5 11:38:33 DEBUG[12848]: channel.c:1711 ast_settimeout: Scheduling 
timer at 0 sample intervals
May  5 11:38:35 WARNING[12777]: channel.c:2219 ast_write: Thread 
-151622736 Blocking 'SIP/212.248.181.59-08414df0', already blocked by 
thread -151622736 in procedure ast_waitfor_nandfds
May  5 11:38:37 DEBUG[12786]: chan_sip.c:3169 find_call: = Found Their 
Call ID: 3c3a0b48d1f6-avmx7p0i1mw3 at 212-248-181-34 Their Tag ulh6ppw5km 
Our tag: as6637b91c
May  5 11:38:37 DEBUG[12786]: chan_sip.c:10980 handle_request: **** 
Received BYE (8) - Command in SIP BYE
May  5 11:38:37 DEBUG[12848]: channel.c:2348 set_format: Set channel 
SIP/212.248.181.59-08414df0 to write format slin
     -- Stopped music on hold on SIP/212.248.181.59-08414df0
May  5 11:38:37 DEBUG[12848]: channel.c:1711 ast_settimeout: Scheduling 
timer at 0 sample intervals
May  5 11:38:37 DEBUG[12848]: channel.c:3265 ast_generic_bridge: Didn't 
get a frame from channel: SIP/212.248.181.59-08414df0
May  5 11:38:37 DEBUG[12848]: channel.c:3540 ast_channel_bridge: Bridge 
stops bridging channels SIP/212.248.181.59-08414df0 and Zap/32-1
May  5 11:38:37 DEBUG[12848]: channel.c:1323 ast_hangup: Hanging up 
channel 'Zap/32-1'
May  5 11:38:37 DEBUG[12848]: chan_zap.c:2312 zt_hangup: zt_hangup(Zap/32-1)
May  5 11:38:37 DEBUG[12848]: chan_zap.c:2864 zt_setoption: Set option 
AUDIO MODE, value: ON(1) on Zap/32-1
May  5 11:38:37 DEBUG[12848]: chan_zap.c:2345 zt_hangup: Hangup: 
channel: 32 index = 0, normal = 44, callwait = -1, thirdcall = -1
May  5 11:38:37 DEBUG[12848]: chan_zap.c:2494 zt_hangup: Not yet 
hungup...  Calling hangup once with icause, and clearing call
May  5 11:38:37 DEBUG[12848]: chan_zap.c:1437 zt_disable_ec: disabled 
echo cancellation on channel 32
May  5 11:38:37 DEBUG[12848]: chan_zap.c:2785 zt_setoption: Set option 
TDD MODE, value: OFF(0) on Zap/32-1
May  5 11:38:37 DEBUG[12848]: chan_zap.c:1374 update_conf: Updated 
conferencing on 32, with 0 conference users
May  5 11:38:37 DEBUG[12848]: chan_zap.c:2860 zt_setoption: Set option 
AUDIO MODE, value: OFF(0) on Zap/32-1
May  5 11:38:37 DEBUG[12848]: chan_zap.c:1437 zt_disable_ec: disabled 
echo cancellation on channel 32
     -- Hungup 'Zap/32-1'
May  5 11:38:37 DEBUG[12848]: app_dial.c:1605 dial_exec_full: Exiting 
with DIALSTATUS=ANSWER.
May  5 11:38:37 DEBUG[12848]: pbx.c:2313 __ast_pbx_run: Spawn extension 
(ipoffice,s,1) exited non-zero on 'SIP/212.248.181.59-08414df0'
May  5 11:38:37 DEBUG[12848]: pbx.c:1674 pbx_extension_helper: Launching 
'DeadAGI'
     -- Executing DeadAGI("SIP/212.248.181.59-08414df0", 
"agi://127.0.0.1/end") in new stack
May  5 11:38:37 DEBUG[12848]: res_agi.c:216 launch_netscript: Wow, 
connected!
   == SIP/212.248.181.59-08414df0 got tired of being parked
May  5 11:38:37 DEBUG[12777]: pbx.c:1519 
pbx_substitute_variables_helper_full: Function result is '"1010" <1010>'
May  5 11:38:37 DEBUG[12777]: pbx.c:1519 
pbx_substitute_variables_helper_full: Function result is '1010'
May  5 11:38:37 DEBUG[12777]: pbx.c:1519 
pbx_substitute_variables_helper_full: Function result is 's'
May  5 11:38:37 DEBUG[12777]: pbx.c:1519 
pbx_substitute_variables_helper_full: Function result is 'ipoffice'
May  5 11:38:37 DEBUG[12777]: pbx.c:1519 
pbx_substitute_variables_helper_full: Function result is 
'SIP/212.248.181.59-08414df0'
May  5 11:38:37 DEBUG[12777]: pbx.c:1519 
pbx_substitute_variables_helper_full: Function result is 'Zap/32-1'
May  5 11:38:37 DEBUG[12777]: pbx.c:1519 
pbx_substitute_variables_helper_full: Function result is 'DeadAGI'
May  5 11:38:37 DEBUG[12777]: pbx.c:1519 
pbx_substitute_variables_helper_full: Function result is 
'agi://127.0.0.1/end'
May  5 11:38:37 DEBUG[12777]: pbx.c:1519 
pbx_substitute_variables_helper_full: Function result is '2006-05-05 
11:38:24'
May  5 11:38:37 DEBUG[12777]: pbx.c:1519 
pbx_substitute_variables_helper_full: Function result is '2006-05-05 
11:38:26'
May  5 11:38:37 DEBUG[12777]: pbx.c:1519 
pbx_substitute_variables_helper_full: Function result is '2006-05-05 
11:38:37'
May  5 11:38:37 DEBUG[12777]: pbx.c:1519 
pbx_substitute_variables_helper_full: Function result is '13'
May  5 11:38:37 DEBUG[12777]: pbx.c:1519 
pbx_substitute_variables_helper_full: Function result is '11'
May  5 11:38:37 DEBUG[12777]: pbx.c:1519 
pbx_substitute_variables_helper_full: Function result is 'ANSWERED'
May  5 11:38:37 DEBUG[12777]: pbx.c:1519 
pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION'
May  5 11:38:37 DEBUG[12777]: pbx.c:1519 
pbx_substitute_variables_helper_full: Function result is '(null)'
May  5 11:38:37 DEBUG[12777]: pbx.c:1519 
pbx_substitute_variables_helper_full: Function result is '1146825504.1'
May  5 11:38:37 DEBUG[12777]: pbx.c:1519 
pbx_substitute_variables_helper_full: Function result is '(null)'
May  5 11:38:37 DEBUG[12777]: channel.c:1323 ast_hangup: Hanging up 
channel 'SIP/212.248.181.59-08414df0'
May  5 11:38:37 DEBUG[12777]: chan_sip.c:2411 sip_hangup: Hangup call 
SIP/212.248.181.59-08414df0, SIP callid 
3c3a0b48d1f6-avmx7p0i1mw3 at 212-248-181-34)
May  5 11:38:37 DEBUG[12777]: chan_sip.c:2419 sip_hangup: 
update_call_counter() - decrement call limit counter
May  5 11:38:37 DEBUG[12777]: chan_sip.c:2202 update_call_counter: 
Updating call counter for incoming call
May  5 11:38:37 WARNING[12777]: channel.c:935 ast_channel_free: PBX may 
not have been terminated properly on 'SIP/212.248.181.59-08414df0'
May  5 11:38:37 DEBUG[12772]: devicestate.c:187 do_state_change: 
Changing state for Zap/32 - state 0 (Unknown)
May  5 11:38:37 DEBUG[12859]: app_queue.c:471 changethread: Device 
'Zap/32' changed to state '0' (Unknown)
May  5 11:38:37 DEBUG[12772]: chan_sip.c:11502 sip_devicestate: Checking 
device state for peer 212.248.181.59
May  5 11:38:37 DEBUG[12772]: devicestate.c:187 do_state_change: 
Changing state for SIP/212.248.181.59 - state 1 (Not in use)
May  5 11:38:37 DEBUG[12860]: app_queue.c:471 changethread: Device 
'SIP/212.248.181.59' changed to state '1' (Not in use)
May  5 11:38:37 DEBUG[12848]: channel.c:1106 ast_softhangup_nolock: 
Soft-Hanging up channel 'XF'
     -- AGI Script agi://127.0.0.1/end completed, returning 0
May  5 11:38:37 DEBUG[12848]: channel.c:1323 ast_hangup: Hanging up 
channel 'XF'
May  5 11:38:37 DEBUG[12848]: chan_sip.c:2407 sip_hangup: Asked to 
hangup channel not connected
May  5 11:38:37 WARNING[12848]: channel.c:903 ast_channel_free: Unable 
to find channel in list
May  5 11:38:37 DEBUG[12772]: devicestate.c:187 do_state_change: 
Changing state for XF - state 4 (Invalid)
May  5 11:38:50 DEBUG[12786]: chan_sip.c:3121 sip_alloc: Allocating new 
SIP dialog for 3c3a0b633d09-k0680n8npfkt at 212-248-181-34 - INVITE (With RTP)
May  5 11:38:50 DEBUG[12786]: chan_sip.c:10980 handle_request: **** 
Received INVITE (5) - Command in SIP INVITE
May  5 11:38:50 DEBUG[12786]: chan_sip.c:1026 parse_sip_options: * SIP 
extension value: 7 for call 3c3a0b633d09-k0680n8npfkt at 212-248-181-34
May  5 11:38:50 DEBUG[12786]: chan_sip.c:7128 check_user_full: Setting 
NAT on RTP to 524288
May  5 11:38:50 DEBUG[12786]: chan_sip.c:10354 handle_request_invite: 
Checking SIP call limits for device
May  5 11:38:50 DEBUG[12786]: chan_sip.c:2202 update_call_counter: 
Updating call counter for incoming call
May  5 11:38:50 DEBUG[12786]: chan_sip.c:6019 build_route: build_route: 
Record-Route hop: <sip:212.248.181.59;ftag=ea8zc4v8e8;lr=on>
May  5 11:38:50 DEBUG[12862]: pbx.c:1674 pbx_extension_helper: Launching 
'Goto'
     -- Executing Goto("SIP/212.248.181.59-0841ae38", 
"parkedcalls|701|1") in new stack
     -- Goto (parkedcalls,701,1)
May  5 11:38:50 WARNING[12862]: pbx.c:2354 __ast_pbx_run: Channel 
'SIP/212.248.181.59-0841ae38' sent into invalid extension '701' in 
context 'parkedcalls', but no invalid handler
May  5 11:38:50 DEBUG[12772]: chan_sip.c:11502 sip_devicestate: Checking 
device state for peer 212.248.181.59
May  5 11:38:50 DEBUG[12772]: devicestate.c:187 do_state_change: 
Changing state for SIP/212.248.181.59 - state 2 (In use)
May  5 11:38:50 DEBUG[12863]: app_queue.c:471 changethread: Device 
'SIP/212.248.181.59' changed to state '2' (In use)
itsp3*CLI>
Disconnected from Asterisk server








     --  Feature Found: park_caller exten: park_caller
   == Parked SIP/212.248.181.59-09525648 on 701. Will timeout back to 
extension [ipoffice] s, 1 in 45 seconds
     -- Added extension '701' priority 1 to parkedcalls
     -- Playing 'digits/7' (language 'en')
     -- Playing 'digits/0' (language 'en')
     -- Playing 'digits/1' (language 'en')
     -- Started music on hold, class 'default', on channel 
'SIP/212.248.181.59-09525648'
May  5 11:30:23 WARNING[12209]: channel.c:2219 ast_write: Thread 
-151954512 Blocking 'SIP/212.248.181.59-09525648', already blocked by 
thread -151954512 in procedure ast_waitfor_nandfds
May  5 11:30:35 WARNING[12209]: channel.c:2219 ast_write: Thread 
-151954512 Blocking 'SIP/212.248.181.59-09525648', already blocked by 
thread -151954512 in procedure ast_waitfor_nandfds
     -- Stopped music on hold on SIP/212.248.181.59-09525648
     -- Hungup 'Zap/32-1'
   == Spawn extension (ipoffice, s, 1) exited non-zero on 
'SIP/212.248.181.59-09525648'
     -- Executing DeadAGI("SIP/212.248.181.59-09525648", 
"agi://127.0.0.1/end") in new stack
   == SIP/212.248.181.59-09525648 got tired of being parked
May  5 11:30:37 WARNING[12209]: channel.c:935 ast_channel_free: PBX may 
not have been terminated properly on 'SIP/212.248.181.59-09525648'
     -- AGI Script agi://127.0.0.1/end completed, returning 0
May  5 11:30:37 WARNING[12348]: channel.c:903 ast_channel_free: Unable 
to find channel in list



-- 
Alistair Cunningham,
Integrics Ltd,
+44 (0)7870 699 479
http://integrics.com/

More information about the asterisk-dev mailing list