From 4c48f4f26323b39078df9be3608b6532833b00b7 Mon Sep 17 00:00:00 2001 From: Camila Ayres Date: Wed, 12 Jun 2024 15:32:01 +0200 Subject: [PATCH 1/3] Add more logs to track file hydration. Signed-off-by: Camila Ayres --- src/libsync/propagatedownload.cpp | 2 +- src/libsync/vfs/cfapi/cfapiwrapper.cpp | 28 +++++++++++++++++++++++--- 2 files changed, 26 insertions(+), 4 deletions(-) diff --git a/src/libsync/propagatedownload.cpp b/src/libsync/propagatedownload.cpp index f3058d8d12b12..a602dacb0d365 100644 --- a/src/libsync/propagatedownload.cpp +++ b/src/libsync/propagatedownload.cpp @@ -332,7 +332,7 @@ void GETFileJob::slotReadyRead() } if (reply()->isFinished() && (reply()->bytesAvailable() == 0 || !_saveBodyToFile)) { - qCDebug(lcGetJob) << "Actually finished!"; + qCDebug(lcGetJob) << "Get file job finished bytesAvailable/_saveBodyToFile:" << reply()->bytesAvailable() << "/" << _saveBodyToFile ; if (_bandwidthManager) { _bandwidthManager->unregisterDownloadJob(this); } diff --git a/src/libsync/vfs/cfapi/cfapiwrapper.cpp b/src/libsync/vfs/cfapi/cfapiwrapper.cpp index 8b16887956944..57707af4cf1e5 100644 --- a/src/libsync/vfs/cfapi/cfapiwrapper.cpp +++ b/src/libsync/vfs/cfapi/cfapiwrapper.cpp @@ -133,6 +133,9 @@ void cfApiSendTransferInfo(const CF_CONNECTION_KEY &connectionKey, const CF_TRAN void CALLBACK cfApiFetchDataCallback(const CF_CALLBACK_INFO *callbackInfo, const CF_CALLBACK_PARAMETERS *callbackParameters) { qDebug(lcCfApiWrapper) << "Fetch data callback called. File size:" << callbackInfo->FileSize.QuadPart; + qDebug(lcCfApiWrapper) << "Fetch data requested by proccess id:" << callbackInfo->ProcessInfo->ProcessId; + qDebug(lcCfApiWrapper) << "Fetch data requested by application id:" << QString(QString::fromWCharArray(callbackInfo->ProcessInfo->ApplicationId)); + const auto sendTransferError = [=] { cfApiSendTransferInfo(callbackInfo->ConnectionKey, callbackInfo->TransferKey, @@ -158,6 +161,8 @@ void CALLBACK cfApiFetchDataCallback(const CF_CALLBACK_INFO *callbackInfo, const const auto path = QString(QString::fromWCharArray(callbackInfo->VolumeDosName) + QString::fromWCharArray(callbackInfo->NormalizedPath)); const auto requestId = QString::number(callbackInfo->TransferKey.QuadPart, 16); + qCDebug(lcCfApiWrapper) << "Request hydration for" << path << requestId; + const auto invokeResult = QMetaObject::invokeMethod(vfs, [=] { vfs->requestHydration(requestId, path); }, Qt::QueuedConnection); if (!invokeResult) { qCCritical(lcCfApiWrapper) << "Failed to trigger hydration for" << path << requestId; @@ -165,26 +170,33 @@ void CALLBACK cfApiFetchDataCallback(const CF_CALLBACK_INFO *callbackInfo, const return; } + qCDebug(lcCfApiWrapper) << "Successfully triggered hydration for" << path << requestId; + // Block and wait for vfs to signal back the hydration is ready bool hydrationRequestResult = false; QEventLoop loop; QObject::connect(vfs, &OCC::VfsCfApi::hydrationRequestReady, &loop, [&](const QString &id) { if (requestId == id) { hydrationRequestResult = true; + qCDebug(lcCfApiWrapper) << "Hydration request ready for" << path << requestId; loop.quit(); } }); QObject::connect(vfs, &OCC::VfsCfApi::hydrationRequestFailed, &loop, [&](const QString &id) { if (requestId == id) { hydrationRequestResult = false; + qCDebug(lcCfApiWrapper) << "Hydration request failed for" << path << requestId; loop.quit(); } }); + + qCDebug(lcCfApiWrapper) << "Starting event loop 1"; loop.exec(); - QObject::disconnect(vfs, nullptr, &loop, nullptr); - qCInfo(lcCfApiWrapper) << "VFS replied for hydration of" << path << requestId << "status was:" << hydrationRequestResult; + QObject::disconnect(vfs, nullptr, &loop, nullptr); // Ensure we properly cancel hydration on server errors + qCInfo(lcCfApiWrapper) << "VFS replied for hydration of" << path << requestId << "status was:" << hydrationRequestResult; if (!hydrationRequestResult) { + qCCritical(lcCfApiWrapper) << "Failed to trigger hydration for" << path << requestId; sendTransferError(); return; } @@ -212,6 +224,7 @@ void CALLBACK cfApiFetchDataCallback(const CF_CALLBACK_INFO *callbackInfo, const auto hydrationRequestCancelled = false; QObject::connect(&signalSocket, &QLocalSocket::readyRead, &loop, [&] { hydrationRequestCancelled = true; + qCCritical(lcCfApiWrapper) << "Hydration canceled for " << path << requestId; }); // CFAPI expects sent blocks to be of a multiple of a block size. @@ -223,17 +236,25 @@ void CALLBACK cfApiFetchDataCallback(const CF_CALLBACK_INFO *callbackInfo, const const auto alignAndSendData = [&](const QByteArray &receivedData) { QByteArray data = protrudingData + receivedData; + qCWarning(lcCfApiWrapper) << "protrudingData + receivedData:" << data; protrudingData.clear(); if (data.size() < cfapiBlockSize) { protrudingData = data; + qCWarning(lcCfApiWrapper) << "protrudingData:" << protrudingData; + sendTransferInfo(data, dataOffset); + dataOffset += data.size(); return; } const auto protudingSize = data.size() % cfapiBlockSize; + qCWarning(lcCfApiWrapper) << "protudingSize:" << protudingSize; protrudingData = data.right(protudingSize); + qCWarning(lcCfApiWrapper) << "data.right(protudingSize):" << protrudingData; data.chop(protudingSize); - + qCWarning(lcCfApiWrapper) << "data.chop(protudingSize)" << data; + qCWarning(lcCfApiWrapper) << "sendTransferInfo(data:" << data << ", dataOffset:" << dataOffset << ")"; sendTransferInfo(data, dataOffset); dataOffset += data.size(); + qCWarning(lcCfApiWrapper) << "dataOffset:" << dataOffset; }; QObject::connect(&socket, &QLocalSocket::readyRead, &loop, [&] { @@ -260,6 +281,7 @@ void CALLBACK cfApiFetchDataCallback(const CF_CALLBACK_INFO *callbackInfo, const } }); + qCDebug(lcCfApiWrapper) << "Starting event loop 2"; loop.exec(); if (!hydrationRequestCancelled && !protrudingData.isEmpty()) { From e69dfe53ae531a478966a3e17991adeb05fd0758 Mon Sep 17 00:00:00 2001 From: Camila Ayres Date: Thu, 13 Jun 2024 19:57:27 +0200 Subject: [PATCH 2/3] Add new cfapi callbacks for logging. Signed-off-by: Camila Ayres --- src/libsync/vfs/cfapi/cfapiwrapper.cpp | 48 ++++++++++++++++++++++++++ 1 file changed, 48 insertions(+) diff --git a/src/libsync/vfs/cfapi/cfapiwrapper.cpp b/src/libsync/vfs/cfapi/cfapiwrapper.cpp index 57707af4cf1e5..6138146532a59 100644 --- a/src/libsync/vfs/cfapi/cfapiwrapper.cpp +++ b/src/libsync/vfs/cfapi/cfapiwrapper.cpp @@ -373,9 +373,57 @@ void CALLBACK cfApiCancelFetchData(const CF_CALLBACK_INFO *callbackInfo, const C } } +void CALLBACK cfApiNotifyFileOpenCompletion(const CF_CALLBACK_INFO *callbackInfo, const CF_CALLBACK_PARAMETERS * /*callbackParameters*/) +{ + const auto path = QString(QString::fromWCharArray(callbackInfo->VolumeDosName) + QString::fromWCharArray(callbackInfo->NormalizedPath)); + + auto vfs = reinterpret_cast(callbackInfo->CallbackContext); + Q_ASSERT(vfs->metaObject()->className() == QByteArrayLiteral("OCC::VfsCfApi")); + const auto requestId = QString::number(callbackInfo->TransferKey.QuadPart, 16); + + qCDebug(lcCfApiWrapper) << "Open file completion:" << path << requestId; +} + +void CALLBACK cfApiValidateData(const CF_CALLBACK_INFO *callbackInfo, const CF_CALLBACK_PARAMETERS * /*callbackParameters*/) +{ + const auto path = QString(QString::fromWCharArray(callbackInfo->VolumeDosName) + QString::fromWCharArray(callbackInfo->NormalizedPath)); + + auto vfs = reinterpret_cast(callbackInfo->CallbackContext); + Q_ASSERT(vfs->metaObject()->className() == QByteArrayLiteral("OCC::VfsCfApi")); + const auto requestId = QString::number(callbackInfo->TransferKey.QuadPart, 16); + + qCDebug(lcCfApiWrapper) << "Validate data:" << path << requestId; +} + +void CALLBACK cfApiCancelFetchPlaceHolders(const CF_CALLBACK_INFO *callbackInfo, const CF_CALLBACK_PARAMETERS * /*callbackParameters*/) +{ + const auto path = QString(QString::fromWCharArray(callbackInfo->VolumeDosName) + QString::fromWCharArray(callbackInfo->NormalizedPath)); + + auto vfs = reinterpret_cast(callbackInfo->CallbackContext); + Q_ASSERT(vfs->metaObject()->className() == QByteArrayLiteral("OCC::VfsCfApi")); + const auto requestId = QString::number(callbackInfo->TransferKey.QuadPart, 16); + + qCDebug(lcCfApiWrapper) << "Cancel fetch placeholder:" << path << requestId; +} + +void CALLBACK cfApiNotifyFileCloseCompletion(const CF_CALLBACK_INFO *callbackInfo, const CF_CALLBACK_PARAMETERS * /*callbackParameters*/) +{ + const auto path = QString(QString::fromWCharArray(callbackInfo->VolumeDosName) + QString::fromWCharArray(callbackInfo->NormalizedPath)); + + auto vfs = reinterpret_cast(callbackInfo->CallbackContext); + Q_ASSERT(vfs->metaObject()->className() == QByteArrayLiteral("OCC::VfsCfApi")); + const auto requestId = QString::number(callbackInfo->TransferKey.QuadPart, 16); + + qCDebug(lcCfApiWrapper) << "Close file completion:" << path << requestId; +} + CF_CALLBACK_REGISTRATION cfApiCallbacks[] = { { CF_CALLBACK_TYPE_FETCH_DATA, cfApiFetchDataCallback }, { CF_CALLBACK_TYPE_CANCEL_FETCH_DATA, cfApiCancelFetchData }, + { CF_CALLBACK_TYPE_NOTIFY_FILE_OPEN_COMPLETION, cfApiNotifyFileOpenCompletion }, + { CF_CALLBACK_TYPE_NOTIFY_FILE_CLOSE_COMPLETION, cfApiNotifyFileCloseCompletion }, + { CF_CALLBACK_TYPE_VALIDATE_DATA, cfApiValidateData }, + { CF_CALLBACK_TYPE_CANCEL_FETCH_PLACEHOLDERS, cfApiCancelFetchPlaceHolders }, CF_CALLBACK_REGISTRATION_END }; From f926f5b9d861345861233f1e67014e5718f748a8 Mon Sep 17 00:00:00 2001 From: Camila Ayres Date: Wed, 19 Jun 2024 16:27:06 +0200 Subject: [PATCH 3/3] Print desktop client process id. Signed-off-by: Camila Ayres --- src/libsync/vfs/cfapi/cfapiwrapper.cpp | 1 + 1 file changed, 1 insertion(+) diff --git a/src/libsync/vfs/cfapi/cfapiwrapper.cpp b/src/libsync/vfs/cfapi/cfapiwrapper.cpp index 6138146532a59..7dcedcff422de 100644 --- a/src/libsync/vfs/cfapi/cfapiwrapper.cpp +++ b/src/libsync/vfs/cfapi/cfapiwrapper.cpp @@ -133,6 +133,7 @@ void cfApiSendTransferInfo(const CF_CONNECTION_KEY &connectionKey, const CF_TRAN void CALLBACK cfApiFetchDataCallback(const CF_CALLBACK_INFO *callbackInfo, const CF_CALLBACK_PARAMETERS *callbackParameters) { qDebug(lcCfApiWrapper) << "Fetch data callback called. File size:" << callbackInfo->FileSize.QuadPart; + qDebug(lcCfApiWrapper) << "Desktop client proccess id:" << QCoreApplication::applicationPid(); qDebug(lcCfApiWrapper) << "Fetch data requested by proccess id:" << callbackInfo->ProcessInfo->ProcessId; qDebug(lcCfApiWrapper) << "Fetch data requested by application id:" << QString(QString::fromWCharArray(callbackInfo->ProcessInfo->ApplicationId));