Nested Longhaul Tests: Various small improvements (#5061)

* bump edgehub log rotation

* explicitly catch unauthorized exception

* move delays to beginning of operation

* missed nested deployment files

* compress logs for log upload

* don't fail out for transient dns errors

* don't throw for weird exception types

* show missing logs for connectivity tests

e2e_deployment_files/long_haul_deployment.template.json

@@ -28,7 +28,7 @@
                 "value": "true"
               },
               "RuntimeLogLevel": {
-                "value": "debug"
+                "value": "info"
               }
             },
             "settings": {
@@ -46,11 +46,14 @@
               },
               "NestedEdgeEnabled": {
                 "value": "false"
+              },
+              "RuntimeLogLevel": {
+                "value": "debug"
               }
             },
             "settings": {
               "image": "<Container_Registry>/microsoft/azureiotedge-hub:<EdgeRuntime.BuildNumber>-linux-<Architecture>",
-              "createOptions": "{\"ExposedPorts\": {\"9600/tcp\": {}}, \"HostConfig\": {\"LogConfig\":{\"Type\":\"json-file\",\"Config\":{\"max-size\":\"4m\",\"max-file\":\"<LogRotationMaxFile>\",\"compress\":\"true\"}}, \"PortBindings\": {\"8883/tcp\": [{\"HostPort\": \"8883\"}],\"5671/tcp\": [{\"HostPort\": \"5671\"}],\"9600/tcp\": [{\"HostPort\": \"9601\"}]}}}"
+              "createOptions": "{\"ExposedPorts\": {\"9600/tcp\": {}}, \"HostConfig\": {\"LogConfig\":{\"Type\":\"json-file\",\"Config\":{\"max-size\":\"4m\",\"max-file\":\"<LogRotationMaxFileEdgeHub>\",\"compress\":\"true\"}}, \"PortBindings\": {\"8883/tcp\": [{\"HostPort\": \"8883\"}],\"5671/tcp\": [{\"HostPort\": \"5671\"}],\"9600/tcp\": [{\"HostPort\": \"9601\"}]}}}"
             }
           }
         },

e2e_deployment_files/nestededge_bottomLayerBaseDeployment_long_haul_amqp.template.json

@@ -28,7 +28,7 @@
                 "value": "true"
               },
               "RuntimeLogLevel": {
-                "value": "debug"
+                "value": "info"
               }
             },
             "settings": {
@@ -47,7 +47,7 @@
             },
             "settings": {
               "image": "<Container_Registry>/microsoft/azureiotedge-hub:<EdgeRuntime.BuildNumber>-linux-<Architecture>",
-              "createOptions": "{\"ExposedPorts\": {\"9600/tcp\": {}}, \"HostConfig\": {\"LogConfig\":{\"Type\":\"json-file\",\"Config\":{\"max-size\":\"4m\",\"max-file\":\"<LogRotationMaxFile>\",\"compress\":\"true\"}}, \"PortBindings\": {\"8883/tcp\": [{\"HostPort\": \"8883\"}],\"5671/tcp\": [{\"HostPort\": \"5671\"}],\"9600/tcp\": [{\"HostPort\": \"9601\"}]}}}"
+              "createOptions": "{\"ExposedPorts\": {\"9600/tcp\": {}}, \"HostConfig\": {\"LogConfig\":{\"Type\":\"json-file\",\"Config\":{\"max-size\":\"4m\",\"max-file\":\"<LogRotationMaxFileEdgeHub>\",\"compress\":\"true\"}}, \"PortBindings\": {\"8883/tcp\": [{\"HostPort\": \"8883\"}],\"5671/tcp\": [{\"HostPort\": \"5671\"}],\"9600/tcp\": [{\"HostPort\": \"9601\"}]}}}"
             }
           }
         },

e2e_deployment_files/nestededge_bottomLayerBaseDeployment_long_haul_mqtt.template.json

@@ -28,7 +28,7 @@
                 "value": "true"
               },
               "RuntimeLogLevel": {
-                "value": "debug"
+                "value": "info"
               }
             },
             "settings": {
@@ -56,7 +56,7 @@
             },
             "settings": {
               "image": "<Container_Registry>/microsoft/azureiotedge-hub:<EdgeRuntime.BuildNumber>-linux-<Architecture>",
-              "createOptions": "{\"ExposedPorts\": {\"9600/tcp\": {}}, \"HostConfig\": {\"LogConfig\":{\"Type\":\"json-file\",\"Config\":{\"max-size\":\"4m\",\"max-file\":\"<LogRotationMaxFile>\",\"compress\":\"true\"}}, \"PortBindings\": {\"8883/tcp\": [{\"HostPort\": \"8883\"}],\"5671/tcp\": [{\"HostPort\": \"5671\"}],\"9600/tcp\": [{\"HostPort\": \"9601\"}]}}}"
+              "createOptions": "{\"ExposedPorts\": {\"9600/tcp\": {}}, \"HostConfig\": {\"LogConfig\":{\"Type\":\"json-file\",\"Config\":{\"max-size\":\"4m\",\"max-file\":\"<LogRotationMaxFileEdgeHub>\",\"compress\":\"true\"}}, \"PortBindings\": {\"8883/tcp\": [{\"HostPort\": \"8883\"}],\"5671/tcp\": [{\"HostPort\": \"5671\"}],\"9600/tcp\": [{\"HostPort\": \"9601\"}]}}}"
             }
           }
         },

scripts/linux/trcE2ETest.sh

@@ -211,6 +211,7 @@ function prepare_test_from_artifacts() {
     sed -i -e "s@<TestMode>@$TEST_MODE@g" "$deployment_working_file"
 
     sed -i -e "s@<LogRotationMaxFile>@$log_rotation_max_file@g" "$deployment_working_file"
+    sed -i -e "s@<LogRotationMaxFileEdgeHub>@$log_rotation_max_file_edgehub@g" "$deployment_working_file"
 
     if [[ "${TEST_NAME,,}" == "${LONGHAUL_TEST_NAME,,}" ]]; then
         sed -i -e "s@<DesiredModulesToRestartCSV>@$DESIRED_MODULES_TO_RESTART_CSV@g" "$deployment_working_file"
@@ -310,6 +311,9 @@ function print_test_run_logs() {
     print_highlighted_message 'directMethodReceiver2 LOGS'
     docker logs directMethodReceiver2 || true
 
+    print_highlighted_message 'directMethodSender3 LOGS'
+    docker logs directMethodSender3 || true
+
     print_highlighted_message 'twinTester1 LOGS'
     docker logs twinTester1 || true
 
@@ -322,6 +326,25 @@ function print_test_run_logs() {
     print_highlighted_message 'twinTester4 LOGS'
     docker logs twinTester4 || true
 
+    print_highlighted_message 'deploymentTester1 LOGS'
+    docker logs deploymentTester1 || true
+
+    print_highlighted_message 'deploymentTester2 LOGS'
+    docker logs deploymentTester2 || true
+
+    print_highlighted_message 'cloudToDeviceMessageSender1 LOGS'
+    docker logs cloudToDeviceMessageSender1 || true
+
+    print_highlighted_message 'cloudToDeviceMessageReceiver1 LOGS'
+    docker logs cloudToDeviceMessageReceiver1 || true
+
+    print_highlighted_message 'cloudToDeviceMessageSender2 LOGS'
+    docker logs cloudToDeviceMessageSender2 || true
+
+    print_highlighted_message 'cloudToDeviceMessageReceiver2 LOGS'
+    docker logs cloudToDeviceMessageReceiver2 || true
+
+
     print_highlighted_message 'networkController LOGS'
     docker logs networkController || true
 }
@@ -859,6 +882,7 @@ if [ "$image_architecture_label" = 'amd64' ]; then
     optimize_for_performance=true
     log_upload_enabled=true
     log_rotation_max_file="125"
+    log_rotation_max_file_edgehub="400"
 
     LOADGEN_MESSAGE_FREQUENCY="00:00:01"
     TWIN_UPDATE_FREQUENCY="00:00:15"
@@ -869,6 +893,7 @@ if [ "$image_architecture_label" = 'arm32v7' ] ||
     optimize_for_performance=false
     log_upload_enabled=false
     log_rotation_max_file="7"
+    log_rotation_max_file_edgehub="30"
 
     LOADGEN_MESSAGE_FREQUENCY="00:00:10"
     TWIN_UPDATE_FREQUENCY="00:01:00"

test/modules/DirectMethodSender/DirectMethodSenderBase.cs

@@ -52,6 +52,11 @@ public async Task<Tuple<HttpStatusCode, ulong>> InvokeDirectMethodAsync(string m
                 logger.LogInformation($"Invoke DirectMethod with count {this.directMethodCount}: finished.");
                 return new Tuple<HttpStatusCode, ulong>((HttpStatusCode)resultStatus, this.directMethodCount);
             }
+            catch (UnauthorizedException e)
+            {
+                logger.LogInformation(e, $"Unauthorized exception caught with count {this.directMethodCount}");
+                return new Tuple<HttpStatusCode, ulong>(HttpStatusCode.Unauthorized, this.directMethodCount);
+            }
             catch (DeviceNotFoundException e)
             {
                 logger.LogInformation(e, $"DeviceNotFound exception caught with count {this.directMethodCount}");

test/modules/DirectMethodSender/Program.cs

@@ -41,6 +41,8 @@ public static async Task<int> MainAsync()
 
                 while (!cts.Token.IsCancellationRequested && IsTestTimeUp(testStartAt))
                 {
+                    await Task.Delay(Settings.Current.DirectMethodFrequency, cts.Token);
+
                     (HttpStatusCode resultStatusCode, ulong dmCounter) = await directMethodClient.InvokeDirectMethodAsync(Settings.Current.DirectMethodName, cts);
                     DirectMethodResultType resultType = Settings.Current.DirectMethodResultType;
 
@@ -55,8 +57,6 @@ public static async Task<int> MainAsync()
 
                         await reportClient.SendTestResultAsync(testResult);
                     }
-
-                    await Task.Delay(Settings.Current.DirectMethodFrequency, cts.Token);
                 }
 
                 await cts.Token.WhenCanceled();

test/modules/TestResultCoordinator/Reports/DirectMethod/Connectivity/DirectMethodConnectivityReportGenerator.cs

@@ -278,13 +278,9 @@ async Task<DirectMethodReportGeneratorMetadata> ProcessSenderTestResults(
                         networkOffFailure++;
                     }
                 }
-                else if (HttpStatusCode.InternalServerError.Equals(statusCode))
-                {
-                    networkOffFailure++;
-                }
                 else
                 {
-                    throw new InvalidDataException($"Unexpected HttpStatusCode of {statusCode}");
+                    networkOffFailure++;
                 }
             }
 

test/modules/TestResultCoordinator/TestReportUtil.cs

@@ -156,7 +156,7 @@ internal static async Task UploadLogsAsync(string iotHubConnectionString, Uri bl
             ServiceClient serviceClient = ServiceClient.CreateFromConnectionString(iotHubConnectionString);
             CloudToDeviceMethod uploadLogRequest =
                 new CloudToDeviceMethod("UploadModuleLogs")
-                    .SetPayloadJson($"{{ \"schemaVersion\": \"1.0\", \"sasUrl\": \"{blobContainerWriteUri.AbsoluteUri}\", \"items\": [{{ \"id\": \".*\", \"filter\": {{}} }}], \"encoding\": \"none\",\"content-type\": \"text\" }}");
+                .SetPayloadJson($"{{ \"schemaVersion\": \"1.0\", \"sasUrl\": \"{blobContainerWriteUri.AbsoluteUri}\", \"items\": [{{ \"id\": \".*\", \"filter\": {{}} }}], \"encoding\": \"gzip\", \"contentType\": \"json\" }}");
 
             CloudToDeviceMethodResult uploadLogResponse = await serviceClient.InvokeDeviceMethodAsync(Settings.Current.DeviceId, "$edgeAgent", uploadLogRequest);
 

test/modules/generic-mqtt-tester/src/lib.rs

@@ -20,7 +20,6 @@ use std::{
 use bytes::Buf;
 use mqtt3::{PublishError, ReceivedPublication, UpdateSubscriptionError};
 use tokio::{sync::mpsc::error::SendError, sync::mpsc::Sender, task::JoinError};
-use trc_client::ReportResultError;
 
 pub mod message_channel;
 pub mod message_initiator;
@@ -101,9 +100,6 @@ pub enum MessageTesterError {
     #[error("failed to parse publication payload: {0:?}")]
     DeserializePayload(#[from] serde_json::Error),
 
-    #[error("failed to report test result: {0:?}")]
-    ReportResult(#[from] ReportResultError),
-
     #[error("received rejected subscription: {0}")]
     RejectedSubscription(String),
 

test/modules/generic-mqtt-tester/src/message_channel.rs

@@ -63,10 +63,14 @@ impl MessageHandler for ReportResultMessageHandler {
 
         let test_type = trc_client::TestType::Messages;
         let created_at = chrono::Utc::now();
-        self.reporting_client
+
+        if let Err(e) = self
+            .reporting_client
             .report_result(self.report_source.clone(), result, test_type, created_at)
             .await
-            .map_err(MessageTesterError::ReportResult)?;
+        {
+            error!("error reporting result to trc: {:?}", e);
+        }
 
         Ok(())
     }

test/modules/generic-mqtt-tester/src/message_initiator.rs

@@ -10,6 +10,7 @@ use tokio::{
     sync::mpsc::{self, Receiver},
     time,
 };
+use tracing::error;
 use tracing::info;
 use uuid::{self, Uuid};
 
@@ -106,7 +107,7 @@ impl MessageInitiator {
                 }
             };
 
-            self.report_message_sent(seq_num).await?;
+            self.report_message_sent(seq_num).await;
             seq_num += 1;
 
             time::delay_for(self.message_frequency).await;
@@ -119,7 +120,7 @@ impl MessageInitiator {
         self.shutdown_handle.clone()
     }
 
-    async fn report_message_sent(&self, sequence_number: u32) -> Result<(), MessageTesterError> {
+    async fn report_message_sent(&self, sequence_number: u32) {
         let result = MessageTestResult::new(
             self.tracking_id.clone(),
             self.batch_id.to_string(),
@@ -128,11 +129,13 @@ impl MessageInitiator {
 
         let test_type = trc_client::TestType::Messages;
         let created_at = chrono::Utc::now();
-        self.reporting_client
+
+        if let Err(e) = self
+            .reporting_client
             .report_result(self.report_source.clone(), result, test_type, created_at)
             .await
-            .map_err(MessageTesterError::ReportResult)?;
-
-        Ok(())
+        {
+            error!("error reporting result to trc: {:?}", e);
+        }
     }
 }

test/modules/load-gen/DefaultMessageSender.cs

@@ -26,6 +26,8 @@ public async override Task RunAsync(CancellationTokenSource cts, DateTime testSt
             {
                 try
                 {
+                    await Task.Delay(Settings.Current.MessageFrequency);
+
                     await this.SendEventAsync(messageIdCounter, Settings.Current.OutputName);
 
                     // Report sending message successfully to Test Result Coordinator
@@ -36,7 +38,6 @@ public async override Task RunAsync(CancellationTokenSource cts, DateTime testSt
                         this.Logger.LogInformation($"Sent {messageIdCounter} messages.");
                     }
 
-                    await Task.Delay(Settings.Current.MessageFrequency);
                     messageIdCounter++;
                 }
                 catch (Exception ex)