Bug 14555

Created attachment 4828 [details]
A couple more logs + pseudo sqlite db screenshots.

Using (hardknott branch):

 -  poky at 4624b855ed47c5da08953191bfbb39e764ecb343
 -  meta-openembedded at 7bd7e1da9034e72ca4262dba55f70b2b23499aae

which means:

 -  pseudo at b988b0a6b8afd8d459bc9a2528e834f63a3d59b2 (oe-core branch)

Which host distro is this being built on? Is buildtools tarball in use?

Also, which version of the hardknott branch is this please? There were fixes for some issues like this in later versions of the branch.

(In reply to comment #3)
> Which host distro is this being built on? Is buildtools tarball in use?

"crops/poky:ubuntu-20.04" docker image.

I am not sure about the "buildtools tarball" aspect. We are using the docker image as it is. How can I tell if I am using this "buildtools tarball"?

(In reply to comment #4)
> Also, which version of the hardknott branch is this please? There were fixes
> for some issues like this in later versions of the branch.

See above comment <https://bugzilla.yoctoproject.org/show_bug.cgi?id=14555#c2>.

Thanks for the info, sorry I missed the hardknott revision! This is all a bit odd as I build in 20.04 myself and I don't see this.

You'd usually expect that if there were this kind of corruption occuring, there would be incorrect inode entries in the database after each rootfs construction. I appreciate that may or may not then fail due to inode reuse but the inode would be incorrect.

Do you know if the inode for ld.so.conf is always incorrect after every build and it just sometimes hits the race? The bit I'm trying to get to is if it isn't always incorrect, what is the trigger to make it incorrect?

What puzzles me is your logs clearly say:

updating path ${IMAGE_ROOTFS}/etc/ld.so.conf to dev 65025, ino 20469339

which would come from pdb_update_inode() in pseudo.

That is doing an "UPDATE files SET dev = ?, ino = ?  WHERE path = ?;" which should have changed any reference to that path to the new inode.

and yet:

# $ sqlite3 ${WORKDIR}/pseudo/files.db 'select * from files where path like "%ld.so.conf"'
# 77|${IMAGE_ROOTFS}/etc/ld.so.conf|65025|20469387|0|0|33188|0|0

so this doesn't make any sense. The cut down logs are good but also mean it is hard to know what is going on here. There is something happening that shouldn't be but what, I don't know. I'm going to need to be able to reproduce this.

I've tried for several hours to reproduce this with docker and your reproducer but couldn't make it happen unfortunately. Not sure what to do now.

(In reply to comment #9)
> I've tried for several hours to reproduce this with docker and your
> reproducer but couldn't make it happen unfortunately. Not sure what to do
> now.

Hi again and thanks for trying. I myself had a hard time understanding how to reproduce this in isolation, what could go wrong in the prelink step so that this is occurring. Outside of the mv, there is not much, unless the prelink executable actually does something funny. Even tough I am able to reproduce the issue systematically with the private project using the crops docker run from 2 distinct pcs, a colleague told me he failed to reproduce. Could it have something to do with the level of parallelism, some hw specific feature or even the particular docker host computer, it is hard to tell.

It is indeed odd that this is occurring. It really looks like a race condition. However, I can't see how that is possible as the pseudo server seems to handle client message sequentially. And as you say, the "updating path" log appear to tell us the update was successful. Would the `sqlite3_step` function return something else than `SQLITE_DONE` if no entry with path found? I do not know.

Let me see if I couldn't fatten up the layer next week or the next to bring it closer to the private project and make it systematically reproducible using it.

I think I worked out what is going on here.

Firstly, whilst I never did see your failure, I could see that the inode of the ld.so.conf file didn't match that in the pseudo database. I also found if I printed the inode of the file, it matched that on disk.

This reminded me of an issue someone else ran into with docker a while ago. The issue is docker shuts down instantly when the command completes. If there is a pseudo database server left in memory that hasn't flushed to disk, it is destroyed and never does. The symptoms here are exactly that - the data isn't flushed to disk and the last changes are lost.

To test, I did:

diff --git a/bitbake/lib/bb/ui/knotty.py b/bitbake/lib/bb/ui/knotty.py
index 0efa614dfc..524731c7ab 100644
--- a/bitbake/lib/bb/ui/knotty.py
+++ b/bitbake/lib/bb/ui/knotty.py
@@ -729,6 +729,9 @@ def main(server, eventHandler, params, tf = TerminalFilter):
                 main.shutdown = 2
                 continue
             if isinstance(event, (bb.command.CommandCompleted, bb.cooker.CookerExit)):
+                print("Shutdown sleep")
+                time.sleep(40)
+                print("Sleep over")
                 main.shutdown = 2
                 continue
             if isinstance(event, bb.event.MultipleProviders):


which puts a 40s sleep into the shutdown path of the UI. The timeout in pseudo for server shutdown is 30s.

Once I did this, I don't see the inode corruption. I'm therefore pretty sure the issue is docker terminating the session before pseudo writes it's db.

FWIW there is code in pyrex for handling the process shutdown:

https://github.com/JoshuaWatt/pyrex/blob/master/image/cleanup.py

Created attachment 4833 [details]
Better pseudo shutdown patch

This patch seems to address the issue too

(In reply to comment #11)
> I think I worked out what is going on here.
> 
> Firstly, whilst I never did see your failure, I could see that the inode of
> the ld.so.conf file didn't match that in the pseudo database. I also found
> if I printed the inode of the file, it matched that on disk.
> 
> This reminded me of an issue someone else ran into with docker a while ago.
> The issue is docker shuts down instantly when the command completes. If
> there is a pseudo database server left in memory that hasn't flushed to
> disk, it is destroyed and never does. The symptoms here are exactly that -
> the data isn't flushed to disk and the last changes are lost.
> 
> To test, I did:
> 
> diff --git a/bitbake/lib/bb/ui/knotty.py b/bitbake/lib/bb/ui/knotty.py
> index 0efa614dfc..524731c7ab 100644
> --- a/bitbake/lib/bb/ui/knotty.py
> +++ b/bitbake/lib/bb/ui/knotty.py
> @@ -729,6 +729,9 @@ def main(server, eventHandler, params, tf =
> TerminalFilter):
>                  main.shutdown = 2
>                  continue
>              if isinstance(event, (bb.command.CommandCompleted,
> bb.cooker.CookerExit)):
> +                print("Shutdown sleep")
> +                time.sleep(40)
> +                print("Sleep over")
>                  main.shutdown = 2
>                  continue
>              if isinstance(event, bb.event.MultipleProviders):
> 
> 
> which puts a 40s sleep into the shutdown path of the UI. The timeout in
> pseudo for server shutdown is 30s.
> 
> Once I did this, I don't see the inode corruption. I'm therefore pretty sure
> the issue is docker terminating the session before pseudo writes it's db.
> 
> FWIW there is code in pyrex for handling the process shutdown:
> 
> https://github.com/JoshuaWatt/pyrex/blob/master/image/cleanup.py

Oh, you're quick ;) That would make a great lot of sense.

This definitely might happens to those launching their build in CIs through the docker crops (increment builds).

Now that I know what really is the cause of the problem, I will be able to work around it with some sleep like the one you refer to.

However, it seems wrong to me that we're leaving such an important job as a dangling background process running unmonitored / untracked by any bitbake task.

Is there already an issue whose goal it to fix the issue at pseudo use site (in yocto poky metadata)? It seems to me this is not really a pseudo issue not a crops docker issue but rather a build system one. 

This automatically detached server pseudo instance implicitly launched by the pseudo client (or the ld preload lib) is something that bit me and so I had to deal with this when I attempted to design some helpers for my pseudo python automated tests. I observed it as a locked sqlite3 db error when running a batch of tests (each with a different working dir under a new pytest temp dir) as soon as I attempted to load the db in order to compare those with the filesystem (see <https://github.com/amotus/oe-pseudo-test-env/blob/master/tests/test_600_pseudo_cmd_case.py#L76>). This is what led me to explicitly launch the server in the foreground `-f` (see <(see <https://github.com/amotus/oe-pseudo-test-env/blob/master/test_lib/pseudo.py#L298>)>) so that I had the opportunity to shut it down once my client was done with a particular bash script.

A potential idea for a fix (rough):

Pseudo part:
------------

Add a flag or env var to the pseudo client indicating it that instead of launching the server implicitly / automatically it should systematically fail with an explanatory error if a proper server instance does not exists.

Pseudo build system might possibly offer a flag to inject a default value for this flag at config / build time (this might be used by pseudo yocto package).

The above flag would also be nice for user that intend to run (for some reason) the pseudo server as a systemd service so that the client can be used on their system for testing purposes, etc.


Yocto / poky part:
-----------------

Yocto metadata explicitly launch the server in foreground as a special monitored build task automatically started once the first time pseudo is required by a task and explicitly terminated once we're done with the image generation (an image completed hook or something else).

The above flag or env is used for the pseudo client runs so that is is no longer possible for this dangling un-managed pseudo server process to be launched inadvertently.

This way, the bitbake ui will only exit once pseudo server is really done with its job.

(In reply to comment #13)
> Now that I know what really is the cause of the problem, I will be able to
> work around it with some sleep like the one you refer to.
> 
> However, it seems wrong to me that we're leaving such an important job as a
> dangling background process running unmonitored / untracked by any bitbake
> task.
>
> Is there already an issue whose goal it to fix the issue at pseudo use site
> (in yocto poky metadata)? It seems to me this is not really a pseudo issue
> not a crops docker issue but rather a build system one. 

Keep in mind these background processes have sigterm and at atexit handlers and are designed to shut down gracefully. The docker container model however just kills them outright with no chance to shut down gracefully. I consider that rather poor on docker's part.

That said, we probably need to deal with it. There is no open issue for it.

> This automatically detached server pseudo instance implicitly launched by
> the pseudo client (or the ld preload lib) is something that bit me and so I
> had to deal with this when I attempted to design some helpers for my pseudo
> python automated tests. I observed it as a locked sqlite3 db error when
> running a batch of tests (each with a different working dir under a new
> pytest temp dir) as soon as I attempted to load the db in order to compare
> those with the filesystem (see
> <https://github.com/amotus/oe-pseudo-test-env/blob/master/tests/
> test_600_pseudo_cmd_case.py#L76>). This is what led me to explicitly launch
> the server in the foreground `-f` (see <(see
> <https://github.com/amotus/oe-pseudo-test-env/blob/master/test_lib/pseudo.
> py#L298>)>) so that I had the opportunity to shut it down once my client was
> done with a particular bash script.
> 
> A potential idea for a fix (rough):
> 
> Pseudo part:
> ------------
> 
> Add a flag or env var to the pseudo client indicating it that instead of
> launching the server implicitly / automatically it should systematically
> fail with an explanatory error if a proper server instance does not exists.
> 
> Pseudo build system might possibly offer a flag to inject a default value
> for this flag at config / build time (this might be used by pseudo yocto
> package).
> 
> The above flag would also be nice for user that intend to run (for some
> reason) the pseudo server as a systemd service so that the client can be
> used on their system for testing purposes, etc.
> 
> 
> Yocto / poky part:
> -----------------
> 
> Yocto metadata explicitly launch the server in foreground as a special
> monitored build task automatically started once the first time pseudo is
> required by a task and explicitly terminated once we're done with the image
> generation (an image completed hook or something else).
> 
> The above flag or env is used for the pseudo client runs so that is is no
> longer possible for this dangling un-managed pseudo server process to be
> launched inadvertently.
> 
> This way, the bitbake ui will only exit once pseudo server is really done
> with its job.

I did post a patch earlier (attached to this bug) which:

a) sends a shutdown event to pseudo through it's existing -S option at task exit time
b) upon receipt of a shutdown event, even if it can't due to existing processes, flush the database

This should be good enough to solve the issues whilst being a relatively simple change.

> > Is there already an issue whose goal it to fix the issue at pseudo use site
> > (in yocto poky metadata)? It seems to me this is not really a pseudo issue
> > not a crops docker issue but rather a build system one. 
> 
> Keep in mind these background processes have sigterm and at atexit handlers
> and are designed to shut down gracefully. The docker container model however
> just kills them outright with no chance to shut down gracefully. I consider
> that rather poor on docker's part.
> 
> That said, we probably need to deal with it. There is no open issue for it.

I agree that what docker does seems abusive / agressive.

However, I also think that it is not right that bitbake cli ui exit leaving dangling processes behind when the job is not done. I would assume that when bitbake cli ui exits, my build is really done and that I have no manual cleanup to do by myself.

>
> I did post a patch earlier (attached to this bug) which:
> 
> a) sends a shutdown event to pseudo through it's existing -S option at task
> exit time
> b) upon receipt of a shutdown event, even if it can't due to existing
> processes, flush the database
> 
> This should be good enough to solve the issues whilst being a relatively
> simple change.

Ok, just I just saw that. It seems like good and simple idea. I will try to work with it for a while and confirm it fixes the issue.

Just for reference, pseudo's server does the double fork dance to "escape" all process tracking from bitbake btw as bitbake does try and wait for and clean up any processes left running that it knows about. There is little bitbake itself can do if subprocesses choose to do that.

I've sent the patches out for wider review.

http://git.yoctoproject.org/cgit.cgi/poky/commit/?id=eab1c2087fd37af7b64c25545a7f39ccd2e607de
http://git.yoctoproject.org/cgit.cgi/poky/commit/?id=a6f6bcb9db22d4fd47f904c6e8ee3cd98294fcec

The patch here needed some tweaks but merged as above.

(In reply to comment #16 and comment #17)
> Just for reference, pseudo's server does the double fork dance to "escape"
> all process tracking from bitbake btw as bitbake does try and wait for and
> clean up any processes left running that it knows about. There is little
> bitbake itself can do if subprocesses choose to do that.
> 

Ok. It seems alright to me that we do that now that we decided to take an approach in which the bitbake worker logic takes the explicit responsibility to manage the pseudo server resource, ensuring it timely / graceful termination.

> I've sent the patches out for wider review.

# .. comment #17
> The patch here needed some tweaks but merged as above.

I took a look at both patches you sent including what was done in pseudo oe branch.

I have a couple of question / comments:

 1. For the pseudo changes, I now understands that pseudo uses the in-memory db config option by default which explains why we had in issue in the first place (I was wondering how exactly it was possible for the log to say something different from the db as I tough we were directly writing to the file backed db). I can see that we now force a backup of the in-memory db to the actual file when a shutdown request is made by the client (the `pseudo -S` we now send from the bitbake worker logic). This seems alright to me.

 2.  However, looking at ln290 of new `bitbake/bin/bitbake-worker` version (<http://git.yoctoproject.org/cgit.cgi/poky/tree/bitbake/bin/bitbake-worker?id=eab1c2087fd37af7b64c25545a7f39ccd2e607de#n290>):

```py
ret = bb.build.exec_task(fn, taskname, the_data, cfg.profile)
if fakeroot:
    fakerootcmd = shlex.split(the_data.getVar("FAKEROOTCMD"))
    subprocess.run(fakerootcmd + ['-S'], check=True, stdout=subprocess.PIPE)
return ret
```

what if `bb.build.exec_task` raise an exception? What kind of exception can it raise? Will it raise on `Ctrl+c` or other mean of interrupting bitbake?

Wouldn't it be better using a finally clause so that we always ensure proper cleanup?, graceful pseudo termination Something like:

```py
try:
    ret = bb.build.exec_task(fn, taskname, the_data, cfg.profile)
finally:
    if fakeroot:
        fakerootcmd = shlex.split(the_data.getVar("FAKEROOTCMD"))
        subprocess.run(fakerootcmd + ['-S'], check=True, stdout=subprocess.PIPE)
return ret
```

Any reason why not to do this?

 3. Any plan to backport these to the `hardknott` branch? We made ourself a backport of the fix on top of current hardknott changeset at <https://github.com/amotus/poky/tree/amotus/hardknott-w-14555-fix-backport>. I think it would be warranted : it would clearly make our update / upgrade path easier but more importantly would prevent other people project being bit by this issue. What do you think?

By the way, thanks for promptly looking into this issue. We're positively surprised at the level of expertise / support.

Created attachment 4834 [details]
20210930 - Bug still reproducible after applying patch when Ctrl+c during rootfs creation

(In reply to comment #20)
> Created attachment 4834 [details]
> 20210930 - Bug still reproducible after applying patch when Ctrl+c during
> rootfs creation

Hi again,

I confirm that I was unable to reproduce the issue again under normal build circumstances.

However, as I was a bit worried about item \#2 from comment <https://bugzilla.yoctoproject.org/show_bug.cgi?id=14555#c18>, I decided to see what would occurs were I to abort the build using Ctrl+c (twice) during rootfs building phase. I found this path still lead to the issue. You can see the anonymized log at: 

<https://bugzilla.yoctoproject.org/attachment.cgi?id=4834>

Re-opening. See <https://bugzilla.yoctoproject.org/show_bug.cgi?id=14555#c21>.

(In reply to comment #18)
> (In reply to comment #16 and comment #17)
> 
>  2.  However, looking at ln290 of new `bitbake/bin/bitbake-worker` version
> (<http://git.yoctoproject.org/cgit.cgi/poky/tree/bitbake/bin/bitbake-
> worker?id=eab1c2087fd37af7b64c25545a7f39ccd2e607de#n290>):
> 
> ```py
> ret = bb.build.exec_task(fn, taskname, the_data, cfg.profile)
> if fakeroot:
>     fakerootcmd = shlex.split(the_data.getVar("FAKEROOTCMD"))
>     subprocess.run(fakerootcmd + ['-S'], check=True, stdout=subprocess.PIPE)
> return ret
> ```
> 
> what if `bb.build.exec_task` raise an exception? What kind of exception can
> it raise? Will it raise on `Ctrl+c` or other mean of interrupting bitbake?
> 
> Wouldn't it be better using a finally clause so that we always ensure proper
> cleanup?, graceful pseudo termination Something like:
> 
> ```py
> try:
>     ret = bb.build.exec_task(fn, taskname, the_data, cfg.profile)
> finally:
>     if fakeroot:
>         fakerootcmd = shlex.split(the_data.getVar("FAKEROOTCMD"))
>         subprocess.run(fakerootcmd + ['-S'], check=True,
> stdout=subprocess.PIPE)
> return ret
> ```
> 
> Any reason why not to do this?

I just wasn't really thinking of that particular case. In Ctrl+C'd builds, bitbake does intercept the first one and allow tasks to finish gracefully so you'd have to have hit it multiple times which can generally leave things in a bad state outside of bitbake's control.

I'd accept a patch to tweak this, or I can look at sorting one out.

>  3. Any plan to backport these to the `hardknott` branch? We made ourself a
> backport of the fix on top of current hardknott changeset at
> <https://github.com/amotus/poky/tree/amotus/hardknott-w-14555-fix-backport>.
> I think it would be warranted : it would clearly make our update / upgrade
> path easier but more importantly would prevent other people project being
> bit by this issue. What do you think?

We'd need to discuss it with the hardknott stable maintainer but I think this should be ok. We do let changes like this settle a little to check for regressions or other issues (such as your 2 above).

I've sent out a patch handling this with a try/finally clause.

(In reply to comment #24)
> I've sent out a patch handling this with a try/finally clause.

Hi, I am having trouble finding the patch. Looked in `master` branch and mailing lists. Can you add a ref to it?

(In reply to comment #25)
> (In reply to comment #24)
> > I've sent out a patch handling this with a try/finally clause.
> 
> Hi, I am having trouble finding the patch. Looked in `master` branch and
> mailing lists. Can you add a ref to it?

Ah, alright, I just found it, I was not looking at the right mailing list. Here's the ref: <https://lists.openembedded.org/g/bitbake-devel/topic/patch_2_2_bitbake_worker/86144117>.

I will be using it for a while, see how it behaves.

(In reply to comment #26)
> (In reply to comment #25)
> > (In reply to comment #24)
> > > I've sent out a patch handling this with a try/finally clause.
> > 
> > Hi, I am having trouble finding the patch. Looked in `master` branch and
> > mailing lists. Can you add a ref to it?
> 
> Ah, alright, I just found it, I was not looking at the right mailing list.
> Here's the ref:
> <https://lists.openembedded.org/g/bitbake-devel/topic/
> patch_2_2_bitbake_worker/86144117>.
> 
> I will be using it for a while, see how it behaves.

Single ctrl+c case is working fine. I think it already was before this patch.

However, it systematically fails when using ctlr+c twice during rootfs or image generation phases. And this, even tough I do it from inside the docker env and remain there afterward. So this case clearly affect everyone, not only the docker cmd immediate exit case.

I am a bit puzzled why the finally clause never gets executed. It is as if the worker process is killed with the wrong signal. From experience with our internal projects, I know that python natively support stack unwinding on SIGINT. It however does not automatically behave as well for other signal without manual intervention.

I would suggest that on second ctrl+c an attempt to terminate the worker using SIGINT (the same signal as sent by user to the client) be first made. Attempt to use other non natively/cleanly supported signals should only be made on subsequent ctrl+c. This way, worker python code would be given an opportunity for cleanup while still interrupting ongoing task immediately. This is a more gradual approach then immediately resorting to unclean termination.

What do you think?

(In reply to comment #27)
> (In reply to comment #26)
> > (In reply to comment #25)
> > > (In reply to comment #24)
> > > > I've sent out a patch handling this with a try/finally clause.
> > > 
> > > Hi, I am having trouble finding the patch. Looked in `master` branch and
> > > mailing lists. Can you add a ref to it?
> > 
> > Ah, alright, I just found it, I was not looking at the right mailing list.
> > Here's the ref:
> > <https://lists.openembedded.org/g/bitbake-devel/topic/
> > patch_2_2_bitbake_worker/86144117>.
> > 
> > I will be using it for a while, see how it behaves.
> 
> Single ctrl+c case is working fine. I think it already was before this patch.
> 
> However, it systematically fails when using ctlr+c twice during rootfs or
> image generation phases. And this, even tough I do it from inside the docker
> env and remain there afterward. So this case clearly affect everyone, not
> only the docker cmd immediate exit case.
> 
> I am a bit puzzled why the finally clause never gets executed. It is as if
> the worker process is killed with the wrong signal. From experience with our
> internal projects, I know that python natively support stack unwinding on
> SIGINT. It however does not automatically behave as well for other signal
> without manual intervention.
> 
> I would suggest that on second ctrl+c an attempt to terminate the worker
> using SIGINT (the same signal as sent by user to the client) be first made.
> Attempt to use other non natively/cleanly supported signals should only be
> made on subsequent ctrl+c. This way, worker python code would be given an
> opportunity for cleanup while still interrupting ongoing task immediately.
> This is a more gradual approach then immediately resorting to unclean
> termination.
> 
> What do you think?

I think there are a lot of other ways builds killed with double Ctrl+C can end up broken unrelated to pseudo such as partially written files. I wouldn't recommend doing that and if you do, you'd expect to have to clean up the workdir. As such I'm not sure I think it is worth complicating the code further.

(In reply to comment #28)
> I think there are a lot of other ways builds killed with double Ctrl+C can
> end up broken unrelated to pseudo such as partially written files. I
> wouldn't recommend doing that and if you do, you'd expect to have to clean
> up the workdir. As such I'm not sure I think it is worth complicating the
> code further.

That seems like a defensible position.

It might be a good idea to doc this design decision (if not already so) so that user can be referred to it as it now almost becomes a certitude that the build is broken on ctrl+c twice when interrupting a build worker using pseudo.

Marking this as resolved fixed for us.