From 4a492767f2e74d39b749e66b8d3531287847a2bd Mon Sep 17 00:00:00 2001 From: Alexey Milovidov Date: Sun, 16 Aug 2026 23:17:35 +0000 Subject: [PATCH] Fix the event capture regression: poll all three pages of /events The crawler polled only page 1 of the Events API. GitHub does not spread event types evenly over the pages: page 1 carries the push / create / delete stream, and everything else - pull requests, issues, comments, stars, reviews, releases, forks - is only reachable on pages 2 and 3. Reading page 1 alone therefore captured pushes and silently dropped nearly everything else, which is the degradation reported in #310 and #320. Measured on the live API: of 4654 unique events observed over 78 seconds, 1995 of 1996 PushEvents came from page 1, while all 944 PullRequestEvents, all 434 IssueCommentEvents and all 225 WatchEvents came from pages 2 and 3. Reproduced against the live API with the previous code, 20 seconds of capture: 283 PushEvent, 13 CreateEvent, 3 DeleteEvent, 1 IssuesEvent and with this change, 2 minutes of capture, 16248 events and no duplicates: 10894 PushEvent 436 PullRequestReviewEvent 47 ForkEvent 2054 PullRequestEvent 385 CreateEvent 33 PublicEvent 868 IssueCommentEvent 349 PullRequestReviewComment 21 CommitCommentEvent 583 IssuesEvent 328 WatchEvent 15 MemberEvent 118 ReleaseEvent 4 DiscussionEvent 110 DeleteEvent 3 GollumEvent Changes: - poll pages 1..3, each on its own schedule, so a busy page 1 cannot delay the others. Page 4 is not fetched: the API refuses it with "pagination is limited for this resource"; - de-duplicate against a bounded set of recently seen event ids. The previous code compared only against the immediately preceding response, so an event that briefly dropped out of the window was archived twice; - restore the missed-records alarm. It tested `new_events.size >= PAGE_LIMIT`, and f1f4200 set PAGE_LIMIT to 500 while the API clamps per_page to 100, so the condition could never be true and the crawler ran saturated and silent. It is now per page, and rate-limited to one line a minute because page 1 is expected to saturate; - accept several tokens separated by commas, used round-robin. The polling rate above costs 14400 requests/hour, more than one user token allows; - back off when the remaining quota runs behind the window, and honour Retry-After on 403 and 429 instead of hammering through a throttle; - use conditional GETs with per-page ETags, from #317 by @emalaj-seq; - only report to StatHat when STATHATKEY is set, instead of raising on every cycle; - fix the git:// remotes in the Gemfile, also from #317. GitHub disabled the git:// protocol in 2022, so bundle install could not resolve them. Co-Authored-By: Claude Opus 5 (1M context) --- crawler/Gemfile | 4 +- crawler/Gemfile.lock | 4 +- crawler/README.md | 38 ++++++- crawler/crawler.rb | 235 +++++++++++++++++++++++++++++++++---------- 4 files changed, 223 insertions(+), 58 deletions(-) diff --git a/crawler/Gemfile b/crawler/Gemfile index e3d3279..5a15afd 100644 --- a/crawler/Gemfile +++ b/crawler/Gemfile @@ -1,7 +1,7 @@ source 'http://rubygems.org' -gem 'eventmachine', :git => 'git://github.com/eventmachine/eventmachine.git' -gem 'em-http-request', :git => 'git://github.com/igrigorik/em-http-request.git' +gem 'eventmachine', :git => 'https://github.com/eventmachine/eventmachine.git' +gem 'em-http-request', :git => 'https://github.com/igrigorik/em-http-request.git' gem 'yajl-ruby', :require => 'yajl' gem 'em-stathat' diff --git a/crawler/Gemfile.lock b/crawler/Gemfile.lock index aa0ea5c..73332a3 100644 --- a/crawler/Gemfile.lock +++ b/crawler/Gemfile.lock @@ -1,11 +1,11 @@ GIT - remote: git://github.com/eventmachine/eventmachine.git + remote: https://github.com/eventmachine/eventmachine.git revision: 98ff494aac2279af2675fd8dd49cc5f130f8b236 specs: eventmachine (1.2.5) GIT - remote: git://github.com/igrigorik/em-http-request.git + remote: https://github.com/igrigorik/em-http-request.git revision: 6061430336bd1421b25c2244d5b85e4cdfcfb3f7 specs: em-http-request (1.1.5) diff --git a/crawler/README.md b/crawler/README.md index d4fecda..915fc13 100644 --- a/crawler/README.md +++ b/crawler/README.md @@ -24,5 +24,39 @@ bundle install ## Run Crawler ```sh -bundle exec ruby crawler.rb -``` \ No newline at end of file +GITHUB_TOKEN=[,...] bundle exec ruby crawler.rb +``` + +### Why more than one token + +The Events API serves at most 100 events per request and refuses page 4 +(`pagination is limited for this resource`), so one poll can observe 300 events. +Event types are not spread evenly over those three pages: **page 1 carries the +push / create / delete stream, and everything else — pull requests, issues, +comments, stars, reviews, releases, forks — is only reachable on pages 2 and 3.** +Polling page 1 alone captures pushes and silently drops nearly everything else. + +Measured in 2026-08, page 1 replaces all 100 of its entries in well under a +second and pages 2 and 3 in one to two seconds, so all three are polled on +independent schedules. The defaults (`PAGE1_INTERVAL=0.5`, `PAGE23_INTERVAL=1.0`) +cost 4 requests/second — 14400/hour — and each response spends one unit of the +primary rate limit. That is more than the 5000/hour of a single user token, so +either give the crawler a GitHub App installation token (15000/hour) or pass +several user tokens separated by commas; they are used round-robin. + +Page 1 alone runs at over 190 events/second, which is faster than the API will +serve it to one client, so pushes cannot be captured completely at any affordable +polling rate. Pages 2 and 3 can. When a page returns 100 entries that are all +new, the window turned over completely between two polls and events in between +were lost; the crawler warns about it (at most once a minute per page) and counts +it in the per-minute summary. + +### Environment + +| Variable | Default | Meaning | +| --- | --- | --- | +| `GITHUB_TOKEN` | required | one token, or several separated by commas | +| `PAGE1_INTERVAL` | `0.5` | seconds between polls of page 1 | +| `PAGE23_INTERVAL` | `1.0` | seconds between polls of pages 2 and 3 | +| `SEEN_LIMIT` | `200000` | event ids remembered for de-duplication | +| `STATHATKEY` | unset | report event counts to StatHat if set | \ No newline at end of file diff --git a/crawler/crawler.rb b/crawler/crawler.rb index 78009d3..35a2727 100644 --- a/crawler/crawler.rb +++ b/crawler/crawler.rb @@ -12,7 +12,40 @@ ## Setup ## -PAGE_LIMIT = 500 +# GitHub caps per_page at 100 for /events (a larger value is silently clamped), +# and refuses page 4 with "pagination is limited for this resource", so a single +# poll can observe at most 3 * 100 events. +PAGE_LIMIT = 100 +PAGES = (1..3).to_a + +# Event types are not spread evenly over the pages: page 1 carries the push / +# create / delete stream, and everything else - pull requests, issues, comments, +# stars, reviews, releases, forks - is only reachable on pages 2 and 3. A crawler +# that reads page 1 alone therefore captures pushes and silently drops almost +# everything else. +# +# Measured turnover (2026-08): page 1 replaces all 100 entries in well under a +# second, pages 2 and 3 in one to two seconds. Every page is polled on its own +# schedule, so a busy page 1 cannot delay the others. +# +# The defaults cost 4 requests/second - 14400/hour, which one GitHub App +# installation (15000/hour) or three user tokens can serve. Page 1 alone runs at +# over 190 events/second, so pushes cannot be captured completely through this +# endpoint at any affordable polling rate; pages 2 and 3 can. +PAGE_INTERVALS = { + 1 => (ENV['PAGE1_INTERVAL'] || 0.5).to_f, + 2 => (ENV['PAGE23_INTERVAL'] || 1.0).to_f, + 3 => (ENV['PAGE23_INTERVAL'] || 1.0).to_f +} + +# Pass several tokens separated by commas (or a GitHub App installation token, +# 15000/hour) and they are used round-robin. +TOKENS = (ENV['GITHUB_TOKEN'] || '').split(',').map(&:strip).reject(&:empty?) + +# Remember which event ids have already been written. The previous version of +# this crawler only compared against the immediately preceding response, so any +# event that briefly dropped out of the window was archived twice. +SEEN_LIMIT = (ENV['SEEN_LIMIT'] || 200_000).to_i StatHat.config do |c| c.ukey = ENV['STATHATKEY'] @@ -24,7 +57,7 @@ :formatter => Log4r::PatternFormatter.new(:pattern => "[#{Process.pid}:%l] %d :: %m") })) -if !ENV['GITHUB_TOKEN'] +if TOKENS.empty? @log.error "No GITHUB_TOKEN environment variable defined." raise "No GITHUB_TOKEN environment variable defined." end @@ -42,74 +75,172 @@ Signal.trap("INT", &stop) Signal.trap("TERM", &stop) - @latest = [] - @latest_key = lambda { |e| "#{e['id']}" } + @seen = {} + @etags = {} + @inflight = {} + @due = {} + @token = 0 + @stats = Hash.new(0) + @warned = {} + @paused_until = nil - process = Proc.new do - req = HttpRequest.new("https://api.github.com/events?per_page=#{PAGE_LIMIT}", { - :inactivity_timeout => 5, - :connect_timeout => 5 - }).get({ - :head => { - 'user-agent' => 'gharchive.org', - 'Authorization' => 'token ' + ENV['GITHUB_TOKEN'] - } - }) + PAGES.each { |page| @due[page] = Time.now } - req.callback do - begin - latest = Yajl::Parser.parse(req.response) - urls = latest.collect(&@latest_key) - new_events = latest.reject {|e| @latest.include? @latest_key.call(e)} + @event_key = lambda { |e| "#{e['id']}" } + + next_token = lambda do + token = TOKENS[@token % TOKENS.size] + @token += 1 + token + end + + # Insertion-ordered hash, so the oldest ids are the first to be evicted. Evict + # in batches, otherwise every poll past the limit walks the whole key set. + remember = lambda do |ids| + ids.each { |id| @seen[id] = true } + if @seen.size > SEEN_LIMIT + @seen.keys.first(SEEN_LIMIT / 10).each { |id| @seen.delete(id) } + end + end + + archive_file = lambda do + # Name the archive after the wall clock, not after the event timestamps: + # an event may arrive after the file matching its own hour was compressed. + archive = "data/#{Time.now.strftime('%Y-%m-%d-%-k')}.json" + if @file.nil? || (archive != @file.to_path) + if !@file.nil? + @log.info "Rotating archive. Current: #{@file.to_path}, New: #{archive}" + @file.close + end + @file = File.new(archive, "a+") + end + @file + end + + # Slow every page down when the remaining quota runs behind the time left in + # the window, so that a burst cannot exhaust the hour and blind the crawler. + check_budget = lambda do |header| + remaining = header.raw['X-RateLimit-Remaining'].to_i + reset = header.raw['X-RateLimit-Reset'].to_i + return if reset.zero? + seconds_left = reset - Time.now.to_i + return if seconds_left <= 0 + # The header describes the token that served this request, so the threshold + # is per token and does not depend on how many are in the pool. + if remaining < 50 + delay = seconds_left.to_f / [remaining, 1].max + @paused_until = Time.now + [delay, 60].min + @log.warn "Rate limit nearly exhausted (#{remaining} left, resets in #{seconds_left}s), " \ + "backing off for #{'%.1f' % [@paused_until - Time.now]}s" + end + end - @latest = urls + handle = lambda do |page, req| + status = req.response_header.status - # Determine archive filename based on current time, before processing events - current_processing_time = Time.now - timestamp = current_processing_time.strftime('%Y-%m-%d-%-k') - archive = "data/#{timestamp}.json" + if status == 304 + @stats[:not_modified] += 1 + return + end - # Open or rotate file based on the current time's archive path - if @file.nil? || (archive != @file.to_path) - if !@file.nil? - @log.info "Rotating archive. Current: #{@file.to_path}, New: #{archive}" - @file.close - end - @file = File.new(archive, "a+") - end + if status == 403 || status == 429 + retry_after = req.response_header.raw['Retry-After'].to_i + retry_after = 60 if retry_after.zero? + @paused_until = Time.now + retry_after + @log.warn "Throttled by GitHub on page #{page} (HTTP #{status}), pausing for #{retry_after}s" + return + end - new_events.each do |event| - @file.puts(Yajl::Encoder.encode(Obfuscate.email(event))) - end + if status != 200 + @log.error "Unexpected HTTP #{status} on page #{page}: #{req.response[0, 500]}" + return + end - remaining = req.response_header.raw['X-RateLimit-Remaining'] - reset = Time.at(req.response_header.raw['X-RateLimit-Reset'].to_i) - @log.info "Found #{new_events.size} new events: #{new_events.collect(&@latest_key)}, API: #{remaining}, reset: #{reset}" + events = Yajl::Parser.parse(req.response) + unless events.is_a?(Array) + @log.error "Page #{page} did not return a list: #{req.response[0, 500]}" + return + end - if new_events.size >= PAGE_LIMIT - @log.info "Missed records.." - end + ids = events.collect(&@event_key) + fresh = events.reject { |e| @seen.key?(@event_key.call(e)) } + remember.call(ids) + + file = archive_file.call + fresh.each { |event| file.puts(Yajl::Encoder.encode(Obfuscate.email(event))) } + file.flush + + @stats[:events] += fresh.size + @stats[:polls] += 1 + + # Every entry of the page being new means the window turned over completely + # between two polls, so events in between were never seen. This is the check + # that PAGE_LIMIT = 500 disabled: it compared against a limit the API can + # never return, so it could not fire. + if !events.empty? && fresh.size == events.size && @seen.size > events.size + @stats[:"saturated_page#{page}"] += 1 + # Page 1 is expected to saturate - it moves faster than the API can serve + # to one client - so keep this to one line a minute per page. + if @warned[page].nil? || Time.now - @warned[page] > 60 + @warned[page] = Time.now + @log.warn "Page #{page} turned over completely between polls " \ + "(#{fresh.size}/#{events.size} new) - events in between were missed" + end + end - StatHat.new.ez_count('Github Events', new_events.size) + check_budget.call(req.response_header) + end + poll = lambda do |page| + @inflight[page] = true + url = "https://api.github.com/events?per_page=#{PAGE_LIMIT}&page=#{page}" + req = HttpRequest.new(url, { + :inactivity_timeout => 5, + :connect_timeout => 5 + }).get({ + :head => { + 'user-agent' => 'gharchive.org', + 'accept' => 'application/vnd.github+json', + 'Authorization' => 'token ' + next_token.call, + 'If-None-Match' => @etags[page] + }.compact + }) + + req.callback do + begin + @etags[page] = req.response_header.etag if req.response_header.status == 200 + handle.call(page, req) rescue Exception => e - @log.error "Failed to process response" - @log.error "Response: #{req.response}" - @log.error "Response headers: #{req.response_header}" - @log.error "Processing exception: #{e}, #{e.backtrace.first(5)}" + @log.error "Failed to process page #{page}: #{e}, #{e.backtrace.first(5)}" ensure - EM.add_timer(0.75, &process) + @inflight[page] = false + @due[page] = Time.now + PAGE_INTERVALS[page] end end req.errback do - @log.error "Error: #{req.response_header.status}, \ - header: #{req.response_header}, \ - response: #{req.response}" + @log.error "Error fetching page #{page}: #{req.response_header.status}, #{req.error}" + @inflight[page] = false + @due[page] = Time.now + PAGE_INTERVALS[page] + end + end - EM.add_timer(0.75, &process) + EM.add_periodic_timer(0.1) do + now = Time.now + if @paused_until && now < @paused_until + next + end + PAGES.each do |page| + poll.call(page) if !@inflight[page] && now >= @due[page] end end - process.call + EM.add_periodic_timer(60) do + saturated = PAGES.map { |p| "p#{p}:#{@stats[:"saturated_page#{p}"]}" }.join(' ') + @log.info "Last minute: #{@stats[:events]} events archived over #{@stats[:polls]} polls " \ + "(#{@stats[:not_modified]} not modified), #{@seen.size} ids remembered, " \ + "polls that saturated: #{saturated}" + StatHat.new.ez_count('Github Events', @stats[:events]) if ENV['STATHATKEY'] + @stats.clear + end end