Add/remove/change some log messages for clarity

builtin/game/chat.lua

@@ -60,6 +60,8 @@ core.register_on_chat_message(function(name, message)
 
 	param = param or ""
 
+	core.log("verbose", string.format("Handling chat command %q with params %q", cmd, param))
+
 	-- Run core.registered_on_chatcommands callbacks.
 	if core.run_callbacks(core.registered_on_chatcommands, 5, name, cmd, param) then
 		return true

src/client/client.cpp

@@ -869,6 +869,8 @@ bool Client::loadMedia(const std::string &data, const std::string &filename,
 	const char *font_ext[] = {".ttf", ".woff", NULL};
 	name = removeStringEnd(filename, font_ext);
 	if (!name.empty()) {
+		verbosestream<<"Client: Loading file as font: \""
+				<< filename << "\"" << std::endl;
 		g_fontengine->setMediaFont(name, data);
 		return true;
 	}

src/client/shader.cpp

@@ -451,9 +451,6 @@ u32 ShaderSource::getShaderIdDirect(const std::string &name,
 	u32 id = m_shaderinfo_cache.size();
 	m_shaderinfo_cache.push_back(info);
 
-	infostream<<"getShaderIdDirect(): "
-			<<"Returning id="<<id<<" for name \""<<name<<"\""<<std::endl;
-
 	return id;
 }
 
@@ -789,7 +786,7 @@ ShaderInfo ShaderSource::generateShader(const std::string &name,
 		dumpShaderProgram(warningstream, "Fragment", fragment_shader);
 		dumpShaderProgram(warningstream, "Geometry", geometry_shader);
 		throw ShaderException(
-			fmtgettext("Failed to compile the \"%s\" shader.", name.c_str()) +
+			fmtgettext("Failed to compile the \"%s\" shader.", log_name.c_str()) +
 			strgettext("\nCheck debug.txt for details."));
 	}
 

src/content/mod_configuration.cpp

@@ -34,6 +34,8 @@ std::string ModConfiguration::getUnsatisfiedModsError() const
 
 void ModConfiguration::addModsInPath(const std::string &path, const std::string &virtual_path)
 {
+	verbosestream << "Adding mods from path " << path << " virtual=\""
+		<< virtual_path << "\"" << std::endl;
 	addMods(flattenMods(getModsInPath(path, virtual_path)));
 }
 

src/gettext.h

@@ -59,6 +59,7 @@ inline std::wstring wstrgettext(const std::string &str)
  * @tparam Args Template parameter for format args
  * @param src Translation source string
  * @param args Variable format args
+ * @warning No dynamic sizing! string will be cut off if longer than 255 chars.
  * @return translated string
  */
 template <typename ...Args>
@@ -81,14 +82,19 @@ inline std::wstring fwgettext(const char *src, Args&&... args)
 template <typename ...Args>
 inline std::string fmtgettext(const char *format, Args&&... args)
 {
-	std::string buf;
-	std::size_t buf_size = 256;
-	buf.resize(buf_size);
-
 	format = gettext(format);
 
-	int len = porting::mt_snprintf(&buf[0], buf_size, format, std::forward<Args>(args)...);
-	if (len <= 0) throw std::runtime_error("gettext format error: " + std::string(format));
+	std::string buf;
+	{
+		size_t default_size = strlen(format);
+		if (default_size < 256)
+			default_size = 256;
+		buf.resize(default_size);
+	}
+
+	int len = porting::mt_snprintf(&buf[0], buf.size(), format, std::forward<Args>(args)...);
+	if (len <= 0)
+		throw std::runtime_error("gettext format error: " + std::string(format));
 	if ((size_t)len >= buf.size()) {
 		buf.resize(len+1); // extra null byte
 		porting::mt_snprintf(&buf[0], buf.size(), format, std::forward<Args>(args)...);

src/nodedef.cpp

@@ -1299,7 +1299,7 @@ content_t NodeDefManager::set(const std::string &name, const ContentFeatures &de
 		// Get new id
 		id = allocateId();
 		if (id == CONTENT_IGNORE) {
-			warningstream << "NodeDefManager: Absolute "
+			errorstream << "NodeDefManager: Absolute "
 				"limit reached" << std::endl;
 			return CONTENT_IGNORE;
 		}
@@ -1307,15 +1307,14 @@ content_t NodeDefManager::set(const std::string &name, const ContentFeatures &de
 		addNameIdMapping(id, name);
 	}
 
-	// If there is already ContentFeatures registered for this id, clear old groups
-	if (id < m_content_features.size())
-		eraseIdFromGroups(id);
+	// Clear old groups in case of re-registration
+	eraseIdFromGroups(id);
 
 	m_content_features[id] = def;
 	m_content_features[id].floats = itemgroup_get(def.groups, "float") != 0;
 	m_content_lighting_flag_cache[id] = def.getLightingFlags();
-	verbosestream << "NodeDefManager: registering content id \"" << id
-		<< "\": name=\"" << def.name << "\""<<std::endl;
+	verbosestream << "NodeDefManager: registering content id " << id
+		<< ": name=\"" << def.name << "\"" << std::endl;
 
 	getNodeBoxUnion(def.selection_box, def, &m_selection_box_union);
 	fixSelectionBoxIntUnion();
@@ -1349,9 +1348,9 @@ void NodeDefManager::removeNode(const std::string &name)
 	if (m_name_id_mapping.getId(name, id)) {
 		m_name_id_mapping.eraseName(name);
 		m_name_id_mapping_with_aliases.erase(name);
-	}
 
-	eraseIdFromGroups(id);
+		eraseIdFromGroups(id);
+	}
 }
 
 
@@ -1475,8 +1474,7 @@ void NodeDefManager::serialize(std::ostream &os, u16 protocol_version) const
 		os2<<serializeString16(wrapper_os.str());
 
 		// must not overflow
-		u16 next = count + 1;
-		FATAL_ERROR_IF(next < count, "Overflow");
+		FATAL_ERROR_IF(count == U16_MAX, "overflow");
 		count++;
 	}
 	writeU16(os, count);
@@ -1524,7 +1522,7 @@ void NodeDefManager::deSerialize(std::istream &is, u16 protocol_version)
 
 		// All is ok, add node definition with the requested ID
 		if (i >= m_content_features.size())
-			m_content_features.resize((u32)(i) + 1);
+			m_content_features.resize((size_t)(i) + 1);
 		m_content_features[i] = f;
 		m_content_features[i].floats = itemgroup_get(f.groups, "float") != 0;
 		m_content_lighting_flag_cache[i] = f.getLightingFlags();
@@ -1598,13 +1596,6 @@ void NodeDefManager::resetNodeResolveState()
 	m_pending_resolve_callbacks.clear();
 }
 
-static void removeDupes(std::vector<content_t> &list)
-{
-	std::sort(list.begin(), list.end());
-	auto new_end = std::unique(list.begin(), list.end());
-	list.erase(new_end, list.end());
-}
-
 void NodeDefManager::resolveCrossrefs()
 {
 	for (ContentFeatures &f : m_content_features) {
@@ -1619,7 +1610,7 @@ void NodeDefManager::resolveCrossrefs()
 		for (const std::string &name : f.connects_to) {
 			getIds(name, f.connects_to_ids);
 		}
-		removeDupes(f.connects_to_ids);
+		SORT_AND_UNIQUE(f.connects_to_ids);
 	}
 }
 

src/pathfinder.cpp

@@ -879,10 +879,10 @@ PathCost Pathfinder::calcCost(v3s16 pos, v3s16 dir)
 					DEBUG_OUT("Pathfinder cost below height found" << std::endl);
 				}
 				else {
-					INFO_TARGET << "Pathfinder:"
+					DEBUG_OUT("Pathfinder:"
 							" distance to surface below too big: "
 							<< (testpos.Y - pos2.Y) << " max: " << m_maxdrop
-							<< std::endl;
+							<< std::endl);
 				}
 			}
 			else {

src/script/lua_api/l_mapgen.cpp

@@ -428,7 +428,7 @@ size_t get_biome_list(lua_State *L, int index,
 	if (is_single) {
 		Biome *biome = get_or_load_biome(L, index, biomemgr);
 		if (!biome) {
-			infostream << "get_biome_list: failed to get biome '"
+			warningstream << "get_biome_list: failed to get biome '"
 				<< (lua_isstring(L, index) ? lua_tostring(L, index) : "")
 				<< "'." << std::endl;
 			return 1;
@@ -445,7 +445,7 @@ size_t get_biome_list(lua_State *L, int index,
 		Biome *biome = get_or_load_biome(L, -1, biomemgr);
 		if (!biome) {
 			fail_count++;
-			infostream << "get_biome_list: failed to get biome '"
+			warningstream << "get_biome_list: failed to get biome '"
 				<< (lua_isstring(L, -1) ? lua_tostring(L, -1) : "")
 				<< "'" << std::endl;
 			continue;

src/server.cpp

@@ -567,8 +567,7 @@ void Server::start()
 {
 	init();
 
-	infostream << "Starting server on " << m_bind_addr.serializeString()
-			<< "..." << std::endl;
+	infostream << "Starting server thread..." << std::endl;
 
 	// Stop thread if already running
 	m_thread->stop();
@@ -967,6 +966,7 @@ void Server::AsyncRunStep(float dtime, bool initial_step)
 		// We'll log the amount of each
 		Profiler prof;
 
+		size_t block_count = 0;
 		std::unordered_set<v3s16> node_meta_updates;
 
 		while (!m_unsent_map_edit_queue.empty()) {
@@ -1015,6 +1015,8 @@ void Server::AsyncRunStep(float dtime, bool initial_step)
 				break;
 			}
 
+			block_count += event->modified_blocks.size();
+
 			/*
 				Set blocks not sent to far players
 			*/
@@ -1026,11 +1028,9 @@ void Server::AsyncRunStep(float dtime, bool initial_step)
 			delete event;
 		}
 
-		if (event_count >= 5) {
-			infostream << "Server: MapEditEvents:" << std::endl;
-			prof.print(infostream);
-		} else if (event_count != 0) {
-			verbosestream << "Server: MapEditEvents:" << std::endl;
+		if (event_count != 0) {
+			verbosestream << "Server: MapEditEvents modified total "
+				<< block_count << " blocks:" << std::endl;
 			prof.print(verbosestream);
 		}
 
@@ -1310,9 +1310,7 @@ void Server::ProcessData(NetworkPacket *pkt)
 		}
 
 		if (m_clients.getClientState(peer_id) < CS_Active) {
-			if (command == TOSERVER_PLAYERPOS) return;
-
-			errorstream << "Server: Got packet command "
+			warningstream << "Server: Got packet command "
 					<< static_cast<unsigned>(command)
 					<< " for peer id " << peer_id
 					<< " but client isn't active yet. Dropping packet." << std::endl;
@@ -2166,10 +2164,6 @@ void Server::SendActiveObjectRemoveAdd(RemoteClient *client, PlayerSAO *playersa
 	}
 
 	Send(&pkt);
-
-	verbosestream << "Server::SendActiveObjectRemoveAdd(): "
-		<< removed_objects.size() << " removed, " << added_objects.size()
-		<< " added, packet size is " << pkt.getSize() << std::endl;
 }
 
 void Server::SendActiveObjectMessages(session_t peer_id, const std::string &datas,
@@ -3921,7 +3915,11 @@ std::string Server::getBuiltinLuaPath()
 
 void Server::setAsyncFatalError(const std::string &error)
 {
+	// print error right here in the thread that set it, for clearer logging
+	infostream << "setAsyncFatalError: " << error << std::endl;
+
 	m_async_fatal_error.set(error);
+
 	// make sure server steps stop happening immediately
 	if (m_thread)
 		m_thread->stop();

src/server/mods.cpp

@@ -42,21 +42,25 @@ void ServerModManager::loadMods(ServerScripting &script)
 	for (const ModSpec &mod : configuration.getMods()) {
 		infostream << mod.name << " ";
 	}
-
 	infostream << std::endl;
+
 	// Load and run "mod" scripts
+	auto t0 = porting::getTimeMs();
 	for (const ModSpec &mod : configuration.getMods()) {
 		mod.checkAndLog();
 
+		auto t1 = porting::getTimeMs();
 		std::string script_path = mod.path + DIR_DELIM + "init.lua";
-		auto t = porting::getTimeMs();
 		script.loadMod(script_path, mod.name);
 		infostream << "Mod \"" << mod.name << "\" loaded after "
-			<< (porting::getTimeMs() - t) << " ms" << std::endl;
+			<< (porting::getTimeMs() - t1) << " ms" << std::endl;
 	}
 
 	// Run a callback when mods are loaded
 	script.on_mods_loaded();
+
+	infostream << "All mods loaded after " << (porting::getTimeMs() - t0)
+		<< " ms" << std::endl;
 }
 
 const ModSpec *ServerModManager::getModSpec(const std::string &modname) const

src/serverenvironment.cpp

@@ -472,28 +472,25 @@ void ServerEnvironment::loadMeta()
 	SANITY_CHECK(!m_meta_loaded);
 	m_meta_loaded = true;
 
+	// This has nothing to do with this method but it's nice to know
+	infostream << "ServerEnvironment: " << m_abms.size() << " ABMs are registered" << std::endl;
+
 	std::string path = m_server->getWorldPath() + DIR_DELIM "env_meta.txt";
 
 	// If file doesn't exist, load default environment metadata
 	if (!fs::PathExists(path)) {
-		infostream << "ServerEnvironment: Loading default environment metadata"
-			<< std::endl;
 		loadDefaultMeta();
 		return;
 	}
 
-	infostream << "ServerEnvironment: Loading environment metadata" << std::endl;
+	infostream << "ServerEnvironment: Loading environment metadata from file" << std::endl;
 
 	// Open file and deserialize
-	std::ifstream is(path.c_str(), std::ios_base::binary);
-	if (!is.good()) {
-		infostream << "ServerEnvironment::loadMeta(): Failed to open "
-			<< path << std::endl;
+	auto is = open_ifstream(path.c_str(), true);
+	if (!is.good())
 		throw SerializationError("Couldn't load env meta");
-	}
 
 	Settings args("EnvArgsEnd");
-
 	if (!args.parseConfigLines(is)) {
 		throw SerializationError("ServerEnvironment::loadMeta(): "
 			"EnvArgsEnd not found!");
@@ -503,32 +500,32 @@ void ServerEnvironment::loadMeta()
 		m_game_time = args.getU64("game_time");
 	} catch (SettingNotFoundException &e) {
 		// Getting this is crucial, otherwise timestamps are useless
-		throw SerializationError("Couldn't load env meta game_time");
+		throw SerializationError("Couldn't read game_time from env meta");
 	}
 
 	setTimeOfDay(args.exists("time_of_day") ?
-		// set day to early morning by default
+		// if it's missing for some reason, set early morning
 		args.getU64("time_of_day") : 5250);
 
 	m_last_clear_objects_time = args.exists("last_clear_objects_time") ?
 		// If missing, do as if clearObjects was never called
 		args.getU64("last_clear_objects_time") : 0;
 
+	m_day_count = args.exists("day_count") ? args.getU32("day_count") : 0;
+
 	std::string lbm_introduction_times;
 	try {
-		u64 ver = args.getU64("lbm_introduction_times_version");
+		u32 ver = args.getU32("lbm_introduction_times_version");
 		if (ver == 1) {
 			lbm_introduction_times = args.get("lbm_introduction_times");
 		} else {
-			infostream << "ServerEnvironment::loadMeta(): Non-supported"
+			warningstream << "ServerEnvironment::loadMeta(): Unsupported"
 				<< " introduction time version " << ver << std::endl;
 		}
 	} catch (SettingNotFoundException &e) {
 		// No problem, this is expected. Just continue with an empty string
 	}
 	m_lbm_mgr.loadIntroductionTimes(lbm_introduction_times, m_server, m_game_time);
-
-	m_day_count = args.exists("day_count") ? args.getU32("day_count") : 0;
 }
 
 /**
@@ -536,6 +533,8 @@ void ServerEnvironment::loadMeta()
  */
 void ServerEnvironment::loadDefaultMeta()
 {
+	infostream << "ServerEnvironment: Using default environment metadata"
+		<< std::endl;
 	m_lbm_mgr.loadIntroductionTimes("", m_server, m_game_time);
 }
 
@@ -1694,13 +1693,14 @@ void ServerEnvironment::deactivateFarObjects(const bool _force_delete)
 		if (!force_delete && still_active)
 			return false;
 
-		verbosestream << "ServerEnvironment::deactivateFarObjects(): "
-					  << "deactivating object id=" << id << " on inactive block "
-					  << blockpos_o << std::endl;
-
 		// If known by some client, don't immediately delete.
 		bool pending_delete = (obj->m_known_by_count > 0 && !force_delete);
 
+		verbosestream << "ServerEnvironment::deactivateFarObjects(): "
+					  << "deactivating object id=" << id << " on inactive block "
+					  << blockpos_o << (pending_delete ? " (pending)" : "")
+					  << std::endl;
+
 		/*
 			Update the static data
 		*/
@@ -1759,17 +1759,9 @@ void ServerEnvironment::deactivateFarObjects(const bool _force_delete)
 		// This ensures that LuaEntity on_deactivate is always called.
 		obj->markForDeactivation();
 
-		/*
-			If known by some client, set pending deactivation.
-			Otherwise delete it immediately.
-		*/
-		if (pending_delete && !force_delete) {
-			verbosestream << "ServerEnvironment::deactivateFarObjects(): "
-						  << "object id=" << id << " is known by clients"
-						  << "; not deleting yet" << std::endl;
-
+		// If known by some client, don't delete yet.
+		if (pending_delete && !force_delete)
 			return false;
-		}
 
 		processActiveObjectRemove(obj);