Normalize log output format for human-readable stdout by thiagoralves · Pull Request #98 · Autonomy-Logic/openplc-runtime

thiagoralves · 2026-01-30T18:33:20Z

Summary

Implement human-readable log format for stdout while preserving JSON for API responses
Convert all printf/print calls across C and Python to use the centralized logging system
Change verbose OPC-UA plugin logging from INFO to DEBUG level

Changes

Phase 1: Python Logging Formatter

Add HumanReadableFormatter class that converts JSON logs to [YYYY-MM-DD HH:MM:SS] [LEVEL] message format
Apply to StreamHandler (stdout) while keeping JsonFormatter for BufferHandler (API)

Phase 2: C printf/fprintf Conversions

Convert 73 printf/fprintf calls in plugin_driver.c to log_info/log_error/log_warn/log_debug
Convert calls in plugin_config.c, journal_buffer.c, plc_main.c, watchdog.c
Fix native plugin symbol issue by using PLUGIN_LOGGER_STDERR macro instead of log.h

Phase 3: Python print() Conversions

Convert print() calls in webserver files to use logger (plugin_config_model.py, credentials.py, config.py, app.py)

Phase 4: Plugin Fallback Updates

Update fallback print() in shared/plugin_logger.py and opcua/opcua_logging.py with timestamp format

Phase 5: OPC-UA Verbose Logging Fix

Change ~50 verbose log_info calls to log_debug across 9 OPC-UA plugin files
Keep important status messages (plugin lifecycle, server start/stop, security init) as INFO

Before/After

Before:

[PLUGIN]: Creating Python capsule for args
[OPCUA INFO] OPC UA Plugin initializing...
{"timestamp": "1769785673", "level": "INFO", "message": "Logging initialized", "id": 8}
[2026-01-30 18:12:44] [INFO] Added security profile 'signed': Basic256Sha256/Sign -> 5
[2026-01-30 18:12:44] [INFO] === SECURITY MANAGER DEBUG ===

After:

[2024-01-30 12:00:00] [INFO] Creating Python capsule for args
[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] Security initialized: policy=Basic256Sha256, mode=SignAndEncrypt

(Verbose security/certificate details now only appear with --print-debug)

Test plan

Run runtime and verify all stdout logs use human-readable format
Verify API /api/runtime-logs still returns JSON
Verify --print-debug flag shows DEBUG level messages
Test plugin fallback logging (when runtime logging unavailable)

🤖 Generated with Claude Code

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 <noreply@anthropic.com>

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 <noreply@anthropic.com>

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 <noreply@anthropic.com>

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 <noreply@anthropic.com>

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 <noreply@anthropic.com>

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 <noreply@anthropic.com>

Copilot

Pull request overview

This PR standardizes log output to a human-readable format [YYYY-MM-DD HH:MM:SS] [LEVEL] message for stdout while preserving JSON format for API responses. The changes include adding a HumanReadableFormatter class, converting 84 printf/fprintf calls in C code and ~40 print() calls in Python to use centralized logging, and reducing verbose OPC-UA plugin logging by changing ~50 INFO-level logs to DEBUG.

Changes:

Implemented dual formatters: HumanReadableFormatter for stdout and JsonFormatter for API
Converted direct output calls (printf/print) across C and Python to logging system
Reduced OPC-UA plugin verbosity by demoting diagnostic logs from INFO to DEBUG

Reviewed changes

Copilot reviewed 25 out of 25 changed files in this pull request and generated 5 comments.

Show a summary per file

File	Description
webserver/logger/formatter.py	Added `HumanReadableFormatter` class to parse JSON logs and format as `[timestamp] [level] message`
webserver/logger/logger.py	Changed StreamHandler to use `HumanReadableFormatter` instead of `JsonFormatter`
webserver/logger/init.py	Updated exports and StreamHandler formatter
webserver/plugin_config_model.py	Converted 6 print() calls to logger.info/error/warning
webserver/credentials.py	Converted 10 print() calls to logger.info/error/warning
webserver/config.py	Converted 2 print() calls to logger.info/error
webserver/app.py	Converted 2 print() calls to logger.info
core/src/plc_app/utils/watchdog.c	Converted fprintf to formatted timestamp output
core/src/plc_app/plc_main.c	Converted fprintf to formatted timestamp output
core/src/plc_app/journal_buffer.c	Converted 2 fprintf calls to log_error
core/src/drivers/plugins/python/shared/plugin_logger.py	Updated fallback print() to include timestamp
core/src/drivers/plugins/python/opcua/*.py	Changed ~50 verbose log_info calls to log_debug across 9 files
core/src/drivers/plugins/native/plugin_logger.c	Added PLUGIN_LOGGER_STDERR macro and updated fallback to match format
core/src/drivers/plugin_driver.c	Converted 73 printf/fprintf calls to log_info/error/warn/debug
core/src/drivers/plugin_config.c	Converted 2 printf calls to log_debug
docs/LOGGING_NORMALIZATION_PLAN.md	Added comprehensive documentation of logging changes

💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.

Copilot · 2026-01-30T18:36:36Z


+from webserver.logger import get_logger
+
+logger, _ = get_logger(__name__)


The underscore variable name for the second return value is unclear. Consider using a more descriptive name like buffer_handler or add a comment explaining it represents an unused buffer handler.

Suggested change

logger, _ = get_logger(__name__)

logger, buffer_handler = get_logger(__name__) # buffer_handler is provided by get_logger but not used in this module

Copilot · 2026-01-30T18:36:37Z

+/* 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);                             \


The PLUGIN_LOGGER_STDERR macro calls time() and gmtime_r() on every invocation. For frequently called logging, consider caching the timestamp or using a less expensive time source.

Suggested change

/* 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); \

/* Cached time helper for formatted stderr output */

static void plugin_logger_get_time_str(char *buffer, size_t buffer_size)

{

static time_t last_time = (time_t)0;

static char cached_time_buf[20] = {0};

time_t now = time(NULL);

if (now != last_time)

{

struct tm t;

if (gmtime_r(&now, &t) != NULL)

{

/* Ensure consistent format: "YYYY-MM-DD HH:MM:SS" */

if (strftime(cached_time_buf, sizeof(cached_time_buf), "%Y-%m-%d %H:%M:%S", &t) == 0)

{

/* Fallback in unlikely case of formatting failure */

cached_time_buf[0] = '\0';

}

}

else

{

cached_time_buf[0] = '\0';

}

last_time = now;

}

if (buffer && buffer_size > 0)

{

/* Copy cached timestamp into caller's buffer */

strncpy(buffer, cached_time_buf, buffer_size - 1);

buffer[buffer_size - 1] = '\0';

}

}

/* Helper macro for formatted stderr output matching human-readable log format */

#define PLUGIN_LOGGER_STDERR(level, fmt, ...) \

do \

{ \

char time_buf[20]; \

plugin_logger_get_time_str(time_buf, sizeof(time_buf)); \

Copilot · 2026-01-30T18:36:37Z

+        /* 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);


This timestamp formatting code is duplicated in the PLUGIN_LOGGER_STDERR macro above. Consider extracting it into a helper function to avoid duplication.

Copilot · 2026-01-30T18:36:37Z

+            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);


This timestamp formatting code is duplicated across multiple C files (watchdog.c, plc_main.c, plugin_logger.c). Consider creating a shared helper function in log.c to reduce duplication.

Copilot · 2026-01-30T18:36:37Z

+        log_error("Error: 'init' function not found or not callable in module '%s' - this function "
+                  "is required",


The error message spans two lines but reads as a single sentence. This could be confusing. Consider reformatting to 'Error: Required function "init" not found or not callable in module "%s"' on a single line.

Suggested change

log_error("Error: 'init' function not found or not callable in module '%s' - this function "

"is required",

log_error("Error: Required function \"init\" not found or not callable in module \"%s\"",

thiagoralves and others added 6 commits January 30, 2026 11:29

thiagoralves requested a review from Copilot January 30, 2026 18:35

Copilot AI reviewed Jan 30, 2026

View reviewed changes

thiagoralves merged commit db6eb3a into development Jan 30, 2026
1 check failed

thiagoralves deleted the feature/normalize-log-output branch January 30, 2026 18:39

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Normalize log output format for human-readable stdout#98

Normalize log output format for human-readable stdout#98
thiagoralves merged 6 commits into
developmentfrom
feature/normalize-log-output

thiagoralves commented Jan 30, 2026

Uh oh!

Copilot AI left a comment

Uh oh!

Copilot AI Jan 30, 2026

Uh oh!

Copilot AI Jan 30, 2026

Uh oh!

Copilot AI Jan 30, 2026

Uh oh!

Copilot AI Jan 30, 2026

Uh oh!

Copilot AI Jan 30, 2026

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants


		from webserver.logger import get_logger

		logger, _ = get_logger(__name__)

	logger, _ = get_logger(__name__)
	logger, buffer_handler = get_logger(__name__) # buffer_handler is provided by get_logger but not used in this module

-/* 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);                             \
+/* Cached time helper for formatted stderr output */
+static void plugin_logger_get_time_str(char *buffer, size_t buffer_size)
+{
+    static time_t last_time = (time_t)0;
+    static char cached_time_buf[20] = {0};
+    time_t now = time(NULL);
+    if (now != last_time)
+    {
+        struct tm t;
+        if (gmtime_r(&now, &t) != NULL)
+        {
+            /* Ensure consistent format: "YYYY-MM-DD HH:MM:SS" */
+            if (strftime(cached_time_buf, sizeof(cached_time_buf), "%Y-%m-%d %H:%M:%S", &t) == 0)
+            {
+                /* Fallback in unlikely case of formatting failure */
+                cached_time_buf[0] = '\0';
+            }
+        }
+        else
+        {
+            cached_time_buf[0] = '\0';
+        }
+        last_time = now;
+    }
+    if (buffer && buffer_size > 0)
+    {
+        /* Copy cached timestamp into caller's buffer */
+        strncpy(buffer, cached_time_buf, buffer_size - 1);
+        buffer[buffer_size - 1] = '\0';
+    }
+}
+/* Helper macro for formatted stderr output matching human-readable log format */
+#define PLUGIN_LOGGER_STDERR(level, fmt, ...)                                                      \
+    do                                                                                             \
+    {                                                                                              \
+        char time_buf[20];                                                                         \
+        plugin_logger_get_time_str(time_buf, sizeof(time_buf));                                    \

		log_error("Error: 'init' function not found or not callable in module '%s' - this function "
		"is required",

	log_error("Error: 'init' function not found or not callable in module '%s' - this function "
	"is required",
	log_error("Error: Required function \"init\" not found or not callable in module \"%s\"",

Conversation

thiagoralves commented Jan 30, 2026

Summary

Changes

Phase 1: Python Logging Formatter

Phase 2: C printf/fprintf Conversions

Phase 3: Python print() Conversions

Phase 4: Plugin Fallback Updates

Phase 5: OPC-UA Verbose Logging Fix

Before/After

Test plan

Uh oh!

Copilot AI left a comment

Choose a reason for hiding this comment

Pull request overview

Reviewed changes

Uh oh!

Copilot AI Jan 30, 2026

Choose a reason for hiding this comment

Uh oh!

Copilot AI Jan 30, 2026

Choose a reason for hiding this comment

Uh oh!

Copilot AI Jan 30, 2026

Choose a reason for hiding this comment

Uh oh!

Copilot AI Jan 30, 2026

Choose a reason for hiding this comment

Uh oh!

Copilot AI Jan 30, 2026

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants