Add real logging

This commit is contained in:
Brian Picciano 2023-06-13 21:33:43 +02:00
parent d93d4accba
commit 01b47fb010
6 changed files with 80 additions and 32 deletions

37
Cargo.lock generated
View File

@ -449,12 +449,14 @@ version = "0.1.0"
dependencies = [ dependencies = [
"acme2", "acme2",
"clap", "clap",
"env_logger",
"futures", "futures",
"gix", "gix",
"handlebars", "handlebars",
"hex", "hex",
"http", "http",
"hyper", "hyper",
"log",
"mime_guess", "mime_guess",
"mockall", "mockall",
"openssl", "openssl",
@ -522,6 +524,19 @@ dependencies = [
"syn 1.0.109", "syn 1.0.109",
] ]
[[package]]
name = "env_logger"
version = "0.10.0"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "85cdab6a89accf66733ad5a1693a4dcced6aeff64602b634530dd73c1f3ee9f0"
dependencies = [
"humantime",
"is-terminal",
"log",
"regex",
"termcolor",
]
[[package]] [[package]]
name = "errno" name = "errno"
version = "0.3.1" version = "0.3.1"
@ -1468,6 +1483,12 @@ version = "1.0.3"
source = "registry+https://github.com/rust-lang/crates.io-index" source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "86cce260d758a9aa3d7c4b99d55c815a540f8a37514ba6046ab6be402a157cb0" checksum = "86cce260d758a9aa3d7c4b99d55c815a540f8a37514ba6046ab6be402a157cb0"
[[package]]
name = "humantime"
version = "2.1.0"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "9a3a5bfb195931eeb336b2a7b4d761daec841b97f947d34394601737a7bba5e4"
[[package]] [[package]]
name = "hyper" name = "hyper"
version = "0.14.26" version = "0.14.26"
@ -1715,12 +1736,9 @@ dependencies = [
[[package]] [[package]]
name = "log" name = "log"
version = "0.4.17" version = "0.4.19"
source = "registry+https://github.com/rust-lang/crates.io-index" source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "abb12e687cfb44aa40f41fc3978ef76448f9b6038cad6aef4259d3c095a2382e" checksum = "b06a4cde4c0f271a446782e3eff8de789548ce57dbc8eca9292c27f4a42004b4"
dependencies = [
"cfg-if",
]
[[package]] [[package]]
name = "lru-cache" name = "lru-cache"
@ -2689,6 +2707,15 @@ dependencies = [
"windows-sys 0.45.0", "windows-sys 0.45.0",
] ]
[[package]]
name = "termcolor"
version = "1.2.0"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "be55cf8942feac5c765c2c993422806843c9a9a45d4d5c407ad6dd2ea95eb9b6"
dependencies = [
"winapi-util",
]
[[package]] [[package]]
name = "termtree" name = "termtree"
version = "0.4.1" version = "0.4.1"

View File

@ -39,3 +39,5 @@ pem = "2.0.1"
serde_with = "3.0.0" serde_with = "3.0.0"
tls-listener = { version = "0.7.0", features = [ "rustls", "hyper-h1" ]} tls-listener = { version = "0.7.0", features = [ "rustls", "hyper-h1" ]}
tokio-rustls = "0.24.0" tokio-rustls = "0.24.0"
log = "0.4.19"
env_logger = "0.10.0"

1
TODO
View File

@ -1,4 +1,3 @@
- logging
- expect statements (pretend it's "expected", not "expect") - expect statements (pretend it's "expected", not "expect")
- map_unexpected annotation string - map_unexpected annotation string
- clean up main a lot - clean up main a lot

View File

@ -104,7 +104,7 @@ where
} }
} }
println!("fetching a new certificate for domain {}", domain.as_str()); log::info!("Fetching a new certificate for domain {}", domain.as_str());
let mut builder = acme2::OrderBuilder::new(self.account.clone()); let mut builder = acme2::OrderBuilder::new(self.account.clone());
builder.add_dns_identifier(domain.as_str().to_string()); builder.add_dns_identifier(domain.as_str().to_string());
let order = builder.build().await.map_unexpected()?; let order = builder.build().await.map_unexpected()?;
@ -137,8 +137,8 @@ where
// `validate()` call below will instigate the acme server to make this check, and // `validate()` call below will instigate the acme server to make this check, and
// block until it succeeds. // block until it succeeds.
println!( log::info!(
"waiting for ACME challenge to be validated for domain {}", "Waiting for ACME challenge to be validated for domain {}",
domain.as_str(), domain.as_str(),
); );
let challenge = challenge.validate().await.map_unexpected()?; let challenge = challenge.validate().await.map_unexpected()?;
@ -166,8 +166,8 @@ where
// Poll the authorization every 5 seconds until it is in either the // Poll the authorization every 5 seconds until it is in either the
// `valid` or `invalid` state. // `valid` or `invalid` state.
println!( log::info!(
"waiting for ACME authorization to be validated for domain {}", "Waiting for ACME authorization to be validated for domain {}",
domain.as_str(), domain.as_str(),
); );
@ -189,8 +189,8 @@ where
// Poll the order every 5 seconds until it is in either the `ready` or `invalid` state. // Poll the order every 5 seconds until it is in either the `ready` or `invalid` state.
// Ready means that it is now ready for finalization (certificate creation). // Ready means that it is now ready for finalization (certificate creation).
println!( log::info!(
"waiting for ACME order to be made ready for domain {}", "Waiting for ACME order to be made ready for domain {}",
domain.as_str(), domain.as_str(),
); );
@ -224,8 +224,8 @@ where
// Poll the order every 5 seconds until it is in either the // Poll the order every 5 seconds until it is in either the
// `valid` or `invalid` state. Valid means that the certificate // `valid` or `invalid` state. Valid means that the certificate
// has been provisioned, and is now ready for download. // has been provisioned, and is now ready for download.
println!( log::info!(
"waiting for ACME order to be validated for domain {}", "Waiting for ACME order to be validated for domain {}",
domain.as_str(), domain.as_str(),
); );
let order = order let order = order
@ -244,7 +244,7 @@ where
} }
// Download the certificate, and panic if it doesn't exist. // Download the certificate, and panic if it doesn't exist.
println!("fetching certificate for domain {}", domain.as_str()); log::info!("Fetching certificate for domain {}", domain.as_str());
let cert = order let cert = order
.certificate() .certificate()
.await .await
@ -267,7 +267,7 @@ where
)); ));
} }
println!("certificate for {} successfully retrieved", domain.as_str()); log::info!("Certificate for {} successfully retrieved", domain.as_str());
self.store self.store
.set_certificate(domain.as_str(), pkey, cert) .set_certificate(domain.as_str(), pkey, cert)
.map_unexpected()?; .map_unexpected()?;

View File

@ -198,7 +198,7 @@ impl rustls::server::ResolvesServerCert for BoxedFSStore {
match self.get_certificate(domain) { match self.get_certificate(domain) {
Err(GetCertificateError::NotFound) => { Err(GetCertificateError::NotFound) => {
println!("No cert found for domain {domain}"); log::warn!("No cert found for domain {domain}");
Ok(None) Ok(None)
} }
Err(GetCertificateError::Unexpected(err)) => Err(err), Err(GetCertificateError::Unexpected(err)) => Err(err),
@ -215,7 +215,7 @@ impl rustls::server::ResolvesServerCert for BoxedFSStore {
} }
} }
.unwrap_or_else(|err| { .unwrap_or_else(|err| {
println!("Unexpected error getting cert for domain {domain}: {err}"); log::error!("Unexpected error getting cert for domain {domain}: {err}");
None None
}) })
} }

View File

@ -19,6 +19,17 @@ use domiply::domain::manager::Manager;
#[command(version)] #[command(version)]
#[command(about = "A domiply to another dimension")] #[command(about = "A domiply to another dimension")]
struct Cli { struct Cli {
#[arg(
long,
help = "OFF, ERROR, WARN, INFO, DEBUG, or TRACE",
default_value_t = log::LevelFilter::Info,
env = "DOMIPLY_LOG_LEVEL"
)]
log_level: log::LevelFilter,
#[arg(long, default_value_t = false, env = "DOMIPLY_LOG_TIMESTAMP")]
log_timestamp: bool,
#[arg(long, required = true, env = "DOMIPLY_HTTP_DOMAIN")] #[arg(long, required = true, env = "DOMIPLY_HTTP_DOMAIN")]
http_domain: domiply::domain::Name, http_domain: domiply::domain::Name,
@ -71,6 +82,15 @@ where
async fn main() { async fn main() {
let config = Cli::parse(); let config = Cli::parse();
env_logger::Builder::new()
.filter_level(config.log_level)
.format_timestamp(
config
.log_timestamp
.then_some(env_logger::TimestampPrecision::Micros),
)
.init();
let mut wait_group = FuturesUnordered::new(); let mut wait_group = FuturesUnordered::new();
let canceller = tokio_util::sync::CancellationToken::new(); let canceller = tokio_util::sync::CancellationToken::new();
@ -82,12 +102,12 @@ async fn main() {
Signals::new(signal_hook::consts::TERM_SIGNALS).expect("initialized signals"); Signals::new(signal_hook::consts::TERM_SIGNALS).expect("initialized signals");
if (signals.next().await).is_some() { if (signals.next().await).is_some() {
println!("Gracefully shutting down..."); log::info!("Gracefully shutting down...");
canceller.cancel(); canceller.cancel();
} }
if (signals.next().await).is_some() { if (signals.next().await).is_some() {
println!("Forcefully shutting down"); log::warn!("Forcefully shutting down");
std::process::exit(1); std::process::exit(1);
}; };
}); });
@ -157,7 +177,7 @@ async fn main() {
let errors_iter = domain_manager.sync_all_origins(); let errors_iter = domain_manager.sync_all_origins();
if let Err(err) = errors_iter { if let Err(err) = errors_iter {
println!("Got error calling sync_all_origins: {err}"); log::error!("Got error calling sync_all_origins: {err}");
continue; continue;
} }
@ -165,8 +185,8 @@ async fn main() {
.unwrap() .unwrap()
.into_iter() .into_iter()
.for_each(|(descr, err)| match descr { .for_each(|(descr, err)| match descr {
None => println!("error while syncing unknown descr: {err}"), None => log::error!("Error while syncing unknown descr: {err}"),
Some(descr) => println!("failed to sync {descr:?}: {err}"), Some(descr) => log::error!("Failed to sync {descr:?}: {err}"),
}); });
} }
}) })
@ -201,7 +221,7 @@ async fn main() {
tokio::spawn(async move { tokio::spawn(async move {
let addr = config.http_listen_addr; let addr = config.http_listen_addr;
println!( log::info!(
"Listening on http://{}:{}", "Listening on http://{}:{}",
http_domain.as_str(), http_domain.as_str(),
addr.port() addr.port()
@ -240,7 +260,7 @@ async fn main() {
.sync_domain(http_domain.clone()) .sync_domain(http_domain.clone())
.await .await
.inspect_err(|err| { .inspect_err(|err| {
println!( log::error!(
"Error while getting cert for {}: {err}", "Error while getting cert for {}: {err}",
http_domain.as_str() http_domain.as_str()
) )
@ -249,7 +269,7 @@ async fn main() {
let domains_iter = domain_manager.all_domains(); let domains_iter = domain_manager.all_domains();
if let Err(err) = domains_iter { if let Err(err) = domains_iter {
println!("Got error calling all_domains: {err}"); log::error!("Got error calling all_domains: {err}");
continue; continue;
} }
@ -261,13 +281,13 @@ async fn main() {
.sync_domain(domain.clone()) .sync_domain(domain.clone())
.await .await
.inspect_err(|err| { .inspect_err(|err| {
println!( log::error!(
"Error while getting cert for {}: {err}", "Error while getting cert for {}: {err}",
domain.as_str(), domain.as_str(),
) )
}); });
} }
Err(err) => println!("Error iterating through domains: {err}"), Err(err) => log::error!("Error iterating through domains: {err}"),
}; };
} }
} }
@ -310,7 +330,7 @@ async fn main() {
let incoming = let incoming =
tls_listener::TlsListener::new(server_config, addr_incoming).filter(|conn| { tls_listener::TlsListener::new(server_config, addr_incoming).filter(|conn| {
if let Err(err) = conn { if let Err(err) = conn {
println!("Error accepting TLS connection: {:?}", err); log::error!("Error accepting TLS connection: {:?}", err);
future::ready(false) future::ready(false)
} else { } else {
future::ready(true) future::ready(true)
@ -319,7 +339,7 @@ async fn main() {
let incoming = hyper::server::accept::from_stream(incoming); let incoming = hyper::server::accept::from_stream(incoming);
println!( log::info!(
"Listening on https://{}:{}", "Listening on https://{}:{}",
http_domain.as_str(), http_domain.as_str(),
addr.port() addr.port()
@ -340,5 +360,5 @@ async fn main() {
while wait_group.next().await.is_some() {} while wait_group.next().await.is_some() {}
println!("Graceful shutdown complete"); log::info!("Graceful shutdown complete");
} }