etzel-mes commented on PR #27910: URL: https://github.com/apache/camel/pull/27910#issuecomment-6201032249
Thanks @davsclaus, the silent drop was the right question. I tried it, and the first revision did not always end in a usable state, so the recovery works differently now. **Setup.** A real server instead of the embedded one: [opc-plc](https://github.com/Azure-Samples/iot-edge-opc-plc) 2.15.4, an OPC UA PLC simulator on the OPC Foundation .NET stack, in Docker, with each Camel client in its own container on Milo's defaults (keep-alive every 5 s, 5 s timeout, 1 failure allowed) and the default publishing interval of 1000 ms. The drop is an iptables `DROP` of the traffic to and from the server port in the client's network namespace, so nothing is closed or reset and both sides keep retransmitting, as with a pulled cable. It starts 8 s after a keep-alive PublishResponse, so the watchdog fired 7 to 8 s into the drop, 2.4 to 7.5 s before the keep-alive declared the session lost: the order you describe. A separate client writes a new value every second, and the times below run from the end of the drop to the first new value the consumer delivers. Each run dropped two clients at once, main and one revision. | Drop | main | first revision | this revision | |---|---|---|---| | 30 s | 1.1 to 2.2 s | 9.6 s, connection rebuilt | 2.2 s, same session | | 30 s, 1 CPU | 1.1 to 2.1 s | 26.5 s, connection rebuilt | 1.1 s, same session | | 30 s, with a producer writing every 2 s on the same connection | 11.7 to 11.8 s, rebuilt after the failed writes | no value within 240 s | 11.8 s, rebuilt after the failed writes | | 75 s: the subscription times out on the server, the session does not | no value within 240 s | 10.0 s, connection rebuilt | 8.9 s, same session | | 150 s: the session times out as well | 19.7 s, rebuilt after the failed transfer | not run | 19.7 s, rebuilt after the failed transfer | **First revision.** The blocking `delete()` went into the dead connection and only failed when the keep-alive closed the channel. `reset()` and `create()` then waited for the session on a thread of `Stack.sharedScheduledExecutor()` while holding `lock`. With a producer, the failed writes run `handleConnectionFailure` on the same executor, and those tasks parked on `lock` until they held the remaining threads (the thread dump showed four in `handleConnectionFailure` from `write` and one in `OpcUaSubscription.create`). Milo schedules the session reconnect on that executor too, so the session never came back and `create()` never returned. Without a producer, `create()` failed while the network was still down, and the fallback rebuilt a connection that Milo would otherwise have resumed. **This revision.** Both callbacks call `deleteAsync()`, without `lock` and without waiting for it, and act on its result: - `Good` or `Bad_SubscriptionIdInvalid`, the answers on which Milo resets the object itself: the server has confirmed in this session that the subscription is gone. Only then is it created again under `lock`, with its monitored items going through `putSubscriptions`. For `Bad_Timeout`, Milo has already reset the subscription, so the delete completes without a service call. - `Bad_ConnectionClosed`, `Bad_SessionClosed`, `Bad_SessionIdInvalid` or `Bad_SessionNotActivated`: nothing more. Milo's session recovery resumes the subscription and arms its watchdog again when publishing resumes (`PublishingManager.resumePublishing`), so a subscription that turns out to be gone is caught again on the live session. A failed transfer still rebuilds through `onTransferFailed`. - Anything else, such as a request timeout: the connection is rebuilt, which closes the session and the subscription with it. So nothing waits on a dead connection while holding `lock`: it is taken for `create()` and the monitored items only after the server has answered the delete. This follows the Milo Javadoc of `onWatchdogTimerElapsed` ("Consider deleting and creating a new Subscription") and leaves the connection-level recovery to Milo. In the 30 s runs the delete failed with `Bad_ConnectionClosed`, and the server's diagnostics show the original subscription alive after the recovery, so a delete that failed with the connection was not applied later. Three more runs covered the other orders, each followed by a minute of values written every second, during which both clients kept delivering values with no gap longer than 2.1 s: - A drop starting 2 s after a keep-alive: the session is declared lost before the watchdog fires, the watchdog is paused, and Milo recovers alone (1.1 s for both). - A drop starting 5 s after a keep-alive: the watchdog fires first, the delete fails with the connection, and the subscription keeps its id (1.1 s for both). - A 10 s drop that ends before the keep-alive gives up: the delete reaches the server once the network is back, and the subscription is created again in the same session. The first value arrived after 5.4 s, against 4.4 s for main, which resumed the old subscription. The 75 s row is the case the PR is about, caused by the network: the session survives the drop and the subscription does not. main only logs the `Bad_Timeout` that the server reports after the reconnect, and stays silent; this revision creates the subscription again 26 ms later, in the same session. **Without a network fault.** opc-plc has a chaos mode that, 56 times in 31 minutes here, deletes a subscription without telling the client, closes one session (keeping or deleting its subscriptions) or all sessions, closes all subscriptions or injects service faults. I ran one client per variant against it, with a third client writing a value every second: - main was silent for 24 of the 30 minutes. Each deleted subscription left it without values until the chaos monkey happened to close its session, which failed the transfer and rebuilt the connection: five outages of 110 to 829 s, and it was silent again at the end. - This revision was silent for 7.7 minutes, in 25 outages of about 17.6 s. Its subscription was created again in the same session 25 times, 24 times after the 16.5 s watchdog and once after a `Bad_Timeout` from the server; the longest outage, 34 s, was a recreated subscription that the next chaos round deleted right away. Two deletes took the other branches: one was answered with `Bad_SessionIdInvalid` because the server had closed the session, so Milo's recovery opened a new session and the failed transfer rebuilt the connection; the other was answered with an injected `Bad_SecureChannelClosed` fault and rebuilt the connection directly, which had a new subscription 46 ms later. Sessions the chaos monkey closed rebuilt it through `onTransferFailed`, as on main. **Docs.** The section now covers the silent drop: the delete fails with the connection, the client restores the session once the server can be reached again, and the subscription resumes publishing, or is created again when the server reports that it timed out in the meantime. It also says that a network that is back before the client has noticed the loss has the subscription created again. **A correction to my earlier reply.** Milo 1.1.8 does serialize the lifecycle transitions of `OpcUaSubscription` (`create`, `modify`, `delete`) itself; only the monitored item management is not serialized. That is why the delete can run without `lock` now, while `create()` and the monitored items still take it. @gnodet-bot, your two follow-up findings are the two inline threads; both are answered there. _Claude Code on behalf of etzel-mes_ -- This is an automated message from the Apache Git Service. To respond to the message, please log on to GitHub and use the URL above to go to the specific comment. To unsubscribe, e-mail: [email protected] For queries about this service, please contact Infrastructure at: [email protected]
