Throws `KNXTimeoutException` due to missing confirmation although the confirmation was received

[dallmair]

We're not entirely sure yet and still digging through the code (both calimero and ours), but it seems there is a synchronization issue in calimero-core 2.5.1. It happens only occasionally and definitely depends on timing.

Please see attached log file for a DEBUG log in HTML format that includes all messages that led up to the problem in an instance last week. We use ManagementClientImpl over a Tunneling connection via a certified IP interface to a DIY device. After a few successful message exchanges, the log contains:

1. 00:17:20.449 calimero sends T_ACK message to the device ✔️
2. 00:17:20.453 calimero sends T_DATA_CONNECTED message to the device ✔️
3. 00:17:20.470 + 00:17:20.471 calimero receives confirmation of the T_ACK message ✔️
4. 00:17:20.514 calimero receives confirmation of the T_DATA_CONNECTED message ✔️
5. 00:17:20.526 calimero receives T_ACK in response of message sent in step 2 ✔️
6. 00:17:20.549 calimero receives T_DATA_CONNECTED (some response message from device) ✔️
7. 00:17:23.549 device repeats the message from step 6 as it did not get an answer within 3 seconds ⚠️ Should not have happened, but just a consequence of the underlying issue, see next
8. 00:17:24.467 calimero throws a KNXTimeoutException saying "no confirmation reply received for" the message sent in step 2 ❌ This is strange as it logged reception of the confirmation right there in step 4.

To sum it up, calimero writes a log entry about having successfully received the confirmation, but then throws an exception because it thinks it did not receive the confirmation.

Or are we reading the log file incorrectly, missing something else, or just don't get it...? It would be great if you could take a look and help us pinpoint the root cause. Many thanks in advance!

updater-2023-04-21_00-17-15.501-short.zip

[dallmair]

The only thing that looks a bit suspicious to me is the implementation of ClientConnection::doExtraBlockingModes: waitForStateChange already returns whether the state change happened or not, but doExtraBlockingModes ignores that result and compares the internalState field again. That seems odd to me, but I have no idea whether this is actually in the relevant code path for the issue reported here.

[bmalinowsky]

Thank you for the log file. I'll try to find out what's wrong.

• There are several duplicate confirmations in the log, e.g., 00:17:18.807 and 00:17:18.840.
• The logic in KNXnet/IP tunneling for determining a successful .con is currently after the notification to the link layer. Hence, a .con is always reported (logged). This has its benefits (there is a TODO to move that, because I know that can be confusing), but is not helpful in your case: a L2 log entry does not mean that tunneling moved on from CEMI_CON_PENDING. I think that's the culprit.
  In essence, the relevant part whether a .con is accepted or not starts here:

  calimero-core/src/io/calimero/knxnetip/KNXnetIPTunnel.java

  Line 408 in 104731d

  if (ldata != null && internalState == CEMI_CON_PENDING) {

• For instance, at

  calimero-core/src/io/calimero/knxnetip/KNXnetIPTunnel.java

  Line 421 in 104731d

  final int sendCount = ldata.getHopCount() - 1;

  
  there is a workaround for eibd, but there is currently no other log output for other conditions (i.e., if the array comparison of recv and sent fails completely).

I don't know how easy it is for you to run with changed source code, but setting the log output to TRACE, and adding some log output, e.g., array mismatch, would help. I think the .con is currently not accepted.

[Darthyson]

a L2 log entry does not mean that tunneling moved on from CEMI_CON_PENDING. I think that's the culprit.

I think you were absolutely right. Unfortunately for this one we only had a debug-level log.
Imho the actual cause was a KNXAckTimeoutException due to a missing tunneling ACK.

no confirmation reply received for...

confirms this.
The "old" debug log just showed that the corresponding L4 T_ACK from the Destination came through.

I could reproduce this recently only once, after many many hours of continuous L4 testing the last weeks. Unfortunately I have added more detailed calimero-core logging, so line numbers won`t match to calimero-core/release/2.6. There is also a -1 hour offset in the wireshark log. Hopefully they are still useful in some way:

20250115_issue_120_log.zip

[bmalinowsky]

@Darthyson I looked at your code modifications wrt logging. You added quite a few, and then removed some again.
Out of curiosity: did you find a particular log event missing in calimero (or the opposite: a log event that doesn't provide relevant info)?

[Darthyson]

I got some logs from a user with many send disconnect to 1.1.255, where 1.1.255 is the PA of the IP interface (Loxone Miniserver Gen 1). So I extended the logs to find the cause and later removed the redundant ones.
The cause was in the end that the Loxone Miniserver Gen 1 also uses its own PA for the tunnel PA. That PA is transmitted in the Connection Response Data Block (CRD), but is not evaluated by calimero-core for UDP tunneling v1.
Since I only have KNX Spec 2.1, is this worth a new issue? Right now we just set the tunnel-PA with TPSettings(new IndividualAddress("a.l.d")).

So Imho missing log events are the unexcpected causes of L4 disconnects in

• TransportLayerImpl::checkSendDisconnect and
• TransportLayerImpl::sendDisconnect

or the opposite: a log event that doesn't provide relevant info

This is more a question of the log level.
Stack traces on log level info are not that user friendly e.g. for a KNXAckTimeoutException.
Thats why i added to our Updater this logging filter:

• EXCEPTION_FILTER_MAP

And for the info log level eibd message:

• FILTERED_MESSAGES

I know i could set the calimero-core log level "globally" to warn or error, but that would filter out some useful info messages, e.g. connection established (... tunneling address 1.0.251)

[bmalinowsky]

Thanks for the pointers!

Wrt. the tunneling address: there is no reason to evaluate the CRD tunneling address for v1. What you link to is specifically for tunneling v2, tunneling features don't exist for v1. In v1, setting the individual address within the client connection is not necessary (and there do exist old servers which don't like that anyway). Do you need the address for anything?

You can override the tunneling address as you do in TPSettings; but also here, is the assigned address of importance?

[Darthyson]

I expressed it poorly. I meant maybe an additional if for tunneling v1, like:

if (c instanceof final KNXnetIPTunnel tunnel && mode == TUNNELING) {
	KNXMediumSettings knxMedium = getKNXMedium();
	if (knxMedium.getDeviceAddress().getRawAddress() == BackboneRouter.getRawAddress()) {
		IndividualAddress tunnelAddress = tunnel.getTunnelingAddress();
		logger.info("Use tunnel address {} received in connection response data block (CRD)", tunnelAddress);
		knxMedium.setDeviceAddress(tunnelAddress);
	}
}
else if (c instanceof final KNXnetIPTunnel tunnel && mode == TunnelingV2) {

Out of pure interest. Do you have an example of a server that doesn't like this?

So far it works with 0.0.0 without any problems. Only with the Loxone Miniserver Gen1 the tunnel address has to be set, otherwise, as written above, there is a continuous send disconnect to 1.1.255. Here is a rather older log regarding this:

updater-1.20-2025-01-05_13-49-40.537_TRACE_x.zip

[bmalinowsky]

Wrt logging, i pulled over some recent log level adjustments from the master branch. As you said, some levels were not user friendly, as those events occur quite often.

The link medium settings now contain a new accessor

calimero-core/src/tuwien/auto/calimero/link/medium/KNXMediumSettings.java

Line 142 in 4b74952

public final Optional<IndividualAddress> assignedAddress() { return assigned.get(); }

which retrieves the currently assigned IA if applicable with the used protocol after the link connected.
(The master branch now uses this to check L4 disconnects more thoroughly, but I'm hesitant to put that in here before releasing, as it is a rather subtle change.)

Out of pure interest. Do you have an example of a server that doesn't like this?

I don't really recall the make or model, it has been some time; I mainly mentioned it because a lot of HW is rarely flashed once installed.