[WIP] Add ability to configure logging for debugging

[josh146]

Context:

When debugging configuration and API access, it's useful to be able to output debugging logging information to a file. This can then be shared when requesting help.

Currently, Strawberry Fields performs logging of internal state and warning, but requires the user have knowledge of the Python logging module in order to modify the logging level/output the log information to a file.

Description of the Change:

• Adds a new section to the configuration pertaining to logging:

  [logging]
  # default logger output on the terminal
  level = "info"
  # optional logfile output
  logfile = "sf.log"

  By changing the level option, the user can specify the types of log messages that are displayed in the terminal when using the default SF logger. For instance, by setting level = "debug", more detailed information is output during execution.

  By setting the logfile option, the user can specify a logfile that is appended to during SF execution. Currently, the logfile contains all logged messages, of level DEBUG and up.

  Click here to see an example logfile created when submitting a remote program.

  ```console 2020-04-12 21:12:26,640 - DEBUG - Configuration file /home/josh/.config/strawberryfields/config.toml loaded 2020-04-12 21:12:26,641 - DEBUG - Loaded configuration: {'api': {'authentication_token': 'm8Tox***********************************', 'hostname': 'platform.strawberryfields.ai', 'use_ssl': True, 'port': 443}, 'logging': {'level': 'debug'}} 2020-04-12 21:12:26,641 - DEBUG - Compiling program for target X8_01 with compile options {} 2020-04-12 21:12:26,964 - DEBUG - Submitting job name test version 1.0 target X8_01 (shots=10) S2gate(0, 0) | [2, 6] S2gate(1, 0.0) | [1, 5] S2gate(0.0, 0.0) | [3, 7] S2gate(1.0, 0.0) | [0, 4] MZgate(5.3074357926500895, 1.5739876247864792) | [0, 1] MZgate(4.279290161703878, 4.202979995136468) | [2, 3] MZgate(5.824121814032434, 5.033017799971674) | [1, 2] MZgate(5.198882953351497, 3.715902833866422) | [0, 1] MZgate(4.712954779003035, 3.107023958221405) | [2, 3] MZgate(4.83853796968657, 5.988756943006127) | [1, 2] Rgate(0.6651640322699326) | 0 Rgate(0.06106261020227405) | 1 Rgate(2.94378117796741) | 2 Rgate(1.820738947340938) | 3 MZgate(5.3074357926500895, 1.5739876247864792) | [4, 5] MZgate(4.279290161703878, 4.202979995136468) | [6, 7] MZgate(5.824121814032434, 5.033017799971674) | [5, 6] MZgate(5.198882953351497, 3.715902833866422) | [4, 5] MZgate(4.712954779003035, 3.107023958221405) | [6, 7] MZgate(4.83853796968657, 5.988756943006127) | [5, 6] Rgate(0.6651640322699326) | 4 Rgate(0.06106261020227405) | 5 Rgate(2.94378117796741) | 6 Rgate(1.820738947340938) | 7 MeasureFock() | [0, 1, 2, 3, 4, 5, 6, 7] 2020-04-12 21:12:27,608 - INFO - Job d101fc18-289f-442b-a899-3d5a6d40fffc was successfully submitted. ```

  Note: these options only affect the built-in SF logger handlers. If the user creates their own custom logging handler, this overrides the SF built-in handlers.

• Adds a DEBUG log message on job submission, logging the submitted blackbird script.

• Adds a DEBUG log message on RemoteEngine.run_async(), providing details on program compilation if it occurs.

• Adds an INFO log message if the job is complete after a refresh

• Adds a sf.configuration.SESSION_CONFIG global variable that stores the configuration of Strawberry Fields as first import. This is used to configure the logger --- the configuration of the logger should not change after this.

• load_config() now logs debugging information, including the loaded configuration. Note that loaded API tokens are automatically masked.

• Minor refactor of the sf.configuration module:

  • The logging section has been added to DEFAULT_CONFIG_SPEC.

  • Some existing functions had hardcoded dependence on the "api" section of the configuration file. This has been removed; now no functions, except for store_account(), depend on the structure of the "api" section. As a result, create_config has been replaced with _generate_config, which automatically generates a default configuration object given a configuration spec.

  • find_config_file seemed to duplicate the logic in get_available_config_paths, so now depends on the former.

  • get_api_section was currently used only in load_config. Since load_config is now agnostic of the configuration structure, this function is redundant.

  • keep_valid_options was removed; in testing, it tended to lead to bad user experience to filter out unknown options. Typos (e.g., prot instead of port) would be pruned from the loaded configuration, making debugging difficult.

• Since there is now more than just an api section in the configuration, store_account now loads the existing configuration, modifies it as requested, and then re-writes it to disk. This avoids non-API configuration from being overwritten.

Benefits:

• Provides an interface for easy logging configuration for the user.

Possible Drawbacks:

• Currently, create_logger requires a loaded configuration to configure the logger. However, load_config creates a logger in order to log details about finding/loading the configuration! This leads to a circular dependency. Currently, this is avoided by passing logging=False to load_config on first load, to turn off any logging (since the logger has not been created yet). However, this is ugly, and bad form. If something goes wrong with the users logging configuration, it won't be logged!

• We could consider having a function sf.configure_logger() in order to configure the logging section of the config file within SF, similar to how sf.store_account() configures the API section. E.g.:

  >>> sf.configure_logger(level="debug", logfile="sf.log")

  However, since the logger is configured on import, these settings would not take affect until the next SF import.

Related GitHub Issues: n/a

[antalszava]

Seems like the circular dependency could be resolved by having module imports: https://stackoverflow.com/a/22210807/12899253

Edit: locally I also had to separate parsing logging optionsfunction into a load_logging_config() and used this in create_logger.

Overall the overhead of pulling the logging options each time create_logger runs does not seem to be something too significant.

This is also the reason why in #359 such a solution was chosen for Connection.__init__ and the previous module attribute was removed. This would help out also in having a configure_logger (the logging details being pulled dynamically means that after a call to configure_logger, create_logger will indeed be using the new options).

[thisac]

@josh146 There seem to be an issue with updating from environment variables. test_environment_variables_take_precedence_over_conf_file is failing, and by quickly looking at it it seems like the environment variables never overwrite the config (haven't run it yet though, only briefly looked at the code). :bug: