XNAT upgraded to 1.6.4, storescu blocked due to "Possible CSRF Attempt"

[goo...@merctech.com]

I just upgraded our install of XNAT from 1.6.3 to 1.6.4 -- fairly painless &
well documented, thanks!

However, when I test sending data from the command-line of a Linux client
via 'storescu', cases are not received and XNAT sends email warning about
a "Possible CSRF Attempt" (see email below, lines broken for readability,
minor obfuscation of hostname & IPs).

The storescu test, which was used under 1.6.3, uses the following command and
produces the output as shown:

-----------------------------
storescu --verbose --call MeningiomaVol --propose-jpeg8 myxnat 8104 IM-0001-0120.dcm
I: checking input files ...
I: Requesting Association
I: Association Accepted (Max Send PDV: 16372)
I: Sending file: IM-0001-0120.dcm
I: Transfer Syntax: LittleEndianExplicit -> LittleEndianExplicit
I: Sending Store Request: MsgID 1, (CT)
XMIT: .................................
I: Received Store Response
W: Status Detail:
W:
W: # Dicom-Data-Set
W: # Used TransferSyntax: Little Endian Implicit
W: (0000,0902) LO [java.io.IOException: No locks available] # 40, 1 ErrorComment
W:
I: Releasing Association
-----------------------------

The curious thing is that the build.properties file from both the previous
1.6.3 install (where this problem never appeared) and the 1.6.4 version
contains:
xdat.enable_csrf_token=true

Any suggestions?

Thanks,

Mark


-------------------------------------
HOST: http://myxnat.example.com:8080/xnat
TIME: Thu Feb 19 12:39:21 EST 201192.168
MESSAGE: XNAT_CSRF token was not properly set in the session. GET on URL:
http://localhost:8080/xnat/REST/projects from /192.168.181.85 (58056) user:
127.0.0.1 Headers: host: localhost:8080 user-agent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko)
Chrome/40.0.2214.45 Safari/537.36 x-requested-with: XMLHttpRequest accept: */* dnt: 1 referer:
http://myxnat.example.com/xnat/ accept-encoding: gzip, deflate, sdch
accept-language: en-US,en;q=0.8 cookie:
JSESSIONID=BDF0DC60244D4EF519B2945BC4E795D0; _ga=GA1.2.441862876.1384470768;
__utma=10244330.441862876.1384470768.1411955079.1411962638.2; __utmc=10244330;
__utmz=10244330.1411962638.2.2.utmcsr=google|utmccn=(organic)|utmcmd=organic|utmctr=(not%20provided);
WARNING_BAR=OPEN; SESSION_TIMEOUT_TIME=1424367253763;
open.nodes=projectData.r%2Css%2Cd; guest=false;
SESSION_EXPIRATION_TIME_DIALOG_DISPLAYING=false;
SESSION_EXPIRATION_TIMEOUT=false; SESSION_LOGOUT_HAS_REDIRECTED=cleared=true;
SESSION_EXPIRATION_TIME="1424367561065,900000" x-forwarded-for: 192.168.181.85 x-forwarded-host: myxnat.example.com
x-forwarded-server: myxnat.example.com connection: Keep-Alive
Cookies: JSESSIONID BDF0DC60244D4EF519B2945BC4E795D0 -1 null _ga GA1.2.441862876.1384470768 -1 null __utma 10244330.441862876.1384470768.1411955079.1411962638.2 -1 null __utmc 10244330 -1 null __utmz 10244330.1411962638.2.2.utmcsr -1 null
WARNING_BAR OPEN -1 null SESSION_TIMEOUT_TIME 1424367253763 -1 null open.nodes projectData.r%2Css%2Cd -1 null
guest false -1 null SESSION_EXPIRATION_TIME_DIALOG_DISPLAYING false -1 null SESSION_EXPIRATION_TIMEOUT false -1 null
SESSION_LOGOUT_HAS_REDIRECTED cleared -1 null SESSION_EXPIRATION_TIME 1424367561065,900000 -1 null
-------------------------------------

[Herrick, Rick]

That is very strange, because storescu doesn¹t even use HTTP and the CSRF
is only for HTTP calls. Do you see anything in the XNAT logs?

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

>--
>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/d/optout.


________________________________

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.

[goo...@merctech.com]

In the message dated: Thu, 19 Feb 2015 20:02:24 +0000,
The pithy ruminations from "Herrick, Rick" on
<Re: [XNAT Discussion] XNAT upgraded to 1.6.4, storescu blocked due to "Possible CSRF Attempt"> were:
=> That is very strange, because storescu doesn¹t even use HTTP and the CSRF
=> is only for HTTP calls. Do you see anything in the XNAT logs?

Yeah, that's what I thought...

Hmmm.... Let me check more closely ... /var/log/maillog doesn't show
additional email re. CSRF attempts in response to each storescu call. I
now suspect that the CSRF warnings were coming from the attempt to bring
up the 1.6.4 instance, not from storescu uploads. The count of mail
warnings & timing corresponded very, very closely to my initial upload
attempts, but I now see that they probably weren't related. Sorry about
the confusion.

In any case, I am unable to send data to xnat using the storescu technique I previously
used with v 1.6.3.

To reduce distracting log entries, I just:

stopped tomcat6
removed logs from /var/lib/tomcat6/webapps/xnat/logs
removed files from $XDAT/prearchive
started tomcat6
attempted storescu transfer of one DICOM file

The entire contents of the only logs in /var/lib/tomcat6/webapps/xnat/logs with data are:

################## axis.log #######################
15895 [main] ERROR org.apache.axis.configuration.EngineConfigurationFactoryServlet - Unable to find config file. Creating new servlet engine config file: /WEB-INF/server-config.wsdd
#############################################


################## dicom.log #######################
2015-02-19 17:49:43,975 [pool-1-thread-2] ERROR org.nrg.dcm.CStoreService - C-STORE operation failed org.nrg.action.ServerException: java.io.IOException: No locks available
at org.nrg.xnat.archive.GradualDicomImporter.call(GradualDicomImporter.java:456)
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:1146)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:701)
Caused by: java.io.IOException: No locks available
at sun.nio.ch.FileChannelImpl.lock0(Native Method)
at sun.nio.ch.FileChannelImpl.tryLock(FileChannelImpl.java:924)
at java.nio.channels.FileChannel.tryLock(FileChannel.java:978)
at org.nrg.xnat.helpers.prearchive.PrearcUtils.lockFile(PrearcUtils.java:735)
at org.nrg.xnat.archive.GradualDicomImporter.call(GradualDicomImporter.java:451)
... 14 more
#############################################


################## sql.log #######################
2015-02-19 17:48:26,398 - SELECT pg_get_serial_sequence('xnat_projectData_resource','xnat_projectData_resource_id') AS col_name
2015-02-19 17:48:26,405 - SELECT pg_get_serial_sequence('xnat_projectData_investigator','xnat_projectData_investigator_id') AS col_name
2015-02-19 17:48:26,406 - SELECT * FROM xnat_projectData_investigator_xnat_projectData_investigator_id_seq
2015-02-19 17:48:26,407 - SELECT * FROM xnat_projectData_investigator_xnat_projectData_investigator__seq
2015-02-19 17:48:26,414 - SELECT pg_get_serial_sequence('xnat_subjectData_resource','xnat_subjectData_resource_id') AS col_name
2015-02-19 17:48:26,421 - SELECT pg_get_serial_sequence('xnat_experimentData_resource','xnat_experimentData_resource_id') AS col_name
2015-02-19 17:48:26,422 - SELECT * FROM xnat_experimentData_resource_xnat_experimentData_resource_id_seq
2015-02-19 17:48:26,439 - SELECT pg_get_serial_sequence('xnat_datatypeProtocol_fieldGroups','xnat_datatypeProtocol_fieldGroups_id') AS col_name
2015-02-19 17:48:26,440 - SELECT * FROM xnat_datatypeProtocol_fieldGroups_xnat_datatypeProtocol_fieldGroups_id_seq
2015-02-19 17:48:26,441 - SELECT * FROM xnat_datatypeProtocol_fieldGro_xnat_datatypeProtocol_fieldGro_seq
#############################################


################## velocity.log #######################
2015-02-19 17:48:21,114 [main] ERROR velocity - VM #xdatStringBoxOnChange: error : too few arguments to macro. Wanted 6 got 0
2015-02-19 17:48:21,115 [main] ERROR velocity - VM #xdatStringBoxOnChange: error : too few arguments to macro. Wanted 6 got 0
2015-02-19 17:48:21,115 [main] ERROR velocity - VM #xdatStringBoxOnChange: error : too few arguments to macro. Wanted 6 got 0
2015-02-19 17:48:21,176 [main] ERROR velocity - VM #xdatSearchForm: error : too few arguments to macro. Wanted 2 got 0
2015-02-19 17:48:21,198 [main] ERROR velocity - VM #addCustomScreens: error : too few arguments to macro. Wanted 2 got 0
2015-02-19 17:48:21,260 [main] ERROR velocity - VM #displayFileSystem: error : too few arguments to macro. Wanted 1 got 0
2015-02-19 17:48:21,261 [main] ERROR velocity - VM #auditBoxes: error : too few arguments to macro. Wanted 4 got 0
#############################################


The $XDAT/prearchive directory contains a directory structure for the DICOM I was attempting to send, but no files.

Thanks,

Mark

=>
=> --
=> Rick Herrick
=> Sr. Programmer/Analyst
=> Neuroinformatics Research Group
=> Washington University School of Medicine
=> (314) 740-5961
=>
=>
=>
=>
=>
=>
=>
=>
=> On 2/19/15, 1:59 PM, "goo...@merctech.com" <goo...@merctech.com> wrote:
=>
=> >I just upgraded our install of XNAT from 1.6.3 to 1.6.4 -- fairly
=> >painless &
=> >well documented, thanks!
=> >
=> >However, when I test sending data from the command-line of a Linux client
=> >via 'storescu', cases are not received and XNAT sends email warning about
=> >a "Possible CSRF Attempt" (see email below, lines broken for readability,
=> >minor obfuscation of hostname & IPs).
=> >
=> >The storescu test, which was used under 1.6.3, uses the following command
=> >and
=> >produces the output as shown:
=> >
=> >-----------------------------
=> > storescu --verbose --call MeningiomaVol --propose-jpeg8 myxnat 8104
=> >IM-0001-0120.dcm
=> > I: checking input files ...
=> > I: Requesting Association
=> > I: Association Accepted (Max Send PDV: 16372)
=> > I: Sending file: IM-0001-0120.dcm
=> > I: Transfer Syntax: LittleEndianExplicit -> LittleEndianExplicit
=> > I: Sending Store Request: MsgID 1, (CT)
=> > XMIT: .................................
=> > I: Received Store Response
=> > W: Status Detail:
=> > W:
=> > W: # Dicom-Data-Set
=> > W: # Used TransferSyntax: Little Endian Implicit
=> > W: (0000,0902) LO [java.io.IOException: No locks available] # 40, 1
=> >ErrorComment
=> > W:
=> > I: Releasing Association
=> >-----------------------------
=> >
=> >The curious thing is that the build.properties file from both the previous
=> >1.6.3 install (where this problem never appeared) and the 1.6.4 version
=> >contains:
=> > xdat.enable_csrf_token=true
=> >
=> >Any suggestions?
=> >
=> >Thanks,
=> >
=> >Mark
=> >
=> >
=> >-------------------------------------
=> >HOST: http://myxnat.example.com:8080/xnat
=> >TIME: Thu Feb 19 12:39:21 EST 201192.168
=> >MESSAGE: XNAT_CSRF token was not properly set in the session. GET on URL:
=> >http://localhost:8080/xnat/REST/projects from /192.168.181.85 (58056)
=> >user:
=> >127.0.0.1 Headers: host: localhost:8080 user-agent: Mozilla/5.0 (X11;
=> >Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko)
=> >Chrome/40.0.2214.45 Safari/537.36 x-requested-with: XMLHttpRequest
=> >accept: */* dnt: 1 referer:
=> >http://myxnat.example.com/xnat/ accept-encoding: gzip, deflate, sdch
=> >accept-language: en-US,en;q=0.8 cookie:
=> >JSESSIONID=BDF0DC60244D4EF519B2945BC4E795D0;
=> >_ga=GA1.2.441862876.1384470768;
=> >__utma=10244330.441862876.1384470768.1411955079.1411962638.2;
=> >__utmc=10244330;
=> >__utmz=10244330.1411962638.2.2.utmcsr=google|utmccn=(organic)|utmcmd=organ
=> >ic|utmctr=(not%20provided);
=> >WARNING_BAR=OPEN; SESSION_TIMEOUT_TIME=1424367253763;
=> >open.nodes=projectData.r%2Css%2Cd; guest=false;
=> >SESSION_EXPIRATION_TIME_DIALOG_DISPLAYING=false;
=> >SESSION_EXPIRATION_TIMEOUT=false;
=> >SESSION_LOGOUT_HAS_REDIRECTED=cleared=true;
=> >SESSION_EXPIRATION_TIME="1424367561065,900000" x-forwarded-for:
=> >192.168.181.85 x-forwarded-host: myxnat.example.com
=> >x-forwarded-server: myxnat.example.com connection: Keep-Alive
=> >Cookies: JSESSIONID BDF0DC60244D4EF519B2945BC4E795D0 -1 null _ga
=> >GA1.2.441862876.1384470768 -1 null __utma
=> >10244330.441862876.1384470768.1411955079.1411962638.2 -1 null __utmc
=> >10244330 -1 null __utmz 10244330.1411962638.2.2.utmcsr -1 null
=> >WARNING_BAR OPEN -1 null SESSION_TIMEOUT_TIME 1424367253763 -1 null
=> >open.nodes projectData.r%2Css%2Cd -1 null
=> >guest false -1 null SESSION_EXPIRATION_TIME_DIALOG_DISPLAYING false -1
=> >null SESSION_EXPIRATION_TIMEOUT false -1 null
=> >SESSION_LOGOUT_HAS_REDIRECTED cleared -1 null SESSION_EXPIRATION_TIME
=> >1424367561065,900000 -1 null
=> >-------------------------------------
=> >
=> >

[Herrick, Rick]

This is some sort of issue with your back-end storage. It’s very hard to
say what the cause might be without knowing how your overall system is
configured. XNAT is attempting to lock files for writing, but can’t get a
lock. That means some process has grabbed up a bunch of locks and hasn’t
let them go. That process could conceivably be XNAT, but it’s unlikely
that XNAT would consume that many locks without releasing them, unless
something went drastically wrong with a previous import operation.

Here’s what I’d try, in this order:

* Restart Tomcat. If this fixes the problem, let us know, since that
indicates that there’s a possible bug inside the DICOM import function.
* Reboot the server. If this fixes the problem, then there’s something
else going on with your server that’s grabbing those locks. You should
review what other services are running on the machine that might be
causing this issue.
* If the back-end storage is NFS mounted, you can try rebooting that
server. This can be really tricky, since it’s hard to know who’s consuming
the locks. In an enterprise or cloud scenario, lots of other machines are
doing things that you have no visibility to access. If this is the case,
you’d need to escalate this problem to your IT staff.

--
Rick Herrick
Sr. Programmer/Analyst
Neuroinformatics Research Group

Washington University School of Medicine

(314) 740-5961

[Tim Olsen]

One other note, can you let us know how you installed 1.6.4. Did you download the zip/tar.gz? Or did you pull directly from bitbucket?

Tim

[goo...@merctech.com]

In the message dated: Fri, 20 Feb 2015 09:46:57 -0600,
The pithy ruminations from "Tim Olsen" on
<RE: [XNAT Discussion] XNAT upgraded to 1.6.4, storescu blocked due to "Possible CSRF Attempt"> were:
=> One other note, can you let us know how you installed 1.6.4. Did you download the zip/tar.gz? Or did you pull directly from bitbucket?

The tar.gz file.

Thanks,

Mark

=>
=> Tim
=>