[asterisk-users] Zap channels: no sound with certain call paths

[Christian Weeks]

Hi,
A most peculiar and vexing problem for you all. I hope I have been
verbose enough without being a firehose ;)

The set up:
I have a channel bank, using the r1t1 rhino driver with a rhino T1 card
(the channel bank itself is a very legacy piece of equipment)- this
supplies FXS for all the house phones. Also, a Wildcard TDM400P, using
the wctdm module with 1 FXO module, this supplies FXO to the upstream
telco (a single line).

The problem:
Lately, and without any configuration changes, incoming calls that route
through the Wildcard (from the telco) to the channel bank (well, a phone
connected to the channel bank) have no voice in either direction.
Obviously, this is rather frustrating. The same configuration has worked
quite reliably for the past year or so, so I am reasonably confident
that the problem isn't directly configuration related (though I have,
since this started occuring tried various configs).

The version where this started to occur (intermittently) was
asterisk/zaptel in debian etch (the 1.2 branch). I have since upgraded
to zaptel/asterisk from debian sid (the 1.4 branch) and the problems
have gotten marginally worse.

Stuff I have tried:
1. Zap->Zap (calling one channel bank extn from another) works fine.
2. Zap->anywhere (calling out from CB to telco through wildcard, or to
SIP provider, or IAX provider) works fine.
3. telco->Zap (calling in from telco to CB line) fails: no voice.
4. SIP/IAX->Zap (calling in from a SIP client to CB line) works.

Diagnostics examined:
1. ztmonitor <any line> -v shows expected signals, from the asterisk
perspective. But e.g. in scenario 3 above, there is no received voice
from the zap line. Which is consistent with the dialled CB line not
being properly connected somehow.

Oddities noticed:
1. Sometimes, when picking up a CB line, there is no dialtone. Only
resolution has been to reset the computer.
2. There are several odd messages in the log files:
(/var/log/syslog)
[..snip..]
Sep 12 17:52:04 phone kernel: Got pulse digit 36 on R1T1/0/3??
(note: lots of these, at least one per CB line, whenever we restart or
reprobe the module)
[..snip..]
Sep 12 17:53:29 phone asterisk[2638]: rc_avpair_new: unknown attribute
1490026597
(lots of these too, there seems to be a correlation between these
messages and no voice routings)
(/var/log/asterisk/messages (I have verbosity up nice and high))
[Sep 12 20:35:20] WARNING[3174] chan_zap.c: Ring/Off-hook in strange
state 6 on channel 25
(I've had this since I set the environment up. No one seems to be able
to give a sane answer as to why).

Finally, here's an interesting oddity. I can get the voice to come up,
in certain circumstances, by doing the following:
1. Dial in from telco using cellphone.
2. Answer with CB Zap line. No voice.
3. Hang up the CB Zap line.
4. Re-open any Zap CB line, execute a dial that uses telco line.
5. The telco line picks up (to execute the dial); voice is now connected
to the still waiting original call.

