New tasks are queuing but not being run

[drnic]

I'm using latest bosh-lite with pre-built virtualbox. I've vagrant destroy; vagrant up and I've deleted tmp and .vagrant; and I've tried upgrading to vagrant 1.4; but each time my bosh-lite isn't doing the work I need it to do; rather it just queues things.

✗ bosh upload stemcell latest-bosh-stemcell-warden.tgz

Verifying stemcell...
File exists and readable                                     OK
Using cached manifest...
Stemcell properties                                          OK

Stemcell info
-------------
Name:    bosh-stemcell
Version: 993

Checking if stemcell already exists...
No

Uploading stemcell...

latest-bosh-s: 100% |oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo| 170.4MB  37.9MB/s Time: 00:00:04

Director task 1

Update stemcell
  extracting stemcell archive (00:00:01)                                                            
  verifying stemcell manifest (00:00:00)                                                            
  checking if this stemcell already exists (00:00:00)                                               
  uploading stemcell bosh-stemcell/993 to the cloud (00:00:07)                                      
  save stemcell bosh-stemcell/993 (stemcell-ed9d039c-e808-4a07-bbe1-5d5c86cfa61a) (00:00:00)        
Not done                5/5 00:00:08                                                                

Task 1 queued

[drnic]

Later, the job above did get done.

bosh stemcells

+---------------+---------+-----------------------------------------------+
| Name          | Version | CID                                           |
+---------------+---------+-----------------------------------------------+
| bosh-stemcell | 993     | stemcell-20e22694-0099-46fa-96eb-28f667fb652a |
+---------------+---------+-----------------------------------------------+

I didn't notice this issue until I did a deploy which also quickly skipped ahead to queuing work. Reproducing now.

[drnic]

When I deploy, it quickly displays the following, noting "Task 4 queued", and quits.

✗ bosh -n deploy                           
Getting deployment properties from director...
Unable to get properties list from director, trying without it...
Compiling deployment manifest...

Director task 4

Preparing deployment
  binding deployment (00:00:00)                                                                     
  binding releases (00:00:00)                                                                       
  binding existing deployment (00:00:00)                                                            
  binding resource pools (00:00:00)                                                                 
  binding stemcells (00:00:00)                                                                      
  binding templates (00:00:00)                                                                      
  binding properties (00:00:00)                                                                     
  binding unallocated VMs (00:00:00)                                                                
  binding instance networks (00:00:00)                                                              
Done                    9/9 00:00:00                                                                

Preparing package compilation

Compiling packages
  loggregator_trafficcontroller/4 (00:00:08)                                                        
  dea_logging_agent/13 (00:00:08)                                                                   
  loggregator/13 (00:00:08)                                                                         
  mysqlclient/4 (00:00:05)                                                                          
  libpq/6 (00:02:27)                                                                                
  sqlite/4 (00:02:37)                                                                               
  debian_nfs_server/4 (00:00:01)                                                                    
  postgres/5 (00:00:23)                                                                             
  common/6 (00:00:01)                                                                               
  golang/4 (00:01:01)                                                                               
  nginx/10 (00:04:03)                                                                               
  libyaml/2 (00:01:12)                                                                              
  gorouter/18 (00:00:56)                                                                            
  narc/9 (00:00:41)                                                                                 
  gnatsd/1 (00:00:37)                                                                               
  rootfs_lucid64/2 (00:05:29)                                                                       
  git/2 (00:06:08)                                                                                  
  hm9000/5 (00:00:26)                                                                               
  buildpack_cache/6 (00:07:04)                                                                      
  ruby/10 (00:06:35)                                                                                
  warden/35 (00:01:24)                                                                              
  health_manager_next/24 (00:01:57)                                                                 
  nats/10 (00:01:05)                                                                                
  syslog_aggregator/8 (00:00:04)                                                                    
  login/29 (00:03:07)                                                                               
  uaa/40 (00:03:14)                                                                                 
  collector/19 (00:02:02)                                                                           
  dea_next/33 (00:03:38)                                                                            
  haproxy/1 (00:01:45)                                                                              
  cloud_controller_ng/30 (00:06:05)                                                                 
Done                    30/30 00:17:24                                                              

Preparing DNS
  binding DNS (00:00:00)                                                                            
Done                    1/1 00:00:00                                                                

Creating bound missing VMs
  medium_z1/0 (00:00:06)                                                                            
  router_z1/0 (00:00:06)                                                                            
  large_z1/0 (00:00:07)                                                                             
  large_z1/1 (00:00:07)                                                                             
  small_z1/0 (00:00:07)                                                                             
  runner_z1/0 (00:00:07)                                                                            
  medium_z1/1 (00:00:08)                                                                            
  medium_z1/2 (00:00:08)                                                                            
  router_z1/1 (00:00:08)                                                                            
  large_z1/2 (00:00:08)                                                                             
  large_z1/3 (00:00:08)                                                                             
Done                    11/11 00:00:08                                                              

Binding instance VMs
  ha_proxy_z1/0 (00:00:01)                                                                          
  login_z1/0 (00:00:01)                                                                             
  api_z1/0 (00:00:01)                                                                               
  postgres_z1/0 (00:00:01)                                                                          
  nats_z1/0 (00:00:01)                                                                              
  uaa_z1/0 (00:00:01)                                                                               
  loggregator_z1/0 (00:00:01)                                                                       
  router_z1/0 (00:00:01)                                                                            
  loggregator_trafficcontroller_z1/0 (00:00:01)                                                     
  runner_z1/0 (00:00:01)                                                                            
  hm9000_z1/0 (00:00:01)                                                                            
Done                    11/11 00:00:01                                                              

Preparing configuration
  binding configuration (00:00:01)                                                                  
Done                    1/1 00:00:01                                                                

Updating job ha_proxy_z1
  ha_proxy_z1/0 (00:00:29)                                                                          
Done                    1/1 00:00:29                                                                

Updating job nats_z1
  nats_z1/0 (00:00:30)                                                                              
Done                    1/1 00:00:30                                                                

Updating job postgres_z1
  postgres_z1/0 (00:00:32)                                                                          
Done                    1/1 00:00:32                                                                

Updating job uaa_z1
  uaa_z1/0 (00:00:35)                                                                               
Done                    1/1 00:00:35                                                                

Updating job login_z1
  login_z1/0 (00:00:39)                                                                             
Done                    1/1 00:00:39                                                                

Updating job api_z1
  api_z1/0 (00:00:38)                                                                               
Done                    1/1 00:00:38                                                                

Updating job hm9000_z1
  hm9000_z1/0 (00:00:34)                                                                            
Done                    1/1 00:00:34                                                                

Updating job runner_z1
  runner_z1/0 (00:01:36)                                                                            
Done                    1/1 00:01:36                                                                

Updating job loggregator_z1
  loggregator_z1/0 (00:00:29)                                                                       
Done                    1/1 00:00:29                                                                

Updating job loggregator_trafficcontroller_z1
  loggregator_trafficcontroller_z1/0 (00:00:29)                                                     
Done                    1/1 00:00:29                                                                

Updating job router_z1
  router_z1/0 (00:00:33)                                                                            
Not done                1/1 00:00:33                                                                

Task 4 queued

[drnic]

But there shouldn't be any compiled packages. I deleted the tmp folder in bosh-lite.

[drnic]

This whole output has been cached from somewhere. Any ideas on what's going on?

[drnic]

✗ bosh -v
BOSH 1.5.0.pre.1211

[drnic]

I can see the progress of the compile part of the deployment by looking in the host's package cache:

✗ ls -alt tmp/compiled_package_cache/
total 2458296
drwxr-xr-x  30 drnic  staff       1020 Dec  9 18:53 .
-rw-r--r--   1 drnic  staff   22533913 Dec  9 18:53 dea_next-ff72e078ecb2026f840f25e115ede6d67b05b2e5
-rw-r--r--   1 drnic  staff   13572464 Dec  9 18:53 collector-417e30251da990ecc76848f6c5642186f762d728
-rw-r--r--   1 drnic  staff   61843071 Dec  9 18:53 login-4afd818a1b269e87d4579c0ae48bf29f6126d8d0
-rw-r--r--   1 drnic  staff   99171208 Dec  9 18:53 uaa-5419f9a902efd2ee75f3ee449276e296d34cf40b
-rw-r--r--   1 drnic  staff       1620 Dec  9 18:53 syslog_aggregator-484cbe422333dbd685abf3d3deaebb4fd5fd930b
-rw-r--r--   1 drnic  staff    5334559 Dec  9 18:53 nats-ce3579c314e13dedb304f8db1e4cf49d2d858693
-rw-r--r--   1 drnic  staff   19455189 Dec  9 18:53 health_manager_next-9daa9fd51ff18d4b374aa48cefbd34e43d9761b2
-rw-r--r--   1 drnic  staff    8131771 Dec  9 18:52 warden-48121f51bf1043b38d2d0355466497de7a83fb18
-rw-r--r--   1 drnic  staff   12064363 Dec  9 18:51 ruby-759cb333bf552b35ff912d89697e1723cfc85a2b
-rw-r--r--   1 drnic  staff    4296112 Dec  9 18:50 hm9000-b589589890adae05adf16904af2a5306ce09e7cf
-rw-r--r--   1 drnic  staff  716106000 Dec  9 18:49 buildpack_cache-7512a96505731f0f7df9d92cf21344b3a11df62b
-rw-r--r--   1 drnic  staff   12952934 Dec  9 18:49 git-54cf5fe9b44fb7ec9760f1db80de8ae6b7adf1f7
-rw-r--r--   1 drnic  staff    2182747 Dec  9 18:49 gnatsd-87173ab7410c51bbe53af16d7c973dc2e7b1da64
-rw-r--r--   1 drnic  staff    4011262 Dec  9 18:48 gorouter-2b3da76be99f4f42127109b627aa35a9422772a1
-rw-r--r--   1 drnic  staff    3052229 Dec  9 18:48 narc-757494a9996e93e45aa452b12f3219b75a64110b
-rw-r--r--   1 drnic  staff  199535804 Dec  9 18:48 rootfs_lucid64-63bb882b7cc3f812c32b9a188cc9e1b4815a1ae6
-rw-r--r--   1 drnic  staff     285820 Dec  9 18:48 libyaml-bf7d743f1361917bd36f26c91d8fefc76d693dcd
-rw-r--r--   1 drnic  staff    3253850 Dec  9 18:48 nginx-2200d567617d80846581cacde9e92e849b98c577
-rw-r--r--   1 drnic  staff   42165787 Dec  9 18:48 golang-41f5ef363f2f7d68311e5599c61cbac0c4be9866
-rw-r--r--   1 drnic  staff       1265 Dec  9 18:48 common-87eafa5c5a58e25bd13e005ee4869815321f7f9c
-rw-r--r--   1 drnic  staff   16459121 Dec  9 18:48 postgres-4a0a5620d653a90b8b2c88a76c8788953f480f2e
-rw-r--r--   1 drnic  staff     169306 Dec  9 18:47 debian_nfs_server-a32739df8d30d9a2a59d0b2fd7e60014fac9b77f
-rw-r--r--   1 drnic  staff    1932565 Dec  9 18:47 sqlite-0064b4ed5d9cb23445a0716e916309e8327fa1b5
-rw-r--r--   1 drnic  staff     746393 Dec  9 18:47 libpq-b3cad43c7b3e566212e0d45f76c949a4a756fe79
-rw-r--r--   1 drnic  staff    4106252 Dec  9 18:46 mysqlclient-eb4294169026d126e317b7fa8f61c270cb2df4ee
-rw-r--r--   1 drnic  staff    1689716 Dec  9 18:46 dea_logging_agent-7744b3398f387f38bf33c39ca6672d70e9d46df1
-rw-r--r--   1 drnic  staff    1764373 Dec  9 18:46 loggregator-df967173251ef581d2567dad23e62bae940ad99d
-rw-r--r--   1 drnic  staff    1771127 Dec  9 18:46 loggregator_trafficcontroller-d0e81bba10d9d39fe552cfb743faf220226e15c8

[drnic]

oooh bosh task 4 --no-cache shows the results correctly

When did this caching business happen?

[mkocher]

We've recently ripped caching out of the CLI. If you upgrade to the latest prerelease bosh gem you'll see the right output. You can also work around this by deleteing ~/.bosh_cache, but upgrading is a better option.