backport ntlm auth api logs

bin/pyntlm_auth/entrypoint.py

@@ -1,10 +1,9 @@
-import logging
 import os
 import time
 from threading import Thread
 
 import pymysql
-from flask import Flask, g, request
+from flask import Flask, g
 from flaskext.mysql import MySQL
 
 import config_loader
@@ -13,6 +12,7 @@
 
 import t_health_checker
 import t_async_job
+import log
 
 app = Flask(__name__)
 
@@ -28,11 +28,11 @@
         global_vars.s_bind_account = m
         break
 
-    global_vars.s_worker.log.warning(f"failed to bind machine account: no available accounts, retrying.")
+    log.warning(f"failed to bind machine account: no available accounts, retrying.")
     time.sleep(1)
 
 config_loader.reload_worker_config()
-global_vars.s_worker.log.info(f"successfully registered with machine account '{m}', ready to handle requests.")
+log.info(f"successfully registered with machine account '{m}', ready to handle requests.")
 
 flask_jobs = (
     Thread(target=t_async_job.async_auth, daemon=False, args=(global_vars.s_worker,)),
@@ -43,17 +43,6 @@
 for job in flask_jobs:
     job.start()
 
-werkzeug_logger = logging.getLogger('werkzeug')
-
-
-@app.before_request
-def register_logger():
-    if request.path.startswith("/ping"):
-        werkzeug_logger.setLevel(logging.CRITICAL)
-    else:
-        werkzeug_logger.setLevel(logging.INFO)
-
-
 for i in range(1):
     if not global_vars.c_nt_key_cache_enabled:
         break
@@ -82,7 +71,7 @@ def before_request():
         except Exception as e:
             e_code = e.args[0]
             e_msg = str(e)
-            print(f"  error while init database: {e_code}, {e_msg}. Started without NT Key cache capability.")
+            log.warning(f"error while init database: {e_code}, {e_msg}. Started without NT Key cache capability.")
 
 
     @app.teardown_request

bin/pyntlm_auth/global_vars.py

@@ -1,4 +1,6 @@
 import datetime
+import log
+import utils
 
 _global_dict = {}
 
@@ -71,3 +73,42 @@ def get_value(key, value=None):
 c_ad_old_password_allowed_period = None  # Windows 2003+, Default not set, if not set, 60
 
 c_max_allowed_password_attempts_per_device = None
+
+
+def _debug():
+    log.debug("loaded global variables")
+    log.debug(f"---- Domain profile settings ----")
+    log.debug(f"global_vars.c_server_name                   {c_server_name}")
+    log.debug(f"global_vars.c_ad_server                     {c_ad_server}")
+    log.debug(f"global_vars.c_realm                         {c_realm}")
+    log.debug(f"global_vars.c_workgroup                     {c_workgroup}")
+    log.debug(f"global_vars.c_username                      {c_username}")
+    log.debug(f"global_vars.c_password                      {utils.mask_password(c_password)}")
+    log.debug(f"global_vars.c_additional_machine_accounts   {c_additional_machine_accounts}")
+    log.debug(f"global_vars.c_netbios_name                  {c_netbios_name}")
+    log.debug(f"global_vars.c_workstation                   {c_workstation}")
+    log.debug(f"global_vars.c_server_string                 {c_server_string}")
+    log.debug(f"global_vars.c_domain                        {c_domain}")
+    log.debug(f"global_vars.c_dns_servers                   {c_dns_servers}")
+
+    log.debug(f"---- NT Key cache ----")
+    log.debug(f"global_vars.c_nt_key_cache_enabled  {c_nt_key_cache_enabled}")
+    log.debug(f"global_vars.c_nt_key_cache_expire   {c_nt_key_cache_expire}")
+    log.debug(f"global_vars.c_ad_account_lockout_threshold              {c_ad_account_lockout_threshold}")
+    log.debug(f"global_vars.c_ad_account_lockout_duration               {c_ad_account_lockout_duration}")
+    log.debug(f"global_vars.c_ad_reset_account_lockout_counter_after    {c_ad_reset_account_lockout_counter_after}")
+    log.debug(f"global_vars.c_ad_old_password_allowed_period            {c_ad_old_password_allowed_period}")
+    log.debug(f"global_vars.c_max_allowed_password_attempts_per_device  {c_max_allowed_password_attempts_per_device}")
+
+    log.debug(f"---- Database ----")
+    log.debug(f"global_vars.c_db_host           {c_db_host}")
+    log.debug(f"global_vars.c_db_port           {c_db_port}")
+    log.debug(f"global_vars.c_db_user           {c_db_user}")
+    log.debug(f"global_vars.c_db_pass           {utils.mask_password(c_db_pass)}")
+    log.debug(f"global_vars.c_db                {c_db}")
+    log.debug(f"global_vars.c_db_unix_socket    {c_db_unix_socket}")
+
+    log.debug("---- Multi workers ----")
+    log.debug(f"global_vars.c_cache_host    {c_cache_host}")
+    log.debug(f"global_vars.c_cache_port    {c_cache_port}")
+    log.debug(f"global_vars.s_computer_account_base     {s_computer_account_base}")

bin/pyntlm_auth/gunicorn.conf.py

@@ -10,6 +10,7 @@
 import t_health_checker
 import t_sdnotify
 import t_worker_register
+import log
 
 import logging
 from gunicorn import glogging
@@ -34,10 +35,10 @@ def setup(self, cfg):
     LISTEN = os.getenv("LISTEN")
     bind_port = int(LISTEN)
 except ValueError:
-    print(f"invalid value for environment variable 'LISTEN', {NAME} terminated.")
+    log.critical(f"invalid value for environment variable 'LISTEN', {NAME} terminated.")
     sys.exit(1)
 except Exception as e:
-    print(f"failed to extract parameter 'LISTEN' from environment variable: {str(e)}. {NAME} terminated.")
+    log.critical(f"failed to extract parameter 'LISTEN' from environment variable: {str(e)}. {NAME} terminated.")
     sys.exit(1)
 
 config_loader.config_load()
@@ -54,7 +55,7 @@ def setup(self, cfg):
 
 accesslog = '-'
 errorlog = '-'
-loglevel = 'info'
+loglevel = 'debug'
 logger_class = CustomGunicornLogger
 capture_output = False
 access_log_format = '%(h)s %(l)s %(u)s %(p)s %(t)s "%(r)s" %(s)s %(b)s "%(f)s" "%(a)s"'
@@ -77,9 +78,15 @@ def on_starting(server):
     if not redis_client.init_connection():
         server.log.error("unable to initialize redis connection, terminated.")
         server.stop()
+
+    server.log.info("cleaning up machine account binding.")
     config_loader.cleanup_machine_account_binding(True)
     server.log.info("machine account binding clean up done.")
 
+    if "gunicorn.error" in logging.Logger.manager.loggerDict:
+        log.default_logger = logging.getLogger("gunicorn.error")
+        log.info("default logger set to 'gunicorn.error'.")
+
 
 def on_exit(server):
     server.log.info(f"master process on-exit clean up started...")

bin/pyntlm_auth/handlers.py

@@ -15,6 +15,7 @@
 import ncache
 import redis_client
 import rpc
+import log
 
 
 # For NTSTATUS, see:
@@ -47,13 +48,18 @@ def ping_handler():
 
 def ntlm_connect_handler():
     machine_accounts = config_loader.expand_machine_account_list()
+    log.debug(f"machine account expanded: {machine_accounts}")
 
     mapping, code, msg = _build_machine_account_bind_mapping(machine_accounts)
+    log.debug(f"machine account binding done, e = {code}, m = {msg}, r = {mapping}")
     if code != 0:
+        log.warning(f"failed retrieving machine account binding: e = {code}, m = {msg}")
         return msg, code
 
     job_id, code, msg = _submit_machine_account_test_job(machine_accounts)
+    log.debug(f"submitted machine account test job, e = {code}, m = {msg}, job_id = {job_id}")
     if code != 0:
+        log.warning(f"failed submitting machine account test job: e = {code}, m = {msg}")
         return msg, code
 
     results = _poll_machine_account_test_job_results(job_id, machine_accounts)

bin/pyntlm_auth/log.py

@@ -0,0 +1,66 @@
+import logging
+import os
+
+
+def detect_default_logging_level():
+    available_logging_levels = {'DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL'}
+    logging_level_str = os.getenv('LOG_LEVEL')
+
+    if not logging_level_str:
+        logging_level_str = 'DEBUG'
+
+    if logging_level_str not in available_logging_levels:
+        logging_level_str = 'DEBUG'
+
+    logging_level = logging.DEBUG
+
+    logging_level_str = logging_level_str.upper()
+    if logging_level_str == 'INFO':
+        logging_level = logging.INFO
+    elif logging_level_str == 'WARNING':
+        logging_level = logging.WARNING
+    elif logging_level_str == 'ERROR':
+        logging_level = logging.ERROR
+    elif logging_level_str == 'CRITICAL':
+        logging_level = logging.CRITICAL
+
+    return logging_level
+
+
+def init_logging():
+    logger_ntlm = logging.getLogger("ntlm-auth")
+    logging_level = detect_default_logging_level()
+    logger_ntlm.setLevel(logging_level)
+
+    console_handler = logging.StreamHandler()
+    console_handler.setLevel(logging_level)
+
+    formatter = logging.Formatter('%(asctime)s [%(process)d] [%(levelname)s] %(message)s', datefmt="[%Y-%m-%d %H:%M:%S %z]")
+    console_handler.setFormatter(formatter)
+
+    logger_ntlm.addHandler(console_handler)
+
+    return logger_ntlm
+
+
+def debug(msg):
+    default_logger.debug(msg)
+
+
+def info(msg):
+    default_logger.info(msg)
+
+
+def warning(msg):
+    default_logger.warning(msg)
+
+
+def error(msg):
+    default_logger.error(msg)
+
+
+def critical(msg):
+    default_logger.critical(msg)
+
+
+default_logger = init_logging()

bin/pyntlm_auth/ms_event.py

@@ -2,6 +2,7 @@
 
 import ncache
 import utils
+import log
 
 EVENT_TYPE_USER_CREATED = 4720
 EVENT_TYPE_USER_ENABLED = 4722
@@ -40,7 +41,7 @@ def process_event_password_reset(event):
     account = event['TargetUserName']
     event['EventTime'] = event_time
 
-    print(f"  ---- handling event password reset : happens on {utils.to_ymd_hms(event_time)} ({event_time}) for ID {record_id}: {account}@{domain} ")
+    log.info(f"password reset event: {utils.to_ymd_hms(event_time)}({event_time}). ID={record_id}, {account}@{domain}")
 
     key_root = ncache.build_cache_key(domain, account)
     cache_entry_root = ncache.get_cache_entry(key_root)
@@ -76,7 +77,7 @@ def process_event_password_change(event):
     account = event['TargetUserName']
     event['EventTime'] = event_time
 
-    print(f"  ---- handling event password change: happens on {utils.to_ymd_hms(event_time)} ({event_time}) for ID {record_id}: {account}@{domain} ")
+    log.info(f"password change event: {utils.to_ymd_hms(event_time)}({event_time}). ID={record_id}, {account}@{domain}")
 
     key_root = ncache.build_cache_key(domain, account)
     cache_entry_root = ncache.get_cache_entry(key_root)

bin/pyntlm_auth/ncache.py

@@ -7,6 +7,7 @@
 
 import utils
 import datetime
+import log
 
 NT_KEY_USER_LOCKED = "*"
 NT_KEY_USER_DISABLED = "-"
@@ -286,7 +287,7 @@ def device_miss_root_hit(domain, account_username, mac, challenge, nt_response,
         cache_v_root = json.loads(c_root['value'])
         cache_v_device = cache_v_template(domain, account_username, mac)
     except Exception as e:
-        print(f"  Exception caught while handling cached authentication, error was: {e}")
+        log.warning(f"Exception caught while handling cached authentication, error was: {e}")
         return '', -1, None
 
     if is_ndl(cache_v_root['nt_status']):
@@ -357,7 +358,7 @@ def device_hit_root_hit(domain, account_username, mac, challenge, nt_response, c
         cache_v_root = json.loads(c_root['value'])
         cache_v_device = json.loads(c_device['value'])
     except Exception as e:
-        print(f"  Exception caught while handling cached authentication, error was: {e}")
+        log.warning(f"Exception caught while handling cached authentication, error was: {e}")
         return '', -1, None
 
     if is_ndl(cache_v_root['nt_status']):

bin/pyntlm_auth/redis_client.py

@@ -2,6 +2,7 @@
 import redis
 
 import global_vars
+import log
 
 r = None
 namespace = f"ntlm-auth:{os.getenv('IDENTIFIER')}"
@@ -22,6 +23,6 @@ def init_connection():
         r.ping()
         return True
     except Exception as e:
-        print(f"unable to establish redis connection: {str(e)}")
+        log.warning(f"unable to establish redis connection: {str(e)}")
 
     return False