서버는 죽었다 살았다, 나는 현세와 지옥을 오간다.

제가 관리(? 회사가) 유지보수 중인 서버가 있습니다. 제목에서도 알 수 있듯이 이 서버의 사이트가 불안정하여 사이트가 죽었다 살았다를 반복하고, 식은땀을 흘리게 만들었습니다. 최근에는 서버가 안정되어 한숨을 돌리고 있습니다만 또 언재 문제가 터질지 걱정되기도 합니다. 이 글에서는 이 과정에 관련된 기록을 남기기 위함입니다.

서버 사양

웹사이트 운영 버

• 서버 유형 : VPS
• VPS 제공 : Vultr
• VCPU 수 : 6
• 메모리 : 16GB
• 저장메체 용량 : 320GB SSD
• 운영체제 : Ubuntu 18.04.1 LTS
• 기반 소프트웨어 : pache 2.4.29, PHP 5.6.38, MariaDB 10.1.34-

검색엔진 서버

• 서버 유형 : VPS
• VPS 제공 : Vultr
• VCPU 수 : 1
• 메모리 : 2B
• 저장메체 용량 : 40 SSD
• 운영체제 : Ubuntu 18.04.1 LTS
• 기반 소프트웨어 : Apache Solr 5.5.5

Apache Solr 장애

Apache Solr 다운으로 사이트 검색 기능 다운

아래의 사진은 최근 사진입니다. 하지만 장애가 났던 당시에는 아래와 같은 사진의 내용을 표시할 수 없었습니다. Apache Solr 서비스 데몬이 죽었고, 재실항할 수 없었기 때문입니다.

데몬이 재실행되지 않은 이유는 메모리 부족이 가장 큰 문제였습니다. 메모리가 부족하여 색인 데이터를 모두 로드하지 못했기 때문입니다. 현재는 2GB의 메모리를 가지고 있지만 이 당시 1GB 메모리로 되어 있었습니다. 하지만 메모리를 업그레이드한 이후에도 데몬이 죽는 등 문제가 지속적으로 발생했습니다.

조치 사항

jVM 메모리 제한 업그레이드

장애 발생 당시에는 JVM 최대 힙 사이즈가 256MB 였습니다. 메모리 업그레이드 후 최대 힙 사이즈를 아래와 같이 1GB로 설정하여 실행하도록 했습니다.

# /opt/solr/bin/solr restart -m 1024m -Djava.library.path=/usr/local/lib

주기적인 색인 데이터 최적화

위와 같이 메모리를 널려줘도 다운되는 현상이 생겼습니다. 이문제를 해결하기 위해 색인 데이터를 최적화하여 크기를 줄여줘야 했습니다. 최적화의 가장 간단한 방법은 Apache Solr의 관리용 데시보드의 "Optimize now" 버튼을 클릭하여 실행할 수 있습니다. 이 기능을 주기적으로 실행할 필요가 있어, 임시방편으로 아래와 같이 하루에 두 번 주기적으로 최적화하도록 Crontab에 설정을 해두었습니다.

0 0,12 * * * /usr/bin/curl http://localhost:8983/solr/drupal/update?optimize=true

더 나은 방법

더 나은 방법으로는 자동으로 최적화되도록 하는 것인데, 현재 운영중인 서버에도 기본 설정은 되어 있습니다. 하지만 이 설정이 현재 서버 사양과 맞는지 여부는 검토해볼 필요가 있습니다. 현재로서는 여기에 시간 투자를 할 여유가 없어 기록만 남겨 둡니다. 아래 내용은 'solrconfig.xml' 파일의 일부입니다.

  <indexConfig>
    <!-- maxFieldLength was removed in 4.0. To get similar behavior, include a
         LimitTokenCountFilterFactory in your fieldType definition. E.g.
     <filter class="solr.LimitTokenCountFilterFactory" maxTokenCount="10000"/>
    -->
    <!-- <writeLockTimeout>1000</writeLockTimeout>  -->
    <!-- <maxIndexingThreads>8</maxIndexingThreads>  -->
    <!-- <useCompoundFile>false</useCompoundFile> -->
    <ramBufferSizeMB>32</ramBufferSizeMB>
    <!-- <maxBufferedDocs>1000</maxBufferedDocs> -->
    <mergePolicy class="org.apache.lucene.index.LogByteSizeMergePolicy"/>
    <!--
       <mergeScheduler class="org.apache.lucene.index.ConcurrentMergeScheduler"/>
       -->
    <mergeFactor>4</mergeFactor>
    <lockType>${solr.lock.type:native}</lockType>
    <!-- <termIndexInterval>256</termIndexInterval> -->
    <unlockOnStartup>false</unlockOnStartup>
    <reopenReaders>true</reopenReaders>
    <deletionPolicy class="solr.SolrDeletionPolicy">
      <str name="maxCommitsToKeep">1</str>
      <str name="maxOptimizedCommitsToKeep">0</str>
      <!--
         <str name="maxCommitAge">30MINUTES</str>
         <str name="maxCommitAge">1DAY</str>
      -->
    </deletionPolicy>
    <infoStream>true</infoStream>
  </indexConfig>

