Quibble fails with UnicodeDecodeError when test output has invalid unicode
Closed, ResolvedPublicBUG REPORT
Actions

Assigned To

Authored By

	alex-mashin
	Sep 17 2022, 12:35 PM

Description

Unit tests on a patch to a MediaWiki extension fail strangely:

00:01:22.185 <<< Finish: npm install in /workspace/src, in 7.334 s
00:01:22.185 
00:01:22.362 INFO:quibble.commands:<<< Finish: Run Post-dependency install, pre-database dependent steps in parallel (concurrency=3):
00:01:22.362 * PHPUnit unit tests
00:01:22.362 * Install MediaWiki, db=<MySQL /workspace/db/quibble-mysql-btssh3_8/socket> vendor=True
00:01:22.362 * npm install in /workspace/src, in 7.545 s
00:01:22.363 INFO:backend.MySQL:Terminating MySQL
00:01:24.072 multiprocessing.pool.RemoteTraceback: 
00:01:24.072 """
00:01:24.072 Traceback (most recent call last):
00:01:24.072   File "/usr/lib/python3.7/multiprocessing/pool.py", line 121, in worker
00:01:24.072     result = (True, func(*args, **kwds))
00:01:24.072   File "/usr/local/lib/python3.7/dist-packages/quibble/commands.py", line 1059, in _run_child
00:01:24.072     captured = collector.read()
00:01:24.072   File "/usr/lib/python3.7/codecs.py", line 322, in decode
00:01:24.072     (result, consumed) = self._buffer_decode(data, self.errors, final)
00:01:24.072 UnicodeDecodeError: 'utf-8' codec can't decode byte 0xce in position 18607: invalid continuation byte
00:01:24.072 """
00:01:24.072 
00:01:24.072 The above exception was the direct cause of the following exception:
00:01:24.072 
00:01:24.072 Traceback (most recent call last):
00:01:24.072   File "/usr/local/bin/quibble", line 10, in <module>
00:01:24.072     sys.exit(main())
00:01:24.072   File "/usr/local/lib/python3.7/dist-packages/quibble/cmd.py", line 783, in main
00:01:24.072     cmd.execute(plan, dry_run=args.dry_run)
00:01:24.072   File "/usr/local/lib/python3.7/dist-packages/quibble/cmd.py", line 512, in execute
00:01:24.072     quibble.commands.execute_command(command)
00:01:24.072   File "/usr/local/lib/python3.7/dist-packages/quibble/commands.py", line 26, in execute_command
00:01:24.073     command.execute()
00:01:24.073   File "/usr/local/lib/python3.7/dist-packages/quibble/commands.py", line 1027, in execute
00:01:24.073     for error, capture in results_in_progress:
00:01:24.073   File "/usr/local/lib/python3.7/dist-packages/quibble/util.py", line 143, in __iter__
00:01:24.073     for obj in self.iterable:
00:01:24.073   File "/usr/lib/python3.7/multiprocessing/pool.py", line 748, in next
00:01:24.073     raise value
00:01:24.073 UnicodeDecodeError: 'utf-8' codec can't decode byte 0xce in position 18607: invalid continuation byte
00:01:24.901 Build step 'Execute shell' marked build as failure

Details

Subject	Repo	Branch	Lines +/-
dockerfiles: update to Quibble 1.4.7	integration/config	master	+56 -1
release: Quibble 1.4.7	integration/quibble	master	+18 -3
test_commands: Mark test as broken on macOS	integration/quibble	master	+1 -0
Handle invalid Unicode from commands	integration/quibble	master	+64 -7

Customize query in gerrit

Related Objects

Mentioned In: T320935: api-testing tests break for GrowthExperiments
T299840: Quibble concurrent capture tests fail on MacOS
Mentioned Here: T320935: api-testing tests break for GrowthExperiments
rQUIBBLEf838a24cc220: release: Quibble 1.4.7
T299840: Quibble concurrent capture tests fail on MacOS

Event Timeline

alex-mashin created this task.Sep 17 2022, 12:35 PM

alex-mashin updated the task description. (Show Details)Sep 17 2022, 9:15 PM

hashar updated the task description. (Show Details)Sep 19 2022, 7:47 AM

It crashes cause one of the command outputs invalid unicode (either some raw binary data or a unicode text that got truncated). At a first glance, I would say https://gerrit.wikimedia.org/r/c/mediawiki/extensions/ExternalData/+/832727 has a faulty testPHPUnit unit tests. I will try to reproduce.

I have managed to reproduce it locally with:

repro command

