labkey.saveBatch fails when called from R transformation script

LabKey Support Forum (Inactive)
labkey.saveBatch fails when called from R transformation script Will Holtz  2016-11-29 12:51
Status: Closed
 
I have an assay with an R transformation script. This transformation script uses labkey.saveBatch() to create a new assay batch in a second assay before creating a batch in the original assay. (The first assay contains an FK to the second assay.)

I've used a module with such a configuration on Labkey v15.1-v16.1. I recently upgraded to v16.3, skipping v16.2. Now my transformation script never completes. I've stepped through the code, and it get stuck on a BufferedReader.readLine() call here:
      at org.labkey.api.reports.ExternalScriptEngine.runProcess(ExternalScriptEngine.java:296)
      at org.labkey.api.reports.ExternalScriptEngine.eval(ExternalScriptEngine.java:109)
      at org.labkey.api.reports.RScriptEngine.eval(RScriptEngine.java:90)
      at javax.script.AbstractScriptEngine.eval(AbstractScriptEngine.java:264)
      at org.labkey.api.study.assay.DefaultDataTransformer.transformAndValidate(DefaultDataTransformer.java:137)
      at org.labkey.api.study.assay.DefaultAssayRunCreator.transform(DefaultAssayRunCreator.java:102)
      at org.labkey.api.study.assay.DefaultAssayRunCreator.saveExperimentRun(DefaultAssayRunCreator.java:288)
      at org.labkey.api.study.assay.DefaultAssayRunCreator.saveExperimentRun(DefaultAssayRunCreator.java:135)
      at org.labkey.api.study.actions.UploadWizardAction$RunStepHandler.saveExperimentRun(UploadWizardAction.java:759)
      at org.labkey.api.study.actions.UploadWizardAction$RunStepHandler.handleSuccessfulPost(UploadWizardAction.java:734)
      at org.labkey.api.study.actions.UploadWizardAction$RunStepHandler.handleStep(UploadWizardAction.java:724)
      at org.labkey.api.study.actions.UploadWizardAction.getView(UploadWizardAction.java:173)
      at org.labkey.api.study.actions.UploadWizardAction.getView(UploadWizardAction.java:99)
      at org.labkey.api.action.SimpleViewAction.handleRequest(SimpleViewAction.java:80)
      at org.labkey.api.action.BaseViewAction.handleRequest(BaseViewAction.java:177)
      at org.labkey.api.action.SpringActionController.handleRequest(SpringActionController.java:415)
      at org.labkey.api.module.DefaultModule.dispatch(DefaultModule.java:1211)
      at org.labkey.api.view.ViewServlet._service(ViewServlet.java:190)
      at org.labkey.api.view.ViewServlet.service(ViewServlet.java:124)
      at javax.servlet.http.HttpServlet.service(HttpServlet.java:727)
      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303)
      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
      at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
      at org.labkey.api.data.TransactionFilter.doFilter(TransactionFilter.java:38)
      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
      at org.labkey.core.filters.SetCharacterEncodingFilter.doFilter(SetCharacterEncodingFilter.java:118)
      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
      at org.labkey.api.module.ModuleLoader.doFilter(ModuleLoader.java:1144)
      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
      at org.labkey.api.security.AuthFilter.doFilter(AuthFilter.java:206)
      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
      at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220)
      at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122)
      at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:501)
      at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:170)
      at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:98)
      at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:950)
      at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116)
      at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:408)
      at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1040)
      at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:607)
      at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:315)
      - locked <0x2c9a> (a org.apache.tomcat.util.net.SocketWrapper)
      at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
      at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
      at java.lang.Thread.run(Thread.java:745)

Attached is a minimal module for reproducing this behavior with the following steps:
1) activate module testtrans
2) create instance of assay TestTrans1
3) create instance of assay TestTrans2, the assay instance name must be 'TT2'
4) import a random text file into the TestTrans1 instance
5) Note that the import never completes

This breaks one of my modules that is in production, so if anyone has ideas on how to work around this, please let me know.

thanks,
-Will
 
 
Jon (LabKey DevOps) responded:  2016-11-30 10:43
Hi Will,

I was able to reproduce this problem successfully via your instructions in our Trunk build.

Do you recall when you eventually hit that BufferReader.readLine() stack? So far, my logs don't show that output after a good 10 minutes of waiting.

I'll also check and see if this problem occurs on 16.2 or not.

Regards,

Jon
 
Will Holtz responded:  2016-11-30 11:06
Hi Jon,

Thanks for taking a look at this. I hit the readLine() call within a few seconds. However, I have noticed that if I:

1) put a breakpoint on the readLine() call
2) import into TestTrans1
3) hit the breakpoint
4) continue program execution
5) reload the import page (as it is now stuck)
6) import into TestTrans1 again

This second import never makes it to the readLine() breakpoint. I haven't poked around with this second submission case to see where it is getting stuck. But I'm guessing that when you didn't see the readLine() call for 10 minutes, you had already performed one failed import. Try restarting tomcat and import again and see if you hit the readLine() call quickly.

-Will
 
Jon (LabKey DevOps) responded:  2016-11-30 22:00
Thanks Will,

I will give your instructions a try.

Interesting news is that I did try this on 16.2 and it worked without a problem, so there is something going on in 16.3 and in Trunk that has changed.

I'll run through your instructions and then have this reviewed by our developers to further investigate things.

Regards,

Jon
 
Jon (LabKey DevOps) responded:  2016-12-11 23:34
Hi Will,

Sorry for the late response. I did manage to reproduce the issue fully and also confirm the same issue in the code. I've created https://www.labkey.org/home/Developer/issues/issues-details.view?issueId=28711 to have this investigated further.

Thank you for your patience.

Regards,

Jon