precompilation failed: failed to validate component output

[calebschoepp]

I'm trying to run finicky whiskers and it is failing when using an OCI artifact (as opposed to a scratch container). Containerd logs:

time="2024-10-16T17:44:43.219747046Z" level=error msg="ttrpc: received message on inactive stream" stream=23
time="2024-10-16T17:44:43.220724129Z" level=info msg="shim disconnected" id=2b8cab36d04c85b5da242761f4b2fe732dca5ed51750b7bed90c661673dbba7c namespace=k8s.io
time="2024-10-16T17:44:43.220749337Z" level=warning msg="cleaning up after shim disconnected" id=2b8cab36d04c85b5da242761f4b2fe732dca5ed51750b7bed90c661673dbba7c namespace=k8s.io
time="2024-10-16T17:44:43.220753254Z" level=info msg="cleaning up dead shim" namespace=k8s.io
time="2024-10-16T17:44:43.327922462Z" level=info msg="RemoveContainer for \"08194e8692812a45f8856c2601c90086c9578139cb01414920fc6f57800a0ed6\""
time="2024-10-16T17:44:43.330033421Z" level=info msg="RemoveContainer for \"08194e8692812a45f8856c2601c90086c9578139cb01414920fc6f57800a0ed6\" returns successfully"
time="2024-10-16T17:45:08.865291877Z" level=info msg="CreateContainer within sandbox \"2232c714d69a72f4b8ea3e18e7bb54f74a3e3978d1303aa02f44a201664c33cd\" for container &ContainerMetadata{Name:finicky,Attempt:3,}"
time="2024-10-16T17:45:08.872765919Z" level=info msg="CreateContainer within sandbox \"2232c714d69a72f4b8ea3e18e7bb54f74a3e3978d1303aa02f44a201664c33cd\" for &ContainerMetadata{Name:finicky,Attempt:3,} returns container id \"4ec995e3ee965a492f711a802b5b058770bbbd26e4e57cf1db5d8871a71ae09b\""
time="2024-10-16T17:45:08.873098627Z" level=info msg="StartContainer for \"4ec995e3ee965a492f711a802b5b058770bbbd26e4e57cf1db5d8871a71ae09b\""
time="2024-10-16T17:45:08.93002371Z" level=error msg="precompilation failed: failed to validate component output"

time="2024-10-16T17:45:08.956262002Z" level=info msg="StartContainer for \"4ec995e3ee965a492f711a802b5b058770bbbd26e4e57cf1db5d8871a71ae09b\" returns successfully"
time="2024-10-16T17:45:09.21545996Z" level=error msg="run_wasi ERROR >>>  failed: failed to build spin trigger

Caused by:
    0: Failed to instantiate component 'tally'
    1: Unknown file magic"

Kate hypothesizes that it is likely b/c layers in the OCI artifact are too big.

[kate-goldenring]

This issue is due to running newer Spin apps with an older version of the shim. If you build a Spin app with Spin 2.7 and then run it on the 0.16 shim it will fail due to the Wasmtime version being incompatible. While older spin apps can be run on newer spin runtimes, the opposite is not the case. I was able to successfully run your app (Finicky Whiskers) that was built with Spin 2.7 on the canary release of the Shim (that has the same Wasmtime version. You can install the canary shim with the Node installer like so:

helm upgrade --install kwasm-operator kwasm/kwasm-operator --namespace kwasm  --create-namespace --set "kwasmOperator.installerImage=ghcr.io/spinkube/containerd-shim-spin/node-installer:20241015-215852-g71c8351

I am going to close this as resolved. But please reopen if the issue persists.

[Mossaka]

If you build a Spin app with Spin 2.7 and then run it on the 0.16 shim it will fail due to the Wasmtime version being incompatible.

Could you please elaborate on this point? Parcitularly, I don't understand why apps built from Spin 2.7 SDK cannot be executed on the wasmtime that embedded in the v0.16 shim

[kate-goldenring]

Could you please elaborate on this point? Parcitularly, I don't understand why apps built from Spin 2.7 SDK cannot be executed on the wasmtime that embedded in the v0.16 shim

The v0.16 shim using v2.6 Spin crates: https://www.spinkube.dev/docs/reference/shim-spin-version-map/

[jsturtevant]

This makes sense, if its a common occurrence maybe it makes sense to improve the error message? I think it should be possible to inspect the wasm component to see what wasmtime that was used to build it?

[kate-goldenring]

@jsturtevant good call. I'll create a new issue for that.

[kate-goldenring]

Clarifying here: the incompatibility can come from which Spin SDKs the Spin app uses not which Spin CLI was used to build the app. I am reopening this because i haven't been able to repro on the Spin CLI

[kate-goldenring]

Looking farther up in the logs, it looks like precompilation is failing and then that causes wasmtime instantiation to fail:

Oct 29 16:36:28 kagold-ThinkPad-X1-Carbon-6th containerd[1265664]: time="2024-10-29T23:36:28.184024476Z" level=info msg="precompiling layers for image: ttl.sh/fw-new-sdk:24hr"
Oct 29 16:36:28 kagold-ThinkPad-X1-Carbon-6th containerd[1265664]: time="2024-10-29T23:36:28.186234355Z" level=info msg="Precompile called for wasm layer "sha256:6c5110160ab9a9a44301977acb6dd1794a0ad302fb21cf011e5d0fbd9f737297""
Oct 29 16:36:28 kagold-ThinkPad-X1-Carbon-6th containerd[1265664]: time="2024-10-29T23:36:28.709427025Z" level=info msg="Precompile called for wasm layer "sha256:627349e2505bd9626d4242252ad606716087b8a202554603e88fd91c0f52f07c""
Oct 29 16:36:28 kagold-ThinkPad-X1-Carbon-6th containerd[1265664]: time="2024-10-29T23:36:28.718351116Z" level=error msg="precompilation failed: failed to validate component output"
Oct 29 16:36:28 kagold-ThinkPad-X1-Carbon-6th containerd[1265664]: time="2024-10-29T23:36:28.736367834Z" level=info msg="close_range; preserve_fds=0"
Oct 29 16:36:28 kagold-ThinkPad-X1-Carbon-6th containerd[1265664]: time="2024-10-29T23:36:28.740194583Z" level=info msg="cgroup manager V2 will be used"
Oct 29 16:36:28 kagold-ThinkPad-X1-Carbon-6th containerd[1265664]: time="2024-10-29T23:36:28.740406317Z" level=warn msg="Controller rdma is not yet implemented."
Oct 29 16:36:28 kagold-ThinkPad-X1-Carbon-6th containerd[1265664]: time="2024-10-29T23:36:28.740424464Z" level=warn msg="Controller misc is not yet implemented."
Oct 29 16:36:28 kagold-ThinkPad-X1-Carbon-6th containerd[1265664]: time="2024-10-29T23:36:28.750318766Z" level=warn msg="Controller rdma is not yet implemented."
Oct 29 16:36:28 kagold-ThinkPad-X1-Carbon-6th containerd[1265664]: time="2024-10-29T23:36:28.750333514Z" level=warn msg="Controller misc is not yet implemented."
Oct 29 16:36:28 kagold-ThinkPad-X1-Carbon-6th containerd[1265664]: time="2024-10-29T23:36:28.766851338Z" level=info msg="close_range; preserve_fds=0"
Oct 29 16:36:28 kagold-ThinkPad-X1-Carbon-6th containerd[1265664]: time="2024-10-29T23:36:28.772363955Z" level=info msg="starting instance: new"
Oct 29 16:36:28 kagold-ThinkPad-X1-Carbon-6th containerd[1265664]: time="2024-10-29T23:36:28.772603538Z" level=info msg="calling start function"
Oct 29 16:36:28 kagold-ThinkPad-X1-Carbon-6th containerd[1265664]: time="2024-10-29T23:36:28.772659236Z" level=info msg="setting up wasi"
Oct 29 16:36:28 kagold-ThinkPad-X1-Carbon-6th containerd[1265664]: time="2024-10-29T23:36:28.77348831Z" level=info msg=" >>> configuring spin oci application 45"
Oct 29 16:36:28 kagold-ThinkPad-X1-Carbon-6th containerd[1265664]: time="2024-10-29T23:36:28.773516586Z" level=info msg="<<< writing wasm artifact with length 4058631 config to cache, near "/.cache/registry/manifests""
Oct 29 16:36:28 kagold-ThinkPad-X1-Carbon-6th containerd[1265664]: time="2024-10-29T23:36:28.780331962Z" level=info msg="<<< writing wasm artifact with length 442338 config to cache, near "/.cache/registry/manifests""
Oct 29 16:36:28 kagold-ThinkPad-X1-Carbon-6th containerd[1265664]: time="2024-10-29T23:36:28.78070232Z" level=info msg="<<< writing wasm artifact with length 298420 config to cache, near "/.cache/registry/manifests""
Oct 29 16:36:28 kagold-ThinkPad-X1-Carbon-6th containerd[1265664]: time="2024-10-29T23:36:28.780976304Z" level=info msg="<<< writing wasm artifact with length 11348138 config to cache, near "/.cache/registry/manifests""
Oct 29 16:36:28 kagold-ThinkPad-X1-Carbon-6th containerd[1265664]: time="2024-10-29T23:36:28.793908504Z" level=info msg="<<< writing wasm artifact with length 280814 config to cache, near "/.cache/registry/manifests""
Oct 29 16:36:28 kagold-ThinkPad-X1-Carbon-6th containerd[1265664]: time="2024-10-29T23:36:28.794244449Z" level=info msg="<<< writing wasm artifact with length 288790 config to cache, near "/.cache/registry/manifests""
Oct 29 16:36:28 kagold-ThinkPad-X1-Carbon-6th containerd[1265664]: time="2024-10-29T23:36:28.794547201Z" level=info msg="<<< writing wasm artifact with length 194313 config to cache, near "/.cache/registry/manifests""
Oct 29 16:36:28 kagold-ThinkPad-X1-Carbon-6th containerd[1265664]: time="2024-10-29T23:36:28.794746054Z" level=info msg="writing spin oci config to "/spin.json""
Oct 29 16:36:28 kagold-ThinkPad-X1-Carbon-6th containerd[1265664]: time="2024-10-29T23:36:28.849597051Z" level=error msg="run_wasi ERROR >>>  failed: failed to build spin trigger
Oct 29 16:36:28 kagold-ThinkPad-X1-Carbon-6th containerd[1265664]: Caused by:
Oct 29 16:36:28 kagold-ThinkPad-X1-Carbon-6th containerd[1265664]:     0: failed to build trigger
Oct 29 16:36:28 kagold-ThinkPad-X1-Carbon-6th containerd[1265664]:     1: Failed to instantiate component 'fileserver'
Oct 29 16:36:28 kagold-ThinkPad-X1-Carbon-6th containerd[1265664]:     2: Unknown file magic"
Oct 29 16:36:28 kagold-ThinkPad-X1-Carbon-6th containerd[1265664]: time="2024-10-29T23:36:28.85125395Z" level=info msg="error running start function: failed to build spin trigger"

The validation error is being thrown by the ComponentEncoder in Wasmtime here. I can't find the v0.200.0 branch of wit-component to reference, so that is the main link.