Error 'while sending received' with out-of-order messages

[jimbojd72]

Hi sippers,

I'm trying to handle a case where I am receiving a NOTIFY before a 200 OK after a unSUBSCRIBE to an event as suggested in this thread.

        <!-- Handle receiving NOTIFY before 200 OK -->
    <recv request="NOTIFY" optional="true" next="handle_overlapping_notify_after_unsubscribe">
        <action>
            <ereg regexp=".*" search_in="hdr" header="Subscription-State:" check_it="true" assign_to="2"/>
            <ereg regexp="call-info" search_in="hdr" header="Event:" check_it="true" assign_to="3"/>
            <log message="From is [last_From]. Expires is [$1] [$2] [$3]"/>
        </action>
    </recv>
    <recv response="200">
        <action>
            <ereg regexp="0" search_in="hdr" header="Expires:" check_it="true" assign_to="1"/>
            <log message="From is [last_From]. Expires is [$1]"/>
        </action>
    </recv>
    <recv request="NOTIFY">
        <action>
            <ereg regexp=".*" search_in="hdr" header="Subscription-State:" check_it="true" assign_to="2"/>
            <ereg regexp="call-info" search_in="hdr" header="Event:" check_it="true" assign_to="3"/>
            <log message="From is [last_From]. Expires is [$1] [$2] [$3]"/>
        </action>
    </recv>

<!-- CLASH HAPPEN HERE -->
    <send>
        <![CDATA[
      SIP/2.0 200 OK
      [last_Via:]
      [last_From:]
      [last_To:];tag=[call_number]
      [last_Call-ID:]
      [last_CSeq:]
      Contact: <sip:[local_ip]:[local_port];transport=[transport]>
      [last_Event:]
      User-Agent: PolycomVVX-VVX_400-UA/5.4.5.6771
      Accept-Language: en
      Content-Length: [len]
    ]]>
    </send>
    <nop next="all_done_after_unsubscribe"/>
    <label id="handle_overlapping_notify_after_unsubscribe"/>
    <send>
        <![CDATA[
      SIP/2.0 200 OK
      [last_Via:]
      [last_From:]
      [last_To:];tag=[call_number]
      [last_Call-ID:]
      [last_CSeq:]
      Contact: <sip:[local_ip]:[local_port];transport=[transport]>
      [last_Event:]
      User-Agent: PolycomVVX-VVX_400-UA/5.4.5.6771
      Accept-Language: en
      Content-Length: [len]
    ]]>
    </send>
    <recv response="200">
        <action>
            <ereg regexp="0" search_in="hdr" header="Expires:" check_it="true" assign_to="1"/>
            <log message="From is [last_From]. Expires is [$1]"/>
        </action>
    </recv>
    <label id="all_done_after_unsubscribe"/>

    <!-- Finish Handle receiving NOTIFY before 200 OK -->

Still I am receiving the error while sending (index 22), received like if there is some clashing between sending and receiving as you can see below.

2017-09-05 12:50:42,992 - report - WARNING: stderr for 'uac_sla1' @ ('172.24.0.2', 56345)
b'Resolving remote host \'162.250.63.16\'... Done.\n2017-09-05\t12:50:39.969279\t1504615839.969279: Aborting call on unexpected message for Call-Id \'[email protected]\': while sending (index 22), received \'SIP/2.0 200 OK\r\nVia: SIP/2.0/UDP 172.24.0.2:56345;branch=z9hG4bK-16-1-17;received=24.37.126.10\r\nf: "0jsx1IR5h4M4Iib9N0WvDtf3L6aYmi" <sip:[email protected]>;tag=16SIPpTag001\r\nt: "9000" <sip:[email protected]>;tag=as1a1365b1\r\ni: [email protected]\r\nCSeq: 107 SUBSCRIBE\r\nServer: Jive Application Server\r\nAllow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE\r\nk: replaces\r\nExpires: 0\r\nl: 0\r\nRecord-Route: <sip:[email protected]:5061;lr>\r\n\r\n\'.\n'

I am using version:

SIPp v3.5.1-TLS-SCTP-PCAP-RTPSTREAM built Mar 27 2017, 09:59:05

It may be possible that there is some better way to handle some out-of-order messages

Thanks for your help

[jimbojd72]

FYI, what I did finally to handle this case was to wait for both my NOTIFY and 200 OK to come, then sending 200 OK to the NOTIFY request. If the NOTIFY came first, I just forge a message the assignstr from diverse fields.

just did unSUBSCRIBE with Expires: 0

<!-- Handle receiving NOTIFY before 200 OK -->
    <recv request="NOTIFY" optional="true" next="handle_overlapping_notify_after_unsubscribe">
        <action>
            <ereg regexp=".*" search_in="hdr" header="Subscription-State:" check_it="true" assign_to="2"/>
            <ereg regexp="call-info" search_in="hdr" header="Event:" check_it="true" assign_to="3"/>
            <log message="From is [last_From]. Expires is [$1] [$2] [$3]"/>
        </action>
    </recv>
    <recv response="200">
        <action>
            <ereg regexp="0" search_in="hdr" header="Expires:" check_it="true" assign_to="1"/>
            <log message="From is [last_From]. Expires is [$1]"/>
        </action>
    </recv>
    <recv request="NOTIFY">
        <action>
            <ereg regexp=".*" search_in="hdr" header="Subscription-State:" check_it="true" assign_to="2"/>
            <ereg regexp="call-info" search_in="hdr" header="Event:" check_it="true" assign_to="3"/>
            <log message="From is [last_From]. Expires is [$1] [$2] [$3]"/>
        </action>
    </recv>
    <send>
        <![CDATA[
      SIP/2.0 200 OK
      [last_Via:]
      [last_From:]
      [last_To:];tag=[call_number]
      [last_Call-ID:]
      [last_CSeq:]
      Contact: <sip:[local_ip]:[local_port];transport=[transport]>
      Event: call-info
      User-Agent: LOR_SIPP
      Accept-Language: en
      Content-Length: [len]
    ]]>
    </send>
    <nop next="all_done_after_unsubscribe"/>
    <label id="handle_overlapping_notify_after_unsubscribe"/>
    <!--Save Notify values to forge a 200 OK with it since we can't use last-->
    <nop>
        <action>
            <assignstr assign_to="last_notify_cseq" value="[last_CSeq:]"/>
            <assignstr assign_to="last_via" value="[last_Via:]"/>
            <assignstr assign_to="last_to" value="[last_To:]"/>
            <assignstr assign_to="last_from" value="[last_From:]"/>
        </action>
    </nop>
    <recv response="200">
        <action>
            <ereg regexp="0" search_in="hdr" header="Expires:" check_it="true" assign_to="1"/>
            <log message="From is [last_From]. Expires is [$1]"/>
        </action>
    </recv>
    <send>
        <![CDATA[
      SIP/2.0 200 OK
      [$last_via]
      [$last_from]
      [$last_to]
      [last_Call-ID:]
      [$last_notify_cseq]
      Contact: <sip:[local_ip]:[local_port];transport=[transport]>
      Event: call-info
      User-Agent: LOR_SIPP
      Accept-Language: en
      Content-Length: [len]
    ]]>
    </send>
    <label id="all_done_after_unsubscribe" crlf="true"/>
    <!-- Finish Handle receiving NOTIFY before 200 OK -->

Still I don't see this issue as fixed.

[GeorgeTsaplin]

Same issue because of response retransmission:

<recv request="INVITE" />

<send retrans="500">
<![CDATA[SIP/2.0 200 OK
  [last_Via:]
  [last_From:]
  [last_To:];tag=[call_number]
  [last_Call-ID:]
  [last_CSeq:]
  Contact: <sip:[$callingPhone]@[local_ip]:[local_port]>
  Content-Type: application/sdp
  Content-Length: [len]

  v=0
  o=user1 53655765 2353687637 IN IP[local_ip_type] [local_ip]
  s=-
  c=IN IP[media_ip_type] [media_ip]
  t=0 0
  m=audio [media_port] RTP/AVP 0
  a=rtpmap:0 PCMU/8000
]]>
</send>

<recv request="ACK" crlf="true" optional="true" />

While retransmitting 200 OK got ACK