[Freeswitch-users] Possible Loopback / Originate Race?

Sun Dec 5 10:23:33 MSK 2010

Hi,

(Filed in JIRA FS-2899. Please let me know if posting this on the list as
well is frowned upon.)

I'm using switch_limit in a loopback extension with the following
problematic dialplan fragment (full dialplan context at end of message):

    <extension name="limit_exceeded">

      <condition field="destination_number" expression="^limit_exceeded$">

        <action application="hangup" data="NORMAL_CIRCUIT_CONGESTION"/>

      </condition>

    </extension>

This works fine in MOST cases with the expected result:

  switch_ivr_originate.c:3448 Originate Resulted in Error Cause: 34
[NORMAL_CIRCUIT_CONGESTION]

Every once in a while though this very same extension will magically yield:

  switch_ivr_originate.c:3448 Originate Resulted in Error Cause: 19
[NO_ANSWER]

Looking at the log snippets pasted below the correct result (34) appears
when this sequence of events occurs (first snippet):

  mod_loopback.c:425 Hangup loopback/18884447693-a [CS_CONSUME_MEDIA]
[NORMAL_CIRCUIT_CONGESTION]

  switch_ivr_originate.c:3448 Originate Resulted in Error Cause: 34
[NORMAL_CIRCUIT_CONGESTION]

The incorrect answer (19) appears whenever this sequence shows in the logs:

  switch_ivr_originate.c:3448 Originate Resulted in Error Cause: 19
[NO_ANSWER]

  mod_loopback.c:425 Hangup loopback/18884447701-a [CS_CONSUME_MEDIA]
[NORMAL_CIRCUIT_CONGESTION]

Pouring over my logs this ALWAYS is the case. Whenever the wrong error cause
appears the switch_ivr_originate call precedes the mod_loopback call.
Conversely whenever the correct error cause is given the call sequence is
reversed.

I can reproduce this at will by rapidly invoking the loopback extension in
the dialplan pasted at the bottom of this mail.

Any help is appreciated.

Cheers,

-Slim

----8<----8<----8<----8<----8<----8<----8<----

EXECUTE loopback/18884447693-b hangup(NORMAL_CIRCUIT_CONGESTION)

2010-12-05 01:27:13.318020 [DEBUG] switch_channel.c:2455
(loopback/18884447693-b) Callstate Change EARLY -> HANGUP

2010-12-05 01:27:13.318020 [NOTICE] mod_dptools.c:906 Hangup
loopback/18884447693-b [CS_EXECUTE] [NORMAL_CIRCUIT_CONGESTION]

2010-12-05 01:27:13.319023 [DEBUG] switch_channel.c:2471 Send signal
loopback/18884447693-b [KILL]

2010-12-05 01:27:13.319023 [DEBUG] mod_loopback.c:468 loopback/18884447693-b
CHANNEL KILL

2010-12-05 01:27:13.319023 [DEBUG] switch_core_session.c:1083 Send signal
loopback/18884447693-b [BREAK]

2010-12-05 01:27:13.319023 [DEBUG] mod_loopback.c:468 loopback/18884447693-b
CHANNEL KILL

2010-12-05 01:27:13.320024 [DEBUG] switch_core_session.c:1993
loopback/18884447693-b skip receive message [APPLICATION_EXEC_COMPLETE]
(chann

el is hungup already)

2010-12-05 01:27:13.320024 [DEBUG] switch_core_state_machine.c:366
(loopback/18884447693-b) State EXECUTE going to sleep

2010-12-05 01:27:13.320024 [DEBUG] switch_core_state_machine.c:320
(loopback/18884447693-b) Running State Change CS_HANGUP

2010-12-05 01:27:13.321011 [DEBUG] switch_core_state_machine.c:557
(loopback/18884447693-b) State HANGUP

2010-12-05 01:27:13.321983 [DEBUG] mod_loopback.c:414 loopback/18884447693-b
CHANNEL HANGUP

2010-12-05 01:27:13.321983 [DEBUG] switch_channel.c:2455
(loopback/18884447693-a) Callstate Change EARLY -> HANGUP

2010-12-05 01:27:13.321983 [NOTICE] mod_loopback.c:425 Hangup
loopback/18884447693-a [CS_CONSUME_MEDIA] [NORMAL_CIRCUIT_CONGESTION]

2010-12-05 01:27:13.322995 [DEBUG] switch_ivr_originate.c:3448 Originate
Resulted in Error Cause: 34 [NORMAL_CIRCUIT_CONGESTION]

----8<----8<----8<----8<----8<----8<----8<----

EXECUTE loopback/18884447701-b hangup(NORMAL_CIRCUIT_CONGESTION)

2010-12-05 01:27:14.364448 [DEBUG] switch_channel.c:2455
(loopback/18884447701-b) Callstate Change EARLY -> HANGUP

2010-12-05 01:27:14.365470 [NOTICE] mod_dptools.c:906 Hangup
loopback/18884447701-b [CS_EXECUTE] [NORMAL_CIRCUIT_CONGESTION]

2010-12-05 01:27:14.365470 [DEBUG] switch_channel.c:2471 Send signal
loopback/18884447701-b [KILL]

2010-12-05 01:27:14.365470 [DEBUG] mod_loopback.c:468 loopback/18884447701-b
CHANNEL KILL

2010-12-05 01:27:14.365470 [DEBUG] switch_core_session.c:1083 Send signal
loopback/18884447701-b [BREAK]

2010-12-05 01:27:14.366485 [DEBUG] mod_loopback.c:468 loopback/18884447701-b
CHANNEL KILL

2010-12-05 01:27:14.366485 [DEBUG] switch_core_session.c:1993
loopback/18884447701-b skip receive message [APPLICATION_EXEC_COMPLETE]
(chann

el is hungup already)

2010-12-05 01:27:14.366485 [DEBUG] switch_core_state_machine.c:366
(loopback/18884447701-b) State EXECUTE going to sleep

2010-12-05 01:27:14.367508 [DEBUG] switch_core_state_machine.c:320
(loopback/18884447701-b) Running State Change CS_HANGUP

2010-12-05 01:27:14.369585 [DEBUG] switch_core_state_machine.c:557
(loopback/18884447701-b) State HANGUP

2010-12-05 01:27:14.369585 [DEBUG] mod_loopback.c:414 loopback/18884447701-b
CHANNEL HANGUP

2010-12-05 01:27:14.369585 [DEBUG] switch_channel.c:2455
(loopback/18884447701-a) Callstate Change EARLY -> HANGUP

2010-12-05 01:27:14.369585 [DEBUG] switch_ivr_originate.c:3448 Originate
Resulted in Error Cause: 19 [NO_ANSWER]

2010-12-05 01:27:14.369585 [NOTICE] mod_loopback.c:425 Hangup
loopback/18884447701-a [CS_CONSUME_MEDIA] [NORMAL_CIRCUIT_CONGESTION]

----8<----8<----8<----8<----8<----8<----8<----

  <context name="tech-outbound">

    <extension name="tech-outbound">

      <condition field="destination_number" expression="^1888(\d{7})$">

        <action application="info"/>

        <action application="set" data="loopback_bowout=false"/>

        <action application="limit" data="db outgoing goip 1" />

        <action application="bridge"
data="{ignore_early_media=true}sofia/internal/${destination_number}@192.168.
3.11:5060"/>

      </condition>

    </extension>

    <extension name="limit_exceeded">

      <condition field="destination_number" expression="^limit_exceeded$">

        <action application="<nothing> OR <answer> OR <pre_answer>"/> <!--
Tried all 3 variations, no difference -->

        <action application="hangup" data="NORMAL_CIRCUIT_CONGESTION"/>

      </condition>

    </extension>

  </context>

-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20101205/f1fe8901/attachment-0001.html 