fix quest menu selection bug

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

src/Channel.cc

@@ -10,6 +10,7 @@
 #include <phosg/Network.hh>
 #include <phosg/Time.hh>
 
+#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;
     }

src/ChatCommands.cc

@@ -8,6 +8,7 @@
 #include <phosg/Strings.hh>
 #include <phosg/Time.hh>
 
+#include "Loggers.hh"
 #include "Server.hh"
 #include "ProxyServer.hh"
 #include "Lobby.hh"
@@ -166,7 +167,7 @@ static void server_command_ax(shared_ptr<ServerState>, shared_ptr<Lobby>,
     shared_ptr<Client> 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<ServerState> s, shared_ptr<Lobby>,

src/Client.cc

@@ -9,6 +9,7 @@
 #include <phosg/Network.hh>
 #include <phosg/Time.hh>
 
+#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),

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<const License> license;
   GameVersion version;

src/CommandFormats.hh

@@ -267,7 +267,7 @@ struct SC_TextHeader_01_06_11_B0_EE {
 // The client will respond with an (encrypted) 9A or 9E command on PSO GC; on
 // PSO PC, the client will respond with an (encrypted) 9A or 9D command.
 // The copyright field in the below structure must contain the following text:
-// "DreamCast Port Map. Copyright SEGA Enterprises. 1999"
+// "DreamCast Lobby Server. Copyright SEGA Enterprises. 1999"
 
 struct S_ServerInit_DC_PC_GC_02_17_92_9B {
   ptext<char, 0x40> copyright;
@@ -524,7 +524,7 @@ struct C_WriteFileConfirmation_GC_BB_13_A7 {
 // receive a 17 command in any online session; after the first time, they will
 // respond with a 9E. Non-V3 clients will respond with a 9D.
 // The copyright field in the structure must contain the following text:
-// "DreamCast Lobby Server. Copyright SEGA Enterprises. 1999";
+// "DreamCast Port Map. Copyright SEGA Enterprises. 1999"
 
 // 18 (S->C): License verification result (PC/GC)
 // Behaves exactly the same as 9A (S->C). No arguments except header.flag.
@@ -540,8 +540,8 @@ struct S_Reconnect_19 {
 
 // Because PSO PC and some versions of PSO GC use the same port but different
 // protocols, we use a specially-crafted 19 command to send them to two
-// different ports depending on the client version. I originally saw this
+// different ports depending on the client version. I first saw this technique
-// technique used by Schthack; I don't know if it was his original creation.
+// used by Schthack; I don't know if it was his original creation.
 
 struct S_ReconnectSplit_19 {
   be_uint32_t pc_address;
@@ -556,13 +556,15 @@ struct S_ReconnectSplit_19 {
 };
 
 // 1A: Large message box
-// Client will usually respond with a D6 command (see D6 for more information).
+// On V3 (PSO GC), client will usually respond with a D6 command (see D6 for
+// more information).
 // Contents are plain text (char on DC/GC, char16_t on PC/BB). There must be at
 // least one null character ('\0') before the end of the command data.
 // There is a bug in V3 (and possibly all versions) where if this command is
 // sent after the client has joined a lobby, the chat log window contents will
 // appear in the message box, prepended to the message text from the command.
-// The maximum length of the message is 0x400 bytes.
+// The maximum length of the message is 0x400 bytes. This is the only difference
+// between this command and the D5 command.
 
 // 1B: Valid but ignored (PC/GC)
 // 1C: Valid but ignored (PC/GC)
@@ -1710,17 +1712,15 @@ struct S_Unknown_GC_Ep3_CC {
 
 // D5: Large message box (GC/BB)
 // Same as 1A command, except the maximum length of the message is 0x1000 bytes.
-// Sylverant's documentation notes that D5 is not valid on pre-V3 versions (PSO
-// DC or PSO PC).
 
 // D6 (C->S): Large message box closed (GC)
 // No arguments
-// DC and PC do not send this command at all. GC v1.0 and v1.1 will send this
+// DC, PC, and BB do not send this command at all. GC v1.0 and v1.1 will send
-// command when any large message box (1A/D5) is closed; GC Plus and Episode 3
+// this command when any large message box (1A/D5) is closed; GC Plus and
-// will send D6 only for large message boxes that occur before the client has
+// Episode 3 will send D6 only for large message boxes that occur before the
-// joined a lobby. (After joining a lobby, large message boxes will still be
+// client has joined a lobby. (After joining a lobby, large message boxes will
-// displayed if sent by the server, but the client won't send a D6 when they are
+// still be displayed if sent by the server, but the client won't send a D6 when
-// closed.)
+// they are closed.)
 
 // D7 (C->S): Request GBA game file (GC)
 // The server should send the requested file using A6/A7 commands.
@@ -1729,12 +1729,12 @@ struct C_GBAGameRequest_GC_D7 {
   ptext<char, 0x10> filename;
 };
 
-// D7 (S->C): Unknown (GC)
+// D7 (S->C): Unknown (GC/BB)
-// This command does... something. The command isn't *completely* ignored: it
+// No arguments
-// sets a global state variable, but it's not clear what that variable does, or
+// On PSO GC, this command does... something. The command isn't *completely*
-// even if it does anything at all.
+// ignored: it sets a global state variable, but it's not clear what that
-
+// variable does, or even if it does anything at all.
-// D7 (S->C): Valid but ignored (BB)
+// PSO BB completely ignores this command.
 
 // D8 (C->S): Info board request (GC/BB)
 // No arguments

src/DNSServer.cc

@@ -12,6 +12,7 @@
 #include <vector>
 #include <string>
 
+#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 {

src/Episode3.cc

@@ -5,6 +5,7 @@
 #include <array>
 #include <phosg/Filesystem.hh>
 
+#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;

src/FunctionCompiler.cc

@@ -10,6 +10,7 @@
 #include <resource_file/Emulators/PPC32Emulator.hh>
 #endif
 
+#include "Loggers.hh"
 #include "CommandFormats.hh"
 
 using namespace std;
@@ -133,7 +134,7 @@ shared_ptr<CompiledFunctionCode> 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<MenuItem> 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());
     }
   }
 }

src/IPStackSimulator.cc

@@ -19,6 +19,7 @@
 #include <phosg/Random.hh>
 #include <phosg/Time.hh>
 
+#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",
+  ip_stack_simulator_log.info("Client fd %d connected via fd %d", fd, listen_fd);
-      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",
+    ip_stack_simulator_log.info("Client fd %d disconnected", bufferevent_getfd(bev));
-        bufferevent_getfd(bev));
-
     this->bev_to_client.erase(bev);
   }
 }
