[asterisk-users] How to tell if a dropped call is my fault
Douglas Mortensen
doug at impalanetworks.com
Mon Jun 21 12:39:35 CDT 2010
I just had a user report that they called out to someone on a cell phone this morning, and after a short conversation, the call was dropped/lost. The person on the cell phone says that this is very rare, and would not suspect the dropped/lost call to be on their side. I have looked at the asterisk/full log as thoroughly as I can, and have pasted the lines which seem relevant to that call below. From what I can tell, only the last 26 lines of the log really pertain to the actual call being connected, then hung up. The preceding lines are just setting the caller id, and other related call-setup logging.
Is it common to have a dropped call being caused by asterisk? How would it show up in the log? The only possible thing I can see in the logs, is the "exited non-zero", which I've pasted here:
[Jun 21 08:53:29] DEBUG[21559] chan_zap.c: Dialing '15053203372'
[Jun 21 08:53:29] DEBUG[21559] chan_zap.c: Deferring dialing...
[Jun 21 08:53:29] VERBOSE[21559] logger.c: -- Called g1/15053203372
[Jun 21 08:53:29] DEBUG[21559] chan_zap.c: Sent deferred digit string: T15053203372w
[Jun 21 08:53:32] VERBOSE[21559] logger.c: -- Zap/25-1 answered SIP/611-b7b9ae38
[Jun 21 08:53:56] VERBOSE[21559] logger.c: -- Hungup 'Zap/25-1'
[Jun 21 08:53:56] VERBOSE[21559] logger.c: == Spawn extension (macro-dialout-trunk, s, 19) exited non-zero on 'SIP/611-b7b9ae38' in macro 'dialout-trunk'
[Jun 21 08:53:56] VERBOSE[21559] logger.c: == Spawn extension (macro-dialout-trunk, s, 19) exited non-zero on 'SIP/611-b7b9ae38'
My experience is that with most programs, if they exit with a non-zero status, that means that there was some kind of error. If that is the case, I cannot tell what that would have been, based on the log.
As far a the log/verbose level is concerned, asterisk was started as /usr/sbin/asterisk -vvvg
Here's the complete asterisk/full as it pertains to the given time period. I do think that there are a few lines below that are relating to a different call, which we're not concerned with.
[Jun 21 08:53:28] VERBOSE[22157] logger.c: Extension Changed 611[ext-local] new state InUse for Notify User 610
[Jun 21 08:53:28] VERBOSE[21559] logger.c: -- Executing [5053203372 at from-internal-NTC-custom:1] Macro("SIP/611-b7b9ae38", "user-callerid|SKIPTTL|") in new stack
[Jun 21 08:53:28] VERBOSE[21559] logger.c: -- Executing [s at macro-user-callerid:1] Set("SIP/611-b7b9ae38", "AMPUSER=611") in new stack
[Jun 21 08:53:28] DEBUG[21559] app_macro.c: Executed application: Set
[Jun 21 08:53:28] VERBOSE[21559] logger.c: -- Executing [s at macro-user-callerid:2] GotoIf("SIP/611-b7b9ae38", "0?report") in new stack
[Jun 21 08:53:28] DEBUG[21559] app_macro.c: Executed application: GotoIf
[Jun 21 08:53:28] VERBOSE[21559] logger.c: -- Executing [s at macro-user-callerid:3] ExecIf("SIP/611-b7b9ae38", "1|Set|REALCALLERIDNUM=611") in new stack
[Jun 21 08:53:28] DEBUG[21559] app_macro.c: Executed application: ExecIf
[Jun 21 08:53:28] VERBOSE[21559] logger.c: -- Executing [s at macro-user-callerid:4] Set("SIP/611-b7b9ae38", "AMPUSER=611") in new stack
[Jun 21 08:53:28] DEBUG[21559] app_macro.c: Executed application: Set
[Jun 21 08:53:28] VERBOSE[21559] logger.c: -- Executing [s at macro-user-callerid:5] Set("SIP/611-b7b9ae38", "AMPUSERCIDNAME=Kurt") in new stack
[Jun 21 08:53:28] DEBUG[21559] app_macro.c: Executed application: Set
[Jun 21 08:53:28] VERBOSE[21559] logger.c: -- Executing [s at macro-user-callerid:6] GotoIf("SIP/611-b7b9ae38", "0?report") in new stack
[Jun 21 08:53:28] DEBUG[21559] app_macro.c: Executed application: GotoIf
[Jun 21 08:53:28] VERBOSE[21559] logger.c: -- Executing [s at macro-user-callerid:7] Set("SIP/611-b7b9ae38", "AMPUSERCID=611") in new stack
[Jun 21 08:53:28] DEBUG[21559] app_macro.c: Executed application: Set
[Jun 21 08:53:28] VERBOSE[21559] logger.c: -- Executing [s at macro-user-callerid:8] Set("SIP/611-b7b9ae38", "CALLERID(all)="Kurt" <611>") in new stack
[Jun 21 08:53:28] DEBUG[21559] app_macro.c: Executed application: Set
[Jun 21 08:53:28] VERBOSE[21559] logger.c: -- Executing [s at macro-user-callerid:9] Set("SIP/611-b7b9ae38", "REALCALLERIDNUM=611") in new stack
[Jun 21 08:53:28] DEBUG[21559] app_macro.c: Executed application: Set
[Jun 21 08:53:28] VERBOSE[21559] logger.c: -- Executing [s at macro-user-callerid:10] ExecIf("SIP/611-b7b9ae38", "0|Set|CHANNEL(language)=") in new stack
[Jun 21 08:53:28] DEBUG[21559] app_macro.c: Executed application: ExecIf
[Jun 21 08:53:28] VERBOSE[21559] logger.c: -- Executing [s at macro-user-callerid:11] GotoIf("SIP/611-b7b9ae38", "1?continue") in new stack
[Jun 21 08:53:28] VERBOSE[21559] logger.c: -- Goto (macro-user-callerid,s,20)
[Jun 21 08:53:28] DEBUG[21559] app_macro.c: Executed application: GotoIf
[Jun 21 08:53:28] VERBOSE[21559] logger.c: -- Executing [s at macro-user-callerid:20] NoOp("SIP/611-b7b9ae38", "Using CallerID "Kurt" <611>") in new stack
[Jun 21 08:53:28] DEBUG[21559] app_macro.c: Executed application: Noop
[Jun 21 08:53:28] VERBOSE[21559] logger.c: -- Executing [5053203372 at from-internal-NTC-custom:2] Set("SIP/611-b7b9ae38", "_NODEST=") in new stack
[Jun 21 08:53:28] VERBOSE[21559] logger.c: -- Executing [5053203372 at from-internal-NTC-custom:3] Macro("SIP/611-b7b9ae38", "record-enable|611|OUT|") in new stack
[Jun 21 08:53:28] VERBOSE[21559] logger.c: -- Executing [s at macro-record-enable:1] GotoIf("SIP/611-b7b9ae38", "1?check") in new stack
[Jun 21 08:53:28] VERBOSE[21559] logger.c: -- Goto (macro-record-enable,s,4)
[Jun 21 08:53:28] DEBUG[21559] app_macro.c: Executed application: GotoIf
[Jun 21 08:53:28] VERBOSE[21559] logger.c: -- Executing [s at macro-record-enable:4] AGI("SIP/611-b7b9ae38", "recordingcheck|20100621-085328|1277132008.6419") in new stack
[Jun 21 08:53:28] VERBOSE[21559] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
[Jun 21 08:53:29] VERBOSE[21559] logger.c: recordingcheck|20100621-085328|1277132008.6419: Outbound recording not enabled
[Jun 21 08:53:29] VERBOSE[21559] logger.c: -- AGI Script recordingcheck completed, returning 0
[Jun 21 08:53:29] DEBUG[21559] app_macro.c: Executed application: AGI
[Jun 21 08:53:29] VERBOSE[21559] logger.c: -- Executing [s at macro-record-enable:5] MacroExit("SIP/611-b7b9ae38", "") in new stack
[Jun 21 08:53:29] VERBOSE[21559] logger.c: -- Executing [5053203372 at from-internal-NTC-custom:4] Macro("SIP/611-b7b9ae38", "dialout-trunk|2|5053203372||") in new stack
[Jun 21 08:53:29] VERBOSE[21559] logger.c: -- Executing [s at macro-dialout-trunk:1] Set("SIP/611-b7b9ae38", "DIAL_TRUNK=2") in new stack
[Jun 21 08:53:29] DEBUG[21559] app_macro.c: Executed application: Set
[Jun 21 08:53:29] DEBUG[21559] func_db.c: DB: AMPUSER/611/pinless not found in database.
[Jun 21 08:53:29] VERBOSE[21559] logger.c: -- Executing [s at macro-dialout-trunk:2] GosubIf("SIP/611-b7b9ae38", "0?sub-pincheck|s|1") in new stack
[Jun 21 08:53:29] DEBUG[21559] app_macro.c: Executed application: GosubIf
[Jun 21 08:53:29] DEBUG[21559] func_db.c: DB: AMPUSER/611/pinless not found in database.
[Jun 21 08:53:29] VERBOSE[21559] logger.c: -- Executing [s at macro-dialout-trunk:3] GotoIf("SIP/611-b7b9ae38", "0?disabletrunk|1") in new stack
[Jun 21 08:53:29] DEBUG[21559] app_macro.c: Executed application: GotoIf
[Jun 21 08:53:29] VERBOSE[21559] logger.c: -- Executing [s at macro-dialout-trunk:4] Set("SIP/611-b7b9ae38", "DIAL_NUMBER=5053203372") in new stack
[Jun 21 08:53:29] DEBUG[21559] app_macro.c: Executed application: Set
[Jun 21 08:53:29] VERBOSE[21559] logger.c: -- Executing [s at macro-dialout-trunk:5] Set("SIP/611-b7b9ae38", "DIAL_TRUNK_OPTIONS=tr") in new stack
[Jun 21 08:53:29] DEBUG[21559] app_macro.c: Executed application: Set
[Jun 21 08:53:29] VERBOSE[21559] logger.c: -- Executing [s at macro-dialout-trunk:6] Set("SIP/611-b7b9ae38", "OUTBOUND_GROUP=OUT_2") in new stack
[Jun 21 08:53:29] DEBUG[21559] app_macro.c: Executed application: Set
[Jun 21 08:53:29] VERBOSE[21559] logger.c: -- Executing [s at macro-dialout-trunk:7] GotoIf("SIP/611-b7b9ae38", "1?nomax") in new stack
[Jun 21 08:53:29] VERBOSE[21559] logger.c: -- Goto (macro-dialout-trunk,s,9)
[Jun 21 08:53:29] DEBUG[21559] app_macro.c: Executed application: GotoIf
[Jun 21 08:53:29] VERBOSE[21559] logger.c: -- Executing [s at macro-dialout-trunk:9] GotoIf("SIP/611-b7b9ae38", "0?skipoutcid") in new stack
[Jun 21 08:53:29] DEBUG[21559] app_macro.c: Executed application: GotoIf
[Jun 21 08:53:29] VERBOSE[21559] logger.c: -- Executing [s at macro-dialout-trunk:10] Set("SIP/611-b7b9ae38", "DIAL_TRUNK_OPTIONS=") in new stack
[Jun 21 08:53:29] DEBUG[21559] app_macro.c: Executed application: Set
[Jun 21 08:53:29] VERBOSE[21559] logger.c: -- Executing [s at macro-dialout-trunk:11] Macro("SIP/611-b7b9ae38", "outbound-callerid|2") in new stack
[Jun 21 08:53:29] VERBOSE[21559] logger.c: -- Executing [s at macro-outbound-callerid:1] ExecIf("SIP/611-b7b9ae38", "0|SetCallerPres|") in new stack
[Jun 21 08:53:29] DEBUG[21559] app_macro.c: Executed application: ExecIf
[Jun 21 08:53:29] VERBOSE[21559] logger.c: -- Executing [s at macro-outbound-callerid:2] ExecIf("SIP/611-b7b9ae38", "0|Set|REALCALLERIDNUM=611") in new stack
[Jun 21 08:53:29] DEBUG[21559] app_macro.c: Executed application: ExecIf
[Jun 21 08:53:29] VERBOSE[21559] logger.c: -- Executing [s at macro-outbound-callerid:3] GotoIf("SIP/611-b7b9ae38", "1?normcid") in new stack
[Jun 21 08:53:29] VERBOSE[21559] logger.c: -- Goto (macro-outbound-callerid,s,6)
[Jun 21 08:53:29] DEBUG[21559] app_macro.c: Executed application: GotoIf
[Jun 21 08:53:29] VERBOSE[21559] logger.c: -- Executing [s at macro-outbound-callerid:6] Set("SIP/611-b7b9ae38", "USEROUTCID=<5053251685>") in new stack
[Jun 21 08:53:29] DEBUG[21559] app_macro.c: Executed application: Set
[Jun 21 08:53:29] DEBUG[21559] func_db.c: DB: DEVICE/611/emergency_cid not found in database.
[Jun 21 08:53:29] VERBOSE[21559] logger.c: -- Executing [s at macro-outbound-callerid:7] Set("SIP/611-b7b9ae38", "EMERGENCYCID=") in new stack
[Jun 21 08:53:29] DEBUG[21559] app_macro.c: Executed application: Set
[Jun 21 08:53:29] VERBOSE[21559] logger.c: -- Executing [s at macro-outbound-callerid:8] Set("SIP/611-b7b9ae38", "TRUNKOUTCID=") in new stack
[Jun 21 08:53:29] DEBUG[21559] app_macro.c: Executed application: Set
[Jun 21 08:53:29] VERBOSE[21559] logger.c: -- Executing [s at macro-outbound-callerid:9] GotoIf("SIP/611-b7b9ae38", "1?trunkcid") in new stack
[Jun 21 08:53:29] VERBOSE[21559] logger.c: -- Goto (macro-outbound-callerid,s,12)
[Jun 21 08:53:29] DEBUG[21559] app_macro.c: Executed application: GotoIf
[Jun 21 08:53:29] VERBOSE[21559] logger.c: -- Executing [s at macro-outbound-callerid:12] ExecIf("SIP/611-b7b9ae38", "0|Set|CALLERID(all)=") in new stack
[Jun 21 08:53:29] DEBUG[21559] app_macro.c: Executed application: ExecIf
[Jun 21 08:53:29] VERBOSE[21559] logger.c: -- Executing [s at macro-outbound-callerid:13] ExecIf("SIP/611-b7b9ae38", "1|Set|CALLERID(all)=<5053251685>") in new stack
[Jun 21 08:53:29] DEBUG[21559] app_macro.c: Executed application: ExecIf
[Jun 21 08:53:29] DEBUG[21559] app_macro.c: Last app: Set|CALLERID(all)=<5053251685>
[Jun 21 08:53:29] VERBOSE[21559] logger.c: -- Executing [s at macro-outbound-callerid:14] ExecIf("SIP/611-b7b9ae38", "0|SetCallerPres|prohib_passed_screen") in new stack
[Jun 21 08:53:29] DEBUG[21559] app_macro.c: Executed application: ExecIf
[Jun 21 08:53:29] DEBUG[21559] app_macro.c: Executed application: Macro
[Jun 21 08:53:29] VERBOSE[21559] logger.c: -- Executing [s at macro-dialout-trunk:12] ExecIf("SIP/611-b7b9ae38", "1|AGI|fixlocalprefix") in new stack
[Jun 21 08:53:29] VERBOSE[21559] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/fixlocalprefix
[Jun 21 08:53:29] VERBOSE[21559] logger.c: == fixlocalprefix: Dialpattern 1+NXXNXXXXXX matched. 5053203372 -> 15053203372
[Jun 21 08:53:29] VERBOSE[21559] logger.c: -- AGI Script fixlocalprefix completed, returning 0
[Jun 21 08:53:29] DEBUG[21559] app_macro.c: Executed application: ExecIf
[Jun 21 08:53:29] DEBUG[21559] app_macro.c: Last app: AGI|fixlocalprefix
[Jun 21 08:53:29] VERBOSE[21559] logger.c: -- Executing [s at macro-dialout-trunk:13] Set("SIP/611-b7b9ae38", "OUTNUM=15053203372") in new stack
[Jun 21 08:53:29] DEBUG[21559] app_macro.c: Executed application: Set
[Jun 21 08:53:29] VERBOSE[21559] logger.c: -- Executing [s at macro-dialout-trunk:14] Set("SIP/611-b7b9ae38", "custom=ZAP/g1") in new stack
[Jun 21 08:53:29] DEBUG[21559] app_macro.c: Executed application: Set
[Jun 21 08:53:29] VERBOSE[21559] logger.c: -- Executing [s at macro-dialout-trunk:15] ExecIf("SIP/611-b7b9ae38", "0|Set|DIAL_TRUNK_OPTIONS=M(setmusic^)") in new stack
[Jun 21 08:53:29] DEBUG[21559] app_macro.c: Executed application: ExecIf
[Jun 21 08:53:29] VERBOSE[21559] logger.c: -- Executing [s at macro-dialout-trunk:16] Macro("SIP/611-b7b9ae38", "dialout-trunk-predial-hook|") in new stack
[Jun 21 08:53:29] VERBOSE[21559] logger.c: -- Executing [s at macro-dialout-trunk-predial-hook:1] MacroExit("SIP/611-b7b9ae38", "") in new stack
[Jun 21 08:53:29] DEBUG[21559] app_macro.c: Executed application: Macro
[Jun 21 08:53:29] VERBOSE[21559] logger.c: -- Executing [s at macro-dialout-trunk:17] GotoIf("SIP/611-b7b9ae38", "0?bypass|1") in new stack
[Jun 21 08:53:29] DEBUG[21559] app_macro.c: Executed application: GotoIf
[Jun 21 08:53:29] VERBOSE[21559] logger.c: -- Executing [s at macro-dialout-trunk:18] GotoIf("SIP/611-b7b9ae38", "0?customtrunk") in new stack
[Jun 21 08:53:29] DEBUG[21559] app_macro.c: Executed application: GotoIf
[Jun 21 08:53:29] VERBOSE[21559] logger.c: -- Executing [s at macro-dialout-trunk:19] Dial("SIP/611-b7b9ae38", "ZAP/g1/15053203372|300|") in new stack
[Jun 21 08:53:29] DEBUG[21559] chan_zap.c: Dialing '15053203372'
[Jun 21 08:53:29] DEBUG[21559] chan_zap.c: Deferring dialing...
[Jun 21 08:53:29] VERBOSE[21559] logger.c: -- Called g1/15053203372
[Jun 21 08:53:29] DEBUG[21559] chan_zap.c: Sent deferred digit string: T15053203372w
[Jun 21 08:53:32] VERBOSE[21559] logger.c: -- Zap/25-1 answered SIP/611-b7b9ae38
[Jun 21 08:53:42] VERBOSE[21484] logger.c: -- Executing [s at ivr-14:13] WaitExten("Zap/1-1", "|") in new stack
[Jun 21 08:53:56] VERBOSE[21559] logger.c: -- Hungup 'Zap/25-1'
[Jun 21 08:53:56] VERBOSE[21559] logger.c: == Spawn extension (macro-dialout-trunk, s, 19) exited non-zero on 'SIP/611-b7b9ae38' in macro 'dialout-trunk'
[Jun 21 08:53:56] VERBOSE[21559] logger.c: == Spawn extension (macro-dialout-trunk, s, 19) exited non-zero on 'SIP/611-b7b9ae38'
[Jun 21 08:53:56] VERBOSE[21559] logger.c: -- Executing [h at macro-dialout-trunk:1] Macro("SIP/611-b7b9ae38", "hangupcall|") in new stack
[Jun 21 08:53:56] VERBOSE[21559] logger.c: -- Executing [s at macro-hangupcall:1] ResetCDR("SIP/611-b7b9ae38", "vw") in new stack
[Jun 21 08:53:56] DEBUG[21559] app_macro.c: Executed application: ResetCDR
[Jun 21 08:53:56] VERBOSE[21559] logger.c: -- Executing [s at macro-hangupcall:2] NoCDR("SIP/611-b7b9ae38", "") in new stack
[Jun 21 08:53:56] DEBUG[21559] app_macro.c: Executed application: NoCDR
[Jun 21 08:53:56] VERBOSE[21559] logger.c: -- Executing [s at macro-hangupcall:3] GotoIf("SIP/611-b7b9ae38", "1?skiprg") in new stack
[Jun 21 08:53:56] VERBOSE[21559] logger.c: -- Goto (macro-hangupcall,s,6)
[Jun 21 08:53:56] DEBUG[21559] app_macro.c: Executed application: GotoIf
[Jun 21 08:53:56] VERBOSE[21559] logger.c: -- Executing [s at macro-hangupcall:6] GotoIf("SIP/611-b7b9ae38", "1?skipblkvm") in new stack
[Jun 21 08:53:56] VERBOSE[21559] logger.c: -- Goto (macro-hangupcall,s,9)
[Jun 21 08:53:56] DEBUG[21559] app_macro.c: Executed application: GotoIf
[Jun 21 08:53:56] VERBOSE[21559] logger.c: -- Executing [s at macro-hangupcall:9] GotoIf("SIP/611-b7b9ae38", "1?theend") in new stack
[Jun 21 08:53:56] VERBOSE[21559] logger.c: -- Goto (macro-hangupcall,s,11)
[Jun 21 08:53:56] DEBUG[21559] app_macro.c: Executed application: GotoIf
[Jun 21 08:53:56] VERBOSE[21559] logger.c: -- Executing [s at macro-hangupcall:11] Hangup("SIP/611-b7b9ae38", "") in new stack
[Jun 21 08:53:56] VERBOSE[21559] logger.c: == Spawn extension (macro-hangupcall, s, 11) exited non-zero on 'SIP/611-b7b9ae38' in macro 'hangupcall'
[Jun 21 08:53:56] VERBOSE[21559] logger.c: == Spawn extension (macro-hangupcall, s, 11) exited non-zero on 'SIP/611-b7b9ae38'
[Jun 21 08:53:56] VERBOSE[22157] logger.c: Extension Changed 611[ext-local] new state Idle for Notify User 610
I appreciate your help and any suggestions on this.
Thanks,
-
Doug Mortensen
Network Consultant
Impala Networks Inc
CCNA, MCP, Security+, A+
Linux+, Network+, Server+
.
www.impalanetworks.com
P: (505) 327-7300
F: (505) 327-7545
More information about the asterisk-users
mailing list