docker run --rm -it \
  -v "$(pwd)/cache:/cache" \
  -v "/home/hashar/projects:/srv/git:ro" \
  -v "$(pwd)/log:/workspace/log"
  -v "$(pwd)/src:/workspace/src"
  -e ZUUL_URL=https://gerrit.wikimedia.org/r \
  -e ZUUL_PROJECT=mediawiki/extensions/ExternalData \
  -e ZUUL_BRANCH=master \
  -e ZUUL_REF=refs/changes/27/832727/6 \
  --entrypoint=quibble-with-supervisord \
  docker-registry.wikimedia.org/releng/quibble-buster-php72:1.4.6 \
    --skip selenium,npm-test,phpunit-standalone,api-testing \
    mediawiki/extensions/ExternalData

The reason comes from Quibble ProgressReporter which retrieves the command output/error on completion. If I run the docker image with -c "/bin/bash" I drop to a shell and when running the unit tests:

nobody@8c5d2d189428:/workspace/src$ composer run phpunit:unit
> phpunit --colors=always --testsuite=core:unit,extensions:unit,skins:unit
PHPUnit 8.5.28 #StandWithUkraine

...........................................................    59 / 12675 (  0%)
<snip>
....FFF..........................................           12675 / 12675 (100%)

There were 3 failures:

1) EDParserPharTest::testInvoke with data set "zip: one file" (Binary String: 0x504b030414000...0000000, array('1.csv'), '/workspace/src/extensions/Ext...ve.zip', array(array('11', '21', '31'), array('12', '22', '32'), array('1.csv', '1.csv', '1.csv')))
'col1' not returned by parser. $parsed = array (
  0 => 
  array (
    0 => 's��1�q��1�24�14�22�12�26�16�',
  ),
  '__text' => 
  array (
    0 => 's��1�q��1�24�14�22�12�26�16�',
  ),
  '__total' => 
  array (
    0 => 1,
  ),
  '__start' => 
  array (
    0 => 1,
  ),
  '__end' => 
  array (
    0 => 2,
  ),
  '__lines' => 
  array (
    0 => 2,
  ),
  '__format' => 
  array (
    0 => 'CSV',
  ),
  '__archived_file' => 
  array (
    0 => '1.csv',
  ),
)
Failed asserting that an array has the key 'col1'.

/workspace/src/extensions/ExternalData/tests/phpunit/unit/parsers/EDParserBaseTest.php:39
/workspace/src/extensions/ExternalData/tests/phpunit/unit/parsers/EDParserPharTest.php:91
/workspace/src/tests/phpunit/MediaWikiUnitTestCase.php:116
phpvfscomposer:///workspace/src/vendor/phpunit/phpunit/phpunit:97

2) EDParserPharTest::testInvoke with data set "zip: mask *.csv, two files" (Binary String: 0x504b030414000...0000000, array('*.csv'), '/workspace/src/extensions/Ext...ve.zip', array(array('11', '21', '31', '41', '51', '61'), array('12', '22', '32', '42', '52', '62'), array('1.csv', '1.csv', '1.csv', '2.csv', '2.csv', '2.csv')))
'col1' not returned by parser. $parsed = array (
  0 => 
  array (
    0 => 's��1�q��1�24�14�22�12�26�16�',
    1 => 's��1�q��1�21�11�25�15�23�13�',
  ),
  '__text' => 
  array (
    0 => 's��1�q��1�24�14�22�12�26�16�',
    1 => 's��1�q��1�21�11�25�15�23�13�',
  ),
  '__total' => 
  array (
    0 => 1,
    1 => 1,
  ),
  '__start' => 
  array (
    0 => 1,
    1 => 1,
  ),
  '__end' => 
  array (
    0 => 2,
    1 => 2,
  ),
  '__lines' => 
  array (
    0 => 2,
    1 => 2,
  ),
  '__format' => 
  array (
    0 => 'CSV',
    1 => 'CSV',
  ),
  '__archived_file' => 
  array (
    0 => '1.csv',
    1 => '2.csv',
  ),
)
Failed asserting that an array has the key 'col1'.

/workspace/src/extensions/ExternalData/tests/phpunit/unit/parsers/EDParserBaseTest.php:39
/workspace/src/extensions/ExternalData/tests/phpunit/unit/parsers/EDParserPharTest.php:91
/workspace/src/tests/phpunit/MediaWikiUnitTestCase.php:116
phpvfscomposer:///workspace/src/vendor/phpunit/phpunit/phpunit:97

