2

Problem

In one sentence

SNS Topic sending too many notifications to HTTPs subscriber.

More detailed

I have enabled events in one of my S3 buckets, and I have subscribed one of my applications to its SNS Topic via HTTPS. Everything was working fine until today, when my app started taking too long to respond.

After restarting the EC2 instance and noticing that the problem was still there, I SSH'd to the EC2 instance and realized that I was connected almost instantly, commands were being executed with no noticeable delays. So I knew the problem was not with the instance network.

I went to check the apache logs and that's when I noticed hundreds (perhaps thousands) of POST requests per second. See a snippet of the logs below.

Question(s)

  • Is there a way to see whether it is S3 that is sending all these notifications events to SNS?

  • Also, could this be that S3 is receiving that many uploads per second, is that even possible?

  • Lastly, what can I do to stop this other than simply unsubscribing from the topic?

Apache logs:

72.21.217.87 - - [02/Mar/2017:15:33:52 -0500] "POST /notifications HTTP/1.1" 500 619 "-" "Amazon Simple Notification Service Agent"
72.21.217.133 - - [02/Mar/2017:15:33:52 -0500] "POST /notifications HTTP/1.1" 500 6404 "-" "Amazon Simple Notification Service Agent"
72.21.217.141 - - [02/Mar/2017:15:33:52 -0500] "POST /notifications HTTP/1.1" 500 619 "-" "Amazon Simple Notification Service Agent"
72.21.217.139 - - [02/Mar/2017:15:33:52 -0500] "POST /notifications HTTP/1.1" 500 619 "-" "Amazon Simple Notification Service Agent"
72.21.217.75 - - [02/Mar/2017:15:33:51 -0500] "POST /notifications HTTP/1.1" 500 619 "-" "Amazon Simple Notification Service Agent"
72.21.217.182 - - [02/Mar/2017:15:33:52 -0500] "POST /notifications HTTP/1.1" 500 619 "-" "Amazon Simple Notification Service Agent"
72.21.217.137 - - [02/Mar/2017:15:33:52 -0500] "POST /notifications HTTP/1.1" 500 619 "-" "Amazon Simple Notification Service Agent"
72.21.217.157 - - [02/Mar/2017:15:33:52 -0500] "POST /notifications HTTP/1.1" 500 619 "-" "Amazon Simple Notification Service Agent"
72.21.217.161 - - [02/Mar/2017:15:33:52 -0500] "POST /notifications HTTP/1.1" 500 619 "-" "Amazon Simple Notification Service Agent"
72.21.217.139 - - [02/Mar/2017:15:33:52 -0500] "POST /notifications HTTP/1.1" 500 619 "-" "Amazon Simple Notification Service Agent"
72.21.217.156 - - [02/Mar/2017:15:33:52 -0500] "POST /notifications HTTP/1.1" 500 6404 "-" "Amazon Simple Notification Service Agent"
72.21.217.70 - - [02/Mar/2017:15:33:52 -0500] "POST /notifications HTTP/1.1" 500 619 "-" "Amazon Simple Notification Service Agent"
72.21.217.135 - - [02/Mar/2017:15:33:52 -0500] "POST /notifications HTTP/1.1" 500 619 "-" "Amazon Simple Notification Service Agent"
72.21.217.152 - - [02/Mar/2017:15:33:52 -0500] "POST /notifications HTTP/1.1" 500 619 "-" "Amazon Simple Notification Service Agent"
72.21.217.113 - - [02/Mar/2017:15:33:52 -0500] "POST /notifications HTTP/1.1" 500 619 "-" "Amazon Simple Notification Service Agent"
72.21.217.83 - - [02/Mar/2017:15:33:52 -0500] "POST /notifications HTTP/1.1" 500 619 "-" "Amazon Simple Notification Service Agent"
72.21.217.158 - - [02/Mar/2017:15:33:52 -0500] "POST /notifications HTTP/1.1" 500 619 "-" "Amazon Simple Notification Service Agent"
72.21.217.129 - - [02/Mar/2017:15:33:52 -0500] "POST /notifications HTTP/1.1" 500 619 "-" "Amazon Simple Notification Service Agent"
72.21.217.75 - - [02/Mar/2017:15:33:52 -0500] "POST /notifications HTTP/1.1" 500 619 "-" "Amazon Simple Notification Service Agent"
72.21.217.156 - - [02/Mar/2017:15:33:52 -0500] "POST /notifications HTTP/1.1" 500 619 "-" "Amazon Simple Notification Service Agent"
72.21.217.64 - - [02/Mar/2017:15:33:52 -0500] "POST /notifications HTTP/1.1" 500 619 "-" "Amazon Simple Notification Service Agent"
72.21.217.134 - - [02/Mar/2017:15:33:52 -0500] "POST /notifications HTTP/1.1" 500 619 "-" "Amazon Simple Notification Service Agent"
72.21.217.130 - - [02/Mar/2017:15:33:52 -0500] "POST /notifications HTTP/1.1" 500 619 "-" "Amazon Simple Notification Service Agent"
72.21.217.86 - - [02/Mar/2017:15:33:52 -0500] "POST /notifications HTTP/1.1" 500 619 "-" "Amazon Simple Notification Service Agent"
72.21.217.167 - - [02/Mar/2017:15:33:52 -0500] "POST /notifications HTTP/1.1" 500 619 "-" "Amazon Simple Notification Service Agent"
72.21.217.135 - - [02/Mar/2017:15:33:52 -0500] "POST /notifications HTTP/1.1" 500 619 "-" "Amazon Simple Notification Service Agent"
72.21.217.169 - - [02/Mar/2017:15:33:52 -0500] "POST /notifications HTTP/1.1" 500 619 "-" "Amazon Simple Notification Service Agent"
72.21.217.76 - - [02/Mar/2017:15:33:52 -0500] "POST /notifications HTTP/1.1" 500 619 "-" "Amazon Simple Notification Service Agent"
72.21.217.75 - - [02/Mar/2017:15:33:52 -0500] "POST /notifications HTTP/1.1" 500 6404 "-" "Amazon Simple Notification Service Agent"
72.21.217.79 - - [02/Mar/2017:15:33:52 -0500] "POST /notifications HTTP/1.1" 500 619 "-" "Amazon Simple Notification Service Agent"
72.21.217.180 - - [02/Mar/2017:15:33:52 -0500] "POST /notifications HTTP/1.1" 500 619 "-" "Amazon Simple Notification Service Agent"
72.21.217.75 - - [02/Mar/2017:15:33:52 -0500] "POST /notifications HTTP/1.1" 500 619 "-" "Amazon Simple Notification Service Agent"
72.21.217.80 - - [02/Mar/2017:15:33:52 -0500] "POST /notifications HTTP/1.1" 500 619 "-" "Amazon Simple Notification Service Agent"
72.21.217.74 - - [02/Mar/2017:15:33:52 -0500] "POST /notifications HTTP/1.1" 500 6404 "-" "Amazon Simple Notification Service Agent"
72.21.217.137 - - [02/Mar/2017:15:33:52 -0500] "POST /notifications HTTP/1.1" 500 619 "-" "Amazon Simple Notification Service Agent"
72.21.217.155 - - [02/Mar/2017:15:33:52 -0500] "POST /notifications HTTP/1.1" 500 619 "-" "Amazon Simple Notification Service Agent"
72.21.217.87 - - [02/Mar/2017:15:33:52 -0500] "POST /notifications HTTP/1.1" 500 619 "-" "Amazon Simple Notification Service Agent"
72.21.217.152 - - [02/Mar/2017:15:33:52 -0500] "POST /notifications HTTP/1.1" 500 619 "-" "Amazon Simple Notification Service Agent"
72.21.217.130 - - [02/Mar/2017:15:33:52 -0500] "POST /notifications HTTP/1.1" 500 619 "-" "Amazon Simple Notification Service Agent"
72.21.217.161 - - [02/Mar/2017:15:33:52 -0500] "POST /notifications HTTP/1.1" 500 619 "-" "Amazon Simple Notification Service Agent"
72.21.217.74 - - [02/Mar/2017:15:33:52 -0500] "POST /notifications HTTP/1.1" 500 619 "-" "Amazon Simple Notification Service Agent"

[Update]

After looking closer at the logs, I see that my app is responding with 500. At first I thought it was Apache2 since it was receiving so many requests. I guess SNS continues to re-deliver messages (indefinitely?) when it doesn't receive a success message.

[Update 2]

I was able to get what notification was being sent, and it's a "ObjectRemoved:Delete" for a file that was deleted. The file no longer exists in the bucket.

I subscribed via email as suggested by @EEAA for less than 15 seconds, and have received 252 emails and counting :[ for the same notification.

[Update 3]

Checked the delivery policy on the SNS Topic, and confirmed that retries is set to 3!

enter image description here

Note: As of now, I've received almost 900 notifications from S3. I've also noticed that the x-amz-request-id and x-amz-id-2 is always different, does this mean something?

Francisco C.
  • 141
  • 5
  • Some are probably retries, given the 500s. I'd check your S3, though - maybe someone's got an API key and is popping lots of files there on your dime. – ceejayoz Mar 02 '17 at 21:10
  • Thanks for your comment! I was able to view what the notification that SNS is sending, and it was a file that I deleted. So I don't think these notifications are by someone else actions. – Francisco C. Mar 02 '17 at 22:49
  • 1
    *does this mean something?* Check your bucket logs. It *should* mean that these aren't entirely duplicates. I don't know if lifecycle policies trigger events, but that seems like one possibility. – Michael - sqlbot Mar 03 '17 at 00:30

1 Answers1

3

A few points:

  1. Those IPs are all assigned to Amazon, so we know the traffic is coming from Amazon's network.
  2. Your server is responding with a 500 error code. Is that intentional?
  3. You should be able to do a packet capture to see the POST data.
  4. If you're unable to perform a packet capture, you can also subscribe to the SNS topic via email for a very short period and details of the SNS message will be sent to your email.
EEAA
  • 108,414
  • 18
  • 172
  • 242
  • 1
    I subscribed via email as you suggested, but I left it for too long (~15 seconds), I'm still getting emails 1200 emails later. – Francisco C. Mar 02 '17 at 23:06
  • 2
    Haha, RIP your inbox. :) Were you able to get the information you needed though? – EEAA Mar 03 '17 at 00:08
  • Lol - and they are still coming in at a slower rate, about 10 emails a minute (perhaps Gmail throttles it). I was able to notice that although the notifications are about the same file/object, the ids in the notifications are different, which implies that they are not retries but new messages. – Francisco C. Mar 03 '17 at 00:41