How to Log and stay Modular

Started by
55 comments, last by ApochPiQ 12 years, 7 months ago

If you want more complex behavior


Something struck me recently. Many companies advertise: "... complex solutions..." I suppose simple solutions to complex problems don't sell. What I want is dead simple behavior that cannot be messed up, either now or somewhere far along the line.


Major thing that is painfully missing in such debates is what constitutes a "module". C++ only knows compilation unit and process.


If we define per-system logging, things become much clearer. If we want Physics, Input and Renderer systems to have modular logging, then each of these has its own. What does this mean? Several ways:struct System {
public const char * LOG_SYSTEM_NAME = "System";
};
..
struct System {
Logger logger;
};

System::Logger logger = "System";
...

The thing we need in common is a tag unique to system which we append to logs. Logs are typically text files on disk. Tag must be immutable since it will outlive the process by far, so whatever can be done while the code is running is just the birth of a log.

It may seem like deciding upon this tag is the big challenge now, making sure it's unique, but the tag itself, its location and name will be implicitly determine by logical dependencies of the project itself. If suddenly Input wants to log as Renderer, there is something weird going on and in reverse - Input will never need access to Renderer log. If it does, we got emergent complexity of InputRenderer, which is more of a design issue to worry than how the log is stored.

And by implication - if all tags are stored in some global file, we succumb to the God Class or "#include <everywhere.h>" problem, where modularity was lost already - a single change in that file affects everything.
--------
Log aggregation needs to be addressed next. At simplest level each system logs to its own file. We might choose each run to create its own instance in which case filename needs to be stateful in system implementation. Something like:Logger logger("SYSTEM", Date.now());

Problem of uniqueness now becomes an issue (the static/global/singleton problem). Maybe we add process or machine ID to that. Benefit of this - ability to directly store all logs.

A minor triviality that needs to be solved is how to initialize such system, we might want log location to be externally specified. Again, passing a Config struct or having command-line parser set some common fields works, but one can wrap this into full IoC design. As mentioned, IoC is most intrusive and may not enable third-party libraries to use it.
-------
Advanced logging:
Let's say our logging is not boring, and we track a bunch of stuff, user actions, transactions, etc... with goal of running ETL. The idea of logging straight to database might be tempting in this case and is often done for web services but it's just implementation detail. Typical stumbling blocks here will involve configuration parsing and sequential initialization (config comes from database but to talk to database we need to read config, or database connection may drop or database may become unresponsive).

With the last two issues we come back to state. Stateful loggers are hard and if they hiccup, the application stops.

For this reason we want whatever "tags" our loggers use to be immutable per some unique context (see process, etc.). This way, logging can continue without regard to state (database/file are state) and we can even make use of fragments.

Also, see various logging services provided by OS which prevent logs from overflowing, but useful logs might not be

Then there's fancy fast stuff, such as K/V database (redis, mongo, etc...) which may be good fit with stateless loggers but may be at odds with ETL. Dumb SQL table or flat files might still be simplest way.
-------
Q: "I know, I'll log as XML or HTML"
A: "Any time your application exits unexpectedly (the time you need logs most) the log will not be valid XML and HTML" Don't add complexity - XML/HTML are stateful - the depth and nesting need to be properly terminated which can only happen under ideal circumstances.

Q: "But good logging system will make debugging easy"
A: "No, it will never log the correct information, use debugger or printf, the data will be discarded after each run anyway"

Q: "So, which option is the best"
A: "Depends on goals and how pragmatical one is"

--------
PS: If logging, start each line/entry with date/time in standardized format: YYYYMMDDThhmmss.msecZ. The reason - they are naturally ordered and can be compared using any strcmp algorithm to produce correct ordering. It makes searching easy (str > "2009" && str < "2010") will return expected range using just about any text mangling tool.
Advertisement

*snip*

