Skip to content

PSMDB-810 improve logging #695

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Draft
wants to merge 3 commits into
base: v4.2
Choose a base branch
from
Draft

PSMDB-810 improve logging #695

Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
598a093
PSMDB-810 explicitly close destination file to avoid error swallowing
igorsol Feb 12, 2021
bec98c3
PSMDB-810 output more information in case of exception while copying
igorsol Feb 12, 2021
3dd2a6e
PSMDB-810 log more info during hot backup
igorsol Feb 14, 2021
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
32 changes: 29 additions & 3 deletions src/mongo/db/storage/wiredtiger/wiredtiger_kv_engine.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -1491,6 +1491,8 @@ static void copy_file_size(const boost::filesystem::path& srcFile, const boost::
dst.write(bufptr, cnt);
fsize -= cnt;
}

dst.close();
Copy link
Preview

Copilot AI Aug 19, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The dst.close() call is redundant and potentially problematic. The ofstream destructor will automatically close the file when the function exits, and calling close() explicitly here could mask exceptions that occur during the write operations since close() is called outside the try-catch block that handles the file operations.

Suggested change
dst.close();

Copilot uses AI. Check for mistakes.

}

Status WiredTigerKVEngine::_hotBackupPopulateLists(OperationContext* opCtx, const std::string& path, std::vector<DBTuple>& dbList, std::vector<FileTuple>& filesList) {
Expand Down Expand Up @@ -2062,11 +2064,20 @@ Status WiredTigerKVEngine::hotBackup(OperationContext* opCtx, const std::string&
std::set<fs::path> existDirs{destPath};

// Do copy files
int fcCtr = 0;
for (auto&& file : filesList) {
fs::path srcFile{std::get<0>(file)};
fs::path destFile{std::get<1>(file)};
auto fsize{std::get<2>(file)};

log() << "Beginning copy of {}/{} files in backup snapshot: {}, {} bytes"_format(
++fcCtr, filesList.size(), srcFile.string(), fsize);
Copy link
Preview

Copilot AI Aug 19, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

[nitpick] Logging every file copy operation could generate excessive log output for large backups with many files. Consider using a higher log level (e.g., debug) or throttling the logging to only show progress at intervals (e.g., every 100 files or every 10%).

Suggested change
++fcCtr, filesList.size(), srcFile.string(), fsize);
LOG(1) << "Beginning copy of " << (fcCtr + 1) << "/" << filesList.size()
<< " files in backup snapshot: " << srcFile.string() << ", " << fsize << " bytes";
if ((fcCtr % 100 == 0) || (fcCtr + 1 == filesList.size())) {
log() << "Backup progress: copying file " << (fcCtr + 1) << " of " << filesList.size();
}
++fcCtr;

Copilot uses AI. Check for mistakes.

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can you focus on improving log messages so they are more user / support friendly?

if (!fs::exists(srcFile)) {
log() << "Source file does not exist: {}"_format(srcFile.string());
} else {
log() << "Source file size is: {} bytes"_format(fs::file_size(srcFile));
Copy link
Preview

Copilot AI Aug 19, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The fs::file_size() call can throw an exception if the file doesn't exist or there are permission issues, but it's not wrapped in a try-catch block. This could cause the backup operation to fail unexpectedly. Consider wrapping this call in a try-catch block or checking file existence first.

Suggested change
log() << "Source file size is: {} bytes"_format(fs::file_size(srcFile));
try {
log() << "Source file size is: {} bytes"_format(fs::file_size(srcFile));
} catch (const fs::filesystem_error& ex) {
log() << "Could not get source file size for '{}': {}"_format(srcFile.string(), ex.what());
}

Copilot uses AI. Check for mistakes.

}

Comment on lines +2077 to +2080
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
} else {
log() << "Source file size is: {} bytes"_format(fs::file_size(srcFile));
}
}

Truncating the byte size log line from here because the preceding edit suggestion would include it there.

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

My idea was to show current size of the file. It may be different from the size reported in another message (that size is captured when file list is generated)

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks for catching the fcCtr increment bug.

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Regarding showing the size of the file it is true, it might become notably bigger during the backup. And that is so interesting to DBAs worried about file size growth that I first drafted an edit where it would warn() (not log) if the file size had grown (> +10% && > +100MB).

I don't think it's helpful for users to just be informed what the size is if it is not the same size as what is copied. I think they will see it as an error and report it.

But then I discarded that draft because the $backupCursor work will probably require us doing this all again, didn't seem worthwhile now.

try {
// Try creating destination directories if needed.
const fs::path destDir(destFile.parent_path());
Expand All @@ -2079,11 +2090,26 @@ Status WiredTigerKVEngine::hotBackup(OperationContext* opCtx, const std::string&
// more fine-grained copy
copy_file_size(srcFile, destFile, fsize);
} catch (const fs::filesystem_error& ex) {
return Status(ErrorCodes::InvalidPath, ex.what());
return Status(ErrorCodes::InvalidPath,
"filesystem_error while copying '{}' to '{}': ({}/{}): {}"_format(
srcFile.string(),
destFile.string(),
ex.code().value(),
ex.code().message(),
ex.what()));
} catch (const std::system_error& ex) {
return Status(
ErrorCodes::InternalError,
"system_error while copying '{}' to '{}': ({}/{}): {}"_format(srcFile.string(),
destFile.string(),
ex.code().value(),
ex.code().message(),
ex.what()));
} catch (const std::exception& ex) {
return Status(ErrorCodes::InternalError, ex.what());
return Status(ErrorCodes::InternalError,
"exception while copying '{}' to '{}': {}"_format(
srcFile.string(), destFile.string(), ex.what()));
}

}

return Status::OK();
Expand Down