[Live-devel] When streaming RTP over TCP, Live555 Proxy Server sometimes does not reconnect to 'back end' device

Erik Montnemery erik at montnemery.com
Sun Jan 1 06:10:57 PST 2017 

Hi,

I've digged a bit further into this.
The problem is related to the backgroundhandler being overwritten
before a TCP connection to the 'back end' is established, i.e. before
RTSPClient::connectionHandler has been called.

The problem frequently occurs in the following scenarios:
1) ProxyRTSPClient::continueAfterLivenessCommand called from within
the stack frame of SocketDescriptor::tcpReadHandler.
During reset of the ProxyRTSPClient, socketDescriptor->fDeleteMyselfNext is set.
Then, the socketDescriptor is deleted from
SocketDescriptor::tcpReadHandler, this will have the side effect of
also doing fEnv.taskScheduler().turnOffBackgroundReadHandling on the
new socket.
(I guess this is actually done on the "wrong" socket and related to
the socket number being reused?)
Hence, RTSPClient::connectionHandler will never be called.
I tried to solve this by deferring the reset of the ProxyRTSPClient as
a scheduled task, and it seems to work well.
(The log in the previous message shows the sequence)

2)
A client to the proxy server issues PLAY while the connection to the
'back end' is being reestablished.
This will cause RTPInterface::startNetworkReading to change the
background handler from RTSPClient::connectionHandler to
SocketDescriptor::tcpReadHandler, again preventing
RTSPClient::connectionHandler from being called.
How to solve this?
Should the ProxyRTSPClient for example be reset as soon as the TCP
connection is lost (when streaming over TCP), thus preventing a client
from issuing a PLAY while connection to 'back-end' is being
reestablished?

