Logs from FileSystemHandler are not captured in tests

[inetic]

When a println! line is inserted into a function inside an implementation of the FileSystemHandler and a test is run, the println! line is not captured by the test but is printed out right when the test is run.

For example, if we add println!("<<< hello from handler >>>") above this line, and then run the (currently failing) test cargo test can_find_files. The output is

running 1 test
<<< hello from handler >>>
test usage_tests::can_find_files ... FAILED

failures:

---- usage_tests::can_find_files stdout ----
thread 'usage_tests::can_find_files' panicked at dokan\src\usage_tests.rs:1144:9:
assertion `left == right` failed
  left: 16
 right: 128
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace


failures:
    usage_tests::can_find_files

test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 32 filtered out; finished in 0.02s

error: test failed, to rerun pass `-p dokan --lib`

Notice that the "<<< hello from handler >>>" line appears above the "---- usage_tests::can_find_files stdout ----" line.

This would normally not be too big of a problem, but it becomes one when tests run ok individually and only start misbehaving when they are run all at once.

My theory is that the FileSystemHandler functions are being called from insider the driver and this somehow circumvents the stdout output that the test is capturing. But I know next to nothing about Windows driver development, so I might very well be wrong.

Perhaps there is a flag that I missed that could fix this? Or maybe someone could suggest a fix?

[Liryna]

Hi @inetic ,

I have limited rust knowledge but I don't believe this is related to the driver.
Rust seems to have some rules regarding output in tests so that’s maybe the reason somehow https://stackoverflow.com/questions/25106554/why-doesnt-println-work-in-rust-unit-tests

[inetic]

Hi @Liryna , thanks for the reply.

Yeah, when one doesn't use the --nocapture flag (which I am purposely not using), the test should "buffer" the standard output and only print it out on the screen if the test fails, one test output at a time. But this is not what I see, what I see is that the output is not buffered and is printed on the screen right a way and because the tests are run concurrently, I see the output from all tests interleaved.

Thinking about it, what I wrote above that it might be a driver thing is probably not the case because (if I understand it correctly) the FileSystemHandler code must be run from the same process as the app, that is, not from the driver.

An interesting thing is, that if I do println!("<<< hello from test >>>") in the test body (e.g. above this line), then that line is buffered. It's really only the prinln! lines from the handler functions that are not captured.

<<< hello from handler >>>
test usage_tests::can_find_files ... FAILED

failures:

---- usage_tests::can_find_files stdout ----
<<< hello from test >>>
thread 'usage_tests::can_find_files' panicked at dokan\src\usage_tests.rs:1144:9:
assertion `left == right` failed
  left: 16
 right: 128
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace


failures:
    usage_tests::can_find_files

test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 32 filtered out; finished in 0.03s

So if it's not related to the code being run from the driver, another thing that comes to my mind that could cause this is if the Dokan (Rust or C) code redirected the stdout to stderr because AFAIK the stderr is not being captured/buffered.

Would you know if Dokan has code that is doing a redirection like that?

[Liryna]

The Dokan C library does not redirect stdout.

Looking at the code, I would expect to have create and other calls (by the OS or other apps) done at mount time (with_test_drive) and therefore before the actual can_find_files scope with the test code running.

dokan-rust/dokan/src/usage_tests.rs

Lines 1188 to 1189 in f3c2280

	fn can_find_files() {
	with_test_drive(|context| {

[Liryna]

@inetic have you been able to make progress here ? Can this be closed ?

[inetic]

I have fixed a problem that I had with a workaround to this issue and them moved to work on something else. I do plan to come back to this when there is more time or once I'm back to working on Windows. If you wish, I'm fine if you close this ticket and I or someone can reopen it when it's an issue again.