Whenever I run the JVM tests for my Kotlin Multiplatform Couchbase Lite library, I get a ton of these logs:
rotateLog fails to open /Users/runner/work/kotbase/kotbase/couchbase-lite/build/cb-tmp/cbl_test_scratch/log-dir_0OdgfeNqn4K7/cbl_info_1696182797644.cbllog
See this test run for example. This happens on both macOS and Linux, but not on Windows. It seems to be coming from this code in LiteCore, but is specifically happening with the Java SDK. It doesn’t happen with the iOS/macOS tests using the Objective-C SDK or native tests on Linux or Windows using the C SDK. I also don’t see logs like this on Android.
What would be causing this? It doesn’t seem to be problematic, but does overload and clutter the test error stream.
Note, my library is using CBL 3.0.12 currently, so I can’t yet confirm if anything might have changed with 3.1.x.
@jeff.lockhart : I don’t know why the open is failing; I can explain what is going on.
There are 2+ loggers: built in are the FileLogger and the ConsoleLogger. Both are available as properties of the java static Database.log
The FileLogger is a moderately complex beast. It is configured using a LogFileConfiguration. Unless an application configures the logger, no logs will be written to files. The test suite does configure the logger: deets below.
A configuration installed in the logger ( Database.log.getFile().setConfig(...) ) controls both the directory in which the logs are stored, and the way they are rotated. You can set a max size for a log file and the the number of log files to keep. When writing a log to a file causes it to exceed its max size, the file is closed, a new one opened and subsequent logs are written to the new file. If creating the new file creates maxFiles+1 log files, the oldest file is deleted.
Note that LiteCore logs the various log levels (Error, Warning, Info, Verbose, Debug) to separate files: the total size of the log directory is 4 * (maxFiles+1) * maxFileSize. 4, because production LiteCore disables Debug level logging.
log-dir_0OdgfeNqn4K7 Is a randomly named directory created in $ROOT/common/common/java/test/java/com/couchbase/lite/PlatformBaseTest.java for the Java test suite. Users/runner/work/kotbase/kotbase/couchbase-lite/build/cb-tmp/cbl_test_scratch should be writeable… and the log_dir created inside it should be writeable too.
I’m mystified. Hope that’s enough info so that you can figure something out…
Thanks for the explanation, @blake.meike. I narrowed down the cause to this line of LogTest, but still can’t figure out why it’s causing these error logs. The errors are not logged when running the LogTest tests by themselves, only when running all the tests together.
This test is the only test in LogTest that actually uses testWithConfiguration(). LogTest is nearly identical to your LogTest in the Java SDK, just with the internal specific tests commented out, based on these findings.
This other test also sets the FileLogger.config, but does not cause the errors to log as the other one is doing.
Indeed that scratch directory should be writable. The only thing I can think is that it could just not exist anymore, since the scratch directories are cleaned up at the end of the test suite. The file logging should be disabled, with the config set to null at the end of the LogTests too though.
It makes sense, to me, that this happens consistently, in kind of a random place. It is going to depend on when the log file gets big enough to be rolled. That is going to depend on the logging done by previous tests.
I’m not positive about this, but I am relatively certain that file logging is disabled for most of those “unit” tests. It is turned on only to test, exactly, the file logging feature.
I’d be looking for a reason that Java can’t create that file. If this were Windows, I’d look at permissions. Maybe quotas or something? Maybe something is altering the permissions of the directory, during the run.
I am, quite frankly, mystified: If it can create a log file at all, it ought to be able to create the second one… Maybe the file already exists?
The errors are not logged when running the LogTest tests by themselves, only when running all the tests together
Maybe the file already exists?
From the previous test, maybe? Maybe the random names aren’t re-generated?
This happens on both macOS and Linux, but not on Windows.
Maybe Windows is happy to use an existing file, but MacOS and Linux are not?
I narrowed down the cause to [this line of LogTest ]> testWithConfiguration(LogLevel.DEBUG, LogFileConfiguration(scratchDirPath!!))
Then using a different scratchDirPath for each run would solve the problem if it was because the file already exists?
@mreiche
From the previous test, maybe? Maybe the random names aren’t re-generated?
Shouldn’t be a problem. Not only are all of the files that the tests create randomly named each time they are created, but the directory in which a suite of test runs is also randomly named.
Then using a different scratchDirPath for each run would solve the problem if it was because the file already exists?
Yeah. That is, exactly, how the tests work: they create a new, randomly named scratch directory for each test run
I am relatively certain that file logging is disabled for most of those “unit” tests. It is turned on only to test, exactly, the file logging feature.
This is true. Those two tests are the only place in any of the test code that the file logging is accessed at all. And it’s really odd that one of the tests causes the errors, while the other doesn’t, as they’re both setting the file logging to the same scratch directory.
the files that the tests create randomly named each time
Also true. The log-dir paths are unique with each test run. The directories are empty each time. The directories are deleted at the end of the test suite.
I confirmed Database.log.file.config is null whenever the scratch directories are deleted at the end of the tests. So the file logging shouldn’t be accessing the path after this.
However, I also discovered that if I remove the code that deletes the scratch directories, then the errors are not logged. So the error does seem to be caused by the path not existing. But also LiteCore seems to still be accessing the file logging path even after the config is set to null, disabling file logging.
Is it possible even after file logging is disabled, that log rotation is somehow still continuing?
When I run the tests without deleting the scratch directories, one of the log-dir directories contains 6 log files, cbl_verbose…cbllog, cbl_debug…cbllog, cbl_warning…cbllog, cbl_error…cbllog, and 2 cbl_info…cbllog files. So it’s the info log file that is rotated. The other log-dir directories are mostly empty (one just has an empty foo directory from that other test).
I’m assuming this directory with logs is the last one configured, and it seems the file logging continues despite the config being set to null and level set to NONE. And the reason the other test that configures file logging doesn’t cause the error is because it doesn’t actually set the level, which defaults to NONE.
Could this be caused by setting the config to null before the level to NONE in the Log.reset() function?
Setting the file log level to NONE before the config to null doesn’t seem to make a difference. Although, using setLevel() to set the log level is an error if there is no configuration.
Testing this same behavior on the Windows platform, removing deletion of the scratch directories results in the same outcome with 6 log files, the info log being rotated. So there doesn’t seem to be a real difference between macOS, Linux, and Windows here, other than Windows doesn’t seem to log the error when it finds the file log directory doesn’t exist, or else somehow those logs aren’t making their way into the log output.
Oh for heavens sake: So, LiteCore is, apparently, trying to log even after the test is over. Filed CBL-4996 to fix this.
Thanks @blake.meike. To be clear, the tests aren’t actually failing, just cluttered with error logs from “rotateLog fails to open …” because the directory is deleted and file logging is continuing even after the level is set to NONE and config is set to null.
Since I was only seeing this on the JVM tests, I tested the macOS tests using the CBL Objective-C SDK to see what happens if the log-dir directory isn’t deleted. Sure enough, it experiences the same behavior of continuing the file logging, even after it’s reset at the end of the LogTest suite. The only difference is that there are two log-dir paths that contain logs and none of them are rotated. This probably just has something to do with the order that the tests are executed in on macOS vs JVM. LiteCore would probably log the same errors if the logs needed to be rotated, finding the directory missing.
Yeah… I get it. People get into the habit of ignoring errors, though, and that’s bad.
The ticket I filed is lopri.