사이트 운영 서버 장애

급격히 상승하는 서버 부하

아래 그림과 같이 순식간에 서버 부하가 상승하고 메모리 사용도 급격하게 늘어 사용 가능 메모리 공간이 없어 서버가 매우 느려지거나 응답하지 않는 상태가 자주 발생합니다. 심한 경우 mariaDB 서비스 데몬이 다운되고, 데이터 손상으로 실행이 아에 되지 않는 사태도 발생했습니다.

AmariaDB 서버

아래의 내용은 DB 서버 데몬이 죽었을 때의 로그입니다. 로그를 보면 메모리가 부족하고 요구 용량이 표시되고 있고, 현제 Buffer Pool Size의 크기가 표시되어 있습니다. 그리고 마지막에는 이로 인해 InnoDB 엔진을 초기화 할수 없어 재시작도 못하고 다운된 것을 확인했습니다.

2024-03-04  1:49:02 140636705234048 [ERROR] mysqld: Out of memory (Needed 128663552 bytes)
2024-03-04  1:49:02 140636705234048 [ERROR] mysqld: Out of memory (Needed 96485376 bytes)

......

InnoDB: mmap(140574720 bytes) failed; errno 12
2024-03-14 23:41:28 140476940496000 [ERROR] InnoDB: Cannot allocate memory for the buffer pool
2024-03-14 23:41:28 140476940496000 [ERROR] Plugin 'InnoDB' init function returned error.
2024-03-14 23:41:28 140476940496000 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
2024-03-14 23:41:28 140476940496000 [Note] Plugin 'FEEDBACK' is disabled.
2024-03-14 23:41:28 140476940496000 [ERROR] Unknown/unsupported storage engine: InnoDB
2024-03-14 23:41:28 140476940496000 [ERROR] Aborting

장애 원인 추정

해킹 시도

Apache Access Log를 확인해보니 아래와 같은 로그가 다수 보입니다. 로그에서 아래와 같이 /ru/events/2023-01-16?language=en, calendar-node-field-event-date/month/2021-03 등이 보입니다. 이들 경로는 사이트에서 재공하지 않는 경로입니다. 아래의 경로로 직접 접속해보니 응답속도도 느리고, 마지막에는 오류가 출력됩니다. DB의 Slow Query 로그를 확인해보니 이때 Slow Query가 발생합니다. 사이트의 취약점을 활용한 해킹시도로 보입니다.

85.208.96.197 - - [24/Nov/2023:17:51:14 +0900] "GET /ru/events/2023-01-16?language=en HTTP/1.1" 200 14033 "-" "Mozilla/5.0 (compatible; SemrushBot/7~bl; +http://www.semrush.com/bot.html)"

...

114.119.135.182 - - [24/Nov/2023:19:47:05 +0900] "GET /calendar-node-field-event-date/day/2021-03-06?field_events_title_value&page=52&language=en HTTP/1.1" 200 13886 "https://g.........org/calendar-node-field-event-date/month/2021-03?field_events_title_value&page=52&language=en" "Mozilla/5.0 (Linux; Android 7.0;) AppleWebKit/537.36 (KHTML, like Gecko) Mobile Safari/537.36 (compatible; PetalBot;+https://webmaster.petalsearch.com/site/petalbot)"

사이트에서 발생한 Slow Query

아래의 이미지는 장애가 발생했을 때 확인한 Slow Query 내용입니다. 아래의 쿼리는 제가 개발한 모듈에서 발생한 것이 아니라 Drupal의 공식 사이트에서 설치한 기여 모듈입니다. 저의 짧은 생각에는 이런 모듈들이 대량의 데이터를 예상하지 않고 만들어진 것이 아닌가 합니다.

작은 용량의 Buffer Pool Size

최초 Buffer Pool Size는 128MB로 8개의 인스턴스가 나누어 사용하는 것으로 되어 있습니다.

2024-03-04  1:49:02 140636705234048 [Note] InnoDB: Initializing buffer pool, size = 128.0M
InnoDB: mmap(140574720 bytes) failed; errno 12

+-------------------------------------+----------------+
| Variable_name                       | Value          |
+-------------------------------------+----------------+
| innodb_buffer_pool_dump_at_shutdown | OFF            |
| innodb_buffer_pool_dump_now         | OFF            |
| innodb_buffer_pool_dump_pct         | 100            |
| innodb_buffer_pool_filename         | ib_buffer_pool |
| innodb_buffer_pool_instances        | 8              |
| innodb_buffer_pool_load_abort       | OFF            |
| innodb_buffer_pool_load_at_startup  | OFF            |
| innodb_buffer_pool_load_now         | OFF            |
| innodb_buffer_pool_populate         | OFF            |
| innodb_buffer_pool_size             | 131072         |
+-------------------------------------+----------------+

조치 사항

InnoDB 손성 복구

MariaDB는 /etc/mysql/mariadb.conf.d/50-server.cnf 파일 내용 중에 아래와 주석을 제거하고 저장한 후 서비스를 복구모드로 실행하도록 했습니다.

[mariadb]
# innodb_force_recovery = 1
innodb_force_recovery = 1

# service mysql restart

해킹 시도 조치사항

일단 사용하지 않는 모듈을 전수 검사하여 비활성화 했습니다. 그리고 아래 내용과 같이 사이트 DocumentRoot 폴드에 .htaccess 파일에 사이트 경로를 rewrite하는 코드 위에 rewrite 조건을 지정해두었습니다.

  # 해킹으로 의심되는 요청 차단
  RewriteCond %{REQUEST_URI} /events/\d{4}-\d{2}-\d{2}$
  RewriteRule ^ 400.html [L]

아래 내용과 같이 해킹 시도로 의심되는 IP를 C클래스의 크기 단위로 차단하도록 ufw를 이용하여 설정해두었습니다.

To                         Action      From
--                         ------      ----
80/tcp                     ALLOW       Anywhere
443/tcp                    ALLOW       Anywhere
Anywhere                   DENY        106.11.167.0/24
Anywhere                   DENY        106.11.229.0/24
Anywhere                   DENY        106.11.230.0/24
Anywhere                   DENY        106.11.228.0/24
Anywhere                   DENY        106.11.231.0/24
50022                      ALLOW       .......
Anywhere                   DENY        114.234.157.0/24
Anywhere                   DENY        119.39.100.0/24
Anywhere                   DENY        119.39.102.0/24
Anywhere                   DENY        119.39.16.0/24
Anywhere                   DENY        119.39.17.0/24
Anywhere                   DENY        122.247.154.0/24
Anywhere                   DENY        122.247.157.0/24
Anywhere                   DENY        125.115.105.0/24
Anywhere                   DENY        125.115.189.0/24
Anywhere                   DENY        125.115.191.0/24
Anywhere                   DENY        180.115.187.0/24
Anywhere                   DENY        180.115.190.0/24
Anywhere                   DENY        180.116.178.0/24
Anywhere                   DENY        180.116.181.0/24
Anywhere                   DENY        180.116.182.0/24
Anywhere                   DENY        183.27.48.0/24
Anywhere                   DENY        183.27.49.0/24
Anywhere                   DENY        183.27.50.0/24
Anywhere                   DENY        183.27.51.0/24
Anywhere                   DENY        218.68.102.0/24
Anywhere                   DENY        218.68.105.0/24
Anywhere                   DENY        218.68.107.0/24
Anywhere                   DENY        218.68.108.0/24
Anywhere                   DENY        221.197.56.0/24
Anywhere                   DENY        221.197.66.0/24
Anywhere                   DENY        49.81.173.0/24
Anywhere                   DENY        60.24.14.0/24
Anywhere                   DENY        117.45.252.0/24
Anywhere                   DENY        117.45.253.0/24
....                       ALLOW       .......
..../tcp                   ALLOW       .......
..../tcp                   ALLOW       .......
..../tcp                   ALLOW       .......
..../tcp                   ALLOW       .......
..../tcp                   ALLOW       .......
..../tcp                   ALLOW       .......
..../tcp                   ALLOW       .......
..../tcp                   ALLOW       .......
..../tcp                   DENY        Anywhere
80/tcp (v6)                ALLOW       Anywhere (v6)
root@apceiu:~#
..../tcp  (v6)             DENY        Anywhere (v6)

Slow Query 예방을 위한 조치

