Add Fastly log processor #1176

Merged
merged 9 commits into from Feb 18, 2016

Conversation

Projects
None yet
5 participants
@ktheory
Member

ktheory commented Jan 15, 2016

馃憢 Happy Friday 馃檰

This implements much of rubygems/rubygems-infrastructure#35, allowing us to update Rubygem download counts in bulk using Fastly access logs rather than on each HTTP request.

I still have some cleanup to do, but wanted to get some 馃憖 earlier.

To Do

  • add a feature flag to control whether to have FastlyLogProcessor actually update stats, or just log results. (It would only log initially.)
  • figure out how to disable the stat-update C library as part of the feature flag
  • Cleanup & test shoryuken config, preferably loading SQS queue names from ENV vars
  • Make another PR to run a shoryuken process on deploy once Chef provisions a runit script for it

Deploy plan

NB that this code is disabled right now. We're not currently running a shoryuken worker, and so nothing would enqueue a FastlyLogProcessor job.

Once this is merged, the next step is to start running a shoryuken process, with FastlyLogProcessor only logging results & not updating redis.

After that I'll toggle the feature flag so FastlyLogProcessor updates stats, and disable stat-update per request.

FYI @dwradcliffe

@ktheory

This comment has been minimized.

Show comment
Hide comment
@ktheory

ktheory Jan 15, 2016

Member

Rubocop is not a happy. 馃槺

I'll amend the commits. 馃槃

Member

ktheory commented Jan 15, 2016

Rubocop is not a happy. 馃槺

I'll amend the commits. 馃槃

@dwradcliffe

View changes

config/initializers/delayed_job.rb
@@ -3,4 +3,4 @@
Delayed::Worker.max_run_time = 5.minutes
Delayed::Worker.logger = Logger.new(Rails.root.join('log/delayed_job.log'))
-PRIORITIES = { push: 1, download: 2, web_hook: 3 }.freeze
+PRIORITIES = { push: 1, download: 2, web_hook: 3, download_metrics: 4 }.freeze

This comment has been minimized.

@dwradcliffe

dwradcliffe Feb 1, 2016

Member

Can we shorten this to stats?

@dwradcliffe

dwradcliffe Feb 1, 2016

Member

Can we shorten this to stats?

This comment has been minimized.

@arthurnn

arthurnn Feb 17, 2016

Member

I hate this constant been here :( eventually i wanna moved it out. I had that somewhere. Anyways, not in the scope of this PR

@arthurnn

arthurnn Feb 17, 2016

Member

I hate this constant been here :( eventually i wanna moved it out. I had that somewhere. Anyways, not in the scope of this PR

+ celluloid-pool (0.20.5)
+ timers (>= 4.1.1)
+ celluloid-supervision (0.20.5)
+ timers (>= 4.1.1)

This comment has been minimized.

@dwradcliffe

dwradcliffe Feb 2, 2016

Member

Too bad we need all the celluloid gems :/

@dwradcliffe

dwradcliffe Feb 2, 2016

Member

Too bad we need all the celluloid gems :/

This comment has been minimized.

@arthurnn

arthurnn Feb 17, 2016

Member

do we? why?

@arthurnn

arthurnn Feb 17, 2016

Member

do we? why?

This comment has been minimized.

@arthurnn

arthurnn Feb 17, 2016

Member

shoryuken gem. right.. I guess it is fine for now. I can try to remove the dependency afterwards, and write something simpler.

@arthurnn

arthurnn Feb 17, 2016

Member

shoryuken gem. right.. I guess it is fine for now. I can try to remove the dependency afterwards, and write something simpler.

@dwradcliffe

View changes

app/jobs/fastly_log_processor.rb
+ enumerator.each_with_object(Hash.new(0)) do |log_line, accum|
+ path, response_code = log_line.split[10, 2]
+ # Only count successful downloads
+ # TODO: should we count 304 not modified responses?

This comment has been minimized.

@dwradcliffe

dwradcliffe Feb 2, 2016

Member

A 304 is a download attempt, so I think that counts? Right now they would be real downloads so we should probably keep counting them. Any other opinions? @evanphx @qrush @indirect

@dwradcliffe

dwradcliffe Feb 2, 2016

Member

A 304 is a download attempt, so I think that counts? Right now they would be real downloads so we should probably keep counting them. Any other opinions? @evanphx @qrush @indirect

This comment has been minimized.

@qrush

qrush Feb 2, 2016

Member

I'd say yes, count any attempt.

@qrush

qrush Feb 2, 2016

Member

I'd say yes, count any attempt.

@dwradcliffe

This comment has been minimized.

Show comment
Hide comment
@dwradcliffe

dwradcliffe Feb 2, 2016

Member

I added a few comments and it looks like this needs a rebase.

Member

dwradcliffe commented Feb 2, 2016

I added a few comments and it looks like this needs a rebase.

@qrush

View changes

app/jobs/sqs_worker.rb
+
+ # TODO: set real queue name
+ # TODO: set auto_delete: true after testing
+ shoryuken_options queue: 'TODO-add-real-queue', body_parser: :json, auto_delete: false

This comment has been minimized.

@qrush

qrush Feb 2, 2016

Member

Do we actually need Shoryuken here? What's the advantage to using this when we have Delayed::Job?

@qrush

qrush Feb 2, 2016

Member

Do we actually need Shoryuken here? What's the advantage to using this when we have Delayed::Job?

This comment has been minimized.

@ktheory

ktheory Feb 17, 2016

Member

@qrush:

Do we actually need Shoryuken here? What's the advantage to using this when we have Delayed::Job?

We need a tool that uses AWS SQS as the queue. See this comment & discussion on rubygems-infrastructure.

@ktheory

ktheory Feb 17, 2016

Member

@qrush:

Do we actually need Shoryuken here? What's the advantage to using this when we have Delayed::Job?

We need a tool that uses AWS SQS as the queue. See this comment & discussion on rubygems-infrastructure.

+ redis.zincrby(today_key, count, full_name)
+ redis.zincrby(ALL_KEY, count, full_name)
+ redis.hincrby(version_history_key(full_name), today, count)
+ redis.hincrby(rubygem_history_key(name), today, count)

This comment has been minimized.

@qrush

qrush Feb 2, 2016

Member

Could wrap all of these in a redis.pipelined block, it'll be a lot faster since we don't need to wait for any replies.

@qrush

qrush Feb 2, 2016

Member

Could wrap all of these in a redis.pipelined block, it'll be a lot faster since we don't need to wait for any replies.

This comment has been minimized.

@ktheory

ktheory Feb 17, 2016

Member

@qrush:

Could wrap all of these in a redis.pipelined block, it'll be a lot faster since we don't need to wait for any replies.

The bulk_update method that calls this already sets up a pipeline. 馃槃

@ktheory

ktheory Feb 17, 2016

Member

@qrush:

Could wrap all of these in a redis.pipelined block, it'll be a lot faster since we don't need to wait for any replies.

The bulk_update method that calls this already sets up a pipeline. 馃槃

+ # E.g.:
+ # ['rake', 'rake-10.4.2', 1]
+ def self.bulk_update(ary)
+ Redis.current.multi do

This comment has been minimized.

@qrush

qrush Feb 2, 2016

Member

Why do we need a MULTI/EXEC transaction here? I think pipelining is probably fast enough. Are we worried some counts might be inaccurate?

@qrush

qrush Feb 2, 2016

Member

Why do we need a MULTI/EXEC transaction here? I think pipelining is probably fast enough. Are we worried some counts might be inaccurate?

This comment has been minimized.

@ktheory

ktheory Feb 17, 2016

Member

@qrush:

Why do we need a MULTI/EXEC transaction here?

It's for data consistency.

If a ruby process crashes part-way through updating a bunch of stats, the transaction will rollback, and the FastlyLogProcessor job will eventually retry.

Either all the redis commands succeed and FastlyLogProcessor job succeeds. Or the whole transaction fails, and the FastlyLogProcessor job retries.

@ktheory

ktheory Feb 17, 2016

Member

@qrush:

Why do we need a MULTI/EXEC transaction here?

It's for data consistency.

If a ruby process crashes part-way through updating a bunch of stats, the transaction will rollback, and the FastlyLogProcessor job will eventually retry.

Either all the redis commands succeed and FastlyLogProcessor job succeeds. Or the whole transaction fails, and the FastlyLogProcessor job retries.

@qrush

View changes

script/shoryuken
@@ -0,0 +1,3 @@
+#!/bin/sh
+
+exec bin/shoryuken --rails -r app/jobs/sqs_worker.rb

This comment has been minimized.

@qrush

qrush Feb 2, 2016

Member

This should go in bin/ now

@qrush

qrush Feb 2, 2016

Member

This should go in bin/ now

This comment has been minimized.

@ktheory

ktheory Feb 17, 2016

Member

@qrush:

This should go in bin/ now

Since bin is gitignored, it seemed like a non-starter for custom executables like this. Any suggestions?

@ktheory

ktheory Feb 17, 2016

Member

@qrush:

This should go in bin/ now

Since bin is gitignored, it seemed like a non-starter for custom executables like this. Any suggestions?

This comment has been minimized.

@dwradcliffe

dwradcliffe Feb 17, 2016

Member

I'd say remove from gitignore, as we should be placing things in bin/ now.

@dwradcliffe

dwradcliffe Feb 17, 2016

Member

I'd say remove from gitignore, as we should be placing things in bin/ now.

This comment has been minimized.

@ktheory

ktheory Feb 17, 2016

Member

馃檰 Separate PR incoming.

@ktheory

ktheory Feb 17, 2016

Member

馃檰 Separate PR incoming.

This comment has been minimized.

@ktheory

ktheory Feb 17, 2016

Member

Actually, just realized I could add this with git add -f. 馃嵃

@ktheory

ktheory Feb 17, 2016

Member

Actually, just realized I could add this with git add -f. 馃嵃

This comment has been minimized.

@qrush

View changes

test/unit/fastly_log_processor_test.rb
+
+class FastlyLogProcessorTest < ActiveSupport::TestCase
+ setup do
+ @sample_log = File.read(Rails.root.join('test/sample_logs/fastly-fake.log'))

This comment has been minimized.

@qrush

qrush Feb 2, 2016

Member

Can use Pathname#read here instead:

Rails.root.join('test/sample_logs/fastly-fake.log').read

@qrush

qrush Feb 2, 2016

Member

Can use Pathname#read here instead:

Rails.root.join('test/sample_logs/fastly-fake.log').read

@qrush

View changes

app/jobs/fastly_log_processor.rb
+ def perform
+ counts = download_counts
+
+ unless Gemcutter::ENABLE_FASTLY_LOG_PROCESSOR

This comment has been minimized.

@qrush

qrush Feb 2, 2016

Member

This seems like a weird place for the feature flag. Can we move it to where we enqueue the job instead?

@qrush

qrush Feb 2, 2016

Member

This seems like a weird place for the feature flag. Can we move it to where we enqueue the job instead?

This comment has been minimized.

@ktheory

ktheory Feb 17, 2016

Member

@qrush We still want to enqueue the job & process the log regardless.

This feature flag is toggling whether we actually update the counts in redis; or just log the counts for debugging.

NB this is a temporary feature flag while we dark-launch log processing. I'll remove it once we're confident it's working well.

@ktheory

ktheory Feb 17, 2016

Member

@qrush We still want to enqueue the job & process the log regardless.

This feature flag is toggling whether we actually update the counts in redis; or just log the counts for debugging.

NB this is a temporary feature flag while we dark-launch log processing. I'll remove it once we're confident it's working well.

@@ -0,0 +1,4 @@
+module Gemcutter
+ # Feature flag for counting downloads through stats-update or FastlyLogProcessor
+ ENABLE_FASTLY_LOG_PROCESSOR = Rails.env.test? || Rails.env.development?

This comment has been minimized.

@arthurnn

arthurnn Feb 17, 2016

Member

why do we need this constant here? can we move this to the Download model or the log processor itself?

@arthurnn

arthurnn Feb 17, 2016

Member

why do we need this constant here? can we move this to the Download model or the log processor itself?

This comment has been minimized.

@ktheory

ktheory Feb 17, 2016

Member

why do we need this constant here? can we move this to the Download model or the log processor itself?

We don't need it here, but we need it somewhere. 馃槃

Since it's serving as a feature flag, it's more appropriate as config than as app or library code. My rule of thumb is that app code can talk to config code; and config code can use Rails.env. But app code should never directly check Rails.env.

app <--> config <--> environments

FWIW, this is a temporary feature flag while we dark-launch Fastly log processing. Once we're confident it's working well, we'd remove this.

@ktheory

ktheory Feb 17, 2016

Member

why do we need this constant here? can we move this to the Download model or the log processor itself?

We don't need it here, but we need it somewhere. 馃槃

Since it's serving as a feature flag, it's more appropriate as config than as app or library code. My rule of thumb is that app code can talk to config code; and config code can use Rails.env. But app code should never directly check Rails.env.

app <--> config <--> environments

FWIW, this is a temporary feature flag while we dark-launch Fastly log processing. Once we're confident it's working well, we'd remove this.

@arthurnn

View changes

app/jobs/fastly_log_processor.rb
@@ -0,0 +1,75 @@
+require 'zlib'
+FastlyLogProcessor = Struct.new(:bucket, :key) do

This comment has been minimized.

@arthurnn

arthurnn Feb 17, 2016

Member

I dont like Structs. they are usually slower than normal classes too. Can we define a class here instead?

@arthurnn

arthurnn Feb 17, 2016

Member

I dont like Structs. they are usually slower than normal classes too. Can we define a class here instead?

This comment has been minimized.

This comment has been minimized.

@ktheory

ktheory Feb 17, 2016

Member

I dont like Structs. they are usually slower than normal classes too. Can we define a class here instead?

I was following app/jobs/notifier.rb as an example (which uses a Struct), and the Struct saves me some boilerplate initializer/accessor code.

I was aiming to be as conventional as possible. 馃槃 @arthurnn Is the project's convention now to use classes?

@ktheory

ktheory Feb 17, 2016

Member

I dont like Structs. they are usually slower than normal classes too. Can we define a class here instead?

I was following app/jobs/notifier.rb as an example (which uses a Struct), and the Struct saves me some boilerplate initializer/accessor code.

I was aiming to be as conventional as possible. 馃槃 @arthurnn Is the project's convention now to use classes?

This comment has been minimized.

@arthurnn

arthurnn Feb 17, 2016

Member

yeah. I guess classes are better. Lets use a class, and maybe we can re-work the other notifier to change for a class too in the future

@arthurnn

arthurnn Feb 17, 2016

Member

yeah. I guess classes are better. Lets use a class, and maybe we can re-work the other notifier to change for a class too in the future

This comment has been minimized.

@kerrizor

kerrizor Feb 17, 2016

I see you've made the change already, but for the curious, Structs are ~46% slower than using a Class (at least, for simple getter/setter actions.) Some benchmarking

@kerrizor

kerrizor Feb 17, 2016

I see you've made the change already, but for the curious, Structs are ~46% slower than using a Class (at least, for simple getter/setter actions.) Some benchmarking

ktheory added some commits Jan 12, 2016

Gemfile: Add shoryuken & aws-sdk
We鈥檒l use shoryuken for processing SQS messages; and aws-sdk for
downloading S3 files
Add a FastlyLogProcessor job
It takes an S3 bucket & key, parses out the download counts, and bulk
updated download counts in redis
Add a Shoryuken worker
The Shoryuken worker reads S3 ObjectCreated messages from SQS, and
enqueues an associated FastlyLogProcessor job.
Fastly logs: incorporate feedback from PR
- count 304 responses as download attempts
- rename download_metrics queue to stats

Also add a test that 404 responses are not counted as downloads.
shoryuken: clean up config
Now it relies on an SQS_QUEUE env var
@dwradcliffe

This comment has been minimized.

Show comment
Hide comment
@dwradcliffe

dwradcliffe Feb 18, 2016

Member

LGTM 馃殺

Member

dwradcliffe commented Feb 18, 2016

LGTM 馃殺

@ktheory ktheory changed the title from Add Fastly log processor (work-in-progress) to Add Fastly log processor Feb 18, 2016

ktheory added a commit that referenced this pull request Feb 18, 2016

@ktheory ktheory merged commit 7f8a32b into rubygems:master Feb 18, 2016

1 check passed

continuous-integration/travis-ci/pr The Travis CI build passed
Details

@ktheory ktheory referenced this pull request Feb 18, 2016

Merged

Restart shoryuken processes on deploy #1198

1 of 1 task complete

@ktheory ktheory deleted the ktheory:fastly-log-processor branch Feb 18, 2016

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment