Earlier  
Later
New Search
Posted Nick Remark
#openstack-nova - 2017-10-03
17:30:03 dansmith updated_at is built into oslo.db
17:30:14 dansmith so if it's never set on those, it's because we never did a save, AFAIK
17:30:35 dansmith there are other things missing in that spec,
17:30:44 dansmith like it doesn't show them actually using the marker they say they're going to,
17:31:06 dansmith but I assume they really mean start_time, which is its own field
17:31:11 dansmith separate from the usual three default ones
17:31:31 dansmith there is a finish_time on that object too
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 melwitt well, because each action is just "instance create started" "instance create finished" and they're separate right?
17:45:22 dansmith regardless, I would expect changes-since on this kind of thing to use the inbuilt fields
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

Earlier   Later