what happens when kinesis is throttled?

[mattford63]

Hi again,

:-)

What's the behaviour of the agent when say for example Kinesis is throttled? Do logs get dropped or does the tailing stay at the last sent log or something else?

I've noticed memory consumption increase as throttling occurs.

In our testing we configured log generation to be much greater than what a kinesis stream could handle. When throttling turned off (i.e, kinesis allowed traffic again) we saw very high short bursts of CPU utilisation until throttling started again. What could be done to limit this?

[mattford63]

I've looked into this some more. I see this pattern over and over again: each record of the record set is tried even though kinesis reports it's throttled. When record 500 fails the record set is requeued until eventually the kinesis throttling is removed and then the recordset uploads successfully.

The code has it's own throttling but I see no sign of it actually being used. Is this expected behaviour?

2016-05-04 11:38:18.515+0000 ip-10-30-152-18 (sender-14) com.amazon.kinesis.streaming.agent.tailing.AsyncPublisher [DEBUG] AsyncPublisher[kinesis:dev-amazon-agent-kinesis-AmazonAgentKinesisStream-2EHGD272A811:/var/log/canary/ingress/ingress.log]:RecordBuffer(id=148,records=500,bytes=354226)

** Send PARTIAL_SUCCESS: Sent: 0, Failed: 500 **

2016-05-04 11:38:18.515+0000 ip-10-30-152-18 (sender-14) com.amazon.kinesis.streaming.agent.tailing.AsyncPublisher [TRACE] AsyncPublisher[kinesis:dev-amazon-agent-kinesis-AmazonAgentKinesisStream-2EHGD272A811:/var/log/canary/ingress/ingress.log]:RecordBuffer(id=148,records=500,bytes=354226)

** Buffer Queued for Retry **

2016-05-04 11:38:18.515+0000 ip-10-30-152-18 (sender-14) com.amazon.kinesis.streaming.agent.tailing.AsyncPublisher [TRACE] AsyncPublisher[kinesis:dev-amazon-agent-kinesis-AmazonAgentKinesisStream-2EHGD272A811:/var/log/canary/ingress/ingress.log]:RecordBuffer(id=148,records=500,bytes=354226)

** Send Completed **

2016-05-04 11:38:18.958+0000 ip-10-30-152-18 (AsyncPublisher[kinesis:dev-amazon-agent-kinesis-AmazonAgentKinesisStream-2EHGD272A811:/var/log/canary/ingress/ingress.log]) com.amazon.kinesis.streaming.agent.tailing.AsyncPublisher [TRACE] AsyncPublisher[kinesis:dev-amazon-agent-kinesis-AmazonAgentKinesisStream-2EHGD272A811:/var/log/canary/ingress/ingress.log]:RecordBuffer(id=148,records=500,bytes=354226)

** Send Scheduled **

