Frequent warning, until process-crash: send aio error Out of files #1546
Replies: 13 comments 21 replies
-
|
This is an error returned by kernel when trying to send packet to socket. Check NNG_ENOFILES. It basically tells There is no file descriptor left. In this case, if there is still new connu coming, broker will take a backoff strategy to sleep and wait for new FD is released |
Beta Was this translation helpful? Give feedback.
-
|
Found the respective docs about the exception, but well - pretty much undocumented ;) So, I thought a while about a possible reason, and it might be related to the following: The ubuntu-vm is running on a hyperV-Server with a thin-provisioned disk. I remember years ago, where this caused IO-issues the moment the thin-provisioned virtual disk is at the edge of expanding. Will see, if the problem appears again during the next day, or if this might be the root cause and therefore gone for quite a time. |
Beta Was this translation helpful? Give feedback.
-
|
Mhhh, dk why it is related to Disk size.... |
Beta Was this translation helpful? Give feedback.
-
|
Ok, apparently seems not disk related. Currently the server is still running, but producing about 20 "out of files" log-messages per seconds. Will test the recommendation with ulimit -n, probably the next days. |
Beta Was this translation helpful? Give feedback.
-
|
Yup, increase the max FD number, and check with ulimit -n |
Beta Was this translation helpful? Give feedback.
-
|
I've just checked the actual running threads - and noted, that two of the nng:aio:expire threads are stuck with ~ 9.3% CPU usage. Not sure if related at all, just noted. (and while finishing this comment, the server finally crashed / got killed) |
Beta Was this translation helpful? Give feedback.
-
|
Pretty curious about your test case. If you are using a Top similar command, then 9.3% means 9.3% of one core. aio_expire thread is for reaping the expired async I/O, while other thread that for real workload is not taking too much CPU time, so that seems like massive timeout/disconnect/connect is going on. I believe this is a OOM kill, already 83% mem usage, perhaps mostly consumed by expired connection, not strange the process got killed, |
Beta Was this translation helpful? Give feedback.
-
|
Oh, didn't pay attention at the memory so far. But I believe this memory-footprint is just a consequence, not the cause. I have about 40 mqtt-devices / applications, shouldn't be too much of a memory issue. |
Beta Was this translation helpful? Give feedback.
-
|
That sounds like you are DDoS yourself.... |
Beta Was this translation helpful? Give feedback.
-
|
Found some minutes to take the required actions. I've created a systemd service for nanomq, so I don't have to wory about starting it on each reboot. systemd services allow to specify that in the respective service file, i.e. to verify it applies, use Will report back during the next days, if the problem is resolved - OR if raising the limit will just delay potential issues that shouldn't occur in the first place ;) |
Beta Was this translation helpful? Give feedback.
-
|
So far, no crash until today. I've did some checks and found out, that there is actually one device (Shelly H&T Sensor) that keeps a lot of open sockets, even if it is only waking up every once in a while to report data. (triggered by temperature and/or humidity change) Right now, nanomq has 245 open sockets, of which about 200 belong to this device. So, with the default limit of 1024, there is a potential chance that to frequent temperature / humidity changes caused a raising number of left over sockets, leading to the error.
and Since this is stable at about 250 for the past days, it seems there is some sort of timeout, when these sockets get recycled? (The Shelly itself is configured to connect with a clean session and a keepalive of 10seconds - so apparently a bug, maybe related to it's deep sleep between measurements) |
Beta Was this translation helpful? Give feedback.
-
|
Aha, see, told u. As for socket recycling. It is managed by the kernel, not much we can do other than use close(). You can check “tcp_tw_recycle/reuse” option in the kernel. that closed socket should be in TIMEWAIT state if my assumption is correct. |
Beta Was this translation helpful? Give feedback.
-
So, yeah, just happened right now ;) checking So it seems, that even if linux is closing sockets after a while, nanoMQ doesn't or doesn't release the fd-handle in some sort? I could upload both the dumps (proc / sockstat) if that's helpfull? |
Beta Was this translation helpful? Give feedback.
-
|
I don't think this is nanoMQ issue. Broker called close. Then it is kernel's place to do the rest job. What is your disconnecting scenario? It could be a bug If this is a case I neglected before, |
Beta Was this translation helpful? Give feedback.
-
I've just cheked the logs, and (this time) there are hundrets of thousands of these lines: (heavy log-flooding) and these (light log-flooding) Not sure if these errors tell you the kind of connection error that's happening.
nanoMQ may not be the root cause - but as a software developer myself i'd say: |
Beta Was this translation helpful? Give feedback.
-
|
I've now enabled trace logging, and a short script to track the fd-count per minute. Maybe this better allows to identify what is going on "the moment it starts to build up massive fd-handles". |
Beta Was this translation helpful? Give feedback.
-
|
I am an open-minded & rational person; my feeling is the last thing you need to be concerned. But still appreciate your kindness. "we have to handle that issue to ensure reliability of our service", correct, but nanomq as a broker live on the top of POSIX/Kernal rarely has any weapon against it. Actually this is a common case when running huge scale of internet service, this is why ssl/tls exist, and usually, we disable an IP if it initiates too much useless request in a short time. as long as the FD will decrease, I don't think any issues remains in broker internally. In your case particularly, perhaps reusing the FD for this undisciplined sensor/MCU is the way to go. |
Beta Was this translation helpful? Give feedback.
-
|
I will still see, if the debug logs will unveil something. That one mentioned sensor is doing something wrong, that's obvious - but it's socket-pollution is at a rate of about 100 per day. So, the current limit of 24000 should be good for at least 240 days without any recycling going on - which it wasn't. Either that sensor is going crazy after a while or it's open sockets is / was the wrong "trace" to pick up. As mentioned above, it is strange that the processes' fd-count goes beyond 24k, while sockstat shows ~ 250 sockets in use. I've been running nanoMQ on a Windows Server for 4 Months before. Didn't have any issues there. Ofc, windows handles the stuff different than POSIX, but from my experience... Most the time not better :) But it also was nanoMQ 19.1 compared to the current 20.8, don't know if there are major changes to fundamental classes that may have an impact. Whatsoever - I will post an update if there's something worth mentioning inside this (probably) gigabytes of trace logs ;-) |
Beta Was this translation helpful? Give feedback.
-
|
Those logs are worth little despite telling you how fast that sensor connects and disconnects. According to your last post, the rate definitely varies, As you can image, while the reading experiencing dramatical change.... The most significant fix between 19.1-20.8 is #1411, this is also the only PR change TCP/Core part. BTW, Yes Windows handles sockets in a different way compare to Linux. It use IOCP while Linux stay with epoll |
Beta Was this translation helpful? Give feedback.
-
|
Everything has been running 3 days without any surprise so far. 250 fd-handles +/- Today, I checked the fd-handle-count-log and noted, that nanoMQ has started to build up handles. At this rate, it'll probably hit the 25k limit in about 3 more days i'd say. yet, at this point, sockstat just reports ~ 240-251 sockets beeing open: At exactly 14:00 I even So, whatever triggers the increase in fd-handles does not seem to be related to external socket connections - else sockstat should report? I've attached a trace log from around 13:59 - 14:01 of today, in case you want to have a look at it. Since I don't know the messages I could only look for repeated stuff, but probably just encounter traces that are meant to repeat over and over without any indicator of an error.
I've checked the logs a bit - every full hour, there are about 280 "conenctions & publishes" of a customers remote-servers (disk-space-check) - they are done through a powershell client, over a VPN-Connection. (The clients in the subnet 192.168.136.0) this matches the hourly fd-handle increase quite good - the big question would be, why does this become an issue after 3 days of uptime of nanoMQ - and not right away? May it be possible that NAT has something to do with it? And nanoMQ maybe associates all 280 connections by their "next hop" rather than their actual address, hence somehow just "closes" 279 handles probably? (But again, why does this begin after a certain uptime? these servers are publishing 24/7) |
Beta Was this translation helpful? Give feedback.
-
|
With all due respect, the log tells the whole story. Broker is not able to decrease the fd-count other than fire a request to kernel. and this is a pretty basic action; if this goes wrong, the bug report shall have already filled this board. There is no ground to put accusation on nanomq. From 2023-12-07 14:00:06 to 2023-12-07 14:00:35, connect/disconnect happens 120 times, The broker has to deal with it, and once the client disconnects, it will tell the kernel to release it. NanoMQ is able to accept the TCP connection in high performance, this could make things worse. And FYI, the kernel is able to recycle the FD quickly only if the TCP/Socket connection is closed properly(this is also what you said " everything works as expected again" ). If this is an abrupt disconnect due to network outrage or whatever reason, it will produce a TIME_WAIT/CLOSE_WAIT state, it will leave the socket fd living for a while. This is common knowledge regarding networking and OS. you could find it by using "netstat" command. My suggestion is, learn about Computer networking, read https://serverfault.com/questions/212093/how-to-reduce-number-of-sockets-in-time-wait, and then check the network or firewall or client to find out what causes the frequent reconnect issue. |
Beta Was this translation helpful? Give feedback.
-
|
No need become offending mate. There is no "reconnect issue", it's a total of 280 messages delivered through a independent connection, opening it, sending data, closing it. There aren't any sockets remaining in TIME_WAIT / CLOSE_WAIT - they are closed. Yet the fd-handles remains unchanged AFTER a certain uptime of the system / nanomq process. For ANY client. As I said, and as u are arguing: It may be related to the operating system (or configuration or lack thereof), that these fd-handles are not closed when nanoMQ requests to do so. (then it is obviously not nanomqs fault) I'm a software dev, so you are - so you know, there could be code that is working 99.8% flawless and fails in a very special edge szenario. Spending time to extract and write down some observations doesn't have the purpose to blame or insult somebody. This is not a fb-group where discussions are about who's right. |
Beta Was this translation helpful? Give feedback.
-
|
Well, as I said, I don't have strong emotions... I apologize if you feel offended. Feel free to fire your issue and questions, debate produces truth. But, I doubt your statement "There aren't any sockets remaining in TIME_WAIT / CLOSE_WAIT", it is clear from log that the client is closed abnormally. The disconnect packet has not yet been received. And reconnecting 120+ times within 20 seconds definitely seems like a reconnect issue to me. Double-check the netstat. Some packet sniffing could help. Whoops even worse. |
Beta Was this translation helpful? Give feedback.
-
|
I think I have to add some clarification about the (re-)connect issue: I'm running about 20 Servers with a total of 35 disks on a remote-site. Each Server runs a script every hour to report it's disk usage(s) to the mqtt server. The Publish method (script below) is creating a new connection per-publish because it is used in various scripts that sometimes need to publish something. So, each report for a single disk is 8 connections, publishes and disconnects. Total of 280 connections for 35 disks. The script itself / the Since none of the scripts ever get's stuck and netstat / sockstat on the mqtt host don't show anything else, it is pretty "save" to say that each client is performing it's disconnect as it should. As mentioned, these scripts are running 24/7 and don't cause any issues upto a certain point. At that point (Which I noted after 3 days so far) I still can see that sockets are closed properly - but the fd-handles are no longer removed. They then start to increase until the process runs out of fd-handles. I also can confirm, that NO OTHER clients disconnect causes a drop in fd-handles (anymore). Upon connection it's a +1 - upon disconnect fd-handles remain constant. This is the diskspace-script mentioned: I've even just ran the following "test":
So, whatever happens after "about 3 days" (and cause that fd-handles are no longer removed) will be the interesting thing, i'm sure. So, when I encounter this Issue next time, I will verify 2 things:
If others fail as well: |
Beta Was this translation helpful? Give feedback.
-
|
Your perseverance really inspired me.... Well.... you tested it, you see that FD requires certain times to be recycled... And dislike Win. Resource operation in Linux requires a FD. Including reaping worker of nng:aio:expire as you see in the top. Running out of files could result in serious side effects and unexpected software action. And as the screenshot you posted in the early thread (that indicates nng:aio:expire occupied much of CPU time ), I started to paint a reasonable pic. Clients keep connecting and disconnecting, the recycling rate is a bit lower than the acceptance rate. For some reason (or just run out of files already, this is where become strange in your case), nanomq cannot get new FD from the kernel and hit NNG_ENOFILES, in this case, it will backoff for 10 seconds to wait for the new FD to be released. So that the processing of current TCP will be delayed and add up to the queue for later resolution. Upon that, old TCP was holding, new connection is kept flowing into the system, finally the equilibrium is broken, at this moment, the FD will add up exponentially, since broker is nearly not able to accept any new TCP connection, and busy handling the past connection, the queue grows longer and longer. the reaper(aio_expire) of NanoMQ cannot keep with the pace of flooding TCP socket. This is called FD-Exhaustion. This is pretty common case for our customer, we have dealt with a lot of similar cases in Cloud, nothing particular for you case, except that you were saying the FD lives forever. I believe by stopping all clients, you will see the FD slowly get recycled. This is my final guess, I will leave you to your struggle then. |
Beta Was this translation helpful? Give feedback.
-
|
I have now been encountering the Issue for three more times - and added another layer of "tracing" to it. Finally, I was able to find what I was hoping to find: An error logged, appearing ONCE, beeing able to confirm fd-handle-releasing works before - but stops after. So, what I did:
So, derived from this and the syslog of the system, this is what I was able to figure out:
I will now clear the logs, restart everything, and see if this is "exactly" happening again - or if the message and failure-time was a coincidence. I've checked the code in nmq_mqtt.c but i'm not into C.
Maybe whatever should happen there is STILL disrupting the "state machine"? ;-) From a logical point of view: Maybe the calls to "Set msg=null" and " free(msg)" should be swapped? like this? (Just a wild guess) |
Beta Was this translation helpful? Give feedback.
-
|
The solid proof shall be: once you think fd-handle-releasing stops working, stop all connections, and the fd count never drops. |
Beta Was this translation helpful? Give feedback.
-
|
According to the log, apprantely the client is not graceful disconnecting. Other wise a Disconnect will be logged. “pipe id 1441120957 is gone, pub failed” only says, "hey, the target client is gone. You are sending msg to void! I gonna drop the msg" |
Beta Was this translation helpful? Give feedback.
-
|
Will do next time - just rebooted. btw, So, while I may be terrible wrong in C about this, but if this was java or c#, it would definitly set the underlaying object-property ( |
Beta Was this translation helpful? Give feedback.
-
|
A potential case looks similar to the scenario described here: look issue #1619. |
Beta Was this translation helpful? Give feedback.
-
|
@realdognose This turns out a bug that only with TLS transport, my fault. |
Beta Was this translation helpful? Give feedback.
-
|
Thx for the headsup. I will give that a try when I have some time and let you know if this is applicable for my situation. (Currently switched to another Broker, cause needed to have it running unattended for a couple of weeks) |
Beta Was this translation helpful? Give feedback.
-
I'm using nanoMQ 0.20.8 with ubuntu 22.04.
After one day of uptime, logs are beeing spamed with the following error, until the process dies:
Any hint, what this message means? Google did not yield any valuable results.
Beta Was this translation helpful? Give feedback.
All reactions