search

moby / buildkit

concurrent, cache-efficient, and Dockerfile-agnostic builder toolkit
https://github.com/moby/moby/issues/34227
Apache License 2.0
8.09k stars 1.14k forks source link

Flaky test: `TestHistoryError/worker=containerd-1.6` #5122

Closed crazy-max closed 2 months ago

crazy-max commented 3 months ago

https://github.com/moby/buildkit/actions/runs/9781065516/job/27004380153?pr=5121#step:8:1490

=== FAIL: frontend/dockerfile TestIntegration/TestHistoryError/worker=containerd-1.6/frontend=gateway (1.89s)
    dockerfile_test.go:7453: 
            Error Trace:    /src/frontend/dockerfile/dockerfile_test.go:7453
                                        /src/util/testutil/integration/run.go:96
                                        /src/util/testutil/integration/run.go:211
            Error:          Not equal: 
                            expected: true
                            actual  : false
            Test:           TestIntegration/TestHistoryError/worker=containerd-1.6/frontend=gateway
    sandbox.go:133: stderr: /opt/containerd-alt-16/bin/containerd --config /tmp/bktest_containerd2972322853/config.toml
    sandbox.go:136: > StartCmd 2024-07-03 16:05:17.184490194 +0000 UTC m=+11.340196434 /opt/containerd-alt-16/bin/containerd --config /tmp/bktest_containerd2972322853/config.toml
    sandbox.go:136: time="2024-07-03T16:05:17Z" level=warning msg="containerd config version `1` has been deprecated and will be converted on each startup in containerd v2.0, use `containerd config migrate` after upgrading to containerd 2.0 to avoid conversion on startup"
    sandbox.go:136: time="2024-07-03T16:05:17.205769749Z" level=info msg="starting containerd" revision=d2d58213f83a351ca8f528a95fbd145f5654e957 version=v1.6.33
    sandbox.go:136: time="2024-07-03T16:05:17.233153043Z" level=info msg="loading plugin \"io.containerd.content.v1.content\"..." type=io.containerd.content.v1
    sandbox.go:136: time="2024-07-03T16:05:17.233359991Z" level=info msg="loading plugin \"io.containerd.snapshotter.v1.devmapper\"..." type=io.containerd.snapshotter.v1
    sandbox.go:136: time="2024-07-03T16:05:17.233410996Z" level=warning msg="failed to load plugin io.containerd.snapshotter.v1.devmapper" error="devmapper not configured"
    sandbox.go:136: time="2024-07-03T16:05:17.233441674Z" level=info msg="loading plugin \"io.containerd.snapshotter.v1.native\"..." type=io.containerd.snapshotter.v1
    sandbox.go:136: time="2024-07-03T16:05:17.233567309Z" level=info msg="loading plugin \"io.containerd.snapshotter.v1.overlayfs\"..." type=io.containerd.snapshotter.v1
    sandbox.go:136: time="2024-07-03T16:05:17.233891757Z" level=info msg="loading plugin \"io.containerd.snapshotter.v1.aufs\"..." type=io.containerd.snapshotter.v1
    sandbox.go:136: time="2024-07-03T16:05:17.234689661Z" level=info msg="skip loading plugin \"io.containerd.snapshotter.v1.aufs\"..." error="aufs is not supported (modprobe aufs failed: exit status 1 \"modprobe: can't change directory to '/lib/modules': No such file or directory\\n\"): skip plugin" type=io.containerd.snapshotter.v1
    sandbox.go:136: time="2024-07-03T16:05:17.234742871Z" level=info msg="loading plugin \"io.containerd.snapshotter.v1.zfs\"..." type=io.containerd.snapshotter.v1
    sandbox.go:136: time="2024-07-03T16:05:17.235012967Z" level=info msg="skip loading plugin \"io.containerd.snapshotter.v1.zfs\"..." error="path /tmp/bktest_containerd2972322853/root/io.containerd.snapshotter.v1.zfs must be a zfs filesystem to be used with the zfs snapshotter: skip plugin" type=io.containerd.snapshotter.v1
    sandbox.go:136: time="2024-07-03T16:05:17.235062139Z" level=info msg="loading plugin \"io.containerd.metadata.v1.bolt\"..." type=io.containerd.metadata.v1
    sandbox.go:136: time="2024-07-03T16:05:17.235146066Z" level=warning msg="could not use snapshotter devmapper in metadata plugin" error="devmapper not configured"
    sandbox.go:136: time="2024-07-03T16:05:17.235189868Z" level=info msg="metadata content store policy set" policy=shared
    sandbox.go:136: time="2024-07-03T16:05:17.238585375Z" level=info msg="loading plugin \"io.containerd.differ.v1.walking\"..." type=io.containerd.differ.v1
    sandbox.go:136: time="2024-07-03T16:05:17.239194195Z" level=info msg="loading plugin \"io.containerd.event.v1.exchange\"..." type=io.containerd.event.v1
    sandbox.go:136: time="2024-07-03T16:05:17.239249980Z" level=info msg="loading plugin \"io.containerd.gc.v1.scheduler\"..." type=io.containerd.gc.v1
    sandbox.go:136: time="2024-07-03T16:05:17.239294784Z" level=info msg="loading plugin \"io.containerd.runtime.v1.linux\"..." type=io.containerd.runtime.v1
    sandbox.go:136: time="2024-07-03T16:05:17.239488727Z" level=info msg="loading plugin \"io.containerd.runtime.v2.task\"..." type=io.containerd.runtime.v2
    sandbox.go:136: time="2024-07-03T16:05:17.239640281Z" level=info msg="loading plugin \"io.containerd.internal.v1.opt\"..." type=io.containerd.internal.v1
    sandbox.go:136: time="2024-07-03T16:05:17.239688441Z" level=info msg="loading plugin \"io.containerd.warning.v1.deprecations\"..." type=io.containerd.warning.v1
    sandbox.go:136: time="2024-07-03T16:05:17.239707567Z" level=info msg="loading plugin \"io.containerd.monitor.v1.cgroups\"..." type=io.containerd.monitor.v1
    sandbox.go:136: time="2024-07-03T16:05:17.240397940Z" level=info msg="loading plugin \"io.containerd.service.v1.containers-service\"..." type=io.containerd.service.v1
    sandbox.go:136: time="2024-07-03T16:05:17.240425030Z" level=info msg="loading plugin \"io.containerd.service.v1.content-service\"..." type=io.containerd.service.v1
    sandbox.go:136: time="2024-07-03T16:05:17.240444798Z" level=info msg="loading plugin \"io.containerd.service.v1.diff-service\"..." type=io.containerd.service.v1
    sandbox.go:136: time="2024-07-03T16:05:17.240465416Z" level=info msg="loading plugin \"io.containerd.service.v1.images-service\"..." type=io.containerd.service.v1
    sandbox.go:136: time="2024-07-03T16:05:17.240486746Z" level=info msg="loading plugin \"io.containerd.service.v1.introspection-service\"..." type=io.containerd.service.v1
    sandbox.go:136: time="2024-07-03T16:05:17.240506433Z" level=info msg="loading plugin \"io.containerd.service.v1.leases-service\"..." type=io.containerd.service.v1
    sandbox.go:136: time="2024-07-03T16:05:17.240519968Z" level=info msg="loading plugin \"io.containerd.service.v1.namespaces-service\"..." type=io.containerd.service.v1
    sandbox.go:136: time="2024-07-03T16:05:17.240535968Z" level=info msg="loading plugin \"io.containerd.service.v1.snapshots-service\"..." type=io.containerd.service.v1
    sandbox.go:136: time="2024-07-03T16:05:17.240551547Z" level=info msg="loading plugin \"io.containerd.service.v1.tasks-service\"..." type=io.containerd.service.v1
    sandbox.go:136: time="2024-07-03T16:05:17.240570883Z" level=debug msg="No RDT config file specified, RDT not configured"
    sandbox.go:136: time="2024-07-03T16:05:17.240586844Z" level=info msg="loading plugin \"io.containerd.grpc.v1.containers\"..." type=io.containerd.grpc.v1
    sandbox.go:136: time="2024-07-03T16:05:17.240606791Z" level=info msg="loading plugin \"io.containerd.grpc.v1.content\"..." type=io.containerd.grpc.v1
    sandbox.go:136: time="2024-07-03T16:05:17.240620617Z" level=info msg="loading plugin \"io.containerd.grpc.v1.diff\"..." type=io.containerd.grpc.v1
    sandbox.go:136: time="2024-07-03T16:05:17.240634092Z" level=info msg="loading plugin \"io.containerd.grpc.v1.events\"..." type=io.containerd.grpc.v1
    sandbox.go:136: time="2024-07-03T16:05:17.240650964Z" level=info msg="loading plugin \"io.containerd.grpc.v1.images\"..." type=io.containerd.grpc.v1
    sandbox.go:136: time="2024-07-03T16:05:17.240670120Z" level=info msg="loading plugin \"io.containerd.grpc.v1.introspection\"..." type=io.containerd.grpc.v1
    sandbox.go:136: time="2024-07-03T16:05:17.240687692Z" level=info msg="loading plugin \"io.containerd.grpc.v1.leases\"..." type=io.containerd.grpc.v1
    sandbox.go:136: time="2024-07-03T16:05:17.240707620Z" level=info msg="loading plugin \"io.containerd.grpc.v1.namespaces\"..." type=io.containerd.grpc.v1
    sandbox.go:136: time="2024-07-03T16:05:17.240722968Z" level=info msg="loading plugin \"io.containerd.grpc.v1.snapshots\"..." type=io.containerd.grpc.v1
    sandbox.go:136: time="2024-07-03T16:05:17.240742675Z" level=info msg="loading plugin \"io.containerd.grpc.v1.tasks\"..." type=io.containerd.grpc.v1
    sandbox.go:136: time="2024-07-03T16:05:17.240764366Z" level=info msg="loading plugin \"io.containerd.grpc.v1.version\"..." type=io.containerd.grpc.v1
    sandbox.go:136: time="2024-07-03T16:05:17.240781498Z" level=info msg="loading plugin \"io.containerd.tracing.processor.v1.otlp\"..." type=io.containerd.tracing.processor.v1
    sandbox.go:136: time="2024-07-03T16:05:17.240802557Z" level=info msg="skip loading plugin \"io.containerd.tracing.processor.v1.otlp\"..." error="skip plugin: tracing endpoint not configured" type=io.containerd.tracing.processor.v1
    sandbox.go:136: time="2024-07-03T16:05:17.240814620Z" level=info msg="loading plugin \"io.containerd.internal.v1.tracing\"..." type=io.containerd.internal.v1
    sandbox.go:136: time="2024-07-03T16:05:17.240829037Z" level=info msg="skip loading plugin \"io.containerd.internal.v1.tracing\"..." error="skip plugin: tracing endpoint not configured" type=io.containerd.internal.v1
    sandbox.go:136: time="2024-07-03T16:05:17.240844847Z" level=info msg="loading plugin \"io.containerd.internal.v1.restart\"..." type=io.containerd.internal.v1
    sandbox.go:136: time="2024-07-03T16:05:17.240885583Z" level=info msg="loading plugin \"io.containerd.grpc.v1.healthcheck\"..." type=io.containerd.grpc.v1
    sandbox.go:136: time="2024-07-03T16:05:17.244336586Z" level=info msg=serving... address=/tmp/bktest_containerd2972322853/debug.sock
    sandbox.go:136: time="2024-07-03T16:05:17.244419972Z" level=info msg=serving... address=/tmp/bktest_containerd2972322853/containerd.sock.ttrpc
    sandbox.go:136: time="2024-07-03T16:05:17.244491216Z" level=info msg=serving... address=/tmp/bktest_containerd2972322853/containerd.sock
    sandbox.go:136: time="2024-07-03T16:05:17.244519719Z" level=debug msg="sd notification" error="<nil>" notified=false state="READY=1"
    sandbox.go:136: time="2024-07-03T16:05:17.244552480Z" level=info msg="containerd successfully booted in 0.039659s"
    sandbox.go:136: time="2024-07-03T16:05:17.495849932Z" level=debug msg="(*service).Write started" expected="sha256:9d9545c4ec0477879643006c481ccc3d6b7d4d84de188afa11e758dffc06a4cd" ref="manifest-sha256:9d9545c4ec0477879643006c481ccc3d6b7d4d84de188afa11e758dffc06a4cd" total=482
    sandbox.go:136: time="2024-07-03T16:05:17.528320411Z" level=debug msg="(*service).Write started" expected="sha256:ebb4cdf9b384c8654e2fe841d01df2327bc5aa446f8ff9b5e490b38898af9642" ref="config-sha256:ebb4cdf9b384c8654e2fe841d01df2327bc5aa446f8ff9b5e490b38898af9642" total=1256
    sandbox.go:136: time="2024-07-03T16:05:17.563725309Z" level=debug msg="(*service).Write started" expected="sha256:9d9545c4ec0477879643006c481ccc3d6b7d4d84de188afa11e758dffc06a4cd" ref="manifest-sha256:9d9545c4ec0477879643006c481ccc3d6b7d4d84de188afa11e758dffc06a4cd" total=482
    sandbox.go:136: time="2024-07-03T16:05:17.569740697Z" level=debug msg="(*service).Write started" expected="sha256:ebb4cdf9b384c8654e2fe841d01df2327bc5aa446f8ff9b5e490b38898af9642" ref="config-sha256:ebb4cdf9b384c8654e2fe841d01df2327bc5aa446f8ff9b5e490b38898af9642" total=1256
    sandbox.go:136: time="2024-07-03T16:05:17.599135328Z" level=debug msg="stat snapshot" key="sha256:2b63ee31d1cc14f2f1639a1a6825558b68e1ebbc97390ced4be62964b5a83039"
    sandbox.go:136: time="2024-07-03T16:05:17.604598498Z" level=debug msg="(*service).Write started" expected="sha256:b1d7f8c809499b34d0bd040cd08869ed948c33b4aacce39b56235efc9a3ad992" ref="layer-sha256:b1d7f8c809499b34d0bd040cd08869ed948c33b4aacce39b56235efc9a3ad992" total=12439547
    sandbox.go:136: time="2024-07-03T16:05:17.733634301Z" level=debug msg="prepare snapshot" key="extract-jk7khjmgdwjuytsz5np30n709 sha256:2b63ee31d1cc14f2f1639a1a6825558b68e1ebbc97390ced4be62964b5a83039" parent=
    sandbox.go:136: time="2024-07-03T16:05:17.747597454Z" level=debug msg="get snapshot mounts" key="extract-jk7khjmgdwjuytsz5np30n709 sha256:2b63ee31d1cc14f2f1639a1a6825558b68e1ebbc97390ced4be62964b5a83039"
    sandbox.go:136: time="2024-07-03T16:05:17.749891337Z" level=debug msg="unpigz not found, falling back to go gzip" error="exec: \"unpigz\": executable file not found in $PATH"
    sandbox.go:136: time="2024-07-03T16:05:18.042324139Z" level=debug msg="diff applied" d=292.532147ms digest="sha256:b1d7f8c809499b34d0bd040cd08869ed948c33b4aacce39b56235efc9a3ad992" media=application/vnd.oci.image.layer.v1.tar+gzip size=12439547
    sandbox.go:136: time="2024-07-03T16:05:18.042834092Z" level=debug msg="stat snapshot" key="extract-jk7khjmgdwjuytsz5np30n709 sha256:2b63ee31d1cc14f2f1639a1a6825558b68e1ebbc97390ced4be62964b5a83039"
    sandbox.go:136: time="2024-07-03T16:05:18.043312498Z" level=debug msg="commit snapshot" key="extract-jk7khjmgdwjuytsz5np30n709 sha256:2b63ee31d1cc14f2f1639a1a6825558b68e1ebbc97390ced4be62964b5a83039" name="sha256:2b63ee31d1cc14f2f1639a1a6825558b68e1ebbc97390ced4be62964b5a83039"
    sandbox.go:136: time="2024-07-03T16:05:18.051825561Z" level=debug msg="prepare snapshot" key=svor1duzu7qvmex025jjjub77 parent="sha256:2b63ee31d1cc14f2f1639a1a6825558b68e1ebbc97390ced4be62964b5a83039"
    sandbox.go:136: time="2024-07-03T16:05:18.058517083Z" level=debug msg="get snapshot mounts" key=svor1duzu7qvmex025jjjub77
    sandbox.go:136: time="2024-07-03T16:05:18.088688379Z" level=info msg="loading plugin \"io.containerd.event.v1.publisher\"..." runtime=io.containerd.runc.v2 type=io.containerd.event.v1
    sandbox.go:136: time="2024-07-03T16:05:18.095795341Z" level=info msg="loading plugin \"io.containerd.internal.v1.shutdown\"..." runtime=io.containerd.runc.v2 type=io.containerd.internal.v1
    sandbox.go:136: time="2024-07-03T16:05:18.095991328Z" level=info msg="loading plugin \"io.containerd.ttrpc.v1.task\"..." runtime=io.containerd.runc.v2 type=io.containerd.ttrpc.v1
    sandbox.go:136: time="2024-07-03T16:05:18.096705895Z" level=debug msg="registering ttrpc service" id=io.containerd.ttrpc.v1.task
    sandbox.go:136: time="2024-07-03T16:05:18.096880963Z" level=debug msg="serving api on socket" socket="[inherited from parent]"
    sandbox.go:136: time="2024-07-03T16:05:18.096915910Z" level=info msg="starting signal loop" namespace=buildkit path=/tmp/bktest_containerd2972322853/state/io.containerd.runtime.v2.task/buildkit/vbwiliehxyr2lhg1flz6xo0ey pid=13958 runtime=io.containerd.runc.v2
    sandbox.go:136: time="2024-07-03T16:05:18.177954991Z" level=debug msg="prepare snapshot" key=q9h3tncsd4lf680ke2z6mken7 parent=
    sandbox.go:136: time="2024-07-03T16:05:18.182183192Z" level=debug msg="get snapshot mounts" key=q9h3tncsd4lf680ke2z6mken7
    sandbox.go:136: time="2024-07-03T16:05:18.187549069Z" level=debug msg="get snapshot mounts" key=q9h3tncsd4lf680ke2z6mken7
    sandbox.go:136: time="2024-07-03T16:05:18.203558783Z" level=debug msg="prepare snapshot" key=2nbhmt8mw5q8hyh5amuix0syr parent=
    sandbox.go:136: time="2024-07-03T16:05:18.209525980Z" level=debug msg="get snapshot mounts" key=2nbhmt8mw5q8hyh5amuix0syr
    sandbox.go:136: time="2024-07-03T16:05:18.221544118Z" level=debug msg="get snapshot mounts" key=2nbhmt8mw5q8hyh5amuix0syr
    sandbox.go:136: time="2024-07-03T16:05:18.250815357Z" level=info msg="shim disconnected" id=vbwiliehxyr2lhg1flz6xo0ey
    sandbox.go:136: time="2024-07-03T16:05:18.250995444Z" level=warning msg="cleaning up after shim disconnected" id=vbwiliehxyr2lhg1flz6xo0ey namespace=buildkit
    sandbox.go:136: time="2024-07-03T16:05:18.251013518Z" level=info msg="cleaning up dead shim"
    sandbox.go:136: time="2024-07-03T16:05:18.260684380Z" level=warning msg="cleanup warnings time=\"2024-07-03T16:05:18Z\" level=info msg=\"starting signal loop\" namespace=buildkit pid=14045 runtime=io.containerd.runc.v2\n"
    sandbox.go:136: time="2024-07-03T16:05:18.292680042Z" level=debug msg="prepare snapshot" key=yl029qc1975d7twoutayaj8in parent=
    sandbox.go:136: time="2024-07-03T16:05:18.299261961Z" level=debug msg="get snapshot mounts" key=yl029qc1975d7twoutayaj8in
    sandbox.go:136: time="2024-07-03T16:05:18.304720582Z" level=debug msg="get snapshot mounts" key=yl029qc1975d7twoutayaj8in
    sandbox.go:136: time="2024-07-03T16:05:18.307032141Z" level=debug msg="(*service).Write started" ref=history-ref_305848895-jxUu
    sandbox.go:136: time="2024-07-03T16:05:18.315245887Z" level=debug msg="(*service).Write started" ref=history-ref_314344809-qpD2
    sandbox.go:136: time="2024-07-03T16:05:18.324385694Z" level=debug msg="remove snapshot" key=svor1duzu7qvmex025jjjub77 snapshotter=overlayfs
    sandbox.go:136: time="2024-07-03T16:05:18.324421771Z" level=debug msg="remove content" key="sha256:5b958ee19fec03ab4734599729cd8c6c0492af97fe09823e47af95d908fa5a9f"
    sandbox.go:136: time="2024-07-03T16:05:18.328111321Z" level=debug msg="schedule snapshotter cleanup" snapshotter=overlayfs
    sandbox.go:136: time="2024-07-03T16:05:18.328133833Z" level=debug msg="schedule content cleanup"
    sandbox.go:136: time="2024-07-03T16:05:18.328632187Z" level=debug msg="removed content" digest="sha256:5b958ee19fec03ab4734599729cd8c6c0492af97fe09823e47af95d908fa5a9f"
    sandbox.go:136: time="2024-07-03T16:05:18.328986470Z" level=debug msg="removed snapshot" key=buildkit/3/svor1duzu7qvmex025jjjub77 snapshotter=overlayfs
    sandbox.go:136: time="2024-07-03T16:05:18.334406180Z" level=debug msg="(*service).Write started" expected="sha256:5b958ee19fec03ab4734599729cd8c6c0492af97fe09823e47af95d908fa5a9f" ref="history-migrate-sha256:5b958ee19fec03ab4734599729cd8c6c0492af97fe09823e47af95d908fa5a9f"
    sandbox.go:133: stdout: /usr/bin/buildkitd --containerd-worker-gc=false --containerd-worker=true --containerd-worker-addr /tmp/bktest_containerd2972322853/containerd.sock --containerd-worker-labels=org.mobyproject.buildkit.worker.sandbox=true --oci-worker=false --config=/tmp/bktest_config3105108576/buildkitd.toml --root /tmp/bktest_buildkitd977923936 --addr unix:///tmp/bktest_buildkitd977923936/buildkitd.sock --debug
    sandbox.go:133: stderr: /usr/bin/buildkitd --containerd-worker-gc=false --containerd-worker=true --containerd-worker-addr /tmp/bktest_containerd2972322853/containerd.sock --containerd-worker-labels=org.mobyproject.buildkit.worker.sandbox=true --oci-worker=false --config=/tmp/bktest_config3105108576/buildkitd.toml --root /tmp/bktest_buildkitd977923936 --addr unix:///tmp/bktest_buildkitd977923936/buildkitd.sock --debug
    sandbox.go:136: > StartCmd 2024-07-03 16:05:17.287540262 +0000 UTC m=+11.443246492 /usr/bin/buildkitd --containerd-worker-gc=false --containerd-worker=true --containerd-worker-addr /tmp/bktest_containerd2972322853/containerd.sock --containerd-worker-labels=org.mobyproject.buildkit.worker.sandbox=true --oci-worker=false --config=/tmp/bktest_config3105108576/buildkitd.toml --root /tmp/bktest_buildkitd977923936 --addr unix:///tmp/bktest_buildkitd977923936/buildkitd.sock --debug
    sandbox.go:136: time="2024-07-03T16:05:17Z" level=warning msg="failed to get disk size: no such file or directory"
    sandbox.go:136: time="2024-07-03T16:05:17Z" level=warning msg="failed to get disk size: no such file or directory"
    sandbox.go:136: time="2024-07-03T16:05:17Z" level=debug msg="could not read \"/tmp/bktest_buildkitd977923936/net/cni\" for cleanup: open /tmp/bktest_buildkitd977923936/net/cni: no such file or directory"
    sandbox.go:136: time="2024-07-03T16:05:17Z" level=debug msg="creating new network namespace xdy7g21m90knny2si86bexali"
    sandbox.go:136: time="2024-07-03T16:05:17Z" level=debug msg="finished creating network namespace xdy7g21m90knny2si86bexali"
    sandbox.go:136: time="2024-07-03T16:05:17Z" level=debug msg="finished setting up network namespace xdy7g21m90knny2si86bexali"
    sandbox.go:136: time="2024-07-03T16:05:17Z" level=debug msg="remote introspection plugin filters" filters="[type==io.containerd.runtime.v1 type==io.containerd.runtime.v2]"
    sandbox.go:136: time="2024-07-03T16:05:17Z" level=info msg="found worker \"5thyp837ynpqpy05zwarrddyq\", labels=map[org.mobyproject.buildkit.worker.containerd.namespace:buildkit org.mobyproject.buildkit.worker.containerd.uuid:06a941fb-5950-4f62-ac8d-990a87c86704 org.mobyproject.buildkit.worker.executor:containerd org.mobyproject.buildkit.worker.hostname:a66379faa83e org.mobyproject.buildkit.worker.network:cni org.mobyproject.buildkit.worker.sandbox:true org.mobyproject.buildkit.worker.selinux.enabled:false org.mobyproject.buildkit.worker.snapshotter:overlayfs], platforms=[linux/amd64 linux/amd64/v2 linux/amd64/v3 linux/arm64 linux/riscv64 linux/ppc64le linux/s390x linux/386 linux/mips64le linux/mips64 linux/arm/v7 linux/arm/v6]"
    sandbox.go:136: time="2024-07-03T16:05:17Z" level=info msg="found 1 workers, default=\"5thyp837ynpqpy05zwarrddyq\""
    sandbox.go:136: time="2024-07-03T16:05:17Z" level=warning msg="currently, only the default worker can be used."
    sandbox.go:136: time="2024-07-03T16:05:17Z" level=info msg="running server on /tmp/bktest_buildkitd977923936/buildkitd.sock"
    sandbox.go:136: time="2024-07-03T16:05:17Z" level=debug msg="session started"
    sandbox.go:136: time="2024-07-03T16:05:17Z" level=debug msg="checked for cached auth handler namespace" cached=false key="docker.io/buildkit_test/ozmvqsy3u4dfm55o7tbrr6g0k::pull" name=docker.io/buildkit_test/ozmvqsy3u4dfm55o7tbrr6g0k scope=pull
    sandbox.go:136: time="2024-07-03T16:05:17Z" level=debug msg=resolving host="localhost:46809"
    sandbox.go:136: time="2024-07-03T16:05:17Z" level=debug msg="do request" host="localhost:46809" request.header.accept="application/vnd.docker.distribution.manifest.v2+json, application/vnd.docker.distribution.manifest.list.v2+json, application/vnd.oci.image.manifest.v1+json, application/vnd.oci.image.index.v1+json, */*" request.header.user-agent=buildkit/v0.0.0+unknown request.method=HEAD url="http://localhost:46809/v2/buildkit_test/ozmvqsy3u4dfm55o7tbrr6g0k/manifests/latest?ns=docker.io"
    sandbox.go:136: time="2024-07-03T16:05:17Z" level=debug msg="fetch response received" host="localhost:46809" response.header.content-length=482 response.header.content-type=application/vnd.oci.image.manifest.v1+json response.header.date="Wed, 03 Jul 2024 16:05:17 GMT" response.header.docker-content-digest="sha256:9d9545c4ec0477879643006c481ccc3d6b7d4d84de188afa11e758dffc06a4cd" response.header.docker-distribution-api-version=registry/2.0 response.header.etag="\"sha256:9d9545c4ec0477879643006c481ccc3d6b7d4d84de188afa11e758dffc06a4cd\"" response.status="200 OK" url="http://localhost:46809/v2/buildkit_test/ozmvqsy3u4dfm55o7tbrr6g0k/manifests/latest?ns=docker.io"
    sandbox.go:136: time="2024-07-03T16:05:17Z" level=debug msg=resolved desc.digest="sha256:9d9545c4ec0477879643006c481ccc3d6b7d4d84de188afa11e758dffc06a4cd" host="localhost:46809"
    sandbox.go:136: time="2024-07-03T16:05:17Z" level=debug msg=fetch digest="sha256:9d9545c4ec0477879643006c481ccc3d6b7d4d84de188afa11e758dffc06a4cd" mediatype=application/vnd.oci.image.manifest.v1+json size=482
    sandbox.go:136: time="2024-07-03T16:05:17Z" level=debug msg="do request" digest="sha256:9d9545c4ec0477879643006c481ccc3d6b7d4d84de188afa11e758dffc06a4cd" mediatype=application/vnd.oci.image.manifest.v1+json request.header.accept="application/vnd.oci.image.manifest.v1+json, */*" request.header.user-agent=buildkit/v0.0.0+unknown request.method=GET size=482 url="http://localhost:46809/v2/buildkit_test/ozmvqsy3u4dfm55o7tbrr6g0k/manifests/sha256:9d9545c4ec0477879643006c481ccc3d6b7d4d84de188afa11e758dffc06a4cd?ns=docker.io"
    sandbox.go:136: time="2024-07-03T16:05:17Z" level=debug msg="fetch response received" digest="sha256:9d9545c4ec0477879643006c481ccc3d6b7d4d84de188afa11e758dffc06a4cd" mediatype=application/vnd.oci.image.manifest.v1+json response.header.content-length=482 response.header.content-type=application/vnd.oci.image.manifest.v1+json response.header.date="Wed, 03 Jul 2024 16:05:17 GMT" response.header.docker-content-digest="sha256:9d9545c4ec0477879643006c481ccc3d6b7d4d84de188afa11e758dffc06a4cd" response.header.docker-distribution-api-version=registry/2.0 response.header.etag="\"sha256:9d9545c4ec0477879643006c481ccc3d6b7d4d84de188afa11e758dffc06a4cd\"" response.status="200 OK" size=482 url="http://localhost:46809/v2/buildkit_test/ozmvqsy3u4dfm55o7tbrr6g0k/manifests/sha256:9d9545c4ec0477879643006c481ccc3d6b7d4d84de188afa11e758dffc06a4cd?ns=docker.io"
    sandbox.go:136: time="2024-07-03T16:05:17Z" level=debug msg=fetch digest="sha256:ebb4cdf9b384c8654e2fe841d01df2327bc5aa446f8ff9b5e490b38898af9642" mediatype=application/vnd.oci.image.config.v1+json size=1256
    sandbox.go:136: time="2024-07-03T16:05:17Z" level=debug msg="do request" digest="sha256:ebb4cdf9b384c8654e2fe841d01df2327bc5aa446f8ff9b5e490b38898af9642" mediatype=application/vnd.oci.image.config.v1+json request.header.accept="application/vnd.oci.image.config.v1+json, */*" request.header.user-agent=buildkit/v0.0.0+unknown request.method=GET size=1256 url="http://localhost:46809/v2/buildkit_test/ozmvqsy3u4dfm55o7tbrr6g0k/blobs/sha256:ebb4cdf9b384c8654e2fe841d01df2327bc5aa446f8ff9b5e490b38898af9642?ns=docker.io"
    sandbox.go:136: time="2024-07-03T16:05:17Z" level=debug msg="fetch response received" digest="sha256:ebb4cdf9b384c8654e2fe841d01df2327bc5aa446f8ff9b5e490b38898af9642" mediatype=application/vnd.oci.image.config.v1+json response.header.accept-ranges=bytes response.header.cache-control="max-age=31536000" response.header.content-length=1256 response.header.content-type=application/octet-stream response.header.date="Wed, 03 Jul 2024 16:05:17 GMT" response.header.docker-content-digest="sha256:ebb4cdf9b384c8654e2fe841d01df2327bc5aa446f8ff9b5e490b38898af9642" response.header.docker-distribution-api-version=registry/2.0 response.header.etag="\"sha256:ebb4cdf9b384c8654e2fe841d01df2327bc5aa446f8ff9b5e490b38898af9642\"" response.status="200 OK" size=1256 url="http://localhost:46809/v2/buildkit_test/ozmvqsy3u4dfm55o7tbrr6g0k/blobs/sha256:ebb4cdf9b384c8654e2fe841d01df2327bc5aa446f8ff9b5e490b38898af9642?ns=docker.io"
    sandbox.go:136: time="2024-07-03T16:05:17Z" level=debug msg="checked for cached auth handler namespace" cached=true key="docker.io/buildkit_test/ozmvqsy3u4dfm55o7tbrr6g0k::pull" name=docker.io/buildkit_test/ozmvqsy3u4dfm55o7tbrr6g0k scope=pull
    sandbox.go:136: time="2024-07-03T16:05:17Z" level=debug msg=fetch digest="sha256:9d9545c4ec0477879643006c481ccc3d6b7d4d84de188afa11e758dffc06a4cd" mediatype=application/vnd.oci.image.manifest.v1+json size=482
    sandbox.go:136: time="2024-07-03T16:05:17Z" level=debug msg=fetch digest="sha256:ebb4cdf9b384c8654e2fe841d01df2327bc5aa446f8ff9b5e490b38898af9642" mediatype=application/vnd.oci.image.config.v1+json size=1256
    sandbox.go:136: time="2024-07-03T16:05:17Z" level=debug msg="checked for cached auth handler namespace" cached=true key="docker.io/buildkit_test/ozmvqsy3u4dfm55o7tbrr6g0k::pull" name=docker.io/buildkit_test/ozmvqsy3u4dfm55o7tbrr6g0k scope=pull
    sandbox.go:136: time="2024-07-03T16:05:17Z" level=debug msg="checked for cached auth handler namespace" cached=true key="docker.io/buildkit_test/ozmvqsy3u4dfm55o7tbrr6g0k::pull" name=docker.io/buildkit_test/ozmvqsy3u4dfm55o7tbrr6g0k scope=pull
    sandbox.go:136: time="2024-07-03T16:05:17Z" level=debug msg=fetch digest="sha256:b1d7f8c809499b34d0bd040cd08869ed948c33b4aacce39b56235efc9a3ad992" mediatype=application/vnd.oci.image.layer.v1.tar+gzip size=12439547
    sandbox.go:136: time="2024-07-03T16:05:17Z" level=debug msg="do request" digest="sha256:b1d7f8c809499b34d0bd040cd08869ed948c33b4aacce39b56235efc9a3ad992" mediatype=application/vnd.oci.image.layer.v1.tar+gzip request.header.accept="application/vnd.oci.image.layer.v1.tar+gzip, */*" request.header.user-agent=containerd/1.7.19+unknown request.method=GET size=12439547 url="http://localhost:46809/v2/buildkit_test/ozmvqsy3u4dfm55o7tbrr6g0k/blobs/sha256:b1d7f8c809499b34d0bd040cd08869ed948c33b4aacce39b56235efc9a3ad992?ns=docker.io"
    sandbox.go:136: time="2024-07-03T16:05:17Z" level=debug msg="fetch response received" digest="sha256:b1d7f8c809499b34d0bd040cd08869ed948c33b4aacce39b56235efc9a3ad992" mediatype=application/vnd.oci.image.layer.v1.tar+gzip response.header.accept-ranges=bytes response.header.cache-control="max-age=31536000" response.header.content-length=12439547 response.header.content-type=application/octet-stream response.header.date="Wed, 03 Jul 2024 16:05:17 GMT" response.header.docker-content-digest="sha256:b1d7f8c809499b34d0bd040cd08869ed948c33b4aacce39b56235efc9a3ad992" response.header.docker-distribution-api-version=registry/2.0 response.header.etag="\"sha256:b1d7f8c809499b34d0bd040cd08869ed948c33b4aacce39b56235efc9a3ad992\"" response.status="200 OK" size=12439547 url="http://localhost:46809/v2/buildkit_test/ozmvqsy3u4dfm55o7tbrr6g0k/blobs/sha256:b1d7f8c809499b34d0bd040cd08869ed948c33b4aacce39b56235efc9a3ad992?ns=docker.io"
    sandbox.go:136: time="2024-07-03T16:05:18Z" level=debug msg="serving grpc connection"
    sandbox.go:136: time="2024-07-03T16:05:18Z" level=debug msg="new ref for local: q9h3tncsd4lf680ke2z6mken7" span="[internal] load build definition from Dockerfile"
    sandbox.go:136: time="2024-07-03T16:05:18Z" level=debug msg="diffcopy took: 1.887663ms" span="[internal] load build definition from Dockerfile"
    sandbox.go:136: time="2024-07-03T16:05:18Z" level=debug msg="saved q9h3tncsd4lf680ke2z6mken7 as dockerfile:dockerfile:" span="[internal] load build definition from Dockerfile"
    sandbox.go:136: time="2024-07-03T16:05:18Z" level=debug msg="new ref for local: 2nbhmt8mw5q8hyh5amuix0syr" span="[internal] load .dockerignore"
    sandbox.go:136: time="2024-07-03T16:05:18Z" level=debug msg="diffcopy took: 2.801709ms" span="[internal] load .dockerignore"
    sandbox.go:136: time="2024-07-03T16:05:18Z" level=debug msg="saved 2nbhmt8mw5q8hyh5amuix0syr as context:context-.dockerignore:" span="[internal] load .dockerignore"
    sandbox.go:136: time="2024-07-03T16:05:18Z" level=debug msg="new ref for local: yl029qc1975d7twoutayaj8in" span="[internal] load build context"
    sandbox.go:136: time="2024-07-03T16:05:18Z" level=debug msg="diffcopy took: 1.33517ms" span="[internal] load build context"
    sandbox.go:136: time="2024-07-03T16:05:18Z" level=debug msg="saved yl029qc1975d7twoutayaj8in as context:context:" span="[internal] load build context"
    sandbox.go:136: time="2024-07-03T16:05:18Z" level=error msg="/moby.buildkit.v1.Control/Solve returned error: rpc error: code = Unknown desc = failed to compute cache key: failed to calculate checksum of ref 5thyp837ynpqpy05zwarrddyq::c137wt50hf460yjzsunug1pnj: \"/notexist\": not found"
    sandbox.go:136: failed to compute cache key: failed to calculate checksum of ref 5thyp837ynpqpy05zwarrddyq::c137wt50hf460yjzsunug1pnj: "/notexist": not found
    sandbox.go:136: 13225 1ab8eb7 buildkitd --containerd-worker-gc=false --containerd-worker=true --containerd-worker-addr /tmp/bktest_containerd2972322853/containerd.sock --containerd-worker-labels=org.mobyproject.buildkit.worker.sandbox=true --oci-worker=false --config=/tmp/bktest_config3105108576/buildkitd.toml --root /tmp/bktest_buildkitd977923936 --addr unix:///tmp/bktest_buildkitd977923936/buildkitd.sock --debug
    sandbox.go:136: github.com/moby/buildkit/cache/contenthash.init
    sandbox.go:136:     /src/cache/contenthash/checksum.go:28
    sandbox.go:136: runtime.doInit1
    sandbox.go:136:     /usr/local/go/src/runtime/proc.go:7176
    sandbox.go:136: runtime.doInit
    sandbox.go:136:     /usr/local/go/src/runtime/proc.go:7143
    sandbox.go:136: runtime.main
    sandbox.go:136:     /usr/local/go/src/runtime/proc.go:253
    sandbox.go:136: runtime.goexit
    sandbox.go:136:     /usr/local/go/src/runtime/asm_amd64.s:1695
    sandbox.go:136: 
    sandbox.go:136: 13225 1ab8eb7 buildkitd --containerd-worker-gc=false --containerd-worker=true --containerd-worker-addr /tmp/bktest_containerd2972322853/containerd.sock --containerd-worker-labels=org.mobyproject.buildkit.worker.sandbox=true --oci-worker=false --config=/tmp/bktest_config3105108576/buildkitd.toml --root /tmp/bktest_buildkitd977923936 --addr unix:///tmp/bktest_buildkitd977923936/buildkitd.sock --debug
    sandbox.go:136: github.com/moby/buildkit/cache/contenthash.(*cacheContext).checksum
    sandbox.go:136:     /src/cache/contenthash/checksum.go:860
    sandbox.go:136: github.com/moby/buildkit/cache/contenthash.(*cacheContext).scanChecksum
    sandbox.go:136:     /src/cache/contenthash/checksum.go:844
    sandbox.go:136: github.com/moby/buildkit/cache/contenthash.(*cacheContext).lazyChecksum
    sandbox.go:136:     /src/cache/contenthash/checksum.go:807
    sandbox.go:136: github.com/moby/buildkit/cache/contenthash.(*cacheContext).Checksum
    sandbox.go:136:     /src/cache/contenthash/checksum.go:411
    sandbox.go:136: github.com/moby/buildkit/cache/contenthash.(*cacheManager).Checksum
    sandbox.go:136:     /src/cache/contenthash/checksum.go:104
    sandbox.go:136: github.com/moby/buildkit/cache/contenthash.Checksum
    sandbox.go:136:     /src/cache/contenthash/checksum.go:55
    sandbox.go:136: github.com/moby/buildkit/solver/llbsolver/ops.(*fileOp).CacheMap.NewContentHashFunc.func3.1
    sandbox.go:136:     /src/solver/llbsolver/ops/opsutils/contenthash.go:47
    sandbox.go:136: golang.org/x/sync/errgroup.(*Group).Go.func1
    sandbox.go:136:     /src/vendor/golang.org/x/sync/errgroup/errgroup.go:78
    sandbox.go:136: runtime.goexit
    sandbox.go:136:     /usr/local/go/src/runtime/asm_amd64.s:1695
    sandbox.go:136: 
    sandbox.go:136: 13225 1ab8eb7 buildkitd --containerd-worker-gc=false --containerd-worker=true --containerd-worker-addr /tmp/bktest_containerd2972322853/containerd.sock --containerd-worker-labels=org.mobyproject.buildkit.worker.sandbox=true --oci-worker=false --config=/tmp/bktest_config3105108576/buildkitd.toml --root /tmp/bktest_buildkitd977923936 --addr unix:///tmp/bktest_buildkitd977923936/buildkitd.sock --debug
    sandbox.go:136: github.com/moby/buildkit/solver/llbsolver/ops.(*fileOp).CacheMap.NewContentHashFunc.func3.1
    sandbox.go:136:     /src/solver/llbsolver/ops/opsutils/contenthash.go:58
    sandbox.go:136: golang.org/x/sync/errgroup.(*Group).Go.func1
    sandbox.go:136:     /src/vendor/golang.org/x/sync/errgroup/errgroup.go:78
    sandbox.go:136: runtime.goexit
    sandbox.go:136:     /usr/local/go/src/runtime/asm_amd64.s:1695
    sandbox.go:136: 
    sandbox.go:136: 13225 1ab8eb7 buildkitd --containerd-worker-gc=false --containerd-worker=true --containerd-worker-addr /tmp/bktest_containerd2972322853/containerd.sock --containerd-worker-labels=org.mobyproject.buildkit.worker.sandbox=true --oci-worker=false --config=/tmp/bktest_config3105108576/buildkitd.toml --root /tmp/bktest_buildkitd977923936 --addr unix:///tmp/bktest_buildkitd977923936/buildkitd.sock --debug
    sandbox.go:136: github.com/moby/buildkit/solver.(*edge).createInputRequests.(*edge).createInputRequests.func1.func2
    sandbox.go:136:     /src/solver/edge.go:912
    sandbox.go:136: github.com/moby/buildkit/solver/internal/pipe.NewWithFunction.func2
    sandbox.go:136:     /src/solver/internal/pipe/pipe.go:82
    sandbox.go:136: runtime.goexit
    sandbox.go:136:     /usr/local/go/src/runtime/asm_amd64.s:1695
    sandbox.go:136: 
    sandbox.go:136: 13225 1ab8eb7 buildkitd --containerd-worker-gc=false --containerd-worker=true --containerd-worker-addr /tmp/bktest_containerd2972322853/containerd.sock --containerd-worker-labels=org.mobyproject.buildkit.worker.sandbox=true --oci-worker=false --config=/tmp/bktest_config3105108576/buildkitd.toml --root /tmp/bktest_buildkitd977923936 --addr unix:///tmp/bktest_buildkitd977923936/buildkitd.sock --debug
    sandbox.go:136: main.unaryInterceptor
    sandbox.go:136:     /src/cmd/buildkitd/main.go:713
    sandbox.go:136: google.golang.org/grpc.NewServer.chainUnaryServerInterceptors.chainUnaryInterceptors.func1
    sandbox.go:136:     /src/vendor/google.golang.org/grpc/server.go:1154
    sandbox.go:136: github.com/moby/buildkit/api/services/control._Control_Solve_Handler
    sandbox.go:136:     /src/api/services/control/control.pb.go:2484
    sandbox.go:136: google.golang.org/grpc.(*Server).processUnaryRPC
    sandbox.go:136:     /src/vendor/google.golang.org/grpc/server.go:1343
    sandbox.go:136: google.golang.org/grpc.(*Server).handleStream
    sandbox.go:136:     /src/vendor/google.golang.org/grpc/server.go:1737
    sandbox.go:136: google.golang.org/grpc.(*Server).serveStreams.func1.1
    sandbox.go:136:     /src/vendor/google.golang.org/grpc/server.go:986
    sandbox.go:136: runtime.goexit
    sandbox.go:136:     /usr/local/go/src/runtime/asm_amd64.s:1695
    sandbox.go:136: 
    sandbox.go:136: time="2024-07-03T16:05:18Z" level=debug msg="session finished: <nil>"
    sandbox.go:133: stdout: /opt/containerd-alt-16/bin/containerd --config /tmp/bktest_containerd2972322853/config.toml
    --- FAIL: TestIntegration/TestHistoryError/worker=containerd-1.6/frontend=gateway (1.89s)
tonistiigi commented 3 months ago

The error means that ListenBuildHistory(ref) returned EOF instead of a record. I think it might be that Solve() returned and error, but not the one we expected, and the history was not really saved.

We could update the test to make sure the build doesn't just end with any error, but checks for a specific return error as well (atm it only looks for the specific error inside the history record).