From cc485ac4c8a41f277378a7879c1d29c63db215ed Mon Sep 17 00:00:00 2001 From: Bertrand Martin Date: Thu, 8 Oct 2026 20:28:41 +0200 Subject: [PATCH] Recover from a lost UDP reply in seconds instead of minutes A dropped BMC reply used to cost the whole 300 s per-message timeout and an empty result. Four defects in the transport path made every retry pointless and every wait unbounded: - MessageListener kept the "Message timed out" error of the previous try, so a retry rethrew it at once instead of waiting for the resent message (#78). The listener now resets its outcome per try and waits on a monitor instead of polling. - MessageQueue kept a timed-out message for another timeout period and its tag reservation was inverted (#93). A timed-out message now leaves the queue at once and is reported once; a listener that throws no longer kills the timer thread, and the wait for a free queue slot is bounded by the message timeout. - Connection.waitForResponse counted sleeps instead of elapsed time and swallowed interruption (#79). It now waits on a wall-clock deadline, and an interrupt rolls the state machine back and propagates, so Future.cancel(true) from IpmiClient really stops the worker. The retry loops of the connectors no longer retry an interrupted step. The UDP receiver and the timers are daemon threads, and AbstractIpmiRunner .close() tolerates a session that never got a connector. - The default per-message timeout is 5 s instead of 300 s, and IpmiClient caps it by the overall timeout of the call (#77). IpmiConnector exposes getTimeout(handle). Verified on a GIGABYTE and a Lenovo BMC: a dropped Get SDR reply is now retried after 5 s and the sensor walk completes in about 9 s instead of timing out at 120 s; an unreachable host fails with "Command timed out" after 20 s, and the JVM exits without System.exit(). Fixes #77, fixes #78, fixes #79, fixes #93. Co-Authored-By: Claude Fable 5.1 --- .../ipmi/client/IpmiClientConfiguration.java | 17 +-- .../client/runner/AbstractIpmiRunner.java | 18 +++ .../core/api/async/IpmiAsyncConnector.java | 35 ++++-- .../ipmi/core/api/sync/IpmiConnector.java | 13 +- .../ipmi/core/api/sync/MessageListener.java | 26 ++-- .../ipmi/core/connection/Connection.java | 25 ++-- .../core/connection/queue/MessageQueue.java | 40 +++--- .../core/connection/queue/QueueElement.java | 14 --- .../ipmi/core/transport/UdpMessenger.java | 1 + src/main/resources/connection.properties | 2 +- src/site/markdown/configuration.md | 4 +- src/site/markdown/installation.md | 8 +- src/site/markdown/low-level-api.md | 4 +- src/site/markdown/timeouts-and-errors.md | 39 ++---- src/site/markdown/troubleshooting.md | 14 +-- src/site/markdown/upgrading.md | 18 ++- .../core/api/sync/MessageListenerTest.java | 69 ++++++++++ .../ipmi/core/connection/ConnectionTest.java | 106 ++++++++++++++++ .../connection/queue/MessageQueueTest.java | 118 ++++++++++++++++++ .../ipmi/core/transport/SilentMessenger.java | 27 ++++ 20 files changed, 486 insertions(+), 112 deletions(-) create mode 100644 src/test/java/org/metricshub/ipmi/core/api/sync/MessageListenerTest.java create mode 100644 src/test/java/org/metricshub/ipmi/core/connection/ConnectionTest.java create mode 100644 src/test/java/org/metricshub/ipmi/core/connection/queue/MessageQueueTest.java create mode 100644 src/test/java/org/metricshub/ipmi/core/transport/SilentMessenger.java diff --git a/src/main/java/org/metricshub/ipmi/client/IpmiClientConfiguration.java b/src/main/java/org/metricshub/ipmi/client/IpmiClientConfiguration.java index 232d114..6be33c9 100644 --- a/src/main/java/org/metricshub/ipmi/client/IpmiClientConfiguration.java +++ b/src/main/java/org/metricshub/ipmi/client/IpmiClientConfiguration.java @@ -52,7 +52,8 @@ public class IpmiClientConfiguration { * @param password Password used to establish the connection with the host via the IPMI protocol. * @param bmcKey The key that should be provided if the two-key authentication is enabled, null otherwise. * @param skipAuth Whether the client should skip authentication - * @param timeout Timeout used for each IPMI request. + * @param timeout Overall deadline of each {@code IpmiClient} call, in seconds. It also caps the timeout of each + * message. */ public IpmiClientConfiguration(String hostname, String username, char[] password, byte[] bmcKey, boolean skipAuth, long timeout) { @@ -73,7 +74,8 @@ public IpmiClientConfiguration(String hostname, String username, char[] password * @param password Password used to establish the connection with the host via the IPMI protocol. * @param bmcKey The key that should be provided if the two-key authentication is enabled, null otherwise. * @param skipAuth Whether the client should skip authentication - * @param timeout Timeout used for each IPMI request. + * @param timeout Overall deadline of each {@code IpmiClient} call, in seconds. It also caps the timeout of each + * message. */ public IpmiClientConfiguration(String hostname, int port, String username, char[] password, byte[] bmcKey, boolean skipAuth, long timeout) { @@ -89,7 +91,8 @@ public IpmiClientConfiguration(String hostname, int port, String username, char[ * @param password Password used to establish the connection with the host via the IPMI protocol. * @param bmcKey The key that should be provided if the two-key authentication is enabled, null otherwise. * @param skipAuth Whether the client should skip authentication - * @param timeout Timeout used for each IPMI request. + * @param timeout Overall deadline of each {@code IpmiClient} call, in seconds. It also caps the timeout of each + * message. * @param pingPeriod The period in milliseconds used to send the keep alive messages.
* Set pingPeriod to 0 to turn off keep-alive messages sent to the remote host. */ @@ -217,18 +220,18 @@ public void setSkipAuth(boolean skipAuth) { } /** - * Returns the timeout used for each IPMI request. + * Returns the overall deadline of each {@code IpmiClient} call, in seconds. * - * @return The timeout used for each IPMI request. + * @return The overall deadline of each {@code IpmiClient} call, in seconds. */ public long getTimeout() { return timeout; } /** - * Sets the timeout used for each IPMI request. + * Sets the overall deadline of each {@code IpmiClient} call, in seconds. It also caps the timeout of each message. * - * @param timeout The timeout used for each IPMI request. + * @param timeout The overall deadline of each {@code IpmiClient} call, in seconds. */ public void setTimeout(long timeout) { this.timeout = timeout; diff --git a/src/main/java/org/metricshub/ipmi/client/runner/AbstractIpmiRunner.java b/src/main/java/org/metricshub/ipmi/client/runner/AbstractIpmiRunner.java index 6ab64ac..9f2802b 100644 --- a/src/main/java/org/metricshub/ipmi/client/runner/AbstractIpmiRunner.java +++ b/src/main/java/org/metricshub/ipmi/client/runner/AbstractIpmiRunner.java @@ -147,6 +147,7 @@ protected void startSession() throws Exception { ipmiConfiguration.getPort(), Connection.getDefaultCipherSuite(), PrivilegeLevel.User); + capMessageTimeout(); } // Start the session, provide user name and password, and optionally the @@ -175,6 +176,7 @@ public void authenticate() throws Exception { .createConnection( InetAddress.getByName(ipmiConfiguration.getHostname()), ipmiConfiguration.getPort()); + capMessageTimeout(); // Get available cipher suites list via getAvailableCipherSuites and // pick one of them that will be used further in the session. @@ -212,8 +214,24 @@ protected CipherSuite getAvailableCipherSuite() throws Exception { return suites.get(0); } + /** + * Caps the timeout of each message by the overall deadline of the call, so that a lost reply is retried + * within that deadline rather than reported after it. + */ + private void capMessageTimeout() { + long deadlineMs = ipmiConfiguration.getTimeout() * 1000; + if (deadlineMs > 0 && deadlineMs < connector.getTimeout(handle)) { + connector.setTimeout(handle, (int) deadlineMs); + } + } + @Override public void close() { + // startSession() may have failed before the connector or the handle existed + if (connector == null) { + return; + } + if (handle != null) { // Close the session try { diff --git a/src/main/java/org/metricshub/ipmi/core/api/async/IpmiAsyncConnector.java b/src/main/java/org/metricshub/ipmi/core/api/async/IpmiAsyncConnector.java index 8f6b631..d221868 100644 --- a/src/main/java/org/metricshub/ipmi/core/api/async/IpmiAsyncConnector.java +++ b/src/main/java/org/metricshub/ipmi/core/api/async/IpmiAsyncConnector.java @@ -45,6 +45,7 @@ import java.net.InetAddress; import java.util.ArrayList; import java.util.List; +import java.util.concurrent.TimeUnit; import org.slf4j.Logger; import org.slf4j.LoggerFactory; @@ -225,6 +226,8 @@ public List getAvailableCipherSuites( ++tries; result = connectionManager .getAvailableCipherSuites(connectionHandle.getHandle()); + } catch (InterruptedException e) { + throw e; } catch (Exception e) { logger.warn(FAILED_TO_RECEIVE_ANSWER_CAUSE_MESSAGE, e); if (tries > retries) { @@ -269,6 +272,8 @@ public GetChannelAuthenticationCapabilitiesResponseData getChannelAuthentication requestedPrivilegeLevel); connectionHandle.setCipherSuite(cipherSuite); connectionHandle.setPrivilegeLevel(requestedPrivilegeLevel); + } catch (InterruptedException e) { + throw e; } catch (Exception e) { logger.warn(FAILED_TO_RECEIVE_ANSWER_CAUSE_MESSAGE, e); if (tries > retries) { @@ -326,6 +331,8 @@ public Session openSession( session = sessionManager.registerSession(sessionId, connectionHandle); succeded = true; + } catch (InterruptedException e) { + throw e; } catch (Exception e) { logger.warn(FAILED_TO_RECEIVE_ANSWER_CAUSE_MESSAGE, e); if (tries > retries) { @@ -416,26 +423,26 @@ public int sendMessage( throws Exception { int tries = 0; int tag = -1; + Connection connection = connectionManager.getConnection(connectionHandle.getHandle()); while (tries <= retries && tag < 0) { try { ++tries; + // tag < 0 means that the MessageQueue is full: wait for a slot, at most one message timeout + long deadline = System.nanoTime() + TimeUnit.MILLISECONDS.toNanos(connection.getTimeout()); while (tag < 0) { - tag = connectionManager - .getConnection( - connectionHandle.getHandle()) - .sendMessage( - request, - isOneWay); + tag = connection.sendMessage(request, isOneWay); if (tag < 0) { - Thread.sleep(10); // tag < 0 means that MessageQueue is - // full so we need to wait and retry + if (System.nanoTime() >= deadline) { + throw new ConnectionException("Message queue is full"); + } + Thread.sleep(10); } } logger .debug( "Sending message with tag " + tag + ", try " + tries); - } catch (IllegalArgumentException e) { + } catch (IllegalArgumentException | InterruptedException e) { throw e; } catch (Exception e) { logger.warn("Failed to send message, cause:", e); @@ -585,4 +592,14 @@ public void setTimeout(ConnectionHandle handle, int timeout) { connectionManager.getConnection(handle.getHandle()).setTimeout(timeout); } + /** + * Returns the timeout of a single message on the given connection. + * + * @param handle {@link ConnectionHandle} of the connection + * @return the timeout in milliseconds after which a message without a reply is reported as timed out + */ + public int getTimeout(ConnectionHandle handle) { + return connectionManager.getConnection(handle.getHandle()).getTimeout(); + } + } diff --git a/src/main/java/org/metricshub/ipmi/core/api/sync/IpmiConnector.java b/src/main/java/org/metricshub/ipmi/core/api/sync/IpmiConnector.java index 136246b..96f5703 100644 --- a/src/main/java/org/metricshub/ipmi/core/api/sync/IpmiConnector.java +++ b/src/main/java/org/metricshub/ipmi/core/api/sync/IpmiConnector.java @@ -425,7 +425,7 @@ private ResponseData sendThroughAsyncConnector( } messageSent = true; - } catch (IllegalArgumentException e) { + } catch (IllegalArgumentException | InterruptedException e) { throw e; } catch (IPMIException e) { handleErrorResponse(tries, e); @@ -496,6 +496,17 @@ public void setTimeout(ConnectionHandle handle, int timeout) { asyncConnector.setTimeout(handle, timeout); } + /** + * Returns the timeout of a single message on the connection with the given handle. + * + * @param handle + * - {@link ConnectionHandle} associated with the remote host. + * @return the timeout in ms after which a message without a reply is reported as timed out + */ + public int getTimeout(ConnectionHandle handle) { + return asyncConnector.getTimeout(handle); + } + /** * Returns configured number of retries. * diff --git a/src/main/java/org/metricshub/ipmi/core/api/sync/MessageListener.java b/src/main/java/org/metricshub/ipmi/core/api/sync/MessageListener.java index 6e1bb31..5667cb0 100644 --- a/src/main/java/org/metricshub/ipmi/core/api/sync/MessageListener.java +++ b/src/main/java/org/metricshub/ipmi/core/api/sync/MessageListener.java @@ -86,24 +86,25 @@ public ResponseData waitForAnswer(int messageTag) throws Exception { if (messageTag < 0 || messageTag > 63) { throw new IllegalArgumentException("Corrupted message tag"); } + IpmiResponse answer; synchronized (this) { + // Forget the outcome of the previous try: a retry must wait for the reply of the resent message + response = null; this.tag = messageTag; for (IpmiResponse quickResponse : quickMessages) { this.notify(quickResponse); } - } - - while (response == null) { - Thread.sleep(1); - } - if (response instanceof IpmiResponseData) { - synchronized (this) { - this.tag = -1; - quickMessages.clear(); + while (response == null) { + wait(); } - return ((IpmiResponseData) response).getResponseData(); - } else /* response instanceof IpmiError */ { - throw ((IpmiError) response).getException(); + answer = response; + this.tag = -1; + quickMessages.clear(); + } + if (answer instanceof IpmiResponseData) { + return ((IpmiResponseData) answer).getResponseData(); + } else /* answer instanceof IpmiError */ { + throw ((IpmiError) answer).getException(); } } @@ -114,6 +115,7 @@ public synchronized void notify(IpmiResponse ipmiResponse) { quickMessages.add(ipmiResponse); } else if (ipmiResponse.getTag() == tag) { this.response = ipmiResponse; + notifyAll(); } } } diff --git a/src/main/java/org/metricshub/ipmi/core/connection/Connection.java b/src/main/java/org/metricshub/ipmi/core/connection/Connection.java index 6eb1906..cdc2f91 100644 --- a/src/main/java/org/metricshub/ipmi/core/connection/Connection.java +++ b/src/main/java/org/metricshub/ipmi/core/connection/Connection.java @@ -76,6 +76,7 @@ import java.util.Map; import java.util.Timer; import java.util.TimerTask; +import java.util.concurrent.TimeUnit; import java.util.concurrent.atomic.AtomicInteger; /** @@ -96,6 +97,7 @@ public class Connection extends TimerTask implements MachineObserver { */ private volatile int timeout = -1; private volatile StateMachineAction lastAction; + private final Object responseLock = new Object(); private volatile int sessionId; private volatile int managedSystemSessionId; private volatile byte[] sik; @@ -208,7 +210,7 @@ public void connect(InetAddress address, int port, long pingPeriod, boolean skip // If the pingPeriod greater than 0, start the timer otherwise don't start it // means that the connection won't be kept alive by sending no-op messages if (pingPeriod > 0) { - timer = new Timer(); + timer = new Timer(true); timer.schedule(this, pingPeriod, pingPeriod); } @@ -321,15 +323,21 @@ public List getAvailableCipherSuites(int tag) throws Exception { } private void waitForResponse() throws Exception { - int time = 0; + long deadline = System.nanoTime() + TimeUnit.MILLISECONDS.toNanos(timeout); - while (time < timeout && lastAction == null) { + synchronized (responseLock) { try { - Thread.sleep(1); + long remaining = deadline - System.nanoTime(); + while (lastAction == null && remaining > 0) { + TimeUnit.NANOSECONDS.timedWait(responseLock, remaining); + remaining = deadline - System.nanoTime(); + } } catch (InterruptedException e) { - LOGGER.error(e.getMessage(), e); + // The caller gave up on us (Future.cancel): leave the state machine in a state that allows a retry + stateMachine.doTransition(new Timeout()); + Thread.currentThread().interrupt(); + throw e; } - ++time; } if (lastAction == null) { @@ -644,7 +652,10 @@ public void notify(StateMachineAction action) { if (action instanceof GetSikAction) { sik = ((GetSikAction) action).getSik(); } else if (!(action instanceof MessageAction)) { - lastAction = action; + synchronized (responseLock) { + lastAction = action; + responseLock.notifyAll(); + } if (action instanceof ErrorAction) { ErrorAction errorAction = (ErrorAction) action; LOGGER.error(errorAction.getException().getMessage(), errorAction.getException()); diff --git a/src/main/java/org/metricshub/ipmi/core/connection/queue/MessageQueue.java b/src/main/java/org/metricshub/ipmi/core/connection/queue/MessageQueue.java index 1a27f8c..4880eda 100644 --- a/src/main/java/org/metricshub/ipmi/core/connection/queue/MessageQueue.java +++ b/src/main/java/org/metricshub/ipmi/core/connection/queue/MessageQueue.java @@ -79,7 +79,7 @@ public MessageQueue(Connection connection, int timeout, int minSequenceNumber, i this.connection = connection; queue = new ArrayList(); setTimeout(timeout); - timer = new Timer(); + timer = new Timer(true); timer.schedule(this, cleaningFrequency, cleaningFrequency); } @@ -117,7 +117,7 @@ private synchronized boolean isReserved(int tag) { * @return true if tag was reserved successfully, false otherwise */ private synchronized boolean reserveTag(int tag) { - if (isReserved(tag)) { + if (!isReserved(tag)) { reservedTags.add(tag); return true; } @@ -349,23 +349,29 @@ private boolean messageJustTimedOut(QueueElement oldestQueueElement) { return now.getTime() - oldestQueueElement.getTimestamp().getTime() > (long) timeout; } + /** + * Removes the oldest message from the queue; when it timed out (rather than being answered), the response + * listeners are told so, which lets the sender retry it with a fresh tag. + */ private void processObsoleteMessage(QueueElement message, boolean done) { int tag = message.getId(); - boolean previouslyTimedOut = message.isTimedOut(); - - if (previouslyTimedOut || done) { - queue.remove(0); - logger.info("Removing message after timeout, tag: " + tag); - releaseTag(tag); - } else { - message.makeTimedOut(); - message.refreshTimestamp(); - connection - .notifyResponseListeners( - connection.getHandle(), - tag, - null, - new ConnectionException("Message timed out")); + + queue.remove(0); + releaseTag(tag); + + if (!done) { + logger.debug("Message timed out, tag: {}", tag); + try { + connection + .notifyResponseListeners( + connection.getHandle(), + tag, + null, + new ConnectionException("Message timed out")); + } catch (RuntimeException e) { + // A failing listener must not kill the timer thread that expires the other messages + logger.warn("Response listener failed while handling the timeout of tag {}", tag, e); + } } } diff --git a/src/main/java/org/metricshub/ipmi/core/connection/queue/QueueElement.java b/src/main/java/org/metricshub/ipmi/core/connection/queue/QueueElement.java index 504d7c9..d3f0a9d 100644 --- a/src/main/java/org/metricshub/ipmi/core/connection/queue/QueueElement.java +++ b/src/main/java/org/metricshub/ipmi/core/connection/queue/QueueElement.java @@ -34,7 +34,6 @@ public class QueueElement { */ @Deprecated private int retries; - private boolean timedOut; private PayloadCoder request; private ResponseData response; @@ -45,7 +44,6 @@ public QueueElement(int id, PayloadCoder request) { this.request = request; timestamp = new Date(); retries = 0; - this.timedOut = false; } public int getId() { @@ -91,16 +89,4 @@ public void setResponse(ResponseData response) { public Date getTimestamp() { return timestamp; } - - public void refreshTimestamp() { - timestamp = new Date(); - } - - public boolean isTimedOut() { - return timedOut; - } - - public void makeTimedOut() { - this.timedOut = true; - } } diff --git a/src/main/java/org/metricshub/ipmi/core/transport/UdpMessenger.java b/src/main/java/org/metricshub/ipmi/core/transport/UdpMessenger.java index b59b93c..5728789 100644 --- a/src/main/java/org/metricshub/ipmi/core/transport/UdpMessenger.java +++ b/src/main/java/org/metricshub/ipmi/core/transport/UdpMessenger.java @@ -94,6 +94,7 @@ public UdpMessenger(int port, InetAddress address) throws SocketException { bufferSize = DEFAULTBUFFERSIZE; socket = new DatagramSocket(this.port, address); socket.setSoTimeout(0); + setDaemon(true); this.start(); } diff --git a/src/main/resources/connection.properties b/src/main/resources/connection.properties index 3f64be6..785e798 100644 --- a/src/main/resources/connection.properties +++ b/src/main/resources/connection.properties @@ -1,6 +1,6 @@ #Frequency of the no-op commands that will be sent to keep up the session pingPeriod=30000 #Time in ms after which a message times out. -timeout=300000 +timeout=5000 #Frequency of checking messages for timeouts in ms. cleaningFrequency=500 diff --git a/src/site/markdown/configuration.md b/src/site/markdown/configuration.md index f3f35ad..54f46b4 100644 --- a/src/site/markdown/configuration.md +++ b/src/site/markdown/configuration.md @@ -88,8 +88,8 @@ take tens of seconds on a slow BMC: 120 s is a safe value. `getFrusAndSensorsAsStringResult()` makes two calls (FRUs, then sensors), each with this deadline, so it can take up to twice the timeout. -The timeout of each **message** is a different setting, 5 minutes by default; see -[Timeouts and Errors](timeouts-and-errors.html). +The timeout of each **message** is a different setting, 5 s by default and never longer than +this deadline; see [Timeouts and Errors](timeouts-and-errors.html). ### Keep-alive diff --git a/src/site/markdown/installation.md b/src/site/markdown/installation.md index d597711..fa283c3 100644 --- a/src/site/markdown/installation.md +++ b/src/site/markdown/installation.md @@ -57,10 +57,10 @@ What is logged, and at which level: | Level | Messages | | --- | --- | -| `ERROR` | A value the decoders do not know (`Invalid value: ...` for an entity ID, sensor type or unit), a failed session handshake, exceptions in the receiving and keep-alive threads, and the `InterruptedException` of a session interrupted by the [overall timeout](timeouts-and-errors.html#overall-timeout). | -| `WARN` | An SDR record that cannot be decoded and is skipped, a FRU that cannot be read or decoded (the FRU is then truncated or missing), a message that failed and is resent, a packet whose integrity check failed. | -| `INFO` | Every lookup of a [`connection.properties`](timeouts-and-errors.html#library-wide-defaults) value, and every message removed from the queue after its timeout. | -| `DEBUG` | Each message sent, with its tag and attempt number; a session that could not be closed cleanly. | +| `ERROR` | A value the decoders do not know (`Invalid value: ...` for an entity ID, sensor type or unit), a failed session handshake, exceptions in the receiving and keep-alive threads. | +| `WARN` | An SDR record that cannot be decoded and is skipped, a FRU that cannot be read or decoded (the FRU is then truncated or missing), a message that failed and is resent, a packet whose integrity check failed, a response listener that threw while a timeout was reported. | +| `INFO` | Every lookup of a [`connection.properties`](timeouts-and-errors.html#library-wide-defaults) value. | +| `DEBUG` | Each message sent, with its tag and attempt number; each message that timed out; a session that could not be closed cleanly. | > [!TIP] > The `INFO` messages are noisy: set the `org.metricshub.ipmi` logger to `WARN` in production, diff --git a/src/site/markdown/low-level-api.md b/src/site/markdown/low-level-api.md index e775fae..81277a7 100644 --- a/src/site/markdown/low-level-api.md +++ b/src/site/markdown/low-level-api.md @@ -42,8 +42,8 @@ public class LowLevelExample { // Register a connection to the BMC, on UDP port 623 ConnectionHandle handle = connector.createConnection(InetAddress.getByName("bmc.example.com")); - // Wait at most 5 s for each reply instead of 5 min - connector.setTimeout(handle, 5000); + // Wait at most 2 s for each reply instead of the default 5 s + connector.setTimeout(handle, 2000); // Pick a cipher suite among those the BMC offers: 17 if available, else 3 List suites = connector.getAvailableCipherSuites(handle); diff --git a/src/site/markdown/timeouts-and-errors.md b/src/site/markdown/timeouts-and-errors.md index cd94f39..e60aeec 100644 --- a/src/site/markdown/timeouts-and-errors.md +++ b/src/site/markdown/timeouts-and-errors.md @@ -12,7 +12,7 @@ time. Two timeouts apply: | Timeout | Set with | Default | Scope | | --- | --- | --- | --- | | [Overall timeout](#overall-timeout) | `IpmiClientConfiguration.timeout` (seconds) | none, required | One `IpmiClient` call, from the first packet to the closed session | -| [Per-message timeout](#per-message-timeout-and-retries) | `IpmiConnector.setTimeout(handle, ms)`, or the `timeout` of [`connection.properties`](#library-wide-defaults) | 300 000 ms | Each request, including each step of the session handshake | +| [Per-message timeout](#per-message-timeout-and-retries) | `IpmiConnector.setTimeout(handle, ms)`, or the `timeout` of [`connection.properties`](#library-wide-defaults) | 5 000 ms, capped by the overall timeout | Each request, including each step of the session handshake | ## Overall timeout @@ -21,12 +21,8 @@ the session — in a worker thread, and waits for it at most `timeout` seconds. expires, the worker is interrupted and the method throws `java.util.concurrent.TimeoutException`, with nothing collected: there are no partial results. -> [!WARNING] -> Interrupting the worker does not always stop it -> ([#79](https://github.com/metricshub/ipmi-java/issues/79)): a worker waiting for a reply may -> keep waiting, and the library's receiving and timer threads are not daemon threads. The calling -> thread gets its `TimeoutException` on time, but these threads can keep a short-lived JVM alive: -> end command-line programs with `System.exit(0)`. +The interrupted worker stops at its current wait, and the library's receiving and timer threads +are daemon threads: they never keep the JVM alive. ## Per-message timeout and retries @@ -41,28 +37,19 @@ Below the overall timeout, each message has its own timeout and is retried: BMC replies with a *transient* completion code — node busy, out of resources, initialization in progress, timeout — are retried the same way. Any other error completion code fails at once. -> [!IMPORTANT] -> The per-message timeout is **5 minutes** by default, longer than any reasonable overall -> timeout, and `IpmiClientConfiguration` does not expose it -> ([#77](https://github.com/metricshub/ipmi-java/issues/77), -> [#101](https://github.com/metricshub/ipmi-java/issues/101)). With the defaults, **a single lost -> reply makes the whole call wait for the overall timeout** and throw `TimeoutException`. +The per-message timeout is **5 s** by default, and `IpmiClient` caps it by the overall timeout. +With the defaults, a lost reply costs the per-message timeout plus the pause, then the request +is sent again; a BMC that never answers fails after 4 tries, about 20 s (plus the pauses) into +the call. -To recover from lost replies within the overall timeout, lower the per-message timeout to a few -seconds: +`IpmiClientConfiguration` does not expose the per-message timeout +([#101](https://github.com/metricshub/ipmi-java/issues/101)). To change it: * with the [low-level API](low-level-api.html#timeouts), call `setTimeout(handle, ms)` on the connector right after `createConnection()`; * with `IpmiClient`, change the [library-wide default](#library-wide-defaults) before the first call. -Two known defects limit what the retries achieve: a retried in-session message does not wait -for the reply to the resent request -([#78](https://github.com/metricshub/ipmi-java/issues/78)), and each handshake step waits longer -than its timeout because it counts its 1 ms sleeps rather than the elapsed time -([#79](https://github.com/metricshub/ipmi-java/issues/79)). A short per-message timeout still -turns a lost reply into a retry (or a fast failure) instead of a stall. - ## Library-wide defaults The defaults come from two properties files packaged in the jar, read through the @@ -70,7 +57,7 @@ The defaults come from two properties files packaged in the jar, read through th | Property | Default | Meaning | Read | | --- | --- | --- | --- | -| `timeout` | `300000` | Per-message timeout, in ms | When each connection is created | +| `timeout` | `5000` | Per-message timeout, in ms | When each connection is created | | `retries` | `3` | How many times a failed message is sent again | When each `IpmiConnector` is created | | `idleTime` | `4000` | Upper bound of the random pause before a retry, in ms | When each `IpmiConnector` is created | | `pingPeriod` | `30000` | Keep-alive period, in ms, when the configuration's `pingPeriod` is `-1` | When each `IpmiConnector` is created | @@ -82,7 +69,7 @@ values then apply to every connection created afterwards, in the whole JVM. import org.metricshub.ipmi.core.common.PropertiesManager; PropertiesManager properties = PropertiesManager.getInstance(); -properties.setProperty("timeout", "5000"); // per-message timeout: 5 s instead of 5 min +properties.setProperty("timeout", "2000"); // per-message timeout: 2 s instead of 5 s properties.setProperty("retries", "3"); ``` @@ -96,7 +83,7 @@ The `IpmiClient` methods declare three checked exceptions: | Exception | When | | --- | --- | -| `TimeoutException` | The [overall timeout](#overall-timeout) expired. Also the usual symptom of a wrong host, a closed UDP port, IPMI over LAN disabled, or a lost reply with the default per-message timeout. | +| `TimeoutException` | The [overall timeout](#overall-timeout) expired: a large SDR repository or many FRUs on a slow BMC, or an overall timeout shorter than the handshake tries (about 20 s). | | `ExecutionException` | The exchange failed. `getCause()` holds the actual exception (see below). | | `InterruptedException` | The calling thread was interrupted while waiting. | @@ -105,7 +92,7 @@ Common causes wrapped in the `ExecutionException`: | Cause | Meaning | | --- | --- | | `ConnectionException: Illegal connection state: Rakp1Waiting` | The RAKP handshake failed: wrong user name or password, account not allowed over LAN or at the User level. The `ERROR` log shows the actual reason (`Authentication check failed`, ...), see [#109](https://github.com/metricshub/ipmi-java/issues/109). | -| `ConnectionException: Command timed out` / `Message timed out` | No reply after all the tries of a message (with a [shortened](#per-message-timeout-and-retries) per-message timeout). | +| `ConnectionException: Command timed out` / `Message timed out` | No reply after all the [tries](#per-message-timeout-and-retries) of a message: `Command timed out` during the session handshake, the usual symptom of a wrong host, a closed UDP port or IPMI over LAN disabled; `Message timed out` in the session. | | `IPMIException` | The BMC answered with an error completion code. `getCompletionCode()` returns it, for example `InsufficientPrivilege` (`0xD4`). | | `IllegalArgumentException: ... is not yet implemented.` | The chosen cipher suite uses an algorithm the client does not implement (xRC4, MD5-128). See [cipher suites](preparing-the-bmc.html#cipher-suites). | | `Exception: Cannot get the available cipher suites.` | The BMC returned an empty cipher suite list. | diff --git a/src/site/markdown/troubleshooting.md b/src/site/markdown/troubleshooting.md index d9e05e8..ef31c1c 100644 --- a/src/site/markdown/troubleshooting.md +++ b/src/site/markdown/troubleshooting.md @@ -16,11 +16,12 @@ description: Diagnose the usual failures of the IPMI Java Client — timeouts, a 3. **Start with `getChassisStatus()`**: it is a single command, so it tests the network, the credentials and the cipher suite in a few hundred milliseconds. -## `TimeoutException`, nothing collected +## `Command timed out` or `TimeoutException`, nothing collected -The BMC did not answer in time. With the default settings, this is the symptom of every network -or configuration problem, because the 5-minute per-message timeout is longer than the overall -timeout ([Timeouts and Errors](timeouts-and-errors.html)). +The BMC did not answer in time. A BMC that never answers fails the session handshake after its +4 tries of 5 s: the `ExecutionException` wraps `ConnectionException: Command timed out`. A +`TimeoutException` means the whole call outlived the overall timeout +([Timeouts and Errors](timeouts-and-errors.html)). | Cause | Check | | --- | --- | @@ -28,12 +29,11 @@ timeout ([Timeouts and Errors](timeouts-and-errors.html)). | IPMI over LAN disabled on the BMC | [Enabling IPMI over LAN](preparing-the-bmc.html#enabling-ipmi-over-lan) | | UDP port 623 filtered | [Firewall](preparing-the-bmc.html#firewall) | | An IPMI 1.5-only BMC | Such BMCs never answer the RMCP+ Open Session request ([#91](https://github.com/metricshub/ipmi-java/issues/91)). | -| A lost UDP reply | Run the call again. With a [shorter per-message timeout](timeouts-and-errors.html#library-wide-defaults), lost replies are retried instead. | +| A lost UDP reply | Retried after the [per-message timeout](timeouts-and-errors.html#per-message-timeout-and-retries); the call only fails when 4 tries in a row get no reply. | | Several sessions to the same BMC at the same time | BMCs drop replies under concurrent sessions: query each BMC [from one thread at a time](configuration.html#thread-safety). | | A large SDR repository or many FRUs on a slow BMC | Raise the [timeout](configuration.html#timeout): 120 s is a safe value. | -When the timeout expires, the interrupted session logs an `ERROR` with an `InterruptedException` -(`sleep interrupted`): its stack trace shows the step that was waiting. A wait in +The stack trace of the `Command timed out` shows the step that was waiting. A failure in `getAvailableCipherSuites` means the BMC never answered the very first request: the address, the port or the firewall is wrong, or IPMI over LAN is disabled. diff --git a/src/site/markdown/upgrading.md b/src/site/markdown/upgrading.md index a5a40b0..576c3b4 100644 --- a/src/site/markdown/upgrading.md +++ b/src/site/markdown/upgrading.md @@ -19,9 +19,21 @@ The `IpmiClient` API is unchanged, and the client is more tolerant of real-world [BMC key](configuration.html#bmc-key) is used as raw bytes: a key with bytes `80h` or above no longer gets corrupted into a wrong session key; * the user name is limited to 16 bytes once encoded, as the IPMI specification requires, instead of - 16 characters. - -Code that **extends** the library's protocol classes needs the changes below. + 16 characters; +* a lost UDP reply is recovered in seconds instead of stalling the call: the per-message timeout + is 5 s by default (it was 5 minutes) and capped by the overall timeout, a retried message waits + for the reply of the resent request, and the handshake steps wait for the elapsed time rather + than a number of sleeps ([Timeouts and Errors](timeouts-and-errors.html)); +* a BMC that never answers now fails the session handshake with + `ExecutionException` wrapping `ConnectionException: Command timed out`, about 20 s into the + call, where 1.2.02 threw `TimeoutException` at the overall timeout; +* the overall timeout cancels the worker for good: the interrupted session stops at its current + wait, and the receiving and timer threads are daemon threads, so a program no longer needs + `System.exit()` to end. + +Code that **extends** the library's protocol classes needs the changes below. `QueueElement` +lost its `isTimedOut()`, `makeTimedOut()` and `refreshTimestamp()` methods: a timed-out message +now leaves the queue at once. ### Protected fields diff --git a/src/test/java/org/metricshub/ipmi/core/api/sync/MessageListenerTest.java b/src/test/java/org/metricshub/ipmi/core/api/sync/MessageListenerTest.java new file mode 100644 index 0000000..1899eec --- /dev/null +++ b/src/test/java/org/metricshub/ipmi/core/api/sync/MessageListenerTest.java @@ -0,0 +1,69 @@ +package org.metricshub.ipmi.core.api.sync; + +import static org.junit.jupiter.api.Assertions.assertFalse; +import static org.junit.jupiter.api.Assertions.assertSame; +import static org.junit.jupiter.api.Assertions.assertThrows; +import static org.junit.jupiter.api.Assertions.assertTrue; + +import java.net.InetAddress; +import java.util.concurrent.atomic.AtomicReference; + +import org.junit.jupiter.api.Test; +import org.metricshub.ipmi.core.api.async.ConnectionHandle; +import org.metricshub.ipmi.core.api.async.messages.IpmiError; +import org.metricshub.ipmi.core.api.async.messages.IpmiResponse; +import org.metricshub.ipmi.core.api.async.messages.IpmiResponseData; +import org.metricshub.ipmi.core.coding.commands.ResponseData; +import org.metricshub.ipmi.core.connection.ConnectionException; + +class MessageListenerTest { + + private static final int TAG = 5; + private static final ConnectionHandle HANDLE = new ConnectionHandle(0, InetAddress.getLoopbackAddress(), 623); + + @Test + void retryWaitsForTheReplyOfTheResentMessage() throws Exception { + MessageListener listener = new MessageListener(HANDLE); + ResponseData data = new ResponseData() {}; + + // First try: the message times out + deliverLater(listener, new IpmiError(new ConnectionException("Message timed out"), TAG, HANDLE)); + assertThrows(ConnectionException.class, () -> listener.waitForAnswer(TAG)); + + // Retry with the same tag: the reply of the resent message must be returned, not the stale error + deliverLater(listener, new IpmiResponseData(data, TAG, HANDLE)); + assertSame(data, listener.waitForAnswer(TAG)); + } + + @Test + void waitForAnswerReturnsWhenInterrupted() throws Exception { + MessageListener listener = new MessageListener(HANDLE); + AtomicReference thrown = new AtomicReference<>(); + Thread waiter = new Thread(() -> { + try { + listener.waitForAnswer(TAG); + } catch (Throwable t) { + thrown.set(t); + } + }); + waiter.start(); + Thread.sleep(100); + waiter.interrupt(); + waiter.join(5000); + assertFalse(waiter.isAlive(), "the waiting thread must return when interrupted"); + assertTrue(thrown.get() instanceof InterruptedException, String.valueOf(thrown.get())); + } + + private static void deliverLater(MessageListener listener, IpmiResponse response) { + Thread deliverer = new Thread(() -> { + try { + Thread.sleep(50); + } catch (InterruptedException e) { + return; + } + listener.notify(response); + }); + deliverer.setDaemon(true); + deliverer.start(); + } +} diff --git a/src/test/java/org/metricshub/ipmi/core/connection/ConnectionTest.java b/src/test/java/org/metricshub/ipmi/core/connection/ConnectionTest.java new file mode 100644 index 0000000..a8dd717 --- /dev/null +++ b/src/test/java/org/metricshub/ipmi/core/connection/ConnectionTest.java @@ -0,0 +1,106 @@ +package org.metricshub.ipmi.core.connection; + +import static org.junit.jupiter.api.Assertions.assertEquals; +import static org.junit.jupiter.api.Assertions.assertFalse; +import static org.junit.jupiter.api.Assertions.assertThrows; +import static org.junit.jupiter.api.Assertions.assertTrue; + +import java.io.IOException; +import java.net.InetAddress; +import java.util.HashSet; +import java.util.Set; +import java.util.concurrent.TimeUnit; +import java.util.concurrent.atomic.AtomicBoolean; +import java.util.concurrent.atomic.AtomicReference; + +import org.junit.jupiter.api.Test; +import org.metricshub.ipmi.core.api.sync.IpmiConnector; +import org.metricshub.ipmi.core.transport.SilentMessenger; + +class ConnectionTest { + + private static final int TIMEOUT_MS = 200; + + private static final String COMMAND_TIMED_OUT = "Command timed out"; + + private static Connection connect(int timeout) throws IOException { + Connection connection = new Connection(new SilentMessenger(), 0); + connection.setTimeout(timeout); + connection.connect(InetAddress.getLoopbackAddress(), 623, 0); + return connection; + } + + @Test + void handshakeStepTimesOutOnWallClock() throws Exception { + Connection connection = connect(TIMEOUT_MS); + try { + long start = System.nanoTime(); + ConnectionException e = assertThrows( + ConnectionException.class, + () -> connection.getAvailableCipherSuites(1)); + long elapsed = TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - start); + + assertEquals(COMMAND_TIMED_OUT, e.getMessage()); + assertTrue(elapsed >= TIMEOUT_MS && elapsed < 10 * TIMEOUT_MS, "elapsed " + elapsed + " ms"); + + // The state machine is back to Uninitialized: the step can be tried again + e = assertThrows(ConnectionException.class, () -> connection.getAvailableCipherSuites(2)); + assertEquals(COMMAND_TIMED_OUT, e.getMessage()); + } finally { + connection.disconnect(); + } + } + + @Test + void handshakeStepReturnsWhenInterrupted() throws Exception { + Connection connection = connect(60000); + try { + AtomicReference thrown = new AtomicReference<>(); + AtomicBoolean interruptedOnReturn = new AtomicBoolean(); + Thread worker = new Thread(() -> { + try { + connection.getAvailableCipherSuites(1); + } catch (Throwable t) { + thrown.set(t); + } + interruptedOnReturn.set(Thread.currentThread().isInterrupted()); + }); + worker.start(); + Thread.sleep(100); + worker.interrupt(); + worker.join(5000); + + assertFalse(worker.isAlive(), "the interrupted step must return"); + assertTrue(thrown.get() instanceof InterruptedException, String.valueOf(thrown.get())); + assertTrue(interruptedOnReturn.get(), "the interrupt flag must be restored"); + + // The state machine was rolled back: the step can be tried again + connection.setTimeout(TIMEOUT_MS); + ConnectionException e = assertThrows( + ConnectionException.class, + () -> connection.getAvailableCipherSuites(2)); + assertEquals(COMMAND_TIMED_OUT, e.getMessage()); + } finally { + connection.disconnect(); + } + } + + @Test + void libraryThreadsAreDaemonThreads() throws Exception { + Set before = Thread.getAllStackTraces().keySet(); + IpmiConnector connector = new IpmiConnector(0); + try { + // UDP receiver, keep-alive timer and the message queue timers + connector.createConnection(InetAddress.getLoopbackAddress(), 623); + + Set created = new HashSet<>(Thread.getAllStackTraces().keySet()); + created.removeAll(before); + assertFalse(created.isEmpty(), "the connector must have started its threads"); + for (Thread thread : created) { + assertTrue(thread.isDaemon(), thread.getName() + " must be a daemon thread"); + } + } finally { + connector.tearDown(); + } + } +} diff --git a/src/test/java/org/metricshub/ipmi/core/connection/queue/MessageQueueTest.java b/src/test/java/org/metricshub/ipmi/core/connection/queue/MessageQueueTest.java new file mode 100644 index 0000000..3e903bc --- /dev/null +++ b/src/test/java/org/metricshub/ipmi/core/connection/queue/MessageQueueTest.java @@ -0,0 +1,118 @@ +package org.metricshub.ipmi.core.connection.queue; + +import static org.junit.jupiter.api.Assertions.assertEquals; +import static org.junit.jupiter.api.Assertions.assertFalse; +import static org.junit.jupiter.api.Assertions.assertTrue; + +import java.util.Arrays; +import java.util.Collections; +import java.util.List; +import java.util.concurrent.CopyOnWriteArrayList; + +import org.junit.jupiter.api.Test; +import org.metricshub.ipmi.core.coding.PayloadCoder; +import org.metricshub.ipmi.core.coding.commands.IpmiVersion; +import org.metricshub.ipmi.core.coding.commands.ResponseData; +import org.metricshub.ipmi.core.coding.commands.session.GetChannelAuthenticationCapabilities; +import org.metricshub.ipmi.core.coding.payload.IpmiPayload; +import org.metricshub.ipmi.core.coding.payload.lan.IpmiLanMessage; +import org.metricshub.ipmi.core.coding.security.CipherSuite; +import org.metricshub.ipmi.core.connection.Connection; +import org.metricshub.ipmi.core.connection.ConnectionListener; +import org.metricshub.ipmi.core.transport.SilentMessenger; + +class MessageQueueTest { + + private static final int TIMEOUT_MS = 100; + + /** Longer than the timeout plus the 500 ms cleaning period of the queue timer. */ + private static final int TIMER_TICK_MS = 800; + + private static final int WINDOW_SIZE = 8; + + private final Connection connection = new Connection(new SilentMessenger(), 0); + + /** "tag:message" of every timeout reported to the listeners. */ + private final List reported = new CopyOnWriteArrayList<>(); + + private MessageQueue newQueue() { + return new MessageQueue( + connection, + TIMEOUT_MS, + IpmiLanMessage.MIN_SEQUENCE_NUMBER, + IpmiLanMessage.MAX_SEQUENCE_NUMBER); + } + + private static PayloadCoder request() { + return new GetChannelAuthenticationCapabilities(IpmiVersion.V20, IpmiVersion.V20, CipherSuite.getEmpty()); + } + + private ConnectionListener recorder() { + return new ConnectionListener() { + @Override + public void processResponse(ResponseData responseData, int handle, int tag, Exception exception) { + reported.add(tag + ":" + exception.getMessage()); + } + + @Override + public void processRequest(IpmiPayload payload) { + // not used + } + }; + } + + @Test + void timedOutMessageLeavesTheQueueAtOnceAndIsReportedOnce() throws Exception { + MessageQueue queue = newQueue(); + try { + connection.registerListener(recorder()); + + int tag = queue.add(request()); + assertTrue(queue.containsId(tag)); + + Thread.sleep(TIMEOUT_MS + 50); + queue.run(); + + assertEquals(Collections.singletonList(tag + ":Message timed out"), reported); + assertFalse(queue.containsId(tag), "a timed-out message must not linger in the queue"); + + // The window is free: a full window of new messages is accepted without waiting + for (int i = 0; i < WINDOW_SIZE; i++) { + assertTrue(queue.add(request()) > 0, "add " + i); + } + queue.run(); + assertEquals(1, reported.size(), "a timeout must be reported once"); + } finally { + queue.tearDown(); + } + } + + @Test + void timerSurvivesAListenerThatThrows() throws Exception { + MessageQueue queue = newQueue(); + try { + connection.registerListener(recorder()); + connection.registerListener(new ConnectionListener() { + @Override + public void processResponse(ResponseData responseData, int handle, int tag, Exception exception) { + throw new IllegalStateException("listener failure"); + } + + @Override + public void processRequest(IpmiPayload payload) { + // not used + } + }); + + int first = queue.add(request()); + Thread.sleep(TIMER_TICK_MS); // expired by the timer thread, whose notification throws + + int second = queue.add(request()); + Thread.sleep(TIMER_TICK_MS); // only a live timer thread can expire this one + + assertEquals(Arrays.asList(first + ":Message timed out", second + ":Message timed out"), reported); + } finally { + queue.tearDown(); + } + } +} diff --git a/src/test/java/org/metricshub/ipmi/core/transport/SilentMessenger.java b/src/test/java/org/metricshub/ipmi/core/transport/SilentMessenger.java new file mode 100644 index 0000000..208f75e --- /dev/null +++ b/src/test/java/org/metricshub/ipmi/core/transport/SilentMessenger.java @@ -0,0 +1,27 @@ +package org.metricshub.ipmi.core.transport; + +/** + * A {@link Messenger} that sends nothing and never delivers anything: stands in for a BMC that does not answer. + */ +public class SilentMessenger implements Messenger { + + @Override + public void send(UdpMessage message) { + // dropped + } + + @Override + public void register(UdpListener listener) { + // nothing will ever be delivered + } + + @Override + public void unregister(UdpListener listener) { + // nothing to do + } + + @Override + public void closeConnection() { + // nothing to do + } +}