Overall improvements to log messages (#9598)

Hide some unnecessarily verbose ones behind --trace or disable them entirely.
Remove duplicate ones. Improve their contents in some places.

src/client/client.cpp

@@ -60,6 +60,20 @@ with this program; if not, write to the Free Software Foundation, Inc.,
 
 extern gui::IGUIEnvironment* guienv;
 
+/*
+	Utility classes
+*/
+
+void PacketCounter::print(std::ostream &o) const
+{
+	for (const auto &it : m_packets) {
+		auto name = it.first >= TOCLIENT_NUM_MSG_TYPES ? "?"
+			: toClientCommandTable[it.first].name;
+		o << "cmd " << it.first << " (" << name << ") count "
+			<< it.second << std::endl;
+	}
+}
+
 /*
 	Client
 */
@@ -336,12 +350,12 @@ void Client::step(float dtime)
 	{
 		float &counter = m_packetcounter_timer;
 		counter -= dtime;
-		if(counter <= 0.0)
+		if(counter <= 0.0f)
 		{
-			counter = 20.0;
+			counter = 30.0f;
 
 			infostream << "Client packetcounter (" << m_packetcounter_timer
-					<< "):"<<std::endl;
+					<< "s):"<<std::endl;
 			m_packetcounter.print(infostream);
 			m_packetcounter.clear();
 		}
@@ -621,14 +635,17 @@ void Client::step(float dtime)
 
 	m_mod_storage_save_timer -= dtime;
 	if (m_mod_storage_save_timer <= 0.0f) {
-		verbosestream << "Saving registered mod storages." << std::endl;
 		m_mod_storage_save_timer = g_settings->getFloat("server_map_save_interval");
+		int n = 0;
 		for (std::unordered_map<std::string, ModMetadata *>::const_iterator
 				it = m_mod_storages.begin(); it != m_mod_storages.end(); ++it) {
 			if (it->second->isModified()) {
 				it->second->save(getModStoragePath());
+				n++;
 			}
 		}
+		if (n > 0)
+			infostream << "Saved " << n << " modified mod storages." << std::endl;
 	}
 
 	// Write server map
@@ -653,8 +670,8 @@ bool Client::loadMedia(const std::string &data, const std::string &filename)
 	};
 	name = removeStringEnd(filename, image_ext);
 	if (!name.empty()) {
-		verbosestream<<"Client: Attempting to load image "
-		<<"file \""<<filename<<"\""<<std::endl;
+		TRACESTREAM(<< "Client: Attempting to load image "
+			<< "file \"" << filename << "\"" << std::endl);
 
 		io::IFileSystem *irrfs = RenderingEngine::get_filesystem();
 		video::IVideoDriver *vdrv = RenderingEngine::get_video_driver();
@@ -687,10 +704,9 @@ bool Client::loadMedia(const std::string &data, const std::string &filename)
 	};
 	name = removeStringEnd(filename, sound_ext);
 	if (!name.empty()) {
-		verbosestream<<"Client: Attempting to load sound "
-		<<"file \""<<filename<<"\""<<std::endl;
-		m_sound->loadSoundData(name, data);
-		return true;
+		TRACESTREAM(<< "Client: Attempting to load sound "
+			<< "file \"" << filename << "\"" << std::endl);
+		return m_sound->loadSoundData(name, data);
 	}
 
 	const char *model_ext[] = {
@@ -714,8 +730,8 @@ bool Client::loadMedia(const std::string &data, const std::string &filename)
 	};
 	name = removeStringEnd(filename, translate_ext);
 	if (!name.empty()) {
-		verbosestream << "Client: Loading translation: "
-				<< "\"" << filename << "\"" << std::endl;
+		TRACESTREAM(<< "Client: Loading translation: "
+				<< "\"" << filename << "\"" << std::endl);
 		g_translations->loadTranslation(data);
 		return true;
 	}

src/client/client.h

@@ -82,30 +82,19 @@ public:
 
 	void add(u16 command)
 	{
-		std::map<u16, u16>::iterator n = m_packets.find(command);
-		if(n == m_packets.end())
-		{
+		auto n = m_packets.find(command);
+		if (n == m_packets.end())
 			m_packets[command] = 1;
-		}
 		else
-		{
 			n->second++;
 	}
-	}
 
 	void clear()
 	{
-		for (auto &m_packet : m_packets) {
-			m_packet.second = 0;
-		}
+		m_packets.clear();
 	}
 
-	void print(std::ostream &o)
-	{
-		for (const auto &m_packet : m_packets) {
-			o << "cmd "<< m_packet.first <<" count "<< m_packet.second << std::endl;
-		}
-	}
+	void print(std::ostream &o) const;
 
 private:
 	// command, count

src/client/content_cao.cpp

@@ -576,9 +576,10 @@ void GenericCAO::addToScene(ITextureSource *tsrc)
 
 	m_visuals_expired = false;
 
-	if (!m_prop.is_visible) {
+	if (!m_prop.is_visible)
 		return;
-	}
+
+	infostream << "GenericCAO::addToScene(): " << m_prop.visual << std::endl;
 
 	if (m_enable_shaders) {
 		IShaderSource *shader_source = m_client->getShaderSource();
@@ -593,7 +594,6 @@ void GenericCAO::addToScene(ITextureSource *tsrc)
 	}
 
 	auto grabMatrixNode = [this] {
-		infostream << "GenericCAO::addToScene(): " << m_prop.visual << std::endl;
 		m_matrixnode = RenderingEngine::get_scene_manager()->
 				addDummyTransformationSceneNode();
 		m_matrixnode->grab();

src/client/fontengine.cpp

@@ -239,7 +239,7 @@ void FontEngine::updateSkin()
 	FATAL_ERROR_IF(font == NULL, "Could not create/get font");
 
 	u32 text_height = font->getDimension(L"Hello, world!").Height;
-	infostream << "text_height=" << text_height << std::endl;
+	infostream << "FontEngine: measured text_height=" << text_height << std::endl;
 }
 
 /******************************************************************************/

src/client/game.cpp

@@ -2010,7 +2010,6 @@ void Game::processItemSelection(u16 *new_playeritem)
 	for (u16 i = 0; i <= max_item; i++) {
 		if (wasKeyDown((GameKeyType) (KeyType::SLOT_1 + i))) {
 			*new_playeritem = i;
-			infostream << "Selected item: " << new_playeritem << std::endl;
 			break;
 		}
 	}
@@ -2039,7 +2038,7 @@ void Game::openInventory()
 	if (!player || !player->getCAO())
 		return;
 
-	infostream << "the_game: " << "Launching inventory" << std::endl;
+	infostream << "Game: Launching inventory" << std::endl;
 
 	PlayerInventoryFormSource *fs_src = new PlayerInventoryFormSource(client);
 

src/client/renderingengine.cpp

@@ -226,27 +226,17 @@ bool RenderingEngine::setupTopLevelWindow(const std::string &name)
 {
 	// FIXME: It would make more sense for there to be a switch of some
 	// sort here that would call the correct toplevel setup methods for
-	// the environment Minetest is running in but for now not deviating
-	// from the original pattern.
+	// the environment Minetest is running in.
 
 	/* Setting Xorg properties for the top level window */
 	setupTopLevelXorgWindow(name);
-	/* Done with Xorg properties */
 
 	/* Setting general properties for the top level window */
 	verbosestream << "Client: Configuring general top level"
 		<< " window properties"
 		<< std::endl;
-
 	bool result = setWindowIcon();
 
-	verbosestream << "Client: Finished configuring general top level"
-		<< " window properties"
-		<< std::endl;
-	/* Done with general properties */
-
-	// FIXME: setWindowIcon returns a bool result but it is unused.
-	// For now continue to return this result.
 	return result;
 }
 
@@ -262,7 +252,7 @@ void RenderingEngine::setupTopLevelXorgWindow(const std::string &name)
 		return;
 	}
 
-	verbosestream << "Client: Configuring Xorg specific top level"
+	verbosestream << "Client: Configuring X11-specific top level"
 		<< " window properties"
 		<< std::endl;
 
@@ -309,8 +299,6 @@ void RenderingEngine::setupTopLevelXorgWindow(const std::string &name)
 	Atom NET_WM_PID = XInternAtom(x11_dpl, "_NET_WM_PID", false);
 
 	pid_t pid = getpid();
-	infostream << "Client: PID is '" << static_cast<long>(pid) << "'"
-		<< std::endl;
 
 	XChangeProperty(x11_dpl, x11_win, NET_WM_PID,
 			XA_CARDINAL, 32, PropModeReplace,
@@ -327,10 +315,6 @@ void RenderingEngine::setupTopLevelXorgWindow(const std::string &name)
 	XChangeProperty (x11_dpl, x11_win, WM_CLIENT_LEADER,
 		XA_WINDOW, 32, PropModeReplace,
 		reinterpret_cast<unsigned char *>(&x11_win), 1);
-
-	verbosestream << "Client: Finished configuring Xorg specific top level"
-		<< " window properties"
-		<< std::endl;
 #endif
 }
 

src/client/sound_openal.cpp

@@ -165,8 +165,8 @@ SoundBuffer *load_opened_ogg_file(OggVorbis_File *oggFile,
 				<< "preparing sound buffer" << std::endl;
 	}
 
-	infostream << "Audio file "
-		<< filename_for_logging << " loaded" << std::endl;
+	//infostream << "Audio file "
+	//	<< filename_for_logging << " loaded" << std::endl;
 
 	// Clean up!
 	ov_clear(oggFile);
@@ -498,9 +498,11 @@ public:
 	// Remove stopped sounds
 	void maintain()
 	{
-		verbosestream<<"OpenALSoundManager::maintain(): "
-				<<m_sounds_playing.size()<<" playing sounds, "
-				<<m_buffers.size()<<" sound names loaded"<<std::endl;
+		if (!m_sounds_playing.empty()) {
+			verbosestream << "OpenALSoundManager::maintain(): "
+					<< m_sounds_playing.size() <<" playing sounds, "
+					<< m_buffers.size() <<" sound names loaded"<<std::endl;
+		}
 		std::unordered_set<int> del_list;
 		for (const auto &sp : m_sounds_playing) {
 			int id = sp.first;
@@ -530,7 +532,7 @@ public:
 		SoundBuffer *buf = load_ogg_from_file(filepath);
 		if (buf)
 			addBuffer(name, buf);
-		return false;
+		return !!buf;
 	}
 
 	bool loadSoundData(const std::string &name,
@@ -539,7 +541,7 @@ public:
 		SoundBuffer *buf = load_ogg_from_buffer(filedata, name);
 		if (buf)
 			addBuffer(name, buf);
-		return false;
+		return !!buf;
 	}
 
 	void updateListener(const v3f &pos, const v3f &vel, const v3f &at, const v3f &up)

src/client/tile.cpp

@@ -471,8 +471,8 @@ TextureSource::~TextureSource()
 		driver->removeTexture(t);
 	}
 
-	infostream << "~TextureSource() "<< textures_before << "/"
-			<< driver->getTextureCount() << std::endl;
+	infostream << "~TextureSource() before cleanup: "<< textures_before
+			<< " after: " << driver->getTextureCount() << std::endl;
 }
 
 u32 TextureSource::getTextureId(const std::string &name)
@@ -763,6 +763,9 @@ void TextureSource::rebuildImagesAndTextures()
 	video::IVideoDriver *driver = RenderingEngine::get_video_driver();
 	sanity_check(driver);
 
+	infostream << "TextureSource: recreating " << m_textureinfo_cache.size()
+		<< " textures" << std::endl;
+
 	// Recreate textures
 	for (TextureInfo &ti : m_textureinfo_cache) {
 		video::IImage *img = generateImage(ti.name);
@@ -1270,8 +1273,6 @@ bool TextureSource::generateImagePart(std::string part_of_name,
 				video::IImage *img = generateImage(filename);
 				if (img) {
 					core::dimension2d<u32> dim = img->getDimension();
-					infostream<<"Size "<<dim.Width
-							<<"x"<<dim.Height<<std::endl;
 					core::position2d<s32> pos_base(x, y);
 					video::IImage *img2 =
 							driver->createImage(video::ECF_A8R8G8B8, dim);

src/content/subgames.cpp

@@ -253,7 +253,7 @@ std::vector<WorldSpec> getAvailableWorlds()
 	worldspaths.insert(porting::path_user + DIR_DELIM + "worlds");
 	infostream << "Searching worlds..." << std::endl;
 	for (const std::string &worldspath : worldspaths) {
-		infostream << "  In " << worldspath << ": " << std::endl;
+		infostream << "  In " << worldspath << ": ";
 		std::vector<fs::DirListNode> dirvector = fs::GetDirListing(worldspath);
 		for (const fs::DirListNode &dln : dirvector) {
 			if (!dln.dir)

src/content_sao.cpp

@@ -711,13 +711,11 @@ float LuaEntitySAO::getMinimumSavedMovement()
 
 std::string LuaEntitySAO::getDescription()
 {
-	std::ostringstream os(std::ios::binary);
-	os<<"LuaEntitySAO at (";
-	os<<(m_base_position.X/BS)<<",";
-	os<<(m_base_position.Y/BS)<<",";
-	os<<(m_base_position.Z/BS);
-	os<<")";
-	return os.str();
+	std::ostringstream oss;
+	oss << "LuaEntitySAO \"" << m_init_name << "\" ";
+	auto pos = floatToInt(m_base_position, BS);
+	oss << "at " << PP(pos);
+	return oss.str();
 }
 
 void LuaEntitySAO::setHP(s32 hp, const PlayerHPChangeReason &reason)

src/craftdef.cpp

@@ -1066,8 +1066,8 @@ public:
 	}
 	virtual void registerCraft(CraftDefinition *def, IGameDef *gamedef)
 	{
-		verbosestream << "registerCraft: registering craft definition: "
-				<< def->dump() << std::endl;
+		TRACESTREAM(<< "registerCraft: registering craft definition: "
+				<< def->dump() << std::endl);
 		m_craft_defs[(int) CRAFT_HASH_TYPE_UNHASHED][0].push_back(def);
 
 		CraftInput input;

src/emerge.cpp

@@ -136,7 +136,6 @@ EmergeManager::EmergeManager(Server *server)
 		nthreads = Thread::getNumberOfProcessors() - 2;
 	if (nthreads < 1)
 		nthreads = 1;
-	verbosestream << "Using " << nthreads << " emerge threads." << std::endl;
 
 	m_qlimit_total = g_settings->getU16("emergequeue_limit_total");
 	if (!g_settings->getU16NoEx("emergequeue_limit_diskonly", m_qlimit_diskonly))

src/itemdef.cpp

@@ -463,7 +463,7 @@ public:
 	}
 	virtual void registerItem(const ItemDefinition &def)
 	{
-		verbosestream<<"ItemDefManager: registering \""<<def.name<<"\""<<std::endl;
+		TRACESTREAM(<< "ItemDefManager: registering " << def.name << std::endl);
 		// Ensure that the "" item (the hand) always has ToolCapabilities
 		if (def.name.empty())
 			FATAL_ERROR_IF(!def.tool_capabilities, "Hand does not have ToolCapabilities");
@@ -490,8 +490,8 @@ public:
 			const std::string &convert_to)
 	{
 		if (m_item_definitions.find(name) == m_item_definitions.end()) {
-			verbosestream<<"ItemDefManager: setting alias "<<name
-				<<" -> "<<convert_to<<std::endl;
+			TRACESTREAM(<< "ItemDefManager: setting alias " << name
+				<< " -> " << convert_to << std::endl);
 			m_aliases[name] = convert_to;
 		}
 	}

src/main.cpp

@@ -207,9 +207,6 @@ int main(int argc, char *argv[])
 
 	sanity_check(!game_params.world_path.empty());
 
-	infostream << "Using commanded world path ["
-	           << game_params.world_path << "]" << std::endl;
-
 	if (game_params.is_dedicated_server)
 		return run_dedicated_server(game_params, cmd_args) ? 0 : 1;
 
@@ -686,8 +683,6 @@ static bool auto_select_world(GameParams *game_params)
 	// No world was specified; try to select it automatically
 	// Get information about available worlds
 
-	verbosestream << _("Determining world path") << std::endl;
-
 	std::vector<WorldSpec> worldspecs = getAvailableWorlds();
 	std::string world_path;
 
@@ -708,7 +703,7 @@ static bool auto_select_world(GameParams *game_params)
 		// This is the ultimate default world path
 		world_path = porting::path_user + DIR_DELIM + "worlds" +
 				DIR_DELIM + "world";
-		infostream << "Creating default world at ["
+		infostream << "Using default world at ["
 		           << world_path << "]" << std::endl;
 	}
 
@@ -770,7 +765,6 @@ static bool determine_subgame(GameParams *game_params)
 
 	assert(game_params->world_path != "");	// Pre-condition
 
-	verbosestream << _("Determining gameid/gamespec") << std::endl;
 	// If world doesn't exist
 	if (!game_params->world_path.empty()
 		&& !getWorldExists(game_params->world_path)) {

src/map.cpp

@@ -1827,10 +1827,10 @@ void ServerMap::save(ModifiedState save_level)
 	*/
 	if(save_level == MOD_STATE_CLEAN
 			|| block_count != 0) {
-		infostream<<"ServerMap: Written: "
-				<<block_count<<" block files"
-				<<", "<<block_count_all<<" blocks in memory."
-				<<std::endl;
+		infostream << "ServerMap: Written: "
+				<< block_count << " blocks"
+				<< ", " << block_count_all << " blocks in memory."
+				<< std::endl;
 		PrintInfo(infostream); // ServerMap/ClientMap:
 		infostream<<"Blocks modified by: "<<std::endl;
 		modprofiler.print(infostream);

src/network/clientpackethandler.cpp

@@ -386,10 +386,10 @@ void Client::handleCommand_TimeOfDay(NetworkPacket* pkt)
 	m_env.setTimeOfDaySpeed(time_speed);
 	m_time_of_day_set = true;
 
-	u32 dr = m_env.getDayNightRatio();
-	infostream << "Client: time_of_day=" << time_of_day
-			<< " time_speed=" << time_speed
-			<< " dr=" << dr << std::endl;
+	//u32 dr = m_env.getDayNightRatio();
+	//infostream << "Client: time_of_day=" << time_of_day
+	//		<< " time_speed=" << time_speed
+	//		<< " dr=" << dr << std::endl;
 }
 
 void Client::handleCommand_ChatMessage(NetworkPacket *pkt)

src/network/connectionthreads.cpp

@@ -199,7 +199,6 @@ void ConnectionSendThread::runTimeouts(float dtime)
 			infostream << m_connection->getDesc()
 				<< "RunTimeouts(): Peer " << peer->id
 				<< " has timed out."
-				<< " (source=peer->timeout_counter)"
 				<< std::endl;
 			// Add peer to the list
 			timeouted_peers.push_back(peer->id);
@@ -292,7 +291,7 @@ void ConnectionSendThread::runTimeouts(float dtime)
 
 	// Remove timed out peers
 	for (u16 timeouted_peer : timeouted_peers) {
-		LOG(derr_con << m_connection->getDesc()
+		LOG(dout_con << m_connection->getDesc()
 			<< "RunTimeouts(): Removing peer " << timeouted_peer << std::endl);
 		m_connection->deletePeer(timeouted_peer, true);
 	}

src/nodedef.cpp

@@ -1458,7 +1458,7 @@ void NodeDefManager::deSerialize(std::istream &is)
 			m_content_features.resize((u32)(i) + 1);
 		m_content_features[i] = f;
 		addNameIdMapping(i, f.name);
-		verbosestream << "deserialized " << f.name << std::endl;
+		TRACESTREAM(<< "NodeDef: deserialized " << f.name << std::endl);
 
 		getNodeBoxUnion(f.selection_box, f, &m_selection_box_union);
 		fixSelectionBoxIntUnion();

src/script/cpp_api/s_env.cpp

@@ -86,7 +86,7 @@ void ScriptApiEnv::player_event(ServerActiveObject *player, const std::string &t
 void ScriptApiEnv::initializeEnvironment(ServerEnvironment *env)
 {
 	SCRIPTAPI_PRECHECKHEADER
-	verbosestream << "scriptapi_add_environment" << std::endl;
+	verbosestream << "ScriptApiEnv: Environment initialized" << std::endl;
 	setEnv(env);
 
 	/*

src/script/lua_api/l_item.cpp

@@ -522,7 +522,6 @@ int ModApiItemMod::l_register_item_raw(lua_State *L)
 	lua_getfield(L, table, "name");
 	if(lua_isstring(L, -1)){
 		name = readParam<std::string>(L, -1);
-		verbosestream<<"register_item_raw: "<<name<<std::endl;
 	} else {
 		throw LuaError("register_item_raw: name is not defined or not a string");
 	}

src/server.cpp

@@ -656,14 +656,17 @@ void Server::AsyncRunStep(bool initial_step)
 		// Save mod storages if modified
 		m_mod_storage_save_timer -= dtime;
 		if (m_mod_storage_save_timer <= 0.0f) {
-			infostream << "Saving registered mod storages." << std::endl;
 			m_mod_storage_save_timer = g_settings->getFloat("server_map_save_interval");
+			int n = 0;
 			for (std::unordered_map<std::string, ModMetadata *>::const_iterator
 				it = m_mod_storages.begin(); it != m_mod_storages.end(); ++it) {
 				if (it->second->isModified()) {
 					it->second->save(getModStoragePath());
+					n++;
 				}
 			}
+			if (n > 0)
+				infostream << "Saved " << n << " modified mod storages." << std::endl;
 		}
 	}
 
@@ -809,7 +812,6 @@ void Server::AsyncRunStep(bool initial_step)
 						disable_single_change_sending ? 5 : 30);
 				break;
 			case MEET_BLOCK_NODE_METADATA_CHANGED: {
-				verbosestream << "Server: MEET_BLOCK_NODE_METADATA_CHANGED" << std::endl;
 				prof.add("MEET_BLOCK_NODE_METADATA_CHANGED", 1);
 				if (!event->is_private_change) {
 					// Don't send the change yet. Collect them to eliminate dupes.
@@ -825,7 +827,6 @@ void Server::AsyncRunStep(bool initial_step)
 				break;
 			}
 			case MEET_OTHER:
-				infostream << "Server: MEET_OTHER" << std::endl;
 				prof.add("MEET_OTHER", 1);
 				for (const v3s16 &modified_block : event->modified_blocks) {
 					m_clients.markBlockposAsNotSent(modified_block);
@@ -2535,9 +2536,6 @@ void Server::fillMediaCache()
 
 void Server::sendMediaAnnouncement(session_t peer_id, const std::string &lang_code)
 {
-	verbosestream << "Server: Announcing files to id(" << peer_id << ")"
-		<< std::endl;
-
 	// Make packet
 	NetworkPacket pkt(TOCLIENT_ANNOUNCE_MEDIA, 0, peer_id);
 
@@ -2560,6 +2558,9 @@ void Server::sendMediaAnnouncement(session_t peer_id, const std::string &lang_co
 
 	pkt << g_settings->get("remote_media");
 	Send(&pkt);
+
+	verbosestream << "Server: Announcing files to id(" << peer_id
+		<< "): count=" << media_sent << " size=" << pkt.getSize() << std::endl;
 }
 
 struct SendableMedia
@@ -2938,10 +2939,8 @@ void Server::UpdateCrafting(RemotePlayer *player)
 	if (!clist || clist->getSize() == 0)
 		return;
 
-	if (!clist->checkModified()) {
-		verbosestream << "Skip Server::UpdateCrafting(): list unmodified" << std::endl;
+	if (!clist->checkModified())
 		return;
-	}
 
 	// Get a preview for crafting
 	ItemStack preview;

src/server/mods.cpp

@@ -22,6 +22,7 @@ with this program; if not, write to the Free Software Foundation, Inc.,
 #include "log.h"
 #include "scripting_server.h"
 #include "content/subgames.h"
+#include "porting.h"
 
 /**
  * Manage server mods
@@ -66,14 +67,10 @@ void ServerModManager::loadMods(ServerScripting *script)
 					"Only characters [a-z0-9_] are allowed.");
 		}
 		std::string script_path = mod.path + DIR_DELIM + "init.lua";
-		infostream << "  [" << padStringRight(mod.name, 12) << "] [\""
-			<< script_path << "\"]" << std::endl;
-		auto t = std::chrono::steady_clock::now();
+		auto t = porting::getTimeMs();
 		script->loadMod(script_path, mod.name);
 		infostream << "Mod \"" << mod.name << "\" loaded after "
-			<< std::chrono::duration_cast<std::chrono::milliseconds>(
-				std::chrono::steady_clock::now() - t).count() * 0.001f
-			<< " seconds" << std::endl;
+			<< (porting::getTimeMs() - t) << " ms" << std::endl;
 	}
 
 	// Run a callback when mods are loaded