[Live-devel] Live555 Proxy Server sometimes does not proxy source after connection loss

Sun Sep 25 12:14:34 PDT 2016

>>
>> To reproduce the issue:
>> - Restart 'back end' server
>> - RTSP proxy will reconnect, and reuse the previous SESSION identifier
>> for PLAY / PAUSE, assuming the session is still valid
>> - 'Back end' server incorrectly accepts this, although the SESSION has
>> not been setup
>
> I don’t understand what you’re saying here.  When the proxy server reconnects, it will do so by sending a whole new sequence of “DESCRIBE”, “SETUP”, and “PLAY” commands - i.e., to create a whole new RTSP session.  It is the *back-end server* that selects the RTSP session identifier (in its response to the first “SETUP” command).  If the back-end server happens to select the same session id that it used before, then that shouldn’t affect the proxy server, because by this time the proxy server will have forgotten all about the previous session (that happened to have used the same session id).
>
> Please provide a complete listing of the RTSP protocol exchange (i.e., from running the proxy server with the -V option) that illustrates this alleged problem.
>
The proxy server only creates a whole new RTSP session under certain
conditions, for example while waiting for an "OPTIONS" liveness reply.
If the RTSP TCP session is interrupted when there is no pending
request, the proxy server instead silently reconnects before sending
the next request and reuses the existing session.

This may cause problems, for example in this scenario:
- Proxy server has an RTSP session open towards the
'back-end' server, session identifier 'A'
- A 2nd client has an RTSP session open towards the 'back-end' server,
session identifier 'B'
- Back-end RTSP server restarts
- Proxy server and the 2nd clients both reconnect to the 'back-end' server
- The 2nd client connects first and opens a new session, which happens
to be assigned session identifier 'A'
- The proxy server reconnects, and keeps using the session identifier 'A'

A log of this scenario is further down in the mail.
Note: In my case, there is most likely no 2nd client, and the
'back-end' server is behaving incorrectly.

>> To detect this issue and recover, I implemented the following:
>> Add an additional liveness check to ProxyRTSPClient
>> ...
>> Is this a reasonable solution?
>
> No - because the 'back end’ server might have decided to stop sending RTP packets for a perfectly legitimate reason (e.g., in response to a “PAUSE” command,
The condition I use for the additional liveness check is that:
a) lastPacketReceptionTime is older than a certain threshold
- and -
b) fOurServerMediaSession.referenceCount() > 0, which it to my
understanding is if at least one client is requesting to stream (i.e.
is in state PLAYING)
> or because it just happened to decide to not stream video for a while).
The RTSP proxy does not really use the range parameter, so I didn't
think that was a concern.

Sep 18 15:13:46 RTSPClient::sendRequest
Sep 18 15:13:46 RTSPClient::sendRequest - connectionIsPending:0
Sep 18 15:13:46 Sending request: OPTIONS
rtsp://192.168.0.126/ch0_0.h264/ RTSP/1.0
Sep 18 15:13:46 CSeq: 12883
Sep 18 15:13:46 User-Agent: ProxyRTSPClient (LIVE555 Streaming Media
v2016.09.08)
Sep 18 15:13:46 Session: 6B8B4567
Sep 18 15:13:46
Sep 18 15:13:46
Sep 18 15:13:46 Received 156 new bytes of response data.
Sep 18 15:13:46 Received a complete OPTIONS response:
Sep 18 15:13:46 RTSP/1.0 200 OK
Sep 18 15:13:46 CSeq: 12883
Sep 18 15:13:46 Date: Sun, Sep 18 2016 13:16:43 GMT
Sep 18 15:13:46 Public: OPTIONS, DESCRIBE, SETUP, TEARDOWN, PLAY,
PAUSE, GET_PARAMETER, SET_PARAMETER
Sep 18 15:13:46
Sep 18 15:13:46
<-- 'back end' device has restarted its RTSP server, and RTSP TCP
connection has been lost
Sep 18 15:14:16 RTSPClient::sendRequest
Sep 18 15:14:16 RTSPClient::sendRequest - we need to open a connection
Sep 18 15:14:16 Opening connection to 192.168.0.126, port 554...
Sep 18 15:14:16 Setting up BackgroundHandling for socket 9
Sep 18 15:14:16 RTSPClient::sendRequest - connectResult:0
Sep 18 15:14:16 RTSPClient::sendRequest - connectionIsPending:1
Sep 18 15:14:26 OnDemandServerMediaSubsession::sdpLines()
Sep 18 15:14:26 OnDemandServerMediaSubsession::sdpLines()
Sep 18 15:14:26 OnDemandServerMediaSubsession::sdpLines()
Sep 18 15:14:26 OnDemandServerMediaSubsession::sdpLines()
Sep 18 15:14:47 ...remote connection opened
Sep 18 15:14:47 RTSPClient::sendRequest
Sep 18 15:14:47 RTSPClient::sendRequest - connectionIsPending:0
Sep 18 15:14:47 Sending request: OPTIONS
rtsp://192.168.0.126/ch0_0.h264/ RTSP/1.0
Sep 18 15:14:47 CSeq: 12884
Sep 18 15:14:47 User-Agent: ProxyRTSPClient (LIVE555 Streaming Media
v2016.09.08)
Sep 18 15:14:47 Session: 6B8B4567
Sep 18 15:14:47
Sep 18 15:14:47
Sep 18 15:14:47 Received 156 new bytes of response data.
Sep 18 15:14:47 Received a complete OPTIONS response:
Sep 18 15:14:47 RTSP/1.0 200 OK
Sep 18 15:14:47 CSeq: 12884
Sep 18 15:14:47 Date: Thu, Jan 01 1970 00:00:40 GMT
Sep 18 15:14:47 Public: OPTIONS, DESCRIBE, SETUP, TEARDOWN, PLAY,
PAUSE, GET_PARAMETER, SET_PARAMETER
Sep 18 15:14:47
Sep 18 15:14:47
<-- Proxy client gives up because it has not received any data for a
while, RTSP Proxy sends PAUSE
Sep 18 15:14:48 StreamState::reclaim()
Sep 18 15:14:48
ProxyServerMediaSubsession[rtsp://192.168.0.126/ch0_0.h264/,H264]::closeStreamSource()
Sep 18 15:14:48 RTSPClient::sendRequest
Sep 18 15:14:48 RTSPClient::sendRequest - connectionIsPending:0
Sep 18 15:14:48 Sending request: PAUSE rtsp://192.168.0.126/ch0_0.h264/ RTSP/1.0
Sep 18 15:14:48 CSeq: 12885
Sep 18 15:14:48 User-Agent: ProxyRTSPClient (LIVE555 Streaming Media
v2016.09.08)
Sep 18 15:14:48 Session: 6B8B4567
Sep 18 15:14:48
Sep 18 15:14:48
Sep 18 15:14:48 StreamState::reclaim()
Sep 18 15:14:48
ProxyServerMediaSubsession[rtsp://192.168.0.126/ch0_0.h264/,MPEG4-GENERIC]::closeStreamSource()
Sep 18 15:14:48 Received 88 new bytes of response data.
Sep 18 15:14:48 Received a complete PAUSE response:
Sep 18 15:14:48 RTSP/1.0 200 OK
Sep 18 15:14:48 CSeq: 12885
Sep 18 15:14:48 Date: Thu, Jan 01 1970 00:00:41 GMT
Sep 18 15:14:48 Session: 6B8B4567
Sep 18 15:14:48
Sep 18 15:14:48
<-- Proxy client reconnects and starts playing, RTSP Proxy sends PLAY.
No data is received by RTSP Proxy.
Sep 18 15:14:56 OnDemandServerMediaSubsession::sdpLines()
Sep 18 15:14:56 OnDemandServerMediaSubsession::sdpLines()
Sep 18 15:14:56 OnDemandServerMediaSubsession::sdpLines()
Sep 18 15:14:56 OnDemandServerMediaSubsession::sdpLines()
Sep 18 15:14:56
ProxyServerMediaSubsession[rtsp://192.168.0.126/ch0_0.h264/,H264]::createNewStreamSource(session
id 1042224728)
Sep 18 15:14:56 RTSPClient::sendRequest
Sep 18 15:14:56 RTSPClient::sendRequest - connectionIsPending:0
Sep 18 15:14:56 Sending request: PLAY rtsp://192.168.0.126/ch0_0.h264/ RTSP/1.0
Sep 18 15:14:56 CSeq: 12886
Sep 18 15:14:56 User-Agent: ProxyRTSPClient (LIVE555 Streaming Media
v2016.09.08)
Sep 18 15:14:56 Session: 6B8B4567
Sep 18 15:14:56
Sep 18 15:14:56
Sep 18 15:14:56
ProxyServerMediaSubsession[rtsp://192.168.0.126/ch0_0.h264/,H264]::createNewRTPSink()
Sep 18 15:14:56
ProxyServerMediaSubsession[rtsp://192.168.0.126/ch0_0.h264/,MPEG4-GENERIC]::createNewStreamSource(session
id 1042224728)
Sep 18 15:14:56
ProxyServerMediaSubsession[rtsp://192.168.0.126/ch0_0.h264/,MPEG4-GENERIC]::createNewRTPSink()
Sep 18 15:14:56 Received 68 new bytes of response data.
Sep 18 15:14:56 Received a complete PLAY response:
Sep 18 15:14:56 RTSP/1.0 200 OK
Sep 18 15:14:56 CSeq: 12886
Sep 18 15:14:56 Session: 6B8B4567
Sep 18 15:14:56 Range: npt=now-