Here's the log file:
[Sep 12 18:23:51] VERBOSE[3051] logger.c:     -- Starting simple switch
on 'Zap/25-1'
[Sep 12 18:23:51] VERBOSE[3051] logger.c:     -- Executing
[s at telco-in:1] Goto("Zap/25-1", "incoming-home|s|1") in new stack
[Sep 12 18:23:51] VERBOSE[3051] logger.c:     -- Goto
(incoming-home,s,1)
[Sep 12 18:23:51] VERBOSE[3051] logger.c:     -- Executing
[s at incoming-home:1] NoOp("Zap/25-1", """ <Number>") in new stack
[Sep 12 18:23:51] VERBOSE[3051] logger.c:     -- Executing
[s at incoming-home:2] Set("Zap/25-1", "TRANSFER_CONTEXT=transfer") in new
stack
[Sep 12 18:23:51] VERBOSE[3051] logger.c:     -- Executing
[s at incoming-home:3] GotoIfTime("Zap/25-1", "9:00-20:00|*|*|*?s-DAY|1")
in new stack
[Sep 12 18:23:51] VERBOSE[3051] logger.c:     -- Goto
(incoming-home,s-DAY,1)
[Sep 12 18:23:51] VERBOSE[3051] logger.c:     -- Executing
[s-DAY at incoming-home:1] Dial("Zap/25-1",
"Zap/1&Zap/3&Zap/2&Zap/10&Zap/5&Zap/6&SIP/cpw...)
[Sep 12 18:23:51] VERBOSE[3051] logger.c:     -- Called 1
[Sep 12 18:23:51] VERBOSE[3051] logger.c:     -- Called 3
[Sep 12 18:23:51] VERBOSE[3051] logger.c:     -- Called 2
[Sep 12 18:23:51] VERBOSE[3051] logger.c:     -- Called 10
[Sep 12 18:23:51] VERBOSE[3051] logger.c:     -- Called 5
[Sep 12 18:23:51] VERBOSE[3051] logger.c:     -- Called 6
[Sep 12 18:23:51] VERBOSE[3051] logger.c:     -- Called <me>
[Sep 12 18:23:51] VERBOSE[3051] logger.c:     -- Zap/1-1 is ringing
[Sep 12 18:23:51] VERBOSE[3051] logger.c:     -- Zap/3-1 is ringing
[Sep 12 18:23:51] VERBOSE[3051] logger.c:     -- Zap/2-1 is ringing
[Sep 12 18:23:51] VERBOSE[3051] logger.c:     -- Zap/10-1 is ringing
[Sep 12 18:23:51] VERBOSE[3051] logger.c:     -- Zap/5-1 is ringing
[Sep 12 18:23:51] VERBOSE[3051] logger.c:     -- Zap/6-1 is ringing
[Sep 12 18:23:51] VERBOSE[3051] logger.c:     -- SIP/<me>-081f3db0 is
ringing
[Sep 12 18:23:53] VERBOSE[3051] logger.c:     -- Zap/10-1 answered
Zap/25-1
[Sep 12 18:23:53] VERBOSE[3051] logger.c:     -- Hungup 'Zap/6-1'
[Sep 12 18:23:53] VERBOSE[3051] logger.c:     -- Hungup 'Zap/5-1'
[Sep 12 18:23:53] VERBOSE[3051] logger.c:     -- Hungup 'Zap/2-1'
[Sep 12 18:23:53] VERBOSE[3051] logger.c:     -- Hungup 'Zap/3-1'
[Sep 12 18:23:53] VERBOSE[3051] logger.c:     -- Hungup 'Zap/1-1'
[Sep 12 18:24:04] VERBOSE[3051] logger.c:     -- Hungup 'Zap/10-1'
[Sep 12 18:24:04] VERBOSE[3051] logger.c:   == Spawn extension
(incoming-home, s-DAY, 1) exited non-zero on 'Zap/25-1'
[Sep 12 18:24:04] VERBOSE[3051] logger.c:     -- Hungup 'Zap/25-1'
[Sep 12 18:24:08] VERBOSE[3069] logger.c:     -- Starting simple switch
on 'Zap/10-1'
[Sep 12 18:24:16] VERBOSE[3069] logger.c:     -- Executing
[<number>@internal:1] Dial("Zap/10-1", "Zap/25/<number>") in new stack
[Sep 12 18:24:16] VERBOSE[3069] logger.c:     -- Called 25/<number>
[Sep 12 18:24:20] VERBOSE[3069] logger.c:     -- Zap/25-1 answered
Zap/10-1
[Sep 12 18:24:20] VERBOSE[3069] logger.c:     -- Native bridging
Zap/10-1 and Zap/25-1
[Sep 12 18:26:25] VERBOSE[3069] logger.c:     -- Hungup 'Zap/25-1'
[Sep 12 18:26:25] VERBOSE[3069] logger.c:   == Spawn extension
(internal, <number>, 1) exited non-zero on 'Zap/10-1'
[Sep 12 18:26:25] VERBOSE[3069] logger.c:     -- Hungup 'Zap/10-1'


Note, throughout the above, that Zap/25 never actually hung up on me (on
my cellphone), and the call continued when the Native bridge occurred,
and voice was passed.

Can anyone suggest anything that might be able to help me here? This is
very frustrating. I have a suspicion that my super-cheap eBay special
channel bank is probably the ultimate culprit, but without hard core
testing equipment I don't know how to verify this (and the diagnostic
tooling available on the channel bank is, well, non-existent). I would
like to hear others' suggestions and thoughts, as I an highly confused
by this exceedingly peculiar problem, before I go ahead and buy another
eBay special.

Thanks
Christian