| Summary: | pseudo connection startup/rework | ||||||
|---|---|---|---|---|---|---|---|
| Product: | [Yocto Project Subprojects] Pseudo | Reporter: | Richard Purdie <richard.purdie> | ||||
| Component: | pseudo | Assignee: | Joshua Lock <joshuagloe> | ||||
| Status: | RESOLVED FIXED | QA Contact: | Francisco Pedraza <francisco.j.pedraza.gonzalez> | ||||
| Severity: | enhancement | ||||||
| Priority: | High | CC: | jose.perez.carranza, mark.hatle, randy.macleod, seebs, sgw, yp.pseudo.watcher, yp.watcher | ||||
| Version: | master | ||||||
| Target Milestone: | 2.2 M2 | ||||||
| Hardware: | x86 | ||||||
| OS: | Multiple | ||||||
| Whiteboard: | |||||||
| OS type for building Yocto: | --- | Type of Regression: | --- | ||||
| Verified: | Documentation change: | No (bug/feature does not impact docs) | |||||
| Attachments: |
|
||||||
|
Description
Richard Purdie
2016-02-14 23:14:57 UTC
Nothing interesting in pseudo.log from this build. We've seen a second failure: https://autobuilder.yoctoproject.org/main/builders/nightly-x32/builds/634/steps/BuildImages/logs/stdio :( 8 more failures in a world build: https://autobuilder.yoctoproject.org/main/builders/nightly-world-lsb/builds/365/steps/BuildImages/logs/stdio and another in https://autobuilder.yoctoproject.org/main/builders/nightly-fsl-arm/builds/639/steps/BuildImages_2/logs/stdio Seebs generated a test version: http://git.yoctoproject.org/cgit/cgit.cgi/pseudo/log/?h=diagtests The top commit is the change: http://git.yoctoproject.org/cgit/cgit.cgi/pseudo/commit/?h=diagtests&id=732790277cd0af97179c2781a2208c016b07b04f This will print additional diagnostics prior to an abort. We just need to make sure that bitbake task engine will capture them before stopping. As discussed with Mark, we've been running builds with the logging patch he suggested in master-next. We've finally hit an issue with the logging enabled, https://autobuilder.yoctoproject.org/main/builders/nightly-world-lsb/builds/371/steps/BuildImages/logs/stdio. ERROR: Task 18438 (/home/pokybuild/yocto-autobuilder/yocto-worker/nightly-world-lsb/build/meta/recipes-kernel/cryptodev/cryptodev-tests_1.8.bb, do_package_write_ipk) failed with exit code '134' I'll attach the pseudo.log file but the relevant bit appears to be: pseudo: server connection persistently failed, aborting. path mismatch [2 links]: ino 683965864 db '/dev/shm/sem.mp21377-0' req '/dev/shm/NbrR1H'. try 0: client setup failed try 1: client setup failed try 2: client setup failed try 3: client setup failed try 4: client setup failed try 5: client setup failed try 6: client setup failed try 7: client setup failed try 8: client setup failed try 9: client setup failed try 10: client setup failed try 11: client setup failed try 12: client setup failed try 13: client setup failed try 14: client setup failed try 15: client setup failed try 16: client setup failed try 17: client setup failed try 18: client setup failed try 19: client setup failed try 20: client setup failed try 21: client setup failed try 22: client setup failed try 23: client setup failed try 24: client setup failed try 25: client setup failed try 26: client setup failed try 27: client setup failed try 28: client setup failed try 29: client setup failed try 30: client setup failed try 31: client setup failed try 32: client setup failed try 33: client setup failed try 34: client setup failed try 35: client setup failed try 36: client setup failed try 37: client setup failed try 38: client setup failed try 39: client setup failed try 40: client setup failed try 41: client setup failed try 42: client setup failed try 43: client setup failed try 44: client setup failed try 45: client setup failed try 46: client setup failed try 47: client setup failed try 48: client setup failed try 49: client thinks it started server path mismatch [2 links]: ino 683965866 db '/dev/shm/sem.mp21376-0' req '/dev/shm/gwQWxI'. Created attachment 2996 [details]
Pseudo log from failed build
Very similar to the last one but the last line is different. path mismatch [2 links]: ino 9750896768 db '/home/pokybuild/yocto-autobuilder/yocto-worker/nightly-deb-non-deb/build/build/tmp/work/i586-poky-linux/trace-cmd/2.6-r0/pkgdata/ runtime/trace-cmd' req '/home/pokybuild/yocto-autobuilder/yocto-worker/nightly-deb-non-deb/build/build/tmp/sysroots/qemux86/pkgdata/runtime/trace-cmd'. pseudo: server connection persistently failed, aborting. try 0: client setup failed try 1: client setup failed try 2: client setup failed try 3: client setup failed try 4: client setup failed try 5: client setup failed try 6: client setup failed try 7: client setup failed try 8: client setup failed try 9: client setup failed try 10: client setup failed try 11: client setup failed try 12: client setup failed try 13: client setup failed try 14: client setup failed try 15: client setup failed try 16: client setup failed try 17: client setup failed try 18: client setup failed try 19: client setup failed try 20: client setup failed try 21: client setup failed try 22: client setup failed try 23: client setup failed try 24: client setup failed try 25: client setup failed try 26: client setup failed try 27: client setup failed try 28: client setup failed try 29: client setup failed try 30: client setup failed try 31: client setup failed try 32: client setup failed try 33: client setup failed try 34: client setup failed try 35: client setup failed try 36: client setup failed try 37: client setup failed try 38: client setup failed try 39: client setup failed try 40: client setup failed try 41: client setup failed try 42: client setup failed try 43: client setup failed try 44: client setup failed try 45: client setup failed try 46: client setup failed try 47: client setup failed try 48: client setup failed try 49: client setup failed With the additional logging from Mark, we saw more failures overnight. These showed: pseudo: server connection persistently failed, aborting. try 0: couldn't find server at pid 22412: No such process Failed to connect to server 22412: No such file or directory try 1: couldn't find server at pid 22412: No such process Failed to connect to server 22412: No such file or directory try 2: couldn't find server at pid 22412: No such process Failed to connect to server 22412: No such file or directory try 3: couldn't find server at pid 22412: No such process Failed to connect to server 22412: No such file or directory [...] try 48: couldn't find server at pid 22412: No such process Failed to connect to server 22412: No such file or directory try 49: couldn't find server at pid 22412: No such process Failed to connect to server 22412: No such file or directory pseudo: server connection persistently failed, aborting. in the logs. The new logging failed on another build. I can't easily upload the log from my current location but basically, there was no difference that I can see in the failure logs, it shows the same pattern as the last one with no additional information. The extra logging therefore isn't telling us anything in addition to what we already knew. v If there is no additional logging, either the log messages aren't going out -- or the log file won't open or worse the exec itself failed (without logging that result). We may have to start monitoring the waitpid and use return codes or something to try to track this. I've hacked in my own logging patch on top of everything else, going to let that run overnight, see if we can get more info. I did finally get some data from the failure case with heavy locking. The server is repeatedly being started and logs: Last logs follow: Existing server has lock. Exiting. acquiring lock. opening lock. new pid: 29525 abscwd: </home/pokybuild/yocto-autobuilder/yocto-worker/nightly-world/build/build> getcwd okay: [/home/pokybuild/yocto-autobuilder/yocto-worker/nightly-world/build/build] 72 bytes getcwd: trying to find cwd. so it simply can't obtain the server lock. There are 10 log files like this of the server attempting to start and failing. The pids were: pokybuild@debian7:~$ less /home/pokybuild/yocto-autobuilder/yocto-worker/nightly-world/build/build/tmp/work/x86-pokymllib32-linux/lib32-gtk+/2.24.29-r0/pseudo/pseudo.log pseudo.log29427 pseudo.log29450 pseudo.log29469 pseudo.log29492 pseudo.log29514 pseudo.log29525 pseudo.log pseudo.log29430 pseudo.log29460 pseudo.log29482 pseudo.log29505 pseudo.log29522 and to get an idea of pids at the time of other task execution: pokybuild@debian7:~$ less /home/pokybuild/yocto-autobuilder/yocto-worker/nightly-world/build/build/tmp/work/x86-pokymllib32-linux/lib32-gtk+/2.24.29-r0/temp/log. log.do_compile log.do_install.18773 log.do_package_write_ipk log.do_populate_lic_setscene.10106 log.do_compile.28661 log.do_package log.do_package_write_ipk.29413 log.do_populate_sysroot log.do_configure log.do_package.13036 log.do_package_write_rpm log.do_populate_sysroot.10615 log.do_configure.10026 log.do_packagedata log.do_package_write_rpm.29535 log.do_unpack log.do_fetch log.do_packagedata.5467 log.do_patch log.do_unpack.30746 log.do_fetch.30469 log.do_package_qa log.do_patch.11410 log.task_order log.do_install log.do_package_qa.24099 log.do_populate_lic_setscene The pseudo.log itself shows: pseudo: server connection persistently failed, aborting. try 0: couldn't find server at pid 18786: No such process Failed to connect to server 18786: No such file or directory try 1: couldn't find server at pid 18786: No such process Failed to connect to server 18786: No such file or directory try 2: couldn't find server at pid 18786: No such process Failed to connect to server 18786: No such file or directory try 3: couldn't find server at pid 18786: No such process Failed to connect to server 18786: No such file or directory try 4: couldn't find server at pid 18786: No such process Failed to connect to server 18786: No such file or directory so it looks like the server would have been spawned by do_install (log.do_install.18773) since that is close to 18786. The backtrace of logs from the client (pseudo.log29427) was: couldn't get or spawn a server. wrapper completed: close returns 0 (errno: 2) close - yielded lock, restored signals close calling real syscall. close - signals blocked, obtaining lock wrapper called: close wrapper completed: fchdir returns 0 (errno: 2) fchdir - yielded lock, restored signals fchdir calling real syscall. fchdir - signals blocked, obtaining lock wrapper called: fchdir wrapper completed: close returns 0 (errno: 2) close - yielded lock, restored signals close calling real syscall. close - signals blocked, obtaining lock wrapper completed: open returns 33 (errno: 2) open - yielded lock, restored signals open calling real syscall. open - signals blocked, obtaining lock wrapper called: open So, when the old server is shutting down, it closes the socket file descriptor (which will cause ECONNREFUSED), and thet calls exit(). Which calls the database cleanup, which closes the file and log databases. But it also, if we're using MEMORY_DB, causes the backup, which dumps the file database to disk. And that could take non-trivial time, possibly. During that time, the lock is still held (which is right!), and you'll get ECONNREFUSED from the socket, and you can't start new servers. But. There's another part of this that's bugging me a lot, which is: I don't think there's any circumstance under which I would expect to see the "can't start server, aborting" message in pseudo.log. pseudo.log is only opened *in the server*, which should be running outside the pseudo environment. Which means it shouldn't be getting pseudo client error messages, I don't think. I've gotten as far as a reasonably usable event logger, with which I've added a lot of logging to the client setup, and cleaned up a couple of things which were, at the very least, making it less usable. (For instance, it now checks exit status of server, and won't read the pid file if it doesn't think the server got started.) With that, plus the server exiting status 1 if it can't get the lock, I see fewer obviously spurious messages in a log if I have a large delay on server shutdown. It might make sense to add timestamping to the cleanup_db code in pseudo_db.c, so we can record when it starts and when it finishes, and compare that with other logs, and also see whether it's running for a really long time. Also, worth considering: Disable the memory-db feature, see whether the problem goes away. It could be that the amount of time needed for that backup is significantly larger than we anticipated? Okay, so, there's now a seebs/evlog branch which has my initial event logging implementation, complete with fancy timestamping, and also adds server diagnostics for the database cleanup. If nothing else, just running with this and nothing fancy or special going on should result in us getting things in the server log that say something like: db cleanup for server shutdown, 16:36:31.985 memory-to-file backup complete, 16:36:31.985. db cleanup finished, 16:36:31.985 which shows that, on my system, it was using about 0ms to do those things. But if we had failures, and those showed longer times, that would be super informative. I've done some poking around, and reworked the startup code pretty thoroughly, and it's passing simple tests on my end anyway. Still in the seebs/evlog branch. The big difference is that, at this point, if you *can* reproduce the failures, we ought to get useful information about what's failing. Probably. The other big difference is I think it should be much, much, harder to get it to fail, because there were a couple of logic bugs and one very strange getenv/unsetenv behavior which were causing the server to try to connect to the server during its initial startup. At this point with the increased timeout values in the local patch applied to OE, we have stopped seeing any issues with this. It therefore does simply look like the delay needed to be of a particular level. I'm nervous about changing pseudo at this point in the release given the number of changes involved. I'm therefore calling this issue "done" as far as 2.1 goes and pushing the remaining work to 2.2. We can continue to use this bug for that, or open a new one, I don't have a strong preference. I would like to address some of the issues I found, because I did find things that would make the timeouts potentially an order of magnitude larger than they should need to be. But it can wait for next release, certainly. We have a recipe which upgrades to the latest ~1.8 pseudo release and fixes some of the issues identified within. This recipe and related changes are currently undergoing test and review. Upgraded to http://git.yoctoproject.org/cgit.cgi/poky/commit/?id=9df3cdf42d8c1216682f497f0b166a43ef9f4184 which includes the new startup changes. |