Posted	Nick	Remark
#openstack-nova - 2018-06-18
20:37:06	mriedem	whew
20:37:16	anupn	mriedem: so I think scheduling should work now
20:37:20	mriedem	i hope so
20:37:28	anupn	mriedem: what commands, made this magic?
20:37:34	mriedem	discover_hosts --by-service
20:37:35	mriedem	presumably
20:37:52	anupn	mriedem: Ah, that's interesting, worth making a note
20:43:25	anupn	mriedem: Instance got scheduled like charm :)
20:43:40	anupn	thanks
20:44:26	mriedem	anupn: cool, yw
20:51:09	openstackgerrit	Matt Riedemann proposed openstack/nova master: Fix regression when listing build_requests with marker and ip filter https://review.openstack.org/576161
20:56:49	openstackgerrit	Eric Fried proposed openstack/nova master: Tighten up ReportClient use of generation https://review.openstack.org/556669
20:57:54	openstackgerrit	Matt Riedemann proposed openstack/nova master: Clarify placement DB schema migration https://review.openstack.org/576265
20:59:53	SpamapS	So.. question about placement service logs..
21:00:00	SpamapS	They're basically destroying our ELK stack
21:00:05	SpamapS	is there any value in logging all of that at INFO?
21:10:59	openstackgerrit	Eric Fried proposed openstack/nova-specs master: Spec: Handling Reshaped Provider Trees https://review.openstack.org/572583
21:13:16	openstackgerrit	Eric Fried proposed openstack/nova-specs master: Spec: Handling Reshaped Provider Trees https://review.openstack.org/572583
21:13:53	efried	SpamapS: You can bust the log level down if you like.
21:14:19	efried	SpamapS: What kind of logging are you seeing? I haven't looked at one lately.
21:16:20	openstackgerrit	Chris Dent proposed openstack/nova master: Isolate placement database config https://review.openstack.org/541435
21:16:34	openstackgerrit	Chris Dent proposed openstack/nova master: Ensure that os-traits sync is attempted only at start of process https://review.openstack.org/553857
21:19:26	openstackgerrit	Dan Smith proposed openstack/nova stable/queens: Add amd-ssbd and amd-no-ssb CPU flags https://review.openstack.org/576270
21:25:11	jroll	efried: random tempest-full run on INFO: http://logs.openstack.org/66/362766/109/gate/tempest-full/52a4e60/controller/logs/screen-placement-api.txt.gz?level=INFO
21:25:17	jroll	that is certainly a lot of logs
21:25:32	jroll	looks like it's logging each request at INFO
21:25:44	efried	jroll: Is that not what it should be doing?
21:25:56	efried	It's not logging payloads.
21:26:02	efried	That would be DEBUG-worthy.
21:26:04	jroll	I don't know, I don't make those decisions :P
21:26:18	zcorneli	dansmith: For that test fixup, looks like there's a number of similar issues in the objects/ dir, worth fixing them all?
21:26:33	jroll	efried: in my experience, apache/nginx/whatever does the request logging, and the service only logs whatever else is needed
21:26:55	jroll	but clearly someone decided at some point this should happen in placement at info ¯\_(ツ)_/¯
21:27:17	efried	cdent, jaypipes - what are your thoughts on making placement logging less noisy?
21:27:41	efried	jroll: I mean, you can always bust the log level down, right?
21:28:06	jroll	efried: I assume there are some important things logged at INFO
21:28:39	efried	jroll: You mean in general, or here?
21:28:48	jroll	both?
21:28:50	efried	cause here all I see is just the calls.
21:29:06	jroll	well that's the point, signal-to-noise ratio is low
21:30:12	jroll	to be clear, I don't (currently) have a problem, just got curious
21:30:38	efried	and what I'm saying is, if these lines about which operations are called and how long they took and how many bytes they generated are all considered "noise", you can switch to WARNING and you'll get not those, but you (seemingly) won't lose out on anything else.
21:30:51	efried	Ima go look see if there's anything else logged at INFO...
21:30:59	jroll	I just checked, heh
21:31:09	jroll	curl http://logs.openstack.org/66/362766/109/gate/tempest-full/52a4e60/controller/logs/screen-placement-api.txt.gz\?level\=INFO | grep -v nova.api.openstack.placement.requestlog | grep -v 'switches on core' | grep INFO
21:31:19	jroll	gives a single line
21:31:44	efried	Yeah, traits db sync and online migration are the only other two things in the code.
21:31:49	jroll	so you're right, there isn't really anything other than request logging at INFO
21:32:07	efried	(online _data_ migration, that is - nothing to do with migrating instances)
21:32:13	jroll	most openstack services log very useful things at INFO, so operators tend to run at INFO
21:32:21	SpamapS	"Info: Usually indicates successful service start/stop, versions and such non-error related data. This should include largely positive units of work that are accomplished (such as starting a compute, creating a user, deleting a volume, etc.)"
21:33:07	efried	useful is in the eye of the beholder, I suppose.
21:33:08	SpamapS	https://specs.openstack.org/openstack/openstack-specs/specs/log-guidelines.html
21:33:18	SpamapS	IMO those should be TRACE
21:33:19	efried	SpamapS: I don't really see this as violating that precept, personally.
21:33:36	SpamapS	They aren't really useful for realtime analysis.
21:33:45	efried	No, trace would include all the payloads, generated SQL statements and result sets, etc.
21:33:47	SpamapS	They're good for like, tracing through to find out when an aggregate changed to what or was requested as what.
21:34:08	SpamapS	but every single compute node is constantly hitting placement
21:34:39	efried	Put in the context of the other logs, the info level is useful for letting you figure out which calls happened when and what their result was.
21:35:19	efried	Keeping in mind that placement doesn't necessarily see a 4xx as a "failure" or whatever, so something that's an ERROR in n-cpu or n-cond or whatever might just be a vanilla request/response to placement.
21:35:28	efried	So we can't condition on status code.
21:35:55	efried	Turn it around: if we were to take these lines out of INFO level, the log would be basically empty.
21:36:17	SpamapS	Ya, at this point we're just going to dump them from our ELK cluster.
21:36:28	SpamapS	They represent ~70% of all logs flowing in.
21:36:49	efried	SpamapS: I'm going to say again, if you don't like these INFO messages, change the log level (for placement only) to WARNING.
21:37:10	SpamapS	Ya, just wondering why people would think these would be useful enough for INFO.
21:37:12	efried	SpamapS: Because I reckon you do want to know if something goes wrong. So you don't just want to blow away the logs.
21:37:45	SpamapS	Yeah thats what I meant by dump them.. we'll not send the INFO+placement through to elastic.
21:38:11	efried	SpamapS: For ffdc, being able to correlate an ERROR in the nova logs to the corresponding placement calls - that's useful. And INFO-worthy IMO.
21:38:47	efried	again because placement has no way to distinguish what's ERROR-worthy from the client's perspective.
21:39:22	efried	Also finding it a little hard to believe that the placement log is noisier than the combined compute logs. Keep in mind that there's only one placement service.
21:39:54	SpamapS	the computes don't spray as much on INFO
21:40:06	SpamapS	unless they're super busy with churn
21:40:43	SpamapS	meanwhile they're constantly hammering on placement
21:40:48	efried	yup
21:52:01	jaypipes	SpamapS, jroll: do you have specific advice on what to down-level from INFO?
22:07:02	Sundar	efried: Please ping me when you can
22:07:17	efried	Sundar: I'm here.
22:07:35	efried	Sundar: I skimmed your responses, but didn't dig deep yet.
22:08:02	efried	oh, right, the main issue is "cyborg discovers automatically etc."
22:08:09	efried	This is missing the point, I think.
22:08:40	efried	When we do `openstack accelerator create` we're not getting a specific device. We're creating an ethereal meta-thingy that basically just has an ID for now.
22:09:15	efried	It's not until after placement has done its thang that you can actually (with the help of the plugin) associate that with an actual (possibly-virtual) device.
22:10:02	Sundar	efried: Sure, I am saying that Cyborg discovers PCI functions and such, apart from devices per se. So, all the information needed for an attach are already there.
22:10:17	efried	Except it's not.
22:10:44	Sundar	Could you clarify? What is missing?
22:10:53	efried	The main purpose of `openstack accelerator create <config details>` is to give <config details> a handle so we don't have to sling a random dict around all the services.
22:11:16	efried	It's the same principle as the port in neutron. You do a `port create` and get a UUID, but it's not associated with anything *real* yet.
22:11:36	efried	It's only much later, once you've landed on a real host, that you actually get a port on a NIC with an IP or whatever.
22:11:42	efried	Same thing here.
22:11:44	Sundar	That can be done from Nova compute -> os-acc, as opposed t doing at the controller between n-sched/placement and Cyborg
22:12:28	Sundar	The analogy with Neutron is ok, but do we need to copy it exactly?
22:12:41	Sundar	We need to see what makes sense in this context, right?
22:12:52	efried	heh, yeah, we should copy it insofar as it makes sense, and no further.
22:13:28	Sundar	What goes wrong if we create an attach object when n-cpu calls os-acc?
22:13:48	efried	well, what's an "attach object"?
22:13:58	efried	But let me answer that anyway
22:14:13	jaypipes	efried: it's pretty much the same as a "volume attachment". it's an ephemeral connection_info thing.
22:14:20	efried	The problem is that n-cond needed to know things about that accelerator long before we ever get to n-cpu.

Earlier   Later