Cleanup and complete json logs a bit

[eseliger]

Required for new SSBC step resolvers to have all data needed.

Successful run

{"operation":"PARSING_BATCH_SPEC","timestamp":"2021-09-22T14:32:05.623Z","status":"STARTED"}
{"operation":"PARSING_BATCH_SPEC","timestamp":"2021-09-22T14:32:05.624Z","status":"SUCCESS"}

{"operation":"PREPARING_DOCKER_IMAGES","timestamp":"2021-09-22T14:32:05.624Z","status":"STARTED"}
{"operation":"PREPARING_DOCKER_IMAGES","timestamp":"2021-09-22T14:32:05.624Z","status":"PROGRESS","metadata":{"done":0,"total":1}}
{"operation":"PREPARING_DOCKER_IMAGES","timestamp":"2021-09-22T14:32:05.792Z","status":"PROGRESS","metadata":{"done":1,"total":1}}
{"operation":"PREPARING_DOCKER_IMAGES","timestamp":"2021-09-22T14:32:05.792Z","status":"SUCCESS"}

{"operation":"DETERMINING_WORKSPACE_TYPE","timestamp":"2021-09-22T14:32:05.792Z","status":"STARTED"}
{"operation":"DETERMINING_WORKSPACE_TYPE","timestamp":"2021-09-22T14:32:06.579Z","status":"SUCCESS","metadata":{"type":"VOLUME"}}

{"operation":"CHECKING_CACHE","timestamp":"2021-09-22T14:32:06.579Z","status":"STARTED"}
{"operation":"CHECKING_CACHE","timestamp":"2021-09-22T14:32:06.579Z","status":"SUCCESS","metadata":{"cachedSpecsFound":0,"tasksToExecute":1}}

{"operation":"EXECUTING_TASKS","timestamp":"2021-09-22T14:32:06.579Z","status":"STARTED","metadata":{"tasks":[{"id":"3DBBix6IBjG","repository":"bitbucket.sgdev.org/SOUR/automation-testing","workspace":"","steps":[{"run":"echo Hello World | tee -a $(find -name README.md)","container":"ubuntu:18.04","env":{}},{"run":"echo Hello World | tee -a $(find -name README.md)","container":"ubuntu:18.04","env":{}}],"cachedStepResultFound":false,"startStep":0}]}}
    {"operation":"EXECUTING_TASK","timestamp":"2021-09-22T14:32:06.579Z","status":"STARTED","metadata":{"taskID":"3DBBix6IBjG"}}
        {"operation":"TASK_DOWNLOADING_ARCHIVE","timestamp":"2021-09-22T14:32:06.579Z","status":"STARTED","metadata":{"taskID":"3DBBix6IBjG"}}
        {"operation":"TASK_DOWNLOADING_ARCHIVE","timestamp":"2021-09-22T14:32:06.611Z","status":"SUCCESS","metadata":{"taskID":"3DBBix6IBjG"}}
        
        {"operation":"TASK_INITIALIZING_WORKSPACE","timestamp":"2021-09-22T14:32:06.611Z","status":"STARTED","metadata":{"taskID":"3DBBix6IBjG"}}
        {"operation":"TASK_INITIALIZING_WORKSPACE","timestamp":"2021-09-22T14:32:08.653Z","status":"SUCCESS","metadata":{"taskID":"3DBBix6IBjG"}}
        
        {"operation":"TASK_PREPARING_STEP","timestamp":"2021-09-22T14:32:08.653Z","status":"STARTED","metadata":{"step":1,"taskID":"3DBBix6IBjG"}}
        {"operation":"TASK_PREPARING_STEP","timestamp":"2021-09-22T14:32:09.234Z","status":"SUCCESS","metadata":{"step":1,"taskID":"3DBBix6IBjG"}}
        
        {"operation":"TASK_STEP","timestamp":"2021-09-22T14:32:09.234Z","status":"STARTED","metadata":{"env":{},"runScript":"echo Hello World | tee -a $(find -name README.md)","step":1,"taskID":"3DBBix6IBjG"}}
        {"operation":"TASK_STEP","timestamp":"2021-09-22T14:32:09.737Z","status":"PROGRESS","metadata":{"out":"stdout: Hello World\nstdout: \n","step":0,"taskID":"3DBBix6IBjG"}}
        {"operation":"TASK_STEP","timestamp":"2021-09-22T14:32:11.368Z","status":"SUCCESS","metadata":{"changes":{"modified":["README.md","examples/README.md","examples/project3/README.md","project1/README.md","project2/README.md"],"added":null,"deleted":null,"renamed":null},"diff":"diff --git README.md README.md\nindex 40f2a50..d637716 100644\n--- README.md\n+++ README.md\n@@ -4,4 +4,4 @@ This repository is used to test opening and closing pull request with Automation\n (c) Copyright Sourcegraph 2013-2020.\n (c) Copyright Sourcegraph 2013-2020.\n (c) Copyright Sourcegraph 2013-2020.\n-(c) Copyright Sourcegraph 2013-2020.\n\\ No newline at end of file\n+(c) Copyright Sourcegraph 2013-2020.Hello World\ndiff --git examples/README.md examples/README.md\nindex 1672048..fa0249d 100644\n--- examples/README.md\n+++ examples/README.md\n@@ -6,4 +6,4 @@ This folder contains examples\n \n (c) Copyright Sourcegraph 2013-2020.\n (c) Copyright Sourcegraph 2013-2020.\n-(c) Copyright Sourcegraph 2013-2020.\n\\ No newline at end of file\n+(c) Copyright Sourcegraph 2013-2020.Hello World\ndiff --git examples/project3/README.md examples/project3/README.md\nindex 2dda72d..29637aa 100644\n--- examples/project3/README.md\n+++ examples/project3/README.md\n@@ -2,4 +2,4 @@\n \n (c) Copyright Sourcegraph 2013-2020.\n (c) Copyright Sourcegraph 2013-2020.\n-(c) Copyright Sourcegraph 2013-2020.\n\\ No newline at end of file\n+(c) Copyright Sourcegraph 2013-2020.Hello World\ndiff --git project1/README.md project1/README.md\nindex 49052b2..e49f1fd 100644\n--- project1/README.md\n+++ project1/README.md\n@@ -4,4 +4,4 @@ This is project 1.\n \n (c) Copyright Sourcegraph 2013-2020.\n (c) Copyright Sourcegraph 2013-2020.\n-(c) Copyright Sourcegraph 2013-2020.\n\\ No newline at end of file\n+(c) Copyright Sourcegraph 2013-2020.Hello World\ndiff --git project2/README.md project2/README.md\nindex b999c76..705a7c7 100644\n--- project2/README.md\n+++ project2/README.md\n@@ -4,4 +4,4 @@ This is project 2\n \n (c) Copyright Sourcegraph 2013-2020.\n (c) Copyright Sourcegraph 2013-2020.\n-(c) Copyright Sourcegraph 2013-2020.\n\\ No newline at end of file\n+(c) Copyright Sourcegraph 2013-2020.Hello World\n","outputs":{},"step":1,"taskID":"3DBBix6IBjG"}}
        
        {"operation":"TASK_PREPARING_STEP","timestamp":"2021-09-22T14:32:11.369Z","status":"STARTED","metadata":{"step":2,"taskID":"3DBBix6IBjG"}}
        {"operation":"TASK_PREPARING_STEP","timestamp":"2021-09-22T14:32:11.992Z","status":"SUCCESS","metadata":{"step":2,"taskID":"3DBBix6IBjG"}}
        
        {"operation":"TASK_STEP","timestamp":"2021-09-22T14:32:11.992Z","status":"STARTED","metadata":{"env":{},"runScript":"echo Hello World | tee -a $(find -name README.md)","step":2,"taskID":"3DBBix6IBjG"}}
        {"operation":"TASK_STEP","timestamp":"2021-09-22T14:32:12.684Z","status":"PROGRESS","metadata":{"out":"stdout: Hello World\nstdout: \n","step":1,"taskID":"3DBBix6IBjG"}}
        {"operation":"TASK_STEP","timestamp":"2021-09-22T14:32:14.199Z","status":"SUCCESS","metadata":{"changes":{"modified":["README.md","examples/README.md","examples/project3/README.md","project1/README.md","project2/README.md"],"added":null,"deleted":null,"renamed":null},"diff":"diff --git README.md README.md\nindex 40f2a50..954e8e3 100644\n--- README.md\n+++ README.md\n@@ -4,4 +4,5 @@ This repository is used to test opening and closing pull request with Automation\n (c) Copyright Sourcegraph 2013-2020.\n (c) Copyright Sourcegraph 2013-2020.\n (c) Copyright Sourcegraph 2013-2020.\n-(c) Copyright Sourcegraph 2013-2020.\n\\ No newline at end of file\n+(c) Copyright Sourcegraph 2013-2020.Hello World\n+Hello World\ndiff --git examples/README.md examples/README.md\nindex 1672048..08258c9 100644\n--- examples/README.md\n+++ examples/README.md\n@@ -6,4 +6,5 @@ This folder contains examples\n \n (c) Copyright Sourcegraph 2013-2020.\n (c) Copyright Sourcegraph 2013-2020.\n-(c) Copyright Sourcegraph 2013-2020.\n\\ No newline at end of file\n+(c) Copyright Sourcegraph 2013-2020.Hello World\n+Hello World\ndiff --git examples/project3/README.md examples/project3/README.md\nindex 2dda72d..7c46e5e 100644\n--- examples/project3/README.md\n+++ examples/project3/README.md\n@@ -2,4 +2,5 @@\n \n (c) Copyright Sourcegraph 2013-2020.\n (c) Copyright Sourcegraph 2013-2020.\n-(c) Copyright Sourcegraph 2013-2020.\n\\ No newline at end of file\n+(c) Copyright Sourcegraph 2013-2020.Hello World\n+Hello World\ndiff --git project1/README.md project1/README.md\nindex 49052b2..7d135fd 100644\n--- project1/README.md\n+++ project1/README.md\n@@ -4,4 +4,5 @@ This is project 1.\n \n (c) Copyright Sourcegraph 2013-2020.\n (c) Copyright Sourcegraph 2013-2020.\n-(c) Copyright Sourcegraph 2013-2020.\n\\ No newline at end of file\n+(c) Copyright Sourcegraph 2013-2020.Hello World\n+Hello World\ndiff --git project2/README.md project2/README.md\nindex b999c76..1c9eddf 100644\n--- project2/README.md\n+++ project2/README.md\n@@ -4,4 +4,5 @@ This is project 2\n \n (c) Copyright Sourcegraph 2013-2020.\n (c) Copyright Sourcegraph 2013-2020.\n-(c) Copyright Sourcegraph 2013-2020.\n\\ No newline at end of file\n+(c) Copyright Sourcegraph 2013-2020.Hello World\n+Hello World\n","outputs":{},"step":2,"taskID":"3DBBix6IBjG"}}
        
        {"operation":"TASK_CALCULATING_DIFF","timestamp":"2021-09-22T14:32:14.199Z","status":"STARTED","metadata":{"taskID":"3DBBix6IBjG"}}
        {"operation":"TASK_CALCULATING_DIFF","timestamp":"2021-09-22T14:32:14.876Z","status":"SUCCESS","metadata":{"taskID":"3DBBix6IBjG"}}
    {"operation":"EXECUTING_TASK","timestamp":"2021-09-22T14:32:15.06Z","status":"SUCCESS","metadata":{"taskID":"3DBBix6IBjG"}}
    
    {"operation":"TASK_BUILD_CHANGESET_SPECS","timestamp":"2021-09-22T14:32:15.061Z","status":"SUCCESS","metadata":{"taskID":"3DBBix6IBjG"}}
{"operation":"EXECUTING_TASKS","timestamp":"2021-09-22T14:32:15.061Z","status":"SUCCESS"}

{"operation":"UPLOADING_CHANGESET_SPECS","timestamp":"2021-09-22T14:32:15.061Z","status":"STARTED","metadata":{"total":1}}
{"operation":"UPLOADING_CHANGESET_SPECS","timestamp":"2021-09-22T14:32:15.072Z","status":"PROGRESS","metadata":{"done":1,"total":1}}
{"operation":"UPLOADING_CHANGESET_SPECS","timestamp":"2021-09-22T14:32:15.072Z","status":"SUCCESS","metadata":{"ids":["Q2hhbmdlc2V0U3BlYzoiOGNPSU1HMlJHaDci"]}}

Failed run

{"operation":"PARSING_BATCH_SPEC","timestamp":"2021-09-27T14:10:21.718Z","status":"STARTED","metadata":{}}
{"operation":"PARSING_BATCH_SPEC","timestamp":"2021-09-27T14:10:21.719Z","status":"SUCCESS","metadata":{}}

{"operation":"PREPARING_DOCKER_IMAGES","timestamp":"2021-09-27T14:10:21.719Z","status":"STARTED","metadata":{}}
{"operation":"PREPARING_DOCKER_IMAGES","timestamp":"2021-09-27T14:10:21.719Z","status":"PROGRESS","metadata":{"total":1}}
{"operation":"PREPARING_DOCKER_IMAGES","timestamp":"2021-09-27T14:10:21.903Z","status":"PROGRESS","metadata":{"done":1,"total":1}}
{"operation":"PREPARING_DOCKER_IMAGES","timestamp":"2021-09-27T14:10:21.903Z","status":"SUCCESS","metadata":{}}

{"operation":"DETERMINING_WORKSPACE_TYPE","timestamp":"2021-09-27T14:10:21.903Z","status":"STARTED","metadata":{}}
{"operation":"DETERMINING_WORKSPACE_TYPE","timestamp":"2021-09-27T14:10:22.863Z","status":"SUCCESS","metadata":{"type":"VOLUME"}}

{"operation":"CHECKING_CACHE","timestamp":"2021-09-27T14:10:22.864Z","status":"STARTED","metadata":{}}
{"operation":"CHECKING_CACHE","timestamp":"2021-09-27T14:10:22.864Z","status":"SUCCESS","metadata":{"tasksToExecute":1}}

{"operation":"EXECUTING_TASKS","timestamp":"2021-09-27T14:10:22.864Z","status":"STARTED","metadata":{"tasks":[{"id":"5empzDpio4q","repository":"bitbucket.sgdev.org/SOUR/automation-testing","workspace":"","steps":[{"run":"echo Hello World | tee -a $(find -name README.md)","container":"ubuntu:18.04","env":{}},{"run":"echo Hello World | tee -a $(find -name README.md) \u0026\u0026 exit 1","container":"ubuntu:18.04","env":{}}],"cachedStepResultFound":false,"startStep":0}]}}
    {"operation":"EXECUTING_TASK","timestamp":"2021-09-27T14:10:22.864Z","status":"STARTED","metadata":{"taskID":"5empzDpio4q"}}
        {"operation":"TASK_DOWNLOADING_ARCHIVE","timestamp":"2021-09-27T14:10:22.865Z","status":"STARTED","metadata":{"taskID":"5empzDpio4q"}}
        {"operation":"TASK_DOWNLOADING_ARCHIVE","timestamp":"2021-09-27T14:10:22.904Z","status":"SUCCESS","metadata":{"taskID":"5empzDpio4q"}}
        
        {"operation":"TASK_INITIALIZING_WORKSPACE","timestamp":"2021-09-27T14:10:22.904Z","status":"STARTED","metadata":{"taskID":"5empzDpio4q"}}
        {"operation":"TASK_INITIALIZING_WORKSPACE","timestamp":"2021-09-27T14:10:25.241Z","status":"SUCCESS","metadata":{"taskID":"5empzDpio4q"}}
        
        {"operation":"TASK_PREPARING_STEP","timestamp":"2021-09-27T14:10:25.241Z","status":"STARTED","metadata":{"taskID":"5empzDpio4q","step":1}}
        {"operation":"TASK_PREPARING_STEP","timestamp":"2021-09-27T14:10:25.957Z","status":"SUCCESS","metadata":{"taskID":"5empzDpio4q","step":1}}
        
        {"operation":"TASK_STEP","timestamp":"2021-09-27T14:10:25.957Z","status":"STARTED","metadata":{"taskID":"5empzDpio4q","step":1}}
            {"operation":"TASK_STEP","timestamp":"2021-09-27T14:10:26.708Z","status":"PROGRESS","metadata":{"taskID":"5empzDpio4q","out":"stdout: Hello World\nstdout: \n"}}
        {"operation":"TASK_STEP","timestamp":"2021-09-27T14:10:28.506Z","status":"SUCCESS","metadata":{"taskID":"5empzDpio4q","step":1,"diff":"diff --git README.md README.md\nindex 40f2a50..d637716 100644\n--- README.md\n+++ README.md\n@@ -4,4 +4,4 @@ This repository is used to test opening and closing pull request with Automation\n (c) Copyright Sourcegraph 2013-2020.\n (c) Copyright Sourcegraph 2013-2020.\n (c) Copyright Sourcegraph 2013-2020.\n-(c) Copyright Sourcegraph 2013-2020.\n\\ No newline at end of file\n+(c) Copyright Sourcegraph 2013-2020.Hello World\ndiff --git examples/README.md examples/README.md\nindex 1672048..fa0249d 100644\n--- examples/README.md\n+++ examples/README.md\n@@ -6,4 +6,4 @@ This folder contains examples\n \n (c) Copyright Sourcegraph 2013-2020.\n (c) Copyright Sourcegraph 2013-2020.\n-(c) Copyright Sourcegraph 2013-2020.\n\\ No newline at end of file\n+(c) Copyright Sourcegraph 2013-2020.Hello World\ndiff --git examples/project3/README.md examples/project3/README.md\nindex 2dda72d..29637aa 100644\n--- examples/project3/README.md\n+++ examples/project3/README.md\n@@ -2,4 +2,4 @@\n \n (c) Copyright Sourcegraph 2013-2020.\n (c) Copyright Sourcegraph 2013-2020.\n-(c) Copyright Sourcegraph 2013-2020.\n\\ No newline at end of file\n+(c) Copyright Sourcegraph 2013-2020.Hello World\ndiff --git project1/README.md project1/README.md\nindex 49052b2..e49f1fd 100644\n--- project1/README.md\n+++ project1/README.md\n@@ -4,4 +4,4 @@ This is project 1.\n \n (c) Copyright Sourcegraph 2013-2020.\n (c) Copyright Sourcegraph 2013-2020.\n-(c) Copyright Sourcegraph 2013-2020.\n\\ No newline at end of file\n+(c) Copyright Sourcegraph 2013-2020.Hello World\ndiff --git project2/README.md project2/README.md\nindex b999c76..705a7c7 100644\n--- project2/README.md\n+++ project2/README.md\n@@ -4,4 +4,4 @@ This is project 2\n \n (c) Copyright Sourcegraph 2013-2020.\n (c) Copyright Sourcegraph 2013-2020.\n-(c) Copyright Sourcegraph 2013-2020.\n\\ No newline at end of file\n+(c) Copyright Sourcegraph 2013-2020.Hello World\n"}}
        
        {"operation":"TASK_PREPARING_STEP","timestamp":"2021-09-27T14:10:28.506Z","status":"STARTED","metadata":{"taskID":"5empzDpio4q","step":2}}
        {"operation":"TASK_PREPARING_STEP","timestamp":"2021-09-27T14:10:29.331Z","status":"SUCCESS","metadata":{"taskID":"5empzDpio4q","step":2}}
        
        {"operation":"TASK_STEP","timestamp":"2021-09-27T14:10:29.331Z","status":"STARTED","metadata":{"taskID":"5empzDpio4q","step":2}}
            {"operation":"TASK_STEP","timestamp":"2021-09-27T14:10:30.057Z","status":"PROGRESS","metadata":{"taskID":"5empzDpio4q","step":1,"out":"stdout: Hello World\nstdout: \n"}}
        {"operation":"TASK_STEP","timestamp":"2021-09-27T14:10:30.283Z","status":"FAILURE","metadata":{"taskID":"5empzDpio4q","step":2,"exitCode":1,"error":"run: echo Hello World | tee -a $(find -name README.md) \u0026\u0026 exit 1\ncontainer: ubuntu:18.04\n\nstandard out:\n\tHello World\n\nCommand failed with exit code 1."}}
        {"operation":"EXECUTING_TASK","timestamp":"2021-09-27T14:10:30.491Z","status":"FAILURE","metadata":{"taskID":"5empzDpio4q","error":"execution in bitbucket.sgdev.org/SOUR/automation-testing failed: run: echo Hello World | tee -a $(find -name README.md) \u0026\u0026 exit 1\ncontainer: ubuntu:18.04\n\nstandard out:\n\tHello World\n\nCommand failed with exit code 1. (see /tmp/changeset-bitbucket.sgdev.org-SOUR-automation-testing-433511c512c568a6dbc308c2347879f9d6095849.2203834475.log for details)"}}
    {"operation":"EXECUTING_TASKS","timestamp":"2021-09-27T14:10:30.491Z","status":"FAILURE","metadata":{"error":"execution in bitbucket.sgdev.org/SOUR/automation-testing failed: run: echo Hello World | tee -a $(find -name README.md) \u0026\u0026 exit 1\ncontainer: ubuntu:18.04\n\nstandard out:\n\tHello World\n\nCommand failed with exit code 1. (see /tmp/changeset-bitbucket.sgdev.org-SOUR-automation-testing-433511c512c568a6dbc308c2347879f9d6095849.2203834475.log for details)"}}
{"operation":"BATCH_SPEC_EXECUTION","timestamp":"2021-09-27T14:10:30.491Z","status":"FAILURE","metadata":{"error":"execution in bitbucket.sgdev.org/SOUR/automation-testing failed: run: echo Hello World | tee -a $(find -name README.md) \u0026\u0026 exit 1\ncontainer: ubuntu:18.04\n\nstandard out:\n\tHello World\n\nCommand failed with exit code 1. (see /tmp/changeset-bitbucket.sgdev.org-SOUR-automation-testing-433511c512c568a6dbc308c2347879f9d6095849.2203834475.log for details)"}}