[PATCH 1/2] commands: send stderr to a new pipe

[PATCH 1/2] commands: send stderr to a new pipe

[leonardo.sandoval.gonzalez]

From: Leonardo Sandoval <leonardo.sandoval.gonzalez@linux.intel.com>

Do not mix the stderr into stdout, allowing test cases to query
the specific output.

[YOCTO #9693]

Signed-off-by: Leonardo Sandoval <leonardo.sandoval.gonzalez@linux.intel.com>
---
 meta/lib/oeqa/utils/commands.py | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/meta/lib/oeqa/utils/commands.py b/meta/lib/oeqa/utils/commands.py
index 57286fcb10..4ef0e874ff 100644
--- a/meta/lib/oeqa/utils/commands.py
+++ b/meta/lib/oeqa/utils/commands.py
@@ -29,7 +29,7 @@ class Command(object):
 
         self.defaultopts = {
             "stdout": subprocess.PIPE,
-            "stderr": subprocess.STDOUT,
+            "stderr": subprocess.PIPE,
             "stdin": None,
             "shell": False,
             "bufsize": -1,
-- 
2.12.0

[PATCH 2/2] selftest/cases: use stderr data when querying for errors

[leonardo.sandoval.gonzalez]

From: Leonardo Sandoval <leonardo.sandoval.gonzalez@linux.intel.com>

Error data is now placed on the result.error variable, thus
change relevant test cases to query the latter (instead of
stdout). Also a bit of refactor with a new file created on
with single function used by the selftest modules.

[YOCTO #9693]

Signed-off-by: Leonardo Sandoval <leonardo.sandoval.gonzalez@linux.intel.com>
---
 meta/lib/oeqa/selftest/cases/bbtests.py      | 24 +++++++++++-------------
 meta/lib/oeqa/selftest/cases/buildhistory.py |  6 +++---
 meta/lib/oeqa/selftest/cases/buildoptions.py | 21 +++++++++------------
 meta/lib/oeqa/selftest/cases/lic_checksum.py |  4 ++--
 meta/lib/oeqa/selftest/cases/pkgdata.py      | 16 ++++++++--------
 meta/lib/oeqa/selftest/cases/signing.py      |  2 +-
 meta/lib/oeqa/utils/commands.py              |  8 ++++----
 meta/lib/oeqa/utils/misc.py                  | 11 +++++++++++
 8 files changed, 49 insertions(+), 43 deletions(-)
 create mode 100644 meta/lib/oeqa/utils/misc.py

diff --git a/meta/lib/oeqa/selftest/cases/bbtests.py b/meta/lib/oeqa/selftest/cases/bbtests.py
index 4c82049032..f377de4996 100644
--- a/meta/lib/oeqa/selftest/cases/bbtests.py
+++ b/meta/lib/oeqa/selftest/cases/bbtests.py
@@ -3,17 +3,13 @@ import re
 
 import oeqa.utils.ftools as ftools
 from oeqa.utils.commands import runCmd, bitbake, get_bb_var, get_bb_vars
+from oeqa.utils.misc import getline
 
 from oeqa.selftest.case import OESelftestTestCase
 from oeqa.core.decorator.oeid import OETestID
 
 class BitbakeTests(OESelftestTestCase):
 
-    def getline(self, res, line):
-        for l in res.output.split('\n'):
-            if line in l:
-                return l
-
     @OETestID(789)
     def test_run_bitbake_from_dir_1(self):
         os.chdir(os.path.join(self.builddir, 'conf'))
@@ -46,13 +42,15 @@ class BitbakeTests(OESelftestTestCase):
 
     @OETestID(105)
     def test_bitbake_invalid_recipe(self):
-        result = bitbake('-b asdf', ignore_status=True)
-        self.assertTrue("ERROR: Unable to find any recipe file matching 'asdf'" in result.output, msg = "Though asdf recipe doesn't exist, bitbake didn't output any err. message. bitbake output: %s" % result.output)
+        invalid = 'asdf'
+        result = bitbake('-b %s' % invalid, ignore_status=True)
+        self.assertTrue("ERROR: Unable to find any recipe file matching '%s'" % invalid in result.error, msg = "Though %s recipe doesn't exist, bitbake didn't output any err. message. bitbake output: %s" % (invalid, result.error))
 
     @OETestID(107)
     def test_bitbake_invalid_target(self):
-        result = bitbake('asdf', ignore_status=True)
-        self.assertTrue("ERROR: Nothing PROVIDES 'asdf'" in result.output, msg = "Though no 'asdf' target exists, bitbake didn't output any err. message. bitbake output: %s" % result.output)
+        invalid = 'asdf'
+        result = bitbake(invalid, ignore_status=True)
+        self.assertTrue("ERROR: Nothing PROVIDES '%s'" % invalid in result.error, msg = "Though no '%s' target exists, bitbake didn't output any err. message. bitbake output: %s" % (invalid, result.error))
 
     @OETestID(106)
     def test_warnings_errors(self):
@@ -71,8 +69,8 @@ class BitbakeTests(OESelftestTestCase):
         result = bitbake('man -c patch', ignore_status=True)
         self.delete_recipeinc('man')
         bitbake('-cclean man')
-        line = self.getline(result, "Function failed: patch_do_patch")
-        self.assertTrue(line and line.startswith("ERROR:"), msg = "Repeated patch application didn't fail. bitbake output: %s" % result.output)
+        line = getline(result.error, "Function failed: patch_do_patch")
+        self.assertTrue(line and line.startswith("ERROR:"), msg = "Repeated patch application didn't fail. bitbake output: %s" % result.error)
 
     @OETestID(1354)
     def test_force_task_1(self):
@@ -144,9 +142,9 @@ INHERIT_remove = \"report-error\"
         bitbake('-ccleanall man')
         self.delete_recipeinc('man')
         self.assertEqual(result.status, 1, msg="Command succeded when it should have failed. bitbake output: %s" % result.output)
-        self.assertTrue('Fetcher failure: Unable to find file file://invalid anywhere. The paths that were searched were:' in result.output, msg = "\"invalid\" file \
+        self.assertTrue('Fetcher failure: Unable to find file file://invalid anywhere. The paths that were searched were:' in result.error, msg = "\"invalid\" file \
 doesn't exist, yet no error message encountered. bitbake output: %s" % result.output)
-        line = self.getline(result, 'Fetcher failure for URL: \'file://invalid\'. Unable to fetch URL from any source.')
+        line = getline(result.error, 'Fetcher failure for URL: \'file://invalid\'. Unable to fetch URL from any source.')
         self.assertTrue(line and line.startswith("ERROR:"), msg = "\"invalid\" file \
 doesn't exist, yet fetcher didn't report any error. bitbake output: %s" % result.output)
 
diff --git a/meta/lib/oeqa/selftest/cases/buildhistory.py b/meta/lib/oeqa/selftest/cases/buildhistory.py
index 06792d9146..2d28cefdcb 100644
--- a/meta/lib/oeqa/selftest/cases/buildhistory.py
+++ b/meta/lib/oeqa/selftest/cases/buildhistory.py
@@ -37,10 +37,10 @@ class BuildhistoryBase(OESelftestTestCase):
 
         if expect_error:
             self.assertEqual(result.status, 1, msg="Error expected for global config '%s' and target config '%s'" % (global_config, target_config))
-            search_for_error = re.search(error_regex, result.output)
-            self.assertTrue(search_for_error, msg="Could not find desired error in output: %s (%s)" % (error_regex, result.output))
+            search_for_error = re.search(error_regex, result.error)
+            self.assertTrue(search_for_error, msg="Could not find desired error in output: %s (%s)" % (error_regex, result.error))
         else:
-            self.assertEqual(result.status, 0, msg="Command 'bitbake %s' has failed unexpectedly: %s" % (target, result.output))
+            self.assertEqual(result.status, 0, msg="Command 'bitbake %s' has failed unexpectedly: %s" % (target, result.error))
 
     # No tests should be added to the base class.
     # Please create a new class that inherit this one, or use one of those already available for adding tests.
diff --git a/meta/lib/oeqa/selftest/cases/buildoptions.py b/meta/lib/oeqa/selftest/cases/buildoptions.py
index 1f1bb7ae63..bfb6ba339a 100644
--- a/meta/lib/oeqa/selftest/cases/buildoptions.py
+++ b/meta/lib/oeqa/selftest/cases/buildoptions.py
@@ -6,6 +6,7 @@ import tempfile
 from oeqa.selftest.case import OESelftestTestCase
 from oeqa.selftest.cases.buildhistory import BuildhistoryBase
 from oeqa.utils.commands import runCmd, bitbake, get_bb_var, get_bb_vars
+from oeqa.utils.misc import getline
 import oeqa.utils.ftools as ftools
 from oeqa.core.decorator.oeid import OETestID
 
@@ -58,21 +59,17 @@ class DiskMonTest(OESelftestTestCase):
     def test_stoptask_behavior(self):
         self.write_config('BB_DISKMON_DIRS = "STOPTASKS,${TMPDIR},100000G,100K"')
         res = bitbake("m4", ignore_status = True)
-        self.assertTrue('ERROR: No new tasks can be executed since the disk space monitor action is "STOPTASKS"!' in res.output, msg = "Tasks should have stopped. Disk monitor is set to STOPTASK: %s" % res.output)
-        self.assertEqual(res.status, 1, msg = "bitbake reported exit code %s. It should have been 1. Bitbake output: %s" % (str(res.status), res.output))
+        self.assertTrue('ERROR: No new tasks can be executed since the disk space monitor action is "STOPTASKS"!' in res.error, msg = "Tasks should have stopped. Disk monitor is set to STOPTASK: %s" % res.error)
+        self.assertEqual(res.status, 1, msg = "bitbake reported exit code %s. It should have been 1. Bitbake output: %s" % (str(res.status), res.error))
         self.write_config('BB_DISKMON_DIRS = "ABORT,${TMPDIR},100000G,100K"')
         res = bitbake("m4", ignore_status = True)
-        self.assertTrue('ERROR: Immediately abort since the disk space monitor action is "ABORT"!' in res.output, "Tasks should have been aborted immediatelly. Disk monitor is set to ABORT: %s" % res.output)
-        self.assertEqual(res.status, 1, msg = "bitbake reported exit code %s. It should have been 1. Bitbake output: %s" % (str(res.status), res.output))
+        self.assertTrue('ERROR: Immediately abort since the disk space monitor action is "ABORT"!' in res.error, "Tasks should have been aborted immediatelly. Disk monitor is set to ABORT: %s" % res.error)
+        self.assertEqual(res.status, 1, msg = "bitbake reported exit code %s. It should have been 1. Bitbake output: %s" % (str(res.status), res.error))
         self.write_config('BB_DISKMON_DIRS = "WARN,${TMPDIR},100000G,100K"')
         res = bitbake("m4")
         self.assertTrue('WARNING: The free space' in res.output, msg = "A warning should have been displayed for disk monitor is set to WARN: %s" %res.output)
 
 class SanityOptionsTest(OESelftestTestCase):
-    def getline(self, res, line):
-        for l in res.output.split('\n'):
-            if line in l:
-                return l
 
     @OETestID(927)
     def test_options_warnqa_errorqa_switch(self):
@@ -85,7 +82,7 @@ class SanityOptionsTest(OESelftestTestCase):
         self.add_command_to_tearDown('bitbake -c clean xcursor-transparent-theme')
         res = bitbake("xcursor-transparent-theme -f -c package", ignore_status=True)
         self.delete_recipeinc('xcursor-transparent-theme')
-        line = self.getline(res, "QA Issue: xcursor-transparent-theme-dbg is listed in PACKAGES multiple times, this leads to packaging errors.")
+        line = getline(res.error, "QA Issue: xcursor-transparent-theme-dbg is listed in PACKAGES multiple times, this leads to packaging errors.")
         self.assertTrue(line and line.startswith("ERROR:"), msg=res.output)
         self.assertEqual(res.status, 1, msg = "bitbake reported exit code %s. It should have been 1. Bitbake output: %s" % (str(res.status), res.output))
         self.write_recipeinc('xcursor-transparent-theme', 'PACKAGES += \"${PN}-dbg\"')
@@ -93,7 +90,7 @@ class SanityOptionsTest(OESelftestTestCase):
         self.append_config('WARN_QA_append = " packages-list"')
         res = bitbake("xcursor-transparent-theme -f -c package")
         self.delete_recipeinc('xcursor-transparent-theme')
-        line = self.getline(res, "QA Issue: xcursor-transparent-theme-dbg is listed in PACKAGES multiple times, this leads to packaging errors.")
+        line = getline(res.output, "QA Issue: xcursor-transparent-theme-dbg is listed in PACKAGES multiple times, this leads to packaging errors.")
         self.assertTrue(line and line.startswith("WARNING:"), msg=res.output)
 
     @OETestID(278)
@@ -102,7 +99,7 @@ class SanityOptionsTest(OESelftestTestCase):
 
         self.add_command_to_tearDown('bitbake -c clean gzip')
         res = bitbake("gzip -f -c package_qa")
-        line = self.getline(res, "QA Issue: gzip")
+        line = getline(res.output, "QA Issue: gzip")
         self.assertFalse(line, "WARNING: QA Issue: gzip message is present in bitbake's output and shouldn't be: %s" % res.output)
 
         self.append_config("""
@@ -111,7 +108,7 @@ do_install_append_pn-gzip () {
 }
 """)
         res = bitbake("gzip -f -c package_qa")
-        line = self.getline(res, "QA Issue: gzip")
+        line = getline(res.output, "QA Issue: gzip")
         self.assertTrue(line and line.startswith("WARNING:"), "WARNING: QA Issue: gzip message is not present in bitbake's output: %s" % res.output)
 
     @OETestID(1421)
diff --git a/meta/lib/oeqa/selftest/cases/lic_checksum.py b/meta/lib/oeqa/selftest/cases/lic_checksum.py
index 37407157c1..33bb47ac3a 100644
--- a/meta/lib/oeqa/selftest/cases/lic_checksum.py
+++ b/meta/lib/oeqa/selftest/cases/lic_checksum.py
@@ -31,5 +31,5 @@ SRC_URI = "file://%s;md5=d41d8cd98f00b204e9800998ecf8427e"
 
         self.write_config("INHERIT_remove = \"report-error\"")
         result = bitbake(bitbake_cmd, ignore_status=True)
-        if error_msg not in result.output:
-            raise AssertionError(result.output)
+        if error_msg not in result.error:
+            raise AssertionError(result.error)
diff --git a/meta/lib/oeqa/selftest/cases/pkgdata.py b/meta/lib/oeqa/selftest/cases/pkgdata.py
index 0b4caf1b2c..696fa7d5e2 100644
--- a/meta/lib/oeqa/selftest/cases/pkgdata.py
+++ b/meta/lib/oeqa/selftest/cases/pkgdata.py
@@ -23,16 +23,16 @@ class OePkgdataUtilTests(OESelftestTestCase):
         result = runCmd('oe-pkgdata-util lookup-pkg zlib-dev')
         self.assertEqual(result.output, 'libz-dev')
         result = runCmd('oe-pkgdata-util lookup-pkg nonexistentpkg', ignore_status=True)
-        self.assertEqual(result.status, 1, "Status different than 1. output: %s" % result.output)
-        self.assertEqual(result.output, 'ERROR: The following packages could not be found: nonexistentpkg')
+        self.assertEqual(result.status, 1, "Status different than 1. error: %s" % result.error)
+        self.assertEqual(result.error, 'ERROR: The following packages could not be found: nonexistentpkg')
         # Reverse tests
         result = runCmd('oe-pkgdata-util lookup-pkg -r "libz1 busybox"')
         self.assertEqual(result.output, 'zlib\nbusybox')
         result = runCmd('oe-pkgdata-util lookup-pkg -r libz-dev')
         self.assertEqual(result.output, 'zlib-dev')
         result = runCmd('oe-pkgdata-util lookup-pkg -r nonexistentpkg', ignore_status=True)
-        self.assertEqual(result.status, 1, "Status different than 1. output: %s" % result.output)
-        self.assertEqual(result.output, 'ERROR: The following packages could not be found: nonexistentpkg')
+        self.assertEqual(result.status, 1, "Status different than 1. error: %s" % result.error)
+        self.assertEqual(result.error, 'ERROR: The following packages could not be found: nonexistentpkg')
 
     @OETestID(1205)
     def test_read_value(self):
@@ -51,8 +51,8 @@ class OePkgdataUtilTests(OESelftestTestCase):
         result = runCmd('oe-pkgdata-util find-path /usr/bin/m4')
         self.assertEqual(result.output, 'm4: /usr/bin/m4')
         result = runCmd('oe-pkgdata-util find-path /not/exist', ignore_status=True)
-        self.assertEqual(result.status, 1, "Status different than 1. output: %s" % result.output)
-        self.assertEqual(result.output, 'ERROR: Unable to find any package producing path /not/exist')
+        self.assertEqual(result.status, 1, "Status different than 1. error: %s" % result.error)
+        self.assertEqual(result.error, 'ERROR: Unable to find any package producing path /not/exist')
 
     @OETestID(1204)
     def test_lookup_recipe(self):
@@ -61,8 +61,8 @@ class OePkgdataUtilTests(OESelftestTestCase):
         result = runCmd('oe-pkgdata-util lookup-recipe libz-dbg')
         self.assertEqual(result.output, 'zlib')
         result = runCmd('oe-pkgdata-util lookup-recipe nonexistentpkg', ignore_status=True)
-        self.assertEqual(result.status, 1, "Status different than 1. output: %s" % result.output)
-        self.assertEqual(result.output, 'ERROR: The following packages could not be found: nonexistentpkg')
+        self.assertEqual(result.status, 1, "Status different than 1. error: %s" % result.error)
+        self.assertEqual(result.error, 'ERROR: The following packages could not be found: nonexistentpkg')
 
     @OETestID(1202)
     def test_list_pkgs(self):
diff --git a/meta/lib/oeqa/selftest/cases/signing.py b/meta/lib/oeqa/selftest/cases/signing.py
index edb5f653f2..cd64eb5cbf 100644
--- a/meta/lib/oeqa/selftest/cases/signing.py
+++ b/meta/lib/oeqa/selftest/cases/signing.py
@@ -133,7 +133,7 @@ class Signing(OESelftestTestCase):
         ret = runCmd('gpg --homedir %s --verify %s %s' % (self.gpg_dir, recipe_sig[0], recipe_tgz[0]))
         # gpg: Signature made Thu 22 Oct 2015 01:45:09 PM EEST using RSA key ID 61EEFB30
         # gpg: Good signature from "testuser (nocomment) <testuser@email.com>"
-        self.assertIn('gpg: Good signature from', ret.output, 'Package signed incorrectly.')
+        self.assertIn('gpg: Good signature from', ret.error, 'Package signed incorrectly.')
 
 
 class LockedSignatures(OESelftestTestCase):
diff --git a/meta/lib/oeqa/utils/commands.py b/meta/lib/oeqa/utils/commands.py
index 4ef0e874ff..055a59cab1 100644
--- a/meta/lib/oeqa/utils/commands.py
+++ b/meta/lib/oeqa/utils/commands.py
@@ -70,6 +70,7 @@ class Command(object):
             self.stop()
 
     def stop(self):
+
         if self.thread.isAlive():
             self.process.terminate()
             # let's give it more time to terminate gracefully before killing it
@@ -78,10 +79,9 @@ class Command(object):
                 self.process.kill()
                 self.thread.join()
 
-        if not self.output:
-            self.output = ""
-        else:
-            self.output = self.output.decode("utf-8", errors='replace').rstrip()
+        self.output = self.output.decode("utf-8", errors='replace').rstrip() if self.output else ""
+        self.error = self.error.decode("utf-8", errors='ignore').rstrip() if self.error else ""
+
         self.status = self.process.poll()
 
         self.log.debug("Command '%s' returned %d as exit code." % (self.cmd, self.status))
diff --git a/meta/lib/oeqa/utils/misc.py b/meta/lib/oeqa/utils/misc.py
new file mode 100644
index 0000000000..b5579e5b63
--- /dev/null
+++ b/meta/lib/oeqa/utils/misc.py
@@ -0,0 +1,11 @@
+# Copyright (C) 2013-2017 Intel Corporation
+#
+# Released under the MIT license (see COPYING.MIT)
+
+def getline(data, line):
+    _line = ''
+    for l in data.split('\n'):
+        if line in l:
+            _line = l
+            break
+    return _line
-- 
2.12.0

Re: [PATCH 1/2] commands: send stderr to a new pipe

[Jussi Kukkonen]

[-- Attachment #1: Type: text/plain, Size: 1538 bytes --]

On 19 June 2017 at 17:39, <leonardo.sandoval.gonzalez@linux.intel.com>
wrote:
>
> From: Leonardo Sandoval <leonardo.sandoval.gonzalez@linux.intel.com>
>
> Do not mix the stderr into stdout, allowing test cases to query
> the specific output.

I wonder if this patch could be related to the strange selftest failures
where command output seems to be missing completely, e.g.
    AssertionError: '' != 'ERROR: Unable to find any package producing path
/not/exist'

https://autobuilder.yocto.io/builders/nightly-oe-selftest/builds/349/steps/Running%20oe-selftest/logs/stdio


Jussi

>
> [YOCTO #9693]
>
> Signed-off-by: Leonardo Sandoval <
leonardo.sandoval.gonzalez@linux.intel.com>
> ---
>  meta/lib/oeqa/utils/commands.py | 2 +-
>  1 file changed, 1 insertion(+), 1 deletion(-)
>
> diff --git a/meta/lib/oeqa/utils/commands.py
b/meta/lib/oeqa/utils/commands.py
> index 57286fcb10..4ef0e874ff 100644
> --- a/meta/lib/oeqa/utils/commands.py
> +++ b/meta/lib/oeqa/utils/commands.py
> @@ -29,7 +29,7 @@ class Command(object):
>
>          self.defaultopts = {
>              "stdout": subprocess.PIPE,
> -            "stderr": subprocess.STDOUT,
> +            "stderr": subprocess.PIPE,
>              "stdin": None,
>              "shell": False,
>              "bufsize": -1,
> --
> 2.12.0
>
> --
> _______________________________________________
> Openembedded-core mailing list
> Openembedded-core@lists.openembedded.org
> http://lists.openembedded.org/mailman/listinfo/openembedded-core

[-- Attachment #2: Type: text/html, Size: 2354 bytes --]

Re: [PATCH 1/2] commands: send stderr to a new pipe

[Burton, Ross]

[-- Attachment #1: Type: text/plain, Size: 482 bytes --]

On 21 June 2017 at 11:56, Jussi Kukkonen <jussi.kukkonen@intel.com> wrote:

> I wonder if this patch could be related to the strange selftest failures
> where command output seems to be missing completely, e.g.
>     AssertionError: '' != 'ERROR: Unable to find any package producing
> path /not/exist'
>

I'll admit that my first thought when I saw this patch was "this is going
to break selftest" but I failed to run a single build of it before firing
nightly.

Ross

[-- Attachment #2: Type: text/html, Size: 892 bytes --]

Re: [PATCH 1/2] commands: send stderr to a new pipe

[Leonardo Sandoval]

On Wed, 2017-06-21 at 13:56 +0300, Jussi Kukkonen wrote:
> On 19 June 2017 at 17:39, <leonardo.sandoval.gonzalez@linux.intel.com>
> wrote:
> >
> > From: Leonardo Sandoval <leonardo.sandoval.gonzalez@linux.intel.com>
> >
> > Do not mix the stderr into stdout, allowing test cases to query
> > the specific output.
> 
> I wonder if this patch could be related to the strange selftest
> failures where command output seems to be missing completely, e.g.
>     AssertionError: '' != 'ERROR: Unable to find any package producing
> path /not/exist'
> 
> https://autobuilder.yocto.io/builders/nightly-oe-selftest/builds/349/steps/Running%20oe-selftest/logs/stdio


I double check this series on local AB and I saw green in all tests, so
I am not sure what is going on.

This patch basically separates stdout and stderr, so now tests look into
stderr for errors instead of stdout.

Leo

> 
> Jussi
> 
> >
> > [YOCTO #9693]
> >
> > Signed-off-by: Leonardo Sandoval
> <leonardo.sandoval.gonzalez@linux.intel.com>
> > ---
> >  meta/lib/oeqa/utils/commands.py | 2 +-
> >  1 file changed, 1 insertion(+), 1 deletion(-)
> >
> > diff --git a/meta/lib/oeqa/utils/commands.py
> b/meta/lib/oeqa/utils/commands.py
> > index 57286fcb10..4ef0e874ff 100644
> > --- a/meta/lib/oeqa/utils/commands.py
> > +++ b/meta/lib/oeqa/utils/commands.py
> > @@ -29,7 +29,7 @@ class Command(object):
> >
> >          self.defaultopts = {
> >              "stdout": subprocess.PIPE,
> > -            "stderr": subprocess.STDOUT,
> > +            "stderr": subprocess.PIPE,
> >              "stdin": None,
> >              "shell": False,
> >              "bufsize": -1,
> > --
> > 2.12.0
> >
> > --
> > _______________________________________________
> > Openembedded-core mailing list
> > Openembedded-core@lists.openembedded.org
> > http://lists.openembedded.org/mailman/listinfo/openembedded-core
> 

Re: [PATCH 1/2] commands: send stderr to a new pipe

[Patrick Ohly]

On Mon, 2017-06-19 at 07:39 -0700,
leonardo.sandoval.gonzalez@linux.intel.com wrote:
> From: Leonardo Sandoval <leonardo.sandoval.gonzalez@linux.intel.com>
> 
> Do not mix the stderr into stdout, allowing test cases to query
> the specific output.

This changes the behavior of functions that are also used outside of
OE-core in a way that won't be easy to notice. I also don't think that
it is the right default. For example, for bitbake it is easier to
understand where an error occurred when stderr goes to the same stream
as stdout.

Can't you keep the current semantic and just override it explicitly in
those tests that need separate stdout/stderr?

-- 
Best Regards, Patrick Ohly

The content of this message is my personal opinion only and although
I am an employee of Intel, the statements I make here in no way
represent Intel's position on the issue, nor am I authorized to speak
on behalf of Intel on this matter.

Re: [PATCH 1/2] commands: send stderr to a new pipe

[Leonardo Sandoval]

On Thu, 2017-06-22 at 16:17 +0200, Patrick Ohly wrote:
> On Mon, 2017-06-19 at 07:39 -0700,
> leonardo.sandoval.gonzalez@linux.intel.com wrote:
> > From: Leonardo Sandoval <leonardo.sandoval.gonzalez@linux.intel.com>
> > 
> > Do not mix the stderr into stdout, allowing test cases to query
> > the specific output.
> 
> This changes the behavior of functions that are also used outside of
> OE-core in a way that won't be easy to notice. I also don't think that
> it is the right default. For example, for bitbake it is easier to
> understand where an error occurred when stderr goes to the same stream
> as stdout.

how would that make it easier?

> 
> Can't you keep the current semantic and just override it explicitly in
> those tests that need separate stdout/stderr?
> 

My proposed patch was mainly based on a RP's comment [1], suggesting to
split std[out|err].


[1] https://bugzilla.yoctoproject.org/show_bug.cgi?id=9693#c2

Re: [PATCH 1/2] commands: send stderr to a new pipe

[Patrick Ohly]

On Thu, 2017-06-22 at 09:58 -0500, Leonardo Sandoval wrote:
> On Thu, 2017-06-22 at 16:17 +0200, Patrick Ohly wrote:
> > On Mon, 2017-06-19 at 07:39 -0700,
> > leonardo.sandoval.gonzalez@linux.intel.com wrote:
> > > From: Leonardo Sandoval <leonardo.sandoval.gonzalez@linux.intel.com>
> > > 
> > > Do not mix the stderr into stdout, allowing test cases to query
> > > the specific output.
> > 
> > This changes the behavior of functions that are also used outside of
> > OE-core in a way that won't be easy to notice. I also don't think that
> > it is the right default. For example, for bitbake it is easier to
> > understand where an error occurred when stderr goes to the same stream
> > as stdout.
> 
> how would that make it easier?

Because then output will be properly interleaved, as it would be on a
console.

Actually, the entire error reporting in runCmd() only prints
result.output, so with stderr going to result.error by default, you
won't get the actual errors reported anymore at all, will you? 

> > Can't you keep the current semantic and just override it explicitly in
> > those tests that need separate stdout/stderr?
> > 
> 
> My proposed patch was mainly based on a RP's comment [1], suggesting to
> split std[out|err].

He did not suggest to change the default behavior. I agree that using
split stdout/stderr in those specific tests which specifically want to
check for error messages makes sense, but only in those tests.

-- 
Best Regards, Patrick Ohly

The content of this message is my personal opinion only and although
I am an employee of Intel, the statements I make here in no way
represent Intel's position on the issue, nor am I authorized to speak
on behalf of Intel on this matter.

Re: [PATCH 1/2] commands: send stderr to a new pipe

[Leonardo Sandoval]

On Thu, 2017-06-22 at 17:14 +0200, Patrick Ohly wrote:
> On Thu, 2017-06-22 at 09:58 -0500, Leonardo Sandoval wrote:
> > On Thu, 2017-06-22 at 16:17 +0200, Patrick Ohly wrote:
> > > On Mon, 2017-06-19 at 07:39 -0700,
> > > leonardo.sandoval.gonzalez@linux.intel.com wrote:
> > > > From: Leonardo Sandoval <leonardo.sandoval.gonzalez@linux.intel.com>
> > > > 
> > > > Do not mix the stderr into stdout, allowing test cases to query
> > > > the specific output.
> > > 
> > > This changes the behavior of functions that are also used outside of
> > > OE-core in a way that won't be easy to notice. I also don't think that
> > > it is the right default. For example, for bitbake it is easier to
> > > understand where an error occurred when stderr goes to the same stream
> > > as stdout.
> > 
> > how would that make it easier?
> 
> Because then output will be properly interleaved, as it would be on a
> console.
> 
> Actually, the entire error reporting in runCmd() only prints
> result.output, so with stderr going to result.error by default, you
> won't get the actual errors reported anymore at all, will you? 
> 

process stderr will go into result.error and process stdout into
result.output. So when the process is executed ignoring the return
status, then test must check result.error. I find the latter cleaner
that checking errors into stdout.


> > > Can't you keep the current semantic and just override it explicitly in
> > > those tests that need separate stdout/stderr?
> > > 
> > 
> > My proposed patch was mainly based on a RP's comment [1], suggesting to
> > split std[out|err].
> 
> He did not suggest to change the default behavior. I agree that using
> split stdout/stderr in those specific tests which specifically want to
> check for error messages makes sense, but only in those tests.

No tests require splitting the output (all tests pass with and without
this series). The series is actually an enhancement and without it, we
saw (specially when the python 2 to 3 was going on) past warnings going
into stdout, so Chris and RP suggested the approach.



> 

Re: [PATCH 1/2] commands: send stderr to a new pipe

[Patrick Ohly]

On Thu, 2017-06-22 at 10:37 -0500, Leonardo Sandoval wrote:
> On Thu, 2017-06-22 at 17:14 +0200, Patrick Ohly wrote:
> > On Thu, 2017-06-22 at 09:58 -0500, Leonardo Sandoval wrote:
> > > On Thu, 2017-06-22 at 16:17 +0200, Patrick Ohly wrote:
> > > > On Mon, 2017-06-19 at 07:39 -0700,
> > > > leonardo.sandoval.gonzalez@linux.intel.com wrote:
> > > > > From: Leonardo Sandoval <leonardo.sandoval.gonzalez@linux.intel.com>
> > > > > 
> > > > > Do not mix the stderr into stdout, allowing test cases to query
> > > > > the specific output.
> > > > 
> > > > This changes the behavior of functions that are also used outside of
> > > > OE-core in a way that won't be easy to notice. I also don't think that
> > > > it is the right default. For example, for bitbake it is easier to
> > > > understand where an error occurred when stderr goes to the same stream
> > > > as stdout.
> > > 
> > > how would that make it easier?
> > 
> > Because then output will be properly interleaved, as it would be on a
> > console.
> > 
> > Actually, the entire error reporting in runCmd() only prints
> > result.output, so with stderr going to result.error by default, you
> > won't get the actual errors reported anymore at all, will you? 
> > 
> 
> process stderr will go into result.error and process stdout into
> result.output. So when the process is executed ignoring the return
> status, then test must check result.error. I find the latter cleaner
> that checking errors into stdout.

It depends on how the result is used. That you prefer split output for
some tests does not mean that everyone wants the same in their tests. I
don't want it in my own usage of runCmd() or bitbake() because I don't
care about where a message was printed. I just want it in proper order.

If you change the default, then you will also have to enhance runCmd()'s
error handling to include results.error. That's currently missing in
your patch.

> > > > Can't you keep the current semantic and just override it explicitly in
> > > > those tests that need separate stdout/stderr?
> > > > 
> > > 
> > > My proposed patch was mainly based on a RP's comment [1], suggesting to
> > > split std[out|err].
> > 
> > He did not suggest to change the default behavior. I agree that using
> > split stdout/stderr in those specific tests which specifically want to
> > check for error messages makes sense, but only in those tests.
> 
> No tests require splitting the output (all tests pass with and without
> this series). The series is actually an enhancement and without it, we
> saw (specially when the python 2 to 3 was going on) past warnings going
> into stdout, so Chris and RP suggested the approach.

Richard, can you please comment on whether changing the default is
really what you meant?

-- 
Best Regards, Patrick Ohly

The content of this message is my personal opinion only and although
I am an employee of Intel, the statements I make here in no way
represent Intel's position on the issue, nor am I authorized to speak
on behalf of Intel on this matter.

Re: [PATCH 1/2] commands: send stderr to a new pipe

[Leonardo Sandoval]

On Thu, 2017-06-22 at 17:59 +0200, Patrick Ohly wrote:
> On Thu, 2017-06-22 at 10:37 -0500, Leonardo Sandoval wrote:
> > On Thu, 2017-06-22 at 17:14 +0200, Patrick Ohly wrote:
> > > On Thu, 2017-06-22 at 09:58 -0500, Leonardo Sandoval wrote:
> > > > On Thu, 2017-06-22 at 16:17 +0200, Patrick Ohly wrote:
> > > > > On Mon, 2017-06-19 at 07:39 -0700,
> > > > > leonardo.sandoval.gonzalez@linux.intel.com wrote:
> > > > > > From: Leonardo Sandoval <leonardo.sandoval.gonzalez@linux.intel.com>
> > > > > > 
> > > > > > Do not mix the stderr into stdout, allowing test cases to query
> > > > > > the specific output.
> > > > > 
> > > > > This changes the behavior of functions that are also used outside of
> > > > > OE-core in a way that won't be easy to notice. I also don't think that
> > > > > it is the right default. For example, for bitbake it is easier to
> > > > > understand where an error occurred when stderr goes to the same stream
> > > > > as stdout.
> > > > 
> > > > how would that make it easier?
> > > 
> > > Because then output will be properly interleaved, as it would be on a
> > > console.
> > > 
> > > Actually, the entire error reporting in runCmd() only prints
> > > result.output, so with stderr going to result.error by default, you
> > > won't get the actual errors reported anymore at all, will you? 
> > > 
> > 
> > process stderr will go into result.error and process stdout into
> > result.output. So when the process is executed ignoring the return
> > status, then test must check result.error. I find the latter cleaner
> > that checking errors into stdout.
> 
> It depends on how the result is used. That you prefer split output for
> some tests does not mean that everyone wants the same in their tests. I
> don't want it in my own usage of runCmd() or bitbake() because I don't
> care about where a message was printed. I just want it in proper order.
> 
> If you change the default, then you will also have to enhance runCmd()'s
> error handling to include results.error. That's currently missing in
> your patch.

it is not missing, it is on 2/2, but yes, the latter should be on 1/2. I
can re-factor and send v2 but lets see other opinions.

Leo

> 
> > > > > Can't you keep the current semantic and just override it explicitly in
> > > > > those tests that need separate stdout/stderr?
> > > > > 
> > > > 
> > > > My proposed patch was mainly based on a RP's comment [1], suggesting to
> > > > split std[out|err].
> > > 
> > > He did not suggest to change the default behavior. I agree that using
> > > split stdout/stderr in those specific tests which specifically want to
> > > check for error messages makes sense, but only in those tests.
> > 
> > No tests require splitting the output (all tests pass with and without
> > this series). The series is actually an enhancement and without it, we
> > saw (specially when the python 2 to 3 was going on) past warnings going
> > into stdout, so Chris and RP suggested the approach.
> 
> Richard, can you please comment on whether changing the default is
> really what you meant?
> 

Re: [PATCH 1/2] commands: send stderr to a new pipe

[Richard Purdie]

On Thu, 2017-06-22 at 17:59 +0200, Patrick Ohly wrote:
> On Thu, 2017-06-22 at 10:37 -0500, Leonardo Sandoval wrote:
> > 
> > On Thu, 2017-06-22 at 17:14 +0200, Patrick Ohly wrote:
> > > 
> > > On Thu, 2017-06-22 at 09:58 -0500, Leonardo Sandoval wrote:
> > > > 
> > > > On Thu, 2017-06-22 at 16:17 +0200, Patrick Ohly wrote:
> > > > > 
> > > > > On Mon, 2017-06-19 at 07:39 -0700,
> > > > > leonardo.sandoval.gonzalez@linux.intel.com wrote:
> > > > > > 
> > > > > > From: Leonardo Sandoval <leonardo.sandoval.gonzalez@linux.i
> > > > > > ntel.com>
> > > > > > 
> > > > > > Do not mix the stderr into stdout, allowing test cases to
> > > > > > query
> > > > > > the specific output.
> > > > > This changes the behavior of functions that are also used
> > > > > outside of
> > > > > OE-core in a way that won't be easy to notice. I also don't
> > > > > think that
> > > > > it is the right default. For example, for bitbake it is
> > > > > easier to
> > > > > understand where an error occurred when stderr goes to the
> > > > > same stream
> > > > > as stdout.
> > > > how would that make it easier?
> > > Because then output will be properly interleaved, as it would be
> > > on a
> > > console.
> > > 
> > > Actually, the entire error reporting in runCmd() only prints
> > > result.output, so with stderr going to result.error by default,
> > > you
> > > won't get the actual errors reported anymore at all, will you? 
> > > 
> > process stderr will go into result.error and process stdout into
> > result.output. So when the process is executed ignoring the return
> > status, then test must check result.error. I find the latter
> > cleaner
> > that checking errors into stdout.
> It depends on how the result is used. That you prefer split output
> for some tests does not mean that everyone wants the same in their
> tests. I don't want it in my own usage of runCmd() or bitbake()
> because I don't care about where a message was printed. I just want
> it in proper order.
> 
> If you change the default, then you will also have to enhance
> runCmd()'s error handling to include results.error. That's currently
> missing in your patch.
> 
> > 
> > > 
> > > > 
> > > > > 
> > > > > Can't you keep the current semantic and just override it
> > > > > explicitly in
> > > > > those tests that need separate stdout/stderr?
> > > > > 
> > > > My proposed patch was mainly based on a RP's comment [1],
> > > > suggesting to
> > > > split std[out|err].
> > > He did not suggest to change the default behavior. I agree that
> > > using
> > > split stdout/stderr in those specific tests which specifically
> > > want to
> > > check for error messages makes sense, but only in those tests.
> > No tests require splitting the output (all tests pass with and
> > without
> > this series). The series is actually an enhancement and without it,
> > we
> > saw (specially when the python 2 to 3 was going on) past warnings
> > going
> > into stdout, so Chris and RP suggested the approach.
> Richard, can you please comment on whether changing the default is
> really what you meant?

The problem here is that stdout and stderr are being mixed and that
mixing is not accounting for newlines. bitbake itself does print
different messages to both. The mixing depends on kernel page size and
when the buffers are flushed.

The key thing I'm not sure about from reading the bug is whether this
output is from the same bitbake process or different ones?

I can think of three things we can do here:

a) Add some flush calls somewhere assuming this is different calls.
That somehow seems unlikely

b) Keep stdout and stderr separate as per Leo's change

c) Have a command version which merges stdout and stderr respecting
newlines. I suspect this happens on a console but likely not on inter
process pipes...

It does sound like we need to answer some questions on what exactly is
happening before we can know which solution(s) might work.

Cheers,

Richard

Re: [PATCH 1/2] commands: send stderr to a new pipe

[Patrick Ohly]

On Thu, 2017-06-22 at 11:18 -0500, Leonardo Sandoval wrote:
> On Thu, 2017-06-22 at 17:59 +0200, Patrick Ohly wrote:
> > On Thu, 2017-06-22 at 10:37 -0500, Leonardo Sandoval wrote:
> > > On Thu, 2017-06-22 at 17:14 +0200, Patrick Ohly wrote:
> > > > On Thu, 2017-06-22 at 09:58 -0500, Leonardo Sandoval wrote:
> > > > > On Thu, 2017-06-22 at 16:17 +0200, Patrick Ohly wrote:
> > > > > > On Mon, 2017-06-19 at 07:39 -0700,
> > > > > > leonardo.sandoval.gonzalez@linux.intel.com wrote:
> > > > > > > From: Leonardo Sandoval <leonardo.sandoval.gonzalez@linux.intel.com>
> > > > > > > 
> > > > > > > Do not mix the stderr into stdout, allowing test cases to query
> > > > > > > the specific output.
> > > > > > 
> > > > > > This changes the behavior of functions that are also used outside of
> > > > > > OE-core in a way that won't be easy to notice. I also don't think that
> > > > > > it is the right default. For example, for bitbake it is easier to
> > > > > > understand where an error occurred when stderr goes to the same stream
> > > > > > as stdout.
> > > > > 
> > > > > how would that make it easier?
> > > > 
> > > > Because then output will be properly interleaved, as it would be on a
> > > > console.
> > > > 
> > > > Actually, the entire error reporting in runCmd() only prints
> > > > result.output, so with stderr going to result.error by default, you
> > > > won't get the actual errors reported anymore at all, will you? 
> > > > 
> > > 
> > > process stderr will go into result.error and process stdout into
> > > result.output. So when the process is executed ignoring the return
> > > status, then test must check result.error. I find the latter cleaner
> > > that checking errors into stdout.
> > 
> > It depends on how the result is used. That you prefer split output for
> > some tests does not mean that everyone wants the same in their tests. I
> > don't want it in my own usage of runCmd() or bitbake() because I don't
> > care about where a message was printed. I just want it in proper order.
> > 
> > If you change the default, then you will also have to enhance runCmd()'s
> > error handling to include results.error. That's currently missing in
> > your patch.
> 
> it is not missing, it is on 2/2

I'm talking about this code:

def runCmd(command, ignore_status=False, timeout=None, assert_error=True,
          native_sysroot=None, limit_exc_output=0, **options):
...
    if result.status and not ignore_status:
        exc_output = result.output
        if limit_exc_output > 0:
            split = result.output.splitlines()
            if len(split) > limit_exc_output:
                exc_output = "\n... (last %d lines of output)\n" % limit_exc_output + \
                             '\n'.join(split[-limit_exc_output:])
        if assert_error:
            raise AssertionError("Command '%s' returned non-zero exit status %d:\n%s" % (command, result.status, exc_output))
        else:
            raise CommandError(result.status, command, exc_output)

You are not extending that in either 2/2, are you? At the moment, when a
command fails, one gets stdout+stderr. With your path, one only gets
stdout, which typically won't have the error message that caused the
non-zero status.

Here's my proposal:
     1. drop the "commands: send stderr to a new pipe" path, because
        that has much wider implications for everyone else
     2. in "selftest/cases: use stderr data when querying for errors",
        explicitly change the bitbake() calls so that they have
        stderr=subprocess.PIPE

Example:

     @OETestID(105)
     def test_bitbake_invalid_recipe(self):
-        result = bitbake('-b asdf', ignore_status=True)
-        self.assertTrue("ERROR: Unable to find any recipe file matching 'asdf'" in result.output, msg = "Though asdf recipe doesn't exist, bitbake didn't output any err. message. bitbake output: %s" % result.output)
+        invalid = 'asdf'
+        result = bitbake('-b %s' % invalid, ignore_status=True, stderr=subprocess.PIPE)
+        self.assertTrue("ERROR: Unable to find any recipe file matching '%s'" % invalid in result.error, msg = "Though %s recipe doesn't exist, bitbake didn't output any err. message. bitbake output: %s" % (invalid, result.error))



-- 
Best Regards, Patrick Ohly

The content of this message is my personal opinion only and although
I am an employee of Intel, the statements I make here in no way
represent Intel's position on the issue, nor am I authorized to speak
on behalf of Intel on this matter.

Re: [PATCH 1/2] commands: send stderr to a new pipe

[Patrick Ohly]

On Thu, 2017-06-22 at 17:59 +0100, Richard Purdie wrote:
> The problem here is that stdout and stderr are being mixed and that
> mixing is not accounting for newlines. bitbake itself does print
> different messages to both. The mixing depends on kernel page size and
> when the buffers are flushed.

It's a single process were stdout and stderr share the same pipe.
Caching outside of the kernel may be to blame, but kernel behavior
should not have an effect.

My guess is that "Parsing recipes..WARNING:
File /etc/selftest-replaceme-patched..." comes from printing "Parsing
recipes.." to stdout without newline and then printing "WARNING:
File ..." to stderr.

I don't know whether Python logging can coordinate two streams. The
logic would have to be that when stdout/stderr go to the same stream and
the last output to stdout did not end in a new line and there's a
message to be printed on stderr, a newline should be inserted first.

> The key thing I'm not sure about from reading the bug is whether this
> output is from the same bitbake process or different ones?

It's from a single "devtool" invocation, so whatever goes wrong with
output handling is in that process.

> I can think of three things we can do here:
> 
> a) Add some flush calls somewhere assuming this is different calls.
> That somehow seems unlikely
> b) Keep stdout and stderr separate as per Leo's change

That helps testing, but actual users will still see confusing output. So
I would prefer to enhance output handling. However, it's probably more
complicated than running tests with split output.

> c) Have a command version which merges stdout and stderr respecting
> newlines. I suspect this happens on a console but likely not on inter
> process pipes...

In this case it happens for a pipe.

> It does sound like we need to answer some questions on what exactly is
> happening before we can know which solution(s) might work.

Yes.

And please, whatever we do, let's not change oeqa in a way that breaks
existing tests, whether they are in OE-core or some other layer.

-- 
Best Regards, Patrick Ohly

The content of this message is my personal opinion only and although
I am an employee of Intel, the statements I make here in no way
represent Intel's position on the issue, nor am I authorized to speak
on behalf of Intel on this matter.

Re: [PATCH 1/2] commands: send stderr to a new pipe

[Leonardo Sandoval]

On Thu, 2017-06-22 at 19:39 +0200, Patrick Ohly wrote:
> On Thu, 2017-06-22 at 11:18 -0500, Leonardo Sandoval wrote:
> > On Thu, 2017-06-22 at 17:59 +0200, Patrick Ohly wrote:
> > > On Thu, 2017-06-22 at 10:37 -0500, Leonardo Sandoval wrote:
> > > > On Thu, 2017-06-22 at 17:14 +0200, Patrick Ohly wrote:
> > > > > On Thu, 2017-06-22 at 09:58 -0500, Leonardo Sandoval wrote:
> > > > > > On Thu, 2017-06-22 at 16:17 +0200, Patrick Ohly wrote:
> > > > > > > On Mon, 2017-06-19 at 07:39 -0700,
> > > > > > > leonardo.sandoval.gonzalez@linux.intel.com wrote:
> > > > > > > > From: Leonardo Sandoval <leonardo.sandoval.gonzalez@linux.intel.com>
> > > > > > > > 
> > > > > > > > Do not mix the stderr into stdout, allowing test cases to query
> > > > > > > > the specific output.
> > > > > > > 
> > > > > > > This changes the behavior of functions that are also used outside of
> > > > > > > OE-core in a way that won't be easy to notice. I also don't think that
> > > > > > > it is the right default. For example, for bitbake it is easier to
> > > > > > > understand where an error occurred when stderr goes to the same stream
> > > > > > > as stdout.
> > > > > > 
> > > > > > how would that make it easier?
> > > > > 
> > > > > Because then output will be properly interleaved, as it would be on a
> > > > > console.
> > > > > 
> > > > > Actually, the entire error reporting in runCmd() only prints
> > > > > result.output, so with stderr going to result.error by default, you
> > > > > won't get the actual errors reported anymore at all, will you? 
> > > > > 
> > > > 
> > > > process stderr will go into result.error and process stdout into
> > > > result.output. So when the process is executed ignoring the return
> > > > status, then test must check result.error. I find the latter cleaner
> > > > that checking errors into stdout.
> > > 
> > > It depends on how the result is used. That you prefer split output for
> > > some tests does not mean that everyone wants the same in their tests. I
> > > don't want it in my own usage of runCmd() or bitbake() because I don't
> > > care about where a message was printed. I just want it in proper order.
> > > 
> > > If you change the default, then you will also have to enhance runCmd()'s
> > > error handling to include results.error. That's currently missing in
> > > your patch.
> > 
> > it is not missing, it is on 2/2
> 
> I'm talking about this code:
> 
> def runCmd(command, ignore_status=False, timeout=None, assert_error=True,
>           native_sysroot=None, limit_exc_output=0, **options):
> ...
>     if result.status and not ignore_status:
>         exc_output = result.output
>         if limit_exc_output > 0:
>             split = result.output.splitlines()
>             if len(split) > limit_exc_output:
>                 exc_output = "\n... (last %d lines of output)\n" % limit_exc_output + \
>                              '\n'.join(split[-limit_exc_output:])
>         if assert_error:
>             raise AssertionError("Command '%s' returned non-zero exit status %d:\n%s" % (command, result.status, exc_output))
>         else:
>             raise CommandError(result.status, command, exc_output)
> 




> You are not extending that in either 2/2, are you? At the moment, when a
> command fails, one gets stdout+stderr. With your path, one only gets
> stdout, which typically won't have the error message that caused the
> non-zero status.

that is not true. I tested my patch and all tests are green. If you look
at the code, the  'if len(split) > limit)exc)output' body is not
changing the result object, so what you get from cmd.run() is what what
is it returned.

> 
> Here's my proposal:
>      1. drop the "commands: send stderr to a new pipe" path, because
>         that has much wider implications for everyone else
>      2. in "selftest/cases: use stderr data when querying for errors",
>         explicitly change the bitbake() calls so that they have
>         stderr=subprocess.PIPE
> 
> Example:
> 
>      @OETestID(105)
>      def test_bitbake_invalid_recipe(self):
> -        result = bitbake('-b asdf', ignore_status=True)
> -        self.assertTrue("ERROR: Unable to find any recipe file matching 'asdf'" in result.output, msg = "Though asdf recipe doesn't exist, bitbake didn't output any err. message. bitbake output: %s" % result.output)
> +        invalid = 'asdf'
> +        result = bitbake('-b %s' % invalid, ignore_status=True, stderr=subprocess.PIPE)
> +        self.assertTrue("ERROR: Unable to find any recipe file matching '%s'" % invalid in result.error, msg = "Though %s recipe doesn't exist, bitbake didn't output any err. message. bitbake output: %s" % (invalid, result.error))
> 
> 
> 

Re: [PATCH 1/2] commands: send stderr to a new pipe

[Leonardo Sandoval]

On Thu, 2017-06-22 at 21:35 +0200, Patrick Ohly wrote:

> 
> And please, whatever we do, let's not change oeqa in a way that breaks
> existing tests, whether they are in OE-core or some other layer.
> 

The AB issue that was reported recently may be related to this change
but locally I have not seen the problem, so it may either another commit
breaking it or AB setup.

Leo

Re: [PATCH 1/2] commands: send stderr to a new pipe

[Patrick Ohly]

On Thu, 2017-06-22 at 15:47 -0500, Leonardo Sandoval wrote:
> On Thu, 2017-06-22 at 19:39 +0200, Patrick Ohly wrote:
> > On Thu, 2017-06-22 at 11:18 -0500, Leonardo Sandoval wrote:
> > > On Thu, 2017-06-22 at 17:59 +0200, Patrick Ohly wrote:
> > > > On Thu, 2017-06-22 at 10:37 -0500, Leonardo Sandoval wrote:
> > > > > On Thu, 2017-06-22 at 17:14 +0200, Patrick Ohly wrote:
> > > > > > On Thu, 2017-06-22 at 09:58 -0500, Leonardo Sandoval wrote:
> > > > > > > On Thu, 2017-06-22 at 16:17 +0200, Patrick Ohly wrote:
> > > > > > > > On Mon, 2017-06-19 at 07:39 -0700,
> > > > > > > > leonardo.sandoval.gonzalez@linux.intel.com wrote:
> > > > > > > > > From: Leonardo Sandoval <leonardo.sandoval.gonzalez@linux.intel.com>
> > > > > > > > > 
> > > > > > > > > Do not mix the stderr into stdout, allowing test cases to query
> > > > > > > > > the specific output.
> > > > > > > > 
> > > > > > > > This changes the behavior of functions that are also used outside of
> > > > > > > > OE-core in a way that won't be easy to notice. I also don't think that
> > > > > > > > it is the right default. For example, for bitbake it is easier to
> > > > > > > > understand where an error occurred when stderr goes to the same stream
> > > > > > > > as stdout.
> > > > > > > 
> > > > > > > how would that make it easier?
> > > > > > 
> > > > > > Because then output will be properly interleaved, as it would be on a
> > > > > > console.
> > > > > > 
> > > > > > Actually, the entire error reporting in runCmd() only prints
> > > > > > result.output, so with stderr going to result.error by default, you
> > > > > > won't get the actual errors reported anymore at all, will you? 
> > > > > > 
> > > > > 
> > > > > process stderr will go into result.error and process stdout into
> > > > > result.output. So when the process is executed ignoring the return
> > > > > status, then test must check result.error. I find the latter cleaner
> > > > > that checking errors into stdout.
> > > > 
> > > > It depends on how the result is used. That you prefer split output for
> > > > some tests does not mean that everyone wants the same in their tests. I
> > > > don't want it in my own usage of runCmd() or bitbake() because I don't
> > > > care about where a message was printed. I just want it in proper order.
> > > > 
> > > > If you change the default, then you will also have to enhance runCmd()'s
> > > > error handling to include results.error. That's currently missing in
> > > > your patch.
> > > 
> > > it is not missing, it is on 2/2
> > 
> > I'm talking about this code:
> > 
> > def runCmd(command, ignore_status=False, timeout=None, assert_error=True,
> >           native_sysroot=None, limit_exc_output=0, **options):
> > ...
> >     if result.status and not ignore_status:
> >         exc_output = result.output
> >         if limit_exc_output > 0:
> >             split = result.output.splitlines()
> >             if len(split) > limit_exc_output:
> >                 exc_output = "\n... (last %d lines of output)\n" % limit_exc_output + \
> >                              '\n'.join(split[-limit_exc_output:])
> >         if assert_error:
> >             raise AssertionError("Command '%s' returned non-zero exit status %d:\n%s" % (command, result.status, exc_output))
> >         else:
> >             raise CommandError(result.status, command, exc_output)
> > 
> 
> 
> 
> 
> > You are not extending that in either 2/2, are you? At the moment, when a
> > command fails, one gets stdout+stderr. With your path, one only gets
> > stdout, which typically won't have the error message that caused the
> > non-zero status.
> 
> that is not true. I tested my patch and all tests are green.

That's not addressing the point that I raised. I am pointing out a
functional deficiency in runCmd that is caused by the first patch.
Probably there are no tests which rely on the AssertionError, so you
won't see test failures due to the changed exception message. But when a
command fails unexpectedly, the error reporting will be incomplete.

The exception is supposed to explain why a command failed. With your
patch, it doesn't achieve that goal anymore because error messages of
the command are not included (only stdout is).

Regarding your argument that "all tests are green": you are changing the
API of oeqa in a way that made it necessary to change tests in OE-core.
Other layers will be affected the same way. You haven't run "all tests"
that use oeqa, so you can't know that they "are green".

Just as an aside, your patch series breaks testing of OE-core (in the
first commit) and fixes that (in the second). That's bad for bisecting.
You would have to combine both changes in one commit to avoid that.

> If you look
> at the code, the  'if len(split) > limit)exc)output' body is not
> changing the result object, so what you get from cmd.run() is what what
> is it returned.

But it's not the same result as before, so you are changing a public API
of OE-core.

-- 
Best Regards, Patrick Ohly

The content of this message is my personal opinion only and although
I am an employee of Intel, the statements I make here in no way
represent Intel's position on the issue, nor am I authorized to speak
on behalf of Intel on this matter.

Re: [PATCH 1/2] commands: send stderr to a new pipe

[Leonardo Sandoval]

On Thu, 2017-06-22 at 23:07 +0200, Patrick Ohly wrote:
> On Thu, 2017-06-22 at 15:47 -0500, Leonardo Sandoval wrote:
> > On Thu, 2017-06-22 at 19:39 +0200, Patrick Ohly wrote:
> > > On Thu, 2017-06-22 at 11:18 -0500, Leonardo Sandoval wrote:
> > > > On Thu, 2017-06-22 at 17:59 +0200, Patrick Ohly wrote:
> > > > > On Thu, 2017-06-22 at 10:37 -0500, Leonardo Sandoval wrote:
> > > > > > On Thu, 2017-06-22 at 17:14 +0200, Patrick Ohly wrote:
> > > > > > > On Thu, 2017-06-22 at 09:58 -0500, Leonardo Sandoval wrote:
> > > > > > > > On Thu, 2017-06-22 at 16:17 +0200, Patrick Ohly wrote:
> > > > > > > > > On Mon, 2017-06-19 at 07:39 -0700,
> > > > > > > > > leonardo.sandoval.gonzalez@linux.intel.com wrote:
> > > > > > > > > > From: Leonardo Sandoval <leonardo.sandoval.gonzalez@linux.intel.com>
> > > > > > > > > > 
> > > > > > > > > > Do not mix the stderr into stdout, allowing test cases to query
> > > > > > > > > > the specific output.
> > > > > > > > > 
> > > > > > > > > This changes the behavior of functions that are also used outside of
> > > > > > > > > OE-core in a way that won't be easy to notice. I also don't think that
> > > > > > > > > it is the right default. For example, for bitbake it is easier to
> > > > > > > > > understand where an error occurred when stderr goes to the same stream
> > > > > > > > > as stdout.
> > > > > > > > 
> > > > > > > > how would that make it easier?
> > > > > > > 
> > > > > > > Because then output will be properly interleaved, as it would be on a
> > > > > > > console.
> > > > > > > 
> > > > > > > Actually, the entire error reporting in runCmd() only prints
> > > > > > > result.output, so with stderr going to result.error by default, you
> > > > > > > won't get the actual errors reported anymore at all, will you? 
> > > > > > > 
> > > > > > 
> > > > > > process stderr will go into result.error and process stdout into
> > > > > > result.output. So when the process is executed ignoring the return
> > > > > > status, then test must check result.error. I find the latter cleaner
> > > > > > that checking errors into stdout.
> > > > > 
> > > > > It depends on how the result is used. That you prefer split output for
> > > > > some tests does not mean that everyone wants the same in their tests. I
> > > > > don't want it in my own usage of runCmd() or bitbake() because I don't
> > > > > care about where a message was printed. I just want it in proper order.
> > > > > 
> > > > > If you change the default, then you will also have to enhance runCmd()'s
> > > > > error handling to include results.error. That's currently missing in
> > > > > your patch.
> > > > 
> > > > it is not missing, it is on 2/2
> > > 
> > > I'm talking about this code:
> > > 
> > > def runCmd(command, ignore_status=False, timeout=None, assert_error=True,
> > >           native_sysroot=None, limit_exc_output=0, **options):
> > > ...
> > >     if result.status and not ignore_status:
> > >         exc_output = result.output
> > >         if limit_exc_output > 0:
> > >             split = result.output.splitlines()
> > >             if len(split) > limit_exc_output:
> > >                 exc_output = "\n... (last %d lines of output)\n" % limit_exc_output + \
> > >                              '\n'.join(split[-limit_exc_output:])
> > >         if assert_error:
> > >             raise AssertionError("Command '%s' returned non-zero exit status %d:\n%s" % (command, result.status, exc_output))
> > >         else:
> > >             raise CommandError(result.status, command, exc_output)
> > > 
> > 
> > 
> > 
> > 
> > > You are not extending that in either 2/2, are you? At the moment, when a
> > > command fails, one gets stdout+stderr. With your path, one only gets
> > > stdout, which typically won't have the error message that caused the
> > > non-zero status.
> > 
> > that is not true. I tested my patch and all tests are green.
> 
> That's not addressing the point that I raised. I am pointing out a
> functional deficiency in runCmd that is caused by the first patch.
> Probably there are no tests which rely on the AssertionError, so you
> won't see test failures due to the changed exception message. But when a
> command fails unexpectedly, the error reporting will be incomplete.
> 
> The exception is supposed to explain why a command failed. With your
> patch, it doesn't achieve that goal anymore because error messages of
> the command are not included (only stdout is).
> 
> Regarding your argument that "all tests are green": you are changing the
> API of oeqa in a way that made it necessary to change tests in OE-core.
> Other layers will be affected the same way. You haven't run "all tests"
> that use oeqa, so you can't know that they "are green".
> 

fair enough. I just tested with poky, that is my tiny world.

> Just as an aside, your patch series breaks testing of OE-core (in the
> first commit) and fixes that (in the second). That's bad for bisecting.
> You would have to combine both changes in one commit to avoid that.
> 

as I mentioned before, you noticed (and I agreed) that the series needed
a refactor and I was going to send a v2 in case needed (atomicity was
not meet at the series).

Leo


> > If you look
> > at the code, the  'if len(split) > limit)exc)output' body is not
> > changing the result object, so what you get from cmd.run() is what what
> > is it returned.
> 
> But it's not the same result as before, so you are changing a public API
> of OE-core.
>