Skip to content

Fix log level in examples#2902

Merged
janiversen merged 2 commits into
pymodbus-dev:devfrom
KevinWMatthews:km/fix-logging-in-examples
Mar 12, 2026
Merged

Fix log level in examples#2902
janiversen merged 2 commits into
pymodbus-dev:devfrom
KevinWMatthews:km/fix-logging-in-examples

Conversation

@KevinWMatthews
Copy link
Copy Markdown
Contributor

This sets logging.basicConfig() in several example applications so that it respects the user's selection at the CLI (see #2901).

Background

In order for Python to respect the log level that is set, logging.basicConfig() must be called.
If this is not done, then the first calls to logging functions will:

The lastResort handler defaults to a log level of WARNING, which I believe is why most log statements do not appear.

Examples

Info level

Setup:

% cd pymodbus/examples
% python3 -m venv .venv
% source .venv/bin/activate

For the server:

(.venv) % python3 server_async.py
INFO:/Users/kevin/src/pymodbus-dev/examples/server_async.py:### Create datastore
INFO:/Users/kevin/src/pymodbus-dev/examples/server_async.py:### start ASYNC server, listening on 5020 - tcp
INFO:asyncio:<Server sockets=(<asyncio.TransportSocket fd=7, family=30, type=1, proto=6, laddr=('::', 5020, 0, 0)>, <asyncio.TransportSocket fd=8, family=2, type=1, proto=6, laddr=('0.0.0.0', 5020)>)> is serving
2026-03-11 22:37:32,876 INFO  base:89 Server listening.
INFO:pymodbus.logging:Server listening.

For the client:

(.venv) % python3 client_async.py
INFO:__main__:### Create client object
INFO:__main__:### Client starting
INFO:__main__:### End of Program

Note that:

  • __file__ has an impact
  • INFO-level logs from server_async.py now appear
  • INFO-level logs from client_async.py now appear

Debug level

Setup:

% cd pymodbus/examples
% python3 -m venv .venv
% source .venv/bin/activate

For the server

% python3 server_async.py --log debug
INFO:/Users/kevin/src/pymodbus-dev/examples/server_async.py:### Create datastore
INFO:/Users/kevin/src/pymodbus-dev/examples/server_async.py:### start ASYNC server, listening on 5020 - tcp
2026-03-11 22:40:24,986 DEBUG transport:265 Awaiting connections server_listener
DEBUG:pymodbus.logging:Awaiting connections server_listener
DEBUG:asyncio:Get address info None:5020, type=<SocketKind.SOCK_STREAM: 1>, flags=<AddressInfo.AI_PASSIVE: 1>
DEBUG:asyncio:Getting address info None:5020, type=<SocketKind.SOCK_STREAM: 1>, flags=<AddressInfo.AI_PASSIVE: 1> took 0.894ms: [(<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, 6, '', ('::', 5020, 0, 0)), (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, 6, '', ('0.0.0.0', 5020))]
INFO:asyncio:<Server sockets=(<asyncio.TransportSocket fd=7, family=2, type=1, proto=6, laddr=('0.0.0.0', 5020)>, <asyncio.TransportSocket fd=8, family=30, type=1, proto=6, laddr=('::', 5020, 0, 0)>)> is serving
2026-03-11 22:40:24,988 INFO  base:89 Server listening.
INFO:pymodbus.logging:Server listening.
DEBUG:asyncio:<Server sockets=(<asyncio.TransportSocket fd=7, family=2, type=1, proto=6, laddr=('0.0.0.0', 5020)>, <asyncio.TransportSocket fd=8, family=30, type=1, proto=6, laddr=('::', 5020, 0, 0)>)> got a new connection from ('127.0.0.1', 54996): <socket.socket fd=9, family=2, type=1, proto=0, laddr=('127.0.0.1', 5020), raddr=('127.0.0.1', 54996)>
2026-03-11 22:40:32,008 DEBUG transport:287 Connected to server
DEBUG:pymodbus.logging:Connected to server
2026-03-11 22:40:32,110 DEBUG transport:339 recv: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x1 0x0 0x20 0x0 0x1 extra data:
DEBUG:pymodbus.logging:recv: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x1 0x0 0x20 0x0 0x1 extra data:
2026-03-11 22:40:32,110 DEBUG base:72 Processing: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x1 0x0 0x20 0x0 0x1
DEBUG:pymodbus.logging:Processing: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x1 0x0 0x20 0x0 0x1
2026-03-11 22:40:32,110 DEBUG decoders:77 decoded PDU function_code(1 sub -1) -> ReadCoilsRequest(dev_id=0, transaction_id=0, address=32, count=1, bits=[], registers=[], status=1, retries=0)
DEBUG:pymodbus.logging:decoded PDU function_code(1 sub -1) -> ReadCoilsRequest(dev_id=0, transaction_id=0, address=32, count=1, bits=[], registers=[], status=1, retries=0)
2026-03-11 22:40:32,110 DEBUG transport:393 send: 0x0 0x1 0x0 0x0 0x0 0x4 0x1 0x1 0x1 0x1
DEBUG:pymodbus.logging:send: 0x0 0x1 0x0 0x0 0x0 0x4 0x1 0x1 0x1 0x1
2026-03-11 22:40:32,110 DEBUG transport:339 recv: 0x0 0x2 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x4 0x0 0x2 extra data:
DEBUG:pymodbus.logging:recv: 0x0 0x2 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x4 0x0 0x2 extra data:
2026-03-11 22:40:32,110 DEBUG base:72 Processing: 0x0 0x2 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x4 0x0 0x2
DEBUG:pymodbus.logging:Processing: 0x0 0x2 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x4 0x0 0x2
2026-03-11 22:40:32,110 DEBUG decoders:77 decoded PDU function_code(3 sub -1) -> ReadHoldingRegistersRequest(dev_id=0, transaction_id=0, address=4, count=2, bits=[], registers=[], status=1, retries=0)
DEBUG:pymodbus.logging:decoded PDU function_code(3 sub -1) -> ReadHoldingRegistersRequest(dev_id=0, transaction_id=0, address=4, count=2, bits=[], registers=[], status=1, retries=0)
2026-03-11 22:40:32,111 DEBUG transport:393 send: 0x0 0x2 0x0 0x0 0x0 0x7 0x1 0x3 0x4 0x0 0x11 0x0 0x11
DEBUG:pymodbus.logging:send: 0x0 0x2 0x0 0x0 0x0 0x7 0x1 0x3 0x4 0x0 0x11 0x0 0x11
DEBUG:asyncio:<_SelectorSocketTransport fd=9 read=polling write=<idle, bufsize=0>> received EOF
2026-03-11 22:40:32,111 DEBUG transport:356 -> transport: received eof
DEBUG:pymodbus.logging:-> transport: received eof
2026-03-11 22:40:32,111 DEBUG transport:299 Connection lost server due to None
DEBUG:pymodbus.logging:Connection lost server due to None
2026-03-11 22:40:32,111 DEBUG requesthandler:49 Handler for stream [server] has been canceled
DEBUG:pymodbus.logging:Handler for stream [server] has been canceled

For the client:

% python3 client_async.py --log debug
INFO:__main__:### Create client object
INFO:__main__:### Client starting
2026-03-11 22:40:32,007 DEBUG base:56 Connecting to 127.0.0.1:5020.
DEBUG:pymodbus.logging:Connecting to 127.0.0.1:5020.
2026-03-11 22:40:32,007 DEBUG transport:251 Connecting comm
DEBUG:pymodbus.logging:Connecting comm
2026-03-11 22:40:32,008 DEBUG transport:287 Connected to comm
DEBUG:pymodbus.logging:Connected to comm
DEBUG:asyncio:<asyncio.TransportSocket fd=6, family=2, type=1, proto=6, laddr=('127.0.0.1', 54996), raddr=('127.0.0.1', 5020)> connected to 127.0.0.1:5020: (<_SelectorSocketTransport fd=6 read=polling write=<idle, bufsize=0>>, <pymodbus.transaction.transaction.TransactionManager object at 0x10a270050>)
2026-03-11 22:40:32,109 DEBUG transport:393 send: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x1 0x0 0x20 0x0 0x1
DEBUG:pymodbus.logging:send: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x1 0x0 0x20 0x0 0x1
2026-03-11 22:40:32,110 DEBUG transport:339 recv: 0x0 0x1 0x0 0x0 0x0 0x4 0x1 0x1 0x1 0x1 extra data:
DEBUG:pymodbus.logging:recv: 0x0 0x1 0x0 0x0 0x0 0x4 0x1 0x1 0x1 0x1 extra data:
2026-03-11 22:40:32,110 DEBUG base:72 Processing: 0x0 0x1 0x0 0x0 0x0 0x4 0x1 0x1 0x1 0x1
DEBUG:pymodbus.logging:Processing: 0x0 0x1 0x0 0x0 0x0 0x4 0x1 0x1 0x1 0x1
2026-03-11 22:40:32,110 DEBUG decoders:77 decoded PDU function_code(1 sub -1) -> ReadCoilsResponse(dev_id=0, transaction_id=0, address=0, count=0, bits=[True, False, False, False, False, False, False, False], registers=[], status=1, retries=0)
DEBUG:pymodbus.logging:decoded PDU function_code(1 sub -1) -> ReadCoilsResponse(dev_id=0, transaction_id=0, address=0, count=0, bits=[True, False, False, False, False, False, False, False], registers=[], status=1, retries=0)
2026-03-11 22:40:32,110 DEBUG transport:393 send: 0x0 0x2 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x4 0x0 0x2
DEBUG:pymodbus.logging:send: 0x0 0x2 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x4 0x0 0x2
2026-03-11 22:40:32,111 DEBUG transport:339 recv: 0x0 0x2 0x0 0x0 0x0 0x7 0x1 0x3 0x4 0x0 0x11 0x0 0x11 extra data:
DEBUG:pymodbus.logging:recv: 0x0 0x2 0x0 0x0 0x0 0x7 0x1 0x3 0x4 0x0 0x11 0x0 0x11 extra data:
2026-03-11 22:40:32,111 DEBUG base:72 Processing: 0x0 0x2 0x0 0x0 0x0 0x7 0x1 0x3 0x4 0x0 0x11 0x0 0x11
DEBUG:pymodbus.logging:Processing: 0x0 0x2 0x0 0x0 0x0 0x7 0x1 0x3 0x4 0x0 0x11 0x0 0x11
2026-03-11 22:40:32,111 DEBUG decoders:77 decoded PDU function_code(3 sub -1) -> ReadHoldingRegistersResponse(dev_id=0, transaction_id=0, address=0, count=0, bits=[], registers=[17, 17], status=1, retries=0)
DEBUG:pymodbus.logging:decoded PDU function_code(3 sub -1) -> ReadHoldingRegistersResponse(dev_id=0, transaction_id=0, address=0, count=0, bits=[], registers=[17, 17], status=1, retries=0)
INFO:__main__:### End of Program
DEBUG:asyncio:Close <_UnixSelectorEventLoop running=False closed=False debug=True>

Open Questions

Should examples call logging.getLogger(__name__) instead of logging.getLogger(__file__)?
This is recommended by the docs and gives log messages that are more brief.

Copy link
Copy Markdown
Collaborator

@janiversen janiversen left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

please see comment on the corresponding issue.

Copy link
Copy Markdown
Collaborator

@janiversen janiversen left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM, thanks.

@janiversen janiversen merged commit c17f780 into pymodbus-dev:dev Mar 12, 2026
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants