Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Change: reworked the debug levels for network facility #9251

Merged
merged 1 commit into from May 12, 2021

Conversation

TrueBrain
Copy link
Member

@TrueBrain TrueBrain commented May 12, 2021

Motivation / Problem

Running a dedicated server shows a lot of information that is not all that relevant.

Also, during working on the STUN patch, I noticed that often I saw too much debugging, or not enough.

After reading #9171 I came to realisation we have been trying to do "our own thing" instead of looking to the world. That gave me inspiration to just use the default: fatal / error / warning / info / debug / trace setup. This PR implements that.

Description

It now follows very simple rules:
0 - Fatal, user should know about this
1 - Error, but we are recovering
2 - Warning, wrong but okay if you don't know
3 - Info, information you might care about
4 -
5 - Debug #1 - High level debug messages
6 - Debug #2 - Low level debug messages
7 - Trace information

I also applied some consistency to all strings:

  • Start with a capital.
  • Use : %s for error instead of all the combinations we had (with error, failed with, ...).
  • Removed prefixes like [udp] which don't really mean anything.

Also:

  • Changed the debug logging level of dedicated servers to be 4 (so no debug-messages).
  • Moved some DEBUG statements to the desync facility, as it had little to do with net.

Limitations

Checklist for review

Some things are not automated, and forgotten often. This list is a reminder for the reviewers.

  • The bug fix is important enough to be backported? (label: 'backport requested')
  • This PR affects the save game format? (label 'savegame upgrade')
  • This PR affects the GS/AI API? (label 'needs review: Script API')
    • ai_changelog.hpp, gs_changelog.hpp need updating.
    • The compatibility wrappers (compat_*.nut) need updating.
  • This PR affects the NewGRF API? (label 'needs review: NewGRF')

Complete list of debug messages on net facility

In case you find it easier to read the full list of messages we now have, here you go, sorted by level:

(net, 0, "  This is likely an issue in the DNS name resolver's configuration causing it to time out");
(net, 0, "  This savegame cannot be used for multiplayer");
(net, 0, "  please allow udp and tcp packets from port %u to be delivered", _settings_client.network.server_port);
(net, 0, "  please allow udp and tcp packets to port %u to be delivered", _settings_client.network.server_port);
(net, 0, "  please allow udp packets from %s to you to be delivered", out_addr.GetAddressAsString(false).c_str());
(net, 0, "  please allow udp packets from you to %s to be delivered", out_addr.GetAddressAsString(false).c_str());
(net, 0, "  this is likely an issue in the DNS name resolver's configuration causing it to time out");
(net, 0, "  this usually means that the master server cannot reach us");
(net, 0, "  we are not receiving the acknowledgement from the server");
(net, 0, "  we are not receiving the session key from the server");
(net, 0, "%s background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.", name.c_str());
(net, 0, "Advertising to the master server is failing");
(net, 0, "Advertising to the master server is failing");
(net, 0, "Could not bind socket on %s: %s", address.c_str(), NetworkError::GetLast().AsString());
(net, 0, "Could not create %s %s socket: %s", NetworkAddress::SocketTypeAsString(address->ai_socktype), NetworkAddress::AddressFamilyAsString(address->ai_family), NetworkError::GetLast().AsString());
(net, 0, "Could not create %s %s socket: %s", type, family, NetworkError::GetLast().AsString());
(net, 0, "Could not create socket: %s", NetworkError::GetLast().AsString());
(net, 0, "Could not listen on socket: %s", NetworkError::GetLast().AsString());
(net, 0, "Could not start network: could not create listening socket");
(net, 0, "Error running _netstat()");
(net, 0, "Failed to open connection to %s for redirecting DEBUG()", this->connection_string.c_str());
(net, 0, "Failed to resolve DNS for %s", this->connection_string.c_str());
(net, 0, "Generating map failed; closing server");
(net, 0, "Loading game failed, so a new (random) game will be started");
(net, 0, "Loading requested map failed; closing server.");
(net, 0, "Recv failed: %s", err.AsString());
(net, 0, "Recv failed: %s", err.AsString());
(net, 0, "Recv failed: %s", err.AsString());
(net, 0, "Send failed: %s", err.AsString());
(net, 0, "Setting non-blocking mode failed: %s", NetworkError::GetLast().AsString());
(net, 0, "Setting non-blocking mode failed: %s", NetworkError::GetLast().AsString());
(net, 0, "Setting reuse-address mode failed: %s", NetworkError::GetLast().AsString());
(net, 0, "Sync error detected");
(net, 0, "The loading savegame was paused due to an error state");
(net, 0, "Timeout while connecting to %s", this->connection_string.c_str());
(net, 0, "Unknown callback for command; no callback sent (command: %d)", cp->cmd);
(net, 0, "WSAStartup failed, network unavailable");
(net, 0, "[%s] send failed: %s", Tsocket::GetName(), NetworkError::GetLast().AsString());
(net, 0, "[%s] send failed: %s", Tsocket::GetName(), NetworkError::GetLast().AsString());
(net, 0, "[tcp/admin] Received illegal packet from '%s' (%s)", this->admin_name, this->admin_version);
(net, 0, "[tcp/admin] Received illegal packet type %d from admin %s (%s)", type, this->admin_name, this->admin_version);
(net, 0, "[tcp/admin] Received invalid packet type %d from '%s' (%s)", type, this->admin_name, this->admin_version);
(net, 0, "[tcp/content] Received illegal packet type %d", type);
(net, 0, "[tcp/content] Received illegal packet");
(net, 0, "[tcp/content] Received invalid packet type %d", type);
(net, 0, "[tcp/game] Received illegal packet from client %d", this->client_id);
(net, 0, "[tcp/game] Received illegal packet type %d from client %d", type, this->client_id);
(net, 0, "[tcp/game] Received invalid packet type %d from client %d", type, this->client_id);
(net, 0, "[udp] Received illegal packet from %s", client_addr->GetAddressAsString().c_str());
(net, 0, "[udp] Received invalid packet type %d from %s", type, client_addr->GetAddressAsString().c_str());
(net, 0, "[udp] Received packet type %d on wrong port from %s", type, client_addr->GetAddressAsString().c_str());
(net, 0, "getaddrinfo for hostname \"%s\", port %s, address family %s and socket type %s failed: %s",
(net, 0, "getaddrinfo for hostname \"%s\", port %s, address family %s and socket type %s took %i seconds",
(net, 0, "getaddrinfo() for address \"%s\" took %i seconds", this->connection_string.c_str(), (int)duration.count());
(net, 1, "'%s' made an error and has been disconnected: %s", client_name, str);
(net, 1, "'%s' reported an error and is closing its connection: %s", client_name, str);
(net, 1, "Client %d made an error and has been disconnected: %s", this->client_id, str);
(net, 1, "Could not connect to %s: %s", network_address.GetAddressAsString().c_str(), NetworkError::GetLast().AsString());
(net, 1, "Could not connect to %s: %s", this->sock_to_address[*it].GetAddressAsString().c_str(), socket_error.AsString());
(net, 1, "Missed frame for sync-test: %d / %d", _sync_frame, _frame_counter);
(net, 1, "No \"client_name\" has been set, using \"%s\" instead. Please set this now using the \"name <new name>\" command", fallback_client_name);
(net, 1, "No \"server_name\" has been set, using \"%s\" instead. Please set this now using the \"server_name <new name>\" command", fallback_server_name);
(net, 1, "Received a packet with mismatching size from %s", address.GetAddressAsString().c_str());
(net, 1, "Received invalid client index = 0");
(net, 1, "Received unknown chat destination type %d; doing broadcast instead", desttype);
(net, 1, "Setting TCP_NODELAY failed: %s", NetworkError::GetLast().AsString());
(net, 1, "Setting broadcast mode failed: %s", NetworkError::GetLast().AsString());
(net, 1, "Setting no-delay mode failed: %s", NetworkError::GetLast().AsString());
(net, 1, "Unknown client (%d) is leaving the game", client_id);
(net, 1, "[admin] Empty company given for update");
(net, 1, "[admin] Invalid chat action %d from admin '%s' (%s).", action, this->admin_name, this->admin_version);
(net, 1, "[admin] Not supported poll %d (%d) from '%s' (%s).", type, d1, this->admin_name, this->admin_version);
(net, 1, "[admin] Not supported update frequency %d (%d) from '%s' (%s)", type, freq, this->admin_name, this->admin_version);
(net, 1, "[admin] The admin '%s' (%s) made an error and has been disconnected: '%s'", this->admin_name, this->admin_version, str);
(net, 1, "[rcon] Wrong password from client-id %d", this->client_id);
(net, 1, "[tcp/http] Header too big");
(net, 1, "[tcp/http] Unhandled status reply %s", status);
(net, 1, "select() failed: %s", NetworkError::GetLast().AsString());
(net, 1, "sendto(%s) failed: %s", send.GetAddressAsString().c_str(), NetworkError::GetLast().AsString());
(net, 1, msg); return -1; }
(net, 2, "Wrong password from client-id #%d for company #%d", this->client_id, company_id + 1);
(net, 2, "[%s] Banned ip tried to join (%s), refused", Tsocket::GetName(), entry.c_str());
(net, 2, "[admin] Admin did not send its authorisation within %d seconds", (uint32)std::chrono::duration_cast<std::chrono::seconds>(ADMIN_AUTHORISATION_TIMEOUT).count());
(net, 3, " %d) %s", i++, addr.GetHostname());
(net, 3, "Advertising on master server successful (%s)", NetworkAddress::AddressFamilyAsString(client_addr->GetAddress()->ss_family));
(net, 3, "Advertising to master server");
(net, 3, "Auto-restarting map: year %d reached", _cur_year);
(net, 3, "Closed client connection %d", this->client_id);
(net, 3, "Closed client connection %d", this->client_id);
(net, 3, "Connected to %s", this->connection_string.c_str());
(net, 3, "Could not disable IPv4 over IPv6: %s", NetworkError::GetLast().AsString());
(net, 3, "Detected broadcast addresses:");
(net, 3, "Generating map, please wait...");
(net, 3, "Initializing UDP listeners");
(net, 3, "Listening on %s", address.c_str());
(net, 3, "Map generated, starting game");
(net, 3, "Map generation percentage complete: %d", _gws.percent);
(net, 3, "Network online, multiplayer available");
(net, 3, "Network revision name: %s", network_revision);
(net, 3, "Network revision name: %s", network_revision);
(net, 3, "Performing emergency save: %s", filename);
(net, 3, "Redirecting DEBUG() to %s", this->connection_string.c_str());
(net, 3, "Removing advertise from master server");
(net, 3, "Searching server");
(net, 3, "Server response from %s", client_addr->GetAddressAsString().c_str());
(net, 3, "Shutting down network");
(net, 3, "Starting dedicated server, version %s", _openttd_revision);
(net, 3, "Starting network");
(net, 3, "[%s] Client connected from %s on frame %d", Tsocket::GetName(), address.GetHostname(), _frame_counter);
(net, 3, "[admin] '%s' (%s) has connected", this->admin_name, this->admin_version);
(net, 3, "[admin] '%s' (%s) has disconnected", this->admin_name, this->admin_version);
(net, 3, "[admin] Rcon command from '%s' (%s): %s", this->admin_name, this->admin_version, command);
(net, 3, "[rcon] Client-id %d executed: %s", this->client_id, command);
(net, 5, "- using %s", NetworkAddress::GetPeerName(connected_socket).c_str());
(net, 5, "Attempting to connect to %s", network_address.GetAddressAsString().c_str());
(net, 5, "Broadcasting to %s", addr.GetHostname());
(net, 5, "Closed UDP listeners");
(net, 5, "Loading windows socket library");
(net, 5, "Starting listeners for admins");
(net, 5, "Starting listeners for clients");
(net, 5, "Starting listeners for incoming server queries");
(net, 5, "[%s] Closed listeners", Tsocket::GetName());
(net, 5, "[tcp/http] Requesting %s%s", host, url);
(net, 6, "%s resolved in:", this->connection_string.c_str());
(net, 6, "- %s", NetworkAddress(address->ai_addr, (int)address->ai_addrlen).GetAddressAsString().c_str());
(net, 6, "Master server queried at %s", out_addr.GetAddressAsString().c_str());
(net, 6, "Received new session key from master server (%s)", NetworkAddress::AddressFamilyAsString(client_addr->GetAddress()->ss_family));
(net, 6, "[admin] GameScript JSON from '%s' (%s): %s", this->admin_name, this->admin_version, json);
(net, 6, "[admin] Ping from '%s' (%s): %d", this->admin_name, this->admin_version, d1);
(net, 7, "NewGRF data reply from %s", client_addr->GetAddressAsString().c_str());
(net, 7, "NewGRF data request from %s", client_addr->GetAddressAsString().c_str());
(net, 7, "Queried from %s", client_addr->GetHostname());
(net, 7, "Received FRAME %d", _frame_counter_server);
(net, 7, "Sent ACK at %d", _frame_counter);
(net, 7, "[tcp/http] Downloading %i bytes", len);
(net, 7, "[tcp/http] Redirecting to %s", uri);
(net, 7, "sendto(%s)", send.GetAddressAsString().c_str());

@TrueBrain TrueBrain force-pushed the network-debug-level branch 2 times, most recently from 50f3386 to fca620f Compare May 12, 2021 11:58
It now follows very simple rules:
0 - Fatal, user should know about this
1 - Error, but we are recovering
2 - Warning, wrong but okay if you don't know
3 - Info, information you might care about
4 -
5 - Debug #1 - High level debug messages
6 - Debug #2 - Low level debug messages
7 - Trace information
@TrueBrain TrueBrain merged commit b136e65 into OpenTTD:master May 12, 2021
@TrueBrain TrueBrain deleted the network-debug-level branch May 12, 2021 14:34
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

2 participants