From fb2b170001bf2bacaf551c477b59cacce05afece Mon Sep 17 00:00:00 2001 From: Claude Date: Fri, 30 Jan 2026 01:34:12 +0000 Subject: [PATCH 1/9] feat: Add --print-debug flag to control debug log output By default, debug-level logs are now disabled (no terminal output, no Unix socket transmission, no REST API exposure). This reduces noise in production environments. When --print-debug is passed to start_openplc.sh, it propagates to both the Python webserver and C runtime, enabling debug logs across all components: - C runtime: Only sets LOG_LEVEL_DEBUG when flag is passed - Python webserver: Sets handler levels to INFO by default, DEBUG with flag - Plugins: Automatically respect the C runtime log level https://claude.ai/code/session_01YaVx8wb6vyPSnyfYW6QYMP --- core/src/plc_app/plc_main.c | 15 ++++++++++++--- start_openplc.sh | 10 +++++++++- webserver/app.py | 11 +++++++++++ webserver/logger/__init__.py | 19 +++++++++++++++++++ webserver/logger/config.py | 1 + webserver/runtimemanager.py | 13 ++++++++++--- 6 files changed, 62 insertions(+), 7 deletions(-) diff --git a/core/src/plc_app/plc_main.c b/core/src/plc_app/plc_main.c index 5b106ecf..81da9ef3 100644 --- a/core/src/plc_app/plc_main.c +++ b/core/src/plc_app/plc_main.c @@ -35,18 +35,27 @@ void handle_sigint(int sig) int main(int argc, char *argv[]) { - // Check for --print-logs argument + bool print_debug = false; + + // Check for command line arguments for (int i = 1; i < argc; i++) { if (strcmp(argv[i], "--print-logs") == 0) { print_logs = true; - break; + } + if (strcmp(argv[i], "--print-debug") == 0) + { + print_debug = true; } } // Initialize logging system - log_set_level(LOG_LEVEL_DEBUG); + // Only enable debug level logging if --print-debug flag is passed + if (print_debug) + { + log_set_level(LOG_LEVEL_DEBUG); + } if (log_init(LOG_SOCKET_PATH) < 0) { diff --git a/start_openplc.sh b/start_openplc.sh index c4227268..b363bd3b 100755 --- a/start_openplc.sh +++ b/start_openplc.sh @@ -206,5 +206,13 @@ setup_plugin_venvs() { setup_plugin_venvs setup_runtime_venv +# Parse command line arguments +PRINT_DEBUG="" +for arg in "$@"; do + if [ "$arg" = "--print-debug" ]; then + PRINT_DEBUG="--print-debug" + fi +done + # Start the PLC webserver -"$OPENPLC_DIR/venvs/runtime/bin/python3" -m "webserver.app" +"$OPENPLC_DIR/venvs/runtime/bin/python3" -m "webserver.app" $PRINT_DEBUG diff --git a/webserver/app.py b/webserver/app.py index 99a59846..e0014cf3 100644 --- a/webserver/app.py +++ b/webserver/app.py @@ -1,3 +1,13 @@ +import sys + +# Parse --print-debug argument before any logger imports +# This must happen first so LoggerConfig.print_debug is set before loggers are created +_print_debug = "--print-debug" in sys.argv + +from webserver.logger.config import LoggerConfig + +LoggerConfig.print_debug = _print_debug + import errno import json import os @@ -43,6 +53,7 @@ runtime_path="./build/plc_main", plc_socket="/run/runtime/plc_runtime.socket", log_socket="/run/runtime/log_runtime.socket", + print_debug=_print_debug, ) runtime_manager.start() diff --git a/webserver/logger/__init__.py b/webserver/logger/__init__.py index 3dec2e03..df4ddc57 100644 --- a/webserver/logger/__init__.py +++ b/webserver/logger/__init__.py @@ -6,6 +6,7 @@ from .parser import LogParser from .bufferhandler import BufferHandler from .formatter import JsonFormatter +from .config import LoggerConfig __all__ = ["get_logger", "LogParser", "BufferHandler", "JsonFormatter"] __version__ = "0.1" @@ -19,20 +20,38 @@ formatter = JsonFormatter() shared_buffer_handler.setFormatter(formatter) + +def _get_effective_level(): + """Return the effective log level based on print_debug config.""" + return logging.DEBUG if LoggerConfig.print_debug else logging.INFO + + def get_logger(name="runtime", use_buffer: bool = False): """Return a logger that shares the same buffer handler.""" logger = logging.getLogger(name) logger.setLevel(logging.DEBUG) logger.propagate = False + effective_level = _get_effective_level() + # Always ensure a StreamHandler exists if not any(isinstance(h, logging.StreamHandler) for h in logger.handlers): stream_handler = logging.StreamHandler(sys.stdout) stream_handler.setFormatter(JsonFormatter()) + stream_handler.setLevel(effective_level) logger.addHandler(stream_handler) + else: + # Update existing StreamHandler level + for h in logger.handlers: + if isinstance(h, logging.StreamHandler) and not isinstance(h, BufferHandler): + h.setLevel(effective_level) if use_buffer: if not any(isinstance(h, BufferHandler) for h in logger.handlers): + shared_buffer_handler.setLevel(effective_level) logger.addHandler(shared_buffer_handler) + else: + # Update existing BufferHandler level + shared_buffer_handler.setLevel(effective_level) return logger, shared_buffer_handler diff --git a/webserver/logger/config.py b/webserver/logger/config.py index 219b3b22..6a40e270 100644 --- a/webserver/logger/config.py +++ b/webserver/logger/config.py @@ -6,6 +6,7 @@ class LoggerConfig: log_id: int = 0 log_level: int = logging.INFO use_buffer: bool = False + print_debug: bool = False _log_id_lock = threading.Lock() @classmethod diff --git a/webserver/runtimemanager.py b/webserver/runtimemanager.py index 659d37c0..84ac7b29 100644 --- a/webserver/runtimemanager.py +++ b/webserver/runtimemanager.py @@ -25,10 +25,11 @@ class RuntimeManager: - def __init__(self, runtime_path, plc_socket, log_socket): + def __init__(self, runtime_path, plc_socket, log_socket, print_debug=False): self.runtime_path = runtime_path self.plc_socket = plc_socket self.log_socket = log_socket + self.print_debug = print_debug self.process = None self.log_server = UnixLogServer(log_socket) self.runtime_socket = SyncUnixClient(plc_socket) @@ -131,7 +132,10 @@ def start(self): logger.info("Starting PLC runtime core...") self._safe_start_log_server() try: - self.process = subprocess.Popen([self.runtime_path]) + cmd = [self.runtime_path] + if self.print_debug: + cmd.append("--print-debug") + self.process = subprocess.Popen(cmd) except (OSError, subprocess.SubprocessError) as e: logger.error("Failed to start PLC runtime process: %s", e) self.process = None @@ -170,7 +174,10 @@ def _monitor(self): self._safe_start_log_server() try: - self.process = subprocess.Popen([self.runtime_path]) + cmd = [self.runtime_path] + if self.print_debug: + cmd.append("--print-debug") + self.process = subprocess.Popen(cmd) except (OSError, subprocess.SubprocessError) as e: logger.error("Failed to start PLC runtime process: %s", e) self.process = None From a329c0ae24c1bf1c267c02f138b7fd7e988a83ee Mon Sep 17 00:00:00 2001 From: Claude Date: Fri, 30 Jan 2026 02:37:14 +0000 Subject: [PATCH 2/9] refactor: Simplify start script to forward all arguments to Python Instead of parsing specific arguments in the bash script, forward all command line arguments directly to the Python webserver. This is more generic and allows future arguments to work without script modifications. https://claude.ai/code/session_01YaVx8wb6vyPSnyfYW6QYMP --- start_openplc.sh | 12 ++---------- 1 file changed, 2 insertions(+), 10 deletions(-) diff --git a/start_openplc.sh b/start_openplc.sh index b363bd3b..af80f517 100755 --- a/start_openplc.sh +++ b/start_openplc.sh @@ -206,13 +206,5 @@ setup_plugin_venvs() { setup_plugin_venvs setup_runtime_venv -# Parse command line arguments -PRINT_DEBUG="" -for arg in "$@"; do - if [ "$arg" = "--print-debug" ]; then - PRINT_DEBUG="--print-debug" - fi -done - -# Start the PLC webserver -"$OPENPLC_DIR/venvs/runtime/bin/python3" -m "webserver.app" $PRINT_DEBUG +# Start the PLC webserver (forward all arguments) +"$OPENPLC_DIR/venvs/runtime/bin/python3" -m "webserver.app" "$@" From 7e493c402e49a297cc3b5bfac47c884bdd06cbd8 Mon Sep 17 00:00:00 2001 From: Claude Date: Fri, 30 Jan 2026 02:38:43 +0000 Subject: [PATCH 3/9] fix: Address Copilot review comments - C runtime: Use else-if and early break when both flags are found to avoid redundant loop iterations - Python logger: Always update handler levels consistently regardless of whether handlers already exist, ensuring config changes are properly reflected https://claude.ai/code/session_01YaVx8wb6vyPSnyfYW6QYMP --- core/src/plc_app/plc_main.c | 8 +++++++- webserver/logger/__init__.py | 30 ++++++++++++++---------------- 2 files changed, 21 insertions(+), 17 deletions(-) diff --git a/core/src/plc_app/plc_main.c b/core/src/plc_app/plc_main.c index 81da9ef3..ade09a4c 100644 --- a/core/src/plc_app/plc_main.c +++ b/core/src/plc_app/plc_main.c @@ -44,10 +44,16 @@ int main(int argc, char *argv[]) { print_logs = true; } - if (strcmp(argv[i], "--print-debug") == 0) + else if (strcmp(argv[i], "--print-debug") == 0) { print_debug = true; } + + // Early exit if both flags are found + if (print_logs && print_debug) + { + break; + } } // Initialize logging system diff --git a/webserver/logger/__init__.py b/webserver/logger/__init__.py index df4ddc57..484fdad4 100644 --- a/webserver/logger/__init__.py +++ b/webserver/logger/__init__.py @@ -34,24 +34,22 @@ def get_logger(name="runtime", use_buffer: bool = False): effective_level = _get_effective_level() - # Always ensure a StreamHandler exists - if not any(isinstance(h, logging.StreamHandler) for h in logger.handlers): + # Ensure a StreamHandler exists + if not any( + isinstance(h, logging.StreamHandler) and not isinstance(h, BufferHandler) + for h in logger.handlers + ): stream_handler = logging.StreamHandler(sys.stdout) stream_handler.setFormatter(JsonFormatter()) - stream_handler.setLevel(effective_level) logger.addHandler(stream_handler) - else: - # Update existing StreamHandler level - for h in logger.handlers: - if isinstance(h, logging.StreamHandler) and not isinstance(h, BufferHandler): - h.setLevel(effective_level) - - if use_buffer: - if not any(isinstance(h, BufferHandler) for h in logger.handlers): - shared_buffer_handler.setLevel(effective_level) - logger.addHandler(shared_buffer_handler) - else: - # Update existing BufferHandler level - shared_buffer_handler.setLevel(effective_level) + + # Ensure BufferHandler exists if requested + if use_buffer and not any(isinstance(h, BufferHandler) for h in logger.handlers): + logger.addHandler(shared_buffer_handler) + + # Always update all handler levels to reflect current config + for h in logger.handlers: + if isinstance(h, logging.StreamHandler): + h.setLevel(effective_level) return logger, shared_buffer_handler From 3e81f98be553d89ca7cae715a5650b87614fe762 Mon Sep 17 00:00:00 2001 From: Thiago Alves Date: Fri, 30 Jan 2026 11:29:12 -0500 Subject: [PATCH 4/9] feat: Add human-readable log format for stdout output Replace JSON output with human-readable format for stdout logs: [YYYY-MM-DD HH:MM:SS] [LEVEL] message - Add HumanReadableFormatter class to formatter.py - Use HumanReadableFormatter for StreamHandler (stdout) - Keep JsonFormatter for BufferHandler (API responses) - Handle both Python-native logs and C runtime JSON logs - Convert Unix timestamps to human-readable datetime This is Phase 1 of the logging normalization effort. API endpoint /api/runtime-logs still returns JSON format. Co-Authored-By: Claude Opus 4.5 --- docs/LOGGING_NORMALIZATION_PLAN.md | 333 +++++++++++++++++++++++++++++ webserver/logger/__init__.py | 6 +- webserver/logger/formatter.py | 35 +++ webserver/logger/logger.py | 4 +- 4 files changed, 373 insertions(+), 5 deletions(-) create mode 100644 docs/LOGGING_NORMALIZATION_PLAN.md diff --git a/docs/LOGGING_NORMALIZATION_PLAN.md b/docs/LOGGING_NORMALIZATION_PLAN.md new file mode 100644 index 00000000..d233701d --- /dev/null +++ b/docs/LOGGING_NORMALIZATION_PLAN.md @@ -0,0 +1,333 @@ +# Logging Normalization Plan + +**Goal**: Unify all log output to a human-readable format for stdout while maintaining JSON for API responses. + +**Target Format**: +``` +[2024-01-30 12:00:00] [INFO] message +[2024-01-30 12:00:00] [WARN] warning message +[2024-01-30 12:00:00] [ERROR] error message +``` + +--- + +## Current State Analysis + +### Problem + +The codebase has **two parallel output mechanisms**: + +1. **Formal logging system** (JSON output): + - C side: `log_info()`, `log_error()`, etc. in `core/src/plc_app/utils/log.c` + - Python side: `logger.info()`, `logger.error()`, etc. + - Goes through UNIX socket, printed as JSON to stdout + +2. **Direct printf/print calls** (human-readable): + - C side: `printf()`, `fprintf(stderr)` scattered throughout code + - Python side: `print()` statements in various modules + +### Current Output (Mixed) + +``` +[PLUGIN]: Creating Python capsule for args +[PLUGIN]: Python capsule created successfully +[OPCUA INFO] OPC UA Plugin initializing... +{"timestamp": "1769785673", "level": "INFO", "message": "Logging initialized", "id": 8} +{"timestamp": "1769785673", "level": "INFO", "message": "Buffer accessor created", "id": 9} +``` + +--- + +## Implementation Plan + +### Phase 1: Update Python Logging System + +**Goal**: Change stdout output from JSON to human-readable format. + +#### Files to Modify + +| File | Change | +|------|--------| +| `webserver/logger/formatter.py` | Add `HumanReadableFormatter` class | +| `webserver/logger/__init__.py` | Use `HumanReadableFormatter` for `StreamHandler` (line 43) | +| `webserver/logger/logger.py` | Use `HumanReadableFormatter` for `StreamHandler` (line 19) | + +#### HumanReadableFormatter Implementation + +```python +class HumanReadableFormatter(logging.Formatter): + """Format log records as human-readable strings for stdout.""" + + def format(self, record): + msg = record.getMessage() + + # Try to detect pre-formatted JSON (from C runtime) + try: + log_entry = json.loads(msg) + timestamp = log_entry.get("timestamp", "") + level = log_entry.get("level", record.levelname) + message = log_entry.get("message", msg) + + # Convert Unix timestamp to human-readable + if timestamp and str(timestamp).isdigit(): + dt = datetime.fromtimestamp(int(timestamp), tz=timezone.utc) + timestamp = dt.strftime("%Y-%m-%d %H:%M:%S") + elif timestamp: + # Handle ISO 8601 format + dt = datetime.fromisoformat(timestamp.replace('Z', '+00:00')) + timestamp = dt.strftime("%Y-%m-%d %H:%M:%S") + else: + timestamp = datetime.now(timezone.utc).strftime("%Y-%m-%d %H:%M:%S") + + except (json.JSONDecodeError, ValueError): + # Not JSON - use record fields directly + timestamp = datetime.now(timezone.utc).strftime("%Y-%m-%d %H:%M:%S") + level = record.levelname + message = msg + + return f"[{timestamp}] [{level}] {message}" +``` + +#### Changes in `__init__.py` (line 43) + +```python +# Current: +stream_handler.setFormatter(JsonFormatter()) + +# New: +stream_handler.setFormatter(HumanReadableFormatter()) +``` + +#### Changes in `logger.py` (line 19) + +```python +# Current: +stream_handler.setFormatter(JsonFormatter()) + +# New: +stream_handler.setFormatter(HumanReadableFormatter()) +``` + +**Note**: `BufferHandler` keeps using `JsonFormatter` for API responses. + +--- + +### Phase 2: Convert C printf/fprintf to log_*() calls + +#### Files and Occurrence Count + +| File | printf | fprintf | Total | +|------|--------|---------|-------| +| `core/src/drivers/plugin_driver.c` | 41 | 32 | 73 | +| `core/src/drivers/plugin_config.c` | 2 | 0 | 2 | +| `core/src/drivers/plugins/native/plugin_logger.c` | 1 | 3 | 4 | +| `core/src/plc_app/plc_main.c` | 0 | 1 | 1 | +| `core/src/plc_app/journal_buffer.c` | 0 | 2 | 2 | +| `core/src/plc_app/utils/watchdog.c` | 0 | 1 | 1 | +| `core/src/plc_app/python_loader.c` | 0 | 1 | 1 | +| **Total** | **44** | **40** | **84** | + +**Skip** (not production code): +- `core/src/drivers/plugins/native/examples/test_plugin_loader.c` (test file) +- `core/src/drivers/README.md` (documentation examples) + +#### Conversion Rules + +| Original Pattern | Converted To | +|------------------|--------------| +| `printf("[PLUGIN]: %s\n", msg)` | `log_info("%s", msg)` | +| `printf("[PLUGIN]: ... successfully\n")` | `log_info("...")` | +| `fprintf(stderr, "[PLUGIN]: Error...\n")` | `log_error("...")` | +| `fprintf(stderr, "Failed to...\n")` | `log_error("Failed to...")` | +| `fprintf(stderr, "Warning:...\n")` | `log_warn("...")` | + +#### Main File: `core/src/drivers/plugin_driver.c` + +This file has the most occurrences. Key conversions: + +```c +// Current: +printf("[PLUGIN]: Config file %s not found, copying from plugins_default.conf\n", config_file); + +// Converted: +log_info("Config file %s not found, copying from plugins_default.conf", config_file); +``` + +```c +// Current: +fprintf(stderr, "[PLUGIN]: Error - driver is NULL\n"); + +// Converted: +log_error("Error - driver is NULL"); +``` + +```c +// Current: +printf("[PLUGIN]: Plugin %s started successfully.\n", plugin->config.name); + +// Converted: +log_info("Plugin %s started successfully", plugin->config.name); +``` + +**Note**: Need to include `log.h` header in files that don't already have it. + +--- + +### Phase 3: Convert Python print() to logger.*() calls + +#### Files and Occurrence Count + +| File | print() calls | Notes | +|------|---------------|-------| +| `webserver/plugin_config_model.py` | 6 | Config file operations | +| `webserver/credentials.py` | 10 | Certificate generation | +| `webserver/config.py` | 2 | Env validation | +| `webserver/app.py` | 2 | Platform detection | +| `core/src/drivers/plugins/python/modbus_master/modbus_master_memory.py` | ~20 | Error messages | +| **Total** | **~40** | | + +#### Conversion Rules + +| Original Pattern | Converted To | +|------------------|--------------| +| `print(f"[PLUGIN]: {msg}")` | `logger.info(msg)` | +| `print(f"[PLUGIN]: Failed to {x}")` | `logger.error(f"Failed to {x}")` | +| `print(f"Warning: {msg}")` | `logger.warning(msg)` | +| `print(f"Error: {msg}")` | `logger.error(msg)` | +| `print(f"Successfully {x}")` | `logger.info(f"Successfully {x}")` | + +#### Example: `webserver/plugin_config_model.py` + +```python +# Current: +print(f"[PLUGIN]: Config file {file_path} not found, copying from {default_file}") + +# Converted: +logger.info(f"Config file {file_path} not found, copying from {default_file}") +``` + +```python +# Current: +print(f"[PLUGIN]: Failed to copy {default_file}: {e}") + +# Converted: +logger.error(f"Failed to copy {default_file}: {e}") +``` + +#### Example: `webserver/credentials.py` + +```python +# Current: +print(f"Generating self-signed certificate for {self.hostname}...") + +# Converted: +logger.info(f"Generating self-signed certificate for {self.hostname}...") +``` + +```python +# Current: +print(f"Certificate saved to {cert_path}") + +# Converted: +logger.info(f"Certificate saved to {cert_path}") +``` + +**Note**: Each file needs to import the logger: +```python +from webserver.logger import get_logger +logger, _ = get_logger(__name__) +``` + +--- + +### Phase 4: Update Plugin Fallback Logging + +#### File: `core/src/drivers/plugins/python/opcua/opcua_logging.py` + +The fallback `print()` statements should match the standard format when runtime logging isn't available. + +```python +# Current fallback: +print(f"[OPCUA INFO] {message}", file=sys.stdout) + +# Updated fallback (matching standard format): +timestamp = datetime.now().strftime("%Y-%m-%d %H:%M:%S") +print(f"[{timestamp}] [INFO] {message}", file=sys.stdout) +``` + +Apply to all 4 fallback print statements (info, warn, error, debug). + +--- + +## Implementation Order + +1. **Phase 1** - Python logging formatter (3 files) + - Lowest risk, immediate visible improvement + - Test: Run runtime, verify JSON messages now appear human-readable + +2. **Phase 3** - Python print conversions (~40 calls across 5 files) + - Medium effort, easy to test + - Test: Run runtime, verify print messages go through logger + +3. **Phase 2** - C printf/fprintf conversions (~84 calls across 7 files) + - Highest effort, requires rebuild + - Test: Run runtime, verify all plugin messages use logging system + +4. **Phase 4** - Plugin fallback updates (1 file) + - Final cleanup for edge cases + - Test: Run with logging accessor unavailable + +--- + +## Expected Result + +**Before**: +``` +[PLUGIN]: Creating Python capsule for args +[PLUGIN]: Python capsule created successfully +[OPCUA INFO] OPC UA Plugin initializing... +{"timestamp": "1769785673", "level": "INFO", "message": "Logging initialized", "id": 8} +{"timestamp": "1769785673", "level": "INFO", "message": "Buffer accessor created", "id": 9} +[PLUGIN]: Skipping disabled plugin: s7comm +``` + +**After**: +``` +[2024-01-30 12:00:00] [INFO] Creating Python capsule for args +[2024-01-30 12:00:00] [INFO] Python capsule created successfully +[2024-01-30 12:00:00] [INFO] OPC UA Plugin initializing... +[2024-01-30 12:00:00] [INFO] Logging initialized +[2024-01-30 12:00:00] [INFO] Buffer accessor created +[2024-01-30 12:00:00] [INFO] Skipping disabled plugin: s7comm +``` + +**API Response** (`/api/runtime-logs`) - unchanged, still JSON: +```json +{ + "runtime-logs": [ + {"id": 1, "timestamp": "2024-01-30T12:00:00+00:00", "level": "INFO", "message": "..."} + ] +} +``` + +--- + +## Testing Checklist + +- [ ] Phase 1: JSON logs now display as human-readable on stdout +- [ ] Phase 1: API `/api/runtime-logs` still returns JSON +- [ ] Phase 2: All C plugin messages go through logging system +- [ ] Phase 3: All Python print statements converted to logger +- [ ] Phase 4: Fallback logging matches standard format +- [ ] All timestamps are in UTC +- [ ] Log levels display correctly (INFO, WARN, ERROR, DEBUG) +- [ ] No duplicate messages (both printf and log_*) + +--- + +## Status + +- [x] Phase 1: Python Logging System (COMPLETED) +- [ ] Phase 2: C printf/fprintf Conversions +- [ ] Phase 3: Python print() Conversions +- [ ] Phase 4: Plugin Fallback Updates diff --git a/webserver/logger/__init__.py b/webserver/logger/__init__.py index 484fdad4..1469219b 100644 --- a/webserver/logger/__init__.py +++ b/webserver/logger/__init__.py @@ -5,10 +5,10 @@ from .logger import get_logger from .parser import LogParser from .bufferhandler import BufferHandler -from .formatter import JsonFormatter +from .formatter import JsonFormatter, HumanReadableFormatter from .config import LoggerConfig -__all__ = ["get_logger", "LogParser", "BufferHandler", "JsonFormatter"] +__all__ = ["get_logger", "LogParser", "BufferHandler", "JsonFormatter", "HumanReadableFormatter"] __version__ = "0.1" __author__ = "Autonomy" __license__ = "MIT" @@ -40,7 +40,7 @@ def get_logger(name="runtime", use_buffer: bool = False): for h in logger.handlers ): stream_handler = logging.StreamHandler(sys.stdout) - stream_handler.setFormatter(JsonFormatter()) + stream_handler.setFormatter(HumanReadableFormatter()) logger.addHandler(stream_handler) # Ensure BufferHandler exists if requested diff --git a/webserver/logger/formatter.py b/webserver/logger/formatter.py index 3d7b2181..3103dd43 100644 --- a/webserver/logger/formatter.py +++ b/webserver/logger/formatter.py @@ -29,3 +29,38 @@ def format(self, record): return json.dumps(log_entry) + +class HumanReadableFormatter(logging.Formatter): + """Format log records as human-readable strings for stdout.""" + + def format(self, record): + msg = record.getMessage() + + # Try to detect pre-formatted JSON (from C runtime) + try: + log_entry = json.loads(msg) + timestamp = log_entry.get("timestamp", "") + level = log_entry.get("level", record.levelname) + message = log_entry.get("message", msg) + + # Convert Unix timestamp to human-readable + if timestamp and str(timestamp).isdigit(): + dt = datetime.fromtimestamp(int(timestamp), tz=timezone.utc) + timestamp = dt.strftime("%Y-%m-%d %H:%M:%S") + elif timestamp: + # Handle ISO 8601 format + try: + dt = datetime.fromisoformat(timestamp.replace("Z", "+00:00")) + timestamp = dt.strftime("%Y-%m-%d %H:%M:%S") + except ValueError: + timestamp = datetime.now(timezone.utc).strftime("%Y-%m-%d %H:%M:%S") + else: + timestamp = datetime.now(timezone.utc).strftime("%Y-%m-%d %H:%M:%S") + + except (json.JSONDecodeError, ValueError): + # Not JSON - use record fields directly + timestamp = datetime.now(timezone.utc).strftime("%Y-%m-%d %H:%M:%S") + level = record.levelname + message = msg + + return f"[{timestamp}] [{level}] {message}" diff --git a/webserver/logger/logger.py b/webserver/logger/logger.py index 86ebdca2..943cbd77 100644 --- a/webserver/logger/logger.py +++ b/webserver/logger/logger.py @@ -1,7 +1,7 @@ # logger/logger.py import logging import sys -from .formatter import JsonFormatter +from .formatter import JsonFormatter, HumanReadableFormatter from .bufferhandler import BufferHandler @@ -16,7 +16,7 @@ def get_logger(name: str = "logger", # Always ensure a StreamHandler exists if not any(isinstance(h, logging.StreamHandler) for h in collector_logger.handlers): stream_handler = logging.StreamHandler(sys.stdout) - stream_handler.setFormatter(JsonFormatter()) + stream_handler.setFormatter(HumanReadableFormatter()) collector_logger.addHandler(stream_handler) buffer_handler = None From cd265999dcc70cb1a2e1fdeb7f761d00f5ee1da1 Mon Sep 17 00:00:00 2001 From: Thiago Alves Date: Fri, 30 Jan 2026 11:56:45 -0500 Subject: [PATCH 5/9] refactor: Convert C printf/fprintf to log_* calls Phase 2 of logging normalization - convert direct printf/fprintf calls in C code to use the centralized logging system. Files modified: - plugin_driver.c: Convert 73 printf/fprintf calls to log_info/log_error/log_warn/log_debug - plugin_config.c: Convert 2 printf calls to log_debug - plugin_logger.c: Convert init warnings to log_warn, format fallback output - journal_buffer.c: Convert 2 fprintf calls to log_error - plc_main.c: Format early init error with timestamp - watchdog.c: Format critical error with timestamp Fallback logging (when central logging unavailable) now uses human-readable format: [YYYY-MM-DD HH:MM:SS] [LEVEL] message Co-Authored-By: Claude Opus 4.5 --- core/src/drivers/plugin_config.c | 5 +- core/src/drivers/plugin_driver.c | 189 ++++++++---------- .../drivers/plugins/native/plugin_logger.c | 20 +- core/src/plc_app/journal_buffer.c | 5 +- core/src/plc_app/plc_main.c | 7 +- core/src/plc_app/utils/watchdog.c | 11 +- docs/LOGGING_NORMALIZATION_PLAN.md | 2 +- 7 files changed, 122 insertions(+), 117 deletions(-) diff --git a/core/src/drivers/plugin_config.c b/core/src/drivers/plugin_config.c index 80a7ba7b..d115e7be 100644 --- a/core/src/drivers/plugin_config.c +++ b/core/src/drivers/plugin_config.c @@ -1,4 +1,5 @@ #include "plugin_config.h" +#include "../plc_app/utils/log.h" #include #include #include @@ -72,7 +73,7 @@ int parse_plugin_config(const char *config_file, plugin_config_t *configs, int m token = strtok(NULL, ","); if (token && strlen(token) > 0) { - printf("[PLUGIN_CONFIG]: Found config_path: '%s'\n", token); + log_debug("Found config_path: '%s'", token); strncpy(configs[config_count].plugin_related_config_path, token, sizeof(configs[config_count].plugin_related_config_path) - 1); configs[config_count] @@ -82,7 +83,7 @@ int parse_plugin_config(const char *config_file, plugin_config_t *configs, int m } else { - printf("[PLUGIN_CONFIG]: No config_path found, using empty string\n"); + log_debug("No config_path found, using empty string"); // No config path specified, use empty string configs[config_count].plugin_related_config_path[0] = '\0'; } diff --git a/core/src/drivers/plugin_driver.c b/core/src/drivers/plugin_driver.c index c7511dd1..77ec4969 100644 --- a/core/src/drivers/plugin_driver.c +++ b/core/src/drivers/plugin_driver.c @@ -180,13 +180,12 @@ int plugin_driver_update_config(plugin_driver_t *driver, const char *config_file // Check if config file exists, if not copy from default if (access(config_file, F_OK) != 0) { - printf("[PLUGIN]: Config file %s not found, copying from plugins_default.conf\n", - config_file); + log_info("Config file %s not found, copying from plugins_default.conf", config_file); // Check if default config exists if (access("plugins_default.conf", F_OK) != 0) { - printf("[PLUGIN]: Default config file plugins_default.conf not found\n"); + log_error("Default config file plugins_default.conf not found"); return -1; } @@ -196,7 +195,7 @@ int plugin_driver_update_config(plugin_driver_t *driver, const char *config_file if (!src || !dst) { - printf("[PLUGIN]: Failed to copy default config\n"); + log_error("Failed to copy default config"); if (src) fclose(src); if (dst) @@ -213,7 +212,7 @@ int plugin_driver_update_config(plugin_driver_t *driver, const char *config_file fclose(src); fclose(dst); - printf("[PLUGIN]: Successfully copied default config to %s\n", config_file); + log_info("Successfully copied default config to %s", config_file); } plugin_config_t configs[MAX_PLUGINS]; @@ -255,8 +254,7 @@ int plugin_driver_load_config(plugin_driver_t *driver, const char *config_file) { if (python_plugin_get_symbols(plugin) != 0) { - fprintf(stderr, "Failed to get Python plugin symbols for: %s\n", - plugin->config.path); + log_error("Failed to get Python plugin symbols for: %s", plugin->config.path); return -1; } } @@ -264,8 +262,7 @@ int plugin_driver_load_config(plugin_driver_t *driver, const char *config_file) { if (native_plugin_get_symbols(plugin) != 0) { - fprintf(stderr, "Failed to get native plugin symbols for: %s\n", - plugin->config.path); + log_error("Failed to get native plugin symbols for: %s", plugin->config.path); return -1; } } @@ -299,7 +296,7 @@ int plugin_driver_init(plugin_driver_t *driver) // Skip disabled plugins if (!plugin->config.enabled) { - printf("[PLUGIN]: Skipping disabled plugin: %s\n", plugin->config.name); + log_info("Skipping disabled plugin: %s", plugin->config.name); continue; } @@ -311,8 +308,7 @@ int plugin_driver_init(plugin_driver_t *driver) (PyObject *)generate_structured_args_with_driver(PLUGIN_TYPE_PYTHON, driver, i); if (!args) { - fprintf(stderr, "Failed to generate runtime args for plugin: %s\n", - plugin->config.name); + log_error("Failed to generate runtime args for plugin: %s", plugin->config.name); if (have_gil) { @@ -330,8 +326,7 @@ int plugin_driver_init(plugin_driver_t *driver) if (!result) { PyErr_Print(); - fprintf(stderr, "Python init function failed for plugin: %s\n", - plugin->config.name); + log_error("Python init function failed for plugin: %s", plugin->config.name); if (have_gil) { @@ -350,8 +345,8 @@ int plugin_driver_init(plugin_driver_t *driver) driver, i); if (!args) { - fprintf(stderr, "Failed to generate runtime args for native plugin: %s\n", - plugin->config.name); + log_error("Failed to generate runtime args for native plugin: %s", + plugin->config.name); if (have_gil) { PyGILState_Release(local_gstate); @@ -363,8 +358,8 @@ int plugin_driver_init(plugin_driver_t *driver) int result = plugin->native_plugin->init(args); if (result != 0) { - fprintf(stderr, "Native init function failed for plugin: %s (returned %d)\n", - plugin->config.name, result); + log_error("Native init function failed for plugin: %s (returned %d)", + plugin->config.name, result); free_structured_args(args); if (have_gil) { @@ -396,7 +391,7 @@ int plugin_driver_start(plugin_driver_t *driver) if (driver->plugin_count == 0) { - printf("[PLUGIN]: No plugins to start.\n"); + log_info("No plugins to start"); return 0; } @@ -414,7 +409,7 @@ int plugin_driver_start(plugin_driver_t *driver) // Skip disabled plugins if (!plugin->config.enabled) { - printf("[PLUGIN]: Skipping disabled plugin during start: %s\n", plugin->config.name); + log_info("Skipping disabled plugin during start: %s", plugin->config.name); continue; } @@ -432,12 +427,11 @@ int plugin_driver_start(plugin_driver_t *driver) if (!res) { PyErr_Print(); - fprintf(stderr, "Python start call failed for plugin: %s\n", - plugin->config.name); + log_error("Python start call failed for plugin: %s", plugin->config.name); } else { - printf("[PLUGIN]: Plugin %s started successfully.\n", plugin->config.name); + log_info("Plugin %s started successfully", plugin->config.name); } Py_DECREF( res); // There's no problem in calling DECREF here because it only @@ -448,8 +442,8 @@ int plugin_driver_start(plugin_driver_t *driver) } else { - fprintf(stderr, "Python plugin %s does not have a start_loop function.\n", - plugin->config.name); + log_warn("Python plugin %s does not have a start_loop function", + plugin->config.name); } } break; @@ -460,13 +454,13 @@ int plugin_driver_start(plugin_driver_t *driver) if (plugin->native_plugin && plugin->native_plugin->start) { plugin->native_plugin->start(); - printf("[PLUGIN]: Native plugin %s started successfully.\n", plugin->config.name); + log_info("Native plugin %s started successfully", plugin->config.name); plugin->running = 1; } else { - fprintf(stderr, "Native plugin %s does not have a start_loop function.\n", - plugin->config.name); + log_warn("Native plugin %s does not have a start_loop function", + plugin->config.name); } } break; @@ -482,7 +476,7 @@ int plugin_driver_start(plugin_driver_t *driver) int plugin_driver_stop(plugin_driver_t *driver) { - printf("[PLUGIN]: Stopping all plugins...\n"); + log_info("Stopping all plugins..."); if (!driver) { return -1; @@ -490,7 +484,7 @@ int plugin_driver_stop(plugin_driver_t *driver) if (driver->plugin_count == 0) { - printf("[PLUGIN]: No plugins to stop.\n"); + log_info("No plugins to stop"); return 0; } @@ -510,19 +504,19 @@ int plugin_driver_stop(plugin_driver_t *driver) // Skip disabled plugins if (!plugin->config.enabled) { - printf("[PLUGIN]: Skipping disabled plugin during stop: %s\n", plugin->config.name); + log_info("Skipping disabled plugin during stop: %s", plugin->config.name); continue; } - printf("[PLUGIN]: Stopping plugin %d/%d: %s\n", i + 1, driver->plugin_count, - driver->plugins[i].config.name); + log_info("Stopping plugin %d/%d: %s", i + 1, driver->plugin_count, + driver->plugins[i].config.name); if (plugin->python_plugin && plugin->python_plugin->pFuncStop && plugin->running) { plugin_instance_t *plugin = &driver->plugins[i]; if (plugin->config.enabled == 0) { - printf("[PLUGIN]: Plugin %s is disabled, skipping stop.\n", plugin->config.name); + log_info("Plugin %s is disabled, skipping stop", plugin->config.name); continue; } @@ -530,14 +524,14 @@ int plugin_driver_stop(plugin_driver_t *driver) if (!res) { PyErr_Print(); - fprintf(stderr, "Python stop call failed for plugin: %s\n", plugin->config.name); + log_error("Python stop call failed for plugin: %s", plugin->config.name); } else { - printf("[PLUGIN]: Plugin %s stopped successfully.\n", plugin->config.name); + log_info("Plugin %s stopped successfully", plugin->config.name); } Py_DECREF(res); - printf("[PLUGIN]: Plugin %s stopped...\n", driver->plugins[i].config.name); + log_info("Plugin %s stopped", driver->plugins[i].config.name); plugin->running = 0; } @@ -545,7 +539,7 @@ int plugin_driver_stop(plugin_driver_t *driver) plugin->running) { plugin->native_plugin->stop(); - printf("[PLUGIN]: Native plugin %s stopped successfully.\n", plugin->config.name); + log_info("Native plugin %s stopped successfully", plugin->config.name); plugin->running = 0; } // Plugin manager only handles destruction, not stopping @@ -566,12 +560,12 @@ int plugin_driver_restart(plugin_driver_t *driver) return -1; } - printf("[PLUGIN]: Restarting all plugins...\n"); + log_info("Restarting all plugins..."); // Stop all running plugins first if (plugin_driver_stop(driver) != 0) { - fprintf(stderr, "[PLUGIN]: Failed to stop plugins during restart\n"); + log_error("Failed to stop plugins during restart"); return -1; } @@ -592,28 +586,28 @@ int plugin_driver_restart(plugin_driver_t *driver) } // CRITICAL: Reload configuration from plugins.conf file - printf("[PLUGIN]: Reloading plugin configuration...\n"); + log_info("Reloading plugin configuration..."); if (plugin_driver_load_config(driver, "plugins.conf") != 0) { - fprintf(stderr, "[PLUGIN]: Failed to reload plugin configuration during restart\n"); + log_error("Failed to reload plugin configuration during restart"); return -1; } // Reinitialize all plugins (only enabled ones) if (plugin_driver_init(driver) != 0) { - fprintf(stderr, "[PLUGIN]: Failed to reinitialize plugins during restart\n"); + log_error("Failed to reinitialize plugins during restart"); return -1; } // Restart all plugins (only enabled ones) if (plugin_driver_start(driver) != 0) { - fprintf(stderr, "[PLUGIN]: Failed to start plugins during restart\n"); + log_error("Failed to start plugins during restart"); return -1; } - printf("[PLUGIN]: All plugins restarted successfully\n"); + log_info("All plugins restarted successfully"); return 0; } @@ -626,7 +620,7 @@ void plugin_driver_destroy(plugin_driver_t *driver) if (driver->plugin_count == 0) { - printf("[PLUGIN]: No plugins to destroy.\n"); + log_info("No plugins to destroy"); pthread_mutex_destroy(&driver->buffer_mutex); free(driver); return; @@ -657,8 +651,7 @@ void plugin_driver_destroy(plugin_driver_t *driver) if (plugin->native_plugin->cleanup) { plugin->native_plugin->cleanup(); - printf("[PLUGIN]: Native plugin %s cleaned up successfully.\n", - plugin->config.name); + log_info("Native plugin %s cleaned up successfully", plugin->config.name); } // Close the shared library handle if (plugin->native_plugin->handle) @@ -705,23 +698,22 @@ void plugin_driver_destroy(plugin_driver_t *driver) void *generate_structured_args_with_driver(plugin_type_t type, plugin_driver_t *driver, int plugin_index) { - printf("[PLUGIN]: Generating structured args for plugin type %d\n", type); + log_debug("Generating structured args for plugin type %d", type); if (!driver) { - fprintf(stderr, "[PLUGIN]: Error - driver is NULL\n"); + log_error("Error - driver is NULL"); return NULL; } plugin_runtime_args_t *args = malloc(sizeof(plugin_runtime_args_t)); if (!args) { - fprintf(stderr, "[PLUGIN]: Error - failed to allocate memory for runtime args\n"); + log_error("Error - failed to allocate memory for runtime args"); return NULL; } - printf("[PLUGIN]: Allocated runtime args structure (size: %zu bytes)\n", - sizeof(plugin_runtime_args_t)); + log_debug("Allocated runtime args structure (size: %zu bytes)", sizeof(plugin_runtime_args_t)); // Initialize all buffer pointers args->bool_input = bool_input; @@ -784,14 +776,14 @@ void *generate_structured_args_with_driver(plugin_type_t type, plugin_driver_t * // Validate critical pointers if (!args->buffer_mutex) { - fprintf(stderr, "[PLUGIN]: Error - buffer_mutex is NULL\n"); + log_error("Error - buffer_mutex is NULL"); free(args); return NULL; } if (!args->mutex_take || !args->mutex_give) { - fprintf(stderr, "[PLUGIN]: Error - mutex function pointers are NULL\n"); + log_error("Error - mutex function pointers are NULL"); free(args); return NULL; } @@ -799,25 +791,25 @@ void *generate_structured_args_with_driver(plugin_type_t type, plugin_driver_t * switch (type) { case PLUGIN_TYPE_NATIVE: - printf("[PLUGIN]: Returning native plugin args\n"); + log_debug("Returning native plugin args"); // For native plugins, return the structure directly return args; case PLUGIN_TYPE_PYTHON: - printf("[PLUGIN]: Creating Python capsule for args\n"); + log_debug("Creating Python capsule for args"); // For Python plugins, wrap in a PyCapsule PyObject *capsule = create_python_runtime_args_capsule(args); if (!capsule) { - fprintf(stderr, "[PLUGIN]: Error - failed to create Python capsule\n"); + log_error("Error - failed to create Python capsule"); // Note: create_python_runtime_args_capsule already freed args on failure return NULL; } - printf("[PLUGIN]: Python capsule created successfully\n"); + log_debug("Python capsule created successfully"); return capsule; default: - fprintf(stderr, "[PLUGIN]: Error - unknown plugin type: %d\n", type); + log_error("Error - unknown plugin type: %d", type); // Unknown type, clean up and return NULL free(args); return NULL; @@ -913,8 +905,8 @@ int python_plugin_get_symbols(plugin_instance_t *plugin) { // Not found if (PyList_Insert(sys_path, 0, venv_path_obj) != 0) { - fprintf(stderr, "Failed to insert venv path into sys.path for plugin: %s\n", - plugin->config.name); + log_error("Failed to insert venv path into sys.path for plugin: %s", + plugin->config.name); Py_DECREF(venv_path_obj); free(py_binds); return -1; @@ -924,19 +916,19 @@ int python_plugin_get_symbols(plugin_instance_t *plugin) } else { - fprintf(stderr, "Failed to get sys.path for plugin: %s\n", plugin->config.name); + log_error("Failed to get sys.path for plugin: %s", plugin->config.name); free(py_binds); return -1; } - printf("[PLUGIN] Using venv for %s: %s\n", plugin->config.name, venv_site_packages); + log_info("Using venv for %s: %s", plugin->config.name, venv_site_packages); } // Load the Python module py_binds->pModule = PyImport_ImportModule(module_name); if (!py_binds->pModule) { - fprintf(stderr, "Failed to load Python module '%s' from path '%s'\n", module_name, - plugin->config.path); + log_error("Failed to load Python module '%s' from path '%s'", module_name, + plugin->config.path); PyErr_Print(); free(py_binds); return -1; @@ -946,10 +938,9 @@ int python_plugin_get_symbols(plugin_instance_t *plugin) py_binds->pFuncInit = PyObject_GetAttrString(py_binds->pModule, "init"); if (!py_binds->pFuncInit || !PyCallable_Check(py_binds->pFuncInit)) { - fprintf(stderr, - "Error: 'init' function not found or not callable in module '%s' - this function " - "is required\n", - module_name); + log_error("Error: 'init' function not found or not callable in module '%s' - this function " + "is required", + module_name); Py_XDECREF(py_binds->pModule); free(py_binds); return -1; @@ -982,11 +973,11 @@ int python_plugin_get_symbols(plugin_instance_t *plugin) // Store the python binds in the plugin instance plugin->python_plugin = py_binds; - printf("Python plugin '%s' symbols loaded successfully\n", module_name); - printf(" - init: %s\n", py_binds->pFuncInit ? "(PASS)" : "(FAIL)"); - printf(" - start_loop: %s\n", py_binds->pFuncStart ? "(PASS)" : "(FAIL)"); - printf(" - stop_loop: %s\n", py_binds->pFuncStop ? "(PASS)" : "(FAIL)"); - printf(" - cleanup: %s\n", py_binds->pFuncCleanup ? "(PASS)" : "(FAIL)"); + log_info("Python plugin '%s' symbols loaded successfully", module_name); + log_info(" - init: %s", py_binds->pFuncInit ? "(PASS)" : "(FAIL)"); + log_info(" - start_loop: %s", py_binds->pFuncStart ? "(PASS)" : "(FAIL)"); + log_info(" - stop_loop: %s", py_binds->pFuncStop ? "(PASS)" : "(FAIL)"); + log_info(" - cleanup: %s", py_binds->pFuncCleanup ? "(PASS)" : "(FAIL)"); return 0; } @@ -1009,7 +1000,7 @@ int native_plugin_get_symbols(plugin_instance_t *plugin) void *handle = dlopen(plugin->config.path, RTLD_LOCAL | RTLD_NOW); if (!handle) { - fprintf(stderr, "Failed to load native plugin '%s': %s\n", plugin->config.path, dlerror()); + log_error("Failed to load native plugin '%s': %s", plugin->config.path, dlerror()); free(native_bundle); return -1; } @@ -1025,8 +1016,8 @@ int native_plugin_get_symbols(plugin_instance_t *plugin) native_bundle->init = (plugin_init_func_t)dlsym(handle, "init"); if (!native_bundle->init) { - fprintf(stderr, "Error: 'init' function not found in native plugin '%s': %s\n", - plugin->config.path, dlerror()); + log_error("Error: 'init' function not found in native plugin '%s': %s", + plugin->config.path, dlerror()); dlclose(handle); free(native_bundle); return -1; @@ -1036,52 +1027,48 @@ int native_plugin_get_symbols(plugin_instance_t *plugin) native_bundle->start = (plugin_start_loop_func_t)dlsym(handle, "start_loop"); if (!native_bundle->start) { - fprintf(stderr, - "Warning: 'start_loop' function not found in native plugin '%s' (optional)\n", - plugin->config.path); + log_warn("'start_loop' function not found in native plugin '%s' (optional)", + plugin->config.path); } native_bundle->stop = (plugin_stop_loop_func_t)dlsym(handle, "stop_loop"); if (!native_bundle->stop) { - fprintf(stderr, - "Warning: 'stop_loop' function not found in native plugin '%s' (optional)\n", - plugin->config.path); + log_warn("'stop_loop' function not found in native plugin '%s' (optional)", + plugin->config.path); } native_bundle->cycle_start = (plugin_cycle_start_func_t)dlsym(handle, "cycle_start"); if (!native_bundle->cycle_start) { - fprintf(stderr, - "Warning: 'cycle_start' function not found in native plugin '%s' (optional)\n", - plugin->config.path); + log_warn("'cycle_start' function not found in native plugin '%s' (optional)", + plugin->config.path); } native_bundle->cycle_end = (plugin_cycle_end_func_t)dlsym(handle, "cycle_end"); if (!native_bundle->cycle_end) { - fprintf(stderr, - "Warning: 'cycle_end' function not found in native plugin '%s' (optional)\n", - plugin->config.path); + log_warn("'cycle_end' function not found in native plugin '%s' (optional)", + plugin->config.path); } native_bundle->cleanup = (plugin_cleanup_func_t)dlsym(handle, "cleanup"); if (!native_bundle->cleanup) { - fprintf(stderr, "Warning: 'cleanup' function not found in native plugin '%s' (optional)\n", - plugin->config.path); + log_warn("'cleanup' function not found in native plugin '%s' (optional)", + plugin->config.path); } // Store the native bundle and handle in the plugin instance plugin->native_plugin = native_bundle; - printf("Native plugin '%s' symbols loaded successfully\n", plugin->config.path); - printf(" - init: (PASS)\n"); - printf(" - start_loop: %s\n", native_bundle->start ? "(PASS)" : "(FAIL)"); - printf(" - stop_loop: %s\n", native_bundle->stop ? "(PASS)" : "(FAIL)"); - printf(" - cycle_start: %s\n", native_bundle->cycle_start ? "(PASS)" : "(FAIL)"); - printf(" - cycle_end: %s\n", native_bundle->cycle_end ? "(PASS)" : "(FAIL)"); - printf(" - cleanup: %s\n", native_bundle->cleanup ? "(PASS)" : "(FAIL)"); + log_info("Native plugin '%s' symbols loaded successfully", plugin->config.path); + log_info(" - init: (PASS)"); + log_info(" - start_loop: %s", native_bundle->start ? "(PASS)" : "(FAIL)"); + log_info(" - stop_loop: %s", native_bundle->stop ? "(PASS)" : "(FAIL)"); + log_info(" - cycle_start: %s", native_bundle->cycle_start ? "(PASS)" : "(FAIL)"); + log_info(" - cycle_end: %s", native_bundle->cycle_end ? "(PASS)" : "(FAIL)"); + log_info(" - cleanup: %s", native_bundle->cleanup ? "(PASS)" : "(FAIL)"); return 0; } @@ -1165,11 +1152,11 @@ static void python_plugin_cleanup(plugin_instance_t *plugin) if (!res) { PyErr_Print(); - fprintf(stderr, "Python cleanup call failed for plugin: %s\n", plugin->config.name); + log_error("Python cleanup call failed for plugin: %s", plugin->config.name); } else { - printf("[PLUGIN]: Plugin %s cleaned up successfully.\n", plugin->config.name); + log_info("Plugin %s cleaned up successfully", plugin->config.name); } Py_DECREF(res); } diff --git a/core/src/drivers/plugins/native/plugin_logger.c b/core/src/drivers/plugins/native/plugin_logger.c index ac87353a..6c31443f 100644 --- a/core/src/drivers/plugins/native/plugin_logger.c +++ b/core/src/drivers/plugins/native/plugin_logger.c @@ -4,10 +4,12 @@ */ #include "plugin_logger.h" +#include "../../../plc_app/utils/log.h" #include "../../plugin_types.h" #include #include #include +#include /* Maximum size for formatted log messages */ #define MAX_LOG_MESSAGE_SIZE 1024 @@ -29,7 +31,7 @@ bool plugin_logger_init(plugin_logger_t *logger, const char *plugin_name, void * if (!plugin_name) { - fprintf(stderr, "[PLUGIN_LOGGER] Error: plugin_name is NULL\n"); + log_error("Plugin logger init failed: plugin_name is NULL"); return false; } @@ -39,8 +41,8 @@ bool plugin_logger_init(plugin_logger_t *logger, const char *plugin_name, void * if (!runtime_args) { - fprintf(stderr, "[%s] Warning: runtime_args is NULL, logging will fall back to printf\n", - logger->plugin_name); + log_warn("[%s] runtime_args is NULL, logging will fall back to printf", + logger->plugin_name); return true; /* Still return true - logger will fall back to printf */ } @@ -59,8 +61,8 @@ bool plugin_logger_init(plugin_logger_t *logger, const char *plugin_name, void * } else { - fprintf(stderr, "[%s] Warning: Some log functions are NULL, falling back to printf\n", - logger->plugin_name); + log_warn("[%s] Some log functions are NULL, falling back to printf", + logger->plugin_name); } return true; @@ -88,7 +90,13 @@ static void plugin_logger_log(plugin_logger_t *logger, plugin_log_func_t log_fun } else { - printf("[%s] [%s] %s\n", logger->plugin_name, level, message); + /* Fallback: format to match human-readable log format */ + time_t now = time(NULL); + struct tm t; + gmtime_r(&now, &t); + char time_buf[20]; + strftime(time_buf, sizeof(time_buf), "%Y-%m-%d %H:%M:%S", &t); + printf("[%s] [%s] [%s] %s\n", time_buf, level, logger->plugin_name, message); } } diff --git a/core/src/plc_app/journal_buffer.c b/core/src/plc_app/journal_buffer.c index 7358f75e..467a85fd 100644 --- a/core/src/plc_app/journal_buffer.c +++ b/core/src/plc_app/journal_buffer.c @@ -11,6 +11,7 @@ */ #include "journal_buffer.h" +#include "utils/log.h" #include #include @@ -55,12 +56,12 @@ static void emergency_flush_locked(void); int journal_init(const journal_buffer_ptrs_t *buffer_ptrs) { if (buffer_ptrs == NULL) { - fprintf(stderr, "[JOURNAL] Error: buffer_ptrs is NULL\n"); + log_error("Journal: buffer_ptrs is NULL"); return -1; } if (buffer_ptrs->image_mutex == NULL) { - fprintf(stderr, "[JOURNAL] Error: image_mutex is NULL\n"); + log_error("Journal: image_mutex is NULL"); return -1; } diff --git a/core/src/plc_app/plc_main.c b/core/src/plc_app/plc_main.c index ade09a4c..ec182678 100644 --- a/core/src/plc_app/plc_main.c +++ b/core/src/plc_app/plc_main.c @@ -65,7 +65,12 @@ int main(int argc, char *argv[]) if (log_init(LOG_SOCKET_PATH) < 0) { - fprintf(stderr, "Failed to initialize logging system\n"); + time_t now = time(NULL); + struct tm t; + gmtime_r(&now, &t); + char time_buf[20]; + strftime(time_buf, sizeof(time_buf), "%Y-%m-%d %H:%M:%S", &t); + fprintf(stderr, "[%s] [ERROR] Failed to initialize logging system\n", time_buf); return -1; } diff --git a/core/src/plc_app/utils/watchdog.c b/core/src/plc_app/utils/watchdog.c index ee723965..a669e4c9 100644 --- a/core/src/plc_app/utils/watchdog.c +++ b/core/src/plc_app/utils/watchdog.c @@ -30,10 +30,13 @@ void *watchdog_thread(void *arg) long now = atomic_load(&plc_heartbeat); if (now == last) { - fprintf( - stderr, - "[Watchdog] No heartbeat! PLC unresponsive.\n"); // Use stderr to ensure visibility - // and avoid lockups in log system + // Use stderr to ensure visibility and avoid lockups in log system + time_t now_time = time(NULL); + struct tm t; + gmtime_r(&now_time, &t); + char time_buf[20]; + strftime(time_buf, sizeof(time_buf), "%Y-%m-%d %H:%M:%S", &t); + fprintf(stderr, "[%s] [ERROR] Watchdog: No heartbeat! PLC unresponsive.\n", time_buf); exit(EXIT_FAILURE); } diff --git a/docs/LOGGING_NORMALIZATION_PLAN.md b/docs/LOGGING_NORMALIZATION_PLAN.md index d233701d..a0862089 100644 --- a/docs/LOGGING_NORMALIZATION_PLAN.md +++ b/docs/LOGGING_NORMALIZATION_PLAN.md @@ -328,6 +328,6 @@ Apply to all 4 fallback print statements (info, warn, error, debug). ## Status - [x] Phase 1: Python Logging System (COMPLETED) -- [ ] Phase 2: C printf/fprintf Conversions +- [x] Phase 2: C printf/fprintf Conversions (COMPLETED) - [ ] Phase 3: Python print() Conversions - [ ] Phase 4: Plugin Fallback Updates From 9416b01e3e5a508465cdb2e171b817e20e807d01 Mon Sep 17 00:00:00 2001 From: Thiago Alves Date: Fri, 30 Jan 2026 12:00:57 -0500 Subject: [PATCH 6/9] fix: Remove log.h dependency from plugin_logger.c plugin_logger.c is compiled into native plugins, not the main runtime. Using log_warn/log_error directly causes undefined symbol errors when loading plugins. Replace with PLUGIN_LOGGER_STDERR macro that uses fprintf with the human-readable timestamp format. Co-Authored-By: Claude Opus 4.5 --- .../drivers/plugins/native/plugin_logger.c | 23 ++++++++++++++----- 1 file changed, 17 insertions(+), 6 deletions(-) diff --git a/core/src/drivers/plugins/native/plugin_logger.c b/core/src/drivers/plugins/native/plugin_logger.c index 6c31443f..c37a76fb 100644 --- a/core/src/drivers/plugins/native/plugin_logger.c +++ b/core/src/drivers/plugins/native/plugin_logger.c @@ -4,13 +4,24 @@ */ #include "plugin_logger.h" -#include "../../../plc_app/utils/log.h" #include "../../plugin_types.h" #include #include #include #include +/* Helper macro for formatted stderr output matching human-readable log format */ +#define PLUGIN_LOGGER_STDERR(level, fmt, ...) \ + do \ + { \ + time_t now = time(NULL); \ + struct tm t; \ + gmtime_r(&now, &t); \ + char time_buf[20]; \ + strftime(time_buf, sizeof(time_buf), "%Y-%m-%d %H:%M:%S", &t); \ + fprintf(stderr, "[%s] [%s] " fmt "\n", time_buf, level, ##__VA_ARGS__); \ + } while (0) + /* Maximum size for formatted log messages */ #define MAX_LOG_MESSAGE_SIZE 1024 @@ -31,7 +42,7 @@ bool plugin_logger_init(plugin_logger_t *logger, const char *plugin_name, void * if (!plugin_name) { - log_error("Plugin logger init failed: plugin_name is NULL"); + PLUGIN_LOGGER_STDERR("ERROR", "Plugin logger init failed: plugin_name is NULL"); return false; } @@ -41,8 +52,8 @@ bool plugin_logger_init(plugin_logger_t *logger, const char *plugin_name, void * if (!runtime_args) { - log_warn("[%s] runtime_args is NULL, logging will fall back to printf", - logger->plugin_name); + PLUGIN_LOGGER_STDERR("WARN", "[%s] runtime_args is NULL, logging will fall back to printf", + logger->plugin_name); return true; /* Still return true - logger will fall back to printf */ } @@ -61,8 +72,8 @@ bool plugin_logger_init(plugin_logger_t *logger, const char *plugin_name, void * } else { - log_warn("[%s] Some log functions are NULL, falling back to printf", - logger->plugin_name); + PLUGIN_LOGGER_STDERR("WARN", "[%s] Some log functions are NULL, falling back to printf", + logger->plugin_name); } return true; From 30a62e6a3469f256ac08df31ae498b32d0f4fb5e Mon Sep 17 00:00:00 2001 From: Thiago Alves Date: Fri, 30 Jan 2026 12:53:52 -0500 Subject: [PATCH 7/9] refactor: Convert Python print() to logger calls (Phase 3) Convert print() statements in webserver Python files to use the centralized logging system. Files modified: - plugin_config_model.py: 6 print -> logger.info/error/warning - credentials.py: 10 print -> logger.info/error/warning - config.py: 2 print -> logger.info/error - app.py: 2 print -> logger.info Note: Python plugin files (modbus_master_memory.py) need a dedicated logging solution similar to opcua_logging.py and are deferred to Phase 4. Co-Authored-By: Claude Opus 4.5 --- docs/LOGGING_NORMALIZATION_PLAN.md | 8 ++++++-- webserver/app.py | 6 ++---- webserver/config.py | 4 ++-- webserver/credentials.py | 26 +++++++++++++++----------- webserver/plugin_config_model.py | 16 ++++++++++------ 5 files changed, 35 insertions(+), 25 deletions(-) diff --git a/docs/LOGGING_NORMALIZATION_PLAN.md b/docs/LOGGING_NORMALIZATION_PLAN.md index a0862089..b864abb7 100644 --- a/docs/LOGGING_NORMALIZATION_PLAN.md +++ b/docs/LOGGING_NORMALIZATION_PLAN.md @@ -329,5 +329,9 @@ Apply to all 4 fallback print statements (info, warn, error, debug). - [x] Phase 1: Python Logging System (COMPLETED) - [x] Phase 2: C printf/fprintf Conversions (COMPLETED) -- [ ] Phase 3: Python print() Conversions -- [ ] Phase 4: Plugin Fallback Updates +- [x] Phase 3: Python print() Conversions (COMPLETED - webserver files) +- [ ] Phase 4: Plugin Fallback Updates (includes Python plugin print conversions) + +### Note on Python Plugin Files +Python plugin files (e.g., `modbus_master_memory.py`) run in the plugin context and +need a logging solution similar to `opcua_logging.py`. These are deferred to Phase 4. diff --git a/webserver/app.py b/webserver/app.py index e0014cf3..2b369f4a 100644 --- a/webserver/app.py +++ b/webserver/app.py @@ -307,7 +307,7 @@ def run_https(): # to handle EAGAIN/EWOULDBLOCK errors that cause "Resource temporarily unavailable" is_linux = platform.system() == "Linux" if not is_linux: - print(f"Non-Linux platform detected ({platform.system()}). Patching recv socket...") + logger.info(f"Non-Linux platform detected ({platform.system()}). Patching recv socket...") _orig_recv = ssl.SSLSocket.recv def _patched_recv(self, buflen, flags=0): @@ -327,9 +327,7 @@ def _patched_recv(self, buflen, flags=0): # Check if certificate exists. If not, generate one if not os.path.exists(CERT_FILE) or not os.path.exists(KEY_FILE): # logger.info("Generating https certificate...") - print( - "Generating https certificate..." - ) # TODO: remove this temporary print once logger is functional again + logger.info("Generating https certificate...") cert_gen.generate_self_signed_cert(cert_file=CERT_FILE, key_file=KEY_FILE) else: logger.warning("Credentials already generated!") diff --git a/webserver/config.py b/webserver/config.py index 023a2c8b..752be4e9 100644 --- a/webserver/config.py +++ b/webserver/config.py @@ -148,11 +148,11 @@ def generate_env_file(): .lower() ) if response == "y": - print("Regenerating .env with new valid values...") + logger.info("Regenerating .env with new valid values...") generate_env_file() load_dotenv(ENV_PATH) else: - print("Exiting due to invalid environment configuration.") + logger.error("Exiting due to invalid environment configuration.") sys.exit(1) diff --git a/webserver/credentials.py b/webserver/credentials.py index 97130fa2..f41913a1 100644 --- a/webserver/credentials.py +++ b/webserver/credentials.py @@ -4,6 +4,10 @@ from ipaddress import ip_address from pathlib import Path +from webserver.logger import get_logger + +logger, _ = get_logger(__name__) + def validate_hostname(hostname: str) -> str: """ @@ -158,7 +162,7 @@ def generate_self_signed_cert(self, cert_file="cert.pem", key_file="key.pem"): ValueError: If file paths are invalid RuntimeError: If certificate generation fails """ - print(f"Generating self-signed certificate for {self.hostname}...") + logger.info(f"Generating self-signed certificate for {self.hostname}...") cert_path = str(validate_file_path(cert_file)) key_path = str(validate_file_path(key_file)) @@ -196,16 +200,16 @@ def generate_self_signed_cert(self, cert_file="cert.pem", key_file="key.pem"): try: subprocess.run(cmd, check=True, capture_output=True, text=True) - print(f"Certificate saved to {cert_path}") - print(f"Private key saved to {key_path}") + logger.info(f"Certificate saved to {cert_path}") + logger.info(f"Private key saved to {key_path}") return f"Certificate generated successfully for {self.hostname}" except subprocess.CalledProcessError as e: error_msg = f"Error generating certificate: {e.stderr}" - print(error_msg) + logger.error(error_msg) raise RuntimeError(error_msg) from e except FileNotFoundError as exc: error_msg = "OpenSSL not found. Please ensure OpenSSL is installed." - print(error_msg) + logger.error(error_msg) raise RuntimeError(error_msg) from exc def is_certificate_valid(self, cert_file): @@ -221,11 +225,11 @@ def is_certificate_valid(self, cert_file): try: cert_path = str(validate_file_path(cert_file)) except ValueError as e: - print(f"Invalid certificate path: {e}") + logger.error(f"Invalid certificate path: {e}") return False if not os.path.exists(cert_path): - print(f"Certificate file not found: {cert_path}") + logger.warning(f"Certificate file not found: {cert_path}") return False try: @@ -259,14 +263,14 @@ def is_certificate_valid(self, cert_file): text=True, ) expiry_line = date_result.stdout.strip() - print(f"Certificate is valid. {expiry_line}") + logger.info(f"Certificate is valid. {expiry_line}") return True - print("Certificate has expired.") + logger.warning("Certificate has expired.") return False except subprocess.CalledProcessError as e: - print(f"Error checking certificate validity: {e.stderr}") + logger.error(f"Error checking certificate validity: {e.stderr}") return False except FileNotFoundError: - print("OpenSSL not found. Please ensure OpenSSL is installed.") + logger.error("OpenSSL not found. Please ensure OpenSSL is installed.") return False diff --git a/webserver/plugin_config_model.py b/webserver/plugin_config_model.py index b0709a8f..4722975c 100644 --- a/webserver/plugin_config_model.py +++ b/webserver/plugin_config_model.py @@ -12,6 +12,10 @@ import glob import shutil +from webserver.logger import get_logger + +logger, _ = get_logger(__name__) + class PluginType(IntEnum): """Plugin type enumeration.""" @@ -122,18 +126,18 @@ def from_file(cls, file_path: str = "plugins.conf") -> 'PluginsConfiguration': # If plugins.conf doesn't exist, copy from plugins_default.conf if not os.path.exists(file_path): default_file = "plugins_default.conf" - print(f"[PLUGIN]: Config file {file_path} not found, copying from {default_file}") + logger.info(f"Config file {file_path} not found, copying from {default_file}") if os.path.exists(default_file): try: import shutil shutil.copy2(default_file, file_path) - print(f"[PLUGIN]: Successfully copied {default_file} to {file_path}") + logger.info(f"Successfully copied {default_file} to {file_path}") except Exception as e: - print(f"[PLUGIN]: Failed to copy {default_file}: {e}") + logger.error(f"Failed to copy {default_file}: {e}") return config else: - print(f"[PLUGIN]: Default config file {default_file} not found") + logger.error(f"Default config file {default_file} not found") return config if not os.path.exists(file_path): @@ -155,7 +159,7 @@ def from_file(cls, file_path: str = "plugins.conf") -> 'PluginsConfiguration': except Exception as e: # Log error but continue with empty configuration - print(f"Warning: Failed to load plugin configuration from {file_path}: {e}") + logger.warning(f"Failed to load plugin configuration from {file_path}: {e}") return config @@ -199,7 +203,7 @@ def to_file(self, file_path: str = "plugins.conf") -> bool: return True except Exception as e: - print(f"Error: Failed to save plugin configuration to {file_path}: {e}") + logger.error(f"Failed to save plugin configuration to {file_path}: {e}") return False def get_plugin(self, name: str) -> Optional[PluginConfig]: From a14304e9a0d977ece661a84df48a37156a121ccb Mon Sep 17 00:00:00 2001 From: Thiago Alves Date: Fri, 30 Jan 2026 13:00:09 -0500 Subject: [PATCH 8/9] refactor: Update plugin fallback logging with timestamp format (Phase 4) Update Python plugin logger fallback print statements to use the standard timestamp format for consistency: - shared/plugin_logger.py: Add timestamp to _fallback_print() - opcua/opcua_logging.py: Add timestamps to info/warn/error/debug fallbacks Format: [YYYY-MM-DD HH:MM:SS] [LEVEL] [PREFIX] message Co-Authored-By: Claude Opus 4.5 --- .../drivers/plugins/python/opcua/opcua_logging.py | 13 +++++++++---- .../drivers/plugins/python/shared/plugin_logger.py | 4 +++- docs/LOGGING_NORMALIZATION_PLAN.md | 6 +++--- 3 files changed, 15 insertions(+), 8 deletions(-) diff --git a/core/src/drivers/plugins/python/opcua/opcua_logging.py b/core/src/drivers/plugins/python/opcua/opcua_logging.py index ed58350b..73dc01b6 100644 --- a/core/src/drivers/plugins/python/opcua/opcua_logging.py +++ b/core/src/drivers/plugins/python/opcua/opcua_logging.py @@ -5,6 +5,7 @@ runtime logging system while providing fallback to standard output. """ +from datetime import datetime, timezone from typing import Optional, Callable import sys @@ -69,7 +70,8 @@ def info(self, message: str) -> None: return except Exception: pass - print(f"[OPCUA INFO] {message}", file=sys.stdout) + timestamp = datetime.now(timezone.utc).strftime("%Y-%m-%d %H:%M:%S") + print(f"[{timestamp}] [INFO] [OPCUA] {message}", file=sys.stdout) def warn(self, message: str) -> None: """Log a warning message.""" @@ -79,7 +81,8 @@ def warn(self, message: str) -> None: return except Exception: pass - print(f"[OPCUA WARN] {message}", file=sys.stderr) + timestamp = datetime.now(timezone.utc).strftime("%Y-%m-%d %H:%M:%S") + print(f"[{timestamp}] [WARN] [OPCUA] {message}", file=sys.stderr) def error(self, message: str) -> None: """Log an error message.""" @@ -89,7 +92,8 @@ def error(self, message: str) -> None: return except Exception: pass - print(f"[OPCUA ERROR] {message}", file=sys.stderr) + timestamp = datetime.now(timezone.utc).strftime("%Y-%m-%d %H:%M:%S") + print(f"[{timestamp}] [ERROR] [OPCUA] {message}", file=sys.stderr) def debug(self, message: str) -> None: """Log a debug message.""" @@ -99,7 +103,8 @@ def debug(self, message: str) -> None: return except Exception: pass - print(f"[OPCUA DEBUG] {message}", file=sys.stdout) + timestamp = datetime.now(timezone.utc).strftime("%Y-%m-%d %H:%M:%S") + print(f"[{timestamp}] [DEBUG] [OPCUA] {message}", file=sys.stdout) # Module-level convenience functions diff --git a/core/src/drivers/plugins/python/shared/plugin_logger.py b/core/src/drivers/plugins/python/shared/plugin_logger.py index ec7aeedd..7ce353f9 100644 --- a/core/src/drivers/plugins/python/shared/plugin_logger.py +++ b/core/src/drivers/plugins/python/shared/plugin_logger.py @@ -25,6 +25,7 @@ "[MODBUS_SLAVE] Server started on port 502" """ +from datetime import datetime, timezone from typing import Optional from .safe_logging_access import SafeLoggingAccess @@ -83,7 +84,8 @@ def _fallback_print(self, level: str, message: str): This ensures messages are still visible in stdout even if the central logging system is not available. """ - print(f"{self._prefix} [{level}] {message}") + timestamp = datetime.now(timezone.utc).strftime("%Y-%m-%d %H:%M:%S") + print(f"[{timestamp}] [{level}] {self._prefix} {message}") def info(self, message: str) -> bool: """ diff --git a/docs/LOGGING_NORMALIZATION_PLAN.md b/docs/LOGGING_NORMALIZATION_PLAN.md index b864abb7..cab593c6 100644 --- a/docs/LOGGING_NORMALIZATION_PLAN.md +++ b/docs/LOGGING_NORMALIZATION_PLAN.md @@ -330,8 +330,8 @@ Apply to all 4 fallback print statements (info, warn, error, debug). - [x] Phase 1: Python Logging System (COMPLETED) - [x] Phase 2: C printf/fprintf Conversions (COMPLETED) - [x] Phase 3: Python print() Conversions (COMPLETED - webserver files) -- [ ] Phase 4: Plugin Fallback Updates (includes Python plugin print conversions) +- [x] Phase 4: Plugin Fallback Updates (COMPLETED) ### Note on Python Plugin Files -Python plugin files (e.g., `modbus_master_memory.py`) run in the plugin context and -need a logging solution similar to `opcua_logging.py`. These are deferred to Phase 4. +Python plugin files use `PluginLogger` from `shared/plugin_logger.py` or `OpcuaLogger` +from `opcua/opcua_logging.py`. Both have been updated with timestamp-formatted fallbacks. From 94abe4b2ecfcdd1fd45f9415ee45305f7850bd71 Mon Sep 17 00:00:00 2001 From: Thiago Alves Date: Fri, 30 Jan 2026 13:27:48 -0500 Subject: [PATCH 9/9] refactor: Change verbose OPC-UA log_info calls to log_debug Move diagnostic and verbose logging from INFO to DEBUG level: - opcua_security.py: Certificate details, security setup debug blocks - user_manager.py: Per-connection authentication details - address_space.py: Node creation details - server.py: Endpoint verification, setup progress - plugin.py: Internal initialization steps - callbacks.py: Permission callback registration details - synchronization.py: Sync manager internal state - config.py: Configuration parsing details - opcua_memory.py: Metadata caching details Keep as INFO: Important status messages (server started/stopped, plugin initialized, security initialized, sync loop status) Co-Authored-By: Claude Opus 4.5 --- .../plugins/python/opcua/address_space.py | 22 ++-- .../drivers/plugins/python/opcua/callbacks.py | 18 +-- .../drivers/plugins/python/opcua/config.py | 16 +-- .../plugins/python/opcua/opcua_memory.py | 6 +- .../plugins/python/opcua/opcua_security.py | 110 +++++++++--------- .../drivers/plugins/python/opcua/plugin.py | 12 +- .../drivers/plugins/python/opcua/server.py | 42 +++---- .../plugins/python/opcua/synchronization.py | 14 +-- .../plugins/python/opcua/user_manager.py | 16 +-- 9 files changed, 128 insertions(+), 128 deletions(-) diff --git a/core/src/drivers/plugins/python/opcua/address_space.py b/core/src/drivers/plugins/python/opcua/address_space.py index caae1154..c174ca0f 100644 --- a/core/src/drivers/plugins/python/opcua/address_space.py +++ b/core/src/drivers/plugins/python/opcua/address_space.py @@ -23,11 +23,11 @@ # Import local modules (handle both package and direct loading) try: - from .opcua_logging import log_info, log_warn, log_error + from .opcua_logging import log_debug, log_error, log_info, log_warn from .opcua_types import VariableNode from .opcua_utils import map_plc_to_opcua_type, convert_value_for_opcua except ImportError: - from opcua_logging import log_info, log_warn, log_error + from opcua_logging import log_debug, log_error, log_info, log_warn from opcua_types import VariableNode from opcua_utils import map_plc_to_opcua_type, convert_value_for_opcua @@ -114,7 +114,7 @@ async def build(self) -> bool: log_error(f"Error creating array {arr.node_id}: {e}") traceback.print_exc() - log_info(f"Created {len(self.variable_nodes)} variable nodes") + log_debug(f"Created {len(self.variable_nodes)} variable nodes") return True except Exception as e: @@ -165,9 +165,9 @@ async def _create_simple_variable( has_write_permission = self._check_write_permission(var.permissions) if has_write_permission: await node.set_writable() - log_info(f"Node {var.node_id} set as writable") + log_debug(f"Node {var.node_id} set as writable") else: - log_info(f"Node {var.node_id} set as read-only") + log_debug(f"Node {var.node_id} set as read-only") # Store node mapping access_mode = "readwrite" if has_write_permission else "readonly" @@ -183,7 +183,7 @@ async def _create_simple_variable( self.node_permissions[var.node_id] = var.permissions self.nodeid_to_variable[node.nodeid] = var.node_id - log_info(f"Created variable {var.node_id} (index: {var.index})") + log_debug(f"Created variable {var.node_id} (index: {var.index})") async def _create_struct( self, @@ -223,7 +223,7 @@ async def _create_struct( for field in struct.fields: await self._create_struct_field(struct_obj, struct.node_id, field) - log_info(f"Created struct {struct.node_id} with {len(struct.fields)} fields") + log_debug(f"Created struct {struct.node_id} with {len(struct.fields)} fields") async def _create_struct_field( self, @@ -266,7 +266,7 @@ async def _create_struct_field( for nested_field in field.fields: await self._create_struct_field(field_obj, field_node_id, nested_field) - log_info(f"Created nested object {field_node_id} with {len(field.fields)} fields") + log_debug(f"Created nested object {field_node_id} with {len(field.fields)} fields") return # This is a leaf field - create a Variable node @@ -310,10 +310,10 @@ async def _create_struct_field( self.node_permissions[field_node_id] = field.permissions self.nodeid_to_variable[node.nodeid] = field_node_id - log_info(f"Created field {field_node_id} (index: {field.index})") + log_debug(f"Created field {field_node_id} (index: {field.index})") else: # Complex types (FBs, nested structs) have null indices - only leaf fields have indices - log_info(f"Field {field_node_id} is a complex type (no index) - skipping node mapping") + log_debug(f"Field {field_node_id} is a complex type (no index) - skipping node mapping") async def _create_array( self, @@ -383,7 +383,7 @@ async def _create_array( self.node_permissions[arr.node_id] = arr.permissions self.nodeid_to_variable[node.nodeid] = arr.node_id - log_info(f"Created array {arr.node_id}[{arr.length}] (index: {arr.index})") + log_debug(f"Created array {arr.node_id}[{arr.length}] (index: {arr.index})") def _check_write_permission(self, permissions: VariablePermissions) -> bool: """ diff --git a/core/src/drivers/plugins/python/opcua/callbacks.py b/core/src/drivers/plugins/python/opcua/callbacks.py index cec7fe03..1337950f 100644 --- a/core/src/drivers/plugins/python/opcua/callbacks.py +++ b/core/src/drivers/plugins/python/opcua/callbacks.py @@ -74,7 +74,7 @@ async def register(self, server: Server) -> bool: Returns: True if callbacks registered successfully """ - log_info("=== REGISTERING PERMISSION CALLBACKS ===") + log_debug("=== REGISTERING PERMISSION CALLBACKS ===") try: if server.iserver is None: @@ -87,7 +87,7 @@ async def register(self, server: Server) -> bool: CallbackType.PreWrite, self._on_pre_write ) - log_info("PreWrite callback registered successfully") + log_debug("PreWrite callback registered successfully") # Register PreRead callback (synchronous method) log_debug("Registering PreRead callback...") @@ -95,16 +95,16 @@ async def register(self, server: Server) -> bool: CallbackType.PreRead, self._on_pre_read ) - log_info("PreRead callback registered successfully") + log_debug("PreRead callback registered successfully") - log_info(f"Permission callbacks registered for {len(self.node_permissions)} nodes") + log_debug(f"Permission callbacks registered for {len(self.node_permissions)} nodes") return True except Exception as e: log_error(f"Failed to register callbacks: {e}") # Try alternative callback registration method - log_info("Trying alternative callback registration...") + log_debug("Trying alternative callback registration...") try: if hasattr(server, 'subscribe_server_callback'): server.subscribe_server_callback( @@ -115,7 +115,7 @@ async def register(self, server: Server) -> bool: CallbackType.PreRead, self._on_pre_read ) - log_info("Alternative callback registration successful") + log_debug("Alternative callback registration successful") return True else: log_error("No callback registration method found") @@ -232,8 +232,8 @@ async def _on_pre_write(self, event: Any, dispatcher: Any) -> None: f"(role: {user_role}) on node {simple_node_id}: {value}") raise ua.UaError("Access denied: insufficient write permissions") else: - log_info(f"ALLOW write for user {username} " - f"(role: {user_role}) on node {simple_node_id}: {value}") + log_debug(f"ALLOW write for user {username} " + f"(role: {user_role}) on node {simple_node_id}: {value}") else: # No permissions configured - deny by default (fail-closed) log_warn(f"DENY write for user {username} " @@ -247,7 +247,7 @@ async def _on_pre_write(self, event: Any, dispatcher: Any) -> None: if "w" not in str(viewer_perm): log_warn(f"DENY write for anonymous client on node {simple_node_id}") raise ua.UaError("Access denied: anonymous write not allowed") - log_info(f"ALLOW write for anonymous client on node {simple_node_id}: {value}") + log_debug(f"ALLOW write for anonymous client on node {simple_node_id}: {value}") else: # No permissions configured - deny by default (fail-closed) log_warn(f"DENY write for anonymous client on node {simple_node_id}: {value} " diff --git a/core/src/drivers/plugins/python/opcua/config.py b/core/src/drivers/plugins/python/opcua/config.py index f4422808..03e0a9f1 100644 --- a/core/src/drivers/plugins/python/opcua/config.py +++ b/core/src/drivers/plugins/python/opcua/config.py @@ -21,9 +21,9 @@ # Import logging (handle both package and direct loading) try: - from .opcua_logging import log_info, log_error, log_warn + from .opcua_logging import log_debug, log_error, log_info, log_warn except ImportError: - from opcua_logging import log_info, log_error, log_warn + from opcua_logging import log_debug, log_error, log_info, log_warn from shared.plugin_config_decode.opcua_config_model import ( OpcuaConfig, @@ -64,12 +64,12 @@ def load_config(config_path: str) -> Optional[OpcuaConfig]: # Return first plugin's config (single-server approach) config = master_config.plugins[0].config - log_info(f"Configuration loaded from {config_path}") - log_info(f"Server: {config.server.name}") - log_info(f"Endpoint: {config.server.endpoint_url}") - log_info(f"Variables: {len(config.address_space.variables)}") - log_info(f"Structures: {len(config.address_space.structures)}") - log_info(f"Arrays: {len(config.address_space.arrays)}") + log_debug(f"Configuration loaded from {config_path}") + log_debug(f"Server: {config.server.name}") + log_debug(f"Endpoint: {config.server.endpoint_url}") + log_debug(f"Variables: {len(config.address_space.variables)}") + log_debug(f"Structures: {len(config.address_space.structures)}") + log_debug(f"Arrays: {len(config.address_space.arrays)}") return config diff --git a/core/src/drivers/plugins/python/opcua/opcua_memory.py b/core/src/drivers/plugins/python/opcua/opcua_memory.py index 5f8696f5..08b488d1 100644 --- a/core/src/drivers/plugins/python/opcua/opcua_memory.py +++ b/core/src/drivers/plugins/python/opcua/opcua_memory.py @@ -13,10 +13,10 @@ # Import local modules (handle both package and direct loading) try: from .opcua_types import VariableMetadata - from .opcua_logging import log_info, log_warn, log_error + from .opcua_logging import log_debug, log_error, log_info, log_warn except ImportError: from opcua_types import VariableMetadata - from opcua_logging import log_info, log_warn, log_error + from opcua_logging import log_debug, log_error, log_info, log_warn # IEC 61131-3 STRING constants (must match iec_types.h) @@ -296,7 +296,7 @@ def initialize_variable_cache(sba, indices: List[int]) -> Dict[int, VariableMeta ) cache[var_index] = metadata - log_info(f"Cached metadata for {len(cache)} variables") + log_debug(f"Cached metadata for {len(cache)} variables") return cache except Exception as e: diff --git a/core/src/drivers/plugins/python/opcua/opcua_security.py b/core/src/drivers/plugins/python/opcua/opcua_security.py index f92fa73a..0632789a 100644 --- a/core/src/drivers/plugins/python/opcua/opcua_security.py +++ b/core/src/drivers/plugins/python/opcua/opcua_security.py @@ -43,9 +43,9 @@ # Import logging (handle both package and direct loading) try: - from .opcua_logging import log_error, log_info, log_warn + from .opcua_logging import log_debug, log_error, log_info, log_warn except ImportError: - from opcua_logging import log_error, log_info, log_warn + from opcua_logging import log_debug, log_error, log_info, log_warn # ioctl constants for network interface enumeration (Linux) @@ -274,10 +274,10 @@ def generate_certificate_with_sans( with open(cert_path, "wb") as f: f.write(certificate.public_bytes(serialization.Encoding.PEM)) - log_info(f"Generated certificate with {len(san_entries)} SAN entries") - log_info(f" DNS names: {dns_names}") - log_info(f" IP addresses: {ip_addresses}") - log_info(f" URI: {app_uri}") + log_debug(f"Generated certificate with {len(san_entries)} SAN entries") + log_debug(f" DNS names: {dns_names}") + log_debug(f" IP addresses: {ip_addresses}") + log_debug(f" URI: {app_uri}") return True @@ -507,7 +507,7 @@ def _is_certificate_valid(self, cert_path: str) -> bool: # Certificate is valid days_until_expiry = (not_valid_after - now_utc).days - log_info(f"Certificate {cert_path} is valid for {days_until_expiry} more days") + log_debug(f"Certificate {cert_path} is valid for {days_until_expiry} more days") return True except Exception as e: @@ -526,7 +526,7 @@ def _remove_certificate_files(self, cert_path: str, key_path: str) -> None: if os.path.exists(file_path): try: os.remove(file_path) - log_info(f"Removed expired certificate file: {file_path}") + log_debug(f"Removed expired certificate file: {file_path}") except Exception as e: log_warn(f"Failed to remove file {file_path}: {e}") @@ -547,14 +547,14 @@ async def _ensure_server_certificates(self) -> bool: # Check if certificates already exist and are valid if os.path.exists(cert_path) and os.path.exists(key_path): if self._is_certificate_valid(cert_path): - log_info(f"Found valid server certificates in {self.certs_dir}") + log_debug(f"Found valid server certificates in {self.certs_dir}") else: - log_info("Server certificate is expired or invalid, regenerating") + log_debug("Server certificate is expired or invalid, regenerating") self._remove_certificate_files(cert_path, key_path) if not await self.generate_server_certificate(cert_path, key_path): return False else: - log_info(f"Server certificates not found, generating new ones in {self.certs_dir}") + log_debug(f"Server certificates not found, generating new ones in {self.certs_dir}") if not await self.generate_server_certificate(cert_path, key_path): return False @@ -585,7 +585,7 @@ def _load_certificates(self, cert_path: str, key_path: str) -> bool: if not self._validate_certificate_format(): return False - log_info(f"Server certificates loaded from {cert_path}") + log_debug(f"Server certificates loaded from {cert_path}") return True except FileNotFoundError as e: @@ -657,9 +657,9 @@ def _validate_certificate_format(self) -> bool: if isinstance(name, x509.UniformResourceIdentifier) ] - log_info(f"Certificate SAN DNS names: {dns_names}") - log_info(f"Certificate SAN IP addresses: {ip_addresses}") - log_info(f"Certificate SAN URIs: {uris}") + log_debug(f"Certificate SAN DNS names: {dns_names}") + log_debug(f"Certificate SAN IP addresses: {ip_addresses}") + log_debug(f"Certificate SAN URIs: {uris}") # Check if we have expected entries system_hostname = socket.gethostname() @@ -690,7 +690,7 @@ def _validate_certificate_format(self) -> bool: except x509.ExtensionNotFound: log_warn("Certificate missing key usage extension") - log_info("Certificate format and extensions validated") + log_debug("Certificate format and extensions validated") return True except ImportError: @@ -701,7 +701,7 @@ def _validate_certificate_format(self) -> bool: try: # Try as DER format ssl.DER_cert_to_PEM_cert(self.certificate_data) - log_info("Certificate validated as DER format") + log_debug("Certificate validated as DER format") return True except Exception as e: log_error(f"Invalid certificate format: {e}") @@ -733,13 +733,13 @@ def _load_trusted_certificates(self) -> bool: {"pem": cert_pem, "der": cert_der, "hash": cert_hash} ) - log_info(f"Loaded trusted certificate {i + 1} (SHA256: {cert_hash})") + log_debug(f"Loaded trusted certificate {i + 1} (SHA256: {cert_hash})") except Exception as e: log_error(f"Invalid trusted certificate {i + 1}: {e}") return False - log_info(f"Loaded {len(self.trusted_certificates)} trusted client certificates") + log_debug(f"Loaded {len(self.trusted_certificates)} trusted client certificates") return True except Exception as e: @@ -774,7 +774,7 @@ def validate_client_certificate(self, client_cert_pem: str) -> bool: # Check if client certificate matches any trusted certificate for trusted_cert in self.trusted_certificates: if trusted_cert["der"] == client_cert_der: - log_info(f"Client certificate trusted (SHA256: {client_hash})") + log_debug(f"Client certificate trusted (SHA256: {client_hash})") return True log_error(f"Client certificate not trusted (SHA256: {client_hash})") @@ -863,9 +863,9 @@ async def generate_server_certificate( local_ips = get_local_ip_addresses() ip_addresses = list(local_ips) - log_info(f"Generating certificate with DNS SANs: {dns_names}") - log_info(f"Generating certificate with IP SANs: {ip_addresses}") - log_info(f"Application URI: {app_uri}") + log_debug(f"Generating certificate with DNS SANs: {dns_names}") + log_debug(f"Generating certificate with IP SANs: {ip_addresses}") + log_debug(f"Application URI: {app_uri}") # Use custom certificate generation with multiple SANs success = generate_certificate_with_sans( @@ -880,7 +880,7 @@ async def generate_server_certificate( ) if success: - log_info(f"Server certificate generated with proper SANs: {cert_path}") + log_debug(f"Server certificate generated with proper SANs: {cert_path}") return success except Exception as e: @@ -907,7 +907,7 @@ async def setup_server_security(self, server, security_profiles, app_uri: str = if policy_type is not None: security_policies.append(policy_type) - log_info( + log_debug( f"Added security profile '{profile.name}': {profile.security_policy}/{profile.security_mode} -> {policy_type}" ) else: @@ -919,12 +919,12 @@ async def setup_server_security(self, server, security_profiles, app_uri: str = permission_ruleset = OpenPLCRoleRuleset() if security_policies: - log_info("=== SECURITY MANAGER DEBUG ===") - log_info(f"Setting {len(security_policies)} security policies: {security_policies}") + log_debug("=== SECURITY MANAGER DEBUG ===") + log_debug(f"Setting {len(security_policies)} security policies: {security_policies}") server.set_security_policy(security_policies, permission_ruleset=permission_ruleset) - log_info("Security policies applied to server successfully") - log_info("Using OpenPLCRoleRuleset for subscription permission support") - log_info("=== END SECURITY MANAGER DEBUG ===") + log_debug("Security policies applied to server successfully") + log_debug("Using OpenPLCRoleRuleset for subscription permission support") + log_debug("=== END SECURITY MANAGER DEBUG ===") else: # Default to no security if no profiles enabled log_warn("No security profiles enabled, defaulting to NoSecurity") @@ -933,9 +933,9 @@ async def setup_server_security(self, server, security_profiles, app_uri: str = ) # Setup server certificates if needed - log_info("=== CERTIFICATE SETUP DEBUG ===") + log_debug("=== CERTIFICATE SETUP DEBUG ===") await self._setup_server_certificates_for_asyncua(server, app_uri) - log_info("=== END CERTIFICATE SETUP DEBUG ===") + log_debug("=== END CERTIFICATE SETUP DEBUG ===") async def _setup_server_certificates_for_asyncua(self, server, app_uri: str = None) -> None: """Setup server certificates for asyncua Server. @@ -965,17 +965,17 @@ async def _setup_server_certificates_for_asyncua(self, server, app_uri: str = No # Check if we need to generate new certificates need_generation = False if not cert_file.exists() or not key_file.exists(): - log_info("Certificate files not found, will generate new ones") + log_debug("Certificate files not found, will generate new ones") need_generation = True elif not self._is_certificate_valid(str(cert_file)): - log_info("Certificate is expired or invalid, will regenerate") + log_debug("Certificate is expired or invalid, will regenerate") self._remove_certificate_files(str(cert_file), str(key_file)) need_generation = True if need_generation: - log_info(f"Generating new self-signed certificate in {cert_dir}") - log_info(f"Certificate will be created for app_uri: {app_uri}") - log_info(f"Certificate will be created for hostname: {hostname}") + log_debug(f"Generating new self-signed certificate in {cert_dir}") + log_debug(f"Certificate will be created for app_uri: {app_uri}") + log_debug(f"Certificate will be created for hostname: {hostname}") # Collect DNS names for SAN dns_names = [hostname] @@ -986,8 +986,8 @@ async def _setup_server_certificates_for_asyncua(self, server, app_uri: str = No local_ips = get_local_ip_addresses() ip_addresses = list(local_ips) - log_info(f"Certificate DNS SANs: {dns_names}") - log_info(f"Certificate IP SANs: {ip_addresses}") + log_debug(f"Certificate DNS SANs: {dns_names}") + log_debug(f"Certificate IP SANs: {ip_addresses}") # Use custom certificate generation with multiple SANs success = generate_certificate_with_sans( @@ -1006,18 +1006,18 @@ async def _setup_server_certificates_for_asyncua(self, server, app_uri: str = No ) return - log_info(f"Certificate files created successfully: {cert_file}, {key_file}") + log_debug(f"Certificate files created successfully: {cert_file}, {key_file}") else: - log_info(f"Using existing valid certificate files: {cert_file}, {key_file}") + log_debug(f"Using existing valid certificate files: {cert_file}, {key_file}") # Load and convert certificate from PEM to DER - log_info(f"Loading server certificate from: {cert_file}") + log_debug(f"Loading server certificate from: {cert_file}") with open(cert_file, "rb") as f: cert_pem_data = f.read() - log_info(f"Certificate PEM loaded: {len(cert_pem_data)} bytes") + log_debug(f"Certificate PEM loaded: {len(cert_pem_data)} bytes") # Load private key - log_info(f"Loading server private key from: {key_file}") + log_debug(f"Loading server private key from: {key_file}") with open(key_file, "rb") as f: key_pem_data = f.read() @@ -1030,7 +1030,7 @@ async def _setup_server_certificates_for_asyncua(self, server, app_uri: str = No # Convert certificate PEM to DER cert_obj = x509.load_pem_x509_certificate(cert_pem_data) cert_der_data = cert_obj.public_bytes(serialization.Encoding.DER) - log_info(f"Certificate converted to DER: {len(cert_der_data)} bytes") + log_debug(f"Certificate converted to DER: {len(cert_der_data)} bytes") # Convert private key PEM to DER private_key = load_pem_private_key(key_pem_data, password=None) @@ -1039,19 +1039,19 @@ async def _setup_server_certificates_for_asyncua(self, server, app_uri: str = No format=serialization.PrivateFormat.PKCS8, encryption_algorithm=serialization.NoEncryption(), ) - log_info(f"Private key converted to DER: {len(key_der_data)} bytes") + log_debug(f"Private key converted to DER: {len(key_der_data)} bytes") # Load certificate and key into server (both in DER format) - log_info(f"Loading certificate into asyncua server: {len(cert_der_data)} bytes DER") + log_debug(f"Loading certificate into asyncua server: {len(cert_der_data)} bytes DER") await server.load_certificate(cert_der_data) - log_info(f"Loading private key into asyncua server: {len(key_der_data)} bytes DER") + log_debug(f"Loading private key into asyncua server: {len(key_der_data)} bytes DER") await server.load_private_key(key_der_data) except Exception as e: log_error(f"Failed to load certificate/key into asyncua server: {e}") raise - log_info("Self-signed server certificate loaded successfully into asyncua server") + log_debug("Self-signed server certificate loaded successfully into asyncua server") elif hasattr(self.config, "security") and self.config.security.server_certificate_custom: cert_path = self.config.security.server_certificate_custom @@ -1079,14 +1079,14 @@ async def _setup_server_certificates_for_asyncua(self, server, app_uri: str = No await server.load_certificate(cert_data) await server.load_private_key(der_key_data) - log_info("Custom server certificate loaded (PEM cert + DER key)") + log_debug("Custom server certificate loaded (PEM cert + DER key)") except Exception as e: log_error(f"Failed to load custom certificate: {e}") elif self.certificate_data and self.private_key_data: await server.load_certificate(self.certificate_data) await server.load_private_key(self.private_key_data) - log_info("SecurityManager certificates loaded into server") + log_debug("SecurityManager certificates loaded into server") async def create_trust_store(self, trusted_certificates: List[str]) -> Optional[TrustStore]: """Create and configure TrustStore with trusted client certificates. @@ -1119,7 +1119,7 @@ async def create_trust_store(self, trusted_certificates: List[str]) -> Optional[ f.write(cert_der) cert_files.append(cert_file) - log_info(f"Added trusted certificate {i + 1} to trust store") + log_debug(f"Added trusted certificate {i + 1} to trust store") except Exception as e: log_warn(f"Failed to process trusted certificate {i + 1}: {e}") @@ -1128,7 +1128,7 @@ async def create_trust_store(self, trusted_certificates: List[str]) -> Optional[ # Create TrustStore with certificate files trust_store = TrustStore(cert_files, []) await trust_store.load() - log_info(f"TrustStore created with {len(cert_files)} certificates") + log_debug(f"TrustStore created with {len(cert_files)} certificates") return trust_store else: log_warn("No valid trusted certificates processed") @@ -1146,7 +1146,7 @@ def cleanup(self) -> None: if self._trust_store_temp_dir and os.path.exists(self._trust_store_temp_dir): try: shutil.rmtree(self._trust_store_temp_dir) - log_info(f"Cleaned up trust store temp directory: {self._trust_store_temp_dir}") + log_debug(f"Cleaned up trust store temp directory: {self._trust_store_temp_dir}") self._trust_store_temp_dir = None except Exception as e: log_warn(f"Failed to clean up trust store temp directory: {e}") @@ -1182,7 +1182,7 @@ async def setup_certificate_validation(self, server, trusted_certificates) -> No # Set validator on server server.set_certificate_validator(cert_validator) - log_info("Certificate validation configured") + log_debug("Certificate validation configured") except Exception as e: log_error(f"Failed to setup certificate validation: {e}") diff --git a/core/src/drivers/plugins/python/opcua/plugin.py b/core/src/drivers/plugins/python/opcua/plugin.py index 41962f0e..c8e1c31f 100644 --- a/core/src/drivers/plugins/python/opcua/plugin.py +++ b/core/src/drivers/plugins/python/opcua/plugin.py @@ -36,12 +36,12 @@ # Import local modules (use absolute imports for runtime compatibility) try: # Try relative imports first (when loaded as package) - from .opcua_logging import get_logger, log_info, log_warn, log_error + from .opcua_logging import get_logger, log_debug, log_error, log_info, log_warn from .config import load_config from .server import OpcuaServerManager except ImportError: # Fall back to absolute imports (when loaded directly by runtime) - from opcua_logging import get_logger, log_info, log_warn, log_error + from opcua_logging import get_logger, log_debug, log_error, log_info, log_warn from config import load_config from server import OpcuaServerManager @@ -82,7 +82,7 @@ def init(args_capsule) -> bool: logging_accessor = SafeLoggingAccess(_runtime_args) if logging_accessor.is_valid: get_logger().initialize(logging_accessor) - log_info("Logging initialized with runtime accessor") + log_debug("Logging initialized with runtime accessor") # Create buffer accessor _buffer_accessor = SafeBufferAccess(_runtime_args) @@ -90,7 +90,7 @@ def init(args_capsule) -> bool: log_error(f"Failed to create buffer accessor: {_buffer_accessor.error_msg}") return False - log_info("Buffer accessor created") + log_debug("Buffer accessor created") # Load configuration config_path, config_error = _buffer_accessor.get_config_path() @@ -144,7 +144,7 @@ def start_loop() -> bool: ) _server_thread.start() - log_info("OPC UA server thread started") + log_debug("OPC UA server thread started") return True except Exception as e: @@ -176,7 +176,7 @@ def stop_loop() -> bool: if _server_thread.is_alive(): log_warn("Server thread did not stop within timeout") else: - log_info("Server thread stopped") + log_debug("Server thread stopped") _server_thread = None log_info("OPC UA server stopped") diff --git a/core/src/drivers/plugins/python/opcua/server.py b/core/src/drivers/plugins/python/opcua/server.py index cd637454..72bed7e2 100644 --- a/core/src/drivers/plugins/python/opcua/server.py +++ b/core/src/drivers/plugins/python/opcua/server.py @@ -149,7 +149,7 @@ async def run(self) -> None: return # Run main loop - log_info("Server running, entering main loop...") + log_debug("Server running, entering main loop...") await self._main_loop() except Exception as e: @@ -164,7 +164,7 @@ async def stop(self) -> None: Sets running flag to False and waits for main loop to exit. """ - log_info("Stop requested...") + log_debug("Stop requested...") self.running = False async def _setup_server(self) -> bool: @@ -194,7 +194,7 @@ async def _setup_server(self) -> bool: ) self.server.set_endpoint(normalized_endpoint) self._client_endpoints = suggest_client_endpoints(normalized_endpoint) - log_info(f"Server endpoint set to: {normalized_endpoint}") + log_debug(f"Server endpoint set to: {normalized_endpoint}") except Exception as e: log_warn(f"Endpoint normalization failed, using raw URL: {e}") self.server.set_endpoint(self.config.server.endpoint_url) @@ -219,13 +219,13 @@ async def _setup_server(self) -> bool: # Initialize the server await self.server.init() - log_info("OPC-UA server initialized") + log_debug("OPC-UA server initialized") # Register namespace (AFTER init) self.namespace_idx = await self.server.register_namespace( self.config.address_space.namespace_uri ) - log_info( + log_debug( f"Registered namespace: {self.config.address_space.namespace_uri} " f"(index: {self.namespace_idx})" ) @@ -240,7 +240,7 @@ async def _setup_server(self) -> bool: build_date=datetime.now() ) - log_info("OPC-UA server setup completed successfully") + log_debug("OPC-UA server setup completed successfully") return True except Exception as e: @@ -267,10 +267,10 @@ async def _start_server(self) -> bool: # Print alternative endpoints for client connection if self._client_endpoints: - log_info("Alternative client endpoints:") + log_debug("Alternative client endpoints:") for scenario, endpoint in self._client_endpoints.items(): if endpoint: - log_info(f" {scenario}: {endpoint}") + log_debug(f" {scenario}: {endpoint}") return True @@ -302,7 +302,7 @@ async def _main_loop(self) -> None: try: await asyncio.sleep(cycle_time) except asyncio.CancelledError: - log_info("Main loop cancelled") + log_debug("Main loop cancelled") break async def _cleanup(self) -> None: @@ -355,7 +355,7 @@ async def _create_address_space(self) -> bool: self.node_permissions = self.address_space_builder.node_permissions self.nodeid_to_variable = self.address_space_builder.nodeid_to_variable - log_info(f"Address space created with {len(self.variable_nodes)} nodes") + log_debug(f"Address space created with {len(self.variable_nodes)} nodes") return True except Exception as e: @@ -385,7 +385,7 @@ async def _initialize_sync_manager(self) -> bool: log_warn("Sync manager initialization failed - sync may be limited") # Don't fail completely - sync manager can still work with batch ops - log_info("Synchronization manager initialized") + log_debug("Synchronization manager initialized") return True except Exception as e: @@ -406,7 +406,7 @@ async def _register_callbacks(self) -> bool: try: # Only register callbacks if we have nodes with permissions if not self.node_permissions: - log_info("No node permissions configured - skipping callback registration") + log_debug("No node permissions configured - skipping callback registration") return True self.callback_handler = PermissionCallbackHandler( @@ -418,7 +418,7 @@ async def _register_callbacks(self) -> bool: log_warn("Callback registration returned False") return False - log_info("Permission callback handler initialized") + log_debug("Permission callback handler initialized") return True except Exception as e: @@ -433,17 +433,17 @@ async def _register_callbacks(self) -> bool: async def debug_endpoints(self) -> None: """Debug method to verify endpoint configuration.""" try: - log_info("=== ENDPOINT VERIFICATION ===") + log_debug("=== ENDPOINT VERIFICATION ===") endpoints = await self.server.get_endpoints() - log_info(f"Total endpoints created: {len(endpoints)}") + log_debug(f"Total endpoints created: {len(endpoints)}") for i, endpoint in enumerate(endpoints): - log_info(f"Endpoint {i+1}:") - log_info(f" URL: {endpoint.EndpointUrl}") - log_info(f" Security Policy: {endpoint.SecurityPolicyUri}") - log_info(f" Security Mode: {endpoint.SecurityMode}") - log_info(f" User Tokens: {len(endpoint.UserIdentityTokens)}") + log_debug(f"Endpoint {i+1}:") + log_debug(f" URL: {endpoint.EndpointUrl}") + log_debug(f" Security Policy: {endpoint.SecurityPolicyUri}") + log_debug(f" Security Mode: {endpoint.SecurityMode}") + log_debug(f" User Tokens: {len(endpoint.UserIdentityTokens)}") - log_info("=== END ENDPOINT VERIFICATION ===") + log_debug("=== END ENDPOINT VERIFICATION ===") except Exception as e: log_error(f"Error during endpoint verification: {e}") diff --git a/core/src/drivers/plugins/python/opcua/synchronization.py b/core/src/drivers/plugins/python/opcua/synchronization.py index 57758291..6915e790 100644 --- a/core/src/drivers/plugins/python/opcua/synchronization.py +++ b/core/src/drivers/plugins/python/opcua/synchronization.py @@ -135,8 +135,8 @@ async def initialize(self) -> bool: if var_node.access_mode == "readwrite" } - log_info(f"Sync manager: {len(self._readwrite_nodes)} readwrite nodes, " - f"{len(self.variable_nodes) - len(self._readwrite_nodes)} readonly nodes") + log_debug(f"Sync manager: {len(self._readwrite_nodes)} readwrite nodes, " + f"{len(self.variable_nodes) - len(self._readwrite_nodes)} readonly nodes") # Initialize metadata cache for direct memory access if self.variable_nodes: @@ -157,9 +157,9 @@ async def initialize(self) -> bool: self._direct_memory_access_enabled = bool(self.variable_metadata) if self._direct_memory_access_enabled: - log_info(f"Direct memory access enabled for {len(self.variable_metadata)} indices") + log_debug(f"Direct memory access enabled for {len(self.variable_metadata)} indices") else: - log_info("Using batch operations for sync") + log_debug("Using batch operations for sync") return True @@ -193,9 +193,9 @@ async def _reinitialize_metadata(self) -> None: self._direct_memory_access_enabled = bool(self.variable_metadata) if self._direct_memory_access_enabled: - log_info(f"Direct memory access enabled for {len(self.variable_metadata)} indices") + log_debug(f"Direct memory access enabled for {len(self.variable_metadata)} indices") else: - log_info("Using batch operations for sync") + log_debug("Using batch operations for sync") # Clear value cache to force full sync on next cycle self.opcua_value_cache.clear() @@ -254,7 +254,7 @@ async def run( await asyncio.sleep(cycle_time_seconds) except asyncio.CancelledError: - log_info("Sync loop cancelled") + log_debug("Sync loop cancelled") break except Exception as e: log_error(f"Error in sync loop: {e}") diff --git a/core/src/drivers/plugins/python/opcua/user_manager.py b/core/src/drivers/plugins/python/opcua/user_manager.py index bd005fde..8bcba480 100644 --- a/core/src/drivers/plugins/python/opcua/user_manager.py +++ b/core/src/drivers/plugins/python/opcua/user_manager.py @@ -125,9 +125,9 @@ def hash_password(password: str) -> str: # Import logging (handle both package and direct loading) try: - from .opcua_logging import log_error, log_info, log_warn + from .opcua_logging import log_debug, log_error, log_info, log_warn except ImportError: - from opcua_logging import log_info, log_warn, log_error + from opcua_logging import log_debug, log_error, log_info, log_warn from shared.plugin_config_decode.opcua_config_model import OpcuaConfig # noqa: E402 @@ -389,7 +389,7 @@ def get_user( ) return None - log_info(f"Authentication attempt: method={auth_method}") + log_debug(f"Authentication attempt: method={auth_method}") # Find a security profile that supports this authentication method profile = self._find_profile_by_auth_method(auth_method) @@ -403,7 +403,7 @@ def get_user( self.rate_limiter.record_attempt(rate_limit_id, success=False) return None - log_info(f"Using security profile '{profile.name}' for {auth_method} authentication") + log_debug(f"Using security profile '{profile.name}' for {auth_method} authentication") # Authenticate based on method user = None @@ -425,7 +425,7 @@ def get_user( if user: # Store OpenPLC role as attribute for permission callbacks user.openplc_role = openplc_role - log_info( + log_debug( f"User '{user.name or 'anonymous'}' authenticated successfully " f"using '{auth_method}' method for profile '{profile.name}' " f"(role: {openplc_role})" @@ -506,7 +506,7 @@ def _authenticate_certificate(self, certificate: Any) -> tuple[Optional[User], O openplc_role = self._user_roles.get(f"cert:{cert_id}", "viewer") asyncua_role = self.ROLE_MAPPING.get(openplc_role, UserRole.User) - log_info(f"Certificate authenticated as user with role '{openplc_role}'") + log_debug(f"Certificate authenticated as user with role '{openplc_role}'") # Return asyncua User object return User(role=asyncua_role, name=f"cert:{cert_id}"), openplc_role @@ -551,7 +551,7 @@ def _extract_cert_id(self, certificate: Any) -> Optional[str]: for cert_info in self.config.security.trusted_client_certificates: config_fingerprint = self._pem_to_fingerprint(cert_info["pem"]) if config_fingerprint and client_fingerprint == config_fingerprint: - log_info( + log_debug( f"Certificate matched: {cert_info['id']} " f"(fingerprint: {client_fingerprint[:16]}...)" ) @@ -673,7 +673,7 @@ def _find_profile_by_auth_method(self, auth_method: str) -> Optional[Any]: if not profile.enabled: continue if auth_method in profile.auth_methods: - log_info(f"Found profile '{profile.name}' supporting {auth_method}") + log_debug(f"Found profile '{profile.name}' supporting {auth_method}") return profile log_warn(f"No enabled profile found supporting authentication method: {auth_method}")