1

We noticed our Jenkins build logs were being filled with 10 times more content than we expected. This greatly increases the amount of logs that slaves have to send back to the master, which in turn makes all builds take longer, which in turn makes builds fail with spurious timeouts.

On investigation, we find the lines all have a huge URL prepended.

ha:////{320 bytes of base64 junk} Log message
ha:////{320 bytes of base64 junk} [blank line]
ha:////{320 bytes of base64 junk} Next log message

I tried decoding the base64, but it doesn't produce any structure which I'm familiar with.

I didn't want to post ours because someone who knows how to decode it might find private info in there, but I tried searching for some of the content we were seeing, and noticed that someone else had posted the same sort of thing to pastebin:

https://pastebin.com/LM7mht8W

Taking one of those URLs:

ha:////4HTWhKVov8LrT80csqfIVuXrtfeJTJod3fz9PpkDu0UAAAAAzh+LCAAAAAAAAP9b85aBtbiIQSOjNKU4P0+vIKc0PTOvWK8kMze1uCQxtyC1SC8ExvbLL0llgABGJgYmLwaB3MycnMzi4My85FTXgvzkDB8G3tScxILi1BRfsEwJg4BPVmJZon5OYl66vk9+Xrp1RRGDFNSy5Py84vycVD1nCI1qPENFAZCOr07/fwfoPj6QKXogU/TApnQ/mXCmX/k+EwOjFwNrWWJOaSrQXAGEIr/S3KTUorY1U2W5pzzohprGwMDU+O4jAJgnACXyAAAA

And decoding it (including the ////):

00000000 ff ff ff e0 74 d6 84 a5 68 bf c2 eb 4f cd 1c b2 |....t...h...O...| 00000010 a7 c8 56 e5 eb b5 f7 89 4c 9a 1d dd fc fd 3e 99 |..V.....L.....>.| 00000020 03 bb 45 00 00 00 00 ce 1f 8b 08 00 00 00 00 00 |..E.............| 00000030 00 ff 5b f3 96 81 b5 b8 88 41 23 a3 34 a5 38 3f |..[......A#.4.8?| 00000040 4f af 20 a7 34 3d 33 af 58 af 24 33 37 b5 b8 24 |O. .4=3.X.$37..$| 00000050 31 b7 20 b5 48 2f 04 c6 f6 cb 2f 49 65 80 00 46 |1. .H/..../Ie..F| 00000060 26 06 26 2f 06 81 dc cc 9c 9c cc e2 e0 cc bc e4 |&.&/............| 00000070 54 d7 82 fc e4 0c 1f 06 de d4 9c c4 82 e2 d4 14 |T...............| 00000080 5f b0 4c 09 83 80 4f 56 62 59 a2 7e 4e 62 5e ba |_.L...OVbY.~Nb^.| 00000090 be 4f 7e 5e ba 75 45 11 83 14 d4 b2 e4 fc bc e2 |.O~^.uE.........| 000000a0 fc 9c 54 3d 67 08 8d 6a 3c 43 45 01 90 8e af 4e |..T=g..j<CE....N| 000000b0 ff 7f 07 e8 3e 3e 90 29 7a 20 53 f4 c0 a6 74 3f |....>>.)z S...t?| 000000c0 99 70 a6 5f f9 3e 13 03 a3 17 03 6b 59 62 4e 69 |.p._.>.....kYbNi| 000000d0 2a d0 5c 01 84 22 bf d2 dc a4 d4 a2 b6 35 53 65 |*.\..".......5Se| 000000e0 b9 a7 3c e8 86 9a c6 c0 c0 d4 f8 ee 23 00 98 27 |..<.........#..'| 000000f0 00 25 f2 00 00 00 |.%....| 000000f6

Noticing that 1f 8b 08 looked like a gzip header, I tried cutting the file at that point and decompressed it. This gave:

00000000 ac ed 00 05 73 72 00 28 68 75 64 73 6f 6e 2e 70 |....sr.(hudson.p| 00000010 6c 75 67 69 6e 73 2e 74 69 6d 65 73 74 61 6d 70 |lugins.timestamp| 00000020 65 72 2e 54 69 6d 65 73 74 61 6d 70 4e 6f 74 65 |er.TimestampNote| 00000030 00 00 00 00 00 00 00 01 02 00 02 4a 00 10 6d 69 |...........J..mi| 00000040 6c 6c 69 73 53 69 6e 63 65 45 70 6f 63 68 4c 00 |llisSinceEpochL.| 00000050 0d 65 6c 61 70 73 65 64 4d 69 6c 6c 69 73 74 00 |.elapsedMillist.| 00000060 10 4c 6a 61 76 61 2f 6c 61 6e 67 2f 4c 6f 6e 67 |.Ljava/lang/Long| 00000070 3b 78 72 00 1a 68 75 64 73 6f 6e 2e 63 6f 6e 73 |;xr..hudson.cons| 00000080 6f 6c 65 2e 43 6f 6e 73 6f 6c 65 4e 6f 74 65 00 |ole.ConsoleNote.| 00000090 00 00 00 00 00 00 01 02 00 00 78 70 00 00 01 5f |..........xp..._| 000000a0 7b 67 ff dc 73 72 00 0e 6a 61 76 61 2e 6c 61 6e |{g..sr..java.lan| 000000b0 67 2e 4c 6f 6e 67 3b 8b e4 90 cc 8f 23 df 02 00 |g.Long;.....#...| 000000c0 01 4a 00 05 76 61 6c 75 65 78 72 00 10 6a 61 76 |.J..valuexr..jav| 000000d0 61 2e 6c 61 6e 67 2e 4e 75 6d 62 65 72 86 ac 95 |a.lang.Number...| 000000e0 1d 0b 94 e0 8b 02 00 00 78 70 00 00 00 00 02 81 |........xp......| 000000f0 ee f1 |..| 000000f2

So it kind of seems like the timestamper plugin is somehow implicated in this nonsense, but when I go and read their code, I don't see anything about this stuff.

Which bit of Jenkins is actually doing this, and is there a way to avoid it?

Hakanai
  • 12,010
  • 10
  • 62
  • 132
  • 1
    The "ha" protocol is "high availability". Do you have a HA plugin installed? –  Dec 21 '17 at 22:21
  • @Amy nope, no HA plugin installed. – Hakanai Dec 21 '17 at 22:35
  • Is it https://groups.google.com/d/msg/jenkinsci-dev/_6PSKgQ8giQ/PF2kgp1nOykJ? (a serialized ConsoleNote object or one of its decendants.) See http://code.dblock.org/2011/09/07/implementing-my-first-jenkins-plugin-ansicolor.html#console-notes or https://www.programcreek.com/java-api-examples/index.php?api=hudson.console.ConsoleNote – VonC Dec 21 '17 at 22:38
  • @VonC it seems _really similar_, maybe this is it? The only difference is AAAA vs. ////. So I guess the only mystery is how to stop it doing this... :/ – Hakanai Dec 21 '17 at 22:41
  • @Trejkaz Try disabling all plugins, and re-enabling them one by one, to see which one would produce such a log. – VonC Dec 21 '17 at 22:42
  • If it's a ConsoleNote then it's [jenkins itself](https://github.com/jenkinsci/jenkins/blob/master/core/src/main/java/hudson/console/ConsoleNote.java#L302)... – Hakanai Dec 21 '17 at 22:43
  • Turning off timestamper makes things run at a normal speed again, so I guess that's the answer to the question. But we do want timestamps, so this is a rather dissatisfying conclusion. It seems that the timestamper plugin is an overengineered mess which could have just timestamped the logs, but instead appears to contain a framework to allow reformatting timestamps on the page when viewing the log, and everything about how that thing is stored (or nearly everything) is completely broken. :( – Hakanai Dec 22 '17 at 03:11
  • According [Class TimestampNote](http://javadoc.jenkins.io/timestamper/hudson/plugins/timestamper/TimestampNote.html) time-stamp console note are inserted into the log file when: "The build does not extend AbstractBuild, e.g. a pipeline job. Running the Timestamper plugin prior to version 1.4. The system property is set ... Otherwise, the time-stamps are stored in a separate file ..." – U880D Feb 28 '18 at 10:17

1 Answers1

0

Good detective work, @Trejkaz. Disabling the timestamper plugin did NOT fix things for me (I left the plugin installed; perhaps I should have removed it altogether or restarted Jenkins one more time to be sure).

My best answer (the one I'm using in practice) gets rid of all the escape sequences in the console AND in the context of this question, removes all of the 'ha:////' URLs as well so I get pretty close to unadorned, complete ASCII text in my processed console log. It's worth mentioning that our site's automation culture is to allow Jenkins builds to expire except those marked for keeping, so my workflow is to produce a postprocessed console log artifact to "keep" and not to archive the original log. It's not to create a smaller log in the first place, which I saw as more time- and resource-consuming for no discernible benefit.
Presuming the raw Jenkins console log lives in console-log.txt, it's:

ansi2txt < console-log.txt | col -b | sed 's;ha:////[[:print:]]*AAAA[=]*;;g'

This eliminates escape sequences meant to provide terminal display sugar without requiring build and installation of tool packages not found in any repo (in Ubuntu ansi2txt comes from colorized-logs and col comes from bsdmainutils), removes the mysterious 'ha:////' URLs regardless of their source, and turns a raw console log that looks like:

Started by user ESC[8mha:////4AqgegZw7qQ8DI1+KvWPDM7IJMwAv+ifWfXHqdHJJeCwAAAAlx+
LCAAAAAAAAP9b85aBtbiIQTGjNKU4P08vOT+vOD8nVc83PyU1x6OyILUoJzMv2y+/JJUBAhiZGBgqihh
k0NSjKDWzXb3RdlLBUSYGJk8GtpzUvPSSDB8G5tKinBIGIZ+sxLJE/ZzEvHT94JKizLx0a6BxUmjGOUN
odHsLgAzWEgZu/dLi1CL9xJTczDwAj6GcLcAAAAA=ESC[0mAdmin
Checking out git ssh://git@github.com/SlipChip/PHX-Inst-App-SW.git into /var/tmp
/meta-talis/workspace/Firmware-Inst-App-SW@script to read Jenkinsfile
...
Commit message: "Add Jenkins console log as artifact console-log.txt."
 > git rev-list --no-walk b70ac257fc5c87aa4a1fe55661b3523842f43412 # timeout=10
Running in Durability level: MAX_SURVIVABILITY
ESC[8mha:////4Ke8FKbo31T+wvpwDtO0m31cw6Dr9enqafGE6M9os2Y7AAAAoh+LCAAAAAAAAP9tjTEOwjAQBM8BClpKHuFItIiK1krDC0x8GCfWnbEdkooX8TX+gCESFVvtrLSa5wtWKcKBo5UdUu8otU4GP9jS5Mixv3geZcdn2TIl9igbHBs2eJyx4YwwR1SwULBGaj0nRzbDRnX6rmuvydanHMu2V1A5c4MHCFXMWcf8hSnC9jqYxPTz/BXAFEIGsfuclm8zQVqFvQAAAA==ESC[0m[Pipeline] Start of Pipeline
ESC[8mha:////4IgCbJC4forU2exyZEKrDUTKRV7HgFuwndWEBhDMO34wAAAApR+LCAAAAAAAAP9tjTEOwjAUQ3+KOrAycohUghExsUZZOEFIQkgb/d8mKe3EibgadyBQiQlLlmxL1nu+oE4RjhQdby12HpP2vA+jK4lPFLtroIm3dOGaMFGwXNpJkrGnpUrKFhaxClYC1hZ1oOTRZdiIVt1VExS65pxj2Q4CKm8GeAAThZxVzN8yR9jeRpMIf5y/AJj7DGxXvP/86jduZBmjwAAAAA==ESC[0m[Pipeline] node
...

into the considerably more palatable:

Started by user Admin
Checking out git ssh://git@github.com/SlipChip/PHX-Inst-App-SW.git into /var/tmp/meta-talis/workspace/Firmware-Inst-App-SW@script to read Jenkinsfile
...
Commit message: "Add Jenkins console log as artifact console-log.txt."
 > git rev-list --no-walk b70ac257fc5c87aa4a1fe55661b3523842f43412 # timeout=10
Running in Durability level: MAX_SURVIVABILITY
[Pipeline] Start of Pipeline
[Pipeline] node

which is the same as what I see in the Jenkins web interface when browsing the console log.

I hope this answer helps you in a practical sense (i.e. rather than making an O(n) walkthrough of all of your plugins searching for the 'ha:////' culprit).

Modus Tollens
  • 5,083
  • 3
  • 38
  • 46
Frank Hoeflich
  • 538
  • 2
  • 9