Kea can't start after upgrading database backend to version 27.0
Our build farm detected a problem with Kea after upgrading the database to version 27. Test scenario:
- create database 8.2 with data
- start current Kea - expect to fail
- run kea-admin to upgrade db schema to the newest version
- start current Kea - expect to succeed
- check migrated data
This is the output (important places are marked with <<<<<<<<<< you can search it)
00:46:42 [10.53.60.44] out: INFO/keactrl: Starting /usr/local/sbin/kea-dhcp6 -c /usr/local/etc/kea/kea-dhcp6.conf
00:46:42 [10.53.60.44] out: INFO/keactrl: Starting /usr/local/sbin/kea-ctrl-agent -c /usr/local/etc/kea/kea-ctrl-agent.conf
00:46:42 [10.53.60.44] out: 2024-12-02 22:54:51.169 ERROR [kea-dhcp6.dhcp6/2517184.140611391526784] DHCP6_INIT_FAIL failed to initialize Kea server: configuration error using file '/usr/local/etc/kea/kea-dhcp6.conf': during update from config backend database: MySQL schema version mismatch: expected version: 27.0, found version: 8.2 <<<<<<<<<< first expected failure, Kea wants db schema version 27.0
00:46:42 [10.53.60.44] out: 2024-12-02 22:54:51.169 INFO [kea-dhcp6.commands/2517184.140611391526784] HTTP_COMMAND_MGR_SERVICE_STOPPING stopping HTTP service
00:46:42 [10.53.60.44] out: 2024-12-02 22:54:51.169 INFO [kea-dhcp6.mysql-lb-hooks/2517184.140611391526784] MYSQL_DEINIT_OK unloading MySQL hooks library successful
00:46:42 [10.53.60.44] out: 2024-12-02 22:54:51.169 INFO [kea-dhcp6.cb-cmds-hooks/2517184.140611391526784] CB_CMDS_DEINIT_OK unloading cb_cmds hooks library successful
00:46:42 [10.53.60.44] out: 2024-12-02 22:54:51.169 INFO [kea-dhcp6.lease-cmds-hooks/2517184.140611391526784] LEASE_CMDS_DEINIT_OK unloading Lease Commands hooks library successful
00:46:42 [10.53.60.44] out: 2024-12-02 22:54:51.169 INFO [kea-dhcp6.host-cmds-hooks/2517184.140611391526784] HOST_CMDS_DEINIT_OK unloading Host Commands hooks library successful
00:46:42 [10.53.60.44] out: 2024-12-02 22:54:51.169 INFO [kea-dhcp6.hooks/2517184.140611391526784] HOOKS_LIBRARY_CLOSED hooks library /usr/local/lib/kea/hooks/libdhcp_mysql.so successfully closed
00:46:42 [10.53.60.44] out: 2024-12-02 22:54:51.170 INFO [kea-dhcp6.hooks/2517184.140611391526784] HOOKS_LIBRARY_CLOSED hooks library /usr/local/lib/kea/hooks/libdhcp_cb_cmds.so successfully closed
00:46:42 [10.53.60.44] out: 2024-12-02 22:54:51.170 INFO [kea-dhcp6.hooks/2517184.140611391526784] HOOKS_LIBRARY_CLOSED hooks library /usr/local/lib/kea/hooks/libdhcp_lease_cmds.so successfully closed
00:46:42 [10.53.60.44] out: 2024-12-02 22:54:51.170 INFO [kea-dhcp6.hooks/2517184.140611391526784] HOOKS_LIBRARY_CLOSED hooks library /usr/local/lib/kea/hooks/libdhcp_host_cmds.so successfully closed
00:46:42 [10.53.60.44] out:
00:46:42
00:46:42 [10.53.60.44] sudo: sudo /usr/local/sbin/kea-admin db-upgrade mysql -u kea_tmp_user -p keapass -n kea_tmp_db
00:46:42 [10.53.60.44] out: Schema version reported before upgrade: 8.2
00:46:42 [10.53.60.44] out: Verifying upgrade permissions for kea_tmp_user
00:46:42 [10.53.60.44] out: MySQL Version is: 10.11.10-MariaDB
00:46:42 [10.53.60.44] out: Processing /usr/local/share/kea/scripts/mysql/upgrade_001.0_to_002.0.sh file...
00:46:42 [10.53.60.44] out: Processing /usr/local/share/kea/scripts/mysql/upgrade_002.0_to_003.0.sh file...
00:46:42 [10.53.60.44] out: Processing /usr/local/share/kea/scripts/mysql/upgrade_003.0_to_004.0.sh file...
00:46:42 [10.53.60.44] out: Processing /usr/local/share/kea/scripts/mysql/upgrade_004.0_to_004.1.sh file...
00:46:42 [10.53.60.44] out: Processing /usr/local/share/kea/scripts/mysql/upgrade_004.1_to_005.0.sh file...
00:46:42 [10.53.60.44] out: Processing /usr/local/share/kea/scripts/mysql/upgrade_005.0_to_005.1.sh file...
00:46:42 [10.53.60.44] out: Processing /usr/local/share/kea/scripts/mysql/upgrade_005.1_to_005.2.sh file...
00:46:42 [10.53.60.44] out: Processing /usr/local/share/kea/scripts/mysql/upgrade_005.2_to_006.0.sh file...
00:46:42 [10.53.60.44] out: Processing /usr/local/share/kea/scripts/mysql/upgrade_006.0_to_007.0.sh file...
00:46:42 [10.53.60.44] out: Processing /usr/local/share/kea/scripts/mysql/upgrade_007.0_to_008.0.sh file...
00:46:42 [10.53.60.44] out: Processing /usr/local/share/kea/scripts/mysql/upgrade_008.0_to_008.1.sh file...
00:46:42 [10.53.60.44] out: Processing /usr/local/share/kea/scripts/mysql/upgrade_008.1_to_008.2.sh file...
00:46:42 [10.53.60.44] out: Processing /usr/local/share/kea/scripts/mysql/upgrade_008.2_to_009.0.sh file...
00:46:42 [10.53.60.44] out: Processing /usr/local/share/kea/scripts/mysql/upgrade_009.0_to_009.1.sh file...
00:46:42 [10.53.60.44] out: Processing /usr/local/share/kea/scripts/mysql/upgrade_009.1_to_009.2.sh file...
00:46:42 [10.53.60.44] out: Processing /usr/local/share/kea/scripts/mysql/upgrade_009.2_to_009.3.sh file...
00:46:42 [10.53.60.44] out: Processing /usr/local/share/kea/scripts/mysql/upgrade_009.3_to_009.4.sh file...
00:46:42 [10.53.60.44] out: Processing /usr/local/share/kea/scripts/mysql/upgrade_009.4_to_009.5.sh file...
00:46:42 [10.53.60.44] out: Processing /usr/local/share/kea/scripts/mysql/upgrade_009.5_to_009.6.sh file...
00:46:42 [10.53.60.44] out: Processing /usr/local/share/kea/scripts/mysql/upgrade_009.6_to_010.0.sh file...
00:46:42 [10.53.60.44] out: /usr/local/share/kea/scripts/mysql/upgrade_009.6_to_010.0.sh: line 68: [: : integer expression expected
00:46:42 [10.53.60.44] out: /usr/local/share/kea/scripts/mysql/upgrade_009.6_to_010.0.sh: line 68: [: : integer expression expected
00:46:42 [10.53.60.44] out: Processing /usr/local/share/kea/scripts/mysql/upgrade_010_to_011.sh file...
00:46:42 [10.53.60.44] out: Processing /usr/local/share/kea/scripts/mysql/upgrade_011_to_012.sh file...
00:46:42 [10.53.60.44] out: Processing /usr/local/share/kea/scripts/mysql/upgrade_012_to_013.sh file...
00:46:42 [10.53.60.44] out: Processing /usr/local/share/kea/scripts/mysql/upgrade_013_to_014.sh file...
00:46:42 [10.53.60.44] out: Processing /usr/local/share/kea/scripts/mysql/upgrade_014_to_015.sh file...
00:46:42 [10.53.60.44] out: Processing /usr/local/share/kea/scripts/mysql/upgrade_015_to_016.sh file...
00:46:42 [10.53.60.44] out: Processing /usr/local/share/kea/scripts/mysql/upgrade_016_to_017.sh file...
00:46:42 [10.53.60.44] out: Processing /usr/local/share/kea/scripts/mysql/upgrade_017_to_018.sh file...
00:46:42 [10.53.60.44] out: Processing /usr/local/share/kea/scripts/mysql/upgrade_018_to_019.sh file...
00:46:42 [10.53.60.44] out: Processing /usr/local/share/kea/scripts/mysql/upgrade_019_to_020.sh file...
00:46:42 [10.53.60.44] out: Processing /usr/local/share/kea/scripts/mysql/upgrade_020_to_021.sh file...
00:46:42 [10.53.60.44] out: Processing /usr/local/share/kea/scripts/mysql/upgrade_021_to_022.sh file...
00:46:42 [10.53.60.44] out: Processing /usr/local/share/kea/scripts/mysql/upgrade_022_to_023.sh file...
00:46:42 [10.53.60.44] out: Processing /usr/local/share/kea/scripts/mysql/upgrade_023_to_024.sh file...
00:46:42 [10.53.60.44] out: Processing /usr/local/share/kea/scripts/mysql/upgrade_024_to_025.sh file...
00:46:42 [10.53.60.44] out: Processing /usr/local/share/kea/scripts/mysql/upgrade_025_to_026.sh file...
00:46:42 [10.53.60.44] out: Processing /usr/local/share/kea/scripts/mysql/upgrade_026_to_027.sh file...
00:46:42 [10.53.60.44] out: Schema version reported after upgrade: 27.0 <<<<<<<<<< upgrade script reports db version 27.0
00:46:42 [10.53.60.44] out:
00:46:42
00:46:42 [10.53.60.44] sudo: nohup /usr/local/sbin/keactrl start < /dev/null > /tmp/keactrl.log 2>&1; SECONDS=0; while (( SECONDS < 4 )); do tail /usr/local/var/kea/kea.log 2>/dev/null | grep 'server version .* started' 2>/dev/null; if [ $? -eq 0 ]; then break; fi done; sync; cat /tmp/keactrl.log
00:46:42 [10.53.60.44] out: INFO/keactrl: Starting /usr/local/sbin/kea-dhcp6 -c /usr/local/etc/kea/kea-dhcp6.conf
00:46:42 [10.53.60.44] out: INFO/keactrl: kea-ctrl-agent appears to be running, see: PID 2517190, PID file: /usr/local/var/run/kea/kea-ctrl-agent.kea-ctrl-agent.pid.
00:46:42 [10.53.60.44] out: 2024-12-02 22:54:59.803 ERROR [kea-dhcp6.dhcp6/2524608.139676460767104] DHCP6_INIT_FAIL failed to initialize Kea server: configuration error using file '/usr/local/etc/kea/kea-dhcp6.conf': during update from config backend database: invalid 'client_classes' value error: unexpected character a in <string>:1:2. Statement is <SELECT n.id, n.name, n.client_classes, n.interface, n.modification_ts, n.preferred_lifetime, n.rapid_commit, n.rebind_timer, n.relay, n.renew_timer, n.evaluate_additional_classes, n.reservations_global, n.user_context, n.valid_lifetime, o.option_id, o.code, o.value, o.formatted_value, o.space, o.persistent, o.cancelled, o.dhcp6_subnet_id, o.scope_id, o.user_context, o.shared_network_name, o.pool_id, o.modification_ts, o.client_classes, o.pd_pool_id, n.calculate_tee_times, n.t1_percent, n.t2_percent, n.interface_id, n.min_preferred_lifetime, n.max_preferred_lifetime, n.min_valid_lifetime, n.max_valid_lifetime, n.ddns_send_updates, n.ddns_override_no_update, n.ddns_override_client_update, n.ddns_replace_client_name, n.ddns_generated_prefix, n.ddns_qualifying_suffix, n.reservations_in_subnet, n.reservations_out_of_pool, n.cache_threshold, n.cache_max_age, n.allocator, n.pd_allocator, s.tag FROM dhcp6_shared_network AS n INNER JOIN dhcp6_shared_network_server AS a ON n.id = a.shared_network_id INNER JOIN dhcp6_server AS s ON (a.server_id = s.id) LEFT JOIN dhcp6_options AS o ON o.scope_id = 4 AND n.name = o.shared_network_name ORDER BY n.id, s.id, o.option_id> <<<<<<<<<< Kea fail to start due to unexpected client_classes
00:46:42 [10.53.60.44] out: 2024-12-02 22:54:59.803 INFO [kea-dhcp6.commands/2524608.139676460767104] HTTP_COMMAND_MGR_SERVICE_STOPPING stopping HTTP service
00:46:42 [10.53.60.44] out: 2024-12-02 22:54:59.804 INFO [kea-dhcp6.mysql-lb-hooks/2524608.139676460767104] MYSQL_DEINIT_OK unloading MySQL hooks library successful
00:46:42 [10.53.60.44] out: 2024-12-02 22:54:59.804 INFO [kea-dhcp6.cb-cmds-hooks/2524608.139676460767104] CB_CMDS_DEINIT_OK unloading cb_cmds hooks library successful
00:46:42 [10.53.60.44] out: 2024-12-02 22:54:59.804 INFO [kea-dhcp6.lease-cmds-hooks/2524608.139676460767104] LEASE_CMDS_DEINIT_OK unloading Lease Commands hooks library successful
00:46:42 [10.53.60.44] out: 2024-12-02 22:54:59.804 INFO [kea-dhcp6.host-cmds-hooks/2524608.139676460767104] HOST_CMDS_DEINIT_OK unloading Host Commands hooks library successful
00:46:42 [10.53.60.44] out: 2024-12-02 22:54:59.804 INFO [kea-dhcp6.hooks/2524608.139676460767104] HOOKS_LIBRARY_CLOSED hooks library /usr/local/lib/kea/hooks/libdhcp_mysql.so successfully closed
00:46:42 [10.53.60.44] out: 2024-12-02 22:54:59.804 INFO [kea-dhcp6.hooks/2524608.139676460767104] HOOKS_LIBRARY_CLOSED hooks library /usr/local/lib/kea/hooks/libdhcp_cb_cmds.so successfully closed
00:46:42 [10.53.60.44] out: 2024-12-02 22:54:59.804 INFO [kea-dhcp6.hooks/2524608.139676460767104] HOOKS_LIBRARY_CLOSED hooks library /usr/local/lib/kea/hooks/libdhcp_lease_cmds.so successfully closed
00:46:42 [10.53.60.44] out: 2024-12-02 22:54:59.804 INFO [kea-dhcp6.hooks/2524608.139676460767104] HOOKS_LIBRARY_CLOSED hooks library /usr/local/lib/kea/hooks/libdhcp_host_cmds.so successfully closed
00:46:42 [10.53.60.44] out:
00:46:42
00:46:42 FAILED[31;1m******************* RESULT FAILED #675/931: tests/dhcp/v6/db_upgrade/test_db_mysql_upgrade.py::test_v6_upgrade_mysql_db ********************[0m
Jenkins points to #3652 (closed) as probable cause of regression.