[JEP-210] Log handling rewrite #27

jglick · 2016-09-23T22:51:30Z

Downstream of jenkinsci/workflow-api-plugin#17 and jenkinsci/workflow-support-plugin#15. Cf. #21.

JEP-210

basics
avoid overhead of serialized ConsoleNote on every line
pluggable log location
tests of annotation, single-step log display
basic show/hide UI for steps (adapted from [JENKINS-27394] Collapsible sections in log #21)
show/hide entire sections
~~optimize PipelineLargeText.<init>~~
~~optimize WorkflowRun.getLogInputStream~~

Nice-to-have things I am deferring:

node anchors, e.g. for [JENKINS-28119] ErrorInfoStep workflow-basic-steps-plugin#2
hide all but first parallel branch by default
gesture to hide all Pipeline steps

oleg-nenashev

Looks good so far

oleg-nenashev · 2016-09-26T23:01:29Z

src/main/java/org/jenkinsci/plugins/workflow/job/WorkflowRun.java

+        if (executor != null) {
+            AsynchronousExecution asynchronousExecution = executor.getAsynchronousExecution();
+            if (asynchronousExecution != null) {
+                asynchronousExecution.completed(null);


Why would we need it?

Uses to be part of copyLogsTask (line 278); that is now gone, so we need to somehow release the flyweight executor slot. This seems like the appropriate place to do it.

oleg-nenashev · 2016-09-28T10:12:25Z

pom.xml

        </pluginRepository>
    </pluginRepositories>
    <properties>
        <jenkins.version>1.642.3</jenkins.version>
+        <hpi-plugin.version>1.120</hpi-plugin.version>


Ideally should be updated in the Parent POM

Please review jenkinsci/plugin-pom#35. :-)

oleg-nenashev · 2016-09-28T10:13:31Z

src/main/java/org/jenkinsci/plugins/workflow/job/WorkflowRun.java

@@ -200,8 +181,10 @@ public WorkflowRun(WorkflowJob job, File dir) throws IOException {
        }
        try {
            onStartBuilding();
+            // TODO introduce API to wrap out log location


Implementation from the prototype: https://github.com/oleg-nenashev/workflow-job-plugin/tree/jw-hackaton-external-logging

Saw that, but it is not going to work.

oleg-nenashev · 2016-09-28T10:18:43Z

src/main/java/org/jenkinsci/plugins/workflow/job/WorkflowRun.java

@@ -825,6 +646,10 @@ private String key() {
                return TaskListener.NULL;
            }
        }
+        @Override public InputStream getLog() throws IOException {


Maybe Stream is not a perfect solution for Logging. I would rather go after an event-based model similar to JUL, but it will require more changes (it's in my design btw)

Tons of Jenkins APIs expect a TaskListener or OutputStream for output, and expect an AnnotatedLargeText or InputStream for input, so streams are mandated at some level I think. Of course a logging implementation might internally work with lines.

oleg-nenashev · 2016-09-28T10:20:25Z

src/main/java/org/jenkinsci/plugins/workflow/job/console/WorkflowRunConsoleNote.java

 */
 public class WorkflowRunConsoleNote extends ConsoleNote<Run<?, ?>> {

    /**
     * Prefix used in metadata lines.
     */
-    public static final String CONSOLE_NOTE_PREFIX = "[Pipeline] ";
+    private static final String CONSOLE_NOTE_PREFIX = "[Pipeline] ";


🐜 binary compat change without a real need

Just minimizing access of things which were never really supposed to be public.

…ase.

…e for getLogFile().

…es from jenkinsci#21.

…y encompassing all of the functionality of jenkinsci#21.

svanoort · 2018-09-26T23:04:29Z

src/main/java/org/jenkinsci/plugins/workflow/job/WorkflowRun.java

+    // TODO log-related overrides pending JEP-207:
+
+    @Override public InputStream getLogInputStream() throws IOException {
+        // Inefficient but probably rarely used anyway.


And comments like this make me realize that the log-handling rewrite that was supposed to deliver some great performance improvements may fall well short of that mark.

My interest is in writes, not reads.

Not much point of a log that nobody reads though, is there? Anyway, we can see if it comes up as an issue.

Also, please do not mark this one "resolved" unless the code has been changed due to feedback -- it'll make it easier to address this if it comes up as a problem in the future.

This particular method is rarely called AFAIK.

svanoort · 2018-09-26T23:08:28Z

src/main/java/org/jenkinsci/plugins/workflow/job/WorkflowRun.java

+
+    @Override public List<String> getLog(int maxLines) throws IOException {
+        int lineCount = 0;
+        List<String> logLines = new LinkedList<>();


🐜 Why you should never use a LinkedList. TL;DR: Locality-of-reference matters, allocate a darned ArrayList.

This is just copied from core.

Note that the core implementation of this method has since been rewritten. As I pointed out in jenkinsci/jenkins#2607 (comment) that is irrelevant, since this method is not used in production workflows. Anyway the rewrite is impossible to apply here since it relies on RandomAccessFile.

Copy and pasted code? Still...

I'm going to keep pointing out that LinkedList is a bad idea until people stop (ab)using it.

This method is not used in production. The performance does not matter.

src/main/java/org/jenkinsci/plugins/workflow/job/WorkflowRun.java

svanoort · 2018-09-26T23:19:36Z

src/main/java/org/jenkinsci/plugins/workflow/job/WorkflowRun.java

@@ -1291,6 +1124,15 @@ public void save() throws IOException {
        synchronized (this) {
            PipelineIOUtils.writeByXStream(this, loc, XSTREAM2, isAtomic);
            SaveableListener.fireOnChange(this, file);
+            if (Boolean.TRUE.equals(completed)) {


@jglick No! 🐛 🐛 🐛 and a whole nest of 🐛s. This is not the right place to be terminating the AsynchronousExecution - if an IOException never occurs, the build never finishes.

You're welcome to do an extra on-save check somewhere logical -- because we have had hard-to-trace issues with the build not getting killed before, but this makes undead Pipelines more likely.

There is explanation elsewhere of why we have to do the termination here. I can think about whether it is possible to do so more forcefully, such as in a finally block.

if an IOException never occurs

I suppose you mean if an IOException does occur.

the build never finishes

As noted in a separate thread, even if no subsequent call to save is ever made, it is misleading to say that the build is “not finished”. Rather, there would be a stale AsynchronousExecution, which likely has little or no visible impact.

(see #27 (comment) for fuller discussion)

A stale AsynchronousExecution translates to essentially a "zombie" job that proves highly irritating to users -- it seems like it never completes even if the build is marked as done. Also it holds onto the OneShotExecutor indefinitely.

Again the AsynchronousExecution normally has no visible effect on anything—it only appears while we are actively running Groovy code, which of course we are not if the build is completed.

And again if some problem in existing code (whether in workflow-job or workflow-cps) results in a condition whereby <completed>true</completed> never gets written to build.xml, the AsynchronousExecution is the least of your concerns, since after the next restart onLoad will be confused. Possibly #93 will defend against that case—figure out that completed is wrong and save the correction—but at that point any old Executors are no longer an issue anyway (and there should be no new AfterRestartTask).

I think the after-restart case should have been fixed by #104.

Yeah, @jglick we have explicit handling for that onRestart case now (as Devin noted, #104 does the exactly cleanup you called out a need for).

src/main/java/org/jenkinsci/plugins/workflow/job/WorkflowRun.java

svanoort

I've done my best to give this at least a decent readthrough (though I don't imagine every bug has been caught). There are a couple bugs that need fixing but in general the implementation is pretty sane.

Or as sane as Pipeline internals are going to be anyway, given some of the Lovecraftian back-compatibility horrors they're dragging along with them... (ia ia FlowGraph f'htagn!) 🐙

svanoort

The handling of AsynchronousExecutions here is wrong and will probably break in the face of some fairly common cases (IOExceptions, etc). But that's not going to cause Critical/Blocker issues for users, just annoying ones. So, I'm removing my "changes requested" and this can go forward without my approval (I don't feel right "approving" something which I see actual bugs in).

The more critical risks here are the problems we can't anticipate, anyway.

…Also reduce scope of lock.

src/main/java/org/jenkinsci/plugins/workflow/job/console/NewNodeConsoleNote.java

svanoort

This still does not feel like the correct place to mark the AsynchronousExecution completed, but it seems to work as far as I can tell from cross-testing, whereas for reasons I'm still at a loss to explain, the correct place to mark it generates test flakes (primarily in CI) -- see #108 -- so I say we roll with this and release it -- with appropriate cautions that the log handling rewrite is a more-than-normal risk for people updating.

jglick · 2018-10-04T20:21:58Z

the correct place to mark it generates test flakes (primarily in CI)

Also unclear to me why. I note that the last build of this PR not only passed, but acc. to the log had no flakes. Anyway, this is something that could be sorted out later—there is no API or settings impact.

…ob-plugin#27.

[JENKINS-38381] Prototype of log handling rewrite.

c229421

jglick added the work-in-progress label Sep 23, 2016

jglick added 8 commits September 26, 2016 15:05

Pick up jenkinsci/maven-hpi-plugin#25.

754ab9e

Updated dependency versions.

e3ccb7b

Obsolete Javadoc comment.

721bc75

Reproduced AssociatedNodeNote error in a test.

30d64c7

Another snapshot version forgotten.

78c5fbf

Lighter-weight way of marking which node printed a line.

875b3ed

FindBugs

f2f1296

Updated TODOs.

141d748

oleg-nenashev reviewed Sep 28, 2016

View reviewed changes

This was referenced Sep 29, 2016

[JENKINS-38381] API to receive asynchronous notifications jenkinsci/durable-task-plugin#29

Closed

Make fewer assumptions about log handling jenkinsci/jenkins-test-harness#37

Merged

jglick added 2 commits September 30, 2016 17:08

Extracting createBuildListener.

19530bd

2.16 parent

4579f77

jglick mentioned this pull request Oct 4, 2016

[JEP-210] Integration tests with DurableTaskStep jenkinsci/workflow-durable-task-step-plugin#21

Merged

7 tasks

jglick added 5 commits October 5, 2016 18:25

Prototype SPI for replacing the log file of a build.

6f1ab49

Deleting comment implemented as jenkinsci/jenkins-test-harness#38.

e57d7c6

Faulty _getLogInputStream caused StackOverflowError’s in the normal c…

7db5d9d

…ase.

Pending jenkinsci/jenkins-test-harness#38 avoid printing a stack trac…

e4968ef

…e for getLogFile().

Reimplemented HTML display of Pipeline console to include some featur…

e6a58e8

…es from jenkinsci#21.

jglick mentioned this pull request Oct 10, 2016

[JENKINS-27394] Collapsible sections in log #21

Closed

jglick added 8 commits October 10, 2016 20:16

FindBugs

f46b98c

Hide the show/hide link except during hover.

62ccf49

Do not hide a “show” link.

51fdc25

[JENKINS-27394] Better implementation of collapsible sections, finall…

d34d03e

…y encompassing all of the functionality of jenkinsci#21.

Discovered a problem with NewNodeConsoleNote and LabelAction.

aa12940

Found a fix for the LabelAction timing problem.

08268a3

Fixed a bug in enclosing logic.

d2a39dd

Noting LessAbstractTaskListener.

89559d5

svanoort reviewed Sep 26, 2018

View reviewed changes

src/main/java/org/jenkinsci/plugins/workflow/job/WorkflowRun.java Show resolved Hide resolved

svanoort reviewed Sep 26, 2018

View reviewed changes

src/main/java/org/jenkinsci/plugins/workflow/job/WorkflowRun.java Show resolved Hide resolved

svanoort reviewed Sep 26, 2018

View reviewed changes

src/main/java/org/jenkinsci/plugins/workflow/job/WorkflowRun.java Show resolved Hide resolved

svanoort reviewed Sep 26, 2018

View reviewed changes

src/main/java/org/jenkinsci/plugins/workflow/job/WorkflowRun.java Show resolved Hide resolved

svanoort requested changes Sep 26, 2018

View reviewed changes

jglick requested a review from svanoort September 28, 2018 15:44

svanoort reviewed Sep 28, 2018

View reviewed changes

Call AsynchronousExecution.completed even if saving build.xml fails. …

9e07b63

…Also reduce scope of lock.

jglick requested a review from svanoort October 1, 2018 14:08

jglick mentioned this pull request Oct 3, 2018

[Testing Only] Start validating log rewrite jenkinsci/workflow-cps-plugin#251

Closed

jglick commented Oct 3, 2018

View reviewed changes

src/main/java/org/jenkinsci/plugins/workflow/job/console/NewNodeConsoleNote.java Show resolved Hide resolved

jglick added work-in-progress and removed work-in-progress labels Oct 3, 2018

svanoort mentioned this pull request Oct 4, 2018

[WIP] Log handling rewrite modifications #108

Closed

svanoort approved these changes Oct 4, 2018

View reviewed changes

compatibleSinceVersion=2.26

5623f82

jglick merged commit ced929d into jenkinsci:master Oct 4, 2018

jglick deleted the logs-JENKINS-38381 branch October 4, 2018 21:05

jglick added a commit to jglick/dump-live-pipeline-programs that referenced this pull request Aug 27, 2019

Adapting to jenkinsci/workflow-job-plugin#93 and jenkinsci/workflow-j…

50d0f3b

…ob-plugin#27.

dwnusbaum mentioned this pull request Feb 3, 2022

Fix issue with big logs, causing the browser to freeze (JENKINS-56377) #164

Closed

This was referenced May 23, 2023

Switch WorkflowRunRestartTest to JenkinsSessionRule #356

Merged

Improved WorkflowRun.finish timing #357

Merged

jglick mentioned this pull request Aug 16, 2023

Deleting old comment about closing listener #375

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[JEP-210] Log handling rewrite #27

[JEP-210] Log handling rewrite #27

jglick commented Sep 23, 2016 •

edited

Loading

oleg-nenashev left a comment

oleg-nenashev Sep 26, 2016

jglick Sep 30, 2016

oleg-nenashev Sep 28, 2016

jglick Sep 30, 2016

oleg-nenashev Sep 28, 2016

jglick Sep 30, 2016

oleg-nenashev Sep 28, 2016

jglick Sep 30, 2016

oleg-nenashev Sep 28, 2016

jglick Sep 30, 2016

svanoort Sep 26, 2018

jglick Sep 28, 2018

svanoort Oct 1, 2018 •

edited

Loading

jglick Oct 1, 2018

svanoort Sep 26, 2018

jglick Sep 28, 2018

jglick Sep 28, 2018

svanoort Sep 28, 2018

jglick Oct 1, 2018

svanoort Sep 26, 2018

jglick Sep 28, 2018

jglick Sep 28, 2018

jglick Sep 28, 2018

svanoort Sep 28, 2018

jglick Sep 28, 2018

dwnusbaum Sep 28, 2018

svanoort Sep 29, 2018

svanoort left a comment

svanoort left a comment

svanoort left a comment

jglick commented Oct 4, 2018

[JEP-210] Log handling rewrite #27

[JEP-210] Log handling rewrite #27

Conversation

jglick commented Sep 23, 2016 • edited Loading

oleg-nenashev left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

svanoort Oct 1, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

svanoort left a comment

Choose a reason for hiding this comment

svanoort left a comment

Choose a reason for hiding this comment

svanoort left a comment

Choose a reason for hiding this comment

jglick commented Oct 4, 2018

jglick commented Sep 23, 2016 •

edited

Loading

svanoort Oct 1, 2018 •

edited

Loading