nerdctl icon indicating copy to clipboard operation
nerdctl copied to clipboard
verified publisher icon containerd

Container logs stop printing after restart with `restart: on-failure` set in compose

Open lwj5 opened this issue 2 years ago • 2 comments

Description

When a container restarts on failure the log is not printed out to console when the compose file is launched using nerdctl compose up

Using this compose file

version: "3.9"

services:
  db:
    image: postgres:15
    volumes:
      - ./init.sql:/docker-entrypoint-initdb.d/init.sql
    restart: on-failure
    environment:
      - POSTGRES_PASSWORD=alongpassword

and a bad SQL init.sql

CREATE DATABASE IF NOT EXISTS `bad`;

Steps to reproduce the issue

  1. Run nerdctl compose up with the above files
  2. See PostgreSQL fail and INFO[0001] All the containers have exited
  3. See that PostgreSQL has restarted with nerdctl ps in another console

If we have multiple containers in the compose file, nerdctl will continue to output logs for the other app but will stop showing logs for PostgreSQL in 2.

Describe the results you received and expected

Not exit and continue to print logs for the restarted container

What version of nerdctl are you using?

Client: Version: v1.4.0 OS/Arch: linux/arm64 Git commit: 7e8114a82da342cdbec9a518c5c6a1cce58105e9 buildctl: Version: v0.11.6 GitCommit: 2951a28cd7085eb18979b1f710678623d94ed578

Server: containerd: Version: v1.7.0 GitCommit: 1fbd70374134b891f97ce19c70b6e50c7b9f4e0d runc: Version: 1.1.7 GitCommit: 860f061b76bb4fc671f0f9e900f7d80ff93d4eb7

Are you using a variant of nerdctl? (e.g., Rancher Desktop)

Rancher Desktop for macOS

Host information

Client: Namespace: default Debug Mode: false

Server: Server Version: v1.7.0 Storage Driver: overlayfs Logging Driver: json-file Cgroup Driver: cgroupfs Cgroup Version: 1 Plugins: Log: fluentd journald json-file syslog Storage: native overlayfs Security Options: seccomp Profile: default Kernel Version: 6.1.30-0-virt Operating System: Alpine Linux v3.18 OSType: linux Architecture: aarch64 CPUs: 4 Total Memory: 9.698GiB Name: lima-rancher-desktop ID: 27e0c08b-22e6-44f3-9667-e102c2b03384

WARNING: IPv4 forwarding is disabled WARNING: bridge-nf-call-iptables is disabled WARNING: bridge-nf-call-ip6tables is disabled

lwj5 avatar Oct 13 '23 15:10 lwj5

HI @lwj5

I try print the log with containerd restarted, it's OK to show the new logs.

If running the nerdctl logs or nerdctl compose logs command again, can the new logs(containerd restarted) be printed ? Thanks for the issue .

yankay avatar Oct 17 '23 03:10 yankay

Using a simple compose file

version: "3.9"

services:
  db:
    image: postgres:15
    volumes:
      - ./init.sql:/docker-entrypoint-initdb.d/init.sql
    restart: on-failure
    environment:
      - POSTGRES_PASSWORD=alongpassword

  redis:
    image: redis:6.2
    restart: on-failure

volumes:
  db:
    driver: local

Spinning up for the first time:

test-docker % nerdctl compose up
INFO[0000] Creating network test-docker_default         
WARN[0000] Ignoring: volume db: [Driver]                
INFO[0000] Creating volume test-docker_db               
INFO[0000] Ensuring image postgres:15                   
INFO[0000] Ensuring image redis:6.2                     
INFO[0000] Creating container test-docker_db_1          
INFO[0000] Creating container test-docker_redis_1       
INFO[0000] Attaching to logs                            
redis_1 |1:C 21 Oct 2023 06:56:38.151 # oO0OoO0OoO0Oo Redis is starting oO0OoO0OoO0Oo
redis_1 |1:C 21 Oct 2023 06:56:38.151 # Redis version=6.2.13, bits=64, commit=00000000, modified=0, pid=1, just started
redis_1 |1:C 21 Oct 2023 06:56:38.151 # Warning: no config file specified, using the default config. In order to specify a config file use redis-server /path/to/redis.conf
redis_1 |1:M 21 Oct 2023 06:56:38.152 # You requested maxclients of 10000 requiring at least 10032 max file descriptors.
redis_1 |1:M 21 Oct 2023 06:56:38.152 # Server can't set maximum open files to 10032 because of OS error: Operation not permitted.
redis_1 |1:M 21 Oct 2023 06:56:38.152 # Current maximum open files is 1024. maxclients has been reduced to 992 to compensate for low ulimit. If you need higher maxclients increase 'ulimit -n'.
redis_1 |1:M 21 Oct 2023 06:56:38.152 * monotonic clock: POSIX clock_gettime
redis_1 |1:M 21 Oct 2023 06:56:38.152 * Running mode=standalone, port=6379.
redis_1 |1:M 21 Oct 2023 06:56:38.152 # Server initialized
redis_1 |1:M 21 Oct 2023 06:56:38.152 # WARNING Memory overcommit must be enabled! Without it, a background save or replication may fail under low memory condition. Being disabled, it can can also cause failures without low memory condition, see https://github.com/jemalloc/jemalloc/issues/1328. To fix this issue add 'vm.overcommit_memory = 1' to /etc/sysctl.conf and then reboot or run the command 'sysctl vm.overcommit_memory=1' for this to take effect.
redis_1 |1:M 21 Oct 2023 06:56:38.154 * Ready to accept connections
db_1    |The files belonging to this database system will be owned by user "postgres".
db_1    |This user must also own the server process.
db_1    |
db_1    |The database cluster will be initialized with locale "en_US.utf8".
db_1    |The default database encoding has accordingly been set to "UTF8".
db_1    |The default text search configuration will be set to "english".
db_1    |
db_1    |Data page checksums are disabled.
db_1    |
db_1    |fixing permissions on existing directory /var/lib/postgresql/data/pgdata ... ok
db_1    |creating subdirectories ... ok
db_1    |selecting dynamic shared memory implementation ... posix
db_1    |selecting default max_connections ... 100
db_1    |selecting default shared_buffers ... 128MB
db_1    |selecting default time zone ... Etc/UTC
db_1    |creating configuration files ... ok
db_1    |running bootstrap script ... ok
INFO[0000] Container "test-docker_db_1" exited

It says INFO[0001] Container "test-docker_db_1" exited and stops outputting the logs for db_1 although db_1 has been restarted.

If we check nerdctl ps we can see that the new db_1 container is indeed running, and there are new log outputs (as shown below). But these new logs are not shown in the terminal above.

test-docker % nerdctl ps
CONTAINER ID    IMAGE                            COMMAND                   CREATED           STATUS    PORTS                      NAMES
48c8abc3990f    docker.io/library/postgres:15    "docker-entrypoint.s…"    28 seconds ago    Up                                   test-docker_db_1
e3da2245f14f    docker.io/library/redis:6.2      "docker-entrypoint.s…"    28 seconds ago    Up        0.0.0.0:49153->6379/tcp    test-docker_redis_1
test-docker % nerdctl logs 48c8abc3990f

PostgreSQL Database directory appears to contain a database; Skipping initialization

2023-10-21 06:56:38.953 UTC [1] LOG:  starting PostgreSQL 15.4 (Debian 15.4-2.pgdg120+1) on aarch64-unknown-linux-gnu, compiled by gcc (Debian 12.2.0-14) 12.2.0, 64-bit
2023-10-21 06:56:38.953 UTC [1] LOG:  listening on IPv4 address "0.0.0.0", port 5432
2023-10-21 06:56:38.953 UTC [1] LOG:  listening on IPv6 address "::", port 5432
2023-10-21 06:56:38.954 UTC [1] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2023-10-21 06:56:38.957 UTC [29] LOG:  database system was interrupted; last known up at 2023-10-21 06:56:38 UTC
2023-10-21 06:56:39.007 UTC [29] LOG:  database system was not properly shut down; automatic recovery in progress
2023-10-21 06:56:39.008 UTC [29] LOG:  invalid record length at 0/1501A58: wanted 24, got 0
2023-10-21 06:56:39.008 UTC [29] LOG:  redo is not required
2023-10-21 06:56:39.009 UTC [27] LOG:  checkpoint starting: end-of-recovery immediate wait
2023-10-21 06:56:39.013 UTC [27] LOG:  checkpoint complete: wrote 3 buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.002 s, sync=0.001 s, total=0.005 s; sync files=2, longest=0.001 s, average=0.001 s; distance=0 kB, estimate=0 kB
2023-10-21 06:56:39.015 UTC [1] LOG:  database system is ready to accept connections

