split logging into multiple classes with configurable levels

This commit is contained in:
Martin Michelsen
2022-06-26 22:53:11 -07:00
parent 47f97f357f
commit 6b958c9f25
26 changed files with 297 additions and 225 deletions
+1
View File
@@ -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
+7 -5
View File
@@ -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;
}
+2 -1
View File
@@ -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>,
+3 -1
View File
@@ -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),
+2
View File
@@ -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;
+3 -2
View File
@@ -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 {
+7 -6
View File
@@ -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;
+9 -8
View File
@@ -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());
}
}
}
+35 -38
View File
@@ -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",
fd, listen_fd);
ip_stack_simulator_log.info("Client fd %d connected via fd %d", fd, listen_fd);
struct bufferevent *bev = bufferevent_socket_new(this->base.get(), fd,
BEV_OPT_CLOSE_ON_FREE | BEV_OPT_DEFER_CALLBACKS);
@@ -182,7 +181,7 @@ void IPStackSimulator::dispatch_on_listen_error(
void IPStackSimulator::on_listen_error(struct evconnlistener* listener) {
int err = EVUTIL_SOCKET_ERROR();
this->log(ERROR, "Failure on listening socket %d: %d (%s)",
ip_stack_simulator_log.error("Failure on listening socket %d: %d (%s)",
evconnlistener_get_fd(listener), err, evutil_socket_error_to_string(err));
event_base_loopexit(this->base.get(), nullptr);
}
@@ -202,7 +201,7 @@ void IPStackSimulator::on_client_input(struct bufferevent* bev) {
c = this->bev_to_client.at(bev);
} catch (const out_of_range&) {
size_t bytes = evbuffer_get_length(buf);
this->log(ERROR, "Ignoring data received from unregistered client (0x%zX bytes)",
ip_stack_simulator_log.warning("Ignoring data received from unregistered client (0x%zX bytes)",
bytes);
evbuffer_drain(buf, bytes);
return;
@@ -223,7 +222,7 @@ void IPStackSimulator::on_client_input(struct bufferevent* bev) {
this->on_client_frame(c, frame);
} catch (const exception& e) {
if (this->state->ip_stack_debug) {
this->log(WARNING, "Failed to process client frame: %s", e.what());
ip_stack_simulator_log.warning("Failed to process client frame: %s", e.what());
print_data(stderr, frame);
}
}
@@ -238,13 +237,11 @@ void IPStackSimulator::on_client_error(struct bufferevent* bev,
short events) {
if (events & BEV_EVENT_ERROR) {
int err = EVUTIL_SOCKET_ERROR();
this->log(WARNING, "Client caused error %d (%s)", err,
ip_stack_simulator_log.warning("Client caused error %d (%s)", err,
evutil_socket_error_to_string(err));
}
if (events & (BEV_EVENT_EOF | BEV_EVENT_ERROR)) {
this->log(INFO, "Client fd %d disconnected",
bufferevent_getfd(bev));
ip_stack_simulator_log.info("Client fd %d disconnected", bufferevent_getfd(bev));
this->bev_to_client.erase(bev);
}
}
@@ -255,7 +252,7 @@ void IPStackSimulator::on_client_frame(
shared_ptr<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));
}
-1
View File
@@ -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;
+2 -1
View File
@@ -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());
}
}
+1
View File
@@ -4,6 +4,7 @@
#include <phosg/Random.hh>
#include "Loggers.hh"
#include "SendCommands.hh"
#include "Text.hh"
+3 -1
View File
@@ -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;
+36 -28
View File
@@ -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,
pw->pw_gid);
config_log.info("Switched to user %s (%d:%d)", username.c_str(), pw->pw_uid, pw->pw_gid);
}
@@ -320,57 +328,57 @@ int main(int argc, char** argv) {
shared_ptr<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;
}
+4 -2
View File
@@ -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,
map[y].skin);
static_game_data_log.warning("Unknown enemy type %08" PRIX32 " %08" PRIX32,
map[y].base, map[y].skin);
break;
}
if (num_clones) {
+6 -5
View File
@@ -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) {
+40 -38
View File
@@ -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",
id, data[0]);
session.log.warning("Received subcommand %02hhX which is not implemented on the server",
data[0]);
}
}
}
@@ -157,7 +159,7 @@ static HandlerResult process_server_pc_gc_patch_02_17(shared_ptr<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();
}
}
+29 -29
View File
@@ -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);
}
}
-1
View File
@@ -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;
+3 -2
View File
@@ -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());
}
}
}
+8 -8
View File
@@ -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]);
}
}
@@ -1514,7 +1515,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);
}
}
@@ -1866,10 +1866,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());
}
}
}
@@ -2070,9 +2070,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>,
uint16_t command, uint32_t flag, const string& data) {
log(WARNING, "Unknown command: size=%04zX command=%04hX flag=%08" PRIX32 "\n",
void process_unimplemented_command(shared_ptr<ServerState>,
shared_ptr<Client> c, uint16_t command, uint32_t flag, const string& data) {
c->log.warning("Unknown command: size=%04zX command=%04hX flag=%08" PRIX32 "\n",
data.size(), command, flag);
throw invalid_argument("unimplemented command");
}
+28 -29
View File
@@ -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->lobby_id, cmd->client_id, cmd->item_id.load(), cmd->area.load(), cmd->x.load(), cmd->z.load());
l->log.info("Player %hhu dropped item %08" PRIX32 " at %hu:(%g, %g)",
cmd->client_id, cmd->item_id.load(), cmd->area.load(), cmd->x.load(), cmd->z.load());
c->game_data.player()->print_inventory(stderr);
}
@@ -307,8 +308,8 @@ static void process_subcommand_create_inventory_item(shared_ptr<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->lobby_id, cmd->client_id, cmd->item.id.load());
l->log.info("Player %hhu created inventory item %08" PRIX32,
cmd->client_id, cmd->item.id.load());
c->game_data.player()->print_inventory(stderr);
}
@@ -338,8 +339,8 @@ static void process_subcommand_drop_partial_stack(shared_ptr<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->lobby_id, cmd->client_id, item.data.id.load(), cmd->area.load(), cmd->x.load(), cmd->z.load());
l->log.info("Player %hhu split stack to create ground item %08" PRIX32 " at %hu:(%g, %g)",
cmd->client_id, item.data.id.load(), cmd->area.load(), cmd->x.load(), cmd->z.load());
c->game_data.player()->print_inventory(stderr);
}
@@ -375,8 +376,8 @@ static void process_subcommand_drop_partial_stack_bb(shared_ptr<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->lobby_id, cmd->client_id, cmd->item_id.load(), cmd->amount.load(),
l->log.info("Player %hhu split stack %08" PRIX32 " (%" PRIu32 " of them) at %hu:(%g, %g)",
cmd->client_id, cmd->item_id.load(), cmd->amount.load(),
cmd->area.load(), cmd->x.load(), cmd->z.load());
c->game_data.player()->print_inventory(stderr);
@@ -407,8 +408,8 @@ static void process_subcommand_buy_shop_item(shared_ptr<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->lobby_id, cmd->client_id, item.data.id.load());
l->log.info("Player %hhu bought item %08" PRIX32 " from shop",
cmd->client_id, item.data.id.load());
c->game_data.player()->print_inventory(stderr);
}
@@ -434,8 +435,8 @@ static void process_subcommand_box_or_enemy_item_drop(shared_ptr<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->lobby_id, item.data.id.load(), cmd->area, cmd->x.load(), cmd->z.load());
l->log.info("Leader created ground item %08" PRIX32 " at %hhu:(%g, %g)",
item.data.id.load(), cmd->area, cmd->x.load(), cmd->z.load());
forward_subcommand(l, c, command, flag, data);
}
@@ -461,8 +462,8 @@ static void process_subcommand_pick_up_item(shared_ptr<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->lobby_id, cmd->client_id.load(), cmd->item_id.load());
l->log.info("Player %hu picked up %08" PRIX32,
cmd->client_id.load(), cmd->item_id.load());
effective_c->game_data.player()->print_inventory(stderr);
}
@@ -486,8 +487,7 @@ static void process_subcommand_pick_up_item_request(shared_ptr<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->lobby_id, cmd->client_id, cmd->item_id.load());
l->log.info("Player %hhu picked up %08" PRIX32, cmd->client_id, cmd->item_id.load());
c->game_data.player()->print_inventory(stderr);
send_pick_up_item(l, c, cmd->item_id, cmd->area);
@@ -537,8 +537,7 @@ static void process_subcommand_use_item(shared_ptr<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->lobby_id, cmd->client_id, cmd->item_id.load());
l->log.info("Player used item %hhu:%08" PRIX32, cmd->client_id, cmd->item_id.load());
c->game_data.player()->print_inventory(stderr);
}
@@ -933,8 +932,8 @@ static void process_subcommand_destroy_inventory_item(shared_ptr<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->lobby_id, cmd->client_id, cmd->item_id.load(), cmd->amount.load());
l->log.info("Inventory item %hhu:%08" PRIX32 " destroyed (%" PRIX32 " of them)",
cmd->client_id, cmd->item_id.load(), cmd->amount.load());
c->game_data.player()->print_inventory(stderr);
forward_subcommand(l, c, command, flag, data);
}
@@ -949,8 +948,8 @@ static void process_subcommand_destroy_ground_item(shared_ptr<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->lobby_id, cmd->item_id.load(), cmd->amount.load());
l->log.info("Ground item %08" PRIX32 " destroyed (%" PRIX32 " of them)",
cmd->item_id.load(), cmd->amount.load());
forward_subcommand(l, c, command, flag, data);
}
}
@@ -1085,24 +1084,24 @@ static void process_subcommand_forward_check_size_ep3_game(shared_ptr<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]);
}
}
+15 -16
View File
@@ -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);
}
-1
View File
@@ -32,7 +32,6 @@ public:
std::shared_ptr<Client> get_client() const;
private:
PrefixedLogger log;
std::shared_ptr<struct event_base> base;
struct ListeningSocket {
+3 -2
View File
@@ -5,6 +5,7 @@
#include <memory>
#include <phosg/Network.hh>
#include "Loggers.hh"
#include "IPStackSimulator.hh"
#include "NetworkAddresses.hh"
#include "SendCommands.hh"
@@ -300,7 +301,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 +314,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;
+50
View File
@@ -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