From 3e81f98be553d89ca7cae715a5650b87614fe762 Mon Sep 17 00:00:00 2001 From: Thiago Alves Date: Fri, 30 Jan 2026 11:29:12 -0500 Subject: [PATCH 1/6] 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 2/6] 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 3/6] 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 4/6] 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 5/6] 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 6/6] 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}")