Universalmediaserver: Bad format in debug.log

[taconaut]

Lately it happened a few times that when opening the debug.log file by clicking the button from the traces tab, PSPad (my default editor associated with *.log files) showed the log as if it were a file in HEX format.

PSPad:

Notepad++:

These NUL values shouldn't be there and seem to confuse PSPad.

I think the issue happens when a second log file is being created, but am not really sure about it as I haven't found a way to consistently reproduce it.

[Nadahar]

Very strange. I haven't seen it. Truncating the file is done by logback, so it's a bit strange if we've caused that.

Do you have a custom logback configuration that split the log into multiple files?

[taconaut]

It's probably not exactly the same as the UMS one, but I'm only using a FileAppender (see logback.xml).
Here's the beginning of the log file containing those NUL, if it can be of any use.

[Nadahar]

@taconaut The linked logback.xml is identical to the current default UMS file.

I don't think the log file itself can give much clues, we have to try to figure out what is happening. There's quite a big time gap before and after the NUL entries.

[taconaut]

Ok, then we can be sure it's not related to a custom logback configuration.
I'll see if it happens again and if I can add some more info then.

[Nadahar]

Yes, as it is now there's really not a lot to go on.

[taconaut]

The path contained in the file I've attached is weird. C:\Program Files (x86)\Jenkins\jobs\ums-mlx trunk (nightly)\workspace\core\src\main\external-resources\logback.xml is my jenkins build from where I've never launched ums. Could unit tests be at cause?

[Nadahar]

Hmm... a lot of the tests do reset logback configuration... that could be something...

I've made some tests that just set root level to OFF instead, maybe that's either a reason or solution. The standard solution is simply to initialize logback and then reset/clear the configuration. But, the actual logback.xml must be explicitly loaded to interfere with debug.log, so it's hard to see how that could impact the log file. Maybe some of the logging tests actually log the real configuration, I don't remember.

[Nadahar]

@taconaut I made ce175f255c4a252a0c2d50cc0d2f5ebf631c1145 yesterday. If fixes some potential synchronization issues with the cachelogger and the logging tests that could have brought strange results under rare circumstances. It shouldn't under normal circumstances though, since the unprotected calls were run from the same thread. But during testing, strange things might have occurred.

I'd be great if you could report back if you ever see this bug again when this commit is included.

[taconaut]

Cheers, I'll let you know if I see this happening again (or not)

[Sami32]

@taconaut @SubJunk So, what happened ? No news good news :-)

[taconaut]

I didn't notice it again and as it isn't a big issue anyway, you can close it

[Nadahar]

It's likely that the concurrency bug fixed in ce175f255c4a252a0c2d50cc0d2f5ebf631c1145 was the culprit. If tests were run in parallel the bug would probably cause problems.

[Sami32]

@Nadahar Thanks for the information :-)