Github code search stop due negative interval

[cafeitduong]

Hello,

The github code search task usually stop due to error : "Error: time interval must be positive", have anyone encountered the same? Please see below for the full error log:

Unable to run task Github Code Search on Users. Error: time interval must be positive ["/home/scumblr/Scumblr/lib/scumblr_tasks/security/github_analyzer.rb:106:in sleep'", "/home/scumblr/Scumblr/lib/scumblr_tasks/security/github_analyzer.rb:106:inrate_limit_sleep'", "/home/scumblr/Scumblr/lib/scumblr_tasks/security/github_analyzer.rb:543:in block (2 levels) in run'", "/home/scumblr/Scumblr/lib/scumblr_tasks/security/github_analyzer.rb:494:ineach'", "/home/scumblr/Scumblr/lib/scumblr_tasks/security/github_analyzer.rb:494:in block in run'", "/home/scumblr/Scumblr/lib/scumblr_tasks/security/github_analyzer.rb:490:ineach'", "/home/scumblr/Scumblr/lib/scumblr_tasks/security/github_analyzer.rb:490:in run'", "/home/scumblr/Scumblr/app/models/task.rb:161:inperform_task'", "/home/scumblr/Scumblr/app/workers/task_worker.rb:30:in perform'", "/home/scumblr/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/sidekiq-4.2.3/lib/sidekiq/processor.rb:155:inexecute_job'", "/home/scumblr/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/sidekiq-4.2.3/lib/sidekiq/processor.rb:136:in block (3 levels) in process'", "/home/scumblr/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/sidekiq-4.2.3/lib/sidekiq/middleware/chain.rb:128:inblock in invoke'", "/home/scumblr/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/sidekiq-status-0.6.0/lib/sidekiq-status/server_middleware.rb:37:in call'", "/home/scumblr/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/sidekiq-4.2.3/lib/sidekiq/middleware/chain.rb:130:inblock in invoke'", "/home/scumblr/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/sidekiq-4.2.3/lib/sidekiq/middleware/server/active_record.rb:6:in call'", "/home/scumblr/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/sidekiq-4.2.3/lib/sidekiq/middleware/chain.rb:130:inblock in invoke'", "/home/scumblr/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/sidekiq-4.2.3/lib/sidekiq/middleware/server/retry_jobs.rb:74:in call'", "/home/scumblr/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/sidekiq-4.2.3/lib/sidekiq/middleware/chain.rb:130:inblock in invoke'", "/home/scumblr/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/sidekiq-4.2.3/lib/sidekiq/middleware/server/logging.rb:11:in block in call'", "/home/scumblr/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/sidekiq-4.2.3/lib/sidekiq/logging.rb:32:inwith_context'", "/home/scumblr/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/sidekiq-4.2.3/lib/sidekiq/middleware/server/logging.rb:7:in call'", "/home/scumblr/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/sidekiq-4.2.3/lib/sidekiq/middleware/chain.rb:130:inblock in invoke'", "/home/scumblr/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/sidekiq-4.2.3/lib/sidekiq/middleware/chain.rb:133:in invoke'", "/home/scumblr/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/sidekiq-4.2.3/lib/sidekiq/processor.rb:131:inblock (2 levels) in process'", "/home/scumblr/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/sidekiq-4.2.3/lib/sidekiq/processor.rb:171:in stats'", "/home/scumblr/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/sidekiq-4.2.3/lib/sidekiq/processor.rb:130:inblock in process'", "/home/scumblr/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/sidekiq-4.2.3/lib/sidekiq.rb:35:in block in <module:Sidekiq>'", "/home/scumblr/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/sidekiq-4.2.3/lib/sidekiq/processor.rb:122:inprocess'", "/home/scumblr/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/sidekiq-4.2.3/lib/sidekiq/processor.rb:81:in process_one'", "/home/scumblr/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/sidekiq-4.2.3/lib/sidekiq/processor.rb:69:inrun'", "/home/scumblr/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/sidekiq-4.2.3/lib/sidekiq/util.rb:17:in watchdog'", "/home/scumblr/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/sidekiq-4.2.3/lib/sidekiq/util.rb:25:inblock in safe_thread'"]

[cafeitduong]

Looks like the timezone logged in sidekiq.log is not identical with local system timezone, so I wonder if it's the cause for this issue? How can I change the timezone to correct one please help me?

[ahoernecke]

Hi @cafeitduong,

Sidekiq by design logs in UTC (https://github.com/mperham/sidekiq/wiki/Logging).

You can update the time zone for Scumblr in config/application.rb. There should be a line that indicates the current setting that you will need to update.

Additionally please make sure your system time is correct as this could cause the issue as well.

Please try the above and report back.

Thanks!

[cafeitduong]

Hi @ahoernecke ,

In my config/application.rb already has

config.time_zone = 'Hanoi'
config.active_record.default_timezone = :local

And local machine has been set to Hanoi time too. I also restart the scumblr after save the config, but it's still the same result. The job get running for first about 30 search, and stop due to above error.

Thanks.

[ahoernecke]

Can you run this command from your Scumblr folder and post the result:

rails r 'puts DateTime.now.to_i';date "+%s %Z"; curl -I https://api.github.com/events | grep '\(X-RateLimit-Reset:\)\|\(Last-Modified\)'

[cafeitduong]

Hi @ahoernecke,

Here is the result:

DEPRECATION WARNING: The configuration option `config.serve_static_assets` has been renamed to `config.serve_static_files` to clarify its role (it merely enables serving everything in the `public` folder and is unrelated to the asset pipeline). The `serve_static_assets` alias will be removed in Rails 5.0. Please migrate your configuration files accordingly. (called from block in <top (required)> at /home/scumblr/Scumblr/config/environments/production.rb:37)
DEPRECATION WARNING: You did not specify a `log_level` in `production.rb`. Currently, the default value for `log_level` is `:info` for the production environment and `:debug` in all other environments. In Rails 5 the default value will be unified to `:debug` across all environments. To preserve the current setting, add the following line to your `production.rb`:

   config.log_level = :info

. (called from block in tsort_each at /home/scumblr/.rbenv/versions/2.3.1/lib/ruby/2.3.0/tsort.rb:228)
1481728110
1481728110 ICT
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
  0  129k    0     0    0     0      0      0 --:--:--  0:00:02 --:--:--     0
X-RateLimit-Reset: 1481731695
Last-Modified: Wed, 14 Dec 2016 15:08:25 GMT

And system local time is: Wed Dec 14 22:10:23 ICT 2016

[ahoernecke]

I'm not positive what's going on here, but it does look like your system time is slightly ahead of Github's and this could cause you to get an error when the sleep gets a negative number. I'll try to push up a fix later today.

[ahoernecke]

Hi, I pushed an update that should hopefully address your issue. Can you update to the latest code on master, restart your server and sidekiq, and let me know if you notice a difference?

[cafeitduong]

Hi @ahoernecke

Looks like the issue has gone, currently there are negative sleeping value but the task still running. I think issue has been resolved. Thanks a lot for prompt respond :)

[ahoernecke]

Awesome, good to hear!