jenkinsci / ansicolor-plugin

Jenkins ANSI Color Plugin
https://plugins.jenkins.io/ansicolor/
MIT License
252 stars 82 forks source link

StringIndexOutOfBoundsException cause by long lines in log #267

Open bewinsnw opened 1 year ago

bewinsnw commented 1 year ago

Jenkins and plugins versions report

Environment ```text 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

https://github.com/jenkinsci/ansicolor-plugin/blob/c3e57428e365091923935fd5332c32f82853528f/src/main/java/hudson/plugins/ansicolor/action/ShortlogActionCreator.java#L108

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 commented 1 year ago

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

bewinsnw commented 1 year ago

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 https://github.com/jenkinsci/ansicolor-plugin/blob/c3e57428e365091923935fd5332c32f82853528f/src/test/java/hudson/plugins/ansicolor/action/ShortlogActionCreatorTest.java#L165 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 https://github.com/jenkinsci/ansicolor-plugin/blob/c3e57428e365091923935fd5332c32f82853528f/src/main/java/hudson/plugins/ansicolor/action/ShortlogActionCreator.java#L105-L111 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 commented 1 year ago

Thanks @bewinsnw, hopefully someone can finish this.