Add a trace level that logs each provider request

Level 1 answered the question it was built for and ruled out both
candidates. In test_create_and_list_image - 1400 of the AWS suite's 1407
seconds - only 207s is wait_for polling, and there were no botocore
retries anywhere in the run, so neither poll overhead nor throttling
explains it. The timeline is:

      0 ->    8 s   blocked
      8 ->  188 s   AMI -> available (173 polls, healthy)
    188 -> 1372 s   blocked, no polls, no retries
   1372 -> 1399 s   two instance deletions (12 polls each)

That 1184s stretch sits between the AMI becoming available and the
instance cleanup, which is where the test launches a second instance from
the AMI it just created. Nothing there polls through wait_for, so level 1
cannot see into it; the AWS provider does hold three boto3 waiters that
block silently, and any of them would look exactly like this.

Level 2 logs one line per boto invocation, so the gap between consecutive
lines is the call that blocked. Roughly 20x the volume, hence a separate
level rather than always on. Set it for the AWS suite.

Also stop treating "No retry needed." as a retry: botocore's two retry
implementations word the negative case differently, and only the
botocore.retries wording was being filtered out, so all 345 records level
1 collected were the quiet case.

tests/conftest.py

@@ -9,6 +9,7 @@ rather than the test as a whole.
 
 Set CB_TEST_TRACE=1 to capture, per xdist worker:
 
