SIP calls from Flash browsers killed by KeepAlive

snoozamoorooed

New Member
Hi.
I'm having troubles with SIP calls from flash browser.
Sessions get killed after 10 seconds, in case of using http origin websocket channel forced to close by command from server side (https client just hangs)
According to server logs session is closed because keep alive thread thinks thant client is unreachable.
If i make pcap dumps ping / pong messages are there.
It seems like server improperly handles ping replies from some of the channels (websocket, rtmp, rtmfp).
The problem appeared after 2108 build (2107 is ok) and 2130 is still buggy.
The only way to avoid this behavior is to turn off keep alive by setting keep_alive.algorithm =NONE
Both INTERNAL and HIGH_LEVEL are buggy.
How to reproduce:
Install flashphoner with default settings and run.
Start flash browser, run phone-video example and make sip call, wait 10 seconds and voila: video has gone.
Here is one moment: server and client behaviors are a bit different if i use http for loading web page (with ws / rtmfp channels) or https (with wss / rtmfp).
With ws / rtmfp example phone app receives command for disconnection by websocket channel and just makes disconnect as it should.
With wss / rtmfp media flow disappears and webpage just hangs. A few seconds later flash plugin displays error message about playing closed netstream
At this point server log might contain something like that.

case 1, wss / rtmfp. Seems that rtmfp session is closed and SIP connection is still alive.

09:46:41,902 INFO Session - KeepAliveManager-18 Timeout keepalive attempts: 10; keepAlive algorithm - HIGH_LEVEL
09:46:41,902 INFO Session - KeepAliveManager-18 kill id: 1
09:46:41,903 WARN FlowWriter - KeepAliveManager-18 FlowWriter closed for FlowConnection flow. The session must be closed here. this: FlowWriter{id
=2, flowId=2, closed=true, stage=4, critical=true, nameConnection='NetConnection', session=1}
09:46:41,903 INFO Streams - KeepAliveManager-18 unsubscribe name: IN_1002_84bd0a20-0929-11e7-aa9a-ad8bf3814858
09:46:41,904 WARN Peer - KeepAliveManager-18 Unsubscription client before connection
09:46:41,905 WARN Peer - KeepAliveManager-18 Unpublication client before connection
09:46:41,913 INFO Session - RTMFPManager-17 fail error: CriticalFlowWriterClosedEvent this: Session{id=1}
09:46:41,916 WARN Peer - pool-4-thread-12 AudioPacket client before connection
09:46:41,929 WARN Peer - pool-4-thread-5 VideoPacket client before connection
09:46:41,930 INFO Streams - KeepAliveManager-18 destroyPublication name OUT_1002_84bd0a20-0929-11e7-aa9a-ad8bf3814858
09:46:41,934 INFO Session - pool-4-thread-9 No such flow by id: 5
context: this: Session{id=1} +requestSpecial: RequestSpecial{flowId=5, flowWriterId=0, sequenceNumber=2664, deltaNAck=1, flags=0, flowWriter=null, fragment=0
80000d01472d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5
d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5d5...} nextRequestIsSpecial: false served Flow: null
09:46:41,935 INFO Session - KeepAliveManager-18 Session 1 died
09:46:41,939 INFO Sessions - KeepAliveManager-18 Session has died an will be removed key: 1
09:46:41,939 INFO Sessions - KeepAliveManager-18 sessions count 0
09:46:41,939 INFO Sessions - KeepAliveManager-18 sessions: {}
09:47:08,843 INFO SipUserAgentListener - EventScannerThread-46 processTransactionTerminated: javax.sip.TransactionTerminatedEvent[source=gov.nist.javax.sip.
SipProviderImpl@5bb92d3d]
09:47:36,833 DEBUG sipMessages - UDPMessageChannelThread-30000-49

<-------------------- OPTIONS sip:1002@XXX.XXX.XXX.XXX:30000 SIP/2.0
from: /YYY.YYY.YYY.YYY:5060
to: /XXX.XXX.XXX.XXX:30000
time: 1489546056832
timeStamp:
isSender: false
transactionId: z9hg4bk7a0dd7c3
callId: 7c299de60548f86f78dea64467ec26bd@YYY.YYY.YYY.YYY:5060
OPTIONS sip:1002@XXX.XXX.XXX.XXX:30000 SIP/2.0
Via: SIP/2.0/UDP YYY.YYY.YYY.YYY:5060;branch=z9hG4bK7a0dd7c3
Max-Forwards: 70
From: "asterisk" <sip:asterisk@YYY.YYY.YYY.YYY>;tag=as16fc509a
To: <sip:1002@XXX.XXX.XXX.XXX:30000>
Contact: <sip:asterisk@YYY.YYY.YYY.YYY:5060>
Call-ID: 7c299de60548f86f78dea64467ec26bd@YYY.YYY.YYY.YYY:5060
CSeq: 102 OPTIONS
User-Agent: Asterisk PBX 13.13.1~dfsg-4
Date: Wed, 15 Mar 2017 02:47:48 GMT
Allow: INVITE,ACK,CANCEL,OPTIONS,BYE,REFER,SUBSCRIBE,NOTIFY,INFO,PUBLISH,MESSAGE
Supported: replaces,timer
Content-Length: 0

09:47:36,840 DEBUG sipMessages - pool-19-thread-8

--------------------> SIP/2.0 200 OK
from: /XXX.XXX.XXX.XXX:30000
to: /YYY.YYY.YYY.YYY:5060
time: 1489546056836
timeStamp:
isSender: true
transactionId: z9hg4bk7a0dd7c3
callId: 7c299de60548f86f78dea64467ec26bd@YYY.YYY.YYY.YYY:5060

SIP/2.0 200 OK
Via: SIP/2.0/UDP YYY.YYY.YYY.YYY:5060;branch=z9hG4bK7a0dd7c3
From: "asterisk" <sip:asterisk@YYY.YYY.YYY.YYY>;tag=as16fc509a
To: <sip:1002@XXX.XXX.XXX.XXX:30000>;tag=314a038d
Call-ID: 7c299de60548f86f78dea64467ec26bd@YYY.YYY.YYY.YYY:5060
CSeq: 102 OPTIONS
User-Agent: WebCallServer
Allow: MESSAGE,REFER,NOTIFY,CANCEL,ACK,UPDATE,INVITE,OPTIONS,INFO,BYE
Accept: application/sdp
Accept-Language: en
Content-Length: 0
09:47:49,275 WARN RtpActivityTimerTask - Flashphoner-RtpActivityTimer-31002 RTP ACTIVITY EVENT DETECTED!


case 2 ws / rtmfp


09:50:32,101 INFO WCS4CallbackHandler - pool-19-thread-10 unregistered
09:50:32,102 INFO ManagerApiConnection - pool-19-thread-10 Config for method RegistrationStatusEvent not found, using defaults
09:50:32,105 WARN Peer - pool-4-thread-13 AudioPacket client before connection
09:50:32,118 INFO ManagerApiConnection - KeepAliveManager-18 Config for method ConnectionStatusEvent not found, using defaults
09:50:32,124 WARN Peer - pool-4-thread-22 AudioPacket client before connection
09:50:32,129 WARN Peer - pool-4-thread-17 Unpublication client before connection
09:50:32,130 INFO Streams - pool-4-thread-17 destroyPublication name OUT_1002_4ec539a8-1bb3-4946
09:50:32,239 WARN FlowWriter - KeepAliveManager-18 FlowWriter closed for FlowConnection flow. The session must be closed here. this: FlowWriter{id
=2, flowId=2, closed=true, stage=4, critical=true, nameConnection='NetConnection', session=2}
09:50:32,239 INFO Session - KeepAliveManager-18 Session 2 died
09:50:32,240 INFO Sessions - KeepAliveManager-18 Session has died an will be removed key: 2
09:50:32,240 INFO Sessions - KeepAliveManager-18 sessions count 0
09:50:32,240 INFO Sessions - KeepAliveManager-18 sessions: {}
09:50:34,426 INFO WSClient - WSClientsKeepaliveThread-43 Close connection for channel [id: 0x35762a8a, /ZZZ.ZZZ.ZZZ.ZZZ:53839 :> /XXX.XXX.XXX.XXX:8080]
with status code: 1000
09:50:34,426 INFO WCS4Handler - WSClientsKeepaliveThread-43 Disconnect client: null
09:50:37,088 INFO SipUserAgent - Timer-7 Shutdown instance. Count: 1 this: SIP UA: login: 1002 assignedPort: 30001 listeningPort: 30001
 

snoozamoorooed

New Member
Fresh news.
The problem is with something related to rtmfp channel only.
Either flash client is not sending ping replies or server side is not nandling them.
It is possible to disable rtmfp keep alive checks by adding option keep_alive.enabled=websocket,rtmp to server properties.
The default is keep_alive.enabled=websocket,rtmp,rtmfp
For some reason developers forgot to add this line to bundled config.
 

Max

Administrator
Staff member
Hello
as an option you can set
Code:
keep_alive.algorithm=INTERNAL
keep_alive.enabled=websocket,rtmp,rtmfp
By default it is HIGH_LEVEL. We will check the issue.
 

Max

Administrator
Staff member
This issue was fixed in the build 2132
So you can use default keep alive settings with the latest build
Note. It is not currently verified by our QA.
 
Top