Logging

International board Development
#1

I’ve thought of some improvements regarding logging. Currently logger objects are named like tlog[1-6]. What about changing it to more readable and comprehensible names? I would also remove some logger levels as they’re barerly different when I think about major/minor warning. My proposal:

tlog0 -> logInfo
tlog1 -> logError
tlog2 -> logWarn
tlog3 -> remove (belongs to logWarn)
tlog4 -> remove (belongs to logDebug)
tlog5 -> logDebug
tlog6 -> remove (belongs to logDebug)

So we would have four different logger objects/levels. Refactoring should be relatively easy with find/replace.

My next point is colored logging. Many IDEs(qtcreator, eclipse) have problems in interpreting color codes, so they are represented as raw text in the console output window which makes it mostly unreadable. Is there anyone who wants to keep it as it is? We could make color output optional as well. (settings.json). To see the different better between warning and debug then, the log level could be printed before the actual log message.
e.g.: DEBUG: This is a very boring debug message:)
Printing the log level on your own becomes unnecessary e.g. tlog3 << "Warn: …"
Errors could be directed to std::cerr insted of std::cout. Most editors can interpret this and display error texts in red.

PS: Sorry, what I forgot to say is that if I will do that refactoring/changes then not before 0.9.1 release. It will change mostly every source file, so I’ll say you the exact date. After a release there aren’t so many SC updates, this will probably the best time.

#2

The purpose of different loggers is just to color the text. Tlog6 for example is teal log for AI, very different from everything else.

But I agree that loggers should be given some more menaingful names, personally i find it hard to find out which one is which.

#3

A good idea for refactoring. Along with these changes you could add more logging, I think. BTW, Info should be split to two levels: major info and minor notices. We don’t have many messages that should be notices but we should have more.

You could also think about outputting something parsable by log browsers.

#4

Another possibility is split logDebug into domain-specific loggers (domain AI, domain bonus system, etc). By default all of them write to file only, but also can be set to write to console as well (should be done without recompilation)

So one developer can enable logging only messages from specific subsystem he is working on instead of whole engine.

I’d like to keep it, but making it optional is fine for me.

#5

It is intended for displaying certain log level messages only as well. The part missing here is as Ivan said that the log level of console/file should be customizable via config file, not only via recompilation. So you can display errors in console only and warnings+errors in file for example.

@Tow dragon:
Can you give some examples for major info messages and notices? Can you name some log browsers? So I can see how valuable they are.

Proposal for domain-specific loggers:
logDebug -> for general debug messages
logAI
logBonus
logRMG
I think it should be fine to don’t mention debug in domain-specific debug loggers.
These loggers can be enabled/disabled via config file separately.

We should also think if it’s ok to print all debug messages to file by default. For the novice user I would disable all debugging stuff. The user can then freely customize the log level and set it to debug if it’s required.

No problem! Colored output remains default setting.

#6

major info: “map loaded”, “game ended”, "battle started"
notices: “package from server received”, “path costs calculated”

Something like retrospective.centeractive.c … ent/search . I’m not sure if there are free log browsers like these.

I think domain and importance are more or less unrelated but standarizing domain info looks like a good idea.

#7

IMO notices are debug messages, aren’t they? Log levels should be clear and distinguishable.

Personally I don’t need a log browser or a log viewer. From what I see they are intended for system/server log messages where logging is active over several weeks/months. Admins need a filtering functionality according to a date criteria.
If we specify log level and log debug domains via config file, this will be enough for most cases. With the standardized output “header” (WARN: ) the importance of the message can be read fast. Many text editors can display same texts highlighted and if it’s really required they allow custom syntax highlighting like Gedit where error messages can be displayed red for example. (which should be trivial to implement…)

#8

Compare with this, for example: logging.apache.org/log4j/1.2/api … Level.html

Notices mean progress in execution, debug gives additional, possibly runtime-generated information.
notice: 'hero movement completed’
debug: ‘hero moved to (12,3,0), direction 3’, ‘following artifacts influence X: …’

#9

Logging changes are planned for the 2nd/3rd feburary 2013. So stay tuned! If you want to check-in sth. before, then do it. If this date isn’t ok for you, just cry.

@Tow dragon:
Can I name notices trace(logTrace) instead, as probably this term is more used and better known(coming from java,as,…)?

#10

OK, no problem.

#11

It may be too late to put my 0.02$ but I’ll anyway. :wink:

Initially loggers were created to separate different levels of severity. But over the time they got to be used just to color the output. (tlog1/tlog4/tlog6 are pretty much all debug output) Basic issue: ATM we have loggers that are like tuples<Severity, Color, Module>. tlog3 is <Warning, Yellow, Engine>, tlog6 <Log, Teal, AI>. This is not flexible.

I am against removing colors or making the current tlog6 and tlog4 the same thing. Color is an important factor for me that allows very quickly recognize what is what in the console without cluttering it with additional text. Having different colors for AI logs and engine logs is just helpful. Making it optional is fine.

Some things to consider:

  • several loggers for various modules. Each of them would have its own severity=>color mapping. AI_Logger.Debug would be then a different thing Engine.Debug and that makes sense. Allow various modules (like AI) have their own loggers with their own colors and so on.
  • color should be used only for console output. In file place additional text info — like that TRACE/WARNING headers, module, and so on. Make that configurable.
#12

No, they will come later:) I got some interesting plans regarding logging. Logging levels, logging format to file, color settings,… among other things will be configurable.

#13

@beegee
Just don’t make it overcomplicated ;).

BTW, I think new syntax for logging should be discussed here before doing the refactoring. I’ll be quite significant change.

#14

Finally, I have time to write about my plans regarding logging:) Still there is no new logging API or any code programmed for it. As Tow Dragon said, it’ll be better to discuss such a change before actual development concretely, than investing many hours in rewritting things a few times.

I have compared several C++ logging frameworks to gather ideas for our own API:
Pantheios
Log4cxx
Boost Log

The only framework which has support for different logging domains, which is required to fulfill our needs, is log4cxx. The current class design is based on it with minor modifications. It is kept simple, but flexible.

That’s how logging can look like:

// Read config file(settings.json), create & configure log targets, setup initial log levels
CBasicLogConfigurator logConfig("/path_to_log_file/home/xxx/.vcmi/log.txt");

// The log API calls are encapsulated in C macros to provide a typical c++ "std::cout <<" stream syntax and
// to retrieve & print information which is only available to the C precompiler (function name, line number, etc...)
LOG_INFO(log, "Info message" << x << std::endl);

// Logs a message to a different logger which has a different domain
LOG_DEBUG(logBonus, "Bonus message" << std::endl);

The UML class diagram is attached to the post. Below a short explanation of all classes:
CLogger: Represents the logger object. It has a name and a log level.
CLogManager: Holds all logger instances & applied log targets
CBasicLogConfigurator: See description above.
CLogFileTarget: Writes log records to file. It has a format setting.
CLogConsoleTarget: Writes log records to console. It has a format & color setting.
CLogFormatter: Formats log records to strings with a fix conversion format.
CLogRecord: Represents a single log message.

The settings.json configuration file can look like this:

{
	"adventure" : {
	},
	"battle" : {
	},
	"general" : {
		"music" : 0,
		"sound" : 0
	},
	"server" : {
	},
	"video" : {
		"screenRes" : {
			"height" : 900,
			"width" : 1440
		}
	},
	"logging" : {
		"console.enableColoredOutput" : true,
		"console.minLogLevel" : "info",
		// any more wishes regarding logging format?
		"file.format" : "%l %n (%t-%f) - %m",
		"console.format" : "%n - %m",
		"loggers" : 
			{
				"rootLogger" : 
				{
					"level" : "info",
					"color.debug" : "yellow"
				},
				"rootLogger.bonus" :
				{
					"level" : "trace",
					"color.debug" : "green"
				}
			}
		]
	}
}

rootLogger.bonus is a logger which is derived from rootLogger. It inherits the log level & color mapping. In the above config it overwrites the level and the color mapping for the debug level. The dot between rootLogger and bonus visualizes the inheritance relationship.

Short explanation of the log format:
%l -> log level
%n -> name of logger
%t -> thread id
%f -> function name
%m -> message

class_diagram_logging.png1295×565 20.1 KB

#15

Great work, beegee. Your design look reasonable.

Boost.Log does similar thing with its attributes, though they don’t support inheritance. I don’t have any preference here anyway.

I just have a suggestion to make logging thread-safe.

#16

Any reason not to use one of those?
Quick look on boost log shows that it can do what we need:
boost-log.sourceforge.net/libs/l … /defs.html

So we may define some functions that will set two attributes to log message: domain and severity and then use filters to determine where it should be printed (file, console, nowhere).
Maybe even add “inheritance” or sub-domains by allowing more than two attributes at once.

I’m pretty much neutral on how you’re going to implement logging so custom system is OK with me but why write same functionality as in these libraries?

#17

Opps, that’s true. Boost log records/sources can be extended with (custom) attributes like domain(they name it channel) or severity. Both attributes are supported by standard logger types. There are filters which can be applied on sinks which can omit specific log records. The boost log library looks interesting and has a very good documentation. All in all it is highly customizable. It has no support for inheritance, but I don’t think that it’s really needed. Sadly there is one problem with the Boost log API. It is not part of the standard boost libraries.

This library is not an official part of Boost libraries collection although it has passed the review and is provisionally accepted. The review result is available here.

boost-log.sourceforge.net/libs/l … index.html

It is a relatively new API, the first version has been released on 9 may 2010. Boost log v2 is still in beta, which is not a real problem. Don’t know if the library is compatible with boost version 1.47 and older.

boost-log.sourceforge.net/libs/l … gelog.html
Boost FS v2 is not supported which shouldn’t be a problem. Don’t know if boost 1.48 could be a problem. In our windows compilation guide it is said that boost 1.51 is required even whereas the linux guide states that boost 1.44 is enough.

Boost log has to be compiled on *NIX operating systems by yourself. There are no prebuild RPM packages or sth. like that, at least not for Fedora in the official repos. Boost log cannot be build separately, it has to be done with the boost compilation system(bjam). So I don’t think that we can include it in our CMake build system.

@Ivan:
Could you review sketchily how we can integrate Boost log into our current build system(at least for *NIX systems) and how much effort it will take? Thanks.

#18

1.48 requirement is something we can live with - Ubuntu LTS comes with 1.46 and 1.48, next Debian Stable will have 1.49. Everyone else is much faster with updates.
Besides - it does not says “requires” but “compatible”. So boost log may not require 1.48

Can be a problem.

  • Integrating into CMake would be hard - this would need writing CMake files for boost.log
  • Providing packages for boost log - much more easier. But still would need some work
  • Static linking into vcmi lib - can be difficult to setup for regular users who compile from source.

IMO providing packages is the easiest way. Some distributions already have boost log as user-provided packages so at least part of work is already done.

#19

Me too. Let’s describe shortly which changes it will have to add boost-log to our library dependencies. Developers on Windows & *NIX have to build Boost with the log library. This is easy(just a few command line steps) and you can tell the boost build system to build the log library only(if the rest is already installed/built on your system). So this shouldn’t be a problem. Users on Windows aren’t required to do any extra steps. Boost libraries are statically linked. Users on *NIX systems have to install a boost-log package which we have to provide if there isn’t any available from external.(PPA or official repos). Perhaps it is possible to write an shell install script which bundles vcmi and boost-log in one file(in case of simplicity).

Changes are high that Boost log v2 will be added to the core boost libraries, when v2 is officially released. (stable release) But this will take some time. Then we won’t have to provide packages for the log library.

Now it depends on from what we benefit more in the long term. I’ve created a class diagram already and have a clear picture of how to develop an own logging API. The effort shouldn’t be that high. A problem could be to write it thread-safe which is a must criteria. (not so much exp in it, but anyway). On the other hand we could use the boost log API. It doesn’t come without any additional work. It has to be extended and customized to fit our needs. In concrete terms this means: Parsing our configuration from JSON and setup the log configuration(sources, sinks,etc…), writing a console backend(handling of colored output, some sort of inheritance respective overriding default values) and writing some macros for easier access. A problem could be the extra step in compiling and deploying it.

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?

PS:

I wonder what are the problems to linking it statically? Isn’t that easier compared to providing own packages? That way users aren’t required to do any additional step at least.

#20

Perhaps try to use syntax similar to boost log and later (if needed) - switch to it?
Something like this should be great:

logger::trace("network") << "Package received\n";
logger::error("global") << "Something evil happened\n";

Everything else (like most of your class diagram) will be hidden internally with initialization done in something like logger::init(JsonNode & config)

Fine with me either way but introducing library that is not trivial to install (for users) may not be the best idea.

  1. Mix of static and dynamic boost libraries may not work correctly
  2. Those users who compile from source will need to setup this themselves
  3. We will need to either provide Cmake files for boost log OR depend on boost build system