[Buildroot] Discussion on per-package logging

[Buildroot] Discussion on per-package logging

[Thomas Petazzoni]

Hello,

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")
-       $(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
-- 
Thomas Petazzoni, CTO, Free Electrons
Embedded Linux and Kernel engineering
http://free-electrons.com

[Buildroot] Discussion on per-package logging

[Arnout Vandecappelle]

On 11-10-17 10:58, Thomas Petazzoni wrote:
> 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. 

 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.

 Regards,
 Arnout

> 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.

-- 
Arnout Vandecappelle                          arnout at mind be
Senior Embedded Software Architect            +32-16-286500
Essensium/Mind                                http://www.mind.be
G.Geenslaan 9, 3001 Leuven, Belgium           BE 872 984 063 RPR Leuven
LinkedIn profile: http://www.linkedin.com/in/arnoutvandecappelle
GPG fingerprint:  7493 020B C7E3 8618 8DEC 222C 82EB F404 F9AC 0DDF

[Buildroot] Discussion on per-package logging

[Thomas Petazzoni]

Hello,

On Wed, 11 Oct 2017 11:05:06 +0200, Arnout Vandecappelle wrote:

>  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.

Ah, I indeed forgot to cover the -O/--output-sync option. The drawback
with -Orecurse is that you don't see anything happening for the entire
duration of a given package build step. Also I'm not sure if the ">>>
foo 1.0 Building" message will actually be grouped with the build of
that package, which makes the analysis of the build output a bit
difficult.

I'll do a bit of testing and report.

Best regards,

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

[Buildroot] Discussion on per-package logging

[Yann E. MORIN]

Thomas, All,

On 2017-10-11 10:58 +0200, Thomas Petazzoni spake thusly:
> 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.

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.

So, mangled output should not be a major concern, I think.

As we've seen, the SHELL and .ONESHELL hacks are not entirely working,
so we should just ignore the issue, which is not really a problem.

If the user wants a cleaner output, let him pass one of the various
--output-sync values.

Regards,
Yann E. MORIN.

> 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")
> -       $(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
> -- 
> Thomas Petazzoni, CTO, Free Electrons
> Embedded Linux and Kernel engineering
> http://free-electrons.com

-- 
.-----------------.--------------------.------------------.--------------------.
|  Yann E. MORIN  | Real-Time Embedded | /"\ ASCII RIBBON | Erics' conspiracy: |
| +33 662 376 056 | Software  Designer | \ / CAMPAIGN     |  ___               |
| +33 223 225 172 `------------.-------:  X  AGAINST      |  \e/  There is no  |
| http://ymorin.is-a-geek.org/ | _/*\_ | / \ HTML MAIL    |   v   conspiracy.  |
'------------------------------^-------^------------------^--------------------'

[Buildroot] Discussion on per-package logging

[Thomas Petazzoni]

Hello,

On Wed, 11 Oct 2017 15:08:42 +0200, Yann E. MORIN wrote:

> 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
-- 
Thomas Petazzoni, CTO, Free Electrons
Embedded Linux and Kernel engineering
http://free-electrons.com

[Buildroot] Discussion on per-package logging

[Yann E. MORIN]

Thomas, All,

On 2017-10-11 15:19 +0200, Thomas Petazzoni spake thusly:
> On Wed, 11 Oct 2017 15:08:42 +0200, Yann E. MORIN wrote:
> > 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.

Fair enough.

Yet, that does not change the outcome: we can't and shouldn't do much.
The user can specify -Orecursive (or maybe just -Otarget) in that case.

Regards,
Yann E. MORIN.

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

-- 
.-----------------.--------------------.------------------.--------------------.
|  Yann E. MORIN  | Real-Time Embedded | /"\ ASCII RIBBON | Erics' conspiracy: |
| +33 662 376 056 | Software  Designer | \ / CAMPAIGN     |  ___               |
| +33 223 225 172 `------------.-------:  X  AGAINST      |  \e/  There is no  |
| http://ymorin.is-a-geek.org/ | _/*\_ | / \ HTML MAIL    |   v   conspiracy.  |
'------------------------------^-------^------------------^--------------------'

[Buildroot] [PATCH RFC] core: enable per-package log files

[Anisse Astier]

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 <anisse@astier.eu>
---

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

diff --git a/package/pkg-generic.mk b/package/pkg-generic.mk
index cca94ba..335e2be 100644
--- a/package/pkg-generic.mk
+++ b/package/pkg-generic.mk
@@ -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 $@
 
@@ -233,9 +237,10 @@ $(BUILD_DIR)/%/.stamp_configured:
 $(BUILD_DIR)/%/.stamp_built::
 	@$(call step_start,build)
 	@$(call MESSAGE,"Building")
-	$(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)) >> $($(PKG)_LOGFILE) 2>&1 $(sep))
+	@$(call exportvar,$(PKG)_BUILD_CMDS)
+	+$(TOPDIR)/support/scripts/recipe-forward-log "$($(PKG)_LOGFILE)" "$$$(PKG)_BUILD_CMDS"
+	$(foreach hook,$($(PKG)_POST_BUILD_HOOKS),$(call $(hook)) >> $($(PKG)_LOGFILE) 2>&1 $(sep))
 	@$(call step_end,build)
 	$(Q)touch $@
 
