search

clulab / reach

Reach Biomedical Information Extraction
Other
97 stars 39 forks source link

Errors during RunReachCLI over 100k papers #573

Open herongrove opened 6 years ago

herongrove commented 6 years ago

When running runReachCLI.sh, I'm getting many similar instances of this error (but only after it's been running for days):

08:37:36.760 [ForkJoinPool-1-worker-1549] ERROR org.clulab.reach.ReachCLI - 
==========

 ¡¡¡ NxmlReader error !!!

paper: PMC4537452

error:
java.lang.IllegalStateException: cannot enqueue after timer shutdown

stack trace:
akka.actor.LightArrayRevolverScheduler.scheduleOnce(LightArrayRevolverScheduler.scala:136)
akka.actor.Scheduler$class.scheduleOnce(Scheduler.scala:140)
akka.actor.LightArrayRevolverScheduler.scheduleOnce(LightArrayRevolverScheduler.scala:37)
akka.pattern.PromiseActorRef$.apply(AskSupport.scala:599)
akka.pattern.AskableActorRef$.internalAsk$extension(AskSupport.scala:294)
akka.pattern.AskableActorRef$.$qmark$extension1(AskSupport.scala:281)
org.clulab.processors.client.ProcessorClient.callServer(ProcessorClient.scala:106)
org.clulab.processors.client.ProcessorClient.preprocessText(ProcessorClient.scala:149)
org.clulab.reach.PaperReader$$anonfun$1.apply(PaperReader.scala:51)
org.clulab.reach.PaperReader$$anonfun$1.apply(PaperReader.scala:51)
ai.lum.nxmlreader.NXMLPreprocessor.transform(NXMLPreprocessor.scala:23)
ai.lum.nxmlreader.NXMLPreprocessor$$anonfun$1.apply(NXMLPreprocessor.scala:76)
ai.lum.nxmlreader.NXMLPreprocessor$$anonfun$1.apply(NXMLPreprocessor.scala:76)
scala.collection.TraversableLike$$anonfun$flatMap$1.apply(TraversableLike.scala:241)
scala.collection.TraversableLike$$anonfun$flatMap$1.apply(TraversableLike.scala:241)
scala.collection.immutable.List.foreach(List.scala:381)
scala.collection.TraversableLike$class.flatMap(TraversableLike.scala:241)
scala.collection.immutable.List.flatMap(List.scala:344)
ai.lum.nxmlreader.NXMLPreprocessor.transformChildren(NXMLPreprocessor.scala:76)
ai.lum.nxmlreader.NXMLPreprocessor.transform(NXMLPreprocessor.scala:31)
ai.lum.nxmlreader.NXMLPreprocessor$$anonfun$1.apply(NXMLPreprocessor.scala:76)
ai.lum.nxmlreader.NXMLPreprocessor$$anonfun$1.apply(NXMLPreprocessor.scala:76)
scala.collection.TraversableLike$$anonfun$flatMap$1.apply(TraversableLike.scala:241)
scala.collection.TraversableLike$$anonfun$flatMap$1.apply(TraversableLike.scala:241)
scala.collection.immutable.List.foreach(List.scala:381)
scala.collection.TraversableLike$class.flatMap(TraversableLike.scala:241)
scala.collection.immutable.List.flatMap(List.scala:344)
ai.lum.nxmlreader.NXMLPreprocessor.transformChildren(NXMLPreprocessor.scala:76)
ai.lum.nxmlreader.NXMLPreprocessor.transform(NXMLPreprocessor.scala:68)
ai.lum.nxmlreader.NXMLPreprocessor$$anonfun$1.apply(NXMLPreprocessor.scala:76)
ai.lum.nxmlreader.NXMLPreprocessor$$anonfun$1.apply(NXMLPreprocessor.scala:76)
scala.collection.TraversableLike$$anonfun$flatMap$1.apply(TraversableLike.scala:241)
scala.collection.TraversableLike$$anonfun$flatMap$1.apply(TraversableLike.scala:241)
scala.collection.immutable.List.foreach(List.scala:381)
scala.collection.TraversableLike$class.flatMap(TraversableLike.scala:241)
scala.collection.immutable.List.flatMap(List.scala:344)
ai.lum.nxmlreader.NXMLPreprocessor.transformChildren(NXMLPreprocessor.scala:76)
ai.lum.nxmlreader.NXMLPreprocessor.transform(NXMLPreprocessor.scala:68)
ai.lum.nxmlreader.NXMLPreprocessor$$anonfun$1.apply(NXMLPreprocessor.scala:76)
ai.lum.nxmlreader.NXMLPreprocessor$$anonfun$1.apply(NXMLPreprocessor.scala:76)
scala.collection.TraversableLike$$anonfun$flatMap$1.apply(TraversableLike.scala:241)
scala.collection.TraversableLike$$anonfun$flatMap$1.apply(TraversableLike.scala:241)
scala.collection.immutable.List.foreach(List.scala:381)
scala.collection.TraversableLike$class.flatMap(TraversableLike.scala:241)
scala.collection.immutable.List.flatMap(List.scala:344)
ai.lum.nxmlreader.NXMLPreprocessor.transformChildren(NXMLPreprocessor.scala:76)
ai.lum.nxmlreader.NXMLPreprocessor.transform(NXMLPreprocessor.scala:68)
ai.lum.nxmlreader.NXMLPreprocessor$$anonfun$1.apply(NXMLPreprocessor.scala:76)
ai.lum.nxmlreader.NXMLPreprocessor$$anonfun$1.apply(NXMLPreprocessor.scala:76)
scala.collection.TraversableLike$$anonfun$flatMap$1.apply(TraversableLike.scala:241)
scala.collection.TraversableLike$$anonfun$flatMap$1.apply(TraversableLike.scala:241)
scala.collection.immutable.List.foreach(List.scala:381)
scala.collection.TraversableLike$class.flatMap(TraversableLike.scala:241)
scala.collection.immutable.List.flatMap(List.scala:344)
ai.lum.nxmlreader.NXMLPreprocessor.transformChildren(NXMLPreprocessor.scala:76)
ai.lum.nxmlreader.NXMLPreprocessor.transform(NXMLPreprocessor.scala:68)
scala.xml.transform.BasicTransformer.apply(BasicTransformer.scala:55)
ai.lum.nxmlreader.NxmlDocument.mkStandoff(NxmlDocument.scala:97)
ai.lum.nxmlreader.NxmlDocument.<init>(NxmlDocument.scala:112)
ai.lum.nxmlreader.NxmlReader.read(NxmlReader.scala:17)
org.clulab.reach.PaperReader$.getEntryFromPaper(PaperReader.scala:145)
org.clulab.reach.ReachCLI.processPaper(ReachCLI.scala:132)
org.clulab.reach.ReachCLI$$anonfun$4.apply(ReachCLI.scala:87)
org.clulab.reach.ReachCLI$$anonfun$4.apply(ReachCLI.scala:81)
scala.collection.parallel.AugmentedIterableIterator$class.map2combiner(RemainsIterator.scala:115)
scala.collection.parallel.immutable.ParVector$ParVectorIterator.map2combiner(ParVector.scala:62)
scala.collection.parallel.ParIterableLike$Map.leaf(ParIterableLike.scala:1054)
scala.collection.parallel.Task$$anonfun$tryLeaf$1.apply$mcV$sp(Tasks.scala:49)
scala.collection.parallel.Task$$anonfun$tryLeaf$1.apply(Tasks.scala:48)
scala.collection.parallel.Task$$anonfun$tryLeaf$1.apply(Tasks.scala:48)
scala.collection.parallel.Task$class.tryLeaf(Tasks.scala:51)
scala.collection.parallel.ParIterableLike$Map.tryLeaf(ParIterableLike.scala:1051)
scala.collection.parallel.AdaptiveWorkStealingTasks$WrappedTask$class.internal(Tasks.scala:159)
scala.collection.parallel.AdaptiveWorkStealingForkJoinTasks$WrappedTask.internal(Tasks.scala:443)
scala.collection.parallel.AdaptiveWorkStealingTasks$WrappedTask$class.compute(Tasks.scala:149)
scala.collection.parallel.AdaptiveWorkStealingForkJoinTasks$WrappedTask.compute(Tasks.scala:443)
scala.concurrent.forkjoin.RecursiveAction.exec(RecursiveAction.java:160)
scala.concurrent.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260)
scala.concurrent.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1339)
scala.concurrent.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979)
scala.concurrent.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107)

==========

[ERROR] [12/07/2017 08:37:36.897] [run-main-0] [akka.tcp://procServer@127.0.0.1:2552/user/procActorPool] swallowing exception during message send (akka.remote.RemoteTransportExceptionNoStackTrace: Attempted to send remote message but Remoting is not running.)
[ERROR] [12/07/2017 08:37:36.925] [run-main-0] [akka.tcp://procServer@127.0.0.1:2552/user/procActorPool] swallowing exception during message send (akka.remote.RemoteTransportExceptionNoStackTrace: Attempted to send remote message but Remoting is not running.)
[WARN] [12/07/2017 08:37:44.490] [New I/O boss #3] [NettyTransport(akka://procServer)] Remote connection to [null] failed with java.net.ConnectException: Connection refused: /127.0.0.1:41575
[WARN] [12/07/2017 08:37:44.491] [procServer-akka.remote.default-remote-dispatcher-14331] [akka.tcp://procServer@127.0.0.1:2552/system/endpointManager/reliableEndpointWriter-akka.tcp%3A%2F%2FprocClient%40127.0.0.1%3A41575-1] Association with remote system [akka.tcp://procClient@127.0.0.1:41575] has failed, address is now gated for [5000] ms. Reason: [Association failed with [akka.tcp://procClient@127.0.0.1:41575]] Caused by: [Connection refused: /127.0.0.1:41575]
[success] Total time: 159310 s, completed Dec 7, 2017 8:37:47 AM
dane@clara:/net/kate/storage/work/dane/code/reach$ [WARN] [12/07/2017 08:38:48.656] [New I/O boss #3] [NettyTransport(akka://procServer)] Remote connection to [null] failed with java.net.ConnectException: Connection refused: /127.0.0.1:41575
[WARN] [12/07/2017 08:38:48.657] [procServer-akka.remote.default-remote-dispatcher-14331] [akka.tcp://procServer@127.0.0.1:2552/system/endpointManager/reliableEndpointWriter-akka.tcp%3A%2F%2FprocClient%40127.0.0.1%3A41575-1] Association with remote system [akka.tcp://procClient@127.0.0.1:41575] has failed, address is now gated for [5000] ms. Reason: [Association failed with [akka.tcp://procClient@127.0.0.1:41575]] Caused by: [Connection refused: /127.0.0.1:41575]
hickst commented 6 years ago

Yuck. How many papers (out of total) have processed? Does this occur near the end of the papers? (do wc -l on output/restart.log to see how many successfully processed).

herongrove commented 6 years ago

The first time, it occurred after about 50k of 100k papers. The second time was about 80k, and then the third 87k.

hickst commented 6 years ago

OK, thanks. And how many papers failed in this manner each time?

herongrove commented 6 years ago

I didn't have the foresight to print the logs to files, but from what didn't get erased in my tmux window, it looks like more than 5.

hickst commented 6 years ago

These kinds of distributed problems are really hard to debug. I'm gonna, at least, need to see the log file (look for reach.log). It seems like there may be a uncaught error that happens very sporadically, then the system recovers and continues. Note, that after the original error, the remoting library imposes a 5-second ban on client connections, which could cause other secondary errors. If we can get the log file, we can see if all the errors are the same or not (and we can hope for more information).

hickst commented 6 years ago

Dane retrieved the log file and I notice that the very first error is a CMU-exporter error (i.e. not related to Akka) and that it seems likely (IMHO) to have been caused by a bad data structure. The log shows several other similar types of problems.

17:51:42.902 [ForkJoinPool-1-worker-943] ERROR org.clulab.reach.ReachCLI -
==========

 ¡¡¡ NxmlReader error !!!

paper: PMC1877819

error:
java.util.NoSuchElementException: next on empty iterator

stack trace:
scala.collection.Iterator$$anon$2.next(Iterator.scala:39)
scala.collection.Iterator$$anon$2.next(Iterator.scala:37)
scala.collection.IterableLike$class.head(IterableLike.scala:107)
scala.collection.AbstractIterable.head(Iterable.scala:54)
org.clulab.reach.export.cmu.CMUExporter.createMechanismType(CMUExporter.scala:25)
org.clulab.reach.export.cmu.CMUExporter$$anonfun$1.apply(CMUExporter.scala:106)
org.clulab.reach.export.cmu.CMUExporter$$anonfun$1.apply(CMUExporter.scala:96)
scala.collection.TraversableLike$$anonfun$map$1.apply(TraversableLike.scala:234)
scala.collection.TraversableLike$$anonfun$map$1.apply(TraversableLike.scala:234)
scala.collection.immutable.HashSet$HashSet1.foreach(HashSet.scala:316)
scala.collection.immutable.HashSet$HashTrieSet.foreach(HashSet.scala:972)
scala.collection.immutable.HashSet$HashTrieSet.foreach(HashSet.scala:972)
scala.collection.TraversableLike$class.map(TraversableLike.scala:234)
scala.collection.AbstractSet.scala$collection$SetLike$$super$map(Set.scala:47)
scala.collection.SetLike$class.map(SetLike.scala:92)
scala.collection.AbstractSet.map(Set.scala:47)
org.clulab.reach.export.cmu.CMUExporter.getRows(CMUExporter.scala:96)
org.clulab.reach.assembly.export.AssemblyExporter.rowsToString(AssemblyExporter.scala:209)
org.clulab.reach.export.cmu.CMUExporter$.tabularOutput(CMUExporter.scala:206)
org.clulab.reach.ReachCLI.outputMentions(ReachCLI.scala:226)
org.clulab.reach.ReachCLI$$anonfun$processPaper$1.apply(ReachCLI.scala:140)
org.clulab.reach.ReachCLI$$anonfun$processPaper$1.apply(ReachCLI.scala:140)
scala.collection.immutable.List.foreach(List.scala:381)
org.clulab.reach.ReachCLI.processPaper(ReachCLI.scala:140)
org.clulab.reach.ReachCLI$$anonfun$4.apply(ReachCLI.scala:87)
org.clulab.reach.ReachCLI$$anonfun$4.apply(ReachCLI.scala:81)
scala.collection.parallel.AugmentedIterableIterator$class.map2combiner(RemainsIterator.scala:115)
scala.collection.parallel.immutable.ParVector$ParVectorIterator.map2combiner(ParVector.scala:62)
scala.collection.parallel.ParIterableLike$Map.leaf(ParIterableLike.scala:1054)
scala.collection.parallel.Task$$anonfun$tryLeaf$1.apply$mcV$sp(Tasks.scala:49)
scala.collection.parallel.Task$$anonfun$tryLeaf$1.apply(Tasks.scala:48)
scala.collection.parallel.Task$$anonfun$tryLeaf$1.apply(Tasks.scala:48)
scala.collection.parallel.Task$class.tryLeaf(Tasks.scala:51)
scala.collection.parallel.ParIterableLike$Map.tryLeaf(ParIterableLike.scala:1051)
scala.collection.parallel.AdaptiveWorkStealingTasks$WrappedTask$class.internal(Tasks.scala:159)
scala.collection.parallel.AdaptiveWorkStealingForkJoinTasks$WrappedTask.internal(Tasks.scala:443)
scala.collection.parallel.AdaptiveWorkStealingTasks$WrappedTask$class.compute(Tasks.scala:149)
scala.collection.parallel.AdaptiveWorkStealingForkJoinTasks$WrappedTask.compute(Tasks.scala:443)
scala.concurrent.forkjoin.RecursiveAction.exec(RecursiveAction.java:160)
scala.concurrent.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260)
scala.concurrent.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1339)
scala.concurrent.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979)
scala.concurrent.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107)