CASE 2: No Hangup request received from operator. CLI: 3447471673 Call Ref: 22322 Channel: Zap/110-1 [Jan 9 19:24:39] VERBOSE[4729] logger.c: -- ACKing all packets from 106 to (but not including) 107 [Jan 9 19:24:39] VERBOSE[4729] logger.c: -- Since there was nothing left, stopping T200 counter [Jan 9 19:24:39] VERBOSE[4729] logger.c: -- Stopping T203 counter since we got an ACK [Jan 9 19:24:39] VERBOSE[4729] logger.c: -- Nothing left, starting T203 counter [Jan 9 19:24:39] VERBOSE[4729] logger.c: < Protocol Discriminator: Q.931 (8) len=47 [Jan 9 19:24:39] VERBOSE[4729] logger.c: < Call Ref: len= 2 (reference 22322/0x5732) (Originator) [Jan 9 19:24:39] VERBOSE[4729] logger.c: < Message type: SETUP (5) [Jan 9 19:24:39] VERBOSE[4729] logger.c: < [a1] [Jan 9 19:24:39] VERBOSE[4729] logger.c: < Sending Complete (len= 1) [Jan 9 19:24:39] VERBOSE[4729] logger.c: < [04 03 80 90 a3] [Jan 9 19:24:39] VERBOSE[4729] logger.c: < Bearer Capability (len= 5) [ Ext: 1 Q.931 Std: 0 Info transfer capability: Speech (0) [Jan 9 19:24:39] VERBOSE[4729] logger.c: < Ext: 1 Trans mode/rate: 64kbps, circuit-mode (16) [Jan 9 19:24:39] VERBOSE[4729] logger.c: < Ext: 1 User information layer 1: A-Law (35) [Jan 9 19:24:39] VERBOSE[4729] logger.c: < [18 03 a9 83 91] [Jan 9 19:24:39] VERBOSE[4729] logger.c: < Channel ID (len= 5) [ Ext: 1 IntID: Implicit PRI Spare: 0 Exclusive Dchan: 0 [Jan 9 19:24:39] VERBOSE[4729] logger.c: < ChanSel: Reserved [Jan 9 19:24:39] VERBOSE[4729] logger.c: < Ext: 1 Coding: 0 Number Specified Channel Type: 3 [Jan 9 19:24:39] VERBOSE[4729] logger.c: < Ext: 1 Channel: 17 ] [Jan 9 19:24:39] VERBOSE[4729] logger.c: < [6c 0c 21 83 33 34 34 37 34 37 31 36 37 33] [Jan 9 19:24:39] VERBOSE[4729] logger.c: < Calling Number (len=14) [ Ext: 0 TON: National Number (2) NPI: ISDN/Telephony Numbering Plan (E.164/E.163) (1) [Jan 9 19:24:39] VERBOSE[4729] logger.c: < Presentation: Presentation allowed of network provided number (3) '3447471673' ] [Jan 9 19:24:39] VERBOSE[4729] logger.c: < [70 0b 81 34 35 35 34 39 30 30 34 34 34] [Jan 9 19:24:39] VERBOSE[4729] logger.c: < Called Number (len=13) [ Ext: 1 TON: Unknown Number Type (0) NPI: ISDN/Telephony Numbering Plan (E.164/E.163) (1) '4554900444' ] [Jan 9 19:24:39] VERBOSE[4729] logger.c: < [7d 02 91 81] [Jan 9 19:24:39] VERBOSE[4729] logger.c: < IE: High-layer Compatibility (len = 4) [Jan 9 19:24:39] VERBOSE[4729] logger.c: -- Making new call for cr 22322 [Jan 9 19:24:39] VERBOSE[4729] logger.c: -- Processing Q.931 Call Setup [Jan 9 19:24:39] VERBOSE[4729] logger.c: -- Processing IE 161 (cs0, Sending Complete) [Jan 9 19:24:39] VERBOSE[4729] logger.c: -- Processing IE 4 (cs0, Bearer Capability) [Jan 9 19:24:39] VERBOSE[4729] logger.c: -- Processing IE 24 (cs0, Channel Identification) [Jan 9 19:24:39] VERBOSE[4729] logger.c: -- Processing IE 108 (cs0, Calling Party Number) [Jan 9 19:24:39] VERBOSE[4729] logger.c: -- Processing IE 112 (cs0, Called Party Number) [Jan 9 19:24:39] VERBOSE[4729] logger.c: -- Processing IE 125 (cs0, High-layer Compatibility) [Jan 9 19:24:39] VERBOSE[4729] logger.c: q931.c:3298 q931_receive: call 22322 on channel 17 enters state 6 (Call Present) [Jan 9 19:24:39] VERBOSE[4729] logger.c: Sending Receiver Ready (106) [Jan 9 19:24:39] VERBOSE[4729] logger.c: > [ 02 01 01 d4 ] [Jan 9 19:24:39] VERBOSE[4729] logger.c: > Supervisory frame: [Jan 9 19:24:39] VERBOSE[4729] logger.c: > SAPI: 00 C/R: 1 EA: 0 > TEI: 000 EA: 1 [Jan 9 19:24:39] VERBOSE[4729] logger.c: > Zero: 0 S: 0 01: 1 [ RR (receive ready) ] > N(R): 106 P/F: 0 > 0 bytes of data [Jan 9 19:24:39] VERBOSE[4729] logger.c: -- Restarting T203 counter [Jan 9 19:24:39] VERBOSE[4729] logger.c: -- Restarting T203 counter [Jan 9 19:24:39] VERBOSE[4729] logger.c: q931.c:2571 q931_call_proceeding: call 22322 on channel 17 enters state 9 (Incoming Call Proceeding) [Jan 9 19:24:39] VERBOSE[4729] logger.c: > [ 00 01 d6 d4 08 02 d7 32 02 18 03 a9 83 91 ] [Jan 9 19:24:39] VERBOSE[4729] logger.c: > Informational frame: [Jan 9 19:24:39] VERBOSE[4729] logger.c: > SAPI: 00 C/R: 0 EA: 0 > TEI: 000 EA: 1 [Jan 9 19:24:39] VERBOSE[4729] logger.c: > N(S): 107 0: 0 > N(R): 106 P: 0 > 10 bytes of data [Jan 9 19:24:39] VERBOSE[4729] logger.c: -- Restarting T203 counter [Jan 9 19:24:39] VERBOSE[4729] logger.c: Stopping T_203 timer [Jan 9 19:24:39] VERBOSE[4729] logger.c: Starting T_200 timer [Jan 9 19:24:39] VERBOSE[4729] logger.c: > Protocol Discriminator: Q.931 (8) len=10 [Jan 9 19:24:39] VERBOSE[4729] logger.c: > Call Ref: len= 2 (reference 22322/0x5732) (Terminator) [Jan 9 19:24:39] VERBOSE[4729] logger.c: > Message type: CALL PROCEEDING (2) [Jan 9 19:24:39] VERBOSE[4729] logger.c: > [18 03 a9 83 91] [Jan 9 19:24:39] VERBOSE[4729] logger.c: > Channel ID (len= 5) [ Ext: 1 IntID: Implicit PRI Spare: 0 Exclusive Dchan: 0 [Jan 9 19:24:39] VERBOSE[4729] logger.c: > ChanSel: Reserved [Jan 9 19:24:39] VERBOSE[4729] logger.c: > Ext: 1 Coding: 0 Number Specified Channel Type: 3 [Jan 9 19:24:39] VERBOSE[4729] logger.c: > Ext: 1 Channel: 17 ] [Jan 9 19:24:39] VERBOSE[4729] logger.c: -- Accepting call from '3447471673' to '4554900444' on channel 0/17, span 5 [Jan 9 19:24:39] VERBOSE[26960] logger.c: -- Executing [4554900444@default:1] Set("Zap/110-1", "__DEST=444") in new stack [Jan 9 19:24:39] VERBOSE[26960] logger.c: -- Executing [4554900444@default:2] SetCDRUserField("Zap/110-1", "444") in new stack [Jan 9 19:24:39] VERBOSE[26960] logger.c: -- Executing [4554900444@default:3] Goto("Zap/110-1", "MUSIC_STATION1|s|1") in new stack [Jan 9 19:24:39] VERBOSE[26960] logger.c: -- Goto (MUSIC_STATION1,s,1) [Jan 9 19:24:39] VERBOSE[26960] logger.c: -- Executing [s@MUSIC_STATION1:1] Answer("Zap/110-1", "") in new stack [Jan 9 19:24:39] VERBOSE[26960] logger.c: q931.c:2700 q931_connect: call 22322 on channel 17 enters state 8 (Connect Request) [Jan 9 19:24:39] VERBOSE[26960] logger.c: > [ 00 01 d8 d4 08 02 d7 32 07 18 03 a9 83 91 1e 02 81 82 ] [Jan 9 19:24:39] VERBOSE[26960] logger.c: > Informational frame: [Jan 9 19:24:39] VERBOSE[26960] logger.c: > SAPI: 00 C/R: 0 EA: 0 > TEI: 000 EA: 1 [Jan 9 19:24:39] VERBOSE[26960] logger.c: > N(S): 108 0: 0 > N(R): 106 P: 0 > 14 bytes of data [Jan 9 19:24:39] VERBOSE[26960] logger.c: T_200 timer already going (2) [Jan 9 19:24:39] VERBOSE[26960] logger.c: > Protocol Discriminator: Q.931 (8) len=14 [Jan 9 19:24:39] VERBOSE[26960] logger.c: > Call Ref: len= 2 (reference 22322/0x5732) (Terminator) [Jan 9 19:24:39] VERBOSE[26960] logger.c: > Message type: CONNECT (7) [Jan 9 19:24:39] VERBOSE[26960] logger.c: > [18 03 a9 83 91] [Jan 9 19:24:39] VERBOSE[26960] logger.c: > Channel ID (len= 5) [ Ext: 1 IntID: Implicit PRI Spare: 0 Exclusive Dchan: 0 [Jan 9 19:24:39] VERBOSE[26960] logger.c: > ChanSel: Reserved [Jan 9 19:24:39] VERBOSE[26960] logger.c: > Ext: 1 Coding: 0 Number Specified Channel Type: 3 [Jan 9 19:24:39] VERBOSE[26960] logger.c: > Ext: 1 Channel: 17 ] [Jan 9 19:24:39] VERBOSE[26960] logger.c: > [1e 02 81 82] [Jan 9 19:24:39] VERBOSE[26960] logger.c: > Progress Indicator (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) 0: 0 Location: Private network serving the local user (1) [Jan 9 19:24:39] VERBOSE[26960] logger.c: > Ext: 1 Progress Description: Called equipment is non-ISDN. (2) ] [Jan 9 19:24:39] VERBOSE[26960] logger.c: -- Executing [s@MUSIC_STATION1:2] Set("Zap/110-1", "__DB_USER_ID=1199888679") in new stack [Jan 9 19:24:39] VERBOSE[26960] logger.c: -- Executing [s@MUSIC_STATION1:3] Set("Zap/110-1", "__DB_CLI=3447471673") in new stack [Jan 9 19:24:39] VERBOSE[26960] logger.c: -- Executing [s@MUSIC_STATION1:4] Playback("Zap/110-1", "/efclub/prompts/music/music_welcome") in new stack [Jan 9 19:24:39] VERBOSE[4729] logger.c: < [ 00 01 01 d8 ] [Jan 9 19:24:39] VERBOSE[4729] logger.c: < Supervisory frame: [Jan 9 19:24:39] VERBOSE[4729] logger.c: < SAPI: 00 C/R: 0 EA: 0 < TEI: 000 EA: 1 [Jan 9 19:24:39] VERBOSE[4729] logger.c: < Zero: 0 S: 0 01: 1 [ RR (receive ready) ] < N(R): 108 P/F: 0 < 0 bytes of data [Jan 9 19:24:39] VERBOSE[4729] logger.c: -- ACKing all packets from 106 to (but not including) 108 [Jan 9 19:24:39] VERBOSE[4729] logger.c: -- ACKing packet 107, new txqueue is 108 (-1 means empty) [Jan 9 19:24:39] VERBOSE[4729] logger.c: -- Something left to transmit (108), restarting T200 counter [Jan 9 19:24:39] VERBOSE[26960] logger.c: -- Playing '/efclub/prompts/music/music_welcome' (language 'en') [Jan 9 19:24:39] VERBOSE[4729] logger.c: < [ 00 01 01 da ] [Jan 9 19:24:39] VERBOSE[4729] logger.c: < Supervisory frame: [Jan 9 19:24:39] VERBOSE[4729] logger.c: < SAPI: 00 C/R: 0 EA: 0 < TEI: 000 EA: 1 [Jan 9 19:24:39] VERBOSE[4729] logger.c: < Zero: 0 S: 0 01: 1 [ RR (receive ready) ] < N(R): 109 P/F: 0 < 0 bytes of data [Jan 9 19:24:39] VERBOSE[4729] logger.c: -- ACKing all packets from 107 to (but not including) 109 [Jan 9 19:24:39] VERBOSE[4729] logger.c: -- ACKing packet 108, new txqueue is -1 (-1 means empty) [Jan 9 19:24:39] VERBOSE[4729] logger.c: -- Since there was nothing left, stopping T200 counter [Jan 9 19:24:39] VERBOSE[4729] logger.c: -- Nothing left, starting T203 counter [Jan 9 19:24:39] VERBOSE[4729] logger.c: -- Restarting T203 counter [Jan 9 19:24:39] VERBOSE[4729] logger.c: < [ 02 01 d4 da 08 02 57 32 0f ] [Jan 9 19:24:39] VERBOSE[4729] logger.c: < Informational frame: [Jan 9 19:24:39] VERBOSE[4729] logger.c: < SAPI: 00 C/R: 1 EA: 0 < TEI: 000 EA: 1 [Jan 9 19:24:39] VERBOSE[4729] logger.c: < N(S): 106 0: 0 < N(R): 109 P: 0 < 5 bytes of data [Jan 9 19:24:39] VERBOSE[4729] logger.c: -- ACKing all packets from 108 to (but not including) 109 [Jan 9 19:24:39] VERBOSE[4729] logger.c: -- Since there was nothing left, stopping T200 counter [Jan 9 19:24:39] VERBOSE[4729] logger.c: -- Stopping T203 counter since we got an ACK [Jan 9 19:24:39] VERBOSE[4729] logger.c: -- Nothing left, starting T203 counter [Jan 9 19:24:39] VERBOSE[4729] logger.c: < Protocol Discriminator: Q.931 (8) len=5 [Jan 9 19:24:39] VERBOSE[4729] logger.c: < Call Ref: len= 2 (reference 22322/0x5732) (Originator) [Jan 9 19:24:39] VERBOSE[4729] logger.c: < Message type: CONNECT ACKNOWLEDGE (15) [Jan 9 19:24:39] VERBOSE[4729] logger.c: q931.c:3456 q931_receive: call 22322 on channel 17 enters state 10 (Active) [Jan 9 19:24:39] VERBOSE[4729] logger.c: Sending Receiver Ready (107) [Jan 9 19:24:39] VERBOSE[4729] logger.c: > [ 02 01 01 d6 ] [Jan 9 19:24:39] VERBOSE[4729] logger.c: > Supervisory frame: [Jan 9 19:24:39] VERBOSE[4729] logger.c: > SAPI: 00 C/R: 1 EA: 0 > TEI: 000 EA: 1 [Jan 9 19:24:39] VERBOSE[4729] logger.c: > Zero: 0 S: 0 01: 1 [ RR (receive ready) ] > N(R): 107 P/F: 0 > 0 bytes of data [Jan 9 19:24:39] VERBOSE[4729] logger.c: -- Restarting T203 counter [Jan 9 19:24:39] VERBOSE[4729] logger.c: -- Restarting T203 counter [Jan 9 19:24:39] VERBOSE[4730] logger.c: < [ 02 01 26 4a 08 02 10 4a 05 a1 04 03 80 90 a3 18 03 a9 83 9d 6c 0c 21 83 33 34 34 35 30 34 32 35 33 38 70 0b 81 34 35 35 34 39 30 30 34 34 34 7d 02 91 81 ] [Jan 9 19:24:45] VERBOSE[26960] logger.c: -- Executing [s@MUSIC_STATION1:5] Set("Zap/110-1", "__EXPCUST_GIFTED_LIST=0") in new stack [Jan 9 19:24:45] VERBOSE[26960] logger.c: -- Executing [s@MUSIC_STATION1:6] Set("Zap/110-1", "__VALID_CUST=no") in new stack [Jan 9 19:24:45] VERBOSE[26960] logger.c: -- Executing [s@MUSIC_STATION1:7] Set("Zap/110-1", "__EXP_CUST=no") in new stack [Jan 9 19:24:45] VERBOSE[26960] logger.c: -- Executing [s@MUSIC_STATION1:8] Set("Zap/110-1", "__NOT_CUST_NOGT=no") in new stack [Jan 9 19:24:45] VERBOSE[26960] logger.c: -- Executing [s@MUSIC_STATION1:9] Set("Zap/110-1", "__NOT_CUST_HVGT=no") in new stack [Jan 9 19:24:45] VERBOSE[26960] logger.c: -- Executing [s@MUSIC_STATION1:10] Set("Zap/110-1", "__BALANCE=0") in new stack [Jan 9 19:24:45] VERBOSE[26960] logger.c: -- Executing [s@MUSIC_STATION1:11] AGI("Zap/110-1", "regusers.agi|3447471673") in new stack [Jan 9 19:24:45] VERBOSE[26960] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/regusers.agi [Jan 9 19:24:46] VERBOSE[26960] logger.c: regusers.agi|3447471673: hangup callback set............. [Jan 9 19:24:46] VERBOSE[26960] logger.c: regusers.agi|3447471673: .......user cell no is >>>03447471673............. [Jan 9 19:24:46] VERBOSE[26960] logger.c: -- AGI Script regusers.agi completed, returning 0 [Jan 9 19:24:46] VERBOSE[26960] logger.c: -- Executing [s@MUSIC_STATION1:12] AGI("Zap/110-1", "jbxValidCust.agi|3447471673") in new stack [Jan 9 19:24:46] VERBOSE[4729] logger.c: < [ 02 01 e4 e6 08 02 57 2f 45 08 02 80 90 1e 02 82 88 ] [Jan 9 19:24:46] VERBOSE[26960] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/jbxValidCust.agi [Jan 9 19:24:46] VERBOSE[4729] logger.c: < Informational frame: [Jan 9 19:24:46] VERBOSE[4729] logger.c: < SAPI: 00 C/R: 1 EA: 0 < TEI: 000 EA: 1 [Jan 9 19:24:46] VERBOSE[4729] logger.c: < N(S): 114 0: 0 < N(R): 115 P: 0 < 13 bytes of data [Jan 9 19:24:46] VERBOSE[26960] logger.c: jbxValidCust.agi|3447471673: ......Valid Customer and balance is 1000000000........ [Jan 9 19:24:46] VERBOSE[26960] logger.c: -- AGI Script jbxValidCust.agi completed, returning 0 [Jan 9 19:24:46] VERBOSE[26960] logger.c: -- Executing [s@MUSIC_STATION1:13] ExecIf("Zap/110-1", "1|Goto|VALID_CUSTOMER|s|1") in new stack [Jan 9 19:24:46] VERBOSE[26960] logger.c: -- Goto (VALID_CUSTOMER,s,1) [Jan 9 19:24:46] VERBOSE[26960] logger.c: -- Executing [s@VALID_CUSTOMER:1] Answer("Zap/110-1", "") in new stack [Jan 9 19:24:46] VERBOSE[26960] logger.c: -- Executing [s@VALID_CUSTOMER:2] Set("Zap/110-1", "__PLAN=/efclub") in new stack [Jan 9 19:24:46] VERBOSE[26960] logger.c: -- Executing [s@VALID_CUSTOMER:3] Set("Zap/110-1", "__PROMPTS=/efclub/prompts/music") in new stack [Jan 9 19:24:46] VERBOSE[26960] logger.c: -- Executing [s@VALID_CUSTOMER:4] Set("Zap/110-1", "__RECORDINGS=/efclub/recordings/music") in new stack [Jan 9 19:24:46] VERBOSE[26960] logger.c: -- Executing [s@VALID_CUSTOMER:5] Set("Zap/110-1", "__MAIN_CNTXT=VALID_CUSTOMER") in new stack [Jan 9 19:24:46] VERBOSE[26960] logger.c: -- Executing [s@VALID_CUSTOMER:6] Set("Zap/110-1", "__PREV_CNTXT=VALID_CUSTOMER") in new stack [Jan 9 19:24:46] VERBOSE[26960] logger.c: -- Executing [s@VALID_CUSTOMER:7] Set("Zap/110-1", "__ERR_CNTXT=VALID_CUSTOMER") in new stack [Jan 9 19:24:46] VERBOSE[26960] logger.c: -- Executing [s@VALID_CUSTOMER:8] Set("Zap/110-1", "__MAIN_EXT=s") in new stack [Jan 9 19:24:46] VERBOSE[26960] logger.c: -- Executing [s@VALID_CUSTOMER:9] Set("Zap/110-1", "__PREV_EXT=s") in new stack [Jan 9 19:24:46] VERBOSE[26960] logger.c: -- Executing [s@VALID_CUSTOMER:10] Set("Zap/110-1", "__ERR_EXT=s") in new stack [Jan 9 19:24:46] VERBOSE[26960] logger.c: -- Executing [s@VALID_CUSTOMER:11] Set("Zap/110-1", "__MAIN_PRI=start") in new stack [Jan 9 19:24:46] VERBOSE[26960] logger.c: -- Executing [s@VALID_CUSTOMER:12] Set("Zap/110-1", "__PREV_PRI=start") in new stack [Jan 9 19:24:46] VERBOSE[26960] logger.c: -- Executing [s@VALID_CUSTOMER:13] Set("Zap/110-1", "__ERR_PRI=menu") in new stack [Jan 9 19:24:46] VERBOSE[26960] logger.c: -- Executing [s@VALID_CUSTOMER:14] Set("Zap/110-1", "__ERR_COUNT=0") in new stack [Jan 9 19:24:46] VERBOSE[26960] logger.c: -- Executing [s@VALID_CUSTOMER:15] Set("Zap/110-1", "__MENU_COUNT=0") in new stack [Jan 9 19:24:46] VERBOSE[26960] logger.c: -- Executing [s@VALID_CUSTOMER:16] BackGround("Zap/110-1", "/efclub/prompts/music/music_menu") in new stack [Jan 9 19:24:46] VERBOSE[26960] logger.c: -- Playing '/efclub/prompts/music/music_menu' (language 'en') [Jan 9 19:25:00] VERBOSE[26960] logger.c: -- Executing [s@VALID_CUSTOMER:17] Set("Zap/110-1", "__MENU_COUNT=0+1") in new stack [Jan 9 19:25:00] VERBOSE[26960] logger.c: -- Executing [s@VALID_CUSTOMER:18] ExecIf("Zap/110-1", "0|Goto|1|1") in new stack [Jan 9 19:25:00] VERBOSE[26960] logger.c: -- Executing [s@VALID_CUSTOMER:19] BackGround("Zap/110-1", "silence/2") in new stack [Jan 9 19:25:00] VERBOSE[26960] logger.c: -- Playing 'silence/2' (language 'en') [Jan 9 19:25:02] VERBOSE[26960] logger.c: -- Executing [s@VALID_CUSTOMER:20] BackGround("Zap/110-1", "/efclub/prompts/music/idle_cond") in new stack [Jan 9 19:25:02] VERBOSE[26960] logger.c: -- Playing '/efclub/prompts/music/idle_cond' (language 'en') [Jan 9 19:25:09] VERBOSE[26960] logger.c: -- Executing [s@VALID_CUSTOMER:21] Goto("Zap/110-1", "menu") in new stack [Jan 9 19:25:09] VERBOSE[26960] logger.c: -- Goto (VALID_CUSTOMER,s,16) [Jan 9 19:25:09] VERBOSE[26960] logger.c: -- Executing [s@VALID_CUSTOMER:16] BackGround("Zap/110-1", "/efclub/prompts/music/music_menu") in new stack [Jan 9 19:25:09] VERBOSE[26960] logger.c: -- Playing '/efclub/prompts/music/music_menu' (language 'en') [Jan 9 19:25:22] DTMF[26960] channel.c: DTMF end '2' received on Zap/110-1, duration 0 ms [Jan 9 19:25:22] DTMF[26960] channel.c: DTMF end accepted without begin '2' on Zap/110-1 [Jan 9 19:25:22] DTMF[26960] channel.c: DTMF end passthrough '2' on Zap/110-1 [Jan 9 19:25:22] VERBOSE[26960] logger.c: == CDR updated on Zap/110-1 [Jan 9 19:25:22] VERBOSE[26960] logger.c: -- Executing [2@VALID_CUSTOMER:1] Set("Zap/110-1", "__VALID_CUSTOMER=2") in new stack [Jan 9 19:25:22] VERBOSE[26960] logger.c: -- Executing [2@VALID_CUSTOMER:2] ResetCDR("Zap/110-1", "w") in new stack [Jan 9 19:25:22] VERBOSE[26960] logger.c: -- Executing [2@VALID_CUSTOMER:3] SetCDRUserField("Zap/110-1", "444-JUKEBOX") in new stack [Jan 9 19:25:22] VERBOSE[26960] logger.c: -- Executing [2@VALID_CUSTOMER:4] Goto("Zap/110-1", "JUKEBOX|s|1") in new stack [Jan 9 19:25:22] VERBOSE[26960] logger.c: -- Goto (JUKEBOX,s,1) [Jan 9 19:25:22] VERBOSE[26960] logger.c: -- Executing [s@JUKEBOX:1] Answer("Zap/110-1", "") in new stack [Jan 9 19:25:22] VERBOSE[26960] logger.c: -- Executing [s@JUKEBOX:2] Set("Zap/110-1", "__PROMPTS=/efclub/prompts/music/jukebox") in new stack [Jan 9 19:25:22] VERBOSE[26960] logger.c: -- Executing [s@JUKEBOX:3] Set("Zap/110-1", "__CTDGTDLIST=no") in new stack [Jan 9 19:25:22] VERBOSE[26960] logger.c: -- Executing [s@JUKEBOX:4] Set("Zap/110-1", "__CTDLIST=no") in new stack [Jan 9 19:25:22] VERBOSE[26960] logger.c: -- Executing [s@JUKEBOX:5] Set("Zap/110-1", "__GTDLIST=no") in new stack [Jan 9 19:25:22] VERBOSE[26960] logger.c: -- Executing [s@JUKEBOX:6] Set("Zap/110-1", "__NOLIST=no") in new stack [Jan 9 19:25:22] VERBOSE[26960] logger.c: -- Executing [s@JUKEBOX:7] AGI("Zap/110-1", "checkplaylist.agi|3447471673") in new stack [Jan 9 19:25:22] VERBOSE[26960] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/checkplaylist.agi [Jan 9 19:25:22] VERBOSE[26960] logger.c: checkplaylist.agi|3447471673: ........no list [Jan 9 19:25:22] VERBOSE[26960] logger.c: -- AGI Script checkplaylist.agi completed, returning 0 [Jan 9 19:25:22] VERBOSE[26960] logger.c: -- Executing [s@JUKEBOX:8] ExecIf("Zap/110-1", "0|Goto|CTDGTD_LIST|s|1") in new stack [Jan 9 19:25:22] VERBOSE[26960] logger.c: -- Executing [s@JUKEBOX:9] ExecIf("Zap/110-1", "0|Goto|CTD_LIST|s|1") in new stack [Jan 9 19:25:22] VERBOSE[26960] logger.c: -- Executing [s@JUKEBOX:10] ExecIf("Zap/110-1", "0|Goto|GTD_LIST|s|1") in new stack [Jan 9 19:25:22] VERBOSE[26960] logger.c: -- Executing [s@JUKEBOX:11] ExecIf("Zap/110-1", "1|Goto|NO_LIST|s|1") in new stack [Jan 9 19:25:22] VERBOSE[26960] logger.c: -- Goto (NO_LIST,s,1) [Jan 9 19:25:22] VERBOSE[26960] logger.c: -- Executing [s@NO_LIST:1] Answer("Zap/110-1", "") in new stack [Jan 9 19:25:22] VERBOSE[26960] logger.c: -- Executing [s@NO_LIST:2] Set("Zap/110-1", "__MAIN_CNTXT=MUSIC_STATION1") in new stack [Jan 9 19:25:22] VERBOSE[26960] logger.c: -- Executing [s@NO_LIST:3] Set("Zap/110-1", "__PREV_CNTXT=MUSIC_STATION1") in new stack [Jan 9 19:25:22] VERBOSE[26960] logger.c: -- Executing [s@NO_LIST:4] Set("Zap/110-1", "__ERR_CNTXT=NO_LIST") in new stack [Jan 9 19:25:22] VERBOSE[26960] logger.c: -- Executing [s@NO_LIST:5] Set("Zap/110-1", "__MAIN_EXT=s") in new stack [Jan 9 19:25:22] VERBOSE[26960] logger.c: -- Executing [s@NO_LIST:6] Set("Zap/110-1", "__PREV_EXT=s") in new stack [Jan 9 19:25:22] VERBOSE[26960] logger.c: -- Executing [s@NO_LIST:7] Set("Zap/110-1", "__ERR_EXT=s") in new stack [Jan 9 19:25:22] VERBOSE[26960] logger.c: -- Executing [s@NO_LIST:8] Set("Zap/110-1", "__MAIN_PRI=start") in new stack [Jan 9 19:25:22] VERBOSE[26960] logger.c: -- Executing [s@NO_LIST:9] Set("Zap/110-1", "__PREV_PRI=start") in new stack [Jan 9 19:25:22] VERBOSE[26960] logger.c: -- Executing [s@NO_LIST:10] Set("Zap/110-1", "__ERR_PRI=menu") in new stack [Jan 9 19:25:22] VERBOSE[26960] logger.c: -- Executing [s@NO_LIST:11] Set("Zap/110-1", "__ERR_COUNT=0") in new stack [Jan 9 19:25:22] VERBOSE[26960] logger.c: -- Executing [s@NO_LIST:12] BackGround("Zap/110-1", "/efclub/prompts/music/jukebox/no_list_menu") in new stack [Jan 9 19:25:22] VERBOSE[26960] logger.c: -- Playing '/efclub/prompts/music/jukebox/no_list_menu' (language 'en') [Jan 9 19:25:41] VERBOSE[26960] logger.c: -- Executing [s@NO_LIST:13] BackGround("Zap/110-1", "silence/2") in new stack [Jan 9 19:25:41] VERBOSE[26960] logger.c: -- Playing 'silence/2' (language 'en') >>>>>>> there are many events where a call is dropped because the channel is busy eg [Jan 9 19:26:19] VERBOSE[4729] logger.c: < [ 02 01 56 4a 08 02 57 54 05 a1 04 03 80 90 a3 18 03 a9 83 91 6c 0c 21 83 33 34 33 35 30 30 31 38 31 35 70 0b 81 34 35 35 34 39 30 30 34 34 34 7d 02 91 81 ] [Jan 9 19:26:19] VERBOSE[4729] logger.c: < Informational frame: [Jan 9 19:26:19] VERBOSE[4729] logger.c: < SAPI: 00 C/R: 1 EA: 0 < TEI: 000 EA: 1 [Jan 9 19:26:19] VERBOSE[4729] logger.c: < N(S): 043 0: 0 < N(R): 037 P: 0 < 47 bytes of data [Jan 9 19:26:19] VERBOSE[4729] logger.c: -- ACKing all packets from 36 to (but not including) 37 [Jan 9 19:26:19] VERBOSE[4729] logger.c: -- Since there was nothing left, stopping T200 counter [Jan 9 19:26:19] VERBOSE[4729] logger.c: -- Stopping T203 counter since we got an ACK [Jan 9 19:26:19] VERBOSE[4729] logger.c: -- Nothing left, starting T203 counter [Jan 9 19:26:19] VERBOSE[4729] logger.c: < Protocol Discriminator: Q.931 (8) len=47 [Jan 9 19:26:19] VERBOSE[4729] logger.c: < Call Ref: len= 2 (reference 22356/0x5754) (Originator) [Jan 9 19:26:19] VERBOSE[4729] logger.c: < Message type: SETUP (5) [Jan 9 19:26:19] VERBOSE[4729] logger.c: < [a1] [Jan 9 19:26:19] VERBOSE[4729] logger.c: < Sending Complete (len= 1) [Jan 9 19:26:19] VERBOSE[4729] logger.c: < [04 03 80 90 a3] [Jan 9 19:26:19] VERBOSE[4729] logger.c: < Bearer Capability (len= 5) [ Ext: 1 Q.931 Std: 0 Info transfer capability: Speech (0) [Jan 9 19:26:19] VERBOSE[4729] logger.c: < Ext: 1 Trans mode/rate: 64kbps, circuit-mode (16) [Jan 9 19:26:19] VERBOSE[4729] logger.c: < Ext: 1 User information layer 1: A-Law (35) [Jan 9 19:26:19] VERBOSE[4729] logger.c: < [18 03 a9 83 91] [Jan 9 19:26:19] VERBOSE[4729] logger.c: < Channel ID (len= 5) [ Ext: 1 IntID: Implicit PRI Spare: 0 Exclusive Dchan: 0 [Jan 9 19:26:19] VERBOSE[4729] logger.c: < ChanSel: Reserved [Jan 9 19:26:19] VERBOSE[4729] logger.c: < Ext: 1 Coding: 0 Number Specified Channel Type: 3 [Jan 9 19:26:19] VERBOSE[4729] logger.c: < Ext: 1 Channel: 17 ] [Jan 9 19:26:19] VERBOSE[4729] logger.c: < [6c 0c 21 83 33 34 33 35 30 30 31 38 31 35] [Jan 9 19:26:19] VERBOSE[4729] logger.c: < Calling Number (len=14) [ Ext: 0 TON: National Number (2) NPI: ISDN/Telephony Numbering Plan (E.164/E.163) (1) [Jan 9 19:26:19] VERBOSE[4729] logger.c: < Presentation: Presentation allowed of network provided number (3) '3435001815' ] [Jan 9 19:26:19] VERBOSE[4729] logger.c: < [70 0b 81 34 35 35 34 39 30 30 34 34 34] [Jan 9 19:26:19] VERBOSE[4729] logger.c: < Called Number (len=13) [ Ext: 1 TON: Unknown Number Type (0) NPI: ISDN/Telephony Numbering Plan (E.164/E.163) (1) '4554900444' ] [Jan 9 19:26:19] VERBOSE[4729] logger.c: < [7d 02 91 81] [Jan 9 19:26:19] VERBOSE[4729] logger.c: < IE: High-layer Compatibility (len = 4) [Jan 9 19:26:19] VERBOSE[4729] logger.c: -- Making new call for cr 22356 [Jan 9 19:26:19] VERBOSE[4729] logger.c: -- Processing Q.931 Call Setup [Jan 9 19:26:19] VERBOSE[4729] logger.c: -- Processing IE 161 (cs0, Sending Complete) [Jan 9 19:26:19] VERBOSE[4729] logger.c: -- Processing IE 4 (cs0, Bearer Capability) [Jan 9 19:26:19] VERBOSE[4729] logger.c: -- Processing IE 24 (cs0, Channel Identification) [Jan 9 19:26:19] VERBOSE[4729] logger.c: -- Processing IE 108 (cs0, Calling Party Number) [Jan 9 19:26:19] VERBOSE[4729] logger.c: -- Processing IE 112 (cs0, Called Party Number) [Jan 9 19:26:19] VERBOSE[4729] logger.c: -- Processing IE 125 (cs0, High-layer Compatibility) [Jan 9 19:26:19] VERBOSE[4729] logger.c: q931.c:3298 q931_receive: call 22356 on channel 17 enters state 6 (Call Present) [Jan 9 19:26:19] VERBOSE[4729] logger.c: Sending Receiver Ready (44) [Jan 9 19:26:19] VERBOSE[4729] logger.c: > [ 02 01 01 58 ] [Jan 9 19:26:19] VERBOSE[4729] logger.c: > Supervisory frame: [Jan 9 19:26:19] VERBOSE[4729] logger.c: > SAPI: 00 C/R: 1 EA: 0 > TEI: 000 EA: 1 [Jan 9 19:26:19] VERBOSE[4729] logger.c: > Zero: 0 S: 0 01: 1 [ RR (receive ready) ] > N(R): 044 P/F: 0 > 0 bytes of data [Jan 9 19:26:19] VERBOSE[4729] logger.c: -- Restarting T203 counter [Jan 9 19:26:19] VERBOSE[4729] logger.c: -- Restarting T203 counter [Jan 9 19:26:19] DEBUG[4729] chan_zap.c: Ring requested on channel 0/17 already in use or previously requested on span 5. Attempting to renegotiating channel. [Jan 9 19:26:19] VERBOSE[4729] logger.c: NEW_HANGUP DEBUG: Calling q931_hangup, ourstate Call Present, peerstate Call Initiated [Jan 9 19:26:19] VERBOSE[4729] logger.c: q931.c:2893 q931_release_complete: call 22356 on channel 17 enters state 0 (Null) [Jan 9 19:26:19] VERBOSE[4729] logger.c: > [ 00 01 4a 58 08 02 d7 54 5a 08 02 81 ac ] [Jan 9 19:26:19] VERBOSE[4729] logger.c: > Informational frame: [Jan 9 19:26:19] VERBOSE[4729] logger.c: > SAPI: 00 C/R: 0 EA: 0 > TEI: 000 EA: 1 [Jan 9 19:26:19] VERBOSE[4729] logger.c: > N(S): 037 0: 0 > N(R): 044 P: 0 > 9 bytes of data [Jan 9 19:26:19] VERBOSE[4729] logger.c: -- Restarting T203 counter [Jan 9 19:26:19] VERBOSE[4729] logger.c: Stopping T_203 timer [Jan 9 19:26:19] VERBOSE[4729] logger.c: Starting T_200 timer [Jan 9 19:26:19] VERBOSE[4729] logger.c: > Protocol Discriminator: Q.931 (8) len=9 [Jan 9 19:26:19] VERBOSE[4729] logger.c: > Call Ref: len= 2 (reference 22356/0x5754) (Terminator) [Jan 9 19:26:19] VERBOSE[4729] logger.c: > Message type: RELEASE COMPLETE (90) [Jan 9 19:26:19] VERBOSE[4729] logger.c: > [08 02 81 ac] [Jan 9 19:26:19] VERBOSE[4729] logger.c: > Cause (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) Spare: 0 Location: Private network serving the local user (1) [Jan 9 19:26:19] VERBOSE[4729] logger.c: > Ext: 1 Cause: Requested channel not available (44), class = Network Congestion (resource unavailable) (2) ] [Jan 9 19:26:19] VERBOSE[4729] logger.c: NEW_HANGUP DEBUG: Calling q931_hangup, ourstate Null, peerstate Null [Jan 9 19:26:19] VERBOSE[4729] logger.c: NEW_HANGUP DEBUG: Destroying the call, ourstate Null, peerstate Null [Jan 9 19:26:19] VERBOSE[4729] logger.c: >>>>>>> the channel is cleared only when asterisk is restarted [Jan 9 20:58:53] VERBOSE[26960] logger.c: == Spawn extension (NO_LIST, s, 12) exited non-zero on 'Zap/110-1' [Jan 9 20:58:53] DEBUG[26960] chan_zap.c: Set option AUDIO MODE, value: ON(1) on Zap/110-1 [Jan 9 20:58:53] DEBUG[26960] chan_zap.c: Not yet hungup... Calling hangup once with icause, and clearing call [Jan 9 20:58:53] VERBOSE[26960] logger.c: NEW_HANGUP DEBUG: Calling q931_hangup, ourstate Active, peerstate Active [Jan 9 20:58:53] VERBOSE[26960] logger.c: q931.c:2764 q931_disconnect: call 22322 on channel 17 enters state 11 (Disconnect Request) [Jan 9 20:58:53] VERBOSE[26960] logger.c: [Jan 9 20:58:53] VERBOSE[26960] logger.c: > Informational frame: [Jan 9 20:58:53] VERBOSE[26960] logger.c: > SAPI: 00 C/R: 0 EA: 0 > TEI: 000 EA: 1 [Jan 9 20:58:53] VERBOSE[26960] logger.c: > N(S): 056 0: 0 > N(R): 069 P: 0 > 9 bytes of data [Jan 9 20:58:53] VERBOSE[26960] logger.c: T_200 timer already going (2) [Jan 9 20:58:53] VERBOSE[26960] logger.c: > Protocol Discriminator: Q.931 (8) len=9 [Jan 9 20:58:53] VERBOSE[26960] logger.c: > Call Ref: len= 2 (reference 22322/0x5732) (Terminator) [Jan 9 20:58:53] VERBOSE[26960] logger.c: > Message type: DISCONNECT (69) [Jan 9 20:58:53] VERBOSE[26960] logger.c: > [08 02 81 90] [Jan 9 20:58:53] VERBOSE[26960] logger.c: > Cause (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) Spare: 0 Location: Private network serving the local user (1) [Jan 9 20:58:53] VERBOSE[26960] logger.c: > Ext: 1 Cause: Normal Clearing (16), class = Normal Event (1) ] [Jan 9 20:58:53] DEBUG[26960] chan_zap.c: Set option AUDIO MODE, value: OFF(0) on Zap/110-1 [Jan 9 20:58:53] VERBOSE[26960] logger.c: -- Hungup 'Zap/110-1' [Jan 9 20:58:53] VERBOSE[4729] logger.c: < Call Ref: len= 2 (reference 22322/0x5732) (Originator) [Jan 9 20:58:53] VERBOSE[4729] logger.c: > Call Ref: len= 2 (reference 22322/0x5732) (Terminator)