Skip to content

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

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom
Closed
gskjold opened this issue Sep 4, 2023 · 57 comments · Fixed by #10501 or #10605
Closed

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

gskjold opened this issue Sep 4, 2023 · 57 comments · Fixed by #10501 or #10605
Labels
Bug For general bugs on Jetty side

Comments

@gskjold
Copy link

gskjold commented Sep 4, 2023

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
@gskjold gskjold added the Bug For general bugs on Jetty side label Sep 4, 2023
@joakime
Copy link
Contributor

joakime commented Sep 4, 2023

I'm going to rip out the pgrep.
Seems that there's no consistency in command line arguments between versions. :-(

@ofrias
Copy link

ofrias commented Sep 12, 2023

Similar problem here, systemctl start jetty is broken in 10.0.16

@joakime
Copy link
Contributor

joakime commented Sep 12, 2023 •
edited
Loading

The only failure case is if pgrep is not present on your system, or is using a non gnu pgrep alternate version.

So, if I revert pgrep, then the issue that added it #10271 becomes a problem again, and you cannot stop the Jetty server.

Damned if you do, Damned if you don't.
Still researching other solutions.

@joakime
Copy link
Contributor

joakime commented Sep 12, 2023

For those of you that are experiencing issues with no PID file ...

Enable DEBUG logging for org.eclipse.jetty.util.PidFile and report back what you see.
There could also be an Exception stacktrace seen on startup that could yield interesting information.

@joakime
Copy link
Contributor

joakime commented Sep 12, 2023

Opened PR #10501 to revert the new pgrep addition.

@ofrias @gskjold @l-cdc PR #10501 will need testing on your environment, as you all apparently have an unusual offshoot of a typical linux/unix/osx environment. (Our testing on our own systems, and the various official docker images do not manifest the issues you are reporting to us)

@ofrias
Copy link

ofrias commented Sep 13, 2023 •
edited
Loading

It looks like in my case it is a different error.

Jetty 10.0.15 starts fine:

# /usr/local/jetty/bin/jetty.sh start
Starting Jetty: . . OK Wed Sep 13 09:26:46 AM CEST 2023

But when upgrading my JETTY_HOME to Jetty 10.0.16 the script exits almost immediately and Jetty is not started (even though the script says "ok"):

# /usr/local/jetty/bin/jetty.sh start
Starting Jetty: ok Wed Sep 13 09:31:15 AM CEST 2023

I have added pid and state modules to my JETTY_BASE but it looks like there is something else missing.

@gskjold
Copy link
Author

gskjold commented Sep 13, 2023

@joakime With the changes in you PR, the pid file is still empty I'm afraid..

@joakime joakime mentioned this issue Sep 13, 2023
Closed
@joakime
Copy link
Contributor

joakime commented Sep 13, 2023

@gskjold @ofrias please turn on DEBUG of the org.eclipse.jetty.util.PidFile named logger in your startup, and try again.

Also, what unix distributions are you using? I'd like to try to find a docker image for it so I can attempt to replicate.

@joakime
Copy link
Contributor

joakime commented Sep 13, 2023 •
edited
Loading

I have added pid and state modules to my JETTY_BASE but it looks like there is something else missing.

There's no need to enable those modules manually when using the jetty.sh, they come from the ${jetty.home}/etc/jetty.conf file.
You can verify this with a manual run ...

cd /path/to/my-jetty-base
java -jar /path/to/jetty-home/start.jar --list-config

The output should indicate ...

  1. that pid and state are enabled modules in your Enabled Modules: section.
  2. that jetty-pid.xml and jetty-state.xml are present in your Active XMLs: Jetty section.

@gskjold
Copy link
Author

gskjold commented Sep 13, 2023

@gskjold @ofrias please turn on DEBUG of the org.eclipse.jetty.util.PidFile named logger in your startup, and try again.

Added this to my logback.xml, but cannot see anything in the log about it after:

    <logger name="org.eclipse.jetty.util.PidFile" level="DEBUG">
	<appender-ref ref="file1" />
    </logger>

Also, what unix distributions are you using? I'd like to try to find a docker image for it so I can attempt to replicate.

I am using Amazon Linux 2

@l-cdc
Copy link

l-cdc commented Sep 13, 2023

@l-cdc PR #10501 will need testing on your environment, as you all apparently have an unusual offshoot of a typical linux/unix/osx environment. (Our testing on our own systems, and the various official docker images do not manifest the issues you are reporting to us)

Strange. I am pretty sure we are using an unmodified - if somewhat old - RHEL7 image.

In any case, it makes sense to disown the xargs process (not its child process), so I do not see issues with the changes in this PR. The problem in #10271 was that the wrong pid was written to the file, which was fixed.

It is unclear to me why the PID file would be empty for @gskjold. Could it be a permission issue?

@joakime
Copy link
Contributor

joakime commented Sep 13, 2023

It is unclear to me why the PID file would be empty for @gskjold. Could it be a permission issue?

The fact that he sees no logs on org.eclipse.jetty.util.PidFile means nothing is even attempting to write a PID file.
The code never had a chance to even fail a permission check.

@gskjold
Copy link
Author

gskjold commented Sep 13, 2023

The jetty instance is running as user "jetty". The file is updated at last start, but is empty:
-rw-r--r-- 1 jetty root 0 sep. 13 14:25 jetty-prodtest.pid

@joakime
Copy link
Contributor

joakime commented Sep 13, 2023

@gskjold what is the output of your service jetty status call?

@gskjold
Copy link
Author

gskjold commented Sep 13, 2023 

# service jetty-prodtest status
WARN  : Use of both ${jetty.base}/start.d and ${jetty.base}/start.ini is deprecated
Jetty NOT running

JAVA                  =  /usr/lib/jvm/java-11-amazon-corretto.x86_64/bin/java
JAVA_OPTIONS          =  -Djetty.http.port=8081 -Xms64m -Xmx6g -server
JETTY_HOME            =  /usr/lib/jetty/10.0
JETTY_BASE            =  /var/jetty/prodtest
START_D               =  /var/jetty/prodtest/start.d
START_INI             =  /var/jetty/prodtest/start.ini
JETTY_START           =  /usr/lib/jetty/10.0/start.jar
JETTY_CONF            =  /var/jetty/prodtest/etc/jetty.conf
JETTY_ARGS            =  jetty.state=/var/jetty/prodtest/jetty-prodtest.state jetty.pid=/var/jetty/run/jetty-prodtest.pid jetty-http.xml jetty-deploy.xml jetty-jndi.xml console-capture.xml
JETTY_RUN             =  /var/jetty/run
JETTY_PID             =  /var/jetty/run/jetty-prodtest.pid
JETTY_START_LOG       =  /var/jetty/run/jetty-prodtest-start.log
JETTY_STATE           =  /var/jetty/prodtest/jetty-prodtest.state
JETTY_START_TIMEOUT   =  300
JETTY_SYS_PROPS       =  
RUN_ARGS              =  -Djava.io.tmpdir=/tmp -Djetty.home=/usr/lib/jetty/10.0 -Djetty.base=/var/jetty/prodtest -Xms64m -Xmx6g -server -Djetty.http.port=8081 --class-path /var/jetty/prodtest/lib/ext/activation-1.1.1.jar:/var/jetty/prodtest/lib/ext/HikariCP-4.0.3.jar:/var/jetty/prodtest/lib/ext/log4j-over-slf4j-1.7.36.jar:/var/jetty/prodtest/lib/ext/logback-classic-1.2.11.jar:/var/jetty/prodtest/lib/ext/logback-core-1.2.11.jar:/var/jetty/prodtest/lib/ext/mssql-jdbc-11.2.1.jre11.jar:/var/jetty/prodtest/lib/ext/slf4j-api-1.7.36.jar:/var/jetty/prodtest/resources:/usr/lib/jetty/10.0/lib/logging/slf4j-api-2.0.5.jar:/usr/lib/jetty/10.0/lib/logging/jetty-slf4j-impl-10.0.16.jar:/usr/lib/jetty/10.0/lib/jetty-servlet-api-4.0.6.jar:/usr/lib/jetty/10.0/lib/jetty-http-10.0.16.jar:/usr/lib/jetty/10.0/lib/jetty-server-10.0.16.jar:/usr/lib/jetty/10.0/lib/jetty-xml-10.0.16.jar:/usr/lib/jetty/10.0/lib/jetty-util-10.0.16.jar:/usr/lib/jetty/10.0/lib/jetty-io-10.0.16.jar:/usr/lib/jetty/10.0/lib/jetty-jndi-10.0.16.jar:/usr/lib/jetty/10.0/lib/jetty-security-10.0.16.jar:/usr/lib/jetty/10.0/lib/jetty-servlet-10.0.16.jar:/usr/lib/jetty/10.0/lib/jetty-webapp-10.0.16.jar:/usr/lib/jetty/10.0/lib/jetty-plus-10.0.16.jar:/usr/lib/jetty/10.0/lib/jakarta.transaction-api-1.3.3.jar:/usr/lib/jetty/10.0/lib/jetty-annotations-10.0.16.jar:/usr/lib/jetty/10.0/lib/annotations/asm-9.5.jar:/usr/lib/jetty/10.0/lib/annotations/asm-analysis-9.5.jar:/usr/lib/jetty/10.0/lib/annotations/asm-commons-9.5.jar:/usr/lib/jetty/10.0/lib/annotations/asm-tree-9.5.jar:/usr/lib/jetty/10.0/lib/annotations/jakarta.annotation-api-1.3.5.jar:/usr/lib/jetty/10.0/lib/apache-jsp/org.eclipse.jdt.ecj-3.26.0.jar:/usr/lib/jetty/10.0/lib/apache-jsp/org.eclipse.jetty.apache-jsp-10.0.16.jar:/usr/lib/jetty/10.0/lib/apache-jsp/org.mortbay.jasper.apache-el-9.0.52.jar:/usr/lib/jetty/10.0/lib/apache-jsp/org.mortbay.jasper.apache-jsp-9.0.52.jar:/usr/lib/jetty/10.0/lib/apache-jstl/org.apache.taglibs.taglibs-standard-impl-1.2.5.jar:/usr/lib/jetty/10.0/lib/apache-jstl/org.apache.taglibs.taglibs-standard-spec-1.2.5.jar:/usr/lib/jetty/10.0/lib/jetty-client-10.0.16.jar:/usr/lib/jetty/10.0/lib/jetty-alpn-client-10.0.16.jar:/usr/lib/jetty/10.0/lib/jetty-deploy-10.0.16.jar:/usr/lib/jetty/10.0/lib/websocket/websocket-core-common-10.0.16.jar:/usr/lib/jetty/10.0/lib/websocket/websocket-core-client-10.0.16.jar:/usr/lib/jetty/10.0/lib/websocket/websocket-core-server-10.0.16.jar:/usr/lib/jetty/10.0/lib/websocket/websocket-servlet-10.0.16.jar:/usr/lib/jetty/10.0/lib/websocket/jetty-javax-websocket-api-1.1.2.jar:/usr/lib/jetty/10.0/lib/websocket/websocket-javax-client-10.0.16.jar:/usr/lib/jetty/10.0/lib/websocket/websocket-javax-common-10.0.16.jar:/usr/lib/jetty/10.0/lib/websocket/websocket-javax-server-10.0.16.jar:/usr/lib/jetty/10.0/lib/websocket/websocket-jetty-api-10.0.16.jar:/usr/lib/jetty/10.0/lib/websocket/websocket-jetty-common-10.0.16.jar:/usr/lib/jetty/10.0/lib/websocket/websocket-jetty-server-10.0.16.jar org.eclipse.jetty.xml.XmlConfiguration http.timeout=30000 java.version=11.0.20.1 jetty.base=/var/jetty/prodtest jetty.base.uri=file:///var/jetty/prodtest jetty.dump.start=false jetty.dump.stop=false jetty.home=/usr/lib/jetty/10.0 jetty.home.uri=file:///usr/lib/jetty/10.0 jetty.http.port=8081 jetty.pid=/var/jetty/run/jetty-prodtest.pid jetty.state=/var/jetty/prodtest/jetty-prodtest.state jetty.webapp.addServerClasses=org.eclipse.jetty.logging.,file:///usr/lib/jetty/10.0/lib/logging/,org.slf4j. jsp-impl=apache runtime.feature.alpn=true slf4j.version=2.0.5 threads.max=200 threads.min=10 threads.timeout=60000 /usr/lib/jetty/10.0/etc/jetty-bytebufferpool.xml /usr/lib/jetty/10.0/etc/jetty-threadpool.xml /usr/lib/jetty/10.0/etc/jetty.xml /usr/lib/jetty/10.0/etc/jetty-webapp.xml /usr/lib/jetty/10.0/etc/jetty-deploy.xml /usr/lib/jetty/10.0/etc/jetty-http.xml /usr/lib/jetty/10.0/etc/jetty-http-forwarded.xml /var/jetty/prodtest/etc/jetty-jndi.xml /usr/lib/jetty/10.0/etc/console-capture.xml

Currently running with PID 3171

@joakime
Copy link
Contributor

joakime commented Sep 13, 2023

@gskjold are you running Jetty 10.0.16 with the modified jetty.sh from PR #10501 ? (The org.eclipse.jetty.util.PidFile concept was introduced in 10.0.16, it is not present in 10.0.15 and earlier)

@joakime
Copy link
Contributor

joakime commented Sep 13, 2023

I was able to replicate the behavior you are seeing on amazon-linux with amazon-corretto using the following docker image ...

https://github.com/joakime/jettysh-tests/blob/main/amazoncorretto/Dockerfile

It doesn't run PidFile like ubuntu or fedora does (the docker images for those are also in the above linked repo and work just fine).
I don't yet know why this fails on amazon-linux / amzon-corretto.

Note: the docker images don't use systemd or rc.d / init.d (as that's not really a concept for docker, and is generally discouraged in docker).
I was testing using jetty.sh directly.

@joakime
Copy link
Contributor

joakime commented Sep 13, 2023

Looks like the combination of amazon-linux + start-stop-daemon is not supported (looks like their start-stop-daemon isn't the normal one).
amazon-linux without start-stop-daemon works fine.

To see the debug of PidFile behaviors you can do the following on the docker image in the repo above.

echo "org.eclipse.jetty.util.PidFile.LEVEL=DEBUG" >> /var/www/test/jetty-base/resources/jetty-logging.properties

Now to setup a jetty user and attempt to start it from the root user. (like init.d would)
I want to see if this is a permissions issue.

@gskjold
Copy link
Author

gskjold commented Sep 13, 2023

are you running Jetty 10.0.16 with the modified jetty.sh from PR #10501

Correct

Now to setup a jetty user and attempt to start it from the root user. (like init.d would)
I want to see if this is a permissions issue.

Not entirely sure what you mean by that, but jetty.sh is softlinked into init.d:

# ls -al /etc/init.d/jetty-prodtest 
lrwxrwxrwx 1 root root 32 jan.   9  2023 /etc/init.d/jetty-prodtest -> /usr/lib/jetty/10.0/bin/jetty.sh

I have added your change to logging properties:

# cat /var/jetty/prodtest/resources/jetty-logging.properties 
org.eclipse.jetty.util.PidFile.LEVEL=DEBUG

And when I run service jetty-prodtest start, it returns very quickly after:

# service jetty-prodtest start
WARN  : Use of both ${jetty.base}/start.d and ${jetty.base}/start.ini is deprecated
Starting Jetty: ok Wed Sep 13 16:25:52 CEST 2023
#

Then after a few seconds I get some WARNINGS which I think are unrelated to your issue, and has something to do with one of my applications:

WARNING: An illegal reflective access operation has occurred
WARNING: Illegal reflective access by com.sun.xml.bind.v2.runtime.reflect.opt.Injector (file:/var/jetty/prodtest/work/jetty-0_0_0_0-8081-nkk_war-_nkk-any-/webapp/WEB-INF/lib/jaxb-impl-2.3.0.1.jar) to method java.lang.ClassLoader.defineClass(java.lang.String,byte[],int,int)
WARNING: Please consider reporting this to the maintainers of com.sun.xml.bind.v2.runtime.reflect.opt.Injector
WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
WARNING: All illegal access operations will be denied in a future release

Still nothing about PidFile in the logs...

@joakime
Copy link
Contributor

joakime commented Sep 13, 2023 •
edited
Loading

@gskjold based on your output of service jetty status, the RUN_ARGS shows the following (broken down with line feeds)

RUN_ARGS              =  
  -Djava.io.tmpdir=/tmp 
  -Djetty.home=/usr/lib/jetty/10.0 
  -Djetty.base=/var/jetty/prodtest 
  -Xms64m 
  -Xmx6g 
  -server 
  -Djetty.http.port=8081 
  --class-path 
    /var/jetty/prodtest/lib/ext/activation-1.1.1.jar:
    /var/jetty/prodtest/lib/ext/HikariCP-4.0.3.jar:
    /var/jetty/prodtest/lib/ext/log4j-over-slf4j-1.7.36.jar:
    /var/jetty/prodtest/lib/ext/logback-classic-1.2.11.jar:
    /var/jetty/prodtest/lib/ext/logback-core-1.2.11.jar:
    /var/jetty/prodtest/lib/ext/mssql-jdbc-11.2.1.jre11.jar:
    /var/jetty/prodtest/lib/ext/slf4j-api-1.7.36.jar:
    /var/jetty/prodtest/resources
    /usr/lib/jetty/10.0/lib/logging/slf4j-api-2.0.5.jar
    /usr/lib/jetty/10.0/lib/logging/jetty-slf4j-impl-10.0.16.jar
    /usr/lib/jetty/10.0/lib/jetty-servlet-api-4.0.6.jar
    /usr/lib/jetty/10.0/lib/jetty-http-10.0.16.jar
    /usr/lib/jetty/10.0/lib/jetty-server-10.0.16.jar
    /usr/lib/jetty/10.0/lib/jetty-xml-10.0.16.jar
    /usr/lib/jetty/10.0/lib/jetty-util-10.0.16.jar
    /usr/lib/jetty/10.0/lib/jetty-io-10.0.16.jar
    /usr/lib/jetty/10.0/lib/jetty-jndi-10.0.16.jar
    /usr/lib/jetty/10.0/lib/jetty-security-10.0.16.jar
    /usr/lib/jetty/10.0/lib/jetty-servlet-10.0.16.jar
    /usr/lib/jetty/10.0/lib/jetty-webapp-10.0.16.jar
    /usr/lib/jetty/10.0/lib/jetty-plus-10.0.16.jar
    /usr/lib/jetty/10.0/lib/jakarta.transaction-api-1.3.3.jar
    /usr/lib/jetty/10.0/lib/jetty-annotations-10.0.16.jar
    /usr/lib/jetty/10.0/lib/annotations/asm-9.5.jar
    /usr/lib/jetty/10.0/lib/annotations/asm-analysis-9.5.jar
    /usr/lib/jetty/10.0/lib/annotations/asm-commons-9.5.jar
    /usr/lib/jetty/10.0/lib/annotations/asm-tree-9.5.jar
    /usr/lib/jetty/10.0/lib/annotations/jakarta.annotation-api-1.3.5.jar
    /usr/lib/jetty/10.0/lib/apache-jsp/org.eclipse.jdt.ecj-3.26.0.jar
    /usr/lib/jetty/10.0/lib/apache-jsp/org.eclipse.jetty.apache-jsp-10.0.16.jar
    /usr/lib/jetty/10.0/lib/apache-jsp/org.mortbay.jasper.apache-el-9.0.52.jar
    /usr/lib/jetty/10.0/lib/apache-jsp/org.mortbay.jasper.apache-jsp-9.0.52.jar
    /usr/lib/jetty/10.0/lib/apache-jstl/org.apache.taglibs.taglibs-standard-impl-1.2.5.jar
    /usr/lib/jetty/10.0/lib/apache-jstl/org.apache.taglibs.taglibs-standard-spec-1.2.5.jar
    /usr/lib/jetty/10.0/lib/jetty-client-10.0.16.jar
    /usr/lib/jetty/10.0/lib/jetty-alpn-client-10.0.16.jar
    /usr/lib/jetty/10.0/lib/jetty-deploy-10.0.16.jar
    /usr/lib/jetty/10.0/lib/websocket/websocket-core-common-10.0.16.jar
    /usr/lib/jetty/10.0/lib/websocket/websocket-core-client-10.0.16.jar
    /usr/lib/jetty/10.0/lib/websocket/websocket-core-server-10.0.16.jar
    /usr/lib/jetty/10.0/lib/websocket/websocket-servlet-10.0.16.jar
    /usr/lib/jetty/10.0/lib/websocket/jetty-javax-websocket-api-1.1.2.jar
    /usr/lib/jetty/10.0/lib/websocket/websocket-javax-client-10.0.16.jar
    /usr/lib/jetty/10.0/lib/websocket/websocket-javax-common-10.0.16.jar
    /usr/lib/jetty/10.0/lib/websocket/websocket-javax-server-10.0.16.jar
    /usr/lib/jetty/10.0/lib/websocket/websocket-jetty-api-10.0.16.jar
    /usr/lib/jetty/10.0/lib/websocket/websocket-jetty-common-10.0.16.jar
    /usr/lib/jetty/10.0/lib/websocket/websocket-jetty-server-10.0.16.jar 
  org.eclipse.jetty.xml.XmlConfiguration
  http.timeout=30000
  java.version=11.0.20.1
  jetty.base=/var/jetty/prodtest
  jetty.base.uri=file:///var/jetty/prodtest
  jetty.dump.start=false
  jetty.dump.stop=false
  jetty.home=/usr/lib/jetty/10.0
  jetty.home.uri=file:///usr/lib/jetty/10.0
  jetty.http.port=8081
  jetty.pid=/var/jetty/run/jetty-prodtest.pid
  jetty.state=/var/jetty/prodtest/jetty-prodtest.state
  jetty.webapp.addServerClasses=org.eclipse.jetty.logging.,file:///usr/lib/jetty/10.0/lib/logging/,org.slf4j. 
  jsp-impl=apache
  runtime.feature.alpn=true
  slf4j.version=2.0.5
  threads.max=200
  threads.min=10
  threads.timeout=60000
  /usr/lib/jetty/10.0/etc/jetty-bytebufferpool.xml
  /usr/lib/jetty/10.0/etc/jetty-threadpool.xml
  /usr/lib/jetty/10.0/etc/jetty.xml
  /usr/lib/jetty/10.0/etc/jetty-webapp.xml
  /usr/lib/jetty/10.0/etc/jetty-deploy.xml
  /usr/lib/jetty/10.0/etc/jetty-http.xml
  /usr/lib/jetty/10.0/etc/jetty-http-forwarded.xml
  /var/jetty/prodtest/etc/jetty-jndi.xml
  /usr/lib/jetty/10.0/etc/console-capture.xml

This seems to indicate that you are not using a pristene Jetty 10.0.16 for your jetty-home directory.

I say this because the output of that status call should show entries for ${JETTY_HOME}/etc/jetty-pid.xml and ${JETTY_HOME}/etc/jetty-state.xml, which your version does not.

There's some conflicting files in your JETTY_BASE as well.

    /var/jetty/prodtest/lib/ext/log4j-over-slf4j-1.7.36.jar:
    /var/jetty/prodtest/lib/ext/logback-classic-1.2.11.jar:
    /var/jetty/prodtest/lib/ext/logback-core-1.2.11.jar:
    /var/jetty/prodtest/lib/ext/slf4j-api-1.7.36.jar:

Remove sfl4j-api, logback-core, logback-classic, and log4j-over-slf4j jars.
Add the logging-logback and logging-log4j1-capture modules instead.

cd /var/jetty/prodtest
java -jar /usr/lib/jetty/10.0/start.jar --add-to-startd=logging-logback,logging-log4j1-capture

Because you are not using the module system ...

  • you have a conflict with your slf4j-api jar, you have 2 present on your server classpath (slf4j-api-1.7.36.jar and slf4j-api-2.0.5.jar)
  • you have a conflict with your 2 slf4j implementation jars (logback-classic, and jetty-slf4j-impl) on your server classpath
  • you have console-capture.xml present, due to the default behavior of logging, which can easily cause logging feedback loops with a full blown logging implementation (like logback)

This configuration likely came from when you were using Java 8 and Jetty 9.
It should be cleaned up now.

Unpack a fresh copy of jetty-home, in a new directory, and use it (important: do not modify any contents in the jetty-home directory, consider it read-only).
When you test new versions of Jetty, don't overwrite the old jetty-home directory, use a new directory each time.
It's common to setup a symlink to the "active" jetty-home and just use the symlink everywhere.

You'll need to ensure the following to test this new jetty-home.

  • the symlink in /etc/init.d/jetty-prodtest points to the correct place.
  • the location of the JETTY_HOME variable in your /etc/default/jetty-prodtest file

If you still do not see a pid file, verify that your ${JETTY_HOME}/etc/jetty.conf looks like this ...
https://github.com/eclipse/jetty.project/blob/jetty-10.0.x/jetty-home/src/main/resources/etc/jetty.conf

And verify that the output of service jetty status shows the jetty-pid.xml and jetty-state.xml entries in your RUN_ARGS

@joakime
Copy link
Contributor

joakime commented Sep 13, 2023

@l-cdc I intentionally setup an environment which will trigger permissions issues with PidFile.

It will result in the following output, and will fail to start Jetty.
So I feel we have this case covered, as long as the PidFile option actually attempts to run.

Starting Jetty: ok Wed Sep 13 15:01:32 UTC 2023
2023-09-13 15:01:32.399: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:///var/www/test/jetty-home-10.0.16/etc/jetty-pid.xml
2023-09-13 15:01:32.403: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)
Caused by: 
java.nio.file.AccessDeniedException: /var/www/test/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)
Exception in thread "main" 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)
Caused by: java.nio.file.AccessDeniedException: /var/www/test/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)
	... 11 more

@gskjold
Copy link
Author

gskjold commented Sep 13, 2023

You are absolutely right about that, I have preserved too much of the original configuration from jetty-9.4. Thanks for pointing this out, I should have caught on to that... It is a good while back that I did the upgrade, but no errors have been thrown until the pgrep issue.

Everything is working correctly now, together with the updated jetty.sh file from your PR. Thank you for a excellent followup on this issue!

@joakime
Copy link
Contributor

joakime commented Sep 13, 2023

@gskjold @l-cdc it seems that both of you are happy with the changes in PR #10501, am I right in that assumption?

@ofrias have you had a chance to test the updated jetty.sh in that PR? (you can use the normal 10.0.16 jetty-home, and just copy over the bin/jetty.sh from the PR to test it)

Here's some links to the jetty.sh from the PR branch.

@gskjold
Copy link
Author

gskjold commented Sep 13, 2023

I can confirm from my side

Just updated two servers (Running 9 instances of jetty in total) with the patched jetty.sh, and it they are all functioning as they should

@ofrias
Copy link

ofrias commented Sep 13, 2023

Hi. I don't think I have the same issue. In my case the jetty.pid is correctly filled in every time I start Jetty even when using the jetty.sh file shipped with 10.0.16. My problem is that Jetty immediately stops without printing or logging any error. If I go back to 10.0.15 everything works OK.

How can I enable some kind of logging to see what's happening?

By the way, I don't know if this is related to my issue or not, but Jetty 10.0.15 prints an uppercase OK:

# /usr/local/jetty/bin/jetty.sh start
Starting Jetty: . . OK Wed Sep 13 09:26:46 AM CEST 2023

whiel Jetty 10.0.16 prints a lowercase ok:

# /usr/local/jetty/bin/jetty.sh start
Starting Jetty: ok Wed Sep 13 09:31:15 AM CEST 2023

And this is because they are going through different execution paths in this code in jetty.sh:

    if expr "${JETTY_ARGS[*]}" : '.*jetty-started.xml.*' >/dev/null
    then
      if started "$JETTY_STATE" "$JETTY_PID" "$JETTY_START_TIMEOUT"
      then
        echo "OK `date`"
      else
        echo "FAILED `date`"
        exit 1
      fi
    else
      echo "ok `date`"
    fi

It seems that jetty-started.xml is no longer present in 10.0.16 so maybe this code is obsolete (don't know if this is related to my issue or not).

@joakime
Copy link
Contributor

joakime commented Sep 13, 2023

It seems that jetty-started.xml is no longer present in 10.0.16 so maybe this code is obsolete (don't know if this is related to my issue or not).

That is a good point, I'll address this in PR #10501 too.

joakime added a commit that referenced this issue Sep 13, 2023
@joakime
Issue #10473 - Remove URL usage
b638c36
@joakime
Copy link
Contributor

joakime commented Sep 13, 2023

@ofrias the change for the name change of jetty-started.xml to jetty-state.xml is now in the PR #10501

See commit 069b027

Can you see if this helps you?

@joakime
Copy link
Contributor

joakime commented Sep 21, 2023

@ofrias i've added a bunch of cleanup on jetty.sh to add DEBUG and clear messages on the state check and pid related behaviors.

New SNAPSHOT tarball can be found at ...

https://oss.sonatype.org/content/repositories/jetty-snapshots/org/eclipse/jetty/jetty-home/10.0.17-SNAPSHOT/jetty-home-10.0.17-20230921.215746-22.tar.gz

I've tested this SNAPSHOT successfully on the 3 docker images at https://github.com/joakime/jettysh-tests

  • jetty.sh -d start
  • with basic config of jetty-base
  • with demo webapps
  • with setuid
  • with requestlog
  • with your requestlog configuration

No issues on ubuntu, fedora, and amazon-corretto.
Works as intended and expected.

@ofrias
Copy link

ofrias commented Sep 22, 2023

This is the output with the last SNAPSHOT:

# /usr/local/jetty/bin/jetty.sh -d start
Reading /etc/default/jetty..
JAVA                  =  /usr/local/java/bin/java
JAVA_OPTIONS          =  
JETTY_HOME            =  /usr/local/jetty
JETTY_BASE            =  /srv/www.myweb.com/jetty
START_D               =  /srv/www.myweb.com/jetty/start.d
START_INI             =  /srv/www.myweb.com/jetty/start.ini
JETTY_START           =  /usr/local/jetty/start.jar
JETTY_CONF            =  /usr/local/jetty/etc/jetty.conf
JETTY_ARGS            =  jetty.state=/srv/www.myweb.com/jetty/jetty.state jetty.pid=/run/jetty/jetty.pid --module=pid,state
JETTY_RUN             =  /var/run/jetty
JETTY_PID             =  /run/jetty/jetty.pid
JETTY_START_LOG       =  /srv/www.myweb.com/jetty/logs/start.log
JETTY_STATE           =  /srv/www.myweb.com/jetty/jetty.state
JETTY_START_TIMEOUT   =  60
JETTY_SYS_PROPS       =  
RUN_ARGS              =  -Djava.io.tmpdir=/tmp -Djetty.home=/usr/local/jetty-home-10.0.17-SNAPSHOT -Djetty.base=/srv/www.myweb.com/jetty --class-path /srv/www.myweb.com/jetty/lib/ext/HikariCP-5.0.1.jar:/srv/www.myweb.com/jetty/lib/ext/mysql-connector-j-8.1.0.jar:/srv/www.myweb.com/jetty/lib/ext/postgresql-42.6.0.jar:/srv/www.myweb.com/jetty/resources:/usr/local/jetty-home-10.0.17-SNAPSHOT/lib/logging/slf4j-api-2.0.5.jar:/usr/local/jetty-home-10.0.17-SNAPSHOT/lib/logging/jetty-slf4j-impl-10.0.17-SNAPSHOT.jar:/usr/local/jetty-home-10.0.17-SNAPSHOT/lib/jetty-servlet-api-4.0.6.jar:/usr/local/jetty-home-10.0.17-SNAPSHOT/lib/jetty-http-10.0.17-SNAPSHOT.jar:/usr/local/jetty-home-10.0.17-SNAPSHOT/lib/jetty-server-10.0.17-SNAPSHOT.jar:/usr/local/jetty-home-10.0.17-SNAPSHOT/lib/jetty-xml-10.0.17-SNAPSHOT.jar:/usr/local/jetty-home-10.0.17-SNAPSHOT/lib/jetty-util-10.0.17-SNAPSHOT.jar:/usr/local/jetty-home-10.0.17-SNAPSHOT/lib/jetty-io-10.0.17-SNAPSHOT.jar:/usr/local/jetty-home-10.0.17-SNAPSHOT/lib/jetty-jndi-10.0.17-SNAPSHOT.jar:/usr/local/jetty-home-10.0.17-SNAPSHOT/lib/jetty-security-10.0.17-SNAPSHOT.jar:/usr/local/jetty-home-10.0.17-SNAPSHOT/lib/jetty-servlet-10.0.17-SNAPSHOT.jar:/usr/local/jetty-home-10.0.17-SNAPSHOT/lib/jetty-webapp-10.0.17-SNAPSHOT.jar:/usr/local/jetty-home-10.0.17-SNAPSHOT/lib/jetty-plus-10.0.17-SNAPSHOT.jar:/usr/local/jetty-home-10.0.17-SNAPSHOT/lib/jakarta.transaction-api-1.3.3.jar:/usr/local/jetty-home-10.0.17-SNAPSHOT/lib/jetty-annotations-10.0.17-SNAPSHOT.jar:/usr/local/jetty-home-10.0.17-SNAPSHOT/lib/annotations/asm-9.5.jar:/usr/local/jetty-home-10.0.17-SNAPSHOT/lib/annotations/asm-analysis-9.5.jar:/usr/local/jetty-home-10.0.17-SNAPSHOT/lib/annotations/asm-commons-9.5.jar:/usr/local/jetty-home-10.0.17-SNAPSHOT/lib/annotations/asm-tree-9.5.jar:/usr/local/jetty-home-10.0.17-SNAPSHOT/lib/annotations/jakarta.annotation-api-1.3.5.jar:/usr/local/jetty-home-10.0.17-SNAPSHOT/lib/apache-jsp/org.eclipse.jdt.ecj-3.26.0.jar:/usr/local/jetty-home-10.0.17-SNAPSHOT/lib/apache-jsp/org.eclipse.jetty.apache-jsp-10.0.17-SNAPSHOT.jar:/usr/local/jetty-home-10.0.17-SNAPSHOT/lib/apache-jsp/org.mortbay.jasper.apache-el-9.0.52.jar:/usr/local/jetty-home-10.0.17-SNAPSHOT/lib/apache-jsp/org.mortbay.jasper.apache-jsp-9.0.52.jar:/usr/local/jetty-home-10.0.17-SNAPSHOT/lib/jetty-deploy-10.0.17-SNAPSHOT.jar:/usr/local/jetty-home-10.0.17-SNAPSHOT/lib/http2/http2-common-10.0.17-SNAPSHOT.jar:/usr/local/jetty-home-10.0.17-SNAPSHOT/lib/http2/http2-hpack-10.0.17-SNAPSHOT.jar:/usr/local/jetty-home-10.0.17-SNAPSHOT/lib/http2/http2-server-10.0.17-SNAPSHOT.jar:/usr/local/jetty-home-10.0.17-SNAPSHOT/lib/jetty-servlets-10.0.17-SNAPSHOT.jar:/usr/local/jetty-home-10.0.17-SNAPSHOT/lib/setuid/jetty-setuid-java-1.0.4.jar org.eclipse.jetty.xml.XmlConfiguration db-connection-type=datasource java.version=11.0.20.1 jetty.base=/srv/www.myweb.com/jetty jetty.base.uri=file:///srv/www.myweb.com/jetty jetty.console-capture.retainDays=2 jetty.home=/usr/local/jetty-home-10.0.17-SNAPSHOT jetty.home.uri=file:///usr/local/jetty-home-10.0.17-SNAPSHOT jetty.http.idleTimeout=150000 jetty.http.port=8081 jetty.http2.rateControl.maxEventsPerSecond=60 jetty.httpConfig.forwardedOnly=true jetty.httpConfig.sendServerVersion=false jetty.pid=/run/jetty/jetty.pid jetty.requestlog.formatString=\''%{client}a - %u %t "%r" %s %O "%{Referer}i" "%{User-Agent}i" %{X-Forwarded-Proto}i://%{server}a'\' jetty.server.stopAtShutdown=true jetty.sessionIdManager.workerName=arya jetty.setuid.umask=002 jetty.state=/srv/www.myweb.com/jetty/jetty.state jetty.threadPool.maxThreads=1000 jetty.webapp.addServerClasses=org.eclipse.jetty.logging.,file:///usr/local/jetty-home-10.0.17-SNAPSHOT/lib/logging/,org.slf4j. runtime.feature.alpn=true slf4j.version=2.0.5 /usr/local/jetty-home-10.0.17-SNAPSHOT/etc/jetty-bytebufferpool.xml /usr/local/jetty-home-10.0.17-SNAPSHOT/etc/jetty-pid.xml /usr/local/jetty-home-10.0.17-SNAPSHOT/etc/jetty-threadpool.xml /usr/local/jetty-home-10.0.17-SNAPSHOT/etc/jetty.xml /usr/local/jetty-home-10.0.17-SNAPSHOT/etc/jetty-webapp.xml /usr/local/jetty-home-10.0.17-SNAPSHOT/etc/console-capture.xml /usr/local/jetty-home-10.0.17-SNAPSHOT/etc/jetty-state.xml /srv/www.myweb.com/jetty/etc/jetty-deploy.xml /usr/local/jetty-home-10.0.17-SNAPSHOT/etc/jetty-gzip.xml /usr/local/jetty-home-10.0.17-SNAPSHOT/etc/jetty-http.xml /usr/local/jetty-home-10.0.17-SNAPSHOT/etc/jetty-http2c.xml /usr/local/jetty-home-10.0.17-SNAPSHOT/etc/jetty-http-forwarded.xml /usr/local/jetty-home-10.0.17-SNAPSHOT/etc/jetty-requestlog.xml /usr/local/jetty-home-10.0.17-SNAPSHOT/etc/sessions/id-manager.xml /usr/local/jetty-home-10.0.17-SNAPSHOT/etc/sessions/jdbc/datasource.xml /usr/local/jetty-home-10.0.17-SNAPSHOT/etc/sessions/jdbc/session-store.xml /usr/local/jetty-home-10.0.17-SNAPSHOT/etc/jetty-setuid.xml /srv/www.myweb.com/jetty/etc/myweb.xml
Starting Jetty: Unable to read State File: /srv/www.myweb.com/jetty/jetty.state
:Unable to read State File: /srv/www.myweb.com/jetty/jetty.state
:Unable to read State File: /srv/www.myweb.com/jetty/jetty.state
:Unable to read State File: /srv/www.myweb.com/jetty/jetty.state
:Unable to read State File: /srv/www.myweb.com/jetty/jetty.state
:Unable to read State File: /srv/www.myweb.com/jetty/jetty.state
:Unable to read State File: /srv/www.myweb.com/jetty/jetty.state
:Unable to read State File: /srv/www.myweb.com/jetty/jetty.state
:Unable to read State File: /srv/www.myweb.com/jetty/jetty.state
:Unable to read State File: /srv/www.myweb.com/jetty/jetty.state
:Unable to read State File: /srv/www.myweb.com/jetty/jetty.state
:Unable to read State File: /srv/www.myweb.com/jetty/jetty.state
:Unable to read State File: /srv/www.myweb.com/jetty/jetty.state
:Unable to read State File: /srv/www.myweb.com/jetty/jetty.state
:Unable to read State File: /srv/www.myweb.com/jetty/jetty.state
:FAILED Fri Sep 22 08:53:26 AM CEST 2023

While jetty.sh was trying to read the state file I did a ps and no java process was running:

$ ps aux |grep java
myuser   1584114  0.0  0.0   9436  2300 pts/2    S+   08:52   0:00 grep --color=auto java

So it looks like something fails during the start and the process ends without doing its job, there is no need to wait for more time because the process has already finished.

With regard to JETTY_START_TIMEOUT, I have not manually configured it. It looks like 60 seconds is the default:

if [ -z "$JETTY_START_TIMEOUT" ]
then
  JETTY_START_TIMEOUT=60
fi

@joakime
Copy link
Contributor

joakime commented Sep 25, 2023 •
edited
Loading

@ofrias there's no evidence of the Jetty side startup even being attempted.

I'll need logs.

First, remove any logs you have in /srv/www.myweb.com/jetty/logs/.
Then make sure your /srv/www.myweb.com/jetty/resources/jetty-logging.properties has only 1 line in it.

org.eclipse.jetty.LEVEL=DEBUG

Then run your jetty.sh command again.
Can you gzip + attach your logs in /srv/www.myweb.com/jetty/logs/ on this issue (drag-n-drop the gzip into a issue comment and github will attach it)

@joakime
Copy link
Contributor

joakime commented Sep 25, 2023

@ofrias separately, can you run your jetty.base without jetty.sh once to see if it can startup?

$ 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

joakime added a commit that referenced this issue Sep 26, 2023
@joakime
Issue #10473 - Revert jetty.sh pgrep, and update started checks (#10501)
cc8f976 
* Revert pgrep usage in jetty.sh
* Adding test for jetty.conf
* Correcting renamed xml file
* Improved started check
+ Improved `started` function code
  - adding comment explaining steps
  - adding named parameters
+ Improved ARGS check for "jetty.state="
  option, to know when to check the
  state file.
* Make sure state.mod is before any deploy steps to ensure jetty-state file is created early.
* Early cleanup / creation of State file
* Improved `started` function
+ Don't attempt to read from State File
  if it doesn't exist
+ Don't attempt to read from PID File
  if it doesn't exist
+ DEBUG in state file logic
+ DEBUG in pid file logic
+ proper startsWith logic for state detection
* Better state debugging and pid kill

Signed-off-by: Joakim Erdfelt <[email protected]>
@ofrias
Copy link

ofrias commented Sep 27, 2023

First, remove any logs you have in /srv/www.myweb.com/jetty/logs/. Then make sure your /srv/www.myweb.com/jetty/resources/jetty-logging.properties has only 1 line in it.

org.eclipse.jetty.LEVEL=DEBUG

Then run your jetty.sh command again. Can you gzip + attach your logs in /srv/www.myweb.com/jetty/logs/ on this issue (drag-n-drop the gzip into a issue comment and github will attach it)

Same output in the console and nothing is written in /srv/www.myweb.com/jetty/logs/

@ofrias separately, can you run your jetty.base without jetty.sh once to see if it can startup?

$ 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

Yes, it starts successfully when running this command. This is the console output:

# /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 13:51:23.844:DEBUG:oejx.XmlConfiguration:main: args=[/tmp/start_1657379945697683946.properties, /usr/local/jetty-home-10.0.17-SNAPSHOT/etc/jetty-bytebufferpool.xml, /usr/local/jetty-home-10.0.17-SNAPSHOT/etc/jetty-pid.xml, /usr/local/jetty-home-10.0.17-SNAPSHOT/etc/jetty-threadpool.xml, /usr/local/jetty-home-10.0.17-SNAPSHOT/etc/jetty.xml, /usr/local/jetty-home-10.0.17-SNAPSHOT/etc/jetty-webapp.xml, /usr/local/jetty-home-10.0.17-SNAPSHOT/etc/console-capture.xml, /usr/local/jetty-home-10.0.17-SNAPSHOT/etc/jetty-state.xml, /srv/www.myweb.com/jetty/etc/jetty-deploy.xml, /usr/local/jetty-home-10.0.17-SNAPSHOT/etc/jetty-gzip.xml, /usr/local/jetty-home-10.0.17-SNAPSHOT/etc/jetty-http.xml, /usr/local/jetty-home-10.0.17-SNAPSHOT/etc/jetty-http2c.xml, /usr/local/jetty-home-10.0.17-SNAPSHOT/etc/jetty-http-forwarded.xml, /usr/local/jetty-home-10.0.17-SNAPSHOT/etc/jetty-requestlog.xml, /usr/local/jetty-home-10.0.17-SNAPSHOT/etc/sessions/id-manager.xml, /usr/local/jetty-home-10.0.17-SNAPSHOT/etc/sessions/jdbc/datasource.xml, /usr/local/jetty-home-10.0.17-SNAPSHOT/etc/sessions/jdbc/session-store.xml, /usr/local/jetty-home-10.0.17-SNAPSHOT/etc/jetty-setuid.xml, /srv/www.myweb.com/jetty/etc/myweb.xml]
2023-09-27 13:51:23.855:DEBUG:oeju.Pool:main: Pool@60611244[inUse=0,size=1,max=8,closed=false] returning new reserved entry MonoEntry@1a0dcaa{PENDING,pooled=null}
2023-09-27 13:51:23.879:DEBUG:oejx.XmlParser:main: parsing: sid=null,pid=null
2023-09-27 13:51:23.896:DEBUG:oejx.XmlParser:main: resolveEntity(-//Jetty//Configure//EN,https://www.eclipse.org/jetty/configure_10_0.dtd)
2023-09-27 13:51:23.896:DEBUG:oejx.XmlParser:main: Redirected entity https://www.eclipse.org/jetty/configure_10_0.dtd  --> jar:file:/usr/local/jetty-home-10.0.17-SNAPSHOT/lib/jetty-xml-10.0.17-SNAPSHOT.jar!/org/eclipse/jetty/xml/configure_10_0.dtd
2023-09-27 13:51:23.909:DEBUG:oejx.XmlConfiguration:main: Configure file:///usr/local/jetty-home-10.0.17-SNAPSHOT/etc/jetty-bytebufferpool.xml
2023-09-27 13:51:23.909:DEBUG:oejx.XmlConfiguration:main: Configure null null
2023-09-27 13:51:23.910:DEBUG:oejx.XmlConfiguration:main: XML new org.eclipse.jetty.io.ArrayByteBufferPool
2023-09-27 13:51:23.916:DEBUG:oejx.XmlParser:main: parsing: sid=null,pid=null
2023-09-27 13:51:23.917:DEBUG:oejx.XmlParser:main: resolveEntity(-//Jetty//Configure//EN,https://www.eclipse.org/jetty/configure_10_0.dtd)
2023-09-27 13:51:23.917:DEBUG:oejx.XmlParser:main: Redirected entity https://www.eclipse.org/jetty/configure_10_0.dtd  --> jar:file:/usr/local/jetty-home-10.0.17-SNAPSHOT/lib/jetty-xml-10.0.17-SNAPSHOT.jar!/org/eclipse/jetty/xml/configure_10_0.dtd
2023-09-27 13:51:23.921:DEBUG:oejx.XmlConfiguration:main: Configure file:///usr/local/jetty-home-10.0.17-SNAPSHOT/etc/jetty-pid.xml
2023-09-27 13:51:23.921:DEBUG:oejx.XmlConfiguration:main: Configure null null
2023-09-27 13:51:23.921:DEBUG:oejx.XmlConfiguration:main: XML call create
2023-09-27 13:51:23.934:DEBUG:oeju.PidFile:main: PID file: /run/jetty/jetty.pid
2023-09-27 13:51:23.934:DEBUG:oejx.XmlParser:main: parsing: sid=null,pid=null
2023-09-27 13:51:23.935:DEBUG:oejx.XmlParser:main: resolveEntity(-//Jetty//Configure//EN,https://www.eclipse.org/jetty/configure_10_0.dtd)
2023-09-27 13:51:23.935:DEBUG:oejx.XmlParser:main: Redirected entity https://www.eclipse.org/jetty/configure_10_0.dtd  --> jar:file:/usr/local/jetty-home-10.0.17-SNAPSHOT/lib/jetty-xml-10.0.17-SNAPSHOT.jar!/org/eclipse/jetty/xml/configure_10_0.dtd
2023-09-27 13:51:23.939:DEBUG:oejx.XmlConfiguration:main: Configure file:///usr/local/jetty-home-10.0.17-SNAPSHOT/etc/jetty-threadpool.xml
2023-09-27 13:51:23.939:DEBUG:oejx.XmlConfiguration:main: Configure null null
2023-09-27 13:51:23.939:DEBUG:oejx.XmlConfiguration:main: XML new org.eclipse.jetty.util.thread.QueuedThreadPool
2023-09-27 13:51:23.951:DEBUG:oejuc.ContainerLifeCycle:main: QueuedThreadPool[qtp1020520290]@3cd3e762{STOPPED,8<=0<=200,i=0,r=-1,t=-708872648ms,q=0}[NO_TRY] added {org.eclipse.jetty.util.thread.ThreadPoolBudget@752325ad,POJO}
2023-09-27 13:51:23.954:DEBUG:oejx.XmlConfiguration:main: XML QueuedThreadPool[qtp1020520290]@3cd3e762{STOPPED,8<=0<=200,i=0,r=-1,t=-708872652ms,q=0}[NO_TRY].setMinThreads (10)
2023-09-27 13:51:23.955:DEBUG:oejx.XmlConfiguration:main: XML QueuedThreadPool[qtp1020520290]@3cd3e762{STOPPED,10<=0<=200,i=0,r=-1,t=-708872653ms,q=0}[NO_TRY].setMaxThreads (1000)
2023-09-27 13:51:23.958:DEBUG:oejx.XmlConfiguration:main: XML QueuedThreadPool[qtp1020520290]@3cd3e762{STOPPED,10<=0<=1000,i=0,r=-1,t=-708872655ms,q=0}[NO_TRY].setReservedThreads (-1)
2023-09-27 13:51:23.958:DEBUG:oejx.XmlConfiguration:main: XML QueuedThreadPool[qtp1020520290]@3cd3e762{STOPPED,10<=0<=1000,i=0,r=-1,t=-708872655ms,q=0}[NO_TRY].setIdleTimeout (60000)
2023-09-27 13:51:23.958:DEBUG:oejx.XmlConfiguration:main: XML QueuedThreadPool[qtp1020520290]@3cd3e762{STOPPED,10<=0<=1000,i=0,r=-1,t=-708872656ms,q=0}[NO_TRY].setMaxEvictCount (1)
2023-09-27 13:51:23.959:DEBUG:oejx.XmlConfiguration:main: XML QueuedThreadPool[qtp1020520290]@3cd3e762{STOPPED,10<=0<=1000,i=0,r=-1,t=-708872656ms,q=0}[NO_TRY].setDetailedDump (false)
2023-09-27 13:51:23.959:DEBUG:oejx.XmlParser:main: parsing: sid=null,pid=null
2023-09-27 13:51:23.960:DEBUG:oejx.XmlParser:main: resolveEntity(-//Jetty//Configure//EN,https://www.eclipse.org/jetty/configure_10_0.dtd)
2023-09-27 13:51:23.960:DEBUG:oejx.XmlParser:main: Redirected entity https://www.eclipse.org/jetty/configure_10_0.dtd  --> jar:file:/usr/local/jetty-home-10.0.17-SNAPSHOT/lib/jetty-xml-10.0.17-SNAPSHOT.jar!/org/eclipse/jetty/xml/configure_10_0.dtd
2023-09-27 13:51:23.966:DEBUG:oejx.XmlConfiguration:main: Configure file:///usr/local/jetty-home-10.0.17-SNAPSHOT/etc/jetty.xml
2023-09-27 13:51:23.971:DEBUG:oejx.XmlConfiguration:main: Configure class org.eclipse.jetty.server.Server null
2023-09-27 13:51:23.977:DEBUG:oejuc.ContainerLifeCycle:main: Server@7c83dc97{STOPPED}[10.0.17-SNAPSHOT,sto=0] added {QueuedThreadPool[qtp1020520290]@3cd3e762{STOPPED,10<=0<=1000,i=0,r=-1,t=-708872676ms,q=0}[NO_TRY],AUTO}
2023-09-27 13:51:23.979:DEBUG:oejuc.ContainerLifeCycle:main: Server@7c83dc97{STOPPED}[10.0.17-SNAPSHOT,sto=0] added {AttributeContainerMap@568ff82{size=0},AUTO}
2023-09-27 13:51:23.979:DEBUG:oejx.XmlConfiguration:main: XML call addBean
2023-09-27 13:51:23.986:DEBUG:oejuc.ContainerLifeCycle:main: Server@7c83dc97{STOPPED}[10.0.17-SNAPSHOT,sto=0] added {ArrayByteBufferPool@3315d2d7{minBufferCapacity=0, maxBufferCapacity=65536, maxQueueLength=-1, factor=4096},POJO}
2023-09-27 13:51:23.987:DEBUG:oejx.XmlConfiguration:main: XML call addBean
2023-09-27 13:51:23.987:DEBUG:oejx.XmlConfiguration:main: XML new org.eclipse.jetty.util.thread.ScheduledExecutorScheduler
2023-09-27 13:51:23.988:DEBUG:oejuc.ContainerLifeCycle:main: Server@7c83dc97{STOPPED}[10.0.17-SNAPSHOT,sto=0] added {ScheduledExecutorScheduler@4da4253{STOPPED},AUTO}
2023-09-27 13:51:23.988:DEBUG:oejx.XmlConfiguration:main: XML new org.eclipse.jetty.server.HttpConfiguration
2023-09-27 13:51:24.000:DEBUG:oejx.XmlConfiguration:main: XML HttpConfiguration@3fb1549b{32768/8192,8192/8192,https://:0,[]}.setSendServerVersion (false)
2023-09-27 13:51:24.000:DEBUG:oejx.XmlConfiguration:main: XML HttpConfiguration@3fb1549b{32768/8192,8192/8192,https://:0,[]}.setSendDateHeader (false)
2023-09-27 13:51:24.000:DEBUG:oejx.XmlConfiguration:main: XML call from
2023-09-27 13:51:24.001:DEBUG:oejx.XmlConfiguration:main: XML HttpConfiguration@3fb1549b{32768/8192,8192/8192,https://:0,[]}.setHttpCompliance (CUSTOM0[])
2023-09-27 13:51:24.001:DEBUG:oejx.XmlConfiguration:main: XML call from
2023-09-27 13:51:24.001:DEBUG:oejh.UriCompliance:main: UriCompliance from SAFE->CUSTOM0[AMBIGUOUS_PATH_SEPARATOR, AMBIGUOUS_PATH_ENCODING]
2023-09-27 13:51:24.001:DEBUG:oejx.XmlConfiguration:main: XML HttpConfiguration@3fb1549b{32768/8192,8192/8192,https://:0,[]}.setUriCompliance (CUSTOM0[AMBIGUOUS_PATH_SEPARATOR, AMBIGUOUS_PATH_ENCODING])
2023-09-27 13:51:24.002:DEBUG:oejx.XmlConfiguration:main: XML call from
2023-09-27 13:51:24.002:DEBUG:oejh.CookieCompliance:main: CookieCompliance from RFC6265->RFC6265@49c7b90e[INVALID_COOKIES, OPTIONAL_WHITE_SPACE, SPACE_IN_VALUES]
2023-09-27 13:51:24.002:DEBUG:oejx.XmlConfiguration:main: XML HttpConfiguration@3fb1549b{32768/8192,8192/8192,https://:0,[]}.setRequestCookieCompliance (RFC6265@49c7b90e[INVALID_COOKIES, OPTIONAL_WHITE_SPACE, SPACE_IN_VALUES])
2023-09-27 13:51:24.002:DEBUG:oejx.XmlConfiguration:main: XML call from
2023-09-27 13:51:24.002:DEBUG:oejh.CookieCompliance:main: CookieCompliance from RFC6265->RFC6265@49c7b90e[INVALID_COOKIES, OPTIONAL_WHITE_SPACE, SPACE_IN_VALUES]
2023-09-27 13:51:24.002:DEBUG:oejx.XmlConfiguration:main: XML HttpConfiguration@3fb1549b{32768/8192,8192/8192,https://:0,[]}.setResponseCookieCompliance (RFC6265@49c7b90e[INVALID_COOKIES, OPTIONAL_WHITE_SPACE, SPACE_IN_VALUES])
2023-09-27 13:51:24.003:DEBUG:oejx.XmlConfiguration:main: XML call valueOf
2023-09-27 13:51:24.003:DEBUG:oejx.XmlConfiguration:main: XML HttpConfiguration@3fb1549b{32768/8192,8192/8192,https://:0,[]}.setMultiPartFormDataCompliance (RFC7578)
2023-09-27 13:51:24.003:DEBUG:oejx.XmlConfiguration:main: XML HttpConfiguration@3fb1549b{32768/8192,8192/8192,https://:0,[]}.setRelativeRedirectAllowed (false)
2023-09-27 13:51:24.003:DEBUG:oejx.XmlConfiguration:main: XML new org.eclipse.jetty.server.handler.HandlerList
2023-09-27 13:51:24.005:DEBUG:oejx.XmlConfiguration:main: XML new org.eclipse.jetty.server.handler.ContextHandlerCollection
2023-09-27 13:51:24.008:DEBUG:oejx.XmlConfiguration:main: XML new org.eclipse.jetty.server.handler.DefaultHandler
2023-09-27 13:51:24.012:DEBUG:oejx.XmlConfiguration:main: XML HandlerList@47987356{STOPPED}.setHandlers ([ContextHandlerCollection@6283d8b8{STOPPED}, DefaultHandler@3b6ddd1d{STOPPED}])
2023-09-27 13:51:24.013:DEBUG:oejuc.ContainerLifeCycle:main: HandlerList@47987356{STOPPED} added {ContextHandlerCollection@6283d8b8{STOPPED},AUTO}
2023-09-27 13:51:24.013:DEBUG:oejuc.ContainerLifeCycle:main: HandlerList@47987356{STOPPED} added {DefaultHandler@3b6ddd1d{STOPPED},AUTO}
2023-09-27 13:51:24.013:DEBUG:oejx.XmlConfiguration:main: XML Server@7c83dc97{STOPPED}[10.0.17-SNAPSHOT,sto=0].setHandler (HandlerList@47987356{STOPPED})
2023-09-27 13:51:24.013:DEBUG:oejuc.ContainerLifeCycle:main: Server@7c83dc97{STOPPED}[10.0.17-SNAPSHOT,sto=0] added {HandlerList@47987356{STOPPED},MANAGED}
2023-09-27 13:51:24.013:DEBUG:oejx.XmlConfiguration:main: XML Server@7c83dc97{STOPPED}[10.0.17-SNAPSHOT,sto=0].setStopAtShutdown (true)
2023-09-27 13:51:24.014:DEBUG:oejx.XmlConfiguration:main: XML Server@7c83dc97{STOPPED}[10.0.17-SNAPSHOT,sto=0].setStopTimeout (5000)
2023-09-27 13:51:24.014:DEBUG:oejx.XmlParser:main: parsing: sid=null,pid=null
2023-09-27 13:51:24.015:DEBUG:oejx.XmlParser:main: resolveEntity(-//Jetty//Configure//EN,https://www.eclipse.org/jetty/configure_10_0.dtd)
2023-09-27 13:51:24.015:DEBUG:oejx.XmlParser:main: Redirected entity https://www.eclipse.org/jetty/configure_10_0.dtd  --> jar:file:/usr/local/jetty-home-10.0.17-SNAPSHOT/lib/jetty-xml-10.0.17-SNAPSHOT.jar!/org/eclipse/jetty/xml/configure_10_0.dtd
2023-09-27 13:51:24.019:DEBUG:oejx.XmlConfiguration:main: Configure file:///usr/local/jetty-home-10.0.17-SNAPSHOT/etc/jetty-webapp.xml
2023-09-27 13:51:24.019:DEBUG:oejx.XmlConfiguration:main: Configure class org.eclipse.jetty.server.Server Server@7c83dc97{STOPPED}[10.0.17-SNAPSHOT,sto=5000]
2023-09-27 13:51:24.023:DEBUG:oejx.XmlConfiguration:main: XML call addSystemClasses
2023-09-27 13:51:24.023:DEBUG:oejx.XmlConfiguration:main: XML call csvSplit
2023-09-27 13:51:24.046:DEBUG:oejx.XmlConfiguration:main: XML call addServerClasses
2023-09-27 13:51:24.046:DEBUG:oejx.XmlConfiguration:main: XML call csvSplit
2023-09-27 13:51:24.047:DEBUG:oejuc.ContainerLifeCycle:main: AttributeContainerMap@568ff82{size=1} added {[Ljava.lang.String;@2b30a42c,POJO}
2023-09-27 13:51:24.047:DEBUG:oejx.XmlParser:main: parsing: sid=null,pid=null
2023-09-27 13:51:24.048:DEBUG:oejx.XmlParser:main: resolveEntity(-//Jetty//Configure//EN,https://www.eclipse.org/jetty/configure_10_0.dtd)
2023-09-27 13:51:24.048:DEBUG:oejx.XmlParser:main: Redirected entity https://www.eclipse.org/jetty/configure_10_0.dtd  --> jar:file:/usr/local/jetty-home-10.0.17-SNAPSHOT/lib/jetty-xml-10.0.17-SNAPSHOT.jar!/org/eclipse/jetty/xml/configure_10_0.dtd
2023-09-27 13:51:24.052:DEBUG:oejx.XmlConfiguration:main: Configure file:///usr/local/jetty-home-10.0.17-SNAPSHOT/etc/console-capture.xml
2023-09-27 13:51:24.052:DEBUG:oejx.XmlConfiguration:main: Configure null null
2023-09-27 13:51:24.052:DEBUG:oejx.XmlConfiguration:main: XML new java.io.PrintStream
2023-09-27 13:51:24.052:DEBUG:oejx.XmlConfiguration:main: XML new org.eclipse.jetty.util.RolloverFileOutputStream
2023-09-27 13:51:24.053:DEBUG:oejx.XmlConfiguration:main: XML call getTimeZone
2023-09-27 13:51:24.074:DEBUG:oejx.XmlConfiguration:main: XML get datedFilename
2023-09-27 13:51:24.075:DEBUG:oejx.XmlConfiguration:main: XML call getLogger
2023-09-27 13:51:24.076:DEBUG:oejx.XmlConfiguration:main: XML call info
2023-09-27 13:51:24.077:INFO :oe.jetty:main: Console stderr/stdout captured to|        /srv/www.myweb.com/jetty/logs/2023_09_27.jetty.log
2023-09-27 13:51:24.077:DEBUG:oejx.XmlConfiguration:main: XML call setErr
WARNING: An illegal reflective access operation has occurred
WARNING: Illegal reflective access by org.eclipse.angus.mail.util.SocketFetcher (file:/srv/www.myweb.com/jetty/webapps/ROOT/WEB-INF/lib/jakarta.mail-2.0.2.jar) to method sun.security.util.HostnameChecker.getInstance(byte)
WARNING: Please consider reporting this to the maintainers of org.eclipse.angus.mail.util.SocketFetcher
WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
WARNING: All illegal access operations will be denied in a future release

@joakime
Copy link
Contributor

joakime commented Sep 27, 2023

That log looks incomplete.
The server didn't start, according to that DEBUG output.

BTW, The warning on jakarta.mail is discussed at jakartaee/mail-api#391

Something to think about.
Java Mail 2.0.x is for Java 1.7 (Java 1.8 support is accidental, not intentional)
Java Mail 2.1.0 was the first version to support Java 11, but that version requires jakarta.mail. namespace.

@ofrias
Copy link

ofrias commented Sep 27, 2023

Sorry, logs continue on /srv/www.myweb.com/jetty/logs/2023_09_27.jetty.log:

2023-09-27 14:50:14.302:DEBUG:oejx.XmlConfiguration:main: XML call setOut
2023-09-27 14:50:14.302:DEBUG:oejx.XmlParser:main: parsing: sid=null,pid=null
2023-09-27 14:50:14.303:DEBUG:oejx.XmlParser:main: resolveEntity(-//Jetty//Configure//EN,https://www.eclipse.org/jetty/configure_10_0.dtd)
2023-09-27 14:50:14.303:DEBUG:oejx.XmlParser:main: Redirected entity https://www.eclipse.org/jetty/configure_10_0.dtd  --> jar:file:/usr/local/jetty-home-10.0.17-SNAPSHOT/lib/jetty-xml-10.0.17-SNAPSHOT.jar!/org/eclipse/jetty/xml/configure_10_0.dtd
2023-09-27 14:50:14.305:DEBUG:oejx.XmlConfiguration:main: Configure file:///usr/local/jetty-home-10.0.17-SNAPSHOT/etc/jetty-state.xml
2023-09-27 14:50:14.305:DEBUG:oejx.XmlConfiguration:main: Configure class org.eclipse.jetty.server.Server Server@7c83dc97{STOPPED}[10.0.17-SNAPSHOT,sto=5000]
2023-09-27 14:50:14.305:DEBUG:oejx.XmlConfiguration:main: XML call addEventListener
2023-09-27 14:50:14.305:DEBUG:oejx.XmlConfiguration:main: XML new org.eclipse.jetty.server.StateLifeCycleListener
2023-09-27 14:50:14.306:DEBUG:oejs.StateLifeCycleListener:main: State File: /srv/www.myweb.com/jetty/jetty.state
2023-09-27 14:50:14.307:DEBUG:oejuc.ContainerLifeCycle:main: Server@7c83dc97{STOPPED}[10.0.17-SNAPSHOT,sto=5000] added {StateLifeCycleListener@d23e042,POJO}
2023-09-27 14:50:14.307:DEBUG:oejx.XmlParser:main: parsing: sid=null,pid=null
2023-09-27 14:50:14.308:DEBUG:oejx.XmlParser:main: resolveEntity(-//Jetty//Configure//EN,https://www.eclipse.org/jetty/configure_10_0.dtd)
2023-09-27 14:50:14.308:DEBUG:oejx.XmlParser:main: Redirected entity https://www.eclipse.org/jetty/configure_10_0.dtd  --> jar:file:/usr/local/jetty-home-10.0.17-SNAPSHOT/lib/jetty-xml-10.0.17-SNAPSHOT.jar!/org/eclipse/jetty/xml/configure_10_0.dtd
2023-09-27 14:50:14.312:DEBUG:oejx.XmlConfiguration:main: Configure file:///srv/www.myweb.com/jetty/etc/jetty-deploy.xml
2023-09-27 14:50:14.312:DEBUG:oejx.XmlConfiguration:main: Configure class org.eclipse.jetty.server.Server Server@7c83dc97{STOPPED}[10.0.17-SNAPSHOT,sto=5000]
2023-09-27 14:50:14.312:DEBUG:oejx.XmlConfiguration:main: XML call addBean
2023-09-27 14:50:14.312:DEBUG:oejx.XmlConfiguration:main: XML new org.eclipse.jetty.deploy.DeploymentManager
2023-09-27 14:50:14.315:DEBUG:oejx.XmlConfiguration:main: XML DeploymentManager@23941fb4{STOPPED}.setContexts (ContextHandlerCollection@6283d8b8{STOPPED})
2023-09-27 14:50:14.316:DEBUG:oejx.XmlConfiguration:main: XML call setContextAttribute
2023-09-27 14:50:14.316:DEBUG:oejx.XmlConfiguration:main: XML call addAppProvider
2023-09-27 14:50:14.316:DEBUG:oejx.XmlConfiguration:main: XML new org.eclipse.jetty.deploy.providers.WebAppProvider
2023-09-27 14:50:14.318:DEBUG:oejuc.ContainerLifeCycle:main: class org.eclipse.jetty.deploy.providers.WebAppProvider@1a5a4e19[] added {{},POJO}
2023-09-27 14:50:14.318:DEBUG:oejx.XmlConfiguration:main: XML call resolvePath
2023-09-27 14:50:14.318:DEBUG:oejx.XmlConfiguration:main: XML class org.eclipse.jetty.deploy.providers.WebAppProvider@1a5a4e19[].setMonitoredDirName (/srv/www.myweb.com/jetty/webapps)
2023-09-27 14:50:14.319:DEBUG:oejx.XmlConfiguration:main: XML class org.eclipse.jetty.deploy.providers.WebAppProvider@1a5a4e19[file:///srv/www.myweb.com/jetty/webapps/].setDefaultsDescriptor (/srv/www.myweb.com/jetty/etc/webdefault.xml)
2023-09-27 14:50:14.319:DEBUG:oejx.XmlConfiguration:main: XML class org.eclipse.jetty.deploy.providers.WebAppProvider@1a5a4e19[file:///srv/www.myweb.com/jetty/webapps/].setScanInterval (1)
2023-09-27 14:50:14.319:DEBUG:oejx.XmlConfiguration:main: XML class org.eclipse.jetty.deploy.providers.WebAppProvider@1a5a4e19[file:///srv/www.myweb.com/jetty/webapps/].setExtractWars (true)
2023-09-27 14:50:14.319:DEBUG:oejx.XmlConfiguration:main: XML new org.eclipse.jetty.deploy.PropertiesConfigurationManager
2023-09-27 14:50:14.320:DEBUG:oejx.XmlConfiguration:main: XML class org.eclipse.jetty.deploy.providers.WebAppProvider@1a5a4e19[file:///srv/www.myweb.com/jetty/webapps/].setConfigurationManager (class org.eclipse.jetty.deploy.PropertiesConfigurationManager@a8ef162{null})
2023-09-27 14:50:14.320:DEBUG:oejuc.ContainerLifeCycle:main: class org.eclipse.jetty.deploy.providers.WebAppProvider@1a5a4e19[file:///srv/www.myweb.com/jetty/webapps/] added {class org.eclipse.jetty.deploy.PropertiesConfigurationManager@a8ef162{null},POJO}
2023-09-27 14:50:14.320:DEBUG:oejuc.ContainerLifeCycle:main: DeploymentManager@23941fb4{STOPPED} added {class org.eclipse.jetty.deploy.providers.WebAppProvider@1a5a4e19[file:///srv/www.myweb.com/jetty/webapps/],MANAGED}
2023-09-27 14:50:14.320:DEBUG:oejuc.ContainerLifeCycle:main: Server@7c83dc97{STOPPED}[10.0.17-SNAPSHOT,sto=5000] added {DeploymentManager@23941fb4{STOPPED},AUTO}
2023-09-27 14:50:14.321:DEBUG:oejx.XmlParser:main: parsing: sid=null,pid=null
2023-09-27 14:50:14.321:DEBUG:oejx.XmlParser:main: resolveEntity(-//Jetty//Configure//EN,https://www.eclipse.org/jetty/configure_10_0.dtd)
2023-09-27 14:50:14.321:DEBUG:oejx.XmlParser:main: Redirected entity https://www.eclipse.org/jetty/configure_10_0.dtd  --> jar:file:/usr/local/jetty-home-10.0.17-SNAPSHOT/lib/jetty-xml-10.0.17-SNAPSHOT.jar!/org/eclipse/jetty/xml/configure_10_0.dtd
2023-09-27 14:50:14.325:DEBUG:oejx.XmlConfiguration:main: Configure file:///usr/local/jetty-home-10.0.17-SNAPSHOT/etc/jetty-gzip.xml
2023-09-27 14:50:14.325:DEBUG:oejx.XmlConfiguration:main: Configure class org.eclipse.jetty.server.Server Server@7c83dc97{STOPPED}[10.0.17-SNAPSHOT,sto=5000]
2023-09-27 14:50:14.326:DEBUG:oejx.XmlConfiguration:main: XML call insertHandler
2023-09-27 14:50:14.326:DEBUG:oejx.XmlConfiguration:main: XML new org.eclipse.jetty.server.handler.gzip.GzipHandler
2023-09-27 14:50:14.333:DEBUG:oejh.PreEncodedHttpField:main: HttpField encoders loaded: [org.eclipse.jetty.http.Http1FieldPreEncoder@4808bc9b, org.eclipse.jetty.http2.hpack.HpackFieldPreEncoder@70e38ce1]
2023-09-27 14:50:14.351:DEBUG:oejhp.ServletPathSpec:main: Creating ServletPathSpec[*.svgz] (group: SUFFIX_GLOB, prefix: "null", suffix: "svgz")
2023-09-27 14:50:14.352:DEBUG:oejhp.PathMappings:main: Added MappedResource[pathSpec=ServletPathSpec@9727ded2{*.svgz},resource=true] to PathMappings[size=1]
2023-09-27 14:50:14.352:DEBUG:oejshg.GzipHandler:main: GzipHandler@12299890{STOPPED,min=32,inflate=-1} mime types IncludeExclude@2fba3fc4{i=[],ip=CONTAINS,e=[image/ief, image/vnd.wap.wbmp, image/jpeg, application/bzip2, image/x-portable-graymap, application/brotli, image/bmp, image/gif, image/x-icon, image/apng, audio/midi, image/webp, video/x-msvideo, image/x-xbitmap, application/x-rar-compressed, text/event-stream, image/avif, image/x-portable-bitmap, image/x-rgb, image/x-cmu-raster, application/gzip, audio/x-wav, audio/x-pn-realaudio, audio/basic, application/compress, audio/x-aiff, video/x.ms.asx, video/x.ms.asf, image/png, video/vnd.rn-realvideo, image/x-xwindowdump, image/jpeg2000, video/x-sgi-movie, audio/mpeg, image/xcf, video/mpeg, image/x-portable-pixmap, image/tiff, image/x-portable-anymap, image/x-xpixmap, application/zip, video/quicktime, application/x-xz, video/mp4],ep=CONTAINS}
2023-09-27 14:50:14.353:DEBUG:oejx.XmlConfiguration:main: XML new org.eclipse.jetty.util.compression.InflaterPool
2023-09-27 14:50:14.353:DEBUG:oejx.XmlConfiguration:main: XML GzipHandler@12299890{STOPPED,min=32,inflate=-1}.setInflaterPool (InflaterPool@389c4eb1{STOPPED,size=-1,capacity=1024})
2023-09-27 14:50:14.354:DEBUG:oejuc.ContainerLifeCycle:main: GzipHandler@12299890{STOPPED,min=32,inflate=-1} added {InflaterPool@389c4eb1{STOPPED,size=-1,capacity=1024},AUTO}
2023-09-27 14:50:14.354:DEBUG:oejx.XmlConfiguration:main: XML new org.eclipse.jetty.util.compression.DeflaterPool
2023-09-27 14:50:14.354:DEBUG:oejx.XmlConfiguration:main: XML GzipHandler@12299890{STOPPED,min=32,inflate=-1}.setDeflaterPool (DeflaterPool@3fc79729{STOPPED,size=-1,capacity=1024})
2023-09-27 14:50:14.354:DEBUG:oejuc.ContainerLifeCycle:main: GzipHandler@12299890{STOPPED,min=32,inflate=-1} added {DeflaterPool@3fc79729{STOPPED,size=-1,capacity=1024},AUTO}
2023-09-27 14:50:14.354:DEBUG:oejuc.ContainerLifeCycle:main: Server@7c83dc97{STOPPED}[10.0.17-SNAPSHOT,sto=5000] added {GzipHandler@12299890{STOPPED,min=32,inflate=-1},MANAGED}
2023-09-27 14:50:14.354:DEBUG:oejuc.ContainerLifeCycle:main: GzipHandler@12299890{STOPPED,min=32,inflate=-1} added {HandlerList@47987356{STOPPED},MANAGED}
2023-09-27 14:50:14.355:DEBUG:oejx.XmlParser:main: parsing: sid=null,pid=null
2023-09-27 14:50:14.355:DEBUG:oejx.XmlParser:main: resolveEntity(-//Jetty//Configure//EN,https://www.eclipse.org/jetty/configure_10_0.dtd)
2023-09-27 14:50:14.356:DEBUG:oejx.XmlParser:main: Redirected entity https://www.eclipse.org/jetty/configure_10_0.dtd  --> jar:file:/usr/local/jetty-home-10.0.17-SNAPSHOT/lib/jetty-xml-10.0.17-SNAPSHOT.jar!/org/eclipse/jetty/xml/configure_10_0.dtd
2023-09-27 14:50:14.360:DEBUG:oejx.XmlConfiguration:main: Configure file:///usr/local/jetty-home-10.0.17-SNAPSHOT/etc/jetty-http.xml
2023-09-27 14:50:14.360:DEBUG:oejx.XmlConfiguration:main: Configure class org.eclipse.jetty.server.Server Server@7c83dc97{STOPPED}[10.0.17-SNAPSHOT,sto=5000]
2023-09-27 14:50:14.360:DEBUG:oejx.XmlConfiguration:main: XML call addConnector
2023-09-27 14:50:14.360:DEBUG:oejx.XmlConfiguration:main: XML new org.eclipse.jetty.server.ServerConnector
2023-09-27 14:50:14.364:DEBUG:oejx.XmlConfiguration:main: XML new org.eclipse.jetty.server.HttpConnectionFactory
2023-09-27 14:50:14.366:DEBUG:oejuc.ContainerLifeCycle:main: HttpConnectionFactory@4032d386[HTTP/1.1] added {HttpConfiguration@3fb1549b{32768/8192,8192/8192,https://:0,[]},POJO}
2023-09-27 14:50:14.371:DEBUG:oejuc.ContainerLifeCycle:main: ServerConnector@5e403b4a{null, ()}{0.0.0.0:0} added {QueuedThreadPool[qtp1020520290]@3cd3e762{STOPPED,10<=0<=1000,i=0,r=-1,t=-712403070ms,q=0}[NO_TRY],AUTO}
2023-09-27 14:50:14.372:DEBUG:oejuc.ContainerLifeCycle:main: ServerConnector@5e403b4a{null, ()}{0.0.0.0:0} added {ScheduledExecutorScheduler@4da4253{STOPPED},AUTO}
2023-09-27 14:50:14.373:DEBUG:oejuc.ContainerLifeCycle:main: ServerConnector@5e403b4a{null, ()}{0.0.0.0:0} added {ArrayByteBufferPool@3315d2d7{minBufferCapacity=0, maxBufferCapacity=65536, maxQueueLength=-1, factor=4096},UNMANAGED}
2023-09-27 14:50:14.373:DEBUG:oejuc.ContainerLifeCycle:main: ServerConnector@5e403b4a{null, ()}{0.0.0.0:0} added {org.eclipse.jetty.io.ArrayByteBufferPool$Retained@662706a7{min=0,max=65536,buckets=16,heap=0/4200595456,direct=0/4200595456},POJO}
2023-09-27 14:50:14.373:DEBUG:oejuc.ContainerLifeCycle:main: ServerConnector@5e403b4a{null, ()}{0.0.0.0:0} added {org.eclipse.jetty.server.AbstractConnector$1@c7045b9,POJO}
2023-09-27 14:50:14.374:DEBUG:oejuc.ContainerLifeCycle:main: ServerConnector@5e403b4a{null, (http/1.1)}{0.0.0.0:0} added {HttpConnectionFactory@4032d386[HTTP/1.1],AUTO}
2023-09-27 14:50:14.374:DEBUG:oejs.AbstractConnector:main: ServerConnector@5e403b4a{HTTP/1.1, (http/1.1)}{0.0.0.0:0} added HttpConnectionFactory@4032d386[HTTP/1.1]
2023-09-27 14:50:14.377:DEBUG:oejuc.ContainerLifeCycle:main: ServerConnector@5e403b4a{HTTP/1.1, (http/1.1)}{0.0.0.0:0} added {SelectorManager@ServerConnector@5e403b4a{HTTP/1.1, (http/1.1)}{0.0.0.0:0},MANAGED}
2023-09-27 14:50:14.388:DEBUG:oejx.XmlConfiguration:main: XML ServerConnector@5e403b4a{HTTP/1.1, (http/1.1)}{0.0.0.0:0}.setPort (8081)
2023-09-27 14:50:14.390:DEBUG:oejx.XmlConfiguration:main: XML ServerConnector@5e403b4a{HTTP/1.1, (http/1.1)}{0.0.0.0:8081}.setIdleTimeout (150000)
2023-09-27 14:50:14.390:DEBUG:oejx.XmlConfiguration:main: XML ServerConnector@5e403b4a{HTTP/1.1, (http/1.1)}{0.0.0.0:8081}.setReuseAddress (true)
2023-09-27 14:50:14.390:DEBUG:oejx.XmlConfiguration:main: XML ServerConnector@5e403b4a{HTTP/1.1, (http/1.1)}{0.0.0.0:8081}.setReusePort (false)
2023-09-27 14:50:14.391:DEBUG:oejx.XmlConfiguration:main: XML ServerConnector@5e403b4a{HTTP/1.1, (http/1.1)}{0.0.0.0:8081}.setAcceptedTcpNoDelay (true)
2023-09-27 14:50:14.391:DEBUG:oejx.XmlConfiguration:main: XML get SelectorManager
2023-09-27 14:50:14.392:DEBUG:oejx.XmlConfiguration:main: XML SelectorManager@ServerConnector@5e403b4a{HTTP/1.1, (http/1.1)}{0.0.0.0:8081}.setConnectTimeout (15000)
2023-09-27 14:50:14.393:DEBUG:oejuc.ContainerLifeCycle:main: Server@7c83dc97{STOPPED}[10.0.17-SNAPSHOT,sto=5000] added {ServerConnector@5e403b4a{HTTP/1.1, (http/1.1)}{0.0.0.0:8081},AUTO}
2023-09-27 14:50:14.393:DEBUG:oejx.XmlParser:main: parsing: sid=null,pid=null
2023-09-27 14:50:14.394:DEBUG:oejx.XmlParser:main: resolveEntity(-//Jetty//Configure//EN,https://www.eclipse.org/jetty/configure_10_0.dtd)
2023-09-27 14:50:14.394:DEBUG:oejx.XmlParser:main: Redirected entity https://www.eclipse.org/jetty/configure_10_0.dtd  --> jar:file:/usr/local/jetty-home-10.0.17-SNAPSHOT/lib/jetty-xml-10.0.17-SNAPSHOT.jar!/org/eclipse/jetty/xml/configure_10_0.dtd
2023-09-27 14:50:14.397:DEBUG:oejx.XmlConfiguration:main: Configure file:///usr/local/jetty-home-10.0.17-SNAPSHOT/etc/jetty-http2c.xml
2023-09-27 14:50:14.397:DEBUG:oejx.XmlConfiguration:main: Configure class org.eclipse.jetty.server.ServerConnector ServerConnector@5e403b4a{HTTP/1.1, (http/1.1)}{0.0.0.0:8081}
2023-09-27 14:50:14.397:DEBUG:oejx.XmlConfiguration:main: XML call addConnectionFactory
2023-09-27 14:50:14.397:DEBUG:oejx.XmlConfiguration:main: XML new org.eclipse.jetty.http2.server.HTTP2CServerConnectionFactory
2023-09-27 14:50:14.410:DEBUG:oejuc.ContainerLifeCycle:main: HTTP2CServerConnectionFactory@35645047[h2c] added {HTTP2SessionContainer@6f44a157[size=0],POJO}
2023-09-27 14:50:14.410:DEBUG:oejuc.ContainerLifeCycle:main: HTTP2CServerConnectionFactory@35645047[h2c] added {HttpConfiguration@3fb1549b{32768/8192,8192/8192,https://:0,[]},POJO}
2023-09-27 14:50:14.411:DEBUG:oejx.XmlConfiguration:main: XML new org.eclipse.jetty.http2.parser.WindowRateControl$Factory
2023-09-27 14:50:14.411:DEBUG:oejx.XmlConfiguration:main: XML HTTP2CServerConnectionFactory@35645047[h2c].setRateControlFactory (org.eclipse.jetty.http2.parser.WindowRateControl$Factory@49c66ade)
2023-09-27 14:50:14.412:DEBUG:oejuc.ContainerLifeCycle:main: ServerConnector@5e403b4a{HTTP/1.1, (http/1.1, h2c)}{0.0.0.0:8081} added {HTTP2CServerConnectionFactory@35645047[h2c],AUTO}
2023-09-27 14:50:14.412:DEBUG:oejs.AbstractConnector:main: ServerConnector@5e403b4a{HTTP/1.1, (http/1.1, h2c)}{0.0.0.0:8081} added HTTP2CServerConnectionFactory@35645047[h2c]
2023-09-27 14:50:14.412:DEBUG:oejx.XmlParser:main: parsing: sid=null,pid=null
2023-09-27 14:50:14.413:DEBUG:oejx.XmlParser:main: resolveEntity(-//Jetty//Configure//EN,https://www.eclipse.org/jetty/configure_10_0.dtd)
2023-09-27 14:50:14.413:DEBUG:oejx.XmlParser:main: Redirected entity https://www.eclipse.org/jetty/configure_10_0.dtd  --> jar:file:/usr/local/jetty-home-10.0.17-SNAPSHOT/lib/jetty-xml-10.0.17-SNAPSHOT.jar!/org/eclipse/jetty/xml/configure_10_0.dtd
2023-09-27 14:50:14.416:DEBUG:oejx.XmlConfiguration:main: Configure file:///usr/local/jetty-home-10.0.17-SNAPSHOT/etc/jetty-http-forwarded.xml
2023-09-27 14:50:14.416:DEBUG:oejx.XmlConfiguration:main: Configure class org.eclipse.jetty.server.HttpConfiguration HttpConfiguration@3fb1549b{32768/8192,8192/8192,https://:0,[]}
2023-09-27 14:50:14.416:DEBUG:oejx.XmlConfiguration:main: XML call addCustomizer
2023-09-27 14:50:14.416:DEBUG:oejx.XmlConfiguration:main: XML new org.eclipse.jetty.server.ForwardedRequestCustomizer
2023-09-27 14:50:14.418:DEBUG:oejx.XmlConfiguration:main: XML [email protected] (true)
2023-09-27 14:50:14.419:DEBUG:oejx.XmlParser:main: parsing: sid=null,pid=null
2023-09-27 14:50:14.420:DEBUG:oejx.XmlParser:main: resolveEntity(-//Jetty//Configure//EN,https://www.eclipse.org/jetty/configure_10_0.dtd)
2023-09-27 14:50:14.420:DEBUG:oejx.XmlParser:main: Redirected entity https://www.eclipse.org/jetty/configure_10_0.dtd  --> jar:file:/usr/local/jetty-home-10.0.17-SNAPSHOT/lib/jetty-xml-10.0.17-SNAPSHOT.jar!/org/eclipse/jetty/xml/configure_10_0.dtd
2023-09-27 14:50:14.423:DEBUG:oejx.XmlConfiguration:main: Configure file:///usr/local/jetty-home-10.0.17-SNAPSHOT/etc/jetty-requestlog.xml
2023-09-27 14:50:14.423:DEBUG:oejx.XmlConfiguration:main: Configure class org.eclipse.jetty.server.Server Server@7c83dc97{STOPPED}[10.0.17-SNAPSHOT,sto=5000]
2023-09-27 14:50:14.423:DEBUG:oejx.XmlConfiguration:main: XML new org.eclipse.jetty.server.CustomRequestLog
2023-09-27 14:50:14.424:DEBUG:oejx.XmlConfiguration:main: XML new org.eclipse.jetty.server.AsyncRequestLogWriter
2023-09-27 14:50:14.425:DEBUG:oejx.XmlConfiguration:main: XML call resolvePath
2023-09-27 14:50:14.425:DEBUG:oejx.XmlConfiguration:main: XML AsyncRequestLogWriter@74589991{STOPPED}.setFilenameDateFormat (yyyy_MM_dd)
2023-09-27 14:50:14.425:DEBUG:oejx.XmlConfiguration:main: XML AsyncRequestLogWriter@74589991{STOPPED}.setRetainDays (90)
2023-09-27 14:50:14.425:DEBUG:oejx.XmlConfiguration:main: XML AsyncRequestLogWriter@74589991{STOPPED}.setAppend (false)
2023-09-27 14:50:14.426:DEBUG:oejx.XmlConfiguration:main: XML AsyncRequestLogWriter@74589991{STOPPED}.setTimeZone (GMT)
2023-09-27 14:50:14.426:DEBUG:oejx.XmlConfiguration:main: XML get EXTENDED_NCSA_FORMAT
2023-09-27 14:50:14.428:DEBUG:oejuc.ContainerLifeCycle:main: CustomRequestLog@2bb3058{STOPPED} added {AsyncRequestLogWriter@74589991{STOPPED},AUTO}
2023-09-27 14:50:14.433:DEBUG:oejx.XmlConfiguration:main: XML Server@7c83dc97{STOPPED}[10.0.17-SNAPSHOT,sto=5000].setRequestLog (CustomRequestLog@2bb3058{STOPPED})
2023-09-27 14:50:14.434:DEBUG:oejuc.ContainerLifeCycle:main: Server@7c83dc97{STOPPED}[10.0.17-SNAPSHOT,sto=5000] added {CustomRequestLog@2bb3058{STOPPED},AUTO}
2023-09-27 14:50:14.434:DEBUG:oejx.XmlParser:main: parsing: sid=null,pid=null
2023-09-27 14:50:14.434:DEBUG:oejx.XmlParser:main: resolveEntity(-//Jetty//Configure//EN,https://www.eclipse.org/jetty/configure_10_0.dtd)
2023-09-27 14:50:14.435:DEBUG:oejx.XmlParser:main: Redirected entity https://www.eclipse.org/jetty/configure_10_0.dtd  --> jar:file:/usr/local/jetty-home-10.0.17-SNAPSHOT/lib/jetty-xml-10.0.17-SNAPSHOT.jar!/org/eclipse/jetty/xml/configure_10_0.dtd
2023-09-27 14:50:14.437:DEBUG:oejx.XmlConfiguration:main: Configure file:///usr/local/jetty-home-10.0.17-SNAPSHOT/etc/sessions/id-manager.xml
2023-09-27 14:50:14.437:DEBUG:oejx.XmlConfiguration:main: Configure class org.eclipse.jetty.server.Server Server@7c83dc97{STOPPED}[10.0.17-SNAPSHOT,sto=5000]
2023-09-27 14:50:14.437:DEBUG:oejx.XmlConfiguration:main: XML new org.eclipse.jetty.server.session.DefaultSessionIdManager
2023-09-27 14:50:14.439:DEBUG:oejuc.ContainerLifeCycle:main: Server@7c83dc97{STOPPED}[10.0.17-SNAPSHOT,sto=5000] added {DefaultSessionIdManager@3b96c42e{STOPPED}[worker=null],AUTO}
2023-09-27 14:50:14.439:DEBUG:oejx.XmlConfiguration:main: XML DefaultSessionIdManager@3b96c42e{STOPPED}[worker=null].setWorkerName (arya)
2023-09-27 14:50:14.439:DEBUG:oejx.XmlConfiguration:main: XML new org.eclipse.jetty.server.session.HouseKeeper
2023-09-27 14:50:14.440:DEBUG:oejx.XmlConfiguration:main: XML DefaultSessionIdManager@3b96c42e{STOPPED}[worker=arya].setSessionHouseKeeper (HouseKeeper@9ebe38b{STOPPED}[interval=600000, ownscheduler=false])
2023-09-27 14:50:14.449:DEBUG:oejuc.ContainerLifeCycle:main: DefaultSessionIdManager@3b96c42e{STOPPED}[worker=arya] added {HouseKeeper@9ebe38b{STOPPED}[interval=600000, ownscheduler=false],AUTO}
2023-09-27 14:50:14.449:DEBUG:oejx.XmlParser:main: parsing: sid=null,pid=null
2023-09-27 14:50:14.450:DEBUG:oejx.XmlParser:main: resolveEntity(-//Jetty//Configure//EN,https://www.eclipse.org/jetty/configure_10_0.dtd)
2023-09-27 14:50:14.450:DEBUG:oejx.XmlParser:main: Redirected entity https://www.eclipse.org/jetty/configure_10_0.dtd  --> jar:file:/usr/local/jetty-home-10.0.17-SNAPSHOT/lib/jetty-xml-10.0.17-SNAPSHOT.jar!/org/eclipse/jetty/xml/configure_10_0.dtd
2023-09-27 14:50:14.452:DEBUG:oejx.XmlConfiguration:main: Configure file:///usr/local/jetty-home-10.0.17-SNAPSHOT/etc/sessions/jdbc/datasource.xml
2023-09-27 14:50:14.452:DEBUG:oejx.XmlConfiguration:main: Configure class org.eclipse.jetty.server.Server Server@7c83dc97{STOPPED}[10.0.17-SNAPSHOT,sto=5000]
2023-09-27 14:50:14.452:DEBUG:oejx.XmlConfiguration:main: XML new org.eclipse.jetty.server.session.DatabaseAdaptor
2023-09-27 14:50:14.455:DEBUG:oejx.XmlParser:main: parsing: sid=null,pid=null
2023-09-27 14:50:14.456:DEBUG:oejx.XmlParser:main: resolveEntity(-//Jetty//Configure//EN,https://www.eclipse.org/jetty/configure_10_0.dtd)
2023-09-27 14:50:14.456:DEBUG:oejx.XmlParser:main: Redirected entity https://www.eclipse.org/jetty/configure_10_0.dtd  --> jar:file:/usr/local/jetty-home-10.0.17-SNAPSHOT/lib/jetty-xml-10.0.17-SNAPSHOT.jar!/org/eclipse/jetty/xml/configure_10_0.dtd
2023-09-27 14:50:14.459:DEBUG:oejx.XmlConfiguration:main: Configure file:///usr/local/jetty-home-10.0.17-SNAPSHOT/etc/sessions/jdbc/session-store.xml
2023-09-27 14:50:14.459:DEBUG:oejx.XmlConfiguration:main: Configure class org.eclipse.jetty.server.Server Server@7c83dc97{STOPPED}[10.0.17-SNAPSHOT,sto=5000]
2023-09-27 14:50:14.459:DEBUG:oejx.XmlConfiguration:main: XML call addBean
2023-09-27 14:50:14.459:DEBUG:oejx.XmlConfiguration:main: XML new org.eclipse.jetty.server.session.JDBCSessionDataStoreFactory
2023-09-27 14:50:14.461:DEBUG:oejx.XmlConfiguration:main: XML org.eclipse.jetty.server.session.JDBCSessionDataStoreFactory@6b88ca8c.setDatabaseAdaptor (org.eclipse.jetty.server.session.DatabaseAdaptor@336f1079[jndi=null,driver=null])
2023-09-27 14:50:14.461:DEBUG:oejx.XmlConfiguration:main: XML new org.eclipse.jetty.server.session.JDBCSessionDataStore$SessionTableSchema
2023-09-27 14:50:14.462:DEBUG:oejx.XmlConfiguration:main: XML org.eclipse.jetty.server.session.JDBCSessionDataStore$SessionTableSchema@2f16c6b3[null,null,JettySessions,sessionId,contextPath,virtualHost,cookieTime,createTime,expiryTime,accessTime,lastAccessTime,lastNode,lastSavedTime,maxInterval].setAccessTimeColumn (accessTime)
2023-09-27 14:50:14.463:DEBUG:oejx.XmlConfiguration:main: XML org.eclipse.jetty.server.session.JDBCSessionDataStore$SessionTableSchema@2f16c6b3[null,null,JettySessions,sessionId,contextPath,virtualHost,cookieTime,createTime,expiryTime,accessTime,lastAccessTime,lastNode,lastSavedTime,maxInterval].setContextPathColumn (contextPath)
2023-09-27 14:50:14.463:DEBUG:oejx.XmlConfiguration:main: XML org.eclipse.jetty.server.session.JDBCSessionDataStore$SessionTableSchema@2f16c6b3[null,null,JettySessions,sessionId,contextPath,virtualHost,cookieTime,createTime,expiryTime,accessTime,lastAccessTime,lastNode,lastSavedTime,maxInterval].setCookieTimeColumn (cookieTime)
2023-09-27 14:50:14.464:DEBUG:oejx.XmlConfiguration:main: XML org.eclipse.jetty.server.session.JDBCSessionDataStore$SessionTableSchema@2f16c6b3[null,null,JettySessions,sessionId,contextPath,virtualHost,cookieTime,createTime,expiryTime,accessTime,lastAccessTime,lastNode,lastSavedTime,maxInterval].setCreateTimeColumn (createTime)
2023-09-27 14:50:14.464:DEBUG:oejx.XmlConfiguration:main: XML org.eclipse.jetty.server.session.JDBCSessionDataStore$SessionTableSchema@2f16c6b3[null,null,JettySessions,sessionId,contextPath,virtualHost,cookieTime,createTime,expiryTime,accessTime,lastAccessTime,lastNode,lastSavedTime,maxInterval].setExpiryTimeColumn (expiryTime)
2023-09-27 14:50:14.464:DEBUG:oejx.XmlConfiguration:main: XML org.eclipse.jetty.server.session.JDBCSessionDataStore$SessionTableSchema@2f16c6b3[null,null,JettySessions,sessionId,contextPath,virtualHost,cookieTime,createTime,expiryTime,accessTime,lastAccessTime,lastNode,lastSavedTime,maxInterval].setLastAccessTimeColumn (lastAccessTime)
2023-09-27 14:50:14.464:DEBUG:oejx.XmlConfiguration:main: XML org.eclipse.jetty.server.session.JDBCSessionDataStore$SessionTableSchema@2f16c6b3[null,null,JettySessions,sessionId,contextPath,virtualHost,cookieTime,createTime,expiryTime,accessTime,lastAccessTime,lastNode,lastSavedTime,maxInterval].setLastSavedTimeColumn (lastSavedTime)
2023-09-27 14:50:14.464:DEBUG:oejx.XmlConfiguration:main: XML org.eclipse.jetty.server.session.JDBCSessionDataStore$SessionTableSchema@2f16c6b3[null,null,JettySessions,sessionId,contextPath,virtualHost,cookieTime,createTime,expiryTime,accessTime,lastAccessTime,lastNode,lastSavedTime,maxInterval].setIdColumn (sessionId)
2023-09-27 14:50:14.464:DEBUG:oejx.XmlConfiguration:main: XML org.eclipse.jetty.server.session.JDBCSessionDataStore$SessionTableSchema@2f16c6b3[null,null,JettySessions,sessionId,contextPath,virtualHost,cookieTime,createTime,expiryTime,accessTime,lastAccessTime,lastNode,lastSavedTime,maxInterval].setLastNodeColumn (lastNode)
2023-09-27 14:50:14.464:DEBUG:oejx.XmlConfiguration:main: XML org.eclipse.jetty.server.session.JDBCSessionDataStore$SessionTableSchema@2f16c6b3[null,null,JettySessions,sessionId,contextPath,virtualHost,cookieTime,createTime,expiryTime,accessTime,lastAccessTime,lastNode,lastSavedTime,maxInterval].setVirtualHostColumn (virtualHost)
2023-09-27 14:50:14.464:DEBUG:oejx.XmlConfiguration:main: XML org.eclipse.jetty.server.session.JDBCSessionDataStore$SessionTableSchema@2f16c6b3[null,null,JettySessions,sessionId,contextPath,virtualHost,cookieTime,createTime,expiryTime,accessTime,lastAccessTime,lastNode,lastSavedTime,maxInterval].setMaxIntervalColumn (maxInterval)
2023-09-27 14:50:14.464:DEBUG:oejx.XmlConfiguration:main: XML org.eclipse.jetty.server.session.JDBCSessionDataStore$SessionTableSchema@2f16c6b3[null,null,JettySessions,sessionId,contextPath,virtualHost,cookieTime,createTime,expiryTime,accessTime,lastAccessTime,lastNode,lastSavedTime,maxInterval].setMapColumn (map)
2023-09-27 14:50:14.465:DEBUG:oejx.XmlConfiguration:main: XML org.eclipse.jetty.server.session.JDBCSessionDataStore$SessionTableSchema@2f16c6b3[null,null,JettySessions,sessionId,contextPath,virtualHost,cookieTime,createTime,expiryTime,accessTime,lastAccessTime,lastNode,lastSavedTime,maxInterval].setSchemaName (null)
2023-09-27 14:50:14.465:DEBUG:oejx.XmlConfiguration:main: XML org.eclipse.jetty.server.session.JDBCSessionDataStore$SessionTableSchema@2f16c6b3[null,null,JettySessions,sessionId,contextPath,virtualHost,cookieTime,createTime,expiryTime,accessTime,lastAccessTime,lastNode,lastSavedTime,maxInterval].setCatalogName (null)
2023-09-27 14:50:14.465:DEBUG:oejx.XmlConfiguration:main: XML org.eclipse.jetty.server.session.JDBCSessionDataStore$SessionTableSchema@2f16c6b3[null,null,JettySessions,sessionId,contextPath,virtualHost,cookieTime,createTime,expiryTime,accessTime,lastAccessTime,lastNode,lastSavedTime,maxInterval].setTableName (JettySessions)
2023-09-27 14:50:14.465:DEBUG:oejx.XmlConfiguration:main: XML org.eclipse.jetty.server.session.JDBCSessionDataStoreFactory@6b88ca8c.setSessionTableSchema (org.eclipse.jetty.server.session.JDBCSessionDataStore$SessionTableSchema@2f16c6b3[null,null,JettySessions,sessionId,contextPath,virtualHost,cookieTime,createTime,expiryTime,accessTime,lastAccessTime,lastNode,lastSavedTime,maxInterval])
2023-09-27 14:50:14.465:DEBUG:oejuc.ContainerLifeCycle:main: Server@7c83dc97{STOPPED}[10.0.17-SNAPSHOT,sto=5000] added {org.eclipse.jetty.server.session.JDBCSessionDataStoreFactory@6b88ca8c,POJO}
2023-09-27 14:50:14.466:DEBUG:oejx.XmlParser:main: parsing: sid=null,pid=null
2023-09-27 14:50:14.466:DEBUG:oejx.XmlParser:main: resolveEntity(-//Jetty//Configure//EN,https://www.eclipse.org/jetty/configure_9_3.dtd)
2023-09-27 14:50:14.466:DEBUG:oejx.XmlParser:main: Redirected entity https://www.eclipse.org/jetty/configure_9_3.dtd  --> jar:file:/usr/local/jetty-home-10.0.17-SNAPSHOT/lib/jetty-xml-10.0.17-SNAPSHOT.jar!/org/eclipse/jetty/xml/configure_10_0.dtd
2023-09-27 14:50:14.468:DEBUG:oejx.XmlConfiguration:main: Configure file:///usr/local/jetty-home-10.0.17-SNAPSHOT/etc/jetty-setuid.xml
2023-09-27 14:50:14.469:DEBUG:oejx.XmlConfiguration:main: Configure class org.eclipse.jetty.server.Server Server@7c83dc97{STOPPED}[10.0.17-SNAPSHOT,sto=5000]
2023-09-27 14:50:14.469:DEBUG:oejx.XmlConfiguration:main: XML call addEventListener
2023-09-27 14:50:14.469:DEBUG:oejx.XmlConfiguration:main: XML new org.eclipse.jetty.setuid.SetUIDListener
2023-09-27 14:50:14.470:DEBUG:oejx.XmlConfiguration:main: XML org.eclipse.jetty.setuid.SetUIDListener@6e4566f1.setStartServerAsPrivileged (false)
2023-09-27 14:50:14.471:DEBUG:oejx.XmlConfiguration:main: XML [email protected] (002)
2023-09-27 14:50:14.471:DEBUG:oejx.XmlConfiguration:main: XML [email protected] (jetty)
2023-09-27 14:50:14.472:DEBUG:oejs.SetUID:main: System.loadLibrary(setuid)
2023-09-27 14:50:14.472:DEBUG:oejs.SetUID:main: no setuid in java.library.path: [/usr/java/packages/lib, /usr/lib64, /lib64, /lib, /usr/lib]
java.lang.UnsatisfiedLinkError: no setuid in java.library.path: [/usr/java/packages/lib, /usr/lib64, /lib64, /lib, /usr/lib]
	at java.base/java.lang.ClassLoader.loadLibrary(ClassLoader.java:2678)
	at java.base/java.lang.Runtime.loadLibrary0(Runtime.java:830)
	at java.base/java.lang.System.loadLibrary(System.java:1886)
	at org.eclipse.jetty.setuid.SetUID.loadLibrary(SetUID.java:101)
	at org.eclipse.jetty.setuid.SetUID.<clinit>(SetUID.java:219)
	at org.eclipse.jetty.setuid.SetUIDListener.setUsername(SetUIDListener.java:54)
	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.set(XmlConfiguration.java:611)
	at org.eclipse.jetty.xml.XmlConfiguration$JettyXmlConfiguration.configure(XmlConfiguration.java:498)
	at org.eclipse.jetty.xml.XmlConfiguration$JettyXmlConfiguration.newObj(XmlConfiguration.java:1028)
	at org.eclipse.jetty.xml.XmlConfiguration$JettyXmlConfiguration.itemValue(XmlConfiguration.java:1543)
	at org.eclipse.jetty.xml.XmlConfiguration$JettyXmlConfiguration.value(XmlConfiguration.java:1444)
	at org.eclipse.jetty.xml.XmlConfiguration$JettyXmlConfiguration$Args.<init>(XmlConfiguration.java:1702)
	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)
2023-09-27 14:50:14.473:DEBUG:oejs.SetUID:main: OS specific file found: libsetuid-linux.so
2023-09-27 14:50:14.473:DEBUG:oejs.SetUID:main: setuid library libsetuid-linux.so
2023-09-27 14:50:14.473:DEBUG:oejs.SetUID:main: System.load((jetty.home)lib.getCanonicalPath()
2023-09-27 14:50:14.474:DEBUG:oejx.XmlConfiguration:main: XML [email protected] (jetty)
2023-09-27 14:50:14.474:DEBUG:oejx.XmlConfiguration:main: XML org.eclipse.jetty.setuid.SetUIDListener@6e4566f1.setClearSupplementalGroups (false)
2023-09-27 14:50:14.475:DEBUG:oejuc.ContainerLifeCycle:main: Server@7c83dc97{STOPPED}[10.0.17-SNAPSHOT,sto=5000] added {org.eclipse.jetty.setuid.SetUIDListener@6e4566f1,POJO}
2023-09-27 14:50:14.475:DEBUG:oejx.XmlParser:main: parsing: sid=null,pid=null
2023-09-27 14:50:14.475:DEBUG:oejx.XmlParser:main: resolveEntity(-//Jetty//Configure//EN,http://www.eclipse.org/jetty/configure_9_3.dtd)
2023-09-27 14:50:14.476:DEBUG:oejx.XmlParser:main: Redirected entity http://www.eclipse.org/jetty/configure_9_3.dtd  --> jar:file:/usr/local/jetty-home-10.0.17-SNAPSHOT/lib/jetty-xml-10.0.17-SNAPSHOT.jar!/org/eclipse/jetty/xml/configure_10_0.dtd
2023-09-27 14:50:14.479:DEBUG:oejx.XmlConfiguration:main: Configure file:///srv/www.myweb.com/jetty/etc/myweb.xml
2023-09-27 14:50:14.479:DEBUG:oejx.XmlConfiguration:main: Configure class org.eclipse.jetty.server.Server Server@7c83dc97{STOPPED}[10.0.17-SNAPSHOT,sto=5000]
2023-09-27 14:50:14.480:DEBUG:oejx.XmlConfiguration:main: XML new org.eclipse.jetty.plus.jndi.Resource
2023-09-27 14:50:14.480:DEBUG:oejx.XmlConfiguration:main: XML new com.zaxxer.hikari.HikariDataSource
2023-09-27 14:50:14.482:DEBUG:oejx.XmlConfiguration:main: XML new com.zaxxer.hikari.HikariConfig
2023-09-27 14:50:14.483:DEBUG:oejx.XmlConfiguration:main: XML [email protected] (13)
2023-09-27 14:50:14.483:DEBUG:oejx.XmlConfiguration:main: XML [email protected] (jdbc:mysql://localhost/myweb?useConfigs=maxPerformance&prepStmtCacheSize=250&prepStmtCacheSqlLimit=2048&useServerPrepStmts=true&cacheResultSetMetadata=true&cacheServerConfiguration=true&maintainTimeStats=false&serverTimezone=Europe/Madrid)
2023-09-27 14:50:14.483:DEBUG:oejx.XmlConfiguration:main: XML [email protected] (...)
2023-09-27 14:50:14.484:DEBUG:oejx.XmlConfiguration:main: XML [email protected] (...)
2023-09-27 14:50:14.484:DEBUG:oejx.XmlConfiguration:main: XML [email protected] (20000)
2023-09-27 14:50:14.484:DEBUG:oejx.XmlConfiguration:main: XML [email protected] (2000)
2023-09-27 14:50:14.484:DEBUG:oejx.XmlConfiguration:main: XML com.zaxxer.hikari.HikariConfig@5b1ebf56.setInitializationFailTimeout (20000)
2023-09-27 14:50:14.484:DEBUG:oejx.XmlConfiguration:main: XML [email protected] (true)
2023-09-27 14:50:14.484:DEBUG:oejx.XmlConfiguration:main: XML [email protected] (SessionsPool)
2023-09-27 14:50:14.487:INFO :czh.HikariDataSource:main: SessionsPool - Starting...
2023-09-27 14:50:14.662:INFO :czhp.HikariPool:main: SessionsPool - Added connection com.mysql.cj.jdbc.ConnectionImpl@464649c
2023-09-27 14:50:14.704:INFO :czh.HikariDataSource:main: SessionsPool - Start completed.
2023-09-27 14:50:14.704:DEBUG:oejpj.NamingEntry:main: SAVE org.eclipse.jetty.plus.jndi.Resource@6bc28a83{name=jdbc/sessions} in null
2023-09-27 14:50:14.716:DEBUG:oejj.InitialContextFactory:main: InitialContextFactory.getInitialContext()
2023-09-27 14:50:14.718:DEBUG:oejj.NamingContext:main: new org.eclipse.jetty.jndi.local.localContextRoot$NamingRoot@65f87a2c[name=null,parent=,bindings.size=0]
2023-09-27 14:50:14.719:DEBUG:oejj.InitialContextFactory:main: Created initial context delegate for local namespace:org.eclipse.jetty.jndi.local.localContextRoot@6ce1f601
2023-09-27 14:50:14.719:DEBUG:oejj.InitialContextFactory:main: InitialContextFactory.getInitialContext()
2023-09-27 14:50:14.719:DEBUG:oejj.InitialContextFactory:main: Created initial context delegate for local namespace:org.eclipse.jetty.jndi.local.localContextRoot@6e33c391
2023-09-27 14:50:14.720:DEBUG:oejjl.localContextRoot:main: Looking up name="__\"
2023-09-27 14:50:14.720:DEBUG:oejj.NamingContext:main: new org.eclipse.jetty.jndi.NamingContext@70eecdc2[name=__,parent=org.eclipse.jetty.jndi.local.localContextRoot$NamingRoot@65f87a2c,bindings.size=0]
2023-09-27 14:50:14.720:DEBUG:oejj.NamingContext:main: Adding binding with key=__  obj=org.eclipse.jetty.jndi.NamingContext@70eecdc2[name=__,parent=org.eclipse.jetty.jndi.local.localContextRoot$NamingRoot@65f87a2c,bindings.size=0] for context=null as __: org.eclipse.jetty.jndi.NamingContext:org.eclipse.jetty.jndi.NamingContext@70eecdc2[name=__,parent=org.eclipse.jetty.jndi.local.localContextRoot$NamingRoot@65f87a2c,bindings.size=0]
2023-09-27 14:50:14.723:DEBUG:oejj.NamingUtil:main: Subcontext __ created
2023-09-27 14:50:14.723:DEBUG:oejj.NamingContext:main: Looking up name="jdbc"
2023-09-27 14:50:14.724:DEBUG:oejj.NamingContext:main: new org.eclipse.jetty.jndi.NamingContext@49a64d82[name=jdbc,parent=org.eclipse.jetty.jndi.NamingContext@70eecdc2,bindings.size=0]
2023-09-27 14:50:14.724:DEBUG:oejj.NamingContext:main: Adding binding with key=jdbc  obj=org.eclipse.jetty.jndi.NamingContext@49a64d82[name=jdbc,parent=org.eclipse.jetty.jndi.NamingContext@70eecdc2,bindings.size=0] for context=__ as jdbc: org.eclipse.jetty.jndi.NamingContext:org.eclipse.jetty.jndi.NamingContext@49a64d82[name=jdbc,parent=org.eclipse.jetty.jndi.NamingContext@70eecdc2,bindings.size=0]
2023-09-27 14:50:14.724:DEBUG:oejj.NamingUtil:main: Subcontext jdbc created
2023-09-27 14:50:14.724:DEBUG:oejj.NamingContext:main: Removing binding with key=sessions
2023-09-27 14:50:14.724:DEBUG:oejj.NamingContext:main: Adding binding with key=sessions  obj=org.eclipse.jetty.plus.jndi.Resource@6bc28a83{name=jdbc/sessions} for context=jdbc as sessions: org.eclipse.jetty.plus.jndi.Resource:org.eclipse.jetty.plus.jndi.Resource@6bc28a83{name=jdbc/sessions}
2023-09-27 14:50:14.724:DEBUG:oejj.NamingUtil:main: Bound object to sessions
2023-09-27 14:50:14.724:DEBUG:oejjl.localContextRoot:main: Looking up name="jdbc\"
2023-09-27 14:50:14.724:DEBUG:oejj.NamingContext:main: new org.eclipse.jetty.jndi.NamingContext@66d23e4a[name=jdbc,parent=org.eclipse.jetty.jndi.local.localContextRoot$NamingRoot@65f87a2c,bindings.size=0]
2023-09-27 14:50:14.724:DEBUG:oejj.NamingContext:main: Adding binding with key=jdbc  obj=org.eclipse.jetty.jndi.NamingContext@66d23e4a[name=jdbc,parent=org.eclipse.jetty.jndi.local.localContextRoot$NamingRoot@65f87a2c,bindings.size=0] for context=null as jdbc: org.eclipse.jetty.jndi.NamingContext:org.eclipse.jetty.jndi.NamingContext@66d23e4a[name=jdbc,parent=org.eclipse.jetty.jndi.local.localContextRoot$NamingRoot@65f87a2c,bindings.size=0]
2023-09-27 14:50:14.724:DEBUG:oejj.NamingUtil:main: Subcontext jdbc created
2023-09-27 14:50:14.724:DEBUG:oejj.NamingContext:main: Removing binding with key=sessions
2023-09-27 14:50:14.725:DEBUG:oejj.NamingContext:main: Adding binding with key=sessions  obj=HikariDataSource (SessionsPool) for context=jdbc as sessions: com.zaxxer.hikari.HikariDataSource:HikariDataSource (SessionsPool)
2023-09-27 14:50:14.725:DEBUG:oejj.NamingUtil:main: Bound object to sessions
2023-09-27 14:50:14.725:DEBUG:oejx.XmlConfiguration:main: XML call addConnector
2023-09-27 14:50:14.725:DEBUG:oejx.XmlConfiguration:main: XML new org.eclipse.jetty.server.ServerConnector
2023-09-27 14:50:14.725:DEBUG:oejx.XmlConfiguration:main: XML new org.eclipse.jetty.server.HttpConnectionFactory
2023-09-27 14:50:14.725:DEBUG:oejuc.ContainerLifeCycle:main: HttpConnectionFactory@36ac8a63[HTTP/1.1] added {HttpConfiguration@3fb1549b{32768/8192,8192/8192,https://:0,[ForwardedRequestCustomizer@59a008ba]},POJO}
2023-09-27 14:50:14.725:DEBUG:oejx.XmlConfiguration:main: XML new org.eclipse.jetty.http2.server.HTTP2CServerConnectionFactory
2023-09-27 14:50:14.725:DEBUG:oejuc.ContainerLifeCycle:main: HTTP2CServerConnectionFactory@4d9d1b69[h2c] added {HTTP2SessionContainer@52c8295b[size=0],POJO}
2023-09-27 14:50:14.725:DEBUG:oejuc.ContainerLifeCycle:main: HTTP2CServerConnectionFactory@4d9d1b69[h2c] added {HttpConfiguration@3fb1549b{32768/8192,8192/8192,https://:0,[ForwardedRequestCustomizer@59a008ba]},POJO}
2023-09-27 14:50:14.725:DEBUG:oejx.XmlConfiguration:main: XML HTTP2CServerConnectionFactory@4d9d1b69[h2c].setMaxConcurrentStreams (1024)
2023-09-27 14:50:14.726:DEBUG:oejx.XmlConfiguration:main: XML HTTP2CServerConnectionFactory@4d9d1b69[h2c].setInitialStreamRecvWindow (65535)
2023-09-27 14:50:14.726:DEBUG:oejuc.ContainerLifeCycle:main: ServerConnector@251f7d26{null, ()}{0.0.0.0:0} added {QueuedThreadPool[qtp1020520290]@3cd3e762{STOPPED,10<=0<=1000,i=0,r=-1,t=-712403424ms,q=0}[NO_TRY],AUTO}
2023-09-27 14:50:14.726:DEBUG:oejuc.ContainerLifeCycle:main: ServerConnector@251f7d26{null, ()}{0.0.0.0:0} added {ScheduledExecutorScheduler@4da4253{STOPPED},AUTO}
2023-09-27 14:50:14.726:DEBUG:oejuc.ContainerLifeCycle:main: ServerConnector@251f7d26{null, ()}{0.0.0.0:0} added {ArrayByteBufferPool@3315d2d7{minBufferCapacity=0, maxBufferCapacity=65536, maxQueueLength=-1, factor=4096},UNMANAGED}
2023-09-27 14:50:14.726:DEBUG:oejuc.ContainerLifeCycle:main: ServerConnector@251f7d26{null, ()}{0.0.0.0:0} added {org.eclipse.jetty.io.ArrayByteBufferPool$Retained@662706a7{min=0,max=65536,buckets=16,heap=0/4200595456,direct=0/4200595456},POJO}
2023-09-27 14:50:14.726:DEBUG:oejuc.ContainerLifeCycle:main: ServerConnector@251f7d26{null, ()}{0.0.0.0:0} added {org.eclipse.jetty.server.AbstractConnector$1@77b21474,POJO}
2023-09-27 14:50:14.727:DEBUG:oejuc.ContainerLifeCycle:main: ServerConnector@251f7d26{null, (http/1.1)}{0.0.0.0:0} added {HttpConnectionFactory@36ac8a63[HTTP/1.1],AUTO}
2023-09-27 14:50:14.727:DEBUG:oejs.AbstractConnector:main: ServerConnector@251f7d26{HTTP/1.1, (http/1.1)}{0.0.0.0:0} added HttpConnectionFactory@36ac8a63[HTTP/1.1]
2023-09-27 14:50:14.727:DEBUG:oejuc.ContainerLifeCycle:main: ServerConnector@251f7d26{HTTP/1.1, (http/1.1, h2c)}{0.0.0.0:0} added {HTTP2CServerConnectionFactory@4d9d1b69[h2c],AUTO}
2023-09-27 14:50:14.727:DEBUG:oejs.AbstractConnector:main: ServerConnector@251f7d26{HTTP/1.1, (http/1.1, h2c)}{0.0.0.0:0} added HTTP2CServerConnectionFactory@4d9d1b69[h2c]
2023-09-27 14:50:14.727:DEBUG:oejuc.ContainerLifeCycle:main: ServerConnector@251f7d26{HTTP/1.1, (http/1.1, h2c)}{0.0.0.0:0} added {SelectorManager@ServerConnector@251f7d26{HTTP/1.1, (http/1.1, h2c)}{0.0.0.0:0},MANAGED}
2023-09-27 14:50:14.727:DEBUG:oejx.XmlConfiguration:main: XML ServerConnector@251f7d26{HTTP/1.1, (http/1.1, h2c)}{0.0.0.0:0}.setHost (null)
2023-09-27 14:50:14.727:DEBUG:oejx.XmlConfiguration:main: XML ServerConnector@251f7d26{HTTP/1.1, (http/1.1, h2c)}{0.0.0.0:0}.setPort (8082)
2023-09-27 14:50:14.727:DEBUG:oejx.XmlConfiguration:main: XML ServerConnector@251f7d26{HTTP/1.1, (http/1.1, h2c)}{0.0.0.0:8082}.setIdleTimeout (150000)
2023-09-27 14:50:14.727:DEBUG:oejx.XmlConfiguration:main: XML ServerConnector@251f7d26{HTTP/1.1, (http/1.1, h2c)}{0.0.0.0:8082}.setAcceptorPriorityDelta (0)
2023-09-27 14:50:14.728:DEBUG:oejx.XmlConfiguration:main: XML ServerConnector@251f7d26{HTTP/1.1, (http/1.1, h2c)}{0.0.0.0:8082}.setAcceptQueueSize (0)
2023-09-27 14:50:14.728:DEBUG:oejuc.ContainerLifeCycle:main: Server@7c83dc97{STOPPED}[10.0.17-SNAPSHOT,sto=5000] added {ServerConnector@251f7d26{HTTP/1.1, (http/1.1, h2c)}{0.0.0.0:8082},AUTO}
2023-09-27 14:50:14.728:DEBUG:oejx.XmlConfiguration:main: objects=[Server@7c83dc97{STOPPED}[10.0.17-SNAPSHOT,sto=5000], ServerConnector@5e403b4a{HTTP/1.1, (http/1.1, h2c)}{0.0.0.0:8081}, HttpConfiguration@3fb1549b{32768/8192,8192/8192,https://:0,[ForwardedRequestCustomizer@59a008ba]}]
2023-09-27 14:50:14.728:DEBUG:oejuc.AbstractLifeCycle:main: STARTING Server@7c83dc97{STOPPED}[10.0.17-SNAPSHOT,sto=5000]
2023-09-27 14:50:14.728:DEBUG:oejs.StateLifeCycleListener:main: appendEntry to /srv/www.myweb.com/jetty/jetty.state: STARTING Server@7c83dc97{STARTING}[10.0.17-SNAPSHOT,sto=5000]|
2023-09-27 14:50:14.728:INFO :oejs.SetUIDListener:main: Setting umask=02
2023-09-27 14:50:14.728:DEBUG:oejuc.AbstractLifeCycle:main: STARTING QueuedThreadPool[qtp1020520290]@3cd3e762{STOPPED,10<=0<=1000,i=0,r=-1,t=-712403426ms,q=0}[NO_TRY]
2023-09-27 14:50:14.729:DEBUG:oejut.ReservedThreadExecutor:main: ReservedThreadExecutor@503d56b5{reserved=0/8,pending=0}
2023-09-27 14:50:14.729:DEBUG:oejuc.ContainerLifeCycle:main: QueuedThreadPool[qtp1020520290]@3cd3e762{STARTING,10<=0<=1000,i=0,r=-1,t=-712403427ms,q=0}[ReservedThreadExecutor@503d56b5{reserved=0/8,pending=0}] added {ReservedThreadExecutor@503d56b5{reserved=0/8,pending=0},AUTO}
2023-09-27 14:50:14.729:DEBUG:oejuc.AbstractLifeCycle:main: STARTING ReservedThreadExecutor@503d56b5{reserved=0/8,pending=0}
2023-09-27 14:50:14.731:DEBUG:oejuc.AbstractLifeCycle:main: STARTED @1051ms ReservedThreadExecutor@503d56b5{reserved=0/8,pending=0}
2023-09-27 14:50:14.736:DEBUG:oejut.QueuedThreadPool:main: Starting Thread[qtp1020520290-17,5,main]
2023-09-27 14:50:14.736:DEBUG:oejut.QueuedThreadPool:main: Starting Thread[qtp1020520290-18,5,main]
2023-09-27 14:50:14.737:DEBUG:oejut.QueuedThreadPool:main: Starting Thread[qtp1020520290-19,5,main]
2023-09-27 14:50:14.736:DEBUG:oejut.QueuedThreadPool:qtp1020520290-17: Runner started for QueuedThreadPool[qtp1020520290]@3cd3e762{STARTING,10<=2<=1000,i=2,r=-1,t=59999ms,q=0}[ReservedThreadExecutor@503d56b5{reserved=0/8,pending=0}]
2023-09-27 14:50:14.737:DEBUG:oejut.QueuedThreadPool:qtp1020520290-18: Runner started for QueuedThreadPool[qtp1020520290]@3cd3e762{STARTING,10<=3<=1000,i=3,r=-1,t=59999ms,q=0}[ReservedThreadExecutor@503d56b5{reserved=0/8,pending=0}]
2023-09-27 14:50:14.737:DEBUG:oejut.QueuedThreadPool:main: Starting Thread[qtp1020520290-20,5,main]
2023-09-27 14:50:14.737:DEBUG:oejut.QueuedThreadPool:qtp1020520290-19: Runner started for QueuedThreadPool[qtp1020520290]@3cd3e762{STARTING,10<=4<=1000,i=4,r=-1,t=59999ms,q=0}[ReservedThreadExecutor@503d56b5{reserved=0/8,pending=0}]
2023-09-27 14:50:14.737:DEBUG:oejut.QueuedThreadPool:main: Starting Thread[qtp1020520290-21,5,main]
2023-09-27 14:50:14.737:DEBUG:oejut.QueuedThreadPool:qtp1020520290-20: Runner started for QueuedThreadPool[qtp1020520290]@3cd3e762{STARTING,10<=5<=1000,i=5,r=-1,t=59999ms,q=0}[ReservedThreadExecutor@503d56b5{reserved=0/8,pending=0}]
2023-09-27 14:50:14.737:DEBUG:oejut.QueuedThreadPool:main: Starting Thread[qtp1020520290-22,5,main]
2023-09-27 14:50:14.737:DEBUG:oejut.QueuedThreadPool:main: Starting Thread[qtp1020520290-23,5,main]
2023-09-27 14:50:14.737:DEBUG:oejut.QueuedThreadPool:qtp1020520290-21: Runner started for QueuedThreadPool[qtp1020520290]@3cd3e762{STARTING,10<=6<=1000,i=6,r=-1,t=59999ms,q=0}[ReservedThreadExecutor@503d56b5{reserved=0/8,pending=0}]
2023-09-27 14:50:14.737:DEBUG:oejut.QueuedThreadPool:qtp1020520290-22: Runner started for QueuedThreadPool[qtp1020520290]@3cd3e762{STARTING,10<=7<=1000,i=7,r=-1,t=59999ms,q=0}[ReservedThreadExecutor@503d56b5{reserved=0/8,pending=0}]
2023-09-27 14:50:14.738:DEBUG:oejut.QueuedThreadPool:main: Starting Thread[qtp1020520290-24,5,main]
2023-09-27 14:50:14.738:DEBUG:oejut.QueuedThreadPool:qtp1020520290-23: Runner started for QueuedThreadPool[qtp1020520290]@3cd3e762{STARTING,10<=8<=1000,i=8,r=-1,t=59999ms,q=0}[ReservedThreadExecutor@503d56b5{reserved=0/8,pending=0}]
2023-09-27 14:50:14.738:DEBUG:oejut.QueuedThreadPool:main: Starting Thread[qtp1020520290-25,5,main]
2023-09-27 14:50:14.738:DEBUG:oejut.QueuedThreadPool:qtp1020520290-24: Runner started for QueuedThreadPool[qtp1020520290]@3cd3e762{STARTING,10<=9<=1000,i=9,r=-1,t=59999ms,q=0}[ReservedThreadExecutor@503d56b5{reserved=0/8,pending=0}]
2023-09-27 14:50:14.738:DEBUG:oejut.QueuedThreadPool:main: Starting Thread[qtp1020520290-26,5,main]
2023-09-27 14:50:14.738:DEBUG:oejut.QueuedThreadPool:qtp1020520290-25: Runner started for QueuedThreadPool[qtp1020520290]@3cd3e762{STARTING,10<=10<=1000,i=10,r=-1,t=59999ms,q=0}[ReservedThreadExecutor@503d56b5{reserved=0/8,pending=0}]
2023-09-27 14:50:14.739:DEBUG:oejuc.AbstractLifeCycle:main: STARTED @1059ms QueuedThreadPool[qtp1020520290]@3cd3e762{STARTED,10<=10<=1000,i=10,r=-1,t=59999ms,q=0}[ReservedThreadExecutor@503d56b5{reserved=0/8,pending=0}]
2023-09-27 14:50:14.739:DEBUG:oejut.QueuedThreadPool:qtp1020520290-26: Runner started for QueuedThreadPool[qtp1020520290]@3cd3e762{STARTED,10<=10<=1000,i=10,r=-1,t=59999ms,q=0}[ReservedThreadExecutor@503d56b5{reserved=0/8,pending=0}]
2023-09-27 14:50:14.742:DEBUG:oejuc.ContainerLifeCycle:main: ServerConnector@5e403b4a{HTTP/1.1, (http/1.1, h2c)}{0.0.0.0:8081} added {sun.nio.ch.ServerSocketChannelImpl[/0:0:0:0:0:0:0:0:8081],POJO}
2023-09-27 14:50:14.743:INFO :oejs.SetUIDListener:main: Opened ServerConnector@5e403b4a{HTTP/1.1, (http/1.1, h2c)}{0.0.0.0:8081}
2023-09-27 14:50:14.743:DEBUG:oejuc.ContainerLifeCycle:main: ServerConnector@251f7d26{HTTP/1.1, (http/1.1, h2c)}{0.0.0.0:8082} added {sun.nio.ch.ServerSocketChannelImpl[/0:0:0:0:0:0:0:0:8082],POJO}
2023-09-27 14:50:14.743:INFO :oejs.SetUIDListener:main: Opened ServerConnector@251f7d26{HTTP/1.1, (http/1.1, h2c)}{0.0.0.0:8082}
2023-09-27 14:50:14.743:INFO :oejs.SetUIDListener:main: Setting GID=1004
2023-09-27 14:50:14.743:INFO :oejs.SetUIDListener:main: Setting UID=1003
2023-09-27 14:50:14.744:DEBUG:oejuc.ContainerLifeCycle:main: Server@7c83dc97{STARTING}[10.0.17-SNAPSHOT,sto=5000] added {ErrorHandler@1a38ba58{STOPPED},AUTO}
2023-09-27 14:50:14.746:INFO :oejs.Server:main: jetty-10.0.17-SNAPSHOT; built: 2023-09-21T21:58:08.927Z; git: c8e8ad5b3d22221229075c2decbad3995ed57988; jvm 11.0.20.1+1
2023-09-27 14:50:14.754:DEBUG:oejsh.AbstractHandler:main: starting Server@7c83dc97{STARTING}[10.0.17-SNAPSHOT,sto=5000]
2023-09-27 14:50:14.755:DEBUG:oejuc.AbstractLifeCycle:main: STARTING AttributeContainerMap@568ff82{size=1}
2023-09-27 14:50:14.755:DEBUG:oejuc.AbstractLifeCycle:main: STARTED @1075ms AttributeContainerMap@568ff82{size=1}
2023-09-27 14:50:14.755:DEBUG:oejuc.AbstractLifeCycle:main: STARTING ScheduledExecutorScheduler@4da4253{STOPPED}
2023-09-27 14:50:14.755:DEBUG:oejuc.AbstractLifeCycle:main: STARTED @1075ms ScheduledExecutorScheduler@4da4253{STARTED}
2023-09-27 14:50:14.755:DEBUG:oejuc.AbstractLifeCycle:main: STARTING DeploymentManager@23941fb4{STOPPED}
2023-09-27 14:50:14.755:DEBUG:oejd.DeploymentManager:main: DeploymentManager using standard bindings
2023-09-27 14:50:14.756:DEBUG:oejuc.AbstractLifeCycle:main: STARTING class org.eclipse.jetty.deploy.providers.WebAppProvider@1a5a4e19[file:///srv/www.myweb.com/jetty/webapps/]
2023-09-27 14:50:14.756:DEBUG:oejdp.ScanningAppProvider:main: WebAppProvider.doStart()
2023-09-27 14:50:14.756:INFO :oejdp.ScanningAppProvider:main: Deployment monitor [file:///srv/www.myweb.com/jetty/webapps/]
2023-09-27 14:50:14.757:DEBUG:oejuc.ContainerLifeCycle:main: Scanner@11963225{STOPPED} added {ScheduledExecutorScheduler@3f3c966c{STOPPED},AUTO}
2023-09-27 14:50:14.758:DEBUG:oejuc.ContainerLifeCycle:main: class org.eclipse.jetty.deploy.providers.WebAppProvider@1a5a4e19[file:///srv/www.myweb.com/jetty/webapps/] added {Scanner@11963225{STOPPED},AUTO}
2023-09-27 14:50:14.758:DEBUG:oejuc.AbstractLifeCycle:main: STARTING Scanner@11963225{STOPPED}
2023-09-27 14:50:14.758:DEBUG:oeju.Scanner:main: Scanner start: rprtExists=true, depth=1, rprtDirs=true, interval=1, filter=org.eclipse.jetty.deploy.providers.WebAppProvider$Filter@3a71c100, scannables={/srv/www.myweb.com/jetty/webapps=IncludeExcludeSet@5b69fd74{i=[],ip=SELF,e=[],ep=SELF}}
2023-09-27 14:50:14.761:DEBUG:oeju.Scanner:main: scan accepted /srv/www.myweb.com/jetty/webapps/ROOT mod=1695817746998
2023-09-27 14:50:14.761:DEBUG:oeju.Scanner:main: scanned [/srv/www.myweb.com/jetty/webapps]
2023-09-27 14:50:14.761:DEBUG:oeju.Scanner:main: scan accepted /srv/www.myweb.com/jetty/webapps/ROOT mod=1695817746998
2023-09-27 14:50:14.762:DEBUG:oeju.Scanner:main: scanned [/srv/www.myweb.com/jetty/webapps]
2023-09-27 14:50:14.762:DEBUG:oejdp.ScanningAppProvider:main: added /srv/www.myweb.com/jetty/webapps/ROOT
2023-09-27 14:50:14.762:DEBUG:oejd.DeploymentManager:main: Deployable added: /srv/www.myweb.com/jetty/webapps/ROOT
[...]

@joakime
Copy link
Contributor

joakime commented Sep 27, 2023 •
edited
Loading 

2023-09-27 14:50:14.728:DEBUG:oejs.StateLifeCycleListener:main: appendEntry to /srv/www.myweb.com/jetty/jetty.state: STARTING Server@7c83dc97{STARTING}[10.0.17-SNAPSHOT,sto=5000]|

Looks like the state file was created and had content put in it.

Why can't the jetty.sh script read from it?
Looks like there was a setuid change about the same time.

Can you try this from the command line, as the user running Jetty. (uid=1003, gid=1004).

$ if [ -r "/srv/www.myweb.com/jetty/jetty.state" ] ; then echo "Can Read"; else echo "Cannot Read"; fi

It should return "Can Read"

Also, try disabling the setuid module temporarily and see if the jetty.sh can start that Jetty instance.

@ofrias
Copy link

ofrias commented Sep 27, 2023

Can you try this from the command line, as the user running Jetty. (uid=1003, gid=1004).

$ if [ -r "/srv/www.myweb.com/jetty/jetty.state" ] ; then echo "Can Read"; else echo "Cannot Read"; fi

It should return "Can Read"

Yes, it returns "Can Read" and file permissions seem right:

-rw-r--r-- 1 root root 99 Sep 27 15:45 jetty.state

Also, try disabling the setuid module temporarily and see if the jetty.sh can start that Jetty instance.

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

@joakime joakime reopened this Sep 27, 2023
@joakime joakime moved this from ✅ Done to 🏗 In progress in Jetty 10.0.17 / 11.0.17 FROZEN Sep 27, 2023
@joakime
Copy link
Contributor

joakime commented Sep 27, 2023

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

@joakime
Copy link
Contributor

joakime commented Sep 27, 2023

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
Copy link
Contributor

joakime commented Sep 27, 2023

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
Copy link

ofrias commented Sep 27, 2023

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
Copy link
Contributor

joakime commented Sep 27, 2023

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 added a commit that referenced this issue Sep 27, 2023
@joakime
Issue #10473 - Better warnings in jetty.sh on filesystem permission i…
216c2dd 
…ssues

Signed-off-by: Joakim Erdfelt <[email protected]>
joakime added a commit that referenced this issue Sep 27, 2023
@joakime
Issue #10473 - JETTY_RUN version
60e713c 
Signed-off-by: Joakim Erdfelt <[email protected]>
@joakime joakime linked a pull request Sep 27, 2023 that will close this issue
Issue #10473 - Better warnings in jetty.sh on filesystem permission issues #10605
Merged
@joakime
Copy link
Contributor

joakime commented Sep 27, 2023

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

joakime added a commit that referenced this issue Sep 27, 2023
@joakime
Issue #10473 - Move "Starting Jetty: " to later
85ba90f 
Signed-off-by: Joakim Erdfelt <[email protected]>
joakime added a commit that referenced this issue Sep 28, 2023
@joakime
Issue #10473 - Better warnings in jetty.sh on filesystem permission…
551ad8b 
… issues (#10605)

* Issue #10473 - Better warnings in jetty.sh on filesystem permission issues

Signed-off-by: Joakim Erdfelt <[email protected]>
@github-project-automation github-project-automation bot moved this from 🏗 In progress to ✅ Done in Jetty 10.0.17 / 11.0.17 FROZEN Sep 28, 2023
@olamy olamy mentioned this issue Oct 1, 2023
Closed
@ofrias
Copy link

ofrias commented Oct 10, 2023

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
Copy link
Contributor

joakime commented Oct 10, 2023

@ofrias we encountered this as well.

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
Bug For general bugs on Jetty side
Projects
None yet
Milestone
No milestone
4 participants
@joakime @gskjold @l-cdc @ofrias