More consistent logging for inpod (istio#1256)

Log UID wherever we can basically. Only other difference is to log the
error before we say we are retrying, instead of after (which makes it
seem like the error is after the retry)

src/inpod.rs

@@ -42,8 +42,8 @@ pub mod istio {
 
 #[derive(thiserror::Error, Debug)]
 pub enum Error {
-    #[error("error creating proxy: {0}")]
-    ProxyError(crate::proxy::Error),
+    #[error("error creating proxy {0}: {1}")]
+    ProxyError(String, crate::proxy::Error),
     #[error("error receiving message: {0}")]
     ReceiveMessageError(String),
     #[error("error sending ack: {0}")]

src/inpod/statemanager.rs

@@ -131,16 +131,21 @@ impl WorkloadProxyManagerState {
                 if !self.snapshot_received {
                     self.snapshot_names.insert(poddata.workload_uid.clone());
                 }
-                let netns = InpodNetns::new(self.inpod_config.cur_netns(), poddata.netns)
-                    .map_err(|e| Error::ProxyError(crate::proxy::Error::Io(e)))?;
+                let netns =
+                    InpodNetns::new(self.inpod_config.cur_netns(), poddata.netns).map_err(|e| {
+                        Error::ProxyError(
+                            poddata.workload_uid.0.clone(),
+                            crate::proxy::Error::Io(e),
+                        )
+                    })?;
                 let info = poddata.workload_info.map(|w| WorkloadInfo {
                     name: w.name,
                     namespace: w.namespace,
                     service_account: w.service_account,
                 });
                 self.add_workload(&poddata.workload_uid, info, netns)
                     .await
-                    .map_err(Error::ProxyError)
+                    .map_err(|e| Error::ProxyError(poddata.workload_uid.0, e))
             }
             WorkloadMessage::KeepWorkload(workload_uid) => {
                 info!(
@@ -173,7 +178,7 @@ impl WorkloadProxyManagerState {
                 Ok(())
             }
             WorkloadMessage::WorkloadSnapshotSent => {
-                info!("pod received snapshot sent");
+                info!("received snapshot sent");
                 if self.snapshot_received {
                     return Err(Error::ProtocolError("pod snapshot received already".into()));
                 }
@@ -328,6 +333,10 @@ impl WorkloadProxyManagerState {
         !self.pending_workloads.is_empty()
     }
 
+    pub fn pending_uids(&self) -> Vec<String> {
+        self.pending_workloads.keys().map(|k| k.0.clone()).collect()
+    }
+
     pub fn ready(&self) -> bool {
         // We are ready after we received our first snapshot and don't have any proxies that failed to start.
         self.snapshot_received && !self.have_pending()
@@ -337,11 +346,11 @@ impl WorkloadProxyManagerState {
         let current_pending_workloads = std::mem::take(&mut self.pending_workloads);
 
         for (uid, (info, netns)) in current_pending_workloads {
-            info!("retrying workload {:?}", uid);
+            info!(uid = uid.0, "retrying workload");
             match self.add_workload(&uid, info, netns).await {
                 Ok(()) => {}
                 Err(e) => {
-                    info!("retrying workload {:?} failed: {}", uid, e);
+                    info!(uid = uid.0, "retrying workload failed: {}", e);
                 }
             }
         }

src/inpod/workloadmanager.rs

@@ -335,12 +335,12 @@ impl<'a> WorkloadProxyManagerProcessor<'a> {
                         .await
                         .map_err(|e| Error::SendAckError(e.to_string()))?;
                 }
-                Err(Error::ProxyError(e)) => {
+                Err(Error::ProxyError(uid, e)) => {
+                    error!(%uid, "failed to start proxy: {:?}", e);
                     // setup the retry timer:
                     self.schedule_retry();
                     // proxy error is a transient error, so report it but don't disconnect
                     // TODO: raise metrics
-                    error!("failed to start proxy: {:?}", e);
                     processor
                         .send_nack(anyhow::anyhow!("failure to start proxy : {:?}", e))
                         .await
@@ -363,10 +363,11 @@ impl<'a> WorkloadProxyManagerProcessor<'a> {
 
     fn schedule_retry(&mut self) {
         if self.next_pending_retry.is_none() {
-            info!("scheduling retry");
+            info!(uids=?self.state.pending_uids(), "scheduling retry");
             self.next_pending_retry = Some(Box::pin(tokio::time::sleep(RETRY_DURATION)));
         }
     }
+
     fn check_ready(&mut self) {
         if self.state.ready() {
             self.readiness.mark_ready();