사실 이 부분은 다른 기여 모듈에서 발생하는 것이라 수정하기에는 어려움이 많습니다. 사실 어느 모듈에서 이런 ㅋ쿼리를 넘기는지 알수가 없습니다. 사용하지 않는 모듈을 찾아 비활성화하는 것으로 마무리했습니다.

Buffer Pool Size 조정

사이트를 서비스하고 있는 사이트의 서버는 16GB의 메모리를 보유하고 있습니다. 이 장애가 발생하고 나서 인터넷을 검색해보니 물리적인 메모리의 70%~80%로 설정할 것을 권장하고 있습니다. 하지만 DBMS만 실행되고 있는 것이 아니라 적용하기에는 어려워 점진적으로 조정해왔습니다. 현재는 4GB로 설정되어 있습니다. 아래의 내용을 /etc/mysql/mariadb.conf.d/50-server.cnf 추가한 후 서비스를 다시 실행했습니다.

[mysqld]
innodb_buffer_pool_size = 4G

이렇게 조치한 후 InnoDB 엔진의 상태를 아래의 명령으로 확인해봤습니다. 확인 결과 8개의 인스턴스가 동일하게 512MG 씩 나우어 사용하고 있었습니다.

show engine innodb status\G;

---BUFFER POOL 0
Buffer pool size        32767
Buffer pool size, bytes 536854528
Free buffers            1024
Database pages          30413
Old database pages      11206
Modified db pages       7

---BUFFER POOL 1
Buffer pool size        32767
Buffer pool size, bytes 536854528
Free buffers            1024
Database pages          30427
Old database pages      11211
Modified db pages       2

---BUFFER POOL 2
Buffer pool size        32767
Buffer pool size, bytes 536854528
Free buffers            1024
Database pages          30414
Old database pages      11207
Modified db pages       0

---BUFFER POOL 2
Buffer pool size        32767
Buffer pool size, bytes 536854528
Free buffers            1024
Database pages          30414
Old database pages      11207
Modified db pages       0

---BUFFER POOL 3
Buffer pool size        32767
Buffer pool size, bytes 536854528
Free buffers            1024
Database pages          30414
Old database pages      11207
Modified db pages       2

---BUFFER POOL 4
Buffer pool size        32767
Buffer pool size, bytes 536854528
Free buffers            1024
Database pages          30420
Old database pages      11209
Modified db pages       2

---BUFFER POOL 5
Buffer pool size        32767
Buffer pool size, bytes 536854528
Free buffers            1024
Database pages          30418
Old database pages      11208
Modified db pages       0

---BUFFER POOL 6
Buffer pool size        32767
Buffer pool size, bytes 536854528
Free buffers            1024
Database pages          30401
Old database pages      11202
Modified db pages       3

---BUFFER POOL 7
Buffer pool size        32767
Buffer pool size, bytes 536854528
Free buffers            1024
Database pages          30413
Old database pages      11206
Modified db pages       1

아래의 명령으로 버퍼의 상태 등을 보다 간략하게 확인할 수도 있습니다. 여기서 관심있게 본 부분은 Innodb_buffer_pool_wait_free 부분인데, 2GB로 지정했을 때는 이 값이 126 정도였습니다. 아래 명령은 이 글을 작성하고 있는 시점에서 실행한 것인데, 4GB로 저종한 이후 46번 정도의 락으로 인한 대기가 있었다는 것으로 현상태로 충분하겠다 싶어 더 이상 Buffer Pool Size를 조정하지 않고 있습니다.

MariaDB [(none)]> show status like '%innodb_buffer_pool%';
+-----------------------------------------+----------------------------------------+
| Variable_name                           | Value                                  |
+-----------------------------------------+----------------------------------------+
| Innodb_buffer_pool_bytes_data           | 3985571840                             |
| Innodb_buffer_pool_bytes_dirty          | 6750208                                |
| Innodb_buffer_pool_dump_status          | Dumping buffer pool(s) not yet started |
| Innodb_buffer_pool_load_status          | Loading buffer pool(s) not yet started |
| Innodb_buffer_pool_pages_data           | 243260                                 |
| Innodb_buffer_pool_pages_dirty          | 412                                    |
| Innodb_buffer_pool_pages_flushed        | 87821456                               |
| Innodb_buffer_pool_pages_free           | 8192                                   |
| Innodb_buffer_pool_pages_lru_flushed    | 0                                      |
| Innodb_buffer_pool_pages_made_not_young | 491905155                              |
| Innodb_buffer_pool_pages_made_young     | 1605166                                |
| Innodb_buffer_pool_pages_misc           | 10684                                  |
| Innodb_buffer_pool_pages_old            | 89633                                  |
| Innodb_buffer_pool_pages_total          | 262136                                 |
| Innodb_buffer_pool_read_ahead           | 8956261                                |
| Innodb_buffer_pool_read_ahead_evicted   | 0                                      |
| Innodb_buffer_pool_read_ahead_rnd       | 0                                      |
| Innodb_buffer_pool_read_requests        | 500759227970                           |
| Innodb_buffer_pool_reads                | 1546483                                |
| Innodb_buffer_pool_wait_free            | 46                                     |
| Innodb_buffer_pool_write_requests       | 848190430                              |
+-----------------------------------------+----------------------------------------+

DB Table 최적화

최적화에 대한 이야기는 장애가 발생하기 전에 익히 들어왔던 것이었으나, 최적화 과정에 문제가 발생할 가능성을 우려해 손도 못되고 있다가 쟁애가 발생한 시점에 고객사쪽에도 미리 이야기를 해서 밤 12시에 약 2시간을 작업 시간으로 설정하고 최적화를 작업을 진행을 했습니다.

작업을 진행하기 전에 .htaccess 파일에 아래의 내용을 추가하여 사이트 각종 서비스에 접근할 수 없도록 한 후 작업을 했습니다. 이렇게 한 이유는 예전에 서비스 중인 데이터 필드와 자료를 통패합할 때가 있었는데, 작업을 다 하고 검토를 하는데, 통패합 전 데이터로 입력된 것이 다수 있어서 "내가 작업을 잘 못했나?"하는 생각에 엄청 당황했었습니다. 나중에 알고보니 서비스 자체의 점검모드를 켜 두어도 관리자는 예외로 설정되어 있고, 세션 유지시간도 약 2주(? 미친)로 설정되어 있다보니 별도의 로그인 없이 들어와서 작업을 한 것이었습니다.

  # 본 규칙은 서버의 중요한 유지보수 모드를 위한 것입니다.
  # 규칙을 적용하기 위해 아래의 IP 주소를 유지보수 작업 IP를 기록하고
  # maintenance.enable 파일을 생성해주세요.
  RewriteCond %{REMOTE_ADDR} !121.144.74.110
  RewriteCond %{DOCUMENT_ROOT}/maintenance.html -f
  RewriteCond %{DOCUMENT_ROOT}/maintenance.enable -f
  RewriteRule ^ maintenance.html [L]

위 내용 IP주소는 제가 작업 중인 PC의 IP주소입니다. 접속한 IP가 명기된 IP가 아니고, maintenance.html, maintenance.enable 파일이 존재하면 maintenance.htm 파일의 내용이 출력되도록 해둔 것입니다.

MySQL이나 MariaDB 모두 최적화하는 방식의 차이는 있으나 테이블 단위로 최적화하는 명령을 재공합니다. 하지만 전 mysql과 mysqldump를 이용하여 백업하고 복구하는 형태로 진행을 했습니다.

아래 내용은 최적화 전 물리적인 파일의 용량입니다.

# 최적화 전
root@axxxxx:/var/lib/mysql# du -m
64154   ./g...............    // 62.5GB
12      ./mysql
1       ./performance_schema
64785

그리고 아래의 내용은 최적화 후의 용량입니다.

# 최적화 후
root@axxxxx:/var/lib/mysql# du -m
12330   ./g...............     // 12.0GB
12      ./mysql
1       ./performance_schema
12961

약 5배의 공간 절약이 있었습니다.

swap 메모리(가상메모리) 추가

메모리가 부족하여 서비스가 다운되는 것을 막기 위해 성능은 떨어지지만 저장소(SSD)에 Swap 파일을 생성하여 들록했습니다. 용량은 메모리와 동일한 16GB로 지정했습니다. 아래의 내용은 Swap 메몰리를 추가하는 과정입니다.

# 핸재 메모리 사용 현황 확인
free -m

# 디스크 가용 용량 확인
df

# Swap 메모리 상태 확인
swapon

# Swap 메모리용 파일 생성
fallocate -l 4G /swapfile

# 권한 설정
chmod 600 /swapfile 

# swapfile을 Swap 메모리용으로 설정
mkswap /swapfile

# swapfile을 Swap 메모리로 활성화
swapon /swapfile

# fstab에 마운터 정보 설정
echo "/swapfile swap swap defaults 0 0"    >> /etc/fstab