yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1637390] [NEW] nova.consoleauth.manager often denies access to VNC: First login fails or token expires too fast

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Jens Offenbach <wolle5050@xxxxxx>
Date: Fri, 28 Oct 2016 05:32:31 -0000
Reply-to: Bug 1637390 <1637390@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
Public bug reported:

I am confronted with a really strange problem with nova-consoleauth. I
am running OpenStack Newton on Ubuntu Server 16.04.1. When I use VNC
from Horizon, I get frequently get the error "Failed to connect to
server (code: 1006)". There is only a single nova-consoleauth service
available.

There are two scenarios:
- The first login with a fresh token fails. The next one succeeds.
- The first logon succeeds, but the token expires really fast.

Scenario 1 (nova-consoleauth.log):
2016-10-28 06:50:55.845 9973 INFO nova.consoleauth.manager [req-f0f8fc1d-ae41-443d-9647-83287114bf1d 58963f571cad45b3b7b6272c73f4cb3b 638770a11625458299c2d205759d09df - - -] Received Token: 37d8bbfb-03b8-4368-b339-b3791e77a4b7, {'instance_uuid': u'f35b3673-e2ac-4bfa-878c-6700efd289d5', 'access_url': u'https://10.30.216.100:6080/vnc_auto.html?token=37d8bbfb-03b8-4368-b339-b3791e77a4b7', 'token': u'37d8bbfb-03b8-4368-b339-b3791e77a4b7', 'last_activity_at': 1477630255.842381, 'internal_access_path': None, 'console_type': u'novnc', 'host': u'10.30.200.113', 'port': u'5900'}
2016-10-28 06:50:56.313 9973 INFO nova.consoleauth.manager [req-1d623f93-5e05-462a-8058-4867bca71665 - - - - -] Checking Token: 37d8bbfb-03b8-4368-b339-b3791e77a4b7, False
2016-10-28 06:51:22.427 9973 INFO nova.consoleauth.manager [req-805a354e-c325-4f67-8a64-9e6b1a689f18 - - - - -] Checking Token: 37d8bbfb-03b8-4368-b339-b3791e77a4b7, False
2016-10-28 06:51:48.809 9973 INFO nova.consoleauth.manager [req-048a2bf7-ac53-4136-b28a-d3c5903ef226 58963f571cad45b3b7b6272c73f4cb3b 638770a11625458299c2d205759d09df - - -] Received Token: cdf07104-102c-44c6-ba90-56049702e3ae, {'instance_uuid': u'8c793085-1f79-458f-92a8-ee95add830da', 'access_url': u'https://10.30.216.100:6080/vnc_auto.html?token=cdf07104-102c-44c6-ba90-56049702e3ae', 'token': u'cdf07104-102c-44c6-ba90-56049702e3ae', 'last_activity_at': 1477630068.805975, 'internal_access_path': None, 'console_type': u'novnc', 'host': u'10.30.200.111', 'port': u'5900'}
2016-10-28 06:52:49.168 9973 INFO nova.consoleauth.manager [req-81b8c139-303f-4c6e-9b2d-0f7e0ea1467c - - - - -] Checking Token: cdf07104-102c-44c6-ba90-56049702e3ae, True
2016-10-28 06:53:02.168 9973 INFO nova.consoleauth.manager [req-81b8c139-303f-4c6e-9b2d-0f7e0ea1467c - - - - -] Checking Token: cdf07104-102c-44c6-ba90-56049702e3ae, True

Scenario 2 (nova-consoleauth.log):
2016-10-28 07:11:00.059 9973 INFO nova.consoleauth.manager [req-c3cfaf64-935f-4b2e-83f1-6bff35f4e923 ba6f9eddfd154b88b6a45d218fb5b310 638770a11625458299c2d205759d09df - - -] Received Token: bc3c697d-8740-4053-adf9-8133ce5f2296, {'instance_uuid': u'8c793085-1f79-458f-92a8-ee95add830da', 'access_url': u'https://10.30.216.100:6080/vnc_auto.html?token=bc3c697d-8740-4053-adf9-8133ce5f2296', 'token': u'bc3c697d-8740-4053-adf9-8133ce5f2296', 'last_activity_at': 1477631460.049053, 'internal_access_path': None, 'console_type': u'novnc', 'host': u'10.30.200.111', 'port': u'5900'}
2016-10-28 07:11:00.494 9973 INFO nova.consoleauth.manager [req-34d85dce-54e9-475d-9968-524bedffaa0b - - - - -] Checking Token: bc3c697d-8740-4053-adf9-8133ce5f2296, True
2016-10-28 07:11:07.479 9973 INFO nova.consoleauth.manager [req-c835b16c-4bb4-4d9d-83c8-e59c174052a6 - - - - -] Checking Token: bc3c697d-8740-4053-adf9-8133ce5f2296, True
2016-10-28 07:12:24.923 9973 INFO nova.consoleauth.manager [req-f1748791-e631-429d-b75e-7b865664a09b - - - - -] Checking Token: bc3c697d-8740-4053-adf9-8133ce5f2296, False

I successfully locked in at "07:11:00.059" with the token
"bc3c697d-8740-4053-adf9-8133ce5f229" and made some refreshes. At
"07:12:24.923" the token is suddenly invalid. This is really fast...
What is the reason.

This is my nova.conf on the controller:
[DEFAULT]
auth_strategy = keystone
debug = true
enabled_apis = osapi_compute,metadata
firewall_driver = nova.virt.firewall.NoopFirewallDriver
host = os-controller01
linuxnet_interface_driver = nova.network.linux_net.LinuxOVSInterfaceDriver
log_dir = /var/log/nova
memcached_servers = os-memcache:11211
metadata_listen = $my_ip
metadata_listen_port = 8775
my_ip = 10.30.200.101
osapi_compute_listen = $my_ip
osapi_compute_listen_port = 8774
state_path = /var/lib/nova
transport_url = rabbit://nova:XYZ@os-rabbit01:5672,nova:XYZ@os-rabbit02:5672/openstack
use_neutron = true

[cache]
backend = oslo_cache.memcache_pool
enabled = true
memcache_servers = os-memcache:11211

[cinder]
catalog_info = volumev2:cinderv2:internalURL
os_region_name = RegionOne

[database]
connection = mysql+pymysql://nova:XYZ@os-controller/nova
max_retries = -1

[api_database]
connection = mysql+pymysql://nova:XYZ@os-controller/nova_api
max_retries = -1

[glance]
api_servers = http://os-image:9292

[keystone_authtoken]
auth_type = password
auth_uri = http://os-identity:5000
auth_url = http://os-identity:35357
memcached_servers = os-memcache:11211
password = XYZ
project_domain_name = default
project_name = service
user_domain_name = default
username = nova

[neutron]
auth_type = password
auth_uri = http://os-identity:5000
auth_url = http://os-identity:35357
metadata_proxy_shared_secret = 2a9c2c3a435ad6fefd61
password = XYZ
project_domain_name = default
project_name = service
region_name = RegionOne
service_metadata_proxy = true
# NOTE: python-rfc3986 could not handle URI which has '-' characters.
#       Should be replaced as soon as possible by 'http://os-network:9696'.
#       https://bugs.launchpad.net/kolla/+bug/1629729
url = http://10.30.200.100:9696
user_domain_name = default
username = neutron

[oslo_concurrency]
lock_path = /var/lock/nova

[oslo_messaging_notifications]
driver = messagingv2

[oslo_messaging_rabbit]
amqp_durable_queues = true
rabbit_ha_queues = true
rabbit_retry_backoff = 2
rabbit_retry_interval = 1

[oslo_middleware]
enable_proxy_headers_parsing = true

[vnc]
enabled = true
novncproxy_host = 10.30.200.101
novncproxy_port = 6080
vncserver_listen = $my_ip
vncserver_proxyclient_address = $my_ip

All caches are configured. I looked at the code of the consoleauth
service. If I get everything right, the manager just looks into the
cache and checks if the token is present. If it is not, it denies access
to the console.

Has anybody an idea what causes the issue?

Thanks a lot!

** Affects: nova
     Importance: Undecided
         Status: New


** Tags: console nova-consoleauth

** Description changed:

  I am confronted with a really strange problem with nova-consoleauth. I
  am running OpenStack Newton on Ubuntu Server 16.04.1. When I use VNC
- from Horizonm, I get frequently get the error "Failed to connect to
+ from Horizon, I get frequently get the error "Failed to connect to
  server (code: 1006)". There is only a single nova-consoleauth service
  available.
  
  There are two scenarios:
  - The first login with a fresh token fails. The next one succeeds.
  - The first logon succeeds, but the token expires really fast.
  
  Scenario 1 (nova-consoleauth.log):
  2016-10-28 06:50:55.845 9973 INFO nova.consoleauth.manager [req-f0f8fc1d-ae41-443d-9647-83287114bf1d 58963f571cad45b3b7b6272c73f4cb3b 638770a11625458299c2d205759d09df - - -] Received Token: 37d8bbfb-03b8-4368-b339-b3791e77a4b7, {'instance_uuid': u'f35b3673-e2ac-4bfa-878c-6700efd289d5', 'access_url': u'https://10.30.216.100:6080/vnc_auto.html?token=37d8bbfb-03b8-4368-b339-b3791e77a4b7', 'token': u'37d8bbfb-03b8-4368-b339-b3791e77a4b7', 'last_activity_at': 1477630255.842381, 'internal_access_path': None, 'console_type': u'novnc', 'host': u'10.30.200.113', 'port': u'5900'}
  2016-10-28 06:50:56.313 9973 INFO nova.consoleauth.manager [req-1d623f93-5e05-462a-8058-4867bca71665 - - - - -] Checking Token: 37d8bbfb-03b8-4368-b339-b3791e77a4b7, False
  2016-10-28 06:51:22.427 9973 INFO nova.consoleauth.manager [req-805a354e-c325-4f67-8a64-9e6b1a689f18 - - - - -] Checking Token: 37d8bbfb-03b8-4368-b339-b3791e77a4b7, False
  2016-10-28 06:51:48.809 9973 INFO nova.consoleauth.manager [req-048a2bf7-ac53-4136-b28a-d3c5903ef226 58963f571cad45b3b7b6272c73f4cb3b 638770a11625458299c2d205759d09df - - -] Received Token: cdf07104-102c-44c6-ba90-56049702e3ae, {'instance_uuid': u'8c793085-1f79-458f-92a8-ee95add830da', 'access_url': u'https://10.30.216.100:6080/vnc_auto.html?token=cdf07104-102c-44c6-ba90-56049702e3ae', 'token': u'cdf07104-102c-44c6-ba90-56049702e3ae', 'last_activity_at': 1477630068.805975, 'internal_access_path': None, 'console_type': u'novnc', 'host': u'10.30.200.111', 'port': u'5900'}
  2016-10-28 06:52:49.168 9973 INFO nova.consoleauth.manager [req-81b8c139-303f-4c6e-9b2d-0f7e0ea1467c - - - - -] Checking Token: cdf07104-102c-44c6-ba90-56049702e3ae, True
  2016-10-28 06:53:02.168 9973 INFO nova.consoleauth.manager [req-81b8c139-303f-4c6e-9b2d-0f7e0ea1467c - - - - -] Checking Token: cdf07104-102c-44c6-ba90-56049702e3ae, True
  
  Scenario 2 (nova-consoleauth.log):
  2016-10-28 07:11:00.059 9973 INFO nova.consoleauth.manager [req-c3cfaf64-935f-4b2e-83f1-6bff35f4e923 ba6f9eddfd154b88b6a45d218fb5b310 638770a11625458299c2d205759d09df - - -] Received Token: bc3c697d-8740-4053-adf9-8133ce5f2296, {'instance_uuid': u'8c793085-1f79-458f-92a8-ee95add830da', 'access_url': u'https://10.30.216.100:6080/vnc_auto.html?token=bc3c697d-8740-4053-adf9-8133ce5f2296', 'token': u'bc3c697d-8740-4053-adf9-8133ce5f2296', 'last_activity_at': 1477631460.049053, 'internal_access_path': None, 'console_type': u'novnc', 'host': u'10.30.200.111', 'port': u'5900'}
  2016-10-28 07:11:00.494 9973 INFO nova.consoleauth.manager [req-34d85dce-54e9-475d-9968-524bedffaa0b - - - - -] Checking Token: bc3c697d-8740-4053-adf9-8133ce5f2296, True
  2016-10-28 07:11:07.479 9973 INFO nova.consoleauth.manager [req-c835b16c-4bb4-4d9d-83c8-e59c174052a6 - - - - -] Checking Token: bc3c697d-8740-4053-adf9-8133ce5f2296, True
  2016-10-28 07:12:24.923 9973 INFO nova.consoleauth.manager [req-f1748791-e631-429d-b75e-7b865664a09b - - - - -] Checking Token: bc3c697d-8740-4053-adf9-8133ce5f2296, False
  
  I successfully locked in at "07:11:00.059" with the token
  "bc3c697d-8740-4053-adf9-8133ce5f229" and made some refreshes. At
  "07:12:24.923" the token is suddenly invalid. This is really fast...
  What is the reason.
  
  This is my nova.conf on the controller:
  [DEFAULT]
  auth_strategy = keystone
  debug = true
  enabled_apis = osapi_compute,metadata
  firewall_driver = nova.virt.firewall.NoopFirewallDriver
  host = os-controller01
  linuxnet_interface_driver = nova.network.linux_net.LinuxOVSInterfaceDriver
  log_dir = /var/log/nova
  memcached_servers = os-memcache:11211
  metadata_listen = $my_ip
  metadata_listen_port = 8775
  my_ip = 10.30.200.101
  osapi_compute_listen = $my_ip
  osapi_compute_listen_port = 8774
  state_path = /var/lib/nova
  transport_url = rabbit://nova:XYZ@os-rabbit01:5672,nova:XYZ@os-rabbit02:5672/openstack
  use_neutron = true
  
  [cache]
  backend = oslo_cache.memcache_pool
  enabled = true
  memcache_servers = os-memcache:11211
  
  [cinder]
  catalog_info = volumev2:cinderv2:internalURL
  os_region_name = RegionOne
  
  [database]
  connection = mysql+pymysql://nova:XYZ@os-controller/nova
  max_retries = -1
  
  [api_database]
  connection = mysql+pymysql://nova:XYZ@os-controller/nova_api
  max_retries = -1
  
  [glance]
  api_servers = http://os-image:9292
  
  [keystone_authtoken]
  auth_type = password
  auth_uri = http://os-identity:5000
  auth_url = http://os-identity:35357
  memcached_servers = os-memcache:11211
  password = XYZ
  project_domain_name = default
  project_name = service
  user_domain_name = default
  username = nova
  
  [neutron]
  auth_type = password
  auth_uri = http://os-identity:5000
  auth_url = http://os-identity:35357
  metadata_proxy_shared_secret = 2a9c2c3a435ad6fefd61
  password = XYZ
  project_domain_name = default
  project_name = service
  region_name = RegionOne
  service_metadata_proxy = true
  # NOTE: python-rfc3986 could not handle URI which has '-' characters.
  #       Should be replaced as soon as possible by 'http://os-network:9696'.
  #       https://bugs.launchpad.net/kolla/+bug/1629729
  url = http://10.30.200.100:9696
  user_domain_name = default
  username = neutron
  
  [oslo_concurrency]
  lock_path = /var/lock/nova
  
  [oslo_messaging_notifications]
  driver = messagingv2
  
  [oslo_messaging_rabbit]
  amqp_durable_queues = true
  rabbit_ha_queues = true
  rabbit_retry_backoff = 2
  rabbit_retry_interval = 1
  
  [oslo_middleware]
  enable_proxy_headers_parsing = true
  
  [vnc]
  enabled = true
  novncproxy_host = 10.30.200.101
  novncproxy_port = 6080
  vncserver_listen = $my_ip
  vncserver_proxyclient_address = $my_ip
  
  All caches are configured. I looked at the code of the consoleauth
  service. If I get everything right, the manager just looks into the
  cache and checks if the token is present. If it is not, it denies access
  to the console.
  
  Has anybody an idea what causes the issue?
  
  Thanks a lot!

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to OpenStack Compute (nova).
https://bugs.launchpad.net/bugs/1637390

