search

Shopify / shipit-engine

Deployment coordination
https://shopify.engineering/introducing-shipit
MIT License
1.42k stars 145 forks source link

Undefined method data for Nil GithubSyncJob #816

Closed btoconnor closed 6 years ago

btoconnor commented 6 years ago

After setting up shipit on localhost, I'm trying to kick the tires to see if this is a good fit for our org. After setting up the github app, putting the various details into the configuration file and navigating to the application on localhost, whenever the app tries to sync to GitHub we see this:

2018-10-05T20:06:49.494Z 23685 TID-ovdousoy5 WARN: {"context":"Job raised exception","job":{"class":"ActiveJob::QueueAdapters::SidekiqAdapter::JobWrapper","wrapped":"Shipit::GithubSyncJob","queue":"default","args":[{"job_class":"Shipit::GithubSyncJob","job_id":"69ff00e6-882b-4cf5-89f9-879618930104","provider_job_id":null,"queue_name":"default","priority":null,"arguments":[{"stack_id":1,"_aj_symbol_keys":["stack_id"]}],"executions":0,"locale":"en"}],"retry":true,"jid":"bab64f2d1375b94bd5dea146","created_at":1538769612.748343,"enqueued_at":1538770008.6277819,"error_message":"undefined method `data' for nil:NilClass","error_class":"NoMethodError","failed_at":1538769619.032265,"retry_count":3,"retried_at":1538769840.457341},"jobstr":"{\"class\":\"ActiveJob::QueueAdapters::SidekiqAdapter::JobWrapper\",\"wrapped\":\"Shipit::GithubSyncJob\",\"queue\":\"default\",\"args\":[{\"job_class\":\"Shipit::GithubSyncJob\",\"job_id\":\"69ff00e6-882b-4cf5-89f9-879618930104\",\"provider_job_id\":null,\"queue_name\":\"default\",\"priority\":null,\"arguments\":[{\"stack_id\":1,\"_aj_symbol_keys\":[\"stack_id\"]}],\"executions\":0,\"locale\":\"en\"}],\"retry\":true,\"jid\":\"bab64f2d1375b94bd5dea146\",\"created_at\":1538769612.748343,\"enqueued_at\":1538770008.6277819,\"error_message\":\"undefined method `data' for nil:NilClass\",\"error_class\":\"NoMethodError\",\"failed_at\":1538769619.032265,\"retry_count\":3,\"retried_at\":1538769840.457341}"}
2018-10-05T20:06:49.494Z 23685 TID-ovdousoy5 WARN: NoMethodError: undefined method `data' for nil:NilClass

I set up a stack on my localhost application pointing to the appropriate github repository, and authorized the app on my account when I first viewed the app.

We have placed the GH App id, the installation id, the private key, the oauth values all into secrets.yml in the development environment.

Any idea what we're doing wrong?

casperisfine commented 6 years ago

Hum, that error is indicative of an API call to GitHub failing, but it's hard to tell which one exactly without an actual backtrace.

nathancolgate commented 6 years ago

We're seeing the same thing in development. Here is our backtrace:

sidekiq_1  | 2018-10-10T15:09:02.825Z 1 TID-pez0h Shipit::GithubSyncJob JID-995a0887785462338c0b4aa6 INFO: start
sidekiq_1  | [ActiveJob] [Shipit::GithubSyncJob] [9be857cd-aa28-4446-b45c-5b93e671a034] Performing Shipit::GithubSyncJob (Job ID: 9be857cd-aa28-4446-b45c-5b93e671a034) from Sidekiq(default) with arguments: {:stack_id=>1}
sidekiq_1  | [ActiveJob] [Shipit::GithubSyncJob] [9be857cd-aa28-4446-b45c-5b93e671a034] [Redis] command=SETNX args="Shipit::GithubSyncJob-{\"stack_id\"=>1, \"_aj_symbol_keys\"=>[\"stack_id\"]}" "1539184203.83349"
sidekiq_1  | [ActiveJob] [Shipit::GithubSyncJob] [9be857cd-aa28-4446-b45c-5b93e671a034] [Redis] call_time=2.49 ms
sidekiq_1  | [ActiveJob] [Shipit::GithubSyncJob] [9be857cd-aa28-4446-b45c-5b93e671a034]   Shipit::Stack Load (1.5ms)  SELECT  "stacks".* FROM "stacks" WHERE "stacks"."id" = $1 LIMIT $2  [["id", 1], ["LIMIT", 1]]
sidekiq_1  | [ActiveJob] [Shipit::GithubSyncJob] [9be857cd-aa28-4446-b45c-5b93e671a034] HTTP Cache: [GET /repos/brandnewbox/client-project/commits?sha=master] miss, store
sidekiq_1  | [ActiveJob] [Shipit::GithubSyncJob] [9be857cd-aa28-4446-b45c-5b93e671a034] [Redis] command=DEL args="Shipit::GithubSyncJob-{\"stack_id\"=>1, \"_aj_symbol_keys\"=>[\"stack_id\"]}"
sidekiq_1  | [ActiveJob] [Shipit::GithubSyncJob] [9be857cd-aa28-4446-b45c-5b93e671a034] [Redis] call_time=0.92 ms
sidekiq_1  | [ActiveJob] [Shipit::GithubSyncJob] [9be857cd-aa28-4446-b45c-5b93e671a034] Error performing Shipit::GithubSyncJob (Job ID: 9be857cd-aa28-4446-b45c-5b93e671a034) from Sidekiq(default) in 2418.42ms: NoMethodError (undefined method `data' for nil:NilClass):
sidekiq_1  | /usr/local/bundle/bundler/gems/shipit-engine-5cb3dfdabfb9/lib/shipit/octokit_iterator.rb:18:in `block in each'
sidekiq_1  | /usr/local/bundle/bundler/gems/shipit-engine-5cb3dfdabfb9/lib/shipit/octokit_iterator.rb:17:in `loop'
sidekiq_1  | /usr/local/bundle/bundler/gems/shipit-engine-5cb3dfdabfb9/lib/shipit/octokit_iterator.rb:17:in `each'
sidekiq_1  | /usr/local/bundle/bundler/gems/shipit-engine-5cb3dfdabfb9/lib/shipit/first_parent_commits_iterator.rb:5:in `each'
sidekiq_1  | /usr/local/bundle/bundler/gems/shipit-engine-5cb3dfdabfb9/app/jobs/shipit/github_sync_job.rb:35:in `each_with_index'
sidekiq_1  | /usr/local/bundle/bundler/gems/shipit-engine-5cb3dfdabfb9/app/jobs/shipit/github_sync_job.rb:35:in `fetch_missing_commits'
sidekiq_1  | /usr/local/bundle/bundler/gems/shipit-engine-5cb3dfdabfb9/app/jobs/shipit/github_sync_job.rb:15:in `block in perform'
sidekiq_1  | /usr/local/bundle/bundler/gems/shipit-engine-5cb3dfdabfb9/app/jobs/shipit/github_sync_job.rb:49:in `handle_github_errors'
sidekiq_1  | /usr/local/bundle/bundler/gems/shipit-engine-5cb3dfdabfb9/app/jobs/shipit/github_sync_job.rb:14:in `perform'
sidekiq_1  | /usr/local/bundle/gems/activejob-5.1.6/lib/active_job/execution.rb:37:in `block in perform_now'
sidekiq_1  | /usr/local/bundle/gems/activesupport-5.1.6/lib/active_support/callbacks.rb:108:in `block in run_callbacks'
sidekiq_1  | /usr/local/bundle/gems/redis-objects-1.2.1/lib/redis/lock.rb:58:in `lock'
sidekiq_1  | /usr/local/bundle/bundler/gems/shipit-engine-5cb3dfdabfb9/app/jobs/shipit/background_job/unique.rb:20:in `acquire_lock'
sidekiq_1  | /usr/local/bundle/bundler/gems/shipit-engine-5cb3dfdabfb9/app/jobs/shipit/background_job/unique.rb:8:in `block (2 levels) in <module:Unique>'
sidekiq_1  | /usr/local/bundle/gems/activesupport-5.1.6/lib/active_support/callbacks.rb:117:in `instance_exec'
sidekiq_1  | /usr/local/bundle/gems/activesupport-5.1.6/lib/active_support/callbacks.rb:117:in `block in run_callbacks'
sidekiq_1  | /usr/local/bundle/gems/i18n-1.0.1/lib/i18n.rb:284:in `with_locale'
sidekiq_1  | /usr/local/bundle/gems/activejob-5.1.6/lib/active_job/translation.rb:7:in `block (2 levels) in <module:Translation>'
sidekiq_1  | /usr/local/bundle/gems/activesupport-5.1.6/lib/active_support/callbacks.rb:117:in `instance_exec'
sidekiq_1  | /usr/local/bundle/gems/activesupport-5.1.6/lib/active_support/callbacks.rb:117:in `block in run_callbacks'
sidekiq_1  | /usr/local/bundle/gems/activejob-5.1.6/lib/active_job/logging.rb:24:in `block (4 levels) in <module:Logging>'
sidekiq_1  | /usr/local/bundle/gems/activesupport-5.1.6/lib/active_support/notifications.rb:166:in `block in instrument'
sidekiq_1  | /usr/local/bundle/gems/activesupport-5.1.6/lib/active_support/notifications/instrumenter.rb:21:in `instrument'
sidekiq_1  | /usr/local/bundle/gems/activesupport-5.1.6/lib/active_support/notifications.rb:166:in `instrument'
sidekiq_1  | /usr/local/bundle/gems/activejob-5.1.6/lib/active_job/logging.rb:23:in `block (3 levels) in <module:Logging>'
sidekiq_1  | /usr/local/bundle/gems/activejob-5.1.6/lib/active_job/logging.rb:44:in `block in tag_logger'
sidekiq_1  | /usr/local/bundle/gems/activesupport-5.1.6/lib/active_support/tagged_logging.rb:69:in `block in tagged'
sidekiq_1  | /usr/local/bundle/gems/activesupport-5.1.6/lib/active_support/tagged_logging.rb:26:in `tagged'
sidekiq_1  | /usr/local/bundle/gems/activesupport-5.1.6/lib/active_support/tagged_logging.rb:69:in `tagged'
sidekiq_1  | /usr/local/bundle/gems/activejob-5.1.6/lib/active_job/logging.rb:44:in `tag_logger'
sidekiq_1  | /usr/local/bundle/gems/activejob-5.1.6/lib/active_job/logging.rb:20:in `block (2 levels) in <module:Logging>'
sidekiq_1  | /usr/local/bundle/gems/activesupport-5.1.6/lib/active_support/callbacks.rb:117:in `instance_exec'
sidekiq_1  | /usr/local/bundle/gems/activesupport-5.1.6/lib/active_support/callbacks.rb:117:in `block in run_callbacks'
sidekiq_1  | /usr/local/bundle/gems/activesupport-5.1.6/lib/active_support/callbacks.rb:135:in `run_callbacks'
sidekiq_1  | /usr/local/bundle/gems/activejob-5.1.6/lib/active_job/execution.rb:33:in `perform_now'
sidekiq_1  | /usr/local/bundle/gems/activejob-5.1.6/lib/active_job/execution.rb:22:in `block in execute'
sidekiq_1  | /usr/local/bundle/gems/activesupport-5.1.6/lib/active_support/callbacks.rb:108:in `block in run_callbacks'
sidekiq_1  | /usr/local/bundle/gems/activejob-5.1.6/lib/active_job/railtie.rb:26:in `block (4 levels) in <class:Railtie>'
sidekiq_1  | /usr/local/bundle/gems/activesupport-5.1.6/lib/active_support/execution_wrapper.rb:85:in `wrap'
sidekiq_1  | /usr/local/bundle/gems/activesupport-5.1.6/lib/active_support/reloader.rb:68:in `block in wrap'
sidekiq_1  | /usr/local/bundle/gems/activesupport-5.1.6/lib/active_support/execution_wrapper.rb:81:in `wrap'
sidekiq_1  | /usr/local/bundle/gems/activesupport-5.1.6/lib/active_support/reloader.rb:67:in `wrap'
sidekiq_1  | /usr/local/bundle/gems/activejob-5.1.6/lib/active_job/railtie.rb:25:in `block (3 levels) in <class:Railtie>'
sidekiq_1  | /usr/local/bundle/gems/activesupport-5.1.6/lib/active_support/callbacks.rb:117:in `instance_exec'
sidekiq_1  | /usr/local/bundle/gems/activesupport-5.1.6/lib/active_support/callbacks.rb:117:in `block in run_callbacks'
sidekiq_1  | /usr/local/bundle/gems/activesupport-5.1.6/lib/active_support/callbacks.rb:135:in `run_callbacks'
sidekiq_1  | /usr/local/bundle/gems/activejob-5.1.6/lib/active_job/execution.rb:20:in `execute'
sidekiq_1  | /usr/local/bundle/gems/activejob-5.1.6/lib/active_job/queue_adapters/sidekiq_adapter.rb:40:in `perform'
sidekiq_1  | /usr/local/bundle/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:187:in `execute_job'
sidekiq_1  | /usr/local/bundle/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:169:in `block (2 levels) in process'
sidekiq_1  | /usr/local/bundle/gems/sidekiq-5.1.3/lib/sidekiq/middleware/chain.rb:128:in `block in invoke'
sidekiq_1  | /usr/local/bundle/gems/sidekiq-5.1.3/lib/sidekiq/middleware/chain.rb:133:in `invoke'
sidekiq_1  | /usr/local/bundle/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:168:in `block in process'
sidekiq_1  | /usr/local/bundle/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:139:in `block (6 levels) in dispatch'
sidekiq_1  | /usr/local/bundle/gems/sidekiq-5.1.3/lib/sidekiq/job_retry.rb:98:in `local'
sidekiq_1  | /usr/local/bundle/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:138:in `block (5 levels) in dispatch'
sidekiq_1  | /usr/local/bundle/gems/sidekiq-5.1.3/lib/sidekiq/rails.rb:42:in `block in call'
sidekiq_1  | /usr/local/bundle/gems/activesupport-5.1.6/lib/active_support/execution_wrapper.rb:85:in `wrap'
sidekiq_1  | /usr/local/bundle/gems/activesupport-5.1.6/lib/active_support/reloader.rb:68:in `block in wrap'
sidekiq_1  | /usr/local/bundle/gems/activesupport-5.1.6/lib/active_support/execution_wrapper.rb:85:in `wrap'
sidekiq_1  | /usr/local/bundle/gems/activesupport-5.1.6/lib/active_support/reloader.rb:67:in `wrap'
sidekiq_1  | /usr/local/bundle/gems/sidekiq-5.1.3/lib/sidekiq/rails.rb:41:in `call'
sidekiq_1  | /usr/local/bundle/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:134:in `block (4 levels) in dispatch'
sidekiq_1  | /usr/local/bundle/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:199:in `stats'
sidekiq_1  | /usr/local/bundle/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:129:in `block (3 levels) in dispatch'
sidekiq_1  | /usr/local/bundle/gems/sidekiq-5.1.3/lib/sidekiq/job_logger.rb:8:in `call'
sidekiq_1  | /usr/local/bundle/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:128:in `block (2 levels) in dispatch'
sidekiq_1  | /usr/local/bundle/gems/sidekiq-5.1.3/lib/sidekiq/job_retry.rb:73:in `global'
sidekiq_1  | /usr/local/bundle/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:127:in `block in dispatch'
sidekiq_1  | /usr/local/bundle/gems/sidekiq-5.1.3/lib/sidekiq/logging.rb:48:in `with_context'
sidekiq_1  | /usr/local/bundle/gems/sidekiq-5.1.3/lib/sidekiq/logging.rb:42:in `with_job_hash_context'
sidekiq_1  | /usr/local/bundle/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:126:in `dispatch'
sidekiq_1  | /usr/local/bundle/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:167:in `process'
sidekiq_1  | /usr/local/bundle/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:85:in `process_one'
sidekiq_1  | /usr/local/bundle/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:73:in `run'
sidekiq_1  | /usr/local/bundle/gems/sidekiq-5.1.3/lib/sidekiq/util.rb:16:in `watchdog'
sidekiq_1  | /usr/local/bundle/gems/sidekiq-5.1.3/lib/sidekiq/util.rb:25:in `block in safe_thread'
sidekiq_1  | 2018-10-10T15:09:05.255Z 1 TID-pez0h Shipit::GithubSyncJob JID-995a0887785462338c0b4aa6 INFO: fail: 2.43 sec

Our @stack.github_commits is returning an array of 30 objects, but somehow when it is passed to the iterator, it becomes nil.

casperisfine commented 6 years ago

@nathancolgate looks like it could be due to https://github.com/Shopify/shipit-engine/commit/82c444da5f77fb5aa51c281d5ba08eac95808022

Can you try the latest release?

nathancolgate commented 6 years ago

@casperisfine We updated to:

gem 'shipit-engine', github: 'Shopify/shipit-engine', :tag => 'v0.25.0'

Looks like we're getting the same error:

sidekiq_1       | 2018-10-10T19:45:29.702Z 1 TID-orecv9e7d Shipit::GithubSyncJob JID-04ec08600ff538688c1d062a INFO: start
sidekiq_1       | [ActiveJob] [Shipit::GithubSyncJob] [c3858eab-3313-4f93-bda3-d98782e9eb93] Performing Shipit::GithubSyncJob (Job ID: c3858eab-3313-4f93-bda3-d98782e9eb93) from Sidekiq(default) with arguments: {:stack_id=>1}
sidekiq_1       | [ActiveJob] [Shipit::GithubSyncJob] [c3858eab-3313-4f93-bda3-d98782e9eb93] [Redis] command=SETNX args="Shipit::GithubSyncJob-{\"stack_id\"=>1, \"_aj_symbol_keys\"=>[\"stack_id\"]}" "1539200790.7113562"
sidekiq_1       | [ActiveJob] [Shipit::GithubSyncJob] [c3858eab-3313-4f93-bda3-d98782e9eb93] [Redis] call_time=0.71 ms
sidekiq_1       | [ActiveJob] [Shipit::GithubSyncJob] [c3858eab-3313-4f93-bda3-d98782e9eb93]   Shipit::Stack Load (1.2ms)  SELECT  "stacks".* FROM "stacks" WHERE "stacks"."id" = $1 LIMIT $2  [["id", 1], ["LIMIT", 1]]
sidekiq_1       | [ActiveJob] [Shipit::GithubSyncJob] [c3858eab-3313-4f93-bda3-d98782e9eb93] HTTP Cache: [POST /installations/removed/access_tokens] unacceptable, delete
sidekiq_1       | [ActiveJob] [Shipit::GithubSyncJob] [c3858eab-3313-4f93-bda3-d98782e9eb93] HTTP Cache: [POST /installations/removed/access_tokens] unacceptable, delete
sidekiq_1       | [ActiveJob] [Shipit::GithubSyncJob] [c3858eab-3313-4f93-bda3-d98782e9eb93] HTTP Cache: [POST /installations/removed/access_tokens] unacceptable, delete
sidekiq_1       | [ActiveJob] [Shipit::GithubSyncJob] [c3858eab-3313-4f93-bda3-d98782e9eb93] HTTP Cache: [GET /repos/brandnewbox/client-project/commits?sha=master] miss, store
sidekiq_1       | [ActiveJob] [Shipit::GithubSyncJob] [c3858eab-3313-4f93-bda3-d98782e9eb93] HTTP Cache: [POST /installations/removed/access_tokens] unacceptable, delete
sidekiq_1       | [ActiveJob] [Shipit::GithubSyncJob] [c3858eab-3313-4f93-bda3-d98782e9eb93] HTTP Cache: [POST /installations/removed/access_tokens] unacceptable, delete
sidekiq_1       | [ActiveJob] [Shipit::GithubSyncJob] [c3858eab-3313-4f93-bda3-d98782e9eb93] [Redis] command=DEL args="Shipit::GithubSyncJob-{\"stack_id\"=>1, \"_aj_symbol_keys\"=>[\"stack_id\"]}"
sidekiq_1       | [ActiveJob] [Shipit::GithubSyncJob] [c3858eab-3313-4f93-bda3-d98782e9eb93] [Redis] call_time=0.91 ms
sidekiq_1       | [ActiveJob] [Shipit::GithubSyncJob] [c3858eab-3313-4f93-bda3-d98782e9eb93] Error performing Shipit::GithubSyncJob (Job ID: c3858eab-3313-4f93-bda3-d98782e9eb93) from Sidekiq(default) in 1662.69ms: NoMethodError (undefined method `data' for nil:NilClass):
sidekiq_1       | /usr/local/bundle/bundler/gems/shipit-engine-0d29c647f25b/lib/shipit/octokit_iterator.rb:18:in `block in each'
sidekiq_1       | /usr/local/bundle/bundler/gems/shipit-engine-0d29c647f25b/lib/shipit/octokit_iterator.rb:17:in `loop'
sidekiq_1       | /usr/local/bundle/bundler/gems/shipit-engine-0d29c647f25b/lib/shipit/octokit_iterator.rb:17:in `each'
sidekiq_1       | /usr/local/bundle/bundler/gems/shipit-engine-0d29c647f25b/lib/shipit/first_parent_commits_iterator.rb:5:in `each'
sidekiq_1       | /usr/local/bundle/bundler/gems/shipit-engine-0d29c647f25b/app/jobs/shipit/github_sync_job.rb:35:in `each_with_index'
sidekiq_1       | /usr/local/bundle/bundler/gems/shipit-engine-0d29c647f25b/app/jobs/shipit/github_sync_job.rb:35:in `fetch_missing_commits'
sidekiq_1       | /usr/local/bundle/bundler/gems/shipit-engine-0d29c647f25b/app/jobs/shipit/github_sync_job.rb:15:in `block in perform'
sidekiq_1       | /usr/local/bundle/bundler/gems/shipit-engine-0d29c647f25b/app/jobs/shipit/github_sync_job.rb:49:in `handle_github_errors'
sidekiq_1       | /usr/local/bundle/bundler/gems/shipit-engine-0d29c647f25b/app/jobs/shipit/github_sync_job.rb:14:in `perform'
sidekiq_1       | /usr/local/bundle/gems/activejob-5.1.6/lib/active_job/execution.rb:37:in `block in perform_now'
sidekiq_1       | /usr/local/bundle/gems/activesupport-5.1.6/lib/active_support/callbacks.rb:108:in `block in run_callbacks'
sidekiq_1       | /usr/local/bundle/gems/redis-objects-1.2.1/lib/redis/lock.rb:58:in `lock'
sidekiq_1       | /usr/local/bundle/bundler/gems/shipit-engine-0d29c647f25b/app/jobs/shipit/background_job/unique.rb:20:in `acquire_lock'
sidekiq_1       | /usr/local/bundle/bundler/gems/shipit-engine-0d29c647f25b/app/jobs/shipit/background_job/unique.rb:8:in `block (2 levels) in <module:Unique>'
sidekiq_1       | /usr/local/bundle/gems/activesupport-5.1.6/lib/active_support/callbacks.rb:117:in `instance_exec'
sidekiq_1       | /usr/local/bundle/gems/activesupport-5.1.6/lib/active_support/callbacks.rb:117:in `block in run_callbacks'
sidekiq_1       | /usr/local/bundle/gems/i18n-1.0.1/lib/i18n.rb:284:in `with_locale'
sidekiq_1       | /usr/local/bundle/gems/activejob-5.1.6/lib/active_job/translation.rb:7:in `block (2 levels) in <module:Translation>'
sidekiq_1       | /usr/local/bundle/gems/activesupport-5.1.6/lib/active_support/callbacks.rb:117:in `instance_exec'
sidekiq_1       | /usr/local/bundle/gems/activesupport-5.1.6/lib/active_support/callbacks.rb:117:in `block in run_callbacks'
sidekiq_1       | /usr/local/bundle/gems/activejob-5.1.6/lib/active_job/logging.rb:24:in `block (4 levels) in <module:Logging>'
sidekiq_1       | /usr/local/bundle/gems/activesupport-5.1.6/lib/active_support/notifications.rb:166:in `block in instrument'
sidekiq_1       | /usr/local/bundle/gems/activesupport-5.1.6/lib/active_support/notifications/instrumenter.rb:21:in `instrument'
sidekiq_1       | /usr/local/bundle/gems/activesupport-5.1.6/lib/active_support/notifications.rb:166:in `instrument'
sidekiq_1       | /usr/local/bundle/gems/activejob-5.1.6/lib/active_job/logging.rb:23:in `block (3 levels) in <module:Logging>'
sidekiq_1       | /usr/local/bundle/gems/activejob-5.1.6/lib/active_job/logging.rb:44:in `block in tag_logger'
sidekiq_1       | /usr/local/bundle/gems/activesupport-5.1.6/lib/active_support/tagged_logging.rb:69:in `block in tagged'
sidekiq_1       | /usr/local/bundle/gems/activesupport-5.1.6/lib/active_support/tagged_logging.rb:26:in `tagged'
sidekiq_1       | /usr/local/bundle/gems/activesupport-5.1.6/lib/active_support/tagged_logging.rb:69:in `tagged'
sidekiq_1       | /usr/local/bundle/gems/activejob-5.1.6/lib/active_job/logging.rb:44:in `tag_logger'
sidekiq_1       | /usr/local/bundle/gems/activejob-5.1.6/lib/active_job/logging.rb:20:in `block (2 levels) in <module:Logging>'
sidekiq_1       | /usr/local/bundle/gems/activesupport-5.1.6/lib/active_support/callbacks.rb:117:in `instance_exec'
sidekiq_1       | /usr/local/bundle/gems/activesupport-5.1.6/lib/active_support/callbacks.rb:117:in `block in run_callbacks'
sidekiq_1       | /usr/local/bundle/gems/activesupport-5.1.6/lib/active_support/callbacks.rb:135:in `run_callbacks'
sidekiq_1       | /usr/local/bundle/gems/activejob-5.1.6/lib/active_job/execution.rb:33:in `perform_now'
sidekiq_1       | /usr/local/bundle/gems/activejob-5.1.6/lib/active_job/execution.rb:22:in `block in execute'
sidekiq_1       | /usr/local/bundle/gems/activesupport-5.1.6/lib/active_support/callbacks.rb:108:in `block in run_callbacks'
sidekiq_1       | /usr/local/bundle/gems/activejob-5.1.6/lib/active_job/railtie.rb:26:in `block (4 levels) in <class:Railtie>'
sidekiq_1       | /usr/local/bundle/gems/activesupport-5.1.6/lib/active_support/execution_wrapper.rb:85:in `wrap'
sidekiq_1       | /usr/local/bundle/gems/activesupport-5.1.6/lib/active_support/reloader.rb:68:in `block in wrap'
sidekiq_1       | /usr/local/bundle/gems/activesupport-5.1.6/lib/active_support/execution_wrapper.rb:81:in `wrap'
sidekiq_1       | /usr/local/bundle/gems/activesupport-5.1.6/lib/active_support/reloader.rb:67:in `wrap'
sidekiq_1       | /usr/local/bundle/gems/activejob-5.1.6/lib/active_job/railtie.rb:25:in `block (3 levels) in <class:Railtie>'
sidekiq_1       | /usr/local/bundle/gems/activesupport-5.1.6/lib/active_support/callbacks.rb:117:in `instance_exec'
sidekiq_1       | /usr/local/bundle/gems/activesupport-5.1.6/lib/active_support/callbacks.rb:117:in `block in run_callbacks'
sidekiq_1       | /usr/local/bundle/gems/activesupport-5.1.6/lib/active_support/callbacks.rb:135:in `run_callbacks'
sidekiq_1       | /usr/local/bundle/gems/activejob-5.1.6/lib/active_job/execution.rb:20:in `execute'
sidekiq_1       | /usr/local/bundle/gems/activejob-5.1.6/lib/active_job/queue_adapters/sidekiq_adapter.rb:40:in `perform'
sidekiq_1       | /usr/local/bundle/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:187:in `execute_job'
sidekiq_1       | /usr/local/bundle/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:169:in `block (2 levels) in process'
sidekiq_1       | /usr/local/bundle/gems/sidekiq-5.1.3/lib/sidekiq/middleware/chain.rb:128:in `block in invoke'
sidekiq_1       | /usr/local/bundle/gems/sidekiq-5.1.3/lib/sidekiq/middleware/chain.rb:133:in `invoke'
sidekiq_1       | /usr/local/bundle/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:168:in `block in process'
sidekiq_1       | /usr/local/bundle/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:139:in `block (6 levels) in dispatch'
sidekiq_1       | /usr/local/bundle/gems/sidekiq-5.1.3/lib/sidekiq/job_retry.rb:98:in `local'
sidekiq_1       | /usr/local/bundle/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:138:in `block (5 levels) in dispatch'
sidekiq_1       | /usr/local/bundle/gems/sidekiq-5.1.3/lib/sidekiq/rails.rb:42:in `block in call'
sidekiq_1       | /usr/local/bundle/gems/activesupport-5.1.6/lib/active_support/execution_wrapper.rb:85:in `wrap'
sidekiq_1       | /usr/local/bundle/gems/activesupport-5.1.6/lib/active_support/reloader.rb:68:in `block in wrap'
sidekiq_1       | /usr/local/bundle/gems/activesupport-5.1.6/lib/active_support/execution_wrapper.rb:85:in `wrap'
sidekiq_1       | /usr/local/bundle/gems/activesupport-5.1.6/lib/active_support/reloader.rb:67:in `wrap'
sidekiq_1       | /usr/local/bundle/gems/sidekiq-5.1.3/lib/sidekiq/rails.rb:41:in `call'
sidekiq_1       | /usr/local/bundle/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:134:in `block (4 levels) in dispatch'
sidekiq_1       | /usr/local/bundle/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:199:in `stats'
sidekiq_1       | /usr/local/bundle/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:129:in `block (3 levels) in dispatch'
sidekiq_1       | /usr/local/bundle/gems/sidekiq-5.1.3/lib/sidekiq/job_logger.rb:8:in `call'
sidekiq_1       | /usr/local/bundle/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:128:in `block (2 levels) in dispatch'
sidekiq_1       | /usr/local/bundle/gems/sidekiq-5.1.3/lib/sidekiq/job_retry.rb:73:in `global'
sidekiq_1       | /usr/local/bundle/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:127:in `block in dispatch'
sidekiq_1       | /usr/local/bundle/gems/sidekiq-5.1.3/lib/sidekiq/logging.rb:48:in `with_context'
sidekiq_1       | /usr/local/bundle/gems/sidekiq-5.1.3/lib/sidekiq/logging.rb:42:in `with_job_hash_context'
sidekiq_1       | /usr/local/bundle/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:126:in `dispatch'
sidekiq_1       | /usr/local/bundle/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:167:in `process'
sidekiq_1       | /usr/local/bundle/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:85:in `process_one'
sidekiq_1       | /usr/local/bundle/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:73:in `run'
sidekiq_1       | /usr/local/bundle/gems/sidekiq-5.1.3/lib/sidekiq/util.rb:16:in `watchdog'
sidekiq_1       | /usr/local/bundle/gems/sidekiq-5.1.3/lib/sidekiq/util.rb:25:in `block in safe_thread'
sidekiq_1       | 2018-10-10T19:45:31.378Z 1 TID-orecv9e7d Shipit::GithubSyncJob JID-04ec08600ff538688c1d062a INFO: fail: 1.675 sec
casperisfine commented 6 years ago

Hum, the 5 POST /installations/177213/access_tokens suggest you might have authentication issues.

I'd suggest trying some API requests from a rails console:

> Shipit.github.api.get('/')

> Shipit.github.api.commits('brandnewbox/aecom-rosetta', sha: 'master')

Sorry for the messy advices, but unless I can repro, all I can offer is vague directions.

btoconnor commented 6 years ago

I receive this when I run the first command:

HTTP Cache: [POST /installations/220551/access_tokens] unacceptable, delete
HTTP Cache: [GET /] miss, store
=> {:current_user_url=>"https://api.github.com/user",
 :current_user_authorizations_html_url=>
  "https://github.com/settings/connections/applications{/client_id}",
 :authorizations_url=>"https://api.github.com/authorizations",
 :code_search_url=>
  "https://api.github.com/search/code?q={query}{&page,per_page,sort,order}",
 :commit_search_url=>
  "https://api.github.com/search/commits?q={query}{&page,per_page,sort,order}",
 :emails_url=>"https://api.github.com/user/emails",
 :emojis_url=>"https://api.github.com/emojis",
 :events_url=>"https://api.github.com/events",
 :feeds_url=>"https://api.github.com/feeds",
 :followers_url=>"https://api.github.com/user/followers",
 :following_url=>"https://api.github.com/user/following{/target}",
 :gists_url=>"https://api.github.com/gists{/gist_id}",
 :hub_url=>"https://api.github.com/hub",
 :issue_search_url=>
  "https://api.github.com/search/issues?q={query}{&page,per_page,sort,order}",
 :issues_url=>"https://api.github.com/issues",
 :keys_url=>"https://api.github.com/user/keys",
 :notifications_url=>"https://api.github.com/notifications",
 :organization_repositories_url=>
  "https://api.github.com/orgs/{org}/repos{?type,page,per_page,sort}",
 :organization_url=>"https://api.github.com/orgs/{org}",
 :public_gists_url=>"https://api.github.com/gists/public",
 :rate_limit_url=>"https://api.github.com/rate_limit",
 :repository_url=>"https://api.github.com/repos/{owner}/{repo}",
 :repository_search_url=>
  "https://api.github.com/search/repositories?q={query}{&page,per_page,sort,order}",
 :current_user_repositories_url=>
  "https://api.github.com/user/repos{?type,page,per_page,sort}",
 :starred_url=>"https://api.github.com/user/starred{/owner}{/repo}",
 :starred_gists_url=>"https://api.github.com/gists/starred",
 :team_url=>"https://api.github.com/teams",
 :user_url=>"https://api.github.com/users/{user}",
 :user_organizations_url=>"https://api.github.com/user/orgs",
 :user_repositories_url=>
  "https://api.github.com/users/{user}/repos{?type,page,per_page,sort}",
 :user_search_url=>
  "https://api.github.com/search/users?q={query}{&page,per_page,sort,order}"}

I've confirmed 220551 is the installation ID of our application and that the relevant app ID is also correct in our config/secrets.yml file. We also have the private key in the file as well. Additionally I've confirmed the OAuth credentials in the file as well.

nathancolgate commented 6 years ago

@btoconnor That's the same error we're getting. I think it has something to do with the unacceptable, delete response from Faraday-Http-Cache. But it's been a hard one to debug.

I'm planning on working on it again today.

casperisfine commented 6 years ago

I think I have an idea of what might be happening. I'll try to repro locally based on that theory.

casperisfine commented 6 years ago

Yes! I'm able to repo.

So this is triggered by a non functional cache. The GitHub access token is stored in cache, and fetched back on every request. If it's missing a new client is instantiated which cause this particular code path to fail.

I'll try to produce a fix ASAP (even though ultimately I'd recommend to fix the cache config).

btoconnor commented 6 years ago

Fantastic! Let me know if there's anything else I can provide to help out.

As a follow up - I have no issues "fixing" the cache config, but I'm not sure what I'm fixing it to. This is a fresh rails repository setup just for this. Happy to modify whatever, but just not sure what Shipit is expecting here.

nathancolgate commented 6 years ago

@casperisfine Glad you were able to reproduce!

I agree with your direction. Here is the difference we're seeing between our production and development environments:

Development:

Rails.cache.clear
@github = Shipit::GitHubApp.new(Rails.application.secrets.github)
@github.token
#=> HTTP Cache: [POST /installations/177213/access_tokens] unacceptable, delete
=> "v1.8973588ff91e3b14c5de20fcb8a3ff6fafa77e28"
@github.token
#=> HTTP Cache: [POST /installations/177213/access_tokens] unacceptable, delete
=> "v1.bbcae7656e946f3ab95f04135ef7c10a9cb18d5e"

Production:

Rails.cache.clear
@github = Shipit::GitHubApp.new(Rails.application.secrets.github)
@github.token
#=> HTTP Cache: [POST /installations/145205/access_tokens] unacceptable, delete
=> "v1.8973588ff91e3b14c53e21fcb8a9ff6fafa77e28"
@github.token
#=> "v1.8973588ff91e3b14c53e21fcb8a9ff6fafa77e28"

It's the same response for both environments. The same endpoint. The same unacceptable, delete message from Faraday. The same response of a v1.something string.

But as you mentioned the non functional cache in development forces the application to make the request over and over again.

What's interesting is that I would kind of expect that to work, as the response back from the server is still a valid v1.something string.

casperisfine commented 6 years ago

This branch should fix it: https://github.com/Shopify/shipit-engine/pull/818

Would you mind trying it out just to be sure?

nathancolgate commented 6 years ago

Works great. Thanks so much!

irb(main):002:0> @github = Shipit::GitHubApp.new(Rails.application.secrets.github)
=> #<Shipit::GitHubApp:0x00000000057fd4d8 ... >
irb(main):003:0> @github.token
HTTP Cache: [POST /installations/177213/access_tokens] unacceptable, delete
=> "v1.d60...."
irb(main):004:0> @github.token
=> "v1.d60...."
casperisfine commented 6 years ago

Ok, I'll merge then.

btoconnor commented 6 years ago

That fixes it for me as well. Thanks for the quick help!