[우분투 서버 에러 사례] Job for mariadb.service failed because the control process exited with error code.

밤이 늦어 잠에 드려고 하는데 사이트에 이상이 생겼다. 갑자기 한 서버에 입주한 모든 사이트들이 접속하지 못하는 것..

문제가 생겼음을 알고 침대에서 일어나 1시간정도 삽질해서 문제를 해결했는데요. 이 과정을 기록 삼아 간단히 정리해 봤다.

아주 다행히도 문제는 서버 용량 부족으로 인해서 DB가 기록이불가능해지자 다운되어버린 것이었다. 그러므로 용량을 확보함으로써 이 문제를 해결할 수 있었다.

서버가 문제가 생기면 항상 긴장하기 마련이다. 이 어려운 서버라는 괴물을 상대로 해결가능할까? 아니면 며칠동안 작업본을 날리고 snapshot 백업본으로 서버를 되살려야할까? 그러면 그 정도만 희생을 하면 문제를 해결할 수 있을까 아니면 극적인 해결 방안은 없을까?

DB에서 문제가 발생하다.

사이트에 접속하면 DB 에러라고 메세지가 뜬다…. 이것은 무엇인지? 어떻하지? 고민하다..다음과 같은 액션을 취했다.

• 먼저 현재 서버상태를 그대로 백업하는 snapshot을 진행(30분 소요)
• 각 사이트들의 DB가 백업 받았는지 확인. 일부는 2시간 전, 일부는 20분전에 백업받았음 그 정도는 어느 정도 안정적으로 백업 시스템이 작동하고 있다고 봄.
  그 백업 DB를 확보(PC로 저장해 FTP로 올릴 수 있도록 준비
• 에러 메세지 확인을 위해 log를 살펴봄 그런데 MariaDB관련 아무런 log가 없음. SQLDB 관련해 있는데 해독할 수 없는 0과 1이라는 디지탈 자료라 도움이 안됨 그리고 시스템 관련 Log에서고 도움이 될 log 메세지가 없음
• 서버를 부재팅해보고, 웹서버나 DB 등을 다시 부팅해 봄
  service nginx restart && service mysql restart && service php7.3-fpm restart
  -> mysql을 다시 시작하지 못함
  이때 나오는 각종 메세지는 아래 참조
  Job for mariadb.service failed because the control process exited with error code.

# systemctl status mariadb.service
● mariadb.service - MariaDB 10.4.12 database server
   Loaded: loaded (/lib/systemd/system/mariadb.service; enabled; vendor preset: enabled)
  Drop-In: /etc/systemd/system/mariadb.service.d
           └─migrated-from-my.cnf-settings.conf
   Active: failed (Result: exit-code) since Mon 2020-02-17 02:27:56 KST; 26s ago
     Docs: man:mysqld(8)
           https://mariadb.com/kb/en/library/systemd/
  Process: 1839 ExecStart=/usr/sbin/mysqld $MYSQLD_OPTS $_WSREP_NEW_CLUSTER $_WSREP_START_POSITION (code=exited, status=1/FAILURE)
  Process: 1684 ExecStartPre=/bin/sh -c [ ! -e /usr/bin/galera_recovery ] && VAR= ||   VAR=`/usr/bin/galera_recovery`; [ $? -eq 0 ]   && syste
  Process: 1675 ExecStartPre=/bin/sh -c systemctl unset-environment _WSREP_START_POSITION (code=exited, status=0/SUCCESS)
  Process: 1666 ExecStartPre=/usr/bin/install -m 755 -o mysql -g root -d /var/run/mysqld (code=exited, status=0/SUCCESS)
 Main PID: 1839 (code=exited, status=1/FAILURE)
   Status: "MariaDB server is down"

Feb 17 02:27:56 ownergolf mysqld[1839]: 2020-02-17  2:27:56 0 [Note] InnoDB: Starting shutdown...
Feb 17 02:27:56 ownergolf mysqld[1839]: 2020-02-17  2:27:56 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
Feb 17 02:27:56 ownergolf mysqld[1839]: 2020-02-17  2:27:56 0 [ERROR] Plugin 'InnoDB' init function returned error.
Feb 17 02:27:56 ownergolf mysqld[1839]: 2020-02-17  2:27:56 0 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
Feb 17 02:27:56 ownergolf mysqld[1839]: 2020-02-17  2:27:56 0 [Note] Plugin 'FEEDBACK' is disabled.
Feb 17 02:27:56 ownergolf mysqld[1839]: 2020-02-17  2:27:56 0 [ERROR] Unknown/unsupported storage engine: InnoDB
Feb 17 02:27:56 ownergolf mysqld[1839]: 2020-02-17  2:27:56 0 [ERROR] Aborting
Feb 17 02:27:56 ownergolf systemd[1]: mariadb.service: Main process exited, code=exited, status=1/FAILURE
Feb 17 02:27:56 ownergolf systemd[1]: mariadb.service: Failed with result 'exit-code'.
Feb 17 02:27:56 ownergolf systemd[1]: Failed to start MariaDB 10.4.12 database server.Code language: PHP (php)

• 구글 검색을 해보았지만 별 도움이 없었음

용량 확인

에러 메세지에 아래와 같은 내용이 있길래 용량을 확인하기로 함

Feb 17 02:27:56 ownergolf mysqld[1839]: 2020-02-17  2:27:56 0 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.Code language: PHP (php)

아래처럼 용량을 확인하니 물리 용량이 하나도 없다.. 결국 문제는 데이타베이스를 저장할 용량이 어뵤었기 때문에 데이타베이스가 죽어 버린 것

# df -h
Filesystem      Size  Used Avail Use% Mounted on
udev            1.9G     0  1.9G   0% /dev
tmpfs           395M  644K  394M   1% /run
/dev/vda1       126G  120G     0 100% /
tmpfs           2.0G     0  2.0G   0% /dev/shm
tmpfs           5.0M     0  5.0M   0% /run/lock
tmpfs           2.0G     0  2.0G   0% /sys/fs/cgroup
tmpfs           512M     0  512M   0% /dev/shm/fasCode language: PHP (php)

갑자기 용량이 부족해진 원인은 백업본을 10일치를 저장하다보니 디스크 용량이 부족하게 되었음.. 우선은 백업본을 삭제해 용량을 확보했음

나중에 보관 기간을 줄이든지 아니면 백업 대상을 조정할 필요가 있을 듯…

용량 정리 후 서버 용향을 확인하니 아래와 같다..

df -h
Filesystem      Size  Used Avail Use% Mounted on
udev            1.9G     0  1.9G   0% /dev
tmpfs           395M  644K  394M   1% /run
/dev/vda1       126G   63G   58G  53% /
tmpfs           2.0G     0  2.0G   0% /dev/shm
tmpfs           5.0M     0  5.0M   0% /run/lock
tmpfs           2.0G     0  2.0G   0% /sys/fs/cgroup
tmpfs           512M     0  512M   0% /dev/shm/fastcgi
tmpfs           395M     0  395M   0% /run/user/0
Code language: PHP (php)

DB 재가동

이제 문제가 해결되었다고 판단되어 데이타베이스를 재가동했다.

특별한 에러 메세지없이 잘 작동되는듯..

# service mariadb restart; journalctl -xe
Feb 17 03:06:29 ownergolf mysqld[3567]: 2020-02-17  3:06:29 0 [Note] InnoDB: Using Linux native AIO
Feb 17 03:06:29 ownergolf mysqld[3567]: 2020-02-17  3:06:29 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
Feb 17 03:06:29 ownergolf mysqld[3567]: 2020-02-17  3:06:29 0 [Note] InnoDB: Uses event mutexes
Feb 17 03:06:29 ownergolf mysqld[3567]: 2020-02-17  3:06:29 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
Feb 17 03:06:29 ownergolf mysqld[3567]: 2020-02-17  3:06:29 0 [Note] InnoDB: Number of pools: 1
Feb 17 03:06:29 ownergolf mysqld[3567]: 2020-02-17  3:06:29 0 [Note] InnoDB: Using SSE2 crc32 instructions
Feb 17 03:06:29 ownergolf mysqld[3567]: 2020-02-17  3:06:29 0 [Note] mysqld: O_TMPFILE is not supported on /tmp (disabling future attempts)
Feb 17 03:06:29 ownergolf mysqld[3567]: 2020-02-17  3:06:29 0 [Note] InnoDB: Initializing buffer pool, total size = 256M, instances = 1, chunk
Feb 17 03:06:29 ownergolf mysqld[3567]: 2020-02-17  3:06:29 0 [Note] InnoDB: Completed initialization of buffer pool
Feb 17 03:06:29 ownergolf mysqld[3567]: 2020-02-17  3:06:29 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread p
Feb 17 03:06:29 ownergolf mysqld[3567]: 2020-02-17  3:06:29 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=28287516216
Feb 17 03:06:30 ownergolf mysqld[3567]: 2020-02-17  3:06:30 0 [Note] InnoDB: Transaction 10251199 was in the XA prepared state.
Feb 17 03:06:30 ownergolf mysqld[3567]: 2020-02-17  3:06:30 0 [Note] InnoDB: Transaction 10251190 was in the XA prepared state.
Feb 17 03:06:30 ownergolf mysqld[3567]: 2020-02-17  3:06:30 0 [Note] InnoDB: Transaction 10251191 was in the XA prepared state.
Feb 17 03:06:30 ownergolf mysqld[3567]: 2020-02-17  3:06:30 0 [Note] InnoDB: Transaction 10251193 was in the XA prepared state.
Feb 17 03:06:30 ownergolf mysqld[3567]: 2020-02-17  3:06:30 0 [Note] InnoDB: 4 transaction(s) which must be rolled back or cleaned up in total
Feb 17 03:06:30 ownergolf mysqld[3567]: 2020-02-17  3:06:30 0 [Note] InnoDB: Trx id counter is 10251200
Feb 17 03:06:30 ownergolf mysqld[3567]: 2020-02-17  3:06:30 0 [Note] InnoDB: Last binlog file '/var/log/mysql/mariadb-bin.000119', position 17
Feb 17 03:06:30 ownergolf mysqld[3567]: 2020-02-17  3:06:30 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
Feb 17 03:06:30 ownergolf mysqld[3567]: 2020-02-17  3:06:30 0 [Note] InnoDB: Starting in background the rollback of recovered transactions
Feb 17 03:06:30 ownergolf mysqld[3567]: 2020-02-17  3:06:30 0 [Note] InnoDB: Rollback of non-prepared transactions completed
Feb 17 03:06:30 ownergolf mysqld[3567]: 2020-02-17  3:06:30 0 [Note] InnoDB: Creating shared tablespace for temporary tables
Feb 17 03:06:30 ownergolf mysqld[3567]: 2020-02-17  3:06:30 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the fil
Feb 17 03:06:30 ownergolf mysqld[3567]: 2020-02-17  3:06:30 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
Feb 17 03:06:30 ownergolf mysqld[3567]: 2020-02-17  3:06:30 0 [Note] InnoDB: Waiting for purge to start
Feb 17 03:06:30 ownergolf mysqld[3567]: 2020-02-17  3:06:30 0 [Note] InnoDB: 10.4.12 started; log sequence number 28287516225; transaction id 
Feb 17 03:06:30 ownergolf mysqld[3567]: 2020-02-17  3:06:30 0 [Note] Plugin 'FEEDBACK' is disabled.
Feb 17 03:06:30 ownergolf mysqld[3567]: 2020-02-17  3:06:30 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
Feb 17 03:06:30 ownergolf mysqld[3567]: 2020-02-17  3:06:30 0 [Note] Recovering after a crash using /var/log/mysql/mariadb-bin
Feb 17 03:06:30 ownergolf mysqld[3567]: 2020-02-17  3:06:30 0 [ERROR] Error in Log_event::read_log_event(): 'Event truncated', data_len: 350, 
Feb 17 03:06:30 ownergolf mysqld[3567]: 2020-02-17  3:06:30 0 [Note] Starting crash recovery...
Feb 17 03:06:30 ownergolf mysqld[3567]: 2020-02-17  3:06:30 0 [Note] InnoDB: Starting recovery for XA transactions...
Feb 17 03:06:30 ownergolf mysqld[3567]: 2020-02-17  3:06:30 0 [Note] InnoDB: Transaction 10251193 in prepared state after recovery
Feb 17 03:06:30 ownergolf mysqld[3567]: 2020-02-17  3:06:30 0 [Note] InnoDB: Transaction contains changes to 1 rows
Feb 17 03:06:30 ownergolf mysqld[3567]: 2020-02-17  3:06:30 0 [Note] InnoDB: Transaction 10251190 in prepared state after recovery
Feb 17 03:06:30 ownergolf mysqld[3567]: 2020-02-17  3:06:30 0 [Note] InnoDB: Transaction contains changes to 1 rows
Feb 17 03:06:30 ownergolf mysqld[3567]: 2020-02-17  3:06:30 0 [Note] InnoDB: Transaction 10251199 in prepared state after recovery
Feb 17 03:06:30 ownergolf mysqld[3567]: 2020-02-17  3:06:30 0 [Note] InnoDB: Transaction contains changes to 1 rows
Feb 17 03:06:30 ownergolf mysqld[3567]: 2020-02-17  3:06:30 0 [Note] InnoDB: Transaction 10251191 in prepared state after recovery
Feb 17 03:06:30 ownergolf mysqld[3567]: 2020-02-17  3:06:30 0 [Note] InnoDB: Transaction contains changes to 1 rows
Feb 17 03:06:30 ownergolf mysqld[3567]: 2020-02-17  3:06:30 0 [Note] InnoDB: 4 transactions in prepared state after recovery
Feb 17 03:06:30 ownergolf mysqld[3567]: 2020-02-17  3:06:30 0 [Note] Found 4 prepared transaction(s) in InnoDB
Feb 17 03:06:30 ownergolf mysqld[3567]: 2020-02-17  3:06:30 0 [Note] Crash recovery finished.
Feb 17 03:06:30 ownergolf mysqld[3567]: 2020-02-17  3:06:30 0 [Note] InnoDB: Buffer pool(s) load completed at 200217  3:06:30
Feb 17 03:06:30 ownergolf mysqld[3567]: 2020-02-17  3:06:30 0 [Note] Server socket created on IP: '127.0.0.1'.
Feb 17 03:06:30 ownergolf mysqld[3567]: 2020-02-17  3:06:30 0 [Note] Reading of all Master_info entries succeeded
Feb 17 03:06:30 ownergolf mysqld[3567]: 2020-02-17  3:06:30 0 [Note] Added new Master_info '' to hash table
Feb 17 03:06:30 ownergolf mysqld[3567]: 2020-02-17  3:06:30 0 [Note] /usr/sbin/mysqld: ready for connections.
Feb 17 03:06:30 ownergolf mysqld[3567]: Version: '10.4.12-MariaDB-1:10.4.12+maria~bionic-log'  socket: '/var/run/mysqld/mysqld.sock'  port: 33
Feb 17 03:06:30 ownergolf systemd[1]: Started MariaDB 10.4.12 database server.
-- Subject: Unit mariadb.service has finished start-up
-- Defined-By: systemd
-- Support: http://www.ubuntu.com/support
-- 
-- Unit mariadb.service has finished starting up.
-- 
-- The start-up result is RESULT.
Code language: PHP (php)

혹시 서버를 고민하신가요?

안녕하세요?

저는 Vultr를 사용하고 있는데요. 혹 신규로 서버 구축을 고민하신다면 Vultr도 검토해 보시라고 권해드립니다.

저는 2016년부터 Vultr을 사용했는데 큰 불만없이 잘 사용하고 있습니다. 아래 사용기도 한번 보시구요.

한국과 일본 서버 중에서 리노드나 AWS도 좋은 대안이지요. Vultr도 장점이 많은 VPS이고 대안으로 검토해볼만합니다. 성능면에서 괜찮다고 생각합니다.

혹시 Vultr에 관심이 있다면 아래 리퍼럴 링크를 이용해 보세요. 신규 계정을 등록 시 10$을 받을 수 있는 제휴 링크입니다.