Skip to content

Send step INFO and DEBUG logging to stdout, keep warnings on stderr - #225

Open
skywalkw3r wants to merge 1 commit into
rundeck-plugins:mainfrom
skywalkw3r:step-logging-stdout
Open

skywalkw3r wants to merge 1 commit into
rundeck-plugins:mainfrom
skywalkw3r:step-logging-stdout

Conversation

@skywalkw3r

Copy link
Copy Markdown

Fixes #223. Also addresses #172 and #179 (the "everything is red" part).

Problem

Rundeck records every line a step writes to stderr at ERROR level, and this plugin sends all Python logging to stderr. So normal progress messages show in red as errors:

  • the pod log printed by Kubernetes / Job / Waitfor,
  • Job succeeded, waiting for deployment, and so on,
  • debug output when "Debug" is on.

Log filters that only act on NORMAL-level lines skip them: key-value-data, quiet-output (at its matchLoglevel), highlight-output and render-datatype.

Cause

Every script imports common.py before calling logging.basicConfig(...), and common.py calls logging.basicConfig(stream=sys.stderr, ...) at import. The first call wins, so each script's own call has no effect, including the two that ask for stdout.

Fix

  • Add common.log_info_to_stdout(). It sends DEBUG and INFO records to stdout and WARNING and above to stderr, in the same LEVEL: logger: message format as before, so existing filters that match that text keep working.
  • Call it instead of the ineffective basicConfig in the 21 workflow steps whose output is read by people.
  • Leave four scripts as they are, because Rundeck or job authors parse their stdout:
    • the resource model (node data),
    • the node executor and Execute Command step, which share a script (command output),
    • the file copier (the copied file's path),
    • the inline script step (the script's output).
  • In Waitfor, log Job failed as an error. It was INFO and red only because everything was.
  • In plugin.yaml, the Debug option of the 17 affected steps now says "Write debug messages to the step log" instead of "... to stderr".

This is opt-in per script rather than a change to common.py's default. A future script that writes data to stdout therefore stays safe unless it chooses to send its logging to stdout.

Compatibility

  • Text: the log format is unchanged.
  • Levels: warnings, errors and exceptions stay at ERROR level, and step exit codes are unchanged. What changes is the level of informational lines, from ERROR to NORMAL.
  • Filters:
    • Mask filters behave as before, because they act at every level.
    • highlight-output, render-datatype and quiet-output (with matchLoglevel: normal) now apply to these steps' INFO lines.
    • key-value-data can now capture RUNDECK:DATA: values from these steps if its regex matches the line as printed, INFO: kubernetes-wait-job: b'RUNDECK:DATA: ...'. Our jobs do this with mask filters that strip the prefix first. With the default regex, the prefix still prevents a match.
  • Unchanged format for three scripts: pods-read-logs.py, debug-ephemeral-container.py and deployment-wait.py asked for a bare %(message)s format that they never actually got. I kept the format they produce today so their output doesn't change shape.

Testing

  • New tests in contents/tests/test_common.py:
    • INFO goes to stdout, while WARNING and ERROR go to stderr.
    • DEBUG goes to stdout when it is enabled.
    • The four stdout-parsing scripts don't call the helper.
  • The full suite passes (138 tests). The helper also runs on Python 3.9.
  • job-wait.py run as a real process against an unreachable API with Debug on: the DEBUG line went to stdout, while urllib3's retry warnings and the traceback went to stderr.
  • Rundeck 6.2.1 with a k3s cluster, installed as a patched 3.0.5 zip together with the Waitfor duplicate-log PR (Wait for Job: print the pod log once #224). The Waitfor steps in these jobs have mask filters that strip the plugin prefix, plus a key-value-data filter:
Run 3.0.5 Patched
Waitfor, Indexed Job 38 lines, all ERROR (the pod log is printed 4 times). RUNDECK:DATA: pod_0 = done not captured 15 NORMAL, 2 ERROR (the plugin's WARNING: An error occurred - retries: N). {"pod_0":"done"} captured
Waitfor, failing Job 11 lines, all ERROR 9 NORMAL, 4 ERROR: two WARNING lines, ERROR: kubernetes-wait-job: Job failed, and Rundeck's result-code line. The step fails as before
Waitfor, our Ansible runner 413 lines, all ERROR (that run hit the race, so the log is printed twice) 209 lines, all NORMAL

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Copilot review overview

🟡 Changes recommended

Debug logging can corrupt the machine-readable JSON output from debug-ephemeral-container.py.

Review effort: Lite
Findings: 1 High severity

Open (1)
What changed in this PR

Updates Kubernetes workflow logging so informational output goes to stdout while warnings and errors remain on stderr.

Changes:

  • Adds split-stream logging and tests.
  • Applies it across workflow scripts.
  • Updates debug descriptions and failed-job error handling.
File Summary
plugin.yaml Updates Debug option descriptions.
contents/​tests/​test_common.py Tests logging routing and stdout exclusions.
contents/​StatefulSet-wait.py Enables normal output on stdout.
contents/​service-update.py Enables normal output on stdout.
contents/​service-delete.py Enables normal output on stdout.
contents/​service-create.py Enables normal output on stdout.
contents/​pods-wait.py Enables normal output on stdout.
contents/​pods-read-logs.py Updates logging behavior.
contents/​pods-delete.py Enables normal output on stdout.
contents/​pods-create.py Enables normal output on stdout.
contents/​pod-describe.py Enables normal output on stdout.
contents/​job-wait.py Splits logging and reports failed Jobs as errors.
contents/​job-run.py Enables normal output on stdout.
contents/​job-delete.py Enables normal output on stdout.
contents/​job-create.py Enables normal output on stdout.
contents/​deployment-wait.py Updates logging behavior.
contents/​deployment-update.py Enables normal output on stdout.
contents/​deployment-status.py Enables normal output on stdout.
contents/​deployment-delete.py Enables normal output on stdout.
contents/​deployment-create.py Enables normal output on stdout.
contents/​delete.py Enables normal output on stdout.
contents/​debug-ephemeral-container.py Changes logging, but debug output can contaminate JSON stdout.
contents/​create-from-yaml.py Enables normal output on stdout.
contents/​common.py Adds split stdout/stderr logging.

💡 Configure MCP servers for context-aware, tailored reviews. Learn more in the docs.


logging.basicConfig(stream=sys.stdout, level=logging.INFO,
format='%(message)s')
common.log_info_to_stdout()
Rundeck records every line a step writes to stderr at ERROR level. Every
script imports common.py, whose logging.basicConfig(stream=sys.stderr)
runs first, so each script's own basicConfig call has no effect and all
log records go to stderr, including those scripts meant for stdout. So
normal progress messages, such as the pod log that Kubernetes / Job /
Waitfor prints, are shown in red as errors, and log filters that only act
on normal output (key-value-data, quiet-output) never see those lines:
RUNDECK:DATA values printed by a Job cannot be captured, for example.

Add common.log_info_to_stdout(), which sends DEBUG and INFO records to
stdout and WARNING and above to stderr, in the same format as before so
existing filters keep matching, and call it in place of the ineffective
basicConfig in the workflow steps whose output is read by people. The
resource model, node executor, file copier and inline script steps are
unchanged, because Rundeck and job authors parse their stdout.

The Waitfor step now logs "Job failed" as an error, so a failed Job is
still shown as one.

The Debug option of those steps now says debug messages go to the step
log instead of to stderr.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

Step output logged through Python logging lands at ERROR level (red), and log filters skip it

2 participants