Bug: No feedback on failed Channel Offsets

[jamoore]

The Channel Offset util script failed (#5406). Insight didn't offer stdout or stderr, nor did it display a failure. (See screenshot).

[jburel]

related to #5406. If the error or info is returned, they will be displayed.
Ran script locally (working version) and the results are correctly displayed.

[wmoore]

I remember this problem a while back, but haven't seen it recently. Except once when I ran quite a long-running script. Can't remember if the script completed OK. Maybe I'll try to reproduce......

Nah - Insight still returned me a message etc even with a long-running script. Can you reproduce this Josh?

[jmoore]

Definitely reproduced:

• on gretzky as jmoore run "Channel Offsets" with a new dataset name
• stdout and stderr get uploaded (which I find in Processor-0.log)
• but the gui just says "finished", with no txt files.

[jmoore]

Same thing happened for "Combin images". Message says, "Combine images finished". No log viewable. But looking in Processor-0.log:

omero@gretzky:~/OMERO-CURRENT/var/log$ cat /OMERO/Files/Dir-004/4299 
Traceback (most recent call last):
  File "./script", line 552, in <module>
    runAsScript()
  File "./script", line 536, in runAsScript
    images = combineImages(session, parameterMap)
  File "./script", line 438, in combineImages
    newImg = makeSingleImage(services, parameterMap, imageIds, dataset, colourMap)
  File "./script", line 344, in makeSingleImage
    plane2D = getPlane(rawPixelStore, pixels, planeZ, 0, 0)
  File "./script", line 96, in getPlane
    plane2D = scriptUtil.downloadPlane(rawPixelStore, pixels, theZ, theC, theT)
  File "/home/omero/OMERO.server-4.3.0-DEV-8b719fb2/lib/python/omero/util/script_utils.py", line 408, in downloadPlane
    rawPlane = rawPixelsStore.getPlane(z, c, t);
  File "/home/omero/OMERO.server-4.3.0-DEV-8b719fb2/lib/python/omero_api_RawPixelsStore_ice.py", line 212, in getPlane
    return _M_omero.api.RawPixelsStore._op_getPlane.invoke(self, ((z, c, t), _ctx))
omero.ApiUsageException: exception ::omero::ApiUsageException
{
    serverStackTrace = ome.conditions.ApiUsageException: Z '1' greater than sizeZ '1'.
	at ome.services.RawPixelsBean.handleException(RawPixelsBean.java:659)
	at ome.services.RawPixelsBean.getPlane(RawPixelsBean.java:367)
	at sun.reflect.GeneratedMethodAccessor2176.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:307)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
	at ome.security.basic.EventHandler.invoke(EventHandler.java:150)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
	at ome.tools.hibernate.SessionHandler.doStateful(SessionHandler.java:182)
	at ome.tools.hibernate.SessionHandler.invoke(SessionHandler.java:166)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
	at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:108)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
	at ome.tools.hibernate.ProxyCleanupFilter$Interceptor.invoke(ProxyCleanupFilter.java:231)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
	at ome.services.util.ServiceHandler.invoke(ServiceHandler.java:111)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
	at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
	at $Proxy88.getPlane(Unknown Source)
	at sun.reflect.GeneratedMethodAccessor2176.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:307)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
	at ome.security.basic.BasicSecurityWiring.invoke(BasicSecurityWiring.java:83)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
	at ome.services.blitz.fire.AopContextInitializer.invoke(AopContextInitializer.java:43)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
	at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
	at $Proxy88.getPlane(Unknown Source)
	at sun.reflect.GeneratedMethodAccessor2179.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at ome.services.blitz.util.IceMethodInvoker.invoke(IceMethodInvoker.java:179)
	at ome.services.throttling.Callback.run(Callback.java:56)
	at ome.services.throttling.InThreadThrottlingStrategy.callInvokerOnRawArgs(InThreadThrottlingStrategy.java:56)
	at ome.services.blitz.impl.AbstractAmdServant.callInvokerOnRawArgs(AbstractAmdServant.java:136)
	at ome.services.blitz.impl.RawPixelsStoreI.getPlane_async(RawPixelsStoreI.java:101)
	at omero.api._RawPixelsStoreTie.getPlane_async(_RawPixelsStoreTie.java:134)
	at omero.api._RawPixelsStoreDisp.___getPlane(_RawPixelsStoreDisp.java:754)
	at omero.api._RawPixelsStoreDisp.__dispatch(_RawPixelsStoreDisp.java:1181)
	at IceInternal.Incoming.invoke(Incoming.java:159)
	at Ice.ConnectionI.invokeAll(ConnectionI.java:2037)
	at Ice.ConnectionI.message(ConnectionI.java:972)
	at IceInternal.ThreadPool.run(ThreadPool.java:577)
	at IceInternal.ThreadPool.access$100(ThreadPool.java:12)
	at IceInternal.ThreadPool$EventHandlerThread.run(ThreadPool.java:971)

    serverExceptionClass = ome.conditions.ApiUsageException
    message = Z '1' greater than sizeZ '1'.
}

[jmoore]

And again for a successful call to 'Images from ROIs'. Perhaps this is a problem with the callback since I'm outside the network?

omero@gretzky:~/OMERO-CURRENT/var/log$ cat /OMERO/Files/Dir-004/4303
{'Make_Image_Stack': True, 'IDs': [66L], 'Data_Type': 'Image', 'Container_Name': 'From_ROIs'}
rois
[(230, 68, 89, 61, 2, 3, 0, 4)]

Making Image stack from ROIs of Image: 66
physicalSize X, Y:  None, None
Image from ROIS on parent Image:
  Name: multi-channel-4D-series.ome.tif
  Image ID: 66
uint8
Script timer = 0.389401912689 secs

[wmoore]

When I use Insight from home to gretzky I get the same problem. The Message and stderr & stdout links are not displayed (although it's almost as if they flicker into view and are instantly lost), but the 'View' link to the new image does appear.

If I run the same script (Channel_Offsets.py) on gretzky using the command line, I do get the stdout and stderr displayed, so it seems it's not a network blocker.

[jburel]

Did you notice the problem with other scripts or only that one?

[jmoore]

From above, I saw it with all three Util scripts from TestingScenario? 21.3. I can try to confirm with others if you like.

[wmoore]

Testing various scripts running on mage from home:

• Channel_Offsets.py - Get 'View' for new image, but no 'Info' or Message.
• Combine_Images.py - Get 'View' for new image, but no 'Info' or Message.
• Images_From_ROIs.py (only returns a 'Message') - Ran 4 times: Only the first time were Message and 'info' shown. On other times, visible flicker of message etc
• Batch_Image_Export.py - Visible flicker and disappearance of message.

[wmoore]

Screen-shot after running scripts above.

[jmoore]

This is still happening. #5706 error was thrown, but no message showed up in the GUI. Elevating to critical.

[jmoore]

Just had no response from "Images_from_Rois" although the directory "From_ROIs" appeared (after a refresh). Several of the channel_offsets.py runs did show the results.

[jmoore]

Sorry, I meant #5716 above not #5706.

[jburel]

Seems like a problem in the call-back
Can we restart gretzky, it will be easier to test from home.

[jburel]

Ran 5 different scripts, one failure (expected) and the rest worked fine.
All controls were displayed.
I connect to gretzky from home. I will try again tomorrow morning after update

[jburel]

I have been running scripts but still no luck.
Can you still notice the problem?

[jmoore]

Latest insight (just fetched) against current gretzky, reproduced first invocation (see next screenshot). Nothing on stdout. Nothing in log:

 [thread: Initializer][class: org.openmicroscopy.shoola.env.rnd.PixelsServicesFactory] -
 Heap memory usage: max 530186240

43 ms since start (2011-06-03 21:05:39,602) ** INFO **
 [thread: Initializer][class: org.openmicroscopy.shoola.env.init.TaskBarInit] -
 Loaded L&F: com.apple.laf.AquaLookAndFeel

12411 ms since start (2011-06-03 21:05:51,970) ** INFO **
 [thread: Initializer][class: org.openmicroscopy.shoola.env.data.DataServicesFactory] -
 Server version: 4.3.0
Client version: Beta4.3-DEV
os_name: Mac OS X
os_arch: x86_64
java_version: 1.6.0_24
os_version: 10.6.6


13194 ms since start (2011-06-03 21:05:52,753) ** INFO **
 [thread: Initializer][class: org.openmicroscopy.shoola.env.data.login.LoginServiceImpl] -
 Logged onto OMERO at: gretzky.openmicroscopy.org.uk
User Name: Swedlow+Admin -- Password: ***

[jburel]

I ran several times. I connected to gretzky

run 1. {Image=pojos.ImageData (id=18815), Message=New Image created: CT-MONO2-12-lomb-an2.dcm_offsets, stdout=omero.model.OriginalFileI@48392b}
run 2. {Image=pojos.ImageData (id=18816), stdout=omero.model.OriginalFileI@68bfe0, Message=New Image created: CT-MONO2-12-lomb-an2.dcm_offsets}
run 3. {Image=pojos.ImageData (id=18817), stdout=omero.model.OriginalFileI@a498e3, Message=New Image created: CT-MONO2-12-lomb-an2.dcm_offsets_offsets}
run 4. {Image=pojos.ImageData (id=18818), stdout=omero.model.OriginalFileI@8de8ca, Message=New Image created: CT-MONO2-16-chest.dcm_offsets}
run 5. {Image=pojos.ImageData (id=18819), Message=New Image created: CT-MONO2-16-chest.dcm_offsets, stdout=omero.model.OriginalFileI@69e3d7}
run 6. {Image=pojos.ImageData (id=18820), Message=New Image created: CT-MONO2-16-chest.dcm_offsets, stdout=omero.model.OriginalFileI@aabf0a}
       {Image=pojos.ImageData (id=18820)}

run 6, the activity component is notified twice of a result. First one is the correct one.

[jburel <j.burel@…>]

(In [6ad9a74f5d1debbe1a0b2d30440435c034a1fff5/ome.git] on branch develop) Fix problem when handling results of script and delete call-backs (close #5408)

[jburel]

I think the issue is now fixed. 15 runs and did not notice the problem after the change.
Please re-open the ticket if necessary