Logging fails on TinyGo Spin Apps

[kate-goldenring]

trafficstars

Problem: TinyGo Spin apps that use log gets the following runtime error from Wasmtime:

$ spin build --up
Building component go-app with `tinygo build -target=wasi -gc=leaking -no-debug -o main.wasm main.go`
Finished building all Spin components
Logging component stdio to ".spin/logs/"

Serving http://127.0.0.1:3000
Available Routes:
  go-app: http://127.0.0.1:3000 (wildcard)
panic: runtime error: nil pointer dereference
2023-12-15T23:25:33.689230Z ERROR spin_trigger_http: Error processing request: error while executing at wasm backtrace:
    0: 0xeb05 - <unknown>!runtime.runtimePanicAt.llvm.3901647063377195771
    1: 0x33a77 - <unknown>!byn$mgfn-shared$runtime.lookupPanic.llvm.3901647063377195771
    2: 0x574a - <unknown>!runtime.nilPanic.llvm.3901647063377195771
    3: 0xcfe7 - <unknown>!(*sync.Mutex).Lock
    4: 0x32ca5 - <unknown>!spin_http_handle_http_request
    5: 0x33870 - <unknown>!__wasm_export_spin_http_handle_http_request
    6: 0x441b8 - wit-component:adapter:wasi_snapshot_preview1!fermyon:spin/inbound-http#handle-request

Caused by:
    wasm trap: wasm `unreachable` instruction executed    

Example app:

package main

import (
	"fmt"
	"log"
	"net/http"

	spinhttp "github.com/fermyon/spin/sdk/go/v2/http"
)

func init() {
	spinhttp.Handle(func(w http.ResponseWriter, r *http.Request) {
		log.Printf("THIS WILL CAUSE AN ERROR")

		fmt.Fprintln(w, "== THIS WILL NOT BE REACHED ==")
	})
}

func main() {}

• Spin version (spin --version) spin 2.0.1 (1d72f1c 2023-11-10)

[rajatjindal]

possible similar issues here:

https://github.com/fermyon/spin/issues/1259 and https://github.com/tinygo-org/tinygo/issues/3798

initializing a logger instance and using that for logging fixes the issue:

package main

import (
	"fmt"
	"log"
	"net/http"
	"os"

	spinhttp "github.com/fermyon/spin/sdk/go/v2/http"
)

func init() {
	spinhttp.Handle(func(w http.ResponseWriter, r *http.Request) {
		logger := log.New(os.Stderr, "", log.LstdFlags)
		logger.Println("This will cause an error")

		w.Header().Set("Content-Type", "text/plain")
		fmt.Fprintln(w, "Hello Fermyon!")
	})
}

func main() {}

[vdice]

@rajatjindal @kate-goldenring do we have a handle on if this is an upstream (tinygo) bug or an issue with Spin/wasmtime?

[deadprogram]

Hello, all

Finally saw this issue and looked a little deeper.

The solution is to use the latest version(s) of TinyGo, and to build the modules with this command:

tinygo build -target=wasip1 -no-debug -gc=leaking -scheduler=none -buildmode=c-shared -o main.wasm .

I just tried in a sample app with Spin v3 and worked as expected.

Bonus: you can now remove the extra func main() {} from your TinyGo modules, it is no longer needed for "reactor" mode.

[deadprogram]

The above might also address #1259 and any similar issues.

[itowlson]

Thanks for this update @deadprogram - I will get that into our docs and templates.

Bonus: you can now remove the extra func main() {} from your TinyGo modules, it is no longer needed for "reactor" mode.

Now that is a bonus! Thanks for highlighting it - that's really nice.

[deadprogram]

Note that you will also need to update to newer TinyGo versions. Seems like you are still using v0.27? https://github.com/fermyon/spin/blob/main/.github/workflows/build.yml#L206

[itowlson]

We will! Is it okay to say 0.32 and above, or should we tell folks 0.34?

[deadprogram]

I would recommend 0.35? That is the latest release and has a lot of important fixes and improvements.

[itowlson]

How did I miss the one right at the top? I'll update the build and the docs to use that. Thanks!

[adamreese]

I think this issue can be closed now that upstream fix is in place and docs are updated.