Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Plugin spews MANY, MANY log messages. #49

Closed
nightskyguy opened this issue Jun 11, 2021 · 9 comments
Closed

Plugin spews MANY, MANY log messages. #49

nightskyguy opened this issue Jun 11, 2021 · 9 comments
Labels
bug Something isn't working

Comments

@nightskyguy
Copy link

Version report

Jenkins and plugins versions report:

Jenkins: 2.277.4.3
OS: Linux - 4.15.0-47-generic
---
Parameterized-Remote-Trigger: "3.1.5.1"
ace-editor: "1.1"
analysis-collector: "2.0.0"
analysis-core: "1.96"
analysis-model-api: "10.0.0"
ansicolor: "1.0.0"
ant: "1.11"
antisamy-markup-formatter: "2.1"
any-buildstep: "0.1"
apache-httpcomponents-client-4-api: "4.5.13-1.0"
artifactdeployer: "0.33"
async-http-client: "1.7.24.3"
audit-trail: "3.8"
authentication-tokens: "1.4"
authorize-project: "1.4.0"
aws-credentials: "1.28.1"
aws-java-sdk: "1.11.995"
blame-upstream-commiters: "1.2"
blueocean: "DISABLED:1.24.6"
blueocean-autofavorite: "DISABLED:1.2.4"
blueocean-bitbucket-pipeline: "DISABLED:1.24.6"
blueocean-commons: "DISABLED:1.24.6"
blueocean-config: "DISABLED:1.24.6"
blueocean-core-js: "DISABLED:1.24.6"
blueocean-dashboard: "DISABLED:1.24.6"
blueocean-display-url: "DISABLED:2.4.1"
blueocean-events: "DISABLED:1.24.6"
blueocean-git-pipeline: "DISABLED:1.24.6"
blueocean-github-pipeline: "DISABLED:1.24.6"
blueocean-i18n: "DISABLED:1.24.6"
blueocean-jira: "DISABLED:1.24.6"
blueocean-jwt: "DISABLED:1.24.6"
blueocean-personalization: "DISABLED:1.24.6"
blueocean-pipeline-api-impl: "DISABLED:1.24.6"
blueocean-pipeline-editor: "DISABLED:1.24.6"
blueocean-pipeline-scm-api: "DISABLED:1.24.6"
blueocean-rest: "DISABLED:1.24.6"
blueocean-rest-impl: "DISABLED:1.24.6"
blueocean-web: "DISABLED:1.24.6"
bootstrap4-api: "4.6.0-3"
bouncycastle-api: "2.20"
branch-api: "2.6.3"
>> build-history-manager: "1.3.0"  <<
build-name-setter: "2.2.0"
build-timeout: "1.20"
build-token-root: "1.7"
build-user-vars-plugin: "1.7"
build-view-column: "0.3"
build-with-parameters: "1.5.1"
built-on-column: "1.1"
checks-api: "1.7.0"
checkstyle: "4.0.0"
claim: "2.18.2"
clang-scanbuild-plugin: "1.7"
cloudbees-aborted-builds: "1.14"
cloudbees-administrative-monitors: "1.0.1"
cloudbees-analytics: "1.28"
cloudbees-assurance: "2.276.0.3"
cloudbees-aws-cli: "1.5.15"
cloudbees-aws-deployer: "1.18"
cloudbees-bitbucket-branch-source: "2.9.7"
cloudbees-blueocean-default-theme: "DISABLED:0.8"
cloudbees-consolidated-build-view: "1.6.1"
cloudbees-credentials: "3.3"
cloudbees-even-scheduler: "3.10"
cloudbees-folder: "6.15"
cloudbees-folders-plus: "3.12"
cloudbees-groovy-view: "1.13"
cloudbees-ha: "DISABLED:4.27"
cloudbees-jsync-archiver: "5.15"
cloudbees-label-throttling-plugin: "3.8"
cloudbees-license: "9.53"
cloudbees-long-running-build: "1.16"
cloudbees-monitoring: "2.11"
cloudbees-nodes-plus: "1.22"
cloudbees-platform-common: "1.7"
cloudbees-plugin-usage: "2.7"
cloudbees-quiet-start: "1.7"
cloudbees-request-filter: "1.7"
cloudbees-ssh-slaves: "2.9"
cloudbees-support: "3.26"
cloudbees-template: "4.49"
cloudbees-uc-data-api: "4.43"
cloudbees-unified-ui: "1.6"
cloudbees-update-center-plugin: "4.59"
cloudbees-view-creation-filter: "1.6"
cloudbees-workflow-template: "3.12"
cloudbees-workflow-ui: "2.6"
clover: "4.12.0"
cobertura: "1.16"
code-coverage-api: "1.3.2"
command-launcher: "1.5"
concurrent-step: "1.0.0"
conditional-buildstep: "1.4.1"
config-file-provider: "3.7.2"
configuration-as-code: "1.47"
configuration-as-code-support: "DISABLED:1.18"
copyartifact: "1.46"
cors-filter: "1.1"
coverity: "1.11.4"
create-fingerprint: "1.2"
credentials: "2.3.15.1"
credentials-binding: "1.24"
cucumber-testresult-plugin: "0.10.1"
dashboard-view: "2.16"
data-tables-api: "1.10.23-3"
depgraph-view: "1.0.5"
deployed-on-column: "1.8"
deployer-framework: "1.3"
description-setter: "1.10"
display-url-api: "2.3.4"
docker-build-publish: "1.3.3"
docker-commons: "1.17"
docker-java-api: "3.1.5.2"
docker-plugin: "1.2.2"
docker-traceability: "1.2"
docker-workflow: "1.26"
dockerhub-notification: "2.5.2"
downstream-build-cache: "1.6"
downstream-buildview: "1.9"
dropdown-viewstabbar-plugin: "1.7"
dtkit-api: "3.0.0"
durable-task: "1.35"
echarts-api: "5.0.1-1"
email-ext: "2.82"
embeddable-build-status: "2.0.3"
emma: "1.31"
envinject: "2.4.0"
envinject-api: "1.7"
external-monitor-job: "1.7"
fail-the-build-plugin: "1.0"
favorite: "DISABLED:2.3.3"
file-leak-detector: "1.6"
findbugs: "5.0.0"
flexible-publish: "0.16.1"
font-awesome-api: "5.15.2-2"
forensics-api: "1.0.0"
git: "4.7.1"
git-client: "3.7.1"
git-parameter: "0.9.13"
git-server: "1.9"
git-validated-merge: "3.30"
github: "1.33.1"
github-api: "1.123"
github-branch-source: "2.10.2"
github-pull-request-build: "1.13"
gradle: "1.36"
greenballs: "1.15.1"
groovy: "2.4"
groovy-events-listener-plugin: "1.014"
handlebars: "1.1.1"
handy-uri-templates-2-api: "2.1.8-1.0"
hsts-filter-plugin: "1.0"
htmlpublisher: "1.25"
http_request: "1.9.0"
hue-light: "1.2.0"
icon-shim: "3.0.0"
icon-shim-plugin: "1.0.0"
ignore-committer-strategy: "1.0.4"
infradna-backup: "3.38.34"
jackson2-api: "2.12.1"
jacoco: "3.1.1"
javadoc: "1.6"
jaxb: "2.3.0.1"
jdk-tool: "1.5"
jenkins-design-language: "DISABLED:1.24.6"
jenkins-multijob-plugin: "1.36"
jira: "3.2.1"
jjwt-api: "0.11.2-5.143e44951c52"
job-dsl: "1.77"
join: "1.21"
jquery: "1.12.4-1"
jquery-detached: "1.2.1"
jquery-ui: "1.0.2"
jquery3-api: "3.6.0-1"
jsch: "0.1.55.2"
junit: "1.49"
kubernetes: "1.29.2"
kubernetes-client-api: "4.13.2-1"
kubernetes-credentials: "0.8.0"
label-linked-jobs: "6.0.1"
ldap: "2.4"
lenientshutdown: "1.1.1"
lockable-resources: "2.10"
log-parser: "DISABLED:2.1"
login-theme: "1.1"
mail-watcher-plugin: "1.16"
mailer: "1.34"
managed-scripts: "1.5.4"
mapdb-api: "1.0.9.0"
matrix-auth: "2.6.6"
matrix-project: "1.18"
matrixtieparent: "1.2"
maven-plugin: "3.10"
mercurial: "2.14"
metrics: "4.0.2.7"
mission-control-view: "0.9.16"
momentjs: "1.1.1"
monitoring: "1.87.0"
msbuild: "1.30"
mstest: "1.0.0"
mstestrunner: "1.3.0"
multibranch-action-triggers: "1.8.6"
multiple-scms: "0.8"
nectar-license: "8.31"
nectar-rbac: "5.57"
next-build-number: "1.6"
node-iterator-api: "1.5"
nodelabelparameter: "1.8.1"
notification: "1.14"
okhttp-api: "3.14.9"
operations-center-agent: "2.277.0.2"
operations-center-analytics-config: "2.222.0.1"
operations-center-analytics-reporter: "2.222.0.1"
operations-center-client: "2.277.0.4"
operations-center-cloud: "2.277.0.1"
operations-center-context: "2.277.0.5"
operations-center-openid-cse: "1.8.110"
pagerduty: "0.7.0"
pam-auth: "1.6"
parameterized-trigger: "2.40"
pipeline-build-step: "2.13"
pipeline-github: "2.7"
pipeline-github-lib: "1.0"
pipeline-graph-analysis: "1.10"
pipeline-input-step: "2.12"
pipeline-milestone-step: "1.3.2"
pipeline-model-api: "1.8.4"
pipeline-model-declarative-agent: "1.1.1"
pipeline-model-definition: "1.8.4"
pipeline-model-extensions: "1.8.4"
pipeline-rest-api: "2.19"
pipeline-stage-step: "2.5"
pipeline-stage-tags-metadata: "1.8.4"
pipeline-stage-view: "2.19"
pipeline-utility-steps: "2.8.0"
plain-credentials: "1.7"
plugin-util-api: "2.1.0"
pmd: "4.0.0"
popper-api: "1.16.1-2"
postbuildscript: "2.11.0"
preSCMbuildstep: "0.3"
promoted-builds: "3.9.1"
pubsub-light: "DISABLED:1.13"
python: "1.3"
rake: "1.8.0"
rebuild: "1.32"
resource-disposer: "0.15"
run-condition: "1.5"
saml: "2.0.3"
scm-api: "2.6.4"
script-security: "1.76"
scriptler: "3.1"
secure-requester-whitelist: "1.6"
skip-plugin: "4.10"
snakeyaml-api: "1.27.0"
sse-gateway: "DISABLED:1.24"
ssh-agent: "1.22"
ssh-credentials: "1.18.1"
ssh-slaves: "1.31.5"
structs: "1.22"
subversion: "2.14.2"
support-core: "2.72.1"
suppress-stack-trace: "1.6"
testdroid-run-in-cloud: "2.114.0"
testng-plugin: "1.15"
text-file-operations: "1.3.2"
throttle-concurrents: "2.2"
timestamper: "1.12"
token-macro: "2.15"
translation: "1.15"
trigger-restrictions: "1.6"
trilead-api: "1.0.13"
unique-id: "2.2.0"
uno-choice: "2.5.6"
variant: "1.4"
view-job-filters: "2.3"
violations: "0.7.11"
warnings: "DISABLED:5.0.1"
warnings-ng: "9.0.1"
wikitext: "3.13"
windows-slaves: "1.7"
workflow-aggregator: "2.6"
workflow-api: "2.42"
workflow-basic-steps: "2.23"
workflow-cps: "2.90"
workflow-cps-checkpoint: "2.10"
workflow-cps-global-lib: "2.18"
workflow-cps-global-lib-http: "1.13.0"
workflow-durable-task-step: "2.38"
workflow-job: "2.40"
workflow-multibranch: "2.23"
workflow-remote-loader: "1.5"
workflow-scm-step: "2.12"
workflow-step-api: "2.23"
workflow-support: "3.8"
ws-cleanup: "0.39"
xcode-plugin: "2.0.15"
xunit: "3.0.2"
yet-another-build-visualizer: "1.14"
  • What Operating System are you using (both controller, and any agents involved in the problem)?
Ubuntu: OS: Linux - 4.15.0-47-generic

Reproduction steps

  • Create a pipeline script that allows one to set success/failure.
  • Build this script multiple times.
  • Observe the logs generated
#!groovy
  properties([[$class: 'JiraProjectProperty'], 
    buildDiscarder(BuildHistoryManager([[actions: [], conditions: [], continueAfterMatch: false, matchAtMost: 3],  // SKIP latest 3 builds 
        [actions: [], conditions: [BuildResult(matchSuccess: true)], continueAfterMatch: false, matchAtMost: 1],   // SKIP to and OVER the most recent SUCCESSful build.
        // to test, may want to delete the log file [$class: 'DeleteLogFileAction'] rather than the whole build.
        [actions: [DeleteBuild()], conditions: [MatchEveryBuild(), BuildResult(matchSuccess: true)], continueAfterMatch: false], // Delete all remaining successful builds.
        [actions: [], conditions: [MatchEveryBuild()], continueAfterMatch: false, matchAtMost: 4],  // keep 4 more builds (total of 8)
        [actions: [DeleteBuild()], conditions: [], continueAfterMatch: false]])), // delete all the remaining builds regardless of status
        disableConcurrentBuilds(), disableResume(), [$class: 'RebuildSettings', autoRebuild: false, rebuildDisabled: false], 
        parameters([booleanParam(defaultValue: false, description: '', name: 'FAILME')]), 
        throttleJobProperty(categories: [], limitOneJobWithMatchingParams: false, maxConcurrentPerNode: 0, maxConcurrentTotal: 0, paramsToUseForLimit: '', throttleEnabled: false, throttleOption: 'project')]
        )
    if (params.FAILME)
    {
        currentBuild.description = 'FAIL'
        sleep 5
        error "Forced to fail"
    } else {
        currentBuild.description = 'SUCCESS'
    }
  • Set up a job that can be made to succeed or fail.
  • Set up build history rules - really any will do, but this attempt was intended to: keep the latest 3 builds, the most recent successful build and all failed builds up to a total of 8 builds
  • Inspect the Jenkins log searching for p.d.j.b.BuildHistoryManager or p.d.j.b.model.Rule

Results

Expected result:

I expect perhaps one or two log messages per build - independent of the number of builds in the job or the number of rules.

Something like

Processing BuildHistory for Job X build number N with 200 builds. Applying 4 rules.
...
Done process BuildHistory for Job X build number N: 23 builds deleted, 2 logs removed, 0 artifacts removed.

I also expect that a DEBUG level log could be set to determine what rule(s) are being applied. But this level of detail should only be enabled if DEBUG level logging is enabled.

Actual result:

Info Level logging swamps the Jenkins log (this example is from kibana in reverse order). Here are 138 messages from ONE build with only 8 retained builds. Note that this came from Kibana and was resorted to restore proper order, so may not match the actual log order (since it will sort two records with the same time alphabetically). However these are all the log messages that were received.

2021-06-10 22:38:27.730+0000 [id=52]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Start evaluating build history
2021-06-10 22:38:27.731+0000 [id=52]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing actions for rule no 1
2021-06-10 22:38:27.731+0000 [id=52]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing actions for rule no 1
2021-06-10 22:38:27.731+0000 [id=52]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing actions for rule no 1
2021-06-10 22:38:27.731+0000 [id=52]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing actions for rule no 2
2021-06-10 22:38:27.731+0000 [id=52]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing build #135
2021-06-10 22:38:27.731+0000 [id=52]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing build #136
2021-06-10 22:38:27.731+0000 [id=52]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing build #137
2021-06-10 22:38:27.731+0000 [id=52]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing build #138
2021-06-10 22:38:27.731+0000 [id=52]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing build #139
2021-06-10 22:38:27.731+0000 [id=52]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing rule no 1
2021-06-10 22:38:27.731+0000 [id=52]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing rule no 1
2021-06-10 22:38:27.731+0000 [id=52]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing rule no 1
2021-06-10 22:38:27.731+0000 [id=52]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing rule no 1
2021-06-10 22:38:27.731+0000 [id=52]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing rule no 1
2021-06-10 22:38:27.731+0000 [id=52]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing rule no 2
2021-06-10 22:38:27.731+0000 [id=52]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing rule no 2
2021-06-10 22:38:27.731+0000 [id=52]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing rule no 3
2021-06-10 22:38:27.731+0000 [id=52]	INFO	p.d.j.b.model.Rule#validateConditions: platform/slave/slc_monitor_TEST: Processing condition 'Build result'
2021-06-10 22:38:27.731+0000 [id=52]	INFO	p.d.j.b.model.Rule#validateConditions: platform/slave/slc_monitor_TEST: Skipping rule because matched 1 times
2021-06-10 22:38:27.731+0000 [id=52]	INFO	p.d.j.b.model.Rule#validateConditions: platform/slave/slc_monitor_TEST: Skipping rule because matched 3 times
2021-06-10 22:38:27.731+0000 [id=52]	INFO	p.d.j.b.model.Rule#validateConditions: platform/slave/slc_monitor_TEST: Skipping rule because matched 3 times
2021-06-10 22:38:27.732+0000 [id=52]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing actions for rule no 3
2021-06-10 22:38:27.732+0000 [id=52]	INFO	p.d.j.b.model.Rule#performActions: platform/slave/slc_monitor_TEST: Processing action 'Delete build' for build #135
2021-06-10 22:38:27.732+0000 [id=52]	INFO	p.d.j.b.model.Rule#validateConditions: platform/slave/slc_monitor_TEST: Processing condition 'Build result'
2021-06-10 22:38:27.732+0000 [id=52]	INFO	p.d.j.b.model.Rule#validateConditions: platform/slave/slc_monitor_TEST: Processing condition 'Match every build'
2021-06-10 22:38:27.742+0000 [id=52]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing build #134
2021-06-10 22:38:27.742+0000 [id=52]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing rule no 1
2021-06-10 22:38:27.742+0000 [id=52]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing rule no 2
2021-06-10 22:38:27.742+0000 [id=52]	INFO	p.d.j.b.model.Rule#validateConditions: platform/slave/slc_monitor_TEST: Skipping rule because matched 1 times
2021-06-10 22:38:27.742+0000 [id=52]	INFO	p.d.j.b.model.Rule#validateConditions: platform/slave/slc_monitor_TEST: Skipping rule because matched 3 times
2021-06-10 22:38:27.743+0000 [id=52]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing actions for rule no 4
2021-06-10 22:38:27.743+0000 [id=52]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing actions for rule no 4
2021-06-10 22:38:27.743+0000 [id=52]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing build #132
2021-06-10 22:38:27.743+0000 [id=52]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing rule no 1
2021-06-10 22:38:27.743+0000 [id=52]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing rule no 2
2021-06-10 22:38:27.743+0000 [id=52]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing rule no 3
2021-06-10 22:38:27.743+0000 [id=52]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing rule no 3
2021-06-10 22:38:27.743+0000 [id=52]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing rule no 4
2021-06-10 22:38:27.743+0000 [id=52]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing rule no 4
2021-06-10 22:38:27.743+0000 [id=52]	INFO	p.d.j.b.model.Rule#validateConditions: platform/slave/slc_monitor_TEST: Condition 'Build result' does not match
2021-06-10 22:38:27.743+0000 [id=52]	INFO	p.d.j.b.model.Rule#validateConditions: platform/slave/slc_monitor_TEST: Condition 'Build result' does not match
2021-06-10 22:38:27.743+0000 [id=52]	INFO	p.d.j.b.model.Rule#validateConditions: platform/slave/slc_monitor_TEST: Processing condition 'Build result'
2021-06-10 22:38:27.743+0000 [id=52]	INFO	p.d.j.b.model.Rule#validateConditions: platform/slave/slc_monitor_TEST: Processing condition 'Build result'
2021-06-10 22:38:27.743+0000 [id=52]	INFO	p.d.j.b.model.Rule#validateConditions: platform/slave/slc_monitor_TEST: Processing condition 'Match every build'
2021-06-10 22:38:27.743+0000 [id=52]	INFO	p.d.j.b.model.Rule#validateConditions: platform/slave/slc_monitor_TEST: Processing condition 'Match every build'
2021-06-10 22:38:27.743+0000 [id=52]	INFO	p.d.j.b.model.Rule#validateConditions: platform/slave/slc_monitor_TEST: Processing condition 'Match every build'
2021-06-10 22:38:27.743+0000 [id=52]	INFO	p.d.j.b.model.Rule#validateConditions: platform/slave/slc_monitor_TEST: Processing condition 'Match every build'
2021-06-10 22:38:27.743+0000 [id=52]	INFO	p.d.j.b.model.Rule#validateConditions: platform/slave/slc_monitor_TEST: Skipping rule because matched 1 times
2021-06-10 22:38:27.743+0000 [id=52]	INFO	p.d.j.b.model.Rule#validateConditions: platform/slave/slc_monitor_TEST: Skipping rule because matched 3 times
2021-06-10 22:38:27.744+0000 [id=52]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing actions for rule no 4
2021-06-10 22:38:27.744+0000 [id=52]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing build #130
2021-06-10 22:38:27.744+0000 [id=52]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing build #131
2021-06-10 22:38:27.744+0000 [id=52]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing rule no 1
2021-06-10 22:38:27.744+0000 [id=52]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing rule no 1
2021-06-10 22:38:27.744+0000 [id=52]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing rule no 2
2021-06-10 22:38:27.744+0000 [id=52]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing rule no 2
2021-06-10 22:38:27.744+0000 [id=52]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing rule no 3
2021-06-10 22:38:27.744+0000 [id=52]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing rule no 3
2021-06-10 22:38:27.744+0000 [id=52]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing rule no 4
2021-06-10 22:38:27.744+0000 [id=52]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing rule no 4
2021-06-10 22:38:27.744+0000 [id=52]	INFO	p.d.j.b.model.Rule#validateConditions: platform/slave/slc_monitor_TEST: Condition 'Build result' does not match
2021-06-10 22:38:27.744+0000 [id=52]	INFO	p.d.j.b.model.Rule#validateConditions: platform/slave/slc_monitor_TEST: Condition 'Build result' does not match
2021-06-10 22:38:27.744+0000 [id=52]	INFO	p.d.j.b.model.Rule#validateConditions: platform/slave/slc_monitor_TEST: Processing condition 'Build result'
2021-06-10 22:38:27.744+0000 [id=52]	INFO	p.d.j.b.model.Rule#validateConditions: platform/slave/slc_monitor_TEST: Processing condition 'Build result'
2021-06-10 22:38:27.744+0000 [id=52]	INFO	p.d.j.b.model.Rule#validateConditions: platform/slave/slc_monitor_TEST: Processing condition 'Match every build'
2021-06-10 22:38:27.744+0000 [id=52]	INFO	p.d.j.b.model.Rule#validateConditions: platform/slave/slc_monitor_TEST: Processing condition 'Match every build'
2021-06-10 22:38:27.744+0000 [id=52]	INFO	p.d.j.b.model.Rule#validateConditions: platform/slave/slc_monitor_TEST: Skipping rule because matched 1 times
2021-06-10 22:38:27.744+0000 [id=52]	INFO	p.d.j.b.model.Rule#validateConditions: platform/slave/slc_monitor_TEST: Skipping rule because matched 1 times
2021-06-10 22:38:27.744+0000 [id=52]	INFO	p.d.j.b.model.Rule#validateConditions: platform/slave/slc_monitor_TEST: Skipping rule because matched 3 times
2021-06-10 22:38:27.744+0000 [id=52]	INFO	p.d.j.b.model.Rule#validateConditions: platform/slave/slc_monitor_TEST: Skipping rule because matched 3 times
2021-06-10 22:38:27.744+0000 [id=52]	INFO	p.d.j.b.model.Rule#validateConditions: platform/slave/slc_monitor_TEST: Processing condition 'Match every build'
2021-06-10 22:38:27.745+0000 [id=15922]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing actions for rule no 1
2021-06-10 22:38:27.745+0000 [id=15922]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing actions for rule no 1
2021-06-10 22:38:27.745+0000 [id=15922]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing actions for rule no 1
2021-06-10 22:38:27.745+0000 [id=15922]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing build #136
2021-06-10 22:38:27.745+0000 [id=15922]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing build #137
2021-06-10 22:38:27.745+0000 [id=15922]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing build #138
2021-06-10 22:38:27.745+0000 [id=15922]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing build #139
2021-06-10 22:38:27.745+0000 [id=15922]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing rule no 1
2021-06-10 22:38:27.745+0000 [id=15922]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing rule no 1
2021-06-10 22:38:27.745+0000 [id=15922]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing rule no 1
2021-06-10 22:38:27.745+0000 [id=15922]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing rule no 1
2021-06-10 22:38:27.745+0000 [id=15922]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing rule no 2
2021-06-10 22:38:27.745+0000 [id=15922]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Start evaluating build history
2021-06-10 22:38:27.745+0000 [id=15922]	INFO	p.d.j.b.model.Rule#validateConditions: platform/slave/slc_monitor_TEST: Processing condition 'Build result'
2021-06-10 22:38:27.745+0000 [id=15922]	INFO	p.d.j.b.model.Rule#validateConditions: platform/slave/slc_monitor_TEST: Skipping rule because matched 3 times
2021-06-10 22:38:27.745+0000 [id=52]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing actions for rule no 4
2021-06-10 22:38:27.745+0000 [id=52]	INFO	p.d.j.b.model.Rule#validateConditions: platform/slave/slc_monitor_TEST: Processing condition 'Match every build'
2021-06-10 22:38:27.746+0000 [id=15922]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing actions for rule no 2
2021-06-10 22:38:27.746+0000 [id=15922]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing actions for rule no 4
2021-06-10 22:38:27.746+0000 [id=15922]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing build #132
2021-06-10 22:38:27.746+0000 [id=15922]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing build #134
2021-06-10 22:38:27.746+0000 [id=15922]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing rule no 1
2021-06-10 22:38:27.746+0000 [id=15922]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing rule no 1
2021-06-10 22:38:27.746+0000 [id=15922]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing rule no 2
2021-06-10 22:38:27.746+0000 [id=15922]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing rule no 2
2021-06-10 22:38:27.746+0000 [id=15922]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing rule no 3
2021-06-10 22:38:27.746+0000 [id=15922]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing rule no 3
2021-06-10 22:38:27.746+0000 [id=15922]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing rule no 4
2021-06-10 22:38:27.746+0000 [id=15922]	INFO	p.d.j.b.model.Rule#validateConditions: platform/slave/slc_monitor_TEST: Condition 'Build result' does not match
2021-06-10 22:38:27.746+0000 [id=15922]	INFO	p.d.j.b.model.Rule#validateConditions: platform/slave/slc_monitor_TEST: Processing condition 'Build result'
2021-06-10 22:38:27.746+0000 [id=15922]	INFO	p.d.j.b.model.Rule#validateConditions: platform/slave/slc_monitor_TEST: Processing condition 'Match every build'
2021-06-10 22:38:27.746+0000 [id=15922]	INFO	p.d.j.b.model.Rule#validateConditions: platform/slave/slc_monitor_TEST: Processing condition 'Match every build'
2021-06-10 22:38:27.746+0000 [id=15922]	INFO	p.d.j.b.model.Rule#validateConditions: platform/slave/slc_monitor_TEST: Processing condition 'Match every build'
2021-06-10 22:38:27.746+0000 [id=15922]	INFO	p.d.j.b.model.Rule#validateConditions: platform/slave/slc_monitor_TEST: Skipping rule because matched 1 times
2021-06-10 22:38:27.746+0000 [id=15922]	INFO	p.d.j.b.model.Rule#validateConditions: platform/slave/slc_monitor_TEST: Skipping rule because matched 1 times
2021-06-10 22:38:27.746+0000 [id=15922]	INFO	p.d.j.b.model.Rule#validateConditions: platform/slave/slc_monitor_TEST: Skipping rule because matched 3 times
2021-06-10 22:38:27.746+0000 [id=15922]	INFO	p.d.j.b.model.Rule#validateConditions: platform/slave/slc_monitor_TEST: Skipping rule because matched 3 times
2021-06-10 22:38:27.747+0000 [id=15922]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing actions for rule no 4
2021-06-10 22:38:27.747+0000 [id=15922]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing build #131
2021-06-10 22:38:27.747+0000 [id=15922]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing rule no 1
2021-06-10 22:38:27.747+0000 [id=15922]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing rule no 2
2021-06-10 22:38:27.747+0000 [id=15922]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing rule no 3
2021-06-10 22:38:27.747+0000 [id=15922]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing rule no 4
2021-06-10 22:38:27.747+0000 [id=15922]	INFO	p.d.j.b.model.Rule#validateConditions: platform/slave/slc_monitor_TEST: Condition 'Build result' does not match
2021-06-10 22:38:27.747+0000 [id=15922]	INFO	p.d.j.b.model.Rule#validateConditions: platform/slave/slc_monitor_TEST: Processing condition 'Build result'
2021-06-10 22:38:27.747+0000 [id=15922]	INFO	p.d.j.b.model.Rule#validateConditions: platform/slave/slc_monitor_TEST: Processing condition 'Match every build'
2021-06-10 22:38:27.747+0000 [id=15922]	INFO	p.d.j.b.model.Rule#validateConditions: platform/slave/slc_monitor_TEST: Processing condition 'Match every build'
2021-06-10 22:38:27.747+0000 [id=15922]	INFO	p.d.j.b.model.Rule#validateConditions: platform/slave/slc_monitor_TEST: Skipping rule because matched 1 times
2021-06-10 22:38:27.747+0000 [id=15922]	INFO	p.d.j.b.model.Rule#validateConditions: platform/slave/slc_monitor_TEST: Skipping rule because matched 3 times
2021-06-10 22:38:27.754+0000 [id=15922]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing actions for rule no 4
2021-06-10 22:38:27.754+0000 [id=15922]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing build #130
2021-06-10 22:38:27.754+0000 [id=15922]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing rule no 1
2021-06-10 22:38:27.754+0000 [id=15922]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing rule no 2
2021-06-10 22:38:27.754+0000 [id=15922]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing rule no 3
2021-06-10 22:38:27.754+0000 [id=15922]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing rule no 4
2021-06-10 22:38:27.754+0000 [id=15922]	INFO	p.d.j.b.model.Rule#validateConditions: platform/slave/slc_monitor_TEST: Condition 'Build result' does not match
2021-06-10 22:38:27.754+0000 [id=15922]	INFO	p.d.j.b.model.Rule#validateConditions: platform/slave/slc_monitor_TEST: Processing condition 'Build result'
2021-06-10 22:38:27.754+0000 [id=15922]	INFO	p.d.j.b.model.Rule#validateConditions: platform/slave/slc_monitor_TEST: Processing condition 'Match every build'
2021-06-10 22:38:27.754+0000 [id=15922]	INFO	p.d.j.b.model.Rule#validateConditions: platform/slave/slc_monitor_TEST: Skipping rule because matched 1 times
2021-06-10 22:38:27.754+0000 [id=15922]	INFO	p.d.j.b.model.Rule#validateConditions: platform/slave/slc_monitor_TEST: Skipping rule because matched 3 times
2021-06-10 22:38:27.755+0000 [id=15922]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing actions for rule no 4
2021-06-10 22:38:27.755+0000 [id=15922]	INFO	p.d.j.b.BuildHistoryManager#perform: platform/slave/slc_monitor_TEST: Processing rule no 4
2021-06-10 22:38:27.755+0000 [id=15922]	INFO	p.d.j.b.model.Rule#validateConditions: platform/slave/slc_monitor_TEST: Condition 'Build result' does not match
2021-06-10 22:38:27.755+0000 [id=15922]	INFO	p.d.j.b.model.Rule#validateConditions: platform/slave/slc_monitor_TEST: Processing condition 'Build result'
2021-06-10 22:38:27.755+0000 [id=15922]	INFO	p.d.j.b.model.Rule#validateConditions: platform/slave/slc_monitor_TEST: Processing condition 'Match every build'
2021-06-10 22:38:27.755+0000 [id=15922]	INFO	p.d.j.b.model.Rule#validateConditions: platform/slave/slc_monitor_TEST: Processing condition 'Match every build'

image

@nightskyguy nightskyguy added the bug Something isn't working label Jun 11, 2021
@damianszczepanik
Copy link
Member

This is not a bug. This is a feature.

Imagine the situation when you are designing rules and conditions for new job. This helps you to prove that configuration is correct. This also helps me to fix the problem in case user reports bug.

@nightskyguy
Copy link
Author

nightskyguy commented Oct 16, 2021

This makes your plugin incompatible with our use of Jenkins. We can't afford thousands and thousands of lines of INFO level debugging that swamps all other logs. If someone DID need to debug, they could always add logging via the log manager.

Checking if Cloudbees supports SUPPRESSING logs using the log manager... but this is the first (and only) plugin we've used that exhibits this overabundance of logs.

https://support.cloudbees.com/hc/en-us/articles/204880580/comments/4408473755675

@a-wildman
Copy link

I disagree that this is a 'feature' -- such logging should occur at level DEBUG or TRACE. One can always set a custom logging level for a specific package if one wants to inspect how new rules are being evaluated.

On my Jenkins instance, INFO logging for this plugin is 844K lines per minute.

INFO is clearly not the right level for this kind of output.

@damianszczepanik
Copy link
Member

The goal is to show those log at job level not Jenkins level because access to the first is generally allowed for everyone while Jenkins logs is available only for admins

@a-wildman
Copy link

a-wildman commented Feb 22, 2022 via email

@damianszczepanik
Copy link
Member

That's true and this is because code that clears old jobs has no access to job context

@phillipjohnston
Copy link

This is definitely a problem that the default is DEBUG and not INFO, it is a ton of output. Why is it a feature to use up file system space and clutter a log with undesired information?

@damianszczepanik
Copy link
Member

@phillipjohnston @nightskyguy @a-wildman
can you review #59 - does it solve this problem ?

@damianszczepanik
Copy link
Member

Published

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

No branches or pull requests

4 participants