Logging

How Logging Works

Manager.start() installs a log handler on the root logger. From that moment on, every record that passes the level of its logger is forwarded to WinCC OA. Nothing has to be configured and nothing beyond logging has to be imported.

If the root logger still carries the Python default level WARNING when the manager starts, the level is lowered to DEBUG. A level that was set before start() is kept, so an explicit configuration is never overwritten.

Records written before start() do not reach the WinCC OA log, because the handler does not exist yet. They are processed by whatever configuration is active at that point — by default the last-resort handler of Python, which writes WARNING and above to sys.stderr.

The handler is internal. It is not exported and carries no public name.

Log Levels and Destinations

The level of a record determines the WinCC OA priority and the file the record is written to.


Python level	Value	WinCC OA priority	Destination
`CRITICAL`	50	`PRIO_FATAL`	`<project>/log/PVSS_II.log`
`ERROR`	40	`PRIO_SEVERE`	`<project>/log/PVSS_II.log`
`WARNING`	30	`PRIO_WARNING`	`<project>/log/PVSS_II.log`
`INFO`	20	`PRIO_INFO`	`<project>/log/PVSS_II.log`
`DEBUG`	10	—	`<project>/log/python<num>.log`

<num> is the manager number the script was started with.

Warning CRITICAL stops the manager. It is mapped to PRIO_FATAL, and a fatal error ends a WinCC OA manager by definition. The record is written to PVSS_II.log and the manager shuts down immediately afterwards, so the rest of the script does not run. Use ERROR for a condition the script reports but survives, and reserve CRITICAL for the case where stopping is the intended reaction.

The values in the table are lower bounds. A custom level in between is mapped to the next lower entry, so level 35 is written with PRIO_WARNING and level 25 with PRIO_INFO. Everything below 20 takes the DEBUG path.

The split keeps the central log file free of development output. DEBUG records stay in the log file of the manager, while everything from INFO upwards appears in PVSS_II.log together with the output of all other managers. The LogViewer displays both files.

Writing Log Messages

Create one logger per module and name it after the module.

import logging

logger = logging.getLogger(__name__)


def start_pump(name: str) -> None:
    logger.info("starting pump %s", name)

The logger name becomes the category and is written in front of the message. A record of logging.getLogger("pump.control") therefore appears as:

[pump.control] starting pump P1

Records of the root logger — everything logged through logging.info() and its siblings — carry no meaningful name and are written without a category prefix.

Use logger.exception() inside an exception handler. It logs with level ERROR and appends the traceback to the message.

try:
    manager.dp_set("Pump1.speed", 42)
except OaError:
    logger.exception("could not set the pump speed")

Log records can be written from any thread and from inside a subscription callback.

Customizing the Output

The handler writes the message text only. Time stamp and manager name are added by WinCC OA, for INFO and above also the priority, so a formatter that repeats them produces redundant output.

As long as the root logger is left at DEBUG, third-party libraries also write their debug output to <project>/log/python<num>.log. A level on the logger of the library or on the own top-level logger limits this.

logging.getLogger("some_library").setLevel(logging.WARNING)

Additional handlers can be added to the root logger as usual, for example to write a separate audit file. The WinCC OA handler stays active alongside them.

Warning logging.basicConfig() has no effect after Manager.start(). The root logger already has a handler at that point, so the call returns without changing anything. basicConfig(force=True) does take effect, but it removes the WinCC OA handler, and the script stops writing to the WinCC OA log. Calling it before start() is not a way around this either. The handler it installs on sys.stderr keeps working, so every record is written twice from then on: once through the WinCC OA handler, and once, unformatted, into the manager log. A level argument also keeps start() from raising the root level to DEBUG. The module level functions logging.info(), logging.warning() and their siblings call basicConfig() implicitly when the root logger has no handler yet, so a single such call before start() is enough to cause this. Set levels and handlers directly instead.

Enabling Debug Output

The debug flags of WinCC OA, set with -dbg and queried with isDbgFlag() in CTRL, are not available in Python. What they are used for — switching on additional detail without changing the code — is covered by the logger hierarchy.

A flag number in CTRL corresponds to a logger name in Python. Instead of guarding a message with a flag query, write it unconditionally with logger.debug() and decide when configuring which part of the tree produces output. Names replace numbers, and the module structure replaces the central list of flag assignments.

logging.getLogger("pump.control").setLevel(logging.DEBUG)

This enables the debug output of pump.control and everything below it. The rest of the application keeps its level.

To choose the level without changing the code, read it from the environment. setLevel() accepts the name of a level as a string, but only the upper-case name. Lower case and a numeric string such as "10" are both rejected, so convert the value before passing it on.

import logging
import os

logging.getLogger("pump").setLevel(os.environ.get("PUMP_LOG_LEVEL", "INFO").upper())

An unknown name raises ValueError. Because the configuration usually runs at import time, a typo in the environment ends the script before it does any work.

When more than a few loggers are involved, keep the settings in a file and apply them with logging.config.dictConfig(). This is the usual way to describe levels, formatters and handlers together, outside the code.

import json
import logging.config

with open("logging.json", encoding="utf-8") as f:
    logging.config.dictConfig(json.load(f))

Warning dictConfig() replaces the handlers of every logger it configures, so a configuration that contains a root entry removes the WinCC OA handler. It also disables every logger that already exists and is not named in the configuration, unless the configuration sets "disable_existing_loggers": false. Apply the configuration after Manager.start(), leave out the root entry and set "disable_existing_loggers": false.

A query is needed in one case only: when producing the diagnostic value is expensive in itself. isEnabledFor() is the closest equivalent to isDbgFlag() and is shown in Deferred Formatting.

Print Output

print() writes to sys.stdout. By default WinCC OA redirects stdout and stderr of a manager to <project>/log/python<num>.log, so the output appears in the same file as the DEBUG records — but without time stamp, level and category, and never in PVSS_II.log.

The redirection happens inside start(). Whatever is printed before that goes to the stream the process was started with: the terminal during development, and the log of PMON when PMON started the manager.

After the redirection start() switches both streams to UTF-8 and line buffering, so that non-ASCII characters survive and every line reaches the log as it is written. The stream objects themselves stay the same, so a reference taken earlier keeps working. This keeps print() working, but it does not turn print() into a logging mechanism.

Use logging for everything that has to be readable during operation.

Best Practices

Deferred Formatting

Pass the values as arguments instead of assembling the message with an f-string.

logger.debug("pump %s reached %s bar", name, pressure)   # preferred
logger.debug(f"pump {name} reached {pressure} bar")      # formatted on every call

The % placeholders are resolved when the record is written, not when the call is made. If the effective level of the logger discards the record, no formatting happens at all. An f-string is evaluated before the logging call, so its cost is paid whether the record is used or not.

Whether this saves anything depends on the logger the call is made on. Its effective level is the first level set on the logger itself or on one of its ancestors, which is not necessarily the root logger. As long as that level lets the record through, both forms cost the same. The deferred form only pays off where the record is discarded.

Only the conversion of the arguments is deferred — the arguments themselves are still evaluated. When the value has to be computed first, query the level before the call.

if logger.isEnabledFor(logging.DEBUG):
    logger.debug("current state: %s", expensive_snapshot())

Logger Names

Use logging.getLogger(__name__) at module level. The logger names then follow the package structure, which makes the origin of a record obvious and allows a whole subtree to be switched on with a single setLevel().

Do not build logger names from runtime data such as datapoint names. Loggers are never released, so a new name for every datapoint lets the internal registry grow without bound. Such values belong in the message.

logger = logging.getLogger(__name__)         # one logger per module
logger.info("value of %s changed", dp_name)  # the datapoint is part of the message

Choosing a Level

The level decides who reads the record. INFO and above reaches whoever operates the project, so it should describe what the script does, not how it does it. DEBUG carries the development detail.

Records written from a subscription callback deserve extra attention. A callback can fire many times per second, and every record of INFO or above passes through the log file that all other managers write to as well. Log such events with DEBUG and reserve INFO for state changes that occur rarely.

Warning Both log files are readable for everyone with access to the project directory or the LogViewer. Do not log passwords, tokens or personal data.

Running pytest in a Manager

A test that talks to the runtime system has to run inside a manager, which means pytest and the manager share one process — and with it sys.stdout and sys.stderr. Three settings decide whether the report of such a run is readable afterwards.

import pathlib
import tempfile

import pytest

from etm.wccoa.manager import Manager

test_file = pathlib.Path(__file__).parent / "test_pumps.py"
cache_dir = pathlib.Path(tempfile.gettempdir()) / ".pytest_cache_pumps"

with Manager():
    exit_code = pytest.main([str(test_file), "--capture=sys", "-o", f"cache_dir={cache_dir}"])

Create the manager before pytest.main(). The redirection to <project>/log/python<num>.log happens inside start(), so everything pytest writes before that — the session header, the collection phase — goes to the stream the process was started with, and under PMON that is the log of PMON. Manager is a singleton, so a fixture that needs it does not have to create it.

@pytest.fixture(scope="session")
def manager() -> Manager:
    return Manager()

Pass --capture=sys. The default --capture=fd claims the file descriptors 1 and 2 for itself and restores at the end the copies it took when it started, which point at the destination from before the manager existed. The report is then written past the manager log rather than into it. --capture=sys captures on the Python level and leaves the descriptors alone.

Give the cache a directory of its own with -o cache_dir=. PMON hands the manager a working directory the process usually cannot write to, on Windows C:\WINDOWS\system32. Without an ini file above the tests, pytest treats it as the rootdir and puts .pytest_cache there. Creating it fails, and the retry loop below it takes minutes, during which the run appears to hang and no summary appears. Any writable directory does; next to the jUnit XML is a natural choice when the run produces one.

Log records are unaffected by all of this: they go through the handler, not through the streams. A failing test, however, reports the output it captured from the test in its report, so the print() and logging output of the failing case is only readable when the report itself reaches the log.