From 2bc6fbe352792f1b950078819651faef3be621bf Mon Sep 17 00:00:00 2001 From: Adele Reed Date: Mon, 19 Sep 2022 12:30:48 -0700 Subject: [PATCH 1/6] Upload testing logs to storage account on failed test --- e2etest/declarativeScenario.go | 71 +++++++++++++++++++++++++++++++--- e2etest/runner.go | 6 ++- 2 files changed, 70 insertions(+), 7 deletions(-) diff --git a/e2etest/declarativeScenario.go b/e2etest/declarativeScenario.go index 7f27c9708..f7e10ef36 100644 --- a/e2etest/declarativeScenario.go +++ b/e2etest/declarativeScenario.go @@ -27,6 +27,7 @@ import ( "os" "path" "path/filepath" + "strings" "time" "github.com/Azure/azure-storage-azcopy/v10/common" @@ -70,7 +71,22 @@ type scenarioState struct { func (s *scenario) Run() { defer s.cleanup() - // setup + // setup runner + logDir, err := os.MkdirTemp("", "") + if err != nil { + s.a.Error(err.Error()) + return + } + azcopyRan := false + defer func() { + if azcopyRan { + s.uploadLogs(logDir) + s.a.(*testingAsserter).t.Log("uploaded logs for job " + s.state.result.jobID.String() + " to container azcopylogs in account " + os.Getenv("AZCOPY_E2E_ACCOUNT_NAME")) + } + s.cleanupLogs(logDir) + }() + + // setup scenario s.assignSourceAndDest() // what/where are they s.state.source.createLocation(s.a, s) s.state.dest.createLocation(s.a, s) @@ -86,7 +102,8 @@ func (s *scenario) Run() { } // execute - s.runAzCopy() + azcopyRan = true + s.runAzCopy(logDir) if s.a.Failed() { return // execution failed. No point in running validation } @@ -101,7 +118,7 @@ func (s *scenario) Run() { return } - s.resumeAzCopy() + s.resumeAzCopy(logDir) } if s.a.Failed() { return // resume failed. No point in running validation @@ -127,6 +144,47 @@ func (s *scenario) Run() { s.runHook(s.hs.afterValidation) } +func (s *scenario) cleanupLogs(logDir string) { + s.a.Assert(os.RemoveAll(logDir), equals(), nil, "cleanup of log files") +} + +func (s *scenario) uploadLogs(logDir string) { + container := TestResourceFactory{}.GetBlobServiceURL(EAccountType.Standard()).NewContainerURL("azcopylogs") + _, err := container.Create(ctx, nil, azblob.PublicAccessNone) + + if err != nil { + if stgErr, ok := err.(azblob.StorageError); ok && stgErr.ServiceCode() == azblob.ServiceCodeContainerAlreadyExists { + } else { + s.a.Assert(err, equals(), nil, "failed to ensure log container exists") + return // cannot upload logs + } + } + + entries, err := os.ReadDir(logDir) + s.a.Assert(err, equals(), nil, "failed to read log directory") + for _, entry := range entries { + if entry.IsDir() { + continue + } + + if !strings.HasSuffix(entry.Name(), ".log") { + continue + } + + file, err := os.Open(filepath.Join(logDir, entry.Name())) + if err != nil { + s.a.Assert(err, equals(), nil, "failed to open log file "+entry.Name()) + continue + } + + bURL := container.NewBlockBlobURL(s.state.result.jobID.String() + "/" + entry.Name()) + _, err = azblob.UploadFileToBlockBlob(ctx, file, bURL, azblob.UploadToBlockBlobOptions{}) + s.a.Assert(err, equals(), nil, "failed to upload log file "+entry.Name()) + + s.a.Assert(file.Close(), equals(), nil, "failed to close file "+entry.Name()+" after upload") + } +} + func (s *scenario) runHook(h hookFunc) bool { if h == nil { return true // nothing to do. So "successful" @@ -171,7 +229,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 +255,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 +273,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 +304,7 @@ func (s *scenario) resumeAzCopy() { false, afterStart, s.chToStdin, + logDir, ) if !wasClean { diff --git a/e2etest/runner.go b/e2etest/runner.go index 895ce3c65..d4c54d83b 100644 --- a/e2etest/runner.go +++ b/e2etest/runner.go @@ -184,7 +184,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 +234,10 @@ func (t *TestRunner) ExecuteAzCopyCommand(operation Operation, src, dst string, } } + if logDir != "" { + env = append(env, "AZCOPY_LOG_LOCATION="+logDir) + } + out, err := t.execDebuggableWithOutput(GlobalInputManager{}.GetExecutablePath(), args, env, afterStart, chToStdin) wasClean := true From 64cb8a6cee2c5bd64dc2159b7d4f4306949b6b1e Mon Sep 17 00:00:00 2001 From: Adele Reed Date: Mon, 19 Sep 2022 12:31:38 -0700 Subject: [PATCH 2/6] Handle as pipeline artifact instead --- azure-pipelines.yml | 10 +++++++++ e2etest/declarativeScenario.go | 41 +--------------------------------- 2 files changed, 11 insertions(+), 40 deletions(-) diff --git a/azure-pipelines.yml b/azure-pipelines.yml index 051fdbd13..943007398 100644 --- a/azure-pipelines.yml +++ b/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' diff --git a/e2etest/declarativeScenario.go b/e2etest/declarativeScenario.go index f7e10ef36..e939a4a76 100644 --- a/e2etest/declarativeScenario.go +++ b/e2etest/declarativeScenario.go @@ -27,7 +27,6 @@ import ( "os" "path" "path/filepath" - "strings" "time" "github.com/Azure/azure-storage-azcopy/v10/common" @@ -83,7 +82,6 @@ func (s *scenario) Run() { s.uploadLogs(logDir) s.a.(*testingAsserter).t.Log("uploaded logs for job " + s.state.result.jobID.String() + " to container azcopylogs in account " + os.Getenv("AZCOPY_E2E_ACCOUNT_NAME")) } - s.cleanupLogs(logDir) }() // setup scenario @@ -144,45 +142,8 @@ func (s *scenario) Run() { s.runHook(s.hs.afterValidation) } -func (s *scenario) cleanupLogs(logDir string) { - s.a.Assert(os.RemoveAll(logDir), equals(), nil, "cleanup of log files") -} - func (s *scenario) uploadLogs(logDir string) { - container := TestResourceFactory{}.GetBlobServiceURL(EAccountType.Standard()).NewContainerURL("azcopylogs") - _, err := container.Create(ctx, nil, azblob.PublicAccessNone) - - if err != nil { - if stgErr, ok := err.(azblob.StorageError); ok && stgErr.ServiceCode() == azblob.ServiceCodeContainerAlreadyExists { - } else { - s.a.Assert(err, equals(), nil, "failed to ensure log container exists") - return // cannot upload logs - } - } - - entries, err := os.ReadDir(logDir) - s.a.Assert(err, equals(), nil, "failed to read log directory") - for _, entry := range entries { - if entry.IsDir() { - continue - } - - if !strings.HasSuffix(entry.Name(), ".log") { - continue - } - - file, err := os.Open(filepath.Join(logDir, entry.Name())) - if err != nil { - s.a.Assert(err, equals(), nil, "failed to open log file "+entry.Name()) - continue - } - - bURL := container.NewBlockBlobURL(s.state.result.jobID.String() + "/" + entry.Name()) - _, err = azblob.UploadFileToBlockBlob(ctx, file, bURL, azblob.UploadToBlockBlobOptions{}) - s.a.Assert(err, equals(), nil, "failed to upload log file "+entry.Name()) - - s.a.Assert(file.Close(), equals(), nil, "failed to close file "+entry.Name()+" after 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 { From 4cefbeb09c5d21c9f29ca302480b71e992b9a72f Mon Sep 17 00:00:00 2001 From: Adele Reed Date: Mon, 19 Sep 2022 13:04:26 -0700 Subject: [PATCH 3/6] mkdirall --- main.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/main.go b/main.go index c47c38aaf..77290a631 100644 --- a/main.go +++ b/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) } From aba5db80961d3f79756387a9a0b6767a751a0c1b Mon Sep 17 00:00:00 2001 From: Adele Reed Date: Mon, 19 Sep 2022 13:13:22 -0700 Subject: [PATCH 4/6] copy plan files too --- e2etest/declarativeScenario.go | 12 ++++++++++-- e2etest/runner.go | 2 ++ 2 files changed, 12 insertions(+), 2 deletions(-) diff --git a/e2etest/declarativeScenario.go b/e2etest/declarativeScenario.go index e939a4a76..a40d9529e 100644 --- a/e2etest/declarativeScenario.go +++ b/e2etest/declarativeScenario.go @@ -78,9 +78,14 @@ func (s *scenario) Run() { } azcopyRan := false defer func() { - if azcopyRan { + 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(logDir) - s.a.(*testingAsserter).t.Log("uploaded logs for job " + s.state.result.jobID.String() + " to container azcopylogs in account " + os.Getenv("AZCOPY_E2E_ACCOUNT_NAME")) + s.a.(*testingAsserter).t.Log("uploaded logs for job " + s.state.result.jobID.String() + " as an artifact") } }() @@ -143,6 +148,9 @@ func (s *scenario) Run() { } func (s *scenario) uploadLogs(logDir string) { + if s.state.result == nil { + 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) } diff --git a/e2etest/runner.go b/e2etest/runner.go index d4c54d83b..a5f5d1e22 100644 --- a/e2etest/runner.go +++ b/e2etest/runner.go @@ -26,6 +26,7 @@ import ( "fmt" "os" "os/exec" + "path/filepath" "strconv" "strings" @@ -236,6 +237,7 @@ 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) From e109305d19b7cb2abd1a875b09428cc85f0286b7 Mon Sep 17 00:00:00 2001 From: Adele Reed Date: Tue, 20 Sep 2022 10:01:43 -0700 Subject: [PATCH 5/6] Fix failing tests --- e2etest/declarativeScenario.go | 23 ++++++++++++++--------- e2etest/runner.go | 14 ++++++++++---- 2 files changed, 24 insertions(+), 13 deletions(-) diff --git a/e2etest/declarativeScenario.go b/e2etest/declarativeScenario.go index a40d9529e..c79e50cfe 100644 --- a/e2etest/declarativeScenario.go +++ b/e2etest/declarativeScenario.go @@ -71,20 +71,25 @@ func (s *scenario) Run() { defer s.cleanup() // setup runner - logDir, err := os.MkdirTemp("", "") + 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(logDir) + s.uploadLogs(azcopyDir) s.a.(*testingAsserter).t.Log("uploaded logs for job " + s.state.result.jobID.String() + " as an artifact") } }() @@ -106,14 +111,14 @@ func (s *scenario) Run() { // execute azcopyRan = true - s.runAzCopy(logDir) + 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") @@ -121,14 +126,14 @@ func (s *scenario) Run() { return } - s.resumeAzCopy(logDir) + 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 } @@ -148,7 +153,7 @@ func (s *scenario) Run() { } func (s *scenario) uploadLogs(logDir string) { - if s.state.result == nil { + 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) @@ -295,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 @@ -318,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) diff --git a/e2etest/runner.go b/e2etest/runner.go index a5f5d1e22..d02b32196 100644 --- a/e2etest/runner.go +++ b/e2etest/runner.go @@ -274,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 } @@ -313,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 } From a7d2ad11ba107936da1c73f8ef9ac7472643d187 Mon Sep 17 00:00:00 2001 From: Adele Reed Date: Tue, 20 Sep 2022 14:49:22 -0700 Subject: [PATCH 6/6] Change overwrite to affect any "locked in"/completed state --- common/fe-ste-models.go | 5 +++++ ste/JobPartPlan.go | 5 ++--- 2 files changed, 7 insertions(+), 3 deletions(-) diff --git a/common/fe-ste-models.go b/common/fe-ste-models.go index a0a32f4e0..46d68d396 100644 --- a/common/fe-ste-models.go +++ b/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) } diff --git a/ste/JobPartPlan.go b/ste/JobPartPlan.go index bf9bbd975..ef7cd7638 100644 --- a/ste/JobPartPlan.go +++ b/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)