Task #7477

Error with an algorithm deployed in the past which doesn't work anymore.

Added by Julien Barde over 2 years ago. Updated over 2 years ago.

Status:ClosedStart date:Mar 13, 2017
Priority:HighDue date:
Assignee:Julien Barde% Done:

50%

Category:Default
Sprint:WP08
Infrastructure:
Milestones:
Duration:

Description

I have this error:
Error in { : task 1 failed - "object 'out1' not found" (see attached logs)
When I try to run the main.R code (see attached file). The error seems to come from the ichthyop_wps.R file (see attached file).
This algorithm used to work (http://dataminer-bigdata.d4science.org/wps/WebProcessingService?request=Execute&service=WPS&Version=1.0.0&gcube-token=728a6f51-bd63-4425-8dc4-ab5bb9520ef4-843339462&lang=en-US&Identifier=org.gcube.dataanalysis.wps.statisticalmanager.synchserver.mappedclasses.transducerers.ICHTHYOP_MODEL_MULTIPLE_RUNS). You helped me to parallelize the loop where each iteration is supposed to be achieved through a WPS executer (using such calls http://dataminer-bigdata.d4science.org/wps/WebProcessingService?request=Execute&service=WPS&Version=1.0.0&gcube-token=728a6f51-bd63-4425-8dc4-ab5bb9520ef4-843339462&lang=en-US&Identifier=org.gcube.dataanalysis.wps.statisticalmanager.synchserver.mappedclasses.transducerers.ICHTHYOP_MODEL_ONE_BY_ONE&DataInputs=id_drifter=63908;starting_point_latitude=-13.548;starting_point_longitude=63.757;starting_point_starting_date=2007-01-15;trajectory_temporal_extent=193 day(s) 00 hour(s) 00 minute(s); )
I don't think I changed anything but I didn't use it since a while.
Let me know if you have any obvious solution...

main.R (9.65 KB) Julien Barde, Mar 13, 2017 12:50 PM

ichthyop_wps.R (5.02 KB) Julien Barde, Mar 13, 2017 12:52 PM

RLOGdecd324a-3acf-4554-a9c0-9549808eae84.txt Magnifier (14.9 KB) Julien Barde, Mar 13, 2017 12:57 PM

History

#1 Updated by Gianpaolo Coro over 2 years ago

  • Assignee changed from Gianpaolo Coro to Paolo Scarponi

I guess you are referring to the BFT VRE and the best is to reinstall the latest version of the algorithm we were provided with. Paolo could you please do it?

#2 Updated by Julien Barde over 2 years ago

These are Ichthyop algorithms set up in Stock Assessment VRE (cf identifiers in WPS URLs above).

#4 Updated by Paolo Scarponi over 2 years ago

The issue seems to be, as you suggested, at line 84 of ichthyop_wps.R. It looks like the variable "out1" does not contain the object that it is supposed to. Could you please debug the code locally and tell me what value has the variable "llout" at line 83 of the aforementioned file?

#5 Updated by Julien Barde over 2 years ago

llout is empty

see logs below

stop_condition_success<-grepl("Process successful",as.character(out))
No encoding supplied: defaulting to UTF-8.
stop_condition_fail<-grepl("Exception",as.character(out))
No encoding supplied: defaulting to UTF-8.
#GET THE STATUS LOCATION FROM THE ACCEPTANCE RESPONSE#
lout<-as.character(out)
No encoding supplied: defaulting to UTF-8.
print(lout)
[1] "Error (400) : this resource cannot process this request because it is malformed\nStacktrace:\norg.gcube.smartgears.handlers.application.request.RequestException: DataMiner cannot be called in scope /gcube/devsec/devVRE\n\tat org.gcube.smartgears.handlers.application.request.RequestError.toException(RequestError.java:110)\n\tat org.gcube.smartgears.handlers.application.request.RequestError.fire(RequestError.java:94)\n\tat org.gcube.smartgears.handlers.application.request.RequestValidator.validateScope(RequestValidator.java:95)\n\tat org.gcube.smartgears.handlers.application.request.RequestValidator.retreiveAndSetInfo(RequestValidator.java:179)\n\tat org.gcube.smartgears.handlers.application.request.RequestValidator.validateToken(RequestValidator.java:118)\n\tat org.gcube.smartgears.handlers.application.request.RequestValidator.handleRequest(RequestValidator.java:53)\n\tat org.gcube.smartgears.handlers.application.RequestHandler.onEvent(RequestHandler.java:56)\n\tat org.gcube.smartgears.handlers.application.RequestHandler.onEvent(RequestHandler.java:21)\n\tat org.gcube.smartgears.handlers.Pipeline.forward(Pipeline.java:65)\n\tat org.gcube.smartgears.managers.RequestManager.doFilter(RequestManager.java:78)\n\tat org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)\n\tat org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)\n\tat org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220)\n\tat org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122)\n\tat org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:501)\n\tat org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:171)\n\tat org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103)\n\tat org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:950)\n\tat org.apache.catalina.valves.RemoteIpValve.invoke(RemoteIpValve.java:683)\n\tat org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116)\n\tat org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:408)\n\tat org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1070)\n\tat org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:611)\n\tat org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:314)\n\tat java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)\n\tat java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)\n\tat org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)\n\tat java.lang.Thread.run(Thread.java:745)\n"

write(lout, file = "log.txt",append = TRUE, sep = " ")
statusLocation='statusLocation=\"'
endstatusLocation='">\n'
pos1 = regexpr(statusLocation, lout)
pos2 = regexpr(endstatusLocation, lout)
llout<-substr(lout, pos1+nchar(statusLocation), pos2-1)
print(llout)
[1] ""

#6 Updated by Paolo Scarponi over 2 years ago

Is this a problem you already encountered in some previous version of your code? If yes I'll proceed to reinstall the algorithm and it should fix the issue.

#7 Updated by Julien Barde over 2 years ago

no I never saw this issue. I adapted the wps code from a sample delivered by @gianpaolo.coro@isti.cnr.it who checked it and improved some parts. It was working properly. I don't really know what this part of code is doing (sending execute order to WPS server I guess) as I didn't write it.

#8 Updated by Paolo Scarponi over 2 years ago

Reading the last log more carefully I noticed that the issue can be related to something that goes wrong earlier in the process. In particular the "out" variable may be different from what it is expected. Could you please provide me with a complete log of the whole computation up until the error occurs?

#9 Updated by Julien Barde over 2 years ago

here is the result for the "out" variable:

out
Response [[http://dataminer-d-d4s.d4science.org/wps/WebProcessingService]]
Date: 2017-03-14 03:43
Status: 400
Content-Type:
Size: 2.73 kB

here is the log of the ichthyop_wps.R compilation:

print("So far so good 1")
[1] "So far so good 1"
options(digits.secs=3)
#TEMPLATE TO FULFILL TO INVOKE THE ALGORITHM#
templateFile="../configuration_files/TemplateIchtyopRequest.xml";
#CREATE NEW ON-THE-FLY VERSION OF THE TEMPLATE#
sentfile=paste("ichtyop_req_",Sys.time(),".xml",sep="")
sentfile<-gsub(":", "_", sentfile)
sentfile<-gsub(":", "_", sentfile)
sentfile<-gsub(" ", "_", sentfile)
filexml<-readChar(templateFile, file.info(templateFile)$size)
filexml<-gsub("\r\n", "\n", filexml)
#FULFILL THE TEMPLATE#
filexml<-gsub("#id_drifter#", id_drifter, filexml)
filexml<-gsub("#starting_point_latitude#", starting_point_latitude, filexml)
filexml<-gsub("#starting_point_longitude#", starting_point_longitude, filexml)
filexml<-gsub("#starting_point_starting_date#", starting_point_starting_date, filexml)
filexml<-gsub("#trajectory_temporal_extent#", trajectory_temporal_extent, filexml)
print("write XML for DescribeProcess query")
[1] "write XML for DescribeProcess query"
filehandle <- file(filexml)
write(filexml, file = sentfile,append = FALSE, sep = "")
close(filehandle)
#CALL WPS VIA POST#
out<-POST(url = wps_uri, config=c(authenticate(username, token, type = "basic")),body = upload_file(sentfile, type="text/xml"),encode = c("multipart"), handle = NULL, timeout(3600))
###ALTERNATIVE CALL FOR FAST TESTING###
#testURL<-"http://dataminer-d-d4s.d4science.org/wps/WebProcessingService?request=Execute&service=WPS&Version=1.0.0&gcube-token=4ccc2c35-60c9-4c9b-9800-616538d5d48b&lang=en-US&Identifier=org.gcube.dataanalysis.wps.statisticalmanager.synchserver.mappedclasses.modellers.FEED_FORWARD_ANN&storeExecuteResponse=true&lineage=true&status=true&DataInputs=TrainingDataSet=http://data-d.d4science.org/UndsT051bEZwbEpnRzM4WHQ3RWVlVDQ0eHNITWgzRXdHbWJQNStIS0N6Yz0;TrainingColumns=a|b;TargetColumn=t;LayersNeurons=1;Reference=1;LearningThreshold=0.01;MaxIterations=100;ModelName=neuralnet_;"
#out<-GET(url = testURL, config=c(authenticate(username, token, type = "basic")),handle = NULL, timeout(3600))
#out1<-out
#CHECK IF THE PROCESS HAS ALREADY FINISHED#
stop_condition_success<-grepl("Process successful",as.character(out))
No encoding supplied: defaulting to UTF-8.
stop_condition_fail<-grepl("Exception",as.character(out))
No encoding supplied: defaulting to UTF-8.
#GET THE STATUS LOCATION FROM THE ACCEPTANCE RESPONSE#
lout<-as.character(out)
No encoding supplied: defaulting to UTF-8.
print(lout)
[1] "Error (400) : this resource cannot process this request because it is malformed\nStacktrace:\norg.gcube.smartgears.handlers.application.request.RequestException: DataMiner cannot be called in scope /gcube/devsec/devVRE\n\tat org.gcube.smartgears.handlers.application.request.RequestError.toException(RequestError.java:110)\n\tat org.gcube.smartgears.handlers.application.request.RequestError.fire(RequestError.java:94)\n\tat org.gcube.smartgears.handlers.application.request.RequestValidator.validateScope(RequestValidator.java:95)\n\tat org.gcube.smartgears.handlers.application.request.RequestValidator.retreiveAndSetInfo(RequestValidator.java:179)\n\tat org.gcube.smartgears.handlers.application.request.RequestValidator.validateToken(RequestValidator.java:118)\n\tat org.gcube.smartgears.handlers.application.request.RequestValidator.handleRequest(RequestValidator.java:53)\n\tat org.gcube.smartgears.handlers.application.RequestHandler.onEvent(RequestHandler.java:56)\n\tat org.gcube.smartgears.handlers.application.RequestHandler.onEvent(RequestHandler.java:21)\n\tat org.gcube.smartgears.handlers.Pipeline.forward(Pipeline.java:65)\n\tat org.gcube.smartgears.managers.RequestManager.doFilter(RequestManager.java:78)\n\tat org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)\n\tat org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)\n\tat org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220)\n\tat org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122)\n\tat org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:501)\n\tat org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:171)\n\tat org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103)\n\tat org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:950)\n\tat org.apache.catalina.valves.RemoteIpValve.invoke(RemoteIpValve.java:683)\n\tat org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116)\n\tat org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:408)\n\tat org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1070)\n\tat org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:611)\n\tat org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:314)\n\tat java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)\n\tat java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)\n\tat org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)\n\tat java.lang.Thread.run(Thread.java:745)\n"
write(lout, file = "log.txt",append = TRUE, sep = " ")
statusLocation='statusLocation=\"'
endstatusLocation='">\n'
pos1 = regexpr(statusLocation, lout)
pos2 = regexpr(endstatusLocation, lout)
llout<-substr(lout, pos1+nchar(statusLocation), pos2-1)
print(llout)
[1] ""
count <- 0
#CHECK THE STATUS OF THE COMPUTATION UNTIL COMPLETION#
timeTestStart <- Sys.time()
while (!stop_condition_fail && !stop_condition_success){
+ message=paste("Checking every 10 seconds while processing is not over: ",count," seconds",sep="")
+ cat(message)
+ #CHECK THE STATUS URL#
+ out1<-GET(url = llout, config=c(authenticate(username, token, type = "basic")),handle = NULL, timeout(3600))
+ print(as.character(out1))
+ stop_condition_success<-grepl("ProcessSucceeded",as.character(out1))
+ stop_condition_fail<-grepl("Exception",as.character(out1))
+ if (!stop_condition_fail)
+ stop_condition_fail<-grepl("temporarily unavailable",as.character(out1))
+ #SLEEP FOR 10 SECONDS BEFORE THE NEXT CHECK#
+ Sys.sleep(10)
+ count <- count + 10
+ }
timeTestEnd <- Sys.time()
ExecutionTime <- timeTestEnd - timeTestStart
message=paste("Execution of the process took: ",ExecutionTime," seconds",sep="")
write(message, file = "log.txt",append = TRUE, sep = " ")
print(as.character(out1))
Error in print(as.character(out1)) : object 'out1' not found
write(as.character(out1), file = "log.txt",append = TRUE, sep = " ")
Error in cat(x, file = file, sep = c(rep.int(sep, ncolumns - 1), "\n"), :
object 'out1' not found
if (stop_condition_success){
+ print("get Response XML before error1")
+ #PARSE THE OUTPUT IN THE CASE OF SUCCESS
+ wps.output<-parseResponse(response=out1)
+ print("get Response XML before error2")
+ output<-as.data.frame(wps.output)
+ print("get Response XML before error3")
+ #View(output)
+ print("begin print output")
+ print("get Response XML after error")
+ #print(output)
+ print("URL: ")
+ #print(output$Value)
+ print("end print output")
+ }
#closeAllConnections()
print("begin return output to main code")
[1] "begin return output to main code"
return (output)
Error: object 'output' not found
print("end return output to main code")
[1] "end return output to main code"
}

#10 Updated by Julien Barde over 2 years ago

It seems to be a token issue. When I try this URL (similar as the one used in the code:
http://dataminer-d-d4s.d4science.org/wps/WebProcessingService?request=describeProcess&service=WPS&Version=1.0.0&gcube-token=3e437c61-725b-447f-be27-ffd501c97aeb&lang=en-US&Identifier=org.gcube.dataanalysis.wps.statisticalmanager.synchserver.mappedclasses.transducerers.CATCHES_BY_FLAGS

I have this error:

Error (400) : this resource cannot process this request because it is malformed
Stacktrace:
org.gcube.smartgears.handlers.application.request.RequestException: DataMiner invalid token : 3e437c61-725b-447f-be27-ffd501c97aeb
at org.gcube.smartgears.handlers.application.request.RequestError.toException(RequestError.java:110)
at org.gcube.smartgears.handlers.application.request.RequestError.fire(RequestError.java:94)
at org.gcube.smartgears.handlers.application.request.RequestValidator.retreiveAndSetInfo(RequestValidator.java:164)
at org.gcube.smartgears.handlers.application.request.RequestValidator.validateToken(RequestValidator.java:145)
at org.gcube.smartgears.handlers.application.request.RequestValidator.handleRequest(RequestValidator.java:53)
at org.gcube.smartgears.handlers.application.RequestHandler.onEvent(RequestHandler.java:56)
at org.gcube.smartgears.handlers.application.RequestHandler.onEvent(RequestHandler.java:21)
at org.gcube.smartgears.handlers.Pipeline.forward(Pipeline.java:65)
at org.gcube.smartgears.managers.RequestManager.doFilter(RequestManager.java:78)
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:171)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103)
at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:950)
at org.apache.catalina.valves.RemoteIpValve.invoke(RemoteIpValve.java:683)
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:1070)
at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:611)
at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:314)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:745)

