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

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:)

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.

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”)

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.

Good, that’s ok!

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:)

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.

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.

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 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.

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.

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.

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?

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.

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.

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.

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…

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

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.

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.

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.

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…

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.

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.

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

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?

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.

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:)

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:)

If could get initializers list and variadic templates just by killing VC10, I would have done so long time ago. Unfortunately, from the features you listed, VC11 support only strongly typed enums and range-based for. The other ones were released in so called “November '12 CTP of the C++ compiler” that is alpha-quality and practically useless.
I had hoped that these C++11 features would be released as part of recent Update 2 but that did not happen. I guess we’ll have to wait at least till the Build 2013 conference (26–28 Jun) for further updates. That would be consistent with their promise that “next batch of C++11 features would be coming in the first half of 2013” ( blogs.msdn.com/b/vcblog/archive/ … x#10369778 ).

XP support is not an issue. AFAIK there are no developers using Windows XP and Visual Studio. If there were, they can always switch to MinGW. AVS uses that configuration if I remember correctly.

Catching stacktrace is not always reliable in optimized builds. Even when it works, in order to get the names of symbols and source file references you need the debug symbols. They are big and not distributed with VCMI binaries.
The macro seems much more feasible to me. It can create a custom exception class object as well and reliably give its constructor the information, where the throwing is taking place. (stacktrace are impossible though )

Why do we don’t want to print line number, etc… of throwing place when logging system fails to initialize? Such failure seems to me like an abnormal situation that we care what caused it.

I’d say that every situation when we throw an exception should be by default treated as error and we should log as much information about it as possible. It is better to log the source code line for a non-critical error, than not to do it for a truly critical one.

I am aware that there are places when exceptions are used to steer the codeflow (not to signal an unexpected problem) and there logging the location may be pointless. If an exception throw is an expected execution path, then such cases can be handled individually. I am not saying to forcibly use the hypothetic throwing macro for all throws in the code.

Sorry, I don’t quite understand this point. Why should they decide? Logger is just logging.
Writing location should be decided either at the throwing place or by the catch block.

Well, a custom “throw” macro seems like a way to have more accurate logs without imposing a cost on writing/maintaining the code. I wanted to do that for a quite while, just there was no opportunity.

I’m also going to rethink the automatic indent level. It would make logs more readable, especially with that function entry/leave style. It could work as a global, thread-local state. Still I need to experiment with the idea a little, I’ll write how I see that later.

I would agree with 4.6 as minimum if this will give us bigger c++11 support (like features from VC11 update). Right now I don’t see any need for version bump - from 4.6 features vc10 supports only range-based for and vc11 gives forward enums

Along with that we could implement our own stacktrace in regard to the unreliability of built-in stacktraces in debug builds . We could have a stacktrace class:

struct CStackTrace
{
	CStackTrace * prev;
	std::string fileName;
	std::string funcName;
};

An object of it is created with the macro LOG_TRACE or sth. similar in the stack. We need a global, thread-local storage which can be used for a automatic indent level too. In this storage the macro saves a pointer to the currently created CStackTrace object. In the d-tor of the object, the pointer in the thread-local storage is assigned the value of the prev CStackTrace. With this method you can build sth. like a linked list of CStackTrace objects. We can add a count function to determine the indent level(or add a counter variable). A custom exception object can collect this information on construction to build a stacktrace message. The throw and the exception can be wrapped into a macro as well to support showing the line number where the exception occured. Keep in mind, you have not to use the macro LOG_TRACE in performance-intensive operations or wrapper functions.
I would apply the automatic indent level either to all logs or to no logs. The indent level should be part of the CLogFormatter which is customizable as well. So we can a different log layout for file or console output. The indent could be a tab, but in my opinion a single * or a single .(dot) would be ok.
Tow, I hope I could give and share you some ideas. Feel free to implement it!

That’s right. Hopefully we have not to wait till next VS release(2015)

In regard to the revision 3335 sourceforge.net/apps/trac/vcmi/changeset/3335 I have to say two things. First of all, thanks to stopiccot for fixing the bug:) It was definitely difficult to find. Strangely enough it doesn’t caused a bug when compiling with GCC or VC. Luckily in the same compilation unit the static initialization order is defined. So it should be fine now.
The second point is that normally objects with relationships to other objects should be initialized after execution entered the main function or in a lazy init function(which will be called after the main function). The lazy init function approach requires for each function a separate static mutex to be thread-safe. If you don’t use this approach, you have to be sure that you haven’t forgotten to initialize logger objects. I think it’s best to keep things like they are now.

I did two more changes:

1. Set default level of logging to the trace. VCMI builds are mainly meant for testers and they should gather as much info as possible.
2. Fixed an issue with tracing macros. They were like

if(tracing_enabled)
{ RAII_tracer object(params); }

That caused guardian to be destructed immediately after macro’s “if”, not at the end of enclosing scope. I used unique_ptr to represent a guardian object that may be constructed or not. I’m not sure if it is the best approach. I considered boost::optional but encountered some issues with object copying causing additional logs. Can be done, though I found that not effort-worthy.

I like the idea. If we stack Trace objects, they naturally create a stacktrace, so we should take advantage of it.

I fully agree.

Thanks! However, likely I won’t touch that soon, too much other work.

That’s ok and thanks for the bug-fix!