AutoRun notifier fails - v1.6.3

64 views
Skip to first unread message

Jordi

unread,
Jul 7, 2014, 11:57:57 AM7/7/14
to xnat_di...@googlegroups.com
Hi all,

When I'm archiving image sessions with current XNAT version the last part of the AutoRun pipeline fails at notifying to the end user the archival of the session. The rest of pipeline seems to work properly (i.e. data is archived and snapshots are generated) and actually the email notification of the failure of the pipeline is indeed sent to user/admin. In addition, other pipelines of my own work nicely and notify their final status without problems.

One thing that looks strange to me is that when the pipeline tries to notify first its completion it has no TO parameter:

DEBUG main org.springframework.web.client.RestTemplate - Writing [{from=[pipe...@mydomain.com], cc=[pipe...@mydomain.com], subject=[XNAT update: dummy Archiving complete], text=[...]

Meanwhile when it crashed and notifies the error on the pipeline it does:

DEBUG main org.springframework.web.client.RestTemplate - Writing [{from=[pipe...@mydomain.com], to=[us...@mydomain.compipe...@mydomain.com], subject=[XNAT update: Processing failed for dummy], text=[...]

More complete pipeline log fragment:

INFO main org.nrg.pipeline.process.LocalProcessLauncher - Executing /xnat/pipeline/xnat-tools/XNATRestClient -host {MY_HOST} -remote "/data/archive/projects/test/resources/notifications/files/archival.lst" -user_session XXX -m GET > /xnat/data/cache/test//archival.lst
...
DEBUG main org.nrg.pipeline.xpath.XPathResolverSaxon - Expre ^/Pipeline/parameters/parameter[name='emaillistfileExists']/values/unique/text()='true'^ [true]
INFO main org.nrg.pipeline.utils.ConditionUtils - Condition: true
...
DEBUG main org.springframework.web.client.RestTemplate - Created POST request for "{MY_HOST}/data/services/mail/send"
DEBUG main org.springframework.web.client.RestTemplate - Setting request Accept header to [text/plain, */*]
DEBUG main org.springframework.web.client.RestTemplate - Writing [{from=[pipe...@mydomain.com], cc=[pipe...@mydomain.com], subject=[XNAT update: dummy Archiving complete], text=[...]
DEBUG main httpclient.wire.header - >> "POST /xnat/data/services/mail/send HTTP/1.1[\r][\n]"
DEBUG main httpclient.wire.header - >> "Accept: text/plain, */*[\r][\n]"
DEBUG main httpclient.wire.header - >> "Content-Type: application/x-www-form-urlencoded[\r][\n]"
DEBUG main httpclient.wire.header - >> "Content-Length: 1195[\r][\n]"
DEBUG main httpclient.wire.header - >> "Authorization: Basic XXX=[\r][\n]"
DEBUG main httpclient.wire.header - >> "User-Agent: Jakarta Commons-HttpClient/3.1[\r][\n]"
DEBUG main httpclient.wire.header - >> "Host: {MY_HOST}[\r][\n]"
DEBUG main httpclient.wire.header - >> "[\r][\n]"
DEBUG main httpclient.wire.content - >> "from=..."

DEBUG main httpclient.wire.header - << "HTTP/1.1 400 Bad Request[\r][\n]"
DEBUG main httpclient.wire.header - << "HTTP/1.1 400 Bad Request[\r][\n]"
DEBUG main httpclient.wire.header - << "Date: Mon, 07 Jul 2014 14:38:23 GMT[\r][\n]"
DEBUG main httpclient.wire.header - << "Server: Noelios-Restlet-Engine/1.1.6[\r][\n]"
DEBUG main httpclient.wire.header - << "Accept-Ranges: bytes[\r][\n]"
DEBUG main httpclient.wire.header - << "Content-Type: text/html;charset=ISO-8859-1[\r][\n]"
DEBUG main httpclient.wire.header - << "Content-Length: 345[\r][\n]"
DEBUG main httpclient.wire.header - << "Connection: close[\r][\n]"
DEBUG main httpclient.wire.header - << "[\r][\n]"
WARN main org.springframework.web.client.RestTemplate - POST request for "{MY_HOST}/data/services/mail/send" resulted in 400 (Bad Request); invoking error handler
ERROR main org.nrg.pipeline.utils.MailUtils - Message failed to send through REST service, retrying with direct SMTP.
org.springframework.web.client.HttpClientErrorException: 400 Bad Request
        at org.springframework.web.client.DefaultResponseErrorHandler.handleError(DefaultResponseErrorHandler.java:75)
        at org.springframework.web.client.RestTemplate.handleResponseError(RestTemplate.java:486)
        ...
DEBUG main org.nrg.pipeline.exception.PipelineEngineException - Personnel notification email could not be sent class java.lang.ArrayStoreExceptionnull
DEBUG main org.nrg.pipeline.exception.PipelineEngineException - java.lang.ArrayStoreException
        at java.lang.System.arraycopy(Native Method)
...
FATAL main org.nrg.pipeline.manager.ExecutionManager -  Execution of /xnat/pipeline/catalog/notifications/Notifier -user XXX -password XXX -from pipe...@mydomain.com -tolist /xnat/data/cache/test//archival.lst -cc pipe...@mydomain.com -subject XNAT update: dummy Archiving complete -body ...
...
DEBUG main org.nrg.pipeline.exception.PipelineEngineException - org.nrg.pipeline.exception.PipelineEngineException: Personnel notification email could not be sent class java.lang.ArrayStoreExceptionnull null
        at org.nrg.pipeline.process.PersonnelNotificationLauncher.launchProcess(PersonnelNotificationLauncher.java:217)

Restlet logs complain also about request syntax: 

2014-07-07 16:38:24,462 [http-8080-3] WARN  org.nrg.xnat.restlet.services.mail.MailRestlet - I was unable to properly parse an incoming request, check the logs for more information, returning: Bad Request (400) - The request could not be understood by the server due to malformed syntax

Any ideas of what's going on and/or how to solve it?

Thanks in advanced,
Jordi


Jordi

unread,
Jul 8, 2014, 5:30:42 AM7/8/14
to xnat_di...@googlegroups.com
Small update on that issue:

Kind of manually debugging the pipeline execution I have found out an interesting discovery, it is related with the 'Notifications Configuration' feature. If I add some email list and a notification resource file (archival.lst) is created and used by AutoRun pipeline it can't probably parse out the list of mailing addresses and then fails at notifying as I pointed out in my last post.

Removing the resource collection 'notifications', makes emaillistfileExists precondition to fail and notification is sent normally (as it is for other pipelines).

That reminds me that every time pipeline engine tries to execute xnat_tools (i.e. XNATRestClient) I receive the following warning which might be related:

log4j:ERROR setFile(null,true) call failed.
java.io.FileNotFoundException: xnat-rest-client.log (Permission denied)
        at java.io.FileOutputStream.open(Native Method)
 

cheers,
Jordi

On Monday, July 7, 2014 5:57:57 PM UTC+2, Jordi wrote:
Hi all,

When I'm archiving image sessions with current XNAT version the last part of the AutoRun pipeline fails at notifying to the end user the archival of the session. The rest of pipeline seems to work properly (i.e. data is archived and snapshots are generated) and actually the email notification of the failure of the pipeline is indeed sent to user/admin. In addition, other pipelines of my own work nicely and notify their final status without problems.

One thing that looks strange to me is that when the pipeline tries to notify first its completion it has no TO parameter:

DEBUG main org.springframework.web.client.RestTemplate - Writing [{from=[pipe...@mydomain.com], cc=[pipe...@mydomain.com], subject=[XNAT update: dummy Archiving complete], text=[...]

Meanwhile when it crashed and notifies the error on the pipeline it does:

DEBUG main org.springframework.web.client.RestTemplate - Writing [{from=[pipe...@mydomain.com], to=[us...@mydomain.compipeline...@mydomain.com], subject=[XNAT update: Processing failed for dummy], text=[...]
Reply all
Reply to author
Forward
0 new messages