@@ -243,9 +248,10 @@ $(BUILD_DIR)/%/.stamp_built::
 $(BUILD_DIR)/%/.stamp_host_installed:
 	@$(call step_start,install-host)
 	@$(call MESSAGE,"Installing to host directory")
-	$(foreach hook,$($(PKG)_PRE_INSTALL_HOOKS),$(call $(hook))$(sep))
-	+$($(PKG)_INSTALL_CMDS)
-	$(foreach hook,$($(PKG)_POST_INSTALL_HOOKS),$(call $(hook))$(sep))
+	$(foreach hook,$($(PKG)_PRE_INSTALL_HOOKS),$(call $(hook)) >> $($(PKG)_LOGFILE) 2>&1 $(sep))
+	@$(call exportvar,$(PKG)_INSTALL_CMDS)
+	+$(TOPDIR)/support/scripts/recipe-forward-log "$($(PKG)_LOGFILE)" "$$$(PKG)_INSTALL_CMDS"
+	$(foreach hook,$($(PKG)_POST_INSTALL_HOOKS),$(call $(hook)) >> $($(PKG)_LOGFILE) 2>&1 $(sep))
 	@$(call step_end,install-host)
 	$(Q)touch $@
 
@@ -272,9 +278,10 @@ $(BUILD_DIR)/%/.stamp_host_installed:
 $(BUILD_DIR)/%/.stamp_staging_installed:
 	@$(call step_start,install-staging)
 	@$(call MESSAGE,"Installing to staging directory")
-	$(foreach hook,$($(PKG)_PRE_INSTALL_STAGING_HOOKS),$(call $(hook))$(sep))
-	+$($(PKG)_INSTALL_STAGING_CMDS)
-	$(foreach hook,$($(PKG)_POST_INSTALL_STAGING_HOOKS),$(call $(hook))$(sep))
+	$(foreach hook,$($(PKG)_PRE_INSTALL_STAGING_HOOKS),$(call $(hook)) >> $($(PKG)_LOGFILE) 2>&1 $(sep))
+	@$(call exportvar,$(PKG)_INSTALL_STAGING_CMDS)
+	+$(TOPDIR)/support/scripts/recipe-forward-log "$($(PKG)_LOGFILE)" "$$$(PKG)_INSTALL_STAGING_CMDS"
+	$(foreach hook,$($(PKG)_POST_INSTALL_STAGING_HOOKS),$(call $(hook)) >> $($(PKG)_LOGFILE) 2>&1 $(sep))
 	$(Q)if test -n "$($(PKG)_CONFIG_SCRIPTS)" ; then \
 		$(call MESSAGE,"Fixing package configuration files") ;\
 			$(SED)  "s,$(BASE_DIR), at BASE_DIR@,g" \
@@ -303,10 +310,11 @@ $(BUILD_DIR)/%/.stamp_staging_installed:
 # Install to images dir
 $(BUILD_DIR)/%/.stamp_images_installed:
 	@$(call step_start,install-image)
