- Feature Articles
- CodeSOD
- Error'd
-
Forums
-
Other Articles
- Random Article
- Alex's Soapbox
- Announcements
- Best of…
- Best of Email
- Best of the Sidebar
- Bring Your Own Code
- Coded Smorgasbord
- Mandatory Fun Day
- Off Topic
- Representative Line
- News Roundup
- Editor's Soapbox
- Software on the Rocks
- Souvenir Potpourri
- Sponsor Post
- Tales from the Interview
- The Daily WTF: Live
- Virtudyne
Admin
I can see a scenario where bitmask choice of error types makes sense. Not sure if that was what was originally intended (and strayed from) here, though.
I've been in the position of chasing faults that exhibit a number of warning or info messages before an error is eventually thrown and where timing of those messages is quite important to compare to other system logs. Being able to say "show me warnings and errors but nothing else" is really handing in those cases.
Admin
I'm of the opinion that this is a far more sensible logging mechanism than, say, log4j. In fact, I'm so strongly of that opinion that I've implemented such a thing. I don't really care whether a log message is "critical" or "benign" or "purple monkey dishwasher." If it's to do with comms, I want to filter on that. If it's to do with a database, I want to filter on that. And so on. None of this abstract qualifier nonsense, which in any case is almost always subject to programmer whim.
Of course, the actual implementation sounds like a dog, but there you go.
Admin
It's a bit mask. With 5 you get warning AND critical. If it makes sense is another question ...
Admin
Myeah, but those two are orthogonal. Being able to filter on the source of the error is not the same thing as wanting all errors of severity 2 or worse. They should be two different fields.
Admin
And logging levels rather than sources are good if you have a whole heap of stuff with info and warning an debug stuff crowding out the stuff at the level of 'error' that you need to get to.
Admin
So Dirk had to go diggling through some logs. Sounds about right.
Admin
Spot on. They are potentially orthogonal.
Which is why I use the equivalent of a C# enum with flags. (Actually it's a bitmask, but whatever.)
To use my example (and I constrained it vastly), you may wish to log a state change that is purely comms: say, closing a Web connection. Or you may want to log a state change that is purely DB: say, starting or ending a transaction.
Or you may wish to log a state change that is both: say, creating a DB connection over a TCP socket. And this is where "orthogonal" becomes "non-orthogonal."
We're still living in the world of (I believe it was) HP View, wherein you are forced to log things on a categorical scale that makes no sense to anybody. Except managers, who love them a bit of logging dashboard nonsense with pretty colors and flashing lights and metrics and other utter nonsense.
Admin
Given a flags enum, you can also do that, and I would encourage it. Say you're logging a state change as COMMS | DB | DEBUG.
Easy enough to filter DEBUG out, isn't it?
Admin
If you have a discrete set of categories, you'll always need some amount of human interpretation to map things to them. And while different logging frameworks may differ, I've always found the typical log levels to be pretty intuitive - ERROR for something that definitely should not happen; WARN for something that's potentially bad, especially in aggregate; INFO for high-level runtime information; TRACE for detailed information; and DEBUG for when you're debugging a specific problem. Yes, there's some ambiguity about ERROR vs WARN and INFO vs. TRACE, and different teams will have different conventions. Pick one that makes sense for your use case and accept that you might sometimes see something in your error logs that in retrospect probably doesn't need to be.
That said, you do have a cool idea here! It's just orthogonal, like RLB said. Since you brought up log4j, I'd like to mention that it already supports a form of that in the logger name and (when you're logging exceptions) exception type.
Admin
I think you misunderstood their response. Look at the rest of the post: "Being able to filter on the source of the error is not the same thing as wanting all errors of severity 2 or worse. They should be two different fields."
In other words, log levels and log categories address different facets of the problem. Both are valuable and it doesn't make a whole lot of sense to discard the one for the other. To continue your analogy, "couldn't connect to the database" is obviously a database error, "fetched 2000 widget records" is database info (depending on the larger context, anyway), and "this database operation is taking a long time" is a database warning, and if I'm trying to make sense of an issue, which I care about very much depends on what the issue is.
Admin
Maybe it's just me, or it's too close to Christmas, or there's a paragraph missing from the description - but can someone explain why this is a WTF?
Admin
sometimes you want debug sent to a different location than error
Admin
This strategy is hardly uncommon. PHP's error_reporting is a bitmask (yes, I know many of you abhor PHP, so you'll just add this as a reason).
Admin
Idunno..... Most logging engines I've worked with take a setting like "Warning" (4 in this case) and log messages for Warning, Error, and Critical -- not just "Warning".
I would bet the bitmask was an accident of implementation and that the logger logic checks for an error level less than or equal to the TraceEventType value. I don't see any value in setting the bitmask to any value that does not include the values below it. Otherwise, you've given me a system where I can set it to 8 and never see any warnings, errors, or critical messages. But if that's how this engine actually works, it's an awesome way to eliminate all warnings and errors at runtime.
Admin
Most of the time the convention becomes "log everything as WARNING because that's what gets logged in production"...
Admin
Most of the time? I have a difficult time accepting that, even if for no other reason than the default in every logging framework I've seen is INFO. If your team decided to only log warnings and errors, and then started abusing warnings instead of setting it back, that's TRWTF (and I'm sure it's really frustrating).
Admin
The PHP flags are not log levels. Sure, some of them correspond to well-known log levels, but there is also stuff like E_DEPRECATED which does not fit into the scheme.
Admin
The cutting edge system is SkyNet.
Admin
As a long-time "platform guy" for big-iron companies large and small, I have personally authored this pattern twice - but with a piece that is missing. The missing piece is that the logging API also allows "categories", which are not level-based, and which are all individually selectable. The "categories" are the other bits (not found in this code sample), and they provide another way to select the messages to be logged. The bitmask simultaneously supports both old-style levels, for you gluttonous people who want a firehouse of useless garbage at "Debug" level, but also a "categories" for those enlightened people who want much less garbage when debugging. On many systems I've worked on, "Debug" level logging simply cannot be used in a production environment - it is just costs to much to generate all those messages and everything slows down. Customers don't like that.
The reason why you see individual bits for Debug, Info, Warning, Error, et cetera, in such a bitmask model, is because you want the most efficient test to decide whether to log or not. The test is just one bitwise and. The code that handles the level change ensures that all the bits are set for the level you choose when you change the level. But the same code ALSO allows you to set the categories independently in any combination. Best of both worlds.
This code? Not (quite) a WTF, at least not where I come from. The WTF is level-based logging. Please stop making me turn on a firehose to debug your garbage.
Admin
"was inconsistent" -- 99.995% of the time, this being the root cause of the WTF. If only people would understand DRY and SRP (the "S" in SOLID) fully....
Admin
Just use the bitmask internally, and organise it so an externally-visable call sets the mask to 2^level-1.
Admin
Generally the higher-level messages are for tracking what is happening in the program in general. It gives a high-level overview of what happened. Then you can include lower level messages such as errors in the log and it will also include all of the higher-level messages as well.
Having the ability to display only the error messages is a bit strange because then you lose the higher-level overview of what point in the program the error happened in. It seems like an overly complicated way of allowing something that you almost certainly don't want to do in the first place.
Admin
Unexpected failures need logging in production, but there's plenty of stuff that doesn't need to be logged normally; if the program's behaving itself, you don't want it to blather on about it. The ability to selectively get more information proves most useful when investigating why a program is not behaving right; you don't want everything because everything is far too much, but you want more than default. That's when selectivity by level and source (as separate axes) becomes vital.
Bitmasks and conventional levels cost the same amount computationally; comparisons take the same number of CPU cycles as ANDs (though maybe a few more transistors; it doesn't matter too much). Use the one that makes most sense.
Admin
Haha, I love this. You can have something that's both information and an error, and as it's not a warning, so you shouldn't log it throught the warning log right. Ultimate flexibility! Not error prone at all /s