Merge pull request #158 from sanoursa/log-improvements

Mac: prjfs-log improvements
microsoft · Aug 14, 2018 · 9750956 · 9750956
2 parents a08f0ea + 34fc540
commit 9750956
Show file tree

Hide file tree

Showing 5 changed files with 77 additions and 7 deletions.
diff --git a/ProjFS.Mac/PrjFS.xcworkspace/xcshareddata/WorkspaceSettings.xcsettings b/ProjFS.Mac/PrjFS.xcworkspace/xcshareddata/WorkspaceSettings.xcsettings
@@ -0,0 +1,8 @@
+<?xml version="1.0" encoding="UTF-8"?>
+<!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
+<plist version="1.0">
+<dict>
+	<key>IDEWorkspaceSharedSettings_AutocreateContextsIfNeeded</key>
+	<false/>
+</dict>
+</plist>
diff --git a/ProjFS.Mac/PrjFS.xcworkspace/xcshareddata/xcschemes/PrjFS.xcscheme b/ProjFS.Mac/PrjFS.xcworkspace/xcshareddata/xcschemes/PrjFS.xcscheme
@@ -34,6 +34,20 @@
                ReferencedContainer = "container:PrjFSLib/PrjFSLib.xcodeproj">
             </BuildableReference>
          </BuildActionEntry>
+         <BuildActionEntry
+            buildForTesting = "YES"
+            buildForRunning = "YES"
+            buildForProfiling = "YES"
+            buildForArchiving = "YES"
+            buildForAnalyzing = "YES">
+            <BuildableReference
+               BuildableIdentifier = "primary"
+               BlueprintIdentifier = "D308477D20B4431200F69E92"
+               BuildableName = "prjfs-log"
+               BlueprintName = "prjfs-log"
+               ReferencedContainer = "container:PrjFSLib/PrjFSLib.xcodeproj">
+            </BuildableReference>
+         </BuildActionEntry>
       </BuildActionEntries>
    </BuildAction>
    <TestAction

diff --git a/ProjFS.Mac/PrjFSKext/PrjFSKext/KextLog.cpp b/ProjFS.Mac/PrjFSKext/PrjFSKext/KextLog.cpp
@@ -81,6 +81,11 @@ void KextLog_DeregisterUserClient(PrjFSLogUserClient* userClient)
 
 void KextLog_Printf(KextLog_Level loglevel, const char* fmt, ...)
 {
+    if (nullptr == s_currentUserClient)
+    {
+        return;
+    }
+
     // Stack-allocated message with 128-character string buffer for fast path
     struct KextLog_StackMessageBuffer message = {};
     KextLog_MessageHeader* messagePtr = &message.header;
@@ -122,10 +127,6 @@ void KextLog_Printf(KextLog_Level loglevel, const char* fmt, ...)
             messagePtr->machAbsoluteTimestamp = time;
             s_currentUserClient->sendLogMessage(messagePtr, messageSize);
         }
-        else
-        {
-            kprintf("%s\n", messagePtr->logString);
-        }
     }
     RWLock_ReleaseShared(s_kextLogRWLock);
 

diff --git a/ProjFS.Mac/PrjFSKext/PrjFSKext/KextLog.hpp b/ProjFS.Mac/PrjFSKext/PrjFSKext/KextLog.hpp
@@ -42,5 +42,47 @@ template <typename... args>
 #define KextLog_FileInfo(vnode, format, ...)  ({ _os_log_verify_format_str(format, ##__VA_ARGS__); KextLogFile_Printf(KEXTLOG_INFO, vnode, format " (vnode path: '%s')", ##__VA_ARGS__); })
 #define KextLog_FileNote(vnode, format, ...)  ({ _os_log_verify_format_str(format, ##__VA_ARGS__); KextLogFile_Printf(KEXTLOG_NOTE, vnode, format " (vnode path: '%s')", ##__VA_ARGS__); })
 
