Skip to content

daemon: killWithSignal: use more structured logs#48673

Merged
thaJeztah merged 1 commit intomoby:masterfrom
thaJeztah:daemon_kill_logs
Oct 16, 2024
Merged

daemon: killWithSignal: use more structured logs#48673
thaJeztah merged 1 commit intomoby:masterfrom
thaJeztah:daemon_kill_logs

Conversation

@thaJeztah
Copy link
Copy Markdown
Member

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"}

- Description for the changelog

- A picture of a cute animal (not mandatory but encouraged)

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 <[email protected]>
@thaJeztah thaJeztah added status/2-code-review kind/enhancement Enhancements are not bugs or new features but can improve usability or performance. area/daemon Core Engine labels Oct 15, 2024
@thaJeztah thaJeztah added this to the 28.0.0 milestone Oct 15, 2024
@thaJeztah thaJeztah self-assigned this Oct 15, 2024
Copy link
Copy Markdown
Contributor

@austinvazquez austinvazquez left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

+1 for structured logging.

@thaJeztah thaJeztah merged commit b849b4d into moby:master Oct 16, 2024
@thaJeztah thaJeztah deleted the daemon_kill_logs branch October 16, 2024 12:00
@thaJeztah
Copy link
Copy Markdown
Member Author

For the name of signals, I started looking at the moby/sys/signals package to provide a reverse mapping (signal -> string) as an alternative to Go's built-in .String() for these.

We have these maps; https://github.com/moby/sys/blob/e9445a405da6189ad668a7189c49f20c094b1422/signal/signal_darwin.go

But the fun thing is that entries are not unique on some platforms. For example, on darwin, syscall.SIGIOT and syscall.SIGABRT have the same value (both are 6) 😂

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

area/daemon Core Engine kind/enhancement Enhancements are not bugs or new features but can improve usability or performance. status/2-code-review

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants