Deployment locked by a vm. Error Unmarshalling monit status

[poblin-orange]

I consistently have a problem with bosh director loosing control on a deployment (see traces below)
A single vm on a depl under load prevents us from any operation (instances / vms / deploy).

Tested with bosh 262.3
Id expect an inconsistent vm not to block bosh director operation on a deployment.

poblin@prod:~$ bosh -d logsearch vms
Using environment '192.168.116.158' as client 'poblin'

Task 641331

09:44:02 | Error: Action Failed get_state: Getting processes status: Getting service status: Unmarshalling Monit status: read tcp 127.0.0.1:49154->127.0.0.1:2822: read: connection reset by peer

Started  Wed Aug  9 09:44:02 UTC 2017
Finished Wed Aug  9 09:44:02 UTC 2017
Duration 00:00:00

Task 641331 error

Listing deployment 'logsearch' vms infos:
  Expected task '641331' to succeed but state is 'error'

Exit code 1

Here the related bosh task --debug

running","uptime":{"secs":133400},"mem":{"kb":14840,"percent":0.1},"cpu":{"total":0}}],"resurrection_paused":false,"az":null,"id":"1b7e4b2a-b1ee-4b5e-8782-10fd40864aef","bootstrap":true,"ignore":false}                                                                                                                                       
') WHERE ("id" = 641403)                                                                                                                                                
D, [2017-08-09 10:05:14 #12270] [] DEBUG -- DirectorJobRunner: Thread is no longer needed, cleaning up                                                                  
D, [2017-08-09 10:05:14 #12270] [] DEBUG -- DirectorJobRunner: (0.000751s) COMMIT                                                                                       
D, [2017-08-09 10:05:14 #12270] [] DEBUG -- DirectorJobRunner: Thread is no longer needed, cleaning up                                                                  
D, [2017-08-09 10:05:15 #12270] [] DEBUG -- DirectorJobRunner: RECEIVED: director.1fd9f6a4-ecda-400f-84f0-3545b8b7de95.ebcbecf1-39ac-4ee2-a8b0-79517c991493 {"exception":{"message":"Action Failed get_state: Getting processes status: Getting service status: Unmarshalling Monit status: read tcp 127.0.0.1:55068-\u003e127.0.0.1:2822: read: connection reset by peer"}}                                                                                                                                            
E, [2017-08-09 10:05:15 #12270] [] ERROR -- DirectorJobRunner: Worker thread raised exception: Action Failed get_state: Getting processes status: Getting service status: Unmarshalling Monit status: read tcp 127.0.0.1:55068->127.0.0.1:2822: read: connection reset by peer - /var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-0.0.0/lib/bosh/director/agent_client.rb:280:in `handle_method'                                                                                                      
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-0.0.0/lib/bosh/director/agent_client.rb:335:in `handle_message_with_retry'                           
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-0.0.0/lib/bosh/director/agent_client.rb:387:in `start_task'                                          
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-0.0.0/lib/bosh/director/agent_client.rb:353:in `send_message'                                        
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-0.0.0/lib/bosh/director/agent_client.rb:62:in `get_state'                                            
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-0.0.0/lib/bosh/director/jobs/vm_state.rb:88:in `vm_details'                                          
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-0.0.0/lib/bosh/director/jobs/vm_state.rb:37:in `process_instance'                                    
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-0.0.0/lib/bosh/director/jobs/vm_state.rb:24:in `block (3 levels) in perform'                         
/var

bosh agent logs

2017-08-09_09:54:57.71038 [http-client] 2017/08/09 09:54:57 DEBUG - status function called
2017-08-09_09:54:57.71038 [http-client] 2017/08/09 09:54:57 DEBUG - Monit request: url='http://127.0.0.1:2822/_status2?format=xml' body=''
2017-08-09_09:54:57.71038 [attemptRetryStrategy] 2017/08/09 09:54:57 DEBUG - Making attempt #0 for *http.requestRetryable
2017-08-09_09:54:57.71039 [clientRetryable] 2017/08/09 09:54:57 DEBUG - [requestID=2954d296-4103-4add-5742-14cb0399b8aa] Requesting (attempt=1): Request{ Method: 'GET', URL: 'http://127.0.0.1:2822/_status2?format=xml' }
2017-08-09_09:54:58.71078 [attemptRetryStrategy] 2017/08/09 09:54:58 DEBUG - Making attempt #1 for *http.requestRetryable
2017-08-09_09:54:58.71080 [clientRetryable] 2017/08/09 09:54:58 DEBUG - [requestID=2954d296-4103-4add-5742-14cb0399b8aa] Requesting (attempt=2): Request{ Method: 'GET', URL: 'http://127.0.0.1:2822/_status2?format=xml' }
2017-08-09_09:54:58.71129 [Action Dispatcher] 2017/08/09 09:54:58 ERROR - Action Failed get_state: Getting processes status: Getting service status: Unmarshalling Monit status: read tcp 127.0.0.1:52808->127.0.0.1:2822: read: connection reset by peer
2017-08-09_09:54:58.71131 [MBus Handler] 2017/08/09 09:54:58 INFO - Responding
2017-08-09_09:54:58.71131 [MBus Handler] 2017/08/09 09:54:58 DEBUG - Payload
2017-08-09_09:54:58.71131 ********************
2017-08-09_09:54:58.71134 {"exception":{"message":"Action Failed get_state: Getting processes status: Getting service status: Unmarshalling Monit status: read tcp 127.0.0.1:52808-\u003e127.0.0.1:2822: read: connection reset by peer"}}
2017-08-09_09:54:58.71134 ********************

[voelzmo]

Saw the same some time ago. Director error handling isn't very good in these situations, so we definitely should fix this.

[voelzmo]

In case others stumble upon this:

• Finding the blocking VMs worked nicely with bosh ssh -d <DEPLOYMENT> -c 'http://vcap:random-password@127.0.0.1:2822/_status2?format=xml' -r --tty > /tmp/ssh-out
• root-cause was in our case that the VM was overloaded in terms of CPU. Killing the CPU-heavy process made monit responsive again

Still todo: Make the Director able to cope with that message and show the unresponsive VM to the user.

[voelzmo]

Fixed with c9cc3ff

[alext]

@voelzmo As far as I can tell, that fix is only included in the 262.x series. It doesn't appear to be included in 265.x. We're currently hitting this issue running v265.2.0.

I see that https://www.pivotaltracker.com/n/projects/1456570/stories/151434806 is marked as accepted. What needs to happen to get this fix included in 265?

[voelzmo]

Good catch, @alext! I think we might have missed this when branching off the 265.x branch. Version 266 should contain the fix again:

bosh/src/bosh-director/lib/bosh/director/deployment_plan/assembler.rb

Lines 120 to 125 in fa2d5cf

	rescue Bosh::Director::RpcTimeout, Bosh::Director::RpcRemoteException => e
	if fix
	state = {'job_state' => 'unresponsive'}
	else
	raise e, "#{existing_instance.name}: #{e.message}"
	end

@cppforlife can you backport c9cc3ff also to 265.x? It's also not in 264.x and 263.x, not sure what your long maintenance plans are for those.

[voelzmo]

Turns out that fix was not included in 262.x either: https://github.com/cloudfoundry/bosh/blob/262.x/src/bosh-director/lib/bosh/director/deployment_plan/assembler.rb#L90 It's just an incorrect github tag that's suggesting this commit is in a 262 release.

266 will be the first version containing this fix.

[jfmyers9]

Closing this issue as it has been fixed in v266+.