Not enough values to unpack for certain NAMES entries when behind ZNC

[dgw]

Description

I just updated our official instance to current master (8d077a0) and observed some errors in its startup log upon reconnecting to Libera, apparently related to NAMES replies not always containing the hostmask for every value.

Reproduction steps

0. Enable both raw and debug logging, for completeness
1. Connect Sopel to Libera via ZNC, preferably in a channel with a decent user count such as #sopel
2. Observe "Not enough values to unpack" errors from certain lines in the initial NAMES responses

Expected behavior

Sopel should not error, as this means it will fail to process the whole line. Regardless of whether Libera's IRCd is breaking spec by failing to always include hostmasks in NAMES when the relevant capability is enabled, Sopel should gracefully handle this case.

Relevant logs

# just one of several NAMES lines that triggered this, all including at least
# one nick that had no !user@host.name after it

[2022-06-24 06:03:33,451] sopel.bot            ERROR    - Unexpected error (not enough values to unpack (expected 2, got 1)) from
  silver.libera.chat at 2022-06-24 06:03:33.450989. Message was: AFKnuke!nuke@connection.reset.by.peer.sbs Benett
  Chex!~Chex@user/chex +Duckle!~Duckle@user/duckle +Exirel!sid255844@sopel-irc/rockstars/Exirel Foxy!foxy@user/foxy
  GNU\Andrew!Andrew@user/AndrewYu +HumorBaby!HumorBaby@sopel-irc/rockstars/HumorBaby Legomannetje
  Noisytoot!~noisytoot@sourcehut/user/noisytoot Pilate!~pilate@pilate.io RhinosF1!sid339563@miraheze/RhinosF1
  +RustyCloud Sario!sid356235@fosshost/cdo/Sario ShArkZ SnoopJ!~snoopj@user/snoopj +Sopel!Sopel@sopel/official/bot
Traceback (most recent call last):
  File "/home/sopel/sopel-git/sopel/bot.py", line 620, in call_rule
    rule.execute(sopel, trigger)
  File "/home/sopel/sopel-git/sopel/plugins/rules.py", line 1117, in execute
    exit_code = self._handler(bot, trigger)
  File "/home/sopel/sopel-git/sopel/coretasks.py", line 524, in handle_names
    name, mask = name.rsplit('!', 1)
ValueError: not enough values to unpack (expected 2, got 1)

# relevant raw log
# note attempted PRIVMSG of error to the server hostname, which we might also consider trying to avoid doing

2022-06-24 06:03:33,449 <<	'@time=2022-06-24T06:03:33.378Z :silver.libera.chat 353 Sopel = #1472 
  :AFKnuke!nuke@connection.reset.by.peer.sbs Benett Chex!~Chex@user/chex +Duckle!~Duckle@user/duckle
  +Exirel!sid255844@sopel-irc/rockstars/Exirel Foxy!foxy@user/foxy GNU\\Andrew!Andrew@user/AndrewYu
  +HumorBaby!HumorBaby@sopel-irc/rockstars/HumorBaby Legomannetje Noisytoot!~noisytoot@sourcehut/user/noisytoot
  Pilate!~pilate@pilate.io RhinosF1!sid339563@miraheze/RhinosF1 +RustyCloud Sario!sid356235@fosshost/cdo/Sario ShArkZ
  SnoopJ!~snoopj@user/snoopj +Sopel!Sopel@sopel/official/bot\r\n'
2022-06-24 06:03:33,454 >>	'PRIVMSG silver.libera.chat :Unexpected error (not enough values to unpack (expected 2,
  got 1)) from silver.libera.chat at 2022-06-24 06:03:33.450989. Message was: AFKnuke!nuke@connection.reset.by.peer.sbs
  Benett Chex!~Chex@user/chex +Duckle!~Duckle@user/duckle +Exirel!sid255844@sopel-irc/rockstars/Exirel
  Foxy!foxy@user/foxy GNU\\Andrew!Andrew@user/AndrewYu +HumorBaby!HumorBaby@sopel-irc/rockstars/HumorBaby
  Legomannetje Noisytoot!~noisytoot@sourcehut/user/noisytoot Pilate!~pilate@pilate.io RhinosF1!sid33956\r\n'

Notes

Likely related to #2102, though I have not taken the time tonight for anything like a git bisect to prove it. Honestly, the relevant code seems obvious enough to skip that step.

I have amended the report to include that Sopel was connecting via ZNC, a fact I forgot about initially.

Sopel version

8d077a0

Installation method

pip install

Python version

4.9

Operating system

No response

IRCd

solanum-1.0-dev via ZNC 1.8.2

Relevant plugins

No response

[dgw]

"Can't sleep, bug report will eat me." — Connecting directly to Libera on the same commit (plus one unrelated WIP change to the EntryPointPlugin handler) did not reproduce the observed error; Libera appears to send all the hostnames, which points to something in ZNC being an issue. Next test should be to try ZNC 1.9-dev/nightly and see if the same error recurs.

@HumorBaby is that something you can test for me without disrupting your regular setup? If not I'll get a local ZNC built sometime this weekend. (I hope.)

[half-duplex]

Duplicate of #2289, I think.

[dgw]

Not the same. Libera and ZNC (as tested) both advertise and ACK userhost-in-names; UHNAMES isn't involved in this one.

The same workaround/mitigation could apply to both, though: gracefully handle missing hostmask even when Sopel expects it to be present.

[dgw]

Reproduced on freshly built ZNC 1.9.x-git-176-fab1bb1b today. On my test instance, which had been started less than a minute or two before Sopel connected, it appeared that only Sopel had a hostmask included in the 353 lines.

Noticed znc/znc#1224 after a bit of digging. So yes, the workaround I stated last night is still the safe bet: Handle missing userhosts gracefully, even if we're expecting the server to include them, because… sometimes it won't.

---

Also noticed in the raw log that one of the 353s contained a truncated nick ('deathbyba\r\n' ended the line, instead of the full 'deathbybandaid'), but haven't dug into that. It's probably a separate issue, and not ours to solve anyway.

Never mind this, I was reading Sopel's own error PRIVMSG, which truncated the raw line it received to fit the error message and so forth.

2022-06-24 18:09:26,624 <<	'@time=2022-06-24T23:09:26.600Z :zinc.libera.chat 353 SopelTest = #sopel :AFKnuke Benett Chex +Duckle +Exirel Foxy GNU\\Andrew +HumorBaby Legomannetje Noisytoot Pilate RhinosF1 +RustyCloud Sario ShArkZ SnoopJ +Sopel SopelTest!~sopel@68-168-183-9.fttp.usinternet.com Speed2u Strykar Supersta1s111 Techcable TheCoffeMaker Thornelius TimeRider TypoToni adamus1red calebj carstene1ns catbeard corsican cottongin deadyeti deathbybandaid derelict +dgw dmehus dreamer duds- fatalis hekel jaqque kiska3 luk3yx +mal mboehn milkii op873\r\n'
2022-06-24 18:09:26,639 >>	'PRIVMSG zinc.libera.chat :Unexpected error (not enough values to unpack (expected 2, got 1)) from zinc.libera.chat at 2022-06-24 23:09:26.625682. Message was: AFKnuke Benett Chex +Duckle +Exirel Foxy GNU\\Andrew +HumorBaby Legomannetje Noisytoot Pilate RhinosF1 +RustyCloud Sario ShArkZ SnoopJ +Sopel SopelTest!~sopel@68-168-183-9.fttp.usinternet.com Speed2u Strykar Supersta1s111 Techcable TheCoffeMaker Thornelius TimeRider TypoToni adamus1red calebj carstene1ns catbeard corsican cottongin deadyeti deathbyba\r\n'

[Exirel]

Does #2312 fix the issue?

[dgw]

"Fix" as in "works around". The error shouldn't happen any more; Sopel should just store incomplete user info like it would on servers without the feature. If you think it's sufficient, go ahead and close this.

[Exirel]

Yup, I don't really see how we can do better when the server makes a promise and then proceed to break it. Not crashing is good enough for me at this point.