soruh/centralex
1
0
Fork 0
Code Issues Pull Requests 1 Actions Packages Projects Releases Wiki Activity

move logging to tracing

Browse Source
This commit is contained in:
soruh
2023-03-18 20:47:16 +01:00
parent 6b698ae869
commit e17547ad83
7 changed files with 300 additions and 395 deletions
Download Patch File Download Diff File Expand all files Collapse all files

5
src/debug_server.rs
View File

@@ -6,6 +6,7 @@ use std::convert::Infallible;
use std::net::SocketAddr;
use std::sync::Arc;
use tokio::sync::Mutex;
use tracing::error;
use crate::ports::PortHandler;
use crate::spawn;
@@ -36,7 +37,7 @@ pub async fn debug_server(addr: SocketAddr, port_handler: Arc<Mutex<PortHandler>
}));
// Run this server for... forever!
if let Err(e) = server.await {
eprintln!("server error: {}", e);
if let Err(error) = server.await {
error!(%error, "debug server error");
}
}

331
src/main.rs
View File

@@ -13,6 +13,7 @@ use debug_server::debug_server;
use futures::Future;
use packets::{Header, Packet, RemConnect};
use serde::{Deserialize, Deserializer};
use time::format_description::OwnedFormatItem;
use tokio::{
io::AsyncWriteExt,
net::{TcpListener, TcpStream},
@@ -20,6 +21,7 @@ use tokio::{
sync::Mutex,
time::{sleep, timeout, Instant},
};
use tracing::{debug, error, info, warn, Level};
use crate::packets::{dyn_ip_update, PacketKind, REJECT_OOP, REJECT_TIMEOUT};
use crate::ports::{AllowedPorts, PortHandler, PortStatus};
@@ -54,6 +56,29 @@ pub struct Config {
#[serde(deserialize_with = "maybe_parse_socket_addr")]
#[serde(default)]
debug_server_addr: Option<SocketAddr>,
#[serde(deserialize_with = "parse_time_format")]
time_format: OwnedFormatItem,
#[serde(deserialize_with = "parse_log_level")]
log_level: Level,
}
fn parse_log_level<'de, D: Deserializer<'de>>(deserializer: D) -> Result<Level, D::Error> {
use serde::de::Error;
String::deserialize(deserializer)?
.parse()
.map_err(|err| D::Error::custom(err))
}
fn parse_time_format<'de, D: Deserializer<'de>>(
deserializer: D,
) -> Result<OwnedFormatItem, D::Error> {
use serde::de::Error;
time::format_description::parse_owned::<2>(&String::deserialize(deserializer)?)
.map_err(|err| D::Error::custom(err))
}
fn maybe_parse_socket_addr<'de, D: Deserializer<'de>>(
@@ -87,7 +112,7 @@ fn parse_socket_addr<'de, D: Deserializer<'de>>(deserializer: D) -> Result<Socke
impl Config {
fn load(path: impl AsRef<Path>) -> std::io::Result<Self> {
println!("loading config");
info!("loading config");
Ok(serde_json::from_reader(BufReader::new(File::open(path)?))?)
}
}
@@ -113,154 +138,182 @@ fn spawn<T: Send + 'static>(
.unwrap_or_else(|err| panic!("failed to spawn {name:?}: {err:?}"))
}
#[tokio::main]
async fn main() -> anyhow::Result<()> {
#[cfg(feature = "tokio_console")]
console_subscriber::init();
fn main() -> anyhow::Result<()> {
let config = Arc::new(Config::load("config.json")?);
if config.allowed_ports.is_empty() {
panic!("no allowed ports");
}
let cache_path = PathBuf::from("cache.json");
let local_offset = time::UtcOffset::local_offset_at(time::OffsetDateTime::UNIX_EPOCH)?;
let (change_sender, mut change_receiver) = tokio::sync::watch::channel(Instant::now());
tokio::runtime::Builder::new_multi_thread()
.enable_all()
.build()?
.block_on(async move {
{
use tracing_subscriber::prelude::*;
use tracing_subscriber::*;
let mut port_handler = PortHandler::load_or_default(&cache_path, change_sender);
port_handler.update_allowed_ports(&config.allowed_ports);
// build a `Subscriber` by combining layers with a
// `tracing_subscriber::Registry`:
let registry = tracing_subscriber::registry();
let port_handler = Arc::new(Mutex::new(port_handler));
#[cfg(feature = "tokio_console")]
let registry = registry.with(console_subscriber::spawn());
{
let port_handler = port_handler.clone();
spawn("cache daemon", async move {
let mut last_store = Instant::now() - 2 * CACHE_STORE_INTERVAL;
let mut change_timeout = None;
loop {
if let Some(change_timeout) = change_timeout.take() {
tokio::time::timeout(change_timeout, change_receiver.changed())
.await
.unwrap_or(Ok(()))
} else {
change_receiver.changed().await
}
.expect("failed to wait for cache changes");
registry
.with(
fmt::layer()
.with_target(false)
.with_timer(fmt::time::OffsetTime::new(
local_offset,
config.time_format.clone(),
))
.with_filter(filter::LevelFilter::from_level(config.log_level)),
)
.init();
}
let time_since_last_store = last_store.elapsed();
let cache_path = PathBuf::from("cache.json");
if time_since_last_store > CACHE_STORE_INTERVAL {
let port_handler = port_handler.lock().await;
let (change_sender, mut change_receiver) = tokio::sync::watch::channel(Instant::now());
last_store = Instant::now();
if let Err(err) = port_handler.store(&cache_path) {
println!("failed to store cache: {err:?}");
let mut port_handler = PortHandler::load_or_default(&cache_path, change_sender);
port_handler.update_allowed_ports(&config.allowed_ports);
let port_handler = Arc::new(Mutex::new(port_handler));
{
let port_handler = port_handler.clone();
spawn("cache daemon", async move {
let mut last_store = Instant::now() - 2 * CACHE_STORE_INTERVAL;
let mut change_timeout = None;
loop {
if let Some(change_timeout) = change_timeout.take() {
tokio::time::timeout(change_timeout, change_receiver.changed())
.await
.unwrap_or(Ok(()))
} else {
change_receiver.changed().await
}
.expect("failed to wait for cache changes");
let time_since_last_store = last_store.elapsed();
if time_since_last_store > CACHE_STORE_INTERVAL {
let port_handler = port_handler.lock().await;
last_store = Instant::now();
if let Err(err) = port_handler.store(&cache_path) {
error!("failed to store cache: {err:?}");
}
} else {
change_timeout = Some(CACHE_STORE_INTERVAL - time_since_last_store);
}
}
} else {
change_timeout = Some(CACHE_STORE_INTERVAL - time_since_last_store);
}
}
});
}
#[cfg(feature = "debug_server")]
if let Some(debug_server_addr) = config.debug_server_addr {
println!("starting debug server on {debug_server_addr:?}");
spawn(
"debug server",
debug_server(debug_server_addr, port_handler.clone()),
);
}
let listener = TcpListener::bind(config.listen_addr).await?;
println!("listening on {}", config.listen_addr);
while let Ok((mut stream, addr)) = listener.accept().await {
println!("connection from {addr}");
let port_handler = port_handler.clone();
let config = config.clone();
let mut handler_metadata = HandlerMetadata::default();
spawn(&format!("connection to {addr}"), async move {
use futures::future::FutureExt;
let res = std::panic::AssertUnwindSafe(connection_handler(
&config,
&mut handler_metadata,
&port_handler,
&mut stream,
))
.catch_unwind()
.await;
let error = match res {
Err(err) => {
let err = err
.downcast::<String>()
.map(|err| *err)
.unwrap_or_else(|_| "?".to_owned());
Some(format!("panic at: {err}"))
}
Ok(Err(err)) => Some(err.to_string()),
Ok(Ok(())) => None,
};
if let Some(err) = error {
println!("client at {addr} had an error: {err}");
let mut packet = Packet::default();
packet.data.extend_from_slice(err.as_bytes());
packet.data.truncate((u8::MAX - 1) as usize);
packet.data.push(0);
packet.header = Header {
kind: PacketKind::Error.raw(),
length: packet.data.len() as u8,
};
let (_, mut writer) = stream.split();
let _ = packet.send(&mut writer).await;
});
}
if let Some(port) = handler_metadata.port {
let mut port_handler = port_handler.lock().await;
#[cfg(feature = "debug_server")]
if let Some(listen_addr) = config.debug_server_addr {
warn!(%listen_addr, "debug server listening");
spawn(
"debug server",
debug_server(listen_addr, port_handler.clone()),
);
}
if let Some(port_state) = port_handler.port_state.get_mut(&port) {
port_state.new_state(PortStatus::Disconnected);
port_handler.register_update();
}
let listener = TcpListener::bind(config.listen_addr).await?;
warn!(
listen_addr = %config.listen_addr,
"centralex server listening"
);
if let Some(listener) = handler_metadata.listener.take() {
let res = port_handler.start_rejector(
port,
listener,
Packet {
header: Header {
kind: PacketKind::Reject.raw(),
length: 3,
},
data: b"nc\0".to_vec(),
},
);
while let Ok((mut stream, addr)) = listener.accept().await {
info!(%addr, "new connection");
if let Err(err) = res {
println!(
"failed to start rejector on port {port} after client error: {err}"
);
let port_handler = port_handler.clone();
let config = config.clone();
let mut handler_metadata = HandlerMetadata::default();
spawn(&format!("connection to {addr}"), async move {
use futures::future::FutureExt;
let res = std::panic::AssertUnwindSafe(connection_handler(
&config,
&mut handler_metadata,
&port_handler,
&mut stream,
))
.catch_unwind()
.await;
let error = match res {
Err(err) => {
let err = err
.downcast::<String>()
.map(|err| *err)
.unwrap_or_else(|_| "?".to_owned());
Some(format!("panic at: {err}"))
}
Ok(Err(err)) => Some(err.to_string()),
Ok(Ok(())) => None,
};
if let Some(error) = error {
error!(%addr, %error, "Client had an error");
let mut packet = Packet::default();
packet.data.extend_from_slice(error.as_bytes());
packet.data.truncate((u8::MAX - 1) as usize);
packet.data.push(0);
packet.header = Header {
kind: PacketKind::Error.raw(),
length: packet.data.len() as u8,
};
let (_, mut writer) = stream.split();
let _ = packet.send(&mut writer).await;
}
}
if let Some(port) = handler_metadata.port {
let mut port_handler = port_handler.lock().await;
if let Some(port_state) = port_handler.port_state.get_mut(&port) {
port_state.new_state(PortStatus::Disconnected);
port_handler.register_update();
}
if let Some(listener) = handler_metadata.listener.take() {
let res = port_handler.start_rejector(
port,
listener,
Packet {
header: Header {
kind: PacketKind::Reject.raw(),
length: 3,
},
data: b"nc\0".to_vec(),
},
);
if let Err(error) = res {
error!(%port, %error, "failed to start rejector");
}
}
}
sleep(Duration::from_secs(3)).await;
let _ = stream.shutdown().await;
});
}
sleep(Duration::from_secs(3)).await;
let _ = stream.shutdown().await;
});
}
Ok(())
Ok(())
})
}
#[derive(Debug, Default)]
@@ -301,7 +354,7 @@ async fn connection_handler(
.await
.allocate_port_for_number(config, number);
println!("allocated port: {:?}", port);
info!(port, "allocated port");
let Some(port) = port else {
writer.write_all(REJECT_OOP).await?;
@@ -383,8 +436,18 @@ async fn connection_handler(
let mut last_ping_received_at = Instant::now();
let result = loop {
// println!("next ping in {:?}s", SEND_PING_INTERVAL.saturating_sub(now.saturating_duration_since(last_ping_sent_at)).as_secs());
// println!("will timeout in in {:?}s", PING_TIMEOUT.saturating_sub(now.saturating_duration_since(last_ping_received_at)).as_secs());
debug!(
seconds = SEND_PING_INTERVAL
.saturating_sub(last_ping_sent_at.elapsed())
.as_secs(),
"next ping in"
);
debug!(
seconds = PING_TIMEOUT
.saturating_sub(last_ping_received_at.elapsed())
.as_secs(),
"timeout in",
);
let send_next_ping_in = SEND_PING_INTERVAL.saturating_sub(last_ping_sent_at.elapsed());
let next_ping_expected_in = PING_TIMEOUT.saturating_sub(last_ping_received_at.elapsed());
@@ -398,14 +461,14 @@ async fn connection_handler(
packet.recv_into(&mut reader).await?;
if packet.kind() == PacketKind::Ping {
// println!("received ping");
debug!("received ping");
last_ping_received_at = Instant::now();
} else {
break Result::Packet { packet }
}
},
_ = sleep(send_next_ping_in) => {
// println!("sending ping");
debug!("sending ping");
writer.write_all(bytemuck::bytes_of(& Header { kind: PacketKind::Ping.raw(), length: 0 })).await?;
last_ping_sent_at = Instant::now();
}
@@ -422,7 +485,7 @@ async fn connection_handler(
packet.kind(),
packets::PacketKind::End | packets::PacketKind::Reject
) {
println!("got disconnect packet: {packet:?}");
info!(?packet, "got disconnect packet");
if packet.kind() == packets::PacketKind::End {
packet.header.kind = packets::PacketKind::Reject.raw();
@@ -449,7 +512,7 @@ async fn connection_handler(
stream,
addr,
} => {
println!("got caller from: {addr}");
info!(%addr, "got caller from");
packet.data.clear();
/* The I-Telex Clients can't handle data in this packet due to a bug

9
src/packets.rs
View File

@@ -6,6 +6,7 @@ use tokio::{
io::{AsyncReadExt, AsyncWriteExt},
net::tcp::{ReadHalf, WriteHalf},
};
use tracing::info;
pub const REJECT_OOP: &[u8; 6] = b"\x04\x04oop\x00";
pub const REJECT_TIMEOUT: &[u8; 10] = b"\x04\x08timeout\x00";
@@ -183,7 +184,7 @@ pub async fn dyn_ip_update(
pin: u16,
port: u16,
) -> anyhow::Result<std::net::Ipv4Addr> {
println!("starting dyn ip update for number={number} port={port}...");
info!(%number, %port, "starting dyn ip update");
let mut packet = Packet::default();
packet.header = Header {
@@ -205,7 +206,7 @@ pub async fn dyn_ip_update(
packet.recv_into(&mut reader).await?;
let res = match packet.kind() {
let result = match packet.kind() {
PacketKind::DynIpUpdateResponse => Ok(<[u8; 4]>::try_from(packet.data)
.map_err(|err| {
anyhow::anyhow!(
@@ -234,7 +235,7 @@ pub async fn dyn_ip_update(
_ => bail!("server returned unexpected packet"),
};
println!("finished dyn ip update result: {res:?}");
info!(?result, "finished dyn ip update");
res
result
}

39
src/ports.rs
View File

@@ -13,6 +13,7 @@ use std::{
use anyhow::anyhow;
use serde::{Deserialize, Serialize};
use tokio::{net::TcpListener, sync::Mutex, task::JoinHandle, time::Instant};
use tracing::{error, info, warn};
use crate::{
packets::Packet, spawn, Config, Number, Port, UnixTimestamp, PORT_OWNERSHIP_TIMEOUT,
@@ -65,6 +66,8 @@ fn duration_in_hours(duration: Duration) -> String {
fn format_instant(instant: Instant) -> String {
let when = duration_in_hours(instant.elapsed()) + " ago";
todo!();
#[cfg(feature = "chrono")]
let when = (|| -> anyhow::Result<_> {
use chrono::{Local, TimeZone};
@@ -208,7 +211,7 @@ impl PortHandler {
}
pub fn store(&self, cache: &Path) -> anyhow::Result<()> {
println!("storing cache");
info!("storing cache");
let temp_file = cache.with_extension(".temp");
serde_json::to_writer(BufWriter::new(File::create(&temp_file)?), self)?;
@@ -221,18 +224,18 @@ impl PortHandler {
cache: &Path,
change_sender: tokio::sync::watch::Sender<Instant>,
) -> std::io::Result<Self> {
println!("loading cache");
info!("loading cache");
let mut cache: Self = serde_json::from_reader(BufReader::new(File::open(cache)?))?;
cache.change_sender = Some(change_sender);
Ok(cache)
}
pub fn load_or_default(
cache: &Path,
path: &Path,
change_sender: tokio::sync::watch::Sender<Instant>,
) -> Self {
Self::load(cache, change_sender).unwrap_or_else(|err| {
println!("failed to parse cache file at {cache:?} using empty cache. error: {err}");
Self::load(path, change_sender).unwrap_or_else(|error| {
error!(?path, %error, "failed to parse cache file");
Self::default()
})
}
@@ -280,7 +283,7 @@ impl PortHandler {
listener: TcpListener,
packet: Packet,
) -> anyhow::Result<()> {
println!("starting rejector: for port {port} with {packet:?}");
info!(port, ?packet, "starting rejector");
let port_guard = Rejector::start(listener, packet);
@@ -293,7 +296,7 @@ impl PortHandler {
}
pub async fn stop_rejector(&mut self, port: Port) -> Option<(TcpListener, Packet)> {
println!("stopping rejector: for port {port}");
info!(port, "stopping rejector");
Some(self.port_guards.remove(&port)?.stop().await)
}
@@ -394,10 +397,10 @@ impl PortHandler {
if recovered_port.is_none()
&& now.saturating_sub(Duration::from_secs(timestamp)) >= PORT_RETRY_TIME
{
println!(
" trying port: {port} at -{:?}",
Duration::from_secs(now.as_secs())
.saturating_sub(Duration::from_secs(timestamp))
info!(
port,
last_try = ?Duration::from_secs(now.as_secs()).saturating_sub(Duration::from_secs(timestamp)),
"retrying errored port",
);
match std::net::TcpListener::bind((config.listen_addr.ip(), port)) {
@@ -408,10 +411,10 @@ impl PortHandler {
Err(_) => timestamp = now.as_secs(),
}
} else {
println!(
"skipped port: {port} at -{:?}",
Duration::from_secs(now.as_secs())
.saturating_sub(Duration::from_secs(timestamp))
info!(
port,
last_try = ?Duration::from_secs(now.as_secs()).saturating_sub(Duration::from_secs(timestamp)),
"skipped retrying errored port",
);
}
@@ -421,7 +424,7 @@ impl PortHandler {
if let Some((_, port)) = recovered_port {
self.register_update();
println!("recovered_port: {port}");
info!(port, "recovered port");
return Some(port);
}
@@ -440,7 +443,7 @@ impl PortHandler {
if let Some((&old_number, &port)) = removable_entry {
self.register_update();
println!("reused port {port} which used to be allocated to {old_number} which wasn't connected in a long time");
info!(port, old_number, "reused port");
assert!(self.allocated_ports.remove(&old_number).is_some());
return Some(port);
}
@@ -449,7 +452,7 @@ impl PortHandler {
}
pub fn mark_port_error(&mut self, number: Number, port: Port) {
println!("registering an error on port {port} for number {number}");
warn!(port, number, "registering an error on");
self.register_update();
self.errored_ports.insert((