TcpConnection writes become stuck

[gbl08ma]

Steps to reproduce:

1. Set up a v86 VM that boots the linux4.iso available at https://i.copy.sh/linux4.iso (note: you might need to copy link and paste in a new window to not run into a 403 Forbidden 😕)
2. Create a stack with a TAP interface and attach it to the v86 VM, more or less like this:

const networkStack = await createStack();

const tapInterface = await networkStack.createTapInterface({
  mac: '02:00:00:01:00:01',
  ip: 192.168.255.1/24',
});

const vmNic = createV86NetworkStream(emulator);
tapInterface.readable.pipeTo(vmNic.writable);
vmNic.readable.pipeTo(tapInterface.writable);

3. Create a TCP listener that queues lots of stuff to be written as soon as a client connects, more or less like this:

const listener = await lan.listenTcp(5000);
const handler = async () => {
	for await (const connection of listener) {
		const readable = new ReadableStream({
			start: (controller) => {
				const a = async () => {
					for (let j = 0; j < 10; j++) {
						const b = new TextEncoder().encode('12345678\nabcdefgh\n'.repeat(2000) + "END\n");
						controller.enqueue(b);
					}
				};
				a();
			}
		});

		// could also use await readable.pipeTo(connection.writable) - it also wouldn't work as intended
		const reader = readable.getReader();
		const writer = connection.writable.getWriter();
		while (true) {
			const { done, value } = await reader.read();
			if (done) break;
			await writer.write(value);
		}
	}
};
handler();

3. Boot the VM and assign it an IP within the subnet, with ifconfig eth0 up arp 192.168.255.2. You may ping 192.168.255.1 to confirm it's connected.
4. Connect to the listener with e.g. telnet 192.168.255.1 5000

Expectation: the full stream available from the ReadableStream gets printed, ending with END.

What I observe: after one or two calls to writer.write (depends on how much is being written/read at a time from the reader-writer combo), the promise returned by writer.write(value) never resolves and the data transfer becomes stuck, despite the VM guest still having the socket open and trying to receive data.
I observe the same behavior with Windows guests inside the VM, and also when using the stream() provided by a File from a file input.

If you have trouble reproducing just let me know, I can try to set up a full minimal example that's ready to run.

[gregnr]

Thanks for the report and repro details @gbl08ma - I'll try to recreate and see if I can get to the bottom of it.

[Angelmmiguel]

@gregnr @gbl08ma I found that sometimes the network stack waits a certain amount of time before sending the data (~300ms). Checking the lwIP docs, I found that the tcp_write method does not send the data immediately. The project use this method when sending the TCP chunks:

tcpip.js/packages/tcpip/wasm/tcp.c

Line 29 in 59f9944

err_t result = tcp_write(conn, chunk, bytes_to_send, TCP_WRITE_FLAG_COPY);

To ensure it sends the data immediately, we can call the tcp_output method.

I'm not sure if this is related, but I found some weird behaviors with WebStreams and delays. I will open a PR to fix this :)

[gregnr]

@gbl08ma it's been a little while, but wanted to mention that we fixed @Angelmmiguel's TCP slowdown issue in #23. I'm not 100% sure if this is related to your issue since you mentioned that the data transfer becomes stuck vs slow, but would you mind giving it another shot and see if anything improves?

[gbl08ma]

I think this is an unrelated problem. I recently had a bit of time which I used to update my project to tcpip 0.3.3 and do a brief test, and unfortunately the problem persisted. I'll try to find some more time to at least get a simpler example that reproduces the problem - preferably one that doesn't involve v86, but I wonder if the problem isn't precisely related to v86 also being involved (especially because v86 also has wasm stuff to run).

The server code on my actual project looks like this:

const listener = await lan.listenTcp(port);
const handler = async () => {
	try {
		for await (const connection of listener) {
			console.log('file transfer connection');
			/*await file.stream().pipeTo(connection.writable);*/
			const reader = file.stream().getReader();
			const writer = connection.writable.getWriter();
			while (true) {
				const { done, value } = await reader.read();
				console.log("read", done, value?.length);
				if (done) break;
				await writer.write(value);
				console.log("wrote");
			}
			reader.releaseLock();
			writer.releaseLock();
			console.log('file transfer done');
			writer.close();
			connection.close();
			console.log('file transfer closed');
			return;
		}
	} catch (e) {
		console.log("file transfer handler exception:", e)
		return;
	}
};
handler();

i.e. I am getting a ReadableStream from a File, and trying to pipe it to the TcpConnection's WritableStream in a pretty straightforward fashion. My TCP client (inside the VM) is also pretty straightforward, it just keeps pulling bytes until the connection closes. And what I see in the console when the client connects is the following (the file is 23598 bytes long):

file transfer connection
read false 23598

and that's it, "wrote" never gets logged; inside the VM, some bytes are received (in the test runs I did today, the client always received exactly 5840 bytes) but the connection never closes and the rest of the bytes aren't received in the TCP connection either. So the server is stuck on await writer.write(value); and the client is stuck waiting for more bytes or for the connection to be closed (which it never is, because the server code never reaches connection.close();).
This is pretty much the case I had in my original example, except my original example sometimes manages to perform some smaller writes before getting stuck at a later point (presumably because it writes fewer bytes at a time).

[gregnr]

@gbl08ma thanks for confirming. Good news - I was able to reproduce this and I think I have a fix. There were 2 issues:

1. Linux's TCP stack uses the timestamp option (used in TCP headers), and we didn't have that enabled in lwIP. For some reason this prevented Linux from sending any more packets after its initial SYN from telnet. Enabling it in lwIP fixed this.
2. There was a bug in tcpip.js C bindings that only registered ACKs from outbound TCP connections but not inbound (whoops). This isn't as bad as it sounds since lwIP mostly handles ACKs for us, but in the case where you send a large payload that is greater than the send buffer size (which happens to be 5840), then it will stall forever because we have logic that waits for these ACKs to know when to send more data. Adding in this ACK registration fixed this.

I need to add some tests to catch this going forward - once that's done I'll create a PR.

By the way, we'll likely increase these buffer sizes in the future to support faster data transfers, but its actually good we've kept it low until now so that we catch these kind of bugs.

[gregnr]

Update - tests have been added but now previous TCP back pressure tests are failing. I'm still trying to figure out exactly why they're failing, but its likely to do with the fact that the TCP header size is different now that the timestamp option is enabled and this throws off MSS.