Page MenuHomePhabricator

Jenkins console section matching breaks output HTML rendering
Open, NormalPublic

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 Normal priority.Wed, Oct 23, 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 TranscriptSun, Oct 27, 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 TranscriptWed, Nov 6, 7:46 PM
Krinkle moved this task from Inbox to Blocked or Needs-CR on the Performance-Team board.EditedWed, Nov 6, 7:47 PM

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