add fields such as CONTAINER_NAME to journald log entries sent to by containers #3667

haytok · 2024-11-12T15:21:31Z

In the current implementation, containers running by nerdctl don't
export entries containing fileds such as CONTAINER_NAME, IMAGE_NAME
, and etc to the journald log like containers runnging by docker cli.

At this time, the journald log entry describes below when sending to the journald log using nerdctl.

Details

> nerdctl run -d --name nginx-nerdctl --log-driver=journald nginx
bb7df47d27fd73426cec286ed88c5abf1443e74df637e2440d2dbca7229a84dc

> nerdctl ps
CONTAINER ID    IMAGE                             COMMAND                   CREATED          STATUS    PORTS    NAMES
bb7df47d27fd    docker.io/library/nginx:latest    "/docker-entrypoint.…"    3 seconds ago    Up                 nginx-nerdctl

> sudo journalctl SYSLOG_IDENTIFIER=bb7df47d27fd -a -n 1 -o json-pretty
{
        "__CURSOR" : "???",
        "__REALTIME_TIMESTAMP" : "1730899940827182",
        "__MONOTONIC_TIMESTAMP" : "10815937979908",
        "_BOOT_ID" : "???",
        "_UID" : "0",
        "_GID" : "0",
        "_CAP_EFFECTIVE" : "1ffffffffff",
        "_MACHINE_ID" : "???",
        "_HOSTNAME" : "???.us-west-2.amazon.com",
        "_TRANSPORT" : "journal",
        "_SYSTEMD_SLICE" : "system.slice",
        "PRIORITY" : "3",
        "_SYSTEMD_CGROUP" : "/system.slice/containerd.service",
        "_SYSTEMD_UNIT" : "containerd.service",
        "_COMM" : "nerdctl",
        "_EXE" : "/usr/local/bin/nerdctl",
        "_CMDLINE" : "/usr/local/bin/nerdctl _NERDCTL_INTERNAL_LOGGING /var/lib/nerdctl/1935db59",
        "SYSLOG_IDENTIFIER" : "bb7df47d27fd",
        "_PID" : "8118",
        "MESSAGE" : "2024/11/06 13:32:20 [notice] 1#1: start worker process 44",
        "_SOURCE_REALTIME_TIMESTAMP" : "1730899940825905"
}

On the other hand, the output fields are listed below when we use the journald logging driver with docker cli.

https://docs.docker.com/engine/logging/drivers/journald/

As you can see, some entries are not output by nerdctl and are incompatible with docker cli.

This feature request is reported in the following:

journald log driver doesn't work as advertised #3486

Therefore, in this pull request, we will add the fields to be output in
the journald log.

After applying this fix, the journald log will output the following
fields.

Details

> sudo journalctl SYSLOG_IDENTIFIER=fe22eccbd704 -a -n 1 -o json-pretty
{
  "__CURSOR": "???",
  "__REALTIME_TIMESTAMP": "1731385591671422",
  "__MONOTONIC_TIMESTAMP": "11301588824148",
  "_BOOT_ID": "???",
  "_MACHINE_ID": "???",
  "_HOSTNAME": "???.us-west-2.amazon.com",
  "PRIORITY": "3",
  "_TRANSPORT": "journal",
  "_UID": "0",
  "_GID": "0",
  "_COMM": "nerdctl",
  "_EXE": "/usr/local/bin/nerdctl",
  "_CMDLINE": "/usr/local/bin/nerdctl _NERDCTL_INTERNAL_LOGGING /var/lib/nerdctl/1935db59",
  "_CAP_EFFECTIVE": "1ffffffffff",
  "_SYSTEMD_CGROUP": "/system.slice/containerd.service",
  "_SYSTEMD_UNIT": "containerd.service",
  "_SYSTEMD_SLICE": "system.slice",
  "CONTAINER_NAME": "nginx-nerdctl",
  "IMAGE_NAME": "nginx",
  "CONTAINER_ID_FULL": "fe22eccbd704ba799785999079ac465ed067d5914e9e3f1020e769921d5a83c5",
  "SYSLOG_IDENTIFIER": "fe22eccbd704",
  "CONTAINER_TAG": "fe22eccbd704",
  "CONTAINER_ID": "fe22eccbd704",
  "_PID": "31643",
  "MESSAGE": "2024/11/12 04:26:31 [notice] 1#1: start worker process 44",
  "_SOURCE_REALTIME_TIMESTAMP": "1731385591669765"
}

Note that details are described in each commits.

haytok · 2024-11-12T16:08:54Z

The following PR will resolve CI faillures of lint / go | windows and lint / go | linux.

refactor: Fix golanglint action error #3666

haytok · 2024-11-12T16:11:35Z

The following error in CI is related to this modification, so I'll investigate to resolve.

=== Failed
=== FAIL: cmd/nerdctl/container TestRunWithJournaldLogDriver/filter_using_IMAGE_NAME_field (20.00s)
    container_run_test.go:368: timeout hit after 20s: reading from journald is not yet finished

=== FAIL: cmd/nerdctl/container TestRunWithJournaldLogDriver (23.27s)

=== FAIL: cmd/nerdctl/container TestRunWithJournaldLogDriver/filter_using_IMAGE_NAME_field (re-run 1) (20.00s)
    container_run_test.go:368: timeout hit after 20s: reading from journald is not yet finished

=== FAIL: cmd/nerdctl/container TestRunWithJournaldLogDriver (re-run 1) (23.30s)

=== FAIL: cmd/nerdctl/container TestRunWithJournaldLogDriver/filter_using_IMAGE_NAME_field (re-run 2) (20.00s)
    container_run_test.go:368: timeout hit after 20s: reading from journald is not yet finished

=== FAIL: cmd/nerdctl/container TestRunWithJournaldLogDriver (re-run 2) (23.28s)

DONE 3 runs, 481 tests, 123 skipped, 6 failures in 767.586s
Error: Process completed with exit code 1.

haytok · 2024-11-12T17:07:28Z

After my investigation, I checked the docker cli doc and found no description of the details output in the IMAGE_NAME field.
However, it was confirmed that the current implementation (nerdctl) and the docker cli differ in the behaviour of the output to IMAGE_NAME in the image's Tag.

https://docs.docker.com/engine/logging/drivers/journald/

IMAGE_NAME The name of the container image.

Details

In case of Docker

> CONTAINER_NAME="issue_3486"
> d run --rm --name $CONTAINER_NAME --log-driver=journald ghcr.io/stargz-containers/alpine:3.13-org sh -euxc "echo foo; echo bar"

+ echo foo
+ echo bar
foo
bar

> sudo journalctl CONTAINER_NAME=$CONTAINER_NAME -a -n 1 -o json-pretty | grep IMAGE_NAME
	"IMAGE_NAME" : "ghcr.io/stargz-containers/alpine:3.13-org",

In case of nerdctl in this modification.

> nerdctl run --rm --name $CONTAINER_NAME --log-driver=journald ghcr.io/stargz-containers/alpine:3.13-org sh -euxc "echo foo; echo bar"
+ echo foo
+ echofoo
bar
 bar

> sudo journalctl CONTAINER_NAME=$CONTAINER_NAME -a -n 1 -o json-pretty | grep IMAGE_NAME
	"IMAGE_NAME" : "ghcr.io/stargz-containers/alpine",

Therefore, the IMAGE_NAME of the entry that nerdctl outputs to the journald log should be modified to be docker-compatible.

haytok · 2024-11-13T14:45:52Z

CI passed except for the lint issue which will be fixed in PR 3666.

AkihiroSuda · 2024-11-20T01:00:50Z

CI passed except for the lint issue which will be fixed in PR 3666.

Could you rebase with the current main branch?

