alex/valence
1
0
Fork 0
mirror of https://github.com/italicsjenga/valence.git synced 2025-01-09 22:31:30 +11:00
Code Issues Packages Projects Releases Wiki Activity

Replace log crate with tracing (#157)

Browse source 
The `tracing` crate seems to be the go-to
logging/profiling/instrumentation solution nowadays. Perhaps in the
future we could use `tracing` for profiling instead of (or in addition
to) the `perf`-based `cargo flamegraph` command. This would sidestep the
issue of `rayon` polluting the output. I conducted an initial experiment
by adding some more spans but wasn't very happy with the result.

Log messages have also been improved. There is some additional context
and events are raised when clients are added/removed from the server.
This commit is contained in:
Ryan Johnson 2022-11-16 18:22:44 -08:00 committed by GitHub
parent ab2e1081ed
commit 4226201fed
No known key found for this signature in database
GPG key ID: 4AEE18F83AFDEB23
23 changed files with 110 additions and 125 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

4
Cargo.toml
View file

@ -22,7 +22,6 @@ bytes = "1.2.1"
flume = "0.10.14"
futures = "0.3.24"
hmac = "0.12.1"
log = "0.4.17"
num = "0.4.0"
paste = "1.0.9"
rand = "0.8.5"
@ -34,6 +33,7 @@ serde_json = "1.0.85"
sha1 = "0.10.5"
sha2 = "0.10.6"
thiserror = "1.0.35"
tracing = "0.1.37"
url = { version = "2.2.2", features = ["serde"] }
uuid = { version = "1.1.2", features = ["serde"] }
valence_nbt = { version = "0.4.0", path = "valence_nbt" }
@ -51,7 +51,7 @@ default-features = false
features = ["rustls-tls", "json"]
[dev-dependencies]
env_logger = "0.9.1"
tracing-subscriber = "0.3.16"
noise = "0.7.0"
[build-dependencies]

6
examples/biomes.rs
View file

@ -2,14 +2,10 @@ use std::iter;
use std::net::SocketAddr;
use std::sync::atomic::{AtomicUsize, Ordering};
use log::LevelFilter;
use valence::prelude::*;
pub fn main() -> ShutdownResult {
env_logger::Builder::new()
.filter_module("valence", LevelFilter::Trace)
.parse_default_env()
.init();
tracing_subscriber::fmt().init();
valence::start_server(
Game {

6
examples/building.rs
View file

@ -1,16 +1,12 @@
use std::net::SocketAddr;
use std::sync::atomic::{AtomicUsize, Ordering};
use log::LevelFilter;
use num::Integer;
use valence::client::DiggingStatus;
use valence::prelude::*;
pub fn main() -> ShutdownResult {
env_logger::Builder::new()
.filter_module("valence", LevelFilter::Trace)
.parse_default_env()
.init();
tracing_subscriber::fmt().init();
valence::start_server(
Game {

8
examples/chest.rs
View file

@ -1,16 +1,12 @@
use std::net::SocketAddr;
use std::sync::atomic::{AtomicUsize, Ordering};
use log::LevelFilter;
use num::Integer;
use valence::prelude::*;
use valence_protocol::var_int::VarInt;
use valence::protocol::VarInt;
pub fn main() -> ShutdownResult {
env_logger::Builder::new()
.filter_module("valence", LevelFilter::Trace)
.parse_default_env()
.init();
tracing_subscriber::fmt().init();
valence::start_server(
Game {

6
examples/combat.rs
View file

@ -1,14 +1,10 @@
use std::net::SocketAddr;
use std::sync::atomic::{AtomicUsize, Ordering};
use log::LevelFilter;
use valence::prelude::*;
pub fn main() -> ShutdownResult {
env_logger::Builder::new()
.filter_module("valence", LevelFilter::Trace)
.parse_default_env()
.init();
tracing_subscriber::fmt().init();
valence::start_server(
Game {

6
examples/conway.rs
View file

@ -2,16 +2,12 @@ use std::mem;
use std::net::{Ipv4Addr, SocketAddr, SocketAddrV4};
use std::sync::atomic::{AtomicUsize, Ordering};
use log::LevelFilter;
use num::Integer;
use rayon::prelude::*;
use valence::prelude::*;
pub fn main() -> ShutdownResult {
env_logger::Builder::new()
.filter_module("valence", LevelFilter::Trace)
.parse_default_env()
.init();
tracing_subscriber::fmt().init();
valence::start_server(
Game {

6
examples/cow_sphere.rs
View file

@ -3,15 +3,11 @@ use std::f64::consts::TAU;
use std::net::SocketAddr;
use std::sync::atomic::{AtomicUsize, Ordering};
use log::LevelFilter;
use uuid::Uuid;
use valence::prelude::*;
pub fn main() -> ShutdownResult {
env_logger::Builder::new()
.filter_module("valence", LevelFilter::Trace)
.parse_default_env()
.init();
tracing_subscriber::fmt().init();
valence::start_server(
Game {

6
examples/death.rs
View file

@ -1,14 +1,10 @@
use std::net::SocketAddr;
use std::sync::atomic::{AtomicUsize, Ordering};
use log::LevelFilter;
use valence::prelude::*;
pub fn main() -> ShutdownResult {
env_logger::Builder::new()
.filter_module("valence", LevelFilter::Trace)
.parse_default_env()
.init();
tracing_subscriber::fmt().init();
valence::start_server(
Game {

6
examples/entity_raycast.rs
View file

@ -1,15 +1,11 @@
use std::net::SocketAddr;
use std::sync::atomic::{AtomicUsize, Ordering};
use log::LevelFilter;
use valence::prelude::*;
use valence_protocol::entity_meta::{Facing, PaintingKind};
pub fn main() -> ShutdownResult {
env_logger::Builder::new()
.filter_module("valence", LevelFilter::Trace)
.parse_default_env()
.init();
tracing_subscriber::fmt().init();
valence::start_server(
Game {

6
examples/inventory_piano.rs
View file

@ -1,16 +1,12 @@
use std::net::SocketAddr;
use std::sync::atomic::{AtomicUsize, Ordering};
use log::LevelFilter;
use num::Integer;
pub use valence::prelude::*;
use valence_protocol::types::ClickContainerMode;
pub fn main() -> ShutdownResult {
env_logger::Builder::new()
.filter_module("valence", LevelFilter::Trace)
.parse_default_env()
.init();
tracing_subscriber::fmt().init();
valence::start_server(
Game {

6
examples/parkour.rs
View file

@ -3,16 +3,12 @@ use std::net::SocketAddr;
use std::sync::atomic::{AtomicUsize, Ordering};
use std::time::{SystemTime, UNIX_EPOCH};
use log::LevelFilter;
use rand::seq::SliceRandom;
use rand::Rng;
use valence::prelude::*;
pub fn main() -> ShutdownResult {
env_logger::Builder::new()
.filter_module("valence", LevelFilter::Trace)
.parse_default_env()
.init();
tracing_subscriber::fmt().init();
valence::start_server(
Game {

6
examples/resource_pack.rs
View file

@ -1,16 +1,12 @@
use std::net::SocketAddr;
use std::sync::atomic::{AtomicUsize, Ordering};
use log::LevelFilter;
use valence::prelude::*;
use valence_protocol::packets::c2s::play::ResourcePackC2s;
use valence_protocol::types::EntityInteraction;
pub fn main() -> ShutdownResult {
env_logger::Builder::new()
.filter_module("valence", LevelFilter::Trace)
.parse_default_env()
.init();
tracing_subscriber::fmt().init();
valence::start_server(
Game {

6
examples/terrain.rs
View file

@ -2,17 +2,13 @@ use std::net::SocketAddr;
use std::sync::atomic::{AtomicUsize, Ordering};
use std::time::SystemTime;
use log::LevelFilter;
use noise::{NoiseFn, Seedable, SuperSimplex};
use rayon::iter::ParallelIterator;
pub use valence::prelude::*;
use vek::Lerp;
pub fn main() -> ShutdownResult {
env_logger::Builder::new()
.filter_module("valence", LevelFilter::Trace)
.parse_default_env()
.init();
tracing_subscriber::fmt().init();
let seconds_per_day = 86_400;

4
performance_tests/players/Cargo.toml
View file

@ -4,6 +4,6 @@ version = "0.1.0"
edition = "2021"
[dependencies]
env_logger = "0.9.1"
log = "0.4.17"
tracing-subscriber = "0.3.16"
valence = { path = "../.." }

10
performance_tests/players/src/main.rs
View file

@ -1,14 +1,10 @@
use std::net::SocketAddr;
use std::time::Instant;
use log::LevelFilter;
use valence::prelude::*;
pub fn main() -> ShutdownResult {
env_logger::Builder::new()
.filter_module("valence", LevelFilter::Trace)
.parse_default_env()
.init();
tracing_subscriber::fmt().init();
valence::start_server(
Game,
@ -119,8 +115,6 @@ impl Config for Game {
server.clients.retain(|_, client| {
if client.created_this_tick() {
log::info!("Client \"{}\" joined", client.username());
client.spawn(world_id);
client.set_flat(true);
client.teleport([0.0, 1.0, 0.0], 0.0, 0.0);
@ -152,8 +146,6 @@ impl Config for Game {
}
if client.is_disconnected() {
log::info!("Client \"{}\" disconnected", client.username());
if WITH_PLAYER_ENTITIES {
if let Some(id) = &server.state.player_list {
server.player_lists.get_mut(id).remove(client.uuid());

3
src/biome.rs
View file

@ -3,6 +3,7 @@
use std::collections::HashSet;
use anyhow::ensure;
use tracing::warn;
use valence_nbt::{compound, Compound};
use valence_protocol::ident;
use valence_protocol::ident::Ident;
@ -157,7 +158,7 @@ pub(crate) fn validate_biomes(biomes: &[Biome]) -> anyhow::Result<()> {
}
if !names.contains(&ident!("plains")) {
log::warn!(
warn!(
"A biome named \"plains\" is missing from the biome registry! Due to a bug in the \
vanilla client, players may not be able to join the game!"
);

3
src/chunk/paletted_container.rs
View file

@ -2,8 +2,7 @@ use std::array;
use std::io::Write;
use arrayvec::ArrayVec;
use valence_protocol::var_int::VarInt;
use valence_protocol::Encode;
use valence_protocol::{Encode, VarInt};
use crate::chunk::{compact_u64s_len, encode_compact_u64s};
use crate::util::bits_needed;

39
src/client.rs
View file

@ -9,6 +9,7 @@ use anyhow::{bail, Context};
pub use bitfield_struct::bitfield;
pub use event::*;
use rayon::iter::ParallelIterator;
use tracing::{error, info, warn};
use uuid::Uuid;
use valence_protocol::packets::c2s::play::ClientCommand;
use valence_protocol::packets::s2c::play::{
@ -81,14 +82,24 @@ impl<C: Config> Clients<C> {
/// and the client is deleted. Otherwise, `None` is returned and the
/// function has no effect.
pub fn remove(&mut self, client: ClientId) -> Option<C::ClientState> {
self.slab.remove(client.0).map(|c| c.state)
self.slab.remove(client.0).map(|c| {
info!(username = %c.username, uuid = %c.uuid, "removing client");
c.state
})
}
/// Deletes all clients from the server for which `f` returns `false`.
///
/// All clients are visited in an unspecified order.
pub fn retain(&mut self, mut f: impl FnMut(ClientId, &mut Client<C>) -> bool) {
self.slab.retain(|k, v| f(ClientId(k), v))
self.slab.retain(|k, v| {
if !f(ClientId(k), v) {
info!(username = %v.username, uuid = %v.uuid, "removing client");
false
} else {
true
}
})
}
/// Returns the number of clients on the server. This includes clients for
@ -321,10 +332,10 @@ impl<C: Config> Client<C> {
{
if let Some(ctrl) = &mut self.ctrl {
if let Err(e) = ctrl.append_packet(pkt) {
log::warn!(
"failed to queue packet {} for client {}: {e:#}",
pkt.packet_name(),
&self.username
warn!(
username = %self.username,
uuid = %self.uuid,
"failed to queue packet: {e:#}"
);
self.ctrl = None;
}
@ -817,7 +828,7 @@ impl<C: Config> Client<C> {
pub fn disconnect(&mut self, reason: impl Into<Text>) {
if self.ctrl.is_some() {
let txt = reason.into();
log::info!("disconnecting client '{}': \"{txt}\"", self.username);
info!("disconnecting client '{}': \"{txt}\"", self.username);
self.queue_packet(&DisconnectPlay { reason: txt });
@ -829,7 +840,7 @@ impl<C: Config> Client<C> {
/// displayed.
pub fn disconnect_no_reason(&mut self) {
if self.ctrl.is_some() {
log::info!("disconnecting client '{}'", self.username);
info!("disconnecting client '{}'", self.username);
self.ctrl = None;
}
}
@ -859,7 +870,7 @@ impl<C: Config> Client<C> {
Ok(Some(pkt)) => {
let name = pkt.packet_name();
if let Err(e) = self.handle_serverbound_packet(entities, pkt) {
log::error!(
error!(
"failed to handle {name} packet from client {}: {e:#}",
&self.username
);
@ -871,7 +882,7 @@ impl<C: Config> Client<C> {
return;
}
Err(e) => {
log::error!(
error!(
"failed to read next serverbound packet from client {}: {e:#}",
&self.username
);
@ -1175,7 +1186,11 @@ impl<C: Config> Client<C> {
) {
Ok(()) => self.ctrl = Some(ctrl),
Err(e) => {
log::warn!("error updating client '{}': {e:#}", &self.username);
error!(
username = %self.username,
uuid = %self.uuid,
"error updating client: {e:#}"
);
}
}
}
@ -1197,7 +1212,7 @@ impl<C: Config> Client<C> {
) -> anyhow::Result<()> {
let world = match worlds.get(self.world) {
Some(world) => world,
None => bail!("client is in an invalid world and must be disconnected",),
None => bail!("client is in an invalid world and must be disconnected"),
};
let current_tick = shared.current_tick();

3
src/player_list.rs
View file

@ -6,9 +6,8 @@ use std::collections::{HashMap, HashSet};
use bitfield_struct::bitfield;
use uuid::Uuid;
use valence_protocol::packets::s2c::play::{PlayerInfo, SetTabListHeaderAndFooter};
use valence_protocol::text::Text;
use valence_protocol::types::{GameMode, PlayerInfoAddPlayer, SignedProperty};
use valence_protocol::var_int::VarInt;
use valence_protocol::{Text, VarInt};
use crate::config::Config;
use crate::player_textures::SignedPlayerTextures;

76
src/server.rs
View file

@ -20,6 +20,7 @@ use tokio::net::tcp::{OwnedReadHalf, OwnedWriteHalf};
use tokio::net::{TcpListener, TcpStream};
use tokio::runtime::{Handle, Runtime};
use tokio::sync::Semaphore;
use tracing::{error, info, info_span, instrument, trace, warn};
use uuid::Uuid;
use valence_nbt::{compound, Compound, List};
use valence_protocol::packets::c2s::handshake::HandshakeOwned;
@ -63,6 +64,7 @@ pub struct Server<C: Config> {
pub worlds: Worlds<C>,
/// All of the player lists on the server.
pub player_lists: PlayerLists<C>,
/// All of the inventories on the server.
pub inventories: Inventories,
}
@ -276,13 +278,14 @@ pub fn start_server<C: Config>(config: C, data: C::ServerState) -> ShutdownResul
inventories: Inventories::new(),
};
shared.config().init(&mut server);
info_span!("configured_init").in_scope(|| shared.config().init(&mut server));
tokio::spawn(do_accept_loop(shared));
do_update_loop(&mut server)
}
#[instrument(skip_all)]
fn setup_server<C: Config>(cfg: C) -> anyhow::Result<SharedServer<C>> {
let max_connections = cfg.max_connections();
let address = cfg.address();
@ -381,7 +384,6 @@ fn make_registry_codec(dimensions: &[Dimension], biomes: &[Biome]) -> Compound {
.map(|(id, biome)| biome.to_biome_registry_item(id as i32))
.collect())
}
},
ident!("chat_type") => compound! {
"type" => ident!("chat_type"),
@ -392,25 +394,36 @@ fn make_registry_codec(dimensions: &[Dimension], biomes: &[Biome]) -> Compound {
fn do_update_loop(server: &mut Server<impl Config>) -> ShutdownResult {
let mut tick_start = Instant::now();
let mut current_tick = 0;
let shared = server.shared.clone();
loop {
let _span = info_span!("update_loop", tick = current_tick).entered();
if let Some(res) = shared.0.shutdown_result.lock().unwrap().take() {
return res;
}
while let Ok(msg) = shared.0.new_clients_rx.try_recv() {
info!(
username = %msg.ncd.username,
uuid = %msg.ncd.uuid,
ip = %msg.ncd.remote_addr,
"inserting client"
);
server
.clients
.insert(Client::new(msg.ctrl, msg.ncd, Default::default()));
}
// Get serverbound packets first so they are not dealt with a tick late.
server.clients.par_iter_mut().for_each(|(_, client)| {
client.handle_serverbound_packets(&server.entities);
});
shared.config().update(server);
info_span!("configured_update").in_scope(|| shared.config().update(server));
server.worlds.par_iter_mut().for_each(|(id, world)| {
world.spatial_index.update(&server.entities, id);
@ -433,6 +446,7 @@ fn do_update_loop(server: &mut Server<impl Config>) -> ShutdownResult {
});
server.player_lists.update();
server.inventories.update();
// Sleep for the remainder of the tick.
@ -440,13 +454,12 @@ fn do_update_loop(server: &mut Server<impl Config>) -> ShutdownResult {
thread::sleep(tick_duration.saturating_sub(tick_start.elapsed()));
tick_start = Instant::now();
shared.0.tick_counter.fetch_add(1, Ordering::SeqCst);
current_tick = shared.0.tick_counter.fetch_add(1, Ordering::SeqCst) + 1;
}
}
#[instrument(skip_all)]
async fn do_accept_loop(server: SharedServer<impl Config>) {
log::trace!("entering accept loop");
let listener = match TcpListener::bind(server.0.address).await {
Ok(listener) => listener,
Err(e) => {
@ -461,23 +474,12 @@ async fn do_accept_loop(server: SharedServer<impl Config>) {
Ok((stream, remote_addr)) => {
let server = server.clone();
tokio::spawn(async move {
if let Err(e) = stream.set_nodelay(true) {
log::error!("failed to set TCP_NODELAY: {e}");
}
if let Err(e) = handle_connection(server, stream, remote_addr).await {
if let Some(e) = e.downcast_ref::<io::Error>() {
if e.kind() == io::ErrorKind::UnexpectedEof {
return;
}
}
log::error!("connection to {remote_addr} ended: {e:#}");
}
handle_connection(server, stream, remote_addr).await;
drop(permit);
});
}
Err(e) => {
log::error!("failed to accept incoming connection: {e}");
error!("failed to accept incoming connection: {e}");
}
},
// Closed semaphore indicates server shutdown.
@ -486,14 +488,21 @@ async fn do_accept_loop(server: SharedServer<impl Config>) {
}
}
#[instrument(skip(server, stream))]
async fn handle_connection(
server: SharedServer<impl Config>,
stream: TcpStream,
remote_addr: SocketAddr,
) -> anyhow::Result<()> {
) {
trace!("handling connection");
if let Err(e) = stream.set_nodelay(true) {
error!("failed to set TCP_NODELAY: {e}");
}
let (read, write) = stream.into_split();
let mut ctrl = InitialPacketController::new(
let ctrl = InitialPacketController::new(
read,
write,
PacketEncoder::new(),
@ -503,6 +512,23 @@ async fn handle_connection(
// TODO: peek stream for 0xFE legacy ping
if let Err(e) = handle_handshake(server, ctrl, remote_addr).await {
// EOF can happen if the client disconnects while joining, which isn't
// very erroneous.
if let Some(e) = e.downcast_ref::<io::Error>() {
if e.kind() == io::ErrorKind::UnexpectedEof {
return;
}
}
warn!("connection ended with error: {e:#}");
}
}
async fn handle_handshake(
server: SharedServer<impl Config>,
mut ctrl: InitialPacketController<OwnedReadHalf, OwnedWriteHalf>,
remote_addr: SocketAddr,
) -> anyhow::Result<()> {
let handshake = ctrl.recv_packet::<HandshakeOwned>().await?;
ensure!(
@ -514,10 +540,10 @@ async fn handle_connection(
match handshake.next_state {
HandshakeNextState::Status => handle_status(server, ctrl, remote_addr, handshake)
.await
.context("error during status"),
.context("error handling status"),
HandshakeNextState::Login => match handle_login(&server, &mut ctrl, remote_addr, handshake)
.await
.context("error during login")?
.context("error handling login")?
{
Some(ncd) => {
let msg = NewClientMessage {
@ -631,7 +657,7 @@ async fn handle_login(
}
if let Err(reason) = server.0.cfg.login(server, &ncd).await {
log::info!("Disconnect at login: \"{reason}\"");
info!("disconnect at login: \"{reason}\"");
ctrl.send_packet(&DisconnectLogin { reason }).await?;
return Ok(None);
}

9
src/server/packet_controller.rs
View file

@ -7,6 +7,7 @@ use tokio::io::{AsyncRead, AsyncReadExt, AsyncWrite, AsyncWriteExt};
use tokio::runtime::Handle;
use tokio::task::JoinHandle;
use tokio::time::timeout;
use tracing::debug;
use valence_protocol::{Decode, Encode, Packet, PacketDecoder, PacketEncoder};
use crate::server::byte_channel::{byte_channel, ByteReceiver, ByteSender, TryRecvError};
@ -129,7 +130,7 @@ where
match self.reader.read_buf(&mut buf).await {
Ok(0) => break,
Err(e) => {
log::warn!("error reading packet data: {e}");
debug!("error reading packet data: {e}");
break;
}
_ => {}
@ -137,7 +138,7 @@ where
// This should always be an O(1) unsplit because we reserved space earlier.
if let Err(e) = incoming_sender.send_async(buf).await {
log::warn!("error sending packet data: {e}");
debug!("error sending packet data: {e}");
break;
}
}
@ -150,13 +151,13 @@ where
let bytes = match outgoing_receiver.recv_async().await {
Ok(bytes) => bytes,
Err(e) => {
log::warn!("error receiving packet data: {e}");
debug!("error receiving packet data: {e}");
break;
}
};
if let Err(e) = self.writer.write_all(&bytes).await {
log::warn!("error writing packet data: {e}");
debug!("error writing packet data: {e}");
}
}
});

3
src/slab_versioned.rs
View file

@ -2,6 +2,7 @@ use std::iter::FusedIterator;
use std::num::NonZeroU32;
use rayon::iter::{IntoParallelRefIterator, IntoParallelRefMutIterator, ParallelIterator};
use tracing::warn;
use crate::slab::Slab;
@ -87,7 +88,7 @@ impl<T> VersionedSlab<T> {
pub fn insert_with(&mut self, f: impl FnOnce(Key) -> T) -> (Key, &mut T) {
let version = self.version;
self.version = NonZeroU32::new(version.get().wrapping_add(1)).unwrap_or_else(|| {
log::warn!("slab version overflow");
warn!("slab version overflow");
ONE
});

7
valence_protocol/src/lib.rs
View file

@ -114,16 +114,15 @@ mod raw_bytes;
pub mod text;
pub mod types;
pub mod username;
pub mod var_int;
pub mod var_long;
mod var_int;
mod var_long;
/// Used only by proc macros. Not public API.
#[doc(hidden)]
pub mod __private {
pub use anyhow::{anyhow, bail, ensure, Context, Result};
pub use crate::var_int::VarInt;
pub use crate::{Decode, DerivedPacketDecode, DerivedPacketEncode, Encode};
pub use crate::{Decode, DerivedPacketDecode, DerivedPacketEncode, Encode, VarInt};
}
/// The maximum number of bytes in a single Minecraft packet.