receiverd ACKs messages if it was interrupted

It finally got deployed but after 35-40 minutes (just for 5 minutes which I was filing this bug +)

During Astute logs message about correct status for both controllers send in time.

2014-10-20T22:35:52 debug: [432] Data received by DeploymentProxyReporter to report it up: {"nodes"=>[{"uid"=>"78", "status"=>"ready", "role"=>"controller"}, {"uid"=>"85", "progress"=>56, "status"=>"deploying", "role"=>"controller"}]}
2014-10-20T22:36:00 debug: [432] Data received by DeploymentProxyReporter to report it up: {"nodes"=>[{"uid"=>"85", "status"=>"ready", "role"=>"controller"}]}

Nailgun got this messages also in time:

2014-10-20 22:35:52.269 INFO [7f34f7f14700] (receiver) RPC method deploy_resp received: {"task_uuid": "24d4f50b-9775-42ca-a436-e0cacfa1e107", "nodes": [{"status": "ready", "progress": 100, "role": "controller", "uid": "78"}]}
2014-10-20 22:36:16.692 INFO [7f34f7f14700] (receiver) RPC method deploy_resp received: {"task_uuid": "24d4f50b-9775-42ca-a436-e0cacfa1e107", "nodes": [{"status": "ready", "progress": 100, "role": "controller", "uid": "85"}]}

Looks like UI problem.

If/when this happens next time, please also attach output of /api/tasks . It is impossible to determine from diagnostic snapshot what is the root cause. But according to comment #2, most likely it is not an UI issue, as deployment finished successfully.

Python guys, please analyze diagnostic snapshot. If the bug is in nailgun, you'll find a reason there

Happens again on 50 nodes deployment. All nodes are in Ready state.

This time it took about 6 minutes to realize that cluster was deployed.

After analyzing the code and the snapshot I found that it's definitely not a problem with the UI. Something kills the RPC receiver before it can store the update from the node.

Right now it's clear that it's supervisord that is killing Nailgun's RPC receiver (receiverd). It does not log any particular reason for doing that.

I can confirm that receiverd (and other nailgun processes) are getting periodically killed, but there are definitely no docker requests triggering this behavior. We may need to find out some way to audit processes to see who or what is killing these.

On my local env I don't have any such mysterious SIGINTs, which makes it hard to reproduce.

Does it require a different team's attention?

We can play with acknowledge logic for rabbitmq, to prevent any acks before message will be saved to database,
but we need a plan/ideas how to prevent this from happening.

Matthew, do we have any instrument to monitor such behaviour in prod?

Fix proposed to branch: master
Review: https://review.openstack.org/132560

@Dima: This looks like fixing symptoms but the problem itself. As the logs show supervisord kills different services several times during that period of time. No one really can tell what kind of bugs can it actually cause.

There is the service, which is randomly killing other processes whenever it wants. That is the problem which has to be fixed.

In my opinion it should be ok for service to be restarted, as long as restart doesnot lead to incosistent state in database and/or
lost messages.

I agree that problem with supervisord should be researched, but fixing acknowledge will increase reliability of receiver.

@Dima: It's definitely not ok when there is something that is randomly killing processes without us knowing why and how to control that.

Update on this bug: This of course happens if the nailgun container is restarted, but it happened a few times in the MOS Scale Lab that supervisord killed some of the processes in the nailgun container. It's hard to reproduce, so I am waiting for the issue to appear again.

It's going to take some time to reproduce this bug, unfortunately. I believe the fix provided for https://bugs.launchpad.net/fuel/+bug/1377105 will minimize the occurence of this bug, thuogh. I'm pushing for that to fix to get merged ASAP.

Reviewed: https://review.openstack.org/132560
Committed: https://git.openstack.org/cgit/stackforge/fuel-web/commit/?id=c439874d65e539c65e043578a3b40d218d11e9a1
Submitter: Jenkins
Branch: master

commit c439874d65e539c65e043578a3b40d218d11e9a1
Author: Dima Shulyak <email address hidden>
Date: Mon Nov 3 15:23:44 2014 +0200

    Explicitly requeue rabbitmq message in case process interupted

    In case if process is interrupted excplit requeue will be
    requested

    Dont think that we should consider dead-letter exchanges
    at this point, becauce messaging traffic is low, and only
    thing that we need is reliably process message after
    receiverd restarted

    DocImpact
    Change-Id: If530049b6e519ceb03de0cfd82c3449cdb616f50
    Related-Bug: 1383511

Folks,
what is the latest update on the bug? Patch merged has "related" in its commit message...

Mike, that patch only fixes one of all possible consequences of the wrong receiverd's behaviour. That particular consequence is described by this bug so maybe we can close it and open a new one, which describes receiverd's misbehaviour. What do you think?

The other option is to update title, tags and maybe change priority.

Roman, I agree with you. Let's close this ticket and open other receiverd's related

@Vladimir, there nothing can be fixed in astute, regarding problem described in the bug

@Mike, it was Related-Bug because it only prevents nailgun-astute interaction from failing in case supervisord sends uncontrollable
SIGINT

So I made a conversation with Lukasz and we decided to close this bug changing the original title to the actual reason of wrong progress on the last controller. The bug which is describing wrong superwisord's behaviour could be found here: https://bugs.launchpad.net/fuel/+bug/1395753