SaveImages fails


#1

I have a pipeline that uses a series of SaveImages modules to save images of identified objects from upstream pipeline steps.

When the pipeline runs on our Linux cluster multiple job array tasks fail. Remember that in this scenario multiple CP processes are working on separate image sets till the entire image list is 'consumed’
Reviewing the failed task log I see errors like:

Version: 2015-05-06T14:54:12 Unknown rev. / 20150506145412
Plugin directory doesn't point to valid folder: /dlab/hcs/PHCHBS-I21881/cluster_runs/CPJENKINS/JCP_2015-05-06_16-52-00/plugins
Pipeline saved with CellProfiler version 20140124151645
Times reported are CPU times for each module, not wall-clock time
Wed May  6 16:55:00 2015: Image # 1177, module LoadData # 1: 2.11 sec
Wed May  6 16:55:02 2015: Image # 1177, module IdentifyPrimaryObjects # 2: 2.21 sec
Wed May  6 16:55:04 2015: Image # 1177, module MeasureObjectIntensity # 3: 0.26 sec
Wed May  6 16:55:05 2015: Image # 1177, module FilterObjects # 4: 0.22 sec
Wed May  6 16:55:05 2015: Image # 1177, module FilterObjects # 5: 0.22 sec
Wed May  6 16:55:05 2015: Image # 1177, module FilterObjects # 6: 0.21 sec
Wed May  6 16:55:05 2015: Image # 1177, module FilterObjects # 7: 0.08 sec
Wed May  6 16:55:06 2015: Image # 1177, module FilterObjects # 8: 0.11 sec
Wed May  6 16:55:06 2015: Image # 1177, module SaveImages # 9: 1.76 sec
Wed May  6 16:55:09 2015: Image # 1177, module SaveImages # 10: 1.01 sec
Wed May  6 16:55:11 2015: Image # 1177, module SaveImages # 11: 0.97 sec
Wed May  6 16:55:12 2015: Image # 1177, module SaveImages # 12: 0.97 sec
Wed May  6 16:55:13 2015: Image # 1177, module SaveImages # 13: 0.90 sec
Wed May  6 16:55:14 2015: Image # 1177, module SaveImages # 14: 0.89 sec
Wed May  6 16:55:15 2015: Image # 1177, module ExportToSpreadsheet # 15: 0.00 sec
Wed May  6 16:55:15 2015: Image # 1178, module LoadData # 1: 0.31 sec
Wed May  6 16:55:16 2015: Image # 1178, module IdentifyPrimaryObjects # 2: 2.43 sec
Wed May  6 16:55:18 2015: Image # 1178, module MeasureObjectIntensity # 3: 0.19 sec
Wed May  6 16:55:18 2015: Image # 1178, module FilterObjects # 4: 0.16 sec
Wed May  6 16:55:19 2015: Image # 1178, module FilterObjects # 5: 0.16 sec
Wed May  6 16:55:19 2015: Image # 1178, module FilterObjects # 6: 0.06 sec
Wed May  6 16:55:19 2015: Image # 1178, module FilterObjects # 7: 0.12 sec
Wed May  6 16:55:19 2015: Image # 1178, module FilterObjects # 8: 0.08 sec
Wed May  6 16:55:19 2015: Image # 1178, module SaveImages # 9: 1.14 sec
Wed May  6 16:55:20 2015: Image # 1178, module SaveImages # 10: 0.98 sec
Wed May  6 16:55:21 2015: Image # 1178, module SaveImages # 11: 0.95 sec
Wed May  6 16:55:22 2015: Image # 1178, module SaveImages # 12: 1.04 sec
Wed May  6 16:55:23 2015: Image # 1178, module SaveImages # 13: 0.94 sec
Wed May  6 16:55:25 2015: Image # 1178, module SaveImages # 14: 0.85 sec
Wed May  6 16:55:25 2015: Image # 1178, module ExportToSpreadsheet # 15: 0.00 sec
Wed May  6 16:55:26 2015: Image # 1179, module LoadData # 1: 0.30 sec
Wed May  6 16:55:26 2015: Image # 1179, module IdentifyPrimaryObjects # 2: 2.45 sec
Wed May  6 16:55:29 2015: Image # 1179, module MeasureObjectIntensity # 3: 0.23 sec
Wed May  6 16:55:29 2015: Image # 1179, module FilterObjects # 4: 0.15 sec
Wed May  6 16:55:29 2015: Image # 1179, module FilterObjects # 5: 0.14 sec
Wed May  6 16:55:30 2015: Image # 1179, module FilterObjects # 6: 0.14 sec
Wed May  6 16:55:30 2015: Image # 1179, module FilterObjects # 7: 0.06 sec
Wed May  6 16:55:30 2015: Image # 1179, module FilterObjects # 8: 0.05 sec
Wed May  6 16:55:30 2015: Image # 1179, module SaveImages # 9: 0.98 sec
Wed May  6 16:55:31 2015: Image # 1179, module SaveImages # 10: 0.85 sec
Wed May  6 16:55:32 2015: Image # 1179, module SaveImages # 11: 0.84 sec
Wed May  6 16:55:34 2015: Image # 1179, module SaveImages # 12: 0.95 sec
Wed May  6 16:55:34 2015: Image # 1179, module SaveImages # 13: 0.88 sec
Wed May  6 16:55:35 2015: Image # 1179, module SaveImages # 14: 0.93 sec
Wed May  6 16:55:37 2015: Image # 1179, module ExportToSpreadsheet # 15: 0.00 sec
Wed May  6 16:55:37 2015: Image # 1180, module LoadData # 1: 0.34 sec
Wed May  6 16:55:37 2015: Image # 1180, module IdentifyPrimaryObjects # 2: 2.41 sec
Wed May  6 16:55:40 2015: Image # 1180, module MeasureObjectIntensity # 3: 0.21 sec
Wed May  6 16:55:40 2015: Image # 1180, module FilterObjects # 4: 0.23 sec
Wed May  6 16:55:40 2015: Image # 1180, module FilterObjects # 5: 0.30 sec
Wed May  6 16:55:40 2015: Image # 1180, module FilterObjects # 6: 0.21 sec
Wed May  6 16:55:41 2015: Image # 1180, module FilterObjects # 7: 0.07 sec
Wed May  6 16:55:41 2015: Image # 1180, module FilterObjects # 8: 0.09 sec
Wed May  6 16:55:41 2015: Image # 1180, module SaveImages # 9: 0.97 sec
Wed May  6 16:55:42 2015: Image # 1180, module SaveImages # 10: 0.89 sec
Wed May  6 16:55:43 2015: Image # 1180, module SaveImages # 11: 0.89 sec
Wed May  6 16:55:44 2015: Image # 1180, module SaveImages # 12: 0.91 sec
Wed May  6 16:55:45 2015: Image # 1180, module SaveImages # 13: 0.95 sec
Wed May  6 16:55:46 2015: Image # 1180, module SaveImages # 14: 0.87 sec
Wed May  6 16:55:48 2015: Image # 1180, module ExportToSpreadsheet # 15: 0.00 sec
Wed May  6 16:55:48 2015: Image # 1181, module LoadData # 1: 0.28 sec
Wed May  6 16:55:49 2015: Image # 1181, module IdentifyPrimaryObjects # 2: 2.22 sec
Wed May  6 16:55:51 2015: Image # 1181, module MeasureObjectIntensity # 3: 0.20 sec
Wed May  6 16:55:51 2015: Image # 1181, module FilterObjects # 4: 0.16 sec
Wed May  6 16:55:51 2015: Image # 1181, module FilterObjects # 5: 0.18 sec
Wed May  6 16:55:52 2015: Image # 1181, module FilterObjects # 6: 0.16 sec
Wed May  6 16:55:52 2015: Image # 1181, module FilterObjects # 7: 0.21 sec
Wed May  6 16:55:52 2015: Image # 1181, module FilterObjects # 8: 0.08 sec
Wed May  6 16:55:52 2015: Image # 1181, module SaveImages # 9: 0.93 sec
Exception in thread "Thread-0" org.mozilla.javascript.WrappedException: Wrapped java.lang.IllegalArgumentException (<java-python-bridge>#10)
	at org.mozilla.javascript.Context.throwAsScriptRuntimeEx(Context.java:1754)
	at org.mozilla.javascript.MemberBox.invoke(MemberBox.java:148)
	at org.mozilla.javascript.NativeJavaMethod.call(NativeJavaMethod.java:225)
	at org.mozilla.javascript.optimizer.OptRuntime.call2(OptRuntime.java:42)
	at org.mozilla.javascript.gen._java_python_bridge__31._c_script_0(<java-python-bridge>:10)
	at org.mozilla.javascript.gen._java_python_bridge__31.call(<java-python-bridge>)
	at org.mozilla.javascript.ContextFactory.doTopCall(ContextFactory.java:394)
	at org.mozilla.javascript.ScriptRuntime.doTopCall(ScriptRuntime.java:3091)
	at org.mozilla.javascript.gen._java_python_bridge__31.call(<java-python-bridge>)
	at org.mozilla.javascript.gen._java_python_bridge__31.exec(<java-python-bridge>)
	at org.mozilla.javascript.Context.evaluateString(Context.java:1079)
Caused by: java.lang.IllegalArgumentException
	at java.nio.Buffer.limit(Buffer.java:249)
	at ome.scifio.io.NIOFileHandle.buffer(NIOFileHandle.java:542)
	at ome.scifio.io.NIOFileHandle.writeSetup(NIOFileHandle.java:548)
	at ome.scifio.io.NIOFileHandle.write(NIOFileHandle.java:423)
	at ome.scifio.io.NIOFileHandle.write(NIOFileHandle.java:413)
	at ome.scifio.io.RandomAccessOutputStream.write(RandomAccessOutputStream.java:129)
	at loci.common.RandomAccessOutputStream.write(RandomAccessOutputStream.java:126)
	at javax.imageio.stream.FileCacheImageOutputStream.flushBefore(FileCacheImageOutputStream.java:236)
	at javax.imageio.stream.ImageInputStreamImpl.flush(ImageInputStreamImpl.java:811)
	at com.sun.imageio.plugins.jpeg.JPEGImageWriter.write(JPEGImageWriter.java:1027)
	at javax.imageio.ImageWriter.write(ImageWriter.java:598)
	at javax.imageio.ImageIO.write(ImageIO.java:1479)
	at javax.imageio.ImageIO.write(ImageIO.java:1565)
	at loci.formats.out.ImageIOWriter.savePlane(ImageIOWriter.java:116)
	at loci.formats.out.ImageIOWriter.saveBytes(ImageIOWriter.java:98)
	at loci.formats.FormatWriter.saveBytes(FormatWriter.java:136)
	at loci.formats.ImageWriter.saveBytes(ImageWriter.java:205)
	at sun.reflect.GeneratedMethodAccessor16.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at org.mozilla.javascript.MemberBox.invoke(MemberBox.java:126)
	... 9 more
Error detected during run of module SaveImages
Traceback (most recent call last):
  File "/usr/prog/cellprofiler/2.1.0/cellprofiler/pipeline.py", line 1796, in run_with_yield
    module.run(workspace)
  File "/usr/prog/cellprofiler/2.1.0/cellprofiler/modules/saveimages.py", line 465, in run
    should_save = self.run_objects(workspace)
  File "/usr/prog/cellprofiler/2.1.0/cellprofiler/modules/saveimages.py", line 570, in run_objects
    self.do_save_image(workspace, filename, cpixels, ome.PT_UINT8)
  File "/usr/prog/cellprofiler/2.1.0/cellprofiler/modules/saveimages.py", line 611, in do_save_image
    channel_names = channel_names)
  File "/usr/prog/cellprofiler/2.1.0/bioformats/formatwriter.py", line 114, in write_image
    buffer=pixel_buffer))
  File "/usr/prog/cellprofiler/2.1.0/cellprofiler/utilities/jutil.py", line 436, in run_script
    raise JavaException(call(e.throwable, "unwrap", "()Ljava/lang/Object;"))
JavaException
Wed May  6 16:55:53 2015: Image # 1181, module SaveImages # 10: 1.01 sec
Failed to stop Ilastik
Exiting the JVM monitor thread

You can see that some image sets are processed fine but at some point an image set throws a java.lang.IllegalArgumentException and aborts the job.

How do you interpret these errors? What do you think is the underlying cause of these errors?

Thanks and best regards
Ioannis


#2

Hi Ioannis,

This is an unusual bug! I filed a Github issue here (github.com/CellProfiler/CellPro … -101300757) and I am copying Lee’s response below:

I am looking at the Java stack trace. There’s a reference to ome.scifio.io.NIOFileHandle which indicates that the version of Bio-formats that’s being used is 5.0.0_rc2. NIOFileHandle has moved to io.scif.io,NIOFileHandle and there have been a few changes in the code block that made the bad call to buffer.limit().

It might be a good idea to remove all .jar files from the imagej/jars folder and rerun python external_dependencies.py with the latest code base to ensure that you are running Bio-formats 5.1.1. If the problem still persists, perhaps we can get a copy of the image set files and the pipeline in order to make a test case that demonstrates the problem and then submit the bug and possibly a fix to Bio-formats.

Can you try his suggestions and let us know (though this may be annoying to do on all your nodes - hopefully the configuration for the jar files, etc. is centralized for your setup).
Cheers,
David