[asterisk-users] Spurious hangups on Sangoma A102d, Trixbox 2.6.1

[Jeff LaCoursiere]

[also posted on Trixbox trunk forum]

I am also working with Sangoma directly to debug this, but so far no real 
luck. TrixBox 2.6.1, A102d card with V33 firmware (latest) and WANPIPE 
3.2.6 (3.2.7 is out, but nothing has changed that would affect this 
problem). The system gets about 200 calls inbound on the trunk, which is 
not very heavily used, and of those calls one or two a day is randomly 
terminated in the middle of a call. Other than this problem everything is 
working fine. All phones are Polycom IP501 with latest firmware as of a 
year ago...

There is only one ethernet switch (Linksys 100/1000 managed) between the 
phones and the Trixbox, and the runs are less than 50 feet. Calls 
extension to extension seem to have no issue at all. The network *is* 
shared data/voice with no QOS and no virtual segments, but if the network 
was the issue I would expect to see extension to extension calls report 
this issue, which they have not.  This is actually a hotel, and the data 
portion of the traffic isn't heavily used either.  They don't even have a 
file server.

I have the "full" logging enabled, and here is an excerpt of a call that 
was terminated. You can see the conversation lasted about forty seconds 
before it was hungup.

[snipped the beginning of this process...]
[Jan 9 12:34:12] VERBOSE[2778] logger.c: -- Executing [s at macro-dial:7] 
Dial("Zap/9-1", "SIP/2607&SIP/2605&SIP/2510|20|trM(auto-blkvm)") in new 
stack
[Jan 9 12:34:12] VERBOSE[2778] logger.c: -- Called 2607
[Jan 9 12:34:12] VERBOSE[2778] logger.c: -- Called 2605
[Jan 9 12:34:12] VERBOSE[2778] logger.c: -- Called 2510
[Jan 9 12:34:12] VERBOSE[2778] logger.c: -- SIP/2510-0a29a140 is ringing
[Jan 9 12:34:12] VERBOSE[2778] logger.c: -- SIP/2607-0a30c8d0 is ringing
[Jan 9 12:34:12] VERBOSE[2778] logger.c: -- SIP/2605-0a372cb0 is ringing
[Jan 9 12:34:21] VERBOSE[2778] logger.c: -- SIP/2605-0a372cb0 answered 
Zap/9-1
[Jan 9 12:34:21] VERBOSE[2778] logger.c: -- Executing 
[s at macro-auto-blkvm:1] Set("SIP/2605-0a372cb0", "__MACRO_RESULT=") in new 
stack
[Jan 9 12:34:21] DEBUG[2778] app_macro.c: Executed application: Set
[Jan 9 12:34:21] VERBOSE[2778] logger.c: -- Executing 
[s at macro-auto-blkvm:2] Set("SIP/2605-0a372cb0", "__CWIGNORE=") in new 
stack
[Jan 9 12:34:21] DEBUG[2778] app_macro.c: Executed application: Set
[Jan 9 12:34:21] VERBOSE[2778] logger.c: -- Executing 
[s at macro-auto-blkvm:3] DBdel("SIP/2605-0a372cb0", "BLKVM/602/Zap/9-1") in 
new stack
[Jan 9 12:34:21] VERBOSE[2778] logger.c: -- DBdel: family=BLKVM, 
key=602/Zap/9-1
[Jan 9 12:34:21] DEBUG[2778] app_macro.c: Executed application: DBDel
[Jan 9 12:34:21] DEBUG[2778] app_dial.c: Macro exited with status 0
[Jan 9 12:34:21] DEBUG[2778] chan_zap.c: Took Zap/9-1 off hook
[Jan 9 12:35:01] VERBOSE[2778] logger.c: == Spawn extension (macro-dial, 
s, 7) exited non-zero on 'Zap/9-1' in macro 'dial'
[Jan 9 12:35:01] VERBOSE[2778] logger.c: == Spawn extension (macro-dial, 
s, 7) exited non-zero on 'Zap/9-1'
[Jan 9 12:35:01] VERBOSE[2778] logger.c: -- Executing [h at macro-dial:1] 
Macro("Zap/9-1", "hangupcall") in new stack
[Jan 9 12:35:01] VERBOSE[2778] logger.c: -- Executing 
[s at macro-hangupcall:1] ResetCDR("Zap/9-1", "w") in new stack
[Jan 9 12:35:01] DEBUG[2778] app_macro.c: Executed application: ResetCDR
[Jan 9 12:35:01] VERBOSE[2778] logger.c: -- Executing 
[s at macro-hangupcall:2] NoCDR("Zap/9-1", "") in new stack
[Jan 9 12:35:01] DEBUG[2778] app_macro.c: Executed application: NoCDR
[Jan 9 12:35:01] VERBOSE[2778] logger.c: -- Executing 
[s at macro-hangupcall:3] GotoIf("Zap/9-1", "1?skiprg") in new stack
[Jan 9 12:35:01] VERBOSE[2778] logger.c: -- Goto (macro-hangupcall,s,6)
[Jan 9 12:35:01] DEBUG[2778] app_macro.c: Executed application: GotoIf
[Jan 9 12:35:01] VERBOSE[2778] logger.c: -- Executing 
[s at macro-hangupcall:6] GotoIf("Zap/9-1", "0?skipblkvm") in new stack
[Jan 9 12:35:01] DEBUG[2778] app_macro.c: Executed application: GotoIf
[Jan 9 12:35:01] VERBOSE[2778] logger.c: -- Executing 
[s at macro-hangupcall:7] NoOp("Zap/9-1", "Cleaning Up Block VM Flag: 
BLKVM/602/Zap/9-1") in new stack
[Jan 9 12:35:01] DEBUG[2778] app_macro.c: Executed application: Noop
[Jan 9 12:35:01] VERBOSE[2778] logger.c: -- Executing 
[s at macro-hangupcall:8] DBdel("Zap/9-1", "BLKVM/602/Zap/9-1") in new stack
[Jan 9 12:35:01] VERBOSE[2778] logger.c: -- DBdel: family=BLKVM, 
key=602/Zap/9-1
[Jan 9 12:35:01] VERBOSE[2778] logger.c: -- DBdel: Error deleting key from 
database.
[Jan 9 12:35:01] DEBUG[2778] app_macro.c: Executed application: DBDel
[Jan 9 12:35:01] VERBOSE[2778] logger.c: -- Executing 
[s at macro-hangupcall:9] GotoIf("Zap/9-1", "1?theend") in new stack
[Jan 9 12:35:01] VERBOSE[2778] logger.c: -- Goto (macro-hangupcall,s,11)
[Jan 9 12:35:01] DEBUG[2778] app_macro.c: Executed application: GotoIf
[Jan 9 12:35:01] VERBOSE[2778] logger.c: -- Executing 
[s at macro-hangupcall:11] Hangup("Zap/9-1", "") in new stack
[Jan 9 12:35:01] VERBOSE[2778] logger.c: == Spawn extension 
(macro-hangupcall, s, 11) exited non-zero on 'Zap/9-1' in macro 
'hangupcall'
[Jan 9 12:35:01] VERBOSE[2778] logger.c: == Spawn extension 
(macro-hangupcall, s, 11) exited non-zero on 'Zap/9-1'
[Jan 9 12:35:01] VERBOSE[2778] logger.c: -- Hungup 'Zap/9-1'

Does this trace look normal? Several macros seem to be exiting with 
non-zero status, but that seems after the fact... the call had already 
been determined to be hungup. I'm kind of at my wits end with this 
problem. I don't know if I should blame the Sangoma card or the phone 
company (which is extremely hard to work with - this being the Virgin 
Islands!), and it is kind of expensive to go buy an alternate card just to 
test this.

Any advice?

Thanks!

j