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
[5053203...@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
[...@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
[...@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
[...@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
[...@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
[...@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
[...@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
[...@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
[...@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
[...@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
[...@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
[...@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
[...@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
[5053203...@from-internal-ntc-custom:2] Set("SIP/611-b7b9ae38", "_NODEST=") in
new stack
[Jun 21 08:53:28] VERBOSE[21559] logger.c: -- Executing
[5053203...@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
[...@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
[...@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
[...@macro-record-enable:5] MacroExit("SIP/611-b7b9ae38", "") in new stack
[Jun 21 08:53:29] VERBOSE[21559] logger.c: -- Executing
[5053203...@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
[...@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
[...@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
[...@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
[...@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
[...@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
[...@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
[...@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
[...@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
[...@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
[...@macro-dialout-trunk:11] Macro("SIP/611-b7b9ae38", "outbound-callerid|2")
in new stack
[Jun 21 08:53:29] VERBOSE[21559] logger.c: -- Executing
[...@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
[...@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
[...@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
[...@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
[...@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
[...@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
[...@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
[...@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
[...@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
[...@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
[...@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
[...@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
[...@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
[...@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
[...@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
[...@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
[...@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
[...@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
[...@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 [...@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
[...@macro-dialout-trunk:1] Macro("SIP/611-b7b9ae38", "hangupcall|") in new
stack
[Jun 21 08:53:56] VERBOSE[21559] logger.c: -- Executing
[...@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
[...@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
[...@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
[...@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
[...@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
[...@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
--
_____________________________________________________________________
-- Bandwidth and Colocation Provided by http://www.api-digital.com --
New to Asterisk? Join us for a live introductory webinar every Thurs:
http://www.asterisk.org/hello
asterisk-users mailing list
To UNSUBSCRIBE or update options visit:
http://lists.digium.com/mailman/listinfo/asterisk-users
