Connection forcibly closed using `TcpStream` as `Box<dyn Write + Send>`

[disassembledd]

I am attempting to chain my logger to a TcpStream in a client/server setup. I can apply the log and proceed to use it, however, it appears to be forcibly closed, presumably by fern, at a certain point within my process. It is not a timed issue as I can apply a fake workload or sleep and the connection stays open. I am calling the Win32 API using COM objects, though I don't believe that is relevant.

I can apply the meta-logging-in-format feature and it gets me one function call further for no logical reason as the windows-rs crate does not log anywhere whatsoever. I also do not have any structs in the client which directly implement Display and if they implement Debug, it's only derived.

[daboross]

I don't have an immediate solution here, but perhaps I can provide some help.

The implementation - where we write to dyn Write + Send is here:

fern/src/log_impl.rs

Lines 576 to 617 in fdff7e8

	macro_rules! writer_log_impl {
	($ident:ident) => {
	impl Log for $ident {
	fn enabled(&self, _: &log::Metadata) -> bool {
	true
	}
	fn log(&self, record: &log::Record) {
	fallback_on_error(record, |record| {
	if cfg!(feature = "meta-logging-in-format") {
	// Formatting first prevents deadlocks on file-logging,
	// when the process of formatting itself is logged.
	// note: this is only ever needed if some Debug, Display, or other
	// formatting trait itself is logging.
	let msg = format!("{}{}", record.args(), self.line_sep);
	let mut writer = self.stream.lock().unwrap_or_else(|e| e.into_inner());
	write!(writer, "{}", msg)?;
	writer.flush()?;
	} else {
	let mut writer = self.stream.lock().unwrap_or_else(|e| e.into_inner());
	write!(writer, "{}{}", record.args(), self.line_sep)?;
	writer.flush()?;
	}
	Ok(())
	});
	}
	fn flush(&self) {
	let _ = self
	.stream
	.lock()
	.unwrap_or_else(|e| e.into_inner())
	.flush();
	}
	}
	};
	}

(self.stream is the Box<dyn Write + Send>)

If meta-logging-in-format is getting you further, is there any possibility the receiver of the TcpStream is closing after exactly one call to write(&[u8])?

Fern won't do any buffering itself for Box<dyn Write + Send> instances, and doesn't do an intermediate format unless meta-logging-in-format is enabled, so each separate part of a formatted message will result in a separate call to write(&[u8]).

Each log message will thus usually result in many calls to TcpStream::write(&[u8]) - except if meta-logging-in-format is enabled, where each log message will result in one call to TcpStream::write(&[u8]).

If you haven't already done this debugging, could you try calling TcpStream::write(&[u8]) with some dummy bytes twice or three times, then calling flush? If that errors out, I believe that should remove fern from the equation and make the rest easier to debug. If it doesn't, then maybe I can help more with figuring out what's different between that and what fern is doing.

[Soul85]

I have since went down a different avenue though for the sake of possible resolution, the receiver is only receiving and never writes back. It also makes no attempts to close the connection or stop listening until given a keyword from the sender. What I was developing was a remote agent for the Windows Update API that would write to the tool a sysadmin would use, providing period progress reports.