Incoming ZAP disconnects 6:16 mins

[lopaka]

I have a problem where all incoming ZAP calls are automatically disconnected at exactly 6:16 minutes. Any suggestions where to start troubleshooting?

 

[thunderheart]

Really?

Every single time? What do you see in the log?

Dallas

 

[lopaka]

What command do I need to use to view the log, or can I see what I need to from the web interface?

 

[lopaka]

I added "callprogress=yes" to zapata.conf and that seems to have fixed my problem. Crossing fingers

 

[lopaka]

Well, the problem is back. Any help appreciated. Incoming calls from PSTN are dropped at exactly 6:16 mins. I do have an IVR with 2 options to go to either of 2 extensions. 1 extension is a SIP phone on an ATA and the other is coming from a digium card. the Both do the same thing and disconnect while you're talking at exactly 6:16.

 

[thunderheart]

Look at your log

From a bash prompt do a tail -50 /var/log/asterisk/full and look around where you see the ZAP channel hang up. You can pipe it into a file and send it to me if you want. Don't send the whole log file though as it is pretty hefty: kimmyd at nc dot rr dot com. I'm also over in the IRC channel #pbxinaflash on freenode.

Dallas

 

[lopaka]

This is what the log shows around the disconnect

[Sep 20 09:49:36] VERBOSE[19480] logger.c: == Manager 'admin' logged on from 127.0.0.1
[Sep 20 09:49:36] VERBOSE[19476] logger.c: dialparties.agi: Caller ID name is 'unknown' number is 'unknown'
[Sep 20 09:49:36] VERBOSE[19476] logger.c: dialparties.agi: Methodology of ring is 'none'
[Sep 20 09:49:36] VERBOSE[19476] logger.c: -- dialparties.agi: Added extension 1004 to extension map
[Sep 20 09:49:36] VERBOSE[19476] logger.c: -- dialparties.agi: Extension 1004 cf is disabled
[Sep 20 09:49:36] VERBOSE[19476] logger.c: -- dialparties.agi: Extension 1004 do not disturb is disabled
[Sep 20 09:49:36] VERBOSE[19476] logger.c: -- dialparties.agi: DbDel CALLTRACE/1004 - Caller ID is not defined
[Sep 20 09:49:36] VERBOSE[19476] logger.c: -- dialparties.agi: Filtered ARG3: 1004
[Sep 20 09:49:36] VERBOSE[19476] logger.c: -- AGI Script dialparties.agi completed, returning 0
[Sep 20 09:49:36] DEBUG[19476] app_macro.c: Executed application: AGI
[Sep 20 09:49:36] VERBOSE[19476] logger.c: -- Executing [s@macro-dial:7] Dial("Zap/1-1", "ZAP/2|20|tr") in new stack
[Sep 20 09:49:36] VERBOSE[19476] logger.c: -- Called 2
[Sep 20 09:49:36] VERBOSE[19480] logger.c: == Manager 'admin' logged off from 127.0.0.1
[Sep 20 09:49:36] VERBOSE[19476] logger.c: -- Zap/2-1 is ringing
[Sep 20 09:49:38] VERBOSE[19476] logger.c: -- Zap/2-1 is ringing
[Sep 20 09:49:44] VERBOSE[19476] logger.c: -- Zap/2-1 is ringing
[Sep 20 09:49:50] VERBOSE[19476] logger.c: -- Zap/2-1 is ringing
[Sep 20 09:49:56] VERBOSE[19476] logger.c: -- Zap/2-1 is ringing
[Sep 20 09:49:57] DEBUG[19476] chan_zap.c: Engaged echo training on channel 2
[Sep 20 09:49:57] DEBUG[19476] chan_zap.c: channel 2 answered
[Sep 20 09:49:57] VERBOSE[19476] logger.c: -- Zap/2-1 answered Zap/1-1
[Sep 20 09:51:22] DEBUG[19476] chan_zap.c: Started VLDTMF digit 'A'
[Sep 20 09:51:22] DEBUG[19476] chan_zap.c: Ending VLDTMF digit 'A'
[Sep 20 09:55:01] DEBUG[19476] chan_zap.c: Started VLDTMF digit '1'
[Sep 20 09:55:01] DEBUG[19476] chan_zap.c: Ending VLDTMF digit '1'
[Sep 20 09:55:42] VERBOSE[19476] logger.c: -- Hungup 'Zap/2-1'
[Sep 20 09:55:42] VERBOSE[19476] logger.c: == Spawn extension (macro-dial, s, 7) exited non-zero on 'Zap/1-1' in macro 'dial'
[Sep 20 09:55:42] VERBOSE[19476] logger.c: == Spawn extension (macro-dial, s, 7) exited non-zero on 'Zap/1-1' in macro 'exten-vm'
[Sep 20 09:55:42] VERBOSE[19476] logger.c: == Spawn extension (macro-dial, s, 7) exited non-zero on 'Zap/1-1'
[Sep 20 09:55:42] VERBOSE[19476] logger.c: -- Executing [h@macro-dial:1] Macro("Zap/1-1", "hangupcall") in new stack
[Sep 20 09:55:42] VERBOSE[19476] logger.c: -- Executing [s@macro-hangupcall:1] ResetCDR("Zap/1-1", "w") in new stack
[Sep 20 09:55:42] DEBUG[19476] app_macro.c: Executed application: ResetCDR
[Sep 20 09:55:42] VERBOSE[19476] logger.c: -- Executing [s@macro-hangupcall:2] NoCDR("Zap/1-1", "") in new stack
[Sep 20 09:55:42] DEBUG[19476] app_macro.c: Executed application: NoCDR
[Sep 20 09:55:42] VERBOSE[19476] logger.c: -- Executing [s@macro-hangupcall:3] GotoIf("Zap/1-1", "1?skiprg") in new stack
[Sep 20 09:55:42] VERBOSE[19476] logger.c: -- Goto (macro-hangupcall,s,6)
[Sep 20 09:55:42] DEBUG[19476] app_macro.c: Executed application: GotoIf
[Sep 20 09:55:42] VERBOSE[19476] logger.c: -- Executing [s@macro-hangupcall:6] GotoIf("Zap/1-1", "1?skipblkvm") in new stack
[Sep 20 09:55:42] VERBOSE[19476] logger.c: -- Goto (macro-hangupcall,s,9)
[Sep 20 09:55:42] DEBUG[19476] app_macro.c: Executed application: GotoIf
[Sep 20 09:55:42] VERBOSE[19476] logger.c: -- Executing [s@macro-hangupcall:9] GotoIf("Zap/1-1", "1?theend") in new stack
[Sep 20 09:55:42] VERBOSE[19476] logger.c: -- Goto (macro-hangupcall,s,11)
[Sep 20 09:55:42] DEBUG[19476] app_macro.c: Executed application: GotoIf
[Sep 20 09:55:42] VERBOSE[19476] logger.c: -- Executing [s@macro-hangupcall:11] Hangup("Zap/1-1", "") in new stack
[Sep 20 09:55:42] VERBOSE[19476] logger.c: == Spawn extension (macro-hangupcall, s, 11) exited non-zero on 'Zap/1-1' in macro 'hangupcall'
[Sep 20 09:55:42] VERBOSE[19476] logger.c: == Spawn extension (macro-hangupcall, s, 11) exited non-zero on 'Zap/1-1'
[Sep 20 09:55:42] VERBOSE[19476] logger.c: -- Hungup 'Zap/1-1'
[Sep 20 09:55:54] VERBOSE[19491] logger.c: -- Starting simple switch on 'Zap/2-1'
[Sep 20 09:56:05] VERBOSE[19491] logger.c: -- Executing [18313323239@from-internal:1] Macro("Zap/2-1", "user-callerid|SKIPTTL|") in new stack
[Sep 20 09:56:05] VERBOSE[19491] logger.c: -- Executing [s@macro-user-callerid:1] NoOp("Zap/2-1", "user-callerid: device 1004") in new stack
[Sep 20 09:56:05] DEBUG[19491] app_macro.c: Executed application: Noop
[Sep 20 09:56:05] VERBOSE[19491] logger.c: -- Executing [s@macro-user-callerid:2] Set("Zap/2-1", "AMPUSER=1004") in new stack
[Sep 20 09:56:05] DEBUG[19491] app_macro.c: Executed application: Set
[Sep 20 09:56:05] VERBOSE[19491] logger.c: -- Executing [s@macro-user-callerid:3] GotoIf("Zap/2-1", "0?report") in new stack
[Sep 20 09:56:05] DEBUG[19491] app_macro.c: Executed application: GotoIf

 

[thunderheart]

Zap 2-1

Hey Lopaka,

Looks like Zap channel 2 just suddenly hung up. That is your handset right? What equipment are you using? I'm guessing a FXS module to a analog phone.

Dallas

 

[lopaka]

Its a digium TDM400P card. I've had a couple different wireless dect phones but they both do the same thing. Any suggestions?

 

[thunderheart]

Set up a Softphone

Set up a softphone (use VOIPER since it does SIP and IAX). Repeat the experiment and report back. Set it up as SIP first then IAX.

Dallas

 

[Alex728]

that doesn't look like it should be there

[Sep 20 09:51:22] DEBUG[19476] chan_zap.c: Started VLDTMF digit 'A'
[Sep 20 09:51:22] DEBUG[19476] chan_zap.c: Ending VLDTMF digit 'A'
[Sep 20 09:55:01] DEBUG[19476] chan_zap.c: Started VLDTMF digit '1'
[Sep 20 09:55:01] DEBUG[19476] chan_zap.c: Ending VLDTMF digit '1'

DTMF digits "A-D" aren't normally found on a phone but are occasionally used by telcos and PBXs for supervisory purposes (including disconnect supervision!)

it appears a "A" digit is getting sent to the trunk somehow, the telco's equipment is probably programmed to think "what the h*ll is this dude playing at?" and clears the line.

just how this spurious digit is getting sent to the trunk is another issue though, as from comparing it with my logs it seems to be getting sent somehow from the extensions (I can recreate the signals in this log by pressing the DTMF keys on my own phone)

what versions zaptel are you using?

 

[cosmicwombat]

Variable length DTMF?

This looks funny to me. Could there be some sort of DTMF mismatch?

 

[thunderheart]

Yeah but look at the time stamp on that Digit "A" collection. It is way before the hangup. I don't think the "trunk" would take that long to act on a supervision event. Also, it's a POTS line so I don't think it would even see the digit. I've written code for Nortel LCM for instance and I'm pretty sure it would get ignored.

It does look strange though. I would check a SIP/IAX phone real quick just for comfort. Then you'd know for sure it was some Zaptel issue.

I thought maybe the IVR had a no response timeout that somehow was hanging up the call after it had been routed to the extension. I don't even know if that is possible but since the timing of the problem is so consistent it seemed somewhat reasonable.

Dallas

 

[lopaka]

I'll try the test with a soft phone tonite. I'll report back whatever I find. Thanks.