[zorg] Parse Ninja output.

[Meinersbur]

Summary

Parses the output from Ninja to split logs for each launched command that emits some output.

If there is any command that failed (indicated by ninja using a FAILED: prefix), emits only the failed commands. Otherwise it builds logs for any output (usually warnings or CMake re-runs).

See it in action e.g. at http://meinersbur.de:8011/#/builders/142/builds/514

[Meinersbur]

zorg/buildbot/commands/NinjaCommand.py

49

If logObserver is set, addLogObserver will fail. It had to be called after super().__init__. That is, the logObserver parameter is currently not used so I removed it.

[Meinersbur]

@gkistanova ping

[gkistanova]

Sorry for the delay.

Thanks for proposing a fix for the logObserver, Michael. At a quick glance it looks good.

Since NinjaCommand could be used for builds, tests, and installations, people may want to register different log observers depending on the nature of the step. The fact that it hasn't been used yet suggests that maybe it will not happen soon, still it would be great to have the ability from the beginning. What do you think? The proposed observer with the parseErrorLogs parser could be the default one.

In the mean time I'll stage this patch for a few days. Let's see it in action.

[gkistanova]

Almost forgot to mention.

zorg/buildbot/commands/NinjaCommand.py

6

Did you mean LineConsumerLogObserver here?

[Meinersbur]

• Re-add logObserver
• Correct import

[Meinersbur]

• Make LineConsumerLogObserver just the default observer.

[Meinersbur]

In D101717#2749734, @gkistanova wrote:

Since NinjaCommand could be used for builds, tests, and installations, people may want to register different log observers depending on the nature of the step. The fact that it hasn't been used yet suggests that maybe it will not happen soon, still it would be great to have the ability from the beginning. What do you think? The proposed observer with the parseErrorLogs parser could be the default one.

The problem I see is that fixing something that is no checked for whether it is working will likely still not work, or whether it matches anyone's use case. E.g. someone might want to have both logObservers and the parseErrorLogs-derived ones. The logObserver argument could simply be re-added in that patch that needs it. As with LitTestCommand, CmakeCommand, AnnotatedCommand that don't even have logObservers arguments yet. Why does NinjaCommand need one, but not the others?

[gkistanova]

LitTestCommand parses LIT logs only and is not intended to parse anything else, AnnotatedCommand parses annotations only and is not intended to parse anything else. NinjaCommand could build (build logs), test (LIT logs), install (install logs).

Anyway, if you feel that strongly to defer this and consider it out of the scope of this patch, this is fine. I wouldn't make it a requirement.

[Meinersbur]

I don't feel strongly about it (I already updated the patch)

[Meinersbur]

ping

[Meinersbur]

Ping

[gkistanova]

