From 9807d51d0227ecba0414ed58c9042a18a1b515f7 Mon Sep 17 00:00:00 2001 From: Saeed Noursalehi Date: Mon, 13 Aug 2018 14:34:36 -0700 Subject: [PATCH 1/2] Log improvements: build everything under one target, added utility for expanding action bitfield, print line number and timestamp, avoid perf hit of kprintf --- .../xcshareddata/WorkspaceSettings.xcsettings | 8 ++++ .../xcshareddata/xcschemes/PrjFS.xcscheme | 14 +++++++ ProjFS.Mac/PrjFSKext/PrjFSKext/KextLog.cpp | 9 ++-- ProjFS.Mac/PrjFSKext/PrjFSKext/KextLog.hpp | 42 +++++++++++++++++++ ProjFS.Mac/PrjFSLib/prjfs-log/prjfs-log.cpp | 16 +++++-- 5 files changed, 82 insertions(+), 7 deletions(-) create mode 100644 ProjFS.Mac/PrjFS.xcworkspace/xcshareddata/WorkspaceSettings.xcsettings diff --git a/ProjFS.Mac/PrjFS.xcworkspace/xcshareddata/WorkspaceSettings.xcsettings b/ProjFS.Mac/PrjFS.xcworkspace/xcshareddata/WorkspaceSettings.xcsettings new file mode 100644 index 0000000000..08de0be8d3 --- /dev/null +++ b/ProjFS.Mac/PrjFS.xcworkspace/xcshareddata/WorkspaceSettings.xcsettings @@ -0,0 +1,8 @@ + + + + + IDEWorkspaceSharedSettings_AutocreateContextsIfNeeded + + + diff --git a/ProjFS.Mac/PrjFS.xcworkspace/xcshareddata/xcschemes/PrjFS.xcscheme b/ProjFS.Mac/PrjFS.xcworkspace/xcshareddata/xcschemes/PrjFS.xcscheme index f2ea9f350e..558130ad60 100644 --- 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"> + + + + 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 index 82bead23e8..cf40321b84 100644 --- a/ProjFS.Mac/PrjFSKext/PrjFSKext/KextLog.hpp +++ b/ProjFS.Mac/PrjFSKext/PrjFSKext/KextLog.hpp @@ -42,5 +42,47 @@ template #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 index 8e0f138bc7..10692d6202 100644 --- a/ProjFS.Mac/PrjFSLib/prjfs-log/prjfs-log.cpp +++ b/ProjFS.Mac/PrjFSLib/prjfs-log/prjfs-log.cpp @@ -5,7 +5,7 @@ #include #include #include - +#include static const char* KextLogLevelAsString(KextLog_Level level); @@ -24,7 +24,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,6 +41,7 @@ int main(int argc, const char * argv[]) { break; } + int messageSize = entry->size; if (messageSize >= sizeof(KextLog_MessageHeader) + 2) { @@ -46,8 +49,15 @@ int main(int argc, const char * argv[]) 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)); + + struct timeval tp; + gettimeofday(&tp, NULL); + long int timestamp = tp.tv_sec * 1000 + tp.tv_usec / 1000; + + printf("(%d: %ld) %s: %.*s\n", lineCount, timestamp, messageType, logStringLength, entry->data + sizeof(KextLog_MessageHeader)); + lineCount++; } + IODataQueueDequeue(dataQueue.queueMemory, nullptr, nullptr); } }); From 34fc54037c324879cbb84031111c99a4ff6a50a8 Mon Sep 17 00:00:00 2001 From: Saeed Noursalehi Date: Tue, 14 Aug 2018 10:29:12 -0700 Subject: [PATCH 2/2] Print the timestamp in the message rather than the current time --- ProjFS.Mac/PrjFSLib/prjfs-log/prjfs-log.cpp | 7 +------ 1 file changed, 1 insertion(+), 6 deletions(-) diff --git a/ProjFS.Mac/PrjFSLib/prjfs-log/prjfs-log.cpp b/ProjFS.Mac/PrjFSLib/prjfs-log/prjfs-log.cpp index 10692d6202..220c58858e 100644 --- a/ProjFS.Mac/PrjFSLib/prjfs-log/prjfs-log.cpp +++ b/ProjFS.Mac/PrjFSLib/prjfs-log/prjfs-log.cpp @@ -5,7 +5,6 @@ #include #include #include -#include static const char* KextLogLevelAsString(KextLog_Level level); @@ -49,12 +48,8 @@ int main(int argc, const char * argv[]) memcpy(&message, entry->data, sizeof(KextLog_MessageHeader)); const char* messageType = KextLogLevelAsString(message.level); int logStringLength = messageSize - sizeof(KextLog_MessageHeader) - 1; - - struct timeval tp; - gettimeofday(&tp, NULL); - long int timestamp = tp.tv_sec * 1000 + tp.tv_usec / 1000; - printf("(%d: %ld) %s: %.*s\n", lineCount, timestamp, messageType, logStringLength, entry->data + sizeof(KextLog_MessageHeader)); + printf("(%d: %llu) %s: %.*s\n", lineCount, message.machAbsoluteTimestamp, messageType, logStringLength, entry->data + sizeof(KextLog_MessageHeader)); lineCount++; }