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
=> >-------------------------------------
=> >
=> >