3) EDParserPharTest::testInvoke with data set "zip: mask *, two files" (Binary String: 0x504b030414000...0000000, array('*'), '/workspace/src/extensions/Ext...ve.zip', array(array('11', '21', '31', '41', '51', '61'), array('12', '22', '32', '42', '52', '62'), array('1.csv', '1.csv', '1.csv', '2.csv', '2.csv', '2.csv')))
'col1' not returned by parser. $parsed = array (
  0 => 
  array (
    0 => 's��1�q��1�24�14�22�12�26�16�',
    1 => 's��1�q��1�21�11�25�15�23�13�',
  ),
  '__text' => 
  array (
    0 => 's��1�q��1�24�14�22�12�26�16�',
    1 => 's��1�q��1�21�11�25�15�23�13�',
  ),
  '__total' => 
  array (
    0 => 1,
    1 => 1,
  ),
  '__start' => 
  array (
    0 => 1,
    1 => 1,
  ),
  '__end' => 
  array (
    0 => 2,
    1 => 2,
  ),
  '__lines' => 
  array (
    0 => 2,
    1 => 2,
  ),
  '__format' => 
  array (
    0 => 'CSV',
    1 => 'CSV',
  ),
  '__archived_file' => 
  array (
    0 => '1.csv',
    1 => '2.csv',
  ),
)
Failed asserting that an array has the key 'col1'.

/workspace/src/extensions/ExternalData/tests/phpunit/unit/parsers/EDParserBaseTest.php:39
/workspace/src/extensions/ExternalData/tests/phpunit/unit/parsers/EDParserPharTest.php:91
/workspace/src/tests/phpunit/MediaWikiUnitTestCase.php:116
phpvfscomposer:///workspace/src/vendor/phpunit/phpunit/phpunit:97

FAILURES!
Tests: 12675, Assertions: 152936, Failures: 3, Skipped: 7.
Script phpunit --colors=always --testsuite=core:unit,extensions:unit,skins:unit handling the phpunit:unit event returned with error code 1

Some test fail, PHPUnit then dump the result which is some arbitrary binary data. When Python tries to decode the output as Unicode it fails and errors out.

Thank you, @hashar. I tried to output some diagnostic information, which contained binary data, for a test that had succeeded on my development server but failed when run on MediaWiki gerrit. I sanitised the output, and this issue disappeared, although the test still fails.

@alex-mashin great! I will get a fix to let Quibble handle binary data coming from the output, it should not fail with a cryptic stacktrace :)

Change 832979 had a related patch set uploaded (by Hashar; author: Hashar):

[integration/quibble@master] Handle invalid Unicode from commands

https://gerrit.wikimedia.org/r/832979

gerritbot added a project: Patch-For-Review.Sep 19 2022, 10:40 AM

And the failing tests were caused by bug 76584.

hashar added a project: Release-Engineering-Team (Blocking 🧱).Sep 19 2022, 3:08 PM

hashar renamed this task from Possible bug in Quibble to Quibble fails with UnicodeDecodeError when test output has invalid unicode.Sep 21 2022, 9:39 AM

Change 832979 merged by jenkins-bot:

[integration/quibble@master] Handle invalid Unicode from commands

https://gerrit.wikimedia.org/r/832979

Maintenance_bot removed a project: Patch-For-Review.Sep 22 2022, 1:30 PM

A quick status update: the change got merged. The issue only surface on this task and never presented previously, it will be included in a future release and deployment of Quibble though. I am marking the task stalled until the update happens.

Change 843424 had a related patch set uploaded (by Kosta Harlan; author: Kosta Harlan):

[integration/quibble@master] test_commands: Mark tset as broken on macOS

https://gerrit.wikimedia.org/r/843424

gerritbot added a project: Patch-For-Review.Oct 17 2022, 10:20 AM

In T318029#8320495, @gerritbot wrote:

Change 843424 had a related patch set uploaded (by Kosta Harlan; author: Kosta Harlan):

[integration/quibble@master] test_commands: Mark tset as broken on macOS

https://gerrit.wikimedia.org/r/843424

@hashar I assume the test works for you locally; it is failing for me on macOS, hence this patch.

Oups. May you paste the output of the test with verbose mode?

tox -e py3-unit -- -vv -k invalid_unicode

In T318029#8320787, @hashar wrote:
Oups. May you paste the output of the test with verbose mode?
tox -e py3-unit -- -vv -k invalid_unicode

sure, here you go:

➜ tox -e py3-unit -- -vv -k invalid_unicode
/Users/kostajh/src/integration/quibble/.tox/venv-py3/lib/python3.10/site-packages/setuptools/config/setupcfg.py:508: SetuptoolsDeprecationWarning: The license_file parameter is deprecated, use license_files instead.
  warnings.warn(msg, warning_class)
/Users/kostajh/src/integration/quibble/.tox/venv-py3/lib/python3.10/site-packages/setuptools/installer.py:27: SetuptoolsDeprecationWarning: setuptools.installer is deprecated. Requirements should be satisfied by a PEP 517 installer.
  warnings.warn(
py3-unit develop-inst-noop: /Users/kostajh/src/integration/quibble
py3-unit installed: attrs==22.1.0,coverage==6.5.0,extras==1.0.0,gitdb2==2.0.6,GitPython==2.1.15,iniconfig==1.1.1,packaging==21.3,pluggy==1.0.0,py==1.11.0,pyparsing==3.0.9,pytest==7.1.3,PyYAML==6.0,-e git+ssh://kharlan@gerrit.wikimedia.org:29418/integration/quibble@5c29fb1be4b35657a14f2fe207712e6ac9746323#egg=quibble,six==1.16.0,smmap==5.0.0,smmap2==3.0.1,tomli==2.0.1
py3-unit run-test-pre: PYTHONHASHSEED='1030933403'
py3-unit run-test: commands[0] | pytest -m 'not integration' -vv -k invalid_unicode
=================================================================== test session starts ====================================================================
platform darwin -- Python 3.10.7, pytest-7.1.3, pluggy-1.0.0 -- /Users/kostajh/src/integration/quibble/.tox/venv-py3/bin/python
cachedir: .tox/venv-py3/.pytest_cache
rootdir: /Users/kostajh/src/integration/quibble, configfile: tox.ini
collected 154 items / 153 deselected / 1 selected

tests/test_commands.py::ParallelTest::test_parallel_run_child_handles_invalid_unicode FAILED                                                         [100%]

========================================================================= FAILURES =========================================================================
_______________________________________________ ParallelTest.test_parallel_run_child_handles_invalid_unicode _______________________________________________

self = <tests.test_commands.ParallelTest testMethod=test_parallel_run_child_handles_invalid_unicode>, mock_log = <MagicMock name='log' id='4572882080'>

    @mock.patch('quibble.commands.log')
    def test_parallel_run_child_handles_invalid_unicode(self, mock_log):
        p = quibble.commands.Parallel(
            steps=[
                InvalidUnicodeCommand(),
                InvalidUnicodeCommand(),
            ]
        )
        p.execute()

>       mock_log.info.assert_called_with(
            "stdout with invalid unicode: \\x80abc"
            "stderr with invalid unicode: \\x80abc"
        )

tests/test_commands.py:764:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

self = <MagicMock name='log.info' id='4573229168'>, args = ('stdout with invalid unicode: \\x80abcstderr with invalid unicode: \\x80abc',), kwargs = {}
expected = call('stdout with invalid unicode: \\x80abcstderr with invalid unicode: \\x80abc'), actual = call('')
_error_message = <function NonCallableMock.assert_called_with.<locals>._error_message at 0x11095bf40>, cause = None

    def assert_called_with(self, /, *args, **kwargs):
        """assert that the last call was made with the specified arguments.

        Raises an AssertionError if the args and keyword args passed in are
        different to the last call to the mock."""
        if self.call_args is None:
            expected = self._format_mock_call_signature(args, kwargs)
            actual = 'not called.'
            error_message = ('expected call not found.\nExpected: %s\nActual: %s'
                    % (expected, actual))
            raise AssertionError(error_message)

        def _error_message():
            msg = self._format_mock_failure_message(args, kwargs)
            return msg
        expected = self._call_matcher(_Call((args, kwargs), two=True))
        actual = self._call_matcher(self.call_args)
        if actual != expected:
            cause = expected if isinstance(expected, Exception) else None
>           raise AssertionError(_error_message()) from cause
E           AssertionError: expected call not found.
E           Expected: info('stdout with invalid unicode: \\x80abcstderr with invalid unicode: \\x80abc')
E           Actual: info('')

/opt/homebrew/Cellar/python@3.10/3.10.7/Frameworks/Python.framework/Versions/3.10/lib/python3.10/unittest/mock.py:919: AssertionError
================================================================= short test summary info ==================================================================
FAILED tests/test_commands.py::ParallelTest::test_parallel_run_child_handles_invalid_unicode - AssertionError: expected call not found.
============================================================ 1 failed, 153 deselected in 1.68s =============================================================
ERROR: InvocationError for command /Users/kostajh/src/integration/quibble/.tox/venv-py3/bin/pytest -m 'not integration' -vv -k invalid_unicode (exited with code 1)
_________________________________________________________________________ summary __________________________________________________________________________
ERROR:   py3-unit: commands failed

At least the log.info seems to be called: Actual: info('').

The call is made from Parallel.execute with the data coming from captured = collector.read().decode(errors='backslashreplace'). Looks like something shallows the whole string.

Maybe that is reproducible from the REPL:

$ python3.10
>>> b"stdout \x80abc".decode(errors='backslashreplace')
'stdout \\x80abc'

I would suspect that to yield an empty string.

Oh, looking at T299840, it is because stdout is not captured with ParallelTest, so I guess that is the issue. So, I think we should mark it as broken on macOS and leave it for the resolution of T299840: Quibble concurrent capture tests fail on MacOS.