Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fix NTLM auth API missing logs #8448

Merged
merged 6 commits into from
Jan 6, 2025
Merged

Fix NTLM auth API missing logs #8448

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
6 commits
Select commit Hold shift + click to select a range
3a5cab9
filter /ping request by filters
stgmsa Dec 18, 2024
48fa3cc
adds several common cases of NT Error.
stgmsa Dec 19, 2024
d11214c
adds another common error code.
stgmsa Dec 20, 2024
5c36efb
adds log.py to spec file
stgmsa Dec 30, 2024
7d5777a
remove file log handlers
stgmsa Jan 2, 2025
4ff8d7f
adds default log level support
stgmsa Jan 3, 2025
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
114 changes: 60 additions & 54 deletions bin/pyntlm_auth/config_loader.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -8,6 +8,7 @@
import config_generator
import global_vars
import utils
import log


def get_boolean_value(v):
Expand Down Expand Up @@ -38,45 +39,51 @@ def get_int_value(v):


def config_load():
global_vars.c_listen_port = os.getenv("LISTEN")
global_vars.c_domain_identifier = socket.gethostname() + " " + os.getenv("IDENTIFIER")
listen = os.getenv("LISTEN")
identifier = os.getenv("IDENTIFIER")

if global_vars.c_domain_identifier == "" or global_vars.c_listen_port == "":
print("Unable to start ntlm-auth-api: 'IDENTIFIER' or 'LISTEN' is missing.")
if not listen:
log.critical("unable to start ntlm-auth-api: missing environment variable 'LISTEN'")
exit(1)
if not identifier:
log.critical("unable to start ntlm-auth-api: missing environment variable 'IDENTIFIER'")
exit(1)

print(f"ntlm-auth-api@{global_vars.c_domain_identifier} on port {global_vars.c_listen_port}...")
global_vars.c_listen_port = os.getenv("LISTEN")
global_vars.c_domain_identifier = socket.gethostname() + " " + os.getenv("IDENTIFIER")

log.debug(f"ntlm-auth-api@{identifier} starting on port {global_vars.c_listen_port}")

identifier = global_vars.c_domain_identifier

conf_dm = "/usr/local/pf/conf/domain.conf"
cp_dm = ConfigParser(interpolation=None)
print(f"Load domain config from {conf_dm}")
log.debug(f"Load domain config from {conf_dm}")
try:
with open(conf_dm, 'r') as file:
cp_dm.read_file(file)
if identifier not in cp_dm:
print(f" Section {identifier} does not exist in domain.conf. Terminated.")
log.critical(f"Section {identifier} does not exist in domain.conf. Terminated.")
sys.exit(1)
except FileNotFoundError:
print(f" {conf_dm} not found or unreadable. Terminated.")
log.critical(f"{conf_dm} not found or unreadable. Terminated.")
sys.exit(1)
except configparser.Error as e:
print(f" Error loading config from domain.conf: {e}. Terminated.")
log.critical(f"Error loading config from domain.conf: {e}. Terminated.")
sys.exit(1)

conf_db = f"/usr/local/pf/var/conf/ntlm-auth-api.d/db.ini"
cp_db = ConfigParser(interpolation=None)
print(f"Load database config from {conf_db}")
log.debug(f"Load database config from {conf_db}")
try:
with open(conf_db, 'r') as file:
cp_db.read_file(file)
if 'DB' not in cp_db:
print(f" Section [DB] not found, ntlm-auth-api starts without NT Key caching capability.")
log.warning(f"Section [DB] not found, ntlm-auth-api starts without NT Key caching capability.")
except FileNotFoundError:
print(f" {conf_db} not found, ntlm-auth-api@{identifier} starts without NT Key caching capability.")
log.warning(f"{conf_db} not found, ntlm-auth-api@{identifier} starts without NT Key caching capability.")
stgmsa marked this conversation as resolved.
Show resolved Hide resolved
except configparser.Error as e:
print(f" Error loading {conf_db}: {e}, ntlm-auth-api@{identifier} starts without NT Key caching capability.")
log.warning(f"Error loading {conf_db}: {e}, ntlm-auth-api@{identifier} starts without NT Key caching capability.")

server_name_raw = cp_dm.get(identifier, 'server_name')
server_name_or_hostname = server_name_raw
Expand Down Expand Up @@ -111,46 +118,45 @@ def config_load():
c_db_pass = cp_db.get('DB', "DB_PASS", fallback=None)
c_db = cp_db.get('DB', "DB", fallback=None)
c_db_unix_socket = cp_db.get('DB', 'DB_UNIX_SOCKET', fallback=None)
print(f" {c_db_user}:{utils.mask_password(c_db_pass)}@{c_db_host}:{c_db_port}/{c_db}")
log.debug(f"db config: {c_db_user}:{utils.mask_password(c_db_pass)}@{c_db_host}:{c_db_port}/{c_db}")

# validate domain.conf
print(f"starting ntlm-auth-api@{identifier}")
if ad_fqdn == "":
print(" 'ad_fqdn' is not set. NTLM Auth API wasn't able to start")
log.critical("'ad_fqdn' is not set. NTLM Auth API wasn't able to start")
sys.exit(1)

if dns_servers != "":
config_generator.generate_resolv_conf(realm, dns_servers)
time.sleep(1)
ip, err_msg = utils.dns_lookup(ad_fqdn, "")
if ip != "" and err_msg == "":
print(f" AD FQDN: {ad_fqdn} resolved with IP: {ip}.")
log.debug(f"AD FQDN: {ad_fqdn} resolved with IP: {ip}.")
else:
if utils.is_ipv4(ad_server): # if it's not resolvable, we use static IP provided in domain.conf
print(f" AD FQDN resolving failed. Starting with static hosts entry: {ad_server} {ad_fqdn}.")
log.debug(f"AD FQDN resolving failed. Starting with static hosts entry: {ad_server} {ad_fqdn}.")
config_generator.generate_hosts_entry(ad_server, ad_fqdn)
else:
print(" Failed to retrieve IP address of AD server. Terminated.")
log.critical("Failed to retrieve IP address of AD server. Terminated.")
sys.exit(1)
else:
if utils.is_ipv4(ad_server):
config_generator.generate_hosts_entry(ad_server, ad_fqdn)
print(f" DNS servers not available, Starting using static hosts entry: {ad_server} {ad_fqdn}.")
log.warning(f"DNS servers not available, Starting using static hosts entry: {ad_server} {ad_fqdn}.")
else:
print(" Unable to start NTLM Auth API. 'ad_server' must be a valid IPv4 if DNS servers not specified.")
log.critical("Unable to start NTLM Auth API. 'ad_server' must be a valid IPv4 if DNS servers not specified.")
sys.exit(1)

print("NTLM Auth API started with the following parameters:")
print(f" ad_fqdn : {ad_fqdn}")
print(f" ad_server : {ad_server}")
print(f" server_name : {server_name_raw}")
print(f" server_name (parsed) : {server_name_or_hostname}")
print(f" dns_name : {realm}")
print(f" workgroup : {workgroup}")
print(f" machine_account_password : {utils.mask_password(password)}")
print(f" dns_servers : {dns_servers}")
print(f" nt_key_cache_enabled : {nt_key_cache_enabled}")
print(f" nt_key_cache_expire : {nt_key_cache_expire}")
log.debug("NTLM Auth API started with the following parameters:")
log.debug(f" ad_fqdn : {ad_fqdn}")
log.debug(f" ad_server : {ad_server}")
log.debug(f" server_name : {server_name_raw}")
log.debug(f" server_name (parsed) : {server_name_or_hostname}")
log.debug(f" dns_name : {realm}")
log.debug(f" workgroup : {workgroup}")
log.debug(f" machine_account_password : {utils.mask_password(password)}")
log.debug(f" dns_servers : {dns_servers}")
log.debug(f" nt_key_cache_enabled : {nt_key_cache_enabled}")
log.debug(f" nt_key_cache_expire : {nt_key_cache_expire}")

# validate NT Key cache configuration
nt_key_cache_enabled = get_boolean_value(nt_key_cache_enabled)
Expand All @@ -159,29 +165,29 @@ def config_load():
for i in range(1):
nt_key_cache_expire, error = get_int_value(nt_key_cache_expire)
if error is not None:
print(" NT Key cache: can not parse 'nt_key_cache_expire', cache disabled.")
log.warning(" NT Key cache: can not parse 'nt_key_cache_expire', cache disabled.")
nt_key_cache_enabled = False
break
if nt_key_cache_expire < 60:
print(f" NT key cache: expire value '{nt_key_cache_expire}' too small, set to minimum value: 60")
log.warning(f" NT key cache: expire value '{nt_key_cache_expire}' too small, set to minimum value: 60")
nt_key_cache_expire = 60
if nt_key_cache_expire > 864000:
print(f" NT key cache: expire value '{nt_key_cache_expire}' too large, set to maximum value: 864000")
log.warning(f" NT key cache: expire value '{nt_key_cache_expire}' too large, set to maximum value: 864000")
nt_key_cache_expire = 864000

ad_old_password_allowed_period, error = get_int_value(ad_old_password_allowed_period)
if error is not None:
print(f" NT Key cache: unable to parse 'ad_old_password_allowed_period', cache disabled.")
log.warning(f" NT Key cache: unable to parse 'ad_old_password_allowed_period', cache disabled.")
nt_key_cache_enabled = False
break
if ad_old_password_allowed_period < 0 or ad_old_password_allowed_period > 99999:
print(f" NT Key cache: 'ad_old_password_allowed_period' ranges from 0..99999, cache disabled.")
log.warning(f" NT Key cache: 'ad_old_password_allowed_period' ranges from 0..99999, cache disabled.")
nt_key_cache_enabled = False
break

ad_account_lockout_threshold, error = get_int_value(ad_account_lockout_threshold)
if error is not None:
print(" NT Key cache: can not parse 'ad_account_lockout_threshold', cache disabled.")
log.warning(" NT Key cache: can not parse 'ad_account_lockout_threshold', cache disabled.")
nt_key_cache_enabled = False
break
if ad_account_lockout_threshold == 0:
Expand All @@ -193,59 +199,59 @@ def config_load():
if error is not None: ad_old_password_allowed_period = 0
break
if ad_account_lockout_threshold < 2 or ad_account_lockout_threshold > 999:
print(f" NT Key cache: 'ad_account_lock_threshold' ranges from 2..999, cache disabled.")
log.warning(f" NT Key cache: 'ad_account_lock_threshold' ranges from 2..999, cache disabled.")
nt_key_cache_enabled = False
break

ad_account_lockout_duration, error = get_int_value(ad_account_lockout_duration)
if error is not None:
print(f" NT Key cache: can not parse 'account_lockout_duration', cache disabled.")
log.warning(f" NT Key cache: can not parse 'account_lockout_duration', cache disabled.")
nt_key_cache_enabled = False
break
if ad_account_lockout_duration < 1 or ad_account_lockout_duration > 99999:
print(f" NT Key cache: 'ad_account_lockout_duration' ranges from 1..99999, cache disabled.")
log.warning(f" NT Key cache: 'ad_account_lockout_duration' ranges from 1..99999, cache disabled.")
nt_key_cache_enabled = False
break

ad_reset_account_lockout_count_after, error = get_int_value(ad_reset_account_lockout_count_after)
if error is not None:
print(f" NT Key cache: can not parse 'ad_reset_account_lockout_after', cache disabled.")
log.warning(f" NT Key cache: can not parse 'ad_reset_account_lockout_after', cache disabled.")
nt_key_cache_enabled = False
break
if ad_reset_account_lockout_count_after < 1 or ad_reset_account_lockout_count_after > 99999:
print(f" NT Key cache: 'ad_reset_account_lockout_counter_after' ranges from 1..99999, cache disabled.")
log.warning(f" NT Key cache: 'ad_reset_account_lockout_counter_after' ranges from 1..99999, cache disabled.")
nt_key_cache_enabled = False
break
if ad_reset_account_lockout_count_after > ad_account_lockout_duration:
s_reset = 'ad_reset_account_lockout_counter_after'
s_duration = 'ad_account_lockout_duration'
print(f" NT Key cache: '{s_reset}' larger than '{s_duration}', cache disabled.")
log.warning(f" NT Key cache: '{s_reset}' larger than '{s_duration}', cache disabled.")
nt_key_cache_enabled = False
break

max_allowed_attempts_per_device, error = get_int_value(max_allowed_attempts_per_device)
s_device = 'max_allowed_attempts_per_device'
s_threshold = 'ad_account_lockout_threshold'
if error is not None:
print(f" NT Key cache: unable to parse '{s_device}', set to '{s_threshold}' by default.")
log.warning(f" NT Key cache: unable to parse '{s_device}', set to '{s_threshold}' by default.")
max_allowed_attempts_per_device = ad_account_lockout_threshold
break
if max_allowed_attempts_per_device < 0 or max_allowed_attempts_per_device > 999:
print(f" NT Key cache: '{s_device}' ranges from 0..999, set to '{s_threshold}' by default.")
log.warning(f" NT Key cache: '{s_device}' ranges from 0..999, set to '{s_threshold}' by default.")
break
if max_allowed_attempts_per_device > ad_account_lockout_threshold:
print(f" NT Key cache: '{s_device}' larger than '{s_threshold}', set to '{s_threshold}' by default.")
log.warning(f" NT Key cache: '{s_device}' larger than '{s_threshold}', set to '{s_threshold}' by default.")