-	$(foreach hook,$($(PKG)_PRE_INSTALL_IMAGES_HOOKS),$(call $(hook))$(sep))
+	$(foreach hook,$($(PKG)_PRE_INSTALL_IMAGES_HOOKS),$(call $(hook)) >> $($(PKG)_LOGFILE) 2>&1 $(sep))
 	@$(call MESSAGE,"Installing to images directory")
-	+$($(PKG)_INSTALL_IMAGES_CMDS)
-	$(foreach hook,$($(PKG)_POST_INSTALL_IMAGES_HOOKS),$(call $(hook))$(sep))
+	@$(call exportvar,$(PKG)_INSTALL_IMAGES_CMDS)
+	+$(TOPDIR)/support/scripts/recipe-forward-log "$($(PKG)_LOGFILE)" "$$$(PKG)_INSTALL_IMAGES_CMDS"
+	$(foreach hook,$($(PKG)_POST_INSTALL_IMAGES_HOOKS),$(call $(hook)) >> $($(PKG)_LOGFILE) 2>&1 $(sep))
 	@$(call step_end,install-image)
 	$(Q)touch $@
 
@@ -314,13 +322,14 @@ $(BUILD_DIR)/%/.stamp_images_installed:
 $(BUILD_DIR)/%/.stamp_target_installed:
 	@$(call step_start,install-target)
 	@$(call MESSAGE,"Installing to target")
-	$(foreach hook,$($(PKG)_PRE_INSTALL_TARGET_HOOKS),$(call $(hook))$(sep))
-	+$($(PKG)_INSTALL_TARGET_CMDS)
+	$(foreach hook,$($(PKG)_PRE_INSTALL_TARGET_HOOKS),$(call $(hook)) >> $($(PKG)_LOGFILE) 2>&1 $(sep))
+	@$(call exportvar,$(PKG)_INSTALL_TARGET_CMDS)
+	+$(TOPDIR)/support/scripts/recipe-forward-log "$($(PKG)_LOGFILE)" "$$$(PKG)_INSTALL_TARGET_CMDS"
 	$(if $(BR2_INIT_SYSTEMD),\
 		$($(PKG)_INSTALL_INIT_SYSTEMD))
 	$(if $(BR2_INIT_SYSV)$(BR2_INIT_BUSYBOX),\
 		$($(PKG)_INSTALL_INIT_SYSV))
-	$(foreach hook,$($(PKG)_POST_INSTALL_TARGET_HOOKS),$(call $(hook))$(sep))
+	$(foreach hook,$($(PKG)_POST_INSTALL_TARGET_HOOKS),$(call $(hook)) >> $($(PKG)_LOGFILE) 2>&1 $(sep))
 	$(Q)if test -n "$($(PKG)_CONFIG_SCRIPTS)" ; then \
 		$(RM) -f $(addprefix $(TARGET_DIR)/usr/bin/,$($(PKG)_CONFIG_SCRIPTS)) ; \
 	fi
@@ -443,6 +452,7 @@ $(2)_BASE_NAME	= $$(if $$($(2)_VERSION),$(1)-$$($(2)_VERSION),$(1))
 $(2)_RAW_BASE_NAME = $$(if $$($(2)_VERSION),$$($(2)_RAWNAME)-$$($(2)_VERSION),$$($(2)_RAWNAME))
 $(2)_DL_DIR	=  $$(DL_DIR)
 $(2)_DIR	=  $$(BUILD_DIR)/$$($(2)_BASE_NAME)
+$(2)_LOGFILE	=  $$(BUILD_DIR)/$$($(2)_BASE_NAME).log
 
 ifndef $(2)_SUBDIR
  ifdef $(3)_SUBDIR
@@ -589,7 +599,7 @@ $(2)_TARGET_DIRCLEAN =		$$($(2)_DIR)/.stamp_dircleaned
 
 # default extract command
 $(2)_EXTRACT_CMDS ?= \
