Teaspeak-Server/server/src/TS3ServerHeartbeat.cpp

#include <cstring>
#include <protocol/buffers.h>
#include "client/voice/VoiceClient.h"
#include <log/LogUtils.h>
#include "InstanceHandler.h"
#include "VirtualServer.h"
#include "./manager/ConversationManager.h"
#include "./music/MusicBotManager.h"

using namespace std;
using namespace std::chrono;
using namespace ts::server;
using namespace ts::protocol;
using namespace ts::buffer;

inline void banClientFlood(VirtualServer* server, const shared_ptr<ConnectedClient>& cl, time_point<system_clock> until){
    auto time = until.time_since_epoch().count() == 0 ? 0L : chrono::ceil<chrono::seconds>(until - system_clock::now()).count();

    std::string reason = "You're flooding too much";
    serverInstance->banManager()->registerBan(server->getServerId(), cl->getClientDatabaseId(), reason, cl->getUid(), cl->getLoggingPeerIp(), "", "", until);

    for(const auto &client :  server->findClientsByUid(cl->getUid())) {
        server->notify_client_ban(client, server->getServerRoot(), reason, time);
        client->close_connection(system_clock::now() + seconds(1));
    }
}

#define BEGIN_TIMINGS() timing_begin = system_clock::now()
#define END_TIMINGS(variable) \
timing_end = system_clock::now(); \
variable = duration_cast<decltype(variable)>(timing_end - timing_begin);

void VirtualServer::executeServerTick() {
    threads::MutexTryLock l(this->stateLock); //Should not attempt to shutdown or start the server while ticking
    if(!l) {
        if(this->running())
            logError(this->getServerId(), "Failed to lock tick mutex!");
        return;
    }
    if(!this->running()) return;

    try {
        if(lastTick.time_since_epoch().count() != 0) {
            auto delay = system_clock::now() - lastTick;
            auto delay_ms = duration_cast<milliseconds>(delay).count();
            if(delay_ms > 510) {
                if(delay_ms < 750) {
                    logWarning(this->getServerId(),
                            "Found varianzes within the server tick! (Supposed: 500ms Hold: {}ms)", delay_ms);
                } else {
                    logError(this->getServerId(),
                            "Found varianzes within the server tick! This long delay could be an issue. (Supposed: 500ms Hold: {}ms)", delay_ms);
                }
            }
        }
        lastTick = system_clock::now();

        system_clock::time_point timing_begin, timing_end;
        milliseconds timing_update_states, timing_client_tick, timing_channel, timing_statistic, timing_groups, timing_ccache, music_manager;

        auto client_list = this->getClients();

        {
            BEGIN_TIMINGS();

            size_t clientOnline = 0;
            size_t queryOnline = 0;
            for(const auto& conn : client_list){
                switch (conn->getType()){
                    case ClientType::CLIENT_TEAMSPEAK:
                    case ClientType::CLIENT_TEASPEAK:
                    case ClientType::CLIENT_WEB:
                        clientOnline++;
                        break;
                    case ClientType::CLIENT_QUERY:
                    case ClientType::CLIENT_MUSIC:
                        queryOnline++;
                        break;
                    default:
                        break;
                }
            }

            properties()[property::VIRTUALSERVER_UPTIME] = std::chrono::duration_cast<std::chrono::seconds>(std::chrono::system_clock::now() - this->startTimestamp).count();
            properties()[property::VIRTUALSERVER_CLIENTS_ONLINE] = clientOnline + queryOnline;
            properties()[property::VIRTUALSERVER_QUERYCLIENTS_ONLINE] = queryOnline;
            if(clientOnline + queryOnline == 0) //We don't need to tick, when server is empty!
                return;
            properties()[property::VIRTUALSERVER_CHANNELS_ONLINE] = this->channelTree->channel_count();
            properties()[property::VIRTUALSERVER_TOTAL_PING] = this->generate_network_report().average_ping;
            END_TIMINGS(timing_update_states);
        }
        
        {
            BEGIN_TIMINGS();

            auto flood_decrease = this->properties()[property::VIRTUALSERVER_ANTIFLOOD_POINTS_TICK_REDUCE].as<FloodPoints>();
            auto flood_block = this->properties()[property::VIRTUALSERVER_ANTIFLOOD_POINTS_NEEDED_IP_BLOCK].as<FloodPoints>();

            bool flag_update_spoken = this->spoken_time_timestamp + seconds(30) < system_clock::now();

            system_clock::time_point tick_client_begin, tick_client_end = system_clock::now();
            for(const auto& cl : client_list) {
                tick_client_begin = tick_client_end;
                if(cl->server != this) {
                    logError(this->getServerId(), "Got registered client, but client does not think hes bound to this server!");

                    {
                        lock_guard lock(this->clients.lock);
                        for(auto& client : this->clients.clients) {
                            if(client != cl) continue;

                            client.reset();
                            this->clients.count--;
                            break;
                        }
                    }
                    continue; //Fully ha?
                }
                if(cl->floodPoints > flood_block){
                    if(!cl->ignoresFlood()) {
                        banClientFlood(this, cl, system_clock::now() + minutes(10));
                        continue;
                    }
                }
                if(cl->floodPoints > flood_decrease)
                    cl->floodPoints -= flood_decrease;
                else cl->floodPoints = 0;
                cl->tick(tick_client_end);
                auto voice = dynamic_pointer_cast<SpeakingClient>(cl);
                if(flag_update_spoken && voice)
                    this->spoken_time += voice->takeSpokenTime();
                tick_client_end = system_clock::now();

                auto passed_time = tick_client_end - tick_client_begin;
                if(passed_time > microseconds(2500)) {
                    if(passed_time > milliseconds(10)) {
                        logError(this->serverId, "Ticking of client {:1} ({:2}) needs more that 2500 microseconds! ({:3} microseconds)",
                                 cl->getLoggingPeerIp() + ":" + to_string(cl->getPeerPort()),
                                 cl->getDisplayName(),
                                 duration_cast<microseconds>(tick_client_end - tick_client_begin).count()
                        );
                    } else {
                        logWarning(this->serverId, "Ticking of client {:1} ({:2}) needs more that 2500 microseconds! ({:3} microseconds)",
                                 cl->getLoggingPeerIp() + ":" + to_string(cl->getPeerPort()),
                                 cl->getDisplayName(),
                                 duration_cast<microseconds>(tick_client_end - tick_client_begin).count()
                        );
                    }
                }

                if(cl->clientPermissions->require_db_updates()) {
                    auto begin = system_clock::now();
                    serverInstance->databaseHelper()->saveClientPermissions(this->ref(), cl->getClientDatabaseId(), cl->clientPermissions);
                    auto end = system_clock::now();
                    debugMessage(this->serverId, "Saved client permissions for client {} ({}) in {}ms", cl->getClientDatabaseId(), cl->getDisplayName(), duration_cast<milliseconds>(end - begin).count());
                }
            }
            if(flag_update_spoken)
                this->spoken_time_timestamp = system_clock::now();

            END_TIMINGS(timing_client_tick);
        }


        {
            BEGIN_TIMINGS();

            unique_lock channel_lock(this->channel_tree_lock);
            auto channels = this->channelTree->channels();
            channel_lock.unlock();

            for(const auto& channel : this->channelTree->channels()){
                if(channel->channelType() == ChannelType::temporary) {
                    auto server_channel = dynamic_pointer_cast<ServerChannel>(channel);
                    assert(server_channel);
                    if(server_channel->client_count() > 0 || !this->getClientsByChannelRoot(channel, true).empty())
                        continue;

                    seconds deleteTimeout(0);
                    if(channel->properties().hasProperty(property::CHANNEL_DELETE_DELAY))
                        deleteTimeout = seconds(channel->properties()[property::CHANNEL_DELETE_DELAY].as<uint64_t>());

                    auto last_left = time_point<system_clock>() + milliseconds(channel->properties()[property::CHANNEL_LAST_LEFT].as<int64_t>());
                    auto channel_created = channel->createdTimestamp();

                    if(system_clock::now() - last_left < deleteTimeout) continue; //One second stay
                    if(system_clock::now() - channel_created < deleteTimeout + seconds(1)) continue; //One second stay

                    this->delete_channel(server_channel, this->serverRoot, "temporary autodelete", channel_lock);
                    if(channel_lock.owns_lock())
                        channel_lock.unlock();
                }
                {
                    auto permission_manager = channel->permissions();
                    if(permission_manager->require_db_updates()) {
                        auto begin = system_clock::now();
                        serverInstance->databaseHelper()->saveChannelPermissions(this->ref(), channel->channelId(), permission_manager);
                        auto end = system_clock::now();
                        debugMessage(this->serverId, "Saved channel permissions for channel {} ({}) in {}ms", channel->channelId(), channel->name(), duration_cast<milliseconds>(end - begin).count());
                    }
                }
            }

            END_TIMINGS(timing_channel);
        }

        {
            BEGIN_TIMINGS();

            this->serverStatistics->tick();

            if(fileStatisticsTimestamp + seconds(5) < system_clock::now()) {
                fileStatisticsTimestamp = system_clock::now();
                auto update = this->serverStatistics->mark_file_bytes();
                if(update.first > 0) {
                    this->properties()[property::VIRTUALSERVER_MONTH_BYTES_DOWNLOADED] += update.first;
                    this->properties()[property::VIRTUALSERVER_TOTAL_BYTES_DOWNLOADED] += update.first;
                }
                if(update.second > 0) {
                    this->properties()[property::VIRTUALSERVER_MONTH_BYTES_UPLOADED] += update.second;
                    this->properties()[property::VIRTUALSERVER_TOTAL_BYTES_UPLOADED] += update.second;
                }
            }

            {
                lock_guard<threads::Mutex> lock(this->join_attempts_lock);
                if(system_clock::now() > this->join_last_decrease + seconds(5)) {
                    for(auto& elm : this->join_attempts)
                        if(elm.second > 0) elm.second--;

                    auto copy = this->join_attempts;
                    for(const auto& elm : copy)
                        if(elm.second == 0){
                            auto found = find(this->join_attempts.begin(), this->join_attempts.end(), elm);
                            if(found != this->join_attempts.end()) this->join_attempts.erase(found);
                        }
                    this->join_last_decrease = system_clock::now();
                }
            }
            END_TIMINGS(timing_statistic);
        }

        {
            BEGIN_TIMINGS();

            auto groups = this->getGroupManager()->availableGroups(false);
            for(auto& group : groups) {
                auto permissions = group->permissions();
                if(permissions->require_db_updates()) {
                    auto begin = system_clock::now();
                    serverInstance->databaseHelper()->saveGroupPermissions(this->ref(), group->groupId(), permissions);
                    auto end = system_clock::now();
                    debugMessage(this->serverId, "Saved group permissions for group {} ({}) in {}ms", group->groupId(), group->name(), duration_cast<milliseconds>(end - begin).count());
                }
            }

            END_TIMINGS(timing_groups);
        }

        {
            BEGIN_TIMINGS();
            if(this->conversation_cache_cleanup_timestamp + minutes(15) < system_clock::now()) {
                debugMessage(this->serverId, "Cleaning up conversation cache.");
                this->_conversation_manager->cleanup_cache();
                conversation_cache_cleanup_timestamp = system_clock::now();
            }
            END_TIMINGS(timing_ccache);
        }

        {
            BEGIN_TIMINGS();
            this->musicManager->execute_tick();
            END_TIMINGS(music_manager);
        }

        if(system_clock::now() - lastTick > milliseconds(100)) {
            //milliseconds timing_update_states, timing_client_tick, timing_channel, timing_statistic;
            logError(this->serverId, "Server tick tooks to long ({}ms => Status updates: {}ms Client tick: {}ms, Channel tick: {}ms, Statistic tick: {}ms, Groups: {}ms, Conversation cache: {}ms)",
                    duration_cast<milliseconds>(system_clock::now() - lastTick).count(),
                     timing_update_states.count(),
                     timing_client_tick.count(),
                     timing_channel.count(),
                     timing_statistic.count(),
                     timing_groups.count(),
                     timing_ccache.count()
            );
        }
    } catch (std::exception& ex) {
        logCritical(this->serverId, "Failed to tick server! Got exception message: {}", ex.what());
    }
}