{"action":"created","issue":{"url":"https://api.github.com/repos/geminabox/geminabox/issues/202","labels_url":"https://api.github.com/repos/geminabox/geminabox/issues/202/labels{/name}","comments_url":"https://api.github.com/repos/geminabox/geminabox/issues/202/comments","events_url":"https://api.github.com/repos/geminabox/geminabox/issues/202/events","html_url":"https://github.com/geminabox/geminabox/issues/202","id":74436372,"number":202,"title":"Rubygems proxy race condition","user":{"login":"Primer42","id":555841,"avatar_url":"https://avatars.githubusercontent.com/u/555841?v=3","gravatar_id":"","url":"https://api.github.com/users/Primer42","html_url":"https://github.com/Primer42","followers_url":"https://api.github.com/users/Primer42/followers","following_url":"https://api.github.com/users/Primer42/following{/other_user}","gists_url":"https://api.github.com/users/Primer42/gists{/gist_id}","starred_url":"https://api.github.com/users/Primer42/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/Primer42/subscriptions","organizations_url":"https://api.github.com/users/Primer42/orgs","repos_url":"https://api.github.com/users/Primer42/repos","events_url":"https://api.github.com/users/Primer42/events{/privacy}","received_events_url":"https://api.github.com/users/Primer42/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"milestone":null,"comments":3,"created_at":"2015-05-08T17:28:40Z","updated_at":"2015-11-30T14:43:11Z","closed_at":null,"body":"Hello,\r\n\r\nWe're using geminabox with unicorn, behind an nginx reverse proxy.  We have the rubygems proxy configuration enabled.\r\n\r\nWe noticed that intermittently, calling `gem list --remote --clear-sources --source <our geminabox server> <gem name>` would hang, and never complete.\r\n\r\nWe saw the following log messages in the nginx error log:\r\n```\r\n2015/05/08 13:05:20 [error] 16851#0: *70457234 upstream prematurely closed connection while reading upstream, client: <ip address>, server: <geminabox server>, request: \"GET /latest_specs.4.8.gz HTTP/1.1\", upstream: \"https://127.0.0.1:7707/latest_specs.4.8.gz\", host: \"<geminabox server>\"\r\n```\r\nAnd the following in the unicorn error logs:\r\n```\r\nE, [2015-05-08T13:05:20.418185 #340] ERROR -- : app error: Content-Length header was 871233, but should be 458752 (Rack::Lint::LintError)\r\nE, [2015-05-08T13:05:20.418275 #340] ERROR -- : /opt/ruby/2.2.0/lib/ruby/gems/2.2.0/gems/rack-1.5.2/lib/rack/lint.rb:20:in `assert'\r\nE, [2015-05-08T13:05:20.418302 #340] ERROR -- : /opt/ruby/2.2.0/lib/ruby/gems/2.2.0/gems/rack-1.5.2/lib/rack/lint.rb:631:in `verify_content_length'\r\nE, [2015-05-08T13:05:20.418326 #340] ERROR -- : /opt/ruby/2.2.0/lib/ruby/gems/2.2.0/gems/rack-1.5.2/lib/rack/lint.rb:655:in `each'\r\nE, [2015-05-08T13:05:20.418349 #340] ERROR -- : /opt/ruby/2.2.0/lib/ruby/gems/2.2.0/gems/rack-1.5.2/lib/rack/body_proxy.rb:31:in `each'\r\nE, [2015-05-08T13:05:20.418372 #340] ERROR -- : /opt/ruby/2.2.0/lib/ruby/gems/2.2.0/gems/unicorn-4.8.3/lib/unicorn/http_response.rb:60:in `http_response_write'\r\nE, [2015-05-08T13:05:20.418395 #340] ERROR -- : /opt/ruby/2.2.0/lib/ruby/gems/2.2.0/gems/unicorn-4.8.3/lib/unicorn/http_server.rb:586:in `process_client'\r\nE, [2015-05-08T13:05:20.418417 #340] ERROR -- : /opt/ruby/2.2.0/lib/ruby/gems/2.2.0/gems/unicorn-4.8.3/lib/unicorn/http_server.rb:670:in `worker_loop'\r\nE, [2015-05-08T13:05:20.418440 #340] ERROR -- : /opt/ruby/2.2.0/lib/ruby/gems/2.2.0/gems/unicorn-4.8.3/lib/unicorn/http_server.rb:525:in `spawn_missing_workers'\r\nE, [2015-05-08T13:05:20.418462 #340] ERROR -- : /opt/ruby/2.2.0/lib/ruby/gems/2.2.0/gems/unicorn-4.8.3/lib/unicorn/http_server.rb:536:in `maintain_worker_count'\r\nE, [2015-05-08T13:05:20.418489 #340] ERROR -- : /opt/ruby/2.2.0/lib/ruby/gems/2.2.0/gems/unicorn-4.8.3/lib/unicorn/http_server.rb:294:in `join'\r\nE, [2015-05-08T13:05:20.418512 #340] ERROR -- : /opt/ruby/2.2.0/lib/ruby/gems/2.2.0/gems/unicorn-4.8.3/bin/unicorn:126:in `<top (required)>'\r\nE, [2015-05-08T13:05:20.418535 #340] ERROR -- : /opt/ruby/2.2.0/bin/unicorn:23:in `load'\r\nE, [2015-05-08T13:05:20.418557 #340] ERROR -- : /opt/ruby/2.2.0/bin/unicorn:23:in `<main>'\r\n```\r\n\r\nI did a `watch -n .1 ls -la /<geminabox data directory>/proxy` and noticed that the size of the `latest_specs.4.8.gz` file is switching between 0 and its correct size of ~870 KB every second or two, sometimes multiple times a second.  Less frequently, I saw the same thing happen to the `specs.4.8.gz` file.\r\n\r\nMy theory is that there is a race condition between the unicorn workers, where one worker must be trying to download a new copy of the `lastest_specs.4.8.gz` from rubygems, and before it completes another worker serves the partial file.\r\n\r\nI have looked at the proxy code, but have not been able to determine why geminabox is trying to update the file so frequently.\r\n\r\nCan anyone else reproduce this?\r\n\r\nThanks!"},"comment":{"url":"https://api.github.com/repos/geminabox/geminabox/issues/comments/160649325","html_url":"https://github.com/geminabox/geminabox/issues/202#issuecomment-160649325","issue_url":"https://api.github.com/repos/geminabox/geminabox/issues/202","id":160649325,"user":{"login":"JohnMorales","id":360409,"avatar_url":"https://avatars.githubusercontent.com/u/360409?v=3","gravatar_id":"","url":"https://api.github.com/users/JohnMorales","html_url":"https://github.com/JohnMorales","followers_url":"https://api.github.com/users/JohnMorales/followers","following_url":"https://api.github.com/users/JohnMorales/following{/other_user}","gists_url":"https://api.github.com/users/JohnMorales/gists{/gist_id}","starred_url":"https://api.github.com/users/JohnMorales/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/JohnMorales/subscriptions","organizations_url":"https://api.github.com/users/JohnMorales/orgs","repos_url":"https://api.github.com/users/JohnMorales/repos","events_url":"https://api.github.com/users/JohnMorales/events{/privacy}","received_events_url":"https://api.github.com/users/JohnMorales/received_events","type":"User","site_admin":false},"created_at":"2015-11-30T14:43:11Z","updated_at":"2015-11-30T14:43:11Z","body":"@Primer42, were you able to get to the bottom of this? I'm seeing the same error as well."}}