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

fix(wasip2): fix environment initialization in reactors #4482

Closed
wants to merge 2 commits into from

Conversation

rvolosatovs
Copy link
Contributor

@rvolosatovs rvolosatovs commented Sep 26, 2024

Using init() to initialize stdio or environment is prone to race conditions for reactor-style components, e.g.
wasi:http/incoming-handler interface implementations due to the fact that init() is normally used to "register" the export implementation

In result, using e.g. fmt.Println may cause a runtime panic as follows:

ERROR wasmtime_cli::commands::serve: [125] :: Error {
    context: "error while executing at wasm backtrace:\n    0: 0x548e9 - wit-component:shim!indirect-wasi:io/streams@0.2.0-[method]output-stream.blocking-write-and-flush\n    1: 0x4d56 - main!(internal/wasi/io/v0.2.0/streams.OutputStream).BlockingWriteAndFlush\n    2: 0x99f0 - main!syscall.writeStream\n    3: 0x96a0 - main!write\n    4: 0x4623 - main!(os.unixFileHandle).Write\n    5: 0x3cf5 - main!wasi:http/incoming-handler@0.2.0#handle\nnote: using the `WASMTIME_BACKTRACE_DETAILS=1` environment variable may show more debugging information",
    source: "unknown handle index 0",
}
error: hyper::Error(User(Service), guest never invoked `response-outparam::set` method: error while executing at wasm backtrace:
    0: 0x548e9 - wit-component:shim!indirect-wasi:io/streams@0.2.0-[method]output-stream.blocking-write-and-flush
    1: 0x4d56 - main!(internal/wasi/io/v0.2.0/streams.OutputStream).BlockingWriteAndFlush
    2: 0x99f0 - main!syscall.writeStream
    3: 0x96a0 - main!write
    4: 0x4623 - main!(os.unixFileHandle).Write
    5: 0x3cf5 - main!wasi:http/incoming-handler@0.2.0#handle
note: using the `WASMTIME_BACKTRACE_DETAILS=1` environment variable may show more debugging information

Caused by:
    unknown handle index 0)

using sync.OnceValue to lazily initialize the environment instead of init() ensures correctness and should improve cold start times as a nice side effect (especially for applications not utilizing this functionality) I had to preserve the "eager" initialization approach in init(), to allow tests to pass but not exactly sure why

This issue can be reproduced using a wasi:http/incoming-handler implementation run in wasmtime 24

For example, I used https://github.com/Mossaka/hello-wasi-http-tinygo, to which I've added a fmt.Println line at the top

Using `init()` to initialize stdio or environment is prone to race
conditions for reactor-style components, e.g.
`wasi:http/incoming-handler` interface implementations due to the fact
that `init()` is normally used to "register" the export implementation

In result, using e.g. `fmt.Println` may cause a runtime panic as follows:

```
ERROR wasmtime_cli::commands::serve: [125] :: Error {
    context: "error while executing at wasm backtrace:\n    0: 0x548e9 - wit-component:shim!indirect-wasi:io/streams@0.2.0-[method]output-stream.blocking-write-and-flush\n    1: 0x4d56 - main!(internal/wasi/io/v0.2.0/streams.OutputStream).BlockingWriteAndFlush\n    2: 0x99f0 - main!syscall.writeStream\n    3: 0x96a0 - main!write\n    4: 0x4623 - main!(os.unixFileHandle).Write\n    5: 0x3cf5 - main!wasi:http/incoming-handler@0.2.0#handle\nnote: using the `WASMTIME_BACKTRACE_DETAILS=1` environment variable may show more debugging information",
    source: "unknown handle index 0",
}
error: hyper::Error(User(Service), guest never invoked `response-outparam::set` method: error while executing at wasm backtrace:
    0: 0x548e9 - wit-component:shim!indirect-wasi:io/streams@0.2.0-[method]output-stream.blocking-write-and-flush
    1: 0x4d56 - main!(internal/wasi/io/v0.2.0/streams.OutputStream).BlockingWriteAndFlush
    2: 0x99f0 - main!syscall.writeStream
    3: 0x96a0 - main!write
    4: 0x4623 - main!(os.unixFileHandle).Write
    5: 0x3cf5 - main!wasi:http/incoming-handler@0.2.0#handle
note: using the `WASMTIME_BACKTRACE_DETAILS=1` environment variable may show more debugging information

Caused by:
    unknown handle index 0)
```

using `sync.OnceValue` to lazily initialize the environment instead of `init()`
ensures correctness and should improve cold start times as a
nice side effect (especially for applications not utilizing this
functionality)

Signed-off-by: Roman Volosatovs <rvolosatovs@riseup.net>
@rvolosatovs rvolosatovs marked this pull request as draft September 26, 2024 14:47
Signed-off-by: Roman Volosatovs <rvolosatovs@riseup.net>
@rvolosatovs
Copy link
Contributor Author

Not exactly sure why, but looks like 1d20c31 is required to make the tests pass 🤔

@rvolosatovs rvolosatovs marked this pull request as ready for review September 26, 2024 14:54
@rvolosatovs rvolosatovs changed the title fix(wasip2): lazily initialize environment fix(wasip2): fix environment initialization race condition in reactors Sep 26, 2024
@aykevl
Copy link
Member

aykevl commented Sep 28, 2024

I don't really understand the problem yet, because race conditions aren't really a thing in init() functions (package initializers are all run one by one in _initialize, no parallelism involved).
I can see a few ways this could maybe happen:

  • Somehow, there's a package initializer that is run before the syscall package initializer, and it calls fmt.Println. I don't see how that's possible.
  • You are not calling _initialize before calling other exported functions.
  • You are doing parallel requests. This is unsupported, you can only call a single exported wasm function at a time. (This also means that you must wait for _initialize to return before calling any other exported functions).

