`wasix_32v1`.`sock_status` never changes after `sock_open` or `sock_bind` calls

Question

`wasix_32v1`.`sock_status` never changes after `sock_open` or `sock_bind` calls

Closed this issue 3 months ago · 7 comments

Describe the bug

Unable to wasix_32v1.sock_listen without getting error code 4. I can't find any documentation that might imply I am setting up the socket incorrectly - but maybe it's just a skill issue on my part.

Steps to reproduce

Save the source below as server.wat
wasmer server.wat --net
See error error code 0 at line 50 (printed at Panic __4 @ _50)

Expected behavior

There should be no error code (code==0) when calling sock_listen, unless:

The socket is already bound
Permissions are lacking (no --net)
The file descriptor is invalid
Bad backlog size

Actual behavior

Error code 4 (Errno::Interrupted) when attempting to listen to a bound socket

Additional context

I have tried running the wasm version of the Winter.js benchmark to ensure that isn't the issue isn't just a part of my local config or wasmer install

Source

(module
  (type (;0;) (func (param i32) (result i32)))
  (type (;1;) (func (param i32 i32) (result i32)))
  (type (;2;) (func (param i32 i32 i32) (result i32)))
  (type (;3;) (func (param i32 i32 i32 i32) (result i32)))
  (type (;4;) (func (param i32 i32 i32 i32 i32) (result i32)))
  (type (;5;) (func))
  (type (;6;) (func (param i32)))
  (type (;7;) (func (param i32 i32)))
  (import "wasi_snapshot_preview1" "fd_write" (func (;0;) (type 3)))
  (import "wasi_snapshot_preview1" "fd_close" (func (;1;) (type 0)))
  (import "wasix_32v1" "sock_open"      (func (;2;) (type 3)))
  (import "wasix_32v1" "sock_bind"      (func (;3;) (type 1)))
  (import "wasix_32v1" "sock_listen"    (func (;4;) (type 1)))
  (import "wasix_32v1" "sock_accept_v2" (func (;5;) (type 3)))
  (import "wasix_32v1" "sock_send"      (func (;6;) (type 4)))
  (import "wasi_snapshot_preview1" "proc_exit" (func (;7;) (type 6)))

  ;; main()
  (func (;8;) (type 5) (local i32 i32)
    ;; Create socket using sock_open
    i32.const 2   ;; PF_NET
    i32.const 1   ;; SOCK_STREAM
    i32.const 0   ;; Protocol
    i32.const 80  ;; result pointer
    call 2        ;; sock_open

    ;; panic on error @
    (call 9 i32.const 29)

    ;; Load the socket descriptor from memory
    i32.const 80
    i32.load
    local.set 0

    ;; Bind socket to address and port
    local.get 0   ;; Socket file descriptor
    i32.const 48  ;; Address of the sockaddr_in structure
    call 3        ;; sock_bind

    ;; panic on error @
    (call 9 i32.const 42)

    ;; Listen for incoming connections
    local.get 0   ;; Socket file descriptor
    i32.const 1   ;; Backlog (maximum pending connections)
    call 4        ;; sock_listen

    ;; panic on error @
    (call 9 i32.const 50)

    local.get 0   ;; Listening socket file descriptor
    i32.const 0   ;; Desired file descriptor flags (default)
    i32.const 80  ;; result pointer: new socket
    i32.const 68  ;; result pointer: remote address
    call 5        ;; sock_accept_v2

    ;; panic on error @
    (call 9 i32.const 59)

    ;; Load the new socket descriptor from memory
    i32.const 80
    i32.load
    local.set 1

    ;; Send response to the client
    local.get 1   ;; socket
    i32.const 16  ;; iovs
    i32.const 1   ;; iovs_len
    i32.const 0   ;; No additional flags
    i32.const 56  ;; ptr: remote address
    call 6        ;; sock_send

    ;; panic on error @
    (call 9 i32.const 75)

    ;; TOOD: loop forever to respond to more than a single request
    (loop
      br 0
    )
  )

  ;; panicOnError(code: i32, lineNum: i32)
  (func (;9;) (type 7) (param i32 i32)
    local.get 0
    i32.const 0
    i32.eq
    if
      return
    end

    ;; overwrite string encoding param.0
    i32.const 6
    (call 10
      (i32.div_u local.get 0 i32.const 100)
      i32.const 2
    )
    i32.store8

    i32.const 7
    (call 10
      (i32.div_u local.get 0 i32.const 10)
      i32.const 1
    )
    i32.store8

    i32.const 8
    (call 10
      local.get 0
      i32.const 0
    )
    i32.store8

    ;; overwrite string encoding param.1
    i32.const 12
    (call 10
      (i32.div_u local.get 1 i32.const 100)
      i32.const 2
    )
    i32.store8

    i32.const 13
    (call 10
      (i32.div_u local.get 1 i32.const 10)
      i32.const 1
    )
    i32.store8

    i32.const 14
    (call 10
      local.get 1
      i32.const 0
    )
    i32.store8

    ;; write to buffer
    i32.const 1   ;; std.io file descriptor
    i32.const 16  ;; iovs
    i32.const 1   ;; iovs_len
    i32.const 80  ;; nwritten
    call 0        ;; fd_write
    drop

    local.get 0
    call 7
  )

  ;; digitToChar(num: i32, place: i32)
  (func (;10;) (type 1) (param i32 i32) (result i32) (local i32)
    (i32.rem_u
      local.get 0
      i32.const 10
    )
    local.set 2

    local.get 1
    i32.const 0
    i32.ne
    if
      local.get 2
      i32.const 0
      i32.eq
      if
        i32.const 95
        return
      end
    end

    local.get 2
    i32.const 48
    i32.add
    return
  )
  (memory (;0;) 1)
  (export "memory" (memory 0))
  (export "_start" (func 8))

  (data (i32.const 0) "Panic ??? @ ???")
  (data (i32.const 16) "\00\00\00\00\0f\00\00\00")

  ;; sockaddr_in
  (data (i32.const 48) "\02\00")                   ;; sin_family: AF_INET = 0x0002
  (data (i32.const 50) "\1f\90")                   ;; sin_port:      8080 = 0x901F
  (data (i32.const 52) "\00\00\00\00")             ;; sin_addr:INADDR_ANY = 0.0.0.0
  (data (i32.const 54) "\00\00\00\00\00\00\00\00") ;; sin_zero = char[8] padding for sockaddr compatibility

  ;; global: remote sock_addr
  (data (i32.const 56) "\00\00\00\00\00\00\00\00\00\00\00\00\00\00\00\00")

  ;; http response
  (data (;1;) (i32.const 64) "\44\00\00\00\20\00\00\00")
  (data (;0;) (i32.const 68) "HTTP/1.1 200 OK\0d\0a\0d\0aHello, World!")

  ;; extra blank

  ;; stack: offset.80
)

Answer 1 · 2024-03-12T02:25:16.000Z

RUN-110 Always getting `Errno::Interrupted` on `wasix_32v1`.`sock_listen` call

Answer 2 · 2024-03-12T04:18:19.000Z

I did some more experimentation, and it seems the socket never changes from an opening status when I tried blocking on a while loop after sock_open or sock_bind

Gist: server.wat

Answer 3 · 2024-03-12T06:28:09.000Z

Confirmed with defintly occurs on both Windows 11, and Ubuntu with wasmer 4.2.6

Answer 4 · 2024-03-12T09:48:11.000Z

@AjaniBilby you run with RUST_LOG=wasmer_wasix=trace wasmer run ... to get more details about the syscall invocations, that might provide some insight.

For context on calling the APIs correctly you can check for example the WASIX libc here: https://github.com/wasix-org/wasix-libc

My bet is that the encoding might be wrong.

Please first try to get the debug logs above to see if that helps, otherwise we can dig into it further.

Answer 5 · 2024-03-12T10:21:56.000Z

That extra logging makes the problem seem evident, unless I'm miss-reading
It seems to be starting AF_INET6 instead of AF_INET with sin_family = 2, which does seem to be the correct value based on some grepping of the wasix-libc. So the socket binds incorrectly with an IPv4 treated as IPv6, then silently fails during opening

I tried some other values for sin_family such as PF_INET6 = 10 and __WASI_ADDRESS_FAMILY_INET4 = 1, but they caused error code 28 on the bind call.

Changing the address_family on the sock_open appears to have no affect on the program at all.

But here is the log with source unchanged from the gist:

wasmer server.wat --net
⠁ Compiling to WebAssembly                                                                                                                                                                                                                                                              2024-03-12T10:20:14.118083Z DEBUG ThreadId(01) load_module:load: wasmer_wasix::runtime::module_cache::shared: close time.busy=3.60µs time.idle=5.70µs key=CEEB85D313148508
2024-03-12T10:20:14.118698Z DEBUG ThreadId(22) wasmer_wasix::runtime::module_cache::filesystem: Cache hit!
2024-03-12T10:20:14.118788Z DEBUG ThreadId(01) load_module:load: wasmer_wasix::runtime::module_cache::filesystem: close time.busy=28.4µs time.idle=594µs key=CEEB85D313148508
2024-03-12T10:20:14.118850Z DEBUG ThreadId(01) load_module:save: wasmer_wasix::runtime::module_cache::shared: close time.busy=3.20µs time.idle=2.50µs key=CEEB85D313148508
2024-03-12T10:20:14.118907Z DEBUG ThreadId(01) load_module: wasmer_wasix::runtime: close time.busy=274µs time.idle=596µs
2024-03-12T10:20:14.119152Z DEBUG ThreadId(01) prepare_webc_env: wasmer_wasix::runners::wasi: close time.busy=46.6µs time.idle=1.70µs
2024-03-12T10:20:14.119222Z DEBUG ThreadId(01) wasmer_wasix::fs: Initializing WASI filesystem
2024-03-12T10:20:14.119283Z DEBUG ThreadId(01) wasmer_wasix::fs: Attempting to preopen / with alias None
2024-03-12T10:20:14.119332Z DEBUG ThreadId(01) wasmer_wasix::fs: Attempting to preopen / with alias Some(".")
2024-03-12T10:20:14.119404Z TRACE ThreadId(01) wasmer_wasix::state::env: import wasix_32v1.fd_write
2024-03-12T10:20:14.119447Z TRACE ThreadId(01) wasmer_wasix::state::env: import wasix_32v1.fd_close
2024-03-12T10:20:14.119487Z TRACE ThreadId(01) wasmer_wasix::state::env: import wasix_32v1.sock_open
2024-03-12T10:20:14.119527Z TRACE ThreadId(01) wasmer_wasix::state::env: import wasix_32v1.sock_bind
2024-03-12T10:20:14.119567Z TRACE ThreadId(01) wasmer_wasix::state::env: import wasix_32v1.sock_listen
2024-03-12T10:20:14.119607Z TRACE ThreadId(01) wasmer_wasix::state::env: import wasix_32v1.sock_accept_v2
2024-03-12T10:20:14.119647Z TRACE ThreadId(01) wasmer_wasix::state::env: import wasix_32v1.sock_send
2024-03-12T10:20:14.119686Z TRACE ThreadId(01) wasmer_wasix::state::env: import wasix_32v1.sock_status
2024-03-12T10:20:14.119725Z TRACE ThreadId(01) wasmer_wasix::state::env: import wasix_32v1.proc_exit
2024-03-12T10:20:14.120225Z TRACE ThreadId(01) wasmer_wasix::state::func_env: initializing with layout WasiMemoryLayout { stack_upper: 1048576, stack_lower: 0, guard_size: 0, stack_size: 1048576 }
2024-03-12T10:20:14.120357Z DEBUG ThreadId(01) sock_open: wasmer_wasix::syscalls::wasix::sock_open: return=Ok(Errno::success) af=Addressfamily::Inet6 ty=Socktype::Stream pt=SockProto::Ip sock=6
2024-03-12T10:20:14.120414Z DEBUG ThreadId(01) sock_open: wasmer_wasix::syscalls::wasix::sock_open: close time.busy=69.7µs time.idle=700ns af=Addressfamily::Inet6 ty=Socktype::Stream pt=SockProto::Ip sock=6
2024-03-12T10:20:14.120494Z DEBUG ThreadId(01) sock_bind: wasmer_wasix::syscalls::wasix::sock_bind: return=Ok(Errno::success) sock=6 addr="[::4400:0]:36895"
2024-03-12T10:20:14.120559Z DEBUG ThreadId(01) sock_bind: wasmer_wasix::syscalls::wasix::sock_bind: close time.busy=76.2µs time.idle=2.60µs sock=6 addr="[::4400:0]:36895"
2024-03-12T10:20:14.120641Z DEBUG ThreadId(01) sock_status: wasmer_wasix::syscalls::wasix::sock_status: return=Errno::success sock=6 status="Sockstatus::Opening"
2024-03-12T10:20:14.120694Z DEBUG ThreadId(01) sock_status: wasmer_wasix::syscalls::wasix::sock_status: close time.busy=61.3µs time.idle=1.00µs sock=6 status="Sockstatus::Opening"
Sock Status: __0
2024-03-12T10:20:14.120906Z TRACE ThreadId(01) fd_write: wasmer_wasix::syscalls::wasi::fd_write: return=Ok(Errno::success) fd=1 nwritten=20
2024-03-12T10:20:14.120960Z TRACE ThreadId(01) fd_write: wasmer_wasix::syscalls::wasi::fd_write: close time.busy=201µs time.idle=800ns fd=1 nwritten=20
2024-03-12T10:20:14.122139Z DEBUG ThreadId(01) sock_listen: wasmer_wasix::syscalls::wasix::sock_listen: return=Ok(Errno::addrnotavail) sock=6 backlog=1
2024-03-12T10:20:14.122196Z DEBUG ThreadId(01) sock_listen: wasmer_wasix::syscalls::wasix::sock_listen: close time.busy=1.17ms time.idle=900ns sock=6 backlog=1
Panic __4 @ _50
2024-03-12T10:20:14.122326Z TRACE ThreadId(01) fd_write: wasmer_wasix::syscalls::wasi::fd_write: return=Ok(Errno::success) fd=1 nwritten=16
2024-03-12T10:20:14.122382Z TRACE ThreadId(01) fd_write: wasmer_wasix::syscalls::wasi::fd_write: close time.busy=130µs time.idle=800ns fd=1 nwritten=16
2024-03-12T10:20:14.122440Z DEBUG ThreadId(01) proc_exit: wasmer_wasix::syscalls::wasi::proc_exit: code=ExitCode::addrnotavail (error 4)
2024-03-12T10:20:14.122486Z DEBUG ThreadId(01) proc_exit: wasmer_wasix::syscalls::wasi::proc_exit: close time.busy=46.5µs time.idle=600ns
2024-03-12T10:20:14.129003Z TRACE ThreadId(01) wasmer_wasix::state::builder: main exit pid=1 tid=1 exit_code=ExitCode::addrnotavail (error 4) error=WASI error error.sources=[WASI exited with code: ExitCode::addrnotavail (error 4)]
2024-03-12T10:20:14.129079Z TRACE ThreadId(01) wasmer_wasix::state::func_env: wasi[1:1]::on_exit
2024-03-12T10:20:14.129131Z TRACE ThreadId(01) wasmer_wasix::state::env: cleaning up open file handles pid=1
2024-03-12T10:20:14.129193Z TRACE ThreadId(01) wasmer_wasix::fs: weakening file descriptor fd=4 inode=5 ref_cnt=2
2024-03-12T10:20:14.129252Z TRACE ThreadId(01) wasmer_wasix::fs: closing file descriptor fd=2 inode=4 ref_cnt=1
2024-03-12T10:20:14.129306Z TRACE ThreadId(01) wasmer_wasix::fs: closing file descriptor fd=6 inode=7 ref_cnt=1
2024-03-12T10:20:14.129411Z TRACE ThreadId(01) wasmer_wasix::fs: weakening file descriptor fd=5 inode=6 ref_cnt=2
2024-03-12T10:20:14.129483Z TRACE ThreadId(01) wasmer_wasix::fs: closing file descriptor fd=1 inode=3 ref_cnt=1
2024-03-12T10:20:14.129547Z TRACE ThreadId(01) wasmer_wasix::fs: closing file descriptor fd=0 inode=2 ref_cnt=1
2024-03-12T10:20:14.129616Z TRACE ThreadId(01) wasmer_wasix::fs: weakening file descriptor fd=3 inode=1 ref_cnt=2
2024-03-12T10:20:14.129688Z TRACE ThreadId(01) wasmer_wasix::os::task::process: signal-process(Signal::Sigquit) pid=1

This debug line throws a lot of alarm bells for me:

2024-03-12T10:20:14.120694Z DEBUG ThreadId(01) sock_status: wasmer_wasix::syscalls::wasix::sock_status: close time.busy=61.3µs time.idle=1.00µs sock=6 status="Sockstatus::Opening"

This line implies the socket_status is both closed and opening

Answer 6 · 2024-03-12T22:59:26.000Z

Looking at those same logs for Winter.js it's clear that my socket isn't being opened correctly

2024-03-12T22:35:43.507166Z DEBUG ThreadId(39) sock_open: wasmer_wasix::syscalls::wasix::sock_open: return=Ok(Errno::success) af=Addressfamily::Inet4 ty=Socktype::Stream pt=SockProto::Tcp sock=9
2024-03-12T22:35:43.507238Z DEBUG ThreadId(39) sock_open: wasmer_wasix::syscalls::wasix::sock_open: close time.busy=77.3µs time.idle=700ns af=Addressfamily::Inet4 ty=Socktype::Stream pt=SockProto::Tcp sock=9
2024-03-12T22:35:43.507329Z DEBUG ThreadId(39) sock_bind: wasmer_wasix::syscalls::wasix::sock_bind: return=Ok(Errno::success) sock=9 addr="127.0.0.1:8080"
2024-03-12T22:35:43.507393Z DEBUG ThreadId(39) sock_bind: wasmer_wasix::syscalls::wasix::sock_bind: close time.busy=72.1µs time.idle=1.50µs sock=9 addr="127.0.0.1:8080"
2024-03-12T22:35:43.507526Z DEBUG ThreadId(39) sock_set_opt_flag: wasmer_wasix::syscalls::wasix::sock_set_opt_flag: return=Ok(Errno::success) sock=9 opt=Sockoption::ReuseAddr flag=true
2024-03-12T22:35:43.507598Z DEBUG ThreadId(39) sock_set_opt_flag: wasmer_wasix::syscalls::wasix::sock_set_opt_flag: close time.busy=100µs time.idle=1.10µs sock=9 opt=Sockoption::ReuseAddr flag=true
2024-03-12T22:35:43.508066Z DEBUG ThreadId(39) sock_listen: wasmer_wasix::syscalls::wasix::sock_listen: return=Ok(Errno::success) sock=9 backlog=128
2024-03-12T22:35:43.508142Z DEBUG ThreadId(39) sock_listen: wasmer_wasix::syscalls::wasix::sock_listen: close time.busy=437µs time.idle=800ns sock=9 backlog=128

Looking at the wasix-libc you can see that socket is clearly just a proxy function for sock_open.
socket is called by is_wasi_port_ok with parameters (AF_INET, SOCK_STREAM, 0)

AF_INET appears to be defined as __WASI_ADDRESS_FAMILY_INET4 when received from wasm as uposed to the value it's translated to for native call - and __WASI_ADDRESS_FAMILY_INET4 is defined as (UINT8_C(1)).
SOCK_STREAM appears to be defined as __WASI_SOCK_TYPE_SOCKET_STREAM which is defined as (UINT8_C(1))

Based on all of this we can assume the socket() call in is_wasi_port_ok has the values socket(1, 1, 0) which means the call sock_open(1, 1, 0) is called. This then fixes the first issue which is that the socket is being opened as IPv6 instead of IPv4

2024-03-12T22:54:11.486116Z DEBUG ThreadId(01) sock_open: wasmer_wasix::syscalls::wasix::sock_open: return=Ok(Errno::success) af=Addressfamily::Inet4 ty=Socktype::Stream pt=SockProto::Ip sock=6
2024-03-12T22:54:11.486204Z DEBUG ThreadId(01) sock_open: wasmer_wasix::syscalls::wasix::sock_open: close time.busy=104µs time.idle=1.30µs af=Addressfamily::Inet4 ty=Socktype::Stream pt=SockProto::Ip sock=6

Based on the fact that AF_INET is using the value of 1 instead of 2 which is standard in most POSIX systems I then also applied that in sockaddr_in.sin_family which then allowed the socket it work.

Since there is a macro defining these values under __WASI_*, are these values stable? And if so do you think it's okay for me to write up some docs about these values for the wasix api and make a PR over there?

Answer 7 · 2024-03-13T08:48:33.000Z

Great findings, thanks for diving deep.

are these values stable?

Yes, since we have quite a bit of compiled code that works with these values, we will not make arbitrary breaking changes.
Breaking changes would come with a bump in the namespace or with _v2 functions to call.

And if so do you think it's okay for me to write up some docs about these values for the wasix api and make a PR over there?

That would be highly appreciated!