[Freeswitch-users] PRI channels get stuck in HANGUP state.

Wed Feb 4 01:45:48 MSK 2015

I am trying to track down an issue where FreeTDM seems to get confused
about the state of channels on my PRI. The state seems to occur on
origination; FreeTDM opens a channel, and immediately closes it, logging
REQUESTED_CHAN_UNAVAIL. The channel then sits in the HANGUP state,
preventing inbound calls and logging the following error.

2015-02-03 08:25:04.774438 [ERR] ftmod_libpri.c:1883 [s1c1][1:1] --
Selected channel is already in use

I can resolve this by restarting Freeswitch, but it is obviously
less-than-ideal. A bit of relevant logging is at the end of this message.
It seems to occur immediately after a hangup on the same channel; could I
be triggering a race condition?

https://freeswitch.org/jira/browse/OPENZAP-220 seems to have similar
symptoms, but manifests as a different error number. I upgraded Freeswitch
last week (1.5.15b git 608d3e2 2015-01-22 09:09:59Z 64bit) to ensure that I
had the patch referenced by the ticket. Is it possible that this could be a
cabling issue? We're running Freeswitch on FreeBSD 10.0 amd64.

I'm happy to provide any other information that would be useful. I'm
[relatively] new to Freeswitch, so please be gentle ;-).

Thank you,
Tom

2015-02-03 14:34:23.437947 [DEBUG] ftmod_libpri.c:1451 -- Hangup ACK on
channel 1:1
2015-02-03 14:34:23.437947 [DEBUG] ftmod_libpri.c:1460 [s1c1][1:1] Changed
state from HANGUP to HANGUP_COMPLETE
2015-02-03 14:34:23.437947 [DEBUG] ftdm_state.c:541 [s1c1][1:1] Executing
state processor for HANGUP_COMPLETE
2015-02-03 14:34:23.437947 [DEBUG] ftmod_libpri.c:942 -- 1:1 STATE
[HANGUP_COMPLETE]
2015-02-03 14:34:23.437947 [DEBUG] ftmod_libpri.c:950 [s1c1][1:1] Completed
state change from HANGUP to HANGUP_COMPLETE in 0 ms
2015-02-03 14:34:23.437947 [DEBUG] ftmod_libpri.c:1268 [s1c1][1:1] Changed
state from HANGUP_COMPLETE to DOWN
2015-02-03 14:34:23.437947 [DEBUG] ftdm_state.c:541 [s1c1][1:1] Executing
state processor for DOWN
2015-02-03 14:34:23.437947 [DEBUG] ftmod_libpri.c:942 -- 1:1 STATE [DOWN]
2015-02-03 14:34:23.437947 [DEBUG] ftmod_libpri.c:950 [s1c1][1:1] Completed
state change from HANGUP_COMPLETE to DOWN in 0 ms
2015-02-03 14:34:23.437947 [DEBUG] ftdm_io.c:3194 [s1c1][1:1] DTMF debug is
already disabled
2015-02-03 14:34:23.437947 [DEBUG] ftdm_io.c:3226 [s1c1][1:1] No need to
disable input dump
2015-02-03 14:34:23.437947 [DEBUG] ftdm_io.c:3257 [s1c1][1:1] No need to
disable output dump
2015-02-03 14:34:23.437947 [DEBUG] mod_freetdm.c:2707 got clear channel sig
[RELEASED]
2015-02-03 14:34:23.437947 [DEBUG] ftdm_io.c:6873 Cleared call with id 37
2015-02-03 14:34:23.437947 [DEBUG] ftdm_io.c:2999 [s1c1][1:1] channel done
2015-02-03 14:34:23.437947 [DEBUG] ftmod_libpri.c:978 -- Closed channel 1:1
2015-02-03 14:34:23.679236 [DEBUG] switch_ivr_originate.c:2099 Parsing
global variables
2015-02-03 14:34:23.679236 [DEBUG] switch_event.c:1688 Parsing variable
[ignore_early_media]=[true]
2015-02-03 14:34:23.679236 [DEBUG] switch_event.c:1688 Parsing variable
[file]=[46475.tif]
2015-02-03 14:34:23.679236 [DEBUG] switch_event.c:1688 Parsing variable
[jobid]=[293102]
2015-02-03 14:34:23.679236 [INFO] ftmod_zt.c:671 Setting echo cancel to 64
taps for 1:1
2015-02-03 14:34:23.679236 [DEBUG] mod_freetdm.c:403 Set codec PCMU 20ms
8d09030a-e4ab-e411-905b-0026b95c8602 2015-02-03 14:34:23.679236 [DEBUG]
mod_freetdm.c:1251 Connect outbound channel FreeTDM/1:1/18019941076
8d09030a-e4ab-e411-905b-0026b95c8602 2015-02-03 14:34:23.679236 [NOTICE]
switch_channel.c:1055 New Channel FreeTDM/1:1/18019941076
[8d09030a-e4ab-e411-905b-0026b95c8602]
8d09030a-e4ab-e411-905b-0026b95c8602 2015-02-03 14:34:23.679236 [DEBUG]
mod_freetdm.c:1260 (FreeTDM/1:1/18019941076) State Change CS_NEW -> CS_INIT
8d09030a-e4ab-e411-905b-0026b95c8602 2015-02-03 14:34:23.679236 [DEBUG]
switch_core_session.c:1388 Send signal FreeTDM/1:1/18019941076 [BREAK]
8d09030a-e4ab-e411-905b-0026b95c8602 2015-02-03 14:34:23.679236 [DEBUG]
mod_freetdm.c:1279 Attached session 8d09030a-e4ab-e411-905b-0026b95c8602 to
channel 1:1
2015-02-03 14:34:23.679236 [DEBUG] mod_freetdm.c:1767 [s1c1][1:1] Changed
state from DOWN to DIALING
2015-02-03 14:34:23.778359 [DEBUG] ftdm_state.c:541 [s1c1][1:1] Executing
state processor for DIALING
2015-02-03 14:34:23.778359 [DEBUG] ftmod_libpri.c:942 -- 1:1 STATE [DIALING]
2015-02-03 14:34:23.778359 [DEBUG] mod_freetdm.c:2707 got clear channel sig
[DIALING]
2015-02-03 14:34:23.778359 [DEBUG] ftmod_libpri.c:950 [s1c1][1:1] Completed
state change from DOWN to DIALING in 95 ms
8d09030a-e4ab-e411-905b-0026b95c8602 2015-02-03 14:34:23.778359 [DEBUG]
switch_core_state_machine.c:472 (FreeTDM/1:1/18019941076) Running State
Change CS_INIT
8d09030a-e4ab-e411-905b-0026b95c8602 2015-02-03 14:34:23.778359 [DEBUG]
switch_core_state_machine.c:512 (FreeTDM/1:1/18019941076) State INIT
8d09030a-e4ab-e411-905b-0026b95c8602 2015-02-03 14:34:23.778359 [DEBUG]
mod_freetdm.c:430 (FreeTDM/1:1/18019941076) State Change CS_INIT ->
CS_ROUTING
8d09030a-e4ab-e411-905b-0026b95c8602 2015-02-03 14:34:23.778359 [DEBUG]
switch_core_session.c:1388 Send signal FreeTDM/1:1/18019941076 [BREAK]
8d09030a-e4ab-e411-905b-0026b95c8602 2015-02-03 14:34:23.778359 [DEBUG]
switch_core_state_machine.c:512 (FreeTDM/1:1/18019941076) State INIT going
to sleep
8d09030a-e4ab-e411-905b-0026b95c8602 2015-02-03 14:34:23.778359 [DEBUG]
switch_core_state_machine.c:472 (FreeTDM/1:1/18019941076) Running State
Change CS_ROUTING
8d09030a-e4ab-e411-905b-0026b95c8602 2015-02-03 14:34:23.778359 [DEBUG]
switch_core_state_machine.c:528 (FreeTDM/1:1/18019941076) State ROUTING
2015-02-03 14:34:23.778359 [DEBUG] mod_freetdm.c:453
FreeTDM/1:1/18019941076 CHANNEL ROUTING
8d09030a-e4ab-e411-905b-0026b95c8602 2015-02-03 14:34:23.778359 [DEBUG]
switch_ivr_originate.c:67 (FreeTDM/1:1/18019941076) State Change CS_ROUTING
-> CS_CONSUME_MEDIA
8d09030a-e4ab-e411-905b-0026b95c8602 2015-02-03 14:34:23.778359 [DEBUG]
switch_core_session.c:1388 Send signal FreeTDM/1:1/18019941076 [BREAK]
8d09030a-e4ab-e411-905b-0026b95c8602 2015-02-03 14:34:23.778359 [DEBUG]
switch_core_state_machine.c:528 (FreeTDM/1:1/18019941076) State ROUTING
going to sleep
8d09030a-e4ab-e411-905b-0026b95c8602 2015-02-03 14:34:23.778359 [DEBUG]
switch_core_state_machine.c:472 (FreeTDM/1:1/18019941076) Running State
Change CS_CONSUME_MEDIA
8d09030a-e4ab-e411-905b-0026b95c8602 2015-02-03 14:34:23.778359 [DEBUG]
switch_core_state_machine.c:547 (FreeTDM/1:1/18019941076) State
CONSUME_MEDIA
8d09030a-e4ab-e411-905b-0026b95c8602 2015-02-03 14:34:23.778359 [DEBUG]
switch_core_state_machine.c:547 (FreeTDM/1:1/18019941076) State
CONSUME_MEDIA going to sleep
2015-02-03 14:34:23.799281 [DEBUG] ftmod_libpri.c:1466 -- Hangup on channel
1:1
2015-02-03 14:34:23.799281 [DEBUG] ftmod_libpri.c:1479 [s1c1][1:1] Changed
state from DIALING to TERMINATING
2015-02-03 14:34:23.799281 [DEBUG] ftdm_state.c:541 [s1c1][1:1] Executing
state processor for TERMINATING
2015-02-03 14:34:23.799281 [DEBUG] ftmod_libpri.c:942 -- 1:1 STATE
[TERMINATING]
2015-02-03 14:34:23.799281 [DEBUG] ftmod_libpri.c:950 [s1c1][1:1] Completed
state change from DIALING to TERMINATING in 0 ms
2015-02-03 14:34:23.799281 [DEBUG] ftdm_io.c:6216 [s1c1][1:1] Scheduling
safety hangup timer
2015-02-03 14:34:23.799281 [DEBUG] mod_freetdm.c:2707 got clear channel sig
[STOP]
8d09030a-e4ab-e411-905b-0026b95c8602 2015-02-03 14:34:23.799281 [NOTICE]
mod_freetdm.c:2731 Hangup FreeTDM/1:1/18019941076 [CS_CONSUME_MEDIA]
[REQUESTED_CHAN_UNAVAIL]
8d09030a-e4ab-e411-905b-0026b95c8602 2015-02-03 14:34:23.799281 [DEBUG]
switch_channel.c:3222 Send signal FreeTDM/1:1/18019941076 [KILL]
8d09030a-e4ab-e411-905b-0026b95c8602 2015-02-03 14:34:23.799281 [DEBUG]
switch_core_session.c:1388 Send signal FreeTDM/1:1/18019941076 [BREAK]
8d09030a-e4ab-e411-905b-0026b95c8602 2015-02-03 14:34:23.799281 [DEBUG]
switch_core_state_machine.c:472 (FreeTDM/1:1/18019941076) Running State
Change CS_HANGUP
8d09030a-e4ab-e411-905b-0026b95c8602 2015-02-03 14:34:23.799281 [DEBUG]
switch_core_state_machine.c:735 (FreeTDM/1:1/18019941076) Callstate Change
DOWN -> HANGUP
8d09030a-e4ab-e411-905b-0026b95c8602 2015-02-03 14:34:23.799281 [DEBUG]
switch_core_state_machine.c:737 (FreeTDM/1:1/18019941076) State HANGUP
2015-02-03 14:34:23.799281 [DEBUG] mod_freetdm.c:544 [1:1]
FreeTDM/1:1/18019941076 CHANNEL HANGUP ENTER
2015-02-03 14:34:23.799281 [DEBUG] mod_freetdm.c:623 [s1c1][1:1] Changed
state from TERMINATING to HANGUP
2015-02-03 14:34:23.819045 [DEBUG] switch_ivr_originate.c:3719 Originate
Resulted in Error Cause: 44 [REQUESTED_CHAN_UNAVAIL]
2015-02-03 14:34:23.918415 [DEBUG] ftdm_state.c:541 [s1c1][1:1] Executing
state processor for HANGUP
2015-02-03 14:34:23.918415 [DEBUG] ftmod_libpri.c:942 -- 1:1 STATE [HANGUP]
2015-02-03 14:34:23.918415 [DEBUG] ftmod_libpri.c:950 [s1c1][1:1] Completed
state change from TERMINATING to HANGUP in 109 ms
2015-02-03 14:34:23.918415 [DEBUG] mod_freetdm.c:643 [1:1]
FreeTDM/1:1/18019941076 CHANNEL HANGUP EXIT
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20150203/65abc05e/attachment-0001.html 