[Live-devel] Logging or debug info

[Jan Ekholm]

On 6 maj 2014, at 23:35, Jan Ekholm <jan.ekholm at d-pointer.com> wrote:

> 
> On 6 maj 2014, at 23:07, Ross Finlayson <finlayson at live555.com> wrote:
> 
>> Once again:
>> 
>>>> In fact, I suggest that you first run the (unmodified!) "testOnDemandRTSPServer" application, using "testRTSPClient" or "openRTSP" as a client.  Verify that this combination works OK.
> 
> It does, once I got rid of isSSM. Now testRTSPClient runs forever, at least for a definition of forever that
> goes up to 30 minutes. So that at least is not an issue anymore and was my mistake.

Ok, after some Wiresharking and lots of testing I have a case that seems to explain why my client
freezes. I may have misunderstood something, but as far as I can see this behavior is not correct.

I have:

* a server based on the Live555 libraries that serve local camera data to clients.
* a libav based client that can connect to one stream and decode it.

To reproduce the problem I do:

1. start server, make sure there are no clients connected to it.

2. start one client that uses TCP as the transport. The client successfully connects
and negotiates the RTSP setup for the stream. The client starts getting RTP data
over TCP and decodes the video fine. The server outputs when the stream starts:

parseRTSPRequestString() succeeded, returning cmdName "PLAY", urlPreSuffix "camera0", urlSuffix "", CSeq "4", Content-Length 0, with 0 bytes following the message.
sending response: RTSP/1.0 200 OK
CSeq: 4
Date: Wed, May 07 2014 14:02:46 GMT
Range: npt=0.000-
Session: 61AA5DE4
RTP-Info: url=rtsp://192.168.1.12:8554/camera0/track1;seq=1220;rtptime=2615924584

I see from my own logs that the camera has been opened and Live555 requests frames
which are delivered.


3. kill the client. This gives the output:

RTSPClientConnection[0x10c008000]::handleRequestBytes() read -1 new bytes (of 10000); terminating connection!

 I assume this means that the server noticed that the client was killed and closes the connection. So far
so good.

4. start the same client again, this gives:

accept()ed connection from 192.168.1.124
RTSPClientConnection[0x10c008000]::handleRequestBytes() read 87 new bytes:OPTIONS rtsp://192.168.1.12:8554/camera0 RTSP/1.0
CSeq: 1
User-Agent: Lavf55.16.0
...

There is more related to DESCRIBE etc and then comes:

parseRTSPRequestString() succeeded, returning cmdName "PLAY", urlPreSuffix "camera0", urlSuffix "", CSeq "4", Content-Length 0, with 0 bytes following the message.
sending response: RTSP/1.0 200 OK
CSeq: 4
Date: Wed, May 07 2014 14:03:02 GMT
Range: npt=0.000-
Session: 5CEA1D88
RTP-Info: url=rtsp://192.168.1.12:8554/camera0/track1;seq=4242;rtptime=2617382418

This client now also receives the stream and decodes it fine.


5. the client sends a GET_PARAMETER as a keep alive.

parseRTSPRequestString() succeeded, returning cmdName "GET_PARAMETER", urlPreSuffix "camera0", urlSuffix "", CSeq "5", Content-Length 0, with 0 bytes following the message.
sending response: RTSP/1.0 200 OK
CSeq: 5
Date: Wed, May 07 2014 14:03:34 GMT
Session: 5CEA1D88
Content-Length: 10


6. some time passes, 65 seconds from that the first client was killed, then this is shown
by the server:

2014.03.25RTSP client session (id "61AA5DE4", stream name "camera0") has timed out (due to inactivity)

Note that the session id is the same as the one for the first client. So it times out 65 seconds after
Live555 noticed that the client disconnected.  At this point there is no more data delivered to the
second client. This is verified using Wireshark. As soon as the time out is printed, all network data
to the second client stops and the client blocks as it expects more data.

7. check the camera logging. I see that Live555 still requests frames from it and they get delivered
normally.

8. some time passes, enough for the second client to time out. Now I see:

RTSP client session (id "5CEA1D88", stream name "camera0") has timed out (due to inactivity)

The second client never sends and more keepalives as it's expecting data from Live555. It should
perhaps not block for so long and should perhaps abort the reading and send the keep alive, but that
is another matter. When this second session times out then the camera source is released and
no more frames are requested.


Based on what I see it seems as if Live555 does not properly clean up the first session when the
connection breaks. Instead it seems to close the wrong connection when the time out occurs.
Perhaps there is a 65 s timer that does not get cleaned up or there is some array index that
refers to the wrong session? Whatever the cause, the stream to a still valid client gets killed.
As the camera source is not closed it's also an indication that Live555 thinks that there is at
least one valid stream left.

Note that if UDP is used there doesn't seem to be any problems like these. I can start and kill
clients at will and all streams are delivered as they should. If more details are needed please
let me know.

Best regards,
    Jan Ekholm


-- 
Jan Ekholm
jan.ekholm at d-pointer.com