RSB: log.py tends to remove relevant error messages

[Frank Kuehndel]

I sometime see (spontaneous) RSB build errors when building the tools. Fortunately, RSB provides error logs like this:

rtems/rsb-report-sparc-rtems6-gcc-0f001dd-newlib-64b2081-x86_64-linux-gnu-1.txt

Unfortunately, I can often not find the error message in the report. The reason is that the file source-builder/sb/log.py shortens the report to the last 400 lines in

148         if len(self.tail) > self.tail_size:
149             self.tail = self.tail[-self.tail_size:]

This is fine if the number of jobs is 1. If the number of jobs is greater one, the following tends to happen:

Assume the top level Makefile is called with -j 2 and it makes one job to execute a sub-Makefile in foo/Makefile and concurrently the second job to execute another one: bar/Makefile. Now, assume the job in foo/Makefile runs into an error, prints the error and returns to the top Makefile. The top Makefile will then wait for the second job to finish bar/Makefile. This job will typically print thousands of lines into the log and succeed in its execution. The result is that the truncated log will not contain the error message but only final lines of the output of the successful job.

For example, I oft did see this log report:

make[8]: Entering directory '/home/minna/src/rtems-source-builder/rtems/build/sparc-rtems6-gcc-0f001dd-newlib-64b2081-x86_64-linux-gnu-1/build/sparc-rtems6/soft/leon/at697f/libstdc++-v3'
true "AR_FLAGS=rc" "CC_FOR_BUILD=gcc -O2 -g -pipe -I/home/minna/src/rtems-source-builder/rtems/build/tmp/sb-1000/6/rtems-sparc/opt/rtems/6/include" "CC_FOR_TARGET=/home/minna/src/rtems-source-builder/rtems/build/sparc-rtems6-gcc-0f001dd-newlib-64b2081-x86_64-linux-gnu-1/build/./gcc/xgcc -B/home/minna/src/rtems-source-builder/rtems/build/sparc-rtems6-gcc-0f001dd-newlib-64b2081-x86_64-linux-gnu-1/build/./gcc/" "CFLAGS=-g -O2  -msoft-float -mcpu=leon -mfix-at697f" "CXXFLAGS=-g -O2  -msoft-float -mcpu=leon -mfix-at697f" "CFLAGS_FOR_BUILD=-g -O2" "CFLAGS_FOR_TARGET=-g -O2" "INSTALL=/usr/bin/install -c" "INSTALL_DATA=/usr/bin/install -c -m 644" "INSTALL_PROGRAM=/usr/bin/install -c" "INSTALL_SCRIPT=/usr/bin/install -c" "LDFLAGS=-msoft-float -mcpu=leon -mfix-at697f" "LIBCFLAGS=-g -O2  -msoft-float -mcpu=leon -mfix-at697f" "LIBCFLAGS_FOR_TARGET=-g -O2" "MAKE=make" "MAKEINFO=makeinfo --split-size=5000000 --split-size=5000000       " "SHELL=/bin/sh" "RUNTESTFLAGS=" "exec_prefix=/opt/rtems/6" "infodir=/opt/rtems/6/share/info" "libdir=/opt/rtems/6/lib" "includedir=/opt/rtems/6/include" "prefix=/opt/rtems/6" "tooldir=/opt/rtems/6/sparc-rtems6" "gxx_include_dir=/opt/rtems/6/lib/gcc/sparc-rtems6/10.3.1/include/c++" "AR=sparc-rtems6-ar" "AS=/home/minna/src/rtems-source-builder/rtems/build/sparc-rtems6-gcc-0f001dd-newlib-64b2081-x86_64-linux-gnu-1/build/./gcc/as" "LD=/home/minna/src/rtems-source-builder/rtems/build/sparc-rtems6-gcc-0f001dd-newlib-64b2081-x86_64-linux-gnu-1/build/./gcc/collect-ld" "RANLIB=sparc-rtems6-ranlib" "NM=/home/minna/src/rtems-source-builder/rtems/build/sparc-rtems6-gcc-0f001dd-newlib-64b2081-x86_64-linux-gnu-1/build/./gcc/nm" "NM_FOR_BUILD=" "NM_FOR_TARGET=sparc-rtems6-nm" "DESTDIR=" "WERROR=" DO=all multi-do # make
make[8]: Leaving directory '/home/minna/src/rtems-source-builder/rtems/build/sparc-rtems6-gcc-0f001dd-newlib-64b2081-x86_64-linux-gnu-1/build/sparc-rtems6/soft/leon/at697f/libstdc++-v3'
make[7]: Leaving directory '/home/minna/src/rtems-source-builder/rtems/build/sparc-rtems6-gcc-0f001dd-newlib-64b2081-x86_64-linux-gnu-1/build/sparc-rtems6/soft/leon/at697f/libstdc++-v3'
make[6]: Leaving directory '/home/minna/src/rtems-source-builder/rtems/build/sparc-rtems6-gcc-0f001dd-newlib-64b2081-x86_64-linux-gnu-1/build/sparc-rtems6/soft/leon/at697f/libstdc++-v3'
make[5]: Leaving directory '/home/minna/src/rtems-source-builder/rtems/build/sparc-rtems6-gcc-0f001dd-newlib-64b2081-x86_64-linux-gnu-1/build/sparc-rtems6/libstdc++-v3'
make[4]: Leaving directory '/home/minna/src/rtems-source-builder/rtems/build/sparc-rtems6-gcc-0f001dd-newlib-64b2081-x86_64-linux-gnu-1/build/sparc-rtems6/libstdc++-v3'
make[3]: Leaving directory '/home/minna/src/rtems-source-builder/rtems/build/sparc-rtems6-gcc-0f001dd-newlib-64b2081-x86_64-linux-gnu-1/build/sparc-rtems6/libstdc++-v3'
make[2]: Leaving directory '/home/minna/src/rtems-source-builder/rtems/build/sparc-rtems6-gcc-0f001dd-newlib-64b2081-x86_64-linux-gnu-1/build/sparc-rtems6/libstdc++-v3'
make[1]: Leaving directory '/home/minna/src/rtems-source-builder/rtems/build/sparc-rtems6-gcc-0f001dd-newlib-64b2081-x86_64-linux-gnu-1/build'
make: *** [Makefile:965: all] Error 2
shell cmd failed: /bin/sh -ex  /home/minna/src/rtems-source-builder/rtems/build/sparc-rtems6-gcc-0f001dd-newlib-64b2081-x86_64-linux-gnu-1/do-build
error: building sparc-rtems6-gcc-0f001dd-newlib-64b2081-x86_64-linux-gnu-1minna@

When I managed to get the complete output, the real error was in line 881481 of 894625 (please, do not ask why this was build with Fortran – it turned out that I did build using command line options I did not intend to use):

/bin/sh ./libtool  --tag=CC   --mode=compile /home/minna/src/rtems-source-builder/rtems/build/sparc-rtems6-gcc-0f001dd-newlib-64b2081-x86_64-linux-gnu-1/build/./gcc/xgcc -B/home/minna/src/rtems-source-builder/rtems/build/sparc-rtems6-gcc-0f001dd-newlib-64b2081-x86_64-linux-gnu-1/build/./gcc/ -nostdinc -B/home/minna/src/rtems-source-builder/rtems/build/sparc-rtems6-gcc-0f001dd-newlib-64b2081-x86_64-linux-gnu-1/build/sparc-rtems6/newlib/ -isystem /home/minna/src/rtems-source-builder/rtems/build/sparc-rtems6-gcc-0f001dd-newlib-64b2081-x86_64-linux-gnu-1/build/sparc-rtems6/newlib/targ-include -isystem /home/minna/src/rtems-source-builder/rtems/build/sparc-rtems6-gcc-0f001dd-newlib-64b2081-x86_64-linux-gnu-1/gnu-mirror-gcc-0f001dd/newlib/libc/include -B/usr/lib/rtems6/devtools-arm/sparc-rtems6/bin/ -B/usr/lib/rtems6/devtools-arm/sparc-rtems6/lib/ -isystem /usr/lib/rtems6/devtools-arm/sparc-rtems6/include -isystem /usr/lib/rtems6/devtools-arm/sparc-rtems6/sys-include    -DHAVE_CONFIG_H -I. -I../../../gnu-mirror-gcc-0f001dd/libgfortran  -iquote../../../gnu-mirror-gcc-0f001dd/libgfortran/io -I../../../gnu-mirror-gcc-0f001dd/libgfortran/../gcc -I../../../gnu-mirror-gcc-0f001dd/libgfortran/../gcc/config  -I../.././gcc -I../../../gnu-mirror-gcc-0f001dd/libgfortran/../libgcc -I../libgcc -I../../../gnu-mirror-gcc-0f001dd/libgfortran/../libbacktrace -I../libbacktrace -I../libbacktrace  -std=gnu11 -Wall -Wstrict-prototypes -Wmissing-prototypes -Wold-style-definition -Wextra -Wwrite-strings -Werror=implicit-function-declaration -Werror=vla  -fcx-fortran-rules -ffunction-sections -fdata-sections   -g -O2 -MT pause.lo -MD -MP -MF .deps/pause.Tpo -c -o pause.lo `test -f 'runtime/pause.c' || echo '../../../gnu-mirror-gcc-0f001dd/libgfortran/'`runtime/pause.c
In file included from ../../../gnu-mirror-gcc-0f001dd/libgfortran/runtime/fpu.c:29:
./fpu-target.h: In function 'set_fpu_trap_exceptions':
./fpu-target.h:90:3: error: implicit declaration of function 'feenableexcept'; did you mean 'feraiseexcept'? [-Werror=implicit-function-declaration]
   90 |   feenableexcept (mode_set);
      |   ^~~~~~~~~~~~~~
      |   feraiseexcept
./fpu-target.h:91:3: error: implicit declaration of function 'fedisableexcept'; did you mean 'feraiseexcept'? [-Werror=implicit-function-declaration]
   91 |   fedisableexcept (mode_clr);
      |   ^~~~~~~~~~~~~~~
      |   feraiseexcept
./fpu-target.h: In function 'get_fpu_trap_exceptions':
./fpu-target.h:98:20: error: implicit declaration of function 'fegetexcept'; did you mean 'fetestexcept'? [-Werror=implicit-function-declaration]
   98 |   int exceptions = fegetexcept ();
      |                    ^~~~~~~~~~~
      |                    fetestexcept
libtool: compile:  /home/minna/src/rtems-source-builder/rtems/build/sparc-rtems6-gcc-0f001dd-newlib-64b2081-x86_64-linux-gnu-1/build/./gcc/xgcc -B/home/minna/src/rtems-source-builder/rtems/build/sparc-rtems6-gcc-0f001dd-newlib-64b2081-x86_64-linux-gnu-1/build/./gcc/ -nostdinc -B/home/minna/src/rtems-source-builder/rtems/build/sparc-rtems6-gcc-0f001dd-newlib-64b2081-x86_64-linux-gnu-1/build/sparc-rtems6/newlib/ -isystem /home/minna/src/rtems-source-builder/rtems/build/sparc-rtems6-gcc-0f001dd-newlib-64b2081-x86_64-linux-gnu-1/build/sparc-rtems6/newlib/targ-include -isystem /home/minna/src/rtems-source-builder/rtems/build/sparc-rtems6-gcc-0f001dd-newlib-64b2081-x86_64-linux-gnu-1/gnu-mirror-gcc-0f001dd/newlib/libc/include -B/usr/lib/rtems6/devtools-arm/sparc-rtems6/bin/ -B/usr/lib/rtems6/devtools-arm/sparc-rtems6/lib/ -isystem /usr/lib/rtems6/devtools-arm/sparc-rtems6/include -isystem /usr/lib/rtems6/devtools-arm/sparc-rtems6/sys-include -DHAVE_CONFIG_H -I. -I../../../gnu-mirror-gcc-0f001dd/libgfortran -iquote../../../gnu-mirror-gcc-0f001dd/libgfortran/io -I../../../gnu-mirror-gcc-0f001dd/libgfortran/../gcc -I../../../gnu-mirror-gcc-0f001dd/libgfortran/../gcc/config -I../.././gcc -I../../../gnu-mirror-gcc-0f001dd/libgfortran/../libgcc -I../libgcc -I../../../gnu-mirror-gcc-0f001dd/libgfortran/../libbacktrace -I../libbacktrace -I../libbacktrace -std=gnu11 -Wall -Wstrict-prototypes -Wmissing-prototypes -Wold-style-definition -Wextra -Wwrite-strings -Werror=implicit-function-declaration -Werror=vla -fcx-fortran-rules -ffunction-sections -fdata-sections -g -O2 -MT pause.lo -MD -MP -MF .deps/pause.Tpo -c ../../../gnu-mirror-gcc-0f001dd/libgfortran/runtime/pause.c -o pause.o
cc1: some warnings being treated as errors
make[5]: *** [Makefile:2809: fpu.lo] Error 1
make[5]: *** Waiting for unfinished jobs....
mv -f .deps/main.Tpo .deps/main.Plo
mv -f .deps/environ.Tpo .deps/environ.Plo
mv -f .deps/pause.Tpo .deps/pause.Plo
mv -f .deps/error.Tpo .deps/error.Plo
mv -f .deps/single.Tpo .deps/single.Plo
make[5]: Leaving directory '/home/minna/src/rtems-source-builder/rtems/build/sparc-rtems6-gcc-0f001dd-newlib-64b2081-x86_64-linux-gnu-1/build/sparc-rtems6/libgfortran'

I would expect that the log/RSB report contains the actual error message by either somehow making sure the error containing piece is kept or the whole output is available. (I do not want to suggest a design decision on how this is solved the best way.)

For the records:

$ git -C rtems-source-builder/ rev-parse HEAD
49e3dac17765fa82ce2f754da839638ee352f95c

Build command:

$ cd rtems-source-builder/rtems && ../source-builder/sb-set-builder --rtems-version 6 --prefix /usr/lib/rtems6/devtools-arm --with_ada --with_cxx --with_fortran --with_objc --log /home/minna/src/sb-set-builder.log --trace --no-clean --jobs=12 6/rtems-arm 6/rtems-sparc 6/rtems-powerpc 6/rtems-riscv

Build environment: openSUSE Leap 15.3 container

[Frank Kuehndel]

There is an easy workaround:

When using the --log <log-file> option on the sb-set-builder command line, that log file contains all the output - including the lines not in the rtems/rsb-report-*.txt file. What me confused is the message "See error report" below the error:

Error: building arm-rtems6-gcc-0f001dd-newlib-64b2081-x86_64-linux-gnu-1
Build FAILED

See error report: rsb-report-arm-rtems6-gcc-0f001dd-newlib-64b2081-x86_64-linux-gnu-1.txt

This error report is shortened and may not contain the actual error message but it can be found in the log file mentioned above. Maybe changing the text to something link "See log or this error report" would prevent users like me from only looking into the error report.

[Chris Johns]

It is not possible to teach the RSB all the error messages that exist so it can find them.

A few of solutions exist:

1. Increase the size of the log tail
2. Remove the log tail on error
3. Do nothing and close this ticket? (my preferred option)

[Frank Kuehndel]

I opened this ticked because I wasted a lot of time looking into the error reports and not understanding that the real error is not shown there at all. With this ticket, I would like to prevent others to drop into the same pit I did fall in.

An error message like

See error report: rsb-report-arm-rtems6-gcc-0f001dd-newlib-64b2081-x86_64-linux-gnu-1.txt

strongly suggests that the error can be found in the report. This is the more confusing when the log close to the end contains something like make: *** [Makefile:965: all] Error 2. Yet, it turns out that when the number of jobs is greater than 1, the "real" error message appears so early that it is not in this report. (The real error message appears typically just before it says make: [...] Error 1 - but this may depend on the used make tool).

1. "Increasing the log size" does not help as the errors appears a lot of lines before the output ends.
2. "Remove the log tail on error." Keeping the whole log would help. Yet, these files are very very large and the current log.py implementation keeps everything in memory.
3. "Do nothing and close this ticket?" You can certainly close this ticks, as it is not a hard bug. Yet, many stupid users like me will end up looking uselessly into the report, instead of identifying the error and providing a patch. But nonetheless, just closing this ticket is certainly valid.

As a forth solution I would suggest to print a different text or some text below (esp. when the "jobs > 1"), indicating that the error cause in some cases can only be spotted in the full log generated by the -log <log-file> option.

[Chris Johns]

Yes the message can be wrong and it depends on the number of jobs and cores you have running and on the package being built. There are too many variables.

The log.py code does not keep the log in memory. Only the tail fragment is kept.

I think I will remove the log tail from the RSB and users can check the actual log. I can update the message to refer to the log.

[Frank Kuehndel]

There was a discussion on the devel at rtems.org mailing list on this topic. The thread starts with [PATCH 1/1] RSB: Mitigate too short error reports Tue Dec 20 16:44:11 UTC 2022:

​https://lists.rtems.org/pipermail/devel/2022-December/073973.html

and continues in January 2023:

​https://lists.rtems.org/pipermail/devel/2023-January/074087.html

With the following results:

• It is not possible to change the error report so that it always contains the relevant error. The errors can come from too may different sources and tools.
• Nonetheless the error report should be kept as it proved often helpful.
• The message which is printed when an error report is produced should be changed in such a way that the reader is made aware of the problem that the relevant error can sometimes not be found in the error report but only in the full build log.

[Frank Kühndel <frank.kuehndel@…>]

In b3b53c52/rtems-source-builder:

RSB: Mitigate too short error reports

Close #4642