Client spews "Setting timeout of" messages

[larseggert]

Running the test/test.sh script generates a ton of messages like

0s356ms DEBUG [Client e4cf3ef0326dc9b16338] pn=9 type=Short pri-path:1bf8e83784f7e3129ce7 0.0.0.0:53440->127.0.0.1:4433 IpTos(Cs0, NotEct)
  TX -> ConnectionClose { error_code: Application(0), frame_type: 0, reason_phrase: [107, 116, 104, 120, 98, 121, 101, 33] }
0s357ms DEBUG [LossRecovery] packet ap-9 sent
0s357ms DEBUG Setting timeout of 141.61858ms
0s357ms DEBUG Setting timeout of 141.612121ms
0s357ms DEBUG Setting timeout of 141.607246ms
0s357ms DEBUG Setting timeout of 141.602788ms
0s357ms DEBUG Setting timeout of 141.598496ms
0s357ms DEBUG Setting timeout of 141.594246ms
0s357ms DEBUG Setting timeout of 141.590163ms
0s357ms DEBUG Setting timeout of 141.58608ms
0s357ms DEBUG Setting timeout of 141.581955ms
0s357ms DEBUG Setting timeout of 141.577871ms

after the client closes the connection.

Anyone got any idea where those come from? Maybe @mxinden?
client.log

[mxinden]

Both the client and the server log when setting a timeout (aka. callback):

neqo/neqo-bin/src/client/mod.rs

Lines 418 to 422 in dcc88e3

	Output::Callback(new_timeout) => {
	qdebug!("Setting timeout of {:?}", new_timeout);
	self.timeout = Some(Box::pin(tokio::time::sleep(new_timeout)));
	break;
	}

neqo/neqo-bin/src/server/mod.rs

Lines 516 to 520 in dcc88e3

	Output::Callback(new_timeout) => {
	qdebug!("Setting timeout of {:?}", new_timeout);
	self.timeout = Some(Box::pin(tokio::time::sleep(new_timeout)));
	break;
	}

I am not sure why the client continuously sets the same timeout.

after the client closes the connection.

I would expect the client to break out of the run loop once the connection is closed.

neqo/neqo-bin/src/client/mod.rs

Lines 392 to 393 in dcc88e3

	// no more work, connection closed, terminating
	(true, true) => break,

I can take a deeper look in the next couple of days.

[martinthomson]

This is probably the PTO time for the request. Once the client has sent its requests, it will need to wait for a response. This is what that waiting looks like.

We should just bump that message down to TRACE. If it is as commonplace as it is, then we don't need to see it in logs.

[larseggert]

But why would the client busy-wait like this? There are thousands of these in the log.

[martinthomson]

Is there some way in which the tokio select would exit early? The expected outcome is that the client should indicate it wants to wait for a PTO. The next thing should either be a new datagram arriving or the PTO expiring.

[martinthomson]

Ahh, I think that I can see what is happening. We're setting self.timeout, but we don't bother to tell the socket about it. The recv call therefore just polls without delay.

I think that the fix here is to have process_multiple_input exit once the timeout becomes Some. Otherwise, yes, the loop is a busy one.

[mxinden]

The problematic instruction is this continue, continuously closing an already closing connection:

neqo/neqo-bin/src/client/mod.rs

Lines 388 to 391 in 14cafba

	(true, false) => {
	self.client.close(Instant::now(), 0, "kthxbye!");
	continue;
	}

#1866 fixes the issue.

Regression introduced in #1837. Sorry about that. Thank you for raising it.