jenkinsloggingcontinuous-integrationverbosity

Jenkins console output flooded with [DEBUG] http-outgoing log entries


We have a build job where the console output shows many strange messages like below, so we cannot load a full log and have to remove the -X option in the build configuration to get rid of them. I think it happened after I upgraded the Jenkins version.

Any idea of what might be causing this?

[DEBUG] http-outgoing-0 >> "j[0x5]q4/J[0x18]^di[0x86][0xbf]C_[0xd6]G[0x1d] 
[0xd4][0x7][0xf3][0xc7][0x14][0xdf][0x8d][0xe1][0x13][0xd8]$y|#[0x1e][0xbf] 
[0xe6][0x81]<[0xca][0x6][0xa1]~j[0x81]3[0xbc][0x98][0xd1][0x83][0xa7] 
[0xc5]8[0xfa]>[0xd9]edZ[0xb2][0xc][0xe0][0x5][0xab][0xf3][0x1a]M[0xb3][0xe7] 
[0x1][0xf4][\n]"
[DEBUG] http-outgoing-0 >> "[0xcd][0x9d][0x86]Zjp[0xb4][0x8d][0x87] 
[0x8f]cn[0xe7][0xab]oL.[0xb2]}[0x86][0xf8]D[0x87][0xba][0x9d][0xcc]j[0x15] 
[0xa4][0xe6]![0x9f]_BBC[0xbf]j[0xab]Rl[0x10][0x92][0xc5])[0xb2][0xc5]i[0xc2]

Solution

  • I encountered this exact problem right around the same time (April 2018), and found that it was being triggered by Artifactory plugin 2.15.0 (and later). For over a year, I had left that plugin downgraded in order to avoid having DEBUG logging in my build logs. Although this worked for me (until I was forced to upgrade last week due to an incompatibility with new versions of Artifactory), it is possible that a different plugin or jar file in your classpath is causing the problem in your case.

    After spending an entire weekend troubleshooting this problem, I finally found the underlying cause in my build environment.

    The important points are:

    The Dormant Problem


    In my case, the underlying cause of the DEBUG logging was that I had cobertura-2.1.1.jar in my test dependencies, which contains a logback.xml file and also brings logback-classic.jar in as a dependency (widely regarded as a mistake, see Issue 2, Issue 14, Issue 36). The logback.xml file, when found in the classpath, overrides any other logback settings in Jenkins (and the project being built). However, since logback was not the logging framework selected by Apache Commons Logging (JCL), this log setting had never been triggered.

    The Trigger


    Upgrading the Artifactory plugin from 2.14.0 to 2.15.0 switched its logging from: commons-logging-1.1.1.jar (log4j-1.2.17.jar) to: jcl-over-slf4j-1.7.25.jar (slf4j-api-1.7.25.jar). FYI, log4j 1.x uses a default root logging level of DEBUG, while log4j 2.x uses a global logging level of ERROR, which may be an entirely different source of DEBUG logging (but not in my case). My build environment (ant) was supplying log4j 2.10.0 and logback on the classpath, which served only to confound my testing by producing inconsistent results depending on which plugins were running within the build process.

    When using Artifactory plugin v2.15.0+, the logging framework switches to logback, which gives the logback.xml file in cobertura-2.1.1.jar permission to set the root log level to DEBUG, forcing all of the subsequent parts of the build process to record at the DEBUG level. This includes wire-logging for Apache Commons HttpClient, which produces http-outgoing-0 (serialized hexadecimal and interleaved Base64 encoded content from every HTTP/S message - as you show in your question). Even for a small project, recording a single PUT of a JAR file in this way will increase both the build time and the size of your build logs by several orders of magnitude (this is what I was experiencing in my build environment), which can easily cripple your entire Jenkins server. This is a huge problem, and as you can see from the Cobertura GitHub issues above, even though it is an easy fix, no steps have been taken to produce a fixed version in four years.

    The Fix


    To fix this, I had to make several changes on my Jenkins server:

    For reference, my broken .ant/lib folder contained these logging-related jar files (2 possible sources of DEBUG logs):

    while my fixed .ant/lib folder contains the following logging jars:

    In my fixed Ant classpath, commons-logging-1.2 can only select the SLF4J API (or JUL), and only a single SLF4J implementation is available (slf4j-simple).

    TL;DR


    For three years, Cobertura 2.1.1 was telling logback to "DEBUG All the Things!", but nobody was listening until a new version of the Artifactory plugin changed the JCL version and brought along an SLF4J implementation that allowed logback to be selected as the "best available" logging framework. When the JCL was introduced to logback, logback took Cobertura's advice and threw a party in my build logs. This can be prevented by removing logback from the environment and supplying a well-behaved logging framework for the JCL and SLF4J API (such as slf4j-simple).