Unavailable feed is not reported in metrics, root cause is unclear

hbruch commented 1 month ago

Expected behavior

A feed that has been subscribed to successfully but turns unavailable (e.g. due to exceptions when parsing a result) should be reported in the metrics.

Observed behavior

For some of our feeds, we receive NPEs during update. Neither is the reason recognizable from the exception, nor is the system_id:

{"serviceContext":{"service":"lamassu"},"message":"Caught exception in ForkJoinPool
java.lang.NullPointerException: null
 java.base/jdk.internal.reflect.DirectConstructorHandleAccessor.newInstance(DirectConstructorHandleAccessor.java:62)
 java.base/java.lang.reflect.Constructor.newInstanceWithCaller(Constructor.java:502)
 java.base/java.lang.reflect.Constructor.newInstance(Constructor.java:486)
 java.base/java.util.concurrent.ForkJoinTask.getThrowableException(ForkJoinTask.java:542)
 java.base/java.util.concurrent.ForkJoinTask.reportException(ForkJoinTask.java:567)
 java.base/java.util.concurrent.ForkJoinTask.invoke(ForkJoinTask.java:670)
 java.base/java.util.stream.ForEachOps$ForEachOp.evaluateParallel(ForEachOps.java:160)
 java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateParallel(ForEachOps.java:174)
 java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:233)
 java.base/java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:596)
 java.base/java.util.stream.ReferencePipeline$Head.forEach(ReferencePipeline.java:765)
 org.entur.gbfs.GbfsSubscriptionManager.lambda$update$0(GbfsSubscriptionManager.java:91)
 java.base/java.util.concurrent.ForkJoinTask$RunnableExecuteAction.exec(ForkJoinTask.java:1423)
 java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:387)
 java.base/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1312)
 java.base/java.util.concurrent.ForkJoinPool.scan(ForkJoinPool.java:1843)
 java.base/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1808)
 java.base/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:188)
Caused by: java.lang.NullPointerException: null
","severity":"WARN","reportLocation":{"filePath":"org.entur.lamassu.leader.FeedUpdater","lineNumber":"107","functionName":"lambda$start$0"}}

To debug this issue, this discussion of NPEs in ForkJoinPool might be helpful.

I suggest to let GbfsSubscription.update throw a custom Lamassu exception in case of error, providing a) the system Id and b) the causing exception including stacktrace. Additionally, the FeedUpdater might provide appropriate metric state for this subscription.

Version of lamassu used (exact commit hash or JAR name)

373e17a

Steps to reproduce the problem

Can't yet reproduce locally.

hbruch commented 1 month ago

In fact, there a two unrelated issues: the exception is not related to the unavailable feed, but caused by a missing form_factor in https://gbfs.nextbike.net/maps/gbfs/v2/nextbike_eh/en/vehicle_types.json:

The above exception was not the first of it's kind in the logs and due to JVM optimizations (see this StackOverflow answer) lacked the stacktrace of the causing NPE.

Scrolling up in the logs reveals the root cause: the update fails as the ingested feed apparently does not provide a formFactor for all of it's vehicleTypes:

...
Caused by: java.lang.NullPointerException: Cannot invoke \"org.entur.gbfs.v2_3.vehicle_types.GBFSVehicleType$FormFactor.name()\" because the return value of \"org.entur.gbfs.v2_3.vehicle_types.GBFSVehicleType.getFormFactor()\" is null\n\tat org.entur.lamassu.mapper.entitymapper.VehicleTypeMapper.mapVehicleType(VehicleTypeMapper.java:54)\n\tat org.entur.lamassu.leader.entityupdater.VehiclesUpdater.lambda$getVehicleTypes$6(VehiclesUpdater.java:272)\n\tat java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:197)\n\tat java.base/java.util.ArrayList$ArrayListSpliterator.forEachRemaining(ArrayList.java:1708)\n\tat java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:509)\n\tat java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:499)\n\tat java.base/java.util.stream.ReduceOps$ReduceOp.evaluateSequential(ReduceOps.java:921)\n\tat java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)\n\tat java.base/java.util.stream.ReferencePipeline.collect(ReferencePipeline.java:682)\n\tat org.entur.lamassu.leader.entityupdater.VehiclesUpdater.getVehicleTypes(VehiclesUpdater.java:278)\n\tat org.entur.lamassu.leader.entityupdater.VehiclesUpdater.addOrUpdateVehicles(VehiclesUpdater.java:144)\n\tat org.entur.lamassu.leader.entityupdater.EntityCachesUpdater.updateEntityCaches(EntityCachesUpdater.java:51)\n\tat org.entur.lamassu.leader.FeedUpdater.receiveV2Update(FeedUpdater.java:257)\n\tat org.entur.lamassu.leader.FeedUpdater.lambda$createSubscription$2(FeedUpdater.java:161)\n\tat org.entur.gbfs.loader.v2.GbfsV2Subscription.update(GbfsV2Subscription.java:109)\n\tat java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:184)\n\tat java.base/java.util.concurrent.ConcurrentHashMap$ValueSpliterator.forEachRemaining(ConcurrentHashMap.java:3612)\n\tat java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:509)\n\tat java.base/java.util.stream.ForEachOps$ForEachTask.compute(ForEachOps.java:291)\n\tat java.base/java.util.concurrent.CountedCompleter.exec(CountedCompleter.java:754)\n\t... 5 common frames omitted\n","severity":"WARN","reportLocation":{"filePath":"org.entur.lamassu.leader.FeedUpdater","lineNumber":"107","functionName":"lambda$start$0"}}

hbruch commented 1 month ago

Closing this issue in favor of #453 and #250, which, I suppose, describe the different issues better.

entur / lamassu