OOM crash, likely due to plugin list fetch

[danbulant]

trafficstars

Jenkins and plugins versions report

Environment

Jenkins: 2.333
OS: Linux - 5.15.12-arch1-1
---

What Operating System are you using (both controller, and any agents involved in the problem)?

Arch Linux x86_64 (5.15.12-arch1-1)

VM, using KVM/QEMU (Contabo VPS). 8GB RAM total, jenkins on Docker managed by Nomad with 2GB reserved and 5GB hard limit. No disk space limits.

Reproduction steps

1. setup docker container (default jenkins/jenkins image with no configuration).
2. create default user
3. restart
4. OOM crash (multiple times), likely because of plugin fetching (later when I somehow made it not crash, the list of plugins was empty, even though logs said that they were fetched correctly. Clicking check now on the plugin page made it crash again, but after another restart the list was there.

Expected Results

Normal memory use (<1GB when idle and no jobs or plugins configured)

Actual Results

OOM killed, using more than 2GB of memory (sometimes)

Anything else?

/var/jenkins_home is bind mounted. /var/run/docker.sock is a volume pointing to the host docker engine. /etc/hosts is volume pointed (normal DNS worked, but localhost failed to resolve).

During first few tries, I had problems with internet (all connections were timing out). When this occured, there were logs about connections timing out, but jenkins said it finished up correctly, but wasn't accessible over HTTP.

Jenkins is on a host network (issues with setting up nomad+consul+docker correctly to network).

Logs are the same between normal runs and runs where it runs out of memory (except nomad added OOM killed).

STDOUT

Running from: /usr/share/jenkins/jenkins.war
webroot: EnvVars.masterEnvVars.get("JENKINS_HOME")

STDERR

2022-02-05 18:07:09.160+0000 [id=1]	INFO	org.eclipse.jetty.util.log.Log#initialized: Logging initialized @883ms to org.eclipse.jetty.util.log.JavaUtilLog
2022-02-05 18:07:09.283+0000 [id=1]	INFO	winstone.Logger#logInternal: Beginning extraction from war file
2022-02-05 18:07:09.322+0000 [id=1]	WARNING	o.e.j.s.handler.ContextHandler#setContextPath: Empty contextPath
2022-02-05 18:07:09.412+0000 [id=1]	INFO	org.eclipse.jetty.server.Server#doStart: jetty-9.4.43.v20210629; built: 2021-06-30T11:07:22.254Z; git: 526006ecfa3af7f1a27ef3a288e2bef7ea9dd7e8; jvm 11.0.13+8
2022-02-05 18:07:09.915+0000 [id=1]	INFO	o.e.j.w.StandardDescriptorProcessor#visitServlet: NO JSP Support for /, did not find org.eclipse.jetty.jsp.JettyJspServlet
2022-02-05 18:07:09.986+0000 [id=1]	INFO	o.e.j.s.s.DefaultSessionIdManager#doStart: DefaultSessionIdManager workerName=node0
2022-02-05 18:07:09.986+0000 [id=1]	INFO	o.e.j.s.s.DefaultSessionIdManager#doStart: No SessionScavenger set, using defaults
2022-02-05 18:07:09.989+0000 [id=1]	INFO	o.e.j.server.session.HouseKeeper#startScavenging: node0 Scavenging every 660000ms
2022-02-05 18:07:10.791+0000 [id=1]	INFO	hudson.WebAppMain#contextInitialized: Jenkins home directory: /var/jenkins_home found at: EnvVars.masterEnvVars.get("JENKINS_HOME")
2022-02-05 18:07:11.250+0000 [id=1]	INFO	o.e.j.s.handler.ContextHandler#doStart: Started w.@169da7f2{Jenkins v2.333,/,file:///var/jenkins_home/war/,AVAILABLE}{/var/jenkins_home/war}
2022-02-05 18:07:11.326+0000 [id=1]	INFO	o.e.j.server.AbstractConnector#doStart: Started ServerConnector@5b7a5baa{HTTP/1.1, (http/1.1)}{0.0.0.0:8080}
2022-02-05 18:07:11.326+0000 [id=1]	INFO	org.eclipse.jetty.server.Server#doStart: Started @3068ms
2022-02-05 18:07:11.334+0000 [id=24]	INFO	winstone.Logger#logInternal: Winstone Servlet Engine running: controlPort=disabled
2022-02-05 18:07:12.085+0000 [id=31]	INFO	jenkins.InitReactorRunner$1#onAttained: Started initialization
2022-02-05 18:07:12.208+0000 [id=29]	INFO	jenkins.InitReactorRunner$1#onAttained: Listed all plugins
2022-02-05 18:07:13.827+0000 [id=29]	INFO	jenkins.InitReactorRunner$1#onAttained: Prepared all plugins
2022-02-05 18:07:13.840+0000 [id=32]	INFO	jenkins.InitReactorRunner$1#onAttained: Started all plugins
2022-02-05 18:07:13.848+0000 [id=35]	INFO	jenkins.InitReactorRunner$1#onAttained: Augmented all extensions
2022-02-05 18:07:14.487+0000 [id=35]	INFO	jenkins.InitReactorRunner$1#onAttained: System config loaded
2022-02-05 18:07:14.489+0000 [id=36]	INFO	jenkins.InitReactorRunner$1#onAttained: System config adapted
2022-02-05 18:07:14.489+0000 [id=36]	INFO	jenkins.InitReactorRunner$1#onAttained: Loaded all jobs
2022-02-05 18:07:14.496+0000 [id=31]	INFO	jenkins.InitReactorRunner$1#onAttained: Configuration for all jobs updated
2022-02-05 18:07:14.572+0000 [id=49]	INFO	hudson.model.AsyncPeriodicWork#lambda$doRun$1: Started Download metadata
2022-02-05 18:07:14.605+0000 [id=49]	INFO	hudson.model.AsyncPeriodicWork#lambda$doRun$1: Finished Download metadata. 6 ms
WARNING: An illegal reflective access operation has occurred
WARNING: Illegal reflective access by org.codehaus.groovy.reflection.CachedClass (file:/var/jenkins_home/war/WEB-INF/lib/groovy-all-2.4.21.jar) to method java.lang.Object.finalize()
WARNING: Please consider reporting this to the maintainers of org.codehaus.groovy.reflection.CachedClass
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
2022-02-05 18:07:15.086+0000 [id=35]	INFO	jenkins.InitReactorRunner$1#onAttained: Completed initialization
2022-02-05 18:07:15.366+0000 [id=23]	INFO	hudson.lifecycle.Lifecycle#onReady: Jenkins is fully up and running
2022-02-05 18:07:52.148+0000 [id=68]	INFO	hudson.util.Retrier#start: Attempt #1 to do the action check updates server
2022-02-05 18:08:29.678+0000 [id=1]	INFO	org.eclipse.jetty.util.log.Log#initialized: Logging initialized @931ms to org.eclipse.jetty.util.log.JavaUtilLog
2022-02-05 18:08:29.861+0000 [id=1]	INFO	winstone.Logger#logInternal: Beginning extraction from war file
2022-02-05 18:08:29.905+0000 [id=1]	WARNING	o.e.j.s.handler.ContextHandler#setContextPath: Empty contextPath
2022-02-05 18:08:29.994+0000 [id=1]	INFO	org.eclipse.jetty.server.Server#doStart: jetty-9.4.43.v20210629; built: 2021-06-30T11:07:22.254Z; git: 526006ecfa3af7f1a27ef3a288e2bef7ea9dd7e8; jvm 11.0.13+8
2022-02-05 18:08:30.478+0000 [id=1]	INFO	o.e.j.w.StandardDescriptorProcessor#visitServlet: NO JSP Support for /, did not find org.eclipse.jetty.jsp.JettyJspServlet
2022-02-05 18:08:30.562+0000 [id=1]	INFO	o.e.j.s.s.DefaultSessionIdManager#doStart: DefaultSessionIdManager workerName=node0
2022-02-05 18:08:30.563+0000 [id=1]	INFO	o.e.j.s.s.DefaultSessionIdManager#doStart: No SessionScavenger set, using defaults
2022-02-05 18:08:30.565+0000 [id=1]	INFO	o.e.j.server.session.HouseKeeper#startScavenging: node0 Scavenging every 660000ms
2022-02-05 18:08:31.399+0000 [id=1]	INFO	hudson.WebAppMain#contextInitialized: Jenkins home directory: /var/jenkins_home found at: EnvVars.masterEnvVars.get("JENKINS_HOME")
2022-02-05 18:08:31.866+0000 [id=1]	INFO	o.e.j.s.handler.ContextHandler#doStart: Started w.@169da7f2{Jenkins v2.333,/,file:///var/jenkins_home/war/,AVAILABLE}{/var/jenkins_home/war}
2022-02-05 18:08:31.901+0000 [id=1]	INFO	o.e.j.server.AbstractConnector#doStart: Started ServerConnector@776aec5c{HTTP/1.1, (http/1.1)}{0.0.0.0:8080}
2022-02-05 18:08:31.901+0000 [id=1]	INFO	org.eclipse.jetty.server.Server#doStart: Started @3158ms
2022-02-05 18:08:31.909+0000 [id=24]	INFO	winstone.Logger#logInternal: Winstone Servlet Engine running: controlPort=disabled
2022-02-05 18:08:32.397+0000 [id=31]	INFO	jenkins.InitReactorRunner$1#onAttained: Started initialization
2022-02-05 18:08:32.498+0000 [id=33]	INFO	jenkins.InitReactorRunner$1#onAttained: Listed all plugins
2022-02-05 18:08:34.280+0000 [id=30]	INFO	jenkins.InitReactorRunner$1#onAttained: Prepared all plugins
2022-02-05 18:08:34.288+0000 [id=30]	INFO	jenkins.InitReactorRunner$1#onAttained: Started all plugins
2022-02-05 18:08:34.294+0000 [id=31]	INFO	jenkins.InitReactorRunner$1#onAttained: Augmented all extensions
2022-02-05 18:08:34.776+0000 [id=34]	INFO	jenkins.InitReactorRunner$1#onAttained: System config loaded
2022-02-05 18:08:34.778+0000 [id=34]	INFO	jenkins.InitReactorRunner$1#onAttained: System config adapted
2022-02-05 18:08:34.779+0000 [id=34]	INFO	jenkins.InitReactorRunner$1#onAttained: Loaded all jobs
2022-02-05 18:08:34.782+0000 [id=34]	INFO	jenkins.InitReactorRunner$1#onAttained: Configuration for all jobs updated
2022-02-05 18:08:34.837+0000 [id=49]	INFO	hudson.model.AsyncPeriodicWork#lambda$doRun$1: Started Download metadata
2022-02-05 18:08:34.890+0000 [id=49]	INFO	hudson.model.AsyncPeriodicWork#lambda$doRun$1: Finished Download metadata. 17 ms
WARNING: An illegal reflective access operation has occurred
WARNING: Illegal reflective access by org.codehaus.groovy.reflection.CachedClass (file:/var/jenkins_home/war/WEB-INF/lib/groovy-all-2.4.21.jar) to method java.lang.Object.finalize()
WARNING: Please consider reporting this to the maintainers of org.codehaus.groovy.reflection.CachedClass
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
2022-02-05 18:08:35.252+0000 [id=30]	INFO	jenkins.InitReactorRunner$1#onAttained: Completed initialization
2022-02-05 18:08:35.486+0000 [id=23]	INFO	hudson.lifecycle.Lifecycle#onReady: Jenkins is fully up and running

[MarkEWaite]

I can't duplicate the problem on the configuration that I tested. I tested:

$ cat /etc/os-release
PRETTY_NAME="Debian GNU/Linux 10 (buster)"
NAME="Debian GNU/Linux"
VERSION_ID="10"
VERSION="10 (buster)"
VERSION_CODENAME=buster
ID=debian
HOME_URL="https://www.debian.org/"
SUPPORT_URL="https://www.debian.org/support"
BUG_REPORT_URL="https://bugs.debian.org/"
$ docker --version
Docker version 20.10.14, build a224086
$ uname -a
Linux debian10-c 4.19.0-19-amd64 #1 SMP Debian 4.19.232-1 (2022-03-07) x86_64 GNU/Linux
mwaite@debian10-c:~$

$ docker run --memory=5g --memory-reservation=2g -p 8080:8080 jenkins/jenkins:2.340

I did not attempt to bind mount the docker socket, the /etc/hosts file, or to bind mount the Jenkins home directory.

I installed the suggested plugins during the initial Jenkins setup wizard, then installed several additional plugins without any issue. Jenkins restart had no issue and was well behaved.