[Freeswitch-users] hangup with cause:WRONG_CALL_STATE

李俊俊 rockxsj at gmail.com
Mon Apr 28 18:02:06 MSD 2014 

I add some code to log the pop function,just like below:
switch_mutex_lock(mod_sofia_globals.mutex);
n = msg_queue_threads;
msg_queue_threads++;
switch_mutex_unlock(mod_sofia_globals.mutex);

switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_WARNING, "MSG Thread %d
Started\n", my_id);


for(;;) {

if (switch_queue_pop(q, &pop) != SWITCH_STATUS_SUCCESS) {
switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_WARNING, "POP FAIL %s\n",
"SELF");
switch_cond_next();
continue;
}

if (pop) {
sofia_dispatch_event_t *de = (sofia_dispatch_event_t *) pop;
switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_WARNING, "MSG Thread %d
Dispatcher Started\n", n);
sofia_process_dispatch_event(&de);
switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_WARNING, "MSG Thread %d
Dispatcher Ended\n", n);
} else {
break;
}
}

And I got logs like below:
2014-04-28 21:23:54.229117 [WARNING] sofia.c:1922 MSG Thread 0 Dispatcher
Started
2014-04-28 21:23:54.229174 [WARNING] sofia.c:1924 MSG Thread 0 Dispatcher
Ended
2014-04-28 21:23:54.231115 [WARNING] sofia.c:1922 MSG Thread 0 Dispatcher
Started
2014-04-28 21:23:54.231137 [WARNING] sofia.c:1924 MSG Thread 0 Dispatcher
Ended
2014-04-28 21:23:54.894118 [WARNING] sofia.c:1922 MSG Thread 0 Dispatcher
Started
2014-04-28 21:23:54.894157 [WARNING] sofia.c:1924 MSG Thread 0 Dispatcher
Ended
2014-04-28 21:23:54.894232 [WARNING] sofia.c:1922 MSG Thread 0 Dispatcher
Started
2014-04-28 21:23:55.200100 [WARNING] sofia.c:1924 MSG Thread 0 Dispatcher
Ended
2014-04-28 21:23:55.200127 [WARNING] sofia.c:1922 MSG Thread 0 Dispatcher
Started
2014-04-28 21:23:55.540108 [WARNING] sofia.c:1924 MSG Thread 0 Dispatcher
Ended
2014-04-28 21:23:55.540108 [WARNING] sofia.c:1922 MSG Thread 0 Dispatcher
Started
2014-04-28 21:23:55.840114 [WARNING] sofia.c:1924 MSG Thread 0 Dispatcher
Ended
2014-04-28 21:23:55.840114 [WARNING] sofia.c:1922 MSG Thread 0 Dispatcher
Started
2014-04-28 21:23:55.840114 [WARNING] sofia.c:1924 MSG Thread 0 Dispatcher
Ended
2014-04-28 21:23:55.840114 [WARNING] sofia.c:1922 MSG Thread 0 Dispatcher
Started
2014-04-28 21:23:56.100116 [WARNING] sofia.c:1924 MSG Thread 0 Dispatcher
Ended
2014-04-28 21:23:56.100116 [WARNING] sofia.c:1922 MSG Thread 0 Dispatcher
Started
2014-04-28 21:23:56.380119 [WARNING] sofia.c:1924 MSG Thread 0 Dispatcher
Ended

I found it is too long between a pop ended and other stated.I think this
will make the pop function execute slow than push.Will it?


2014-04-28 21:22 GMT+08:00 Michael Jerris <mike at jerris.com>:

> This is a completely different issue than i was talking about.  What rate
> of traffic are you putting on this box?  it seems your box is way
> underpowered for whatever your doing, or your using something to lookup
> users or something of the sort that is blocking or taking way too long.
>
> On Apr 28, 2014, at 9:07 AM, 李俊俊 <rockxsj at gmail.com> wrote:
>
> Yes,my code is pulled from the master branch on 4.23.It <http://4.23.it/>seems that the push is fast than pop.I add some code to log the queue
> length,just like below:
> if (!sofia_private) {
>  if (sess_count >= sess_max || !sofia_test_pflag(profile, PFLAG_RUNNING)
> || !switch_core_ready_inbound()) {
> nua_respond(nh, 503, "Maximum Calls In Progress",
> SIPTAG_RETRY_AFTER_STR("300"), NUTAG_WITH_THIS(nua), TAG_END());
>  goto end;
> }
>
> switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_DEBUG,
> "switch_queue_size(mod_sofia_globals.msg_queue):%d\n",
> switch_queue_size(mod_sofia_globals.msg_queue));
>  switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_DEBUG, "critical:%d\n",
> (unsigned int)critical);
>
> if (switch_queue_size(mod_sofia_globals.msg_queue) > (unsigned
> int)critical) {
>  nua_respond(nh, 503, "System Busy", SIPTAG_RETRY_AFTER_STR("300"),
> NUTAG_WITH_THIS(nua), TAG_END());
> goto end;
>  }
>
> if (sofia_test_pflag(profile, PFLAG_STANDBY)) {
> nua_respond(nh, 503, "System Paused", NUTAG_WITH_THIS(nua), TAG_END());
>  goto end;
> }
> }
>
> And I found the switch_queue_size(mod_sofia_globals.msg_queue) is increase
> so fast and almost did not decrease,the below is the log:
> 2014-04-28 18:55:31.416405 [DEBUG] sofia.c:2081
> switch_queue_size(mod_sofia_globals.msg_queue):56157
> 2014-04-28 18:55:31.436402 [DEBUG] sofia.c:2081
> switch_queue_size(mod_sofia_globals.msg_queue):56158
> 2014-04-28 18:55:31.436402 [DEBUG] sofia.c:2081
> switch_queue_size(mod_sofia_globals.msg_queue):56159
> 2014-04-28 18:55:31.476402 [DEBUG] sofia.c:2081
> switch_queue_size(mod_sofia_globals.msg_queue):56160
> 2014-04-28 18:55:31.496402 [DEBUG] sofia.c:2081
> switch_queue_size(mod_sofia_globals.msg_queue):56161
> 2014-04-28 18:55:31.496402 [DEBUG] sofia.c:2081
> switch_queue_size(mod_sofia_globals.msg_queue):56162
> 2014-04-28 18:55:31.496402 [DEBUG] sofia.c:2081
> switch_queue_size(mod_sofia_globals.msg_queue):56163
> 2014-04-28 18:55:31.516402 [DEBUG] sofia.c:2081
> switch_queue_size(mod_sofia_globals.msg_queue):56164
> 2014-04-28 18:55:31.516402 [DEBUG] sofia.c:2081
> switch_queue_size(mod_sofia_globals.msg_queue):56165
> 2014-04-28 18:55:31.536402 [DEBUG] sofia.c:2081
> switch_queue_size(mod_sofia_globals.msg_queue):56166
> 2014-04-28 18:55:31.556402 [DEBUG] sofia.c:2081
> switch_queue_size(mod_sofia_globals.msg_queue):56167
> 2014-04-28 18:55:31.576407 [DEBUG] sofia.c:2081
> switch_queue_size(mod_sofia_globals.msg_queue):56168
> 2014-04-28 18:55:31.576407 [DEBUG] sofia.c:2081
> switch_queue_size(mod_sofia_globals.msg_queue):56169
> 2014-04-28 18:55:31.576407 [DEBUG] sofia.c:2081
> switch_queue_size(mod_sofia_globals.msg_queue):56170
> 2014-04-28 18:55:31.596403 [DEBUG] sofia.c:2081
> switch_queue_size(mod_sofia_globals.msg_queue):56171
> 2014-04-28 18:55:31.616404 [DEBUG] sofia.c:2081
> switch_queue_size(mod_sofia_globals.msg_queue):56169
> 2014-04-28 18:55:31.636404 [DEBUG] sofia.c:2081
> switch_queue_size(mod_sofia_globals.msg_queue):56170
> 2014-04-28 18:55:31.656403 [DEBUG] sofia.c:2081
> switch_queue_size(mod_sofia_globals.msg_queue):56172
> 2014-04-28 18:55:31.656403 [DEBUG] sofia.c:2081
> switch_queue_size(mod_sofia_globals.msg_queue):56173
> 2014-04-28 18:55:31.656403 [DEBUG] sofia.c:2081
> switch_queue_size(mod_sofia_globals.msg_queue):56174
> 2014-04-28 18:55:31.676404 [DEBUG] sofia.c:2081
> switch_queue_size(mod_sofia_globals.msg_queue):56175
> 2014-04-28 18:55:31.676404 [DEBUG] sofia.c:2081
> switch_queue_size(mod_sofia_globals.msg_queue):56175
> 2014-04-28 18:55:31.716404 [DEBUG] sofia.c:2081
> switch_queue_size(mod_sofia_globals.msg_queue):56177
> 2014-04-28 18:55:31.716404 [DEBUG] sofia.c:2081
> switch_queue_size(mod_sofia_globals.msg_queue):56178
> 2014-04-28 18:55:31.756407 [DEBUG] sofia.c:2081
> switch_queue_size(mod_sofia_globals.msg_queue):56180
> 2014-04-28 18:55:31.756407 [DEBUG] sofia.c:2081
> switch_queue_size(mod_sofia_globals.msg_queue):56181
> 2014-04-28 18:55:31.756407 [DEBUG] sofia.c:2081
> switch_queue_size(mod_sofia_globals.msg_queue):56182
> 2014-04-28 18:55:31.756407 [DEBUG] sofia.c:2081
> switch_queue_size(mod_sofia_globals.msg_queue):56183
> 2014-04-28 18:55:31.776414 [DEBUG] sofia.c:2081
> switch_queue_size(mod_sofia_globals.msg_queue):56184
> 2014-04-28 18:55:31.796402 [DEBUG] sofia.c:2081
> switch_queue_size(mod_sofia_globals.msg_queue):56185
> 2014-04-28 18:55:31.836415 [DEBUG] sofia.c:2081
> switch_queue_size(mod_sofia_globals.msg_queue):56179
> 2014-04-28 18:55:31.856415 [DEBUG] sofia.c:2081
> switch_queue_size(mod_sofia_globals.msg_queue):56180
> 2014-04-28 18:55:31.896415 [DEBUG] sofia.c:2081
> switch_queue_size(mod_sofia_globals.msg_queue):56183
> 2014-04-28 18:55:31.896415 [DEBUG] sofia.c:2081
> switch_queue_size(mod_sofia_globals.msg_queue):56184
> 2014-04-28 18:55:31.896415 [DEBUG] sofia.c:2081
> switch_queue_size(mod_sofia_globals.msg_queue):56185
> 2014-04-28 18:55:31.916416 [DEBUG] sofia.c:2081
> switch_queue_size(mod_sofia_globals.msg_queue):56186
> 2014-04-28 18:55:31.916416 [DEBUG] sofia.c:2081
> switch_queue_size(mod_sofia_globals.msg_queue):56187
> 2014-04-28 18:55:31.916416 [DEBUG] sofia.c:2081
> switch_queue_size(mod_sofia_globals.msg_queue):56188
> 2014-04-28 18:55:31.936415 [DEBUG] sofia.c:2081
> switch_queue_size(mod_sofia_globals.msg_queue):56189
> 2014-04-28 18:55:31.936415 [DEBUG] sofia.c:2081
> switch_queue_size(mod_sofia_globals.msg_queue):56190
> 2014-04-28 18:55:31.936415 [DEBUG] sofia.c:2081
> switch_queue_size(mod_sofia_globals.msg_queue):56191
> 2014-04-28 18:55:31.996416 [DEBUG] sofia.c:2081
> switch_queue_size(mod_sofia_globals.msg_queue):56192
> 2014-04-28 18:55:32.036417 [DEBUG] sofia.c:2081
> switch_queue_size(mod_sofia_globals.msg_queue):56194
> 2014-04-28 18:55:32.036417 [DEBUG] sofia.c:2081
> switch_queue_size(mod_sofia_globals.msg_queue):56195
> 2014-04-28 18:55:32.036417 [DEBUG] sofia.c:2081
> switch_queue_size(mod_sofia_globals.msg_queue):56196
> 2014-04-28 18:55:32.056417 [DEBUG] sofia.c:2081
> switch_queue_size(mod_sofia_globals.msg_queue):56197
>
>
> Can you confirm again?
>
>
> 2014-04-28 20:03 GMT+08:00 Michael Jerris <mike at jerris.com>:
>
>> I think we have already fixed this bug.  Have you tried updating to more
>> recent code?
>>
>> On Apr 28, 2014, at 7:46 AM, rockxsj <rockxsj at gmail.com> wrote:
>>
>>  Hi guys!
>>
>> I found that the some of the incoming call will hangup with case:
>> WRONG_CALL_STATE,but else will be ok.After a hour,almost every incoming
>> call will be hangup with the same cause.Then I will restart the
>> freeswitch,it will server like before:some call will be hangup with the
>> cause...
>>
>> 28e10f2e-c851-11e3-a146-85a8fadad1b0 2014-04-20 14:01:15.498169 [WARNING]
>> switch_core_state_machine.c:567 28e10f2e-c851-11e3-a146-85a8fadad1b0
>> sofia/internal/123456 at sipsj.236.cn Abandoned
>> 28e10f2e-c851-11e3-a146-85a8fadad1b0 2014-04-20 14:01:15.498169 [NOTICE]
>> switch_core_state_machine.c:570 Hangup sofia/internal/123456 at sipsj.236.cn[CS_NEW] [WRONG_CALL_STATE]
>>
>> What does Wrong call state mean and what can I do to fix this issue?
>>
>> Everything else is working. I can make outgoing calls and call other
>> extensions.
>>
>> Thanks in advance.
>>
>>
>>
> _________________________________________________________________________
> Professional FreeSWITCH Consulting Services:
> consulting at freeswitch.org
> http://www.freeswitchsolutions.com
>
> 
> 
>
> Official FreeSWITCH Sites
> http://www.freeswitch.org
> http://wiki.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
>
>


-- 
个人主页：http://yazi.whoknow.me
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20140428/5b0a9a04/attachment-0001.html

Join us at ClueCon 2013 Aug 6-8, 2013
More information about the FreeSWITCH-users mailing list