CentOS 7 tomcat 7 baffling error creating xnat temp file

[Bill Crum]

Hi,

Am installing XNAT in CentOS 7 and have a problem slightly different to ones previously reported.
Essentially the tomcat XNAT service fails to start because of an error trying to create a temporary folder in xnat.home.
I am convinced the user/folder permissions are right so would appreciate some input.

Here is the catalina log:

Nov 02, 2018 11:18:42 AM org.apache.catalina.startup.VersionLoggerListener log
INFO: Server version:        Apache Tomcat/7.0.91
Nov 02, 2018 11:18:42 AM org.apache.catalina.startup.VersionLoggerListener log
INFO: Server built:          Sep 13 2018 19:52:12 UTC
Nov 02, 2018 11:18:42 AM org.apache.catalina.startup.VersionLoggerListener log
INFO: Server number:         7.0.91.0
Nov 02, 2018 11:18:42 AM org.apache.catalina.startup.VersionLoggerListener log
INFO: OS Name:               Linux
Nov 02, 2018 11:18:42 AM org.apache.catalina.startup.VersionLoggerListener log
INFO: OS Version:            3.10.0-862.el7.x86_64
Nov 02, 2018 11:18:42 AM org.apache.catalina.startup.VersionLoggerListener log
INFO: Architecture:          amd64
Nov 02, 2018 11:18:42 AM org.apache.catalina.startup.VersionLoggerListener log
INFO: Java Home:             /usr/lib/jvm/java-1.7.0-openjdk-1.7.0.191-2.6.15.4.el7_5.x86_64/jre
Nov 02, 2018 11:18:42 AM org.apache.catalina.startup.VersionLoggerListener log
INFO: JVM Version:           1.7.0_191-mockbuild_2018_07_30_15_33-b00
Nov 02, 2018 11:18:42 AM org.apache.catalina.startup.VersionLoggerListener log
INFO: JVM Vendor:            Oracle Corporation
Nov 02, 2018 11:18:42 AM org.apache.catalina.startup.VersionLoggerListener log
INFO: CATALINA_BASE:         /usr/share/tomcat
Nov 02, 2018 11:18:42 AM org.apache.catalina.startup.VersionLoggerListener log
INFO: CATALINA_HOME:         /usr/share/tomcat
Nov 02, 2018 11:18:42 AM org.apache.catalina.startup.VersionLoggerListener log
INFO: Command line argument: -Dxnat.home=/home/xnat/home
Nov 02, 2018 11:18:42 AM org.apache.catalina.startup.VersionLoggerListener log
INFO: Command line argument: -Xms512m
Nov 02, 2018 11:18:42 AM org.apache.catalina.startup.VersionLoggerListener log
INFO: Command line argument: -Xmx1024m
Nov 02, 2018 11:18:42 AM org.apache.catalina.startup.VersionLoggerListener log
INFO: Command line argument: -XX:MaxPermSize=256m
Nov 02, 2018 11:18:42 AM org.apache.catalina.startup.VersionLoggerListener log
INFO: Command line argument: -Dcatalina.base=/usr/share/tomcat
Nov 02, 2018 11:18:42 AM org.apache.catalina.startup.VersionLoggerListener log
INFO: Command line argument: -Dcatalina.home=/usr/share/tomcat
Nov 02, 2018 11:18:42 AM org.apache.catalina.startup.VersionLoggerListener log
INFO: Command line argument: -Djava.endorsed.dirs=
Nov 02, 2018 11:18:42 AM org.apache.catalina.startup.VersionLoggerListener log
INFO: Command line argument: -Djava.io.tmpdir=/var/cache/tomcat/temp
Nov 02, 2018 11:18:42 AM org.apache.catalina.startup.VersionLoggerListener log
INFO: Command line argument: -Djava.util.logging.config.file=/usr/share/tomcat/conf/logging.properties
Nov 02, 2018 11:18:42 AM org.apache.catalina.startup.VersionLoggerListener log
INFO: Command line argument: -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager
Nov 02, 2018 11:18:42 AM org.apache.catalina.core.AprLifecycleListener lifecycleEvent
INFO: The APR based Apache Tomcat Native library which allows optimal performance in production environments was not found on the java.library.path: /usr/java/packages/lib/amd64:/usr/lib64:/lib64:/lib:/usr/lib
Nov 02, 2018 11:18:42 AM org.apache.coyote.AbstractProtocol init
INFO: Initializing ProtocolHandler ["http-bio-8080"]
Nov 02, 2018 11:18:42 AM org.apache.coyote.AbstractProtocol init
INFO: Initializing ProtocolHandler ["ajp-bio-8009"]
Nov 02, 2018 11:18:42 AM org.apache.catalina.startup.Catalina load
INFO: Initialization processed in 1160 ms
Nov 02, 2018 11:18:42 AM org.apache.catalina.core.StandardService startInternal
INFO: Starting service Catalina
Nov 02, 2018 11:18:42 AM org.apache.catalina.core.StandardEngine startInternal
INFO: Starting Servlet Engine: Apache Tomcat/7.0.91
Nov 02, 2018 11:18:42 AM org.apache.catalina.startup.HostConfig deployWAR
INFO: Deploying web application archive /var/lib/tomcat/webapps/ROOT.war
Nov 02, 2018 11:18:56 AM org.apache.catalina.startup.TldConfig execute
INFO: At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time.
Nov 02, 2018 11:18:57 AM org.apache.catalina.core.ContainerBase addChildInternal
SEVERE: ContainerBase.addChild: start:
org.apache.catalina.LifecycleException: Failed to start component [StandardEngine[Catalina].StandardHost[localhost].StandardContext[]]
        at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:162)
        at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:1018)
        at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:994)
        at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:652)
        at org.apache.catalina.startup.HostConfig.deployWAR(HostConfig.java:1127)
        at org.apache.catalina.startup.HostConfig$DeployWar.run(HostConfig.java:2021)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:473)
        at java.util.concurrent.FutureTask.run(FutureTask.java:262)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1152)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:622)
        at java.lang.Thread.run(Thread.java:748)
Caused by: org.nrg.framework.exceptions.NrgServiceRuntimeException: Error [Unknown]: Error [Unknown]: An error occurred trying to create the temp folder xnat_92283085024921 in the containing folder /home/xnat/home
        at org.nrg.xnat.initialization.XnatWebAppInitializer.getMultipartConfigElement(XnatWebAppInitializer.java:125)
        at org.nrg.xnat.initialization.XnatWebAppInitializer.customizeRegistration(XnatWebAppInitializer.java:104)
        at org.springframework.web.servlet.support.AbstractDispatcherServletInitializer.registerDispatcherServlet(AbstractDispatcherServletInitializer.java:113)
        at org.springframework.web.servlet.support.AbstractDispatcherServletInitializer.onStartup(AbstractDispatcherServletInitializer.java:71)
        at org.nrg.xnat.initialization.XnatWebAppInitializer.onStartup(XnatWebAppInitializer.java:60)
        at org.springframework.web.SpringServletContainerInitializer.onStartup(SpringServletContainerInitializer.java:169)
        at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5669)
        at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:145)
        ... 10 more

Nov 02, 2018 11:18:57 AM org.apache.catalina.startup.HostConfig deployWAR
SEVERE: Error deploying web application archive /var/lib/tomcat/webapps/ROOT.war
java.lang.IllegalStateException: ContainerBase.addChild: start: org.apache.catalina.LifecycleException: Failed to start component [StandardEngine[Catalina].StandardHost[localhost].StandardContext[]]
        at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:1022)
        at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:994)
        at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:652)
        at org.apache.catalina.startup.HostConfig.deployWAR(HostConfig.java:1127)
        at org.apache.catalina.startup.HostConfig$DeployWar.run(HostConfig.java:2021)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:473)
        at java.util.concurrent.FutureTask.run(FutureTask.java:262)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1152)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:622)
        at java.lang.Thread.run(Thread.java:748)

Nov 02, 2018 11:18:57 AM org.apache.catalina.startup.HostConfig deployWAR
INFO: Deployment of web application archive /var/lib/tomcat/webapps/ROOT.war has finished in 15,210 ms
Nov 02, 2018 11:18:57 AM org.apache.coyote.AbstractProtocol start
INFO: Starting ProtocolHandler ["http-bio-8080"]
Nov 02, 2018 11:18:58 AM org.apache.coyote.AbstractProtocol start
INFO: Starting ProtocolHandler ["ajp-bio-8009"]
Nov 02, 2018 11:18:58 AM org.apache.catalina.startup.Catalina start
INFO: Server startup in 15886 ms
---------------------------------------------------------------------

Here is tomcat.conf:
# This variable is used to figure out if config is loaded or not.
TOMCAT_CFG_LOADED="1"

# In new-style instances, if CATALINA_BASE isn't specified, it will
# be constructed by joining TOMCATS_BASE and NAME.
TOMCATS_BASE="/var/lib/tomcats/"

# Where your java installation lives
JAVA_HOME="/usr/lib/jvm/jre"

# Where your tomcat installation lives
CATALINA_HOME="/usr/share/tomcat"

# System-wide tmp
CATALINA_TMPDIR="/var/cache/tomcat/temp"

#CATALINA_OPTS="${CATALINA_OPTS} -Dxnat.home=/home/xnat/home -Xms512m -Xmx1024m -XX:MaxPermSize=256m"
CATALINA_OPTS="-Dxnat.home=/home/xnat/home -Xms512m -Xmx1024m -XX:MaxPermSize=256m"
# You can pass some parameters to java here if you wish to
#JAVA_OPTS="-Xminf0.1 -Xmaxf0.3"

# Use JAVA_OPTS to set java.library.path for libtcnative.so
#JAVA_OPTS="-Djava.library.path=/usr/lib"

# You can change your tomcat locale here
#LANG="en_US"

# Run tomcat under the Java Security Manager
SECURITY_MANAGER="false"

# Time to wait in seconds, before killing process
# TODO(stingray): does nothing, fix.
# SHUTDOWN_WAIT="30"
--------------------------------------------------------------------------

Here is the tomcat process - the tomcat user and group are xnat and all the tomcat folders have beem chowned to xnat:xnat
[xnat@localhost log]$ ps -ef | egrep tomcat
xnat     12128     1  3 11:18 ?        00:00:17 java -Dxnat.home=/home/xnat/home -Xms512m -Xmx1024m -XX:MaxPermSize=256m -classpath /usr/share/tomcat/bin/bootstrap.jar:/usr/share/tomcat/bin/tomcat-juli.jar:/usr/share/java/commons-daemon.jar -Dcatalina.base=/usr/share/tomcat -Dcatalina.home=/usr/share/tomcat -Djava.endorsed.dirs= -Djava.io.tmpdir=/var/cache/tomcat/temp -Djava.util.logging.config.file=/usr/share/tomcat/conf/logging.properties -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager org.apache.catalina.startup.Bootstrap start
xnat     12276  3081  0 11:27 pts/0    00:00:00 grep -E --color=auto tomcat
--------------------------------------------------------------------------------

Here is the systemd file for tomcat:
# Systemd unit file for default tomcat
#
# To create clones of this service:
# DO NOTHING, use tomcat@.service instead.

[Unit]
Description=Apache Tomcat Web Application Container
After=syslog.target network.target

[Service]
Type=simple
EnvironmentFile=/etc/tomcat/tomcat.conf
Environment="NAME="
EnvironmentFile=-/etc/sysconfig/tomcat
ExecStart=/usr/libexec/tomcat/server start
SuccessExitStatus=143
User=xnat
Group=xnat

[Install]
WantedBy=multi-user.target
-------------------------------------------------------------------------

Here are the folder permissions for /home/xnat/home

[xnat@localhost ~]$ ls -alrt /home
total 0
dr-xr-xr-x. 17 root root 224 Oct 30 14:50 ..
drwxr-xr-x.  3 root root  18 Oct 30 14:50 .
drwxr-xr-x. 12 xnat xnat 219 Nov  2 11:29 xnat

[xnat@localhost ~]$ ls -alrt /home/xnat
total 24
-rwxr-xr-x.  1 xnat     xnat      231 Apr 11  2018 .bashrc
-rwxr-xr-x.  1 xnat     xnat      193 Apr 11  2018 .bash_profile
-rwxr-xr-x.  1 xnat     xnat       18 Apr 11  2018 .bash_logout
drwxr-xr-x.  3 root     root       18 Oct 30 14:50 ..
drwxr-xr-x.  2 xnat     xnat        6 Oct 30 15:23 ftp
drwxr-xr-x.  2 xnat     xnat        6 Oct 30 15:23 cache
drwxr-xr-x.  2 xnat     xnat        6 Oct 30 15:23 build
drwxr-xr-x.  2 xnat     xnat        6 Oct 30 15:23 archive
drwxr-xr-x.  2 xnat     xnat        6 Oct 30 15:23 prearchive
drwxr-xr-x.  2 xnat     xnat        6 Oct 30 15:23 pipeline
drwx------. 20 postgres postgres 4096 Oct 30 16:32 pgdata
drwxr-xr-x.  2 xnat     xnat       25 Oct 31 15:30 .ssh
-rwxr-xr-x.  1 xnat     xnat     6103 Oct 31 18:53 .bash_history
drwxr-xr-x.  7 xnat     xnat       71 Nov  1 09:59 home
drwxrwxr-x.  3 xnat     xnat       94 Nov  2 11:29 temp
drwxr-xr-x. 12 xnat     xnat      219 Nov  2 11:29 .
------------------------------------------------------------------------------------------------

Other things I have tried:
1. Originally the XNAT folders were created on a network share but the above replicates the problem when they are created in a standard user directory
2. I'm aware there is a problem with the standard tomcat version installed in CentOS 7 but I'm not even getting that far.
 I have manually updated to 7.0.91 which makes no difference.
3. As user xnat I can manually create any folder I like in /home/xnat/home

I have a bad feeling I am  missing something obvious,  but can't think what it can be,
The only time I recall reading about this there was a more obvious permissions problem.
Does anyone have any ideas?

Many Thanks

-Bill

[Herrick, Rick]

That seems like it has to be a permissions issue. The code there looks to see if xnat.home is set and, if so, tries to create or access the directory ${xnat.home}/work (if xnat.home is not set, it uses java.io.tmpdir/xnat but xnat.home seems to be set in your case). Then, under that directory, it tries to create a working temp folder xnat_timestamp (which in your case is xnat_92283085024921). Here’s the code:

 

final String prefix = "xnat_" + System.nanoTime(); // prefix is xnat_92283085024921

final Path path = Paths.get(root, subfolder); // root is ${xnat.home}, subfolder is work, so /home/xnat/home/work

path.toFile().mkdirs(); // Try to actually create /home/xnat/home}/work
final Path tmpDir = Files.createTempDirectory(path, prefix); // Now try to create /home/xnat/home/work/xnat_92283085024921

 

Unfortunately, Java isn’t giving much information about what’s going wrong. The line number is actually just where the error is being thrown by XNAT and doesn’t include the root cause exception for some reason. However, it HAS to be failing on the mkDirs() call, because it makes no sense that it could create that directory then not be able to create another directory immediately inside that directory.

 

The only thing I can suggest is manually creating the work folder under /home/xnat/home as the xnat user before starting Tomcat and see if that helps.

 

-- 

Rick Herrick

Sr. Programmer/Analyst

Neuroinformatics Research Group

Washington University School of Medicine

Phone: +1 (314) 273-1645

--
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.
To view this discussion on the web visit https://groups.google.com/d/msgid/xnat_discussion/06959ce4-5ff6-4765-82fc-95824d067db8%40googlegroups.com.
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.

[Bill Crum]

Thanks for the sanity check Rick.

A couple of other details. This problem appeared on a system running java-1.7.0-openjdk.
I have since recreated it on a system running java-1.8.0-openjdk and after doing
chmod  -R  777  /home/xnat

drwxrwxrwx.  2 xnat xnat   6 Nov  2 16:19 work
drwxrwxrwx.  2 xnat xnat   6 Nov  2 16:19 plugins
drwxrwxrwx.  2 xnat xnat   6 Nov  2 16:19 logs
drwxrwxrwx.  2 xnat xnat   6 Nov  2 16:19 config
drwxrwxrwx.  6 xnat xnat  59 Nov  2 16:19 .
drwxrwxrwx. 10 xnat xnat 223 Nov  2 16:39 ..

All these systems are *minimal* installations of CentOS 7 if this makes a difference but I don't see why it should.
I'll think about it over the weekend ..

Thanks

-Bill

[Bill Crum]

Well you learn something every day.
Turns out there is a simple explanation to this problem.

CentOS 7 by default runs with the Security Enhanced Linux (SELinux) module in enforce mode.
This prevents services like Tomcat from writing anywhere that has not been specifically permitted.
Without knowing this (like in my case last week) the appearance is of a permissions problem when none should exist.

The crude way to fix it is to do the following:
sudo  setenforce  0

However the more desirable way is to (I think) create an appropriate SELinux context for the directories tomcat needs.
I'll post up the way to do this in due course when I figure it out.

[Bill Crum]

I found out the simplest way to allow XNAT to run with SELinux in CentOS 7 is as follows:

1. Install XNAT

2. Set SELinux to permissive mode
sudo  setenforce  0

3. Allow XNAT to run and sort out any problems.
SELinux will be busy logging perceived tomcat infractions but will allow them.

4. Get SELinux to generate a policy based on the log of tomcat infractions and apply the policy
(You may need to sudo  yum  install  setroubleshoot first)
sudo  grep  tomcat  /var/log/audit/audit.log  | audit2allow  -M  tomcat_selinux_policy
sudo  semodule  -i  tomcat_selinux_policy.pp

5. Switch SELinux to enforce mode
sudo  setenforce  1

[Tashrif]

I have been able to define a custom SELinux policy following this. Thank you.

-Tashrif

.