Refactor logging

- Add warning log level
- Change debug_log_level setting to enumeration string
- Map Irrlicht log events to MT log events
- Encapsulate log_* functions and global variables into a class, Logger
- Unify dstream with standard logging mechanism
- Unify core.debug() with standard core.log() script API

1 files changed, 56 insertions, 69 deletions

diff --git a/src/main.cpp b/src/main.cpp
index dece27428..cc8b4bcaa 100644
--- a/src/main.cpp
+++ b/src/main.cpp
@@ -80,10 +80,10 @@ static void list_game_ids();
 static void list_worlds();
 static void setup_log_params(const Settings &cmd_args);
 static bool create_userdata_path();
-static bool init_common(int *log_level, const Settings &cmd_args, int argc, char *argv[]);
+static bool init_common(const Settings &cmd_args, int argc, char *argv[]);
 static void startup_message();
 static bool read_config_file(const Settings &cmd_args);
-static void init_debug_streams(int *log_level, const Settings &cmd_args);
+static void init_log_streams(const Settings &cmd_args);
 
 static bool game_configure(GameParams *game_params, const Settings &cmd_args);
 static void game_configure_port(GameParams *game_params, const Settings &cmd_args);
@@ -122,25 +122,7 @@ u32 getTime(TimePrecision prec)
 
 #endif
 
-class StderrLogOutput: public ILogOutput
-{
-public:
-	/* line: Full line with timestamp, level and thread */
-	void printLog(const std::string &line)
-	{
-		std::cerr << line << std::endl;
-	}
-} main_stderr_log_out;
-
-class DstreamNoStderrLogOutput: public ILogOutput
-{
-public:
-	/* line: Full line with timestamp, level and thread */
-	void printLog(const std::string &line)
-	{
-		dstream_no_stderr << line << std::endl;
-	}
-} main_dstream_no_stderr_log_out;
+FileLogOutput file_log_output;
 
 static OptionList allowed_options;
 
@@ -150,10 +132,8 @@ int main(int argc, char *argv[])
 
 	debug_set_exception_handler();
 
-	log_add_output_maxlev(&main_stderr_log_out, LMT_ACTION);
-	log_add_output_all_levs(&main_dstream_no_stderr_log_out);
-
-	log_register_thread("Main");
+	g_logger.registerThread("Main");
+	g_logger.addOutputMaxLevel(&stderr_output, LL_ACTION);
 
 	Settings cmd_args;
 	bool cmd_args_ok = get_cmdline_opts(argc, argv, &cmd_args);
@@ -180,8 +160,7 @@ int main(int argc, char *argv[])
 	}
 
 	// Initialize debug stacks
-	debug_stacks_init();
-	DSTACK(__FUNCTION_NAME);
+	DSTACK(FUNCTION_NAME);
 
 	// Debug handler
 	BEGIN_DEBUG_EXCEPTION_HANDLER
@@ -198,8 +177,7 @@ int main(int argc, char *argv[])
 		return 0;
 	}
 
-	GameParams game_params;
-	if (!init_common(&game_params.log_level, cmd_args, argc, argv))
+	if (!init_common(cmd_args, argc, argv))
 		return 1;
 
 #ifndef __ANDROID__
@@ -210,6 +188,7 @@ int main(int argc, char *argv[])
 	}
 #endif
 
+	GameParams game_params;
 #ifdef SERVER
 	game_params.is_dedicated_server = true;
 #else
@@ -219,7 +198,7 @@ int main(int argc, char *argv[])
 	if (!game_configure(&game_params, cmd_args))
 		return 1;
 
-	sanity_check(game_params.world_path != "");
+	sanity_check(!game_params.world_path.empty());
 
 	infostream << "Using commanded world path ["
 	           << game_params.world_path << "]" << std::endl;
@@ -247,7 +226,7 @@ int main(int argc, char *argv[])
 	// Stop httpfetch thread (if started)
 	httpfetch_cleanup();
 
-	END_DEBUG_EXCEPTION_HANDLER(errorstream)
+	END_DEBUG_EXCEPTION_HANDLER(errorstream);
 
 	return retval;
 }
@@ -403,26 +382,26 @@ static void setup_log_params(const Settings &cmd_args)
 {
 	// Quiet mode, print errors only
 	if (cmd_args.getFlag("quiet")) {
-		log_remove_output(&main_stderr_log_out);
-		log_add_output_maxlev(&main_stderr_log_out, LMT_ERROR);
+		g_logger.removeOutput(&stderr_output);
+		g_logger.addOutputMaxLevel(&stderr_output, LL_ERROR);
 	}
 
 	// If trace is enabled, enable logging of certain things
 	if (cmd_args.getFlag("trace")) {
 		dstream << _("Enabling trace level debug output") << std::endl;
-		log_trace_level_enabled = true;
-		dout_con_ptr = &verbosestream; // this is somewhat old crap
-		socket_enable_debug_output = true; // socket doesn't use log.h
+		g_logger.setTraceEnabled(true);
+		dout_con_ptr = &verbosestream; // This is somewhat old
+		socket_enable_debug_output = true; // Sockets doesn't use log.h
 	}
 
 	// In certain cases, output info level on stderr
 	if (cmd_args.getFlag("info") || cmd_args.getFlag("verbose") ||
 			cmd_args.getFlag("trace") || cmd_args.getFlag("speedtests"))
-		log_add_output(&main_stderr_log_out, LMT_INFO);
+		g_logger.addOutput(&stderr_output, LL_INFO);
 
 	// In certain cases, output verbose level on stderr
 	if (cmd_args.getFlag("verbose") || cmd_args.getFlag("trace"))
-		log_add_output(&main_stderr_log_out, LMT_VERBOSE);
+		g_logger.addOutput(&stderr_output, LL_VERBOSE);
 }
 
 static bool create_userdata_path()
@@ -450,7 +429,7 @@ static bool create_userdata_path()
 	return success;
 }
 
-static bool init_common(int *log_level, const Settings &cmd_args, int argc, char *argv[])
+static bool init_common(const Settings &cmd_args, int argc, char *argv[])
 {
 	startup_message();
 	set_default_settings(g_settings);
@@ -462,7 +441,7 @@ static bool init_common(int *log_level, const Settings &cmd_args, int argc, char
 	if (!read_config_file(cmd_args))
 		return false;
 
-	init_debug_streams(log_level, cmd_args);
+	init_log_streams(cmd_args);
 
 	// Initialize random seed
 	srand(time(0));
@@ -533,38 +512,47 @@ static bool read_config_file(const Settings &cmd_args)
 	return true;
 }
 
-static void init_debug_streams(int *log_level, const Settings &cmd_args)
+static void init_log_streams(const Settings &cmd_args)
 {
 #if RUN_IN_PLACE
-	std::string logfile = DEBUGFILE;
+	std::string log_filename = DEBUGFILE;
 #else
-	std::string logfile = porting::path_user + DIR_DELIM + DEBUGFILE;
+	std::string log_filename = porting::path_user + DIR_DELIM + DEBUGFILE;
 #endif
 	if (cmd_args.exists("logfile"))
-		logfile = cmd_args.get("logfile");
-
-	log_remove_output(&main_dstream_no_stderr_log_out);
-	*log_level = g_settings->getS32("debug_log_level");
-
-	if (*log_level == 0) //no logging
-		logfile = "";
-	if (*log_level < 0) {
-		dstream << "WARNING: Supplied debug_log_level < 0; Using 0" << std::endl;
-		*log_level = 0;
-	} else if (*log_level > LMT_NUM_VALUES) {
-		dstream << "WARNING: Supplied debug_log_level > " << LMT_NUM_VALUES
-		        << "; Using " << LMT_NUM_VALUES << std::endl;
-		*log_level = LMT_NUM_VALUES;
+		log_filename = cmd_args.get("logfile");
+
+	g_logger.removeOutput(&file_log_output);
+	std::string conf_loglev = g_settings->get("debug_log_level");
+
+	// Old integer format
+	if (std::isdigit(conf_loglev[0])) {
+		warningstream << "Deprecated use of debug_log_level with an "
+			"integer value; please update your configuration." << std::endl;
+		static const char *lev_name[] =
+			{"", "error", "action", "info", "verbose"};
+		int lev_i = atoi(conf_loglev.c_str());
+		if (lev_i < 0 || lev_i >= (int)ARRLEN(lev_name)) {
+			warningstream << "Supplied invalid debug_log_level!"
+				"  Assuming action level." << std::endl;
+			lev_i = 2;
+		}
+		conf_loglev = lev_name[lev_i];
 	}
 
-	log_add_output_maxlev(&main_dstream_no_stderr_log_out,
-			(LogMessageLevel)(*log_level - 1));
+	if (conf_loglev.empty())  // No logging
+		return;
 
-	debugstreams_init(false, logfile == "" ? NULL : logfile.c_str());
+	LogLevel log_level = Logger::stringToLevel(conf_loglev);
+	if (log_level == LL_MAX) {
+		warningstream << "Supplied unrecognized debug_log_level; "
+			"using maximum." << std::endl;
+	}
 
-	infostream << "logfile = " << logfile << std::endl;
+	verbosestream << "log_filename = " << log_filename << std::endl;
 
-	atexit(debugstreams_deinit);
+	file_log_output.open(log_filename.c_str());
+	g_logger.addOutputMaxLevel(&file_log_output, log_level);
 }
 
 static bool game_configure(GameParams *game_params, const Settings &cmd_args)
@@ -678,10 +666,10 @@ static bool auto_select_world(GameParams *game_params)
 		        << world_path << "]" << std::endl;
 	// If there are multiple worlds, list them
 	} else if (worldspecs.size() > 1 && game_params->is_dedicated_server) {
-		dstream << _("Multiple worlds are available.") << std::endl;
-		dstream << _("Please select one using --worldname <name>"
+		std::cerr << _("Multiple worlds are available.") << std::endl;
+		std::cerr << _("Please select one using --worldname <name>"
 				" or --world <path>") << std::endl;
-		print_worldspecs(worldspecs, dstream);
+		print_worldspecs(worldspecs, std::cerr);
 		return false;
 	// If there are no worlds, automatically create a new one
 	} else {
@@ -774,7 +762,7 @@ static bool determine_subgame(GameParams *game_params)
 		if (game_params->game_spec.isValid()) {
 			gamespec = game_params->game_spec;
 			if (game_params->game_spec.id != world_gameid) {
-				errorstream << "WARNING: Using commanded gameid ["
+				warningstream << "Using commanded gameid ["
 				            << gamespec.id << "]" << " instead of world gameid ["
 				            << world_gameid << "]" << std::endl;
 			}
@@ -835,9 +823,8 @@ static bool run_dedicated_server(const GameParams &game_params, const Settings &
 		return migrate_database(game_params, cmd_args);
 
 	// Create server
-	Server server(game_params.world_path,
-			game_params.game_spec, false, bind_addr.isIPv6());
-
+	Server server(game_params.world_path, game_params.game_spec, false,
+		bind_addr.isIPv6());
 	server.start(bind_addr);
 
 	// Run server