integration_tests: set log-cli-level to INFO by default

[OddBloke]

Proposed Commit Message

integration_tests: set log-cli-level to INFO by default

This gives us more detailed integration testing output by default.
This will make debugging failures reported by users/developers easier to
debug, as it removes the need for an initial round-trip to get the
output we need for debugging. It will also make debugging intermittent
failures easier: there will definitely be log output from runs which
exhibit the intermittent failure.

Test Steps

Run the integration tests without any CLI arguments and observe log output:

$ pytest tests/integration_tests/modules/test_ntp_servers.py
...
2020-12-18 15:20:52 INFO      integration_testing:clouds.py:73 Detected image: image_id=focal os=ubuntu release=focal
...

Run the unittests without any CLI arguments and observe no log output:

$ pytest
...

Run the integration tests with a different log level and observe it being honoured:

$ pytest --log-cli-level DEBUG tests/integration_tests/modules/test_ntp_servers.py
...
2020-12-18 15:22:18 INFO      integration_testing:clouds.py:73 Detected image: image_id=focal os=ubuntu release=focal
2020-12-18 15:22:18 DEBUG     pycloudlib.cloud:cloud.py:322 finding released Ubuntu image for focal
...

Run the integration tests with CRITICAL log level and observe no log output:

$ pytest --log-cli-level CRITICAL tests/integration_tests/modules/test_ntp_servers.py
...

Checklist:

• My code follows the process laid out in the documentation
• I have updated or added any unit tests accordingly
• I have updated or added any documentation accordingly

[TheRealFalcon]

Is there a way to make this play nicely with pytest's capture semantics? For me, running pytest without any arguments would ideally output something like this:

=================================================================================================================================== test session starts ====================================================================================================================================
platform linux -- Python 3.5.9, pytest-5.4.2, py-1.8.1, pluggy-0.13.1
rootdir: /home/james/cloud-init, inifile: tox.ini
plugins: cov-2.9.0
collected 1 item                                                                                                                                                                                                                                                                           

tests/integration_tests/test_example.py .                                                                                                                                                                                                                                            [100%]

=============================================================================================================================== 1 passed in 67.66s (0:01:07) ============================================================================================================================

whereas running pytest with -s would look like this:

/home/james/envs/cloud-init/lib/python3.5/site-packages/OpenSSL/crypto.py:12: CryptographyDeprecationWarning: Python 3.5 support will be dropped in the next release ofcryptography. Please upgrade your Python.
  from cryptography import x509
=================================================================================================================================== test session starts ====================================================================================================================================
platform linux -- Python 3.5.9, pytest-5.4.2, py-1.8.1, pluggy-0.13.1
rootdir: /home/james/cloud-init, inifile: tox.ini
plugins: cov-2.9.0
collected 1 item                                                                                                                                                                                                                                                                           

tests/integration_tests/test_example.py::test_ec2 Detected image: image_id=groovy os=ubuntu release=groovy

-------------------------------------------------------------------------------------------------------------------------------------- live log setup --------------------------------------------------------------------------------------------------------------------------------------
2020-12-18 16:55:02 INFO      integration_testing:clouds.py:77 Detected image: image_id=groovy os=ubuntu release=groovy
2020-12-18 16:55:02 INFO      botocore.credentials:credentials.py:1210 Found credentials in shared credentials file: ~/.aws/credentials
Detected image: image_id=groovy os=ubuntu release=groovy
2020-12-18 16:55:02 INFO      integration_testing:clouds.py:77 Detected image: image_id=groovy os=ubuntu release=groovy
Settings:
CLOUD_INIT_SOURCE=NONE
COLLECT_LOGS=NEVER
EXISTING_INSTANCE_ID=None
GCE_PROJECT=ubuntu-server-277015
GCE_REGION=us-central1
GCE_ZONE=a
INSTANCE_TYPE=None
KEEP_IMAGE=False
KEEP_INSTANCE=True
LOCAL_LOG_PATH=/tmp/cloud_init_test_logs
OCI_COMPARTMENT_ID=ocid1.compartment.oc1..aaaaaaaanz4b63fdemmuag77dg2pi22xfyhrpq46hcgdd3dozkvqfzwwjwxa
OS_IMAGE=groovy
PLATFORM=ec2
RUN_UNSTABLE=False
2020-12-18 16:55:12 INFO      integration_testing:clouds.py:109 Settings:
CLOUD_INIT_SOURCE=NONE
COLLECT_LOGS=NEVER
EXISTING_INSTANCE_ID=None
GCE_PROJECT=ubuntu-server-277015
GCE_REGION=us-central1
GCE_ZONE=a
INSTANCE_TYPE=None
KEEP_IMAGE=False
KEEP_INSTANCE=True
LOCAL_LOG_PATH=/tmp/cloud_init_test_logs
OCI_COMPARTMENT_ID=ocid1.compartment.oc1..aaaaaaaanz4b63fdemmuag77dg2pi22xfyhrpq46hcgdd3dozkvqfzwwjwxa
OS_IMAGE=groovy
PLATFORM=ec2
RUN_UNSTABLE=False
Launching instance with launch_kwargs:
user_data=None
wait=False
image_id=ami-04804ce6d06dadb2c
2020-12-18 16:55:12 INFO      integration_testing:clouds.py:152 Launching instance with launch_kwargs:
user_data=None
wait=False
image_id=ami-04804ce6d06dadb2c
2020-12-18 16:55:44 INFO      pycloudlib.instance:instance.py:166 executing: sh -c whoami
2020-12-18 16:55:45 INFO      pycloudlib.instance:instance.py:334 [Errno None] Unable to connect to port 22 on 18.219.124.143
Retrying ssh connection 60 more time(s) to  ubuntu@18.219.124.143:22
2020-12-18 16:55:55 INFO      paramiko.transport:transport.py:1819 Connected (version 2.0, client OpenSSH_8.3p1)
2020-12-18 16:55:55 INFO      paramiko.transport:transport.py:1819 Authentication (publickey) successful!
2020-12-18 16:55:57 INFO      pycloudlib.instance:instance.py:166 executing: sh -c 'cloud-init status --help'
2020-12-18 16:55:58 INFO      pycloudlib.instance:instance.py:166 executing: cloud-init status --wait --long
Launched instance: EC2Instance(key_pair=KeyPair(/home/james/.ssh/id_rsa, /home/james/.ssh/id_rsa.pub, name=james), client=<botocore.client.EC2 object at 0x7f3b9dc2db00>, instance=ec2.Instance(id='i-0e32faf4b29b8be52'))
2020-12-18 16:56:03 INFO      integration_testing:clouds.py:159 Launched instance: EC2Instance(key_pair=KeyPair(/home/james/.ssh/id_rsa, /home/james/.ssh/id_rsa.pub, name=james), client=<botocore.client.EC2 object at 0x7f3b9dc2db00>, instance=ec2.Instance(id='i-0e32faf4b29b8be52'))
-------------------------------------------------------------------------------------------------------------------------------------- live log call ---------------------------------------------------------------------------------------------------------------------------------------
2020-12-18 16:56:03 INFO      pycloudlib.instance:instance.py:166 executing: sudo -- sh -c 'cloud-init --version'
PASSED

=============================================================================================================================== 1 passed in 61.11s (0:01:01) =============================================================================================================================

[TheRealFalcon]

Regardless, I think this is ok. I think I would like a less verbose default option.

[OddBloke]

Regardless, I think this is ok. I think I would like a less verbose default option.

IMO, we want the default to be verbose: it makes the framework more accessible for folks who aren't familiar with it, and means that if someone copy-pastes their output, it's useful without explaining how to enable logging and a round-trip.

I've just tested, and PYTEST_ADDOPTS="--log-cli-level CRITICAL" pytest tests/integration_tests/modules/test_ntp_servers.py does not emit logs, but PYTEST_ADDOPTS="--log-cli-level CRITICAL" pytest --log-cli-level INFO tests/integration_tests/modules/test_ntp_servers.py does.

So if you'd like your local default to be different, you could set PYTEST_ADDOPTS="--log-cli-level CRITICAL" in your .(ba|z)shrc? Certainly not a perfect solution, but gets you what you want now. (We could also consider adding a distinct environment variable like CLOUD_INIT_LOG_LEVEL=..., so that you aren't modifying every pytest call on your system; that's left as an exercise to the reader, though. 😉)