This pull request will add the fields such as `CONTAINER_NAME` and `IMAGE_NAME` to the journald log entries sent by containers when `nerdctl run` is run with `--log-driver=journald`. However, the following `import cycle not allowed` error occurs when trying to import `containerutil package` in `logging package` in the implementation to be changed in this pull request. ``` > make CGO_ENABLED=0 GOOS=linux go -C /local/home/haytok/workspace/nerdctl build -ldflags "-s -w -X github.com/containerd/nerdctl/v2/pkg/version.Version=0d7dc8ec.m -X github.com/containerd/nerdctl/v2/pkg/version.Revision=0d7dc8ec4cda815acfca165b0281e801c4c5ef6e.m" -o /local/home/haytok/workspace/nerdctl/_output/nerdctl ./cmd/nerdctl package github.com/containerd/nerdctl/v2/cmd/nerdctl ... imports github.com/containerd/nerdctl/v2/pkg/infoutil: import cycle not allowed make: *** [nerdctl] Error 1 ``` Therefore, this commit refactors `infoutil package` to avoid `import cycle not allowd` error in the next commit. Signed-off-by: Hayato Kiwata <haytok@amazon.co.jp>

haytok · 2024-11-20T02:46:53Z

@AkihiroSuda

Thanks, I forgot to rebase ...
I rebased and pushed.

Zheaoli

LGTM

BTW, I'm not sure whether we should let people config the log field they want

pkg/logging/journald_logger.go

haytok · 2024-11-21T04:26:10Z

Hi @fahedouch
I have fixed based on your review, so could you re-review when you have time?

fahedouch · 2024-11-21T11:12:19Z

pkg/logging/journald_logger.go

+
+func GetJournaldImageNameField(image string) string {
+	imageName := image
+	if repo, tag := imgutil.ParseRepoTag(imageName); tag == "latest" {


is it disturbing to to have a latest tag ?

I would rather check for empty tag using this func

@fahedouch, Thanks!!!

I have not considered dangling image ...
Considering the behaviour in Docker, I think the name that should be specified in IMAGE_NAME can be categorized into the following 3 types.

dangling Image

tag of Image is latest

tag of Image isn't latest (ex. 3.13-org)

The following is the result of checking each case with Docker.

Details

In case of a dangling image

> CONTAINER_NAME="none-image" > NONE_IMAGE_ID="3b25b682ea82" > d images | grep $NONE_IMAGE_ID <none> <none> 3b25b682ea82 7 weeks ago 192MB > d run --rm --name $CONTAINER_NAME --log-driver=journald $NONE_IMAGE_ID sh -euxc "echo foo; echo bar" + echo foo + echo bar foo bar > sudo journalctl -a CONTAINER_NAME=$CONTAINER_NAME -n 1 -o json-pretty | grep $NONE_IMAGE_ID "IMAGE_NAME" : "3b25b682ea82",

In case of an image which has latest tag.

> CONTAINER_NAME="latest-image" > LATEST_IMAGE="debian" > d images | grep $LATEST_IMAGE debian latest 617f2e89852e 5 weeks ago 117MB > d run --rm --name $CONTAINER_NAME --log-driver=journald $LATEST_IMAGE sh -euxc "echo foo; echo bar" + echo foo + echo bar foo bar > sudo journalctl -a CONTAINER_NAME=$CONTAINER_NAME -n 1 -o json-pretty | grep $LATEST_IMAGE "IMAGE_NAME" : "debian",

In case of an image which dosen't have latest tag.

> CONTAINER_NAME="tag-image" > TAG_IMAGE="ghcr.io/stargz-containers/alpine:3.13-org" > d images | grep ghcr.io/stargz-containers/alpine ghcr.io/stargz-containers/alpine 3.13-org 49f356fa4513 3 years ago 5.61MB > d run --rm --name $CONTAINER_NAME --log-driver=journald $TAG_IMAGE sh -euxc "echo foo; echo bar" + echo foo + echo bar foo bar > sudo journalctl -a CONTAINER_NAME=$CONTAINER_NAME -n 1 -o json-pretty | grep $TAG_IMAGE "IMAGE_NAME" : "ghcr.io/stargz-containers/alpine:3.13-org",

Therefore, I think it is necessary to distinguish between the cases where the dangling image / tag is latest / tag is other than latest, but what do you think?

The current fix does not take into account the case of dangling image, so I'll fix that.

Also, I'll add a test for the case where tag is latest.

thanks for your feedback @haytok, LGTM!

Thanks for the comments!!! @fahedouch
When implementing tests, I noticed that Docker displays the image name specified when running a container in the IMAGE_NAME field ...

For example, we can check this behavior when running a container using the following image (ghcr.io/containerd/busybox:latest).

Details

> CONTAINER_NAME="latest-image" > LATEST_IMAGE="ghcr.io/containerd/busybox:latest" > d images | grep ghcr.io/containerd/busybox ghcr.io/containerd/busybox latest 16ea53ea7c65 3 years ago 1.24MB > d run --rm --name $CONTAINER_NAME --log-driver=journald $LATEST_IMAGE sh -euxc "echo foo; echo bar" + echo foo + echo bar foo bar > sudo journalctl -a CONTAINER_NAME=$CONTAINER_NAME -n 1 -o json-pretty | grep $LATEST_IMAGE "IMAGE_NAME" : "ghcr.io/containerd/busybox:latest",

This behavior makes sense in the three cases above.
Therefore, I think it's not necessary to split the process according to the tag of image, so I'll fix the commit to delete GetJournaldImageNameField().

…o by containers In the current implementation, containers running by `nerdctl` dose not export entries containing fields such as `CONTAINER_NAME`, `IMAGE_NAME` , and etc to the journald log like containers running by `docker cli`. At this time, the journald log entry describes below when sending to the journald log using nerdctl. ``` > nerdctl run -d --name nginx-nerdctl --log-driver=journald nginx bb7df47d27fd73426cec286ed88c5abf1443e74df637e2440d2dbca7229a84dc > nerdctl ps CONTAINER ID IMAGE COMMAND CREATED STATUS PORTS NAMES bb7df47d27fd docker.io/library/nginx:latest "/docker-entrypoint.…" 3 seconds ago Up nginx-nerdctl > sudo journalctl SYSLOG_IDENTIFIER=bb7df47d27fd -a -n 1 -o json-pretty { "__CURSOR" : "???", "__REALTIME_TIMESTAMP" : "1730899940827182", "__MONOTONIC_TIMESTAMP" : "10815937979908", "_BOOT_ID" : "???", "_UID" : "0", "_GID" : "0", "_CAP_EFFECTIVE" : "1ffffffffff", "_MACHINE_ID" : "???", "_HOSTNAME" : "???.us-west-2.amazon.com", "_TRANSPORT" : "journal", "_SYSTEMD_SLICE" : "system.slice", "PRIORITY" : "3", "_SYSTEMD_CGROUP" : "/system.slice/containerd.service", "_SYSTEMD_UNIT" : "containerd.service", "_COMM" : "nerdctl", "_EXE" : "/usr/local/bin/nerdctl", "_CMDLINE" : "/usr/local/bin/nerdctl _NERDCTL_INTERNAL_LOGGING /var/lib/nerdctl/1935db59", "SYSLOG_IDENTIFIER" : "bb7df47d27fd", "_PID" : "8118", "MESSAGE" : "2024/11/06 13:32:20 [notice] 1#1: start worker process 44", "_SOURCE_REALTIME_TIMESTAMP" : "1730899940825905" } ``` On the other hand, the output fields are listed below when we use the journald logging driver with docker cli. - https://docs.docker.com/engine/logging/drivers/journald/ As you can see, some entries are not output by nerdctl and are incompatible with the docker cli. This feature request is reported in the following: - containerd#3486 Therefore, in this pull request, we will add the fields to be output in the journald log. After applying this fix, the journald log will output the following fields. ``` { "__CURSOR": "???", "__REALTIME_TIMESTAMP": "1731385591671422", "__MONOTONIC_TIMESTAMP": "11301588824148", "_BOOT_ID": "???", "_MACHINE_ID": "???", "_HOSTNAME": "???.us-west-2.amazon.com", "PRIORITY": "3", "_TRANSPORT": "journal", "_UID": "0", "_GID": "0", "_COMM": "nerdctl", "_EXE": "/usr/local/bin/nerdctl", "_CMDLINE": "/usr/local/bin/nerdctl _NERDCTL_INTERNAL_LOGGING /var/lib/nerdctl/1935db59", "_CAP_EFFECTIVE": "1ffffffffff", "_SYSTEMD_CGROUP": "/system.slice/containerd.service", "_SYSTEMD_UNIT": "containerd.service", "_SYSTEMD_SLICE": "system.slice", "CONTAINER_NAME": "nginx-nerdctl", "IMAGE_NAME": "nginx", "CONTAINER_ID_FULL": "fe22eccbd704ba799785999079ac465ed067d5914e9e3f1020e769921d5a83c5", "SYSLOG_IDENTIFIER": "fe22eccbd704", "CONTAINER_TAG": "fe22eccbd704", "CONTAINER_ID": "fe22eccbd704", "_PID": "31643", "MESSAGE": "2024/11/12 04:26:31 [notice] 1#1: start worker process 44", "_SOURCE_REALTIME_TIMESTAMP": "1731385591669765" } ``` Signed-off-by: Hayato Kiwata <haytok@amazon.co.jp>

Zheaoli requested review from Zheaoli and fahedouch November 12, 2024 16:07

Zheaoli added area/logging enhancement New feature or request labels Nov 12, 2024

haytok force-pushed the issue_3486 branch from f2cdd5f to 16a7a55 Compare November 13, 2024 10:27

fahedouch added this to the v2.1.0 milestone Nov 19, 2024

haytok force-pushed the issue_3486 branch from 16a7a55 to deb3ea5 Compare November 20, 2024 01:49

Zheaoli approved these changes Nov 20, 2024

View reviewed changes

fahedouch reviewed Nov 20, 2024

View reviewed changes

pkg/logging/journald_logger.go Outdated Show resolved Hide resolved

haytok force-pushed the issue_3486 branch 2 times, most recently from a9df3e5 to 67f0a10 Compare November 21, 2024 03:25

fahedouch reviewed Nov 21, 2024

View reviewed changes

haytok force-pushed the issue_3486 branch from 67f0a10 to 4ab45b9 Compare November 23, 2024 06:15

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

add fields such as CONTAINER_NAME to journald log entries sent to by containers #3667

add fields such as CONTAINER_NAME to journald log entries sent to by containers #3667

haytok commented Nov 12, 2024

haytok commented Nov 12, 2024 •

edited

Loading

haytok commented Nov 12, 2024

haytok commented Nov 12, 2024

haytok commented Nov 13, 2024

AkihiroSuda commented Nov 20, 2024

haytok commented Nov 20, 2024

Zheaoli left a comment

haytok commented Nov 21, 2024

fahedouch Nov 21, 2024

haytok Nov 21, 2024 •

edited

Loading

haytok Nov 21, 2024

fahedouch Nov 21, 2024

haytok Nov 23, 2024

add fields such as CONTAINER_NAME to journald log entries sent to by containers #3667

Are you sure you want to change the base?

add fields such as CONTAINER_NAME to journald log entries sent to by containers #3667

Conversation

haytok commented Nov 12, 2024

haytok commented Nov 12, 2024 • edited Loading

haytok commented Nov 12, 2024

haytok commented Nov 12, 2024

haytok commented Nov 13, 2024

AkihiroSuda commented Nov 20, 2024

haytok commented Nov 20, 2024

Zheaoli left a comment

Choose a reason for hiding this comment

haytok commented Nov 21, 2024

fahedouch Nov 21, 2024

Choose a reason for hiding this comment

haytok Nov 21, 2024 • edited Loading

Choose a reason for hiding this comment

haytok Nov 21, 2024

Choose a reason for hiding this comment

fahedouch Nov 21, 2024

Choose a reason for hiding this comment

haytok Nov 23, 2024

Choose a reason for hiding this comment

haytok commented Nov 12, 2024 •

edited

Loading

haytok Nov 21, 2024 •

edited

Loading