After a server restart, while MySQL shows to be running, it's totally inaccessible and everything i've tried to do to rectify hasn't resolved the issue.
I'm going to try to make this has easy to read as possible, without missing any details. I've been battling this for two days now.
Server Setup:
- Ubuntu 18.04.2 LTS
- MySQL 5.7.27
Important Contants:
- I have not updated any software/packages since the start of this process
- MySQL has ran absolutely fine for many many years with this setup
- All MySQL configs are written into the files to ensure they load on restart
- MySQL always starts on server boot.
- There is plenty of space on the server
- This is not a big database (maybe 1GB).
- This is not a high-traffic server (maybe 5-10 users at once max).
- Memory is not depleted and there is plenty of swap available too.
Chapter 1: Let's Restart the Server, for fun!
After debugging some fairly simple coding issues, I decided to restart the server, mainly because it hadn't been restarted in over a year and thought it would be a good idea to clear out all the old stuff that might be hanging around.
Chapter 2: The Server Restart(s)
The first restart was fairly routine. I use Google Cloud Platform and have learned from past experience to always manually shut down mysql before restarting via GCP's dashboard. So I ran, as root, service mysql stop and waited for it to shut down (maybe 30 seconds). I then proceeded to Stop, and then Start the Compute Engine from GCP's dashboard. This took quite a long time, but expected, so there was no panic. I've known it to take up to 1 hour at times (i'm running a tiny f1-micro and have been doing so successfully with this database for a few years now).
When the server finally came back, while all the services were running, mysql wasn't accessible whatsoever. If I tried to connect via my website, MySQL Workbench or even directly in shell as root, it was hang and timeout. With only 'timeout' errors.
The strangest part about it was when I tried to connect as root via shell simply typing mysql, it would hang, then it would go to the mysql prompt, but this seemed to be caused by a restart every 15 minutes due to the service not starting correctly.
I tried doing a few more restarts of the server as mentioned above in hope it would 'fix itself'...nope.
I tried manually stopped and starting MySQL, using service mysql stop and service mysql start. This was also interesting. The commands would take many minutes to complete, even though I could see mysqld running in top and syslog and mysql's error log showing that it's running. I would eventually get a timeout/failed message back.
Chapter 3: Removing the ib_logfile(s)
So, I decided that maybe MySQL was hanging because it was doing some sort of InnoDB recovery of some sort as I have seen this before. I made sure that the database had stopped successfully, and then renamed the ib_logfile, which I believe MySQL users on startup to keep the database up-to-date upon shutdown->restart. I then cycled MySQL as mentioned above, still the same result. Upon looking closing into the syslog, I noticed some mention of apparmor not having permissions. Which leads us to Chatper 4...
Chapter 4: Disabling AppArmor
AppArmor was new to me. I didn't recall this being a part of anything before. Researching the apparmor errors I received, I came across a number of stackoverflow posts talking about editing the apparmor profile to give it access. So, I went for it and while that fixed those errors, it eventually got to an error I could not figure out how to resolve:
kernel: [11834.156430] audit: type=1400 audit(1623157780.551:136): apparmor="DENIED" operation="capable" profile="/usr/sbin/mysqld" pid=5245 comm="mysqld" capability=2 capname="dac_read_search"
Therefore, I decided to look at a way to remove AppArmor from the equation (https://askubuntu.com/questions/1144497/how-to-disable-apparmor-for-mysql). Still no improvement.
Chapter 5: StackExchange HELP!
So here I am, stuck and exhausted all the avenues I can find without totally uninstall and re-installing the database, which I don't want to do.
My mysql error.log always looks like this:
2021-06-08T17:55:41.591752Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2021-06-08T17:55:41.594058Z 0 [Note] /usr/sbin/mysqld (mysqld 5.7.27-0ubuntu0.18.04.1-log) starting as process 10299 ...
2021-06-08T17:55:41.599049Z 0 [Note] InnoDB: PUNCH HOLE support available
2021-06-08T17:55:41.599326Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2021-06-08T17:55:41.599401Z 0 [Note] InnoDB: Uses event mutexes
2021-06-08T17:55:41.599453Z 0 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
2021-06-08T17:55:41.599502Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2021-06-08T17:55:41.599557Z 0 [Note] InnoDB: Using Linux native AIO
2021-06-08T17:55:41.599909Z 0 [Note] InnoDB: Number of pools: 1
2021-06-08T17:55:41.600093Z 0 [Note] InnoDB: Using CPU crc32 instructions
2021-06-08T17:55:41.616337Z 0 [Note] InnoDB: Initializing buffer pool, total size = 64M, instances = 1, chunk size = 64M
2021-06-08T17:55:41.621572Z 0 [Note] InnoDB: Completed initialization of buffer pool
2021-06-08T17:55:41.635534Z 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2021-06-08T17:55:41.767140Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
2021-06-08T17:55:42.359183Z 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2021-06-08T17:55:42.359441Z 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2021-06-08T17:55:42.483637Z 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2021-06-08T17:55:42.484566Z 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active.
2021-06-08T17:55:42.484586Z 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active.
2021-06-08T17:55:42.484960Z 0 [Note] InnoDB: Waiting for purge to start
2021-06-08T17:55:42.535229Z 0 [Note] InnoDB: 5.7.27 started; log sequence number 556158661
2021-06-08T17:55:42.535816Z 0 [Note] Plugin 'FEDERATED' is disabled.
2021-06-08T17:55:42.536173Z 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
2021-06-08T17:55:42.680632Z 0 [Warning] Failed to set up SSL because of the following SSL library error: SSL context is not usable without certificate and private key
2021-06-08T17:55:42.680966Z 0 [Note] Server hostname (bind-address): '127.0.0.1'; port: 3306
2021-06-08T17:55:42.681085Z 0 [Note] - '127.0.0.1' resolves to '127.0.0.1';
2021-06-08T17:55:42.681173Z 0 [Note] Server socket created on IP: '127.0.0.1'.
2021-06-08T17:55:42.995012Z 0 [Note] InnoDB: Buffer pool(s) load completed at 210608 17:55:42
2021-06-08T18:11:12.650489Z 0 [Note] Event Scheduler: Loaded 0 events
2021-06-08T18:11:12.659131Z 0 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.7.27-0ubuntu0.18.04.1-log' socket: '/var/run/mysqld/mysqld.sock' port: 3306 (Ubuntu)
2021-06-08T18:11:12.707920Z 0 [Note] Giving 5 client threads a chance to die gracefully
2021-06-08T18:11:12.708094Z 0 [Note] Shutting down slave threads
2021-06-08T18:11:12.766810Z 0 [Note] Forcefully disconnecting 0 remaining clients
2021-06-08T18:11:12.766993Z 0 [Note] Event Scheduler: Purging the queue. 0 events
2021-06-08T18:11:12.767159Z 0 [Note] Binlog end
2021-06-08T18:11:12.768176Z 0 [Note] Shutting down plugin 'auth_socket'
2021-06-08T18:11:12.768328Z 0 [Note] Shutting down plugin 'ngram'
2021-06-08T18:11:12.768388Z 0 [Note] Shutting down plugin 'partition'
2021-06-08T18:11:12.768441Z 0 [Note] Shutting down plugin 'BLACKHOLE'
2021-06-08T18:11:12.768492Z 0 [Note] Shutting down plugin 'ARCHIVE'
2021-06-08T18:11:12.768535Z 0 [Note] Shutting down plugin 'PERFORMANCE_SCHEMA'
2021-06-08T18:11:12.768609Z 0 [Note] Shutting down plugin 'MRG_MYISAM'
2021-06-08T18:11:12.768653Z 0 [Note] Shutting down plugin 'MyISAM'
2021-06-08T18:11:12.768699Z 0 [Note] Shutting down plugin 'INNODB_SYS_VIRTUAL'
2021-06-08T18:11:12.768744Z 0 [Note] Shutting down plugin 'INNODB_SYS_DATAFILES'
2021-06-08T18:11:12.768786Z 0 [Note] Shutting down plugin 'INNODB_SYS_TABLESPACES'
2021-06-08T18:11:12.768828Z 0 [Note] Shutting down plugin 'INNODB_SYS_FOREIGN_COLS'
2021-06-08T18:11:12.768871Z 0 [Note] Shutting down plugin 'INNODB_SYS_FOREIGN'
2021-06-08T18:11:12.768914Z 0 [Note] Shutting down plugin 'INNODB_SYS_FIELDS'
2021-06-08T18:11:12.768956Z 0 [Note] Shutting down plugin 'INNODB_SYS_COLUMNS'
2021-06-08T18:11:12.768997Z 0 [Note] Shutting down plugin 'INNODB_SYS_INDEXES'
2021-06-08T18:11:12.769041Z 0 [Note] Shutting down plugin 'INNODB_SYS_TABLESTATS'
2021-06-08T18:11:12.769083Z 0 [Note] Shutting down plugin 'INNODB_SYS_TABLES'
2021-06-08T18:11:12.769125Z 0 [Note] Shutting down plugin 'INNODB_FT_INDEX_TABLE'
2021-06-08T18:11:12.769166Z 0 [Note] Shutting down plugin 'INNODB_FT_INDEX_CACHE'
2021-06-08T18:11:12.769208Z 0 [Note] Shutting down plugin 'INNODB_FT_CONFIG'
2021-06-08T18:11:12.769250Z 0 [Note] Shutting down plugin 'INNODB_FT_BEING_DELETED'
2021-06-08T18:11:12.769300Z 0 [Note] Shutting down plugin 'INNODB_FT_DELETED'
2021-06-08T18:11:12.769342Z 0 [Note] Shutting down plugin 'INNODB_FT_DEFAULT_STOPWORD'
2021-06-08T18:11:12.769384Z 0 [Note] Shutting down plugin 'INNODB_METRICS'
2021-06-08T18:11:12.769426Z 0 [Note] Shutting down plugin 'INNODB_TEMP_TABLE_INFO'
2021-06-08T18:11:12.769486Z 0 [Note] Shutting down plugin 'INNODB_BUFFER_POOL_STATS'
2021-06-08T18:11:12.769553Z 0 [Note] Shutting down plugin 'INNODB_BUFFER_PAGE_LRU'
2021-06-08T18:11:12.769596Z 0 [Note] Shutting down plugin 'INNODB_BUFFER_PAGE'
2021-06-08T18:11:12.769638Z 0 [Note] Shutting down plugin 'INNODB_CMP_PER_INDEX_RESET'
2021-06-08T18:11:12.769683Z 0 [Note] Shutting down plugin 'INNODB_CMP_PER_INDEX'
2021-06-08T18:11:12.769725Z 0 [Note] Shutting down plugin 'INNODB_CMPMEM_RESET'
2021-06-08T18:11:12.769766Z 0 [Note] Shutting down plugin 'INNODB_CMPMEM'
2021-06-08T18:11:12.769807Z 0 [Note] Shutting down plugin 'INNODB_CMP_RESET'
2021-06-08T18:11:12.769849Z 0 [Note] Shutting down plugin 'INNODB_CMP'
2021-06-08T18:11:12.769892Z 0 [Note] Shutting down plugin 'INNODB_LOCK_WAITS'
2021-06-08T18:11:12.769933Z 0 [Note] Shutting down plugin 'INNODB_LOCKS'
2021-06-08T18:11:12.769975Z 0 [Note] Shutting down plugin 'INNODB_TRX'
2021-06-08T18:11:12.770017Z 0 [Note] Shutting down plugin 'InnoDB'
2021-06-08T18:11:12.770349Z 0 [Note] InnoDB: FTS optimize thread exiting.
2021-06-08T18:11:12.770596Z 0 [Note] InnoDB: Starting shutdown...
2021-06-08T18:11:12.871037Z 0 [Note] InnoDB: Dumping buffer pool(s) to /var/lib/mysql/ib_buffer_pool
2021-06-08T18:11:12.878360Z 0 [Note] InnoDB: Buffer pool(s) dump completed at 210608 18:11:12
2021-06-08T18:11:14.577043Z 0 [Note] InnoDB: Shutdown completed; log sequence number 556158689
2021-06-08T18:11:14.585803Z 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2021-06-08T18:11:14.585996Z 0 [Note] Shutting down plugin 'MEMORY'
2021-06-08T18:11:14.586054Z 0 [Note] Shutting down plugin 'CSV'
2021-06-08T18:11:14.586108Z 0 [Note] Shutting down plugin 'sha256_password'
2021-06-08T18:11:14.586161Z 0 [Note] Shutting down plugin 'mysql_native_password'
2021-06-08T18:11:14.636915Z 0 [Note] Shutting down plugin 'binlog'
2021-06-08T18:11:14.715404Z 0 [Note] /usr/sbin/mysqld: Shutdown complete
2021-06-08T18:11:16.187617Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2021-06-08T18:11:16.190347Z 0 [Note] /usr/sbin/mysqld (mysqld 5.7.27-0ubuntu0.18.04.1-log) starting as process 10533 ...
2021-06-08T18:11:16.195635Z 0 [Note] InnoDB: PUNCH HOLE support available
2021-06-08T18:11:16.195881Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2021-06-08T18:11:16.195946Z 0 [Note] InnoDB: Uses event mutexes
2021-06-08T18:11:16.195999Z 0 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
2021-06-08T18:11:16.196080Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2021-06-08T18:11:16.196136Z 0 [Note] InnoDB: Using Linux native AIO
2021-06-08T18:11:16.196604Z 0 [Note] InnoDB: Number of pools: 1
2021-06-08T18:11:16.196855Z 0 [Note] InnoDB: Using CPU crc32 instructions
2021-06-08T18:11:16.231010Z 0 [Note] InnoDB: Initializing buffer pool, total size = 64M, instances = 1, chunk size = 64M
2021-06-08T18:11:16.258135Z 0 [Note] InnoDB: Completed initialization of buffer pool
2021-06-08T18:11:16.279826Z 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2021-06-08T18:11:16.407111Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
2021-06-08T18:11:16.779664Z 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2021-06-08T18:11:16.779986Z 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2021-06-08T18:11:16.899999Z 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2021-06-08T18:11:16.900886Z 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active.
2021-06-08T18:11:16.900908Z 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active.
2021-06-08T18:11:16.901270Z 0 [Note] InnoDB: Waiting for purge to start
2021-06-08T18:11:16.951472Z 0 [Note] InnoDB: 5.7.27 started; log sequence number 556158689
2021-06-08T18:11:16.952148Z 0 [Note] Plugin 'FEDERATED' is disabled.
2021-06-08T18:11:16.952543Z 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
2021-06-08T18:11:17.062344Z 0 [Warning] Failed to set up SSL because of the following SSL library error: SSL context is not usable without certificate and private key
2021-06-08T18:11:17.062517Z 0 [Note] Server hostname (bind-address): '127.0.0.1'; port: 3306
2021-06-08T18:11:17.062588Z 0 [Note] - '127.0.0.1' resolves to '127.0.0.1';
2021-06-08T18:11:17.062714Z 0 [Note] Server socket created on IP: '127.0.0.1'.
2021-06-08T18:11:17.332974Z 0 [Note] InnoDB: Buffer pool(s) load completed at 210608 18:11:17
My Syslog now looks like this:
un 8 17:39:22 instance-1 systemd[1]: Starting MySQL Community Server...
Jun 8 17:45:32 instance-1 systemd[1]: Started Session 73 of user davidburleson.
Jun 8 17:49:22 instance-1 systemd[1]: mysql.service: Start operation timed out. Terminating.
Jun 8 17:55:40 instance-1 systemd[1]: mysql.service: Failed with result 'timeout'.
Jun 8 17:55:41 instance-1 systemd[1]: Failed to start MySQL Community Server.
Jun 8 17:55:41 instance-1 systemd[1]: mysql.service: Service hold-off time over, scheduling restart.
Jun 8 17:55:41 instance-1 systemd[1]: mysql.service: Scheduled restart job, restart counter is at 2.
Jun 8 17:55:41 instance-1 systemd[1]: Stopped MySQL Community Server.
Jun 8 17:55:41 instance-1 systemd[1]: Starting MySQL Community Server...
Jun 8 18:05:41 instance-1 systemd[1]: mysql.service: Start operation timed out. Terminating.
Jun 8 18:08:06 instance-1 snapd[947]: storehelpers.go:551: cannot refresh: snap has no updates available: "core", "core18", "google-cloud-sdk"
Jun 8 18:09:02 instance-1 CRON[10391]: (root) CMD ( [ -x /usr/lib/php/sessionclean ] && if [ ! -d /run/systemd/system ]; then /usr/lib/php/sessionclean; fi)
Jun 8 18:09:39 instance-1 systemd[1]: Starting Clean php session files...
Jun 8 18:10:51 instance-1 systemd[1]: Started Clean php session files.
Jun 8 18:11:14 instance-1 systemd[1]: mysql.service: Failed with result 'timeout'.
Jun 8 18:11:15 instance-1 systemd[1]: Failed to start MySQL Community Server.
Jun 8 18:11:15 instance-1 systemd[1]: mysql.service: Service hold-off time over, scheduling restart.
Jun 8 18:11:15 instance-1 systemd[1]: mysql.service: Scheduled restart job, restart counter is at 3.
Jun 8 18:11:15 instance-1 systemd[1]: Stopped MySQL Community Server.
Jun 8 18:11:15 instance-1 systemd[1]: Starting MySQL Community Server...
Jun 8 18:21:16 instance-1 systemd[1]: mysql.service: Start operation timed out. Terminating.
Every time I try running as root mysql, service mysql start, service mysql stop, service mysql status and even the mysqladmin and direct /etc/init.d/mysql commands, they all hang until timeout.
What else might I be missing?
