RCA: job_stopped_callback failed — Permission denied opening tesla_production-event.log

Overview#

What Happened#

2026-06-18 21:55 ~ 22:25 KST 사이 cupixworks-worker (Sidekiq) 의 JobCallbackWorker 가 job_stopped_callback 실행 중 3회 실패했다. 실패 원인은 Cupix::Event singleton logger 가 /var/app/current/log/tesla_production-event.log 파일을 열 때 OS 레벨 Permission denied 가 발생한 것으로, 그 결과 state machine transition (stopped_state_with_error → job_stopped_callback) 안에서 raise 되어 callback worker 가 실패 상태로 종료됐다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-06-18 21:55 KST — 첫 발생: Eventable::Events::Update.create_event 가 Permission denied @ rb_sysopen 로그 출력 (Datadog).
2. 2026-06-18 21:55 KST — JobCallbackWorker#perform 가 동일 원인으로 실패 (cluster first_seen 12:55:29 UTC).
3. 2026-06-18 22:25 KST — 동일 에러 2회 추가 발생 (last_seen 13:25:30 UTC, occurrence_count = 3).
4. 2026-06-18 22:25 KST — error-sweeper status-board 에서 cupixworks-worker 서비스 디그레이드 인시던트 (2026-06-18-svc-cupixworks-worker-1) 의 다섯 번째 클러스터로 묶임.

상위 인시던트: Status Board — 2026-06-18-svc-cupixworks-worker-1 (서비스 단위 묶음, 본 클러스터는 독립적 root cause).

Error Log#

Datadog Logs

job 1132621 job_stopped_callback error - /var/app/current/vendor/bundle/ruby/3.3.0/gems/logger-1.6.6/lib/logger/log_device.rb:114:in `initialize'
/var/app/current/vendor/bundle/ruby/3.3.0/gems/logger-1.6.6/lib/logger/log_device.rb:90:in `set_dev'
/var/app/current/vendor/bundle/ruby/3.3.0/gems/logger-1.6.6/lib/logger/log_device.rb:19:in `initialize'
/var/app/current/vendor/bundle/ruby/3.3.0/gems/logger-1.6.6/lib/logger.rb:593:in `new'
/var/app/current/vendor/bundle/ruby/3.3.0/gems/activesupport-7.2.2/lib/active_support/logger.rb:34:in `initialize'
/var/app/current/lib/cupix/event.rb:8:in `initialize'
/usr/lib64/ruby/3.3.0/singleton.rb:124:in `instance'
/var/app/current/lib/cupix/event.rb:18:in `publish'
/var/app/current/app/models/concerns/eventable/events/base.rb:18:in `create_event'
/var/app/current/app/models/concerns/jobable.rb:67:in `create_running_state_changed_event'
/var/app/current/app/models/concerns/jobable/capture.rb:30:in `job_stopped_callback'
/var/app/current/app/workers/job_callback_worker.rb:10:in `perform'

Eventable::Events::Base#create_event 의 rescue 가 잡아서 다음 한 줄로 정리한 동일 에러를 같은 시간대에 함께 출력했다 (Datadog query: service:cupixworks-worker "tesla_production-event.log"):

{
  "timestamp": "2026-06-18 22:25:30",
  "status": "error",
  "message": "Failed to create event: Permission denied @ rb_sysopen - /var/app/current/log/tesla_production-event.log",
  "class": "Eventable::Events::Update",
  "function": "create_event",
  "error": { "msg": "Permission denied @ rb_sysopen - /var/app/current/log/tesla_production-event.log" }
}

Impact#

• Service: cupixworks-worker
• 발생 횟수: 3
• 최초 발생: 2026-06-18 21:55 KST
• 최근 발생: 2026-06-18 22:25 KST
• 영향: JobCallbackWorker#perform 가 rescue StandardError 로 에러를 로깅하지만, 그 내부에서 state_machines 콜백이 transaction 안에서 raise 되었기 때문에 stopped_state_with_error transition 자체가 정상적으로 종료되지 않았을 가능성이 높다. 이로 인해 (1) Job 의 stopped 상태 전이 후 후속 이벤트 publish 누락, (2) Segment/Analytics 트래킹 누락, (3) Sidekiq retry 가 3회까지 동일 원인으로 재시도될 수 있음 (retry: 3).

Root Cause Summary#

Cupix::Event 는 ActiveSupport::Logger 를 상속한 Singleton 으로, 첫 publish 호출 시 "#{Rails.root}/log/tesla_#{Rails.env}-event.log" 경로로 daily-rotated 파일을 연다 (lib/cupix/event.rb:8). 운영 호스트에서 worker 프로세스가 해당 파일을 열 때 OS 가 EACCES (Permission denied) 를 돌려주어 로거 초기화가 실패했고, 이 예외가 state machine before_save 콜백 안에서 raise 되면서 job_stopped_callback 가 실패했다. Permission denied 는 일반적으로 (a) 새 파일이 다른 uid/gid 로 생성됨 (예: 배포/로그 로테이트 직후 root 가 만든 파일을 webapp user 가 못 여는 케이스), (b) 디스크 풀 또는 read-only 마운트 (현재 로그상 ENOSPC/EROFS 흔적은 없음) 중 (a) 가 가장 가능성이 높다 — 본 에러가 14일 retention 내 처음으로 2026-06-18 에만 등장했고, 여러 클러스터가 동시에 09:21 ~ 13:25 UTC 사이에 묶여 발생한 패턴은 deploy/rotate 전후의 일회성 권한 불일치 시나리오와 일치한다 (uncertain — 배포/로테이트 타임라인 미확인, 호스트 metadata 확인 필요).

Technical Analysis#

Code Path#

• Entry point: app/workers/job_callback_worker.rb:5 — Sidekiq worker perform
• State transition: app/models/concerns/jobable/capture.rb:30 가 job_stopped_callback 을 실행
• Eventable callback: app/models/concerns/jobable.rb:67 의 create_running_state_changed_event 가 Eventable::Events::Base.create_event(model) 호출
• Singleton init: lib/cupix/event.rb:7-11 에서 daily logger 를 처음 한 번만 초기화 (Singleton)
• Failure point: lib/cupix/event.rb:8 의 super(...) 호출 → Logger::LogDevice#open_logfile 에서 File.open (rb_sysopen) 이 EACCES 로 실패

require 'singleton'

module Cupix
  class Event < ActiveSupport::Logger
    include Singleton

    def initialize
      super("#{Rails.root}/log/tesla_#{Rails.env}-event.log", 'daily')
      self.formatter = Cupix::EventFormatter.new
      self.level = $CUPIX_LOGGER_LEVEL || Logger::INFO
    end

    def publish(event_body)
      info(event_body)
    end

    class << self
      delegate :publish, to: :instance
    end
  end
end

def create_event(model)
  return nil if invalid_event?(model)

  begin
    event = _create_event(model)
    reason = extract_reason(event, model)
    properties = build_properties(model)

    track_event(model, reason, properties)

    Cupix::EventService.publish_event([event])
    Cupix::Event.publish(event.serializable_hash(stringify_nested_fields: false))
  rescue StandardError => e
    Cupix::Logger.error("Failed to create event: #{e.message}", function: __method__, class: self.name, model: model.class.to_s, id: model.id, event_params: model.event_params, error: e)
    raise e
  end
end

class JobCallbackWorker
  include Sidekiq::Worker
  sidekiq_options queue: :default, retry: 3

  def perform(id, callback_name)
    Cupix::Logger.info("job #{id}, run #{callback_name}", ...)
    job = ::Job.find_by_id(id)
    return if job.nil?

    job.jobable.send(callback_name, job)
    ...
  rescue StandardError => e
    Cupix::Logger.error("job #{id} #{callback_name} error - #{e.class}: #{e.message}\n#{e.backtrace.join("\n")}", ...)
  end
end

기대 동작: Cupix::Event.publish 는 daily-rotated 파일에 INFO 라인을 한 줄 append. 실제 동작: super(path, 'daily') 가 Errno::EACCES 를 raise → Eventable::Events::Base.create_event 의 rescue 가 한 번 로깅 후 raise → state machine transaction 안의 before_save 체인이 실패 → JobCallbackWorker 의 outer rescue 가 stack trace 만 error 로 출력 (이게 Datadog 의 representative error).

이 에러 경로의 또 다른 특징은, Cupix::Event 가 Singleton 이라 프로세스 내 첫 호출이 실패하면 Singleton.instance 캐시에는 인스턴스가 저장되지 않아 다음 publish 가 또다시 initialize 를 호출 → 동일 실패가 반복된다는 점이다 (3회 발생 패턴과 일치).

Log Evidence#

사용한 Datadog 쿼리:

service:cupixworks-worker "log_device.rb"
service:cupixworks-worker "job_stopped_callback error"
service:cupixworks-worker ("Permission denied" OR "No space left" OR "Read-only file system" OR "Errno::EACCES" OR "Errno::ENOSPC" OR "Errno::EROFS")
service:cupixworks-worker "tesla_production-event.log"

핵심 관찰:

• 14일 retention 내 Permission denied @ rb_sysopen 로그는 2026-06-18 에만 3건. 그 이전 13일 동안 0건.
• 동일 시간대의 Failed to create event 로그가 모두 같은 경로 /var/app/current/log/tesla_production-event.log 를 가리킴.
• 다른 filesystem 에러 (ENOSPC, EROFS) 의 동시 출현은 없음.
• status-board 의 동일 인시던트에 묶인 다른 클러스터들은 서로 다른 root cause (예: 71467667... 는 "Bookmark not found after 6 retries") — 서비스 단위 그룹핑일 뿐 본 권한 에러와 직접 관련이 없다.

2026-06-18 22:25:30  error  Failed to create event: Permission denied @ rb_sysopen - /var/app/current/log/tesla_production-event.log
2026-06-18 22:25:28  error  Failed to create event: Permission denied @ rb_sysopen - /var/app/current/log/tesla_production-event.log
2026-06-18 21:55:29  error  Failed to create event: Permission denied @ rb_sysopen - /var/app/current/log/tesla_production-event.log

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• 호스트 inspect 후 권한 복구: 영향 받은 EB 인스턴스에서 ls -lZ /var/app/current/log/ 로 tesla_production-event.log 와 디렉토리 소유자/모드를 확인하고, webapp user (보통 webapp 또는 nginx) 가 read/write 가능하도록 chown/chmod. logrotate 또는 배포 스크립트가 root 권한으로 파일을 재생성하지 않는지 확인.
• 영향 파일: 운영 인프라 (Elastic Beanstalk .platform/hooks 또는 logrotate 설정). 코드 변경은 즉시 단계에서 불필요.

단기 개선 (1주 이내)#

• lib/cupix/event.rb:7-11 — Singleton 초기화 실패에 대한 방어선을 추가하는 방향 검토:
  • 옵션 A: 파일이 열리지 않을 때 STDERR 또는 Cupix::Logger 로 fallback 하도록 logger 생성을 lazy/safe 하게 변경. 단, ActiveSupport::Logger 의 super(path, ...) 가 raise 하면 Singleton 인스턴스가 캐시되지 않아 매 publish 마다 재시도되는 현재 동작을 어떻게 바꿀지 결정 필요.
  • 옵션 B: Eventable::Events::Base#create_event (base.rb:18) 에서 Cupix::Event.publish 실패가 비즈니스 로직(state transition) 을 raise 시키지 않도록 별도 rescue 로 감싸 event 발행 실패와 state 전이를 분리. 현재 구조에서는 로깅 실패 = state 전이 실패가 되어 운영상 risk 가 큼.
• app/workers/job_callback_worker.rb:13-15 — outer rescue 가 에러를 삼키지만, 이미 transaction 안에서 raise 된 후라 부분 rollback 가능성. retry-safe 하도록 callback 의 idempotency 점검.

장기 개선 (재발 방지)#

• 이벤트 publish 채널 일원화: 파일 기반 logger (tesla_*-event.log) 를 STDOUT → CloudWatch / Datadog 파이프로 이전해 호스트 파일시스템 권한에 의존하지 않게 함.
• Elastic Beanstalk 배포/logrotate 훅에 로그 디렉토리 권한 검증 단계 추가 (deploy post-hook 에서 test -w /var/app/current/log/tesla_${RAILS_ENV}-event.log 실패 시 배포 abort).
• Sidekiq job 안에서 부수효과 (Segment, Event log) 가 비즈니스 transaction 을 깨뜨리지 않도록 outbox/async publish 패턴 도입 검토.

Monitoring#

추가/유지해야 할 Datadog 쿼리 (모두 release dashboard timeseries widget 에 그대로 사용 가능):

service:cupixworks-worker status:error "Permission denied"

service:cupixworks-worker status:error "rb_sysopen"

service:cupixworks-worker status:error "Failed to create event"

service:cupixworks-worker status:error "log_device.rb"

알림 권장:

• service:cupixworks-worker status:error "Permission denied" 가 5분 윈도우에서 1건 이상이면 PagerDuty 알림 (현재 14일 baseline 0건이므로 즉각적으로 의미 있음).
• 디스크 사용률 메트릭 (avg:system.disk.in_use{service:cupixworks-worker}) 90% 초과 알림 — H2 가설 재발 방지 차원.

Risk Assessment#

• Risk level: medium — 발생 빈도는 3회로 낮지만, 실패 시 state machine transaction 무결성 (job stopped 처리 + downstream event/track) 에 영향. 운영 호스트의 파일 권한이 복구되지 않으면 동일 인스턴스에서 무한 재현 가능.
• 예상 복잡도: standard — 즉시 조치는 인프라 권한 수정 (단순). 단기/장기 개선은 logger/event publish 아키텍처 변경 검토 필요.