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

Mon Feb 9 17:03:09 MSK 2015

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.

On Fri, Feb 6, 2015 at 5:50 PM, Brian Wiese <
brian.wiese.freeswitch at gmail.com> wrote:

> Thomas:
>
> I haven't seen this exact issue before, but I have had problems with
> glare on our PRI.  Since calls come in starting on the first channel
> you should bridge outgoing calls starting with channel 23:
>
> http://wiki.freeswitch.org/wiki/FreeTDM#Ascending_vs._Descending_Channel_Selection
>
> Also consider enabling the trace feature so you can see what is
> actually being sent and received on the PRI:
> http://wiki.sangoma.com/Freeswitch-FreeTDM-Sangoma-ISDN-Library#q931-trace
>
> Again, this might not be the resolution to your issue but hopefully it
> helps point you in the right direction.
>
> ~Brian
>
> On Tue, Feb 3, 2015 at 4:45 PM, Thomas Johnson <tommyj27 at gmail.com> wrote:
> > 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
> >
> > _________________________________________________________________________
> > Professional FreeSWITCH Consulting Services:
> > consulting at freeswitch.org
> > http://www.freeswitchsolutions.com
> >
> > Official FreeSWITCH Sites
> > http://www.freeswitch.org
> > http://confluence.freeswitch.org
> > http://www.cluecon.com
> >
> > FreeSWITCH-users mailing list
> > FreeSWITCH-users at lists.freeswitch.org
> > http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
> > UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
> > http://www.freeswitch.org
>
> _________________________________________________________________________
> Professional FreeSWITCH Consulting Services:
> consulting at freeswitch.org
> http://www.freeswitchsolutions.com
>
> Official FreeSWITCH Sites
> http://www.freeswitch.org
> http://confluence.freeswitch.org
> http://www.cluecon.com
>
> FreeSWITCH-users mailing list
> FreeSWITCH-users at lists.freeswitch.org
> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
> UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
> http://www.freeswitch.org
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20150209/1f33ba3b/attachment-0001.html 