[Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: TEI: 0 State 7 [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: V(S) 102 V(A) 102 V(R) 115 [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: K 7, RC 0, l3initiated 0, reject_except 0 ack_pend 0 [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: T200 0, N200 3, T203 1 [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: < [ 00 01 e6 cc 08 02 52 50 05 04 03 80 90 a3 18 03 a9 83 9f 6c 0a 21 81 34 35 36 38 30 33 31 32 70 0b 80 30 32 37 31 32 33 34 35 36 37 ] [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: < Informational frame: [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: < SAPI: 00 C/R: 0 EA: 0 [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: < TEI: 000 EA: 1 [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: < N(S): 115 0: 0 [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: < N(R): 102 P: 0 [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: < 40 bytes of data [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: < Protocol Discriminator: Q.931 (8) len=40 [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: < Call Ref: len= 2 (reference 21072/0x5250) (Originator) [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: < Message Type: SETUP (5) [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: < [04 03 80 90 a3] [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: < Bearer Capability (len= 5) [ Ext: 1 Q.931 Std: 0 Info transfer capability: Speech (0) [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: < Ext: 1 Trans mode/rate: 64kbps, circuit-mode (16) [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: < User information layer 1: A-Law (35) [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: < [18 03 a9 83 9f] [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: < Channel ID (len= 5) [ Ext: 1 IntID: Implicit Other(PRI) Spare: 0 Exclusive Dchan: 0 [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: < ChanSel: As indicated in following octets [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: < Ext: 1 Coding: 0 Number Specified Channel Type: 3 [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: < Ext: 1 Channel: 31 Type: NET] [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: < [6c 0a 21 81 34 35 36 38 30 33 31 32] [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: < Calling Number (len=12) [ Ext: 0 TON: National Number (2) NPI: ISDN/Telephony Numbering Plan (E.164/E.163) (1) [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: < Presentation: Presentation permitted, user number passed network screening (1) '45680312' ] [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: < [70 0b 80 30 32 37 31 32 33 34 35 36 37] [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: < Called Number (len=13) [ Ext: 1 TON: Unknown Number Type (0) NPI: Unknown Number Plan (0) '0271234567' ] [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: -- Making new call for cr 21072 [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: Received message for call 0xb6591340 on 0x9641cf8 TEI/SAPI 0/0, call->pri is 0x9641cf8 TEI/SAPI 0/0 [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: -- Processing Q.931 Call Setup [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: -- Processing IE 4 (cs0, Bearer Capability) [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: -- Processing IE 24 (cs0, Channel Identification) [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: -- Processing IE 108 (cs0, Calling Party Number) [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: -- Processing IE 112 (cs0, Called Party Number) [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: q931.c:6611 post_handle_q931_message: Call 21072 enters state 6 (Call Present). Hold state: Idle [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: ALEC Fill Ring Event on channel=31, newcr=21072, flexible=0 [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: -- ACKing all packets from 102 to (but not including) 102 [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: -- T200 requested to stop when not started [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: T203 requested to start without stopping first [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: -- Starting T203 timer [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: Sending Receiver Ready (116) [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: TEI: 0 State 7 [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: V(S) 102 V(A) 102 V(R) 116 [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: K 7, RC 0, l3initiated 0, reject_except 0 ack_pend 0 [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: T200 0, N200 3, T203 1 [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: > [ 00 01 01 e8 ] [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: > Supervisory frame: [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: > SAPI: 00 C/R: 0 EA: 0 [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: > TEI: 000 EA: 1 [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: > Zero: 0 S: 0 01: 1 [ RR (receive ready) ] [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: > N(R): 116 P/F: 0 [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: > 0 bytes of data [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: Handling message for SAPI/TEI=0/0 [Feb 8 22:01:36] WARNING[16867] chan_dahdi.c: ALEC PRI_EVENT_RING channel 0/31, span 2 [Feb 8 22:01:36] WARNING[16867] chan_dahdi.c: ALEC SETUP requested on channel 0/31, span 2 [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: q931.c:4379 q931_setup_ack: Call 21072 enters state 25 (Overlap Receiving). Hold state: Idle [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: -- Finally transmitting 0, since window opened up (7) [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: TEI: 0 State 7 [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: V(S) 102 V(A) 102 V(R) 116 [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: K 7, RC 0, l3initiated 0, reject_except 0 ack_pend 0 [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: T200 0, N200 3, T203 1 [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: > [ 02 01 cc e8 08 02 d2 50 0d 18 03 a9 83 9f 1e 02 81 82 ] [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: > Informational frame: [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: > SAPI: 00 C/R: 1 EA: 0 [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: > TEI: 000 EA: 1 [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: > N(S): 102 0: 0 [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: > N(R): 116 P: 0 [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: > 14 bytes of data [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: -- Stopping T203 timer [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: -- Starting T200 timer [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: > Protocol Discriminator: Q.931 (8) len=14 [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: > Call Ref: len= 2 (reference 21072/0x5250) (Terminator) [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: > Message Type: SETUP ACKNOWLEDGE (13) [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: > [18 03 a9 83 9f] [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: > Channel ID (len= 5) [ Ext: 1 IntID: Implicit Other(PRI) Spare: 0 Exclusive Dchan: 0 [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: > ChanSel: As indicated in following octets [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: > Ext: 1 Coding: 0 Number Specified Channel Type: 3 [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: > Ext: 1 Channel: 31 Type: NET] [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: > [1e 02 81 82] [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: > Progress Indicator (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) 0: 0 Location: Private network serving the local user (1) [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: > Ext: 1 Progress Description: Called equipment is non-ISDN. (2) ] [Feb 8 22:01:36] DEBUG[16867] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [Feb 8 22:01:36] DEBUG[16867] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [Feb 8 22:01:36] DEBUG[16867] devicestate.c: device 'DAHDI/62-1' state '2' [Feb 8 22:01:36] DEBUG[16863] app_queue.c: Device 'DAHDI/62-1' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 8 22:01:36] VERBOSE[2243] chan_dahdi.c: -- Starting simple switch on 'DAHDI/62-1' [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: -- Accepting overlap call from '45680312' to '0271234567' on channel 0/31, span 2 [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: TEI: 0 State 7 [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: V(S) 103 V(A) 102 V(R) 116 [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: K 7, RC 0, l3initiated 0, reject_except 0 ack_pend 0 [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: T200 1, N200 3, T203 0 [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: < [ 02 01 01 ce ] [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: < Supervisory frame: [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: < SAPI: 00 C/R: 1 EA: 0 [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: < TEI: 000 EA: 1 [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: < Zero: 0 S: 0 01: 1 [ RR (receive ready) ] [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: < N(R): 103 P/F: 0 [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: < 0 bytes of data [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: -- ACKing all packets from 102 to (but not including) 103 [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: -- ACKing packet 102, new txqueue is -1 (-1 means empty) [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: -- Stopping T200 timer [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: -- Starting T203 timer [Feb 8 22:01:36] VERBOSE[16867] chan_dahdi.c: Handling message for SAPI/TEI=0/0 [Feb 8 22:01:39] DEBUG[2243] chan_dahdi.c: Enabled echo cancellation on channel 62 [Feb 8 22:01:39] DEBUG[2243] pbx.c: Launching 'Macro' [Feb 8 22:01:39] DEBUG[16856] devicestate.c: No provider found, checking channel drivers for DAHDI - 62 [Feb 8 22:01:39] VERBOSE[2243] pbx.c: -- Executing [0271234567@incoming:1] Macro("DAHDI/62-1", "callmobile,0271234567") in new stack [Feb 8 22:01:39] DEBUG[16856] devicestate.c: Changing state for DAHDI/62 - state 2 (In use) [Feb 8 22:01:39] DEBUG[16856] devicestate.c: device 'DAHDI/62' state '2' [Feb 8 22:01:39] DEBUG[2243] pbx.c: Launching 'NoOp' [Feb 8 22:01:39] VERBOSE[2243] pbx.c: -- Executing [s@macro-callmobile:1] NoOp("DAHDI/62-1", "****** Call Mobile called=0271234567 context=incoming ******") in new stack [Feb 8 22:01:39] DEBUG[2243] app_macro.c: Executed application: NoOp [Feb 8 22:01:39] DEBUG[2243] pbx.c: Launching 'MYSQL' [Feb 8 22:01:39] VERBOSE[2243] pbx.c: -- Executing [s@macro-callmobile:2] MYSQL("DAHDI/62-1", "Connect connid localhost database user password") in new stack [Feb 8 22:01:39] DEBUG[16863] app_queue.c: Device 'DAHDI/62' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 8 22:01:39] DEBUG[2243] app_macro.c: Executed application: MYSQL [Feb 8 22:01:39] DEBUG[2243] pbx.c: Function result is '45680312' [Feb 8 22:01:39] DEBUG[2243] pbx.c: Function result is '' [Feb 8 22:01:39] DEBUG[2243] pbx.c: Launching 'MYSQL' [Feb 8 22:01:39] VERBOSE[2243] pbx.c: -- Executing [s@macro-callmobile:3] MYSQL("DAHDI/62-1", "Query resultid 1 call pbx_callerid('45680312','0271234567','')") in new stack [Feb 8 22:01:39] DEBUG[2243] app_macro.c: Executed application: MYSQL [Feb 8 22:01:39] DEBUG[2243] pbx.c: Launching 'MYSQL' [Feb 8 22:01:39] VERBOSE[2243] pbx.c: -- Executing [s@macro-callmobile:4] MYSQL("DAHDI/62-1", "Fetch fetchid 2 prefix calleridnum calleridname dialing ringtone") in new stack [Feb 8 22:01:39] DEBUG[2243] app_macro.c: Executed application: MYSQL [Feb 8 22:01:39] DEBUG[2243] pbx.c: Launching 'MYSQL' [Feb 8 22:01:39] VERBOSE[2243] pbx.c: -- Executing [s@macro-callmobile:5] MYSQL("DAHDI/62-1", "Clear 2") in new stack [Feb 8 22:01:39] DEBUG[2243] app_macro.c: Executed application: MYSQL [Feb 8 22:01:39] DEBUG[2243] pbx.c: Launching 'MYSQL' [Feb 8 22:01:39] VERBOSE[2243] pbx.c: -- Executing [s@macro-callmobile:6] MYSQL("DAHDI/62-1", "Disconnect 1") in new stack [Feb 8 22:01:39] DEBUG[2243] app_macro.c: Executed application: MYSQL [Feb 8 22:01:39] DEBUG[2243] pbx.c: Launching 'Set' [Feb 8 22:01:39] VERBOSE[2243] pbx.c: -- Executing [s@macro-callmobile:7] Set("DAHDI/62-1", "CALLERID(num)=1045680312") in new stack [Feb 8 22:01:39] DEBUG[2243] app_macro.c: Executed application: Set [Feb 8 22:01:39] DEBUG[2243] pbx.c: Function result is '' [Feb 8 22:01:39] DEBUG[2243] pbx.c: Function result is '0' [Feb 8 22:01:39] DEBUG[2243] pbx.c: Expression result is '0' [Feb 8 22:01:39] DEBUG[2243] pbx.c: Launching 'GotoIf' [Feb 8 22:01:39] VERBOSE[2243] pbx.c: -- Executing [s@macro-callmobile:8] GotoIf("DAHDI/62-1", "0?knowcaller") in new stack [Feb 8 22:01:39] DEBUG[2243] pbx.c: Not taking any branch [Feb 8 22:01:39] DEBUG[2243] app_macro.c: Executed application: GotoIf [Feb 8 22:01:39] DEBUG[2243] pbx.c: Launching 'Set' [Feb 8 22:01:39] VERBOSE[2243] pbx.c: -- Executing [s@macro-callmobile:9] Set("DAHDI/62-1", "CALLERID(name)=external") in new stack [Feb 8 22:01:39] DEBUG[2243] app_macro.c: Executed application: Set [Feb 8 22:01:39] DEBUG[2243] pbx.c: Launching 'NoOp' [Feb 8 22:01:39] VERBOSE[2243] pbx.c: -- Executing [s@macro-callmobile:10] NoOp("DAHDI/62-1", "CallMobile: from external 045680312 to 0271234567") in new stack [Feb 8 22:01:39] DEBUG[2243] app_macro.c: Executed application: NoOp [Feb 8 22:01:39] DEBUG[2243] pbx.c: Launching 'MYSQL' [Feb 8 22:01:39] VERBOSE[2243] pbx.c: -- Executing [s@macro-callmobile:11] MYSQL("DAHDI/62-1", "Connect connid localhost database user password") in new stack [Feb 8 22:01:39] DEBUG[2243] app_macro.c: Executed application: MYSQL [Feb 8 22:01:39] DEBUG[2243] pbx.c: Launching 'MYSQL' [Feb 8 22:01:39] VERBOSE[2243] pbx.c: -- Executing [s@macro-callmobile:12] MYSQL("DAHDI/62-1", "Query resultid 1 SELECT number, name, staff FROM mobiles WHERE number=0271234567 ") in new stack [Feb 8 22:01:39] DEBUG[2243] app_macro.c: Executed application: MYSQL [Feb 8 22:01:39] DEBUG[2243] pbx.c: Launching 'MYSQL' [Feb 8 22:01:39] VERBOSE[2243] pbx.c: -- Executing [s@macro-callmobile:13] MYSQL("DAHDI/62-1", "Fetch fetchid 2 number name staff") in new stack [Feb 8 22:01:39] DEBUG[2243] app_macro.c: Executed application: MYSQL [Feb 8 22:01:39] DEBUG[2243] pbx.c: Launching 'MYSQL' [Feb 8 22:01:39] VERBOSE[2243] pbx.c: -- Executing [s@macro-callmobile:14] MYSQL("DAHDI/62-1", "Clear 2") in new stack [Feb 8 22:01:39] DEBUG[2243] app_macro.c: Executed application: MYSQL [Feb 8 22:01:39] DEBUG[2243] pbx.c: Launching 'MYSQL' [Feb 8 22:01:39] VERBOSE[2243] pbx.c: -- Executing [s@macro-callmobile:15] MYSQL("DAHDI/62-1", "Disconnect 1") in new stack [Feb 8 22:01:39] DEBUG[2243] app_macro.c: Executed application: MYSQL [Feb 8 22:01:39] DEBUG[2243] pbx.c: Expression result is '1' [Feb 8 22:01:39] DEBUG[2243] pbx.c: Launching 'GotoIf' [Feb 8 22:01:39] VERBOSE[2243] pbx.c: -- Executing [s@macro-callmobile:16] GotoIf("DAHDI/62-1", "1?nstaff:staff") in new stack [Feb 8 22:01:39] VERBOSE[2243] pbx.c: -- Goto (macro-callmobile,s,48) [Feb 8 22:01:39] DEBUG[2243] app_macro.c: Executed application: GotoIf [Feb 8 22:01:39] DEBUG[2243] pbx.c: Launching 'Verbose' [Feb 8 22:01:39] VERBOSE[2243] pbx.c: -- Executing [s@macro-callmobile:48] Verbose("DAHDI/62-1", "0,****** Call Non Staff Mobile: from external < 045680312 > to < 0271234567 > ******") in new stack [Feb 8 22:01:39] VERBOSE[2243] app_verbose.c: ****** Call Non Staff Mobile: from external < 045680312 > to < 0271234567 > ****** [Feb 8 22:01:39] DEBUG[2243] app_macro.c: Executed application: Verbose [Feb 8 22:01:39] DEBUG[2243] pbx.c: Expression result is '0' [Feb 8 22:01:39] DEBUG[2243] pbx.c: Launching 'GotoIf' [Feb 8 22:01:39] VERBOSE[2243] pbx.c: -- Executing [s@macro-callmobile:49] GotoIf("DAHDI/62-1", "0?nstafftrusted") in new stack [Feb 8 22:01:39] DEBUG[2243] pbx.c: Not taking any branch [Feb 8 22:01:39] DEBUG[2243] app_macro.c: Executed application: GotoIf [Feb 8 22:01:39] DEBUG[2243] pbx.c: Launching 'Progress' [Feb 8 22:01:39] VERBOSE[2243] pbx.c: -- Executing [s@macro-callmobile:50] Progress("DAHDI/62-1", "") in new stack [Feb 8 22:01:39] DEBUG[2243] chan_dahdi.c: Requested indication 14 on channel DAHDI/62-1 [Feb 8 22:01:39] DEBUG[2243] chan_dahdi.c: Received AST_CONTROL_PROGRESS on DAHDI/62-1 [Feb 8 22:01:39] VERBOSE[2243] chan_dahdi.c: -- Finally transmitting 0, since window opened up (7) [Feb 8 22:01:39] VERBOSE[2243] chan_dahdi.c: TEI: 0 State 7 [Feb 8 22:01:39] VERBOSE[2243] chan_dahdi.c: V(S) 103 V(A) 103 V(R) 116 [Feb 8 22:01:39] VERBOSE[2243] chan_dahdi.c: K 7, RC 0, l3initiated 0, reject_except 0 ack_pend 0 [Feb 8 22:01:39] VERBOSE[2243] chan_dahdi.c: T200 0, N200 3, T203 1 [Feb 8 22:01:39] VERBOSE[2243] chan_dahdi.c: [Feb 8 22:01:39] VERBOSE[2243] chan_dahdi.c: > [ 02 01 ce e8 08 02 d2 50 03 1e 02 81 88 ] [Feb 8 22:01:39] VERBOSE[2243] chan_dahdi.c: [Feb 8 22:01:39] VERBOSE[2243] chan_dahdi.c: > Informational frame: [Feb 8 22:01:39] VERBOSE[2243] chan_dahdi.c: > SAPI: 00 C/R: 1 EA: 0 [Feb 8 22:01:39] VERBOSE[2243] chan_dahdi.c: > TEI: 000 EA: 1 [Feb 8 22:01:39] VERBOSE[2243] chan_dahdi.c: > N(S): 103 0: 0 [Feb 8 22:01:39] VERBOSE[2243] chan_dahdi.c: > N(R): 116 P: 0 [Feb 8 22:01:39] VERBOSE[2243] chan_dahdi.c: > 9 bytes of data [Feb 8 22:01:39] VERBOSE[2243] chan_dahdi.c: -- Stopping T203 timer [Feb 8 22:01:39] VERBOSE[2243] chan_dahdi.c: -- Starting T200 timer [Feb 8 22:01:39] VERBOSE[2243] chan_dahdi.c: > Protocol Discriminator: Q.931 (8) len=9 [Feb 8 22:01:39] VERBOSE[2243] chan_dahdi.c: > Call Ref: len= 2 (reference 21072/0x5250) (Terminator) [Feb 8 22:01:39] VERBOSE[2243] chan_dahdi.c: > Message Type: PROGRESS (3) [Feb 8 22:01:39] VERBOSE[2243] chan_dahdi.c: > [1e 02 81 88] [Feb 8 22:01:39] VERBOSE[2243] chan_dahdi.c: > Progress Indicator (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) 0: 0 Location: Private network serving the local user (1) [Feb 8 22:01:39] VERBOSE[2243] chan_dahdi.c: > Ext: 1 Progress Description: Inband information or appropriate pattern now available. (8) ] [Feb 8 22:01:39] DEBUG[2243] app_macro.c: Executed application: Progress [Feb 8 22:01:39] DEBUG[2243] pbx.c: Launching 'BackGround' [Feb 8 22:01:39] VERBOSE[2243] pbx.c: -- Executing [s@macro-callmobile:51] BackGround("DAHDI/62-1", "connecting,n") in new stack [Feb 8 22:01:39] DEBUG[2243] channel.c: Set channel DAHDI/62-1 to write format slin [Feb 8 22:01:39] VERBOSE[16867] chan_dahdi.c: TEI: 0 State 7 [Feb 8 22:01:39] VERBOSE[16867] chan_dahdi.c: V(S) 104 V(A) 103 V(R) 116 [Feb 8 22:01:39] VERBOSE[16867] chan_dahdi.c: K 7, RC 0, l3initiated 0, reject_except 0 ack_pend 0 [Feb 8 22:01:39] VERBOSE[16867] chan_dahdi.c: T200 1, N200 3, T203 0 [Feb 8 22:01:39] VERBOSE[16867] chan_dahdi.c: [Feb 8 22:01:39] VERBOSE[16867] chan_dahdi.c: < [ 02 01 01 d0 ] [Feb 8 22:01:39] VERBOSE[16867] chan_dahdi.c: [Feb 8 22:01:39] VERBOSE[16867] chan_dahdi.c: < Supervisory frame: [Feb 8 22:01:39] VERBOSE[16867] chan_dahdi.c: < SAPI: 00 C/R: 1 EA: 0 [Feb 8 22:01:39] VERBOSE[16867] chan_dahdi.c: < TEI: 000 EA: 1 [Feb 8 22:01:39] VERBOSE[16867] chan_dahdi.c: < Zero: 0 S: 0 01: 1 [ RR (receive ready) ] [Feb 8 22:01:39] VERBOSE[16867] chan_dahdi.c: < N(R): 104 P/F: 0 [Feb 8 22:01:39] VERBOSE[16867] chan_dahdi.c: < 0 bytes of data [Feb 8 22:01:39] VERBOSE[16867] chan_dahdi.c: -- ACKing all packets from 103 to (but not including) 104 [Feb 8 22:01:39] VERBOSE[16867] chan_dahdi.c: -- ACKing packet 103, new txqueue is -1 (-1 means empty) [Feb 8 22:01:39] VERBOSE[16867] chan_dahdi.c: -- Stopping T200 timer [Feb 8 22:01:39] VERBOSE[16867] chan_dahdi.c: -- Starting T203 timer [Feb 8 22:01:39] VERBOSE[16867] chan_dahdi.c: Handling message for SAPI/TEI=0/0 [Feb 8 22:01:39] DEBUG[2243] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Feb 8 22:01:39] VERBOSE[2243] file.c: -- Playing 'connecting.slin' (language 'en') [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: TEI: 0 State 7 [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: V(S) 104 V(A) 104 V(R) 116 [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: K 7, RC 0, l3initiated 0, reject_except 0 ack_pend 0 [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: T200 0, N200 3, T203 1 [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: < [ 00 01 e8 d0 08 02 52 50 05 04 03 80 90 a3 18 03 a9 83 9f 6c 0a 21 81 34 35 36 38 30 33 31 32 70 0b 80 30 32 37 31 32 33 34 35 36 37 ] [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: < Informational frame: [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: < SAPI: 00 C/R: 0 EA: 0 [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: < TEI: 000 EA: 1 [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: < N(S): 116 0: 0 [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: < N(R): 104 P: 0 [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: < 40 bytes of data [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: < Protocol Discriminator: Q.931 (8) len=40 [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: < Call Ref: len= 2 (reference 21072/0x5250) (Originator) [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: < Message Type: SETUP (5) [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: < [04 03 80 90 a3] [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: < Bearer Capability (len= 5) [ Ext: 1 Q.931 Std: 0 Info transfer capability: Speech (0) [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: < Ext: 1 Trans mode/rate: 64kbps, circuit-mode (16) [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: < User information layer 1: A-Law (35) [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: < [18 03 a9 83 9f] [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: < Channel ID (len= 5) [ Ext: 1 IntID: Implicit Other(PRI) Spare: 0 Exclusive Dchan: 0 [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: < ChanSel: As indicated in following octets [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: < Ext: 1 Coding: 0 Number Specified Channel Type: 3 [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: < Ext: 1 Channel: 31 Type: NET] [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: < [6c 0a 21 81 34 35 36 38 30 33 31 32] [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: < Calling Number (len=12) [ Ext: 0 TON: National Number (2) NPI: ISDN/Telephony Numbering Plan (E.164/E.163) (1) [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: < Presentation: Presentation permitted, user number passed network screening (1) '45680312' ] [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: < [70 0b 80 30 32 37 31 32 33 34 35 36 37] [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: < Called Number (len=13) [ Ext: 1 TON: Unknown Number Type (0) NPI: Unknown Number Plan (0) '0271234567' ] [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: Received message for call 0xb6591340 on 0x9641cf8 TEI/SAPI 0/0, call->pri is 0x9641cf8 TEI/SAPI 0/0 [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: -- Processing Q.931 Call Setup [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: -- Processing IE 4 (cs0, Bearer Capability) [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: -- Processing IE 24 (cs0, Channel Identification) [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: -- Processing IE 108 (cs0, Calling Party Number) [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: -- Processing IE 112 (cs0, Called Party Number) [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: ALEC Not new call on channel=31, oldcr=1 newcr=21072 [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: -- ACKing all packets from 104 to (but not including) 104 [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: -- T200 requested to stop when not started [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: T203 requested to start without stopping first [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: -- Starting T203 timer [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: Sending Receiver Ready (117) [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: TEI: 0 State 7 [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: V(S) 104 V(A) 104 V(R) 117 [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: K 7, RC 0, l3initiated 0, reject_except 0 ack_pend 0 [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: T200 0, N200 3, T203 1 [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: > [ 00 01 01 ea ] [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: > Supervisory frame: [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: > SAPI: 00 C/R: 0 EA: 0 [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: > TEI: 000 EA: 1 [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: > Zero: 0 S: 0 01: 1 [ RR (receive ready) ] [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: > N(R): 117 P/F: 0 [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: > 0 bytes of data [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: Handling message for SAPI/TEI=0/0 [Feb 8 22:01:40] DEBUG[2243] channel.c: Scheduling timer at (58 requested / 58 actual) timer ticks per second [Feb 8 22:01:40] DEBUG[2243] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Feb 8 22:01:40] DEBUG[2243] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Feb 8 22:01:40] DEBUG[2243] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Feb 8 22:01:40] DEBUG[2243] channel.c: Set channel DAHDI/62-1 to write format alaw [Feb 8 22:01:40] DEBUG[2243] app_macro.c: Executed application: Background [Feb 8 22:01:40] DEBUG[2243] pbx.c: Launching 'Congestion' [Feb 8 22:01:40] VERBOSE[2243] pbx.c: -- Executing [s@macro-callmobile:52] Congestion("DAHDI/62-1", "0") in new stack [Feb 8 22:01:40] DEBUG[2243] chan_dahdi.c: Requested indication 8 on channel DAHDI/62-1 [Feb 8 22:01:40] DEBUG[16856] devicestate.c: No provider found, checking channel drivers for DAHDI - 62 [Feb 8 22:01:40] DEBUG[16856] devicestate.c: Changing state for DAHDI/62 - state 2 (In use) [Feb 8 22:01:40] DEBUG[16856] devicestate.c: device 'DAHDI/62' state '2' [Feb 8 22:01:40] DEBUG[16863] app_queue.c: Device 'DAHDI/62' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 8 22:01:40] DEBUG[2243] app_macro.c: Spawn extension (macro-callmobile,s,52) exited non-zero on 'DAHDI/62-1' in macro 'callmobile' [Feb 8 22:01:40] VERBOSE[2243] app_macro.c: == Spawn extension (macro-callmobile, s, 52) exited non-zero on 'DAHDI/62-1' in macro 'callmobile' [Feb 8 22:01:40] DEBUG[2243] pbx.c: Spawn extension (incoming,0271234567,1) exited non-zero on 'DAHDI/62-1' [Feb 8 22:01:40] VERBOSE[2243] pbx.c: == Spawn extension (incoming, 0271234567, 1) exited non-zero on 'DAHDI/62-1' [Feb 8 22:01:40] DEBUG[2243] channel.c: Soft-Hanging up channel 'DAHDI/62-1' [Feb 8 22:01:40] DEBUG[2243] channel.c: Hanging up channel 'DAHDI/62-1' [Feb 8 22:01:40] DEBUG[2243] chan_dahdi.c: dahdi_hangup(DAHDI/62-1) [Feb 8 22:01:40] DEBUG[2243] chan_dahdi.c: Set option AUDIO MODE, value: ON(1) on DAHDI/62-1 [Feb 8 22:01:40] DEBUG[2243] chan_dahdi.c: Hangup: channel: 62 index = 0, normal = 72, callwait = -1, thirdcall = -1 [Feb 8 22:01:40] DEBUG[2243] chan_dahdi.c: Not yet hungup... Calling hangup once with icause, and clearing call [Feb 8 22:01:40] VERBOSE[2243] chan_dahdi.c: q931_hangup: other hangup [Feb 8 22:01:40] VERBOSE[2243] chan_dahdi.c: NEW_HANGUP DEBUG: Calling q931_hangup, ourstate Overlap Receiving, peerstate Overlap Sending, hold-state Idle [Feb 8 22:01:40] VERBOSE[2243] chan_dahdi.c: q931.c:4768 q931_release_complete: Call 21072 enters state 0 (Null). Hold state: Idle [Feb 8 22:01:40] VERBOSE[2243] chan_dahdi.c: -- Finally transmitting 0, since window opened up (7) [Feb 8 22:01:40] VERBOSE[2243] chan_dahdi.c: TEI: 0 State 7 [Feb 8 22:01:40] VERBOSE[2243] chan_dahdi.c: V(S) 104 V(A) 104 V(R) 117 [Feb 8 22:01:40] VERBOSE[2243] chan_dahdi.c: K 7, RC 0, l3initiated 0, reject_except 0 ack_pend 0 [Feb 8 22:01:40] VERBOSE[2243] chan_dahdi.c: T200 0, N200 3, T203 1 [Feb 8 22:01:40] VERBOSE[2243] chan_dahdi.c: [Feb 8 22:01:40] VERBOSE[2243] chan_dahdi.c: > [ 02 01 d0 ea 08 02 d2 50 5a 08 02 81 a2 ] [Feb 8 22:01:40] VERBOSE[2243] chan_dahdi.c: [Feb 8 22:01:40] VERBOSE[2243] chan_dahdi.c: > Informational frame: [Feb 8 22:01:40] VERBOSE[2243] chan_dahdi.c: > SAPI: 00 C/R: 1 EA: 0 [Feb 8 22:01:40] VERBOSE[2243] chan_dahdi.c: > TEI: 000 EA: 1 [Feb 8 22:01:40] VERBOSE[2243] chan_dahdi.c: > N(S): 104 0: 0 [Feb 8 22:01:40] VERBOSE[2243] chan_dahdi.c: > N(R): 117 P: 0 [Feb 8 22:01:40] VERBOSE[2243] chan_dahdi.c: > 9 bytes of data [Feb 8 22:01:40] VERBOSE[2243] chan_dahdi.c: -- Stopping T203 timer [Feb 8 22:01:40] VERBOSE[2243] chan_dahdi.c: -- Starting T200 timer [Feb 8 22:01:40] VERBOSE[2243] chan_dahdi.c: > Protocol Discriminator: Q.931 (8) len=9 [Feb 8 22:01:40] VERBOSE[2243] chan_dahdi.c: > Call Ref: len= 2 (reference 21072/0x5250) (Terminator) [Feb 8 22:01:40] VERBOSE[2243] chan_dahdi.c: > Message Type: RELEASE COMPLETE (90) [Feb 8 22:01:40] VERBOSE[2243] chan_dahdi.c: > [08 02 81 a2] [Feb 8 22:01:40] VERBOSE[2243] chan_dahdi.c: > Cause (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) Spare: 0 Location: Private network serving the local user (1) [Feb 8 22:01:40] VERBOSE[2243] chan_dahdi.c: > Ext: 1 Cause: Circuit/channel congestion (34), class = Network Congestion (resource unavailable) (2) ] [Feb 8 22:01:40] VERBOSE[2243] chan_dahdi.c: q931_hangup: other hangup [Feb 8 22:01:40] VERBOSE[2243] chan_dahdi.c: NEW_HANGUP DEBUG: Calling q931_hangup, ourstate Null, peerstate Null, hold-state Idle [Feb 8 22:01:40] VERBOSE[2243] chan_dahdi.c: NEW_HANGUP DEBUG: Destroying the call, ourstate Null, peerstate Null, hold-state Idle [Feb 8 22:01:40] DEBUG[2243] chan_dahdi.c: Disabled echo cancellation on channel 62 [Feb 8 22:01:40] DEBUG[2243] chan_dahdi.c: Set option TDD MODE, value: OFF(0) on DAHDI/62-1 [Feb 8 22:01:40] DEBUG[2243] chan_dahdi.c: Updated conferencing on 62, with 0 conference users [Feb 8 22:01:40] DEBUG[2243] chan_dahdi.c: Set option AUDIO MODE, value: OFF(0) on DAHDI/62-1 [Feb 8 22:01:40] VERBOSE[2243] chan_dahdi.c: -- Hungup 'DAHDI/62-1' [Feb 8 22:01:40] DEBUG[16856] devicestate.c: No provider found, checking channel drivers for DAHDI - 62 [Feb 8 22:01:40] DEBUG[16856] devicestate.c: Changing state for DAHDI/62 - state 0 (Unknown) [Feb 8 22:01:40] DEBUG[16856] devicestate.c: device 'DAHDI/62' state '0' [Feb 8 22:01:40] DEBUG[16863] app_queue.c: Device 'DAHDI/62' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: TEI: 0 State 7 [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: V(S) 105 V(A) 104 V(R) 117 [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: K 7, RC 0, l3initiated 0, reject_except 0 ack_pend 0 [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: T200 1, N200 3, T203 0 [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: < [ 02 01 01 d2 ] [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: < Supervisory frame: [Feb 8 22:01:40] VERBOSE[16867] chan_dahdi.c: < SAPI: 00 C/R: 1 EA: 0