#### 1. Dial to mISDN group. It fails because all the ports have L2Link DOWN: ############################################################################# [Apr 3 13:30:25] WARNING[24744]: chan_oss.c:682 setformat: Unable to re-open DSP device /dev/dsp: No such file or directory [Apr 3 13:30:25] DEBUG[24800]: pbx.c:1795 pbx_extension_helper: Launching 'Dial' [Apr 3 13:30:25] -- Executing [940@pruebas:1] Dial("OSS/dsp", "mISDN/g:te/675511308") in new stack P[ 0] --> Group Call group: te P[ 1] Group [te] Port [1] P[ 1] Port Down L2:0 L1:1 P[ 1] portup:0 P[ 2] Group [te] Port [2] P[ 2] Port Down L2:0 L1:1 P[ 2] portup:0 P[ 3] Group [te] Port [3] P[ 3] Port Down L2:0 L1:1 P[ 3] portup:0 [Apr 3 13:30:25] WARNING[24800]: chan_misdn.c:5256 chan_misdn_log: Could not create channel on port:-1 with extensions:675511308 [Apr 3 13:30:25] WARNING[24800]: app_dial.c:1090 dial_exec_full: Unable to create channel of type 'mISDN' (cause 0 - Unknown) [Apr 3 13:30:25] == Everyone is busy/congested at this time (1:0/0/1) [Apr 3 13:30:25] DEBUG[24800]: rtp.c:1468 ast_rtp_early_bridge: Channel 'OSS/dsp' has no RTP, not doing anything [Apr 3 13:30:25] DEBUG[24800]: app_dial.c:1670 dial_exec_full: Exiting with DIALSTATUS=CHANUNAVAIL. [Apr 3 13:30:25] == Auto fallthrough, channel 'OSS/dsp' status is 'CHANUNAVAIL' [Apr 3 13:30:25] DEBUG[24800]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel OSS/dsp [Apr 3 13:30:25] DEBUG[24693]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for OSS - dsp [Apr 3 13:30:25] DEBUG[24693]: devicestate.c:287 do_state_change: Changing state for OSS/dsp - state 4 (Invalid) [Apr 3 13:30:25] DEBUG[24801]: app_queue.c:546 changethread: Device 'OSS/dsp' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Apr 3 13:30:35] DEBUG[24800]: cdr_addon_mysql.c:213 mysql_log: cdr_mysql: inserting a CDR record. [Apr 3 13:30:35] DEBUG[24800]: cdr_addon_mysql.c:229 mysql_log: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield) VALUES ('2007-04-03 13:30:25','','','940','pruebas', 'OSS/dsp','','Dial','mISDN/g:te/675511308',10,0,'NO ANSWER',3,'','1175599825.11','') [Apr 3 13:30:35] DEBUG[24800]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 3 13:30:35] DEBUG[24800]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 3 13:30:35] DEBUG[24800]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '940' [Apr 3 13:30:35] DEBUG[24800]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'pruebas' [Apr 3 13:30:35] DEBUG[24800]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'OSS/dsp' [Apr 3 13:30:35] DEBUG[24800]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 3 13:30:35] DEBUG[24800]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'Dial' [Apr 3 13:30:35] DEBUG[24800]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'mISDN/g:te/675511308' [Apr 3 13:30:35] DEBUG[24800]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '2007-04-03 13:30:25' [Apr 3 13:30:35] DEBUG[24800]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 3 13:30:35] DEBUG[24800]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '2007-04-03 13:30:35' [Apr 3 13:30:35] DEBUG[24800]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '10' [Apr 3 13:30:35] DEBUG[24800]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '0' [Apr 3 13:30:35] DEBUG[24800]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'NO ANSWER' [Apr 3 13:30:35] DEBUG[24800]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Apr 3 13:30:35] DEBUG[24800]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 3 13:30:35] DEBUG[24800]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '1175599825.11' [Apr 3 13:30:35] DEBUG[24800]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 3 13:30:35] DEBUG[24800]: channel.c:1693 ast_hangup: Hanging up channel 'OSS/dsp' [Apr 3 13:30:35] << Hangup on console >> [Apr 3 13:30:35] DEBUG[24800]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel OSS/dsp [Apr 3 13:30:35] DEBUG[24693]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for OSS - dsp [Apr 3 13:30:35] DEBUG[24693]: devicestate.c:287 do_state_change: Changing state for OSS/dsp - state 4 (Invalid) [Apr 3 13:30:35] DEBUG[24802]: app_queue.c:546 changethread: Device 'OSS/dsp' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. #### 2. Dial to mISDN port. It works: ############################################################################# [Apr 3 13:30:46] WARNING[24744]: chan_oss.c:682 setformat: Unable to re-open DSP device /dev/dsp: No such file or directory [Apr 3 13:30:46] DEBUG[24803]: pbx.c:1795 pbx_extension_helper: Launching 'Dial' [Apr 3 13:30:46] -- Executing [941@pruebas:1] Dial("OSS/dsp", "mISDN/1/675511308") in new stack P[ 0] maxnum:2P[ 0] --> * NEW CHANNEL dad:675511308 oad:(null) P[ 1] * Queuing chan 0x81fc6a0 P[ 1] read_config: Getting Config P[ 1] --> TON: Unknown P[ 1] --> LTON: Unknown P[ 1] --> CTON: Unknown [Apr 3 13:30:46] DEBUG[24803]: rtp.c:1551 ast_rtp_make_compatible: Channel 'mISDN/0-u12' has no RTP, not doing anything [Apr 3 13:30:46] DEBUG[24803]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-pruebas-941-1. P[ 1] * CALL: 1/675511308 P[ 1] --> * dad:675511308 tech:mISDN/0-u12 ctx:entrantes-analogicas P[ 1] --> * adding2newbc ext 675511308 P[ 1] --> * adding2newbc callerid P[ 1] --> pres: -1 screen: -1 P[ 1] --> pres: 0 P[ 1] --> PRES: Allowed (0x0) P[ 1] --> SCREEN: Unscreened (0x0) P[ 1] NO OPTS GIVEN P[ 1] I SEND:SETUP oad: dad:675511308 pid:5 P[ 1] --> bc_state:BCHAN_CLEANED P[ 1] --> channel:0 mode:TE cause:16 ocause:16 rad: cad: P[ 1] --> info_dad: onumplan:0 dnumplan:0 rnumplan:0 cpnnumplan:0 P[ 1] --> caps:Speech pi:0 keypad: sending_complete:0 P[ 1] --> screen:0 --> pres:0 P[ 1] --> addr:0 l3id:90001 b_stid:0 layer_id:50010180 P[ 1] --> facility:Fac_None out_facility:Fac_None P[ 1] --> found chan: 1 P[ 1] I IND :NEW_CHANNEL oad: dad:675511308 pid:5 state:NOTHING P[ 1] --> channel:1 mode:TE cause:16 ocause:16 rad: cad: P[ 1] --> info_dad: onumplan:0 dnumplan:0 rnumplan:0 cpnnumplan:0 P[ 1] --> caps:Speech pi:0 keypad: sending_complete:0 P[ 1] --> screen:0 --> pres:0 P[ 1] --> addr:0 l3id:90001 b_stid:0 layer_id:50010180 P[ 1] --> facility:Fac_None out_facility:Fac_None P[ 1] --> bc_state:BCHAN_CLEANED P[ 1] --> updating channel name to [mISDN/1-u13] P[ 1] --> found channel: 1 P[ 1] set_chan_in_stack: 1 P[ 1] --> new_l3id 90004 P[ 1] NO USERUESRINFO ENCODED P[ 1] --> * SEND: State Dialing pid:5 [Apr 3 13:30:46] DEBUG[24803]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel mISDN/1-u13 [Apr 3 13:30:46] -- Called 1/675511308 [Apr 3 13:30:46] DEBUG[24803]: channel.c:2845 set_format: Set channel mISDN/1-u13 to read format slin [Apr 3 13:30:46] DEBUG[24803]: channel.c:2845 set_format: Set channel OSS/dsp to write format slin [Apr 3 13:30:46] DEBUG[24803]: channel.c:2845 set_format: Set channel OSS/dsp to read format alaw P[ 1] Sending msg, prim:30580 addr:41000104 dinfo:90004 [Apr 3 13:30:46] DEBUG[24693]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for mISDN - 1 [Apr 3 13:30:46] DEBUG[24693]: devicestate.c:287 do_state_change: Changing state for mISDN/1 - state 2 (In use) [Apr 3 13:30:46] DEBUG[24804]: app_queue.c:546 changethread: Device 'mISDN/1' changed to state '2' (In use) but we don't care because they're not a member of any queue. P[ 1] MGMT: SSTATUS: L2_ESTABLISH P[ 1] handle_frm: frm->addr:42000103 frm->prim:30282 P[ 1] set_channel: bc->channel:1 channel:1 P[ 1] I IND :NEW_CHANNEL oad: dad:675511308 pid:5 state:CALLING P[ 1] --> channel:1 mode:TE cause:16 ocause:16 rad: cad: P[ 1] --> info_dad: onumplan:0 dnumplan:0 rnumplan:0 cpnnumplan:0 P[ 1] --> caps:Speech pi:0 keypad: sending_complete:0 P[ 1] --> screen:0 --> pres:0 P[ 1] --> addr:0 l3id:90004 b_stid:0 layer_id:50010180 P[ 1] --> facility:Fac_None out_facility:Fac_None P[ 1] --> bc_state:BCHAN_CLEANED P[ 1] --> updating channel name to [mISDN/1-u14] P[ 1] setup_bc: with dsp P[ 1] --> Channel is 1 P[ 1] --> TRANSPARENT Mode P[ 1] set_chan_in_stack: 1 P[ 1] channel already in use:1 P[ 1] I IND :PROCEEDING oad: dad:675511308 pid:5 state:CALLING P[ 1] --> channel:1 mode:TE cause:16 ocause:16 rad: cad: P[ 1] --> info_dad: onumplan:0 dnumplan:0 rnumplan:0 cpnnumplan:0 P[ 1] --> caps:Speech pi:0 keypad: sending_complete:0 P[ 1] --> screen:0 --> pres:0 P[ 1] --> addr:50010102 l3id:90004 b_stid:10010100 layer_id:50010180 P[ 1] --> facility:Fac_None out_facility:Fac_None P[ 1] --> bc_state:BCHAN_ACTIVATED P[ 1] --> updating channel name to [mISDN/1-u15] [Apr 3 13:30:46] -- mISDN/1-u15 is proceeding passing it to OSS/dsp [Apr 3 13:30:46] DEBUG[24803]: rtp.c:1468 ast_rtp_early_bridge: Channel 'OSS/dsp' has no RTP, not doing anything [Apr 3 13:30:46] WARNING[24803]: chan_oss.c:978 oss_indicate: Don't know how to display condition 15 on OSS/dsp P[ 1] BCHAN: bchan ACT Confirm pid:5 [Apr 3 13:30:47] WARNING[24803]: chan_oss.c:682 setformat: Unable to re-open DSP device /dev/dsp: No such file or directory [Apr 3 13:30:48] WARNING[24803]: chan_oss.c:682 setformat: Unable to re-open DSP device /dev/dsp: No such file or directory [Apr 3 13:30:49] WARNING[24803]: chan_oss.c:682 setformat: Unable to re-open DSP device /dev/dsp: No such file or directory [Apr 3 13:30:50] WARNING[24803]: chan_oss.c:682 setformat: Unable to re-open DSP device /dev/dsp: No such file or directory P[ 1] handle_frm: frm->addr:42000103 frm->prim:30182 P[ 1] $$$ bc already upsetted stid :10010100 (state:BCHAN_ACTIVATED) P[ 1] set_chan_in_stack: 1 P[ 1] channel already in use:1 P[ 1] I IND :ALERTING oad: dad:675511308 pid:5 state:PROCEEDING P[ 1] --> channel:1 mode:TE cause:16 ocause:16 rad: cad: P[ 1] --> info_dad: onumplan:0 dnumplan:0 rnumplan:0 cpnnumplan:0 P[ 1] --> caps:Speech pi:8 keypad: sending_complete:0 P[ 1] --> screen:0 --> pres:0 P[ 1] --> addr:50010102 l3id:90004 b_stid:10010100 layer_id:50010180 P[ 1] --> facility:Fac_None out_facility:Fac_None P[ 1] --> bc_state:BCHAN_ACTIVATED P[ 1] --> updating channel name to [mISDN/1-u16] [Apr 3 13:30:51] -- mISDN/1-u16 is ringing [Apr 3 13:30:51] DEBUG[24803]: rtp.c:1468 ast_rtp_early_bridge: Channel 'OSS/dsp' has no RTP, not doing anything [Apr 3 13:30:51] DEBUG[24705]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel mISDN/1-u16 [Apr 3 13:30:51] DEBUG[24693]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for mISDN - 1 [Apr 3 13:30:51] DEBUG[24693]: devicestate.c:287 do_state_change: Changing state for mISDN/1 - state 6 (Ringing) P[ 1] Starting Tones, we have inband Data [Apr 3 13:30:51] DEBUG[24808]: app_queue.c:546 changethread: Device 'mISDN/1' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Apr 3 13:30:52] DEBUG[24803]: rtp.c:1468 ast_rtp_early_bridge: Channel 'OSS/dsp' has no RTP, not doing anything [Apr 3 13:30:52] DEBUG[24803]: channel.c:1693 ast_hangup: Hanging up channel 'mISDN/1-u16' [Apr 3 13:30:52] DEBUG[24803]: chan_misdn.c:2301 misdn_hangup: misdn_hangup(mISDN/1-u16) P[ 1] * IND : HANGUP pid:5 ctx:entrantes-analogicas dad:675511308 oad:941 State:ALERTING P[ 1] --> l3id:90004 P[ 1] --> cause:16 P[ 1] --> out_cause:16 P[ 1] --> state:ALERTING P[ 1] I SEND:DISCONNECT oad: dad:675511308 pid:5 P[ 1] --> bc_state:BCHAN_ACTIVATED P[ 1] --> channel:1 mode:TE cause:16 ocause:16 rad: cad: P[ 1] --> info_dad: onumplan:0 dnumplan:0 rnumplan:0 cpnnumplan:0 P[ 1] --> caps:Speech pi:8 keypad: sending_complete:0 P[ 1] --> screen:0 --> pres:0 P[ 1] --> addr:50010102 l3id:90004 b_stid:10010100 layer_id:50010180 P[ 1] --> facility:Fac_None out_facility:Fac_None P[ 1] --> Channel: mISDN/1-u16 hanguped new state:CLEANING P[ 1] Sending msg, prim:34580 addr:41000104 dinfo:90004 [Apr 3 13:30:52] DEBUG[24803]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel mISDN/1-u16 [Apr 3 13:30:52] DEBUG[24803]: app_dial.c:1670 dial_exec_full: Exiting with DIALSTATUS=CANCEL. [Apr 3 13:30:52] DEBUG[24693]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for mISDN - 1 [Apr 3 13:30:52] DEBUG[24693]: devicestate.c:287 do_state_change: Changing state for mISDN/1 - state 0 (Unknown) [Apr 3 13:30:52] DEBUG[24809]: app_queue.c:546 changethread: Device 'mISDN/1' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Apr 3 13:30:52] DEBUG[24803]: pbx.c:2393 __ast_pbx_run: Spawn extension (pruebas,941,1) exited non-zero on 'OSS/dsp' [Apr 3 13:30:52] == Spawn extension (pruebas, 941, 1) exited non-zero on 'OSS/dsp' [Apr 3 13:30:52] DEBUG[24803]: cdr_addon_mysql.c:213 mysql_log: cdr_mysql: inserting a CDR record. [Apr 3 13:30:52] DEBUG[24803]: cdr_addon_mysql.c:229 mysql_log: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield) VALUES ('2007-04-03 13:30:46','','','941','pruebas', 'OSS/dsp','mISDN/1-u13','Dial','mISDN/1/675511308',6,0,'NO ANSWER',3,'','1175599846.12','') [Apr 3 13:30:52] DEBUG[24803]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 3 13:30:52] DEBUG[24803]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 3 13:30:52] DEBUG[24803]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '941' [Apr 3 13:30:52] DEBUG[24803]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'pruebas' [Apr 3 13:30:52] DEBUG[24803]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'OSS/dsp' [Apr 3 13:30:52] DEBUG[24803]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'mISDN/1-u13' [Apr 3 13:30:52] DEBUG[24803]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'Dial' [Apr 3 13:30:52] DEBUG[24803]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'mISDN/1/675511308' [Apr 3 13:30:52] DEBUG[24803]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '2007-04-03 13:30:46' [Apr 3 13:30:52] DEBUG[24803]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 3 13:30:52] DEBUG[24803]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '2007-04-03 13:30:52' [Apr 3 13:30:52] DEBUG[24803]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '6' [Apr 3 13:30:52] DEBUG[24803]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '0' [Apr 3 13:30:52] DEBUG[24803]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'NO ANSWER' [Apr 3 13:30:52] DEBUG[24803]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Apr 3 13:30:52] DEBUG[24803]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 3 13:30:52] DEBUG[24803]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '1175599846.12' [Apr 3 13:30:52] DEBUG[24803]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 3 13:30:52] DEBUG[24803]: channel.c:1693 ast_hangup: Hanging up channel 'OSS/dsp' [Apr 3 13:30:52] << Hangup on console >> [Apr 3 13:30:52] DEBUG[24803]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel OSS/dsp [Apr 3 13:30:52] DEBUG[24693]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for OSS - dsp [Apr 3 13:30:52] DEBUG[24693]: devicestate.c:287 do_state_change: Changing state for OSS/dsp - state 4 (Invalid) [Apr 3 13:30:52] DEBUG[24810]: app_queue.c:546 changethread: Device 'OSS/dsp' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. P[ 1] handle_frm: frm->addr:42000103 frm->prim:34d82 P[ 1] empty_chan_in_stack: 1 P[ 1] $$$ CLEANUP CALLED pid:5 P[ 1] $$$ Cleaning up bc with stid :10010100 pid:5 P[ 1] --> ec_disable P[ 1] Sending Control ECHOCAN_OFF P[ 1] ph_control: c1:2319 c2:0 P[ 1] I IND :RELEASE oad: dad: pid:5 state:CLEANING P[ 1] --> channel:0 mode:TE cause:16 ocause:16 rad: cad: P[ 1] --> info_dad: onumplan:0 dnumplan:0 rnumplan:0 cpnnumplan:0 P[ 1] --> caps:Speech pi:0 keypad: sending_complete:0 P[ 1] --> screen:0 --> pres:0 P[ 1] --> addr:50010102 l3id:90004 b_stid:0 layer_id:50010180 P[ 1] --> facility:Fac_None out_facility:Fac_None P[ 1] --> bc_state:BCHAN_CLEANED P[ 1] ast_hangup already called, so we have no ast ptr anymore in event(RELEASE) P[ 1] --> No need to queue hangup P[ 1] Cannot hangup chan, no ast P[ 1] I SEND:RELEASE_COMPLETE oad: dad: pid:5 P[ 1] --> bc_state:BCHAN_CLEANED P[ 1] --> channel:0 mode:TE cause:16 ocause:16 rad: cad: P[ 1] --> info_dad: onumplan:0 dnumplan:0 rnumplan:0 cpnnumplan:0 P[ 1] --> caps:Speech pi:0 keypad: sending_complete:0 P[ 1] --> screen:0 --> pres:0 P[ 1] --> addr:50010102 l3id:90004 b_stid:0 layer_id:50010180 P[ 1] --> facility:Fac_None out_facility:Fac_None P[ 1] $$$ CLEANUP CALLED pid:5 P[ 1] handle_frm: frm->addr:42000103 frm->prim:3f182 P[ 1] --> lib: RELEASE_CR Ind with l3id:90004 P[ 1] --> lib: CLEANING UP l3id: 90004 P[ 1] $$$ CLEANUP CALLED pid:5 P[ 1] BCHAN: MGR_DELLAYER|CNF pid:5 P[ 1] Sending msg, prim:35a80 addr:41000104 dinfo:90004 #### 3. Dial again to mISDN group. It works now because port 1 L2Link is still UP: ############################################################################# [Apr 3 13:31:01] WARNING[24744]: chan_oss.c:682 setformat: Unable to re-open DSP device /dev/dsp: No such file or directory [Apr 3 13:31:01] DEBUG[24814]: pbx.c:1795 pbx_extension_helper: Launching 'Dial' [Apr 3 13:31:01] -- Executing [940@pruebas:1] Dial("OSS/dsp", "mISDN/g:te/675511308") in new stack P[ 0] --> Group Call group: te P[ 1] Group [te] Port [1] P[ 1] portup:1 P[ 0] maxnum:2P[ 0] --> * NEW CHANNEL dad:675511308 oad:(null) P[ 1] * Queuing chan 0x81fc6a0 P[ 1] read_config: Getting Config P[ 1] --> TON: Unknown P[ 1] --> LTON: Unknown P[ 1] --> CTON: Unknown [Apr 3 13:31:01] DEBUG[24814]: rtp.c:1551 ast_rtp_make_compatible: Channel 'mISDN/0-u17' has no RTP, not doing anything [Apr 3 13:31:01] DEBUG[24814]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-pruebas-940-1. P[ 1] * CALL: g:te/675511308 P[ 1] --> * dad:675511308 tech:mISDN/0-u17 ctx:entrantes-analogicas P[ 1] --> * adding2newbc ext 675511308 P[ 1] --> * adding2newbc callerid P[ 1] --> pres: -1 screen: -1 P[ 1] --> pres: 0 P[ 1] --> PRES: Allowed (0x0) P[ 1] --> SCREEN: Unscreened (0x0) P[ 1] NO OPTS GIVEN P[ 1] I SEND:SETUP oad: dad:675511308 pid:6 P[ 1] --> bc_state:BCHAN_CLEANED P[ 1] --> channel:0 mode:TE cause:16 ocause:16 rad: cad: P[ 1] --> info_dad: onumplan:0 dnumplan:0 rnumplan:0 cpnnumplan:0 P[ 1] --> caps:Speech pi:0 keypad: sending_complete:0 P[ 1] --> screen:0 --> pres:0 P[ 1] --> addr:0 l3id:90004 b_stid:0 layer_id:50010180 P[ 1] --> facility:Fac_None out_facility:Fac_None P[ 1] --> found chan: 1 P[ 1] I IND :NEW_CHANNEL oad: dad:675511308 pid:6 state:NOTHING P[ 1] --> channel:1 mode:TE cause:16 ocause:16 rad: cad: P[ 1] --> info_dad: onumplan:0 dnumplan:0 rnumplan:0 cpnnumplan:0 P[ 1] --> caps:Speech pi:0 keypad: sending_complete:0 P[ 1] --> screen:0 --> pres:0 P[ 1] --> addr:0 l3id:90004 b_stid:0 layer_id:50010180 P[ 1] --> facility:Fac_None out_facility:Fac_None P[ 1] --> bc_state:BCHAN_CLEANED P[ 1] --> updating channel name to [mISDN/1-u18] P[ 1] --> found channel: 1 P[ 1] set_chan_in_stack: 1 P[ 1] --> new_l3id 90005 P[ 1] NO USERUESRINFO ENCODED P[ 1] Sending msg, prim:30580 addr:41000104 dinfo:90005 P[ 1] --> * SEND: State Dialing pid:6 [Apr 3 13:31:01] DEBUG[24814]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel mISDN/1-u18 [Apr 3 13:31:01] DEBUG[24693]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for mISDN - 1 [Apr 3 13:31:01] DEBUG[24693]: channel.c:1026 channel_find_locked: Avoiding initial deadlock for channel '0x823f078' [Apr 3 13:31:01] -- Called g:te/675511308 [Apr 3 13:31:01] DEBUG[24814]: channel.c:2845 set_format: Set channel mISDN/1-u18 to read format slin [Apr 3 13:31:01] DEBUG[24814]: channel.c:2845 set_format: Set channel OSS/dsp to write format slin [Apr 3 13:31:01] DEBUG[24814]: channel.c:2845 set_format: Set channel OSS/dsp to read format alaw [Apr 3 13:31:01] DEBUG[24693]: devicestate.c:287 do_state_change: Changing state for mISDN/1 - state 2 (In use) [Apr 3 13:31:01] DEBUG[24815]: app_queue.c:546 changethread: Device 'mISDN/1' changed to state '2' (In use) but we don't care because they're not a member of any queue. P[ 1] handle_frm: frm->addr:42000103 frm->prim:30282 P[ 1] set_channel: bc->channel:1 channel:1 P[ 1] I IND :NEW_CHANNEL oad: dad:675511308 pid:6 state:CALLING P[ 1] --> channel:1 mode:TE cause:16 ocause:16 rad: cad: P[ 1] --> info_dad: onumplan:0 dnumplan:0 rnumplan:0 cpnnumplan:0 P[ 1] --> caps:Speech pi:0 keypad: sending_complete:0 P[ 1] --> screen:0 --> pres:0 P[ 1] --> addr:0 l3id:90005 b_stid:0 layer_id:50010180 P[ 1] --> facility:Fac_None out_facility:Fac_None P[ 1] --> bc_state:BCHAN_CLEANED P[ 1] --> updating channel name to [mISDN/1-u19] P[ 1] setup_bc: with dsp P[ 1] --> Channel is 1 P[ 1] --> TRANSPARENT Mode P[ 1] set_chan_in_stack: 1 P[ 1] channel already in use:1 P[ 1] I IND :PROCEEDING oad: dad:675511308 pid:6 state:CALLING P[ 1] --> channel:1 mode:TE cause:16 ocause:16 rad: cad: P[ 1] --> info_dad: onumplan:0 dnumplan:0 rnumplan:0 cpnnumplan:0 P[ 1] --> caps:Speech pi:0 keypad: sending_complete:0 P[ 1] --> screen:0 --> pres:0 P[ 1] --> addr:50010102 l3id:90005 b_stid:10010100 layer_id:50010180 P[ 1] --> facility:Fac_None out_facility:Fac_None P[ 1] --> bc_state:BCHAN_ACTIVATED P[ 1] --> updating channel name to [mISDN/1-u20] [Apr 3 13:31:01] -- mISDN/1-u20 is proceeding passing it to OSS/dsp [Apr 3 13:31:01] DEBUG[24814]: rtp.c:1468 ast_rtp_early_bridge: Channel 'OSS/dsp' has no RTP, not doing anything [Apr 3 13:31:01] WARNING[24814]: chan_oss.c:978 oss_indicate: Don't know how to display condition 15 on OSS/dsp P[ 1] BCHAN: bchan ACT Confirm pid:6 [Apr 3 13:31:02] WARNING[24814]: chan_oss.c:682 setformat: Unable to re-open DSP device /dev/dsp: No such file or directory [Apr 3 13:31:03] WARNING[24814]: chan_oss.c:682 setformat: Unable to re-open DSP device /dev/dsp: No such file or directory [Apr 3 13:31:04] WARNING[24814]: chan_oss.c:682 setformat: Unable to re-open DSP device /dev/dsp: No such file or directory [Apr 3 13:31:05] WARNING[24814]: chan_oss.c:682 setformat: Unable to re-open DSP device /dev/dsp: No such file or directory P[ 1] handle_frm: frm->addr:42000103 frm->prim:30182 P[ 1] $$$ bc already upsetted stid :10010100 (state:BCHAN_ACTIVATED) P[ 1] set_chan_in_stack: 1 P[ 1] channel already in use:1 P[ 1] I IND :ALERTING oad: dad:675511308 pid:6 state:PROCEEDING P[ 1] --> channel:1 mode:TE cause:16 ocause:16 rad: cad: P[ 1] --> info_dad: onumplan:0 dnumplan:0 rnumplan:0 cpnnumplan:0 P[ 1] --> caps:Speech pi:8 keypad: sending_complete:0 P[ 1] --> screen:0 --> pres:0 P[ 1] --> addr:50010102 l3id:90005 b_stid:10010100 layer_id:50010180 P[ 1] --> facility:Fac_None out_facility:Fac_None P[ 1] --> bc_state:BCHAN_ACTIVATED P[ 1] --> updating channel name to [mISDN/1-u21] [Apr 3 13:31:06] DEBUG[24705]: devicestate.c:303 __ast_device_state_changed_literal: [Apr 3 13:31:06] -- mISDN/1-u21 is ringing Notification of state change to be queued on device/channel mISDN/1-u21 P[ 1] [Apr 3 13:31:06] DEBUG[24814]: rtp.c:1468 ast_rtp_early_bridge: Starting Tones, we have inband Data Channel 'OSS/dsp' has no RTP, not doing anything [Apr 3 13:31:06] DEBUG[24693]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for mISDN - 1 [Apr 3 13:31:06] DEBUG[24693]: devicestate.c:287 do_state_change: Changing state for mISDN/1 - state 6 (Ringing) [Apr 3 13:31:06] DEBUG[24819]: app_queue.c:546 changethread: Device 'mISDN/1' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Apr 3 13:31:08] DEBUG[24814]: rtp.c:1468 ast_rtp_early_bridge: Channel 'OSS/dsp' has no RTP, not doing anything [Apr 3 13:31:08] DEBUG[24814]: channel.c:1693 ast_hangup: Hanging up channel 'mISDN/1-u21' [Apr 3 13:31:08] DEBUG[24814]: chan_misdn.c:2301 misdn_hangup: misdn_hangup(mISDN/1-u21) P[ 1] * IND : HANGUP pid:6 ctx:entrantes-analogicas dad:675511308 oad:940 State:ALERTING P[ 1] --> l3id:90005 P[ 1] --> cause:16 P[ 1] --> out_cause:16 P[ 1] --> state:ALERTING P[ 1] I SEND:DISCONNECT oad: dad:675511308 pid:6 P[ 1] --> bc_state:BCHAN_ACTIVATED P[ 1] --> channel:1 mode:TE cause:16 ocause:16 rad: cad: P[ 1] --> info_dad: onumplan:0 dnumplan:0 rnumplan:0 cpnnumplan:0 P[ 1] --> caps:Speech pi:8 keypad: sending_complete:0 P[ 1] --> screen:0 --> pres:0 P[ 1] --> addr:50010102 l3id:90005 b_stid:10010100 layer_id:50010180 P[ 1] --> facility:Fac_None out_facility:Fac_None P[ 1] --> Channel: mISDN/1-u21 hanguped new state:CLEANING P[ 1] Sending msg, prim:34580 addr:41000104 dinfo:90005 [Apr 3 13:31:08] DEBUG[24814]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel mISDN/1-u21 [Apr 3 13:31:08] DEBUG[24814]: app_dial.c:1670 dial_exec_full: Exiting with DIALSTATUS=CANCEL. [Apr 3 13:31:08] DEBUG[24814]: pbx.c:2393 __ast_pbx_run: Spawn extension (pruebas,940,1) exited non-zero on 'OSS/dsp' [Apr 3 13:31:08] == Spawn extension (pruebas, 940, 1) exited non-zero on 'OSS/dsp' [Apr 3 13:31:08] DEBUG[24693]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for mISDN - 1 [Apr 3 13:31:08] DEBUG[24693]: devicestate.c:287 do_state_change: Changing state for mISDN/1 - state 0 (Unknown) [Apr 3 13:31:08] DEBUG[24814]: cdr_addon_mysql.c:213 mysql_log: cdr_mysql: inserting a CDR record. [Apr 3 13:31:08] DEBUG[24814]: cdr_addon_mysql.c:229 mysql_log: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield) VALUES ('2007-04-03 13:31:01','','','940','pruebas', 'OSS/dsp','mISDN/1-u18','Dial','mISDN/g:te/675511308',7,0,'NO ANSWER',3,'','1175599861.14','') [Apr 3 13:31:08] DEBUG[24820]: app_queue.c:546 changethread: Device 'mISDN/1' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Apr 3 13:31:08] DEBUG[24814]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 3 13:31:08] DEBUG[24814]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 3 13:31:08] DEBUG[24814]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '940' [Apr 3 13:31:08] DEBUG[24814]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'pruebas' [Apr 3 13:31:08] DEBUG[24814]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'OSS/dsp' [Apr 3 13:31:08] DEBUG[24814]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'mISDN/1-u18' [Apr 3 13:31:08] DEBUG[24814]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'Dial' [Apr 3 13:31:08] DEBUG[24814]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'mISDN/g:te/675511308' [Apr 3 13:31:08] DEBUG[24814]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '2007-04-03 13:31:01' [Apr 3 13:31:08] DEBUG[24814]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 3 13:31:08] DEBUG[24814]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '2007-04-03 13:31:08' [Apr 3 13:31:08] DEBUG[24814]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '7' [Apr 3 13:31:08] DEBUG[24814]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '0' [Apr 3 13:31:08] DEBUG[24814]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'NO ANSWER' [Apr 3 13:31:08] DEBUG[24814]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Apr 3 13:31:08] DEBUG[24814]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 3 13:31:08] DEBUG[24814]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '1175599861.14' [Apr 3 13:31:08] DEBUG[24814]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 3 13:31:08] DEBUG[24814]: channel.c:1693 ast_hangup: Hanging up channel 'OSS/dsp' [Apr 3 13:31:08] << Hangup on console >> [Apr 3 13:31:08] DEBUG[24814]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel OSS/dsp [Apr 3 13:31:08] DEBUG[24693]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for OSS - dsp [Apr 3 13:31:08] DEBUG[24693]: devicestate.c:287 do_state_change: Changing state for OSS/dsp - state 4 (Invalid) [Apr 3 13:31:08] DEBUG[24821]: app_queue.c:546 changethread: Device 'OSS/dsp' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. P[ 1] handle_frm: frm->addr:42000103 frm->prim:34d82 P[ 1] empty_chan_in_stack: 1 P[ 1] $$$ CLEANUP CALLED pid:6 P[ 1] $$$ Cleaning up bc with stid :10010100 pid:6 P[ 1] --> ec_disable P[ 1] Sending Control ECHOCAN_OFF P[ 1] ph_control: c1:2319 c2:0 P[ 1] I IND :RELEASE oad: dad: pid:6 state:CLEANING P[ 1] --> channel:0 mode:TE cause:16 ocause:16 rad: cad: P[ 1] --> info_dad: onumplan:0 dnumplan:0 rnumplan:0 cpnnumplan:0 P[ 1] --> caps:Speech pi:0 keypad: sending_complete:0 P[ 1] --> screen:0 --> pres:0 P[ 1] --> addr:50010102 l3id:90005 b_stid:0 layer_id:50010180 P[ 1] --> facility:Fac_None out_facility:Fac_None P[ 1] --> bc_state:BCHAN_CLEANED P[ 1] ast_hangup already called, so we have no ast ptr anymore in event(RELEASE) P[ 1] --> No need to queue hangup P[ 1] Cannot hangup chan, no ast P[ 1] I SEND:RELEASE_COMPLETE oad: dad: pid:6 P[ 1] --> bc_state:BCHAN_CLEANED P[ 1] --> channel:0 mode:TE cause:16 ocause:16 rad: cad: P[ 1] --> info_dad: onumplan:0 dnumplan:0 rnumplan:0 cpnnumplan:0 P[ 1] --> caps:Speech pi:0 keypad: sending_complete:0 P[ 1] --> screen:0 --> pres:0 P[ 1] --> addr:50010102 l3id:90005 b_stid:0 layer_id:50010180 P[ 1] --> facility:Fac_None out_facility:Fac_None P[ 1] $$$ CLEANUP CALLED pid:6 P[ 1] handle_frm: frm->addr:42000103 frm->prim:3f182 P[ 1] P[ 1] Sending msg, prim:35a80 addr:41000104 dinfo:90005 --> lib: RELEASE_CR Ind with l3id:90005 P[ 1] --> lib: CLEANING UP l3id: 90005 P[ 1] $$$ CLEANUP CALLED pid:6 P[ 1] BCHAN: MGR_DELLAYER|CNF pid:6 P[ 1] MGMT: SSTATUS: L2_RELEASED #### 4. Dial again to mISDN group. It fails now because I waited for L" to be released DOWN: ############################################################################# [Apr 3 13:31:21] WARNING[24744]: chan_oss.c:682 setformat: Unable to re-open DSP device /dev/dsp: No such file or directory [Apr 3 13:31:21] DEBUG[24825]: pbx.c:1795 pbx_extension_helper: Launching 'Dial' [Apr 3 13:31:21] -- Executing [940@pruebas:1] Dial("OSS/dsp", "mISDN/g:te/675511308") in new stack P[ 0] --> Group Call group: te P[ 1] Group [te] Port [1] P[ 1] Port Down L2:0 L1:1 P[ 1] portup:0 P[ 2] Group [te] Port [2] P[ 2] Port Down L2:0 L1:1 P[ 2] portup:0 P[ 3] Group [te] Port [3] P[ 3] Port Down L2:0 L1:1 P[ 3] portup:0 [Apr 3 13:31:22] WARNING[24825]: chan_misdn.c:5256 chan_misdn_log: Could not create channel on port:-1 with extensions:675511308 [Apr 3 13:31:22] WARNING[24825]: app_dial.c:1090 dial_exec_full: Unable to create channel of type 'mISDN' (cause 0 - Unknown) [Apr 3 13:31:22] == Everyone is busy/congested at this time (1:0/0/1) [Apr 3 13:31:22] DEBUG[24825]: rtp.c:1468 ast_rtp_early_bridge: Channel 'OSS/dsp' has no RTP, not doing anything [Apr 3 13:31:22] DEBUG[24825]: app_dial.c:1670 dial_exec_full: Exiting with DIALSTATUS=CHANUNAVAIL. [Apr 3 13:31:22] == Auto fallthrough, channel 'OSS/dsp' status is 'CHANUNAVAIL' [Apr 3 13:31:22] DEBUG[24825]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel OSS/dsp [Apr 3 13:31:22] DEBUG[24693]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for OSS - dsp [Apr 3 13:31:22] DEBUG[24693]: devicestate.c:287 do_state_change: Changing state for OSS/dsp - state 4 (Invalid) [Apr 3 13:31:22] DEBUG[24826]: app_queue.c:546 changethread: Device 'OSS/dsp' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Apr 3 13:31:27] DEBUG[24825]: cdr_addon_mysql.c:213 mysql_log: cdr_mysql: inserting a CDR record. [Apr 3 13:31:27] DEBUG[24825]: cdr_addon_mysql.c:229 mysql_log: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield) VALUES ('2007-04-03 13:31:21','','','940','pruebas', 'OSS/dsp','','Dial','mISDN/g:te/675511308',6,0,'NO ANSWER',3,'','1175599881.16','') [Apr 3 13:31:27] DEBUG[24825]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 3 13:31:27] DEBUG[24825]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 3 13:31:27] DEBUG[24825]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '940' [Apr 3 13:31:27] DEBUG[24825]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'pruebas' [Apr 3 13:31:27] DEBUG[24825]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'OSS/dsp' [Apr 3 13:31:27] DEBUG[24825]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 3 13:31:27] DEBUG[24825]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'Dial' [Apr 3 13:31:27] DEBUG[24825]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'mISDN/g:te/675511308' [Apr 3 13:31:27] DEBUG[24825]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '2007-04-03 13:31:21' [Apr 3 13:31:27] DEBUG[24825]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 3 13:31:27] DEBUG[24825]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '2007-04-03 13:31:27' [Apr 3 13:31:27] DEBUG[24825]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '6' [Apr 3 13:31:27] DEBUG[24825]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '0' [Apr 3 13:31:27] DEBUG[24825]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'NO ANSWER' [Apr 3 13:31:27] DEBUG[24825]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Apr 3 13:31:27] DEBUG[24825]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 3 13:31:27] DEBUG[24825]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '1175599881.16' [Apr 3 13:31:27] DEBUG[24825]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 3 13:31:27] DEBUG[24825]: channel.c:1693 ast_hangup: Hanging up channel 'OSS/dsp' [Apr 3 13:31:27] << Hangup on console >> [Apr 3 13:31:27] DEBUG[24825]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel OSS/dsp [Apr 3 13:31:27] DEBUG[24693]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for OSS - dsp [Apr 3 13:31:27] DEBUG[24693]: devicestate.c:287 do_state_change: Changing state for OSS/dsp - state 4 (Invalid) [Apr 3 13:31:27] DEBUG[24827]: app_queue.c:546 changethread: Device 'OSS/dsp' changed to state '4' (Invalid) but we don't care because they're not a member of any queue.