-	$$(if $$($(2)_SOURCE),$$(INFLATE$$(suffix $$($(2)_SOURCE))) $$(DL_DIR)/$$($(2)_SOURCE) | \
+	$$(if $$($(2)_SOURCE),	$$(INFLATE$$(suffix $$($(2)_SOURCE))) $$(DL_DIR)/$$($(2)_SOURCE) | \
 	$$(TAR) --strip-components=$$($(2)_STRIP_COMPONENTS) \
 		-C $$($(2)_DIR) \
 		$$(foreach x,$$($(2)_EXCLUDES),--exclude='$$(x)' ) \
diff --git a/support/scripts/recipe-forward-log b/support/scripts/recipe-forward-log
new file mode 100755
index 0000000..8240d74
--- /dev/null
+++ b/support/scripts/recipe-forward-log
@@ -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,
+                              stdout=sys.stdout)
+        ret = proc.wait()
+        if ret != 0 and stop_on_err:
+            sys.exit(ret)
-- 
2.7.5

[Buildroot] [PATCH RFC] core: enable per-package log files

[Anisse Astier]

On Mon, Oct 16, 2017 at 06:20:01PM +0200, Anisse Astier wrote:
> 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 <anisse@astier.eu>
> ---
> 
> This is a proof of concept and does not log everything yet, but should work.
> 
> 

Note that I initially wanted to do the support script in pure shell, but
stumbled on nested double quotes and other lexing issues, so I gave up.
See attachment (not working) for what it could have been.

Regards,

Anisse

-------------- next part --------------
A non-text attachment was scrubbed...
Name: recipe-forward-log.sh
Type: application/x-sh
Size: 1447 bytes
Desc: not available
URL: <http://lists.busybox.net/pipermail/buildroot/attachments/20171016/0b589f11/attachment.sh>

[Buildroot] [PATCH RFC] core: enable per-package log files

[Thomas Petazzoni]

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! :-)

On Mon, 16 Oct 2017 18:20:01 +0200, Anisse Astier wrote:

> -	$(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.

>  	$(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 ?

> diff --git a/support/scripts/recipe-forward-log b/support/scripts/recipe-forward-log
> new file mode 100755
> index 0000000..8240d74
> --- /dev/null
> +++ b/support/scripts/recipe-forward-log
> @@ -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,
> +                              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.

Thanks!

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

[Buildroot] [PATCH RFC] core: enable per-package log files

[Anisse Astier]

On Mon, Oct 16, 2017 at 06:52:48PM +0200, Thomas Petazzoni wrote:
> 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! :-)
> 
> On Mon, 16 Oct 2017 18:20:01 +0200, Anisse Astier wrote:
> 
> > -	$(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.

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

> 
> >  	$(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 ?
> 

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.

> > diff --git a/support/scripts/recipe-forward-log b/support/scripts/recipe-forward-log
> > new file mode 100755
> > index 0000000..8240d74
> > --- /dev/null
> > +++ b/support/scripts/recipe-forward-log
> > @@ -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,
> > +                              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.

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.

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

I just want to see this progress! Let's hope it gives new ideas :-)

Regards,

Anisse

[Buildroot] [PATCH RFC] core: enable per-package log files

[Thomas Petazzoni]

Hello,

On Mon, 16 Oct 2017 23:18:42 +0200, Anisse Astier wrote:

> > 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.

> > 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 ?

> 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 :)

> > 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.

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

Thanks!

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

[Buildroot] [PATCH RFC] core: enable per-package log files

[Arnout Vandecappelle]

On 17-10-17 09:11, Thomas Petazzoni wrote:
> Hello,
> 
> On Mon, 16 Oct 2017 23:18:42 +0200, Anisse Astier wrote:
> 
>>> 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.
> 
>>> 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 ?

 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.


>> 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).


>>> 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.

>>
>> 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))


 Regards,
 Arnout


-- 
Arnout Vandecappelle                          arnout at mind be
Senior Embedded Software Architect            +32-16-286500
Essensium/Mind                                http://www.mind.be
G.Geenslaan 9, 3001 Leuven, Belgium           BE 872 984 063 RPR Leuven
LinkedIn profile: http://www.linkedin.com/in/arnoutvandecappelle
GPG fingerprint:  7493 020B C7E3 8618 8DEC 222C 82EB F404 F9AC 0DDF

[Buildroot] [PATCH RFC] core: enable per-package log files

[Thomas Petazzoni]

Hello,

On Tue, 17 Oct 2017 14:01:41 +0200, Arnout Vandecappelle wrote:

>  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.

Best regards,

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

[Buildroot] [PATCH RFC] core: enable per-package log files

[Arnout Vandecappelle]

On 17-10-17 14:11, Thomas Petazzoni wrote:
> Hello,
> 
> On Tue, 17 Oct 2017 14:01:41 +0200, Arnout Vandecappelle wrote:
> 
>>  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?

 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.


> 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?

 Regards,
 Arnout


-- 
Arnout Vandecappelle                          arnout at mind be
Senior Embedded Software Architect            +32-16-286500
Essensium/Mind                                http://www.mind.be
G.Geenslaan 9, 3001 Leuven, Belgium           BE 872 984 063 RPR Leuven
LinkedIn profile: http://www.linkedin.com/in/arnoutvandecappelle
GPG fingerprint:  7493 020B C7E3 8618 8DEC 222C 82EB F404 F9AC 0DDF

[Buildroot] [PATCH RFC] core: enable per-package log files

[Anisse Astier]

On Tue, Oct 17, 2017 at 02:01:41PM +0200, Arnout Vandecappelle wrote:
> 
> 
> On 17-10-17 09:11, Thomas Petazzoni wrote:
> > Hello,
> > 
> > On Mon, 16 Oct 2017 23:18:42 +0200, Anisse Astier wrote:
> > 
> >>> 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.
> > 
> >>> 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 ?
> 
>  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!

Indeed! That was the only way I found to get through this boundary
properly.

> 
>  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.
> 
> 
> >> 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).
> 
> 
> >>> 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.

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:

@@ -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:]
             else:  # no more matching initial recipe character
                 break
         if print_command:

> 
> >>
> >> 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.

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.

> 
> 
>  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))

Interesting approach, indeed it could work, if that's a direction we
want to take.

Regards,

Anisse

[Buildroot] [PATCH RFC] core: enable per-package log files

[Anisse Astier]

On Mon, Oct 16, 2017 at 06:20:01PM +0200, Anisse Astier wrote:
> 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 <anisse@astier.eu>
> ---
> 
> 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
> 
> diff --git a/package/pkg-generic.mk b/package/pkg-generic.mk
> index cca94ba..335e2be 100644
> --- a/package/pkg-generic.mk
> +++ b/package/pkg-generic.mk
> @@ -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 $@
>  
> @@ -233,9 +237,10 @@ $(BUILD_DIR)/%/.stamp_configured:
>  $(BUILD_DIR)/%/.stamp_built::
>  	@$(call step_start,build)
>  	@$(call MESSAGE,"Building")
> -	$(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)) >> $($(PKG)_LOGFILE) 2>&1 $(sep))
> +	@$(call exportvar,$(PKG)_BUILD_CMDS)
> +	+$(TOPDIR)/support/scripts/recipe-forward-log "$($(PKG)_LOGFILE)" "$$$(PKG)_BUILD_CMDS"
> +	$(foreach hook,$($(PKG)_POST_BUILD_HOOKS),$(call $(hook)) >> $($(PKG)_LOGFILE) 2>&1 $(sep))

Side-note: before this, every use of +$(PKG)_XXX_CMDS wouldn't use the
make jobserver feature for anything but the first command of a multiline
_CMDS variable. This is a small issue since $(MAKE) seems to be used in
all packages.

Regards,

Anisse

[Buildroot] [PATCH RFC] core: enable per-package log files

[Thomas Petazzoni]

Hello,

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

> > 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.

True. I had some code doing that as part of my experiments, so I could
revive this.

> 
> > 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?

Yes, my idea was to have a BR2_PARALLEL_BUILD like we have
BR2_REPRODUCIBLE, mainly to guard the feature while it is being
developed/validated. Fully reliable top-level parallel build is not
going to arrive over night, so initially I would prefer to keep the
current behavior totally unchanged, except for users that opt-in by
enabling BR2_PARALLEL_BUILD. Once we agree that the feature is
reasonably safe, we can drop that option and make it the default.

> 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.

>  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 :/

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

[Buildroot] [PATCH RFC] core: enable per-package log files

