Page MenuHomePhabricator

Jenkins console section matching breaks output HTML rendering
Closed, ResolvedPublic

Description

The Jenkins build output viewer seems to have broken recently. Specifically, it appears to be creating console sections start and end tags in a way that makes the output unbalanced HTML.

Problem

The actual console output from the plain text (with limited codes). This plain text undergoes three transformations, and somewhere along the way things are seemingly done based on raw HTML instead of based on safe text:

  • The output is HTML escaped to display in a <pre> tag. This is the default Jenkins behaviour.
  • ANSI escape codes are interpreted by the "AnsiColor" plugin for Jenkins. It interprets the "start" and "end" markers in a way that is similar to what xterm would do, and creates a <span> for the wrapped text with a similar CSS text color as what xterm would have displayed the text as.
  • The "Console Section" plugin for Jenkins is running regular expressions from the Jenkins Configuration page and adding a <div> before any line that matches the "start" pattern, and adding a </div> after any line that matches the "end" pattern.

What's happening is that this opening <div> ends up not in front of the line, but inside an HTML comment that the AnsiColor plugin leaves behind.

As such:

Console output
[32m INFO [0m :quibble.commands:PHPUnit unit tests
…
[32m INFO [0m :quibble.commands:PHPUnit done

Becomes:

HTML (Actual)
<!--<div class="section" data-level=""><div class="collapseHeader">PHPUnit unit tests<div class="collapseAction"><p onClick="doToggle(this)">Hide Details</p></div></div><div class="expanded">
   --><span style="color: #00CD00;">INFO<!----></span>:quibble.commands:PHPUnit unit tests
…
<!--[32m--><span style="color: #00CD00;">INFO<!----></span>:quibble.commands:PHPUnit done
</div>

Whereas it used to be:

HTML (Expected)
<div class="section" data-level=""><div class="collapseHeader">PHPUnit unit tests<div class="collapseAction"><p onClick="doToggle(this)">Hide Details</p></div></div><div class="expanded">
<!--[32m--><span style="color: #00CD00;">INFO<!----></span>:quibble.commands:PHPUnit unit tests
…
<!--[32m--><span style="color: #00CD00;">INFO<!----></span>:quibble.commands:PHPUnit done
</div>

If I recall correctly, these <!--[32m--> comments didn't use to be there. And it seems a likely that this is the trigger. It is unclear to me why .*INFO:quibble would start its match mid-way this HTML comment. On the other hand, this HTML comment only exists because of the AnsiColor code handling.

Impact

As far as I know, this regular expression is meant to run on the text form, not on the HTML form. Running it on the HTML form would be unsafe as the patterns don't take escaping into account, e.g. it might match a tag midway and change its meaning.

Or, in this case, it means the </div> is actually closing an unrelated element and the entire page is distorted:

Details

Related Gerrit Patches:

Event Timeline

Krinkle created this task.Oct 23 2019, 1:12 AM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptOct 23 2019, 1:12 AM
Issue 1: Unbalanced match

Output going outside content boundary. – Caused by a match starting at the color code which is wrapped inside the HTML comment
https://integration.wikimedia.org/ci/job/mediawiki-fresnel-patch-docker/11409/console

Example
<!--[32m--><span style="color: #00CD00;">INFO<!----></span>:quibble.commands:PHPUnit done
    ^ match for /.*INFO:/ starts here starts here???

Becomes:
<!-- <div …section…> --> stuff </div>

Issue 2: Mid-color match

Output being fully colorised by an inline tag intended for the first word on a line only. – Caused by the match starting between the <span> and the first word

https://integration.wikimedia.org/ci/job/wmf-quibble-vendor-mysql-php72-docker/11841/consoleFull#console-section-4

Example
<!--[32m--><span style="color: #00CD00;">INFO<!----></span>:quibble.commands:PHPUnit done
                                         ^ match for /.*INFO:/ starts here starts here???

Becomes:
<!-- … --><span color><div section> green stuff</span> this is also green stuff now </div>

(Here </span> has to be ignored because the currently open span tag is for outside the div.)

If I assume it is a regression somewhere in Jenkins:

At least I don't think I had the plugin updated any recently. From contint1001, the file is from February 2018:

$ ls -la /var/lib/jenkins/plugins/collapsing*
-rw-rw-r-- 1 jenkins jenkins 21766 Jun 20  2017 /var/lib/jenkins/plugins/collapsing-console-sections.bak
-rw-rw-r-- 1 jenkins jenkins 22610 Feb  5  2018 /var/lib/jenkins/plugins/collapsing-console-sections.jpi

The plugin page https://wiki.jenkins.io/display/JENKINS/Collapsing+Console+Sections+Plugin has:

Version 1.7.0 (Jan 23, 2018)
(plus) PR #15 - Improve the outline layout

So does not seem to be related to the plugin version.


The plugin configuration is done in the system configuration https://integration.wikimedia.org/ci/configure . On left there is a (poorly named) Job Config History link. Eventually that list history of any configuration files
(to be fair, I wasn't aware of that web UI until now)

So for the Collapsing Section plugin, we can find the changes at:

https://integration.wikimedia.org/ci/jobConfigHistory/history?name=org.jvnet.hudson.plugins.collapsingconsolesections.CollapsingSectionNote

Which are borrowed from backups of the plugin XML config file which can be found on disk:

$ ls -1 /var/lib/jenkins/config-history/org.jvnet.hudson.plugins.collapsingconsolesections.CollapsingSectionNote
2019-07-26_15-49-31
2019-07-26_15-50-54
2019-07-26_15-51-15
2019-07-26_15-52-04
2019-07-26_15-53-27
2019-07-26_15-53-34
2019-07-26_15-55-31
2019-07-26_15-55-36
2019-07-26_15-56-42
2019-07-26_15-59-28
2019-07-26_15-59-52
2019-07-26_16-00-16
2019-07-26_16-02-02
2019-07-26_16-02-06
2019-07-26_16-04-07
2019-07-26_16-04-11
2019-07-26_16-04-36
2019-07-26_16-04-38
2019-07-26_16-05-10
2019-07-26_16-05-51
2019-07-26_16-07-06
2019-07-26_16-08-32
2019-07-26_16-10-28
2019-10-02_03-06-00
2019-10-04_19-17-05
2019-10-23_00-27-51
2019-10-23_00-34-56
2019-10-23_00-36-28
2019-10-23_00-37-34
2019-10-23_00-39-24
2019-10-23_00-41-52
2019-10-23_00-43-20
2019-10-23_00-45-15
2019-10-23_00-46-26
2019-10-23_00-48-26
2019-10-23_00-48-50
2019-10-23_00-49-32
2019-10-23_00-55-21
2019-10-23_00-55-36
2019-10-23_01-17-24

Continuing on the regression tracking. Yesterday I have updated a bunch of plugins, including AnsiColor Plugin, which is known to break in non obvious way. I guess I have upgraded it by mistake cause usually I just leave it as is to whatever "stable" version.

The update happened yesterday Oct 21th at 19:01 UTC (that sounds late for a plugin upgrade but well ...):

-rw-rw-r-- 1 jenkins jenkins 38519 Dec 14  2018 /var/lib/jenkins/plugins/ansicolor.bak
-rw-rw-r-- 1 jenkins jenkins 45147 Oct 21 19:01 /var/lib/jenkins/plugins/ansicolor.jpi

And Jenkins UI at https://integration.wikimedia.org/ci/pluginManager/installed says:

PluginVersionPrevious
AnsiColor0.6.20.5.3

Given you mention the AnsiColor plugin, I guess we can just rollback the upgrade :D

I have downgraded AnsiColor through the web interface. State on disk:

$ ls -la /var/lib/jenkins/plugins/*ansi*
-rw-rw-r-- 1 jenkins jenkins 38519 Dec 14  2018 /var/lib/jenkins/plugins/ansicolor.jpi

Apparently that does not require a restart, but maybe Jenkins really should be restarted.

At least the two examples are still showing as broken:

Note I have restarted Jenkins to make sure the AnsiColor plugin is effecti

14:00 	<hashar> 	Restarting CI Jenkins
hashar triaged this task as Medium priority.Oct 23 2019, 4:55 PM

Maybe Quibble changed the way it outputs or wraps the colors?

Krinkle changed the visibility from "Custom Policy" to "Public (No Login Required)".
Restricted Application added a project: Security. · View Herald TranscriptOct 27 2019, 12:11 AM

Change 545988 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[integration/quibble@master] Disable color codes around log level words in CI

https://gerrit.wikimedia.org/r/545988

Change 545988 merged by jenkins-bot:
[integration/quibble@master] Disable color codes around log level words in CI

https://gerrit.wikimedia.org/r/545988

Krinkle added a project: Fresnel.
Restricted Application added a project: Performance-Team. · View Herald TranscriptNov 6 2019, 7:46 PM
Krinkle moved this task from Inbox to Blocked or Needs-CR on the Performance-Team board.EditedNov 6 2019, 7:47 PM

Blocked on the above Quibble patch being released and deployed in CI.

Quibble hasn't changed but I had the following suspect in mind:

  • Jenkins got upgraded, which might have changed the order in which the plugins are processing the output
  • The AnsiColor plugin got upgraded. Dismissed by rolling back to the previous version
  • The collapsible rules have been changed.

To make it easier, I have created a small reproduction case. A simple Jenkins job running on contint1001, using shell to emit output similar to what Quibble does. I have not enabled the timestamp plugin on that job. The shell is:

set +x

info='\033[32mINFO\033[0m:%s\n'

# Start of section
printf $info 'quibble.commands:PHPUnit unit tests'

echo 'Phpunit output ....'

# End of section
printf $info 'quibble.cmd:PHPUnit unit tests finished in 3.943 s'

echo 'After end of section'

Which does show the text After end of section being greenish.

The related collapsible configuration is:

Section name{1}
Section starts.*quibble.commands:(PHPUnit.+)
Section ends.*quibble.cmd:.*finished.*

\033[32mINFO\033[0m:quibble.commands:PHPUnit unit tests\n


When disabling the collapsible section, the HTML looks like:

+ set +x
<span style="color: #00CD00;">INFO</span>:quibble.commands:PHPUnit unit tests
Phpunit output ....
<span style="color: #00CD00;">INFO</span>:quibble.cmd:PHPUnit unit tests finished in 3.943 s
After end of section
Finished: SUCCESS

With the collapsible section plugin (reindented):

+ set +x
<span style="color: #00CD00;">
    <div class="section" data-level="">
        <div class="collapseHeader">PHPUnit unit tests
            <div class="collapseAction"><p onClick="doToggle(this)">Hide Details</p></div>
        </div>
        <div class="expanded">INFO</span>:quibble.commands:PHPUnit unit tests
                                  ^^^^^^^
Phpunit output ....
        <span style="color: #00CD00;">INFO</span>:quibble.cmd:PHPUnit unit tests finished in 3.943 s
    </div>
</div>After end of section
Finished: SUCCESS

The coloring <span> opens before the section but is closed just after the INFO right in the middle of the collapsible section <div>. So surely that is messed. It acts as is the collapsible section is starting too late.

The lines are passed to each plugin registering a ConsoleAnnotator, the original text is passed to each one in order.

Using the [https://integration.wikimedia.org/ci/script Jenkins Script Console] we can get the list:

println(
  Jenkins.instance.getExtensionList(hudson.console.ConsoleAnnotatorFactory.class)
  )
[
 hudson.console.UrlAnnotator@32369e2d,
 hudson.plugins.ansicolor.ColorConsoleAnnotator$Factory@35c3fd0e,
 hudson.plugins.timestamper.annotator.TimestampAnnotatorFactory3@6201a545,
 hudson.plugins.timestamper.pipeline.GlobalAnnotator$Factory@62e52662,
 org.jvnet.hudson.plugins.collapsingconsolesections.CollapsingSectionAnnotatorFactory@64241be5
]

On a build without the timestamper, I do see the funky commented html (I replace the escape character below with <ESC>:

+ set +x
<!--<div class="section" data-level=""><div class="collapseHeader">PHPUnit unit tests<div class="collapseAction"><p onClick="doToggle(this)">Hide Details</p></div></div><div class="expanded"><ESC>[32m--><span style="color: #00CD00;">INFO<!--<ESC>[0m--></span>:quibble.commands:PHPUnit unit tests
Phpunit output ....
<!--<ESC>[32m--><span style="color: #00CD00;">INFO<!--<ESC>[0m--></span>:quibble.cmd:PHPUnit unit tests finished in 3.943 s
</div></div>After end of section
Finished: SUCCESS
</pre></div></div>

The debug logger for hudson.plugins.ansicolor.ColorConsoleAnnotator gives some clues, I have added some more details

creating annotator with colorMapName=xterm openTags=[]
lastPoint=-1
emitting html='<span style="color: #00CD00;">' @ inCount=5 / s.length()=50
hiding 5 @0

emitting </span> @13/50
hiding 4 @9

The final debug log shows what is emitted:

before

\u001B[32mINFO\u001B[0m:quibble.commands:PHPUnit unit tests\n

after

<!--\u001B[32m--><span style=\"color: #00CD00;\">INFO<!--\u001B[0m--></span>:quibble.commands:PHPUnit unit tests\n

The CollapsingSectionAnnotatorFactory then kicks in. I can't find why it inserts its HTML after <!-- and before the <ESC>[32m.

So hmm Jenkins is broken :] The ConsoleAnnotations is a hudson.MarkupText which is a list of Tag. One can insert a tag using:

MarkupText.addMarkup( <position>, <sometext> )

The plugins do use addMarkup( 0, whatever ) to insert their HTML tag at the front. That is put in ArrayList.

Eventually when the MarkupText is rendered to a string, the tags are sorted using Collections.Sort and the Tags object are compared based on the value of their position. So if you do:

text.addMarkup( 0, '<!--' )
text.addMarkup( 0, '<span style="color: #00CD00;">' )
text.addMarkup( 0, '<div>' )

You don't really now in which order they will be sorted? :-\

I have rebuild the plugin collapsing-console-sections-plugin with a hack:

--- a/src/main/java/org/jvnet/hudson/plugins/collapsingconsolesections/CollapsingSectionAnnotatorFactory.java
+++ b/src/main/java/org/jvnet/hudson/plugins/collapsingconsolesections/CollapsingSectionAnnotatorFactory.java
@@ -32,7 +32,7 @@ import jenkins.model.Jenkins;
  *
  * @author dty
  */
-@Extension
+@Extension(ordinal = -100) // to wrap buildtimestamp, ansicolor etc
 public class CollapsingSectionAnnotatorFactory extends ConsoleAnnotatorFactory {
     @Override
     public ConsoleAnnotator newInstance(Object context) {

But that does not change anything. I have disabled the plugin for now.

hashar added a project: Upstream.EditedDec 3 2019, 3:49 PM

Tested locally (one can run the plugin easily via mvn hpi:run from the root of the plugin git repo) and went with a potential fix. In short the idea is to have the collapsible section plugin to act after ansicolor. I also made it to have its HTML to wrap the build timestamper output in order to have the timestamps inside the collapsible section.

The long story is in the Upstream pull request
https://github.com/jenkinsci/collapsing-console-sections-plugin/pull/18

And https://github.com/jenkinsci/collapsing-console-sections-plugin/pull/16 to fix versions in the pom.xml.

I have rebuild the plugin and deployed it. Should be fixed now.

Krinkle closed this task as Resolved.Dec 3 2019, 10:34 PM

LGTM. Thanks!

hashar added a subscriber: brennen.

My pull request (#pr18) has been approved and has been released with collapsing console sections 1.8.0.

We will update it as part of T239985: Upgrade Jenkins to 2.190.3 with @brennen

Change 562918 had a related patch set uploaded (by Jforrester; owner: Jforrester):
[integration/quibble@master] Release Quibble 0.0.40

https://gerrit.wikimedia.org/r/562918

Change 562918 merged by jenkins-bot:
[integration/quibble@master] Release Quibble 0.0.40

https://gerrit.wikimedia.org/r/562918

Change 562959 had a related patch set uploaded (by Jforrester; owner: Jforrester):
[integration/config@master] dockerfiles: Create images for Quibble version 0.0.40

https://gerrit.wikimedia.org/r/562959

Change 562960 had a related patch set uploaded (by Jforrester; owner: Jforrester):
[integration/config@master] jjb: Switch over to images using Quibble version 0.0.40

https://gerrit.wikimedia.org/r/562960

Change 562959 merged by jenkins-bot:
[integration/config@master] dockerfiles: Create images for Quibble version 0.0.40

https://gerrit.wikimedia.org/r/562959

Change 562960 merged by jenkins-bot:
[integration/config@master] jjb: Switch over to images using Quibble version 0.0.40

https://gerrit.wikimedia.org/r/562960