{"action":"created","issue":{"url":"https://api.github.com/repos/cloudfoundry/bosh/issues/1224","repository_url":"https://api.github.com/repos/cloudfoundry/bosh","labels_url":"https://api.github.com/repos/cloudfoundry/bosh/issues/1224/labels{/name}","comments_url":"https://api.github.com/repos/cloudfoundry/bosh/issues/1224/comments","events_url":"https://api.github.com/repos/cloudfoundry/bosh/issues/1224/events","html_url":"https://github.com/cloudfoundry/bosh/issues/1224","id":149356539,"number":1224,"title":"DB inconsistency and Nil dereference ","user":{"login":"tomoe","id":468185,"avatar_url":"https://avatars.githubusercontent.com/u/468185?v=3","gravatar_id":"","url":"https://api.github.com/users/tomoe","html_url":"https://github.com/tomoe","followers_url":"https://api.github.com/users/tomoe/followers","following_url":"https://api.github.com/users/tomoe/following{/other_user}","gists_url":"https://api.github.com/users/tomoe/gists{/gist_id}","starred_url":"https://api.github.com/users/tomoe/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/tomoe/subscriptions","organizations_url":"https://api.github.com/users/tomoe/orgs","repos_url":"https://api.github.com/users/tomoe/repos","events_url":"https://api.github.com/users/tomoe/events{/privacy}","received_events_url":"https://api.github.com/users/tomoe/received_events","type":"User","site_admin":false},"labels":[{"url":"https://api.github.com/repos/cloudfoundry/bosh/labels/problem","name":"problem","color":"eb6420"}],"state":"open","locked":false,"assignee":null,"milestone":null,"comments":5,"created_at":"2016-04-19T06:01:00Z","updated_at":"2016-05-09T08:46:54Z","closed_at":null,"body":"This is caused by #1223\r\n\r\n### bosh task  --debug log\r\n```\r\nActing as user 'director' on 'p-bosh-f3b1fb3436882cdaa51b'\r\n\r\nDirector task 483\r\nI, [2016-04-17T22:01:09.769108 #2545] [0x2b1a692e5334]  INFO -- TaskHelper: Director Version: 1.3146.10.0\r\nI, [2016-04-17T22:01:09.769161 #2545] [0x2b1a692e5334]  INFO -- TaskHelper: Enqueuing task: 483\r\nI, [2016-04-17 22:01:10 #10857] []  INFO -- DirectorJobRunner: Looking for task with task id 483\r\nD, [2016-04-17 22:01:10 #10857] [] DEBUG -- DirectorJobRunner: (0.000630s) SELECT NULL\r\nD, [2016-04-17 22:01:10 #10857] [] DEBUG -- DirectorJobRunner: (0.000621s) SELECT * FROM \"tasks\" WHERE \"id\" = 483\r\nI, [2016-04-17 22:01:10 #10857] []  INFO -- DirectorJobRunner: Found task #<Bosh::Director::Models::Task @values={:id=>483, :state=>\"queued\", :timestamp=>2016-04-17 22:01:09 +0000, :description=>\"scan and fix\", :result=>nil, :output=>\"/var/vcap/store/director/tasks/483\", :checkpoint_time=>2016-04-17 22:01:09 +0000, :type=>\"cck_scan_and_fix\", :username=>\"director\"}>\r\nI, [2016-04-17 22:01:10 #10857] []  INFO -- DirectorJobRunner: Starting task: 483\r\nI, [2016-04-17 22:01:10 #10857] [task:483]  INFO -- DirectorJobRunner: Creating job\r\nD, [2016-04-17 22:01:10 #10857] [task:483] DEBUG -- DirectorJobRunner: (0.000279s) SELECT NULL\r\nD, [2016-04-17 22:01:10 #10857] [task:483] DEBUG -- DirectorJobRunner: (0.000195s) SELECT NULL\r\nD, [2016-04-17 22:01:10 #10857] [task:483] DEBUG -- DirectorJobRunner: (0.004402s) SELECT * FROM \"deployments\" WHERE (\"name\" = 'cf-88d0a479447294d3465e') LIMIT 1\r\nD, [2016-04-17 22:01:10 #10857] [task:483] DEBUG -- DirectorJobRunner: (0.000213s) SELECT NULL\r\nD, [2016-04-17 22:01:10 #10857] [task:483] DEBUG -- DirectorJobRunner: (0.000375s) SELECT * FROM \"tasks\" WHERE \"id\" = 483\r\nD, [2016-04-17 22:01:10 #10857] [task:483] DEBUG -- DirectorJobRunner: (0.000204s) SELECT NULL\r\nD, [2016-04-17 22:01:10 #10857] [task:483] DEBUG -- DirectorJobRunner: (0.000359s) SELECT * FROM \"tasks\" WHERE \"id\" = 483\r\nI, [2016-04-17 22:01:10 #10857] [task:483]  INFO -- DirectorJobRunner: Performing task: #<Bosh::Director::Models::Task @values={:id=>483, :state=>\"queued\", :timestamp=>2016-04-17 22:01:09 +0000, :description=>\"scan and fix\", :result=>nil, :output=>\"/var/vcap/store/director/tasks/483\", :checkpoint_time=>2016-04-17 22:01:09 +0000, :type=>\"cck_scan_and_fix\", :username=>\"director\"}>\r\nD, [2016-04-17 22:01:10 #10857] [task:483] DEBUG -- DirectorJobRunner: (0.000302s) SELECT NULL\r\nD, [2016-04-17 22:01:10 #10857] [task:483] DEBUG -- DirectorJobRunner: (0.000143s) BEGIN\r\nD, [2016-04-17 22:01:10 #10857] [task:483] DEBUG -- DirectorJobRunner: (0.000510s) UPDATE \"tasks\" SET \"state\" = 'processing', \"timestamp\" = '2016-04-17 22:01:10.552908+0000', \"description\" = 'scan and fix', \"result\" = NULL, \"output\" = '/var/vcap/store/director/tasks/483', \"checkpoint_time\" = '2016-04-17 22:01:10.554094+0000', \"type\" = 'cck_scan_and_fix', \"username\" = 'director' WHERE (\"id\" = 483)\r\nD, [2016-04-17 22:01:10 #10857] [task:483] DEBUG -- DirectorJobRunner: (0.002576s) COMMIT\r\nI, [2016-04-17 22:01:10 #10857] [task:483]  INFO -- DirectorJobRunner: Acquiring deployment lock on cf-88d0a479447294d3465e\r\nD, [2016-04-17 22:01:10 #10857] [task:483] DEBUG -- DirectorJobRunner: Acquiring lock: lock:deployment:cf-88d0a479447294d3465e\r\nD, [2016-04-17 22:01:10 #10857] [task:483] DEBUG -- DirectorJobRunner: Acquired lock: lock:deployment:cf-88d0a479447294d3465e\r\nD, [2016-04-17 22:01:10 #10857] [] DEBUG -- DirectorJobRunner: Renewing lock: lock:deployment:cf-88d0a479447294d3465e\r\nD, [2016-04-17 22:01:10 #10857] [task:483] DEBUG -- DirectorJobRunner: (0.000731s) SELECT NULL\r\nD, [2016-04-17 22:01:10 #10857] [task:483] DEBUG -- DirectorJobRunner: (0.000451s) SELECT NULL\r\nD, [2016-04-17 22:01:10 #10857] [task:483] DEBUG -- DirectorJobRunner: (0.003543s) SELECT * FROM \"deployments\" WHERE (\"name\" = 'cf-88d0a479447294d3465e') LIMIT 1\r\nD, [2016-04-17 22:01:10 #10857] [task:483] DEBUG -- DirectorJobRunner: (0.001602s) SELECT NULL\r\nD, [2016-04-17 22:01:10 #10857] [task:483] DEBUG -- DirectorJobRunner: (0.000230s) SELECT NULL\r\nD, [2016-04-17 22:01:10 #10857] [task:483] DEBUG -- DirectorJobRunner: (0.000474s) SELECT * FROM \"instances\" WHERE ((\"deployment_id\" = 1) AND (\"job\" = 'diego_cell-partition-2a76849bdc38728d413f') AND (\"index\" = 2)) LIMIT 1\r\nD, [2016-04-17 22:01:10 #10857] [] DEBUG -- DirectorJobRunner: Lock renewal thread exiting\r\nD, [2016-04-17 22:01:10 #10857] [task:483] DEBUG -- DirectorJobRunner: Deleting lock: lock:deployment:cf-88d0a479447294d3465e\r\nD, [2016-04-17 22:01:10 #10857] [task:483] DEBUG -- DirectorJobRunner: Deleted lock: lock:deployment:cf-88d0a479447294d3465e\r\nE, [2016-04-17 22:01:10 #10857] [task:483] ERROR -- DirectorJobRunner: undefined method `id' for nil:NilClass\r\n/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/bosh-director-1.3146.10.0/lib/bosh/director/problem_scanner/scanner.rb:27:in `block in reset'\r\n/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/bosh-director-1.3146.10.0/lib/bosh/director/problem_scanner/scanner.rb:22:in `each'\r\n/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/bosh-director-1.3146.10.0/lib/bosh/director/problem_scanner/scanner.rb:22:in `reset'\r\n/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/bosh-director-1.3146.10.0/lib/bosh/director/jobs/cloud_check/scan_and_fix.rb:33:in `block in perform'\r\n/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/bosh-director-1.3146.10.0/lib/bosh/director/lock_helper.rb:13:in `block in with_deployment_lock'\r\n/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/bosh-director-1.3146.10.0/lib/bosh/director/lock.rb:56:in `lock'\r\n/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/bosh-director-1.3146.10.0/lib/bosh/director/lock_helper.rb:13:in `with_deployment_lock'\r\n/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/bosh-director-1.3146.10.0/lib/bosh/director/jobs/cloud_check/scan_and_fix.rb:30:in `perform'\r\n/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/bosh-director-1.3146.10.0/lib/bosh/director/job_runner.rb:102:in `perform_job'\r\n/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/bosh-director-1.3146.10.0/lib/bosh/director/job_runner.rb:32:in `block in run'\r\n/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/bosh_common-1.3146.10.0/lib/common/thread_formatter.rb:49:in `with_thread_name'\r\n/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/bosh-director-1.3146.10.0/lib/bosh/director/job_runner.rb:32:in `run'\r\n/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/bosh-director-1.3146.10.0/lib/bosh/director/jobs/base_job.rb:10:in `perform'\r\n/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/resque-1.25.2/lib/resque/job.rb:227:in `perform'\r\n/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/resque-1.25.2/lib/resque/worker.rb:250:in `perform'\r\n/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/resque-1.25.2/lib/resque/worker.rb:189:in `block in work'\r\n/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/resque-1.25.2/lib/resque/worker.rb:166:in `loop'\r\n/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/resque-1.25.2/lib/resque/worker.rb:166:in `work'\r\n/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/bosh-director-1.3146.10.0/bin/bosh-director-worker:76:in `<top (required)>'\r\n/var/vcap/packages/director/bin/bosh-director-worker:16:in `load'\r\n/var/vcap/packages/director/bin/bosh-director-worker:16:in `<main>'\r\nD, [2016-04-17 22:01:10 #10857] [task:483] DEBUG -- DirectorJobRunner: (0.000204s) SELECT NULL\r\nD, [2016-04-17 22:01:10 #10857] [task:483] DEBUG -- DirectorJobRunner: (0.000134s) BEGIN\r\nD, [2016-04-17 22:01:10 #10857] [task:483] DEBUG -- DirectorJobRunner: (0.000544s) UPDATE \"tasks\" SET \"state\" = 'error', \"timestamp\" = '2016-04-17 22:01:10.579340+0000', \"description\" = 'scan and fix', \"result\" = 'undefined method `id'' for nil:NilClass', \"output\" = '/var/vcap/store/director/tasks/483', \"checkpoint_time\" = '2016-04-17 22:01:10.554094+0000', \"type\" = 'cck_scan_and_fix', \"username\" = 'director' WHERE (\"id\" = 483)\r\nD, [2016-04-17 22:01:10 #10857] [task:483] DEBUG -- DirectorJobRunner: (0.002158s) COMMIT\r\nI, [2016-04-17 22:01:10 #10857] []  INFO -- DirectorJobRunner: Task took 0.045048555 seconds to process.\r\n\r\nTask 483 error\r\n```\r\n\r\n### Relevant code snippet. \r\n\r\nBecause a VM got deleted due to #1223, instance was nil. There's no check for nil:\r\n\r\n\r\nlib/bosh/director/problem_scanner/scanner.rb: \r\n```\r\n      def reset(vms=nil)\r\n        if vms\r\n          vms.each do |job, index|\r\n            instance = @instance_manager.find_by_name(@deployment.name, job, index)\r\n\r\n            Models::DeploymentProblem.where(\r\n              deployment: @deployment,\r\n              resource_id: instance.vm.id,\r\n              state: 'open'\r\n            ).update(state: 'closed')\r\n\r\n          end\r\n        else\r\n          Models::DeploymentProblem.where(\r\n            state: 'open',\r\n            deployment: @deployment\r\n          ).update(state: 'closed')\r\n        end\r\n      end\r\n```\r\n\r\n### bosh tasks recent \r\nThis error is shown in the Result column. See task 483 and 498. \r\n```\r\nubuntu@ops-manager:~$ bosh tasks recent 40 --no-filter\r\nActing as user 'director' on 'p-bosh-f3b1fb3436882cdaa51b'\r\n\r\n+-----+-------+-------------------------+-----------+-------------------------------+--------------------------------------------------------------------------------+\r\n| #   | State | Timestamp               | User      | Description                   | Result                                                                         |\r\n+-----+-------+-------------------------+-----------+-------------------------------+--------------------------------------------------------------------------------+\r\n| 510 | done  | 2016-04-19 02:39:57 UTC | director  | scan cloud                    | scan complete                                                                  |\r\n| 509 | done  | 2016-04-19 02:39:39 UTC | director  | retrieve vm-stats             |                                                                                |\r\n| 508 | done  | 2016-04-19 02:39:31 UTC | director  | retrieve vm-stats             |                                                                                |\r\n| 507 | done  | 2016-04-19 02:39:24 UTC | director  | retrieve vm-stats             |                                                                                |\r\n| 506 | done  | 2016-04-19 02:38:56 UTC | director  | retrieve vm-stats             |                                                                                |\r\n| 505 | done  | 2016-04-19 02:38:48 UTC | director  | retrieve vm-stats             |                                                                                |\r\n| 504 | done  | 2016-04-19 02:11:18 UTC | director  | retrieve vm-stats             |                                                                                |\r\n| 503 | done  | 2016-04-19 02:11:10 UTC | director  | retrieve vm-stats             |                                                                                |\r\n| 502 | done  | 2016-04-18 07:00:02 UTC | scheduler | snapshot deployment           | snapshots of deployment 'p-redis-7610e87c76d5313640d8' created                 |\r\n| 501 | done  | 2016-04-18 07:00:02 UTC | scheduler | snapshot deployment           | snapshots of deployment 'p-spring-cloud-services-b6214d29c5c183e56831' created |\r\n| 500 | done  | 2016-04-18 07:00:02 UTC | scheduler | snapshot deployment           | snapshots of deployment 'p-rabbitmq-fe14dc176302b15a1999' created              |\r\n| 499 | done  | 2016-04-18 07:00:02 UTC | scheduler | snapshot deployment           | snapshots of deployment 'p-mysql-fe95de2f4dadf3d2142c' created                 |\r\n| 498 | error | 2016-04-18 07:00:02 UTC | scheduler | snapshot deployment           | undefined method `cid' for nil:NilClass                                        |\r\n| 497 | done  | 2016-04-18 07:00:02 UTC | scheduler | scheduled SnapshotDeployments | Enqueued snapshot tasks [498, 499, 500, 501, 502]                              |\r\n| 496 | done  | 2016-04-18 06:57:42 UTC | director  | retrieve vm-stats             |                                                                                |\r\n| 495 | done  | 2016-04-18 06:00:03 UTC | scheduler | scheduled SnapshotSelf        |                                                                                |\r\n| 494 | done  | 2016-04-18 05:25:59 UTC | director  | retrieve vm-stats             |                                                                                |\r\n| 493 | done  | 2016-04-18 05:25:54 UTC | director  | retrieve vm-stats             |                                                                                |\r\n| 492 | done  | 2016-04-18 05:25:49 UTC | director  | retrieve vm-stats             |                                                                                |\r\n| 491 | done  | 2016-04-18 05:25:39 UTC | director  | retrieve vm-stats             |                                                                                |\r\n| 490 | done  | 2016-04-18 05:25:34 UTC | director  | retrieve vm-stats             |                                                                                |\r\n| 489 | done  | 2016-04-18 05:24:44 UTC | director  | retrieve vm-stats             |                                                                                |\r\n| 488 | done  | 2016-04-18 05:24:34 UTC | director  | retrieve vm-stats             |                                                                                |\r\n| 487 | done  | 2016-04-18 05:24:24 UTC | director  | retrieve vm-stats             |                                                                                |\r\n| 486 | done  | 2016-04-18 05:24:14 UTC | director  | retrieve vm-stats             |                                                                                |\r\n| 485 | done  | 2016-04-18 05:24:09 UTC | director  | retrieve vm-stats             |                                                                                |\r\n| 484 | done  | 2016-04-18 05:08:43 UTC | director  | retrieve vm-stats             |                                                                                |\r\n| 483 | error | 2016-04-17 22:01:10 UTC | director  | scan and fix                  | undefined method `id' for nil:NilClass                                         |\r\n| 482 | done  | 2016-04-17 22:01:00 UTC | director  | scan and fix                  | scan and fix complete                                                          |\r\n```"},"comment":{"url":"https://api.github.com/repos/cloudfoundry/bosh/issues/comments/217808999","html_url":"https://github.com/cloudfoundry/bosh/issues/1224#issuecomment-217808999","issue_url":"https://api.github.com/repos/cloudfoundry/bosh/issues/1224","id":217808999,"user":{"login":"cppforlife","id":185847,"avatar_url":"https://avatars.githubusercontent.com/u/185847?v=3","gravatar_id":"","url":"https://api.github.com/users/cppforlife","html_url":"https://github.com/cppforlife","followers_url":"https://api.github.com/users/cppforlife/followers","following_url":"https://api.github.com/users/cppforlife/following{/other_user}","gists_url":"https://api.github.com/users/cppforlife/gists{/gist_id}","starred_url":"https://api.github.com/users/cppforlife/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/cppforlife/subscriptions","organizations_url":"https://api.github.com/users/cppforlife/orgs","repos_url":"https://api.github.com/users/cppforlife/repos","events_url":"https://api.github.com/users/cppforlife/events{/privacy}","received_events_url":"https://api.github.com/users/cppforlife/received_events","type":"User","site_admin":false},"created_at":"2016-05-09T08:46:53Z","updated_at":"2016-05-09T08:46:53Z","body":"i'll try to add something to bosh.io/docs."}}