Description

The contrail-api needs to communicate with keystone to sync up the tenant (project) information. Therefore, a keystone database problem may affact the contrail-api process status.

Symptoms

In all three Contrail controllers, the contrail-api gets stuck in 'initializing' status.

initializing (Generic Connection:Keystone[Error: badly formed hexadecimal UUID string 

Output from 'contrail-status -d ':

    root@cont102:~# contrail-status -d
    == Contrail Control ==
    supervisor-control:           active
    contrail-control              active              pid 27676, uptime 3:46:38
    contrail-control-nodemgr      active              pid 27675, uptime 3:46:38
    contrail-dns                  active              pid 27677, uptime 3:46:38
    contrail-named                active              pid 27678, uptime 3:46:38

    == Contrail Analytics ==
    supervisor-analytics:         active
    contrail-alarm-gen            active              pid 1623, uptime 29 days, 4:41:25
    contrail-analytics-api        active              pid 1622, uptime 29 days, 4:41:25
    contrail-analytics-nodemgr    active              pid 1616, uptime 29 days, 4:41:25
    contrail-collector            active              pid 1620, uptime 29 days, 4:41:25
    contrail-query-engine         active              pid 1621, uptime 29 days, 4:41:25
    contrail-snmp-collector       active              pid 21578, uptime 29 days, 3:10:05
    contrail-topology             active              pid 14893, uptime 22 days, 1:12:23

    == Contrail Config ==
    supervisor-config:            active
    contrail-api:0                initializing (Generic Connection:Keystone[Error: badly formed hexadecimal UUID string at UTC 2018-12-08 01:25:46.670537] connection down)pid 15565, uptime 6:40:14
    contrail-config-nodemgr       active              pid 15562, uptime 6:40:14
    contrail-device-manager       backup              pid 15566, uptime 6:40:14
    contrail-discovery:0          active              pid 15564, uptime 6:40:14
    contrail-schema               backup              pid 15567, uptime 6:40:14
    contrail-svc-monitor          backup              pid 15568, uptime 6:40:14
    ifmap                         active              pid 15563, uptime 6:40:14

    == Contrail Web UI ==
    supervisor-webui:             active
    contrail-webui                active              pid 1606, uptime 29 days, 4:41:25
    contrail-webui-middleware     active              pid 1608, uptime 29 days, 4:41:25

    == Contrail Database ==
    contrail-database:            active

    == Contrail Supervisor Database ==
    supervisor-database:          active
    contrail-database-nodemgr     active              pid 1601, uptime 29 days, 4:41:25
    kafka                         active              pid 13221, uptime 23 days, 22:43:05

    == Contrail Support Services ==
    supervisor-support-service:   active
    rabbitmq-server               active              pid 1600, uptime 29 days, 4:41:25


In the contrail-api.log and contrail-api-0-stdout.log , the following messages can be found:

    172.29.0.22 - - [2018-11-13 00:00:20] "POST /fqname-to-id HTTP/1.1" 200 156 0.027712
    INFO:pycassa.pool:Connection 139776041287824 (172.29.2.248:9160) in pool 139776426408848 failed: UnavailableException(_message=None)
    ERROR:contrail-api:Session Event: TCP Connection Closed
    ERROR:contrail-api:SANDESH: [DROP: WrongClientSMState] NodeStatusUVE: data = <<  name = zrdm3ccnt01.rdm3.cci.att.com  process_status = [ <<  module_id = contrail-api  instance_id = 0  state = Non-Functional  connection_infos = [ <<  type = IFMap  name = IfMap  server_addrs = [ 172.29.2.249:8443,  ]  status = Up  description =   >>, <<  type = Collector  name =   server_addrs = [ 172.29.2.247:8086,  ]  status = Down  description = ClientInit to Idle on EvConnectTimerExpired  >>, <<  type = Database  name = RabbitMQ  server_addrs = [ 172.29.0.21,  ]  status = Up  description =   >>, <<  type = Zookeeper  name = Zookeeper  server_addrs = [ 172.29.2.248:2181, 172.29.2.249:2181, 172.29.2.250:2181,  ]  status = Up  description =   >>, <<  type = Discovery  name = ApiServer  server_addrs = [ 172.29.0.21:5998,  ]  status = Up  description = Publish Success  >>, <<  type = Discovery  name = IfmapServer  server_addrs = [ 172.29.0.21:5998,  ]  status = Up  description = Publish Success  >>, <<  type = Discovery  name = Collector  server_addrs = [ 172.29.0.21:5998,  ]  status = Up  description = Subscribe Response  >>, <<  type = Database  name = Cassandra  server_addrs = [ 172.29.2.248:9160, 172.29.2.249:9160, 172.29.2.250:9160,  ]  status = Up  description =   >>, <<  type = Generic Connection  name = Keystone  server_addrs = [ https://identity-aic.rdm3.cci.att.com:35357/v2.0,  ]  status = Down  description = Error: badly formed hexadecimal UUID string at UTC 2018-11-12 23:59:20.835793  >>,  ]  description = Collector, Generic Connection:Keystone[Error: badly formed hexadecimal UUID string at UTC 2018-11-12 23:59:20.835793] connection down  >>,  ]  >> 

When this issue occurs, the contrail-api service can actually be up and running, but it has a problem syncing up data from keystone, which is indicated by the error message. There may not be any service impact observed.

Solution

The 'badly formed hexadecimal UUID string' error is a generic python error when uuid module is fed with an invalid UUID.

    root@cont102:~# python
    Python 2.7.6 (default, Jun 22 2015, 17:58:13)
    [GCC 4.8.2] on linux2
    Type "help", "copyright", "credits" or "license" for more information.
    >>> import uuid
    >>> str(uuid.UUID('abc'))
    Traceback (most recent call last):
      File " <stdin> ", line 1, in <module>
      File "/usr/lib/python2.7/uuid.py", line 134, in __init__
        raise ValueError('badly formed hexadecimal UUID string')
    ValueError: badly formed hexadecimal UUID string


When contrail-api is trying to read the keystone DB, a 'badly-formed UUID' in any record of the keystone table may trigger the error. The same exact issue can be replicated by manually adding a project record in keystone that does not have a valid UUID. 

  1. Login to keystone mysql

    root@opsk99:~# mysql -ukeystone -pc0ntrail123
    Welcome to the MySQL monitor.  Commands end with ; or \g.
    Your MySQL connection id is 275742
    Server version: 5.5.37 MySQL Community Server (GPL), wsrep_25.10.r3990
    
    Copyright (c) 2000, 2016, Oracle and/or its affiliates. All rights reserved.
    
    Oracle is a registered trademark of Oracle Corporation and/or its
    affiliates. Other names may be trademarks of their respective
    owners.
  2. Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

        mysql> show databases;
        +--------------------+
        | Database           |
        +--------------------+
        | information_schema |
        | keystone           |
        | test               |
        +--------------------+
        3 rows in set (0.00 sec)
  3. Select keystone DB:

    mysql> use keystone;
    Reading table information for completion of table and column names
    You can turn off this feature to get a quicker startup with -A

        Database changed
  4. List tables in the keystone DB:

        mysql> show tables;
        +------------------------+
        | Tables_in_keystone     |
        +------------------------+
        | access_token           |
        | assignment             |
        | consumer               |
        | credential             |
        | domain                 |
        | endpoint               |
        | endpoint_group         |
        | federation_protocol    |
        | group                  |
        | id_mapping             |
        | identity_provider      |
        | idp_remote_ids         |
        | mapping                |
        | migrate_version        |
        | policy                 |
        | policy_association     |
        | project                |
        | project_endpoint       |
        | project_endpoint_group |
        | region                 |
        | request_token          |
        | revocation_event       |
        | role                   |
        | sensitive_config       |
        | service                |
        | service_provider       |
        | token                  |
        | trust                  |
        | trust_role             |
        | user                   |
        | user_group_membership  |
        | whitelisted_config     |
        +------------------------+
        32 rows in set (0.00 sec)
  5. List the project table:

        mysql> select * from project;
        +----------------------------------+--------------------+-------+-------------+---------+-----------+-----------+
        | id                               | name               | extra | description | enabled | domain_id | parent_id |
        +----------------------------------+--------------------+-------+-------------+---------+-----------+-----------+
        | 05b091dfd9bd4191926072ff19aecb10 | niranjants         | {}    |             |       1 | default   | NULL      |
        | 109ac1f3c5034b61baa7296a9aa85f21 | service            | {}    |             |       1 | default   | NULL      |
        | 15dbc03fbdda4eb380ea1f014d9be0d7 | test2              | {}    | NULL        |       1 | default   | NULL      |
        | 295a084ab8e84a13b001cd35f9cc9741 | aamonker           | {}    |             |       1 | default   | NULL      |
        | 3cbd379c48f34a06a6e9ecfe86012283 | invisible_to_admin | {}    | NULL        |       1 | default   | NULL      |
        | 4209ff6c449e4dd39b58583b7bdb7328 | jlu                | {}    |             |       1 | default   | NULL      |
        | 5b3ebb0c0a794f27be662242290a593a | test1              | {}    | NULL        |       1 | default   | NULL      |
        | 6259d182fc9b4a0aac7e3fcb28ac9f5b | bfarooq            | {}    |             |       1 | default   | NULL      |
        | 7ecef979004c45acadb8c88b96e96fd3 | demo               | {}    |             |       1 | default   | NULL      |
        | 7fccf71a7e7d4c798413513ee809435a | jjzhang            | {}    |             |       1 | default   | NULL      |
        | 98e0a0be21e746b0b4e18194515d2918 | AnalyticsAPITest   | {}    | 3212 test   |       1 | default   | NULL      |
        | a791f02319ed4450888d167c935eb94b | cheny              | {}    |             |       1 | default   | NULL      |
        | abb527ab95d946438097ecf64cba3d02 | nzhong             | {}    |             |       1 | default   | NULL      |
        | acae6b2a3291444596179e23a271c980 | pings              | {}    |             |       1 | default   | NULL      |
        | ede15b5d21eb4401bd2a56e8d373aa71 | admin              | {}    | NULL        |       1 | default   | NULL      |
        +----------------------------------+--------------------+-------+-------------+---------+-----------+-----------+
        15 rows in set (0.00 sec)
  6. To replicate the issue, insert a 'bogus' record without a valid UUID in the project table:

    mysql> insert into project ( id, name, domain_id ) values ( "default", "bogus_project", "default" );
                                                                     ^^^^^^^
                                                               (invalid UUID)

    mysql> select * from project;
    +----------------------------------+--------------------+-------+-------------+---------+-----------+-----------+
    | id                               | name               | extra | description | enabled | domain_id | parent_id |
    +----------------------------------+--------------------+-------+-------------+---------+-----------+-----------+
    | 05b091dfd9bd4191926072ff19aecb10 | niranjants         | {}    |             |       1 | default   | NULL      |
    | 109ac1f3c5034b61baa7296a9aa85f21 | service            | {}    |             |       1 | default   | NULL      |
    | 15dbc03fbdda4eb380ea1f014d9be0d7 | test2              | {}    | NULL        |       1 | default   | NULL      |
    | 295a084ab8e84a13b001cd35f9cc9741 | aamonker           | {}    |             |       1 | default   | NULL      |
    | 3cbd379c48f34a06a6e9ecfe86012283 | invisible_to_admin | {}    | NULL        |       1 | default   | NULL      |
    | 4209ff6c449e4dd39b58583b7bdb7328 | jlu                | {}    |             |       1 | default   | NULL      |
    | 5b3ebb0c0a794f27be662242290a593a | test1              | {}    | NULL        |       1 | default   | NULL      |
    | 6259d182fc9b4a0aac7e3fcb28ac9f5b | bfarooq            | {}    |             |       1 | default   | NULL      |
    | 7ecef979004c45acadb8c88b96e96fd3 | demo               | {}    |             |       1 | default   | NULL      |
    | 7fccf71a7e7d4c798413513ee809435a | jjzhang            | {}    |             |       1 | default   | NULL      |
    | 98e0a0be21e746b0b4e18194515d2918 | AnalyticsAPITest   | {}    | 3212 test   |       1 | default   | NULL      |
    | a791f02319ed4450888d167c935eb94b | cheny              | {}    |             |       1 | default   | NULL      |
    | abb527ab95d946438097ecf64cba3d02 | nzhong             | {}    |             |       1 | default   | NULL      |
    | acae6b2a3291444596179e23a271c980 | pings              | {}    |             |       1 | default   | NULL      |
    | default                          | bogus_project      | NULL  | NULL        |    NULL | default   | NULL      |
    | ede15b5d21eb4401bd2a56e8d373aa71 | admin              | {}    | NULL        |       1 | default   | NULL      |
    +----------------------------------+--------------------+-------+-------------+---------+-----------+-----------+
    16 rows in set (0.00 sec)
  7. Immediately after the bad record is inserted in the project table, in all Contrail controllers, the exact error messages from contrail-api will show up:

    == Contrail Config ==
    supervisor-config:            active
    contrail-api:0                initializing (Generic Connection:Keystone[Error: <type 'NoneType'> can't be decoded (HTTP 400) (Request-ID: req-6eabcc90-1492-4c19-9fc2-5182bb3c7010) at UTC 2018-12-08 00:58:44.289556] connection down)pid 15565, uptime 6:13:01
    contrail-config-nodemgr       active              pid 15562, uptime 6:13:01
    contrail-device-manager       backup              pid 15566, uptime 6:13:01
    contrail-discovery:0          active              pid 15564, uptime 6:13:01
    contrail-schema               backup              pid 15567, uptime 6:13:01
    contrail-svc-monitor          backup              pid 15568, uptime 6:13:01
    ifmap                         active              pid 15563, uptime 6:13:01

        mysql> delete from project where id="default";
        Query OK, 1 row affected (0.00 sec)

        == Contrail Config ==
        supervisor-config:            active
        contrail-api:0                active              pid 15565, uptime 6:13:39
        contrail-config-nodemgr       active              pid 15562, uptime 6:13:39
        contrail-device-manager       backup              pid 15566, uptime 6:13:39
        contrail-discovery:0          active              pid 15564, uptime 6:13:39
        contrail-schema               backup              pid 15567, uptime 6:13:39
        contrail-svc-monitor          backup              pid 15568, uptime 6:13:39
        ifmap                         active              pid 15563, uptime 6:13:39

        mysql> insert into project ( id, name, extra, description, enabled, domain_id ) values ( "default", "bogus_project", "{}", "crash api", 1, "default" );

        == Contrail Config ==
        supervisor-config:            active
        contrail-api:0                initializing (Generic Connection:Keystone[Error: badly formed hexadecimal UUID string at UTC 2018-12-08 01:11:45.275981] connection down)pid 15565, uptime 6:25:49
        contrail-config-nodemgr       active              pid 15562, uptime 6:25:49
        contrail-device-manager       backup              pid 15566, uptime 6:25:49
        contrail-discovery:0          active              pid 15564, uptime 6:25:49
        contrail-schema               backup              pid 15567, uptime 6:25:49
        contrail-svc-monitor          backup              pid 15568, uptime 6:25:49
        ifmap                         active              pid 15563, uptime 6:25:49
  8. To clear the issue, drop the 'bogus' record from the project table:

        mysql> delete from project where id="default";
        Query OK, 1 row affected (0.00 sec)