Improve logging

[lgarc15]

Summary

Addresses #524

Details and comments

This PR sets up a logger for the package, which allows loggers within the modules to inherit the correct level when the QISKIT_IBMQ_PROVIDER_LOG_LEVEL environment variable is set. Also, it allows users to specify a filename to place logs into, via the QISKIT_IBMQ_PROVIDER_LOG_FILE environment variable.

It also adds more debugging messages, using Session.request as the centralized logging placement.

An example of the log format is:

websocket.get_job_status:DEBUG:2020-03-17 16:21:45,632: Received message from websocket: {'hubInfo': '...', 'id': '5e70f8f18a2f2f0018e12452', 'endDate': '2020-03-17T16:21:43.196Z', 'backend': {'id': '5ae875670f020500393162ad', 'name': '...'}, 'kind': 'q-object-external-storage', 'status': 'COMPLETED', 'creationDate': '2020-03-17T16:21:05.284Z'}

The first part:
websocket.get_job_status:DEBUG:2020-03-17 16:21:45,632:
is formatted automatically.

The second part:
Received message from websocket: {'hubInfo': '...', 'id': '5e70f8f18a2f2f0018e12452', 'endDate': '2020-03-17T16:21:43.196Z', 'backend': {'id': '5ae875670f020500393162ad', 'name': '...'}, 'kind': 'q-object-external-storage', 'status': 'COMPLETED', 'creationDate': '2020-03-17T16:21:05.284Z'}
is the specified message to include in the log.

[jyu00]

Some response data is also worth logging - like job cancel which has not been super reliable.

[lgarc15]

TODO: Fix test_log_file since tests are run in parallel.

[jyu00]

Can you also add logging to websocket and ensure any causing exceptions are logged (e.g. if there's raise ex2 from ex1 make sure both ex2 and ex1 are logged)?

[jyu00]

One more comment. You mentioned that you wanted to reuse LOG_LEVEL for both test and mainline so the user doesn't have to specify two different variables. You can still accomplish this by manually setting the logging level of qiskit.providers.ibmq to LOG_LEVEL in IBMQTestCase.

[lgarc15]

One more comment. You mentioned that you wanted to reuse LOG_LEVEL for both test and mainline so the user doesn't have to specify two different variables. You can still accomplish this by manually setting the logging level of qiskit.providers.ibmq to LOG_LEVEL in IBMQTestCase.

Are you suggesting changing the level of the qiskit.providers.ibmq logger within the tests, to the level specified by LOG_LEVEL, when LOG_LEVEL is set as an environment variable?

[jyu00]

Some comments based on the Travis output:

• Drop %(name)s from the log format to shorten the log. %(module)s.%(funcName)s should be enough to tell us where it's from.
• Why is log level displayed as [secure]?
• Drop /devices/.../queue/status and /devices/v/1
• Log that we're uploading/downloading to/from object storage but don't log the actual url
• Log request data only for certain endpoints

[jyu00]

Are you suggesting changing the level of the qiskit.providers.ibmq logger within the tests, to the level specified by LOG_LEVEL, when LOG_LEVEL is set as an environment variable?

Yes, if the qiskit.providers.ibmq logger level is UNSET.

[lgarc15]

Why is log level displayed as [secure]?

This was the case because I had the setting in my Travis CI to hide the value set for QISKIT_IBMQ_PROVIDER_LOG_LEVEL. I unchecked the box, so the log level will be present in future runs.

Also, I added this into IBMQTestCase ✅:

One more comment. You mentioned that you wanted to reuse LOG_LEVEL for both test and mainline so the user doesn't have to specify two different variables. You can still accomplish this by manually setting the logging level of qiskit.providers.ibmq to LOG_LEVEL in IBMQTestCase.

[jyu00]

This looks good, just a few small suggestions.

[jyu00]

The docstring is now outdated with additional endpoints not being logged. It might be easier to either just say "not all endpoints are logged" or define a "constant" for excluded endpoints and just say those in the constant are not logged.

[lgarc15]

I separated filtering out url logs by introducing another private method _is_worth_logging(...), in order to make the filtering more readable and maintainable (in case we add other endpoints in the future). Would it be better to have a "constant" defined or would the function be an okay addition instead?

[jyu00]

I personally like a "constant" since it's obvious and easy to update, but it's not a big deal to just use the method.