Issues after upgrading from 1.5.4 to 1.6.2.1

[Andrey Fedorov]

Hi,

I have upgraded my XNAT installation from 1.5.4 to 1.6.2.1, this post is essentially a follow-up on the earlier discussion: https://groups.google.com/forum/#!topic/xnat_discussion/fXRzjzDkMK4

The current problem I am having is related to data upload. I use DICOM upload. I observe the following issues in the upgraded installation:

1) AET has changed from the one I had in 1.5.4 to the default "XNAT"

2) after I sent the data, if I check the prearchive in the web interface as a regular user, it is empty. I do not see the directory corresponding to the project where I am sending the data in the XNAT/prearchive folder.

3) If I try to manually send it using storescu tool from DCMTK, I have error "OutOfResources". Note I have not changed any directories - it should be pointing to the same directories as in the 1.5.4 installation, so I don't see how this can be a permission problem.

4) if I check prearchive in the web interface as admin, I have the error (missing page?), as shown in the screenshot.

I am pretty sure I followed the upgrade instructions here: https://wiki.xnat.org/display/XNAT/How+to+Upgrade+XNAT#HowtoUpgradeXNAT-NewReleaseOldDatabase. Is there anything else I needed to do?

AF

[Andrey Fedorov]

Here is the specific error message from storescu:

[fedorov@gridftp-spl DICOM]$ storescu -v -aec XNAT 134.174.9.53 8104 *dcm

I: checking input files ...

I: Requesting Association

I: Association Accepted (Max Send PDV: 16372)

I: Sending file: PCAMRGBX-00067.MR.M2197_PRO_BD_Pelvis_w.10.100.20040429.115446.ko5db9.dcm

I: Converting transfer syntax: Little Endian Explicit -> Little Endian Explicit

I: Sending Store Request (MsgID 1, MR)

XMIT: .........

I: Received Store Response (Refused: OutOfResources)

I: Releasing Association

[Herrick, Rick]

Hey Andrey,

Are there any corresponding messages in any of the XNAT logs? These would be in the logs folder under your xnat web app directory. I think they would probably be in the dicom.log file, but I usually do something like this:

ls -l /var/lib/tomcat7/webapps/xnat/logs/*.log > /tmp/before.txt

<do whatever you're trying to fix>

ls -l /var/lib/tomcat7/webapps/xnat/logs/*.log > /tmp/after.txt

diff /tmp/before.txt /tmp/after.txt

The diff will show you which log files changed and you can target your search more easily.

Let me know if you find anything in there that might indicate the root cause of the out of resources error.

Rick Herrick

Sr. Programmer/Analyst

Neuroinformatics Research Group

Washington University School of Medicine

(314) 827-4250

---

From: xnat_di...@googlegroups.com [xnat_di...@googlegroups.com] on behalf of Andrey Fedorov [andrey....@gmail.com]
Sent: Friday, August 16, 2013 4:17 PM
To: xnat_di...@googlegroups.com
Subject: [XNAT Discussion] Re: Issues after upgrading from 1.5.4 to 1.6.2.1

--
You received this message because you are subscribed to the Google Groups "xnat_discussion" group.
To unsubscribe from this group and stop receiving emails from it, send an email to xnat_discussi...@googlegroups.com.
To post to this group, send email to xnat_di...@googlegroups.com.
Visit this group at http://groups.google.com/group/xnat_discussion.
For more options, visit https://groups.google.com/groups/opt_out.

[Andrey Fedorov]

here it is Rick.

2013-08-16 16:56:57,053 [pool-3-thread-4] ERROR
org.nrg.dcm.CStoreService - C-STORE operation failed
org.nrg.action.ServerException: org.postgresql.util.PSQLException:
ERROR: INSERT has more expressions than target columns
Position: 86
at org.nrg.xnat.archive.GradualDicomImporter.call(GradualDicomImporter.java:342)
at org.nrg.dcm.CStoreService.doCStore(CStoreService.java:232)
at org.nrg.dcm.CStoreService.cstore(CStoreService.java:195)
at org.dcm4che2.net.DicomServiceRegistry.process(DicomServiceRegistry.java:238)
at org.dcm4che2.net.NetworkApplicationEntity.perform(NetworkApplicationEntity.java:1158)
at org.dcm4che2.net.Association.onDimseRQ(Association.java:979)
at org.dcm4che2.net.PDUDecoder.decodeDIMSE(PDUDecoder.java:530)
at org.dcm4che2.net.Association.onPDataTF(Association.java:956)
at org.dcm4che2.net.State$Sta6.receivedPDataTF(State.java:239)
at org.dcm4che2.net.Association.receivedPDataTF(Association.java:952)
at org.dcm4che2.net.PDUDecoder.nextPDU(PDUDecoder.java:231)
at org.dcm4che2.net.Association.run(Association.java:851)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:722)
Caused by: org.postgresql.util.PSQLException: ERROR: INSERT has more
expressions than target columns
Position: 86
at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2102)
at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1835)
at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:257)
at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:500)
at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:388)
at org.postgresql.jdbc2.AbstractJdbc2Statement.executeUpdate(AbstractJdbc2Statement.java:334)
at org.apache.commons.dbcp.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:101)
at org.nrg.xnat.helpers.prearchive.PrearcDatabase$30$3.op(PrearcDatabase.java:1484)
at org.nrg.xnat.helpers.prearchive.PrearcDatabase$30$3.op(PrearcDatabase.java:1461)
at org.nrg.xnat.helpers.prearchive.PrearcDatabase$SessionOp.run(PrearcDatabase.java:1797)
at org.nrg.xnat.helpers.prearchive.PrearcDatabase$30.falseOp(PrearcDatabase.java:1461)
at org.nrg.xnat.helpers.prearchive.PrearcDatabase$PredicatedOp.run(PrearcDatabase.java:1029)
at org.nrg.xnat.helpers.prearchive.PrearcDatabase.eitherGetOrCreateSession(PrearcDatabase.java:1445)
at org.nrg.xnat.archive.GradualDicomImporter.call(GradualDicomImporter.java:334)
... 14 more

Also found this in prearchive.log:

2013-08-15 23:59:17,445
[org.springframework.scheduling.quartz.SchedulerFactoryBean#0_Worker-4]
ERROR org.nrg.xnat.helpers.prearchive.SessionXMLRebuilderJob -
org.postgresql.util.PSQLException: The column index is out of range:
14, number of columns: 13.
at org.postgresql.jdbc2.AbstractJdbc2ResultSet.checkColumnIndex(AbstractJdbc2ResultSet.java:2680)
at org.postgresql.jdbc2.AbstractJdbc2ResultSet.checkResultSet(AbstractJdbc2ResultSet.java:2697)
at org.postgresql.jdbc2.AbstractJdbc2ResultSet.getBoolean(AbstractJdbc2ResultSet.java:1889)
at org.apache.commons.dbcp.DelegatingResultSet.getBoolean(DelegatingResultSet.java:177)
at org.nrg.xnat.helpers.prearchive.DatabaseSession$ColType$5.getFromResult(DatabaseSession.java:384)
at org.nrg.xnat.helpers.prearchive.DatabaseSession.getFromResult(DatabaseSession.java:761)
at org.nrg.xnat.helpers.prearchive.DatabaseSession.fillSession(DatabaseSession.java:804)
at org.nrg.xnat.helpers.prearchive.PrearcDatabase$27.op(PrearcDatabase.java:1349)
at org.nrg.xnat.helpers.prearchive.PrearcDatabase$27.op(PrearcDatabase.java:1345)
at org.nrg.xnat.helpers.prearchive.PrearcDatabase$SessionOp.run(PrearcDatabase.java:1797)
at org.nrg.xnat.helpers.prearchive.PrearcDatabase.getAllSessions(PrearcDatabase.java:1345)
at org.nrg.xnat.helpers.prearchive.SessionXMLRebuilderJob.execute(SessionXMLRebuilderJob.java:46)
at org.nrg.schedule.DelegatingJobBean.executeInternal(DelegatingJobBean.java:55)
at org.springframework.scheduling.quartz.QuartzJobBean.execute(QuartzJobBean.java:86)
at org.quartz.core.JobRunShell.run(JobRunShell.java:216)
at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:549)
2013-08-15 23:59:17,445
[org.springframework.scheduling.quartz.SchedulerFactoryBean#0_Worker-4]
INFO org.nrg.xnat.helpers.prearchive.SessionXMLRebuilderJob - Built 0
of 0

> You received this message because you are subscribed to a topic in the
> Google Groups "xnat_discussion" group.
> To unsubscribe from this topic, visit
> https://groups.google.com/d/topic/xnat_discussion/PKzKTZFLYYg/unsubscribe.
> To unsubscribe from this group and all its topics, send an email to

[Herrick, Rick]

Ah! Try this:

* Shut down your Tomcat.
* Run the following SQL: DROP TABLE xdat_search.prearchive; You can do this via psql or pgAdmin or whatever (actually in pgAdmin, you can go to the table and drop it via a menu command).
* Restart Tomcat.

This is a known bug that somehow got through testing. We have an issue report for it but obviously it's not in 1.6.2.1. The fix is pretty simple and only needs to be the one time, though.

Rick Herrick
Sr. Programmer/Analyst
Neuroinformatics Research Group
Washington University School of Medicine
(314) 827-4250

________________________________________

From: xnat_di...@googlegroups.com [xnat_di...@googlegroups.com] on behalf of Andrey Fedorov [andrey....@gmail.com]

Sent: Friday, August 16, 2013 4:39 PM
To: xnat_di...@googlegroups.com
Subject: Re: [XNAT Discussion] Re: Issues after upgrading from 1.5.4 to 1.6.2.1

[Andrey Fedorov]

Thank you Rick. One step closer. I am now able to access prearchive
and initiate archival. One question that remains from the previous
list - how did my AET got reset back to default "XNAT"?

My next error is the failure of the AutoRun process. Here is what I
get in the email failure notification:

Pipeline:

/xnat/xnat/xnat/pipeline/catalog/xnat_tools/AutoRun.xml


Cause:

java.lang.IndexOutOfBoundsException: Index: 0, Size: 0 at
java.util.ArrayList.rangeCheck(ArrayList.java:604) at
java.util.ArrayList.get(ArrayList.java:382) at
org.nrg.pipeline.utils.ParameterUtils.resolveParameterValues(ParameterUtils.java:187)
at org.nrg.pipeline.utils.ParameterUtils.setParameterValues(ParameterUtils.java:171)
at org.nrg.pipeline.utils.PipelineUtils.resolveXPath(PipelineUtils.java:89)
at org.nrg.pipeline.manager.PipelineManager.launchPipeline(PipelineManager.java:210)
at org.nrg.pipeline.manager.PipelineManager.launchPipeline(PipelineManager.java:193)
at org.nrg.pipeline.client.XNATPipelineLauncher.launch(XNATPipelineLauncher.java:47)
at org.nrg.pipeline.client.XNATPipelineLauncher.main(XNATPipelineLauncher.java:265)

This is the last message of prearchive.log (it seems to keep updating
it with that last line over and over):

2013-08-16 19:17:10,758
[org.springframework.scheduling.quartz.SchedulerFactoryBean#0_Worker-8]

INFO org.nrg.xnat.helpers.prearchive.SessionXMLRebuilderJob - Built 0
of 0

Here's what looks like an error from velocity.log:

2013-08-16 19:10:42,299 [http-8080-3] ERROR velocity -
VMProxyArg.setObject() : Programmer error : I am a constant! No
setting! : dataType / "xnat:projectData"
2013-08-16 19:10:42,363 [http-8080-3] ERROR velocity - Left side
($om.getItem().getGenericSchemaElement().getPrimaryElements().indexOf("xnat:experimentData"))
of '!=' operation has null value. Operation not possible.
navigations//Breadcrumb.vm [line 177, column 102]
2013-08-16 19:10:44,093 [http-8080-4] ERROR velocity - #parse() error
: null argument
2013-08-16 19:10:44,164 [http-8080-4] ERROR velocity - Left side
($om.getItem().getGenericSchemaElement().getPrimaryElements().indexOf("xnat:experimentData"))
of '!=' operation has null value. Operation not possible.
navigations//Breadcrumb.vm [line 177, column 102]
2013-08-16 19:10:45,772 [http-8080-4] ERROR velocity - #parse() error
: null argument
2013-08-16 19:10:45,920 [http-8080-4] ERROR velocity - #parse() error
: null argument
2013-08-16 19:10:52,743 [http-8080-6] ERROR velocity - #parse() error
: null argument
2013-08-16 19:10:52,872 [http-8080-6] ERROR velocity - #parse() error
: null argument
2013-08-16 19:10:56,031 [http-8080-4] ERROR velocity - #parse() error
: null argument
2013-08-16 19:10:56,161 [http-8080-4] ERROR velocity - #parse() error
: null argument
2013-08-16 19:11:00,506 [http-8080-3] ERROR velocity - #parse() error
: null argument
2013-08-16 19:11:00,633 [http-8080-3] ERROR velocity - #parse() error
: null argument
2013-08-16 19:11:09,953 [http-8080-5] ERROR velocity - #parse() error
: null argument
2013-08-16 19:11:10,091 [http-8080-5] ERROR velocity - #parse() error
: null argument
2013-08-16 19:12:47,963 [http-8080-2] ERROR velocity - #parse() error
: null argument
2013-08-16 19:12:48,089 [http-8080-2] ERROR velocity - #parse() error
: null argument
2013-08-16 19:12:51,273 [http-8080-1] ERROR velocity - #parse() error
: null argument
2013-08-16 19:12:51,398 [http-8080-1] ERROR velocity - #parse() error
: null argument
2013-08-16 19:14:42,213 [http-8080-2] ERROR velocity - #parse() error
: null argument
2013-08-16 19:14:42,351 [http-8080-2] ERROR velocity - #parse() error
: null argument


Any ideas about this one?

[Simon Doran]

Andrey,

  I think I can shed a bit of light on at least the first of these problems. Kevin will no doubt correct anything I haven't quite got right below.

  Between 1.5.4 and 1.6, a lot of work was done to change the way that XNAT configuration is done and it now uses the Spring framework. Kevin has described in some detail what this means for the DICOM receiver here:
https://wiki.xnat.org/display/XNAT16/DICOM+identifier+configuration+and+customization

  The short answer to your problem is to go to your $TOMCAT_HOME/webapps/<YOUR_XNAT>/WEB-INF/conf directory and edit dicom-import-context.xml. In the section:

<bean name="dicomSCP" class="org.nrg.dcm.DicomSCP" factory-method="create">

    <constructor-arg ref="dicomSCPExecutor" />

    <constructor-arg value="8104" />

    <constructor-arg value="XNAT" />

    <constructor-arg ref="receivedFileUserProvider" />

    <constructor-arg ref="dicomObjectIdentifier" />

</bean>

just replace XNAT with the AETITLE you want and then restart Tomcat. I think this will do the trick. It would also be wise to modify the corresponding file in your $XNAT_HOME/projects/<YOUR_XNAT>, but I'm away from the office at the moment, so can't check exactly where it is located.

  The long answer is that the new system is much more flexible than previously and one of the neat things that you can do is to set up multiple AETITLES for the same XNAT server. Typically, you might configure each AETITLE to route the incoming DICOM studies to a different project.

  Our use case for this involves an XNAT server sitting behind the clinical firewall, which houses non-anonymised data. We are very keen to retain all metadata "uncorrupted" by any anonymisation. So we have one "fixed project" AETITLE to which all our scanners push completely unadulterated data. This means that the DICOM files themselves, in general, do not contain the information required for XNAT to determine the project, so our system is configured to send all files pushed to this AETITLE to a single "CLINICAL" project. At the same time, it also constructs a new XNAT subject directly from the DICOM patient name and a session name from various other DICOM elements.

  On the same server, we maintain a second AETITLE to which users send data to their own personal projects via DicomBrowser, This second route is more flexible, using the standard XNAT mechanisms described at
https://wiki.xnat.org/display/XNAT16/Basic+DICOM+object+identification
to specify the project, subject and session. However, this comes at the cost of having to get users to run a DicomEdit script to provide the routing information, or add it manually. (From a purist's point of view, doing this also "corrupts" the original DICOM files.)

  On your second question about pipeline, have you checked in the $XNAT_HOME/pipeline/logs directory? Each pipeline has a separate file, in which there is a good record of all the steps that the AutoRun pipeline is taking, and you might find more detail on the error there.

  Hope that's helpful.

Simon

[Andrey Fedorov]

Hi Simon,

Thank you for your explanation regarding the flipped AET. Now I know how to fix this.

I am still stuck with the archival issues I described in the earlier email. I looked in $XNAT_HOME/pipelines/logs, and the permissions for those directories were set to 700. There were no logs in that directory. I was not sure if this is correct, since perhaps tomcat user should be able to write the logs, so I changed all directories in $XNAT_HOME to g+rwx, and all individual files to g+rw, and restarted tomcat. This didn't help - I am still having the same issue as I described in the earlier post.

This is very unfortunate, since several projects here at BWH now rely on this XNAT instance. Looks like I will need to roll back the database and downgrade to 1.5.4, unless I get any help on this list in the next few days. It's a bad time for us to have non-functional XNAT. 

The upgrade instructions looked deceivingly simple...

AF

[Herrick, Rick]

Andrey,

 

It’s really hard to say what that error on pipeline execution might be. It’s clearly expecting something in an array and then getting an empty or null array, but in the standard auto-run pipeline that I know of that does that. Have you modified the auto-run pipeline at all? If necessary, maybe we can set up an online conference to walk through it and figure out what the issue is in the pipeline. There are a number of little things that might cause an issue, some within XNAT and some without, so it may be easier to get the whole picture before trying to diagnose the problem.

 

The message from the prearchive log is just what it says, an INFO message. It’s trying to build session XMLs for any incoming sessions in the prearchive. It didn’t find anything to do. You can turn those messages off by changing the log4j.properties file settings for the prearchive log, setting it to WARN, ERROR, or FATAL (probably WARN would be fine).

 

The velocity.log file is really kind of a problem for us. We get tons of messages in there, some legit, most not. The “most not” is primarily related to the fact that we have a very old version of Velocity that seems to get grumpier as each month goes by. But the snippet that you posted seems to have one legit issue or at least possibly legit, which is the “Programmer error” thing. Do you know which page you were accessing when that error occurred?

 

Rick Herrick

Sr. Programmer/Analyst

Neuroinformatics Research Group

Washington University School of Medicine

(314) 827-4250

 

---

The material in this message is private and may contain Protected Healthcare Information (PHI). If you are not the intended recipient, be advised that any unauthorized use, disclosure, copying or the taking of any action in reliance on the contents of this information is strictly prohibited. If you have received this email in error, please immediately notify the sender via telephone or return mail.

[Andrey Fedorov]

Rick,

I understand how difficult it is to debug remotely. It is very kind of
you to offer a remote session, and I would be happy to do that
together. I am available any time after 2pm today, if this works for
you, just let me know your availability. I would really like to be
using the current version of XNAT.

I did not modify anything in the default pipeline. I know it was
working find in 1.5.4, but now I don't even know if it's the same
pipeline now in 1.6.2. I recall that in 1.5.4 I had some issues with
generating thumbnails, and they were resolved with some help from this
list. I can try to find those posts if that would help. If you haven't
figured this out already - I am not an advanced XNAT user, I am just
trying to use out of the box functionality to cover the basic data
archival needs of our group.

I believe the errors in the velocity log are related to the pipeline
being run. I think they occurred while executing the pipeline. I do
not think they are related to a specific page.

Looking forward to your reply, let me know when we could have the
debug session.

AF

[Andrey Fedorov]

Following a quick debug session with Rick, the problem was identified
and resolved.

The pipeline location set by the old installation of XNAT was not
updated. This was identified by examining
$TOMCAT_HOME/webapps/xnat/logs/application.log. (Simon gave me a good
hint, but I didn't think to look at the XNAT webapp location!)

Auto run pipeline now works as expected. For those updating from an
older version - add the update of the pipelines location to the list
of things you need to do manually (under "admin" account,
Administer->Configuration->File system:Pipeline Installation
location), until this is fixed in the update script!

Rick -- thanks a lot!!

[Herrick, Rick]

Yeah, this is a good point that we missed on our migration tests. Generally, we have separate xnat_builder and pipeline locations that don't change, but each just gets upgraded. This is as opposed to having the pipeline folder located under the xnat_builder folder and installing the new version into a separate folder (this was the case with Andrey's pipeline issue). So just be aware of this. I've added it as a prominent note on the How to Upgrade XNAT documentation:

https://wiki.xnat.org/display/XNAT16/How+to+Upgrade+XNAT

Rick Herrick
Sr. Programmer/Analyst
Neuroinformatics Research Group
Washington University School of Medicine
(314) 827-4250