need some help troubleshooting a PRI connection that randomly drops calls

jpcwilliams
Joined: Fri 03 of Sep, 2004

need some help troubleshooting a PRI connection that randomly drops calls

Posted:Thu 12 of Aug, 2010 (00:31 UTC)
We recently upgraded our trixbox system from 4xBRI lines to 1xPRI 20 channel and now I need some help troubleshooting a PRI connection that randomly drops calls.

Asterisk log with pri debugging on I have marked the spot where I think the issue is occurring with a **.
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Executing [04XXXXXXX@from-internal:1] Macro("SIP/204-0852ecd0", "user-callerid|SKIPTTL|") in new stack
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Executing [s@macro-user-callerid:1] NoOp("SIP/204-0852ecd0", "user-callerid: device 204") in new stack
[Aug 12 07:56:28] DEBUG[12476] app_macro.c: Executed application: Noop
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Executing [s@macro-user-callerid:2] Set("SIP/204-0852ecd0", "AMPUSER=204") in new stack
[Aug 12 07:56:28] DEBUG[12476] app_macro.c: Executed application: Set
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Executing [s@macro-user-callerid:3] GotoIf("SIP/204-0852ecd0", "0?report") in new stack
[Aug 12 07:56:28] DEBUG[12476] app_macro.c: Executed application: GotoIf
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Executing [s@macro-user-callerid:4] ExecIf("SIP/204-0852ecd0", "1|Set|REALCALLERIDNUM=204") in new stack
[Aug 12 07:56:28] DEBUG[12476] app_macro.c: Executed application: ExecIf
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Executing [s@macro-user-callerid:5] NoOp("SIP/204-0852ecd0", "REALCALLERIDNUM is 204") in new stack
[Aug 12 07:56:28] DEBUG[12476] app_macro.c: Executed application: Noop
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Executing [s@macro-user-callerid:6] Set("SIP/204-0852ecd0", "AMPUSER=204") in new stack
[Aug 12 07:56:28] DEBUG[12476] app_macro.c: Executed application: Set
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Executing [s@macro-user-callerid:7] Set("SIP/204-0852ecd0", "AMPUSERCIDNAME=Carolanne van Leeuwen") in new stack
[Aug 12 07:56:28] DEBUG[12476] app_macro.c: Executed application: Set
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Executing [s@macro-user-callerid:8] GotoIf("SIP/204-0852ecd0", "0?report") in new stack
[Aug 12 07:56:28] DEBUG[12476] app_macro.c: Executed application: GotoIf
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Executing [s@macro-user-callerid:9] Set("SIP/204-0852ecd0", "AMPUSERCID=204") in new stack
[Aug 12 07:56:28] DEBUG[12476] app_macro.c: Executed application: Set
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Executing [s@macro-user-callerid:10] Set("SIP/204-0852ecd0", "CALLERID(all)="Carolanne van Leeuwen" <204>") in new stack
[Aug 12 07:56:28] DEBUG[12476] app_macro.c: Executed application: Set
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Executing [s@macro-user-callerid:11] Set("SIP/204-0852ecd0", "REALCALLERIDNUM=204") in new stack
[Aug 12 07:56:28] DEBUG[12476] app_macro.c: Executed application: Set
[Aug 12 07:56:28] DEBUG[12476] func_db.c: DB: AMPUSER/204/language not found in database.
[Aug 12 07:56:28] DEBUG[12476] func_db.c: DB: AMPUSER/204/language not found in database.
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Executing [s@macro-user-callerid:12] ExecIf("SIP/204-0852ecd0", "0|Set|CHANNEL(language)=") in new stack
[Aug 12 07:56:28] DEBUG[12476] app_macro.c: Executed application: ExecIf
[Aug 12 07:56:28] DEBUG[12476] func_db.c: DB: AMPUSER/204/language not found in database.
[Aug 12 07:56:28] DEBUG[12476] func_db.c: DB: AMPUSER/204/language not found in database.
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Executing [s@macro-user-callerid:13] NoOp("SIP/204-0852ecd0", "TTL:  ARG1: SKIPTTL") in new stack
[Aug 12 07:56:28] DEBUG[12476] app_macro.c: Executed application: Noop
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Executing [s@macro-user-callerid:14] GotoIf("SIP/204-0852ecd0", "1?continue") in new stack
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Goto (macro-user-callerid,s,23)
[Aug 12 07:56:28] DEBUG[12476] app_macro.c: Executed application: GotoIf
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Executing [s@macro-user-callerid:23] NoOp("SIP/204-0852ecd0", "Using CallerID "Carolanne van Leeuwen" <204>") in new stack
[Aug 12 07:56:28] DEBUG[12476] app_macro.c: Executed application: Noop
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Executing [04XXXXXXX@from-internal:2] Set("SIP/204-0852ecd0", "_NODEST=") in new stack
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Executing [04XXXXXXX@from-internal:3] Macro("SIP/204-0852ecd0", "record-enable|204|OUT|") in new stack
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Executing [s@macro-record-enable:1] GotoIf("SIP/204-0852ecd0", "0?2:4") in new stack
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Goto (macro-record-enable,s,4)
[Aug 12 07:56:28] DEBUG[12476] app_macro.c: Executed application: GotoIf
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Executing [s@macro-record-enable:4] AGI("SIP/204-0852ecd0", "recordingcheck|20100812-075628|1281563788.194") in new stack
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
[Aug 12 07:56:28] VERBOSE[12476] logger.c:   recordingcheck|20100812-075628|1281563788.194: Outbound recording not enabled
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- AGI Script recordingcheck completed, returning 0
[Aug 12 07:56:28] DEBUG[12476] app_macro.c: Executed application: AGI
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Executing [s@macro-record-enable:5] NoOp("SIP/204-0852ecd0", "No recording needed") in new stack
[Aug 12 07:56:28] DEBUG[12476] app_macro.c: Executed application: Noop
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Executing [04XXXXXXX@from-internal:4] Macro("SIP/204-0852ecd0", "dialout-trunk|6|47572340||") in new stack
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Executing [s@macro-dialout-trunk:1] Set("SIP/204-0852ecd0", "DIAL_TRUNK=6") in new stack
[Aug 12 07:56:28] DEBUG[12476] app_macro.c: Executed application: Set
[Aug 12 07:56:28] DEBUG[12476] func_db.c: DB: AMPUSER/204/pinless not found in database.
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Executing [s@macro-dialout-trunk:2] ExecIf("SIP/204-0852ecd0", "0|Authenticate|") in new stack
[Aug 12 07:56:28] DEBUG[12476] app_macro.c: Executed application: ExecIf
[Aug 12 07:56:28] DEBUG[12476] func_db.c: DB: AMPUSER/204/pinless not found in database.
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Executing [s@macro-dialout-trunk:3] GotoIf("SIP/204-0852ecd0", "0?disabletrunk|1") in new stack
[Aug 12 07:56:28] DEBUG[12476] app_macro.c: Executed application: GotoIf
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Executing [s@macro-dialout-trunk:4] Set("SIP/204-0852ecd0", "DIAL_NUMBER=47572340") in new stack
[Aug 12 07:56:28] DEBUG[12476] app_macro.c: Executed application: Set
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Executing [s@macro-dialout-trunk:5] Set("SIP/204-0852ecd0", "DIAL_TRUNK_OPTIONS=tr") in new stack
[Aug 12 07:56:28] DEBUG[12476] app_macro.c: Executed application: Set
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Executing [s@macro-dialout-trunk:6] Set("SIP/204-0852ecd0", "GROUP()=OUT_6") in new stack
[Aug 12 07:56:28] DEBUG[12476] app_macro.c: Executed application: Set
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Executing [s@macro-dialout-trunk:7] GotoIf("SIP/204-0852ecd0", "0?nomax") in new stack
[Aug 12 07:56:28] DEBUG[12476] app_macro.c: Executed application: GotoIf
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Executing [s@macro-dialout-trunk:8] GotoIf("SIP/204-0852ecd0", "0?chanfull") in new stack
[Aug 12 07:56:28] DEBUG[12476] app_macro.c: Executed application: GotoIf
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Executing [s@macro-dialout-trunk:9] GotoIf("SIP/204-0852ecd0", "0?skipoutcid") in new stack
[Aug 12 07:56:28] DEBUG[12476] app_macro.c: Executed application: GotoIf
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Executing [s@macro-dialout-trunk:10] Set("SIP/204-0852ecd0", "DIAL_TRUNK_OPTIONS=r") in new stack
[Aug 12 07:56:28] DEBUG[12476] app_macro.c: Executed application: Set
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Executing [s@macro-dialout-trunk:11] Macro("SIP/204-0852ecd0", "outbound-callerid|6") in new stack
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Executing [s@macro-outbound-callerid:1] ExecIf("SIP/204-0852ecd0", "0|SetCallerPres|") in new stack
[Aug 12 07:56:28] DEBUG[12476] app_macro.c: Executed application: ExecIf
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Executing [s@macro-outbound-callerid:2] GotoIf("SIP/204-0852ecd0", "1?start") in new stack
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Goto (macro-outbound-callerid,s,4)
[Aug 12 07:56:28] DEBUG[12476] app_macro.c: Executed application: GotoIf
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Executing [s@macro-outbound-callerid:4] NoOp("SIP/204-0852ecd0", "REALCALLERIDNUM is 204") in new stack
[Aug 12 07:56:28] DEBUG[12476] app_macro.c: Executed application: Noop
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Executing [s@macro-outbound-callerid:5] GotoIf("SIP/204-0852ecd0", "1?normcid") in new stack
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Goto (macro-outbound-callerid,s,10)
[Aug 12 07:56:28] DEBUG[12476] app_macro.c: Executed application: GotoIf
[Aug 12 07:56:28] DEBUG[12476] func_db.c: DB: AMPUSER/204/outboundcid not found in database.
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Executing [s@macro-outbound-callerid:10] Set("SIP/204-0852ecd0", "USEROUTCID=") in new stack
[Aug 12 07:56:28] DEBUG[12476] app_macro.c: Executed application: Set
[Aug 12 07:56:28] DEBUG[12476] func_db.c: DB: DEVICE/204/emergency_cid not found in database.
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Executing [s@macro-outbound-callerid:11] Set("SIP/204-0852ecd0", "EMERGENCYCID=") in new stack
[Aug 12 07:56:28] DEBUG[12476] app_macro.c: Executed application: Set
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Executing [s@macro-outbound-callerid:12] Set("SIP/204-0852ecd0", "TRUNKOUTCID=29XXXXXXX") in new stack
[Aug 12 07:56:28] DEBUG[12476] app_macro.c: Executed application: Set
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Executing [s@macro-outbound-callerid:13] GotoIf("SIP/204-0852ecd0", "1?trunkcid") in new stack
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Goto (macro-outbound-callerid,s,17)
[Aug 12 07:56:28] DEBUG[12476] app_macro.c: Executed application: GotoIf
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Executing [s@macro-outbound-callerid:17] GotoIf("SIP/204-0852ecd0", "0?usercid") in new stack
[Aug 12 07:56:28] DEBUG[12476] app_macro.c: Executed application: GotoIf
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Executing [s@macro-outbound-callerid:18] Set("SIP/204-0852ecd0", "CALLERID(all)=29XXXXXXX") in new stack
[Aug 12 07:56:28] DEBUG[12476] app_macro.c: Executed application: Set
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Executing [s@macro-outbound-callerid:19] GotoIf("SIP/204-0852ecd0", "1?report") in new stack
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Goto (macro-outbound-callerid,s,23)
[Aug 12 07:56:28] DEBUG[12476] app_macro.c: Executed application: GotoIf
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Executing [s@macro-outbound-callerid:23] NoOp("SIP/204-0852ecd0", "CallerID set to "" <29XXXXXXX>") in new stack
[Aug 12 07:56:28] DEBUG[12476] app_macro.c: Executed application: Noop
[Aug 12 07:56:28] DEBUG[12476] app_macro.c: Executed application: Macro
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Executing [s@macro-dialout-trunk:12] AGI("SIP/204-0852ecd0", "fixlocalprefix") in new stack
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Launched AGI Script /var/lib/asterisk/agi-bin/fixlocalprefix
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- AGI Script fixlocalprefix completed, returning 0
[Aug 12 07:56:28] DEBUG[12476] app_macro.c: Executed application: AGI
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Executing [s@macro-dialout-trunk:13] Set("SIP/204-0852ecd0", "OUTNUM=47572340") in new stack
[Aug 12 07:56:28] DEBUG[12476] app_macro.c: Executed application: Set
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Executing [s@macro-dialout-trunk:14] Set("SIP/204-0852ecd0", "custom=ZAP/g0") in new stack
[Aug 12 07:56:28] DEBUG[12476] app_macro.c: Executed application: Set
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Executing [s@macro-dialout-trunk:15] GotoIf("SIP/204-0852ecd0", "1?gocall") in new stack
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Goto (macro-dialout-trunk,s,17)
[Aug 12 07:56:28] DEBUG[12476] app_macro.c: Executed application: GotoIf
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Executing [s@macro-dialout-trunk:17] Macro("SIP/204-0852ecd0", "dialout-trunk-predial-hook|") in new stack
[Aug 12 07:56:28] WARNING[12476] app_macro.c: Context 'macro-dialout-trunk-predial-hook' for macro 'dialout-trunk-predial-hook' lacks 's' extension, priority 1
[Aug 12 07:56:28] DEBUG[12476] app_macro.c: Executed application: Macro
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Executing [s@macro-dialout-trunk:18] GotoIf("SIP/204-0852ecd0", "0?bypass|1") in new stack
[Aug 12 07:56:28] DEBUG[12476] app_macro.c: Executed application: GotoIf
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Executing [s@macro-dialout-trunk:19] GotoIf("SIP/204-0852ecd0", "0?customtrunk") in new stack
[Aug 12 07:56:28] DEBUG[12476] app_macro.c: Executed application: GotoIf
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Executing [s@macro-dialout-trunk:20] Dial("SIP/204-0852ecd0", "ZAP/g0/47572340|300|r") in new stack
[Aug 12 07:56:28] VERBOSE[12476] logger.c: -- Making new call for cr 32797
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Requested transfer capability: 0x00 - SPEECH
[Aug 12 07:56:28] VERBOSE[12476] logger.c: > Protocol Discriminator: Q.931 (8)  len=40
[Aug 12 07:56:28] VERBOSE[12476] logger.c: > Call Ref: len= 2 (reference 29/0x1D) (Originator)
[Aug 12 07:56:28] VERBOSE[12476] logger.c: > Message type: SETUP (5)
[Aug 12 07:56:28] VERBOSE[12476] logger.c: > [04 03 80 90 a3]
[Aug 12 07:56:28] VERBOSE[12476] logger.c: > Bearer Capability (len= 5) [ Ext: 1  Q.931 Std: 0  Info transfer capability: Speech (0)
[Aug 12 07:56:28] VERBOSE[12476] logger.c: >                              Ext: 1  Trans mode/rate: 64kbps, circuit-mode (16)
[Aug 12 07:56:28] VERBOSE[12476] logger.c: >                                User information layer 1: A-Law (35)
[Aug 12 07:56:28] VERBOSE[12476] logger.c: > [18 03 a9 83 81]
[Aug 12 07:56:28] VERBOSE[12476] logger.c: > Channel ID (len= 5) [ Ext: 1  IntID: Implicit  PRI  Spare: 0  Exclusive  Dchan: 0
[Aug 12 07:56:28] VERBOSE[12476] logger.c: >                        ChanSel: As indicated in following octets
[Aug 12 07:56:28] VERBOSE[12476] logger.c: >                       Ext: 1  Coding: 0  Number Specified  Channel Type: 3
[Aug 12 07:56:28] VERBOSE[12476] logger.c: >                       Ext: 1  Channel: 1 ]
[Aug 12 07:56:28] VERBOSE[12476] logger.c: > [6c 0b 00 80 32 39 34 36 37 39 32 30 30]
[Aug 12 07:56:28] VERBOSE[12476] logger.c: > Calling Number (len=13) [ Ext: 0  TON: Unknown Number Type (0)  NPI: Unknown Number Plan (0)
[Aug 12 07:56:28] VERBOSE[12476] logger.c: >                           Presentation: Presentation permitted, user number not screened (0)  '29XXXXXXX' ]
[Aug 12 07:56:28] VERBOSE[12476] logger.c: > [70 09 80 34 37 35 37 32 33 34 30]
[Aug 12 07:56:28] VERBOSE[12476] logger.c: > Called Number (len=11) [ Ext: 1  TON: Unknown Number Type (0)  NPI: Unknown Number Plan (0)  '47572340' ]
[Aug 12 07:56:28] VERBOSE[12476] logger.c: > [a1]
[Aug 12 07:56:28] VERBOSE[12476] logger.c: > Sending Complete (len= 1)
[Aug 12 07:56:28] VERBOSE[12476] logger.c: q931.c:3092 q931_setup: call 32797 on channel 1 enters state 1 (Call Initiated)
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Called g0/47572340
[Aug 12 07:56:28] VERBOSE[11440] logger.c: < Protocol Discriminator: Q.931 (8)  len=10
[Aug 12 07:56:28] VERBOSE[11440] logger.c: < Call Ref: len= 2 (reference 29/0x1D) (Terminator)
[Aug 12 07:56:28] VERBOSE[11440] logger.c: < Message type: CALL PROCEEDING (2)
[Aug 12 07:56:28] VERBOSE[11440] logger.c: < [18 03 a9 83 81]
[Aug 12 07:56:28] VERBOSE[11440] logger.c: < Channel ID (len= 5) [ Ext: 1  IntID: Implicit  PRI  Spare: 0  Exclusive  Dchan: 0
[Aug 12 07:56:28] VERBOSE[11440] logger.c: <                        ChanSel: As indicated in following octets
[Aug 12 07:56:28] VERBOSE[11440] logger.c: <                       Ext: 1  Coding: 0  Number Specified  Channel Type: 3
[Aug 12 07:56:28] VERBOSE[11440] logger.c: <                       Ext: 1  Channel: 1 ]
[Aug 12 07:56:28] VERBOSE[11440] logger.c: -- Processing IE 24 (cs0, Channel Identification)
[Aug 12 07:56:28] VERBOSE[11440] logger.c: q931.c:3641 q931_receive: call 32797 on channel 1 enters state 3 (Outgoing call  Proceeding)
[Aug 12 07:56:28] DEBUG[11440] chan_zap.c: Queuing frame from PRI_EVENT_PROCEEDING on channel 0/1 span 1
[Aug 12 07:56:28] VERBOSE[12476] logger.c:     -- Zap/1-1 is proceeding passing it to SIP/204-0852ecd0
[Aug 12 07:56:29] VERBOSE[11440] logger.c: < Protocol Discriminator: Q.931 (8)  len=13
[Aug 12 07:56:29] VERBOSE[11440] logger.c: < Call Ref: len= 2 (reference 29/0x1D) (Terminator)
[Aug 12 07:56:29] VERBOSE[11440] logger.c: < Message type: ALERTING (1)
[Aug 12 07:56:29] VERBOSE[11440] logger.c: < [1e 02 84 88]
[Aug 12 07:56:29] VERBOSE[11440] logger.c: < Progress Indicator (len= 4) [ Ext: 1  Coding: CCITT (ITU) standard (0)  0: 0  Location: Public network serving the remote user (4)
[Aug 12 07:56:29] VERBOSE[11440] logger.c: <                               Ext: 1  Progress Description: Inband information or appropriate pattern now available. (8) ]
[Aug 12 07:56:29] VERBOSE[11440] logger.c: < [1e 02 84 82]
[Aug 12 07:56:29] VERBOSE[11440] logger.c: < Progress Indicator (len= 4) [ Ext: 1  Coding: CCITT (ITU) standard (0)  0: 0  Location: Public network serving the remote user (4)
[Aug 12 07:56:29] VERBOSE[11440] logger.c: <                               Ext: 1  Progress Description: Called equipment is non-ISDN. (2) ]
[Aug 12 07:56:29] VERBOSE[11440] logger.c: -- Processing IE 30 (cs0, Progress Indicator)
[Aug 12 07:56:29] VERBOSE[11440] logger.c: -- Processing IE 30 (cs0, Progress Indicator)
[Aug 12 07:56:29] VERBOSE[11440] logger.c: q931.c:3554 q931_receive: call 32797 on channel 1 enters state 4 (Call Delivered)
[Aug 12 07:56:29] VERBOSE[12476] logger.c:     -- Zap/1-1 is ringing
[Aug 12 07:56:43] VERBOSE[11440] logger.c: < Protocol Discriminator: Q.931 (8)  len=12
[Aug 12 07:56:43] VERBOSE[11440] logger.c: < Call Ref: len= 2 (reference 29/0x1D) (Terminator)
[Aug 12 07:56:43] VERBOSE[11440] logger.c: < Message type: CONNECT (7)
[Aug 12 07:56:43] VERBOSE[11440] logger.c: < [29 05 0a 08 0c 07 38]
[Aug 12 07:56:43] VERBOSE[11440] logger.c: < Time Date (len= 7) [ [Aug 12 07:56:43] VERBOSE[11440] logger.c: 10[Aug 12 07:56:43] VERBOSE[11440] logger.c: -08[Aug 12 07:56:43] VERBOSE[11440] logger.c: -12[Aug 12 07:56:43] VERBOSE[11440] logger.c:  07[Aug 12 07:56:43] VERBOSE[11440] logger.c: :56[Aug 12 07:56:43] VERBOSE[11440] logger.c:  ]
[Aug 12 07:56:43] VERBOSE[11440] logger.c: -- Processing IE 41 (cs0, Date/Time)
[Aug 12 07:56:43] VERBOSE[11440] logger.c: q931.c:3584 q931_receive: call 32797 on channel 1 enters state 10 (Active)
[Aug 12 07:56:43] VERBOSE[11440] logger.c: > Protocol Discriminator: Q.931 (8)  len=5
[Aug 12 07:56:43] VERBOSE[11440] logger.c: > Call Ref: len= 2 (reference 29/0x1D) (Originator)
[Aug 12 07:56:43] VERBOSE[11440] logger.c: > Message type: CONNECT ACKNOWLEDGE (15)
[Aug 12 07:56:43] DEBUG[11440] chan_zap.c: Echo cancellation already on
**[Aug 12 07:56:43] VERBOSE[12476] logger.c:     -- Zap/1-1 answered SIP/204-0852ecd0
**[Aug 12 08:03:37] DEBUG[12476] chan_zap.c: Set option AUDIO MODE, value: ON(1) on Zap/1-1
**[Aug 12 08:03:37] DEBUG[12476] chan_zap.c: Not yet hungup...  Calling hangup once with icause, and clearing call
**[Aug 12 08:03:37] VERBOSE[12476] logger.c: NEW_HANGUP DEBUG: Calling q931_hangup, ourstate Active, peerstate Connect Request
[Aug 12 08:03:37] VERBOSE[12476] logger.c: q931.c:2973 q931_disconnect: call 32797 on channel 1 enters state 11 (Disconnect Request)
[Aug 12 08:03:37] VERBOSE[12476] logger.c: > Protocol Discriminator: Q.931 (8)  len=9
[Aug 12 08:03:37] VERBOSE[12476] logger.c: > Call Ref: len= 2 (reference 29/0x1D) (Originator)
[Aug 12 08:03:37] VERBOSE[12476] logger.c: > Message type: DISCONNECT (69)
[Aug 12 08:03:37] VERBOSE[12476] logger.c: > [08 02 81 90]
[Aug 12 08:03:37] VERBOSE[12476] logger.c: > Cause (len= 4) [ Ext: 1  Coding: CCITT (ITU) standard (0)  Spare: 0  Location: Private network serving the local user (1)
[Aug 12 08:03:37] VERBOSE[12476] logger.c: >                  Ext: 1  Cause: Normal Clearing (16), Event (1) ]
[Aug 12 08:03:37] DEBUG[12476] chan_zap.c: Set option AUDIO MODE, value: OFF(0) on Zap/1-1
[Aug 12 08:03:37] VERBOSE[12476] logger.c:     -- Hungup 'Zap/1-1'
[Aug 12 08:03:37] VERBOSE[12476] logger.c:   == Spawn extension (macro-dialout-trunk, s, 20) exited non-zero on 'SIP/204-0852ecd0' in macro 'dialout-trunk'
[Aug 12 08:03:37] VERBOSE[12476] logger.c:   == Spawn extension (macro-dialout-trunk, s, 20) exited non-zero on 'SIP/204-0852ecd0'
[Aug 12 08:03:37] VERBOSE[12476] logger.c:     -- Executing [h@macro-dialout-trunk:1] Macro("SIP/204-0852ecd0", "hangupcall|") in new stack
[Aug 12 08:03:37] VERBOSE[12476] logger.c:     -- Executing [s@macro-hangupcall:1] ResetCDR("SIP/204-0852ecd0", "w") in new stack
[Aug 12 08:03:37] DEBUG[12476] app_macro.c: Executed application: ResetCDR
[Aug 12 08:03:37] VERBOSE[12476] logger.c:     -- Executing [s@macro-hangupcall:2] NoCDR("SIP/204-0852ecd0", "") in new stack
[Aug 12 08:03:37] DEBUG[12476] app_macro.c: Executed application: NoCDR
[Aug 12 08:03:37] VERBOSE[12476] logger.c:     -- Executing [s@macro-hangupcall:3] GotoIf("SIP/204-0852ecd0", "1?skiprg") in new stack
[Aug 12 08:03:37] VERBOSE[12476] logger.c:     -- Goto (macro-hangupcall,s,6)
[Aug 12 08:03:37] DEBUG[12476] app_macro.c: Executed application: GotoIf
[Aug 12 08:03:37] VERBOSE[12476] logger.c:     -- Executing [s@macro-hangupcall:6] GotoIf("SIP/204-0852ecd0", "1?skipblkvm") in new stack
[Aug 12 08:03:37] VERBOSE[12476] logger.c:     -- Goto (macro-hangupcall,s,9)
[Aug 12 08:03:37] DEBUG[12476] app_macro.c: Executed application: GotoIf
[Aug 12 08:03:37] VERBOSE[12476] logger.c:     -- Executing [s@macro-hangupcall:9] GotoIf("SIP/204-0852ecd0", "1?theend") in new stack
[Aug 12 08:03:37] VERBOSE[12476] logger.c:     -- Goto (macro-hangupcall,s,11)
[Aug 12 08:03:37] DEBUG[12476] app_macro.c: Executed application: GotoIf
[Aug 12 08:03:37] VERBOSE[12476] logger.c:     -- Executing [s@macro-hangupcall:11] Hangup("SIP/204-0852ecd0", "") in new stack
[Aug 12 08:03:37] VERBOSE[12476] logger.c:   == Spawn extension (macro-hangupcall, s, 11) exited non-zero on 'SIP/204-0852ecd0' in macro 'hangupcall'
[Aug 12 08:03:37] VERBOSE[12476] logger.c:   == Spawn extension (macro-hangupcall, s, 11) exited non-zero on 'SIP/204-0852ecd0'
[Aug 12 08:03:37] VERBOSE[11440] logger.c: < Protocol Discriminator: Q.931 (8)  len=5
[Aug 12 08:03:37] VERBOSE[11440] logger.c: < Call Ref: len= 2 (reference 29/0x1D) (Terminator)
[Aug 12 08:03:37] VERBOSE[11440] logger.c: < Message type: RELEASE (77)
[Aug 12 08:03:37] VERBOSE[11440] logger.c: q931.c:3759 q931_receive: call 32797 on channel 1 enters state 0 (Null)
[Aug 12 08:03:37] VERBOSE[11440] logger.c: NEW_HANGUP DEBUG: Calling q931_hangup, ourstate Null, peerstate Release Request
[Aug 12 08:03:37] VERBOSE[11440] logger.c: > Protocol Discriminator: Q.931 (8)  len=9
[Aug 12 08:03:37] VERBOSE[11440] logger.c: > Call Ref: len= 2 (reference 29/0x1D) (Originator)
[Aug 12 08:03:37] VERBOSE[11440] logger.c: > Message type: RELEASE COMPLETE (90)
[Aug 12 08:03:37] VERBOSE[11440] logger.c: > [08 02 81 90]
[Aug 12 08:03:37] VERBOSE[11440] logger.c: > Cause (len= 4) [ Ext: 1  Coding: CCITT (ITU) standard (0)  Spare: 0  Location: Private network serving the local user (1)
[Aug 12 08:03:37] VERBOSE[11440] logger.c: >                  Ext: 1  Cause: Normal Clearing (16), Event (1) ]
[Aug 12 08:03:37] VERBOSE[11440] logger.c: NEW_HANGUP DEBUG: Calling q931_hangup, ourstate Null, peerstate Null
[Aug 12 08:03:37] VERBOSE[11440] logger.c: NEW_HANGUP DEBUG: Destroying the call, ourstate Null, peerstate Null



Chan_zap seems to be trying to disconnect the call.