Files
moby/daemon/kill.go
Sebastiaan van Stijn bca54a6838 daemon: killWithSignal: use more structured logs
Use more structured logs, and provide a human-readable presentation of the signal
that's sent. For the human-readable presentation, we should probably look at
converting back to the signal _names_ (e.g. `SIGWINCH` or `SIGKILL`), which may
be easier to interpret, but we currently don't have a utility for that.

Before:

    DEBU[2024-10-14T10:24:51.538705343Z] Sending kill signal 28 to container 7e9e99e52fc69ef1038b2fd212c8dc18948a56e6f024fbe46192f43006a229aa
    DEBU[2024-10-14T10:24:51.740502218Z] Calling POST /v1.47/containers/7e9e99e52fc69ef1038b2fd212c8dc18948a56e6f024fbe46192f43006a229aa/kill?signal=WINCH  spanID=9b993a93d28479f3 traceID=a37022e0429abaf9fb8b66a6cd4e4a19
    DEBU[2024-10-14T10:24:51.740874218Z] Sending kill signal 28 to container 7e9e99e52fc69ef1038b2fd212c8dc18948a56e6f024fbe46192f43006a229aa
    DEBU[2024-10-14T10:24:51.740501843Z] Calling POST /v1.47/containers/7e9e99e52fc69ef1038b2fd212c8dc18948a56e6f024fbe46192f43006a229aa/resize?h=39&w=127  spanID=f1563bdd86230804 traceID=9c25ff5910b30a4a04b774c8f5d0160e

After:

    DEBU[2024-10-15T17:17:18.988605173Z] Calling POST /v1.47/containers/cafc94ca93a8e10eb79ce86235c4510d6bba1dab9cf4827abe490328148418c8/kill?signal=WINCH  spanID=491d75545f89902a traceID=de72bdd1130bfc010ff1172ac23695b3
    DEBU[2024-10-15T17:17:18.988763173Z] sending signal 28 (window changed) to container  container=cafc94ca93a8e10eb79ce86235c4510d6bba1dab9cf4827abe490328148418c8 signal=28
    DEBU[2024-10-15T17:17:18.988605214Z] Calling POST /v1.47/containers/cafc94ca93a8e10eb79ce86235c4510d6bba1dab9cf4827abe490328148418c8/resize?h=46&w=152  spanID=8b18f64b12931da2 traceID=0a38e4a16dbbfda72172209382faec91
    ...
    ...
    DEBU[2024-10-15T20:26:16.863097005Z] sending signal 1 (hangup) to container        container=824197a9af794c4bcda13914021f13d702954114d3410c9db629a51bf685bdc7 signal=1
    DEBU[2024-10-15T20:26:31.431432554Z] sending signal 10 (user defined signal 1) to container  container=824197a9af794c4bcda13914021f13d702954114d3410c9db629a51bf685bdc7 signal=10
    DEBU[2024-10-15T19:52:41.717507211Z] shutting down container                       container=824197a9af794c4bcda13914021f13d702954114d3410c9db629a51bf685bdc7
    DEBU[2024-10-15T19:52:41.717681920Z] sending signal 15 (terminated) to container   container=824197a9af794c4bcda13914021f13d702954114d3410c9db629a51bf685bdc7 signal=15

