[PBCKP-129] change logging levels verbosity for other commands

.travis.yml

@@ -34,18 +34,18 @@ env:
     - PG_VERSION=10 PG_BRANCH=REL_10_STABLE
     - PG_VERSION=9.6 PG_BRANCH=REL9_6_STABLE
     - PG_VERSION=9.5 PG_BRANCH=REL9_5_STABLE
-#    - PG_VERSION=13 PG_BRANCH=REL_13_STABLE PTRACK_PATCH_PG_BRANCH=off MODE=archive
-#    - PG_VERSION=13 PG_BRANCH=REL_13_STABLE PTRACK_PATCH_PG_BRANCH=REL_13_STABLE MODE=backup
+    - PG_VERSION=13 PG_BRANCH=REL_13_STABLE PTRACK_PATCH_PG_BRANCH=off MODE=archive
+    - PG_VERSION=13 PG_BRANCH=REL_13_STABLE PTRACK_PATCH_PG_BRANCH=REL_13_STABLE MODE=backup
     - PG_VERSION=13 PG_BRANCH=REL_13_STABLE PTRACK_PATCH_PG_BRANCH=REL_13_STABLE MODE=catchup
 #    - PG_VERSION=13 PG_BRANCH=REL_13_STABLE PTRACK_PATCH_PG_BRANCH=off MODE=compression
 #    - PG_VERSION=13 PG_BRANCH=REL_13_STABLE PTRACK_PATCH_PG_BRANCH=off MODE=delta
 #    - PG_VERSION=13 PG_BRANCH=REL_13_STABLE PTRACK_PATCH_PG_BRANCH=off MODE=locking
-#    - PG_VERSION=13 PG_BRANCH=REL_13_STABLE PTRACK_PATCH_PG_BRANCH=REL_13_STABLE MODE=merge
+    - PG_VERSION=13 PG_BRANCH=REL_13_STABLE PTRACK_PATCH_PG_BRANCH=REL_13_STABLE MODE=merge
 #    - PG_VERSION=13 PG_BRANCH=REL_13_STABLE PTRACK_PATCH_PG_BRANCH=off MODE=page
 #    - PG_VERSION=13 PG_BRANCH=REL_13_STABLE PTRACK_PATCH_PG_BRANCH=REL_13_STABLE MODE=ptrack
 #    - PG_VERSION=13 PG_BRANCH=REL_13_STABLE PTRACK_PATCH_PG_BRANCH=REL_13_STABLE MODE=replica
 #    - PG_VERSION=13 PG_BRANCH=REL_13_STABLE PTRACK_PATCH_PG_BRANCH=off MODE=retention
-#    - PG_VERSION=13 PG_BRANCH=REL_13_STABLE PTRACK_PATCH_PG_BRANCH=REL_13_STABLE MODE=restore
+    - PG_VERSION=13 PG_BRANCH=REL_13_STABLE PTRACK_PATCH_PG_BRANCH=REL_13_STABLE MODE=restore
 
 jobs:
     allow_failures:

src/archive.c

@@ -3,7 +3,7 @@
  * archive.c: -  pg_probackup specific archive commands for archive backups.
  *
  *
- * Portions Copyright (c) 2018-2021, Postgres Professional
+ * Portions Copyright (c) 2018-2022, Postgres Professional
  *
  *-------------------------------------------------------------------------
  */
@@ -361,7 +361,7 @@ push_file(WALSegno *xlogfile, const char *archive_status_dir,
 		canonicalize_path(wal_file_ready);
 		canonicalize_path(wal_file_done);
 		/* It is ok to rename status file in archive_status directory */
-		elog(VERBOSE, "Rename \"%s\" to \"%s\"", wal_file_ready, wal_file_done);
+		elog(LOG, "Rename \"%s\" to \"%s\"", wal_file_ready, wal_file_done);
 
 		/* do not error out, if rename failed */
 		if (fio_rename(wal_file_ready, wal_file_done, FIO_DB_HOST) < 0)
@@ -505,7 +505,7 @@ push_file_internal_uncompressed(const char *wal_file_name, const char *pg_xlog_d
 	}
 
 part_opened:
-	elog(VERBOSE, "Temp WAL file successfully created: \"%s\"", to_fullpath_part);
+	elog(LOG, "Temp WAL file successfully created: \"%s\"", to_fullpath_part);
 	/* Check if possible to skip copying */
 	if (fileExists(to_fullpath, FIO_BACKUP_HOST))
 	{
@@ -595,7 +595,7 @@ push_file_internal_uncompressed(const char *wal_file_name, const char *pg_xlog_d
 						to_fullpath_part, strerror(errno));
 	}
 
-	elog(VERBOSE, "Rename \"%s\" to \"%s\"", to_fullpath_part, to_fullpath);
+	elog(LOG, "Rename \"%s\" to \"%s\"", to_fullpath_part, to_fullpath);
 
 	//copy_file_attributes(from_path, FIO_DB_HOST, to_path_temp, FIO_BACKUP_HOST, true);
 
@@ -752,7 +752,7 @@ push_file_internal_gz(const char *wal_file_name, const char *pg_xlog_dir,
 	}
 
 part_opened:
-	elog(VERBOSE, "Temp WAL file successfully created: \"%s\"", to_fullpath_gz_part);
+	elog(LOG, "Temp WAL file successfully created: \"%s\"", to_fullpath_gz_part);
 	/* Check if possible to skip copying,
 	 */
 	if (fileExists(to_fullpath_gz, FIO_BACKUP_HOST))
@@ -844,7 +844,7 @@ push_file_internal_gz(const char *wal_file_name, const char *pg_xlog_dir,
 					to_fullpath_gz_part, strerror(errno));
 	}
 
-	elog(VERBOSE, "Rename \"%s\" to \"%s\"",
+	elog(LOG, "Rename \"%s\" to \"%s\"",
 			to_fullpath_gz_part, to_fullpath_gz);
 
 	//copy_file_attributes(from_path, FIO_DB_HOST, to_path_temp, FIO_BACKUP_HOST, true);
@@ -1155,7 +1155,7 @@ do_archive_get(InstanceState *instanceState, InstanceConfig *instance, const cha
 		if (get_wal_file(wal_file_name, backup_wal_file_path, absolute_wal_file_path, false))
 		{
 			fail_count = 0;
-			elog(INFO, "pg_probackup archive-get copied WAL file %s", wal_file_name);
+			elog(LOG, "pg_probackup archive-get copied WAL file %s", wal_file_name);
 			n_fetched++;
 			break;
 		}
@@ -1511,7 +1511,7 @@ get_wal_file_internal(const char *from_path, const char *to_path, FILE *out,
 	char    *buf = pgut_malloc(OUT_BUF_SIZE); /* 1MB buffer */
 	int      exit_code = 0;
 
-	elog(VERBOSE, "Attempting to %s WAL file '%s'",
+	elog(LOG, "Attempting to %s WAL file '%s'",
 			is_decompress ? "open compressed" : "open", from_path);
 
 	/* open source file for read */

src/backup.c

@@ -3,7 +3,7 @@
  * backup.c: backup DB cluster, archived WAL
  *
  * Portions Copyright (c) 2009-2013, NIPPON TELEGRAPH AND TELEPHONE CORPORATION
- * Portions Copyright (c) 2015-2019, Postgres Professional
+ * Portions Copyright (c) 2015-2022, Postgres Professional
  *
  *-------------------------------------------------------------------------
  */
@@ -116,7 +116,7 @@ do_backup_pg(InstanceState *instanceState, PGconn *backup_conn,
 	char		pretty_time[20];
 	char		pretty_bytes[20];
 
-	elog(LOG, "Database backup start");
+	elog(INFO, "Database backup start");
 	if(current.external_dir_str)
 	{
 		external_dirs = make_external_directory_list(current.external_dir_str,
@@ -336,11 +336,11 @@ do_backup_pg(InstanceState *instanceState, PGconn *backup_conn,
 	/* Extract information about files in backup_list parsing their names:*/
 	parse_filelist_filenames(backup_files_list, instance_config.pgdata);
 
-	elog(LOG, "Current Start LSN: %X/%X, TLI: %X",
+	elog(INFO, "Current Start LSN: %X/%X, TLI: %X",
 			(uint32) (current.start_lsn >> 32), (uint32) (current.start_lsn),
 			current.tli);
 	if (current.backup_mode != BACKUP_MODE_FULL)
-		elog(LOG, "Parent Start LSN: %X/%X, TLI: %X",
+		elog(INFO, "Parent Start LSN: %X/%X, TLI: %X",
 			 (uint32) (prev_backup->start_lsn >> 32), (uint32) (prev_backup->start_lsn),
 			 prev_backup->tli);
 
@@ -412,7 +412,7 @@ do_backup_pg(InstanceState *instanceState, PGconn *backup_conn,
 			else
 				join_path_components(dirpath, current.database_dir, file->rel_path);
 
-			elog(VERBOSE, "Create directory '%s'", dirpath);
+			elog(LOG, "Create directory '%s'", dirpath);
 			fio_mkdir(dirpath, DIR_PERMISSION, FIO_BACKUP_HOST);
 		}
 
@@ -673,7 +673,7 @@ pgdata_basic_setup(ConnectionOptions conn_opt, PGNodeInfo *nodeInfo)
 	nodeInfo->checksum_version = current.checksum_version;
 
 	if (current.checksum_version)
-		elog(LOG, "This PostgreSQL instance was initialized with data block checksums. "
+		elog(INFO, "This PostgreSQL instance was initialized with data block checksums. "
 					"Data block corruption will be detected");
 	else
 		elog(WARNING, "This PostgreSQL instance was initialized without data block checksums. "
@@ -1513,7 +1513,7 @@ wait_wal_and_calculate_stop_lsn(const char *xlog_path, XLogRecPtr stop_lsn, pgBa
 		stop_lsn_exists = true;
 	}
 
-	elog(LOG, "stop_lsn: %X/%X",
+	elog(INFO, "stop_lsn: %X/%X",
 		(uint32) (stop_lsn >> 32), (uint32) (stop_lsn));
 
 	/*
@@ -1902,15 +1902,15 @@ pg_stop_backup(InstanceState *instanceState, pgBackup *backup, PGconn *pg_startb
 
 	backup->recovery_xid = stop_backup_result.snapshot_xid;
 
-	elog(LOG, "Getting the Recovery Time from WAL");
+	elog(INFO, "Getting the Recovery Time from WAL");
 
 	/* iterate over WAL from stop_backup lsn to start_backup lsn */
 	if (!read_recovery_info(xlog_path, backup->tli,
 						instance_config.xlog_seg_size,
 						backup->start_lsn, backup->stop_lsn,
 						&backup->recovery_time))
 	{
-		elog(LOG, "Failed to find Recovery Time in WAL, forced to trust current_timestamp");
+		elog(INFO, "Failed to find Recovery Time in WAL, forced to trust current_timestamp");
 		backup->recovery_time = stop_backup_result.invocation_time;
 	}
 
@@ -1992,9 +1992,8 @@ backup_files(void *arg)
 		if (interrupted || thread_interrupted)
 			elog(ERROR, "interrupted during backup");
 
-		if (progress)
-			elog(INFO, "Progress: (%d/%d). Process file \"%s\"",
-				 i + 1, n_backup_files_list, file->rel_path);
+		elog(progress ? INFO : LOG, "Progress: (%d/%d). Process file \"%s\"",
+			 i + 1, n_backup_files_list, file->rel_path);
 
 		/* Handle zero sized files */
 		if (file->size == 0)
@@ -2064,11 +2063,11 @@ backup_files(void *arg)
 
 		if (file->write_size == BYTES_INVALID)
 		{
-			elog(VERBOSE, "Skipping the unchanged file: \"%s\"", from_fullpath);
+			elog(LOG, "Skipping the unchanged file: \"%s\"", from_fullpath);
 			continue;
 		}
 
-		elog(VERBOSE, "File \"%s\". Copied "INT64_FORMAT " bytes",
+		elog(LOG, "File \"%s\". Copied "INT64_FORMAT " bytes",
 						from_fullpath, file->write_size);
 	}
 
@@ -2186,26 +2185,26 @@ set_cfs_datafiles(parray *files, const char *root, char *relative, size_t i)
 		elog(ERROR, "Out of memory");
 	len = strlen("/pg_compression");
 	cfs_tblspc_path[strlen(cfs_tblspc_path) - len] = 0;
-	elog(VERBOSE, "CFS DIRECTORY %s, pg_compression path: %s", cfs_tblspc_path, relative);
+	elog(LOG, "CFS DIRECTORY %s, pg_compression path: %s", cfs_tblspc_path, relative);
 
 	for (p = (int) i; p >= 0; p--)
 	{
 		prev_file = (pgFile *) parray_get(files, (size_t) p);
 
-		elog(VERBOSE, "Checking file in cfs tablespace %s", prev_file->rel_path);
+		elog(LOG, "Checking file in cfs tablespace %s", prev_file->rel_path);
 
 		if (strstr(prev_file->rel_path, cfs_tblspc_path) != NULL)
 		{
 			if (S_ISREG(prev_file->mode) && prev_file->is_datafile)
 			{
-				elog(VERBOSE, "Setting 'is_cfs' on file %s, name %s",
+				elog(LOG, "Setting 'is_cfs' on file %s, name %s",
 					prev_file->rel_path, prev_file->name);
 				prev_file->is_cfs = true;
 			}
 		}
 		else
 		{
-			elog(VERBOSE, "Breaking on %s", prev_file->rel_path);
+			elog(LOG, "Breaking on %s", prev_file->rel_path);
 			break;
 		}
 	}

src/catchup.c

@@ -398,9 +398,8 @@ catchup_thread_runner(void *arg)
 		if (interrupted || thread_interrupted)
 			elog(ERROR, "Interrupted during catchup");
 
-		if (progress)
-			elog(INFO, "Progress: (%d/%d). Process file \"%s\"",
-				 i + 1, n_files, file->rel_path);
+		elog(progress ? INFO : LOG, "Progress: (%d/%d). Process file \"%s\"",
+			 i + 1, n_files, file->rel_path);
 
 		/* construct destination filepath */
 		Assert(file->external_dir_num == 0);

src/data.c

@@ -793,7 +793,7 @@ backup_non_data_file(pgFile *file, pgFile *prev_file,
 	}
 
 	/*
-	 * If nonedata file exists in previous backup
+	 * If non-data file exists in previous backup
 	 * and its mtime is less than parent backup start time ... */
 	if ((pg_strcasecmp(file->name, RELMAPPER_FILENAME) != 0) &&
 		(prev_file && file->exists_in_prev &&
@@ -1195,7 +1195,7 @@ restore_data_file_internal(FILE *in, FILE *out, pgFile *file, uint32 backup_vers
 			datapagemap_add(map, blknum);
 	}
 
-	elog(VERBOSE, "Copied file \"%s\": %lu bytes", from_fullpath, write_len);
+	elog(LOG, "Copied file \"%s\": %lu bytes", from_fullpath, write_len);
 	return write_len;
 }
 
@@ -1218,7 +1218,7 @@ restore_non_data_file_internal(FILE *in, FILE *out, pgFile *file,
 
 		/* check for interrupt */
 		if (interrupted || thread_interrupted)
-			elog(ERROR, "Interrupted during nonedata file restore");
+			elog(ERROR, "Interrupted during non-data file restore");
 
 		read_len = fread(buf, 1, STDIO_BUFSIZE, in);
 
@@ -1239,7 +1239,7 @@ restore_non_data_file_internal(FILE *in, FILE *out, pgFile *file,
 
 	pg_free(buf);
 
-	elog(VERBOSE, "Copied file \"%s\": %lu bytes", from_fullpath, file->write_size);
+	elog(LOG, "Copied file \"%s\": %lu bytes", from_fullpath, file->write_size);
 }
 
 size_t
@@ -1284,7 +1284,7 @@ restore_non_data_file(parray *parent_chain, pgBackup *dest_backup,
 			 */
 			if (!tmp_file)
 			{
-				elog(ERROR, "Failed to locate nonedata file \"%s\" in backup %s",
+				elog(ERROR, "Failed to locate non-data file \"%s\" in backup %s",
 					dest_file->rel_path, base36enc(tmp_backup->start_time));
 				continue;
 			}
@@ -1309,14 +1309,14 @@ restore_non_data_file(parray *parent_chain, pgBackup *dest_backup,
 
 	/* sanity */
 	if (!tmp_backup)
-		elog(ERROR, "Failed to locate a backup containing full copy of nonedata file \"%s\"",
+		elog(ERROR, "Failed to locate a backup containing full copy of non-data file \"%s\"",
 			to_fullpath);
 
 	if (!tmp_file)
-		elog(ERROR, "Failed to locate a full copy of nonedata file \"%s\"", to_fullpath);
+		elog(ERROR, "Failed to locate a full copy of non-data file \"%s\"", to_fullpath);
 
 	if (tmp_file->write_size <= 0)
-		elog(ERROR, "Full copy of nonedata file has invalid size: %li. "
+		elog(ERROR, "Full copy of non-data file has invalid size: %li. "
 				"Metadata corruption in backup %s in file: \"%s\"",
 				tmp_file->write_size, base36enc(tmp_backup->start_time),
 				to_fullpath);
@@ -1329,7 +1329,7 @@ restore_non_data_file(parray *parent_chain, pgBackup *dest_backup,
 
 		if (file_crc == tmp_file->crc)
 		{
-			elog(VERBOSE, "Already existing nonedata file \"%s\" has the same checksum, skip restore",
+			elog(LOG, "Already existing non-data file \"%s\" has the same checksum, skip restore",
 				to_fullpath);
 			return 0;
 		}
@@ -1357,7 +1357,7 @@ restore_non_data_file(parray *parent_chain, pgBackup *dest_backup,
 		elog(ERROR, "Cannot open backup file \"%s\": %s", from_fullpath,
 			 strerror(errno));
 
-	/* disable stdio buffering for nonedata files */
+	/* disable stdio buffering for non-data files */
 	setvbuf(in, NULL, _IONBF, BUFSIZ);
 
 	/* do actual work */
@@ -1681,7 +1681,7 @@ validate_file_pages(pgFile *file, const char *fullpath, XLogRecPtr stop_lsn,
 	int         n_hdr = -1;
 	off_t       cur_pos_in = 0;
 
-	elog(VERBOSE, "Validate relation blocks for file \"%s\"", fullpath);
+	elog(LOG, "Validate relation blocks for file \"%s\"", fullpath);
 
 	/* should not be possible */
 	Assert(!(backup_version >= 20400 && file->n_headers <= 0));
@@ -1740,7 +1740,7 @@ validate_file_pages(pgFile *file, const char *fullpath, XLogRecPtr stop_lsn,
 					elog(ERROR, "Cannot seek block %u of \"%s\": %s",
 						blknum, fullpath, strerror(errno));
 				else
-					elog(INFO, "Seek to %u", headers[n_hdr].pos);
+					elog(VERBOSE, "Seek to %u", headers[n_hdr].pos);
 
 				cur_pos_in = headers[n_hdr].pos;
 			}
@@ -1764,7 +1764,7 @@ validate_file_pages(pgFile *file, const char *fullpath, XLogRecPtr stop_lsn,
 		/* backward compatibility kludge TODO: remove in 3.0 */
 		if (compressed_size == PageIsTruncated)
 		{
-			elog(INFO, "Block %u of \"%s\" is truncated",
+			elog(VERBOSE, "Block %u of \"%s\" is truncated",
 				 blknum, fullpath);
 			continue;
 		}
@@ -1835,10 +1835,10 @@ validate_file_pages(pgFile *file, const char *fullpath, XLogRecPtr stop_lsn,
 		switch (rc)
 		{
 			case PAGE_IS_NOT_FOUND:
-				elog(LOG, "File \"%s\", block %u, page is NULL", file->rel_path, blknum);
+				elog(VERBOSE, "File \"%s\", block %u, page is NULL", file->rel_path, blknum);
 				break;
 			case PAGE_IS_ZEROED:
-				elog(LOG, "File: %s blknum %u, empty zeroed page", file->rel_path, blknum);
+				elog(VERBOSE, "File: %s blknum %u, empty zeroed page", file->rel_path, blknum);
 				break;
 			case PAGE_HEADER_IS_INVALID:
 				elog(WARNING, "Page header is looking insane: %s, block %i", file->rel_path, blknum);

src/dir.c

@@ -3,7 +3,7 @@
  * dir.c: directory operation utility.
  *
  * Portions Copyright (c) 2009-2013, NIPPON TELEGRAPH AND TELEPHONE CORPORATION
- * Portions Copyright (c) 2015-2019, Postgres Professional
+ * Portions Copyright (c) 2015-2022, Postgres Professional
  *
  *-------------------------------------------------------------------------
  */
@@ -1134,7 +1134,7 @@ create_data_directories(parray *dest_files, const char *data_dir, const char *ba
 
 					join_path_components(to_path, data_dir, dir->rel_path);
 
-					elog(VERBOSE, "Create directory \"%s\" and symbolic link \"%s\"",
+					elog(LOG, "Create directory \"%s\" and symbolic link \"%s\"",
 							 linked_path, to_path);
 
 					/* create tablespace directory */
@@ -1151,7 +1151,7 @@ create_data_directories(parray *dest_files, const char *data_dir, const char *ba
 		}
 
 		/* This is not symlink, create directory */
-		elog(VERBOSE, "Create directory \"%s\"", dir->rel_path);
+		elog(LOG, "Create directory \"%s\"", dir->rel_path);
 
 		join_path_components(to_path, data_dir, dir->rel_path);
 
@@ -1889,7 +1889,7 @@ cleanup_tablespace(const char *path)
 		join_path_components(fullpath, path, file->rel_path);
 
 		fio_delete(file->mode, fullpath, FIO_DB_HOST);
-		elog(VERBOSE, "Deleted file \"%s\"", fullpath);
+		elog(LOG, "Deleted file \"%s\"", fullpath);
 	}
 
 	parray_walk(files, pgFileFree);