Automated dumps include generated column values

[dabico]

First observed in #124

The backups we automate through a dedicated service create dumps including the values of generated columns. Since we only use these types of columns in git_repo_metric, the dump will work up until those values need to be inserted, at which point the import process will raise an error. Not sure what exactly is causing this, since using the same configurations to dump manually does not lead to such an outcome. I'll take a look at the debug log of the backup service and see if that yields any insights.

[dabico]

Log of the last backup run:

2023-08-15.00:00:00 [DEBUG] /etc/services.available/10-db-backup/run ** [db-backup] Backup routines started time: 2023-08-15 00:00:00 UTC
+ case "${dbtype,,}" in
+ check_availability
+ var_false FALSE
+ '[' false = false ']'
+ case "$dbtype" in
+ counter=0
+ transform_file_var DB_PASS
+ local variables
++ echo DB_PASS
++ tr ' ' '\n'
+ variables=DB_PASS
+ for variable in $variables
+ '[' -v DB_PASS_FILE ']'
+ unset file_variable
+ unset variables
+ export MYSQL_PWD=Lugano2020
+ MYSQL_PWD=Lugano2020
+ mysqladmin -ugseadmin -P3306 -hgse-database status
+ backup_mysql
+ var_true TRUE
+ '[' true = true ']'
+ single_transaction=--single-transaction
+ var_true TRUE
+ '[' true = true ']'
+ stored_procedures=--routines
+ '[' gse = all ']'
++ echo gse
++ tr , '\n'
+ db_names=gse
++ echo gse
++ xargs
++ tr ' ' ,
+ print_debug 'Databases Found: gse'
+ output_off
+ '[' true = true ']'
+ set +x
2023-08-15.00:00:00 [DEBUG] /etc/services.available/10-db-backup/run ** [db-backup] Databases Found: gse
+ var_true false
+ '[' false = true ']'
+ '[' false = yes ']'
+ print_debug 'Not splitting database dumps into their own files'
+ output_off
+ '[' true = true ']'
+ set +x
2023-08-15.00:00:00 [DEBUG] /etc/services.available/10-db-backup/run ** [db-backup] Not splitting database dumps into their own files
+ prepare_dbbackup
++ date +%s
+ dbbackup_start_time=1692057600
++ date +%Y%m%d-%H%M%S
+ now=20230815-000000
++ date +%H:%M:%S
+ now_time=00:00:00
++ date +%Y-%m-%d
+ now_date=2023-08-15
+ ltarget=mysql_gse_gse-database
+ target=mysql_gse_gse-database_20230815-000000.sql
+ target=mysql_all_gse-database_20230815-000000.sql
+ ltarget=mysql_all_gse-database
+ compression
+ var_false TRUE
+ '[' true = false ']'
+ '[' true = no ']'
+ var_true ''
+ '[' '' = true ']'
+ '[' '' = yes ']'
+ case "${COMPRESSION,,}" in
+ compress_cmd='pigz -q -3 -p 256 '
+ compression_type=gzip
+ extension=.gz
+ dir_compress_cmd='pigz -q -3 -p 256 '
+ target_dir=mysql_all_gse-database_20230815-000000.sql
+ target=mysql_all_gse-database_20230815-000000.sql.gz
+ case "${CONTAINER_LOG_LEVEL,,}" in
+ '[' gzip = none ']'
+ compression_string='and compressing with '\''gzip:3'\'' with '\''256'\'' threads'
+ pre_dbbackup all
+ '[' -n '' ']'
+ '[' -d /assets/custom-scripts/pre ']'
+ '[' -d /assets/scripts/pre/ ']'
++ echo gse
++ xargs
++ tr ' ' ,
+ print_notice 'Dumping all MySQL / MariaDB databases: '\''gse'\'' and compressing with '\''gzip:3'\'' with '\''256'\'' threads'
+ output_off
+ '[' true = true ']'
+ set +x
2023-08-15.00:00:00 [NOTICE] /etc/services.available/10-db-backup/run ** [db-backup] Dumping all MySQL / MariaDB databases: 'gse' and compressing with 'gzip:3' with '256' threads
+ pigz -q -3 -p 256
++ echo gse
++ xargs
+ mysqldump --max-allowed-packet=512M -h gse-database -P 3306 -ugseadmin --single-transaction --routines --databases gse
mysqldump: Error: 'Access denied; you need (at least one of) the PROCESS privilege(s) for this operation' when trying to dump tablespaces
+ exit_code=0
+ check_exit_code mysql_all_gse-database_20230815-000000.sql.gz
+ print_debug 'DB Backup Exit Code is 0'
+ output_off
+ '[' true = true ']'
+ set +x
2023-08-15.00:00:47 [DEBUG] /etc/services.available/10-db-backup/run ** [db-backup] DB Backup Exit Code is 0
+ case "${1}" in
+ case "${exit_code}" in
+ print_info 'DB Backup of '\''mysql_all_gse-database_20230815-000000.sql.gz'\'' completed successfully'
+ output_off
+ '[' true = true ']'
+ set +x
2023-08-15.00:00:47 [INFO] /etc/services.available/10-db-backup/run ** [db-backup] DB Backup of 'mysql_all_gse-database_20230815-000000.sql.gz' completed successfully
+ generate_checksum
+ var_true TRUE
+ '[' true = true ']'
+ '[' 0 = 0 ']'
+ case "${CHECKSUM,,}" in
+ checksum_command=sha1sum
+ checksum_extension=sha1
+ print_notice 'Generating SHA1 for '\''mysql_all_gse-database_20230815-000000.sql.gz'\'''
+ output_off
+ '[' true = true ']'
+ set +x
2023-08-15.00:00:47 [NOTICE] /etc/services.available/10-db-backup/run ** [db-backup] Generating SHA1 for 'mysql_all_gse-database_20230815-000000.sql.gz'
+ cd /tmp/backups
+ sha1sum mysql_all_gse-database_20230815-000000.sql.gz
++ sha1sum mysql_all_gse-database_20230815-000000.sql.gz
++ awk ' { print $1}'
+ checksum_value=be21170bc111b1a94deecd6b7323a49e55ba068e
+ print_debug 'SHA1: be21170bc111b1a94deecd6b7323a49e55ba068e - mysql_all_gse-database_20230815-000000.sql.gz'
+ output_off
+ '[' true = true ']'
+ set +x
2023-08-15.00:00:49 [DEBUG] /etc/services.available/10-db-backup/run ** [db-backup] SHA1: be21170bc111b1a94deecd6b7323a49e55ba068e - mysql_all_gse-database_20230815-000000.sql.gz
+ move_dbbackup
+ '[' 0 = 0 ']'
++ stat -c%s /tmp/backups/mysql_all_gse-database_20230815-000000.sql.gz
+ dbbackup_size=310764108
++ date -r /tmp/backups/mysql_all_gse-database_20230815-000000.sql.gz +%s
+ dbbackup_date=1692057647
+ case "${SIZE_VALUE,,}" in
+ SIZE_VALUE=1
+ '[' 1 = 1 ']'
++ stat -c%s /tmp/backups/mysql_all_gse-database_20230815-000000.sql.gz
+ filesize=310764108
+ print_notice 'Backup of mysql_all_gse-database_20230815-000000.sql.gz created with the size of 310764108 bytes'
+ output_off
+ '[' true = true ']'
+ set +x
2023-08-15.00:00:49 [NOTICE] /etc/services.available/10-db-backup/run ** [db-backup] Backup of mysql_all_gse-database_20230815-000000.sql.gz created with the size of 310764108 bytes
+ case "${BACKUP_LOCATION,,}" in
+ print_debug 'Moving backup to filesystem'
+ output_off
+ '[' true = true ']'
+ set +x
2023-08-15.00:00:49 [DEBUG] /etc/services.available/10-db-backup/run ** [db-backup] Moving backup to filesystem
+ mkdir -p /backup
+ mv /tmp/backups/mysql_all_gse-database_20230815-000000.sql.gz.sha1 /backup/
+ mv /tmp/backups/mysql_all_gse-database_20230815-000000.sql.gz /backup/mysql_all_gse-database_20230815-000000.sql.gz
+ move_exit_code=0
+ var_true TRUE
+ '[' true = true ']'
+ ln -sf /backup/mysql_all_gse-database_20230815-000000.sql.gz /backup/latest-mysql_all_gse-database
+ '[' -n '' ']'
+ rm -rf /tmp/backups/-transfer.log
+ check_exit_code move mysql_all_gse-database_20230815-000000.sql.gz
+ print_debug 'DB Backup Exit Code is 0'
+ output_off
+ '[' true = true ']'
+ set +x
2023-08-15.00:00:49 [DEBUG] /etc/services.available/10-db-backup/run ** [db-backup] DB Backup Exit Code is 0
+ case "${1}" in
+ case "${move_exit_code}" in
+ print_debug 'Moving of backup '\''mysql_all_gse-database_20230815-000000.sql.gz'\'' completed successfully'
+ output_off
+ '[' true = true ']'
+ set +x
2023-08-15.00:00:49 [DEBUG] /etc/services.available/10-db-backup/run ** [db-backup] Moving of backup 'mysql_all_gse-database_20230815-000000.sql.gz' completed successfully
+ case "${exit_code}" in
+ print_info 'DB Backup of '\''move'\'' completed successfully'
+ output_off
+ '[' true = true ']'
+ set +x
2023-08-15.00:00:49 [INFO] /etc/services.available/10-db-backup/run ** [db-backup] DB Backup of 'move' completed successfully
+ post_dbbackup all
++ date +%s
+ dbbackup_finish_time=1692057649
++ echo 49
+ dbbackup_total_time=49
+ var_true false
+ '[' false = true ']'
+ '[' false = yes ']'
+ '[' -n '' ']'
+ '[' -d /assets/custom-scripts/ ']'
+ '[' -d /assets/scripts/post/ ']'
+ dir_notempty /assets/scripts/post/
++ ls -A /assets/scripts/post/
+ '[' -n '.keep
.upload-dump.sh' ']'
++ find /assets/scripts/post/ -name '*.sh' -type f
+ for f in $(find ${SCRIPT_LOCATION_POST} -name \*.sh -type f)
+ var_true ''
+ '[' '' = true ']'
+ '[' '' = yes ']'
+ '[' -x /assets/scripts/post/.upload-dump.sh ']'
+ print_notice 'Executing post backup custom script : '\''/assets/scripts/post/.upload-dump.sh'\'''
+ output_off
+ '[' true = true ']'
+ set +x
2023-08-15.00:00:49 [NOTICE] /etc/services.available/10-db-backup/run ** [db-backup] Executing post backup custom script : '/assets/scripts/post/.upload-dump.sh'
+ /assets/scripts/post/.upload-dump.sh 0 mysql gse-database all 1692057600 1692057649 49 mysql_all_gse-database_20230815-000000.sql.gz 310764108 be21170bc111b1a94deecd6b7323a49e55ba068e 0
Compressing database backups into single archive...
tar: removing leading '/' from member names
backup/latest-mysql_all_gse-database
backup/mysql_all_gse-database_20230808-000001.sql.gz
backup/mysql_all_gse-database_20230808-000001.sql.gz.sha1
backup/mysql_all_gse-database_20230809-000001.sql.gz
backup/mysql_all_gse-database_20230809-000001.sql.gz.sha1
backup/mysql_all_gse-database_20230810-000001.sql.gz
backup/mysql_all_gse-database_20230810-000001.sql.gz.sha1
backup/mysql_all_gse-database_20230811-000001.sql.gz
backup/mysql_all_gse-database_20230811-000001.sql.gz.sha1
backup/mysql_all_gse-database_20230812-000001.sql.gz
backup/mysql_all_gse-database_20230812-000001.sql.gz.sha1
backup/mysql_all_gse-database_20230813-000000.sql.gz
backup/mysql_all_gse-database_20230813-000000.sql.gz.sha1
backup/mysql_all_gse-database_20230814-000001.sql.gz
backup/mysql_all_gse-database_20230814-000001.sql.gz.sha1
backup/mysql_all_gse-database_20230815-000000.sql.gz
backup/mysql_all_gse-database_20230815-000000.sql.gz.sha1
Uploading database backups to bar.si.usi.ch... Done!
Performing post-transfer cleanup... Done!
++ echo 49
++ awk '{printf "Hours: %d Minutes: %02d Seconds: %02d", $1/3600, ($1/60)%60, $1%60}'
+ print_notice 'DB Backup for '\''all'\'' time taken: Hours: 0 Minutes: 00 Seconds: 49'
+ output_off
+ '[' true = true ']'
+ set +x
2023-08-15.00:02:43 [NOTICE] /etc/services.available/10-db-backup/run ** [db-backup] DB Backup for 'all' time taken: Hours: 0 Minutes: 00 Seconds: 49
+ unset s3_ssl
+ unset s3_ca_cert
++ date +%s
+ backup_finish_time=1692057763
++ echo 163
+ backup_total_time=163
+ '[' -z 0 ']'
++ date -d @1692057763 '+%Y-%m-%d %T %Z'
+ print_info 'Backup routines finish time: 2023-08-15 00:02:43 UTC with overall exit code 0'
+ output_off
+ '[' true = true ']'
+ set +x
2023-08-15.00:02:43 [INFO] /etc/services.available/10-db-backup/run ** [db-backup] Backup routines finish time: 2023-08-15 00:02:43 UTC with overall exit code 0
++ echo 163
++ awk '{printf "Hours: %d Minutes: %02d Seconds: %02d", $1/3600, ($1/60)%60, $1%60}'
+ print_notice 'Backup routines time taken: Hours: 0 Minutes: 02 Seconds: 43'
+ output_off
+ '[' true = true ']'
+ set +x
2023-08-15.00:02:43 [NOTICE] /etc/services.available/10-db-backup/run ** [db-backup] Backup routines time taken: Hours: 0 Minutes: 02 Seconds: 43
+ cleanup_old_data
+ '[' -n 10080 ']'
+ '[' 0 '!=' 1 ']'
+ case "${BACKUP_LOCATION,,}" in
+ print_info 'Cleaning up old backups on filesystem'
+ output_off
+ '[' true = true ']'
+ set +x
2023-08-15.00:02:43 [INFO] /etc/services.available/10-db-backup/run ** [db-backup] Cleaning up old backups on filesystem
+ mkdir -p /backup
+ find /backup/ -mmin +10080 -iname '*' -exec rm '{}' ';'
+ var_true ''
+ '[' '' = true ']'
+ '[' '' = yes ']'
+++ date +%s
++ date -d@1692144000 '+%Y-%m-%d %T %Z'
+ print_notice 'Sleeping for another 86237 seconds. Waking up at 2023-08-16 00:00:00 UTC '
+ output_off
+ '[' true = true ']'
+ set +x
2023-08-15.00:02:43 [NOTICE] /etc/services.available/10-db-backup/run ** [db-backup] Sleeping for another 86237 seconds. Waking up at 2023-08-16 00:00:00 UTC 
+ sleep 86237

Still not exactly sure where the problem is.

[dabico]

I've just now confirmed that this is an issue with MariaDB, which a lot of these automated database backup images use. See: databacker/mysql-backup#105