T1 Line configuration -24 b channels

mayank · March 15, 2010, 9:33pm

I have a T1 line from a Nortel PBX. The line is not a PRI line but has 24 b channel and no d channel. I tried configuring the dahdi driver but the dahdi module is not getting loaded into the asterisk. At the asterisk server I have a Digium TE220b interface card. I am attaching the asterisk configuration files

/etc/dahdi/system.conf

Span 1: TE2/0/1 “T2XXP (PCI) Card 0 Span 1” (MASTER) B8ZS/D4 ClockSource

span=1,1,0,d4,b8zs

termtype: te

bchan=1-24
echocanceller=mg2,1-23

/etc/asterisk/chan_dahdi.conf
[channels]
language=en

; include dahdi extensions defined in FreePBX
;#include chan_dahdi_additional.conf

; XTDM20B Port #1,2 plugged into PSTN
;AMPLABEL:Channel %c - Button %n

context=from-pstn
signalling=fxs_ls
faxdetect=incoming
usecallerid=yes
echocancel=yes
echocancelwhenbridged=no
echotraining=800
group=0
channel=1-24

blanchae · March 16, 2010, 6:21am

in /etc/dahdi/system.conf change this line

bchan=1-24 to fxsls=1-24

It is a PRI channel but not using ISDN so no B channel reference. I would not put the T1 configuration in /etc/asterisk/chan_dahdi_additional.conf as it will get written over by FreePBX the first time you create a dahdi extension.

Add an include: #include chan_dahdi_custom.conf to /etc/asterisk/chan_dahdi.conf and create a new file called chan_dahdi_custiom.conf and put your T1 config in there.

mayank · March 31, 2010, 4:20pm

Did that…Now I am able to dial out in the trunk (I can see it from the asterisk CLI)…But still the calls are not getting completed…If I dial from my softphone, like to my mobile, it shows as call established but actually I dont get any call to my mobile…Similarly if I dial the DID I get a busy tone

I have configured the voicemail for the single extension that I have created…some time back when I was trying with different configurations and I called on the DID I got a busy tone…but later when I checked on voicemail there was a voicemail…on playing it it was playing back the busy tone that I got…I am no longer able to recreate it but dont know how it could happen…Here is my overall setup…Can anybody tell me where should I look to debug or where the problem may lie

Nortel PBX —IPMux(Remote)----IPMux(In lab) ------ Asterisk(Digium TE 220b interface card)

I have added CLI output with debug level 6 and for channel 1 which is being used for dialing out below

mayank · March 31, 2010, 4:20pm

