SWAMPy

✎ CARVE FLESH

EDITING: log.py

# Module for logging in subprocess. Process related info (call stack) is logged
# to simplify investigation of lveclt hangings
#
# Copyright © Cloud Linux GmbH & Cloud Linux Software, Inc 2010-2024 All Rights Reserved
#
# Licensed under CLOUD LINUX LICENSE AGREEMENT
# http://cloudlinux.com/docs/LICENSE.TXT
# Base module for logging in subprocess
#
# Copyright © Cloud Linux GmbH & Cloud Linux Software, Inc 2010-2024 All Rights Reserved
#
# Licensed under CLOUD LINUX LICENSE AGREEMENT
# http://cloudlinux.com/docs/LICENSE.TXT
import logging
import os
import sys
import time

from cllvectl.base_subprocess_log import get_log_level, init_subprocess_logger as base_init_subprocess_logger

DEFAULT_LOG_FORMAT = '%(asctime)s - %(name)s - %(levelname)s - %(message)s'
LVECTL_SUBPROCESS_LOG_FILENAME = '/var/log/cloudlinux/lvectl-subprocess.log'
LVECTL_LOG_FILENAME = '/var/log/cloudlinux/lvectl.log'
LVECTL_LOGGER_NAME = 'lvectl'

# Captured when this module is first imported, which for lvectl is during its
# own imports -- close enough to process start for the duration in the closing
# record to be meaningful.
_STARTED_AT = time.monotonic()
# A parent's command line has no length bound (a shell -c wrapper runs to
# kilobytes) and the leading argv is what identifies the caller, so cap it
# rather than let one record dominate the log.
_MAX_PARENT_CMDLINE = 160
# Tokens that select an output format rather than name a command, skipped when
# falling back to argv for the name of the command that ran.
_NON_COMMAND_ARGS = frozenset(('json', 'no-iops', 'bytes'))
# Set by log_command() so the closing record names the command that ran rather
# than the raw argv; the two differ once json/no-iops flags are stripped out.
_running_command: str | None = None

# Control characters must never reach a record verbatim: a newline splits one
# record into two, and ESC reaches the terminal of whoever tails the log.
# Values that arrive from tenant-writable config (~/.lve/domains.json) are
# logged with %r, which escapes these already; this table is for the records
# whose message %r would make unreadable.
_LOG_CONTROL_CHARS = {c: f'\\x{c:02x}' for c in range(0x20)} | {0x7f: '\\x7f'}

def sanitize_for_log(message) -> str:
    """Escape control characters so untrusted text cannot forge log records.

:param message: value to render into a single-line record
    :return str: the text with control characters replaced by \\xNN escapes
    """
    try:
        return str(message).translate(_LOG_CONTROL_CHARS)
    except Exception:  # pylint: disable=broad-except
        return '<unprintable log message>'

def _lvectl_logger() -> logging.Logger:
    """The logger get_synchronous_logger('lvectl') configured, if it ran."""
    return logging.getLogger(LVECTL_LOGGER_NAME)

def describe_caller() -> str:
    """Describe this process and the one that invoked it.

lvectl is rarely run by hand: cagefsctl loops over it once per user,
    lveutils-panel-cron drives it every 5 minutes, lvemanager and the
    selectors shell out to it.  "Which of them ran this?" is the first
    question of most investigations and the answer is not recoverable from
    the log afterwards.

Every step is guarded: this only decorates a log record, so no failure
    to identify the caller may propagate into the command being reported
    on.  An unidentifiable caller degrades to '?', never to an exception.

:return str: 'pid=<n> ppid=<n> parent=<cmdline>', with '?' for any part
                 that could not be determined
    """
    try:
        pid: int | str = os.getpid()
    except Exception:  # pylint: disable=broad-except
        pid = '?'
    try:
        ppid: int | str = os.getppid()
    except Exception:  # pylint: disable=broad-except
        ppid = '?'
    parent = '?'
    try:
        with open(f'/proc/{ppid}/cmdline', 'rb') as fd:
            parent = fd.read().replace(b'\0', b' ').decode('utf-8', 'replace').strip() or '?'
        if len(parent) > _MAX_PARENT_CMDLINE:
            parent = parent[:_MAX_PARENT_CMDLINE] + '...'
    except Exception:  # pylint: disable=broad-except
        parent = '?'
    return f'pid={pid} ppid={ppid} parent={parent!r}'

def log_invocation(argv) -> None:
    """Record the invocation and who made it.

:param argv: the argument list as received, logged verbatim
    """
    _lvectl_logger().info('Called with args: %s (%s)', argv, describe_caller())

def log_command(command: str, **context) -> None:
    """Record a command and the values it resolved its arguments to.

log_invocation() says what the caller typed; this says what lvectl made
    of it -- the uid behind a username, the docroot and domain LVE id behind
    a domain name, the limits behind a --pmem=1G.  Keep the context to
    values a troubleshooter needs in order to correlate the log with ve.cfg
    and /proc/lve/map: this runs once per user of a `cagefsctl
    --isolates-allow-all` sweep.

:param str command: command name, also used to name the closing record
    :param context: resolved values to record, as key=repr pairs
    """
    global _running_command
    _running_command = command
    if context:
        details = ' '.join(f'{key}={value!r}' for key, value in context.items())
        _lvectl_logger().info('Running command %s: %s', command, details)
    else:
        _lvectl_logger().info('Running command %s', command)

def log_finished(exit_code) -> None:
    """Record how the run ended -- nothing logged the outcome before.

:param exit_code: the exit code the process is about to leave with
    """
    command = _running_command
    if command is None:
        # Listing commands log no dispatch record, and a run can fail before
        # dispatch; name it from argv so the outcome line stays identifiable.
        command = next(
            (arg for arg in sys.argv[1:]
             if not arg.startswith('-') and arg not in _NON_COMMAND_ARGS),
            'lvectl',
        )
    _lvectl_logger().info('Finished %s in %.3fs with exit code %s',
                          command, time.monotonic() - _STARTED_AT, exit_code)

def get_lvectl_child_logger(name: str) -> logging.Logger:
    """Logger for library code whose records belong in lvectl.log.

lveapi and lvectllib are shared with other entry points (cllimits,
    lvemanager, the panel cron), so they must not open lvectl.log
    themselves.  A child of the 'lvectl' logger inherits that logger's
    handler and level while lvectl is the running program, and is an
    inexpensive no-op under any other caller -- nothing else configures the
    'lvectl' logger, and the root logger has no handlers.

:param str name: child name, e.g. 'lveapi'
    :return logging.Logger: logger instance
    """
    return logging.getLogger(f'{LVECTL_LOGGER_NAME}.{name}')

def attach_to_lvectl_log(*logger_names: str, file_name: str = LVECTL_LOG_FILENAME) -> None:
    """Route foreign loggers' records into the lvectl.log handlers.

For third-party-shaped loggers that cannot be renamed into the 'lvectl'
    hierarchy because another tool configures them -- websiteisolation.* is
    owned by isolatectl, which points it at a per-user log.  Under lvectl
    those records had no handler anywhere and were discarded.

:param logger_names: logger names to attach
    :param str file_name: log file whose debug flag sets the level
    """
    parent = logging.getLogger(LVECTL_LOGGER_NAME)
    level = get_log_level(file_name)
    for name in logger_names:
        target = logging.getLogger(name)
        for handler in parent.handlers:
            if handler not in target.handlers:
                target.addHandler(handler)
        target.setLevel(level)

def get_subprocess_logger(name: str, file_name: str = LVECTL_SUBPROCESS_LOG_FILENAME) -> logging.Logger:
    """Get ordinary synchronous logger instance

:param str name: logger name
    :param str file_name: log file, defaults to LVECTL_LOG_FILENAME
    :return logging.Logger: logger instance
    """
    return base_init_subprocess_logger(name, file_name)

def get_synchronous_logger(name: str, file_name: str = LVECTL_LOG_FILENAME):
    logger = logging.getLogger(name)

fh = logging.FileHandler(file_name)
    fh.setFormatter(logging.Formatter(DEFAULT_LOG_FORMAT))
    log_level = get_log_level(file_name)
    fh.setLevel(log_level)
    logger.addHandler(fh)

logger.setLevel(log_level)

return logger

CANCEL

Name	Type	Size	Modified	Actions
↩ ..	DIR	—	—
📁 __pycache__/	DIR	—	2026-11-02 22:52
📄 __init__.py	PY	210 B	2026-10-16 11:34	EDIT
📄 base_subprocess_log.py	PY	9.7 KB	2026-10-16 11:34	EDIT
📄 log.py	PY	8.2 KB	2026-10-16 11:34	EDIT