Discussion on per-package logging

One first issue with top-level parallel build is simple: the build output of several packages is mixed up, making the overall build output mostly unreadable.

Therefore, an idea is to log the build output in log
files per package, and only keep the ">>> foo 1.0 Building" messages on the standard output. It turns out this is not as easy as it sounds, and it seems like there is no good solution for that.

For the record (since I'm sure this must have been discussed before), why isn't
the --output-sync option sufficient? Output from parallel make is expected to be garbled in any parallel build. When a user calls 'make -j', we can expect them to also provide --output-sync=recurse option.

I am currently trying to revive a former effort from Gustavo to implement top-level parallel build (i.e the ability to build several packages in parallel).

One first issue with top-level parallel build is simple: the build output of several packages is mixed up, making the overall build output mostly unreadable.

Therefore, an idea is to log the build output in log
files per package, and only keep the ">>> foo 1.0 Building" messages on the standard output. It turns out this is not as easy as it sounds, and it seems like there is no good solution for that.

I will document below the two approaches that have been tried. Many thanks to Gustavo for the initial work on the "shell wrapper" approach, and thanks to Yann for the very useful discussion on IRC.

Shell wrapper approach
======================

This is the original approach taken by Gustavo, which can be seen at
http://repo.or.cz/buildroot-gz.git/commitdiff/833e8fa7c7437931f1356b5b03a6b3810a3db586.

Basically, the idea is to override the SHELL variable and make it point to a wrapper script instead of pointing to bash directly. This wrapper script then re-executes the command under bash, but also redirects the output to a logfile. The core of the script is:

  exec ${BASH} "$@ > >(tee -a ${BR2_PACKAGE_LOGFILE}) 2> >(tee -a ${BR2_PACKAGE_LOGFILE} >&2)"

Note that we cannot just redirect the output, we need to use "tee" to keep the output both in the log file and on stdout, because if you capture stdout, all the make commands such as:

HOSTCC_VERSION := $(shell $(HOSTCC_NOCCACHE) --version | \
        sed -n -r 's/^.* ([0-9]*)\.([0-9]*)\.([0-9]*)[ ]*.*/\1 \2/p')

no longer have their output, and therefore HOSTCC_VERSION is empty.

But that's fine: we can use "tee" here, and then at a higher level redirect stdout to /dev/null, except the ">>>" messages. I did this inside the top-level make invocation that we already have calling ourselves as a sub-make to solve the umask and canonical directory issues.

However, where this solution falls apart is because make does *not* guarantee that all commands are executed through a sub-shell. As the make documentation says:

When it is time to execute recipes to update a target, they are executed by invoking a new sub-shell for each line of the recipe, unless the '.ONESHELL' special target is in effect (*note Using One Shell: One Shell.) (In practice, 'make' may take shortcuts that do not affect the results.)

And Yann has indeed been able to easily create make targets that do not invoke a sub-shell to run a command. The output of such commands would not be captured. I had a brief look at make's source code to see what is the criteria, and my understanding is that make doesn't use a sub-shell, unless there are some specific keywords (such as while, for, etc.) in the command or specific characters (such as ; etc.).

Therefore this solution is not 100% correct. From my quick testing, it does capture all the output, but it is not 100% guaranteed. The question is: is it a big problem? It some sense it is, because it means that the per-package log files are not complete. But on the other hand it doesn't make the build incorrect.

Perhaps we could keep this approach, but make it optional?

Explicit redirect approach
==========================

The other approach I've investigated is adding explicit redirects to a log file in the package infrastructure itself. I.e, something like:

$(BUILD_DIR)/%/.stamp_built::

        @$(call step_start,build)
        @$(call MESSAGE,"Building")

(quoted diff) +3 -3

-       $(foreach hook,$($(PKG)_PRE_BUILD_HOOKS),$(call $(hook))$(sep))
-       +$($(PKG)_BUILD_CMDS)
-       $(foreach hook,$($(PKG)_POST_BUILD_HOOKS),$(call $(hook))$(sep))
+       @$(foreach hook,$($(PKG)_PRE_BUILD_HOOKS),$(call $(hook)) >> $(LOGFILE) 2>&1 $(sep))
+       $(Q)+$($(PKG)_BUILD_CMDS) >> $(LOGFILE) 2>&1
+       @$(foreach hook,$($(PKG)_POST_BUILD_HOOKS),$(call $(hook)) >> $(LOGFILE) 2>&1 $(sep))
        @$(call step_end,build)
        $(Q)touch $@

The problem with this is that if the variable <pkg>_BUILD_CMDS contains multiple commands (which is very often the case), then only the output of the last command is redirected. Indeed if you have:

define FOO_BUILD_CMDS

	$(MAKE) foo
	$(MAKE) bar

endef

Then what gets executed is:

	$(MAKE) foo
	$(MAKE) bar >> $(LOGFILE)

Obviously, we cannot patch all the package .mk files one by one to add a >> $(LOGFILE) to each and every command. It would make the package .mk files horrible to read and write.

One option would be to use the .ONESHELL make statements, that asks make to run all commands in a target under a single shell invocation. Unfortunately, this will break a lot of things in our packages. For example, something like:

define FOO_BUILD_CMDS

	cd $(@D)/bar; $(MAKE) blabla
	$(MAKE) foo

endef

Will no longer work, because the second command $(MAKE) foo will be executed from $(@D)/bar, which is not currently the case since each command runs in a separate sub-shell. This would require changing a lot of packages, and it would be somewhat "unconventional" to have commands that depend on each other.

Conclusion
==========

None of the two approaches are completely convincing. The second approach looks totally unworkable to me. The first approach could be acceptable if we see that in practice, most commands are executed in a sub-shell.

Suggestions? Comments? Alternative proposals?

Best regards,

Thomas

Signature · 3 lines

Thomas Petazzoni, CTO, Free Electrons
Embedded Linux and Kernel engineering
http://free-electrons.com

In my opinion, we can't do and should not do anything about it.

Either the user wants a fast build, and then it is acceptable that the output gets mangled, or he is trying to debug the build and thus is not doing parallel build to start with.

Quoted 5 lines

In my opinion, we can't do and should not do anything about it.

Either the user wants a fast build, and then it is acceptable that the output gets mangled, or he is trying to debug the build and thus is not doing parallel build to start with.

I disagree with you, because there will obviously be cases where we want to debug a parallel build. A parallel build might uncover some specific issues, and we will want to have a look at the build log of a given package to understand what happened.

So I disagree on your assumption that either you're debugging or you're building in parallel.

Best regards,

Thomas Petazzoni

Signature · 3 lines

Thomas Petazzoni, CTO, Free Electrons
Embedded Linux and Kernel engineering
http://free-electrons.com

This includes a new support script that helps parsing *_CMDS recipes, ensuring everything is forwarded.

See also: http://repo.or.cz/buildroot-gz.git/commitdiff/833e8fa7c7437931f1356b5b03a6b3810a3db586
Latest discussion: http://lists.busybox.net/pipermail/buildroot/2017-October/204159.html

Signed-off-by Anisse Astier <[email protected]>

---

This is a proof of concept and does not log everything yet, but should work.

support/scripts/recipe-forward-log new file +49 -0

new file mode 100755
index 0000000..8240d74
@@ -0,0 +1,59 @@
+#!/usr/bin/env python3
+
+import sys
+import subprocess
+
+
+DEBUG = False
+
+if len(sys.argv) < 2:
+    print("usage: %s <log-file> <make-recipe>" % (sys.argv[0]))
+    sys.exit(-1)
+
+
+def dprint(*pargs):
+    if DEBUG:
+        print(*pargs)
+
+log_file = sys.argv[1]
+
+args = sys.argv[2:]
+
+dprint("args: %s" % (args))
+if len(args) == 1 and len(args[0]) == 0:
+    sys.exit(0)  # only one empty argument, supported use case
+
+for arg in args:
+    for line in arg.splitlines():
+        dprint("line: %s" % (line))
+        if line[0] != '\t':
+            print("Recipe line does not start with tab, aborting: %s" % (line))
+            sys.exit(-1)
+        line = line[1:]  # remove initial tab
+        if len(line) == 0:
+            continue  # empty lines are tolerated
+        print_command = True
+        stop_on_err = True
+        while True:
+            if line[0] == '@':
+                dprint("silent mode")
+                print_command = False
+                line = line[1:]
+            elif line[0] == '-':
+                dprint("ignore err mode")
+                stop_on_err = False
+                line = line[1:]
+            elif line[0] == '+':  # ignore
+                dprint("jobserver MAKEFLAGS mode")
+                line = line[1:]
+            else:  # no more matching initial recipe character

Hello,

Thanks for participating into the discussion and trying to prototype other solutions! I'm happy to make the connection between your nickname on IRC, and the real person: we have met several times at Kernel Recipes! :-)

package/pkg-generic.mk $(BUILD_DIR)/%/.stamp_actual_downloaded: · line 171

Quoted 2 lines · Anisse Astier

package/pkg-generic.mk +1 -1

-	$(foreach hook,$($(PKG)_PRE_EXTRACT_HOOKS),$(call $(hook))$(sep))
+	$(foreach hook,$($(PKG)_PRE_EXTRACT_HOOKS),$(call $(hook)) >> $($(PKG)_LOGFILE) 2>&1 $(sep))

Are you sure this is working for multi-line hooks ? I think hooks suffer from the same problem as commands.

package/pkg-generic.mk $(BUILD_DIR)/%/.stamp_actual_downloaded: · line 173

Quoted 4 lines

package/pkg-generic.mk +1 -1

 	$(Q)mkdir -p $(@D)
-	$($(PKG)_EXTRACT_CMDS)
+	@$(call exportvar,$(PKG)_EXTRACT_CMDS)

Why do variables need to be exported? Isn't their value passed as argument to the recipe-forward-log script ?

Quoted 61 lines

support/scripts/recipe-forward-log new file +55 -0

new file mode 100755
index 0000000..8240d74
@@ -0,0 +1,59 @@
+#!/usr/bin/env python3
+
+import sys
+import subprocess
+
+
+DEBUG = False
+
+if len(sys.argv) < 2:
+    print("usage: %s <log-file> <make-recipe>" % (sys.argv[0]))
+    sys.exit(-1)
+
+
+def dprint(*pargs):
+    if DEBUG:
+        print(*pargs)
+
+log_file = sys.argv[1]
+
+args = sys.argv[2:]
+
+dprint("args: %s" % (args))
+if len(args) == 1 and len(args[0]) == 0:
+    sys.exit(0)  # only one empty argument, supported use case
+
+for arg in args:
+    for line in arg.splitlines():
+        dprint("line: %s" % (line))
+        if line[0] != '\t':
+            print("Recipe line does not start with tab, aborting: %s" % (line))
+            sys.exit(-1)
+        line = line[1:]  # remove initial tab
+        if len(line) == 0:
+            continue  # empty lines are tolerated
+        print_command = True
+        stop_on_err = True
+        while True:
+            if line[0] == '@':
+                dprint("silent mode")
+                print_command = False
+                line = line[1:]
+            elif line[0] == '-':
+                dprint("ignore err mode")
+                stop_on_err = False
+                line = line[1:]
+            elif line[0] == '+':  # ignore
+                dprint("jobserver MAKEFLAGS mode")
+                line = line[1:]
+            else:  # no more matching initial recipe character
+                break
+        if print_command:
+            print(line)
+        proc = subprocess.Popen(line, shell=True, stdout=subprocess.PIPE,
+                                stderr=subprocess.STDOUT)
+        tee = subprocess.call(["tee", "-a", log_file], stdin=proc.stdout,

support/scripts/recipe-forward-log line 59

Quoted 4 lines

support/scripts/recipe-forward-log new file +4 -0

+                              stdout=sys.stdout)
+        ret = proc.wait()
+        if ret != 0 and stop_on_err:
+            sys.exit(ret)

How many packages have you tested with this? I'm just a little bit concerned with this parsing, and how it could break with arbitrary (but valid) make commands.

But besides that, I have to say your approach overall looks interesting, and probably less hackish than the global shell wrapper approach.

Quoted 2 lines

Are you sure this is working for multi-line hooks ? I think hooks suffer from the same problem as commands.

No, it's not working for multi-line hooks, I forgot about it. But we could use the helper for this as well.

Quoted 2 lines

Why do variables need to be exported? Isn't their value passed as argument to the recipe-forward-log script ?

When simply using the multi-line make variable, it gets replaced in the recipe, and the shell command only receives the first line, even if we enclose the variable in double quotes. Exporting it to the environment made it possible to go through the make -> shell barrier.

Then I had to use the eval trick because otherwise the nested/computed $(PKG)_EXTRACT_CMDS variable would only be interpreted once, at initial parsing and not for each packages.

Quoted 3 lines

How many packages have you tested with this? I'm just a little bit concerned with this parsing, and how it could break with arbitrary (but valid) make commands.

Not many. I have only tested the qemu_aarch64_virt_defconfig which does not contain much(~28 packages), but I was already able to fix a few parsing issues.

Hello,

Quoted 5 lines · Anisse Astier

Quoted 2 lines

Are you sure this is working for multi-line hooks ? I think hooks suffer from the same problem as commands.

No, it's not working for multi-line hooks, I forgot about it. But we could use the helper for this as well.

Sure, OK.

Quoted 7 lines

Quoted 2 lines

Why do variables need to be exported? Isn't their value passed as argument to the recipe-forward-log script ?

When simply using the multi-line make variable, it gets replaced in the recipe, and the shell command only receives the first line, even if we enclose the variable in double quotes. Exporting it to the environment made it possible to go through the make -> shell barrier.

But then there is no point in passing the commands as argument on the wrapper command line, no? It could just use the variable from the environment, no?

Does something like:

	COMMANDS="$($(PKG)_BUILD_CMDS)" ./support/script/your-wrapper

works ?

Quoted 3 lines

Then I had to use the eval trick because otherwise the nested/computed $(PKG)_EXTRACT_CMDS variable would only be interpreted once, at initial parsing and not for each packages.

Adding Arnout in Cc on this topic, because he understands all this make/shell sorcery :)

