Skip to content

Flakey test: winlogbeat.tests.system.test_wineventlog.Test.test_query_ignore_older #22753

Closed
Closed
Flakey test: winlogbeat.tests.system.test_wineventlog.Test.test_query_ignore_older#22753
Labels
StalledWinlogbeatflaky-testUnstable or unreliable test cases.
@urso

Description

@urso
urso
opened on Nov 25, 2020

Flaky Test

  • Test Name: winlogbeat.tests.system.test_wineventlog.Test.test_query_ignore_older
  • Link: Link to file/line number in github.
  • Branch: master
  • Artifact Link: If available, attach the generated zip artifact associated with the stack trace for this failure.
  • Notes: The tests seems to fail consistently on Windows 7 (32bit)

Stack Trace

self = <test_wineventlog.Test testMethod=test_query_ignore_older>

    def test_query_ignore_older(self):
        """
        wineventlog - Query by time (ignore_older than 2s)
        """
        self.write_event_log(">=2 seconds old", eventID=20)
        time.sleep(2)
        self.write_event_log("~0 seconds old", eventID=10)
>       evts = self.read_events(config={
            "event_logs": [
                {
                    "name": self.providerName,
                    "api": self.api,
                    "ignore_older": "2s"
                }
            ]
        })

tests\system\test_wineventlog.py:260: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
tests\system\winlogbeat.py:106: in read_events
    self.wait_until(lambda: self.output_has(expected_events))
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

self = <test_wineventlog.Test testMethod=test_query_ignore_older>
cond = <function WriteReadTest.read_events.<locals>.<lambda> at 0x01FA6730>
max_timeout = 10, poll_interval = 0.1, name = 'cond'

    def wait_until(self, cond, max_timeout=10, poll_interval=0.1, name="cond"):
        """
        Waits until the cond function returns true,
        or until the max_timeout is reached. Calls the cond
        function every poll_interval seconds.
    
        If the max_timeout is reached before cond() returns
        true, an exception is raised.
        """
        start = datetime.now()
        while not cond():
            if datetime.now() - start > timedelta(seconds=max_timeout):
>               raise TimeoutError("Timeout waiting for '{}' to be true. ".format(name) +
                                   "Waited {} seconds.".format(max_timeout))
E               beat.beat.TimeoutError: Timeout waiting for 'cond' to be true. Waited 10 seconds.

..\libbeat\tests\system\beat\beat.py:362: TimeoutError

Winlogbeat logs:

2020-11-25T03:59:31.230Z	INFO	instance/beat.go:635	Home path: [C:\Users\jenkins\workspace\Beats_beats_master\src\github.com\elastic\beats\winlogbeat\build\system-tests\run\test_wineventlog.Test.test_query_ignore_older] Config path: [C:\Users\jenkins\workspace\Beats_beats_master\src\github.com\elastic\beats\winlogbeat\build\system-tests\run\test_wineventlog.Test.test_query_ignore_older] Data path: [C:\Users\jenkins\workspace\Beats_beats_master\src\github.com\elastic\beats\winlogbeat\build\system-tests\run\test_wineventlog.Test.test_query_ignore_older\data] Logs path: [C:\Users\jenkins\workspace\Beats_beats_master\src\github.com\elastic\beats\winlogbeat\build\system-tests\run\test_wineventlog.Test.test_query_ignore_older\logs]
2020-11-25T03:59:31.230Z	DEBUG	[beat]	instance/beat.go:687	Beat metadata path: C:\Users\jenkins\workspace\Beats_beats_master\src\github.com\elastic\beats\winlogbeat\build\system-tests\run\test_wineventlog.Test.test_query_ignore_older\data\meta.json
2020-11-25T03:59:31.236Z	INFO	instance/beat.go:643	Beat ID: 8d95121e-1ac2-4d3a-a10d-a09440927584
2020-11-25T03:59:31.237Z	DEBUG	[seccomp]	seccomp/seccomp.go:96	Syscall filtering is only supported on Linux
2020-11-25T03:59:31.237Z	INFO	[beat]	instance/beat.go:967	Beat info	{"system_info": {"beat": {"path": {"config": "C:\\Users\\jenkins\\workspace\\Beats_beats_master\\src\\github.com\\elastic\\beats\\winlogbeat\\build\\system-tests\\run\\test_wineventlog.Test.test_query_ignore_older", "data": "C:\\Users\\jenkins\\workspace\\Beats_beats_master\\src\\github.com\\elastic\\beats\\winlogbeat\\build\\system-tests\\run\\test_wineventlog.Test.test_query_ignore_older\\data", "home": "C:\\Users\\jenkins\\workspace\\Beats_beats_master\\src\\github.com\\elastic\\beats\\winlogbeat\\build\\system-tests\\run\\test_wineventlog.Test.test_query_ignore_older", "logs": "C:\\Users\\jenkins\\workspace\\Beats_beats_master\\src\\github.com\\elastic\\beats\\winlogbeat\\build\\system-tests\\run\\test_wineventlog.Test.test_query_ignore_older\\logs"}, "type": "winlogbeat", "uuid": "8d95121e-1ac2-4d3a-a10d-a09440927584"}}}
2020-11-25T03:59:31.237Z	INFO	[beat]	instance/beat.go:976	Build info	{"system_info": {"build": {"commit": "unknown", "libbeat": "8.0.0", "time": "1754-08-30T22:43:41.128Z", "version": "8.0.0"}}}
2020-11-25T03:59:31.237Z	INFO	[beat]	instance/beat.go:979	Go runtime info	{"system_info": {"go": {"os":"windows","arch":"386","max_procs":8,"version":"go1.14.7"}}}
2020-11-25T03:59:31.240Z	INFO	[beat]	instance/beat.go:983	Host info	{"system_info": {"host": {"architecture":"x86","boot_time":"2020-11-25T03:49:34.7Z","name":"johnny-PC","ip":["10.224.1.1/20","::1/128","127.0.0.1/8"],"kernel_version":"6.1.7601.24545 (win7sp1_ldr_escrow.200102-1707)","mac":["42:01:0a:e0:01:01"],"os":{"family":"windows","platform":"windows","name":"Windows 7 Ultimate","version":"6.1","major":1,"minor":0,"patch":0,"build":"7601.24546"},"timezone":"GMT","timezone_offset_sec":0,"id":"ae38c079-eb5f-4cb2-8f21-e239ee80ef9d"}}}
2020-11-25T03:59:31.241Z	INFO	[beat]	instance/beat.go:1012	Process info	{"system_info": {"process": {"cwd": "C:\\Users\\jenkins\\workspace\\Beats_beats_master\\src\\github.com\\elastic\\beats\\winlogbeat", "exe": "C:\\Users\\jenkins\\workspace\\Beats_beats_master\\src\\github.com\\elastic\\beats\\winlogbeat\\winlogbeat.test", "name": "winlogbeat.test", "pid": 1404, "ppid": 2412, "start_time": "2020-11-25T03:59:28.886Z"}}}
2020-11-25T03:59:31.241Z	INFO	instance/beat.go:300	Setup Beat: winlogbeat; Version: 8.0.0
2020-11-25T03:59:31.241Z	DEBUG	[beat]	instance/beat.go:326	Initializing output plugins
2020-11-25T03:59:31.241Z	DEBUG	[rotator]	file/rotator.go:176	Initialized file rotator	{"rotator": {"filename": "C:\\Users\\jenkins\\workspace\\Beats_beats_master\\src\\github.com\\elastic\\beats\\winlogbeat\\build\\system-tests\\run\\test_wineventlog.Test.test_query_ignore_older\\output\\winlogbeat", "max_size_bytes": 1024000, "max_backups": 7, "permissions": "-rw-------", "interval": 0}}
2020-11-25T03:59:31.241Z	INFO	[file]	fileout/file.go:101	Initialized file output. path=C:\Users\jenkins\workspace\Beats_beats_master\src\github.com\elastic\beats\winlogbeat\build\system-tests\run\test_wineventlog.Test.test_query_ignore_older\output\winlogbeat max_size_bytes=1024000 max_backups=7 permissions=-rw-------
2020-11-25T03:59:31.241Z	DEBUG	[publisher]	pipeline/consumer.go:148	start pipeline event consumer
2020-11-25T03:59:31.241Z	INFO	[publisher]	pipeline/module.go:113	Beat name: johnny-PC
2020-11-25T03:59:31.241Z	INFO	beater/winlogbeat.go:69	State will be read from and persisted to C:\Users\jenkins\workspace\Beats_beats_master\src\github.com\elastic\beats\winlogbeat\build\system-tests\run\test_wineventlog.Test.test_query_ignore_older\data\.winlogbeat.yml
2020-11-25T03:59:31.241Z	DEBUG	[eventlog]	eventlog/factory.go:104	Checking eventlogging
2020-11-25T03:59:31.241Z	DEBUG	[eventlog]	eventlog/factory.go:104	Checking wineventlog
2020-11-25T03:59:31.241Z	DEBUG	[eventlog]	eventlog/factory.go:106	Using wineventlog API for event log WinlogbeatTestPython_394d2
2020-11-25T03:59:31.242Z	DEBUG	[winlogbeat]	beater/winlogbeat.go:96	Initialized EventLog[WinlogbeatTestPython_394d2]
2020-11-25T03:59:31.242Z	INFO	instance/beat.go:456	winlogbeat start running.
2020-11-25T03:59:31.242Z	INFO	[monitoring]	log/log.go:118	Starting metrics logging every 30s
2020-11-25T03:59:31.243Z	DEBUG	[service]	service/service_windows.go:93	Windows is interactive: false
2020-11-25T03:59:31.244Z	INFO	service/service_windows.go:122	Attempted to register Windows service handlers, but this is not a service. No action necessary
2020-11-25T03:59:31.250Z	DEBUG	[eventlog]	eventlog/wineventlog.go:177	WinEventLog[WinlogbeatTestPython_394d2] using subscription query=<QueryList>
  <Query Id="0">
    <Select Path="WinlogbeatTestPython_394d2">*[System[TimeCreated[timediff(@SystemTime) &lt;= 2000]]]</Select>
  </Query>
