Mailinglist Archive: opensuse-buildservice (124 mails)

< Previous Next >
Re: [opensuse-buildservice] own obs: osc -A obs mr -m "..." failed
Hi Adrian,

I changed production.rb (config.log_level = :debug) and attached
production.log

I tried only once:
admin@lap:~/MyOBS/home:admin:branches:OBS_Maintained:owncloud> osc -A
obs mr -m "some minor fixes for owncloud"
Using target project 'SIT:Maintenance'
Server returned an error: HTTP Error 400: Bad Request
Maintenance incident requests have to go to projects of type maintenance
or maintenance_incident

obs:~ # rpm -qa | grep obs
obs-service-set_version-0.5.3-66.1.noarch
obs-server-2.7.2-2.2.noarch
obs-service-download_files-0.5.1.git.1455712026.9c0a4a0-67.1.noarch
obs-api-2.7.2-2.2.noarch
obs-service-format_spec_file-20160929-217.1.noarch
obs-source_service-2.7.2-2.2.noarch
obs-service-extract_file-0.3-17.1.noarch
obs-common-2.7.2-2.2.noarch
obs-service-download_url-0.1-18.1.noarch
obs-service-verify_file-0.1.1-33.1.noarch
obs-service-download_src_package-0.2-3.1.noarch
obs-signd-2.2.1-1.1.x86_64
obs-service-recompress-0.3.1+git20160217.7897d3f-27.1.noarch
obs-service-source_validator-0.6+git20160707.a6ff89d-95.1.noarch
obs-productconverter-2.7.2-2.2.noarch

hopefully you can help.
Thanks


Am 14.11.2016 um 08:50 schrieb Adrian Schröter:
On Samstag, 12. November 2016, 18:58:58 CET wrote Christian:
My maintenance project which used to work is somehow broken ... could
need some help:


we would need some more information. Which version do you run
exactly? Can you enable debug output in your rails environment
please? (the output from the last operation would be enough then)

this is from production.log:

[6064df21-e43f-4edb-a9b8-0b8cb40fedc2] [17258:525599.30] Started GET
"/attribs/SIT:Maintenance" for 192.168.101.8 at 2016-11-12 17:46:01 +0000
[6064df21-e43f-4edb-a9b8-0b8cb40fedc2] [17258:525599.31] Processing by
Webui::AttributeController#index as HTML
[6064df21-e43f-4edb-a9b8-0b8cb40fedc2] [17258:525599.31] Parameters:
{"project"=>"SIT:Maintenance"}
[6064df21-e43f-4edb-a9b8-0b8cb40fedc2] [17258:525599.32] Rendered
webui/project/_tabs.html.erb (3.9ms)
[6064df21-e43f-4edb-a9b8-0b8cb40fedc2] [17258:525599.34] Rendered
webui/attribute/_attributes.html.erb (14.8ms)
[6064df21-e43f-4edb-a9b8-0b8cb40fedc2] [17258:525599.34] Rendered
webui/attribute/index.html.erb within layouts/webui/webui (23.1ms)
[6064df21-e43f-4edb-a9b8-0b8cb40fedc2] [17258:525599.34] Rendered
layouts/webui/_watch_and_search.html.erb (2.3ms)
[6064df21-e43f-4edb-a9b8-0b8cb40fedc2] [17258:525599.34] Rendered
layouts/webui/_header.html.erb (2.9ms)
[6064df21-e43f-4edb-a9b8-0b8cb40fedc2] [17258:525599.35] Rendered
layouts/webui/_personal_navigation.html.erb (3.6ms)
[6064df21-e43f-4edb-a9b8-0b8cb40fedc2] [17258:525599.35] Rendered
layouts/webui/_flash.html.erb (0.0ms)
[6064df21-e43f-4edb-a9b8-0b8cb40fedc2] [17258:525599.35] Completed 200
OK in 45ms (Views: 31.9ms | ActiveRecord: 5.6ms | Backend: 0.0ms | XML:
0.0ms)
[aa3691d2-629b-4516-a221-3a602506b41d] [17258:525614.50] Started GET
"/project/meta/SIT:Maintenance" for 192.168.101.8 at 2016-11-12 17:46:17
+0000
[aa3691d2-629b-4516-a221-3a602506b41d] [17258:525614.50] Processing by
Webui::ProjectController#meta as HTML
[aa3691d2-629b-4516-a221-3a602506b41d] [17258:525614.50] Parameters:
{"project"=>"SIT:Maintenance"}
[aa3691d2-629b-4516-a221-3a602506b41d] [17258:525614.53] Rendered
models/_project.xml.builder (14.6ms)
[aa3691d2-629b-4516-a221-3a602506b41d] [17258:525614.53] Rendered
webui/project/_tabs.html.erb (3.6ms)
[aa3691d2-629b-4516-a221-3a602506b41d] [17258:525614.62] Rendered
shared/_editor.html.erb (3.4ms)
[aa3691d2-629b-4516-a221-3a602506b41d] [17258:525614.62] Rendered
webui/project/meta.html.erb within layouts/webui/webui (96.1ms)
[aa3691d2-629b-4516-a221-3a602506b41d] [17258:525614.63] Rendered
layouts/webui/_watch_and_search.html.erb (1.2ms)
[aa3691d2-629b-4516-a221-3a602506b41d] [17258:525614.63] Rendered
layouts/webui/_header.html.erb (1.6ms)
[aa3691d2-629b-4516-a221-3a602506b41d] [17258:525614.63] Rendered
layouts/webui/_personal_navigation.html.erb (1.9ms)
[aa3691d2-629b-4516-a221-3a602506b41d] [17258:525614.63] Rendered
layouts/webui/_flash.html.erb (0.0ms)
[aa3691d2-629b-4516-a221-3a602506b41d] [17258:525614.63] Completed 200
OK in 133ms (Views: 103.5ms | ActiveRecord: 6.5ms | Backend: 0.0ms |
XML: 0.0ms)
[4918:585741.84] 2016-11-12T17:46:25+0000: [Worker(delayed_job.1
host:obs pid:4918)] Job Event::NotifyBackends#send_not_in_queue
(id=60222) RUNNING
[4987:585725.56] 2016-11-12T17:46:25+0000: [Worker(delayed_job.1030
host:obs pid:4987)] Job SendEventEmails#perform (id=60223) RUNNING
[4918:585741.90] 2016-11-12T17:46:25+0000: [Worker(delayed_job.1
host:obs pid:4918)] Job Event::NotifyBackends#send_not_in_queue
(id=60222) COMPLETED after 0.0602
[4918:585741.90] 2016-11-12T17:46:25+0000: [Worker(delayed_job.1
host:obs pid:4918)] 1 jobs processed at 4.6475 j/s, 0 failed
[4987:585725.60] 2016-11-12T17:46:25+0000: [Worker(delayed_job.1030
host:obs pid:4987)] Job SendEventEmails#perform (id=60223) COMPLETED
after 0.0459
[4987:585725.60] 2016-11-12T17:46:25+0000: [Worker(delayed_job.1030
host:obs pid:4987)] 1 jobs processed at 4.7711 j/s, 0 failed
[4918:585772.17] 2016-11-12T17:46:56+0000: [Worker(delayed_job.1
host:obs pid:4918)] Job Event::NotifyBackends#send_not_in_queue
(id=60224) RUNNING
[4987:585755.88] 2016-11-12T17:46:56+0000: [Worker(delayed_job.1030
host:obs pid:4987)] Job SendEventEmails#perform (id=60225) RUNNING
[4918:585772.23] 2016-11-12T17:46:56+0000: [Worker(delayed_job.1
host:obs pid:4918)] Job Event::NotifyBackends#send_not_in_queue
(id=60224) COMPLETED after 0.0663
[4918:585772.23] 2016-11-12T17:46:56+0000: [Worker(delayed_job.1
host:obs pid:4918)] 1 jobs processed at 3.1355 j/s, 0 failed
[4987:585755.95] 2016-11-12T17:46:56+0000: [Worker(delayed_job.1030
host:obs pid:4987)] Job SendEventEmails#perform (id=60225) COMPLETED
after 0.0644
[4987:585755.95] 2016-11-12T17:46:56+0000: [Worker(delayed_job.1030
host:obs pid:4987)] 1 jobs processed at 3.0422 j/s, 0 failed
[f59565cc-ad26-468e-8a77-b15d78c28ea0] [17258:525661.30] Started GET
"/search/project/id?match=attribute%2F%40name+%3D+%27OBS%3AMaintenanceProject%27"
for 192.168.101.8 at 2016-11-12 17:47:03 +0000
[f59565cc-ad26-468e-8a77-b15d78c28ea0] [17258:525661.30] Processing by
SearchController#project_id as XML
[f59565cc-ad26-468e-8a77-b15d78c28ea0] [17258:525661.30] Parameters:
{"match"=>"attribute/@name = 'OBS:MaintenanceProject'"}
[f59565cc-ad26-468e-8a77-b15d78c28ea0] [17258:525661.31] Rendered
status.xml.builder (0.5ms)
[f59565cc-ad26-468e-8a77-b15d78c28ea0] [17258:525661.31] Completed 401
Unauthorized in 8ms (Views: 1.7ms | ActiveRecord: 0.7ms | Backend: 0.0ms
| XML: 0.0ms)
[20eba724-3979-496f-b52b-da12dc30d21d] [17258:525661.52] Started GET
"/search/project/id?match=attribute%2F%40name+%3D+%27OBS%3AMaintenanceProject%27"
for 192.168.101.8 at 2016-11-12 17:47:04 +0000
[20eba724-3979-496f-b52b-da12dc30d21d] [17258:525661.52] Processing by
SearchController#project_id as XML
[20eba724-3979-496f-b52b-da12dc30d21d] [17258:525661.52] Parameters:
{"match"=>"attribute/@name = 'OBS:MaintenanceProject'"}
[20eba724-3979-496f-b52b-da12dc30d21d] [17258:525661.66] Rendered text
template (0.0ms)
[20eba724-3979-496f-b52b-da12dc30d21d] [17258:525661.66] Completed 200
OK in 144ms (Views: 0.4ms | ActiveRecord: 132.1ms | Backend: 0.0ms |
XML: 0.0ms)
[4e7822e3-6634-4bc3-8013-dd79be8a9877] [17258:525661.87] Started POST
"/request?cmd=create&addrevision=1" for 192.168.101.8 at 2016-11-12
17:47:04 +0000
[4e7822e3-6634-4bc3-8013-dd79be8a9877] [17258:525661.87] Processing by
RequestController#global_command as XML
[4e7822e3-6634-4bc3-8013-dd79be8a9877] [17258:525661.87] Parameters:
{"cmd"=>"create", "addrevision"=>"1"}
[4e7822e3-6634-4bc3-8013-dd79be8a9877] [17258:525661.87] Can't verify
CSRF token authenticity
[4e7822e3-6634-4bc3-8013-dd79be8a9877] [17258:525661.88] Rendered
status.xml.builder (0.2ms)
[4e7822e3-6634-4bc3-8013-dd79be8a9877] [17258:525661.88] Completed 401
Unauthorized in 7ms (Views: 0.9ms | ActiveRecord: 0.8ms | Backend: 0.0ms
| XML: 0.0ms)
[d7e409f8-bcb9-4223-a1c0-369de8835467] [17258:525662.08] Started POST
"/request?cmd=create&addrevision=1" for 192.168.101.8 at 2016-11-12
17:47:04 +0000
[d7e409f8-bcb9-4223-a1c0-369de8835467] [17258:525662.08] Processing by
RequestController#global_command as XML
[d7e409f8-bcb9-4223-a1c0-369de8835467] [17258:525662.08] Parameters:
{"cmd"=>"create", "addrevision"=>"1"}
[d7e409f8-bcb9-4223-a1c0-369de8835467] [17258:525662.08] Can't verify
CSRF token authenticity
[d7e409f8-bcb9-4223-a1c0-369de8835467] [17258:525662.16] Rendered
status.xml.builder (0.2ms)
[d7e409f8-bcb9-4223-a1c0-369de8835467] [17258:525662.16] Completed 400
Bad Request in 81ms (Views: 0.8ms | ActiveRecord: 63.5ms | Backend:
0.0ms | XML: 0.0ms)







--

