Improved Logging and Manual Tests (#14)

* Add ListHandler with UnitTests

* Move duplicate handler code into super class

* Add capibility to log exceptions

* Add guide on how to test changes manually E2E

* Fix pre-commit failing check

GetAtt was not found by pre-commit. Removed it from the yaml.

aws-opsworkscm-server/README.md

@@ -10,6 +10,12 @@
       1. `pre-commit run --all-files`.  To install `pre-commit` run `pip install pre-commit`
       2. `cfn submit --dry-run`
 
+* Testing it manually End to End:
+    1. Deploy the resource type for your own account: `cfn submit --region <REGION> --set-default`
+    2. Make sure the type is published `aws cloudformation describe-type-registration --registration-token '<REGISTRATION_TOKEN'>` using the token from the previous step
+    3. Create a test stack with `aws cloudformation create-stack --stack-name STACK_NAME --template-body file://TEMPLATE_FILE`. You can find templates in the `templates` directory.
+    4. Go to the CloudWatch log group 'aws-opsworkscm-server-logs' to see the handler logs
+
 * Use CloudFormation Handler Contracts with `cfn test`. More on that here: https://docs.aws.amazon.com/cloudformation-cli/latest/userguide/resource-type-test.html
 
 ____________________

aws-opsworkscm-server/src/main/java/software/amazon/opsworkscm/server/BaseOpsWorksCMHandler.java

@@ -7,14 +7,15 @@
 import software.amazon.cloudformation.proxy.ProgressEvent;
 import software.amazon.cloudformation.proxy.ResourceHandlerRequest;
 import software.amazon.cloudformation.resource.IdentifierUtils;
+import software.amazon.opsworkscm.server.utils.LoggerWrapper;
 
 abstract public class BaseOpsWorksCMHandler extends BaseHandler<CallbackContext> {
 
 
     protected ResourceModel model;
     protected ResourceModel oldModel;
     protected CallbackContext callbackContext;
-    protected Logger logger;
+    protected LoggerWrapper log;
     protected ResourceHandlerRequest<ResourceModel> request;
     protected ClientWrapper client;
 
@@ -37,18 +38,18 @@ protected void initialize(final AmazonWebServicesClientProxy proxy,
         this.model = request.getDesiredResourceState();
         this.oldModel = request.getPreviousResourceState();
         this.callbackContext = callbackContext;
-        this.logger = logger;
+        this.log = new LoggerWrapper(logger);
 
         setModelServerName();
         setModelId();
 
         final OpsWorksCmClient opsWorksCmClientclient = ClientBuilder.getClient();
-        this.client = new ClientWrapper(opsWorksCmClientclient, model, oldModel, proxy, logger);
+        this.client = new ClientWrapper(opsWorksCmClientclient, model, oldModel, proxy, log);
     }
 
     private void setModelServerName() {
         if (StringUtils.isNullOrEmpty(model.getServerName())) {
-            logger.log("RequestModel doesn't have the server name. Setting it using request identifier and client token");
+            log.log("RequestModel doesn't have the server name. Setting it using request identifier and client token");
             model.setServerName(
                     IdentifierUtils.generateResourceIdentifier(
                             request.getLogicalResourceIdentifier(),
@@ -57,14 +58,14 @@ private void setModelServerName() {
                     )
             );
         } else if (model.getServerName().length() > MAX_LENGTH_CONFIGURATION_SET_NAME) {
-            logger.log(String.format("ServerName length was greater than %d characters. Truncating the ServerName", MAX_LENGTH_CONFIGURATION_SET_NAME));
+            log.log(String.format("ServerName length was greater than %d characters. Truncating the ServerName", MAX_LENGTH_CONFIGURATION_SET_NAME));
             model.setServerName(model.getServerName().substring(0, MAX_LENGTH_CONFIGURATION_SET_NAME));
         }
     }
 
     private void setModelId() {
         if (model.getId() == null) {
-            logger.log("RequestModel doesn't have the model id. Setting it using request identifier and client token");
+            log.log("RequestModel doesn't have the model id. Setting it using request identifier and client token");
             model.setId(IdentifierUtils.generateResourceIdentifier(
                     request.getLogicalResourceIdentifier(),
                     request.getClientRequestToken()

aws-opsworkscm-server/src/main/java/software/amazon/opsworkscm/server/ClientWrapper.java

@@ -19,6 +19,7 @@
 import software.amazon.awssdk.services.opsworkscm.model.UpdateServerResponse;
 import software.amazon.cloudformation.proxy.AmazonWebServicesClientProxy;
 import software.amazon.cloudformation.proxy.Logger;
+import software.amazon.opsworkscm.server.utils.LoggerWrapper;
 
 import java.util.Collections;
 import java.util.List;
@@ -32,7 +33,7 @@ public class ClientWrapper {
     ResourceModel model;
     ResourceModel oldModel;
     AmazonWebServicesClientProxy proxy;
-    Logger logger;
+    LoggerWrapper log;
 
     public DescribeServersResponse describeServer() {
         return proxy.injectCredentialsAndInvokeV2(buildDescribeServerRequest(), client::describeServers);

aws-opsworkscm-server/src/main/java/software/amazon/opsworkscm/server/CreateHandler.java

@@ -30,10 +30,10 @@ public ProgressEvent<ResourceModel, CallbackContext> handleRequest(
                 return handleExecute();
             }
         } catch (InvalidStateException e) {
-            logger.log(String.format("Service Side failure during create-server for %s.", model.getServerName()));
+            log.error(String.format("Service Side failure during create-server for %s.", model.getServerName()), e);
             return ProgressEvent.failed(model, callbackContext, HandlerErrorCode.InternalFailure, "Service Internal Failure");
         } catch (Exception e) {
-            logger.log(String.format("CreateHandler failure during create-server for %s.", model.getServerName()));
+            log.error(String.format("CreateHandler failure during create-server for %s.", model.getServerName()), e);
             return ProgressEvent.failed(model, callbackContext, HandlerErrorCode.InternalFailure, "Internal Failure");
         }
     }
@@ -44,7 +44,7 @@ private ProgressEvent<ResourceModel, CallbackContext> handleExecute() {
             callbackContext.setStabilizationStarted(true);
             return ProgressEvent.defaultInProgressHandler(callbackContext, CALLBACK_DELAY_SECONDS, model);
         } catch (ResourceAlreadyExistsException e) {
-            logger.log(String.format("Server %s already exists.", model.getServerName()));
+            log.info(String.format("Server %s already exists.", model.getServerName()));
             return ProgressEvent.defaultFailureHandler(e, HandlerErrorCode.AlreadyExists);
         }
     }
@@ -61,7 +61,7 @@ private ProgressEvent<ResourceModel, CallbackContext> handleStabilize() {
         }
 
         if (result == null || result.servers() == null) {
-            logger.log("Describe result is Null. Retrying request.");
+            log.info("Describe result is Null. Retrying request.");
             return ProgressEvent.defaultInProgressHandler(callbackContext, NO_CALLBACK_DELAY, model);
         }
 
@@ -75,7 +75,7 @@ private ProgressEvent<ResourceModel, CallbackContext> handleStabilize() {
         String actualServerName = server.serverName();
         switch (serverStatus) {
             case HEALTHY:
-                logger.log(String.format("Server %s succeeded CREATE.", actualServerName));
+                log.info(String.format("Server %s succeeded CREATE.", actualServerName));
                 return ProgressEvent.defaultSuccessHandler(model);
             case BACKING_UP:
             case MODIFYING:
@@ -84,7 +84,7 @@ private ProgressEvent<ResourceModel, CallbackContext> handleStabilize() {
             case CREATING:
                 return ProgressEvent.defaultInProgressHandler(callbackContext, CALLBACK_DELAY_SECONDS, model);
             default:
-                logger.log(String.format("Server %s failed to CREATE because of reason: %s", actualServerName, statusReason));
+                log.info(String.format("Server %s failed to CREATE because of reason: %s", actualServerName, statusReason));
                 return ProgressEvent.failed(
                         model,
                         callbackContext,
@@ -96,7 +96,7 @@ private ProgressEvent<ResourceModel, CallbackContext> handleStabilize() {
 
 
     private ProgressEvent<ResourceModel, CallbackContext> handleServerNotFound(final String serverName) {
-        logger.log(String.format("Server %s failed to CREATE because it was not found.", serverName));
+        log.info(String.format("Server %s failed to CREATE because it was not found.", serverName));
         return ProgressEvent.failed(
                 model,
                 callbackContext,

aws-opsworkscm-server/src/main/java/software/amazon/opsworkscm/server/DeleteHandler.java

@@ -34,18 +34,19 @@ public ProgressEvent<ResourceModel, CallbackContext> handleRequest(
                 return handleExecute();
             }
         } catch (InvalidStateException e) {
-            logger.log(String.format("Service Side failure during delete-server for %s.", model.getServerName()));
+            log.error(String.format("Service Side failure during delete-server for %s.", model.getServerName()), e);
             return ProgressEvent.failed(model, callbackContext, HandlerErrorCode.NotStabilized, "Service Internal Failure");
         } catch (ResourceNotFoundException e) {
             return handleServerNotFound(model.getServerName());
         } catch (ValidationException e) {
+            log.error(String.format("ValidationException during delete-server of %s.", model.getServerName()), e);
             if (e.getMessage().matches(String.format(SERVER_OPERATION_STILL_IN_PROGRESS_MESSAGE, model.getServerName()))) {
-                logger.log(String.format("Server operation still in progress during delete-server of %s.", model.getServerName()));
+                log.error(String.format("Server operation still in progress during delete-server of %s.", model.getServerName()));
                 return ProgressEvent.defaultInProgressHandler(callbackContext, CALLBACK_DELAY_SECONDS, model);
             }
             return ProgressEvent.defaultFailureHandler(e, HandlerErrorCode.InvalidRequest);
         } catch (Exception e) {
-            logger.log(String.format("CreateHandler failure during delete-server for %s.", model.getServerName()));
+            log.error(String.format("CreateHandler failure during delete-server for %s.", model.getServerName()), e);
             return ProgressEvent.failed(model, callbackContext, HandlerErrorCode.InternalFailure, "Internal Failure");
         }
     }
@@ -64,7 +65,7 @@ private ProgressEvent<ResourceModel, CallbackContext> handleStabilize() {
         result = client.describeServer();
 
         if (result == null || result.servers() == null) {
-            logger.log("Describe result is Null. Retrying request.");
+            log.info("Describe result is Null. Retrying request.");
             return ProgressEvent.defaultInProgressHandler(callbackContext, NO_CALLBACK_DELAY, model);
         }
 
@@ -81,17 +82,17 @@ private ProgressEvent<ResourceModel, CallbackContext> handleStabilize() {
             case DELETING:
                 return ProgressEvent.defaultInProgressHandler(callbackContext, CALLBACK_DELAY_SECONDS, model);
             case FAILED:
-                logger.log(String.format(SERVER_DELETION_FAILED_MESSAGE, actualServerName, statusReason));
+                log.info(String.format(SERVER_DELETION_FAILED_MESSAGE, actualServerName, statusReason));
                 return ProgressEvent.failed(model, callbackContext, HandlerErrorCode.NotUpdatable, String.format(SERVER_DELETION_FAILED_MESSAGE, actualServerName, statusReason));
             default:
-                logger.log(String.format("Server %s is in an unexpected state. Server should be deleted, but is %s. With reason: %s",
+                log.info(String.format("Server %s is in an unexpected state. Server should be deleted, but is %s. With reason: %s",
                         actualServerName, serverStatus, statusReason));
                 return ProgressEvent.defaultInProgressHandler(callbackContext, CALLBACK_DELAY_SECONDS, model);
         }
     }
 
     private ProgressEvent<ResourceModel, CallbackContext> handleServerNotFound(final String serverName) {
-        logger.log(String.format("Server %s deleted successfully.", serverName));
+        log.info(String.format("Server %s deleted successfully.", serverName));
         return ProgressEvent.defaultSuccessHandler(model);
     }
 }

aws-opsworkscm-server/src/main/java/software/amazon/opsworkscm/server/ListHandler.java

@@ -8,6 +8,7 @@
 import software.amazon.cloudformation.proxy.OperationStatus;
 import software.amazon.cloudformation.proxy.ProgressEvent;
 import software.amazon.cloudformation.proxy.ResourceHandlerRequest;
+import software.amazon.opsworkscm.server.utils.LoggerWrapper;
 
 import java.util.ArrayList;
 import java.util.List;
@@ -17,7 +18,7 @@ public class ListHandler extends BaseHandler<CallbackContext> {
     private static final int NO_CALLBACK_DELAY = 0;
 
     CallbackContext callbackContext;
-    Logger logger;
+    LoggerWrapper log;
     ResourceHandlerRequest<ResourceModel> request;
     ClientWrapper client;
 
@@ -28,16 +29,16 @@ public ProgressEvent<ResourceModel, CallbackContext> handleRequest(
             final CallbackContext callbackContext,
             final Logger logger) {
 
-        this.logger = logger;
+        this.log = new LoggerWrapper(logger);
 
         final OpsWorksCmClient opsWorksCmClientclient = ClientBuilder.getClient();
-        this.client = new ClientWrapper(opsWorksCmClientclient, request.getDesiredResourceState(), request.getPreviousResourceState(), proxy, logger);
+        this.client = new ClientWrapper(opsWorksCmClientclient, request.getDesiredResourceState(), request.getPreviousResourceState(), proxy, log);
 
-        logger.log("Calling Describe Servers with no ServerName");
+        log.info("Calling Describe Servers with no ServerName");
 
         DescribeServersResponse result = client.describeAllServers();
         if (result == null || result.servers() == null) {
-            logger.log("Describe result is Null. Retrying request.");
+            log.info("Describe result is Null. Retrying request.");
             return ProgressEvent.defaultInProgressHandler(callbackContext, NO_CALLBACK_DELAY, request.getDesiredResourceState());
         }
 

aws-opsworkscm-server/src/main/java/software/amazon/opsworkscm/server/ReadHandler.java

@@ -23,15 +23,15 @@ public ProgressEvent<ResourceModel, CallbackContext> handleRequest(
         final String serverName = model.getServerName();
         callbackContext.incrementRetryTimes();
 
-        logger.log(String.format("Calling Describe Servers for ServerName %s", serverName));
+        log.info(String.format("Calling Describe Servers for ServerName %s", serverName));
 
         try {
             result = client.describeServer();
             Server server = result.servers().get(0);
             addDescribeServerResponseAttributes(server);
             return ProgressEvent.defaultSuccessHandler(model);
         } catch (final software.amazon.awssdk.services.opsworkscm.model.ResourceNotFoundException e) {
-            logger.log(String.format("Server %s was not found.", serverName));
+            log.error(String.format("Server %s was not found.", serverName), e);
             throw new ResourceNotFoundException(String.format("Server %s was not found.", serverName), e.getMessage());
         }
     }

aws-opsworkscm-server/src/main/java/software/amazon/opsworkscm/server/UpdateHandler.java

@@ -29,13 +29,13 @@ public ProgressEvent<ResourceModel, CallbackContext> handleRequest(
             }
             return ProgressEvent.defaultSuccessHandler(model);
         } catch (ResourceNotFoundException e) {
-            logger.log(String.format("ResourceNotFoundException during update of server %s, with message %s", model.getServerName(), e.getMessage()));
+            log.error(String.format("ResourceNotFoundException during update of server %s, with message %s", model.getServerName(), e.getMessage()), e);
             return ProgressEvent.defaultFailureHandler(e, HandlerErrorCode.NotFound);
         } catch (InvalidStateException e) {
-            logger.log(String.format("InvalidStateException during update of server %s, with message %s", model.getServerName(), e.getMessage()));
+            log.error(String.format("InvalidStateException during update of server %s, with message %s", model.getServerName(), e.getMessage()), e);
             return ProgressEvent.defaultFailureHandler(e, HandlerErrorCode.NotUpdatable);
         } catch (ValidationException e) {
-            logger.log(String.format("ValidationException during update of server %s, with message %s", model.getServerName(), e.getMessage()));
+            log.error(String.format("ValidationException during update of server %s, with message %s", model.getServerName(), e.getMessage()), e);
             return ProgressEvent.defaultFailureHandler(e, HandlerErrorCode.InvalidRequest);
         }
     }

aws-opsworkscm-server/src/main/java/software/amazon/opsworkscm/server/utils/LoggerWrapper.java

@@ -0,0 +1,38 @@
+package software.amazon.opsworkscm.server.utils;
+
+import software.amazon.cloudformation.proxy.Logger;
+
+public class LoggerWrapper {
+
+    Logger logger;
+
+    private static final String infoPrefix = "[INFO] ";
+    private static final String errorPrefix = "[ERROR] ";
+
+    public LoggerWrapper(Logger logger) {
+        this.logger = logger;
+    }
+
+    public void log(final String message) {
+        info(message);
+    }
+
+    public void info(final String message) {
+        logger.log(infoPrefix + message);
+    }
+
+    public void error(final String message) {
+        logger.log(errorPrefix + message);
+    }
+
+    public void error(final String message, final Exception e) {
+        StringBuilder sb = new StringBuilder();
+        sb.append(errorPrefix).append(message).append('\n');
+        sb.append(e.toString()).append('\n');
+        for (StackTraceElement stackTraceElement : e.getStackTrace()) {
+            sb.append('\t').append("at ").append(stackTraceElement.toString()).append('\n');
+        }
+        logger.log(sb.toString());
+    }
+
+}

aws-opsworkscm-server/templates/opsworkscm-server.yaml

@@ -0,0 +1,15 @@
+AWSTemplateFormatVersion: '2010-09-09'
+Resources:
+  MyChefServer:
+    Type: AWS::OpsWorksCM::Server
+    Properties:
+      BackupRetentionCount: 12
+      DisableAutomatedBackup: False
+      Engine: 'ChefAutomate'
+      EngineVersion: '2'
+      EngineModel: 'Single'
+      InstanceProfileArn: "arn:aws:iam::<ACCOUNT_ID>:instance-profile/opsworks-cm-ec2-role"
+      InstanceType: 'm4.xlarge'
+      PreferredBackupWindow: '08:00'
+      PreferredMaintenanceWindow: 'Fri:08:00'
+      ServiceRoleArn: "arn:aws:iam::<ACCOUNT_ID>:role/opsworks-cm-service-role"