When I try to visit my Magento 2 application, it doesn't respond, it gives a slow white web page trying to load and eventually I get some error from the browser. There is no Magento exception provided. To immediately solve the issue, I restart the server instance and everything is back to normal.
At the time of the issue, I don't know if I could connect through SSH to the server.
This happens every now and then, it is irregular and has happened maybe 3-7 times during this year. It is frustrating as the site can be down for days without me noticing in worst case. Hence, I'm looking for fixing the root cause.
- Apache 2.4.43
- Magento 2.3.5
- PHP 7.3.17
- MySQL 8.0.18
- Debian 4.9
I've looked into some of the logs, but cannot with full certainty determine where the problem starts.
[2020-11-19 19:15:03] setup-cron.ERROR: SQLSTATE[HY000]  No such file or directory   [2020-12-26 09:42:22] update-cron.WARNING: Update is already in progress.   [2020-12-26 09:42:22] update-cron.WARNING: Update is already in progress.   [2020-12-26 09:43:03] setup-cron.ERROR: SQLSTATE[HY000]  No such file or directory   ....
The last message means MySQL is not running.
[Sat Dec 26 09:27:44.489313 2020] [log_config:warn] [pid 5091:tid 140160855422720] (28)No space left on device: [client 127.0.0.1:60560] AH00646: Error writing to logs/access_log ... [Sat Dec 26 09:27:47.889486 2020] [log_config:warn] [pid 5091:tid 140160830244608] (28)No space left on device: [client 127.0.0.1:60560] AH00646: Error writing to logs/access_log [Sat Dec 26 09:27:[Sat Dec 26 09:42:22.852498 2020] [proxy_fcgi:error] [pid 5091:tid 140160771495680] (70007)The timeout specified has expired: [client 127.0.0.1:60794] AH01075: Error dispatching request to :81: (polling) .... [Sat Dec 26 09:48:58.853101 2020] [proxy_fcgi:error] [pid 5091:tid 140160721139456] (70007)The timeout specified has expired: [client 127.0.0.1:60910] AH01075: Error dispatching request to :81: (polling) [Sat Dec 26 10:50:37.829758 2020] [mpm_event:error] [pid 2432:tid 140161215820480] AH10159: server is within MinSpareThreads of MaxRequestWorkers, consider raising the MaxRequestWorkers setting [Sat Dec 26 11:30:38.554952 2020] [mpm_event:error] [pid 2432:tid 140161215820480] AH00484: server reached MaxRequestWorkers setting, consider raising the MaxRequestWorkers setting [Sun Dec 27 00:00:06.419966 2020] [mpm_event:notice] [pid 2432:tid 140161215820480] AH00493: SIGUSR1 received. Doing graceful restart
AT 09.27, Apache is out of space for log writing. Within the coming hours, I guess, there are quite many requests to the server which it doesn't manage to serve, due to non-responding MySQL, then I guess the restart it just part of normal operation.
MySQL mysqld.log (there is not much more than this, I would have expected that there were something before 09.46)
2020-12-26T09:46:31.905912Z 1 [Warning] [MY-012637] [InnoDB] 1048576 bytes should have been written. Only 901120 bytes written. Retrying for the remaining bytes. 2020-12-26T09:46:31.906170Z 1 [Warning] [MY-012638] [InnoDB] Retry attempts for writing partial data failed. 2020-12-26T09:46:31.906305Z 1 [ERROR] [MY-012639] [InnoDB] Write to file ./ibtmp1 failed at offset 11534336, 1048576 bytes should have been written, only 901120 were written. Operating system error number 28. Check that your OS and file system support files of this size. Check also that the disk is not full or a disk quota exceeded. 2020-12-26T09:46:31.906442Z 1 [ERROR] [MY-012640] [InnoDB] Error number 28 means 'No space left on device' 2020-12-26T09:46:31.906704Z 1 [ERROR] [MY-012267] [InnoDB] Could not set the file size of './ibtmp1'. Probably out of disk space 2020-12-26T09:46:31.906865Z 1 [ERROR] [MY-012926] [InnoDB] Unable to create the shared innodb_temporary. 2020-12-26T09:46:31.907013Z 1 [ERROR] [MY-012930] [InnoDB] Plugin initialization aborted with error Generic error. 2020-12-26T09:46:32.085740Z 1 [ERROR] [MY-010334] [Server] Failed to initialize DD Storage Engine 2020-12-26T09:46:32.086048Z 0 [ERROR] [MY-010020] [Server] Data Dictionary initialization failed. 2020-12-26T09:46:32.086347Z 0 [ERROR] [MY-010119] [Server] Aborting 2020-12-26T09:46:32.087033Z 0 [System] [MY-010910] [Server] /opt/bitnami/mysql/bin/mysqld.bin: Shutdown complete (mysqld 8.0.18) MySQL Community Server - GPL.
Again, there is no error message I can find before 09.46, and the connection is failing at 09.43 according to Magento update.log. However, if disk is full, it might explain there is no error message written.
Leaning into disk space being the issue
With the above error messages, I'm tempted to conclude that disk space is the issue.
df -h /dev/sda1 gives below output.
Filesystem Size Used Avail Use% Mounted on /dev/sda1 15G 14G 980M 94% /
If I presume that space is the issue:
- Why would a restart of the server give more space? Is it log rotation with compressed logs? Something else?
- Is there any other way I determine that lack of disk space is the issue for Magento?