[PATCH RFC 0/3] Preparatory work for sstate cache log replay

[PATCH RFC 0/3] Preparatory work for sstate cache log replay

[Mathieu Dubois-Briand]

The sstate cache mechanism currently has a blind spot: log messages shown
while a task first runs are not replayed when the task output comes back
from the cache. This is particularly true for warnings, which are
effectively hidden unless the task is rebuilt.

This bitbake series provides the needed support, storing each task's log
to a file that the openembedded-core series can later retrieve.

Signed-off-by: Mathieu Dubois-Briand <mathieu.dubois-briand@bootlin.com>
---
Mathieu Dubois-Briand (3):
      utils: Extend LogCatcher to record raw messages and levels
      build: Attach a log catcher to tasks and save their records
      runqueue: Hand each covered task's log to a single setscene task

 bin/bitbake-worker    |  1 +
 lib/bb/build.py       | 13 +++++++++++++
 lib/bb/runqueue.py    |  9 +++++++++
 lib/bb/tests/utils.py | 42 ++++++++++++++++++++++++++++++++++++++++++
 lib/bb/utils.py       |  4 +++-
 5 files changed, 68 insertions(+), 1 deletion(-)
---
base-commit: 1763256342ae4d7f8028e8222400c6fc8c24d4a3
change-id: 20261023-mathieu-debug-replay-v4-6594f3ecad25

Best regards,
-- 
Mathieu Dubois-Briand <mathieu.dubois-briand@bootlin.com>

[PATCH RFC 1/3] utils: Extend LogCatcher to record raw messages and levels

[Mathieu Dubois-Briand]

LogCatcher stores only formatted messages, which strips the severity. Also
record each log record's raw message and level, so callers can later
replay them with their original severity. Lower the handler minimum level
to WARNONCE so warnonce and erroronce messages are captured too.

Add unit tests covering the captured levels and raw messages, the
formatted output and the level filtering.

AI-Generated: Uses opencode (DeepSeek V4 Flash)
Signed-off-by: Mathieu Dubois-Briand <mathieu.dubois-briand@bootlin.com>
---
 lib/bb/tests/utils.py | 42 ++++++++++++++++++++++++++++++++++++++++++
 lib/bb/utils.py       |  4 +++-
 2 files changed, 45 insertions(+), 1 deletion(-)

diff --git a/lib/bb/tests/utils.py b/lib/bb/tests/utils.py
index 52b7bf85bf47..a34f6d698225 100644
--- a/lib/bb/tests/utils.py
+++ b/lib/bb/tests/utils.py
@@ -8,9 +8,11 @@
 
 import unittest
 import bb
+import bb.build
 import os
 import tempfile
 import re
+import logging
 
 class VerCmpString(unittest.TestCase):
 
@@ -693,6 +695,46 @@ class EnvironmentTests(unittest.TestCase):
         self.assertEqual(os.environ["A"], "this is A")
         self.assertNotIn("B", os.environ)
 
+class LogCatcherTests(unittest.TestCase):
+    def setUp(self):
+        self.logger = logging.getLogger("BitBake")
+        self.oldlevel = self.logger.level
+        self.logger.setLevel(logging.DEBUG)
+        self.catcher = bb.utils.LogCatcher()
+        self.logger.addHandler(self.catcher)
+
+    def tearDown(self):
+        self.logger.removeHandler(self.catcher)
+        self.logger.setLevel(self.oldlevel)
+
+    def test_records_capture_level_and_raw_message(self):
+        bb.warn("a warning")
+        bb.warnonce("a warn once")
+        bb.error("an error")
+        bb.erroronce("an error once")
+
+        self.assertEqual(self.catcher.records, [
+            (logging.WARNING, "a warning"),
+            (bb.msg.BBLogFormatter.WARNONCE, "a warn once"),
+            (logging.ERROR, "an error"),
+            (bb.msg.BBLogFormatter.ERRORONCE, "an error once"),
+        ])
+
+    def test_messages_are_formatted(self):
+        bb.warn("a warning")
+        self.assertEqual(self.catcher.messages, ["WARNING: a warning"])
+        self.assertTrue(self.catcher.contains("WARNING: a warning"))
+
+    def test_below_minimum_level_is_ignored(self):
+        bb.debug(1, "a debug")
+        bb.plain("a plain")
+        bb.note("a note")
+        bb.verbnote("a verb note")
+
+        self.assertEqual(self.catcher.records, [])
+        self.assertEqual(self.catcher.messages, [])
+
+
 class FilemodeTests(unittest.TestCase):
     def test_filemode_convert(self):
         self.assertEqual(0o775, bb.utils.to_filemode("0o775"))
diff --git a/lib/bb/utils.py b/lib/bb/utils.py
index ec6eb2181aa8..4a4e911b0f8a 100644
--- a/lib/bb/utils.py
+++ b/lib/bb/utils.py
@@ -2154,9 +2154,11 @@ class LogCatcher(logging.Handler):
     """Logging handler for collecting logged messages so you can check them later"""
     def __init__(self):
         self.messages = []
-        logging.Handler.__init__(self, logging.WARNING)
+        self.records = []
+        logging.Handler.__init__(self, bb.msg.BBLogFormatter.WARNONCE)
     def emit(self, record):
         self.messages.append(bb.build.logformatter.format(record))
+        self.records.append((record.levelno, record.getMessage()))
     def contains(self, message):
         return (message in self.messages)
 

-- 
2.47.3

[PATCH RFC 2/3] build: Attach a log catcher to tasks and save their records

[Mathieu Dubois-Briand]

Every task gets a LogCatcher which records its warnings and errors during
execution. Right after the task body, and before the postfuncs, the
records are written to ${T}/logrecords.<task>.json. The sstate packaging
postfunc reads the current task's file to bundle the messages for replay
when the task is later restored from the sstate cache.

Writing the file before the postfuncs makes both the current task's own
record and the files of already finished dependency tasks readable from
the same place.

AI-Generated: Uses opencode (DeepSeek V4 Flash)
Signed-off-by: Mathieu Dubois-Briand <mathieu.dubois-briand@bootlin.com>
---
 lib/bb/build.py | 13 +++++++++++++
 1 file changed, 13 insertions(+)

diff --git a/lib/bb/build.py b/lib/bb/build.py
index 8b49721d60f8..033e5b1c3f30 100644
--- a/lib/bb/build.py
+++ b/lib/bb/build.py
@@ -21,6 +21,7 @@ import time
 import re
 import stat
 import datetime
+import json
 import bb
 import bb.msg
 import bb.process
@@ -656,6 +657,11 @@ def _exec_task(fn, task, d, quieterr):
         except OSError:
            pass
 
+    # Task log records, for sstate log replay. Written right after the task
+    # body, before the postfuncs, so the sstate packaging postfunc can read them.
+    logrecords = os.path.join(tempdir, 'logrecords.{0}.json'.format(task))
+    bb.utils.remove(logrecords)
+
     prefuncs = localdata.getVarFlag(task, 'prefuncs', expand=True)
     postfuncs = localdata.getVarFlag(task, 'postfuncs', expand=True)
 
@@ -698,6 +704,9 @@ def _exec_task(fn, task, d, quieterr):
     errchk = ErrorCheckHandler()
     bblogger.addHandler(errchk)
 
+    tasklogcatcher = bb.utils.LogCatcher()
+    bblogger.addHandler(tasklogcatcher)
+
     localdata.setVar('BB_LOGFILE', logfn)
     localdata.setVar('BB_RUNTASK', task)
     localdata.setVar('BB_TASK_LOGGER', bblogger)
@@ -711,6 +720,9 @@ def _exec_task(fn, task, d, quieterr):
             for func in (prefuncs or '').split():
                 exec_func(func, localdata)
             exec_func(task, localdata)
+            if tasklogcatcher.records:
+                with open(logrecords, 'w') as f:
+                    json.dump(tasklogcatcher.records, f)
             for func in (postfuncs or '').split():
                 exec_func(func, localdata)
         finally:
@@ -720,6 +732,7 @@ def _exec_task(fn, task, d, quieterr):
             sys.stderr.flush()
 
             bblogger.removeHandler(handler)
+            bblogger.removeHandler(tasklogcatcher)
 
             # Restore the backup fds
             os.dup2(osi[0], osi[1])

-- 
2.47.3

[PATCH RFC 3/3] runqueue: Hand each covered task's log to a single setscene task

[Mathieu Dubois-Briand]

When a setscene task starts, hand it the covered tasks of the same recipe
which were not yet handed to another setscene task, and pass their names
to the task through BB_SETSCENE_REPLAY_TASKS. Several setscene tasks can
cover the same task (e.g. do_populate_sysroot and do_package both cover
do_compile), so this lets metadata replay the log of each covered task
exactly once when restoring it from the sstate cache.

AI-Generated: Uses opencode (DeepSeek V4 Flash)
Signed-off-by: Mathieu Dubois-Briand <mathieu.dubois-briand@bootlin.com>
---
 bin/bitbake-worker | 1 +
 lib/bb/runqueue.py | 9 +++++++++
 2 files changed, 10 insertions(+)

diff --git a/bin/bitbake-worker b/bin/bitbake-worker
index 61484a5c2522..0a46eea3ccb5 100755
--- a/bin/bitbake-worker
+++ b/bin/bitbake-worker
@@ -266,6 +266,7 @@ def fork_off_task(cfg, data, databuilder, workerdata, extraconfigdata, runtask):
                 the_data = databuilder.mcdata[mc]
                 the_data.setVar("BB_WORKERCONTEXT", "1")
                 the_data.setVar("BB_TASKDEPDATA", taskdepdata)
+                the_data.setVar("BB_SETSCENE_REPLAY_TASKS", " ".join(runtask.get('replaytasks', [])))
                 the_data.setVar('BB_CURRENTTASK', taskname.replace("do_", ""))
                 if cfg.limited_deps:
                     the_data.setVar("BB_LIMITEDDEPS", "1")
diff --git a/lib/bb/runqueue.py b/lib/bb/runqueue.py
index ef95eb46bf95..8bb1cb1a6e72 100644
--- a/lib/bb/runqueue.py
+++ b/lib/bb/runqueue.py
@@ -1939,6 +1939,8 @@ class RunQueueExecute:
         self.scenequeue_notcovered = set()
         self.tasks_notcovered = set()
         self.scenequeue_notneeded = set()
+        # Covered tasks already handed to a setscene task for log replay
+        self.sq_replay_assigned = set()
 
         self.setscene_tids_generator = None
 
@@ -2297,6 +2299,12 @@ class RunQueueExecute:
             startevent = sceneQueueTaskStarted(task, self.stats, self.rq)
             bb.event.fire(startevent, self.cfgData)
 
+            # Each covered task of this recipe is assigned to exactly one
+            # setscene task, so its log is replayed only once.
+            replaytasks = {t for t in self.sqdata.sq_covered_tasks[task]
+                           if fn_from_tid(t) == taskfn} - self.sq_replay_assigned
+            self.sq_replay_assigned |= replaytasks
+
             taskdep = self.rqdata.dataCaches[mc].task_deps[taskfn]
             realfn = bb.cache.virtualfn2realfn(taskfn)[0]
             runtask = {
@@ -2305,6 +2313,7 @@ class RunQueueExecute:
                 'taskname' : taskname,
                 'taskhash' : self.rqdata.get_task_hash(task),
                 'unihash' : self.rqdata.get_task_unihash(task),
+                'replaytasks' : sorted(taskname_from_tid(t) for t in replaytasks),
                 'quieterrors' : True,
                 'appends' : self.cooker.collections[mc].get_file_appends(taskfn),
                 'layername' : self.cooker.collections[mc].calc_bbfile_priority(realfn)[2],

-- 
2.47.3

Re: [bitbake-devel] [PATCH RFC 2/3] build: Attach a log catcher to tasks and save their records

[Richard Purdie]

On Sat, 2026-10-24 at 14:33 +0200, Mathieu Dubois-Briand via lists.openembedded.org wrote:
> Every task gets a LogCatcher which records its warnings and errors during
> execution. Right after the task body, and before the postfuncs, the
> records are written to ${T}/logrecords.<task>.json. The sstate packaging
> postfunc reads the current task's file to bundle the messages for replay
> when the task is later restored from the sstate cache.
> 
> Writing the file before the postfuncs makes both the current task's own
> record and the files of already finished dependency tasks readable from
> the same place.
> 
> AI-Generated: Uses opencode (DeepSeek V4 Flash)
> Signed-off-by: Mathieu Dubois-Briand <mathieu.dubois-briand@bootlin.com>
> ---
>  lib/bb/build.py | 13 +++++++++++++
>  1 file changed, 13 insertions(+)
> 
> diff --git a/lib/bb/build.py b/lib/bb/build.py
> index 8b49721d60f8..033e5b1c3f30 100644
> --- a/lib/bb/build.py
> +++ b/lib/bb/build.py
> @@ -21,6 +21,7 @@ import time
>  import re
>  import stat
>  import datetime
> +import json
>  import bb
>  import bb.msg
>  import bb.process
> @@ -656,6 +657,11 @@ def _exec_task(fn, task, d, quieterr):
>          except OSError:
>             pass
>  
> +    # Task log records, for sstate log replay. Written right after the task
> +    # body, before the postfuncs, so the sstate packaging postfunc can read them.
> +    logrecords = os.path.join(tempdir, 'logrecords.{0}.json'.format(task))
> +    bb.utils.remove(logrecords)
> +
>      prefuncs = localdata.getVarFlag(task, 'prefuncs', expand=True)
>      postfuncs = localdata.getVarFlag(task, 'postfuncs', expand=True)
>  
> @@ -698,6 +704,9 @@ def _exec_task(fn, task, d, quieterr):
>      errchk = ErrorCheckHandler()
>      bblogger.addHandler(errchk)
>  
> +    tasklogcatcher = bb.utils.LogCatcher()
> +    bblogger.addHandler(tasklogcatcher)
> +
>      localdata.setVar('BB_LOGFILE', logfn)
>      localdata.setVar('BB_RUNTASK', task)
>      localdata.setVar('BB_TASK_LOGGER', bblogger)
> @@ -711,6 +720,9 @@ def _exec_task(fn, task, d, quieterr):
>              for func in (prefuncs or '').split():
>                  exec_func(func, localdata)
>              exec_func(task, localdata)
> +            if tasklogcatcher.records:
> +                with open(logrecords, 'w') as f:
> +                    json.dump(tasklogcatcher.records, f)
>              for func in (postfuncs or '').split():
>                  exec_func(func, localdata)

I was going to ask if this should unconditionally rewrite the file even
if there are no records, else messages might persist if you fix
warnings output for example? I then see you delete the file above.

If there is no log output, I guess the question is whether we should
write an empty file or not...

Cheers,

Richard

Re: [bitbake-devel] [PATCH RFC 3/3] runqueue: Hand each covered task's log to a single setscene task

[Richard Purdie]

On Sat, 2026-10-24 at 14:33 +0200, Mathieu Dubois-Briand via lists.openembedded.org wrote:
> When a setscene task starts, hand it the covered tasks of the same recipe
> which were not yet handed to another setscene task, and pass their names
> to the task through BB_SETSCENE_REPLAY_TASKS. Several setscene tasks can
> cover the same task (e.g. do_populate_sysroot and do_package both cover
> do_compile), so this lets metadata replay the log of each covered task
> exactly once when restoring it from the sstate cache.
> 
> AI-Generated: Uses opencode (DeepSeek V4 Flash)
> Signed-off-by: Mathieu Dubois-Briand <mathieu.dubois-briand@bootlin.com>
> ---
>  bin/bitbake-worker | 1 +
>  lib/bb/runqueue.py | 9 +++++++++
>  2 files changed, 10 insertions(+)

This is a very specific piece of API, specifically tailored to what
this particular task entails.

I'm a bit worried that it still doesn't cover everything it should, for
example a warning from another recipe that is only covered by a given
sstate task and nothing else.

You can pobably calculate it from BB_TASKDEPDATA already too, if you
know which tasks are sstate, which I think we know.

There is also the potential for multiple log output from these covered
tasks, e.g. do_package and do_populate_sysroot both 'cover' on
do_install so a warning from do_install will be shown by both tasks at
setscene time.

So we should probably handle wider tasks than just the current
recipe...

Cheers,

Richard

Re: [bitbake-devel] [PATCH RFC 3/3] runqueue: Hand each covered task's log to a single setscene task

[Mathieu Dubois-Briand]

On Sun Oct 25, 2026 at 3:20 PM CET, Richard Purdie wrote:
> On Sat, 2026-10-24 at 14:33 +0200, Mathieu Dubois-Briand via lists.openembedded.org wrote:
>> When a setscene task starts, hand it the covered tasks of the same recipe
>> which were not yet handed to another setscene task, and pass their names
>> to the task through BB_SETSCENE_REPLAY_TASKS. Several setscene tasks can
>> cover the same task (e.g. do_populate_sysroot and do_package both cover
>> do_compile), so this lets metadata replay the log of each covered task
>> exactly once when restoring it from the sstate cache.
>> 
>> AI-Generated: Uses opencode (DeepSeek V4 Flash)
>> Signed-off-by: Mathieu Dubois-Briand <mathieu.dubois-briand@bootlin.com>
>> ---
>>  bin/bitbake-worker | 1 +
>>  lib/bb/runqueue.py | 9 +++++++++
>>  2 files changed, 10 insertions(+)
>
> This is a very specific piece of API, specifically tailored to what
> this particular task entails.
>

Just to make sure I fully understand this: I should rather try to rely
more on existing API or introduce something a bit more generic. Is that
right?

> I'm a bit worried that it still doesn't cover everything it should, for
> example a warning from another recipe that is only covered by a given
> sstate task and nothing else.

Indeed. Knowing we have to replay these logs should be easy, but
accessing these logs in the first place might be a bit tricky. I will
have to experiment a bit and understand what is possible.

>
> You can pobably calculate it from BB_TASKDEPDATA already too, if you
> know which tasks are sstate, which I think we know.
>
> There is also the potential for multiple log output from these covered
> tasks, e.g. do_package and do_populate_sysroot both 'cover' on
> do_install so a warning from do_install will be shown by both tasks at
> setscene time.
>

This should not happen with the current code. But I will have to be
careful when covering tasks from another recipe.

In your example, only one of the two tasks should be assigned with the
logs of do_install, either do_package or do_populate_sysroot, but not
both. This is the point of the sq_replay_assigned set here.

Also, it should be covered by my tests on the oe-core side.

Thanks,
Mathieu

-- 
Mathieu Dubois-Briand, Bootlin
Embedded Linux and Kernel engineering
https://bootlin.com

Re: [bitbake-devel] [PATCH RFC 2/3] build: Attach a log catcher to tasks and save their records

[Mathieu Dubois-Briand]

On Sun Oct 25, 2026 at 3:15 PM CET, Richard Purdie wrote:
> On Sat, 2026-10-24 at 14:33 +0200, Mathieu Dubois-Briand via lists.openembedded.org wrote:
>> Every task gets a LogCatcher which records its warnings and errors during
>> execution. Right after the task body, and before the postfuncs, the
>> records are written to ${T}/logrecords.<task>.json. The sstate packaging
>> postfunc reads the current task's file to bundle the messages for replay
>> when the task is later restored from the sstate cache.
>> 
>> Writing the file before the postfuncs makes both the current task's own
>> record and the files of already finished dependency tasks readable from
>> the same place.
>> 
>> AI-Generated: Uses opencode (DeepSeek V4 Flash)
>> Signed-off-by: Mathieu Dubois-Briand <mathieu.dubois-briand@bootlin.com>
>> ---

...

>> @@ -711,6 +720,9 @@ def _exec_task(fn, task, d, quieterr):
>>              for func in (prefuncs or '').split():
>>                  exec_func(func, localdata)
>>              exec_func(task, localdata)
>> +            if tasklogcatcher.records:
>> +                with open(logrecords, 'w') as f:
>> +                    json.dump(tasklogcatcher.records, f)
>>              for func in (postfuncs or '').split():
>>                  exec_func(func, localdata)
>
> I was going to ask if this should unconditionally rewrite the file even
> if there are no records, else messages might persist if you fix
> warnings output for example? I then see you delete the file above.
>
> If there is no log output, I guess the question is whether we should
> write an empty file or not...
>

I had no strong opinion here, but based on your comment, I feel like we
should indeed write an empty file when there is no log.

Thanks,
Mathieu

-- 
Mathieu Dubois-Briand, Bootlin
Embedded Linux and Kernel engineering
https://bootlin.com