Summary:	ASTERISK-22217: TestSuite sip_hold test fails in SIPp scenarios on unexpected SIP INVITE requests
Reporter:	Matt Jordan (mjordan)	Labels:	Asterisk12
Date Opened:	2013-07-30 13:48:28	Date Closed:	2013-09-27 08:45:09
Priority:	Major	Regression?
Status:	Closed/Complete	Components:	Channels/chan_sip/General Tests/testsuite
Versions:	12	Frequency of Occurrence
Related Issues:
Environment:		Attachments:
Description:	It appears as if some re-INVITE messages are occurring - apparently to force directmedia - that weren't before. Yay. {noformat} Running ['tests/channels/SIP/sip_hold/run-test'] ... [Jul 30 13:11:14] WARNING[5035]: asterisk.sipp:378 processEnded: Resolving remote host '127.0.0.1'... [Jul 30 13:11:14] WARNING[5035]: asterisk.sipp:378 processEnded: Done. [Jul 30 13:11:14] WARNING[5035]: asterisk.sipp:378 processEnded: 2013-07-30 13:11:14:986 1375204274.986483: Aborting call on unexpected message for Call-Id '37f12a637c8d7f1b17769da73ecf6c75@127.0.0.1:5060': while pausing (index 6), received 'INVITE sip:phone_B@127.0.0.3:5060;transport=UDP SIP/2.0 Via: SIP/2.0/UDP 127.0.0.1:5060;branch=z9hG4bK278ebec0 Max-Forwards: 70 From: "phone_A" <sip:phone_A@127.0.0.1>;tag=as50c16487 To: <sip:127.0.0.3>;tag=1 Contact: <sip:phone_A@127.0.0.1:5060> Call-ID: 37f12a637c8d7f1b17769da73ecf6c75@127.0.0.1:5060 CSeq: 103 INVITE User-Agent: Asterisk PBX SVN-trunk-r395686M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer X-asterisk-Info: SIP re-invite (External RTP bridge) Content-Type: application/sdp Content-Length: 267 v=0 o=root 1387452781 1387452782 IN IP4 127.0.0.2 s=Asterisk PBX SVN-trunk-r395686M c=IN IP4 127.0.0.2 t=0 0 m=audio 2226 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv '. [Jul 30 13:11:14] WARNING[5035]: asterisk.sipp:467 __scenario_callback: SIPp Scenario phone_B_media_restrict.xml Failed [1] [Jul 30 13:11:14] WARNING[5035]: asterisk.sipp:475 __evaluate_scenario_results: SIPp Scenario phone_B_media_restrict.xml Failed [Jul 30 13:11:14] WARNING[5035]: asterisk.sipp:378 processEnded: Resolving remote host '127.0.0.1'... [Jul 30 13:11:14] WARNING[5035]: asterisk.sipp:378 processEnded: Done. [Jul 30 13:11:14] WARNING[5035]: asterisk.sipp:378 processEnded: 2013-07-30 13:11:14:988 1375204274.988396: Aborting call on unexpected message for Call-Id '1-7543@127.0.0.2': while expecting 'BYE' (index 6), received 'INVITE sip:phone_A@127.0.0.2:5060 SIP/2.0 Via: SIP/2.0/UDP 127.0.0.1:5060;branch=z9hG4bK0c48a3e2 Max-Forwards: 70 From: <sip:basicdial@127.0.0.1:5060;user=phone>;tag=as004df771 To: phone_A <sip:phone_A@127.0.0.2:5060>;tag=1 Contact: <sip:basicdial@127.0.0.1:5060> Call-ID: 1-7543@127.0.0.2 CSeq: 102 INVITE User-Agent: Asterisk PBX SVN-trunk-r395686M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer X-asterisk-Info: SIP re-invite (External RTP bridge) Content-Type: application/sdp Content-Length: 268 v=0 o=root 1242229468 1242229469 IN IP4 127.0.0.1 s=Asterisk PBX SVN-trunk-r395686M c=IN IP4 127.0.0.1 t=0 0 m=audio 10848 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv '. [Jul 30 13:11:14] WARNING[5035]: asterisk.sipp:467 __scenario_callback: SIPp Scenario phone_A.xml Failed [1] [Jul 30 13:11:14] WARNING[5035]: asterisk.sipp:475 __evaluate_scenario_results: SIPp Scenario phone_A.xml Failed [Jul 30 13:11:15] WARNING[5035]: asterisk.sipp:378 processEnded: Resolving remote host '127.0.0.1'... [Jul 30 13:11:15] WARNING[5035]: asterisk.sipp:378 processEnded: Done. [Jul 30 13:11:15] WARNING[5035]: asterisk.sipp:378 processEnded: 2013-07-30 13:11:15:193 1375204275.193873: Aborting call on unexpected message for Call-Id '1-7548@127.0.0.2': while expecting '180' (index 2), received 'SIP/2.0 603 Declined Via: SIP/2.0/UDP 127.0.0.2:5060;branch=z9hG4bK-7548-1-0;received=127.0.0.2 From: phone_A <sip:phone_A@127.0.0.2:5060>;tag=1 To: <sip:basicdial@127.0.0.1:5060;user=phone>;tag=as4a10f805 Call-ID: 1-7548@127.0.0.2 CSeq: 1 INVITE Server: Asterisk PBX SVN-trunk-r395686M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 '. [Jul 30 13:11:15] WARNING[5035]: asterisk.sipp:467 __scenario_callback: SIPp Scenario phone_A.xml Failed [1] [Jul 30 13:11:15] WARNING[5035]: asterisk.sipp:475 __evaluate_scenario_results: SIPp Scenario phone_A.xml Failed [Jul 30 13:11:15] WARNING[5035]: asterisk.sipp:378 processEnded: Resolving remote host '127.0.0.1'... Done. [Jul 30 13:11:15] WARNING[5035]: asterisk.sipp:378 processEnded: 2013-07-30 13:11:15:688 1375204275.688405: Aborting call on unexpected message for Call-Id '37f12a637c8d7f1b17769da73ecf6c75@127.0.0.1:5060': while pausing (index 6), received 'INVITE sip:phone_B@127.0.0.3:5060;transport=UDP SIP/2.0 Via: SIP/2.0/UDP 127.0.0.1:5060;branch=z9hG4bK7afe8fbf Max-Forwards: 70 From: "phone_A" <sip:phone_A@127.0.0.1>;tag=as50c16487 To: <sip:127.0.0.3>;tag=1 Contact: <sip:phone_A@127.0.0.1:5060> Call-ID: 37f12a637c8d7f1b17769da73ecf6c75@127.0.0.1:5060 CSeq: 104 INVITE User-Agent: Asterisk PBX SVN-trunk-r395686M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer X-asterisk-Info: SIP re-invite (External RTP bridge) Content-Type: application/sdp Content-Length: 267 v=0 o=root 1387452781 1387452783 IN IP4 127.0.0.2 s=Asterisk PBX SVN-trunk-r395686M c=IN IP4 127.0.0.2 t=0 0 m=audio 2226 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv '. [Jul 30 13:11:15] WARNING[5035]: asterisk.sipp:467 __scenario_callback: SIPp Scenario phone_B_IP_restrict.xml Failed [1] [Jul 30 13:11:15] WARNING[5035]: asterisk.sipp:475 __evaluate_scenario_results: SIPp Scenario phone_B_IP_restrict.xml Failed [Jul 30 13:11:15] WARNING[5035]: asterisk.sipp:378 processEnded: Resolving remote host '127.0.0.1'... Done. [Jul 30 13:11:15] WARNING[5035]: asterisk.sipp:378 processEnded: 2013-07-30 13:11:15:803 1375204275.803695: Aborting call on unexpected message for Call-Id '1-8043@127.0.0.2': while expecting '100' (index 1), received 'SIP/2.0 503 Unavailable Via: SIP/2.0/UDP 127.0.0.2:5060;branch=z9hG4bK-8043-1-0;received=127.0.0.2 From: phone_A <sip:phone_A@127.0.0.2:5060>;tag=1 To: <sip:basicdial@127.0.0.1:5060;user=phone>;tag=as44182b0f Call-ID: 1-8043@127.0.0.2 CSeq: 1 INVITE Server: Asterisk PBX SVN-trunk-r395686M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 '. [Jul 30 13:11:15] WARNING[5035]: asterisk.sipp:467 __scenario_callback: SIPp Scenario phone_A.xml Failed [1] [Jul 30 13:11:15] WARNING[5035]: asterisk.sipp:475 __evaluate_scenario_results: SIPp Scenario phone_A.xml Failed [Jul 30 13:11:19] WARNING[5035]: asterisk.sipp:378 processEnded: Resolving remote host '127.0.0.1'... Done. [Jul 30 13:11:19] WARNING[5035]: asterisk.sipp:378 processEnded: 2013-07-30 13:11:19:599 1375204279.599578: Aborting call on unexpected message for Call-Id '37f12a637c8d7f1b17769da73ecf6c75@127.0.0.1:5060': while pausing (index 12), received 'INVITE sip:phone_B@127.0.0.3:5060;transport=UDP SIP/2.0 Via: SIP/2.0/UDP 127.0.0.1:5060;branch=z9hG4bK66e8c55e Max-Forwards: 70 From: phone_A <sip:phone_B@127.0.0.1>;tag=as50c16487 To: phone_B <sip:phone_B@127.0.0.3:5060>;tag=1 Contact: <sip:phone_A@127.0.0.1:5060> Call-ID: 37f12a637c8d7f1b17769da73ecf6c75@127.0.0.1:5060 CSeq: 105 INVITE User-Agent: Asterisk PBX SVN-trunk-r395686M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer X-asterisk-Info: SIP re-invite (External RTP bridge) Content-Type: application/sdp Content-Length: 268 v=0 o=root 1387452781 1387452785 IN IP4 127.0.0.1 s=Asterisk PBX SVN-trunk-r395686M c=IN IP4 127.0.0.1 t=0 0 m=audio 12068 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=recvonly '. [Jul 30 13:11:19] WARNING[5035]: asterisk.sipp:467 __scenario_callback: SIPp Scenario phone_B_IP_media_restrict.xml Failed [1] [Jul 30 13:11:19] WARNING[5035]: asterisk.sipp:475 __evaluate_scenario_results: SIPp Scenario phone_B_IP_media_restrict.xml Failed [Jul 30 13:11:20] ERROR[5035]: __main__:116 main: Failed to receive 6 MOH start events (received 0) [Jul 30 13:11:20] ERROR[5035]: __main__:119 main: Failed to receive 6 MOH stop events (received 0) [Jul 30 13:11:20] ERROR[5035]: __main__:122 main: Failed to receive 6 user test events (received 4) {noformat}
Comments:	By: Jonathan Rose (jrose) 2013-08-08 14:40:16.603-0500 First part of the failure appears to be resolvable by setting directmedia=no in configs. This exposes another failure though. Asterisk 12 splits MusicOnHold events to MusicOnHoldStart and MusicOnHoldStop so that only the channel snapshot is exposed as data rather than the event name. This does not appear to be taken into account for the test.