Migrate logging to rust log with optional env_logger feature
moparisthebest/xmpp-proxy/pipeline/head This commit looks good Details

This commit is contained in:
Travis Burtrum 2021-06-08 00:14:22 -04:00
parent 0357959bab
commit b99e6cd923
12 changed files with 157 additions and 66 deletions

1
.gitignore vendored
View File

@ -4,3 +4,4 @@
**/*.kate-swp
**/out/
**/core.*
fuzz/target/

76
Cargo.lock generated
View File

@ -1,5 +1,14 @@
# This file is automatically @generated by Cargo.
# It is not intended for manual editing.
[[package]]
name = "aho-corasick"
version = "0.7.15"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "7404febffaa47dac81aa44dba71523c9d069b1bdc50a77db41195149e17f68e5"
dependencies = [
"memchr",
]
[[package]]
name = "anyhow"
version = "1.0.40"
@ -17,6 +26,17 @@ dependencies = [
"syn",
]
[[package]]
name = "atty"
version = "0.2.14"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "d9b39be18770d11421cdb1b9947a45dd3f37e93092cbf377614828a319d5fee8"
dependencies = [
"hermit-abi",
"libc",
"winapi",
]
[[package]]
name = "autocfg"
version = "1.0.1"
@ -108,6 +128,19 @@ dependencies = [
"syn",
]
[[package]]
name = "env_logger"
version = "0.8.3"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "17392a012ea30ef05a610aa97dfb49496e71c9f676b27879922ea5bdf60d9d3f"
dependencies = [
"atty",
"humantime",
"log",
"regex",
"termcolor",
]
[[package]]
name = "form_urlencoded"
version = "1.0.1"
@ -250,6 +283,12 @@ dependencies = [
"winapi",
]
[[package]]
name = "humantime"
version = "2.1.0"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "9a3a5bfb195931eeb336b2a7b4d761daec841b97f947d34394601737a7bba5e4"
[[package]]
name = "idna"
version = "0.2.3"
@ -586,6 +625,23 @@ dependencies = [
"bitflags",
]
[[package]]
name = "regex"
version = "1.4.6"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "2a26af418b574bd56588335b3a3659a65725d4e636eb1016c2f9e3b38c7cc759"
dependencies = [
"aho-corasick",
"memchr",
"regex-syntax",
]
[[package]]
name = "regex-syntax"
version = "0.6.25"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "f497285884f3fcff424ffc933e56d7cbca511def0c9831a7f9b5f6153e3cc89b"
[[package]]
name = "resolv-conf"
version = "0.7.0"
@ -745,6 +801,15 @@ dependencies = [
"unicode-xid",
]
[[package]]
name = "termcolor"
version = "1.1.2"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "2dfed899f0eb03f32ee8c6a0aabdb8a7949659e3466561fc0adf54e26d88c5f4"
dependencies = [
"winapi-util",
]
[[package]]
name = "thiserror"
version = "1.0.24"
@ -1063,6 +1128,15 @@ version = "0.4.0"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "ac3b87c63620426dd9b991e5ce0329eff545bccbbb34f3be09ff6fb6ab51b7b6"
[[package]]
name = "winapi-util"
version = "0.1.5"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "70ec6ce85bb158151cae5e5c87f95a8e97d2c0c4b001223f33a334e3ce5de178"
dependencies = [
"winapi",
]
[[package]]
name = "winapi-x86_64-pc-windows-gnu"
version = "0.4.0"
@ -1084,8 +1158,10 @@ version = "1.0.0"
dependencies = [
"anyhow",
"die",
"env_logger",
"futures",
"lazy_static",
"log",
"quinn",
"serde",
"serde_derive",

View File

@ -28,6 +28,10 @@ die = "0.2"
anyhow = "1.0"
tokio = { version = "1.4", features = ["net", "rt", "rt-multi-thread", "macros", "io-util"] }
# logging deps
log = "0.4"
env_logger = { version = "0.8", optional = true }
# incoming deps
tokio-rustls = { version = "0.22", optional = true }
@ -41,7 +45,7 @@ trust-dns-resolver = { version = "0.20", optional = true }
quinn = { version = "0.7", optional = true }
[features]
default = ["incoming", "outgoing", "quic"]
default = ["incoming", "outgoing", "quic", "env_logger"]
#default = ["incoming", "outgoing"]
#default = ["incoming", "quic"]
#default = ["outgoing", "quic"]

View File

@ -65,7 +65,6 @@ interfaces = { "127.0.0.1" }
-- we don't need prosody doing any encryption, xmpp-proxy does this now
-- these are likely set to true somewhere in your file, find them, make them false
-- you can also remove all certificates from your config
c2s_require_encryption = false
s2s_require_encryption = false
s2s_secure_auth = false
@ -140,6 +139,6 @@ GNU/AGPLv3 - Check LICENSE.md for details
Thanks [rxml](https://github.com/horazont/rxml) for afl-fuzz seeds
#### todo
1. sasl external for s2s, initiating and recieving
1. sasl external for s2s, initiating and receiving
2. better debug log output
3. websocket incoming and outgoing, maybe even for s2s

View File

@ -1,6 +1,16 @@
mod stanzafilter;
pub use stanzafilter::*;
pub use log::{debug, error, info, trace};
pub fn to_str(buf: &[u8]) -> std::borrow::Cow<'_, str> {
String::from_utf8_lossy(buf)
}
pub fn c2s(is_c2s: bool) -> &'static str {
if is_c2s {
"c2s"
} else {
"s2s"
}
}

View File

@ -27,10 +27,7 @@ use anyhow::{bail, Result};
mod slicesubsequence;
use slicesubsequence::*;
mod stanzafilter;
use stanzafilter::*;
use xmpp_proxy::to_str;
pub use xmpp_proxy::*;
#[cfg(feature = "quic")]
mod quic;
@ -56,27 +53,6 @@ const OUT_BUFFER_SIZE: usize = 8192;
const ALPN_XMPP_CLIENT: &[&[u8]] = &[b"xmpp-client"];
const ALPN_XMPP_SERVER: &[&[u8]] = &[b"xmpp-server"];
#[cfg(debug_assertions)]
fn c2s(is_c2s: bool) -> &'static str {
if is_c2s {
"c2s"
} else {
"s2s"
}
}
#[cfg(debug_assertions)]
#[macro_export]
macro_rules! debug {
($($y:expr),+) => (println!($($y),+));
}
#[cfg(not(debug_assertions))]
#[macro_export]
macro_rules! debug {
($($y:expr),+) => {};
}
#[derive(Deserialize)]
struct Config {
tls_key: String,
@ -88,6 +64,10 @@ struct Config {
s2s_target: String,
c2s_target: String,
proxy: bool,
#[cfg(feature = "env_logger")]
log_level: Option<String>,
#[cfg(feature = "env_logger")]
log_style: Option<String>,
}
#[derive(Clone)]
@ -152,7 +132,7 @@ async fn shuffle_rd_wr_filter<R: AsyncRead + Unpin, W: AsyncWrite + Unpin>(
let target = if is_c2s { config.c2s_target } else { config.s2s_target };
println!("INFO: {} is_c2s: {}, target: {}", client_addr, is_c2s, target);
info!("{} is_c2s: {}, target: {}", client_addr, is_c2s, target);
let out_stream = tokio::net::TcpStream::connect(target).await?;
let (mut out_rd, mut out_wr) = tokio::io::split(out_stream);
@ -176,10 +156,10 @@ async fn shuffle_rd_wr_filter<R: AsyncRead + Unpin, W: AsyncWrite + Unpin>(
local_addr.port()
)?;
let end_idx = &(&in_filter.buf[0..]).first_index_of(b"\n")? + 1;
debug!("< {} {} '{}'", client_addr, c2s(is_c2s), to_str(&in_filter.buf[0..end_idx]));
trace!("< {} {} '{}'", client_addr, c2s(is_c2s), to_str(&in_filter.buf[0..end_idx]));
out_wr.write_all(&in_filter.buf[0..end_idx]).await?;
}
debug!("< {} {} '{}'", client_addr, c2s(is_c2s), to_str(&stream_open));
trace!("< {} {} '{}'", client_addr, c2s(is_c2s), to_str(&stream_open));
out_wr.write_all(&stream_open).await?;
out_wr.flush().await?;
drop(stream_open);
@ -192,7 +172,7 @@ async fn shuffle_rd_wr_filter<R: AsyncRead + Unpin, W: AsyncWrite + Unpin>(
match buf {
None => break,
Some(buf) => {
debug!("< {} {} '{}'", client_addr, c2s(is_c2s), to_str(buf));
trace!("< {} {} '{}'", client_addr, c2s(is_c2s), to_str(buf));
out_wr.write_all(buf).await?;
out_wr.flush().await?;
}
@ -204,21 +184,21 @@ async fn shuffle_rd_wr_filter<R: AsyncRead + Unpin, W: AsyncWrite + Unpin>(
if n == 0 {
break;
}
debug!("> {} {} '{}'", client_addr, c2s(is_c2s), to_str(&out_buf[0..n]));
trace!("> {} {} '{}'", client_addr, c2s(is_c2s), to_str(&out_buf[0..n]));
in_wr.write_all(&out_buf[0..n]).await?;
in_wr.flush().await?;
},
}
}
println!("INFO: {} disconnected", client_addr);
info!("{} disconnected", client_addr);
Ok(())
}
async fn stream_preamble<R: AsyncRead + Unpin>(mut in_rd: StanzaReader<R>, client_addr: SocketAddr, mut in_filter: StanzaFilter) -> Result<(Vec<u8>, bool, StanzaReader<R>, StanzaFilter)> {
let mut stream_open = Vec::new();
while let Ok(Some(buf)) = in_rd.next(&mut in_filter).await {
debug!("received pre-<stream:stream> stanza: {} '{}'", client_addr, to_str(&buf));
trace!("received pre-<stream:stream> stanza: {} '{}'", client_addr, to_str(&buf));
if buf.starts_with(b"<?xml ") {
stream_open.extend_from_slice(buf);
} else if buf.starts_with(b"<stream:stream ") {
@ -241,6 +221,21 @@ async fn stream_preamble<R: AsyncRead + Unpin>(mut in_rd: StanzaReader<R>, clien
async fn main() {
let main_config = Config::parse(std::env::args_os().skip(1).next().unwrap_or(OsString::from("/etc/xmpp-proxy/xmpp-proxy.toml"))).die("invalid config file");
#[cfg(feature = "env_logger")]
{
use env_logger::{Builder, Env, Target};
let env = Env::default().filter_or("XMPP_PROXY_LOG_LEVEL", "info").write_style_or("XMPP_PROXY_LOG_STYLE", "never");
let mut builder = Builder::from_env(env);
builder.target(Target::Stdout);
if let Some(ref log_level) = main_config.log_level {
builder.parse_filters(log_level);
}
if let Some(ref log_style) = main_config.log_style {
builder.parse_write_style(log_style);
}
builder.init();
}
let config = main_config.get_cloneable_cfg();
let mut handles: Vec<JoinHandle<Result<()>>> = Vec::new();

View File

@ -1,7 +1,7 @@
use crate::*;
async fn handle_outgoing_connection(stream: tokio::net::TcpStream, client_addr: SocketAddr, max_stanza_size_bytes: usize) -> Result<()> {
println!("INFO: out {} connected", client_addr);
info!("out {} connected", client_addr);
let in_filter = StanzaFilter::new(max_stanza_size_bytes);
@ -18,9 +18,9 @@ async fn handle_outgoing_connection(stream: tokio::net::TcpStream, client_addr:
// todo: unsure how legit changing to a string here is...
let domain = to_str(stream_open.extract_between(b" to='", b"'").or_else(|_| stream_open.extract_between(b" to=\"", b"\""))?);
println!("INFO: out {} is_c2s: {}, domain: {}", client_addr, is_c2s, domain);
info!("out {} is_c2s: {}, domain: {}", client_addr, is_c2s, domain);
debug!("out < {} {} '{}'", client_addr, c2s(is_c2s), to_str(&stream_open));
trace!("out < {} {} '{}'", client_addr, c2s(is_c2s), to_str(&stream_open));
let (mut out_wr, mut out_rd, stream_open) = srv_connect(&domain, is_c2s, &stream_open, &mut in_filter).await?;
// send server response to client
in_wr.write_all(&stream_open).await?;
@ -35,7 +35,7 @@ async fn handle_outgoing_connection(stream: tokio::net::TcpStream, client_addr:
match buf {
None => break,
Some(buf) => {
debug!("out < {} {} '{}'", domain, c2s(is_c2s), to_str(buf));
trace!("out < {} {} '{}'", domain, c2s(is_c2s), to_str(buf));
in_wr.write_all(buf).await?;
in_wr.flush().await?;
}
@ -47,14 +47,14 @@ async fn handle_outgoing_connection(stream: tokio::net::TcpStream, client_addr:
if n == 0 {
break;
}
debug!("out > {} {} '{}'", domain, c2s(is_c2s), to_str(&out_buf[0..n]));
trace!("out > {} {} '{}'", domain, c2s(is_c2s), to_str(&out_buf[0..n]));
out_wr.write_all(&out_buf[0..n]).await?;
out_wr.flush().await?;
},
}
}
println!("INFO: out {} disconnected", client_addr);
info!("out {} disconnected", client_addr);
Ok(())
}
@ -65,7 +65,7 @@ pub fn spawn_outgoing_listener(local_addr: SocketAddr, max_stanza_size_bytes: us
let (stream, client_addr) = listener.accept().await?;
tokio::spawn(async move {
if let Err(e) = handle_outgoing_connection(stream, client_addr, max_stanza_size_bytes).await {
eprintln!("ERROR: {} {}", client_addr, e);
error!("{} {}", client_addr, e);
}
});
}

View File

@ -16,7 +16,7 @@ pub async fn quic_connect(target: SocketAddr, server_name: &str, is_c2s: bool) -
let (endpoint, _incoming) = endpoint_builder.bind(&bind_addr)?;
// connect to server
let quinn::NewConnection { connection, .. } = endpoint.connect(&target, server_name)?.await?;
debug!("[client] connected: addr={}", connection.remote_address());
trace!("quic connected: addr={}", connection.remote_address());
let (wrt, rd) = connection.open_bi().await?;
Ok((Box::new(wrt), Box::new(rd)))
@ -79,20 +79,20 @@ pub fn spawn_quic_listener(local_addr: SocketAddr, config: CloneableConfig, serv
tokio::spawn(async move {
if let Ok(mut new_conn) = incoming_conn.await {
let client_addr = new_conn.connection.remote_address();
println!("INFO: {} quic connected", client_addr);
info!("{} quic connected", client_addr);
while let Some(Ok((wrt, rd))) = new_conn.bi_streams.next().await {
let config = config.clone();
tokio::spawn(async move {
if let Err(e) = shuffle_rd_wr(rd, wrt, config, local_addr, client_addr).await {
eprintln!("ERROR: {} {}", client_addr, e);
error!("{} {}", client_addr, e);
}
});
}
}
});
}
println!("INFO: quic listener shutting down, should never happen????");
info!("quic listener shutting down, should never happen????");
#[allow(unreachable_code)]
Ok(())
})

View File

@ -8,7 +8,6 @@ use anyhow::{bail, Result};
use tokio::io::{AsyncRead, AsyncWrite, AsyncWriteExt};
use crate::stanzafilter::StanzaReader;
use crate::*;
lazy_static::lazy_static! {
@ -54,16 +53,16 @@ impl XmppConnection {
match self.conn_type {
XmppConnectionType::StartTLS => match crate::starttls_connect(SocketAddr::new(ip, self.port), domain, is_c2s, &stream_open, &mut in_filter).await {
Ok((wr, rd)) => return Ok((wr, rd)),
Err(e) => println!("ERROR: starttls connection failed to IP {} from SRV {}, error: {}", ip, self.target, e),
Err(e) => error!("starttls connection failed to IP {} from SRV {}, error: {}", ip, self.target, e),
},
XmppConnectionType::DirectTLS => match crate::tls_connect(SocketAddr::new(ip, self.port), domain, is_c2s).await {
Ok((wr, rd)) => return Ok((wr, rd)),
Err(e) => println!("ERROR: direct tls connection failed to IP {} from SRV {}, error: {}", ip, self.target, e),
Err(e) => error!("direct tls connection failed to IP {} from SRV {}, error: {}", ip, self.target, e),
},
#[cfg(feature = "quic")]
XmppConnectionType::QUIC => match crate::quic_connect(SocketAddr::new(ip, self.port), domain, is_c2s).await {
Ok((wr, rd)) => return Ok((wr, rd)),
Err(e) => println!("ERROR: quic connection failed to IP {} from SRV {}, error: {}", ip, self.target, e),
Err(e) => error!("quic connection failed to IP {} from SRV {}, error: {}", ip, self.target, e),
},
}
}
@ -179,7 +178,7 @@ pub async fn srv_connect(
// let's read to first <stream:stream to make sure we are successfully connected to a real XMPP server
let mut stream_received = false;
while let Ok(Some(buf)) = out_rd.next(&mut in_filter).await {
debug!("received pre-tls stanza: {} '{}'", domain, to_str(&buf));
trace!("received pre-tls stanza: {} '{}'", domain, to_str(&buf));
if buf.starts_with(b"<?xml ") {
server_response.extend_from_slice(&buf);
} else if buf.starts_with(b"<stream:stream ") {
@ -187,7 +186,7 @@ pub async fn srv_connect(
stream_received = true;
break;
} else {
debug!("bad pre-tls stanza: {}", to_str(&buf));
trace!("bad pre-tls stanza: {}", to_str(&buf));
break;
}
}

View File

@ -155,7 +155,7 @@ impl StanzaFilter {
}
}
}
//println!("cnt: {}, tag_cnt: {}, state: {:?}", self.cnt, self.tag_cnt, self.state);
//trace!("cnt: {}, tag_cnt: {}, state: {:?}", self.cnt, self.tag_cnt, self.state);
self.cnt += 1;
if self.cnt == self.buf_size {
bail!("stanza too big: {}", to_str(&self.buf));
@ -168,7 +168,7 @@ impl StanzaFilter {
self.tag_cnt = 0;
self.cnt = 0;
self.state = OutsideStanza;
//println!("cnt: {}, tag_cnt: {}, state: {:?}", self.cnt, self.tag_cnt, self.state);
//trace!("cnt: {}, tag_cnt: {}, state: {:?}", self.cnt, self.tag_cnt, self.state);
return ret;
}

View File

@ -47,7 +47,7 @@ pub async fn starttls_connect(
let (in_rd, mut in_wr) = stream.split();
// send the stream_open
debug!("starttls sending: {} '{}'", server_name, to_str(&stream_open));
trace!("starttls sending: {} '{}'", server_name, to_str(&stream_open));
in_wr.write_all(&stream_open).await?;
in_wr.flush().await?;
@ -56,9 +56,9 @@ pub async fn starttls_connect(
let mut in_rd = StanzaReader(in_rd);
let mut proceed_received = false;
debug!("starttls reading stream open {}", server_name);
trace!("starttls reading stream open {}", server_name);
while let Ok(Some(buf)) = in_rd.next(&mut in_filter).await {
debug!("received pre-tls stanza: {} '{}'", server_name, to_str(&buf));
trace!("received pre-tls stanza: {} '{}'", server_name, to_str(&buf));
if buf.starts_with(b"<?xml ") {
// ignore this
} else if buf.starts_with(b"<stream:stream ") {
@ -66,7 +66,7 @@ pub async fn starttls_connect(
} else if buf.starts_with(b"<stream:features") {
// we send starttls regardless, it could have been stripped out, we don't do plaintext
let buf = br###"<starttls xmlns='urn:ietf:params:xml:ns:xmpp-tls'/>"###;
debug!("> {} '{}'", server_name, to_str(buf));
trace!("> {} '{}'", server_name, to_str(buf));
in_wr.write_all(buf).await?;
in_wr.flush().await?;
} else if buf.starts_with(b"<proceed ") {
@ -100,7 +100,7 @@ pub fn spawn_tls_listener(local_addr: SocketAddr, config: CloneableConfig, accep
let acceptor = acceptor.clone();
tokio::spawn(async move {
if let Err(e) = handle_tls_connection(stream, client_addr, local_addr, config, acceptor).await {
eprintln!("ERROR: {} {}", client_addr, e);
error!("{} {}", client_addr, e);
}
});
}
@ -111,7 +111,7 @@ pub fn spawn_tls_listener(local_addr: SocketAddr, config: CloneableConfig, accep
#[cfg(feature = "incoming")]
async fn handle_tls_connection(mut stream: tokio::net::TcpStream, client_addr: SocketAddr, local_addr: SocketAddr, config: CloneableConfig, acceptor: TlsAcceptor) -> Result<()> {
println!("INFO: {} connected", client_addr);
info!("{} connected", client_addr);
let mut in_filter = StanzaFilter::new(config.max_stanza_size_bytes);
@ -145,7 +145,7 @@ async fn handle_tls_connection(mut stream: tokio::net::TcpStream, client_addr: S
p[0] == 0x16 && p[1] == 0x03 && p[2] <= 0x03
};
println!("INFO: {} direct_tls: {}", client_addr, direct_tls);
info!("{} direct_tls: {}", client_addr, direct_tls);
// starttls
if !direct_tls {
@ -157,9 +157,9 @@ async fn handle_tls_connection(mut stream: tokio::net::TcpStream, client_addr: S
let mut in_rd = StanzaReader(in_rd);
while let Ok(Some(buf)) = in_rd.next(&mut in_filter).await {
debug!("received pre-tls stanza: {} '{}'", client_addr, to_str(&buf));
trace!("received pre-tls stanza: {} '{}'", client_addr, to_str(&buf));
if buf.starts_with(b"<?xml ") {
debug!("> {} '{}'", client_addr, to_str(&buf));
trace!("> {} '{}'", client_addr, to_str(&buf));
in_wr.write_all(&buf).await?;
in_wr.flush().await?;
} else if buf.starts_with(b"<stream:stream ") {
@ -176,18 +176,18 @@ async fn handle_tls_connection(mut stream: tokio::net::TcpStream, client_addr: S
.replace_first(br#" bla toblala="#, br#" id='xmpp-proxy' from="#)
};
debug!("> {} '{}'", client_addr, to_str(&buf));
trace!("> {} '{}'", client_addr, to_str(&buf));
in_wr.write_all(&buf).await?;
// ejabberd never sends <starttls/> with the first, only the second?
//let buf = br###"<features xmlns="http://etherx.jabber.org/streams"><starttls xmlns="urn:ietf:params:xml:ns:xmpp-tls"><required/></starttls></features>"###;
let buf = br###"<stream:features><starttls xmlns="urn:ietf:params:xml:ns:xmpp-tls"><required/></starttls></stream:features>"###;
debug!("> {} '{}'", client_addr, to_str(buf));
trace!("> {} '{}'", client_addr, to_str(buf));
in_wr.write_all(buf).await?;
in_wr.flush().await?;
} else if buf.starts_with(b"<starttls ") {
let buf = br###"<proceed xmlns="urn:ietf:params:xml:ns:xmpp-tls" />"###;
debug!("> {} '{}'", client_addr, to_str(buf));
trace!("> {} '{}'", client_addr, to_str(buf));
in_wr.write_all(buf).await?;
in_wr.flush().await?;
proceed_sent = true;

View File

@ -30,3 +30,10 @@ max_stanza_size_bytes = 262_144
# included systemd unit can only read files from /etc/xmpp-proxy/ so put them in there
tls_key = "/etc/xmpp-proxy/le.key"
tls_cert = "/etc/xmpp-proxy/fullchain.cer"
# configure logging, defaults are commented
# can also set env variables XMPP_PROXY_LOG_LEVEL and/or XMPP_PROXY_LOG_STYLE, but values in this file override them
# many options, trace is XML-console-level, refer to: https://docs.rs/env_logger/0.8.3/env_logger/#enabling-logging
#log_level = "info"
# one of auto, always, never, refer to: https://docs.rs/env_logger/0.8.3/env_logger/#disabling-colors
#log_style = "never"