Or in JSON format:

    {"level":"debug","msg":"Calling POST /v1.47/containers/6a62783bc6a591381dd625b8dca20bebf6b0f6e927956b92a4c8ea0438f2ff76/kill?signal=WINCH","spanID":"d7622e49d248a2e5","time":"2024-10-15T19:54:36.258464042Z","traceID":"8dcc62a38b0289c9eeb7d9fa7f9a485d"}
    {"container":"6a62783bc6a591381dd625b8dca20bebf6b0f6e927956b92a4c8ea0438f2ff76","level":"debug","msg":"sending signal 28 (window changed) to container","signal":28,"time":"2024-10-15T19:54:36.258546167Z"}
    {"level":"debug","msg":"Calling POST /v1.47/containers/6a62783bc6a591381dd625b8dca20bebf6b0f6e927956b92a4c8ea0438f2ff76/kill?signal=WINCH","spanID":"0c908cb6fe55a921","time":"2024-10-15T19:54:36.458532084Z","traceID":"a0225edfaa0b3c3b0ce93e3d2c98f326"}
    {"container":"6a62783bc6a591381dd625b8dca20bebf6b0f6e927956b92a4c8ea0438f2ff76","level":"debug","msg":"sending signal 28 (window changed) to container","signal":28,"time":"2024-10-15T19:54:36.458614126Z"}
    {"level":"debug","msg":"Calling POST /v1.47/containers/6a62783bc6a591381dd625b8dca20bebf6b0f6e927956b92a4c8ea0438f2ff76/resize?h=50\u0026w=167","spanID":"1679a419b3f8b5e4","time":"2024-10-15T19:54:36.458560459Z","traceID":"cad46e855dc5975799a7c82bdbed1b81"}

Signed-off-by: Sebastiaan van Stijn <github@gone.nl>
2024-10-15 22:40:39 +02:00

214 lines
6.7 KiB
Go

package daemon // import "github.com/docker/docker/daemon"
import (
"context"
"fmt"
"runtime"
"strconv"
"syscall"
"time"
"github.com/containerd/log"
"github.com/docker/docker/api/types/events"
containerpkg "github.com/docker/docker/container"
"github.com/docker/docker/errdefs"
"github.com/moby/sys/signal"
"github.com/pkg/errors"
)
type errNoSuchProcess struct {
pid int
signal syscall.Signal
}
func (e errNoSuchProcess) Error() string {
return fmt.Sprintf("cannot kill process (pid=%d) with signal %d: no such process", e.pid, e.signal)
}
func (errNoSuchProcess) NotFound() {}
// ContainerKill sends signal to the container
// If no signal is given, then Kill with SIGKILL and wait
// for the container to exit.
// If a signal is given, then just send it to the container and return.
func (daemon *Daemon) ContainerKill(name, stopSignal string) error {
var (
err error
sig = syscall.SIGKILL
)
if stopSignal != "" {
sig, err = signal.ParseSignal(stopSignal)
if err != nil {
return errdefs.InvalidParameter(err)
}
if !signal.ValidSignalForPlatform(sig) {
return errdefs.InvalidParameter(errors.Errorf("the %s daemon does not support signal %d", runtime.GOOS, sig))
}
}
container, err := daemon.GetContainer(name)
if err != nil {
return err
}
if sig == syscall.SIGKILL {
// perform regular Kill (SIGKILL + wait())
return daemon.Kill(container)
}
return daemon.killWithSignal(container, sig)
}
// killWithSignal sends the container the given signal. This wrapper for the
// host specific kill command prepares the container before attempting
// to send the signal. An error is returned if the container is paused
// or not running, or if there is a problem returned from the
// underlying kill command.
func (daemon *Daemon) killWithSignal(container *containerpkg.Container, stopSignal syscall.Signal) error {
log.G(context.TODO()).WithFields(log.Fields{
"signal": int(stopSignal),
"container": container.ID,
}).Debugf("sending signal %[1]d (%[1]s) to container", stopSignal)
container.Lock()
defer container.Unlock()
task, err := container.GetRunningTask()
if err != nil {
return err
}
var unpause bool
if container.Config.StopSignal != "" && stopSignal != syscall.SIGKILL {
containerStopSignal, err := signal.ParseSignal(container.Config.StopSignal)
if err != nil {
return err
}
if containerStopSignal == stopSignal {
container.ExitOnNext()
unpause = container.Paused
}
} else {
container.ExitOnNext()
unpause = container.Paused
}
if !daemon.IsShuttingDown() {
container.HasBeenManuallyStopped = true
if err := container.CheckpointTo(context.WithoutCancel(context.TODO()), daemon.containersReplica); err != nil {
log.G(context.TODO()).WithFields(log.Fields{
"error": err,
"container": container.ID,
}).Warn("error checkpointing container state")
}
}
// if the container is currently restarting we do not need to send the signal
// to the process. Telling the monitor that it should exit on its next event
// loop is enough
if container.Restarting {
return nil
}
if err := task.Kill(context.Background(), stopSignal); err != nil {
if errdefs.IsNotFound(err) {
unpause = false
log.G(context.TODO()).WithFields(log.Fields{
"error": err,
"container": container.ID,
"action": "kill",
}).Debug("container kill failed because of 'container not found' or 'no such process'")
go func() {
// We need to clean up this container but it is possible there is a case where we hit here before the exit event is processed
// but after it was fired off.
// So let's wait the container's stop timeout amount of time to see if the event is eventually processed.
// Doing this has the side effect that if no event was ever going to come we are waiting a longer period of time unnecessarily.
// But this prevents race conditions in processing the container.
ctx, cancel := context.WithTimeout(context.TODO(), time.Duration(container.StopTimeout())*time.Second)
defer cancel()
s := <-container.Wait(ctx, containerpkg.WaitConditionNotRunning)
if s.Err() != nil {
if err := daemon.handleContainerExit(container, nil); err != nil {
log.G(context.TODO()).WithFields(log.Fields{
"error": err,
"container": container.ID,
"action": "kill",
}).Warn("error while handling container exit")
}
}
}()
} else {
return errors.Wrapf(err, "Cannot kill container %s", container.ID)
}
}
if unpause {
// above kill signal will be sent once resume is finished
if err := task.Resume(context.Background()); err != nil {
log.G(context.TODO()).WithFields(log.Fields{
"error": err,
"container": container.ID,
"action": "kill",
}).Warn("cannot unpause container")
}
}
daemon.LogContainerEventWithAttributes(container, events.ActionKill, map[string]string{
"signal": strconv.Itoa(int(stopSignal)),
})
return nil
}
// Kill forcefully terminates a container.
func (daemon *Daemon) Kill(container *containerpkg.Container) error {
if !container.IsRunning() {
return errNotRunning(container.ID)
}
// 1. Send SIGKILL
if err := daemon.killPossiblyDeadProcess(container, syscall.SIGKILL); err != nil {
// kill failed, check if process is no longer running.
if errors.As(err, &errNoSuchProcess{}) {
return nil
}
}
waitTimeout := 10 * time.Second
if runtime.GOOS == "windows" {
waitTimeout = 75 * time.Second // runhcs can be sloooooow.
}
ctx, cancel := context.WithTimeout(context.Background(), waitTimeout)
defer cancel()
status := <-container.Wait(ctx, containerpkg.WaitConditionNotRunning)
if status.Err() == nil {
return nil
}
log.G(ctx).WithFields(log.Fields{"error": status.Err(), "container": container.ID}).Warnf("Container failed to exit within %v of kill - trying direct SIGKILL", waitTimeout)
if err := killProcessDirectly(container); err != nil {
if errors.As(err, &errNoSuchProcess{}) {
return nil
}
return err
}
// wait for container to exit one last time, if it doesn't then kill didnt work, so return error
ctx2, cancel2 := context.WithTimeout(context.Background(), 2*time.Second)
defer cancel2()
if status := <-container.Wait(ctx2, containerpkg.WaitConditionNotRunning); status.Err() != nil {
return errors.New("tried to kill container, but did not receive an exit event")
}
return nil
}
// killPossiblyDeadProcess is a wrapper around killSig() suppressing "no such process" error.
func (daemon *Daemon) killPossiblyDeadProcess(container *containerpkg.Container, sig syscall.Signal) error {
err := daemon.killWithSignal(container, sig)
if errdefs.IsNotFound(err) {
err = errNoSuchProcess{container.GetPID(), sig}
log.G(context.TODO()).Debug(err)
return err
}
return err
}