Repository navigation
apcmicrolink: back off failed session starts, don't write from missing pages - #3806
JayToltTech wants to merge 4 commits into
Conversation
Once a session drops into the HID fallback, `upsdrv_updateinfo()` retries the Microlink handshake every `MLINK_SESSION_RETRY_INTERVAL_SEC`, which is 1 s, forever. Every retry is a STOP and an INIT, and every one that gets far enough sends the slave password again. On an SCL500RM1UC (FW UPS 16.5) here the UPS reset every 4-5 minutes for about 20 minutes while the driver logged a failed Microlink startup on each boot. It stopped when I pulled the USB cable. I can't prove the retry loop is what did it, but a device that's already refusing sessions shouldn't get probed once a second. This doubles the wait after each failed retry, 1 s up to `MLINK_SESSION_RETRY_MAX_SEC` (60 s), and resets it once a session comes up. Status still publishes from the HID fallback on every poll in between. Against a fake Microlink device on a pty that goes silent mid-session, master sent 186 INITs in 183 s and this sends 7, at 1/2/4/8/16/32/60 s. It reconnects when the device comes back, up to 60 s later than master would. Signed-off-by: Jay Beavers <jay@tolttechnologies.com>
|
Preparing a ZIP file with standard source tarball and another tarball with pre-built docs for commit 9b295ec ... |
36d26a3 to
894469a
Compare
nmbro
left a comment
nmbro
left a comment
There was a problem hiding this comment.
Thanks for the submission, and for splitting it into one commit per change. The fake-device numbers (186 INITs against 7) make the backoff easy to judge.
I hit something close to this on an SCL500RM1UC (FW UPS 16.1) on USB. After a test build of the driver was force-stopped on Windows, every new start logged could not complete Microlink startup and never reached session_established. Standard HID reads kept working. It stayed that way across two VMs, two builds, a 5-minute wait and two USB replugs. The UPS never reset itself while I watched, and no slave password went out, since no session got that far. So in my case the Microlink side got stuck without any password retries. Nine days later, with nothing talking to it in between, it started a full Microlink session again on the first try.
A few notes inline.
| } | ||
|
|
||
| for (p = off / page0.width; p <= (off + len - 1U) / page0.width; p++) { | ||
| if (p >= page0.count || !microlink_get_object((unsigned int)p)->seen) { |
There was a problem hiding this comment.
objects[] is only cleared in upsdrv_initinfo(), so after an in-process reconnect seen means "received at some point since the driver started", not in this session. This accepts a page that only the earlier session delivered. A per-session flag, cleared in microlink_start_session_impl(), would fix this and the AUTH_STATUS check below.
There was a problem hiding this comment.
Agreed. Fixed in 9b16d8f with a per-session flag, as you suggested.
| return 0; | ||
| time_t now = microlink_now(); | ||
|
|
||
| if (microlink_auth_data_valid()) { |
There was a problem hiding this comment.
This can read the previous session's AUTH_STATUS page (see the note on microlink_blob_range_seen()). If the UPS rebooted, as in your case, and that page hasn't come round again before the last page arrives, the driver sets authentication_accepted = 1 and doesn't send the password for the whole session. Before this change it always re-sent the password after a reconnect.
There was a problem hiding this comment.
Yes, and it was worse than the seen issue, since microlink_auth_data_valid() didn't check receipt at all. Reproduced it on a fake device: after the reboot the driver logged "AUTH_STATUS already valid" off the cached page and never sent the password. It now requires the AUTH_STATUS page to have come in this session.
| authentication_sent = 1; | ||
| authentication_sent_at = now; | ||
| authentication_accepted = 1; | ||
| } else if (authentication_last_write_at != 0 |
There was a problem hiding this comment.
During this hold-off authentication_sent stays 0 and the device serves no measurement pages. Other pages keep last_microlink_data fresh, so as far as I can tell the driver goes on publishing the previous session's cached measurements as current. Is that what you saw, or does the HID fallback take over here?
There was a problem hiding this comment.
Didn't see it. The hold-off never fired on the real UPS. But you're right that it would. While the password is held off it now publishes the HID fallback where there is one, and marks the data stale otherwise. I've only exercised the stale half, on serial.
| no longer leaves a transfer outstanding. [issue #3751, PR #3778] | ||
| * A failed Microlink session start is now retried after a doubling | ||
| wait of 1 up to 60 seconds instead of every second, and the slave | ||
| password is sent at most once per 5 minutes across sessions, or not |
There was a problem hiding this comment.
authentication_last_write_at lasts only as long as the process, so a driver restart (by systemd or upsdrvctl) sends the password again right away. "Across sessions" could be read as across restarts too.
There was a problem hiding this comment.
Fair. Reworded to say it lasts for one driver run and a restart sends it again at once.
|
|
||
| /* One write frame addresses one page; a field running past it, or on a page | ||
| * never received, would land somewhere the map cannot vouch for. */ | ||
| if (offset + usage->size > page0.width || page >= page0.count |
There was a problem hiding this comment.
This refuses any write that crosses a page boundary. Did you check whether any writable field in the SCL500's map crosses one? A write that worked before would now fail with only a warning in the log.
There was a problem hiding this comment.
I haven't checked yet. The only write that went out here is the slave password, to page 101, and it fits in one page. Before this change the driver would have sent a single frame running past the page end, and I don't know what the UPS does with that either, so I'd rather refuse it with a warning than find out. I'll dump the SCL500's map and post whether anything crosses.
| if (!session_ready) { | ||
| microlink_fallback_retries++; | ||
| microlink_session_next_retry = now + MLINK_SESSION_RETRY_INTERVAL_SEC; | ||
| microlink_session_next_retry = now + microlink_session_retry_wait; |
There was a problem hiding this comment.
This also delays the microlink_usb_device_gone() check above, so after a real unplug the reopen can wait up to 60 s longer than before. That seems fine, but it could go in the NEWS entry.
Review of PR networkupstools#3806 caught that `objects[].seen` is only cleared at driver start, so after a reconnect a page counts as received if any earlier session delivered it. Two things followed from that. The page guards could pass on a previous session's page. Worse, `microlink_auth_data_valid()` never checked receipt at all, so after a UPS reboot the stale cached AUTH_STATUS read valid and the driver skipped the slave password for the whole session. Before this PR it always re-sent the password after a reconnect. This adds a per-session `session_seen` flag, cleared in `microlink_start_session_impl()`, and uses it for the page guards and the AUTH_STATUS check. `seen` stays as is, since frame-length parsing depends on it across reconnects. While the password is held off the device serves no measurement page, but other pages keep `last_microlink_data` fresh, so the driver went on publishing the previous session's readings as current. It now publishes the standard HID PDC fallback where there is one and marks the data stale otherwise. The NEWS entry now says the 5-minute limit lasts only for one driver run, and that the retry backoff also spaces the USB unplug check. Tested against a fake serial device that requires the password and reboots with AUTH_STATUS clear. Before this change the driver read the stale valid bit, never re-sent the password, and sat at AUTH_STATUS 0x0000. After it, the password goes out as soon as the AUTH_STATUS page arrives, or once the 5-minute hold-off ends, and upsd reports the data stale for the length of the hold-off. The earlier backoff and missing-page scenarios give the same results as before. Signed-off-by: Jay Beavers <jay@tolttechnologies.com>
|
Thanks for the careful read, and for the SCL500 data point. A Microlink side that wedges with no slave password going out is interesting. Ours reset itself a few times while the old driver was failing startup in a loop, and I never pinned down the cause, so the password retries were a suspect rather than a finding. Yours suggests the session traffic alone can do it. Pushed 9b16d8f for the inline points. Pages now carry a per-session Tested against a fake serial device that requires the password and reboots mid-run with AUTH_STATUS clear. On 894469a the driver read the stale valid bit after the reboot, never re-sent, and sat at 0x0000 with the 'not acknowledged' warning. On 9b16d8f it re-sends as soon as the AUTH_STATUS page comes round, or after the 5-minute hold-off if a write went out recently, with upsd reporting the data stale for the length of the hold-off. |
|
do be aware that the serial and usb part of the microlink behave a little different timing wise |
|
Ran 9b16d8f on the real SCL500RM1UC (FW UPS 16.5, USB) and pulled the cable mid-run. The rate limit turned out to be the problem, so da8df3c drops it. With the limit: the driver reopened USB and got a session about 2 s after the replug. The UPS had cleared AUTH_STATUS, so the driver held the password back, since the last one went out 4 minutes earlier. About 10 s later the UPS stopped answering the tunnel. In-process retries never got it back over the next 4 minutes, but a fresh driver process got a session and auth straight away. Without the limit, same cable pull: USB reopened, session up, password out and AUTH_STATUS 0x0001 about 3 s after the replug, no intervention. So the limit was a guess at what reset ours on 10/29, and it does harm. Together with your wedge with no password going out, I don't think the password retries were ever the cause. The backoff already bounds how often the password can go out, since it only goes out after a full descriptor read. The 'already valid' skip and the received-pages guard stay, and the hold-off stale-data handling went with the limit. On the page boundary question: I dumped the map on this unit. None of the 31 writable fields in it crosses a page, and none sits on page 91, the one it never sends. Six read-only usages do cross ( Two things the cable pull showed that this PR doesn't touch:
Can open separate issues for those, your call. |
`microlink_update_blob()` zero-fills any page the device hasn't sent, and the descriptor is parsed from that blob and every write takes its address from it. The SCL500RM1UC here reports 103 pages and never sends 0x5B, so the blob always has a hole in it. Was going to require every page before accepting the descriptor, but on this unit that never completes. So this checks the pages that matter instead. The descriptor's own bytes have to come from received pages, and `microlink_send_descriptor_write()` refuses a write whose field crosses a page or sits on a page that wasn't received. "Received" means in the current session. `objects[].seen` is only cleared at driver start, and after a reconnect the blob still holds the earlier session's pages, so this adds a `session_seen` flag cleared in `microlink_start_session_impl()`. `seen` stays as is, since frame-length parsing depends on it across reconnects. It also caps the startup loop in `upsdrv_initinfo()` at `MLINK_STARTUP_MAX_SEC` (60 s) once a session answers. A device that keeps replying but never completes the descriptor holds startup forever otherwise, since `consecutive_timeouts` never climbs. After the cap it drops to the HID fallback like any other failed startup. On the real unit the descriptor comes up with 268 usages despite the missing page, and none of the 31 writable fields in its map crosses a page or sits on the missing one. Against a fake device with a missing page outside the descriptor, startup completes, and with the descriptor running into the missing page it stops at 60 s. I haven't seen the write refusal fire on real hardware. Signed-off-by: Jay Beavers <jay@tolttechnologies.com>
…ng it The slave password is computed from the serial number and master password in the descriptor blob, so with a page missing it goes out computed from zero fill. This holds it until both have arrived in the current session. It also skips the write when AUTH_STATUS, received in the current session, already reads valid. The current-session part matters: on this UPS a USB replug clears AUTH_STATUS, and a stale cached valid bit would keep the driver from authenticating at all. Tested against a fake device that requires the password and reboots mid-run with AUTH_STATUS clear: the password goes out again on the next page cycle and is accepted. On the SCL500RM1UC a USB cable pull mid-run recovers by itself, with AUTH_STATUS 0x0001 about 3 s after the replug. Signed-off-by: Jay Beavers <jay@tolttechnologies.com>
Signed-off-by: Jay Beavers <jay@tolttechnologies.com>
da8df3c to
9b295ec
Compare
|
✅ Build nut 2.8.5.5945-master completed (commit cd3936dd42 by @JayToltTech)
|
An SCL500RM1UC (FW UPS 16.5) here on USB reset itself every 4-5 minutes for about 20 minutes one morning, taking everything plugged into it down each time. The driver logged
could not complete Microlink startupon every boot in that window, and the resets stopped when I pulled the USB cable. I can't prove the driver caused it, there's no event log I can get off this unit, but reading the code turned up three things I'd rather not have pointed at a UPS that's already misbehaving.upsdrv_updateinfo()retries the handshake every second forever.microlink_update_blob()zero-fills pages the device never sent, and the descriptor and every write address come from that blob. This unit reports 103 pages and never sends 0x5B.upsdrv_initinfo()never exits, sinceconsecutive_timeoutsnever climbs.Retries now back off 1 to 60 s. Writes and the slave password are refused when a page they depend on wasn't received in the current session, and the password isn't sent while AUTH_STATUS received in the current session reads valid. Startup gives up after 60 s and drops to the HID fallback.
Was going to require every page before accepting the descriptor, but on this unit that never completes, so the checks are per page instead.
An earlier revision also had a 5-minute password rate limit, since squashed out. On a cable pull the UPS clears AUTH_STATUS, and holding the password back stalled the tunnel until the driver restarted. Details are in the thread, where the commit hashes refer to the pre-squash branch.
Ran it on the SCL500RM1UC at
-DDand it's in service now. The descriptor comes up with 268 usages despite the missing page, the only write is the 4-byte slave password to page 101, and AUTH_STATUS reads 0x0001 about 3.5 s later. A USB cable pull mid-run recovers by itself: reopen, session, password and AUTH_STATUS 0x0001 about 3 s after the replug. None of the 31 writable fields in this unit's map crosses a page or sits on the missing one.Against a fake Microlink device on a serial pty, master sends 186 INITs in 183 s of silence and this sends 7, then reconnects when the device comes back. A missing page outside the descriptor doesn't block startup, and a descriptor running into a missing page stops at 60 s. A device that reboots with AUTH_STATUS clear gets the password again on the next cycle, where 0.08 before the review fix read the stale valid bit and never re-sent.
I haven't seen the write refusal fire on real hardware, and it's one UPS model. Each commit builds on its own and
make spellcheckpasses.Claude Code was used for the code review, the patch and the testing.