search

Azure / azure-cli

Azure Command-Line Interface
MIT License
3.98k stars 2.95k forks source link

`test_vmss_extension_image` live test fails: TypeError: super(type, obj): obj must be an instance or subtype of type #28678

Open jiasli opened 5 months ago

jiasli commented 5 months ago

https://dev.azure.com/azclitools/internal/_build/results?buildId=145445&view=logs&j=c4f33547-49c0-5c65-7824-491d55a01606&t=a7ac92da-e355-5684-e29f-c3f1345ef523

2024-04-02T10:43:15.0567815Z _______________ VMSSExtensionImageTest.test_vmss_extension_image _______________
2024-04-02T10:43:15.0568238Z [gw0] linux -- Python 3.10.14 /mnt/vss/_work/1/s/env/bin/python
2024-04-02T10:43:15.0568542Z self = <azure.cli.testsdk.base.ExecutionResult object at 0x7f7f0cdeff70>
2024-04-02T10:43:15.0568854Z cli_ctx = <azure.cli.core.mock.DummyCli object at 0x7f7f0d5277f0>
2024-04-02T10:43:15.0569399Z command = 'vmss extension image list -p Microsoft.Azure.NetworkWatcher'
2024-04-02T10:43:15.0569662Z expect_failure = False
2024-04-02T10:43:15.0569753Z 
2024-04-02T10:43:15.0569994Z     def _in_process_execute(self, cli_ctx, command, expect_failure=False):
2024-04-02T10:43:15.0570262Z         from io import StringIO
2024-04-02T10:43:15.0570525Z         from vcr.errors import CannotOverwriteExistingCassetteException
2024-04-02T10:43:15.0570761Z     
2024-04-02T10:43:15.0571036Z         if command.startswith('az '):
2024-04-02T10:43:15.0571262Z             command = command[3:]
2024-04-02T10:43:15.0571452Z     
2024-04-02T10:43:15.0571640Z         stdout_buf = StringIO()
2024-04-02T10:43:15.0571858Z         logging_buf = StringIO()
2024-04-02T10:43:15.0572062Z         try:
2024-04-02T10:43:15.0572328Z             # issue: stderr cannot be redirect in this form, as a result some failure information
2024-04-02T10:43:15.0572766Z             # is lost when command fails.
2024-04-02T10:43:15.0573054Z >           self.exit_code = cli_ctx.invoke(shlex.split(command), out_file=stdout_buf) or 0
2024-04-02T10:43:15.0573210Z 
2024-04-02T10:43:15.0573529Z src/azure-cli-testsdk/azure/cli/testsdk/base.py:302: 
2024-04-02T10:43:15.0573812Z _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
2024-04-02T10:43:15.0574327Z env/lib/python3.10/site-packages/knack/cli.py:245: in invoke
2024-04-02T10:43:15.0574606Z     exit_code = self.exception_handler(ex)
2024-04-02T10:43:15.0575007Z src/azure-cli-core/azure/cli/core/__init__.py:127: in exception_handler
2024-04-02T10:43:15.0575284Z     return handle_exception(ex)
2024-04-02T10:43:15.0575533Z _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
2024-04-02T10:43:15.0575658Z 
2024-04-02T10:43:15.0576177Z ex = TypeError('super(type, obj): obj must be an instance or subtype of type')
2024-04-02T10:43:15.0576450Z args = (), kwargs = {}
2024-04-02T10:43:15.0576558Z 
2024-04-02T10:43:15.0576941Z     def _handle_main_exception(ex, *args, **kwargs):  # pylint: disable=unused-argument
2024-04-02T10:43:15.0577270Z         if isinstance(ex, CannotOverwriteExistingCassetteException):
2024-04-02T10:43:15.0577580Z             # This exception usually caused by a no match HTTP request. This is a product error
2024-04-02T10:43:15.0577867Z             # that is caused by change of SDK invocation.
2024-04-02T10:43:15.0578084Z             raise ex
2024-04-02T10:43:15.0578254Z     
2024-04-02T10:43:15.0578439Z >       raise CliExecutionError(ex)
2024-04-02T10:43:15.0578744Z E       azure.cli.testsdk.exceptions.CliExecutionError: The CLI throws exception TypeError during execution and fails the command.
2024-04-02T10:43:15.0578924Z 
2024-04-02T10:43:15.0579276Z src/azure-cli-testsdk/azure/cli/testsdk/patches.py:35: CliExecutionError
2024-04-02T10:43:15.0579423Z 
2024-04-02T10:43:15.0579651Z During handling of the above exception, another exception occurred:
2024-04-02T10:43:15.0579791Z 
2024-04-02T10:43:15.0580045Z self = <latest.test_vm_commands.VMSSExtensionImageTest testMethod=test_vmss_extension_image>
2024-04-02T10:43:15.0580514Z resource_group = 'cli_test_vmss_extension_image_rybbbcyqniwsp5f3hz7uz5yltiqf4kxh2yaaux47tayqp'
2024-04-02T10:43:15.0580675Z 
2024-04-02T10:43:15.0580846Z     @AllowLargeResponse()
2024-04-02T10:43:15.0581200Z     @ResourceGroupPreparer(name_prefix='cli_test_vmss_extension_image_')
2024-04-02T10:43:15.0581503Z     def test_vmss_extension_image(self, resource_group):
2024-04-02T10:43:15.0581746Z         self.kwargs.update({
2024-04-02T10:43:15.0582078Z             'pub': 'Microsoft.Azure.NetworkWatcher',
2024-04-02T10:43:15.0582417Z             'name': 'NetworkWatcherAgentLinux',
2024-04-02T10:43:15.0582717Z             'location': 'eastus',
2024-04-02T10:43:15.0582994Z             'ver': '1.4.905.2'
2024-04-02T10:43:15.0583183Z         })
2024-04-02T10:43:15.0583378Z     
2024-04-02T10:43:15.0583710Z >       self.cmd('vmss extension image list -p {pub}', checks=[
2024-04-02T10:43:15.0584080Z             self.check('[0].publisher', self.kwargs['pub'])
2024-04-02T10:43:15.0584298Z         ])
2024-04-02T10:43:15.0584372Z 
2024-04-02T10:43:15.0584738Z src/azure-cli/azure/cli/command_modules/vm/tests/latest/test_vm_commands.py:2675: 
2024-04-02T10:43:15.0585044Z _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
2024-04-02T10:43:15.0585420Z src/azure-cli-testsdk/azure/cli/testsdk/base.py:176: in cmd
2024-04-02T10:43:15.0585744Z     return execute(self.cli_ctx, command, expect_failure=expect_failure).assert_with_checks(checks)
2024-04-02T10:43:15.0586149Z src/azure-cli-testsdk/azure/cli/testsdk/base.py:251: in __init__
2024-04-02T10:43:15.0586415Z     self._in_process_execute(cli_ctx, command, expect_failure=expect_failure)
2024-04-02T10:43:15.0586788Z src/azure-cli-testsdk/azure/cli/testsdk/base.py:314: in _in_process_execute
2024-04-02T10:43:15.0587010Z     raise ex.exception
2024-04-02T10:43:15.0587439Z env/lib/python3.10/site-packages/knack/cli.py:233: in invoke
2024-04-02T10:43:15.0587758Z     cmd_result = self.invocation.execute(args)
2024-04-02T10:43:15.0588177Z src/azure-cli-core/azure/cli/core/commands/__init__.py:664: in execute
2024-04-02T10:43:15.0588386Z     raise ex
2024-04-02T10:43:15.0588705Z src/azure-cli-core/azure/cli/core/commands/__init__.py:731: in _run_jobs_serially
2024-04-02T10:43:15.0588965Z     results.append(self._run_job(expanded_arg, cmd_copy))
2024-04-02T10:43:15.0589303Z src/azure-cli-core/azure/cli/core/commands/__init__.py:701: in _run_job
2024-04-02T10:43:15.0589565Z     result = cmd_copy(params)
2024-04-02T10:43:15.0589955Z src/azure-cli-core/azure/cli/core/commands/__init__.py:334: in __call__
2024-04-02T10:43:15.0590217Z     return self.handler(*args, **kwargs)
2024-04-02T10:43:15.0590608Z src/azure-cli-core/azure/cli/core/commands/command_operation.py:121: in handler
2024-04-02T10:43:15.0590899Z     return op(**command_args)
2024-04-02T10:43:15.0591331Z src/azure-cli/azure/cli/command_modules/vm/custom.py:2169: in list_vm_extension_images
2024-04-02T10:43:15.0591661Z     return load_extension_images_thru_services(
2024-04-02T10:43:15.0592105Z src/azure-cli/azure/cli/command_modules/vm/_actions.py:235: in load_extension_images_thru_services
2024-04-02T10:43:15.0592548Z     t.result()  # don't use the result but expose exceptions from the threads
2024-04-02T10:43:15.0592876Z /opt/hostedtoolcache/Python/3.10.14/x64/lib/python3.10/concurrent/futures/_base.py:451: in result
2024-04-02T10:43:15.0593156Z     return self.__get_result()
2024-04-02T10:43:15.0593452Z /opt/hostedtoolcache/Python/3.10.14/x64/lib/python3.10/concurrent/futures/_base.py:403: in __get_result
2024-04-02T10:43:15.0593732Z     raise self._exception
2024-04-02T10:43:15.0594014Z /opt/hostedtoolcache/Python/3.10.14/x64/lib/python3.10/concurrent/futures/thread.py:58: in run
2024-04-02T10:43:15.0594300Z     result = self.fn(*self.args, **self.kwargs)
2024-04-02T10:43:15.0594772Z src/azure-cli/azure/cli/command_modules/vm/_actions.py:191: in _load_extension_images_from_publisher
2024-04-02T10:43:15.0595330Z     types = client.virtual_machine_extension_images.list_types(location, publisher)
2024-04-02T10:43:15.0595844Z env/lib/python3.10/site-packages/azure/core/tracing/decorator.py:76: in wrapper_use_tracer
2024-04-02T10:43:15.0596149Z     return func(*args, **kwargs)
2024-04-02T10:43:15.0596641Z env/lib/python3.10/site-packages/azure/mgmt/compute/v2023_09_01/operations/_operations.py:18754: in list_types
2024-04-02T10:43:15.0597215Z     pipeline_response: PipelineResponse = self._client._pipeline.run(  # pylint: disable=protected-access
2024-04-02T10:43:15.0597707Z env/lib/python3.10/site-packages/azure/core/pipeline/_base.py:213: in run
2024-04-02T10:43:15.0598011Z     return first_node.send(pipeline_request)
2024-04-02T10:43:15.0598429Z env/lib/python3.10/site-packages/azure/core/pipeline/_base.py:70: in send
2024-04-02T10:43:15.0598721Z     response = self.next.send(request)
2024-04-02T10:43:15.0599133Z env/lib/python3.10/site-packages/azure/core/pipeline/_base.py:70: in send
2024-04-02T10:43:15.0599430Z     response = self.next.send(request)
2024-04-02T10:43:15.0599841Z env/lib/python3.10/site-packages/azure/core/pipeline/_base.py:70: in send
2024-04-02T10:43:15.0600126Z     response = self.next.send(request)
2024-04-02T10:43:15.0600531Z env/lib/python3.10/site-packages/azure/core/pipeline/_base.py:70: in send
2024-04-02T10:43:15.0600814Z     response = self.next.send(request)
2024-04-02T10:43:15.0601217Z env/lib/python3.10/site-packages/azure/core/pipeline/_base.py:70: in send
2024-04-02T10:43:15.0601500Z     response = self.next.send(request)
2024-04-02T10:43:15.0601915Z env/lib/python3.10/site-packages/azure/mgmt/core/policies/_base.py:47: in send
2024-04-02T10:43:15.0602208Z     response = self.next.send(request)
2024-04-02T10:43:15.0602647Z env/lib/python3.10/site-packages/azure/core/pipeline/policies/_redirect.py:181: in send
2024-04-02T10:43:15.0602950Z     response = self.next.send(request)
2024-04-02T10:43:15.0603504Z env/lib/python3.10/site-packages/azure/core/pipeline/policies/_retry.py:467: in send
2024-04-02T10:43:15.0603889Z     response = self.next.send(request)
2024-04-02T10:43:15.0604347Z env/lib/python3.10/site-packages/azure/core/pipeline/policies/_authentication.py:115: in send
2024-04-02T10:43:15.0604660Z     response = self.next.send(request)
2024-04-02T10:43:15.0605069Z env/lib/python3.10/site-packages/azure/core/pipeline/_base.py:70: in send
2024-04-02T10:43:15.0605357Z     response = self.next.send(request)
2024-04-02T10:43:15.0605770Z env/lib/python3.10/site-packages/azure/core/pipeline/_base.py:70: in send
2024-04-02T10:43:15.0606056Z     response = self.next.send(request)
2024-04-02T10:43:15.0606462Z env/lib/python3.10/site-packages/azure/core/pipeline/_base.py:70: in send
2024-04-02T10:43:15.0606745Z     response = self.next.send(request)
2024-04-02T10:43:15.0607151Z env/lib/python3.10/site-packages/azure/core/pipeline/_base.py:70: in send
2024-04-02T10:43:15.0607429Z     response = self.next.send(request)
2024-04-02T10:43:15.0607840Z env/lib/python3.10/site-packages/azure/core/pipeline/_base.py:70: in send
2024-04-02T10:43:15.0608117Z     response = self.next.send(request)
2024-04-02T10:43:15.0608518Z env/lib/python3.10/site-packages/azure/core/pipeline/_base.py:108: in send
2024-04-02T10:43:15.0608843Z     self._sender.send(request.http_request, **request.context.options),
2024-04-02T10:43:15.0609342Z env/lib/python3.10/site-packages/azure/core/pipeline/transport/_requests_basic.py:338: in send
2024-04-02T10:43:15.0609678Z     response = self.session.request(  # type: ignore
2024-04-02T10:43:15.0610099Z env/lib/python3.10/site-packages/requests/sessions.py:589: in request
2024-04-02T10:43:15.0610382Z     resp = self.send(prep, **send_kwargs)
2024-04-02T10:43:15.0610765Z env/lib/python3.10/site-packages/requests/sessions.py:703: in send
2024-04-02T10:43:15.0611035Z     r = adapter.send(request, **kwargs)
2024-04-02T10:43:15.0611404Z env/lib/python3.10/site-packages/requests/adapters.py:486: in send
2024-04-02T10:43:15.0611667Z     resp = conn.urlopen(
2024-04-02T10:43:15.0612033Z env/lib/python3.10/site-packages/urllib3/connectionpool.py:715: in urlopen
2024-04-02T10:43:15.0612312Z     httplib_response = self._make_request(
2024-04-02T10:43:15.0612719Z env/lib/python3.10/site-packages/urllib3/connectionpool.py:416: in _make_request
2024-04-02T10:43:15.0613018Z     conn.request(method, url, **httplib_request_kw)
2024-04-02T10:43:15.0613276Z _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
2024-04-02T10:43:15.0613400Z 
2024-04-02T10:43:15.0613616Z self = <urllib3.connection.HTTPSConnection object at 0x7f7f078f1990>
2024-04-02T10:43:15.0613878Z method = 'GET'
2024-04-02T10:43:15.0614548Z url = '/subscriptions/0b1f6471-1bf0-4dda-aec3-cb9272f09590/providers/Microsoft.Compute/locations/westus/publishers/Microsoft.Azure.NetworkWatcher.Test/artifacttypes/vmextension/types?api-version=2023-09-01'
2024-04-02T10:43:15.0614956Z body = None
2024-04-02T10:43:15.0615905Z headers = {'User-Agent': 'AZURECLI/2.59.0 azsdk-python-core/1.28.0 Python/3.10.14 (Linux-5.15.0-1059-azure-x86_64-with-glibc2.31...y1pbEclAbqZgyqqAwvUfesa6cI1yJOxzR885MxZvMq5GskbwIb_xyZtiJNPaVbLbfdES84v5FYrbc-EfP8Nmpbm1-ERMyowUU1sRteEAXajFhAUNU04ag'}
2024-04-02T10:43:15.0616260Z 
2024-04-02T10:43:15.0616516Z     def request(self, method, url, body=None, headers=None):
2024-04-02T10:43:15.0616947Z         # Update the inner socket's timeout value to send the request.
2024-04-02T10:43:15.0617340Z         # This only triggers if the connection is re-used.
2024-04-02T10:43:15.0617618Z         if getattr(self, "sock", None) is not None:
2024-04-02T10:43:15.0617875Z             self.sock.settimeout(self.timeout)
2024-04-02T10:43:15.0618086Z     
2024-04-02T10:43:15.0618274Z         if headers is None:
2024-04-02T10:43:15.0618482Z             headers = {}
2024-04-02T10:43:15.0618676Z         else:
2024-04-02T10:43:15.0618915Z             # Avoid modifying the headers passed into .request()
2024-04-02T10:43:15.0619168Z             headers = headers.copy()
2024-04-02T10:43:15.0619773Z         if "user-agent" not in (six.ensure_str(k.lower()) for k in headers):
2024-04-02T10:43:15.0620178Z             headers["User-Agent"] = _get_default_user_agent()
2024-04-02T10:43:15.0620495Z >       super(HTTPConnection, self).request(method, url, body=body, headers=headers)
2024-04-02T10:43:15.0620836Z E       TypeError: super(type, obj): obj must be an instance or subtype of type
2024-04-02T10:43:15.0620985Z 
2024-04-02T10:43:15.0621370Z env/lib/python3.10/site-packages/urllib3/connection.py:244: TypeError
yonzhan commented 5 months ago

Thank you for opening this issue, we will look into it.

zhoxing-ms commented 5 months ago

I am unable to reproduce this issue locally image And from the error message, it doesn't seem like a issue with the logic of the test itself~ Could you retry this test in pipeline or consider manually recording the yaml file for this test locally?

jiasli commented 5 months ago

From this line

self = <urllib3.connection.HTTPSConnection object at 0x7f7f078f1990>

we can see self is urllib3.connection.HTTPSConnection which is indeed an instance of urllib3.connection.HTTPConnection.

After some debugging, I found during a normal live test (AZURE_TEST_RUN_LIVE=1), at site-packages/urllib3/connectionpool.py:416, 

                conn.request(method, url, **httplib_request_kw)

the conn.request call is redirected to vcr.stubs.VCRConnection.request (site-packages/vcr/stubs/__init__.py:209), not urllib3.connection.HTTPConnection.request (site-packages/urllib3/connection.py:244), so I guess in the failed test, urllib3.connection.HTTPSConnection has not been patched yet, but the name urllib3.connection.HTTPConnection has been patched to a vcr.stubs.VCRConnection.

This is usually caused by a racing condition. However, azdev uses --forked on Linux:

https://github.com/Azure/azure-cli-dev-tools/blob/da197478b7837f4cb89f0679c1c3115fca89fa57/azdev/operations/testtool/pytest_runner.py#L20-L21

        if os.name == 'posix':
            arguments = ['-x', '-v', '--forked', '-p no:warnings', '--log-level=WARN', '--junit-xml', log_path]

making each test run isolated.

Looking at

https://github.com/Azure/azure-cli/blob/aa482cd61e2db22b45523367d02c54dc599c3bbc/src/azure-cli/azure/cli/command_modules/vm/_actions.py#L230-L235

these HTTP requests are made in parallel. However, as VCR.py is not designed to be thread-safe (https://github.com/kevin1024/vcrpy/pull/213#issuecomment-144912292), these parallel executions breaks live tests randomly.

In a normal az command execution, using multi-threading is fine, but these HTTP requests should be executed serially in live tests.

jiasli commented 5 months ago

To my surprise, the usage of ThreadPoolExecutor was introduced very long time ago in https://github.com/Azure/azure-cli/pull/198.

kfcaio commented 2 weeks ago

It's still a problem in version 6.0.1. In my tests, I've patched ThreadPoolExecutor and as_completed to work around it.