[Mar 20 08:59:07] VERBOSE[28663] asterisk.c:     -- Remote UNIX connection
[Mar 20 08:59:23] Asterisk 11.16-0SNAPSHOT built by root @ b2v-deb-build-wheezy on a x86_64 running Linux on 2015-03-19 13:05:05 UTC
[Mar 20 08:59:23] DEBUG[29083] config.c: Parsing /etc/asterisk/logger.conf
[Mar 20 08:59:23] VERBOSE[29083] config.c:   == Parsing '/etc/asterisk/logger.conf': Found
[Mar 20 08:59:23] DEBUG[29083] config.c: Parsing /etc/asterisk/logger_common.conf
[Mar 20 08:59:23] VERBOSE[29083] config.c:   == Parsing '/etc/asterisk/logger_common.conf': Found
[Mar 20 08:59:23] VERBOSE[29083] logger.c:  Asterisk Queue Logger restarted
[Mar 20 09:01:54] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 
[Mar 20 09:01:54] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 < Protocol Discriminator: Q.931 (8)  len=47
[Mar 20 09:01:54] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 < TEI=0 Call Ref: len= 2 (reference 20682/0x50CA) (Sent from originator)
[Mar 20 09:01:54] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 < Message Type: SETUP (5)
[Mar 20 09:01:54] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 < [a1]
[Mar 20 09:01:54] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 < Sending Complete (len= 1)
[Mar 20 09:01:54] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 < [04 03 90 90 a3]
[Mar 20 09:01:54] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 < Bearer Capability (len= 5) [ Ext: 1  Coding-Std: 0  Info transfer capability: 3.1kHz audio (16)
[Mar 20 09:01:54] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 <                              Ext: 1  Trans mode/rate: 64kbps, circuit-mode (16)
[Mar 20 09:01:54] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 <                                User information layer 1: A-Law (35)
[Mar 20 09:01:54] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 < [18 03 a1 83 82]
[Mar 20 09:01:54] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 < Channel ID (len= 5) [ Ext: 1  IntID: Implicit  Other(PRI)  Spare: 0  Preferred  Dchan: 0
[Mar 20 09:01:54] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 <                       ChanSel: As indicated in following octets
[Mar 20 09:01:54] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 <                       Ext: 1  Coding: 0  Number Specified  Channel Type: 3
[Mar 20 09:01:54] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 <                       Ext: 1  Channel: 2 Type: CPE]
[Mar 20 09:01:54] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 < [1e 02 8a 81]
[Mar 20 09:01:54] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 < Progress Indicator (len= 4) [ Ext: 1  Coding: CCITT (ITU) standard (0)  0: 0  Location: Network beyond the interworking point (10)
[Mar 20 09:01:54] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 <                               Ext: 1  Progress Description: Call is not end-to-end ISDN; further call progress information may be available inband. (1) ]
[Mar 20 09:01:54] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 < [6c 0d 21 83 38 39 32 31 39 30 39 39 38 34 34]
[Mar 20 09:01:54] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 < Calling Party Number (len=15) [ Ext: 0  TON: National Number (2)  NPI: ISDN/Telephony Numbering Plan (E.164/E.163) (1)
[Mar 20 09:01:54] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 <                                 Presentation: Presentation allowed, Network provided (3)  '89xxxxxxxxx' ]
[Mar 20 09:01:54] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 < [70 0a c1 33 35 38 39 39 32 34 30 30]
[Mar 20 09:01:54] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 < Called Party Number (len=12) [ Ext: 1  TON: Subscriber Number (4)  NPI: ISDN/Telephony Numbering Plan (E.164/E.163) (1)  '3yyyyy400' ]
[Mar 20 09:01:54] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 -- Making new call for cref 20682
[Mar 20 09:01:54] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 Received message for call 0x7fe9f4024350 on link 0x2c36780 TEI/SAPI 0/0
[Mar 20 09:01:54] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 -- Processing Q.931 Call Setup
[Mar 20 09:01:54] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 -- Processing IE 161 (cs0, Sending Complete)
[Mar 20 09:01:54] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 -- Processing IE 4 (cs0, Bearer Capability)
[Mar 20 09:01:54] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 -- Processing IE 24 (cs0, Channel ID)
[Mar 20 09:01:54] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 -- Processing IE 30 (cs0, Progress Indicator)
[Mar 20 09:01:54] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 -- Processing IE 108 (cs0, Calling Party Number)
[Mar 20 09:01:54] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 -- Processing IE 112 (cs0, Called Party Number)
[Mar 20 09:01:54] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 q931.c:8661 post_handle_q931_message: Call 20682 enters state 6 (Call Present).  Hold state: Idle
[Mar 20 09:01:54] VERBOSE[28690] sig_pri.c: Span 1: Processing event PRI_EVENT_RING(5)
[Mar 20 09:01:54] DEBUG[28690][C-00000001] sig_pri.c: prioffset: 2 mastertrunkgroup: 0 logicalspan: 0 result: 2
[Mar 20 09:01:54] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 q931.c:5707 q931_call_proceeding: Call 20682 enters state 9 (Incoming Call Proceeding).  Hold state: Idle
[Mar 20 09:01:54] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 
[Mar 20 09:01:54] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 > DL-DATA request
[Mar 20 09:01:54] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 > Protocol Discriminator: Q.931 (8)  len=10
[Mar 20 09:01:54] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 > TEI=0 Call Ref: len= 2 (reference 20682/0x50CA) (Sent to originator)
[Mar 20 09:01:54] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 > Message Type: CALL PROCEEDING (2)
[Mar 20 09:01:54] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 TEI=0 Transmitting N(S)=4, window is open V(A)=4 K=7
[Mar 20 09:01:54] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 
[Mar 20 09:01:54] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 > Protocol Discriminator: Q.931 (8)  len=10
[Mar 20 09:01:54] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 > TEI=0 Call Ref: len= 2 (reference 20682/0x50CA) (Sent to originator)
[Mar 20 09:01:54] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 > Message Type: CALL PROCEEDING (2)
[Mar 20 09:01:54] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 > [18 03 a9 83 82]
[Mar 20 09:01:54] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 > Channel ID (len= 5) [ Ext: 1  IntID: Implicit  Other(PRI)  Spare: 0  Exclusive  Dchan: 0
[Mar 20 09:01:54] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 >                       ChanSel: As indicated in following octets
[Mar 20 09:01:54] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 >                       Ext: 1  Coding: 0  Number Specified  Channel Type: 3
[Mar 20 09:01:54] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 >                       Ext: 1  Channel: 2 Type: CPE]
[Mar 20 09:01:54] DEBUG[28690][C-00000001] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21
[Mar 20 09:01:54] DEBUG[28690][C-00000001] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
[Mar 20 09:01:54] DEBUG[28696] manager.c: Examining event:
Event: Newchannel
Privilege: call,all
Channel: DAHDI/i1/4989xxxxxxxxx-2
ChannelState: 4
ChannelStateDesc: Ring
CallerIDNum: 4989xxxxxxxxx
CallerIDName: 
AccountCode: 
Exten: 3yyyyy400
Context: default
Uniqueid: 1426838514.1


[Mar 20 09:01:54] DEBUG[28682] devicestate.c: No provider found, checking channel drivers for DAHDI - i1/4989xxxxxxxxx
[Mar 20 09:01:54] DEBUG[28696] manager.c: Examining event:
Event: DAHDIChannel
Privilege: call,all
Channel: DAHDI/i1/4989xxxxxxxxx-2
Uniqueid: 1426838514.1
DAHDISpan: 1
DAHDIChannel: 2


[Mar 20 09:01:54] DEBUG[28682] devicestate.c: Changing state for DAHDI/i1/4989xxxxxxxxx - state 2 (In use)
[Mar 20 09:01:54] DEBUG[28682] devicestate.c: device 'DAHDI/i1/4989xxxxxxxxx' state '2'
[Mar 20 09:01:54] VERBOSE[28690][C-00000001] sig_pri.c:     -- Accepting call from '4989xxxxxxxxx' to '3yyyyy400' on channel 0/2, span 1
[Mar 20 09:01:54] DEBUG[29084][C-00000001] pbx.c: Result of 'MONITORING_ENABLED' is '0'
[Mar 20 09:01:54] DEBUG[29084][C-00000001] pbx.c: Expression result is '1'
[Mar 20 09:01:54] DEBUG[29084][C-00000001] pbx.c: Launching 'GotoIf'
[Mar 20 09:01:54] VERBOSE[29084][C-00000001] pbx.c:     -- Executing [3yyyyy400@default:1] GotoIf("DAHDI/i1/4989xxxxxxxxx-2", "1?nomonitor") in new stack
[Mar 20 09:01:54] VERBOSE[29084][C-00000001] pbx.c:     -- Goto (default,3yyyyy400,5)
[Mar 20 09:01:54] DEBUG[29084][C-00000001] pbx.c: Result of 'HEAD_NUMBER' is '358992'
[Mar 20 09:01:54] DEBUG[29084][C-00000001] pbx.c: Function LEN(358992) result is '6'
[Mar 20 09:01:54] DEBUG[29084][C-00000001] pbx.c: Result of 'EXTEN' is '3yyyyy400'
[Mar 20 09:01:54] DEBUG[29084][C-00000001] pbx.c: Launching 'Goto'
[Mar 20 09:01:54] VERBOSE[29084][C-00000001] pbx.c:     -- Executing [3yyyyy400@default:5] Goto("DAHDI/i1/4989xxxxxxxxx-2", "default,400,1") in new stack
[Mar 20 09:01:54] VERBOSE[29084][C-00000001] pbx.c:     -- Goto (default,400,1)
[Mar 20 09:01:54] DEBUG[29084][C-00000001] pbx.c: Launching 'Answer'
[Mar 20 09:01:54] VERBOSE[29084][C-00000001] pbx.c:     -- Executing [400@default:1] Answer("DAHDI/i1/4989xxxxxxxxx-2", "") in new stack
[Mar 20 09:01:54] DEBUG[28682] devicestate.c: No provider found, checking channel drivers for DAHDI - i1/4989xxxxxxxxx
[Mar 20 09:01:54] DEBUG[28696] manager.c: Examining event:
Event: VarSet
Privilege: dialplan,all
Channel: DAHDI/i1/4989xxxxxxxxx-2
Variable: TRANSFERCAPABILITY
Value: 3K1AUDIO
Uniqueid: 1426838514.1


[Mar 20 09:01:54] DEBUG[28696] manager.c: Examining event:
Event: VarSet
Privilege: dialplan,all
Channel: DAHDI/i1/4989xxxxxxxxx-2
Variable: ANI2
Value: 0
Uniqueid: 1426838514.1


[Mar 20 09:01:54] DEBUG[28696] manager.c: Examining event:
Event: VarSet
Privilege: dialplan,all
Channel: DAHDI/i1/4989xxxxxxxxx-2
Variable: CALLEDTON
Value: 65
Uniqueid: 1426838514.1


[Mar 20 09:01:54] DEBUG[28696] manager.c: Examining event:
Event: VarSet
Privilege: dialplan,all
Channel: DAHDI/i1/4989xxxxxxxxx-2
Variable: PRIREDIRECTREASON
Value: UNKNOWN
Uniqueid: 1426838514.1


[Mar 20 09:01:54] DEBUG[28696] manager.c: Examining event:
Event: Newexten
Privilege: dialplan,all
Channel: DAHDI/i1/4989xxxxxxxxx-2
Context: default
Extension: 3yyyyy400
Priority: 1
Application: GotoIf
AppData: 1?nomonitor
Uniqueid: 1426838514.1


[Mar 20 09:01:54] DEBUG[28696] manager.c: Examining event:
Event: Newexten
Privilege: dialplan,all
Channel: DAHDI/i1/4989xxxxxxxxx-2
Context: default
Extension: 3yyyyy400
Priority: 5
Application: Goto
AppData: default,400,1
Uniqueid: 1426838514.1


[Mar 20 09:01:54] DEBUG[28696] manager.c: Examining event:
Event: Newexten
Privilege: dialplan,all
Channel: DAHDI/i1/4989xxxxxxxxx-2
Context: default
Extension: 400
Priority: 1
Application: Answer
AppData: 
Uniqueid: 1426838514.1


[Mar 20 09:01:54] DEBUG[28696] manager.c: Examining event:
Event: Newstate
Privilege: call,all
Channel: DAHDI/i1/4989xxxxxxxxx-2
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum: 4989xxxxxxxxx
CallerIDName: 
ConnectedLineNum: 
ConnectedLineName: 
Uniqueid: 1426838514.1


[Mar 20 09:01:54] DEBUG[28690][C-00000001] chan_dahdi.c: Enabled echo cancellation on channel 2
[Mar 20 09:01:54] VERBOSE[29084] chan_dahdi.c: PRI Span: 1 q931.c:5903 q931_connect: Call 20682 enters state 8 (Connect Request).  Hold state: Idle
[Mar 20 09:01:54] VERBOSE[29084] chan_dahdi.c: PRI Span: 1 
[Mar 20 09:01:54] VERBOSE[29084] chan_dahdi.c: PRI Span: 1 > DL-DATA request
[Mar 20 09:01:54] VERBOSE[29084] chan_dahdi.c: PRI Span: 1 > Protocol Discriminator: Q.931 (8)  len=14
[Mar 20 09:01:54] VERBOSE[29084] chan_dahdi.c: PRI Span: 1 > TEI=0 Call Ref: len= 2 (reference 20682/0x50CA) (Sent to originator)
[Mar 20 09:01:54] VERBOSE[29084] chan_dahdi.c: PRI Span: 1 > Message Type: CONNECT (7)
[Mar 20 09:01:54] VERBOSE[29084] chan_dahdi.c: PRI Span: 1 TEI=0 Transmitting N(S)=5, window is open V(A)=4 K=7
[Mar 20 09:01:54] VERBOSE[29084] chan_dahdi.c: PRI Span: 1 
[Mar 20 09:01:54] VERBOSE[29084] chan_dahdi.c: PRI Span: 1 > Protocol Discriminator: Q.931 (8)  len=14
[Mar 20 09:01:54] VERBOSE[29084] chan_dahdi.c: PRI Span: 1 > TEI=0 Call Ref: len= 2 (reference 20682/0x50CA) (Sent to originator)
[Mar 20 09:01:54] VERBOSE[29084] chan_dahdi.c: PRI Span: 1 > Message Type: CONNECT (7)
[Mar 20 09:01:54] VERBOSE[29084] chan_dahdi.c: PRI Span: 1 > [18 03 a9 83 82]
[Mar 20 09:01:54] VERBOSE[29084] chan_dahdi.c: PRI Span: 1 > Channel ID (len= 5) [ Ext: 1  IntID: Implicit  Other(PRI)  Spare: 0  Exclusive  Dchan: 0
[Mar 20 09:01:54] VERBOSE[29084] chan_dahdi.c: PRI Span: 1 >                       ChanSel: As indicated in following octets
[Mar 20 09:01:54] VERBOSE[29084] chan_dahdi.c: PRI Span: 1 >                       Ext: 1  Coding: 0  Number Specified  Channel Type: 3
[Mar 20 09:01:54] VERBOSE[29084] chan_dahdi.c: PRI Span: 1 >                       Ext: 1  Channel: 2 Type: CPE]
[Mar 20 09:01:54] VERBOSE[29084] chan_dahdi.c: PRI Span: 1 > [1e 02 81 82]
[Mar 20 09:01:54] VERBOSE[29084] chan_dahdi.c: PRI Span: 1 > Progress Indicator (len= 4) [ Ext: 1  Coding: CCITT (ITU) standard (0)  0: 0  Location: Private network serving the local user (1)
[Mar 20 09:01:54] VERBOSE[29084] chan_dahdi.c: PRI Span: 1 >                               Ext: 1  Progress Description: Called equipment is non-ISDN. (2) ]
[Mar 20 09:01:54] DEBUG[28682] devicestate.c: Changing state for DAHDI/i1/4989xxxxxxxxx - state 2 (In use)
[Mar 20 09:01:54] DEBUG[28682] devicestate.c: device 'DAHDI/i1/4989xxxxxxxxx' state '2'
[Mar 20 09:01:54] DEBUG[29084][C-00000001] chan_dahdi.c: Requested indication -1 on channel DAHDI/i1/4989xxxxxxxxx-2
[Mar 20 09:01:54] DEBUG[29084][C-00000001] pbx.c: Launching 'Playback'
[Mar 20 09:01:54] VERBOSE[29084][C-00000001] pbx.c:     -- Executing [400@default:2] Playback("DAHDI/i1/4989xxxxxxxxx-2", "hello-world") in new stack
[Mar 20 09:01:54] DEBUG[28696] manager.c: Examining event:
Event: Newexten
Privilege: dialplan,all
Channel: DAHDI/i1/4989xxxxxxxxx-2
Context: default
Extension: 400
Priority: 2
Application: Playback
AppData: hello-world
Uniqueid: 1426838514.1


[Mar 20 09:01:54] DEBUG[29084][C-00000001] channel.c: Set channel DAHDI/i1/4989xxxxxxxxx-2 to write format gsm
[Mar 20 09:01:54] DEBUG[29084][C-00000001] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Mar 20 09:01:54] VERBOSE[29084][C-00000001] file.c:     -- <DAHDI/i1/4989xxxxxxxxx-2> Playing 'hello-world.gsm' (language 'de')
[Mar 20 09:01:55] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 
[Mar 20 09:01:55] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 < Protocol Discriminator: Q.931 (8)  len=5
[Mar 20 09:01:55] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 < TEI=0 Call Ref: len= 2 (reference 20682/0x50CA) (Sent from originator)
[Mar 20 09:01:55] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 < Message Type: CONNECT ACKNOWLEDGE (15)
[Mar 20 09:01:55] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 Received message for call 0x7fe9f4024350 on link 0x2c36780 TEI/SAPI 0/0
[Mar 20 09:01:55] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 q931.c:8876 post_handle_q931_message: Call 20682 enters state 10 (Active).  Hold state: Idle
[Mar 20 09:01:55] VERBOSE[28690] sig_pri.c: Span 1: Processing event PRI_EVENT_CONNECT_ACK(27)
[Mar 20 09:01:56] DEBUG[29084][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar 20 09:01:56] DEBUG[29084][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar 20 09:01:56] DEBUG[29084][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar 20 09:01:56] DEBUG[29084][C-00000001] channel.c: Set channel DAHDI/i1/4989xxxxxxxxx-2 to write format alaw
[Mar 20 09:01:56] DEBUG[29084][C-00000001] pbx.c: Launching 'Playback'
[Mar 20 09:01:56] VERBOSE[29084][C-00000001] pbx.c:     -- Executing [400@default:3] Playback("DAHDI/i1/4989xxxxxxxxx-2", "hello-world") in new stack
[Mar 20 09:01:56] DEBUG[28696] manager.c: Examining event:
Event: VarSet
Privilege: dialplan,all
Channel: DAHDI/i1/4989xxxxxxxxx-2
Variable: PLAYBACKSTATUS
Value: SUCCESS
Uniqueid: 1426838514.1