Quoted 3 lines

Quoted 3 lines

How many packages have you tested with this? I'm just a little bit concerned with this parsing, and how it could break with arbitrary (but valid) make commands.

Quoted 4 lines

Not many. I have only tested the qemu_aarch64_virt_defconfig which does not contain much(~28 packages), but I was already able to fix a few parsing issues.

A bigger test is indeed needed to validate things. But let's see what others have to say first.

So first of all I would like to see an explanation why --output-sync=recurse is
not sufficient.

Hello,

Quoted 2 lines · Arnout Vandecappelle

So first of all I would like to see an explanation why --output-sync=recurse is
not sufficient.

I did some quick testing with -Orecurse, and it looks pretty good to me. The only downside that I've seen so far is that the entire log of a given make target is shown when the target is finished, which in the current organization of things means even the ">>> foo 1.0 building" message is shown once the build of "foo" is completed.

Therefore, you end up in a situation where a lot of things have been displayed, and then nothing happens (because foo is being built). So you're wondering "what the heck is going on in here". And once "foo" has finished building, everything is displayed, and you understand what was going on. Perhaps this can be solved by having the message displayed as part of a separate target. Or perhaps we don't need to solve this problem at all?

Another thing is that I'd ideally want this to be done automatically by Buildroot, which is something we can do as part of the "make-calls-itself" in the main Makefile. Except that at this point, we don't have the Buildroot configuration available, and I wanted to make this conditional on some BR2_PARALLEL_BUILD=y option. Or we make -Orecurse the default, but that is going to significantly change the visible behavior even for people not using top-level parallel build.

