Null Pointer in FuryLogger log method

[davidnadeau]

Search before asking

• I had searched in the issues and found no similar issues.

Version

0.6.0

Component(s)

Java

Minimal reproduce step

Pass in a null msg, and the logger will fail to log the error message and instead print:

j.l.NullPointerException: Cannot invoke "String.length()" because "msg" is null
	at o.a.f.l.FuryLogger.log(FuryLogger.java:145)
	at o.a.f.l.FuryLogger.error(FuryLogger.java:133)

The null pointer is caused by this line: https://github.com/apache/fury/blob/releases-0.6/java/fury-core/src/main/java/org/apache/fury/logging/FuryLogger.java#L145. We should first check that the msg is not null, before trying to get its length.

What did you expect to see?

I expect the stack trace to print if mayPrintTrace is true, even when the msg is null.

What did you see instead?

the actual error is not printed, instead we get a null pointer printed, this makes debugging the actual error more difficult.

Anything Else?

No response

Are you willing to submit a PR?

• I'm willing to submit a PR!

[chaokunyang]

Do you use FuryLogger directly? Fury didn't pass null message to FuryLogger. But still, I will fix right now

[davidnadeau]

No I do not, this stack trace shows better that fury is passing in null messages to FuryLogger:

java.lang.NullPointerException: Cannot invoke "String.length()" because "msg" is null
	at org.apache.fury.logging.FuryLogger.log(FuryLogger.java:145)
	at org.apache.fury.logging.FuryLogger.error(FuryLogger.java:133)
	at org.apache.fury.pool.ThreadPoolFury.execute(ThreadPoolFury.java:81)
	at org.apache.fury.pool.ThreadPoolFury.serialize(ThreadPoolFury.java:92)

[chaokunyang]

I see, thanks. I fixed it in #1762. I'm curious about why ThreadPoolFury throws exception. Do you invoked this method with your function?

[davidnadeau]

I have this setup:

val fury = Fury
    .builder()
    .withLanguage(Language.JAVA)
    .withScalaOptimizationEnabled(true)
    .requireClassRegistration(false)
    .withRefTracking(false)
    .buildThreadSafeFuryPool(Runtime.getRuntime.availableProcessors() * 2, Runtime.getRuntime.availableProcessors() * 2)

Then I call fury.serialize(value) and fury.deserialize(bytes).asInstanceOf[Value]

[davidnadeau]

I wonder if there is an issue with Scala compatibility. I am seeing strange errors like:

java.lang.NullPointerException: Cannot read field "serializer" because "classInfo" is null at 
org.apache.==fury==.resolver.ClassResolver.getOrUpdateClassInfo(ClassResolver.java:1151) at 
org.apache.==fury==.resolver.ClassResolver.readClassInfo(ClassResolver.java:1609) at 
org.apache.fury.Fury.readRef(Fury.java:825) at org.apache.fury.Fury.deserialize(Fury.java:760) at 
org.apache.fury.Fury.deserialize(Fury.java:682) at 
org.apache.fury.pool.ThreadPoolFury.lambda$deserialize$9(ThreadPoolFury.java:135) at 
org.apache.fury.pool.ThreadPoolFury.execute(ThreadPoolFury.java:79) at 
org.apache.fury.pool.ThreadPoolFury.deserialize(ThreadPoolFury.java:135)

and

Failed to deserialize key: �����+mxe������(����(��(�� due to exception: java.lang.NullPointerException: Cannot read field "serializer" because "classInfo" is null"

[chaokunyang]

Could you provide reproduction code?

[davidnadeau]

I will try today to see if I can create a reproducible code snippet

[chaokunyang]

If the schema are inconsistent, you may need to set CompatibleMode to Compatible

[davidnadeau]

Thanks, the schema of the class is not changing the data looks like

case class Features(id: Long, counts: Option[CountFeature], timeseries: Option[TimeseriesFeature])
case class CountFeature(featureA: Option[Long], featureB: Option[Long], featureC: Option[Long], featureD: Option[Long])
case class TimeseriesFeature(
  featureA: Option[List[TimestampedId]],
  featureB: Option[List[TimestampedId]],
  featureC: Option[List[TimestampedId]],
  featureD: Option[List[TimestampedId]]
)
case class TimestampedId(timestamp: Instant, id: Long)

Features is the type being serialized to and from using Fury.

[davidnadeau]

I havn't been able to reproduce this issue outside of my company infrastructure, which is k8s running debian 11, jdk 17. I created a small Scala app that uses Fury andTwitter Finagle, and in a loop serializes and deserializes randomly generated Features objects on multiple different threads. However, this code was not able to reproduce any errors.

The issue only happens at pod startup, I will see a large surge of errors like:

java.lang.NullPointerException: Cannot read field "serializer" because "classInfo" is null at org.apache.==fury==.resolver.ClassResolver.getOrUpdateClassInfo(ClassResolver.java:1151) at org.apache.==fury==.resolver.ClassResolver.readClassInfo(ClassResolver.java:1609) at org.apache.fury.Fury.readRef(Fury.java:825) at org.apache.fury.Fury.deserialize(Fury.java:760) at org.apache.fury.Fury.deserialize(Fury.java:682) at org.apache.fury.pool.ThreadPoolFury.lambda$deserialize$9(ThreadPoolFury.java:135) at org.apache.fury.pool.ThreadPoolFury.execute(ThreadPoolFury.java:79) at org.apache.fury.pool.ThreadPoolFury.deserialize(ThreadPoolFury.java:135)

and

Failed to deserialize key: �����+mxe������(����(��(�� due to exception: java.lang.NullPointerException: Cannot read field "serializer" because "classInfo" is null"

Then they subside after a few seconds, and fury serialization/deserialization becomes stable.

[davidnadeau]

I'll try to keep digging, and open up another issue if I find something conclusive. If you have any hints or ideas, that would help me a lot.

[chaokunyang]

I see Wrapped by: j.l.NoClassDefFoundError: Could not initialize class com.etsy.mmx.core.se.. from your pasted stacktrace in slack, could you share more detailed stack?