Unable to read logs which contains unprintable characters

[Pesegato]

I have logs that sometimes contains unprintable characters (hexadecimal value 0x00, for example). In this case Lilith discards the record.

[huxi]

I need more info about how to reproduce this.

• Are you using the multiplex-appender?
• Logback or log4j1/2?
• Is just that single log record lost or the connection closed?
• Is something printed to the Lilith log (Cmd-0 or Ctrl-0)?
• Is something suspicious in the error log at ~/.lilith/errors.log?

etc.

[Pesegato]

• socket appender with XML formatter
• java.util.Logger
• all the records that contains unprintable chars

[huxi]

This should now be fixed in master.
Just build Lilith as described in the readme, i.e. first sulky, then lilith.

It would be nice if you could confirm if everything is fine or if I missed something.

Cheers, and thanks for the report!

[Pesegato]

Building sulky ok, build lilith with errors:

de.huxhorn.lilith.services.clipboard.LoggingEventJsonFormatterSpec > works on co
rpus. FAILED
    org.spockframework.runtime.SpockComparisonFailure

de.huxhorn.lilith.services.clipboard.LoggingThrowableFormatterSpec > works on co
rpus. FAILED
    org.spockframework.runtime.SpockComparisonFailure

151 tests completed, 2 failed
:lilith:test FAILED

FAILURE: Build failed with an exception.

* What went wrong:
Execution failed for task ':lilith:test'.

This is the report:

Test Summary
151
tests
2
failures
0
ignored
1.053s
duration
98%
successful
Failed tests
Packages
Classes
LoggingEventJsonFormatterSpec. works on corpus.
LoggingThrowableFormatterSpec. works on corpus.

[Pesegato]

Plus, if I try to run the "8.1.0-SNAPSHOT" with lilith.bat I get an error for input line too long, and lilith isn't started. Did anybody try the snapshot build with windows?

[huxi]

Nope, I don't have access to any Windows machine.

Gradle should tell you about the location of the test report.

It would be great if you could take a look at that HTML report and find out what's going wrong in the FormatterSpecs exactly. The file should be lilith/build/reports/tests/index.html and if you click on the failed tests, you should get more information about what exactly is going wrong.

There should also be a lilith/build/libs/de.huxhorn.lilith-8.1.0-SNAPSHOT-all.jar file that you can start using java -jar filename to circumvent the .bat problem.

I never heard of anything like that. Could be related to that strange Windows path length limit of 256 characters, though, so moving the whole distribution to a shorter path might already fix the problem. Just guessing here, though.

[huxi]

Regarding the tests: I suspect it's line ending stuff but I need to know...

[huxi]

I likely fixed the tests on Windows. Can't check myself, though.

[huxi]

I guess http://www.digizol.com/2006/12/input-line-is-too-long-windows-command.html describes the .bat problem.

Moving the lilith install to a shorter path should fix the problem. Or simply use the -all.jar mentioned above. I don't know how I should fix this.

[Pesegato]

with -all.jar I was able to run Lilith.
Now I can read logs containing hex characters, but they are printed out like this:
� 11�
Which is correct: unprintable character don't get printed but instead replaced with unicode. However, if a log contains binary stuff probably I'm interested in seeing the actual values. The ideal would be to have something like this:
� 11� (0x3F 0x20 0x 0x31 0x31 0x3F)

You might need this http://stackoverflow.com/questions/3585053/in-java-is-it-possible-to-check-if-a-string-is-only-ascii

I'll try with a shorter path, but I fear that the problem is because too many libraries are named "-SNAPSHOT" thus increasing their name size. Not much to do here, except document it on the readme.

[huxi]

The � are created by me explicitly in case of invalid characters contained in the XML stream erroneously produced by java.util.logging.XMLFormatter. It's actually a bug in XMLFormatter for which I implemented a workaround.

The problem you are actually facing is java.util.logging in general.

I'd strongly suggest to move away to a logging framework that is based on SLF4J. If you'd use Logback with the Lilith appender then you'd get exactly the behavior you suggest, i.e. a byte[] used as a log message parameter would be formatted as [0xCA, 0xFE, 0xBA, 0xBE].

But I know that circumstances won't always allow a free choice regarding the frameworks that are allowed to be used...

[Pesegato]

My problem is that I can't use Java 8 on the runtime log. Is it possible to have lilith appender compiled for earlier JDK? Lilith itself (herself?) is fine.

[huxi]

Just use version 0.9.44 in your app. They are compatible.

[Pesegato]

Can't make it work :(

here is the pastebin:
http://pastebin.com/rswp7jdS

[huxi]

I'm not sure what's wrong with the config. The "com" logger shouldn't be necessary since it's the same as the root logger.

I'd suggest that you try to get the config right with a small program that's just creating log events in a loop, ideally with some Thread.sleep() between them to not flood too badly. If you have a small program that just logs and then quits then you have a good chance that the log events won't have a chance to leave your app at all before it quits.

You can try a Logback SocketAppender with a queueSize of 1 to set it into synchronous mode.

I can't see any obvious error in your config... I might miss something, though.

[Pesegato]

Ok, I think I've found it. Let's make a step backward: originally, I had no idea which jar was needed for the logger, so I picked de.huxhorn.lilith.logback.appender.multiplex-classic.jar or something like that. But it complained of missing classes, so I added the classes until the error was gone. Now on my test case it says again Failed to instantiate [ch.qos.logback.classic.LoggerContext]
Reported exception:
java.lang.NoClassDefFoundError: de/huxhorn/sulky/io/TimeoutOutputStream
...and for some reason the library failed silently on the (non-Java8) logger.

...so I guess I should ditch the effort and just ask: which jar should I use?

[huxi]

Oh, you aren't using Maven or Gradle... Let's see...

Below are the runtime dependencies of multiplex-appender-classic:

runtime - Runtime dependencies for source set 'main'.
+--- de.huxhorn.sulky:de.huxhorn.sulky.codec:8.1.0-SNAPSHOT
|    +--- org.slf4j:slf4j-api:1.7.21
|    \--- de.huxhorn.sulky:de.huxhorn.sulky.io:8.1.0-SNAPSHOT
+--- project :lilith-data-logging-protobuf
|    +--- project :lilith-data-logging
|    |    +--- project :lilith-data-eventsource
|    |    \--- de.huxhorn.sulky:de.huxhorn.sulky.formatting:8.1.0-SNAPSHOT
|    |         \--- org.slf4j:slf4j-api:1.7.21
|    +--- com.google.protobuf:protobuf-java:2.6.1
|    \--- de.huxhorn.sulky:de.huxhorn.sulky.codec:8.1.0-SNAPSHOT (*)
+--- project :logback-multiplex-appender-core
|    +--- project :lilith-sender
|    |    +--- org.slf4j:slf4j-api:1.7.21
|    |    \--- de.huxhorn.sulky:de.huxhorn.sulky.io:8.1.0-SNAPSHOT
|    +--- de.huxhorn.sulky:de.huxhorn.sulky.codec:8.1.0-SNAPSHOT (*)
|    \--- ch.qos.logback:logback-core:1.1.7
+--- project :logback-converter-classic
|    +--- project :lilith-data-converter
|    +--- project :lilith-data-logging (*)
|    +--- project :logback-classic
|    |    \--- project :lilith-data-logging (*)
|    +--- de.huxhorn.sulky:de.huxhorn.sulky.codec:8.1.0-SNAPSHOT (*)
|    +--- org.slf4j:slf4j-api:1.7.21
|    \--- ch.qos.logback:logback-classic:1.1.7
|         +--- ch.qos.logback:logback-core:1.1.7
|         \--- org.slf4j:slf4j-api:1.7.20 -> 1.7.21
\--- ch.qos.logback:logback-classic:1.1.7 (*)

You can find out about those by changing into the directory logback/multiplex-appender-classic and executing ../../gradlew dependencies or ..\..\gradlew.bat dependencies respectively.

Both Maven and Gradle would take care of those for you.

Hope that helps.

[Pesegato]

OK that worked, but I stil don't see unprintable characters even with de.huxhorn.lilith.logback.appender.ClassicMultiplexSocketAppender

public class TestLog {

    final static Logger logger = LoggerFactory.getLogger(TestLog.class);

    public static void main(String args[]) {
        byte b[]=new byte[]{0x1,0x2,0x31};
        while (true){
       logger.warn(new String(b));
            try {
                Thread.sleep(1000);
            } catch (InterruptedException ex) {
                java.util.logging.Logger.getLogger(TestLog.class.getName()).log(Level.SEVERE, null, ex);
            }
        }
    }
}

On the lilith log I see " 1"

[huxi]

Your call should look like this:
logger.warn("byte array: {}", b);

I'm not sure if 0.9.44 is already formatting the byte[] as hex. Should at least print the numbers, e.g. "byte array: [1, 2, 3]". The current snapshot version would result in "byte array: [0x01, 0x02, 0x03]".

[Pesegato]

That did it! Yes, I get decimal values (49 instead of 0x31) but is enough. Many thanks! :)

[Pesegato]

I'd like to change the Remotehost of ClassicMultiplexSocketAppender programmatically... how can I do that?

[huxi]

That's more of a Logback issue than a Lilith issue. Please refer to the manual. It would probably be enough to use a Groovy Logback configuration instead of XML.