Menu

SipUnit generates 489 in response to NOTIFY

SipUnit
bantao
2012-03-28
2015-10-26
  • bantao

    bantao - 2012-03-28

    Hi,
    I had a previously working test that strangely turned out to generating 489's in place of the 200OKs that I was generating in response to the NOTIFY requests… the  response is SIP/2.0 489 Received a NOTIFY request with unrecognized event header : message-summary … The NOTIFYs seem to be perfectly ok Not sure why SipUnit started to generate this 489s any clues would help debugging this.

     
  • Becky Mc

    Becky Mc - 2012-03-28

    Hi Brian,

    Can you post the SIP message traces and indicate which side is the SipUnit side?
    (Include the SUBSCRIBE and NOTIFY messages)

    Also, maybe first: check the RFC regarding error checking of received NOTIFY messages for a clue to why the 489 is coming out.

    Regards,
    Becky

     
  • bantao

    bantao - 2012-03-28

    Hi Becky,

    Many thanks for responding … following is the test SIP message trace … also the NOTIFYs are RFC complient that are generated …

    from="192.168.30.149:8097" -> SipUnit End
    to="192.168.8.94:5060"  -> SipServer End

    Cheers !
          - Brian

    <!- Use the  Trace Viewer in src/tools/tracesviewer to view this  trace 
    Here are the stack configuration properties
    javax.sip.IP_ADDRESS= null
    javax.sip.STACK_NAME= testAgent8097
    javax.sip.ROUTER_PATH= null
    javax.sip.OUTBOUND_PROXY= null
    ->
    <description
    logDescription="testAgent8097"
    name="testAgent8097"
    auxInfo="null"/>

    <message
    from="192.168.30.149:8097"
    to="192.168.8.94:5060"
    time="1332935134159"
    isSender="true"
    transactionId="z9hg4bk3f295abbc4fa7a312d22ce976e194bf9"
    callId="d1070d19e219dd0e901b06d8451f16ef@192.168.30.149"
    firstLine="SUBSCRIBE sip:USER_TWO_1332935100813_1@192.168.30.149 SIP/2.0"
    >
    <![CDATA[SUBSCRIBE sip:USER_TWO_1332935100813_1@192.168.30.149 SIP/2.0
    Call-ID: d1070d19e219dd0e901b06d8451f16ef@192.168.30.149
    CSeq: 1 SUBSCRIBE
    From: <sip:USER_TWO_1332935100813_1@192.168.30.149:8097>;tag=USER_TWO_1332935100813_1
    To: <sip:USER_THREE_1332935100813_1@192.168.30.149:8097>
    Via: SIP/2.0/UDP ubiquity.net:8097;branch=z9hG4bK3f295abbc4fa7a312d22ce976e194bf9
    Max-Forwards: 69
    Event: message-summary
    Contact: <sip:USER_TWO_1332935100813_1@192.168.30.149:8097>
    Expires: 60
    Route: <sip:192.168.8.94:5060;transport=udp;lr>
    Content-Length: 0

    ]]>
    </message>

    <message
    from="192.168.8.94:5060"
    to="192.168.30.149:8097"
    time="1332935134219"
    isSender="false"
    transactionId="z9hg4bk3f295abbc4fa7a312d22ce976e194bf9"
    callId="d1070d19e219dd0e901b06d8451f16ef@192.168.30.149"
    firstLine="SIP/2.0 200 OK"
    >
    <![CDATA[SIP/2.0 200 OK
    Via: SIP/2.0/UDP ubiquity.net:8097;branch=z9hG4bK3f295abbc4fa7a312d22ce976e194bf9;received=192.168.30.149
    To: <sip:USER_THREE_1332935100813_1@192.168.30.149:8097>;tag=1735154000*47244640264*1246218737~47244640264~mwi_integrator.sar~
    From: <sip:USER_TWO_1332935100813_1@192.168.30.149:8097>;tag=USER_TWO_1332935100813_1
    Call-ID: d1070d19e219dd0e901b06d8451f16ef@192.168.30.149
    CSeq: 1 SUBSCRIBE
    Contact: <sip:192.168.8.94:5060>
    Server: Ubiquity-AS/9.0.8
    Content-Length: 0

    ]]>
    </message>

    <message
    from="192.168.8.94:5070"
    to="192.168.30.149:8097"
    time="1332935134199"
    isSender="false"
    transactionId="z9hg4bkc0a8085e53de9d100300"
    callId="d1070d19e219dd0e901b06d8451f16ef@192.168.30.149"
    firstLine="NOTIFY sip:USER_TWO_1332935100813_1@192.168.30.149:8097 SIP/2.0"
    >
    <![CDATA[NOTIFY sip:USER_TWO_1332935100813_1@192.168.30.149:8097 SIP/2.0
    Call-ID: d1070d19e219dd0e901b06d8451f16ef@192.168.30.149
    From: <sip:USER_THREE_1332935100813_1@192.168.30.149:8097>;tag=1735154000*47244640264*1246218737~47244640264~mwi_integrator.sar~
    To: <sip:USER_TWO_1332935100813_1@192.168.30.149:8097>;tag=USER_TWO_1332935100813_1
    CSeq: 2 NOTIFY
    Contact: <sip:192.168.8.94:5060>
    Via: SIP/2.0/UDP 192.168.8.94:5070;branch=z9hG4bKC0A8085E53DE9D100300,SIP/2.0/UDP 192.168.8.94:5070;branch=z9hG4bKC0A8085E53DE9D101298
    Event: message-summary
    Subscription-State: active
    Content-Type: application/simple-message-summary
    Max-Forwards: 69
    User-Agent: Ubiquity-AS/9.0.8
    Content-Length: 20

    ]]>
    </message>

    <message
    from="192.168.30.149:8097"
    to="192.168.8.94:5070"
    time="1332935134235"
    isSender="true"
    transactionId="z9hg4bkc0a8085e53de9d100300"
    callId="d1070d19e219dd0e901b06d8451f16ef@192.168.30.149"
    firstLine="SIP/2.0 489 Received a NOTIFY request with unrecognized event header : message-summary"
    >
    <![CDATA[SIP/2.0 489 Received a NOTIFY request with unrecognized event header : message-summary
    Call-ID: d1070d19e219dd0e901b06d8451f16ef@192.168.30.149
    From: <sip:USER_THREE_1332935100813_1@192.168.30.149:8097>;tag=1735154000*47244640264*1246218737~47244640264~mwi_integrator.sar~
    To: <sip:USER_TWO_1332935100813_1@192.168.30.149:8097>;tag=USER_TWO_1332935100813_1
    CSeq: 2 NOTIFY
    Via: SIP/2.0/UDP 192.168.8.94:5070;branch=z9hG4bKC0A8085E53DE9D100300,SIP/2.0/UDP 192.168.8.94:5070;branch=z9hG4bKC0A8085E53DE9D101298
    Content-Length: 0

    ]]>
    </message>

    <message
    from="192.168.30.149:8097"
    to="192.168.8.94:5060"
    time="1332935134244"
    isSender="true"
    transactionId="z9hg4bka3d69e81ddcaea353ef3d733e4067ec3"
    callId="8ab6d581da5a8f4d9961a909a7c8ef1a@192.168.30.149"
    firstLine="NOTIFY sip:USER_THREE_1332935100813_1@192.168.30.149 SIP/2.0"
    >
    <![CDATA[NOTIFY sip:USER_THREE_1332935100813_1@192.168.30.149 SIP/2.0
    Call-ID: 8ab6d581da5a8f4d9961a909a7c8ef1a@192.168.30.149
    CSeq: 3 NOTIFY
    From: <sip:USER_THREE_1332935100813_1@192.168.30.149:8097>;tag=USER_TWO_1332935100813_1
    To: <sip:USER_TWO_1332935100813_1@192.168.30.149:8097>
    Via: SIP/2.0/UDP ubiquity.net:8097;branch=z9hG4bKa3d69e81ddcaea353ef3d733e4067ec3
    Max-Forwards: 69
    Event: message-summary
    Contact: <sip:USER_THREE_1332935100813_1@192.168.30.149:8097>
    Subscription-State: terminated
    Content-Type: application/simple-message-summary
    Route: <sip:192.168.8.94:5060;transport=udp;lr>
    Content-Length: 20

    ]]>
    </message>

    <message
    from="192.168.8.94:5060"
    to="192.168.30.149:8097"
    time="1332935134263"
    isSender="false"
    transactionId="z9hg4bka3d69e81ddcaea353ef3d733e4067ec3"
    callId="8ab6d581da5a8f4d9961a909a7c8ef1a@192.168.30.149"
    firstLine="SIP/2.0 200 OK"
    >
    <![CDATA[SIP/2.0 200 OK
    Via: SIP/2.0/UDP ubiquity.net:8097;branch=z9hG4bKa3d69e81ddcaea353ef3d733e4067ec3;received=192.168.30.149
    To: <sip:USER_TWO_1332935100813_1@192.168.30.149:8097>;tag=1735154000*47244640264*1246218739~47244640264~mwi_integrator.sar~
    From: <sip:USER_THREE_1332935100813_1@192.168.30.149:8097>;tag=USER_TWO_1332935100813_1
    Call-ID: 8ab6d581da5a8f4d9961a909a7c8ef1a@192.168.30.149
    CSeq: 3 NOTIFY
    Contact: <sip:192.168.8.94:5060>
    Server: Ubiquity-AS/9.0.8
    Content-Length: 0

    ]]>
    </message>

    <message
    from="192.168.8.94:5070"
    to="192.168.30.149:8097"
    time="1332935134275"
    isSender="false"
    transactionId="z9hg4bkc0a8085e53de9d100303"
    callId="d1070d19e219dd0e901b06d8451f16ef@192.168.30.149"
    firstLine="NOTIFY sip:USER_TWO_1332935100813_1@192.168.30.149:8097 SIP/2.0"
    >
    <![CDATA[NOTIFY sip:USER_TWO_1332935100813_1@192.168.30.149:8097 SIP/2.0
    Call-ID: d1070d19e219dd0e901b06d8451f16ef@192.168.30.149
    From: <sip:USER_THREE_1332935100813_1@192.168.30.149:8097>;tag=1735154000*47244640264*1246218737~47244640264~mwi_integrator.sar~
    To: <sip:USER_TWO_1332935100813_1@192.168.30.149:8097>;tag=USER_TWO_1332935100813_1
    CSeq: 3 NOTIFY
    Contact: <sip:192.168.8.94:5060>
    Via: SIP/2.0/UDP 192.168.8.94:5070;branch=z9hG4bKC0A8085E53DE9D100303,SIP/2.0/UDP 192.168.8.94:5070;branch=z9hG4bKC0A8085E53DE9D101301
    Event: message-summary
    Subscription-State: active
    Content-Type: application/simple-message-summary
    Max-Forwards: 69
    User-Agent: Ubiquity-AS/9.0.8
    Content-Length: 20

    ]]>
    </message>

    <message
    from="192.168.30.149:8097"
    to="192.168.8.94:5070"
    time="1332935134284"
    isSender="true"
    transactionId="z9hg4bkc0a8085e53de9d100303"
    callId="d1070d19e219dd0e901b06d8451f16ef@192.168.30.149"
    firstLine="SIP/2.0 489 Received a NOTIFY request with unrecognized event header : message-summary"
    >
    <![CDATA[SIP/2.0 489 Received a NOTIFY request with unrecognized event header : message-summary
    Call-ID: d1070d19e219dd0e901b06d8451f16ef@192.168.30.149
    From: <sip:USER_THREE_1332935100813_1@192.168.30.149:8097>;tag=1735154000*47244640264*1246218737~47244640264~mwi_integrator.sar~
    To: <sip:USER_TWO_1332935100813_1@192.168.30.149:8097>;tag=USER_TWO_1332935100813_1
    CSeq: 3 NOTIFY
    Via: SIP/2.0/UDP 192.168.8.94:5070;branch=z9hG4bKC0A8085E53DE9D100303,SIP/2.0/UDP 192.168.8.94:5070;branch=z9hG4bKC0A8085E53DE9D101301
    Content-Length: 0

    ]]>
    </message>

    <!- Use the  Trace Viewer in src/tools/tracesviewer to view this  trace 
    Here are the stack configuration properties
    javax.sip.IP_ADDRESS= null
    javax.sip.STACK_NAME= testAgent8097
    javax.sip.ROUTER_PATH= null
    javax.sip.OUTBOUND_PROXY= null
    ->
    <description
    logDescription="testAgent8097"
    name="testAgent8097"
    auxInfo="null"/>

    <message
    from="192.168.30.149:8097"
    to="192.168.8.94:5060"
    time="1332935135307"
    isSender="true"
    transactionId="z9hg4bk532769710e641ada5518299057af51bb"
    callId="e1b170b595d4573f40aeb98823bf46f3@192.168.30.149"
    firstLine="SUBSCRIBE sip:USER_TWO_1332935100813_1@192.168.30.149 SIP/2.0"
    >
    <![CDATA[SUBSCRIBE sip:USER_TWO_1332935100813_1@192.168.30.149 SIP/2.0
    Call-ID: e1b170b595d4573f40aeb98823bf46f3@192.168.30.149
    CSeq: 5 SUBSCRIBE
    From: <sip:USER_TWO_1332935100813_1@192.168.30.149:8097>;tag=USER_TWO_1332935100813_1
    To: <sip:USER_THREE_1332935100813_1@192.168.30.149:8097>
    Via: SIP/2.0/UDP ubiquity.net:8097;branch=z9hG4bK532769710e641ada5518299057af51bb
    Max-Forwards: 69
    Event: message-summary
    Contact: <sip:USER_TWO_1332935100813_1@192.168.30.149:8097>
    Expires: 60
    Route: <sip:192.168.8.94:5060;transport=udp;lr>
    Content-Length: 0

    ]]>
    </message>

    <message
    from="192.168.8.94:5060"
    to="192.168.30.149:8097"
    time="1332935135324"
    isSender="false"
    transactionId="z9hg4bk532769710e641ada5518299057af51bb"
    callId="e1b170b595d4573f40aeb98823bf46f3@192.168.30.149"
    firstLine="SIP/2.0 200 OK"
    >
    <![CDATA[SIP/2.0 200 OK
    Via: SIP/2.0/UDP ubiquity.net:8097;branch=z9hG4bK532769710e641ada5518299057af51bb;received=192.168.30.149
    To: <sip:USER_THREE_1332935100813_1@192.168.30.149:8097>;tag=1735154000*47244640264*1246218741~47244640264~mwi_integrator.sar~
    From: <sip:USER_TWO_1332935100813_1@192.168.30.149:8097>;tag=USER_TWO_1332935100813_1
    Call-ID: e1b170b595d4573f40aeb98823bf46f3@192.168.30.149
    CSeq: 5 SUBSCRIBE
    Contact: <sip:192.168.8.94:5060>
    Server: Ubiquity-AS/9.0.8
    Content-Length: 0

    ]]>
    </message>

    <message
    from="192.168.8.94:5070"
    to="192.168.30.149:8097"
    time="1332935135327"
    isSender="false"
    transactionId="z9hg4bkc0a8085e53de9d100306"
    callId="e1b170b595d4573f40aeb98823bf46f3@192.168.30.149"
    firstLine="NOTIFY sip:USER_TWO_1332935100813_1@192.168.30.149:8097 SIP/2.0"
    >
    <![CDATA[NOTIFY sip:USER_TWO_1332935100813_1@192.168.30.149:8097 SIP/2.0
    Call-ID: e1b170b595d4573f40aeb98823bf46f3@192.168.30.149
    From: <sip:USER_THREE_1332935100813_1@192.168.30.149:8097>;tag=1735154000*47244640264*1246218741~47244640264~mwi_integrator.sar~
    To: <sip:USER_TWO_1332935100813_1@192.168.30.149:8097>;tag=USER_TWO_1332935100813_1
    CSeq: 6 NOTIFY
    Contact: <sip:192.168.8.94:5060>
    Via: SIP/2.0/UDP 192.168.8.94:5070;branch=z9hG4bKC0A8085E53DE9D100306,SIP/2.0/UDP 192.168.8.94:5070;branch=z9hG4bKC0A8085E53DE9D101304
    Event: message-summary
    Subscription-State: active
    Content-Type: application/simple-message-summary
    Max-Forwards: 69
    User-Agent: Ubiquity-AS/9.0.8
    Content-Length: 20

    ]]>
    </message>

    <message
    from="192.168.30.149:8097"
    to="192.168.8.94:5070"
    time="1332935135332"
    isSender="true"
    transactionId="z9hg4bkc0a8085e53de9d100306"
    callId="e1b170b595d4573f40aeb98823bf46f3@192.168.30.149"
    firstLine="SIP/2.0 489 Received a NOTIFY request with unrecognized event header : message-summary"
    >
    <![CDATA[SIP/2.0 489 Received a NOTIFY request with unrecognized event header : message-summary
    Call-ID: e1b170b595d4573f40aeb98823bf46f3@192.168.30.149
    From: <sip:USER_THREE_1332935100813_1@192.168.30.149:8097>;tag=1735154000*47244640264*1246218741~47244640264~mwi_integrator.sar~
    To: <sip:USER_TWO_1332935100813_1@192.168.30.149:8097>;tag=USER_TWO_1332935100813_1
    CSeq: 6 NOTIFY
    Via: SIP/2.0/UDP 192.168.8.94:5070;branch=z9hG4bKC0A8085E53DE9D100306,SIP/2.0/UDP 192.168.8.94:5070;branch=z9hG4bKC0A8085E53DE9D101304
    Content-Length: 0

    ]]>
    </message>

    <message
    from="192.168.30.149:8097"
    to="192.168.8.94:5060"
    time="1332935135338"
    isSender="true"
    transactionId="z9hg4bkb6a421ec4210603d3a6a61a97406685e"
    callId="e1b170b595d4573f40aeb98823bf46f3@192.168.30.149"
    firstLine="SUBSCRIBE sip:USER_TWO_1332935100813_1@192.168.30.149 SIP/2.0"
    >
    <![CDATA[SUBSCRIBE sip:USER_TWO_1332935100813_1@192.168.30.149 SIP/2.0
    CSeq: 7 SUBSCRIBE
    From: <sip:USER_TWO_1332935100813_1@192.168.30.149:8097>;tag=USER_TWO_1332935100813_1
    To: <sip:USER_THREE_1332935100813_1@192.168.30.149:8097>
    Via: SIP/2.0/UDP ubiquity.net:8097;branch=z9hG4bKb6a421ec4210603d3a6a61a97406685e
    Max-Forwards: 69
    Event: message-summary
    Contact: <sip:USER_TWO_1332935100813_1@192.168.30.149:8097>
    Expires: 0
    Call-ID: e1b170b595d4573f40aeb98823bf46f3@192.168.30.149
    Route: <sip:192.168.8.94:5060;transport=udp;lr>
    Content-Length: 0

    ]]>
    </message>

    <message
    from="192.168.8.94:5060"
    to="192.168.30.149:8097"
    time="1332935135354"
    isSender="false"
    transactionId="z9hg4bkb6a421ec4210603d3a6a61a97406685e"
    callId="e1b170b595d4573f40aeb98823bf46f3@192.168.30.149"
    firstLine="SIP/2.0 200 OK"
    >
    <![CDATA[SIP/2.0 200 OK
    Via: SIP/2.0/UDP ubiquity.net:8097;branch=z9hG4bKb6a421ec4210603d3a6a61a97406685e;received=192.168.30.149
    To: <sip:USER_THREE_1332935100813_1@192.168.30.149:8097>;tag=1735154000*47244640264*1246218743~47244640264~mwi_integrator.sar~
    From: <sip:USER_TWO_1332935100813_1@192.168.30.149:8097>;tag=USER_TWO_1332935100813_1
    Call-ID: e1b170b595d4573f40aeb98823bf46f3@192.168.30.149
    CSeq: 7 SUBSCRIBE
    Contact: <sip:192.168.8.94:5060>
    Server: Ubiquity-AS/9.0.8
    Content-Length: 0

    ]]>
    </message>

    <message
    from="192.168.8.94:5070"
    to="192.168.30.149:8097"
    time="1332935135360"
    isSender="false"
    transactionId="z9hg4bkc0a8085e53de9d100309"
    callId="e1b170b595d4573f40aeb98823bf46f3@192.168.30.149"
    firstLine="NOTIFY sip:USER_TWO_1332935100813_1@192.168.30.149:8097 SIP/2.0"
    >
    <![CDATA[NOTIFY sip:USER_TWO_1332935100813_1@192.168.30.149:8097 SIP/2.0
    Call-ID: e1b170b595d4573f40aeb98823bf46f3@192.168.30.149
    From: <sip:USER_THREE_1332935100813_1@192.168.30.149:8097>;tag=1735154000*47244640264*1246218743~47244640264~mwi_integrator.sar~
    To: <sip:USER_TWO_1332935100813_1@192.168.30.149:8097>;tag=USER_TWO_1332935100813_1
    CSeq: 8 NOTIFY
    Contact: <sip:192.168.8.94:5060>
    Via: SIP/2.0/UDP 192.168.8.94:5070;branch=z9hG4bKC0A8085E53DE9D100309,SIP/2.0/UDP 192.168.8.94:5070;branch=z9hG4bKC0A8085E53DE9D101307
    Event: message-summary
    Subscription-State: terminated
    Max-Forwards: 69
    User-Agent: Ubiquity-AS/9.0.8
    Content-Length: 0

    ]]>
    </message>

    <message
    from="192.168.30.149:8097"
    to="192.168.8.94:5070"
    time="1332935135365"
    isSender="true"
    transactionId="z9hg4bkc0a8085e53de9d100309"
    callId="e1b170b595d4573f40aeb98823bf46f3@192.168.30.149"
    firstLine="SIP/2.0 489 Received a NOTIFY request with unrecognized event header : message-summary"
    >
    <![CDATA[SIP/2.0 489 Received a NOTIFY request with unrecognized event header : message-summary
    Call-ID: e1b170b595d4573f40aeb98823bf46f3@192.168.30.149
    From: <sip:USER_THREE_1332935100813_1@192.168.30.149:8097>;tag=1735154000*47244640264*1246218743~47244640264~mwi_integrator.sar~
    To: <sip:USER_TWO_1332935100813_1@192.168.30.149:8097>;tag=USER_TWO_1332935100813_1
    CSeq: 8 NOTIFY
    Via: SIP/2.0/UDP 192.168.8.94:5070;branch=z9hG4bKC0A8085E53DE9D100309,SIP/2.0/UDP 192.168.8.94:5070;branch=z9hG4bKC0A8085E53DE9D101307
    Content-Length: 0

    ]]>
    </message>

     
  • Becky Mc

    Becky Mc - 2012-03-29

    Hi Brian,

    Sorry - the answer is simple, should have caught it immediately.

    While SipUnit supports generic SUBSCRIBE/NOTIFY handling as outlined in RFC-3265, it only supports a couple of event packages (Event types "presence" or "refer") - it doesn't support any old event package such as "message-summary". It's a matter of being able to handle/validate and interpret the NOTIFY message bodies of the type of event package. For example, for presence, it uses the xsd for "application/pidf+xml" to be able to parse and understand the NOTIFY body content for "presence" event package NOTIFYs.

    You have a couple of options:

    1) modify SipUnit to handle the "message-summary" event package. This will require some development to:
       - add a new subclass of EventSubscriber, similar to the PresenceSubscriber shown in the architecture diagram here  http://www.cafesip.org/projects/sipunit/user_guide.html#mozTocId125415. You'll have to add code to parse/handle NOTIFY message body as per the event package rfc.
      - modify SipPhone.processRequestEvent() to check for your event package type and use your above class.

    2) Use the SUBSCRIBE/NOTIFY high level processing of SipUnit up to a certain point - that is, up to waiting for NOTIFY request, as shown in the signaling diagram here:  http://www.cafesip.org/projects/sipunit/user_guide.html#mozTocId223222
    And then use the low level SipSession.waitRequest() to collect the NOTIFY message yourself and process it yourself. Toward the beginning of that user guide there is a discussion of using low and high level capabilities of SipUnit, but you'll have to handle the NOTIFY message processing in your test program ,yourself. This you should be able to do without having to modify SipUnit, just use SipSession low level methods for that part.

    If you do option 1, please consider contributing it back :)

    Hope this helps, and good luck.
    Becky

     
  • bantao

    bantao - 2012-03-29

    Hi Becky,

    Many thanks for your informative response … It seems that option 1 may be the only solution to the problem… as I have already been working with option 2 and SipUnit still gives me the 489s … In place of when I am sending a reply with a SipSession.sendReply() to the NOTIFY message this is where the 489 is generated.

    Cheers,
         - Brian

     
  • Daniel Brenzel

    Daniel Brenzel - 2015-10-26

    Hi Becky,

    it was verry interesting to knew how to handle this issue. Please actulize the links.

    Thanks in advanced

    Daniel

     

Log in to post a comment.