diff --git a/CMakeLists.txt b/CMakeLists.txt index c175e8d3..d8a30b09 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -59,6 +59,7 @@ add_executable(newserv src/LevelTable.cc src/License.cc src/Lobby.cc + src/Loggers.cc src/Main.cc src/Map.cc src/Menu.cc diff --git a/src/Channel.cc b/src/Channel.cc index 583f212a..25c98bef 100644 --- a/src/Channel.cc +++ b/src/Channel.cc @@ -10,6 +10,7 @@ #include #include +#include "Loggers.hh" #include "Version.hh" using namespace std; @@ -133,7 +134,8 @@ void Channel::disconnect() { auto on_error = +[](struct bufferevent* bev, short events, void*) -> void { if (events & BEV_EVENT_ERROR) { int err = EVUTIL_SOCKET_ERROR(); - log(WARNING, "Disconnecting channel caused error %d (%s)", err, + channel_exceptions_log.warning( + "Disconnecting channel caused error %d (%s)", err, evutil_socket_error_to_string(err)); } if (events & (BEV_EVENT_EOF | BEV_EVENT_ERROR)) { @@ -215,7 +217,7 @@ Channel::Message Channel::recv(bool print_contents) { if (!this->name.empty()) { name_token = " from " + this->name; } - log(INFO, "Received%s (version=%s command=%04hX flag=%08X)", + command_data_log.info("Received%s (version=%s command=%04hX flag=%08X)", name_token.c_str(), name_for_version(this->version), header.command(this->version), @@ -241,7 +243,7 @@ Channel::Message Channel::recv(bool print_contents) { void Channel::send(uint16_t cmd, uint32_t flag, const void* data, size_t size, bool print_contents) { if (!this->connected()) { - log(WARNING, "Attempted to send command on closed channel; dropping data"); + channel_exceptions_log.warning("Attempted to send command on closed channel; dropping data"); } string send_data; @@ -325,7 +327,7 @@ void Channel::send(uint16_t cmd, uint32_t flag, const void* data, size_t size, if (use_terminal_colors && this->terminal_send_color != TerminalFormat::NORMAL) { print_color_escape(stderr, TerminalFormat::FG_YELLOW, TerminalFormat::BOLD, TerminalFormat::END); } - log(INFO, "Sending%s (version=%s command=%04hX flag=%08X)", + command_data_log.info("Sending%s (version=%s command=%04hX flag=%08X)", name_token.c_str(), name_for_version(version), cmd, flag); print_data(stderr, send_data.data(), logical_size, 0, nullptr, PrintDataFlags::PRINT_ASCII | PrintDataFlags::DISABLE_COLOR); if (use_terminal_colors && this->terminal_send_color != TerminalFormat::NORMAL) { @@ -373,7 +375,7 @@ void Channel::dispatch_on_input(struct bufferevent*, void* ctx) { } catch (const out_of_range&) { break; } catch (const exception& e) { - log(WARNING, "Error receiving on channel: %s", e.what()); + channel_exceptions_log.warning("Error receiving on channel: %s", e.what()); ch->on_error(*ch, BEV_EVENT_ERROR); break; } diff --git a/src/ChatCommands.cc b/src/ChatCommands.cc index 7812d9b3..b99ee2d3 100644 --- a/src/ChatCommands.cc +++ b/src/ChatCommands.cc @@ -8,6 +8,7 @@ #include #include +#include "Loggers.hh" #include "Server.hh" #include "ProxyServer.hh" #include "Lobby.hh" @@ -166,7 +167,7 @@ static void server_command_ax(shared_ptr, shared_ptr, shared_ptr c, const std::u16string& args) { check_privileges(c, Privilege::ANNOUNCE); string message = encode_sjis(args); - log(INFO, "[Client message from %010u] %s\n", c->license->serial_number, message.c_str()); + ax_messages_log.info("%s", message.c_str()); } static void server_command_announce(shared_ptr s, shared_ptr, diff --git a/src/Client.cc b/src/Client.cc index d0222173..8cd9fcc0 100644 --- a/src/Client.cc +++ b/src/Client.cc @@ -9,6 +9,7 @@ #include #include +#include "Loggers.hh" #include "Version.hh" using namespace std; @@ -23,7 +24,8 @@ Client::Client( struct bufferevent* bev, GameVersion version, ServerBehavior server_behavior) - : version(version), + : log("", client_log.min_level), + version(version), bb_game_state(0), flags(flags_for_version(this->version, 0)), channel(bev, this->version, nullptr, nullptr, this, "", TerminalFormat::FG_YELLOW, TerminalFormat::FG_GREEN), diff --git a/src/Client.hh b/src/Client.hh index a62afd7c..4c70642b 100644 --- a/src/Client.hh +++ b/src/Client.hh @@ -57,6 +57,8 @@ struct Client { DEFAULT_V4_BB = NO_MESSAGE_BOX_CLOSE_CONFIRMATION_AFTER_LOBBY_JOIN | NO_MESSAGE_BOX_CLOSE_CONFIRMATION | SAVE_ENABLED, }; + PrefixedLogger log; + // License & account std::shared_ptr license; GameVersion version; diff --git a/src/DNSServer.cc b/src/DNSServer.cc index 11db5f37..25aacb57 100644 --- a/src/DNSServer.cc +++ b/src/DNSServer.cc @@ -12,6 +12,7 @@ #include #include +#include "Loggers.hh" #include "NetworkAddresses.hh" using namespace std; @@ -91,7 +92,7 @@ void DNSServer::on_receive_message(int fd, short) { if (bytes < 0) { if (errno != EAGAIN) { - log(INFO, "[DNSServer] input error %d", errno); + dns_server_log.error("input error %d", errno); throw runtime_error("cannot read from udp socket"); } break; @@ -100,7 +101,7 @@ void DNSServer::on_receive_message(int fd, short) { break; } else if (bytes < 0x0C) { - log(WARNING, "[DNSServer] input query too small"); + dns_server_log.warning("input query too small"); print_data(stderr, input.data(), bytes); } else { diff --git a/src/Episode3.cc b/src/Episode3.cc index d1d26754..ee2813dc 100644 --- a/src/Episode3.cc +++ b/src/Episode3.cc @@ -5,6 +5,7 @@ #include #include +#include "Loggers.hh" #include "Compression.hh" #include "Text.hh" @@ -722,7 +723,7 @@ Ep3DataIndex::Ep3DataIndex(const string& directory) { } } catch (const exception& e) { - log(WARNING, "Failed to load card text: %s", e.what()); + static_game_data_log.warning("Failed to load card text: %s", e.what()); } } @@ -768,9 +769,9 @@ Ep3DataIndex::Ep3DataIndex(const string& directory) { } } - log(INFO, "Indexed %zu Episode 3 card definitions", this->card_definitions.size()); + static_game_data_log.info("Indexed %zu Episode 3 card definitions", this->card_definitions.size()); } catch (const exception& e) { - log(WARNING, "Failed to load Episode 3 card update: %s", e.what()); + static_game_data_log.warning("Failed to load Episode 3 card update: %s", e.what()); } for (const auto& filename : list_directory(directory)) { @@ -788,12 +789,12 @@ Ep3DataIndex::Ep3DataIndex(const string& directory) { throw runtime_error("duplicate map number"); } string name = entry->map.name; - log(INFO, "Indexed Episode 3 map %s (%08" PRIX32 "; %s)", + static_game_data_log.info("Indexed Episode 3 map %s (%08" PRIX32 "; %s)", filename.c_str(), entry->map.map_number.load(), name.c_str()); } } catch (const exception& e) { - log(WARNING, "Failed to index Episode 3 map %s: %s", + static_game_data_log.warning("Failed to index Episode 3 map %s: %s", filename.c_str(), e.what()); } } @@ -883,7 +884,7 @@ const string& Ep3DataIndex::get_compressed_map_list() const { compressed_w.put_u32b(w.str().size()); compressed_w.write(prs_compress(w.str())); this->compressed_map_list = move(compressed_w.str()); - log(INFO, "Generated Episode 3 compressed map list (%zu -> %zu bytes)", + static_game_data_log.info("Generated Episode 3 compressed map list (%zu -> %zu bytes)", w.size(), this->compressed_map_list.size()); } return this->compressed_map_list; diff --git a/src/FunctionCompiler.cc b/src/FunctionCompiler.cc index 7abd9ac4..cf9ec722 100644 --- a/src/FunctionCompiler.cc +++ b/src/FunctionCompiler.cc @@ -10,6 +10,7 @@ #include #endif +#include "Loggers.hh" #include "CommandFormats.hh" using namespace std; @@ -133,7 +134,7 @@ shared_ptr compile_function_code( FunctionCodeIndex::FunctionCodeIndex(const string& directory) { if (!function_compiler_available()) { - log(INFO, "Function compiler is not available"); + function_compiler_log.info("Function compiler is not available"); return; } @@ -161,13 +162,13 @@ FunctionCodeIndex::FunctionCodeIndex(const string& directory) { this->name_to_patch_function.emplace(name, code); } if (code->index) { - log(INFO, "Compiled function %02X => %s", code->index, name.c_str()); + function_compiler_log.info("Compiled function %02X => %s", code->index, name.c_str()); } else { - log(INFO, "Compiled function %s", name.c_str()); + function_compiler_log.info("Compiled function %s", name.c_str()); } } catch (const exception& e) { - log(WARNING, "Failed to compile function %s: %s", name.c_str(), e.what()); + function_compiler_log.warning("Failed to compile function %s: %s", name.c_str(), e.what()); } } } @@ -187,11 +188,11 @@ vector FunctionCodeIndex::patch_menu() const { DOLFileIndex::DOLFileIndex(const string& directory) { if (!function_compiler_available()) { - log(INFO, "Function compiler is not available"); + function_compiler_log.info("Function compiler is not available"); return; } if (!isdir(directory)) { - log(INFO, "DOL file directory is missing"); + function_compiler_log.info("DOL file directory is missing"); return; } @@ -212,10 +213,10 @@ DOLFileIndex::DOLFileIndex(const string& directory) { this->name_to_file.emplace(dol->name, dol); this->item_id_to_file.emplace_back(dol); - log(INFO, "Loaded DOL file %s", filename.c_str()); + function_compiler_log.info("Loaded DOL file %s", filename.c_str()); } catch (const exception& e) { - log(WARNING, "Failed to load DOL file %s: %s", filename.c_str(), e.what()); + function_compiler_log.warning("Failed to load DOL file %s: %s", filename.c_str(), e.what()); } } } diff --git a/src/IPStackSimulator.cc b/src/IPStackSimulator.cc index 775a1050..f2f73434 100644 --- a/src/IPStackSimulator.cc +++ b/src/IPStackSimulator.cc @@ -19,6 +19,7 @@ #include #include +#include "Loggers.hh" #include "IPFrameInfo.hh" #include "DNSServer.hh" @@ -27,7 +28,6 @@ using namespace std; static const size_t DEFAULT_RESEND_PUSH_USECS = 200000; // 200ms -PrefixedLogger IPStackSimulator::log("[IPStackSimulator] "); @@ -161,8 +161,7 @@ void IPStackSimulator::dispatch_on_listen_accept( void IPStackSimulator::on_listen_accept(struct evconnlistener* listener, evutil_socket_t fd, struct sockaddr*, int) { int listen_fd = evconnlistener_get_fd(listener); - this->log(INFO, "Client fd %d connected via fd %d", - fd, listen_fd); + ip_stack_simulator_log.info("Client fd %d connected via fd %d", fd, listen_fd); struct bufferevent *bev = bufferevent_socket_new(this->base.get(), fd, BEV_OPT_CLOSE_ON_FREE | BEV_OPT_DEFER_CALLBACKS); @@ -182,7 +181,7 @@ void IPStackSimulator::dispatch_on_listen_error( void IPStackSimulator::on_listen_error(struct evconnlistener* listener) { int err = EVUTIL_SOCKET_ERROR(); - this->log(ERROR, "Failure on listening socket %d: %d (%s)", + ip_stack_simulator_log.error("Failure on listening socket %d: %d (%s)", evconnlistener_get_fd(listener), err, evutil_socket_error_to_string(err)); event_base_loopexit(this->base.get(), nullptr); } @@ -202,7 +201,7 @@ void IPStackSimulator::on_client_input(struct bufferevent* bev) { c = this->bev_to_client.at(bev); } catch (const out_of_range&) { size_t bytes = evbuffer_get_length(buf); - this->log(ERROR, "Ignoring data received from unregistered client (0x%zX bytes)", + ip_stack_simulator_log.warning("Ignoring data received from unregistered client (0x%zX bytes)", bytes); evbuffer_drain(buf, bytes); return; @@ -223,7 +222,7 @@ void IPStackSimulator::on_client_input(struct bufferevent* bev) { this->on_client_frame(c, frame); } catch (const exception& e) { if (this->state->ip_stack_debug) { - this->log(WARNING, "Failed to process client frame: %s", e.what()); + ip_stack_simulator_log.warning("Failed to process client frame: %s", e.what()); print_data(stderr, frame); } } @@ -238,13 +237,11 @@ void IPStackSimulator::on_client_error(struct bufferevent* bev, short events) { if (events & BEV_EVENT_ERROR) { int err = EVUTIL_SOCKET_ERROR(); - this->log(WARNING, "Client caused error %d (%s)", err, + ip_stack_simulator_log.warning("Client caused error %d (%s)", err, evutil_socket_error_to_string(err)); } if (events & (BEV_EVENT_EOF | BEV_EVENT_ERROR)) { - this->log(INFO, "Client fd %d disconnected", - bufferevent_getfd(bev)); - + ip_stack_simulator_log.info("Client fd %d disconnected", bufferevent_getfd(bev)); this->bev_to_client.erase(bev); } } @@ -255,7 +252,7 @@ void IPStackSimulator::on_client_frame( shared_ptr c, const string& frame) { if (this->state->ip_stack_debug) { fputc('\n', stderr); - this->log(INFO, "Client sent frame"); + ip_stack_simulator_log.info("Client sent frame"); print_data(stderr, frame); } this->log_frame(frame); @@ -263,7 +260,7 @@ void IPStackSimulator::on_client_frame( FrameInfo fi(frame); if (this->state->ip_stack_debug) { string fi_header = fi.header_str(); - this->log(INFO, "Frame header: %s", fi_header.c_str()); + ip_stack_simulator_log.info("Frame header: %s", fi_header.c_str()); } if (fi.arp) { @@ -372,7 +369,7 @@ void IPStackSimulator::on_client_arp_frame( evbuffer_add(out_buf, r_payload, sizeof(r_payload)); if (this->state->ip_stack_debug) { - this->log(INFO, "Sending ARP response"); + ip_stack_simulator_log.info("Sending ARP response"); } if (this->pcap_text_log_file) { @@ -434,7 +431,7 @@ void IPStackSimulator::on_client_udp_frame( if (this->state->ip_stack_debug) { string remote_str = this->str_for_ipv4_netloc(fi.ipv4->src_addr, fi.udp->src_port); - this->log(INFO, "Sending DNS response to %s", remote_str.c_str()); + ip_stack_simulator_log.info("Sending DNS response to %s", remote_str.c_str()); } uint16_t frame_size = sizeof(r_ether) + sizeof(r_ipv4) + sizeof(r_udp) + r_data.size(); @@ -481,7 +478,7 @@ uint64_t IPStackSimulator::tcp_conn_key_for_client_frame(const FrameInfo& fi) { void IPStackSimulator::on_client_tcp_frame( shared_ptr c, const FrameInfo& fi) { if (this->state->ip_stack_debug) { - this->log(INFO, "Client sent TCP frame (seq=%08" PRIX32 ", ack=%08" PRIX32 ")", + ip_stack_simulator_log.info("Client sent TCP frame (seq=%08" PRIX32 ", ack=%08" PRIX32 ")", fi.tcp->seq_num.load(), fi.tcp->ack_num.load()); } @@ -561,10 +558,10 @@ void IPStackSimulator::on_client_tcp_frame( conn_str = this->str_for_tcp_connection(c, conn); if (this->state->ip_stack_debug) { - this->log(INFO, "Client opened TCP connection %s (acked_server_seq=%08" PRIX32 ", next_client_seq=%08" PRIX32 ")", + ip_stack_simulator_log.info("Client opened TCP connection %s (acked_server_seq=%08" PRIX32 ", next_client_seq=%08" PRIX32 ")", conn_str.c_str(), conn.acked_server_seq, conn.next_client_seq); } else { - this->log(INFO, "Client opened TCP connection %s", + ip_stack_simulator_log.info("Client opened TCP connection %s", conn_str.c_str()); } @@ -577,7 +574,7 @@ void IPStackSimulator::on_client_tcp_frame( // they're correct conn_str = this->str_for_tcp_connection(c, conn); if (this->state->ip_stack_debug) { - this->log(INFO, "Client resent SYN for TCP connection %s", + ip_stack_simulator_log.info("Client resent SYN for TCP connection %s", conn_str.c_str()); } } @@ -585,7 +582,7 @@ void IPStackSimulator::on_client_tcp_frame( // Send a SYN+ACK (send_tcp_frame always adds the ACK flag) this->send_tcp_frame(c, conn, TCPHeader::Flag::SYN); if (this->state->ip_stack_debug) { - this->log(INFO, "Sent SYN+ACK on %s (acked_server_seq=%08" PRIX32 ", next_client_seq=%08" PRIX32 ")", + ip_stack_simulator_log.info("Sent SYN+ACK on %s (acked_server_seq=%08" PRIX32 ", next_client_seq=%08" PRIX32 ")", conn_str.c_str(), conn.acked_server_seq, conn.next_client_seq); } @@ -602,7 +599,7 @@ void IPStackSimulator::on_client_tcp_frame( if (fi.tcp->flags & TCPHeader::Flag::ACK) { if (this->state->ip_stack_debug) { - this->log(INFO, "Client sent ACK %08" PRIX32, fi.tcp->ack_num.load()); + ip_stack_simulator_log.info("Client sent ACK %08" PRIX32, fi.tcp->ack_num.load()); } if (conn->awaiting_first_ack) { if (fi.tcp->ack_num != conn->acked_server_seq + 1) { @@ -614,7 +611,7 @@ void IPStackSimulator::on_client_tcp_frame( } else { if (seq_num_greater(fi.tcp->ack_num, conn->acked_server_seq)) { if (this->state->ip_stack_debug) { - this->log(INFO, "Advancing acked_server_seq from %08" PRIX32, conn->acked_server_seq); + ip_stack_simulator_log.info("Advancing acked_server_seq from %08" PRIX32, conn->acked_server_seq); } uint32_t ack_delta = fi.tcp->ack_num - conn->acked_server_seq; size_t pending_bytes = evbuffer_get_length(conn->pending_data.get()); @@ -627,7 +624,7 @@ void IPStackSimulator::on_client_tcp_frame( conn->resend_push_usecs = DEFAULT_RESEND_PUSH_USECS; if (this->state->ip_stack_debug) { - this->log(INFO, "Removed %08" PRIX32 " bytes from pending buffer and advanced acked_server_seq to %08" PRIX32, + ip_stack_simulator_log.info("Removed %08" PRIX32 " bytes from pending buffer and advanced acked_server_seq to %08" PRIX32, ack_delta, conn->acked_server_seq); } @@ -648,7 +645,7 @@ void IPStackSimulator::on_client_tcp_frame( } string conn_str = this->str_for_tcp_connection(c, *conn); - this->log(INFO, "Client closed TCP connection %s", conn_str.c_str()); + ip_stack_simulator_log.info("Client closed TCP connection %s", conn_str.c_str()); // TODO: Are we supposed to send a response to an RST? Here we do, and the // client probably just ignores it anyway @@ -689,7 +686,7 @@ void IPStackSimulator::on_client_tcp_frame( // ignore it (but warn) and send an ACK later, and the client should // retransmit the lost data if (this->state->ip_stack_debug) { - this->log(WARNING, + ip_stack_simulator_log.warning( "Client sent out-of-order sequence number (expected %08" PRIX32 ", received %08" PRIX32 ", 0x%zX data bytes)", conn->next_client_seq, fi.tcp->seq_num.load(), fi.payload_size); } @@ -706,10 +703,10 @@ void IPStackSimulator::on_client_tcp_frame( if (this->state->ip_stack_debug) { if (payload_skip_bytes) { - this->log(INFO, "Client sent data on TCP connection %s, overlapping existing ack'ed data (0x%zX bytes ignored)", + ip_stack_simulator_log.info("Client sent data on TCP connection %s, overlapping existing ack'ed data (0x%zX bytes ignored)", conn_str.c_str(), payload_skip_bytes); } else { - this->log(INFO, "Client sent data on TCP connection %s", + ip_stack_simulator_log.info("Client sent data on TCP connection %s", conn_str.c_str()); } print_data(stderr, payload, payload_size); @@ -728,7 +725,7 @@ void IPStackSimulator::on_client_tcp_frame( // Send an ACK this->send_tcp_frame(c, *conn); if (this->state->ip_stack_debug) { - this->log(INFO, "Sent PSH ACK on %s (acked_server_seq=%08" PRIX32 ", next_client_seq=%08" PRIX32 ", bytes_received=0x%zX)", + ip_stack_simulator_log.info("Sent PSH ACK on %s (acked_server_seq=%08" PRIX32 ", next_client_seq=%08" PRIX32 ", bytes_received=0x%zX)", conn_str.c_str(), conn->acked_server_seq, conn->next_client_seq, conn->bytes_received); } } @@ -769,21 +766,21 @@ void IPStackSimulator::open_server_connection( string conn_str = this->str_for_tcp_connection(c, conn); if (port_config->behavior == ServerBehavior::PROXY_SERVER) { if (!this->state->proxy_server.get()) { - this->log(ERROR, "TCP connection %s is to non-running proxy server", + ip_stack_simulator_log.error("TCP connection %s is to non-running proxy server", conn_str.c_str()); flush_and_free_bufferevent(bevs[1]); } else { this->state->proxy_server->connect_client(bevs[1], conn.server_port); - this->log(INFO, "Connected TCP connection %s to proxy server", + ip_stack_simulator_log.info("Connected TCP connection %s to proxy server", conn_str.c_str()); } } else if (this->state->game_server.get()) { this->state->game_server->connect_client(bevs[1], c->ipv4_addr, conn.client_port, port_config->version, port_config->behavior); - this->log(INFO, "Connected TCP connection %s to game server", + ip_stack_simulator_log.info("Connected TCP connection %s to game server", conn_str.c_str()); } else { - this->log(ERROR, "No server available for TCP connection %s", + ip_stack_simulator_log.error("No server available for TCP connection %s", conn_str.c_str()); flush_and_free_bufferevent(bevs[1]); } @@ -799,7 +796,7 @@ void IPStackSimulator::send_pending_push_frame( size_t bytes_to_send = min(pending_bytes, conn.max_frame_size); if (this->state->ip_stack_debug) { - this->log(INFO, "Sending PSH frame with seq_num %08" PRIX32 ", 0x%zX/0x%zX data bytes", + ip_stack_simulator_log.info("Sending PSH frame with seq_num %08" PRIX32 ", 0x%zX/0x%zX data bytes", conn.acked_server_seq, bytes_to_send, pending_bytes); } @@ -887,7 +884,7 @@ void IPStackSimulator::dispatch_on_resend_push(evutil_socket_t, short, void* ctx auto* conn = reinterpret_cast(ctx); auto c = conn->client.lock(); if (!c.get()) { - IPStackSimulator::log(WARNING, "Resend push event triggered for deleted client; ignoring"); + ip_stack_simulator_log.warning("Resend push event triggered for deleted client; ignoring"); } else { c->sim->on_resend_push(c, *conn); } @@ -901,7 +898,7 @@ void IPStackSimulator::dispatch_on_server_input(struct bufferevent*, void* ctx) auto* conn = reinterpret_cast(ctx); auto c = conn->client.lock(); if (!c.get()) { - IPStackSimulator::log(WARNING, "Server input event triggered for deleted client; ignoring"); + ip_stack_simulator_log.warning("Server input event triggered for deleted client; ignoring"); } else { c->sim->on_server_input(c, *conn); } @@ -910,7 +907,7 @@ void IPStackSimulator::dispatch_on_server_input(struct bufferevent*, void* ctx) void IPStackSimulator::on_server_input(shared_ptr c, IPClient::TCPConnection& conn) { struct evbuffer* buf = bufferevent_get_input(conn.server_bev.get()); if (this->state->ip_stack_debug) { - this->log(INFO, "Server input event: 0x%zX bytes to read", + ip_stack_simulator_log.info("Server input event: 0x%zX bytes to read", evbuffer_get_length(buf)); } @@ -923,7 +920,7 @@ void IPStackSimulator::dispatch_on_server_error( auto* conn = reinterpret_cast(ctx); auto c = conn->client.lock(); if (!c.get()) { - IPStackSimulator::log(WARNING, "Server error event triggered for deleted client; ignoring"); + ip_stack_simulator_log.warning("Server error event triggered for deleted client; ignoring"); } else { c->sim->on_server_error(c, *conn, events); } @@ -933,7 +930,7 @@ void IPStackSimulator::on_server_error( shared_ptr c, IPClient::TCPConnection& conn, short events) { if (events & BEV_EVENT_ERROR) { int err = EVUTIL_SOCKET_ERROR(); - this->log(WARNING, "Received error %d from virtual connection (%s)", err, + ip_stack_simulator_log.warning("Received error %d from virtual connection (%s)", err, evutil_socket_error_to_string(err)); } if (events & (BEV_EVENT_EOF | BEV_EVENT_ERROR)) { @@ -945,7 +942,7 @@ void IPStackSimulator::on_server_error( // Delete the connection object (this also flushes and frees the server // virtual connection bufferevent) string conn_str = this->str_for_tcp_connection(c, conn); - this->log(INFO, "Server closed TCP connection %s", + ip_stack_simulator_log.info("Server closed TCP connection %s", conn_str.c_str()); c->tcp_connections.erase(this->tcp_conn_key_for_connection(conn)); } diff --git a/src/IPStackSimulator.hh b/src/IPStackSimulator.hh index 75d1c1ce..0c718c73 100644 --- a/src/IPStackSimulator.hh +++ b/src/IPStackSimulator.hh @@ -28,7 +28,6 @@ public: static uint32_t connect_address_for_remote_address(uint32_t remote_addr); private: - static PrefixedLogger log; std::shared_ptr base; std::shared_ptr state; diff --git a/src/License.cc b/src/License.cc index 6a548d9d..b210ce68 100644 --- a/src/License.cc +++ b/src/License.cc @@ -5,6 +5,7 @@ #include #include +#include "Loggers.hh" #include "License.hh" using namespace std; @@ -57,7 +58,7 @@ LicenseManager::LicenseManager(const string& filename) : filename(filename) { } } catch (const cannot_open_file&) { - log(WARNING, "File %s does not exist; no licenses are registered", + license_log.warning("File %s does not exist; no licenses are registered", this->filename.c_str()); } } diff --git a/src/Lobby.cc b/src/Lobby.cc index d90cab15..c9f1f30e 100644 --- a/src/Lobby.cc +++ b/src/Lobby.cc @@ -4,6 +4,7 @@ #include +#include "Loggers.hh" #include "SendCommands.hh" #include "Text.hh" diff --git a/src/Lobby.hh b/src/Lobby.hh index 580053b5..7dc391c6 100644 --- a/src/Lobby.hh +++ b/src/Lobby.hh @@ -33,6 +33,8 @@ struct Lobby { PERSISTENT = 0x00040000, }; + PrefixedLogger log; + uint32_t lobby_id; uint32_t min_level; @@ -75,7 +77,7 @@ struct Lobby { std::shared_ptr loading_quest; std::array, 12> clients; - Lobby(); + explicit Lobby(uint32_t id); inline bool is_game() const { return this->flags & Flag::GAME; diff --git a/src/Main.cc b/src/Main.cc index 8790a184..32eefe07 100644 --- a/src/Main.cc +++ b/src/Main.cc @@ -10,6 +10,7 @@ #include #include +#include "Loggers.hh" #include "NetworkAddresses.hh" #include "SendCommands.hh" #include "DNSServer.hh" @@ -87,11 +88,11 @@ void populate_state_from_config(shared_ptr s, try { s->local_address = s->all_addresses.at(local_address_str); string addr_str = string_for_address(s->local_address); - log(INFO, "Added local address: %s (%s)", addr_str.c_str(), + config_log.info("Added local address: %s (%s)", addr_str.c_str(), local_address_str.c_str()); } catch (const out_of_range&) { s->local_address = address_for_string(local_address_str.c_str()); - log(INFO, "Added local address: %s", local_address_str.c_str()); + config_log.info("Added local address: %s", local_address_str.c_str()); } s->all_addresses.emplace("", s->local_address); @@ -99,11 +100,11 @@ void populate_state_from_config(shared_ptr s, try { s->external_address = s->all_addresses.at(external_address_str); string addr_str = string_for_address(s->external_address); - log(INFO, "Added external address: %s (%s)", addr_str.c_str(), + config_log.info("Added external address: %s (%s)", addr_str.c_str(), external_address_str.c_str()); } catch (const out_of_range&) { s->external_address = address_for_string(external_address_str.c_str()); - log(INFO, "Added external address: %s", external_address_str.c_str()); + config_log.info("Added external address: %s", external_address_str.c_str()); } s->all_addresses.emplace("", s->external_address); @@ -134,15 +135,23 @@ void populate_state_from_config(shared_ptr s, s->item_tracking_enabled = true; } + shared_ptr log_levels_json; + try { + log_levels_json = d.at("LogLevels"); + } catch (const out_of_range&) { } + if (log_levels_json.get()) { + set_log_levels_from_json(log_levels_json); + } + for (const string& filename : list_directory("system/blueburst/keys")) { if (!ends_with(filename, ".nsk")) { continue; } s->bb_private_keys.emplace_back(new PSOBBEncryption::KeyFile( load_object_file("system/blueburst/keys/" + filename))); - log(INFO, "Loaded Blue Burst key file: %s", filename.c_str()); + config_log.info("Loaded Blue Burst key file: %s", filename.c_str()); } - log(INFO, "%zu Blue Burst key file(s) loaded", s->bb_private_keys.size()); + config_log.info("%zu Blue Burst key file(s) loaded", s->bb_private_keys.size()); try { bool run_shell = d.at("RunInteractiveShell")->as_bool(); @@ -178,8 +187,7 @@ void drop_privileges(const string& username) { throw runtime_error(string_printf("can\'t switch to user %d (%s)", pw->pw_uid, error.c_str())); } - log(INFO, "Switched to user %s (%d:%d)", username.c_str(), pw->pw_uid, - pw->pw_gid); + config_log.info("Switched to user %s (%d:%d)", username.c_str(), pw->pw_uid, pw->pw_gid); } @@ -320,57 +328,57 @@ int main(int argc, char** argv) { shared_ptr base(event_base_new(), event_base_free); - log(INFO, "Reading network addresses"); + config_log.info("Reading network addresses"); state->all_addresses = get_local_addresses(); for (const auto& it : state->all_addresses) { string addr_str = string_for_address(it.second); - log(INFO, "Found interface: %s = %s", it.first.c_str(), addr_str.c_str()); + config_log.info("Found interface: %s = %s", it.first.c_str(), addr_str.c_str()); } - log(INFO, "Loading configuration"); + config_log.info("Loading configuration"); auto config_json = JSONObject::parse(load_file("system/config.json")); populate_state_from_config(state, config_json); - log(INFO, "Loading license list"); + config_log.info("Loading license list"); state->license_manager.reset(new LicenseManager("system/licenses.nsi")); - log(INFO, "Loading battle parameters"); + config_log.info("Loading battle parameters"); state->battle_params.reset(new BattleParamTable("system/blueburst/BattleParamEntry")); - log(INFO, "Loading level table"); + config_log.info("Loading level table"); state->level_table.reset(new LevelTable("system/blueburst/PlyLevelTbl.prs", true)); - log(INFO, "Collecting Episode 3 data"); + config_log.info("Collecting Episode 3 data"); state->ep3_data_index.reset(new Ep3DataIndex("system/ep3")); - log(INFO, "Collecting quest metadata"); + config_log.info("Collecting quest metadata"); state->quest_index.reset(new QuestIndex("system/quests")); - log(INFO, "Compiling client functions"); + config_log.info("Compiling client functions"); state->function_code_index.reset(new FunctionCodeIndex("system/ppc")); - log(INFO, "Loading DOL files"); + config_log.info("Loading DOL files"); state->dol_file_index.reset(new DOLFileIndex("system/dol")); - log(INFO, "Creating menus"); + config_log.info("Creating menus"); state->create_menus(config_json); shared_ptr dns_server; if (state->dns_server_port) { - log(INFO, "Starting DNS server"); + config_log.info("Starting DNS server"); dns_server.reset(new DNSServer(base, state->local_address, state->external_address)); dns_server->listen("", state->dns_server_port); } else { - log(INFO, "DNS server is disabled"); + config_log.info("DNS server is disabled"); } - log(INFO, "Opening sockets"); + config_log.info("Opening sockets"); for (const auto& it : state->name_to_port_config) { const auto& pc = it.second; if (pc->behavior == ServerBehavior::PROXY_SERVER) { if (!state->proxy_server.get()) { - log(INFO, "Starting proxy server"); + config_log.info("Starting proxy server"); state->proxy_server.reset(new ProxyServer(base, state)); } if (state->proxy_server.get()) { @@ -395,7 +403,7 @@ int main(int argc, char** argv) { } } else { if (!state->game_server.get()) { - log(INFO, "Starting game server"); + config_log.info("Starting game server"); state->game_server.reset(new Server(base, state)); } string name = string_printf("%s (%s, %s) on port %hu", @@ -407,7 +415,7 @@ int main(int argc, char** argv) { shared_ptr ip_stack_simulator; if (!state->ip_stack_addresses.empty()) { - log(INFO, "Starting IP stack simulator"); + config_log.info("Starting IP stack simulator"); ip_stack_simulator.reset(new IPStackSimulator(base, state)); for (const auto& it : state->ip_stack_addresses) { auto netloc = parse_netloc(it); @@ -416,7 +424,7 @@ int main(int argc, char** argv) { } if (!state->username.empty()) { - log(INFO, "Switching to user %s", state->username.c_str()); + config_log.info("Switching to user %s", state->username.c_str()); drop_privileges(state->username); } @@ -430,10 +438,10 @@ int main(int argc, char** argv) { shell.reset(new ServerShell(base, state)); } - log(INFO, "Ready"); + config_log.info("Ready"); event_base_dispatch(base.get()); - log(INFO, "Normal shutdown"); + config_log.info("Normal shutdown"); state->proxy_server.reset(); // Break reference cycle return 0; } diff --git a/src/Map.cc b/src/Map.cc index 3af41cde..673627cc 100644 --- a/src/Map.cc +++ b/src/Map.cc @@ -1,7 +1,9 @@ #include "Map.hh" #include +#include +#include "Loggers.hh" #include "FileContentsCache.hh" using namespace std; @@ -420,8 +422,8 @@ static vector parse_map(uint8_t episode, uint8_t difficulty, break; default: enemies[num_enemies].experience = 0xFFFFFFFF; - log(WARNING, "Unknown enemy type %08" PRIX32 " %08" PRIX32, map[y].base, - map[y].skin); + static_game_data_log.warning("Unknown enemy type %08" PRIX32 " %08" PRIX32, + map[y].base, map[y].skin); break; } if (num_clones) { diff --git a/src/Player.cc b/src/Player.cc index ac4f4d11..15cb7197 100644 --- a/src/Player.cc +++ b/src/Player.cc @@ -7,6 +7,7 @@ #include #include +#include "Loggers.hh" #include "Text.hh" #include "Version.hh" #include "StaticGameData.hh" @@ -385,7 +386,7 @@ void ClientGameData::load_account_data() { throw runtime_error("account data header is incorrect"); } } catch (const exception& e) { - log(INFO, "[BB/Account] No account data for %s; using default", + player_data_log.info("No account data for %s; using default", this->bb_username.c_str()); data.reset(new SavedAccountDataBB( load_object_file("system/players/default.nsa"))); @@ -395,13 +396,13 @@ void ClientGameData::load_account_data() { } this->account_data = data; - log(INFO, "Loaded account data file %s", filename.c_str()); + player_data_log.info("Loaded account data file %s", filename.c_str()); } void ClientGameData::save_account_data() const { string filename = this->account_data_filename(); save_file(filename, this->account_data.get(), sizeof(SavedAccountDataBB)); - log(INFO, "Saved account data file %s", filename.c_str()); + player_data_log.info("Saved account data file %s", filename.c_str()); } void ClientGameData::load_player_data() { @@ -412,13 +413,13 @@ void ClientGameData::load_player_data() { throw runtime_error("player data header is incorrect"); } this->player_data = data; - log(INFO, "Loaded player data file %s", filename.c_str()); + player_data_log.info("Loaded player data file %s", filename.c_str()); } void ClientGameData::save_player_data() const { string filename = this->player_data_filename(); save_file(filename, this->player_data.get(), sizeof(SavedPlayerDataBB)); - log(INFO, "Saved player data file %s", filename.c_str()); + player_data_log.info("Saved player data file %s", filename.c_str()); } void ClientGameData::import_player(const PSOPlayerDataPC& pc) { diff --git a/src/ProxyCommands.cc b/src/ProxyCommands.cc index c93e8c05..33aae738 100644 --- a/src/ProxyCommands.cc +++ b/src/ProxyCommands.cc @@ -26,6 +26,7 @@ #include #endif +#include "Loggers.hh" #include "ChatCommands.hh" #include "Compression.hh" #include "PSOProtocol.hh" @@ -41,20 +42,21 @@ static void forward_command(ProxyServer::LinkedSession& session, bool to_server, uint16_t command, uint32_t flag, string& data, bool print_contents = true) { auto& ch = to_server ? session.server_channel : session.client_channel; if (!ch.connected()) { - session.log(WARNING, "No endpoint is present; dropping command"); + proxy_server_log.warning("No endpoint is present; dropping command"); } else { // TODO: Don't print the command here (usually) ch.send(command, flag, data, print_contents); } } -static void check_implemented_subcommand(uint64_t id, const string& data) { +static void check_implemented_subcommand( + ProxyServer::LinkedSession& session, const string& data) { if (data.size() < 4) { - log(WARNING, "[ProxyServer/%08" PRIX64 "] Received broadcast/target command with no contents", id); + session.log.warning("Received broadcast/target command with no contents"); } else { if (!subcommand_is_implemented(data[0])) { - log(WARNING, "[ProxyServer/%08" PRIX64 "] Received subcommand %02hhX which is not implemented on the server", - id, data[0]); + session.log.warning("Received subcommand %02hhX which is not implemented on the server", + data[0]); } } } @@ -157,7 +159,7 @@ static HandlerResult process_server_pc_gc_patch_02_17(shared_ptr s, offsetof(S_ServerInit_DC_PC_GC_02_17_92_9B, after_message), 0xFFFF); if (!session.license) { - session.log(INFO, "No license in linked session"); + session.log.info("No license in linked session"); // We have to forward the command before setting up encryption, so the // client will be able to understand it. @@ -178,7 +180,7 @@ static HandlerResult process_server_pc_gc_patch_02_17(shared_ptr s, return HandlerResult::SUPPRESS; } - session.log(INFO, "Existing license in linked session"); + session.log.info("Existing license in linked session"); // This isn't forwarded to the client, so don't recreate the client's crypts if ((session.version == GameVersion::PATCH) || (session.version == GameVersion::PC)) { @@ -316,7 +318,7 @@ static HandlerResult process_server_dc_pc_gc_04(shared_ptr, bool had_guild_card_number = (session.remote_guild_card_number != 0); if (session.remote_guild_card_number != cmd.guild_card_number) { session.remote_guild_card_number = cmd.guild_card_number; - session.log(INFO, "Remote guild card number set to %" PRIu32, + session.log.info("Remote guild card number set to %" PRIu32, session.remote_guild_card_number); send_text_message_to_client(session, 0x11, string_printf( "The remote server\nhas assigned your\nGuild Card number as\n\tC6%" PRIu32, @@ -425,7 +427,7 @@ static HandlerResult process_server_B2(shared_ptr, if (session.save_files) { string output_filename = string_printf("code.%" PRId64 ".bin", now()); save_file(output_filename, data); - session.log(INFO, "Wrote code from server to file %s", output_filename.c_str()); + session.log.info("Wrote code from server to file %s", output_filename.c_str()); #ifdef HAVE_RESOURCE_FILE try { @@ -472,16 +474,16 @@ static HandlerResult process_server_B2(shared_ptr, fprintf(f.get(), "// checksum_size = 0x%" PRIX32 "\n", header.checksum_size.load()); fwritex(f.get(), disassembly); } - session.log(INFO, "Wrote disassembly to file %s", output_filename.c_str()); + session.log.info("Wrote disassembly to file %s", output_filename.c_str()); } catch (const exception& e) { - session.log(INFO, "Failed to disassemble code from server: %s", e.what()); + session.log.info("Failed to disassemble code from server: %s", e.what()); } #endif } if (session.function_call_return_value >= 0) { - session.log(INFO, "Blocking function call from server"); + session.log.info("Blocking function call from server"); C_ExecuteCodeResult_B3 cmd; cmd.return_value = session.function_call_return_value; cmd.checksum = 0; @@ -497,7 +499,7 @@ static HandlerResult process_server_E7(shared_ptr, if (session.save_files) { string output_filename = string_printf("player.%" PRId64 ".bin", now()); save_file(output_filename, data); - session.log(INFO, "Wrote player data to file %s", output_filename.c_str()); + session.log.info("Wrote player data to file %s", output_filename.c_str()); } return HandlerResult::FORWARD; } @@ -547,7 +549,7 @@ static HandlerResult process_server_bb_22(shared_ptr, // the story behind why they put that string there. if ((data.size() == 0x2C) && (fnv1a64(data.data(), data.size()) == 0x8AF8314316A27994)) { - session.log(INFO, "Enabling remote IP CRC patch"); + session.log.info("Enabling remote IP CRC patch"); session.enable_remote_ip_crc_patch = true; } return HandlerResult::FORWARD; @@ -586,7 +588,7 @@ static HandlerResult process_server_game_19_patch_14(shared_ptr, sin->sin_port = htons(cmd.port); if (!session.client_channel.connected()) { - session.log(WARNING, "Received reconnect command with no destination present"); + session.log.warning("Received reconnect command with no destination present"); return HandlerResult::SUPPRESS; } else if (command == 0x14) { @@ -639,7 +641,7 @@ static HandlerResult process_server_gc_1A_D5(shared_ptr, static HandlerResult process_server_60_62_6C_6D_C9_CB(shared_ptr, ProxyServer::LinkedSession& session, uint16_t, uint32_t, string& data) { - check_implemented_subcommand(session.id, data); + check_implemented_subcommand(session, data); if (session.save_files) { if ((session.version == GameVersion::GC) && (data.size() >= 0x14)) { @@ -649,7 +651,7 @@ static HandlerResult process_server_60_62_6C_6D_C9_CB(shared_ptr, subs[3].dword.load(), now()); string map_data = prs_decompress(data.substr(0x14)); save_file(filename, map_data); - session.log(INFO, "Wrote %zu bytes to %s", map_data.size(), filename.c_str()); + session.log.warning("Wrote %zu bytes to %s", map_data.size(), filename.c_str()); } } } @@ -680,7 +682,7 @@ static HandlerResult process_server_44_A6(shared_ptr, ProxyServer::LinkedSession::SavingFile sf( cmd.filename, output_filename, cmd.file_size); session.saving_files.emplace(cmd.filename, move(sf)); - session.log(INFO, "Opened file %s", output_filename.c_str()); + session.log.info("Opened file %s", output_filename.c_str()); } return HandlerResult::FORWARD; } @@ -695,27 +697,27 @@ static HandlerResult process_server_13_A7(shared_ptr, sf = &session.saving_files.at(cmd.filename); } catch (const out_of_range&) { string filename = cmd.filename; - session.log(WARNING, "Received data for non-open file %s", filename.c_str()); + session.log.warning("Received data for non-open file %s", filename.c_str()); return HandlerResult::FORWARD; } size_t bytes_to_write = cmd.data_size; if (bytes_to_write > 0x400) { - session.log(WARNING, "Chunk data size is invalid; truncating to 0x400"); + session.log.warning("Chunk data size is invalid; truncating to 0x400"); bytes_to_write = 0x400; } - session.log(INFO, "Writing %zu bytes to %s", bytes_to_write, sf->output_filename.c_str()); + session.log.info("Writing %zu bytes to %s", bytes_to_write, sf->output_filename.c_str()); fwritex(sf->f.get(), cmd.data, bytes_to_write); if (bytes_to_write > sf->remaining_bytes) { - session.log(WARNING, "Chunk size extends beyond original file size; file may be truncated"); + session.log.warning("Chunk size extends beyond original file size; file may be truncated"); sf->remaining_bytes = 0; } else { sf->remaining_bytes -= bytes_to_write; } if (sf->remaining_bytes == 0) { - session.log(INFO, "File %s is complete", sf->output_filename.c_str()); + session.log.info("File %s is complete", sf->output_filename.c_str()); session.saving_files.erase(cmd.filename); } } @@ -726,20 +728,20 @@ static HandlerResult process_server_gc_B8(shared_ptr, ProxyServer::LinkedSession& session, uint16_t, uint32_t, string& data) { if (session.save_files) { if (data.size() < 4) { - session.log(WARNING, "Card list data size is too small; not saving file"); + session.log.warning("Card list data size is too small; not saving file"); return HandlerResult::FORWARD; } StringReader r(data); size_t size = r.get_u32l(); if (r.remaining() < size) { - session.log(WARNING, "Card list data size extends beyond end of command; not saving file"); + session.log.warning("Card list data size extends beyond end of command; not saving file"); return HandlerResult::FORWARD; } string output_filename = string_printf("cardupdate.%" PRIu64 ".mnr", now()); save_file(output_filename, r.read(size)); - session.log(INFO, "Wrote %zu bytes to %s", size, output_filename.c_str()); + session.log.info("Wrote %zu bytes to %s", size, output_filename.c_str()); } return HandlerResult::FORWARD; } @@ -750,7 +752,7 @@ static HandlerResult process_server_65_67_68(shared_ptr, if (command == 0x67) { session.lobby_players.clear(); session.lobby_players.resize(12); - session.log(INFO, "Cleared lobby players"); + session.log.info("Cleared lobby players"); // This command can cause the client to no longer send D6 responses when // 1A/D5 large message boxes are closed. newserv keeps track of this @@ -770,7 +772,7 @@ static HandlerResult process_server_65_67_68(shared_ptr, for (size_t x = 0; x < flag; x++) { size_t index = cmd.entries[x].lobby_data.client_id; if (index >= session.lobby_players.size()) { - session.log(WARNING, "Ignoring invalid player index %zu at position %zu", index, x); + session.log.warning("Ignoring invalid player index %zu at position %zu", index, x); } else { if (session.license && (cmd.entries[x].lobby_data.guild_card == session.remote_guild_card_number)) { cmd.entries[x].lobby_data.guild_card = session.license->serial_number; @@ -779,7 +781,7 @@ static HandlerResult process_server_65_67_68(shared_ptr, session.lobby_players[index].guild_card_number = cmd.entries[x].lobby_data.guild_card; ptext name = cmd.entries[x].disp.name; session.lobby_players[index].name = name; - session.log(INFO, "Added lobby player: (%zu) %" PRIu32 " %s", + session.log.info("Added lobby player: (%zu) %" PRIu32 " %s", index, session.lobby_players[index].guild_card_number, session.lobby_players[index].name.c_str()); @@ -804,7 +806,7 @@ static HandlerResult process_server_64(shared_ptr, // We don't need to clear lobby_players here because we always // overwrite all 4 entries for this command session.lobby_players.resize(4); - session.log(INFO, "Cleared lobby players"); + session.log.info("Cleared lobby players"); const size_t expected_size = session.sub_version >= 0x40 ? sizeof(CmdT) @@ -825,7 +827,7 @@ static HandlerResult process_server_64(shared_ptr, } else { session.lobby_players[x].name.clear(); } - session.log(INFO, "Added lobby player: (%zu) %" PRIu32 " %s", + session.log.info("Added lobby player: (%zu) %" PRIu32 " %s", x, session.lobby_players[x].guild_card_number, session.lobby_players[x].name.c_str()); @@ -848,11 +850,11 @@ static HandlerResult process_server_66_69(shared_ptr, const auto& cmd = check_size_t(data); size_t index = cmd.client_id; if (index >= session.lobby_players.size()) { - session.log(WARNING, "Lobby leave command references missing position"); + session.log.warning("Lobby leave command references missing position"); } else { session.lobby_players[index].guild_card_number = 0; session.lobby_players[index].name.clear(); - session.log(INFO, "Removed lobby player (%zu)", index); + session.log.info("Removed lobby player (%zu)", index); } return HandlerResult::FORWARD; } @@ -978,13 +980,13 @@ static HandlerResult process_client_60_62_6C_6D_C9_CB(shared_ptr s, template <> HandlerResult process_client_60_62_6C_6D_C9_CB(shared_ptr, ProxyServer::LinkedSession& session, uint16_t, uint32_t, string& data) { - check_implemented_subcommand(session.id, data); + check_implemented_subcommand(session, data); if (!data.empty() && (data[0] == 0x05) && session.switch_assist) { auto& cmd = check_size_t(data); if (cmd.enabled && cmd.switch_id != 0xFFFF) { if (session.last_switch_enabled_command.subcommand == 0x05) { - session.log(INFO, "Switch assist: replaying previous enable command"); + session.log.info("Switch assist: replaying previous enable command"); session.server_channel.send(0x60, 0x00, &session.last_switch_enabled_command, sizeof(session.last_switch_enabled_command)); session.client_channel.send(0x60, 0x00, &session.last_switch_enabled_command, @@ -1286,17 +1288,17 @@ void process_proxy_command( if (res == HandlerResult::FORWARD) { forward_command(session, !from_server, command, flag, data, false); } else if (res == HandlerResult::MODIFIED) { - session.log(INFO, "The preceding command from the %s was modified in transit", + session.log.info("The preceding command from the %s was modified in transit", from_server ? "server" : "client"); forward_command(session, !from_server, command, flag, data); } else if (res == HandlerResult::SUPPRESS) { - session.log(INFO, "The preceding command from the %s was not forwarded", + session.log.info("The preceding command from the %s was not forwarded", from_server ? "server" : "client"); } else { throw logic_error("invalid handler result"); } } catch (const exception& e) { - session.log(ERROR, "Failed to process command: %s", e.what()); + session.log.error("Failed to process command: %s", e.what()); session.disconnect(); } } diff --git a/src/ProxyServer.cc b/src/ProxyServer.cc index a13162f1..3a6c4942 100644 --- a/src/ProxyServer.cc +++ b/src/ProxyServer.cc @@ -22,6 +22,7 @@ #include #include +#include "Loggers.hh" #include "PSOProtocol.hh" #include "SendCommands.hh" #include "ReceiveCommands.hh" @@ -41,8 +42,7 @@ static const uint32_t UNLICENSED_SESSION_TIMEOUT_USECS = 10 * 1000000; // 10 sec ProxyServer::ProxyServer( shared_ptr base, shared_ptr state) - : log("[ProxyServer] "), - base(base), + : base(base), state(state), next_unlicensed_session_id(0xFF00000000000001) { } @@ -59,7 +59,7 @@ ProxyServer::ListeningSocket::ListeningSocket( GameVersion version, const struct sockaddr_storage* default_destination) : server(server), - log(string_printf("[ProxyServer:ListeningSocket:%hu] ", port)), + log(string_printf("[ProxyServer:ListeningSocket:%hu] ", port), proxy_server_log.min_level), port(port), fd(::listen("", port, SOMAXCONN)), listener(nullptr, evconnlistener_free), @@ -86,7 +86,7 @@ ProxyServer::ListeningSocket::ListeningSocket( this->default_destination.ss_family = 0; } - this->log(INFO, "Listening on TCP port %hu (%s) on fd %d", + this->log.info("Listening on TCP port %hu (%s) on fd %d", this->port, name_for_version(this->version), static_cast(this->fd)); } @@ -101,7 +101,7 @@ void ProxyServer::ListeningSocket::dispatch_on_listen_error( } void ProxyServer::ListeningSocket::on_listen_accept(int fd) { - this->log(INFO, "Client connected on fd %d (port %hu, version %s)", + this->log.info("Client connected on fd %d (port %hu, version %s)", fd, this->port, name_for_version(this->version)); auto* bev = bufferevent_socket_new(this->server->base.get(), fd, BEV_OPT_CLOSE_ON_FREE | BEV_OPT_DEFER_CALLBACKS); @@ -111,7 +111,7 @@ void ProxyServer::ListeningSocket::on_listen_accept(int fd) { void ProxyServer::ListeningSocket::on_listen_error() { int err = EVUTIL_SOCKET_ERROR(); - this->log(ERROR, "Failure on listening socket %d: %d (%s)", + this->log.error("Failure on listening socket %d: %d (%s)", evconnlistener_get_fd(this->listener.get()), err, evutil_socket_error_to_string(err)); event_base_loopexit(this->server->base.get(), nullptr); @@ -126,14 +126,14 @@ void ProxyServer::connect_client(struct bufferevent* bev, uint16_t server_port) try { version = this->listeners.at(server_port)->version; } catch (const out_of_range&) { - this->log(INFO, "Virtual connection received on unregistered port %hu; closing it", + proxy_server_log.info("Virtual connection received on unregistered port %hu; closing it", server_port); bufferevent_flush(bev, EV_READ | EV_WRITE, BEV_FINISHED); bufferevent_free(bev); return; } - this->log(INFO, "Client connected on virtual connection %p (port %hu)", bev, + proxy_server_log.info("Client connected on virtual connection %p (port %hu)", bev, server_port); this->on_client_connect(bev, server_port, version, nullptr); } @@ -160,7 +160,7 @@ void ProxyServer::on_client_connect( throw logic_error("linked session already exists for unlicensed client"); } auto session = emplace_ret.first->second; - session->log(INFO, "Opened linked session"); + session->log.info("Opened linked session"); Channel ch(bev, version, nullptr, nullptr, session.get(), "", TerminalFormat::FG_YELLOW, TerminalFormat::FG_GREEN); session->resume(move(ch)); @@ -175,7 +175,7 @@ void ProxyServer::on_client_connect( throw logic_error("stale unlinked session exists"); } auto session = emplace_ret.first->second; - this->log(INFO, "Opened unlinked session"); + proxy_server_log.info("Opened unlinked session"); // Note that this should only be set when the linked session is created, not // when it is resumed! @@ -232,7 +232,7 @@ void ProxyServer::on_client_connect( ProxyServer::UnlinkedSession::UnlinkedSession( ProxyServer* server, struct bufferevent* bev, uint16_t local_port, GameVersion version) : server(server), - log(string_printf("[ProxyServer:UnlinkedSession:%p] ", bev)), + log(string_printf("[ProxyServer:UnlinkedSession:%p] ", bev), proxy_server_log.min_level), channel( bev, version, @@ -301,7 +301,7 @@ void ProxyServer::UnlinkedSession::on_input(Channel& ch, uint16_t command, uint3 } } catch (const exception& e) { - session->log(ERROR, "Failed to process command from unlinked client: %s", e.what()); + session->log.error("Failed to process command from unlinked client: %s", e.what()); should_close_unlinked_session = true; } @@ -318,7 +318,7 @@ void ProxyServer::UnlinkedSession::on_input(Channel& ch, uint16_t command, uint3 shared_ptr linked_session; try { linked_session = session->server->id_to_session.at(license->serial_number); - linked_session->log(INFO, "Resuming linked session from unlinked session"); + linked_session->log.info("Resuming linked session from unlinked session"); } catch (const out_of_range&) { // If there's no open session for this license, then there must be a valid @@ -331,7 +331,7 @@ void ProxyServer::UnlinkedSession::on_input(Channel& ch, uint16_t command, uint3 session->version, license, client_config)); - linked_session->log(INFO, "Opened licensed session for unlinked session based on client config"); + linked_session->log.info("Opened licensed session for unlinked session based on client config"); } else if (session->next_destination.ss_family == AF_INET) { linked_session.reset(new LinkedSession( session->server, @@ -339,16 +339,16 @@ void ProxyServer::UnlinkedSession::on_input(Channel& ch, uint16_t command, uint3 session->version, license, session->next_destination)); - linked_session->log(INFO, "Opened licensed session for unlinked session based on unlinked default destination"); + linked_session->log.info("Opened licensed session for unlinked session based on unlinked default destination"); } else { - session->log(ERROR, "Cannot open linked session: no valid destination in client config or unlinked session"); + session->log.error("Cannot open linked session: no valid destination in client config or unlinked session"); } } if (linked_session.get()) { session->server->id_to_session.emplace(license->serial_number, linked_session); if (linked_session->version != session->version) { - linked_session->log(ERROR, "Linked session has different game version"); + linked_session->log.error("Linked session has different game version"); } else { // Resume the linked session using the unlinked session try { @@ -365,14 +365,14 @@ void ProxyServer::UnlinkedSession::on_input(Channel& ch, uint16_t command, uint3 character_name); } } catch (const exception& e) { - linked_session->log(ERROR, "Failed to resume linked session: %s", e.what()); + linked_session->log.error("Failed to resume linked session: %s", e.what()); } } } } if (should_close_unlinked_session) { - session->log(INFO, "Closing session"); + session->log.info("Closing session"); session->server->bev_to_unlinked_session.erase(session_key); // At this point, (*this) is destroyed! We must be careful not to touch it. } @@ -383,11 +383,11 @@ void ProxyServer::UnlinkedSession::on_error(Channel& ch, short events) { if (events & BEV_EVENT_ERROR) { int err = EVUTIL_SOCKET_ERROR(); - session->log(WARNING, "Error %d (%s) in unlinked client stream", err, + session->log.warning("Error %d (%s) in unlinked client stream", err, evutil_socket_error_to_string(err)); } if (events & (BEV_EVENT_ERROR | BEV_EVENT_EOF)) { - session->log(WARNING, "Unlinked client has disconnected"); + session->log.info("Unlinked client has disconnected"); session->server->bev_to_unlinked_session.erase(session->channel.bev.get()); } } @@ -401,7 +401,7 @@ ProxyServer::LinkedSession::LinkedSession( GameVersion version) : server(server), id(id), - log(string_printf("[ProxyServer:LinkedSession:%08" PRIX64 "] ", this->id)), + log(string_printf("[ProxyServer:LinkedSession:%08" PRIX64 "] ", this->id), proxy_server_log.min_level), timeout_event(event_new(this->server->base.get(), -1, EV_TIMEOUT, &LinkedSession::dispatch_on_timeout, this), event_free), license(nullptr), @@ -542,7 +542,7 @@ void ProxyServer::LinkedSession::connect() { local_sin->sin_addr.s_addr = dest_sin->sin_addr.s_addr; string netloc_str = render_sockaddr_storage(local_ss); - this->log(INFO, "Connecting to %s", netloc_str.c_str()); + this->log.info("Connecting to %s", netloc_str.c_str()); this->server_channel.set_bufferevent(bufferevent_socket_new( this->server->base.get(), -1, BEV_OPT_CLOSE_ON_FREE | BEV_OPT_DEFER_CALLBACKS)); @@ -580,7 +580,7 @@ void ProxyServer::LinkedSession::dispatch_on_timeout( void ProxyServer::LinkedSession::on_timeout() { - this->log(INFO, "Session timed out"); + this->log.info("Session timed out"); this->server->delete_session(this->id); } @@ -592,12 +592,12 @@ void ProxyServer::LinkedSession::on_error(Channel& ch, short events) { if (events & BEV_EVENT_ERROR) { int err = EVUTIL_SOCKET_ERROR(); - session->log(WARNING, "Error %d (%s) in %s stream", + session->log.warning("Error %d (%s) in %s stream", err, evutil_socket_error_to_string(err), is_server_stream ? "server" : "client"); } if (events & (BEV_EVENT_EOF | BEV_EVENT_ERROR)) { - session->log(INFO, "%s has disconnected", + session->log.info("%s has disconnected", is_server_stream ? "Server" : "Client"); session->disconnect(); } @@ -638,7 +638,7 @@ void ProxyServer::LinkedSession::on_input(Channel& ch, uint16_t command, uint32_ flag, data); } catch (const exception& e) { - session->log(ERROR, "Failed to process command from %s: %s", + session->log.error("Failed to process command from %s: %s", is_server_stream ? "server" : "client", e.what()); session->disconnect(); } @@ -663,13 +663,13 @@ shared_ptr ProxyServer::create_licensed_session( if (!emplace_ret.second) { throw runtime_error("session already exists for this license"); } - session->log(INFO, "Opening licensed session"); + session->log.info("Opening licensed session"); return emplace_ret.first->second; } void ProxyServer::delete_session(uint64_t id) { if (this->id_to_session.erase(id)) { - this->log(INFO, "Closed LinkedSession:%08" PRIX64, id); + proxy_server_log.info("Closed LinkedSession:%08" PRIX64, id); } } diff --git a/src/ProxyServer.hh b/src/ProxyServer.hh index 2957f87f..785665cf 100644 --- a/src/ProxyServer.hh +++ b/src/ProxyServer.hh @@ -195,7 +195,6 @@ private: static void on_error(Channel& ch, short events); }; - PrefixedLogger log; std::shared_ptr base; std::shared_ptr state; std::map> listeners; diff --git a/src/Quest.cc b/src/Quest.cc index a5cf9301..84741933 100644 --- a/src/Quest.cc +++ b/src/Quest.cc @@ -8,6 +8,7 @@ #include #include +#include "Loggers.hh" #include "CommandFormats.hh" #include "Compression.hh" #include "PSOEncryption.hh" @@ -624,12 +625,12 @@ QuestIndex::QuestIndex(const std::string& directory) : directory(directory) { make_pair(q->version, q->menu_item_id), q).second) { throw logic_error("duplicate quest menu item id"); } - log(INFO, "Indexed quest %s (%s-%" PRId64 " => %" PRIu32 ", %s, %s, joinable=%s, dcv1=%s)", + static_game_data_log.info("Indexed quest %s (%s-%" PRId64 " => %" PRIu32 ", %s, %s, joinable=%s, dcv1=%s)", ascii_name.c_str(), name_for_version(q->version), q->internal_id, q->menu_item_id, name_for_category(q->category), name_for_episode(q->episode), q->joinable ? "true" : "false", q->is_dcv1 ? "true" : "false"); } catch (const exception& e) { - log(WARNING, "Failed to parse quest file %s (%s)", filename.c_str(), e.what()); + static_game_data_log.warning("Failed to parse quest file %s (%s)", filename.c_str(), e.what()); } } } diff --git a/src/ReceiveCommands.cc b/src/ReceiveCommands.cc index 1bbf928e..9d7b6edb 100644 --- a/src/ReceiveCommands.cc +++ b/src/ReceiveCommands.cc @@ -10,6 +10,7 @@ #include #include +#include "Loggers.hh" #include "ChatCommands.hh" #include "FileContentsCache.hh" #include "ProxyServer.hh" @@ -92,7 +93,7 @@ void process_connect(std::shared_ptr s, std::shared_ptr c) break; default: - log(ERROR, "Unimplemented behavior: %" PRId64, + c->log.error("Unimplemented behavior: %" PRId64, static_cast(c->server_behavior)); } } @@ -528,7 +529,7 @@ void process_ep3_server_data_request(shared_ptr s, shared_ptrlog.error("Unknown Episode III server data request: %02X", cmds[1].byte[0]); } } @@ -1514,7 +1515,6 @@ void process_player_preview_request_bb(shared_ptr, shared_ptr create_game_generic(shared_ptr s, try { game->enemies = load_map(filename.c_str(), game->episode, game->difficulty, bp_subtable, false); - log(INFO, "Loaded map %s", filename.c_str()); + c->log.info("Loaded map %s", filename.c_str()); break; } catch (const exception& e) { - log(WARNING, "Failed to load map %s: %s", filename.c_str(), e.what()); + c->log.warning("Failed to load map %s: %s", filename.c_str(), e.what()); } } } @@ -2070,9 +2070,9 @@ independently.\r\n\ void process_ignored_command(shared_ptr, shared_ptr, uint16_t, uint32_t, const string&) { } -void process_unimplemented_command(shared_ptr, shared_ptr, - uint16_t command, uint32_t flag, const string& data) { - log(WARNING, "Unknown command: size=%04zX command=%04hX flag=%08" PRIX32 "\n", +void process_unimplemented_command(shared_ptr, + shared_ptr c, uint16_t command, uint32_t flag, const string& data) { + c->log.warning("Unknown command: size=%04zX command=%04hX flag=%08" PRIX32 "\n", data.size(), command, flag); throw invalid_argument("unimplemented command"); } diff --git a/src/ReceiveSubcommands.cc b/src/ReceiveSubcommands.cc index 36d532df..78d2d5b3 100644 --- a/src/ReceiveSubcommands.cc +++ b/src/ReceiveSubcommands.cc @@ -5,6 +5,7 @@ #include #include +#include "Loggers.hh" #include "Client.hh" #include "Lobby.hh" #include "Player.hh" @@ -234,7 +235,7 @@ static void process_subcommand_switch_state_changed(shared_ptr, if (cmd.enabled && cmd.switch_id != 0xFFFF) { if ((l->flags & Lobby::Flag::CHEATS_ENABLED) && c->switch_assist && (c->last_switch_enabled_command.subcommand == 0x05)) { - log(INFO, "[Switch assist] Replaying previous enable command"); + c->log.info("[Switch assist] Replaying previous enable command"); forward_subcommand(l, c, command, flag, &c->last_switch_enabled_command, sizeof(c->last_switch_enabled_command)); send_command_t(c, command, flag, c->last_switch_enabled_command); @@ -277,8 +278,8 @@ static void process_subcommand_player_drop_item(shared_ptr, l->add_item(c->game_data.player()->remove_item(cmd->item_id, 0), cmd->area, cmd->x, cmd->z); - log(INFO, "[Items/%08" PRIX32 "] Player %hhu dropped item %08" PRIX32 " at %hu:(%g, %g)", - l->lobby_id, cmd->client_id, cmd->item_id.load(), cmd->area.load(), cmd->x.load(), cmd->z.load()); + l->log.info("Player %hhu dropped item %08" PRIX32 " at %hu:(%g, %g)", + cmd->client_id, cmd->item_id.load(), cmd->area.load(), cmd->x.load(), cmd->z.load()); c->game_data.player()->print_inventory(stderr); } @@ -307,8 +308,8 @@ static void process_subcommand_create_inventory_item(shared_ptr, item.data = cmd->item; c->game_data.player()->add_item(item); - log(INFO, "[Items/%08" PRIX32 "] Player %hhu created inventory item %08" PRIX32, - l->lobby_id, cmd->client_id, cmd->item.id.load()); + l->log.info("Player %hhu created inventory item %08" PRIX32, + cmd->client_id, cmd->item.id.load()); c->game_data.player()->print_inventory(stderr); } @@ -338,8 +339,8 @@ static void process_subcommand_drop_partial_stack(shared_ptr, item.data = cmd->data; l->add_item(item, cmd->area, cmd->x, cmd->z); - log(INFO, "[Items/%08" PRIX32 "] Player %hhu split stack to create ground item %08" PRIX32 " at %hu:(%g, %g)", - l->lobby_id, cmd->client_id, item.data.id.load(), cmd->area.load(), cmd->x.load(), cmd->z.load()); + l->log.info("Player %hhu split stack to create ground item %08" PRIX32 " at %hu:(%g, %g)", + cmd->client_id, item.data.id.load(), cmd->area.load(), cmd->x.load(), cmd->z.load()); c->game_data.player()->print_inventory(stderr); } @@ -375,8 +376,8 @@ static void process_subcommand_drop_partial_stack_bb(shared_ptr, l->add_item(item, cmd->area, cmd->x, cmd->z); - log(INFO, "[Items/%08" PRIX32 "/BB] Player %hhu split stack %08" PRIX32 " (%" PRIu32 " of them) at %hu:(%g, %g)", - l->lobby_id, cmd->client_id, cmd->item_id.load(), cmd->amount.load(), + l->log.info("Player %hhu split stack %08" PRIX32 " (%" PRIu32 " of them) at %hu:(%g, %g)", + cmd->client_id, cmd->item_id.load(), cmd->amount.load(), cmd->area.load(), cmd->x.load(), cmd->z.load()); c->game_data.player()->print_inventory(stderr); @@ -407,8 +408,8 @@ static void process_subcommand_buy_shop_item(shared_ptr, item.data = cmd->item; c->game_data.player()->add_item(item); - log(INFO, "[Items/%08" PRIX32 "] Player %hhu bought item %08" PRIX32 " from shop", - l->lobby_id, cmd->client_id, item.data.id.load()); + l->log.info("Player %hhu bought item %08" PRIX32 " from shop", + cmd->client_id, item.data.id.load()); c->game_data.player()->print_inventory(stderr); } @@ -434,8 +435,8 @@ static void process_subcommand_box_or_enemy_item_drop(shared_ptr, item.data = cmd->data; l->add_item(item, cmd->area, cmd->x, cmd->z); - log(INFO, "[Items/%08" PRIX32 "] Leader created ground item %08" PRIX32 " at %hhu:(%g, %g)", - l->lobby_id, item.data.id.load(), cmd->area, cmd->x.load(), cmd->z.load()); + l->log.info("Leader created ground item %08" PRIX32 " at %hhu:(%g, %g)", + item.data.id.load(), cmd->area, cmd->x.load(), cmd->z.load()); forward_subcommand(l, c, command, flag, data); } @@ -461,8 +462,8 @@ static void process_subcommand_pick_up_item(shared_ptr, if (l->flags & Lobby::Flag::ITEM_TRACKING_ENABLED) { effective_c->game_data.player()->add_item(l->remove_item(cmd->item_id)); - log(INFO, "[Items/%08" PRIX32 "] Player %hu picked up %08" PRIX32, - l->lobby_id, cmd->client_id.load(), cmd->item_id.load()); + l->log.info("Player %hu picked up %08" PRIX32, + cmd->client_id.load(), cmd->item_id.load()); effective_c->game_data.player()->print_inventory(stderr); } @@ -486,8 +487,7 @@ static void process_subcommand_pick_up_item_request(shared_ptr, c->game_data.player()->add_item(l->remove_item(cmd->item_id)); - log(INFO, "[Items/%08" PRIX32 "/BB] Player %hhu picked up %08" PRIX32, - l->lobby_id, cmd->client_id, cmd->item_id.load()); + l->log.info("Player %hhu picked up %08" PRIX32, cmd->client_id, cmd->item_id.load()); c->game_data.player()->print_inventory(stderr); send_pick_up_item(l, c, cmd->item_id, cmd->area); @@ -537,8 +537,7 @@ static void process_subcommand_use_item(shared_ptr, size_t index = c->game_data.player()->inventory.find_item(cmd->item_id); player_use_item(c, index); - log(INFO, "[Items/%08" PRIX32 "] Player used item %hhu:%08" PRIX32, - l->lobby_id, cmd->client_id, cmd->item_id.load()); + l->log.info("Player used item %hhu:%08" PRIX32, cmd->client_id, cmd->item_id.load()); c->game_data.player()->print_inventory(stderr); } @@ -933,8 +932,8 @@ static void process_subcommand_destroy_inventory_item(shared_ptr, } if (l->flags & Lobby::Flag::ITEM_TRACKING_ENABLED) { c->game_data.player()->remove_item(cmd->item_id, cmd->amount); - log(INFO, "[Items/%08" PRIX32 "] Inventory item %hhu:%08" PRIX32 " destroyed (%" PRIX32 " of them)", - l->lobby_id, cmd->client_id, cmd->item_id.load(), cmd->amount.load()); + l->log.info("Inventory item %hhu:%08" PRIX32 " destroyed (%" PRIX32 " of them)", + cmd->client_id, cmd->item_id.load(), cmd->amount.load()); c->game_data.player()->print_inventory(stderr); forward_subcommand(l, c, command, flag, data); } @@ -949,8 +948,8 @@ static void process_subcommand_destroy_ground_item(shared_ptr, } if (l->flags & Lobby::Flag::ITEM_TRACKING_ENABLED) { l->remove_item(cmd->item_id); - log(INFO, "[Items/%08" PRIX32 "] Ground item %08" PRIX32 " destroyed (%" PRIX32 " of them)", - l->lobby_id, cmd->item_id.load(), cmd->amount.load()); + l->log.info("Ground item %08" PRIX32 " destroyed (%" PRIX32 " of them)", + cmd->item_id.load(), cmd->amount.load()); forward_subcommand(l, c, command, flag, data); } } @@ -1085,24 +1084,24 @@ static void process_subcommand_forward_check_size_ep3_game(shared_ptr, - shared_ptr, shared_ptr, uint8_t command, uint8_t flag, + shared_ptr, shared_ptr c, uint8_t command, uint8_t flag, const string& data) { const auto* p = check_size_sc(data, sizeof(PSOSubcommand), 0xFFFF); if (command_is_private(command)) { - log(WARNING, "Invalid subcommand: %02hhX (private to %hhu)", p->byte[0], flag); + c->log.error("Invalid subcommand: %02hhX (private to %hhu)", p->byte[0], flag); } else { - log(WARNING, "Invalid subcommand: %02hhX (public)", p->byte[0]); + c->log.error("Invalid subcommand: %02hhX (public)", p->byte[0]); } } static void process_subcommand_unimplemented(shared_ptr, - shared_ptr, shared_ptr, uint8_t command, uint8_t flag, + shared_ptr, shared_ptr c, uint8_t command, uint8_t flag, const string& data) { const auto* p = check_size_sc(data, sizeof(PSOSubcommand), 0xFFFF); if (command_is_private(command)) { - log(WARNING, "Unknown subcommand: %02hhX (private to %hhu)", p->byte[0], flag); + c->log.warning("Unknown subcommand: %02hhX (private to %hhu)", p->byte[0], flag); } else { - log(WARNING, "Unknown subcommand: %02hhX (public)", p->byte[0]); + c->log.warning("Unknown subcommand: %02hhX (public)", p->byte[0]); } } diff --git a/src/Server.cc b/src/Server.cc index 52104b70..1d39cb57 100644 --- a/src/Server.cc +++ b/src/Server.cc @@ -20,6 +20,7 @@ #include #include +#include "Loggers.hh" #include "PSOProtocol.hh" #include "ReceiveCommands.hh" @@ -30,10 +31,10 @@ using namespace std::placeholders; void Server::disconnect_client(shared_ptr c) { if (c->channel.is_virtual_connection) { - this->log(INFO, "Disconnecting client on virtual connection %p", + server_log.info("Disconnecting client on virtual connection %p", c->channel.bev.get()); } else { - this->log(INFO, "Disconnecting client on fd %d", + server_log.info("Disconnecting client on fd %d", bufferevent_getfd(c->channel.bev.get())); } @@ -43,7 +44,7 @@ void Server::disconnect_client(shared_ptr c) { try { process_disconnect(this->state, c); } catch (const exception& e) { - this->log(WARNING, "Error during client disconnect cleanup: %s", e.what()); + server_log.warning("Error during client disconnect cleanup: %s", e.what()); } // c is destroyed here (process_disconnect should remove any other references // to it, e.g. from Lobby objects) @@ -69,13 +70,13 @@ void Server::on_listen_accept(struct evconnlistener* listener, try { listening_socket = &this->listening_sockets.at(listen_fd); } catch (const out_of_range& e) { - this->log(WARNING, "Can\'t determine version for socket %d; disconnecting client", + server_log.warning("Can\'t determine version for socket %d; disconnecting client", listen_fd); close(fd); return; } - this->log(INFO, "Client fd %d connected via fd %d (%s)", + server_log.info("Client fd %d connected via fd %d (%s)", fd, listen_fd, listening_socket->name.c_str()); struct bufferevent *bev = bufferevent_socket_new(this->base.get(), fd, @@ -90,7 +91,7 @@ void Server::on_listen_accept(struct evconnlistener* listener, try { process_connect(this->state, c); } catch (const exception& e) { - this->log(WARNING, "Error during client initialization: %s", e.what()); + server_log.warning("Error during client initialization: %s", e.what()); this->disconnect_client(c); } } @@ -98,7 +99,7 @@ void Server::on_listen_accept(struct evconnlistener* listener, void Server::connect_client( struct bufferevent* bev, uint32_t address, uint16_t port, GameVersion version, ServerBehavior initial_state) { - this->log(INFO, "Client connected on virtual connection %p", bev); + server_log.info("Client connected on virtual connection %p", bev); shared_ptr c(new Client(bev, version, initial_state)); c->channel.on_command_received = Server::on_client_input; @@ -117,14 +118,14 @@ void Server::connect_client( try { process_connect(this->state, c); } catch (const exception& e) { - this->log(WARNING, "Error during client initialization: %s", e.what()); + server_log.error("Error during client initialization: %s", e.what()); this->disconnect_client(c); } } void Server::on_listen_error(struct evconnlistener* listener) { int err = EVUTIL_SOCKET_ERROR(); - this->log(ERROR, "Failure on listening socket %d: %d (%s)", + server_log.error("Failure on listening socket %d: %d (%s)", evconnlistener_get_fd(listener), err, evutil_socket_error_to_string(err)); event_base_loopexit(this->base.get(), nullptr); } @@ -139,7 +140,7 @@ void Server::on_client_input(Channel& ch, uint16_t command, uint32_t flag, std:: try { process_command(server->state, c, command, flag, data); } catch (const exception& e) { - server->log(WARNING, "Error processing client command: %s", e.what()); + server_log.warning("Error processing client command: %s", e.what()); c->should_disconnect = true; } if (c->should_disconnect) { @@ -154,7 +155,7 @@ void Server::on_client_error(Channel& ch, short events) { if (events & BEV_EVENT_ERROR) { int err = EVUTIL_SOCKET_ERROR(); - server->log(WARNING, "Client caused error %d (%s)", err, + server_log.warning("Client caused error %d (%s)", err, evutil_socket_error_to_string(err)); } if (events & (BEV_EVENT_EOF | BEV_EVENT_ERROR)) { @@ -165,9 +166,7 @@ void Server::on_client_error(Channel& ch, short events) { Server::Server( shared_ptr base, shared_ptr state) - : log("[Server] "), - base(base), - state(state) { } + : base(base), state(state) { } void Server::listen( const std::string& name, @@ -175,7 +174,7 @@ void Server::listen( GameVersion version, ServerBehavior behavior) { int fd = ::listen(socket_path, 0, SOMAXCONN); - this->log(INFO, "Listening on Unix socket %s (%s) on fd %d (name: %s)", + server_log.info("Listening on Unix socket %s (%s) on fd %d (name: %s)", socket_path.c_str(), name_for_version(version), fd, name.c_str()); this->add_socket(name, fd, version, behavior); } @@ -188,7 +187,7 @@ void Server::listen( ServerBehavior behavior) { int fd = ::listen(addr, port, SOMAXCONN); string netloc_str = render_netloc(addr, port); - this->log(INFO, "Listening on TCP interface %s (%s) on fd %d (name: %s)", + server_log.info("Listening on TCP interface %s (%s) on fd %d (name: %s)", netloc_str.c_str(), name_for_version(version), fd, name.c_str()); this->add_socket(name, fd, version, behavior); } diff --git a/src/Server.hh b/src/Server.hh index 84474cfb..881c950c 100644 --- a/src/Server.hh +++ b/src/Server.hh @@ -32,7 +32,6 @@ public: std::shared_ptr get_client() const; private: - PrefixedLogger log; std::shared_ptr base; struct ListeningSocket { diff --git a/src/ServerState.cc b/src/ServerState.cc index f24ca6fb..961656d2 100644 --- a/src/ServerState.cc +++ b/src/ServerState.cc @@ -5,6 +5,7 @@ #include #include +#include "Loggers.hh" #include "IPStackSimulator.hh" #include "NetworkAddresses.hh" #include "SendCommands.hh" @@ -300,7 +301,7 @@ void ServerState::create_menus(shared_ptr config_json) { try { const string& netloc_str = d.at("ProxyDestination-Patch")->as_string(); this->proxy_destination_patch = parse_netloc(netloc_str); - log(INFO, "Patch server proxy is enabled with destination %s", netloc_str.c_str()); + config_log.info("Patch server proxy is enabled with destination %s", netloc_str.c_str()); for (auto& it : this->name_to_port_config) { if (it.second->version == GameVersion::PATCH) { it.second->behavior = ServerBehavior::PROXY_SERVER; @@ -313,7 +314,7 @@ void ServerState::create_menus(shared_ptr config_json) { try { const string& netloc_str = d.at("ProxyDestination-BB")->as_string(); this->proxy_destination_bb = parse_netloc(netloc_str); - log(INFO, "BB proxy is enabled with destination %s", netloc_str.c_str()); + config_log.info("BB proxy is enabled with destination %s", netloc_str.c_str()); for (auto& it : this->name_to_port_config) { if (it.second->version == GameVersion::BB) { it.second->behavior = ServerBehavior::PROXY_SERVER; diff --git a/system/config.example.json b/system/config.example.json index 98567fb0..0731b4c7 100644 --- a/system/config.example.json +++ b/system/config.example.json @@ -87,6 +87,56 @@ // run if it's not. This option, if present, overrides that behavior. // "RunInteractiveShell": false, + // Specify which kinds of logging you want to be enabled. This allows you to + // make the terminal more or less noisy when players are connected, so you can + // see only the log messages you care about. The log levels are, in decreasing + // order of verbosity, "debug", "info", "warning", "error", and "disabled". + "LogLevels": { + // AX messages are messages sent to the terminal with the $ax command. + "AXMessages": "info", + // Channel exceptions are messages about clients disconnecting unexpectedly, + // or other unexpected network-level events. + "ChannelExceptions": "info", + // Client messages describe events that are specific to a single client's + // connection or game state. + "Clients": "info", + // Command data messages show the raw data for all commands sent and + // received, on both the game server and proxy server. If stderr is a + // terminal, these messages are colored as well; green is for commands sent + // by the client, yellow is for commands sent by newserv, and red is for + // commands sent by the remote server (for proxy server sessions). + "CommandData": "info", + // Config messages describe server-wide events, and generally only occur + // during the startup procedure. + "Config": "info", + // DNS server messages describe erroneous queries that the DNS server does + // not respond to. Normal DNS queries do not generate any log messages. + "DNSServer": "info", + // Function compiler messages describe PowerPC function call assembly + // events, which generally only occur during startup. + "FunctionCompiler": "info", + // IP stack simulator messages describe clients connecting and disconnecting + // via the IP stack interface, and errors that occur at the simulated + // network level within the simulator. + "IPStackSimulator": "info", + // License manager messages describe the creation of new license files. + "LicenseManager": "info", + // Lobby messages describe creation and deletion of lobbies and games, as + // well as item tracking events within games. + "Lobbies": "info", + // Player data messages describe the loading and saving of player and + // account data files. + "PlayerData": "info", + // Proxy server messages describe clients connecting and disconnecting from + // the proxy server, as well as events that occur in each session. + "ProxyServer": "info", + // Game server messages describe clients connecting and disconnecting from + // the game server. + "GameServer": "info", + // Static game data messages describe the loading of any kind of game data. + "StaticGameData": "info", + }, + // By default, the server only allows users who are registered in the license // file to connect. By enabling this option, all non-BB users will be allowed // to connect. This option has no effect for Blue Burst clients; they are