diff --git a/app/multi-tenant/central-space/cap-js-incidents-app/mta.yaml b/app/multi-tenant/central-space/cap-js-incidents-app/mta.yaml index 831f3a69..491acdc2 100644 --- a/app/multi-tenant/central-space/cap-js-incidents-app/mta.yaml +++ b/app/multi-tenant/central-space/cap-js-incidents-app/mta.yaml @@ -12,6 +12,7 @@ modules: readiness-health-check-http-endpoint: /health properties: REPOSITORY_ID: REPLACE_WITH_YOUR_REPOSITORY_ID + CDS_LOG_LEVELS_SDM: info INCOMING_REQUEST_TIMEOUT: 3600000 INCOMING_SESSION_TIMEOUT: 3600000 INCOMING_CONNECTION_TIMEOUT: 3600000 diff --git a/app/multi-tenant/personal-space/cap-js-incidents-app/mta.yaml b/app/multi-tenant/personal-space/cap-js-incidents-app/mta.yaml index 947d1b76..b035dded 100644 --- a/app/multi-tenant/personal-space/cap-js-incidents-app/mta.yaml +++ b/app/multi-tenant/personal-space/cap-js-incidents-app/mta.yaml @@ -12,6 +12,7 @@ modules: readiness-health-check-http-endpoint: /health properties: REPOSITORY_ID: REPLACE_WITH_YOUR_REPOSITORY_ID + CDS_LOG_LEVELS_SDM: info INCOMING_REQUEST_TIMEOUT: 3600000 INCOMING_SESSION_TIMEOUT: 3600000 INCOMING_CONNECTION_TIMEOUT: 3600000 diff --git a/app/single-tenant/central-space/incidents-app/mta.yaml b/app/single-tenant/central-space/incidents-app/mta.yaml index 5d6b4cf6..e2c4ef74 100644 --- a/app/single-tenant/central-space/incidents-app/mta.yaml +++ b/app/single-tenant/central-space/incidents-app/mta.yaml @@ -19,6 +19,7 @@ modules: buildpack: nodejs_buildpack properties: REPOSITORY_ID: REPLACE_WITH_YOUR_REPOSITORY_ID + CDS_LOG_LEVELS_SDM: info INCOMING_REQUEST_TIMEOUT: 3600000 INCOMING_SESSION_TIMEOUT: 3600000 INCOMING_CONNECTION_TIMEOUT: 3600000 diff --git a/app/single-tenant/personal-space/incidents-app/mta.yaml b/app/single-tenant/personal-space/incidents-app/mta.yaml index 494c95fe..baba3981 100644 --- a/app/single-tenant/personal-space/incidents-app/mta.yaml +++ b/app/single-tenant/personal-space/incidents-app/mta.yaml @@ -19,6 +19,7 @@ modules: buildpack: nodejs_buildpack properties: REPOSITORY_ID: ${REPOSITORY_ID} + CDS_LOG_LEVELS_SDM: info INCOMING_REQUEST_TIMEOUT: 3600000 INCOMING_SESSION_TIMEOUT: 3600000 INCOMING_CONNECTION_TIMEOUT: 3600000 diff --git a/lib/ReadAheadStream.js b/lib/ReadAheadStream.js index eb86ed10..0c94ab27 100644 --- a/lib/ReadAheadStream.js +++ b/lib/ReadAheadStream.js @@ -1,4 +1,7 @@ const { EventEmitter } = require('events'); +const cds = require('@sap/cds/lib'); + +const LOG = cds.log('sdm'); /** * ReadAheadStream wraps a source stream and reads chunks into a bounded queue @@ -30,7 +33,7 @@ class ReadAheadStream extends EventEmitter { this.readPromise = null; this.maxRetries = 5; - console.log('[ReadAheadStream] Initializing read-ahead stream for large file upload'); + LOG.info('[INFO] [ReadAheadStream] Initializing read-ahead stream for large file upload'); } /** @@ -75,7 +78,7 @@ class ReadAheadStream extends EventEmitter { offset = end; } this.lastChunkLoaded = true; - console.log('[ReadAheadStream] Last chunk successfully queued and marked (Buffer path).'); + LOG.debug('[DEBUG] [ReadAheadStream] Last chunk successfully queued and marked (Buffer path).'); return; } @@ -102,16 +105,16 @@ class ReadAheadStream extends EventEmitter { if (this.totalBytesRead >= this.totalSize) { this.lastChunkLoaded = true; - console.log('[ReadAheadStream] Last chunk successfully queued and marked.'); + LOG.debug('[DEBUG] [ReadAheadStream] Last chunk successfully queued and marked.'); break; } } else { - console.warn('[ReadAheadStream] No bytes read from stream. Possible EOF.'); + LOG.warn('[WARN] [ReadAheadStream] No bytes read from stream. Possible EOF.'); break; } } } catch (error) { - console.error('[ReadAheadStream] Unexpected exception during background loading', error); + LOG.error('[FATAL] [ReadAheadStream] Unexpected exception during background loading', error); this.readError = error; // Do NOT emit('error') — if there are no listeners Node.js throws an // uncaught exception and crashes the process. Callers poll readError @@ -153,7 +156,7 @@ class ReadAheadStream extends EventEmitter { throw new Error(`Failed to read chunk after ${this.maxRetries} retries: ${error.message}`); } const delayMs = Math.pow(2, retryCount) * 1000; // 2s, 4s, 8s, 16s, 32s - console.log(`[ReadAheadStream] Retry ${retryCount} in ${delayMs / 1000}s: ${error.message}`); + LOG.warn(`[WARN] [ReadAheadStream] Retry ${retryCount} in ${delayMs / 1000}s: ${error.message}`); await this._sleep(delayMs); } else { throw error; @@ -257,7 +260,7 @@ class ReadAheadStream extends EventEmitter { const last = await this._pollQueue(2000); if (last !== null) return last; } - console.error('[ReadAheadStream] No last chunk found in queue. Returning empty.'); + LOG.error('[ERROR] [ReadAheadStream] No last chunk found in queue. Returning empty.'); return Buffer.allocUnsafe(0); } @@ -354,7 +357,7 @@ class ReadAheadStream extends EventEmitter { new Promise(resolve => setTimeout(() => resolve(TIMEOUT), 5000).unref()) ]); if (result === TIMEOUT) { - console.error('[ReadAheadStream] Forcing stream shutdown after timeout'); + LOG.warn('[WARN] [ReadAheadStream] Forcing stream shutdown after timeout'); this.lastChunkLoaded = true; } } diff --git a/lib/handler/index.js b/lib/handler/index.js index 7b97c532..d983604e 100644 --- a/lib/handler/index.js +++ b/lib/handler/index.js @@ -3,9 +3,12 @@ const FormData = require("form-data"); const { errorMessage, updateAttachmentError, unsupportedProperties } = require("../util/messageConsts"); const NodeCache = require("node-cache"); const cache = new NodeCache({ stdTTL: 3600 }); +const cds = require('@sap/cds'); const { executeHttpRequest } = require('@sap-cloud-sdk/http-client'); const ReadAheadStream = require('../ReadAheadStream'); +const LOG = cds.log('sdm'); + const CHUNK_SIZE = 20 * 1024 * 1024; // 20 MB per chunk const FILE_SIZE_THRESHOLD = 400 * 1024 * 1024; // switch to chunked above 400 MB const CLEANUP_MAX_RETRIES = 3; // delete retries on upload failure @@ -21,6 +24,7 @@ async function readAttachment(Key, destination, credentials) { "/root?objectID=" + Key + "&cmisselector=content"; + LOG.debug(`[DEBUG] [readAttachment] objectId=${Key} repositoryId=${repositoryId}`); try { const response = await executeHttpRequest( destination, { @@ -35,6 +39,7 @@ async function readAttachment(Key, destination, credentials) { if (error.response?.statusText) { statusText = error.response.statusText; } + LOG.error(`[ERROR] [readAttachment] Failed objectId=${Key} status=${error.response?.status || 'unknown'} message=${statusText}`); return statusText; } } @@ -48,6 +53,7 @@ async function getRepositoryInfo(req, credentials, destination) { "browser/" + repositoryId + "?cmisselector=repositoryInfo"; + LOG.debug(`[DEBUG] [getRepositoryInfo] repositoryId=${repositoryId}`); try { const response = await executeHttpRequest( destination, { @@ -58,9 +64,11 @@ async function getRepositoryInfo(req, credentials, destination) { return response; } catch (error) { if (error.response?.status === 404) { + LOG.error(`[ERROR] [getRepositoryInfo] Repository not found repositoryId=${repositoryId}`); req.reject(404, "Failed to get repository info"); } else if (error.response?.status === 500) { + LOG.error(`[ERROR] [getRepositoryInfo] Server error repositoryId=${repositoryId} message=${error.response.data?.message}`); req.reject(500, error.response.data?.message); } throw new Error(error); @@ -78,6 +86,7 @@ async function getFolderIdByPath(req, credentials, attachments, upId, destinatio "/root/" + entityId + "?cmisselector=object"; + LOG.debug(`[DEBUG] [getFolderIdByPath] entityId=${entityId} repositoryId=${repositoryId}`); try { const response = await executeHttpRequest( destination, { @@ -87,6 +96,7 @@ async function getFolderIdByPath(req, credentials, attachments, upId, destinatio ); return response.data.properties["cmis:objectId"].value; } catch { + LOG.debug(`[DEBUG] [getFolderIdByPath] Folder not found for entityId=${entityId}`); return null; } } @@ -102,6 +112,7 @@ async function getFolderIdByIDAsPath(req, credentials, destination, attachments) "/root/" + req.data[idValue] + "?cmisselector=object"; + LOG.debug(`[DEBUG] [getFolderIdByIDAsPath] idValue=${req.data[idValue]} repositoryId=${repositoryId}`); try { const response = await executeHttpRequest( destination, { @@ -111,6 +122,7 @@ async function getFolderIdByIDAsPath(req, credentials, destination, attachments) ); return response.data.properties["cmis:objectId"].value; } catch { + LOG.debug(`[DEBUG] [getFolderIdByIDAsPath] Folder not found for id=${req.data[idValue]}`); return null; } } @@ -124,6 +136,7 @@ async function createFolder(req, credentials, attachments, customFolderName, des formData.append("propertyId[0]", "cmis:name"); // Use customFolderName if provided, otherwise fall back to req.data[upID] const folderName = req.data[upID] || customFolderName; + LOG.info(`[INFO] [createFolder] Creating folder name=${folderName} repositoryId=${repositoryId}`); formData.append("propertyValue[0]", folderName); formData.append("propertyId[1]", "cmis:objectTypeId"); formData.append("propertyValue[1]", "cmis:folder"); @@ -155,13 +168,16 @@ async function createAttachment(data, credentials, parentId, destination) { ? data.contentLength : getContentLength(data.content); - console.log(`[createAttachment] filename=${data.filename} totalSize=${totalSize} threshold=${FILE_SIZE_THRESHOLD}`); + LOG.debug(`[DEBUG] [createAttachment] repositoryId=${repositoryId} parentId=${parentId}`); + LOG.info(`[INFO] [createAttachment] filename=${data.filename} totalSize=${totalSize} threshold=${FILE_SIZE_THRESHOLD}`); if (totalSize > FILE_SIZE_THRESHOLD) { - console.log(`[createAttachment] Large file detected (${totalSize} bytes). Using chunked upload.`); + LOG.info(`[INFO] [createAttachment] Large file detected (${totalSize} bytes). Using chunked upload.`); return uploadLargeFileInChunks(data, credentials, parentId, repositoryId, destination, totalSize); } + LOG.info(`[INFO] [createAttachment] Using single-chunk upload for ${data.filename}`); + return uploadSingleChunk(data, credentials, parentId, repositoryId, destination); } @@ -202,7 +218,9 @@ async function uploadSingleChunk(data, credentials, parentId, repositoryId, dest url: documentCreateURL, data: formData, }); + LOG.info(`[INFO] [uploadSingleChunk] Upload completed filename=${data.filename} status=${response.status}`); } catch (error) { + LOG.error(`[ERROR] [uploadSingleChunk] Upload failed filename=${data.filename} status=${error.response?.status || 500} message=${error.response?.data?.message || error.message}`); response = error; } return response; @@ -213,7 +231,7 @@ async function uploadSingleChunk(data, credentials, parentId, repositoryId, dest * Returns the objectId to be used as the target for appendContentStream calls. */ async function createEmptyDocument(filename, parentId, credentials, repositoryId, destination) { - console.log(`[createEmptyDocument] Creating placeholder for "${filename}" in parent ${parentId}`); + LOG.debug(`[DEBUG] [createEmptyDocument] Creating placeholder for "${filename}" in parent ${parentId}`); const url = credentials.uri + "browser/" + repositoryId + "/root"; const formData = new FormData(); formData.append("cmisaction", "createDocument"); @@ -231,7 +249,7 @@ async function createEmptyDocument(filename, parentId, credentials, repositoryId }); const objectId = response.data?.succinctProperties?.["cmis:objectId"]; - console.log(`[createEmptyDocument] Placeholder created objectId=${objectId}`); + LOG.debug(`[DEBUG] [createEmptyDocument] Placeholder created objectId=${objectId}`); return { response, objectId }; } @@ -254,11 +272,7 @@ async function appendContentStream( try { return await executeHttpRequest(destination, { method: 'POST', url, data: formData }); } catch (error) { - console.error(`[appendContentStream] Chunk ${chunkIndex} failed`, { - objectId, filename, isLastChunk, - status: error.response?.status, - sdmMessage: error.response?.data?.message, - }); + LOG.error(`[ERROR] [appendContentStream] Chunk ${chunkIndex} failed objectId=${objectId} filename=${filename} isLastChunk=${isLastChunk} status=${error.response?.status || 500} message=${error.response?.data?.message || error.message}`); throw new Error(`Error appending chunk ${chunkIndex}: ${error.message}`); } } @@ -272,12 +286,12 @@ async function deleteIncompleteDocumentWithRetry(objectId, credentials, destinat for (let attempt = 1; attempt <= CLEANUP_MAX_RETRIES; attempt++) { try { await deleteAttachmentsOfFolder(credentials, destination, objectId); - console.log(`[cleanup] Deleted incomplete document objectId=${objectId} on attempt ${attempt}`); + LOG.info(`[INFO] [cleanup] Deleted incomplete document objectId=${objectId} on attempt ${attempt}`); return true; } catch (cleanupError) { const delayMs = CLEANUP_BASE_DELAY_MS * Math.pow(2, attempt - 1); // 2s, 4s, 8s - console.error( - `[cleanup] Attempt ${attempt}/${CLEANUP_MAX_RETRIES} failed for objectId=${objectId}: ${cleanupError.message}. ` + + LOG.warn( + `[WARN] [cleanup] Attempt ${attempt}/${CLEANUP_MAX_RETRIES} failed for objectId=${objectId}: ${cleanupError.message}. ` + (attempt < CLEANUP_MAX_RETRIES ? `Retrying in ${delayMs / 1000}s.` : 'Giving up.') ); if (attempt < CLEANUP_MAX_RETRIES) { @@ -306,7 +320,10 @@ async function uploadLargeFileInChunks(data, credentials, parentId, repositoryId const { objectId: newObjectId } = await createEmptyDocument(data.filename, parentId, credentials, repositoryId, destination); - if (!newObjectId) throw new Error('createEmptyDocument returned no objectId'); + if (!newObjectId) { + LOG.error('[FATAL] createEmptyDocument returned no objectId'); + throw new Error('createEmptyDocument returned no objectId'); + } objectId = newObjectId; // Step 2 — feed content directly to ReadAheadStream without full buffering. @@ -314,7 +331,10 @@ async function uploadLargeFileInChunks(data, credentials, parentId, repositoryId // Passing the Buffer directly means ReadAheadStream only holds ≤4×20MB=80MB // in its queue at any time — the rest of the Buffer is referenced but not copied. const content = data.content; - if (!content) throw new Error('No content provided for large file upload'); + if (!content) { + LOG.error('[FATAL] No content provided for large file upload'); + throw new Error('No content provided for large file upload'); + } readAheadStream = new ReadAheadStream(content, totalSize, CHUNK_SIZE); await readAheadStream.startReading(); @@ -328,7 +348,7 @@ async function uploadLargeFileInChunks(data, credentials, parentId, repositoryId // Handle premature EOF with data still queued if (bytesRead === -1 && !readAheadStream.isChunkQueueEmpty()) { - console.log('[uploadLargeFileInChunks] Premature EOF — draining last chunk from queue'); + LOG.warn('[WARN] [uploadLargeFileInChunks] Premature EOF - draining last chunk from queue'); const lastChunk = await readAheadStream.getLastChunkFromQueue(); bytesRead = lastChunk.length; lastChunk.copy(chunkBuffer, 0, 0, bytesRead); @@ -346,8 +366,8 @@ async function uploadLargeFileInChunks(data, credentials, parentId, repositoryId if (isLastChunk) finalResponse = response; - console.log( - `[uploadLargeFileInChunks] Chunk ${chunkIndex}: ${bytesRead} bytes, isLast=${isLastChunk}, ` + + LOG.debug( + `[DEBUG] [uploadLargeFileInChunks] Chunk ${chunkIndex}: ${bytesRead} bytes, isLast=${isLastChunk}, ` + `took ${Date.now() - startTs}ms` ); @@ -364,18 +384,18 @@ async function uploadLargeFileInChunks(data, credentials, parentId, repositoryId error.message.includes('aborted') ); - console.error(`[uploadLargeFileInChunks] Upload failed`, { - filename: data.filename, - chunkIndex, - isClientDisconnect, - totalSize, - objectId, - error: error.message, - }); + if (isClientDisconnect) { + LOG.warn(`[WARN] [uploadLargeFileInChunks] Upload aborted by client filename=${data.filename} chunkIndex=${chunkIndex}`); + } else { + LOG.error(`[ERROR] [uploadLargeFileInChunks] Upload failed filename=${data.filename} chunkIndex=${chunkIndex} totalSize=${totalSize} objectId=${objectId || 'n/a'} error=${error.message}`); + } // Step 3 — attempt cleanup with retry backoff if (objectId) { - await deleteIncompleteDocumentWithRetry(objectId, credentials, destination); + const isCleaned = await deleteIncompleteDocumentWithRetry(objectId, credentials, destination); + if (!isCleaned) { + LOG.error(`[FATAL] [uploadLargeFileInChunks] Cleanup failed objectId=${objectId}`); + } } throw error; @@ -387,6 +407,7 @@ async function uploadLargeFileInChunks(data, credentials, parentId, repositoryId async function editLink(objectId, filename, linkUrl, credentials, destination) { const { repositoryId } = getConfigurations(); + LOG.info(`[INFO] [editLink] objectId=${objectId} filename=${filename} repositoryId=${repositoryId}`); const editLinkURL = `${credentials.uri}browser/${repositoryId}/root`; const formData = new FormData(); const urlShortcut = `[InternetShortcut]\nURL=${linkUrl}`; @@ -421,6 +442,7 @@ async function editLink(objectId, filename, linkUrl, credentials, destination) { async function deleteAttachmentsOfFolder(credentials, destination, objectId) { const { repositoryId } = getConfigurations(); + LOG.debug(`[DEBUG] [deleteAttachmentsOfFolder] objectId=${objectId} repositoryId=${repositoryId}`); const documentDeleteURL = credentials.uri + "browser/" + repositoryId + "/root"; const formData = new FormData(); @@ -437,6 +459,7 @@ async function deleteAttachmentsOfFolder(credentials, destination, objectId) { return response; } catch (error) { // Return error in a format that handleRequest can process + LOG.warn(`[WARN] [deleteAttachmentsOfFolder] Failed objectId=${objectId} status=${error.response?.status || 'unknown'}`); return { status: error.response?.status, response: error.response, @@ -447,6 +470,7 @@ async function deleteAttachmentsOfFolder(credentials, destination, objectId) { async function deleteFolderWithAttachments(credentials, destination, parentId) { const { repositoryId } = getConfigurations(); + LOG.info(`[INFO] [deleteFolderWithAttachments] parentId=${parentId} repositoryId=${repositoryId}`); const folderDeleteURL = credentials.uri + "browser/" + repositoryId + "/root"; const formData = new FormData(); formData.append("cmisaction", "deleteTree"); @@ -462,6 +486,7 @@ async function deleteFolderWithAttachments(credentials, destination, parentId) { return response; } catch (error) { // Return error in a format that handleRequest can process + LOG.warn(`[WARN] [deleteFolderWithAttachments] Failed parentId=${parentId} status=${error.response?.status || 'unknown'}`); return { status: error.response?.status, response: error.response, @@ -472,6 +497,7 @@ async function deleteFolderWithAttachments(credentials, destination, parentId) { async function getAttachment(uri, destination, objectId) { const { repositoryId } = getConfigurations(); + LOG.debug(`[DEBUG] [getAttachment] objectId=${objectId} repositoryId=${repositoryId}`); const getAttachmentURL = uri + "browser/" @@ -493,6 +519,7 @@ async function getAttachment(uri, destination, objectId) { if (error.response?.statusText) { statusText = error.response.statusText; } + LOG.error(`[ERROR] [getAttachment] Failed objectId=${objectId} status=${error.response?.status || 'unknown'} message=${statusText}`); return statusText; } } @@ -509,6 +536,7 @@ async function updateAttachment( ) { const { repositoryId } = getConfigurations(); const objectId = attachment.url; + LOG.info(`[INFO] [updateAttachment] objectId=${objectId} repositoryId=${repositoryId} properties=${Object.keys(updatedSecondaryProperties).join(',')}`); // Fetch secondary types let secondaryTypes; @@ -518,7 +546,7 @@ async function updateAttachment( if (error.response?.status === 403) { return error.status; } - console.log("Error fetching secondary types:", error); + LOG.error(`[ERROR] Error fetching secondary types: ${error.message}`); return 500; } diff --git a/lib/mtx/server.js b/lib/mtx/server.js index d22d1d64..cf2b05e8 100644 --- a/lib/mtx/server.js +++ b/lib/mtx/server.js @@ -4,6 +4,7 @@ const { getConfigurations, transformSDMServiceBindingToClientCredentialsDestinat const { skippingOnboarding } = require("../util/messageConsts"); const { executeHttpRequest } = require('@sap-cloud-sdk/http-client'); const { getDestinationFromServiceBinding } = require('@sap-cloud-sdk/connectivity'); +const LOG = cds.log('sdm'); const profile = cds.env.profile; let configPath; @@ -72,7 +73,7 @@ if (profile === "mtx-sidecar") { if (status === 409) { const messageString = typeof data === 'string' ? data : JSON.stringify(data); if (messageString.includes(`${externalId} already exists`) || messageString.includes('already exists')) { - console.info(skippingOnboarding(displayName, externalId)); + LOG.info(`[INFO] ${skippingOnboarding(displayName, externalId)}`); return { skipped: true, message: skippingOnboarding(displayName, externalId) }; } } @@ -101,7 +102,7 @@ if (profile === "mtx-sidecar") { } return repos; } catch (error) { - console.error("Error listing SDM repositories:", error?.response?.data || error); + LOG.error("[ERROR] Error listing SDM repositories:", error?.response?.data || error); throw error; } }; @@ -128,7 +129,7 @@ if (profile === "mtx-sidecar") { const deploymentService = await cds.connect.to("cds.xt.DeploymentService"); if (!deploymentService) { - console.error("Failed to connect to cds.xt.DeploymentService"); + LOG.error("[ERROR] Failed to connect to cds.xt.DeploymentService"); return; } @@ -136,19 +137,19 @@ if (profile === "mtx-sidecar") { deploymentService.after('subscribe', async (_, req) => { const { tenant, metadata } = req.data; const subdomain = metadata?.subscribedSubdomain; - console.log("SUBDOMAIN DURING SUBSCRIBE "+subdomain); + LOG.debug(`[DEBUG] SUBDOMAIN DURING SUBSCRIBE ${subdomain}`); const SDMCredentials = cds.env.requires?.sdm?.credentials; const sdmUrl = SDMCredentials?.uri; - console.log(`SDM Plugin: Tenant subscription started — ${tenant}`); + LOG.info(`[INFO] SDM Plugin: Tenant subscription started - ${tenant}`); try { const repository = buildRepositoryObject(); const destination = await getDestination(subdomain); await onboardRepository(sdmUrl, repository, destination); - console.log("SDM repository onboarded"); + LOG.info("[INFO] SDM repository onboarded"); } catch (err) { - console.error("Error during SDM onboarding:", err); + LOG.error('[FATAL] Error during SDM onboarding:', err); throw err; } }); @@ -157,15 +158,16 @@ if (profile === "mtx-sidecar") { deploymentService.after('unsubscribe', async (_, req) => { const { tenant, options } = req.data; const subdomain = options?.subscribedSubdomain; - console.log("SUBDOMAIN AFTER UNSUBSCRIBE "+subdomain); + LOG.debug(`[DEBUG] SUBDOMAIN AFTER UNSUBSCRIBE ${subdomain}`); const SDMCredentials = cds.env.requires?.sdm?.credentials; const sdmUrl = SDMCredentials?.uri; - console.log(`SDM Plugin: Tenant Unsubscription started — ${tenant}`); + LOG.info(`[INFO] SDM Plugin: Tenant Unsubscription started - ${tenant}`); try { const { repositoryId } = getConfigurations(); if (!repositoryId) { + LOG.warn('[WARN] Skipping offboarding because repositoryId is not configured'); return; } const destination = await getDestination(subdomain); @@ -175,14 +177,14 @@ if (profile === "mtx-sidecar") { ); if (!repoToOffboard) { - console.error(`SDM Plugin: Could not find a repository with externalId '${repositoryId}' for tenant ${tenant}.`); + LOG.error(`[ERROR] SDM Plugin: Could not find a repository with externalId '${repositoryId}' for tenant ${tenant}.`); } else { const foundRepositoryId = repoToOffboard.repository.id; await offboardRepository(sdmUrl, foundRepositoryId, destination); - console.log("SDM repository offboarded"); + LOG.info("[INFO] SDM repository offboarded"); } } catch (err) { - console.error("Error during SDM offboarding:", err); + LOG.error('[FATAL] Error during SDM offboarding:', err); throw err; } }); diff --git a/lib/persistence/index.js b/lib/persistence/index.js index ae6abdfd..e76cb021 100644 --- a/lib/persistence/index.js +++ b/lib/persistence/index.js @@ -3,8 +3,10 @@ const { attachmentIDRegex } = require("../util/messageConsts"); const { SELECT, UPDATE, INSERT } = cds.ql; +const LOG = cds.log('sdm'); async function getURLFromAttachments(keys, attachments) { + LOG.debug(`[DEBUG] [persistence] getURLFromAttachments keys=${JSON.stringify(keys)}`); return await SELECT.from(attachments, keys).columns("url"); } @@ -94,6 +96,7 @@ async function getFolderIdForEntity(attachments, req, repositoryId, upId) { async function updateAttachmentInDraft(req, data) { const attachmentID = req.req.url.match(attachmentIDRegex)[1]; + LOG.debug(`[DEBUG] [persistence] updateAttachmentInDraft attachmentID=${attachmentID} url=${data.url}`); return await UPDATE(req.target) .set({ folderId: data.folderId, url: data.url, status: "Clean", type: data.type }) .where({ ["ID"]: attachmentID }); @@ -101,9 +104,11 @@ async function updateAttachmentInDraft(req, data) { async function updateLinkInDraft(req, data) { try { + LOG.debug(`[DEBUG] [persistence] updateLinkInDraft inserting link entry`); // Use cds.db to execute the query instead of req.run await INSERT.into(req.target.name).entries(data); } catch (err) { + LOG.error(`[ERROR] [persistence] updateLinkInDraft failed: ${err.message}`); // Forward the error if req has error method if (req.error) { req.error(500, `Failed to create draft entry: ${err.message}`); @@ -121,8 +126,10 @@ async function editLinkInDraft(req, data) { if (data.note !== undefined) { updateData.note = data.note; } + LOG.debug(`[DEBUG] [persistence] editLinkInDraft ID=${data.ID} linkUrl=${data.linkUrl}`); await UPDATE(req.target).set(updateData).where({ ID: data.ID }); } catch (err) { + LOG.error(`[ERROR] [persistence] editLinkInDraft failed: ${err.message}`); if (req.error) { req.error(500, `Failed to update the link: ${err.message}`); } else { @@ -176,6 +183,7 @@ async function setRepositoryId(attachments, repositoryId) { return; } + LOG.info(`[INFO] [persistence] setRepositoryId Updating ${nullAttachments.length} attachment(s) with repositoryId=${repositoryId}`); for (let attachment of nullAttachments) { await UPDATE(attachments) .set({ repositoryId: repositoryId }) diff --git a/lib/sdm.js b/lib/sdm.js index bf50faa6..842473d6 100644 --- a/lib/sdm.js +++ b/lib/sdm.js @@ -79,6 +79,7 @@ const { } = require("./util/messageConsts"); const { getDestinationFromServiceBinding,retrieveJwt} = require('@sap-cloud-sdk/connectivity'); const { executeHttpRequest } = require('@sap-cloud-sdk/http-client'); +const LOG = cds.log('sdm'); // Resolve the base class across @cap-js/attachments layouts: 3.8 ships it at // "srv/basic", 3.12+ ships it at "srv/attachments/basic". Try both so the @@ -97,6 +98,7 @@ module.exports = class SDMAttachmentsService extends resolveAttachmentsBasic() { async init() { this.creds = this.options.credentials; this.originalUrlMap = new Map(); + LOG.info('[INFO] [SDMAttachmentsService] init - service initialized'); return super.init(); } async getTechnicalDestination(){ @@ -114,18 +116,21 @@ let subdomain = cds.context?.user?.authInfo?.token?.payload?.ext_attr?.zdn; // and the non-rename callsites still hit '_default' for back-compat. const cacheKey = attachmentsEntity?.name || '_default'; if (req._sdmDestinations?.[cacheKey]) { + LOG.debug(`[DEBUG] [getDestination] Using cached destination for key=${cacheKey}`); return req._sdmDestinations[cacheKey]; } const userJwt = retrieveJwt(req); let destination; if (isClientCredentialForced(req, attachmentsEntity) || !cds.context?.user?.authInfo?.token?.payload?.origin) { + LOG.debug(`[DEBUG] [getDestination] Using client credentials flow for key=${cacheKey}`); let subdomain = cds.context?.user?.authInfo?.token?.payload?.ext_attr?.zdn; destination = await getDestinationFromServiceBinding({ destinationName: getSdmInstanceName(), useCache: true, serviceBindingTransformFn: (serviceBinding, options) => transformSDMServiceBindingToClientCredentialsDestination(serviceBinding, options, subdomain)}); } else { + LOG.debug(`[DEBUG] [getDestination] Using JWT bearer flow for key=${cacheKey}`); destination = await getDestinationFromServiceBinding({ destinationName: getSdmInstanceName(), jwt: userJwt, @@ -149,6 +154,7 @@ let subdomain = cds.context?.user?.authInfo?.token?.payload?.ext_attr?.zdn; let repotype = cache.get(repositoryId+"_"+subdomain); let isVersioned; let repoInfo; + LOG.debug(`[DEBUG] [checkRepositoryType] repositoryId=${repositoryId} subdomain=${subdomain} cached=${repotype !== undefined}`); if (repotype == undefined) { const destination = await this.getTechnicalDestination(); repoInfo = await getRepositoryInfo(req, this.creds, destination); @@ -157,6 +163,7 @@ let subdomain = cds.context?.user?.authInfo?.token?.payload?.ext_attr?.zdn; isVersioned = repotype == "versioned"; } if (isVersioned) { + LOG.warn(`[WARN] [checkRepositoryType] Repository ${repositoryId} is versioned - rejecting operation`); req.reject(400, versionedRepositoryErr); } } @@ -165,9 +172,11 @@ let subdomain = cds.context?.user?.authInfo?.token?.payload?.ext_attr?.zdn; const response = await getURLFromAttachments(keys, attachments); const Key = response?.url; + LOG.debug(`[DEBUG] [get] Fetching attachment content objectId=${Key}`); // Access current request from cds.context for cloud-sdk authentication const req = cds.context?.http?.req; if (!req) { + LOG.error('[ERROR] [get] HTTP request context not available'); throw new Error('HTTP request context not available'); } const destination = await this.getDestination(req, attachments); @@ -211,6 +220,7 @@ let subdomain = cds.context?.user?.authInfo?.token?.payload?.ext_attr?.zdn; async draftEntityRenameHandler(req) { const { repositoryId } = getConfigurations(); const attachmentCompositions = this.getAttachmentCompositions(req.target); + LOG.debug(`[DEBUG] [draftEntityRenameHandler] entity=${req.target.name} compositions=${attachmentCompositions.length}`); for (const composition of attachmentCompositions) { await this.processCompositionRename(req, composition, repositoryId); @@ -265,6 +275,7 @@ let subdomain = cds.context?.user?.authInfo?.token?.payload?.ext_attr?.zdn; } async updateDraftAttachments(req, attachment, attachmentsEntity, secondaryPropertiesWithInvalidDefinitions, secondaryTypeProperties, compositionName) { + LOG.debug(`[DEBUG] [updateDraftAttachments] ID=${attachment.ID} composition=${compositionName}`); const attachmentData = await this.getAttachementDataInSDM(this.creds.uri, attachment.url, req, attachmentsEntity); const filenameInSDM = attachmentData.filename; @@ -283,6 +294,7 @@ let subdomain = cds.context?.user?.authInfo?.token?.payload?.ext_attr?.zdn; } async updateNonDraftAttachments(req, attachment, attachmentsEntity, secondaryPropertiesWithInvalidDefinitions, secondaryTypeProperties, compositionName) { + LOG.debug(`[DEBUG] [updateNonDraftAttachments] ID=${attachment.ID} composition=${compositionName}`); const fileNameInDB = await getFileNameForAttachmentID(attachmentsEntity, attachment.ID); const context = { @@ -350,19 +362,24 @@ let subdomain = cds.context?.user?.authInfo?.token?.payload?.ext_attr?.zdn; } async performAttachmentUpdate(req, attachment, updatedSecondaryProperties, invalidDefinitions, filenameInRequest, attachmentsEntity) { + LOG.debug(`[DEBUG] [performAttachmentUpdate] filename=${filenameInRequest} objectId=${attachment.url} properties=${Object.keys(updatedSecondaryProperties).join(',')}`); try { const destination = await this.getDestination(req, attachmentsEntity); const responseCode = await updateAttachment(req, attachment, this.creds, destination, updatedSecondaryProperties, invalidDefinitions); switch (responseCode) { case 403: + LOG.warn(`[WARN] [performAttachmentUpdate] No SDM roles for filename=${filenameInRequest}`); return { error: { typeOfError: 'no sdm roles', name: filenameInRequest } }; case 409: + LOG.warn(`[WARN] [performAttachmentUpdate] Duplicate filename=${filenameInRequest}`); return { error: { typeOfError: 'duplicate', name: filenameInRequest } }; case 404: + LOG.warn(`[WARN] [performAttachmentUpdate] Not found filename=${filenameInRequest}`); return { error: { typeOfError: 'not found', name: filenameInRequest } }; case 200: case 201: + LOG.info(`[INFO] [performAttachmentUpdate] Success filename=${filenameInRequest}`); return { success: true }; default: throw new Error(sdmRolesErrorMessage); @@ -370,8 +387,10 @@ let subdomain = cds.context?.user?.authInfo?.token?.payload?.ext_attr?.zdn; } catch (e) { if (e.message.startsWith(unsupportedProperties)) { const unsupportedDetails = e.message.substring(unsupportedProperties.length).trim(); + LOG.warn(`[WARN] [performAttachmentUpdate] Unsupported properties: ${unsupportedDetails}`); return { error: { typeOfError: 'unsupported properties', details: unsupportedDetails } }; } + LOG.error(`[ERROR] [performAttachmentUpdate] Failed filename=${filenameInRequest} error=${e.message}`); return { error: { typeOfError: 'bad request', name: filenameInRequest, message: e.message } }; } } @@ -548,7 +567,7 @@ let subdomain = cds.context?.user?.authInfo?.token?.payload?.ext_attr?.zdn; if (contentLengthNum <= FILE_SIZE_THRESHOLD) return; const isVirusScanEnabled = cds.env?.requires?.["sdm"]?.settings?.isVirusScanEnabled; if (isVirusScanEnabled === 'true' || isVirusScanEnabled === true) { - console.error(`[draftAttachmentUploadHandler] Rejecting: file size ${contentLengthNum} exceeds 400MB limit for virus scan enabled repository`); + LOG.warn(`[WARN] [draftAttachmentUploadHandler] Rejecting: file size ${contentLengthNum} exceeds 400MB limit for virus scan enabled repository`); req.reject(409, largFileVirusScanErr); } } @@ -561,7 +580,8 @@ let subdomain = cds.context?.user?.authInfo?.token?.payload?.ext_attr?.zdn; const rawContentLength = req.req?.headers?.['content-length'] || req.headers?.['content-length']; const contentLengthNum = rawContentLength ? parseInt(rawContentLength, 10) : -1; - console.log(`[draftAttachmentUploadHandler] Upload started — Content-Length: ${contentLengthNum} bytes`); + LOG.debug('[DEBUG] [draftAttachmentUploadHandler] Processing draft upload request'); + LOG.info(`[INFO] [draftAttachmentUploadHandler] Upload started - Content-Length: ${contentLengthNum} bytes`); // Check virus scan before any SDM call — reject large files early. this._rejectIfVirusScanLargeFile(req, contentLengthNum); @@ -590,7 +610,7 @@ let subdomain = cds.context?.user?.authInfo?.token?.payload?.ext_attr?.zdn; attachment_val_create[0].content = req.data.content; attachment_val_create[0].contentLength = contentLengthNum; await this.create(attachment_val_create, draftAttachments, req); - console.log(`[draftAttachmentUploadHandler] Upload finished`); + LOG.info(`[INFO] [draftAttachmentUploadHandler] Upload finished`); } } req.data.content = null; @@ -599,6 +619,7 @@ let subdomain = cds.context?.user?.authInfo?.token?.payload?.ext_attr?.zdn; async create(attachment_val_create, attachments, req){ let parentId = await this.getParentId(attachments, req, undefined); + LOG.debug(`[DEBUG] [create] Resolved parent folder ID ${parentId}`); await this.onCreate( attachment_val_create, this.creds, @@ -683,7 +704,7 @@ let subdomain = cds.context?.user?.authInfo?.token?.payload?.ext_attr?.zdn; return response.data.succinctProperties["cmis:objectId"]; } if (response.status == 403 && response.response?.data == userDoesNotHaveRequiredScope) { - console.error('[getOrCreateCompositionFolder] User not authorized to create composition folder'); + LOG.error('[ERROR] [getOrCreateCompositionFolder] User not authorized to create composition folder'); req.reject(403, userNotAuthorisedError); } // If folder creation failed (e.g., 409 conflict), try to fetch it again @@ -693,7 +714,7 @@ let subdomain = cds.context?.user?.authInfo?.token?.payload?.ext_attr?.zdn; ); return retryResponse.data.properties["cmis:objectId"].value; } catch { - console.error('[getOrCreateCompositionFolder] Failed to create or find folder', { + LOG.error('[ERROR] [getOrCreateCompositionFolder] Failed to create or find folder', { composedFolderName, status: response.status || response.response?.status, message: response.message || response.response?.data?.message @@ -726,6 +747,7 @@ let subdomain = cds.context?.user?.authInfo?.token?.payload?.ext_attr?.zdn; break; } } + LOG.debug(`[DEBUG] [getOrCreateFlatFolder] repositoryId=${repositoryId} cachedFolderId=${parentId || 'none'}`); if (!parentId) { const destination = await this.getDestination(req, attachments); const folderId = await getFolderIdByPath( @@ -746,7 +768,7 @@ let subdomain = cds.context?.user?.authInfo?.token?.payload?.ext_attr?.zdn; destination ); if (response.status == 403 && response.response.data == userDoesNotHaveRequiredScope) { - console.error('[getParentId] User not authorized to create folder'); + LOG.error('[ERROR] [getParentId] User not authorized to create folder'); req.reject(403, userNotAuthorisedError); } parentId = response.data.succinctProperties["cmis:objectId"]; @@ -762,6 +784,7 @@ let subdomain = cds.context?.user?.authInfo?.token?.payload?.ext_attr?.zdn; } const duplicates = this.filterDuplicates(fileNames); if (duplicates.length != 0) { + LOG.warn(`[WARN] [isFileNameDuplicateInDrafts] Duplicate filenames detected: ${duplicates.join(', ')}`); req.reject(409, duplicateDraftFileErr(duplicates.join(", "))); } } @@ -769,6 +792,7 @@ let subdomain = cds.context?.user?.authInfo?.token?.payload?.ext_attr?.zdn; async validateLinkName(data, linkNameInRequest, req) { const nameConstraint = isRestrictedCharactersInName(linkNameInRequest); if (nameConstraint) { + LOG.warn(`[WARN] [validateLinkName] Restricted characters in link name: ${linkNameInRequest}`); req.reject(409, linkNameConstraintMessage([linkNameInRequest], "created")); } @@ -779,6 +803,7 @@ let subdomain = cds.context?.user?.authInfo?.token?.payload?.ext_attr?.zdn; fileNames.push(linkNameInRequest); const duplicates = this.filterDuplicates(fileNames); if (duplicates.length != 0) { + LOG.warn(`[WARN] [validateLinkName] Duplicate link name detected: ${duplicates.join(', ')}`); req.reject(409, duplicateDraftFileErr(duplicates.join(", "))); } } @@ -820,6 +845,7 @@ let subdomain = cds.context?.user?.authInfo?.token?.payload?.ext_attr?.zdn; async attachDeletionData(req) { if (this.getSDMCredentials()) { const attachmentCompositions = this.getAttachmentCompositions(req.target); + LOG.debug(`[DEBUG] [attachDeletionData] entity=${req.target.name} event=${req.event} compositions=${attachmentCompositions.length}`); for (const compositionName of attachmentCompositions) { const attachments = cds.model.definitions[req.target.name + "." + compositionName]; @@ -917,6 +943,7 @@ let subdomain = cds.context?.user?.authInfo?.token?.payload?.ext_attr?.zdn; if (!baseEntity) { return; } + LOG.debug(`[DEBUG] [attachDraftDeletionData] entity=${baseEntityName} event=${req.event}`); const attachmentCompositions = this.getAttachmentCompositions({ name: baseEntityName }); const diffData = req.event == "DELETE" ? await req.diff() : null; @@ -1007,6 +1034,7 @@ let subdomain = cds.context?.user?.authInfo?.token?.payload?.ext_attr?.zdn; if(draftAttachments) { const attachmentsToDeleteFromDraft = await getURLToDeleteFromDraftAttachments(req.data.ID, draftAttachments); if (attachmentsToDeleteFromDraft?.length > 0) { + LOG.info(`[INFO] [attachURLsToDeleteFromAttachmentsDraft] Marking ${attachmentsToDeleteFromDraft.length} draft attachment(s) for deletion ID=${req.data.ID}`); req.attachmentsToDelete = attachmentsToDeleteFromDraft; } if (req?.attachmentsToDelete?.length > 0) { @@ -1019,6 +1047,7 @@ let subdomain = cds.context?.user?.authInfo?.token?.payload?.ext_attr?.zdn; let failedReq = [], Ids = []; if (req?.attachmentsToDelete?.length > 0) { + LOG.info(`[INFO] [deleteAttachmentsWithKeys] Deleting ${req.attachmentsToDelete.length} attachment(s)`); if (req?.parentId) { // Handle both single parentId and array of parentIds const destination = await this.getDestination(req); @@ -1085,7 +1114,7 @@ let subdomain = cds.context?.user?.authInfo?.token?.payload?.ext_attr?.zdn; ); } catch (error) { // Handle Axios errors from SDM (e.g., 409 for duplicates) - console.error('[onCreate] createAttachment threw error', { + LOG.error('[ERROR] [onCreate] createAttachment threw error', { filename: d.filename, status: error.response?.status, errorMessage: error.response?.data?.message, @@ -1123,7 +1152,7 @@ let subdomain = cds.context?.user?.authInfo?.token?.payload?.ext_attr?.zdn; }) .where({ ID: d.ID }); } catch (updateError) { - console.error('[onCreate] UPDATE failed for non-draft attachment', { + LOG.error('[ERROR] [onCreate] UPDATE failed for non-draft attachment', { ID: d.ID, error: updateError.message, stack: updateError.stack @@ -1131,13 +1160,13 @@ let subdomain = cds.context?.user?.authInfo?.token?.payload?.ext_attr?.zdn; throw updateError; } } else { - console.warn('[onCreate] No update performed - missing ID', { + LOG.warn('[WARN] [onCreate] No update performed - missing ID', { filename: d.filename, isDraft: req.target.isDraft }); } } else { - console.error('[onCreate] Upload failed', { + LOG.error('[ERROR] [onCreate] Upload failed', { filename: d.filename, status: response.status, errorMessage: response.response?.data?.message, @@ -1151,7 +1180,7 @@ let subdomain = cds.context?.user?.authInfo?.token?.payload?.ext_attr?.zdn; try { await cds.ql.DELETE.from(req.target).where({ ID: d.ID }); } catch (cleanupError) { - console.error('[onCreate] Cleanup failed', { + LOG.error('[ERROR] [onCreate] Cleanup failed', { ID: d.ID, error: cleanupError.message }); @@ -1159,12 +1188,12 @@ let subdomain = cds.context?.user?.authInfo?.token?.payload?.ext_attr?.zdn; } if(response.response.data.message == 'Malware Service Exception: Virus found in the file!'){ - console.error('[onCreate] Virus detected', { fileNames }); + LOG.warn('[WARN] [onCreate] Virus detected', { fileNames }); req.reject(403, virusFileErr(fileNames)); } else if(response.response.data.exception == "nameConstraintViolation"){ const duplicateErrorMessage = duplicateFileErr(fileNames); - console.error('[onCreate] Duplicate file detected', { + LOG.warn('[WARN] [onCreate] Duplicate file detected', { fileNames, sdmMessage: response.response.data.message, sdmException: response.response.data.exception, @@ -1173,15 +1202,15 @@ let subdomain = cds.context?.user?.authInfo?.token?.payload?.ext_attr?.zdn; req.reject(409, duplicateErrorMessage); } else if(response.status == 403 && response.response?.data?.exception === 'streamNotSupported'){ - console.error('[onCreate] Blocked MIME type', { fileNames, message: response.response?.data?.message }); + LOG.warn('[WARN] [onCreate] Blocked MIME type', { fileNames, message: response.response?.data?.message }); req.reject(403, mimeTypeInvalidError); } else if(response.status == 403){ - console.error('[onCreate] User not authorized', { fileNames }); + LOG.warn('[WARN] [onCreate] User not authorized', { fileNames }); req.reject(403, userNotAuthorisedError); } else{ - console.error('[onCreate] Other upload error', { + LOG.error('[ERROR] [onCreate] Other upload error', { fileNames, status: response.status, message: response.response?.data?.message @@ -1197,6 +1226,7 @@ let subdomain = cds.context?.user?.authInfo?.token?.payload?.ext_attr?.zdn; let attachments = cds.model.definitions[req.target.name]; let attachmentId = { ID: req.req.url.match(attachmentIDRegex)[1] } + LOG.debug(`[DEBUG] [openAttachment] attachmentId=${attachmentId.ID}`); let response = await getMetadataForOpenAttachment(attachmentId, attachments); let objectId = response?.url; if (response?.filename == null) { @@ -1204,6 +1234,7 @@ let subdomain = cds.context?.user?.authInfo?.token?.payload?.ext_attr?.zdn; response = await getMetadataForOpenAttachment(attachmentId, attachments); } if (response?.mimeType.toLowerCase() == "application/internet-shortcut") { + LOG.info(`[INFO] [openAttachment] Opening link attachment ID=${attachmentId.ID} linkUrl=${response.linkUrl}`); const destination = await this.getDestination(req); const authresponse = await getAttachment(this.creds.uri, destination, objectId); @@ -1212,6 +1243,7 @@ let subdomain = cds.context?.user?.authInfo?.token?.payload?.ext_attr?.zdn; } return { value: response.linkUrl }; } else { + LOG.debug(`[DEBUG] [openAttachment] Non-link attachment ID=${attachmentId.ID} mimeType=${response?.mimeType}`); return { value: "None" }; } } @@ -1221,7 +1253,7 @@ let subdomain = cds.context?.user?.authInfo?.token?.payload?.ext_attr?.zdn; let key = req.req.url.match(attachmentIDRegex)[1]; const linkNameInRequest = req.data.name; - console.info(`[createLink] action called`, { + LOG.info(`[INFO] [createLink] action called`, { repositoryId, entity: req.target?.name, key, @@ -1252,7 +1284,7 @@ let subdomain = cds.context?.user?.authInfo?.token?.payload?.ext_attr?.zdn; const upIdKey = attachment.keys.up_.keys[0].$generatedFieldName; const upId = req.req.url.match(attachmentIDRegex)[1]; - console.info(`[processLinkCreation] called`, { + LOG.info(`[INFO] [processLinkCreation] called`, { upIdKey, upId, linkToCreateInSDM @@ -1260,7 +1292,7 @@ let subdomain = cds.context?.user?.authInfo?.token?.payload?.ext_attr?.zdn; let parentId = await this.getParentId(attachment, req, upId); - console.info(`[processLinkCreation] parentId resolved`, { + LOG.info(`[INFO] [processLinkCreation] parentId resolved`, { parentId }); @@ -1272,7 +1304,7 @@ let subdomain = cds.context?.user?.authInfo?.token?.payload?.ext_attr?.zdn; upIdKey ); - console.info(`[processLinkCreation] createLink completed`, { + LOG.info(`[INFO] [processLinkCreation] createLink completed`, { parentId, upIdKey, upId @@ -1283,7 +1315,7 @@ let subdomain = cds.context?.user?.authInfo?.token?.payload?.ext_attr?.zdn; const { repositoryId } = getConfigurations(); const upId = req.req.url.match(attachmentIDRegex)[1]; - console.info(`[createLink] called`, { + LOG.info(`[INFO] [createLink] called`, { linkToCreateInSDM, parentId, upIdKey, @@ -1299,14 +1331,14 @@ let subdomain = cds.context?.user?.authInfo?.token?.payload?.ext_attr?.zdn; destination ); - console.info(`[createLink] createAttachment response`, { + LOG.info(`[INFO] [createLink] createAttachment response`, { status: response.status }); if (response.status == 201) { const draftUUID = await getDraftAdministrativeData_DraftUUIDForUpId(req, upIdKey, upId); - console.info(`[createLink] draftUUID fetched`, { + LOG.info(`[INFO] [createLink] draftUUID fetched`, { draftUUID: draftUUID[0]?.DraftAdministrativeData_DraftUUID }); @@ -1335,20 +1367,20 @@ let subdomain = cds.context?.user?.authInfo?.token?.payload?.ext_attr?.zdn; if (clientId) this._setManagedUser(updatedFields, 'CREATE', clientId); } - console.info(`[createLink] updating link in draft`, { updatedFields }); + LOG.info(`[INFO] [createLink] updating link in draft`, { updatedFields }); await updateLinkInDraft(req, updatedFields); } else { const fileName = req.data?.name; if (response.response.data.exception == "nameConstraintViolation") { - console.warn(`[createLink] nameConstraintViolation`, { fileName, response: response.response.data }); + LOG.warn(`[WARN] [createLink] nameConstraintViolation`, { fileName, response: response.response.data }); req.reject(409, duplicateFileErr([fileName])); } else if (response.status == 403) { - console.warn(`[createLink] user not authorised`, { user: req.user?.id, response: response.response.data }); + LOG.warn(`[WARN] [createLink] user not authorised`, { user: req.user?.id, response: response.response.data }); req.reject(403, userNotAuthorisedErrorLink); } else { - console.error(`[createLink] other error`, { message: response?.response?.data?.message, response: response.response.data }); + LOG.error(`[ERROR] [createLink] other error`, { message: response?.response?.data?.message, response: response.response.data }); req.reject(response?.response?.data?.message); } } @@ -1358,8 +1390,10 @@ let subdomain = cds.context?.user?.authInfo?.token?.payload?.ext_attr?.zdn; const attachmentId = req.req.url.match(attachmentIDRegex)[1]; const attachmentsEntity = cds.model.definitions[req.target.name]; const existingAttachment = await getAttachmentById(attachmentId, attachmentsEntity); + LOG.info(`[INFO] [handleEditLinkAction] attachmentId=${attachmentId} found=${!!existingAttachment}`); if (!existingAttachment || !existingAttachment.url) { + LOG.warn(`[WARN] [handleEditLinkAction] Link not found for attachmentId=${attachmentId}`); req.reject(404, editLinkNotFoundErr); return; } @@ -1399,10 +1433,10 @@ let subdomain = cds.context?.user?.authInfo?.token?.payload?.ext_attr?.zdn; message: "Link edited successfully" }; } else if (status === 403) { - console.warn(`[editLink] user not authorised`, { user: req.user?.id, response: response?.response?.data }); + LOG.warn(`[WARN] [editLink] user not authorised`, { user: req.user?.id, response: response?.response?.data }); req.reject(400, userNotAuthorisedErrorEditLink); } else { - console.error(`[editLink] other error`, { message: response?.response?.data?.message, response: response.response.data }); + LOG.error(`[ERROR] [editLink] other error`, { message: response?.response?.data?.message, response: response.response.data }); req.reject(response?.response?.data?.message); } } @@ -1412,6 +1446,7 @@ let subdomain = cds.context?.user?.authInfo?.token?.payload?.ext_attr?.zdn; const attachmentCompositions = this.getAttachmentCompositions({ name: baseEntityName }); const parentId = req.data?.ID; const clientId = getSdmClientId(); + LOG.debug(`[DEBUG] [handleDraftSaveForLinks] entity=${baseEntityName} parentId=${parentId} compositions=${attachmentCompositions.length}`); for (const compositionName of attachmentCompositions) { const attachmentsEntityName = `${baseEntityName}.${compositionName}`; @@ -1546,7 +1581,7 @@ let subdomain = cds.context?.user?.authInfo?.token?.payload?.ext_attr?.zdn; if (!baseEntity) { return; } - + LOG.debug(`[DEBUG] [handleDraftDiscardForLinks] parentId=${parentId} entity=${baseEntityName}`); const attachmentCompositions = this.getAttachmentCompositions({ name: baseEntityName }); @@ -1571,6 +1606,7 @@ let subdomain = cds.context?.user?.authInfo?.token?.payload?.ext_attr?.zdn; const baselineUrl = attachment.note.substring("__BASELINE_URL__:".length); if (baselineUrl && attachment.linkUrl !== baselineUrl) { + LOG.info(`[INFO] [handleDraftDiscardForLinks] Reverting link ID=${attachment.ID} to baseline URL`); await this.revertLinkInSDM(attachment, baselineUrl, req, attachmentsEntity); const attachmentKey = `${attachment.ID}`; this.originalUrlMap.delete(attachmentKey); @@ -1594,7 +1630,7 @@ let subdomain = cds.context?.user?.authInfo?.token?.payload?.ext_attr?.zdn; destination ); } catch (error) { - console.error(`[revertLinkInSDM] error reverting link for attachment ${draftAttachment.ID}:`, error.message); + LOG.error(`[FATAL] [revertLinkInSDM] error reverting link for attachment ${draftAttachment.ID}:`, error.message); throw error; } } @@ -1644,6 +1680,7 @@ let subdomain = cds.context?.user?.authInfo?.token?.payload?.ext_attr?.zdn; // Skip if no content or if this is a draft entity (handled by draftPutHandler) if (!req.data.content || req.target.isDraft) return; + LOG.info(`[INFO] [nonDraftAttachmentCreateHandler] event=${req.event} target=${req.target.name}`); const rawContentLength = req.req?.headers?.['content-length'] || req.headers?.['content-length']; const contentLengthNum = rawContentLength ? parseInt(rawContentLength, 10) : -1; @@ -1727,6 +1764,7 @@ let subdomain = cds.context?.user?.authInfo?.token?.payload?.ext_attr?.zdn; return; } + LOG.info(`[INFO] [nonDraftAttachmentUpdateHandler] Updating attachment metadata target=${req.target.name} ID=${req.data.ID}`); // Get attachment entity definition const attachmentsEntity = cds.model.definitions[req.target.name]; const attachmentID = req.data.ID; @@ -1809,6 +1847,7 @@ let subdomain = cds.context?.user?.authInfo?.token?.payload?.ext_attr?.zdn; if (!attachmentsEntity) return; + LOG.debug(`[DEBUG] [nonDraftEntityRenameHandler] entity=${req.target.name} repositoryId=${repositoryId}`); const updatedAttachments = await this._getUpdatedAttachments(req); if (!updatedAttachments || updatedAttachments.length === 0) return; @@ -2020,6 +2059,7 @@ let subdomain = cds.context?.user?.authInfo?.token?.payload?.ext_attr?.zdn; const attachments = await cds.ql.SELECT.from(req.subject).columns("url", "ID"); if (attachments.length) { + LOG.info(`[INFO] [attachNonDraftAttachmentDeletionData] Marking ${attachments.length} attachment(s) for deletion`); req.attachmentsToDelete = attachments.map(a => ({ ...a, target: req.target.name })); } } @@ -2078,6 +2118,7 @@ let subdomain = cds.context?.user?.authInfo?.token?.payload?.ext_attr?.zdn; super.registerHandlers(srv); } + LOG.info(`[INFO] [registerHandlers] Registering SDM handlers for service=${srv.name}`); // Prevent duplicate registrations when one entity has multiple attachment compositions this._registeredEntityHandlers = this._registeredEntityHandlers || new Set(); this._registeredTargetHandlers = this._registeredTargetHandlers || new Set(); diff --git a/lib/util/index.js b/lib/util/index.js index 74479835..84175e79 100644 --- a/lib/util/index.js +++ b/lib/util/index.js @@ -3,6 +3,7 @@ const NodeCache = require("node-cache"); const { sdmAnnotationAdditionalpropertyName, sdmAnnotationAdditionalproperty, sdmAnnotationUseClientCredential } = require("./messageConsts"); const cache = new NodeCache(); const { jwtBearerToken, serviceToken, decodeJwt } = require('@sap-cloud-sdk/connectivity'); +const LOG = cds.log('sdm'); function isRepositoryVersioned(repoInfo, repositoryId) { let repoType = repoInfo.data[repositoryId].capabilities["capabilityContentStreamUpdatability"] @@ -12,6 +13,7 @@ function isRepositoryVersioned(repoInfo, repositoryId) { repoType = "non-versioned"; } saveRepoToCache(repositoryId, repoType); + LOG.debug(`[DEBUG] [isRepositoryVersioned] repositoryId=${repositoryId} type=${repoType}`); return repoType === "versioned" ? true : false; } @@ -26,10 +28,12 @@ function getConfigurations() { // Check if the environment variable is present const repositoryId = process.env.REPOSITORY_ID; if (repositoryId) { + LOG.debug(`[DEBUG] [getConfigurations] Using REPOSITORY_ID env var: ${repositoryId}`); return { repositoryId: repositoryId }; } else { - // If not present, return settings from cds.env.requires["sdm"] - return cds.env.requires?.["sdm"]?.settings || {}; + const settings = cds.env.requires?.["sdm"]?.settings || {}; + LOG.debug(`[DEBUG] [getConfigurations] Using cds.env settings repositoryId=${settings.repositoryId}`); + return settings; } } @@ -239,6 +243,7 @@ async function transformSDMServiceBindingToJWTBearerCredentialsDestination(servi // Extract tenant subdomain and replace provider subdomain in UAA URL for multi-tenant support let uaaUrl = service.credentials.uaa.url; const subdomain = cds.context?.user?.authInfo?.token?.payload?.ext_attr?.zdn; + LOG.debug(`[DEBUG] [transformJWTBearerDestination] subdomain=${subdomain} service=${service.name}`); if (subdomain && uaaUrl.includes('://')) { const providerSubdomain = uaaUrl.substring(uaaUrl.indexOf('://') + 3, uaaUrl.indexOf('.')); uaaUrl = uaaUrl.replace(providerSubdomain, subdomain); @@ -251,6 +256,7 @@ async function transformSDMServiceBindingToJWTBearerCredentialsDestination(servi } }; const token = await jwtBearerToken(userJwt, transformedService, options); + LOG.info(`[INFO] [transformJWTBearerDestination] Token acquired for service=${service.name}`); return buildOAuth2JWTBearerDestination( token, uaaUrl, @@ -262,6 +268,7 @@ async function transformSDMServiceBindingToClientCredentialsDestination(service, let uaaUrl = service.credentials.uaa.url; if (!subdomain) subdomain = cds.context?.user?.authInfo?.token?.payload?.ext_attr?.zdn; + LOG.debug(`[DEBUG] [transformClientCredentialsDestination] subdomain=${subdomain} service=${service.name}`); if (subdomain && uaaUrl.includes('://')) { const providerSubdomain = uaaUrl.substring(uaaUrl.indexOf('://') + 3, uaaUrl.indexOf('.')); uaaUrl = uaaUrl.replace(providerSubdomain, subdomain); @@ -275,6 +282,7 @@ async function transformSDMServiceBindingToClientCredentialsDestination(service, }; const token = await serviceToken(transformedService, { ...options,jwt: { ext_attr: { zdn: subdomain } }}); + LOG.info(`[INFO] [transformClientCredentialsDestination] Token acquired for service=${service.name}`); return buildClientCredentialsDestination( token, uaaUrl, @@ -348,8 +356,10 @@ function _getVcapServices() { function getSdmInstanceName() { const jsonData = _getVcapServices(); if (jsonData?.sdm && jsonData.sdm.length > 0) { + LOG.debug(`[DEBUG] [getSdmInstanceName] Found SDM instance: ${jsonData.sdm[0].name}`); return jsonData.sdm[0].name; } + LOG.warn('[WARN] [getSdmInstanceName] No SDM service instance found in VCAP_SERVICES'); return null; } @@ -368,10 +378,16 @@ function isClientCredentialForced(req, attachmentsEntity) { // Explicit entity wins — caller knows which composition it's working with, // so per-composition selection is honored even when the parent has multiple // attachment compositions with different annotations. - if (attachmentsEntity) - return attachmentsEntity[sdmAnnotationUseClientCredential] === true; + if (attachmentsEntity) { + const forced = attachmentsEntity[sdmAnnotationUseClientCredential] === true; + LOG.debug(`[DEBUG] [isClientCredentialForced] entity=${attachmentsEntity.name} forced=${forced}`); + return forced; + } // Direct attachment-target call (e.g. CREATE on Incidents.references). - if (req.target?.[sdmAnnotationUseClientCredential] === true) return true; + if (req.target?.[sdmAnnotationUseClientCredential] === true) { + LOG.debug(`[DEBUG] [isClientCredentialForced] target=${req.target.name} forced=true`); + return true; + } // Parent-entity fallback (rename / SAVE handlers that haven't been threaded // with the explicit entity): scan attachment compositions on req.target. const elements = req.target?.elements; @@ -379,7 +395,10 @@ function isClientCredentialForced(req, attachmentsEntity) { for (const element of Object.values(elements)) { if (element?.type === 'cds.Composition' && element.target) { const targetDef = cds.model.definitions[element.target]; - if (targetDef?.[sdmAnnotationUseClientCredential] === true) return true; + if (targetDef?.[sdmAnnotationUseClientCredential] === true) { + LOG.debug(`[DEBUG] [isClientCredentialForced] composition target=${element.target} forced=true`); + return true; + } } } } diff --git a/test/lib/handler/index.test.js b/test/lib/handler/index.test.js index c0513b2e..82dd4c50 100644 --- a/test/lib/handler/index.test.js +++ b/test/lib/handler/index.test.js @@ -1,5 +1,13 @@ const { executeHttpRequest } = require("@sap-cloud-sdk/http-client"); jest.mock("@sap-cloud-sdk/http-client"); +jest.mock("@sap/cds", () => ({ + log: jest.fn(() => ({ + debug: jest.fn(), + info: jest.fn(), + warn: jest.fn(), + error: jest.fn(), + })), +})); jest.mock("node-cache", () => { return jest.fn().mockImplementation(() => ({ get: jest.fn(), diff --git a/test/lib/mtx/server.test.js b/test/lib/mtx/server.test.js index 4fb1dc95..649fe5e2 100644 --- a/test/lib/mtx/server.test.js +++ b/test/lib/mtx/server.test.js @@ -3,6 +3,12 @@ jest.mock('@sap-cloud-sdk/http-client'); jest.mock('../../../lib/util/index'); const path = require('path'); const messageConsts = require('../../../lib/util/messageConsts'); +const createMockLogger = () => ({ + debug: (...args) => console.debug(...args), + info: (...args) => console.info(...args), + warn: (...args) => console.warn(...args), + error: (...args) => console.error(...args), +}); describe('SDM Plugin Onboarding and Offboarding Logic', () => { let mockCds, mockDeploymentService; @@ -66,6 +72,7 @@ describe('SDM Plugin Onboarding and Offboarding Logic', () => { on: jest.fn(), env: MOCK_CDS_ENV, root: MOCK_CDS_ENV.root, + log: jest.fn(() => createMockLogger()), }; jest.doMock(MOCK_CONFIG_PATH, () => MOCK_CONFIG, { virtual: true }); jest.doMock('@sap/cds', () => mockCds); @@ -83,14 +90,20 @@ describe('SDM Plugin Onboarding and Offboarding Logic', () => { require('../../../lib/mtx/server'); const listeningCallback = mockCds.on.mock.calls.find(call => call[0] === 'listening')[1]; await listeningCallback(); - expect(consoleErrorSpy).toHaveBeenCalledWith("Failed to connect to cds.xt.DeploymentService"); + expect(consoleErrorSpy).toHaveBeenCalledWith("[ERROR] Failed to connect to cds.xt.DeploymentService"); }); it('should throw an error if SDMRepositoryConfig.js is invalid', () => { const MOCK_CDS_ROOT = path.resolve(__dirname, '../../..'); const MOCK_CONFIG_PATH = path.join(MOCK_CDS_ROOT, 'SDMRepositoryConfig.js'); jest.doMock(MOCK_CONFIG_PATH, () => ({}), { virtual: true }); - const badCds = { env: { profile: 'mtx-sidecar' }, root: MOCK_CDS_ROOT, on: jest.fn(), connect: { to: jest.fn() } }; + const badCds = { + env: { profile: 'mtx-sidecar' }, + root: MOCK_CDS_ROOT, + on: jest.fn(), + connect: { to: jest.fn() }, + log: jest.fn(() => createMockLogger()), + }; jest.doMock('@sap/cds', () => badCds); expect(() => require('../../../lib/mtx/server')).toThrow(messageConsts.repositoryConfigurationMissing); }); @@ -144,7 +157,7 @@ describe('SDM Plugin Onboarding and Offboarding Logic', () => { await expect(subscribeCallback({}, req)).resolves.not.toThrow(); // --- FIX: Updated the expected string to match the actual log output --- - const expectedLogMessage = `Repository with name Repository and id ${MOCK_EXTERNAL_ID} already exists. Skipping onboarding.`; + const expectedLogMessage = `[INFO] Repository with name Repository and id ${MOCK_EXTERNAL_ID} already exists. Skipping onboarding.`; // consoleInfoSpy is now guaranteed to be defined here expect(consoleInfoSpy).toHaveBeenCalledWith(expectedLogMessage); }); @@ -161,7 +174,7 @@ describe('SDM Plugin Onboarding and Offboarding Logic', () => { await expect(subscribeCallback({}, req)).resolves.not.toThrow(); - const expectedLogMessage = `Repository with name Repository and id ${MOCK_EXTERNAL_ID} already exists. Skipping onboarding.`; + const expectedLogMessage = `[INFO] Repository with name Repository and id ${MOCK_EXTERNAL_ID} already exists. Skipping onboarding.`; expect(consoleInfoSpy).toHaveBeenCalledWith(expectedLogMessage); }); diff --git a/test/lib/sdm.test.js b/test/lib/sdm.test.js index 04915c03..93e0d2f2 100644 --- a/test/lib/sdm.test.js +++ b/test/lib/sdm.test.js @@ -161,6 +161,12 @@ jest.mock("@sap/cds/lib", () => { model: { definitions: {}, }, + log: jest.fn(() => ({ + debug: jest.fn(), + info: jest.fn(), + warn: jest.fn(), + error: jest.fn(), + })), utils: { uuid: jest.fn(() => "mock-uuid"), }, diff --git a/test/lib/util/index.test.js b/test/lib/util/index.test.js index e5614310..cc64714b 100644 --- a/test/lib/util/index.test.js +++ b/test/lib/util/index.test.js @@ -23,7 +23,20 @@ jest.mock("../../../lib/persistence", () => ({ })); jest.mock("node-cache"); -jest.mock("@sap/cds"); +jest.mock("@sap/cds", () => { + const mockLogger = { + debug: jest.fn(), + info: jest.fn(), + warn: jest.fn(), + error: jest.fn(), + }; + return { + log: jest.fn(() => mockLogger), + env: { requires: {} }, + context: null, + model: { definitions: {} }, + }; +}); jest.mock("@sap/xssec", () => ({ v3: { requests: {