Only when running nerdctl compose logs from another terminal, does it show the logs from the newly restarted container

test-docker % nerdctl compose logs
db_1    |2023-10-21 06:56:38.953 UTC [1] LOG:  starting PostgreSQL 15.4 (Debian 15.4-2.pgdg120+1) on aarch64-unknown-linux-gnu, compiled by gcc (Debian 12.2.0-14) 12.2.0, 64-bit
db_1    |2023-10-21 06:56:38.953 UTC [1] LOG:  listening on IPv4 address "0.0.0.0", port 5432
db_1    |2023-10-21 06:56:38.953 UTC [1] LOG:  listening on IPv6 address "::", port 5432
db_1    |2023-10-21 06:56:38.954 UTC [1] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
db_1    |2023-10-21 06:56:38.957 UTC [29] LOG:  database system was interrupted; last known up at 2023-10-21 06:56:38 UTC
db_1    |2023-10-21 06:56:39.007 UTC [29] LOG:  database system was not properly shut down; automatic recovery in progress
db_1    |2023-10-21 06:56:39.008 UTC [29] LOG:  invalid record length at 0/1501A58: wanted 24, got 0
db_1    |2023-10-21 06:56:39.008 UTC [29] LOG:  redo is not required
db_1    |2023-10-21 06:56:39.009 UTC [27] LOG:  checkpoint starting: end-of-recovery immediate wait
db_1    |2023-10-21 06:56:39.013 UTC [27] LOG:  checkpoint complete: wrote 3 buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.002 s, sync=0.001 s, total=0.005 s; sync files=2, longest=0.001 s, average=0.001 s; distance=0 kB, estimate=0 kB
db_1    |2023-10-21 06:56:39.015 UTC [1] LOG:  database system is ready to accept connections
db_1    |
db_1    |PostgreSQL Database directory appears to contain a database; Skipping initialization
db_1    |
redis_1 |1:C 21 Oct 2023 06:56:38.151 # oO0OoO0OoO0Oo Redis is starting oO0OoO0OoO0Oo
redis_1 |1:C 21 Oct 2023 06:56:38.151 # Redis version=6.2.13, bits=64, commit=00000000, modified=0, pid=1, just started
redis_1 |1:C 21 Oct 2023 06:56:38.151 # Warning: no config file specified, using the default config. In order to specify a config file use redis-server /path/to/redis.conf
redis_1 |1:M 21 Oct 2023 06:56:38.152 # You requested maxclients of 10000 requiring at least 10032 max file descriptors.
redis_1 |1:M 21 Oct 2023 06:56:38.152 # Server can't set maximum open files to 10032 because of OS error: Operation not permitted.
redis_1 |1:M 21 Oct 2023 06:56:38.152 # Current maximum open files is 1024. maxclients has been reduced to 992 to compensate for low ulimit. If you need higher maxclients increase 'ulimit -n'.
redis_1 |1:M 21 Oct 2023 06:56:38.152 * monotonic clock: POSIX clock_gettime
redis_1 |1:M 21 Oct 2023 06:56:38.152 * Running mode=standalone, port=6379.
redis_1 |1:M 21 Oct 2023 06:56:38.152 # Server initialized
redis_1 |1:M 21 Oct 2023 06:56:38.152 # WARNING Memory overcommit must be enabled! Without it, a background save or replication may fail under low memory condition. Being disabled, it can can also cause failures without low memory condition, see https://github.com/jemalloc/jemalloc/issues/1328. To fix this issue add 'vm.overcommit_memory = 1' to /etc/sysctl.conf and then reboot or run the command 'sysctl vm.overcommit_memory=1' for this to take effect.
redis_1 |1:M 21 Oct 2023 06:56:38.154 * Ready to accept connections

When using docker compose, the restarted container logs will be streamed to the terminal running the compose up command.

Not sure if this is intended for nerdctl

lwj5 avatar Oct 21 '23 07:10 lwj5