Bug 14079

Summary: Toaster fails to start a build with recent changes in when cookerdata is populated
Product: [Build System, Metadata & Runtime] BitBake Reporter: Tim Orling <tim.orling>
Component: bitbakeAssignee: Tim Orling <tim.orling>
Status: RESOLVED FIXED QA Contact:
Severity: critical    
Priority: High CC: david.reyna, poky.bs.watcher, poky.watcher, randy.e.witt, randy.macleod, richard.purdie
Version: 3.2   
Target Milestone: 3.2 M4   
Hardware: x86   
OS: Multiple   
Whiteboard:
OS type for building Yocto: --- Type of Regression: Regression (Used to work)
Verified: Documentation change: Don't know
Attachments:
Description Flags
toaster_ui.log none

Description Tim Orling 2020-10-07 19:21:04 UTC 
Created attachment 4735 [details]
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)
Comment 1 Tim Orling 2020-10-07 19:24:07 UTC 
I meant to say "The symptom" in Comment 1
Comment 2 Tim Orling 2020-10-07 19:45:35 UTC 
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?
Comment 3 Tim Orling 2020-10-12 13:00:29 UTC 
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.
Comment 4 Tim Orling 2020-10-16 06:40:22 UTC 
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.")