#11 Updated by Julien Barde over 2 years ago

@gianpaolo.coro@isti.cnr.it @scarponi@isti.cnr.it
it's partially fixed.
For some reasons the deployed algorithms was not using the production environment. I updated the info to fit with production environment (as indicated below by the comments of Gianpaolo) and it works.

wps_uri = "http://dataminer-bigdata.d4science.org/wps/WebProcessingService" #Note by GP: change this to dataminer-bigdata.d4science.org/wps/WebProcessingService to go to production env.
username<-"julien.barde"
token<-"728a6f51-bd63-4425-8dc4-ab5bb9520ef4-843339462" #token for the devVRE Virtual Research Environment, Note by GP, use the StockAssessment Token to go to production env.
process_id<-"org.gcube.dataanalysis.wps.statisticalmanager.synchserver.mappedclasses.transducerers.ICHTHYOP_MODEL_ONE_BY_ONE"

#12 Updated by Julien Barde over 2 years ago

Before deploying a new version we need to fix this URL
zip_package_url = "http://data.d4science.org/cmZiaEkvQ21jWnNncGhJR2pFRTdYS3BmWG44bU93VW1HbWJQNStIS0N6Yz0"#"http://mdst-macroes.ird.fr/BlueBridge/Ichtyop/R/ichthyop.zip"

It's incredibly slow and I don't know where it is physically stored..I can copy it and put it somewhere else...
Do you want me to redeploy it ?

julien

#13 Updated by Paolo Scarponi over 2 years ago

Happy to hear that the problem is almost fixed! Yes,If you modified the "wps_url" to match the one required in production you can re-deploy the algorithm and I'll proceed to install the new version in the Stock Assessment VRE.

About the last link you posted, it's actually the concatenation of two links and they both work properly, and apparently they are both fast (at least for me).

#14 Updated by Paolo Scarponi over 2 years ago

  • % Done changed from 0 to 50
  • Assignee changed from Paolo Scarponi to Julien Barde
  • Status changed from New to Feedback

I update the ticket in order to ask for some feedback.

#15 Updated by Pasquale Pagano over 2 years ago

  • Status changed from Feedback to Closed
  • Tracker changed from Support to Task

I am going to close this activity since the issue seems solved. If not, please reopen it and provide feedback.

Also available in: Atom PDF