꼭 중요한 순간에 터지는 DB

개요

평화롭게 시간을 보내고 있는데 퍼블리셔에서 메시지가 왔습니다.

로딩창에서 더 안 나아가는데 혹시 어떤 것 때문에 이런건가요?

등에서 식은땀이 흐르며 손발이 떨렸습니다. 아무튼 일단 서버 로그부터 열어 확인했습니다.

일단 로그부터

비슷한 시간대에 에러가 하나 떨어져 있었습니다.

MySqlConnector.MySqlException (0x80004005): Unable to connect to any of the specified MySQL hosts.
   at MySqlConnector.Core.ServerSession.OpenTcpSocketAsync(...)
   ...
   at Microsoft.EntityFrameworkCore.ServerVersion.AutoDetect(String connectionString)
   ...
RequestPath:/health

/health 엔드포인트에서 떨어진 거인데, 처음엔 한 번이면 그냥 글리치 아닐까 싶었는데, 퍼블리셔가 멈춰 있다고 한 시간대랑 정확히 맞아떨어졌습니다.

SSE가 범인인가?

직전 타임라인을 다시 봤더니, 슬로우 요청 경고들이 줄지어 있었습니다.

06:35:07  Slow request: GET /api/v1/sse/connect took 23939ms
06:35:42  Slow request: GET /api/v1/sse/connect took 4135ms
06:35:54  Slow request: GET /api/v1/sse/connect took 312339ms

24초, 4초, 그리고 5분 12초. 5분 12초짜리 SSE 요청은 정상이 아니죠.

SseController를 열어봤더니 heartbeat 루프마다 DB를 세 번씩 두드리고 있었습니다.

while (!linkedCts.Token.IsCancellationRequested)
{
    await Task.Delay(heartbeatInterval, linkedCts.Token);
    // ...
    await _presenceService.RefreshPresenceAsync(playerId);
    var sessionValid = await _sessionService.ValidateSessionAsync(sessionId);
    await _sessionService.UpdateSessionActivityAsync(sessionId);
}

“이거다. SSE가 DB connection을 잡아서 신규 요청이 못 들어간 거구나.” 라고 생각했죠.

그런데 헬스체크 에러 스택트레이스를 다시 보니 ServerVersion.AutoDetect였습니다. 이건 connection pool을 안 거치고 새 connection을 직접 여는 거라, pool 고갈 문제가 아니었습니다. 그게 실패했다는 건 MariaDB 서버 자체가 그 순간 TCP 응답을 안 했다는 뜻이죠.

원인 추적

EC2에 들어가서 mariadb 서비스 상태부터 봤습니다.

$ sudo systemctl status mariadb
● mariadb.service - MariaDB 10.11.13 database server
     Active: active (running) since Thu 2026-05-28 06:43:42 UTC; 17min ago

Active since가 딱 그 시각이었습니다. 그 1초 사이에 들어온 모든 요청이 5xx로 떨어진 거죠. mariadb의 살해 현장을 발견했습니다.

문제는 살인자가 누구냐죠. journalctl로 mariadb 서비스 로그를 봤더니 음… 모르겠습니다.

06:43:41  Stopping mariadb.service - MariaDB 10.11.13 database server...
06:43:41  mariadbd[...] (initiated by: unknown): Normal shutdown

initiated by: unknown. 시그널을 보낸 주체를 모른다는 소리죠. 그래도 Normal shutdown이니 크래시는 아니고 누군가 종료를 요청한 겁니다.

용의자 리스트를 뽑아서 하나하나 제거해나갔죠.

  • apt 자동 업데이트? – grep maria /var/log/apt/history.log 결과 비어 있음
  • OOM kill? – 그 시간대 dmesg에 OOM 흔적 없음, 메모리 피크도 142MB로 여유로움
  • 수동 SSH 접속자? – last 봐도 그 시간 접속 없음
  • cron? – 빈 상태

제가 형사였다면 무능하다고 짤렸을 것 같을 정도로 뭐 찍는거마다 꽝입니다. 막막해서 그 30초 구간 journalctl 전체를 떠봤습니다. 거기서 결정적 증거가 나왔죠.

06:43:31  systemd[1]: Starting apt-daily-upgrade.service - Daily apt upgrade...
06:43:38  apt.systemd.daily: unattended-upgrade
06:43:40  systemd[1]: Reexecuting requested from client PID 2751926 ('systemctl')
06:43:40  systemd[1]: Reexecuting.
06:43:41  systemd[1]: Stopping mariadb.service
06:43:42  systemd[1]: Started mariadb.service

범인은 우분투의 unattended-upgrades 였습니다. mariadb 패키지를 건드린 적은 없는데, 자동 보안 패치가 systemd 또는 공유 라이브러리를 업그레이드하면서 systemctl daemon-reexec를 호출했고, 그 여파로 mariadb를 포함한 다수 서비스가 일괄 stop/start된 거였죠. 그 시간대 같이 휩쓸린 서비스 목록은 mariadb, redis, fwupd, irqbalance, polkit, networkd, journald까지… 시스템 핵심 서비스 일괄 재시작 패턴이었습니다.

1초짜리 단절이 왜 사용자 에러로 갔나

여기서 한 가지가 의문점이 생겼습니다. EF Core 옵션에 분명히 EnableRetryOnFailure 정책을 걸어놨는데 말이죠.

mySqlOptions.EnableRetryOnFailure(
    maxRetryCount: 3,
    maxRetryDelay: TimeSpan.FromSeconds(2),
    errorNumbersToAdd: null)

3회, 2초 간격이면 최대 6초까지는 흡수해줘야 했는데, 1초 단절이면 사용자가 거의 못 느끼는 게 정상이죠. 그런데 왜 즉시 5xx로 떨어졌을까?

스택트레이스를 한 번 더 봤습니다.

   at Microsoft.EntityFrameworkCore.ServerVersion.AutoDetect(String connectionString)
   at Microsoft.Extensions.DependencyInjection.EntityFrameworkServiceCollectionExtensions.CreateDbContextOptions[TContext](...)

ServerVersion.AutoDetect가 옵션을 빌드하는 도중에 DB를 두드리고 있었습니다. retry 정책은 옵션의 일부인데, 그 옵션이 만들어지는 중에 발생한 실패는 정책 보호 밖이라 retry 대상이 아니었던 거인거입니다.

해결

AutoDetect를 빼고 MariaDB 버전을 명시적으로 넣었습니다. 

// before
builder.Services.AddDbContext<AppDbContext>(options =>
    options.UseMySql(connectionString,
                     ServerVersion.AutoDetect(connectionString),
                     mySqlOptions => mySqlOptions.EnableRetryOnFailure(
                         maxRetryCount: 3,
                         maxRetryDelay: TimeSpan.FromSeconds(2),
                         errorNumbersToAdd: null)));

// after
var dbVersionString = builder.Configuration["Database:ServerVersion"] ?? "10.11";
var dbServerVersion = new MariaDbServerVersion(Version.Parse(dbVersionString));

builder.Services.AddDbContext<AppDbContext>(options =>
    options.UseMySql(connectionString,
                     dbServerVersion,
                     mySqlOptions => mySqlOptions.EnableRetryOnFailure(
                         maxRetryCount: 3,
                         maxRetryDelay: TimeSpan.FromSeconds(2),
                         errorNumbersToAdd: null)));
// appsettings.json
"Database": {
  "ServerVersion": "10.11"
}

Pomelo의 MariaDbServerVersion은 SQL 번역기 힌트라 patch 레벨까지 정확히 맞출 필요는 없죠. Major.Minor만 넣어두면 10.11.x 시리즈 패치엔 안 만져도 된다고 문서에 써져있더라구요.

이제 옵션 빌드 시점에는 DB를 안 두드리고, 실제 쿼리 단계에서만 DB와 만나게 되겠죠. 거기는 EnableRetryOnFailure 우산 안이라 1~2초짜리 단절은 사용자가 못 느낄 겁니다. 그리고 리트라이 실패해서 바로 깨지는 일도 없겠죠

그리고 개발 서버의 자동 업데이트 timer는 일단 꺼뒀습니다. 이건 직접 해야죠.

sudo systemctl disable --now apt-daily.timer apt-daily-upgrade.timer

마무리

리눅스에 자동 업데이트가 매일 새벽에 도는 게 있다는 사실을 이번에 처음 알았습니다. 정석대로면 안정화된 버전 확인하고 점검 시간에 수동으로 패치하는 게 맞는데, EC2에 설치만 해놓고 그동안 그게 알아서 돌고 있었던 셈이죠.

음 멍청 비용이 너무 비싼데

/0 Comments
0 replies

Leave a Reply

Want to join the discussion?
Feel free to contribute!

Leave a Reply

Your email address will not be published. Required fields are marked *