Logging

[beegee]

Ok, I’ll try to keep the syntax for logging messages boost-log like, so that a migration to the boost log API at a later time can be done easy and quickly if it’s needed. Fine, then I can start with implementing our own logging framework:)

[Tow]

Perhaps it will be better to implement an own logging API due to it hasn’t any extra impact on our build & deployment system and it shouldn’t be that huge effort to do it. The code to output colored text to console is already written so I can use this part from our current system. What are your opinions? Tow, what do you think about it?

I agree, it seems the best apprach.

---

As for some suggestions from my POV:
I did some logging ficilities for the VCAI. They are provisional and not nive but it’d be good to have that features available in all engine in some coherent framework.

1. Boost.Format based syntax. I somehow find it much more convenient than streams with their << and constant opening and closing quotes, worrying about spaces and so on.

BNLOG("Player %d will build %s in town of %s at %s", playerID % b->Name() % t->name % t->pos);

Still, stream syntax is used almost everywhere. It would be best, if the both variants were available (macro-printf-like and stream-like) and use single back-end.
2) automatic appending of the line end after entry. It should be done unless explicitely requested not to. Remembering about \n or endl is tedious.
3) global state that remembers indentation level and automatically puts appropriate count of ‘\t’ before each entry. Indentation helps me much in quickly glancing over logs. It is based on RAII object that increases indent till it is destroyed.
Various logs in VCMI simulates that by prefixing log with \t but it is unreliable and tedious.
4) RAII class for logging time: TimeCheck. Solution like that could replace all that CStopWatch uses.

[beegee]

Finally, I had time to start writing the logging API over the last weekend. It is implemented and commited to SVN. It isn’t used currently due to two reasons. First, you can review it and if there any things you don’t like or things which need improvement you can share it with me. Second, the usage how to log a message needs to be discussed as this is a important part of the API.

My first idea was to implement a macro which provides a c++ stream-like way of logging messages. I think it isn’t a good approach. With stream objects you cannot easily recognize when a single log operation has been completed:

std::cout << "A log record" << xyz << " bla"; 

Should the new line be appended after “A log record” or after xyz? When should the date, domain name, etc… part in front of the actual message be inserted? I don’t know how this could be done with macros. The boost log API can do sth. like that, but I’m not sure. Something like that could be possible:

Def.: LOG_DEBUG(logger, message);
Use: LOG_DEBUG(logGlobal, "bla" << "sjkl");

But if you use a comma in the second argument of the macro, then it will complain about providing 3 args to a 2 args macro function. So, I don’t really like this solution either.

Do we really need stream-like syntax for logging? If not we could use the logging API directly by invoking:

logGlobal->warn("Something...");

1. Boost.Format based syntax.

Shouldn’t be a problem, seems to be nice.

2. automatic appending of the line end after entry.

This is the default behaviour when logging messages. I don’t think that omitting a new line is needed at all, isn’t it?

3. global state that remembers indentation level

4. RAII class for logging time

In my opinion this shouldn’t be part of the logging API. Indentation level cannot be hold for a logger or even globally due to that you can access loggers in several threads simultaneous.

@Ivan:
Is it possible to define an enum in the schema once and use it in several places? Have a look at this file: sourceforge.net/apps/trac/vcmi/b … n?rev=3309
Log level enum is used a few times.

[Tow_dragon]

Should the new line be appended after “A log record” or after xyz? When should the date, domain name, etc… part in front of the actual message be inserted? I don’t know how this could be done with macros. The boost log API can do sth. like that, but I’m not sure. Something like that could be possible:

first operator<< returns object of special class (not that stream). It changes the semantics of following <<'s. It can write std::endl upon destruction.

Don’t take it as a vote for stream-like syntax, I just want to write it’s possible.

[beegee]

Thanks Tow Dragon! That’s a simple and good solution. No need for macros. I’ll simply provide function-style and stream-style logging and let the users decide which style they prefer.

[Ivan]

@Ivan:
Is it possible to define an enum in the schema once and use it in several places?

Yes. Check “definitions” in town siege schema: sourceforge.net/apps/trac/vcmi/b … Siege.json
In file root add
"definitions" : {
loggingEnum : { “enum” : … ]}
}
And to use it as “$ref” : “#/definitions/loggingEnum” (scope is local to file)

[Ivan]

• Added macros for tracing the control flow

What about merging these two macro into one? Right now you need to place this macro before every return statement. In some cases this can be time-consuming.

Merging can be done with something like this (completely not tested)

#define TRACE_BEGIN(logger) logger.trace(boost::format("Entering %s.") % BOOST_CURRENT_FUNCTION)
#define TRACE_END(logger) auto traceFunctionExit = vstd::makeScopeGuard( boost::bind(&CGLogger::trace, &logger boost::format("Leaving %s.") % BOOST_CURRENT_FUNCTION))

#define TRACE_FUNCTION(logger) TRACE_BEGIN(logger); TRACE_END(logger)

vstd::makeScopeGuard is definied in lib/ScopeGuard.h

[beegee]

I’m happy to tell you that the new logging system is implemented and fully integrated now! The old logger API has been removed from SVN. I want to summarize shortly the benefits and functionality of the new API:

• A logger belongs to a “domain”, this enables us to change log level settings more selectively
• The log format can be customized
• The color of a log entry can be customized based on logger domain and logger level
• Logger settings can be changed in the settings.json file
• No std::endl at the end of a log entry required
• Thread-safe
• Macros for tracing the application flow
• Provides stream-like and function-like logging

I’ll write a wiki page on how to configure logger settings in the settings.json file. This is intended for users of VCMI. Devs can look at the schema file to know how things are working:) A example configuration can look like this:

{
	"logging" : {
		"console" : {
			"threshold" : "debug",
			"colorMapping" : 
				{
					"domain" : "network",
					"level" : "trace",
					"color" : "magenta"
				}
			]
		},
		"loggers" : 
			{
				"domain" : "global",
				"level" : "debug"
			},
			{
				"domain" : "ai",
				"level" : "trace"
			}
		]
	}
}

One remark, the threshold property of the console object is a dedicated log level in addition to the levels of the loggers and serves as well as a decision base if a log entry gets written. Normally the console doesn’t log everything.

There are four logger domains and their respective loggers:
global -> logGlobal (super-domain)
bonus -> logBonus
network -> logNetwork
ai -> logAi

There is a LOT more to write, but you have to wait till tomorrow:) I’ve noticed several things when I integrated the new API. A few funny things as well, so stay tuned:)

PS: My next job is to work on the RMG again. I have a lot of time now and my thesis needs to be finished at the end of june, so I won’t work on other parts of VCMI. This was enough refactoring, let’s come to some more interesting parts:)

[Warmonger]

Good job, new logging has a lot of potential! Maybe finally players stat reading them and stop to post meaningless dumps all around

One thing: there’s no need to write WARN or ERROR before every line, this is indicated by color anyway.

[Ivan]

One thing: there’s no need to write WARN or ERROR before every line, this is indicated by color anyway.

I assume that this is needed mostly for file output.

Anyway - I’ve reset console output format to something similar to what we had before - all that verbosity is needed only when reading logs and will only confuse users (“WTF is that wall of text, numbers and symbols”)

[beegee]

I’ve written a wiki page about several aspects of the logging API, here it is:
wiki.vcmi.eu/index.php?title=Logging_API

Next, I’ve added how to set the log level in the bug reporting guidelines site, look here:
wiki.vcmi.eu/index.php?title=Bug … guidelines

There are a few things which can be improved further. Perhaps there is someone who wants to do it:)

• The CConsoleHandler should be re-structured. The class has three purposes: 1. Handling of colored console output. 2. Listens to key input and informs others about a function callback 3. Listens to uncaught exceptions and collects some windows-specific debugging information. IMO point 1 should be part of CLogConsoleTarget. Point 2 is only relevant for vcmiclient and should be moved to CMT. I don’t know if point 3 is useful at all. It would be possible to remove the global object “console”. In its current state the CConsoleHandler is doing too many different things. I’ve thought it’s sole purpose is to print messages to the console.
• There are log messages which contain the words ERROR or WARNING before the initial message. Can be removed, because the log level will be logged in the log file respectively the console shows the message with a specific color.
• We have too much error logs, some of them are warnings only. It sometimes seems to be that after an error, the program executes just as nothing had happened(ok, this were often things like “should never happen”-things:) . During the integration, I’ve noticed several wrong log calls. That’s the funny thing, I’ve talked about. There were statements like that: tlog0 << “ERROR: …” or tlog0 << “WARNING: …” or tlog0 << “a debugging message”, whereas tlog0 was info log.
• At a later time, when we can use variadic templates we can write a template which logs messages just like printf e.g. logGlobal->debug(“hero moved to point ‘%s’ with direction ‘%s’”, hero->getLocation(), hero->getDirection); We can do sth. similar with boost::format just now. But it comes with a performance penalty. The message has to be created first as a string, then the logger decides if the message should be logged. With the variadic template, the parameters are passed first and the logger can decide immediately if the message should be logged. So this would be mostly a performance improvement.

Anyway - I’ve reset console output format to something similar to what we had before

Good, that’s ok!

What about merging these two macro into one?

Your solution has two problems. First, the log message “Leave function xyz” will be written too when an exception occurs. It’s important to see if a method returned properly or not. Second, there can be several return statements where different values are returned. Sometimes you have params to log, but not the return value or vice versa. That’s not possible with one macro. If it’s really a problem, you can try to reduce the amount of return statements in a method and then have only one TRACE_END macro. The VCAI traces are missing a TRACE_END, I will add them. Either no traces or both BEGIN and END should be used. I was a bit lazy there:)

[beegee]

I don’t know where to put this, but it is important and every dev should know about it.

I’ve recognized a lot of null \0 and other non-printable characters in the log files. This is bad to read and in combination with exceptions it results in a loss of information, which I’ve recognized today.

Now, have a look at the following code. The value inside color is 0 and it is of type ui8.

throw std::runtime_error(boost::str(boost::format("Cannot set player type for the player with the color '%d'.") % color.getNum()));

What does it prints to the console respective what does it writes to the log file when the exception is caught and the message logged? The result looks like:

Cannot set player type for the player with the color '

The problem is that I wanted to print a number/integer and not a char/1byte. We interpret the number PlayerColor as a ui8 which is a raw byte. Now I think it would be better to simply use sth. like si32 and don’t care about memory size.
Boost format detects that the variable is of type char, the %d doesn’t gives boost the information that the variable should be converted to a integer type. So if the variable color from the code example above contains a 0 the binary 0 is added to the string. If you don’t use boost format and concat char and string, it doesn’t solve anything.

catch(const std::exception & e)
{
  logGlobal->errorStream() << e.what();
}

The next problem is that the statement e.what() returns a const char *. Everything after a \0 in the message string is truncated and will not be printed.

So if you want to print the numerical value of a ui8 or if you want to concat a exception message where a ui8/si8 is involved, check twice that you’ve casted the ui8 before. For example this works:

throw std::runtime_error(boost::str(boost::format("Cannot set player type for the player with the color '%s'.") % std::to_string(color.getNum())));

It uses one of the new c++11 string functions std::to_string.

[Tow]

How about simple

 throw std::runtime_error(boost::str(boost::format("Cannot set player type for the player with the color '%s'.") % color.getNum())); 

AFAIR there is opeator<< for PlayerColor (or basically all these new stronlgy typed ID classes), so boost::format should be smart enough to use it with %s.

It uses one of the new c++11 string functions std::to_string.

Please avoid this function for the time being, it breaks compilation on Visual 2010 and we still didn’t officially drop support for it (it was meant to be killed after MS releases stable C++11 update for VS2012). boost::lexical_cast does the same, though is unpleasantly verbose.

---

• The CConsoleHandler should be re-structured. The class has three purposes: 1. Handling of colored console output. 2. Listens to key input and informs others about a function callback 3. Listens to uncaught exceptions and collects some windows-specific debugging information. IMO point 1 should be part of CLogConsoleTarget. Point 2 is only relevant for vcmiclient and should be moved to CMT. I don’t know if point 3 is useful at all. It would be possible to remove the global object “console”. In its current state the CConsoleHandler is doing too many different things. I’ve thought it’s sole purpose is to print messages to the console.

The reading console input and coloring console output doesn’t necesserily need to be together… though somehow it felt right for them to be in CConsoleHandler.
The unhandled exception filter doesn’t belong there, it basically because that file already inludes all that platform-specific stuff it needs. Sohuld be probably split out.

Your solution has two problems. First, the log message “Leave function xyz” will be written too when an exception occurs. It’s important to see if a method returned properly or not. Second, there can be several return statements where different values are returned. Sometimes you have params to log, but not the return value or vice versa. That’s not possible with one macro. If it’s really a problem, you can try to reduce the amount of return statements in a method and then have only one TRACE_END macro. The VCAI traces are missing a TRACE_END, I will add them. Either no traces or both BEGIN and END should be used. I was a bit lazy there:)

So how does your solution helps with logging that method was left because of exception? Should we not only place macro in every return point but also wrap everything into try{}catch(…){ trace, rethrow} ?

I’d say the opposite thing: the RAII guardian is useful because it automatically handles all possible exit points. Obviously it doesn’t provide info what method is returning (or if it is left due to exception stack unwinding) but it is better to have some info than none info.

Requiring putting trace and formatting output in all possible exit points seems requiring much effort (and also maintenance cost), I believe there are many cases when it is reasonable to give up on the log details just to save that. It is often enough to know that function was entered/left, not necesserily we care about argument/return values.

• We have too much error logs, some of them are warnings only. It sometimes seems to be that after an error, the program executes just as nothing had happened(ok, this were often things like “should never happen”-things:)

Well… I don’t think that error message should mean that we cannot continue proper execution. Error means that something is wrong, needs attention and should be fixed.

[Tow_dragon]

We interpret the number PlayerColor as a ui8 which is a raw byte. Now I think it would be better to simply use sth. like si32 and don’t care about memory size.

Memory size is of least concern here. 1 byte is how it is encoded in h3m and some places may assume that player -1 == player 255. Strong typization has made it better but I’m not sure it’s perfect. Do you want to review all uses of PlayerColor construction to ensure it is not a problem?

[beegee]

AFAIR there is opeator<< for PlayerColor (or basically all these new stronlgy typed ID classes), so boost::format should be smart enough to use it with %s.

It doesn’t work. PlayerColor has the operator<<, but chars are interpreted just as they are(\0 is \0 not 0), which makes sense. But in log text files we want to have characters and no binary values, so we have to convert a char to a number if it represents a number.

Please avoid this function for the time being, it breaks compilation on Visual 2010

Are you sure? I look carefully on MSDN and GCC pages if I can use a particular c++11 feature. Look at that page: msdn.microsoft.com/de-de/library … 00%29.aspx
There are also stoi, … available for VS10. Can you confirm this please? I have no VS.

So how does your solution helps with logging that method was left because of exception? Should we not only place macro in every return point but also wrap everything into try{}catch(…){ trace, rethrow} ?

No, no, I don’t want you to wrap everything with try,catch. If the method was left because of exception, you’ll simply see that the “Leaving XYZ” message is missing. I don’t think that it requires that much effort to write TRACE_BEGIN and TRACE_END. You don’t have to output param/return values, if you don’t want to. It is optional. So if you’re fine with knowing that a function entered/left, than all you have to do is to write a TRACE_BEGIN at the begin of a method and a TRACE_END at every return statement. As said above, it’s almost always possible to refactor the code, so that it has only one return stmt. Two examples:

Example 1:

int CBattleInfoEssentials::battleGetMoatDmg() const
{
	auto town = getBattle()->town;
	if(!town)
		return 0;

	return town->town->moatDamage;
}

Can be written as:

int CBattleInfoEssentials::battleGetMoatDmg() const
{
	TRACE_BEGIN(logGlobal);
	int moatDmg = 0;
	auto town = getBattle()->town;
	if(town) moatDmg = town->town->moatDamage;
	TRACE_END_PARAMS(logGlobal, "moatDmg '%d'", moatDmg);
	return moatDmg;
}

Example 2:

bool CBattleInfoEssentials::battleHasNativeStack(ui8 side) const
{
	BOOST_FOREACH(const CStack *s, battleGetAllStacks())
	{
		if(s->attackerOwned == !side  &&  s->getCreature()->isItNativeTerrain(getBattle()->terrainType))
			return true;
	}

	return false;
}

Transformed to:

bool CBattleInfoEssentials::battleHasNativeStack(ui8 side) const
{
	TRACE_BEGIN_PARAMS(logGlobal, "side '%s'", std::to_string(side));
	bool hasNativeStack = false;
	BOOST_FOREACH(const CStack *s, battleGetAllStacks())
	{
		if(s->attackerOwned == !side  &&  s->getCreature()->isItNativeTerrain(getBattle()->terrainType))
		{
			hasNativeStack = true;
			break;
		}
	}

	TRACE_END_PARAMS(logGlobal, "hasNativeStack '%d'", hasNativeStack);
	return hasNativeStack;
}

I don’t want to change your style of programming nor impose any coding guidelines towards this and I think too that the first solutions above are nicer to read. But TRACE without printing return values or not knowing that the function has left by exception is not the ideal solution either. However if it’s enough, then the RAII solution seems to be nice just to print “Leaving XYZ” at every possible exit point.

Error means that something is wrong, needs attention and should be fixed.

That’s right. I would have to further investigate the source code to know where printing an error is not enough. Sometimes I got the feeling that we cannot continue proper execution, as it could lead to NPE, Buffer overflow, wrong index access,… But we better leave that for now…

Do you want to review all uses of PlayerColor construction to ensure it is not a problem?

I’m snowed under with work! BTW, what problem do you mean?

[Ivan]

From what it seems you’re more interested in return value and not in detecting when this function is called. Am I right? Maybe in such cases it is better to modify caller or return statements?

int x = functionToTrace();
Can be written as
int x = TRACE_VALUE(functionToTrace());

OR something like this:
return x;
becomes
return TRACE_VALUE(x);

where TRACE_VALUE is simple template that prints passed value to log (perhaps along with name of caller function) and returns it.

As said above, it’s almost always possible to refactor the code, so that it has only one return stmt.

Yes. But it may turn previously trivial function into if-forest with 3-4 level of nesting. Good examples are in GameHandler - multiple input data checks with return on errors.

BTW, what problem do you mean?

PlayerID a(-1);
PlayerID b(255);
assert(a == b);

Works when PlayerID is single-byte, breaks when PlayerID is multi-byte.
BTW - not sure if relevant but there also cases where “player” fields are actually a bitmask.

[beegee]

From what it seems you’re more interested in return value and not in detecting when this function is called. Am I right? Maybe in such cases it is better to modify caller or return statements?

I don’t think it’s a good solution to clutter the code with TRACE macros in return or caller statements. I think the RAII solution is OK. If you want to explicitely log a return variable, you can do that with logGlobal->traceStream, etc…

Works when PlayerID is single-byte, breaks when PlayerID is multi-byte.

Ah,ok! If we change the ui8 to si32 or whatever for PlayerColor what problems it may cause, was the question. I thought it causes problems to ui8 currently. It would be good to have a real integer for PlayerColor, but someone else has to do it.

[Tow_dragon]

BTW - not sure if relevant but there also cases where “player” fields are actually a bitmask.

Bitmasks are a related but separate problem. They were not affected by recent PlayerColor refactoring. Replacing them with std::set would be a more high-level solution but there are more important things to do.

[Tow]

It doesn’t work. PlayerColor has the operator<<, but chars are interpreted just as they are(\0 is \0 not 0), which makes sense. But in log text files we want to have characters and no binary values, so we have to convert a char to a number if it represents a number.

You’re right. I’d say it’s just a bug in operator<<. When outputting ID, we always want to format it as a number. I implemented it in r3332. Now the following should work:

	PlayerColor blue(1);
	std::cout << boost::format("Blue is %s") % blue; //Blue is 1

Are you sure? I look carefully on MSDN and GCC pages if I can use a particular c++11 feature. Look at that page: msdn.microsoft.com…=vs.100%29.aspx
There are also stoi, … available for VS10. Can you confirm this please? I have no VS.

VC10 doesn’t have all the to_string functions. Some of them were added late in the standarization process, after VC10 feature-freeze.
When I try to build in VC10

	int i = 0;
	std::to_string(i);

I get this:

error C2668: 'std::to_string' : ambiguous call to overloaded function
1>          c:\program files (x86)\microsoft visual studio 10.0\vc\include\string(688): could be 'std::string std::to_string(long double)'
1>          c:\program files (x86)\microsoft visual studio 10.0\vc\include\string(680): or       'std::string std::to_string(_ULonglong)'
1>          c:\program files (x86)\microsoft visual studio 10.0\vc\include\string(672): or       'std::string std::to_string(_Longlong)'
1>          while trying to match the argument list '(int)'

This works fine with VC11.
Or should we just kill VC10 support that nobody maintains anyway and was deprecated several months ago?

But TRACE without printing return values or not knowing that the function has left by exception is not the ideal solution either.

Well, yes, there is no perfect solution. They all have their advantages and drawbacks. That’s why having both options in logging API is good.

As for exceptions we already have a macro THROW_FORMAT (rarely used), it could be extended to log the fact of throwing exception (plus write the exact code location). That way we’d always know where the error occurred and what caused the following series of function exits.

[beegee]

Or should we just kill VC10 support that nobody maintains anyway and was deprecated several months ago?

IMO we can kill VC10 support. VC11 including update 1 has a very good c++11 support. The only problem is that we exclude Win XP developers, but I think this is negligible. If someone wants to work for VCMI he/she can obtain a Windows7 license. The important point is that we still can target XP players/gamers. I don’t know which plans Ivan has regarding changing the minimum compiler from GCC4.5 to something higher. I think we can still use GCC 4.5. It has already good C++11 support.

A short and incomplete list of what features we could use in addition:
Language features:

• Forward declarations for enums (only GCC4.6+) -> ok
• Strongly-typed enums -> ok
• Initializer Lists -> nice
• Variadic Templates (finally) -> nice
• Range-based for-loop (only GCC 4.6+) -> boost macro is fine

Library features(incomplete!):

• String functions (to_string, stoi, stof,…) -> nice
• More to add:)

As for exceptions we already have a macro THROW_FORMAT (rarely used), it could be extended to log the fact of throwing exception (plus write the exact code location). That way we’d always know where the error occurred and what caused the following series of function exits.

I don’t know if that’s the right way. IMO it would be better to subclass from std::runtime_error and on construction the ctor of the exception class should collect a stacktrace.(it’s possible for GCC and MSVC) If you want, you can print that stacktrace somewhere in a catch clause. Not all thrown exceptions should print a stacktrace or the name of the function + line number. E.g. When the CBasicLogConfigurator setups the logging system from the settings.json, it wraps the whole stuff with a try/catch, just prints an error that the logging system couldn’t be initialized properly and continues execution. No reason to print line number, etc… From the perspective of a CLogger or a CLogFormatter or a CLogFileTarget object you can’t decide if it’s necessary to print a stacktrace/file number, etc… or not.
I think we shouldn’t put that much effort or complexity(?) into logging traces. The RAII solution is easy and it works. Yes, we cannot exactly follow the execution path when an exception occurs, but we can guess it, so what? If it’s turning out to be really a crucial problem, we can think about it a second time:)