Shortlog strip console notes #4905

tszmytka · 2020-08-09T16:00:38Z

No JIRA ticket exists.

While rendering log output for a large logfile Jenkins skips the beginning and shows the last 150KB of data. It is possible that the beginning of such a shortlog falls in the middle of a serialized ConsoleNote and then part of a Gziped and base64-encoded string gets rendered in the output.
This may lead to suspicions that something in the build went wrong and/or that Jenkins or one of its plugins did something wrong. In fact there is a pretty old issue in ansicolor-plugin suspecting just that.

This PR takes care of this by:

Extending the amount of logfile data being read by an additional amount (preBuffer) used to detect if shortlog begin falls in the middle of a serialized ConsoleNote
Moving the shortlog beginning (if needed) to just after the ConsoleNote
Adding a negative and positive case scenario tests

Please let me know if you would prefer to have a full-blown JIRA ticket (the change is not that big) - I will be happy to create it if you think the issue is worth it.

Proposed changelog entries

Do not render parts of a serialized ConsoleNote in truncated log output.

Proposed upgrade guidelines

N/A

Submitter checklist

Changelog entries and upgrade guidelines are appropriate for the audience affected by the change (users or developer, depending on the change). Examples
- Fill-in the Proposed changelog entries section only if there are breaking changes or other changes which may require extra steps from users during the upgrade
Appropriate autotests or explanation to why this change has no tests

Maintainer checklist

Before the changes are marked as ready-for-merge:

There are at least 2 approvals for the pull request and no outstanding requests for change
Conversations in the pull request are over OR it is explicit that a reviewer does not block the change
Changelog entries in the PR title and/or Proposed changelog entries are correct
Proper changelog labels are set so that the changelog can be generated automatically
If the change needs additional upgrade steps from users, upgrade-guide-needed label is set and there is a Proposed upgrade guidelines section in the PR title. (example)
If it would make sense to backport the change to LTS, a Jira issue must exist, be a Bug or Improvement, and be labeled as lts-candidate to be considered (see query).

…he middle of it. Generalize finding pre/postamble

…l output as well. Test sample script output.

…ly the relevant lines get processed

jglick · 2020-08-10T16:58:00Z

I imagine there is already something in Jira for this.

Seems that the problem could be fixed with a much less intrusive patch solely to the log truncation logic: only truncate at a line boundary (after '\n'). That would be desirable anyway, and would ensure that we do not start in the middle of a console annotation.

jglick · 2020-08-10T17:00:45Z

Or, the log truncation logic (in Run IIRC—not part of hudson.console) could just check for the POSTAMBLE in the start of the truncated log (up to first newline).

tszmytka · 2020-08-10T18:53:42Z

the problem could be fixed with a much less intrusive patch solely to the log truncation logic: only truncate at a line boundary (after '\n').

I thought maybe there was a reason it hasn't been implemented like this in the first place. This would change the actual "contract" from give me last 150KB worth of chars to give me last 150KB _or less_ worth of chars. It would require adjustments in ansicolor-plugin (it needs to find the log line where shortlog will begin) maybe even cause bugs in other plugins.
I tried to keep the outside affecting changes as small as possible.

Or, the log truncation logic (in Run IIRC—not part of hudson.console) could just check for the POSTAMBLE in the start of the truncated log (up to first newline).

I haven't gone this way because I thought the possibility of this functionality unnecessarily kicking-in would be relatively high taking into account that POSTAMBLE = ESC[0m - the same as SGR Reset which is a pretty common ANSI escape sequence. I didn't want to trigger any other problems.

I think the preBuffer approach has the benefit of keeping all existing functionalities intact apart from when the beginning of the log falls in the middle of a ConsoleNote. But of course I can adjust/simplify/change the implementation if needed.

jglick · 2020-08-19T20:36:54Z

I thought maybe there was a reason it hasn't been implemented like this in the first place.

Simple laziness AFAIK.

This would change the actual "contract" from give me last 150KB worth of chars to give me last 150KB _or less_ worth of chars.

Fine from my PoV. The 150Kb is just a rough cutoff.

It would require adjustments in ansicolor-plugin (it needs to find the log line where shortlog will begin)

Not sure I am following.

keeping all existing functionalities intact apart from when the beginning of the log falls in the middle of a ConsoleNote.

I think it would be preferable to only display a complete initial line, even if there are no notes or any other ANSI escapes anywhere near.

daniel-beck · 2020-08-19T21:18:31Z

Fine from my PoV. The 150Kb is just a rough cutoff.

CC @oleg-nenashev this might be a problem with that feature you recently told me about IIRC?

tszmytka · 2020-08-22T12:30:31Z

OK, if I understand correctly this assignment shapes up to be:

Always start the log with a complete line
Begin from the first LF after 150KB spot
In the end truncated log will always contain less than 150KB worth of data

I am waiting on @oleg-nenashev regarding the last comment before starting off.

oleg-nenashev · 2020-08-24T12:23:13Z

CC @oleg-nenashev this might be a problem with that feature you recently told me about IIRC?

To explain, I have started experimenting with console log line linking/highlighting support (similar to GitHub code browser). This pull request is a kind of my spare-time self-education effort, and in the current state it is unlikely to be submitted as a PR anytime soon. So my work does not block this pull request.

jglick · 2020-08-24T15:56:24Z

this assignment shapes up to be

Yes, assuming this works out it seems like it would be the most straightforward solution.

Keep tests in adjusted form.

…lls on last line

…atic for really large logs

tszmytka · 2020-09-13T15:01:29Z

The implementation is done as suggested.
Looking forward to a review.

core/src/test/java/hudson/model/RunTest.java

core/src/main/java/hudson/model/Run.java

oleg-nenashev

Should be a net improvement. I am not sure whether check for \n is enough to cover all use-cases, but it should work for the declared ConSole Note objects which include encoded data and hence should not include line breaks.

Resetting start to 0 is a problem only in edge cases

oleg-nenashev · 2020-10-02T10:47:11Z

core/src/main/java/hudson/model/Run.java

