Shadow warnings

[jtracey]

I'm running some Shadow (603ae87) Tor experiments with some Rust application code, and am seeing some warnings. I suspect they're all harmless, since the experiments seem to run fine, but was hoping for a second opinion to be sure:

• [legacy_tcp.rs:1247] [shadow_rs::host::descriptor::socket::inet::legacy_tcp] setsockopt called with unsupported level 6 and opt 31
• [unix.rs:2211] [shadow_rs::host::descriptor::socket::unix] Unix sockets with pathname addresses are not yet supported
• [callback_queue.rs:47] [shadow_rs::utility::callback_queue] Very likely an infinite loop of event callbacks.

The first two seem to be throughout the experiment, the last one is only at the very end of the experiment, right at the 01:00:00.000000000 mark.

[stevenengler]

[legacy_tcp.rs:1247] [shadow_rs::host::descriptor::socket::inet::legacy_tcp] setsockopt called with unsupported level 6 and opt 31

This is SOL_TCP and TCP_ULP. It's probably being used for in-kernel TLS. Hopefully the application has a fallback TLS implementation (it probably does if it's not failing). I don't know much about the TLS ULP, but if you can verify TLS is still working then it's probably fine. Do you know what application or library is triggering this warning?

[unix.rs:2211] [shadow_rs::host::descriptor::socket::unix] Unix sockets with pathname addresses are not yet supported

This is probably due to hostname lookups. I don't remember the exact code path, but something in libc will sometimes try to connect to the unix socket for systemd-resolved or something. You should be able to check the strace log for the process and look at the connect() calls. There should be one that's connecting to a pathname address, and the pathname should let you know what it is. But it's common to see these in tor sims. This should probably be downgraded from a warning since the syscall will already return an error, or we should use the warn_once_then_debug macro.

[callback_queue.rs:47] [shadow_rs::utility::callback_queue] Very likely an infinite loop of event callbacks

This one is interesting, I've never seen it be triggered before. My guess is that it might happen when dropping the descriptor table. If there's a process with more than 10_000 file descriptors, it might trigger that. If you could change the warning to a panic (or maybe add log::warn!("Backtrace: {}", Backtrace::force_capture()) if you don't want to panic a long simulation), we might be able to see what shadow's doing when that happens. But since the process doesn't seem to get stuck, this is probably harmless.

[jtracey]

Do you know what application or library is triggering this warning?

This actually seems to be coming from tor.

My guess is that it might happen when dropping the descriptor table. If there's a process with more than 10_000 file descriptors, it might trigger that.

The process in question is a server that relies heavily on Tokio channels (for a graph with ~300 nodes, not fully but decently well connected); if it's sending events on destruction to all of those, that would definitely explain it. If I were to scale up and see this warning earlier, that would be a problem though? Not something that would need fixing on Shadow's end to be clear, I can easily scale up the number of servers to accommodate.

[stevenengler]

Do you know what application or library is triggering this warning?

This actually seems to be coming from tor.

Ah cool, it seems this is part of openssl now: openssl/openssl#5253

I think openssl seems to fall back to non-kernel tls, but it's good to know this exists.

My guess is that it might happen when dropping the descriptor table. If there's a process with more than 10_000 file descriptors, it might trigger that.

The process in question is a server that relies heavily on Tokio channels (for a graph with ~300 nodes, not fully but decently well connected); if it's sending events on destruction to all of those, that would definitely explain it. If I were to scale up and see this warning earlier, that would be a problem though? Not something that would need fixing on Shadow's end to be clear, I can easily scale up the number of servers to accommodate.

I'm not sure exactly what you mean by sending events on destruction, but I don't think it would be a problem if you scaled up. I'll try to explain how the callback queue is being used:

We mainly use callbacks in Shadow for file-related events. So for example if something like an epoll file or a blocked syscall is waiting for a state change on another file (for example a read() syscall blocked waiting for a file to become readable).

This CallbackQueue object exists in shadow to prevent recursive mutable borrows when running callbacks. For example if A listens for events on B and B listens for events on A, a state change on A could run B's callback, causing a state change on B which could run A's callback while we're already in the middle of the initial state change on A (causing a runtime panic). So the callback queue allows us to queue callbacks so that code can finish what it's doing and run the callback later. The callback queues are only temporary and are short-lived. If the warning is appearing in the log, it means that there have been at least 10_000 callbacks added to the queue.

For a simple case like a socket becoming readable, you would expect at most a few callbacks (for example a callback to notify an epoll file, a callback to wake a blocked epoll_wait syscall, and a callback to wake a thread blocked on a recv() syscall for the socket). The warning exists because at the time I couldn't conceive of a situation that would cause 10_000 callbacks, and I figured that if we hit this number, then it was likely an infinite loop (imagine A notifies B which notifies A which notifies B ...) and having a warning would be helpful for debugging.

When a thread exits it drops a reference to its descriptor table. When the descriptor table is dropped, it removes all files from the table and calls close() on them. This code all uses a single CallbackQueue, and any callbacks generated from closing the files will be added to this queue. For example if the descriptor table has 10_000 sockets and all of those sockets are being watched by an epoll file, then closing those 10_000 sockets will cause 10_000 callbacks to run informing the epoll file that each socket has closed.

shadow/src/main/host/descriptor/descriptor_table.rs

Lines 208 to 221 in 603ae87

	// Drop all descriptors using a callback queue.
	//
	// Doing this explicitly instead of letting `DescriptorTable`'s `Drop`
	// implementation implicitly close these individually is a performance
	// optimization so that all descriptors are closed before any of their
	// callbacks run.
	let descriptors = self.remove_all();
	crate::utility::legacy_callback_queue::with_global_cb_queue(|| {
	CallbackQueue::queue_and_run(|cb_queue| {
	for desc in descriptors {
	desc.close(host, cb_queue);
	}
	})
	});

This is not really a bad thing. Each socket needs to inform the epoll file that the socket closed, regardless of if we're using this CallbackQueue or not. So if there's a good reason for 10_000 callbacks then it's fine. It would only be a problem if it was getting stuck in an infinite loop.