[reSIProcate] repro crash with Jitsi
Daniel Pocock
daniel at pocock.com.au
Tue Jan 29 11:39:22 CST 2013
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
> <mailto: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
> <mailto:sip%3A1001 at srv1.office.readytechnology.co.uk>>
> From: "1001" <sip:1001 at srv1.office.readytechnology.co.uk
> <mailto:sip%3A1001 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 <http://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
> <mailto:sip%3A1001 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
> <mailto:sip%3A1001 at srv1.office.readytechnology.co.uk>>;tag=c72de72a
> To: "1001" <sip:1001 at srv1.office.readytechnology.co.uk
> <mailto:sip%3A1001 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
> <http://srv1.office.readytechnology.co.uk>",nonce="1359299327:1ba2dffdf6697b06053efcfe4736f581",uri="sip:1001 at srv1.office.readytechnology.co.uk
> <mailto:sip%3A1001 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 <mailto: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 <mailto: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 <http://192.168.1.100:49269> TLS target
> domain=unspecified mFlowKey=31 ]
> >>> received: PUBLISH sip:1001 at srv1.office.readytechnology.co.uk
> <mailto:sip%3A1001 at srv1.office.readytechnology.co.uk> SIP/2.0
> >>> Via: SIP/2.0/TLS
> >>> 192.168.1.100:49269 <http://192.168.1.100:49269>
> >>> ;branch=z9hG4bK-373139-05d032d540e9bca18e3af732e0c948df
> >>> Max-Forwards: 70
> >>> Contact: "1001"
> >>> <sip:1001 at 192.168.1.100:49269
> <http://sip:1001@192.168.1.100:49269>
> >>> ;transport=tls;registering_acc=srv1_office_readytechnology_co_uk>
> >>> To: "1001" <sip:1001 at srv1.office.readytechnology.co.uk
> <mailto:sip%3A1001 at srv1.office.readytechnology.co.uk>>
> >>> From: "1001" <sip:1001 at srv1.office.readytechnology.co.uk
> <mailto:sip%3A1001 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
> <http://srv1.office.readytechnology.co.uk>
> >>> ",nonce="1359299327:1ba2dffdf6697b06053efcfe4736f581",uri="
> >>> sip:1001 at srv1.office.readytechnology.co.uk
> <mailto:sip%3A1001 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
> <mailto:sip%3A1001 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
> <mailto:sip%3A1001 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 <http://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
> <mailto:1001 at srv1.office.readytechnology.co.uk>
> >>> tid=-373139-05d032d540e9bca18e3af732e0c948df cseq=2 PUBLISH
> >>> contact=1001 at 192.168.1.100:49269
> <http://1001@192.168.1.100:49269> / 2 from(wire)
> >>> tlsd=srv1.office.readytechnology.co.uk
> <http://srv1.office.readytechnology.co.uk> ->
> >>> tid=-373139-05d032d540e9bca18e3af732e0c948df [
> >>> ServerNonInvite/Proceeding reliable target=[ V4
> 192.168.1.100:49269 <http://192.168.1.100:49269> TLS
> >>> 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
> <mailto:1001 at srv1.office.readytechnology.co.uk>
> >>> tid=-373139-05d032d540e9bca18e3af732e0c948df cseq=2 PUBLISH
> >>> contact=1001 at 192.168.1.100:49269
> <http://1001@192.168.1.100:49269> / 2 from(wire)
> >>> tlsd=srv1.office.readytechnology.co.uk
> <http://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
> <mailto:resiprocate-devel at resiprocate.org>
> >>> https://list.resiprocate.org/mailman/listinfo/resiprocate-devel
> >>>
> >>
> >>
> >> _______________________________________________
> >> resiprocate-devel mailing list
> >> resiprocate-devel at resiprocate.org
> <mailto: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/2a7ff0ba/attachment.htm>
More information about the resiprocate-devel
mailing list