fix failed log collection from short-lived containers (docklog)

[tonyhb]

Short-lived containers (especially those < 1 second) often do not have
thier logs sent to Nomad.

This PR adjusts the nomad docker driver and docker logging driver to:

1. Enable docklog to run after a container has stopped (to some grace
   period limit)
2. Collect logs from stopped containers up until the grace period

This fixes the current issues:

1. docklog is killed by the handle as soon as the task finishes, which
   means fast running containers can never have their logs scraped
2. docklog quits streaming logs in its event loop if the container has
   stopped
3. docklog closes the fifo streams as soon as the container quits (or
   destroys them after creating, if the container is stopped), so the logs
   can never be streamed to nomad.

In order to do this, we need to know whether we have read logs for the
current container in order to apply a grace period. We add a copier to
the fifo streams which sets an atomic flag, letting us know whether we
need to retry reading the logs and use a grace period or if we can quit
early.

Fixes #2457, #6931.

Notes; I'm not sure on the coding style and am not necessarily a fan
of the two goroutines within Start(). This fixes the issues (with tests)
but I can change it or it can be carried by someone who knows your style
a little more :)

[tonyhb]

hey hashicorp! can i help anyone review this code? i have a suspicion that a large cohort of nomad users run docker containers. the current docker log collection may have several faults which many users can run into.

i would love to get this merged and/or at least a discussion around it, given it could impact many, many users (and obviously impacts us!) :D

[hashicorp-cla]

All committers have signed the CLA.

[josegonzalez]

Any chance this can be reviewed? I've been playing around with short-lived containers and am noticing that logs are being dropped on the floor, and I suspect this is the primary suspect.

[schmichael]

Thanks for the submission and sorry it has languished so long.

I'm inclined to accept it because we have had so many corroborating, however I still can't manage to reproduce the bug myself!

I've been trying jobspecs like this and then asserting that the full date can be read via nomad alloc logs, and I have not been able to reproduce the bug.

Is there something I'm missing?

job "hello" {
  datacenters = ["dc1"]

  type = "batch"

  group "hello" {
    count = 20
    task "hello" {
      driver = "docker"
      config {
        image   = "busybox"
        command = "date"
      }
    }
  }
}

Obviously after all of this time this PR needs rebasing, a changelog entry, and website/docs update, but I can handle that if you'd like!

[schmichael]

Does this need to be info level?

Suggested change

	h.logger.Info("sending stop signal to logger", "job_id", h.task.JobID, "container_id", h.containerID)
	h.logger.Debug("sending stop signal to logger", "job_id", h.task.JobID, "container_id", h.containerID)

[schmichael]

AFAICT read serves 2 purposes:

1. If we've ever read anything, we can exit immediately if the container has exited and be safe from the truncation bug. (L160)
2. If we've received at least 1 read within 1s of container exit, we can exit safely. (L110)

[schmichael]

Hm, on future testing with the hello9000.nomad jobspec I'm seeing logs getting emitted 2 or 3 times. I think because docker_logger's main for loop now continues after the container has exited and the unix timestamp in the Since field is insufficient to prevent reading the last seconds logs more than once.

This is arguably better than dropping the logs the though.

Bash script I used when testing with that jobspec:

#!/bin/bash

completed=$(nomad job status  -all-allocs  hello9000 | rg 'complete' | cut -f1 -d' ')

for alloc in $completed; do
    echo "$alloc" $(nomad alloc logs $alloc)
done

[tonyhb]

I'm no longer working on this particular logging problem and don't have the time to investigate dupes or carry this; apologies. Framework and explanations of the three issues are hopefully helpful, though!