Log level not suppressed

[nicholas-a-guerra]

It appears that on the latest versions the log levels aren't being applied to all logs in the source code. In my code I have these lines:

from pymodbus import pymodbus_apply_logging_config
pymodbus_apply_logging_config(level=logging.CRITICAL)

And yet I am still getting these every once in a while in my log output:

04-15-2025 14:29:03.177 EDT [ERROR] Fatal error: protocol.data_received() call failed.
protocol: <pymodbus.transaction.transaction.TransactionManager object at 0x7f67ffb920>
transport: <_SelectorSocketTransport fd=13 read=polling write=<idle, bufsize=0>>
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/asyncio/selector_events.py", line 1027, in _read_ready__data_received
    self._protocol.data_received(data)
  File "/usr/local/src/project/venv/lib/python3.12/site-packages/pymodbus/transport/transport.py", line 304, in data_received
    self.datagram_received(data, None)
  File "/usr/local/src/project/venv/lib/python3.12/site-packages/pymodbus/transport/transport.py", line 338, in datagram_received
    cut = self.callback_data(self.recv_buffer, addr=addr)
          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/src/project/venv/lib/python3.12/site-packages/pymodbus/transaction/transaction.py", line 192, in callback_data
    self.response_future.set_result(pdu)
asyncio.exceptions.InvalidStateError: invalid state

Since ERROR is lower than CRITICAL, I would expect these to be suppressed. I'm unsure how to suppress them.

[nicholas-a-guerra]

But maybe this update fixes that?

#2582

I was on 3.8.6 but can update now. Not sure if that still means it should normally be suppressed with the set log level or not.

[nicholas-a-guerra]

Although after updating to 3.9.1 I am now still seeing an ERROR log. Not sure why it would not be suppressed with the log level.

04-16-2025 14:36:25.105 EDT [ERROR] Fatal error: protocol.data_received() call failed.
protocol: <pymodbus.transaction.transaction.TransactionManager object at 0x7f99db4d40>
transport: <_SelectorSocketTransport fd=13 read=polling write=<idle, bufsize=0>>
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/asyncio/selector_events.py", line 1027, in _read_ready__data_received
    self._protocol.data_received(data)
  File "/usr/local/src/project/venv/lib/python3.12/site-packages/pymodbus/transport/transport.py", line 304, in data_received
    self.datagram_received(data, None)
  File "/usr/local/src/project/venv/lib/python3.12/site-packages/pymodbus/transport/transport.py", line 338, in datagram_received
    cut = self.callback_data(self.recv_buffer, addr=addr)
          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/src/project/venv/lib/python3.12/site-packages/pymodbus/transaction/transaction.py", line 225, in callback_data
    raise ModbusIOException("received pdu without a corresponding request")
pymodbus.exceptions.ModbusIOException: Modbus Error: [Input/Output] received pdu without a corresponding request

[janiversen]

???? this is not log lines, but a traceback, because the future is used.

Which version do you use, it does no look like "the latest" run "pip show pymodbus"

maybe even more interestingly what happened to get this breakdown ?

[janiversen]

ok just saw your other messages, so this still happens with 3.9.1 but it still have nothing to do with the pymodbus log level it is a python breakdown.

So again how did you get this error, it is probably a bug in pymodbus, but to identify it I need more information about what happened.

Do you have the possibility to try with dev, because we fixed a similar bug, which have not yet been released.

[nicholas-a-guerra]

Hi @janiversen thanks for assisting. This occurs when the device I'm communicating with becomes non responsive very abruptly. So I expect that there would be some type of comm failure and I'm okay with that. I just want to control them myself.

But this output is specifically related to log level. The output is to my log file and it is just formatted per my specification so this 04-16-2025 14:36:25.105 EDT [ERROR] Fatal error: protocol.data_received() call failed corresponds to my formatter:

logging.Formatter(f"%(asctime)s.%(msecs)03d {localtime().tm_zone} [%(levelname)s] %(message)s", datefmt='%m-%d-%Y %H:%M:%S')

And the rest of the traceback shows us that the triggering exception is pymodbus.exceptions.ModbusIOException.

And unfortunately we don't have the capacity to test with dev right now since we're using this for finishing up some production work. Also, it doesn't seem to have any detrimental consequences at the moment. Although it does add some unintended bloat to the logs that seems uncontrollable at the moment.

[janiversen]

Thanks for your explanation, this sounds very much like the bug we solved.

The log line do not originate from pymodbus, but from python itself, so it's not passing the pymodbus log handler. I can say that safely, because the text "call failed" do not exist in the code neither do "protocol.data_received" because we use "intern_protocol".

[janiversen]

Closed as this is not a pymodbus log message, but comes from asyncio.

[nicholas-a-guerra]

@janiversen I'm not sure I understand. The are a couple different log outputs here. One that I showed previously is like below:

04-17-2025 13:56:15.741 EDT [ERROR] Fatal error: protocol.data_received() call failed.
protocol: <pymodbus.transaction.transaction.TransactionManager object at 0x7f96ef8d40>
transport: <_SelectorSocketTransport fd=14 read=polling write=<idle, bufsize=0>>
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/asyncio/selector_events.py", line 1027, in _read_ready__data_received
    self._protocol.data_received(data)
  File "/usr/local/src/project/venv/lib/python3.12/site-packages/pymodbus/transport/transport.py", line 304, in data_received
    self.datagram_received(data, None)
  File "/usr/local/src/project/venv/lib/python3.12/site-packages/pymodbus/transport/transport.py", line 338, in datagram_received
    cut = self.callback_data(self.recv_buffer, addr=addr)
          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/src/project/venv/lib/python3.12/site-packages/pymodbus/transaction/transaction.py", line 225, in callback_data
    raise ModbusIOException("received pdu without a corresponding request")
pymodbus.exceptions.ModbusIOException: Modbus Error: [Input/Output] received pdu without a corresponding request

This specifically says it is a pymodbus.exceptions.ModbusIOException: Modbus Error. Is this not a pymodbus error? And if it is, then it is not being handled by the log level as mentioned previously still. Because this code that is running right now on the latest pymodbus produced this just now and log level is set to critical like below:

from pymodbus import pymodbus_apply_logging_config
pymodbus_apply_logging_config(level=logging.CRITICAL)

Maybe there are some details I don't understand though? Wouldn't a pymodbus.exceptions.ModbusIOException be a pymodbus error?

[janiversen]

Yes it is pymodbus trying to tell the application, that the app needs to decide what to do, it does not have anything to do with logging:

´´´
raise ModbusIOException("received pdu without a corresponding request")
´´´

Raises an exception which the app is expected to catch (see our examples), but the app do not catch it, and therefore it is passed on to the python interpreter, which make a stack trace, to inform about the not handled exception.

Log lines are produced with e.g. _LOGGER.debug("this is a log message")

The library throws an exception when something abnormal happens in the library in order for the app to decide how to handle it, that is a very normal practice.

[nicholas-a-guerra]

I think there may be a misunderstanding a bit. My apologies I didn't provide probably all the details you need to understand. pymodbus.exceptions.ModbusIOException is a pymodbus exception. Right now it is being logged in your code as something like logger.error('log message'). I know this because every call to pymodbus in my code right now for testing is wrapped like this:

except Exception as e:
    logger.debug('message')

However, I do not see a debug message in my logs. I only see an error message. So this is not produced in my code. And it can not be caught because I am already attempting to capture every possible exception. Therefore, the error log must be internal to the pymodbus package.

So you see, I have no way to capture this log as it would have already been caught with except Exception as e: if it was possible. It is instead an internal log that normally we would expect this code to dictate the level of:

from pymodbus import pymodbus_apply_logging_config
pymodbus_apply_logging_config(level=logging.CRITICAL)

Does that make sense?

[janiversen]

No it does not make sense, as you can see from your initial message, the exception is:

´´´
asyncio.exceptions.InvalidStateError: invalid state

meaning it is raised by asyncio and not from pymodbus.

with 
´´´
except Exception as e:
´´´
the app should get it, at least in my apps (and the test suite) except is called for all exceptions.

Again this is NOT a log line from pymodbus and thus NOT following the logging.CRITICAL restriction.

I think you mix exceptions with log, those are 2 very different things !! 

[nicholas-a-guerra]

All of these are logs. As they are in my log file formatted as all the logs are. So we both agree about this. Logs can be anything. Messages or if you capture an exception then log it, then it can be an a log of an exception. So yes I understand the difference. In the first example the traceback is from pymodbus/transport/transport.py. And it is logged as an ERROR. So these are two different thing you are correct. There was an exception and separately it was captured and logged as an ERROR. Some code had to call the logger.error or something similar.

But in my code which is very short, there is not a single logger.error. Not anywhere in any of the code anywhere at all. So it is not possible for my code to produce an ERROR log line. It is only a few hundred lines. It is not possible to produce an ERROR line. And I have captured all pymodbus exceptions and made them logger.debug. And this works perfectly. I have been using pymodbus for many years now. The exception capture works perfect, and when one happens it logs to the file as debug, when I have my log level set this way.

Specifically what we see is ERROR level logs that my code cannot produce or capture. One possibility is that inside the pymodbus package a logger.error is happening and the normal suppression is not working. Surely, pymodbus does some logging separate from exception throwing, correct?

[nicholas-a-guerra]

So maybe this is log.error from asyncio? But the exception is raised in pymodbus? But it seems this has been maybe identified in the latest version and now instead of an exception is going to just do log warning which then will suppress it?

If that's the case when do you think the latest version with this update will be available via pip?

[janiversen]

pymodbus typically do not log exception throwing, the information is in the exception itself.

I have never written that your code produces these log lines, the exception is raised by the asyncio library and the log lines are produced by the python interpreter because the exception is not caught earlier (why, I of course cannot tell you).

Again, the real problem is that asyncio detected an illegal use of a future and thus reports it, totally without pymodbus making log entries.

Both v3.9.0 and v3.9.1 already handles the illegal use, and are available with pip.