CloudWatch logs get_log_events pager seems to loop indefinitley

[Tim-B]

I'm having some trouble using get_log_events with the .each do |response| pager functionality.

Basically it seems to loop indefinitely.

Here's a basic example:

require 'aws-sdk'

cwl = Aws::CloudWatchLogs::Client.new(region: 'us-east-1')

resp = cwl.get_log_events(
    log_group_name: 'CloudTrail/DefaultLogGroup',
    log_stream_name: '284243076752_CloudTrail_us-east-1',
    start_time: (Time.now.to_i - 3 * 60 * 60 * 24) * 1000,
    end_time: (Time.now.to_i - 1 * 60 * 60 * 24) * 1000,
)

resp.each do |event_page|
  puts "Page returned with #{event_page[:events].length} items."
  puts "back #{event_page[:next_backward_token]} forward #{event_page[:next_forward_token]}"
  puts "Last #{event_page.last_page?}"
  puts "Next #{event_page.next_page?}"
end

If you replace log_stream_name with your own log stream name this should print all events from 1 day ago to 3 days ago.

For me that returns:

Page returned with 1013 items.
back b/31761921002636013633299509555220269662210192519471497216 forward f/31765609545891850598367319401354689355894894871384293376
Last false
Next true
Page returned with 0 items.
back b/31765609545891850598367319401354689355894894871384293376 forward f/31765609545891850598367319401354689355894894871384293376
Last false
Next true
Page returned with 0 items.
back b/31765609545891850598367319401354689355894894871384293376 forward f/31765609545891850598367319401354689355894894871384293376
Last false
Next true
Page returned with 0 items.
back b/31765609545891850598367319401354689355894894871384293376 forward f/31765609545891850598367319401354689355894894871384293376
Last false
Next true
Page returned with 0 items.
back b/31765609545891850598367319401354689355894894871384293376 forward f/31765609545891850598367319401354689355894894871384293376
Last false
Next true
Page returned with 0 items.
back b/31765609545891850598367319401354689355894894871384293376 forward f/31765609545891850598367319401354689355894894871384293376
Last false
Next true
Page returned with 0 items.
back b/31765609545891850598367319401354689355894894871384293376 forward f/31765609545891850598367319401354689355894894871384293376
Last false
Next true
Page returned with 0 items.
back b/31765609545891850598367319401354689355894894871384293376 forward f/31765609545891850598367319401354689355894894871384293376
Last false
Next true
Page returned with 0 items.
back b/31765609545891850598367319401354689355894894871384293376 forward f/31765609545891850598367319401354689355894894871384293376
Last false
Next true
Page returned with 0 items.
back b/31765609545891850598367319401354689355894894871384293376 forward f/31765609545891850598367319401354689355894894871384293376
Last false
Next true
Page returned with 0 items.
back b/31765609545891850598367319401354689355894894871384293376 forward f/31765609545891850598367319401354689355894894871384293376
Last false
Next true
Page returned with 0 items.
back b/31765609545891850598367319401354689355894894871384293376 forward f/31765609545891850598367319401354689355894894871384293376
Last false
Next true
Page returned with 0 items.
back b/31765609545891850598367319401354689355894894871384293376 forward f/31765609545891850598367319401354689355894894871384293376
Last false
Next true
Page returned with 0 items.
back b/31765609545891850598367319401354689355894894871384293376 forward f/31765609545891850598367319401354689355894894871384293376
Last false
Next true
Page returned with 0 items.
back b/31765609545891850598367319401354689355894894871384293376 forward f/31765609545891850598367319401354689355894894871384293376
Last false
Next true
Page returned with 0 items.
back b/31765609545891850598367319401354689355894894871384293376 forward f/31765609545891850598367319401354689355894894871384293376
Last false
Next true

After which I kill the process. As you can see it returns all the logs in the first iteration, then returns 0 logs and identical next/previous tokens and continues looping.

Is this intended behaviour?

If this is not intended then I suspect the issue could be the actual REST API rather than the Ruby SDK.

For example if you run this using the AWS CLI:

aws \
logs \
get-log-events \
--log-group-name "CloudTrail/DefaultLogGroup" \
--log-stream-name "284243076752_CloudTrail_us-east-1" \
--next-token "f/31765609545891850598367319401354689355894894871384293376" \
--start-time "1424253534000" \
--end-time "1424426334000" \
> out.txt

You'll get something like:

{
    "nextForwardToken": "f/31765609545891850598367319401354689355894894871384293376", 
    "events": [], 
    "nextBackwardToken": "b/31765609545891850598367319401354689355894894871384293376"
}

In that example the next-token supplied is outside the time range but it still returns a next token leaving the SDK to believe there's still records.

This could probably be resolved in the Ruby SDK by ending the iteration when the next token equals the back token.

[trevorrowe]

Thats for reporting the issue. This is not intended behavior. I'm going to look at this more, and hopefully get a fix shortly.

[trevorrowe]

I've been looking into this. It appears, unlike other services, that cloud watch logs is using the marker to allow continuations, even when there are no more results at the current point in time.

For the SDK to handle this generically, the paginators would need to maintain the paging tokens from the previous response and compare them to the current ones to determine if there are any more results. I'm going to discuss this with a few team members and hopefully put together a solution. Thank you for your patience.

[Tim-B]

No worries.

For the moment I've just been doing this which seems to get around the issue:

resp.each do |log_page|
  if log_page[:events].length == 0
    break
  end
  # something
end

[trevorrowe]

I have a working patch, but I'm doing some more research to ensure that echoing the same token is not a valid pattern elsewhere.

[trevorrowe]

I re-worked the patch (e02eb99), this version is a much smaller code change, and is easier to follow. I'm much happier with the result and I think it satisfies the required change without breaking existing tests. The previous commit had some test failures.

[trevorrowe]

Closed by #730. This will be part of our next release. Thanks for submitting an excellent bug report and for your patience!