Logging fails on TinyGo Spin Apps

[kate-goldenring]

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?