Compose: Logs not displayed for restarted containers until container crashes again

[nickhiggs]

Description of the issue

When containers are restarted after crashing with restart: always the logs do not come out of docker-compose up or docker-compose logs -f until they are flushed on another restart.

Context information (for bug reports)

Output of "docker-compose version"
docker-compose version 1.18.0, build 8dd22a9
docker-py version: 2.6.1
CPython version: 2.7.13
OpenSSL version: OpenSSL 1.0.1t  3 May 2016

Output of "docker version"
Client:
 Version:      17.09.0-ce
 API version:  1.32
 Go version:   go1.8.3
 Git commit:   afdb6d4
 Built:        Tue Sep 26 22:42:18 2017
 OS/Arch:      linux/amd64

Server:
 Version:      17.09.0-ce
 API version:  1.32 (minimum version 1.12)
 Go version:   go1.8.3
 Git commit:   afdb6d4
 Built:        Tue Sep 26 22:40:56 2017
 OS/Arch:      linux/amd64
 Experimental: false

Output of "docker-compose config"
services:
  container1:
    command: /bin/bash -c 'for i in {1..10}; do echo hello world1; sleep 1; done;
      /bin/false'
    image: ubuntu:latest
    restart: always
  container2:
    command: /bin/bash -c 'while true; do echo hello world2; sleep 1; done'
    image: ubuntu:latest
    restart: always
version: '3'

Steps to reproduce the issue

1. docker-compose up using the docker-compose config

Observed result

container2_1  | hello world2
container1_1  | hello world1
container2_1  | hello world2
container1_1  | hello world1
container2_1  | hello world2
container1_1  | hello world1
container2_1  | hello world2
container1_1  | hello world1
container2_1  | hello world2
container1_1  | hello world1
container2_1  | hello world2
container1_1  | hello world1
container2_1  | hello world2
container1_1  | hello world1
container2_1  | hello world2
container1_1  | hello world1
container2_1  | hello world2
container1_1  | hello world1
container2_1  | hello world2
container1_1  | hello world1
container2_1  | hello world2
container2_1  | hello world2
container2_1  | hello world2
container2_1  | hello world2
container2_1  | hello world2
container2_1  | hello world2
container2_1  | hello world2
container2_1  | hello world2
container2_1  | hello world2
container2_1  | hello world2
container2_1  | hello world2
ubuntu_container1_1 exited with code 1
container1_1  | hello world1
container1_1  | hello world1
container1_1  | hello world1
container1_1  | hello world1
container1_1  | hello world1
container1_1  | hello world1
container1_1  | hello world1
container1_1  | hello world1
container1_1  | hello world1
container1_1  | hello world1
container1_1  | hello world1
container1_1  | hello world1
container1_1  | hello world1
container1_1  | hello world1
container1_1  | hello world1
container1_1  | hello world1
container1_1  | hello world1
container1_1  | hello world1
container1_1  | hello world1
container1_1  | hello world1
container1_1  | hello world1
container2_1  | hello world2
container1_1  | hello world1

Expected result

container2_1  | hello world2
container1_1  | hello world1
container2_1  | hello world2
container1_1  | hello world1
container2_1  | hello world2
container1_1  | hello world1
container2_1  | hello world2
container1_1  | hello world1
container2_1  | hello world2
container1_1  | hello world1
container2_1  | hello world2
container1_1  | hello world1
container2_1  | hello world2
container1_1  | hello world1
container2_1  | hello world2
container1_1  | hello world1
container2_1  | hello world2
container1_1  | hello world1
container2_1  | hello world2
container1_1  | hello world1
ubuntu_container1_1 exited with code 1
container1_1  | hello world1
container2_1  | hello world2
container1_1  | hello world1
container2_1  | hello world2
container1_1  | hello world1
container2_1  | hello world2
container1_1  | hello world1
container2_1  | hello world2
container1_1  | hello world1
container2_1  | hello world2
...

Additional information

We could reproduce it on both linux 4.4.0-1061-aws #70-Ubuntu and osx Darwin Kernel Version 17.6.0 with compose 2.3 & 3.

[nickhiggs]

This looks like it is caused by the 'die' event in the log_printer not being handled in the same manner as the 'stop' event. So when the container starts again there is still an 'alive' thread for the container id which hasn't been removed yet. Then, on the next restart, the thread has been removed and the logs all get dumped.

From my understanding, this could be solved by simply killing the containers logging thread on a container 'die' event however on the next start the logs will come from 'docker logs' and duplicate a lot of the logs that occurred before the container death. Alternatively we could reattach to the container to stream the logs but there is a risk of missing some of the startup logs (and would have to be handled separately to docker-compose logs functionality).

[shin-]

This has been reported before in #5451 and #5675 . It is something I'd like Compose to do as well.

[nickhiggs]

Thanks @shin- . In one of the other issues you mentioned re-attaching was 'more complex than it might seem at first glance', could you elaborate on the problem? I was having a look at implementing a fix and the only issue I came across was the chance losing some of the logs from the container launch as the reattach is driven by separate events.

[IzaGz]

logs not displayed- how to fix this?