| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2019-09-23 | |||
| 18:39:42 | mriedem | obviously | |
| 18:39:49 | mriedem | i just left a comment with a bunch of log links, | |
| 18:40:17 | mriedem | but it looks like we start up ok, hit the cell1 db to pull compute nodes and instances, then 4 minutes later is the first scheduling attempt after the upgrade and at that point we're timing out | |
| 18:41:24 | sean-k-mooney | dansmith: we do eventurlly need to adress the rabbit mq heartbeat issue even if it is unrelated to this issue | |
| 18:41:32 | mriedem | it also looks like this goes back to 9/14 which is a few days before i originally thought | |
| 18:41:35 | dansmith | mriedem: that timeout is related to the scatter | |
| 18:42:04 | dansmith | mriedem: that's not new information, I'm just saying | |
| 18:42:29 | dansmith | mriedem: I was expecting to see a trace, but I think the scatter squashes that | |
| 18:43:15 | sean-k-mooney | i belive if any of the request raise an excpeiton we catch it and return the exception instead of raising it or something like that | |
| 18:43:20 | mriedem | it just logs a warning without a trace | |
| 18:43:31 | dansmith | mriedem: right | |
| 18:43:35 | sean-k-mooney | so i dont think we actuly log the traceback the way we normally would | |
| 18:43:52 | dansmith | sean-k-mooney: didn't I just say that? | |
| 18:44:34 | sean-k-mooney | yes i was halfway through typing it when you did so i finished it and hit enter | |
| 18:44:34 | mriedem | what i'm concerned about is if something in https://review.opendev.org/#/c/641907/ which merged and was released late is causing some side effect with the restart | |
| 18:44:48 | dansmith | mriedem: you said it was able to prime its cache on startup right? so this is it getting all nodes from all cells on the schedule run? | |
| 18:45:11 | mriedem | we're getting through this https://github.com/openstack/nova/blob/597b34cd87ac349c0f3702a872630f3c830b1483/nova/scheduler/host_manager.py#L413 | |
| 18:45:18 | mriedem | and then 4 minutes later the first scheduling request comes, | |
| 18:45:25 | mriedem | and it's going back to the cell to pull compute nodes by uuid | |
| 18:45:27 | mriedem | and times out | |
| 18:45:31 | dansmith | mriedem: I guess I thought we were stopping with systemd in that case, so no sighup involed yeah? | |
| 18:47:40 | sean-k-mooney | https://github.com/openstack/grenade/blob/master/projects/60_nova/shutdown.sh#L21 | |
| 18:47:57 | sean-k-mooney | i have not checked devstack but yes | |
| 18:48:16 | sean-k-mooney | i think tha tdoes systemctl stop devstack@n=* effectivly | |
| 18:48:45 | dansmith | right | |
| 18:49:03 | sean-k-mooney | ya it does https://github.com/openstack/devstack/blob/master/lib/nova#L1047-L1059 | |
| 18:49:49 | mriedem | Sep 22 00:37:32.126839 ubuntu-bionic-ovh-gra1-0011664420 systemd[1]: Stopped Devstack devstack@n-sch.service. | |
| 18:49:53 | mriedem | Sep 22 00:45:55.359862 ubuntu-bionic-ovh-gra1-0011664420 systemd[1]: Started Devstack devstack@n-sch.service. | |
| 18:50:42 | dansmith | mriedem: do we even stop/start mysql in grenade during the upgrade? | |
| 18:50:44 | mriedem | Sep 22 00:37:27.786606 ubuntu-bionic-ovh-gra1-0011664420 nova-scheduler[25563]: INFO oslo_service.service [None req-91e88f0d-9b5c-4cb7-a5e9-e7309f922832 None None] Caught SIGTERM, stopping children | |
| 18:50:46 | mriedem | yeah not a HUP | |
| 18:50:54 | mriedem | dansmith: pretty sure we don't | |
| 18:51:21 | dansmith | mriedem: yeah, so, pretty weird that it connects and works once and then times out later, because it's not like we restart mysql after that point or something | |
| 18:51:35 | dansmith | mriedem: so I wonder if we're actually doing something other than what we think | |
| 18:51:48 | dansmith | and since we don't log a trace there we don't know where it's actually timing out | |
| 18:52:46 | openstackgerrit | Dustin Cowles proposed openstack/nova-specs master: Spec: Provider config YAML file https://review.opendev.org/680471 | |
| 18:59:17 | openstackgerrit | Matt Riedemann proposed openstack/nova master: Log CellTimeout traceback in scatter_gather_cells https://review.opendev.org/684118 | |
| 18:59:18 | mriedem | dansmith: thinking like this? ^ | |
| 19:00:13 | dansmith | mriedem: yeah, I mean we kinda specifically decided not to explode there so we're tolerant of transient failures | |
| 19:00:26 | dansmith | I wonder if we should log debug with exc_info=True and warning without or something | |
| 19:00:31 | dansmith | but yeah, something | |
| 19:01:01 | mriedem | was thinking about passing down a kwarg to scatter_gather_cells to tell it what to do, but that's probably icky | |
| 19:01:12 | mriedem | trace_on_timeout = kwargs.pop('trace_on_timeout', False) | |
| 19:01:27 | dansmith | yeah, I don't like that | |
| 19:02:03 | dansmith | I love **kwargs behavior in python, but hate kwargs.pop('arg', None) abuses of it | |
| 19:02:09 | dansmith | which is why we can't have nice things in other languages :) | |
| 19:05:20 | dansmith | mriedem: so you just need to recheck that a few times to get a repro on it yeah? | |
| 19:06:26 | mriedem | maybe if we get lucky http://status.openstack.org/elastic-recheck/#1844929 | |
| 19:06:53 | mriedem | it mostly only shows up on certain node providers | |
| 19:07:00 | mriedem | so if i hit a rax node i likely won't see it | |
| 19:07:10 | mriedem | and only grenade jobs for some reason | |
| 19:07:15 | mriedem | something getting f'ed up in restarts | |
| 19:07:23 | sean-k-mooney | mriedem: which node providers? | |
| 19:07:31 | mriedem | fort nebula and ovh | |
| 19:07:54 | dansmith | mriedem: you should put that in the bug | |
| 19:07:56 | sean-k-mooney | we can target fort nebula using a specific node pool lable | |
| 19:08:00 | dansmith | so people can know and don't have to ask | |
| 19:08:04 | sean-k-mooney | im not sure about ovh | |
| 19:08:28 | mriedem | dansmith: from the bug, "It also appears to only show up on fortnebula and OVH nodes, primarily fortnebula." | |
| 19:08:34 | sean-k-mooney | but we coudl try and repoducice it via FN if you thing that was useful | |
| 19:08:38 | dansmith | mriedem: I know :) | |
| 19:08:44 | mriedem | i see what you did there | |
| 19:09:00 | dansmith | haha | |
| 19:11:20 | hemna | so I still can't seem to run tox -epy27 on anything less than stable/rocky | |
| 19:11:24 | hemna | queens and pike both fail | |
| 19:11:35 | hemna | http://paste.openstack.org/show/778953/ | |
| 19:11:56 | hemna | 6444 failures, all the same type of failure. sqlalchemy.exc.NoSuchTableError: migration_tmp | |
| 19:12:11 | dansmith | hemna: clean your local directory | |
| 19:12:16 | hemna | I did | |
| 19:12:21 | donnyd | Is this job CPU bound? | |
| 19:12:22 | hemna | nuked all pyc files and .tox | |
| 19:12:27 | dansmith | er, well, maybe not with that _tmp prefix | |
| 19:12:44 | dansmith | hemna: yeah, normally that comes from stale migration pycs but I think this is something else | |
| 19:14:23 | mriedem | 2019-09-22 00:47:29.331 | Instance 44d7efdc-c048-4dca-8b4b-3d518321eddd is in cell: cell1 (8acfb79b-2e40-4e1c-bc3d-d404dac6db90) | |
| 19:14:23 | mriedem | looking a bit further between the n-sch restart and the timeout, verify_instance works | |
| 19:14:52 | mriedem | donnyd: i think any job running nova and neutron is CPU bound :) | |
| 19:15:41 | donnyd | Yea that is not a strength of FN | |
| 19:16:51 | sean-k-mooney | mriedem: i assume you have seen the https://c0c3548b65f303ef6c0e-9dc5526a72bde5cc52e2c616e6a483fd.ssl.cf5.rackcdn.com/682061/5/check/grenade-heat/79209ac/logs/screen-n-cond.txt.gz i assume those are a result of the timeout | |
| 19:17:20 | mriedem | what, NoValidHost? yes that's the user visible failure | |
| 19:17:34 | sean-k-mooney | ya | |
| 19:17:51 | mriedem | the scheduler asks placement for providers for a build request, it gives back 1, we ask the cell db for the compute node for that one by uuid, timeout and then run an empty list of hosts through the filters | |
| 19:18:12 | sean-k-mooney | donnyd: well for jobs that actully enable nested vert/kvm FN is proably faster then the qemu based jobs | |
| 19:19:44 | openstackgerrit | Eric Fried proposed openstack/nova master: doc: attaching virtual persistent memory to guests https://review.opendev.org/680300 | |
| 19:19:45 | sean-k-mooney | mriedem: ya i notice the timestamp in the conductor log was after the timeout. | |
| 19:19:47 | donnyd | sean-k-mooney: for that case.. and anything with heavy IO should fly in FN - I am curious if the jobs that are failing on FN are related in any way to ipv6 | |
| 19:20:30 | dansmith | donnyd: could be, as we might be initiating a connection when this fails, | |
| 19:20:37 | dansmith | which might be network-related | |
| 19:20:50 | mriedem | i didn't think grenade jobs were doing anything with ipv6 | |
| 19:21:33 | sean-k-mooney | donnyd: where you thinking about the reduced mtu | |
| 19:21:36 | dansmith | well, maybe not, but just saying, if something network-y is the difference, that could explain flakiness | |
| 19:22:11 | donnyd | I was thinking more about the other one where the node loses contact when the ipv6 public side network is created | |
| 19:22:43 | donnyd | I recently tried to help that out by lowering my RA's so when it does it will pick it back up in time | |
| 19:23:00 | sean-k-mooney | the vms are dual stack vms right. they get a public ipv6 and private ipv4 address | |
| 19:23:11 | donnyd | correct sean-k-mooney | |
| 19:23:35 | sean-k-mooney | in that case ill check what ip we actully use for devstack | |
| 19:23:50 | donnyd | The mtu was lowered to 1450 | |
| 19:23:58 | donnyd | not sure what the other providers are set at | |
| 19:24:03 | sean-k-mooney | we are using the ipv4 addres | |
| 19:24:13 | sean-k-mooney | 192.168.48.93 in this case | |
| 19:24:42 | openstackgerrit | Merged openstack/nova master: Get pci_devices from _list_devices https://review.opendev.org/680674 | |