Add a stdout handler for subprocess while testing

* As we can't sneak in the process to add the handler to fetch warnings and
  errors, use another LOG_CFG for testing which set the default level on
  stdout as warning.
* Remove the on test_basics_cli the first INFO message, which corresponds to
  inform which level setting was set.

confs/testingsubprocess.logcfg

@@ -0,0 +1,41 @@
+version: 1
+disable_existing_loggers: False
+formatters:
+    simple:
+        format: "[%(name)s] %(levelname)s: %(message)s"
+    with_time:
+        format: "%(asctime)s [%(name)s] %(levelname)s: %(message)s"
+handlers:
+    console:
+        class: logging.StreamHandler
+        level: WARNING
+        formatter: simple
+        stream: ext://sys.stdout
+    debug_file_handler:
+        class: logging.handlers.RotatingFileHandler
+        level: DEBUG
+        formatter: with_time
+        filename: debug.log
+        maxBytes: 10485760 # 10MB
+        backupCount: 20
+        encoding: utf8
+    info_file_handler:
+        class: logging.handlers.RotatingFileHandler
+        level: INFO
+        formatter: with_time
+        filename: info.log
+        maxBytes: 10485760 # 10MB
+        backupCount: 20
+        encoding: utf8
+    warn_error_file_handler:
+        class: logging.handlers.RotatingFileHandler
+        level: WARNING
+        formatter: with_time
+        filename: errors.log
+        maxBytes: 10485760 # 10MB
+        backupCount: 20
+        encoding: utf8
+root:
+    level: DEBUG
+    handlers: [console, debug_file_handler, info_file_handler, warn_error_file_handler]
+

runtests

@@ -32,8 +32,11 @@ config_dir = os.path.join(root_dir, 'confs')
 DEBUG_CONFIG_FILE = os.path.join(config_dir, "debug.nose")
 COVERAGE_CONFIG_FILE = os.path.join(config_dir, "prod.nose")
 TESTS_DIR = os.path.join(root_dir, 'tests')
-DEBUG_LOG_CONFIG =os.path.join(config_dir, "debug.logcfg")
-TESTING_LOG_CONFIG =os.path.join(config_dir, "testing.logcfg")
+DEBUG_LOG_CONFIG = os.path.join(config_dir, "debug.logcfg")
+TESTING_LOG_CONFIG = os.path.join(config_dir, "testing.logcfg")
+# subprocess need to output on stdout the logs to be monitored
+# the profile is the testing one + console output in warning mode
+TESTING_SUBPROCESS_LOG_CONFIG = os.path.join(config_dir, "testing.subprocess.logcfg")
 
 
 def transform_nose_config_to_cmd(filename):
@@ -64,7 +67,9 @@ def set_logging_profile(log_config_file):
     with open(log_config_file, 'rt') as f:
         logging_config = yaml.load(f.read())
     logging.config.dictConfig(logging_config)
-    os.putenv("LOG_CFG", log_config_file)
+    os.putenv("LOG_CFG", TESTING_LOG_CONFIG)
+    if log_config_file == TESTING_LOG_CONFIG:
+        os.putenv("LOG_CFG", TESTING_SUBPROCESS_LOG_CONFIG)
 
 
 if __name__ == '__main__':

tests/large/test_basics_cli.py

@@ -30,6 +30,10 @@ def command_as_list(self, commands_input):
         """passthrough, return args"""
         return commands_input
 
+    def return_without_first_output(self, stdout):
+        """We return ignoring the first line which is INFO: set logging level to"""
+        return "\n".join(stdout.split('\n')[1:])
+
     def test_global_help(self):
         """We display a global help message"""
         result = subprocess.check_output(self.command_as_list([UDTC, '--help']))
@@ -39,13 +43,13 @@ def test_setup_info_logging(self):
         """We display info logs"""
         result = subprocess.check_output(self.command_as_list([UDTC, '-v', '--help']),
                                          stderr=subprocess.STDOUT)
-        self.assertIn("INFO:", result.decode("utf-8"))
+        self.assertIn("INFO:", self.return_without_first_output(result.decode("utf-8")))
 
     def test_setup_debug_logging(self):
         """We display debug logs"""
         result = subprocess.check_output(self.command_as_list([UDTC, '-vv', '--help']),
                                          stderr=subprocess.STDOUT)
-        self.assertIn("DEBUG:", result.decode("utf-8"))
+        self.assertIn("DEBUG:", self.return_without_first_output(result.decode("utf-8")))
 
     def test_setup_with_option_logging(self):
         """We don't mix info or debug logs with a -v<something> option"""
@@ -54,7 +58,7 @@ def test_setup_with_option_logging(self):
             subprocess.check_output(self.command_as_list([UDTC, '-vouep', '--help']),
                                     stderr=subprocess.STDOUT)
         except subprocess.CalledProcessError as e:
-            self.assertNotIn("INFO:", e.output.decode("utf-8"))
-            self.assertNotIn("DEBUG:", e.output.decode("utf-8"))
+            self.assertNotIn("INFO:", self.return_without_first_output(e.output.decode("utf-8")))
+            self.assertNotIn("DEBUG:", self.return_without_first_output(e.output.decode("utf-8")))
             exception_raised = True
         self.assertTrue(exception_raised)