| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2017-10-03 | |||
| 17:31:37 | melwitt | yeah, I was trying to say I don't think instance action rows are ever saved, they're created/written once and that's it | |
| 17:31:48 | sdague | melwitt: how is end time set then? | |
| 17:32:08 | sdague | or, only if it's set all at once | |
| 17:32:25 | dansmith | we can update them actually | |
| 17:32:34 | dansmith | action_event_finish() | |
| 17:32:47 | dansmith | sets the finish time and calls action.update() | |
| 17:32:54 | melwitt | oh, weird | |
| 17:33:15 | dansmith | I'd bet we don't finish all the actions we start though.. like everything else:P | |
| 17:38:56 | mriedem | i'd have to read back through the specs, but we create the action record and then we just deal with the events | |
| 17:38:59 | mriedem | which are different records | |
| 17:39:15 | mriedem | so there is event_start and event_finish | |
| 17:40:35 | mriedem | and i don't see us ever updating the action record when the event is finished | |
| 17:41:31 | dansmith | mriedem: https://github.com/openstack/nova/blob/master/nova/db/sqlalchemy/api.py#L6224 | |
| 17:41:48 | dansmith | ohh, the action and event I'm getting confused I guess | |
| 17:42:07 | dansmith | we actually just return the action from the action_finish() thing | |
| 17:42:17 | dansmith | not sure why or how that makes sense | |
| 17:42:25 | dansmith | but I guess that means we're never updating the _action_ | |
| 17:42:40 | mriedem | correct | |
| 17:42:46 | dansmith | it doesn't matter though, because changes-since should key on the start_time I would think | |
| 17:43:25 | dansmith | or it could be on max(start_time, finish_time) in case we ever set finish_time | |
| 17:43:30 | dansmith | but not updated_at I wouldn't think | |
| 17:43:37 | melwitt | I think the question was, why isn't updated_at updated and I was saying because it's never updated | |
| 17:44:13 | cdent | tautology alert | |
| 17:44:19 | cdent | but: yes | |
| 17:44:24 | melwitt | haha yeah | |
| 17:44:26 | dansmith | melwitt: right, I get that, and it's because we're not updating it from action_finish | |
| 17:44:43 | dansmith | melwitt: I had found action_event_finish() when looking for action_finish() which _does_ | |
| 17:44:51 | melwitt | yeah | |
| 17:44:58 | dansmith | I dunno _why_ we're not updating it during the finish, but.. | |
| 17:45:22 | dansmith | regardless, I would expect changes-since on this kind of thing to use the inbuilt fields | |
| 17:45:22 | melwitt | well, because each action is just "instance create started" "instance create finished" and they're separate right? | |
| 17:45:27 | dansmith | not the default one | |
| 17:45:33 | melwitt | there's nothing to update about it, it's just there | |
| 17:45:48 | dansmith | melwitt: except we have a finish method that doesn't finish it, and a finish_time field we never set, apparently | |
| 17:45:57 | mriedem | dansmith: i don't think anything actually calls action_event_finish() | |
| 17:46:06 | mriedem | i remember talking to laski about that at one point | |
| 17:46:14 | melwitt | oh | |
| 17:46:15 | mriedem | and it was like, something something tasks...we never used it | |
| 17:46:22 | dansmith | fine, extend my argument to why we have those in addition to why they do nothing :) | |
| 17:46:35 | mriedem | the EventReporter context manager calls objects.InstanceActionEvent.event_finish_with_failure | |
| 17:46:38 | dansmith | it's beside the point though, IMHO | |
| 17:47:27 | melwitt | I think I don't know what instance action events are. I'm just thinking of the "instance actions" which are a basic log of things that have happened to the instance | |
| 17:47:56 | mriedem | the events are tied to the action | |
| 17:48:06 | dansmith | right, an action is a high level thing, | |
| 17:48:07 | mriedem | see the EventReporter class | |
| 17:48:09 | dansmith | events are small steps | |
| 17:48:21 | mriedem | ever notice the @wrap_instance_event decorator on the compute manager methods? | |
| 17:48:33 | mriedem | that creates the event start on entry, and event finish on exit | |
| 17:48:55 | mriedem | the action record is created in the API before casting to compute where the real business happens, and that real bidness is recorded with events | |
| 17:48:57 | mriedem | on the action | |
| 17:50:06 | melwitt | bidness | |
| 17:51:04 | melwitt | okay, so I guess someone forgot to ever finish_time instance actions after creating the data model | |
| 17:51:28 | mriedem | jesus i thought this was merged in pike https://review.openstack.org/#/c/480746/ | |
| 17:51:44 | mriedem | so ^ gives an example of how a user can use these things for polling when an operation is complete | |
| 17:52:24 | melwitt | that's leet | |
| 17:53:48 | mriedem | leet? | |
| 17:55:06 | mriedem | also, note that if we ever rename methods in the compute manager which have the @wrap_instance_event decorator, we break that api | |
| 17:55:14 | dansmith | which we have, I think | |
| 17:55:17 | melwitt | like elite use of that API | |
| 17:55:19 | dansmith | hasn't gibi complained? | |
| 17:55:26 | mriedem | don't remember | |
| 17:55:41 | dansmith | I think when we moved things from compute to conductor there was a thing about that | |
| 17:56:03 | dansmith | I don't recall if there was an override to fix it or just "meh, this is an internal api" | |
| 17:56:05 | mriedem | for events or notifications? | |
| 17:56:22 | dansmith | oh yeah I guess I'm thinking of notifications | |
| 17:56:30 | dansmith | but similar deal | |
| 18:01:45 | mriedem | heh coincidentally https://bugs.launchpad.net/nova/+bug/1719561 | |
| 18:01:46 | openstack | Launchpad bug 1719561 in OpenStack Compute (nova) "Instance action's updated_at doesn't updated when action created or action event updated." [Undecided,In progress] - Assigned to Yikun Jiang (yikunkero) | |
| 18:01:56 | mriedem | i guess they found this out on their own... | |
| 18:06:00 | mriedem | huh we have no indexes on the events table | |
| 18:10:36 | mriedem | might be time to fire up the ol' create 1000 instances and list some things out of the api machine | |
| 18:11:32 | cdent | mriedem: one of the last times you did that there were 409s coming out of placement, did that ever get narrowed down, or did the rest of the world come rushing in and flush that for a while? | |
| 18:12:30 | mriedem | i've got a patch | |
| 18:12:41 | mriedem | but zuul has been zuuling it up | |
| 18:12:58 | mriedem | https://review.openstack.org/#/c/507918/ | |
| 18:13:54 | cdent | that’s the recreate patch, right, not the “here’s my theory” patch? | |
| 18:14:38 | mriedem | it's a recreate yeah | |
| 18:14:44 | mriedem | to see if we can find out from the logs where the 409 comes from | |
| 18:14:49 | mriedem | what triggers it i mean | |
| 18:15:05 | cdent | ✔ | |
| 18:15:19 | cdent | cool, I just wanted to be sure I hadn’t missed a revelation | |
| 18:18:53 | mriedem | cdent: if you scroll down to the bottom http://logs.openstack.org/18/507918/4/check/legacy-tempest-dsvm-neutron-full/8f969e2/logs/devstacklog.txt.gz you'll see what's going on | |
| 18:19:03 | mriedem | my check is failing, because i've apparently failed at bash | |
| 18:19:56 | mriedem | sdague: maybe you know how to bashtastify this ^ https://review.openstack.org/#/c/507918/5/stack.sh | |
| 18:20:09 | cdent | bash failing is an easy thing to do | |
| 18:21:56 | sdague | mriedem: I can look after, I have a call think shortly | |
| 18:22:19 | mriedem | it could just be we didn't actually fail, or i timed out too early | |
| 18:24:37 | mriedem | this is where it starts in the scheduler http://logs.openstack.org/18/507918/4/check/legacy-tempest-dsvm-neutron-full/8f969e2/logs/screen-n-sch.txt.gz#_Sep_28_20_12_08_486249 | |
| 18:24:51 | mriedem | look at all of those beautiful uuids | |
| 18:25:55 | mriedem | i seem to have also totally f'ed up the logging of the request id | |
| 18:26:06 | mriedem | because the req-47868c4f-61d3-4c32-9ece-94fb6ad35404 used for the instance create it also being logged for running periodic tasks... | |
| 18:27:30 | mriedem | cdent: heh, yeah, i think it actually scheduled the 500 instances | |
| 18:27:44 | cdent | blargh | |
| 18:28:05 | mriedem | yup | |
| 18:28:09 | cdent | you want it to break, no break. want it to work, break. | |
| 18:28:10 | mriedem | "Starting instance..." shows up 500 times in n-cpu | |
| 18:28:20 | mriedem | well, i could bump it to 1000 instances | |
| 18:28:41 | dansmith | lol | |
| 18:30:43 | mriedem | ok bombs away with 1000 | |
| 18:32:56 | mriedem | so there is no unique constraint on instance_actions.request_id, | |