+                    int r;
+                    do {
+                        r = bufferedInputStream.read();
+                        start = (r == -1)? 0 : start + 1;


So it will print the entire log if we hit the end of the stream, which defeats purpose of offset for large logs. Should not be a problem for real use-cases, but we might want to retain original behavior.

Suggested change

start = (r == -1)? 0 : start + 1;

start = (r == -1)? 0 : offset + 1;

The code change is not clear to me. My idea was to advance the start position for each byte that is different than \n. What this change would do is re-set start to the value of offset + 1 multiple times - offset doesn't get updated anywhere. Can you please explain what you had in mind?

This immediately breaks 2 tests which I think are valid use cases.

tszmytka · 2020-10-03T13:24:43Z

Resetting start to 0 is a problem only in edge cases

This might happen if someone tries to write the log, starting in the middle of the last line. I can see the following possibilities:

Behave as before and render part of the last line (possibly starting in the middle of a ConsoleNote).
Don't render anything.
Start reading a certain amount of bytes before offset, recognize this situation and actually render the whole last line.
Render the whole log (currently implemented).

I think options 1. and 2. are the worst and option 3. would be the best - my original approach would actually do just that but it's been viewed as "too intrusive" (not being snarky - maybe it was).
No 4. is the best solution sticking to the "only truncate at a line boundary" approach.
Looking forward to the pending review.

oleg-nenashev · 2020-10-04T10:00:10Z

Option 3 is likely to be an overkill. FTR I can live with Option 4. Since there is no negative feedback, let's go ahead

We may merge it in 24 hours if there is no negative feedback. Please see the merge process documentation for more information about the merge process

jglick · 2025-04-23T20:57:19Z

core/src/test/java/hudson/model/RunTest.java

+    @Test
+    public void wontPushOffsetOnRenderingFromBeginning() throws Exception {
+        assertWriteLogToEquals(new String(new char[5]).replace("\0", SAMPLE_BUILD_OUTPUT) + "Finished: SUCCESS.\n", 0);
+    }


Note that

@Test public void wontPushOffsetOnRenderingFromBeginningOfLine() throws Exception { assertWriteLogToEquals(new String(new char[3]).replace("\0", SAMPLE_BUILD_OUTPUT) + "Finished: SUCCESS.\n", 2 * SAMPLE_BUILD_OUTPUT.length()); }

fails: it prints 2 copies, not 3 like you might expect. This is because of a “fencepost error”: when the offset happens to point to the beginning of a line (just not the first line), that line is skipped.

If this method with offset > 0 is only being used to skip 150Kb of text or whatever, the bug would hardly be noticeable.

jglick · 2025-04-23T20:59:34Z

core/src/main/java/hudson/model/Run.java

-        getLogText().writeHtmlTo(offset, out.asWriter());
+        long start = offset;
+        if (offset > 0) {
+            try (BufferedInputStream bufferedInputStream = new BufferedInputStream(getLogInputStream())) {


This is a serious performance regression for Pipeline as discovered in #10515: as of jenkinsci/workflow-job-plugin#27 this method is not intended to scale well (jenkinsci/workflow-job-plugin#27 (comment)).

tszmytka added 4 commits August 9, 2020 15:45

Do not render parts of serialized a ConsoleNote if output begins in t…

8cd5ae9

…he middle of it. Generalize finding pre/postamble

Do not render parts of serialized a ConsoleNote while writing non-htm…

857a2ac

…l output as well. Test sample script output.

Add positive scenario test case. Fine-tune implementation

f15c856

Render progressive output with explicitly set no preBuffer. Ensure on…

4a1f969

…ly the relevant lines get processed

oleg-nenashev added rfe For changelog: Minor enhancement. use `major-rfe` for changes to be highlighted web-ui The PR includes WebUI changes which may need special expertise labels Aug 10, 2020

oleg-nenashev requested review from a team and oleg-nenashev August 10, 2020 16:17

tszmytka added 5 commits September 12, 2020 18:49

Revert pre-buffer functionality.

bd4d86e

Keep tests in adjusted form.

Push offset forward to start writing log on line beginning

be6cd7a

Move and fine-tune tests. Avoid rendering no output in case offset fa…

db7f231

…lls on last line

Merge branch 'master' into shortlog-strip-console-notes

014b187

Dont render whole log on offset on the last line. It might be problem…

7c79230

…atic for really large logs

varyvol reviewed Sep 17, 2020

View reviewed changes

core/src/test/java/hudson/model/RunTest.java Outdated Show resolved Hide resolved

alecharp reviewed Sep 17, 2020

View reviewed changes

core/src/main/java/hudson/model/Run.java Outdated Show resolved Hide resolved

Style adjustments

2e71002

MRamonLeon approved these changes Sep 24, 2020

View reviewed changes

oleg-nenashev requested a review from a team October 2, 2020 10:43

oleg-nenashev approved these changes Oct 2, 2020

View reviewed changes

oleg-nenashev requested a review from a team October 2, 2020 10:51

oleg-nenashev added the ready-for-merge The PR is ready to go, and it will be merged soon if there is no negative feedback label Oct 4, 2020

oleg-nenashev merged commit dd134ef into jenkinsci:master Oct 8, 2020

jglick mentioned this pull request Apr 23, 2025

[JENKINS-75081] Avoid heap allocation when rendering large logs #10515

Merged

6 tasks

jglick reviewed Apr 23, 2025

View reviewed changes

jglick added a commit to jglick/jenkins that referenced this pull request Apr 23, 2025

Fixing Run.writeLogTo regressions in jenkinsci#4905

9201bc8

	start = (r == -1)? 0 : start + 1;
	start = (r == -1)? 0 : offset + 1;

Uh oh!

Shortlog strip console notes #4905

Shortlog strip console notes #4905

Uh oh!

Conversation

tszmytka commented Aug 9, 2020

Proposed changelog entries

Proposed upgrade guidelines

Submitter checklist

Maintainer checklist

Uh oh!

jglick commented Aug 10, 2020

Uh oh!

jglick commented Aug 10, 2020

Uh oh!

tszmytka commented Aug 10, 2020

Uh oh!

jglick commented Aug 19, 2020

Uh oh!

daniel-beck commented Aug 19, 2020

Uh oh!

tszmytka commented Aug 22, 2020

Uh oh!

oleg-nenashev commented Aug 24, 2020

Uh oh!

jglick commented Aug 24, 2020

Uh oh!

tszmytka commented Sep 13, 2020

Uh oh!

Uh oh!

Uh oh!

oleg-nenashev left a comment

Choose a reason for hiding this comment

Uh oh!

oleg-nenashev Oct 2, 2020

Choose a reason for hiding this comment

Uh oh!

tszmytka Oct 3, 2020

Choose a reason for hiding this comment

Uh oh!

tszmytka commented Oct 3, 2020

Uh oh!

oleg-nenashev commented Oct 4, 2020

Uh oh!

jglick Apr 23, 2025

Choose a reason for hiding this comment

Uh oh!

jglick Apr 23, 2025

Choose a reason for hiding this comment

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

7 participants