if None in (c_db_host, c_db_port, c_db_user, c_db_pass, c_db, c_db_unix_socket):
print(f" DB config: Missing settings, NT Key cache will be disabled")
log.warning(f" DB config: Missing settings, NT Key cache will be disabled")
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This one should be a log.error no?
It will not allow to enable the cache.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

similar to the previous one, cache disabled. but still works.
I don't think this is an error or critical scenario.
they will only see the message during ntlm auth api starts.

nt_key_cache_enabled = False

print("NT Key caching:")
print(f" ad_account_lockout_threshold : {ad_account_lockout_threshold}")
print(f" ad_account_lockout_duration (in minutes) : {ad_account_lockout_duration}")
print(f" ad_reset_account_lockout_counter_after (in minutes) : {ad_reset_account_lockout_count_after}")
print(f" ad_old_password_allowed_period (in minutes) : {ad_old_password_allowed_period}")
print(f" max_allowed_password_attempts_per_device : {max_allowed_attempts_per_device}")
log.debug("NT Key caching:")
log.debug(f" ad_account_lockout_threshold : {ad_account_lockout_threshold}")
log.debug(f" ad_account_lockout_duration (in minutes) : {ad_account_lockout_duration}")
log.debug(f" ad_reset_account_lockout_counter_after (in minutes) : {ad_reset_account_lockout_count_after}")
log.debug(f" ad_old_password_allowed_period (in minutes) : {ad_old_password_allowed_period}")
log.debug(f" max_allowed_password_attempts_per_device : {max_allowed_attempts_per_device}")

global_vars.c_server_name = ad_fqdn
global_vars.c_ad_server = ad_server
Expand Down
60 changes: 60 additions & 0 deletions bin/pyntlm_auth/log.py
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1,60 @@
import logging
import os


def init_logging():
available_logging_levels = {'DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL'}
logging_level = os.getenv('LOG_LEVEL')

if not logging_level:
logging_level = 'DEBUG'

if logging_level not in available_logging_levels:
logging_level = 'DEBUG'

default_logging_level = logging.DEBUG
stgmsa marked this conversation as resolved.
Show resolved Hide resolved

if logging_level == 'INFO':
default_logging_level = logging.INFO
elif logging_level == 'WARNING':
default_logging_level = logging.WARNING
elif logging_level == 'ERROR':
default_logging_level = logging.ERROR
elif logging_level == 'CRITICAL':
default_logging_level = logging.CRITICAL

logger = logging.getLogger("ntlm-auth")
logger.setLevel(default_logging_level)

console_handler = logging.StreamHandler()
console_handler.setLevel(default_logging_level)

formatter = logging.Formatter('%(asctime)s - %(levelname)s - %(message)s', datefmt="%Y-%m-%d %H:%M:%S")
console_handler.setFormatter(formatter)

logger.addHandler(console_handler)

return logger


def debug(msg):
logger.debug(msg)


def info(msg):
logger.info(msg)


def warning(msg):
logger.warning(msg)


def error(msg):
logger.error(msg)


def critical(msg):
logger.critical(msg)


logger = init_logging()
6 changes: 4 additions & 2 deletions bin/pyntlm_auth/ms_event.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -2,6 +2,8 @@

import ncache
import utils
import log


EVENT_TYPE_USER_CREATED = 4720
EVENT_TYPE_USER_ENABLED = 4722
Expand Down Expand Up @@ -40,7 +42,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.debug(f"handling event password reset : happens on {utils.to_ymd_hms(event_time)} ({event_time}) for ID {record_id}: {account}@{domain} ")

key_root = ncache.build_cache_key(domain, account)
cache_entry_root = ncache.get_cache_entry(key_root)
Expand Down Expand Up @@ -76,7 +78,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.debug(f"handling event password change: happens on {utils.to_ymd_hms(event_time)} ({event_time}) for ID {record_id}: {account}@{domain} ")

key_root = ncache.build_cache_key(domain, account)
cache_entry_root = ncache.get_cache_entry(key_root)
Expand Down
5 changes: 3 additions & 2 deletions bin/pyntlm_auth/ncache.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -7,6 +7,7 @@

import utils
import datetime
import log

NT_KEY_USER_LOCKED = "*"
NT_KEY_USER_DISABLED = "-"
Expand Down Expand Up @@ -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']):
Expand Down Expand Up @@ -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']):
Expand Down
Loading
Loading