Notice on OpenJDK 11 and Jetty9.4.15 - Teedy Server fails

[vmario89]

Hi,
updating to latest Jetty9 + OpenJDK 11 leads to be impossible to run Sismics Server because the system goes into an error state of "read-only file system". I have no solution for this, but i wanted to let you know about some ticket i created at Jetty project. I think something new needs to be configured since Jetty 9.4.15

jetty/jetty.project#3579

regards, Mario

[vmario89]

Hi, the issue is still persisent. I tried jetty9 and tomcat9. Both return the same error, which is:

Apr 20 01:14:17 busy-ubuntu jetty9[17707]: 20 Apr 2019 01:14:17,107 INFO com.sismics.util.filter.RequestContextFilter.init(RequestContextFilter.java:42) Using base data directory: /var/docs
Apr 20 01:14:17 busy-ubuntu jetty9[17707]: log4j:ERROR setFile(null,true) call failed.
Apr 20 01:14:17 busy-ubuntu jetty9[17707]: java.io.FileNotFoundException: /var/docs/log/docs.log (Read-only file system)

i have no idea how to fix this problem. I invested many hours now trying to downgrade jetty, change from jetty to tomcat, try to revert java (which i was not able to do). I think there is some breaking change in config from openjdk-11-jre-headless version 10.0.2 which was updated by my system to openjdk-11-jre-headless 11.0.2 regularly.

It seems to belong to some log4j stuff.

[jendib]

It looks like an issue on your system if the file is read only.
Are you sure the user starting Jetty has write access on this?

[vmario89]