[Mar 31 10:18:23] DEBUG[32026]: chan_sip.c:4853 find_call: = No match Their Call ID: MThiOWFmYTU4OTAyY2Y4OWJjOTgzNzFjZjJkNjk5MzA. Their Tag 433c5b27 Our tag: as0a95a18f
[Mar 31 10:18:23] DEBUG[32026]: chan_sip.c:2894 do_setnat: Setting NAT on RTP to Off
[Mar 31 10:18:23] DEBUG[32026]: chan_sip.c:2899 do_setnat: Setting NAT on VRTP to Off
[Mar 31 10:18:23] DEBUG[32026]: chan_sip.c:4797 sip_alloc: Allocating new SIP dialog for NGZmNzQ2MzM3MTMxYzA1ZTk0NjMyMjliMzFiNDlhYjg. - INVITE (With RTP)
[Mar 31 10:18:23] DEBUG[32026]: chan_sip.c:16458 handle_request: **** Received INVITE (5) - Command in SIP INVITE
[Mar 31 10:18:23] DEBUG[32026]: acl.c:370 ast_apply_ha: ##### Testing 129.107.215.143 with 0.0.0.0
[Mar 31 10:18:23] DEBUG[32026]: acl.c:370 ast_apply_ha: ##### Testing 129.107.215.143 with 0.0.0.0
[Mar 31 10:18:23] DEBUG[32026]: chan_sip.c:2894 do_setnat: Setting NAT on RTP to On
[Mar 31 10:18:23] DEBUG[32026]: chan_sip.c:2899 do_setnat: Setting NAT on VRTP to On
[Mar 31 10:18:23] DEBUG[32026]: chan_sip.c:4853 find_call: = Found Their Call ID: NGZmNzQ2MzM3MTMxYzA1ZTk0NjMyMjliMzFiNDlhYjg. Their Tag 5991c653 Our tag: as2640a637
[Mar 31 10:18:23] DEBUG[32026]: chan_sip.c:16458 handle_request: **** Received ACK (6) - Command in SIP ACK
[Mar 31 10:18:23] DEBUG[32026]: chan_sip.c:2271 __sip_ack: Stopping retransmission on ‘NGZmNzQ2MzM3MTMxYzA1ZTk0NjMyMjliMzFiNDlhYjg.’ of Response 1: Match Found
[Mar 31 10:18:23] DEBUG[32026]: chan_sip.c:4853 find_call: = Found Their Call ID: NGZmNzQ2MzM3MTMxYzA1ZTk0NjMyMjliMzFiNDlhYjg. Their Tag 5991c653 Our tag: as2640a637
[Mar 31 10:18:23] DEBUG[32026]: chan_sip.c:16458 handle_request: **** Received INVITE (5) - Command in SIP INVITE
[Mar 31 10:18:23] DEBUG[32026]: acl.c:370 ast_apply_ha: ##### Testing 129.107.215.143 with 0.0.0.0
[Mar 31 10:18:23] DEBUG[32026]: acl.c:370 ast_apply_ha: ##### Testing 129.107.215.143 with 0.0.0.0
[Mar 31 10:18:23] DEBUG[32026]: chan_sip.c:2894 do_setnat: Setting NAT on RTP to On
[Mar 31 10:18:23] DEBUG[32026]: chan_sip.c:2899 do_setnat: Setting NAT on VRTP to On
[Mar 31 10:18:23] DEBUG[32026]: chan_sip.c:5432 process_sdp: Processing session-level SDP v=0… UNSUPPORTED.
[Mar 31 10:18:23] DEBUG[32026]: chan_sip.c:5432 process_sdp: Processing session-level SDP o=- 5 2 IN IP4 129.107.215.143… UNSUPPORTED.
[Mar 31 10:18:23] DEBUG[32026]: chan_sip.c:5432 process_sdp: Processing session-level SDP s=CounterPath X-Lite 4.0… UNSUPPORTED.
[Mar 31 10:18:23] DEBUG[32026]: chan_sip.c:5432 process_sdp: Processing session-level SDP c=IN IP4 129.107.215.143… OK.
[Mar 31 10:18:23] DEBUG[32026]: chan_sip.c:5432 process_sdp: Processing session-level SDP t=0 0… UNSUPPORTED.
[Mar 31 10:18:23] DEBUG[32026]: chan_sip.c:5570 process_sdp: Processing media-level (audio) SDP a=sendrecv… OK.
[Mar 31 10:18:23] DEBUG[32026]: chan_sip.c:5570 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000… OK.
[Mar 31 10:18:23] DEBUG[32026]: chan_sip.c:5570 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-15… UNSUPPORTED.
[Mar 31 10:18:23] DEBUG[32026]: chan_sip.c:5570 process_sdp: Processing media-level (audio) SDP a=alt:1 1 : 8zSffcU0 DLOkLfqY 129.107.215.143 42114… UNSUPPORTED.
[Mar 31 10:18:23] DEBUG[32026]: chan_sip.c:5595 process_sdp: T38 state changed to 0 on channel
[Mar 31 10:18:23] DEBUG[32026]: chan_sip.c:5728 process_sdp: We’re settling with these formats: 0xe (gsm|ulaw|alaw)
[Mar 31 10:18:23] DEBUG[32026]: chan_sip.c:15096 handle_request_invite: Checking SIP call limits for device 8500
[Mar 31 10:18:23] DEBUG[32026]: chan_sip.c:3392 update_call_counter: Updating call counter for incoming call
[Mar 31 10:18:23] DEBUG[32026]: chan_sip.c:3469 update_call_counter: Call from peer ‘8500’ is 1 out of 50
[Mar 31 10:18:23] DEBUG[32026]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/8500
[Mar 31 10:18:23] DEBUG[32026]: chan_sip.c:4243 sip_new: *** Our native formats are 0x4 (ulaw)
[Mar 31 10:18:23] DEBUG[32026]: chan_sip.c:4244 sip_new: *** Joint capabilities are 0xe (gsm|ulaw|alaw)
[Mar 31 10:18:23] DEBUG[32026]: chan_sip.c:4245 sip_new: *** Our capabilities are 0x3c190f (g723|gsm|ulaw|alaw|g726|g729|g722|h261|h263|h263p|h264)
[Mar 31 10:18:23] DEBUG[32026]: chan_sip.c:4246 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw)
[Mar 31 10:18:23] DEBUG[32026]: chan_sip.c:4269 sip_new: This channel will not be able to handle video.
[Mar 31 10:18:23] DEBUG[32026]: chan_sip.c:8919 build_route: build_route: Contact hop: sip:[email protected]:8318
[Mar 31 10:18:23] DEBUG[32026]: chan_sip.c:15195 handle_request_invite: SIP/8500-00000003: New call is still down… Trying…
[Mar 31 10:18:23] DEBUG[32026]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/8500
[Mar 31 10:18:23] DEBUG[32022]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 8500
[Mar 31 10:18:23] DEBUG[32022]: chan_sip.c:17237 sip_devicestate: Checking device state for peer 8500
[Mar 31 10:18:23] DEBUG[32022]: devicestate.c:287 do_state_change: Changing state for SIP/8500 - state 2 (In use)
[Mar 31 10:18:23] DEBUG[32022]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 8500
[Mar 31 10:18:23] DEBUG[32022]: chan_sip.c:17237 sip_devicestate: Checking device state for peer 8500
[Mar 31 10:18:23] DEBUG[32022]: devicestate.c:157 ast_device_state: Checking if I can find provider for “Custom” - number: DND8500
[Mar 31 10:18:23] DEBUG[32022]: devicestate.c:230 getproviderstate: Checking provider SLA with Custom
[Mar 31 10:18:23] DEBUG[32022]: devicestate.c:230 getproviderstate: Checking provider Meetme with Custom
[Mar 31 10:18:23] DEBUG[32022]: devicestate.c:230 getproviderstate: Checking provider Park with Custom
[Mar 31 10:18:23] DEBUG[32022]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 8500
[Mar 31 10:18:23] DEBUG[32022]: chan_sip.c:17237 sip_devicestate: Checking device state for peer 8500
[Mar 31 10:18:23] DEBUG[32022]: devicestate.c:287 do_state_change: Changing state for SIP/8500 - state 2 (In use)
[Mar 31 10:18:23] DEBUG[32022]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 8500
[Mar 31 10:18:23] DEBUG[32022]: chan_sip.c:17237 sip_devicestate: Checking device state for peer 8500
[Mar 31 10:18:23] DEBUG[32022]: devicestate.c:157 ast_device_state: Checking if I can find provider for “Custom” - number: DND8500
[Mar 31 10:18:23] DEBUG[32022]: devicestate.c:230 getproviderstate: Checking provider SLA with Custom
[Mar 31 10:18:23] DEBUG[32022]: devicestate.c:230 getproviderstate: Checking provider Meetme with Custom
[Mar 31 10:18:23] DEBUG[32022]: devicestate.c:230 getproviderstate: Checking provider Park with Custom
[Mar 31 10:18:23] DEBUG[32039]: app_queue.c:701 handle_statechange: Device ‘SIP/8500’ changed to state ‘2’ (In use) but we don’t care because they’re not a member of any queue.
[Mar 31 10:18:23] DEBUG[32039]: app_queue.c:701 handle_statechange: Device ‘SIP/8500’ changed to state ‘2’ (In use) but we don’t care because they’re not a member of any queue.
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1859 pbx_extension_helper: Launching ‘Macro’
– Executing [8172727409@from-internal:1] Macro(“SIP/8500-00000003”, “user-callerid|SKIPTTL|”) in new stack
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1775 pbx_substitute_variables_helper_full: Expression result is ‘1’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1707 pbx_substitute_variables_helper_full: Function result is ‘8500’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1707 pbx_substitute_variables_helper_full: Function result is ‘8500’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1859 pbx_extension_helper: Launching ‘Set’
– Executing [s@macro-user-callerid:1] Set(“SIP/8500-00000003”, “AMPUSER=8500”) in new stack
[Mar 31 10:18:23] DEBUG[32137]: app_macro.c:379 _macro_exec: Executed application: Set
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1775 pbx_substitute_variables_helper_full: Expression result is ‘0’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1859 pbx_extension_helper: Launching ‘GotoIf’
– Executing [s@macro-user-callerid:2] GotoIf(“SIP/8500-00000003”, “0?report”) in new stack
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:6098 pbx_builtin_gotoif: Not taking any branch
[Mar 31 10:18:23] DEBUG[32137]: app_macro.c:379 _macro_exec: Executed application: GotoIf
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1775 pbx_substitute_variables_helper_full: Expression result is ‘1’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1707 pbx_substitute_variables_helper_full: Function result is ‘8500’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1859 pbx_extension_helper: Launching ‘ExecIf’
– Executing [s@macro-user-callerid:3] ExecIf(“SIP/8500-00000003”, “1|Set|REALCALLERIDNUM=8500”) in new stack
[Mar 31 10:18:23] DEBUG[32137]: app_macro.c:379 _macro_exec: Executed application: ExecIf
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1775 pbx_substitute_variables_helper_full: Expression result is ‘0’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1707 pbx_substitute_variables_helper_full: Function result is ‘8500’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1707 pbx_substitute_variables_helper_full: Function result is ‘8500’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1859 pbx_extension_helper: Launching ‘Set’
– Executing [s@macro-user-callerid:4] Set(“SIP/8500-00000003”, “AMPUSER=8500”) in new stack
[Mar 31 10:18:23] DEBUG[32137]: app_macro.c:379 _macro_exec: Executed application: Set
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1707 pbx_substitute_variables_helper_full: Function result is ‘Mayank’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1859 pbx_extension_helper: Launching ‘Set’
– Executing [s@macro-user-callerid:5] Set(“SIP/8500-00000003”, “AMPUSERCIDNAME=Mayank”) in new stack
[Mar 31 10:18:23] DEBUG[32137]: app_macro.c:379 _macro_exec: Executed application: Set
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1775 pbx_substitute_variables_helper_full: Expression result is ‘0’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1859 pbx_extension_helper: Launching ‘GotoIf’
– Executing [s@macro-user-callerid:6] GotoIf(“SIP/8500-00000003”, “0?report”) in new stack
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:6098 pbx_builtin_gotoif: Not taking any branch
[Mar 31 10:18:23] DEBUG[32137]: app_macro.c:379 _macro_exec: Executed application: GotoIf
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1707 pbx_substitute_variables_helper_full: Function result is ‘1’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1775 pbx_substitute_variables_helper_full: Expression result is ‘1’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1707 pbx_substitute_variables_helper_full: Function result is ‘8172728500’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1859 pbx_extension_helper: Launching ‘Set’
– Executing [s@macro-user-callerid:7] Set(“SIP/8500-00000003”, “AMPUSERCID=8172728500”) in new stack
[Mar 31 10:18:23] DEBUG[32137]: app_macro.c:379 _macro_exec: Executed application: Set
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1859 pbx_extension_helper: Launching ‘Set’
– Executing [s@macro-user-callerid:8] Set(“SIP/8500-00000003”, “CALLERID(all)=“Mayank” <8172728500>”) in new stack
[Mar 31 10:18:23] DEBUG[32137]: app_macro.c:379 _macro_exec: Executed application: Set
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1707 pbx_substitute_variables_helper_full: Function result is ‘’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1775 pbx_substitute_variables_helper_full: Expression result is ‘0’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1707 pbx_substitute_variables_helper_full: Function result is ‘’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1859 pbx_extension_helper: Launching ‘ExecIf’
– Executing [s@macro-user-callerid:9] ExecIf(“SIP/8500-00000003”, “0|Set|CHANNEL(language)=”) in new stack
[Mar 31 10:18:23] DEBUG[32137]: app_macro.c:379 _macro_exec: Executed application: ExecIf
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1707 pbx_substitute_variables_helper_full: Function result is ‘’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1775 pbx_substitute_variables_helper_full: Expression result is ‘0’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1707 pbx_substitute_variables_helper_full: Function result is ‘’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1775 pbx_substitute_variables_helper_full: Expression result is ‘1’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1859 pbx_extension_helper: Launching ‘GotoIf’
– Executing [s@macro-user-callerid:10] GotoIf(“SIP/8500-00000003”, “1?continue”) in new stack
– Goto (macro-user-callerid,s,19)
[Mar 31 10:18:23] DEBUG[32137]: app_macro.c:379 _macro_exec: Executed application: GotoIf
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1707 pbx_substitute_variables_helper_full: Function result is ‘“Mayank” <8172728500>’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1859 pbx_extension_helper: Launching ‘NoOp’
– Executing [s@macro-user-callerid:19] NoOp(“SIP/8500-00000003”, “Using CallerID “Mayank” <8172728500>”) in new stack
[Mar 31 10:18:23] DEBUG[32137]: app_macro.c:379 _macro_exec: Executed application: Noop
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1859 pbx_extension_helper: Launching ‘Set’
– Executing [8172727409@from-internal:2] Set(“SIP/8500-00000003”, “_NODEST=”) in new stack
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1859 pbx_extension_helper: Launching ‘Macro’
– Executing [8172727409@from-internal:3] Macro(“SIP/8500-00000003”, “record-enable|8500|OUT|”) in new stack
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1775 pbx_substitute_variables_helper_full: Expression result is ‘1’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1859 pbx_extension_helper: Launching ‘GotoIf’
– Executing [s@macro-record-enable:1] GotoIf(“SIP/8500-00000003”, “1?check”) in new stack
– Goto (macro-record-enable,s,4)
[Mar 31 10:18:23] DEBUG[32137]: app_macro.c:379 _macro_exec: Executed application: GotoIf
Mar 31 10:18:23] DEBUG[32137]: pbx.c:1775 pbx_substitute_variables_helper_full: Expression result is ‘0’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1859 pbx_extension_helper: Launching ‘ExecIf’
– Executing [s@macro-record-enable:4] ExecIf(“SIP/8500-00000003”, “0|MacroExit|”) in new stack
Mar 31 10:18:23] DEBUG[32137]: app_macro.c:379 _macro_exec: Executed application: ExecIf
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1775 pbx_substitute_variables_helper_full: Expression result is ‘0’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1775 pbx_substitute_variables_helper_full: Expression result is ‘0’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1859 pbx_extension_helper: Launching ‘GotoIf’
– Executing [s@macro-record-enable:5] GotoIf(“SIP/8500-00000003”, “0?Group:OUT”) in new stack
– Goto (macro-record-enable,s,15)
[Mar 31 10:18:23] DEBUG[32137]: app_macro.c:379 _macro_exec: Executed application: GotoIf
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1775 pbx_substitute_variables_helper_full: Expression result is ‘0’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1859 pbx_extension_helper: Launching ‘GotoIf’
– Executing [s@macro-record-enable:15] GotoIf(“SIP/8500-00000003”, “0?IN”) in new stack
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:6098 pbx_builtin_gotoif: Not taking any branch
[Mar 31 10:18:23] DEBUG[32137]: app_macro.c:379 _macro_exec: Executed application: GotoIf
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1707 pbx_substitute_variables_helper_full: Function result is ‘out=Adhoc|in=Adhoc’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1707 pbx_substitute_variables_helper_full: Function result is ‘out=Adhoc’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1775 pbx_substitute_variables_helper_full: Expression result is ‘1’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1859 pbx_extension_helper: Launching ‘ExecIf’
– Executing [s@macro-record-enable:16] ExecIf(“SIP/8500-00000003”, “1|MacroExit|”) in new stack
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1859 pbx_extension_helper: Launching ‘Macro’
– Executing [8172727409@from-internal:4] Macro(“SIP/8500-00000003”, “dialout-trunk|1|8172727409||”) in new stack
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1859 pbx_extension_helper: Launching ‘Set’
– Executing [s@macro-dialout-trunk:1] Set(“SIP/8500-00000003”, “DIAL_TRUNK=1”) in new stack
[Mar 31 10:18:23] DEBUG[32137]: app_macro.c:379 _macro_exec: Executed application: Set
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1775 pbx_substitute_variables_helper_full: Expression result is ‘0’
[Mar 31 10:18:23] DEBUG[32137]: db.c:196 ast_db_get: Unable to find key ‘8500/pinless’ in family ‘AMPUSER’
[Mar 31 10:18:23] DEBUG[32137]: func_db.c:70 function_db_read: DB: AMPUSER/8500/pinless not found in database.
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1707 pbx_substitute_variables_helper_full: Function result is ‘’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1775 pbx_substitute_variables_helper_full: Expression result is ‘1’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1775 pbx_substitute_variables_helper_full: Expression result is ‘0’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1859 pbx_extension_helper: Launching ‘GosubIf’
– Executing [s@macro-dialout-trunk:2] GosubIf(“SIP/8500-00000003”, “0?sub-pincheck|s|1”) in new stack
[Mar 31 10:18:23] DEBUG[32137]: app_macro.c:379 _macro_exec: Executed application: GosubIf
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1775 pbx_substitute_variables_helper_full: Expression result is ‘0’
[Mar 31 10:18:23] DEBUG[32137]: db.c:196 ast_db_get: Unable to find key ‘8500/pinless’ in family ‘AMPUSER’
[Mar 31 10:18:23] DEBUG[32137]: func_db.c:70 function_db_read: DB: AMPUSER/8500/pinless not found in database.
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1707 pbx_substitute_variables_helper_full: Function result is ‘’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1775 pbx_substitute_variables_helper_full: Expression result is ‘1’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1775 pbx_substitute_variables_helper_full: Expression result is ‘0’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1775 pbx_substitute_variables_helper_full: Expression result is ‘0’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1859 pbx_extension_helper: Launching ‘GotoIf’
– Executing [s@macro-dialout-trunk:3] GotoIf(“SIP/8500-00000003”, “0?disabletrunk|1”) in new stack
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:6098 pbx_builtin_gotoif: Not taking any branch
[Mar 31 10:18:23] DEBUG[32137]: app_macro.c:379 _macro_exec: Executed application: GotoIf
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1859 pbx_extension_helper: Launching ‘Set’
– Executing [s@macro-dialout-trunk:4] Set(“SIP/8500-00000003”, “DIAL_NUMBER=8172727409”) in new stack
[Mar 31 10:18:23] DEBUG[32137]: app_macro.c:379 _macro_exec: Executed application: Set
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1859 pbx_extension_helper: Launching ‘Set’
– Executing [s@macro-dialout-trunk:5] Set(“SIP/8500-00000003”, “DIAL_TRUNK_OPTIONS=tr”) in new stack
[Mar 31 10:18:23] DEBUG[32137]: app_macro.c:379 _macro_exec: Executed application: Set
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1859 pbx_extension_helper: Launching ‘Set’
– Executing [s@macro-dialout-trunk:6] Set(“SIP/8500-00000003”, “OUTBOUND_GROUP=OUT_1”) in new stack
[Mar 31 10:18:23] DEBUG[32137]: app_macro.c:379 _macro_exec: Executed application: Set
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1775 pbx_substitute_variables_helper_full: Expression result is ‘1’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1859 pbx_extension_helper: Launching ‘GotoIf’
– Executing [s@macro-dialout-trunk:7] GotoIf(“SIP/8500-00000003”, “1?nomax”) in new stack
– Goto (macro-dialout-trunk,s,9)
[Mar 31 10:18:23] DEBUG[32137]: app_macro.c:379 _macro_exec: Executed application: GotoIf
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1775 pbx_substitute_variables_helper_full: Expression result is ‘0’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1859 pbx_extension_helper: Launching ‘GotoIf’
– Executing [s@macro-dialout-trunk:9] GotoIf(“SIP/8500-00000003”, “0?skipoutcid”) in new stack
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:6098 pbx_builtin_gotoif: Not taking any branch
[Mar 31 10:18:23] DEBUG[32137]: app_macro.c:379 _macro_exec: Executed application: GotoIf
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1859 pbx_extension_helper: Launching ‘Set’
– Executing [s@macro-dialout-trunk:10] Set(“SIP/8500-00000003”, “DIAL_TRUNK_OPTIONS=”) in new stack
[Mar 31 10:18:23] DEBUG[32137]: app_macro.c:379 _macro_exec: Executed application: Set
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1859 pbx_extension_helper: Launching ‘Macro’
– Executing [s@macro-dialout-trunk:11] Macro(“SIP/8500-00000003”, “outbound-callerid|1”) in new stack
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1775 pbx_substitute_variables_helper_full: Expression result is ‘0’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1859 pbx_extension_helper: Launching ‘ExecIf’
– Executing [s@macro-outbound-callerid:1] ExecIf(“SIP/8500-00000003”, “0|SetCallerPres|”) in new stack
[Mar 31 10:18:23] DEBUG[32137]: app_macro.c:379 _macro_exec: Executed application: ExecIf
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1775 pbx_substitute_variables_helper_full: Expression result is ‘0’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1775 pbx_substitute_variables_helper_full: Expression result is ‘0’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1707 pbx_substitute_variables_helper_full: Function result is ‘8172728500’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1859 pbx_extension_helper: Launching ‘ExecIf’
– Executing [s@macro-outbound-callerid:2] ExecIf(“SIP/8500-00000003”, “0|Set|REALCALLERIDNUM=8172728500”) in new stack
[Mar 31 10:18:23] DEBUG[32137]: app_macro.c:379 _macro_exec: Executed application: ExecIf
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1775 pbx_substitute_variables_helper_full: Expression result is ‘0’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1707 pbx_substitute_variables_helper_full: Function result is ‘8172728500’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1775 pbx_substitute_variables_helper_full: Expression result is ‘0’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1775 pbx_substitute_variables_helper_full: Expression result is ‘1’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1775 pbx_substitute_variables_helper_full: Expression result is ‘0’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1775 pbx_substitute_variables_helper_full: Expression result is ‘1’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1859 pbx_extension_helper: Launching ‘GotoIf’
– Executing [s@macro-outbound-callerid:3] GotoIf(“SIP/8500-00000003”, “1?normcid”) in new stack
– Goto (macro-outbound-callerid,s,6)
[Mar 31 10:18:23] DEBUG[32137]: app_macro.c:379 _macro_exec: Executed application: GotoIf
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1707 pbx_substitute_variables_helper_full: Function result is ‘8172728500’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1859 pbx_extension_helper: Launching ‘Set’
– Executing [s@macro-outbound-callerid:6] Set(“SIP/8500-00000003”, “USEROUTCID=8172728500”) in new stack
[Mar 31 10:18:23] DEBUG[32137]: app_macro.c:379 _macro_exec: Executed application: Set
[Mar 31 10:18:23] DEBUG[32137]: db.c:196 ast_db_get: Unable to find key ‘8500/emergency_cid’ in family ‘DEVICE’
[Mar 31 10:18:23] DEBUG[32137]: func_db.c:70 function_db_read: DB: DEVICE/8500/emergency_cid not found in database.
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1707 pbx_substitute_variables_helper_full: Function result is ‘’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1859 pbx_extension_helper: Launching ‘Set’
– Executing [s@macro-outbound-callerid:7] Set(“SIP/8500-00000003”, “EMERGENCYCID=”) in new stack
[Mar 31 10:18:23] DEBUG[32137]: app_macro.c:379 _macro_exec: Executed application: Set
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1859 pbx_extension_helper: Launching ‘Set’
– Executing [s@macro-outbound-callerid:8] Set(“SIP/8500-00000003”, “TRUNKOUTCID=”) in new stack
[Mar 31 10:18:23] DEBUG[32137]: app_macro.c:379 _macro_exec: Executed application: Set
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1775 pbx_substitute_variables_helper_full: Expression result is ‘1’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1859 pbx_extension_helper: Launching ‘GotoIf’
– Executing [s@macro-outbound-callerid:9] GotoIf(“SIP/8500-00000003”, “1?trunkcid”) in new stack
– Goto (macro-outbound-callerid,s,12)
[Mar 31 10:18:23] DEBUG[32137]: app_macro.c:379 _macro_exec: Executed application: GotoIf
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1775 pbx_substitute_variables_helper_full: Expression result is ‘0’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1859 pbx_extension_helper: Launching ‘ExecIf’
– Executing [s@macro-outbound-callerid:12] ExecIf(“SIP/8500-00000003”, “0|Set|CALLERID(all)=”) in new stack
[Mar 31 10:18:23] DEBUG[32137]: app_macro.c:379 _macro_exec: Executed application: ExecIf
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1775 pbx_substitute_variables_helper_full: Expression result is ‘0’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1775 pbx_substitute_variables_helper_full: Expression result is ‘1’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1859 pbx_extension_helper: Launching ‘ExecIf’
– Executing [s@macro-outbound-callerid:13] ExecIf(“SIP/8500-00000003”, “1|Set|CALLERID(all)=8172728500”) in new stack
[Mar 31 10:18:23] DEBUG[32137]: app_macro.c:379 _macro_exec: Executed application: ExecIf
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1775 pbx_substitute_variables_helper_full: Expression result is ‘1’
[Mar 31 10:18:23] DEBUG[32137]: app_macro.c:420 _macro_exec: Last app: Set|CALLERID(all)=8172728500
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1775 pbx_substitute_variables_helper_full: Expression result is ‘0’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1775 pbx_substitute_variables_helper_full: Expression result is ‘1’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1707 pbx_substitute_variables_helper_full: Function result is ‘’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1859 pbx_extension_helper: Launching ‘ExecIf’
– Executing [s@macro-outbound-callerid:14] ExecIf(“SIP/8500-00000003”, “0|Set|CALLERID(all)=”) in new stack
[Mar 31 10:18:23] DEBUG[32137]: app_macro.c:379 _macro_exec: Executed application: ExecIf
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1775 pbx_substitute_variables_helper_full: Expression result is ‘0’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1775 pbx_substitute_variables_helper_full: Expression result is ‘1’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1707 pbx_substitute_variables_helper_full: Function result is ‘’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1707 pbx_substitute_variables_helper_full: Function result is ‘’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1775 pbx_substitute_variables_helper_full: Expression result is ‘0’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1859 pbx_extension_helper: Launching ‘ExecIf’
– Executing [s@macro-outbound-callerid:15] ExecIf(“SIP/8500-00000003”, “0|SetCallerPres|prohib_passed_screen”) in new stack
[Mar 31 10:18:23] DEBUG[32137]: app_macro.c:379 _macro_exec: Executed application: ExecIf
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1707 pbx_substitute_variables_helper_full: Function result is ‘’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1775 pbx_substitute_variables_helper_full: Expression result is ‘0’
[Mar 31 10:18:23] DEBUG[32137]: app_macro.c:379 _macro_exec: Executed application: Macro
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1775 pbx_substitute_variables_helper_full: Expression result is ‘0’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1859 pbx_extension_helper: Launching ‘ExecIf’
– Executing [s@macro-dialout-trunk:12] ExecIf(“SIP/8500-00000003”, “0|AGI|fixlocalprefix”) in new stack
[Mar 31 10:18:23] DEBUG[32137]: app_macro.c:379 _macro_exec: Executed application: ExecIf
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1775 pbx_substitute_variables_helper_full: Expression result is ‘0’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1859 pbx_extension_helper: Launching ‘Set’
– Executing [s@macro-dialout-trunk:13] Set(“SIP/8500-00000003”, “OUTNUM=98172727409”) in new stack
[Mar 31 10:18:23] DEBUG[32137]: app_macro.c:379 _macro_exec: Executed application: Set
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1707 pbx_substitute_variables_helper_full: Function result is ‘DAHDI/g0’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1859 pbx_extension_helper: Launching ‘Set’
– Executing [s@macro-dialout-trunk:14] Set(“SIP/8500-00000003”, “custom=DAHDI/g0”) in new stack
[Mar 31 10:18:23] DEBUG[32137]: app_macro.c:379 _macro_exec: Executed application: Set
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1775 pbx_substitute_variables_helper_full: Expression result is ‘1’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1775 pbx_substitute_variables_helper_full: Expression result is ‘0’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1775 pbx_substitute_variables_helper_full: Expression result is ‘0’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1859 pbx_extension_helper: Launching ‘ExecIf’
– Executing [s@macro-dialout-trunk:15] ExecIf(“SIP/8500-00000003”, “0|Set|DIAL_TRUNK_OPTIONS=M(setmusic^)”) in new stack
[Mar 31 10:18:23] DEBUG[32137]: app_macro.c:379 _macro_exec: Executed application: ExecIf
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1775 pbx_substitute_variables_helper_full: Expression result is ‘1’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1775 pbx_substitute_variables_helper_full: Expression result is ‘0’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1775 pbx_substitute_variables_helper_full: Expression result is ‘0’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1859 pbx_extension_helper: Launching ‘Macro’
– Executing [s@macro-dialout-trunk:16] Macro(“SIP/8500-00000003”, “dialout-trunk-predial-hook|”) in new stack
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1859 pbx_extension_helper: Launching ‘MacroExit’
– Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit(“SIP/8500-00000003”, “”) in new stack
[Mar 31 10:18:23] DEBUG[32137]: app_macro.c:379 _macro_exec: Executed application: Macro
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1775 pbx_substitute_variables_helper_full: Expression result is ‘0’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1859 pbx_extension_helper: Launching ‘GotoIf’
– Executing [s@macro-dialout-trunk:17] GotoIf(“SIP/8500-00000003”, “0?bypass|1”) in new stack
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:6098 pbx_builtin_gotoif: Not taking any branch
[Mar 31 10:18:23] DEBUG[32137]: app_macro.c:379 _macro_exec: Executed application: GotoIf
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1775 pbx_substitute_variables_helper_full: Expression result is ‘0’
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1859 pbx_extension_helper: Launching ‘GotoIf’
– Executing [s@macro-dialout-trunk:18] GotoIf(“SIP/8500-00000003”, “0?customtrunk”) in new stack
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:6098 pbx_builtin_gotoif: Not taking any branch
[Mar 31 10:18:23] DEBUG[32137]: app_macro.c:379 _macro_exec: Executed application: GotoIf
[Mar 31 10:18:23] DEBUG[32137]: pbx.c:1859 pbx_extension_helper: Launching ‘Dial’
– Executing [s@macro-dialout-trunk:19] Dial(“SIP/8500-00000003”, “DAHDI/g0/98172727409|300|”) in new stack
[Mar 31 10:18:23] DEBUG[32137]: chan_dahdi.c:8425 dahdi_request: Using channel 24
[Mar 31 10:18:23] DEBUG[32137]: rtp.c:1646 ast_rtp_make_compatible: Channel ‘DAHDI/24-1’ has no RTP, not doing anything
[Mar 31 10:18:23] DEBUG[32137]: channel.c:3759 ast_channel_inherit_variables: Not copying variable DIALEDTIME.
[Mar 31 10:18:23] DEBUG[32137]: channel.c:3759 ast_channel_inherit_variables: Not copying variable ANSWEREDTIME.
[Mar 31 10:18:23] DEBUG[32137]: channel.c:3759 ast_channel_inherit_variables: Not copying variable DIALEDPEERNAME.
[Mar 31 10:18:23] DEBUG[32137]: channel.c:3759 ast_channel_inherit_variables: Not copying variable DIALEDPEERNUMBER.
[Mar 31 10:18:23] DEBUG[32137]: channel.c:3759 ast_channel_inherit_variables: Not copying variable DIALSTATUS.
[Mar 31 10:18:23] DEBUG[32137]: channel.c:3759 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH.
[Mar 31 10:18:23] DEBUG[32137]: channel.c:3759 ast_channel_inherit_variables: Not copying variable MACRO_PRIORITY.
[Mar 31 10:18:23] DEBUG[32137]: channel.c:3759 ast_channel_inherit_variables: Not copying variable MACRO_CONTEXT.
[Mar 31 10:18:23] DEBUG[32137]: channel.c:3759 ast_channel_inherit_variables: Not copying variable MACRO_EXTEN.
[Mar 31 10:18:23] DEBUG[32137]: channel.c:3759 ast_channel_inherit_variables: Not copying variable ARG1.
[Mar 31 10:18:23] DEBUG[32137]: channel.c:3759 ast_channel_inherit_variables: Not copying variable custom.
[Mar 31 10:18:23] DEBUG[32137]: channel.c:3759 ast_channel_inherit_variables: Not copying variable OUTNUM.
[Mar 31 10:18:23] DEBUG[32137]: channel.c:3759 ast_channel_inherit_variables: Not copying variable TRUNKOUTCID.
[Mar 31 10:18:23] DEBUG[32137]: channel.c:3759 ast_channel_inherit_variables: Not copying variable EMERGENCYCID.
[Mar 31 10:18:23] DEBUG[32137]: channel.c:3759 ast_channel_inherit_variables: Not copying variable USEROUTCID.
[Mar 31 10:18:23] DEBUG[32137]: channel.c:3759 ast_channel_inherit_variables: Not copying variable DB_RESULT.
[Mar 31 10:18:23] DEBUG[32137]: channel.c:3759 ast_channel_inherit_variables: Not copying variable DIAL_TRUNK_OPTIONS.
[Mar 31 10:18:23] DEBUG[32137]: channel.c:3759 ast_channel_inherit_variables: Not copying variable OUTBOUND_GROUP.
[Mar 31 10:18:23] DEBUG[32137]: channel.c:3759 ast_channel_inherit_variables: Not copying variable DIAL_NUMBER.
[Mar 31 10:18:23] DEBUG[32137]: channel.c:3759 ast_channel_inherit_variables: Not copying variable DIAL_TRUNK.
[Mar 31 10:18:23] DEBUG[32137]: channel.c:3759 ast_channel_inherit_variables: Not copying variable ARG4.
[Mar 31 10:18:23] DEBUG[32137]: channel.c:3759 ast_channel_inherit_variables: Not copying variable ARG3.
[Mar 31 10:18:23] DEBUG[32137]: channel.c:3759 ast_channel_inherit_variables: Not copying variable ARG2.
[Mar 31 10:18:23] DEBUG[32137]: channel.c:3746 ast_channel_inherit_variables: Copying soft-transferable variable NODEST.
[Mar 31 10:18:23] DEBUG[32137]: channel.c:3759 ast_channel_inherit_variables: Not copying variable AMPUSERCID.
[Mar 31 10:18:23] DEBUG[32137]: channel.c:3759 ast_channel_inherit_variables: Not copying variable AMPUSERCIDNAME.
[Mar 31 10:18:23] DEBUG[32137]: channel.c:3759 ast_channel_inherit_variables: Not copying variable AMPUSER.
[Mar 31 10:18:23] DEBUG[32137]: channel.c:3759 ast_channel_inherit_variables: Not copying variable REALCALLERIDNUM.
[Mar 31 10:18:23] DEBUG[32137]: channel.c:3759 ast_channel_inherit_variables: Not copying variable SIPCALLID.
[Mar 31 10:18:23] DEBUG[32137]: channel.c:3759 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT.
[Mar 31 10:18:23] DEBUG[32137]: channel.c:3759 ast_channel_inherit_variables: Not copying variable SIPDOMAIN.
[Mar 31 10:18:23] DEBUG[32137]: channel.c:3759 ast_channel_inherit_variables: Not copying variable SIPURI.
[Mar 31 10:18:23] DEBUG[32137]: chan_dahdi.c:2301 dahdi_call: Dialing ‘98172727409’
[Mar 31 10:18:23] DEBUG[32137]: chan_dahdi.c:2379 dahdi_call: Deferring dialing… (res -1)
[Mar 31 10:18:23] DEBUG[32137]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel DAHDI/24
[Mar 31 10:18:25] DEBUG[32137]: chan_dahdi.c:5048 __dahdi_exception: Exception on 10, channel 24
[Mar 31 10:18:25] DEBUG[32137]: chan_dahdi.c:4142 dahdi_handle_event: Got event Hook Transition Complete(12) on channel 24 (index 0)
[Mar 31 10:18:25] DEBUG[32137]: chan_dahdi.c:4883 dahdi_handle_event: Sent deferred digit string: T9817272740
[Mar 31 10:18:26] DEBUG[32026]: chan_sip.c:4797 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Mar 31 10:18:26] DEBUG[32026]: chan_sip.c:4853 find_call: = Found Their Call ID: [email protected] Their Tag Our tag: as546207bf
[Mar 31 10:18:26] DEBUG[32026]: chan_sip.c:2271 __sip_ack: Stopping retransmission on ‘[email protected]’ of Request 102: Match Found
Really destroying SIP dialog ‘[email protected]’ Method: OPTIONS
[Mar 31 10:18:27] DEBUG[32137]: chan_dahdi.c:5048 __dahdi_exception: Exception on 10, channel 24
[Mar 31 10:18:27] DEBUG[32137]: chan_dahdi.c:4142 dahdi_handle_event: Got event Dial Complete(9) on channel 24 (index 0)
[Mar 31 10:18:27] DEBUG[32137]: chan_dahdi.c:1784 dahdi_enable_ec: Enabled echo cancellation on channel 24
[Mar 31 10:18:27] DEBUG[32137]: chan_dahdi.c:1800 dahdi_train_ec: Engaged echo training on channel 24
[Mar 31 10:18:29] DEBUG[32137]: chan_dahdi.c:5048 __dahdi_exception: Exception on 10, channel 24
[Mar 31 10:18:29] DEBUG[32137]: chan_dahdi.c:4142 dahdi_handle_event: Got event Dial Complete(9) on channel 24 (index 0)
[Mar 31 10:18:29] DEBUG[32137]: chan_dahdi.c:1763 dahdi_enable_ec: Echo cancellation already on
[Mar 31 10:18:29] DEBUG[32137]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel DAHDI/24
– DAHDI/24-1 answered SIP/8500-00000003
[Mar 31 10:18:29] DEBUG[32137]: rtp.c:1572 ast_rtp_early_bridge: Channel ‘DAHDI/24-1’ has no RTP, not doing anything
[Mar 31 10:18:29] DEBUG[32137]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/8500
[Mar 31 10:18:29] DEBUG[32137]: chan_sip.c:3872 sip_answer: SIP answering channel: SIP/8500-00000003
[Mar 31 10:18:29] DEBUG[32137]: chan_sip.c:7241 transmit_response_with_sdp: Setting framing from config on incoming call
[Mar 31 10:18:29] DEBUG[32137]: chan_sip.c:6956 add_sdp: ** Our capability: 0xe (gsm|ulaw|alaw) Video flag: True
[Mar 31 10:18:29] DEBUG[32137]: chan_sip.c:6957 add_sdp: ** Our prefcodec: 0x0 (nothing)
[Mar 31 10:18:29] DEBUG[32137]: chan_sip.c:7074 add_sdp: – Done with adding codecs to SDP
[Mar 31 10:18:29] DEBUG[32137]: channel.c:2538 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=71)
[Mar 31 10:18:29] DEBUG[32137]: chan_sip.c:7183 add_sdp: Done building SDP. Settling with this capability: 0xe (gsm|ulaw|alaw)
[Mar 31 10:18:29] DEBUG[32137]: chan_dahdi.c:5480 dahdi_indicate: Requested indication 20 on channel DAHDI/24-1
[Mar 31 10:18:29] DEBUG[32022]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for DAHDI - 24
[Mar 31 10:18:29] DEBUG[32022]: devicestate.c:287 do_state_change: Changing state for DAHDI/24 - state 2 (In use)
[Mar 31 10:18:29] DEBUG[32022]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 8500
[Mar 31 10:18:29] DEBUG[32022]: chan_sip.c:17237 sip_devicestate: Checking device state for peer 8500
[Mar 31 10:18:29] DEBUG[32022]: devicestate.c:287 do_state_change: Changing state for SIP/8500 - state 2 (In use)
[Mar 31 10:18:29] DEBUG[32022]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 8500
[Mar 31 10:18:29] DEBUG[32022]: chan_sip.c:17237 sip_devicestate: Checking device state for peer 8500
[Mar 31 10:18:29] DEBUG[32022]: devicestate.c:157 ast_device_state: Checking if I can find provider for “Custom” - number: DND8500
[Mar 31 10:18:29] DEBUG[32022]: devicestate.c:230 getproviderstate: Checking provider SLA with Custom
[Mar 31 10:18:29] DEBUG[32022]: devicestate.c:230 getproviderstate: Checking provider Meetme with Custom
[Mar 31 10:18:29] DEBUG[32022]: devicestate.c:230 getproviderstate: Checking provider Park with Custom
[Mar 31 10:18:29] DEBUG[32039]: app_queue.c:701 handle_statechange: Device ‘DAHDI/24’ changed to state ‘2’ (In use) but we don’t care because they’re not a member of any queue.
[Mar 31 10:18:29] DEBUG[32039]: app_queue.c:701 handle_statechange: Device ‘SIP/8500’ changed to state ‘2’ (In use) but we don’t care because they’re not a member of any queue.
[Mar 31 10:18:29] DEBUG[32137]: rtp.c:2897 ast_rtp_write: Ooh, format changed from unknown to ulaw
[Mar 31 10:18:29] DEBUG[32137]: rtp.c:2914 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160
[Mar 31 10:18:29] DEBUG[32137]: rtp.c:923 ast_rtcp_read: Got RTCP report of 132 bytes
[Mar 31 10:18:29] DEBUG[32026]: chan_sip.c:4853 find_call: = Found Their Call ID: NGZmNzQ2MzM3MTMxYzA1ZTk0NjMyMjliMzFiNDlhYjg. Their Tag 5991c653 Our tag: as786d329f
[Mar 31 10:18:29] DEBUG[32026]: chan_sip.c:16458 handle_request: **** Received ACK (6) - Command in SIP ACK
[Mar 31 10:18:29] DEBUG[32026]: chan_sip.c:2271 __sip_ack: Stopping retransmission on ‘NGZmNzQ2MzM3MTMxYzA1ZTk0NjMyMjliMzFiNDlhYjg.’ of Response 2: Match Found
[Mar 31 10:18:32] DEBUG[32137]: rtp.c:923 ast_rtcp_read: Got RTCP report of 176 bytes
[Mar 31 10:18:34] DEBUG[32062]: manager.c:2233 process_message: Manager received command ‘Command’
[Mar 31 10:18:34] DEBUG[32062]: manager.c:2233 process_message: Manager received command ‘Command’
[Mar 31 10:18:34] DEBUG[32062]: manager.c:2233 process_message: Manager received command ‘Command’
[Mar 31 10:18:34] DEBUG[32062]: manager.c:2233 process_message: Manager received command ‘MailboxStatus’
[Mar 31 10:18:34] DEBUG[32062]: manager.c:2233 process_message: Manager received command ‘MailboxCount’
[Mar 31 10:18:35] DEBUG[32137]: rtp.c:923 ast_rtcp_read: Got RTCP report of 176 bytes
[Mar 31 10:18:38] DEBUG[32137]: rtp.c:923 ast_rtcp_read: Got RTCP report of 176 bytes
[Mar 31 10:18:41] DEBUG[32137]: rtp.c:923 ast_rtcp_read: Got RTCP report of 176 bytes
[Mar 31 10:18:44] DEBUG[32137]: rtp.c:923 ast_rtcp_read: Got RTCP report of 176 bytes
[Mar 31 10:18:45] DEBUG[32137]: rtp.c:923 ast_rtcp_read: Got RTCP report of 160 bytes
[Mar 31 10:18:45] DEBUG[32026]: chan_sip.c:4853 find_call: = Found Their Call ID: NGZmNzQ2MzM3MTMxYzA1ZTk0NjMyMjliMzFiNDlhYjg. Their Tag 5991c653 Our tag: as786d329f
[Mar 31 10:18:45] DEBUG[32026]: chan_sip.c:16458 handle_request: **** Received BYE (8) - Command in SIP BYE
[Mar 31 10:18:45] DEBUG[32026]: chan_sip.c:1719 sip_alreadygone: Setting SIP_ALREADYGONE on dialog NGZmNzQ2MzM3MTMxYzA1ZTk0NjMyMjliMzFiNDlhYjg.
[Mar 31 10:18:45] DEBUG[32026]: chan_sip.c:15991 handle_request_bye: Received bye, issuing owner hangup
[Mar 31 10:18:45] DEBUG[32137]: channel.c:4295 ast_generic_bridge: Didn’t get a frame from channel: SIP/8500-00000003
[Mar 31 10:18:45] DEBUG[32137]: chan_dahdi.c:5480 dahdi_indicate: Requested indication 20 on channel DAHDI/24-1
[Mar 31 10:18:45] DEBUG[32137]: channel.c:4662 ast_channel_bridge: Bridge stops bridging channels SIP/8500-00000003 and DAHDI/24-1
[Mar 31 10:18:45] DEBUG[32137]: pbx.c:1859 pbx_extension_helper: Launching ‘Macro’
– Executing [h@macro-dialout-trunk:1] Macro(“SIP/8500-00000003”, “hangupcall|”) in new stack
[Mar 31 10:18:45] DEBUG[32137]: pbx.c:1775 pbx_substitute_variables_helper_full: Expression result is ‘1’
[Mar 31 10:18:45] DEBUG[32137]: pbx.c:1859 pbx_extension_helper: Launching ‘GotoIf’
– Executing [s@macro-hangupcall:1] GotoIf(“SIP/8500-00000003”, “1?skiprg”) in new stack
– Goto (macro-hangupcall,s,4)
[Mar 31 10:18:45] DEBUG[32137]: app_macro.c:379 _macro_exec: Executed application: GotoIf
[Mar 31 10:18:45] DEBUG[32137]: pbx.c:1775 pbx_substitute_variables_helper_full: Expression result is ‘1’
[Mar 31 10:18:45] DEBUG[32137]: pbx.c:1859 pbx_extension_helper: Launching ‘GotoIf’
– Executing [s@macro-hangupcall:4] GotoIf(“SIP/8500-00000003”, “1?skipblkvm”) in new stack
– Goto (macro-hangupcall,s,7)
[Mar 31 10:18:45] DEBUG[32137]: app_macro.c:379 _macro_exec: Executed application: GotoIf
[Mar 31 10:18:45] DEBUG[32137]: pbx.c:1775 pbx_substitute_variables_helper_full: Expression result is ‘1’
[Mar 31 10:18:45] DEBUG[32137]: pbx.c:1859 pbx_extension_helper: Launching ‘GotoIf’
– Executing [s@macro-hangupcall:7] GotoIf(“SIP/8500-00000003”, “1?theend”) in new stack
– Goto (macro-hangupcall,s,9)
[Mar 31 10:18:45] DEBUG[32137]: app_macro.c:379 _macro_exec: Executed application: GotoIf
[Mar 31 10:18:45] DEBUG[32137]: pbx.c:1859 pbx_extension_helper: Launching ‘Hangup’
– Executing [s@macro-hangupcall:9] Hangup(“SIP/8500-00000003”, “”) in new stack
[Mar 31 10:18:45] DEBUG[32137]: app_macro.c:372 _macro_exec: Spawn extension (macro-hangupcall,s,9) exited non-zero on ‘SIP/8500-00000003’ in macro ‘hangupcall’
[Mar 31 10:18:45] DEBUG[32137]: res_features.c:2036 ast_bridge_call: Spawn h extension (macro-dialout-trunk,h,1) exited non-zero on ‘SIP/8500-00000003’
== Spawn h extension (macro-dialout-trunk, h, 1) exited non-zero on ‘SIP/8500-00000003’
[Mar 31 10:18:45] DEBUG[32137]: channel.c:1565 ast_hangup: Hanging up channel ‘DAHDI/24-1’
[Mar 31 10:18:45] DEBUG[32137]: chan_dahdi.c:2816 dahdi_hangup: dahdi_hangup(DAHDI/24-1)
[Mar 31 10:18:45] DEBUG[32137]: chan_dahdi.c:2851 dahdi_hangup: Hangup: channel: 24 index = 0, normal = 10, callwait = -1, thirdcall = -1
[Mar 31 10:18:45] DEBUG[32137]: chan_dahdi.c:1816 dahdi_disable_ec: disabled echo cancellation on channel 24
[Mar 31 10:18:45] DEBUG[32137]: chan_dahdi.c:3290 dahdi_setoption: Set option TDD MODE, value: OFF(0) on DAHDI/24-1
[Mar 31 10:18:45] DEBUG[32137]: chan_dahdi.c:1752 update_conf: Updated conferencing on 24, with 0 conference users
– Hungup ‘DAHDI/24-1’
[Mar 31 10:18:45] DEBUG[32137]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel DAHDI/24
[Mar 31 10:18:45] DEBUG[32137]: rtp.c:1572 ast_rtp_early_bridge: Channel ‘’ has no RTP, not doing anything
[Mar 31 10:18:45] DEBUG[32137]: app_dial.c:1901 dial_exec_full: Exiting with DIALSTATUS=ANSWER.
[Mar 31 10:18:45] DEBUG[32137]: app_macro.c:372 _macro_exec: Spawn extension (macro-dialout-trunk,s,19) exited non-zero on ‘SIP/8500-00000003’ in macro ‘dialout-trunk’
[Mar 31 10:18:45] DEBUG[32137]: pbx.c:2409 __ast_pbx_run: Spawn extension (from-internal,8172727409,4) exited non-zero on ‘SIP/8500-00000003’
== Spawn extension (from-internal, 8172727409, 4) exited non-zero on ‘SIP/8500-00000003’
[Mar 31 10:18:45] DEBUG[32137]: channel.c:1462 ast_softhangup_nolock: Soft-Hanging up channel ‘SIP/8500-00000003’
[Mar 31 10:18:45] DEBUG[32137]: channel.c:1565 ast_hangup: Hanging up channel ‘SIP/8500-00000003’
[Mar 31 10:18:45] DEBUG[32137]: chan_sip.c:3709 sip_hangup: Hangup call SIP/8500-00000003, SIP callid NGZmNzQ2MzM3MTMxYzA1ZTk0NjMyMjliMzFiNDlhYjg.)
[Mar 31 10:18:45] DEBUG[32137]: chan_sip.c:3392 update_call_counter: Updating call counter for incoming call
[Mar 31 10:18:45] DEBUG[32137]: chan_sip.c:3443 update_call_counter: Call from peer ‘8500’ removed from call limit 50
[Mar 31 10:18:45] DEBUG[32022]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for DAHDI - 24
[Mar 31 10:18:45] DEBUG[32022]: devicestate.c:287 do_state_change: Changing state for DAHDI/24 - state 0 (Unknown)
[Mar 31 10:18:45] DEBUG[32137]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/8500
[Mar 31 10:18:45] DEBUG[32137]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/8500
[Mar 31 10:18:45] DEBUG[32039]: app_queue.c:701 handle_statechange: Device ‘DAHDI/24’ changed to state ‘0’ (Unknown) but we don’t care because they’re not a member of any queue.
[Mar 31 10:18:45] DEBUG[32022]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 8500
[Mar 31 10:18:45] DEBUG[32022]: chan_sip.c:17237 sip_devicestate: Checking device state for peer 8500
[Mar 31 10:18:45] DEBUG[32022]: devicestate.c:287 do_state_change: Changing state for SIP/8500 - state 1 (Not in use)
[Mar 31 10:18:45] DEBUG[32022]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 8500
[Mar 31 10:18:45] DEBUG[32022]: chan_sip.c:17237 sip_devicestate: Checking device state for peer 8500
[Mar 31 10:18:45] DEBUG[32022]: devicestate.c:157 ast_device_state: Checking if I can find provider for “Custom” - number: DND8500
[Mar 31 10:18:45] DEBUG[32022]: devicestate.c:230 getproviderstate: Checking provider SLA with Custom
[Mar 31 10:18:45] DEBUG[32022]: devicestate.c:230 getproviderstate: Checking provider Meetme with Custom
[Mar 31 10:18:45] DEBUG[32022]: devicestate.c:230 getproviderstate: Checking provider Park with Custom
[Mar 31 10:18:45] DEBUG[32022]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 8500
[Mar 31 10:18:45] DEBUG[32022]: chan_sip.c:17237 sip_devicestate: Checking device state for peer 8500
[Mar 31 10:18:45] DEBUG[32022]: devicestate.c:287 do_state_change: Changing state for SIP/8500 - state 1 (Not in use)
[Mar 31 10:18:45] DEBUG[32022]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 8500
[Mar 31 10:18:45] DEBUG[32022]: chan_sip.c:17237 sip_devicestate: Checking device state for peer 8500
[Mar 31 10:18:45] DEBUG[32022]: devicestate.c:157 ast_device_state: Checking if I can find provider for “Custom” - number: DND8500
[Mar 31 10:18:45] DEBUG[32022]: devicestate.c:230 getproviderstate: Checking provider SLA with Custom
[Mar 31 10:18:45] DEBUG[32022]: devicestate.c:230 getproviderstate: Checking provider Meetme with Custom
[Mar 31 10:18:45] DEBUG[32022]: devicestate.c:230 getproviderstate: Checking provider Park with Custom
[Mar 31 10:18:45] DEBUG[32039]: app_queue.c:701 handle_statechange: Device ‘SIP/8500’ changed to state ‘1’ (Not in use) but we don’t care because they’re not a member of any queue.
[Mar 31 10:18:45] DEBUG[32039]: app_queue.c:701 handle_statechange: Device ‘SIP/8500’ changed to state ‘1’ (Not in use) but we don’t care because they’re not a member of any queue.
Really destroying SIP dialog ‘NGZmNzQ2MzM3MTMxYzA1ZTk0NjMyMjliMzFiNDlhYjg.’ Method: BYE
dhcp-0-4-23-b4-f5-55*CLI>