Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Timestamps in 'image list' inconsistent with 'image history' #14456

Closed
edsantiago opened this issue Jun 2, 2022 · 6 comments · Fixed by #14529
Closed

Timestamps in 'image list' inconsistent with 'image history' #14456

edsantiago opened this issue Jun 2, 2022 · 6 comments · Fixed by #14529
Labels
locked - please file new issue/PR Assist humans wanting to comment on an old issue or PR with locked comments.

Comments

@edsantiago
Copy link
Member

Reported by multiarch team in their gitlab tracker

On multiarch, one of the podman image history tests is failing:

[+0011s] # #/vvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvv
[+0011s] # #|     FAIL: CreatedSince and CreatedAt from image history should == image list
[+0011s] # #| expected: '11 months ago--2021-06-10 18:55:50 +0000 UTC'
[+0011s] # #|   actual: '11 months ago--2021-06-10 18:55:51 +0000 UTC'
[+0011s] # #\^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^

Reason: that test runs podman image list $IMAGE and podman image history $IMAGE, and assumes that the first line of history should match the timestamp of list. It does not. Neither does it match the last line.

Reproducer (well, not really, but a one-liner that demonstrates the problem):

$ iii=quay.io/libpod/testimage:20210610
$ for arch in amd64 arm64 ppc64le s390x;do echo;echo $arch;bin/podman rmi $iii >/dev/null;bin/podman pull -q --arch=$arch $iii;bin/podman image list --format="list> {{.CreatedAt}}" $iii;bin/podman image history --format="      {{.CreatedAt}} {{.CreatedBy}}" $iii;done

amd64
9f9ec7f2fdef9168f74e9d057f307955db14d782cff22ded51d277d74798cb2f
list> 2021-06-10 18:55:43 +0000 UTC
      2021-06-10 18:55:43 +0000 UTC /bin/sh -c #(nop) CMD ["/bin/echo", "This ...
      2021-06-10 18:55:43 +0000 UTC /bin/sh -c #(nop) WORKDIR /home/podman
      2021-06-10 18:55:43 +0000 UTC /bin/sh -c #(nop) LABEL created_at=2021-06...
      2021-06-10 18:55:43 +0000 UTC /bin/sh -c #(nop) LABEL created_by=test/sy...
      2021-06-10 18:55:43 +0000 UTC /bin/sh -c #(nop) ADD multi:0ed825786ec124...
      2021-06-10 18:55:42 +0000 UTC /bin/sh -c apk add busybox-extras

arm64
d47f52704fad91e7a4f450ba8e31e95db186a0516005309747c888f19969fdbd
list> 2021-06-10 18:55:50 +0000 UTC
      2021-06-10 18:55:51 +0000 UTC /bin/sh -c #(nop) CMD ["/bin/echo", "This ...
      2021-06-10 18:55:50 +0000 UTC /bin/sh -c #(nop) WORKDIR /home/podman
      2021-06-10 18:55:50 +0000 UTC /bin/sh -c #(nop) LABEL created_at=2021-06...
      2021-06-10 18:55:50 +0000 UTC /bin/sh -c #(nop) LABEL created_by=test/sy...
      2021-06-10 18:55:50 +0000 UTC /bin/sh -c #(nop) ADD multi:0ed825786ec124...
      2021-06-10 18:55:50 +0000 UTC /bin/sh -c apk add busybox-extras

ppc64le
ffbfb81a72a975998e7148cc224ac095fc30c328a3cd686aefab4859e6d3a22b
list> 2021-06-10 18:55:59 +0000 UTC
      2021-06-10 18:56:00 +0000 UTC /bin/sh -c #(nop) CMD ["/bin/echo", "This ...
      2021-06-10 18:55:59 +0000 UTC /bin/sh -c #(nop) WORKDIR /home/podman
      2021-06-10 18:55:59 +0000 UTC /bin/sh -c #(nop) LABEL created_at=2021-06...
      2021-06-10 18:55:59 +0000 UTC /bin/sh -c #(nop) LABEL created_by=test/sy...
      2021-06-10 18:55:59 +0000 UTC /bin/sh -c #(nop) ADD multi:0ed825786ec124...
      2021-06-10 18:55:59 +0000 UTC /bin/sh -c apk add busybox-extras

