From a990bd47ab53702be8d005fcde4ddc3eb2bcc6bf Mon Sep 17 00:00:00 2001 From: nmbro Date: Fri, 28 Aug 2026 00:36:07 +0200 Subject: [PATCH 01/11] fix(apcmicrolink): async USB reads and stability Long-run testing of the USB HID tunnel transport against an SCL500RMI1UC found the driver dropping the session after an inconsistent interval and then failing to recover. Several distinct causes, fixed together here: * The interrupt-IN read was issued per call, so the driver only listened while it happened to be blocked waiting for a reply. This device can go several seconds between replies, and pushes unrelated HID reports on the same pipe meanwhile, so replies arriving outside that window were lost. Reads are now served by a permanently outstanding asynchronous transfer serviced by a dedicated pump thread; only that thread touches libusb's event loop, and everything else takes a lock to drain the queue it fills. Builds without libusb-1.0 or pthreads, and any failure to start the listener, still use the previous synchronous per-call read. This needs the libusb-1.0 context, exposed as nut_libusb_get_context(). * A USB bus reset was triggered off a retry count, which fired just as often for a live-but-stalled device that a reset never helped. It is now triggered only when a read, write or transfer completion has actually reported NO_DEVICE, i.e. a genuine unplug or power cycle. * The cached page 0 contents were wiped on every session (re)start, and the read queue was flushed on every session retry - the latter discarding genuine replies that had already arrived. Neither is done any more. * The authentication challenge was a fixed 0x00 0x00, making the exchange trivially predictable; it is now randomized, as APC's own client does. * When the kernel's usbhid driver reclaims the interface, every submission fails instantly with EBUSY and nothing paced the retries - one observed incident spun at roughly 14,000 failed submissions per second for over half an hour. That case now backs off and logs, rate-limited. * Warn once when built against libusb-0.1, whose interrupt-IN read did not honor its timeout on at least one tested system, hanging the driver. Also maps two further descriptor usages that were previously visible only as microlink.unmapped.*: experimental.battery.serial (the battery pack's own serial, confirmed against the compartment label on a real unit) and microlink.diag.slave_password_echo (the register the auth challenge is written to, echoed back - useful for troubleshooting, but not by itself proof that authentication was accepted). The apcmicrolink(8) USB MODE section is updated to match: it described a periodic reset attempt whenever the tunnel stayed unresponsive, which is no longer what happens, and now also notes the usbhid/EBUSY backoff. It gains a "libusb backend" subsection recording that USB mode is tested only against libusb-1.0, what goes wrong on libusb-0.1, and that the always-listening reader needs libusb-1.0 plus pthreads. Comments in apcmicrolink-usb.c were trimmed throughout: design history, references to material outside this repository, and restatements of what the code already says are gone. Use of coding helper tools and AI disclosed: Claude Code was used for development assistance. Signed-off-by: nmbro --- NEWS.adoc | 16 + docs/man/apcmicrolink.txt | 29 +- drivers/apcmicrolink-maps.c | 14 + drivers/apcmicrolink-usb.c | 826 ++++++++++++++++++++++++++++++------ drivers/apcmicrolink-usb.h | 10 +- drivers/apcmicrolink.c | 219 ++++++++-- drivers/apcmicrolink.h | 11 + drivers/libusb1.c | 11 + drivers/nut_libusb.h | 6 + 9 files changed, 960 insertions(+), 182 deletions(-) diff --git a/NEWS.adoc b/NEWS.adoc index 8da073ce8e..f03e8d61e1 100644 --- a/NEWS.adoc +++ b/NEWS.adoc @@ -89,6 +89,22 @@ https://github.com/networkupstools/nut/milestone/13 (`outlet.group.N.load.*`, `outlet.group.N.shutdown.*`), and the `outlet.group.N.switchable` variable to distinguish switchable groups from an unswitched main bank. + * USB mode: reworked the interrupt-IN read path to use a permanently + outstanding asynchronous transfer serviced by a dedicated thread, so + device replies are no longer missed while the driver is between + polls. Several long-run stability fixes go with it: a USB bus reset + is now triggered only on a genuine disconnect rather than on a retry + count, the cached page 0 contents are no longer wiped on every + session (re)start, the read queue is no longer flushed on every + session retry, and the authentication challenge is randomized. + Also warns once when built against the untested libusb-0.1 backend, + and backs off instead of spinning when the kernel's `usbhid` driver + has reclaimed the interface. + * Mapped two further descriptor usages: + `experimental.battery.serial` (the battery pack's own serial number, + distinct from `ups.serial`) and `microlink.diag.slave_password_echo` + (auth troubleshooting visibility only, not proof that + authentication was accepted). - `apc_modbus` driver updates: * Fixed string join not doing zero termination. [PR #3413] diff --git a/docs/man/apcmicrolink.txt b/docs/man/apcmicrolink.txt index 185ad0076a..a7584c2ca0 100644 --- a/docs/man/apcmicrolink.txt +++ b/docs/man/apcmicrolink.txt @@ -202,9 +202,28 @@ starts up anyway using those for `ups.status`/`battery.charge`/ `battery.runtime` (see the `hid_fallback` option above) instead of refusing to start. Outlet-group data and instant commands, which depend on the full Microlink descriptor, become available automatically once the -tunnel connects -- no driver restart is needed. If the tunnel stays -unresponsive, the driver periodically attempts a USB device reset to try -to recover it. +tunnel connects, with no driver restart needed. If the device disappears +from the bus (unplug, power cycle), the driver resets and reopens it. It +does not reset a device that is still present but not answering the +tunnel, because that does not help. + +libusb backend +~~~~~~~~~~~~~~ + +USB mode has only been tested against libusb-1.0. Builds against +libusb-0.1 log a warning once at startup and then carry on, but that +path is untested for this driver. On at least one system the installed +libusb-0.1 library's interrupt IN read ignored its configured timeout, +so the driver hung waiting for a reply instead of timing out and +retrying. If USB mode stops responding, check that NUT was built with +`--with-usb=libusb-1.0` before looking further. + +With libusb-1.0 and pthreads the driver keeps one read request +outstanding on a dedicated thread, so it picks up a reply whenever the +device sends one. Without both, it reads only while already waiting for +a reply. The tested device can take several seconds to answer and pushes +unrelated reports on the same pipe meanwhile, so replies that arrive +outside that window are missed. Kernel usbhid conflict ~~~~~~~~~~~~~~~~~~~~~~ @@ -216,7 +235,9 @@ cannot claim it and will fail to start; and if `usbhid` reclaims the interface after a USB reset or re-enumeration event *while this driver is already running* (observed on the tested hardware), every following interrupt transfer this driver attempts will be rejected by the kernel -until the driver process is restarted. +until the driver process is restarted. The driver detects this, logs a +warning, and backs off between attempts instead of retrying at full +speed. It cannot recover on its own. Neither this driver nor NUT's shared USB layer (`nut_libusb.c`) attempts to detach `usbhid` on its own. A udev rule that unbinds `usbhid` from the diff --git a/drivers/apcmicrolink-maps.c b/drivers/apcmicrolink-maps.c index 21a788fd19..462209c396 100644 --- a/drivers/apcmicrolink-maps.c +++ b/drivers/apcmicrolink-maps.c @@ -200,6 +200,11 @@ const microlink_desc_value_map_t microlink_desc_value_map[] = { MLINK_DESC_FIXED_POINT, MLINK_DESC_UNSIGNED, 0, MLINK_DESC_RO, MLINK_NAME_INDEX_NONE, NULL }, { "2:4.5.42", "experimental.battery.sku", MLINK_DESC_STRING, MLINK_DESC_UNSIGNED, 0, MLINK_DESC_RO, MLINK_NAME_INDEX_NONE, NULL }, + /* Battery pack serial (distinct from battery.sku's part number and + * the chassis's ups.serial/device.serial at 2:4.9.40). Verified + * against the physical battery label on a real unit - exact match. */ + { "2:4.5.9.40", "experimental.battery.serial", + MLINK_DESC_STRING, MLINK_DESC_UNSIGNED, 0, MLINK_DESC_RO, MLINK_NAME_INDEX_NONE, NULL }, { "2:4.5.48", "battery.date", MLINK_DESC_DATE, MLINK_DESC_UNSIGNED, 0, MLINK_DESC_RW, MLINK_NAME_INDEX_NONE, NULL }, { "2:4.5.74", "battery.lifetime.status", MLINK_DESC_BITFIELD_MAP, MLINK_DESC_UNSIGNED, 0, MLINK_DESC_RO, MLINK_NAME_INDEX_NONE, battery_lifetime_status_map }, @@ -275,6 +280,15 @@ const microlink_desc_value_map_t microlink_desc_value_map[] = { MLINK_DESC_FIXED_POINT, MLINK_DESC_UNSIGNED, 0, MLINK_DESC_RO, MLINK_NAME_INDEX_NONE, NULL }, { "2:4.F.69", "experimental.statistics.ups.totaltime", MLINK_DESC_FIXED_POINT, MLINK_DESC_UNSIGNED, 0, MLINK_DESC_RO, MLINK_NAME_INDEX_NONE, NULL }, + + /* Internal protocol state, not telemetry - hence microlink.diag, not + * ups/battery/experimental. MLINK_DESC_SLAVE_PASSWORD: the register + * microlink_authenticate() writes its random SPC challenge to. Device + * echoes back whatever was last written (verified across 4 restarts, + * 4 different challenges) - useful for auth debugging, but NOT proof + * auth was accepted (a register that echoes any write looks the same). */ + { "2:4.8.5", "microlink.diag.slave_password_echo", + MLINK_DESC_HEX, MLINK_DESC_UNSIGNED, 0, MLINK_DESC_RO, MLINK_NAME_INDEX_NONE, NULL }, }; const size_t microlink_desc_value_map_count = diff --git a/drivers/apcmicrolink-usb.c b/drivers/apcmicrolink-usb.c index d4b1afd405..2e0192ee84 100644 --- a/drivers/apcmicrolink-usb.c +++ b/drivers/apcmicrolink-usb.c @@ -1,38 +1,24 @@ /* apcmicrolink-usb.c - USB HID tunnel transport for the APC Microlink protocol driver * - * The SCL500RMI1UC (and presumably other USB-only Microlink devices) has no - * serial port; it exposes the same Microlink byte protocol that - * apcmicrolink.c already speaks over RS232, tunneled instead through two - * HID vendor-page reports on the generic APC HID vendor tunnel (the same - * one apc_modbus.c uses for Modbus-RTU-over-USB): + * USB-only Microlink devices (e.g. the SCL500RMI1UC) have no serial port; + * they carry the same Microlink byte protocol that apcmicrolink.c speaks over + * RS232, tunneled through two HID vendor page 0xFF86 reports on the generic + * APC HID vendor tunnel (the one apc_modbus.c uses for Modbus-RTU-over-USB): + * usage 0xFC for host->device writes, usage 0xFD for device->host reads. The + * Report IDs behind them are discovered from the device's HID report + * descriptor, as in apc_modbus.c's _apc_modbus_usb_callback(). * - * - Output Report (host->device writes), HID vendor page 0xFF86 usage - * 0xFC. Confirmed live as Report ID 0x90 on the SCL500RMI1UC. - * - Input Report (device->host reads), HID vendor page 0xFF86 usage - * 0xFD. Confirmed live as Report ID 0x89 on the SCL500RMI1UC. + * Only the "send N bytes" / "read next available byte" primitives are replaced + * here; apcmicrolink.c's framing, checksums, object cache, descriptor parser, + * auth and outlet-group logic are unaware of which transport is underneath. * - * Report IDs are discovered dynamically from the device's HID report - * descriptor (they could differ on other devices/firmware revisions), - * mirroring apc_modbus.c's _apc_modbus_usb_callback(). - * - * This file only replaces the "send N bytes" / "read next available byte" - * primitives that apcmicrolink.c's microlink_send_simple()/ - * microlink_send_write()/microlink_receive_once() sit on top of; the frame - * construction, checksum, object cache, descriptor parser, auth and - * outlet-group logic in apcmicrolink.c are untouched and unaware of which - * transport is underneath. - * - * A background-thread reader (keeping a read continuously pending on the - * interrupt IN endpoint, decoupled from write timing, mirroring the real - * Windows driver's design) was tried here to see if it would improve this - * device's occasionally-slow-to-respond behavior. A controlled A/B test - * (two minimal standalone libusb programs, byte-identical 0xFD/0xFE - * sequence, one threaded one not) showed the threaded version getting - * *zero* successful replies over 10s while the sequential version got - * several - a clear regression, not an improvement, likely from libusb's - * synchronous API serializing event-handling between the two threads and - * delaying the write. Reverted; this file is back to the simple - * synchronous write-then-read design that is confirmed working. + * On libusb-1.0 + pthread builds, reads are served by an always-outstanding + * async interrupt-IN transfer serviced by a dedicated pump thread: the device + * can go several seconds between replies, and a synchronous read only listens + * while the driver happens to be blocked waiting on one. Only the pump thread + * may call libusb_handle_events*() on this context. Builds without libusb-1.0 + * or pthreads, and any failure to start the listener, fall back to a + * synchronous per-call read (microlink_usb_get_char_sync()). * * Copyright (C) * 2026 Lukas Schmid @@ -50,37 +36,36 @@ #include #include #include +#include +#ifdef HAVE_PTHREAD +#include +#endif /* HAVE_PTHREAD */ #include "nut_stdint.h" #include "nut_libusb.h" #include "usb-common.h" #include "hidparser.h" +#include "strcasestr-static.h" +#include "apcmicrolink.h" #include "apcmicrolink-usb.h" /* American Power Conversion */ #define APC_VENDORID 0x051d -/* HID vendor page 0xFF86, usages 0xFC (host->device) / 0xFD (device->host) - - * the same generic raw-byte HID tunnel apc_modbus.c's - * modbus_rtu_usb_usage_rx/tx use for Modbus-RTU-over-USB. Numerically - * identical usages, different upper protocol riding over them. */ +/* HID vendor page 0xFF86, usages 0xFC (host->device) / 0xFD (device->host): + * the same raw-byte tunnel apc_modbus.c rides Modbus-RTU over. */ static const HIDNode_t mlink_usb_usage_out = 0xff8600fcUL; static const HIDNode_t mlink_usb_usage_in = 0xff8600fdUL; -/* Report IDs behind those usages, discovered per-device at open time. - * Expected to be 0x90 (out) / 0x89 (in) on the SCL500RMI1UC, but never - * hardcoded - other devices/firmware could number them differently. */ +/* Report IDs behind those usages, discovered per-device at open time. */ static int mlink_report_out = 0; static int mlink_report_in = 0; -/* Standard HID Power/Battery System Page usages behind the "foreign" - * background reports this device also pushes on the same interrupt pipe, - * independent of the Microlink tunnel's health - confirmed live against - * this exact device (report descriptor walk + a real usbhid-ups side by - * side run). Looked up by usage rather than assumed to be at fixed report - * IDs/offsets, same as mlink_usb_usage_out/in above - a firmware revision - * or a different "5G model" device could number/order these differently. */ +/* Standard HID Power/Battery System Page usages, carried by the background + * reports this device also pushes on the same interrupt pipe independent of + * the Microlink tunnel's health. Looked up by usage rather than assumed to be + * at fixed report IDs/offsets, same as the tunnel usages above. */ static const HIDNode_t hid_usage_charging = 0x00850044UL; static const HIDNode_t hid_usage_discharging = 0x00850045UL; static const HIDNode_t hid_usage_ac_present = 0x008500D0UL; @@ -101,8 +86,8 @@ static hid_fallback_field_t ff_below_rcl; static hid_fallback_field_t ff_remaining_capacity; static hid_fallback_field_t ff_runtime_to_empty; -/* Latest opportunistically-decoded fallback snapshot. fb_last_update==0 - * means "nothing decoded yet this session". */ +/* Latest opportunistically decoded fallback snapshot; fb_last_update == 0 + * means nothing decoded yet this session. */ static int fb_ac_present = 0; static int fb_discharging = 0; static int fb_below_rcl = 0; @@ -110,14 +95,10 @@ static long fb_battery_charge = -1; static long fb_battery_runtime = -1; static time_t fb_last_update = 0; -/* Confirmed live: Output/Input report Byte Length 64 (1 Report ID byte + - * 63 bytes of value data, BitSize=8 Count=63 on both sides). */ +/* Output/Input reports are 64 bytes: 1 Report ID byte + 63 data bytes. */ #define MLINK_USB_REPORT_PAYLOAD_LEN 63U #define MLINK_USB_REPORT_TOTAL_LEN (1U + MLINK_USB_REPORT_PAYLOAD_LEN) -/* The decompiled Windows driver used a 400ms timeout for Output report - * writes (ApcUsb_ul.dll, writeMultiByteMessage/writeSingleByteCommand); - * kept a bit more generous here since we are not racing a UI. */ #define MLINK_USB_WRITE_TIMEOUT_MS 1000U static usb_dev_handle *udev = NULL; @@ -125,22 +106,174 @@ static USBDevice_t curDevice; static USBDeviceMatcher_t *regex_matcher = NULL; static usb_communication_subdriver_t *comm_driver = &usb_subdriver; +/* Set when a read, write or transfer completion reports NO_DEVICE: a genuine + * physical disconnect, not just "no reply yet". Cleared once + * microlink_usb_open() succeeds again. apcmicrolink.c polls this to decide + * when a USB reset-and-reopen is actually warranted. */ +static int usb_device_gone = 0; + +#if WITH_LIBUSB_1_0 && defined(HAVE_PTHREAD) +/* Always-outstanding async interrupt-IN listener, serviced by a dedicated pump + * thread: one libusb_transfer is kept permanently submitted, and its callback + * (running on the pump thread) queues completed reports here and resubmits + * itself. */ +#define MLINK_USB_ASYNC_QUEUE_LEN 8U + +typedef struct { + unsigned char data[MLINK_USB_REPORT_TOTAL_LEN]; + size_t len; +} microlink_async_report_t; + +/* The transfer buffer is heap-allocated per instance: an abandoned transfer + * (see microlink_usb_async_stop()) has to be left to free itself, so a + * listener started in the meantime must not be sharing that buffer. */ +static struct libusb_transfer *async_xfer = NULL; +static int async_xfer_active = 0; /* 1 while a transfer is submitted/outstanding */ + +/* The queue, async_xfer_active and the fb_* globals are touched by both the + * pump thread and the main thread, so all go through async_lock. async_cond is + * signalled whenever the callback queues a report, so get_char() can block on + * it instead of polling. */ +static pthread_mutex_t async_lock = PTHREAD_MUTEX_INITIALIZER; +static pthread_cond_t async_cond = PTHREAD_COND_INITIALIZER; + +static microlink_async_report_t async_queue[MLINK_USB_ASYNC_QUEUE_LEN]; +static unsigned int async_queue_head = 0; /* next slot to pop */ +static unsigned int async_queue_count = 0; /* valid entries currently queued */ + +/* Keeps libusb's event loop serviced so the outstanding transfer is reaped and + * resubmitted promptly. */ +static pthread_t async_pump_tid; +static volatile int async_pump_stop = 0; + +/* Defined below microlink_usb_try_decode_fallback(), which the transfer + * callback calls. */ +static int microlink_usb_async_start(void); +static void microlink_usb_async_stop(void); +#endif /* WITH_LIBUSB_1_0 && HAVE_PTHREAD */ + static unsigned char in_report[MLINK_USB_REPORT_TOTAL_LEN]; static size_t in_report_len = 0; /* bytes valid in in_report (0 = empty) */ static size_t in_report_pos = 0; /* next unconsumed index */ static usb_device_id_t apcmicrolink_usb_device_table[] = { - /* SCL500RMI1UC, confirmed live (VID/PID + product string - * "Smart-UPS 500 FW:UPS 15.6 / ID=1036"). Also already recognized - * by apc-hid.c's generic apc_usb_device_table ("various 5G models") - - * expected overlap, same as apc_modbus vs. usbhid-ups for several - * Smart-UPS models; the user picks whichever driver suits them. */ + /* SCL500RMI1UC. Also matched by apc-hid.c's generic APC table ("various 5G + * models") - expected overlap, same as apc_modbus vs. usbhid-ups for several + * Smart-UPS models. */ { USB_DEVICE(APC_VENDORID, 0x0003), NULL }, /* Terminating entry */ { 0, 0, NULL } }; +/* Common USB-to-serial bridge chips. A match here on "port=auto" means the + * right cable, wrong driver mode: use this driver's serial transport against + * the /dev/ttyUSB*|COM* node the adapter created instead. */ +static const struct { + uint16_t vendorid; + uint16_t productid; + const char *name; +} known_usb_serial_bridges[] = { + { 0x0403, 0x6001, "FTDI FT232R" }, + { 0x0403, 0x6014, "FTDI FT232H" }, + { 0x0403, 0x6015, "FTDI FT230X" }, + { 0x067b, 0x2303, "Prolific PL2303" }, + /* Also a legitimate UPS VID/PID for nutdrv_qx (see + * scripts/udev/nut-usbups.rules.in) - only the Product string heuristic + * below can tell the two uses apart. */ + { 0x1a86, 0x7523, "WCH CH340/CH341" }, + { 0x10c4, 0xea60, "Silicon Labs CP2102/CP2109" }, + { 0x10c4, 0xea70, "Silicon Labs CP2105" }, + { 0x10c4, 0xea71, "Silicon Labs CP2108" }, +}; + +/* Lower-confidence signal for chips not in the table above: USB-serial bridges + * almost always name the chip or say "serial"/"UART" in their Product string, + * which a Microlink device's ("Smart-UPS ...") never does. */ +static const char *serial_bridge_product_keywords[] = { + "FTDI", "FT232", "FT231", "FT230", + "PL2303", "PROLIFIC", + "CH340", "CH341", + "CP210", "CP2102", "CP2105", "CP2108", + "USB SERIAL", "USB-SERIAL", "USB TO SERIAL", "UART BRIDGE", +}; + +/* Returns a short chip description if `device` looks like a generic + * USB-to-serial bridge rather than a Microlink-over-USB-HID device, NULL + * otherwise. Heuristic. */ +static const char *microlink_usb_describe_serial_bridge(const USBDevice_t *device) +{ + size_t i; + + for (i = 0; i < SIZEOF_ARRAY(known_usb_serial_bridges); i++) { + if (device->VendorID == known_usb_serial_bridges[i].vendorid + && device->ProductID == known_usb_serial_bridges[i].productid + ) { + return known_usb_serial_bridges[i].name; + } + } + + if (device->Product != NULL) { + for (i = 0; i < SIZEOF_ARRAY(serial_bridge_product_keywords); i++) { + if (strcasestr(device->Product, serial_bridge_product_keywords[i]) != NULL) { + return device->Product; + } + } + } + + return NULL; +} + +/* Rate-limit the diagnostics below to once per (kind, VID:PID) per driver run: + * "port=auto" re-enumerates the whole USB bus on every reconnect, so an + * unrelated device left plugged in would otherwise warn on every cycle. */ +enum { + MLINK_USB_DIAG_SERIAL_BRIDGE = 1, /* known/likely USB-serial bridge chip */ + MLINK_USB_DIAG_NOT_A_UPS_HID = 2 /* HID device, but neither our tunnel nor HID-PDC */ +}; + +#define MLINK_USB_DIAG_WARNED_MAX 6U +static uint64_t mlink_usb_diag_warned[MLINK_USB_DIAG_WARNED_MAX]; +static size_t mlink_usb_diag_warned_count = 0; + +/* Returns nonzero the first time this (kind, vendorid, productid) is seen this + * run, zero on every repeat. */ +static int microlink_usb_diag_warn_once(int kind, uint16_t vendorid, uint16_t productid) +{ + uint64_t key = ((uint64_t)(unsigned int)kind << 32) | ((uint32_t)vendorid << 16) | productid; + size_t i; + + for (i = 0; i < mlink_usb_diag_warned_count; i++) { + if (mlink_usb_diag_warned[i] == key) { + return 0; + } + } + + if (mlink_usb_diag_warned_count < MLINK_USB_DIAG_WARNED_MAX) { + mlink_usb_diag_warned[mlink_usb_diag_warned_count++] = key; + } + return 1; +} + +static void microlink_usb_warn_serial_bridge_once(const USBDevice_t *device, const char *desc) +{ + if (!microlink_usb_diag_warn_once(MLINK_USB_DIAG_SERIAL_BRIDGE, + device->VendorID, device->ProductID) + ) { + return; + } + + upslogx(LOG_WARNING, + "microlink_usb: USB device %04x:%04x (%s) matched your USB " + "port/vendorid/productid settings, but looks like a generic " + "USB-to-serial adapter, not a Microlink-over-USB-HID device. " + "If your UPS has a serial Microlink port wired to this adapter, " + "configure this driver in serial mode instead: point \"port\" " + "at the /dev/ttyUSB*, /dev/ttyACM* or COM* device this adapter " + "created, and remove vendorid/productid/port=auto.", + device->VendorID, device->ProductID, desc); +} + static int microlink_usb_match(USBDevice_t *device, void *privdata) { NUT_UNUSED_VARIABLE(privdata); @@ -153,6 +286,12 @@ static int microlink_usb_match(USBDevice_t *device, void *privdata) case POSSIBLY_SUPPORTED: case NOT_SUPPORTED: default: + { + const char *bridge_desc = microlink_usb_describe_serial_bridge(device); + if (bridge_desc != NULL) { + microlink_usb_warn_serial_bridge_once(device, bridge_desc); + } + } return 0; } } @@ -163,10 +302,9 @@ static USBDeviceMatcher_t microlink_usb_device_matcher = { NULL }; -/* Called by comm_driver->open_dev() once a candidate device's HID report - * descriptor has been fetched. Parse it and pick out the Report IDs behind - * our two vendor-page usages, exactly as apc_modbus.c's - * _apc_modbus_usb_callback() does for its own pair of usages. */ +/* Called by comm_driver->open_dev() with a candidate device's HID report + * descriptor: pick out the Report IDs behind our two vendor-page usages, as + * apc_modbus.c's _apc_modbus_usb_callback() does for its own pair. */ static int microlink_usb_report_callback(usb_dev_handle *arg_udev, USBDevice_t *hd, usb_ctrl_charbuf rdbuf, usb_ctrl_charbufsize rdlen) { @@ -174,7 +312,6 @@ static int microlink_usb_report_callback(usb_dev_handle *arg_udev, USBDevice_t * size_t i; NUT_UNUSED_VARIABLE(arg_udev); - NUT_UNUSED_VARIABLE(hd); mlink_report_out = 0; mlink_report_in = 0; @@ -212,9 +349,8 @@ static int microlink_usb_report_callback(usb_dev_handle *arg_udev, USBDevice_t * continue; } - /* Only the autonomous Input variant is useful here - the - * duplicate Feature-report entries for the same usage would - * need an explicit GET_REPORT control transfer we never send. */ + /* Only the autonomous Input variant is useful here - the duplicate + * Feature entries would need a GET_REPORT we never send. */ if (item->Type != ITEM_INPUT) { continue; } @@ -251,8 +387,34 @@ static int microlink_usb_report_callback(usb_dev_handle *arg_udev, USBDevice_t * Free_ReportDesc(hid_desc); if (mlink_report_out == 0 || mlink_report_in == 0) { + int has_hid_pdc = (ff_ac_present.report_id != 0 && ff_discharging.report_id != 0); + upsdebugx(1, "microlink_usb: Microlink USB HID tunnel (vendor page 0xFF86, " "usages 0xFC/0xFD) not found on this device"); + + /* Neither our vendor tunnel nor standard HID Power Device usages: + * not a supported UPS HID interface at all. More reliable than + * matching an inevitably incomplete VID/PID list. */ + if (!has_hid_pdc + && microlink_usb_diag_warn_once(MLINK_USB_DIAG_NOT_A_UPS_HID, + hd->VendorID, hd->ProductID) + ) { + upslogx(LOG_WARNING, + "microlink_usb: USB device %04x:%04x (%s) exposes a HID " + "interface but has neither the Microlink vendor tunnel nor " + "standard HID Power Device usages - this does not look " + "like a supported UPS HID interface at all (untested, " + "probably-wrong-driver territory). It may be an unrelated " + "HID device, or a USB-to-serial adapter's incidental HID " + "interface. If your UPS has a serial Microlink port wired " + "through a USB-to-serial adapter, configure this driver " + "in serial mode instead: point \"port\" at the adapter's " + "/dev/ttyUSB*, /dev/ttyACM* or COM* device, and remove " + "vendorid/productid/port=auto.", + hd->VendorID, hd->ProductID, + hd->Product ? hd->Product : "unknown product"); + } + return -1; } @@ -272,6 +434,28 @@ int microlink_usb_open(void) char *regex_array[USBMATCHER_REGEXP_ARRAY_LIMIT]; int ret; +#if WITH_LIBUSB_0_1 + { + /* Not validated for this driver: on at least one tested system the + * installed libusb-0.1's interrupt-IN read did not honor its timeout, + * hanging the driver instead of timing out and retrying. Log once per + * process, not on every reconnect. */ + static int warned_libusb01 = 0; + + if (!warned_libusb01) { + warned_libusb01 = 1; + upslogx(LOG_WARNING, + "apcmicrolink: built against libusb-0.1 - this transport is " + "untested for this driver and has shown a real interrupt-IN " + "read timeout defect on at least one system, causing the " + "driver to hang rather than retry. libusb-1.0 is the " + "tested/supported USB backend; if this driver becomes " + "unresponsive, rebuild NUT with --with-usb=libusb-1.0 " + "before investigating further."); + } + } +#endif /* WITH_LIBUSB_0_1 */ + warn_if_bad_usb_port_filename(device_path); regex_array[0] = getval("vendorid"); @@ -303,6 +487,7 @@ int microlink_usb_open(void) if (ret < 1) { fatalx(EXIT_FAILURE, "apcmicrolink: no matching USB Microlink UPS found"); } + usb_device_gone = 0; dstate_setinfo("ups.vendorid", "%04x", curDevice.VendorID); dstate_setinfo("ups.productid", "%04x", curDevice.ProductID); @@ -315,11 +500,22 @@ int microlink_usb_open(void) in_report_len = 0; in_report_pos = 0; +#if WITH_LIBUSB_1_0 && defined(HAVE_PTHREAD) + if (!microlink_usb_async_start()) { + upsdebugx(1, "microlink_usb: continuous async listener unavailable, " + "falling back to per-call synchronous interrupt-IN reads"); + } +#endif /* WITH_LIBUSB_1_0 && HAVE_PTHREAD */ + return 1; } void microlink_usb_close(void) { +#if WITH_LIBUSB_1_0 && defined(HAVE_PTHREAD) + microlink_usb_async_stop(); +#endif /* WITH_LIBUSB_1_0 && HAVE_PTHREAD */ + if (udev) { comm_driver->close_dev(udev); udev = NULL; @@ -346,12 +542,17 @@ int microlink_usb_reset_and_reopen(void) { int ret; +#if WITH_LIBUSB_1_0 && defined(HAVE_PTHREAD) + /* Cancel the outstanding async transfer before resetting and closing + * the handle it is submitted against. */ + microlink_usb_async_stop(); +#endif /* WITH_LIBUSB_1_0 && HAVE_PTHREAD */ + if (udev) { - /* Send USB bus reset. The handle is invalid afterward regardless - * of the return value -- close it unconditionally. usb_reset() - * is NUT's usb-common.h abstraction (libusb_reset_device on - * libusb-1.0, usb_reset on libusb-0.1); calling libusb_reset_device - * directly breaks NUT_USB_VARIANT=0.1 builds. */ + /* Send USB bus reset. The handle is invalid afterward regardless of + * the return value - close it unconditionally. usb_reset() is NUT's + * usb-common.h abstraction; calling libusb_reset_device() directly + * breaks NUT_USB_VARIANT=0.1 builds. */ usb_reset(udev); comm_driver->close_dev(udev); udev = NULL; @@ -380,23 +581,31 @@ int microlink_usb_reset_and_reopen(void) udev = NULL; return 0; } + usb_device_gone = 0; upsdebugx(1, "microlink_usb: reset and reopened %s/%s (USB %04x:%04x)", curDevice.Vendor ? curDevice.Vendor : "unknown", curDevice.Product ? curDevice.Product : "unknown", curDevice.VendorID, curDevice.ProductID); +#if WITH_LIBUSB_1_0 && defined(HAVE_PTHREAD) + if (!microlink_usb_async_start()) { + upsdebugx(1, "microlink_usb: continuous async listener unavailable after " + "reset, falling back to per-call synchronous interrupt-IN reads"); + } +#endif /* WITH_LIBUSB_1_0 && HAVE_PTHREAD */ + return 1; } +int microlink_usb_device_gone(void) +{ + return usb_device_gone; +} + /* A timeout of 0 to libusb_interrupt_transfer() means "wait forever", not - * "don't block" - confirmed the hard way against real hardware, where a - * 0ms drain call could stall this function (and everything after it) for - * however long the device's interrupt pipe happened to be idle, since - * this device also pushes unrelated Input reports on the same pipe only - * every 100-200ms (see apcmicrolink-usb.c's header comment) and the pipe - * can be briefly, genuinely empty. Use a short real timeout instead, and - * cap the number of drained reports as a defensive bound. */ + * "don't block", and this device's interrupt pipe can be genuinely empty for a + * while - so use a short real timeout, and cap the reports drained. */ #define MLINK_USB_FLUSH_TIMEOUT_MS 20U #define MLINK_USB_FLUSH_MAX_REPORTS 32U @@ -413,6 +622,54 @@ void microlink_usb_flush_io(void) return; } +#if WITH_LIBUSB_1_0 && defined(HAVE_PTHREAD) + if (async_xfer_active) { + /* The async listener owns the interrupt-IN endpoint, and its pump + * thread already services the event loop continuously, so just drop + * whatever is queued. This function must never call + * libusb_handle_events*() itself - that would make it a second caller + * of the event loop. + * + * This discards unread genuine tunnel replies too, so it is only + * correct for clearing stale data after a hard reset - which + * microlink_usb_async_stop() already handles independently. No caller + * remains; the discard logging is kept for any future one. */ + { + unsigned int discarded_count; + unsigned int discarded_tunnel_reports = 0; + + pthread_mutex_lock(&async_lock); + discarded_count = async_queue_count; + if (mlink_report_in != 0) { + unsigned int i; + + for (i = 0; i < async_queue_count; i++) { + unsigned int slot = (async_queue_head + i) % MLINK_USB_ASYNC_QUEUE_LEN; + + if (async_queue[slot].len > 0 + && (int)async_queue[slot].data[0] == mlink_report_in + ) { + discarded_tunnel_reports++; + } + } + } + async_queue_head = 0; + async_queue_count = 0; + pthread_mutex_unlock(&async_lock); + + if (discarded_count > 0) { + upsdebugx(discarded_tunnel_reports > 0 ? 1 : 3, + "microlink_usb: flushing %u queued async report(s) " + "(%u were our tunnel's Input report 0x%02X) before a " + "fresh session attempt", + discarded_count, discarded_tunnel_reports, + (unsigned int)mlink_report_in); + } + } + return; + } +#endif /* WITH_LIBUSB_1_0 && HAVE_PTHREAD */ + for (drained = 0; drained < MLINK_USB_FLUSH_MAX_REPORTS; drained++) { ret = comm_driver->get_interrupt(udev, (usb_ctrl_charbuf)discard, (usb_ctrl_charbufsize)sizeof(discard), @@ -423,26 +680,18 @@ void microlink_usb_flush_io(void) } } -/* Confirmed live on real hardware: the Linux kernel's own generic "usbhid" - * driver can reclaim this device's interface out from under an already-open, - * already-claimed libusb handle - observed once, apparently following a USB - * reset/re-enumeration event this driver has no visibility into. Once that - * happens, every USBDEVFS_SUBMITURB this process makes is rejected by the - * kernel with EBUSY (surfaces here as LIBUSB_ERROR_BUSY) until the process - * is restarted - and because that failure returns near-instantly, unlike a - * real timeout, nothing above this file paces the resulting retries: one - * observed incident spun at ~14,000 failed submissions/sec for 30+ minutes - * straight, saturating a CPU core and, via dmesg's own "did not claim - * interface" message at the same rate, completely overwriting the kernel - * ring buffer before the actual triggering event could ever be identified. +/* The kernel's own generic "usbhid" driver can reclaim this device's interface + * out from under an already-claimed libusb handle - observed live, apparently + * following a USB reset this driver has no visibility into. Every submission + * then fails with LIBUSB_ERROR_BUSY until the process is restarted, and + * because that fails near-instantly, nothing above this file paces the + * retries: one observed incident spun at ~14,000 failed submissions/sec for + * 30+ minutes, saturating a CPU core and overwriting the kernel ring buffer + * before the triggering event could be identified. * - * A permanent udev rule that unbinds usbhid from this VID:PID (installed - * outside this source tree, e.g. as a distro packaging step) avoids this in - * practice. This handler is defense in depth for that rule being absent, or - * for some other cause of the same kernel-level symptom: back off hard - * instead of spinning, and log loudly (not upsdebugx, which is invisible - * without -D) but rate-limited, so a recurrence is visible in syslog - * without flooding it or dmesg the way the uncaught case did. */ + * A udev rule unbinding usbhid from this VID:PID avoids this in practice; this + * handler is defense in depth for that rule being absent - back off hard + * instead of spinning, and log loudly but rate-limited. */ #define MLINK_USB_BUSY_BACKOFF_USEC 1000000U #define MLINK_USB_BUSY_LOG_EVERY 30U @@ -482,20 +731,11 @@ int microlink_usb_send_bytes(const unsigned char *buf, size_t len) return 0; } - /* Confirmed against real SCL500RMI1UC hardware: comm_driver->set_report() - * (nut_libusb_set_report(), HID class SET_REPORT control transfer with - * Report Type Output 0x02<<8 instead of its hardcoded Feature 0x03<<8) - * was tried first, and while the control transfer itself succeeds at - * the USB level (no stall, no error), the device never actually reacts - * to it - no reply ever appears on the Input Report 0x89 channel, - * regardless of init byte or how long you wait. Switching to a genuine - * interrupt-OUT write on the Output endpoint (matching the real - * Windows driver's behavior) gets an immediate, correctly-framed, - * checksum-valid response stream. So this device's raw HID tunnel - * genuinely requires interrupt-OUT, not just a HID-spec-valid control - * transfer to the same Report ID - apparently the firmware's tunnel - * implementation only watches the interrupt endpoint's hardware FIFO, - * not the control endpoint. */ + /* This tunnel genuinely requires interrupt-OUT: a HID SET_REPORT control + * transfer to the same Report ID succeeds at the USB level, but the device + * never reacts to it - no reply ever appears on the Input report channel - + * while an interrupt-OUT write on the Output endpoint gets an immediate, + * correctly framed, checksum-valid response stream. */ raw_buf[0] = (unsigned char)mlink_report_out; memset(raw_buf + 1, 0, sizeof(raw_buf) - 1); memcpy(raw_buf + 1, buf, len); @@ -517,6 +757,10 @@ int microlink_usb_send_bytes(const unsigned char *buf, size_t len) return 0; } + if (ret == LIBUSB_ERROR_NO_DEVICE) { + usb_device_gone = 1; + } + if (ret < 0) { upsdebugx(1, "microlink_usb: interrupt-OUT write (Output 0x%02X) failed: %s", (unsigned int)mlink_report_out, nut_usb_strerror(ret)); @@ -526,13 +770,10 @@ int microlink_usb_send_bytes(const unsigned char *buf, size_t len) return 1; } -/* Extract a little-endian, LSB-first-packed bit field from a HID report's - * data (everything after the leading Report ID byte), matching how - * Parse_ReportDesc()'s Offset/Size describe fields - confirmed against - * real captured bytes from this device (e.g. a 32-bit RunTimeToEmpty - * field at offset 0 decoded correctly as little-endian this way). - * bit_size is capped to fit in an unsigned long as this is only ever - * used for <=32-bit fields here. */ +/* Extract a little-endian, LSB-first-packed bit field from a report's data + * (everything after the leading Report ID byte), matching how + * Parse_ReportDesc()'s Offset/Size describe fields. Only used for fields of at + * most 32 bits here. */ static unsigned long hid_extract_bits(const unsigned char *data, size_t data_len, int bit_offset, int bit_size) { @@ -559,10 +800,9 @@ static unsigned long hid_extract_bits(const unsigned char *data, size_t data_len return value; } -/* Opportunistically decode the standard-HID-PDC fallback fields if this - * report happens to be one of them - called on every Input report we see, - * whether or not it turns out to be our own Microlink tunnel reply, since - * these arrive autonomously and independently of tunnel health. */ +/* Decode the standard HID PDC fallback fields if this report happens to be one + * of them - called for every Input report seen, since these arrive + * autonomously and independently of tunnel health. */ static void microlink_usb_try_decode_fallback(const unsigned char *report, size_t report_len) { int report_id; @@ -597,10 +837,231 @@ static void microlink_usb_try_decode_fallback(const unsigned char *report, size_ if (report_id == ff_ac_present.report_id || report_id == ff_discharging.report_id || report_id == ff_below_rcl.report_id || report_id == ff_remaining_capacity.report_id || report_id == ff_runtime_to_empty.report_id) { - fb_last_update = time(NULL); + fb_last_update = microlink_now(); } } +#if WITH_LIBUSB_1_0 && defined(HAVE_PTHREAD) +/* Keeps libusb's event loop serviced so async_xfer is reaped and resubmitted + * promptly, independent of what the main thread is doing. Nothing else may + * call libusb_handle_events*() on this context while this thread runs. */ +static void *microlink_usb_async_pump(void *arg) +{ + NUT_UNUSED_VARIABLE(arg); + + while (!async_pump_stop) { + struct timeval tv; + + tv.tv_sec = 0; + tv.tv_usec = 50000; /* 50ms - bounds how fast a stop request is noticed */ + libusb_handle_events_timeout_completed(nut_libusb_get_context(), &tv, NULL); + } + + return NULL; +} + +/* Runs on the pump thread from inside libusb_handle_events*(). Queues the + * completed report and immediately resubmits the same transfer, so exactly one + * interrupt-IN request stays outstanding at all times. + * + * transfer->user_data doubles as an "abandoned" marker (see + * microlink_usb_async_stop()): libusb forbids freeing a transfer before its + * callback has fired, so an abandoned one frees itself here instead of ever + * resubmitting. */ +static void LIBUSB_CALL microlink_usb_async_cb(struct libusb_transfer *transfer) +{ + int abandoned = (transfer->user_data != NULL); + + if (!abandoned && transfer->status == LIBUSB_TRANSFER_COMPLETED && transfer->actual_length > 0) { + size_t copy_len = (size_t)transfer->actual_length; + + if (copy_len > MLINK_USB_REPORT_TOTAL_LEN) { + copy_len = MLINK_USB_REPORT_TOTAL_LEN; + } + + upsdebugx(4, "microlink_usb: async transfer completed: report 0x%02X, " + "%u bytes", + copy_len > 0 ? (unsigned int)transfer->buffer[0] : 0U, + (unsigned int)copy_len); + + /* Decoded on receipt whether or not this also turns out to be our own + * tunnel reply; the fb_* globals are read by the main thread in + * microlink_usb_get_hid_fallback(), hence the lock. */ + pthread_mutex_lock(&async_lock); + + microlink_usb_try_decode_fallback(transfer->buffer, copy_len); + + if (async_queue_count < MLINK_USB_ASYNC_QUEUE_LEN) { + unsigned int slot = (async_queue_head + async_queue_count) % MLINK_USB_ASYNC_QUEUE_LEN; + + memcpy(async_queue[slot].data, transfer->buffer, copy_len); + async_queue[slot].len = copy_len; + async_queue_count++; + pthread_cond_signal(&async_cond); + } else { + upsdebugx(3, "microlink_usb: async read queue full (%u), dropping " + "incoming report", MLINK_USB_ASYNC_QUEUE_LEN); + } + + pthread_mutex_unlock(&async_lock); + } + + if (abandoned) { + free(transfer->buffer); + libusb_free_transfer(transfer); + return; + } + + switch (transfer->status) { + case LIBUSB_TRANSFER_CANCELLED: + case LIBUSB_TRANSFER_NO_DEVICE: + /* Teardown in progress, or the device is gone - don't resubmit; + * microlink_usb_async_stop() frees this transfer once it observes + * async_xfer_active go to 0. */ + if (transfer->status == LIBUSB_TRANSFER_NO_DEVICE) { + usb_device_gone = 1; + } + pthread_mutex_lock(&async_lock); + async_xfer_active = 0; + pthread_mutex_unlock(&async_lock); + return; + default: + break; + } + + if (libusb_submit_transfer(transfer) != 0) { + upsdebugx(1, "microlink_usb: failed to resubmit async interrupt-IN " + "transfer, continuous listener stopped"); + pthread_mutex_lock(&async_lock); + async_xfer_active = 0; + pthread_mutex_unlock(&async_lock); + } +} + +/* Start the listener and its pump thread. Returns 1 if running (or already + * was), 0 if it could not be started - callers fall back to per-call + * synchronous reads then, so this is never fatal. */ +static int microlink_usb_async_start(void) +{ + int ep_in; + unsigned char *buf; + + if (!udev) { + return 0; + } + if (async_xfer_active) { + return 1; + } + + ep_in = USB_ENDPOINT_IN + usb_subdriver.hid_ep_in; + + /* Heap-allocated per instance - see async_xfer's declaration. */ + buf = xmalloc(MLINK_USB_REPORT_TOTAL_LEN); + + async_xfer = libusb_alloc_transfer(0); + if (!async_xfer) { + upsdebugx(1, "microlink_usb: libusb_alloc_transfer failed for the " + "async listener"); + free(buf); + return 0; + } + + /* Timeout 0 on an async transfer means "no timeout on this submission", + * unlike the synchronous API - exactly what we want here: stay outstanding + * until data arrives or it is cancelled. user_data starts NULL ("owned"); + * microlink_usb_async_stop() sets it to mark the transfer abandoned. */ + libusb_fill_interrupt_transfer(async_xfer, udev, ep_in, + buf, (int)MLINK_USB_REPORT_TOTAL_LEN, + microlink_usb_async_cb, NULL, 0); + + if (libusb_submit_transfer(async_xfer) != 0) { + upsdebugx(1, "microlink_usb: failed to submit the initial async " + "interrupt-IN transfer"); + libusb_free_transfer(async_xfer); + free(buf); + async_xfer = NULL; + return 0; + } + + async_queue_head = 0; + async_queue_count = 0; + async_xfer_active = 1; + + async_pump_stop = 0; + if (pthread_create(&async_pump_tid, NULL, microlink_usb_async_pump, NULL) != 0) { + upsdebugx(1, "microlink_usb: failed to start the async pump thread, " + "abandoning the just-submitted transfer and falling back to " + "synchronous reads"); + /* Nothing will service the event loop until some later synchronous + * call incidentally does, so request cancellation now and then walk + * away exactly like the timeout path in microlink_usb_async_stop() + * below. */ + libusb_cancel_transfer(async_xfer); + async_xfer->user_data = (void *)1; + async_xfer = NULL; + async_xfer_active = 0; + async_queue_head = 0; + async_queue_count = 0; + return 0; + } + + upsdebugx(2, "microlink_usb: continuous async interrupt-IN listener started"); + return 1; +} + +/* Stop the pump thread first; once it has exited, this function is again the + * only thing that might touch libusb's event loop. + * + * Freeing a transfer libusb has not yet reported as complete or cancelled is + * undefined behavior (observed live as a "usbi_mutex_lock" assertion crash + * during a USB reset), so cancel it and wait, bounded, for confirmation. If + * the bound is hit - realistically only when the device is already too wedged + * to answer a cancel, i.e. exactly what leads here - mark the transfer + * abandoned via user_data and let its callback free it whenever libusb + * eventually completes it. Never touch it again after that. */ +static void microlink_usb_async_stop(void) +{ + int i; + + if (!async_xfer) { + return; + } + + async_pump_stop = 1; + pthread_join(async_pump_tid, NULL); + + if (async_xfer_active) { + libusb_cancel_transfer(async_xfer); + + for (i = 0; i < 50 && async_xfer_active; i++) { + struct timeval tv; + + tv.tv_sec = 0; + tv.tv_usec = 20000; + libusb_handle_events_timeout_completed(nut_libusb_get_context(), &tv, NULL); + } + + if (async_xfer_active) { + upsdebugx(1, "microlink_usb: async transfer did not confirm " + "cancellation in time, abandoning it (it will free itself " + "once libusb eventually completes it)"); + async_xfer->user_data = (void *)1; + async_xfer = NULL; + async_xfer_active = 0; + async_queue_head = 0; + async_queue_count = 0; + return; + } + } + + free(async_xfer->buffer); + libusb_free_transfer(async_xfer); + async_xfer = NULL; + async_queue_head = 0; + async_queue_count = 0; +} +#endif /* WITH_LIBUSB_1_0 && HAVE_PTHREAD */ + int microlink_usb_get_hid_fallback(int max_age_sec, int *ac_present, int *discharging, int *below_rcl, long *battery_charge, long *battery_runtime) @@ -609,8 +1070,15 @@ int microlink_usb_get_hid_fallback(int max_age_sec, return 0; } +#if WITH_LIBUSB_1_0 && defined(HAVE_PTHREAD) + pthread_mutex_lock(&async_lock); +#endif /* WITH_LIBUSB_1_0 && HAVE_PTHREAD */ + if (fb_last_update == 0 || max_age_sec < 0 - || difftime(time(NULL), fb_last_update) > (double)max_age_sec) { + || difftime(microlink_now(), fb_last_update) > (double)max_age_sec) { +#if WITH_LIBUSB_1_0 && defined(HAVE_PTHREAD) + pthread_mutex_unlock(&async_lock); +#endif /* WITH_LIBUSB_1_0 && HAVE_PTHREAD */ return 0; } @@ -630,6 +1098,10 @@ int microlink_usb_get_hid_fallback(int max_age_sec, *battery_runtime = (ff_runtime_to_empty.report_id != 0) ? fb_battery_runtime : -1; } +#if WITH_LIBUSB_1_0 && defined(HAVE_PTHREAD) + pthread_mutex_unlock(&async_lock); +#endif /* WITH_LIBUSB_1_0 && HAVE_PTHREAD */ + return 1; } @@ -638,7 +1110,10 @@ int microlink_usb_hid_fallback_supported(void) return (ff_ac_present.report_id != 0 && ff_discharging.report_id != 0); } -int microlink_usb_get_char(unsigned char *ch, long d_usec) +/* Per-call synchronous read: issue one interrupt-IN transfer and wait up to + * d_usec for it. Used as-is on non-libusb-1.0 builds, and as the fallback when + * the async listener could not be started. */ +static int microlink_usb_get_char_sync(unsigned char *ch, long d_usec) { int ret; usb_ctrl_timeout_msec timeout_ms; @@ -667,20 +1142,21 @@ int microlink_usb_get_char(unsigned char *ch, long d_usec) return -1; } + if (ret == LIBUSB_ERROR_NO_DEVICE) { + usb_device_gone = 1; + } + if (ret < 0) { in_report_len = 0; in_report_pos = 0; return -1; } - /* The interrupt IN endpoint can also carry other Input reports this - * device pushes (e.g. the mirrored 0x84:0x24 scalars) - ignore - * anything that is not our row-push channel rather than feeding - * foreign report bytes into the Microlink byte stream. Before - * discarding, though: some of those "other" reports are exactly the - * standard-HID-PDC fallback fields, which keep arriving - * independent of whether the tunnel itself is responding - worth - * decoding regardless of what this specific read call was for. */ + /* The interrupt-IN endpoint also carries other Input reports this device + * pushes - ignore anything that is not our tunnel's rather than feeding + * foreign bytes into the Microlink stream. Decode the HID PDC fallback + * fields first, though: those keep arriving whether or not the tunnel + * itself is responding. */ if (ret >= 1) { microlink_usb_try_decode_fallback(in_report, (size_t)ret); } @@ -697,3 +1173,89 @@ int microlink_usb_get_char(unsigned char *ch, long d_usec) *ch = in_report[in_report_pos++]; return 1; } + +#if WITH_LIBUSB_1_0 && defined(HAVE_PTHREAD) +/* Mirrors ser_get_char()'s contract, same as the synchronous version above: 1 + * with *ch filled, 0 on timeout or a non-matching report, negative on hard + * error - the caller (microlink_receive_once()) already loops on 0. The + * difference is where the wait happens: on async_cond, for the pump thread to + * deliver a report into the listener's queue, including one that completed + * before this call started (e.g. during the caller's sleep between retries). + * This function must never call libusb_handle_events*() itself. */ +int microlink_usb_get_char(unsigned char *ch, long d_usec) +{ + struct timespec deadline; + microlink_async_report_t slot; + size_t copy_len; + + if (!async_xfer_active) { + return microlink_usb_get_char_sync(ch, d_usec); + } + + if (!udev || mlink_report_in == 0) { + return -1; + } + + if (in_report_pos < in_report_len) { + *ch = in_report[in_report_pos++]; + return 1; + } + + if (d_usec < 0) { + d_usec = 0; + } + + /* pthread_cond_timedwait() takes an absolute deadline on the system + * (CLOCK_REALTIME) clock by default - no portable way to request + * CLOCK_MONOTONIC here without pthread_condattr_setclock(), a POSIX + * extension not available everywhere this codebase targets. */ + clock_gettime(CLOCK_REALTIME, &deadline); + deadline.tv_sec += d_usec / 1000000L; + deadline.tv_nsec += (d_usec % 1000000L) * 1000L; + if (deadline.tv_nsec >= 1000000000L) { + deadline.tv_sec++; + deadline.tv_nsec -= 1000000000L; + } + + pthread_mutex_lock(&async_lock); + + while (async_queue_count == 0) { + if (pthread_cond_timedwait(&async_cond, &async_lock, &deadline) != 0) { + /* Timed out (or some other wait error) - no report showed up + * within the caller's budget. */ + pthread_mutex_unlock(&async_lock); + return 0; + } + } + + slot = async_queue[async_queue_head]; + async_queue_head = (async_queue_head + 1) % MLINK_USB_ASYNC_QUEUE_LEN; + async_queue_count--; + + pthread_mutex_unlock(&async_lock); + + copy_len = (slot.len > sizeof(in_report)) ? sizeof(in_report) : slot.len; + memcpy(in_report, slot.data, copy_len); + + if (copy_len < 2 || (int)in_report[0] != mlink_report_in) { + upsdebugx(4, "microlink_usb: discarding queued report 0x%02X " + "(%u bytes, want 0x%02X) - not our tunnel's Input report", + copy_len > 0 ? (unsigned int)in_report[0] : 0U, + (unsigned int)copy_len, (unsigned int)mlink_report_in); + in_report_len = 0; + in_report_pos = 0; + return 0; + } + + in_report_len = copy_len; + in_report_pos = 1; /* skip the leading Report ID byte */ + + *ch = in_report[in_report_pos++]; + return 1; +} +#else /* !(WITH_LIBUSB_1_0 && HAVE_PTHREAD) */ +int microlink_usb_get_char(unsigned char *ch, long d_usec) +{ + return microlink_usb_get_char_sync(ch, d_usec); +} +#endif /* WITH_LIBUSB_1_0 && HAVE_PTHREAD */ diff --git a/drivers/apcmicrolink-usb.h b/drivers/apcmicrolink-usb.h index c140377b2e..5ac9d10f12 100644 --- a/drivers/apcmicrolink-usb.h +++ b/drivers/apcmicrolink-usb.h @@ -72,7 +72,15 @@ int microlink_usb_hid_fallback_supported(void); * Returns 1 on success (udev valid, HID descriptor re-parsed), 0 on failure * (udev left NULL). If udev is already NULL, skips the reset and just tries * to reopen. The regex_matcher is never freed or modified. Call this when - * the Microlink tunnel has been unresponsive for an extended period. */ + * microlink_usb_device_gone() reports a genuine disconnect - a live-but- + * unresponsive device is a different problem this doesn't fix (confirmed + * by testing: it recovers a real unplug/power-cycle, not a stalled tunnel). */ int microlink_usb_reset_and_reopen(void); +/* 1 if a read, write, or async transfer has reported the USB device + * genuinely gone (unplugged, power-cycled) since the last successful + * microlink_usb_open(); 0 otherwise. This is the signal to act on, not a + * retry count - a live-but-stalled device never benefits from a reset. */ +int microlink_usb_device_gone(void); + #endif /* APCMICROLINK_USB_H */ diff --git a/drivers/apcmicrolink.c b/drivers/apcmicrolink.c index 4026475918..ea82ecf867 100644 --- a/drivers/apcmicrolink.c +++ b/drivers/apcmicrolink.c @@ -31,7 +31,7 @@ #endif /* WITH_USB */ #define DRIVER_NAME "APC Microlink protocol driver" -#define DRIVER_VERSION "0.02" +#define DRIVER_VERSION "0.03" upsdrv_info_t upsdrv_info = { DRIVER_NAME, @@ -44,6 +44,18 @@ upsdrv_info_t upsdrv_info = { #define MLINK_DEFAULT_BAUDRATE B9600 #define MLINK_NEXT_BYTE 0xFE #define MLINK_INIT_BYTE 0xFD +/* 0xFE/0xFD are the same ACK/NAK bytes APC's own PowerChute Serial + * Shutdown client uses (matching MLINK_NEXT_BYTE/MLINK_INIT_BYTE above + * exactly), and 0xF7 is its STOP byte - sent, unconditionally, + * immediately before every NAK it issues while recovering from a comms + * timeout. We had never sent this byte at all; see MLINK_STOP_THEN_INIT() + * below for why that appears to matter. Also cross-confirms an + * independent third-party finding already in this codebase's history: the + * two-byte APC_CMD_INIT = [0xF7, 0xFD] sequence documented for the older + * Smart-UPS C1000/SMC1000i in SCL500RM1UC-protocol-notes.md isn't a + * different device's alternate init byte - it's this exact STOP-then-NAK + * pair. */ +#define MLINK_STOP_BYTE 0xF7 #define MLINK_HANDSHAKE_RETRIES 3 #define MLINK_READ_TIMEOUT_USEC 100000 /* Confirmed against real SCL500RMI1UC hardware over USB: unlike serial, @@ -74,6 +86,39 @@ upsdrv_info_t upsdrv_info = { * treating it as a real communication failure. */ #define MLINK_USB_HANDSHAKE_RETRIES 10 +/* EXPERIMENTAL (stability variant A, 2026-08-24): MLINK_USB_HANDSHAKE_RETRIES + * (10 poll cycles, ~10-20s depending on poll_interval) was, until this + * change, ALSO the threshold for tearing down an already-established, + * partway-through-the-96-row-descriptor-fetch session and restarting it + * from zero (see the reconnect check in upsdrv_updateinfo()). That reuse + * conflated two very different situations: giving up on the very first + * handshake (cheap, nothing lost) versus giving up mid-fetch (expensive + * at the time - later fixes made reconnecting non-destructive, see + * febb2e55c/9a8a78bf3). This constant is deliberately separate, much + * larger than the handshake retry budget, and wall-clock-based (not a + * poll-count) so it stays correct if MLINK_USB_READ_TIMEOUT_USEC or + * poll_interval ever change. + * + * Value derived 2026-08-27 from a direct tshark/usbmon measurement of + * real tunnel Input-report (0x89) arrival gaps over ~7 clean hours on + * real hardware (825 replies). The gap distribution was sharply + * trimodal, not a smooth spread: ~80% under 5s, a tight cluster at + * 11.0-13.0s, then a completely empty band from 13s to 289s, then a + * tight cluster at 288.6-290.6s recurring roughly every 5m10s. No + * legitimate reply gap was ever observed between 13s and 289s. 30s sits + * with >2x margin above the 13s cluster's ceiling while staying nowhere + * near the 289s one, so it should never misfire on a normal pause while + * still catching a real stall far sooner than 90s did. + * + * Caveat: the measured window predated the async-queue-flush fix + * (f7f10fc70, same day) - what caused the ~289s cluster specifically is + * not established (an earlier theory that it reflected a genuine + * independent device heartbeat did not hold up to scrutiny). Only the + * empirical gap-distribution finding is treated as reliable here, not + * any particular explanation for it; re-derive from fresh post-fix data + * if this stops matching observed reconnect behavior. */ +#define MLINK_USB_MIDSESSION_IDLE_SEC 30 + /* How stale a standard-HID-PDC fallback snapshot is allowed * to be before it's still considered good enough to publish. Those * reports arrive roughly once a second when the device is behaving @@ -83,17 +128,19 @@ upsdrv_info_t upsdrv_info = { #define MLINK_HID_FALLBACK_MAX_AGE_SEC 10 /* How long to wait between individual Microlink session-start probes when * retrying from upsdrv_updateinfo() after a fallback start. Each probe - * sends one INIT_BYTE and listens for up to MLINK_USB_READ_TIMEOUT_USEC. - * At 1 s per probe this constant is the inter-probe gap; combined they - * give a probe rate of 1 / (1 + MLINK_SESSION_RETRY_INTERVAL_SEC) Hz - * (~1/6 Hz at the default 5 s). Intentionally slower than the startup - * burst so the device gets a quiescent window to finish its own init. */ -#define MLINK_SESSION_RETRY_INTERVAL_SEC 5 -/* Seconds of continuous Microlink fallback before a USB device reset is - * attempted. Pre-backdating microlink_fallback_since by this amount on a - * fallback startup means the first upsdrv_updateinfo() call triggers - * immediately rather than after another full interval of waiting. */ -#define MLINK_USB_RESET_AFTER_SEC 60 + * sends one INIT_BYTE and listens for up to MLINK_USB_READ_TIMEOUT_USEC, so + * combined with that this constant gives a per-cycle time of roughly + * MLINK_USB_READ_TIMEOUT_USEC + this many seconds (~2 s at the default 1 s + * USB read timeout). Tightened from an earlier 5 s: APC's own client + * appears to re-probe (write) far more often than that rather than relying + * on any special listening trick at the transport layer - its apparent + * "never stalls" behavior seems to come from writing often, not from a + * smarter read path. This constant is the driver's equivalent knob: probe + * far more often than the original 5 s so a device that's only briefly + * reachable gets more chances to be caught, without spinning (each cycle + * still spends most of its time in a real blocking wait, not + * busy-polling). */ +#define MLINK_SESSION_RETRY_INTERVAL_SEC 1 #define MLINK_DESC_OP_USAGE_SIZE 0xFC #define MLINK_DESC_OP_COLLECTION 0xFD @@ -149,6 +196,7 @@ static unsigned char rxbuf[MLINK_MAX_FRAME * 2]; static size_t rxbuf_len = 0; static unsigned int parsed_frames = 0; static unsigned int consecutive_timeouts = 0; +static time_t last_poll_success = 0; static int poll_primed = 0; static int authentication_sent = 0; static microlink_page0_state_t page0; @@ -156,6 +204,7 @@ static int descriptor_ready = 0; static int outlet_commands_registered = 0; static time_t microlink_session_next_retry = 0; static time_t microlink_fallback_since = 0; +static unsigned int microlink_fallback_retries = 0; /* main.c's read_upsconf() applies the user's "pollinterval" ups.conf setting * (or its own 2s default) to the global poll_interval before calling * upsdrv_initinfo() - captured here so a successfully-connected session can @@ -191,6 +240,7 @@ static const char *const outlet_suffixes[] = { * mixed into the same series) - "hid_fallback=no" opts back out to the * original behavior. */ static int hid_fallback_enabled = 1; + typedef enum microlink_command_source_e { MLINK_CMD_SOURCE_RJ45 = 0, MLINK_CMD_SOURCE_USB, @@ -505,6 +555,24 @@ static unsigned int microlink_handshake_retries(void) return MLINK_HANDSHAKE_RETRIES; } +/* Whether an already-established session has gone quiet long enough to be + * torn down and restarted. USB uses a much more patient, wall-clock-based + * budget than the initial handshake (see MLINK_USB_MIDSESSION_IDLE_SEC); + * serial keeps the original poll-count behavior, since the too-short-tolerance + * problem was only observed and characterized on USB. */ +static int microlink_midsession_timed_out(time_t now) +{ +#ifdef WITH_USB + if (is_usb) { + if (last_poll_success == 0) { + return consecutive_timeouts >= microlink_handshake_retries(); + } + return difftime(now, last_poll_success) >= MLINK_USB_MIDSESSION_IDLE_SEC; + } +#endif /* WITH_USB */ + return consecutive_timeouts >= microlink_handshake_retries(); +} + static int microlink_prime_poll(void) { if (!microlink_send_simple(MLINK_NEXT_BYTE)) { @@ -2356,6 +2424,8 @@ static int microlink_parse_descriptor(void) } descriptor_ready = 1; + upsdebugx(1, "microlink: STABILITY descriptor_ready usages=%zu blob_len=%zu", + descriptor_usage_count, descriptor_blob_len); return 1; } @@ -2510,9 +2580,12 @@ static int microlink_try_extract_frame(unsigned char *frame, size_t *framelen) } if (rxbuf_len >= sizeof(rxbuf)) { + size_t drop_len = rxbuf_len - (MLINK_RECORD_LEN - 1); + upsdebugx(1, "microlink: dropping %u bytes while resynchronizing", - (unsigned int)(rxbuf_len - (MLINK_RECORD_LEN - 1))); - memmove(rxbuf, rxbuf + (rxbuf_len - (MLINK_RECORD_LEN - 1)), MLINK_RECORD_LEN - 1); + (unsigned int)drop_len); + microlink_trace_frame(1, "dropped (resync)", rxbuf, drop_len); + memmove(rxbuf, rxbuf + drop_len, MLINK_RECORD_LEN - 1); rxbuf_len = MLINK_RECORD_LEN - 1; } @@ -2572,17 +2645,33 @@ static int microlink_authenticate(void) s0 = protocol->data[4]; s1 = protocol->data[3]; + upsdebugx(3, "microlink: auth seed s0=%02X (protocol[4]) s1=%02X (protocol[3])", + s0, s1); + microlink_trace_frame(3, "auth protocol[0:8]", protocol->data, 8); + microlink_trace_frame(3, "auth serial_usage bytes", descriptor_blob + serial_usage->data_offset, + serial_usage->size); + microlink_trace_frame(3, "auth master_password[0:2] (only first 2 used)", master_password, 2); + microlink_auth_update(&s0, &s1, protocol->data, 8); + upsdebugx(3, "microlink: auth after protocol header: s0=%02X s1=%02X", s0, s1); microlink_auth_update(&s0, &s1, descriptor_blob + serial_usage->data_offset, serial_usage->size); + upsdebugx(3, "microlink: auth after serial number: s0=%02X s1=%02X", s0, s1); microlink_auth_update(&s0, &s1, master_password, 2); - - payload[0] = 0x00; - payload[1] = 0x00; + upsdebugx(3, "microlink: auth after master_password: s0=%02X s1=%02X (-> SPC[2:4])", s0, s1); + + /* SPC[0:2]: our own challenge. APC's own PowerChute client draws this + * from a real random source; a fixed 0x00 0x00 here made the exchange + * trivially predictable, and a failed auth is suspected of locking out + * comms until a device reset. Randomization only - the reply itself is + * not verified. */ + payload[0] = (unsigned char)(rand() % 256); + payload[1] = (unsigned char)(rand() % 256); payload[2] = s0; payload[3] = s1; - upsdebugx(2, "microlink: sending slave password %02X %02X", + upsdebugx(1, "microlink: STABILITY auth_sent %02X %02X", payload[2], payload[3]); + microlink_trace_frame(1, "auth SLAVE_PASSWORD payload (SPC[0:4])", payload, sizeof(payload)); return microlink_send_descriptor_write( MLINK_DESC_SLAVE_PASSWORD, @@ -2676,7 +2765,7 @@ static int microlink_receive_once(void) } } -static int microlink_poll_once(void) +static int microlink_poll_once(time_t now) { if (!poll_primed) { if (!microlink_prime_poll()) { @@ -2686,6 +2775,7 @@ static int microlink_poll_once(void) if (microlink_receive_once()) { consecutive_timeouts = 0; + last_poll_success = now; poll_primed = 0; return 1; } @@ -2702,28 +2792,52 @@ static int microlink_start_session_impl(unsigned int max_attempts) rxbuf_len = 0; poll_primed = 0; authentication_sent = 0; - memset(&page0, 0, sizeof(page0)); - descriptor_ready = 0; - descriptor_usage_count = 0; - descriptor_blob_len = 0; + /* NOT resetting page0/descriptor_ready/descriptor_usage_count/ + * descriptor_blob_len: this runs on every reconnect, not just the + * first session. objects[]->seen (which gates whether frame-length + * parsing trusts page0.width) only resets at process start, so + * zeroing page0.width here left every reconnect after the first + * computing frame length as 0+3=3 - too short to ever checksum-valid. + * The device was replying fine the whole time; we just stopped being + * able to parse it. page0 is static per device/firmware and gets + * refreshed on receipt anyway, so keeping stale values costs nothing. */ + + /* NOT calling microlink_usb_flush_io() for USB (unlike ser_flush_io() + * below): it wipes the async queue, and this runs every retry in a + * "not ready yet" loop that can span minutes. Isolated test: this + * discarded ~50% of otherwise-valid replies. The only real use case + * (clearing stale data after a hard reset) is already handled by + * microlink_usb_async_stop(), making this call redundant there and + * harmful everywhere else. */ #ifdef WITH_USB - if (is_usb) { - microlink_usb_flush_io(); - } else + if (!is_usb) #endif /* WITH_USB */ { ser_flush_io(upsfd); } for (attempt = 0; attempt < max_attempts; attempt++) { + /* PowerChute's own comms-lost recovery (MicroLinkTranslator. + * sendStop()/sendNak()) always sends STOP immediately before NAK, + * never NAK alone - see MLINK_STOP_BYTE's comment. A STOP write + * failure is treated the same as an INIT_BYTE write failure + * (hard I/O error, not just "no reply yet"), matching how + * MLINK_INIT_BYTE's own failure is handled just below. */ + if (!microlink_send_simple(MLINK_STOP_BYTE)) { + return 0; + } + if (!microlink_send_simple(MLINK_INIT_BYTE)) { return 0; } if (microlink_receive_once()) { consecutive_timeouts = 0; + last_poll_success = microlink_now(); session_ready = 1; + upsdebugx(1, "microlink: STABILITY session_established attempt=%u", + attempt + 1); return microlink_prime_poll(); } } @@ -2738,8 +2852,10 @@ static int microlink_start_session(void) static int microlink_reconnect_session(void) { - upsdebugx(1, "microlink: reconnecting session after %u consecutive timeouts", - consecutive_timeouts); + upsdebugx(1, "microlink: STABILITY reconnecting after %u consecutive timeouts" + " descriptor_usage_count=%zu descriptor_ready=%d auth_sent=%d", + consecutive_timeouts, descriptor_usage_count, descriptor_ready, + authentication_sent); session_ready = 0; return microlink_start_session(); } @@ -2984,6 +3100,9 @@ static int instcmd(const char *cmdname, const char *extra) void upsdrv_initups(void) { int use_usb = 0; + time_t now = microlink_now(); + + srand((unsigned int)now); microlink_read_config(); @@ -3103,7 +3222,9 @@ void upsdrv_initinfo(void) if (microlink_start_session()) { microlink_ready = 1; while (microlink_ready && !microlink_startup_ready()) { - if (!microlink_poll_once() && consecutive_timeouts >= microlink_handshake_retries()) { + time_t now = microlink_now(); + + if (!microlink_poll_once(now) && consecutive_timeouts >= microlink_handshake_retries()) { microlink_ready = 0; } } @@ -3131,11 +3252,10 @@ void upsdrv_initinfo(void) microlink_publish_hid_fallback_inactive(); } else if (microlink_publish_hid_fallback()) { session_ready = 0; - /* Pre-backdate so upsdrv_updateinfo() can try a USB reset immediately - * rather than waiting a full MLINK_USB_RESET_AFTER_SEC from now: the - * startup handshake already spent microlink_handshake_retries() x 1s - * probing with no response, proving the device is already stalled. */ - microlink_fallback_since = time(NULL) - MLINK_USB_RESET_AFTER_SEC; + /* Backdate microlink_fallback_since by the probing time the startup + * handshake already spent, so the diagnostic log message below + * reports a realistic elapsed time instead of ~0s. */ + microlink_fallback_since = microlink_now() - (time_t)microlink_handshake_retries(); upslogx(LOG_WARNING, "apcmicrolink: could not complete Microlink startup on %s - " "starting up with standard-HID fallback data only (ups.status/" "battery.charge/battery.runtime); outlet-group data and commands " @@ -3163,10 +3283,10 @@ void upsdrv_initinfo(void) void upsdrv_updateinfo(void) { int good = 0; - time_t now = time(NULL); + time_t now = microlink_now(); if (!session_ready) { - int tried_reset = 0; + int reopening = 0; if (microlink_fallback_since == 0) microlink_fallback_since = now; @@ -3178,35 +3298,44 @@ void upsdrv_updateinfo(void) } #ifdef WITH_USB - if (now - microlink_fallback_since >= MLINK_USB_RESET_AFTER_SEC) { - upslogx(LOG_NOTICE, "apcmicrolink: Microlink tunnel unresponsive for " - "%ld s - attempting USB device reset to recover", - (long)(now - microlink_fallback_since)); - microlink_fallback_since = now; - tried_reset = 1; + /* A reset only ever helps a genuine USB disconnect (confirmed live: + * it recovered a real unplug/power-cycle); it never once helped a + * live-but-stalled tunnel in testing, so that's the only condition + * that triggers one now - not a blind retry count. */ + if (is_usb && microlink_usb_device_gone()) { + upslogx(LOG_NOTICE, "apcmicrolink: USB device appears to have been " + "disconnected (unresponsive for %ld s) - reopening once it " + "reappears", (long)(now - microlink_fallback_since)); + reopening = 1; if (microlink_usb_reset_and_reopen()) microlink_start_session(); + } else if (microlink_fallback_retries > 0 && microlink_fallback_retries % 64 == 0) { + upslogx(LOG_NOTICE, "apcmicrolink: Microlink tunnel unresponsive for " + "%ld s (%u consecutive failed retries)", + (long)(now - microlink_fallback_since), microlink_fallback_retries); } #endif - if (!tried_reset) + if (!reopening) microlink_start_session_impl(1); if (!session_ready) { + microlink_fallback_retries++; microlink_session_next_retry = now + MLINK_SESSION_RETRY_INTERVAL_SEC; poll_interval = MLINK_SESSION_RETRY_INTERVAL_SEC; microlink_datastale_or_fallback(); return; } microlink_fallback_since = 0; + microlink_fallback_retries = 0; poll_interval = microlink_configured_poll_interval; } - if (microlink_poll_once()) { + if (microlink_poll_once(now)) { good = 1; } - if (!good && consecutive_timeouts >= microlink_handshake_retries()) { + if (!good && microlink_midsession_timed_out(now)) { if (!microlink_reconnect_session()) { microlink_datastale_or_fallback(); return; diff --git a/drivers/apcmicrolink.h b/drivers/apcmicrolink.h index 0481eb46b4..054617561c 100644 --- a/drivers/apcmicrolink.h +++ b/drivers/apcmicrolink.h @@ -13,6 +13,17 @@ #include #include +#include + +/* Named wrapper for time(NULL) - a bare time(NULL) inline in an expression + * reads less clearly than a named call. Safe to use anywhere a plain + * time(NULL) would be, including inside a short-circuited condition: it is + * still just a function call evaluated at that exact point, not a hoisted + * value, so it introduces no new call where one didn't already happen. */ +static inline time_t microlink_now(void) +{ + return time(NULL); +} #define MLINK_MAX_FRAME 256 #define MLINK_MAX_PAYLOAD (MLINK_MAX_FRAME - 3) diff --git a/drivers/libusb1.c b/drivers/libusb1.c index d250825ea9..d8567a65e5 100644 --- a/drivers/libusb1.c +++ b/drivers/libusb1.c @@ -131,6 +131,17 @@ static void nut_libusb_cleanup_atexit(void) nut_usb_ctx_initialized = false; } +/* Accessor for the libusb context this backend owns, so callers that need + * to submit/manage their own async transfers against an already-open + * usb_dev_handle (e.g. a driver-specific always-outstanding interrupt-IN + * read) can pump its event loop with the correct context instead of + * guessing at libusb's implicit default one. Returns NULL before the first + * nut_libusb_open() call. */ +libusb_context *nut_libusb_get_context(void) +{ + return nut_usb_ctx_initialized ? nut_usb_ctx : NULL; +} + static void nut_libusb_close(libusb_device_handle *udev); /*! Add USB-related driver variables with addvar() and dstate_setinfo(). diff --git a/drivers/nut_libusb.h b/drivers/nut_libusb.h index 376e653037..9fe2879d51 100644 --- a/drivers/nut_libusb.h +++ b/drivers/nut_libusb.h @@ -118,4 +118,10 @@ typedef struct usb_communication_subdriver_s { extern usb_communication_subdriver_t usb_subdriver; +#if WITH_LIBUSB_1_0 +/* Defined in libusb1.c only - the libusb-0.1 backend has no equivalent + * context object to hand out. See its definition for the intended use. */ +libusb_context *nut_libusb_get_context(void); +#endif /* WITH_LIBUSB_1_0 */ + #endif /* NUT_LIBUSB_H_SEEN */ From f0a4525887e645f40dc03964217c0e3b79d530c2 Mon Sep 17 00:00:00 2001 From: nmbro Date: Sat, 29 Aug 2026 16:21:53 +0200 Subject: [PATCH 02/11] fix(apcmicrolink): reject a contradictory page 0 Page 0 announces the frame width that every later frame is parsed with, and microlink_cache_object() accepted any checksum-valid copy of it. A corrupt copy is therefore unrecoverable: the bogus width becomes the length microlink_try_extract_frame_at() demands, no frame checksum- validates again, and the session dies with the device having done nothing wrong. Seen live on a Smart-UPS X 1500 (FW 03.8) in issue #3587. The device served 60 populated pages, then emitted STOP-filled pages and restarted its page index. The wrapped page 0 was checksum-valid and announced a width of 247 inside a 16-byte frame, which replaced the correct width=16/pages=154 header decoded a second earlier. From that point the parser needed 250 contiguous valid bytes out of 19-byte records, so it never extracted another frame. A genuine page 0 always arrives in a frame of exactly the width it announces: on the first read the frame length is derived from that byte, and on every later read the frame length is the established width. So require the two to agree, and keep the previous page 0 when they do not. This is in the shared framing layer, so it applies to the serial transport as well. Use of coding helper tools and AI disclosed: Claude Code was used for development assistance. Signed-off-by: nmbro --- NEWS.adoc | 5 +++++ drivers/apcmicrolink.c | 24 +++++++++++++++++++++++- 2 files changed, 28 insertions(+), 1 deletion(-) diff --git a/NEWS.adoc b/NEWS.adoc index f03e8d61e1..a8021d4f2c 100644 --- a/NEWS.adoc +++ b/NEWS.adoc @@ -105,6 +105,11 @@ https://github.com/networkupstools/nut/milestone/13 distinct from `ups.serial`) and `microlink.diag.slave_password_echo` (auth troubleshooting visibility only, not proof that authentication was accepted). + * A page 0 whose announced frame width disagrees with the width of + the frame that carried it is now rejected instead of cached. Such + a page redefined the length the frame parser demanded, after which + nothing checksum-validated again and the session could not + recover. Affects both transports. [issue #3587] - `apc_modbus` driver updates: * Fixed string join not doing zero termination. [PR #3413] diff --git a/drivers/apcmicrolink.c b/drivers/apcmicrolink.c index ea82ecf867..a7fc2af03d 100644 --- a/drivers/apcmicrolink.c +++ b/drivers/apcmicrolink.c @@ -2433,15 +2433,37 @@ static void microlink_cache_object(const unsigned char *frame, size_t len) { unsigned int id; microlink_object_t *obj; + size_t datalen; if (len < 3) { return; } id = frame[0]; + datalen = len - 3; + + /* Page 0 announces the width every later frame is parsed with, so a + * corrupt copy is unrecoverable: the bogus width becomes the length + * the parser demands, no frame ever checksum-validates again, and the + * session dies without the device having done anything wrong. A real + * page 0 arrives in a frame of exactly the width it announces, so + * reject any copy that contradicts itself instead of caching it. + * + * Seen live on a Smart-UPS X 1500 (FW 03.8): after its last populated + * page the device sent STOP-filled pages and restarted its page index, + * and the resulting checksum-valid "page 0" announced width 247 inside + * a 16-byte frame. */ + if (id == MLINK_OBJ_PROTOCOL && datalen >= 3 && (size_t)frame[2] != datalen) { + upsdebugx(1, "microlink: ignoring implausible page0 - announces width " + "%u but arrived in a %" PRIuSIZE "-byte frame; keeping the " + "previous page0 (width %" PRIuSIZE ")", + (unsigned int)frame[2], datalen, page0.width); + return; + } + obj = microlink_get_object_mut(id); obj->seen = 1; - obj->len = len - 3; + obj->len = datalen; memcpy(obj->data, frame + 1, obj->len); if (id == MLINK_OBJ_PROTOCOL && obj->len >= 3) { From dcc62c16c59e91064980e8312fee37db6e1ee45a Mon Sep 17 00:00:00 2001 From: nmbro Date: Sat, 29 Aug 2026 16:39:18 +0200 Subject: [PATCH 03/11] feat(apcmicrolink): warn on unimplemented stuffing Page 0 bit 1 (MLINK_PAGE0_FLAG_IMPLICIT_STUFFING) asks for implicit byte stuffing on the wire. Nothing in the parser implements it; the bit was only published as microlink.flag.implicit_stuffing and otherwise ignored, so a device that set it would have its frames read as if stuffing were disabled and would fail with checksum errors that point nowhere near the actual cause. No device seen so far sets the bit - both an SCL500RMI1UC and an SMX1500RM2U report flags 0x09, i.e. AUTH_REQUIRED and DESCRIPTOR_PRESENT with stuffing clear - so rather than ship an unstuffing routine that cannot be exercised or tested, say plainly what the driver is doing and ask for a report. Logged once per process at LOG_WARNING, since it is invisible at the default debug level otherwise and describes a condition the user cannot work around. Use of coding helper tools and AI disclosed: Claude Code was used for development assistance. Signed-off-by: nmbro --- drivers/apcmicrolink.c | 20 ++++++++++++++++++++ 1 file changed, 20 insertions(+) diff --git a/drivers/apcmicrolink.c b/drivers/apcmicrolink.c index a7fc2af03d..6bb7d36d68 100644 --- a/drivers/apcmicrolink.c +++ b/drivers/apcmicrolink.c @@ -200,6 +200,7 @@ static time_t last_poll_success = 0; static int poll_primed = 0; static int authentication_sent = 0; static microlink_page0_state_t page0; +static int warned_implicit_stuffing = 0; static int descriptor_ready = 0; static int outlet_commands_registered = 0; static time_t microlink_session_next_retry = 0; @@ -2484,6 +2485,25 @@ static void microlink_cache_object(const unsigned char *frame, size_t len) (unsigned int)page0.width, page0.count, (unsigned int)page0.flags); + + /* Nothing in this parser implements byte stuffing; it is only + * published as microlink.flag.implicit_stuffing. No device seen + * so far sets the bit, so rather than guess at an unexercised + * unstuffing routine, say plainly that frames will be read as if + * it were clear - which is what any resulting checksum failures + * would otherwise be blamed on. */ + if ((page0.flags & MLINK_PAGE0_FLAG_IMPLICIT_STUFFING) != 0U + && !warned_implicit_stuffing + ) { + warned_implicit_stuffing = 1; + upslogx(LOG_WARNING, "microlink: this device requests implicit byte " + "stuffing (page0 flags 0x%02X), which this driver does not " + "implement - frames are parsed as if stuffing were disabled, " + "so expect checksum failures or missing data. Please report " + "this at https://github.com/networkupstools/nut/issues/ with " + "a debug log, as no device known to this driver sets that bit.", + (unsigned int)page0.flags); + } } } From 44de6d99adcfcfff387447bc6384b9a58430a75a Mon Sep 17 00:00:00 2001 From: nmbro Date: Sat, 29 Aug 2026 19:25:37 +0200 Subject: [PATCH 04/11] fix(apcmicrolink): name the async transfer states CodeQL flagged the switch on transfer->status as handling only two of the enum's values by name. Behaviour is unchanged - everything not cancelled or gone still falls through to the resubmit below - but the remaining states are now listed explicitly so the intent is readable and a future libusb addition shows up as a warning rather than silently joining the default. Use of coding helper tools and AI disclosed: Claude Code was used for development assistance. Signed-off-by: nmbro --- drivers/apcmicrolink-usb.c | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/drivers/apcmicrolink-usb.c b/drivers/apcmicrolink-usb.c index 2e0192ee84..e326c464c6 100644 --- a/drivers/apcmicrolink-usb.c +++ b/drivers/apcmicrolink-usb.c @@ -925,7 +925,13 @@ static void LIBUSB_CALL microlink_usb_async_cb(struct libusb_transfer *transfer) async_xfer_active = 0; pthread_mutex_unlock(&async_lock); return; + case LIBUSB_TRANSFER_COMPLETED: + case LIBUSB_TRANSFER_ERROR: + case LIBUSB_TRANSFER_TIMED_OUT: + case LIBUSB_TRANSFER_STALL: + case LIBUSB_TRANSFER_OVERFLOW: default: + /* Anything else - resubmit below and keep listening. */ break; } From 4d79bd6fcc51d337502cbeeb7e3822a458e1d385 Mon Sep 17 00:00:00 2001 From: nmbro Date: Sat, 29 Aug 2026 19:25:37 +0200 Subject: [PATCH 05/11] fix(apcmicrolink): use the HID fallback when it is needed The standard-HID-PDC fallback existed but could not engage in the case it was written for. Found on an SCL500RMI1UC that answered every poll while reporting an all-zero state: ups.status stayed empty for over two days with usable HID PDC reports arriving on the same endpoint the whole time, and upsmon therefore had nothing to act on. Four separate reasons it never took over, each fixed here: * microlink_start_session() refreshed last_poll_success on a bare handshake, so a device that answered the handshake but sent no data looked freshly polled forever. Data freshness is now tracked separately, and only real polled frames advance it. * upsdrv_updateinfo() treated a successful reconnect as good data. A handshake proves the device answers, not that the tunnel delivers. * Startup called fatalx() when no fallback snapshot had been decoded yet, even where the device clearly exposes the usages - they simply had not arrived in the startup window. It now starts and publishes them when they do. The old message also claimed no fallback was available on a device whose descriptor advertised one. * Staleness alone was not enough: this device answers on time and reports zeroes, so the data is fresh and useless. A poll that yields no ups.status flag at all now hands over too. MLINK_HID_FALLBACK_MAX_AGE_SEC goes from 10s to 30s. A usbmon capture showed the two streams are not concurrent: PDC reports arrive every 6.0s while the tunnel is idle, then stop for 19.2s whenever the device services tunnel traffic. A 10s window expired inside that gap, so the fallback became unpublishable exactly when the tunnel was also producing nothing, and ups.status went empty once per cycle. MLINK_DATA_STALE_SEC moves to 45s to stay above it. Handover is deliberately asymmetric. The fallback takes over immediately but only hands back after the Microlink source has looked plausible for 30s continuously; without that the two swapped on alternate polls, measured at 56 handovers in 3 minutes, and a status that flips every 2s is worse than one that lags a recovery. Plausibility is judged only from ups.status, which is rewritten every poll - testing battery.charge made the fallback read back a value it had published itself and hand over to a dead source. microlink_publish_hid_fallback() now writes its measurements before committing status, and states the charging condition explicitly. dstate's status_commit() infers CHRG/DISCHRG from battery.charge movement when the driver reports neither, and it was comparing the degenerate Microlink value against the previous fallback one and synthesizing a DISCHRG that contradicted the OL being set in the same breath. Handovers are logged with their reason at debug level 1, once per transition. A device that answers normally while reporting nothing usable also warns at LOG_WARNING, hourly, and publishes microlink.diag.status_degenerate: a USB bus reset does not clear that state (tested, along with deauthorize and driver unbind - none re-enumerate the device), so the user needs to know the UPS itself likely needs a power cycle. Use of coding helper tools and AI disclosed: Claude Code was used for development assistance. Signed-off-by: nmbro --- drivers/apcmicrolink.c | 279 ++++++++++++++++++++++++++++++++++++++--- 1 file changed, 264 insertions(+), 15 deletions(-) diff --git a/drivers/apcmicrolink.c b/drivers/apcmicrolink.c index 6bb7d36d68..c768c7696b 100644 --- a/drivers/apcmicrolink.c +++ b/drivers/apcmicrolink.c @@ -119,13 +119,49 @@ upsdrv_info_t upsdrv_info = { * if this stops matching observed reconnect behavior. */ #define MLINK_USB_MIDSESSION_IDLE_SEC 30 -/* How stale a standard-HID-PDC fallback snapshot is allowed - * to be before it's still considered good enough to publish. Those - * reports arrive roughly once a second when the device is behaving - * normally, so this is generous margin for a missed cycle or two without - * being so long that a genuinely wedged device (or a truly unplugged one) - * could leave stale fallback data looking current. */ -#define MLINK_HID_FALLBACK_MAX_AGE_SEC 10 +/* How stale a standard-HID-PDC fallback snapshot is allowed to be and still + * be considered good enough to publish. + * + * The two streams share one interrupt endpoint and do not run in parallel: + * a usbmon capture of an SCL500RMI1UC showed the PDC reports arriving every + * 6.0s while the tunnel was idle, then stopping for 19.2s the moment the + * driver started a session and the device answered tunnel traffic. A window + * of 10s expired inside that gap, so the fallback went unpublishable exactly + * when the tunnel was also producing nothing usable, and ups.status went + * empty once per cycle. 30s clears the observed gap with margin while still + * being short enough that a genuinely unplugged device does not leave stale + * fallback data looking current. */ +#define MLINK_HID_FALLBACK_MAX_AGE_SEC 30 + +/* How long the Microlink side may go without delivering real polled data + * before the standard-HID-PDC fallback takes over, when one is available. + * Completing the session handshake does not reset this - a device can answer + * the handshake on every retry while its tunnel stays mute, which is exactly + * the case this exists to catch. Kept above MLINK_HID_FALLBACK_MAX_AGE_SEC so + * the fallback snapshot we switch to is always fresher than the Microlink + * data we are abandoning. */ +#define MLINK_DATA_STALE_SEC 45 + +/* Why the standard-HID-PDC fallback is (or is not) being published right now. + * Only used to log handovers once per transition - see + * microlink_log_fallback_reason(). */ +#define MLINK_FB_REASON_NONE 0 +#define MLINK_FB_REASON_STALE 1 +#define MLINK_FB_REASON_EMPTY 2 + +/* How often to repeat the "tunnel is answering but reporting nothing" warning + * while that state persists. The condition can toggle on every poll, so this + * is deliberately coarse - it is a "your UPS needs attention" notice, not a + * per-poll trace. */ +#define MLINK_DEGENERATE_WARN_INTERVAL_SEC 3600 + +/* How long the Microlink source has to look plausible again, continuously, + * before the driver hands back to it. Without this the two sources swap on + * alternate polls whenever the device dribbles out an occasional status flag + * between all-zero ones, and ups.status oscillates every couple of seconds - + * measured at 56 handovers in 3 minutes on a degraded SCL500RMI1UC. A stable + * status matters more to upsmon than using the freshest possible source. */ +#define MLINK_FALLBACK_DWELL_SEC 30 /* How long to wait between individual Microlink session-start probes when * retrying from upsdrv_updateinfo() after a fallback start. Each probe * sends one INIT_BYTE and listens for up to MLINK_USB_READ_TIMEOUT_USEC, so @@ -197,6 +233,18 @@ static size_t rxbuf_len = 0; static unsigned int parsed_frames = 0; static unsigned int consecutive_timeouts = 0; static time_t last_poll_success = 0; +/* Distinct from last_poll_success, which microlink_start_session() also + * refreshes on a bare handshake: this only ever advances when real polled + * data arrives. See microlink_data_stale(). */ +static time_t last_microlink_data = 0; +/* When the "tunnel answers but reports nothing" warning was last emitted; + * 0 while the condition is not in effect. */ +static time_t degenerate_warned_at = 0; +/* Fallback hysteresis: whether the standard-HID source currently owns the + * published status, and since when the Microlink source has been looking + * plausible again (0 = not currently recovering). */ +static int fallback_engaged = 0; +static time_t fallback_recover_since = 0; static int poll_primed = 0; static int authentication_sent = 0; static microlink_page0_state_t page0; @@ -561,6 +609,33 @@ static unsigned int microlink_handshake_retries(void) * budget than the initial handshake (see MLINK_USB_MIDSESSION_IDLE_SEC); * serial keeps the original poll-count behavior, since the too-short-tolerance * problem was only observed and characterized on USB. */ +/* 1 if the Microlink side has not delivered real polled data recently. + * Deliberately ignores the session handshake: a device that answers the + * handshake but never sends another frame used to look healthy here, so the + * driver kept republishing its last values - all zeroes, with an empty + * ups.status - for days, while usable standard-HID-PDC reports were arriving + * on the same endpoint the whole time. */ +static int microlink_data_stale(time_t now) +{ + if (last_microlink_data == 0) { + return 1; + } + return difftime(now, last_microlink_data) >= MLINK_DATA_STALE_SEC; +} + +/* 1 if this device could publish standard-HID-PDC fallback data, whether or + * not any has been decoded yet. microlink_publish_hid_fallback() answers the + * narrower "is there a fresh snapshot right now"; this answers "is it worth + * staying alive and waiting for one". */ +static int microlink_hid_fallback_possible(void) +{ +#ifdef WITH_USB + return (is_usb && hid_fallback_enabled && microlink_usb_hid_fallback_supported()); +#else + return 0; +#endif /* WITH_USB */ +} + static int microlink_midsession_timed_out(time_t now) { #ifdef WITH_USB @@ -2818,6 +2893,7 @@ static int microlink_poll_once(time_t now) if (microlink_receive_once()) { consecutive_timeouts = 0; last_poll_success = now; + last_microlink_data = now; poll_primed = 0; return 1; } @@ -2963,6 +3039,20 @@ static int microlink_publish_hid_fallback(void) return 0; } + /* Publish the measurements before committing the status, not after. + * dstate's status_commit() infers CHRG/DISCHRG from a change in + * battery.charge when the driver reports neither, and by this point + * microlink_publish_runtime() has already written the degenerate + * Microlink value. Committing first let dstate compare that value + * against the previous fallback one and synthesize a DISCHRG that + * contradicted the OL we were setting in the same breath. */ + if (charge >= 0) { + dstate_setinfo("battery.charge", "%ld", charge); + } + if (runtime >= 0) { + dstate_setinfo("battery.runtime", "%ld", runtime); + } + status_init(); if (discharging || !ac_present) { status_set("OB"); @@ -2972,14 +3062,14 @@ static int microlink_publish_hid_fallback(void) if (below_rcl) { status_set("LB"); } - status_commit(); - - if (charge >= 0) { - dstate_setinfo("battery.charge", "%ld", charge); - } - if (runtime >= 0) { - dstate_setinfo("battery.runtime", "%ld", runtime); + /* Report the charging state explicitly rather than leaving dstate to + * guess it from charge movement: the PDC stream tells us directly. */ + if (discharging) { + status_set("DISCHRG"); + } else if (charge >= 0 && charge < 100) { + status_set("CHRG"); } + status_commit(); dstate_setinfo("experimental.hid_fallback.active", "%u", 1U); return 1; @@ -3007,6 +3097,134 @@ static void microlink_publish_hid_fallback_inactive(void) #endif /* WITH_USB */ } +/* Log a handover to or away from the standard-HID-PDC fallback, with the + * reason. Runs on every poll, so it stays silent unless the reason actually + * changed - otherwise a device that sits in one state would repeat this line + * every couple of seconds forever. */ +static void microlink_log_fallback_reason(int reason, time_t now) +{ + static int last_reason = -1; + + if (reason == last_reason) { + return; + } + last_reason = reason; + + switch (reason) { + case MLINK_FB_REASON_STALE: + upsdebugx(1, "microlink: publishing standard-HID fallback data - no " + "Microlink data for %.0f s (threshold %d s)", + (last_microlink_data == 0) + ? 0.0 : difftime(now, last_microlink_data), + MLINK_DATA_STALE_SEC); + break; + + case MLINK_FB_REASON_EMPTY: + upsdebugx(1, "microlink: publishing standard-HID fallback data - the " + "Microlink data is arriving but yielded no ups.status flags"); + break; + + case MLINK_FB_REASON_NONE: + default: + upsdebugx(1, "microlink: publishing Microlink data again, standard-HID " + "fallback no longer needed"); + break; + } +} + +/* Hand over to the standard-HID-PDC snapshot when the Microlink data just + * published did not yield a single ups.status flag. Returns 1 if it took over. + * + * Staleness alone does not catch this: a device can answer every poll on time + * and still report an all-zero status word (seen live on an SCL500RMI1UC stuck + * in "SystemInitialization" - full page walks, fresh frames, every measurement + * zero). An empty ups.status is indistinguishable from a dead UPS to upsmon, + * so where a real one is available from the HID PDC stream, publish that + * instead of nothing. */ +/* 1 if the Microlink data just published looks like a real reading rather + * than the all-zero state a stalled device reports. + * + * Only ups.status is safe to judge this from. microlink_publish_status() + * rewrites it on every poll, so it always reflects the Microlink source + * alone. Other variables are not rewritten unconditionally, so a leftover + * value the fallback itself published on the previous poll can still be + * sitting there - testing battery.charge here made the fallback read its own + * output back, conclude the Microlink side had recovered, and hand over to a + * source that was still publishing nothing. */ +static int microlink_data_plausible(void) +{ + const char *status = dstate_getinfo("ups.status"); + + return (status != NULL + && (strstr(status, "OL") != NULL || strstr(status, "OB") != NULL)); +} + +/* Decide whether the standard-HID-PDC snapshot should own this poll's status, + * and publish it if so. Returns 1 if it took over. + * + * Asymmetric on purpose: the fallback takes over as soon as the Microlink + * source stops looking plausible, but only hands back once Microlink has + * looked plausible continuously for MLINK_FALLBACK_DWELL_SEC. A UPS status + * that flips every couple of seconds is worse than one that lags a real + * recovery by half a minute. + */ +static int microlink_fallback_takes_over(time_t now) +{ + if (microlink_data_plausible()) { + if (!fallback_engaged) { + fallback_recover_since = 0; + return 0; + } + + if (fallback_recover_since == 0) { + fallback_recover_since = now; + } + + if (difftime(now, fallback_recover_since) < MLINK_FALLBACK_DWELL_SEC + && microlink_publish_hid_fallback() + ) { + return 1; + } + + fallback_engaged = 0; + fallback_recover_since = 0; + dstate_setinfo("microlink.diag.status_degenerate", "%u", 0U); + microlink_log_fallback_reason(MLINK_FB_REASON_NONE, now); + return 0; + } + + fallback_recover_since = 0; + + if (!microlink_publish_hid_fallback()) { + return 0; + } + + /* Worth saying out loud, not just at debug level: the tunnel is healthy + * at the protocol layer - frames arrive, checksums pass, page walks + * complete - and the device is still reporting an all-zero state, so + * every derived measurement reads 0 and nothing sets a status flag. + * Observed live on an SCL500RMI1UC; a USB bus reset does not clear it + * (tested), and it survived driver restarts for days, so the user needs + * to know that only power-cycling the UPS itself is likely to help. */ + dstate_setinfo("microlink.diag.status_degenerate", "%u", 1U); + + if (degenerate_warned_at == 0 + || difftime(now, degenerate_warned_at) >= MLINK_DEGENERATE_WARN_INTERVAL_SEC + ) { + degenerate_warned_at = now; + upslogx(LOG_WARNING, "apcmicrolink: the Microlink tunnel is responding " + "normally but the device is reporting an all-zero state (no status " + "flags, all measurements 0) - publishing standard-HID data instead. " + "A USB bus reset does not clear this; the UPS itself likely needs a " + "power cycle. Reported once per hour while it lasts."); + } + + fallback_engaged = 1; + microlink_log_fallback_reason(MLINK_FB_REASON_EMPTY, now); + return 1; +} + + /* If the Microlink tunnel has nothing fresh right now, fall back to the * standard-HID-PDC source instead of an unconditional Data stale. */ static void microlink_datastale_or_fallback(void) @@ -3303,9 +3521,23 @@ void upsdrv_initinfo(void) "battery.charge/battery.runtime); outlet-group data and commands " "will become available automatically once the Microlink session connects", device_path); + } else if (microlink_hid_fallback_possible()) { + /* The usages are there, no report carrying them has just happened + * to arrive yet. They stream independently of the Microlink tunnel, + * so waiting costs nothing and dying here threw away a device that + * could report ups.status within seconds. */ + session_ready = 0; + microlink_fallback_since = microlink_now() - (time_t)microlink_handshake_retries(); + upslogx(LOG_WARNING, "apcmicrolink: could not complete Microlink startup on %s - " + "this device does expose standard HID Power Device usages, but none " + "have been decoded yet; starting up anyway and publishing " + "ups.status/battery.charge/battery.runtime from them as soon as they " + "arrive. Outlet-group data and commands will become available " + "automatically once the Microlink session connects", device_path); } else { fatalx(EXIT_FAILURE, "apcmicrolink: failed to start Microlink session on %s " - "(no standard-HID fallback available on this device either)", device_path); + "and this device exposes no standard HID Power Device usages to fall " + "back on", device_path); } dstate_addcmd("test.battery.start"); @@ -3385,6 +3617,15 @@ void upsdrv_updateinfo(void) good = 1; } + /* A reconnect only proves the device still answers the handshake, not + * that the tunnel is delivering anything. Where it is not, prefer the + * fallback over republishing whatever the Microlink cache last held. */ + if (good && microlink_data_stale(now) && microlink_publish_hid_fallback()) { + microlink_log_fallback_reason(MLINK_FB_REASON_STALE, now); + dstate_dataok(); + return; + } + if (!good) { if (parsed_frames == 0) { session_ready = 0; @@ -3396,6 +3637,10 @@ void upsdrv_updateinfo(void) microlink_publish_identity(); microlink_publish_status(); microlink_publish_runtime(); + if (microlink_fallback_takes_over(now)) { + dstate_dataok(); + return; + } microlink_publish_hid_fallback_inactive(); dstate_dataok(); return; @@ -3406,6 +3651,10 @@ void upsdrv_updateinfo(void) microlink_publish_identity(); microlink_publish_status(); microlink_publish_runtime(); + if (microlink_fallback_takes_over(now)) { + dstate_dataok(); + return; + } microlink_publish_hid_fallback_inactive(); dstate_dataok(); } From dc3dc40728c014b8170fdade1f78f771d1c014b4 Mon Sep 17 00:00:00 2001 From: nmbro Date: Sun, 30 Aug 2026 02:15:45 +0200 Subject: [PATCH 06/11] fix(apcmicrolink): burst-poll a full pass so auth and page reads keep up Root cause: this driver fetched one tunnel record per pollinterval. The device answers requests roughly every 2-3 ms when asked continuously (as PowerChute does), but gates its live-measurement pages behind a slave-password handshake it does not acknowledge until about 20 further exchanges after the response goes out. At one record per pollinterval the handshake's acknowledgement was never collected, and the driver's own readiness check treated sending the response as "done" - so every measurement read 0 indefinitely on a device that was answering normally the whole time. microlink_poll_burst() now drives the tunnel like APC's own client: keep requesting the next record until the device stops answering, once per upsdrv_updateinfo(), budgeted to one full pass over page0.count (bounded by MLINK_POLL_BURST_MIN/MAX and an MLINK_POLL_BURST_MAX_SEC wall-clock ceiling so a slow-answering device cannot hold updateinfo() open indefinitely). The burst also keeps going past its budget while a handshake is in flight (microlink_auth_pending(), MLINK_AUTH_GRACE_SEC), so a session re-established mid-updateinfo() does not send its auth response on the burst's last record and then go quiet before collecting the answer. microlink_check_auth_result() diagnoses the handshake explicitly: experimental.microlink.diag.auth_status / .auth_refused, an hourly LOG_WARNING while refused, and a one-time warning if AUTH_STATUS ever sets a bit this driver does not know about. Readiness still accepts authentication_sent on its own once the grace window closes - a refused handshake still leaves identity data and the standard-HID fallback worth publishing. upsdrv_cleanup() now sends STOP before closing the session. Seen live on an SCL500RMI1UC: exiting mid-burst left the device answering a later client's INIT with whatever page its cursor had reached instead of page 0, and it would not resync until re-enumerated. Also, a batch of descriptor-map corrections gathered while chasing the above (each verified against a live SCL500RMI1UC, several by watching PowerChute write or read the same usage): * 2:4.7.28 and 2:4.7.49 are percentages of nominal, not absolute power - they were mapped straight onto ups.realpower/ups.power, so both read two orders of magnitude low and ups.load then divided one of them by its nominal rating a second time. 2:4.7.28 now feeds ups.load directly, and microlink_publish_derived_power()/microlink_publish_scaled_percent() derive ups.realpower and ups.power (the apparent-power side kept as experimental.ups.load.apparent, since NUT has no standard name for it) by scaling against the nominal ratings, matching PowerChute's own numbers. * ups.test.result now comes from 2:4.5.11 (the battery-scope test, which actually stepped Pending -> InProgress -> Passed during a PowerChute- triggered self test) rather than 2:11 (UPS-scope, never moved off None on this hardware). 2:11 stays mapped under an experimental name and microlink_publish_test_result() promotes it to ups.test.result on any device that lacks the battery-scope usage - descriptor attribute IDs are scope-relative, so a differently built model could populate the other one. * 2:4.5.18 is a self-test *schedule* enum, not the interval-in-seconds ups.test.interval calls for (two of its members have no interval at all). It is now experimental.microlink.battery.test.schedule, and microlink_publish_test_interval() derives ups.test.interval from the members that do imply a recurring period, matched on the raw bits rather than the label text. * New mappings: input.sensitivity (3:25, values confirmed against PowerChute's dropdown), ups.beeper.status (2:4.B.3A, both values round- tripped by writing them from PowerChute), experimental.battery.firmware (2:4.5.9.4A) and experimental.statistics.battery.transfers (2:4.5.F.59, PowerChute's "Number Of Times On Battery"). * Dropped the duplicate device-status publish at 2:4.A: it used the same apc_status_map already consumed via microlink_desc_publish_map into ups.status/alarms, so the second copy was strictly worse (missing LB and the charger flags) rather than a distinct value. * Renamed for consistency: experimental.device.sku and experimental.battery.sku to device.part / experimental.battery.part (they are part numbers, not SKUs); the microlink.* diagnostic namespace to experimental.microlink.* throughout, since none of it is a settled name; and 2:4.9.42 from experimental.device.sku to device.part directly (an existing standard name this driver had not picked up). Use of coding helper tools and AI disclosed: Claude Code was used for development assistance. Signed-off-by: nmbro --- drivers/apcmicrolink-maps.c | 114 +++++++-- drivers/apcmicrolink.c | 450 ++++++++++++++++++++++++++++++++---- drivers/apcmicrolink.h | 13 ++ 3 files changed, 519 insertions(+), 58 deletions(-) diff --git a/drivers/apcmicrolink-maps.c b/drivers/apcmicrolink-maps.c index 462209c396..9f1d85c955 100644 --- a/drivers/apcmicrolink-maps.c +++ b/drivers/apcmicrolink-maps.c @@ -69,6 +69,34 @@ static const microlink_value_map_t retransfer_delay_map[] = { { 0, NULL } }; +/* Sensitivity, confirmed by watching PowerChute write this usage on a live + * SCL500RMI1UC: its dropdown offers exactly these three, and they came back + * as 1, 2 and 4. Value strings follow the lowercase convention the other NUT + * drivers use for input.sensitivity (apc-ats-mib, cps-hid, belkinunv); + * "reduced" is kept rather than remapped onto anyone else's "medium", + * because that is what the device and PowerChute both call it. */ +static const microlink_value_map_t input_sensitivity_map[] = { + { 1UL, "normal" }, + { 2UL, "reduced" }, + { 4UL, "low" }, + { 0, NULL } +}; + +/* Audible alarm. Both values were observed round-tripping on real hardware - + * PowerChute wrote 0xC2 to silence the alarm and 0xC1 to restore it. + * + * NUT also defines a "muted" state, but there is no third value to map here: + * muting is a transient command on a different usage (2:4.B.3B, the + * user-interface command register this driver targets for beeper.mute and + * test.panel.start), not a setting. PowerChute offers only enabled/disabled + * for the same reason. If a device does report a distinct muted value it will + * be published as-is rather than mislabelled. */ +static const microlink_value_map_t beeper_status_map[] = { + { 193UL, "enabled" }, + { 194UL, "disabled" }, + { 0, NULL } +}; + static const microlink_value_map_t output_voltage_setting_map[] = { { (1UL << 0), "VAC100" }, { (1UL << 1), "VAC120" }, @@ -105,6 +133,20 @@ static const microlink_value_map_t language_map[] = { { 0, NULL } }; +/* Self-test schedule. The four members PowerChute offers were read straight + * out of its own