My preferred solution is to invert the relationship between the code doing the logging (call it the "client") and the logging system itself (call it the "provider"). Most solutions involve the client telling the provider where to log, etc. at the point of invocation (or nearby if you're using constructors and logging objects). To me this seems brittle; if you suddenly want all of your graphics-related logging to go to foo.txt instead of bar.txt, have fun updating your 500 constructor calls across the project!

*snip*

I completely agree with the snipped out portions. The only problem I have with the one paragraph I've left in is the part about updating 500 constructor calls. The reason is: yes, a system designed like that is horrible in my opinion, and so it shouldn't exist in the first place. What I usually mean when it comes to logging systems with objects is essentially what you've described, except where each "channel" is a separate Logger object. Only one per channel. And they're global. So there's only one constructor for each channel (and there shouldn't be that many channels, and they should all be initialized in the same spot). That way, each Logger/Channel encapsulates whatever data it needs to store. And logging with the system is just a simple function call (via the channel logger's member method), something like globalSystemLog.Log("I'm logging this now"). Which is basically the same as a free function (someNamespace::log(LOG_SYSTEM, "I'm logging this now")), only the channel is now a global Logger object rather than an enum being passed to a global logging function.


*snip*

Yeah, I agree with you in pretty much every sense.
[size=2][ I was ninja'd 71 times before I stopped counting a long time ago ] [ f.k.a. MikeTacular ] [ My Blog ] [ SWFer: Gaplessly looped MP3s in your Flash games ]
I still don't see any benefit to using a global object over a free function. Of course I realize they're isomorphic at a certain point, that was never under contention; my dispute with people who use global objects is that there doesn't seem to actually be a reason to have an object to begin with!

You also better hope that nobody besides your logging system uses global objects, or you get a wonderful static order of initialization SNAFU and life is miserable.


A free function minimizes potential points of failure. It also provides a very clean, natural way to serialize log requests, which is essential in multithreaded systems. Nothing sucks like trying to unravel a log file that has three threads stomping on each others' output. Of course you technically can serialize requests made by multiple redundant logger objects, but it's more complex - more possible ways to get it wrong. Why subject yourself to that? Why not do the simplest thing that gets the job done?


I'm not just being argumentative for the hell of it, by the way. I genuinely do not understand the mentality of programmers who do not treat implementation complexity as their enemy.

Wielder of the Sacred Wands
[Work - ArenaNet] [Epoch Language] [Scribblings]

The OP could have written a logging system many times over in the time this thread has taken. I think we have run into the bikeshed principle here.

OP: Use free functions. Forget modularity. Then get on with the real work, of which actual logging is probably a tiny fraction.
Don't thank me, thank the moon's gravitation pull! Post in My Journal and help me to not procrastinate!

The OP could have written a logging system many times over in the time this thread has taken. I think we have run into the bikeshed principle here.

OP: Use free functions. Forget modularity. Then get on with the real work, of which actual logging is probably a tiny fraction.


Done. :)
On 9/11/2011 at 10:37 AM, ApochPiQ said:

Most solutions involve the client telling the provider where to log, etc. at the point of invocation (or nearby if you're using constructors and logging objects). To me this seems brittle; if you suddenly want all of your graphics-related logging to go to foo.txt instead of bar.txt, have fun updating your 500 constructor calls across the project!

Amen, brother. That seems like a poor design choice. (Or perhaps more accurately, it's "lack of design.")

On 9/11/2011 at 10:37 AM, ApochPiQ said:

Sure, if your logger needs to store state, then by all means use a lightweight object to do so; that's fine by me. (I'm skeptical that 99% of the loggers written would ever need to store any state, and that last 1% better be darn convincing, but I wouldn't rule it out entirely.)


Like I said,

On 9/8/2011 at 7:48 PM, vreality said:

The problem with logs in videogame development isn't that no one needs them, it's that they quickly become unusable as they get spammed by every system under development.

When you make a logging system on a full-team development project, within about ten minutes it's being spammed with so much diagnostic information that it becomes nearly useless. So then everyone decides that you shouldn't check in any code containing log calls unless there's a really good reason. Then it takes a good half an hour to an hour for it to become unusable again. Then you do code reviews and don't allow any log calls to be checked in unless there's a very good reason, and this time it takes a good week to a week and a half before you lose your diagnostic info in the noise.

The solution to that - er wait. I should say, A solution to that is to make logging locally configurable.

First, I would introduce logging channels. And I wouldn't use enums. I would allow any arbitrary string to identify a channel, so that at any point a developer could make up a new channel for their own purposes without touching logging system code.

Second, I would make a config file (not shared under revision control) that could optionally exist at a known location, in which they could put entries sending arbitrary channels to various destinations, e.g "AI" to be displayed in-game, "Memory Manager" to be saved to a file, "Network" to be sent to the debug console, etc.

All the systems under development would still post logs with simple calls to free functions which did not store any state. And the application, or logging system, or whatever, could optionally create a single logging system object with which to manipulate and store state, e.g. by loading and applying that config file, passing the object around and making configuration calls on it, etc. It seems right to have only a single instance, but there's no reason to make it global or to create it statically.

This gives users flexibility, freedom, and control, to log arbitrarily and to different destinations, and to see exactly the information they're interested in, without the noise. In other words, it makes logs usable. And it does so without the need to add objects or state to the actual logging interface used by the systems generating log calls.

Now, as written, just about none of the logging systems I've seen in use felt the need to store state...

But pretty much every logging system I've seen really needed to start storing state to avoid becoming instantly useless.

I think this is just a minor discrepancy in terminology. Sure, the process of logging and routing and viewing the logs taken as a whole has stateful components. I'm not disputing the utility of that.

The act of writing a single entry to a log does not, and should not IMO, involve state, and therefore encapsulation as an object is nonsensical.

Of course, my philosophy on logging generally boils down to "spam away, and use better log viewing tools."

Wielder of the Sacred Wands
[Work - ArenaNet] [Epoch Language] [Scribblings]

This topic is closed to new replies.

Advertisement