14079 2020-10-07 19:21:04 +0000 Toaster fails to start a build with recent changes in when cookerdata is populated 2020-10-19 14:18:05 +0000 1 1 7 Build System, Metadata & Runtime BitBake bitbake 3.2 x86 Multiple RESOLVED FIXED High critical 3.2 M4 1 tim.orling tim.orling david.reyna poky.bs.watcher poky.watcher randy.e.witt randy.macleod richard.purdie --- Regression (Used to work) Don't know oldest_to_newest 88313 0 4735 tim.orling 2020-10-07 19:21:04 +0000 Created attachment 4735 toaster_ui.log In an effort to fix the CROPS toaster-container on current development (3.2) branch, we have uncovered a new failure mode that affects bare-metal Toaster as well. The system is that when toaster starts a build, it cannot server.getEventHandle: http://git.yoctoproject.org/cgit/cgit.cgi/poky/tree/bitbake/lib/bb/ui/toasterui.py#n148 which is because in the following, self.event_handle has not been set yet: http://git.yoctoproject.org/cgit/cgit.cgi/poky/tree/bitbake/lib/bb/server/xmlrpcserver.py#n122 The bitbake-cookerdaemon.log shows the XMLRPC server exits almost immediately (this does not seem to be affected by changing maxuitimeout: 37145 18:20:07.173656 --- Starting bitbake server pid 37145 at 2020-10-06 18:20:07.173617 --- 37145 18:20:07.186763 Started bitbake server pid 37145 37145 18:20:07.187053 Bitbake XMLRPC server address: 0.0.0.0, server port: 37331 37145 18:20:07.187270 Entering server connection loop XMLRPC Server triggering exit 37145 18:20:08.742198 Exiting 37145 18:20:08.742435 Original lockfile contents: ['37145 0.0.0.0:37331\n'] 37145 18:20:08.742707 Exiting as we could obtain the lock In toaster_ui.log traceback captured from a run, we see that cookerdata.CookerConfiguration() seems to be the root cause. Meaning that cookerdata has not yet been populated/instantiated. It helps to have a virtual environment setup. For instance: 0. pipenv install -r toaster-requirements.txt pipenv shell Steps to reproduce: 1. source poky/oe-init-build-env build-toaster 2. source toaster start webport=0.0.0.0:8000 3. Wait for the layers to be loaded from layer index and the "Successful Start" message 4. Launch browser pointed to http://0.0.0.0:8000 5. Click "New Project" button in upper right corner 6. Give project a name (e.g. "master"), use Yocto Project master for "Release" 7. Click "Create Project" You should be in the Project view 6. On the left click "Software Recipes" 7. In the search box, type "quilt-native" and click Search 8. On the openembedded-core first hit, click the "Build recipe" button on the right. It will clone, then say "Tasks starting" but never complete. cat ../build-toaster-2/toaster_ui.log (attached) 88314 1 tim.orling 2020-10-07 19:24:07 +0000 I meant to say "The symptom" in Comment 1 88315 2 tim.orling 2020-10-07 19:45:35 +0000 In Comment 1 I meant to say "maxuiwait" has no effect. Question: what are the units on maxuiwait? http://git.yoctoproject.org/cgit/cgit.cgi/poky/tree/bitbake/lib/bb/server/process.py#n56 I realize I did not change the default server_timeout. Question: what are the units on server_timeout? http://git.yoctoproject.org/cgit/cgit.cgi/poky/tree/bitbake/lib/bb/server/process.py#n66 http://git.yoctoproject.org/cgit/cgit.cgi/poky/tree/bitbake/lib/bb/server/xmlrpcclient.py#n44 But this would only matter if we have a race condition or a slow process in XMLRPC protocol. More likely the problem is elswhere? 88370 3 tim.orling 2020-10-12 13:00:29 +0000 The instrumentation I have so far is in this poky-contrib: http://git.yoctoproject.org/cgit/cgit.cgi/poky-contrib/log/?h=timo/fun-with-toaster-failures What I am working on now is using pdb or other debugging to try to step through and figure out what is happening. But TBH, we had a 3 day weekend and I brewed an Oatmeal Cream Stout. 88402 4 tim.orling 2020-10-16 06:40:22 +0000 With sufficient instrumentation, we determined that server.runCmd("setEventMask"... threw BBHandledException in cookerdata.parseBaseConfiguration. This was the hint that was needed to realize the system was trying to parse before the environment was setup. RP figured out that it was improper sequencing of events in toasterui. diff --git a/bitbake/lib/bb/ui/toasterui.py b/bitbake/lib/bb/ui/toasterui.py index 9260f5d9d7..ec5bd4f105 100644 --- a/bitbake/lib/bb/ui/toasterui.py +++ b/bitbake/lib/bb/ui/toasterui.py @@ -131,6 +131,10 @@ def main(server, eventHandler, params): helper = uihelper.BBUIHelper() + if not params.observe_only: + params.updateToServer(server, os.environ.copy()) + params.updateFromServer(server) + # TODO don't use log output to determine when bitbake has started # # WARNING: this log handler cannot be removed, as localhostbecontroller @@ -162,8 +166,6 @@ def main(server, eventHandler, params): logger.warning("buildstats is not enabled. Please enable INHERIT += \"buildstats\" to generate build statistics.") if not params.observe_only: - params.updateFromServer(server) - params.updateToServer(server, os.environ.copy()) cmdline = params.parseActions() if not cmdline: print("Nothing to do. Use 'bitbake world' to build everything, or run 'bitbake --help' for usage information.") 88403 5 tim.orling 2020-10-16 07:05:32 +0000 https://patchwork.openembedded.org/patch/177299/ https://lists.openembedded.org/g/bitbake-devel/message/11757 88429 6 tim.orling 2020-10-19 14:18:05 +0000 Merged: http://git.yoctoproject.org/cgit/cgit.cgi/poky/commit/?id=7cad26d585f67fa6bf873b8be361c6335a7db376 This fix also fixes CROPS toaster-container on "master". https://travis-ci.org/github/moto-timo/toaster-container/builds/736719631 4735 2020-10-07 19:21:04 +0000 2020-10-07 19:21:04 +0000 toaster_ui.log file_14079.txt text/plain 1200 tim.orling VHJhY2ViYWNrIChtb3N0IHJlY2VudCBjYWxsIGxhc3QpOg0KICBGaWxlICIvaG9tZS90dG9ybGlu Zy9Qcm9qZWN0cy9wb2t5L2JpdGJha2UvYmluL2JpdGJha2UiLCBsaW5lIDM2LCBpbiA8bW9kdWxl Pg0KICAgIGNvb2tlcmRhdGEuQ29va2VyQ29uZmlndXJhdGlvbigpKSkNCiAgRmlsZSAiL2hvbWUv dHRvcmxpbmcvUHJvamVjdHMvcG9reS9iaXRiYWtlL2xpYi9iYi9tYWluLnB5IiwgbGluZSAzODMs IGluIGJpdGJha2VfbWFpbg0KICAgIGNvbmZpZ1BhcmFtcykNCiAgRmlsZSAiL2hvbWUvdHRvcmxp bmcvUHJvamVjdHMvcG9reS9iaXRiYWtlL2xpYi9iYi91aS90b2FzdGVydWkucHkiLCBsaW5lIDE0 OCwgaW4gbWFpbg0KICAgIHJlc3VsdCwgZXJyb3IgPSBzZXJ2ZXIucnVuQ29tbWFuZChbInNldEV2 ZW50TWFzayIsIHNlcnZlci5nZXRFdmVudEhhbmRsZSgpLCBsbGV2ZWwsIGRlYnVnX2RvbWFpbnMs IF9ldnRfbGlzdF0pDQogIEZpbGUgIi91c3IvbGliL3B5dGhvbjMuNy94bWxycGMvY2xpZW50LnB5 IiwgbGluZSAxMTEyLCBpbiBfX2NhbGxfXw0KICAgIHJldHVybiBzZWxmLl9fc2VuZChzZWxmLl9f bmFtZSwgYXJncykNCiAgRmlsZSAiL3Vzci9saWIvcHl0aG9uMy43L3htbHJwYy9jbGllbnQucHki LCBsaW5lIDE0NTIsIGluIF9fcmVxdWVzdA0KICAgIHZlcmJvc2U9c2VsZi5fX3ZlcmJvc2UNCiAg RmlsZSAiL3Vzci9saWIvcHl0aG9uMy43L3htbHJwYy9jbGllbnQucHkiLCBsaW5lIDExNTQsIGlu IHJlcXVlc3QNCiAgICByZXR1cm4gc2VsZi5zaW5nbGVfcmVxdWVzdChob3N0LCBoYW5kbGVyLCBy ZXF1ZXN0X2JvZHksIHZlcmJvc2UpDQogIEZpbGUgIi91c3IvbGliL3B5dGhvbjMuNy94bWxycGMv Y2xpZW50LnB5IiwgbGluZSAxMTcwLCBpbiBzaW5nbGVfcmVxdWVzdA0KICAgIHJldHVybiBzZWxm LnBhcnNlX3Jlc3BvbnNlKHJlc3ApDQogIEZpbGUgIi91c3IvbGliL3B5dGhvbjMuNy94bWxycGMv Y2xpZW50LnB5IiwgbGluZSAxMzQyLCBpbiBwYXJzZV9yZXNwb25zZQ0KICAgIHJldHVybiB1LmNs b3NlKCkNCiAgRmlsZSAiL3Vzci9saWIvcHl0aG9uMy43L3htbHJwYy9jbGllbnQucHkiLCBsaW5l IDY1NiwgaW4gY2xvc2UNCiAgICByYWlzZSBGYXVsdCgqKnNlbGYuX3N0YWNrWzBdKQ0KeG1scnBj LmNsaWVudC5GYXVsdDogPEZhdWx0IDE6ICI8Y2xhc3MgJ2JiLkJCSGFuZGxlZEV4Y2VwdGlvbic+ OiI+