Hi. No there is no issue with file system. I have this issue with same setup on two different machines now, because they pulled the same updates. Thats the point :( The error leads thinking about file system error but thats not the case indeed :(
Jetty is owner of the files in /var/docs and has 770 permissions

[jendib]

you tried deleting the log file before starting the app?

[vmario89]

for sure. i cleaned up log files, journalctl, tried to remove and resetup /var/docs and so on

[jendib]

Looks like a bug in log4j, it will need more debug

[vmario89]

Hi,
this is the complete log from journalctl. I have no additional log file because in /var/docs it won't create a log file

Apr 21 22:29:50 busy-ubuntu systemd[1]: Started Jetty 9 Web Application Server.
Apr 21 22:29:50 busy-ubuntu snoopy[18707]: [login:(unknown) ssh:((undefined)) sid:18707 tty:(none) ((none)/(none)) uid:jetty(121)/jetty(121) cwd:/usr/share/jetty9]: /usr/share/jetty9/bin/jetty.sh run
Apr 21 22:29:50 busy-ubuntu snoopy[18724]: [login:jetty ssh:((undefined)) sid:18707 tty:(none) ((none)/(none)) uid:jetty(121)/jetty(121) cwd:/usr/share/jetty9]: sed -e s/^[SK][0-9]*// -e s/.sh$//
Apr 21 22:29:50 busy-ubuntu snoopy[18727]: [login:jetty ssh:((undefined)) sid:18707 tty:(none) ((none)/(none)) uid:jetty(121)/jetty(121) cwd:/usr/share/jetty9]: basename /usr/share/jetty9/bin/jetty.sh
Apr 21 22:29:50 busy-ubuntu snoopy[18731]: [login:jetty ssh:((undefined)) sid:18707 tty:(none) ((none)/(none)) uid:jetty(121)/jetty(121) cwd:/usr/share/jetty9]: mkdir /tmp/jetty
Apr 21 22:29:50 busy-ubuntu snoopy[18732]: [login:jetty ssh:((undefined)) sid:18707 tty:(none) ((none)/(none)) uid:jetty(121)/jetty(121) cwd:/usr/share/jetty9]: uname
Apr 21 22:29:50 busy-ubuntu snoopy[18733]: [login:jetty ssh:((undefined)) sid:18707 tty:(none) ((none)/(none)) uid:jetty(121)/jetty(121) cwd:/usr/share/jetty9]: expr # ======================================================== : #
Apr 21 22:29:50 busy-ubuntu snoopy[18734]: [login:jetty ssh:((undefined)) sid:18707 tty:(none) ((none)/(none)) uid:jetty(121)/jetty(121) cwd:/usr/share/jetty9]: expr # jetty.conf Configuration for jetty.sh script : #
Apr 21 22:29:50 busy-ubuntu snoopy[18735]: [login:jetty ssh:((undefined)) sid:18707 tty:(none) ((none)/(none)) uid:jetty(121)/jetty(121) cwd:/usr/share/jetty9]: expr # -------------------------------------------------------- : #
Apr 21 22:29:50 busy-ubuntu snoopy[18736]: [login:jetty ssh:((undefined)) sid:18707 tty:(none) ((none)/(none)) uid:jetty(121)/jetty(121) cwd:/usr/share/jetty9]: expr # This file is used by the jetty.sh script to provide : #
Apr 21 22:29:50 busy-ubuntu snoopy[18737]: [login:jetty ssh:((undefined)) sid:18707 tty:(none) ((none)/(none)) uid:jetty(121)/jetty(121) cwd:/usr/share/jetty9]: expr # extra configuration arguments for the start.jar command : #
Apr 21 22:29:50 busy-ubuntu snoopy[18738]: [login:jetty ssh:((undefined)) sid:18707 tty:(none) ((none)/(none)) uid:jetty(121)/jetty(121) cwd:/usr/share/jetty9]: expr # created by that script. : #
Apr 21 22:29:50 busy-ubuntu snoopy[18739]: [login:jetty ssh:((undefined)) sid:18707 tty:(none) ((none)/(none)) uid:jetty(121)/jetty(121) cwd:/usr/share/jetty9]: expr # : #
Apr 21 22:29:50 busy-ubuntu snoopy[18740]: [login:jetty ssh:((undefined)) sid:18707 tty:(none) ((none)/(none)) uid:jetty(121)/jetty(121) cwd:/usr/share/jetty9]: expr # Each line in this file becomes an argument to start.jar : #
Apr 21 22:29:50 busy-ubuntu snoopy[18742]: [login:jetty ssh:((undefined)) sid:18707 tty:(none) ((none)/(none)) uid:jetty(121)/jetty(121) cwd:/usr/share/jetty9]: expr # ======================================================= : #
Apr 21 22:29:50 busy-ubuntu snoopy[18743]: [login:jetty ssh:((undefined)) sid:18707 tty:(none) ((none)/(none)) uid:jetty(121)/jetty(121) cwd:/usr/share/jetty9]: expr jetty-started.xml : #
Apr 21 22:29:50 busy-ubuntu snoopy[18744]: [login:jetty ssh:((undefined)) sid:18707 tty:(none) ((none)/(none)) uid:jetty(121)/jetty(121) cwd:/usr/share/jetty9]: which java
Apr 21 22:29:50 busy-ubuntu snoopy[18745]: [login:jetty ssh:((undefined)) sid:18707 tty:(none) ((none)/(none)) uid:jetty(121)/jetty(121) cwd:/usr/share/jetty9]: uname
Apr 21 22:29:50 busy-ubuntu snoopy[18746]: [login:jetty ssh:((undefined)) sid:18707 tty:(none) ((none)/(none)) uid:jetty(121)/jetty(121) cwd:/usr/share/jetty9]: uname
Apr 21 22:29:50 busy-ubuntu snoopy[18747]: [login:jetty ssh:((undefined)) sid:18707 tty:(none) ((none)/(none)) uid:jetty(121)/jetty(121) cwd:/usr/share/jetty9]: uname
Apr 21 22:29:50 busy-ubuntu jetty9[18707]: Running Jetty:
Apr 21 22:29:50 busy-ubuntu snoopy[18748]: [login:jetty ssh:((undefined)) sid:18707 tty:(none) ((none)/(none)) uid:jetty(121)/jetty(121) cwd:/usr/share/jetty9]: rm -f /tmp/jetty/jetty.pid
Apr 21 22:29:50 busy-ubuntu snoopy[18707]: [login:jetty ssh:((undefined)) sid:18707 tty:(none) ((none)/(none)) uid:jetty(121)/jetty(121) cwd:/usr/share/jetty9]: /usr/bin/java -Djetty.home=/usr/share/jetty9 -Djetty.base=/usr/share/jetty9 -Djava.io.tmpdir=/tmp -jar /usr/share/jetty9/start.jar jetty.state=/var/lib/jetty9/jetty.state jetty-started.xml
Apr 21 22:29:50 busy-ubuntu jetty9[18707]: 2019-04-21 22:29:50.647:INFO::main: Logging initialized @406ms to org.eclipse.jetty.util.log.StdErrLog
Apr 21 22:29:50 busy-ubuntu jetty9[18707]: 2019-04-21 22:29:50.735:WARN:oejx.XmlConfiguration:main: Property 'threads.min' is deprecated, use 'jetty.threadPool.minThreads' instead
Apr 21 22:29:50 busy-ubuntu jetty9[18707]: 2019-04-21 22:29:50.736:WARN:oejx.XmlConfiguration:main: Property 'threads.max' is deprecated, use 'jetty.threadPool.maxThreads' instead
Apr 21 22:29:50 busy-ubuntu jetty9[18707]: 2019-04-21 22:29:50.739:WARN:oejx.XmlConfiguration:main: Property 'threads.timeout' is deprecated, use 'jetty.threadPool.idleTimeout' instead
Apr 21 22:29:50 busy-ubuntu jetty9[18707]: 2019-04-21 22:29:50.852:WARN:oejx.XmlConfiguration:main: Property 'jetty.port' is deprecated, use 'jetty.http.port' instead
Apr 21 22:29:50 busy-ubuntu jetty9[18707]: 2019-04-21 22:29:50.853:WARN:oejx.XmlConfiguration:main: Property 'http.timeout' is deprecated, use 'jetty.http.idleTimeout' instead
Apr 21 22:29:50 busy-ubuntu jetty9[18707]: 2019-04-21 22:29:50.860:INFO:oejs.Server:main: jetty-9.4.15.v20190215; built: unknown; git: unknown; jvm 11.0.2+9-Ubuntu-3ubuntu118.04.3
Apr 21 22:29:50 busy-ubuntu jetty9[18707]: 2019-04-21 22:29:50.886:INFO:oejdp.ScanningAppProvider:main: Deployment monitor [file:///var/lib/jetty9/webapps/] at interval 1
Apr 21 22:29:51 busy-ubuntu jetty9[18707]: 2019-04-21 22:29:51.048:INFO:oeja.AnnotationConfiguration:main: Scanning elapsed time=0ms
Apr 21 22:29:51 busy-ubuntu jetty9[18707]: 2019-04-21 22:29:51.086:INFO:oejshC.root:main: Warning: No org.apache.tomcat.JarScanner set in ServletContext. Falling back to default JarScanner implementation.
Apr 21 22:29:51 busy-ubuntu jetty9[18707]: 2019-04-21 22:29:51.181:INFO:oajs.TldScanner:main: 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.
Apr 21 22:29:51 busy-ubuntu jetty9[18707]: 2019-04-21 22:29:51.238:INFO:oejs.session:main: DefaultSessionIdManager workerName=node0
Apr 21 22:29:51 busy-ubuntu jetty9[18707]: 2019-04-21 22:29:51.238:INFO:oejs.session:main: No SessionScavenger set, using defaults
Apr 21 22:29:51 busy-ubuntu jetty9[18707]: 2019-04-21 22:29:51.239:INFO:oejs.session:main: node0 Scavenging every 600000ms
Apr 21 22:29:51 busy-ubuntu jetty9[18707]: 2019-04-21 22:29:51.265:INFO:oejsh.ContextHandler:main: Started o.e.j.w.WebAppContext@57a3af25{root,/,file:///var/lib/jetty9/webapps/root/,AVAILABLE}{/root}
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: 2019-04-21 22:29:52.166:INFO:oeja.AnnotationConfiguration:main: Scanning elapsed time=17ms
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: 2019-04-21 22:29:52.171:INFO:oejshC.dms:main: Warning: No org.apache.tomcat.JarScanner set in ServletContext. Falling back to default JarScanner implementation.
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: 2019-04-21 22:29:52.268:INFO:oajs.TldScanner:main: 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.
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: 21 Apr 2019 22:29:52,478 INFO com.sismics.util.filter.RequestContextFilter.init(RequestContextFilter.java:42) Using base data directory: /var/docs
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: log4j:ERROR setFile(null,true) call failed.
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: java.io.FileNotFoundException: /var/docs/log/docs.log (Read-only file system)
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: at java.base/java.io.FileOutputStream.open0(Native Method)
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: at java.base/java.io.FileOutputStream.open(FileOutputStream.java:298)
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: at java.base/java.io.FileOutputStream.(FileOutputStream.java:237)
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: at java.base/java.io.FileOutputStream.(FileOutputStream.java:158)
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: at org.apache.log4j.FileAppender.setFile(FileAppender.java:294)
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: at org.apache.log4j.RollingFileAppender.setFile(RollingFileAppender.java:207)
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: at org.apache.log4j.FileAppender.activateOptions(FileAppender.java:165)
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: at com.sismics.util.filter.RequestContextFilter.init(RequestContextFilter.java:58)
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: at org.eclipse.jetty.servlet.FilterHolder.initialize(FilterHolder.java:136)
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: at org.eclipse.jetty.servlet.ServletHandler.lambda$initialize$0(ServletHandler.java:750)
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: at java.base/java.util.Spliterators$ArraySpliterator.forEachRemaining(Spliterators.java:948)
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: at java.base/java.util.stream.Streams$ConcatSpliterator.forEachRemaining(Streams.java:734)
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: at java.base/java.util.stream.ReferencePipeline$Head.forEach(ReferencePipeline.java:658)
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: at org.eclipse.jetty.servlet.ServletHandler.initialize(ServletHandler.java:744)
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: at org.eclipse.jetty.servlet.ServletContextHandler.startContext(ServletContextHandler.java:369)
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: at org.eclipse.jetty.webapp.WebAppContext.startWebapp(WebAppContext.java:1497)
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: at org.eclipse.jetty.webapp.WebAppContext.startContext(WebAppContext.java:1459)
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: at org.eclipse.jetty.server.handler.ContextHandler.doStart(ContextHandler.java:852)
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: at org.eclipse.jetty.servlet.ServletContextHandler.doStart(ServletContextHandler.java:278)
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: at org.eclipse.jetty.webapp.WebAppContext.doStart(WebAppContext.java:545)
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:68)
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: at org.eclipse.jetty.deploy.bindings.StandardStarter.processBinding(StandardStarter.java:46)
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: at org.eclipse.jetty.deploy.AppLifeCycle.runBindings(AppLifeCycle.java:192)
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: at org.eclipse.jetty.deploy.DeploymentManager.requestAppGoal(DeploymentManager.java:505)
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: at org.eclipse.jetty.deploy.DeploymentManager.addApp(DeploymentManager.java:151)
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: at org.eclipse.jetty.deploy.providers.ScanningAppProvider.fileAdded(ScanningAppProvider.java:180)
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: at org.eclipse.jetty.deploy.providers.WebAppProvider.fileAdded(WebAppProvider.java:447)
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: at org.eclipse.jetty.deploy.providers.ScanningAppProvider$1.fileAdded(ScanningAppProvider.java:64)
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: at org.eclipse.jetty.util.Scanner.reportAddition(Scanner.java:610)
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: at org.eclipse.jetty.util.Scanner.reportDifferences(Scanner.java:529)
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: at org.eclipse.jetty.util.Scanner.scan(Scanner.java:392)
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: at org.eclipse.jetty.util.Scanner.doStart(Scanner.java:313)
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:68)
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: at org.eclipse.jetty.deploy.providers.ScanningAppProvider.doStart(ScanningAppProvider.java:150)
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:68)
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: at org.eclipse.jetty.deploy.DeploymentManager.startAppProvider(DeploymentManager.java:579)
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: at org.eclipse.jetty.deploy.DeploymentManager.doStart(DeploymentManager.java:240)
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:68)
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: at org.eclipse.jetty.util.component.ContainerLifeCycle.start(ContainerLifeCycle.java:138)
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: at org.eclipse.jetty.server.Server.start(Server.java:415)
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: at org.eclipse.jetty.util.component.ContainerLifeCycle.doStart(ContainerLifeCycle.java:117)
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: at org.eclipse.jetty.server.handler.AbstractHandler.doStart(AbstractHandler.java:113)
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: at org.eclipse.jetty.server.Server.doStart(Server.java:382)
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:68)
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: at org.eclipse.jetty.xml.XmlConfiguration$1.run(XmlConfiguration.java:1572)
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: at org.eclipse.jetty.xml.XmlConfiguration$1.run(XmlConfiguration.java:1512)
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: at java.base/java.security.AccessController.doPrivileged(Native Method)
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: at org.eclipse.jetty.xml.XmlConfiguration.main(XmlConfiguration.java:1511)
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: at java.base/java.lang.reflect.Method.invoke(Method.java:566)
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: at org.eclipse.jetty.start.Main.invokeMain(Main.java:220)
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: at org.eclipse.jetty.start.Main.start(Main.java:490)
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: at org.eclipse.jetty.start.Main.main(Main.java:77)
Apr 21 22:29:52 busy-ubuntu jetty9[18707]: 21 Apr 2019 22:29:52,528 INFO com.sismics.util.jpa.EMF.getEntityManagerProperties(EMF.java:84) Configuring EntityManager from environment parameters

can you give me some help on how to get more debug info for log4j?

[jendib]

I just tested with JDK 11 running on Windows 10 and I cannot reproduce your issue. The log file is created without problem. I will investigate further with an Ubuntu machine.

[jendib]

Tried again with OpenJDK 11 on a fresh Ubuntu 18.04, and no issue, the log file is created.
I think there is something specific on your machines denying write access to this folder.

[vmario89]

Hi, thanks for your time investigation. Did you try to update and upgrade each lib to latest? I am using Ubuntu 18 LTS.

At the other thread somebody find out sth useful as it seems:

I'm facing the same error and I was able to track it down to the jetty9.service file.

This file was NOT included in previous versions of the jetty9 pkg and therefore systemd was starting, stopping, etc Jetty by relying on the old initd scripts.

The new .service file includes the following lines:
ProtectSystem=strict
ReadWritePaths=/var/lib/jetty9

I'm no expert in systemd unit files, but I'm afraid that this lines mean that you can not write anything outside /var/lib/jetty9.

I resolved the problem by removing /lib/systemd/system/jetty9.service and then running systemctl daemon-reload && systemctl restart jetty9

i will try this out tomorrow and find out if it works again. I am still wondering because i was not able to get sismics running with tomcat9 too. So maybe tomcat9 has similar lack of system protection maybe. (as i mentioned i tried to change java policy without luck)

regards, Mario

[jendib]

I used a fresh Ubuntu 18.04 with everything updated yes (in a virtual machine).
However I didn't use systemd to start my server so maybe your issue comes from there.

[vmario89]

hi, adjusting the service file fixed it for me. but i'd like to ask if its possible to change the default basedir /var/docs to sth else. Would be great to have an option to change it to /mnt/teedy/data for example

regards and thanks again, Mario

[jendib]

You can override the default data directory with a system property like here: https://github.com/sismics/docs/blob/master/docs.xml