</QueryList>
2020-11-25T03:59:31.252Z	DEBUG	[winlogbeat]	beater/eventlogger.go:137	EventLog[WinlogbeatTestPython_394d2] opened successfully
2020-11-25T03:59:31.252Z	DEBUG	[eventlog_detail]	eventlog/wineventlog.go:292	WinEventLog[WinlogbeatTestPython_394d2] No more events
2020-11-25T03:59:31.252Z	DEBUG	[winlogbeat]	beater/eventlogger.go:158	EventLog[WinlogbeatTestPython_394d2] Read() returned 0 records
2020-11-25T03:59:32.252Z	DEBUG	[eventlog_detail]	eventlog/wineventlog.go:292	WinEventLog[WinlogbeatTestPython_394d2] No more events
2020-11-25T03:59:32.252Z	DEBUG	[winlogbeat]	beater/eventlogger.go:158	EventLog[WinlogbeatTestPython_394d2] Read() returned 0 records
2020-11-25T03:59:33.252Z	DEBUG	[eventlog_detail]	eventlog/wineventlog.go:292	WinEventLog[WinlogbeatTestPython_394d2] No more events
2020-11-25T03:59:33.252Z	DEBUG	[winlogbeat]	beater/eventlogger.go:158	EventLog[WinlogbeatTestPython_394d2] Read() returned 0 records
2020-11-25T03:59:34.253Z	DEBUG	[eventlog_detail]	eventlog/wineventlog.go:292	WinEventLog[WinlogbeatTestPython_394d2] No more events
2020-11-25T03:59:34.253Z	DEBUG	[winlogbeat]	beater/eventlogger.go:158	EventLog[WinlogbeatTestPython_394d2] Read() returned 0 records
2020-11-25T03:59:35.253Z	DEBUG	[eventlog_detail]	eventlog/wineventlog.go:292	WinEventLog[WinlogbeatTestPython_394d2] No more events
2020-11-25T03:59:35.253Z	DEBUG	[winlogbeat]	beater/eventlogger.go:158	EventLog[WinlogbeatTestPython_394d2] Read() returned 0 records
2020-11-25T03:59:36.253Z	DEBUG	[eventlog_detail]	eventlog/wineventlog.go:292	WinEventLog[WinlogbeatTestPython_394d2] No more events
2020-11-25T03:59:36.253Z	DEBUG	[winlogbeat]	beater/eventlogger.go:158	EventLog[WinlogbeatTestPython_394d2] Read() returned 0 records
2020-11-25T03:59:37.253Z	DEBUG	[eventlog_detail]	eventlog/wineventlog.go:292	WinEventLog[WinlogbeatTestPython_394d2] No more events
2020-11-25T03:59:37.253Z	DEBUG	[winlogbeat]	beater/eventlogger.go:158	EventLog[WinlogbeatTestPython_394d2] Read() returned 0 records
2020-11-25T03:59:38.253Z	DEBUG	[eventlog_detail]	eventlog/wineventlog.go:292	WinEventLog[WinlogbeatTestPython_394d2] No more events
2020-11-25T03:59:38.253Z	DEBUG	[winlogbeat]	beater/eventlogger.go:158	EventLog[WinlogbeatTestPython_394d2] Read() returned 0 records
2020-11-25T03:59:39.253Z	DEBUG	[eventlog_detail]	eventlog/wineventlog.go:292	WinEventLog[WinlogbeatTestPython_394d2] No more events
2020-11-25T03:59:39.253Z	DEBUG	[winlogbeat]	beater/eventlogger.go:158	EventLog[WinlogbeatTestPython_394d2] Read() returned 0 records
2020-11-25T03:59:40.253Z	DEBUG	[eventlog_detail]	eventlog/wineventlog.go:292	WinEventLog[WinlogbeatTestPython_394d2] No more events
2020-11-25T03:59:40.253Z	DEBUG	[winlogbeat]	beater/eventlogger.go:158	EventLog[WinlogbeatTestPython_394d2] Read() returned 0 records
2020-11-25T03:59:41.254Z	DEBUG	[eventlog_detail]	eventlog/wineventlog.go:292	WinEventLog[WinlogbeatTestPython_394d2] No more events
2020-11-25T03:59:41.254Z	DEBUG	[winlogbeat]	beater/eventlogger.go:158	EventLog[WinlogbeatTestPython_394d2] Read() returned 0 records
2020-11-25T03:59:42.254Z	DEBUG	[eventlog_detail]	eventlog/wineventlog.go:292	WinEventLog[WinlogbeatTestPython_394d2] No more events
2020-11-25T03:59:42.254Z	DEBUG	[winlogbeat]	beater/eventlogger.go:158	EventLog[WinlogbeatTestPython_394d2] Read() returned 0 records
2020-11-25T03:59:43.254Z	DEBUG	[eventlog_detail]	eventlog/wineventlog.go:292	WinEventLog[WinlogbeatTestPython_394d2] No more events
2020-11-25T03:59:43.254Z	DEBUG	[winlogbeat]	beater/eventlogger.go:158	EventLog[WinlogbeatTestPython_394d2] Read() returned 0 records
2020-11-25T03:59:44.254Z	DEBUG	[eventlog_detail]	eventlog/wineventlog.go:292	WinEventLog[WinlogbeatTestPython_394d2] No more events
2020-11-25T03:59:44.254Z	DEBUG	[winlogbeat]	beater/eventlogger.go:158	EventLog[WinlogbeatTestPython_394d2] Read() returned 0 records
2020-11-25T03:59:45.254Z	DEBUG	[eventlog_detail]	eventlog/wineventlog.go:292	WinEventLog[WinlogbeatTestPython_394d2] No more events
2020-11-25T03:59:45.254Z	DEBUG	[winlogbeat]	beater/eventlogger.go:158	EventLog[WinlogbeatTestPython_394d2] Read() returned 0 records
2020-11-25T03:59:46.254Z	DEBUG	[eventlog_detail]	eventlog/wineventlog.go:292	WinEventLog[WinlogbeatTestPython_394d2] No more events
2020-11-25T03:59:46.254Z	DEBUG	[winlogbeat]	beater/eventlogger.go:158	EventLog[WinlogbeatTestPython_394d2] Read() returned 0 records
2020-11-25T03:59:47.254Z	DEBUG	[eventlog_detail]	eventlog/wineventlog.go:292	WinEventLog[WinlogbeatTestPython_394d2] No more events
2020-11-25T03:59:47.254Z	DEBUG	[winlogbeat]	beater/eventlogger.go:158	EventLog[WinlogbeatTestPython_394d2] Read() returned 0 records
2020-11-25T03:59:48.255Z	DEBUG	[eventlog_detail]	eventlog/wineventlog.go:292	WinEventLog[WinlogbeatTestPython_394d2] No more events
2020-11-25T03:59:48.255Z	DEBUG	[winlogbeat]	beater/eventlogger.go:158	EventLog[WinlogbeatTestPython_394d2] Read() returned 0 records
2020-11-25T03:59:49.255Z	DEBUG	[eventlog_detail]	eventlog/wineventlog.go:292	WinEventLog[WinlogbeatTestPython_394d2] No more events
2020-11-25T03:59:49.255Z	DEBUG	[winlogbeat]	beater/eventlogger.go:158	EventLog[WinlogbeatTestPython_394d2] Read() returned 0 records
2020-11-25T03:59:50.255Z	DEBUG	[eventlog_detail]	eventlog/wineventlog.go:292	WinEventLog[WinlogbeatTestPython_394d2] No more events
2020-11-25T03:59:50.255Z	DEBUG	[winlogbeat]	beater/eventlogger.go:158	EventLog[WinlogbeatTestPython_394d2] Read() returned 0 records
2020-11-25T03:59:51.255Z	DEBUG	[eventlog_detail]	eventlog/wineventlog.go:292	WinEventLog[WinlogbeatTestPython_394d2] No more events
2020-11-25T03:59:51.255Z	DEBUG	[winlogbeat]	beater/eventlogger.go:158	EventLog[WinlogbeatTestPython_394d2] Read() returned 0 records
2020-11-25T03:59:52.255Z	DEBUG	[eventlog_detail]	eventlog/wineventlog.go:292	WinEventLog[WinlogbeatTestPython_394d2] No more events
2020-11-25T03:59:52.255Z	DEBUG	[winlogbeat]	beater/eventlogger.go:158	EventLog[WinlogbeatTestPython_394d2] Read() returned 0 records
2020-11-25T03:59:53.255Z	DEBUG	[eventlog_detail]	eventlog/wineventlog.go:292	WinEventLog[WinlogbeatTestPython_394d2] No more events
2020-11-25T03:59:53.255Z	DEBUG	[winlogbeat]	beater/eventlogger.go:158	EventLog[WinlogbeatTestPython_394d2] Read() returned 0 records
2020-11-25T03:59:54.255Z	DEBUG	[eventlog_detail]	eventlog/wineventlog.go:292	WinEventLog[WinlogbeatTestPython_394d2] No more events
2020-11-25T03:59:54.255Z	DEBUG	[winlogbeat]	beater/eventlogger.go:158	EventLog[WinlogbeatTestPython_394d2] Read() returned 0 records
2020-11-25T03:59:55.256Z	DEBUG	[eventlog_detail]	eventlog/wineventlog.go:292	WinEventLog[WinlogbeatTestPython_394d2] No more events
2020-11-25T03:59:55.256Z	DEBUG	[winlogbeat]	beater/eventlogger.go:158	EventLog[WinlogbeatTestPython_394d2] Read() returned 0 records
2020-11-25T03:59:56.256Z	DEBUG	[eventlog_detail]	eventlog/wineventlog.go:292	WinEventLog[WinlogbeatTestPython_394d2] No more events
2020-11-25T03:59:56.256Z	DEBUG	[winlogbeat]	beater/eventlogger.go:158	EventLog[WinlogbeatTestPython_394d2] Read() returned 0 records

Metadata

Metadata

Assignees

No one assigned

    Labels

    StalledWinlogbeatflaky-testUnstable or unreliable test cases.

    Type

    No type

    Fields

    No fields configured for issues without a type.

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions