Created attachment 2961 [details] Logfile with PSEUDO_DEBUG=5 If I enable buildhistory with: INHERIT += "buildhistory" BUILDHISTORY_COMMIT = "1" and assuming you have multiple package backends enabled, deb, ipk, rpm, then bitbake adwaita-icon-theme then repeatedly bitbake adwaita-icon-theme -C package around 50% of the time, weirdness is seen in the buildhistory logs, for example: --- a/packages/all-poky-linux/adwaita-icon-theme/adwaita-icon-theme-cursors/files-in-package.txt +++ b/packages/all-poky-linux/adwaita-icon-theme/adwaita-icon-theme-cursors/files-in-package.txt @@ -1,5 +1,5 @@ -drwxr-xr-x root root 4096 ./usr -drwxr-xr-x root root 4096 ./usr/share +drwxr-xr-x 1000 tracing 4096 ./usr +drwxr-xr-x 1000 tracing 4096 ./usr/share Usually only the first 1-3 directories in one or more of the packages are affected and they change to the host system's user/group (1000, tracing) instead of (root, root). Sometimes it will get the correct permissions. If you manually load pseudo and look at the files in a shell (e.g. devshell) they are root, root. What is going on during this test? Basically, these files (in WORKDIR/packages-split/<pkgname>/) are wiped out under pseudo through do_package[cleandirs] and then recreated. After do_package, do_packageinfo runs in parallel with do_package_write_xxxx (for each package backend). The package_write functions read the data under packages-split/ and package/ through pseudo in its LD_PRELOAD form. do_packagedata runs several commands usder pseudo manually, e.g.: ( cd /media/build1/poky/build/tmp/work/all-poky-linux/adwaita-icon-theme/3.18.0-r0/packages-split/adwaita-icon-theme-cursors/ && PSEUDO_PREFIX=/media/build1/poky/build/tmp/sysroots/x86_64-linux/usr PSEUDO_LOCALSTATEDIR=/media/build1/poky/build/tmp/work/all-poky-linux/adwaita-icon-theme/3.18.0-r0/pseudo/ PSEUDO_PASSWD=/media/build1/poky/build/tmp/sysroots/qemux86-64:/media/build1/poky/build/tmp/sysroots/x86_64-linux PSEUDO_NOSYMLINKEXP=1 PSEUDO_DISABLED=0 /media/build1/poky/build/tmp/sysroots/x86_64-linux/usr/bin/pseudo find . ! -path . -printf "%M %-10u %-10g %10s %p -> %l\n" ) There is one of these run per package. Good news is that I ran this hacking PSEUDO_DEBUG=5 into the environment (hacking build.py exec_func) and the logs for this hint at the problem: 1454371225.58: 105878: close calling real syscall. 1454371225.58: 105878: close calling real syscall. 1454371225.58: 105878: close calling real syscall. 1454371225.58: 105878: setting up pseudo environment. 1454371225.58: 105878: calling execv on /media/build1/poky/build/tmp/sysroots/x86_64-linux/usr/bin/pseudo 1454371225.58: 105878: setting up pseudo environment. 1454371225.58: 105878: new pid: 105878 1454371225.58: 105873: read new pid file: 104791 1454371225.58: 105873: restarted, new pid 104791 1454371225.58: 105873: connecting socket... 1454371225.58: 105873: Can't connect socket to pseudo.socket: (Connection refused) 1454371225.58: 105873: couldn't get a server, giving up. 1454371225.58: 105873: (105873) no answer 1454371225.58: 105873: fcntl_dup: 5->4 1454371225.58: 105873: dup /media/build1/poky/build/tmp/work/all-poky-linux/adwaita-icon-theme/3.18.0-r0/packages-split/adwaita-icon-theme-cursors [fd 5]: dup: fd_path(5) = 0x1053a00 [/media/build1/poky/build/tmp/work/all-poky-linux/adwaita-icon-theme/3.18.0-r0/packages-split/adwaita-icon-theme-cursors], dup to 4 1454371225.58: 105873: (105873) (no request) 1454371225.58: 105873: found group gid 1000, name tracing 1454371225.58: 105873: openat /media/build1/poky/build/tmp/work/all-poky-linux/adwaita-icon-theme/3.18.0-r0/packages-split/adwaita-icon-theme-cursors/usr [fd 6] (+buf) [dev/ino: 2065/111396952] (040055): expanding fds from 6 to 7 1454371225.58: 105873: trying to get server 1454371225.58: 105873: connecting socket... 1454371225.58: 105873: Can't connect socket to pseudo.socket: (Connection refused) 1454371225.58: 105873: server seems to be gone, trying to restart 1454371225.58: 105873: spawned server, pid 105879 1454371225.58: 105873: setting up pseudo environment. 1454371225.58: 105879: new pid: 105879 1454371225.58: 105879: getcwd calling real syscall. 1454371225.58: 105879: new pid: 105879 1454371225.58: 105879: close calling real syscall. 1454371225.58: 105879: close calling real syscall. 1454371225.58: 105879: close calling real syscall. 1454371225.58: 105879: close calling real syscall. 1454371225.58: 105879: close calling real syscall. 1454371225.58: 105879: close calling real syscall. It returns "found group gid 1000, name tracing" which is wrong. When it did this, it appears to have tried and failed to connect to a pseudo server, or to start one. At the end of a "pseudo XXX" command it appears to trigger a server shutdown and it looks like there might be some kind of race around this. The server shouldn't be shutting down given the active use of pseudo by other processes (e.g. the do_package_write_xxx tasks). Rebuilds in existing builds seem much more likely to trigger this due to the tasks happening closer together and overlapping. I couldn't reproduce this with -C packagedata alone so it does look like its racing with the other tasks. I'll attach the full logs for the do_packagedata run.
Created attachment 2970 [details] Patch adding retry support Adding this patch fixes the issues I was seeing.
This looks very much like the newly running pseudo command can't start a server whilst the previous pseudo instance is still shutting down. Adding a retry loop to pseudo's client code, as in the attached patch does fix this issue.
Hmm. Indeed, it looks to me like the server shouldn't actually shut down if there's any active clients. It does set its timeout to be really short, but... hmm. And previously I've been unable to make it fail through things like this, because any client that can't reach the server should try to start one, and then whether or not it succeeds, it should retry, and try sending a message again. Hmm. So there may be a race here, but I'm not sure where. The obvious solution, I guess, would be to make the manual pseudo invocation only send a shutdown request if it started a new daemon, but it can't actually tell. ... Ah-hah! There's a path where it gives up without the retry. The logic in pseudo_client_request is probably wrong. So, new commit in master: 9e78667ea604fc0a8e538973973b48ae0741a8b2 This may, or may not, solve it. I suspect I want to think about this more, because the quick shutdown logic isn't really suited to this use case.
Huh, looks like similar logic. If you're seeing it get as far as 7 tries, it probably means that the shutdown needs to be significantly less aggressive. Come to think of it, I think right now I'm checking for a timeout BEFORE checking for new clients. I'll look at that more.
another commit, 2045939, should deal with at least some of the race condition. We were ignoring pending client connections if a shutdown message showed up.
Created attachment 2971 [details] Log file after two patches from master applied
(In reply to comment #5) > another commit, 2045939, should deal with at least some of the race > condition. We were ignoring pending client connections if a shutdown message > showed up. Whilst I'm not seeing the corruption with these patches, I am still seeing a lot of "couldn't get a server, giving up" and "Can't get server going again" which worry me. Would it not be wise to put some kind of retry into the client connection code in case of shutdown as well as the other fixes? To be clear, I did check the connection count and the way this example is working, the connection count *is* low and the server therefore does exit. Its just that it clearly takes time to exit (sync the DB?) and in that time, nothing can connect to the socket or get the lock for a new server to start.
Another way to think about this is to put a sleep in the shutdown code so that before the exit(0), there is a say usleep(2000). Two back to back "pseudo ls" commands would then likely show the problem.
Currently, the client *does* retry, I believe... But it retries immediately, which may not work if the server needs more time to shut down. So, what's in theory happening is, when we try to send a message, if something goes wrong, we try to attach to a server. And that will retry, but it'll give up after three tries. And the problem is, there's no retry interval, it just retries immediately. It probably ought to delay a little bit after trying to start a server, to see whether it can now either reach one successfully, or start one. (And because race condition, the delay probably ought to be somewhat variable, so multiple clients don't end up delaying the same amount of time.) So, yeah, that does indeed seem to be a thing. I've added a few ms of delay to the retry case, and that seems to work more reliably, as long as any delay used on the server side isn't *too* much larger. Added new patch to master. 8a75f99a652c362b64a14a11d4007690dc7f20d5
(In reply to comment #9) > Currently, the client *does* retry, I believe... But it retries immediately, > which may not work if the server needs more time to shut down. > > So, what's in theory happening is, when we try to send a message, if > something goes wrong, we try to attach to a server. And that will retry, but > it'll give up after three tries. And the problem is, there's no retry > interval, it just retries immediately. It probably ought to delay a little > bit after trying to start a server, to see whether it can now either reach > one successfully, or start one. (And because race condition, the delay > probably ought to be somewhat variable, so multiple clients don't end up > delaying the same amount of time.) > > So, yeah, that does indeed seem to be a thing. I've added a few ms of delay > to the retry case, and that seems to work more reliably, as long as any > delay used on the server side isn't *too* much larger. Added new patch to > master. > > 8a75f99a652c362b64a14a11d4007690dc7f20d5 Please could you have a look at the patch I attached here originally? I think that quite nicely handles several more corner cases here where the server is delayed, adding in several steps of retry and delay but only in the cases where trying without delay has caused an issue. I'd add that in testing I've now seen delays of 0.110s before the server could be started and connected to.
I did try 8a75f99a652c362b64a14a11d4007690dc7f20d5 and in my test case, it does hit 3 retries and prints "Can't get server going again" twice before then working. This means two requests did get dropped as far as I can tell and therefore the timeout code as is still isn't enough to stop missing requests and introducing a race window.
Yeah, I think you may be right that we need more retries. And .110s is a really long time, way larger than I thought I'd need to worry about! Hmm. *thinking* You know, a thing occurs to me. Just as an experiment, try taking out the pseudo_client_shutdown() from pseudo.c for the "run command from the command line" case, and see if the race condition goes away. If it does, it seems to me that one viable thing might be to make that contingent on stdout being a tty device -- the theory being that the behavior in question is primarily there for interactive use. Alternatively, I could set the timeout to be, say, several seconds, instead of one, just so it's less than 30. That said, I probably still need to think about the retry case more. Blah.
(In reply to comment #12) > Yeah, I think you may be right that we need more retries. And .110s is a > really long time, way larger than I thought I'd need to worry about! This is .110s on a pretty fast computer too, I suspect others can hit longer delays in the real world. > Hmm. > > *thinking* > > You know, a thing occurs to me. Just as an experiment, try taking out the > pseudo_client_shutdown() from pseudo.c for the "run command from the command > line" case, and see if the race condition goes away. I've tried something similar to this before, I'm 99% sure that would "solve" the problem too. This only happens due to the shutdown and then the restart that is needed. > If it does, it seems to me that one viable thing might be to make that > contingent on stdout being a tty device -- the theory being that the > behavior in question is primarily there for interactive use. > > Alternatively, I could set the timeout to be, say, several seconds, instead > of one, just so it's less than 30. > > That said, I probably still need to think about the retry case more. Blah. I think something around the 3s mark would probably work well, I picked 1s in my patch just as a seemingly reasonable amount compared to failure case I was seeing.
Okay, so, given that... I think maybe we should just (for now) patch out the shutdown-on-run-command. It was only there for command-line debugging. So maybe a local oe-core patch to just - pseudo_client_shutdown(); return WEXITSTATUS(rc); in pseudo.c. That should resolve it in the practical sense, and then I can come back for a more carefully-considered patch when I'm less behind on everything else. I'm sorta leaning towards something like if (isatty(1)) pseudo_client_shutdown(); but I'm not sure. (Also thinking about maybe just making it depend on opt_S, and then if I want to run a command and have pseudo exit immediately, I can "pseudo -S ls".)
d'oh. Rereading my client logic, yeah, it's broken. Your patch is closer to what I probably intended. There's a serious logic failure or three. (Among them, if the client tries to start a server, and meanwhile another client *successfully* starts a server, the client that can't now start one will fail in a bad way.) Gah. So I'm gonna rework that, yes. Not sure how long it will take. Might have something today.
f0d2cb7 may help. I reworked the retry logic significantly, and it should now handle the race condition much more gracefully, with multiple clients being smart enough to retry, and handling it okay if they can't start a server, but on retry it turns out that a server is available.
f0d2cb7..19cbd2f And now "pseudo <cmd>" will abort if <cmd> aborts. It wasn't checking for signal exits.
I am unable to reproduce the original problem with this latest version, even if I set the retry value down to '2'. If I set it to '1', I -always- get a failure.
As for the previous comment. The 'retry' define in the latest pseudo sources is how many times to run the loop. The loop attempts to talk to the server, and then starts a server if it failed, looping back to the top. So a '2' is as low as the number can effectively go to get the server started. Lowering the retry to '2' I was able to get occasional failures (this is what I was testing for). The failure rate was SIGNIFICANTLY lower then the failure rate of the previous version of pseudo. This lead to a fix for the buildhistory components, the fix was sent to the oe-core mailing list as an RFC. Moving the retry back to normal, I'm unable to reproduce any failure conditions.
One of the big problems in the original was that two different kinds of things were incrementing "tries", also I had a weird loop that was retrying a message send if it started the server, but... It was too complicated. So it's a lot simpler now. Submitted tarball and patch.
This was resolved with http://git.yoctoproject.org/cgit.cgi/poky/commit/?id=7cd835177ae0208859f790c0c638cde908386d5c and some of the subsequent tweaks.