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

Thu Mar 3 05:48:13 MSK 2011

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.