[Arnout Vandecappelle]

On 17-10-17 17:45, Anisse Astier wrote:
> On Tue, Oct 17, 2017 at 02:01:41PM +0200, Arnout Vandecappelle wrote:
>>
>>
>> On 17-10-17 09:11, Thomas Petazzoni wrote:
[snip]
>>  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:
> 
> @@ -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').

>              else:  # no more matching initial recipe character
>                  break
>          if print_command:
> 
>>
>>>>
>>>> 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.

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

>>
>> - 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.
> 
> 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...


> 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.


 Regards,
 Arnout


[snip]

-- 
Arnout Vandecappelle                          arnout at mind be
Senior Embedded Software Architect            +32-16-286500
Essensium/Mind                                http://www.mind.be
G.Geenslaan 9, 3001 Leuven, Belgium           BE 872 984 063 RPR Leuven
LinkedIn profile: http://www.linkedin.com/in/arnoutvandecappelle
GPG fingerprint:  7493 020B C7E3 8618 8DEC 222C 82EB F404 F9AC 0DDF

[Buildroot] [PATCH RFC] core: enable per-package log files

[Arnout Vandecappelle]

On 17-10-17 21:03, Thomas Petazzoni wrote:
> Hello,
> 
> On Tue, 17 Oct 2017 16:44:04 +0200, Arnout Vandecappelle wrote:
[snip]
>> 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.

 Right! MAKEFLAGS is only initialized when calling a subprocess, and it anyway
doesn't contain the literal flags passed to make.

 It looks like there is no way to observe the flags passed to make :-(

> 
>>  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.

 Regards,
 Arnout

-- 
Arnout Vandecappelle                          arnout at mind be
Senior Embedded Software Architect            +32-16-286500
Essensium/Mind                                http://www.mind.be
G.Geenslaan 9, 3001 Leuven, Belgium           BE 872 984 063 RPR Leuven
LinkedIn profile: http://www.linkedin.com/in/arnoutvandecappelle
GPG fingerprint:  7493 020B C7E3 8618 8DEC 222C 82EB F404 F9AC 0DDF

[Buildroot] [PATCH RFC] core: enable per-package log files

[Thomas Petazzoni]

Hello,

On Wed, 18 Oct 2017 00:58:20 +0200, Arnout Vandecappelle wrote:

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

https://www.gnu.org/software/make/manual/html_node/Loading-Objects.html#Loading-Objects

Allows to create new functions, written in C, available from make. I
think it only exists since make 4.x, but that statement should be
verified.

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

[Buildroot] [PATCH RFC] core: enable per-package log files

[Thomas Petazzoni]

Hello,

On Wed, 18 Oct 2017 01:11:54 +0200, Arnout Vandecappelle wrote:

>  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.

Best regards,

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

[Buildroot] [PATCH RFC] core: enable per-package log files

[Anisse Astier]

On Wed, Oct 18, 2017 at 12:58:20AM +0200, Arnout Vandecappelle wrote:
> 
> 
> On 17-10-17 17:45, Anisse Astier wrote:
> > On Tue, Oct 17, 2017 at 02:01:41PM +0200, Arnout Vandecappelle wrote:
> >>
> >>
> >> On 17-10-17 09:11, Thomas Petazzoni wrote:
> [snip]
> >>  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:
> > 
> > @@ -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').

I disagree. See this Makefile for example :
all:
			--+	@	@echo multiple tab

It it's interpreted properly and shows that the parsing code seems
correct.

> 
> >              else:  # no more matching initial recipe character
> >                  break
> >          if print_command:
> > 
> >>
> >>>>
> >>>> 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.
> 
>  Anisse, what's your POV about this? Do you see reasons why output-sync is
> insufficient?

I have no attachment to my proposal. If -Orecurse works and removes one
roadblock for parallel building, I'm OK with that.

> 
> >>
> >> - 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.
> > 
> > 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...

Ah yes, it's simpler and could work. Needs testing.

Regards,

Anisse

[Buildroot] [PATCH RFC] core: enable per-package log files

[Anisse Astier]

On Wed, Oct 18, 2017 at 08:57:48AM +0200, Thomas Petazzoni wrote:
> Hello,
> 
> On Wed, 18 Oct 2017 01:11:54 +0200, Arnout Vandecappelle wrote:
> 
> >  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.

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.

Regards,

Anisse

[Buildroot] [PATCH RFC] core: enable per-package log files

[Thomas Petazzoni]

Hello,

On Wed, 18 Oct 2017 09:44:36 +0200, Anisse Astier wrote:

> > 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.

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.

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

[Buildroot] [PATCH RFC] core: enable per-package log files

[Anisse Astier]

Hi,

On Wed, Oct 18, 2017 at 09:58:26AM +0200, Thomas Petazzoni wrote:
> Hello,
> 
> On Wed, 18 Oct 2017 09:44:36 +0200, Anisse Astier wrote:
> 
> > > 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.
> 
> 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.

Also, I think that the tee to a logfile should be done by default, at
least in a parallel make environment, just to make sure the last build
log is kept, can be sent without copy/pasting issues in terminals, etc.
In this case, you don't need to do it manually when invoking buildroot
make.

Regards,

Anisse

[Buildroot] [PATCH RFC] core: enable per-package log files

[Thomas Petazzoni]

Hello,

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

> > 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" ? :-)

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

[Buildroot] [PATCH RFC] core: enable per-package log files

[Anisse Astier]

On Wed, Oct 18, 2017 at 10:11:06AM +0200, Thomas Petazzoni wrote:
> Hello,
> 
> On Wed, 18 Oct 2017 10:09:11 +0200, Anisse Astier wrote:
> 
> > > 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" ? :-)

Then we could consider the pipe case to be the same as a tty :-)

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

Regards,

Anisse

[Buildroot] [PATCH RFC] core: enable per-package log files

[Thomas Petazzoni]

Hello,

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

> 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.

Best regards,

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

[Buildroot] [PATCH RFC] core: enable per-package log files

[Arnout Vandecappelle]

On 18-10-17 11:10, Thomas Petazzoni wrote:
> Hello,
> 
> On Wed, 18 Oct 2017 11:05:10 +0200, Anisse Astier wrote:
> 
>> 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.

 It is nice if the more interesting use cases can be supported in utils/brmake,
so users don't have to reinvent their logging strategy all the time.

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

 Regards,
 Arnout

-- 
Arnout Vandecappelle                          arnout at mind be
Senior Embedded Software Architect            +32-16-286500
Essensium/Mind                                http://www.mind.be
G.Geenslaan 9, 3001 Leuven, Belgium           BE 872 984 063 RPR Leuven
LinkedIn profile: http://www.linkedin.com/in/arnoutvandecappelle
GPG fingerprint:  7493 020B C7E3 8618 8DEC 222C 82EB F404 F9AC 0DDF

[Buildroot] [PATCH RFC] core: enable per-package log files

[Arnout Vandecappelle]

On 18-10-17 08:57, Thomas Petazzoni wrote:
> Hello,
> 
> On Wed, 18 Oct 2017 01:11:54 +0200, Arnout Vandecappelle wrote:
> 
>>  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.

 Regards,
 Arnout
-- 
Arnout Vandecappelle                          arnout at mind be
Senior Embedded Software Architect            +32-16-286500
Essensium/Mind                                http://www.mind.be
G.Geenslaan 9, 3001 Leuven, Belgium           BE 872 984 063 RPR Leuven
LinkedIn profile: http://www.linkedin.com/in/arnoutvandecappelle
GPG fingerprint:  7493 020B C7E3 8618 8DEC 222C 82EB F404 F9AC 0DDF

[Buildroot] [PATCH RFC] core: enable per-package log files

[Thomas Petazzoni]

Hello,

On Wed, 18 Oct 2017 12:54:44 +0200, Arnout Vandecappelle wrote:

>  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.

I don't entirely agree here. While -j5 is well known, -Orecurse
certainly isn't, and I'd like to have something that has a reasonable
behavior out of the box.

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

Same here: if you don't solve the logging problem, top-level parallel
build is horrible. You can't debug anything, it's a total mess.

Yes, it's just one small aspect of the problem, but it's one aspect
that needs to be solved.

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

[Buildroot] [PATCH RFC] core: enable per-package log files

[Thomas Petazzoni]

Hello,

On Wed, 18 Oct 2017 12:57:30 +0200, Arnout Vandecappelle wrote:

>  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 :)

>  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.

The patch I have removes .NOTPARALLEL if BR2_PARALLEL_BUILD=y.

Best regards,

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

[Buildroot] [PATCH RFC] core: enable per-package log files

[Yann E. MORIN]

Thomas, Arnout, Anisse, All,

On 2017-10-18 13:36 +0200, Thomas Petazzoni spake thusly:
> On Wed, 18 Oct 2017 12:57:30 +0200, Arnout Vandecappelle wrote:
> >  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 :)
> 
> >  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.

Eventually, when everything is fully parallel-safe, I believe we will
want to remove BR2_JLEVEL altogether, and let users directly call
"make -jN".

As for the -O option, it all depends on the oldest make we are supposed
to support. It appeared only in make 4.0, released in October 2013.

So I think we'll have to come up with an alternative solution (and I am
sad that we do, I would have prefered we require 4.0, but it is not old
enough :-/ ).

However, I'll repeat my position: having top-level parallel build (TLP)
is important. If we can't find a viable, simple and maintainable
solution, then we should just ignore the problem and still implement
TLP.

I am not much happy with any of the external wrapper, because it is
relatively fragile, and we have to use it everywhere we need to write a
make rule (which is not a package, fs, or bootloader CMDS).

For example, we also need to use it for:

  - the step_start and step_end hooks
  - the intermediate commands [0] [1]
  - ech commands in the finalise-target, legal-info and all similar ones
  - and I suspect countless other locations...


[0] for example, it is needed for the for-loop there:
   package/pkg-generic.mk:
   145 $(BUILD_DIR)/%/.stamp_downloaded:
   146 ?   $(foreach hook,$($(PKG)_PRE_DOWNLOAD_HOOKS),$(call $(hook))$(sep))
   147 # Only show the download message if it isn't already downloaded
   148 ?   $(Q)for p in $($(PKG)_ALL_DOWNLOADS); do \
   149 ?   ?   if test ! -e $(DL_DIR)/`basename $$p` ; then \
   150 ?   ?   ?   $(call MESSAGE,"Downloading") ; \
   151 ?   ?   ?   break ; \
   152 ?   ?   fi ; \
   153 ?   done
   154 ?   $(foreach p,$($(PKG)_ALL_DOWNLOADS),$(call DOWNLOAD,$(p))$(sep))
   155 ?   $(foreach hook,$($(PKG)_POST_DOWNLOAD_HOOKS),$(call $(hook))$(sep))
   156 ?   $(Q)mkdir -p $(@D)
   157 ?   $(Q)touch $@


[1] for example, it is needed for each of mkdir, chmod and touch there:
   package/pkg-generic.mk:
   166 $(BUILD_DIR)/%/.stamp_extracted:
   167 ?   @$(call step_start,extract)
   168 ?   @$(call MESSAGE,"Extracting")
   169 ?   $(foreach hook,$($(PKG)_PRE_EXTRACT_HOOKS),$(call $(hook))$(sep))
   170 ?   $(Q)mkdir -p $(@D)
   171 ?   $($(PKG)_EXTRACT_CMDS)
   172 # some packages have messed up permissions inside
   173 ?   $(Q)chmod -R +rw $(@D)
   174 ?   $(foreach hook,$($(PKG)_POST_EXTRACT_HOOKS),$(call $(hook))$(sep))
   175 ?   @$(call step_end,extract)
   176 ?   $(Q)touch $@


Regards,
Yann E. MORIN.

-- 
.-----------------.--------------------.------------------.--------------------.
|  Yann E. MORIN  | Real-Time Embedded | /"\ ASCII RIBBON | Erics' conspiracy: |
| +33 662 376 056 | Software  Designer | \ / CAMPAIGN     |  ___               |
| +33 223 225 172 `------------.-------:  X  AGAINST      |  \e/  There is no  |
| http://ymorin.is-a-geek.org/ | _/*\_ | / \ HTML MAIL    |   v   conspiracy.  |
'------------------------------^-------^------------------^--------------------'