Mac: prjfs-log improvements by sanoursa · Pull Request #158 · microsoft/VFSForGit

sanoursa · 2018-08-13T21:37:04Z

Build prjfs-log under the same scheme as everything else
Added a utility function for logging vnode actions
Removed a call to kprintf as it seems to be quite slow
Added line numbers and timestamps to the output of prjfs-log

…r expanding action bitfield, print line number and timestamp, avoid perf hit of kprintf

sanoursa · 2018-08-13T21:38:30Z

ProjFS.Mac/PrjFSKext/PrjFSKext/KauthHandler.cpp

        {
            if (FileFlagsBitIsSet(currentVnodeFileFlags, FileFlags_IsEmpty))
            {
+                KextLog_VnodeOp(currentVnode, vnodeType, procname, action, "Enumerating directory");


I plan to drop these changes in the kext before merging in. This is just to demonstrate that it is working. With these log statements in place, I see the following outputs when enumerating and hydrating:

(3: 1534195840999) Note: Enumerating directory. Proc name: ls. Directory vnode action: KAUTH_VNODE_READ_ATTRIBUTES KAUTH_VNODE_READ_SECURITY (vnode path: '/Users/sanoursa/GVFSTest/src') (4: 1534195858026) Note: Hydrating file. Proc name: bash. File vnode action: KAUTH_VNODE_READ_ATTRIBUTES KAUTH_VNODE_READ_SECURITY (vnode path: '/Users/sanoursa/GVFSTest/src/nuget.config')

wilbaker · 2018-08-13T22:42:30Z

ProjFS.Mac/PrjFSLib/prjfs-log/prjfs-log.cpp

+                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));


@sanoursa, what was your reason for adding line number to the output?

It just made it easier for me to compare different test runs and compare logs. I added the timestamp later, you could definitely argue that we don't need both. What are your thoughts?

I had been thinking we wouldn't need line numbers (text editors can provide that) but I can seen the benefit now to keeping the line numbers because we expect the log message to contain new lines.

I think we can keep the line numbers in

Yeah, I can see the value in keeping the line numbers. I vote to keep them in too 👍

Now that you mention it, I think that (multiline traces) is why I added it :-). Hard to remember to the way back from before vacation.

For what it's worth, there is also a timestamp field in the message itself. This is in units of Mach Absolute Time, which is a monotonically increasing clock as opposed to one linked to system time. This time stamp of course also reflects the time when the kernel generated the log message, not when it arrived in the logging daemon. Given we're just outputting seconds here, using the Mach timestamp may be closer to what we want, although I'm of course not exactly sure what it is you do want. One major difference would be that it's not in seconds since midnight, but (nano-)seconds since some arbitrary time, such as the time when the logging daemon started.

Ah it probably makes sense to use that then. I just wanted to be able to see relative timings of events. I'll clean that up before merging.

wilbaker · 2018-08-13T22:45:26Z

ProjFS.Mac/PrjFSKext/PrjFSKext/KextLog.hpp

+                (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" : ""); \


How messy would the output be to separate these with | rather than newlines?

Depends on the event. Sometimes we'll see 3-4 actions in a single kauth event. I'm not opposed to reformatting this though.

I'm good with going what you have now and we can see how it feels in practice

Yep feel free to clean it up if the multiple lines gets to be too much

wilbaker · 2018-08-13T22:49:25Z

ProjFS.Mac/PrjFSLib/prjfs-log/prjfs-log.cpp

    }
-
+
+    __block int lineCount = 0;


Is the __block required here because of something with Objective-C?

Not Objective-C per se. Apple's C++ compiler has an extension to support blocks, which is how we can call the dispatch_source_set_event_handler function down below. This __block flag is required to indicate that you want to be able to modify a variable inside a block.

Ahh okay thanks! I missed that dispatch_source_set_event_handler was in a block.

pmj

Looks good to me.

pmj · 2018-08-14T10:34:31Z

ProjFS.Mac/PrjFSLib/prjfs-log/prjfs-log.cpp

+                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));


For what it's worth, there is also a timestamp field in the message itself. This is in units of Mach Absolute Time, which is a monotonically increasing clock as opposed to one linked to system time. This time stamp of course also reflects the time when the kernel generated the log message, not when it arrived in the logging daemon. Given we're just outputting seconds here, using the Mach timestamp may be closer to what we want, although I'm of course not exactly sure what it is you do want. One major difference would be that it's not in seconds since midnight, but (nano-)seconds since some arbitrary time, such as the time when the logging daemon started.

Includes changes from microsoft#158 and microsoft#159. Signed-off-by: Derrick Stolee <dstolee@microsoft.com>

Log improvements: build everything under one target, added utility fo…

9807d51

…r expanding action bitfield, print line number and timestamp, avoid perf hit of kprintf

sanoursa added domain: kext domain: user-mode labels Aug 13, 2018

sanoursa commented Aug 13, 2018

View reviewed changes

wilbaker reviewed Aug 13, 2018

View reviewed changes

wilbaker approved these changes Aug 13, 2018

View reviewed changes

nickgra approved these changes Aug 13, 2018

View reviewed changes

sanoursa force-pushed the log-improvements branch from ad3f3d1 to 9807d51 Compare August 13, 2018 23:28

pmj approved these changes Aug 14, 2018

View reviewed changes

Print the timestamp in the message rather than the current time

34fc540

sanoursa force-pushed the log-improvements branch from 9c4fbc1 to 34fc540 Compare August 14, 2018 17:29

sanoursa merged commit 9750956 into microsoft:master Aug 14, 2018

sanoursa deleted the log-improvements branch August 14, 2018 19:51

pmj mentioned this pull request Aug 16, 2018

Mac kext logging: Make time stamps more human readable #177

Merged

jrbriggs mentioned this pull request Oct 12, 2018

Merge milestones/M142 to releases/shipped #381

Merged

derrickstolee added a commit to derrickstolee/VFSForGit that referenced this pull request Jul 22, 2019

Update Git to include tracing updates

0dcacf7

Includes changes from microsoft#158 and microsoft#159. Signed-off-by: Derrick Stolee <dstolee@microsoft.com>

Conversation

sanoursa commented Aug 13, 2018

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

pmj left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants