Skip to contentSkip to conversation

Use last 4 lines of log instead of 3 when getting failure reason

PATCH New Vlad Zakharov 3 participants 6 messages Oct 26, 2016 – Apr 15, 2017

lore
Share & tools
lore

Vlad Zakharov

author
#0 lore raw

PATCH 1/1 Use last 4 lines of log instead of 3 when getting failure reason

Latest versions of make produce a bit different output than older versions do. They also print number of line in Makefile where the failure occurred.

E.g. latest make produces the following output:
---------------------------------->8------------------------------------
GNUmakefile:277: recipe for target 'cgiedit.o' failed
make[2]: *** [cgiedit.o] Error 1
package/pkg-generic.mk:201: recipe for target '/home/buildroot/autobuild/run/instance-2/output/build/privoxy-3.0.26/.stamp_built' failed make[1]: *** [/home/buildroot/autobuild/run/instance-2/output/build/privoxy-3.0.26/.stamp_built] Error 2 Makefile:88: recipe for target '_all' failed
make: *** [_all] Error 2
make: Leaving directory '/home/buildroot/autobuild/run/instance-2/buildroot' ---------------------------------->8------------------------------------

When with old version we get something like:
---------------------------------->8------------------------------------
make[2]: *** [cgiedit.o] Error 1
make[1]: *** [/home/buildroot/autobuild/run/instance-1/output/build/privoxy-3.0.26/.stamp_built] Error 2
make: *** [_all] Error 2
make: Leaving directory `/home/buildroot/autobuild/run/instance-1/buildroot' ---------------------------------->8------------------------------------

So latest make produce much more "noise" and we have to analyze at least 4 last lines of log to be sure that they contain a line with failure reason.

Signed-off-by Vlad Zakharov <[email protected]>
---
 scripts/autobuild-run | 2 +-
 web/import.inc.php    | 2 +-
 2 files changed, 2 insertions(+), 2 deletions(-)
scripts/autobuild-run +1 -1
index 0fa5fdc..8c86a29 100755
@@ -667,7 +667,7 @@ def send_results(result, **kwargs):
     def get_failure_reason():
         # Output is a tuple (package, version), or None.
         lastlines = decode_bytes(subprocess.Popen(
-            ["tail", "-n", "3", os.path.join(outputdir, "logfile")],
+            ["tail", "-n", "4", os.path.join(outputdir, "logfile")],
             stdout=subprocess.PIPE).communicate()[0]).splitlines()
 
         regexp = re.compile(r'make: \*\*\* .*/(?:build|toolchain)/([^/]*)/')
web/import.inc.php +1 -1
index 243a1f3..3be1251 100644
@@ -102,7 +102,7 @@ function import_result($buildid, $filename)
       $reason = "none";
     else {
 	$tmp = Array();
-	exec("tail -3 " . $thisbuildfinaldir . "build-end.log | grep -v '\[_all\]' | grep 'make.*: \*\*\*' | sed 's,.*\[\([^\]*\)\] Error.*,\\1,' | sed 's,.*/build/\([^/]*\)/.*,\\1,'", $tmp);
+	exec("tail -4 " . $thisbuildfinaldir . "build-end.log | grep -v '\[_all\]' | grep 'make.*: \*\*\*' | sed 's,.*\[\([^\]*\)\] Error.*,\\1,' | sed 's,.*/build/\([^/]*\)/.*,\\1,'", $tmp);
 	if (trim($tmp[0]))
 	  $reason = $tmp[0];
 	else
Signature · 1 line
2.5.5
#1 lore raw

PATCH 1/1 Use last 4 lines of log instead of 3 when getting failure reason

Hello,

Quoted 23 lines · Vlad Zakharov

Latest versions of make produce a bit different output than older versions do. They also print number of line in Makefile where the failure occurred.

E.g. latest make produces the following output:
---------------------------------->8------------------------------------
GNUmakefile:277: recipe for target 'cgiedit.o' failed
make[2]: *** [cgiedit.o] Error 1
package/pkg-generic.mk:201: recipe for target '/home/buildroot/autobuild/run/instance-2/output/build/privoxy-3.0.26/.stamp_built' failed make[1]: *** [/home/buildroot/autobuild/run/instance-2/output/build/privoxy-3.0.26/.stamp_built] Error 2 Makefile:88: recipe for target '_all' failed
make: *** [_all] Error 2
make: Leaving directory '/home/buildroot/autobuild/run/instance-2/buildroot' ---------------------------------->8------------------------------------

When with old version we get something like:
---------------------------------->8------------------------------------
make[2]: *** [cgiedit.o] Error 1
make[1]: *** [/home/buildroot/autobuild/run/instance-1/output/build/privoxy-3.0.26/.stamp_built] Error 2
make: *** [_all] Error 2
make: Leaving directory `/home/buildroot/autobuild/run/instance-1/buildroot' ---------------------------------->8------------------------------------

Quoted 5 lines

So latest make produce much more "noise" and we have to analyze at least 4 last lines of log to be sure that they contain a line with failure reason.

Signed-off-by Vlad Zakharov <[email protected]>

I'm a little bit worried about this change, because we did a fairly similar change in commit 585358277b80dfe18b17b13035675bfe7db48b20, which I quickly reverted in commit a616a8c592caf2a9c9ce82ac1cac9681775452d3 because it was breaking everything. Following 585358277b80dfe18b17b13035675bfe7db48b20, for a large number of builds, the detected build failure was "all" or "all-recursive".

So we really want to be extra careful, by testing the logic change on existing build results first.

Also, another thing that is annoying that we have two places where we calculate the failure reason: in autobuild-run (on the autobuild slave) and in import.inc.php (which runs on autobuild.b.o when an autobuild result is submitted).

Historically, the failure reason was only extracted in import.inc.php, from the submitted log. But later on, some logic was added in autobuild-run to extract the reason, which was used to make sure we keep in build-end.log not just the 500 last lines of the build, but the entire build log from the beginning of the failing package (which requires knowing the package that failed building, and therefore calculating the reason).

It would be great to get rid of this duplication, and have autobuild-run calculate the reason, store it in a "reason" file, submitted to autobuild.b.o as part of the tarball, and import.inc.php simply reads that file. This way we have the reason calculation logic in just one place.

Thanks,

Thomas

Signature · 3 lines
Thomas Petazzoni, CTO, Free Electrons
Embedded Linux and Kernel engineering
http://free-electrons.com
author
#2 lore raw

PATCH 1/1 Use last 4 lines of log instead of 3 when getting failure reason

Hi Thomas.

Quoted 42 lines · Thomas Petazzoni

Hello,

Quoted 25 lines · Vlad Zakharov

Latest versions of make produce a bit different output than older versions do. They also print number of line in Makefile where the failure occurred.

E.g. latest make produces the following output:
---------------------------------->8------------------------------------??
GNUmakefile:277: recipe for target 'cgiedit.o' failed
make[2]: *** [cgiedit.o] Error 1
package/pkg-generic.mk:201: recipe for target '/home/buildroot/autobuild/run/instance-2/output/build/privoxy- 3.0.26/.stamp_built' failed
make[1]: *** [/home/buildroot/autobuild/run/instance-2/output/build/privoxy-3.0.26/.stamp_built] Error 2 Makefile:88: recipe for target '_all' failed
make: *** [_all] Error 2
make: Leaving directory '/home/buildroot/autobuild/run/instance-2/buildroot' ---------------------------------->8------------------------------------??

