AWS plugin stopped processing messages

[akrus]

Hello!

Plugin just stopped working, I can see the following in the logs:

2017-09-29T09:25:13.256Z ERROR [CloudTrailSubscriber] Could not read messages from SQS. This is most likely a misconfiguration of the plugin. Going into sleep loop and retrying.
java.lang.RuntimeException: Could not parse SNS notification: {
  "Type" : "Notification",
  "MessageId" : "5b0a73e6-a4f8-11e7-8dfb-8f76310a10a8",
  "TopicArn" : "arn:aws:sns:eu-west-1:123456789012:cloudtrail-log-write",
  "Subject" : "[AWS Config:eu-west-1] AWS::RDS::DBSnapshot rds:instance-2017-09-03-23-11 Dele...",
  "Message" : "{\"configurationItemDiff\":{\"changedProperties\":{\"Relationships.0\":{\"previousValue\":{\"resourceId\":\"vpc-12345678\",\"resourceName\":null,\"resourceType\":\"AWS::EC2::VPC\",\"name\":\"Is associated with Vpc\"},\"updatedValue\":null,\"changeType\":\"DELETE\"},\"SupplementaryConfiguration.Tags\":{\"previousValue\":[],\"updatedValue\":null,\"changeType\":\"DELETE\"},\"SupplementaryConfiguration.DBSnapshotAttributes\":{\"previousValue\":[{\"attributeName\":\"restore\",\"attributeValues\":[]}],\"updatedValue\":null,\"changeType\":\"DELETE\"},\"Configuration\":{\"previousValue\":{\"dBSnapshotIdentifier\":\"rds:instance-2017-09-03-23-11\",\"dBInstanceIdentifier\":\"instance\",\"snapshotCreateTime\":\"2017-09-03T23:11:38.218Z\",\"engine\":\"mysql\",\"allocatedStorage\":200,\"status\":\"available\",\"port\":3306,\"availabilityZone\":\"eu-west-1b\",\"vpcId\":\"vpc-12345678\",\"instanceCreateTime\":\"2015-04-09T07:08:07.476Z\",\"masterUsername\":\"root\",\"engineVersion\":\"5.6.34\",\"licenseModel\":\"general-public-license\",\"snapshotType\":\"automated\",\"iops\":null,\"optionGroupName\":\"default:mysql-5-6\",\"percentProgress\":100,\"sourceRegion\":null,\"sourceDBSnapshotIdentifier\":null,\"storageType\":\"standard\",\"tdeCredentialArn\":null,\"encrypted\":false,\"kmsKeyId\":null,\"dBSnapshotArn\":\"arn:aws:rds:eu-west-1:123456789012:snapshot:rds:instance-2017-09-03-23-11\",\"timezone\":null,\"iAMDatabaseAuthenticationEnabled\":false},\"updatedValue\":null,\"changeType\":\"DELETE\"}},\"changeType\":\"DELETE\"},\"configurationItem\":{\"relatedEvents\":[],\"relationships\":[],\"configuration\":null,\"supplementaryConfiguration\":{},\"tags\":{},\"configurationItemVersion\":\"1.2\",\"configurationItemCaptureTime\":\"2017-09-28T19:54:47.815Z\",\"configurationStateId\":1234567890123,\"awsAccountId\":\"123456789012\",\"configurationItemStatus\":\"ResourceDeleted\",\"resourceType\":\"AWS::RDS::DBSnapshot\",\"resourceId\":\"rds:instance-2017-09-03-23-11\",\"resourceName\":\"rds:instance-2017-09-03-23-11\",\"ARN\":\"arn:aws:rds:eu-west-1:123456789012:snapshot:rds:instance-2017-09-03-23-11\",\"awsRegion\":\"eu-west-1\",\"availabilityZone\":null,\"configurationStateMd5Hash\":\"b026324c6904b2a9cb4b88d6d61c81d1\",\"resourceCreationTime\":null},\"notificationCreationTime\":\"2017-09-28T19:54:48.311Z\",\"messageType\":\"ConfigurationItemChangeNotification\",\"recordVersion\":\"1.2\"}",
  "Timestamp" : "2017-09-28T19:54:58.543Z",
  "SignatureVersion" : "1",
  "Signature" : "...",
  "SigningCertURL" : "https://sns.eu-west-1.amazonaws.com/SimpleNotificationService-....pem",
  "UnsubscribeURL" : "https://sns.eu-west-1.amazonaws.com/?Action=Unsubscribe&SubscriptionArn=arn:aws:sns:eu-west-1:123456789012:cloudtrail-log-write:5b0a73e6-a4f8-11e7-8dfb-8f76310a10a8"
}
        at org.graylog.aws.inputs.cloudtrail.notifications.CloudtrailSNSNotificationParser.parse(CloudtrailSNSNotificationParser.java:36) ~[graylog-plugin-aws-2.3.1.jar:?]
        at org.graylog.aws.inputs.cloudtrail.notifications.CloudtrailSQSClient.getNotifications(CloudtrailSQSClient.java:51) ~[graylog-plugin-aws-2.3.1.jar:?]
        at org.graylog.aws.inputs.cloudtrail.CloudTrailSubscriber.run(CloudTrailSubscriber.java:86) [graylog-plugin-aws-2.3.1.jar:?]
Caused by: com.fasterxml.jackson.databind.exc.UnrecognizedPropertyException: Unrecognized field "configurationItemDiff" (class org.graylog.aws.inputs.cloudtrail.json.CloudtrailWriteNotification), not marked as ignorable (2 known properties: "s3ObjectKey", "s3Bucket"])
 at [Source: {"configurationItemDiff":{"changedProperties":{"Relationships.0":{"previousValue":{"resourceId":"vpc-12345678","resourceName":null,"resourceType":"AWS::EC2::VPC","name":"Is associated with Vpc"},"updatedValue":null,"changeType":"DELETE"},"SupplementaryConfiguration.Tags":{"previousValue":[],"updatedValue":null,"changeType":"DELETE"},"SupplementaryConfiguration.DBSnapshotAttributes":{"previousValue":[{"attributeName":"restore","attributeValues":[]}],"updatedValue":null,"changeType":"DELETE"},"Configuration":{"previousValue":{"dBSnapshotIdentifier":"rds:instance-2017-09-03-23-11","dBInstanceIdentifier":"instance","snapshotCreateTime":"2017-09-03T23:11:38.218Z","engine":"mysql","allocatedStorage":200,"status":"available","port":3306,"availabilityZone":"eu-west-1b","vpcId":"vpc-12345678","instanceCreateTime":"2015-04-09T07:08:07.476Z","masterUsername":"root","engineVersion":"5.6.34","licenseModel":"general-public-license","snapshotType":"automated","iops":null,"optionGroupName":"default:mysql-5-6","percentProgress":100,"sourceRegion":null,"sourceDBSnapshotIdentifier":null,"storageType":"standard","tdeCredentialArn":null,"encrypted":false,"kmsKeyId":null,"dBSnapshotArn":"arn:aws:rds:eu-west-1:123456789012:snapshot:rds:instance-2017-09-03-23-11","timezone":null,"iAMDatabaseAuthenticationEnabled":false},"updatedValue":null,"changeType":"DELETE"}},"changeType":"DELETE"},"configurationItem":{"relatedEvents":[],"relationships":[],"configuration":null,"supplementaryConfiguration":{},"tags":{},"configurationItemVersion":"1.2","configurationItemCaptureTime":"2017-09-28T19:54:47.815Z","configurationStateId":1234567890123,"awsAccountId":"123456789012","configurationItemStatus":"ResourceDeleted","resourceType":"AWS::RDS::DBSnapshot","resourceId":"rds:instance-2017-09-03-23-11","resourceName":"rds:instance-2017-09-03-23-11","ARN":"arn:aws:rds:eu-west-1:123456789012:snapshot:rds:instance-2017-09-03-23-11","awsRegion":"eu-west-1","availabilityZone":null,"configurationStateMd5Hash":"b026324c6904b2a9cb4b88d6d61c81d1","resourceCreationTime":null},"notificationCreationTime":"2017-09-28T19:54:48.311Z","messageType":"ConfigurationItemChangeNotification","recordVersion":"1.2"}; line: 1, column: 27] (through reference chain: org.graylog.aws.inputs.cloudtrail.json.CloudtrailWriteNotification["configurationItemDiff"])
        at com.fasterxml.jackson.databind.exc.UnrecognizedPropertyException.from(UnrecognizedPropertyException.java:62) ~[graylog.jar:?]
        at com.fasterxml.jackson.databind.DeserializationContext.handleUnknownProperty(DeserializationContext.java:834) ~[graylog.jar:?]
        at com.fasterxml.jackson.databind.deser.std.StdDeserializer.handleUnknownProperty(StdDeserializer.java:1093) ~[graylog.jar:?]
        at com.fasterxml.jackson.databind.deser.BeanDeserializerBase.handleUnknownProperty(BeanDeserializerBase.java:1478) ~[graylog.jar:?]
        at com.fasterxml.jackson.databind.deser.BeanDeserializerBase.handleUnknownVanilla(BeanDeserializerBase.java:1456) ~[graylog.jar:?]
        at com.fasterxml.jackson.databind.deser.BeanDeserializer.vanillaDeserialize(BeanDeserializer.java:282) ~[graylog.jar:?]
        at com.fasterxml.jackson.databind.deser.BeanDeserializer.deserialize(BeanDeserializer.java:140) ~[graylog.jar:?]
        at com.fasterxml.jackson.databind.ObjectMapper._readMapAndClose(ObjectMapper.java:3814) ~[graylog.jar:?]
        at com.fasterxml.jackson.databind.ObjectMapper.readValue(ObjectMapper.java:2858) ~[graylog.jar:?]
        at org.graylog.aws.inputs.cloudtrail.notifications.CloudtrailSNSNotificationParser.parse(CloudtrailSNSNotificationParser.java:30) ~[?:?]
        ... 2 more

Configuration looks fine, seems it just cannot parse the message.

[akrus]

Any ETA to merge and release?

[kroepke]

@akrus This will be released alongside Graylog 2.4 in which we start bundling this plugin by default.
We won't be releasing individual versions ourselves.

Currently we are working towards a first public beta release for 2.4 which will come as soon as all features are merged.

[akrus]

I'm afraid the problem is still not fixed:

2017-11-02T14:01:12.600Z ERROR [CloudTrailSubscriber] Could not read messages from SQS. This is most likely a misconfiguration of the plugin. Going into sleep loop and retrying.
java.lang.RuntimeException: Could not parse SNS notification: {
  "Type" : "Notification",
  "MessageId" : "68f14be8-bfd7-11e7-9c23-7fac08726775",
  "TopicArn" : "arn:aws:sns:us-east-1:123456789012:cloudtrail-log-write",
  "Subject" : "[AWS Config:us-east-1] Configuration History Delivery Completed for Account 123456789012",
  "Message" : "{\"s3ObjectKey\":\"AWSLogs/123456789012/Config/us-east-1/2017/10/29/ConfigHistory/123456789012_Config_us-east-1_ConfigHistory_AWS::RDS::DBInstance_20171029T120004Z_20171029T120004Z_1.json.gz\",\"s3Bucket\":\"bucket-name\",\"notificationCreationTime\":\"2017-10-29T17:25:23.315Z\",\"messageType\":\"ConfigurationHistoryDeliveryCompleted\",\"recordVersion\":\"1.1\"}",
  "Timestamp" : "2017-10-29T17:25:23.373Z",
  "SignatureVersion" : "1",
  "Signature" : "...",
  "SigningCertURL" : "https://sns.us-east-1.amazonaws.com/SimpleNotificationService-xxx.pem",
  "UnsubscribeURL" : "https://sns.us-east-1.amazonaws.com/?Action=Unsubscribe&SubscriptionArn=arn:aws:sns:us-east-1:123456789012:cloudtrail-log-write:87392f80-bfd7-11e7-bcc2-67cebf3126ff"
}
        at org.graylog.aws.inputs.cloudtrail.notifications.CloudtrailSNSNotificationParser.parse(CloudtrailSNSNotificationParser.java:43) ~[graylog-plugin-aws-2.4.0-beta.1.jar:?]
        at org.graylog.aws.inputs.cloudtrail.notifications.CloudtrailSQSClient.getNotifications(CloudtrailSQSClient.java:54) ~[graylog-plugin-aws-2.4.0-beta.1.jar:?]
        at org.graylog.aws.inputs.cloudtrail.CloudTrailSubscriber.run(CloudTrailSubscriber.java:88) [graylog-plugin-aws-2.4.0-beta.1.jar:?]
Caused by: com.fasterxml.jackson.databind.JsonMappingException: Can not deserialize instance of java.util.ArrayList out of VALUE_STRING token
 at [Source: {"s3ObjectKey":"AWSLogs/123456789012/Config/us-east-1/2017/10/29/ConfigHistory/123456789012_Config_us-east-1_ConfigHistory_AWS::RDS::DBInstance_20171029T120004Z_20171029T120004Z_1.json.gz","s3Bucket":"bucket-name","notificationCreationTime":"2017-10-29T17:25:23.315Z","messageType":"ConfigurationHistoryDeliveryCompleted","recordVersion":"1.1"}; line: 1, column: 16] (through reference chain: org.graylog.aws.inputs.cloudtrail.json.CloudtrailWriteNotification["s3ObjectKey"])
        at com.fasterxml.jackson.databind.JsonMappingException.from(JsonMappingException.java:270) ~[graylog.jar:?]
        at com.fasterxml.jackson.databind.DeserializationContext.reportMappingException(DeserializationContext.java:1234) ~[graylog.jar:?]
        at com.fasterxml.jackson.databind.DeserializationContext.handleUnexpectedToken(DeserializationContext.java:1122) ~[graylog.jar:?]
        at com.fasterxml.jackson.databind.DeserializationContext.handleUnexpectedToken(DeserializationContext.java:1075) ~[graylog.jar:?]
        at com.fasterxml.jackson.databind.deser.std.StringCollectionDeserializer.handleNonArray(StringCollectionDeserializer.java:260) ~[graylog.jar:?]
        at com.fasterxml.jackson.databind.deser.std.StringCollectionDeserializer.deserialize(StringCollectionDeserializer.java:187) ~[graylog.jar:?]
        at com.fasterxml.jackson.databind.deser.std.StringCollectionDeserializer.deserialize(StringCollectionDeserializer.java:177) ~[graylog.jar:?]
        at com.fasterxml.jackson.databind.deser.std.StringCollectionDeserializer.deserialize(StringCollectionDeserializer.java:20) ~[graylog.jar:?]
        at com.fasterxml.jackson.databind.deser.SettableBeanProperty.deserialize(SettableBeanProperty.java:504) ~[graylog.jar:?]
        at com.fasterxml.jackson.databind.deser.impl.FieldProperty.deserializeAndSet(FieldProperty.java:111) ~[graylog.jar:?]
        at com.fasterxml.jackson.databind.deser.BeanDeserializer.vanillaDeserialize(BeanDeserializer.java:276) ~[graylog.jar:?]
        at com.fasterxml.jackson.databind.deser.BeanDeserializer.deserialize(BeanDeserializer.java:140) ~[graylog.jar:?]
        at com.fasterxml.jackson.databind.ObjectMapper._readMapAndClose(ObjectMapper.java:3814) ~[graylog.jar:?]
        at com.fasterxml.jackson.databind.ObjectMapper.readValue(ObjectMapper.java:2858) ~[graylog.jar:?]
        at org.graylog.aws.inputs.cloudtrail.notifications.CloudtrailSNSNotificationParser.parse(CloudtrailSNSNotificationParser.java:30) ~[?:?]
        ... 2 more

[bernd]

@akrus Thanks for the feedback. I will reopen the issue. /cc @joschi

[joschi]

@bernd @akrus While looking similar, this is a completely different problem.
The CloudtrailWriteNotification class expects the "s3ObjectKey" key in the JSON payload to be a string array but it was a literal string in the given example.

graylog-plugin-aws/src/main/java/org/graylog/aws/inputs/cloudtrail/json/CloudtrailWriteNotification.java

Lines 10 to 11 in afa04c9

	@JsonProperty("s3ObjectKey")
	public List<String> s3ObjectKey;

We'll have to check what the canonical response format for this kind of payload is.

[radykal-com]

As documented here: http://docs.aws.amazon.com/awscloudtrail/latest/userguide/configure-cloudtrail-to-send-notifications.html it should be always a string array

@akrus are these messages coming from cloudtrail notifications or is the same topic receiving notifications from other services? Seems the 2 notifications in this issue are related to AWS Config service http://docs.aws.amazon.com/es_es/config/latest/developerguide/how-does-config-work.html

[akrus]

Yes, all the messages are coming from Cloudtrail. We have RDS logs and AWS config writing there (and added SES recently, but this error appeared before SES started to send logs).

[akrus]

@joschi, should I try contacting Amazon on this case? Or is it possible to have a workaround for this?

[kroepke]

@akrus I'm checking this against the official SDK now. sorry for the inconvenience!

[kroepke]

@akrus Can you confirm that you are sending AWS Config via cloudtrail as described here: http://docs.aws.amazon.com/config/latest/developerguide/log-api-calls.html ?

It looks like the SNS notification generated in that case is different to other cloudtrail producers. If that's so, that does look like a bug with the service itself to me.

The AWS SDKs I could find all assume (wrongly) that the s3ObjectKey is a string and not a list (e.g. https://github.com/aws/aws-cloudtrail-processing-library/blob/master/src/main/java/com/amazonaws/services/cloudtrail/processinglibrary/model/CloudTrailLog.java#L30). However in a standard cloudtrail setup I could never get it to send a single value, only a list with a single value.
AFAICS AWS Config can generate two different log streams, one directly interfacing with SQS and one implicitly via CloudTrail.

[kroepke]

Another update: After spending quality time in the debugger, the AWS cloudtrail SDK does indeed expect and parse only List<String> for the object keys, but does so manually, which is why I've missed it earlier.

Which means that those notifications @akrus has in the cloudtrail queue are in fact not cloudtrail logs, but AWS Config events, which have a different format.
The underlying issue is that SNS message payloads typically have no identifier, so you cannot know for sure what the payload actually is.

Long story short: The cloudtrail plugin is correct, the docs are correct, the SDK code is misleading, but correct, it is simply that the AWS Config docs are confusing. To request support for native AWS Config logs, please open a new feature request ticket.

Thanks,
Kay