From de73f989eb1397b1103236031fd91309b294583c Mon Sep 17 00:00:00 2001 From: sfan5 Date: Wed, 8 Apr 2020 20:13:23 +0200 Subject: [PATCH] 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 | 40 ++++++++++++++++++++--------- src/client/client.h | 19 +++----------- src/client/content_cao.cpp | 6 ++--- src/client/fontengine.cpp | 2 +- src/client/game.cpp | 3 +-- src/client/renderingengine.cpp | 20 ++------------- src/client/sound_openal.cpp | 16 +++++++----- src/client/tile.cpp | 9 ++++--- src/content/subgames.cpp | 2 +- src/content_sao.cpp | 12 ++++----- src/craftdef.cpp | 4 +-- src/emerge.cpp | 1 - src/itemdef.cpp | 6 ++--- src/main.cpp | 8 +----- src/map.cpp | 8 +++--- src/network/clientpackethandler.cpp | 8 +++--- src/network/connectionthreads.cpp | 3 +-- src/nodedef.cpp | 2 +- src/script/cpp_api/s_env.cpp | 2 +- src/script/lua_api/l_item.cpp | 1 - src/server.cpp | 17 ++++++------ src/server/mods.cpp | 9 +++---- 22 files changed, 87 insertions(+), 111 deletions(-) diff --git a/src/client/client.cpp b/src/client/client.cpp index e15391dde..c9cd24cb3 100644 --- a/src/client/client.cpp +++ b/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 - << "):"<getFloat("server_map_save_interval"); + int n = 0; for (std::unordered_map::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 \""<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; } diff --git a/src/client/client.h b/src/client/client.h index 1291b944c..eea78d456 100644 --- a/src/client/client.h +++ b/src/client/client.h @@ -82,30 +82,19 @@ public: void add(u16 command) { - std::map::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 diff --git a/src/client/content_cao.cpp b/src/client/content_cao.cpp index d148df522..8509eccb5 100644 --- a/src/client/content_cao.cpp +++ b/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(); diff --git a/src/client/fontengine.cpp b/src/client/fontengine.cpp index 2b5841cd8..61d52cc2f 100644 --- a/src/client/fontengine.cpp +++ b/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; } /******************************************************************************/ diff --git a/src/client/game.cpp b/src/client/game.cpp index 0201ded69..437cc7871 100644 --- a/src/client/game.cpp +++ b/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); diff --git a/src/client/renderingengine.cpp b/src/client/renderingengine.cpp index 6e6509eeb..8b7bbf328 100644 --- a/src/client/renderingengine.cpp +++ b/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(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(&x11_win), 1); - - verbosestream << "Client: Finished configuring Xorg specific top level" - << " window properties" - << std::endl; #endif } diff --git a/src/client/sound_openal.cpp b/src/client/sound_openal.cpp index 8e696f302..d0f935a7a 100644 --- a/src/client/sound_openal.cpp +++ b/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(): " - < 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) diff --git a/src/client/tile.cpp b/src/client/tile.cpp index 3189ab28c..0fa7a4ae2 100644 --- a/src/client/tile.cpp +++ b/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 dim = img->getDimension(); - infostream<<"Size "< pos_base(x, y); video::IImage *img2 = driver->createImage(video::ECF_A8R8G8B8, dim); diff --git a/src/content/subgames.cpp b/src/content/subgames.cpp index bf947cf85..170f54e20 100644 --- a/src/content/subgames.cpp +++ b/src/content/subgames.cpp @@ -253,7 +253,7 @@ std::vector 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 dirvector = fs::GetDirListing(worldspath); for (const fs::DirListNode &dln : dirvector) { if (!dln.dir) diff --git a/src/content_sao.cpp b/src/content_sao.cpp index 75c3eaf37..680bf372a 100644 --- a/src/content_sao.cpp +++ b/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) diff --git a/src/craftdef.cpp b/src/craftdef.cpp index 0181ceb60..210605198 100644 --- a/src/craftdef.cpp +++ b/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; diff --git a/src/emerge.cpp b/src/emerge.cpp index fc1da4ee7..4835c3fad 100644 --- a/src/emerge.cpp +++ b/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)) diff --git a/src/itemdef.cpp b/src/itemdef.cpp index 0d0afeb2b..ba7bd6a0b 100644 --- a/src/itemdef.cpp +++ b/src/itemdef.cpp @@ -463,7 +463,7 @@ public: } virtual void registerItem(const ItemDefinition &def) { - verbosestream<<"ItemDefManager: registering \""< "< " << convert_to << std::endl); m_aliases[name] = convert_to; } } diff --git a/src/main.cpp b/src/main.cpp index 1993f7c24..8df2fe7d3 100644 --- a/src/main.cpp +++ b/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 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)) { diff --git a/src/map.cpp b/src/map.cpp index 40aba067e..eb69955ee 100644 --- a/src/map.cpp +++ b/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: " - <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); } diff --git a/src/nodedef.cpp b/src/nodedef.cpp index 977a4533d..b6eca9497 100644 --- a/src/nodedef.cpp +++ b/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(); diff --git a/src/script/cpp_api/s_env.cpp b/src/script/cpp_api/s_env.cpp index ab3b5fe46..8da5debaa 100644 --- a/src/script/cpp_api/s_env.cpp +++ b/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); /* diff --git a/src/script/lua_api/l_item.cpp b/src/script/lua_api/l_item.cpp index 0c174feca..ff77cba32 100644 --- a/src/script/lua_api/l_item.cpp +++ b/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(L, -1); - verbosestream<<"register_item_raw: "<getFloat("server_map_save_interval"); + int n = 0; for (std::unordered_map::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; diff --git a/src/server/mods.cpp b/src/server/mods.cpp index c5616dcd6..c8d8a28e2 100644 --- a/src/server/mods.cpp +++ b/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::steady_clock::now() - t).count() * 0.001f - << " seconds" << std::endl; + << (porting::getTimeMs() - t) << " ms" << std::endl; } // Run a callback when mods are loaded -- 2.25.1