Christian
----------------------------------------------------
- Please do not 'CC' me on list mails.
Just reply to the list :)
----------------------------------------------------
http://www.sc24.de - Sportbekleidung
----------------------------------------------------
[9228:0.00] 2016-11-14T20:55:21+0000: [Worker(delayed_job.0 host:obs pid:9228)]
Starting job worker
[9241:0.00] 2016-11-14T20:55:22+0000: [Worker(delayed_job.1 host:obs pid:9241)]
Starting job worker
[9248:0.00] 2016-11-14T20:55:22+0000: [Worker(delayed_job.2 host:obs pid:9248)]
Starting job worker
[9268:0.00] 2016-11-14T20:55:26+0000: [Worker(delayed_job.1000 host:obs
pid:9268)] Starting job worker
[9291:0.00] 2016-11-14T20:55:30+0000: [Worker(delayed_job.1010 host:obs
pid:9291)] Starting job worker
[9306:0.00] 2016-11-14T20:55:34+0000: [Worker(delayed_job.1020 host:obs
pid:9306)] Starting job worker
[9321:0.00] 2016-11-14T20:55:38+0000: [Worker(delayed_job.1030 host:obs
pid:9321)] Starting job worker
[9321:5.20] 2016-11-14T20:55:43+0000: [Worker(delayed_job.1030 host:obs
pid:9321)] Job StatusHistoryRescaler#rescale (id=72899) RUNNING
[ActiveJob] [9332:0.00] Enqueued CleanupEvents (Job ID:
7a0b595c-ee7a-401c-9ca5-69ec77dd7781) to DelayedJob(default)
[ActiveJob] [9332:0.08] Enqueued ConsistencyCheckJob (Job ID:
8ed7231e-0368-4d95-bdc5-fcd38ef36162) to DelayedJob(default)
[9321:7.69] 2016-11-14T20:55:45+0000: [Worker(delayed_job.1030 host:obs
pid:9321)] Job StatusHistoryRescaler#rescale (id=72899) FAILED (0 prior
attempts) with ActiveRecord::StatementInvalid: Mysql2::Error: Deadlock found
when trying to get lock; try restarting transaction: DELETE FROM
`status_histories` WHERE `status_histories`.`id` IN (18174898, 18174899,
18174900, 18174901, 18217205, 18174903, 18174904, 18174905, 18174906, 18174907,
18174908, 18174909)
[9321:8.14] 2016-11-14T20:55:46+0000: [Worker(delayed_job.1030 host:obs
pid:9321)] Job Event::NotifyBackends#send_not_in_queue (id=72900) RUNNING
[9321:8.43] 2016-11-14T20:55:46+0000: [Worker(delayed_job.1030 host:obs
pid:9321)] Job Event::NotifyBackends#send_not_in_queue (id=72900) COMPLETED
after 0.2852
[9321:8.50] 2016-11-14T20:55:46+0000: [Worker(delayed_job.1030 host:obs
pid:9321)] Job SendEventEmails#perform (id=72901) RUNNING
[9321:8.58] 2016-11-14T20:55:46+0000: [Worker(delayed_job.1030 host:obs
pid:9321)] Job SendEventEmails#perform (id=72901) COMPLETED after 0.0801
[9321:8.66] 2016-11-14T20:55:46+0000: [Worker(delayed_job.1030 host:obs
pid:9321)] Job FullTextSearch#index_and_start (id=72902) RUNNING
[9228:25.10] 2016-11-14T20:55:47+0000: [Worker(delayed_job.0 host:obs
pid:9228)] Job ProjectLogRotate#perform (id=72903) RUNNING
[9228:25.25] 2016-11-14T20:55:47+0000: [Worker(delayed_job.0 host:obs
pid:9228)] Job ProjectLogRotate#perform (id=72903) COMPLETED after 0.1502
[9228:25.25] 2016-11-14T20:55:47+0000: [Worker(delayed_job.0 host:obs
pid:9228)] 1 jobs processed at 4.6289 j/s, 0 failed
[9321:10.17] 2016-11-14T20:55:48+0000: [Worker(delayed_job.1030 host:obs
pid:9321)] Job FullTextSearch#index_and_start (id=72902) COMPLETED after 1.5136
[9321:10.24] 2016-11-14T20:55:48+0000: [Worker(delayed_job.1030 host:obs
pid:9321)] Job ActiveJob::QueueAdapters::DelayedJobAdapter::JobWrapper
(id=72904) RUNNING
[ActiveJob] [CleanupEvents] [7a0b595c-ee7a-401c-9ca5-69ec77dd7781] [9321:10.24]
Performing CleanupEvents from DelayedJob(default)
[ActiveJob] [CleanupEvents] [7a0b595c-ee7a-401c-9ca5-69ec77dd7781] [9321:10.25]
Performed CleanupEvents from DelayedJob(default) in 12.06ms
[9321:10.36] 2016-11-14T20:55:48+0000: [Worker(delayed_job.1030 host:obs
pid:9321)] Job ActiveJob::QueueAdapters::DelayedJobAdapter::JobWrapper
(id=72904) COMPLETED after 0.1138
[9321:10.46] 2016-11-14T20:55:48+0000: [Worker(delayed_job.1030 host:obs
pid:9321)] Job ActiveJob::QueueAdapters::DelayedJobAdapter::JobWrapper
(id=72905) RUNNING
[ActiveJob] [ConsistencyCheckJob] [8ed7231e-0368-4d95-bdc5-fcd38ef36162]
[9321:10.47] Performing ConsistencyCheckJob from DelayedJob(default)
[ActiveJob] [ConsistencyCheckJob] [8ed7231e-0368-4d95-bdc5-fcd38ef36162]
[9321:10.48] Performed ConsistencyCheckJob from DelayedJob(default) in 10.32ms
[9321:10.48] 2016-11-14T20:55:48+0000: [Worker(delayed_job.1030 host:obs
pid:9321)] Job ActiveJob::QueueAdapters::DelayedJobAdapter::JobWrapper
(id=72905) FAILED (0 prior attempts) with NoMethodError: undefined method
`is_admin?' for nil:NilClass
Did you mean? is_haml?
[9321:10.67] 2016-11-14T20:55:48+0000: [Worker(delayed_job.1030 host:obs
pid:9321)] Job ConsistencyCheckJob#perform (id=72906) RUNNING
[9321:10.67] 2016-11-14T20:55:48+0000: [Worker(delayed_job.1030 host:obs
pid:9321)] Job ConsistencyCheckJob#perform (id=72906) FAILED (0 prior attempts)
with NoMethodError: undefined method `is_admin?' for nil:NilClass
Did you mean? is_haml?
[9321:10.76] 2016-11-14T20:55:49+0000: [Worker(delayed_job.1030 host:obs
pid:9321)] 7 jobs processed at 1.2207 j/s, 3 failed
[9241:30.21] 2016-11-14T20:55:52+0000: [Worker(delayed_job.1 host:obs
pid:9241)] Job StatusHistoryRescaler#rescale (id=72899) RUNNING
[9321:15.86] 2016-11-14T20:55:54+0000: [Worker(delayed_job.1030 host:obs
pid:9321)] Job ActiveJob::QueueAdapters::DelayedJobAdapter::JobWrapper
(id=72905) RUNNING
[ActiveJob] [ConsistencyCheckJob] [8ed7231e-0368-4d95-bdc5-fcd38ef36162]
[9321:15.86] Performing ConsistencyCheckJob from DelayedJob(default)
[ActiveJob] [ConsistencyCheckJob] [8ed7231e-0368-4d95-bdc5-fcd38ef36162]
[9321:15.86] Performed ConsistencyCheckJob from DelayedJob(default) in 4.04ms
[9321:15.86] 2016-11-14T20:55:54+0000: [Worker(delayed_job.1030 host:obs
pid:9321)] Job ActiveJob::QueueAdapters::DelayedJobAdapter::JobWrapper
(id=72905) FAILED (1 prior attempts) with NoMethodError: undefined method
`is_admin?' for nil:NilClass
Did you mean? is_haml?
[9321:16.08] 2016-11-14T20:55:54+0000: [Worker(delayed_job.1030 host:obs
pid:9321)] Job ConsistencyCheckJob#perform (id=72906) RUNNING
[9321:16.09] 2016-11-14T20:55:54+0000: [Worker(delayed_job.1030 host:obs
pid:9321)] Job ConsistencyCheckJob#perform (id=72906) FAILED (1 prior attempts)
with NoMethodError: undefined method `is_admin?' for nil:NilClass
Did you mean? is_haml?
[9321:16.13] 2016-11-14T20:55:54+0000: [Worker(delayed_job.1030 host:obs
pid:9321)] 2 jobs processed at 5.3543 j/s, 2 failed
[9241:37.28] 2016-11-14T20:55:59+0000: [Worker(delayed_job.1 host:obs
pid:9241)] Job StatusHistoryRescaler#rescale (id=72899) COMPLETED after 7.0733
[9241:37.28] 2016-11-14T20:55:59+0000: [Worker(delayed_job.1 host:obs
pid:9241)] 1 jobs processed at 0.1379 j/s, 0 failed
[9228:50.29] 2016-11-14T20:56:12+0000: [Worker(delayed_job.0 host:obs
pid:9228)] Job Event::NotifyBackends#send_not_in_queue (id=72907) RUNNING
[9248:50.10] 2016-11-14T20:56:12+0000: [Worker(delayed_job.2 host:obs
pid:9248)] Job SendEventEmails#perform (id=72908) RUNNING
[9228:50.36] 2016-11-14T20:56:12+0000: [Worker(delayed_job.0 host:obs
pid:9228)] Job Event::NotifyBackends#send_not_in_queue (id=72907) COMPLETED
after 0.0686
[9228:50.36] 2016-11-14T20:56:12+0000: [Worker(delayed_job.0 host:obs
pid:9228)] 1 jobs processed at 9.6146 j/s, 0 failed
[9248:50.14] 2016-11-14T20:56:12+0000: [Worker(delayed_job.2 host:obs
pid:9248)] Job SendEventEmails#perform (id=72908) COMPLETED after 0.0481
[9248:50.15] 2016-11-14T20:56:12+0000: [Worker(delayed_job.2 host:obs
pid:9248)] 1 jobs processed at 9.6900 j/s, 0 failed
[9321:41.20] 2016-11-14T20:56:19+0000: [Worker(delayed_job.1030 host:obs
pid:9321)] Job ActiveJob::QueueAdapters::DelayedJobAdapter::JobWrapper
(id=72905) RUNNING
[ActiveJob] [ConsistencyCheckJob] [8ed7231e-0368-4d95-bdc5-fcd38ef36162]
[9321:41.20] Performing ConsistencyCheckJob from DelayedJob(default)
[ActiveJob] [ConsistencyCheckJob] [8ed7231e-0368-4d95-bdc5-fcd38ef36162]
[9321:41.20] Performed ConsistencyCheckJob from DelayedJob(default) in 5.1ms
[9321:41.20] 2016-11-14T20:56:19+0000: [Worker(delayed_job.1030 host:obs
pid:9321)] Job ActiveJob::QueueAdapters::DelayedJobAdapter::JobWrapper
(id=72905) FAILED (2 prior attempts) with NoMethodError: undefined method
`is_admin?' for nil:NilClass
Did you mean? is_haml?
[9321:41.33] 2016-11-14T20:56:19+0000: [Worker(delayed_job.1030 host:obs
pid:9321)] Job ConsistencyCheckJob#perform (id=72906) RUNNING
[9321:41.33] 2016-11-14T20:56:19+0000: [Worker(delayed_job.1030 host:obs
pid:9321)] Job ConsistencyCheckJob#perform (id=72906) FAILED (2 prior attempts)
with NoMethodError: undefined method `is_admin?' for nil:NilClass
Did you mean? is_haml?
[9321:41.38] 2016-11-14T20:56:19+0000: [Worker(delayed_job.1030 host:obs
pid:9321)] 2 jobs processed at 8.6932 j/s, 2 failed
[9228:80.42] 2016-11-14T20:56:42+0000: [Worker(delayed_job.0 host:obs
pid:9228)] Job Event::NotifyBackends#send_not_in_queue (id=72909) RUNNING
[9248:80.21] 2016-11-14T20:56:42+0000: [Worker(delayed_job.2 host:obs
pid:9248)] Job SendEventEmails#perform (id=72910) RUNNING
[9228:80.49] 2016-11-14T20:56:42+0000: [Worker(delayed_job.0 host:obs
pid:9228)] Job Event::NotifyBackends#send_not_in_queue (id=72909) COMPLETED
after 0.0763
[9228:80.50] 2016-11-14T20:56:42+0000: [Worker(delayed_job.0 host:obs
pid:9228)] 1 jobs processed at 8.3047 j/s, 0 failed
[9248:80.29] 2016-11-14T20:56:42+0000: [Worker(delayed_job.2 host:obs
pid:9248)] Job SendEventEmails#perform (id=72910) COMPLETED after 0.0758
[9248:80.29] 2016-11-14T20:56:42+0000: [Worker(delayed_job.2 host:obs
pid:9248)] 1 jobs processed at 7.6878 j/s, 0 failed
[9228:110.55] 2016-11-14T20:57:12+0000: [Worker(delayed_job.0 host:obs
pid:9228)] Job Event::NotifyBackends#send_not_in_queue (id=72911) RUNNING
[9248:110.34] 2016-11-14T20:57:12+0000: [Worker(delayed_job.2 host:obs
pid:9248)] Job SendEventEmails#perform (id=72912) RUNNING
[9228:110.63] 2016-11-14T20:57:12+0000: [Worker(delayed_job.0 host:obs
pid:9228)] Job Event::NotifyBackends#send_not_in_queue (id=72911) COMPLETED
after 0.0761
[9228:110.63] 2016-11-14T20:57:12+0000: [Worker(delayed_job.0 host:obs
pid:9228)] 1 jobs processed at 8.1673 j/s, 0 failed
[9248:110.42] 2016-11-14T20:57:12+0000: [Worker(delayed_job.2 host:obs
pid:9248)] Job SendEventEmails#perform (id=72912) COMPLETED after 0.0746
[9248:110.42] 2016-11-14T20:57:12+0000: [Worker(delayed_job.2 host:obs
pid:9248)] 1 jobs processed at 8.6601 j/s, 0 failed
[9228:140.74] 2016-11-14T20:57:42+0000: [Worker(delayed_job.0 host:obs
pid:9228)] Job Event::NotifyBackends#send_not_in_queue (id=72913) RUNNING
[9248:140.53] 2016-11-14T20:57:42+0000: [Worker(delayed_job.2 host:obs
pid:9248)] Job SendEventEmails#perform (id=72914) RUNNING
[9228:140.81] 2016-11-14T20:57:42+0000: [Worker(delayed_job.0 host:obs
pid:9228)] Job Event::NotifyBackends#send_not_in_queue (id=72913) COMPLETED
after 0.0639
[9228:140.81] 2016-11-14T20:57:42+0000: [Worker(delayed_job.0 host:obs
pid:9228)] 1 jobs processed at 6.0219 j/s, 0 failed
[9248:140.59] 2016-11-14T20:57:42+0000: [Worker(delayed_job.2 host:obs
pid:9248)] Job SendEventEmails#perform (id=72914) COMPLETED after 0.0640
[9248:140.59] 2016-11-14T20:57:42+0000: [Worker(delayed_job.2 host:obs
pid:9248)] 1 jobs processed at 6.3445 j/s, 0 failed
[9321:131.59] 2016-11-14T20:57:49+0000: [Worker(delayed_job.1030 host:obs
pid:9321)] Job ActiveJob::QueueAdapters::DelayedJobAdapter::JobWrapper
(id=72905) RUNNING
[ActiveJob] [ConsistencyCheckJob] [8ed7231e-0368-4d95-bdc5-fcd38ef36162]
[9321:131.59] Performing ConsistencyCheckJob from DelayedJob(default)
[ActiveJob] [ConsistencyCheckJob] [8ed7231e-0368-4d95-bdc5-fcd38ef36162]
[9321:131.60] Performed ConsistencyCheckJob from DelayedJob(default) in 8.16ms
[9321:131.60] 2016-11-14T20:57:49+0000: [Worker(delayed_job.1030 host:obs
pid:9321)] Job ActiveJob::QueueAdapters::DelayedJobAdapter::JobWrapper
(id=72905) FAILED (3 prior attempts) with NoMethodError: undefined method
`is_admin?' for nil:NilClass
Did you mean? is_haml?
[9321:131.69] 2016-11-14T20:57:49+0000: [Worker(delayed_job.1030 host:obs
pid:9321)] Job ConsistencyCheckJob#perform (id=72906) RUNNING
[9321:131.69] 2016-11-14T20:57:49+0000: [Worker(delayed_job.1030 host:obs
pid:9321)] Job ConsistencyCheckJob#perform (id=72906) FAILED (3 prior attempts)
with NoMethodError: undefined method `is_admin?' for nil:NilClass
Did you mean? is_haml?
[9321:131.74] 2016-11-14T20:57:50+0000: [Worker(delayed_job.1030 host:obs
pid:9321)] 2 jobs processed at 6.4491 j/s, 2 failed
[9228:170.91] 2016-11-14T20:58:12+0000: [Worker(delayed_job.0 host:obs
pid:9228)] Job Event::NotifyBackends#send_not_in_queue (id=72915) RUNNING
[9248:170.68] 2016-11-14T20:58:12+0000: [Worker(delayed_job.2 host:obs
pid:9248)] Job SendEventEmails#perform (id=72916) RUNNING
[9228:170.96] 2016-11-14T20:58:12+0000: [Worker(delayed_job.0 host:obs
pid:9228)] Job Event::NotifyBackends#send_not_in_queue (id=72915) COMPLETED
after 0.0582
[9228:170.96] 2016-11-14T20:58:12+0000: [Worker(delayed_job.0 host:obs
pid:9228)] 1 jobs processed at 7.0670 j/s, 0 failed
[9248:170.75] 2016-11-14T20:58:12+0000: [Worker(delayed_job.2 host:obs
pid:9248)] Job SendEventEmails#perform (id=72916) COMPLETED after 0.0630
[9248:170.75] 2016-11-14T20:58:12+0000: [Worker(delayed_job.2 host:obs
pid:9248)] 1 jobs processed at 6.8750 j/s, 0 failed
[9228:201.06] 2016-11-14T20:58:43+0000: [Worker(delayed_job.0 host:obs
pid:9228)] Job Event::NotifyBackends#send_not_in_queue (id=72917) RUNNING
[9248:200.85] 2016-11-14T20:58:43+0000: [Worker(delayed_job.2 host:obs
pid:9248)] Job SendEventEmails#perform (id=72918) RUNNING
[9228:201.13] 2016-11-14T20:58:43+0000: [Worker(delayed_job.0 host:obs
pid:9228)] Job Event::NotifyBackends#send_not_in_queue (id=72917) COMPLETED
after 0.0689
[9228:201.14] 2016-11-14T20:58:43+0000: [Worker(delayed_job.0 host:obs
pid:9228)] 1 jobs processed at 6.8697 j/s, 0 failed
[9248:200.92] 2016-11-14T20:58:43+0000: [Worker(delayed_job.2 host:obs
pid:9248)] Job SendEventEmails#perform (id=72918) COMPLETED after 0.0645
[9248:200.92] 2016-11-14T20:58:43+0000: [Worker(delayed_job.2 host:obs
pid:9248)] 1 jobs processed at 6.4045 j/s, 0 failed
[9228:0.00] 2016-11-14T20:58:51+0000: [Worker(delayed_job.0 host:obs pid:9228)]
Exiting...
[9241:0.00] 2016-11-14T20:58:53+0000: [Worker(delayed_job.1 host:obs pid:9241)]
Exiting...
[9248:0.00] 2016-11-14T20:58:54+0000: [Worker(delayed_job.2 host:obs pid:9248)]
Exiting...
[9268:0.00] 2016-11-14T20:59:02+0000: [Worker(delayed_job.1000 host:obs
pid:9268)] Exiting...
[9291:0.00] 2016-11-14T20:59:10+0000: [Worker(delayed_job.1010 host:obs
pid:9291)] Exiting...
[9321:216.81] 2016-11-14T20:59:15+0000: [Worker(delayed_job.1030 host:obs
pid:9321)] Job Event::NotifyBackends#send_not_in_queue (id=72919) RUNNING
[9321:217.09] 2016-11-14T20:59:15+0000: [Worker(delayed_job.1030 host:obs
pid:9321)] Job Event::NotifyBackends#send_not_in_queue (id=72919) COMPLETED
after 0.2725
[9321:217.15] 2016-11-14T20:59:15+0000: [Worker(delayed_job.1030 host:obs
pid:9321)] Job SendEventEmails#perform (id=72920) RUNNING
[9321:217.22] 2016-11-14T20:59:15+0000: [Worker(delayed_job.1030 host:obs
pid:9321)] Job SendEventEmails#perform (id=72920) COMPLETED after 0.0717
[9321:217.22] 2016-11-14T20:59:15+0000: [Worker(delayed_job.1030 host:obs
pid:9321)] 2 jobs processed at 4.5427 j/s, 0 failed
[9306:0.00] 2016-11-14T20:59:19+0000: [Worker(delayed_job.1020 host:obs
pid:9306)] Exiting...
[9321:0.00] 2016-11-14T20:59:28+0000: [Worker(delayed_job.1030 host:obs
pid:9321)] Exiting...
[9641:0.00] 2016-11-14T20:59:38+0000: [Worker(delayed_job.0 host:obs pid:9641)]
Starting job worker
[9641:0.02] SQL (0.3ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 20:59:38', `delayed_jobs`.`locked_by`
= 'delayed_job.0 host:obs pid:9641' WHERE ((run_at <= '2016-11-14
20:59:38.889051' AND (locked_at IS NULL OR locked_at < '2016-11-14
16:59:38.889138') OR locked_by = 'delayed_job.0 host:obs pid:9641') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'quick' ORDER BY priority ASC,
run_at ASC LIMIT 1
[9647:0.00] 2016-11-14T20:59:39+0000: [Worker(delayed_job.1 host:obs pid:9647)]
Starting job worker
[9647:0.07] SQL (5.6ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 20:59:39', `delayed_jobs`.`locked_by`
= 'delayed_job.1 host:obs pid:9647' WHERE ((run_at <= '2016-11-14
20:59:39.003458' AND (locked_at IS NULL OR locked_at < '2016-11-14
16:59:39.003547') OR locked_by = 'delayed_job.1 host:obs pid:9647') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'quick' ORDER BY priority ASC,
run_at ASC LIMIT 1
[9654:0.00] 2016-11-14T20:59:39+0000: [Worker(delayed_job.2 host:obs pid:9654)]
Starting job worker
[9654:0.02] SQL (0.3ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 20:59:39', `delayed_jobs`.`locked_by`
= 'delayed_job.2 host:obs pid:9654' WHERE ((run_at <= '2016-11-14
20:59:39.129016' AND (locked_at IS NULL OR locked_at < '2016-11-14
16:59:39.129102') OR locked_by = 'delayed_job.2 host:obs pid:9654') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'quick' ORDER BY priority ASC,
run_at ASC LIMIT 1
[9670:0.00] 2016-11-14T20:59:43+0000: [Worker(delayed_job.1000 host:obs
pid:9670)] Starting job worker
[9670:0.02] SQL (0.3ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 20:59:43', `delayed_jobs`.`locked_by`
= 'delayed_job.1000 host:obs pid:9670' WHERE ((run_at <= '2016-11-14
20:59:43.074039' AND (locked_at IS NULL OR locked_at < '2016-11-14
16:59:43.074133') OR locked_by = 'delayed_job.1000 host:obs pid:9670') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'releasetracking' ORDER BY
priority ASC, run_at ASC LIMIT 1
[9641:5.02] SQL (0.4ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 20:59:43', `delayed_jobs`.`locked_by`
= 'delayed_job.0 host:obs pid:9641' WHERE ((run_at <= '2016-11-14
20:59:43.911309' AND (locked_at IS NULL OR locked_at < '2016-11-14
16:59:43.911360') OR locked_by = 'delayed_job.0 host:obs pid:9641') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'quick' ORDER BY priority ASC,
run_at ASC LIMIT 1
[9647:5.07] SQL (0.8ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 20:59:44', `delayed_jobs`.`locked_by`
= 'delayed_job.1 host:obs pid:9647' WHERE ((run_at <= '2016-11-14
20:59:44.068417' AND (locked_at IS NULL OR locked_at < '2016-11-14
16:59:44.068460') OR locked_by = 'delayed_job.1 host:obs pid:9647') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'quick' ORDER BY priority ASC,
run_at ASC LIMIT 1
[9654:5.02] SQL (0.9ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 20:59:44', `delayed_jobs`.`locked_by`
= 'delayed_job.2 host:obs pid:9654' WHERE ((run_at <= '2016-11-14
20:59:44.148925' AND (locked_at IS NULL OR locked_at < '2016-11-14
16:59:44.149021') OR locked_by = 'delayed_job.2 host:obs pid:9654') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'quick' ORDER BY priority ASC,
run_at ASC LIMIT 1
[9683:0.00] 2016-11-14T20:59:47+0000: [Worker(delayed_job.1010 host:obs
pid:9683)] Starting job worker
[9683:0.03] SQL (1.7ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 20:59:47', `delayed_jobs`.`locked_by`
= 'delayed_job.1010 host:obs pid:9683' WHERE ((run_at <= '2016-11-14
20:59:47.060419' AND (locked_at IS NULL OR locked_at < '2016-11-14
16:59:47.060502') OR locked_by = 'delayed_job.1010 host:obs pid:9683') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'issuetracking' ORDER BY
priority ASC, run_at ASC LIMIT 1
[9670:5.03] SQL (0.5ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 20:59:48', `delayed_jobs`.`locked_by`
= 'delayed_job.1000 host:obs pid:9670' WHERE ((run_at <= '2016-11-14
20:59:48.098518' AND (locked_at IS NULL OR locked_at < '2016-11-14
16:59:48.098563') OR locked_by = 'delayed_job.1000 host:obs pid:9670') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'releasetracking' ORDER BY
priority ASC, run_at ASC LIMIT 1
[9641:10.03] SQL (0.4ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 20:59:48', `delayed_jobs`.`locked_by`
= 'delayed_job.0 host:obs pid:9641' WHERE ((run_at <= '2016-11-14
20:59:48.913282' AND (locked_at IS NULL OR locked_at < '2016-11-14
16:59:48.913327') OR locked_by = 'delayed_job.0 host:obs pid:9641') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'quick' ORDER BY priority ASC,
run_at ASC LIMIT 1
[9647:10.07] SQL (0.4ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 20:59:49', `delayed_jobs`.`locked_by`
= 'delayed_job.1 host:obs pid:9647' WHERE ((run_at <= '2016-11-14
20:59:49.070937' AND (locked_at IS NULL OR locked_at < '2016-11-14
16:59:49.070988') OR locked_by = 'delayed_job.1 host:obs pid:9647') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'quick' ORDER BY priority ASC,
run_at ASC LIMIT 1
[9654:10.03] SQL (0.4ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 20:59:49', `delayed_jobs`.`locked_by`
= 'delayed_job.2 host:obs pid:9654' WHERE ((run_at <= '2016-11-14
20:59:49.152801' AND (locked_at IS NULL OR locked_at < '2016-11-14
16:59:49.152852') OR locked_by = 'delayed_job.2 host:obs pid:9654') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'quick' ORDER BY priority ASC,
run_at ASC LIMIT 1
[9698:0.00] 2016-11-14T20:59:51+0000: [Worker(delayed_job.1020 host:obs
pid:9698)] Starting job worker
[9698:0.02] SQL (0.3ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 20:59:51', `delayed_jobs`.`locked_by`
= 'delayed_job.1020 host:obs pid:9698' WHERE ((run_at <= '2016-11-14
20:59:51.078612' AND (locked_at IS NULL OR locked_at < '2016-11-14
16:59:51.078697') OR locked_by = 'delayed_job.1020 host:obs pid:9698') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'mailers' ORDER BY priority
ASC, run_at ASC LIMIT 1
[9683:5.03] SQL (0.4ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 20:59:52', `delayed_jobs`.`locked_by`
= 'delayed_job.1010 host:obs pid:9683' WHERE ((run_at <= '2016-11-14
20:59:52.088380' AND (locked_at IS NULL OR locked_at < '2016-11-14
16:59:52.088428') OR locked_by = 'delayed_job.1010 host:obs pid:9683') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'issuetracking' ORDER BY
priority ASC, run_at ASC LIMIT 1
[9670:10.03] SQL (0.4ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 20:59:53', `delayed_jobs`.`locked_by`
= 'delayed_job.1000 host:obs pid:9670' WHERE ((run_at <= '2016-11-14
20:59:53.100518' AND (locked_at IS NULL OR locked_at < '2016-11-14
16:59:53.100563') OR locked_by = 'delayed_job.1000 host:obs pid:9670') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'releasetracking' ORDER BY
priority ASC, run_at ASC LIMIT 1
[9641:15.03] SQL (0.4ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 20:59:53', `delayed_jobs`.`locked_by`
= 'delayed_job.0 host:obs pid:9641' WHERE ((run_at <= '2016-11-14
20:59:53.915084' AND (locked_at IS NULL OR locked_at < '2016-11-14
16:59:53.915130') OR locked_by = 'delayed_job.0 host:obs pid:9641') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'quick' ORDER BY priority ASC,
run_at ASC LIMIT 1
[9647:15.07] SQL (0.4ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 20:59:54', `delayed_jobs`.`locked_by`
= 'delayed_job.1 host:obs pid:9647' WHERE ((run_at <= '2016-11-14
20:59:54.072902' AND (locked_at IS NULL OR locked_at < '2016-11-14
16:59:54.072953') OR locked_by = 'delayed_job.1 host:obs pid:9647') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'quick' ORDER BY priority ASC,
run_at ASC LIMIT 1
[9654:15.03] SQL (0.7ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 20:59:54', `delayed_jobs`.`locked_by`
= 'delayed_job.2 host:obs pid:9654' WHERE ((run_at <= '2016-11-14
20:59:54.154807' AND (locked_at IS NULL OR locked_at < '2016-11-14
16:59:54.154901') OR locked_by = 'delayed_job.2 host:obs pid:9654') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'quick' ORDER BY priority ASC,
run_at ASC LIMIT 1
[9713:0.00] 2016-11-14T20:59:55+0000: [Worker(delayed_job.1030 host:obs
pid:9713)] Starting job worker
[9713:0.02] SQL (0.4ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 20:59:55', `delayed_jobs`.`locked_by`
= 'delayed_job.1030 host:obs pid:9713' WHERE ((run_at <= '2016-11-14
20:59:55.070576' AND (locked_at IS NULL OR locked_at < '2016-11-14
16:59:55.070670') OR locked_by = 'delayed_job.1030 host:obs pid:9713') AND
failed_at IS NULL) ORDER BY priority ASC, run_at ASC LIMIT 1
[9698:5.02] SQL (0.4ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 20:59:56', `delayed_jobs`.`locked_by`
= 'delayed_job.1020 host:obs pid:9698' WHERE ((run_at <= '2016-11-14
20:59:56.100407' AND (locked_at IS NULL OR locked_at < '2016-11-14
16:59:56.100451') OR locked_by = 'delayed_job.1020 host:obs pid:9698') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'mailers' ORDER BY priority
ASC, run_at ASC LIMIT 1
[9683:10.03] SQL (0.5ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 20:59:57', `delayed_jobs`.`locked_by`
= 'delayed_job.1010 host:obs pid:9683' WHERE ((run_at <= '2016-11-14
20:59:57.090374' AND (locked_at IS NULL OR locked_at < '2016-11-14
16:59:57.090419') OR locked_by = 'delayed_job.1010 host:obs pid:9683') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'issuetracking' ORDER BY
priority ASC, run_at ASC LIMIT 1
[9670:15.03] SQL (0.7ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 20:59:58', `delayed_jobs`.`locked_by`
= 'delayed_job.1000 host:obs pid:9670' WHERE ((run_at <= '2016-11-14
20:59:58.102465' AND (locked_at IS NULL OR locked_at < '2016-11-14
16:59:58.102561') OR locked_by = 'delayed_job.1000 host:obs pid:9670') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'releasetracking' ORDER BY
priority ASC, run_at ASC LIMIT 1
[9641:20.03] SQL (0.9ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 20:59:58', `delayed_jobs`.`locked_by`
= 'delayed_job.0 host:obs pid:9641' WHERE ((run_at <= '2016-11-14
20:59:58.917137' AND (locked_at IS NULL OR locked_at < '2016-11-14
16:59:58.917236') OR locked_by = 'delayed_job.0 host:obs pid:9641') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'quick' ORDER BY priority ASC,
run_at ASC LIMIT 1
[9724:0.00] --> direct_http url: "/build/_workerstatus"
[9724:0.00] http_do: method: get url:
http://build.de.scorpio-it.net:5352/build/_workerstatus
[9647:20.07] SQL (0.4ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 20:59:59', `delayed_jobs`.`locked_by`
= 'delayed_job.1 host:obs pid:9647' WHERE ((run_at <= '2016-11-14
20:59:59.074818' AND (locked_at IS NULL OR locked_at < '2016-11-14
16:59:59.074903') OR locked_by = 'delayed_job.1 host:obs pid:9647') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'quick' ORDER BY priority ASC,
run_at ASC LIMIT 1
[9724:0.04] Cache write: workerstatus ({:expires_in=>180 seconds})
[9724:0.04] Dalli::Server#connect 127.0.0.1:11211
[9724:0.05]  (0.1ms) BEGIN
[9724:0.06] SQL (0.2ms) INSERT INTO `status_histories` (`time`,
`key`, `value`) VALUES (1479157199, 'blocked_i586', 2.0)
[9724:0.06] SQL (0.2ms) INSERT INTO `status_histories`
(`time`, `key`, `value`) VALUES (1479157199, 'blocked_x86_64', 0.0)
[9724:0.06] SQL (0.2ms) INSERT INTO `status_histories` (`time`,
`key`, `value`) VALUES (1479157199, 'waiting_i586', 0.0)
[9724:0.06] SQL (0.2ms) INSERT INTO `status_histories`
(`time`, `key`, `value`) VALUES (1479157199, 'waiting_x86_64', 0.0)
[9724:0.07] Architecture Load (0.3ms) SELECT `architectures`.*
FROM `architectures` WHERE `architectures`.`name` = 'i586' LIMIT 1
[9724:0.07] Architecture Exists (0.3ms) SELECT 1 AS one
FROM `architectures` WHERE (`architectures`.`name` = BINARY 'i586' AND
`architectures`.`id` != 1) LIMIT 1
[9724:0.07] Cache delete: archcache
[9724:0.08] Architecture Load (0.3ms) SELECT `architectures`.*
FROM `architectures` WHERE `architectures`.`name` = 'x86_64' LIMIT 1
[9724:0.08] Architecture Exists (0.2ms) SELECT 1 AS one
FROM `architectures` WHERE (`architectures`.`name` = BINARY 'x86_64' AND
`architectures`.`id` != 2) LIMIT 1
[9724:0.08] Cache delete: archcache
[9724:0.08] SQL (0.3ms) INSERT INTO `status_histories` (`time`,
`key`, `value`) VALUES (1479157199, 'squeue_high_i586', 0.0)
[9724:0.08] SQL (0.2ms) INSERT INTO `status_histories`
(`time`, `key`, `value`) VALUES (1479157199, 'squeue_next_i586', 0.0)
[9724:0.08] SQL (0.2ms) INSERT INTO `status_histories` (`time`,
`key`, `value`) VALUES (1479157199, 'squeue_med_i586', 0.0)
[9724:0.08] SQL (0.2ms) INSERT INTO `status_histories`
(`time`, `key`, `value`) VALUES (1479157199, 'squeue_low_i586', 1.0)
[9724:0.08] SQL (0.2ms) INSERT INTO `status_histories` (`time`,
`key`, `value`) VALUES (1479157199, 'squeue_high_x86_64', 0.0)
[9724:0.09] SQL (0.2ms) INSERT INTO `status_histories`
(`time`, `key`, `value`) VALUES (1479157199, 'squeue_next_x86_64', 0.0)
[9724:0.09] SQL (0.2ms) INSERT INTO `status_histories` (`time`,
`key`, `value`) VALUES (1479157199, 'squeue_med_x86_64', 0.0)
[9724:0.09] SQL (0.2ms) INSERT INTO `status_histories`
(`time`, `key`, `value`) VALUES (1479157199, 'squeue_low_x86_64', 1.0)
[9654:20.03] SQL (0.4ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 20:59:59', `delayed_jobs`.`locked_by`
= 'delayed_job.2 host:obs pid:9654' WHERE ((run_at <= '2016-11-14
20:59:59.158622' AND (locked_at IS NULL OR locked_at < '2016-11-14
16:59:59.158673') OR locked_by = 'delayed_job.2 host:obs pid:9654') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'quick' ORDER BY priority ASC,
run_at ASC LIMIT 1
[9724:0.82]  (735.4ms) COMMIT
[9724:0.83] IssueTracker Load (0.8ms) SELECT
`issue_trackers`.* FROM `issue_trackers`
[9724:0.85] User Load (0.2ms) SELECT `users`.* FROM `users`
WHERE `users`.`login` = 'Admin' LIMIT 1
[9724:0.87]  (0.1ms) BEGIN
[9724:0.87] SQL (0.9ms) INSERT INTO `delayed_jobs` (`handler`,
`queue`, `run_at`) VALUES ('---
!ruby/object:Delayed::PerformableMethod\nobject:
!ruby/object:StatusHistoryRescaler {}\nmethod_name: :rescale\nargs: []\n',
'quick', '2016-11-14 20:59:59')
[9724:0.99]  (122.8ms) COMMIT
[9724:0.99]  (0.6ms) BEGIN
[9724:1.00] SQL (0.3ms) INSERT INTO `delayed_jobs`
(`handler`, `queue`, `run_at`) VALUES ('---
!ruby/object:Delayed::PerformableMethod\nobject:
!ruby/object:Event::NotifyBackends {}\nmethod_name: :send_not_in_queue\nargs:
[]\n', 'quick', '2016-11-14 21:00:00')
[9724:1.09]  (94.6ms) COMMIT
[9724:1.09]  (0.2ms) BEGIN
[9724:1.10] SQL (0.4ms) INSERT INTO `delayed_jobs` (`handler`,
`queue`, `run_at`) VALUES ('---
!ruby/object:Delayed::PerformableMethod\nobject: !ruby/object:SendEventEmails
{}\nmethod_name: :perform\nargs: []\n', 'quick', '2016-11-14 21:00:00')
[9713:5.09] SQL (62.9ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:00', `delayed_jobs`.`locked_by`
= 'delayed_job.1030 host:obs pid:9713' WHERE ((run_at <= '2016-11-14
21:00:00.092004' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:00.092055') OR locked_by = 'delayed_job.1030 host:obs pid:9713') AND
failed_at IS NULL) ORDER BY priority ASC, run_at ASC LIMIT 1
[9713:5.09] Delayed::Backend::ActiveRecord::Job Load (0.9ms)
SELECT `delayed_jobs`.* FROM `delayed_jobs` WHERE
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:00' AND
`delayed_jobs`.`locked_by` = 'delayed_job.1030 host:obs pid:9713' AND
`delayed_jobs`.`failed_at` IS NULL ORDER BY `delayed_jobs`.`id` ASC LIMIT 1
[9713:5.10] 2016-11-14T21:00:00+0000: [Worker(delayed_job.1030 host:obs
pid:9713)] Job StatusHistoryRescaler#rescale (id=72921) RUNNING
[9724:1.17]  (69.8ms) COMMIT
[9724:1.17]  (0.6ms) BEGIN
[9724:1.17] SQL (0.3ms) INSERT INTO `delayed_jobs`
(`handler`, `queue`, `run_at`) VALUES ('---
!ruby/object:Delayed::PerformableMethod\nobject: !ruby/object:FullTextSearch\n
result: \nmethod_name: :index_and_start\nargs: []\n', 'quick', '2016-11-14
21:00:00')
[9724:0.00] User Load (0.6ms) SELECT `users`.* FROM `users`
WHERE `users`.`login` = 'Admin' LIMIT 1
[9724:1.23]  (60.9ms) COMMIT
[9724:1.23] Cache read: forbidden_projects
[9724:1.24] Cache fetch_hit: forbidden_projects
[9713:5.32]  (0.6ms) SELECT MAX(`status_histories`.`time`) FROM
`status_histories`
[9713:5.32] SQL (0.4ms) DELETE FROM `status_histories`
WHERE (time < 1447621199)
[9724:1.35]  (5.4ms) SELECT `packages`.`project_id` FROM
`packages` left outer join backend_packages on backend_packages.package_id =
packages.id WHERE (`packages`.`id` NOT IN (SELECT `packages`.`id` FROM
`packages` WHERE `packages`.`project_id` = 0)) AND (backend_packages.package_id
is null)
[9713:5.32]  (0.7ms) SELECT DISTINCT `key` FROM
`status_histories`
[9713:5.33]  (0.1ms) BEGIN
[9724:1.36]  (0.1ms) BEGIN
[9713:5.33]  (0.2ms) SELECT MAX(`status_histories`.`time`) FROM
`status_histories`
[9724:1.36] SQL (0.2ms) INSERT INTO `delayed_jobs` (`handler`,
`queue`, `run_at`) VALUES ('---
!ruby/object:Delayed::PerformableMethod\nobject: !ruby/object:ProjectLogRotate
{}\nmethod_name: :perform\nargs: []\n', 'quick', '2016-11-14 21:00:00')
[9713:5.33] StatusHistory Load (5.2ms) SELECT
`status_histories`.* FROM `status_histories` WHERE (`key` = 'blocked_i586' and
`time` < 1476565199) ORDER BY `status_histories`.`time` ASC
[9713:5.35]  (0.3ms) SELECT MIN(`status_histories`.`time`) FROM
`status_histories`
[9713:5.36]  (0.2ms) SELECT MAX(`status_histories`.`time`)
FROM `status_histories`
[9713:5.36] StatusHistory Load (4.6ms) SELECT
`status_histories`.* FROM `status_histories` WHERE (`key` = 'blocked_i586' and
`time` < 1478552399) ORDER BY `status_histories`.`time` ASC
[9713:5.38]  (0.2ms) SELECT MIN(`status_histories`.`time`)
FROM `status_histories`
[9713:5.38]  (0.2ms) SELECT MAX(`status_histories`.`time`) FROM
`status_histories`
[9713:5.39] StatusHistory Load (5.1ms) SELECT
`status_histories`.* FROM `status_histories` WHERE (`key` = 'blocked_i586' and
`time` < 1479070799) ORDER BY `status_histories`.`time` ASC
[9713:5.40]  (0.2ms) SELECT MIN(`status_histories`.`time`) FROM
`status_histories`
[9713:5.42] scaling blocked_i586 1479067200 2 2016-11-13 20:30:00 +0000 2.0
[9713:5.42] SQL (0.3ms) DELETE FROM `status_histories`
WHERE `status_histories`.`id` IN (18218353, 18174842)
[9713:5.42] SQL (0.2ms) INSERT INTO `status_histories` (`key`,
`time`, `value`) VALUES ('blocked_i586', 1479069000, 2.0)
[9713:5.42]  (0.2ms) SELECT MAX(`status_histories`.`time`)
FROM `status_histories`
[9713:5.43] StatusHistory Load (5.5ms) SELECT
`status_histories`.* FROM `status_histories` WHERE (`key` = 'blocked_i586' and
`time` < 1479149999) ORDER BY `status_histories`.`time` ASC
[9724:1.47]  (107.4ms) COMMIT
[ActiveJob] [9724:1.47]  (0.1ms) BEGIN
[ActiveJob] [9724:1.47] SQL (0.2ms) INSERT INTO
`delayed_jobs` (`queue`, `handler`, `run_at`) VALUES ('default', '---
!ruby/object:ActiveJob::QueueAdapters::DelayedJobAdapter::JobWrapper\njob_data:\n
job_class: CleanupEvents\n job_id: d71f42b3-42d2-4f6a-902c-55d2920bf2d8\n
queue_name: default\n arguments: []\n locale: :en\n', '2016-11-14
21:00:00')
[9713:5.45]  (0.2ms) SELECT MIN(`status_histories`.`time`)
FROM `status_histories`
[ActiveJob] [9724:1.68]  (205.3ms) COMMIT
[ActiveJob] [9724:1.68] Enqueued CleanupEvents (Job ID:
d71f42b3-42d2-4f6a-902c-55d2920bf2d8) to DelayedJob(default)
[9724:1.68] User Load (0.6ms) SELECT `users`.* FROM
`users` WHERE `users`.`login` = 'Admin' LIMIT 1
[ActiveJob] [9724:1.69]  (0.1ms) BEGIN
[ActiveJob] [9724:1.69] SQL (0.2ms) INSERT INTO
`delayed_jobs` (`queue`, `handler`, `run_at`) VALUES ('default', '---
!ruby/object:ActiveJob::QueueAdapters::DelayedJobAdapter::JobWrapper\njob_data:\n
job_class: ConsistencyCheckJob\n job_id:
b7bc9da8-1632-4056-8d76-d2cea36ddbf6\n queue_name: default\n arguments: []\n
locale: :en\n', '2016-11-14 21:00:00')
[ActiveJob] [9724:1.78]  (88.1ms) COMMIT
[ActiveJob] [9724:1.78] Enqueued ConsistencyCheckJob (Job ID:
b7bc9da8-1632-4056-8d76-d2cea36ddbf6) to DelayedJob(default)
[9724:1.78]  (0.1ms) BEGIN
[9724:1.78] SQL (0.2ms) INSERT INTO `delayed_jobs` (`handler`,
`queue`, `run_at`) VALUES ('---
!ruby/object:Delayed::PerformableMethod\nobject:
!ruby/object:ConsistencyCheckJob\n arguments: []\n job_id:
b7bc9da8-1632-4056-8d76-d2cea36ddbf6\n queue_name: default\nmethod_name:
:perform\nargs: []\n', 'default', '2016-11-14 21:00:00')
[9713:5.77] scaling blocked_i586 1479149600 3 2016-11-14 18:55:00 +0000 2.0
[9713:5.77] SQL (0.3ms) DELETE FROM `status_histories` WHERE
`status_histories`.`id` IN (18218365, 18214573, 18214587)
[9713:5.77] SQL (0.2ms) INSERT INTO `status_histories`
(`key`, `time`, `value`) VALUES ('blocked_i586', 1479149700, 2.0)
[9713:5.78] scaling blocked_i586 1479149800 7 2016-11-14 18:58:20 +0000 2.0
[9713:5.78] SQL (0.3ms) DELETE FROM `status_histories` WHERE
`status_histories`.`id` IN (18214601, 18214615, 18214629, 18214643, 18214657,
18214671, 18214685)
[9713:5.78] SQL (0.3ms) INSERT INTO `status_histories`
(`key`, `time`, `value`) VALUES ('blocked_i586', 1479149900, 2.0)
[9724:1.87]  (88.2ms) COMMIT
[9713:5.87]  (91.8ms) COMMIT
[9713:5.87]  (0.2ms) BEGIN
[9713:5.87]  (0.5ms) SELECT MAX(`status_histories`.`time`) FROM
`status_histories`
[9713:5.88] StatusHistory Load (7.5ms) SELECT
`status_histories`.* FROM `status_histories` WHERE (`key` = 'blocked_x86_64'
and `time` < 1476565199) ORDER BY `status_histories`.`time` ASC
[9713:5.89]  (0.2ms) SELECT MIN(`status_histories`.`time`) FROM
`status_histories`
[9713:5.90]  (0.2ms) SELECT MAX(`status_histories`.`time`)
FROM `status_histories`
[9713:5.90] StatusHistory Load (5.1ms) SELECT
`status_histories`.* FROM `status_histories` WHERE (`key` = 'blocked_x86_64'
and `time` < 1478552399) ORDER BY `status_histories`.`time` ASC
[9713:5.91]  (0.2ms) SELECT MIN(`status_histories`.`time`)
FROM `status_histories`
[9713:5.92]  (0.2ms) SELECT MAX(`status_histories`.`time`) FROM
`status_histories`
[9713:5.92] StatusHistory Load (5.2ms) SELECT
`status_histories`.* FROM `status_histories` WHERE (`key` = 'blocked_x86_64'
and `time` < 1479070799) ORDER BY `status_histories`.`time` ASC
[9713:5.94]  (0.2ms) SELECT MIN(`status_histories`.`time`) FROM
`status_histories`
[9713:5.96] scaling blocked_x86_64 1479067200 2 2016-11-13 20:30:00 +0000 0.0
[9713:5.96] SQL (0.3ms) DELETE FROM `status_histories`
WHERE `status_histories`.`id` IN (18218366, 18174859)
[9713:5.96] SQL (0.2ms) INSERT INTO `status_histories` (`key`,
`time`, `value`) VALUES ('blocked_x86_64', 1479069000, 0.0)
[9713:5.96]  (0.2ms) SELECT MAX(`status_histories`.`time`)
FROM `status_histories`
[9713:5.97] StatusHistory Load (5.8ms) SELECT
`status_histories`.* FROM `status_histories` WHERE (`key` = 'blocked_x86_64'
and `time` < 1479149999) ORDER BY `status_histories`.`time` ASC
[9713:5.99]  (0.3ms) SELECT MIN(`status_histories`.`time`)
FROM `status_histories`
[9698:10.03] SQL (0.8ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:01', `delayed_jobs`.`locked_by`
= 'delayed_job.1020 host:obs pid:9698' WHERE ((run_at <= '2016-11-14
21:00:01.102318' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:01.102373') OR locked_by = 'delayed_job.1020 host:obs pid:9698') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'mailers' ORDER BY priority
ASC, run_at ASC LIMIT 1
[9713:6.27] scaling blocked_x86_64 1479149600 3 2016-11-14 18:55:00 +0000 0.0
[9713:6.27] SQL (0.4ms) DELETE FROM `status_histories` WHERE
`status_histories`.`id` IN (18218378, 18214574, 18214588)
[9713:6.27] SQL (0.2ms) INSERT INTO `status_histories`
(`key`, `time`, `value`) VALUES ('blocked_x86_64', 1479149700, 0.0)
[9713:6.27] scaling blocked_x86_64 1479149800 7 2016-11-14 18:58:20 +0000 0.0
[9713:6.27] SQL (0.4ms) DELETE FROM `status_histories` WHERE
`status_histories`.`id` IN (18214602, 18214616, 18214630, 18214644, 18214658,
18214672, 18214686)
[9713:6.28] SQL (0.2ms) INSERT INTO `status_histories`
(`key`, `time`, `value`) VALUES ('blocked_x86_64', 1479149900, 0.0)
[9713:6.34]  (59.1ms) COMMIT
[9713:6.34]  (0.3ms) BEGIN
[9713:6.34]  (1.9ms) SELECT MAX(`status_histories`.`time`) FROM
`status_histories`
[9713:6.35] StatusHistory Load (7.1ms) SELECT
`status_histories`.* FROM `status_histories` WHERE (`key` = 'building_x86_64'
and `time` < 1476565199) ORDER BY `status_histories`.`time` ASC
[9713:6.36]  (0.3ms) SELECT MIN(`status_histories`.`time`) FROM
`status_histories`
[9713:6.36]  (0.2ms) SELECT MAX(`status_histories`.`time`)
FROM `status_histories`
[9713:6.36] StatusHistory Load (4.0ms) SELECT
`status_histories`.* FROM `status_histories` WHERE (`key` = 'building_x86_64'
and `time` < 1478552399) ORDER BY `status_histories`.`time` ASC
[9713:6.37]  (0.2ms) SELECT MIN(`status_histories`.`time`)
FROM `status_histories`
[9713:6.38]  (0.2ms) SELECT MAX(`status_histories`.`time`) FROM
`status_histories`
[9713:6.38] StatusHistory Load (4.1ms) SELECT
`status_histories`.* FROM `status_histories` WHERE (`key` = 'building_x86_64'
and `time` < 1479070799) ORDER BY `status_histories`.`time` ASC
[9713:6.40]  (0.2ms) SELECT MIN(`status_histories`.`time`) FROM
`status_histories`
[9713:6.41] scaling building_x86_64 1479067200 2 2016-11-13 20:30:00 +0000 0.0
[9713:6.42] SQL (0.3ms) DELETE FROM `status_histories`
WHERE `status_histories`.`id` IN (18218379, 18174876)
[9713:6.42] SQL (0.2ms) INSERT INTO `status_histories` (`key`,
`time`, `value`) VALUES ('building_x86_64', 1479069000, 0.0)
[9713:6.42]  (0.3ms) SELECT MAX(`status_histories`.`time`)
FROM `status_histories`
[9713:6.42] StatusHistory Load (4.9ms) SELECT
`status_histories`.* FROM `status_histories` WHERE (`key` = 'building_x86_64'
and `time` < 1479149999) ORDER BY `status_histories`.`time` ASC
[9713:6.45]  (0.3ms) SELECT MIN(`status_histories`.`time`)
FROM `status_histories`
[9713:6.72] scaling building_x86_64 1479149600 3 2016-11-14 18:55:00 +0000 0.0
[9713:6.72] SQL (0.3ms) DELETE FROM `status_histories` WHERE
`status_histories`.`id` IN (18218391, 18214577, 18214591)
[9713:6.72] SQL (0.2ms) INSERT INTO `status_histories`
(`key`, `time`, `value`) VALUES ('building_x86_64', 1479149700, 0.0)
[9713:6.72] scaling building_x86_64 1479149800 7 2016-11-14 18:58:20 +0000 0.0
[9713:6.72] SQL (0.3ms) DELETE FROM `status_histories` WHERE
`status_histories`.`id` IN (18214605, 18214619, 18214633, 18214647, 18214661,
18214675, 18214689)
[9713:6.72] SQL (0.2ms) INSERT INTO `status_histories`
(`key`, `time`, `value`) VALUES ('building_x86_64', 1479149900, 0.0)
[9713:6.79]  (72.3ms) COMMIT
[9713:6.80]  (0.2ms) BEGIN
[9713:6.80]  (0.6ms) SELECT MAX(`status_histories`.`time`) FROM
`status_histories`
[9713:6.80] StatusHistory Load (5.5ms) SELECT
`status_histories`.* FROM `status_histories` WHERE (`key` = 'idle_x86_64' and
`time` < 1476565199) ORDER BY `status_histories`.`time` ASC
[9713:6.81]  (0.2ms) SELECT MIN(`status_histories`.`time`) FROM
`status_histories`
[9713:6.81]  (0.2ms) SELECT MAX(`status_histories`.`time`)
FROM `status_histories`
[9713:6.82] StatusHistory Load (3.9ms) SELECT
`status_histories`.* FROM `status_histories` WHERE (`key` = 'idle_x86_64' and
`time` < 1478552399) ORDER BY `status_histories`.`time` ASC
[9713:6.83]  (0.2ms) SELECT MIN(`status_histories`.`time`)
FROM `status_histories`
[9713:6.83]  (0.2ms) SELECT MAX(`status_histories`.`time`) FROM
`status_histories`
[9713:6.84] StatusHistory Load (4.0ms) SELECT
`status_histories`.* FROM `status_histories` WHERE (`key` = 'idle_x86_64' and
`time` < 1479070799) ORDER BY `status_histories`.`time` ASC
[9713:6.85]  (0.2ms) SELECT MIN(`status_histories`.`time`) FROM
`status_histories`
[9713:6.86] scaling idle_x86_64 1479067200 2 2016-11-13 20:30:00 +0000 6.0
[9713:6.86] SQL (0.3ms) DELETE FROM `status_histories`
WHERE `status_histories`.`id` IN (18218392, 18174893)
[9713:6.87] SQL (0.2ms) INSERT INTO `status_histories` (`key`,
`time`, `value`) VALUES ('idle_x86_64', 1479069000, 6.0)
[9713:6.87]  (0.2ms) SELECT MAX(`status_histories`.`time`)
FROM `status_histories`
[9713:6.87] StatusHistory Load (4.6ms) SELECT
`status_histories`.* FROM `status_histories` WHERE (`key` = 'idle_x86_64' and
`time` < 1479149999) ORDER BY `status_histories`.`time` ASC
[9713:6.89]  (0.3ms) SELECT MIN(`status_histories`.`time`)
FROM `status_histories`
[9683:15.03] SQL (0.4ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:02', `delayed_jobs`.`locked_by`
= 'delayed_job.1010 host:obs pid:9683' WHERE ((run_at <= '2016-11-14
21:00:02.092324' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:02.092371') OR locked_by = 'delayed_job.1010 host:obs pid:9683') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'issuetracking' ORDER BY
priority ASC, run_at ASC LIMIT 1
[9713:7.17] scaling idle_x86_64 1479149600 3 2016-11-14 18:55:00 +0000 6.0
[9713:7.18] SQL (0.4ms) DELETE FROM `status_histories` WHERE
`status_histories`.`id` IN (18218404, 18214578, 18214592)
[9713:7.18] SQL (0.2ms) INSERT INTO `status_histories`
(`key`, `time`, `value`) VALUES ('idle_x86_64', 1479149700, 6.0)
[9713:7.18] scaling idle_x86_64 1479149800 7 2016-11-14 18:58:20 +0000 6.0
[9713:7.18] SQL (0.4ms) DELETE FROM `status_histories` WHERE
`status_histories`.`id` IN (18214606, 18214620, 18214634, 18214648, 18214662,
18214676, 18214690)
[9713:7.18] SQL (0.2ms) INSERT INTO `status_histories`
(`key`, `time`, `value`) VALUES ('idle_x86_64', 1479149900, 6.0)
[9713:7.39]  (214.6ms) COMMIT
[9713:7.40]  (0.4ms) BEGIN
[9713:7.40]  (0.7ms) SELECT MAX(`status_histories`.`time`) FROM
`status_histories`
[9713:7.41] StatusHistory Load (5.7ms) SELECT
`status_histories`.* FROM `status_histories` WHERE (`key` = 'squeue_high_i586'
and `time` < 1476565199) ORDER BY `status_histories`.`time` ASC
[9713:7.42]  (0.2ms) SELECT MIN(`status_histories`.`time`) FROM
`status_histories`
[9713:7.42]  (0.2ms) SELECT MAX(`status_histories`.`time`)
FROM `status_histories`
[9713:7.43] StatusHistory Load (4.9ms) SELECT
`status_histories`.* FROM `status_histories` WHERE (`key` = 'squeue_high_i586'
and `time` < 1478552399) ORDER BY `status_histories`.`time` ASC
[9713:7.44]  (0.3ms) SELECT MIN(`status_histories`.`time`)
FROM `status_histories`
[9713:7.44]  (0.2ms) SELECT MAX(`status_histories`.`time`) FROM
`status_histories`
[9713:7.45] StatusHistory Load (5.4ms) SELECT
`status_histories`.* FROM `status_histories` WHERE (`key` = 'squeue_high_i586'
and `time` < 1479070799) ORDER BY `status_histories`.`time` ASC
[9713:7.46]  (0.3ms) SELECT MIN(`status_histories`.`time`) FROM
`status_histories`
[9713:7.48] scaling squeue_high_i586 1479067200 2 2016-11-13 20:30:00 +0000 0.0
[9713:7.56] SQL (75.7ms) DELETE FROM `status_histories`
WHERE `status_histories`.`id` IN (18218405, 18174910)
[9713:7.65] SQL (91.7ms) INSERT INTO `status_histories` (`key`,
`time`, `value`) VALUES ('squeue_high_i586', 1479069000, 0.0)
[9713:7.65]  (0.2ms) SELECT MAX(`status_histories`.`time`)
FROM `status_histories`
[9713:7.66] StatusHistory Load (6.0ms) SELECT
`status_histories`.* FROM `status_histories` WHERE (`key` = 'squeue_high_i586'
and `time` < 1479149999) ORDER BY `status_histories`.`time` ASC
[9713:7.68]  (0.3ms) SELECT MIN(`status_histories`.`time`)
FROM `status_histories`
[9713:7.98] scaling squeue_high_i586 1479149600 3 2016-11-14 18:55:00 +0000 0.0
[9670:20.03] SQL (0.4ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:03', `delayed_jobs`.`locked_by`
= 'delayed_job.1000 host:obs pid:9670' WHERE ((run_at <= '2016-11-14
21:00:03.106088' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:03.106144') OR locked_by = 'delayed_job.1000 host:obs pid:9670') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'releasetracking' ORDER BY
priority ASC, run_at ASC LIMIT 1
[9713:8.05] SQL (66.7ms) DELETE FROM `status_histories` WHERE
`status_histories`.`id` IN (18218417, 18214579, 18214593)
[9713:8.05] SQL (0.2ms) INSERT INTO `status_histories`
(`key`, `time`, `value`) VALUES ('squeue_high_i586', 1479149700, 0.0)
[9713:8.05] scaling squeue_high_i586 1479149800 7 2016-11-14 18:58:20 +0000 0.0
[9713:8.05] SQL (0.3ms) DELETE FROM `status_histories` WHERE
`status_histories`.`id` IN (18214607, 18214621, 18214635, 18214649, 18214663,
18214677, 18214691)
[9713:8.05] SQL (0.2ms) INSERT INTO `status_histories`
(`key`, `time`, `value`) VALUES ('squeue_high_i586', 1479149900, 0.0)
[9713:8.80]  (748.1ms) COMMIT
[9713:8.80]  (0.3ms) BEGIN
[9641:25.15] SQL (115.7ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:03', `delayed_jobs`.`locked_by`
= 'delayed_job.0 host:obs pid:9641' WHERE ((run_at <= '2016-11-14
21:00:03.920962' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:03.921061') OR locked_by = 'delayed_job.0 host:obs pid:9641') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'quick' ORDER BY priority ASC,
run_at ASC LIMIT 1
[9641:25.16] Delayed::Backend::ActiveRecord::Job Load (0.5ms)
SELECT `delayed_jobs`.* FROM `delayed_jobs` WHERE
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:03' AND
`delayed_jobs`.`locked_by` = 'delayed_job.0 host:obs pid:9641' AND
`delayed_jobs`.`failed_at` IS NULL ORDER BY `delayed_jobs`.`id` ASC LIMIT 1
[9641:25.17] 2016-11-14T21:00:04+0000: [Worker(delayed_job.0 host:obs
pid:9641)] Job Event::NotifyBackends#send_not_in_queue (id=72922) RUNNING
[9647:25.89] SQL (819.6ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:04', `delayed_jobs`.`locked_by`
= 'delayed_job.1 host:obs pid:9647' WHERE ((run_at <= '2016-11-14
21:00:04.077085' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:04.077129') OR locked_by = 'delayed_job.1 host:obs pid:9647') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'quick' ORDER BY priority ASC,
run_at ASC LIMIT 1
[9654:25.77] SQL (739.6ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:04', `delayed_jobs`.`locked_by`
= 'delayed_job.2 host:obs pid:9654' WHERE ((run_at <= '2016-11-14
21:00:04.160885' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:04.160943') OR locked_by = 'delayed_job.2 host:obs pid:9654') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'quick' ORDER BY priority ASC,
run_at ASC LIMIT 1
[9654:25.78] Delayed::Backend::ActiveRecord::Job Load (1.2ms)
SELECT `delayed_jobs`.* FROM `delayed_jobs` WHERE
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:04' AND
`delayed_jobs`.`locked_by` = 'delayed_job.2 host:obs pid:9654' AND
`delayed_jobs`.`failed_at` IS NULL ORDER BY `delayed_jobs`.`id` ASC LIMIT 1
[9647:25.91] Delayed::Backend::ActiveRecord::Job Load (10.4ms)
SELECT `delayed_jobs`.* FROM `delayed_jobs` WHERE
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:04' AND
`delayed_jobs`.`locked_by` = 'delayed_job.1 host:obs pid:9647' AND
`delayed_jobs`.`failed_at` IS NULL ORDER BY `delayed_jobs`.`id` ASC LIMIT 1
[9654:25.79] 2016-11-14T21:00:04+0000: [Worker(delayed_job.2 host:obs
pid:9654)] Job FullTextSearch#index_and_start (id=72924) RUNNING
[9647:25.92] 2016-11-14T21:00:04+0000: [Worker(delayed_job.1 host:obs
pid:9647)] Job SendEventEmails#perform (id=72923) RUNNING
[9647:25.92] Event::Base Load (2.1ms) SELECT `events`.* FROM
`events` WHERE `events`.`mails_sent` = 0 ORDER BY `events`.`created_at` ASC
LIMIT 1000 FOR UPDATE
[9647:25.93]  (0.1ms) BEGIN
[9647:25.93] SQL (0.2ms) DELETE FROM `delayed_jobs` WHERE
`delayed_jobs`.`id` = 72923
[9647:26.07]  (141.9ms) COMMIT
[9647:26.07] 2016-11-14T21:00:05+0000: [Worker(delayed_job.1 host:obs
pid:9647)] Job SendEventEmails#perform (id=72923) COMPLETED after 0.1510
[9641:26.24] Event::Base Load (3.7ms) SELECT `events`.* FROM
`events` WHERE `events`.`queued` = 0 ORDER BY `events`.`id` ASC LIMIT 1000
[9641:26.24]  (0.1ms) BEGIN
[9641:26.25] SQL (1.2ms) DELETE FROM `delayed_jobs` WHERE
`delayed_jobs`.`id` = 72922
[9654:26.02] Cache read: forbidden_projects
[9654:26.02] Dalli::Server#connect 127.0.0.1:11211
[9654:26.03] Cache fetch_hit: forbidden_projects
[9647:26.24] SQL (169.9ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:05', `delayed_jobs`.`locked_by`
= 'delayed_job.1 host:obs pid:9647' WHERE ((run_at <= '2016-11-14
21:00:05.073220' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:05.073251') OR locked_by = 'delayed_job.1 host:obs pid:9647') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'quick' ORDER BY priority ASC,
run_at ASC LIMIT 1
[9647:26.24] Delayed::Backend::ActiveRecord::Job Load (0.7ms)
SELECT `delayed_jobs`.* FROM `delayed_jobs` WHERE
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:05' AND
`delayed_jobs`.`locked_by` = 'delayed_job.1 host:obs pid:9647' AND
`delayed_jobs`.`failed_at` IS NULL ORDER BY `delayed_jobs`.`id` ASC LIMIT 1
[9647:26.24] 2016-11-14T21:00:05+0000: [Worker(delayed_job.1 host:obs
pid:9647)] Job ProjectLogRotate#perform (id=72925) RUNNING
[9647:26.25]  (0.2ms) BEGIN
[9641:26.46]  (213.3ms) COMMIT
[9641:26.46] 2016-11-14T21:00:05+0000: [Worker(delayed_job.0 host:obs
pid:9641)] Job Event::NotifyBackends#send_not_in_queue (id=72922) COMPLETED
after 1.2941
[9641:26.46] SQL (0.4ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:05', `delayed_jobs`.`locked_by`
= 'delayed_job.0 host:obs pid:9641' WHERE ((run_at <= '2016-11-14
21:00:05.351184' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:05.351242') OR locked_by = 'delayed_job.0 host:obs pid:9641') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'quick' ORDER BY priority ASC,
run_at ASC LIMIT 1
[9641:26.46] 2016-11-14T21:00:05+0000: [Worker(delayed_job.0 host:obs
pid:9641)] 1 jobs processed at 0.6982 j/s, 0 failed
[9641:26.47] SQL (0.3ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:05', `delayed_jobs`.`locked_by`
= 'delayed_job.0 host:obs pid:9641' WHERE ((run_at <= '2016-11-14
21:00:05.353200' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:05.353217') OR locked_by = 'delayed_job.0 host:obs pid:9641') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'quick' ORDER BY priority ASC,
run_at ASC LIMIT 1
[9647:26.44] SQL (0.5ms) UPDATE `events` SET
`events`.`project_logged` = 1 WHERE `events`.`project_logged` = 0 AND
(created_at < '2016-11-04 21:00:05.247973')
[9647:26.44] Event::Package Load (0.7ms) SELECT `events`.*
FROM `events` WHERE `events`.`eventtype` IN ('Event::Package',
'Event::CreatePackage', 'Event::UpdatePackage', 'Event::UndeletePackage',
'Event::DeletePackage', 'Event::BranchCommand', 'Event::VersionChange',
'Event::Commit', 'Event::Upload', 'Event::ServiceSuccess',
'Event::ServiceFail', 'Event::CommentForPackage', 'Event::Build',
'Event::BuildSuccess', 'Event::BuildFail', 'Event::BuildUnchanged') AND
`events`.`project_logged` = 0 ORDER BY `events`.`id` ASC LIMIT 10000
[9647:26.47]  (0.2ms) SELECT `projects`.`id` FROM
`projects` WHERE `projects`.`name` IS NULL
[9647:26.47] BsRequest Load (0.3ms) SELECT `bs_requests`.*
FROM `bs_requests` WHERE `bs_requests`.`number` IS NULL LIMIT 1
[9724:0.00]  (5732.0ms) optimize table status_histories;
[9713:10.70]  (1897.9ms) SELECT MAX(`status_histories`.`time`)
FROM `status_histories`
[9713:10.71] StatusHistory Load (13.2ms) SELECT
`status_histories`.* FROM `status_histories` WHERE (`key` =
'squeue_high_x86_64' and `time` < 1476565199) ORDER BY
`status_histories`.`time` ASC
[9647:26.79] SQL (0.2ms) UPDATE `events` SET
`events`.`project_logged` = 1 WHERE 1=0
[9647:26.79] Event::Project Load (0.4ms) SELECT `events`.*
FROM `events` WHERE `events`.`eventtype` IN ('Event::Project',
'Event::CreateProject', 'Event::UpdateProjectConfig', 'Event::UndeleteProject',
'Event::UpdateProject', 'Event::DeleteProject', 'Event::CommentForProject') AND
`events`.`project_logged` = 0 ORDER BY `events`.`id` ASC LIMIT 10000
[9647:26.79]  (0.1ms) COMMIT
[9647:26.79] SQL (0.2ms) DELETE FROM `project_log_entries`
WHERE (datetime < '2016-11-04 21:00:05.247973')
[9647:26.79]  (0.1ms) BEGIN
[9713:10.72]  (0.2ms) SELECT MIN(`status_histories`.`time`)
FROM `status_histories`
[9713:10.73]  (0.2ms) SELECT MAX(`status_histories`.`time`)
FROM `status_histories`
[9713:10.73] StatusHistory Load (6.0ms) SELECT
`status_histories`.* FROM `status_histories` WHERE (`key` =
'squeue_high_x86_64' and `time` < 1478552399) ORDER BY
`status_histories`.`time` ASC
[9647:26.81] SQL (20.9ms) DELETE FROM `delayed_jobs` WHERE
`delayed_jobs`.`id` = 72925
[9713:10.75]  (0.2ms) SELECT MIN(`status_histories`.`time`)
FROM `status_histories`
[9713:10.75]  (0.2ms) SELECT MAX(`status_histories`.`time`)
FROM `status_histories`
[9713:10.76] StatusHistory Load (5.4ms) SELECT
`status_histories`.* FROM `status_histories` WHERE (`key` =
'squeue_high_x86_64' and `time` < 1479070799) ORDER BY
`status_histories`.`time` ASC
[9713:10.77]  (0.2ms) SELECT MIN(`status_histories`.`time`)
FROM `status_histories`
[9647:26.85]  (41.2ms) COMMIT
[9647:26.85] 2016-11-14T21:00:05+0000: [Worker(delayed_job.1 host:obs
pid:9647)] Job ProjectLogRotate#perform (id=72925) COMPLETED after 0.6085
[9647:26.86] SQL (0.4ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:05', `delayed_jobs`.`locked_by`
= 'delayed_job.1 host:obs pid:9647' WHERE ((run_at <= '2016-11-14
21:00:05.856418' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:05.856450') OR locked_by = 'delayed_job.1 host:obs pid:9647') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'quick' ORDER BY priority ASC,
run_at ASC LIMIT 1
[9647:26.86] 2016-11-14T21:00:05+0000: [Worker(delayed_job.1 host:obs
pid:9647)] 2 jobs processed at 1.1230 j/s, 0 failed
[9647:26.86] SQL (0.2ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:05', `delayed_jobs`.`locked_by`
= 'delayed_job.1 host:obs pid:9647' WHERE ((run_at <= '2016-11-14
21:00:05.858169' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:05.858186') OR locked_by = 'delayed_job.1 host:obs pid:9647') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'quick' ORDER BY priority ASC,
run_at ASC LIMIT 1
[9713:10.79] scaling squeue_high_x86_64 1479067200 2 2016-11-13 20:30:00 +0000
0.0
[9713:10.79] SQL (0.3ms) DELETE FROM `status_histories`
WHERE `status_histories`.`id` IN (18218418, 18174927)
[9698:15.03] SQL (0.5ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:06', `delayed_jobs`.`locked_by`
= 'delayed_job.1020 host:obs pid:9698' WHERE ((run_at <= '2016-11-14
21:00:06.104976' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:06.105044') OR locked_by = 'delayed_job.1020 host:obs pid:9698') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'mailers' ORDER BY priority
ASC, run_at ASC LIMIT 1
[9713:11.35] SQL (559.4ms) INSERT INTO `status_histories`
(`key`, `time`, `value`) VALUES ('squeue_high_x86_64', 1479069000, 0.0)
[9713:11.35]  (0.3ms) SELECT MAX(`status_histories`.`time`)
FROM `status_histories`
[9713:11.36] StatusHistory Load (8.3ms) SELECT
`status_histories`.* FROM `status_histories` WHERE (`key` =
'squeue_high_x86_64' and `time` < 1479149999) ORDER BY
`status_histories`.`time` ASC
[9713:11.39]  (0.3ms) SELECT MIN(`status_histories`.`time`)
FROM `status_histories`
[9654:27.40]  (0.3ms) BEGIN
[9654:27.40] SQL (0.6ms) DELETE FROM `delayed_jobs` WHERE
`delayed_jobs`.`id` = 72924
[9654:27.50]  (102.3ms) COMMIT
[9654:27.50] 2016-11-14T21:00:06+0000: [Worker(delayed_job.2 host:obs
pid:9654)] Job FullTextSearch#index_and_start (id=72924) COMPLETED after 1.7130
[9654:27.51] SQL (0.6ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:06', `delayed_jobs`.`locked_by`
= 'delayed_job.2 host:obs pid:9654' WHERE ((run_at <= '2016-11-14
21:00:06.632012' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:06.632063') OR locked_by = 'delayed_job.2 host:obs pid:9654') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'quick' ORDER BY priority ASC,
run_at ASC LIMIT 1
[9654:27.51] 2016-11-14T21:00:06+0000: [Worker(delayed_job.2 host:obs
pid:9654)] 1 jobs processed at 0.4042 j/s, 0 failed
[9654:27.51] SQL (0.4ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:06', `delayed_jobs`.`locked_by`
= 'delayed_job.2 host:obs pid:9654' WHERE ((run_at <= '2016-11-14
21:00:06.635060' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:06.635092') OR locked_by = 'delayed_job.2 host:obs pid:9654') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'quick' ORDER BY priority ASC,
run_at ASC LIMIT 1
[9713:11.66] scaling squeue_high_x86_64 1479149600 3 2016-11-14 18:55:00 +0000
0.0
[9713:11.67] SQL (0.4ms) DELETE FROM `status_histories` WHERE
`status_histories`.`id` IN (18218430, 18214583, 18214597)
[9713:11.67] SQL (0.2ms) INSERT INTO `status_histories`
(`key`, `time`, `value`) VALUES ('squeue_high_x86_64', 1479149700, 0.0)
[9713:11.67] scaling squeue_high_x86_64 1479149800 7 2016-11-14 18:58:20 +0000
0.0
[9713:11.67] SQL (0.3ms) DELETE FROM `status_histories` WHERE
`status_histories`.`id` IN (18214611, 18214625, 18214639, 18214653, 18214667,
18214681, 18214695)
[9713:11.67] SQL (0.2ms) INSERT INTO `status_histories`
(`key`, `time`, `value`) VALUES ('squeue_high_x86_64', 1479149900, 0.0)
[9713:11.72]  (48.0ms) COMMIT
[9713:11.72]  (0.2ms) BEGIN
[9713:11.72]  (0.6ms) SELECT MAX(`status_histories`.`time`)
FROM `status_histories`
[9713:11.73] StatusHistory Load (7.3ms) SELECT
`status_histories`.* FROM `status_histories` WHERE (`key` = 'squeue_low_i586'
and `time` < 1476565199) ORDER BY `status_histories`.`time` ASC
[9713:11.74]  (0.2ms) SELECT MIN(`status_histories`.`time`)
FROM `status_histories`
[9713:11.75]  (0.2ms) SELECT MAX(`status_histories`.`time`)
FROM `status_histories`
[9713:11.75] StatusHistory Load (4.9ms) SELECT
`status_histories`.* FROM `status_histories` WHERE (`key` = 'squeue_low_i586'
and `time` < 1478552399) ORDER BY `status_histories`.`time` ASC
[9713:11.76]  (0.2ms) SELECT MIN(`status_histories`.`time`)
FROM `status_histories`
[9713:11.77]  (0.2ms) SELECT MAX(`status_histories`.`time`)
FROM `status_histories`
[9713:11.77] StatusHistory Load (5.2ms) SELECT
`status_histories`.* FROM `status_histories` WHERE (`key` = 'squeue_low_i586'
and `time` < 1479070799) ORDER BY `status_histories`.`time` ASC
[9713:11.79]  (0.2ms) SELECT MIN(`status_histories`.`time`)
FROM `status_histories`
[9713:11.81] scaling squeue_low_i586 1479067200 2 2016-11-13 20:30:00 +0000 1.0
[9713:11.81] SQL (0.3ms) DELETE FROM `status_histories`
WHERE `status_histories`.`id` IN (18218431, 18174944)
[9713:11.81] SQL (0.3ms) INSERT INTO `status_histories` (`key`,
`time`, `value`) VALUES ('squeue_low_i586', 1479069000, 1.0)
[9713:11.81]  (0.2ms) SELECT MAX(`status_histories`.`time`)
FROM `status_histories`
[9713:11.82] StatusHistory Load (5.6ms) SELECT
`status_histories`.* FROM `status_histories` WHERE (`key` = 'squeue_low_i586'
and `time` < 1479149999) ORDER BY `status_histories`.`time` ASC
[9713:11.84]  (0.2ms) SELECT MIN(`status_histories`.`time`)
FROM `status_histories`
[9683:20.04] SQL (0.4ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:07', `delayed_jobs`.`locked_by`
= 'delayed_job.1010 host:obs pid:9683' WHERE ((run_at <= '2016-11-14
21:00:07.094156' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:07.094205') OR locked_by = 'delayed_job.1010 host:obs pid:9683') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'issuetracking' ORDER BY
priority ASC, run_at ASC LIMIT 1
[9713:12.11] scaling squeue_low_i586 1479149600 3 2016-11-14 18:55:00 +0000 1.0
[9713:12.11] SQL (0.6ms) DELETE FROM `status_histories` WHERE
`status_histories`.`id` IN (18218443, 18214582, 18214596)
[9713:12.11] SQL (0.3ms) INSERT INTO `status_histories`
(`key`, `time`, `value`) VALUES ('squeue_low_i586', 1479149700, 1.0)
[9713:12.11] scaling squeue_low_i586 1479149800 7 2016-11-14 18:58:20 +0000 1.0
[9713:12.11] SQL (0.5ms) DELETE FROM `status_histories` WHERE
`status_histories`.`id` IN (18214610, 18214624, 18214638, 18214652, 18214666,
18214680, 18214694)
[9713:12.11] SQL (0.3ms) INSERT INTO `status_histories`
(`key`, `time`, `value`) VALUES ('squeue_low_i586', 1479149900, 1.0)
[9713:12.20]  (88.3ms) COMMIT
[9713:12.20]  (0.2ms) BEGIN
[9713:12.21]  (0.8ms) SELECT MAX(`status_histories`.`time`)
FROM `status_histories`
[9713:12.21] StatusHistory Load (8.4ms) SELECT
`status_histories`.* FROM `status_histories` WHERE (`key` = 'squeue_low_x86_64'
and `time` < 1476565199) ORDER BY `status_histories`.`time` ASC
[9713:12.22]  (0.2ms) SELECT MIN(`status_histories`.`time`)
FROM `status_histories`
[9713:12.23]  (0.2ms) SELECT MAX(`status_histories`.`time`)
FROM `status_histories`
[9713:12.23] StatusHistory Load (4.8ms) SELECT
`status_histories`.* FROM `status_histories` WHERE (`key` = 'squeue_low_x86_64'
and `time` < 1478552399) ORDER BY `status_histories`.`time` ASC
[9713:12.24]  (0.2ms) SELECT MIN(`status_histories`.`time`)
FROM `status_histories`
[9713:12.25]  (0.2ms) SELECT MAX(`status_histories`.`time`)
FROM `status_histories`
[9713:12.26] StatusHistory Load (5.1ms) SELECT
`status_histories`.* FROM `status_histories` WHERE (`key` = 'squeue_low_x86_64'
and `time` < 1479070799) ORDER BY `status_histories`.`time` ASC
[9713:12.27]  (0.2ms) SELECT MIN(`status_histories`.`time`)
FROM `status_histories`
[9713:12.29] scaling squeue_low_x86_64 1479067200 2 2016-11-13 20:30:00 +0000
1.0
[9713:12.29] SQL (0.3ms) DELETE FROM `status_histories`
WHERE `status_histories`.`id` IN (18218444, 18174961)
[9713:12.29] SQL (0.3ms) INSERT INTO `status_histories` (`key`,
`time`, `value`) VALUES ('squeue_low_x86_64', 1479069000, 1.0)
[9713:12.29]  (0.2ms) SELECT MAX(`status_histories`.`time`)
FROM `status_histories`
[9713:12.30] StatusHistory Load (5.6ms) SELECT
`status_histories`.* FROM `status_histories` WHERE (`key` = 'squeue_low_x86_64'
and `time` < 1479149999) ORDER BY `status_histories`.`time` ASC
[9713:12.33]  (0.3ms) SELECT MIN(`status_histories`.`time`)
FROM `status_histories`
[9713:12.59] scaling squeue_low_x86_64 1479149600 3 2016-11-14 18:55:00 +0000
1.0
[9713:12.59] SQL (0.3ms) DELETE FROM `status_histories` WHERE
`status_histories`.`id` IN (18218456, 18214586, 18214600)
[9713:12.59] SQL (0.2ms) INSERT INTO `status_histories`
(`key`, `time`, `value`) VALUES ('squeue_low_x86_64', 1479149700, 1.0)
[9713:12.59] scaling squeue_low_x86_64 1479149800 7 2016-11-14 18:58:20 +0000
1.0
[9713:12.59] SQL (0.3ms) DELETE FROM `status_histories` WHERE
`status_histories`.`id` IN (18214614, 18214628, 18214642, 18214656, 18214670,
18214684, 18214698)
[9713:12.60] SQL (0.2ms) INSERT INTO `status_histories`
(`key`, `time`, `value`) VALUES ('squeue_low_x86_64', 1479149900, 1.0)
[9713:12.64]  (38.8ms) COMMIT
[9713:12.64]  (0.2ms) BEGIN
[9713:12.64]  (4.2ms) SELECT MAX(`status_histories`.`time`)
FROM `status_histories`
[9713:12.65] StatusHistory Load (5.8ms) SELECT
`status_histories`.* FROM `status_histories` WHERE (`key` = 'squeue_med_i586'
and `time` < 1476565199) ORDER BY `status_histories`.`time` ASC
[9713:12.66]  (0.2ms) SELECT MIN(`status_histories`.`time`)
FROM `status_histories`
[9713:12.66]  (0.2ms) SELECT MAX(`status_histories`.`time`)
FROM `status_histories`
[9713:12.67] StatusHistory Load (4.6ms) SELECT
`status_histories`.* FROM `status_histories` WHERE (`key` = 'squeue_med_i586'
and `time` < 1478552399) ORDER BY `status_histories`.`time` ASC
[9713:12.68]  (0.2ms) SELECT MIN(`status_histories`.`time`)
FROM `status_histories`
[9713:12.69]  (0.2ms) SELECT MAX(`status_histories`.`time`)
FROM `status_histories`
[9713:12.69] StatusHistory Load (4.8ms) SELECT
`status_histories`.* FROM `status_histories` WHERE (`key` = 'squeue_med_i586'
and `time` < 1479070799) ORDER BY `status_histories`.`time` ASC
[9713:12.70]  (0.2ms) SELECT MIN(`status_histories`.`time`)
FROM `status_histories`
[9713:12.72] scaling squeue_med_i586 1479067200 2 2016-11-13 20:30:00 +0000 0.0
[9713:12.72] SQL (0.2ms) DELETE FROM `status_histories`
WHERE `status_histories`.`id` IN (18218457, 18174978)
[9713:12.72] SQL (0.4ms) INSERT INTO `status_histories` (`key`,
`time`, `value`) VALUES ('squeue_med_i586', 1479069000, 0.0)
[9713:12.73]  (0.2ms) SELECT MAX(`status_histories`.`time`)
FROM `status_histories`
[9713:12.73] StatusHistory Load (5.3ms) SELECT
`status_histories`.* FROM `status_histories` WHERE (`key` = 'squeue_med_i586'
and `time` < 1479149999) ORDER BY `status_histories`.`time` ASC
[9713:12.75]  (0.2ms) SELECT MIN(`status_histories`.`time`)
FROM `status_histories`
[9713:13.03] scaling squeue_med_i586 1479149600 3 2016-11-14 18:55:00 +0000 0.0
[9713:13.03] SQL (0.3ms) DELETE FROM `status_histories` WHERE
`status_histories`.`id` IN (18218469, 18214581, 18214595)
[9713:13.03] SQL (0.2ms) INSERT INTO `status_histories`
(`key`, `time`, `value`) VALUES ('squeue_med_i586', 1479149700, 0.0)
[9713:13.03] scaling squeue_med_i586 1479149800 7 2016-11-14 18:58:20 +0000 0.0
[9713:13.03] SQL (0.3ms) DELETE FROM `status_histories` WHERE
`status_histories`.`id` IN (18214609, 18214623, 18214637, 18214651, 18214665,
18214679, 18214693)
[9713:13.03] SQL (0.2ms) INSERT INTO `status_histories`
(`key`, `time`, `value`) VALUES ('squeue_med_i586', 1479149900, 0.0)
[9670:25.04] SQL (0.6ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:08', `delayed_jobs`.`locked_by`
= 'delayed_job.1000 host:obs pid:9670' WHERE ((run_at <= '2016-11-14
21:00:08.108197' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:08.108282') OR locked_by = 'delayed_job.1000 host:obs pid:9670') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'releasetracking' ORDER BY
priority ASC, run_at ASC LIMIT 1
[9713:13.09]  (60.6ms) COMMIT
[9713:13.09]  (0.1ms) BEGIN
[9713:13.10]  (1.6ms) SELECT MAX(`status_histories`.`time`)
FROM `status_histories`
[9713:13.10] StatusHistory Load (5.0ms) SELECT
`status_histories`.* FROM `status_histories` WHERE (`key` = 'squeue_med_x86_64'
and `time` < 1476565199) ORDER BY `status_histories`.`time` ASC
[9713:13.11]  (0.2ms) SELECT MIN(`status_histories`.`time`)
FROM `status_histories`
[9713:13.12]  (0.2ms) SELECT MAX(`status_histories`.`time`)
FROM `status_histories`
[9713:13.12] StatusHistory Load (4.8ms) SELECT
`status_histories`.* FROM `status_histories` WHERE (`key` = 'squeue_med_x86_64'
and `time` < 1478552399) ORDER BY `status_histories`.`time` ASC
[9713:13.13]  (0.2ms) SELECT MIN(`status_histories`.`time`)
FROM `status_histories`
[9713:13.14]  (0.2ms) SELECT MAX(`status_histories`.`time`)
FROM `status_histories`
[9713:13.14] StatusHistory Load (4.9ms) SELECT
`status_histories`.* FROM `status_histories` WHERE (`key` = 'squeue_med_x86_64'
and `time` < 1479070799) ORDER BY `status_histories`.`time` ASC
[9713:13.16]  (0.2ms) SELECT MIN(`status_histories`.`time`)
FROM `status_histories`
[9713:13.18] scaling squeue_med_x86_64 1479067200 2 2016-11-13 20:30:00 +0000
0.0
[9713:13.18] SQL (0.2ms) DELETE FROM `status_histories`
WHERE `status_histories`.`id` IN (18218470, 18174995)
[9713:13.18] SQL (0.4ms) INSERT INTO `status_histories` (`key`,
`time`, `value`) VALUES ('squeue_med_x86_64', 1479069000, 0.0)
[9713:13.18]  (0.2ms) SELECT MAX(`status_histories`.`time`)
FROM `status_histories`
[9713:13.18] StatusHistory Load (5.4ms) SELECT
`status_histories`.* FROM `status_histories` WHERE (`key` = 'squeue_med_x86_64'
and `time` < 1479149999) ORDER BY `status_histories`.`time` ASC
[9713:13.21]  (0.2ms) SELECT MIN(`status_histories`.`time`)
FROM `status_histories`
[9713:13.49] scaling squeue_med_x86_64 1479149600 3 2016-11-14 18:55:00 +0000
0.0
[9713:13.49] SQL (0.3ms) DELETE FROM `status_histories` WHERE
`status_histories`.`id` IN (18218482, 18214585, 18214599)
[9713:13.49] SQL (0.2ms) INSERT INTO `status_histories`
(`key`, `time`, `value`) VALUES ('squeue_med_x86_64', 1479149700, 0.0)
[9713:13.49] scaling squeue_med_x86_64 1479149800 7 2016-11-14 18:58:20 +0000
0.0
[9713:13.49] SQL (0.3ms) DELETE FROM `status_histories` WHERE
`status_histories`.`id` IN (18214613, 18214627, 18214641, 18214655, 18214669,
18214683, 18214697)
[9713:13.49] SQL (0.2ms) INSERT INTO `status_histories`
(`key`, `time`, `value`) VALUES ('squeue_med_x86_64', 1479149900, 0.0)
[9713:13.53]  (34.1ms) COMMIT
[9713:13.53]  (0.1ms) BEGIN
[9713:13.53]  (0.2ms) SELECT MAX(`status_histories`.`time`)
FROM `status_histories`
[9713:13.53] StatusHistory Load (4.9ms) SELECT
`status_histories`.* FROM `status_histories` WHERE (`key` = 'squeue_next_i586'
and `time` < 1476565199) ORDER BY `status_histories`.`time` ASC
[9713:13.54]  (0.2ms) SELECT MIN(`status_histories`.`time`)
FROM `status_histories`
[9713:13.55]  (0.2ms) SELECT MAX(`status_histories`.`time`)
FROM `status_histories`
[9713:13.55] StatusHistory Load (4.6ms) SELECT
`status_histories`.* FROM `status_histories` WHERE (`key` = 'squeue_next_i586'
and `time` < 1478552399) ORDER BY `status_histories`.`time` ASC
[9713:13.56]  (0.2ms) SELECT MIN(`status_histories`.`time`)
FROM `status_histories`
[9713:13.57]  (0.2ms) SELECT MAX(`status_histories`.`time`)
FROM `status_histories`
[9713:13.57] StatusHistory Load (4.8ms) SELECT
`status_histories`.* FROM `status_histories` WHERE (`key` = 'squeue_next_i586'
and `time` < 1479070799) ORDER BY `status_histories`.`time` ASC
[9713:13.59]  (0.2ms) SELECT MIN(`status_histories`.`time`)
FROM `status_histories`
[9713:13.61] scaling squeue_next_i586 1479067200 2 2016-11-13 20:30:00 +0000 0.0
[9713:13.61] SQL (0.2ms) DELETE FROM `status_histories`
WHERE `status_histories`.`id` IN (18218483, 18175012)
[9713:13.61] SQL (0.2ms) INSERT INTO `status_histories` (`key`,
`time`, `value`) VALUES ('squeue_next_i586', 1479069000, 0.0)
[9713:13.61]  (0.2ms) SELECT MAX(`status_histories`.`time`)
FROM `status_histories`
[9713:13.62] StatusHistory Load (5.3ms) SELECT
`status_histories`.* FROM `status_histories` WHERE (`key` = 'squeue_next_i586'
and `time` < 1479149999) ORDER BY `status_histories`.`time` ASC
[9713:13.64]  (0.2ms) SELECT MIN(`status_histories`.`time`)
FROM `status_histories`
[9713:13.92] scaling squeue_next_i586 1479149600 3 2016-11-14 18:55:00 +0000 0.0
[9713:13.92] SQL (0.7ms) DELETE FROM `status_histories` WHERE
`status_histories`.`id` IN (18218495, 18214580, 18214594)
[9713:13.93] SQL (0.7ms) INSERT INTO `status_histories`
(`key`, `time`, `value`) VALUES ('squeue_next_i586', 1479149700, 0.0)
[9713:13.93] scaling squeue_next_i586 1479149800 7 2016-11-14 18:58:20 +0000 0.0
[9713:13.93] SQL (0.6ms) DELETE FROM `status_histories` WHERE
`status_histories`.`id` IN (18214608, 18214622, 18214636, 18214650, 18214664,
18214678, 18214692)
[9713:13.93] SQL (0.2ms) INSERT INTO `status_histories`
(`key`, `time`, `value`) VALUES ('squeue_next_i586', 1479149900, 0.0)
[9713:14.00]  (70.2ms) COMMIT
[9713:14.00]  (0.1ms) BEGIN
[9713:14.01]  (2.2ms) SELECT MAX(`status_histories`.`time`)
FROM `status_histories`
[9713:14.01] StatusHistory Load (5.0ms) SELECT
`status_histories`.* FROM `status_histories` WHERE (`key` =
'squeue_next_x86_64' and `time` < 1476565199) ORDER BY
`status_histories`.`time` ASC
[9713:14.02]  (0.2ms) SELECT MIN(`status_histories`.`time`)
FROM `status_histories`
[9713:14.02]  (0.2ms) SELECT MAX(`status_histories`.`time`)
FROM `status_histories`
[9713:14.03] StatusHistory Load (4.8ms) SELECT
`status_histories`.* FROM `status_histories` WHERE (`key` =
'squeue_next_x86_64' and `time` < 1478552399) ORDER BY
`status_histories`.`time` ASC
[9713:14.04]  (0.2ms) SELECT MIN(`status_histories`.`time`)
FROM `status_histories`
[9713:14.05]  (0.2ms) SELECT MAX(`status_histories`.`time`)
FROM `status_histories`
[9713:14.05] StatusHistory Load (5.0ms) SELECT
`status_histories`.* FROM `status_histories` WHERE (`key` =
'squeue_next_x86_64' and `time` < 1479070799) ORDER BY
`status_histories`.`time` ASC
[9713:14.07]  (0.2ms) SELECT MIN(`status_histories`.`time`)
FROM `status_histories`
[9713:14.08] scaling squeue_next_x86_64 1479067200 2 2016-11-13 20:30:00 +0000
0.0
[9713:14.08] SQL (0.2ms) DELETE FROM `status_histories`
WHERE `status_histories`.`id` IN (18218496, 18175029)
[9713:14.09] SQL (0.3ms) INSERT INTO `status_histories` (`key`,
`time`, `value`) VALUES ('squeue_next_x86_64', 1479069000, 0.0)
[9713:14.09]  (0.2ms) SELECT MAX(`status_histories`.`time`)
FROM `status_histories`
[9713:14.09] StatusHistory Load (5.5ms) SELECT
`status_histories`.* FROM `status_histories` WHERE (`key` =
'squeue_next_x86_64' and `time` < 1479149999) ORDER BY
`status_histories`.`time` ASC
[9713:14.11]  (0.2ms) SELECT MIN(`status_histories`.`time`)
FROM `status_histories`
[9713:14.38] scaling squeue_next_x86_64 1479149600 3 2016-11-14 18:55:00 +0000
0.0
[9713:14.38] SQL (0.3ms) DELETE FROM `status_histories` WHERE
`status_histories`.`id` IN (18218508, 18214584, 18214598)
[9713:14.39] SQL (0.3ms) INSERT INTO `status_histories`
(`key`, `time`, `value`) VALUES ('squeue_next_x86_64', 1479149700, 0.0)
[9713:14.39] scaling squeue_next_x86_64 1479149800 7 2016-11-14 18:58:20 +0000
0.0
[9713:14.39] SQL (0.3ms) DELETE FROM `status_histories` WHERE
`status_histories`.`id` IN (18214612, 18214626, 18214640, 18214654, 18214668,
18214682, 18214696)
[9713:14.39] SQL (0.2ms) INSERT INTO `status_histories`
(`key`, `time`, `value`) VALUES ('squeue_next_x86_64', 1479149900, 0.0)
[9713:14.49]  (103.9ms) COMMIT
[9713:14.50]  (0.2ms) BEGIN
[9713:14.50]  (2.2ms) SELECT MAX(`status_histories`.`time`)
FROM `status_histories`
[9713:14.51] StatusHistory Load (7.5ms) SELECT
`status_histories`.* FROM `status_histories` WHERE (`key` = 'waiting_i586' and
`time` < 1476565199) ORDER BY `status_histories`.`time` ASC
[9713:14.52]  (0.2ms) SELECT MIN(`status_histories`.`time`)
FROM `status_histories`
[9713:14.52]  (0.2ms) SELECT MAX(`status_histories`.`time`)
FROM `status_histories`
[9713:14.53] StatusHistory Load (4.4ms) SELECT
`status_histories`.* FROM `status_histories` WHERE (`key` = 'waiting_i586' and
`time` < 1478552399) ORDER BY `status_histories`.`time` ASC
[9713:14.54]  (0.2ms) SELECT MIN(`status_histories`.`time`)
FROM `status_histories`
[9713:14.54]  (0.2ms) SELECT MAX(`status_histories`.`time`)
FROM `status_histories`
[9713:14.55] StatusHistory Load (4.6ms) SELECT
`status_histories`.* FROM `status_histories` WHERE (`key` = 'waiting_i586' and
`time` < 1479070799) ORDER BY `status_histories`.`time` ASC
[9713:14.56]  (0.2ms) SELECT MIN(`status_histories`.`time`)
FROM `status_histories`
[9713:14.59] scaling waiting_i586 1479067200 2 2016-11-13 20:30:00 +0000 0.0
[9713:14.59] SQL (0.3ms) DELETE FROM `status_histories`
WHERE `status_histories`.`id` IN (18218509, 18175046)
[9713:14.59] SQL (0.3ms) INSERT INTO `status_histories` (`key`,
`time`, `value`) VALUES ('waiting_i586', 1479069000, 0.0)
[9713:14.59]  (0.2ms) SELECT MAX(`status_histories`.`time`)
FROM `status_histories`
[9713:14.60] StatusHistory Load (5.3ms) SELECT
`status_histories`.* FROM `status_histories` WHERE (`key` = 'waiting_i586' and
`time` < 1479149999) ORDER BY `status_histories`.`time` ASC
[9713:14.62]  (0.2ms) SELECT MIN(`status_histories`.`time`)
FROM `status_histories`
[9713:14.90] scaling waiting_i586 1479149600 3 2016-11-14 18:55:00 +0000 0.0
[9713:14.90] SQL (0.4ms) DELETE FROM `status_histories` WHERE
`status_histories`.`id` IN (18218521, 18214575, 18214589)
[9713:14.90] SQL (0.4ms) INSERT INTO `status_histories`
(`key`, `time`, `value`) VALUES ('waiting_i586', 1479149700, 0.0)
[9713:14.90] scaling waiting_i586 1479149800 7 2016-11-14 18:58:20 +0000 0.0
[9713:14.90] SQL (0.3ms) DELETE FROM `status_histories` WHERE
`status_histories`.`id` IN (18214603, 18214617, 18214631, 18214645, 18214659,
18214673, 18214687)
[9713:14.90] SQL (0.2ms) INSERT INTO `status_histories`
(`key`, `time`, `value`) VALUES ('waiting_i586', 1479149900, 0.0)
[9713:15.00]  (98.3ms) COMMIT
[9713:15.00]  (0.1ms) BEGIN
[9713:15.01]  (3.5ms) SELECT MAX(`status_histories`.`time`)
FROM `status_histories`
[9713:15.01] StatusHistory Load (5.7ms) SELECT
`status_histories`.* FROM `status_histories` WHERE (`key` = 'waiting_x86_64'
and `time` < 1476565199) ORDER BY `status_histories`.`time` ASC
[9713:15.02]  (0.2ms) SELECT MIN(`status_histories`.`time`)
FROM `status_histories`
[9713:15.03]  (0.2ms) SELECT MAX(`status_histories`.`time`)
FROM `status_histories`
[9713:15.03] StatusHistory Load (4.6ms) SELECT
`status_histories`.* FROM `status_histories` WHERE (`key` = 'waiting_x86_64'
and `time` < 1478552399) ORDER BY `status_histories`.`time` ASC
[9713:15.04]  (0.2ms) SELECT MIN(`status_histories`.`time`)
FROM `status_histories`
[9713:15.05]  (0.2ms) SELECT MAX(`status_histories`.`time`)
FROM `status_histories`
[9713:15.05] StatusHistory Load (4.7ms) SELECT
`status_histories`.* FROM `status_histories` WHERE (`key` = 'waiting_x86_64'
and `time` < 1479070799) ORDER BY `status_histories`.`time` ASC
[9713:15.07]  (0.2ms) SELECT MIN(`status_histories`.`time`)
FROM `status_histories`
[9713:15.09] scaling waiting_x86_64 1479067200 2 2016-11-13 20:30:00 +0000 0.0
[9713:15.09] SQL (0.3ms) DELETE FROM `status_histories`
WHERE `status_histories`.`id` IN (18218522, 18175063)
[9713:15.09] SQL (0.2ms) INSERT INTO `status_histories` (`key`,
`time`, `value`) VALUES ('waiting_x86_64', 1479069000, 0.0)
[9713:15.09]  (0.2ms) SELECT MAX(`status_histories`.`time`)
FROM `status_histories`
[9713:15.10] StatusHistory Load (5.3ms) SELECT
`status_histories`.* FROM `status_histories` WHERE (`key` = 'waiting_x86_64'
and `time` < 1479149999) ORDER BY `status_histories`.`time` ASC
[9713:15.12]  (0.2ms) SELECT MIN(`status_histories`.`time`)
FROM `status_histories`
[9641:31.47] SQL (0.4ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:10', `delayed_jobs`.`locked_by`
= 'delayed_job.0 host:obs pid:9641' WHERE ((run_at <= '2016-11-14
21:00:10.354496' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:10.354546') OR locked_by = 'delayed_job.0 host:obs pid:9641') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'quick' ORDER BY priority ASC,
run_at ASC LIMIT 1
[9713:15.40] scaling waiting_x86_64 1479149600 3 2016-11-14 18:55:00 +0000 0.0
[9713:15.40] SQL (0.4ms) DELETE FROM `status_histories` WHERE
`status_histories`.`id` IN (18218534, 18214576, 18214590)
[9713:15.40] SQL (0.2ms) INSERT INTO `status_histories`
(`key`, `time`, `value`) VALUES ('waiting_x86_64', 1479149700, 0.0)
[9713:15.40] scaling waiting_x86_64 1479149800 7 2016-11-14 18:58:20 +0000 0.0
[9713:15.41] SQL (0.5ms) DELETE FROM `status_histories` WHERE
`status_histories`.`id` IN (18214604, 18214618, 18214632, 18214646, 18214660,
18214674, 18214688)
[9713:15.41] SQL (0.6ms) INSERT INTO `status_histories`
(`key`, `time`, `value`) VALUES ('waiting_x86_64', 1479149900, 0.0)
[9713:15.52]  (108.6ms) COMMIT
[9713:15.52]  (0.2ms) BEGIN
[9713:15.52] SQL (0.5ms) DELETE FROM `delayed_jobs` WHERE
`delayed_jobs`.`id` = 72921
[9713:15.58]  (53.2ms) COMMIT
[9713:15.58] 2016-11-14T21:00:10+0000: [Worker(delayed_job.1030 host:obs
pid:9713)] Job StatusHistoryRescaler#rescale (id=72921) COMPLETED after 10.4726
[9713:15.62] SQL (38.2ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:10', `delayed_jobs`.`locked_by`
= 'delayed_job.1030 host:obs pid:9713' WHERE ((run_at <= '2016-11-14
21:00:10.648067' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:10.648127') OR locked_by = 'delayed_job.1030 host:obs pid:9713') AND
failed_at IS NULL) ORDER BY priority ASC, run_at ASC LIMIT 1
[9713:15.62] Delayed::Backend::ActiveRecord::Job Load (4.1ms)
SELECT `delayed_jobs`.* FROM `delayed_jobs` WHERE
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:10' AND
`delayed_jobs`.`locked_by` = 'delayed_job.1030 host:obs pid:9713' AND
`delayed_jobs`.`failed_at` IS NULL ORDER BY `delayed_jobs`.`id` ASC LIMIT 1
[9713:15.62] 2016-11-14T21:00:10+0000: [Worker(delayed_job.1030 host:obs
pid:9713)] Job ActiveJob::QueueAdapters::DelayedJobAdapter::JobWrapper
(id=72926) RUNNING
[ActiveJob] [CleanupEvents] [d71f42b3-42d2-4f6a-902c-55d2920bf2d8] [9713:15.63]
Performing CleanupEvents from DelayedJob(default)
[ActiveJob] [CleanupEvents] [d71f42b3-42d2-4f6a-902c-55d2920bf2d8] [9713:15.64]
 (0.1ms) BEGIN
[ActiveJob] [CleanupEvents] [d71f42b3-42d2-4f6a-902c-55d2920bf2d8] [9713:15.64]
SQL (0.2ms) DELETE FROM `events` WHERE
`events`.`project_logged` = 1 AND `events`.`queued` = 1 AND
`events`.`undone_jobs` = 0
[ActiveJob] [CleanupEvents] [d71f42b3-42d2-4f6a-902c-55d2920bf2d8] [9713:15.64]
 (0.1ms) COMMIT
[ActiveJob] [CleanupEvents] [d71f42b3-42d2-4f6a-902c-55d2920bf2d8] [9713:15.64]
Performed CleanupEvents from DelayedJob(default) in 12.48ms
[9713:15.64]  (0.1ms) BEGIN
[9713:15.64] SQL (0.2ms) DELETE FROM `delayed_jobs` WHERE
`delayed_jobs`.`id` = 72926
[9713:15.67]  (28.1ms) COMMIT
[9713:15.67] 2016-11-14T21:00:10+0000: [Worker(delayed_job.1030 host:obs
pid:9713)] Job ActiveJob::QueueAdapters::DelayedJobAdapter::JobWrapper
(id=72926) COMPLETED after 0.0436
[9713:15.70] SQL (32.1ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:10', `delayed_jobs`.`locked_by`
= 'delayed_job.1030 host:obs pid:9713' WHERE ((run_at <= '2016-11-14
21:00:10.738719' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:10.738742') OR locked_by = 'delayed_job.1030 host:obs pid:9713') AND
failed_at IS NULL) ORDER BY priority ASC, run_at ASC LIMIT 1
[9713:15.70] Delayed::Backend::ActiveRecord::Job Load (0.8ms)
SELECT `delayed_jobs`.* FROM `delayed_jobs` WHERE
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:10' AND
`delayed_jobs`.`locked_by` = 'delayed_job.1030 host:obs pid:9713' AND
`delayed_jobs`.`failed_at` IS NULL ORDER BY `delayed_jobs`.`id` ASC LIMIT 1
[9713:15.71] 2016-11-14T21:00:10+0000: [Worker(delayed_job.1030 host:obs
pid:9713)] Job ActiveJob::QueueAdapters::DelayedJobAdapter::JobWrapper
(id=72927) RUNNING
[ActiveJob] [ConsistencyCheckJob] [b7bc9da8-1632-4056-8d76-d2cea36ddbf6]
[9713:15.71] Performing ConsistencyCheckJob from DelayedJob(default)
[ActiveJob] [ConsistencyCheckJob] [b7bc9da8-1632-4056-8d76-d2cea36ddbf6]
[9713:15.71] User Load (0.4ms) SELECT `users`.* FROM `users`
WHERE `users`.`login` = 'Admin' LIMIT 1
[ActiveJob] [ConsistencyCheckJob] [b7bc9da8-1632-4056-8d76-d2cea36ddbf6]
[9713:15.72] Performed ConsistencyCheckJob from DelayedJob(default) in 13.28ms
[9713:15.72] 2016-11-14T21:00:10+0000: [Worker(delayed_job.1030 host:obs
pid:9713)] Job ActiveJob::QueueAdapters::DelayedJobAdapter::JobWrapper
(id=72927) FAILED (0 prior attempts) with NoMethodError: undefined method
`is_admin?' for nil:NilClass
Did you mean? is_haml?
[9713:15.72]  (0.1ms) BEGIN
[9713:15.72] SQL (0.5ms) UPDATE `delayed_jobs` SET `last_error`
= 'undefined method `is_admin?\' for nil:NilClass\nDid you mean?
is_haml?\n/srv/www/obs/api/app/models/user.rb:447:in
`get_default_admin\'\n/srv/www/obs/api/app/jobs/consistency_check.rb:10:in
`init\'\n/srv/www/obs/api/app/jobs/consistency_check.rb:15:in
`perform\'\n/usr/lib64/ruby/gems/2.3.0/gems/activejob-4.2.7.1/lib/active_job/execution.rb:32:in
`block in
perform_now\'\n/usr/lib64/ruby/gems/2.3.0/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:117:in

`call\'\n/usr/lib64/ruby/gems/2.3.0/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:555:in
`block (2 levels) in
compile\'\n/usr/lib64/ruby/gems/2.3.0/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:505:in

`call\'\n/usr/lib64/ruby/gems/2.3.0/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:498:in
`block (2 levels) in
around\'\n/usr/lib64/ruby/gems/2.3.0/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:343:in
`block (2 levels) in
simple\'\n/usr/lib64/ruby/gems/2.3.0/gems/i18n-0.7.0/lib/i18n.rb:257:in
`with_locale\'\n/usr/lib64/ruby/gems/2.3.0/gems/activejob-4.2.7.1/lib/active_job/translation.rb:7:in
`block (2 levels) in
<module:Translation>\'\n/usr/lib64/ruby/gems/2.3.0/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:441:in

`instance_exec\'\n/usr/lib64/ruby/gems/2.3.0/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:441:in
`block in
make_lambda\'\n/usr/lib64/ruby/gems/2.3.0/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:342:in
`block in
simple\'\n/usr/lib64/ruby/gems/2.3.0/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:497:in
`block in
around\'\n/usr/lib64/ruby/gems/2.3.0/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:505:in

`call\'\n/usr/lib64/ruby/gems/2.3.0/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:498:in
`block (2 levels) in
around\'\n/usr/lib64/ruby/gems/2.3.0/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:343:in
`block (2 levels) in
simple\'\n/usr/lib64/ruby/gems/2.3.0/gems/activejob-4.2.7.1/lib/active_job/logging.rb:23:in
`block (4 levels) in
<module:Logging>\'\n/usr/lib64/ruby/gems/2.3.0/gems/activesupport-4.2.7.1/lib/active_support/notifications.rb:164:in
`block in
instrument\'\n/usr/lib64/ruby/gems/2.3.0/gems/activesupport-4.2.7.1/lib/active_support/notifications/instrumenter.rb:20:in

`instrument\'\n/usr/lib64/ruby/gems/2.3.0/gems/activesupport-4.2.7.1/lib/active_support/notifications.rb:164:in

`instrument\'\n/usr/lib64/ruby/gems/2.3.0/gems/activejob-4.2.7.1/lib/active_job/logging.rb:22:in
`block (3 levels) in
<module:Logging>\'\n/usr/lib64/ruby/gems/2.3.0/gems/activejob-4.2.7.1/lib/active_job/logging.rb:43:in
`block in
tag_logger\'\n/usr/lib64/ruby/gems/2.3.0/gems/activesupport-4.2.7.1/lib/active_support/tagged_logging.rb:68:in
`block in
tagged\'\n/usr/lib64/ruby/gems/2.3.0/gems/activesupport-4.2.7.1/lib/active_support/tagged_logging.rb:26:in

`tagged\'\n/usr/lib64/ruby/gems/2.3.0/gems/activesupport-4.2.7.1/lib/active_support/tagged_logging.rb:68:in

`tagged\'\n/usr/lib64/ruby/gems/2.3.0/gems/activejob-4.2.7.1/lib/active_job/logging.rb:43:in

`tag_logger\'\n/usr/lib64/ruby/gems/2.3.0/gems/activejob-4.2.7.1/lib/active_job/logging.rb:19:in
`block (2 levels) in
<module:Logging>\'\n/usr/lib64/ruby/gems/2.3.0/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:441:in

`instance_exec\'\n/usr/lib64/ruby/gems/2.3.0/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:441:in
`block in
make_lambda\'\n/usr/lib64/ruby/gems/2.3.0/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:342:in
`block in
simple\'\n/usr/lib64/ruby/gems/2.3.0/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:497:in
`block in
around\'\n/usr/lib64/ruby/gems/2.3.0/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:505:in

`call\'\n/usr/lib64/ruby/gems/2.3.0/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:92:in

`__run_callbacks__\'\n/usr/lib64/ruby/gems/2.3.0/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:778:in

`_run_perform_callbacks\'\n/usr/lib64/ruby/gems/2.3.0/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:81:in

`run_callbacks\'\n/usr/lib64/ruby/gems/2.3.0/gems/activejob-4.2.7.1/lib/active_job/execution.rb:31:in

`perform_now\'\n/usr/lib64/ruby/gems/2.3.0/gems/activejob-4.2.7.1/lib/active_job/execution.rb:21:in

`execute\'\n/usr/lib64/ruby/gems/2.3.0/gems/activejob-4.2.7.1/lib/active_job/queue_adapters/delayed_job_adapter.rb:34:in

`perform\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/backend/base.rb:100:in
`block in
invoke_job\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/lifecycle.rb:61:in
`block in
initialize\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/lifecycle.rb:66:in

`execute\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/lifecycle.rb:40:in

`run_callbacks\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/backend/base.rb:97:in

`invoke_job\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/worker.rb:224:in
`block (2 levels) in run\'\n/usr/lib64/ruby/2.3.0/timeout.rb:91:in `block in
timeout\'\n/usr/lib64/ruby/2.3.0/timeout.rb:101:in
`timeout\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/worker.rb:224:in
`block in run\'\n/usr/lib64/ruby/2.3.0/benchmark.rb:308:in
`realtime\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/worker.rb:223:in

`run\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/worker.rb:300:in
`block in
reserve_and_run_one_job\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/lifecycle.rb:61:in
`block in
initialize\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/lifecycle.rb:66:in

`execute\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/lifecycle.rb:40:in

`run_callbacks\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/worker.rb:300:in

`reserve_and_run_one_job\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/worker.rb:207:in
`block in
work_off\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/worker.rb:206:in

`times\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/worker.rb:206:in

`work_off\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/worker.rb:169:in
`block (4 levels) in start\'\n/usr/lib64/ruby/2.3.0/benchmark.rb:308:in
`realtime\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/worker.rb:168:in
`block (3 levels) in
start\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/lifecycle.rb:61:in
`block in
initialize\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/lifecycle.rb:66:in

`execute\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/lifecycle.rb:40:in

`run_callbacks\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/worker.rb:167:in
`block (2 levels) in
start\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/worker.rb:166:in

`loop\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/worker.rb:166:in
`block in
start\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/plugins/clear_locks.rb:7:in
`block (2 levels) in
<class:ClearLocks>\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/lifecycle.rb:79:in
`block (2 levels) in
add\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/lifecycle.rb:61:in
`block in
initialize\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/lifecycle.rb:79:in
`block in
add\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/lifecycle.rb:66:in

`execute\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/lifecycle.rb:40:in

`run_callbacks\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/worker.rb:165:in

`start\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/command.rb:131:in

`run\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/command.rb:119:in
`block in
run_process\'\n/usr/lib64/ruby/gems/2.3.0/gems/daemons-1.2.3/lib/daemons/application.rb:265:in
`block in
start_proc\'\n/usr/lib64/ruby/gems/2.3.0/gems/daemons-1.2.3/lib/daemons/daemonize.rb:84:in

`call_as_daemon\'\n/usr/lib64/ruby/gems/2.3.0/gems/daemons-1.2.3/lib/daemons/application.rb:269:in

`start_proc\'\n/usr/lib64/ruby/gems/2.3.0/gems/daemons-1.2.3/lib/daemons/application.rb:295:in

`start\'\n/usr/lib64/ruby/gems/2.3.0/gems/daemons-1.2.3/lib/daemons/controller.rb:56:in
`run\'\n/usr/lib64/ruby/gems/2.3.0/gems/daemons-1.2.3/lib/daemons.rb:193:in
`block in
run_proc\'\n/usr/lib64/ruby/gems/2.3.0/gems/daemons-1.2.3/lib/daemons/cmdline.rb:88:in

`catch_exceptions\'\n/usr/lib64/ruby/gems/2.3.0/gems/daemons-1.2.3/lib/daemons.rb:192:in

`run_proc\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/command.rb:117:in

`run_process\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/command.rb:93:in
`daemonize\'\nscript/delayed_job.api.rb:7:in `<main>\'', `attempts` = 1,
`run_at` = '2016-11-14 21:00:16', `locked_at` = NULL, `locked_by` = NULL WHERE
`delayed_jobs`.`id` = 72927
[9713:15.77]  (44.0ms) COMMIT
[9647:31.86] SQL (0.3ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:10', `delayed_jobs`.`locked_by`
= 'delayed_job.1 host:obs pid:9647' WHERE ((run_at <= '2016-11-14
21:00:10.859563' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:10.859605') OR locked_by = 'delayed_job.1 host:obs pid:9647') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'quick' ORDER BY priority ASC,
run_at ASC LIMIT 1
[9713:15.82] SQL (46.9ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:10', `delayed_jobs`.`locked_by`
= 'delayed_job.1030 host:obs pid:9713' WHERE ((run_at <= '2016-11-14
21:00:10.839297' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:10.839364') OR locked_by = 'delayed_job.1030 host:obs pid:9713') AND
failed_at IS NULL) ORDER BY priority ASC, run_at ASC LIMIT 1
[9713:15.82] Delayed::Backend::ActiveRecord::Job Load (0.5ms)
SELECT `delayed_jobs`.* FROM `delayed_jobs` WHERE
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:10' AND
`delayed_jobs`.`locked_by` = 'delayed_job.1030 host:obs pid:9713' AND
`delayed_jobs`.`failed_at` IS NULL ORDER BY `delayed_jobs`.`id` ASC LIMIT 1
[9713:15.82] 2016-11-14T21:00:10+0000: [Worker(delayed_job.1030 host:obs
pid:9713)] Job ConsistencyCheckJob#perform (id=72928) RUNNING
[9713:15.82] User Load (0.4ms) SELECT `users`.* FROM `users`
WHERE `users`.`login` = 'Admin' LIMIT 1
[9713:15.83] 2016-11-14T21:00:10+0000: [Worker(delayed_job.1030 host:obs
pid:9713)] Job ConsistencyCheckJob#perform (id=72928) FAILED (0 prior attempts)
with NoMethodError: undefined method `is_admin?' for nil:NilClass
Did you mean? is_haml?
[9713:15.83]  (0.1ms) BEGIN
[9713:15.83] SQL (0.3ms) UPDATE `delayed_jobs` SET `last_error`
= 'undefined method `is_admin?\' for nil:NilClass\nDid you mean?
is_haml?\n/srv/www/obs/api/app/models/user.rb:447:in
`get_default_admin\'\n/srv/www/obs/api/app/jobs/consistency_check.rb:10:in
`init\'\n/srv/www/obs/api/app/jobs/consistency_check.rb:15:in
`perform\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/performable_method.rb:30:in

`perform\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/backend/base.rb:100:in
`block in
invoke_job\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/lifecycle.rb:61:in
`block in
initialize\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/lifecycle.rb:66:in

`execute\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/lifecycle.rb:40:in

`run_callbacks\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/backend/base.rb:97:in

`invoke_job\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/worker.rb:224:in
`block (2 levels) in run\'\n/usr/lib64/ruby/2.3.0/timeout.rb:91:in `block in
timeout\'\n/usr/lib64/ruby/2.3.0/timeout.rb:101:in
`timeout\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/worker.rb:224:in
`block in run\'\n/usr/lib64/ruby/2.3.0/benchmark.rb:308:in
`realtime\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/worker.rb:223:in

`run\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/worker.rb:300:in
`block in
reserve_and_run_one_job\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/lifecycle.rb:61:in
`block in
initialize\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/lifecycle.rb:66:in

`execute\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/lifecycle.rb:40:in

`run_callbacks\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/worker.rb:300:in

`reserve_and_run_one_job\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/worker.rb:207:in
`block in
work_off\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/worker.rb:206:in

`times\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/worker.rb:206:in

`work_off\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/worker.rb:169:in
`block (4 levels) in start\'\n/usr/lib64/ruby/2.3.0/benchmark.rb:308:in
`realtime\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/worker.rb:168:in
`block (3 levels) in
start\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/lifecycle.rb:61:in
`block in
initialize\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/lifecycle.rb:66:in

`execute\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/lifecycle.rb:40:in

`run_callbacks\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/worker.rb:167:in
`block (2 levels) in
start\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/worker.rb:166:in

`loop\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/worker.rb:166:in
`block in
start\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/plugins/clear_locks.rb:7:in
`block (2 levels) in
<class:ClearLocks>\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/lifecycle.rb:79:in
`block (2 levels) in
add\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/lifecycle.rb:61:in
`block in
initialize\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/lifecycle.rb:79:in
`block in
add\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/lifecycle.rb:66:in

`execute\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/lifecycle.rb:40:in

`run_callbacks\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/worker.rb:165:in

`start\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/command.rb:131:in

`run\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/command.rb:119:in
`block in
run_process\'\n/usr/lib64/ruby/gems/2.3.0/gems/daemons-1.2.3/lib/daemons/application.rb:265:in
`block in
start_proc\'\n/usr/lib64/ruby/gems/2.3.0/gems/daemons-1.2.3/lib/daemons/daemonize.rb:84:in

`call_as_daemon\'\n/usr/lib64/ruby/gems/2.3.0/gems/daemons-1.2.3/lib/daemons/application.rb:269:in

`start_proc\'\n/usr/lib64/ruby/gems/2.3.0/gems/daemons-1.2.3/lib/daemons/application.rb:295:in

`start\'\n/usr/lib64/ruby/gems/2.3.0/gems/daemons-1.2.3/lib/daemons/controller.rb:56:in
`run\'\n/usr/lib64/ruby/gems/2.3.0/gems/daemons-1.2.3/lib/daemons.rb:193:in
`block in
run_proc\'\n/usr/lib64/ruby/gems/2.3.0/gems/daemons-1.2.3/lib/daemons/cmdline.rb:88:in

`catch_exceptions\'\n/usr/lib64/ruby/gems/2.3.0/gems/daemons-1.2.3/lib/daemons.rb:192:in

`run_proc\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/command.rb:117:in

`run_process\'\n/usr/lib64/ruby/gems/2.3.0/gems/delayed_job-4.1.1/lib/delayed/command.rb:93:in
`daemonize\'\nscript/delayed_job.api.rb:7:in `<main>\'', `attempts` = 1,
`run_at` = '2016-11-14 21:00:16', `locked_at` = NULL, `locked_by` = NULL WHERE
`delayed_jobs`.`id` = 72928
[9713:15.86]  (30.4ms) COMMIT
[9713:15.86] SQL (0.3ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:10', `delayed_jobs`.`locked_by`
= 'delayed_job.1030 host:obs pid:9713' WHERE ((run_at <= '2016-11-14
21:00:10.930165' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:10.930193') OR locked_by = 'delayed_job.1030 host:obs pid:9713') AND
failed_at IS NULL) ORDER BY priority ASC, run_at ASC LIMIT 1
[9713:15.86] 2016-11-14T21:00:10+0000: [Worker(delayed_job.1030 host:obs
pid:9713)] 4 jobs processed at 0.3690 j/s, 2 failed
[9713:15.86] SQL (0.3ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:10', `delayed_jobs`.`locked_by`
= 'delayed_job.1030 host:obs pid:9713' WHERE ((run_at <= '2016-11-14
21:00:10.931504' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:10.931533') OR locked_by = 'delayed_job.1030 host:obs pid:9713') AND
failed_at IS NULL) ORDER BY priority ASC, run_at ASC LIMIT 1
[9698:20.03] SQL (0.6ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:11', `delayed_jobs`.`locked_by`
= 'delayed_job.1020 host:obs pid:9698' WHERE ((run_at <= '2016-11-14
21:00:11.107675' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:11.107760') OR locked_by = 'delayed_job.1020 host:obs pid:9698') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'mailers' ORDER BY priority
ASC, run_at ASC LIMIT 1
[9654:32.51] SQL (0.6ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:11', `delayed_jobs`.`locked_by`
= 'delayed_job.2 host:obs pid:9654' WHERE ((run_at <= '2016-11-14
21:00:11.637347' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:11.637431') OR locked_by = 'delayed_job.2 host:obs pid:9654') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'quick' ORDER BY priority ASC,
run_at ASC LIMIT 1
[9683:25.04] SQL (0.7ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:12', `delayed_jobs`.`locked_by`
= 'delayed_job.1010 host:obs pid:9683' WHERE ((run_at <= '2016-11-14
21:00:12.096195' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:12.096285') OR locked_by = 'delayed_job.1010 host:obs pid:9683') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'issuetracking' ORDER BY
priority ASC, run_at ASC LIMIT 1
[9670:30.04] SQL (0.8ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:13', `delayed_jobs`.`locked_by`
= 'delayed_job.1000 host:obs pid:9670' WHERE ((run_at <= '2016-11-14
21:00:13.111719' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:13.111859') OR locked_by = 'delayed_job.1000 host:obs pid:9670') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'releasetracking' ORDER BY
priority ASC, run_at ASC LIMIT 1
[9641:36.47] SQL (0.8ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:15', `delayed_jobs`.`locked_by`
= 'delayed_job.0 host:obs pid:9641' WHERE ((run_at <= '2016-11-14
21:00:15.356577' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:15.356667') OR locked_by = 'delayed_job.0 host:obs pid:9641') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'quick' ORDER BY priority ASC,
run_at ASC LIMIT 1
[9647:36.86] SQL (0.4ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:15', `delayed_jobs`.`locked_by`
= 'delayed_job.1 host:obs pid:9647' WHERE ((run_at <= '2016-11-14
21:00:15.861423' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:15.861503') OR locked_by = 'delayed_job.1 host:obs pid:9647') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'quick' ORDER BY priority ASC,
run_at ASC LIMIT 1
[9713:20.87] SQL (0.9ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:15', `delayed_jobs`.`locked_by`
= 'delayed_job.1030 host:obs pid:9713' WHERE ((run_at <= '2016-11-14
21:00:15.932986' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:15.933070') OR locked_by = 'delayed_job.1030 host:obs pid:9713') AND
failed_at IS NULL) ORDER BY priority ASC, run_at ASC LIMIT 1
[9724:0.00] User Load (0.4ms) SELECT `users`.* FROM
`users` WHERE `users`.`login` = 'Admin' LIMIT 1
[9698:25.04] SQL (0.6ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:16', `delayed_jobs`.`locked_by`
= 'delayed_job.1020 host:obs pid:9698' WHERE ((run_at <= '2016-11-14
21:00:16.111173' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:16.111259') OR locked_by = 'delayed_job.1020 host:obs pid:9698') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'mailers' ORDER BY priority
ASC, run_at ASC LIMIT 1
[9654:37.52] SQL (0.7ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:16', `delayed_jobs`.`locked_by`
= 'delayed_job.2 host:obs pid:9654' WHERE ((run_at <= '2016-11-14
21:00:16.640969' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:16.641053') OR locked_by = 'delayed_job.2 host:obs pid:9654') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'quick' ORDER BY priority ASC,
run_at ASC LIMIT 1
[9683:30.04] SQL (0.8ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:17', `delayed_jobs`.`locked_by`
= 'delayed_job.1010 host:obs pid:9683' WHERE ((run_at <= '2016-11-14
21:00:17.099916' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:17.100006') OR locked_by = 'delayed_job.1010 host:obs pid:9683') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'issuetracking' ORDER BY
priority ASC, run_at ASC LIMIT 1
[9670:35.05] SQL (0.6ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:18', `delayed_jobs`.`locked_by`
= 'delayed_job.1000 host:obs pid:9670' WHERE ((run_at <= '2016-11-14
21:00:18.115532' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:18.115630') OR locked_by = 'delayed_job.1000 host:obs pid:9670') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'releasetracking' ORDER BY
priority ASC, run_at ASC LIMIT 1
[9641:41.47] SQL (0.6ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:20', `delayed_jobs`.`locked_by`
= 'delayed_job.0 host:obs pid:9641' WHERE ((run_at <= '2016-11-14
21:00:20.360205' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:20.360290') OR locked_by = 'delayed_job.0 host:obs pid:9641') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'quick' ORDER BY priority ASC,
run_at ASC LIMIT 1
[9647:41.86] SQL (0.6ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:20', `delayed_jobs`.`locked_by`
= 'delayed_job.1 host:obs pid:9647' WHERE ((run_at <= '2016-11-14
21:00:20.864546' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:20.864626') OR locked_by = 'delayed_job.1 host:obs pid:9647') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'quick' ORDER BY priority ASC,
run_at ASC LIMIT 1
[9713:25.97] SQL (98.6ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:20', `delayed_jobs`.`locked_by`
= 'delayed_job.1030 host:obs pid:9713' WHERE ((run_at <= '2016-11-14
21:00:20.936447' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:20.936529') OR locked_by = 'delayed_job.1030 host:obs pid:9713') AND
failed_at IS NULL) ORDER BY priority ASC, run_at ASC LIMIT 1
[9713:25.97] Delayed::Backend::ActiveRecord::Job Load (0.5ms)
SELECT `delayed_jobs`.* FROM `delayed_jobs` WHERE `delayed_jobs`.`locked_at` =
'2016-11-14 21:00:20' AND `delayed_jobs`.`locked_by` = 'delayed_job.1030
host:obs pid:9713' AND `delayed_jobs`.`failed_at` IS NULL ORDER BY
`delayed_jobs`.`id` ASC LIMIT 1
[9713:25.97] 2016-11-14T21:00:21+0000: [Worker(delayed_job.1030 host:obs
pid:9713)] Job ActiveJob::QueueAdapters::DelayedJobAdapter::JobWrapper
(id=72927) RUNNING
[ActiveJob] [ConsistencyCheckJob] [b7bc9da8-1632-4056-8d76-d2cea36ddbf6]
[9713:25.97] Performing ConsistencyCheckJob from DelayedJob(default)
[ActiveJob] [ConsistencyCheckJob] [b7bc9da8-1632-4056-8d76-d2cea36ddbf6]
[9713:25.97] User Load (0.6ms) SELECT `users`.* FROM
`users` WHERE `users`.`login` = 'Admin' LIMIT 1
[ActiveJob] [ConsistencyCheckJob] [b7bc9da8-1632-4056-8d76-d2cea36ddbf6]
[9713:25.98] Performed ConsistencyCheckJob from DelayedJob(default) in 7.99ms
[9713:25.98] 2016-11-14T21:00:21+0000: [Worker(delayed_job.1030 host:obs
pid:9713)] Job ActiveJob::QueueAdapters::DelayedJobAdapter::JobWrapper
(id=72927) FAILED (1 prior attempts) with NoMethodError: undefined method
`is_admin?' for nil:NilClass
Did you mean? is_haml?
[9713:25.98]  (0.1ms) BEGIN
[9713:25.98] SQL (0.2ms) UPDATE `delayed_jobs` SET
`attempts` = 2, `run_at` = '2016-11-14 21:00:42', `locked_at` = NULL,
`locked_by` = NULL WHERE `delayed_jobs`.`id` = 72927
[9713:26.02]  (35.7ms) COMMIT
[9698:30.04] SQL (0.7ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:21', `delayed_jobs`.`locked_by`
= 'delayed_job.1020 host:obs pid:9698' WHERE ((run_at <= '2016-11-14
21:00:21.114726' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:21.114821') OR locked_by = 'delayed_job.1020 host:obs pid:9698') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'mailers' ORDER BY priority
ASC, run_at ASC LIMIT 1
[9713:26.07] SQL (47.9ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:21', `delayed_jobs`.`locked_by`
= 'delayed_job.1030 host:obs pid:9713' WHERE ((run_at <= '2016-11-14
21:00:21.087416' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:21.087534') OR locked_by = 'delayed_job.1030 host:obs pid:9713') AND
failed_at IS NULL) ORDER BY priority ASC, run_at ASC LIMIT 1
[9713:26.07] Delayed::Backend::ActiveRecord::Job Load (0.8ms)
SELECT `delayed_jobs`.* FROM `delayed_jobs` WHERE `delayed_jobs`.`locked_at` =
'2016-11-14 21:00:21' AND `delayed_jobs`.`locked_by` = 'delayed_job.1030
host:obs pid:9713' AND `delayed_jobs`.`failed_at` IS NULL ORDER BY
`delayed_jobs`.`id` ASC LIMIT 1
[9713:26.07] 2016-11-14T21:00:21+0000: [Worker(delayed_job.1030 host:obs
pid:9713)] Job ConsistencyCheckJob#perform (id=72928) RUNNING
[9713:26.07] User Load (0.5ms) SELECT `users`.* FROM
`users` WHERE `users`.`login` = 'Admin' LIMIT 1
[9713:26.08] 2016-11-14T21:00:21+0000: [Worker(delayed_job.1030 host:obs
pid:9713)] Job ConsistencyCheckJob#perform (id=72928) FAILED (1 prior attempts)
with NoMethodError: undefined method `is_admin?' for nil:NilClass
Did you mean? is_haml?
[9713:26.08]  (0.1ms) BEGIN
[9713:26.08] SQL (0.2ms) UPDATE `delayed_jobs` SET
`attempts` = 2, `run_at` = '2016-11-14 21:00:42', `locked_at` = NULL,
`locked_by` = NULL WHERE `delayed_jobs`.`id` = 72928
[9713:26.11]  (29.6ms) COMMIT
[9713:26.11] SQL (0.3ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:21', `delayed_jobs`.`locked_by`
= 'delayed_job.1030 host:obs pid:9713' WHERE ((run_at <= '2016-11-14
21:00:21.179005' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:21.179033') OR locked_by = 'delayed_job.1030 host:obs pid:9713') AND
failed_at IS NULL) ORDER BY priority ASC, run_at ASC LIMIT 1
[9713:26.11] 2016-11-14T21:00:21+0000: [Worker(delayed_job.1030 host:obs
pid:9713)] 2 jobs processed at 8.2014 j/s, 2 failed
[9713:26.11] SQL (0.3ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:21', `delayed_jobs`.`locked_by`
= 'delayed_job.1030 host:obs pid:9713' WHERE ((run_at <= '2016-11-14
21:00:21.180342' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:21.180360') OR locked_by = 'delayed_job.1030 host:obs pid:9713') AND
failed_at IS NULL) ORDER BY priority ASC, run_at ASC LIMIT 1
[9654:42.52] SQL (0.7ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:21', `delayed_jobs`.`locked_by`
= 'delayed_job.2 host:obs pid:9654' WHERE ((run_at <= '2016-11-14
21:00:21.644559' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:21.644644') OR locked_by = 'delayed_job.2 host:obs pid:9654') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'quick' ORDER BY priority ASC,
run_at ASC LIMIT 1
[9683:35.05] SQL (0.7ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:22', `delayed_jobs`.`locked_by`
= 'delayed_job.1010 host:obs pid:9683' WHERE ((run_at <= '2016-11-14
21:00:22.103641' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:22.103737') OR locked_by = 'delayed_job.1010 host:obs pid:9683') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'issuetracking' ORDER BY
priority ASC, run_at ASC LIMIT 1
[9670:40.05] SQL (0.7ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:23', `delayed_jobs`.`locked_by`
= 'delayed_job.1000 host:obs pid:9670' WHERE ((run_at <= '2016-11-14
21:00:23.119157' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:23.119244') OR locked_by = 'delayed_job.1000 host:obs pid:9670') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'releasetracking' ORDER BY
priority ASC, run_at ASC LIMIT 1
[9641:46.48] SQL (0.5ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:25', `delayed_jobs`.`locked_by`
= 'delayed_job.0 host:obs pid:9641' WHERE ((run_at <= '2016-11-14
21:00:25.363552' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:25.363597') OR locked_by = 'delayed_job.0 host:obs pid:9641') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'quick' ORDER BY priority ASC,
run_at ASC LIMIT 1
[9647:46.87] SQL (0.6ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:25', `delayed_jobs`.`locked_by`
= 'delayed_job.1 host:obs pid:9647' WHERE ((run_at <= '2016-11-14
21:00:25.867966' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:25.868049') OR locked_by = 'delayed_job.1 host:obs pid:9647') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'quick' ORDER BY priority ASC,
run_at ASC LIMIT 1
[9698:35.04] SQL (0.6ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:26', `delayed_jobs`.`locked_by`
= 'delayed_job.1020 host:obs pid:9698' WHERE ((run_at <= '2016-11-14
21:00:26.118395' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:26.118478') OR locked_by = 'delayed_job.1020 host:obs pid:9698') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'mailers' ORDER BY priority
ASC, run_at ASC LIMIT 1
[9713:31.11] SQL (0.8ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:26', `delayed_jobs`.`locked_by`
= 'delayed_job.1030 host:obs pid:9713' WHERE ((run_at <= '2016-11-14
21:00:26.181674' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:26.181758') OR locked_by = 'delayed_job.1030 host:obs pid:9713') AND
failed_at IS NULL) ORDER BY priority ASC, run_at ASC LIMIT 1
[9654:47.52] SQL (0.6ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:26', `delayed_jobs`.`locked_by`
= 'delayed_job.2 host:obs pid:9654' WHERE ((run_at <= '2016-11-14
21:00:26.648203' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:26.648286') OR locked_by = 'delayed_job.2 host:obs pid:9654') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'quick' ORDER BY priority ASC,
run_at ASC LIMIT 1
[9683:40.05] SQL (0.4ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:27', `delayed_jobs`.`locked_by`
= 'delayed_job.1010 host:obs pid:9683' WHERE ((run_at <= '2016-11-14
21:00:27.107185' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:27.107239') OR locked_by = 'delayed_job.1010 host:obs pid:9683') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'issuetracking' ORDER BY
priority ASC, run_at ASC LIMIT 1
[9670:45.05] SQL (0.7ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:28', `delayed_jobs`.`locked_by`
= 'delayed_job.1000 host:obs pid:9670' WHERE ((run_at <= '2016-11-14
21:00:28.122884' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:28.122970') OR locked_by = 'delayed_job.1000 host:obs pid:9670') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'releasetracking' ORDER BY
priority ASC, run_at ASC LIMIT 1
[9724:29.96] --> direct_http url: "/build/_workerstatus"
[9724:29.96] http_do: method: get url:
http://build.de.scorpio-it.net:5352/build/_workerstatus
[9724:29.99] Cache write: workerstatus ({:expires_in=>180 seconds})
[9724:29.99]  (0.3ms) BEGIN
[9724:30.00] SQL (0.5ms) INSERT INTO `status_histories`
(`time`, `key`, `value`) VALUES (1479157229, 'blocked_i586', 2.0)
[9724:30.00] SQL (0.2ms) INSERT INTO `status_histories`
(`time`, `key`, `value`) VALUES (1479157229, 'blocked_x86_64', 0.0)
[9724:30.00] SQL (0.3ms) INSERT INTO `status_histories`
(`time`, `key`, `value`) VALUES (1479157229, 'waiting_i586', 0.0)
[9724:30.00] SQL (0.2ms) INSERT INTO `status_histories`
(`time`, `key`, `value`) VALUES (1479157229, 'waiting_x86_64', 0.0)
[9724:30.00] Architecture Load (0.2ms) SELECT
`architectures`.* FROM `architectures` WHERE `architectures`.`name` = 'i586'
LIMIT 1
[9724:30.00] Architecture Exists (0.3ms) SELECT 1 AS one FROM
`architectures` WHERE (`architectures`.`name` = BINARY 'i586' AND
`architectures`.`id` != 1) LIMIT 1
[9724:30.01] Cache delete: archcache
[9724:30.01] Architecture Load (0.2ms) SELECT
`architectures`.* FROM `architectures` WHERE `architectures`.`name` = 'x86_64'
LIMIT 1
[9724:30.01] Architecture Exists (0.2ms) SELECT 1 AS one FROM
`architectures` WHERE (`architectures`.`name` = BINARY 'x86_64' AND
`architectures`.`id` != 2) LIMIT 1
[9724:30.01] Cache delete: archcache
[9724:30.01] SQL (0.2ms) INSERT INTO `status_histories`
(`time`, `key`, `value`) VALUES (1479157229, 'squeue_high_i586', 0.0)
[9724:30.01] SQL (0.4ms) INSERT INTO `status_histories`
(`time`, `key`, `value`) VALUES (1479157229, 'squeue_next_i586', 0.0)
[9724:30.01] SQL (0.3ms) INSERT INTO `status_histories`
(`time`, `key`, `value`) VALUES (1479157229, 'squeue_med_i586', 0.0)
[9724:30.01] SQL (0.3ms) INSERT INTO `status_histories`
(`time`, `key`, `value`) VALUES (1479157229, 'squeue_low_i586', 1.0)
[9724:30.01] SQL (0.2ms) INSERT INTO `status_histories`
(`time`, `key`, `value`) VALUES (1479157229, 'squeue_high_x86_64', 0.0)
[9724:30.02] SQL (0.2ms) INSERT INTO `status_histories`
(`time`, `key`, `value`) VALUES (1479157229, 'squeue_next_x86_64', 0.0)
[9724:30.02] SQL (0.2ms) INSERT INTO `status_histories`
(`time`, `key`, `value`) VALUES (1479157229, 'squeue_med_x86_64', 0.0)
[9724:30.02] SQL (0.3ms) INSERT INTO `status_histories`
(`time`, `key`, `value`) VALUES (1479157229, 'squeue_low_x86_64', 1.0)
[9724:30.19]  (169.4ms) COMMIT
[9724:30.19]  (0.1ms) BEGIN
[9724:30.19] SQL (0.6ms) INSERT INTO `delayed_jobs`
(`handler`, `queue`, `run_at`) VALUES ('---
!ruby/object:Delayed::PerformableMethod\nobject:
!ruby/object:Event::NotifyBackends {}\nmethod_name: :send_not_in_queue\nargs:
[]\n', 'quick', '2016-11-14 21:00:29')
[9724:30.26]  (69.1ms) COMMIT
[9724:30.26]  (0.1ms) BEGIN
[9724:30.27] SQL (0.2ms) INSERT INTO `delayed_jobs` (`handler`,
`queue`, `run_at`) VALUES ('---
!ruby/object:Delayed::PerformableMethod\nobject: !ruby/object:SendEventEmails
{}\nmethod_name: :perform\nargs: []\n', 'quick', '2016-11-14 21:00:29')
[9724:30.30]  (39.0ms) COMMIT
[9641:51.61] SQL (126.3ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:30', `delayed_jobs`.`locked_by`
= 'delayed_job.0 host:obs pid:9641' WHERE ((run_at <= '2016-11-14
21:00:30.365676' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:30.365764') OR locked_by = 'delayed_job.0 host:obs pid:9641') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'quick' ORDER BY priority ASC,
run_at ASC LIMIT 1
[9641:51.61] Delayed::Backend::ActiveRecord::Job Load (0.9ms)
SELECT `delayed_jobs`.* FROM `delayed_jobs` WHERE
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:30' AND
`delayed_jobs`.`locked_by` = 'delayed_job.0 host:obs pid:9641' AND
`delayed_jobs`.`failed_at` IS NULL ORDER BY `delayed_jobs`.`id` ASC LIMIT 1
[9641:51.61] 2016-11-14T21:00:30+0000: [Worker(delayed_job.0 host:obs
pid:9641)] Job Event::NotifyBackends#send_not_in_queue (id=72929) RUNNING
[9641:51.61] Event::Base Load (0.7ms) SELECT `events`.* FROM
`events` WHERE `events`.`queued` = 0 ORDER BY `events`.`id` ASC LIMIT 1000
[9641:51.61]  (0.2ms) BEGIN
[9641:51.61] SQL (0.4ms) DELETE FROM `delayed_jobs` WHERE
`delayed_jobs`.`id` = 72929
[9641:51.65]  (32.2ms) COMMIT
[9641:51.65] 2016-11-14T21:00:30+0000: [Worker(delayed_job.0 host:obs
pid:9641)] Job Event::NotifyBackends#send_not_in_queue (id=72929) COMPLETED
after 0.0382
[9641:51.69] SQL (40.2ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:30', `delayed_jobs`.`locked_by`
= 'delayed_job.0 host:obs pid:9641' WHERE ((run_at <= '2016-11-14
21:00:30.536390' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:30.536409') OR locked_by = 'delayed_job.0 host:obs pid:9641') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'quick' ORDER BY priority ASC,
run_at ASC LIMIT 1
[9641:51.69] Delayed::Backend::ActiveRecord::Job Load (0.3ms)
SELECT `delayed_jobs`.* FROM `delayed_jobs` WHERE
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:30' AND
`delayed_jobs`.`locked_by` = 'delayed_job.0 host:obs pid:9641' AND
`delayed_jobs`.`failed_at` IS NULL ORDER BY `delayed_jobs`.`id` ASC LIMIT 1
[9641:51.69] 2016-11-14T21:00:30+0000: [Worker(delayed_job.0 host:obs
pid:9641)] Job SendEventEmails#perform (id=72930) RUNNING
[9641:51.69] Event::Base Load (0.3ms) SELECT `events`.* FROM
`events` WHERE `events`.`mails_sent` = 0 ORDER BY `events`.`created_at` ASC
LIMIT 1000 FOR UPDATE
[9641:51.69]  (0.1ms) BEGIN
[9641:51.69] SQL (0.2ms) DELETE FROM `delayed_jobs` WHERE
`delayed_jobs`.`id` = 72930
[9641:51.74]  (45.5ms) COMMIT
[9641:51.74] 2016-11-14T21:00:30+0000: [Worker(delayed_job.0 host:obs
pid:9641)] Job SendEventEmails#perform (id=72930) COMPLETED after 0.0496
[9641:51.74] SQL (0.6ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:30', `delayed_jobs`.`locked_by`
= 'delayed_job.0 host:obs pid:9641' WHERE ((run_at <= '2016-11-14
21:00:30.628895' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:30.628941') OR locked_by = 'delayed_job.0 host:obs pid:9641') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'quick' ORDER BY priority ASC,
run_at ASC LIMIT 1
[9641:51.74] 2016-11-14T21:00:30+0000: [Worker(delayed_job.0 host:obs
pid:9641)] 2 jobs processed at 7.5109 j/s, 0 failed
[9641:51.75] SQL (0.5ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:30', `delayed_jobs`.`locked_by`
= 'delayed_job.0 host:obs pid:9641' WHERE ((run_at <= '2016-11-14
21:00:30.632114' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:30.632157') OR locked_by = 'delayed_job.0 host:obs pid:9641') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'quick' ORDER BY priority ASC,
run_at ASC LIMIT 1
[9647:51.87] SQL (0.6ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:30', `delayed_jobs`.`locked_by`
= 'delayed_job.1 host:obs pid:9647' WHERE ((run_at <= '2016-11-14
21:00:30.871508' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:30.871589') OR locked_by = 'delayed_job.1 host:obs pid:9647') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'quick' ORDER BY priority ASC,
run_at ASC LIMIT 1
[9698:40.05] SQL (0.6ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:31', `delayed_jobs`.`locked_by`
= 'delayed_job.1020 host:obs pid:9698' WHERE ((run_at <= '2016-11-14
21:00:31.122017' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:31.122111') OR locked_by = 'delayed_job.1020 host:obs pid:9698') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'mailers' ORDER BY priority
ASC, run_at ASC LIMIT 1
[9713:36.12] SQL (0.9ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:31', `delayed_jobs`.`locked_by`
= 'delayed_job.1030 host:obs pid:9713' WHERE ((run_at <= '2016-11-14
21:00:31.185114' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:31.185197') OR locked_by = 'delayed_job.1030 host:obs pid:9713') AND
failed_at IS NULL) ORDER BY priority ASC, run_at ASC LIMIT 1
[9654:52.53] SQL (0.6ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:31', `delayed_jobs`.`locked_by`
= 'delayed_job.2 host:obs pid:9654' WHERE ((run_at <= '2016-11-14
21:00:31.651663' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:31.651746') OR locked_by = 'delayed_job.2 host:obs pid:9654') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'quick' ORDER BY priority ASC,
run_at ASC LIMIT 1
[9683:45.05] SQL (0.4ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:32', `delayed_jobs`.`locked_by`
= 'delayed_job.1010 host:obs pid:9683' WHERE ((run_at <= '2016-11-14
21:00:32.109458' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:32.109513') OR locked_by = 'delayed_job.1010 host:obs pid:9683') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'issuetracking' ORDER BY
priority ASC, run_at ASC LIMIT 1
[9724:0.00] User Load (0.3ms) SELECT `users`.* FROM `users`
WHERE `users`.`login` = 'Admin' LIMIT 1
[9670:50.06] SQL (0.7ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:33', `delayed_jobs`.`locked_by`
= 'delayed_job.1000 host:obs pid:9670' WHERE ((run_at <= '2016-11-14
21:00:33.126439' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:33.126483') OR locked_by = 'delayed_job.1000 host:obs pid:9670') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'releasetracking' ORDER BY
priority ASC, run_at ASC LIMIT 1
[9641:56.75] SQL (0.6ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:35', `delayed_jobs`.`locked_by`
= 'delayed_job.0 host:obs pid:9641' WHERE ((run_at <= '2016-11-14
21:00:35.634956' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:35.635043') OR locked_by = 'delayed_job.0 host:obs pid:9641') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'quick' ORDER BY priority ASC,
run_at ASC LIMIT 1
[9647:56.87] SQL (0.6ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:35', `delayed_jobs`.`locked_by`
= 'delayed_job.1 host:obs pid:9647' WHERE ((run_at <= '2016-11-14
21:00:35.874890' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:35.874968') OR locked_by = 'delayed_job.1 host:obs pid:9647') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'quick' ORDER BY priority ASC,
run_at ASC LIMIT 1
[9698:45.05] SQL (0.6ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:36', `delayed_jobs`.`locked_by`
= 'delayed_job.1020 host:obs pid:9698' WHERE ((run_at <= '2016-11-14
21:00:36.125651' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:36.125737') OR locked_by = 'delayed_job.1020 host:obs pid:9698') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'mailers' ORDER BY priority
ASC, run_at ASC LIMIT 1
[9713:41.12] SQL (0.8ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:36', `delayed_jobs`.`locked_by`
= 'delayed_job.1030 host:obs pid:9713' WHERE ((run_at <= '2016-11-14
21:00:36.188600' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:36.188682') OR locked_by = 'delayed_job.1030 host:obs pid:9713') AND
failed_at IS NULL) ORDER BY priority ASC, run_at ASC LIMIT 1
[9654:57.53] SQL (0.6ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:36', `delayed_jobs`.`locked_by`
= 'delayed_job.2 host:obs pid:9654' WHERE ((run_at <= '2016-11-14
21:00:36.655275' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:36.655357') OR locked_by = 'delayed_job.2 host:obs pid:9654') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'quick' ORDER BY priority ASC,
run_at ASC LIMIT 1
[9683:50.05] SQL (0.4ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:37', `delayed_jobs`.`locked_by`
= 'delayed_job.1010 host:obs pid:9683' WHERE ((run_at <= '2016-11-14
21:00:37.111380' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:37.111461') OR locked_by = 'delayed_job.1010 host:obs pid:9683') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'issuetracking' ORDER BY
priority ASC, run_at ASC LIMIT 1
[9670:55.06] SQL (0.7ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:38', `delayed_jobs`.`locked_by`
= 'delayed_job.1000 host:obs pid:9670' WHERE ((run_at <= '2016-11-14
21:00:38.129108' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:38.129201') OR locked_by = 'delayed_job.1000 host:obs pid:9670') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'releasetracking' ORDER BY
priority ASC, run_at ASC LIMIT 1
[9641:61.75] SQL (0.6ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:40', `delayed_jobs`.`locked_by`
= 'delayed_job.0 host:obs pid:9641' WHERE ((run_at <= '2016-11-14
21:00:40.638529' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:40.638626') OR locked_by = 'delayed_job.0 host:obs pid:9641') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'quick' ORDER BY priority ASC,
run_at ASC LIMIT 1
[9647:61.88] SQL (0.6ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:40', `delayed_jobs`.`locked_by`
= 'delayed_job.1 host:obs pid:9647' WHERE ((run_at <= '2016-11-14
21:00:40.878368' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:40.878447') OR locked_by = 'delayed_job.1 host:obs pid:9647') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'quick' ORDER BY priority ASC,
run_at ASC LIMIT 1
[9698:50.05] SQL (0.7ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:41', `delayed_jobs`.`locked_by`
= 'delayed_job.1020 host:obs pid:9698' WHERE ((run_at <= '2016-11-14
21:00:41.129202' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:41.129286') OR locked_by = 'delayed_job.1020 host:obs pid:9698') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'mailers' ORDER BY priority
ASC, run_at ASC LIMIT 1
[9713:46.12] SQL (0.8ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:41', `delayed_jobs`.`locked_by`
= 'delayed_job.1030 host:obs pid:9713' WHERE ((run_at <= '2016-11-14
21:00:41.191979' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:41.192062') OR locked_by = 'delayed_job.1030 host:obs pid:9713') AND
failed_at IS NULL) ORDER BY priority ASC, run_at ASC LIMIT 1
[9654:62.53] SQL (0.6ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:41', `delayed_jobs`.`locked_by`
= 'delayed_job.2 host:obs pid:9654' WHERE ((run_at <= '2016-11-14
21:00:41.658858' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:41.658940') OR locked_by = 'delayed_job.2 host:obs pid:9654') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'quick' ORDER BY priority ASC,
run_at ASC LIMIT 1
[9683:55.05] SQL (0.3ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:42', `delayed_jobs`.`locked_by`
= 'delayed_job.1010 host:obs pid:9683' WHERE ((run_at <= '2016-11-14
21:00:42.113321' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:42.113366') OR locked_by = 'delayed_job.1010 host:obs pid:9683') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'issuetracking' ORDER BY
priority ASC, run_at ASC LIMIT 1
[9670:60.06] SQL (0.4ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:43', `delayed_jobs`.`locked_by`
= 'delayed_job.1000 host:obs pid:9670' WHERE ((run_at <= '2016-11-14
21:00:43.132595' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:43.132637') OR locked_by = 'delayed_job.1000 host:obs pid:9670') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'releasetracking' ORDER BY
priority ASC, run_at ASC LIMIT 1
[9641:66.76] SQL (0.4ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:45', `delayed_jobs`.`locked_by`
= 'delayed_job.0 host:obs pid:9641' WHERE ((run_at <= '2016-11-14
21:00:45.642051' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:45.642098') OR locked_by = 'delayed_job.0 host:obs pid:9641') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'quick' ORDER BY priority ASC,
run_at ASC LIMIT 1
[9647:66.88] SQL (0.4ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:45', `delayed_jobs`.`locked_by`
= 'delayed_job.1 host:obs pid:9647' WHERE ((run_at <= '2016-11-14
21:00:45.881723' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:45.881768') OR locked_by = 'delayed_job.1 host:obs pid:9647') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'quick' ORDER BY priority ASC,
run_at ASC LIMIT 1
[9698:55.06] SQL (0.9ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:46', `delayed_jobs`.`locked_by`
= 'delayed_job.1020 host:obs pid:9698' WHERE ((run_at <= '2016-11-14
21:00:46.132771' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:46.132868') OR locked_by = 'delayed_job.1020 host:obs pid:9698') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'mailers' ORDER BY priority
ASC, run_at ASC LIMIT 1
[9713:51.22] SQL (96.4ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:46', `delayed_jobs`.`locked_by`
= 'delayed_job.1030 host:obs pid:9713' WHERE ((run_at <= '2016-11-14
21:00:46.195198' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:46.195243') OR locked_by = 'delayed_job.1030 host:obs pid:9713') AND
failed_at IS NULL) ORDER BY priority ASC, run_at ASC LIMIT 1
[9713:51.23] Delayed::Backend::ActiveRecord::Job Load (0.9ms)
SELECT `delayed_jobs`.* FROM `delayed_jobs` WHERE `delayed_jobs`.`locked_at` =
'2016-11-14 21:00:46' AND `delayed_jobs`.`locked_by` = 'delayed_job.1030
host:obs pid:9713' AND `delayed_jobs`.`failed_at` IS NULL ORDER BY
`delayed_jobs`.`id` ASC LIMIT 1
[9713:51.23] 2016-11-14T21:00:46+0000: [Worker(delayed_job.1030 host:obs
pid:9713)] Job ActiveJob::QueueAdapters::DelayedJobAdapter::JobWrapper
(id=72927) RUNNING
[ActiveJob] [ConsistencyCheckJob] [b7bc9da8-1632-4056-8d76-d2cea36ddbf6]
[9713:51.23] Performing ConsistencyCheckJob from DelayedJob(default)
[ActiveJob] [ConsistencyCheckJob] [b7bc9da8-1632-4056-8d76-d2cea36ddbf6]
[9713:51.23] User Load (0.3ms) SELECT `users`.* FROM
`users` WHERE `users`.`login` = 'Admin' LIMIT 1
[ActiveJob] [ConsistencyCheckJob] [b7bc9da8-1632-4056-8d76-d2cea36ddbf6]
[9713:51.23] Performed ConsistencyCheckJob from DelayedJob(default) in 5.13ms
[9713:51.23] 2016-11-14T21:00:46+0000: [Worker(delayed_job.1030 host:obs
pid:9713)] Job ActiveJob::QueueAdapters::DelayedJobAdapter::JobWrapper
(id=72927) FAILED (2 prior attempts) with NoMethodError: undefined method
`is_admin?' for nil:NilClass
Did you mean? is_haml?
[9713:51.23]  (0.1ms) BEGIN
[9713:51.24] SQL (0.3ms) UPDATE `delayed_jobs` SET
`attempts` = 3, `run_at` = '2016-11-14 21:02:12', `locked_at` = NULL,
`locked_by` = NULL WHERE `delayed_jobs`.`id` = 72927
[9713:51.27]  (36.7ms) COMMIT
[9713:51.31] SQL (31.8ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:46', `delayed_jobs`.`locked_by`
= 'delayed_job.1030 host:obs pid:9713' WHERE ((run_at <= '2016-11-14
21:00:46.342943' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:46.342981') OR locked_by = 'delayed_job.1030 host:obs pid:9713') AND
failed_at IS NULL) ORDER BY priority ASC, run_at ASC LIMIT 1
[9713:51.31] Delayed::Backend::ActiveRecord::Job Load (0.8ms)
SELECT `delayed_jobs`.* FROM `delayed_jobs` WHERE `delayed_jobs`.`locked_at` =
'2016-11-14 21:00:46' AND `delayed_jobs`.`locked_by` = 'delayed_job.1030
host:obs pid:9713' AND `delayed_jobs`.`failed_at` IS NULL ORDER BY
`delayed_jobs`.`id` ASC LIMIT 1
[9713:51.31] 2016-11-14T21:00:46+0000: [Worker(delayed_job.1030 host:obs
pid:9713)] Job ConsistencyCheckJob#perform (id=72928) RUNNING
[9713:51.31] User Load (0.4ms) SELECT `users`.* FROM
`users` WHERE `users`.`login` = 'Admin' LIMIT 1
[9713:51.32] 2016-11-14T21:00:46+0000: [Worker(delayed_job.1030 host:obs
pid:9713)] Job ConsistencyCheckJob#perform (id=72928) FAILED (2 prior attempts)
with NoMethodError: undefined method `is_admin?' for nil:NilClass
Did you mean? is_haml?
[9713:51.32]  (0.2ms) BEGIN
[9713:51.32] SQL (0.4ms) UPDATE `delayed_jobs` SET
`attempts` = 3, `run_at` = '2016-11-14 21:02:12', `locked_at` = NULL,
`locked_by` = NULL WHERE `delayed_jobs`.`id` = 72928
[9713:51.36]  (34.0ms) COMMIT
[9713:51.36] SQL (0.3ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:46', `delayed_jobs`.`locked_by`
= 'delayed_job.1030 host:obs pid:9713' WHERE ((run_at <= '2016-11-14
21:00:46.426122' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:46.426152') OR locked_by = 'delayed_job.1030 host:obs pid:9713') AND
failed_at IS NULL) ORDER BY priority ASC, run_at ASC LIMIT 1
[9713:51.36] 2016-11-14T21:00:46+0000: [Worker(delayed_job.1030 host:obs
pid:9713)] 2 jobs processed at 8.6128 j/s, 2 failed
[9713:51.36] SQL (0.3ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:46', `delayed_jobs`.`locked_by`
= 'delayed_job.1030 host:obs pid:9713' WHERE ((run_at <= '2016-11-14
21:00:46.427519' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:46.427538') OR locked_by = 'delayed_job.1030 host:obs pid:9713') AND
failed_at IS NULL) ORDER BY priority ASC, run_at ASC LIMIT 1
[9641:0.00] 2016-11-14T21:00:46+0000: [Worker(delayed_job.0 host:obs pid:9641)]
Exiting...
[9654:67.54] SQL (0.4ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:46', `delayed_jobs`.`locked_by`
= 'delayed_job.2 host:obs pid:9654' WHERE ((run_at <= '2016-11-14
21:00:46.662346' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:46.662388') OR locked_by = 'delayed_job.2 host:obs pid:9654') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'quick' ORDER BY priority ASC,
run_at ASC LIMIT 1
[9683:60.06] SQL (0.4ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:47', `delayed_jobs`.`locked_by`
= 'delayed_job.1010 host:obs pid:9683' WHERE ((run_at <= '2016-11-14
21:00:47.115135' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:47.115182') OR locked_by = 'delayed_job.1010 host:obs pid:9683') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'issuetracking' ORDER BY
priority ASC, run_at ASC LIMIT 1
[9670:65.06] SQL (0.8ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:48', `delayed_jobs`.`locked_by`
= 'delayed_job.1000 host:obs pid:9670' WHERE ((run_at <= '2016-11-14
21:00:48.134541' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:48.134633') OR locked_by = 'delayed_job.1000 host:obs pid:9670') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'releasetracking' ORDER BY
priority ASC, run_at ASC LIMIT 1
[9724:0.00] User Load (0.6ms) SELECT `users`.* FROM
`users` WHERE `users`.`login` = 'Admin' LIMIT 1
[9641:71.76] SQL (0.7ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_by` = NULL, `delayed_jobs`.`locked_at` = NULL WHERE
`delayed_jobs`.`locked_by` = 'delayed_job.0 host:obs pid:9641'
[9647:71.88] SQL (0.3ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:50', `delayed_jobs`.`locked_by`
= 'delayed_job.1 host:obs pid:9647' WHERE ((run_at <= '2016-11-14
21:00:50.883577' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:50.883626') OR locked_by = 'delayed_job.1 host:obs pid:9647') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'quick' ORDER BY priority ASC,
run_at ASC LIMIT 1
[9647:0.00] 2016-11-14T21:00:50+0000: [Worker(delayed_job.1 host:obs pid:9647)]
Exiting...
[9698:60.06] SQL (0.3ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:51', `delayed_jobs`.`locked_by`
= 'delayed_job.1020 host:obs pid:9698' WHERE ((run_at <= '2016-11-14
21:00:51.136444' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:51.136491') OR locked_by = 'delayed_job.1020 host:obs pid:9698') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'mailers' ORDER BY priority
ASC, run_at ASC LIMIT 1
[9713:56.36] SQL (0.9ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:51', `delayed_jobs`.`locked_by`
= 'delayed_job.1030 host:obs pid:9713' WHERE ((run_at <= '2016-11-14
21:00:51.428884' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:51.428967') OR locked_by = 'delayed_job.1030 host:obs pid:9713') AND
failed_at IS NULL) ORDER BY priority ASC, run_at ASC LIMIT 1
[9654:72.54] SQL (0.6ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:51', `delayed_jobs`.`locked_by`
= 'delayed_job.2 host:obs pid:9654' WHERE ((run_at <= '2016-11-14
21:00:51.664352' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:51.664434') OR locked_by = 'delayed_job.2 host:obs pid:9654') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'quick' ORDER BY priority ASC,
run_at ASC LIMIT 1
[9683:65.06] SQL (0.4ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:52', `delayed_jobs`.`locked_by`
= 'delayed_job.1010 host:obs pid:9683' WHERE ((run_at <= '2016-11-14
21:00:52.117066' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:52.117121') OR locked_by = 'delayed_job.1010 host:obs pid:9683') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'issuetracking' ORDER BY
priority ASC, run_at ASC LIMIT 1
[9670:70.07] SQL (0.6ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:53', `delayed_jobs`.`locked_by`
= 'delayed_job.1000 host:obs pid:9670' WHERE ((run_at <= '2016-11-14
21:00:53.138419' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:53.138502') OR locked_by = 'delayed_job.1000 host:obs pid:9670') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'releasetracking' ORDER BY
priority ASC, run_at ASC LIMIT 1
[9647:76.88] SQL (0.7ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_by` = NULL, `delayed_jobs`.`locked_at` = NULL WHERE
`delayed_jobs`.`locked_by` = 'delayed_job.1 host:obs pid:9647'
[9698:65.06] SQL (0.4ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:56', `delayed_jobs`.`locked_by`
= 'delayed_job.1020 host:obs pid:9698' WHERE ((run_at <= '2016-11-14
21:00:56.138183' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:56.138232') OR locked_by = 'delayed_job.1020 host:obs pid:9698') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'mailers' ORDER BY priority
ASC, run_at ASC LIMIT 1
[9654:0.00] 2016-11-14T21:00:56+0000: [Worker(delayed_job.2 host:obs pid:9654)]
Exiting...
[9713:61.37] SQL (0.8ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:56', `delayed_jobs`.`locked_by`
= 'delayed_job.1030 host:obs pid:9713' WHERE ((run_at <= '2016-11-14
21:00:56.432357' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:56.432440') OR locked_by = 'delayed_job.1030 host:obs pid:9713') AND
failed_at IS NULL) ORDER BY priority ASC, run_at ASC LIMIT 1
[9654:77.54] SQL (0.3ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_by` = NULL, `delayed_jobs`.`locked_at` = NULL WHERE
`delayed_jobs`.`locked_by` = 'delayed_job.2 host:obs pid:9654'
[9683:70.06] SQL (0.4ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:57', `delayed_jobs`.`locked_by`
= 'delayed_job.1010 host:obs pid:9683' WHERE ((run_at <= '2016-11-14
21:00:57.119206' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:57.119248') OR locked_by = 'delayed_job.1010 host:obs pid:9683') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'issuetracking' ORDER BY
priority ASC, run_at ASC LIMIT 1
[9670:75.07] SQL (0.7ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:00:58', `delayed_jobs`.`locked_by`
= 'delayed_job.1000 host:obs pid:9670' WHERE ((run_at <= '2016-11-14
21:00:58.142022' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:00:58.142121') OR locked_by = 'delayed_job.1000 host:obs pid:9670') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'releasetracking' ORDER BY
priority ASC, run_at ASC LIMIT 1
[9724:59.96] --> direct_http url: "/build/_workerstatus"
[9724:59.96] http_do: method: get url:
http://build.de.scorpio-it.net:5352/build/_workerstatus
[9724:59.98] Cache write: workerstatus ({:expires_in=>180 seconds})
[9724:59.98]  (0.1ms) BEGIN
[9724:59.98] SQL (0.3ms) INSERT INTO `status_histories`
(`time`, `key`, `value`) VALUES (1479157259, 'blocked_i586', 2.0)
[9724:59.98] SQL (0.2ms) INSERT INTO `status_histories`
(`time`, `key`, `value`) VALUES (1479157259, 'blocked_x86_64', 0.0)
[9724:59.98] SQL (0.2ms) INSERT INTO `status_histories`
(`time`, `key`, `value`) VALUES (1479157259, 'waiting_i586', 0.0)
[9724:59.98] SQL (0.2ms) INSERT INTO `status_histories`
(`time`, `key`, `value`) VALUES (1479157259, 'waiting_x86_64', 0.0)
[9724:59.98] Architecture Load (0.2ms) SELECT
`architectures`.* FROM `architectures` WHERE `architectures`.`name` = 'i586'
LIMIT 1
[9724:59.99] Architecture Exists (0.3ms) SELECT 1 AS one FROM
`architectures` WHERE (`architectures`.`name` = BINARY 'i586' AND
`architectures`.`id` != 1) LIMIT 1
[9724:59.99] Cache delete: archcache
[9724:59.99] Architecture Load (0.2ms) SELECT
`architectures`.* FROM `architectures` WHERE `architectures`.`name` = 'x86_64'
LIMIT 1
[9724:59.99] Architecture Exists (0.2ms) SELECT 1 AS one FROM
`architectures` WHERE (`architectures`.`name` = BINARY 'x86_64' AND
`architectures`.`id` != 2) LIMIT 1
[9724:59.99] Cache delete: archcache
[9724:60.00] SQL (13.9ms) INSERT INTO `status_histories`
(`time`, `key`, `value`) VALUES (1479157259, 'squeue_high_i586', 0.0)
[9724:60.01] SQL (0.3ms) INSERT INTO `status_histories`
(`time`, `key`, `value`) VALUES (1479157259, 'squeue_next_i586', 0.0)
[9724:60.01] SQL (0.2ms) INSERT INTO `status_histories`
(`time`, `key`, `value`) VALUES (1479157259, 'squeue_med_i586', 0.0)
[9724:60.01] SQL (0.2ms) INSERT INTO `status_histories`
(`time`, `key`, `value`) VALUES (1479157259, 'squeue_low_i586', 1.0)
[9724:60.01] SQL (0.2ms) INSERT INTO `status_histories`
(`time`, `key`, `value`) VALUES (1479157259, 'squeue_high_x86_64', 0.0)
[9724:60.01] SQL (0.2ms) INSERT INTO `status_histories`
(`time`, `key`, `value`) VALUES (1479157259, 'squeue_next_x86_64', 0.0)
[9724:60.01] SQL (0.2ms) INSERT INTO `status_histories`
(`time`, `key`, `value`) VALUES (1479157259, 'squeue_med_x86_64', 0.0)
[9724:60.01] SQL (0.2ms) INSERT INTO `status_histories`
(`time`, `key`, `value`) VALUES (1479157259, 'squeue_low_x86_64', 1.0)
[9724:60.34]  (321.6ms) COMMIT
[9724:60.34]  (0.2ms) BEGIN
[9724:60.35] SQL (1.1ms) INSERT INTO `delayed_jobs`
(`handler`, `queue`, `run_at`) VALUES ('---
!ruby/object:Delayed::PerformableMethod\nobject:
!ruby/object:Event::NotifyBackends {}\nmethod_name: :send_not_in_queue\nargs:
[]\n', 'quick', '2016-11-14 21:00:59')
[9724:60.40]  (52.8ms) COMMIT
[9724:60.40]  (0.1ms) BEGIN
[9724:60.40] SQL (0.2ms) INSERT INTO `delayed_jobs` (`handler`,
`queue`, `run_at`) VALUES ('---
!ruby/object:Delayed::PerformableMethod\nobject: !ruby/object:SendEventEmails
{}\nmethod_name: :perform\nargs: []\n', 'quick', '2016-11-14 21:00:59')
[9724:60.45]  (46.7ms) COMMIT
[9670:0.00] 2016-11-14T21:01:00+0000: [Worker(delayed_job.1000 host:obs
pid:9670)] Exiting...
[9698:70.06] SQL (0.4ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:01:01', `delayed_jobs`.`locked_by`
= 'delayed_job.1020 host:obs pid:9698' WHERE ((run_at <= '2016-11-14
21:01:01.140067' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:01:01.140110') OR locked_by = 'delayed_job.1020 host:obs pid:9698') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'mailers' ORDER BY priority
ASC, run_at ASC LIMIT 1
[9713:66.47] SQL (104.4ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:01:01', `delayed_jobs`.`locked_by`
= 'delayed_job.1030 host:obs pid:9713' WHERE ((run_at <= '2016-11-14
21:01:01.435555' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:01:01.435597') OR locked_by = 'delayed_job.1030 host:obs pid:9713') AND
failed_at IS NULL) ORDER BY priority ASC, run_at ASC LIMIT 1
[9713:66.47] Delayed::Backend::ActiveRecord::Job Load (0.4ms)
SELECT `delayed_jobs`.* FROM `delayed_jobs` WHERE `delayed_jobs`.`locked_at` =
'2016-11-14 21:01:01' AND `delayed_jobs`.`locked_by` = 'delayed_job.1030
host:obs pid:9713' AND `delayed_jobs`.`failed_at` IS NULL ORDER BY
`delayed_jobs`.`id` ASC LIMIT 1
[9713:66.47] 2016-11-14T21:01:01+0000: [Worker(delayed_job.1030 host:obs
pid:9713)] Job Event::NotifyBackends#send_not_in_queue (id=72931) RUNNING
[9713:66.47] Event::Base Load (0.3ms) SELECT `events`.*
FROM `events` WHERE `events`.`queued` = 0 ORDER BY `events`.`id` ASC LIMIT
1000
[9713:66.47]  (0.1ms) BEGIN
[9713:66.48] SQL (0.2ms) DELETE FROM `delayed_jobs` WHERE
`delayed_jobs`.`id` = 72931
[9713:66.51]  (36.5ms) COMMIT
[9713:66.51] 2016-11-14T21:01:01+0000: [Worker(delayed_job.1030 host:obs
pid:9713)] Job Event::NotifyBackends#send_not_in_queue (id=72931) COMPLETED
after 0.0400
[9713:66.55] SQL (40.6ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:01:01', `delayed_jobs`.`locked_by`
= 'delayed_job.1030 host:obs pid:9713' WHERE ((run_at <= '2016-11-14
21:01:01.582822' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:01:01.582842') OR locked_by = 'delayed_job.1030 host:obs pid:9713') AND
failed_at IS NULL) ORDER BY priority ASC, run_at ASC LIMIT 1
[9713:66.56] Delayed::Backend::ActiveRecord::Job Load (0.3ms)
SELECT `delayed_jobs`.* FROM `delayed_jobs` WHERE `delayed_jobs`.`locked_at` =
'2016-11-14 21:01:01' AND `delayed_jobs`.`locked_by` = 'delayed_job.1030
host:obs pid:9713' AND `delayed_jobs`.`failed_at` IS NULL ORDER BY
`delayed_jobs`.`id` ASC LIMIT 1
[9713:66.56] 2016-11-14T21:01:01+0000: [Worker(delayed_job.1030 host:obs
pid:9713)] Job SendEventEmails#perform (id=72932) RUNNING
[9713:66.56] Event::Base Load (0.3ms) SELECT `events`.*
FROM `events` WHERE `events`.`mails_sent` = 0 ORDER BY `events`.`created_at`
ASC LIMIT 1000 FOR UPDATE
[9713:66.56]  (0.1ms) BEGIN
[9713:66.56] SQL (0.2ms) DELETE FROM `delayed_jobs` WHERE
`delayed_jobs`.`id` = 72932
[9713:66.60]  (36.8ms) COMMIT
[9713:66.60] 2016-11-14T21:01:01+0000: [Worker(delayed_job.1030 host:obs
pid:9713)] Job SendEventEmails#perform (id=72932) COMPLETED after 0.0402
[9713:66.60] SQL (0.3ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:01:01', `delayed_jobs`.`locked_by`
= 'delayed_job.1030 host:obs pid:9713' WHERE ((run_at <= '2016-11-14
21:01:01.666137' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:01:01.666159') OR locked_by = 'delayed_job.1030 host:obs pid:9713') AND
failed_at IS NULL) ORDER BY priority ASC, run_at ASC LIMIT 1
[9713:66.60] 2016-11-14T21:01:01+0000: [Worker(delayed_job.1030 host:obs
pid:9713)] 2 jobs processed at 8.6275 j/s, 0 failed
[9713:66.60] SQL (0.3ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:01:01', `delayed_jobs`.`locked_by`
= 'delayed_job.1030 host:obs pid:9713' WHERE ((run_at <= '2016-11-14
21:01:01.667468' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:01:01.667488') OR locked_by = 'delayed_job.1030 host:obs pid:9713') AND
failed_at IS NULL) ORDER BY priority ASC, run_at ASC LIMIT 1
[9683:75.06] SQL (0.4ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:01:02', `delayed_jobs`.`locked_by`
= 'delayed_job.1010 host:obs pid:9683' WHERE ((run_at <= '2016-11-14
21:01:02.121103' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:01:02.121150') OR locked_by = 'delayed_job.1010 host:obs pid:9683') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'issuetracking' ORDER BY
priority ASC, run_at ASC LIMIT 1
[9670:80.07] SQL (0.3ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_by` = NULL, `delayed_jobs`.`locked_at` = NULL WHERE
`delayed_jobs`.`locked_by` = 'delayed_job.1000 host:obs pid:9670'
[9698:75.07] SQL (0.5ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:01:06', `delayed_jobs`.`locked_by`
= 'delayed_job.1020 host:obs pid:9698' WHERE ((run_at <= '2016-11-14
21:01:06.141893' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:01:06.141942') OR locked_by = 'delayed_job.1020 host:obs pid:9698') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'mailers' ORDER BY priority
ASC, run_at ASC LIMIT 1
[9713:71.60] SQL (0.5ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:01:06', `delayed_jobs`.`locked_by`
= 'delayed_job.1030 host:obs pid:9713' WHERE ((run_at <= '2016-11-14
21:01:06.668738' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:01:06.668787') OR locked_by = 'delayed_job.1030 host:obs pid:9713') AND
failed_at IS NULL) ORDER BY priority ASC, run_at ASC LIMIT 1
[9724:0.00] User Load (0.4ms) SELECT `users`.* FROM `users`
WHERE `users`.`login` = 'Admin' LIMIT 1
[9683:80.06] SQL (0.4ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:01:07', `delayed_jobs`.`locked_by`
= 'delayed_job.1010 host:obs pid:9683' WHERE ((run_at <= '2016-11-14
21:01:07.122894' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:01:07.122945') OR locked_by = 'delayed_job.1010 host:obs pid:9683') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'issuetracking' ORDER BY
priority ASC, run_at ASC LIMIT 1
[9683:0.00] 2016-11-14T21:01:07+0000: [Worker(delayed_job.1010 host:obs
pid:9683)] Exiting...
[9698:80.07] SQL (0.7ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:01:11', `delayed_jobs`.`locked_by`
= 'delayed_job.1020 host:obs pid:9698' WHERE ((run_at <= '2016-11-14
21:01:11.144177' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:01:11.144269') OR locked_by = 'delayed_job.1020 host:obs pid:9698') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'mailers' ORDER BY priority
ASC, run_at ASC LIMIT 1
[9713:76.60] SQL (0.9ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:01:11', `delayed_jobs`.`locked_by`
= 'delayed_job.1030 host:obs pid:9713' WHERE ((run_at <= '2016-11-14
21:01:11.670858' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:01:11.670943') OR locked_by = 'delayed_job.1030 host:obs pid:9713') AND
failed_at IS NULL) ORDER BY priority ASC, run_at ASC LIMIT 1
[9683:85.07] SQL (0.4ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_by` = NULL, `delayed_jobs`.`locked_at` = NULL WHERE
`delayed_jobs`.`locked_by` = 'delayed_job.1010 host:obs pid:9683'
[9698:85.07] SQL (0.4ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:01:16', `delayed_jobs`.`locked_by`
= 'delayed_job.1020 host:obs pid:9698' WHERE ((run_at <= '2016-11-14
21:01:16.147822' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:01:16.147884') OR locked_by = 'delayed_job.1020 host:obs pid:9698') AND
failed_at IS NULL) AND `delayed_jobs`.`queue` = 'mailers' ORDER BY priority
ASC, run_at ASC LIMIT 1
[9698:0.00] 2016-11-14T21:01:16+0000: [Worker(delayed_job.1020 host:obs
pid:9698)] Exiting...
[9713:81.61] SQL (0.9ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:01:16', `delayed_jobs`.`locked_by`
= 'delayed_job.1030 host:obs pid:9713' WHERE ((run_at <= '2016-11-14
21:01:16.674606' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:01:16.674691') OR locked_by = 'delayed_job.1030 host:obs pid:9713') AND
failed_at IS NULL) ORDER BY priority ASC, run_at ASC LIMIT 1
[9698:90.07] SQL (1.0ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_by` = NULL, `delayed_jobs`.`locked_at` = NULL WHERE
`delayed_jobs`.`locked_by` = 'delayed_job.1020 host:obs pid:9698'
[9713:86.61] SQL (0.6ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_at` = '2016-11-14 21:01:21', `delayed_jobs`.`locked_by`
= 'delayed_job.1030 host:obs pid:9713' WHERE ((run_at <= '2016-11-14
21:01:21.678056' AND (locked_at IS NULL OR locked_at < '2016-11-14
17:01:21.678104') OR locked_by = 'delayed_job.1030 host:obs pid:9713') AND
failed_at IS NULL) ORDER BY priority ASC, run_at ASC LIMIT 1
[9724:0.00] User Load (0.4ms) SELECT `users`.* FROM
`users` WHERE `users`.`login` = 'Admin' LIMIT 1
[9713:0.00] 2016-11-14T21:01:25+0000: [Worker(delayed_job.1030 host:obs
pid:9713)] Exiting...
[9713:91.61] SQL (0.4ms) UPDATE `delayed_jobs` SET
`delayed_jobs`.`locked_by` = NULL, `delayed_jobs`.`locked_at` = NULL WHERE
`delayed_jobs`.`locked_by` = 'delayed_job.1030 host:obs pid:9713'
< Previous Next >
Follow Ups