Add debug logging.

Could be helpful when troubleshooting issues with various providers if
the user is able to turn on debug logging. The most critical logging
provided is the request and responses sent and received from the oauth
servers.
This commit is contained in:
Glenn Griffin
2019-12-02 10:56:13 -08:00
parent 6817fce0bc
commit 5c0334ee6f
6 changed files with 68 additions and 16 deletions

View File

@@ -10,6 +10,7 @@ use crate::types::{AccessToken, ApplicationSecret, TokenInfo};
use private::AuthFlow;
use std::borrow::Cow;
use std::fmt;
use std::io;
use std::path::PathBuf;
use std::sync::Mutex;
@@ -22,6 +23,25 @@ pub struct Authenticator<C> {
auth_flow: AuthFlow,
}
struct DisplayScopes<'a, T>(&'a [T]);
impl<'a, T> fmt::Display for DisplayScopes<'a, T>
where
T: AsRef<str>,
{
fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
f.write_str("[")?;
let mut iter = self.0.iter();
if let Some(first) = iter.next() {
f.write_str(first.as_ref())?;
for scope in iter {
f.write_str(", ")?;
f.write_str(scope.as_ref())?;
}
}
f.write_str("]")
}
}
impl<C> Authenticator<C>
where
C: hyper::client::connect::Connect + 'static,
@@ -31,10 +51,15 @@ where
where
T: AsRef<str>,
{
log::debug!(
"access token requested for scopes: {}",
DisplayScopes(scopes)
);
let hashed_scopes = storage::ScopeSet::from(scopes);
match (self.storage.get(hashed_scopes), self.auth_flow.app_secret()) {
(Some(t), _) if !t.is_expired() => {
// unexpired token found
log::debug!("found valid token in cache: {:?}", t);
Ok(t.into())
}
(

View File

@@ -55,6 +55,7 @@ impl DeviceFlow {
scopes,
)
.await?;
log::debug!("Presenting code to user");
self.flow_delegate
.present_user_code(&device_auth_resp)
.await;
@@ -78,6 +79,7 @@ impl DeviceFlow {
C: hyper::client::connect::Connect + 'static,
{
let mut interval = device_auth_resp.interval;
log::debug!("Polling every {:?} for device token", interval);
loop {
tokio::timer::delay_for(interval).await;
interval = match Self::poll_token(
@@ -92,10 +94,16 @@ impl DeviceFlow {
Err(Error::AuthError(AuthError { error, .. }))
if error.as_str() == "authorization_pending" =>
{
log::debug!("still waiting on authorization from the server");
interval
}
Err(Error::AuthError(AuthError { error, .. })) if error.as_str() == "slow_down" => {
interval + Duration::from_secs(5)
let interval = interval + Duration::from_secs(5);
log::debug!(
"server requested slow_down. Increasing polling interval to {:?}",
interval
);
interval
}
Err(err) => return Err(err),
}
@@ -140,8 +148,10 @@ impl DeviceFlow {
.header(header::CONTENT_TYPE, "application/x-www-form-urlencoded")
.body(hyper::Body::from(req))
.unwrap();
let resp = client.request(req).await?;
let body = resp.into_body().try_concat().await?;
log::debug!("requesting code from server: {:?}", req);
let (head, body) = client.request(req).await?.into_parts();
let body = body.try_concat().await?;
log::debug!("received response; head: {:?}, body: {:?}", head, body);
DeviceAuthResponse::from_json(&body)
}
@@ -186,8 +196,10 @@ impl DeviceFlow {
.header(header::CONTENT_TYPE, "application/x-www-form-urlencoded")
.body(hyper::Body::from(req))
.unwrap(); // TODO: Error checking
let res = client.request(request).await?;
let body = res.into_body().try_concat().await?;
log::debug!("polling for token: {:?}", request);
let (head, body) = client.request(request).await?.into_parts();
let body = body.try_concat().await?;
log::debug!("received response; head: {:?} body: {:?}", head, body);
TokenInfo::from_json(&body)
}
}

View File

@@ -126,12 +126,14 @@ impl InstalledFlow {
scopes,
self.flow_delegate.redirect_uri(),
);
let authcode = self
log::debug!("Presenting auth url to user: {}", url);
let auth_code = self
.flow_delegate
.present_user_url(&url, true /* need code */)
.await
.map_err(Error::UserError)?;
self.exchange_auth_code(&authcode, hyper_client, app_secret, None)
log::debug!("Received auth code: {}", auth_code);
self.exchange_auth_code(&auth_code, hyper_client, app_secret, None)
.await
}
@@ -162,11 +164,11 @@ impl InstalledFlow {
scopes,
Some(redirect_uri.as_ref()),
);
log::debug!("Presenting auth url to user: {}", url);
let _ = self
.flow_delegate
.present_user_url(&url, false /* need code */)
.await;
let auth_code = server.wait_for_auth_code().await;
self.exchange_auth_code(&auth_code, hyper_client, app_secret, Some(server_addr))
.await
@@ -184,8 +186,10 @@ impl InstalledFlow {
{
let redirect_uri = self.flow_delegate.redirect_uri();
let request = Self::request_token(app_secret, authcode, redirect_uri, server_addr);
let resp = hyper_client.request(request).await?;
let body = resp.into_body().try_concat().await?;
log::debug!("Sending request: {:?}", request);
let (head, body) = hyper_client.request(request).await?.into_parts();
let body = body.try_concat().await?;
log::debug!("Received response; head: {:?} body: {:?}", head, body);
TokenInfo::from_json(&body)
}
@@ -265,6 +269,7 @@ impl InstalledFlowServer {
})
.await;
});
log::debug!("HTTP server listening on {}", addr);
Ok(InstalledFlowServer {
addr,
auth_code_rx,
@@ -278,11 +283,14 @@ impl InstalledFlowServer {
}
async fn wait_for_auth_code(self) -> String {
log::debug!("Waiting for HTTP server to receive auth code");
// Wait for the auth code from the server.
let auth_code = self
.auth_code_rx
.await
.expect("server shutdown while waiting for auth_code");
log::debug!("HTTP server received auth code: {}", auth_code);
log::debug!("Shutting down HTTP server");
// auth code received. shutdown the server
let _ = self.trigger_shutdown_tx.send(());
self.shutdown_complete.await;

View File

@@ -32,6 +32,10 @@ impl RefreshFlow {
client_secret: &ApplicationSecret,
refresh_token: &str,
) -> Result<TokenInfo, Error> {
log::debug!(
"refreshing access token with refresh token: {}",
refresh_token
);
let req = form_urlencoded::Serializer::new(String::new())
.extend_pairs(&[
("client_id", client_secret.client_id.as_str()),
@@ -45,9 +49,10 @@ impl RefreshFlow {
.header(header::CONTENT_TYPE, "application/x-www-form-urlencoded")
.body(hyper::Body::from(req))
.unwrap();
let resp = client.request(request).await?;
let body = resp.into_body().try_concat().await?;
log::debug!("Sending request: {:?}", request);
let (head, body) = client.request(request).await?.into_parts();
let body = body.try_concat().await?;
log::debug!("Received response; head: {:?}, body: {:?}", head, body);
let mut token = TokenInfo::from_json(&body)?;
// If the refresh result contains a refresh_token use it, otherwise
// continue using our previous refresh_token.

View File

@@ -200,8 +200,10 @@ impl ServiceAccountFlow {
.header(header::CONTENT_TYPE, "application/x-www-form-urlencoded")
.body(hyper::Body::from(rqbody))
.unwrap();
let response = hyper_client.request(request).await?;
let body = response.into_body().try_concat().await?;
log::debug!("requesting token from service account: {:?}", request);
let (head, body) = hyper_client.request(request).await?.into_parts();
let body = body.try_concat().await?;
log::debug!("received response; head: {:?}, body: {:?}", head, body);
TokenInfo::from_json(&body)
}
}

View File

@@ -227,7 +227,7 @@ impl<'de> Deserialize<'de> for JSONTokens {
}
// Instantiate our Visitor and ask the Deserializer to drive
// it over the input data, resulting in an instance of MyMap.
// it over the input data.
deserializer.deserialize_seq(V)
}
}