[Mar 20 09:01:56] DEBUG[28696] manager.c: Examining event:
Event: Newexten
Privilege: dialplan,all
Channel: DAHDI/i1/4989xxxxxxxxx-2
Context: default
Extension: 400
Priority: 3
Application: Playback
AppData: hello-world
Uniqueid: 1426838514.1


[Mar 20 09:01:56] DEBUG[29084][C-00000001] channel.c: Set channel DAHDI/i1/4989xxxxxxxxx-2 to write format gsm
[Mar 20 09:01:56] DEBUG[29084][C-00000001] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Mar 20 09:01:56] VERBOSE[29084][C-00000001] file.c:     -- <DAHDI/i1/4989xxxxxxxxx-2> Playing 'hello-world.gsm' (language 'de')
[Mar 20 09:01:58] DEBUG[29084][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar 20 09:01:58] DEBUG[29084][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar 20 09:01:58] DEBUG[29084][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar 20 09:01:58] DEBUG[29084][C-00000001] channel.c: Set channel DAHDI/i1/4989xxxxxxxxx-2 to write format alaw
[Mar 20 09:01:58] DEBUG[29084][C-00000001] pbx.c: Launching 'Playback'
[Mar 20 09:01:58] VERBOSE[29084][C-00000001] pbx.c:     -- Executing [400@default:4] Playback("DAHDI/i1/4989xxxxxxxxx-2", "hello-world") in new stack
[Mar 20 09:01:58] DEBUG[28696] manager.c: Examining event:
Event: VarSet
Privilege: dialplan,all
Channel: DAHDI/i1/4989xxxxxxxxx-2
Variable: PLAYBACKSTATUS
Value: SUCCESS
Uniqueid: 1426838514.1


[Mar 20 09:01:58] DEBUG[28696] manager.c: Examining event:
Event: Newexten
Privilege: dialplan,all
Channel: DAHDI/i1/4989xxxxxxxxx-2
Context: default
Extension: 400
Priority: 4
Application: Playback
AppData: hello-world
Uniqueid: 1426838514.1


[Mar 20 09:01:58] DEBUG[29084][C-00000001] channel.c: Set channel DAHDI/i1/4989xxxxxxxxx-2 to write format gsm
[Mar 20 09:01:58] DEBUG[29084][C-00000001] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Mar 20 09:01:58] VERBOSE[29084][C-00000001] file.c:     -- <DAHDI/i1/4989xxxxxxxxx-2> Playing 'hello-world.gsm' (language 'de')
[Mar 20 09:01:59] DEBUG[29084][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar 20 09:01:59] DEBUG[29084][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar 20 09:01:59] DEBUG[29084][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar 20 09:01:59] DEBUG[29084][C-00000001] channel.c: Set channel DAHDI/i1/4989xxxxxxxxx-2 to write format alaw
[Mar 20 09:01:59] DEBUG[29084][C-00000001] pbx.c: Launching 'Playback'
[Mar 20 09:01:59] VERBOSE[29084][C-00000001] pbx.c:     -- Executing [400@default:5] Playback("DAHDI/i1/4989xxxxxxxxx-2", "hello-world") in new stack
[Mar 20 09:01:59] DEBUG[28696] manager.c: Examining event:
Event: VarSet
Privilege: dialplan,all
Channel: DAHDI/i1/4989xxxxxxxxx-2
Variable: PLAYBACKSTATUS
Value: SUCCESS
Uniqueid: 1426838514.1