Quoted 7 lines

Therefore, you end up in a situation where a lot of things have been displayed, and then nothing happens (because foo is being built). So you're wondering "what the heck is going on in here". And once "foo" has finished building, everything is displayed, and you understand what was going on. Perhaps this can be solved by having the message displayed as part of a separate target. Or perhaps we don't need to solve this problem at all?

I think we do need to do something about it, but it could be as simple as
letting MESSAGE print to /dev/tty instead of stdout.

Quoted 8 lines

Another thing is that I'd ideally want this to be done automatically by Buildroot, which is something we can do as part of the "make-calls-itself" in the main Makefile. Except that at this point, we don't have the Buildroot configuration available, and I wanted to make this conditional on some BR2_PARALLEL_BUILD=y option. Or we make -Orecurse the default, but that is going to significantly change the visible behavior even for people not using top-level parallel build.

Ah, you would make top-level parallel build a config option?

Isn't it enough to observe the -j in MAKEFLAGS?

I'm not convinced we want to add this option automatically, however, because it
makes it more difficult for people who don't want it. Why not add it to utils/brmake, for example, and point people there in the documentation of top-level parallel build?

Hello,

On Tue, 17 Oct 2017 16:44:04 +0200, Arnout Vandecappelle wrote:

Quoted 1 line

