Fix and improve nnictl warning message (#4430)

nni/experiment/config/convert.py

@@ -262,7 +262,7 @@ def to_v2(v1):
     if v1_trial:
         _logger.error('trial config not fully converted: %s', v1_trial)
     if v1:
-        _logger.error('config not fully converted: %s', v1)
+        _logger.error('Config not fully converted: %s', v1)
     return v2
 
 def _move_field(v1, v2, v1_key, v2_key=None):
@@ -275,7 +275,7 @@ def _move_field(v1, v2, v1_key, v2_key=None):
 
 def _drop_field(v1, key):
     if key in v1:
-        _logger.warning(f'Configuration field {key} is no longer supported and has been ignored')
+        _logger.warning(f'Config field "{key}" is no longer supported and has been ignored')
         v1.pop(key)
 
 def _deprecate(v1, v2, key):

nni/experiment/experiment.py

@@ -82,7 +82,7 @@ class Experiment:
         ...
 
     def __init__(self, config=None, training_service=None):
-        nni.runtime.log.init_logger_experiment()
+        nni.runtime.log.init_logger_for_command_line()
 
         self.config: Optional[ExperimentConfig] = None
         self.id: str = management.generate_experiment_id()

nni/runtime/log.py

@@ -44,17 +44,21 @@ def init_logger() -> None:
 
     logging.getLogger('filelock').setLevel(logging.WARNING)
 
-_exp_log_initialized = False
+_cli_log_initialized = False
 
-def init_logger_experiment() -> None:
+def init_logger_for_command_line() -> None:
     """
-    Initialize logger for `nni.experiment.Experiment`.
+    Initialize logger for command line usage.
+    This means that NNI is used as "main function" rather than underlying library or background service,
+    so it should print log to stdout.
+
+    It is used by nnictl and `nni.experiment.Experiment`.
 
     This function will get invoked after `init_logger()`.
     """
-    global _exp_log_initialized
-    if not _exp_log_initialized:
-        _exp_log_initialized = True
+    global _cli_log_initialized
+    if not _cli_log_initialized:
+        _cli_log_initialized = True
         colorful_formatter = Formatter(log_format, time_format)
         colorful_formatter.format = _colorful_format
         handlers['_default_'].setFormatter(colorful_formatter)
@@ -120,13 +124,17 @@ def _colorful_format(record):
         return '[{}] ({}) {}'.format(time, record.name, record.msg % record.args)
     if record.levelno >= logging.ERROR:
         color = colorama.Fore.RED
+        level = 'ERROR: '
     elif record.levelno >= logging.WARNING:
         color = colorama.Fore.YELLOW
+        level = 'WARNING: '
     elif record.levelno >= logging.INFO:
         color = colorama.Fore.GREEN
+        level = ''
     else:
         color = colorama.Fore.BLUE
-    msg = color + (record.msg % record.args) + colorama.Style.RESET_ALL
+        level = ''
+    msg = color + level + (record.msg % record.args) + colorama.Style.RESET_ALL
     if record.levelno < logging.INFO:
         return '[{}] {}:{} {}'.format(time, record.threadName, record.name, msg)
     else:

nni/tools/nnictl/launcher.py

@@ -2,6 +2,7 @@
 # Licensed under the MIT license.
 
 from getpass import getuser
+import logging
 from pathlib import Path
 import tempfile
 
@@ -10,12 +11,15 @@ import yaml
 
 from nni.experiment import Experiment, RunMode
 from nni.experiment.config import ExperimentConfig, convert, utils
+from nni.runtime.log import init_logger_for_command_line
 from nni.tools.annotation import expand_annotations, generate_search_space
 
 # used for v1-only legacy setup, remove them later
 from nni.experiment.launcher import get_stopped_experiment_config_json
 from . import legacy_launcher
 
+_logger = logging.getLogger(__name__)
+
 def create_experiment(args):
     # to make it clear what are inside args
     config_file = Path(args.config)
@@ -24,8 +28,13 @@ def create_experiment(args):
     url_prefix = args.url_prefix
     foreground = args.foreground
 
+    # it should finally be done in nnictl main function
+    # but for now don't break routines without logging support
+    init_logger_for_command_line()
+    logging.getLogger('nni').setLevel(logging.INFO)
+
     if not config_file.is_file():
-        print(Fore.RED + 'ERROR: "{config_file}" is not a valid file.' + Fore.RESET)
+        _logger.error('"{config_file}" is not a valid file.')
         exit(1)
 
     with config_file.open() as config:
@@ -47,10 +56,14 @@ def create_experiment(args):
         try:
             v2_config = convert.to_v2(config_content)
         except Exception:
-            print(Fore.RED + 'ERROR: You are using legacy config file, please update it to latest format.' + Fore.RESET)
-            print(Fore.RED + 'Reference: https://nni.readthedocs.io/en/stable/reference/experiment_config.html' + Fore.RESET)
+            _logger.error(
+                'You are using legacy config format with incorrect fields or values, '
+                'to get more accurate error message please update it to the new format.'
+            )
+            _logger.error('Reference: https://nni.readthedocs.io/en/stable/reference/experiment_config.html')
             exit(1)
-        print(Fore.YELLOW + f'WARNING: You are using legacy config file, please update it to latest format:' + Fore.RESET)
+        _logger.warning(f'You are using legacy config file, please update it to latest format:')
+        # use `print` here because logging will add timestamp and make it hard to copy paste
         print(Fore.YELLOW + '=' * 80 + Fore.RESET)
         print(yaml.dump(v2_config, sort_keys=False).strip())
         print(Fore.YELLOW + '=' * 80 + Fore.RESET)
@@ -85,6 +98,9 @@ def resume_experiment(args):
     foreground = args.foreground
     exp_dir = args.experiment_dir
 
+    init_logger_for_command_line()
+    logging.getLogger('nni').setLevel(logging.INFO)
+
     config_json = get_stopped_experiment_config_json(exp_id, exp_dir)
     if config_json.get('trainingServicePlatform'):
         legacy_launcher.resume_experiment(args)
@@ -99,6 +115,9 @@ def view_experiment(args):
     port = args.port
     exp_dir = args.experiment_dir
 
+    init_logger_for_command_line()
+    logging.getLogger('nni').setLevel(logging.INFO)
+
     config_json = get_stopped_experiment_config_json(exp_id, exp_dir)
     if config_json.get('trainingServicePlatform'):
         legacy_launcher.view_experiment(args)