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_2283... 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@10.10.10.28:5080] 2011-02-28 14:04:51.644009 [DEBUG] mod_spidermonkey.c:2885 (sofia/external/5551212@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@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@8000hz 1 channels 20ms 2011-02-28 14:04:51.645596 [DEBUG] switch_core_state_machine.c:320 (sofia/external/5551212@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-spiderm... Sent from the FreeSWITCH Dev mailing list archive at Nabble.com.