From 3494475df108e3401c6c8463a0aeae0f227fd1fa Mon Sep 17 00:00:00 2001 From: sfan5 Date: Wed, 8 Apr 2020 20:12:58 +0200 Subject: Miscellaneous networking improvements (#9611) fixes #2862 --- src/network/connectionthreads.cpp | 41 ++++++++++++++++++++++++++------------- 1 file changed, 28 insertions(+), 13 deletions(-) (limited to 'src/network/connectionthreads.cpp') diff --git a/src/network/connectionthreads.cpp b/src/network/connectionthreads.cpp index f8b58c025..48a4f51ab 100644 --- a/src/network/connectionthreads.cpp +++ b/src/network/connectionthreads.cpp @@ -73,6 +73,7 @@ ConnectionSendThread::ConnectionSendThread(unsigned int max_packet_size, m_timeout(timeout), m_max_data_packets_per_iteration(g_settings->getU16("max_packets_per_iteration")) { + SANITY_CHECK(m_max_data_packets_per_iteration > 1); } void *ConnectionSendThread::run() @@ -107,8 +108,13 @@ void *ConnectionSendThread::run() curtime = porting::getTimeMs(); float dtime = CALC_DTIME(lasttime, curtime); - /* first do all the reliable stuff */ + /* first resend timed-out packets */ runTimeouts(dtime); + if (m_iteration_packets_avaialble == 0) { + LOG(warningstream << m_connection->getDesc() + << " Packet quota used up after re-sending packets, " + << "max=" << m_max_data_packets_per_iteration << std::endl); + } /* translate commands to packets */ ConnectionCommand c = m_connection->m_command_queue.pop_frontNoEx(0); @@ -121,7 +127,7 @@ void *ConnectionSendThread::run() c = m_connection->m_command_queue.pop_frontNoEx(0); } - /* send non reliable packets */ + /* send queued packets */ sendPackets(dtime); END_DEBUG_EXCEPTION_HANDLER @@ -644,6 +650,9 @@ void ConnectionSendThread::sendPackets(float dtime) std::list pendingDisconnect; std::map pending_unreliable; + const unsigned int peer_packet_quota = m_iteration_packets_avaialble + / MYMAX(peerIds.size(), 1); + for (session_t peerId : peerIds) { PeerHelper peer = m_connection->getPeerNoEx(peerId); //peer may have been removed @@ -653,8 +662,7 @@ void ConnectionSendThread::sendPackets(float dtime) << std::endl); continue; } - peer->m_increment_packets_remaining = - m_iteration_packets_avaialble / m_connection->m_peers.size(); + peer->m_increment_packets_remaining = peer_packet_quota; UDPPeer *udpPeer = dynamic_cast(&peer); @@ -751,23 +759,30 @@ void ConnectionSendThread::sendPackets(float dtime) } /* send acks immediately */ - if (packet.ack) { + if (packet.ack || peer->m_increment_packets_remaining > 0 || stopRequested()) { rawSendAsPacket(packet.peer_id, packet.channelnum, packet.data, packet.reliable); - peer->m_increment_packets_remaining = - MYMIN(0, peer->m_increment_packets_remaining--); - } else if ( - (peer->m_increment_packets_remaining > 0) || - (stopRequested())) { - rawSendAsPacket(packet.peer_id, packet.channelnum, - packet.data, packet.reliable); - peer->m_increment_packets_remaining--; + if (peer->m_increment_packets_remaining > 0) + peer->m_increment_packets_remaining--; } else { m_outgoing_queue.push(packet); pending_unreliable[packet.peer_id] = true; } } + if (peer_packet_quota > 0) { + for (session_t peerId : peerIds) { + PeerHelper peer = m_connection->getPeerNoEx(peerId); + if (!peer) + continue; + if (peer->m_increment_packets_remaining == 0) { + LOG(warningstream << m_connection->getDesc() + << " Packet quota used up for peer_id=" << peerId + << ", was " << peer_packet_quota << " pkts" << std::endl); + } + } + } + for (session_t peerId : pendingDisconnect) { if (!pending_unreliable[peerId]) { m_connection->deletePeer(peerId, false); -- cgit v1.2.3 From de73f989eb1397b1103236031fd91309b294583c Mon Sep 17 00:00:00 2001 From: sfan5 Date: Wed, 8 Apr 2020 20:13:23 +0200 Subject: 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(-) (limited to 'src/network/connectionthreads.cpp') 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 -- cgit v1.2.3 From 8ef239b448c52485cf94d334c1d8b1c6de37d976 Mon Sep 17 00:00:00 2001 From: sfan5 Date: Mon, 20 Apr 2020 23:22:00 +0200 Subject: Improve protocol-level receiving code (#9617) --- src/network/connection.cpp | 4 +- src/network/connectionthreads.cpp | 250 +++++++++++++++++++------------------- src/network/connectionthreads.h | 2 +- 3 files changed, 126 insertions(+), 130 deletions(-) (limited to 'src/network/connectionthreads.cpp') diff --git a/src/network/connection.cpp b/src/network/connection.cpp index 15eda7725..3692e45a9 100644 --- a/src/network/connection.cpp +++ b/src/network/connection.cpp @@ -1173,7 +1173,9 @@ Connection::Connection(u32 protocol_id, u32 max_packet_size, float timeout, m_bc_peerhandler(peerhandler) { - m_udpSocket.setTimeoutMs(5); + /* Amount of time Receive() will wait for data, this is entirely different + * from the connection timeout */ + m_udpSocket.setTimeoutMs(500); m_sendThread->setParent(this); m_receiveThread->setParent(this); diff --git a/src/network/connectionthreads.cpp b/src/network/connectionthreads.cpp index 13d82e06d..1f33d2ded 100644 --- a/src/network/connectionthreads.cpp +++ b/src/network/connectionthreads.cpp @@ -812,6 +812,14 @@ void *ConnectionReceiveThread::run() ThreadIdentifier); PROFILE(ThreadIdentifier << "ConnectionReceive: [" << m_connection->getDesc() << "]"); + // use IPv6 minimum allowed MTU as receive buffer size as this is + // theoretical reliable upper boundary of a udp packet for all IPv6 enabled + // infrastructure + const unsigned int packet_maxsize = 1500; + SharedBuffer packetdata(packet_maxsize); + + bool packet_queued = true; + #ifdef DEBUG_CONNECTION_KBPS u64 curtime = porting::getTimeMs(); u64 lasttime = curtime; @@ -830,7 +838,7 @@ void *ConnectionReceiveThread::run() #endif /* receive packets */ - receive(); + receive(packetdata, packet_queued); #ifdef DEBUG_CONNECTION_KBPS debug_print_timer += dtime; @@ -892,157 +900,142 @@ void *ConnectionReceiveThread::run() } // Receive packets from the network and buffers and create ConnectionEvents -void ConnectionReceiveThread::receive() +void ConnectionReceiveThread::receive(SharedBuffer &packetdata, + bool &packet_queued) { - // use IPv6 minimum allowed MTU as receive buffer size as this is - // theoretical reliable upper boundary of a udp packet for all IPv6 enabled - // infrastructure - unsigned int packet_maxsize = 1500; - SharedBuffer packetdata(packet_maxsize); - - bool packet_queued = true; - - unsigned int loop_count = 0; - - /* first of all read packets from socket */ - /* check for incoming data available */ - while ((loop_count < 10) && - (m_connection->m_udpSocket.WaitData(50))) { - loop_count++; - try { - if (packet_queued) { - bool data_left = true; - session_t peer_id; - SharedBuffer resultdata; - while (data_left) { - try { - data_left = getFromBuffers(peer_id, resultdata); - if (data_left) { - ConnectionEvent e; - e.dataReceived(peer_id, resultdata); - m_connection->putEvent(e); - } - } - catch (ProcessedSilentlyException &e) { - /* try reading again */ + try { + // First, see if there any buffered packets we can process now + if (packet_queued) { + bool data_left = true; + session_t peer_id; + SharedBuffer resultdata; + while (data_left) { + try { + data_left = getFromBuffers(peer_id, resultdata); + if (data_left) { + ConnectionEvent e; + e.dataReceived(peer_id, resultdata); + m_connection->putEvent(e); } } - packet_queued = false; - } - - Address sender; - s32 received_size = m_connection->m_udpSocket.Receive(sender, *packetdata, - packet_maxsize); - - if ((received_size < BASE_HEADER_SIZE) || - (readU32(&packetdata[0]) != m_connection->GetProtocolID())) { - LOG(derr_con << m_connection->getDesc() - << "Receive(): Invalid incoming packet, " - << "size: " << received_size - << ", protocol: " - << ((received_size >= 4) ? readU32(&packetdata[0]) : -1) - << std::endl); - continue; + catch (ProcessedSilentlyException &e) { + /* try reading again */ + } } + packet_queued = false; + } - session_t peer_id = readPeerId(*packetdata); - u8 channelnum = readChannel(*packetdata); + // Call Receive() to wait for incoming data + Address sender; + s32 received_size = m_connection->m_udpSocket.Receive(sender, + *packetdata, packetdata.getSize()); + if (received_size < 0) + return; - if (channelnum > CHANNEL_COUNT - 1) { - LOG(derr_con << m_connection->getDesc() - << "Receive(): Invalid channel " << (u32)channelnum << std::endl); - throw InvalidIncomingDataException("Channel doesn't exist"); - } + if ((received_size < BASE_HEADER_SIZE) || + (readU32(&packetdata[0]) != m_connection->GetProtocolID())) { + LOG(derr_con << m_connection->getDesc() + << "Receive(): Invalid incoming packet, " + << "size: " << received_size + << ", protocol: " + << ((received_size >= 4) ? readU32(&packetdata[0]) : -1) + << std::endl); + return; + } - /* Try to identify peer by sender address (may happen on join) */ - if (peer_id == PEER_ID_INEXISTENT) { - peer_id = m_connection->lookupPeer(sender); - // We do not have to remind the peer of its - // peer id as the CONTROLTYPE_SET_PEER_ID - // command was sent reliably. - } + session_t peer_id = readPeerId(*packetdata); + u8 channelnum = readChannel(*packetdata); - /* The peer was not found in our lists. Add it. */ - if (peer_id == PEER_ID_INEXISTENT) { - peer_id = m_connection->createPeer(sender, MTP_MINETEST_RELIABLE_UDP, 0); - } + if (channelnum > CHANNEL_COUNT - 1) { + LOG(derr_con << m_connection->getDesc() + << "Receive(): Invalid channel " << (u32)channelnum << std::endl); + return; + } - PeerHelper peer = m_connection->getPeerNoEx(peer_id); + /* Try to identify peer by sender address (may happen on join) */ + if (peer_id == PEER_ID_INEXISTENT) { + peer_id = m_connection->lookupPeer(sender); + // We do not have to remind the peer of its + // peer id as the CONTROLTYPE_SET_PEER_ID + // command was sent reliably. + } - if (!peer) { - LOG(dout_con << m_connection->getDesc() - << " got packet from unknown peer_id: " - << peer_id << " Ignoring." << std::endl); - continue; - } + /* The peer was not found in our lists. Add it. */ + if (peer_id == PEER_ID_INEXISTENT) { + peer_id = m_connection->createPeer(sender, MTP_MINETEST_RELIABLE_UDP, 0); + } - // Validate peer address + PeerHelper peer = m_connection->getPeerNoEx(peer_id); + if (!peer) { + LOG(dout_con << m_connection->getDesc() + << " got packet from unknown peer_id: " + << peer_id << " Ignoring." << std::endl); + return; + } - Address peer_address; + // Validate peer address - if (peer->getAddress(MTP_UDP, peer_address)) { - if (peer_address != sender) { - LOG(derr_con << m_connection->getDesc() - << m_connection->getDesc() - << " Peer " << peer_id << " sending from different address." - " Ignoring." << std::endl); - continue; - } - } else { - - bool invalid_address = true; - if (invalid_address) { - LOG(derr_con << m_connection->getDesc() - << m_connection->getDesc() - << " Peer " << peer_id << " unknown." - " Ignoring." << std::endl); - continue; - } + Address peer_address; + if (peer->getAddress(MTP_UDP, peer_address)) { + if (peer_address != sender) { + LOG(derr_con << m_connection->getDesc() + << " Peer " << peer_id << " sending from different address." + " Ignoring." << std::endl); + return; } + } else { + LOG(derr_con << m_connection->getDesc() + << " Peer " << peer_id << " doesn't have an address?!" + " Ignoring." << std::endl); + return; + } - peer->ResetTimeout(); - - Channel *channel = 0; + peer->ResetTimeout(); - if (dynamic_cast(&peer) != 0) { - channel = &(dynamic_cast(&peer)->channels[channelnum]); - } + Channel *channel = nullptr; + if (dynamic_cast(&peer)) { + channel = &dynamic_cast(&peer)->channels[channelnum]; + } else { + LOG(derr_con << m_connection->getDesc() + << "Receive(): peer_id=" << peer_id << " isn't an UDPPeer?!" + " Ignoring." << std::endl); + return; + } - if (channel != 0) { - channel->UpdateBytesReceived(received_size); - } + channel->UpdateBytesReceived(received_size); - // Throw the received packet to channel->processPacket() + // Throw the received packet to channel->processPacket() - // Make a new SharedBuffer from the data without the base headers - SharedBuffer strippeddata(received_size - BASE_HEADER_SIZE); - memcpy(*strippeddata, &packetdata[BASE_HEADER_SIZE], - strippeddata.getSize()); + // Make a new SharedBuffer from the data without the base headers + SharedBuffer strippeddata(received_size - BASE_HEADER_SIZE); + memcpy(*strippeddata, &packetdata[BASE_HEADER_SIZE], + strippeddata.getSize()); - try { - // Process it (the result is some data with no headers made by us) - SharedBuffer resultdata = processPacket - (channel, strippeddata, peer_id, channelnum, false); + try { + // Process it (the result is some data with no headers made by us) + SharedBuffer resultdata = processPacket + (channel, strippeddata, peer_id, channelnum, false); - LOG(dout_con << m_connection->getDesc() - << " ProcessPacket from peer_id: " << peer_id - << ", channel: " << (u32)channelnum << ", returned " - << resultdata.getSize() << " bytes" << std::endl); + LOG(dout_con << m_connection->getDesc() + << " ProcessPacket from peer_id: " << peer_id + << ", channel: " << (u32)channelnum << ", returned " + << resultdata.getSize() << " bytes" << std::endl); - ConnectionEvent e; - e.dataReceived(peer_id, resultdata); - m_connection->putEvent(e); - } - catch (ProcessedSilentlyException &e) { - } - catch (ProcessedQueued &e) { - packet_queued = true; - } - } - catch (InvalidIncomingDataException &e) { + ConnectionEvent e; + e.dataReceived(peer_id, resultdata); + m_connection->putEvent(e); } catch (ProcessedSilentlyException &e) { } + catch (ProcessedQueued &e) { + // we set it to true anyway (see below) + } + + /* Every time we receive a packet it can happen that a previously + * buffered packet is now ready to process. */ + packet_queued = true; + } + catch (InvalidIncomingDataException &e) { } } @@ -1189,7 +1182,8 @@ SharedBuffer ConnectionReceiveThread::handlePacketType_Control(Channel *chan m_connection->TriggerSend(); } catch (NotFoundException &e) { LOG(derr_con << m_connection->getDesc() - << "WARNING: ACKed packet not in outgoing queue" << std::endl); + << "WARNING: ACKed packet not in outgoing queue" + << " seqnum=" << seqnum << std::endl); channel->UpdatePacketTooLateCounter(); } diff --git a/src/network/connectionthreads.h b/src/network/connectionthreads.h index da4ea92f5..612407c3b 100644 --- a/src/network/connectionthreads.h +++ b/src/network/connectionthreads.h @@ -101,7 +101,7 @@ public: } private: - void receive(); + void receive(SharedBuffer &packetdata, bool &packet_queued); // Returns next data from a buffer if possible // If found, returns true; if not, false. -- cgit v1.2.3 From d76785b4c70d834783d2e578086680941257cfa1 Mon Sep 17 00:00:00 2001 From: sfan5 Date: Thu, 14 May 2020 21:18:26 +0200 Subject: network: Replace a fatal_error with just error logging --- src/network/connectionthreads.cpp | 8 +++----- 1 file changed, 3 insertions(+), 5 deletions(-) (limited to 'src/network/connectionthreads.cpp') diff --git a/src/network/connectionthreads.cpp b/src/network/connectionthreads.cpp index 1f33d2ded..9a6617a1c 100644 --- a/src/network/connectionthreads.cpp +++ b/src/network/connectionthreads.cpp @@ -336,11 +336,9 @@ bool ConnectionSendThread::rawSendAsPacket(session_t peer_id, u8 channelnum, { PeerHelper peer = m_connection->getPeerNoEx(peer_id); if (!peer) { - LOG(dout_con << m_connection->getDesc() - << " INFO: dropped packet for non existent peer_id: " - << peer_id << std::endl); - FATAL_ERROR_IF(!reliable, - "Trying to send raw packet reliable but no peer found!"); + LOG(errorstream << m_connection->getDesc() + << " dropped " << (reliable ? "reliable " : "") + << "packet for non existent peer_id: " << peer_id << std::endl); return false; } Channel *channel = &(dynamic_cast(&peer)->channels[channelnum]); -- cgit v1.2.3