Isn't it enough to observe the -j in MAKEFLAGS?

Interestingly:

all:

	@echo $(MAKEFLAGS)

ifneq ($(filter -j%,$(MAKEFLAGS)),)
@echo "BINGO"
endif

Never shows BINGO when called with "make -j2" even if the echo $(MAKEFLAGS) does show that -j2 has been passed. Also a:

$(warning $(MAKEFLAGS))

shows an empty value.

Quoted 5 lines

I'm not convinced we want to add this option automatically, however, because it
makes it more difficult for people who don't want it. Why not add it to utils/brmake, for example, and point people there in the documentation of top-level parallel build?

Sorry I lost you here :/

I mean that maybe the user doesn't want to gather the output with -Orecurse or
-Otarget but really wants -Onone. If you hardcode -Orecurse in the Makefile, it's impossible for a user who does want to see output immediately.

Hello,

Quoted 3 lines · Arnout Vandecappelle

I mean that maybe the user doesn't want to gather the output with -Orecurse or
-Otarget but really wants -Onone. If you hardcode -Orecurse in the Makefile, it's impossible for a user who does want to see output immediately.

Yes, hence my idea of BR2_PARALLEL_BUILD to preserve the existing behavior when it is disabled. However, the .config is not included in the top-level make invocation, only in the sub-make.

