etzel-mes commented on PR #27910: URL: https://github.com/apache/camel/pull/27910#issuecomment-6220104224
Thanks @allthingssecurity, confirmed. Milo resets the watchdog when a PublishResponse is received (`PublishingManager`: "reset when the response is received rather than when it is eventually processed") but replaces a publish request only after its notifications have been delivered, and the callback waits on the same delivery queue. A route slower than the watchdog therefore makes a live subscription look dead. Your reproducer failed on 9c6d4cf for me as well (`expected: <1> but was: <2>`, the subscription was recreated). Fixed in 70aca32 with the check you suggested. After the watchdog, `setPublishingModeAsync(true)` checks the subscription first; Milo creates it with publishing enabled, so the request does not change its settings. - `Good`: the subscription is kept. - `Bad_InvalidState`: nothing. Milo resets the subscription only after a `Bad_Timeout`, after a delete or after a failed transfer, and each of those already recovers it. A second recovery could delete the subscription that the first one has just created. This is where I departed from your suggestion. - Connection or session lost: left to Milo's session recovery. `SESSION_LOST` now also has the secure channel faults on which Milo leaves the session (`SessionFsmFactory.SessionFaultListener`). The listener also follows the session state with a `SessionActivityListener`, registered before the client connects: a request sent after the client noticed the loss, for example the check of a watchdog callback that waited behind a slow route, waits for the next reconnect attempt and, if that attempt fails, fails with its error, such as `Bad_Timeout`. A check or a delete that fails while the session is not active is therefore left to Milo as well. The delete of the previous revision had this gap. - Anything else, including `Bad_SubscriptionIdInvalid`: delete and recreate, as before. A server that rejected SetPublishingMode would still get the recreate, not a rebuild. A `Bad_Timeout` status change from the server still recreates the subscription directly, without the check, since the server has already said that the subscription is gone. A route that takes longer than the lifetime of the subscription lets it time out and gets it recreated; the docs say so now. Testing this against a real server also turned up a hang in 9c6d4cf. It handled the outcome of the delete on `executor`, which is `Stack.sharedScheduledExecutor()`, and the recreate (`create()`) and the rebuild (`disconnect()`) block there while holding the lock. With one processor that executor has a single thread, and a request sent while the server cannot be reached waits until a reconnect attempt restores the channel or fails; Milo schedules those attempts on that same thread. In a container limited to one CPU, 9c6d4cf sent the delete of a watchdog that had waited behind a slow route while the session was being reactivated. The delete failed with the `Bad_Timeout` of the failed reactivation, and the rebuild blocked that thread in `OpcUaClient.disconnect()` for good: the consumer stayed silent after the network came back, and `getOpcUaClient()` waited for the lock. The outcome of the check and of the delete is now handled on the client's executor (`getTransport().getConfig().ge tExecutor()`). Milo asks that blocking calls are not made there either, because its threads complete the responses. camel-milo does not set the transport's executor, so this is Milo's shared cached pool, which starts another thread for a response while one waits, as it already does while a route processes a value. The producers can reach the same wait, and this PR does not change that path: the failure of a write, a method call, a read or a browse rebuilds the connection on `executor` as well. With a producer writing every 2 s on the connection, one CPU and a 30 s silent outage, upstream main (a16cccbde62) hung in 3 of 11 runs and this revision in 4 of 8, each time in `SubscriptionManager.write` → `handleConnectionFailure` → `OpcUaClient.disconnect()` on the scheduled thread. From the logs it is a race: after the failed keep-alive Milo closes the channel, and a CloseSession that reaches the transport before the channel state machine has handled the close fails at once, while a later one waits for the reconnect. Handling those failures on the client's executor recovered in all 9 runs of the same test, but it also moves the successful completions to that executor and needs a guard so that a stale failure does not start a second reconnect, so I will take it up separately; it touches the sa me handlers as CAMEL-25690. The reconnect job (`connect()`) and `resubscribe` also still run on `executor`, where the same wait is possible in a narrower window; CAMEL-25692 already proposes an executor owned by the component. Tests: - New test `MonitorItemLifecycleTest#subscriptionThatASlowRouteHeldUpIsKept`, based on your reproducer: red on 9c6d4cf, green now. Besides the delivery count and the subscription id, it asserts that the subscription's `ServerState` was replaced, which, with the id unchanged, only a `Good` answer to the check does here, so the test fails if the check never ran. - Your second variant (Camel's and Milo's defaults, a route that holds one value for 30 s) I ran against a real server with this round's code, the first item in the list below: the watchdog fires after 16.5 s, the check is answered `Good`, the value is delivered once and the subscription id is unchanged. It is not in the suite because of its length. - The recovery still works: in `subscriptionThatStopsPublishingIsRecreatedInTheSameSession` the check is answered `Bad_SubscriptionIdInvalid` and the subscription is recreated. In the chaos run from my previous comment, the server's log shows that it had deleted the subscription 14.7 to 16.5 s before each of the 26 watchdog firings, so none of them would have been answered `Good`. - The executor change has no unit test: it needs a scheduled executor with one thread and a server that cannot be reached. The real-server runs below show what it changes. Against a real server (opc-plc 2.15.4, Milo defaults: watchdog 16.5 s, lifetime 50 s; each client in a container limited to one CPU; traffic blocked with iptables in the client's network namespace): - A route that holds one value for 30 s: the check is answered `Good`, the subscription is kept and the value is delivered once. - The server loses the subscription while the session stays (the client deletes it on the server behind the back of its `OpcUaSubscription`): upstream main delivered nothing for 90 s. With this round the check is answered `Bad_SubscriptionIdInvalid`, the subscription is recreated in the same session and a value written after the loss reached the route within 13 s. - A route that holds one value for 90 s, longer than the lifetime: the server reports `Bad_Timeout` and the subscription is recreated once; the check that had waited behind the route is answered `Bad_InvalidState` and does nothing (4 of 4 runs). With a 60 s hold the server still had the subscription (3 of 3): it answers the last outstanding publish request with a keep-alive first, and the lifetime counts from there. - A slow route, with the network blocked after the watchdog has elapsed behind the route and before the route finishes, so that the queued check is sent while the session is not active: the check fails with `Bad_Timeout` from a reconnect attempt and is left to Milo. The session is reactivated with the same subscription, and a value written after the network was back reached the route within 2.2 to 2.3 s (three runs). 9c6d4cf went on to the delete and the rebuild and hung as described above. This round's check without the session state, with its outcome still on the scheduled executor, hung the same way in three of three runs; with the session state it recovered. - A 30 s silent drop starting 8 s after a keep-alive: the watchdog elapses first, the check is in flight when the client notices the loss and fails with `Bad_ConnectionClosed`. Same session and subscription; a value written after the drop reached the route within 2.1 s. - A 10 s drop: the check reaches the server once the drop ends and is answered `Good`, so the subscription is kept; the previous revision recreated it. - A 75 s silent drop, longer than the lifetime: the client notices the loss before the watchdog elapses, so Milo pauses the watchdog and no check is sent. After the session is reactivated the server reports `Bad_Timeout`, and the subscription is recreated in the same session; a value written after the drop reached the route within 9.9 s. - A server restart: the transfer fails with `Bad_SubscriptionIdInvalid` and the connection is rebuilt, as before. - The executor of the recovery, with a recreate in flight when the server becomes unreachable (the subscription deleted on the server, 3 s of added latency so that CreateMonitoredItems is still on its way when the traffic is dropped for 90 s): with the outcome on the scheduled executor, the recreate held its only thread until the request timed out after 60 s. No keep-alive ran in that time, so the loss went unnoticed and the lock was held for 68 s (2 of 2 runs). On the client's executor the keep-alive noticed the loss after 8 s and the connection was rebuilt. With a producer writing on the same connection, the same scenario with a 30 s drop recovered in 7 of 7 runs. One case is left out on purpose: a subscription that the server confirms and then removes, or stops serving, before its next publish response. After a `Good` answer Milo arms the watchdog again only on the next PublishResponse, a reactivated session, or a create or modify; neither the SetPublishingMode answer nor a `Bad_NoSubscription` publish fault does, so such a subscription is not checked again. For a server that keeps the keep-alive rule of the subscription model the window ends with its next keep-alive. A ModifySubscription after each confirmation would close it, at the cost of one more request per check; I left it out, but can add it if you prefer. The previous revision only caught these cases because it recreated every subscription that stopped publishing. Before the rebase below, the class passed 5 runs in a row with reruns disabled; after it, the class passes on each of the three commits. Module `-Psourcecheck verify`: 78 tests, 1 skipped and 1 failure, `ServerCertificateValidationTest` (CAMEL-25645, merged today), which fails the same way on main (16b6e9dfbe8): `mock:trustAll` receives the Bad status of the server item that was not written yet before `Foo`, and the consumer delivers that status since #27908. The docs section (now also covering a slow route and a failed transfer) and the 4.24 note are updated, and so is the PR description. @davsclaus, this round changes more than the revision you approved: the check, the session state and the executor of the recovery. Your inline suggestion is applied in the same commit, with one addition (details in the thread). #27908 has been merged in the meantime, so the branch is rebased onto main; 9c6d4cf, the revision you approved, is now d3c527e. Since #27908 the tests start `item1` after the first write, and the recreate tests and the new one do that now as well. `nodeThatCannotBeMonitoredAgainIsReportedWithoutRebuildingTheConnection` starts `item1` too, so the subscription has the same three monitored items as before. #27906 changes the same part of `SubscriptionManager` (it removes `resubscribe` next to `recreate`); whichever of the two is merged second, I will rebase it. _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]
