<div dir="ltr"><div>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.<br><br>2015-02-03 08:25:04.774438 [ERR] ftmod_libpri.c:1883 [s1c1][1:1] -- Selected channel is already in use<br><br> 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?<br><br><a href="https://freeswitch.org/jira/browse/OPENZAP-220">https://freeswitch.org/jira/browse/OPENZAP-220</a> 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&#39;re running Freeswitch on FreeBSD 10.0 amd64.<br><br></div><div>I&#39;m happy to provide any other information that would be useful. I&#39;m [relatively] new to Freeswitch, so please be gentle ;-).<br></div><div><br>Thank you,<br>Tom<br><br>2015-02-03 14:34:23.437947 [DEBUG] ftmod_libpri.c:1451 -- Hangup ACK on channel 1:1<br>2015-02-03 14:34:23.437947 [DEBUG] ftmod_libpri.c:1460 [s1c1][1:1] Changed state from HANGUP to HANGUP_COMPLETE<br>2015-02-03 14:34:23.437947 [DEBUG] ftdm_state.c:541 [s1c1][1:1] Executing state processor for HANGUP_COMPLETE<br>2015-02-03 14:34:23.437947 [DEBUG] ftmod_libpri.c:942 -- 1:1 STATE [HANGUP_COMPLETE]<br>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<br>2015-02-03 14:34:23.437947 [DEBUG] ftmod_libpri.c:1268 [s1c1][1:1] Changed state from HANGUP_COMPLETE to DOWN<br>2015-02-03 14:34:23.437947 [DEBUG] ftdm_state.c:541 [s1c1][1:1] Executing state processor for DOWN<br>2015-02-03 14:34:23.437947 [DEBUG] ftmod_libpri.c:942 -- 1:1 STATE [DOWN]<br>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<br>2015-02-03 14:34:23.437947 [DEBUG] ftdm_io.c:3194 [s1c1][1:1] DTMF debug is already disabled<br>2015-02-03 14:34:23.437947 [DEBUG] ftdm_io.c:3226 [s1c1][1:1] No need to disable input dump<br>2015-02-03 14:34:23.437947 [DEBUG] ftdm_io.c:3257 [s1c1][1:1] No need to disable output dump<br>2015-02-03 14:34:23.437947 [DEBUG] mod_freetdm.c:2707 got clear channel sig [RELEASED]<br>2015-02-03 14:34:23.437947 [DEBUG] ftdm_io.c:6873 Cleared call with id 37<br>2015-02-03 14:34:23.437947 [DEBUG] ftdm_io.c:2999 [s1c1][1:1] channel done<br>2015-02-03 14:34:23.437947 [DEBUG] ftmod_libpri.c:978 -- Closed channel 1:1<br>2015-02-03 14:34:23.679236 [DEBUG] switch_ivr_originate.c:2099 Parsing global variables<br>2015-02-03 14:34:23.679236 [DEBUG] switch_event.c:1688 Parsing variable [ignore_early_media]=[true]<br>2015-02-03 14:34:23.679236 [DEBUG] switch_event.c:1688 Parsing variable [file]=[46475.tif]<br>2015-02-03 14:34:23.679236 [DEBUG] switch_event.c:1688 Parsing variable [jobid]=[293102]<br>2015-02-03 14:34:23.679236 [INFO] ftmod_zt.c:671 Setting echo cancel to 64 taps for 1:1<br>2015-02-03 14:34:23.679236 [DEBUG] mod_freetdm.c:403 Set codec PCMU 20ms<br>8d09030a-e4ab-e411-905b-0026b95c8602 2015-02-03 14:34:23.679236 [DEBUG] mod_freetdm.c:1251 Connect outbound channel FreeTDM/1:1/18019941076<br>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]<br>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 -&gt; CS_INIT<br>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]<br>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<br>2015-02-03 14:34:23.679236 [DEBUG] mod_freetdm.c:1767 [s1c1][1:1] Changed state from DOWN to DIALING<br>2015-02-03 14:34:23.778359 [DEBUG] ftdm_state.c:541 [s1c1][1:1] Executing state processor for DIALING<br>2015-02-03 14:34:23.778359 [DEBUG] ftmod_libpri.c:942 -- 1:1 STATE [DIALING]<br>2015-02-03 14:34:23.778359 [DEBUG] mod_freetdm.c:2707 got clear channel sig [DIALING]<br>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<br>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<br>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<br>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 -&gt; CS_ROUTING<br>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]<br>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<br>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<br>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<br>2015-02-03 14:34:23.778359 [DEBUG] mod_freetdm.c:453 FreeTDM/1:1/18019941076 CHANNEL ROUTING<br>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 -&gt; CS_CONSUME_MEDIA<br>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]<br>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<br>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<br>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<br>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<br>2015-02-03 14:34:23.799281 [DEBUG] ftmod_libpri.c:1466 -- Hangup on channel 1:1<br>2015-02-03 14:34:23.799281 [DEBUG] ftmod_libpri.c:1479 [s1c1][1:1] Changed state from DIALING to TERMINATING<br>2015-02-03 14:34:23.799281 [DEBUG] ftdm_state.c:541 [s1c1][1:1] Executing state processor for TERMINATING<br>2015-02-03 14:34:23.799281 [DEBUG] ftmod_libpri.c:942 -- 1:1 STATE [TERMINATING]<br>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<br>2015-02-03 14:34:23.799281 [DEBUG] ftdm_io.c:6216 [s1c1][1:1] Scheduling safety hangup timer<br>2015-02-03 14:34:23.799281 [DEBUG] mod_freetdm.c:2707 got clear channel sig [STOP]<br>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]<br>8d09030a-e4ab-e411-905b-0026b95c8602 2015-02-03 14:34:23.799281 [DEBUG] switch_channel.c:3222 Send signal FreeTDM/1:1/18019941076 [KILL]<br>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]<br>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<br>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 -&gt; HANGUP<br>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<br>2015-02-03 14:34:23.799281 [DEBUG] mod_freetdm.c:544 [1:1] FreeTDM/1:1/18019941076 CHANNEL HANGUP ENTER<br>2015-02-03 14:34:23.799281 [DEBUG] mod_freetdm.c:623 [s1c1][1:1] Changed state from TERMINATING to HANGUP<br>2015-02-03 14:34:23.819045 [DEBUG] switch_ivr_originate.c:3719 Originate Resulted in Error Cause: 44 [REQUESTED_CHAN_UNAVAIL]<br>2015-02-03 14:34:23.918415 [DEBUG] ftdm_state.c:541 [s1c1][1:1] Executing state processor for HANGUP<br>2015-02-03 14:34:23.918415 [DEBUG] ftmod_libpri.c:942 -- 1:1 STATE [HANGUP]<br>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<br>2015-02-03 14:34:23.918415 [DEBUG] mod_freetdm.c:643 [1:1] FreeTDM/1:1/18019941076 CHANNEL HANGUP EXIT<br></div></div>