Bug 11185

So unfortunately I can't get much from this - the actual parse failure wasn't displayed (which itself is a bug), and I can't reproduce the issue testing locally.

Are you able to reproduce this manually on the autobuilder, or otherwise provide me with any other information that would help me reproduce it?

Created attachment 3658 [details]
Devtool manual test

(In reply to comment #2)
> Created attachment 3658 [details]
> Devtool manual test

Hi, I tried manually in my pc and failed, this happens only in Ubuntu 16.04, all other OS passed the test.

Log attached.

I am not sure this is correct, your command is not correct and the output shows that the command did not run

Can you please confirm 14.04 vs 16.04, I tried 16.04 and it worked, I could not get it to fail on the direct run of devtool, only through oe-selftest.  I have been running it thought the crops/poky container

Created attachment 3660 [details]
Devtool tests fail log

(In reply to comment #4)
> I am not sure this is correct, your command is not correct and the output
> shows that the command did not run
> 
> Can you please confirm 14.04 vs 16.04, I tried 16.04 and it worked, I could
> not get it to fail on the direct run of devtool, only through oe-selftest. 
> I have been running it thought the crops/poky container

Hi, I attached a new log with the correct command, this executed in Ubuntu 16.04 in commit 6e20b31d5d17133e0fca086e12a0ad06ab5c4cc8, retested with commit 7e0985bab68547f946163828a16beab7542fca2e the test pass.

Wait a second - from your log:

/usr/local/bin/git-proxy: 18: exec: socat: not found

Is socat installed on the machine you're testing? Also, this doesn't look like the same error as the one in comment #1 on this bug.

I guess this could be related to the new HOSTTOOLS handling - socat is listed in HOSTTOOLS_NONFATAL, but maybe the HOSTTOOLS processing code isn't being run within devtool for some reason.

FWIW so far I've not been able to reproduce this issue in a container running Ubuntu 16.04. Saul reports that he can intermittently though.

exact command sequence to reproduce this?

When I tried it I simply did:

1) . ./oe-init-build-env

2) Edit local.conf, change MACHINE to "qemux86-64" - however perhaps I should have used "genericx86-64" since that's what Juan used)

3) bitbake core-image-minimal

4) oe-selftest -r devtool.DevtoolTests.test_devtool_add_fetch_git

Switched to genericx86-64 - still no failures.

Ok, I have been able to reproduce this with the crops/poky-ubuntu-16.04 container with a simple script that I have in my mounted poky clone.

#!/bin/sh

cd poky
rm -rf build

. ./oe-init-build-env $HOME/build

#oe-selftest -r devtool.DevtoolTests.test_devtool_add_fetch_git

devtool add mraa /tmp/devtoolqaip85n8ad/mraa -a -f  gitsm://git.yoctoproject.org/mraa

I see the clone of mraa occur and then get the following error:
ERROR:
ERROR: Parsing newly created recipe failed, moving recipe to /home/pokyuser/poky/build/workspace/recipes/mraa/mraa_git.bb.parsefailed for reference. If this looks to be caused by the recipe itself, please report this error.

If I move the parsefailed recipe to mraa_git.bb and try to bitbake -n mraa_git, it works correctly.

I have started to look at devtool's standard.py and where it calls tinfoil's parse_recipe_file() in order to see if there is more debugging I can do in tinfoil.

My setup:
Host= ubuntu:14.04 (hopefully irrelevant)
Container image:  crops/poky:ubuntu-14.04
"Id": "sha256:d499b0209cb31f77cdad1fb7e020a14b0e767cf50ea523a2cddd73c83f568d8c", from docker inspect crops/poky:ubuntu-14.04

1) . ./oe-init-build-env

2) Edit local.conf, change MACHINE to "qemux86-64" 

3) bitbake core-image-minimal

----
I then took the devtool add in the test apart and tried some variations
These worked:
devtool add   git://git.yoctoproject.org/mraa
devtool add mraa  gitsm://git.yoctoproject.org/mraa
devtool add mraa  /tmp/cowXX1234 -f gitsm://git.yoctoproject.org/mraa

This failed (this is what the test actually does...):
add mraa  /tmp/cowXX123x4 -a  -f gitsm://git.yoctoproject.org/mraa

----
I did a devtool reset mraa and  a manual rm -rf of the mraa-source between each variation .

So, it looks like it is having difficulty with the -a, at least on my setup.

Same error if I don't have a build/tmp and just do
 . poky/oe-init-buildenv 
followed by
devtool add mraa  /tmp/cowXX123x4 -a  -f gitsm://git.yoctoproject.org/mraa
in a fresh container.

Oh, I missed this hint from the previous errors, but noticed it when I started adding debugs.

There is an empty ERROR: line, turns out this is from the try/except section

rd = tinfoil.parse_recipe_file(recipefile, False)                                               logger.debug("parse returned: %s" %rd)
        except Exception as e:
            logger.error(str(e))

We are getting an empty Exception e from the parse_reciple_file(), this is helpful.

Not sure what I did, but I managed to get bitbake to become more verbose, I was adding logger debugs and then bitbake became more verbose, but I did get this on one of the failures:

                                                                      WARNING:BitBake.Main:Timeout while attempting to communicate with bitbake server          CRITICAL:BitBake.Main:Gave up; Too many tries: timeout while attempting to communicate with bitbake server

Created attachment 3667 [details]
Complete debug log

This is a complete debug log that I captured, like I said, not exactly sure how the addition of this code caused it to enable debugging:  I did also add the -d flag to devtool, but initially it only added debugging for devtool, it was not until I added this change that debugging enabled for all of bitbake!


diff --git a/bitbake/lib/bb/server/process.py b/bitbake/lib/bb/server/process.py          index c3c1450..61970c9 100644                                                             --- a/bitbake/lib/bb/server/process.py                                                    +++ b/bitbake/lib/bb/server/process.py                                                    @@ -45,7 +45,11 @@ class ServerCommunicator():                                                                                                                                           def runCommand(self, command):                                                                # @todo try/except                                                               -        self.connection.send(command)                                                    +        logging.debug("Process")                                                         +        try:                                                                             +            self.connection.send(command)
+        except Exception as err:
+            logging.warn("Process: %s" % err)
 
         if not self.server.is_alive():
             raise SystemExit

I've finally managed to reproduce this in a container on my own machine rather than a powerful server. Will try to debug.

So I now have a much clearer picture of what's going on. There are several  things at work here:

1) We're calling git ls-remote, but the code we use to do it ends up in a recursive loop, so it is called 30 times before it stops. I believe this is because of the code in runfetchcmd() which tries to prevent recursion - it does so by trying to simply get the value of PV, which is set to "${SRCPV}", which triggers runfetchcmd("git ls-remote ...") again. Surely there must be a more efficient way of doing this, but I don't yet have a fix.

2) Because we're doing ls-remote 30 times, it takes a while for the server to return from the parseRecipeFile RPC command, and the command times out. It actually times out three times with a warning before returning successfully on Fedora, but we don't see those warnings (see below). For whatever reason on Ubuntu it must be taking fractionally longer to do the git ls-remote operations and thus there it usually times out a fourth time and gives up.

3) bitbake logging on the *client* side isn't being handled within devtool, thus we don't see the timeout messages. Instead if it fails what we get is a BBHandledException with no text, since when the final timeout occurs we call bb.fatal() which logs the message and then raises BBHandledException(), and we don't see the log message. I have a patch to fix this, which will fix all tinfoil-using scripts and allow us to tidy up the code a bit for some of those scripts as well.

I've sent patches to the bitbake-devel list for both the recursion and the logging issues.

Those patches are merged in bitbake 824e73e0f3eaa96b4d84da7e31f9a17ce5c5d7ee.

Paul, does this mean the bug can be closed?

Yes - here's the list of fixes:

http://git.yoctoproject.org/cgit/cgit.cgi/poky/commit/?id=f41740ee8ee91a57f22ce7fa2a4b8ceeea78de0d
http://git.yoctoproject.org/cgit/cgit.cgi/poky/commit/?id=614cbeddc8f092bf2748ae7555d62467f3c45f16
http://git.yoctoproject.org/cgit/cgit.cgi/poky/commit/?id=542eb4731cd491c23e30689e5c8c0da91ba4bb44
http://git.yoctoproject.org/cgit/cgit.cgi/poky/commit/?id=8b1826e78a0dae1ffea84ec5128130d524ecf4b4

Unfortunately the logging fix did cause bug 11275, so we'll have to sort that out; ugly as that is though I prefer it to not logging errors at all.

Verified, in ccommit 415b72ffcbd26e5f3664370d8b2a9b8105fb6342

test_devtool_add_fetch_git (oeqa.selftest.devtool.DevtoolTests) ... OK (50.127s)