[reSIProcate] repro crash with Jitsi
Scott Godin
sgodin at sipspectrum.com
Tue Jan 29 11:43:18 CST 2013
I don't think that is a problem - when we go to parse the message is
appears to be reassembled properly. From your original log you posted:
DEBUG | 20130127-160854.896 | repro | RESIP:TRANSPORT | 140422323181312
| ConnectionBase.cxx:418 | ##Connection: CONN_BASE: 0x7fb6a8234460 [ V4
192.168.1.100:49269 TLS target domain=unspecified mFlowKey=31 ]
received: PUBLISH sip:1001 at srv1.office.readytechnology.co.uk SIP/2.0
Via: SIP/2.0/TLS
192.168.1.100:49269;branch=z9hG4bK-373139-05d032d540e9bca18e3af732e0c948df
Max-Forwards: 70
Contact: "1001"
<sip:1001 at 192.168.1.100:49269;transport=tls;registering_acc=
srv1_office_readytechnology_co_uk>
To: "1001" <sip:1001 at srv1.office.readytechnology.co.uk>
From: "1001" <sip:1001 at srv1.office.readytechnology.co.uk>;tag=c72de72a
Call-ID: 9e82664c30f04d33d1ce879ab846a60b at 0:0:0:0:0:0:0:0
CSeq: 2 PUBLISH
Expires: 3600
Content-Type: application/pidf+xml
Proxy-Authorization: Digest
username="1001",realm="srv1.office.readytechnology.co.uk",nonce="1359299327:
1ba2dffdf6697b06053efcfe4736f581",uri="
sip:1001 at srv1.office.readytechnology.co.uk",response="
71efd5b4af3d25d2405c0e84d9c8e4eb",algorithm=MD5,qop=auth,
cnonce="xyz",nc=00000001
User-Agent: Jitsi1.1.4400.10268Windows 7
Event: presence
Content-Length: 452
<?xml version="1.0" encoding="UTF-8" standalone="no"?><presence
xmlns="urn:ietf:params:xml:ns:pidf"
xmlns:dm="urn:ietf:params:xml:ns:pidf:data-model"
xmlns:rpid="urn:ietf:params:xml:ns:pidf:rpid"
entity="sip:1001 at srv1.office.readytechnology.co.uk"><dm:person
id="p556"><rpid:activities/></dm:person><tuple
id="t6311"><status><basic>open</basic></status><contact>
sip:1001 at srv1.office.readytechnology.co.uk</contact><note>Online</note></
tuple></presence>
Scott
On Tue, Jan 29, 2013 at 12:39 PM, Daniel Pocock <daniel at pocock.com.au>wrote:
> **
> On 29/01/13 17:32, Byron Campen wrote:
>
> Uh, that's odd; a "[UBLISH" request? I would suspect that something is
> going wrong in our garbage-checking. This should probably be rejected with
> a 400, since this probably should not be considered a retransmission. Is
> the original request similarly formed?
>
>
>
> I just did a grep of the log to see if this happens regularly, this is
> what I found:
>
> $ cat crash1.log | grep 'bytes \['
> STACK | 20130127-160847.807 | repro | RESIP:TRANSPORT | 140422323181312 |
> ssl/TlsConnection.cxx:317 | SSL_read returned -1 bytes []
>
> STACK | 20130127-160854.895 | repro | RESIP:TRANSPORT | 140422323181312 |
> ssl/TlsConnection.cxx:317 | SSL_read returned 1 bytes [P]
> STACK | 20130127-160854.895 | repro | RESIP:TRANSPORT | 140422323181312 |
> ssl/TlsConnection.cxx:317 | SSL_read returned 1352 bytes [UBLISH
> sip:1001 at srv1.office.readytechnology.co.uk SIP/2.0
>
> STACK | 20130127-160854.896 | repro | RESIP:TRANSPORT | 140422323181312 |
> ssl/TlsConnection.cxx:317 | SSL_read returned -1 bytes []
>
> Notice a 1 byte read with [P]? I'm not sure if this could be the way
> Jitsi is sending stuff over TLS, or a problem with the way resip/repro is
> receiving it?
>
>
>
>
> Best regards,
> Byron Campen
>
>
> On Mon, Jan 28, 2013 at 11:32 PM, Daniel Pocock <daniel at pocock.com.au>wrote:
>
>>
>>
>> On 29/01/13 00:26, Byron Campen wrote:
>> > We should be tossing out the "full" response (mNextTransmission), but
>> > retaining the serialized retransmit buffer (mMsgToRetransmit). Did we
>> ever
>> > successfully serialize/transmit this response? Perhaps there is a bug
>> that
>>
>>
>>
>> The 100 Trying response was sent about 3 seconds before the new PUBLISH
>> request
>>
>> STACK | 20130127-160851.209 | repro | RESIP:TRANSPORT | 140422323181312
>> | ssl/TlsConnection.cxx:470 | Did TLS write 339 339 [[SIP/2.0 100 Trying
>> Via: SIP/2.0/TLS
>> 192.168.1.100:49269
>> ;branch=z9hG4bK-373139-05d032d540e9bca18e3af732e0c948df
>> To: "1001" <sip:1001 at srv1.office.readytechnology.co.uk>
>> From: "1001" <sip:1001 at srv1.office.readytechnology.co.uk>;tag=c72de72a
>> Call-ID: 9e82664c30f04d33d1ce879ab846a60b at 0:0:0:0:0:0:0:0
>> CSeq: 2 PUBLISH
>> Content-Length: 0
>>
>> ]]
>> STACK | 20130127-160854.895 | repro | RESIP:TRANSPORT | 140422323181312
>> | ssl/TlsConnection.cxx:317 | SSL_read returned 1 bytes [P]
>> STACK | 20130127-160854.895 | repro | RESIP:TRANSPORT | 140422323181312
>> | ssl/TlsConnection.cxx:369 | SSL bytesRead=1
>> DEBUG | 20130127-160854.895 | repro | RESIP:TRANSPORT | 140422323181312
>> | ConnectionBase.cxx:115 | In State: NewMessage
>> DEBUG | 20130127-160854.895 | repro | RESIP:TRANSPORT | 140422323181312
>> | ConnectionBase.cxx:161 | ConnectionBase::process setting source [ V4
>> 192.168.1.100:49269 TLS target domain=unspecified mFlowKey=31 ]
>> DEBUG | 20130127-160854.895 | repro | RESIP:TRANSPORT | 140422323181312
>> | Connection.cxx:298 | Connection::performReads() read=1
>> STACK | 20130127-160854.895 | repro | RESIP:TRANSPORT | 140422323181312
>> | ssl/TlsConnection.cxx:317 | SSL_read returned 1352 bytes [UBLISH
>> sip:1001 at srv1.office.readytechnology.co.uk SIP/2.0
>> Call-ID: 9e82664c30f04d33d1ce879ab846a60b at 0:0:0:0:0:0:0:0
>> CSeq: 2 PUBLISH
>> From: "1001" <sip:1001 at srv1.office.readytechnology.co.uk>;tag=c72de72a
>> To: "1001" <sip:1001 at srv1.office.readytechnology.co.uk>
>> Max-Forwards: 70
>> Content-Type: application/pidf+xml
>> Contact: "1001"
>>
>> <sip:1001 at 192.168.1.100:49269;transport=tls;registering_acc=srv1_office_readytechnology_co_uk>
>> User-Agent: Jitsi1.1.4400.10268Windows 7
>> Expires: 3600
>> Event: presence
>> Via: SIP/2.0/TLS
>> 192.168.1.100:49269
>> ;branch=z9hG4bK-373139-05d032d540e9bca18e3af732e0c948df
>> Proxy-Authorization: Digest
>> username="1001",realm="srv1.office.readytechnology.co.uk
>> ",nonce="1359299327:1ba2dffdf6697b06053efcfe4736f581",uri="
>> sip:1001 at srv1.office.readytechnology.co.uk
>> ",response="71efd5b4af3d25d2405c0e84d9c8e4eb",algorithm=MD5,qop=auth,cnonce="xyz",nc=00000001
>> Content-Length: 452
>>
>>
>>
>>
>>
>>
>>
>> > broke the serialization? Been a very long time since I've looked at
>> this...
>> >
>> > Best regards,
>> > Byron Campen
>> >
>> >
>> > On Mon, Jan 28, 2013 at 10:00 AM, Scott Godin <sgodin at sipspectrum.com
>> >wrote:
>> >
>> >> The assert is indicating a bug so it is valid.
>> >>
>> >> After a quick look at the offending code, my guess is that we have
>> >> received a re-transmission of a non-invite request (ie PUBLISH) after
>> we
>> >> have formed and sent our response, and we are supposed to be
>> re-responding
>> >> with the same response as last time. However one of the code changes
>> made
>> >> in the resip-b-TKLC-perf_work branch merge was to throw away the
>> >> mNextTransmission if it is a response. I suspect the purpose was to
>> try
>> >> and free up some memory as soon as possible. However I see at least
>> two
>> >> places in the code where re-transmitting a stored response is required.
>> >> 1. Appears to be what you have found - Server Non-Invite transaction
>> >> after receiving a re-transmitted requested for which we have already
>> >> responded.
>> >> 2. When TimerG expires (Server Invite transaction) and we need to re
>> >> transmit an Invite response when we don't see the resulting ACK.
>> >>
>> >> I am inclined to just comment out the code block starting on line 2567
>> in
>> >> order to fix this:
>> >> // !bwc! If mNextTransmission is a non-ACK request, we need to
>> >> save the
>> >> // initial request in case we need to send a simulated 408 or
>> a
>> >> 503 to
>> >> // the TU (at least, until we get a response back)
>> >> if(!mNextTransmission->isRequest() ||
>> >> mNextTransmission->method()==ACK)
>> >> {
>> >> delete mNextTransmission;
>> >> mNextTransmission=0;
>> >> }
>> >>
>> >> However I'd like for Byron to chime in here, since these were
>> originally
>> >> his changes.
>> >>
>> >> Regards,
>> >> Scott
>> >>
>> >> On Sun, Jan 27, 2013 at 4:44 PM, Daniel Pocock <daniel at pocock.com.au
>> >wrote:
>> >>
>> >>>
>> >>>
>> >>>
>> >>> I had heard about this in a private email, and have been `lucky'
>> enough
>> >>> to observe it myself now, with a full log at STACK level too
>> >>>
>> >>> The UA (sip:1001 at srv1) is Jitsi v1.1.4400.10268 and repro is r9959
>> (main)
>> >>>
>> >>> The packet from Jitsi is below - has anyone seen similar issues with
>> >>> presence requests or Jitsi? Should the assert(0) be triggered there,
>> >>> does it actually indicate something is wrong, or should I just compile
>> >>> with NDEBUG and ignore it?
>> >>>
>> >>>
>> >>>
>> >>> The code in question is
>> >>>
>> >>> void
>> >>> TransactionState::sendCurrentToWire()
>> >>> {
>> >>> if(!mMsgToRetransmit.empty())
>> >>> {
>> >>> if(mController.mStack.statisticsManagerEnabled())
>> >>> {
>> >>> mController.mStatsManager.retransmitted(mCurrentMethodType,
>> >>> isClient(),
>> >>>
>> mCurrentResponseCode);
>> >>> }
>> >>>
>> >>> mController.mTransportSelector.retransmit(mMsgToRetransmit);
>> >>> }
>> >>> else if(mNextTransmission) // initial transmission; need to
>> determine
>> >>> target
>> >>> {
>> >>> ... snip ...
>> >>> }
>> >>> else
>> >>> { // line 2578
>> >>> assert(0);
>> >>> }
>> >>>
>> >>>
>> >>>
>> >>> DEBUG | 20130127-160854.896 | repro | RESIP:TRANSPORT |
>> 140422323181312
>> >>> | ConnectionBase.cxx:418 | ##Connection: CONN_BASE: 0x7fb6a8234460 [
>> V4
>> >>> 192.168.1.100:49269 TLS target domain=unspecified mFlowKey=31 ]
>> >>> received: PUBLISH sip:1001 at srv1.office.readytechnology.co.uk SIP/2.0
>> >>> Via: SIP/2.0/TLS
>> >>> 192.168.1.100:49269
>> >>> ;branch=z9hG4bK-373139-05d032d540e9bca18e3af732e0c948df
>> >>> Max-Forwards: 70
>> >>> Contact: "1001"
>> >>> <sip:1001 at 192.168.1.100:49269
>> >>> ;transport=tls;registering_acc=srv1_office_readytechnology_co_uk>
>> >>> To: "1001" <sip:1001 at srv1.office.readytechnology.co.uk>
>> >>> From: "1001" <sip:1001 at srv1.office.readytechnology.co.uk
>> >;tag=c72de72a
>> >>> Call-ID: 9e82664c30f04d33d1ce879ab846a60b at 0:0:0:0:0:0:0:0
>> >>> CSeq: 2 PUBLISH
>> >>> Expires: 3600
>> >>> Content-Type: application/pidf+xml
>> >>> Proxy-Authorization: Digest
>> >>> username="1001",realm="srv1.office.readytechnology.co.uk
>> >>> ",nonce="1359299327:1ba2dffdf6697b06053efcfe4736f581",uri="
>> >>> sip:1001 at srv1.office.readytechnology.co.uk
>> >>>
>> ",response="71efd5b4af3d25d2405c0e84d9c8e4eb",algorithm=MD5,qop=auth,cnonce="xyz",nc=00000001
>> >>> User-Agent: Jitsi1.1.4400.10268Windows 7
>> >>> Event: presence
>> >>> Content-Length: 452
>> >>>
>> >>> <?xml version="1.0" encoding="UTF-8" standalone="no"?><presence
>> >>> xmlns="urn:ietf:params:xml:ns:pidf"
>> >>> xmlns:dm="urn:ietf:params:xml:ns:pidf:data-model"
>> >>> xmlns:rpid="urn:ietf:params:xml:ns:pidf:rpid"
>> >>> entity="sip:1001 at srv1.office.readytechnology.co.uk"><dm:person
>> >>> id="p556"><rpid:activities/></dm:person><tuple
>> >>> id="t6311"><status><basic>open</basic></status><contact>
>> >>> sip:1001 at srv1.office.readytechnology.co.uk
>> >>> </contact><note>Online</note></tuple></presence>
>> >>> DEBUG | 20130127-160854.896 | repro | RESIP:TRANSPORT |
>> 140422323181312
>> >>> | Connection.cxx:298 | Connection::performReads() read=1352
>> >>> DEBUG | 20130127-160854.896 | repro | RESIP:TRANSPORT |
>> 140422323181312
>> >>> | ConnectionBase.cxx:661 | Creating buffer for CONN_BASE:
>> 0x7fb6a8234460
>> >>> [ V4 192.168.1.100:49269 TLS target domain=unspecified mFlowKey=31 ]
>> >>> STACK | 20130127-160854.896 | repro | RESIP:TRANSPORT |
>> 140422323181312
>> >>> | ssl/TlsConnection.cxx:317 | SSL_read returned -1 bytes []
>> >>> STACK | 20130127-160854.896 | repro | RESIP:TRANSPORT |
>> 140422323181312
>> >>> | ssl/TlsConnection.cxx:354 | Got TLS read got condition of 2
>> >>> STACK | 20130127-160854.896 | repro | RESIP:TRANSACTION |
>> >>> 140422331574016 | TransactionState.cxx:706 | Found matching
>> transaction
>> >>> for SipReq: PUBLISH 1001 at srv1.office.readytechnology.co.uk
>> >>> tid=-373139-05d032d540e9bca18e3af732e0c948df cseq=2 PUBLISH
>> >>> contact=1001 at 192.168.1.100:49269 / 2 from(wire)
>> >>> tlsd=srv1.office.readytechnology.co.uk ->
>> >>> tid=-373139-05d032d540e9bca18e3af732e0c948df [
>> >>> ServerNonInvite/Proceeding reliable target=[ V4 192.168.1.100:49269TLS
>> >>> target domain=unspecified mFlowKey=31 ]]
>> >>> STACK | 20130127-160854.896 | repro | RESIP:TRANSACTION |
>> >>> 140422331574016 | TransactionState.cxx:1438 |
>> >>> TransactionState::processServerNonInvite: SipReq: PUBLISH
>> >>> 1001 at srv1.office.readytechnology.co.uk
>> >>> tid=-373139-05d032d540e9bca18e3af732e0c948df cseq=2 PUBLISH
>> >>> contact=1001 at 192.168.1.100:49269 / 2 from(wire)
>> >>> tlsd=srv1.office.readytechnology.co.uk
>> >>> repro: TransactionState.cxx:2578: void
>> >>> resip::TransactionState::sendCurrentToWire(): Assertion `0' failed.
>> >>> _______________________________________________
>> >>> resiprocate-devel mailing list
>> >>> resiprocate-devel at resiprocate.org
>> >>> https://list.resiprocate.org/mailman/listinfo/resiprocate-devel
>> >>>
>> >>
>> >>
>> >> _______________________________________________
>> >> resiprocate-devel mailing list
>> >> resiprocate-devel at resiprocate.org
>> >> https://list.resiprocate.org/mailman/listinfo/resiprocate-devel
>> >>
>> >
>>
>
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://list.resiprocate.org/pipermail/resiprocate-devel/attachments/20130129/bda6cf15/attachment.htm>
More information about the resiprocate-devel
mailing list