Strange problem with incoming call on FXO, from PSTN! (TDM11

Hi!

[edit]
It shopped it off in the subject, it is a TDM11B card I have!
[/edit]

My system have worked quite OK for some time now with both ZAP and SIP channels!

I’m using:
Debian 4.0
Asterisk SVN-branch-1.4-r114628 and
Zaptel Version: 1.4.11

For some reason I looked in to the Asterisk logfile and could find these lines over and over again!

[Apr 6 10:59:59] VERBOSE[31805] logger.c: Asterisk Dynamic Loader Starting: [Apr 6 10:59:59] VERBOSE[31805] logger.c: == Parsing '/etc/asterisk/modules.conf': [Apr 6 10:59:59] VERBOSE[31805] logger.c: Found [Apr 6 10:59:59] VERBOSE[31805] logger.c: == Parsing '/etc/asterisk/dnsmgr.conf': [Apr 6 10:59:59] VERBOSE[31805] logger.c: Found [Apr 6 10:59:59] VERBOSE[31805] logger.c: == Parsing '/etc/asterisk/http.conf': [Apr 6 10:59:59] VERBOSE[31805] logger.c: Found [Apr 6 10:59:59] VERBOSE[31805] logger.c: == Manager registered action Ping [Apr 6 10:59:59] VERBOSE[31805] logger.c: == Manager registered action Events [Apr 6 10:59:59] VERBOSE[31805] logger.c: == Manager registered action Logoff [Apr 6 10:59:59] VERBOSE[31805] logger.c: == Manager registered action Hangup [Apr 6 10:59:59] VERBOSE[31805] logger.c: == Manager registered action Status [Apr 6 10:59:59] VERBOSE[31805] logger.c: == Manager registered action Setvar [Apr 6 10:59:59] VERBOSE[31805] logger.c: == Manager registered action Getvar [Apr 6 10:59:59] VERBOSE[31805] logger.c: == Manager registered action GetConfig [Apr 6 10:59:59] VERBOSE[31805] logger.c: == Manager registered action UpdateConfig [Apr 6 10:59:59] VERBOSE[31805] logger.c: == Manager registered action Redirect [Apr 6 10:59:59] VERBOSE[31805] logger.c: == Manager registered action Originate [Apr 6 10:59:59] VERBOSE[31805] logger.c: == Manager registered action Command [Apr 6 10:59:59] VERBOSE[31805] logger.c: == Manager registered action ExtensionState [Apr 6 10:59:59] VERBOSE[31805] logger.c: == Manager registered action AbsoluteTimeout [Apr 6 10:59:59] VERBOSE[31805] logger.c: == Manager registered action MailboxStatus [Apr 6 10:59:59] VERBOSE[31805] logger.c: == Manager registered action MailboxCount [Apr 6 10:59:59] VERBOSE[31805] logger.c: == Manager registered action ListCommands [Apr 6 10:59:59] VERBOSE[31805] logger.c: == Manager registered action UserEvent [Apr 6 10:59:59] VERBOSE[31805] logger.c: == Manager registered action WaitEvent [Apr 6 10:59:59] VERBOSE[31805] logger.c: == Parsing '/etc/asterisk/manager.conf': [Apr 6 10:59:59] VERBOSE[31805] logger.c: Found [Apr 6 10:59:59] WARNING[31805] manager.c: Unable to bind socket: Address already in use
Next I found this in a cron-job mail that I uses to automatically restart Asterisk every second day.

After this I rebooted the whole system and hoped for some success.
To start with it looked ok.

This is what I could find in my </var/log/kern.log>

[code]Apr 6 11:09:50 asterisk kernel: Open Source Line Echo Canceller Installed
Apr 6 11:09:50 asterisk kernel: zaptel: no version for “oslec_echo_can_traintap” found: kernel tainted.
Apr 6 11:09:50 asterisk kernel: Zapata Telephony Interface Registered on major 196
Apr 6 11:09:50 asterisk kernel: Zaptel Version: 1.4.11
Apr 6 11:09:50 asterisk kernel: Zaptel Echo Canceller: OSLEC
Apr 6 11:09:50 asterisk kernel: Zaptap registered ‘sample’ char driver on major 33

Apr 6 11:09:50 asterisk kernel: Module 0: Installed – AUTO FXS/DPO
Apr 6 11:09:50 asterisk kernel: Module 1: Not installed
Apr 6 11:09:50 asterisk kernel: Module 2: Not installed
Apr 6 11:09:50 asterisk kernel: Module 3: Installed – AUTO FXO (SWEDEN mode)
Apr 6 11:09:50 asterisk kernel: Found a Wildcard TDM: Wildcard TDM400P REV I (2 modules)

Apr 6 11:09:54 asterisk kernel: Registered tone zone 16 (Sweden)
Apr 6 11:09:54 asterisk kernel: – Setting echo registers:
Apr 6 11:09:54 asterisk kernel: – Set echo registers successfully
[/code]
But later on, on incoming call I got this in my Asterisk log:

[Apr 7 09:51:56] VERBOSE[27625] logger.c: == Starting post polarity CID detection on channel 4 [Apr 7 09:51:56] DEBUG[27625] dsp.c: dsp busy pattern set to 0,0 [Apr 7 09:51:56] VERBOSE[23909] logger.c: -- Starting simple switch on 'Zap/4-1' [Apr 7 09:51:56] DEBUG[23909] chan_zap.c: Receiving DTMF cid on channel Zap/4-1 [Apr 7 09:51:56] DEBUG[23909] chan_zap.c: CID got string '' [Apr 7 09:51:56] DEBUG[23909] callerid.c: No cid detected [Apr 7 09:51:56] DEBUG[23909] chan_zap.c: CID is '', flags 8 [Apr 7 09:51:56] VERBOSE[23909] logger.c: -- Executing [s@pts_incoming:1] Set("Zap/4-1", "CALLERID=") in new stack [Apr 7 09:51:56] VERBOSE[23909] logger.c: -- Executing [s@pts_incoming:2] Set("Zap/4-1", "INCOMING_FROM=PTS") in new stack [Apr 7 09:51:56] VERBOSE[23909] logger.c: -- Executing [s@pts_incoming:3] GotoIf("Zap/4-1", "1?not_salesman_call|2000-PTS|1:check_incoming|s|1") in new stack [Apr 7 09:51:56] VERBOSE[23909] logger.c: -- Goto (not_salesman_call,2000-PTS,1) [Apr 7 09:51:56] VERBOSE[23909] logger.c: -- Executing [2000-PTS@not_salesman_call:1] NoOp("Zap/4-1", "MySQL Answer - Owner: - Salesman: ") in new stack [Apr 7 09:51:56] VERBOSE[23909] logger.c: -- Executing [2000-PTS@not_salesman_call:2] Dial("Zap/4-1", "SIP/5507&SIP/Micke_Helen&SIP/Nypon&IAX2/Nypon|20|tTKk") in new stack [Apr 7 09:51:56] VERBOSE[27589] logger.c: Extension Changed 6000[internal] new state Ringing for Notify User 6010 [Apr 7 09:51:56] VERBOSE[23909] logger.c: -- Called 5507 [Apr 7 09:51:56] VERBOSE[23909] logger.c: -- Called Micke_Helen [Apr 7 09:51:56] VERBOSE[23909] logger.c: -- Called Nypon [Apr 7 09:51:57] WARNING[23909] app_dial.c: Unable to create channel of type 'IAX2' (cause 3 - No route to destination) [Apr 7 09:51:57] VERBOSE[23909] logger.c: -- SIP/Micke_Helen-0823bf90 is ringing [Apr 7 09:51:57] VERBOSE[23909] logger.c: -- SIP/5507-081f9728 is ringing [Apr 7 09:51:57] DTMF[23909] channel.c: DTMF end 'D' received on Zap/4-1, duration 0 ms [Apr 7 09:51:57] DTMF[23909] channel.c: DTMF begin emulation of 'D' with duration 100 queued on Zap/4-1 [Apr 7 09:51:57] VERBOSE[23909] logger.c: -- SIP/Nypon-082430c8 is ringing [Apr 7 09:51:57] DTMF[23909] channel.c: DTMF end emulation of 'D' queued on Zap/4-1 [Apr 7 09:51:57] VERBOSE[23909] logger.c: -- SIP/Nypon-082430c8 is ringing [Apr 7 09:51:57] DTMF[23909] channel.c: DTMF end '0' received on Zap/4-1, duration 0 ms [Apr 7 09:51:57] DTMF[23909] channel.c: DTMF end '0' put into dtmf queue on Zap/4-1 [Apr 7 09:51:57] DTMF[23909] channel.c: DTMF begin emulation of '0' with duration 100 queued on Zap/4-1 [Apr 7 09:51:57] DTMF[23909] channel.c: DTMF end '1' received on Zap/4-1, duration 0 ms [Apr 7 09:51:57] DTMF[23909] channel.c: DTMF end '1' put into dtmf queue on Zap/4-1 [Apr 7 09:51:57] DTMF[23909] channel.c: DTMF end emulation of '0' queued on Zap/4-1 [Apr 7 09:51:57] DTMF[23909] channel.c: DTMF begin emulation of '1' with duration 100 queued on Zap/4-1 [Apr 7 09:51:57] DTMF[23909] channel.c: DTMF end '3' received on Zap/4-1, duration 0 ms [Apr 7 09:51:57] DTMF[23909] channel.c: DTMF end '3' put into dtmf queue on Zap/4-1 [Apr 7 09:51:57] DTMF[23909] channel.c: DTMF end emulation of '1' queued on Zap/4-1 [Apr 7 09:51:57] DTMF[23909] channel.c: DTMF begin emulation of '3' with duration 100 queued on Zap/4-1 [Apr 7 09:51:57] DTMF[23909] channel.c: DTMF end '1' received on Zap/4-1, duration 0 ms [Apr 7 09:51:57] DTMF[23909] channel.c: DTMF end '1' put into dtmf queue on Zap/4-1 [Apr 7 09:51:57] DTMF[23909] channel.c: DTMF end emulation of '3' queued on Zap/4-1 [Apr 7 09:51:57] DTMF[23909] channel.c: DTMF begin emulation of '1' with duration 100 queued on Zap/4-1 [Apr 7 09:51:57] DTMF[23909] channel.c: DTMF end '8' received on Zap/4-1, duration 0 ms [Apr 7 09:51:57] DTMF[23909] channel.c: DTMF end '8' put into dtmf queue on Zap/4-1 [Apr 7 09:51:57] DTMF[23909] channel.c: DTMF end emulation of '1' queued on Zap/4-1 [Apr 7 09:51:58] DTMF[23909] channel.c: DTMF begin emulation of '8' with duration 100 queued on Zap/4-1 [Apr 7 09:51:58] DTMF[23909] channel.c: DTMF end '5' received on Zap/4-1, duration 0 ms [Apr 7 09:51:58] DTMF[23909] channel.c: DTMF end '5' put into dtmf queue on Zap/4-1 [Apr 7 09:51:58] DTMF[23909] channel.c: DTMF end emulation of '8' queued on Zap/4-1 [Apr 7 09:51:58] DTMF[23909] channel.c: DTMF end '5' received on Zap/4-1, duration 0 ms [Apr 7 09:51:58] DTMF[23909] channel.c: DTMF end '5' put into dtmf queue on Zap/4-1 [Apr 7 09:51:58] DTMF[23909] channel.c: DTMF begin emulation of '5' with duration 100 queued on Zap/4-1 [Apr 7 09:51:58] DTMF[23909] channel.c: DTMF end emulation of '5' queued on Zap/4-1 [Apr 7 09:51:58] DTMF[23909] channel.c: DTMF end '6' received on Zap/4-1, duration 0 ms [Apr 7 09:51:58] DTMF[23909] channel.c: DTMF end '6' put into dtmf queue on Zap/4-1 [Apr 7 09:51:58] DTMF[23909] channel.c: DTMF begin emulation of '5' with duration 100 queued on Zap/4-1 [Apr 7 09:51:58] DTMF[23909] channel.c: DTMF end '0' received on Zap/4-1, duration 0 ms [Apr 7 09:51:58] DTMF[23909] channel.c: DTMF end '0' put into dtmf queue on Zap/4-1 [Apr 7 09:51:58] DTMF[23909] channel.c: DTMF end emulation of '5' queued on Zap/4-1 [Apr 7 09:51:58] DTMF[23909] channel.c: DTMF begin emulation of '6' with duration 100 queued on Zap/4-1 [Apr 7 09:51:58] DTMF[23909] channel.c: DTMF end 'C' received on Zap/4-1, duration 0 ms [Apr 7 09:51:58] DTMF[23909] channel.c: DTMF end 'C' put into dtmf queue on Zap/4-1 [Apr 7 09:51:58] DTMF[23909] channel.c: DTMF end emulation of '6' queued on Zap/4-1 [Apr 7 09:51:58] DTMF[23909] channel.c: DTMF begin emulation of '0' with duration 100 queued on Zap/4-1 [Apr 7 09:51:58] DEBUG[23909] chan_zap.c: Polarity Reversal event occured - DEBUG 1: channel 4, state 4, pol= 1, aonp= 1, honp= 1, pdelay= 600, tv= 2140137505 [Apr 7 09:51:58] DEBUG[23909] chan_zap.c: Polarity Reversal detected and now Hanging up on channel 4 [Apr 7 09:51:58] DEBUG[23909] chan_zap.c: Polarity Reversal event occured - DEBUG 2: channel 4, state 4, pol= 0, aonp= 1, honp= 1, pdelay= 600, tv= 2140137505 [Apr 7 09:51:58] VERBOSE[23909] logger.c: == Spawn extension (not_salesman_call, 2000-PTS, 2) exited non-zero on 'Zap/4-1' [Apr 7 09:51:58] VERBOSE[23909] logger.c: -- Executing [h@not_salesman_call:1] Hangup("Zap/4-1", "") in new stack [Apr 7 09:51:58] VERBOSE[23909] logger.c: == Spawn extension (not_salesman_call, h, 1) exited non-zero on 'Zap/4-1' [Apr 7 09:51:58] VERBOSE[23909] logger.c: -- Hungup 'Zap/4-1' [Apr 7 09:51:58] VERBOSE[27589] logger.c: Extension Changed 6000[internal] new state Idle for Notify User 6010 [Apr 7 09:52:06] DEBUG[27625] dsp.c: dsp busy pattern set to 0,0 [Apr 7 09:52:06] VERBOSE[23923] logger.c: -- Starting simple switch on 'Zap/4-1' [Apr 7 09:52:06] VERBOSE[23923] logger.c: -- Executing [s@pts_incoming:1] Set("Zap/4-1", "CALLERID=") in new stack [Apr 7 09:52:06] VERBOSE[23923] logger.c: -- Executing [s@pts_incoming:2] Set("Zap/4-1", "INCOMING_FROM=PTS") in new stack [Apr 7 09:52:06] VERBOSE[23923] logger.c: -- Executing [s@pts_incoming:3] GotoIf("Zap/4-1", "1?not_salesman_call|2000-PTS|1:check_incoming|s|1") in new stack [Apr 7 09:52:06] VERBOSE[23923] logger.c: -- Goto (not_salesman_call,2000-PTS,1) [Apr 7 09:52:06] VERBOSE[23923] logger.c: -- Executing [2000-PTS@not_salesman_call:1] NoOp("Zap/4-1", "MySQL Answer - Owner: - Salesman: ") in new stack [Apr 7 09:52:06] VERBOSE[23923] logger.c: -- Executing [2000-PTS@not_salesman_call:2] Dial("Zap/4-1", "SIP/5507&SIP/Micke_Helen&SIP/Nypon&IAX2/Nypon|20|tTKk") in new stack [Apr 7 09:52:06] VERBOSE[27589] logger.c: Extension Changed 6000[internal] new state Ringing for Notify User 6010 [Apr 7 09:52:06] VERBOSE[23923] logger.c: -- Called 5507 [Apr 7 09:52:06] VERBOSE[23923] logger.c: -- Called Micke_Helen [Apr 7 09:52:06] VERBOSE[23923] logger.c: -- Called Nypon [Apr 7 09:52:06] WARNING[23923] app_dial.c: Unable to create channel of type 'IAX2' (cause 3 - No route to destination) [Apr 7 09:52:06] VERBOSE[23923] logger.c: -- SIP/Micke_Helen-0823bf90 is ringing [Apr 7 09:52:06] VERBOSE[23923] logger.c: -- SIP/5507-081f08d8 is ringing [Apr 7 09:52:06] VERBOSE[23923] logger.c: -- SIP/Nypon-082430c8 is ringing [Apr 7 09:52:06] VERBOSE[23923] logger.c: -- SIP/Nypon-082430c8 is ringing [Apr 7 09:52:14] VERBOSE[23923] logger.c: == Spawn extension (not_salesman_call, 2000-PTS, 2) exited non-zero on 'Zap/4-1' [Apr 7 09:52:14] VERBOSE[23923] logger.c: -- Executing [h@not_salesman_call:1] Hangup("Zap/4-1", "") in new stack [Apr 7 09:52:14] VERBOSE[23923] logger.c: == Spawn extension (not_salesman_call, h, 1) exited non-zero on 'Zap/4-1' [Apr 7 09:52:14] VERBOSE[23923] logger.c: -- Hungup 'Zap/4-1' [Apr 7 09:52:14] VERBOSE[27589] logger.c: Extension Changed 6000[internal] new state Idle for Notify User 6010
As it was before, the call was coming in from PSTN and Asterisk started to
receive the calling number, after that it started to ring in my house and
I got the caller ID.

As it is now, the call is coming in, it is ringing in the house right away
with no caller ID, it then starts to receive the number and hangs up.
One second later it is ringing in the house again and still no caller ID.

I’m not sure if this is something, but I have (say think) noticed a different dial tone in the phone when off hook.

But from what I could see in the log file after the reboot, zaptel was started and with swedish usage:

[code][Apr 6 11:10:34] VERBOSE[3892] logger.c: – Setting default indication country to ‘se’

[Apr 6 11:10:41] VERBOSE[3892] logger.c: == Parsing ‘/etc/asterisk/zapata.conf’: [Apr 6 11:10:41] VERBOSE[3892] logger.c: Found
[Apr 6 11:10:41] VERBOSE[3892] logger.c: – Registered channel 1, FXO Kewlstart signalling
[Apr 6 11:10:41] VERBOSE[3892] logger.c: – Registered channel 4, FXS Kewlstart signalling
[Apr 6 11:10:41] VERBOSE[3892] logger.c: – Automatically generated pseudo channel
[/code]
In the <indications.conf> file I have:

[general] country=se
This is my <zapata.conf> file

[code][channels]
rxgain=5.0
txgain=5.0
relaxdtmf=no
echocancel=yes
echocancelwhenbridged=no ; With OSLEC for faxes from FXS to FXO with no echo!
;echotraining=400 ; Disable with OSLEC.

usecallerid=yes
usecallingpres=yes
callwaiting=yes
callwaitingcallerid=yes
threewaycalling=yes
useincomingcalleridonzaptransfer=yes
progzone=se
transfer=yes
busydetect=yes
busycount=6
rxwink=300 ; Atlas seems to use long (250ms) winks.
debounce=6

faxdetect=incoming

; Channel 1 FXS port to normal phone
; FXS Interface.
language=se
signalling=fxo_ks
usecallerid=yes
callerid=“Micke & Helen”<6002>
context=internal-call-profile-pre
accountcode=call-in-house
mailbox=6002@intern-ank
cidsignalling=dtmf ; Sweden
cidstart=polarity ; Sweden
channel => 1

; Channel 4 FXO port for incoming analog line
; FXO Interface, PSTN (Public Switched Telephone Network)
cidsignalling=dtmf ; Sweden
cidstart=polarity ; Sweden
language=se
signalling=fxs_ks
usecallerid=yes
callerid=asreceived
transfer=yes
immediate=yes
context=pts_incoming
answeronpolarityswitch=yes
hanguponpolarityswitch=yes
channel => 4
[/code]
All this problem after a automatic restart of Asterisk!
I hope somebody can spread some light over this!

It look like the problem is solved!
I wanted to find out why and what, but never got close to that.

Next I reinstalled Zaptel Version: 1.4.11, and then it worked!