So, here is my plan:

* Introduce BR2_PARALLEL_BUILD

* Make the sub-make invocation mandatory. Right now it's only if the umask is not correct or if O is not a canonical path. Let's just always recurse into a sub-make, it costs essentially nothing.

* Do a grep ^BR2_PARALLEL_BUILD=y in the config file in the top-level make to decide whether we pass -Orecurse to the sub-make invocation. If .config doesn't exist, then we don't pass -Orecurse because it means we're about to configure Buildroot and we anyway don't care about -Orecurse.

Thoughts?

I'm not sure how to handle the MESSAGE macro. One suggestion you made was to output directly to the tty. But a big drawback of that is that if you redirect the build output (make 2>&1 | tee logfile) then the messages displayed by the MESSAGE macro will no longer be stored in the logfile, which is super annoying: I always use them to navigate in the logfile to the appropriate place. So I believe directly writing to the tty in the MESSAGE macro is not a good option.

Quoted 7 lines

I'm not sure how to handle the MESSAGE macro. One suggestion you made was to output directly to the tty. But a big drawback of that is that if you redirect the build output (make 2>&1 | tee logfile) then the messages displayed by the MESSAGE macro will no longer be stored in the logfile, which is super annoying: I always use them to navigate in the logfile to the appropriate place. So I believe directly writing to the tty in the MESSAGE macro is not a good option.

I think Arnout meant that the MESSAGE macro could write to both the tty (if available) and stdout, hence getting the best of both worlds.

Hello,

Quoted 8 lines · Anisse Astier

Quoted 7 lines

I'm not sure how to handle the MESSAGE macro. One suggestion you made was to output directly to the tty. But a big drawback of that is that if you redirect the build output (make 2>&1 | tee logfile) then the messages displayed by the MESSAGE macro will no longer be stored in the logfile, which is super annoying: I always use them to navigate in the logfile to the appropriate place. So I believe directly writing to the tty in the MESSAGE macro is not a good option.

Quoted 2 lines

I think Arnout meant that the MESSAGE macro could write to both the tty (if available) and stdout, hence getting the best of both worlds.

Well, in this case, you'd get the message twice on your terminal if you run "make 2>&1 | tee logfile". Only one of the two will be saved in the log file, but both of them will be visible on your tty.

Quoted 3 lines

Well, in this case, you'd get the message twice on your terminal if you run "make 2>&1 | tee logfile". Only one of the two will be saved in the log file, but both of them will be visible on your tty.

It should be possible to detect if stdout is a tty or a pipe, and not print on the tty when it's already one.

Hello,

On Wed, 18 Oct 2017 10:09:11 +0200, Anisse Astier wrote:

Quoted 6 lines

Quoted 3 lines

Well, in this case, you'd get the message twice on your terminal if you run "make 2>&1 | tee logfile". Only one of the two will be saved in the log file, but both of them will be visible on your tty.

It should be possible to detect if stdout is a tty or a pipe, and not print on the tty when it's already one.

And when it's both, with "tee" ? :-)

But as I said, there should be a top logfile by default, removing the need for tee.

Hello,

Quoted 2 lines · Anisse Astier

But as I said, there should be a top logfile by default, removing the need for tee.

I'm not sure how this solves the problem. Indeed, even if we have a logfile by default, it will be done using "| tee" so that stdout has all the messages, and the logfile as well.

But I am not sure we want to log everything by default. I find it somewhat neat that Buildroot doesn't enforce a logging strategy. Some users prefer to redirect everything, some users prefer a "| tee" thing. Some users prefer the log to be appended after the existing log, some users prefer to truncate and replace the existing log.

So, if we're going the -Orecurse route, I'd prefer to not change our logging strategy, i.e not log anything by default, and leave it up to the user.

I agree here. Leave as much as possible to the user. It is for this very reason
that I'd prefer the -Orecurse to be specified by the user and not enforced in our Makefile. Users who always want this behaviour can make an alias, or export MAKEFLAGS="-Orecurse -j5", or use brmake.

Regardless, I consider the logging one of the least priority things in the
whole top-level parallel build thing.

Hello,

Quoted 3 lines · Arnout Vandecappelle

I mean that maybe the user doesn't want to gather the output with -Orecurse or
-Otarget but really wants -Onone. If you hardcode -Orecurse in the Makefile, it's impossible for a user who does want to see output immediately.

Yes, hence my idea of BR2_PARALLEL_BUILD to preserve the existing behavior when it is disabled. However, the .config is not included in the top-level make invocation, only in the sub-make.

So, here is my plan:

* Introduce BR2_PARALLEL_BUILD

* Make the sub-make invocation mandatory. Right now it's only if the umask is not correct or if O is not a canonical path. Let's just always recurse into a sub-make, it costs essentially nothing.

* Do a grep ^BR2_PARALLEL_BUILD=y in the config file in the top-level make to decide whether we pass -Orecurse to the sub-make invocation. If .config doesn't exist, then we don't pass -Orecurse because it means we're about to configure Buildroot and we anyway don't care about -Orecurse.

Thoughts?

As I said a couple of times already, I don't think we should enforce -Orecurse.

About the BR2_PARALLEL_BUILD option, it may be useful, but for the time being I
would continue asking the user to remove the .NOTPARALLEL line.

Quoted 1 line

As I said a couple of times already, I don't think we should enforce -Orecurse.

As I replied in another e-mail, I disagree :)

Quoted 2 lines

About the BR2_PARALLEL_BUILD option, it may be useful, but for the time being I
would continue asking the user to remove the .NOTPARALLEL line.

Quoted 28 lines · Thomas Petazzoni

Hello,

Quoted 5 lines · Anisse Astier

Quoted 2 lines

Are you sure this is working for multi-line hooks ? I think hooks suffer from the same problem as commands.

No, it's not working for multi-line hooks, I forgot about it. But we could use the helper for this as well.

Sure, OK.

Quoted 7 lines

Quoted 2 lines

Why do variables need to be exported? Isn't their value passed as argument to the recipe-forward-log script ?

When simply using the multi-line make variable, it gets replaced in the recipe, and the shell command only receives the first line, even if we enclose the variable in double quotes. Exporting it to the environment made it possible to go through the make -> shell barrier.

But then there is no point in passing the commands as argument on the wrapper command line, no? It could just use the variable from the environment, no?

Does something like:

	COMMANDS="$($(PKG)_BUILD_CMDS)" ./support/script/your-wrapper

Quoted 1 line

works ?

No it won't:
- any quotation marks will be eaten by the shell;
- non-escaped newlines will still cause the shell to be called twice.

The environment hack is really the way to go. Note that the "export" in
evalexport is a make command, not a shell command!

We could instead export these variable globally from within the generic-package
infra, since the variable names anyway have to be unique. It just means that you'll have quite a huge environment on each process invocation, which might be problem for other reasons (e.g. performance).

Another approach would be to call printvars from within the wrapper script, but
also that has terrible performance implications.

Quoted 6 lines

Quoted 3 lines

Then I had to use the eval trick because otherwise the nested/computed $(PKG)_EXTRACT_CMDS variable would only be interpreted once, at initial parsing and not for each packages.

Adding Arnout in Cc on this topic, because he understands all this make/shell sorcery :)

Heh, at first glance I thought you misspelled sourcery ;-)

eval is indeed needed, otherwise the export is a shell command, not a make
command. I don't think making it a macro is very useful however, so instead of $(call exportvar,...) I'd do $(eval export $(PKG)_EXTRACT_CMDS).

Quoted 3 lines

Quoted 3 lines

Quoted 3 lines

How many packages have you tested with this? I'm just a little bit concerned with this parsing, and how it could break with arbitrary (but valid) make commands.

I don't see any way that it could break things, actually. But obviously it
*does* need to be tested more extensively.

Quoted 8 lines

Quoted 5 lines

Not many. I have only tested the qemu_aarch64_virt_defconfig which does not contain much(~28 packages), but I was already able to fix a few parsing issues.

A bigger test is indeed needed to validate things. But let's see what others have to say first.

Indeed, because I'm not in favour...

- IMO 'make --output-sync=recurse' is sufficient to begin with.

- This script requires python3 for *any* build, but python3 is not currently a dependency.

- If the script is changed so it supports both 2 and 3, it still requires a python invocation for every build step, which is slowing things down.

- Even if it is converted to a shell script or sped up in a different way, it will make things more complicated for IMO limited gain.

So first of all I would like to see an explanation why --output-sync=recurse is
not sufficient.

If we *really* do want per-package log files, and we are willing to change the
.stamp_ commands like you do here, then there is in fact an alternative that may simplify things. We can do

$(subst $(sep),something$(sep)something,$($(PKG)_FOO_CMDS)

to replace all newlines with a redirection command. It's still not trivial:

$(subst $(sep),$(sep) > logfile 2>&1,$($(PKG)_FOO_CMDS) > logfile 2>&1

would be the obvious thing, but the problem is that the commands may already contain some redirection and we'd end up with double redirection. But you can see the pattern here :-)

Note BTW that there is one $(sep) less than the actual number of lines, so you
always need to add an additional preamble and postamble. So clearly we'll want a macro to do that:

redirect = preamble $(subst $(sep),preamble $(sep) postamble,$(1)) postamble
...

	$(call redirect,$($(PKG)_FOO_CMDS))

Quoted 3 lines · Arnout Vandecappelle

On 17-10-17 09:11, Thomas Petazzoni wrote:

Quoted 2 lines

I don't see any way that it could break things, actually. But obviously it
*does* need to be tested more extensively.

Indeed it does. I found another issue in the parsing, it turns out there might be many tabs at the beginning of a recipe, so they must be consumed greedily as well:

(quoted diff) +0 -0

             else:  # no more matching initial recipe character
                 break
         if print_command:

Quoted 7 lines

Quoted 7 lines

Quoted 6 lines

Not many. I have only tested the qemu_aarch64_virt_defconfig which does not contain much(~28 packages), but I was already able to fix a few parsing issues.

Quoted 6 lines

Quoted 2 lines

A bigger test is indeed needed to validate things. But let's see what others have to say first.

Indeed, because I'm not in favour...

- IMO 'make --output-sync=recurse' is sufficient to begin with.

Quoted 4 lines

- This script requires python3 for *any* build, but python3 is not currently a dependency.

Quoted 5 lines

- If the script is changed so it supports both 2 and 3, it still requires a python invocation for every build step, which is slowing things down.

- Even if it is converted to a shell script or sped up in a different way, it will make things more complicated for IMO limited gain.

I'm not sure it can be converted to pure shell because of the lexing issues (nested double quotes, etc.).

But this can still be optimized as well. Either by using a native program, by having a long running process that would receive commands through a pipe, or even by using a GNU make loadable module.

A GNU make loadable module, I never heard of that. Is that really an option?
That could really be useful, also for other things.

Quoted 4 lines · Anisse Astier

Quoted 3 lines · Arnout Vandecappelle

On 17-10-17 09:11, Thomas Petazzoni wrote:

[snip]

Quoted 7 lines

Quoted 2 lines

I don't see any way that it could break things, actually. But obviously it
*does* need to be tested more extensively.

Indeed it does. I found another issue in the parsing, it turns out there might be many tabs at the beginning of a recipe, so they must be consumed greedily as well:

Review for arg in args: · line 51

Quoted 7 lines

(quoted diff) +3 -0

@@ -46,6 +46,9 @@ for arg in args:
             elif line[0] == '+':  # ignore
                 dprint("jobserver MAKEFLAGS mode")
                 line = line[1:]
+            elif line[0] == '\t':  # eat additionnal tabs
+                dprint("more tabs")
+                line = line[1:]

That's not entirely correct either, because any other make character followed
by tab means the tab is part of the command. Better do line.lstrip('\t').

Quoted 14 lines

(quoted diff) +0 -0

             else:  # no more matching initial recipe character
                 break
         if print_command:

Quoted 10 lines

Quoted 9 lines

Quoted 6 lines

Not many. I have only tested the qemu_aarch64_virt_defconfig which does not contain much(~28 packages), but I was already able to fix a few parsing issues.

A bigger test is indeed needed to validate things. But let's see what others have to say first.

Quoted 3 lines

Quoted 3 lines

Indeed, because I'm not in favour...

- IMO 'make --output-sync=recurse' is sufficient to begin with.

Anisse, what's your POV about this? Do you see reasons why output-sync is
insufficient?

Quoted 5 lines

Quoted 5 lines

- This script requires python3 for *any* build, but python3 is not currently a dependency.

Quoted 8 lines

Quoted 5 lines

- If the script is changed so it supports both 2 and 3, it still requires a python invocation for every build step, which is slowing things down.

- Even if it is converted to a shell script or sped up in a different way, it will make things more complicated for IMO limited gain.

I'm not sure it can be converted to pure shell because of the lexing issues (nested double quotes, etc.).

Something like this?

IFS="$(echo)"
for line in $2; do

	sh -c "$line" 2>&1 | $1

done

Hm, stripping the first characters of $line is still to do...

This includes a new support script that helps parsing *_CMDS recipes, ensuring everything is forwarded.

See also: http://repo.or.cz/buildroot-gz.git/commitdiff/833e8fa7c7437931f1356b5b03a6b3810a3db586
Latest discussion: http://lists.busybox.net/pipermail/buildroot/2017-October/204159.html

Signed-off-by Anisse Astier <[email protected]>

---

This is a proof of concept and does not log everything yet, but should work.

 package/pkg-generic.mk             | 54 ++++++++++++++++++++--------------
 support/scripts/recipe-forward-log | 59 ++++++++++++++++++++++++++++++++++++++
 2 files changed, 91 insertions(+), 22 deletions(-)
 create mode 100755 support/scripts/recipe-forward-log

package/pkg-generic.mk +10 -6

index cca94ba..335e2be 100644
@@ -137,6 +137,8 @@ endef
 GLOBAL_INSTRUMENTATION_HOOKS += step_user
 endif
 
+exportvar = $(eval export $(1))
+
 ################################################################################
 # Implicit targets -- produce a stamp file for each step of a package build
 ################################################################################

@@ -166,12 +168,13 @@ $(BUILD_DIR)/%/.stamp_actual_downloaded:
 $(BUILD_DIR)/%/.stamp_extracted:
 	@$(call step_start,extract)
 	@$(call MESSAGE,"Extracting")
-	$(foreach hook,$($(PKG)_PRE_EXTRACT_HOOKS),$(call $(hook))$(sep))
+	$(foreach hook,$($(PKG)_PRE_EXTRACT_HOOKS),$(call $(hook)) >> $($(PKG)_LOGFILE) 2>&1 $(sep))
 	$(Q)mkdir -p $(@D)
-	$($(PKG)_EXTRACT_CMDS)
+	@$(call exportvar,$(PKG)_EXTRACT_CMDS)
+	$(TOPDIR)/support/scripts/recipe-forward-log "$($(PKG)_LOGFILE)" "$$$(PKG)_EXTRACT_CMDS"
 # some packages have messed up permissions inside
 	$(Q)chmod -R +rw $(@D)
-	$(foreach hook,$($(PKG)_POST_EXTRACT_HOOKS),$(call $(hook))$(sep))
+	$(foreach hook,$($(PKG)_POST_EXTRACT_HOOKS),$(call $(hook)) >> $($(PKG)_LOGFILE) 2>&1 $(sep))
 	@$(call step_end,extract)
 	$(Q)touch $@
 

@@ -223,9 +226,10 @@ $(foreach dir,$(call qstrip,$(BR2_GLOBAL_PATCH_DIR)),\
 $(BUILD_DIR)/%/.stamp_configured:
 	@$(call step_start,configure)
 	@$(call MESSAGE,"Configuring")
-	$(foreach hook,$($(PKG)_PRE_CONFIGURE_HOOKS),$(call $(hook))$(sep))
-	$($(PKG)_CONFIGURE_CMDS)
-	$(foreach hook,$($(PKG)_POST_CONFIGURE_HOOKS),$(call $(hook))$(sep))
+	$(foreach hook,$($(PKG)_PRE_CONFIGURE_HOOKS),$(call $(hook)) >> $($(PKG)_LOGFILE) 2>&1 $(sep))
+	@$(call exportvar,$(PKG)_CONFIGURE_CMDS)
+	$(TOPDIR)/support/scripts/recipe-forward-log "$($(PKG)_LOGFILE)" "$$$(PKG)_CONFIGURE_CMDS"
+	$(foreach hook,$($(PKG)_POST_CONFIGURE_HOOKS),$(call $(hook)) >> $($(PKG)_LOGFILE) 2>&1 $(sep))
 	@$(call step_end,configure)
 	$(Q)touch $@