Title:
  nova.consoleauth.manager often denies access to VNC: First login fails
  or token expires too fast

Status in OpenStack Compute (nova):
  New

Bug description:
  I am confronted with a really strange problem with nova-consoleauth. I
  am running OpenStack Newton on Ubuntu Server 16.04.1. When I use VNC
  from Horizon, I get frequently get the error "Failed to connect to
  server (code: 1006)". There is only a single nova-consoleauth service
  available.

  There are two scenarios:
  - The first login with a fresh token fails. The next one succeeds.
  - The first logon succeeds, but the token expires really fast.

  Scenario 1 (nova-consoleauth.log):
  2016-10-28 06:50:55.845 9973 INFO nova.consoleauth.manager [req-f0f8fc1d-ae41-443d-9647-83287114bf1d 58963f571cad45b3b7b6272c73f4cb3b 638770a11625458299c2d205759d09df - - -] Received Token: 37d8bbfb-03b8-4368-b339-b3791e77a4b7, {'instance_uuid': u'f35b3673-e2ac-4bfa-878c-6700efd289d5', 'access_url': u'https://10.30.216.100:6080/vnc_auto.html?token=37d8bbfb-03b8-4368-b339-b3791e77a4b7', 'token': u'37d8bbfb-03b8-4368-b339-b3791e77a4b7', 'last_activity_at': 1477630255.842381, 'internal_access_path': None, 'console_type': u'novnc', 'host': u'10.30.200.113', 'port': u'5900'}
  2016-10-28 06:50:56.313 9973 INFO nova.consoleauth.manager [req-1d623f93-5e05-462a-8058-4867bca71665 - - - - -] Checking Token: 37d8bbfb-03b8-4368-b339-b3791e77a4b7, False
  2016-10-28 06:51:22.427 9973 INFO nova.consoleauth.manager [req-805a354e-c325-4f67-8a64-9e6b1a689f18 - - - - -] Checking Token: 37d8bbfb-03b8-4368-b339-b3791e77a4b7, False
  2016-10-28 06:51:48.809 9973 INFO nova.consoleauth.manager [req-048a2bf7-ac53-4136-b28a-d3c5903ef226 58963f571cad45b3b7b6272c73f4cb3b 638770a11625458299c2d205759d09df - - -] Received Token: cdf07104-102c-44c6-ba90-56049702e3ae, {'instance_uuid': u'8c793085-1f79-458f-92a8-ee95add830da', 'access_url': u'https://10.30.216.100:6080/vnc_auto.html?token=cdf07104-102c-44c6-ba90-56049702e3ae', 'token': u'cdf07104-102c-44c6-ba90-56049702e3ae', 'last_activity_at': 1477630068.805975, 'internal_access_path': None, 'console_type': u'novnc', 'host': u'10.30.200.111', 'port': u'5900'}
  2016-10-28 06:52:49.168 9973 INFO nova.consoleauth.manager [req-81b8c139-303f-4c6e-9b2d-0f7e0ea1467c - - - - -] Checking Token: cdf07104-102c-44c6-ba90-56049702e3ae, True
  2016-10-28 06:53:02.168 9973 INFO nova.consoleauth.manager [req-81b8c139-303f-4c6e-9b2d-0f7e0ea1467c - - - - -] Checking Token: cdf07104-102c-44c6-ba90-56049702e3ae, True

  Scenario 2 (nova-consoleauth.log):
  2016-10-28 07:11:00.059 9973 INFO nova.consoleauth.manager [req-c3cfaf64-935f-4b2e-83f1-6bff35f4e923 ba6f9eddfd154b88b6a45d218fb5b310 638770a11625458299c2d205759d09df - - -] Received Token: bc3c697d-8740-4053-adf9-8133ce5f2296, {'instance_uuid': u'8c793085-1f79-458f-92a8-ee95add830da', 'access_url': u'https://10.30.216.100:6080/vnc_auto.html?token=bc3c697d-8740-4053-adf9-8133ce5f2296', 'token': u'bc3c697d-8740-4053-adf9-8133ce5f2296', 'last_activity_at': 1477631460.049053, 'internal_access_path': None, 'console_type': u'novnc', 'host': u'10.30.200.111', 'port': u'5900'}
  2016-10-28 07:11:00.494 9973 INFO nova.consoleauth.manager [req-34d85dce-54e9-475d-9968-524bedffaa0b - - - - -] Checking Token: bc3c697d-8740-4053-adf9-8133ce5f2296, True
  2016-10-28 07:11:07.479 9973 INFO nova.consoleauth.manager [req-c835b16c-4bb4-4d9d-83c8-e59c174052a6 - - - - -] Checking Token: bc3c697d-8740-4053-adf9-8133ce5f2296, True
  2016-10-28 07:12:24.923 9973 INFO nova.consoleauth.manager [req-f1748791-e631-429d-b75e-7b865664a09b - - - - -] Checking Token: bc3c697d-8740-4053-adf9-8133ce5f2296, False

  I successfully locked in at "07:11:00.059" with the token
  "bc3c697d-8740-4053-adf9-8133ce5f229" and made some refreshes. At
  "07:12:24.923" the token is suddenly invalid. This is really fast...
  What is the reason.

  This is my nova.conf on the controller:
  [DEFAULT]
  auth_strategy = keystone
  debug = true
  enabled_apis = osapi_compute,metadata
  firewall_driver = nova.virt.firewall.NoopFirewallDriver
  host = os-controller01
  linuxnet_interface_driver = nova.network.linux_net.LinuxOVSInterfaceDriver
  log_dir = /var/log/nova
  memcached_servers = os-memcache:11211
  metadata_listen = $my_ip
  metadata_listen_port = 8775
  my_ip = 10.30.200.101
  osapi_compute_listen = $my_ip
  osapi_compute_listen_port = 8774
  state_path = /var/lib/nova
  transport_url = rabbit://nova:XYZ@os-rabbit01:5672,nova:XYZ@os-rabbit02:5672/openstack
  use_neutron = true

  [cache]
  backend = oslo_cache.memcache_pool
  enabled = true
  memcache_servers = os-memcache:11211

  [cinder]
  catalog_info = volumev2:cinderv2:internalURL
  os_region_name = RegionOne

  [database]
  connection = mysql+pymysql://nova:XYZ@os-controller/nova
  max_retries = -1

  [api_database]
  connection = mysql+pymysql://nova:XYZ@os-controller/nova_api
  max_retries = -1

  [glance]
  api_servers = http://os-image:9292

  [keystone_authtoken]
  auth_type = password
  auth_uri = http://os-identity:5000
  auth_url = http://os-identity:35357
  memcached_servers = os-memcache:11211
  password = XYZ
  project_domain_name = default
  project_name = service
  user_domain_name = default
  username = nova

  [neutron]
  auth_type = password
  auth_uri = http://os-identity:5000
  auth_url = http://os-identity:35357
  metadata_proxy_shared_secret = 2a9c2c3a435ad6fefd61
  password = XYZ
  project_domain_name = default
  project_name = service
  region_name = RegionOne
  service_metadata_proxy = true
  # NOTE: python-rfc3986 could not handle URI which has '-' characters.
  #       Should be replaced as soon as possible by 'http://os-network:9696'.
  #       https://bugs.launchpad.net/kolla/+bug/1629729
  url = http://10.30.200.100:9696
  user_domain_name = default
  username = neutron

  [oslo_concurrency]
  lock_path = /var/lock/nova

  [oslo_messaging_notifications]
  driver = messagingv2

  [oslo_messaging_rabbit]
  amqp_durable_queues = true
  rabbit_ha_queues = true
  rabbit_retry_backoff = 2
  rabbit_retry_interval = 1

  [oslo_middleware]
  enable_proxy_headers_parsing = true

  [vnc]
  enabled = true
  novncproxy_host = 10.30.200.101
  novncproxy_port = 6080
  vncserver_listen = $my_ip
  vncserver_proxyclient_address = $my_ip

  All caches are configured. I looked at the code of the consoleauth
  service. If I get everything right, the manager just looks into the
  cache and checks if the token is present. If it is not, it denies
  access to the console.

  Has anybody an idea what causes the issue?

  Thanks a lot!

To manage notifications about this bug go to:
https://bugs.launchpad.net/nova/+bug/1637390/+subscriptions
Follow ups

[Bug 1637390] Re: nova.consoleauth.manager often denies access to VNC: First login fails or token expires too fast
From: Andrey Volkov, 2017-03-03