[Winlogbeat] Tolerate faults when Windows Event Log session is interrupted

[taylor-swanson]

What does this PR do?

• Added a retry mechanism to winlog/input and winlogbeat to reopen a
  session to Windows Event Log when certain error conditions are encountered.
• This applies when opening a session to Windows Event Log and
  also when reading from Windows Event Log.

Why is it important?

• Filebeat/winlogbeat should be able to tolerate disruptions with the Windows Event Log service without having to be manually restarted by the user.

Checklist

• My code follows the style guidelines of this project
  • I have commented my code, particularly in hard-to-understand areas
  • [ ] I have made corresponding changes to the documentation
• [ ] I have made corresponding change to the default configuration files
• [ ] I have added tests that prove my fix is effective or that my feature works
• I have added an entry in CHANGELOG.next.asciidoc or CHANGELOG-developer.next.asciidoc.

How to test this PR locally

Reproducing the issue

• Run filebeat (with winlog input) or winlogbeat on Windows system. The channel subscription doesn't
  matter, it can be Security or other channels. Make sure debug logging and logging to STDERR is enabled.

.\winlogbeat -e -d "*"

.\filebeat -e -d "*"

• You should eventually see messages every second indicating no logs to read. This is normal.
• Stop the Windows Event Log service.
• The filebeat/winlogbeat log should report errors (usually RPC cancelled). The messages logged every second no longer appear.
• Restarting the Windows Event Log service has no effect. New event logs are not picked up by filebeat/winlogbeat.
• The only way to get filebeat/winlogbeat watching logs again is to restart it.

Testing the fix

• Deploy fixed binary to system
• Run filebeat/winlogbeat as before
• Stop the Windows Event Log service.
• Watch the logs for "Recoverable error". The handle to Windows Event Log should be reopened within a matter of seconds.
• Start the Windows Event Log service.
• New events should flow in as they are generated.

Logs

The following logs are from filebeat. Winlogbeat produces similar logs.

Logs showing normal activity (when no event logs are being generated):

2021-09-29T07:09:39.778-0700    DEBUG   [eventlog_detail]       eventlog/wineventlog.go:298     WinEventLog[Security] No more events
2021-09-29T07:09:40.788-0700    DEBUG   [eventlog_detail]       eventlog/wineventlog.go:298     WinEventLog[Security] No more events
2021-09-29T07:09:41.794-0700    DEBUG   [eventlog_detail]       eventlog/wineventlog.go:298     WinEventLog[Security] No more events
2021-09-29T07:09:42.799-0700    DEBUG   [eventlog_detail]       eventlog/wineventlog.go:298     WinEventLog[Security] No more events
...

Logs indicating original problem (error may vary):

2021-09-29T07:09:51.939-0700    WARN    eventlog/wineventlog.go:314     WinEventLog[Security] EventHandles returned error The remote procedure call was cancelled.
2021-09-29T07:09:51.939-0700    ERROR   [input.winlog]  winlog/input.go:123     Error occured while reading from Windows Event Log 'Security': The remote procedure call was cancelled.       {"id": "DF05023D528B0A9F", "input_source": "Security", "eventlog": "Security"}

...

2021-09-29T07:09:51.939-0700    DEBUG   [eventlog]      eventlog/wineventlog.go:284     WinEventLog[Security] Closing handle
2021-09-29T07:09:51.939-0700    ERROR   [input.winlog]  compat/compat.go:122    Input 'winlog' failed with: input.go:130: input DF05023D528B0A9F failed (id=DF05023D528B0A9F)
        The remote procedure call was cancelled.        {"id": "DF05023D528B0A9F"}

Logs showing issue resolved by fix (error may vary):

2021-09-29T07:00:28.159-0700    ERROR   [input.winlog]  winlog/input.go:110     Encountered recoverable error when opening Windows Event Log: The RPC server is unavailable.  {"id": "DF05023D528B0A9F", "input_source": "Security", "eventlog": "Security"}

...

2021-09-29T07:00:33.165-0700    DEBUG   [input.winlog]  winlog/input.go:116     Windows Event Log 'Security' opened successfully     {"id": "DF05023D528B0A9F", "input_source": "Security", "eventlog": "Security"}

Related issues

• Closes [Winlogbeat] Continue to read channel after Windows Event Log service has been restarted #27947

[elasticmachine]

💚 Build Succeeded

the below badges are clickable and redirect to their specific view in the CI or DOCS

Expand to view the summary

Build stats

• Start Time: 2021-10-04T13:21:10.492+0000

• Duration: 127 min 18 sec

• Commit: 199572e

Test stats 🧪

Test	Results
Failed	0
Passed	47072
Skipped	5330
Total	52402

💚 Flaky test report

Tests succeeded.

🤖 GitHub comments

To re-run your PR in the CI, just comment with:

• /test : Re-trigger the build.

• /package : Generate the packages and run the E2E tests.

• /beats-tester : Run the installation tests with beats-tester.

[elasticmachine]

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

[andrewkroh]

LGTM. Just one suggestion from me.

[andrewkroh]

I think using timed.Wait(cancelCtx, 5 * time.Second) would be better because it would allow the sleep to unblock if cancellation occurs.

[nicpenning]

I am excited for this fix, as it seems this happens a lot to the Windows Defender channel.