[Mar 20 09:01:59] DEBUG[28696] manager.c: Examining event:
Event: Newexten
Privilege: dialplan,all
Channel: DAHDI/i1/4989xxxxxxxxx-2
Context: default
Extension: 400
Priority: 5
Application: Playback
AppData: hello-world
Uniqueid: 1426838514.1


[Mar 20 09:01:59] DEBUG[29084][C-00000001] channel.c: Set channel DAHDI/i1/4989xxxxxxxxx-2 to write format gsm
[Mar 20 09:01:59] DEBUG[29084][C-00000001] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Mar 20 09:01:59] VERBOSE[29084][C-00000001] file.c:     -- <DAHDI/i1/4989xxxxxxxxx-2> Playing 'hello-world.gsm' (language 'de')
[Mar 20 09:02:00] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 
[Mar 20 09:02:00] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 < Protocol Discriminator: Q.931 (8)  len=13
[Mar 20 09:02:00] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 < TEI=0 Call Ref: len= 2 (reference 20682/0x50CA) (Sent from originator)
[Mar 20 09:02:00] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 < Message Type: DISCONNECT (69)
[Mar 20 09:02:00] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 < [08 02 80 90]
[Mar 20 09:02:00] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 < Cause (len= 4) [ Ext: 1  Coding: CCITT (ITU) standard (0)  Spare: 0  Location: User (0)
[Mar 20 09:02:00] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 <                  Ext: 1  Cause: Normal Clearing (16), class = Normal Event (1) ]
[Mar 20 09:02:00] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 < [1e 02 82 88]
[Mar 20 09:02:00] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 < Progress Indicator (len= 4) [ Ext: 1  Coding: CCITT (ITU) standard (0)  0: 0  Location: Public network serving the local user (2)
[Mar 20 09:02:00] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 <                               Ext: 1  Progress Description: Inband information or appropriate pattern now available. (8) ]
[Mar 20 09:02:00] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 Received message for call 0x7fe9f4024350 on link 0x2c36780 TEI/SAPI 0/0
[Mar 20 09:02:00] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 -- Processing IE 8 (cs0, Cause)
[Mar 20 09:02:00] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 -- Processing IE 30 (cs0, Progress Indicator)
[Mar 20 09:02:00] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 -- Found active call: 0x7fe9f4024350 cref:20682
[Mar 20 09:02:00] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 q931.c:9099 post_handle_q931_message: Call 20682 enters state 12 (Disconnect Indication).  Hold state: Idle
[Mar 20 09:02:00] VERBOSE[28690] sig_pri.c: Span 1: Processing event PRI_EVENT_HANGUP_REQ(15)
[Mar 20 09:02:00] VERBOSE[28690][C-00000001] sig_pri.c:     -- Span 1: Channel 0/2 got hangup request, cause 16
[Mar 20 09:02:00] DEBUG[29084][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar 20 09:02:00] DEBUG[29084][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Mar 20 09:02:00] DEBUG[29084][C-00000001] channel.c: Set channel DAHDI/i1/4989xxxxxxxxx-2 to write format alaw
[Mar 20 09:02:00] DEBUG[29084][C-00000001] pbx.c: Spawn extension (default,400,5) exited non-zero on 'DAHDI/i1/4989xxxxxxxxx-2'
[Mar 20 09:02:00] VERBOSE[29084][C-00000001] pbx.c:   == Spawn extension (default, 400, 5) exited non-zero on 'DAHDI/i1/4989xxxxxxxxx-2'
[Mar 20 09:02:00] DEBUG[29084][C-00000001] channel.c: Soft-Hanging up channel 'DAHDI/i1/4989xxxxxxxxx-2'
[Mar 20 09:02:00] DEBUG[28696] manager.c: Examining event:
Event: VarSet
Privilege: dialplan,all
Channel: DAHDI/i1/4989xxxxxxxxx-2
Variable: PLAYBACKSTATUS
Value: SUCCESS
Uniqueid: 1426838514.1


[Mar 20 09:02:00] DEBUG[29084][C-00000001] channel.c: Hanging up channel 'DAHDI/i1/4989xxxxxxxxx-2'
[Mar 20 09:02:00] DEBUG[29084][C-00000001] chan_dahdi.c: dahdi_hangup(DAHDI/i1/4989xxxxxxxxx-2)
[Mar 20 09:02:00] DEBUG[29084][C-00000001] chan_dahdi.c: Set option AUDIO MODE, value: ON(1) on DAHDI/i1/4989xxxxxxxxx-2
[Mar 20 09:02:00] DEBUG[28696] manager.c: Examining event:
Event: SoftHangupRequest
Privilege: call,all
Channel: DAHDI/i1/4989xxxxxxxxx-2
Uniqueid: 1426838514.1
Cause: 16


[Mar 20 09:02:00] DEBUG[29084][C-00000001] sig_pri.c: sig_pri_hangup 2
[Mar 20 09:02:00] DEBUG[29084][C-00000001] sig_pri.c: Channel 'DAHDI/i1/4989xxxxxxxxx-2' MOH-Event: SIG_PRI_MOH_EVENT_RESET in state SIG_PRI_MOH_STATE_IDLE
[Mar 20 09:02:00] DEBUG[29084][C-00000001] sig_pri.c: Channel 'DAHDI/i1/4989xxxxxxxxx-2'  MOH-Next-State: $
[Mar 20 09:02:00] DEBUG[29084][C-00000001] sig_pri.c: Not yet hungup...  Calling hangup with cause 16, and clearing call
[Mar 20 09:02:00] VERBOSE[29084] chan_dahdi.c: PRI Span: 1 q931.c:7151 q931_hangup: Hangup other cref:20682
[Mar 20 09:02:00] VERBOSE[29084] chan_dahdi.c: PRI Span: 1 q931.c:6908 __q931_hangup: ourstate Disconnect Indication, peerstate Disconnect Request, hold-state Idle
[Mar 20 09:02:00] VERBOSE[29084] chan_dahdi.c: PRI Span: 1 q931.c:5946 q931_release: Call 20682 enters state 19 (Release Request).  Hold state: Idle
[Mar 20 09:02:00] VERBOSE[29084] chan_dahdi.c: PRI Span: 1 
[Mar 20 09:02:00] VERBOSE[29084] chan_dahdi.c: PRI Span: 1 > DL-DATA request
[Mar 20 09:02:00] VERBOSE[29084] chan_dahdi.c: PRI Span: 1 > Protocol Discriminator: Q.931 (8)  len=9
[Mar 20 09:02:00] VERBOSE[29084] chan_dahdi.c: PRI Span: 1 > TEI=0 Call Ref: len= 2 (reference 20682/0x50CA) (Sent to originator)
[Mar 20 09:02:00] VERBOSE[29084] chan_dahdi.c: PRI Span: 1 > Message Type: RELEASE (77)
[Mar 20 09:02:00] VERBOSE[29084] chan_dahdi.c: PRI Span: 1 TEI=0 Transmitting N(S)=6, window is open V(A)=6 K=7
[Mar 20 09:02:00] VERBOSE[29084] chan_dahdi.c: PRI Span: 1 
[Mar 20 09:02:00] VERBOSE[29084] chan_dahdi.c: PRI Span: 1 > Protocol Discriminator: Q.931 (8)  len=9
[Mar 20 09:02:00] VERBOSE[29084] chan_dahdi.c: PRI Span: 1 > TEI=0 Call Ref: len= 2 (reference 20682/0x50CA) (Sent to originator)
[Mar 20 09:02:00] VERBOSE[29084] chan_dahdi.c: PRI Span: 1 > Message Type: RELEASE (77)
[Mar 20 09:02:00] VERBOSE[29084] chan_dahdi.c: PRI Span: 1 > [08 02 81 90]
[Mar 20 09:02:00] VERBOSE[29084] chan_dahdi.c: PRI Span: 1 > Cause (len= 4) [ Ext: 1  Coding: CCITT (ITU) standard (0)  Spare: 0  Location: Private network serving the local user (1)
[Mar 20 09:02:00] VERBOSE[29084] chan_dahdi.c: PRI Span: 1 >                  Ext: 1  Cause: Normal Clearing (16), class = Normal Event (1) ]
[Mar 20 09:02:00] DEBUG[29084][C-00000001] chan_dahdi.c: Disabled echo cancellation on channel 2
[Mar 20 09:02:00] DEBUG[29084][C-00000001] chan_dahdi.c: Set option TDD MODE, value: OFF(0) on DAHDI/i1/4989xxxxxxxxx-2
[Mar 20 09:02:00] DEBUG[29084][C-00000001] chan_dahdi.c: Updated conferencing on 2, with 0 conference users
[Mar 20 09:02:00] DEBUG[29084][C-00000001] chan_dahdi.c: Set option AUDIO MODE, value: OFF(0) on DAHDI/i1/4989xxxxxxxxx-2
[Mar 20 09:02:00] VERBOSE[29084][C-00000001] chan_dahdi.c:     -- Hungup 'DAHDI/i1/4989xxxxxxxxx-2'
[Mar 20 09:02:00] DEBUG[28696] manager.c: Examining event:
Event: Hangup
Privilege: call,all
Channel: DAHDI/i1/4989xxxxxxxxx-2
Uniqueid: 1426838514.1
CallerIDNum: 4989xxxxxxxxx
CallerIDName: <unknown>
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
AccountCode: 
Cause: 16
Cause-txt: Normal Clearing


[Mar 20 09:02:00] DEBUG[28682] devicestate.c: No provider found, checking channel drivers for DAHDI - i1/4989xxxxxxxxx
[Mar 20 09:02:00] DEBUG[28682] devicestate.c: Changing state for DAHDI/i1/4989xxxxxxxxx - state 0 (Unknown)
[Mar 20 09:02:00] DEBUG[28682] devicestate.c: device 'DAHDI/i1/4989xxxxxxxxx' state '0'
[Mar 20 09:02:00] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 
[Mar 20 09:02:00] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 < Protocol Discriminator: Q.931 (8)  len=5
[Mar 20 09:02:00] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 < TEI=0 Call Ref: len= 2 (reference 20682/0x50CA) (Sent from originator)
[Mar 20 09:02:00] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 < Message Type: RELEASE COMPLETE (90)
[Mar 20 09:02:00] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 Received message for call 0x7fe9f4024350 on link 0x2c36780 TEI/SAPI 0/0
[Mar 20 09:02:00] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 q931.c:8959 post_handle_q931_message: Call 20682 enters state 0 (Null).  Hold state: Idle
[Mar 20 09:02:00] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 q931.c:7151 q931_hangup: Hangup other cref:20682
[Mar 20 09:02:00] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 q931.c:6908 __q931_hangup: ourstate Null, peerstate Null, hold-state Idle
[Mar 20 09:02:00] VERBOSE[28690] chan_dahdi.c: PRI Span: 1 Destroying call 0x7fe9f4024350, ourstate Null, peerstate Null, hold-state Idle
[Mar 20 09:02:00] VERBOSE[28690] sig_pri.c: Span 1: Processing event PRI_EVENT_HANGUP_ACK(9)
[Mar 20 09:03:01] VERBOSE[29083] asterisk.c:     -- Remote UNIX connection disconnected