Production down with message "com.flashphoner.server.B.A.G: No free ports available"

chpat

New Member
Hello,
We are using WCS and WebRTC in production.
Every 8-9 days, Flashphoner freeze and refuse new connections.
In the log, we are seeing a LOT of :

Code:
20:35:50,987 ERROR           RtspAgents - Can't create rtspClient
Mar 13 20:35:50 flashphonerprod000000 bash[3564236]: com.flashphoner.server.B.A.G: No free ports available
Mar 13 20:35:50 flashphonerprod000000 bash[3564236]:         at com.flashphoner.server.B.A.C.E(Unknown Source)
Mar 13 20:35:50 flashphonerprod000000 bash[3564236]:         at com.flashphoner.server.remote.E.D.allocatePort(Unknown Source)
Mar 13 20:35:50 flashphonerprod000000 bash[3564236]:         at com.flashphoner.server.remote.B.<init>(Unknown Source)
Mar 13 20:35:50 flashphonerprod000000 bash[3564236]:         at com.flashphoner.server.remote.E.D.<init>(Unknown Source)
Mar 13 20:35:50 flashphonerprod000000 bash[3564236]:         at com.flashphoner.server.remote.E.A.C(Unknown Source)
Mar 13 20:35:50 flashphonerprod000000 bash[3564236]:         at com.flashphoner.server.remote.E.A.createAgent(Unknown Source)
Mar 13 20:35:50 flashphonerprod000000 bash[3564236]:         at com.flashphoner.server.remote.E.A(Unknown Source)
Mar 13 20:35:50 flashphonerprod000000 bash[3564236]:         at com.flashphoner.server.remote.E.B(Unknown Source)
Mar 13 20:35:50 flashphonerprod000000 bash[3564236]:         at com.flashphoner.server.remote.L.A(Unknown Source)
Mar 13 20:35:50 flashphonerprod000000 bash[3564236]:         at com.flashphoner.server.remote.L.A(Unknown Source)
Mar 13 20:35:50 flashphonerprod000000 bash[3564236]:         at com.flashphoner.rest.server.NodeApi.startupRtspAgent(Unknown Source)
Mar 13 20:35:50 flashphonerprod000000 bash[3564236]:         at com.flashphoner.rest.server.rest_v2.RestRtspController.startup(Unknown Source)
Mar 13 20:35:50 flashphonerprod000000 bash[3564236]:         at jdk.internal.reflect.GeneratedMethodAccessor115.invoke(Unknown Source)
Mar 13 20:35:50 flashphonerprod000000 bash[3564236]:         at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
Mar 13 20:35:50 flashphonerprod000000 bash[3564236]:         at java.base/java.lang.reflect.Method.invoke(Method.java:567)
Mar 13 20:35:50 flashphonerprod000000 bash[3564236]:         at com.flashphoner.rest.server.RestApiRouter.getResponse(Unknown Source)
Mar 13 20:35:50 flashphonerprod000000 bash[3564236]:         at com.flashphoner.rest.server.RestApiRouter.processRequest(Unknown Source)
Mar 13 20:35:50 flashphonerprod000000 bash[3564236]:         at com.flashphoner.server.http.handlers.RestApiRequestHandler.process(Unknown Source)
Mar 13 20:35:50 flashphonerprod000000 bash[3564236]:         at com.flashphoner.server.http.G.messageReceived(Unknown Source)
Mar 13 20:35:50 flashphonerprod000000 bash[3564236]:         at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(Unknown Source)
Mar 13 20:35:50 flashphonerprod000000 bash[3564236]:         at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(Unknown Source)
Mar 13 20:35:50 flashphonerprod000000 bash[3564236]:         at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(Unknown Source)
Mar 13 20:35:50 flashphonerprod000000 bash[3564236]:         at org.jboss.netty.handler.stream.ChunkedWriteHandler.handleUpstream(Unknown Source)
Mar 13 20:35:50 flashphonerprod000000 bash[3564236]:         at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(Unknown Source)
Mar 13 20:35:50 flashphonerprod000000 bash[3564236]:         at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(Unknown Source)
Mar 13 20:35:50 flashphonerprod000000 bash[3564236]:         at org.jboss.netty.handler.codec.http.HttpChunkAggregator.messageReceived(Unknown Source)
Mar 13 20:35:50 flashphonerprod000000 bash[3564236]:         at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(Unknown Source)
Mar 13 20:35:50 flashphonerprod000000 bash[3564236]:         at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(Unknown Source)
Mar 13 20:35:50 flashphonerprod000000 bash[3564236]:         at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(Unknown Source)
Mar 13 20:35:50 flashphonerprod000000 bash[3564236]:         at org.jboss.netty.channel.Channels.fireMessageReceived(Unknown Source)
Mar 13 20:35:50 flashphonerprod000000 bash[3564236]:         at org.jboss.netty.handler.codec.frame.FrameDecoder.unfoldAndFireMessageReceived(Unknown Source)
Mar 13 20:35:50 flashphonerprod000000 bash[3564236]:         at org.jboss.netty.handler.codec.replay.ReplayingDecoder.callDecode(Unknown Source)
Mar 13 20:35:50 flashphonerprod000000 bash[3564236]:         at org.jboss.netty.handler.codec.replay.ReplayingDecoder.messageReceived(Unknown Source)
Mar 13 20:35:50 flashphonerprod000000 bash[3564236]:         at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(Unknown Source)
Mar 13 20:35:50 flashphonerprod000000 bash[3564236]:         at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(Unknown Source)
Mar 13 20:35:50 flashphonerprod000000 bash[3564236]:         at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(Unknown Source)
Mar 13 20:35:50 flashphonerprod000000 bash[3564236]:         at org.jboss.netty.channel.Channels.fireMessageReceived(Unknown Source)
Mar 13 20:35:50 flashphonerprod000000 bash[3564236]:         at org.jboss.netty.channel.Channels.fireMessageReceived(Unknown Source)
Mar 13 20:35:50 flashphonerprod000000 bash[3564236]:         at org.jboss.netty.channel.socket.nio.NioWorker.read(Unknown Source)
Mar 13 20:35:50 flashphonerprod000000 bash[3564236]:         at org.jboss.netty.channel.socket.nio.AbstractNioWorker.processSelectedKeys(Unknown Source)
Mar 13 20:35:50 flashphonerprod000000 bash[3564236]:         at org.jboss.netty.channel.socket.nio.DeadlockAwareNioWorker.run(Unknown Source)
Mar 13 20:35:50 flashphonerprod000000 bash[3564236]:         at org.jboss.netty.util.ThreadRenamingRunnable.run(Unknown Source)
Mar 13 20:35:50 flashphonerprod000000 bash[3564236]:         at org.jboss.netty.util.internal.DeadLockProofWorker$1.run(Unknown Source)
Mar 13 20:35:50 flashphonerprod000000 bash[3564236]:         at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
Mar 13 20:35:50 flashphonerprod000000 bash[3564236]:         at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
Mar 13 20:35:50 flashphonerprod000000 bash[3564236]:         at java.base/java.lang.Thread.run(Thread.java:835)
I attached our Grafana Dashboards, we are not seeing saturation on media or wcs_agent ports during the incident (20H-21H40 on the graph).

We are using an old version (5.2.1794) with the configuration below.
We are going to upgrade to the latest version and increase the media_port range to 30000-32500.
We looked at this issue https://forum.flashphoner.com/threads/com-flashphoner-server-g-a-e-no-free-ports-available.11295/ but we don't have this much usage. Only 10-30 users and 100 streams maximum.

Are you aware of a bug in this version? (we found no trace of a fix in the release note)
Do you think it could be a configuration issue or something else? Thanks !

I did a netstat -laputen on the virtual machine during the incident, and there was only a few ESTABLISHED and TIME_WAIT connections. As you can see on the dashboard, metrics show a lot of available ports. Incident occurred two time in a row already. Very strange.

Code:
ip                     = {{EXTERNAL_IP}}
ip_local               = {{LOCAL_IP}}

# RTP/SRTP port range
media_port_from        = 30000
media_port_to          = 31000

# RTSP port range
rtsp_port_from = 35001
rtsp_port_to = 40000

# WSS port range
wcs_agent_port_from = 40001
wcs_agent_port_to = 45000

# SIP port range
port_from = 30000
port_to = 31000

rtsp_interleaved_mode = true
# codecs = h264 # Breaks audio sdp
force_client_requested_video_resolution = false

# If true, activate loadbalancer:
# load_balancing_enabled = true

# Suppress audio globally (not available in trial version)
suppress_audio = true

http_enable_paths = rest,action,shared,embed_player,empty,health-check

# Close inactive RTSP->WCS stream with no subscriber
rtsp_activity_timer_timeout = 30000

# Websockets port
ws.port                 = {{WS_PORT}}
wss.port                = {{WSS_PORT}}

# Logs
client_log_level = ERROR
client_dump_level = 0
enable_extended_logging = false

# Disable all unused features
cli_enabled = false
https_server_enabled = false
manager_http_ports_enabled = false
# Disable WebRTC Selective Forwarding Unit
# This is only usefu when :
# - publishing a stream in a number of encodings (for example, 720p, 360p, 180p) with quality switching on the fly
# - building chat rooms
sfu_bridge_enabled = false

# Disable unused protocols on the client side
# We only expose RTSP stream with MSE over websocket or WebRTC
rtsp_server_enabled = false
rtmp_server_enabled = false
rtmfp_server_enabled = false
hls_server_enabled = false

# Disabled unused protocols on the proxy side (DVR and cameras in parkings)
hls_enabled = false
 

Attachments

chpat

New Member
Hi,
We updated to 5.2.2192 and went into production (docker image).
This morning the issue reappear and our streaming service was down until we restarted the application.

Please find below our configuration, the log, and a dashboard with our metrics.
Thank you for your help.

Code:
# cat flashphoner.properties
# https://docs.flashphoner.com/display/WCS52EN/Settings+file+flashphoner.properties

ip       = {{EXTERNAL_IP}}
ip_local = {{LOCAL_IP}}

# SIP port range
port_from = 43301
port_to = 43400

rtmp_port_from = 43201
rtmp_port_to = 43300

turn_media_port_from = 43101
turn_media_port_to = 43200

mpegts_reserved_port_from = 43001
mpegts_reserved_port_to = 43100

# RTP/SRTP port range
media_port_from = 30000
media_port_to   = 32500

# RTSP port range
rtsp_port_from = 35001
rtsp_port_to = 40000

# WSS port range
wcs_agent_port_from = 40001
wcs_agent_port_to = 42000

# tune UDP sockets buffers
rtp_receive_buffer_size=131072
rtp_send_buffer_size =131072

rtsp_interleaved_mode = true
# codecs = h264 # Breaks audio sdp
force_client_requested_video_resolution = false

# enable Java Cryptography Extension usage
webrtc_aes_crypto_provider=JCE

# If true, activate loadbalancer:
# load_balancing_enabled = true

# Suppress audio globally (not available in trial version)
suppress_audio = true

http_enable_paths = rest,action,shared,embed_player,empty,health-check

# Close inactive RTSP->WCS stream with no subscriber
rtsp_activity_timer_timeout = 5000

# Websockets port
ws.port  = {{WS_PORT}}
wss.port = {{WSS_PORT}}

# Logs
client_log_level = ERROR
client_dump_level = 0
enable_extended_logging = false

# Disable all unused features
cli_enabled = false
https_server_enabled = false
manager_http_ports_enabled = false
# Disable WebRTC Selective Forwarding Unit
# This is only usefu when :
# - publishing a stream in a number of encodings (for example, 720p, 360p, 180p) with quality switching on the fly
# - building chat rooms
sfu_bridge_enabled = false

# Disable unused protocols on the client side
# We only expose RTSP stream with MSE over websocket or WebRTC
rtsp_server_enabled = false
rtmp_server_enabled = false
rtmfp_server_enabled = false
hls_server_enabled = false

# Disabled unused protocols on the proxy side (DVR and cameras in parkings)
hls_enabled = false
Code:
# cat wcs-core.properties
### SERVER OPTIONS ###
# Set this property to false to disable session debug
-DsessionDebugEnabled=false
-Djdk.tls.client.protocols="TLSv1.2,TLSv1.3"


### JVM OPTIONS ###
-Xmx{{XMX}}
-Xms{{XMS}}
#-Xcheck:jni

# Can be a better GC setting to avoid long pauses

#-XX:NewSize=1024m
#-XX:+CMSIncrementalMode
#-XX:+UseParNewGC"

#Disable heuristic rules
-XX:+UseCMSInitiatingOccupancyOnly
#Reduce Old Gen threshold
-XX:CMSInitiatingOccupancyFraction=70

#enable AES support
-server
-XX:+UnlockDiagnosticVMOptions
-XX:+UseAES
-XX:+UseAESIntrinsics

# Uncomment to fix multicast crosstalk problem when streams share multicast port
-Djava.net.preferIPv4Stack=true

# Default monitoring port is 50999. Make sure the port is closed on firewall. Use ssh tunel for the monitoring.
-Dcom.sun.management.jmxremote=false
-Dcom.sun.management.jmxremote.local.only=false
-Dcom.sun.management.jmxremote.ssl=false
-Dcom.sun.management.jmxremote.authenticate=false
-Dcom.sun.management.jmxremote.port=50999
-Dcom.sun.management.jmxremote.host=localhost
-Djava.rmi.server.hostname=localhost

-XX:ErrorFile=/usr/local/FlashphonerWebCallServer/logs/error%p.log


-Xlog:gc*:/usr/local/FlashphonerWebCallServer/logs/gc-core-:time
# Use System.gc() concurrently in CMS
-XX:+ExplicitGCInvokesConcurrent
# Disable System.gc() for RMI, for 10000 hours
-Dsun.rmi.dgc.client.gcInterval=36000000000
-Dsun.rmi.dgc.server.gcInterval=36000000000

# Proxy configuration
-Dhttp.proxyHost=proxy1.flashphoner.com
-Dhttp.proxyPort=3128
-Dhttps.proxyHost=proxy1.flashphoner.com
-Dhttps.proxyPort=3128
-Dhttp.nonProxyHosts=localhost|127.0.0.1|10.*|169.254.169.254

#List of caught system signals
#-DsignalHandlers=ABRT
#-DsignalHandlersLogBufferSize=1048576
Code:
com.flashphoner.server.B.A.G: No free ports available
#011at com.flashphoner.server.B.A.C.E(Unknown Source)
#011at com.flashphoner.server.remote.E.D.allocatePort(Unknown Source)
#011at com.flashphoner.server.remote.B.<init>(Unknown Source)
#011at com.flashphoner.server.remote.E.D.<init>(Unknown Source)
#011at com.flashphoner.server.remote.E.A.C(Unknown Source)
#011at com.flashphoner.server.remote.E.A.createAgent(Unknown Source)
#011at com.flashphoner.server.remote.D.A(Unknown Source)
#011at com.flashphoner.server.remote.D.B(Unknown Source)
#011at com.flashphoner.server.remote.L.A(Unknown Source)
#011at com.flashphoner.server.remote.L.A(Unknown Source)
#011at com.flashphoner.rest.server.NodeApi.startupRtspAgent(Unknown Source)
#011at com.flashphoner.rest.server.rest_v2.RestRtspController.startup(Unknown Source)
#011at jdk.internal.reflect.GeneratedMethodAccessor12.invoke(Unknown Source)
#011at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
#011at java.base/java.lang.reflect.Method.invoke(Method.java:567)
#011at com.flashphoner.rest.server.RestApiRouter.getResponseContent(Unknown Source)
#011at com.flashphoner.rest.server.RestApiRouter.processRequest(Unknown Source)
#011at com.flashphoner.server.http.handlers.RestApiRequestHandler.process(Unknown Source)
#011at com.flashphoner.server.http.G.messageReceived(Unknown Source)
#011at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:76)
#011at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:563)
#011at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791)
#011at org.jboss.netty.handler.stream.ChunkedWriteHandler.handleUpstream(ChunkedWriteHandler.java:142)
#011at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:563)
#011at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791)
#011at org.jboss.netty.handler.codec.http.HttpChunkAggregator.messageReceived(HttpChunkAggregator.java:111)
#011at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:76)
#011at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:563)
#011at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791)
#011at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:296)
#011at org.jboss.netty.handler.codec.frame.FrameDecoder.unfoldAndFireMessageReceived(FrameDecoder.java:420)
#011at org.jboss.netty.handler.codec.replay.ReplayingDecoder.callDecode(ReplayingDecoder.java:546)
#011at org.jboss.netty.handler.codec.replay.ReplayingDecoder.messageReceived(ReplayingDecoder.java:445)
#011at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:76)
#011at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:563)
#011at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:558)
#011at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:268)
#011at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:255)
#011at org.jboss.netty.channel.socket.nio.NioWorker.read(NioWorker.java:91)
#011at org.jboss.netty.channel.socket.nio.AbstractNioWorker.processSelectedKeys(AbstractNioWorker.java:373)
#011at org.jboss.netty.channel.socket.nio.DeadlockAwareNioWorker.run(Unknown Source)
#011at org.jboss.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunnable.java:102)
#011at org.jboss.netty.util.internal.DeadLockProofWorker$1.run(DeadLockProofWorker.java:42)
#011at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
#011at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
#011at java.base/java.lang.Thread.run(Thread.java:835)
INFO               NodeApi - HTTP-pool-3-thread-5124 Connection failed stream name - rtsp://x.x.x.x/Streaming/Channels/301
INFO          AgentFactory - HTTP-pool-3-thread-5124 Provide stream initialization result com.flashphoner.server.remote
INFO            RestClient - API-ASYNC-pool-8-thread-210 Method availableStream not available for app defaultApp
INFO         RestApiRouter - HTTP-pool-3-thread-5124 handleRequest method: /rest-api/rtsp/startup, params:{uri=rtsp://x.x.x.x/cam/realmonitor?channel=1&subtype=1, toStream=[...]&STANDARD}
ERROR           RtspAgents - HTTP-pool-3-thread-5124 Can't create rtspClient

Screenshot From 2025-04-17 09-51-12.png
 

Max

Administrator
Staff member
Hello
We assume that it is a kind of leak in RTSP port manager.
Unfortunately RTSP ports are not listed in the Stats. So you have to gather logs.

Please add a line into the config conf/log4j.properties
It does not require server restart.
Code:
log4j.logger.RtspPortManager=DEBUG
The log4j.properties will look like
Code:
log4j.rootLogger=info, stdout, fAppender
log4j.logger.RtspPortManager=DEBUG
...
Once the file log4j.properties is saved, it will print logs into logs/server_logs/flashphoner.log file.
Please send logs via the private Report Form or download link.

From our end we will check similar case with your settings.
 

chpat

New Member
Thanks for your help.

I had
log4j.logger.RtspPortManager=ERROR and change it to log4j.logger.RtspPortManager=DEBUG

Do I wait for the issue to occur again, and THEN I send you the logs ?
How much log duration do you want ? Before and after the event ? Because we are rotating these logs quite aggressively :-D .

Best regards,
 

Max

Administrator
Staff member
Just send a few hours of logs.
We have to estimate state of RtspPortManager

Also please temporary switch logs to info level if it is possible.
Code:
log4j.rootLogger=info, stdout, fAppender
It will give us more details.
 

Max

Administrator
Staff member
We can't reproduce the issue with build 5.2.2192 using your configs and supposed test case. So you should do the following:
1. Enable server logs INFO level as mentioned above
2. Enable RTSP port manager DEBUG logs as mentioned above
3. Let the server work for a few hours
4. Collect a report as described: Getting logs with report.sh script (preferable)
5. Do not change anything in the report files!
6. Send the report archive using the form.
 
Top