Improve debug-ability of e2e tests by uploading logs of failed jobs

azure-pipelines.yml

@@ -112,6 +112,7 @@ jobs:
           AZCOPY_E2E_CLIENT_SECRET: $(AZCOPY_SPA_CLIENT_SECRET)
           AZCOPY_E2E_CLASSIC_ACCOUNT_NAME: $(AZCOPY_E2E_CLASSIC_ACCOUNT_NAME)
           AZCOPY_E2E_CLASSIC_ACCOUNT_KEY: $(AZCOPY_E2E_CLASSIC_ACCOUNT_KEY)
+          AZCOPY_E2E_LOG_OUTPUT: '$(System.DefaultWorkingDirectory)/logs'
           CPK_ENCRYPTION_KEY: $(CPK_ENCRYPTION_KEY)
           CPK_ENCRYPTION_KEY_SHA256: $(CPK_ENCRYPTION_KEY_SHA256)
         displayName: 'E2E Test Linux - AMD64'
@@ -133,6 +134,7 @@ jobs:
           AZCOPY_E2E_CLIENT_SECRET: $(AZCOPY_SPA_CLIENT_SECRET)
           AZCOPY_E2E_CLASSIC_ACCOUNT_NAME: $(AZCOPY_E2E_CLASSIC_ACCOUNT_NAME)
           AZCOPY_E2E_CLASSIC_ACCOUNT_KEY: $(AZCOPY_E2E_CLASSIC_ACCOUNT_KEY)
+          AZCOPY_E2E_LOG_OUTPUT: '$(System.DefaultWorkingDirectory)/logs'
           CPK_ENCRYPTION_KEY: $(CPK_ENCRYPTION_KEY)
           CPK_ENCRYPTION_KEY_SHA256: $(CPK_ENCRYPTION_KEY_SHA256)
           AZCOPY_E2E_EXECUTABLE_PATH: $(System.DefaultWorkingDirectory)/azcopy_windows_amd64.exe
@@ -156,11 +158,19 @@ jobs:
           AZCOPY_E2E_CLIENT_SECRET: $(AZCOPY_SPA_CLIENT_SECRET)
           AZCOPY_E2E_CLASSIC_ACCOUNT_NAME: $(AZCOPY_E2E_CLASSIC_ACCOUNT_NAME)
           AZCOPY_E2E_CLASSIC_ACCOUNT_KEY: $(AZCOPY_E2E_CLASSIC_ACCOUNT_KEY)
+          AZCOPY_E2E_LOG_OUTPUT: '$(System.DefaultWorkingDirectory)/logs'
           CPK_ENCRYPTION_KEY: $(CPK_ENCRYPTION_KEY)
           CPK_ENCRYPTION_KEY_SHA256: $(CPK_ENCRYPTION_KEY_SHA256)
         displayName: 'E2E Test MacOs'
         condition: eq(variables.type, 'mac-os')
 
+      - task: PublishBuildArtifacts@1
+        displayName: 'Publish logs'
+        condition: succeededOrFailed()
+        inputs:
+          pathToPublish: '$(System.DefaultWorkingDirectory)/logs'
+          artifactName: logs
+
   - job: Test_On_Ubuntu
     variables:
       isMutexSet: 'false'

common/fe-ste-models.go

@@ -670,6 +670,11 @@ var ETransferStatus = TransferStatus(0)
 
 type TransferStatus int32 // Must be 32-bit for atomic operations; negative #s represent a specific failure code
 
+func (t TransferStatus) StatusLocked() bool { // Is an overwrite necessary to change tx status?
+	// Any kind of failure, or success is considered "locked in".
+	return t <= ETransferStatus.Failed() || t == ETransferStatus.Success()
+}
+
 // Transfer is ready to transfer and not started transferring yet
 func (TransferStatus) NotStarted() TransferStatus { return TransferStatus(0) }
 

e2etest/declarativeScenario.go

@@ -70,7 +70,31 @@ type scenarioState struct {
 func (s *scenario) Run() {
 	defer s.cleanup()
 
-	// setup
+	// setup runner
+	azcopyDir, err := os.MkdirTemp("", "")
+	if err != nil {
+		s.a.Error(err.Error())
+		return
+	}
+	azcopyRan := false
+	defer func() {
+		if os.Getenv("AZCOPY_E2E_LOG_OUTPUT") == "" {
+			s.a.Assert(os.RemoveAll(azcopyDir), equals(), nil)
+			return // no need, just delete logdir
+		}
+
+		err := os.MkdirAll(os.Getenv("AZCOPY_E2E_LOG_OUTPUT"), os.ModePerm|os.ModeDir)
+		if err != nil {
+			s.a.Assert(err, equals(), nil)
+			return
+		}
+		if azcopyRan && s.a.Failed() {
+			s.uploadLogs(azcopyDir)
+			s.a.(*testingAsserter).t.Log("uploaded logs for job " + s.state.result.jobID.String() + " as an artifact")
+		}
+	}()
+
+	// setup scenario
 	s.assignSourceAndDest() // what/where are they
 	s.state.source.createLocation(s.a, s)
 	s.state.dest.createLocation(s.a, s)
@@ -86,29 +110,30 @@ func (s *scenario) Run() {
 	}
 
 	// execute
-	s.runAzCopy()
+	azcopyRan = true
+	s.runAzCopy(azcopyDir)
 	if s.a.Failed() {
 		return // execution failed. No point in running validation
 	}
 
 	// resume if needed
 	if s.needResume {
-		tx, err := s.state.result.GetTransferList(common.ETransferStatus.Cancelled())
+		tx, err := s.state.result.GetTransferList(common.ETransferStatus.Cancelled(), azcopyDir)
 		s.a.AssertNoErr(err, "Failed to get transfer list for Cancelled")
 		s.a.Assert(len(tx), equals(), len(s.p.debugSkipFiles), "Job cancel didn't completely work")
 
 		if !s.runHook(s.hs.beforeResumeHook) {
 			return
 		}
 
-		s.resumeAzCopy()
+		s.resumeAzCopy(azcopyDir)
 	}
 	if s.a.Failed() {
 		return // resume failed. No point in running validation
 	}
 
 	// check
-	s.validateTransferStates()
+	s.validateTransferStates(azcopyDir)
 	if s.a.Failed() {
 		return // no point in doing more validation
 	}
@@ -127,6 +152,13 @@ func (s *scenario) Run() {
 	s.runHook(s.hs.afterValidation)
 }
 
+func (s *scenario) uploadLogs(logDir string) {
+	if s.state.result == nil || os.Getenv("AZCOPY_E2E_LOG_OUTPUT") == "" {
+		return // nothing to upload
+	}
+	s.a.Assert(os.Rename(logDir, filepath.Join(os.Getenv("AZCOPY_E2E_LOG_OUTPUT"), s.state.result.jobID.String())), equals(), nil)
+}
+
 func (s *scenario) runHook(h hookFunc) bool {
 	if h == nil {
 		return true // nothing to do. So "successful"
@@ -171,7 +203,7 @@ func (s *scenario) assignSourceAndDest() {
 	s.state.dest = createTestResource(s.fromTo.To(), false)
 }
 
-func (s *scenario) runAzCopy() {
+func (s *scenario) runAzCopy(logDirectory string) {
 	s.chToStdin = make(chan string) // unubuffered seems the most predictable for our usages
 	defer close(s.chToStdin)
 
@@ -197,7 +229,7 @@ func (s *scenario) runAzCopy() {
 		s.state.source.getParam(s.stripTopDir, s.credTypes[0] == common.ECredentialType.Anonymous(), tf.objectTarget),
 		s.state.dest.getParam(false, s.credTypes[1] == common.ECredentialType.Anonymous(), common.IffString(tf.destTarget != "", tf.destTarget, tf.objectTarget)),
 		s.credTypes[0] == common.ECredentialType.OAuthToken() || s.credTypes[1] == common.ECredentialType.OAuthToken(), // needsOAuth
-		afterStart, s.chToStdin)
+		afterStart, s.chToStdin, logDirectory)
 
 	if !wasClean {
 		s.a.AssertNoErr(err, "running AzCopy")
@@ -215,7 +247,7 @@ func (s *scenario) runAzCopy() {
 	s.state.result = &result
 }
 
-func (s *scenario) resumeAzCopy() {
+func (s *scenario) resumeAzCopy(logDir string) {
 	s.chToStdin = make(chan string) // unubuffered seems the most predictable for our usages
 	defer close(s.chToStdin)
 
@@ -246,6 +278,7 @@ func (s *scenario) resumeAzCopy() {
 		false,
 		afterStart,
 		s.chToStdin,
+		logDir,
 	)
 
 	if !wasClean {
@@ -267,7 +300,7 @@ func (s *scenario) validateRemove() {
 		}
 	}
 }
-func (s *scenario) validateTransferStates() {
+func (s *scenario) validateTransferStates(azcopyDir string) {
 	if s.operation == eOperation.Remove() {
 		s.validateRemove()
 		return
@@ -290,7 +323,7 @@ func (s *scenario) validateTransferStates() {
 		//       Is that OK? (Not sure what to do if it's not, because azcopy jobs show, apparently doesn't offer us a way to get the skipped list)
 	} {
 		expectedTransfers := s.fs.getForStatus(statusToTest, expectFolders, expectRootFolder)
-		actualTransfers, err := s.state.result.GetTransferList(statusToTest)
+		actualTransfers, err := s.state.result.GetTransferList(statusToTest, azcopyDir)
 		s.a.AssertNoErr(err)
 
 		Validator{}.ValidateCopyTransfersAreScheduled(s.a, isSrcEncoded, isDstEncoded, srcRoot, dstRoot, expectedTransfers, actualTransfers, statusToTest, s.FromTo(), s.srcAccountType, s.destAccountType)

e2etest/runner.go

@@ -26,6 +26,7 @@ import (
 	"fmt"
 	"os"
 	"os/exec"
+	"path/filepath"
 	"strconv"
 	"strings"
 
@@ -184,7 +185,7 @@ func (t *TestRunner) execDebuggableWithOutput(name string, args []string, env []
 	return stdout.Bytes(), runErr
 }
 
-func (t *TestRunner) ExecuteAzCopyCommand(operation Operation, src, dst string, needsOAuth bool, afterStart func() string, chToStdin <-chan string) (CopyOrSyncCommandResult, bool, error) {
+func (t *TestRunner) ExecuteAzCopyCommand(operation Operation, src, dst string, needsOAuth bool, afterStart func() string, chToStdin <-chan string, logDir string) (CopyOrSyncCommandResult, bool, error) {
 	capLen := func(b []byte) []byte {
 		if len(b) < 1024 {
 			return b
@@ -234,6 +235,11 @@ func (t *TestRunner) ExecuteAzCopyCommand(operation Operation, src, dst string,
 		}
 	}
 
+	if logDir != "" {
+		env = append(env, "AZCOPY_LOG_LOCATION="+logDir)
+		env = append(env, "AZCOPY_JOB_PLAN_LOCATION="+filepath.Join(logDir, "plans"))
+	}
+
 	out, err := t.execDebuggableWithOutput(GlobalInputManager{}.GetExecutablePath(), args, env, afterStart, chToStdin)
 
 	wasClean := true
@@ -268,9 +274,15 @@ func (t *TestRunner) SetTransferStatusFlag(value string) {
 	t.flags["with-status"] = value
 }
 
-func (t *TestRunner) ExecuteJobsShowCommand(jobID common.JobID) (JobsShowCommandResult, error) {
+func (t *TestRunner) ExecuteJobsShowCommand(jobID common.JobID, azcopyDir string) (JobsShowCommandResult, error) {
 	args := append([]string{"jobs", "show", jobID.String()}, t.computeArgs()...)
-	out, err := exec.Command(GlobalInputManager{}.GetExecutablePath(), args...).Output()
+	cmd := exec.Command(GlobalInputManager{}.GetExecutablePath(), args...)
+
+	if azcopyDir != "" {
+		cmd.Env = append(cmd.Env, "AZCOPY_JOB_PLAN_LOCATION="+filepath.Join(azcopyDir, "plans"))
+	}
+
+	out, err := cmd.Output()
 	if err != nil {
 		return JobsShowCommandResult{}, err
 	}
@@ -307,12 +319,12 @@ func newCopyOrSyncCommandResult(rawOutput string) (CopyOrSyncCommandResult, bool
 	return CopyOrSyncCommandResult{jobID: jobSummary.JobID, finalStatus: jobSummary}, true
 }
 
-func (c *CopyOrSyncCommandResult) GetTransferList(status common.TransferStatus) ([]common.TransferDetail, error) {
+func (c *CopyOrSyncCommandResult) GetTransferList(status common.TransferStatus, azcopyDir string) ([]common.TransferDetail, error) {
 	runner := newTestRunner()
 	runner.SetTransferStatusFlag(status.String())
 
 	// invoke AzCopy to get the status from the plan files
-	result, err := runner.ExecuteJobsShowCommand(c.jobID)
+	result, err := runner.ExecuteJobsShowCommand(c.jobID, azcopyDir)
 	if err != nil {
 		return make([]common.TransferDetail, 0), err
 	}

main.go

@@ -60,12 +60,12 @@ func main() {
 	// the user can optionally put the plan files somewhere else
 	if azcopyJobPlanFolder == "" {
 		// make the app path folder ".azcopy" first so we can make a plans folder in it
-		if err := os.Mkdir(azcopyAppPathFolder, os.ModeDir); err != nil && !os.IsExist(err) {
+		if err := os.MkdirAll(azcopyAppPathFolder, os.ModeDir); err != nil && !os.IsExist(err) {
 			common.PanicIfErr(err)
 		}
 		azcopyJobPlanFolder = path.Join(azcopyAppPathFolder, "plans")
 	}
-	if err := os.Mkdir(azcopyJobPlanFolder, os.ModeDir|os.ModePerm); err != nil && !os.IsExist(err) {
+	if err := os.MkdirAll(azcopyJobPlanFolder, os.ModeDir|os.ModePerm); err != nil && !os.IsExist(err) {
 		common.PanicIfErr(err)
 	}
 

ste/JobPartPlan.go

@@ -409,9 +409,8 @@ func (jppt *JobPartPlanTransfer) SetTransferStatus(status common.TransferStatus,
 	if !overWrite {
 		common.AtomicMorphInt32((*int32)(&jppt.atomicTransferStatus),
 			func(startVal int32) (val int32, morphResult interface{}) {
-				// start value < 0 means that transfer status is already a failed value.
-				// If current transfer status has already failed value, then it will not be changed.
-				return common.Iffint32(startVal < 0, startVal, int32(status)), nil
+				// If current transfer status has some completed value, then it will not be changed.
+				return common.Iffint32(common.TransferStatus(startVal).StatusLocked(), startVal, int32(status)), nil
 			})
 	} else {
 		(&jppt.atomicTransferStatus).AtomicStore(status)