From 6dc8f219bd5d7381b88935dadd6f3f7e5ef8c0f8 Mon Sep 17 00:00:00 2001 From: Joe Date: Sat, 31 Jan 2026 12:06:27 -0600 Subject: [PATCH] Enhance logging for syncback operations and patch applications - Added detailed logging for syncback operations, including additions, removals, and updates, to improve traceability and debugging. - Implemented summary logs for patch applications in both the client and server, capturing the number of changes made. - Enhanced logging in the ChangeBatcher and ApiService to provide insights into property changes and instance updates during syncback processes. - Improved error handling and logging for VFS events to ensure better visibility of file operations. --- plugin/src/ApiContext.lua | 37 +++++++++++++ plugin/src/ChangeBatcher/encodeInstance.lua | 17 ++++++ plugin/src/ChangeBatcher/init.lua | 18 +++++++ plugin/src/Reconciler/applyPatch.lua | 42 +++++++++++++++ plugin/src/ServeSession.lua | 59 ++++++++++++++++++++- src/change_processor.rs | 52 ++++++++++++++++-- src/web/api.rs | 23 ++++++++ 7 files changed, 242 insertions(+), 6 deletions(-) diff --git a/plugin/src/ApiContext.lua b/plugin/src/ApiContext.lua index fbaa0f3f..e222c948 100644 --- a/plugin/src/ApiContext.lua +++ b/plugin/src/ApiContext.lua @@ -177,6 +177,43 @@ end function ApiContext:write(patch) local url = ("%s/api/write"):format(self.__baseUrl) + -- Log what we're sending to the server (syncback/pull) + local addedCount = 0 + for _ in pairs(patch.added) do + addedCount += 1 + end + + -- Only log summary at debug level to reduce verbosity + if #patch.removed > 0 or addedCount > 0 or #patch.updated > 0 then + Log.debug( + "Sending to server: {} removals, {} additions, {} updates", + #patch.removed, + addedCount, + #patch.updated + ) + end + + -- Log individual operations at trace level (very detailed) + for _, removed in ipairs(patch.removed) do + Log.trace("[Syncback] Remove ID: {}", tostring(removed)) + end + + for _, addedInstance in pairs(patch.added) do + local instanceName = addedInstance.name or addedInstance.Name or "unknown" + local instanceClass = addedInstance.className or addedInstance.ClassName or "unknown" + Log.trace("[Syncback] Add {} ({})", instanceName, instanceClass) + end + + for _, update in ipairs(patch.updated) do + local propCount = 0 + if update.changedProperties then + for _ in pairs(update.changedProperties) do + propCount += 1 + end + end + Log.trace("[Syncback] Update ID {} ({} properties)", update.id, propCount) + end + local updated = {} for _, update in ipairs(patch.updated) do local fixedUpdate = { diff --git a/plugin/src/ChangeBatcher/encodeInstance.lua b/plugin/src/ChangeBatcher/encodeInstance.lua index 6644fd12..1617e501 100644 --- a/plugin/src/ChangeBatcher/encodeInstance.lua +++ b/plugin/src/ChangeBatcher/encodeInstance.lua @@ -173,6 +173,11 @@ encodeInstance = function(instance, parentId, _skipPathCheck) return nil end + -- Log encoding at trace level (very detailed) + if not _skipPathCheck then + Log.trace("Encoding for syncback: {} ({})", instance:GetFullName(), instance.ClassName) + end + local properties = {} -- Always try to encode Attributes and Tags for any instance type @@ -262,6 +267,18 @@ encodeInstance = function(instance, parentId, _skipPathCheck) end end + -- Log property count for debugging + local propCount = 0 + for _ in pairs(properties) do + propCount += 1 + end + Log.trace( + " Encoded {} with {} properties, {} children", + instance.Name, + propCount, + #children + ) + return { parent = parentId, name = instance.Name, diff --git a/plugin/src/ChangeBatcher/init.lua b/plugin/src/ChangeBatcher/init.lua index 4c0d7956..dc097fa4 100644 --- a/plugin/src/ChangeBatcher/init.lua +++ b/plugin/src/ChangeBatcher/init.lua @@ -5,6 +5,9 @@ local RunService = game:GetService("RunService") +local Packages = script.Parent.Parent.Packages +local Log = require(Packages.Log) + local PatchSet = require(script.Parent.PatchSet) local createPatchSet = require(script.createPatchSet) @@ -64,8 +67,10 @@ function ChangeBatcher:add(instance, propertyName) if not properties then properties = {} self.__pendingPropertyChanges[instance] = properties + Log.trace("ChangeBatcher: tracking changes to {}", instance:GetFullName()) end + Log.trace("ChangeBatcher: property '{}' changed on {}", propertyName, instance:GetFullName()) properties[propertyName] = true end @@ -96,11 +101,24 @@ function ChangeBatcher:__flush() end local patch = createPatchSet(self.__instanceMap, self.__pendingPropertyChanges, self.__syncSourceOnly) + self.__pendingPropertyChanges = {} if PatchSet.isEmpty(patch) then return nil end + -- Log summary at debug level + local addedCount = 0 + for _ in pairs(patch.added) do + addedCount += 1 + end + Log.debug( + "Two-way sync: {} updates, {} additions, {} removals", + #patch.updated, + addedCount, + #patch.removed + ) + return patch end diff --git a/plugin/src/Reconciler/applyPatch.lua b/plugin/src/Reconciler/applyPatch.lua index 3940a1b6..027b668f 100644 --- a/plugin/src/Reconciler/applyPatch.lua +++ b/plugin/src/Reconciler/applyPatch.lua @@ -27,6 +27,20 @@ local function applyPatch(instanceMap, patch) -- to ensure that referents can be mapped to instances correctly. local deferredRefs = {} + -- Log summary of patch being applied (debug level for summary) + local addCount = 0 + for _ in pairs(patch.added) do + addCount += 1 + end + if #patch.removed > 0 or addCount > 0 or #patch.updated > 0 then + Log.debug( + "Applying patch to Studio: {} removals, {} additions, {} updates", + #patch.removed, + addCount, + #patch.updated + ) + end + for _, removedIdOrInstance in ipairs(patch.removed) do -- Skip auto-created instances that shouldn't be synced local instance = if Types.RbxId(removedIdOrInstance) @@ -36,6 +50,11 @@ local function applyPatch(instanceMap, patch) continue end + -- Log the removal (info level for major operations) + local instancePath = if instance then instance:GetFullName() else tostring(removedIdOrInstance) + local instanceClass = if instance then instance.ClassName else "unknown" + Log.info("[Studio] Remove: {} ({})", instancePath, instanceClass) + local removeInstanceSuccess = pcall(function() if Types.RbxId(removedIdOrInstance) then instanceMap:destroyId(removedIdOrInstance) @@ -44,6 +63,7 @@ local function applyPatch(instanceMap, patch) end end) if not removeInstanceSuccess then + Log.warn("[Studio] Remove failed: {}", instancePath) table.insert(unappliedPatch.removed, removedIdOrInstance) end end @@ -81,9 +101,14 @@ local function applyPatch(instanceMap, patch) ) end + -- Log the addition (info level for major operations) + local parentPath = parentInstance:GetFullName() + Log.info("[Studio] Add: {}.{} ({})", parentPath, virtualInstance.Name, virtualInstance.ClassName) + local failedToReify = reifyInstance(deferredRefs, instanceMap, patch.added, id, parentInstance) if not PatchSet.isEmpty(failedToReify) then + Log.warn("[Studio] Add failed: {}.{}", parentPath, virtualInstance.Name) Log.debug("Failed to reify as part of applying a patch: {:#?}", failedToReify) PatchSet.assign(unappliedPatch, failedToReify) end @@ -94,10 +119,27 @@ local function applyPatch(instanceMap, patch) if instance == nil then -- We can't update an instance that doesn't exist. + Log.warn("[Studio] Update failed: Instance with ID {} not found", update.id) table.insert(unappliedPatch.updated, update) continue end + -- Log the update (debug level for property details to reduce verbosity) + local instancePath = instance:GetFullName() + local propList = {} + if update.changedName then + table.insert(propList, "Name") + end + if update.changedClassName then + table.insert(propList, "ClassName") + end + if update.changedProperties then + for propName, _ in pairs(update.changedProperties) do + table.insert(propList, propName) + end + end + Log.debug("[Studio] Update: {} - {}", instancePath, table.concat(propList, ", ")) + -- Pause updates on this instance to avoid picking up our changes when -- two-way sync is enabled. instanceMap:pauseInstance(instance) diff --git a/plugin/src/ServeSession.lua b/plugin/src/ServeSession.lua index aedeca9e..058829cb 100644 --- a/plugin/src/ServeSession.lua +++ b/plugin/src/ServeSession.lua @@ -669,6 +669,24 @@ function ServeSession:__confirmAndApplyInitialPatch(catchUpPatch, serverInfo) -- New: Apply based on per-item selections local selections = userDecision.selections or {} + -- Log selection summary (debug level) + local pushCount, pullCount, ignoreCount = 0, 0, 0 + for _, selection in pairs(selections) do + if selection == "push" then + pushCount += 1 + elseif selection == "pull" then + pullCount += 1 + else + ignoreCount += 1 + end + end + Log.debug( + "User selections: {} push, {} pull, {} ignored", + pushCount, + pullCount, + ignoreCount + ) + -- Build partial patches based on selections local pushPatch = PatchSet.newEmpty() -- Items to apply to Studio local pullPatch = PatchSet.newEmpty() -- Items to send back to Rojo @@ -676,12 +694,15 @@ function ServeSession:__confirmAndApplyInitialPatch(catchUpPatch, serverInfo) -- Process updated items for _, change in catchUpPatch.updated do local selection = selections[change.id] + local instance = self.__instanceMap.fromIds[change.id] + local instancePath = if instance then instance:GetFullName() else "ID:" .. tostring(change.id) + if selection == "push" then -- Apply Rojo changes to Studio + Log.trace("[Push] Update: {}", instancePath) table.insert(pushPatch.updated, change) elseif selection == "pull" and self.__twoWaySync then -- Send Studio state back to Rojo - local instance = self.__instanceMap.fromIds[change.id] if instance then local propertiesToSync = change.changedProperties if self.__syncSourceOnly then @@ -691,6 +712,7 @@ function ServeSession:__confirmAndApplyInitialPatch(catchUpPatch, serverInfo) continue end end + Log.trace("[Pull] Update: {}", instancePath) local update = encodePatchUpdate(instance, change.id, propertiesToSync) if update then table.insert(pullPatch.updated, update) @@ -716,8 +738,12 @@ function ServeSession:__confirmAndApplyInitialPatch(catchUpPatch, serverInfo) -- If we don't have an ID, use the instance itself as the key local selection = if id then selections[id] else selections[idOrInstance] + local instancePath = if instance then instance:GetFullName() else "ID:" .. tostring(idOrInstance) + local instanceClass = if instance then instance.ClassName else "unknown" + if selection == "push" then -- Apply Rojo removal to Studio (delete the instance) + Log.trace("[Push] Delete: {}", instancePath) table.insert(pushPatch.removed, idOrInstance) elseif selection == "pull" and self.__twoWaySync then -- Syncback: Create file in Rojo from Studio instance @@ -731,7 +757,8 @@ function ServeSession:__confirmAndApplyInitialPatch(catchUpPatch, serverInfo) local guid = HttpService:GenerateGUID(false) local tempRef = string.gsub(guid, "-", ""):lower() pullPatch.added[tempRef] = encoded - Log.info("Syncback: encoding {:?} for creation in Rojo", instance) + -- Log at info level since this is a major file creation operation + Log.info("[Pull] Create file: {} ({})", instancePath, instanceClass) end else Log.warn("Cannot syncback {:?}: parent not in Rojo tree", instance) @@ -744,11 +771,19 @@ function ServeSession:__confirmAndApplyInitialPatch(catchUpPatch, serverInfo) -- Process added items for id, change in catchUpPatch.added do local selection = selections[id] + local instanceName = change.Name or "unknown" + local instanceClass = change.ClassName or "unknown" + local parentInstance = self.__instanceMap.fromIds[change.Parent] + local parentPath = if parentInstance then parentInstance:GetFullName() else "ID:" .. tostring(change.Parent) + if selection == "push" then -- Apply Rojo addition to Studio + Log.trace("[Push] Add: {}.{}", parentPath, instanceName) pushPatch.added[id] = change elseif selection == "pull" and self.__twoWaySync then -- Don't add in Studio, remove from Rojo + -- Log at info level since this is a major file deletion operation + Log.info("[Pull] Delete file: {}.{} ({})", parentPath, instanceName, instanceClass) table.insert(pullPatch.removed, id) end -- "ignore" items are skipped @@ -760,11 +795,31 @@ function ServeSession:__confirmAndApplyInitialPatch(catchUpPatch, serverInfo) -- Apply push items to Studio if not PatchSet.isEmpty(pushPatch) then + local addCount = 0 + for _ in pairs(pushPatch.added) do + addCount += 1 + end + Log.debug( + "Applying to Studio: {} additions, {} removals, {} updates", + addCount, + #pushPatch.removed, + #pushPatch.updated + ) self:__applyPatch(pushPatch) end -- Send pull items back to Rojo server if self.__twoWaySync and not PatchSet.isEmpty(pullPatch) then + local addCount = 0 + for _ in pairs(pullPatch.added) do + addCount += 1 + end + Log.info( + "Sending to Rojo: {} file creations, {} file deletions, {} updates", + addCount, + #pullPatch.removed, + #pullPatch.updated + ) return self.__apiContext:write(pullPatch) end diff --git a/src/change_processor.rs b/src/change_processor.rs index 85f1a6e1..a5d9fb58 100644 --- a/src/change_processor.rs +++ b/src/change_processor.rs @@ -158,7 +158,13 @@ impl JobThreadContext { } fn handle_vfs_event(&self, event: VfsEvent) { - log::trace!("Vfs event: {:?}", event); + // Log VFS events at debug level (not too verbose, but visible when needed) + match &event { + VfsEvent::Create(path) => log::debug!("VFS: File created: {}", path.display()), + VfsEvent::Write(path) => log::debug!("VFS: File modified: {}", path.display()), + VfsEvent::Remove(path) => log::debug!("VFS: File removed: {}", path.display()), + _ => log::trace!("VFS: Other event: {:?}", event), + } // Update the VFS immediately with the event. self.vfs @@ -169,7 +175,19 @@ impl JobThreadContext { // of the tree. Calculate and apply all of these changes. let applied_patches = match event { VfsEvent::Create(path) | VfsEvent::Write(path) => { - self.apply_patches(self.vfs.canonicalize(&path).unwrap()) + // The path might have been deleted before we could process this event + // (e.g., during syncback when directories are being removed). + // In that case, just skip this event. + match self.vfs.canonicalize(&path) { + Ok(canonical_path) => self.apply_patches(canonical_path), + Err(_) => { + log::trace!( + "Skipping create/write event for {:?} - path no longer exists", + path + ); + Vec::new() + } + } } VfsEvent::Remove(path) => { // MemoFS does not track parent removals yet, so we can canonicalize @@ -196,13 +214,34 @@ impl JobThreadContext { } }; + // Log patch application summary at debug level + if !applied_patches.is_empty() { + let total_added: usize = applied_patches.iter().map(|p| p.added.len()).sum(); + let total_removed: usize = applied_patches.iter().map(|p| p.removed.len()).sum(); + let total_updated: usize = applied_patches.iter().map(|p| p.updated.len()).sum(); + if total_added > 0 || total_removed > 0 || total_updated > 0 { + log::debug!( + "VFS event applied: {} added, {} removed, {} updated", + total_added, + total_removed, + total_updated + ); + } + } + // Notify anyone listening to the message queue about the changes we // just made. self.message_queue.push_messages(&applied_patches); } fn handle_tree_event(&self, patch_set: PatchSet) { - log::trace!("Applying PatchSet from client: {:#?}", patch_set); + // Log incoming patch summary at debug level + log::debug!( + "Processing client patch: {} removed, {} added, {} updated", + patch_set.removed_instances.len(), + patch_set.added_instances.len(), + patch_set.updated_instances.len() + ); let applied_patch = { let mut tree = self.tree.lock().unwrap(); @@ -212,6 +251,7 @@ impl JobThreadContext { if let Some(instigating_source) = &instance.metadata().instigating_source { match instigating_source { InstigatingSource::Path(path) => { + log::info!("Two-way sync: Removing file {}", path.display()); if let Err(err) = fs::remove_file(path) { log::error!( "Failed to remove file {:?} for instance {:?}: {}", @@ -264,6 +304,10 @@ impl JobThreadContext { match instigating_source { InstigatingSource::Path(path) => { if let Some(Variant::String(value)) = changed_value { + log::info!( + "Two-way sync: Writing Source to {}", + path.display() + ); if let Err(err) = fs::write(path, value) { log::error!( "Failed to write Source to {:?} for instance {:?}: {}", @@ -290,7 +334,7 @@ impl JobThreadContext { ); } } else { - log::warn!("Cannot change properties besides BaseScript.Source."); + log::trace!("Skipping non-Source property change: {}", key); } } } else { diff --git a/src/web/api.rs b/src/web/api.rs index 899d5c11..d337ba5e 100644 --- a/src/web/api.rs +++ b/src/web/api.rs @@ -264,6 +264,29 @@ impl ApiService { } } + // Log property updates being synced back + for update in &request.updated { + let prop_names: Vec<&str> = update + .changed_properties + .keys() + .map(|k| k.as_str()) + .collect(); + if !prop_names.is_empty() { + log::info!( + "Syncback: Updating properties for instance {:?}: {}", + update.id, + prop_names.join(", ") + ); + } + if update.changed_name.is_some() { + log::info!( + "Syncback: Renaming instance {:?} to {:?}", + update.id, + update.changed_name + ); + } + } + let updated_instances = request .updated .into_iter()