chore: simplify debug logging for app readiness checks (#520)

* chore: simplify debug logging for app readiness checks

* chore: print debug log if app is not ready for more than 5 seconds

* chore: reduce web readiness check interval from 5 to 2 seconds

* chore: enhance debug logging for app readiness checks with URL context

* chore: change debug log level to info for app readiness checks

* chore: extract Checkpoint struct for readiness check

Author: DiscreteTom

src/lib.rs

@@ -1,6 +1,8 @@
 // Copyright Amazon.com, Inc. or its affiliates. All Rights Reserved.
 // SPDX-License-Identifier: Apache-2.0
 
+mod readiness;
+
 use http::{
     header::{HeaderName, HeaderValue},
     Method, StatusCode,
@@ -13,6 +15,7 @@ use lambda_http::request::RequestContext;
 use lambda_http::Body;
 pub use lambda_http::Error;
 use lambda_http::{Request, RequestExt, Response};
+use readiness::Checkpoint;
 use std::fmt::Debug;
 use std::{
     env,
@@ -24,8 +27,7 @@ use std::{
     },
     time::Duration,
 };
-use tokio::net::TcpStream;
-use tokio::time::timeout;
+use tokio::{net::TcpStream, time::timeout};
 use tokio_retry::{strategy::FixedInterval, Retry};
 use tower::{Service, ServiceBuilder};
 use tower_http::compression::CompressionLayer;
@@ -266,7 +268,12 @@ impl Adapter<HttpConnector, Body> {
     }
 
     async fn is_web_ready(&self, url: &Url, protocol: &Protocol) -> bool {
+        let mut checkpoint = Checkpoint::new();
         Retry::spawn(FixedInterval::from_millis(10), || {
+            if checkpoint.lapsed() {
+                tracing::info!(url = %url.to_string(), "app is not ready after {}ms", checkpoint.next_ms());
+                checkpoint.increment();
+            }
             self.check_web_readiness(url, protocol)
         })
         .await
@@ -282,10 +289,11 @@ impl Adapter<HttpConnector, Body> {
                             && response.status().as_u16() >= 100
                     } =>
                 {
+                    tracing::debug!("app is ready");
                     Ok(())
                 }
                 _ => {
-                    tracing::debug!("app is not ready");
+                    tracing::trace!("app is not ready");
                     Err(-1)
                 }
             },

src/readiness.rs

@@ -0,0 +1,63 @@
+use std::time::Instant;
+
+pub(crate) struct Checkpoint {
+    start: Instant,
+    interval_ms: u128,
+    next_ms: u128,
+}
+
+impl Checkpoint {
+    pub fn new() -> Checkpoint {
+        // The default function timeout is 3 seconds. This will alert the users. See #520
+        let interval_ms = 2000;
+
+        let start = Instant::now();
+        Checkpoint {
+            start,
+            interval_ms,
+            next_ms: start.elapsed().as_millis() + interval_ms,
+        }
+    }
+
+    pub const fn next_ms(&self) -> u128 {
+        self.next_ms
+    }
+
+    pub const fn increment(&mut self) {
+        self.next_ms += self.interval_ms;
+    }
+
+    pub fn lapsed(&self) -> bool {
+        self.start.elapsed().as_millis() >= self.next_ms
+    }
+}
+
+#[cfg(test)]
+mod tests {
+    use super::*;
+
+    #[test]
+    fn test_checkpoint_new() {
+        let checkpoint = Checkpoint::new();
+        assert_eq!(checkpoint.next_ms(), 2000);
+        assert!(!checkpoint.lapsed());
+    }
+
+    #[test]
+    fn test_checkpoint_increment() {
+        let mut checkpoint = Checkpoint::new();
+        checkpoint.increment();
+        assert_eq!(checkpoint.next_ms(), 4000);
+        assert!(!checkpoint.lapsed());
+    }
+
+    #[test]
+    fn test_checkpoint_lapsed() {
+        let checkpoint = Checkpoint {
+            start: Instant::now(),
+            interval_ms: 0,
+            next_ms: 0,
+        };
+        assert!(checkpoint.lapsed());
+    }
+}