search

elastic / beats

:tropical_fish: Beats - Lightweight shippers for Elasticsearch & Logstash
https://www.elastic.co/products/beats
Other
12.15k stars 4.91k forks source link

Winlogbeat sending winevt with '%' variables and not the replacement values on Win11 22H2 #33966

Closed drewmiranda-gl closed 11 months ago

drewmiranda-gl commented 1 year ago

For confirmed bugs, please report:

fields_under_root: true

output.logstash:
   hosts: ["redacted:5044"]
path:
  data: .\data
  logs: .\logs
winlogbeat:
  event_logs:
   - name: Application
     ignore_older: 1h
   - name: System
     ignore_older: 1h
   - name: Security
     ignore_older: 1h
   - name: Setup
     ignore_older: 1h

Example text excerpt:

Credential Manager credentials were read.

Subject:
    Security ID:        %1
    Account Name:       %2
    Account Domain:     %3
    Logon ID:       %4
    Read Operation:     %8

This event occurs when a user performs a read operation on stored credentials in Credential Manager.

Example JSON

{
    "winlogbeat_event_created": "2022-11-14T23:26:53.533Z",
    "winlogbeat_agent_id": "19ecbfde-93bb-42ca-99d7-1aae1aba63b2",
    "winlogbeat_winlog_opcode": "Info",
    "winlogbeat_ecs_version": "8.0.0",
    "winlogbeat_event_code": "7040",
    "source": "unknown",
    "winlogbeat_winlog_user_identifier": "S-1-5-21-63776543-3909903815-3855965128-1001",
    "winlogbeat_winlog_user_type": "User",
    "winlogbeat_winlog_event_data_param4": "BITS",
    "winlogbeat_winlog_event_data_param3": "demand start",
    "winlogbeat_event_original": "<Event xmlns='http://schemas.microsoft.com/win/2004/08/events/event'><System><Provider Name='Service Control Manager' Guid='{555908d1-a6d7-4695-8e1e-26931d2012f4}' EventSourceName='Service Control Manager'/><EventID Qualifiers='16384'>7040</EventID><Version>0</Version><Level>4</Level><Task>0</Task><Opcode>0</Opcode><Keywords>0x8080000000000000</Keywords><TimeCreated SystemTime='2022-11-14T23:25:46.7729215Z'/><EventRecordID>4749</EventRecordID><Correlation/><Execution ProcessID='1456' ThreadID='27768'/><Channel>System</Channel><Computer>DESKTOP-OIU9K0J</Computer><Security UserID='S-1-5-21-63776543-3909903815-3855965128-1001'/></System><EventData><Data Name='param1'>Background Intelligent Transfer Service</Data><Data Name='param2'>auto start</Data><Data Name='param3'>demand start</Data><Data Name='param4'>BITS</Data></EventData><RenderingInfo Culture='en-US'><Message>The start type of the %1 service was changed from %2 to %3.</Message><Level>Information</Level><Provider>Microsoft-Windows-Service Control Manager</Provider><Keywords><Keyword>Classic</Keyword></Keywords></RenderingInfo></Event>",
    "winlogbeat_event_action": "None",
    "streams": [
    "000000000000000000000001"
    ],
    "winlogbeat_@timestamp": "2022-11-14T23:25:46.772Z",
    "winlogbeat_agent_version": "8.5.0",
    "winlogbeat_agent_ephemeral_id": "33e854ff-2ffd-4c75-a3c2-f675cfebdb32",
    "winlogbeat_@metadata_version": "8.5.0",
    "winlogbeat_winlog_record_id": 4749,
    "winlogbeat_log_level": "information",
    "winlogbeat_@metadata_type": "_doc",
    "winlogbeat_@metadata_beat": "winlogbeat",
    "winlogbeat_event_provider": "Service Control Manager",
    "beats_type": "winlogbeat",
    "winlogbeat_winlog_user_domain": "DESKTOP-OIU9K0J",
    "winlogbeat_agent_name": "DESKTOP-OIU9K0J",
    "winlogbeat_winlog_event_id": "7040",
    "timestamp": "2022-11-14T23:25:46.772Z",
    "winlogbeat_winlog_task": "None",
    "winlogbeat_host_name": "DESKTOP-OIU9K0J",
    "winlogbeat_winlog_user_name": "{redacted}",
    "winlogbeat_winlog_channel": "System",
    "winlogbeat_winlog_computer_name": "DESKTOP-OIU9K0J",
    "winlogbeat_event_kind": "event",
    "winlogbeat_winlog_event_data_param2": "auto start",
    "winlogbeat_winlog_event_data_param1": "Background Intelligent Transfer Service",
    "winlogbeat_winlog_process_thread_id": 27768,
    "winlogbeat_winlog_api": "wineventlog",
    "message": "The start type of the %1 service was changed from %2 to %3.",
    "winlogbeat_winlog_provider_guid": "{555908d1-a6d7-4695-8e1e-26931d2012f4}",
    "winlogbeat_agent_type": "winlogbeat",
    "winlogbeat_winlog_provider_name": "Service Control Manager",
    "winlogbeat_winlog_process_pid": 1456,
    "winlogbeat_winlog_keywords": [
    "Classic"
    ]
}
elasticmachine commented 1 year ago

Pinging @elastic/security-external-integrations (Team:Security-External Integrations)

efd6 commented 1 year ago

@drewmiranda-gl Are you able to provide an evtx file corresponding to the 7040 event you've posted here? This would contain your username, which you have redacted above; so if you are prepared to do this it would be best by DM on the community Elastic Slack (https://ela.st/slack), you can ping me at my name, rather than my GH handle.

drewmiranda-gl commented 1 year ago

@drewmiranda-gl Are you able to provide an evtx file corresponding to the 7040 event you've posted here? This would contain your username, which you have redacted above; so if you are prepared to do this it would be best by DM on the community Elastic Slack (https://ela.st/slack), you can ping me at my name, rather than my GH handle.

I would prefer not to. There isn't anything special or unique about the logs on my end. Do you have access to (or can get access to) a Win11 22H2 device? That would give you exactly what you are looking for and have the ability to test.

hugalafutro commented 1 year ago

I don't know what and evtx file is, but I do not care about sharing my local username or machine name. I use winlogbeat with Graylog Sidecar to send event logs to Gralog 5.0, an example of event where mostly everything is %1 %2 %3 etc is here: 

An account was successfully logged on.

Subject:
    Security ID:        %1
    Account Name:       %2
    Account Domain:     %3
    Logon ID:       %4

Logon Information:
    Logon Type:     %9
    Restricted Admin Mode:  %22
    Remote Credential Guard:    %23
    Virtual Account:        %26
    Elevated Token:     %28

Impersonation Level:        %21

New Logon:
    Security ID:        %5
    Account Name:       %6
    Account Domain:     %7
    Logon ID:       %8
    Linked Logon ID:        %27
    Network Account Name:   %24
    Network Account Domain: %25
    Logon GUID:     %13

Process Information:
    Process ID:     %17
    Process Name:       %18

Network Information:
    Workstation Name:   %12
    Source Network Address: %19
    Source Port:        %20

Detailed Authentication Information:
    Logon Process:      %10
    Authentication Package: %11
    Transited Services: %14
    Package Name (NTLM only):   %15
    Key Length:     %16

This event is generated when a logon session is created. It is generated on the computer that was accessed.

The subject fields indicate the account on the local system which requested the logon. This is most commonly a service such as the Server service, or a local process such as Winlogon.exe or Services.exe.

The logon type field indicates the kind of logon that occurred. The most common types are 2 (interactive) and 3 (network).

The New Logon fields indicate the account for whom the new logon was created, i.e. the account that was logged on.

The network fields indicate where a remote logon request originated. Workstation name is not always available and may be left blank in some cases.

The impersonation level field indicates the extent to which a process in the logon session can impersonate.

The authentication information fields provide detailed information about this specific logon request.
    - Logon GUID is a unique identifier that can be used to correlate this event with a KDC event.
    - Transited services indicate which intermediate services have participated in this logon request.
    - Package name indicates which sub-protocol was used among the NTLM protocols.
    - Key length indicates the length of the generated session key. This will be 0 if no session key was requested.
source
turbojeba
timestamp
2023-01-06 11:31:47.849
winlogbeat_@metadata_beat
winlogbeat
winlogbeat_@metadata_type
_doc
winlogbeat_@metadata_version
8.5.2
winlogbeat_@timestamp
2023-01-06 11:31:47.849
winlogbeat_agent_ephemeral_id
3606898e-4f8d-4993-bdb8-419ab3f9bc0e
winlogbeat_agent_id
f67a711f-5399-4e79-89a8-6c4d889a723e
winlogbeat_agent_name
turbojeba
winlogbeat_agent_type
winlogbeat
winlogbeat_agent_version
8.5.2
winlogbeat_collector_node_id
turbojeba
winlogbeat_ecs_version
8.0.0
winlogbeat_event_action
Logon
winlogbeat_event_code
4624
winlogbeat_event_created
2023-01-06 11:31:49.047
winlogbeat_event_kind
event
winlogbeat_event_outcome
success
winlogbeat_event_provider
Microsoft-Windows-Security-Auditing
winlogbeat_host_name
turbojeba
winlogbeat_log_level
information
winlogbeat_tags
["windows"]
winlogbeat_winlog_activity_id
{dc3c77e3-20e1-0004-0078-3cdce120d901}
winlogbeat_winlog_api
wineventlog
winlogbeat_winlog_channel
Security
winlogbeat_winlog_computer_name
turbojeba
winlogbeat_winlog_event_data_AuthenticationPackageName
NTLM
winlogbeat_winlog_event_data_ElevatedToken
%%1843
winlogbeat_winlog_event_data_ImpersonationLevel
%%1833
winlogbeat_winlog_event_data_IpAddress
192.168.1.152
winlogbeat_winlog_event_data_IpPort
13720
winlogbeat_winlog_event_data_KeyLength
128
winlogbeat_winlog_event_data_LmPackageName
NTLM V1
winlogbeat_winlog_event_data_LogonGuid
{00000000-0000-0000-0000-000000000000}
winlogbeat_winlog_event_data_LogonProcessName
NtLmSsp
winlogbeat_winlog_event_data_LogonType
3
winlogbeat_winlog_event_data_ProcessId
0x0
winlogbeat_winlog_event_data_ProcessName
-
winlogbeat_winlog_event_data_RemoteCredentialGuard
-
winlogbeat_winlog_event_data_RestrictedAdminMode
-
winlogbeat_winlog_event_data_SubjectDomainName
-
winlogbeat_winlog_event_data_SubjectLogonId
0x0
winlogbeat_winlog_event_data_SubjectUserName
-
winlogbeat_winlog_event_data_SubjectUserSid
S-1-0-0
winlogbeat_winlog_event_data_TargetDomainName
NT AUTHORITY
winlogbeat_winlog_event_data_TargetLinkedLogonId
0x0
winlogbeat_winlog_event_data_TargetLogonId
0x156a24af
winlogbeat_winlog_event_data_TargetOutboundDomainName
-
winlogbeat_winlog_event_data_TargetOutboundUserName
-
winlogbeat_winlog_event_data_TargetUserName
ANONYMOUS LOGON
winlogbeat_winlog_event_data_TargetUserSid
S-1-5-7
winlogbeat_winlog_event_data_TransmittedServices
-
winlogbeat_winlog_event_data_VirtualAccount
%%1843
winlogbeat_winlog_event_data_WorkstationName
COMMODORE
winlogbeat_winlog_event_id
4624
winlogbeat_winlog_keywords
["Audit Success"]
winlogbeat_winlog_opcode
Info_
winlogbeat_winlog_process_pid
1344
winlogbeat_winlog_process_thread_id
22932
winlogbeat_winlog_provider_guid
{54849625-5478-4994-a5ba-3e3b0328c30d}
winlogbeat_winlog_provider_name
Microsoft-Windows-Security-Auditing
winlogbeat_winlog_record_id
372826
winlogbeat_winlog_task
Logon
winlogbeat_winlog_version
3

Does that help any?

As drew said you don't really need anything but a machine running Windows 11 updated to 22H2 to 100% reproduce the issue.

edit: As in, this is not issue with our installations, I was literally watching the log stream in Graylog as a correctly reporting Win11 machine went through windows update to 22H2 and then very first log event after the 1st reboot and all of them since came with %1 %2 %3. This is something that changed in Windows.

drewmiranda-gl commented 1 year ago

Confirmed that winlogbeat 8.6.0 does not resolve this issue.

hugalafutro commented 1 year ago

Hello any progress on this? Or if the evtx file is what you need can you guide me how to provide it? All I get from my Win11 machines is mumbo jumbo. image

Deathwing182 commented 1 year ago

Having this issue also per #34896, sorry about the duplicate -

Pretty much isolated to Win 11 as far as I can tell, updating Winlogbeat and my Elasticsearch cluster to 8.7 didn't seem to change anything. Nothing special about any of these machines, running bog-standard Win 11 Enterprise 22H2.

BondlerShlorndorf commented 1 year ago

I saw somewhere that some people were in contact with Microsoft. (Can't find the link right now). But that was months ago.

Though I can confirm that this occurs on Win 11 Professional 22H2 as well.

This is a show-stopper. Any company doing business as a prime or subcontractor on a DoD contract will have to replace their log aggregators if this issue is not fixed ASAP.

efd6 commented 1 year ago

I have been able to reproduce this (access to a Win 11 22H2 machine was provided) using a modified version of the config provided in the original issue, but with the output replaced to send to file to reduce moving parts.

Details to date:

  1. This issue does not occur when the logs are read from an EVTX file.
  2. It does occur ~always when events are read directly from publishers.
  3. The issue is occurring at the EvtFormatMessage syscall. This call does not return any indication of an error when the issue happens, and apart from the absence of placeholder substitution, is working as expected.
  4. A number of similar issues appear to exist, all involving Windows 11 (e.g. https://techcommunity.microsoft.com/t5/windows-insider-program/windows-11-wevtutil-cannot-render-system-messages/m-p/2665584, https://gateway.sdl.com/apex/communityknowledge?articleName=000019760 and https://github.com/dotnet/runtime/issues/58829).
drewmiranda-gl commented 1 year ago

Just retested with Winlogbeat 8.7.1 and can confirm this issue still occurs.

alago197 commented 1 year ago

I have been able to reproduce this (access to a Win 11 22H2 machine was provided) using a modified version of the config provided in the original issue, but with the output replaced to send to file to reduce moving parts.

Today Microsoft released (https://support.microsoft.com/en-us/topic/may-9-2023-kb5026372-os-build-22621-1702-ce93c18e-e819-458f-abcf-dc7154ce7e40) a cumulative, monthly rollup of security and non.security fixes. From the patch descriptions I can't locate anything related to the issue discussed here - but both wevtapi.dll and wevtutil.exe are being updated by the patch. I'll check tomorrow if this update solves anything, but it would be nice if someone else can apply that Microsoft update earlier & see if it solves or not the issue.

efd6 commented 1 year ago

@drewmiranda-gl Yeah, the critical section of code is very small, we haven't changed it and it conforms to the MS docs for the system call, so I would not expect any changes (if they did exist) to fix this on the Winlogbeat side.

efd6 commented 1 year ago

I have tried using the experimental API, and this appears to work. Would someone please try this? This involves adding api: wineventlog-experimental to the event_logs groups. Example:

winlogbeat:
  event_logs:
   - name: Application
     api: wineventlog-experimental
   - name: System
     api: wineventlog-experimental
   - name: Security
     api: wineventlog-experimental
   - name: Setup
     api: wineventlog-experimental
drewmiranda-gl commented 1 year ago

@efd6 thanks for the suggestion.

I tested (with winlogbeat 8.7.1) but had mixed results:

  1. When using api: wineventlog-experimental with the security log i get the following error
panic: runtime error: invalid memory address or nil pointer dereference
[signal 0xc0000005 code=0x0 addr=0x0 pc=0xc33574]

goroutine 96 [running]:
github.com/elastic/beats/v7/winlogbeat/sys/wineventlog.(*EventIterator).Close(0x0)
        github.com/elastic/beats/v7/winlogbeat/sys/wineventlog/iterator.go:199 +0x34
github.com/elastic/beats/v7/winlogbeat/eventlog.(*winEventLogExp).Close(0xc00056cc80)
        github.com/elastic/beats/v7/winlogbeat/eventlog/wineventlog_experimental.go:347 +0xb6
github.com/elastic/beats/v7/winlogbeat/beater.(*eventLogger).run.func3()
        github.com/elastic/beats/v7/winlogbeat/beater/eventlogger.go:128 +0x9f
github.com/elastic/beats/v7/winlogbeat/beater.(*eventLogger).run(0xc0001aa600, 0xc0000b9020, {0x3608470?, 0xc0002bdb80}, {{0x0, 0x0}, 0x0, {0x0, 0x0, 0x0}, ...}, ...)
        github.com/elastic/beats/v7/winlogbeat/beater/eventlogger.go:149 +0xa6a
github.com/elastic/beats/v7/winlogbeat/beater.(*Winlogbeat).processEventLog(0x0?, 0x0?, 0x0?, {{0x0, 0x0}, 0x0, {0x0, 0x0, 0x0}, {0x0, ...}}, ...)
        github.com/elastic/beats/v7/winlogbeat/beater/winlogbeat.go:203 +0xb3
created by github.com/elastic/beats/v7/winlogbeat/beater.(*Winlogbeat).Run
        github.com/elastic/beats/v7/winlogbeat/beater/winlogbeat.go:171 +0x37a
  1. Some events only display [{{eventParam ....

While some events do correctly populate the variables in logs such as event id 7040:

The start type of the Background Intelligent Transfer Service service was changed from demand start to auto start.

Others just show something like:

[{{eventParam $ 2}}]

efd6 commented 1 year ago

@drewmiranda-gl Thanks for checking that and sorry it didn't work out.

efd6 commented 1 year ago

@drewmiranda-gl I have a fix for the panic. Are you able to provide sanitized debug logs for the cases where you see things like [{{eventParam $ 2}}]. Debug logging is a little sparse here, but in particular, I'm looking for log lines with the message "Falling back to EvtFormatMessage for event ID \<number>", also if you see any with the message "Dropping event due to rendering error." at warn level corresponding to the events that are misrendered.

drewmiranda-gl commented 1 year ago

Hi @efd6 , I'm happy to provide. I don't have anything sensitive nor proprietary in the logs (honestly probably very boring). Do you have any instructions i can follow to properly prepare and collect?

efd6 commented 1 year ago

Thanks @drewmiranda-gl that would be really helpful. The easiest would be if you are running Winlogbeat directly from the command line and invoke it with winlogbeat -d '*' and any other options that you need. This will write the logs to the configured log location in your winlogbeat.yml. We can take this discussion to the community slack.

drewmmiranda commented 1 year ago

@efd6 thanks for your help! I've sent you a zip via slack :)

ernie-sys commented 1 year ago

Anything new to this problem?

drewmmiranda commented 1 year ago

Anything new to this problem?

I sent Dan some debugging info and he said he’ll review this upcoming work week.

alago197 commented 1 year ago

I have been able to reproduce this (access to a Win 11 22H2 machine was provided) using a modified version of the config provided in the original issue, but with the output replaced to send to file to reduce moving parts.

Today Microsoft released (https://support.microsoft.com/en-us/topic/may-9-2023-kb5026372-os-build-22621-1702-ce93c18e-e819-458f-abcf-dc7154ce7e40) a cumulative, monthly rollup of security and non.security fixes. From the patch descriptions I can't locate anything related to the issue discussed here - but both wevtapi.dll and wevtutil.exe are being updated by the patch. I'll check tomorrow if this update solves anything, but it would be nice if someone else can apply that Microsoft update earlier & see if it solves or not the issue.

After testing with the mentioned latest Windows update - no joy, unfortunately . Same as before.

efd6 commented 1 year ago

@alago197 Thanks for reporting back.

jamiehynds commented 1 year ago

Microsoft have advised us that what we're seeing is a known issue and was addressed in an update released on May 24th - KB5026446. The update is currently an optional update, but will be included in next month's Patch Tuesday.

We're testing the update internally, but if anyone on this Github issue would be willing to test on their side too, we'd love to get some validation from our community that Microsoft's fix addresses the issue you're running into also.

drewmiranda-gl commented 1 year ago

I can confirm, i installed KB5026446 on my Windows 11 device today and messages sent via winlogbeat no longer have %{number} placeholders and have the real actual values!

Before installing this update: The start type of the %1 service was changed from %2 to %3.

After installing this update: The start type of the Background Intelligent Transfer Service service was changed from auto start to demand start.

alago197 commented 1 year ago

I can confirm, i installed KB5026446 on my Windows 11 device today and messages sent via winlogbeat no longer have %{number} placeholders and have the real actual values!

Before installing this update: The start type of the %1 service was changed from %2 to %3.

After installing this update: The start type of the Background Intelligent Transfer Service service was changed from auto start to demand start.

Many thanks for sharing!!!

Microsoft have advised us that what we're seeing is a known issue and was addressed in an update released on May 24th - KB5026446. The update is currently an optional update, but will be included in next month's Patch Tuesday.

We're testing the update internally, but if anyone on this Github issue would be willing to test on their side too, we'd love to get some validation from our community that Microsoft's fix addresses the issue you're running into also.

Thanks for sharing!!!

efd6 commented 1 year ago

I have also checked locally and see expected behaviour after the update is installed. I think we can close this.

jamiehynds commented 1 year ago

Thanks for testing and confirming the result @alago197 and @drewmiranda-gl, and to everyone for their patience and collaboration as we worked through this issue with Microsoft. Closing the issue, thanks to @efd6 for working through it on our side too!

BondlerShlorndorf commented 1 year ago

Are people seeing "XML syntax error on line 1: unexpected EOF" for certain events? I'm seeing this for events 4616, 4622, 4624, 4625, 4634, 4648, 4688 (the ones I've checked so far). Here is redacted XML info for one of these events. You can see the XML string ends partway through the Message section of the RenderingInfo.

<Event xmlns='http://schemas.microsoft.com/win/2004/08/events/event'><System><Provider Name='Microsoft-Windows-Security-Auditing' Guid='{XXXXXXXX-XXXX-XXXX-XXXX-XXXXXXXXXXXX}'/><EventID>4624</EventID><Version>3</Version><Level>0</Level><Task>12544</Task><Opcode>0</Opcode><Keywords>0x8020000000000000</Keywords><TimeCreated SystemTime='2023-06-01T20:11:11.3572380Z'/><EventRecordID>XXXXXXX</EventRecordID><Correlation ActivityID='{XXXXXXXX-XXXX-XXXX-XXXX-XXXXXXXXXXXX}}'/><Execution ProcessID='XXXX' ThreadID='XXXXX'/><Channel>Security</Channel><Computer>_computer.dom.tldom_</Computer><Security/></System><EventData><Data Name='SubjectUserSid'>S-X-X-X</Data><Data Name='SubjectUserName'>COMPUTER$</Data><Data Name='SubjectDomainName'>DOMAIN</Data><Data Name='SubjectLogonId'>0xXXX</Data><Data Name='TargetUserSid'>S-X-X-X</Data><Data Name='TargetUserName'>XXXXXX</Data><Data Name='TargetDomainName'>XXXXXX</Data><Data Name='TargetLogonId'>0xXXX</Data><Data Name='LogonType'>5</Data><Data Name='LogonProcessName'>Advapi </Data><Data Name='AuthenticationPackageName'>Negotiate</Data><Data Name='WorkstationName'>-</Data><Data Name='LogonGuid'>{00000000-0000-0000-0000-000000000000}</Data><Data Name='TransmittedServices'>-</Data><Data Name='LmPackageName'>-</Data><Data Name='KeyLength'>0</Data><Data Name='ProcessId'>0xXXX</Data><Data Name='ProcessName'>C:\Windows\System32\services.exe</Data><Data Name='IpAddress'>-</Data><Data Name='IpPort'>-</Data><Data Name='ImpersonationLevel'>%%1833</Data><Data Name='RestrictedAdminMode'>-</Data><Data Name='RemoteCredentialGuard'>-</Data><Data Name='TargetOutboundUserName'>-</Data><Data Name='TargetOutboundDomainName'>-</Data><Data Name='VirtualAccount'>%%1843</Data><Data Name='TargetLinkedLogonId'>0x0</Data><Data Name='ElevatedToken'>%%1842</Data></EventData><RenderingInfo Culture='en-US'><Message>An account was successfully logged on.&#13;&#10;&#13;&#10;Subject:&#13;&#10;&#9;

efd6 commented 1 year ago

@BondlerShlorndorf Can you post the length of the unredacted XML?

BondlerShlorndorf commented 1 year ago

They appear to be different for the different events. For the redacted one above, the length appears to be 0x790 = 1,936 (copy and pasted into HxD). For an Event 4688, the length appears to be 0x54A = 1,354. For an Event 4634 the length was 0x39A = 922.

They do appear to be consistent with the end of the XML being "Subject: "

So maybe something isn't happy with the tab character at the end?

BondlerShlorndorf commented 1 year ago

Sorry - forgot to put the end of the XML in a code block: Subject:&#13;&#10;&#9;

alago197 commented 1 year ago

Capture_err

I'm too seeing this, event id 4627 (redacted computer/domain names)

4627001255400x802000000000000064802SecurityXXXXX.domain.intS-1-5-18XXXXX$XXXXX0x3e7S-1-5-18SYSTEMNT AUTHORITY0x3e7511 %{S-1-5-32-544} %{S-1-1-0} %{S-1-5-11} %{S-1-16-16384}Información de pertenencia a grupos. Firmante:
efd6 commented 1 year ago

@alago197 Do you see the same terminal string behaviour as seen by @BondlerShlorndorf?

@BondlerShlorndorf Are you able to locate corresponding events in the Windows eventlog viewer and see what the following text is in their rendering of the XML?

alago197 commented 1 year ago

Yes, Dan it's the same string , albeit in my case the culture is spanish:

"........... %{S-1-5-11} %{S-1-16-16384}Información de pertenencia a

grupos. Firmante:

" In my case, the same event (before the new patch which I applied some hours ago) as we know winlogbeat produced the text but with the placholders:

message <== full message field: "Información de pertenencia a grupos.

Firmante: Id. de seguridad: %1 Nombre de cuenta: %2 Nombre de dominio: %3 Id. de inicio de sesión: %4

Tipo de inicio de sesión: %9

Nuevo inicio de sesión: Id. de seguridad: %5 Nombre de cuenta: %6 Dominio de cuenta: %7 Id. de inicio de sesión: %8

Evento en secuencia: %10 of %11

Pertenencia a grupos: %12

Los campos de firmante indican la cuenta del sistema local que solicitó el inicio de sesión. Suele ser un servicio como el servicio de servidor o un proceso local como Winlogon.exe o Services.exe.

El campo Tipo de inicio de sesión indica la clase de inicio de sesión que se realizó. Los tipos más comunes son 2 (interactivo) y 3 (red).

Los campos Nuevo inicio de sesión indican la cuenta para la que se creó el nuevo inicio de sesión, es decir, aquella en la que se inició la sesión.

Este evento se genera cuando se configura la subcategoría de pertenencia a grupo de auditoría. El campo Id. de inicio de sesión se puede usar para correlacionar este evento con el evento de inicio de sesión de usuario correspondiente, así como con cualquier otro evento de auditoría de seguridad generado durante esta sesión de inicio. "

alago197 commented 1 year ago

oh, I see the markdown fidledwith the ending string. it's:

Capture_code

efd6 commented 1 year ago

Thanks @alago197. From that we might feel confident that the text following is not weird (the abbreviation of identidad reminds me of a previous issue with non-en locales, but that would not show this error since it happens after the XML parsing has been completed, however, can you provide your stack version?)

(requoting your text in a \

 — ``` on a line before the text and the same on a line after the text gets you this)


        %{S-1-5-11}
        %{S-1-16-16384}</Data></EventData><RenderingInfo Culture='es-ES'><Message>Información de pertenencia a 

grupos.&#13;&#10;&#13;&#10;Firmante:&#13;&#10;&#9;


So we would expect the next text to be Id. de seguridad which seems pretty innocuous. It does indeed seem to be related to the encoded tab.


Can you also check to see how the Windows eventlog viewer shows this?
alago197 commented 1 year ago

Doh! thanks for the tag reminder. I'm still on (winlogbeat) 7.11.1 (using Graylog - that's the bundled winlogbeat version as of Graylog 5.x)

the expanded XML in the ev viewer details for a sample event (same event id) seems correct:

- <Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
- <System>
  <Provider Name="Microsoft-Windows-Security-Auditing" Guid="{54849625-5478-4994-a5ba-3e3b0328c30d}" /> 
  <EventID>4627</EventID> 
  <Version>0</Version> 
  <Level>0</Level> 
  <Task>12554</Task> 
  <Opcode>0</Opcode> 
  <Keywords>0x8020000000000000</Keywords> 
  <TimeCreated SystemTime="2023-06-01T23:52:07.7200164Z" /> 
  <EventRecordID>64911</EventRecordID> 
  <Correlation ActivityID="{790d1eed-94b4-0001-551f-0d79b494d901}" /> 
  <Execution ProcessID="920" ThreadID="6112" /> 
  <Channel>Security</Channel> 
  <Computer>XXXXX.domain.int</Computer> 
  <Security /> 
  </System>
- <EventData>
  <Data Name="SubjectUserSid">S-1-5-18</Data> 
  <Data Name="SubjectUserName">XXXXXX$</Data> 
  <Data Name="SubjectDomainName">XXXXX</Data> 
  <Data Name="SubjectLogonId">0x3e7</Data> 
  <Data Name="TargetUserSid">S-1-5-18</Data> 
  <Data Name="TargetUserName">SYSTEM</Data> 
  <Data Name="TargetDomainName">NT AUTHORITY</Data> 
  <Data Name="TargetLogonId">0x3e7</Data> 
  <Data Name="LogonType">5</Data> 
  <Data Name="EventIdx">1</Data> 
  <Data Name="EventCountTotal">1</Data> 
  <Data Name="GroupMembership">%{S-1-5-32-544} %{S-1-1-0} %{S-1-5-11} %{S-1-16-16384}</Data> 
  </EventData>
  </Event>

And the normal view of the event seems also normal (things redacted)

Información de pertenencia a grupos.

Firmante:
    Id. de seguridad:       SYSTEM
    Nombre de cuenta:       XXXXXX$
    Nombre de dominio:      XXXXX
    Id. de inicio de sesión:        0x3E7

Tipo de inicio de sesión:           5

Nuevo inicio de sesión:
    Id. de seguridad:       SYSTEM
    Nombre de cuenta:       SYSTEM
    Dominio de cuenta:      NT AUTHORITY
    Id. de inicio de sesión:        0x3E7

Evento en secuencia:        1 of 1

Pertenencia a grupos:           
        BUILTIN\Administradores
        Todos
        NT AUTHORITY\Usuarios autentificados
        Etiqueta obligatoria\Nivel obligatorio del sistema

Los campos de firmante indican la cuenta del sistema local que solicitó el inicio de sesión. Suele ser un servicio como el servicio de servidor o un proceso local como Winlogon.exe o Services.exe.

El campo Tipo de inicio de sesión indica la clase de inicio de sesión que se realizó. Los tipos más comunes son 2 (interactivo) y 3 (red).

Los campos Nuevo inicio de sesión indican la cuenta para la que se creó el nuevo inicio de sesión, es decir, aquella en la que se inició la sesión.

Este evento se genera cuando se configura la subcategoría de pertenencia a grupo de auditoría. El campo Id. de inicio de sesión se puede usar para correlacionar este evento con el evento de inicio de sesión de usuario correspondiente, así como con cualquier otro evento de auditoría de seguridad generado durante esta sesión de inicio.

And the descriptive view for the event:

- System 

  - Provider 

   [ Name]  Microsoft-Windows-Security-Auditing 
   [ Guid]  {54849625-5478-4994-a5ba-3e3b0328c30d} 

   EventID 4627 

   Version 0 

   Level 0 

   Task 12554 

   Opcode 0 

   Keywords 0x8020000000000000 

  - TimeCreated 

   [ SystemTime]  2023-06-01T23:52:07.7200164Z 

   EventRecordID 64911 

  - Correlation 

   [ ActivityID]  {790d1eed-94b4-0001-551f-0d79b494d901} 

  - Execution 

   [ ProcessID]  920 
   [ ThreadID]  6112 

   Channel Security 

   Computer XXXXX.domain.int 

   Security 

- EventData 

  SubjectUserSid S-1-5-18 
  SubjectUserName XXXXXX$ 
  SubjectDomainName XXXXX 
  SubjectLogonId 0x3e7 
  TargetUserSid S-1-5-18 
  TargetUserName SYSTEM 
  TargetDomainName NT AUTHORITY 
  TargetLogonId 0x3e7 
  LogonType 5 
  EventIdx 1 
  EventCountTotal 1 
  GroupMembership %{S-1-5-32-544} %{S-1-1-0} %{S-1-5-11} %{S-1-16-16384}
efd6 commented 1 year ago

Thanks, @alago197. Nothing seems odd there, which is odd. If it weren't for the rest of this issue I'd be worried that we are doing something wrong, but given the rest of the issue and the underlying cause I find it hard not to be suspicious of the OS. How the eventlog viewer works while we don't? That's a confusion, but is entirely consistent with the behaviour we were seeing prior to the update patch being applied, and can potentially be explained by them using internal API to retrieve the data while we are using the public API. If the public API is broken we would see this differential behaviour. This feels like a cop-out, so I'll take a look at what I see on the test machine I have running to see if I can replicate it and check whether the bytes we are getting back from the system call is already truncated. I'll report back when I have some information.

BondlerShlorndorf commented 1 year ago

So, for that event, this is what is shown in the General tab (this appears in the XML string, but only up to the first tab):

An account was successfully logged on.

Subject:
    Security ID:        XXXXX
    Account Name:       COMPUTER$
    Account Domain:     DOMAIN
    Logon ID:       0xXXX

Logon Information:
    Logon Type:     5
    Restricted Admin Mode:  -
    Remote Credential Guard:    -
    Virtual Account:        No
    Elevated Token:     Yes

Impersonation Level:        Impersonation

New Logon:
    Security ID:        SYSTEM
    Account Name:       SYSTEM
    Account Domain:     NT AUTHORITY
    Logon ID:       0xXXX
    Linked Logon ID:        0x0
    Network Account Name:   -
    Network Account Domain: -
    Logon GUID:     {00000000-0000-0000-0000-000000000000}

Process Information:
    Process ID:     0xXXX
    Process Name:       C:\Windows\System32\services.exe

Network Information:
    Workstation Name:   -
    Source Network Address: -
    Source Port:        -

Detailed Authentication Information:
    Logon Process:      Advapi  
    Authentication Package: Negotiate
    Transited Services: -
    Package Name (NTLM only):   -
    Key Length:     0

This event is generated when a logon session is created. It is generated on the computer that was accessed.

The subject fields indicate the account on the local system which requested the logon. This is most commonly a service such as the Server service, or a local process such as Winlogon.exe or Services.exe.

The logon type field indicates the kind of logon that occurred. The most common types are 2 (interactive) and 3 (network).

The New Logon fields indicate the account for whom the new logon was created, i.e. the account that was logged on.

The network fields indicate where a remote logon request originated. Workstation name is not always available and may be left blank in some cases.

The impersonation level field indicates the extent to which a process in the logon session can impersonate.

The authentication information fields provide detailed information about this specific logon request.
    - Logon GUID is a unique identifier that can be used to correlate this event with a KDC event.
    - Transited services indicate which intermediate services have participated in this logon request.
    - Package name indicates which sub-protocol was used among the NTLM protocols.
    - Key length indicates the length of the generated session key. This will be 0 if no session key was requested.

On the details tab, it appears to be the same as I posted above except that the "" tag is followed by the "" tag, and that's it. So, nothing in that XML after that - no "" tag.

efd6 commented 1 year ago

I have replicated the issue here and am looking at where the truncation is coming in.

efd6 commented 1 year ago

Looking at the buffers at the system call site after we get back the data from Windows, we are only receiving the data up until the &#9;. The remainder of the buffer that we have handed in is all zero.

BondlerShlorndorf commented 1 year ago

Just checking if there was any update on this.

jamiehynds commented 1 year ago

@BondlerShlorndorf we are working closely with Microsoft on this issue and they have made some progress in terms of reproducing it on their side. We're currently waiting on an update from Microsoft, but will share here as soon as we have something to share.

jamiehynds commented 1 year ago

@BondlerShlorndorf Microsoft have identified the root cause and working on a patch to resolve the issue. Will let you know as soon as we have an expected timeframe for release.

BondlerShlorndorf commented 1 year ago

Awesome! Thanks for the update.

jamiehynds commented 1 year ago

Microsoft have now confirmed that they have created a patch to resolve this issue and will be shipping it as a optional patch for WIndows 11 22H2 on Sept 26th, with a view to moving towards a regular patch in mid-October.

Thanks to everyone for thier patience as we worked with Microsoft on this.

jamiehynds commented 11 months ago

Microsoft have released an update to address this issue on Windows 11. Details on the update can be found here: September 26, 2023—KB5030310 (OS Build 22621.2361) Preview. The specific fix related to the Windows events bug is 'This update addresses an issue that affects events that have a TAB character. The events do not render, or you cannot forward them.'

Thanks again to everyone for their patience and collaboration. I'll close this issue now that Microsoft has published the fix.

opoplawski commented 11 months ago

It does appear to have resolved it here, though it may have taken a couple minutes after reboot to have fully taken effect. Thank you!