<div dir="ltr">Thanks for the suggestions. I've already implemented the descending allocation, fixing the immediate problem. I'll look at getting tracing enabled, as I would love to track this down.<br></div><div class="gmail_extra"><br><div class="gmail_quote">On Fri, Feb 6, 2015 at 5:50 PM, Brian Wiese <span dir="ltr"><<a href="mailto:brian.wiese.freeswitch@gmail.com" target="_blank">brian.wiese.freeswitch@gmail.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">Thomas:<br>
<br>
I haven't seen this exact issue before, but I have had problems with<br>
glare on our PRI. Since calls come in starting on the first channel<br>
you should bridge outgoing calls starting with channel 23:<br>
<a href="http://wiki.freeswitch.org/wiki/FreeTDM#Ascending_vs._Descending_Channel_Selection" target="_blank">http://wiki.freeswitch.org/wiki/FreeTDM#Ascending_vs._Descending_Channel_Selection</a><br>
<br>
Also consider enabling the trace feature so you can see what is<br>
actually being sent and received on the PRI:<br>
<a href="http://wiki.sangoma.com/Freeswitch-FreeTDM-Sangoma-ISDN-Library#q931-trace" target="_blank">http://wiki.sangoma.com/Freeswitch-FreeTDM-Sangoma-ISDN-Library#q931-trace</a><br>
<br>
Again, this might not be the resolution to your issue but hopefully it<br>
helps point you in the right direction.<br>
<br>
~Brian<br>
<div><div class="h5"><br>
On Tue, Feb 3, 2015 at 4:45 PM, Thomas Johnson <<a href="mailto:tommyj27@gmail.com">tommyj27@gmail.com</a>> wrote:<br>
> I am trying to track down an issue where FreeTDM seems to get confused about<br>
> the state of channels on my PRI. The state seems to occur on origination;<br>
> FreeTDM opens a channel, and immediately closes it, logging<br>
> REQUESTED_CHAN_UNAVAIL. The channel then sits in the HANGUP state,<br>
> 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<br>
> channel is already in use<br>
><br>
> I can resolve this by restarting Freeswitch, but it is obviously<br>
> less-than-ideal. A bit of relevant logging is at the end of this message. It<br>
> seems to occur immediately after a hangup on the same channel; could I be<br>
> triggering a race condition?<br>
><br>
> <a href="https://freeswitch.org/jira/browse/OPENZAP-220" target="_blank">https://freeswitch.org/jira/browse/OPENZAP-220</a> seems to have similar<br>
> symptoms, but manifests as a different error number. I upgraded Freeswitch<br>
> last week (1.5.15b git 608d3e2 2015-01-22 09:09:59Z 64bit) to ensure that I<br>
> had the patch referenced by the ticket. Is it possible that this could be a<br>
> cabling issue? We're running Freeswitch on FreeBSD 10.0 amd64.<br>
><br>
> I'm happy to provide any other information that would be useful. I'm<br>
> [relatively] new to Freeswitch, so please be gentle ;-).<br>
><br>
> Thank you,<br>
> Tom<br>
><br>
> 2015-02-03 14:34:23.437947 [DEBUG] ftmod_libpri.c:1451 -- Hangup ACK on<br>
> channel 1:1<br>
> 2015-02-03 14:34:23.437947 [DEBUG] ftmod_libpri.c:1460 [s1c1][1:1] Changed<br>
> state from HANGUP to HANGUP_COMPLETE<br>
> 2015-02-03 14:34:23.437947 [DEBUG] ftdm_state.c:541 [s1c1][1:1] Executing<br>
> state processor for HANGUP_COMPLETE<br>
> 2015-02-03 14:34:23.437947 [DEBUG] ftmod_libpri.c:942 -- 1:1 STATE<br>
> [HANGUP_COMPLETE]<br>
> 2015-02-03 14:34:23.437947 [DEBUG] ftmod_libpri.c:950 [s1c1][1:1] Completed<br>
> 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<br>
> state from HANGUP_COMPLETE to DOWN<br>
> 2015-02-03 14:34:23.437947 [DEBUG] ftdm_state.c:541 [s1c1][1:1] Executing<br>
> 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<br>
> 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<br>
> already disabled<br>
> 2015-02-03 14:34:23.437947 [DEBUG] ftdm_io.c:3226 [s1c1][1:1] No need to<br>
> disable input dump<br>
> 2015-02-03 14:34:23.437947 [DEBUG] ftdm_io.c:3257 [s1c1][1:1] No need to<br>
> disable output dump<br>
> 2015-02-03 14:34:23.437947 [DEBUG] mod_freetdm.c:2707 got clear channel sig<br>
> [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<br>
> global variables<br>
> 2015-02-03 14:34:23.679236 [DEBUG] switch_event.c:1688 Parsing variable<br>
> [ignore_early_media]=[true]<br>
> 2015-02-03 14:34:23.679236 [DEBUG] switch_event.c:1688 Parsing variable<br>
> [file]=[46475.tif]<br>
> 2015-02-03 14:34:23.679236 [DEBUG] switch_event.c:1688 Parsing variable<br>
> [jobid]=[293102]<br>
> 2015-02-03 14:34:23.679236 [INFO] ftmod_zt.c:671 Setting echo cancel to 64<br>
> 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]<br>
> 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]<br>
> switch_channel.c:1055 New Channel FreeTDM/1:1/18019941076<br>
> [8d09030a-e4ab-e411-905b-0026b95c8602]<br>
> 8d09030a-e4ab-e411-905b-0026b95c8602 2015-02-03 14:34:23.679236 [DEBUG]<br>
> mod_freetdm.c:1260 (FreeTDM/1:1/18019941076) State Change CS_NEW -> CS_INIT<br>
> 8d09030a-e4ab-e411-905b-0026b95c8602 2015-02-03 14:34:23.679236 [DEBUG]<br>
> 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]<br>
> mod_freetdm.c:1279 Attached session 8d09030a-e4ab-e411-905b-0026b95c8602 to<br>
> channel 1:1<br>
> 2015-02-03 14:34:23.679236 [DEBUG] mod_freetdm.c:1767 [s1c1][1:1] Changed<br>
> state from DOWN to DIALING<br>
> 2015-02-03 14:34:23.778359 [DEBUG] ftdm_state.c:541 [s1c1][1:1] Executing<br>
> 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<br>
> [DIALING]<br>
> 2015-02-03 14:34:23.778359 [DEBUG] ftmod_libpri.c:950 [s1c1][1:1] Completed<br>
> state change from DOWN to DIALING in 95 ms<br>
> 8d09030a-e4ab-e411-905b-0026b95c8602 2015-02-03 14:34:23.778359 [DEBUG]<br>
> switch_core_state_machine.c:472 (FreeTDM/1:1/18019941076) Running State<br>
> Change CS_INIT<br>
> 8d09030a-e4ab-e411-905b-0026b95c8602 2015-02-03 14:34:23.778359 [DEBUG]<br>
> 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]<br>
> mod_freetdm.c:430 (FreeTDM/1:1/18019941076) State Change CS_INIT -><br>
> CS_ROUTING<br>
> 8d09030a-e4ab-e411-905b-0026b95c8602 2015-02-03 14:34:23.778359 [DEBUG]<br>
> 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]<br>
> switch_core_state_machine.c:512 (FreeTDM/1:1/18019941076) State INIT going<br>
> to sleep<br>
> 8d09030a-e4ab-e411-905b-0026b95c8602 2015-02-03 14:34:23.778359 [DEBUG]<br>
> switch_core_state_machine.c:472 (FreeTDM/1:1/18019941076) Running State<br>
> Change CS_ROUTING<br>
> 8d09030a-e4ab-e411-905b-0026b95c8602 2015-02-03 14:34:23.778359 [DEBUG]<br>
> 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<br>
> CHANNEL ROUTING<br>
> 8d09030a-e4ab-e411-905b-0026b95c8602 2015-02-03 14:34:23.778359 [DEBUG]<br>
> switch_ivr_originate.c:67 (FreeTDM/1:1/18019941076) State Change CS_ROUTING<br>
> -> CS_CONSUME_MEDIA<br>
> 8d09030a-e4ab-e411-905b-0026b95c8602 2015-02-03 14:34:23.778359 [DEBUG]<br>
> 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]<br>
> switch_core_state_machine.c:528 (FreeTDM/1:1/18019941076) State ROUTING<br>
> going to sleep<br>
> 8d09030a-e4ab-e411-905b-0026b95c8602 2015-02-03 14:34:23.778359 [DEBUG]<br>
> switch_core_state_machine.c:472 (FreeTDM/1:1/18019941076) Running State<br>
> Change CS_CONSUME_MEDIA<br>
> 8d09030a-e4ab-e411-905b-0026b95c8602 2015-02-03 14:34:23.778359 [DEBUG]<br>
> switch_core_state_machine.c:547 (FreeTDM/1:1/18019941076) State<br>
> CONSUME_MEDIA<br>
> 8d09030a-e4ab-e411-905b-0026b95c8602 2015-02-03 14:34:23.778359 [DEBUG]<br>
> switch_core_state_machine.c:547 (FreeTDM/1:1/18019941076) State<br>
> CONSUME_MEDIA going to sleep<br>
> 2015-02-03 14:34:23.799281 [DEBUG] ftmod_libpri.c:1466 -- Hangup on channel<br>
> 1:1<br>
> 2015-02-03 14:34:23.799281 [DEBUG] ftmod_libpri.c:1479 [s1c1][1:1] Changed<br>
> state from DIALING to TERMINATING<br>
> 2015-02-03 14:34:23.799281 [DEBUG] ftdm_state.c:541 [s1c1][1:1] Executing<br>
> state processor for TERMINATING<br>
> 2015-02-03 14:34:23.799281 [DEBUG] ftmod_libpri.c:942 -- 1:1 STATE<br>
> [TERMINATING]<br>
> 2015-02-03 14:34:23.799281 [DEBUG] ftmod_libpri.c:950 [s1c1][1:1] Completed<br>
> 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<br>
> safety hangup timer<br>
> 2015-02-03 14:34:23.799281 [DEBUG] mod_freetdm.c:2707 got clear channel sig<br>
> [STOP]<br>
> 8d09030a-e4ab-e411-905b-0026b95c8602 2015-02-03 14:34:23.799281 [NOTICE]<br>
> mod_freetdm.c:2731 Hangup FreeTDM/1:1/18019941076 [CS_CONSUME_MEDIA]<br>
> [REQUESTED_CHAN_UNAVAIL]<br>
> 8d09030a-e4ab-e411-905b-0026b95c8602 2015-02-03 14:34:23.799281 [DEBUG]<br>
> 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]<br>
> 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]<br>
> switch_core_state_machine.c:472 (FreeTDM/1:1/18019941076) Running State<br>
> Change CS_HANGUP<br>
> 8d09030a-e4ab-e411-905b-0026b95c8602 2015-02-03 14:34:23.799281 [DEBUG]<br>
> switch_core_state_machine.c:735 (FreeTDM/1:1/18019941076) Callstate Change<br>
> DOWN -> HANGUP<br>
> 8d09030a-e4ab-e411-905b-0026b95c8602 2015-02-03 14:34:23.799281 [DEBUG]<br>
> 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]<br>
> FreeTDM/1:1/18019941076 CHANNEL HANGUP ENTER<br>
> 2015-02-03 14:34:23.799281 [DEBUG] mod_freetdm.c:623 [s1c1][1:1] Changed<br>
> state from TERMINATING to HANGUP<br>
> 2015-02-03 14:34:23.819045 [DEBUG] switch_ivr_originate.c:3719 Originate<br>
> 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<br>
> 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<br>
> state change from TERMINATING to HANGUP in 109 ms<br>
> 2015-02-03 14:34:23.918415 [DEBUG] mod_freetdm.c:643 [1:1]<br>
> FreeTDM/1:1/18019941076 CHANNEL HANGUP EXIT<br>
><br>
</div></div>> _________________________________________________________________________<br>
> Professional FreeSWITCH Consulting Services:<br>
> <a href="mailto:consulting@freeswitch.org">consulting@freeswitch.org</a><br>
> <a href="http://www.freeswitchsolutions.com" target="_blank">http://www.freeswitchsolutions.com</a><br>
><br>
> Official FreeSWITCH Sites<br>
> <a href="http://www.freeswitch.org" target="_blank">http://www.freeswitch.org</a><br>
> <a href="http://confluence.freeswitch.org" target="_blank">http://confluence.freeswitch.org</a><br>
> <a href="http://www.cluecon.com" target="_blank">http://www.cluecon.com</a><br>
><br>
> FreeSWITCH-users mailing list<br>
> <a href="mailto:FreeSWITCH-users@lists.freeswitch.org">FreeSWITCH-users@lists.freeswitch.org</a><br>
> <a href="http://lists.freeswitch.org/mailman/listinfo/freeswitch-users" target="_blank">http://lists.freeswitch.org/mailman/listinfo/freeswitch-users</a><br>
> UNSUBSCRIBE:<a href="http://lists.freeswitch.org/mailman/options/freeswitch-users" target="_blank">http://lists.freeswitch.org/mailman/options/freeswitch-users</a><br>
> <a href="http://www.freeswitch.org" target="_blank">http://www.freeswitch.org</a><br>
<br>
_________________________________________________________________________<br>
Professional FreeSWITCH Consulting Services:<br>
<a href="mailto:consulting@freeswitch.org">consulting@freeswitch.org</a><br>
<a href="http://www.freeswitchsolutions.com" target="_blank">http://www.freeswitchsolutions.com</a><br>
<br>
Official FreeSWITCH Sites<br>
<a href="http://www.freeswitch.org" target="_blank">http://www.freeswitch.org</a><br>
<a href="http://confluence.freeswitch.org" target="_blank">http://confluence.freeswitch.org</a><br>
<a href="http://www.cluecon.com" target="_blank">http://www.cluecon.com</a><br>
<br>
FreeSWITCH-users mailing list<br>
<a href="mailto:FreeSWITCH-users@lists.freeswitch.org">FreeSWITCH-users@lists.freeswitch.org</a><br>
<a href="http://lists.freeswitch.org/mailman/listinfo/freeswitch-users" target="_blank">http://lists.freeswitch.org/mailman/listinfo/freeswitch-users</a><br>
UNSUBSCRIBE:<a href="http://lists.freeswitch.org/mailman/options/freeswitch-users" target="_blank">http://lists.freeswitch.org/mailman/options/freeswitch-users</a><br>
<a href="http://www.freeswitch.org" target="_blank">http://www.freeswitch.org</a><br>
</blockquote></div><br></div>