@@ -255,7 +252,7 @@ void IPStackSimulator::on_client_frame(
     shared_ptr<IPClient> 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<IPClient> 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<size_t>(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<IPClient::TCPConnection*>(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<IPClient::TCPConnection*>(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<IPClient> 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<IPClient::TCPConnection*>(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<IPClient> 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));
   }

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<struct event_base> base;
   std::shared_ptr<ServerState> state;
 

src/Items.cc

@@ -23,9 +23,9 @@ using namespace std;
 030D00 = Sorcerer's Right Arm
 030D01 = S-beat's Arms
 030D02 = P-arm's Arms
-030D03 = Delsabre's Right Arm
+030D03 = Delsaber's Right Arm
 030D04 = C-bringer's Right Arm
-030D05 = Delsabre's Left Arm
+030D05 = Delsaber's Left Arm
 030D06 = S-red's Arms
 030D07 = Dragon's Claw
 030D08 = Hildebear's Head

src/License.cc

@@ -5,6 +5,7 @@
 #include <phosg/Filesystem.hh>
 #include <phosg/Time.hh>
 
+#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());
   }
 }

src/Lobby.cc

@@ -4,6 +4,7 @@
 
 #include <phosg/Random.hh>
 
+#include "Loggers.hh"
 #include "SendCommands.hh"
 #include "Text.hh"
 
@@ -11,11 +12,24 @@ using namespace std;
 
 
 
-Lobby::Lobby() : lobby_id(0), min_level(0), max_level(0xFFFFFFFF),
+Lobby::Lobby(uint32_t id)
-    next_game_item_id(0x00810000), version(GameVersion::GC), section_id(0),
+  : log(string_printf("[Lobby/%" PRIX32 "] ", id), lobby_log.min_level),
-    episode(1), difficulty(0), mode(0), rare_seed(random_object<uint32_t>()),
+    lobby_id(id),
-    event(0), block(0), type(0), leader_id(0), max_clients(12), flags(0) {
+    min_level(0),
-
+    max_level(0xFFFFFFFF),
+    next_game_item_id(0x00810000),
+    version(GameVersion::GC),
+    section_id(0),
+    episode(1),
+    difficulty(0),
+    mode(0),
+    rare_seed(random_object<uint32_t>()),
+    event(0),
+    block(0),
+    type(0),
+    leader_id(0),
+    max_clients(12),
+    flags(0) {
   for (size_t x = 0; x < 12; x++) {
     this->next_item_id[x] = 0x00010000 + 0x00200000 * x;
   }

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<const Quest> loading_quest;
   std::array<std::shared_ptr<Client>, 12> clients;
 
-  Lobby();
+  explicit Lobby(uint32_t id);
 
   inline bool is_game() const {
     return this->flags & Flag::GAME;

src/Loggers.cc

@@ -0,0 +1,57 @@
+#include "Loggers.hh"
+
+#include <phosg/Strings.hh>
+
+using namespace std;
+
+
+
+PrefixedLogger ax_messages_log       ("[$ax message] "     , LogLevel::USE_DEFAULT);
+PrefixedLogger channel_exceptions_log("[Channel] "         , LogLevel::USE_DEFAULT);
+PrefixedLogger client_log            (""                   , LogLevel::USE_DEFAULT);
+PrefixedLogger command_data_log      (""                   , LogLevel::USE_DEFAULT);
+PrefixedLogger config_log            ("[Config] "          , LogLevel::USE_DEFAULT);
+PrefixedLogger dns_server_log        ("[DNSServer] "       , LogLevel::USE_DEFAULT);
+PrefixedLogger function_compiler_log ("[FunctionCompiler] ", LogLevel::USE_DEFAULT);
+PrefixedLogger ip_stack_simulator_log("[IPStackSimulator] ", LogLevel::USE_DEFAULT);
+PrefixedLogger license_log           ("[LicenseManager] "  , LogLevel::USE_DEFAULT);
+PrefixedLogger lobby_log             (""                   , LogLevel::USE_DEFAULT);
+PrefixedLogger player_data_log       (""                   , LogLevel::USE_DEFAULT);
+PrefixedLogger proxy_server_log      ("[ProxyServer] "     , LogLevel::USE_DEFAULT);
+PrefixedLogger server_log            ("[Server] "          , LogLevel::USE_DEFAULT);
+PrefixedLogger static_game_data_log  ("[StaticGameData] "  , LogLevel::USE_DEFAULT);
+
+static LogLevel log_level_for_name(const string& name) {
+  static const unordered_map<string, LogLevel> levels({
+    {"debug", LogLevel::DEBUG},
+    {"info", LogLevel::INFO},
+    {"warning", LogLevel::WARNING},
+    {"error", LogLevel::ERROR},
+    {"disabled", LogLevel::DISABLED},
+  });
+  return levels.at(tolower(name));
+}
+
+static void set_log_level_from_json(
+    PrefixedLogger& log, shared_ptr<JSONObject> d, const char* json_key) {
+  try {
+    log.min_level = log_level_for_name(d->at(json_key)->as_string());
+  } catch (const JSONObject::key_error&) { }
+}
+
+void set_log_levels_from_json(shared_ptr<JSONObject> json) {
+  set_log_level_from_json(ax_messages_log       , json, "AXMessages");
+  set_log_level_from_json(channel_exceptions_log, json, "ChannelExceptions");
+  set_log_level_from_json(client_log            , json, "Clients");
+  set_log_level_from_json(command_data_log      , json, "CommandData");
+  set_log_level_from_json(config_log            , json, "Config");
+  set_log_level_from_json(dns_server_log        , json, "DNSServer");
+  set_log_level_from_json(function_compiler_log , json, "FunctionCompiler");
+  set_log_level_from_json(ip_stack_simulator_log, json, "IPStackSimulator");
+  set_log_level_from_json(license_log           , json, "LicenseManager");
+  set_log_level_from_json(lobby_log             , json, "Lobbies");
+  set_log_level_from_json(player_data_log       , json, "PlayerData");
+  set_log_level_from_json(proxy_server_log      , json, "ProxyServer");
+  set_log_level_from_json(server_log            , json, "GameServer");
+  set_log_level_from_json(static_game_data_log  , json, "StaticGameData");
+}

src/Loggers.hh

@@ -0,0 +1,23 @@
+#pragma once
+
+#include <phosg/Strings.hh>
+#include <phosg/JSON.hh>
+
+
+
+extern PrefixedLogger ax_messages_log;
+extern PrefixedLogger channel_exceptions_log;
+extern PrefixedLogger client_log;
+extern PrefixedLogger command_data_log;
+extern PrefixedLogger config_log;
+extern PrefixedLogger dns_server_log;
+extern PrefixedLogger function_compiler_log;
+extern PrefixedLogger ip_stack_simulator_log;
+extern PrefixedLogger license_log;
+extern PrefixedLogger lobby_log;
+extern PrefixedLogger player_data_log;
+extern PrefixedLogger proxy_server_log;
+extern PrefixedLogger server_log;
+extern PrefixedLogger static_game_data_log;
+
+void set_log_levels_from_json(std::shared_ptr<JSONObject> json);

src/Main.cc

@@ -10,6 +10,7 @@
 #include <phosg/Filesystem.hh>
 #include <set>
 
+#include "Loggers.hh"
 #include "NetworkAddresses.hh"
 #include "SendCommands.hh"
 #include "DNSServer.hh"
@@ -87,11 +88,11 @@ void populate_state_from_config(shared_ptr<ServerState> 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("<local>", s->local_address);
 
@@ -99,11 +100,11 @@ void populate_state_from_config(shared_ptr<ServerState> 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("<external>", s->external_address);
 
@@ -134,15 +135,23 @@ void populate_state_from_config(shared_ptr<ServerState> s,
     s->item_tracking_enabled = true;
   }
 
+  shared_ptr<JSONObject> 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<PSOBBEncryption::KeyFile>("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,
+  config_log.info("Switched to user %s (%d:%d)",  username.c_str(), pw->pw_uid, pw->pw_gid);
-      pw->pw_gid);
 }
 
 
@@ -320,57 +328,57 @@ int main(int argc, char** argv) {
 
   shared_ptr<struct event_base> 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<DNSServer> 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<IPStackSimulator> 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;
 }

src/Map.cc

@@ -1,7 +1,9 @@
 #include "Map.hh"
 
 #include <phosg/Filesystem.hh>
+#include <phosg/Strings.hh>
 
+#include "Loggers.hh"
 #include "FileContentsCache.hh"
 
 using namespace std;
@@ -420,8 +422,8 @@ static vector<PSOEnemy> 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,
+        static_game_data_log.warning("Unknown enemy type %08" PRIX32 " %08" PRIX32,
-            map[y].skin);
+            map[y].base, map[y].skin);
         break;
       }
       if (num_clones) {

src/Player.cc

@@ -7,6 +7,7 @@
 #include <stdexcept>
 #include <phosg/Filesystem.hh>
 
+#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<SavedAccountDataBB>("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) {

src/ProxyCommands.cc

@@ -26,6 +26,7 @@
 #include <resource_file/Emulators/PPC32Emulator.hh>
 #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",
+      session.log.warning("Received subcommand %02hhX which is not implemented on the server",
-          id, data[0]);
+          data[0]);
     }
   }
 }
@@ -157,7 +159,7 @@ static HandlerResult process_server_pc_gc_patch_02_17(shared_ptr<ServerState> 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<ServerState> 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<ServerState>,
   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<ServerState>,
   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<ServerState>,
         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<ServerState>,
   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<ServerState>,
   // 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<ServerState>,
   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<ServerState>,
 
 static HandlerResult process_server_60_62_6C_6D_C9_CB(shared_ptr<ServerState>,
     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<ServerState>,
             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<ServerState>,
     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<ServerState>,
       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<ServerState>,
     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<ServerState>,
   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<ServerState>,
   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<ServerState>,
       session.lobby_players[index].guild_card_number = cmd.entries[x].lobby_data.guild_card;
       ptext<char, 0x10> 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<ServerState>,
   // 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<ServerState>,
     } 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<ServerState>,
   const auto& cmd = check_size_t<S_LeaveLobby_66_69_Ep3_E9>(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<ServerState> s,
 template <>
 HandlerResult process_client_60_62_6C_6D_C9_CB<void>(shared_ptr<ServerState>,
     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<G_SwitchStateChanged_6x05>(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();
   }
 }

src/ProxyServer.cc

@@ -22,6 +22,7 @@
 #include <phosg/Strings.hh>
 #include <phosg/Time.hh>
 
+#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<struct event_base> base,
     shared_ptr<ServerState> 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<int>(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<LinkedSession> 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::LinkedSession> 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);
   }
 }
 

src/ProxyServer.hh

@@ -195,7 +195,6 @@ private:
     static void on_error(Channel& ch, short events);
   };
 
-  PrefixedLogger log;
   std::shared_ptr<struct event_base> base;
   std::shared_ptr<ServerState> state;
   std::map<int, std::shared_ptr<ListeningSocket>> listeners;

src/Quest.cc

@@ -8,6 +8,7 @@
 #include <phosg/Random.hh>
 #include <phosg/Strings.hh>
 
+#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());
       }
     }
   }

src/ReceiveCommands.cc

@@ -10,6 +10,7 @@
 #include <phosg/Strings.hh>
 #include <phosg/Time.hh>
 
+#include "Loggers.hh"
 #include "ChatCommands.hh"
 #include "FileContentsCache.hh"
 #include "ProxyServer.hh"
@@ -92,7 +93,7 @@ void process_connect(std::shared_ptr<ServerState> s, std::shared_ptr<Client> c)
       break;
 
     default:
-      log(ERROR, "Unimplemented behavior: %" PRId64,
+      c->log.error("Unimplemented behavior: %" PRId64,
           static_cast<int64_t>(c->server_behavior));
   }
 }
@@ -528,7 +529,7 @@ void process_ep3_server_data_request(shared_ptr<ServerState> s, shared_ptr<Clien
       CommandEp3InitBegin(s, c);
       break; */
     default:
-      log(WARNING, "Unknown Episode III server data request: %02X", cmds[1].byte[0]);
+      c->log.error("Unknown Episode III server data request: %02X", cmds[1].byte[0]);
   }
 }
 
@@ -730,11 +731,12 @@ void process_menu_selection(shared_ptr<ServerState> s, shared_ptr<Client> c,
   u16string password;
   u16string unknown_a1;
 
-  if (flags == 0) {
+  uint8_t type_flags = flags & 3;
+  if (type_flags == 0) {
     const auto& cmd = check_size_t<C_MenuSelection_10_Flag00>(data);
     menu_id = cmd.menu_id;
     item_id = cmd.item_id;
-  } else if (flags == 1) {
+  } else if (type_flags == 1) {
     if (uses_unicode) {
       const auto& cmd = check_size_t<C_MenuSelection_PC_BB_10_Flag01>(data);
       menu_id = cmd.menu_id;
@@ -746,7 +748,7 @@ void process_menu_selection(shared_ptr<ServerState> s, shared_ptr<Client> c,
       item_id = cmd.item_id;
       unknown_a1 = decode_sjis(cmd.unknown_a1);
     }
-  } else if (flags == 2) {
+  } else if (type_flags == 2) {
     if (uses_unicode) {
       const auto& cmd = check_size_t<C_MenuSelection_PC_BB_10_Flag02>(data);
       menu_id = cmd.menu_id;
@@ -758,7 +760,7 @@ void process_menu_selection(shared_ptr<ServerState> s, shared_ptr<Client> c,
       item_id = cmd.item_id;
       password = decode_sjis(cmd.password);
     }
-  } else if (flags == 3) {
+  } else if (type_flags == 3) {
     if (uses_unicode) {
       const auto& cmd = check_size_t<C_MenuSelection_PC_BB_10_Flag03>(data);
       menu_id = cmd.menu_id;
@@ -773,7 +775,7 @@ void process_menu_selection(shared_ptr<ServerState> s, shared_ptr<Client> c,
       password = decode_sjis(cmd.password);
     }
   } else {
-    throw runtime_error("invalid flag");
+    throw logic_error("invalid type flag");
   }
 
   switch (menu_id) {
@@ -949,7 +951,9 @@ void process_menu_selection(shared_ptr<ServerState> s, shared_ptr<Client> c,
         }
       }
 
-      s->change_client_lobby(c, game);
+      if (!s->change_client_lobby(c, game)) {
+        throw logic_error("client cannot join game after all preconditions satisfied");
+      }
       c->flags |= Client::Flag::LOADING;
       break;
     }
@@ -1109,20 +1113,37 @@ void process_change_lobby(shared_ptr<ServerState> s, shared_ptr<Client> c,
     return;
   }
 
-  shared_ptr<Lobby> new_lobby;
+  // If the client isn't in any lobby, then they just left a game. Ignore their
-  try {
+  // selection and add them to any lobby with room. If they're already in a
-    new_lobby = s->find_lobby(cmd.item_id);
+  // lobby, then they used the lobby teleporter - add them to a specific lobby.
-  } catch (const out_of_range&) {
+  if (c->lobby_id == 0) {
-    send_lobby_message_box(c, u"$C6Can't change lobby\n\n$C7The lobby does not\nexist.");
+    shared_ptr<Lobby> new_lobby;
-    return;
+    try {
-  }
+      new_lobby = s->find_lobby(cmd.item_id);
+    } catch (const out_of_range&) { }
 
-  if ((new_lobby->flags & Lobby::Flag::EPISODE_3_ONLY) && !(c->flags & Client::Flag::EPISODE_3)) {
+    s->add_client_to_available_lobby(c, new_lobby);
-    send_lobby_message_box(c, u"$C6Can't change lobby\n\n$C7The lobby is for\nEpisode 3 only.");
-    return;
-  }
 
-  s->change_client_lobby(c, new_lobby);
+  // If the client already is in a lobby, then they're using the lobby
+  // teleporter; add them to the lobby they requested or send a failure message.
+  } else {
+    shared_ptr<Lobby> new_lobby;
+    try {
+      new_lobby = s->find_lobby(cmd.item_id);
+    } catch (const out_of_range&) {
+      send_lobby_message_box(c, u"$C6Can't change lobby\n\n$C7The lobby does not\nexist.");
+      return;
+    }
+
+    if ((new_lobby->flags & Lobby::Flag::EPISODE_3_ONLY) && !(c->flags & Client::Flag::EPISODE_3)) {
+      send_lobby_message_box(c, u"$C6Can't change lobby\n\n$C7The lobby is for\nEpisode 3 only.");
+      return;
+    }
+
+    if (!s->change_client_lobby(c, new_lobby)) {
+      send_lobby_message_box(c, u"$C6Can\'t change lobby\n\n$C7The lobby is full.");
+    }
+  }
 }
 
 void process_game_list_request(shared_ptr<ServerState> s, shared_ptr<Client> c,
@@ -1376,38 +1397,46 @@ void process_player_data(shared_ptr<ServerState> s, shared_ptr<Client> c,
     c->channel.name = remove_language_marker(encode_sjis(player->disp.name));
   }
 
-  if (command == 0x61 && !c->pending_bb_save_username.empty()) {
+  // 98 should only be sent when leaving a game, and we should leave the client
-    string prev_bb_username = c->game_data.bb_username;
+  // in no lobby (they will send an 84 soon afterward to choose a lobby).
-    size_t prev_bb_player_index = c->game_data.bb_player_index;
+  if (command == 0x98) {
+    s->remove_client_from_lobby(c);
 
-    c->game_data.bb_username = c->pending_bb_save_username;
+  } else if (command == 0x61) {
-    c->game_data.bb_player_index = c->pending_bb_save_player_index;
+    if (!c->pending_bb_save_username.empty()) {
+      string prev_bb_username = c->game_data.bb_username;
+      size_t prev_bb_player_index = c->game_data.bb_player_index;
 
-    bool failure = false;
+      c->game_data.bb_username = c->pending_bb_save_username;
-    try {
+      c->game_data.bb_player_index = c->pending_bb_save_player_index;
-      c->game_data.save_player_data();
+
-    } catch (const exception& e) {
+      bool failure = false;
-      u16string buffer = u"$C6PSOBB player data could\nnot be saved:\n" + decode_sjis(e.what());
+      try {
-      send_text_message(c, buffer.c_str());
+        c->game_data.save_player_data();
-      failure = true;
+      } catch (const exception& e) {
+        u16string buffer = u"$C6PSOBB player data could\nnot be saved:\n" + decode_sjis(e.what());
+        send_text_message(c, buffer.c_str());
+        failure = true;
+      }
+
+      if (!failure) {
+        send_text_message_printf(c,
+            "$C6BB player data saved\nas player %hhu for user\n%s",
+            static_cast<uint8_t>(c->pending_bb_save_player_index + 1),
+            c->pending_bb_save_username.c_str());
+      }
+
+      c->game_data.bb_username = prev_bb_username;
+      c->game_data.bb_player_index = prev_bb_player_index;
+
+      c->pending_bb_save_username.clear();
     }
 
-    if (!failure) {
+    // We use 61 during the lobby server init sequence to trigger joining an
-      send_text_message_printf(c,
+    // available lobby
-          "$C6BB player data saved\nas player %hhu for user\n%s",
+    if (!c->lobby_id && (c->server_behavior == ServerBehavior::LOBBY_SERVER)) {
-          static_cast<uint8_t>(c->pending_bb_save_player_index + 1),
+      s->add_client_to_available_lobby(c);
-          c->pending_bb_save_username.c_str());
     }
-
-    c->game_data.bb_username = prev_bb_username;
-    c->game_data.bb_player_index = prev_bb_player_index;
-
-    c->pending_bb_save_username.clear();
-  }
-
-  // if the client isn't in a lobby, add them to an available lobby
-  if (!c->lobby_id && (c->server_behavior == ServerBehavior::LOBBY_SERVER)) {
-    s->add_client_to_available_lobby(c);
   }
 }
 
@@ -1514,7 +1543,6 @@ void process_player_preview_request_bb(shared_ptr<ServerState>, shared_ptr<Clien
 
     } catch (const exception& e) {
       // Player doesn't exist
-      log(INFO, "[BB debug] No player in slot: %s", e.what());
       send_player_preview_bb(c, cmd.player_index, nullptr);
     }
   }
@@ -1809,7 +1837,7 @@ shared_ptr<Lobby> create_game_generic(shared_ptr<ServerState> s,
 
   bool item_tracking_enabled = (c->version == GameVersion::BB) | s->item_tracking_enabled;
 
-  shared_ptr<Lobby> game(new Lobby());
+  shared_ptr<Lobby> game = s->create_lobby();
   game->name = name;
   game->password = password;
   game->version = c->version;
@@ -1866,10 +1894,10 @@ shared_ptr<Lobby> create_game_generic(shared_ptr<ServerState> 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());
         }
       }
     }
@@ -1896,6 +1924,9 @@ shared_ptr<Lobby> create_game_generic(shared_ptr<ServerState> s,
     }
   }
 
+  s->change_client_lobby(c, game);
+  c->flags |= Client::Flag::LOADING;
+
   return game;
 }
 
@@ -1903,12 +1934,8 @@ void process_create_game_pc(shared_ptr<ServerState> s, shared_ptr<Client> c,
     uint16_t, uint32_t, const string& data) { // C1
   const auto& cmd = check_size_t<C_CreateGame_PC_C1>(data);
 
-  auto game = create_game_generic(s, c, cmd.name, cmd.password, 1,
+  create_game_generic(s, c, cmd.name, cmd.password, 1,
       cmd.difficulty, cmd.battle_mode, cmd.challenge_mode, 0);
-
-  s->add_lobby(game);
-  s->change_client_lobby(c, game);
-  c->flags |= Client::Flag::LOADING;
 }
 
 void process_create_game_dc_gc(shared_ptr<ServerState> s, shared_ptr<Client> c,
@@ -1932,24 +1959,16 @@ void process_create_game_dc_gc(shared_ptr<ServerState> s, shared_ptr<Client> c,
   u16string name = decode_sjis(cmd.name);
   u16string password = decode_sjis(cmd.password);
 
-  auto game = create_game_generic(s, c, name.c_str(), password.c_str(),
+  create_game_generic(s, c, name.c_str(), password.c_str(),
       episode, cmd.difficulty, cmd.battle_mode, cmd.challenge_mode, 0);
-
-  s->add_lobby(game);
-  s->change_client_lobby(c, game);
-  c->flags |= Client::Flag::LOADING;
 }
 
 void process_create_game_bb(shared_ptr<ServerState> s, shared_ptr<Client> c,
     uint16_t, uint32_t, const string& data) { // C1
   const auto& cmd = check_size_t<C_CreateGame_BB_C1>(data);
 
-  auto game = create_game_generic(s, c, cmd.name, cmd.password, cmd.episode,
+  create_game_generic(s, c, cmd.name, cmd.password, cmd.episode,
       cmd.difficulty, cmd.battle_mode, cmd.challenge_mode, cmd.solo_mode);
-
-  s->add_lobby(game);
-  s->change_client_lobby(c, game);
-  c->flags |= Client::Flag::LOADING;
 }
 
 void process_lobby_name_request(shared_ptr<ServerState> s, shared_ptr<Client> c,
@@ -2070,9 +2089,9 @@ independently.\r\n\
 void process_ignored_command(shared_ptr<ServerState>, shared_ptr<Client>,
     uint16_t, uint32_t, const string&) { }
 
-void process_unimplemented_command(shared_ptr<ServerState>, shared_ptr<Client>,
+void process_unimplemented_command(shared_ptr<ServerState>,
-    uint16_t command, uint32_t flag, const string& data) {
+    shared_ptr<Client> c, uint16_t command, uint32_t flag, const string& data) {
-  log(WARNING, "Unknown command: size=%04zX command=%04hX flag=%08" PRIX32 "\n",
+  c->log.warning("Unknown command: size=%04zX command=%04hX flag=%08" PRIX32 "\n",
       data.size(), command, flag);
   throw invalid_argument("unimplemented command");
 }

src/ReceiveSubcommands.cc

@@ -5,6 +5,7 @@
 #include <memory>
 #include <phosg/Strings.hh>
 
+#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<ServerState>,
   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<ServerState>,
     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->log.info("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());
+        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<ServerState>,
     item.data = cmd->item;
     c->game_data.player()->add_item(item);
 
-    log(INFO, "[Items/%08" PRIX32 "] Player %hhu created inventory item %08" PRIX32,
+    l->log.info("Player %hhu created inventory item %08" PRIX32,
-        l->lobby_id, cmd->client_id, cmd->item.id.load());
+        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<ServerState>,
     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->log.info("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());
+        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<ServerState>,
 
     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->log.info("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(),
+        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<ServerState>,
     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->log.info("Player %hhu bought item %08" PRIX32 " from shop",
-        l->lobby_id, cmd->client_id, item.data.id.load());
+        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<ServerState>,
   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->log.info("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());
+      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<ServerState>,
 
   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->log.info("Player %hu picked up %08" PRIX32,
-        l->lobby_id, cmd->client_id.load(), cmd->item_id.load());
+        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<ServerState>,
 
     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->log.info("Player %hhu picked up %08" PRIX32, cmd->client_id, cmd->item_id.load());
-        l->lobby_id, 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<ServerState>,
     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->log.info("Player used item %hhu:%08" PRIX32, cmd->client_id, cmd->item_id.load());
-        l->lobby_id, 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<ServerState>,
   }
   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->log.info("Inventory item %hhu:%08" PRIX32 " destroyed (%" PRIX32 " of them)",
-        l->lobby_id, cmd->client_id, cmd->item_id.load(), cmd->amount.load());
+        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<ServerState>,
   }
   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->log.info("Ground item %08" PRIX32 " destroyed (%" PRIX32 " of them)",
-        l->lobby_id, cmd->item_id.load(), cmd->amount.load());
+        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<ServerStat
 }
 
 static void process_subcommand_invalid(shared_ptr<ServerState>,
-    shared_ptr<Lobby>, shared_ptr<Client>, uint8_t command, uint8_t flag,
+    shared_ptr<Lobby>, shared_ptr<Client> 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<ServerState>,
-    shared_ptr<Lobby>, shared_ptr<Client>, uint8_t command, uint8_t flag,
+    shared_ptr<Lobby>, shared_ptr<Client> 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]);
   }
 }
 

src/Server.cc

@@ -20,6 +20,7 @@
 #include <phosg/Strings.hh>
 #include <phosg/Time.hh>
 
+#include "Loggers.hh"
 #include "PSOProtocol.hh"
 #include "ReceiveCommands.hh"
 
@@ -30,10 +31,10 @@ using namespace std::placeholders;
 
 void Server::disconnect_client(shared_ptr<Client> 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<Client> 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<Client> 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<struct event_base> base,
     shared_ptr<ServerState> 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);
 }

src/Server.hh

@@ -32,7 +32,6 @@ public:
   std::shared_ptr<Client> get_client() const;
 
 private:
-  PrefixedLogger log;
   std::shared_ptr<struct event_base> base;
 
   struct ListeningSocket {

src/ServerState.cc

@@ -5,6 +5,7 @@
 #include <memory>
 #include <phosg/Network.hh>
 
+#include "Loggers.hh"
 #include "IPStackSimulator.hh"
 #include "NetworkAddresses.hh"
 #include "SendCommands.hh"
@@ -28,14 +29,13 @@ ServerState::ServerState()
     auto lobby_name = decode_sjis(string_printf("LOBBY%zu", x + 1));
     bool is_ep3_only = (x > 14);
 
-    shared_ptr<Lobby> l(new Lobby());
+    shared_ptr<Lobby> l = this->create_lobby();
     l->flags |= Lobby::Flag::PUBLIC | Lobby::Flag::DEFAULT | Lobby::Flag::PERSISTENT |
         (is_ep3_only ? Lobby::Flag::EPISODE_3_ONLY : 0);
     l->block = x + 1;
     l->type = x;
     l->name = lobby_name;
     l->max_clients = 12;
-    this->add_lobby(l);
 
     if (!is_ep3_only) {
       this->public_lobby_search_order.emplace_back(l);
@@ -51,20 +51,30 @@ ServerState::ServerState()
       ep3_only_lobbies.end());
 }
 
-void ServerState::add_client_to_available_lobby(shared_ptr<Client> c) {
+void ServerState::add_client_to_available_lobby(
-  const auto& search_order = (c->flags & Client::Flag::EPISODE_3)
+    shared_ptr<Client> c, shared_ptr<Lobby> preferred_lobby) {
-      ? this->public_lobby_search_order_ep3
-      : this->public_lobby_search_order;
-
   shared_ptr<Lobby> added_to_lobby;
-  for (const auto& l : search_order) {
+
+  if (preferred_lobby) {
     try {
-      l->add_client(c);
+      preferred_lobby->add_client(c);
-      added_to_lobby = l;
+      added_to_lobby = preferred_lobby;
-      break;
     } catch (const out_of_range&) { }
   }
 
+  if (!added_to_lobby.get()) {
+    const auto& search_order = (c->flags & Client::Flag::EPISODE_3)
+        ? this->public_lobby_search_order_ep3
+        : this->public_lobby_search_order;
+    for (const auto& l : search_order) {
+      try {
+        l->add_client(c);
+        added_to_lobby = l;
+        break;
+      } catch (const out_of_range&) { }
+    }
+  }
+
   if (!added_to_lobby) {
     // TODO: Add the user to a dynamically-created private lobby instead
     throw out_of_range("all lobbies full");
@@ -84,7 +94,7 @@ void ServerState::remove_client_from_lobby(shared_ptr<Client> c) {
   }
 }
 
-void ServerState::change_client_lobby(shared_ptr<Client> c, shared_ptr<Lobby> new_lobby) {
+bool ServerState::change_client_lobby(shared_ptr<Client> c, shared_ptr<Lobby> new_lobby) {
   uint8_t old_lobby_client_id = c->lobby_client_id;
 
   shared_ptr<Lobby> current_lobby = this->find_lobby(c->lobby_id);
@@ -95,8 +105,7 @@ void ServerState::change_client_lobby(shared_ptr<Client> c, shared_ptr<Lobby> ne
       new_lobby->add_client(c);
     }
   } catch (const out_of_range&) {
-    send_lobby_message_box(c, u"$C6Can't change lobby\n\n$C7The lobby is full.");
+    return false;
-    return;
   }
 
   if (current_lobby) {
@@ -107,6 +116,7 @@ void ServerState::change_client_lobby(shared_ptr<Client> c, shared_ptr<Lobby> ne
     }
   }
   this->send_lobby_join_notifications(new_lobby, c);
+  return true;
 }
 
 void ServerState::send_lobby_join_notifications(shared_ptr<Lobby> l,
@@ -134,16 +144,22 @@ vector<shared_ptr<Lobby>> ServerState::all_lobbies() {
   return ret;
 }
 
-void ServerState::add_lobby(shared_ptr<Lobby> l) {
+shared_ptr<Lobby> ServerState::create_lobby() {
-  l->lobby_id = this->next_lobby_id++;
+  shared_ptr<Lobby> l(new Lobby(this->next_lobby_id++));
-  if (this->id_to_lobby.count(l->lobby_id)) {
+  if (!this->id_to_lobby.emplace(l->lobby_id, l).second) {
     throw logic_error("lobby already exists with the given id");
   }
-  this->id_to_lobby.emplace(l->lobby_id, l);
+  l->log.info("Created lobby");
+  return l;
 }
 
 void ServerState::remove_lobby(uint32_t lobby_id) {
-  this->id_to_lobby.erase(lobby_id);
+  auto lobby_it = this->id_to_lobby.find(lobby_id);
+  if (lobby_it == this->id_to_lobby.end()) {
+    throw logic_error("attempted to remove nonexistent lobby");
+  }
+  lobby_it->second->log.info("Deleted lobby");
+  this->id_to_lobby.erase(lobby_it);
 }
 
 shared_ptr<Client> ServerState::find_client(const std::u16string* identifier,
@@ -300,7 +316,7 @@ void ServerState::create_menus(shared_ptr<const JSONObject> 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 +329,7 @@ void ServerState::create_menus(shared_ptr<const JSONObject> 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;

src/ServerState.hh

@@ -74,6 +74,9 @@ struct ServerState {
   std::map<int64_t, std::shared_ptr<Lobby>> id_to_lobby;
   std::vector<std::shared_ptr<Lobby>> public_lobby_search_order;
   std::vector<std::shared_ptr<Lobby>> public_lobby_search_order_ep3;
+  // TODO: Use a free-list instead of an incrementer to prevent wrap-around
+  // behavioral bugs. This... will probably never be an issue for anyone, but we
+  // technically should handle it.
   std::atomic<int32_t> next_lobby_id;
   uint8_t pre_lobby_event;
   int32_t ep3_menu_song;
@@ -87,9 +90,10 @@ struct ServerState {
 
   ServerState();
 
-  void add_client_to_available_lobby(std::shared_ptr<Client> c);
+  void add_client_to_available_lobby(std::shared_ptr<Client> c,
+      std::shared_ptr<Lobby> preferred_lobby = nullptr);
   void remove_client_from_lobby(std::shared_ptr<Client> c);
-  void change_client_lobby(std::shared_ptr<Client> c,
+  bool change_client_lobby(std::shared_ptr<Client> c,
       std::shared_ptr<Lobby> new_lobby);
 
   void send_lobby_join_notifications(std::shared_ptr<Lobby> l,
@@ -98,7 +102,7 @@ struct ServerState {
   std::shared_ptr<Lobby> find_lobby(uint32_t lobby_id);
   std::vector<std::shared_ptr<Lobby>> all_lobbies();
 
-  void add_lobby(std::shared_ptr<Lobby> l);
+  std::shared_ptr<Lobby> create_lobby();
   void remove_lobby(uint32_t lobby_id);
 
   std::shared_ptr<Client> find_client(

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