s390x
8ae9b542c6291490b44995965dc03fabe5f4a6305bb49ab4066645e2c25e0eb5
list> 2021-06-10 18:56:07 +0000 UTC
      2021-06-10 18:56:08 +0000 UTC /bin/sh -c #(nop) CMD ["/bin/echo", "This ...
      2021-06-10 18:56:07 +0000 UTC /bin/sh -c #(nop) WORKDIR /home/podman
      2021-06-10 18:56:07 +0000 UTC /bin/sh -c #(nop) LABEL created_at=2021-06...
      2021-06-10 18:56:07 +0000 UTC /bin/sh -c #(nop) LABEL created_by=test/sy...
      2021-06-10 18:56:07 +0000 UTC /bin/sh -c #(nop) ADD multi:0ed825786ec124...
      2021-06-10 18:56:07 +0000 UTC /bin/sh -c apk add busybox-extras

Note that sometimes the image list timestamp matches the first line from history, and sometimes the last.

Test code:

@test "podman image history Created" {
# Values from image LIST
run_podman image list --format '{{.CreatedSince}}--{{.CreatedAt}}' $IMAGE
from_imagelist="$output"
assert "$from_imagelist" =~ "^[0-9].* ago--[0-9]+-[0-9]+-[0-9]+ [0-9:]+ " \
"CreatedSince and CreatedAt look reasonable"
# Values from image HISTORY
run_podman image history --format '{{.CreatedSince}}--{{.CreatedAt}}' $IMAGE
assert "${lines[0]}" == "$from_imagelist" \
"CreatedSince and CreatedAt from image history should == image list"
}

Questions:

  • Where does podman image list get its timestamp from?
  • How can we fix this test so it is reliable, not just on this image but on all future ones?
@rhatdan
Copy link
Member

rhatdan commented Jun 2, 2022

One would think this is a conversion error. podman image list and podman history converting the timestamp differently and potentially one rounding up, while the other rounds down?

@vrothberg
Copy link
Member

vrothberg commented Jun 2, 2022

I'll take a look

@edsantiago
Copy link
Member Author

converting the timestamp differently

That's a really good suggestion - I had forgotten about fractional time_t. Does anyone know how to actually show that? Command completion shows me all sorts of promising fields, but none of them actually work:

$ bin/podman image history --format '{{.Created.' quay.io/libpod/testimage:20210610
{{.Created.Add           -- This is a function and requires 1 argument
{{.Created.AddDate       -- This is a function and requires 3 arguments
{{.Created.After         -- This is a function and requires 1 argument
{{.Created.AppendFormat  -- This is a function and requires 2 arguments
{{.Created.Before        -- This is a function and requires 1 argument
{{.Created.Equal         -- This is a function and requires 1 argument
{{.Created.Format        -- This is a function and requires 1 argument
{{.Created.In            -- This is a function and requires 1 argument
{{.Created.Round         -- This is a function and requires 1 argument
{{.Created.Sub           -- This is a function and requires 1 argument
{{.Created.Truncate      -- This is a function and requires 1 argument
{{.Created.Day}}         {{.Created.Month}}       {{.Created.Unix}}      
{{.Created.Hour}}        {{.Created.Nanosecond}}  {{.Created.Weekday}}   
{{.Created.IsZero}}      {{.Created.Second}}      {{.Created.YearDay}}   
{{.Created.Local.        {{.Created.String}}      {{.Created.Year}}      
{{.Created.Location}}    {{.Created.UTC.                                 
{{.Created.Minute}}      {{.Created.UnixNano}}      
$ bin/podman image history --format '{{.Created.UnixNano}}' quay.io/libpod/testimage:20210610
Error: template: history:1:21: executing "history" at <.Created.UnixNano>: can't evaluate field UnixNano in type string

@vrothberg
Copy link
Member

I got it ... I'll spin up a PR but I am unable to create a reproducer.

vrothberg added a commit to vrothberg/libpod that referenced this issue Jun 3, 2022
As shown in containers#14456, the `.CreatedAt` fields for `image list` and of
`image history` can differ by one.  The discussed theory is that the
off-by-one is caused by rounding.

Indeed, the field of `image list` is reformatted.  `image history` is
returning the UNIX time; just as the `.CreatedAt` field should.

I am unable to create a reproducer for the issue but double-checked
what the docker client does: return the UNIX time.

[NO NEW TESTS NEEDED]

Fixes: containers#14456
Signed-off-by: Valentin Rothberg <[email protected]>
@vrothberg
Copy link
Member

I gave it a shot in #14476 but I should have taken a closer look at the image. In short:

  • Docker behaves the very same
  • The image returns this data

skopeo inspect --config reveals it:

{
    "created": "2021-06-10T18:55:50.902166709Z",
     [...]
        {
            "created": "2021-06-10T18:55:51.011052917Z",
            "created_by": "/bin/sh -c #(nop) CMD [\"/bin/echo\", \"This container is intended for podman CI testing\"]",
            "comment": "FROM docker.io/arm64v8/alpine:3.13.5"
        }
    ]
}

The image was created before the first layer. Ultimately, it looks a fart in the tool that built the image. I suggest to either change this test or pin it to an image that is known to work (via --arch=xxx).

@edsantiago
Copy link
Member Author

okay, got it: the image .created timestamp bears no relation to those in the history array:

$ bin/podman pull -q --arch=ppc64le $iii
$ skopeo inspect --config containers-storage:$iii|gron|grep -w created|column -t -s= -c 60
json.created               "2021-06-10T18:55:59.923932059Z";     <------ this
json.history[0].created    "2021-06-10T18:55:59.669999782Z";
json.history[1].created    "2021-06-10T18:55:59.881513564Z";
json.history[2].created    "2021-06-10T18:55:59.881544593Z";
json.history[3].created    "2021-06-10T18:55:59.881556911Z";
json.history[4].created    "2021-06-10T18:55:59.901991948Z";
json.history[5].created    "2021-06-10T18:56:00.030467643Z";    <----- is not the same as this

I think I could fix this by building a new testimage using the --timestamp option. I'll look into that today.

edsantiago added a commit to edsantiago/libpod that referenced this issue Jun 15, 2022
Changes:
 - use --timestamp option to produce 'created' stamps
   that can be reliably tested in the image-history test

 - podman now supports manifest & multiarch run, so we
   no longer need buildah

 - bump up base alpine & busybox images

This turned out to be WAY more complicated than it should've been,
because:

 - alpine 3.14 fixed 'date -Iseconds' to include a colon in
   the TZ offset ("-07:00", was "-0700"). This is now consistent
   with GNU date's --iso-8601 format, yay, so we can eliminate
   a minor workaround.

 - with --timestamp, all ADDed files are set to that timestamp,
   including the custom-reference-timestamp file that many tests
   rely on. So we need to split the build into two steps. But:

 - ...with a two-step build I need to use --squash-all, not --squash, but:

 - ... (deep sigh) --squash-all doesn't work with --timestamp (containers#14536)
   so we need to alter existing tests to deal with new image layers.

 - And, long and sordid story relating to --rootfs. TL;DR that option
   only worked by a miracle relating to something special in one
   specific test image; it doesn't work with any other images. Fix
   seems to be complicated, so we're bypassing with a FIXME (containers#14505).

And, unrelated:

 - remove obsolete skip and workaround in run-basic test (dating
   back to varlink days)
 - add a pause-image cleanup to avoid icky red warnings in logs

Fixes: containers#14456

Signed-off-by: Ed Santiago <[email protected]>
@github-actions github-actions bot added the locked - please file new issue/PR Assist humans wanting to comment on an old issue or PR with locked comments. label Sep 20, 2023
@github-actions github-actions bot locked as resolved and limited conversation to collaborators Sep 20, 2023
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
locked - please file new issue/PR Assist humans wanting to comment on an old issue or PR with locked comments.
Projects
None yet
3 participants