[Freeswitch-dev] ready() function inside mod_spidermonkey returning False

Fri Mar 18 01:33:39 MSK 2011

Can you retest with latest git
233d3164be4412aaaf8f9f42d8042e48279a018a or preferably the one from
today?

There is a line in originate now to wait for the state to settle
before returning.
This keeps your script from having access to the session before the
state change is complete.

What was happening is you were getting the session faster than the
initial state change was complete during originate at which time it
would go to sleep and do nothing unless someone transferred it etc but
there is a delay from when you change a state and when that state
actually happens.  This should me moot in lastest GIT.

On Wed, Mar 2, 2011 at 8:48 PM, teldev <ustcorporation at yahoo.com> wrote:
> This issue appears to be an open JIRA, so we've added Comments to the JIRA
> but this post contains a few extra details as well.  We have also analyzed
> the C source code and may have found the cause.
>
> http://jira.freeswitch.org/browse/FS-2966?focusedCommentId=22831#action_22831
>
> Here is our system environment:
>
> CentOS 5.5 x64
> Using GIT Head from 3/1/2011
>
> Linux ivr.anyco.corp 2.6.18-194.32.1.el5 #1 SMP Wed Jan 5 17:52:25 EST 2011
> x86_64 x86_64 x86_64 GNU/Linux
>
> processor : 0
> vendor_id : GenuineIntel
> cpu family : 6
> model : 15
> model name : Intel(R) Xeon(R) CPU            5160  @ 3.00GHz
> stepping : 6
> cpu MHz : 2999.999
> cache size : 4096 KB
> physical id : 0
> siblings : 2
> core id : 0
> cpu cores : 2
> apicid : 0
> fpu : yes
> fpu_exception : yes
> cpuid level : 10
> wp : yes
> flags : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat
> pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm syscall nx lm constant_tsc
> pni monitor ds_cpl vmx est tm2 ssse3 cx16 xtpr lahf_lm
> bogomips : 5999.99
> clflush size : 64
> cache_alignment : 64
> address sizes : 36 bits physical, 48 bits virtual
> power management:
>
> processor : 1
> vendor_id : GenuineIntel
> cpu family : 6
> model : 15
> model name : Intel(R) Xeon(R) CPU            5160  @ 3.00GHz
> stepping : 6
> cpu MHz : 2999.999
> cache size : 4096 KB
> physical id : 0
> siblings : 2
> core id : 1
> cpu cores : 2
> apicid : 1
> fpu : yes
> fpu_exception : yes
> cpuid level : 10
> wp : yes
> flags : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat
> pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm syscall nx lm constant_tsc
> pni monitor ds_cpl vmx est tm2 ssse3 cx16 xtpr lahf_lm
> bogomips : 5999.86
> clflush size : 64
> cache_alignment : 64
> address sizes : 36 bits physical, 48 bits virtual
> power management:
>
> We are trying to originate a new call from an existing session from
> javascript using the session constuctor and then calling the ready()
> function.
>
> We have had intermittent call failures from calls generated by
> mod_spidermonkey.
>
> The following is a sequence of events that lead to failure of call
> originated from javascript interpreted by mod_spidermonkey. The following
> are from Freeswitch log, and my comments are on the end of the lines
> followed by //
>
> 2011-02-28 14:04:51.644009 [DEBUG] switch_ivr_originate.c:3408 Originate
> Resulted in Success: [sofia/external/5551212 at 10.10.10.28:5080]
>
> 2011-02-28 14:04:51.644009 [DEBUG] mod_spidermonkey.c:2885
> (sofia/external/5551212 at 10.10.10.28:5080) State Change CS_CONSUME_MEDIA ->
> CS_SOFT_EXECUTE //This occurs in the session constructor inside
> mod_spidermonkey
>
> 2011-02-28 14:04:51.644009 [DEBUG] switch_core_session.c:1116 Send signal
> sofia/external/5551212 at 10.10.10.28:5080 [BREAK]
>
> 2011-02-28 14:04:51.644009 [DEBUG] fs_General.js:233
> [debugmsg].[].[coach.js].[pupil_Init].[5].[5551212] // Our call to “ready()”
> returns before the running state changes
>
> 2011-02-28 14:04:51.644009 [DEBUG] fs_General.js:233
> [debugmsg].[].[coach.js].[pupil_Init].[5].[]
>
> 2011-02-28 14:04:51.644009 [DEBUG] fs_General.js:233
> [debugmsg].[].[coach.js].[pupil_Init].[5].[CS_SOFT_EXECUTE] // The state is
> already CS_SOFT_EXECUTE
>
> 2011-02-28 14:04:51.644009 [DEBUG] fs_General.js:233
> [debugmsg].[].[coach.js].[pupil_Init].[5].[NONE]
>
> 2011-02-28 14:04:51.644009 [DEBUG] fs_General.js:233
> [debugmsg].[].[coach.js].[pupil_Init].[6].[return false]
>
> 2011-02-28 14:04:51.644009 [DEBUG] fs_General.js:233
> [debugmsg].[].[coach.js].[coach_NewSession].[pupil_Init].[failed] // But the
> return value of “ready()” is false
>
> 2011-02-28 14:04:51.644009 [DEBUG] fs_General.js:233
> [debugmsg].[].[coach.js].[coach_NewSession].[7].[]
>
> 2011-02-28 14:04:51.644009 [DEBUG] switch_core_file.c:176 File
> /usr/local/freeswitch/scripts/javascript/apps/public/audio/connection-failed.wav
> sample rate 16000 doesn't match requested rate 8000
>
> 2011-02-28 14:04:51.644009 [DEBUG] switch_ivr_play_say.c:1244 Codec
> Activated L16 at 8000hz 1 channels 20ms
>
> 2011-02-28 14:04:51.645596 [DEBUG] switch_core_state_machine.c:320
> (sofia/external/5551212 at 10.10.10.28:5080) Running State Change
> CS_SOFT_EXECUTE // The running state changed after “ready()” returns
>
> Looking inside the source code for “mod_spidemonkey”, it calls
> “switch_channel_wait_for_state_timeout” on line 2886, which is supposed to
> check for the “running state”, not the “state”. However, inside
> “switch_channel_wait_for_state_timeout” in switch_channel.c, it compares
> “running state” with “want_state” by a “>=”. Since CS_CONSUME_MEDIA >
> CS_SOFT_EXECUTE, this returns true before the running state actually
> changes.
>
> We cannot easily flip the “>=” check, either. There are enumeration values
> such as CS_NEW that are actually smaller than CS_SOFT_EXECUTE and should
> have precedence. Perhaps being in the state of “CS_CONSUME_MEDIA” is an
> unexpected condition to begin with?
>
> On line 15899 of “switch_channel.c”, it checks
> “!switch_channel_state_change_pending(channel)”. This check fails because
> the “running state” and the “state” are different. In other words, the state
> change is indeed pending.
>
> Because the transition time between CS_CONSUME_MEDIA going into
> CS_SOFT_EXECUTE can't be pre-determined, waiting for the completion of a
> call can make all calls take a long time to get answered.  After running
> several tests the failure rate is somewhat unpredictable but fewer failures
> occur with a softphone like Kapanga (1 out of 4 fails) versus a hardware SIP
> phone like our Aastra 6739i SIP phone (3 out of 4 fails).
>
> Thanks in advance for your assistance.
>
> --
> View this message in context: http://freeswitch-dev.995408.n3.nabble.com/ready-function-inside-mod-spidermonkey-returning-False-tp2622494p2622494.html
> Sent from the FreeSWITCH Dev mailing list archive at Nabble.com.
>
> _______________________________________________
> FreeSWITCH-dev mailing list
> FreeSWITCH-dev at lists.freeswitch.org
> http://lists.freeswitch.org/mailman/listinfo/freeswitch-dev
> UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-dev
> http://www.freeswitch.org
>

-- 
Anthony Minessale II

FreeSWITCH http://www.freeswitch.org/
ClueCon http://www.cluecon.com/
Twitter: http://twitter.com/FreeSWITCH_wire

AIM: anthm
MSN:anthony_minessale at hotmail.com
GTALK/JABBER/PAYPAL:anthony.minessale at gmail.com
IRC: irc.freenode.net #freeswitch

FreeSWITCH Developer Conference
sip:888 at conference.freeswitch.org
googletalk:conf+888 at conference.freeswitch.org
pstn:+19193869900