Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Ban logging verbosity #2144

Closed
wants to merge 15 commits into from

Conversation

@spede
Copy link
Contributor

commented Feb 29, 2016

Adds logging for ban removals/changes.
#1996

b.haAddress.toString(),
b.qsUsername,
b.qsReason,
b.iDuration == 0 ? "Permanent" : "Temporary"));

This comment has been minimized.

Copy link
@hacst

hacst Mar 4, 2016

Member

Given the potentially controversial nature of bans I think it might be helpful to log the whole actual ban with all fields. Because of that we should probably log iMask and the given start and duration instead of trying to simplify it to permanent and temporary (though that might be useful as an addon note to simplify grepping for it). Would also add a "Hash: " before %1 to make it clear it's the hash field (can be empty after all). Reason (maybe other fields too?) should be quoted.

}
foreach(const Ban &tmpBan, tmpBans) {
if (! qlBans.contains(tmpBan)) {
log(uSource, QString("Removed ban: %1, Host: %2, Username: %3, Reason: %4, Length: %5").arg(

This comment has been minimized.

Copy link
@hacst

hacst Mar 4, 2016

Member

Might be worth extracting the "turn a ban into a string" functionality into the Ban class (maybe as toString). Not sure if we need it in any other locations but with just the two locations here it would already simplify things.

@hacst

This comment has been minimized.

Copy link
Member

commented Mar 4, 2016

Hi. Sounds like a very useful feature for server admins to figure out what happened. Only thing I'm a bit concerned about are the high complexity operations: contains on QList is an O(n) operation and doing that inside the loop it's in turns it into O(n^2) for the most common case of basically nothing changing in the list). Depending on the amount of bans on the server this might have excessive runtime. Could you test it with say 1'000 before and after to see how much of an effect there really is? Shooooouuuld be fine for these operations but better safe than sorry.

@mkrautz How much do we care about DOS potential on that surface and how realistic is it? If someone has permissions to ban the world he has plenty of potential to cause havoc on a vserver already. As far as I can see this one might hang one vserver (loading one core). What I'm a bit more concerned about is whether this can be used to logspam enough to hang the server DB or fill the disc affecting a full server.

@spede

This comment has been minimized.

Copy link
Contributor Author

commented Mar 4, 2016

I'll test the contains with very high banlist lengths as soon as I can. Though, I wonder if it would be good enough to test for a.qsHash == b.qsHash || a.haAddress == b.haAddress and ditch contains completely.

@spede

This comment has been minimized.

Copy link
Contributor Author

commented Mar 5, 2016

Tried with a banlist length of ~1200 on a fresh DigitalOcean 1GB/1vCore droplet. Nothing seems off server side. I modified a couple dozen entries at once in client and it all seemed to work just fine.

Log of adding/removing bans with this patch on a database with 1260 bans:

<W>2016-03-05 21:59:31.019 1 => <1:SuperUser(0)> Authenticated
<W>2016-03-05 22:00:00.400 1 => <1:SuperUser(0)> New or changed ban: Hash: "176de480923489333f25", Host: "80.255.21.25", Mask: "32", Username: "someguy", Reason: "Spammer!", BanStart: "la maaliskuuta 5 21:59:59 2016", BanEnd: "la maaliskuuta 5 21:59:59 2016" (permanent)
<W>2016-03-05 22:00:00.400 1 => <1:SuperUser(0)> New or changed ban: Hash: "17651480923489333f25", Host: "80.123.123.123", Mask: "32", Username: "spede", Reason: "Spammer!", BanStart: "la maaliskuuta 5 21:59:45 2016", BanEnd: "la maaliskuuta 5 21:59:45 2016" (permanent)
<W>2016-03-05 22:00:00.456 1 => <1:SuperUser(0)> Updated banlist
<W>2016-03-05 22:00:46.110 1 => <2:SuperUser(0)> Authenticated
<W>2016-03-05 22:00:54.227 1 => <2:SuperUser(0)> Removed ban: Hash: "176de480923489333f25", Host: "80.255.21.25", Mask: "32", Username: "someguy", Reason: "Spammer!", BanStart: "la maaliskuuta 5 21:59:59 2016", BanEnd: "la maaliskuuta 5 21:59:59 2016" (permanent)
<W>2016-03-05 22:00:54.227 1 => <2:SuperUser(0)> Removed ban: Hash: "17651480923489333f25", Host: "80.123.123.123", Mask: "32", Username: "spede", Reason: "Spammer!", BanStart: "la maaliskuuta 5 21:59:45 2016", BanEnd: "la maaliskuuta 5 21:59:45 2016" (permanent)
<W>2016-03-05 22:00:54.254 1 => <2:SuperUser(0)> Updated banlist
@hacst

This comment has been minimized.

Copy link
Member

commented Mar 6, 2016

Cool. Sounds like normal use won't be a problem then. Still waiting for @mkrautz to chime in about the attack surface stuff but apart from that this looks pretty good.

We should probably format the datetimes like we do for the log-lines (.toString("yyyy-MM-dd hh:mm:ss.zzz")) (doubt we need the .zzz part ;) ) to keep them consistent.

About the comparison function: It's a bit hard to judge when to consider bans to be equivalent. There might even be use-cases for multiple bans on the same user/subnet with differing reasons and durations...for now I would probably leave it as is. (btw: Unless you also consider the mask the address alone is kinda meaningless)

Generally speaking it is unfortunate the banlist protocol is as it is. Always replacing everything is a bit simplistic. Probably should rethink/extend that for the future. Maybe giving bans real identity. It works though so.... ;)

@spede

This comment has been minimized.

Copy link
Contributor Author

commented Mar 6, 2016

Yeah, it's a bit curious the way ban changes are handled under the hood. But as you say, it works. I've never heard anyone complain about the ban system being confusing, unlike, for example, the ACLs ;), so it would seem to me that any unfortunate behavior therein is not visible to a regular mumble admin/user. Which is good!

On another note, I changed the timestamps to be consistent.

haAddress.isV6() ? QString::number(iMask) : QString::number(iMask-96),
qsUsername,
qsReason,
qdtStart.toLocalTime().toString("yyyy-MM-dd hh:mm:ss"),

This comment has been minimized.

Copy link
@mkrautz

mkrautz Mar 11, 2016

Member

Wrap string in QLatin1String.

This comment has been minimized.

Copy link
@mkrautz

mkrautz Mar 11, 2016

Member

Can we please add a TZ to the date string? Just to avoid confusion? People might think it's UTC. (What do our log timestamps use, actually?)

This comment has been minimized.

Copy link
@hacst

hacst Mar 12, 2016

Member

Our log timestamps are also localtime. I checked that and since this matched I didn't consider leaving the TZ out important.

qsReason,
qdtStart.toLocalTime().toString("yyyy-MM-dd hh:mm:ss"),
qdtStart.toLocalTime().addSecs(iDuration).toString("yyyy-MM-dd hh:mm:ss"),
iDuration == 0 ? "(permanent)" : "(temporary)"

This comment has been minimized.

Copy link
@mkrautz

mkrautz Mar 11, 2016

Member

Wrap strings in QLatin1String.

foreach(const Ban &tmpBan, tmpBans) {
if (! qlBans.contains(tmpBan)) {
log(uSource, QString("Removed ban: %1").arg(tmpBan.toString()));
}

This comment has been minimized.

Copy link
@mkrautz

mkrautz Mar 11, 2016

Member

I think I'd actually prefer if "tmpBans" was a QSet ("previousBans"?), and once we have qlBans filled out, create a QSet copy if it ("newBans"?).

Then we can simply work out the diff by using the two sets.

QSet added = newBans - previousBans;
QSet removed = previousBans - newBans;

Then print them. It makes the code clearer, at least to me.

WDYT?

@spede

This comment has been minimized.

Copy link
Contributor Author

commented Mar 12, 2016

@mkrautz Yes I agree it's clearer that way.

I wonder what would be the smartest way to implement qHash for the Ban class? Out of my depth with Qt but seems like I got it working. :)

@mkrautz

This comment has been minimized.

Copy link
Member

commented Mar 13, 2016

I can't think of a good qHash for a Ban, since it pretty much needs everything in the Ban to be unique.

And FWIW, the qHash overlay you're using for QString is only available in Qt 5. We'll be shipping 1.3.x with Qt 4 compatibility, so we'll need something that works there, too. :(

@mkrautz

This comment has been minimized.

Copy link
Member

commented Mar 13, 2016

Oops, sorry! I see that according to http://doc.qt.io/qt-4.8/qhash.html#qHash-20, it implemented for QString.

I was looking at qHash overload that is exclusive to Qt 5. Sorry.

@mkrautz mkrautz self-assigned this Apr 8, 2016

@mkrautz

This comment has been minimized.

Copy link
Member

commented Apr 28, 2016

One thing I didn't consider when suggesting we use QSets is that we don't get a "removed" notification if there are duplicates in the banlist.

Is that good enough? @spede @hacst?

@mkrautz

This comment has been minimized.

Copy link
Member

commented Apr 28, 2016

Technically, I guess the behavior with QSets is "correct". While a ban was removed, the server has one or more ban entries that are 100% equivalent. So the ban is still in effect.

@mkrautz

This comment has been minimized.

Copy link
Member

commented Apr 28, 2016

BTW, squished the PR:
master...mkrautz:ban-diff

And changed qHash() for Ban& to XOR instead of creating a string and qHash'ing it.

@spede

This comment has been minimized.

Copy link
Contributor Author

commented Apr 28, 2016

Is that good enough? @spede @hacst?

Didn't even occur to me someone might have duplicate bans. I don't know. :)

@mkrautz

This comment has been minimized.

Copy link
Member

commented Apr 28, 2016

The behavior is a bit surprising, if you're removing bans and expecting the log to show they've been removed -- but instead, you only see "Ban list updated" and no add/remove lines.

@mkrautz

This comment has been minimized.

Copy link
Member

commented Apr 28, 2016

Braindump:

20:23:29 <mkrautz> https://github.com/mumble-voip/mumble/pull/2144 <- any thoughts on the behavior of using QSets for ban update messages?
20:23:38 <mkrautz> the PR adds extra logging for added and removed bans
20:23:55 <mkrautz> so, if you remove 3 bansban, you'll see 3 lines in your log: "Removed: <ban info>"
20:24:02 <mkrautz> same if you add new bans, etc.
20:24:14 <mkrautz> however, the PR now uses QSets to "diff" the old ban list vs. the new one
20:24:29 <mkrautz> our current ban list allows 100% dups
20:24:55 <mkrautz> but the QSet diffing doesn't work too well if there are two 100% equivalent bans:
20:25:05 <mkrautz> if you remove one of the equivalent bans, you will not get a log message for that
20:25:33 <mkrautz> maybe there should simply be a pass that de-dups entries?
20:25:40 <mkrautz> i.e., the internal data structure should just a QSet
20:25:50 <mkrautz> or we should run it through QSet when receiving the list from a client?
@hacst

This comment has been minimized.

Copy link
Member

commented Apr 28, 2016

Sounds like an acceptable edge case to me. We might want to try to filter dupes locally and on the server to prevent it going forward. A duplicate ban is probably unintentional anyways.

@mkrautz

This comment has been minimized.

Copy link
Member

commented May 9, 2016

The thing that has been holding me off from landing this, is wanting to de-dup the rest of the uses of the ban list.

However, I think that can be a separate task. I'll file an issue as up-for-grabs, milestoned for 1.3.0, and land this.

@hacst

This comment has been minimized.

Copy link
Member

commented May 9, 2016

SGTM

mkrautz added a commit that referenced this pull request May 18, 2016
@mkrautz

This comment has been minimized.

Copy link
Member

commented May 18, 2016

Landed via c522cff.

@mkrautz mkrautz closed this May 18, 2016

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
3 participants
You can’t perform that action at this time.