circe-duration-string and related issues

[defanor]

Bitlbee, as well as some IRC servers, don't seem to provide time on netmerge, or Circe doesn't parse it correctly. In any case, would be nice to handle the case when the value is zero, and just not show a date then.

That also exposes another issue: strings such as "47 years 2 months 10 days 11 hours 46 minutes 24 seconds ago" are somewhat wrong (it's not 47 years since 1970 now, while (circe-duration-string (float-time)) claims that), and perhaps showing exact dates would be more useful anyway, if it's more than a few days (maybe a week, or a month).

[jorgenschaefer]

Hello, and thanks for the suggestion!

I like the second suggestion (though duration is always nice, if it's in the range of weeks, we do not need hours, say, and a full timestamp is useful if it's not a short duration as you say).

I do not understand the first point. "Time on netmerge"? What does that mean? Bitlbee, being a single system, does not do net merges at all?

[defanor]

Bitlbee shows disconnects from e.g. XMPP as netsplits, and then there are netmerges.

I'm not sure how exactly a netmerge message looks like, but for some reason Circe shows a correct time on freenode, and those 47 years with Bitlbee and some other servers.

[jorgenschaefer]

I am still not sure what you are talking about. Maybe you could provide all the details?

A "net split" as detected by Circe is indicated by a QUIT message of other users with two server names as the argument. A "net merge" is a JOIN of someone who has QUIT with such a message not too long ago. It sounds like as if the heuristics Circe is using for netsplits is breaking somehow for Bitlbee. More details would be useful.

Setting irc-debug-log to t and providing the actual protocol details in those situations (including the QUIT messages and re-JOIN messages), as well as the contents of circe-netsplit-list after the split messages, would be very useful :-)

[defanor]

Oh, in that case it's pretty strange that it behaves that way. I'll try to reproduce it with the debug log soon.

[defanor]

Turns out that it happens on regular "account X off" and "account X on" commands in Bitlbee, not necessarily on reconnect. Here are quits and joins:

S: :user1!user1@host1 QUIT :localhost.localdomain my-host E: "QUIT" "user1!user1@host1" "localhost.localdomain my-host" E: "channel.quit" "user1!user1@host1" "&bitlbee" "localhost.localdomain my-host" S: :user2!user2@host2 QUIT :localhost.localdomain my-host E: "QUIT" "user2!user2@host2" "localhost.localdomain my-host" E: "channel.quit" "user2!user2@host2" "&bitlbee" "localhost.localdomain my-host" S: :user3!user3@host2 QUIT :localhost.localdomain my-host E: "QUIT" "user3!user3@host2" "localhost.localdomain my-host" E: "channel.quit" "user3_!user3@host2" "&bitlbee" "localhost.localdomain my-host"

S: :user1!user1@host1 JOIN &bitlbee * :user1 E: "JOIN" "user1!user1@host1" "&bitlbee" "" "user1" S: :localhost.localdomain MODE &bitlbee +v user1 E: "MODE" "localhost.localdomain" "&bitlbee" "+v" "user1" S: :user2!user2@host2 JOIN &bitlbee * :user2 E: "JOIN" "user2!user2@host2" "&bitlbee" "" "user2" S: :localhost.localdomain MODE &bitlbee +v user2 E: "MODE" "localhost.localdomain" "&bitlbee" "+v" "user2" S: :user3!user3@host2 JOIN &bitlbee * :user3 E: "JOIN" "user3!user3@host2" "&bitlbee" "*" "user3" S: :localhost.localdomain MODE &bitlbee +v user3 E: "MODE" "localhost.localdomain" "&bitlbee" "+v" "user3"

Circe messages:

*\ Netsplit: localhost.localdomain my-host (Use /WL to see who left)

*\ Netmerge: localhost.localdomain my-host, split 47 years 2 months 10 days 13 hours 37 minutes 24 seconds ago (Use /WL to see who's still missing)

And mode changes after that.

[jorgenschaefer]

What's the value of circe-netsplit-list after the quit messages?

[defanor]

(("localhost.localdomain my-host" 1467986626.4598465 1467986629.3845172 #s(hash-table size 65 test equal rehash-size 1.5 rehash-threshold 0.8 data ("user1" "user1" "user2" "user2" "user3" "user3"))))

That's its local value in the server buffer, the global value is nil.

[jorgenschaefer]

That looks correct to me.

If you then do M-: (circe--netsplit-join "user1_"), what does that return?

[defanor]

It returns nil.

[jorgenschaefer]

After seeing QUITs, before the net merge, using a nick of those named in circe-netsplit-list?

[defanor]

Ouch, sorry, I've just copied and pasted it. It's ("localhost.localdomain my-host" 1467986626.4598465).

[jorgenschaefer]

Circe then does (circe-duration-string (- (float-time) 1467986626.4598465)) which should be fine (47 minutes something). I am confused how Circe would get the 47 years you mentioned. :-(

[defanor]

I've connected again now, and got this:

*\ Netmerge: localhost.localdomain my-host, split 21 minutes 52 seconds ago (Use /WL to see who's still missing)

Apparently it doesn't happen always. But @wasamasa also mentioned that it happens, and I've observed it plenty of times before, so it's not that uncommon.

Now I've turned the bitlbee xmpp account off and on again, got 47 years. And off again, now there is ("localhost.localdomain my-host" 0) in (circe--netsplit-join "user1_"), and circe-netsplit-list looks like this:

(("localhost.localdomain my-host" 1467989772.685837 1467989745.0435324 #s(hash-table size 65 test equal rehash-size 1.5 rehash-threshold 0.8 data ( "user2" "user2" "user3" "user3"))))

No user1 there, though they were online before disconnect (I've seen a +v message in bitlbee, at least). Though didn't see a join and mode change of another user (user2) when connected again. But it still detects the time correctly when connecting again after that.

So, looks like there should be some other conditions that lead to such a behaviour – I don't know how to reproduce that.

Off and on again, 47 years again. And one more time. And off again, now all 3 users are in circe-netsplit-list, but it looks like this:

(("localhost.localdomain my-host" 0 1467990297.7786887 #s(hash-table size 65 test equal rehash-size 1.5 rehash-threshold 0.8 data ("user1" "user1" "user2" "user2" "user3" "user3"))))

circe--netsplit-join returned 0 for one user, then a correct timestamp for another one, and then both were nil. Oh, apparently it removes the users from the hash when invoked – that explains what happened to the first user above.

Connected after that, got a correct message about 4 minutes. Disconnected (account X off), invoked (circe--netsplit-join "user2_") in the bitlbee control channel buffer, got ("localhost.localdomain my-host" 0), connected again – got no netmerge message at all, a single join message, and two mode changes (+v), for 3 users.

[jorgenschaefer]

(circe--netsplit-join "user2_") in the bitlbee control channel buffer, got ("localhost.localdomain my-host" 0)

That's the bug right there. Now, how does it happen. :-(