From b7fad4614db37bc9f72b3d622fc708d15bdde5e9 Mon Sep 17 00:00:00 2001 From: "Michael N. Lipp" Date: Tue, 29 Apr 2025 14:02:12 +0200 Subject: [PATCH] Improve debug messages. --- .../runner/qemu/GuestAgentClient.java | 16 ++++++----- .../vmoperator/runner/qemu/QemuMonitor.java | 25 ++++++++++------- .../runner/qemu/VmopAgentClient.java | 27 +++++++++++++------ .../runner/qemu/events/MonitorEvent.java | 18 +++++++++++++ .../runner/qemu/events/OsinfoEvent.java | 19 +++++++++++++ 5 files changed, 81 insertions(+), 24 deletions(-) diff --git a/org.jdrupes.vmoperator.runner.qemu/src/org/jdrupes/vmoperator/runner/qemu/GuestAgentClient.java b/org.jdrupes.vmoperator.runner.qemu/src/org/jdrupes/vmoperator/runner/qemu/GuestAgentClient.java index b0001e4..45d2487 100644 --- a/org.jdrupes.vmoperator.runner.qemu/src/org/jdrupes/vmoperator/runner/qemu/GuestAgentClient.java +++ b/org.jdrupes.vmoperator.runner.qemu/src/org/jdrupes/vmoperator/runner/qemu/GuestAgentClient.java @@ -69,14 +69,14 @@ public class GuestAgentClient extends AgentConnector { */ @Override protected void agentConnected() { - logger.fine(() -> "guest agent connected"); + logger.fine(() -> "Guest agent connected"); connected = true; rep().fire(new GuestAgentCommand(new QmpGuestGetOsinfo())); } @Override protected void agentDisconnected() { - logger.fine(() -> "guest agent disconnected"); + logger.fine(() -> "Guest agent disconnected"); connected = false; } @@ -88,15 +88,16 @@ public class GuestAgentClient extends AgentConnector { */ @Override protected void processInput(String line) throws IOException { - logger.fine(() -> "guest agent(in): " + line); + logger.finer(() -> "guest agent(in): " + line); try { var response = mapper.readValue(line, ObjectNode.class); if (response.has("return") || response.has("error")) { QmpCommand executed = executing.poll(); - logger.fine(() -> String.format("(Previous \"guest agent(in)\"" + logger.finer(() -> String.format("(Previous \"guest agent(in)\"" + " is result from executing %s)", executed)); if (executed instanceof QmpGuestGetOsinfo) { var osInfo = new OsinfoEvent(response.get("return")); + logger.fine(() -> "Guest agent triggers: " + osInfo); rep().fire(osInfo); } } @@ -120,10 +121,11 @@ public class GuestAgentClient extends AgentConnector { return; } var command = event.command(); - logger.fine(() -> "guest agent(out): " + command.toString()); + logger.fine(() -> "Guest handles: " + event); String asText; try { asText = command.asText(); + logger.finer(() -> "guest agent(out): " + asText); } catch (JsonProcessingException e) { logger.log(Level.SEVERE, e, () -> "Cannot serialize Json: " + e.getMessage()); @@ -163,8 +165,8 @@ public class GuestAgentClient extends AgentConnector { } event.suspendHandling(); suspendedStop = event; - logger.fine(() -> "Sending powerdown command, waiting for" - + " termination until " + waitUntil); + logger.fine(() -> "Attempting shutdown through guest agent," + + " waiting for termination until " + waitUntil); powerdownTimer = Components.schedule(t -> { logger.fine(() -> "Powerdown timeout reached."); synchronized (this) { diff --git a/org.jdrupes.vmoperator.runner.qemu/src/org/jdrupes/vmoperator/runner/qemu/QemuMonitor.java b/org.jdrupes.vmoperator.runner.qemu/src/org/jdrupes/vmoperator/runner/qemu/QemuMonitor.java index 6be7603..e844bc4 100644 --- a/org.jdrupes.vmoperator.runner.qemu/src/org/jdrupes/vmoperator/runner/qemu/QemuMonitor.java +++ b/org.jdrupes.vmoperator.runner.qemu/src/org/jdrupes/vmoperator/runner/qemu/QemuMonitor.java @@ -108,24 +108,30 @@ public class QemuMonitor extends QemuConnector { @Override protected void processInput(String line) throws IOException { - logger.fine(() -> "monitor(in): " + line); + logger.finer(() -> "monitor(in): " + line); try { var response = mapper.readValue(line, ObjectNode.class); if (response.has("QMP")) { monitorReady = true; + logger.fine(() -> "QMP connection ready"); rep().fire(new MonitorReady()); return; } if (response.has("return") || response.has("error")) { QmpCommand executed = executing.poll(); - logger.fine( + logger.finer( () -> String.format("(Previous \"monitor(in)\" is result " + "from executing %s)", executed)); - rep().fire(MonitorResult.from(executed, response)); + var monRes = MonitorResult.from(executed, response); + logger.fine(() -> "QMP triggers: " + monRes); + rep().fire(monRes); return; } if (response.has("event")) { - MonitorEvent.from(response).ifPresent(rep()::fire); + MonitorEvent.from(response).ifPresent(me -> { + logger.fine(() -> "QMP triggers: " + me); + rep().fire(me); + }); } } catch (JsonProcessingException e) { throw new IOException(e); @@ -141,7 +147,7 @@ public class QemuMonitor extends QemuConnector { public void onClosed(Closed event, SocketIOChannel channel) { channel.associated(this, getClass()).ifPresent(qm -> { super.onClosed(event, channel); - logger.finer(() -> "QMP socket closed."); + logger.fine(() -> "QMP connection closed."); monitorReady = false; }); } @@ -158,7 +164,7 @@ public class QemuMonitor extends QemuConnector { public void onMonitorCommand(MonitorCommand event) throws IOException { // Check prerequisites if (!monitorReady && !(event.command() instanceof QmpCapabilities)) { - logger.severe(() -> "Premature monitor command (not ready): " + logger.severe(() -> "Premature QMP command (not ready): " + event.command()); rep().fire(new Stop()); return; @@ -166,10 +172,11 @@ public class QemuMonitor extends QemuConnector { // Send the command var command = event.command(); - logger.fine(() -> "monitor(out): " + command.toString()); + logger.fine(() -> "QMP handles: " + event.toString()); String asText; try { asText = command.asText(); + logger.finer(() -> "monitor(out): " + asText); } catch (JsonProcessingException e) { logger.log(Level.SEVERE, e, () -> "Cannot serialize Json: " + e.getMessage()); @@ -192,8 +199,8 @@ public class QemuMonitor extends QemuConnector { @SuppressWarnings("PMD.AvoidSynchronizedStatement") public void onStop(Stop event) { if (!monitorReady) { - logger.fine(() -> "No QMP connection," - + " cannot send powerdown command"); + logger.fine(() -> "Not sending QMP powerdown command" + + " because QMP connection is closed"); return; } diff --git a/org.jdrupes.vmoperator.runner.qemu/src/org/jdrupes/vmoperator/runner/qemu/VmopAgentClient.java b/org.jdrupes.vmoperator.runner.qemu/src/org/jdrupes/vmoperator/runner/qemu/VmopAgentClient.java index f50d397..cac41d4 100644 --- a/org.jdrupes.vmoperator.runner.qemu/src/org/jdrupes/vmoperator/runner/qemu/VmopAgentClient.java +++ b/org.jdrupes.vmoperator.runner.qemu/src/org/jdrupes/vmoperator/runner/qemu/VmopAgentClient.java @@ -59,10 +59,14 @@ public class VmopAgentClient extends AgentConnector { */ @Handler public void onVmopAgentLogIn(VmopAgentLogIn event) throws IOException { - logger.fine(() -> "vmop agent(out): login " + event.user()); if (writer().isPresent()) { + logger.fine(() -> "Vmop agent handles:" + event); executing.add(event); + logger.finer(() -> "vmop agent(out): login " + event.user()); sendCommand("login " + event.user()); + } else { + logger + .warning(() -> "No vmop agent connection for sending " + event); } } @@ -74,9 +78,10 @@ public class VmopAgentClient extends AgentConnector { */ @Handler public void onVmopAgentLogout(VmopAgentLogOut event) throws IOException { - logger.fine(() -> "vmop agent(out): logout"); if (writer().isPresent()) { + logger.fine(() -> "Vmop agent handles:" + event); executing.add(event); + logger.finer(() -> "vmop agent(out): logout"); sendCommand("logout"); } } @@ -85,23 +90,27 @@ public class VmopAgentClient extends AgentConnector { @SuppressWarnings({ "PMD.UnnecessaryReturn", "PMD.AvoidLiteralsInIfCondition" }) protected void processInput(String line) throws IOException { - logger.fine(() -> "vmop agent(in): " + line); + logger.finer(() -> "vmop agent(in): " + line); // Check validity if (line.isEmpty() || !Character.isDigit(line.charAt(0))) { - logger.warning(() -> "Illegal response: " + line); + logger.warning(() -> "Illegal vmop agent response: " + line); return; } // Check positive responses if (line.startsWith("220 ")) { - rep().fire(new VmopAgentConnected()); + var evt = new VmopAgentConnected(); + logger.fine(() -> "Vmop agent triggers " + evt); + rep().fire(evt); return; } if (line.startsWith("201 ")) { Event cmd = executing.pop(); if (cmd instanceof VmopAgentLogIn login) { - rep().fire(new VmopAgentLoggedIn(login)); + var evt = new VmopAgentLoggedIn(login); + logger.fine(() -> "Vmop agent triggers " + evt); + rep().fire(evt); } else { logger.severe(() -> "Response " + line + " does not match executing command " + cmd); @@ -111,7 +120,9 @@ public class VmopAgentClient extends AgentConnector { if (line.startsWith("202 ")) { Event cmd = executing.pop(); if (cmd instanceof VmopAgentLogOut logout) { - rep().fire(new VmopAgentLoggedOut(logout)); + var evt = new VmopAgentLoggedOut(logout); + logger.fine(() -> "Vmop agent triggers " + evt); + rep().fire(evt); } else { logger.severe(() -> "Response " + line + "does not match executing command " + cmd); @@ -125,7 +136,7 @@ public class VmopAgentClient extends AgentConnector { } // Error - logger.warning(() -> "Error response: " + line); + logger.warning(() -> "Error response from vmop agent: " + line); executing.pop(); } diff --git a/org.jdrupes.vmoperator.runner.qemu/src/org/jdrupes/vmoperator/runner/qemu/events/MonitorEvent.java b/org.jdrupes.vmoperator.runner.qemu/src/org/jdrupes/vmoperator/runner/qemu/events/MonitorEvent.java index e35a172..6663fa4 100644 --- a/org.jdrupes.vmoperator.runner.qemu/src/org/jdrupes/vmoperator/runner/qemu/events/MonitorEvent.java +++ b/org.jdrupes.vmoperator.runner.qemu/src/org/jdrupes/vmoperator/runner/qemu/events/MonitorEvent.java @@ -20,6 +20,8 @@ package org.jdrupes.vmoperator.runner.qemu.events; import com.fasterxml.jackson.databind.JsonNode; import java.util.Optional; +import org.jgrapes.core.Channel; +import org.jgrapes.core.Components; import org.jgrapes.core.Event; /** @@ -112,4 +114,20 @@ public class MonitorEvent extends Event { public JsonNode data() { return data; } + + /* + * (non-Javadoc) + * + * @see java.lang.Object#toString() + */ + @Override + public String toString() { + StringBuilder builder = new StringBuilder(); + builder.append(Components.objectName(this)).append(" [").append(data); + if (channels() != null) { + builder.append(", channels=").append(Channel.toString(channels())); + } + builder.append(']'); + return builder.toString(); + } } diff --git a/org.jdrupes.vmoperator.runner.qemu/src/org/jdrupes/vmoperator/runner/qemu/events/OsinfoEvent.java b/org.jdrupes.vmoperator.runner.qemu/src/org/jdrupes/vmoperator/runner/qemu/events/OsinfoEvent.java index 294ac7b..0e90019 100644 --- a/org.jdrupes.vmoperator.runner.qemu/src/org/jdrupes/vmoperator/runner/qemu/events/OsinfoEvent.java +++ b/org.jdrupes.vmoperator.runner.qemu/src/org/jdrupes/vmoperator/runner/qemu/events/OsinfoEvent.java @@ -19,6 +19,8 @@ package org.jdrupes.vmoperator.runner.qemu.events; import com.fasterxml.jackson.databind.JsonNode; +import org.jgrapes.core.Channel; +import org.jgrapes.core.Components; import org.jgrapes.core.Event; /** @@ -40,4 +42,21 @@ public class OsinfoEvent extends Event { public JsonNode osinfo() { return osinfo; } + + /* + * (non-Javadoc) + * + * @see java.lang.Object#toString() + */ + @Override + public String toString() { + StringBuilder builder = new StringBuilder(); + builder.append(Components.objectName(this)).append(" [") + .append(osinfo); + if (channels() != null) { + builder.append(", channels=").append(Channel.toString(channels())); + } + builder.append(']'); + return builder.toString(); + } }