This looks like its coming from pseudo as exit 4 is a pseudo exit status :(

It does look like the retry logic is working and the build succeeds though so it is a transient issue rather than a fatal one...

Yeah, it should be retrying successfully, but it shouldn't be coming up at all, usually.

also, i still plan to be maintaining pseudo, so these should probably be assigned to me.

Also likely related are various timeout warnings, e.g. https://autobuilder.yoctoproject.org/main/builders/nightly-x86-64-lsb/builds/892/steps/BuildImages/logs/stdio

(grep for "Child process timeout after 2 seconds.")

I suspect there are a lot of these :(

Okay, so, this is *probably* harmless. Probably. But I want to try to look at it.

The big obvious question is: How easy is it to reproduce this on smallish systems or smallish builds? I don't have any 16-core and up monsters to play with at the moment.

It looks sort of odd, and this might indicate there's a logic flaw. I can't tell whether it's actually slowing things down, or just being chatty. Any idea whether similar builds are running faster or slower by significant amounts of wall clock time when this happens?

Note that as part of fixing this it would be great if pseudo would prefix these log messages with "pseudo" so it was clear where they were coming from.

Yes, we need to make sure the log entries are prefixed and see if there is any way to save to a logfile rather than spamming the console, assuming these are "harmless" rather than real problems which is I think the case.

The messages should probably go to stderr when invoking pseudo directly, but log file when invoking it from client. And a prefix wouldn't hurt, yeah.

(In reply to comment #9)
> The messages should probably go to stderr when invoking pseudo directly, but
> log file when invoking it from client. And a prefix wouldn't hurt, yeah.

Hi Peter,

Thanks, I will firstly add prefix and log it to pseudo.log, a better way might be  print to stderr and log it.

I'd want to review the ordering of the startup code, but it seems to me that the right thing would be to have something about the way the client starts the daemon to tell it to switch to using the log file before the fork/exec.

I *think* we fixed the loose ends on stderr usage, but I'm not 100% sure, so you might want to double-check that before sending anything to stderr. Long ago it was possible for that to result in sending debug messages out to client sockets. :P

So it turns out, I'm pretty sure we have a fix for this. The lock held thing is sort of a red herring. The actual problem is that a pseudo daemon takes too long to start up. Then:

(1) another attempt to start it fails, because lock_held.
(2) when the original daemon finally gets up and running, and tries to send its parent SIGUSR1, the original parent is dead so it sends that to init.
(3) dumbinit isn't as smart about signals as other things might be.

I've put in a patch (now in master) that should fix that part of this. Haven't done the diagnostic updates yet.

With Mark's additional patch to pseudo currently in OE-Core/Poky master, I just saw the lock_held message again so it does look to be from a different cause :(

The lock_held message isn't necessarily a sign of anything more severe than "took more than two seconds to start up".

The fix would prevent a thing where that would also have resulted in docker getting killed because dumbinit wasn't running as a different uid. It won't fix whatever's making startup so slow.

I suppose the obvious thing would be to do some timing checks and log a message about startup time.

(In reply to comment #14)
> The lock_held message isn't necessarily a sign of anything more severe than
> "took more than two seconds to start up".
> 
> The fix would prevent a thing where that would also have resulted in docker
> getting killed because dumbinit wasn't running as a different uid. It won't
> fix whatever's making startup so slow.
> 
> I suppose the obvious thing would be to do some timing checks and log a
> message about startup time.

Hi Peter,

Does the message printed by pseudo_diag() should go into pseudo.log or stdio/stderr, please ? It goes into pseudo.log currently.

Once pseudo.log is set up, it should *be* stderr for the pseudo daemon, I believe.

Right now, that is the first thing done after the fork in the daemon:

    pseudo_debug_logfile(PSEUDO_LOGFILE, 2);                                    

What we probably want is, when you're invoking pseudo from the command line directly, this should still happen only in the background daemon, but when the client starts pseudo, it should happen right away.

But pseudo from the command line actually just sets up the environment and then lets the exec'd command spawn the daemon. So I'm not actually sure how to distinguish the cases. The obvious thing would be to directly spawn the daemon before execing the child process, so it won't need to spawn one.

Note that this message can also result in the progress bar being duplicated for me. It shows "Child process exit status 4: lock_held" which is overwritten by task status and the progress bar is duplicated down one line.

Thanks Peter and Jonathan,

Yes, when run "bitbake foo", the pseudo_diag("Child process exited from signal...) goes into stderr. But when I do:
$ bitbake gnome-common -cdevshell
$ ls something

The messages such as pseudo_diag("path mismatch ...") goes into pseudo.log.

And when run pseudo in devshell:

$ pseudo ls

I got no output.

I think that I've figured out the reason, it is a race issue, there is a simple way to reproduce the problem:

# Kill all the pseudo process firstly
$ kill -9 `ps aux | grep usr/bin/pseud | awk '{print $2}'`
# Simulate the race issue
$ /buildarea/lyang1/test_gen/tmp/sysroots/x86_64-linux/usr/bin/pseudo & /buildarea/lyang1/test_gen/tmp/sysroots/x86_64-linux/usr/bin/pseudo

Then I can see the message "Child process exit status 4: lock_held"

If you don't run the two pseudo at the same time, everything is OK:
$ /buildarea/lyang1/test_gen/tmp/sysroots/x86_64-linux/usr/bin/pseudo
$ /buildarea/lyang1/test_gen/tmp/sysroots/x86_64-linux/usr/bin/pseudo

pseudo's rough work flow is:
Check if there is a pseudo daemon running via function connect(), if there is one (connect() returns OK), then go on running the client command, if not, then start the daemon process firstly (run pseudo -d), but pseudo doesn't allow two deamons running on the same localstatedir (database), then we will see the messages when the race issues happens: two process are starting at the same time, both of them can't find the daemon, then both of them will start a daemon, but only one can start.

It seems that we have the following solutions:
1) These messages are harmless, the daemon can't start but there is already one, so the second command still can get the correct info from the database, so we can choose not to fix the problem, and degrade the bug to low priority.
2) Try several times (e.g., 5) when connect()
3) Fix pseudo to not let these message go into terminal since they are harmless.

Please feel free to give your comments.

If this is what is happening, I'd suggest we put these messages into some log file or somewhere other than the main terminal window as they cause significant concern for the user. So doing nothing isn't an option, we need to a) prefix the messages with "pseudo: " so we know where they come from in future and b) hide the messages from the user somehow at the very least.

I agree, at a minimum those messages should be prefixed with a 'pseudo: ' label to make it clear where they are coming from.

Would be interesting to know if pseudo is properly recovering from this collision.  (It was originally designed to retry the child -- but I'm not sure if it is.)

We had added some messages to make it clear when the child couldn't be started to indicate a failure condition that we needed to investigate further.  This could be the sign of a real problem -- or it could be the error message isn't being suppressed on a successful retry.

(In reply to comment #21)
> I agree, at a minimum those messages should be prefixed with a 'pseudo: '
> label to make it clear where they are coming from.
> 
> Would be interesting to know if pseudo is properly recovering from this
> collision.  (It was originally designed to retry the child -- but I'm not
> sure if it is.)

Yes, it can recover in this case, we can see that directory bin and user are owned by "0 0".

$ export PSEUDO_LOCALSTATEDIR=/buildarea/lyang1/test_gen/tmp/work/all-poky-linux/gnome-common/3.18.0-r0/pseudo
$ kill -9 `ps aux | grep usr/bin/pseud | awk '{print $2}'` ; /buildarea/lyang1/test_gen/tmp/sysroots/x86_64-linux/usr/bin/pseudo & /buildarea/lyang1/test_gen/tmp/sysroots/x86_64-linux/usr/bin/pseudo ls -l /buildarea/lyang1/test_gen/tmp/work/all-poky-linux/gnome-common/3.18.0-r0/image/usr/
bash: kill: (29945) - No such process
[1] 29947
pseudo: Child process exit status 4: lock_held
total 8
drwxr-xr-x 2 0 0 4096 Sep 26 20:21 bin
drwxr-xr-x 3 0 0 4096 Sep 26 20:21 share


Sent patch to the mailing list, add prefix "pseudo: ", print the messages into pseudo.log:

http://cgit.openembedded.org/cgit.cgi/openembedded-core-contrib/log/?h=rbt/pseudo

// Robert
> 
> We had added some messages to make it clear when the child couldn't be
> started to indicate a failure condition that we needed to investigate
> further.  This could be the sign of a real problem -- or it could be the
> error message isn't being suppressed on a successful retry.

Merged into master:
http://git.openembedded.org/openembedded-core/commit/?id=efd0b0f604f9f498b9c20bc9a25708c493aa4f4a