SocketAppender stopped working about lilith HOT 21 CLOSED

Hm... that's strange. Never seen anything like that. What port are you connecting to? And what version of Logback are you using?

Also, please check the internal Lilith log (Cmd-0/Ctrl-0) for any suspicious output.

from lilith.

4560 on both cases.

  <appender name="SOCKET" class="ch.qos.logback.classic.net.SocketAppender">
    <remoteHost>localhost</remoteHost>
    <port>4560</port>
    <reconnectionDelay>10000</reconnectionDelay>
  </appender>

from lilith.

The same happens on 8.0 "official". To recap:
8.0 don't work
8.1 don't work
8.1-SNAPSHOT works

from lilith.

That sounds suspiciously like a Logback version incompatibility problem where the SNAPSHOT version is using the Logback version matching yours by coincidence.

8.1 release is using Logback 1.2.1, i.e. the latest.

from lilith.

Already tried to upgrade to 1.2.1, no success (and besides, both logback AND lilith don't tell which version of logback they are running... I would assume universal compatibility)

from lilith.

Lilith says which version of Logback it is using in the release notes.

I just double-checked with my small sandbox application using this configuration and everything works fine.

I can only ensure compatibility in case of my own multiplex appender that is using protobuf for event encoding but I can't do so in case of serialized events.

Did you check the internal Lilith logs as I suggested? Another place to look would be the error log in [lilith.home]/errors.log... but that should only contain uncaught exceptions.

from lilith.

Couldn't start ServerSocket on port 10001!

Level

ERROR

Logger

de.huxhorn.lilith.engine.impl.sourceproducer.AbstractServerSocketEventSourceProducer

Thread

AWT-EventQueue-0 (id=56)

Timestamp

2017-03-15 11:06:36.923

Call Location

at de.huxhorn.lilith.engine.impl.sourceproducer.AbstractServerSocketEventSourceProducer.(AbstractServerSocketEventSourceProducer.java:71)

from lilith.

That should be unrelated. Something is occupying port 10001 but that shouldn't cause any problems for port 4560... Can you reboot your machine and check for other stuff like firewall rules?

This isn't reproducible for me right now so we first need to rule out the most common problems.

from lilith.

Today I rebooted, same behavior. But on the log I see

Exception (java.lang.NullPointerException: 'null') while reading events. Adding eventWrapper with empty event and stopping...

Throwable



java.lang.NullPointerException

at org.slf4j.helpers.BasicMarker.hasReferences(BasicMarker.java:75) ~[slf4j-api-1.7.24.jar:1.7.24]

at de.huxhorn.lilith.data.logging.logback.LogbackLoggingConverter.initMarkerRecursive(LogbackLoggingConverter.java:195) ~[de.huxhorn.lilith.logback.converter-classic-8.1.0.jar:na]

at de.huxhorn.lilith.data.logging.logback.LogbackLoggingConverter.initMarker(LogbackLoggingConverter.java:179) ~[de.huxhorn.lilith.logback.converter-classic-8.1.0.jar:na]

at de.huxhorn.lilith.data.logging.logback.LogbackLoggingConverter.convert(LogbackLoggingConverter.java:270) ~[de.huxhorn.lilith.logback.converter-classic-8.1.0.jar:na]

at de.huxhorn.lilith.data.logging.logback.LogbackLoggingConverter.convert(LogbackLoggingConverter.java:57) ~[de.huxhorn.lilith.logback.converter-classic-8.1.0.jar:na]

at de.huxhorn.lilith.engine.impl.eventproducer.ConvertingStreamEventProducer.postProcessEvent(ConvertingStreamEventProducer.java:86) ~[de.huxhorn.lilith.engine-8.1.0.jar:na]

at de.huxhorn.lilith.engine.impl.eventproducer.AbstractStreamEventProducer$ReceiverRunnable.run(AbstractStreamEventProducer.java:83) ~[de.huxhorn.lilith.engine-8.1.0.jar:na]

at java.lang.Thread.run(Unknown Source) [na:1.8.0_121]

from lilith.

Lilith run on the same pc that is producing the log. Also tried to run lilith as administrator.

from lilith.

Is there anything like an Unauthorized deserialization attempt! message in the logs?

Checked the slf4j code and don't see how referenceList can be null at that point...

from lilith.

I could replicate the issue but I still don't understand the root cause.

from lilith.

OK... this is very likely a problem caused by not using both org.slf4j:slf4j-api:1.7.24 and ch.qos.logback:logback-classic:1.2.1.

I had a similar issue while using org.slf4j:slf4j-api:1.7.23 with ch.qos.logback:logback-classic:1.2.1 by mistake.

With the 1.7.24/1.2.1 combination, everything works fine again.

Consider using my multiplex appender. It works fine with either combination.

Please let me know if this solves your issue.

from lilith.

Indeed I was using slf4j-api:1.7.21; upgrading this lib solved "my" the problem. However... I think Lilith has a problem for not letting the user know this.

from lilith.

I think slf4j/logback has a problem with breaking compatibility in minor version upgrades.

To be more precise: the problem is that this commit in slf4j changed the structure of BasicMarker without also changing the serialVersionUID, preventing the Java deserialization logic from exploding with a reasonable error message.
So a field that "couldn't" be null (in slf4j 1.7.24) was null because it could be null in previous versions of slf4j.

I mean... what would you expect from me/Lilith in this case?

I had no idea that this issue exists at all so how should I let users know about it?
This isn't supposed to happen, in my opinion, and it doesn't in case of the Lilith multiplex appender which is entirely under my control and based on protobuf, thus not having strange serialization issues.

The only other thing I can do is making sure that Lilith "works for me" with the latest slf4j/logback/log4j/log4j2 versions available. And those are listed in the CHANGELOG and the respective release notes.

What else can I possibly do?

Anyway, thanks for analyzing this with me.

from lilith.

I see. I think that Lilith should do 2 things:

• In the "troubleshooting" screen lilith should document this trouble and offer suggestions
• Again in the "troubleshooting" (or somewhere else) show the version compatibility (yes, it is on the release notes, but is buried with tons of other information)

...otherwise risk to waste time (yours and of your users)

from lilith.

Sorry, my bad. Changed the serialVersionUID with qos-ch/slf4j@a8489127b08bd5b8

from lilith.

@Pesegato Thanks for the suggestion.
This is what the Troubleshooting section will look like in the next release:

@ceki Happens. It took me quite a while to realize what exactly was going wrong. It's only obvious in hindsight.

from lilith.

@ceki When you release qos-ch/slf4j@a8489127b08bd5b8 then please try to release a logback version depending on that slf4j version soon after.
Part of the problem is that logback 1.2.1 is still depending on slf4j 1.7.22, causing NPE in Lilith that is using 1.7.24 already.

from lilith.

In general slf4j version are backward compatible. Without the BasicMarker serialization serialization issue you can use slf4j-api version 1.6.0 released 7 years ago. Having said that recent versions of logback require slf4j-api 1.7.16+ because logback supports slf4j event-replay feature during initialization. This requirement is only visible if and when logback classes are introspected, for example by spring.

Anyway, logback 1.2.2 and slf4j 1.7.25 were just released in lock step as you suggested.

from lilith.

Just released Lilith 8.1.1 using slf4j 1.7.25 and logback 1.2.2 and including the above changes to Troubleshooting section of Preferences.

from lilith.