Node powering on but not deploying

When deploying machines, Juju does two things: first it allocates a machine and then it starts it. My guess is that the second step failed but starting the node (which is part of this second step) succeeded even though the transition itself (from Allocated to Deploying) failed. Can you have a look at the django-maas.log and pserv.log files to see if you can find any stacktrace there? Also, apache's log might tell you if the second API call issued by Juju (the one that should have transitioned the node from Allocated to Deploying) failed.

maas-django.log has a chunk of "cluster does not have matching boot image" lines:

ERROR 2014-09-30 01:59:16,102 maasserver Unable to identify boot image for (ubuntu/amd64/generic/trusty/local): cluster 'beretstack' does not have matching boot image.
ERROR 2014-09-30 02:03:53,515 maasserver Unable to identify boot image for (ubuntu/amd64/generic/trusty/local): cluster 'beretstack' does not have matching boot image.
ERROR 2014-09-30 02:04:02,681 maasserver Unable to identify boot image for (ubuntu/amd64/generic/trusty/local): cluster 'beretstack' does not have matching boot image.
ERROR 2014-09-30 02:04:14,495 maasserver Unable to identify boot image for (ubuntu/amd64/generic/trusty/local): cluster 'beretstack' does not have matching boot image.
ERROR 2014-09-30 02:04:25,387 maasserver Unable to identify boot image for (ubuntu/amd64/generic/trusty/local): cluster 'beretstack' does not have matching boot image.
ERROR 2014-09-30 02:10:44,458 maasserver Unable to identify boot image for (ubuntu/amd64/generic/trusty/local): cluster 'beretstack' does not have matching boot image.
ERROR 2014-09-30 02:13:02,114 twisted {}
ERROR 2014-09-30 02:13:38,465 maasserver Unable to identify boot image for (ubuntu/amd64/generic/trusty/poweroff): cluster 'beretstack' does not have matching boot image.

pserv.log has a scattering of

2014-09-30 02:13:38-0500 [RemoteOriginReadSession (UDP)] Got error: <tftp.datagram.ERRORDatagram object at 0x7f918903a210>
2014-09-30 02:13:42-0500 [RemoteOriginReadSession (UDP)] Got error: <tftp.datagram.ERRORDatagram object at 0x7f91860ad190>
2014-09-30 02:13:42-0500 [RemoteOriginReadSession (UDP)] Got error: <tftp.datagram.ERRORDatagram object at 0x7f91860ad190>
2014-09-30 02:13:47-0500 [RemoteOriginReadSession (UDP)] Got error: <tftp.datagram.ERRORDatagram object at 0x7f91861029d0>
2014-09-30 02:13:47-0500 [RemoteOriginReadSession (UDP)] Got error: <tftp.datagram.ERRORDatagram object at 0x7f91861029d0>
2014-09-30 02:13:57-0500 [RemoteOriginReadSession (UDP)] Got error: <tftp.datagram.ERRORDatagram object at 0x7f9186102510>

but otherwise nothing standing out

Juju got a 200 code when starting the node (apache access log)

10.1.3.4 - - [30/Sep/2014:02:13:12 -0500] "GET /MAAS/api/1.0/nodegroups/?op=list HTTP/1.1" 200 416 "-" "Go 1.1 package http"
10.1.3.4 - - [30/Sep/2014:02:13:12 -0500] "POST /MAAS/api/1.0/nodes/?op=acquire HTTP/1.1" 200 758 "-" "Go 1.1 package http"
10.1.3.4 - - [30/Sep/2014:02:13:12 -0500] "GET /MAAS/api/1.0/nodegroups/39929927-cfd0-43b0-9f3c-393dc602c340/boot-images/ HTTP/1.1" 200 813 "-" "Go 1.1 package http"
10.1.3.4 - - [30/Sep/2014:02:13:12 -0500] "POST /MAAS/api/1.0/nodes/node-27e59910-e295-11e3-944d-782bcb8e566b/?op=start HTTP/1.1" 200 780 "-" "Go 1.1 package http"

The content event log shows the node transitioned from 'Allocated' to 'Deploying'; but when the node PXE booted, it seems the node was 'Allocated'. The weird part is that the node event log doesn't show the transition from 'Deploying' back to 'Allocated'; these node transition events are tied to Django's internals and thus I see two possible causes for this:
- something outside Django (i.e. outside MAAS) changed the node's status (very unlikely)
- the transaction 'Allocated' → 'Deploying' got rolled back. This is strange because this is part of the "start node" request and we see it succeeded (return code 200 in apache's log). It's worth investigating how the recent work that introduced maybe_change_power_state can roll the DB transaction back and still power up the node.

Just based on comment #5, could it be that the node is PXE booting fast enough that the transaction in Django hasn't been committed yet?

> Just based on comment #5, could it be that the node is PXE booting fast enough that the transaction in Django hasn't been
> committed yet?

That's a possibility but I doubt it's what happened because:
- I haven't seen a node boot in less than a couple of seconds, ever
- the node was left 'Allocated' in the end

@Adam: can you please give us the content of the node event log with the timestamps (http://paste.ubuntu.com/8484906/)?

The "cluster does not have boot image" message may be originating from the poweroff action, which apparently was broken. See bug 1376028.

Raphael, Dean has noted that the logs for this are gone. We'll need to see if we can trip this ourselves, or see if Landscape causes it again.

I'm going to spend some time trying to trigger this.

I spent a couple of hours trying to trigger this, but to no avail. Adam, can you confirm that you still see this bug? If so, can you give me detailed steps to reproduce it?

I just hit this on a cluster of 33 machines. I acquired them all, then started them all, and about half remained in Allocated, although they were all powered on. This node event log shows on all of the Allocated nodes:

INFO 14 minutes ago PXE Request — power off
INFO 16 minutes ago Node powered on
INFO 16 minutes ago Powering node on
INFO 16 minutes ago Node changed status — From 'Allocated' to 'Deploying'
INFO 16 minutes ago Node changed status — From 'Ready' to 'Allocated' (to root)

Jason just reproduced this in his lab using 1.7.0~beta6+bzr3252-0ubuntu1~trusty1.

I also see the issue show up when trying to release a bunch of nodes at once. When I tried to release all 33, about half failed to change to Releasing state. When I tried to release the remaining ones, only about half again worked.

Exact steps to reproduce:

Using the web UI's bulk actions:

1) Acquire all nodes (I have 33 to test with, not sure how many are required).
2) Start all nodes

Some nodes will be in 'Allocated' still, while some are in 'Deploying'. All should be powered on.

Once all nodes are 'Deploying' or 'Deployed', you can reproduce the issue again with a bulk action
3) Release all nodes

Only some of them will go to Releasing, others will remain in Deploying or Deployed.

With that many nodes, my guess is that we're timing out before all the RPC commands have returned (see src/maasserver/models/node.py:133; we only wait 30s for *all* the deferreds to return… If it takes a couple of seconds for them to return then it won't take more than 15-20 nodes for us to start hitting the timeout.)

Quick update; Gavin, Jason and I have been working to debug this. Through crude bisecting, we've isolated the problem (at least with release()) to the call to power_off_nodes() in NodeManager.stop_nodes().

More precisely, if call_power_command() in power_nodes() (src/maasserver/clusterrpc/power.py) returns early rather than calling the Power(Off|On) RPC command, all the nodes will release just hunky dory. If the RPC call goes through, roughly half of the nodes will remain Allocated. We've also see errors in the log for PowerActionAlreadyInProgress for some nodes, though we don't know yet whether that's spurious or not.

Gavin and I are leaving to grab dinner now; we'll pick this up later.

It's interesting to note that Bulk Commissioning and Abort Commissioning work just fine, even though they also involve power on and off commands and state changes. The difference appears to be that in those actions, the transaction is explicitly saved after each node's state is changed, which is not done for deploying/releasing.

If you add an explicit transaction commit to the deploying and releasing actions, things work fine. I've posted a branch that does this:

 lp:~jason-hobbs/maas/fix-bulk-start-release

FWIW you can hit the issue with the 'nodes release' API also - the branch I posted doesn't cover that.

It's interesting that it seems to be about half of the nodes that don't get state transitioned properly. If I try to release 33 nodes at once, it's almost always either 13 or 14 left that didn't transition, which means about 20 succeeded. If I try to release 17 at once, 8 fail and 9 succeed.

I updated my branch to cover the Nodes release API also. It's interesting that the transaction.commit() doesn't fix things if it's at the end of the method, prior to the return. It only works if it's done on a per node basis.

The branch I just linked adds commit()s that will work for both the UI and API. That might be enough to fix this bug, but I think we need to fix bug 1330765 to be able to be sure about sane node states on bulk actions.

> errors in the log for PowerActionAlreadyInProgress

This is *really* concerning and I've raised this before: I suspect that the power monitor service is clashing with genuine requests.

On 16 October 2014 00:38, Julian Edwards <email address hidden> wrote:
>> errors in the log for PowerActionAlreadyInProgress
>
> This is *really* concerning and I've raised this before: I suspect that
> the power monitor service is clashing with genuine requests.

From an admittedly quick glance at the code I don't think that the
power monitor service uses anything that puts entries in the power
action "registry"; it's only when we're _changing_ power state that we
take a lock on power actions for a node. It's more likely (in this
case) that we PEBKAC'd — there were three of us futzing with the NEC
lab MAAS at the time.

On 10/16/2014 10:11 AM, Graham Binns wrote:
> On 16 October 2014 00:38, Julian Edwards <email address hidden> wrote:
>>> errors in the log for PowerActionAlreadyInProgress
>>
>> This is *really* concerning and I've raised this before: I suspect that
>> the power monitor service is clashing with genuine requests.
>
>>From an admittedly quick glance at the code I don't think that the
> power monitor service uses anything that puts entries in the power
> action "registry"; it's only when we're _changing_ power state that we
> take a lock on power actions for a node. It's more likely (in this
> case) that we PEBKAC'd — there were three of us futzing with the NEC
> lab MAAS at the time.

I think gmb is right on both count: a) PowerActionAlreadyInProgress can
only be raised when power states are being changed b) I know for a fact
I was messing around with the lab at the same time Jason and gmb where
experimenting.

On Thursday 16 Oct 2014 09:00:25 you wrote:
> On 10/16/2014 10:11 AM, Graham Binns wrote:
> > On 16 October 2014 00:38, Julian Edwards <email address hidden>
wrote:
> >>> errors in the log for PowerActionAlreadyInProgress
> >>
> >> This is *really* concerning and I've raised this before: I suspect that
> >> the power monitor service is clashing with genuine requests.
> >>
> >>From an admittedly quick glance at the code I don't think that the
> >>
> > power monitor service uses anything that puts entries in the power
> > action "registry"; it's only when we're _changing_ power state that we
> > take a lock on power actions for a node. It's more likely (in this
> > case) that we PEBKAC'd — there were three of us futzing with the NEC
> > lab MAAS at the time.
>
> I think gmb is right on both count: a) PowerActionAlreadyInProgress can
> only be raised when power states are being changed b) I know for a fact
> I was messing around with the lab at the same time Jason and gmb where
> experimenting.

Fair enough.

What about when the power query clashes with the state change *on the bmc*?