I'm not sure what to do with this one since I don't have access to the machines needed to replicate the issue.

It is interesting that the dcmtk command line tools work differently than the ctk implementation since they should be based on the same underlying code. I guess one check would be to see if the command line tools corresponding to the version that slicer uses behave the same as the ones you tested (there might be some version skew).

If you have suggestions for replicating this for debugging let me know. Otherwise I guess I'll need to mark this as not fixable.

Don't know how to reproduce this one.

I see this issue quite often just retrieving a few studies. Also, I see similar error messages when I start a move operation before starting the storescp:

$ movescu -g -k 0008,0052="STUDY" -k 0010,0020="*" -k 0020,000D="1.3.12.2.1107.5.2.32.35078.30000012043015595639000000007" -aet MYAE -aem MYAE -aec PACSAE pacshostname.edu 104

W: DcmItem: Non-standard VR '12' (31\32) encountered while parsing element (2e31,2e33), assuming 2 byte length field
W: DcmItem: Non-standard VR '.2' (2e\32) encountered while parsing element (2e33,3231), assuming 2 byte length field
W: DcmItem: Non-standard VR '20' (32\30) encountered while parsing element (322e,3130), assuming 2 byte length field
W: DcmItem: Length of element (322e,3130) is odd
W: DcmItem: Non-standard VR '32' (33\32) encountered while parsing element (3736,3732), assuming 2 byte length field
W: DcmItem: Non-standard VR '1.' (31\2e) encountered while parsing element (3135,5c35), assuming 2 byte length field
W: DcmItem: Length of element (3135,5c35) is odd
W: DcmItem: Dataset not in ascending tag order, at element (3135,5c35)
W: DcmItem: Non-standard VR '02' (30\32) encountered while parsing element (3935,3230), assuming 2 byte length field
W: DcmItem: Length of element (3935,3230) is odd
E: DcmElement: Unknown Tag & Data (3935,3230) larger (13367) than remaining bytes (2780) in file, premature end of stream
W: DIMSE Warning: (MOLONEYPCCC,AIRCPACS): DIMSE receiveDataSetInMemory: dset->read() Failed (Invalid stream)
E: Move Request Failed: 0006:020d DIMSE Failed to receive message
E: Move SCU Failed: 0006:020d DIMSE Failed to receive message

Hi - I'm glad to look into this more but it's still not clear to me who to reproduce the issue.

Do you have a phantom image (or shareable volunteer scan) that can replicate the issue? For example, if you start the slicer listener and then use storescu can you replicate the same parser issues?

-Steve

After spending quite a bit of time on this I think it is related to having the ctkDICOM-Database on NFS and having high network/file system load. It is definitely not dependent to the data being retrieved (the same study that failed in the past can work fine later on).

If there is some additional tests or output I can generate, please let me know.

Thanks a lot for testing - Are there any other diagnostics or error checking that should be done on the ctk/slicer side to handle things more gracefully when this happens?

This is definitely a bug in CTK/Slicer not an external issue that just needs to be handled more gracefully.

I can reliably reproduce the issue by unpacking a large (~2GB) .tar.gz archive while performing the retrieve to the same NFS mount. The issue does not occur using plain DCMTK (even while unpacking a large archive).

The issue also does not occur if the CTK DICOM directory is on a local disk (even with high file system load). This makes me think that it is an issue with file locking on NFS.

Ahh - interesting - yes, having the database on NFS might cause the type of problems discussed here:

http://stackoverflow.com/questions/9907429/locking-sqlite-file-on-nfs-filesystem-possible

Are you planning to share the whole database across machines, or did you want to use the NFS disk in order to have more space? If the latter, it might make sense to make the dicom subdirectory a symbolic link to the remote disk space. If the goal is to have the database accessible across multiple machines I guess we need to think about the sqlite/nfs issue.

We just have NFS home directories for all of our Linux systems.

The issues discussed in that link seem to involve multiple processes accessing the same database. Does Slicer have multiple internal processes accessing the sqlite database?

Thinking this through, the only scenario I can come up with is that the incoming data isn't fully written by the time slicer tries to read it back in.

Here's what happens internally to slicer:

• there's an instance of storescp running as the listener. It is configured to write a message when a new instance is received.
• slicer listens for these messages and tries to do a database import of the newly received file.

It could be that the file is not fully flushed to the nfs server and the read operation fails. It's still not clear to me how to fix this.

To help diagnose, could you attach a more complete copy of the console output during a failed transaction? There might be additional clues in the ouptut.

I attached a complete log of the console output for a failed transaction, as well as a log for the same transaction that completed successfully.

Thanks for the logs - there are definitely clues, but unfortunately nothing that makes it clear what is going on.

It still looks like it's the storescp process that gets bad data but I don't see how this is related to the nfs file system or the sqlite database.

W: DIMSE Warning: (MOLONEYPCCC,AIRCPACS): DIMSE receiveDataSetInMemory: dset->read() Failed (Invalid stream)

Another way to test this would be to run storescp independently of slicer but do the query / retrieve operation in slicer. That is, don't start the slicer listener, but instead manually run "storescp <port>" in a temp directory and see if you get the same error messages.

Another way to narrow this down would be to try using the ctkDICOM application, which is in the bin directory of the slicer distribution to initiate the move to to a separate instance of storescp.

Another thing to try if possible would be to access your pacs with CGET instead of CMOVE (if supported).

HTH,
Steve

I did the test with running my own storescp and doing the query/retrieve through slicer. The issue doesn't come up, even with high NFS load.

Should I try with the ctkDICOM application?

Our PACS does not support CGET.

Given the fact Steve is travelling until Monday and that release 4.2-rc2 will be cut this weekend, re-targeted for 4.3.

After discussions with Marco at the ctk meeting, we have a hypothesis that the sqlite operation can take several seconds when the database exists on nfs. Because the receive does an insert it's possible that the storescp process gets tied up (maybe due to full stdout buffer) and fails to accept new transfers.

It's possible that this change fixes the issue:

http://viewvc.slicer.org/viewvc.cgi/Slicer4?view=revision&amp;revision=21978

If it's still possible to check it would be good to know if the issue is resolved.

The problem still exists in the latest nightly (May 9th).

Unfortunately this can't be fixed for the 4.3 release because we don't know the underlying cause. I'm removing the target version tag.