FreeSWITCH中DESTINATION_OUT_OF_ORDER缘由分析

时间 2019-12-04 标签 freeswitch destination order 缘由分析

问题：
在话单中会产生DESTINATION_OUT_OF_ORDER这种挂断缘由, 可是A, B leg都有通话时长，可是貌似时长都比较短，不知道这个会引发什么问题，在FS里是正常仍是异常的？

产生过程：
先originate Aleg, park住，再originate Bleg, 当B按听后，再将ABLeg桥接, uuid_bridge auuid, buuid ，这样会有必定小几率的会出现DESTINATION_OUT_OF_ORDER的挂断缘由。

分析：
这段代码中看出， uuidbrige在等待Bleg的一种状态20秒后未达成，就直接挂掉了，可是因为对FS的代码尚未怎么看过，不知道是什么条件未知足，会致使20S后异常挂机呢？

switch_channel_set_variable(channel, SWITCH_UUID_BRIDGE, NULL);

for (;;) {
	state = switch_channel_get_state(other_channel);
	running_state = switch_channel_get_running_state(other_channel);

	if (switch_channel_down_nosig(other_channel) || switch_channel_down(channel)) {
		break;
	}

	if (state < CS_HANGUP && state == running_state) {

		if (--loops < 1) {
			switch_channel_hangup(channel, SWITCH_CAUSE_DESTINATION_OUT_OF_ORDER);
			switch_channel_hangup(other_channel, SWITCH_CAUSE_DESTINATION_OUT_OF_ORDER);
		}

		if (running_state == CS_RESET) {
			switch_channel_set_state(other_channel, CS_SOFT_EXECUTE);
		}

		if (running_state == CS_SOFT_EXECUTE) {

			if (switch_channel_test_flag(other_channel, CF_UUID_BRIDGE_ORIGINATOR)) {
				goto done;
			} else {
				break;
			}
		}

	} else {
		loops = max;
	}

	switch_yield(20000);
}

switch_core_session_reset(session, SWITCH_TRUE, SWITCH_TRUE);

if (switch_ivr_wait_for_answer(session, other_session) != SWITCH_STATUS_SUCCESS) {
	if (switch_true(switch_channel_get_variable(channel, "uuid_bridge_continue_on_cancel"))) {
		switch_channel_set_state(channel, CS_EXECUTE);
                } else if (switch_true(switch_channel_get_variable(channel, "uuid_bridge_park_on_cancel"))) {
		switch_ivr_park_session(session);
	} else if (!switch_channel_test_flag(channel, CF_TRANSFER)) {
		switch_channel_hangup(channel, SWITCH_CAUSE_ORIGINATOR_CANCEL);
	}
	goto done;
}

ready_a = switch_channel_ready(channel);
ready_b = switch_channel_ready(other_channel);

if (!ready_a || !ready_b) {
	if (!ready_a) {
		switch_channel_hangup(other_channel, SWITCH_CAUSE_DESTINATION_OUT_OF_ORDER);
	}

	if (!ready_b) {
		const char *cid = switch_channel_get_variable(other_channel, "rdnis");
		if (ready_a && cid) {
			switch_ivr_session_transfer(session, cid, NULL, NULL);
		} else {
			switch_channel_hangup(channel, SWITCH_CAUSE_DESTINATION_OUT_OF_ORDER);
		}
	}
	goto done;
}

/* fire events that will change the data table from "show channels" */
if (switch_event_create(&event, SWITCH_EVENT_CHANNEL_EXECUTE) == SWITCH_STATUS_SUCCESS) {
	switch_channel_event_set_data(channel, event);
	switch_event_add_header_string(event, SWITCH_STACK_BOTTOM, "Application", "uuid_bridge");
	switch_event_add_header_string(event, SWITCH_STACK_BOTTOM, "Application-Data", switch_core_session_get_uuid(other_session));
	switch_event_fire(&event);
}

if (switch_event_create(&event, SWITCH_EVENT_CHANNEL_EXECUTE) == SWITCH_STATUS_SUCCESS) {
	switch_channel_event_set_data(other_channel, event);
	switch_event_add_header_string(event, SWITCH_STACK_BOTTOM, "Application", "uuid_bridge");
	switch_event_add_header_string(event, SWITCH_STACK_BOTTOM, "Application-Data", switch_core_session_get_uuid(session));
	switch_event_fire(&event);
}

switch_ivr_multi_threaded_bridge(session, other_session, NULL, NULL, NULL);

state = switch_channel_get_state(channel);
if (!switch_channel_test_flag(channel, CF_TRANSFER) &&
	!switch_channel_test_flag(channel, CF_REDIRECT) && state < CS_HANGUP && state != CS_ROUTING && state != CS_PARK) {
	switch_channel_set_state(channel, CS_EXECUTE);
}
} else {
switch_channel_hangup(channel, SWITCH_CAUSE_DESTINATION_OUT_OF_ORDER);
}

done:

if (other_session) {
	switch_core_session_rwunlock(other_session);
	other_session = NULL;
}

switch_channel_clear_flag(channel, CF_UUID_BRIDGE_ORIGINATOR);

return SWITCH_STATUS_FALSE;
}

FS中的日志以下:

freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:26.752588 [NOTICE] switch_channel.c:1055 New Channel sofia/gw0_002/018605140000 [8709967a-d11f-11e4-9607-a74e6016412e]
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:26.752588 [DEBUG] mod_sofia.c:4627 (sofia/gw0_002/018605140000) State Change CS_NEW -> CS_INIT
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:26.752588 [DEBUG] switch_core_session.c:1388 Send signal sofia/gw0_002/018605140000 [BREAK]
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:26.752588 [DEBUG] switch_core_state_machine.c:472 (sofia/gw0_002/018605140000) Running State Change CS_INIT
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:26.752588 [DEBUG] switch_core_state_machine.c:512 (sofia/gw0_002/018605140000) State INIT
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:26.752588 [DEBUG] mod_sofia.c:87 sofia/gw0_002/018605140000 SOFIA INIT
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:26.752588 [DEBUG] sofia_glue.c:1232 sofia/gw0_002/018605140000 sending invite version: 1.4.15 64bit
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e Local SDP:
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e v=0
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e o=FreeSWITCH 1427057864 1427057865 IN IP4 110.252.198.103
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e s=FreeSWITCH
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e c=IN IP4 110.252.198.103
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e t=0 0
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e m=audio 31542 RTP/AVP 18 8 101 13
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e a=rtpmap:18 G729/8000
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e a=fmtp:18 annexb=no
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e a=rtpmap:8 PCMA/8000
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e a=rtpmap:101 telephone-event/8000
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e a=fmtp:101 0-16
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e a=ptime:20
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e a=sendrecv
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:26.752588 [DEBUG] switch_core_state_machine.c:40 sofia/gw0_002/018605140000 Standard INIT
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:26.752588 [DEBUG] switch_core_state_machine.c:48 (sofia/gw0_002/018605140000) State Change CS_INIT -> CS_ROUTING
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:26.752588 [DEBUG] switch_core_session.c:1388 Send signal sofia/gw0_002/018605140000 [BREAK]
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:26.752588 [DEBUG] switch_core_state_machine.c:512 (sofia/gw0_002/018605140000) State INIT going to sleep
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:26.752588 [DEBUG] switch_core_state_machine.c:472 (sofia/gw0_002/018605140000) Running State Change CS_ROUTING
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:26.752588 [DEBUG] switch_core_session.c:1053 Send signal sofia/gw0_002/018605140000 [BREAK]
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:26.752588 [DEBUG] sofia.c:6614 Channel sofia/gw0_002/018605140000 entering state [calling][0]
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:26.752588 [DEBUG] switch_core_state_machine.c:528 (sofia/gw0_002/018605140000) State ROUTING
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:26.752588 [DEBUG] mod_sofia.c:123 sofia/gw0_002/018605140000 SOFIA ROUTING
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:26.752588 [DEBUG] switch_ivr_originate.c:67 (sofia/gw0_002/018605140000) State Change CS_ROUTING -> CS_CONSUME_MEDIA
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:26.752588 [DEBUG] switch_core_session.c:1388 Send signal sofia/gw0_002/018605140000 [BREAK]
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:26.752588 [DEBUG] switch_core_state_machine.c:528 (sofia/gw0_002/018605140000) State ROUTING going to sleep
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:26.752588 [DEBUG] switch_core_state_machine.c:472 (sofia/gw0_002/018605140000) Running State Change CS_CONSUME_MEDIA
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:26.752588 [DEBUG] switch_core_state_machine.c:547 (sofia/gw0_002/018605140000) State CONSUME_MEDIA
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:26.752588 [DEBUG] switch_core_state_machine.c:547 (sofia/gw0_002/018605140000) State CONSUME_MEDIA going to sleep
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:44.292398 [DEBUG] switch_core_session.c:1053 Send signal sofia/gw0_002/018605140000 [BREAK]
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:44.292398 [DEBUG] switch_core_session.c:1053 Send signal sofia/gw0_002/018605140000 [BREAK]
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:44.292398 [DEBUG] sofia.c:6614 Channel sofia/gw0_002/018605140000 entering state [proceeding][180]
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:44.292398 [DEBUG] sofia.c:6624 Remote SDP:
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e v=0
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e o=- 43015 43015 IN IP4 219.109.173.202
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e s=VOS2009
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e c=IN IP4 219.109.173.202
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e t=0 0
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e m=audio 5226 RTP/AVP 18
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e a=rtpmap:18 G729/8000
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e a=fmtp:18 annexb=no
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:44.292398 [DEBUG] switch_core_media.c:3627 Audio Codec Compare [G729:18:8000:20:8000:1]/[G729:18:8000:20:8000:1]
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:44.292398 [DEBUG] switch_core_media.c:3682 Audio Codec Compare [G729:18:8000:20:8000:1] ++++ is saved as a match
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:44.292398 [DEBUG] switch_core_media.c:3627 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1]
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:44.292398 [DEBUG] switch_core_media.c:2473 Set Codec sofia/gw0_002/018605140000 G729/8000 20 ms 160 samples 8000 bits 1 channels
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:44.292398 [DEBUG] switch_core_codec.c:111 sofia/gw0_002/018605140000 Original read codec set to G729:18
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:44.292398 [DEBUG] switch_core_media.c:3903 No 2833 in SDP. Disable 2833 dtmf and switch to INFO
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:44.292398 [DEBUG] switch_core_media.c:5141 AUDIO RTP [sofia/gw0_002/018605140000] 110.252.198.103 port 31542 -> 219.109.173.202 port 5226 codec: 18 ms: 20
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:44.292398 [DEBUG] switch_rtp.c:3548 Starting timer [soft] 160 bytes per 20ms
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:44.292398 [NOTICE] sofia_media.c:92 Pre-Answer sofia/gw0_002/018605140000!
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:44.292398 [DEBUG] switch_channel.c:3399 (sofia/gw0_002/018605140000) Callstate Change DOWN -> EARLY
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:44.312383 [DEBUG] switch_ivr_bridge.c:1875 (sofia/gw0_002/018605140000) State Change CS_CONSUME_MEDIA -> CS_HIBERNATE
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:44.312383 [DEBUG] switch_core_session.c:1388 Send signal sofia/gw0_002/018605140000 [BREAK]
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:44.312383 [DEBUG] switch_core_state_machine.c:472 (sofia/gw0_002/018605140000) Running State Change CS_HIBERNATE
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:44.312383 [DEBUG] switch_core_state_machine.c:550 (sofia/gw0_002/018605140000) State HIBERNATE
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:44.312383 [DEBUG] mod_sofia.c:160 sofia/gw0_002/018605140000 SOFIA HIBERNATE
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:44.312383 [DEBUG] switch_ivr_bridge.c:835 (sofia/gw0_002/018605140000) State Change CS_HIBERNATE -> CS_RESET
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:44.312383 [DEBUG] switch_core_session.c:1388 Send signal sofia/gw0_002/018605140000 [BREAK]
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:44.312383 [DEBUG] switch_core_state_machine.c:550 (sofia/gw0_002/018605140000) State HIBERNATE going to sleep
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:44.312383 [DEBUG] switch_core_state_machine.c:472 (sofia/gw0_002/018605140000) Running State Change CS_RESET
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:44.312383 [DEBUG] switch_core_state_machine.c:531 (sofia/gw0_002/018605140000) State RESET
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:44.312383 [DEBUG] mod_sofia.c:141 sofia/gw0_002/018605140000 SOFIA RESET
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:44.312383 [DEBUG] switch_ivr_bridge.c:820 sofia/gw0_002/018605140000 CUSTOM RESET
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:44.312383 [DEBUG] switch_core_state_machine.c:118 sofia/gw0_002/018605140000 Standard RESET
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:44.312383 [DEBUG] switch_core_state_machine.c:531 (sofia/gw0_002/018605140000) State RESET going to sleep
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:44.312383 [INFO] switch_channel.c:3062 sofia/gw0_002/018605140000 Flipping CID from "Outbound Call" <6618672560685> to "Outbound Call" <018605140000>
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:44.312383 [DEBUG] mod_commands.c:4460 (sofia/gw0_002/018605140000) State Change CS_RESET -> CS_EXECUTE
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:44.312383 [DEBUG] switch_core_session.c:1388 Send signal sofia/gw0_002/018605140000 [BREAK]
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:44.312383 [DEBUG] switch_core_state_machine.c:472 (sofia/gw0_002/018605140000) Running State Change CS_EXECUTE
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:44.312383 [DEBUG] switch_core_state_machine.c:535 (sofia/gw0_002/018605140000) State EXECUTE
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:44.312383 [DEBUG] mod_sofia.c:178 sofia/gw0_002/018605140000 SOFIA EXECUTE
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:44.312383 [DEBUG] switch_core_state_machine.c:258 sofia/gw0_002/018605140000 Standard EXECUTE
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e EXECUTE sofia/gw0_002/018605140000 park()
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:44.352399 [DEBUG] switch_rtp.c:5853 Correct ip/port confirmed.
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:49.432303 [DEBUG] switch_core_session.c:1053 Send signal sofia/gw0_002/018605140000 [BREAK]
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:49.432303 [DEBUG] switch_core_session.c:1053 Send signal sofia/gw0_002/018605140000 [BREAK]
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:49.452302 [DEBUG] sofia.c:6614 Channel sofia/gw0_002/018605140000 entering state [completing][200]
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:49.452302 [DEBUG] sofia.c:6621 Duplicate SDP
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e v=0
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e o=- 43015 43015 IN IP4 219.109.173.202
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e s=VOS2009
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e c=IN IP4 219.109.173.202
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e t=0 0
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e m=audio 5226 RTP/AVP 18
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e a=rtpmap:18 G729/8000
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e a=fmtp:18 annexb=no
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:49.452302 [DEBUG] switch_core_session.c:1053 Send signal sofia/gw0_002/018605140000 [BREAK]
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:49.452302 [DEBUG] switch_core_session.c:1053 Send signal sofia/gw0_002/018605140000 [BREAK]
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:49.472303 [DEBUG] sofia.c:6614 Channel sofia/gw0_002/018605140000 entering state [ready][200]
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:49.472303 [NOTICE] sofia.c:7416 Channel [sofia/gw0_002/018605140000] has been answered
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e EXECUTE sofia/gw0_002/018605140000 sched_hangup(+6600 alloted_timeout)
freeswitch.log.2015-03-23-13-45-35.1:2015-03-23 13:43:49.472303 [DEBUG] switch_scheduler.c:249 Added task 253969 switch_ivr_schedule_hangup (8709967a-d11f-11e4-9607-a74e6016412e) to run at 1427096029
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:43:49.472303 [DEBUG] switch_channel.c:3689 (sofia/gw0_002/018605140000) Callstate Change EARLY -> ACTIVE
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:44:04.372310 [NOTICE] switch_ivr_bridge.c:873 Hangup sofia/gw0_002/018605140000 [CS_EXECUTE] [DESTINATION_OUT_OF_ORDER]
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:44:04.372310 [DEBUG] switch_channel.c:3222 Send signal sofia/gw0_002/018605140000 [KILL]
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:44:04.372310 [DEBUG] switch_core_session.c:1388 Send signal sofia/gw0_002/018605140000 [BREAK]
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:44:04.392326 [DEBUG] switch_core_session.c:2893 sofia/gw0_002/018605140000 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:44:04.392326 [DEBUG] switch_core_state_machine.c:535 (sofia/gw0_002/018605140000) State EXECUTE going to sleep
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:44:04.392326 [DEBUG] switch_core_state_machine.c:472 (sofia/gw0_002/018605140000) Running State Change CS_HANGUP
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:44:04.392326 [DEBUG] switch_core_state_machine.c:735 (sofia/gw0_002/018605140000) Callstate Change ACTIVE -> HANGUP
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:44:04.392326 [DEBUG] switch_core_state_machine.c:737 (sofia/gw0_002/018605140000) State HANGUP
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:44:04.392326 [DEBUG] mod_sofia.c:413 Channel sofia/gw0_002/018605140000 hanging up, cause: DESTINATION_OUT_OF_ORDER
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:44:04.392326 [DEBUG] mod_sofia.c:465 Sending BYE to sofia/gw0_002/018605140000
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:44:04.392326 [DEBUG] switch_core_state_machine.c:60 sofia/gw0_002/018605140000 Standard HANGUP, cause: DESTINATION_OUT_OF_ORDER
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:44:04.392326 [DEBUG] switch_core_state_machine.c:737 (sofia/gw0_002/018605140000) State HANGUP going to sleep
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:44:04.392326 [DEBUG] switch_core_state_machine.c:504 (sofia/gw0_002/018605140000) State Change CS_HANGUP -> CS_REPORTING
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:44:04.392326 [DEBUG] switch_core_session.c:1388 Send signal sofia/gw0_002/018605140000 [BREAK]
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:44:04.392326 [DEBUG] switch_core_state_machine.c:472 (sofia/gw0_002/018605140000) Running State Change CS_REPORTING
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:44:04.392326 [DEBUG] switch_core_state_machine.c:823 (sofia/gw0_002/018605140000) State REPORTING
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:44:04.392326 [DEBUG] switch_core_state_machine.c:104 sofia/gw0_002/018605140000 Standard REPORTING, cause: DESTINATION_OUT_OF_ORDER
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:44:04.392326 [DEBUG] switch_core_state_machine.c:823 (sofia/gw0_002/018605140000) State REPORTING going to sleep
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:44:04.392326 [DEBUG] switch_core_state_machine.c:498 (sofia/gw0_002/018605140000) State Change CS_REPORTING -> CS_DESTROY
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:44:04.392326 [DEBUG] switch_core_session.c:1388 Send signal sofia/gw0_002/018605140000 [BREAK]
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:44:04.392326 [DEBUG] switch_core_session.c:1615 Session 890502 (sofia/gw0_002/018605140000) Locked, Waiting on external entities
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:44:04.392326 [NOTICE] switch_core_session.c:1633 Session 890502 (sofia/gw0_002/018605140000) Ended
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:44:04.392326 [NOTICE] switch_core_session.c:1637 Close Channel sofia/gw0_002/018605140000 [CS_DESTROY]
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:44:04.392326 [DEBUG] switch_core_state_machine.c:626 (sofia/gw0_002/018605140000) Running State Change CS_DESTROY
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:44:04.392326 [DEBUG] switch_core_state_machine.c:636 (sofia/gw0_002/018605140000) State DESTROY
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:44:04.392326 [DEBUG] mod_sofia.c:323 sofia/gw0_002/018605140000 SOFIA DESTROY
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:44:04.392326 [DEBUG] switch_core_state_machine.c:111 sofia/gw0_002/018605140000 Standard DESTROY
freeswitch.log.2015-03-23-13-45-35.1:8709967a-d11f-11e4-9607-a74e6016412e 2015-03-23 13:44:04.392326 [DEBUG] switch_core_state_machine.c:636 (sofia/gw0_002/018605140000) State DESTROY going to sleep
freeswitch.log.2015-03-23-13-45-35.1:2015-03-23 13:44:04.892637 [DEBUG] switch_scheduler.c:144 Deleting task 253969 switch_ivr_schedule_hangup (8709967a-d11f-11e4-9607-a74e6016412e)

FS官方上说是修复了这个问题,但依然存在, 如今在用的1.6.19版本依然有少许的问题存在

https://freeswitch.org/jira/browse/FS-532638 这个地方说是一个BUG，不过不是已经修复了的么？

曲线救国的方式，有人给FS提过这个BUG, 可是木有打补定，貌似是一个状态正在转变的过程当中，我同时又正在执行uuid_bridge，多线程写状态机的状态值，把状态写飞掉了，session

如今粗爆的在收到事件后，延时200ms再触发uuid_bridge指令，貌似这样的错误会降低一个数量级，但仍然有少许的这样的错误出现。多线程

想一想也怪， FS都已触发出事件了，为何本身内部的状态没有准备好呢？我如今是捕获的channel_progress_media事件到后，再uuid_bridge a， b leg，难道channel_progress_media事件发送和状态机里的状态变动是在不一样的线程里操做的？oop

我是否是能够用channel_state 或是 channel_callstate这两个事件来替换channel_progress_media来uuid_bridge的执行呢？ui

原文发表在: http://bbs.freeswitch.org.cn/t/destination-out-of-orderyuan-yin-fen-xi/419/3 spa

固然这个是当时的一个问题发现过程, 如今又遇到了, 找时间再从根源分析一下...线程