+
 * every ``wait_for`` poll, which brackets each wait - the span from a wait's
   first poll to its last is the wait itself, and the gap between consecutive
   polls shows whether the state call is slow (the interval is 1s for real
@@ -22,8 +23,15 @@ captures stderr at file-descriptor level, and captured output is discarded
 for passing tests - which these are. tox prints the files once the run
 finishes.
 
+CB_TEST_TRACE=2 additionally logs one line per boto invocation. Level 1
+answers whether time is going into polling or into throttled retries; when
+the answer is neither - as it was for test_create_and_list_image, where 1184
+of 1400 seconds passed in a single stretch with no polls and no retries at
+all - level 2 is what names the call that blocked, since the gap between two
+consecutive request lines is that request.
+
 Deliberately opt-in: at a 1s poll interval a 30 minute wait is ~1800 lines
-for a single waiting resource.
+for a single waiting resource, and level 2 is roughly 20x that again.
 """
 import logging
 import os
@@ -31,9 +39,19 @@ import os
 TRACE_FILE_PREFIX = 'cb-trace-'
 
 
-def _tracing_requested():
-    return (os.environ.get('CB_TEST_TRACE') or '').lower() in (
-        '1', 'true', 'yes')
+def _trace_level():
+    """
+    0 off; 1 waits and retries; 2 also every provider request.
+
+    Level 1 answers "is the time going into polling, or into throttled
+    retries" - it is cheap enough to leave on. Level 2 additionally logs each
+    boto invocation, so the gap between two consecutive lines names the call
+    that blocked; that is what level 1 cannot show, at perhaps 20x the volume.
+    """
+    raw = (os.environ.get('CB_TEST_TRACE') or '').lower()
+    if raw in ('2', 'requests', 'all'):
+        return 2
+    return 1 if raw in ('1', 'true', 'yes') else 0
 
 
 def _trace_path():
@@ -43,32 +61,41 @@ def _trace_path():
     return '{0}{1}.log'.format(TRACE_FILE_PREFIX, worker)
 
 
-class _WaitAndRetryOnly(logging.Filter):
+class _TraceFilter(logging.Filter):
     """
-    Keep the poll lines, the test markers and the retries; drop the rest.
+    Keep the test markers, the poll lines and genuine retries; at level 2
+    keep the provider request lines too, and drop everything else.
 
-    cloudbridge at DEBUG is far too chatty to keep wholesale - most of the
-    volume is per-request logging from the provider helpers, which says
-    nothing about where a wait went.
+    cloudbridge at DEBUG is far too chatty to keep wholesale - roughly 20x
+    the volume - and most of it says nothing about where the time went.
     """
 
+    def __init__(self, level):
+        super(_TraceFilter, self).__init__()
+        self.level = level
+
     def filter(self, record):
         message = record.getMessage()
         if record.name.startswith('botocore'):
-            # botocore logs a line per request either way; only the ones
-            # where it actually backed off say anything about throttling.
-            return not message.startswith('Not retrying')
+            # botocore logs a line per request whether or not it retried;
+            # only an actual backoff says anything about throttling. The two
+            # retry implementations word the negative case differently.
+            return not (message.startswith('Not retrying')
+                        or message.startswith('No retry needed'))
+        if record.name.startswith('cloudbridge.providers'):
+            return self.level >= 2
         return message.startswith('=== ') or 'Waiting another' in message
 
 
 def pytest_configure(config):
-    if not _tracing_requested():
+    level = _trace_level()
+    if not level:
         return
 
     handler = logging.FileHandler(_trace_path(), mode='w')
     handler.setFormatter(logging.Formatter(
         '%(asctime)s %(name)s %(message)s'))
-    handler.addFilter(_WaitAndRetryOnly())
+    handler.addFilter(_TraceFilter(level))
 
     # wait_for logs one line per poll at DEBUG, naming the object and the
     # state it is waiting on. Scope the level to that module rather than the
@@ -76,14 +103,17 @@ def pytest_configure(config):
     # provider request build a log record that the filter then discards, and
     # those records still propagate to pytest's own capture handler, which
     # holds them for the duration of the test.
-    waits = logging.getLogger('cloudbridge.base.resources')
-    waits.addHandler(handler)
-    waits.setLevel(logging.DEBUG)
-
-    # Quiet unless a request is actually retried, which is how throttling
-    # shows up client-side. Enabling botocore wholesale would log every
-    # request and response.
-    for name in ('botocore.retries', 'botocore.retryhandler'):
+    loggers = ['cloudbridge.base.resources',
+               # Quiet unless a request is actually retried, which is how
+               # throttling shows up client-side. Enabling botocore wholesale
+               # would log every request and response.
+               'botocore.retries', 'botocore.retryhandler']
+    if level >= 2:
+        # One line per boto invocation, so a stretch with no wait_for polling
+        # can still be attributed to the call that blocked.
+        loggers.append('cloudbridge.providers')
+
+    for name in loggers:
         target = logging.getLogger(name)
         target.addHandler(handler)
         target.setLevel(logging.DEBUG)
@@ -92,12 +122,12 @@ def pytest_configure(config):
 def pytest_runtest_logstart(nodeid, location):
     # Stamps the trace with test boundaries, so a span of polls can be
     # attributed to the test that caused it.
-    if _tracing_requested():
+    if _trace_level():
         logging.getLogger('cloudbridge.base.resources').debug(
             '=== START %s', nodeid)
 
 
 def pytest_runtest_logfinish(nodeid, location):
-    if _tracing_requested():
+    if _trace_level():
         logging.getLogger('cloudbridge.base.resources').debug(
             '=== END %s', nodeid)

tox.ini

@@ -33,7 +33,10 @@ setenv =
     # than in the workflow env because the cloud workflow triggers on
     # pull_request_target, so its definition comes from the base branch and a
     # PR cannot change it; tox.ini is checked out from the PR head and can.
-    aws: CB_TEST_TRACE=1
+    # Level 2 also logs each boto invocation. Level 1 already showed the AWS
+    # image test spends 1184 of its 1400 seconds in one stretch with no
+    # polling and no retries, so the remaining question is which call blocks.
+    aws: CB_TEST_TRACE=2
     azure: CB_TEST_PROVIDER=azure
     gcp: CB_TEST_PROVIDER=gcp
     openstack: CB_TEST_PROVIDER=openstack