1
response

Hello NXLog community!

I was hoping you can help me with the problem I've been dealing with.

I'm trying to configure NXLog to collect Sharepoint audit logs using a PowerShell script following the offical documentation here: https://nxlog.co/documentation/nxlog-user-guide/sharepoint.html#sharepoint_audit

I have enabled Sharepoint audit logging, configured the PowerShell script and the NXLog input, but when I'm trying to run it it does not work. Can you please help me figure out what I'm doing wrong here?

Here is what I'm getting in the log file:

2020-03-05 09:42:14 ERROR failed to parse json string, lexical error: invalid char in json text.;                                       The local farm is not accessibl;                     (right here) ------^; [The local farm is not accessible. Cmdlets with FeatureDependencyId are not registered.]
2020-03-05 09:42:14 ERROR assignment failed at line 40, character 43 in C:\Program Files\Graylog\sidecar\generated\nxlog.conf. statement execution has been aborted; function 'parsedate' failed at line 40, character 42 in C:\Program Files\Graylog\sidecar\generated\nxlog.conf. expression evaluation has been aborted; 'unknown' type argument is invalid
2020-03-05 09:42:14 ERROR failed to parse json string, lexical error: invalid char in json text.;                                       C:\Audit\auditlog.ps1 : An unha;                     (right here) ------^; [C:\Audit\auditlog.ps1 : An unhandled exception occurred!]
2020-03-05 09:42:14 ERROR assignment failed at line 40, character 43 in C:\Program Files\Graylog\sidecar\generated\nxlog.conf. statement execution has been aborted; function 'parsedate' failed at line 40, character 42 in C:\Program Files\Graylog\sidecar\generated\nxlog.conf. expression evaluation has been aborted; 'unknown' type argument is invalid
2020-03-05 09:42:14 ERROR failed to parse json string, lexical error: invalid char in json text.;                                       + CategoryInfo          : NotSp;                     (right here) ------^; [    + CategoryInfo          : NotSpecified: (:) [Write-Error], WriteErrorExcep ]
2020-03-05 09:42:14 ERROR assignment failed at line 40, character 43 in C:\Program Files\Graylog\sidecar\generated\nxlog.conf. statement execution has been aborted; function 'parsedate' failed at line 40, character 42 in C:\Program Files\Graylog\sidecar\generated\nxlog.conf. expression evaluation has been aborted; 'unknown' type argument is invalid
2020-03-05 09:42:14 ERROR failed to parse json string, lexical error: invalid string in json text.;                                       tion;                     (right here) ------^; [   tion]
2020-03-05 09:42:14 ERROR assignment failed at line 40, character 43 in C:\Program Files\Graylog\sidecar\generated\nxlog.conf. statement execution has been aborted; function 'parsedate' failed at line 40, character 42 in C:\Program Files\Graylog\sidecar\generated\nxlog.conf. expression evaluation has been aborted; 'unknown' type argument is invalid
2020-03-05 09:42:14 ERROR failed to parse json string, lexical error: invalid char in json text.;                                       + FullyQualifiedErrorId : Micro;                     (right here) ------^; [    + FullyQualifiedErrorId : Microsoft.PowerShell.Commands.WriteErrorExceptio ]
2020-03-05 09:42:14 ERROR assignment failed at line 40, character 43 in C:\Program Files\Graylog\sidecar\generated\nxlog.conf. statement execution has been aborted; function 'parsedate' failed at line 40, character 42 in C:\Program Files\Graylog\sidecar\generated\nxlog.conf. expression evaluation has been aborted; 'unknown' type argument is invalid
2020-03-05 09:42:14 ERROR failed to parse json string, lexical error: invalid string in json text.;                                       n,auditlog.ps1;                     (right here) ------^; [   n,auditlog.ps1]
2020-03-05 09:42:14 ERROR assignment failed at line 40, character 43 in C:\Program Files\Graylog\sidecar\generated\nxlog.conf. statement execution has been aborted; function 'parsedate' failed at line 40, character 42 in C:\Program Files\Graylog\sidecar\generated\nxlog.conf. expression evaluation has been aborted; 'unknown' type argument is invalid
2020-03-05 09:42:14 ERROR failed to parse json string, parse error: premature EOF;                                        ;                     (right here) ------^; [ ]
2020-03-05 09:42:14 ERROR assignment failed at line 40, character 43 in C:\Program Files\Graylog\sidecar\generated\nxlog.conf. statement execution has been aborted; function 'parsedate' failed at line 40, character 42 in C:\Program Files\Graylog\sidecar\generated\nxlog.conf. expression evaluation has been aborted; 'unknown' type argument is invalid
2020-03-05 09:42:14 ERROR Module audit_powershell got EOF, process exited? 

Here's my config file:

define ROOT C:\Program Files (x86)\nxlog

Moduledir %ROOT%\modules
CacheDir %ROOT%\data
Pidfile %ROOT%\data\nxlog.pid
SpoolDir %ROOT%\data
LogFile %ROOT%\data\nxlog.log
LogLevel INFO

<Extension logrotate>
    Module  xm_fileop
    <Schedule>
        When    @daily
        Exec    file_cycle('%ROOT%\data\nxlog.log', 7);
     </Schedule>
</Extension>


<Extension gelfExt>
  Module xm_gelf
  # Avoid truncation of the short_message field to 64 characters.
  ShortMessageLength 65536
</Extension>

<Extension _json>
    Module  xm_json
</Extension>


<Input audit_powershell>
    Module  im_exec
    Command "C:\Windows\System32\WindowsPowerShell\v1.0\powershell.exe"
    Arg     "-ExecutionPolicy"
    Arg     "Bypass"
    Arg     "-NoProfile"
    Arg     "-File"
    Arg     "C:\Audit\auditlog.ps1"
    <Exec>
        parse_json();
        $EventTime = parsedate($EventTime);
    </Exec>
</Input>

<Output gelf>
    Module om_tcp
    Host 192.168.98.5
    Port 12208
    OutputType  GELF_TCP
    <Exec>
      # These fields are needed for Graylog
      $gl2_source_collector = '3a5aa0c9-aba3-4384-8691-43ed7d1ebbab';
      $collector_node_id = 'Scooby';
    </Exec>
</Output>


<Route route-2>
  Path audit_powershell => gelf
</Route>

And the PowerShell script I've created:

# This script can be used with NXLog to fetch Audit logs via the SharePoint
# API. See the configurable options below. Based on:
# <http://shokochino-sharepointexperience.blogspot.ch/2013/05/create-auditing-reports-in-sharepoint.html>

#Requires -Version 3

# The timestamp is saved to this file for resuming.
$CacheFile = 'C:\Audit\nxlog_sharepoint_auditlog_position.txt'

# The database is queried at this interval in seconds.
$PollInterval = 10

# Allow this many seconds for new logs to be written to database.
$ReadDelay = 30

# Use this to enable debug logging (for testing outside of NXLog).
#$DebugPreference = 'Continue'
################################################################################

# If running 32-bit on a 64-bit system, run 64-bit PowerShell instead.
if ($env:PROCESSOR_ARCHITEW6432 -eq "AMD64") {
    Write-Debug "Running 64-bit PowerShell."
    &"$env:WINDIR\SysNative\WindowsPowerShell\v1.0\powershell.exe" `
    -NonInteractive -NoProfile -ExecutionPolicy Bypass `
    -File "$($myInvocation.InvocationName)" $args
    exit $LASTEXITCODE
}

Add-PSSnapin "Microsoft.SharePoint.Powershell" -ErrorAction Stop

# Return description for event
function Event-Description {
    param( $entry )
    switch ($entry.Event) {
        AuditMaskChange {"The audit flags are changed for the audited object."}
        ChildDelete {"A child of the audited object is deleted."}
        ChildMove {"A child of the audited object is moved."}
        CheckIn {"A document is checked in."}
        'Copy' {"The audited item is copied."}
        Delete {"The audited object is deleted."}
        EventsDeleted {"Some audit entries are deleted from SharePoint database."}
        'Move' {"The audited object is moved."}
        Search {"The audited object is searched."}
        SecGroupCreate {"A group is created for the site collection (this action "`
            + "also generates an Update event)."}
        SecGroupDelete {"A group on the site collection is deleted."}
        SecGroupMemberAdd {"A user is added to a group."}
        SecGroupMemberDelete {"A user is removed from a group."}
        SecRoleBindBreakInherit {"A subsite's inheritance of permission level "`
            + "definitions (that is, role definitions) is severed."}
        SecRoleBindInherit {"A subsite is set to inherit permission level "`
            + "definitions (that is, role definitions) from its parent."}
        SecRoleBindUpdate {"The permissions of a user or group for the audited "`
            + "object are changed."}
        SecRoleDefCreate {"A new permission level (a combination of permissions "`
            + "that are given to people holding a particular role for the site "`
            + "collection) is created."}
        SecRoleDefDelete {"A permission level (a combination of permissions that "`
            + "are given to people holding a particular role for the site "`
            + "collection) is deleted."}
        SecRoleDefModify {"A permission level (a combination of permissions that "`
            + "are given to people holding a particular role for the site "`
            + "collection) is modified."}
        Update {"An existing object is updated."}
        CheckOut {"A document is checked out."}
        View {"The object is viewed by a user."}
        ProfileChange {"Change in a profile that is associated with the object."}
        SchemaChange {"Change in the schema of the object."}
        Undelete {"Restoration of an object from the Recycle Bin."}
        Workflow {"Access of the object as part of a workflow."}
        FileFragmentWrite {"A File Fragment has been written for the file."}
        Custom {"Custom action or event."}
        default {"The event description could not be determined."}
    }
}

# Get audit data from $site in range $start to $end. Timestamps should use
# seconds precision only. A record with timestamp equal to $start time is
# included in output; a record with timestamp equal to $end time is not.
function Get-Audit-Data {
    param( $site, $start, $end )
    Write-Debug "Getting audit log for $site.Url from $start to $end"
    $query = New-Object -TypeName Microsoft.SharePoint.SPAuditQuery($site)
    $query.setRangeStart($start.AddSeconds(-1))
    $query.setRangeEnd($end)
    $coll = $site.Audit.GetEntries($query)
    $root = $site.RootWeb
    for ($i=0; $i -le ($coll.Count)-1 ; $i++) {
        # Get the entry item from the collection
        $entry = $coll.Item($i)
        # Find the current user name
        foreach($User in $root.SiteUsers) {
            if($entry.UserId -eq $User.Id) {
                $UserName = $User.UserLogin
            }
        }
        # Find the item name
        foreach($List in $root.Lists) {
            if($entry.ItemId -eq $List.Id) {
                $ItemName = $List.Title
            }
        }
        # Create hash table
        $record = @{
            # AuditData table fields
            SiteID = $entry.SiteId;
            ItemID = $entry.ItemId;
            ItemType = $entry.ItemType;
            UserID = $entry.UserId;
            AppPrincipalID = $entry.AppPrincipalId;
            MachineName = $entry.MachineName;
            MachineIP = $entry.MachineIP;
            DocLocation = $entry.DocLocation;
            LocationType = $entry.LocationType;
            EventTime = ($entry.Occurred.ToString('o') + "Z");
            Event = $entry.Event;
            EventName = $entry.EventName;
            EventSource = $entry.EventSource;
            SourceName = $entry.SourceName;
            EventData = $entry.EventData;
            # Additional fields
            ItemName = $ItemName;
            Message = Event-Description $entry;
            SiteURL = $site.Url;
            UserName = $UserName;
        }
        # Return record as JSON
        $record | ConvertTo-Json -Compress | Write-Output
    }
}

# Get position timestamp from cache file. On first run, create file using
# current time.
function Get-Position {
    param( $file )
    Try {
        if (Test-Path $file) {
            $time = (Get-Date (Get-Content $file -First 1))
            $time = $time.ToUniversalTime()
            $time = $time.AddTicks(-($time.Ticks % 10000000))
        }
        else {
            $time = [System.DateTime]::UtcNow
            $time = $time.AddTicks(-($time.Ticks % 10000000))
            Save-Position $file $time
        }
        return $time
    }
    Catch {
        Write-Error "Failed to read timestamp from position file."
        exit 1
    }
}

# Save position timestamp to cache file.
function Save-Position {
    param( $file, $time )
    Try { Out-File -FilePath $file -InputObject $time.ToString('o') }
    Catch {
        Write-Error "Failed to write timestamp to position file."
        exit 1
    }
}

# Main
Try {
    $start = Get-Position $CacheFile
    Write-Debug "Got start time of $($start.ToString('o'))."
    $now = [System.DateTime]::UtcNow
    $now = $now.AddTicks(-($now.Ticks % 10000000))
    Write-Debug "Got current time of $($now.ToString('o'))."
    $diff = ($now - $start).TotalSeconds
    # Check whether waiting is required to comply with $ReadDelay.
    if (($diff - $PollInterval) -lt $ReadDelay) {
        $wait = $ReadDelay - $diff + $PollInterval
        Write-Debug "Waiting $wait seconds to start collecting logs."
        Start-Sleep -Seconds $wait
    }
    # Repeatedly read from the audit log
    while($true) {
        Write-Debug "Using range start time of $($start.ToString('o'))."
        $now = [System.DateTime]::UtcNow
        $now = $now.AddTicks(-($now.Ticks % 10000000))
        $end = $now.AddSeconds(-($ReadDelay))
        Write-Debug "Using range end time of $($end.ToString('o'))."
        $sites = Get-SPSite -Limit All
        foreach($site in $sites) { Get-Audit-Data $site $start $end }
        Write-Debug "Saving position timestamp to cache file."
        Save-Position $CacheFile $end
        Write-Debug "Waiting $PollInterval seconds before reading again."
        Start-Sleep -Seconds $PollInterval
        $start = $end
    }
}
Catch {
    Write-Error "An unhandled exception occurred!"
    exit 1
}
AskedMarch 5, 2020 - 1:23pm

Answer (1)

As per the error message it fails at this step:

$EventTime = parsedate($EventTime);

This suggests that the powershell script is not generating proper JSON, i.e. the EventTime field does not seem to be present or of the expected format.
You should look at a sample and investigate what's wrong with it. This can be dumped with the following if there is only a few problematic records that would be hard to spot otherwise:

if not defined($EventTime) file_write('C:\debug-output.log', $raw_event);