Post build status update jenkins job seems to be broken

[MoLow]

https://ci.nodejs.org/job/post-build-status-update/buildTimeTrend

[richardlau]

I suspect this is related to the Script Security plugin update from yesterday (#3158) 😞.

The bot is still posting comments from other webhook triggers, (e.g. nodejs/node#46365 (comment) from 2 hours ago) so it looks like the issue is specifically with the post-build-status-update job.

I am seeing errors in the main Jenkins system log (https://ci.nodejs.org/log/all) relating to the post-build-status-update job:

Jan 26, 2023 8:07:09 AM WARNING org.jenkinsci.plugins.workflow.job.WorkflowRun getLogFile
Avoid calling getLogFile on post-build-status-update #1786251
java.lang.UnsupportedOperationException
	at org.jenkinsci.plugins.workflow.job.WorkflowRun.getLogFile(WorkflowRun.java:1163)
	at org.jenkinsci.plugins.compressbuildlog.BuildLogCompressor$CompressBuildlogRunListener.onFinalized(BuildLogCompressor.java:85)
	at hudson.model.listeners.RunListener.lambda$fireFinalized$3(RunListener.java:244)
	at jenkins.util.Listeners.lambda$notify$0(Listeners.java:59)
	at jenkins.util.Listeners.notify(Listeners.java:67)
	at hudson.model.listeners.RunListener.fireFinalized(RunListener.java:242)
	at hudson.model.Run.onEndBuilding(Run.java:2059)
	at org.jenkinsci.plugins.workflow.job.WorkflowRun.finish(WorkflowRun.java:644)
	at org.jenkinsci.plugins.workflow.job.WorkflowRun.run(WorkflowRun.java:361)
	at hudson.model.ResourceController.execute(ResourceController.java:101)
	at hudson.model.Executor.run(Executor.java:442)

[richardlau]

There's a note in https://www.jenkins.io/security/advisory/2023-01-24/ about map constructors but AFAICT we're not using those in https://github.com/nodejs/build/blob/main/jenkins/pipelines/post-build-status-update.jenkinsfile.

[richardlau]

This is probably the more pertinent error from the Jenkins system log:

Jan 26, 2023 9:59:06 AM WARNING hudson.ExpressionFactory2$JexlExpression evaluate
Caught exception evaluating: it.writeLogTo(offset,output) in /job/post-build-status-update/1786346/console. Reason: java.io.FileNotFoundException: /var/lib/jenkins/jobs/post-build-status-update/builds/1786346/log (No such file or directory)
java.io.FileNotFoundException: /var/lib/jenkins/jobs/post-build-status-update/builds/1786346/log (No such file or directory)
	at java.base/java.io.RandomAccessFile.open0(Native Method)

and on the server there is indeed no log file:

# ls -al /var/lib/jenkins/jobs/post-build-status-update/builds/1786346/
total 952
drwxr-xr-x   2 jenkins jenkins   4096 Jan 26 09:58 .
drwxr-xr-x 103 jenkins jenkins 933888 Jan 26 10:11 ..
-rw-r--r--   1 jenkins jenkins  26151 Jan 26 09:58 build.xml
-rw-r--r--   1 jenkins jenkins      0 Jan 26 09:58 changelog15499655966859328337.xml
-rw-r--r--   1 jenkins jenkins   1635 Jan 26 09:58 log.gz
-rw-r--r--   1 jenkins jenkins      0 Jan 26 09:58 log-index
root@infra-digitalocean-ubuntu2204-x64-1:~#

[richardlau]

I copied log.gz to /tmp, uncompressed it, and got:

# cat log
[2023-01-26T14:58:57.851Z] Started by user ha:////4HPFpwPROnAP0Ja2azLaHyADO/uvicKfJPZ7C4ElaWGoAAAAmR+LCAAAAAAAAP9b85aBtbiIQTGjNKU4P08vOT+vOD8nVc83PyU1x6OyILUoJzMv2y+/JJUBAhiZGBgqihhk0NSjKDWzXb3RdlLBUSYGJk8GtpzUvPSSDB8G5tKinBIGIZ+sxLJE/ZzEvHT94JKizLx0a6BxUmjGOUNodHsLgAy+EgY+/dLi1CL93IyUxHKgLgC5imQhwwAAAA==Michael Dawson
[2023-01-26T14:58:57.854Z] Checking out git https://github.com/nodejs/build.git into /var/lib/jenkins/jobs/post-build-status-update/workspace@script/21b9f2c6cd5a5073cee06e5885bb9036708e041edd091ae3d44c47029d423ee3 to read jenkins/pipelines/post-build-status-update.jenkinsfile
[2023-01-26T14:58:57.855Z] The recommended git tool is: git
[2023-01-26T14:58:57.855Z] No credentials specified
[2023-01-26T14:58:57.855Z]  > git rev-parse --resolve-git-dir /var/lib/jenkins/jobs/post-build-status-update/workspace@script/21b9f2c6cd5a5073cee06e5885bb9036708e041edd091ae3d44c47029d423ee3/.git # timeout=10
[2023-01-26T14:58:57.864Z] Fetching changes from the remote Git repository
[2023-01-26T14:58:57.864Z]  > git config remote.origin.url https://github.com/nodejs/build.git # timeout=10
[2023-01-26T14:58:57.873Z] Fetching upstream changes from https://github.com/nodejs/build.git
[2023-01-26T14:58:57.873Z]  > git --version # timeout=10
[2023-01-26T14:58:57.880Z]  > git --version # 'git version 2.34.1'
[2023-01-26T14:58:57.880Z]  > git fetch --tags --force --progress -- https://github.com/nodejs/build.git +refs/heads/*:refs/remotes/origin/* # timeout=10
[2023-01-26T14:58:58.284Z]  > git rev-parse origin/main^{commit} # timeout=10
[2023-01-26T14:58:58.292Z] Checking out Revision 5c30993afb9ce5a91ec9d99de3b213f825603988 (origin/main)
[2023-01-26T14:58:58.292Z]  > git config core.sparsecheckout # timeout=10
[2023-01-26T14:58:58.298Z]  > git read-tree -mu HEAD # timeout=10
[2023-01-26T14:58:58.314Z]  > git checkout -f 5c30993afb9ce5a91ec9d99de3b213f825603988 # timeout=10
[2023-01-26T14:58:58.326Z] Commit message: "meta: add Stefan Stojanovic to test (#3151)"
[2023-01-26T14:58:58.326Z]  > git rev-list --no-walk 5c30993afb9ce5a91ec9d99de3b213f825603988 # timeout=10
[2023-01-26T14:58:58.633Z] java.lang.NoSuchMethodError: 'boolean org.kohsuke.groovy.sandbox.SandboxTransformer.mightBePositionalArgumentConstructor(org.codehaus.groovy.ast.expr.VariableExpression)'
[2023-01-26T14:58:58.633Z]      at com.cloudbees.groovy.cps.SandboxCpsTransformer.visitAssignmentOrCast(SandboxCpsTransformer.java:93)
[2023-01-26T14:58:58.633Z]      at com.cloudbees.groovy.cps.CpsTransformer$42.run(CpsTransformer.java:1171)
[2023-01-26T14:58:58.633Z]      at com.cloudbees.groovy.cps.CpsTransformer.makeChildren(CpsTransformer.java:446)
[2023-01-26T14:58:58.633Z]      at com.cloudbees.groovy.cps.CpsTransformer.makeNode(CpsTransformer.java:409)
[2023-01-26T14:58:58.633Z]      at com.cloudbees.groovy.cps.CpsTransformer.visitDeclarationExpression(CpsTransformer.java:1164)
[2023-01-26T14:58:58.633Z]      at org.codehaus.groovy.ast.expr.DeclarationExpression.visit(DeclarationExpression.java:89)
[2023-01-26T14:58:58.633Z]      at com.cloudbees.groovy.cps.CpsTransformer.visit(CpsTransformer.java:357)
[2023-01-26T14:58:58.633Z]      at com.cloudbees.groovy.cps.CpsTransformer.visitExpressionStatement(CpsTransformer.java:589)
[2023-01-26T14:58:58.633Z]      at org.codehaus.groovy.ast.stmt.ExpressionStatement.visit(ExpressionStatement.java:42)
[2023-01-26T14:58:58.633Z]      at com.cloudbees.groovy.cps.CpsTransformer.visit(CpsTransformer.java:357)
[2023-01-26T14:58:58.633Z]      at com.cloudbees.groovy.cps.CpsTransformer.visit(CpsTransformer.java:363)
[2023-01-26T14:58:58.633Z]      at com.cloudbees.groovy.cps.CpsTransformer$5.run(CpsTransformer.java:515)
[2023-01-26T14:58:58.633Z]      at com.cloudbees.groovy.cps.CpsTransformer.makeChildren(CpsTransformer.java:446)
[2023-01-26T14:58:58.633Z]      at com.cloudbees.groovy.cps.CpsTransformer.makeNode(CpsTransformer.java:409)
[2023-01-26T14:58:58.633Z]      at com.cloudbees.groovy.cps.CpsTransformer.visitBlockStatement(CpsTransformer.java:512)
[2023-01-26T14:58:58.633Z]      at org.codehaus.groovy.ast.stmt.BlockStatement.visit(BlockStatement.java:71)
[2023-01-26T14:58:58.633Z]      at com.cloudbees.groovy.cps.CpsTransformer.visit(CpsTransformer.java:357)
[2023-01-26T14:58:58.633Z]      at com.cloudbees.groovy.cps.CpsTransformer$2.run(CpsTransformer.java:388)
[2023-01-26T14:58:58.633Z]      at com.cloudbees.groovy.cps.CpsTransformer.makeChildren(CpsTransformer.java:446)
[2023-01-26T14:58:58.633Z]      at com.cloudbees.groovy.cps.CpsTransformer.makeNode(CpsTransformer.java:409)
[2023-01-26T14:58:58.633Z]      at com.cloudbees.groovy.cps.CpsTransformer.visitWithSafepoint(CpsTransformer.java:374)
[2023-01-26T14:58:58.633Z]      at com.cloudbees.groovy.cps.CpsTransformer.visitMethod(CpsTransformer.java:231)
[2023-01-26T14:58:58.633Z]      at com.cloudbees.groovy.cps.SandboxCpsTransformer.visitMethod(SandboxCpsTransformer.java:73)
[2023-01-26T14:58:58.633Z]      at com.cloudbees.groovy.cps.CpsTransformer.call(CpsTransformer.java:136)
[2023-01-26T14:58:58.633Z]      at com.cloudbees.groovy.cps.SandboxCpsTransformer.call(SandboxCpsTransformer.java:29)
[2023-01-26T14:58:58.633Z]      at org.codehaus.groovy.control.CompilationUnit.applyToPrimaryClassNodes(CompilationUnit.java:1087)
[2023-01-26T14:58:58.633Z]      at org.codehaus.groovy.control.CompilationUnit.doPhaseOperation(CompilationUnit.java:624)
[2023-01-26T14:58:58.633Z]      at org.codehaus.groovy.control.CompilationUnit.processPhaseOperations(CompilationUnit.java:602)
[2023-01-26T14:58:58.633Z]      at org.codehaus.groovy.control.CompilationUnit.compile(CompilationUnit.java:579)
[2023-01-26T14:58:58.633Z]      at groovy.lang.GroovyClassLoader.doParseClass(GroovyClassLoader.java:323)
[2023-01-26T14:58:58.633Z]      at groovy.lang.GroovyClassLoader.parseClass(GroovyClassLoader.java:293)
[2023-01-26T14:58:58.633Z]      at groovy.lang.GroovyShell.parseClass(GroovyShell.java:677)
[2023-01-26T14:58:58.633Z]      at groovy.lang.GroovyShell.parse(GroovyShell.java:689)
[2023-01-26T14:58:58.633Z]      at org.jenkinsci.plugins.workflow.cps.CpsGroovyShell.doParse(CpsGroovyShell.java:142)
[2023-01-26T14:58:58.633Z]      at org.jenkinsci.plugins.workflow.cps.CpsGroovyShell.reparse(CpsGroovyShell.java:127)
[2023-01-26T14:58:58.633Z]      at org.jenkinsci.plugins.workflow.cps.CpsFlowExecution.parseScript(CpsFlowExecution.java:571)
[2023-01-26T14:58:58.633Z]      at org.jenkinsci.plugins.workflow.cps.CpsFlowExecution.start(CpsFlowExecution.java:523)
[2023-01-26T14:58:58.633Z]      at org.jenkinsci.plugins.workflow.job.WorkflowRun.run(WorkflowRun.java:334)
[2023-01-26T14:58:58.633Z]      at hudson.model.ResourceController.execute(ResourceController.java:101)
[2023-01-26T14:58:58.633Z]      at hudson.model.Executor.run(Executor.java:442)
[2023-01-26T14:58:58.638Z] Finished: FAILURE

[richardlau]

I'm going to try updating the Groovy plugin from 442.v817e6d937d6c to 453.vcdb_a_c5c99890.

[richardlau]

Still getting the same error in the compressed job log from recent post-build-status-update job runs.

[richardlau]

Looks like Jenkins does backup plugins when updating -- the backups have a .bak extension while the current plugin has a .jpi extension:

root@infra-digitalocean-ubuntu2204-x64-1:/var/lib/jenkins/plugins# ls -al script-security*
-rw-r--r-- 1 jenkins jenkins 187521 Aug 25 12:08 script-security.bak
-rw-r--r-- 1 jenkins jenkins 210929 Jan 25 07:27 script-security.jpi

Going to try rolling back the Script Security plugin as a stop gap 🤞. My suspicion is that we'll need to update some of the pipeline plugins that we currently cannot until we move to the current Jenkins LTS. We should be able to move to current Jenkins LTS now (#3030 (comment)) with the loss of End-of-Life Linux distros (e.g. Debian 8, 9) although I'd rather do that in a more planned fashion (i.e. not right at the end of my working hours).

[richardlau]

Downgrading the Script Security plugin appears to have got the job working again.
I guess we'll need to delay updating the plugin until we also update to the latest Jenkins LTS release and hope updating the other pipeline plugins at the same time resolves the underlying NoSuchMethodError.

[richardlau]

A few of the other jobs started failing since the downgraded security plugin with

FATAL: script not yet approved for use

e.g. https://ci.nodejs.org/job/node-test-commit-freebsd/47893/console
https://ci.nodejs.org/scriptApproval/ had several pending approvals for the Groovy script to load our VersionSelectorScript.groovy -- I've allowed all of the pending approvals that were listed and the jobs appear to be working again.

[richardlau]

Looks like the failure is back after the issues with today's failed Jenkins update (https://github.com/nodejs/build/issues/3176#issuecomment-1462642773)😞

[richardlau]

Looks like this has fixed itself once all plugins were updated and Jenkins updated to 2.387.1. I have a test CI build running https://ci.nodejs.org/job/node-test-pull-request/50307/ which is posting "CI started" comments and build status to the GitHub PR.