View Issue Details

IDProjectCategoryView StatusLast Update
0001978Slicer4Module DICOMpublic2017-06-07 23:27
ReporterbmoloneyAssigned Topieper 
PrioritynormalSeveritymajorReproducibilitysometimes
Status resolvedResolutionfixed 
Product VersionSlicer 4.1.0 
Target VersionFixed in Version 
Summary0001978: Not all series retrieved for some studies
Description

While retrieving a study, sometimes not all series are retrieved. The series are often secondary capture, but the SOPClassUID is standard "MR Image Storage".

I see the following output to the console:

I: Received C-MOVE Response (Warning: SubOperationsCompleteOneOrMoreFailures)
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 (3730,352e), assuming 2 byte length field
W: DcmItem: Non-standard VR '10' (31\30) encountered while parsing element (3035,3133), assuming 2 byte length field
W: DcmItem: Length of element (3035,3133) is odd
W: DcmItem: Dataset not in ascending tag order, at element (3035,3133)
W: DcmItem: Non-standard VR '07' (30\37) encountered while parsing element (3330,3131), assuming 2 byte length field
W: DcmItem: Length of element (3330,3131) is odd
W: DcmItem: Dataset not in ascending tag order, at element (3330,3131)
W: DcmItem: Non-standard VR '05' (30\35) encountered while parsing element (3032,3231), assuming 2 byte length field
W: DcmItem: Dataset not in ascending tag order, at element (3032,3231)
W: DcmItem: Non-standard VR '07' (30\37) encountered while parsing element (3233,3835), assuming 2 byte length field
W: DcmItem: Dataset not in ascending tag order, at element (3233,3835)
W: DcmItem: Non-standard VR '.2' (2e\32) encountered while parsing element (3035,3837), assuming 2 byte length field
W: DcmItem: Dataset not in ascending tag order, at element (3035,3837)
W: DcmItem: Non-standard VR '31' (33\31) encountered while parsing element (3133,3334), assuming 2 byte length field
E: DcmElement: Unknown Tag & Data (3133,3334) larger (13880) than remaining bytes (48) in file, premature end of stream
W: DcmItem: Dataset not in ascending tag order, at element (3133,3334)
W: DIMSE Warning: (MOLONEYPCCC,AIRCPACS): DIMSE receiveDataSetInMemory: dset->read() Failed (Invalid stream)
E: Unable to receive dataset on presentation context 1: 0006:020d DIMSE Failed to receive message
E: Unable to receive C-MOVE dataset on presentation context 1: 0006:020d DIMSE Failed to receive message
MOVE responses report for study: 1.3.12.2.1107.5.2.32.35078.30000012043015595639000000007
1389 images transferred, and
0 images transferred with warning, and
1436 images transfers failed

Additional Information

I can successfully retrieve the same studies with basic DCMTK commands:

$ storescp 12345 &
$ 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

TagsNo tags attached.

Activities

pieper

pieper

2012-08-23 04:59

administrator   ~0005753

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.

pieper

pieper

2012-08-28 07:06

administrator   ~0005826

Don't know how to reproduce this one.

bmoloney

bmoloney

2012-08-28 11:26

reporter   ~0005839

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

pieper

pieper

2012-08-28 13:46

administrator   ~0005841

Last edited: 2012-08-28 13:47

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

bmoloney

bmoloney

2012-08-30 15:47

reporter   ~0005900

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.

pieper

pieper

2012-08-31 04:16

administrator   ~0005901

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?

bmoloney

bmoloney

2012-08-31 13:14

reporter   ~0005918

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.

pieper

pieper

2012-09-04 04:29

administrator   ~0005936

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.

bmoloney

bmoloney

2012-09-04 11:26

reporter   ~0005957

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?

pieper

pieper

2012-09-06 10:19

administrator   ~0005996

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.

2012-09-10 14:56

 

slicer_failed_retr.out.gz (51,661 bytes)

2012-09-10 14:56

 

slicer_success_retr.out.gz (305,442 bytes)
bmoloney

bmoloney

2012-09-10 14:58

reporter   ~0006026

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.

pieper

pieper

2012-09-13 05:42

administrator   ~0006049

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

bmoloney

bmoloney

2012-09-21 13:19

reporter   ~0006166

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.

jcfr

jcfr

2012-10-25 14:22

administrator   ~0006789

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

pieper

pieper

2012-12-12 01:33

administrator   ~0007486

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.

pieper

pieper

2013-05-09 12:16

administrator   ~0008602

It's possible that this change fixes the issue:

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

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

bmoloney

bmoloney

2013-05-10 13:25

reporter   ~0008615

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

pieper

pieper

2013-07-05 07:37

administrator   ~0008866

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.

Related Changesets

Slicer: 2145-support-for-installing-extension-from-file 9445cf5e

2013-05-09 16:15:14

pieper

Details Diff
BUG: avoid overtaxing the system when many studies retrieved

Avoid having too many insert processings active at once
by ensuring that each one completes before the next one is
processed (with storescp --exec-sync option).

http://massmail.spl.harvard.edu/public-archives/slicer-users/2013/006324.html

Might also fix 0001978.

git-svn-id: http://svn.slicer.org/Slicer4/trunk@21978 3bd1e089-480b-0410-8dfb-8563597acbee
mod - Modules/Scripted/DICOM/DICOMLib/DICOMProcesses.py Diff File

Issue History

Date Modified Username Field Change
2012-05-03 13:04 bmoloney New Issue
2012-05-03 13:04 bmoloney Status new => assigned
2012-05-03 13:04 bmoloney Assigned To => pieper
2012-05-18 06:32 pieper Target Version => Slicer 4.2.0 AHM Summer 2012
2012-08-23 04:59 pieper Note Added: 0005753
2012-08-28 07:06 pieper Note Added: 0005826
2012-08-28 07:06 pieper Status assigned => closed
2012-08-28 07:06 pieper Resolution open => not fixable
2012-08-28 11:26 bmoloney Note Added: 0005839
2012-08-28 11:26 bmoloney Status closed => feedback
2012-08-28 11:26 bmoloney Resolution not fixable => reopened
2012-08-28 13:46 pieper Note Added: 0005841
2012-08-28 13:47 pieper Note Edited: 0005841
2012-08-30 15:47 bmoloney Note Added: 0005900
2012-08-31 04:16 pieper Note Added: 0005901
2012-08-31 13:14 bmoloney Note Added: 0005918
2012-09-04 04:29 pieper Note Added: 0005936
2012-09-04 11:26 bmoloney Note Added: 0005957
2012-09-06 10:19 pieper Note Added: 0005996
2012-09-10 14:56 bmoloney File Added: slicer_failed_retr.out.gz
2012-09-10 14:56 bmoloney File Added: slicer_success_retr.out.gz
2012-09-10 14:58 bmoloney Note Added: 0006026
2012-09-13 05:42 pieper Note Added: 0006049
2012-09-21 13:19 bmoloney Note Added: 0006166
2012-10-25 14:20 jcfr Status feedback => assigned
2012-10-25 14:21 jcfr Target Version Slicer 4.2.0 - coming release => Slicer 4.3.0
2012-10-25 14:22 jcfr Note Added: 0006789
2012-12-12 01:33 pieper Note Added: 0007486
2013-05-09 12:16 pieper Note Added: 0008602
2013-05-10 13:25 bmoloney Note Added: 0008615
2013-07-05 07:37 pieper Note Added: 0008866
2013-07-05 07:38 pieper Target Version Slicer 4.3.0 =>
2017-06-07 23:27 pieper Changeset attached => Slicer 2145-support-for-installing-extension-from-file 9445cf5e
2017-06-07 23:27 pieper Status assigned => resolved
2017-06-07 23:27 pieper Resolution reopened => fixed