From d1849bc134ffa1c478420d6bf456b896453a1a56 Mon Sep 17 00:00:00 2001
From: Martin Blanchard <martin.blanchard@codethink.co.uk>
Date: Tue, 23 Oct 2018 14:33:25 +0100
Subject: [PATCH] cmd_operation.py: Improve bgd operation output

---
 buildgrid/_app/commands/cmd_operation.py | 112 ++++++++++++++++++++---
 1 file changed, 97 insertions(+), 15 deletions(-)

diff --git a/buildgrid/_app/commands/cmd_operation.py b/buildgrid/_app/commands/cmd_operation.py
index 404f0ec6c..5a21a37e4 100644
--- a/buildgrid/_app/commands/cmd_operation.py
+++ b/buildgrid/_app/commands/cmd_operation.py
@@ -25,10 +25,12 @@ from urllib.parse import urlparse
 import sys
 
 import click
+from google.protobuf import json_format
 import grpc
 
 from buildgrid._protos.build.bazel.remote.execution.v2 import remote_execution_pb2, remote_execution_pb2_grpc
 from buildgrid._protos.google.longrunning import operations_pb2, operations_pb2_grpc
+from buildgrid._protos.google.rpc import code_pb2
 
 from ..cli import pass_context
 
@@ -65,45 +67,125 @@ def cli(context, remote, instance_name, client_key, client_cert, server_cert):
     context.logger.debug("Starting for remote {}".format(context.remote))
 
 
+def _print_operation_status(operation, print_details=False):
+    metadata = remote_execution_pb2.ExecuteOperationMetadata()
+    # The metadata is expected to be an ExecuteOperationMetadata message:
+    assert operation.metadata.Is(metadata.DESCRIPTOR)
+    operation.metadata.Unpack(metadata)
+
+    stage_name = remote_execution_pb2.ExecuteOperationMetadata.Stage.Name(
+        metadata.stage).upper()
+
+    if not operation.done:
+        if stage_name == 'CACHE_CHECK':
+            click.echo('CacheCheck: {}: Querying action-cache (stage={})'
+                       .format(operation.name, metadata.stage))
+        elif stage_name == 'QUEUED':
+            click.echo('Queued: {}: Waiting for execution (stage={})'
+                       .format(operation.name, metadata.stage))
+        elif stage_name == 'EXECUTING':
+            click.echo('Executing: {}: Currently running (stage={})'
+                       .format(operation.name, metadata.stage))
+        else:
+            click.echo('Error: {}: In an invalid state (stage={})'
+                       .format(operation.name, metadata.stage), err=True)
+        return
+
+    response = remote_execution_pb2.ExecuteResponse()
+    # The response is expected to be an ExecutionResponse message:
+    assert operation.response.Is(response.DESCRIPTOR)
+    operation.response.Unpack(response)
+
+    if response.status.code != code_pb2.OK:
+        click.echo('Failure: {}: {} (code={})'
+                   .format(operation.name, response.status.message, response.status.code))
+    else:
+        if response.result.exit_code != 0:
+            click.echo('Success: {}: Completed with failure (stage={}, exit_code={})'
+                       .format(operation.name, metadata.stage, response.result.exit_code))
+        else:
+            click.echo('Success: {}: Completed succesfully (stage={}, exit_code={})'
+                       .format(operation.name, metadata.stage, response.result.exit_code))
+
+    if print_details:
+        metadata = response.result.execution_metadata
+        click.echo('  worker={}'.format(metadata.worker))
+
+        queued = metadata.queued_timestamp.ToDatetime()
+        click.echo('  queued_at={}'.format(queued))
+
+        worker_start = metadata.worker_start_timestamp.ToDatetime()
+        worker_completed = metadata.worker_completed_timestamp.ToDatetime()
+        click.echo('  work_duration={}'.format(worker_completed - worker_start))
+
+        fetch_start = metadata.input_fetch_start_timestamp.ToDatetime()
+        fetch_completed = metadata.input_fetch_completed_timestamp.ToDatetime()
+        click.echo('    fetch_duration={}'.format(fetch_completed - fetch_start))
+
+        execution_start = metadata.execution_start_timestamp.ToDatetime()
+        execution_completed = metadata.execution_completed_timestamp.ToDatetime()
+        click.echo('    exection_duration={}'.format(execution_completed - execution_start))
+
+        upload_start = metadata.output_upload_start_timestamp.ToDatetime()
+        upload_completed = metadata.output_upload_completed_timestamp.ToDatetime()
+        click.echo('    upload_duration={}'.format(upload_completed - upload_start))
+
+        click.echo('  total_duration={}'.format(worker_completed - queued))
+
+
 @cli.command('status', short_help="Get the status of an operation.")
 @click.argument('operation-name', nargs=1, type=click.STRING, required=True)
+@click.option('--json', is_flag=True, show_default=True,
+              help="Print operations status in JSON format.")
 @pass_context
-def status(context, operation_name):
-    context.logger.info("Getting operation status...")
+def status(context, operation_name, json):
     stub = operations_pb2_grpc.OperationsStub(context.channel)
-
     request = operations_pb2.GetOperationRequest(name=operation_name)
 
-    response = stub.GetOperation(request)
-    context.logger.info(response)
+    operation = stub.GetOperation(request)
+
+    if not json:
+        _print_operation_status(operation, print_details=True)
+    else:
+        click.echo(json_format.MessageToJson(operation))
 
 
 @cli.command('list', short_help="List operations.")
+@click.option('--json', is_flag=True, show_default=True,
+              help="Print operations list in JSON format.")
 @pass_context
-def lists(context):
-    context.logger.info("Getting list of operations")
+def lists(context, json):
     stub = operations_pb2_grpc.OperationsStub(context.channel)
-
     request = operations_pb2.ListOperationsRequest(name=context.instance_name)
 
     response = stub.ListOperations(request)
 
     if not response.operations:
-        context.logger.warning("No operations to list")
+        click.echo('Error: No operations to list', err=True)
         return
 
-    for op in response.operations:
-        context.logger.info(op)
+    for operation in response.operations:
+        if not json:
+            _print_operation_status(operation)
+        else:
+            click.echo(json_format.MessageToJson(operation))
 
 
 @cli.command('wait', short_help="Streams an operation until it is complete.")
 @click.argument('operation-name', nargs=1, type=click.STRING, required=True)
+@click.option('--json', is_flag=True, show_default=True,
+              help="Print operations statuses in JSON format.")
 @pass_context
-def wait(context, operation_name):
+def wait(context, operation_name, json):
     stub = remote_execution_pb2_grpc.ExecutionStub(context.channel)
     request = remote_execution_pb2.WaitExecutionRequest(name=operation_name)
 
-    response = stub.WaitExecution(request)
+    operation_iterator = stub.WaitExecution(request)
 
-    for stream in response:
-        context.logger.info(stream)
+    for operation in operation_iterator:
+        if not json and operation.done:
+            _print_operation_status(operation, print_details=True)
+        elif not json:
+            _print_operation_status(operation)
+        else:
+            click.echo(json_format.MessageToJson(operation))
-- 
GitLab