Hi all,
I've been running Asterisk with a TDM400P for about 6months, no problems.
2 in/outgoing analog lines, one analog phone. Recently I was messing with
the XTEN client, got to finagling with things, and not knowing what was
wrong I upgraded from 1.0.7 to 1.0.9 (both asterisk + zaptel). I was
testing various things, and found everything worked except outgoing calls.
So I checked further, and realized the card was slightly unseated. I
shutdown the machine, and started up again, but still could not make
outgoing calls. Not knowing what to try, I upgraded again to 1.2.0 beta
(both asterisk and zaptel).
Is it possible and/or at all likely that the card could get damaged by
being half unseated or possibly a small static charge? (though I did not
notice any at all, my experience in the past has killed one or two
ethernet cards this way not knowing it). I *AM* seeing an error in the
/var/log/messages that I had not seen before:
Sep 13 16:17:13 tegan kernel: wcfxo: Can't set tx state to 5
Sep 13 16:17:13 tegan last message repeated 2 times
Sep 13 16:17:13 tegan kernel: wctdm: Can't set tx state to 5
Sep 13 16:17:25 tegan kernel: Freed a Wildcard
Sep 13 16:17:38 tegan kernel: wctdm: Can't set tx state to 11
Sep 13 16:17:38 tegan last message repeated 3 times
Sep 13 16:17:38 tegan kernel: Freshmaker version: 63
Sep 13 16:17:38 tegan kernel: Freshmaker passed register test
Sep 13 16:17:38 tegan kernel: Module 0: Installed -- AUTO FXO (FCC mode)
Sep 13 16:17:39 tegan kernel: Module 1: Installed -- AUTO FXO (FCC mode)
Sep 13 16:17:39 tegan kernel: Module 2: Installed -- AUTO FXO (FCC mode)
Sep 13 16:17:40 tegan kernel: Module 3: Installed -- AUTO FXS/DPO
Sep 13 16:17:40 tegan kernel: Found a Wildcard TDM: Wildcard TDM400P REV
E/F (4
modules)
Sep 13 16:17:40 tegan kernel: wcfxo: Can't set tx state to 5
Sep 13 16:17:40 tegan last message repeated 2 times
Sep 13 16:17:40 tegan kernel: wctdm: Can't set tx state to 5
Could these "tx state" messages indicate a problem with the card? I
removed and reattached a couple of the FXO/FXS interfaces, but that didn't
have any affect.
Below is a log of asterisk -vvvcg where I first call an internal IP phone
(works), then try calling the internal analog phone (calls, but phone
doesn't ring), and lastly attempt an outgoing call. Any clues?
Thx.
Sean
--
== Registered custom function CALLERID
== Manager registered action DBGet
== Manager registered action DBPut
== Parsing '/etc/asterisk/enum.conf': Found
Asterisk Ready.
*CLI> Sep 13 22:16:37 DEBUG[13167]: chan_zap.c:6294 do_monitor: Message
status f
or 0 changed from -1 to 0 on 4
Sep 13 22:17:33 DEBUG[13167]: chan_sip.c:1274 __sip_ack: Stopping
retransmission
on '6a7f127b0d47ebd168678c665f4d2365@192.168.0.17' of Request 102:
Match
Found
*CLI> Sep 13 22:18:10 DEBUG[13167]: chan_sip.c:6350 check_user_full:
Setting NAT
on RTP to 0
Sep 13 22:18:10 DEBUG[13167]: chan_sip.c:9413 handle_request_invite:
Checking SI
P call limits for device Phone3
Sep 13 22:18:10 DEBUG[13167]: chan_sip.c:5497 build_route: build_route:
Contact
hop: <sip:Phone3@192.168.0.18:5061>
-- Executing VoiceMailMain("SIP/Phone3-9d74", "") in
new stack
Sep 13 22:18:10 DEBUG[13167]: channel.c:1388 ast_settimeout: Scheduling
timer at
160 sample intervals
-- Playing 'vm-login' (language 'en')
Sep 13 22:18:10 DEBUG[13167]: chan_sip.c:1274 __sip_ack: Stopping
retransmission
on '8CB86803-55AC-4263-BB6F-01E0E056EC1B@192.168.0.18' of Response
30127:
Match
Found
Sep 13 22:18:12 DEBUG[13167]: channel.c:1388 ast_settimeout: Scheduling
timer at
0 sample intervals
Sep 13 22:18:12 WARNING[13167]: app_voicemail.c:4890 vm_authenticate:
Couldn't r
ead username
Sep 13 22:18:12 DEBUG[13167]: pbx.c:2262 __ast_pbx_run: Extension 8500,
priority
1 returned normally even though call was hung up
Sep 13 22:18:12 DEBUG[13167]: chan_sip.c:2315 sip_hangup:
update_user_counter(Ph
one3) - decrement inUse counter
Sep 13 22:18:16 DEBUG[13167]: chan_sip.c:6350 check_user_full: Setting NAT
on RT
P to 0
Sep 13 22:18:16 DEBUG[13167]: chan_sip.c:9413 handle_request_invite:
Checking SI
P call limits for device Phone3
Sep 13 22:18:16 DEBUG[13167]: chan_sip.c:5497 build_route: build_route:
Contact
hop: <sip:Phone3@192.168.0.18:5061>
-- Executing Dial("SIP/Phone3-1a7e", "SIP/23|20") in
new stack
Sep 13 22:18:16 DEBUG[13167]: chan_sip.c:1759 create_addr_from_peer:
Setting NAT
on RTP to 524288
Sep 13 22:18:16 DEBUG[13167]: chan_sip.c:1948 sip_call: Outgoing Call for
23
-- Called 23
Sep 13 22:18:16 DEBUG[13167]: chan_sip.c:1327 __sip_semi_ack:
(Provisional) Stop
ping retransmission (but retaining packet) on
'09cb70377008ee9a6feab1e3268e6a54@
192.168.0.17' Request 102: Found
Sep 13 22:18:16 DEBUG[13167]: chan_sip.c:1327 __sip_semi_ack:
(Provisional) Stop
ping retransmission (but retaining packet) on
'09cb70377008ee9a6feab1e3268e6a54@
192.168.0.17' Request 102: Found
Sep 13 22:18:16 DEBUG[13167]: chan_sip.c:1327 __sip_semi_ack:
(Provisional) Stop
ping retransmission (but retaining packet) on
'09cb70377008ee9a6feab1e3268e6a54@
192.168.0.17' Request 102: Found
-- SIP/23-458f is ringing
Sep 13 22:18:18 DEBUG[13167]: chan_sip.c:2312 sip_hangup:
update_user_counter(23
) - decrement outUse counter
Sep 13 22:18:18 DEBUG[13167]: app_dial.c:1656 dial_exec_full: Exiting with
DIALS
TATUS=CANCEL.
== Spawn extension (local-access, 23, 1) exited non-zero on
'SIP/Phone3-1a7e'
Sep 13 22:18:18 DEBUG[13167]: chan_sip.c:2315 sip_hangup:
update_user_counter(Ph
one3) - decrement inUse counter
Sep 13 22:18:18 DEBUG[13167]: chan_sip.c:1252 __sip_ack: Acked pending
invite 10
2
Sep 13 22:18:18 DEBUG[13167]: chan_sip.c:1274 __sip_ack: Stopping
retransmission
on '09cb70377008ee9a6feab1e3268e6a54@192.168.0.17' of Request 102:
Match
Found
Sep 13 22:18:18 DEBUG[13167]: chan_sip.c:1274 __sip_ack: Stopping
retransmission
on 'F8F52ECF-827E-4337-AC97-06A6F937905A@192.168.0.18' of Response
46682:
Match
Found
Sep 13 22:18:18 DEBUG[13167]: chan_sip.c:1274 __sip_ack: Stopping
retransmission
on '09cb70377008ee9a6feab1e3268e6a54@192.168.0.17' of Request 102:
Match
Found
Sep 13 22:18:20 DEBUG[13167]: chan_sip.c:6350 check_user_full: Setting NAT
on RT
P to 0
Sep 13 22:18:20 DEBUG[13167]: chan_sip.c:9413 handle_request_invite:
Checking SI
P call limits for device Phone3
Sep 13 22:18:20 DEBUG[13167]: chan_sip.c:5497 build_route: build_route:
Contact
hop: <sip:Phone3@192.168.0.18:5061>
-- Executing Dial("SIP/Phone3-1011", "Zap/4|20") in new
stack
Sep 13 22:18:20 DEBUG[13167]: channel.c:699 channel_find_locked: Avoiding
initia
l deadlock for 'Zap/4-1'
-- Called 4
-- Zap/4-1 is ringing
Sep 13 22:18:22 DEBUG[13167]: chan_zap.c:4136 __zt_exception: Exception on
21, c
hannel 4
Sep 13 22:18:22 DEBUG[13167]: chan_zap.c:3346 zt_handle_event: Got event
Ringer
Off(11) on channel 4 (index 0)
-- Zap/4-1 is ringing
Sep 13 22:18:26 DEBUG[13167]: chan_zap.c:4136 __zt_exception: Exception on
21, c
hannel 4
Sep 13 22:18:26 DEBUG[13167]: chan_zap.c:3346 zt_handle_event: Got event
Ringer
On(10) on channel 4 (index 0)
Sep 13 22:18:28 DEBUG[13167]: chan_zap.c:4136 __zt_exception: Exception on
21, c
hannel 4
Sep 13 22:18:28 DEBUG[13167]: chan_zap.c:3346 zt_handle_event: Got event
Ringer
Off(11) on channel 4 (index 0)
-- Zap/4-1 is ringing
Sep 13 22:18:32 DEBUG[13167]: chan_zap.c:4136 __zt_exception: Exception on
21, c
hannel 4
Sep 13 22:18:32 DEBUG[13167]: chan_zap.c:3346 zt_handle_event: Got event
Ringer
On(10) on channel 4 (index 0)
Sep 13 22:18:33 DEBUG[13167]: chan_sip.c:1274 __sip_ack: Stopping
retransmission
on '6efd02a1533a84ce60fa39c8148dfa9c@192.168.0.17' of Request 102:
Match
Found
Sep 13 22:18:34 DEBUG[13167]: chan_zap.c:2186 zt_hangup: Hangup: channel:
4 inde
x = 0, normal = 21, callwait = -1, thirdcall = -1
Sep 13 22:18:34 DEBUG[13167]: chan_zap.c:1403 zt_disable_ec: disabled echo
cance
llation on channel 4
Sep 13 22:18:34 DEBUG[13167]: chan_zap.c:2595 zt_setoption: Set option TDD
MODE,
value: OFF(0) on Zap/4-1
Sep 13 22:18:34 DEBUG[13167]: chan_zap.c:1340 update_conf: Updated
conferencing
on 4, with 0 conference users
-- Hungup 'Zap/4-1'
Sep 13 22:18:34 DEBUG[13167]: app_dial.c:1656 dial_exec_full: Exiting with
DIALS
TATUS=CANCEL.
== Spawn extension (local-access, 0, 1) exited non-zero on
'SIP/Phone3-1011'
Sep 13 22:18:34 DEBUG[13167]: chan_sip.c:2315 sip_hangup:
update_user_counter(Ph
one3) - decrement inUse counter
Sep 13 22:18:34 DEBUG[13167]: chan_sip.c:1274 __sip_ack: Stopping
retransmission
on '9AE9ECEE-D92B-43A3-BA78-BE44D9A9C120@192.168.0.18' of Response
9766:
Match
Found
Sep 13 22:19:24 DEBUG[13167]: chan_sip.c:6350 check_user_full: Setting NAT
on RT
P to 0
Sep 13 22:19:24 DEBUG[13167]: chan_sip.c:9413 handle_request_invite:
Checking SI
P call limits for device Phone3
Sep 13 22:19:24 DEBUG[13167]: chan_sip.c:5497 build_route: build_route:
Contact
hop: <sip:Phone3@192.168.0.18:5061>
Sep 13 22:19:24 DEBUG[13167]: channel.c:699 channel_find_locked: Avoiding
initia
l deadlock for 'SIP/Phone3-cc11'
-- Executing Dial("SIP/Phone3-cc11",
"Zap/1/9174423939") in new stack
Sep 13 22:19:24 DEBUG[13167]: chan_zap.c:1792 zt_call: Dialing
'9174423939'
Sep 13 22:19:24 DEBUG[13167]: chan_zap.c:1853 zt_call: Deferring
dialing...
-- Called 1/9174423939
Sep 13 22:19:25 DEBUG[13167]: chan_zap.c:4136 __zt_exception: Exception on
17, c
hannel 1
Sep 13 22:19:25 DEBUG[13167]: chan_zap.c:3346 zt_handle_event: Got event
Hook Tr
ansition Complete(12) on channel 1 (index 0)
Sep 13 22:19:27 DEBUG[13167]: chan_zap.c:4136 __zt_exception: Exception on
17, c
hannel 1
Sep 13 22:19:27 DEBUG[13167]: chan_zap.c:3346 zt_handle_event: Got event
Dial Co
mplete(9) on channel 1 (index 0)
Sep 13 22:19:27 DEBUG[13167]: chan_zap.c:1371 zt_enable_ec: Enabled echo
cancell
ation on channel 1
-- Zap/1-1 answered SIP/Phone3-cc11
Sep 13 22:19:27 DEBUG[13167]: chan_sip.c:1274 __sip_ack: Stopping
retransmission
on '9B99D135-28CA-49D9-A687-D77046C6829B@192.168.0.18' of Response
2051:
Match
Found
Sep 13 22:19:33 DEBUG[13167]: chan_sip.c:1274 __sip_ack: Stopping
retransmission
on '70ab61c067fe778c4d50ea7f3faea812@192.168.0.17' of Request 102:
Match
Found
Sep 13 22:19:38 DEBUG[13167]: channel.c:2963 ast_generic_bridge: Didn't
get a fr
ame from channel: SIP/Phone3-cc11
Sep 13 22:19:38 DEBUG[13167]: channel.c:3229 ast_channel_bridge: Bridge
stops br
idging channels SIP/Phone3-cc11 and Zap/1-1
Sep 13 22:19:38 DEBUG[13167]: chan_zap.c:2186 zt_hangup: Hangup: channel:
1 inde
x = 0, normal = 17, callwait = -1, thirdcall = -1
Sep 13 22:19:38 DEBUG[13167]: chan_zap.c:1403 zt_disable_ec: disabled echo
cance
llation on channel 1
Sep 13 22:19:38 DEBUG[13167]: chan_zap.c:2595 zt_setoption: Set option TDD
MODE,
value: OFF(0) on Zap/1-1
Sep 13 22:19:38 DEBUG[13167]: chan_zap.c:1340 update_conf: Updated
conferencing
on 1, with 0 conference users
-- Hungup 'Zap/1-1'
Sep 13 22:19:38 DEBUG[13167]: app_dial.c:1656 dial_exec_full: Exiting with
DIALS
TATUS=ANSWER.
== Spawn extension (local-access, 99174423939, 1) exited non-zero on
'SIP/Phon
e3-cc11'
Sep 13 22:19:38 DEBUG[13167]: chan_sip.c:2315 sip_hangup:
update_user_counter(Ph
one3) - decrement inUse counter
Sep 13 22:20:33 DEBUG[13167]: chan_sip.c:1274 __sip_ack: Stopping
retransmission
on '764fdcbb34a2f73a369c593a6f06efae@192.168.0.17' of Request 102:
Match
Found
Sep 13 22:21:33 DEBUG[13167]: chan_sip.c:1274 __sip_ack: Stopping
retransmission on '21b55c0811be4aa201a8fc85283766d9@192.168.0.17' of
Request 102: Match Found
Sep 13 22:22:33 DEBUG[13167]: chan_sip.c:1274 __sip_ack: Stopping
retransmission on '3b406e8536ebf75a3f0dae821900be93@192.168.0.17' of
Request 102: Match Found
Sep 13 22:23:33 DEBUG[13167]: chan_sip.c:1274 __sip_ack: Stopping
retransmission on '61d820ca42d25a925760552e012e0e72@192.168.0.17' of
Request 102: Match Found
Sean Hull
2005-Sep-13 19:36 UTC
[Asterisk-Users] Re: wctdm, issue w/outbound calls (additional notes)
> I've been running Asterisk with a TDM400P for about 6months, no problems. 2 > in/outgoing analog lines, one analog phone. Recently I was messing with the > XTEN client, got to finagling with things, and not knowing what was wrong ITwo more interesting things I've found. (1) When I call the analog internal extension, it does not ring, however when I pickup I can talk between the IP phone and analog phone (yes I've checked the ringer switch). (2) Below is a log with errors when I call the main incoming line at which point I SHOULD get the welcome message, but it just keeps ringing and never picks up. Thx again for any thoughts. Sean -- *CLI> Sep 13 22:30:02 DEBUG[13253]: chan_zap.c:6294 do_monitor: Message status for 0 changed from -1 to 0 on 4 -- Starting simple switch on 'Zap/1-1' -- Executing Answer("Zap/1-1", "") in new stack Sep 13 22:30:12 DEBUG[13253]: chan_zap.c:2503 zt_answer: Took Zap/1-1 off hook Sep 13 22:30:12 DEBUG[13253]: chan_zap.c:1371 zt_enable_ec: Enabled echo cancellation on channel 1 Sep 13 22:30:12 DEBUG[13253]: chan_zap.c:1390 zt_train_ec: No echo training requested -- Executing DigitTimeout("Zap/1-1", "10") in new stack Sep 13 22:30:12 WARNING[13253]: pbx.c:5577 pbx_builtin_dtimeout: DigitTimeout is deprecated, please use Set(TIMEOUT(digit)=timeout) instead. -- Set Digit Timeout to 10 -- Executing ResponseTimeout("Zap/1-1", "20") in new stack Sep 13 22:30:12 WARNING[13253]: pbx.c:5557 pbx_builtin_rtimeout: ResponseTimeout is deprecated, please use Set(TIMEOUT(response)=timeout) instead. -- Set Response Timeout to 20 -- Executing BackGround("Zap/1-1", "iheavy-welcome") in new stack Sep 13 22:30:12 DEBUG[13253]: channel.c:1388 ast_settimeout: Scheduling timer at 160 sample intervals -- Playing 'iheavy-welcome' (language 'en') Sep 13 22:30:17 DEBUG[13253]: chan_zap.c:4136 __zt_exception: Exception on 17, channel 1 Sep 13 22:30:17 DEBUG[13253]: chan_zap.c:3346 zt_handle_event: Got event Ring/Answered(2) on channel 1 (index 0) Sep 13 22:30:17 DEBUG[13253]: chan_zap.c:3695 zt_handle_event: Setting IDLE polarity due to ring. Old polarity was 0 Sep 13 22:30:17 WARNING[13253]: chan_zap.c:3733 zt_handle_event: Ring/Off-hook in strange state 6 on channel 1 Sep 13 22:30:23 DEBUG[13253]: chan_zap.c:4136 __zt_exception: Exception on 17, channel 1 Sep 13 22:30:23 DEBUG[13253]: chan_zap.c:3346 zt_handle_event: Got event Ring/Answered(2) on channel 1 (index 0) Sep 13 22:30:23 DEBUG[13253]: chan_zap.c:3695 zt_handle_event: Setting IDLE polarity due to ring. Old polarity was 0 Sep 13 22:30:23 WARNING[13253]: chan_zap.c:3733 zt_handle_event: Ring/Off-hook in strange state 6 on channel 1 Sep 13 22:30:29 DEBUG[13253]: chan_zap.c:4136 __zt_exception: Exception on 17, channel 1 Sep 13 22:30:35 DEBUG[13253]: chan_zap.c:3346 zt_handle_event: Got event Ring/Answered(2) on channel 1 (index 0) Sep 13 22:30:35 DEBUG[13253]: chan_zap.c:3695 zt_handle_event: Setting IDLE polarity due to ring. Old polarity was 0 Sep 13 22:30:35 WARNING[13253]: chan_zap.c:3733 zt_handle_event: Ring/Off-hook in strange state 6 on channel 1 Sep 13 22:30:39 DEBUG[13253]: chan_zap.c:4136 __zt_exception: Exception on 17, channel 1 Sep 13 22:30:39 DEBUG[13253]: chan_zap.c:3346 zt_handle_event: Got event Ring/Answered(2) on channel 1 (index 0) Sep 13 22:30:39 DEBUG[13253]: chan_zap.c:3695 zt_handle_event: Setting IDLE polarity due to ring. Old polarity was 0 Sep 13 22:30:39 WARNING[13253]: chan_zap.c:3733 zt_handle_event: Ring/Off-hook in strange state 6 on channel 1 Sep 13 22:30:39 DEBUG[13253]: chan_zap.c:4136 __zt_exception: Exception on 17, channel 1 Sep 13 22:30:39 DEBUG[13253]: chan_zap.c:3346 zt_handle_event: Got event On hook(1) on channel 1 (index 0) Sep 13 22:30:39 DEBUG[13253]: chan_zap.c:1403 zt_disable_ec: disabled echo cancellation on channel 1 Sep 13 22:30:39 DEBUG[13253]: channel.c:1388 ast_settimeout: Scheduling timer at 0 sample intervals == Spawn extension (incoming, s, 4) exited non-zero on 'Zap/1-1' Sep 13 22:30:39 DEBUG[13253]: chan_zap.c:2186 zt_hangup: Hangup: channel: 1 index = 0, normal = 17, callwait = -1, thirdcall = -1 Sep 13 22:30:39 DEBUG[13253]: chan_zap.c:1403 zt_disable_ec: disabled echo cancellation on channel 1 Sep 13 22:30:39 DEBUG[13253]: chan_zap.c:2595 zt_setoption: Set option TDD MODE, value: OFF(0) on Zap/1-1 Sep 13 22:30:39 DEBUG[13253]: chan_zap.c:1340 update_conf: Updated conferencing on 1, with 0 conference users -- Hungup 'Zap/1-1' Sep 13 22:30:58 DEBUG[13253]: chan_sip.c:1274 __sip_ack: Stopping retransmission on '7c9c969576264bdb5354e77713ccad26@192.168.0.17' of Request 102: Match Found Sep 13 22:31:58 DEBUG[13253]: chan_sip.c:1274 __sip_ack: Stopping retransmission on '4c14724b08280c217dcda9be5f6286d7@192.168.0.17' of Request 102: Match Found Sep 13 22:32:01 NOTICE[13253]: chan_sip.c:9835 handle_request_register: Registration from 'Phone3 <sip:Phone3@192.168.0.17>' failed for '192.168.0.18' - Wrong password Sep 13 22:32:16 DEBUG[13253]: chan_sip.c:1197 __sip_autodestruct: Auto destroying call '29586FF28477499FAD7843D93E5E9360@192.168.0.17' Sep 13 22:32:21 NOTICE[13253]: chan_sip.c:9835 handle_request_register: Registration from 'Phone3 <sip:Phone3@192.168.0.17>' failed for '192.168.0.18' - Wrong password Sep 13 22:32:36 DEBUG[13253]: chan_sip.c:1197 __sip_autodestruct: Auto destroying call '29586FF28477499FAD7843D93E5E9360@192.168.0.17' Sep 13 22:32:58 DEBUG[13253]: chan_sip.c:1274 __sip_ack: Stopping retransmission on '78696c4f54714b202f67c5163b595b1a@192.168.0.17' of Request 102: Match Found Sep 13 22:33:02 NOTICE[13253]: chan_sip.c:9835 handle_request_register: Registration from 'Phone3 <sip:Phone3@192.168.0.17>' failed for '192.168.0.18' - Wrong password Sep 13 22:33:17 DEBUG[13253]: chan_sip.c:1197 __sip_autodestruct: Auto destroying call '29586FF28477499FAD7843D93E5E9360@192.168.0.17'