02-ConTest-Cleanup

[2020-06-15T12:39:36+02:00]  INFO testfetchers/uri: Fetching tests with params {TestName:RackSwitchProvisioning URI:test_samples/randecho.json}
[2020-06-15T12:39:36+02:00]  INFO pkg/jobmanager: Sending response &{Requestor:contestcli-http JobID:298 Err:<nil> Status:0xc00048f540}
[2020-06-15T12:39:36+02:00]  INFO pkg/runner: Running job 'test job' 1 times
[2020-06-15T12:39:36+02:00]  INFO pkg/runner: Run #1: fetching targets for test 'RackSwitchProvisioning'
[2020-06-15T12:39:36+02:00]  INFO targetlocker/inmemory: Trying to lock 1 targets
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] targetlocker/inmemory: Requested to lock 1 targets: [Target{Name: "compute1234", ID: "172.16.5.6", FQDN: ""}]
[2020-06-15T12:39:36+02:00]  INFO targetlocker/inmemory: Checking if 1 target(s) are locked by job ID 298
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] targetlocker/inmemory: Requested to check locks for 1 targets: [Target{Name: "compute1234", ID: "172.16.5.6", FQDN: ""}]
[2020-06-15T12:39:36+02:00]  INFO pkg/runner: Run #1: running test #0 for job 'test job' (job ID: 298) on 1 targets
[2020-06-15T12:39:36+02:00]  INFO pkg/runner: setting up test pipeline jobid=298 phase=run runid=1
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: starting entity=test_pipeline jobid=298 runid=1
[2020-06-15T12:39:36+02:00]  INFO pkg/runner: setting up cleanup pipeline jobid=298 phase=run runid=1
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: starting entity=cleanup_pipeline jobid=298 runid=1
[2020-06-15T12:39:36+02:00]  INFO pkg/runner: running cleanup pipeline jobid=298 phase=run runid=1
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: run entity=cleanup_pipeline jobid=298 runid=1
[2020-06-15T12:39:36+02:00]  INFO pkg/runner: waiting for pipeline to complete entity=cleanup_pipeline jobid=298 runid=1
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: initializing routing entity=test_pipeline jobid=298 runid=1
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: initializing routeOut for thefirstrandecho_test entity=test_pipeline jobid=298 phase=routeOut runid=1 step=thefirstrandecho_test
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: initializing step entity=test_pipeline jobid=298 phase=runStep runid=1 step=thefirstrandecho_test
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: initializing step entity=test_pipeline jobid=298 phase=runStep runid=1 step=thesecondrandecho_test
[2020-06-15T12:39:36+02:00]  INFO pkg/runner: running test pipeline jobid=298 phase=run runid=1
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: initializing routing entity=test_pipeline jobid=298 runid=1
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: initializing routeOut for thesecondrandecho_test entity=test_pipeline jobid=298 phase=routeOut runid=1 step=thesecondrandecho_test
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: initializing routing entity=cleanup_pipeline jobid=298 runid=1
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: run entity=test_pipeline jobid=298 runid=1
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: initializing routeOut for thefirstrandecho_cleanup entity=cleanup_pipeline jobid=298 phase=routeOut runid=1 step=thefirstrandecho_cleanup
[2020-06-15T12:39:36+02:00]  INFO pkg/runner: waiting for pipeline to complete entity=test_pipeline jobid=298 runid=1
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: initializing routeIn for thefirstrandecho_cleanup entity=cleanup_pipeline jobid=298 phase=routeIn runid=1 step=thefirstrandecho_cleanup
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: injecting Target{Name: "compute1234", ID: "172.16.5.6", FQDN: ""} jobid=298 phase=run runid=1 step=test_injection
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: writing target Target{Name: "compute1234", ID: "172.16.5.6", FQDN: ""}, timeout 5s jobid=298 phase=run runid=1 step=test_injection
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: done writing target Target{Name: "compute1234", ID: "172.16.5.6", FQDN: ""}, spent 6.58µs jobid=298 phase=run runid=1 step=test_injection
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: all targets have been injected jobid=298 phase=run runid=1 step=test_injection
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: initializing routeIn for thefirstrandecho_test entity=test_pipeline jobid=298 phase=routeIn runid=1 step=thefirstrandecho_test
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: received target Target{Name: "compute1234", ID: "172.16.5.6", FQDN: ""} in input entity=test_pipeline jobid=298 phase=routeIn runid=1 step=thefirstrandecho_test
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: writing target Target{Name: "compute1234", ID: "172.16.5.6", FQDN: ""} into test step entity=test_pipeline jobid=298 phase=routeIn runid=1 step=thefirstrandecho_test
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: routing input channel closed entity=test_pipeline jobid=298 phase=routeIn runid=1 step=thefirstrandecho_test
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: initializing routeIn for thesecondrandecho_test entity=test_pipeline jobid=298 phase=routeIn runid=1 step=thesecondrandecho_test
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: initializing step entity=cleanup_pipeline jobid=298 phase=runStep runid=1 step=thefirstrandecho_cleanup
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: writing target Target{Name: "compute1234", ID: "172.16.5.6", FQDN: ""}, timeout 30s entity=test_pipeline jobid=298 phase=routeIn runid=1 step=thefirstrandecho_test
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: done writing target Target{Name: "compute1234", ID: "172.16.5.6", FQDN: ""}, spent 15.795µs entity=test_pipeline jobid=298 phase=routeIn runid=1 step=thefirstrandecho_test
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: received injection result for Target{Name: "compute1234", ID: "172.16.5.6", FQDN: ""} entity=test_pipeline jobid=298 phase=routeIn runid=1 step=thefirstrandecho_test
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: first target received, will start step entity=test_pipeline jobid=298 phase=runStep runid=1 step=thefirstrandecho_test
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: input channel is closed and no more targets are available, closing step input channel entity=test_pipeline jobid=298 phase=routeIn runid=1 step=thefirstrandecho_test
[2020-06-15T12:39:36+02:00]  INFO teststeps/randecho: Run: target Target{Name: "compute1234", ID: "172.16.5.6", FQDN: ""} failed: some very random text first_test
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: step thefirstrandecho_test returned entity=test_pipeline jobid=298 phase=runStep runid=1 step=thefirstrandecho_test
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: targets completed: 0, expected: 1 entity=test_pipeline jobid=298 phase=waitTargets runid=1
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: step error closed entity=test_pipeline jobid=298 phase=routeOut runid=1 step=thefirstrandecho_test
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: step output closed entity=test_pipeline jobid=298 phase=routeOut runid=1 step=thefirstrandecho_test
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: output and error channel from step are closed, routeOut should terminate entity=test_pipeline jobid=298 phase=routeOut runid=1 step=thefirstrandecho_test
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: writing target Target{Name: "compute1234", ID: "172.16.5.6", FQDN: ""} on the completed channel entity=test_pipeline jobid=298 phase=waitTargets runid=1
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: writing target Target{Name: "compute1234", ID: "172.16.5.6", FQDN: ""}, timeout 5s entity=test_pipeline jobid=298 phase=waitTargets runid=1
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: done writing target Target{Name: "compute1234", ID: "172.16.5.6", FQDN: ""}, spent 1.893µs entity=test_pipeline jobid=298 phase=waitTargets runid=1
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: targets completed: 1, expected: 1 entity=test_pipeline jobid=298 phase=waitTargets runid=1
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: no more targets to wait, all targets (1) completed entity=test_pipeline jobid=298 phase=waitTargets runid=1
[2020-06-15T12:39:36+02:00]  INFO pkg/runner: waiting for all steps to complete entity=test_pipeline jobid=298 phase=waitTargets runid=1
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: waiting fot test steps to terminate entity=test_pipeline jobid=298 phase=waitSteps runid=1
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: received routing block result for thefirstrandecho_test entity=test_pipeline jobid=298 phase=waitSteps runid=1
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: steps completed: 1, expected: 2 entity=test_pipeline jobid=298 phase=waitSteps runid=1
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: routing completed: 1, expected: 2 entity=test_pipeline jobid=298 phase=waitSteps runid=1
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: routing input channel closed entity=test_pipeline jobid=298 phase=routeIn runid=1 step=thesecondrandecho_test
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: input channel is closed and no more targets are available, closing step input channel entity=test_pipeline jobid=298 phase=routeIn runid=1 step=thesecondrandecho_test
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: no targets entity=test_pipeline jobid=298 phase=runStep runid=1 step=thesecondrandecho_test
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: step thesecondrandecho_test returned entity=test_pipeline jobid=298 phase=runStep runid=1 step=thesecondrandecho_test
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: received step result for thesecondrandecho_test entity=test_pipeline jobid=298 phase=waitSteps runid=1
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: steps completed: 2, expected: 2 entity=test_pipeline jobid=298 phase=waitSteps runid=1
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: routing completed: 1, expected: 2 entity=test_pipeline jobid=298 phase=waitSteps runid=1
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: received target Target{Name: "compute1234", ID: "172.16.5.6", FQDN: ""}, injecting... jobid=298 phase=run runid=1 step=cleanup_injection
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: injecting Target{Name: "compute1234", ID: "172.16.5.6", FQDN: ""} jobid=298 phase=run runid=1 step=cleanup_injection
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: writing target Target{Name: "compute1234", ID: "172.16.5.6", FQDN: ""}, timeout 5s jobid=298 phase=run runid=1 step=cleanup_injection
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: done writing target Target{Name: "compute1234", ID: "172.16.5.6", FQDN: ""}, spent 1.685µs jobid=298 phase=run runid=1 step=cleanup_injection
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: all targets have been injected jobid=298 phase=run runid=1 step=cleanup_injection
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: received target Target{Name: "compute1234", ID: "172.16.5.6", FQDN: ""} in input entity=cleanup_pipeline jobid=298 phase=routeIn runid=1 step=thefirstrandecho_cleanup
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: writing target Target{Name: "compute1234", ID: "172.16.5.6", FQDN: ""} into test step entity=cleanup_pipeline jobid=298 phase=routeIn runid=1 step=thefirstrandecho_cleanup
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: writing target Target{Name: "compute1234", ID: "172.16.5.6", FQDN: ""}, timeout 30s entity=cleanup_pipeline jobid=298 phase=routeIn runid=1 step=thefirstrandecho_cleanup
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: done writing target Target{Name: "compute1234", ID: "172.16.5.6", FQDN: ""}, spent 1.819µs entity=cleanup_pipeline jobid=298 phase=routeIn runid=1 step=thefirstrandecho_cleanup
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: received injection result for Target{Name: "compute1234", ID: "172.16.5.6", FQDN: ""} entity=cleanup_pipeline jobid=298 phase=routeIn runid=1 step=thefirstrandecho_cleanup
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: step output closed entity=test_pipeline jobid=298 phase=routeOut runid=1 step=thesecondrandecho_test
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: step error closed entity=test_pipeline jobid=298 phase=routeOut runid=1 step=thesecondrandecho_test
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: output and error channel from step are closed, routeOut should terminate entity=test_pipeline jobid=298 phase=routeOut runid=1 step=thesecondrandecho_test
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: received routing block result for thesecondrandecho_test entity=test_pipeline jobid=298 phase=waitSteps runid=1
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: steps completed: 2, expected: 2 entity=test_pipeline jobid=298 phase=waitSteps runid=1
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: routing completed: 2, expected: 2 entity=test_pipeline jobid=298 phase=waitSteps runid=1
[2020-06-15T12:39:36+02:00]  INFO pkg/runner: completed entity=test_pipeline jobid=298 runid=1
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: pipe input channel closed, closing pipe output channel jobid=298 phase=run runid=1 step=cleanup_injection
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: first target received, will start step entity=cleanup_pipeline jobid=298 phase=runStep runid=1 step=thefirstrandecho_cleanup
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: test pipeline terminated jobid=298 phase=waitTestRunner runid=1
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: cleanup completed: false, test completed: true jobid=298 phase=waitTestRunner runid=1
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: routing input channel closed entity=cleanup_pipeline jobid=298 phase=routeIn runid=1 step=thefirstrandecho_cleanup
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: input channel is closed and no more targets are available, closing step input channel entity=cleanup_pipeline jobid=298 phase=routeIn runid=1 step=thefirstrandecho_cleanup
[2020-06-15T12:39:36+02:00]  INFO teststeps/randecho: Run: target Target{Name: "compute1234", ID: "172.16.5.6", FQDN: ""} succeeded: some very random text first_cleanup
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: step thefirstrandecho_cleanup returned entity=cleanup_pipeline jobid=298 phase=runStep runid=1 step=thefirstrandecho_cleanup
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: targets completed: 0, expected: 1 entity=cleanup_pipeline jobid=298 phase=waitTargets runid=1
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: writing target Target{Name: "compute1234", ID: "172.16.5.6", FQDN: ""}, timeout 5s entity=cleanup_pipeline jobid=298 phase=routeOut runid=1 step=thefirstrandecho_cleanup
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: done writing target Target{Name: "compute1234", ID: "172.16.5.6", FQDN: ""}, spent 3.648µs entity=cleanup_pipeline jobid=298 phase=routeOut runid=1 step=thefirstrandecho_cleanup
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: step error closed entity=cleanup_pipeline jobid=298 phase=routeOut runid=1 step=thefirstrandecho_cleanup
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: step output closed entity=cleanup_pipeline jobid=298 phase=routeOut runid=1 step=thefirstrandecho_cleanup
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: output and error channel from step are closed, routeOut should terminate entity=cleanup_pipeline jobid=298 phase=routeOut runid=1 step=thefirstrandecho_cleanup
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: writing target Target{Name: "compute1234", ID: "172.16.5.6", FQDN: ""} on the completed channel entity=cleanup_pipeline jobid=298 phase=waitTargets runid=1
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: writing target Target{Name: "compute1234", ID: "172.16.5.6", FQDN: ""}, timeout 5s entity=cleanup_pipeline jobid=298 phase=waitTargets runid=1
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: done writing target Target{Name: "compute1234", ID: "172.16.5.6", FQDN: ""}, spent 4.927µs entity=cleanup_pipeline jobid=298 phase=waitTargets runid=1
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: targets completed: 1, expected: 1 entity=cleanup_pipeline jobid=298 phase=waitTargets runid=1
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: no more targets to wait, all targets (1) completed entity=cleanup_pipeline jobid=298 phase=waitTargets runid=1
[2020-06-15T12:39:36+02:00]  INFO pkg/runner: waiting for all steps to complete entity=cleanup_pipeline jobid=298 phase=waitTargets runid=1
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: waiting fot test steps to terminate entity=cleanup_pipeline jobid=298 phase=waitSteps runid=1
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: received routing block result for thefirstrandecho_cleanup entity=cleanup_pipeline jobid=298 phase=waitSteps runid=1
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: steps completed: 1, expected: 1 entity=cleanup_pipeline jobid=298 phase=waitSteps runid=1
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: routing completed: 1, expected: 1 entity=cleanup_pipeline jobid=298 phase=waitSteps runid=1
[2020-06-15T12:39:36+02:00]  INFO pkg/runner: completed entity=cleanup_pipeline jobid=298 runid=1
[2020-06-15T12:39:36+02:00]  INFO pkg/runner: test runner completed target: Target{Name: "compute1234", ID: "172.16.5.6", FQDN: ""} jobid=298 phase=waitTestRunner runid=1
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: cleanup completed: false, test completed: true jobid=298 phase=waitTestRunner runid=1
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: cleanup pipeline terminated jobid=298 phase=waitTestRunner runid=1
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: cleanup completed: true, test completed: true jobid=298 phase=waitTestRunner runid=1
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/runner: test runner returning <nil> jobid=298 phase=waitTestRunner runid=1
[2020-06-15T12:39:36+02:00]  INFO targetlocker/inmemory: Trying to unlock 1 targets
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] targetlocker/inmemory: Requested to transactionally unlock 1 targets: [Target{Name: "compute1234", ID: "172.16.5.6", FQDN: ""}]
[2020-06-15T12:39:36+02:00]  INFO pkg/runner: Unlocked 1 target(s) for job ID 298
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] plugin/events/rdbms: Executing query: select event_id, job_id, run_id, test_name, test_step_label, event_name, target_name, target_id, payload, emit_time from test_events where job_id=? and run_id=? and test_name=? and test_step_label=? order by event_id, fields: [298 1 RackSwitchProvisioning thefirstrandecho_test]
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] plugin/events/rdbms: Executing query: select event_id, job_id, run_id, test_name, test_step_label, event_name, target_name, target_id, payload, emit_time from test_events where job_id=? and run_id=? and test_name=? and test_step_label=? order by event_id, fields: [298 1 RackSwitchProvisioning thesecondrandecho_test]
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] plugin/events/rdbms: Executing query: select event_id, job_id, run_id, test_name, test_step_label, event_name, target_name, target_id, payload, emit_time from test_events where job_id=? and event_name=? and run_id=? and test_name=? order by event_id, fields: [298 TargetAcquired 1 RackSwitchProvisioning]
[2020-06-15T12:39:36+02:00] ERROR pkg/runner: Run #1 of job 298 considered failed according to TargetSuccess
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] plugin/events/rdbms: Executing query: select event_id, job_id, run_id, test_name, test_step_label, event_name, target_name, target_id, payload, emit_time from test_events where job_id=? and run_id=? and test_name=? and test_step_label=? order by event_id, fields: [298 1 RackSwitchProvisioning thefirstrandecho_test]
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] plugin/events/rdbms: Executing query: select event_id, job_id, run_id, test_name, test_step_label, event_name, target_name, target_id, payload, emit_time from test_events where job_id=? and run_id=? and test_name=? and test_step_label=? order by event_id, fields: [298 1 RackSwitchProvisioning thesecondrandecho_test]
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] plugin/events/rdbms: Executing query: select event_id, job_id, run_id, test_name, test_step_label, event_name, target_name, target_id, payload, emit_time from test_events where job_id=? and event_name=? and run_id=? and test_name=? order by event_id, fields: [298 TargetAcquired 1 RackSwitchProvisioning]
[2020-06-15T12:39:36+02:00]  INFO pkg/runner: Run #1 of job 298 considered successful according to noop
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/jobmanager: job 298 terminated
[2020-06-15T12:39:36+02:00]  INFO pkg/jobmanager: Job &{ID:298 ExtendedDescriptor:0xc00048f360 Name:test job Tags:[test csv] Done:0xc0004a69c0 CancelCh:0xc0004a6a20 PauseCh:0xc0004a6a80 Runs:1 RunInterval:5s Tests:[0xc0003d3810] RunReporterBundles:[0xc0004dc5a0 0xc0004dc5c0] FinalReporterBundles:[]} completed after 117.5448ms
[2020-06-15T12:39:36+02:00] DEBUG [github.com/sirupsen/logrus.(*Entry).Debugf][entry.go][323] pkg/jobmanager: emitting: JobStateCompleted