cli: Output on the console even with --log-file

In 51f89902 (slapos/cli/entry.py, slapos/cli/format.py, slapos/format.py:
Do not double the log output when "slapos node boot" failed., 2017-05-11)
we fixed a problem that every failure during boot causing twice more output
(which filled up the disk very fast), but a side effect was that using
--log-file no longer cause messages to also go to the console.

The "Always send higher-level messages to the console via stderr" comment
in entry.py seems that this was always intentional to output messages on
the console.

Keep the same "don't configure again logging system when it's already
configured", but implemented in a slightly different way, because since
a FileHandler is a StreamHandler, the check of already having a
StreamHandler was true also for the case where --log-file added a
FileHander (a few lines above, also in configure_logging method)

slapos/cli/entry.py

@@ -121,6 +121,8 @@ class SlapOSHelpAction(argparse.Action):
         return group, '  %-13s  %s\n' % (name, one_liner)
 
 
+_logging_configured = []
+
 class SlapOSApp(App):
 
     #
@@ -230,6 +232,11 @@ class SlapOSApp(App):
     def configure_logging(self):
         """Create logging handlers for any log output.
         """
+        if _logging_configured:
+            # This function is called again if "slapos node boot" failed.
+            # Don't add a handler again, otherwise the output becomes double.
+            return
+
         root_logger = logging.getLogger('')
         root_logger.setLevel(logging.DEBUG)
 
@@ -243,13 +250,6 @@ class SlapOSApp(App):
             root_logger.addHandler(file_handler)
 
         # Always send higher-level messages to the console via stderr
-
-        # This function is called again if "slapos node boot" failed.
-        # Don't add a handler again, otherwise the output becomes double.
-        if [handler for handler in root_logger.handlers
-            if isinstance(handler, logging.StreamHandler)]:
-          return
-
         if self.options.log_color:
             from slapos.cli import coloredlogs
             console = coloredlogs.ColoredStreamHandler(show_name=True,     # logger name (slapos) and PID
@@ -266,7 +266,8 @@ class SlapOSApp(App):
         formatter = logging.Formatter(self.CONSOLE_MESSAGE_FORMAT)
         console.setFormatter(formatter)
         root_logger.addHandler(console)
-        return
+        _logging_configured.append(True)
+
 
     def run(self, argv):
         # same as cliff.app.App.run except that it won't re-raise

slapos/tests/test_cli.py

@@ -339,6 +339,40 @@ class TestCliBoot(CliMixin):
       self.assertFalse(os.path.exists(timestamp),
               timestamp)
 
+  def test_boot_failure(self):
+    # In this test, node and bang command will fail two time each.
+    # `slapos node boot` command retries on failures.
+
+    app = slapos.cli.entry.SlapOSApp()
+    with patch('slapos.cli.boot.check_root_user', return_value=True) as check_root_user,\
+        patch('slapos.cli.boot.sleep') as sleep,\
+        patch('slapos.cli.boot.netifaces.ifaddresses',
+              return_value={socket.AF_INET6: ({'addr': '2000::1'},),},),\
+        patch('slapos.cli.boot._ping_hostname', return_value=0),\
+        patch('slapos.cli.format.check_root_user', return_value=True),\
+        patch('slapos.cli.format.logging.FileHandler', return_value=logging.NullHandler()),\
+        patch('slapos.cli.bang.check_root_user', return_value=True),\
+        patch('slapos.cli.format.do_format', side_effect=[Exception, Exception, None]) as do_format,\
+        patch('slapos.cli.bang.do_bang', side_effect=[Exception, Exception, None]) as do_bang:
+
+      app.run(('node', 'boot'))
+
+    check_root_user.assert_called_once()
+
+    self.assertEqual(do_format.call_count, 3)
+    self.assertEqual(do_bang.call_count, 3)
+
+    # between retries we sleep 15 seconds.
+    sleep.assert_called_with(15)
+
+    # we have only one logger on the console
+    from slapos.cli import coloredlogs
+    self.assertEqual(
+        len([
+            h for h in logging.getLogger('').handlers
+            if isinstance(h, coloredlogs.ColoredStreamHandler)
+        ]), 1)
+
 
 class TestCliNode(CliMixin):