juju4 / ansible-sysmon

Install and configure Sysmon for Linux
BSD 2-Clause "Simplified" License
8 stars 0 forks source link

sysmon rsyslog logs erratic, journald ones fine #1

Open juju4 opened 1 year ago

juju4 commented 1 year ago

Describe the bug sysmon service is active but no logs is written.

more precisely logs are visible via journalctl but not via log file /var/log/sysmon/sysmon.log log file output set by https://github.com/juju4/ansible-sysmon/blob/main/templates/rsyslog-sysmon.conf.j2

To Reproduce Setup with https://github.com/juju4/ansible-sysmon/ Let it run for few days to get logrotation

Sysmon version

$ dpkg -l | grep -iE 'sysmonforlinux|bpf'
ii  libbpf0:amd64                      1:0.5.0-1ubuntu22.04.1                  amd64        eBPF helper library (shared library)
ii  sysinternalsebpf                   1.1.1                                   amd64        A shared library and code library for making eBPF programs.
ii  sysmonforlinux                     1.1.1                                   amd64        A system monitor based on eBPF, ported from Windows, that outputs events to Syslog

Distro/kernel version Ubuntu 22.04.2 LTS kernel 5.19.0-1022-aws

Sysmon configuration

https://github.com/juju4/ansible-sysmon/blob/main/templates/config.xml.j2 but seems to have been resetted somewhere... not sure if installer is doing something like that like it does for systemd unit service file.

$ sudo more /opt/sysmon/config.xml
<Sysmon schemaversion="4.22">
<EventFiltering>
</EventFiltering>
</Sysmon>

Logs Empty config

$ sudo /opt/sysmon/sysmon -i /opt/sysmon/config.xml -service -t

Sysmon v1.1.1 - Monitors system events
Sysinternals - www.sysinternals.com
By Mark Russinovich, Thomas Garnier and Kevin Sheldrake
Copyright (C) 2014-2023 Microsoft Corporation
Licensed under MIT/GPLv2
Using libxml2. libxml2 is Copyright (C) 1998-2012 Daniel Veillard. All Rights Reserved.

Loading configuration file with schema version 4.22
Sysmon schema version: 4.81
Configuration file validated.
Found Kernel version: 5.19
Using EBPF object: /opt/sysmon//sysmonEBPFkern5.6-_core.o
Discovery process: BTF-CORE
Running...
[R] No global rule or pre-filtered for 16
Event SYSMONEVENT_SERVICE_CONFIGURATION_CHANGE
    UtcTime: 2023-04-15 01:10:24.158
    Configuration: sysmon -i
    ConfigurationFileHash: -
[R] No global rule or pre-filtered for 4
Event SYSMONEVENT_SERVICE_STATE_CHANGE
    UtcTime: 2023-04-15 01:10:24.158
    State: Started
    Version: 1.1.1
    SchemaVersion: 4.81
PROCESS_CACHE_REQUEST failed
[!] Default string for User on SYSMONEVENT_PROCESS_TERMINATE - (nil),0
Event SYSMONEVENT_PROCESS_TERMINATE
    RuleName: -
    UtcTime: 2023-04-15 01:10:24.168
    ProcessGuid: {00000000-0000-0000-0000-000000000000}
    ProcessId: 138907
    Image: <unknown process>
    User: -

Expected config from ansible role

$ sudo /opt/sysmon/sysmon -i /opt/sysmon/config.xml -service -t

Sysmon v1.1.1 - Monitors system events
Sysinternals - www.sysinternals.com
By Mark Russinovich, Thomas Garnier and Kevin Sheldrake
Copyright (C) 2014-2023 Microsoft Corporation
Licensed under MIT/GPLv2
Using libxml2. libxml2 is Copyright (C) 1998-2012 Daniel Veillard. All Rights Reserved.

Loading configuration file with schema version 4.81
Configuration file validated.
Found Kernel version: 5.19
Using EBPF object: /opt/sysmon//sysmonEBPFkern5.6-_core.o
Discovery process: BTF-CORE
Running...
[R] No global rule or pre-filtered for 16
Event SYSMONEVENT_SERVICE_CONFIGURATION_CHANGE
    UtcTime: 2023-04-15 01:12:46.651
    Configuration: sysmon -i
    ConfigurationFileHash: -
[R] No global rule or pre-filtered for 4
Event SYSMONEVENT_SERVICE_STATE_CHANGE
    UtcTime: 2023-04-15 01:12:46.651
    State: Started
    Version: 1.1.1
    SchemaVersion: 4.81

Expected behavior Logs should be available both in journalctl and sysmon.log

Additional context Collected Apr 15th.

$ systemctl status sysmon
● sysmon.service - Sysmon event logger
     Loaded: loaded (/etc/systemd/system/sysmon.service; enabled; vendor preset: enabled)
    Drop-In: /etc/systemd/system/sysmon.service.d
             └─hardening.conf
     Active: active (running) since Sat 2023-04-15 00:46:54 UTC; 3min 17s ago
    Process: 138509 ExecStart=/opt/sysmon/sysmon -i /opt/sysmon/config.xml -service (code=exited, status=0/SUCCESS)
   Main PID: 138524 (sysmon)
         IP: 0B in, 0B out
      Tasks: 1 (limit: 2307)
     Memory: 122.7M (limit: 1.0G)
        CPU: 564ms
     CGroup: /system.slice/sysmon.service
             └─138524 /opt/sysmon/sysmon -i /opt/sysmon/config.xml -service

Apr 15 00:49:53 ip-172-16-x-y sysmon[138524]: <Event><System><Provider Name="Linux-Sysmon" Guid="{ff032593-a8d3-4f13-b0d6-01fc615a0f97}"/><EventID>5</EventID><Version>3>
Apr 15 00:49:53 ip-172-16-x-y sysmon[138524]: <Event><System><Provider Name="Linux-Sysmon" Guid="{ff032593-a8d3-4f13-b0d6-01fc615a0f97}"/><EventID>5</EventID><Version>3>
Apr 15 00:49:54 ip-172-16-x-y sysmon[138524]: <Event><System><Provider Name="Linux-Sysmon" Guid="{ff032593-a8d3-4f13-b0d6-01fc615a0f97}"/><EventID>5</EventID><Version>3>
Apr 15 00:49:54 ip-172-16-x-y sysmon[138524]: <Event><System><Provider Name="Linux-Sysmon" Guid="{ff032593-a8d3-4f13-b0d6-01fc615a0f97}"/><EventID>5</EventID><Version>3>
Apr 15 00:49:55 ip-172-16-x-y sysmon[138524]: <Event><System><Provider Name="Linux-Sysmon" Guid="{ff032593-a8d3-4f13-b0d6-01fc615a0f97}"/><EventID>1</EventID><Version>5>
Apr 15 00:49:55 ip-172-16-x-y sysmon[138524]: <Event><System><Provider Name="Linux-Sysmon" Guid="{ff032593-a8d3-4f13-b0d6-01fc615a0f97}"/><EventID>5</EventID><Version>3>
Apr 15 00:50:04 ip-172-16-x-y sysmon[138524]: <Event><System><Provider Name="Linux-Sysmon" Guid="{ff032593-a8d3-4f13-b0d6-01fc615a0f97}"/><EventID>1</EventID><Version>5>
Apr 15 00:50:04 ip-172-16-x-y sysmon[138524]: <Event><System><Provider Name="Linux-Sysmon" Guid="{ff032593-a8d3-4f13-b0d6-01fc615a0f97}"/><EventID>5</EventID><Version>3>
words><TimeCreated SystemTime="2023-04-15T00:50:04.222960000Z"/><EventRecordID>75506</EventRecordID><Correlation/><Execution ProcessID="138524" ThreadID="138524"/><Channel>
Apr 15 00:50:11 ip-172-16-x-y sysmon[138524]: <Event><System><Provider Name="Linux-Sysmon" Guid="{ff032593-a8d3-4f13-b0d6-01fc615a0f97}"/><EventID>1</EventID><Version>5>
Apr 15 00:50:11 ip-172-16-x-y sysmon[138524]: <Event><System><Provider Name="Linux-Sysmon" Guid="{ff032593-a8d3-4f13-b0d6-01fc615a0f97}"/><EventID>1</EventID><Version>5>
$ ls -l /var/log/sysmon/sysmon.log*
-rw-r----- 1 syslog adm        0 Apr 15 00:00 /var/log/sysmon/sysmon.log
-rw-r----- 1 syslog adm        0 Apr 14 00:00 /var/log/sysmon/sysmon.log.1
-rw-r----- 1 syslog adm       20 Apr  5 00:00 /var/log/sysmon/sysmon.log.10.gz
-rw-r----- 1 syslog adm       20 Apr  4 00:00 /var/log/sysmon/sysmon.log.11.gz
-rw-r----- 1 syslog adm       20 Apr  3 00:00 /var/log/sysmon/sysmon.log.12.gz
-rw-r----- 1 syslog adm       20 Apr  2 00:00 /var/log/sysmon/sysmon.log.13.gz
-rw-r----- 1 syslog adm       20 Apr  1 00:00 /var/log/sysmon/sysmon.log.14.gz
-rw-r----- 1 syslog adm       20 Mar 31 17:39 /var/log/sysmon/sysmon.log.15.gz
-rw-r----- 1 syslog adm   170319 Mar 31 20:14 /var/log/sysmon/sysmon.log.16.gz
-rw-r----- 1 syslog adm  2924356 Mar 25 23:24 /var/log/sysmon/sysmon.log.17.gz
-rw-r----- 1 syslog root 2358052 Mar 24 02:24 /var/log/sysmon/sysmon.log.18.gz
-rw-r----- 1 syslog adm       20 Apr 13 00:00 /var/log/sysmon/sysmon.log.2.gz
-rw-r----- 1 syslog adm       20 Apr 12 00:00 /var/log/sysmon/sysmon.log.3.gz
-rw-r----- 1 syslog adm       20 Apr 11 00:00 /var/log/sysmon/sysmon.log.4.gz
-rw-r----- 1 syslog adm       20 Apr 10 00:00 /var/log/sysmon/sysmon.log.5.gz
-rw-r----- 1 syslog adm       20 Apr  9 00:00 /var/log/sysmon/sysmon.log.6.gz
-rw-r----- 1 syslog adm   317899 Apr 10 00:00 /var/log/sysmon/sysmon.log.7.gz
-rw-r----- 1 syslog adm   379222 Apr  9 00:00 /var/log/sysmon/sysmon.log.8.gz
-rw-r----- 1 syslog adm       20 Apr  6 00:00 /var/log/sysmon/sysmon.log.9.gz

Note that logrotate includes a service restart so likely not an issue there. some days fine, some not

00willo commented 1 year ago

This may be related, but after setting up, the sysmon.log was renamed, and a new sysmon.log was created, however, the handle hadn't been released and sysmon was still writing to the old (now renamed) file.

Running systemctl restart sysmon still didn't work correctly, I finally managed to get it to complete the rotation by running /usr/lib/rsyslog/rsyslog-rotate manually. I've added it to the script to see if it works consistently.

The only change made to the logrotate conf, was to use dateext and dateformat for the rotated logs

/var/log/sysmon/sysmon.log {
    rotate 30
    daily
    missingok
    delaycompress
    compress
    create 640 root adm
    sharedscripts
    dateext
    dateformat -%Y%m%d
    postrotate
       if invoke-rc.d sysmon status > /dev/null 2>&1; then \
          invoke-rc.d sysmon restart > /dev/null 2>&1; \
       fi;
    endscript
}

Distro/kernel version Debian 11 kernel 5.10.0-18-amd64

$ dpkg -l | grep -iE 'sysmonforlinux|bpf' 
ii  libbpf0:amd64                  1:0.3-2                        amd64        eBPF helper library (shared library)
ii  sysinternalsebpf               1.0.2                          amd64        A shared library and code library for making eBPF programs.
ii  sysmonforlinux                 1.0.2                          amd64        A system monitor based on eBPF, ported from Windows, that outputs events to Syslog
$ lsof /var/log/sysmon/sysmon.log
COMMAND      PID USER   FD   TYPE DEVICE SIZE/OFF    NODE NAME
rsyslogd     466 root    7w   REG  254,0 37018631 3409500 /var/log/sysmon/sysmon.log
juju4 commented 1 year ago

My main workaround is to get logs via journald/journalctl (and filebeat) will add logrotate options as common anyway