0
answers

I am trying to process the logs collected from MacOX kernel using the method described on page 251 of the guide, using /usr/bin/log.
I pretty much copied the entire code block, including xm_multiline and xm_json modules.
The problem I am running into is that parse_json throws an error for a very specific message and I don't understand what it doesn't like about it. It ONLY complains about this event, while successfully processing others. First the error:
2019-02-06 11:47:19 ERROR failed to parse json string, parse error: invalid object key (must be a string); pple.duetactivityscheduler", }; (right here) ------^; [{; "category" : "scoring",; "processImageUUID" : "C8A8C46F-C86F-3DCE-AA7F-5128FEC80F95",; "processUniqueID" : 104,; "threadID" : 322877,; "timestamp" : "2019-02-06 11:47:19.133462-0500",; "traceID" : 1264507192737796,; "messageType" : "Default",; "senderProgramCounter" : 143258,; "processID" : 104,; "machTimestamp" : 10284775415304436,; "timezoneName" : "",; "subsystem" : "com.apple.duetactivityscheduler",;}]

Seems like it only complains about the events with subsystem of "com.apple.duetactivityscheduler.

I was able to view one of those events and nothing looks out of the ordinary for me:

{
"category" : "lifecycle",
"processImageUUID" : "C8A8C46F-C86F-3DCE-AA7F-5128FEC80F95",
"processUniqueID" : 104,
"threadID" : 324554,
"timestamp" : "2019-02-06 11:54:38.540442-0500",
"traceID" : 1258391159308292,
"messageType" : "Default",
"senderProgramCounter" : 49785,
"processID" : 104,
"machTimestamp" : 10285214841060059,
"timezoneName" : "",
"subsystem" : "com.apple.duetactivityscheduler",
"eventMessage" : "CANCELED: 0:com.apple.timed.ntp.needed:B67ADB <private>!",
"senderImageUUID" : "B94808C8-E8F6-349C-9CCF-2C2C3EF30A24",
"processImagePath" : "\/usr\/libexec\/dasd",
"senderImagePath" : "\/System\/Library\/DuetActivityScheduler\/Scheduler\/DuetActivitySchedulerDaemon.bundle\/Contents\/MacOS\/DuetActivitySchedulerDaemon"
}

AskedFebruary 6, 2019 - 6:12pm

Comments (6)

  • b0ti's picture
    (NXLog)

    The issue seems to be evident from the error message:

    2019-02-06 11:47:19 ERROR failed to parse json string, parse error: invalid object key (must be a string);
     pple.duetactivityscheduler", };
            (right here) ------^;
    

    There is an extra comma after the last key in the JSON record.

    February 7, 2019 - 11:11am
  • b0ti's picture
    (NXLog)

    Do you have any tips on how this can be reproduced? Apparently the issue here is that parse_json() receives an incomplete JSON record for some reason.

    March 2, 2019 - 10:24am
  • gportnoy's picture

    So this is on a Mac running 10.14 (Mojave). It seems to be caused by com.apple.duetactivityscheduler subsystem and appears to happen every 5 minutes for me. The eventMessage field contains one of these 3 strings: NetworkQualityPolicy, DeviceActivityPolicy, PowerNapPolicy. Below are a few sample events I was able to find by running the following:
    sudo log show --predicate 'subsystem == "com.apple.duetactivityscheduler" && eventMessage contains "PowerNapPolicy"' --info --style json --last 5m
    My guess is that regex you are doing to remove extra/spare brackets in $raw_event before passing it to parse_json{} are failing due to the contents of the eventMessage field.

    Sample:
    {
    "traceID" : 1588313367117828,
    "eventMessage" : "0:com.apple.MobileAccessoryUpdater.periodicFirmwareCheck:D42464:[\n\t{name: NetworkQualityPolicy, policyWeight: 11.400, response: {Decision: Must Not Proceed, Score: 0.00, Rationale: [{[wiredQuality]: Required:20.00, Observed:0.00},{[wifiQuality]: Required:100.00, Observed:0.00},{[networkPathAvailability]: Required:1.00, Observed:1.00},]}}\n ], FinalDecision: Must Not Proceed}",
    "eventType" : "logEvent",
    "source" : null,
    "formatString" : "%{public}@:[\n%{public}s ], FinalDecision: %{public}@}",
    "activityIdentifier" : 0,
    "subsystem" : "com.apple.duetactivityscheduler",
    "category" : "scoring",
    "threadID" : 65909,
    "senderImageUUID" : "23CD56DA-C3FC-3A8B-A3DC-0CE5037AE5AB",
    "backtrace" : {
    "frames" : [
    {
    "imageOffset" : 155066,
    "imageUUID" : "23CD56DA-C3FC-3A8B-A3DC-0CE5037AE5AB"
    }
    ]
    },
    "processImagePath" : "\/usr\/libexec\/dasd",
    "senderImagePath" : "\/System\/Library\/DuetActivityScheduler\/Scheduler\/DuetActivitySchedulerDaemon.bundle\/Contents\/MacOS\/DuetActivitySchedulerDaemon",
    "timestamp" : "2019-03-04 11:26:28.821801-0500",
    "machTimestamp" : 249098857809818,
    "messageType" : "Default",
    "processImageUUID" : "175E90D7-F698-33F2-82FA-F056EEB67A2D",
    "processID" : 110,
    "senderProgramCounter" : 155066,
    "parentActivityIdentifier" : 0,
    "timezoneName" : ""
    },{
    "traceID" : 1588313367117828,
    "eventMessage" : "0:com.apple.coreduetd.people:818B15:[\n\t{name: DeviceActivityPolicy, policyWeight: 20.000, response: {Decision: Must Not Proceed, Score: 0.00, Rationale: [{deviceActivity == 1}]}}\n ], FinalDecision: Must Not Proceed}",
    "eventType" : "logEvent",
    "source" : null,
    "formatString" : "%{public}@:[\n%{public}s ], FinalDecision: %{public}@}",
    "activityIdentifier" : 0,
    "subsystem" : "com.apple.duetactivityscheduler",
    "category" : "scoring",
    "threadID" : 67431,
    "senderImageUUID" : "23CD56DA-C3FC-3A8B-A3DC-0CE5037AE5AB",
    "backtrace" : {
    "frames" : [
    {
    "imageOffset" : 155066,
    "imageUUID" : "23CD56DA-C3FC-3A8B-A3DC-0CE5037AE5AB"
    }
    ]
    },
    "processImagePath" : "\/usr\/libexec\/dasd",
    "senderImagePath" : "\/System\/Library\/DuetActivityScheduler\/Scheduler\/DuetActivitySchedulerDaemon.bundle\/Contents\/MacOS\/DuetActivitySchedulerDaemon",
    "timestamp" : "2019-03-04 11:31:09.979275-0500",
    "machTimestamp" : 249380015283210,
    "messageType" : "Default",
    "processImageUUID" : "175E90D7-F698-33F2-82FA-F056EEB67A2D",
    "processID" : 110,
    "senderProgramCounter" : 155066,
    "parentActivityIdentifier" : 0,
    "timezoneName" : ""
    },{
    "traceID" : 1588313367117828,
    "eventMessage" : "0:com.apple.apsd.apprefresh:27B1FF:[\n\t{name: PowerNapPolicy, policyWeight: 5.000, response: {Decision: Must Not Proceed, Score: 0.00, Rationale: [{(inADarkWake == 0 AND appRefresh == 1) AND wakeState == \"0x1f\"}]}}\n ], FinalDecision: Must Not Proceed}",
    "eventType" : "logEvent",
    "source" : null,
    "formatString" : "%{public}@:[\n%{public}s ], FinalDecision: %{public}@}",
    "activityIdentifier" : 0,
    "subsystem" : "com.apple.duetactivityscheduler",
    "category" : "scoring",
    "threadID" : 67431,
    "senderImageUUID" : "23CD56DA-C3FC-3A8B-A3DC-0CE5037AE5AB",
    "backtrace" : {
    "frames" : [
    {
    "imageOffset" : 155066,
    "imageUUID" : "23CD56DA-C3FC-3A8B-A3DC-0CE5037AE5AB"
    }
    ]
    },
    "processImagePath" : "\/usr\/libexec\/dasd",
    "senderImagePath" : "\/System\/Library\/DuetActivityScheduler\/Scheduler\/DuetActivitySchedulerDaemon.bundle\/Contents\/MacOS\/DuetActivitySchedulerDaemon",
    "timestamp" : "2019-03-04 11:31:09.980102-0500",
    "machTimestamp" : 249380016110579,
    "messageType" : "Default",
    "processImageUUID" : "175E90D7-F698-33F2-82FA-F056EEB67A2D",
    "processID" : 110,
    "senderProgramCounter" : 155066,
    "parentActivityIdentifier" : 0,
    "timezoneName" : ""
    }

    March 4, 2019 - 5:40pm
  • b0ti's picture
    (NXLog)

    The following should work better:

        <Exec>
            $raw_event =~ s/^\[{|},{/{/;
            $raw_event =~ s/\}]$//;
            $raw_event = $raw_event + "\n}";
            parse_json();
        </Exec>
    

    Can you test this out?

    March 6, 2019 - 12:01pm
  • gportnoy's picture

    Some more testing and it appears that the problem is actually somewhere within xm_multiline. For the life of me I can't tell what it doesn't like, but when I commented out the recommended $raw_event transformations and just configured $raw=$raw_event to send the raw event directly to the output, the sample events end up being broken up after traceID:

    {"EventReceivedTime":"2019-03-06 10:19:38","SourceModuleName":"Kernel","SourceModuleType":"im_exec","raw":"},{\n \"traceID\" : 1588313367117828,"}
    {"EventReceivedTime":"2019-03-06 10:19:38","SourceModuleName":"Kernel","SourceModuleType":"im_exec","raw":" \"eventMessage\" : \"0:com.apple.MobileAccessoryUpdater.periodicFirmwareCheck:EA9401:[\\n\\t{name: NetworkQualityPolicy, policyWeight: 11.400, response: {Decision: Must Not Proceed, Score: 0.00, Rationale: [{[wiredQuality]: Required:20.00, Observed:0.00},{[wifiQuality]: Required:100.00, Observed:0.00},{[networkPathAvailability]: Required:1.00, Observed:1.00},]}}\\n ], FinalDecision: Must Not Proceed}\",\n \"eventType\" : \"logEvent\",\n \"source\" : null,\n \"formatString\" : \"%{public}@:[\\n%{public}s ], FinalDecision: %{public}@}\",\n \"activityIdentifier\" : 0,\n \"subsystem\" : \"com.apple.duetactivityscheduler\",\n \"category\" : \"scoring\",\n \"threadID\" : 193643,\n \"senderImageUUID\" : \"23CD56DA-C3FC-3A8B-A3DC-0CE5037AE5AB\",\n \"backtrace\" : {\n \"frames\" : [\n {\n \"imageOffset\" : 155066,\n \"imageUUID\" : \"23CD56DA-C3FC-3A8B-A3DC-0CE5037AE5AB\"\n }\n ]\n },\n \"processImagePath\" : \"\\/usr\\/libexec\\/dasd\",\n \"senderImagePath\" : \"\\/System\\/Library\\/DuetActivityScheduler\\/Scheduler\\/DuetActivitySchedulerDaemon.bundle\\/Contents\\/MacOS\\/DuetActivitySchedulerDaemon\",\n \"timestamp\" : \"2019-03-06 10:19:38.836309-0500\",\n \"machTimestamp\" : 417895875868704,\n \"messageType\" : \"Default\",\n \"processImageUUID\" : \"175E90D7-F698-33F2-82FA-F056EEB67A2D\",\n \"processID\" : 110,\n \"senderProgramCounter\" : 155066,\n \"parentActivityIdentifier\" : 0,\n \"timezoneName\" : \"\""}

    xm_multiline is defined as:
    <Extension multiline>
    Module xm_multiline
    HeaderLine /^\[{|},{/
    </Extension>

    I dumped the sample events a text file and tried to look for special characters, extra carriage returns, etc, in the data and not seeing anything different about these events that's different from others. This problem ONLY occurs with com.apple.duetactivityscheduler subsystem.

    March 6, 2019 - 5:00pm
  • b0ti's picture
    (NXLog)

    Looks like the regex wasn't perfect. Hopefully this one will behave better:

    <Extension multiline>
        Module      xm_multiline
        HeaderLine  /^\[{|^},{/
    </Extension>
    
    <Input in>
        Module      im_exec
        Command     /usr/bin/log
        Arg         stream
        Arg         --style=json
        Arg         --type=log
        <Exec>
            $raw_event =~ s/^\[{|^},{/{/;
            $raw_event =~ s/\}]$//;
            $raw_event = $raw_event + "\n}";
            parse_json();
        </Exec>
    </Input>
    

    March 13, 2019 - 3:06pm

Answers (0)