While working on a functional test that relies on the fake_notifier.wait_for_versioned_notifications method the notification never comes and the waiter times out but dumps an unhelpful ValueError:
{0} nova.tests.functional.wsgi.test_servers.ColdMigrationDisallowSameHost.test_cold_migrate_same_host_disabled [] ... inprogress
Captured traceback:
~~~~~~~~~~~~~~~~~~~
b'Traceback (most recent call last):'
b' File "/home/osboxes/git/nova/nova/tests/functional/wsgi/test_servers.py", line 423, in test_cold_migrate_same_host_disabled'
b' self._wait_for_migrate_no_valid_host()'
b' File "/home/osboxes/git/nova/nova/tests/functional/wsgi/test_servers.py", line 408, in _wait_for_migrate_no_valid_host'
b" 'compute_task.migrate_server.error')[0]"
b' File "/home/osboxes/git/nova/nova/tests/unit/fake_notifier.py", line 153, in wait_for_versioned_notifications'
b' return VERSIONED_SUBS[event_type].wait_n(n_events, event_type, timeout)'
b' File "/home/osboxes/git/nova/nova/tests/unit/fake_notifier.py", line 61, in wait_n'
b" 'notifications': notifications,"
b''
Not a text type application/octet-stream
Traceback (most recent call last):
File "/home/osboxes/git/nova/.tox/functional-py36/lib/python3.6/site-packages/cliff/app.py", line 401, in run_subcommand
result = cmd.run(parsed_args)
File "/home/osboxes/git/nova/.tox/functional-py36/lib/python3.6/site-packages/cliff/command.py", line 185, in run
return_code = self.take_action(parsed_args) or 0
File "/home/osboxes/git/nova/.tox/functional-py36/lib/python3.6/site-packages/stestr/commands/run.py", line 235, in take_action
all_attachments=all_attachments)
File "/home/osboxes/git/nova/.tox/functional-py36/lib/python3.6/site-packages/stestr/commands/run.py", line 484, in run_command
all_attachments=all_attachments)
File "/home/osboxes/git/nova/.tox/functional-py36/lib/python3.6/site-packages/stestr/commands/run.py", line 550, in _run_tests
return run_tests()
File "/home/osboxes/git/nova/.tox/functional-py36/lib/python3.6/site-packages/stestr/commands/run.py", line 547, in run_tests
all_attachments=all_attachments)
File "/home/osboxes/git/nova/.tox/functional-py36/lib/python3.6/site-packages/stestr/commands/load.py", line 234, in load
all_attachments)
File "/home/osboxes/git/nova/.tox/functional-py36/lib/python3.6/site-packages/stestr/commands/load.py", line 267, in _load_case
case.run(result)
File "/home/osboxes/git/nova/.tox/functional-py36/lib/python3.6/site-packages/testtools/testsuite.py", line 171, in run
result.status(**event_dict)
File "/home/osboxes/git/nova/.tox/functional-py36/lib/python3.6/site-packages/testtools/testresult/real.py", line 468, in status
_strict_map(methodcaller('status', *args, **kwargs), self.targets)
File "/home/osboxes/git/nova/.tox/functional-py36/lib/python3.6/site-packages/testtools/testresult/real.py", line 443, in _strict_map
return list(map(function, *sequences))
File "/home/osboxes/git/nova/.tox/functional-py36/lib/python3.6/site-packages/testtools/testresult/real.py", line 570, in status
target.status(**kwargs)
File "/home/osboxes/git/nova/.tox/functional-py36/lib/python3.6/site-packages/testtools/testresult/real.py", line 468, in status
_strict_map(methodcaller('status', *args, **kwargs), self.targets)
File "/home/osboxes/git/nova/.tox/functional-py36/lib/python3.6/site-packages/testtools/testresult/real.py", line 443, in _strict_map
return list(map(function, *sequences))
File "/home/osboxes/git/nova/.tox/functional-py36/lib/python3.6/site-packages/testtools/testresult/real.py", line 909, in status
self._hook.status(*args, **kwargs)
File "/home/osboxes/git/nova/.tox/functional-py36/lib/python3.6/site-packages/testtools/testresult/real.py", line 826, in status
self.on_test(self._inprogress.pop(key))
File "/home/osboxes/git/nova/.tox/functional-py36/lib/python3.6/site-packages/testtools/testresult/real.py", line 901, in _handle_test
self.on_test(test_record.to_dict())
File "/home/osboxes/git/nova/.tox/functional-py36/lib/python3.6/site-packages/stestr/subunit_trace.py", line 193, in show_outcome
print_attachments(stream, test, all_channels=True)
File "/home/osboxes/git/nova/.tox/functional-py36/lib/python3.6/site-packages/stestr/subunit_trace.py", line 120, in print_attachments
if (all_channels or name in channels) and detail.as_text():
File "/home/osboxes/git/nova/.tox/functional-py36/lib/python3.6/site-packages/testtools/content.py", line 92, in as_text
return _u('').join(self.iter_text())
File "/home/osboxes/git/nova/.tox/functional-py36/lib/python3.6/site-packages/testtools/content.py", line 108, in iter_text
raise ValueError("Not a text type %r" % self.content_type)
ValueError: Not a text type application/octet-stream
There is a problem formating the AssertionError which is trying to put the notifications that have been received into the error message:
https://github.com/openstack/nova/blob/05d3c01a685de45dd8f98a46bc5c52f6bd08e7cd/nova/tests/unit/fake_notifier.py#L57-L61
Something about the result of pprint.pformat causes issues (I'm on py36).
This code could probably stand to try and be less sneaky and just ditch pprint and put the VERSIONED_SUBS or VERSIONED_NOTIFICATIONS dict into the error. It won't be pretty but at least it's something that can be copy/pasted from the console to another formatting tool (like a json formatter).
The exception in the report is coming from stestr while receiving the attachments from the subunit test executor. Plus pprint.pformat guaranteed to return an unicode string based on the python doc [1].
So I think this is not the nova test code that emits a non text output but the subunit / stestr interaction converts such output to a byte array (hence the b' in your console) and most probably that byte array is split during transport between subunit and stestr. Then on the stestr side one piece of the split byte array is converted back to text. If the split happen at a byte position that is not an end of an unicode character then the byte array -> text conversion fails and the attachment type is set to octet stream as a fallback.
I think this is related to bug 1813147[2] for which we have a potential fix proposed in stestr [2].
I think we should wait for [2] to be fixed instead of removing reasonable output from our test. I understand that if there is less test output then there is less chance to hit the stestr bug but the proposed solution to remove the pprint.pformat did not reduce the test output significantly (it only adds newlines and spaces /tabs ).
[1] https:/
[2] https:/