search

jenkinsci / ansicolor-plugin

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

'Exception caught evaluating condition,' causes builds to fail ungracefully #57

Closed omehegan closed 4 years ago

omehegan commented 9 years ago

I updated from 0.4.1 to the latest master, built at commit 689f6bc4e02d964c738521f575635958d95c7bc8, because I wanted to start using the plugin with Jenkins Workflow jobs (support added in https://github.com/dblock/jenkins-ansicolor-plugin/pull/54). Then my builds which had ANSI color enabled started failing silently. The build job's console log would just end abruptly with no error shown and the build marked as a failure. Finally I looked at the Jenkins service log and found:

2015-09-28 18:24:27.695457500 Sep 28, 2015 6:24:27 PM org.jenkins_ci.plugins.run_condition.BuildStepRunner logEvaluateException
2015-09-28 18:24:27.695459500 WARNING: Exception caught evaluating condition: [java.lang.NumberFormatException: For input string: "31m108 108 108 108 108 108 108 108 108 108 108 108 108 108 108"], action = [Fail the build]
2015-09-28 18:24:27.695461500 java.lang.NumberFormatException: For input string: "31m108 108 108 108 108 108 108 108 108 108 108 108 108 108 108"
2015-09-28 18:24:27.695461500   at java.lang.NumberFormatException.forInputString(NumberFormatException.java:65)
2015-09-28 18:24:27.695483500   at java.lang.Integer.parseInt(Integer.java:492)
2015-09-28 18:24:27.695484500   at java.lang.Integer.<init>(Integer.java:677)
2015-09-28 18:24:27.695484500   at org.fusesource.jansi.AnsiOutputStream.write(AnsiOutputStream.java:120)
2015-09-28 18:24:27.695485500   at hudson.plugins.ansicolor.AnsiHtmlOutputStream.write(AnsiHtmlOutputStream.java:166)
2015-09-28 18:24:27.695485500   at java.io.FilterOutputStream.write(FilterOutputStream.java:125)
2015-09-28 18:24:27.695489500   at hudson.plugins.ansicolor.AnsiColorBuildWrapper$ConsoleLogFilterImpl$1.eol(AnsiColorBuildWrapper.java:222)
2015-09-28 18:24:27.695490500   at hudson.console.LineTransformationOutputStream.eol(LineTransformationOutputStream.java:60)
2015-09-28 18:24:27.695491500   at hudson.console.LineTransformationOutputStream.write(LineTransformationOutputStream.java:56)
2015-09-28 18:24:27.695497500   at hudson.console.LineTransformationOutputStream.write(LineTransformationOutputStream.java:74)
2015-09-28 18:24:27.695498500   at java.io.PrintStream.write(PrintStream.java:480)
2015-09-28 18:24:27.695498500   at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:221)
2015-09-28 18:24:27.695499500   at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:291)
2015-09-28 18:24:27.695500500   at sun.nio.cs.StreamEncoder.flushBuffer(StreamEncoder.java:104)
2015-09-28 18:24:27.695504500   at java.io.OutputStreamWriter.flushBuffer(OutputStreamWriter.java:185)
2015-09-28 18:24:27.695505500   at java.io.PrintStream.newLine(PrintStream.java:546)
2015-09-28 18:24:27.695505500   at java.io.PrintStream.println(PrintStream.java:807)
2015-09-28 18:24:27.695506500   at org.jenkins_ci.plugins.run_condition.core.BooleanCondition.runPerform(BooleanCondition.java:57)
2015-09-28 18:24:27.695507500   at org.jenkins_ci.plugins.run_condition.logic.ConditionContainer.runPerform(ConditionContainer.java:60)
2015-09-28 18:24:27.695524500   at org.jenkins_ci.plugins.run_condition.logic.Or.runPerform(Or.java:60)
2015-09-28 18:24:27.695525500   at org.jenkins_ci.plugins.run_condition.BuildStepRunner$2.evaluate(BuildStepRunner.java:107)
2015-09-28 18:24:27.695526500   at org.jenkins_ci.plugins.run_condition.BuildStepRunner$Fail.conditionalRun(BuildStepRunner.java:147)
2015-09-28 18:24:27.695533500   at org.jenkins_ci.plugins.run_condition.BuildStepRunner.perform(BuildStepRunner.java:105)
2015-09-28 18:24:27.695533500   at org.jenkinsci.plugins.conditionalbuildstep.singlestep.SingleConditionalBuilder.perform(SingleConditionalBuilder.java:108)
2015-09-28 18:24:27.695534500   at hudson.tasks.BuildStepMonitor$1.perform(BuildStepMonitor.java:20)
2015-09-28 18:24:27.695535500   at hudson.model.AbstractBuild$AbstractBuildExecution.perform(AbstractBuild.java:776)
2015-09-28 18:24:27.695539500   at hudson.model.Build$BuildExecution.build(Build.java:203)
2015-09-28 18:24:27.695539500   at hudson.model.Build$BuildExecution.doRun(Build.java:160)
2015-09-28 18:24:27.695540500   at hudson.model.AbstractBuild$AbstractBuildExecution.run(AbstractBuild.java:536)
2015-09-28 18:24:27.695541500   at hudson.model.Run.execute(Run.java:1738)
2015-09-28 18:24:27.695541500   at hudson.matrix.MatrixRun.run(MatrixRun.java:146)
2015-09-28 18:24:27.695544500   at hudson.model.ResourceController.execute(ResourceController.java:98)
2015-09-28 18:24:27.695545500   at hudson.model.Executor.run(Executor.java:381)

Disabling ANSI color fixed the issue. Let me know if I can give you any other info to investigate.

dblock commented 9 years ago

Try to write a test that reproduces this?

dblock commented 9 years ago

Likely something in https://github.com/dblock/jenkins-ansicolor-plugin/commit/b0f9697cc38c0670ff7dc40a3649849d6db891ff.

omehegan commented 9 years ago

Try to write a test that reproduces this?

Unfortunately I don't know Java at all so that's probably beyond my abilities. I tested the new build of the plugin on my local Jenkins server, which is the same version that I use in production, with a job that just runs printf "\e[31mHello World\e[0m\n"

That seemed to work fine. My local system is MacOS with Sun Java 6, though, and production is Linux with OpenJDK 7. I will try that test on the prod system when it is idle and see if I can reproduce.

qvicksilver commented 9 years ago

@omehegan Just for clarity, the jobs where you have this issue are they "old-school" freestyle jobs or workflows?

omehegan commented 9 years ago

@qvicksilver these were freestyle jobs. I haven't had a chance to try to repro again and dig further, I need to wait for some downtime or try and set up a suitable test env.

qvicksilver commented 9 years ago

@omehegan would be great if you could reproduce it or hint on how to do it. I've had no luck with making it fail the way your build does.

omehegan commented 9 years ago

I'll see if I can look into this today.

omehegan commented 9 years ago

I am baffled. So far I can't reproduce this on my test server. The exception seems straightforward: it got a string where it was expecting an integer. I can't figure out why though.

omehegan commented 9 years ago

I am still able to reproduce this on my production server. I'm trying to figure out what's different between it and my test instance - they have identical versions of Jenkins, builds of the plugin, and are running on the same JDK (OpenJDK 7). Here is a more complete error log than what I initially posted. This is dumped once a build gets to the point of trying to display ANSI colored log output. If you can suggest some additional logging or debugging I could try, I'm all for it.

2015-10-15 05:27:37.966606500 Oct 15, 2015 5:27:37 AM org.jenkins_ci.plugins.run_condition.BuildStepRunner logEvaluateException
2015-10-15 05:27:37.966608500 WARNING: Exception caught evaluating condition: [java.lang.ArrayIndexOutOfBoundsException: 175], action = [Fail the build]
2015-10-15 05:27:37.966609500 java.lang.ArrayIndexOutOfBoundsException: 175
2015-10-15 05:27:37.966610500   at org.fusesource.jansi.AnsiOutputStream.write(AnsiOutputStream.java:117)
2015-10-15 05:27:37.966611500   at hudson.plugins.ansicolor.AnsiHtmlOutputStream.write(AnsiHtmlOutputStream.java:166)
2015-10-15 05:27:37.966689500   at java.io.FilterOutputStream.write(FilterOutputStream.java:125)
2015-10-15 05:27:37.966690500   at hudson.plugins.ansicolor.AnsiColorBuildWrapper$ConsoleLogFilterImpl$1.eol(AnsiColorBuildWrapper.java:222)
2015-10-15 05:27:37.966691500   at hudson.console.LineTransformationOutputStream.eol(LineTransformationOutputStream.java:60)
2015-10-15 05:27:37.966691500   at hudson.console.LineTransformationOutputStream.write(LineTransformationOutputStream.java:56)
2015-10-15 05:27:37.966716500   at hudson.console.LineTransformationOutputStream.write(LineTransformationOutputStream.java:74)
2015-10-15 05:27:37.966717500   at java.io.PrintStream.write(PrintStream.java:480)
2015-10-15 05:27:37.966717500   at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:221)
2015-10-15 05:27:37.966717500   at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:291)
2015-10-15 05:27:37.966740500   at sun.nio.cs.StreamEncoder.flushBuffer(StreamEncoder.java:104)
2015-10-15 05:27:37.966740500   at java.io.OutputStreamWriter.flushBuffer(OutputStreamWriter.java:185)
2015-10-15 05:27:37.966741500   at java.io.PrintStream.newLine(PrintStream.java:546)
2015-10-15 05:27:37.966741500   at java.io.PrintStream.println(PrintStream.java:807)
2015-10-15 05:27:37.966742500   at org.jenkins_ci.plugins.run_condition.core.BooleanCondition.runPerform(BooleanCondition.java:57)
2015-10-15 05:27:37.966791500   at org.jenkins_ci.plugins.run_condition.logic.ConditionContainer.runPerform(ConditionContainer.java:60)
2015-10-15 05:27:37.966792500   at org.jenkins_ci.plugins.run_condition.logic.Or.runPerform(Or.java:60)
2015-10-15 05:27:37.966792500   at org.jenkins_ci.plugins.run_condition.BuildStepRunner$2.evaluate(BuildStepRunner.java:107)
2015-10-15 05:27:37.966793500   at org.jenkins_ci.plugins.run_condition.BuildStepRunner$Fail.conditionalRun(BuildStepRunner.java:147)
2015-10-15 05:27:37.966817500   at org.jenkins_ci.plugins.run_condition.BuildStepRunner.perform(BuildStepRunner.java:105)
2015-10-15 05:27:37.966817500   at org.jenkinsci.plugins.conditionalbuildstep.singlestep.SingleConditionalBuilder.perform(SingleConditionalBuilder.java:108)
2015-10-15 05:27:37.966818500   at hudson.tasks.BuildStepMonitor$1.perform(BuildStepMonitor.java:20)
2015-10-15 05:27:37.966862500   at hudson.model.AbstractBuild$AbstractBuildExecution.perform(AbstractBuild.java:776)
2015-10-15 05:27:37.966863500   at hudson.model.Build$BuildExecution.build(Build.java:203)
2015-10-15 05:27:37.966863500   at hudson.model.Build$BuildExecution.doRun(Build.java:160)
2015-10-15 05:27:37.966864500   at hudson.model.AbstractBuild$AbstractBuildExecution.run(AbstractBuild.java:536)
2015-10-15 05:27:37.966864500   at hudson.model.Run.execute(Run.java:1738)
2015-10-15 05:27:37.966896500   at hudson.matrix.MatrixRun.run(MatrixRun.java:146)
2015-10-15 05:27:37.966896500   at hudson.model.ResourceController.execute(ResourceController.java:98)
2015-10-15 05:27:37.966897500   at hudson.model.Executor.run(Executor.java:381)
2015-10-15 05:27:37.966897500
2015-10-15 05:27:37.967868500 Oct 15, 2015 5:27:37 AM hudson.model.listeners.RunListener report
2015-10-15 05:27:37.967869500 WARNING: RunListener failed
2015-10-15 05:27:37.967869500 java.lang.NullPointerException
2015-10-15 05:27:37.967870500   at com.sonyericsson.jenkins.plugins.bfa.BuildFailureScanner.scanIfNotScanned(BuildFailureScanner.java:108)
2015-10-15 05:27:37.967871500   at com.sonyericsson.jenkins.plugins.bfa.BuildFailureScanner.onCompleted(BuildFailureScanner.java:91)
2015-10-15 05:27:37.967871500   at com.sonyericsson.jenkins.plugins.bfa.BuildFailureScanner.onCompleted(BuildFailureScanner.java:65)
2015-10-15 05:27:37.967909500   at hudson.model.listeners.RunListener.fireCompleted(RunListener.java:199)
2015-10-15 05:27:37.967910500   at hudson.model.Run.execute(Run.java:1783)
2015-10-15 05:27:37.967910500   at hudson.matrix.MatrixRun.run(MatrixRun.java:146)
2015-10-15 05:27:37.967911500   at hudson.model.ResourceController.execute(ResourceController.java:98)
2015-10-15 05:27:37.967911500   at hudson.model.Executor.run(Executor.java:381)
2015-10-15 05:27:37.967935500
2015-10-15 05:27:37.970239500 Oct 15, 2015 5:27:37 AM hudson.model.listeners.RunListener report
2015-10-15 05:27:37.970241500 WARNING: RunListener failed
2015-10-15 05:27:37.970241500 java.lang.NullPointerException
2015-10-15 05:27:37.970242500   at jenkins.metrics.impl.JenkinsMetricProviderImpl$ResultRunListener.onCompleted(JenkinsMetricProviderImpl.java:619)
2015-10-15 05:27:37.970243500   at hudson.model.listeners.RunListener.fireCompleted(RunListener.java:199)
2015-10-15 05:27:37.970243500   at hudson.model.Run.execute(Run.java:1783)
2015-10-15 05:27:37.970285500   at hudson.matrix.MatrixRun.run(MatrixRun.java:146)
2015-10-15 05:27:37.970285500   at hudson.model.ResourceController.execute(ResourceController.java:98)
2015-10-15 05:27:37.970286500   at hudson.model.Executor.run(Executor.java:381)
2015-10-15 05:27:37.970287500
2015-10-15 05:27:37.971000500 Oct 15, 2015 5:27:37 AM hudson.model.listeners.RunListener report
2015-10-15 05:27:37.971001500 WARNING: RunListener failed
2015-10-15 05:27:37.971001500 java.lang.NullPointerException
2015-10-15 05:27:37.971002500   at hudson.model.PermalinkProjectAction$Permalink$3.apply(PermalinkProjectAction.java:134)
2015-10-15 05:27:37.971003500   at jenkins.model.PeepholePermalink$RunListenerImpl.onCompleted(PeepholePermalink.java:232)
2015-10-15 05:27:37.971003500   at hudson.model.listeners.RunListener.fireCompleted(RunListener.java:199)
2015-10-15 05:27:37.971047500   at hudson.model.Run.execute(Run.java:1783)
2015-10-15 05:27:37.971048500   at hudson.matrix.MatrixRun.run(MatrixRun.java:146)
2015-10-15 05:27:37.971049500   at hudson.model.ResourceController.execute(ResourceController.java:98)
2015-10-15 05:27:37.971049500   at hudson.model.Executor.run(Executor.java:381)
2015-10-15 05:27:37.971050500
2015-10-15 05:27:37.971801500 Oct 15, 2015 5:27:37 AM hudson.model.Run onEndBuilding
2015-10-15 05:27:37.971802500 WARNING: cserv_build_test_pipeline/label=jenkins-precise64-2 #1862: No build result is set, so marking as failure. This should not happen.
2015-10-15 05:27:37.972385500 Oct 15, 2015 5:27:37 AM hudson.model.Executor finish1
2015-10-15 05:27:37.972386500 SEVERE: Executor threw an exception
2015-10-15 05:27:37.972386500 java.lang.ArrayIndexOutOfBoundsException: 180
2015-10-15 05:27:37.972387500   at org.fusesource.jansi.AnsiOutputStream.write(AnsiOutputStream.java:117)
2015-10-15 05:27:37.972387500   at hudson.plugins.ansicolor.AnsiHtmlOutputStream.write(AnsiHtmlOutputStream.java:166)
2015-10-15 05:27:37.972388500   at java.io.FilterOutputStream.write(FilterOutputStream.java:125)
2015-10-15 05:27:37.972424500   at hudson.plugins.ansicolor.AnsiColorBuildWrapper$ConsoleLogFilterImpl$1.eol(AnsiColorBuildWrapper.java:222)
2015-10-15 05:27:37.972425500   at hudson.console.LineTransformationOutputStream.eol(LineTransformationOutputStream.java:60)
2015-10-15 05:27:37.972426500   at hudson.console.LineTransformationOutputStream.write(LineTransformationOutputStream.java:56)
2015-10-15 05:27:37.972427500   at hudson.console.LineTransformationOutputStream.write(LineTransformationOutputStream.java:74)
2015-10-15 05:27:37.972451500   at java.io.PrintStream.write(PrintStream.java:480)
2015-10-15 05:27:37.972451500   at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:221)
2015-10-15 05:27:37.972452500   at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:291)
2015-10-15 05:27:37.972453500   at sun.nio.cs.StreamEncoder.flushBuffer(StreamEncoder.java:104)
2015-10-15 05:27:37.972453500   at java.io.OutputStreamWriter.flushBuffer(OutputStreamWriter.java:185)
2015-10-15 05:27:37.972486500   at java.io.PrintStream.newLine(PrintStream.java:546)
2015-10-15 05:27:37.972487500   at java.io.PrintStream.println(PrintStream.java:807)
2015-10-15 05:27:37.972487500   at hudson.model.StreamBuildListener.finished(StreamBuildListener.java:79)
2015-10-15 05:27:37.972488500   at hudson.model.Run.execute(Run.java:1790)
2015-10-15 05:27:37.972488500   at hudson.matrix.MatrixRun.run(MatrixRun.java:146)
2015-10-15 05:27:37.972489500   at hudson.model.ResourceController.execute(ResourceController.java:98)
2015-10-15 05:27:37.972530500   at hudson.model.Executor.run(Executor.java:381)
2015-10-15 05:27:37.972530500
omehegan commented 9 years ago

It's definitely not the most recent changes that caused my issue. I have stepped back through the commits and found that the breakage is introduced in between 3d783662a37f8c9dda2c86d97f02ec3928a9ebf0 and 80b9183818f4fce186a009857b09aa78e151791d.

dblock commented 9 years ago

We just need to find out what string is being passed in here, cc: @ejelly since both those commits are his.

omehegan commented 9 years ago

@dblock can you tell me where/what I would hook into to log that string? I've been trying to figure that out.

qvicksilver commented 9 years ago

@omehegan if you are able to run the build outside of Jenkins you should be able to get the string that way.

omehegan commented 9 years ago

@qvicksilver true, I guess I thought we needed to capture the ANSI control chars. The job doesn't blow up until it tries to print ANSI color.

qvicksilver commented 9 years ago

@omehegan depending on what produces the output you should be able to get the ANSI control chars into a text file as well.

dblock commented 9 years ago

I think if you were to log the buffer in https://github.com/dblock/jenkins-ansicolor-plugin/blob/master/src/main/java/hudson/plugins/ansicolor/AnsiColorBuildWrapper.java#L222 that would work.

dblock commented 9 years ago

Also, another useful thing: disable AnsiColor, run the job, save the output. Then enable ansicolor, run the job, save the output. Compare. The last line will tell us what the text was that caused the job to crash.

omehegan commented 9 years ago

Here is the offending string:

base64_suite
    - "a29uaWNoaXdh" == "a29uaWNoaXdh"
    - base64 URL decoded matches input
    - "aGVsbG8gd29ybGQ" == "aGVsbG8gd29ybGQ"
    - base64 URL decoded matches input
    - "Z29vZGJ5ZQ" == "Z29vZGJ5ZQ"
    - base64 URL decoded matches input

When ANSI color is enabled, the last thing I see in the log is "base64_suite," and then the ArrayIndexOutOfBoundsException error (in the Jenkins console log). I presume that the line after that, the first with any color, is what kills us. In preview here the Github Markdown parser seems to think there is a weird UTF-8 char in there, but when I examine the actual string in emacs that just looks like a normal space.

omehegan commented 9 years ago
  1. I have narrowed the bug down specifically to commit 4ef902bd78dac2df0eff2f0a1ad01b17a6aa691a by @sschuberth, but it looks awfully innocent to me.
  2. I have discovered I can reproduce the bug with any ANSI color string, including the example ones in the README. There's nothing special about the ones my builds are producing.
  3. Depending on what string is used, you get different exceptions:

printf '\e[31mHello World\e[0m\n' yields this:

2015-10-16 06:05:27.209474500 java.lang.NumberFormatException: For input string: "31m"
2015-10-16 06:05:27.209474500   at java.lang.NumberFormatException.forInputString(NumberFormatException.java:65)
2015-10-16 06:05:27.209475500   at java.lang.Integer.parseInt(Integer.java:492)
2015-10-16 06:05:27.209476500   at java.lang.Integer.<init>(Integer.java:677)
2015-10-16 06:05:27.209476500   at org.fusesource.jansi.AnsiOutputStream.write(AnsiOutputStream.java:120)
2015-10-16 06:05:27.209577500   at hudson.plugins.ansicolor.AnsiHtmlOutputStream.collectAmbleCharacter(AnsiHtmlOutputStream.java:193)
2015-10-16 06:05:27.209578500   at hudson.plugins.ansicolor.AnsiHtmlOutputStream.write(AnsiHtmlOutputStream.java:179)
2015-10-16 06:05:27.209579500   at java.io.FilterOutputStream.write(FilterOutputStream.java:125)
2015-10-16 06:05:27.209579500   at hudson.plugins.ansicolor.AnsiColorBuildWrapper$2.eol(AnsiColorBuildWrapper.java:107)
2015-10-16 06:05:27.209658500   at hudson.console.LineTransformationOutputStream.eol(LineTransformationOutputStream.java:60)
2015-10-16 06:05:27.209659500   at hudson.console.LineTransformationOutputStream.write(LineTransformationOutputStream.java:56)
2015-10-16 06:05:27.209660500   at hudson.console.LineTransformationOutputStream.write(LineTransformationOutputStream.java:74)
2015-10-16 06:05:27.209733500   at java.io.PrintStream.write(PrintStream.java:480)
2015-10-16 06:05:27.209733500   at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:221)
2015-10-16 06:05:27.209734500   at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:291)
2015-10-16 06:05:27.209735500   at sun.nio.cs.StreamEncoder.flushBuffer(StreamEncoder.java:104)
2015-10-16 06:05:27.209735500   at java.io.OutputStreamWriter.flushBuffer(OutputStreamWriter.java:185)
2015-10-16 06:05:27.209834500   at java.io.PrintStream.newLine(PrintStream.java:546)
2015-10-16 06:05:27.209835500   at java.io.PrintStream.println(PrintStream.java:807)
2015-10-16 06:05:27.209836500   at hudson.model.StreamBuildListener.finished(StreamBuildListener.java:79)
2015-10-16 06:05:27.209836500   at hudson.model.Run.execute(Run.java:1790)
2015-10-16 06:05:27.209837500   at hudson.model.FreeStyleBuild.run(FreeStyleBuild.java:43)
2015-10-16 06:05:27.209915500   at hudson.model.ResourceController.execute(ResourceController.java:98)
2015-10-16 06:05:27.209916500   at hudson.model.Executor.run(Executor.java:381)

Whereas printf ' - \e[32ma29uaWNoaXdh == a29uaWNoaXdh\e[0m' yields this:

2015-10-16 06:07:52.237062500 java.lang.NullPointerException
2015-10-16 06:07:52.237063500   at hudson.plugins.ansicolor.AnsiColorMap.getNormal(AnsiColorMap.java:94)
2015-10-16 06:07:52.237064500   at hudson.plugins.ansicolor.AnsiHtmlOutputStream.processSetForegroundColor(AnsiHtmlOutputStream.java:258)
2015-10-16 06:07:52.237064500   at org.fusesource.jansi.AnsiOutputStream.processEscapeCommand(AnsiOutputStream.java:275)
2015-10-16 06:07:52.237080500   at org.fusesource.jansi.AnsiOutputStream.write(AnsiOutputStream.java:125)
2015-10-16 06:07:52.237081500   at hudson.plugins.ansicolor.AnsiHtmlOutputStream.write(AnsiHtmlOutputStream.java:166)
2015-10-16 06:07:52.237082500   at java.io.FilterOutputStream.write(FilterOutputStream.java:125)
2015-10-16 06:07:52.237082500   at hudson.plugins.ansicolor.AnsiColorBuildWrapper$2.eol(AnsiColorBuildWrapper.java:107)
2015-10-16 06:07:52.237104500   at hudson.console.LineTransformationOutputStream.eol(LineTransformationOutputStream.java:60)
2015-10-16 06:07:52.237105500   at hudson.console.LineTransformationOutputStream.write(LineTransformationOutputStream.java:56)
2015-10-16 06:07:52.237106500   at hudson.console.LineTransformationOutputStream.write(LineTransformationOutputStream.java:74)
2015-10-16 06:07:52.237107500   at java.io.PrintStream.write(PrintStream.java:480)
2015-10-16 06:07:52.237114500   at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:221)
2015-10-16 06:07:52.237115500   at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:291)
2015-10-16 06:07:52.237116500   at sun.nio.cs.StreamEncoder.flushBuffer(StreamEncoder.java:104)
2015-10-16 06:07:52.237116500   at java.io.OutputStreamWriter.flushBuffer(OutputStreamWriter.java:185)
2015-10-16 06:07:52.237117500   at java.io.PrintStream.newLine(PrintStream.java:546)
2015-10-16 06:07:52.237120500   at java.io.PrintStream.println(PrintStream.java:807)
2015-10-16 06:07:52.237121500   at hudson.model.StreamBuildListener.finished(StreamBuildListener.java:79)
2015-10-16 06:07:52.237122500   at hudson.model.Run.execute(Run.java:1790)
2015-10-16 06:07:52.237122500   at hudson.model.FreeStyleBuild.run(FreeStyleBuild.java:43)
2015-10-16 06:07:52.237123500   at hudson.model.ResourceController.execute(ResourceController.java:98)
2015-10-16 06:07:52.237126500   at hudson.model.Executor.run(Executor.java:381)

In fact, the presence or absence of a newline char at the end of the string seems to determine whether we get a NPE (no newline) or a NumberFormatException (newline). Is it me, or is this starting to sound like maybe a Java version issue, or a difference in other library versions that is particular to my plugin build env?

dblock commented 9 years ago

What colormap does this build use?

Does this happen with every color map? XTerm, etc.

Since you have this reproduced you should be able to figure out what that NPE is, it's calling getNormal and then tries to access a color map and gets an error, so I am fairly sure either the map selected is null or something like that.

sschuberth commented 9 years ago

I think the problem is that I renamed member variables in a serializable class without changing the serialVersionUID. So if you upgrade the plugin from an old version, it tries to deserialize the old data into the new class, and fails. I'll file a PR with a fix.

dblock commented 9 years ago

Bah, thanks @sschuberth.

dblock commented 9 years ago

@omehegan I merged that PR, care to try again?

omehegan commented 9 years ago

Thanks @dblock and @sschuberth! I'll try tonight and see.

Forgive my ignorance of Java and serialization, but from what little I do know, I don't understand how this could be the problem. The bug only manifests (well, I've only seen it manifest) when I run a new build and it reaches the point of logging ANSI escape sequences. What does this have to do with earlier versions of the plugin and deserializing any "old data?" If that were the issue I would expect to only see the problem when I looked at an old build's console log after updating the plugin.

dblock commented 9 years ago

The configuration for which terminal colors to use gets serialized into the job, so you have an old(er) job that was created and configured with the old version of the plugin.

tamzinblake commented 9 years ago

Great explanation. Thanks!

omehegan commented 9 years ago

Unfortunately, with the update I'm still getting this:

2015-10-17 00:12:47.260035500 Exception in thread "/bin/bash -ex /tmp/hudson5696670944209428048.sh: stdout copier" java.lang.NullPointerException
2015-10-17 00:12:47.260192500   at hudson.plugins.ansicolor.AnsiColorMap.getNormal(AnsiColorMap.java:124)
2015-10-17 00:12:47.260193500   at hudson.plugins.ansicolor.AnsiHtmlOutputStream.processSetForegroundColor(AnsiHtmlOutputStream.java:258)
2015-10-17 00:12:47.260335500   at org.fusesource.jansi.AnsiOutputStream.processEscapeCommand(AnsiOutputStream.java:275)
2015-10-17 00:12:47.260336500   at org.fusesource.jansi.AnsiOutputStream.write(AnsiOutputStream.java:125)
2015-10-17 00:12:47.260482500   at hudson.plugins.ansicolor.AnsiHtmlOutputStream.write(AnsiHtmlOutputStream.java:166)
2015-10-17 00:12:47.260484500   at java.io.FilterOutputStream.write(FilterOutputStream.java:125)
2015-10-17 00:12:47.260529500   at hudson.plugins.ansicolor.AnsiColorBuildWrapper$ConsoleLogFilterImpl$1.eol(AnsiColorBuildWrapper.java:222)
2015-10-17 00:12:47.260628500   at hudson.console.LineTransformationOutputStream.eol(LineTransformationOutputStream.java:60)
2015-10-17 00:12:47.260629500   at hudson.console.LineTransformationOutputStream.write(LineTransformationOutputStream.java:56)
2015-10-17 00:12:47.260725500   at hudson.console.LineTransformationOutputStream.write(LineTransformationOutputStream.java:74)
2015-10-17 00:12:47.260773500   at java.io.PrintStream.write(PrintStream.java:480)
2015-10-17 00:12:47.260773500   at hudson.util.StreamCopyThread.run(StreamCopyThread.java:61)
2015-10-17 00:12:47.278865500 Oct 17, 2015 12:12:47 AM hudson.model.Run execute
2015-10-17 00:12:47.278866500 INFO: test-ansicolor #19 main build action completed: SUCCESS
2015-10-17 00:12:47.299159500 Oct 17, 2015 12:12:47 AM hudson.model.Executor finish1
2015-10-17 00:12:47.299160500 SEVERE: Executor threw an exception
2015-10-17 00:12:47.299161500 java.lang.NumberFormatException: For input string: "31m"
2015-10-17 00:12:47.299161500   at java.lang.NumberFormatException.forInputString(NumberFormatException.java:65)
2015-10-17 00:12:47.299162500   at java.lang.Integer.parseInt(Integer.java:492)
2015-10-17 00:12:47.299162500   at java.lang.Integer.<init>(Integer.java:677)
2015-10-17 00:12:47.299163500   at org.fusesource.jansi.AnsiOutputStream.write(AnsiOutputStream.java:120)
2015-10-17 00:12:47.299188500   at hudson.plugins.ansicolor.AnsiHtmlOutputStream.collectAmbleCharacter(AnsiHtmlOutputStream.java:193)
2015-10-17 00:12:47.299189500   at hudson.plugins.ansicolor.AnsiHtmlOutputStream.write(AnsiHtmlOutputStream.java:179)
2015-10-17 00:12:47.299190500   at java.io.FilterOutputStream.write(FilterOutputStream.java:125)
2015-10-17 00:12:47.299191500   at hudson.plugins.ansicolor.AnsiColorBuildWrapper$ConsoleLogFilterImpl$1.eol(AnsiColorBuildWrapper.java:222)
2015-10-17 00:12:47.299197500   at hudson.console.LineTransformationOutputStream.eol(LineTransformationOutputStream.java:60)
2015-10-17 00:12:47.299198500   at hudson.console.LineTransformationOutputStream.write(LineTransformationOutputStream.java:56)
2015-10-17 00:12:47.299199500   at hudson.console.LineTransformationOutputStream.write(LineTransformationOutputStream.java:74)
2015-10-17 00:12:47.299206500   at java.io.PrintStream.write(PrintStream.java:480)
2015-10-17 00:12:47.299207500   at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:221)
2015-10-17 00:12:47.299207500   at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:291)
2015-10-17 00:12:47.299208500   at sun.nio.cs.StreamEncoder.flushBuffer(StreamEncoder.java:104)
2015-10-17 00:12:47.299209500   at java.io.OutputStreamWriter.flushBuffer(OutputStreamWriter.java:185)
2015-10-17 00:12:47.299213500   at java.io.PrintStream.newLine(PrintStream.java:546)
2015-10-17 00:12:47.299213500   at java.io.PrintStream.println(PrintStream.java:807)
2015-10-17 00:12:47.299214500   at hudson.model.StreamBuildListener.finished(StreamBuildListener.java:79)
2015-10-17 00:12:47.299214500   at hudson.model.Run.execute(Run.java:1790)
2015-10-17 00:12:47.299215500   at hudson.model.FreeStyleBuild.run(FreeStyleBuild.java:43)
2015-10-17 00:12:47.299230500   at hudson.model.ResourceController.execute(ResourceController.java:98)
2015-10-17 00:12:47.299231500   at hudson.model.Executor.run(Executor.java:381)

This is a new job that I created only with the most recent versions of the plugin. Shouldn't this work regardless?

ejelly commented 9 years ago

I have only taken a cursory glance, but is this maybe related to this?

dblock commented 9 years ago

Ok, so this problem didn't go away with the serialization change. I'll reopen this. @omehegan are you the only one on this thread to have this reproduced?

I guess I can roll up my sleeves this week and try this ...

omehegan commented 9 years ago

It sounds that way. Obviously I'm willing to help however I can. If the comments @ejelly linked to are related, it sounds like if I built an old version of the plugin and used it, then upgraded, we would see the issue. That would explain why I couldn't repro it on my test server which only ever had 0.4.1.

dblock commented 9 years ago

So we're saying just close it and ship it?

omehegan commented 9 years ago

Eh? No, it sounds like it would be a breaking change for anyone who had a sufficiently old version of the plugin installed. I think we should try to fix. I can engage some Jenkins pros for guidance if that's what we need.

dblock commented 9 years ago

@omehegan There's a lot of speculating going on on this thread about what the root cause is, I re-read everything and I can't even figure out what the issue is anymore. You're the only one with a repro, so, what are you seeing with code from HEAD?

Some combination of the above?

omehegan commented 9 years ago

OK, let me summarize the current state of things. I'm using Jenkins 1.609.3 (LTS release) on 64 bit Ubuntu Trusty, with OpenJDK 7. If my build configs can be trusted, I have never used a version of the plugin earlier than 0.4.1. In the latest HEAD, a freestyle build with a shell script step which just does this: printf "\e[31mHello World\e[0m\n" throws the two exceptions I noted in https://github.com/dblock/jenkins-ansicolor-plugin/issues/57#issuecomment-148869752. In all my tests I have been building the plugin on MacOS with Sun Java 6 (it just happens to be convenient when I'm rapidly reloading versions of the plugin), but I did one test with a build of the plugin built on the master with Java 7 and it still failed.

I can't reproduce this on my test Jenkins server, and the only difference between that and production is that it's using Ubuntu Precise. I'm doubtful that that's a factor. I'm wondering if it's possible this is an interaction between two plugins, but I've tried to install all the relevant ones on the test server and it hasn't helped me repro the problem there. I also would think you'd see some reference to another plugin in the stack traces.

I think some of the other exceptions I've seen have partly been the result of the bug occurring during a build on a slave node. The bug causes the job to exit ungracefully, and when it's building on master that seems to generate a fairly straightforward failure (as noted in https://github.com/dblock/jenkins-ansicolor-plugin/issues/57#issuecomment-148869752). When a slave job exits this way Jenkins itself seems to get mad and throw an exception or two of its own.

dblock commented 9 years ago

@omehegan One more thing we should hunt down - a version of jansi. On the failing box see if you have any jansi-1.[something].jar files around? I am almost sure it's not the problem though.

omehegan commented 9 years ago

In my JENKINS_HOME: ./plugins/ansicolor/WEB-INF/lib/jansi-1.9.jar ./war/WEB-INF/lib/jansi-1.9.jar

And I have the same versions on my test instance where everything works.

omehegan commented 9 years ago

I just copied ALL of the plugins from my production Jenkins over to the test system, then install latest HEAD of ansicolor, and still can't reproduce there. Bah.

omehegan commented 9 years ago

WOO I have repro steps!

The issue is with the JENKINS_HOME/hudson.plugins.ansicolor.AnsiColorBuildWrapper.xml file, which controls the global config of the plugin. My production server has that. My test server does not. When I copy the prod version of the file over to the test server and use HEAD of the plugin, I can reproduce the exceptions.

Furthermore, with hudson.plugins.ansicolor.AnsiColorBuildWrapper.xml in place, if you open the global Jenkins config, you see a billion lines of other exceptions related to the plugin.

So it seems like, relative to @ejelly's comments in https://github.com/dblock/jenkins-ansicolor-plugin/issues/24#issuecomment-72599878, that is the data that we need a way to cleanly migrate across plugin versions. Apparently changing the serialVersionUID in AnsiColorMap.java is not enough to handle this. Can you guys make any more progress with this, given this insight?

dblock commented 9 years ago

@omehegan That's awesome. Care to copy-paste/attach/share the xml file here and the first exception related to the plugin from the global log?

omehegan commented 9 years ago

I bet if you install 0.4.1 of the plugin, then go to the Jenkins global config, display the ansicolor config and make a change and save it, the file will be generated. Then install HEAD of the plugin and you should be able to repro.

Here's mine:

<?xml version='1.0' encoding='UTF-8'?>
<hudson.plugins.ansicolor.AnsiColorBuildWrapper_-DescriptorImpl plugin="ansicolor@0.4.1">
  <colorMaps>
    <hudson.plugins.ansicolor.AnsiColorMap>
      <name>xterm</name>
      <fgMap>
        <string>#000000</string>
        <string>#CD0000</string>
        <string>#00CD00</string>
        <string>#CDCD00</string>
        <string>#1E90FF</string>
        <string>#CD00CD</string>
        <string>#00CDCD</string>
        <string>#E5E5E5</string>
      </fgMap>
      <bgMap>
        <string>#4C4C4C</string>
        <string>#FF0000</string>
        <string>#00FF00</string>
        <string>#FFFF00</string>
        <string>#4682B4</string>
        <string>#FF00FF</string>
        <string>#00FFFF</string>
        <string>#FFFFFF</string>
      </bgMap>
    </hudson.plugins.ansicolor.AnsiColorMap>
    <hudson.plugins.ansicolor.AnsiColorMap>
      <name>vga</name>
      <fgMap>
        <string>#000000</string>
        <string>#AA0000</string>
        <string>#00AA00</string>
        <string>#AA5500</string>
        <string>#0000AA</string>
        <string>#AA00AA</string>
        <string>#00AAAA</string>
        <string>#AAAAAA</string>
      </fgMap>
      <bgMap>
        <string>#555555</string>
        <string>#FF5555</string>
        <string>#55FF55</string>
        <string>#FFFF55</string>
        <string>#5555FF</string>
        <string>#FF55FF</string>
        <string>#55FFFF</string>
        <string>#FFFFFF</string>
      </bgMap>
    </hudson.plugins.ansicolor.AnsiColorMap>
    <hudson.plugins.ansicolor.AnsiColorMap>
      <name>css</name>
      <fgMap>
        <string>black</string>
        <string>red</string>
        <string>green</string>
        <string>yellow</string>
        <string>blue</string>
        <string>magenta</string>
        <string>cyan</string>
        <string>white</string>
      </fgMap>
      <bgMap>
        <string>black</string>
        <string>red</string>
        <string>green</string>
        <string>yellow</string>
        <string>blue</string>
        <string>magenta</string>
        <string>cyan</string>
        <string>white</string>
      </bgMap>
    </hudson.plugins.ansicolor.AnsiColorMap>
    <hudson.plugins.ansicolor.AnsiColorMap>
      <name>gnome-terminal</name>
      <fgMap>
        <string>#2E3436</string>
        <string>#CC0000</string>
        <string>#4E9A06</string>
        <string>#C4A000</string>
        <string>#3465A4</string>
        <string>#75507B</string>
        <string>#06989A</string>
        <string>#D3D7CF</string>
      </fgMap>
      <bgMap>
        <string>#2E3436</string>
        <string>#CC0000</string>
        <string>#4E9A06</string>
        <string>#C4A000</string>
        <string>#3465A4</string>
        <string>#75507B</string>
        <string>#06989A</string>
        <string>#D3D7CF</string>
      </bgMap>
    </hudson.plugins.ansicolor.AnsiColorMap>
  </colorMaps>
</hudson.plugins.ansicolor.AnsiColorBuildWrapper_-DescriptorImpl>
qvicksilver commented 9 years ago

I'm able to reproduce this using the steps @omehegan outlined. On the "Manage Jenkins" page I'm informed that:

You have data stored in an older format and/or unreadable data

Looks very much like we need some way of migrating old configuration to new format. Reading up on that now..

omehegan commented 9 years ago

@qvicksilver I think the canonical way to do this is through application of readResolve: https://wiki.jenkins-ci.org/display/JENKINS/Hint+on+retaining+backward+compatibility

qvicksilver commented 9 years ago

@omehegan was just looking at that, first try no luck :(

omehegan commented 9 years ago

@qvicksilver I had already posted about this issue on the jenkinsci-dev mailing list. Maybe we can get some guidance there: https://groups.google.com/forum/#!topic/jenkinsci-dev/aOma439Sdw8 Otherwise, #jenkins on Freenode IRC is active (I'm in there all the time) and a good place for realtime Q&A.

qvicksilver commented 9 years ago

@omehegan care to try this: qvicksilver@5c8ceaab7d705ea88fc0bfd4d784f0a1da246212 seems to be working.

dblock commented 9 years ago

@qvicksilver Do you think you can turn this into a test? Maybe just try to deserialize that XML? And add a comment that this object is serialized into a configuration and should be altered carefully. This will be a good model with moving forward.

qvicksilver commented 9 years ago

@dblock sounds like a good idea, I'll give it a try!

omehegan commented 9 years ago

@qvicksilver yep, your branch works for me as well. However, I notice that it doesn't rewrite the config on disk. Is that expected?

qvicksilver commented 9 years ago

@omehegan I've made no effort for it to rewrite the config so I'd say that is expected. But it would of course be a nice addition.

dblock commented 9 years ago

Make some pull requests! Nice work everyone.