prearchive error

[Reinhard Hameeteman]

I have a lot of sessions in the "Error" state and need some help to find out the cause of this.
I checked the directories of these sessions and they do contain dicom data, their xml is empty and their log files contain:

Error building session

I tried to rebuild one of those sessions, looked in the log files and found what is listed below.
So there is a ArrayIndexOutOfBoundsException followed by a NullPointerException. But I have no idea about the cause of this.

I don't know where to look further, so suggestions are much appreciated.

(using XNAT 1.6.4

/var/log/tomcat/localhost_access_log.2015-12-21.txt
127.0.0.1 - - [21/Dec/2015:09:28:54 +0100] "POST /xnat/REST/services/prearchive/rebuild?nocache=1450686444101&format=csv&XNAT_CSRF=441d54eb-3152-4518-a6f4-6d882acde1e0 HTTP/1.0" 200 418

xdat.log
2015-12-21 09:28:55,032 [org.springframework.jms.listener.DefaultMessageListenerContainer#0-4] ERROR org.nrg.xnat.archive.XNATSessionBuilder -
java.lang.ArrayIndexOutOfBoundsException

prearchive.log
2015-12-21 09:28:55,034 [org.springframework.jms.listener.DefaultMessageListenerContainer#0-4] ERROR org.nrg.xnat.helpers.prearchive.PrearcTableBuilder -
org.nrg.xnat.helpers.prearchive.PrearcDatabase$SyncFailedException: Error building session
        at org.nrg.xnat.helpers.prearchive.PrearcDatabase$12.extSync(PrearcDatabase.java:725)
        at org.nrg.xnat.helpers.prearchive.PrearcDatabase$12.extSync(PrearcDatabase.java:691)
        at org.nrg.xnat.helpers.prearchive.PrearcDatabase$LockAndSync.run(PrearcDatabase.java:1241)
        at org.nrg.xnat.helpers.prearchive.PrearcDatabase.buildSession(PrearcDatabase.java:691)
        at org.nrg.xnat.helpers.prearchive.SessionXmlRebuilderRequestListener.onSessionXmlRebuilderRequest(SessionXmlRebuilderRequestListener.java:41)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:606)
        at org.springframework.util.MethodInvoker.invoke(MethodInvoker.java:273)
        at org.springframework.jms.listener.adapter.MessageListenerAdapter.invokeListenerMethod(MessageListenerAdapter.java:463)
        at org.springframework.jms.listener.adapter.MessageListenerAdapter.onMessage(MessageListenerAdapter.java:355)
        at org.springframework.jms.listener.AbstractMessageListenerContainer.doInvokeListener(AbstractMessageListenerContainer.java:535)
        at org.springframework.jms.listener.AbstractMessageListenerContainer.invokeListener(AbstractMessageListenerContainer.java:495)
        at org.springframework.jms.listener.AbstractMessageListenerContainer.doExecuteListener(AbstractMessageListenerContainer.java:467)
        at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.doReceiveAndExecute(AbstractPollingMessageListenerContainer.java:325)
        at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.receiveAndExecute(AbstractPollingMessageListenerContainer.java:263)
        at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.invokeListener(DefaultMessageListenerContainer.java:1058)
        at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.executeOngoingLoop(DefaultMessageListenerContainer.java:1050)
        at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.run(DefaultMessageListenerContainer.java:947)
        at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.NullPointerException
        at sun.util.calendar.ZoneInfoFile.readZoneInfoFile(ZoneInfoFile.java:1075)
        at sun.util.calendar.ZoneInfoFile.createZoneInfo(ZoneInfoFile.java:629)
        at sun.util.calendar.ZoneInfoFile.getZoneInfo(ZoneInfoFile.java:599)
        at sun.util.calendar.ZoneInfo.getTimeZone(ZoneInfo.java:663)
        at java.util.TimeZone.getTimeZone(TimeZone.java:566)
        at java.util.TimeZone.getTimeZone(TimeZone.java:562)
        at org.nrg.ecat.xnat.PETSessionBuilder.setTimezone(PETSessionBuilder.java:165)
        at org.nrg.xnat.archive.XNATSessionBuilder.call(XNATSessionBuilder.java:240)
        at org.nrg.xnat.helpers.prearchive.PrearcDatabase$12.extSync(PrearcDatabase.java:718)
        ... 20 more
2015-12-21 09:28:55,073 [org.springframework.jms.listener.DefaultMessageListenerContainer#0-4] ERROR org.nrg.xnat.helpers.prearchive.SessionXmlRebuilderRequestListener -
org.nrg.xnat.helpers.prearchive.PrearcDatabase$SyncFailedException: Error building session
        at org.nrg.xnat.helpers.prearchive.PrearcDatabase$12.extSync(PrearcDatabase.java:725)
        at org.nrg.xnat.helpers.prearchive.PrearcDatabase$12.extSync(PrearcDatabase.java:691)
        at org.nrg.xnat.helpers.prearchive.PrearcDatabase$LockAndSync.run(PrearcDatabase.java:1241)
        at org.nrg.xnat.helpers.prearchive.PrearcDatabase.buildSession(PrearcDatabase.java:691)
        at org.nrg.xnat.helpers.prearchive.SessionXmlRebuilderRequestListener.onSessionXmlRebuilderRequest(SessionXmlRebuilderRequestListener.java:41)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:606)
        at org.springframework.util.MethodInvoker.invoke(MethodInvoker.java:273)
        at org.springframework.jms.listener.adapter.MessageListenerAdapter.invokeListenerMethod(MessageListenerAdapter.java:463)
        at org.springframework.jms.listener.adapter.MessageListenerAdapter.onMessage(MessageListenerAdapter.java:355)
        at org.springframework.jms.listener.AbstractMessageListenerContainer.doInvokeListener(AbstractMessageListenerContainer.java:535)
        at org.springframework.jms.listener.AbstractMessageListenerContainer.invokeListener(AbstractMessageListenerContainer.java:495)
        at org.springframework.jms.listener.AbstractMessageListenerContainer.doExecuteListener(AbstractMessageListenerContainer.java:467)
        at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.doReceiveAndExecute(AbstractPollingMessageListenerContainer.java:325)
        at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.receiveAndExecute(AbstractPollingMessageListenerContainer.java:263)
        at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.invokeListener(DefaultMessageListenerContainer.java:1058)
        at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.executeOngoingLoop(DefaultMessageListenerContainer.java:1050)
        at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.run(DefaultMessageListenerContainer.java:947)
        at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.NullPointerException
        at sun.util.calendar.ZoneInfoFile.readZoneInfoFile(ZoneInfoFile.java:1075)
        at sun.util.calendar.ZoneInfoFile.createZoneInfo(ZoneInfoFile.java:629)
        at sun.util.calendar.ZoneInfoFile.getZoneInfo(ZoneInfoFile.java:599)
        at sun.util.calendar.ZoneInfo.getTimeZone(ZoneInfo.java:663)
        at java.util.TimeZone.getTimeZone(TimeZone.java:566)
        at java.util.TimeZone.getTimeZone(TimeZone.java:562)
        at org.nrg.ecat.xnat.PETSessionBuilder.setTimezone(PETSessionBuilder.java:165)
        at org.nrg.xnat.archive.XNATSessionBuilder.call(XNATSessionBuilder.java:240)
        at org.nrg.xnat.helpers.prearchive.PrearcDatabase$12.extSync(PrearcDatabase.java:718)
        ... 20 more
2015-12-21 09:29:35,986 [org.springframework.scheduling.quartz.SchedulerFactoryBean#0_Worker-4] ERROR org.nrg.xnat.helpers.prearchive.SessionXMLRebuilderJob - Prearchive session locked for an abnormally large time within CACHE_DIR/prearc_locks/Unassigned/20151126_103941087/234147

[Herrick, Rick]

What is the modality of the data? The session rebuilder certainly seems to think it’s ECAT data, but this is actually a weird thing. The way that the session builder works is that it tries out each of the builder configurations that it has, starting with DICOM. If the DICOM build fails, it moves onto an ECAT/PET build. This gives the misleading error you’re getting. Basically it’s trying to get the timezone from the parameters submitted with the session, but there IS no timezone submitted with the session because it’s not an ECAT session (and actually even regular PET data is handled by the DICOMSessionBuilder because it is actually DICOM: the DICOM/PET split in the XNAT session builder code is a little misleading, since it’s really about ECAT, i.e. non-DICOM PET data). Once there’s no timezone, you get the null pointer exception when it’s trying to look the time zone up. This is actually fixed in 1.6.5 so that it will use the default timezone if no timezone parameter is specified.

There are three processing blocks there:

• DICOM
• ECAT
• Custom

After each processing block, the code checks whether the session XML was actually created. If so, it breaks out of the loop. If not, it goes onto the next build configuration. In most cases, the data is DICOM and the first build configuration succeeds in initializing the session XML and everything proceeds nicely after that. In this case, something’s going wrong building the DICOM session XML document and processing is falling through to the ECAT processing block.

The DICOM session build operation actually happens in the DICOMSessionBuilder class, which is part of the XNAT DICOM metadata translation library (dicom-xnat-1.6.4.jar). You can try bumping up the logging level to debug to see if that will give you any more information as to what’s happening internally there. If you can connect to the server code with a debugger, you can grab the source code for that in the file plugin-resources/repository/dcm/jars/dicom-xnat-mx-1.6.4-sources.jar. You can also clone the repo from https://bitbucket.org/nrg/dicom-xnat, but will need to update to the tag v1.6.0 (note NOT 1.6.4! https://bitbucket.org/nrg/dicom-xnat/commits/tag/v1.6.0).

-- 

Rick Herrick

Sr. Programmer/Analyst

Neuroinformatics Research Group

Washington University School of Medicine

(314) 362-1882

--
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 https://groups.google.com/group/xnat_discussion.
For more options, visit https://groups.google.com/d/optout.

 

---

The materials in this message are private and may contain Protected Healthcare Information or other information of a sensitive nature. 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.

[Reinhard Hameeteman]

All files are dicom MR images images (tag 0008.0060 is set to MR).
I am afraid I don't have any debugging experience in java
Any idea on why the session builder might think it is not dicom data?
Is there a specific tag that needs to be present?

[Herrick, Rick]

I have no idea why it might not think it’s DICOM data. Most likely there’s some error occurring inside the DICOMSessionBuilder processing that’s causing it to fail to generate the session XML. But it’s annoying that it’s not generating any messages that indicate exactly what has failed.

You can try to bump up the logging level for the DICOM processing classes and see if that yields any useful information. Look in the file WEB-INF/conf/log4j.properties and find this line:

log4j.category.org.nrg.dcm = WARN, dicom
log4j.additivity.org.nrg.dcm = false

Set WARN to DEBUG, then restart Tomcat. The file logs/dicom.log in your deployed web app should start getting a LOT of logging added to it. Run through building a session with that turned up and see if anything interesting gets logged when you get your rebuild failure.

[Reinhard Hameeteman]

I did the following:

vi /var/lib/tomcat/webapps/xnat/WEB-INF/conf/log4j.properties
changed the mention lines to the ones below

# DICOM services
log4j.category.org.nrg.dcm=DEBUG, dicom
log4j.additivity.org.nrg.dcm=false

(should the last line remain false ?)

service tomcat restart

Now my web interface didn't come up again, so I rebooted the system.

tail -f /var/lib/tomcat/webapps/xnat/logs/dicom.log

Logon to the xnat web interface
I selected one of the prearchive sessions that was in an Error state
Pressed rebuild

Nothing appeared in the dicom.log file and the session remained in the Error state.

I tried it with some other sessions, and saw the many of them now did a successful rebuild.
Except for a remaining 383 (of 1700) session that stay in Error.

[Reinhard Hameeteman]

This is no solution, but might give you an idea about the cause:

Doing multiple rebuilds (i.e. doing 4 round of selecting all subjects in ERROR state and issue a rebuild) resulted in a successful (re)build of all subjects. After the first round 383, after the second 33 and after the third 6 and after the fourth 0 subjects were in ERROR state.
The only odd thing I noticed in the dicom.log file was:

java.sql.SQLException: S1000 General error java.lang.NullPointerException in statement [SHUTDOWN IMMEDIATELY]
        at org.hsqldb.jdbc.Util.sqlException(Unknown Source)
        at org.hsqldb.jdbc.jdbcStatement.fetchResult(Unknown Source)
        at org.hsqldb.jdbc.jdbcStatement.executeUpdate(Unknown Source)
        at org.nrg.dcm.EnumeratedMetadataStore$2.close(EnumeratedMetadataStore.java:142)
        at org.nrg.dcm.EnumeratedMetadataStore.close(EnumeratedMetadataStore.java:373)
        at org.nrg.dcm.xnat.DICOMSessionBuilder.close(DICOMSessionBuilder.java:537)
        at org.nrg.xnat.archive.XNATSessionBuilder.call(XNATSessionBuilder.java:223)
        at org.nrg.xnat.helpers.prearchive.PrearcDatabase$12.extSync(PrearcDatabase.java:718)

        at org.nrg.xnat.helpers.prearchive.PrearcDatabase$12.extSync(PrearcDatabase.java:691)
        at org.nrg.xnat.helpers.prearchive.PrearcDatabase$LockAndSync.run(PrearcDatabase.java:1241)
        at org.nrg.xnat.helpers.prearchive.PrearcDatabase.buildSession(PrearcDatabase.java:691)
        at org.nrg.xnat.helpers.prearchive.SessionXmlRebuilderRequestListener.onSessionXmlRebuilderRequest(SessionXmlRebuilderRequestListener.java:41)

        at sun.reflect.GeneratedMethodAccessor125.invoke(Unknown Source)

        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:606)
        at org.springframework.util.MethodInvoker.invoke(MethodInvoker.java:273)
        at org.springframework.jms.listener.adapter.MessageListenerAdapter.invokeListenerMethod(MessageListenerAdapter.java:463)
        at org.springframework.jms.listener.adapter.MessageListenerAdapter.onMessage(MessageListenerAdapter.java:355)
        at org.springframework.jms.listener.AbstractMessageListenerContainer.doInvokeListener(AbstractMessageListenerContainer.java:535)
        at org.springframework.jms.listener.AbstractMessageListenerContainer.invokeListener(AbstractMessageListenerContainer.java:495)
        at org.springframework.jms.listener.AbstractMessageListenerContainer.doExecuteListener(AbstractMessageListenerContainer.java:467)
        at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.doReceiveAndExecute(AbstractPollingMessageListenerContainer.java:325)
        at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.receiveAndExecute(AbstractPollingMessageListenerContainer.java:263)
        at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.invokeListener(DefaultMessageListenerContainer.java:1058)
        at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.executeOngoingLoop(DefaultMessageListenerContainer.java:1050)
        at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.run(DefaultMessageListenerContainer.java:947)
        at java.lang.Thread.run(Thread.java:745)

But this occured only once.