Cloudron 5.3.3 crashed for me, unclear why.
-
Hello,
I had an incident today just a short bit ago where one of my customers was complaining of mail issues, and I went to go review the logs only to find out that my whole Cloudron server was having issues in the sense that nothing was loading (was loading the initial screen but never loaded any actual app icons or any content at all really. I could also see that I was having trouble sending email too, so I immediately rebooted the server to get it operational again and things are working well now for the moment. Naturally, I looked into the logs and found this which strikes out to me:
2020-07-02T13:36:25.221Z box:dyndns refreshDNS: no change in IP 54.xx.xxx.xxx /home/yellowtent/box/node_modules/cron/lib/cron.js:235 throw new Error( ^ Error: Something went wrong. cron reached maximum iterations. Please open an issue (https://github.com/kelektiv/node-cron/issues/new) and provide the following string Time Zone: "" - Cron String: 37 * * * * * - UTC offset: -07:00 - current Date: Thu Jul 02 2020 06:36:46 GMT-0700 at CronTime._getNextDateFrom (/home/yellowtent/box/node_modules/cron/lib/cron.js:235:12) at CronTime.sendAt (/home/yellowtent/box/node_modules/cron/lib/cron.js:156:17) at CronTime.getTimeout (/home/yellowtent/box/node_modules/cron/lib/cron.js:175:29) at CronJob.start (/home/yellowtent/box/node_modules/cron/lib/cron.js:613:31) at Timeout.callbackWrapper [as _onTimeout] (/home/yellowtent/box/node_modules/cron/lib/cron.js:665:29) at ontimeout (timers.js:436:11) at tryOnTimeout (timers.js:300:5) at listOnTimeout (timers.js:263:5) at Timer.processTimers (timers.js:223:10)Just after the above, it looks like Cloudron auto-restarted because I then see the following:
2020-07-02T13:36:50.187Z 2020-07-02T13:36:50.189Z ========================================== 2020-07-02T13:36:50.189Z Cloudron 5.3.3 2020-07-02T13:36:50.189Z ========================================== 2020-07-02T13:36:50.190Z 2020-07-02T13:36:50.279Z box:database reconnect: connecting to database 2020-07-02T13:36:50.302Z box:database reconnect: connected to database 2020-07-02T13:36:50.302Z box:settings initCache: pre-load settings 2020-07-02T13:36:50.320Z box:shell reload spawn: /usr/bin/sudo -S /home/yellowtent/box/src/scripts/reloadnginx.shLater I see this:
2020-07-02T13:37:10.273Z ERROR (node:15666) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 error listeners added. Use emitter.setMaxListeners() to increase limit [ internal/process/warning.js:25:20 ] 2020-07-02T13:37:10.275Z ERROR (node:15666) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 error listeners added. Use emitter.setMaxListeners() to increase limit [ internal/process/warning.js:25:20 ] 2020-07-02T13:37:10.295Z ERROR (node:15666) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 error listeners added. Use emitter.setMaxListeners() to increase limit [ internal/process/warning.js:25:20 ] 2020-07-02T13:37:10.297Z ERROR (node:15666) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 error listeners added. Use emitter.setMaxListeners() to increase limit [ internal/process/warning.js:25:20 ]Now the above wasn't around the time of the incident, but I'm not sure if it's related or not. Later on in the logs just a few hours later, I see the following two stack traces:
2020-07-02T18:59:53.120Z box:ldap 172.18.0.3:39470 unexpected connection error { Error: This socket has been ended by the other party at Socket.writeAfterFIN [as write] (net.js:396:12) at SearchResponse.send (/home/yellowtent/box/node_modules/ldapjs/lib/messages/search_response.js:88:21) at /home/yellowtent/box/src/ldap.js:111:17 at Array.forEach (<anonymous>) at finalSend (/home/yellowtent/box/src/ldap.js:110:17) at /home/yellowtent/box/src/ldap.js:281:17 at Query.<anonymous> (/home/yellowtent/box/src/mailboxdb.js:202:13) at Query.<anonymous> (/home/yellowtent/box/node_modules/mysql/lib/Connection.js:526:10) at Query._callback (/home/yellowtent/box/node_modules/mysql/lib/Connection.js:488:16) at Query.Sequence.end (/home/yellowtent/box/node_modules/mysql/lib/protocol/sequences/Sequence.js:83:24) code: 'EPIPE' } 2020-07-02T18:59:53.148Z box:ldap 172.18.0.3:39470 unexpected connection error { Error: This socket has been ended by the other party at Socket.writeAfterFIN [as write] (net.js:396:12) at SearchResponse.LDAPResult.end (/home/yellowtent/box/node_modules/ldapjs/lib/messages/result.js:58:21) at finalSend (/home/yellowtent/box/src/ldap.js:116:9) at /home/yellowtent/box/src/ldap.js:281:17 at Query.<anonymous> (/home/yellowtent/box/src/mailboxdb.js:202:13) at Query.<anonymous> (/home/yellowtent/box/node_modules/mysql/lib/Connection.js:526:10) at Query._callback (/home/yellowtent/box/node_modules/mysql/lib/Connection.js:488:16) at Query.Sequence.end (/home/yellowtent/box/node_modules/mysql/lib/protocol/sequences/Sequence.js:83:24) at Query._handleFinalResultPacket (/home/yellowtent/box/node_modules/mysql/lib/protocol/sequences/Query.js:149:8) at Query.EofPacket (/home/yellowtent/box/node_modules/mysql/lib/protocol/sequences/Query.js:133:8) code: 'EPIPE' }&
2020-07-02T19:00:10.832Z box:ldap 172.18.0.3:36494 unexpected connection error { Error: This socket has been ended by the other party at Socket.writeAfterFIN [as write] (net.js:396:12) at BindResponse.LDAPResult.end (/home/yellowtent/box/node_modules/ldapjs/lib/messages/result.js:58:21) at /home/yellowtent/box/src/ldap.js:633:25 at AsyncWrap.<anonymous> (/home/yellowtent/box/src/users.js:278:21) at AsyncWrap.wrap.ondone (internal/crypto/pbkdf2.js:36:48) code: 'EPIPE' } 2020-07-02T19:00:12.052Z box:ldap 172.18.0.3:39578 unexpected connection error { Error: This socket has been ended by the other party at Socket.writeAfterFIN [as write] (net.js:396:12) at BindResponse.LDAPResult.end (/home/yellowtent/box/node_modules/ldapjs/lib/messages/result.js:58:21) at /home/yellowtent/box/src/ldap.js:633:25 at AsyncWrap.<anonymous> (/home/yellowtent/box/src/users.js:278:21) at AsyncWrap.wrap.ondone (internal/crypto/pbkdf2.js:36:48) code: 'EPIPE' }Then I see emails and everything still flowing so things appear to be operational still, but then closer to the incident time, I see a lot more of these in the logs (several of these within about 10 seconds of each other:
2020-07-02T22:05:22.506Z box:ldap 172.18.0.3:39724 unexpected connection error { Error: This socket has been ended by the other party at Socket.writeAfterFIN [as write] (net.js:396:12) at BindResponse.LDAPResult.end (/home/yellowtent/box/node_modules/ldapjs/lib/messages/result.js:58:21) at /home/yellowtent/box/src/ldap.js:633:25 at AsyncWrap.<anonymous> (/home/yellowtent/box/src/users.js:278:21) at AsyncWrap.wrap.ondone (internal/crypto/pbkdf2.js:36:48) code: 'EPIPE' } 2020-07-02T22:05:22.810Z box:apphealthmonitor app health: 30 alive / 3 dead. 2020-07-02T22:05:23.161Z box:ldap 172.18.0.3:54758 unexpected connection error { Error: This socket has been ended by the other party at Socket.writeAfterFIN [as write] (net.js:396:12) at BindResponse.LDAPResult.end (/home/yellowtent/box/node_modules/ldapjs/lib/messages/result.js:58:21) at /home/yellowtent/box/src/ldap.js:633:25 at AsyncWrap.<anonymous> (/home/yellowtent/box/src/users.js:278:21) at AsyncWrap.wrap.ondone (internal/crypto/pbkdf2.js:36:48) code: 'EPIPE' } 2020-07-02T22:05:25.346Z box:ldap 172.18.0.3:54860 unexpected connection error { Error: This socket has been ended by the other party at Socket.writeAfterFIN [as write] (net.js:396:12) at BindResponse.LDAPResult.end (/home/yellowtent/box/node_modules/ldapjs/lib/messages/result.js:58:21) at /home/yellowtent/box/src/ldap.js:633:25 at AsyncWrap.<anonymous> (/home/yellowtent/box/src/users.js:278:21) at AsyncWrap.wrap.ondone (internal/crypto/pbkdf2.js:36:48) code: 'EPIPE' } 2020-07-02T22:05:26.293Z box:ldap 172.18.0.3:54872 unexpected connection error { Error: This socket has been ended by the other party at Socket.writeAfterFIN [as write] (net.js:396:12) at BindResponse.LDAPResult.end (/home/yellowtent/box/node_modules/ldapjs/lib/messages/result.js:58:21) at /home/yellowtent/box/src/ldap.js:633:25 at AsyncWrap.<anonymous> (/home/yellowtent/box/src/users.js:278:21) at AsyncWrap.wrap.ondone (internal/crypto/pbkdf2.js:36:48) code: 'EPIPE' } 2020-07-02T22:05:27.297Z box:apphealthmonitor app health: 30 alive / 3 dead. 2020-07-02T22:05:28.890Z box:ldap 172.18.0.3:55298 unexpected connection error { Error: This socket has been ended by the other party at Socket.writeAfterFIN [as write] (net.js:396:12) at BindResponse.LDAPResult.end (/home/yellowtent/box/node_modules/ldapjs/lib/messages/result.js:58:21) at /home/yellowtent/box/src/ldap.js:633:25 at AsyncWrap.<anonymous> (/home/yellowtent/box/src/users.js:278:21) at AsyncWrap.wrap.ondone (internal/crypto/pbkdf2.js:36:48) code: 'EPIPE' } {...} 2020-07-02T22:05:32.617Z box:ldap 172.18.0.3:55570 unexpected connection error { Error: This socket has been ended by the other party at Socket.writeAfterFIN [as write] (net.js:396:12) at BindResponse.LDAPResult.end (/home/yellowtent/box/node_modules/ldapjs/lib/messages/result.js:58:21) at /home/yellowtent/box/src/ldap.js:633:25 at AsyncWrap.<anonymous> (/home/yellowtent/box/src/users.js:278:21) at AsyncWrap.wrap.ondone (internal/crypto/pbkdf2.js:36:48) code: 'EPIPE' }Throughout my log from around that time until I rebooted, it seems I have almost a hundred or more of them. Then after reboot, I have similar issues around too many connections:
2020-07-02T23:20:43.547Z box:mailer BoxError: Invalid greeting from server: 421 Too many concurrent connections: 421 Too many concurrent connections at /home/yellowtent/box/src/mailer.js:85:40 at transporter.send.args (/home/yellowtent/box/node_modules/nodemailer/lib/mailer/index.js:226:21) at SMTPConnection.<anonymous> (/home/yellowtent/box/node_modules/nodemailer-smtp-transport/lib/smtp-transport.js:105:20) at Object.onceWrapper (events.js:286:20) at SMTPConnection.emit (events.js:198:13) at SMTPConnection._onError (/home/yellowtent/box/node_modules/smtp-connection/lib/smtp-connection.js:518:10) at SMTPConnection._actionGreeting (/home/yellowtent/box/node_modules/smtp-connection/lib/smtp-connection.js:893:14) at SMTPConnection._processResponse (/home/yellowtent/box/node_modules/smtp-connection/lib/smtp-connection.js:669:16) at SMTPConnection._onData (/home/yellowtent/box/node_modules/smtp-connection/lib/smtp-connection.js:493:10) at Socket.emit (events.js:198:13) 2020-07-02T23:20:43.554Z box:mailer BoxError: Invalid greeting from server: 421 Too many concurrent connections: 421 Too many concurrent connections at /home/yellowtent/box/src/mailer.js:85:40 at transporter.send.args (/home/yellowtent/box/node_modules/nodemailer/lib/mailer/index.js:226:21) at SMTPConnection.<anonymous> (/home/yellowtent/box/node_modules/nodemailer-smtp-transport/lib/smtp-transport.js:105:20) at Object.onceWrapper (events.js:286:20) at SMTPConnection.emit (events.js:198:13) at SMTPConnection._onError (/home/yellowtent/box/node_modules/smtp-connection/lib/smtp-connection.js:518:10) at SMTPConnection._actionGreeting (/home/yellowtent/box/node_modules/smtp-connection/lib/smtp-connection.js:893:14) at SMTPConnection._processResponse (/home/yellowtent/box/node_modules/smtp-connection/lib/smtp-connection.js:669:16) at SMTPConnection._onData (/home/yellowtent/box/node_modules/smtp-connection/lib/smtp-connection.js:493:10) at Socket.emit (events.js:198:13) 2020-07-02T23:20:43.615Z box:mailer BoxError: Invalid greeting from server: 421 Too many concurrent connections: 421 Too many concurrent connections at /home/yellowtent/box/src/mailer.js:85:40 at transporter.send.args (/home/yellowtent/box/node_modules/nodemailer/lib/mailer/index.js:226:21) at SMTPConnection.<anonymous> (/home/yellowtent/box/node_modules/nodemailer-smtp-transport/lib/smtp-transport.js:105:20) at Object.onceWrapper (events.js:286:20) at SMTPConnection.emit (events.js:198:13) at SMTPConnection._onError (/home/yellowtent/box/node_modules/smtp-connection/lib/smtp-connection.js:518:10) at SMTPConnection._actionGreeting (/home/yellowtent/box/node_modules/smtp-connection/lib/smtp-connection.js:893:14) at SMTPConnection._processResponse (/home/yellowtent/box/node_modules/smtp-connection/lib/smtp-connection.js:669:16) at SMTPConnection._onData (/home/yellowtent/box/node_modules/smtp-connection/lib/smtp-connection.js:493:10) at Socket.emit (events.js:198:13) 2020-07-02T23:20:43.967Z box:mailer BoxError: Invalid greeting from server: 421 Too many concurrent connections: 421 Too many concurrent connections at /home/yellowtent/box/src/mailer.js:85:40 at transporter.send.args (/home/yellowtent/box/node_modules/nodemailer/lib/mailer/index.js:226:21) at SMTPConnection.<anonymous> (/home/yellowtent/box/node_modules/nodemailer-smtp-transport/lib/smtp-transport.js:105:20) at Object.onceWrapper (events.js:286:20) at SMTPConnection.emit (events.js:198:13) at SMTPConnection._onError (/home/yellowtent/box/node_modules/smtp-connection/lib/smtp-connection.js:518:10) at SMTPConnection._actionGreeting (/home/yellowtent/box/node_modules/smtp-connection/lib/smtp-connection.js:893:14) at SMTPConnection._processResponse (/home/yellowtent/box/node_modules/smtp-connection/lib/smtp-connection.js:669:16) at SMTPConnection._onData (/home/yellowtent/box/node_modules/smtp-connection/lib/smtp-connection.js:493:10) at Socket.emit (events.js:198:13) 2020-07-02T23:20:43.970Z box:mailer BoxError: Invalid greeting from server: 421 Too many concurrent connections: 421 Too many concurrent connections at /home/yellowtent/box/src/mailer.js:85:40 at transporter.send.args (/home/yellowtent/box/node_modules/nodemailer/lib/mailer/index.js:226:21) at SMTPConnection.<anonymous> (/home/yellowtent/box/node_modules/nodemailer-smtp-transport/lib/smtp-transport.js:105:20) at Object.onceWrapper (events.js:286:20) at SMTPConnection.emit (events.js:198:13) at SMTPConnection._onError (/home/yellowtent/box/node_modules/smtp-connection/lib/smtp-connection.js:518:10) at SMTPConnection._actionGreeting (/home/yellowtent/box/node_modules/smtp-connection/lib/smtp-connection.js:893:14) at SMTPConnection._processResponse (/home/yellowtent/box/node_modules/smtp-connection/lib/smtp-connection.js:669:16) at SMTPConnection._onData (/home/yellowtent/box/node_modules/smtp-connection/lib/smtp-connection.js:493:10) at Socket.emit (events.js:198:13) 2020-07-02T23:20:44.048Z box:mailer BoxError: Invalid greeting from server: 421 Too many concurrent connections: 421 Too many concurrent connections at /home/yellowtent/box/src/mailer.js:85:40 at transporter.send.args (/home/yellowtent/box/node_modules/nodemailer/lib/mailer/index.js:226:21) at SMTPConnection.<anonymous> (/home/yellowtent/box/node_modules/nodemailer-smtp-transport/lib/smtp-transport.js:105:20) at Object.onceWrapper (events.js:286:20) at SMTPConnection.emit (events.js:198:13) at SMTPConnection._onError (/home/yellowtent/box/node_modules/smtp-connection/lib/smtp-connection.js:518:10) at SMTPConnection._actionGreeting (/home/yellowtent/box/node_modules/smtp-connection/lib/smtp-connection.js:893:14) at SMTPConnection._processResponse (/home/yellowtent/box/node_modules/smtp-connection/lib/smtp-connection.js:669:16) at SMTPConnection._onData (/home/yellowtent/box/node_modules/smtp-connection/lib/smtp-connection.js:493:10) at Socket.emit (events.js:198:13)I'm not certain what all is related which is why I threw a bunch in there, but I suspect the main issues are around the "unexpected connection error" and "Too many concurrent connections" error. And I say this because they were all happening around the time of the incident.
This wouldn't be a a sort of DOS attack, would it? Haven't seen those before on this server, definitely not when running Cloudron.
What are the concurrent limits set to out of curiosity? As in, what sort of numbers of connections were too many at this time of the issue?
Unfortunately the logs look like they rolled, but I actually rebooted the server last night for a similar issue where some of my apps that send emails were unable to do so, and worked fine after the reboot. Now this incident today which had a much larger impact than I noticed yesterday, so unclear if they're related but this reliability the past 24 hours if concerning me now and I need to make sure I can answer to my clients who may inquire as to why there was an outage (albeit it was thankfully a short one).
Thank you in advance for any help / assistance / guidance on this matter.
-
I saw exactly the same stack traces in one Cloudron today. I guess you also saw a "2020-07-02T18:28:00.273Z ERROR (node:20686) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 error listeners added. Use emitter.setMaxListeners() to increase limit" somewhere ? It will be right after the code restarted.
I have made a few fixes earlier today for this - https://git.cloudron.io/cloudron/box/-/commit/70743bd2850031d89422dbd77ef07703c5ed09af and https://git.cloudron.io/cloudron/box/-/commit/d1ff8e9d6bdd3f67df3295603b6f6438858b5b65 . So far since I made those changes, that Cloudron has not seen any errors. We will probably make a 5.3.4 with this fix.
Finally, the "Too many concurrent connections" issue is something else. Let me know if you see it again.
-
-
@girish Sounds great, because one of my clients just informed me of this issue again too.
Unfortunately my alerting doesn't seem to be working because I guess the requests are being served fine for the first while just really slow, so I have to improve my alerting down the road here to find these types of issues, because it almost seems like a performance issue for the first few hours then it breaks and needs the restart. -
-
@girish I just double-checked and yes it seems I do. For example:
2020-07-03T17:33:41.781Z box:ldap 172.18.0.40:48204 unexpected connection error { Error: This socket has been ended by the other party at Socket.writeAfterFIN [as write] (net.js:396:12) at SearchResponse.LDAPResult.end (/home/yellowtent/box/node_modules/ldapjs/lib/messages/result.js:58:21) at sendError (/home/yellowtent/box/node_modules/ldapjs/lib/server.js:401:22) at /home/yellowtent/box/node_modules/ldapjs/lib/server.js:418:11 at /home/yellowtent/box/src/ldap.js:262:70 at Query.<anonymous> (/home/yellowtent/box/src/mailboxdb.js:200:46) at Query.<anonymous> (/home/yellowtent/box/node_modules/mysql/lib/Connection.js:526:10) at Query._callback (/home/yellowtent/box/node_modules/mysql/lib/Connection.js:488:16) at Query.Sequence.end (/home/yellowtent/box/node_modules/mysql/lib/protocol/sequences/Sequence.js:83:24) at Query._handleFinalResultPacket (/home/yellowtent/box/node_modules/mysql/lib/protocol/sequences/Query.js:149:8) code: 'EPIPE' }2020-07-03T17:35:01.509Z box:ldap 172.18.0.40:48312 unexpected connection error { Error: This socket has been ended by the other party at Socket.writeAfterFIN [as write] (net.js:396:12) at BindResponse.LDAPResult.end (/home/yellowtent/box/node_modules/ldapjs/lib/messages/result.js:58:21) at /home/yellowtent/box/src/ldap.js:633:25 at AsyncWrap.<anonymous> (/home/yellowtent/box/src/users.js:278:21) at AsyncWrap.wrap.ondone (internal/crypto/pbkdf2.js:36:48) code: 'EPIPE' }2020-07-03T17:39:57.697Z box:ldap 172.18.0.40:51824 unexpected connection error { Error: This socket has been ended by the other party at Socket.writeAfterFIN [as write] (net.js:396:12) at SearchResponse.send (/home/yellowtent/box/node_modules/ldapjs/lib/messages/search_response.js:88:21) at /home/yellowtent/box/src/ldap.js:111:17 at Array.forEach (<anonymous>) at finalSend (/home/yellowtent/box/src/ldap.js:110:17) at /home/yellowtent/box/src/ldap.js:281:17 at Query.<anonymous> (/home/yellowtent/box/src/mailboxdb.js:202:13) at Query.<anonymous> (/home/yellowtent/box/node_modules/mysql/lib/Connection.js:526:10) at Query._callback (/home/yellowtent/box/node_modules/mysql/lib/Connection.js:488:16) at Query.Sequence.end (/home/yellowtent/box/node_modules/mysql/lib/protocol/sequences/Sequence.js:83:24) code: 'EPIPE' } 2020-07-03T17:39:57.710Z box:ldap 172.18.0.40:51824 unexpected connection error { Error: This socket has been ended by the other party at Socket.writeAfterFIN [as write] (net.js:396:12) at SearchResponse.LDAPResult.end (/home/yellowtent/box/node_modules/ldapjs/lib/messages/result.js:58:21) at finalSend (/home/yellowtent/box/src/ldap.js:116:9) at /home/yellowtent/box/src/ldap.js:281:17 at Query.<anonymous> (/home/yellowtent/box/src/mailboxdb.js:202:13) at Query.<anonymous> (/home/yellowtent/box/node_modules/mysql/lib/Connection.js:526:10) at Query._callback (/home/yellowtent/box/node_modules/mysql/lib/Connection.js:488:16) at Query.Sequence.end (/home/yellowtent/box/node_modules/mysql/lib/protocol/sequences/Sequence.js:83:24) at Query._handleFinalResultPacket (/home/yellowtent/box/node_modules/mysql/lib/protocol/sequences/Query.js:149:8)And yes I now also see the error you mentioned around the MaxListeners
2020-07-03T17:40:02.373Z ERROR (node:13987) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 error listeners added. Use emitter.setMaxListeners() to increase limit [ internal/process/warning.js:25:20 ] -
-
@girish Thank you. Are we talking days though or just maybe hours? I am asking only because this seems to be happening daily now and I have to issue credits to my customers for the outages, so I basically just want to know if I should temporarily setup a reboot cron every 12 hours or something or just wait for the update to come later today?
-
-
@girish Sounds good, I see the update. I will install it in a few hours (just need to wait for the "business day" to be done so it has the least impact). I'll monitor it and see what becomes of it. Thanks a lot for the quick help, Girish!
I suppose I could install an agent in the future to look for certain errors and email me, eh? Just thinking about how to improve my alerting for these types of issues going forward.
-
-
@girish Actually funny enough, I was already using that but only testing so it was still on the same server. I actually disabled it temporarily thinking that may be causing the issue since it was setup to poll a few things on the server, and when I saw the "too many concurrent connections" and such it made me wonder if that was why as this issue coincidentally was around the same time as I setup Statping, but I realized the bigger issue I think was that it was really the 5.3.3 version as it was the day after that was installed that the issue was happening, I believe, and I setup Statping on Monday or so before the update.
-
@girish - I just updated my server a bit ago, so we'll see how it holds up. I'll try to monitor it as best I can and will report back.
Out of curiosity, I think it's odd you and I both saw the issue in our own servers about the same day. Is this because of 5.3.3 then, or something different?