2016-05-04 11:38:18.958+0000 ip-10-30-152-18 (sender-3) com.amazon.kinesis.streaming.agent.tailing.KinesisSender [TRACE] kinesis:dev-amazon-agent-kinesis-AmazonAgentKinesisStream-2EHGD272A811:/var/log/canary/ingress/ingress.log: Sending buffer RecordBuffer(id=148,records=500,bytes=354226) to kinesis stream dev-amazon-agent-kinesis-AmazonAgentKinesisStream-2EHGD272A811...
2016-05-04 11:38:19.009+0000 ip-10-30-152-18 (sender-3) com.amazon.kinesis.streaming.agent.tailing.KinesisSender [TRACE] kinesis:dev-amazon-agent-kinesis-AmazonAgentKinesisStream-2EHGD272A811:/var/log/canary/ingress/ingress.log:RecordBuffer(id=148,records=500,bytes=354226) Record 0 returned error code ProvisionedThroughputExceededException: Rate exceeded for shard shardId-000000000000 in stream dev-amazon-agent-kinesis-AmazonAgentKinesisStream-2EHGD272A811 under account 680012563410.
2016-05-04 11:38:19.009+0000 ip-10-30-152-18 (sender-3) com.amazon.kinesis.streaming.agent.tailing.KinesisSender [TRACE] kinesis:dev-amazon-agent-kinesis-AmazonAgentKinesisStr
eam-2EHGD272A811:/var/log/canary/ingress/ingress.log:RecordBuffer(id=148,records=500,bytes=354226) Record 1 returned error code ProvisionedThroughputExceededException: Rate exceeded for shard shardId-000000000000 in stream dev-amazon-agent-kinesis-AmazonAgentKinesisStream-2EHGD272A811 under account 680012563410.
.....
.....
.....
2016-05-04 11:38:21.274+0000 ip-10-30-152-18 (sender-4) com.amazon.kinesis.streaming.agent.tailing.KinesisSender [TRACE] kinesis:dev-amazon-agent-kinesis-AmazonAgentKinesisStream-2EHGD272A811:/var/log/canary/in
gress/ingress.log:RecordBuffer(id=148,records=500,bytes=354226) Record 498 returned error code ProvisionedThroughputExceededException: Rate exceeded for shard shardId-000000000000 in stream dev-amazon-agent-kinesis-AmazonAgentKinesisStream-2EHGD272A811 under account 680012563410.
2016-05-04 11:38:21.274+0000 ip-10-30-152-18 (sender-4) com.amazon.kinesis.streaming.agent.tailing.KinesisSender [TRACE] kinesis:dev-amazon-agent-kinesis-AmazonAgentKinesisStream-2EHGD272A811:/var/log/canary/in
gress/ingress.log:RecordBuffer(id=148,records=500,bytes=354226) Record 499 returned error code ProvisionedThroughputExceededException: Rate exceeded for shard shardId-000000000000 in stream dev-amazon-agent-kinesis-AmazonAgentKinesisStream-2EHGD272A811 under account 680012563410.
2016-05-04 11:38:21.274+0000 ip-10-30-152-18 (sender-4) com.amazon.kinesis.streaming.agent.tailing.KinesisSender [DEBUG] kinesis:dev-amazon-agent-kinesis-AmazonAgentKinesisStream-2EHGD272A811:/var/log/canary/in
gress/ingress.log:RecordBuffer(id=148,records=500,bytes=354226) Records sent to kinesis stream dev-amazon-agent-kinesis-AmazonAgentKinesisStream-2EHGD272A811: 0. Failed records: 500
2016-05-04 11:38:21.274+0000 ip-10-30-152-18 (sender-4) com.amazon.kinesis.streaming.agent.tailing.KinesisSender [DEBUG] kinesis:dev-amazon-agent-kinesis-AmazonAgentKinesisStream-2EHGD272A811:/var/log/canary/in
gress/ingress.log:RecordBuffer(id=148,records=500,bytes=354226) Errors from kinesis stream dev-amazon-agent-kinesis-AmazonAgentKinesisStream-2EHGD272A811: ProvisionedThroughputExceededException: 500
2016-05-04 11:38:21.274+0000 ip-10-30-152-18 (sender-4) com.amazon.kinesis.streaming.agent.tailing.AsyncPublisher [DEBUG] AsyncPublisher[kinesis:dev-amazon-agent-kinesis-AmazonAgentKinesisStream-2EHGD272A811:/v
ar/log/canary/ingress/ingress.log]:RecordBuffer(id=148,records=500,bytes=354226) Send PARTIAL_SUCCESS: Sent: 0, Failed: 500

2016-05-04 11:38:21.274+0000 ip-10-30-152-18 (sender-4) com.amazon.kinesis.streaming.agent.tailing.AsyncPublisher [TRACE] AsyncPublisher[kinesis:dev-amazon-agent-kinesis-AmazonAgentKinesisStream-2EHGD272A811:/var/log/canary/ingress/ingress.log]:RecordBuffer(id=148,records=500,bytes=354226)

** Buffer Queued for Retry **
2016-05-04 11:38:21.274+0000 ip-10-30-152-18 (sender-4) com.amazon.kinesis.streaming.agent.tailing.AsyncPublisher [TRACE] AsyncPublisher[kinesis:dev-amazon-agent-kinesis-AmazonAgentKinesisStream-2EHGD272A811:/v
ar/log/canary/ingress/ingress.log]:RecordBuffer(id=148,records=500,bytes=354226)

** Send Completed **
2016-05-04 11:38:23.961+0000 ip-10-30-152-18 (AsyncPublisher[kinesis:dev-amazon-agent-kinesis-AmazonAgentKinesisStream-2EHGD272A811:/var/log/canary/ingress/ingress.log]) com.amazon.kinesis.streaming.agent.tailing.AsyncPublisher [TRACE] AsyncPublisher[kinesis:dev-amazon-agent-kinesis-AmazonAgentKinesisStream-2EHGD272A811:/var/log/canary/ingress/ingress.log]:RecordBuffer(id=148,records=500,bytes=354226)

** Send Scheduled **
2016-05-04 11:38:23.961+0000 ip-10-30-152-18 (sender-20) com.amazon.kinesis.streaming.agent.tailing.KinesisSender [TRACE] kinesis:dev-amazon-agent-kinesis-AmazonAgentKinesisStream-2EHGD272A811:/var/log/canary/i
ngress/ingress.log: Sending buffer RecordBuffer(id=148,records=500,bytes=354226) to kinesis stream dev-amazon-agent-kinesis-AmazonAgentKinesisStream-2EHGD272A811...
2016-05-04 11:38:24.108+0000 ip-10-30-152-18 (sender-20) com.amazon.kinesis.streaming.agent.tailing.KinesisSender [DEBUG] kinesis:dev-amazon-agent-kinesis-AmazonAgentKinesisStream-2EHGD272A811:/var/log/canary/i
ngress/ingress.log:RecordBuffer(id=148,records=500,bytes=354226) Records sent to kinesis stream dev-amazon-agent-kinesis-AmazonAgentKinesisStream-2EHGD272A811: 500. Failed records: 0
2016-05-04 11:38:24.108+0000 ip-10-30-152-18 (sender-20) com.amazon.kinesis.streaming.agent.tailing.AsyncPublisher [TRACE] AsyncPublisher[kinesis:dev-amazon-agent-kinesis-AmazonAgentKinesisStream-2EHGD272A811:/
var/log/canary/ingress/ingress.log]:RecordBuffer(id=148,records=500,bytes=354226)

** Send SUCCESS **
2016-05-04 11:38:24.108+0000 ip-10-30-152-18 (sender-20) com.amazon.kinesis.streaming.agent.tailing.AsyncPublisher [TRACE] AsyncPublisher[kinesis:dev-amazon-agent-kinesis-AmazonAgentKinesisStream-2EHGD272A811:/
var/log/canary/ingress/ingress.log]:RecordBuffer(id=148,records=500,bytes=354226) Send Completed

[mattford63]

I set flows with this

"flows": [                                                                                                           
      {                                                                                                              
      "filePattern": "/var/log/canary/ingress/ingress.log*",                                                             
      "kinesisStream": "dev-amazon-agent-kinesis-AmazonAgentKinesisStream-2EHGD272A811",                                 
      "retryInitialBackoffMillis": 1000,                                                                              
      "retryMaxBackoffMillis": 60000,

But to no joy. I don't see any throttler logs or throttling :-(

[chaochenq]

Hi,

When throttling happens, it happens to per record rather than the whole batch. Let's say there are 500 records in each putRecordBatch call, and 5 records are throttled, you will get RecordSendError of 5 and ServiceErrors of 0. And the 5 throttled records will be queued for retrying in the next batch. If the whole batch of 500 records are throttled, the 500 records will be queued for retrying and the tail won't proceed until the publish queue is not full. The default capacity of the queue is 100 if not configured.

It was designed in this way because we don't want to lose data even if service throttling occurs.

[mattford63]

Hi, it's more that I don't see any evidence of actual slow-down. Things are just continuously retried until the Kinesis stream is open again. The back-off doesn't look to happen.

[chaochenq]

I seem to have been able to see the throttler and the backoff working with handling send failures. I tried to make the agent send records to a non-existed stream, and it backs off upon ResourceNotFound failures.

I'll try to reproduce the case of Kinesis throttling, if it doesn't work, I suspect it could be we are not counting throttling as failures.

[chaochenq]

I've been able to make requests with high throughput that causes the Kinesis to return ServiceUnavailableException, and the throttler is working fine:

2016-05-25 22:11:11.129+0000 ip-172-31-10-201 (sender-1) com.amazon.kinesis.streaming.agent.tailing.FirehoseSender [DEBUG] fh:mystream:/tmp/app.log_:RecordBuffer(id=4456,records=500,bytes=36172) Errors from firehose mystream: ServiceUnavailableException: 500
2016-05-25 22:11:11.129+0000 ip-172-31-10-201 (sender-1) com.amazon.kinesis.streaming.agent.tailing.AsyncPublisher [DEBUG] AsyncPublisher[fh:mystream:/tmp/app.log_]:RecordBuffer(id=4456,records=500,bytes=36172) Send PARTIAL_SUCCESS: Sent: 0, Failed: 500
2016-05-25 22:11:11.129+0000 ip-172-31-10-201 (sender-8) com.amazon.kinesis.streaming.agent.tailing.FirehoseSender [TRACE] fh:mystream:/tmp/app.log_:RecordBuffer(id=4440,records=500,bytes=36097) Record 433 returned error code ServiceUnavailableException: Slow down.
2016-05-25 22:11:11.129+0000 ip-172-31-10-201 (sender-8) com.amazon.kinesis.streaming.agent.tailing.FirehoseSender [TRACE] fh:mystream:/tmp/app.log_:RecordBuffer(id=4440,records=500,bytes=36097) Record 434 returned error code ServiceUnavailableException: Slow down.
2016-05-25 22:11:11.129+0000 ip-172-31-10-201 (sender-8) com.amazon.kinesis.streaming.agent.tailing.FirehoseSender [TRACE] fh:mystream:/tmp/app.log_:RecordBuffer(id=4440,records=500,bytes=36097) Record 435 returned error code ServiceUnavailableException: Slow down.
2016-05-25 22:11:11.129+0000 ip-172-31-10-201 (sender-8) com.amazon.kinesis.streaming.agent.tailing.FirehoseSender [TRACE] fh:mystream:/tmp/app.log_:RecordBuffer(id=4440,records=500,bytes=36097) Record 436 returned error code ServiceUnavailableException: Slow down.
2016-05-25 22:11:11.129+0000 ip-172-31-10-201 (sender-8) com.amazon.kinesis.streaming.agent.tailing.FirehoseSender [TRACE] fh:mystream:/tmp/app.log_:RecordBuffer(id=4440,records=500,bytes=36097) Record 437 returned error code ServiceUnavailableException: Slow down.
2016-05-25 22:11:11.129+0000 ip-172-31-10-201 (sender-8) com.amazon.kinesis.streaming.agent.tailing.FirehoseSender [TRACE] fh:mystream:/tmp/app.log_:RecordBuffer(id=4440,records=500,bytes=36097) Record 438 returned error code ServiceUnavailableException: Slow down.
2016-05-25 22:11:11.129+0000 ip-172-31-10-201 (sender-8) com.amazon.kinesis.streaming.agent.tailing.FirehoseSender [TRACE] fh:mystream:/tmp/app.log_:RecordBuffer(id=4440,records=500,bytes=36097) Record 439 returned error code ServiceUnavailableException: Slow down.
2016-05-25 22:11:11.129+0000 ip-172-31-10-201 (sender-8) com.amazon.kinesis.streaming.agent.tailing.FirehoseSender [TRACE] fh:mystream:/tmp/app.log_:RecordBuffer(id=4440,records=500,bytes=36097) Record 440 returned error code ServiceUnavailableException: Slow down.
2016-05-25 22:11:11.129+0000 ip-172-31-10-201 (sender-8) com.amazon.kinesis.streaming.agent.tailing.FirehoseSender [TRACE] fh:mystream:/tmp/app.log_:RecordBuffer(id=4440,records=500,bytes=36097) Record 441 returned error code ServiceUnavailableException: Slow down.
2016-05-25 22:11:11.129+0000 ip-172-31-10-201 (sender-8) com.amazon.kinesis.streaming.agent.tailing.FirehoseSender [TRACE] fh:mystream:/tmp/app.log_:RecordBuffer(id=4440,records=500,bytes=36097) Record 442 returned error code ServiceUnavailableException: Slow down.
2016-05-25 22:11:11.129+0000 ip-172-31-10-201 (sender-8) com.amazon.kinesis.streaming.agent.tailing.FirehoseSender [TRACE] fh:mystream:/tmp/app.log_:RecordBuffer(id=4440,records=500,bytes=36097) Record 443 returned error code ServiceUnavailableException: Slow down.
2016-05-25 22:11:11.129+0000 ip-172-31-10-201 (sender-8) com.amazon.kinesis.streaming.agent.tailing.FirehoseSender [TRACE] fh:mystream:/tmp/app.log_:RecordBuffer(id=4440,records=500,bytes=36097) Record 444 returned error code ServiceUnavailableException: Slow down.
2016-05-25 22:11:11.129+0000 ip-172-31-10-201 (sender-8) com.amazon.kinesis.streaming.agent.tailing.FirehoseSender [TRACE] fh:mystream:/tmp/app.log_:RecordBuffer(id=4440,records=500,bytes=36097) Record 445 returned error code ServiceUnavailableException: Slow down.
2016-05-25 22:11:11.129+0000 ip-172-31-10-201 (sender-8) com.amazon.kinesis.streaming.agent.tailing.FirehoseSender [TRACE] fh:mystream:/tmp/app.log_:RecordBuffer(id=4440,records=500,bytes=36097) Record 446 returned error code ServiceUnavailableException: Slow down.
2016-05-25 22:11:11.129+0000 ip-172-31-10-201 (sender-8) com.amazon.kinesis.streaming.agent.tailing.FirehoseSender [TRACE] fh:mystream:/tmp/app.log_:RecordBuffer(id=4440,records=500,bytes=36097) Record 447 returned error code ServiceUnavailableException: Slow down.
2016-05-25 22:11:11.129+0000 ip-172-31-10-201 (sender-8) com.amazon.kinesis.streaming.agent.tailing.FirehoseSender [TRACE] fh:mystream:/tmp/app.log_:RecordBuffer(id=4440,records=500,bytes=36097) Record 448 returned error code ServiceUnavailableException: Slow down.
2016-05-25 22:11:11.129+0000 ip-172-31-10-201 (sender-8) com.amazon.kinesis.streaming.agent.tailing.FirehoseSender [TRACE] fh:mystream:/tmp/app.log_:RecordBuffer(id=4440,records=500,bytes=36097) Record 449 returned error code ServiceUnavailableException: Slow down.
2016-05-25 22:11:11.129+0000 ip-172-31-10-201 (sender-8) com.amazon.kinesis.streaming.agent.tailing.FirehoseSender [TRACE] fh:mystream:/tmp/app.log_:RecordBuffer(id=4440,records=500,bytes=36097) Record 450 returned error code ServiceUnavailableException: Slow down.
2016-05-25 22:11:11.129+0000 ip-172-31-10-201 (sender-8) com.amazon.kinesis.streaming.agent.tailing.FirehoseSender [TRACE] fh:mystream:/tmp/app.log_:RecordBuffer(id=4440,records=500,bytes=36097) Record 451 returned error code ServiceUnavailableException: Slow down.
2016-05-25 22:11:11.129+0000 ip-172-31-10-201 (sender-8) com.amazon.kinesis.streaming.agent.tailing.FirehoseSender [TRACE] fh:mystream:/tmp/app.log_:RecordBuffer(id=4440,records=500,bytes=36097) Record 452 returned error code ServiceUnavailableException: Slow down.
2016-05-25 22:11:11.129+0000 ip-172-31-10-201 (sender-8) com.amazon.kinesis.streaming.agent.tailing.FirehoseSender [TRACE] fh:mystream:/tmp/app.log_:RecordBuffer(id=4440,records=500,bytes=36097) Record 453 returned error code ServiceUnavailableException: Slow down.
2016-05-25 22:11:11.129+0000 ip-172-31-10-201 (sender-8) com.amazon.kinesis.streaming.agent.tailing.FirehoseSender [TRACE] fh:mystream:/tmp/app.log_:RecordBuffer(id=4440,records=500,bytes=36097) Record 454 returned error code ServiceUnavailableException: Slow down.
2016-05-25 22:11:11.129+0000 ip-172-31-10-201 (sender-8) com.amazon.kinesis.streaming.agent.tailing.FirehoseSender [TRACE] fh:mystream:/tmp/app.log_:RecordBuffer(id=4440,records=500,bytes=36097) Record 455 returned error code ServiceUnavailableException: Slow down.
2016-05-25 22:11:11.129+0000 ip-172-31-10-201 (sender-8) com.amazon.kinesis.streaming.agent.tailing.FirehoseSender [TRACE] fh:mystream:/tmp/app.log_:RecordBuffer(id=4440,records=500,bytes=36097) Record 456 returned error code ServiceUnavailableException: Slow down.
2016-05-25 22:11:11.129+0000 ip-172-31-10-201 (sender-8) com.amazon.kinesis.streaming.agent.tailing.FirehoseSender [TRACE] fh:mystream:/tmp/app.log_:RecordBuffer(id=4440,records=500,bytes=36097) Record 457 returned error code ServiceUnavailableException: Slow down.
2016-05-25 22:11:11.129+0000 ip-172-31-10-201 (sender-8) com.amazon.kinesis.streaming.agent.tailing.FirehoseSender [TRACE] fh:mystream:/tmp/app.log_:RecordBuffer(id=4440,records=500,bytes=36097) Record 458 returned error code ServiceUnavailableException: Slow down.
2016-05-25 22:11:11.129+0000 ip-172-31-10-201 (sender-8) com.amazon.kinesis.streaming.agent.tailing.FirehoseSender [TRACE] fh:mystream:/tmp/app.log_:RecordBuffer(id=4440,records=500,bytes=36097) Record 459 returned error code ServiceUnavailableException: Slow down.
2016-05-25 22:11:11.129+0000 ip-172-31-10-201 (sender-8) com.amazon.kinesis.streaming.agent.tailing.FirehoseSender [TRACE] fh:mystream:/tmp/app.log_:RecordBuffer(id=4440,records=500,bytes=36097) Record 460 returned error code ServiceUnavailableException: Slow down.
2016-05-25 22:11:11.129+0000 ip-172-31-10-201 (sender-8) com.amazon.kinesis.streaming.agent.tailing.FirehoseSender [TRACE] fh:mystream:/tmp/app.log_:RecordBuffer(id=4440,records=500,bytes=36097) Record 461 returned error code ServiceUnavailableException: Slow down.
2016-05-25 22:11:11.129+0000 ip-172-31-10-201 (sender-8) com.amazon.kinesis.streaming.agent.tailing.FirehoseSender [TRACE] fh:mystream:/tmp/app.log_:RecordBuffer(id=4440,records=500,bytes=36097) Record 462 returned error code ServiceUnavailableException: Slow down.
2016-05-25 22:11:11.129+0000 ip-172-31-10-201 (sender-8) com.amazon.kinesis.streaming.agent.tailing.FirehoseSender [TRACE] fh:mystream:/tmp/app.log_:RecordBuffer(id=4440,records=500,bytes=36097) Record 463 returned error code ServiceUnavailableException: Slow down.
2016-05-25 22:11:11.129+0000 ip-172-31-10-201 (sender-8) com.amazon.kinesis.streaming.agent.tailing.FirehoseSender [TRACE] fh:mystream:/tmp/app.log_:RecordBuffer(id=4440,records=500,bytes=36097) Record 464 returned error code ServiceUnavailableException: Slow down.
2016-05-25 22:11:11.129+0000 ip-172-31-10-201 (sender-8) com.amazon.kinesis.streaming.agent.tailing.FirehoseSender [TRACE] fh:mystream:/tmp/app.log_:RecordBuffer(id=4440,records=500,bytes=36097) Record 465 returned error code ServiceUnavailableException: Slow down.
2016-05-25 22:11:11.129+0000 ip-172-31-10-201 (sender-8) com.amazon.kinesis.streaming.agent.tailing.FirehoseSender [TRACE] fh:mystream:/tmp/app.log_:RecordBuffer(id=4440,records=500,bytes=36097) Record 466 returned error code ServiceUnavailableException: Slow down.
2016-05-25 22:11:11.129+0000 ip-172-31-10-201 (sender-8) com.amazon.kinesis.streaming.agent.tailing.FirehoseSender [TRACE] fh:mystream:/tmp/app.log_:RecordBuffer(id=4440,records=500,bytes=36097) Record 467 returned error code ServiceUnavailableException: Slow down.
2016-05-25 22:11:11.129+0000 ip-172-31-10-201 (sender-1) com.amazon.kinesis.streaming.agent.tailing.AsyncPublisher [TRACE] AsyncPublisher[fh:mystream:/tmp/app.log_]:RecordBuffer(id=4456,records=500,bytes=36172) Buffer Queued for Retry
2016-05-25 22:11:11.129+0000 ip-172-31-10-201 (sender-1) com.amazon.kinesis.streaming.agent.tailing.AsyncPublisher [TRACE] AsyncPublisher[fh:mystream:/tmp/app.log_]:RecordBuffer(id=4456,records=500,bytes=36172) Send Completed
2016-05-25 22:11:11.129+0000 ip-172-31-10-201 (AsyncPublisher[fh:mystream:/tmp/app.log_]) com.amazon.kinesis.streaming.agent.tailing.AsyncPublisher [TRACE] AsyncPublisher[fh:mystream:/tmp/app.log_]:RecordBuffer(id=4456,records=500,bytes=36172) Send Scheduled
2016-05-25 22:11:11.129+0000 ip-172-31-10-201 (AsyncPublisher[fh:mystream:/tmp/app.log_]) com.amazon.kinesis.streaming.agent.tailing.AsyncPublisherThrottler [DEBUG] AsyncPublisher[fh:mystream:/tmp/app.log*]: Backing off for 129 millis (failures: 1.0, rejections: 0.0)...

[chaochenq]

Actually if the error is ProvisionedThroughputExceededException, the throttler doesn't seem to be working. I'll have to dive deeper into it.

[mattford63]

Yep that's what I see.

[chaochenq]

Actually I'm able to see the throttler working even upon ProvisionedThroughputExceededException

[exec] 2016-05-27 12:18:17.044-0700 chaocheq.desktop.amazon.com (sender-20) com.amazon.kinesis.streaming.agent.tailing.KinesisSender [ERROR] kinesis:kin
esis-agent-test2:/tmp/aws-kinesis-agent-test2.log_:RecordBuffer(id=72,records=500,bytes=175330) Record 493 returned error code ProvisionedThroughputExceededE
xception: Rate exceeded for shard shardId-000000000002 in stream kinesis-agent-test2 under account 576903325155.
[exec] 2016-05-27 12:18:17.044-0700 chaocheq.desktop.amazon.com (sender-20) com.amazon.kinesis.streaming.agent.tailing.KinesisSender [ERROR] kinesis:kin
esis-agent-test2:/tmp/aws-kinesis-agent-test2.log_:RecordBuffer(id=72,records=500,bytes=175330) Record 494 returned error code ProvisionedThroughputExceededE
xception: Rate exceeded for shard shardId-000000000000 in stream kinesis-agent-test2 under account 576903325155.
[exec] 2016-05-27 12:18:17.044-0700 chaocheq.desktop.amazon.com (sender-20) com.amazon.kinesis.streaming.agent.tailing.KinesisSender [ERROR] kinesis:kin
esis-agent-test2:/tmp/aws-kinesis-agent-test2.log_:RecordBuffer(id=72,records=500,bytes=175330) Record 495 returned error code ProvisionedThroughputExceededE
xception: Rate exceeded for shard shardId-000000000000 in stream kinesis-agent-test2 under account 576903325155.
[exec] 2016-05-27 12:18:17.044-0700 chaocheq.desktop.amazon.com (sender-20) com.amazon.kinesis.streaming.agent.tailing.KinesisSender [ERROR] kinesis:kin
esis-agent-test2:/tmp/aws-kinesis-agent-test2.log_:RecordBuffer(id=72,records=500,bytes=175330) Record 496 returned error code ProvisionedThroughputExceededE
xception: Rate exceeded for shard shardId-000000000002 in stream kinesis-agent-test2 under account 576903325155.
[exec] 2016-05-27 12:18:17.044-0700 chaocheq.desktop.amazon.com (sender-20) com.amazon.kinesis.streaming.agent.tailing.KinesisSender [ERROR] kinesis:kin
esis-agent-test2:/tmp/aws-kinesis-agent-test2.log_:RecordBuffer(id=72,records=500,bytes=175330) Record 497 returned error code ProvisionedThroughputExceededE
xception: Rate exceeded for shard shardId-000000000001 in stream kinesis-agent-test2 under account 576903325155.
[exec] 2016-05-27 12:18:17.044-0700 chaocheq.desktop.amazon.com (sender-20) com.amazon.kinesis.streaming.agent.tailing.KinesisSender [ERROR] kinesis:kin
esis-agent-test2:/tmp/aws-kinesis-agent-test2.log_:RecordBuffer(id=72,records=500,bytes=175330) Record 498 returned error code ProvisionedThroughputExceededE
xception: Rate exceeded for shard shardId-000000000001 in stream kinesis-agent-test2 under account 576903325155.
[exec] 2016-05-27 12:18:17.044-0700 chaocheq.desktop.amazon.com (sender-20) com.amazon.kinesis.streaming.agent.tailing.KinesisSender [ERROR] kinesis:kin
esis-agent-test2:/tmp/aws-kinesis-agent-test2.log_:RecordBuffer(id=72,records=500,bytes=175330) Record 499 returned error code ProvisionedThroughputExceededE
xception: Rate exceeded for shard shardId-000000000002 in stream kinesis-agent-test2 under account 576903325155.
[exec] 2016-05-27 12:18:17.044-0700 chaocheq.desktop.amazon.com (sender-20) com.amazon.kinesis.streaming.agent.tailing.KinesisSender [DEBUG] kinesis:kin
esis-agent-test2:/tmp/aws-kinesis-agent-test2.log_:RecordBuffer(id=72,records=500,bytes=175330) Records sent to kinesis stream kinesis-agent-test2: 0. Failed
records: 500
[exec] 2016-05-27 12:18:17.045-0700 chaocheq.desktop.amazon.com (sender-20) com.amazon.kinesis.streaming.agent.tailing.KinesisSender [DEBUG] kinesis:kin
esis-agent-test2:/tmp/aws-kinesis-agent-test2.log_:RecordBuffer(id=72,records=500,bytes=175330) Errors from kinesis stream kinesis-agent-test2: ProvisionedTh
roughputExceededException: 500
[exec] 2016-05-27 12:18:17.045-0700 chaocheq.desktop.amazon.com (sender-20) com.amazon.kinesis.streaming.agent.tailing.AsyncPublisher [DEBUG] AsyncPubli
sher[kinesis:kinesis-agent-test2:/tmp/aws-kinesis-agent-test2.log_]:RecordBuffer(id=72,records=500,bytes=175330) Send PARTIAL_SUCCESS: Sent: 0, Failed: 500
[exec] 2016-05-27 12:18:17.106-0700 chaocheq.desktop.amazon.com (FileTailer[kinesis:kinesis-agent-test2:/tmp/aws-kinesis-agent-test2.log_]) com.amazon.k
inesis.streaming.agent.tailing.FileTailer [DEBUG] FileTailer[kinesis:kinesis-agent-test2:/tmp/aws-kinesis-agent-test2.log_]: record publisher exerting backpr
essure. Backing off a bit.
[exec] 2016-05-27 12:18:17.126-0700 chaocheq.desktop.amazon.com (AsyncPublisher[kinesis:kinesis-agent-test2:/tmp/aws-kinesis-agent-test2.log_]) com.amazon.kinesis.streaming.agent.tailing.AsyncPublisherThrottler [DEBUG] AsyncPublisher[kinesis:kinesis-agent-test2:/tmp/aws-kinesis-agent-test2.log_]: Backing off for 9150 millis (failures: 23.0, rejections: 0.0)...

[mattford63]

Can you share the magic config that printed these debugging messages? I've found it hard to see output like that. Thanks.

[chaochenq]

I was just using "log.level" : "DEBUG" for that. I also switched some trace log to error which I'll check in another commit later.