(Log is available if it's of any use)

/Erik

2016-12-26 17:03 GMT+01:00 Erik Montnemery <erik at montnemery.com>:
> Hi,
>
> Most of the time, the proxy server reconnects to the 'back-end' server
> after an error or loss of connection, but every now and then the
> following happens:
>
> Error or connection loss is detected, and the reset sequence is performed.
> However, after the new connection to the 'back end' server is
> initiated but before it is established, the socket's background
> handler is reset and the reestablish of the connection to the 'back
> end' server is thus hung forever:
>
> Dec 26 16:20:15 Thor live555ProxyServer[27609]: deregisterSocket sockNum: 5
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> SocketDescriptor(socket 5)::deregisterRTPInterface(channel 0)
> Dec 26 16:20:15 Thor live555ProxyServer[27609]: deregisterSocket sockNum: 5
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> SocketDescriptor(socket 5)::deregisterRTPInterface(channel 255)
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> SocketDescriptor::deregisterRTPInterface setting fDeleteMyselfNext
> ^-- fDeleteMyselfNext is set
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> RTPInterface::stopNetworkReading
> turnOffBackgroundReadHandling(4294967295)
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> BasicTaskScheduler::setBackgroundHandling(4294967295, 0, 0x0, 0x0)
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> RTPInterface::stopNetworkReading
> turnOffBackgroundReadHandling(4294967295)
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> BasicTaskScheduler::setBackgroundHandling(4294967295, 0, 0x0, 0x0)
> Dec 26 16:20:15 Thor live555ProxyServer[27609]: deregisterSocket sockNum: 5
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> SocketDescriptor(socket 5)::deregisterRTPInterface(channel 2)
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> ProxyRTSPClient[(NULL)]: Calling setBaseURL(fOurURL)
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> ProxyRTSPClient[rtsp://root:xxxxxx@192.168.0.35/axis-media/media.amp]:
> Calling sendDESCRIBE(this)
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> ProxyRTSPClient::sendDESCRIBE rtspClient == NULL: FALSE
> Dec 26 16:20:15 Thor live555ProxyServer[27609]: RTSPClient::sendRequest
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> RTSPClient::sendRequest - we need to open a connection
> Dec 26 16:20:15 Thor live555ProxyServer[27609]: RTSPClient::openConnection
> Dec 26 16:20:15 Thor live555ProxyServer[27609]: Opening connection to
> 192.168.0.35, port 554...
> Dec 26 16:20:15 Thor live555ProxyServer[27609]: Setting up
> BackgroundHandling for socket 5
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> RTSPClient::connectToServer setBackgroundHandling(5,
> SOCKET_WRITABLE|SOCKET_EXCEPTION, connectionHandler, this)
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> BasicTaskScheduler::setBackgroundHandling(5, c, 0x40a250, 0x10b6430)
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> RTSPClient::sendRequest - connectResult:0
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> RTSPClient::sendRequest - connectionIsPending:1
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> ProxyRTSPClient[rtsp://root:xxxxxx@192.168.0.35/axis-media/media.amp]:
> Reset done
> ^-- Reset sequence in ProxyRTSPClient::continueAfterLivenessCommand finished
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> SocketDescriptor::tcpReadHandler fDeleteMyselfNext set
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> SocketDescriptor::~SocketDescriptor turnOffBackgroundReadHandling(5)
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> BasicTaskScheduler::setBackgroundHandling(5, 0, 0x0, 0x0)
> ^-- Background handler reset again before the connection is reestablished
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> RTSPClient::handleAlternativeRequestByte1 setBackgroundHandling(5,
> SOCKET_READABLE|SOCKET_EXCEPTION, incomingDataHandler, this)
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> BasicTaskScheduler::setBackgroundHandling(5, a, 0x40d4f0, 0x10b6430)
>
> I guess the problem is related to the reset sequence being run from
> within SocketDescriptor::tcpReadHandler?
>
> More context:
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> ProxyRTSPClient[rtsp://192.168.0.35/axis-media/media.amp/]: lost
> connection to server ('errno': -2).  Resetting...
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> ProxyRTSPClient[rtsp://192.168.0.35/axis-media/media.amp/]: Calling
> reset
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> ProxyRTSPClient[rtsp://192.168.0.35/axis-media/media.amp/]:
> ProxyRTSPClient::reset enter
> Dec 26 16:20:15 Thor live555ProxyServer[27609]: RTSPClient::reset
> Dec 26 16:20:15 Thor live555ProxyServer[27609]: RTSPClient::resetTCPSockets
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> RTSPClient::resetTCPSockets disableBackgroundHandling(5) 1
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> BasicTaskScheduler::setBackgroundHandling(5, 0, 0x0, 0x0)
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> ProxyRTSPClient[(NULL)]: ProxyRTSPClient::reset leave
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> ProxyRTSPClient[(NULL)]: Calling
> fOurServerMediaSession.resetDESCRIBEState()
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> RTSPServer::RTSPClientSession(0x17eea90)::~RTSPClientSession
> session(0x10b6210)->referenceCount(): 1
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> OnDemandServerMediaSubsession::deleteStream() 1
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> OnDemandServerMediaSubsession::deleteStream() 2
> Dec 26 16:20:15 Thor live555ProxyServer[27609]: deregisterSocket sockNum: 9
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> SocketDescriptor(socket 9)::deregisterRTPInterface(channel 0)
> Dec 26 16:20:15 Thor live555ProxyServer[27609]: deregisterSocket sockNum: 9
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> SocketDescriptor(socket 9)::deregisterRTPInterface(channel 1)
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> OnDemandServerMediaSubsession::deleteStream() 3
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> OnDemandServerMediaSubsession::deleteStream()
> streamState(0x17eea20)->referenceCount(): 1
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> OnDemandServerMediaSubsession::deleteStream() 4
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> StreamState(0x17eea20)::~StreamState()
> Dec 26 16:20:15 Thor live555ProxyServer[27609]: StreamState::reclaim()
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> RTPInterface::stopNetworkReading turnOffBackgroundReadHandling(28)
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> BasicTaskScheduler::setBackgroundHandling(28, 0, 0x0, 0x0)
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> RTPInterface::stopNetworkReading
> turnOffBackgroundReadHandling(4294967295)
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> BasicTaskScheduler::setBackgroundHandling(4294967295, 0, 0x0, 0x0)
> Dec 26 16:20:15 Thor live555ProxyServer[27609]: deregisterSocket sockNum: 5
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> SocketDescriptor(socket 5)::deregisterRTPInterface(channel 0)
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> RTPInterface::stopNetworkReading
> turnOffBackgroundReadHandling(4294967295)
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> BasicTaskScheduler::setBackgroundHandling(4294967295, 0, 0x0, 0x0)
> Dec 26 16:20:15 Thor live555ProxyServer[27609]: deregisterSocket sockNum: 5
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> SocketDescriptor(socket 5)::deregisterRTPInterface(channel 0)
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> ProxyServerMediaSubsession[(NULL),H264]::closeStreamSource()
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> ProxyServerMediaSubsession[(NULL),H264]::closeStreamSource()
> fParentSession(0x10b6210)->refcnt: 1
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> ProxyServerMediaSubsession[(NULL),H264]::closeStreamSource()
> subsession:  (0) port:52784, codecName: H264, hasRTPSource: YES
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> ProxyServerMediaSubsession[(NULL),H264]::closeStreamSource()
> subsession:  (1) port:43362, codecName: MPEG4-GENERIC, hasRTPSource:
> YES
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> OnDemandServerMediaSubsession::deleteStream() 5
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> OnDemandServerMediaSubsession::deleteStream() 6
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> OnDemandServerMediaSubsession::deleteStream() 1
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> OnDemandServerMediaSubsession::deleteStream() 2
> Dec 26 16:20:15 Thor live555ProxyServer[27609]: deregisterSocket sockNum: 9
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> SocketDescriptor(socket 9)::deregisterRTPInterface(channel 2)
> Dec 26 16:20:15 Thor live555ProxyServer[27609]: deregisterSocket sockNum: 9
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> SocketDescriptor(socket 9)::deregisterRTPInterface(channel 3)
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> SocketDescriptor::deregisterRTPInterface calling delete
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> SocketDescriptor::~SocketDescriptor turnOffBackgroundReadHandling(9)
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> BasicTaskScheduler::setBackgroundHandling(9, 0, 0x0, 0x0)
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> BasicTaskScheduler::setBackgroundHandling(9, a, 0x402d1a, 0x189b340)
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> OnDemandServerMediaSubsession::deleteStream() 3
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> OnDemandServerMediaSubsession::deleteStream()
> streamState(0x1894570)->referenceCount(): 1
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> OnDemandServerMediaSubsession::deleteStream() 4
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> StreamState(0x1894570)::~StreamState()
> Dec 26 16:20:15 Thor live555ProxyServer[27609]: StreamState::reclaim()
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> RTPInterface::stopNetworkReading turnOffBackgroundReadHandling(31)
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> BasicTaskScheduler::setBackgroundHandling(31, 0, 0x0, 0x0)
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> RTPInterface::stopNetworkReading
> turnOffBackgroundReadHandling(4294967295)
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> BasicTaskScheduler::setBackgroundHandling(4294967295, 0, 0x0, 0x0)
> Dec 26 16:20:15 Thor live555ProxyServer[27609]: deregisterSocket sockNum: 5
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> SocketDescriptor(socket 5)::deregisterRTPInterface(channel 2)
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> ProxyServerMediaSubsession[(NULL),MPEG4-GENERIC]::closeStreamSource()
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> ProxyServerMediaSubsession[(NULL),MPEG4-GENERIC]::closeStreamSource()
> fParentSession(0x10b6210)->refcnt: 1
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> ProxyServerMediaSubsession[(NULL),MPEG4-GENERIC]::closeStreamSource()
> subsession:  (0) port:52784, codecName: H264, hasRTPSource: YES
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> ProxyServerMediaSubsession[(NULL),MPEG4-GENERIC]::closeStreamSource()
> subsession:  (1) port:43362, codecName: MPEG4-GENERIC, hasRTPSource:
> YES
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> OnDemandServerMediaSubsession::deleteStream() 5
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> OnDemandServerMediaSubsession::deleteStream() 6
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> GenericMediaServer::ClientSession::~ClientSession
> fOurServerMediaSession(0x10b6210)->referenceCount(): 0
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> ProxyServerMediaSubsession[(NULL),H264]::~ProxyServerMediaSubsession()
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> ProxyServerMediaSubsession[(NULL),MPEG4-GENERIC]::~ProxyServerMediaSubsession()
> Dec 26 16:20:15 Thor live555ProxyServer[27609]: deregisterSocket sockNum: 5
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> SocketDescriptor(socket 5)::deregisterRTPInterface(channel 255)
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> SocketDescriptor::deregisterRTPInterface setting fDeleteMyselfNext
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> RTPInterface::stopNetworkReading
> turnOffBackgroundReadHandling(4294967295)
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> BasicTaskScheduler::setBackgroundHandling(4294967295, 0, 0x0, 0x0)
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> RTPInterface::stopNetworkReading
> turnOffBackgroundReadHandling(4294967295)
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> BasicTaskScheduler::setBackgroundHandling(4294967295, 0, 0x0, 0x0)
> Dec 26 16:20:15 Thor live555ProxyServer[27609]: deregisterSocket sockNum: 5
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> SocketDescriptor(socket 5)::deregisterRTPInterface(channel 0)
> Dec 26 16:20:15 Thor live555ProxyServer[27609]: deregisterSocket sockNum: 5
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> SocketDescriptor(socket 5)::deregisterRTPInterface(channel 255)
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> SocketDescriptor::deregisterRTPInterface setting fDeleteMyselfNext
> ^-- fDeleteMyselfNext is set
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> RTPInterface::stopNetworkReading
> turnOffBackgroundReadHandling(4294967295)
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> BasicTaskScheduler::setBackgroundHandling(4294967295, 0, 0x0, 0x0)
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> RTPInterface::stopNetworkReading
> turnOffBackgroundReadHandling(4294967295)
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> BasicTaskScheduler::setBackgroundHandling(4294967295, 0, 0x0, 0x0)
> Dec 26 16:20:15 Thor live555ProxyServer[27609]: deregisterSocket sockNum: 5
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> SocketDescriptor(socket 5)::deregisterRTPInterface(channel 2)
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> ProxyRTSPClient[(NULL)]: Calling setBaseURL(fOurURL)
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> ProxyRTSPClient[rtsp://root:xxxxxx@192.168.0.35/axis-media/media.amp]:
> Calling sendDESCRIBE(this)
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> ProxyRTSPClient::sendDESCRIBE rtspClient == NULL: FALSE
> Dec 26 16:20:15 Thor live555ProxyServer[27609]: RTSPClient::sendRequest
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> RTSPClient::sendRequest - we need to open a connection
> Dec 26 16:20:15 Thor live555ProxyServer[27609]: RTSPClient::openConnection
> Dec 26 16:20:15 Thor live555ProxyServer[27609]: Opening connection to
> 192.168.0.35, port 554...
> Dec 26 16:20:15 Thor live555ProxyServer[27609]: Setting up
> BackgroundHandling for socket 5
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> RTSPClient::connectToServer setBackgroundHandling(5,
> SOCKET_WRITABLE|SOCKET_EXCEPTION, connetionHandler, this)
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> BasicTaskScheduler::setBackgroundHandling(5, c, 0x40a250, 0x10b6430)
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> RTSPClient::sendRequest - connectResult:0
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> RTSPClient::sendRequest - connectionIsPending:1
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> ProxyRTSPClient[rtsp://root:xxxxxx@192.168.0.35/axis-media/media.amp]:
> Reset done
> ^-- Reset sequence in ProxyRTSPClient::continueAfterLivenessCommand finished
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> SocketDescriptor::tcpReadHandler fDeleteMyselfNext set
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> SocketDescriptor::~SocketDescriptor turnOffBackgroundReadHandling(5)
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> BasicTaskScheduler::setBackgroundHandling(5, 0, 0x0, 0x0)
> ^-- Background handler reset again before the connection is reestablished
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> RTSPClient::handleAlternativeRequestByte1 setBackgroundHandling(5,
> SOCKET_READABLE|SOCKET_EXCEPTION, incomingDataHandler, this)
> Dec 26 16:20:15 Thor live555ProxyServer[27609]:
> BasicTaskScheduler::setBackgroundHandling(5, a, 0x40d4f0, 0x10b6430)
> Dec 26 16:20:20 Thor live555ProxyServer[27609]:
> RTSPServer::RTSPClientConnection(0x189b340)::~RTSPClientConnection
> Dec 26 16:20:20 Thor live555ProxyServer[27609]:
> RTSPServer::RTSPClientConnection(0x189b340)::closeSocketsRTSP
> Dec 26 16:20:20 Thor live555ProxyServer[27609]:
> GenericMediaServer::ClientConnection::closeSockets
> disableBackgroundHandling(9)
>
> /Erik

More information about the live-devel mailing list