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 + } +}