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.

[nicholas-a-guerra]

I think I haven't explained it well enough. But that's okay, more specifically, in the image there is a commit right now that changes this from raising an exception to instead logging it as a warning. I know this will fix the problem I have. When will this new commit be available via pip? 3.9.1 does not include this commit.

6d81ee3

[janiversen]

v3.9.1 catches the situation and avoids the illegal use of the future. ModbusIOexception is raised to notify the app that a non solicited message was received, the app is expected to handle that.

Dev is for v4.0 and currently v3.9.2 is not planned. v3.9.2 will be made if a serious bug is found (or multiple smaller ones).

[nicholas-a-guerra]

Right and that makes sense and I understand your point. Unfortunately as you pointed out and I now understand, this exception is getting passed along to asyncio because it is not handled. But I have a generic except Exception and that does not catch this. Which means we have no way to directly handle this exception. I make three calls to pymodbus (connect, read, and write) all wrapped in the exception catch. All debugging any exceptions. And none of them catch this. My limited guess is that this exception is likely in a async task or something in which case asyncio will eventually handle it.

So that now the only option I can think of is to suppress asyncio logs to critical. But this seems very unwise as I'd only like to suppress/handle modbus related logs. So you see I am stuck without any way to properly handle this.

However, with the commit that was mentioned, as a warning log level in pymodbus we can use the normal log level control to dictate how this is handled.

Maybe you'd consider some options for us on this? For a long time pymodbus user haha

[janiversen]

I just ran a test with v3.9.1 with ReadHoldingRegisters() and a try/except around the call, and the ModbusIOException is correctly passed to the except, so it seems you have a different problem, did you e.g. not use "await" but evaluate the future in another place.

And I wrote that your original exception only happens with v3.8.6 ORIGINATES from asyncio and is logged in the python interpreter. v3.9.0/1 avoids the illegal use but raises ModIOEXception, which the app need to catch.

If you cannot catch a ModbusIOException then you have a potential dangerous situation, because that happens from time to time (eg. when retrying fails), so that is a thing you should look into. Replacing "raise" with a "log.warning" just hides your problem that the app do not catch ModbusIOException.

So your real "option" is to find you why your app do not catch the ModbusIOException (forget v3.8.6).

[nicholas-a-guerra]

That makes sense for the original exception. I did have 3.8.6 and I did update recently to 3.9.1. But 3.9.1 is where I still see the second received pdu without a corresponding request unhandled exception. To answer your question, I do use await directly on all the pymodbus calls. None of them are evaluated as futures later. Only 3 await calls to pymodbus functions. Also, generally speaking exception are captured in the except catch. I have only ever seen these ones not captured.

When you say you ran a test, you were able to get received pdu without a corresponding request to be caught via pymodbus.transaction.transaction.TransactionManager in your test? Or are you saying just generally you caught a ModbusIOException? Because I can successfully catch ModbusIOException. Only this one seems to be a problem. All others it appears work exactly as expected.

[nicholas-a-guerra]

Actually callback_data from here:

pymodbus/pymodbus/transaction/transaction.py

Line 214 in e342eb5

def callback_data(self, data: bytes, addr: tuple | None = None) -> int:

is called in datagram_received from the ModbusProtocol which is a child of asyncio.BaseProtocol

I would assume it's very possible these functions are used in the BaseProtocol as a callback from a task of some sort. In which case we wouldn't be able to capture these ModbusIOException. Couldn't that be possible?

[janiversen]

the pymodbus client do not start a task but asyncio might.

but anyhow I think you see why this is not a problem with log level as the issue states.

It would be lot more interesting to avoid it from happening in the first place, but with the information you have given we have no way to even start searching for a potential bug, for that we need debug log.

[nicholas-a-guerra]

Right I agree that my original request and description of the problem was incorrect. I apologize for my confusion.

I think you're intuition about asyncio starting a task is correct. I'm not sure I see any other possibility. As my code is so simple and an exception catch is not handling this exception.

Also I agree making it not happen in the first place would be super ideal but also is not possible for this specific application. This error is happening when a modbus device disconnects and reconnects. This is unavoidable as it is a solar inverter which loses comms when it loses power from the solar panels. This means every night it will lose comms but exactly when is not predictable with perfect precision. And therefore we must keep comms open until it fails and keep retrying to regain comms until it becomes available again. This is just the nature of this type of modbus device.

With that said I have no way to avoid this error. I only want to handle it better. I know I haven't provided a good solution and I agree with the caveats that you have highlighted. But the problem it causes still remains and I guess I'm just requesting if you had any ideas for a reasonable solution I would be forever grateful. Right now it is making the logs bloated and much less useable. I now totally agree this is not your fault and nothing is "wrong" with the code. But still this exception is uncatchable and that makes it very difficult to properly log in this situation.

[janiversen]

I can only repeat, this is a problem that should not happen and if it's happens it should be documented so that pymodbus can be changed to avoid the error.

[nicholas-a-guerra]

Okay so then should I open another issue so I can gather any necessary information to identify the problem you are suggesting should not happen? Or should I rename this one and we reopen it?

[nicholas-a-guerra]

Not sure if it's helpful, but I don't believe I have seen this exception creep through in 3.8.x releases before. Is there anything I can do to collect useful information to help?

[janiversen]

This particular exception have existed since v3.1, but it has not been a problem, because apps either did not care about it or catched it as robust apps do.

I do not want to interfere with the design of you app, but since you multiple times have said you cannot catch it, I have to ask:

did you register an asyncio exception handler otherwise it is understandable why you cannot catch it.

I have multiple times written what we need to see if your problem is different from what we already solved.

[nicholas-a-guerra]

The app is very simple by design not trying to do anything too complicated. So to answer your question no we have not implemented an asyncio exception handler. So I spoke too loosely before and I apologize. When I said we can't catch the exception, you are 100% right that there is undoubtedly "a way" to capture it in some fancy way no within pymodbus.

I guess what I really meant was, you can't capture it via just a try block on pymodbus calls. Because this was attempted and it falls outside these calls. My hunch was that it seems like ideally we wouldn't need to create an asyncio exception handler to capture a pymodbus exception. But I for sure could be wrong about that. I truthfully do not actually know. Maybe this is standard practice that exceptions can fall back and that special handlers need to be custom developed to appropriately handled them. I only thought since it was a pymodbus exception, it could make sense to be able to handle it via some pymodbus component or methodology.

But also you mentioned: "this is a problem that should not happen and if it's happens it should be documented so that pymodbus can be changed to avoid the error". My understanding was that this meant you wouldn't expect pymodbus to produce this exception generally and maybe there was something that could be changed to avoid it. If that's correct, I only want to provide my assistance in finding what the "problem" is. Is there anyway that I can help to understand what you mentioned is a problem?

So what this narrows down to, is it reasonable for this exception to occur? If yes that is 100% valid and I have no problem with that. If that's the case then I'm attempting to come up with a good solution for being able to handle it. My gut says that if it is a pymodbus exception it would be ideal to be able to handle it in some way through pymodbus. If that's also not the case that's okay and I will just make my best attempt. I just took a guess at a way to handle the logging aspect specifically and came up with this:

class Custom_Logging_Filter(logging.Filter):
    def filter(self, record):
        if (record.levelno == logging.ERROR and
            "ModbusIOException: Modbus Error: [Input/Output] received pdu without a corresponding request" in record.getMessage()):

            record.levelno = logging.DEBUG
            record.levelname = "DEBUG"

        return True

I think this may work but seems like perhaps it is not as ideal as possible. And just wanted to enquire about if there was a more ideal solution that could be integrated into pymodbus. Although, maybe my intuition is just wrong. I honestly do not have any assumptions about what is "correct", only guesses based on my understanding which you have already helped me correct many times. I very much appreciate the long discussion about this already by the way. Very helpful to get some guidance and correct some incorrect assumptions that I had.

[janiversen]

pymodbus are not responsible (even though the library might be the cause) for asyncio exceptions, that is purely between the app and asyncio. Exception handlers cannot be daisy chained so if pymodbus added one it would overwrite the app supplied one.

Custom filters helps nothing, asyncio and pymodbus use different handlers, just like the app.

This is going nowhere, pymodbus will not/cannot suppress an asyncio exception! please adjust your app as needed.

[nicholas-a-guerra]

Yeah my guess combined that with this.

logging.getLogger("asyncio").addFilter(Custom_Logging_Filter())

That is already in my code and what I'm testing, so I'm already aware that they use different handlers of course. And this idea was only to add to my code. This was not a suggestion for you. This was just to show my guess at how to do it in my app. And how it's not super ideal.

Either way, apologies for the inquiry. Have a nice day and thanks for the amazing package regardless.