Can you explain what's going on here?

@rvolosatovs
Copy link
Contributor Author

There are no dependencies here except for standard library and generated bindings using https://github.com/bytecodealliance/wasm-tools-go

Writing to stdio in wasi:http/incoming-handler.handle export implementation (registered in the init()) causes a trap, due to the runtime receiving an invalid resource handle when run with wasmtime serve -Scommon

By some reason the initializers for stdio do not run before stdio is used. This PR is a quickfix, which fixes that.
It may indeed be the case that wasmtime does not run _initialize (perhaps for reactor components), which would explain why the stdio is left uninitialized, bet that would also be surprising if that's the case since Wasmtime runtime is pretty well tested with various languages at this point.
Another option that comes to mind would be incorrect init() function ordering for dependencies.

I will investigate the _initialize specification and Wasmtime implementation and report back next week

@rvolosatovs rvolosatovs changed the title fix(wasip2): fix environment initialization race condition in reactors fix(wasip2): fix environment initialization in reactors Sep 28, 2024
@rvolosatovs
Copy link
Contributor Author

bytecodealliance/wasmtime#7592

Seems relevant

@aykevl
Copy link
Member

aykevl commented Sep 28, 2024

If _initialize isn't being called, that would be a much bigger problem as it also doesn't initialize the runtime (and therefore the heap is not initialized yet, for example). This PR would not fix that problem.

I'd like to understand what's going on here before merging, to make sure we're fixing the right bug.

You can maybe try putting a println statement in a init function to see whether it is being called?

@rvolosatovs
Copy link
Contributor Author

If _initialize isn't being called, that would be a much bigger problem as it also doesn't initialize the runtime (and therefore the heap is not initialized yet, for example). This PR would not fix that problem.

I'd like to understand what's going on here before merging, to make sure we're fixing the right bug.

You can maybe try putting a println statement in a init function to see whether it is being called?

This PR is meant to address the immediate symptoms of what appears to be a bigger problem indeed.

I can try calling a function from init next week, but do note that the export handler is registered in init https://github.com/Mossaka/hello-wasi-http-tinygo/blob/main/main.go#L10 (and it is active)

So unless variable assignments in init are handled in some different way, it does appear that init(), at least in main package, is called

@aykevl
Copy link
Member

aykevl commented Sep 28, 2024

So unless variable assignments in init are handled in some different way,

They are. Many variables are already initialized by a compiler pass as an optimization. Which variables are initialized like this is unspecified, but simple assignments like this one are typically done at compile time.
You wouldn't notice the difference however as long as _initialize is being called. Which it appears is not the case here.

A function like println (which does I/O) cannot be done at compile time and using it is a good way to test whether _initialize is being called.

@rvolosatovs
Copy link
Contributor Author

So unless variable assignments in init are handled in some different way,

They are. Many variables are already initialized by a compiler pass as an optimization. Which variables are initialized like this is unspecified, but simple assignments like this one are typically done at compile time. You wouldn't notice the difference however as long as _initialize is being called. Which it appears is not the case here.

A function like println (which does I/O) cannot be done at compile time and using it is a good way to test whether _initialize is being called.

I tried calling fmt.Println in init() and indeed it had no effect. It seems that either lazy initialization should be used for reactors or some other way to trigger init() is required (which would probably be expected by users)

@lxfontes
Copy link

lxfontes commented Oct 1, 2024

(sharing experience, not sure how much it helps)

This can be replicated in a regular wasip2 component. Combinations:

  • global var statically defined
  • global var set within init
  • pointers in global vars
  • function calls in global & init
  • var set in the actual wasm call
type holder struct {
	str    string
	ptr    *string
	mapStr map[string]string
	mapPtr map[string]*string
}

var (
	varHolder = holder{
		str:    "top",
		ptr:    ptrFunc(),
		mapStr: map[string]string{"a": "b"},
		mapPtr: map[string]*string{"c": ptrFunc()},
	}
	ptrHolder *holder
)

func init() {
	ptrHolder = &holder{
		str:    "top",
		ptr:    ptrFunc(),
		mapStr: map[string]string{"a": "b"},
		mapPtr: map[string]*string{"c": ptrFunc()},
	}
	caller.Exports.Call = callHandler
}

func ptrFunc() *string {
	s := time.Now().String()
	return &s
}

func callHandler() string {
	callHolder := holder{
		str:    "top",
		ptr:    ptrFunc(),
		mapStr: map[string]string{"a": "b"},
		mapPtr: map[string]*string{"c": ptrFunc()},
	}
	ret := fmt.Sprintf("varHolder: %+v\nptrHolder: %+v\ncallHolder: %+v\n", varHolder, ptrHolder, callHolder)

	return ret
}

yields

varHolder: {str:top ptr:0x15b30 mapStr:map[] mapPtr:map[]}
ptrHolder: &{str:top ptr:0x15b40 mapStr:map[] mapPtr:map[]}
callHolder: {str:top ptr:0x15df0 mapStr:map[a:b] mapPtr:map[c:0x16140]}

looks like symbols & pointers work fine, but things that require make don't.

@aykevl
Copy link
Member

aykevl commented Oct 2, 2024

Ok, clearly the bug here is that package initializers are not being run. I don't know what the exact problem is, but the proposed fix here doesn't fix the root cause (it only hides some symptoms of the bug).

Closing, since this is the wrong way to fix this bug.

I am pretty sure you should adjust your wasm VM to call _initialize on startup.

@aykevl aykevl closed this Oct 2, 2024
@rvolosatovs rvolosatovs deleted the fix/wasip2-env-race branch October 2, 2024 14:30
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants