| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2017-03-01 | |||
| 11:34:22 | kevinbenton | johnthetubaguy: how is your metadata-fu? | |
| 11:35:04 | johnthetubaguy | kevinbenton: rusty, but whats up? | |
| 11:35:18 | kevinbenton | johnthetubaguy: debugging a failure i observed in the gate | |
| 11:35:25 | kevinbenton | johnthetubaguy: one of the cirros VMs is not getting an SSH key | |
| 11:35:45 | johnthetubaguy | oh, interesting, almost like its fetching metadata before the ssh key is present in the metadata service | |
| 11:36:00 | johnthetubaguy | was it using config drive or not? | |
| 11:36:14 | kevinbenton | johnthetubaguy: no config drive | |
| 11:36:18 | kevinbenton | johnthetubaguy: just metadata | |
| 11:36:27 | kevinbenton | johnthetubaguy: i traced the request all of the way to nova API | |
| 11:36:33 | kevinbenton | johnthetubaguy: but the debug logs there aren't very helpful | |
| 11:36:40 | johnthetubaguy | ah, cool, you got a link to those | |
| 11:36:49 | kevinbenton | johnthetubaguy: http://logs.openstack.org/27/436427/2/gate/gate-tempest-dsvm-neutron-linuxbridge-ubuntu-xenial/2f3e394/logs/screen-n-api.txt.gz | |
| 11:36:54 | johnthetubaguy | at least the request got there, that was my main question | |
| 11:37:02 | kevinbenton | johnthetubaguy: request-id in question is req-93182a9d-baa9-4cf5-8648-aa9c4a49500 | |
| 11:37:41 | kevinbenton | johnthetubaguy: whatever it is returning there is making cirros think there is nothing further so it doesn't continue on to query the openssh url for the actual keys | |
| 11:39:19 | kevinbenton | johnthetubaguy: a good request ID in the same tenant and behind the same router is req-ff83fad3-86cc-4097-aa6e-538c6889eae2 | |
| 11:39:42 | kevinbenton | johnthetubaguy: would digging up the corresponding instance IDs be helpful? | |
| 11:40:21 | johnthetubaguy | not sure that helps in the logs, I guess it would let you find the create instance requests etc, int he compute logs which would have a hint | |
| 11:40:33 | johnthetubaguy | kevinbenton: this is one of those cases where we just get ssh didn't work errors right? | |
| 11:40:49 | kevinbenton | johnthetubaguy: well in this case it's explicit authentication failures | |
| 11:40:59 | johnthetubaguy | ah, right, that makes sense | |
| 11:41:00 | kevinbenton | johnthetubaguy: 2017-02-28 11:48:29,144 12602 INFO [paramiko.transport] Authentication (publickey) failed. | |
| 11:43:37 | kevinbenton | good instance ID is 747e0481 | |
| 11:43:55 | johnthetubaguy | kevinbenton: maybe finding the server_id here will help, looks like the bad one was 31ca7a58-2a91-4893-bcb0-7c457023f6a1 | |
| 11:44:42 | kevinbenton | aye | |
| 11:44:47 | johnthetubaguy | kevinbenton: oh right, I see GET /2009-04-04/meta-data/public-keys/0/openssh-key | |
| 11:45:21 | kevinbenton | johnthetubaguy: so in the bad case whatever that first one is returning is telling it no keys | |
| 11:45:31 | johnthetubaguy | yeah, it seems it must be | |
| 11:46:16 | kevinbenton | is the preparation of the metadata asynchronous? | |
| 11:47:24 | johnthetubaguy | I think it should be all before the instance boots | |
| 11:47:28 | johnthetubaguy | but I am wondering that now too | |
| 11:51:22 | johnthetubaguy | kevinbenton: so the ssh key is in the compute logs | |
| 11:52:06 | johnthetubaguy | kevinbenton: 2017-02-28 11:47:44.387 5448 DEBUG nova.virt.libvirt.vif [req-b43e28a2-6040-4273-b21f-cfe8ac5f7fb6 tempest-TestGettingAddress-1009203826 tempest-TestGettingAddress-1009203826] vif_type=bridge instance= | |
| 11:52:32 | johnthetubaguy | includes uuid=31ca7a58-2a91-4893-bcb0-7c457023f6a1 | |
| 11:52:33 | johnthetubaguy | and | |
| 11:52:46 | johnthetubaguy | key_name='tempest-TestGettingAddress-1661300941' | |
| 11:52:55 | johnthetubaguy | it was a key_pair generated by nova, apparently | |
| 11:53:23 | johnthetubaguy | so I assume temptest is correctly remembering the new key | |
| 11:53:40 | johnthetubaguy | although clearly its not fetching it, so thats kinda irrelavant | |
| 11:54:51 | kevinbenton | johnthetubaguy: it seems we may be short on some relevant debug logs in the attempted key lookup in n-api | |
| 11:55:20 | johnthetubaguy | looks like the good one had key_name='tempest-TestGettingAddress-1661300941' | |
| 11:55:22 | johnthetubaguy | strange | |
| 11:55:37 | johnthetubaguy | kevinbenton: yeah, its probably worth adding that | |
| 11:55:52 | kevinbenton | johnthetubaguy: can you point me to that code and i'll push up a patch? | |
| 11:55:56 | sdague | kevinbenton: yeh, it's actually a seperate wsgi handler | |
| 11:56:20 | johnthetubaguy | kevinbenton: yeah, I think thats here: https://github.com/openstack/nova/blob/master/nova/api/metadata/base.py#L273 | |
| 11:56:39 | johnthetubaguy | sdague: seems like its handled in process in this gate job though | |
| 11:56:52 | sdague | johnthetubaguy: ... no exactly | |
| 11:56:57 | sdague | not exactly | |
| 11:57:00 | kevinbenton | ha! https://github.com/openstack/nova/blob/master/nova/api/metadata/base.py#L284 | |
| 11:57:16 | sdague | our n-api has the ability to run multiple worker pools | |
| 11:57:24 | johnthetubaguy | sdague: good point | |
| 11:57:27 | kevinbenton | sdague: will that present an issue with logging statements? | |
| 11:57:56 | sdague | kevinbenton: no, it's all going through a dedicated logger. It's kind of no different than other pools | |
| 11:58:03 | kevinbenton | akc | |
| 11:58:04 | kevinbenton | ack* | |
| 11:58:39 | kevinbenton | I think very few of our jobs use metadata so the poor linux bridge job is the canary in the coal mine | |
| 11:58:43 | sdague | honestly, it would probably be a sensible long term move to make this always stand on it's own and run on it's own | |
| 11:59:16 | sdague | but I take it that the growth of multiple apis servered from one system came from ec2 days | |
| 11:59:47 | asettle | johnthetubaguy: so, who should I be emailing for docs stuff for now? :) | |
| 12:00:18 | johnthetubaguy | asettle: unsure, mriedem_away is the best person to ask about that | |
| 12:00:29 | asettle | Yikes, haha, okay, we need to fix that | |
| 12:00:54 | johnthetubaguy | sdague: certainly worth doing when we shift to uwsgi or whatever it is | |
| 12:01:08 | sdague | there is a mode to run it dedicated today | |
| 12:01:17 | johnthetubaguy | ack | |
| 12:01:31 | sdague | I don't know if that would be less confusing if we defaulted that mode | |
| 12:01:58 | sdague | Also, while this code path never seems to be hit, the caching by remote IP address in here scares me | |
| 12:02:06 | sdague | given that is recycled | |
| 12:02:19 | sdague | https://github.com/openstack/nova/blob/37cd9a961b065a07352b49ee72394cb210d8838b/nova/api/metadata/handler.py#L56-L74 | |
| 12:03:09 | kevinbenton | sdague: ouch | |
| 12:03:24 | kevinbenton | sdague: oh, we shouldn't hit that though | |
| 12:03:40 | kevinbenton | sdague: we should be in this branch https://github.com/openstack/nova/blob/37cd9a961b065a07352b49ee72394cb210d8838b/nova/api/metadata/handler.py#L101-L105 | |
| 12:03:43 | sdague | right, like I said, i don't see any instances of it | |
| 12:03:54 | sdague | it just makes me nervous in looking at the code | |
| 12:05:57 | kevinbenton | this may be quite prevalent | |
| 12:05:58 | kevinbenton | http://logstash.openstack.org/#dashboard/file/logstash.json?query=message%3A%5C%22(Error%20reading%20SSH%20protocol%20banner).%20Number%20attempts%3A%2016%5C%22 | |
| 12:07:11 | johnthetubaguy | kevinbenton: what job is this? | |
| 12:07:23 | johnthetubaguy | oh wait, I can read | |
| 12:07:35 | kevinbenton | :) | |
| 12:08:23 | johnthetubaguy | kevinbenton: I was checking when the keypair is added into the DB, its really early now: https://github.com/openstack/nova/blob/master/nova/compute/api.py#L981 | |
| 12:08:39 | johnthetubaguy | s/now// | |
| 12:09:08 | johnthetubaguy | basically its in the instance from the first DB save | |
| 12:10:19 | openstackgerrit | Timofey Durakov proposed openstack/python-novaclient master: Deperecate cell_name cli arg for migration-list https://review.openstack.org/439141 | |
| 12:11:02 | johnthetubaguy | kevinbenton: I have to run to get some lunch, but hopefully there are some micro leads there | |
| 12:11:25 | johnthetubaguy | sdague: in case its useful, I wrote up my quota notes here: https://review.openstack.org/#/c/429678 | |
| 12:11:55 | johnthetubaguy | sdague: did a quick post PTG refresh, but its mostly just thoughts I put together before the PTG | |
| 12:13:41 | sdague | kevinbenton: if you are patching in logging, probably worth adding a dump of what InstanceMetadata looks like before it's returned, maybe we would find some missing bits in there | |
| 12:13:51 | openstackgerrit | Kevin Benton proposed openstack/nova master: Add some metadata logging to root cause ssh failure https://review.openstack.org/439560 | |
| 12:14:07 | kevinbenton | sdague: can you leave a comment on that of where i should do that? ^^ | |
| 12:14:15 | sdague | yeh, let me go look | |
| 12:15:46 | sdague | kevinbenton: so it's in the other file, let me send a git link | |
| 12:16:00 | sdague | https://github.com/openstack/nova/blob/37cd9a961b065a07352b49ee72394cb210d8838b/nova/api/metadata/handler.py#L306 | |
| 12:16:08 | sdague | I would put a log debug of that data structure before we return it | |
| 12:18:30 | kevinbenton | sdague: ack | |
| 12:18:46 | kevinbenton | sdague: i also filed an E-R query here https://review.openstack.org/439562 | |
| 12:19:18 | sdague | once that is posted I'll +2, we can get johnthetubaguy to +2 after his lunch, and at least hopefully see some of this in the future | |
| 12:20:16 | sdague | kevinbenton: we should wait for mriedem_away / mtreinish for that banner error issue, because I have this vague recolection of things like paramiko lying to us about the real issue on thing like that | |
| 12:20:26 | sdague | but maybe they remember the deal | |
| 12:20:39 | kevinbenton | sdague: ack | |
| 12:21:13 | openstackgerrit | Kevin Benton proposed openstack/nova master: Add some metadata logging to root cause ssh failure https://review.openstack.org/439560 | |