+#define KextLog_VnodeOp(vnode, vnodeType, procname, action, message) \
+    do { \
+        if (VDIR == vnodeType) \
+        { \
+            KextLog_FileNote( \
+                vnode, \
+                message ". Proc name: %s. Directory vnode action: %s%s%s%s%s%s%s%s%s%s%s%s%s \n    ", \
+                procname, \
+                (action & KAUTH_VNODE_LIST_DIRECTORY)       ? " \n    KAUTH_VNODE_LIST_DIRECTORY" : "", \
+                (action & KAUTH_VNODE_ADD_FILE)             ? " \n    KAUTH_VNODE_ADD_FILE" : "", \
+                (action & KAUTH_VNODE_SEARCH)               ? " \n    KAUTH_VNODE_SEARCH" : "", \
+                (action & KAUTH_VNODE_DELETE)               ? " \n    KAUTH_VNODE_DELETE" : "", \
+                (action & KAUTH_VNODE_ADD_SUBDIRECTORY)     ? " \n    KAUTH_VNODE_ADD_SUBDIRECTORY" : "", \
+                (action & KAUTH_VNODE_DELETE_CHILD)         ? " \n    KAUTH_VNODE_DELETE_CHILD" : "", \
+                (action & KAUTH_VNODE_READ_ATTRIBUTES)      ? " \n    KAUTH_VNODE_READ_ATTRIBUTES" : "", \
+                (action & KAUTH_VNODE_WRITE_ATTRIBUTES)     ? " \n    KAUTH_VNODE_WRITE_ATTRIBUTES" : "", \
+                (action & KAUTH_VNODE_READ_EXTATTRIBUTES)   ? " \n    KAUTH_VNODE_READ_EXTATTRIBUTES" : "", \
+                (action & KAUTH_VNODE_WRITE_EXTATTRIBUTES)  ? " \n    KAUTH_VNODE_WRITE_EXTATTRIBUTES" : "", \
+                (action & KAUTH_VNODE_READ_SECURITY)        ? " \n    KAUTH_VNODE_READ_SECURITY" : "", \
+                (action & KAUTH_VNODE_WRITE_SECURITY)       ? " \n    KAUTH_VNODE_WRITE_SECURITY" : "", \
+                (action & KAUTH_VNODE_TAKE_OWNERSHIP)       ? " \n    KAUTH_VNODE_TAKE_OWNERSHIP" : ""); \
+        } \
+        else \
+        { \
+            KextLog_FileNote( \
+                vnode, \
+                message ". Proc name: %s. File vnode action: %s%s%s%s%s%s%s%s%s%s%s%s \n    ", \
+                procname, \
+                (action & KAUTH_VNODE_READ_DATA)            ? " \n    KAUTH_VNODE_READ_DATA" : "", \
+                (action & KAUTH_VNODE_WRITE_DATA)           ? " \n    KAUTH_VNODE_WRITE_DATA" : "", \
+                (action & KAUTH_VNODE_EXECUTE)              ? " \n    KAUTH_VNODE_EXECUTE" : "", \
+                (action & KAUTH_VNODE_DELETE)               ? " \n    KAUTH_VNODE_DELETE" : "", \
+                (action & KAUTH_VNODE_APPEND_DATA)          ? " \n    KAUTH_VNODE_APPEND_DATA" : "", \
+                (action & KAUTH_VNODE_READ_ATTRIBUTES)      ? " \n    KAUTH_VNODE_READ_ATTRIBUTES" : "", \
+                (action & KAUTH_VNODE_WRITE_ATTRIBUTES)     ? " \n    KAUTH_VNODE_WRITE_ATTRIBUTES" : "", \
+                (action & KAUTH_VNODE_READ_EXTATTRIBUTES)   ? " \n    KAUTH_VNODE_READ_EXTATTRIBUTES" : "", \
+                (action & KAUTH_VNODE_WRITE_EXTATTRIBUTES)  ? " \n    KAUTH_VNODE_WRITE_EXTATTRIBUTES" : "", \
+                (action & KAUTH_VNODE_READ_SECURITY)        ? " \n    KAUTH_VNODE_READ_SECURITY" : "", \
+                (action & KAUTH_VNODE_WRITE_SECURITY)       ? " \n    KAUTH_VNODE_WRITE_SECURITY" : "", \
+                (action & KAUTH_VNODE_TAKE_OWNERSHIP)       ? " \n    KAUTH_VNODE_TAKE_OWNERSHIP" : ""); \
+        } \
+    } while (0)
 
 #endif /* KextLog_h */
diff --git a/ProjFS.Mac/PrjFSLib/prjfs-log/prjfs-log.cpp b/ProjFS.Mac/PrjFSLib/prjfs-log/prjfs-log.cpp
@@ -6,7 +6,6 @@
 #include <IOKit/IOKitLib.h>
 #include <mach/mach_time.h>
 
-
 static const char* KextLogLevelAsString(KextLog_Level level);
 
 int main(int argc, const char * argv[])
@@ -24,7 +23,9 @@ int main(int argc, const char * argv[])
         std::cerr << "Failed to set up shared data queue.\n";
         return 1;
     }
-
+
+    __block int lineCount = 0;
+
     dispatch_source_set_event_handler(dataQueue.dispatchSource, ^{
         struct {
             mach_msg_header_t	msgHdr;
@@ -39,15 +40,19 @@ int main(int argc, const char * argv[])
             {
                 break;
             }
+
             int messageSize = entry->size;
             if (messageSize >= sizeof(KextLog_MessageHeader) + 2)
             {
                 struct KextLog_MessageHeader message = {};
                 memcpy(&message, entry->data, sizeof(KextLog_MessageHeader));
                 const char* messageType = KextLogLevelAsString(message.level);
                 int logStringLength = messageSize - sizeof(KextLog_MessageHeader) - 1;
-                printf("%s: %.*s\n", messageType, logStringLength, entry->data + sizeof(KextLog_MessageHeader));
+
+                printf("(%d: %llu) %s: %.*s\n", lineCount, message.machAbsoluteTimestamp, messageType, logStringLength, entry->data + sizeof(KextLog_MessageHeader));
+                lineCount++;
             }
+
             IODataQueueDequeue(dataQueue.queueMemory, nullptr, nullptr);
         }
     });