Troubleshooting-docker bind mount시 파일 쓰기 권한 문제 - 예시 logstash

배경

logstash를 docker container로 띄우고 postgres db를 postgres db로 전달하려고 했다. db가 업데이트 되면 새로운 row들도 지속적으로 전달해야하는데 이미 업로드한 데이터는 전달하면 안되니 config에 아래와 같은 설정을 해두었다.

SELECT 문에 sql_last_value 설정

WHERE id > :spl_last_value

record_last_run 옵션과 last_run_metadapa_path 옵션 설정

record_last_run => true
last_run_metadata_path => "/usr/share/logstash/last_run_record/.logstash_jdbc_last_run

위 두 설정에 따라, .logstash_jdbc_last_run 파일에 가장 최근에 업로드한 row의 id 번호가 기록되고 다음번 logstash가 실행될때 이 번호보다 같거나 작은 id를 가진 row는 더이상 업데이트하지 않는다.

crontab설정

schedule => "* * * * *"

새로 업데이트되는 db 내용도 지속적으로 logstash를 통해 전달하기 위해 매분마다 logstash가 실행되도록 schedule을 설정했다.

예시 conf 내용은 아래와 같다

input {
	jdbc {
		jdbc_connection_string => "jdbc:postgresql://db:5432/db_name"
		jdbc_user => "user"
		jdbc_password => "password"
		jdbc_driver_library => "/usr/share/logstash/postgresql-42.2.14.jar"
		jdbc_driver_class => "org.postgresql.Driver"
		jdbc_paging_enabled => true
		jdbc_page_size => 10000
		tracking_column_type => "numeric"
		tracking_column => id
		use_column_value => true
		statement => 
        "SELECT ... FROM table
         WHERE id > :sql_last_value
         ORDER BY id asc"
		schedule => "0 * * * *"
		clean_run => false
		record_last_run => true
		last_run_metadata_path => "/usr/share/logstash/last_run_record/.logstash_jdbc_last_run"
        }
}

docker-compose 설정

logstash
    image: logstash:7.13.0
    container_name: logstash
    hostname: logstash
    volumes:
      - ./config:/usr/share/logstash/config
      - ./last_run_record:/usr/share/logstash/last_run_record
    restart: unless-stopped
    logging:
      driver: "json-file"
      options:
        max-size: "1M"
        max-file: "30"
    depends_on:
      - postgres

volume 내용을 보면, docker-compose 파일이 있는 폴더내 config 폴더에 conf파일을 저장해놓고 last_run_record 폴더에는 .logstash_jdbc_last_run 파일을 --- 0 이라는 내용으로 저장해놓았다.

예상하는 정상작동 시나리오

1. logstash가 첫번째 실행됐을 때

업데이트할 row가 10개가 있고 데이터들의 id가 1부터 10까지라고 하면 10개 row를 logstash가 두번째 postgres db로 전달하고 .logstash_jdbc_last_run파일은 --- 0에서 --- 10으로 저장된다.

2. schedule 설정에 따라 1분뒤 두번째 실행됐을 때

첫번때 postgres db에 id 11를 갖는 row한 줄이 1분사이에 추가되었다고 하면 logstash가 이 row를 전달하면서 .logstash_jdbc_last_run파일은 --- 11로 저장되야한다.

오류내용

11번째 row가 업데이트가 안되서 docker logs로 logstash의 로그를 봤더니 아래와 같은 에러 메시지가 출력되었다.

  { 2064 rufus-scheduler intercepted an error:
  2064   job:
  2064     Rufus::Scheduler::CronJob "* * * * *" {}
  2064   error:
  2064     2064
  2064     Errno::EACCES
  2064     Permission denied - /usr/share/logstash/last_run_record/.logstash_jdbc_last_run
  2064       org/jruby/RubyIO.java:1237:in `sysopen'
  2064       org/jruby/RubyIO.java:3800:in `write'
  2064       /usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/logstash-integration-jdbc-5.0.7/lib/logstash/plugin_mixins/jdbc/value_tracking.rb:122:in `write'
  2064       /usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/logstash-integration-jdbc-5.0.7/lib/logstash/plugin_mixins/jdbc/value_tracking.rb:46:in `write'
  2064       /usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/logstash-integration-jdbc-5.0.7/lib/logstash/inputs/jdbc.rb:325:in `execute_query'
  2064       /usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/logstash-integration-jdbc-5.0.7/lib/logstash/inputs/jdbc.rb:279:in `block in run'
  2064       /usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/rufus-scheduler-3.0.9/lib/rufus/scheduler/jobs.rb:234:in `do_call'
  2064       /usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/rufus-scheduler-3.0.9/lib/rufus/scheduler/jobs.rb:258:in `do_trigger'
  2064       /usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/rufus-scheduler-3.0.9/lib/rufus/scheduler/jobs.rb:300:in `block in start_work_thread'
  2064       /usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/rufus-scheduler-3.0.9/lib/rufus/scheduler/jobs.rb:299:in `block in start_work_thread'
  2064       org/jruby/RubyKernel.java:1442:in `loop'
  2064       /usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/rufus-scheduler-3.0.9/lib/rufus/scheduler/jobs.rb:289:in `block in start_work_thread'
  2064   tz:
  2064     ENV['TZ']:
  2064     Time.now: 2021-10-10 06:23:00 UTC
  2064   scheduler:
  2064     object_id: 2050
  2064     opts:
  2064       {:max_work_threads=>1}
  2064       frequency: 0.3
  2064       scheduler_lock: 
  2064       trigger_lock: 
  2064     uptime: 128.51644 (2m8s516)
  2064     down?: false
  2064     threads: 2
  2064       thread: 
  2064       thread_key: rufus_scheduler_2050
  2064       work_threads: 1
  2064         active: 1
  2064         vacant: 0
  2064         max_work_threads: 1
  2064       mutexes: {}
  2064     jobs: 1
  2064       at_jobs: 0
  2064       in_jobs: 0
  2064       every_jobs: 0
  2064       interval_jobs: 0
  2064       cron_jobs: 1
  2064     running_jobs: 1
  2064     work_queue: 0
} 2064 .

원인

결론은 파일 쓰기 권한 문제이다.

docker volume을 bind mount했는데 호스트에 저장된 파일의 읽고 쓰는 권한과 container 내에서의 권한이 일치 하지 않아서이다.

docker-composse 파일이 저장된 위치가 /opt/ 하위 폴더 였고 해당폴더의 사용자가 root였다.

반면 logstash container의 계정을 확인해보면 아래와 같이 root가 아니다.

$ docker exec -it logstash-cxr bash
bash-4.2$ whoami
logstash
bash-4.2$ echo $UID
1000

호스트에서로 같은 UID가 1000인 상태로 .logstash_jdbc_last_run 파일을 쓰고 컨테이너로 업데이트 하려고 하게 되고 당연히 권한이 없으므로 에러가 발생한다.

해결책

bind mount한 .last_run_record 폴더의 소유자를 UID 1000으로 맞춰주면 해결된다.

/opt 하위에 폴더, 파일을 만들면 읽기 권한이 other에도 열려있으니 대게 bind mount에 문제없으나, 해당 파일을 docker container를 통해 실행하는 서비스가 업데이트해야하는 상황이 있으면 위와 같은 에러가 발생한다.