I believe I commented this patch, but do not see my comments here. :(
Sorry for this.

This patch is staged.

You can see it in action in the build logs of these builders:

• https://lab.llvm.org/staging/#/builders/llvm-clang-x86_64-gcc-ubuntu
• https://lab.llvm.org/staging/#/builders/llvm-nvptx64-nvidia-win
• https://lab.llvm.org/staging/#/builders/llvm-clang-x86_64-gcc-ubuntu
• https://lab.llvm.org/staging/#/builders/publish-sphinx-docs
• https://lab.llvm.org/staging/#/builders/openmp-offload-cuda-project
• https://lab.llvm.org/staging/#/builders/openmp-offload-cuda-runtime
• https://lab.llvm.org/staging/#/builders/openmp-offload-amdgpu-runtime-experimental
• https://lab.llvm.org/staging/#/builders/clang-with-thin-lto-wpd-ubuntu

Please see if you are happy with the results.

The issues I see are:

1. Issues parsing.

https://lab.llvm.org/staging/#/builders/40/builds/6944 step test-stage1-compiler reported cd /b/clang-with-thin-lto-wpd-ubuntu/llvm-project/clang/bindings/python && /usr/bin/cmake -E env CLANG_LIBRARY_PATH=/b/clang-with-thin-lto-wpd-ubuntu/build/stage1/lib /usr/bin/python3.7 -m unittest discover with the content

[stdout] ...............................................................................................................................
[stdout] ----------------------------------------------------------------------
[stdout] Ran 127 tests in 0.347s
[stdout] 
[stdout] OK

What's wrong with those 5 lines? Doesn't seem contain any warning or error.

Also please see there Running all regression tests which contains pretty much the whole test run printout along with the summary.

2. Title wording.

There is mentioned above title cd /b/clang-with-thin-lto-wpd-ubuntu/llvm-project/clang/bindings/python && /usr/bin/cmake -E env CLANG_LIBRARY_PATH=/b/clang-with-thin-lto-wpd-ubuntu/build/stage1/lib /usr/bin/python3.7 -m unittest discover. It does not look informative.

Another example is in https://lab.llvm.org/staging/#/builders/200/builds/20070, which has a compile error. The title for this error looks like FAIL: Building CXX object unittests/Analysis/CMakeFiles/InlineAdvisorPlugin.dir/InlineAdvisorPlugin.cpp.o. Compiler reports it better - FAILED: unittests/Analysis/CMakeFiles/InlineAdvisorPlugin.dir/InlineAdvisorPlugin.cpp.o. Is it possible to use the compiler output for the title?

It might be trickier for warnings. But still WARNING: /home/buildbot-worker/minipc-1050ti-linux/rundir/llvm.src/llvm/lib/IR/Core.cpp might look better than Building CXX object lib/IR/CMakeFiles/LLVMCore.dir/Core.cpp.o (https://lab.llvm.org/staging/#/builders/200/builds/20068)?

And maybe if an error or a warning message is short and easy to parse, add it to the title? For example in https://lab.llvm.org/staging/#/builders/85/builds/8773 a warning looks like /home/buildbot/as-worker-4/publish-sphinx-docs/llvm-project/libc/docs/source_tree_layout.rst:62: WARNING: Title underline too short.; having a title similar to WARNING: /home/buildbot/as-worker-4/publish-sphinx-docs/llvm-project/libc/docs/source_tree_layout.rst:62: Title underline too short. would be great. This is fine not to do this, though. It could be a subject of a different patch.

zorg/buildbot/commands/NinjaCommand.py

 # TODO: Use Interpolate instead of WithProperties.
 import re
 
 from buildbot.process.properties import WithProperties
 from buildbot.steps.shell import WarningCountingShellCommand
+from buildbot.process.logobserver import LineConsumerLogObserver
 
 class NinjaCommand(WarningCountingShellCommand):
     DEFAULT_NINJA = 'ninja'
 
     @staticmethod
     def sanitize_kwargs(kwargs):
         # kwargs we could get and must not pass through
         # to the buildstep.RemoteShellCommand constructor.
class NinjaCommand(WarningCountingShellCommand):
     description = ["building"]
     descriptionDone = ["build"]
     renderables = (
         'options',
         'targets',
         'ninja',
     )
 
-    def __init__(self, options=None, targets=None, ninja=DEFAULT_NINJA, logObserver=None, **kwargs):
+    def __init__(self, options=None, targets=None, ninja=DEFAULT_NINJA, logObserver=None, maxLogs=20, **kwargs):
         self.ninja = ninja
         self.targets = targets
+        self.maxLogs = maxLogs
 
         if options is None:
             self.options = list()
         else:
             self.options = list(options)
 
-        if logObserver:
-            self.logObserver = logObserver
-            self.addLogObserver('stdio', self.logObserver)
-
         j_opt = re.compile(r'^-j$|^-j\d+$')
         l_opt = re.compile(r'^-l$|^-l\d+(\.(\d+)?)?$')
 
         command = list()
         command += [self.ninja]
 
         # We can get jobs in the options. If so, we would use that.
         if not any(j_opt.search(opt) for opt in self.options if isinstance(opt, str)):
def __init__(self, options=None, targets=None, ninja=DEFAULT_NINJA, logObserver=None, maxLogs=20, **kwargs):
         # still didn't get yet WithProperties rendered.
         sanitized_kwargs = self.sanitize_kwargs(kwargs)
 
         sanitized_kwargs["command"] = command
 
         # And upcall to let the base class do its work
         super().__init__(**sanitized_kwargs)
 
+        self.addLogObserver('stdio', LineConsumerLogObserver(self.parseErrorLogs))
+        if logObserver:
+            self.logObserver = logObserver
+            self.addLogObserver('stdio', self.logObserver)
+
+
+    # FIXME: The regex depends on NINJA_STATUS to be "%e [%u/%r/%f] " which is only a default set by setupEnvironment.
+    kTitleLineRE = re.compile(r'(?P<secs>[0-9]+\.[0-9]+) \[(?P<remaining>[0-9]+)\/(?P<active>[0-9]+)\/(?P<completed>[0-9]+)\] (?P<desc>.+)')
+    kFailedLineRE = re.compile(r'FAILED: (?P<cmdline>.+)')
+
+    def parseErrorLogs(self):
+        last_title = None
+        last_error = None
+        last_lines = []
+        numLogs = 0
+        normalLogs = []
+
+
+        def endOfLog():
+            nonlocal last_title,last_error,last_lines,numLogs,normalLogs
+            if last_title is not None:
+                if last_error is not None:
+                    if numLogs < self.maxLogs:
+                        self.addCompleteLog('FAIL: ' + last_title, '\n'.join(last_lines))
+                        numLogs += 1
+                elif last_lines:
+                    normalLogs.append((last_title, '\n'.join(last_lines)))
+            last_title = None
+            last_error = None
+            last_lines = []
+
+        try:
+          stream, line = yield
+          while True:
+            title = self.kTitleLineRE.fullmatch(line)
+            if title and stream=='o':
+                endOfLog()
+                secs = float(title.group('secs'))
+                remaining = int(title.group('remaining'))
+                active = int(title.group('active'))
+                completed = int(title.group('completed'))
+                desc = title.group('desc')
+
+                last_title = desc
+                self.setProgress('edges', completed)
+                stream, line = yield
+
+                failheader = self.kFailedLineRE.fullmatch(line)
+                if failheader and stream=='o':
+                    cmdline = failheader.group('cmdline')
+                    last_error = cmdline
+                    last_lines.append(line)
+                    stream, line = yield
+                continue
+
+            if stream != 'h':
+                prefix = ''
+                if stream == 'o':
+                    prefix = '[stdout] '
+                elif stream == 'e':
+                    prefix = '[stderr] '
+                last_lines.append(prefix + line)
+            stream, line = yield
+        except GeneratorExit:
+            endOfLog()
+            if numLogs == 0: # Only emit normal logs if no failures found
+                for title,content in normalLogs[:self.maxLogs]:
+                     self.addCompleteLog(title, content)
+
+
     def setupEnvironment(self, cmd):
         # First upcall to get everything prepared.
         super().setupEnvironment(cmd)
 
         # Set default status format string.
         if cmd.args['env'] is None:
             cmd.args['env'] = {}
         cmd.args['env']['NINJA_STATUS'] = cmd.args['env'].get('NINJA_STATUS', "%e [%u/%r/%f] ")
 
     def buildCommandKwargs(self, warnings):
         kwargs = super().buildCommandKwargs(warnings)
         # Remove all the empty items from the command list,
         # which we could get if Interpolate rendered to empty strings.
         kwargs['command'] = [cmd for cmd in kwargs['command'] if cmd]
         return kwargs