Problem transfer to master in Designate after upgrade from Xena to Yoga

Bug #2012324 reported by LuuVuong
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Designate
New
Undecided
Unassigned

Bug Description

I use Kolla-Ansiable to upgrade Openstack Xena to Yoga with failed in Designate as log below. Current slave can not transfer to master. I using backend Bind9

<controller01> SSH: EXEC ssh -vvv -C -o ControlMaster=auto -o ControlPersist=60s -o StrictHostKeyChecking=no -o KbdInteractiveAuthentication=no -o PreferredAuthentications=gssapi-with-mic,gssapi-keyex,hostbased,publickey -o PasswordAuthentication=no -o ConnectTimeout=10 -o 'ControlPath="/root/.ansible/cp/d146e0a5fd"' controller01 '/bin/sh -c '"'"'rm -f -r /root/.ansible/tmp/ansible-tmp-1679305915.7228463-26117-201173847473900/ > /dev/null 2>&1 && sleep 0'"'"''
<controller01> (0, b'', b"OpenSSH_8.0p1, OpenSSL 1.1.1k FIPS 25 Mar 2021\r\ndebug1: Reading configuration data /etc/ssh/ssh_config\r\ndebug3: /etc/ssh/ssh_config line 52: Including file /etc/ssh/ssh_config.d/05-redhat.conf depth 0\r\ndebug1: Reading configuration data /etc/ssh/ssh_config.d/05-redhat.conf\r\ndebug2: checking match for 'final all' host controller01 originally controller01\r\ndebug3: /etc/ssh/ssh_config.d/05-redhat.conf line 3: not matched 'final'\r\ndebug2: match not found\r\ndebug3: /etc/ssh/ssh_config.d/05-redhat.conf line 5: Including file /etc/crypto-policies/back-ends/openssh.config depth 1 (parse only)\r\ndebug1: Reading configuration data /etc/crypto-policies/back-ends/openssh.config\r\ndebug3: gss kex names ok: [gss-curve25519-sha256-,gss-nistp256-sha256-,gss-group14-sha256-,gss-group16-sha512-,gss-gex-sha1-,gss-group14-sha1-]\r\ndebug3: kex names ok: [curve25519-sha256,<email address hidden>,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group14-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1]\r\ndebug1: configuration requests final Match pass\r\ndebug1: re-parsing configuration\r\ndebug1: Reading configuration data /etc/ssh/ssh_config\r\ndebug3: /etc/ssh/ssh_config line 52: Including file /etc/ssh/ssh_config.d/05-redhat.conf depth 0\r\ndebug1: Reading configuration data /etc/ssh/ssh_config.d/05-redhat.conf\r\ndebug2: checking match for 'final all' host controller01 originally controller01\r\ndebug3: /etc/ssh/ssh_config.d/05-redhat.conf line 3: matched 'final'\r\ndebug2: match found\r\ndebug3: /etc/ssh/ssh_config.d/05-redhat.conf line 5: Including file /etc/crypto-policies/back-ends/openssh.config depth 1\r\ndebug1: Reading configuration data /etc/crypto-policies/back-ends/openssh.config\r\ndebug3: gss kex names ok: [gss-curve25519-sha256-,gss-nistp256-sha256-,gss-group14-sha256-,gss-group16-sha512-,gss-gex-sha1-,gss-group14-sha1-]\r\ndebug3: kex names ok: [curve25519-sha256,<email address hidden>,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group14-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1]\r\ndebug1: auto-mux: Trying existing master\r\ndebug2: fd 5 setting O_NONBLOCK\r\ndebug2: mux_client_hello_exchange: master version 4\r\ndebug3: mux_client_forwards: request forwardings: 0 local, 0 remote\r\ndebug3: mux_client_request_session: entering\r\ndebug3: mux_client_request_alive: entering\r\ndebug3: mux_client_request_alive: done pid = 25553\r\ndebug3: mux_client_request_session: session request sent\r\ndebug3: mux_client_read_packet: read header failed: Broken pipe\r\ndebug2: Received exit status from master 0\r\n")
fatal: [controller01 -> controller01]: FAILED! => {
    "changed": true,
    "cmd": [
        "docker",
        "exec",
        "-t",
        "designate_worker",
        "designate-manage",
        "pool",
        "update",
        "--file",
        "/etc/designate/pools.yaml"
    ],
    "delta": "0:00:05.663216",
    "end": "2023-03-20 16:49:57.903800",
    "invocation": {
        "module_args": {
            "_raw_params": "docker exec -t designate_worker designate-manage pool update --file /etc/designate/pools.yaml",
            "_uses_shell": false,
            "argv": null,
            "chdir": null,
            "creates": null,
            "executable": null,
            "removes": null,
            "stdin": null,
            "stdin_add_newline": true,
            "strip_empty_ends": true,
            "warn": false
        }
    },
    "msg": "non-zero return code",
    "rc": 1,
    "start": "2023-03-20 16:49:52.240584",
    "stderr": "",
    "stderr_lines": [],
    "stdout": "Updating Pools Configuration\r\n****************************",
    "stdout_lines": [
        "Updating Pools Configuration",
        "****************************"
    ]
}

NO MORE HOSTS LEFT *************************************************************

Revision history for this message
LuuVuong (luuvuong) wrote :

Check log in mdns with 'docker logs designate_mdns' command

/var/lib/kolla/venv/lib/python3.6/site-packages/oslo_policy/policy.py:809: UserWarning: Policy "delete_zone_transfer_request":"rule:admin_or_owner" was deprecated in W in favor of "delete_zone_transfer_request":"(role:admin and system_scope:all) or (role:member and project_id:%(project_id)s)". Reason:
The zone transfer request API now supports system scope and default roles.
. Either ensure your deployment is ready for the new default or copy/paste the deprecated policy into your policy file and maintain it manually.
  warnings.warn(deprecated_msg)

Revision history for this message
LuuVuong (luuvuong) wrote :
Download full text (11.1 KiB)

Log in /var/log/kolla/designate/designate-mdns.log

[SQL: SELECT recordsets.id, recordsets.type, recordsets.ttl, recordsets.name, records.data, records.action
FROM records INNER JOIN recordsets ON records.recordset_id = recordsets.id
WHERE records.action != %(action_1)s AND recordsets.zone_id = %(zone_id_1)s AND recordsets.type = %(type_1)s ORDER BY recordsets.id]
[parameters: {'action_1': 'DELETE', 'zone_id_1': '7727393d216f46c4ac74e60ec741abf5', 'type_1': 'SOA'}]
(Background on this error at: https://sqlalche.me/e/14/e3q8)
2023-03-21 09:40:42.321 20 ERROR designate.service Traceback (most recent call last):
2023-03-21 09:40:42.321 20 ERROR designate.service File "/var/lib/kolla/venv/lib64/python3.6/site-packages/sqlalchemy/engine/base.py", line 1803, in _execute_context
2023-03-21 09:40:42.321 20 ERROR designate.service cursor, statement, parameters, context
2023-03-21 09:40:42.321 20 ERROR designate.service File "/var/lib/kolla/venv/lib64/python3.6/site-packages/sqlalchemy/engine/default.py", line 732, in do_execute
2023-03-21 09:40:42.321 20 ERROR designate.service cursor.execute(statement, parameters)
2023-03-21 09:40:42.321 20 ERROR designate.service File "/var/lib/kolla/venv/lib/python3.6/site-packages/pymysql/cursors.py", line 148, in execute
2023-03-21 09:40:42.321 20 ERROR designate.service result = self._query(query)
2023-03-21 09:40:42.321 20 ERROR designate.service File "/var/lib/kolla/venv/lib/python3.6/site-packages/pymysql/cursors.py", line 310, in _query
2023-03-21 09:40:42.321 20 ERROR designate.service conn.query(q)
2023-03-21 09:40:42.321 20 ERROR designate.service File "/var/lib/kolla/venv/lib/python3.6/site-packages/pymysql/connections.py", line 548, in query
2023-03-21 09:40:42.321 20 ERROR designate.service self._affected_rows = self._read_query_result(unbuffered=unbuffered)
2023-03-21 09:40:42.321 20 ERROR designate.service File "/var/lib/kolla/venv/lib/python3.6/site-packages/pymysql/connections.py", line 775, in _read_query_result
2023-03-21 09:40:42.321 20 ERROR designate.service result.read()
2023-03-21 09:40:42.321 20 ERROR designate.service File "/var/lib/kolla/venv/lib/python3.6/site-packages/pymysql/connections.py", line 1163, in read
2023-03-21 09:40:42.321 20 ERROR designate.service self._read_result_packet(first_packet)
2023-03-21 09:40:42.321 20 ERROR designate.service File "/var/lib/kolla/venv/lib/python3.6/site-packages/pymysql/connections.py", line 1236, in _read_result_packet
2023-03-21 09:40:42.321 20 ERROR designate.service self._read_rowdata_packet()
2023-03-21 09:40:42.321 20 ERROR designate.service File "/var/lib/kolla/venv/lib/python3.6/site-packages/pymysql/connections.py", line 1270, in _read_rowdata_packet
2023-03-21 09:40:42.321 20 ERROR designate.service packet = self.connection._read_packet()
2023-03-21 09:40:42.321 20 ERROR designate.service File "/var/lib/kolla/venv/lib/python3.6/site-packages/pymysql/connections.py", line 725, in _read_packet
2023-03-21 09:40:42.321 20 ERROR designate.service packet.raise_for_error()
2023-03-21 09:40:42.321 20 ERROR designate.service File "/var/lib/kolla/venv/lib/python3.6/site-packages/pymysq...

Revision history for this message
LuuVuong (luuvuong) wrote :
Download full text (4.7 KiB)

I already fix DB Corrupt, but you to see ERROR in mdns
2023-03-21 17:12:16.557 21 ERROR designate.service [req-ca553f2e-6700-4c14-80ad-341190a4d098 - - - - -] Unhandled exception while processing request from 10.10.30.5:35852: designate.exceptions.ValueError: badly formed hexadecimal UUID string
2023-03-21 17:12:16.557 21 ERROR designate.service Traceback (most recent call last):
2023-03-21 17:12:16.557 21 ERROR designate.service File "/var/lib/kolla/venv/lib/python3.6/site-packages/designate/sqlalchemy/base.py", line 262, in _find
2023-03-21 17:12:16.557 21 ERROR designate.service results = resultproxy.fetchall()
2023-03-21 17:12:16.557 21 ERROR designate.service File "/var/lib/kolla/venv/lib64/python3.6/site-packages/sqlalchemy/engine/result.py", line 1014, in fetchall
2023-03-21 17:12:16.557 21 ERROR designate.service return self._allrows()
2023-03-21 17:12:16.557 21 ERROR designate.service File "/var/lib/kolla/venv/lib64/python3.6/site-packages/sqlalchemy/engine/result.py", line 402, in _allrows
2023-03-21 17:12:16.557 21 ERROR designate.service made_rows = [make_row(row) for row in rows]
2023-03-21 17:12:16.557 21 ERROR designate.service File "/var/lib/kolla/venv/lib64/python3.6/site-packages/sqlalchemy/engine/result.py", line 402, in <listcomp>
2023-03-21 17:12:16.557 21 ERROR designate.service made_rows = [make_row(row) for row in rows]
2023-03-21 17:12:16.557 21 ERROR designate.service File "/var/lib/kolla/venv/lib64/python3.6/site-packages/sqlalchemy/sql/type_api.py", line 1686, in process
2023-03-21 17:12:16.557 21 ERROR designate.service return process_value(value, dialect)
2023-03-21 17:12:16.557 21 ERROR designate.service File "/var/lib/kolla/venv/lib/python3.6/site-packages/designate/sqlalchemy/types.py", line 54, in process_result_value
2023-03-21 17:12:16.557 21 ERROR designate.service return str(uuid.UUID(value))
2023-03-21 17:12:16.557 21 ERROR designate.service File "/usr/lib64/python3.6/uuid.py", line 140, in __init__
2023-03-21 17:12:16.557 21 ERROR designate.service raise ValueError('badly formed hexadecimal UUID string')
2023-03-21 17:12:16.557 21 ERROR designate.service ValueError: badly formed hexadecimal UUID string
2023-03-21 17:12:16.557 21 ERROR designate.service
2023-03-21 17:12:16.557 21 ERROR designate.service During handling of the above exception, another exception occurred:
2023-03-21 17:12:16.557 21 ERROR designate.service
2023-03-21 17:12:16.557 21 ERROR designate.service Traceback (most recent call last):
2023-03-21 17:12:16.557 21 ERROR designate.service File "/var/lib/kolla/venv/lib/python3.6/site-packages/designate/service.py", line 353, in _dns_handle_udp_query
2023-03-21 17:12:16.557 21 ERROR designate.service {'payload': payload, 'addr': addr}):
2023-03-21 17:12:16.557 21 ERROR designate.service File "/var/lib/kolla/venv/lib/python3.6/site-packages/designate/dnsutils.py", line 128, in __call__
2023-03-21 17:12:16.557 21 ERROR designate.service for response in self.application(message):
2023-03-21 17:12:16.557 21 ERROR designate.service File "/var/lib/kolla/venv/lib/python3.6/site-packages/designate/mdns/handler.py", line 80, in __call__
2023-03...

Read more...

Revision history for this message
Michael Johnson (johnsom) wrote :

Hi there,
What a chain of issues....

Starting at the top: The pool update error, please check that the file "/etc/designate/pools.yaml" exists at that location in the container. If so, please run the command manually from the container and see if there is more error output than kola is providing. Also, you can try running with the --dry-run option to see if there is more information about the error.

Comment #1 is a warning that can be ignored. See this document for more information: https://governance.openstack.org/tc/goals/selected/consistent-and-secure-rbac.html

Comment #2 is a mysql issue outside of Designate. It sounds like you have fixed this already.

Comment #3 This implies you have some corruption in your database (related to whatever happened to the index in #2?). I would connect to your designate DB in mysql, "select id, zone_id from recordsets;", check that those two fields for all records has a UUID compatible value (missing the '-'s). I.e. 296c364f-62f2-48fe-8cf8-a220507d1c13 would be stored as 296c364f62f248fe8cf8a220507d1c13. They must be hex compatible characters.

The issues in comment #2 and #3 seem unrelated to the issue you experienced originally as pool update does not touch the recordsets table in the database.

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.