Search code examples
tfscontinuous-integrationpipelinedevops

Team Foundation Server terminates CMD/Batch/Powershell task


I try to write build steps in TFS build definition, one of which is calling a CMD running bat script of SoapUI located in file system:

C:\"Program Files"\SmartBear\SoapUI-5.2.1\bin\testrunner

This bat script runs test steps with *.xml file in repository.

After this step is running TFS tries to terminate script sending SIGBREAK (CTRL_C) and then CMD step is stopping with message "Terminate batch job (Y/N)?".

The problem is certainly in this bat script, because other scripts work fine. The same happens with Batch and Powershell too. Can I prevent this behavior in TFS?

P.S. I find interesting that in file system logs TFS writes following: Stop aggressive process web console line queue.

P.S.S. Script needs internet access to send requests to web-service.

TFS logs:

2019-04-15T13:23:30.6310955Z ##[section]Starting: Run Tests
2019-04-15T13:23:30.6314476Z ==============================================================================
2019-04-15T13:23:30.6314575Z Task         : Batch Script
2019-04-15T13:23:30.6314677Z Description  : Run a windows cmd or bat script and optionally allow it to change the environment
2019-04-15T13:23:30.6314760Z Version      : 1.1.3
2019-04-15T13:23:30.6314831Z Author       : Microsoft Corporation
2019-04-15T13:23:30.6314926Z Help         : [More Information](https://go.microsoft.com/fwlink/?LinkID=613733)
2019-04-15T13:23:30.6315025Z ==============================================================================
2019-04-15T13:23:30.6326914Z ##[command]"C:\Program Files\SmartBear\SoapUI-5.2.1\bin\testrunner.bat" -r -j -ftests %testScript% 2>NUL
2019-04-15T13:23:31.7381481Z 18:23:31,483 INFO  [DefaultSoapUICore] Creating new settings at [C:\Windows\ServiceProfiles\NetworkService\soapui-settings.xml]
2019-04-15T13:23:33.0767434Z 18:23:32,679 INFO  [PluginManager] 0 plugins loaded in 2 ms
2019-04-15T13:23:33.0767679Z 18:23:32,679 INFO  [DefaultSoapUICore] All plugins loaded
2019-04-15T13:24:22.9158044Z Terminate batch job (Y/N)?
2019-04-15T13:24:22.9249350Z ##[error]The operation was canceled.
2019-04-15T13:24:22.9280244Z ##[section]Finishing: Run Tests

I also found the following logs in file system C:\agent_diag

[2019-04-15 12:13:40Z INFO ProcessInvokerWrapper] Process started with process id 7868, waiting for process exit.
[2019-04-15 12:13:40Z INFO JobServerQueue] Try to append 1 batches web console lines for record '5119da93-a929-543c-7e43-439284c14c5d', success rate: 1/1.
[2019-04-15 12:13:40Z INFO JobServerQueue] Try to append 1 batches web console lines for record 'b544018b-4d71-5134-742f-cb63728506de', success rate: 1/1.
[2019-04-15 12:13:40Z INFO JobServerQueue] Try to append 1 batches web console lines for record '85f1bd98-2921-5766-8330-d8b491fc5b96', success rate: 1/1.
[2019-04-15 12:13:43Z INFO JobServerQueue] Try to append 1 batches web console lines for record '85f1bd98-2921-5766-8330-d8b491fc5b96', success rate: 1/1.
[2019-04-15 12:13:43Z INFO JobServerQueue] Try to upload 2 log files or attachments, success rate: 2/2.
[2019-04-15 12:13:44Z INFO JobServerQueue] Try to append 1 batches web console lines for record '85f1bd98-2921-5766-8330-d8b491fc5b96', success rate: 1/1.
[2019-04-15 12:13:51Z INFO JobServerQueue] Stop aggressive process web console line queue.
[2019-04-15 12:18:29Z INFO Worker] Cancellation/Shutdown message received.
[2019-04-15 12:18:29Z INFO ExpressionManager] Evaluating: succeeded()
[2019-04-15 12:18:29Z INFO ExpressionManager] Result: False
[2019-04-15 12:18:29Z INFO StepsRunner] Cancel current running step.
[2019-04-15 12:18:29Z INFO ProcessInvokerWrapper] Sending CTRL_C to process 7868.
[2019-04-15 12:18:29Z INFO ProcessInvokerWrapper] Successfully send CTRL_C to process 7868.
[2019-04-15 12:18:29Z INFO ProcessInvokerWrapper] Waiting for process exit or 7.5 seconds after CTRL_C signal fired.
[2019-04-15 12:18:29Z INFO ProcessInvokerWrapper] Ignore Ctrl+C to current process.
[2019-04-15 12:18:29Z INFO ProcessInvokerWrapper] Finished process with exit code 1, and elapsed time 00:04:49.0108550.
[2019-04-15 12:18:29Z ERR  StepsRunner] Caught cancellation exception from step: System.OperationCanceledException: The operation was canceled.
   at System.Threading.CancellationToken.ThrowOperationCanceledException()
   at Microsoft.VisualStudio.Services.Agent.Util.ProcessInvoker.<ExecuteAsync>d__26.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.VisualStudio.Services.Agent.ProcessInvokerWrapper.<ExecuteAsync>d__12.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.VisualStudio.Services.Agent.Worker.Handlers.PowerShellExeHandler.<RunAsync>d__13.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.VisualStudio.Services.Agent.Worker.TaskRunner.<RunAsync>d__24.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.VisualStudio.Services.Agent.Worker.StepsRunner.<RunStepAsync>d__1.MoveNext()
[2019-04-15 12:18:29Z INFO StepsRunner] Step result: Canceled
[2019-04-15 12:18:29Z INFO StepsRunner] No need for updating job result with current step result 'Canceled'.
[2019-04-15 12:18:29Z INFO StepsRunner] Current state: job state = 'Canceled'
[2019-04-15 12:18:29Z INFO StepsRunner] Processing step: DisplayName='Post Job Cleanup', ContinueOnError=False, Enabled=True
[2019-04-15 12:18:29Z INFO ExpressionManager] Evaluating: AlwaysNode()
[2019-04-15 12:18:29Z INFO ExpressionManager] Result: True`

Solution

  • I solved this problem by re-installing SoapUI.

    Not sure why it happens, but TFS doesn't work clearly with SoapUI 5.2.1