[BUG] salt-cloud intermittent bad request with ec2 provider

Description
Every once in a while (maybe every 3rd or 4th time, but I don't launch EC2 instances very often) I run

$ sudo salt-cloud -m my-map-file.map
The following virtual machines are set to be created:
  some-host.internal

Proceed? [N/y] y     
... proceeding
[ERROR   ] There was a query error: 400 Client Error: Bad Request for url: https://ec2.us-west-2.amazonaws.com/?Action=DescribeInstances&InstanceId.1=i-086efc93cb1948ce7&Version=2016-11-15
$

The end result is that an EC2 instance is launched in the account, but it has no Name tag, and there is no salt-key generated (so salt-cloud doesn't know about it). All network interfaces set to be created are done so, but they do not have the Delete on termination flag set, so all of these need to manually be cleaned by the user.

Setup
One thing I have noticed is that it's hard to reproduce when using -l debug. I've tried a number of times. I don't know if that's just coincidence, or because it's a race condition and the additional logging is slowing things down just enough to make it work more reliably.

However, knowing the specific URL that is failing, and comparing that to what I see when running with debug logs enabled (which works), this is the first section where I see that URL referenced:

[DEBUG   ] AWS Response Status Code: 200
[DEBUG   ] MasterEvent PUB socket URI: /var/run/salt/master/master_event_pub.ipc
[DEBUG   ] MasterEvent PULL socket URI: /var/run/salt/master/master_event_pull.ipc
[DEBUG   ] Sending event: tag = salt/cloud/XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX.internal/querying; data = {'instance_id': 'i-XXXXXXXXXXXXXXXXX', 'event': 'querying instance', '_stamp': '2022-06-24T00:21:00.459296'}
[DEBUG   ] Closing IPCMessageClient instance
[DEBUG   ] The new VM instance_id is i-XXXXXXXXXXXXXXXXX
[DEBUG   ] Using AWS endpoint: ec2.us-west-2.amazonaws.com
[DEBUG   ] AWS Request: https://ec2.us-west-2.amazonaws.com/?Action=DescribeInstances&InstanceId.1=i-XXXXXXXXXXXXXXXXX&Version=2016-11-15
[DEBUG   ] Starting new HTTPS connection (1): ec2.us-west-2.amazonaws.com:443
[DEBUG   ] https://ec2.us-west-2.amazonaws.com:443 "GET /?Action=DescribeInstances&InstanceId.1=i-XXXXXXXXXXXXXXXXX&Version=2016-11-15 HTTP/1.1" 200 None
[DEBUG   ] AWS Response Status Code: 200
[DEBUG   ] The query returned: [{'reservationId': 'r-XXXXXXXXXXXXXXXXX', 'ownerId': 'XXXXXXXXXXXX', 'groupSet': None, 'instancesSet': {'item': {'instanceId': 'i-XXXXXXXXXXXXXXXXX', 'imageId': 'ami-XXXXXXXXXXXXXXXXX', 'instanceState': {'code': '0', 'name': 'pending'}, 'privateDnsName': 'ip-172-31-80-20.us-west-2.compute.internal', 'dnsName': None, 'reason': None, 'keyName': 'root@salt-master (staging)', 'amiLaunchIndex': '0', 'productCodes': None, 'instanceType': 't4g.nano', 'launchTime': '2022-06-24T00:21:00.000Z', 'placement': {'availabilityZone': 'us-west-2b', 'groupName': None, 'tenancy': 'default'}, 'monitoring': {'state': 'disabled'}, 'subnetId': 'subnet-XXXXXXXX', 'vpcId': 'vpc-XXXXXXXX', 'privateIpAddress': '172.31.80.20', 'sourceDestCheck': 'true', 'groupSet': {'item': [{'groupId': 'sg-XXXXXXXXXXXXXXXXX', 'groupName': 'XXXXXXXXXXXXXXXXX'}, {'groupId': 'sg-XXXXXXXX', 'groupName': 'default'}]}, 'architecture': 'arm64', 'rootDeviceType': 'ebs', 'rootDeviceName': '/dev/xvda', 'blockDeviceMapping': None, 'virtualizationType': 'hvm', 'clientToken': None, 'hypervisor': 'xen', 'networkInterfaceSet': {'item': [{'networkInterfaceId': 'eni-XXXXXXXXXXXXXXXXX', 'subnetId': 'subnet-XXXXXXXX', 'vpcId': 'vpc-XXXXXXXX', 'description': None, 'ownerId': '702650179727', 'status': 'in-use', 'macAddress': '06:60:ef:b1:b4:73', 'privateIpAddress': '172.31.80.20', 'privateDnsName': 'ip-172-31-80-20.us-west-2.compute.internal', 'sourceDestCheck': 'true', 'groupSet': {'item': [{'groupId': 'sg-0550caeffc9fe5a21', 'groupName': 'salt-vpn-internal'}, {'groupId': 'sg-a8bf39cd', 'groupName': 'default'}]}, 'attachment': {'attachmentId': 'eni-attach-XXXXXXXXXXXXXXXXX', 'deviceIndex': '0', 'status': 'attaching', 'attachTime': '2022-06-24T00:21:00.000Z', 'deleteOnTermination': 'false', 'networkCardIndex': '0'}, 'privateIpAddressesSet': {'item': {'privateIpAddress': '172.31.80.20', 'privateDnsName': 'ip-172-31-80-20.us-west-2.compute.internal', 'primary': 'true'}}, 'ipv6AddressesSet': None, 'interfaceType': 'interface'}, {'networkInterfaceId': 'eni-XXXXXXXXXXXXXXXXX', 'subnetId': 'subnet-XXXXXXXX', 'vpcId': 'vpc-XXXXXXXX', 'description': None, 'ownerId': 'XXXXXXXXXXXX', 'status': 'in-use', 'macAddress': '06:cd:84:a1:93:ef', 'privateIpAddress': '172.31.144.20', 'privateDnsName': 'ip-172-31-144-20.us-west-2.compute.internal', 'sourceDestCheck': 'true', 'groupSet': {'item': {'groupId': 'sg-XXXXXXXX', 'groupName': 'default'}}, 'attachment': {'attachmentId': 'eni-attach-XXXXXXXXXXXXXXXXX', 'deviceIndex': '1', 'status': 'attaching', 'attachTime': '2022-06-24T00:21:00.000Z', 'deleteOnTermination': 'false', 'networkCardIndex': '0'}, 'privateIpAddressesSet': {'item': {'privateIpAddress': '172.31.144.20', 'privateDnsName': 'ip-172-31-144-20.us-west-2.compute.internal', 'primary': 'true'}}, 'ipv6AddressesSet': None, 'interfaceType': 'interface'}]}, 'iamInstanceProfile': {'arn': 'arn:aws:iam::XXXXXXXXXXXX:instance-profile/XXXXXXXXXXXXXXX', 'id': 'XXXXXXXXXXXXXXXXXXXXX'}, 'ebsOptimized': 'false', 'enaSupport': 'true', 'cpuOptions': {'coreCount': '2', 'threadsPerCore': '1'}, 'capacityReservationSpecification': {'capacityReservationPreference': 'open'}, 'hibernationOptions': {'configured': 'false'}, 'enclaveOptions': {'enabled': 'false'}, 'metadataOptions': {'state': 'pending', 'httpTokens': 'optional', 'httpPutResponseHopLimit': '1', 'httpEndpoint': 'enabled', 'httpProtocolIpv4': 'enabled', 'httpProtocolIpv6': 'disabled', 'instanceMetadataTags': 'disabled'}, 'maintenanceOptions': {'autoRecovery': 'default'}, 'bootMode': 'uefi', 'platformDetails': 'Linux/UNIX', 'usageOperation': 'RunInstances', 'usageOperationUpdateTime': '2022-06-24T00:21:00.000Z', 'privateDnsNameOptions': {'hostnameType': 'ip-name', 'enableResourceNameDnsARecord': 'false', 'enableResourceNameDnsAAAARecord': 'false'}}}}]
[DEBUG   ] Waiting for VM IP. Giving up in 00:10:00.
[DEBUG   ] Using AWS endpoint: ec2.us-west-2.amazonaws.com
[DEBUG   ] AWS Request: https://ec2.us-west-2.amazonaws.com/?Action=DescribeInstances&InstanceId.1=i-XXXXXXXXXXXXXXXXX&Version=2016-11-15
[DEBUG   ] Starting new HTTPS connection (1): ec2.us-west-2.amazonaws.com:443
[DEBUG   ] https://ec2.us-west-2.amazonaws.com:443 "GET /?Action=DescribeInstances&InstanceId.1=i-XXXXXXXXXXXXXXXXX&Version=2016-11-15 HTTP/1.1" 200 None
[DEBUG   ] AWS Response Status Code: 200
[DEBUG   ] Returned query data: [{'reservationId': 'r-XXXXXXXXXXXXXXXXX', 'ownerId': 'XXXXXXXXXXXX', 'groupSet': None, 'instancesSet': {'item': {'instanceId': 'i-XXXXXXXXXXXXXXXXX', 'imageId': 'ami-XXXXXXXXXXXXXXXXX', 'instanceState': {'code': '0', 'name': 'pending'}, 'privateDnsName': 'ip-172-31-80-20.us-west-2.compute.internal', 'dnsName': None, 'reason': None, 'keyName': 'root@salt-master (staging)', 'amiLaunchIndex': '0', 'productCodes': None, 'instanceType': 't4g.nano', 'launchTime': '2022-06-24T00:21:00.000Z', 'placement': {'availabilityZone': 'us-west-2b', 'groupName': None, 'tenancy': 'default'}, 'monitoring': {'state': 'disabled'}, 'subnetId': 'subnet-XXXXXXXX', 'vpcId': 'vpc-XXXXXXXX', 'privateIpAddress': '172.31.80.20', 'sourceDestCheck': 'true', 'groupSet': {'item': [{'groupId': 'sg-XXXXXXXXXXXXXXXXX', 'groupName': 'XXXXXXXXXXXXXXXXX'}, {'groupId': 'sg-XXXXXXXX', 'groupName': 'default'}]}, 'architecture': 'arm64', 'rootDeviceType': 'ebs', 'rootDeviceName': '/dev/xvda', 'blockDeviceMapping': None, 'virtualizationType': 'hvm', 'clientToken': None, 'hypervisor': 'xen', 'networkInterfaceSet': {'item': [{'networkInterfaceId': 'eni-XXXXXXXXXXXXXXXXX', 'subnetId': 'subnet-XXXXXXXX', 'vpcId': 'vpc-XXXXXXXX', 'description': None, 'ownerId': '702650179727', 'status': 'in-use', 'macAddress': '06:60:ef:b1:b4:73', 'privateIpAddress': '172.31.80.20', 'privateDnsName': 'ip-172-31-80-20.us-west-2.compute.internal', 'sourceDestCheck': 'true', 'groupSet': {'item': [{'groupId': 'sg-0550caeffc9fe5a21', 'groupName': 'salt-vpn-internal'}, {'groupId': 'sg-a8bf39cd', 'groupName': 'default'}]}, 'attachment': {'attachmentId': 'eni-attach-XXXXXXXXXXXXXXXXX', 'deviceIndex': '0', 'status': 'attaching', 'attachTime': '2022-06-24T00:21:00.000Z', 'deleteOnTermination': 'false', 'networkCardIndex': '0'}, 'privateIpAddressesSet': {'item': {'privateIpAddress': '172.31.80.20', 'privateDnsName': 'ip-172-31-80-20.us-west-2.compute.internal', 'primary': 'true'}}, 'ipv6AddressesSet': None, 'interfaceType': 'interface'}, {'networkInterfaceId': 'eni-XXXXXXXXXXXXXXXXX', 'subnetId': 'subnet-XXXXXXXX', 'vpcId': 'vpc-XXXXXXXX', 'description': None, 'ownerId': 'XXXXXXXXXXXX', 'status': 'in-use', 'macAddress': '06:cd:84:a1:93:ef', 'privateIpAddress': '172.31.144.20', 'privateDnsName': 'ip-172-31-144-20.us-west-2.compute.internal', 'sourceDestCheck': 'true', 'groupSet': {'item': {'groupId': 'sg-XXXXXXXX', 'groupName': 'default'}}, 'attachment': {'attachmentId': 'eni-attach-XXXXXXXXXXXXXXXXX', 'deviceIndex': '1', 'status': 'attaching', 'attachTime': '2022-06-24T00:21:00.000Z', 'deleteOnTermination': 'false', 'networkCardIndex': '0'}, 'privateIpAddressesSet': {'item': {'privateIpAddress': '172.31.144.20', 'privateDnsName': 'ip-172-31-144-20.us-west-2.compute.internal', 'primary': 'true'}}, 'ipv6AddressesSet': None, 'interfaceType': 'interface'}]}, 'iamInstanceProfile': {'arn': 'arn:aws:iam::XXXXXXXXXXXX:instance-profile/XXXXXXXXXXXXXXX', 'id': 'XXXXXXXXXXXXXXXXXXXXX'}, 'ebsOptimized': 'false', 'enaSupport': 'true', 'cpuOptions': {'coreCount': '2', 'threadsPerCore': '1'}, 'capacityReservationSpecification': {'capacityReservationPreference': 'open'}, 'hibernationOptions': {'configured': 'false'}, 'enclaveOptions': {'enabled': 'false'}, 'metadataOptions': {'state': 'pending', 'httpTokens': 'optional', 'httpPutResponseHopLimit': '1', 'httpEndpoint': 'enabled', 'httpProtocolIpv4': 'enabled', 'httpProtocolIpv6': 'disabled', 'instanceMetadataTags': 'disabled'}, 'maintenanceOptions': {'autoRecovery': 'default'}, 'bootMode': 'uefi', 'platformDetails': 'Linux/UNIX', 'usageOperation': 'RunInstances', 'usageOperationUpdateTime': '2022-06-24T00:21:00.000Z', 'privateDnsNameOptions': {'hostnameType': 'ip-name', 'enableResourceNameDnsARecord': 'false', 'enableResourceNameDnsAAAARecord': 'false'}}}}]

Interesting that the query is called before the line Waiting for VM IP. Giving up in 00:10:00. (and also odd that the same URL is called twice). My initial thought was that the first call is a bug and should never happen.

The first query output for that URL is prefixed with The query returned (instead of Returned query data), so we can be confident the problem is with the query_instance() function getting called early in a way that is dying. In cli.py we can see that the generic exception handler which wraps "create" will result in the There was a query error message on any unhandled exception.

I'm guessing that either somewhere in query() (in utils/aws.py) an exception is getting thrown that is not explicitly handled (but hidden behind the cli general exception handler), or that the data that is returned as a 200 response but does not actually contain the expected data.

In case someone would like to look into this more closely, it's perhaps worth mentioning is that I do not use spot instances, so those code paths are never taken in my case.

Steps to Reproduce the behavior
Just run salt-cloud -m <some map file> with normal logging and be unlucky.

Expected behavior
The instance launched successfully, as per usual.

Versions Report

Salt Version:
          Salt: 3004.1
 
Dependency Versions:
          cffi: Not Installed
      cherrypy: Not Installed
      dateutil: 2.7.3
     docker-py: Not Installed
         gitdb: 2.0.5
     gitpython: 2.1.11
        Jinja2: 2.10
       libgit2: Not Installed
      M2Crypto: Not Installed
          Mako: Not Installed
       msgpack: 0.5.6
  msgpack-pure: Not Installed
  mysql-python: Not Installed
     pycparser: Not Installed
      pycrypto: 2.6.1
  pycryptodome: 3.6.1
        pygit2: Not Installed
        Python: 3.7.3 (default, Jan 22 2021, 20:04:44)
  python-gnupg: 0.4.4
        PyYAML: 3.13
         PyZMQ: 17.1.2
         smmap: 2.0.5
       timelib: Not Installed
       Tornado: 4.5.3
           ZMQ: 4.3.1
 
System Versions:
          dist: debian 10 buster
        locale: UTF-8
       machine: aarch64
       release: 4.19.0-20-arm64
        system: Linux
       version: Debian GNU/Linux 10 buster

If I am later able to pinpoint the issue more precisely, I'll provide an update.

Start with cli.py's create exception path and the query_instance()/query() flow in utils/aws.py; reproduce salt-cloud -m with normal and debug logging and compare the DescribeInstances calls. Done means the intermittent launch completes with the Name tag and salt-key generated, and created network interfaces have Delete on termination set.