When with old version we get something like:
---------------------------------->8------------------------------------??
make[2]: *** [cgiedit.o] Error 1
make[1]: *** [/home/buildroot/autobuild/run/instance-1/output/build/privoxy-3.0.26/.stamp_built] Error 2
make: *** [_all] Error 2
make: Leaving directory `/home/buildroot/autobuild/run/instance-1/buildroot' ---------------------------------->8------------------------------------??

Quoted 5 lines

So latest make produce much more "noise" and we have to analyze at least 4 last lines of log to be sure that they contain a line with failure reason.

Signed-off-by Vlad Zakharov <[email protected]>

I'm a little bit worried about this change, because we did a fairly similar change in commit 585358277b80dfe18b17b13035675bfe7db48b20, which I quickly reverted in commit a616a8c592caf2a9c9ce82ac1cac9681775452d3 because it was breaking everything. Following 585358277b80dfe18b17b13035675bfe7db48b20, for a large number of builds, the detected build failure was "all" or "all-recursive".

Quoted 2 lines

So we really want to be extra careful, by testing the logic change on existing build results first.

But I haven't updated the regex, only lines count printed by tail.
The regex suggested by?585358277b80dfe18b17b13035675bfe7db48b20 was able to recognize both "make:" and "make[n]:". Note that "all" and "all-recursive" targets appears with the second variant. I guess that my changes would not affect failure reason parsing from output of older make versions.

I can offer another solution:
We analyze last 4 lines but use the last matched string. As I understand from my experience of analyzing build logs the string with a real build failure as a rule comes after "all" and "all-recursive".

Quoted 14 lines

Also, another thing that is annoying that we have two places where we calculate the failure reason: in autobuild-run (on the autobuild slave) and in import.inc.php (which runs on autobuild.b.o when an autobuild result is submitted).

Historically, the failure reason was only extracted in import.inc.php, from the submitted log. But later on, some logic was added in autobuild-run to extract the reason, which was used to make sure we keep in build-end.log not just the 500 last lines of the build, but the entire build log from the beginning of the failing package (which requires knowing the package that failed building, and therefore calculating the reason).

Quoted 5 lines

It would be great to get rid of this duplication, and have autobuild-run calculate the reason, store it in a "reason" file, submitted to autobuild.b.o as part of the tarball, and import.inc.php simply reads that file. This way we have the reason calculation logic in just one place.

I can write a separate patch that will exclude duplication and store failure reason in a "reason" file.?

Quoted 4 lines

Thanks,

Thomas

Signature · 2 lines
Best regards,
Vlad Zakharov <[email protected]>
author
#3 lore raw

PATCH 1/1 Use last 4 lines of log instead of 3 when getting failure reason

Hi Thomas, all.

I strongly believe that something should be done with the issue.
Of course the approach that I have suggested may not be the best but we can discuss the subject to find better solution. It is not a good idea to leave everything as is because failure reason detection totally doesn't work if use up-to-date "make" utility.?

Thank you.?

Quoted 91 lines · Vlad Zakharov

Hi Thomas.

Quoted 44 lines · Thomas Petazzoni

Hello,

Quoted 26 lines · Vlad Zakharov

Latest versions of make produce a bit different output than older versions do. They also print number of line in Makefile where the failure occurred.

E.g. latest make produces the following output:
---------------------------------->8------------------------------------??
GNUmakefile:277: recipe for target 'cgiedit.o' failed
make[2]: *** [cgiedit.o] Error 1
package/pkg-generic.mk:201: recipe for target '/home/buildroot/autobuild/run/instance-2/output/build/privoxy- 3.0.26/.stamp_built' failed
make[1]: *** [/home/buildroot/autobuild/run/instance-2/output/build/privoxy-3.0.26/.stamp_built] Error 2 Makefile:88: recipe for target '_all' failed
make: *** [_all] Error 2
make: Leaving directory '/home/buildroot/autobuild/run/instance-2/buildroot' ---------------------------------->8------------------------------------??

When with old version we get something like:
---------------------------------->8------------------------------------??
make[2]: *** [cgiedit.o] Error 1
make[1]: *** [/home/buildroot/autobuild/run/instance-1/output/build/privoxy-3.0.26/.stamp_built] Error 2
make: *** [_all] Error 2
make: Leaving directory `/home/buildroot/autobuild/run/instance-1/buildroot' ---------------------------------->8------------------------------------??

Quoted 5 lines

So latest make produce much more "noise" and we have to analyze at least 4 last lines of log to be sure that they contain a line with failure reason.

Signed-off-by Vlad Zakharov <[email protected]>

I'm a little bit worried about this change, because we did a fairly similar change in commit 585358277b80dfe18b17b13035675bfe7db48b20, which I quickly reverted in commit a616a8c592caf2a9c9ce82ac1cac9681775452d3 because it was breaking everything. Following 585358277b80dfe18b17b13035675bfe7db48b20, for a large number of builds, the detected build failure was "all" or "all-recursive".

Quoted 2 lines

So we really want to be extra careful, by testing the logic change on existing build results first.

But I haven't updated the regex, only lines count printed by tail.
The regex suggested by?585358277b80dfe18b17b13035675bfe7db48b20 was able to recognize both "make:" and "make[n]:". Note that "all" and "all-recursive" targets appears with the second variant. I guess that my changes would not affect failure reason parsing from output of older make versions.

I can offer another solution:
We analyze last 4 lines but use the last matched string. As I understand from my experience of analyzing build logs the
string with a real build failure as a rule comes after "all" and "all-recursive".

Quoted 15 lines

Also, another thing that is annoying that we have two places where we calculate the failure reason: in autobuild-run (on the autobuild slave) and in import.inc.php (which runs on autobuild.b.o when an autobuild result is submitted).

Historically, the failure reason was only extracted in import.inc.php, from the submitted log. But later on, some logic was added in autobuild-run to extract the reason, which was used to make sure we keep in build-end.log not just the 500 last lines of the build, but the entire build log from the beginning of the failing package (which requires knowing the package that failed building, and therefore calculating the reason).

Quoted 5 lines

It would be great to get rid of this duplication, and have autobuild-run calculate the reason, store it in a "reason" file, submitted to autobuild.b.o as part of the tarball, and import.inc.php simply reads that file. This way we have the reason calculation logic in just one place.

I can write a separate patch that will exclude duplication and store failure reason in a "reason" file.?

Quoted 5 lines

Thanks,

Thomas

--?
Best regards,
Vlad Zakharov <[email protected]>

Signature · 2 lines
Best regards,
Vlad Zakharov <[email protected]>
#4 lore raw

PATCH 1/1 Use last 4 lines of log instead of 3 when getting failure reason

Coming back to this old issue...

Quoted 46 lines · Vlad Zakharov

Hi Thomas, all.

I strongly believe that something should be done with the issue.
Of course the approach that I have suggested may not be the best but we can discuss the subject to find better solution. It is not a good idea to leave everything as is because failure reason detection totally doesn't work if use up-to-date "make" utility.

Thank you.

Quoted 36 lines · Vlad Zakharov

Hi Thomas.

Quoted 33 lines · Thomas Petazzoni

Hello,

Quoted 29 lines · Vlad Zakharov

Latest versions of make produce a bit different output than older versions do. They also print number of line in Makefile where the failure occurred.

E.g. latest make produces the following output:
---------------------------------->8------------------------------------
GNUmakefile:277: recipe for target 'cgiedit.o' failed
make[2]: *** [cgiedit.o] Error 1
package/pkg-generic.mk:201: recipe for target '/home/buildroot/autobuild/run/instance-2/output/build/privoxy- 3.0.26/.stamp_built' failed
make[1]: *** [/home/buildroot/autobuild/run/instance-2/output/build/privoxy-3.0.26/.stamp_built] Error 2 Makefile:88: recipe for target '_all' failed
make: *** [_all] Error 2
make: Leaving directory '/home/buildroot/autobuild/run/instance-2/buildroot' ---------------------------------->8------------------------------------

When with old version we get something like:
---------------------------------->8------------------------------------
make[2]: *** [cgiedit.o] Error 1
make[1]: *** [/home/buildroot/autobuild/run/instance-1/output/build/privoxy-3.0.26/.stamp_built] Error 2
make: *** [_all] Error 2
make: Leaving directory `/home/buildroot/autobuild/run/instance-1/buildroot' ---------------------------------->8------------------------------------

So latest make produce much more "noise" and we have to analyze at least 4 last lines of log to be sure that they contain a line with failure reason.

Instead of relying on make's "noise", why don't we just use the very last line
of build-time.log?

Regards,
Arnout

[snip]

Signature · 6 lines
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
#5 lore raw

PATCH 1/1 Use last 4 lines of log instead of 3 when getting failure reason

Hello,

Quoted 2 lines · Arnout Vandecappelle

Instead of relying on make's "noise", why don't we just use the very last line
of build-time.log?

Good idea. I believe we rely on make noise, because build-time.log didn't exist when the autobuild-run stuff was initially written.

Thomas

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