search

jetty / jetty.project

Eclipse Jetty® - Web Container & Clients - supports HTTP/2, HTTP/1.1, HTTP/1.0, websocket, servlets, and more
https://eclipse.dev/jetty
Other
3.85k stars 1.91k forks source link

Startup Script reports `ok` too fast, and doesn't wait for actual start of Jetty #10473

Closed gskjold closed 1 year ago

gskjold commented 1 year ago

Jetty version(s) 10.0.16

Jetty Environment N/A

Java version/vendor (use: java -version) openjdk version "17.0.8" 2023-07-18 LTS

OS type/version Amazon Linux 2

Description Jetty starts fine, but startup script throws error. PID file is empty, so stopping the service is not working.

Startup:

# service jetty start
Starting Jetty: pgrep: option requires an argument -- 'P'

Usage:
 pgrep [options] <pattern>

Options:
 -d, --delimiter <string>  specify output delimiter
 -l, --list-name           list PID and process name
 -a, --list-full           list PID and full command line
 -v, --inverse             negates the matching
 -w, --lightweight         list all TID
 -c, --count               count of matching processes
 -f, --full                use full process name to match
 -g, --pgroup <PGID,...>   match listed process group IDs
 -G, --group <GID,...>     match real group IDs
 -n, --newest              select most recently started
 -o, --oldest              select least recently started
 -P, --parent <PPID,...>   match only child processes of the given parent
 -s, --session <SID,...>   match session IDs
 -t, --terminal <tty,...>  match by controlling terminal
 -u, --euid <ID,...>       match by effective IDs
 -U, --uid <ID,...>        match by real IDs
 -x, --exact               match exactly with the command name
 -F, --pidfile <file>      read PIDs from file
 -L, --logpidfile          fail if PID file is not locked
 --ns <PID>                match the processes that belong to the same
                           namespace as <pid>
 --nslist <ns,...>         list which namespaces will be considered for
                           the --ns option.
                           Available namespaces: ipc, mnt, net, pid, user, uts

 -h, --help     display this help and exit
 -V, --version  output version information and exit

For more details see pgrep(1).
ok Mon Sep  4 10:25:13 CEST 2023

Stop:

# service jetty stop
Stopping Jetty: ERROR: no pid id found in /var/jetty/run/jetty-helse.pid

How to reproduce? Start and stop jetty

joakime commented 1 year ago

I have disabled setuid module and the problem persists. Nothing is written on /srv/www.myweb.com/jetty/jetty.state when I run jetty.sh. In fact there is no Java process running on the server while jetty.sh is waiting (while printing :::::::::::::::) .

# /usr/local/jetty/bin/jetty.sh start
Starting Jetty: :::::::::::::::FAILED Wed Sep 27 03:52:31 PM CEST 2023

Ah, you are running the old SNAPSHOT build. Let me rebuild the SNAPSHOT for what we have currently.

joakime commented 1 year ago

Building the SNAPSHOT is taking me a while, as I'm juggling too many thing right now.

Meanwhile, can you do this on your environment and report back?

$ cd /srv/www.myweb.com/jetty/
$ java -jar /usr/local/jetty-home-10.0.17-SNAPSHOT/start.jar jetty.state=/srv/www.myweb.com/jetty/jetty.state jetty.pid=/run/jetty/jetty.pid --module=pid,state --dry-run > dryrun.sh
$ source dryrun.sh

I just want to eliminate the dry-run behavior as the possible culprit on your configuration.

ofrias commented 1 year ago

Yes, it returns "Can Read" and file permissions seem right: -rw-r--r-- 1 root root 99 Sep 27 15:45 jetty.state

You ran the Java command as root. (that's not a valid test)

Please delete that jetty.state file and run that java command line as the same user id as the eventual setuid configuration would produce. Your configuration shows you want it on UID=1003, GID=1004

I think that we found the root cause. When running Jetty with this command and using jetty user I get this error:

jetty@server:/srv/www.myweb.com/jetty$ /usr/local/java/bin/java -jar /usr/local/jetty-home-10.0.17-SNAPSHOT/start.jar jetty.state=/srv/www.myweb.com/jetty/jetty.state jetty.pid=/run/jetty/jetty.pid --module=pid,state
2023-09-27 19:08:37.685:WARN :oejx.XmlConfiguration:main: Config error java.lang.reflect.InvocationTargetException at <Call class="org.eclipse.jetty.util.PidFile" name="create"><Arg name="file"><Property name="jetty.pid" default="jetty.pid"/></Arg></Call> in file:///usr/local/jetty-home-10.0.17-SNAPSHOT/etc/jetty-pid.xml
2023-09-27 19:08:37.688:WARN :oejx.XmlConfiguration:main: Unable to execute XmlConfiguration
java.lang.reflect.InvocationTargetException
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base/java.lang.reflect.Method.invoke(Method.java:566)
    at org.eclipse.jetty.xml.XmlConfiguration$JettyXmlConfiguration.invokeMethod(XmlConfiguration.java:777)
    at org.eclipse.jetty.xml.XmlConfiguration$JettyXmlConfiguration.call(XmlConfiguration.java:985)
    at org.eclipse.jetty.xml.XmlConfiguration$JettyXmlConfiguration.call(XmlConfiguration.java:950)
    at org.eclipse.jetty.xml.XmlConfiguration$JettyXmlConfiguration.configure(XmlConfiguration.java:504)
    at org.eclipse.jetty.xml.XmlConfiguration$JettyXmlConfiguration.configure(XmlConfiguration.java:457)
    at org.eclipse.jetty.xml.XmlConfiguration.configure(XmlConfiguration.java:359)
    at org.eclipse.jetty.xml.XmlConfiguration.main(XmlConfiguration.java:1900)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base/java.lang.reflect.Method.invoke(Method.java:566)
    at org.eclipse.jetty.start.Main.invokeMain(Main.java:229)
    at org.eclipse.jetty.start.Main.start(Main.java:528)
    at org.eclipse.jetty.start.Main.main(Main.java:76)
Caused by: 
java.nio.file.AccessDeniedException: /run/jetty/jetty.pid
    at java.base/sun.nio.fs.UnixException.translateToIOException(UnixException.java:90)
    at java.base/sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:111)
    at java.base/sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:116)
    at java.base/sun.nio.fs.UnixFileSystemProvider.newByteChannel(UnixFileSystemProvider.java:219)
    at java.base/java.nio.file.spi.FileSystemProvider.newOutputStream(FileSystemProvider.java:478)
    at java.base/java.nio.file.Files.newOutputStream(Files.java:220)
    at java.base/java.nio.file.Files.write(Files.java:3425)
    at java.base/java.nio.file.Files.writeString(Files.java:3641)
    at org.eclipse.jetty.util.PidFile.create(PidFile.java:58)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base/java.lang.reflect.Method.invoke(Method.java:566)
    at org.eclipse.jetty.xml.XmlConfiguration$JettyXmlConfiguration.invokeMethod(XmlConfiguration.java:777)
    at org.eclipse.jetty.xml.XmlConfiguration$JettyXmlConfiguration.call(XmlConfiguration.java:985)
    at org.eclipse.jetty.xml.XmlConfiguration$JettyXmlConfiguration.call(XmlConfiguration.java:950)
    at org.eclipse.jetty.xml.XmlConfiguration$JettyXmlConfiguration.configure(XmlConfiguration.java:504)
    at org.eclipse.jetty.xml.XmlConfiguration$JettyXmlConfiguration.configure(XmlConfiguration.java:457)
    at org.eclipse.jetty.xml.XmlConfiguration.configure(XmlConfiguration.java:359)
    at org.eclipse.jetty.xml.XmlConfiguration.main(XmlConfiguration.java:1900)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base/java.lang.reflect.Method.invoke(Method.java:566)
    at org.eclipse.jetty.start.Main.invokeMain(Main.java:229)
    at org.eclipse.jetty.start.Main.start(Main.java:528)
    at org.eclipse.jetty.start.Main.main(Main.java:76)
java.lang.reflect.InvocationTargetException
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base/java.lang.reflect.Method.invoke(Method.java:566)
    at org.eclipse.jetty.start.Main.invokeMain(Main.java:229)
    at org.eclipse.jetty.start.Main.start(Main.java:528)
    at org.eclipse.jetty.start.Main.main(Main.java:76)
Caused by: java.lang.reflect.InvocationTargetException
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base/java.lang.reflect.Method.invoke(Method.java:566)
    at org.eclipse.jetty.xml.XmlConfiguration$JettyXmlConfiguration.invokeMethod(XmlConfiguration.java:777)
    at org.eclipse.jetty.xml.XmlConfiguration$JettyXmlConfiguration.call(XmlConfiguration.java:985)
    at org.eclipse.jetty.xml.XmlConfiguration$JettyXmlConfiguration.call(XmlConfiguration.java:950)
    at org.eclipse.jetty.xml.XmlConfiguration$JettyXmlConfiguration.configure(XmlConfiguration.java:504)
    at org.eclipse.jetty.xml.XmlConfiguration$JettyXmlConfiguration.configure(XmlConfiguration.java:457)
    at org.eclipse.jetty.xml.XmlConfiguration.configure(XmlConfiguration.java:359)
    at org.eclipse.jetty.xml.XmlConfiguration.main(XmlConfiguration.java:1900)
    ... 7 more
Caused by: java.nio.file.AccessDeniedException: /run/jetty/jetty.pid
    at java.base/sun.nio.fs.UnixException.translateToIOException(UnixException.java:90)
    at java.base/sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:111)
    at java.base/sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:116)
    at java.base/sun.nio.fs.UnixFileSystemProvider.newByteChannel(UnixFileSystemProvider.java:219)
    at java.base/java.nio.file.spi.FileSystemProvider.newOutputStream(FileSystemProvider.java:478)
    at java.base/java.nio.file.Files.newOutputStream(Files.java:220)
    at java.base/java.nio.file.Files.write(Files.java:3425)
    at java.base/java.nio.file.Files.writeString(Files.java:3641)
    at org.eclipse.jetty.util.PidFile.create(PidFile.java:58)
    ... 18 more
java.lang.reflect.InvocationTargetException
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base/java.lang.reflect.Method.invoke(Method.java:566)
    at org.eclipse.jetty.start.Main.invokeMain(Main.java:229)
    at org.eclipse.jetty.start.Main.start(Main.java:528)
    at org.eclipse.jetty.start.Main.main(Main.java:76)
Caused by: java.lang.reflect.InvocationTargetException
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base/java.lang.reflect.Method.invoke(Method.java:566)
    at org.eclipse.jetty.xml.XmlConfiguration$JettyXmlConfiguration.invokeMethod(XmlConfiguration.java:777)
    at org.eclipse.jetty.xml.XmlConfiguration$JettyXmlConfiguration.call(XmlConfiguration.java:985)
    at org.eclipse.jetty.xml.XmlConfiguration$JettyXmlConfiguration.call(XmlConfiguration.java:950)
    at org.eclipse.jetty.xml.XmlConfiguration$JettyXmlConfiguration.configure(XmlConfiguration.java:504)
    at org.eclipse.jetty.xml.XmlConfiguration$JettyXmlConfiguration.configure(XmlConfiguration.java:457)
    at org.eclipse.jetty.xml.XmlConfiguration.configure(XmlConfiguration.java:359)
    at org.eclipse.jetty.xml.XmlConfiguration.main(XmlConfiguration.java:1900)
    ... 7 more
Caused by: java.nio.file.AccessDeniedException: /run/jetty/jetty.pid
    at java.base/sun.nio.fs.UnixException.translateToIOException(UnixException.java:90)
    at java.base/sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:111)
    at java.base/sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:116)
    at java.base/sun.nio.fs.UnixFileSystemProvider.newByteChannel(UnixFileSystemProvider.java:219)
    at java.base/java.nio.file.spi.FileSystemProvider.newOutputStream(FileSystemProvider.java:478)
    at java.base/java.nio.file.Files.newOutputStream(Files.java:220)
    at java.base/java.nio.file.Files.write(Files.java:3425)
    at java.base/java.nio.file.Files.writeString(Files.java:3641)
    at org.eclipse.jetty.util.PidFile.create(PidFile.java:58)
    ... 18 more

Usage: java -jar $JETTY_HOME/start.jar [options] [properties] [configs]
       java -jar $JETTY_HOME/start.jar --help  # for more information

and that's because /run/jetty is owned by root: drwxr-xr-x 2 root root 40 Sep 27 19:04 jetty/

So I changed the directory ownership: chown jetty.jetty /run/jetty

and after that the SNAPSHOT version starts successfully.

Version 10.0.16 does not start even after this change.

I think that this exception should be logged somewhere also when running jetty.sh directly and the pid file path permissions are not correct.

Thanks a lot for your help.

joakime commented 1 year ago

Those error messages should show up in your logs found in ${JETTY_BASE}/logs/ the fact that you don't see any logs at all is also concerning.

joakime commented 1 year ago

@ofrias I went ahead and added some tests for common file system permission issues in PR #10605

ofrias commented 1 year ago

I have tried 10.0.17 and it seems to me that the file system permission checks that you introduced are not compatible with setuid module. At the beginning of the start action in jetty.sh a touch "$JETTY_STATE" command is executed, and it creates a file with root owner. Then, when Jetty starts, it cannot overwrite $JETTY_STATE file because the process is running with another user.

joakime commented 1 year ago

@ofrias we encountered this as well.

See new issue #10696 and the associated PR #10700 for details (and possible fix)