StringIndexOutOfBoundsException cause by long lines in log

[bewinsnw]

Jenkins and plugins versions report

Environment

Jenkins: 2.416
OS: Linux - 5.10.184-175.749.amzn2.x86_64
Java: 11.0.19 - Eclipse Adoptium (OpenJDK 64-Bit Server VM)
---
ansicolor:1.0.2
ant:497.v94e7d9fffa_b_9
antisamy-markup-formatter:159.v25b_c67cd35fb_
apache-httpcomponents-client-4-api:4.5.14-150.v7a_b_9d17134a_5
artifactory:3.18.6
authentication-tokens:1.53.v1c90fd9191a_b_
aws-credentials:191.vcb_f183ce58b_9
aws-java-sdk:1.12.481-392.v8b_291cfcda_09
aws-java-sdk-cloudformation:1.12.481-392.v8b_291cfcda_09
aws-java-sdk-codebuild:1.12.481-392.v8b_291cfcda_09
aws-java-sdk-ec2:1.12.481-392.v8b_291cfcda_09
aws-java-sdk-ecr:1.12.481-392.v8b_291cfcda_09
aws-java-sdk-ecs:1.12.481-392.v8b_291cfcda_09
aws-java-sdk-efs:1.12.481-392.v8b_291cfcda_09
aws-java-sdk-elasticbeanstalk:1.12.481-392.v8b_291cfcda_09
aws-java-sdk-iam:1.12.481-392.v8b_291cfcda_09
aws-java-sdk-kinesis:1.12.481-392.v8b_291cfcda_09
aws-java-sdk-logs:1.12.481-392.v8b_291cfcda_09
aws-java-sdk-minimal:1.12.481-392.v8b_291cfcda_09
aws-java-sdk-sns:1.12.481-392.v8b_291cfcda_09
aws-java-sdk-sqs:1.12.481-392.v8b_291cfcda_09
aws-java-sdk-ssm:1.12.481-392.v8b_291cfcda_09
aws-secrets-manager-credentials-provider:1.202.ve0ec0c17611c
bootstrap5-api:5.3.0-1
bouncycastle-api:2.29
branch-api:2.1122.v09cb_8ea_8a_724
caffeine-api:3.1.6-115.vb_8b_b_328e59d8
checks-api:2.0.0
cloudbees-folder:6.815.v0dd5a_cb_40e0e
command-launcher:100.v2f6722292ee8
commons-lang3-api:3.12.0-36.vd97de6465d5b_
commons-text-api:1.10.0-36.vc008c8fcda_7b_
config-file-provider:952.va_544a_6234b_46
configuration-as-code:1670.v564dc8b_982d0
credentials:1271.v54b_1c2c6388a_
credentials-binding:631.v861c06d062b_4
dark-theme:336.v02165cd8c2ee
data-tables-api:1.13.5-1
datadog:5.4.2
display-url-api:2.3.7
docker-commons:439.va_3cb_0a_6a_fb_29
docker-workflow:563.vd5d2e5c4007f
durable-task:510.v324450f8dca_4
ec2-fleet:2.7.1
echarts-api:5.4.0-5
font-awesome-api:6.4.0-2
git:5.2.0
git-client:4.4.0
git-server:99.va_0826a_b_cdfa_d
github:1.37.1
github-api:1.314-431.v78d72a_3fe4c3
github-branch-source:1728.v859147241f49
github-scm-filter-aged-refs:31.ve3b_ca_fc71d5b_
gradle:2.8.2
instance-identity:173.va_37c494ec4e5
ionicons-api:56.v1b_1c8c49374e
jackson2-api:2.15.2-350.v0c2f3f8fc595
jakarta-activation-api:2.0.1-3
jakarta-mail-api:2.0.1-3
javadoc:233.vdc1a_ec702cff
javax-activation-api:1.2.0-6
javax-mail-api:1.6.2-9
jaxb:2.3.8-1
jdk-tool:66.vd8fa_64ee91b_d
jjwt-api:0.11.5-77.v646c772fddb_0
jnr-posix-api:3.1.17-1
jquery3-api:3.7.0-1
jsch:0.2.8-65.v052c39de79b_2
junit:1217.v4297208a_a_b_ce
kubernetes:3985.vd26d77b_2a_48a_
kubernetes-client-api:6.4.1-215.v2ed17097a_8e9
kubernetes-credentials:0.10.0
kubernetes-credentials-provider:1.225.v14f9e6b_28f53
lockable-resources:1172.v4b_8fc8eed570
mailer:457.v3f72cb_e015e5
matrix-auth:3.1.10
matrix-project:789.v57a_725b_63c79
maven-plugin:3.22
metrics:4.2.18-439.v86a_20b_a_8318b_
mina-sshd-api-common:2.10.0-69.v28e3e36d18eb_
mina-sshd-api-core:2.10.0-69.v28e3e36d18eb_
okhttp-api:4.11.0-145.vcb_8de402ef81
pipeline-build-step:496.v2449a_9a_221f2
pipeline-graph-analysis:202.va_d268e64deb_3
pipeline-groovy-lib:656.va_a_ceeb_6ffb_f7
pipeline-input-step:468.va_5db_051498a_4
pipeline-milestone-step:111.v449306f708b_7
pipeline-model-api:2.2144.v077a_d1928a_40
pipeline-model-definition:2.2144.v077a_d1928a_40
pipeline-model-extensions:2.2144.v077a_d1928a_40
pipeline-rest-api:2.33
pipeline-stage-step:305.ve96d0205c1c6
pipeline-stage-tags-metadata:2.2144.v077a_d1928a_40
pipeline-stage-view:2.33
pipeline-utility-steps:2.16.0
plain-credentials:143.v1b_df8b_d3b_e48
plugin-util-api:3.3.0
role-strategy:670.vc71a_a_c00039e
saml:4.418.vdfa_7489a_b_a_2d
scm-api:676.v886669a_199a_a_
script-security:1251.vfe552ed55f8d
snakeyaml-api:1.33-95.va_b_a_e3e47b_fa_4
ssh-agent:333.v878b_53c89511
ssh-credentials:305.v8f4381501156
ssh-slaves:2.877.v365f5eb_a_b_eec
sshd:3.303.vefc7119b_ec23
structs:324.va_f5d6774f3a_d
theme-manager:193.vcef22f6c5f2b_
timestamper:1.25
token-macro:359.vb_cde11682e0c
trilead-api:2.84.v72119de229b_7
variant:59.vf075fe829ccb
workflow-aggregator:596.v8c21c963d92d
workflow-api:1241.v4edc8b_44933b_
workflow-basic-steps:1017.vb_45b_302f0cea_
workflow-cps:3722.v85ce2a_c6240b_
workflow-durable-task-step:1247.v7f9dfea_b_4fd0
workflow-job:1316.vd2290d3341a_f
workflow-multibranch:756.v891d88f2cd46
workflow-scm-step:415.v434365564324
workflow-step-api:639.v6eca_cd8c04a_a_
workflow-support:848.v5a_383b_d14921

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

controller is running in k8s using the official jenkins helm chart. Agents are AWS Linux 2023.

Reproduction steps

Don't have a direct reproducer but I can see the bug in your code. We're getting this error (which crashed jenkins):

java.lang.StringIndexOutOfBoundsException: offset 16381, count -16381, length 16384
at java.base/java.lang.String.checkBoundsOffCount(String.java:3304)
at java.base/java.lang.String.<init>(String.java:505)
at hudson.plugins.ansicolor.action.ShortlogActionCreator.findLastActionBefore(ShortlogActionCreator.java:70) 

(due to a logging misconfig, we're getting jumbled stacktraces, I'll spare you the rest of the jigsaw, but it's clear from the stacktrace that this is what's at the top).

Expected Results

Jenkins should not crash when ansicolor gets a long line to highlight.

Actual Results

Jenkins crashed.

Anything else?

Looking at the exception, the problem is that count -16381, none of the arguments to the strong constructor are allowed to be negative (per JDK docs).

Looking at findLastActionBefore we can see it gets those arguments by calling calculateBeginLength, and just quick look at the code there shows an obvious bug

ansicolor-plugin/src/main/java/hudson/plugins/ansicolor/action/ShortlogActionCreator.java

Line 108 in c3e5742

return new int[]{begin, eolPos != -1 ? indexOfEol(buf, eolPos) - begin + eol.length : -1};

indexOfEol() can return -1. When that happens and keepLinesWhole is true, and eol.length is 1, this function will return new int[]{begin, -begin} - which is exactly what we saw logged.

That can happen when the eol is past the end of the buffer; in this case, the start of the search was just shy of the end of the 16k buffer and unless any of the next 3 bytes were EOL this is what would happen.

Now we've seen what the bug is, we'll be working around it by disabling keeplineswhole. I expect the better solution would be to treat keeplineswhole as a hint and ignore it if the EOL can't be found.

[dblock]

@bewinsnw Thanks for the report and for digging up the root cause - care to write a test/and maybe even a fix?

[bewinsnw]

Well, it's hard to figure out what the tests in there are trying to achieve, since it's all pretty much comment-free. I can see by poking at it that the error condition I'm hitting is triggered by removing a bunch of characters from src/test/resources/hudson/plugins/ansicolor/action/ShortlogActionCreatorTest/testlog-long.log so that the line tested for in

ansicolor-plugin/src/test/java/hudson/plugins/ansicolor/action/ShortlogActionCreatorTest.java

Line 165 in c3e5742

final String s = "[Pipeline] echo a very very very long line,a very very very long line,a very very very long line,a very very very long line,a very very very long line";

spans the end of the 16384 byte buffer: I did this with vim, :%s,ha:////[A-Za-z0-9+]\{5},ha:////,g. (removing characters from the ha url, since they didn't seem significant to the algorithm where others might)

This results in:

[ERROR] hudson.plugins.ansicolor.action.ShortlogActionCreatorTest.canCreateActionForShortlogOnLogLineExceedingBufferSize -- Time elapsed: 0.004 s <<< ERROR!
java.lang.StringIndexOutOfBoundsException: Range [16244, 16244 + -16244) out of bounds for length 16384
	at java.base/jdk.internal.util.Preconditions$1.apply(Preconditions.java:55)
	at java.base/jdk.internal.util.Preconditions$1.apply(Preconditions.java:52)
	at java.base/jdk.internal.util.Preconditions$4.apply(Preconditions.java:213)
	at java.base/jdk.internal.util.Preconditions$4.apply(Preconditions.java:210)
	at java.base/jdk.internal.util.Preconditions.outOfBounds(Preconditions.java:98)
	at java.base/jdk.internal.util.Preconditions.outOfBoundsCheckFromIndexSize(Preconditions.java:118)
	at java.base/jdk.internal.util.Preconditions.checkFromIndexSize(Preconditions.java:397)
	at java.base/java.lang.String.checkBoundsOffCount(String.java:4596)
	at java.base/java.lang.String.<init>(String.java:521)
	at hudson.plugins.ansicolor.action.ShortlogActionCreator.findLastActionBefore(ShortlogActionCreator.java:70)
	at hudson.plugins.ansicolor.action.ShortlogActionCreator.createActionForShortlog(ShortlogActionCreator.java:39)

And the fix to

ansicolor-plugin/src/main/java/hudson/plugins/ansicolor/action/ShortlogActionCreator.java

Lines 105 to 111 in c3e5742

	private int[] calculateBeginLength(byte[] buf, int startInBuff, int eolPos, boolean keepLinesWhole) {
	if (keepLinesWhole) {
	final int begin = eolPos != -1 ? eolPos + eol.length : startInBuff;
	return new int[]{begin, eolPos != -1 ? indexOfEol(buf, eolPos) - begin + eol.length : -1};
	}
	return new int[]{startInBuff, eolPos != -1 ? eolPos - startInBuff + eol.length : -1};
	}

should be:

    private int[] calculateBeginLength(byte[] buf, int startInBuff, int eolPos, boolean keepLinesWhole) {
        if (keepLinesWhole) {
            final int begin = eolPos != -1 ? eolPos + eol.length : startInBuff;
            final int nextEol = indexOfEol(buf, eolPos);
            return new int[]{begin, eolPos != -1 && nextEol != -1 ? nextEol - begin + eol.length : -1};
        }
        return new int[]{startInBuff, eolPos != -1 ? eolPos - startInBuff + eol.length : -1};
    }

However, this ends up with:

java.lang.AssertionError: expected:<mock-line-hash> but was:<null>
	at org.junit.Assert.fail(Assert.java:89)
	at org.junit.Assert.failNotEquals(Assert.java:835)
	at org.junit.Assert.assertEquals(Assert.java:120)
	at org.junit.Assert.assertEquals(Assert.java:146)
	at hudson.plugins.ansicolor.action.ShortlogActionCreatorTest.canCreateActionForShortlog(ShortlogActionCreatorTest.java:88)

... which takes me into the weeds trying to understand what's going on with how these tests are structured, LineIdentifier, ColorizedAction, etc, and I don't have the spare cycles to take this further.

[dblock]

Thanks @bewinsnw, hopefully someone can finish this.