High CPU usage on pfSense router's miniupnpd service caused by Jami install on Linux after resuming from sleep
Bug report form
Describe your environment
Please specify the following:
- OS: Trisquel 10
- Jami version: Astarte - Build ID: 202412200244
- What build you are using: https://dl.jami.net/stable/ubuntu_20.04/
Steps to reproduce
Note: Better the scenario is, better we will be able to reproduce and debug.
-
Can you reproduce the bug: occasionally
-
Steps:
- Install pfSense as the router for the network and enable the UPnP service.
- Install Jami on a PC, sign in, and enable UPnP.
- Put the computer to sleep.
- Resume from sleep.
- SSH into pfSense, start a shell, run 'top' and check for consistent high CPU usage of the miniupnpd process.
- Quit Jami on PC. Watch the CPU usage of miniupnpd drop back down to normal (~1%).
- Start Jami again. Watch for increased CPU usage as Jami connects, then watch it drop back down to normal.
-
Actual result: pfSense's UPnP service jumps to 95%-100% CPU usage and stays there, slowing down the router and network.
-
Expected result: UPnP service should behave normally, increasing its CPU usage to process new requests, but then returning to normal when completed.
Additional information
I suspect this is not exclusive to pfSense. Jami may be overloading other routers as well when running UPnP. Note that this problem seems to happen at random, possibly after long periods of sleep when the UPnP port reservation has expired and needs to be renewed.
Activity
I was experiencing a network slowdown today after waking my PC from sleep and suspected Jami as being the culprit. Sure enough, upon connecting to pfSense and running 'top' to check CPU usage, the miniupnpd service was near 100%. So I quickly opened up the Jami log window and found that Jami was repeatedly requesting UDP mappings, each time with a port number following the last one. The mapping requests were successful for about 60 ports or so (unsure how many requests it made before starting the log), but then failed after that point. See attached log file:Jami_log_REDACTED2.txt
About 1 minute after quitting Jami, the miniupnpd service returned to normal CPU usage. I'm guessing that Jami requested far too many ports than the pfSense UPnP/NAT-PMP service was willing to provide and it eventually quit mapping ports for it. My PC was only awake for a few minutes before noticing the network congestion, so I may have been lucky to catch the log right at the transition where miniupnpd was mapping ports for Jami and then got fed up with it and quit. I didn't think to check the pfSense logs at the time; but if I catch it happening again, I will take a look and comment again with anything significant that I find.
Thank you very much for taking the time to write a detailed bug report and provide logs.
[...] Jami was repeatedly requesting UDP mappings, each time with a port number following the last one.
The UDP port numbers requested by Jami are chosen at random between 20,000 and 25,000. The fact that we're seeing consecutive port numbers in the logs suggests that Jami tried to open almost all of the ports in that range. This should obviously never happen. I'm guessing it's due to some kind of infinite loop bug, but in any case, it's a serious issue and I'll make fixing it my priority this week.
assigned to @ffauteux-chapleau
added severityhigh sprintbacklog typebug labels
added sprintin progress label and removed sprintbacklog label
This morning I caught Jami in the middle of reserving its ports. This time it completed before pfSense became overwhelmed. I checked pfSense's port mapping logs and Jami successfully mapped a total of 1457 UDP ports starting with port 20001 and ending with port 23230. Not every port in the range, but it definitely started down low and worked its way up (not random). Jami's logs showed all the port mappings to be successful, with no "error -100: TRYAGAIN" log entries. Upon completion of the mappings Jami appears to have continued to load as normal, scheduling the next port mapping renewal for an hour later, finding peer devices, accepting ICE requests, adding a TURN server, storing the public IP address, adding remote candidates, etc.
Let me know if you'd like a copy of this log as well and I'll clean it up and post it. Unfortunately I don't have the time this morning to do so.
Not every port in the range, but it definitely started down low and worked its way up (not random).
When creating a new mapping, Jami chooses the port number at random, but there are situations where it will iterate over a list of ports in order. In particular, if Jami loses and then regains Internet access (which can happen if your computer goes to sleep and later wakes up), then it will attempt to reopen some of the ports it previously had, and it will do so in numerical order, not in the original order in which the ports were requested. The only strange thing is that it stopped at 23230, but maybe you would have seen higher port numbers appear eventually. How long did you wait before closing Jami?
Let me know if you'd like a copy of this log as well and I'll clean it up and post it.
I think that won't be necessary; thanks to the information you had already provided me, I was able to identify two bugs yesterday which I'm pretty sure are responsible for the issue you've been experiencing. I'll let you know once they're fixed.
mentioned in commit dhtnet@a406c4a3
mentioned in commit dhtnet@d16f8162
mentioned in commit jami-daemon@556650c9
How long did you wait before closing Jami?
It seemed to be working alright so I didn't close it; just put the PC back to sleep after writing my last comment. I was watching the log while writing it though and I didn't notice any other attempts to map any ports. Definitely not to the extent that it was trying to do when I first resumed from sleep, which was around 2-4 ports per second.
Looking forward to the update. Glad I could help out.
Edited by Jonathan
added sprintdone label and removed sprintin progress label
