Winlogbeat continuously crashes on Windows 2003 server

gregva · January 28, 2017, 2:50am

Hello, we need to support Win 2003 servers while we migrate the app over to a new stack. Winlogbeat continuously crash on these boxes.

There are 4 app servers. Two are clones of the first one. The fourth was built separately. The latter does not seem to be having the issue. However all three former ones have Winlogbeat service stopping in a few seconds after it was started. They seem to have enough time to deliver some events to the collector (Graylog) and then stop.

After disabling the service an starting the EXE from the command line, I was able to capture the crash output below.

The three cloned servers run Microsoft Windows [Version 5.2.3790]

Config file content is (the same across 5 hosts I have running, two hosts have no issues):

winlogbeat:
#  registry_file: C:/ProgramData/winlogbeat/.winlogbeat.yml
  event_logs:
    - name: Application
      ignore_older: 72h
#    - name: Security
    - name: System
output:
  logstash:
    hosts: ["logger:5044"]
#
#
#
#logging:
#  to_files: true
#  files:
#    path: C:/ProgramData/winlogbeat/Logs
#    rotateeverybytes: 10485760 
#  level: debug

The output console dump is attached.

Thank you in advance!

C:\Program Files\Elastic\Winlogbeat>winlogbeat.exe -c winlogbeat.yml
Exception 0xc0000005 0x0 0x78 0x7c837f9f
PC=0x7c837f9f

syscall.Syscall9(0x77e4f871, 0x7, 0x2800, 0x33680001, 0x4000102a, 0x0, 0x11d66000, 0x8000, 0x11bb1c30, 0x0, ...)
        /usr/local/go/src/runtime/syscall_windows.go:185 +0x4a
github.com/elastic/beats/winlogbeat/sys/eventlogging._FormatMessage(0x2800, 0x33680001, 0x4000102a, 0x0, 0x11d66000, 0x8000, 0x11bb1c30, 0x1, 0x0, 0x0)
        /go/src/github.com/elastic/beats/winlogbeat/sys/eventlogging/zsyscall_windows.go:75 +0x97
github.com/elastic/beats/winlogbeat/sys/eventlogging.formatMessage(0x11bb1ba8, 0x2, 0x4000102a, 0x0, 0x11bb1c30, 0x3, 0x3, 0x11d66000, 0x10000, 0x10000, ...)
        /go/src/github.com/elastic/beats/winlogbeat/sys/eventlogging/eventlogging_windows.go:210 +0x49a
github.com/elastic/beats/winlogbeat/sys/eventlogging.RenderEvents(0x11ce6000, 0x7ffac, 0x7ffff, 0x0, 0x11d66000, 0x10000, 0x10000, 0x11a67768, 0x0, 0x0, ...)
        /go/src/github.com/elastic/beats/winlogbeat/sys/eventlogging/eventlogging_windows.go:155 +0x793
github.com/elastic/beats/winlogbeat/eventlog.(*eventLogging).Read(0x11aea900, 0x0, 0x0, 0x0, 0x0, 0x0)
        /go/src/github.com/elastic/beats/winlogbeat/eventlog/eventlogging.go:152 +0x564
github.com/elastic/beats/winlogbeat/beater.(*Winlogbeat).processEventLog(0x11a445d0, 0x11cb8e80, 0xb11100, 0x11aea900, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
        /go/src/github.com/elastic/beats/winlogbeat/beater/winlogbeat.go:207 +0x322
created by github.com/elastic/beats/winlogbeat/beater.(*Winlogbeat).Run
        /go/src/github.com/elastic/beats/winlogbeat/beater/winlogbeat.go:158 +0x333

goroutine 1 [semacquire]:
sync.runtime_Semacquire(0x11cb8e8c)
        /usr/local/go/src/runtime/sema.go:47 +0x26
sync.(*WaitGroup).Wait(0x11cb8e80)
        /usr/local/go/src/sync/waitgroup.go:131 +0xa4
github.com/elastic/beats/winlogbeat/beater.(*Winlogbeat).Run(0x11a445d0, 0x11ab0840, 0x0, 0x0)
        /go/src/github.com/elastic/beats/winlogbeat/beater/winlogbeat.go:161 +0x35d
github.com/elastic/beats/libbeat/beat.(*Beat).launch(0x11ab0840, 0x95e440, 0x0, 0x0)
        /go/src/github.com/elastic/beats/libbeat/beat/beat.go:211 +0x87b
github.com/elastic/beats/libbeat/beat.Run(0x9097bb, 0xa, 0x0, 0x0, 0x95e440, 0x0, 0x0)
        /go/src/github.com/elastic/beats/libbeat/beat/beat.go:136 +0x57
main.main()
        /go/src/github.com/elastic/beats/winlogbeat/main.go:21 +0x40

goroutine 23 [syscall]:
os/signal.signal_recv(0x0)
        /usr/local/go/src/runtime/sigqueue.go:116 +0x11e
os/signal.loop()
        /usr/local/go/src/os/signal/signal_unix.go:22 +0x1a
created by os/signal.init.1
        /usr/local/go/src/os/signal/signal_unix.go:28 +0x36

goroutine 5 [select]:
github.com/elastic/beats/libbeat/publisher.(*bulkWorker).run(0x11cbb800)
        /go/src/github.com/elastic/beats/libbeat/publisher/bulk.go:54 +0x284
created by github.com/elastic/beats/libbeat/publisher.newBulkWorker
        /go/src/github.com/elastic/beats/libbeat/publisher/bulk.go:42 +0x1da

goroutine 4 [select]:
github.com/elastic/beats/libbeat/publisher.(*messageWorker).run(0x11a444e0)
        /go/src/github.com/elastic/beats/libbeat/publisher/worker.go:63 +0x1c3
created by github.com/elastic/beats/libbeat/publisher.(*messageWorker).init
        /go/src/github.com/elastic/beats/libbeat/publisher/worker.go:57 +0xff

goroutine 30 [chan receive]:
github.com/elastic/beats/libbeat/logp.logExpvars(0x11ab08c0)
        /go/src/github.com/elastic/beats/libbeat/logp/logp.go:224 +0x15d
created by github.com/elastic/beats/libbeat/logp.Init
        /go/src/github.com/elastic/beats/libbeat/logp/logp.go:137 +0x371

goroutine 10 [select]:
github.com/elastic/beats/libbeat/common.(*Cache).StartJanitor.func1(0x11a44720, 0x11a446f0)
        /go/src/github.com/elastic/beats/libbeat/common/cache.go:219 +0xd3
created by github.com/elastic/beats/libbeat/common.(*Cache).StartJanitor
        /go/src/github.com/elastic/beats/libbeat/common/cache.go:227 +0x8f

...truncated...

gregva · January 28, 2017, 2:51am

Here is the end of the console dump...

goroutine 13 [select]:
github.com/elastic/beats/libbeat/common.(*Cache).StartJanitor.func1(0x11a44870, 0x11a44840)
        /go/src/github.com/elastic/beats/libbeat/common/cache.go:219 +0xd3
created by github.com/elastic/beats/libbeat/common.(*Cache).StartJanitor
        /go/src/github.com/elastic/beats/libbeat/common/cache.go:227 +0x8f

goroutine 14 [chan receive]:
github.com/elastic/beats/libbeat/service.HandleSignals.func1(0x11d76040, 0x11cb8bb0, 0x11cb8ba0)
        /go/src/github.com/elastic/beats/libbeat/service/service.go:31 +0x31
created by github.com/elastic/beats/libbeat/service.HandleSignals
        /go/src/github.com/elastic/beats/libbeat/service/service.go:34 +0x158

goroutine 15 [chan receive]:
github.com/elastic/beats/libbeat/service.(*beatService).Execute(0xb438fc, 0x11a83338, 0x1, 0x1, 0x11cb5100, 0x11cb5140, 0x11c97300, 0x0)
        /go/src/github.com/elastic/beats/libbeat/service/service_windows.go:23 +0xda
github.com/elastic/beats/vendor/golang.org/x/sys/windows/svc/debug.Run(0x11a7d6c0, 0xe, 0xb0d2c0, 0xb438fc, 0x0, 0x0)
        /go/src/github.com/elastic/beats/vendor/golang.org/x/sys/windows/svc/debug/service.go:40 +0x14b
github.com/elastic/beats/libbeat/service.ProcessWindowsControlEvents(0x11cb8bd0)
        /go/src/github.com/elastic/beats/libbeat/service/service_windows.go:57 +0x19a
created by github.com/elastic/beats/libbeat/service.HandleSignals
        /go/src/github.com/elastic/beats/libbeat/service/service.go:40 +0x1b6

goroutine 31 [select]:
github.com/elastic/beats/vendor/golang.org/x/sys/windows/svc/debug.Run.func1(0x11cb5180, 0x11cb5100, 0x11cb5140)
        /go/src/github.com/elastic/beats/vendor/golang.org/x/sys/windows/svc/debug/service.go:32 +0x14c
created by github.com/elastic/beats/vendor/golang.org/x/sys/windows/svc/debug.Run
        /go/src/github.com/elastic/beats/vendor/golang.org/x/sys/windows/svc/debug/service.go:38 +0xd2

goroutine 16 [select]:
github.com/elastic/beats/winlogbeat/checkpoint.(*Checkpoint).run(0x11ce4150)
        /go/src/github.com/elastic/beats/winlogbeat/checkpoint/checkpoint.go:114 +0x327
created by github.com/elastic/beats/winlogbeat/checkpoint.NewCheckpoint
        /go/src/github.com/elastic/beats/winlogbeat/checkpoint/checkpoint.go:99 +0x433

goroutine 34 [sleep]:
time.Sleep(0x3b9aca00, 0x0)
        /usr/local/go/src/runtime/time.go:59 +0xd4
github.com/elastic/beats/winlogbeat/beater.(*Winlogbeat).processEventLog(0x11a445d0, 0x11cb8e80, 0xb11100, 0x11aeac60, 0x11cb8c48, 0x6, 0x354f4, 0x0, 0xd01df718, 0xe, ...)
        /go/src/github.com/elastic/beats/winlogbeat/beater/winlogbeat.go:216 +0x5d2
created by github.com/elastic/beats/winlogbeat/beater.(*Winlogbeat).Run
        /go/src/github.com/elastic/beats/winlogbeat/beater/winlogbeat.go:158 +0x333
eax     0x78
ebx     0x31be0073
ecx     0x7
edx     0x7ffffffe
edi     0x20
esi     0x2
ebp     0x31bef77c
esp     0x31bef310
eip     0x7c837f9f
eflags  0x10202
cs      0x1b
fs      0x3b
gs      0x0

C:\Program Files\Elastic\Winlogbeat>

andrewkroh · January 28, 2017, 3:15am

What version and arch are you running?

gregva · January 28, 2017, 4:00am

Andrew, apologies. The servers in question are 32-bit machines and the version of beats is 5.1.2. I have downloaded it from the Elastic.co site today.

Thank you!

andrewkroh · January 28, 2017, 4:34pm

Is the server that is working also a 32-bit machine?

Could you enabled debug on one of the servers that is crashing and share the log? You can either add logging.level: debug to the config file or use -d "*" on the command line.

Through the log file we should be able to figure out what event log record it was processing when it crashed (record_number of the last successful event plus one). Then you can find the event in the Windows Event Viewer and see if there is anything special about it.

In the meantime I'll try to find a 32-bit win2k3 machine to test on.

gregva · January 29, 2017, 4:25am

Andrew, yes, the server that is working is also Windows 2003 32-bit machine.

So I started winlogbeat from command line (the service is disabled currently) and got it to crash. The debug log file seems to have been created, but I don't see anything particularly wrong with it. The last several lines state the below:

2017-01-28T23:01:21-05:00 DBG  EventLogging[Application] RenderEvents returned 2335 events
2017-01-28T23:01:21-05:00 DBG  EventLogging[Application] Read() is returning 0 records
2017-01-28T23:01:21-05:00 DBG  EventLog[Application] Read() returned 0 records
2017-01-28T23:01:22-05:00 DBG  EventLogging[System] ReadEventLog returned error Reached the end of the file.
2017-01-28T23:01:22-05:00 DBG  EventLog[System] Read() returned 0 records
2017-01-28T23:01:22-05:00 DBG  EventLogging[Application] ReadEventLog read 524012 bytes
2017-01-28T23:01:22-05:00 DBG  EventLogging[Application] RenderEvents returned 2389 events
2017-01-28T23:01:22-05:00 DBG  EventLogging[Application] Read() is returning 0 records
2017-01-28T23:01:22-05:00 DBG  EventLog[Application] Read() returned 0 records
2017-01-28T23:01:23-05:00 DBG  EventLogging[System] ReadEventLog returned error Reached the end of the file.
2017-01-28T23:01:23-05:00 DBG  EventLog[System] Read() returned 0 records
2017-01-28T23:01:23-05:00 DBG  EventLogging[Application] ReadEventLog read 524204 bytes

Filtering the log for "successfully" yields the below, which makes me believe that the System log got parsed entirely, but the Application log did not:

	Line 24: 2017-01-28T23:01:16-05:00 DBG  EventLog[System] opened successfully
	Line 26: 2017-01-28T23:01:16-05:00 DBG  EventLog[Application] opened successfully
	Line 1541: 2017-01-28T23:01:16-05:00 INFO EventLog[System] Successfully published 59 events

Further, by looking at the Application log progress, we see the following:

	Line 1554: 2017-01-28T23:01:16-05:00 DBG  EventLogging[Application] RenderEvents returned 942 events
	Line 1572: 2017-01-28T23:01:17-05:00 DBG  EventLogging[Application] RenderEvents returned 2507 events
	Line 1578: 2017-01-28T23:01:18-05:00 DBG  EventLogging[Application] RenderEvents returned 2692 events
	Line 1588: 2017-01-28T23:01:19-05:00 DBG  EventLogging[Application] RenderEvents returned 2658 events
	Line 1594: 2017-01-28T23:01:20-05:00 DBG  EventLogging[Application] RenderEvents returned 2694 events
	Line 1614: 2017-01-28T23:01:21-05:00 DBG  EventLogging[Application] RenderEvents returned 2335 events
	Line 1620: 2017-01-28T23:01:22-05:00 DBG  EventLogging[Application] RenderEvents returned 2389 events

I am not sure how to interpret this as the events count does not grow progressively.

Please advise as well as let me know if I can share the log file with you securely.

Thank you,
Greg

gregva · January 29, 2017, 4:30am

Some additional records regarding parsing the Application log:

Line 16: 2017-01-28T23:01:16-05:00 DBG  Initialized EventLog[Application]
Line 26: 2017-01-28T23:01:16-05:00 DBG  EventLog[Application] opened successfully
Line 1556: 2017-01-28T23:01:16-05:00 DBG  EventLog[Application] Read() returned 0 records
Line 1574: 2017-01-28T23:01:17-05:00 DBG  EventLog[Application] Read() returned 0 records
Line 1580: 2017-01-28T23:01:18-05:00 DBG  EventLog[Application] Read() returned 0 records
Line 1590: 2017-01-28T23:01:19-05:00 DBG  EventLog[Application] Read() returned 0 records
Line 1596: 2017-01-28T23:01:20-05:00 DBG  EventLog[Application] Read() returned 0 records
Line 1616: 2017-01-28T23:01:21-05:00 DBG  EventLog[Application] Read() returned 0 records
Line 1622: 2017-01-28T23:01:22-05:00 DBG  EventLog[Application] Read() returned 0 records


Line 21: 2017-01-28T23:01:16-05:00 DBG  EventLogging[Application] Open(recordNumber=0) calling OpenEventLog(uncServerPath=, providerName=Application)
Line 25: 2017-01-28T23:01:16-05:00 INFO EventLogging[Application] contains 199134 records. Record number range [1, 199134]. Starting at 1 (ignoringFirst=false)
Line 27: 2017-01-28T23:01:16-05:00 DBG  EventLogging[Application] ReadEventLog read 524212 bytes
Line 1554: 2017-01-28T23:01:16-05:00 DBG  EventLogging[Application] RenderEvents returned 942 events
Line 1555: 2017-01-28T23:01:16-05:00 DBG  EventLogging[Application] Read() is returning 0 records
Line 1559: 2017-01-28T23:01:17-05:00 DBG  EventLogging[Application] ReadEventLog read 524276 bytes
Line 1572: 2017-01-28T23:01:17-05:00 DBG  EventLogging[Application] RenderEvents returned 2507 events
Line 1573: 2017-01-28T23:01:17-05:00 DBG  EventLogging[Application] Read() is returning 0 records
Line 1577: 2017-01-28T23:01:18-05:00 DBG  EventLogging[Application] ReadEventLog read 524016 bytes
Line 1578: 2017-01-28T23:01:18-05:00 DBG  EventLogging[Application] RenderEvents returned 2692 events
Line 1579: 2017-01-28T23:01:18-05:00 DBG  EventLogging[Application] Read() is returning 0 records
Line 1583: 2017-01-28T23:01:19-05:00 DBG  EventLogging[Application] ReadEventLog read 524276 bytes
Line 1588: 2017-01-28T23:01:19-05:00 DBG  EventLogging[Application] RenderEvents returned 2658 events
Line 1589: 2017-01-28T23:01:19-05:00 DBG  EventLogging[Application] Read() is returning 0 records
Line 1593: 2017-01-28T23:01:20-05:00 DBG  EventLogging[Application] ReadEventLog read 524276 bytes
Line 1594: 2017-01-28T23:01:20-05:00 DBG  EventLogging[Application] RenderEvents returned 2694 events
Line 1595: 2017-01-28T23:01:20-05:00 DBG  EventLogging[Application] Read() is returning 0 records
Line 1600: 2017-01-28T23:01:21-05:00 DBG  EventLogging[Application] ReadEventLog read 524192 bytes
Line 1614: 2017-01-28T23:01:21-05:00 DBG  EventLogging[Application] RenderEvents returned 2335 events
Line 1615: 2017-01-28T23:01:21-05:00 DBG  EventLogging[Application] Read() is returning 0 records
Line 1619: 2017-01-28T23:01:22-05:00 DBG  EventLogging[Application] ReadEventLog read 524012 bytes
Line 1620: 2017-01-28T23:01:22-05:00 DBG  EventLogging[Application] RenderEvents returned 2389 events
Line 1621: 2017-01-28T23:01:22-05:00 DBG  EventLogging[Application] Read() is returning 0 records
Line 1625: 2017-01-28T23:01:23-05:00 DBG  EventLogging[Application] ReadEventLog read 524204 bytes

andrewkroh · January 31, 2017, 3:09am

I've tried reproducing the crash on a Windows 2003/32-bit host, but haven't had any luck.

The amount of debug logging in the code used on win XP and 2003 isn't really sufficient to narrow down the cause. I was thinking that it logged each event individually after reading it, but it only logs the number of events read in each batch. I have created a build that includes a lot more logging. If you are willing to try it, you can download it from here (code diff).

gregva · February 2, 2017, 6:51pm

Andrew, somehow I did not get notification on your most recent response. Let me run the test build and get back to you. What specifically do you want me to look for unless you want to get the whole log file for further analysis on your own?

Thank you!

andrewkroh · February 2, 2017, 7:09pm

Probably the last 100 lines of the log and the stack trace from the crash would be enough to see what it was doing at the time of the crash. Hopefully it provides us with some clues.

If there's anything sensitive you can email + encrypt it (https://pgp.mit.edu/pks/lookup?search=andrew.kroh%40elastic.co&op=index).

gregva · February 2, 2017, 11:15pm

Andrew, so I got it to crash and found the event record that is the cause. To minimize noise I disabled collection of all other Windows logs but the Application log and removed time restriction so that all the records are parsed since the beginning of the log. Here is the truncated output:

2017-02-02T17:47:18-05:00 DBG  output worker: publish 2048 events
2017-02-02T17:47:18-05:00 DBG  Try to publish 2048 events to logstash with window size 2048
2017-02-02T17:47:18-05:00 DBG  2048 events out of 2048 events sent to logstash. Continue sending
2017-02-02T17:47:18-05:00 DBG  send completed
2017-02-02T17:47:18-05:00 DBG  output worker: publish 801 events
2017-02-02T17:47:18-05:00 DBG  Try to publish 801 events to logstash with window size 2048
2017-02-02T17:47:18-05:00 DBG  801 events out of 801 events sent to logstash. Continue sending
2017-02-02T17:47:18-05:00 DBG  send completed
2017-02-02T17:47:18-05:00 INFO EventLog[Application] Successfully published 2849 events
2017-02-02T17:47:18-05:00 DBG  EventLogging[Application] ReadEventLog read 523848 bytes
2017-02-02T17:47:18-05:00 DBG  pre-rendering Event={Provider:{Name:Ci GUID: EventSourceName:} EventIdentifier:{Qualifiers:16384 ID:4109} Version:0 LevelRaw:4 TaskRaw:1 OpcodeRaw:0 TimeCreated:{SystemTime:2015-08-18 05:53:00 -0400 EDT} RecordID:72429 Correlation:{ActivityID: RelatedActivityID:} Execution:{ProcessID:0 ThreadID:0 ProcessorID:0 SessionID:0 KernelTime:0 UserTime:0 ProcessorTime:0} Channel: Computer:SSAPS3 User:SID Identifier[] Name[] Domain[] Type[] EventData:{Pairs:[{Key: Value:x} {Key: Value:c:\system volume information\catalog.wci} {Key: Value:100000}]} UserData:{Name:{Space: Local:} Pairs:[]} Message: Level:Information Task: Opcode: Keywords:[] RenderErrorCode:0 RenderErrorDataItemName: RenderErr:}

Then winlogbeat forwards the group of formatted events to the collector server.

gregva · February 2, 2017, 11:16pm

Then another parsing batch begins that I show only the ending of that essentially represents the moment the app crashed:

2017-02-02T17:47:22-05:00 DBG  source=Ci, messageFiles={SourceName:Ci Err:<nil> Handles:[{File:C:\windows\System32\query.dll Handle:861274113 Err:<nil>}]}
2017-02-02T17:47:22-05:00 DBG  trying FormatMessage with handle=C:\windows\System32\query.dll (861274113) for eventID=1073745933
2017-02-02T17:47:22-05:00 DBG  post-rendering Event={Provider:{Name:Ci GUID: EventSourceName:} EventIdentifier:{Qualifiers:16384 ID:4109} Version:0 LevelRaw:4 TaskRaw:1 OpcodeRaw:0 TimeCreated:{SystemTime:2015-08-18 05:56:17 -0400 EDT} RecordID:73151 Correlation:{ActivityID: RelatedActivityID:} Execution:{ProcessID:0 ThreadID:0 ProcessorID:0 SessionID:0 KernelTime:0 UserTime:0 ProcessorTime:0} Channel: Computer:SSAPS3 User:SID Identifier[] Name[] Domain[] Type[] EventData:{Pairs:[{Key: Value:x} {Key: Value:c:\system volume information\catalog.wci} {Key: Value:100000}]} UserData:{Name:{Space: Local:} Pairs:[]} Message:Master merge was started on c:\system volume information\catalog.wci because more than 100000 documents have changed
since the last master merge.
 Level:Information Task: Opcode: Keywords:[] RenderErrorCode:0 RenderErrorDataItemName: RenderErr:}
2017-02-02T17:47:22-05:00 DBG  pre-rendering Event={Provider:{Name:Ci GUID: EventSourceName:} EventIdentifier:{Qualifiers:16384 ID:4109} Version:0 LevelRaw:4 TaskRaw:1 OpcodeRaw:0 TimeCreated:{SystemTime:2015-08-18 05:56:17 -0400 EDT} RecordID:73152 Correlation:{ActivityID: RelatedActivityID:} Execution:{ProcessID:0 ThreadID:0 ProcessorID:0 SessionID:0 KernelTime:0 UserTime:0 ProcessorTime:0} Channel: Computer:SSAPS3 User:SID Identifier[] Name[] Domain[] Type[] EventData:{Pairs:[{Key: Value:x} {Key: Value:c:\system volume information\catalog.wci} {Key: Value:100000}]} UserData:{Name:{Space: Local:} Pairs:[]} Message: Level:Information Task: Opcode: Keywords:[] RenderErrorCode:0 RenderErrorDataItemName: RenderErr:}
2017-02-02T17:47:22-05:00 DBG  source=Ci, messageFiles={SourceName:Ci Err:<nil> Handles:[{File:C:\windows\System32\query.dll Handle:861274113 Err:<nil>}]}
2017-02-02T17:47:22-05:00 DBG  trying FormatMessage with handle=C:\windows\System32\query.dll (861274113) for eventID=1073745933
2017-02-02T17:47:22-05:00 DBG  post-rendering Event={Provider:{Name:Ci GUID: EventSourceName:} EventIdentifier:{Qualifiers:16384 ID:4109} Version:0 LevelRaw:4 TaskRaw:1 OpcodeRaw:0 TimeCreated:{SystemTime:2015-08-18 05:56:17 -0400 EDT} RecordID:73152 Correlation:{ActivityID: RelatedActivityID:} Execution:{ProcessID:0 ThreadID:0 ProcessorID:0 SessionID:0 KernelTime:0 UserTime:0 ProcessorTime:0} Channel: Computer:SSAPS3 User:SID Identifier[] Name[] Domain[] Type[] EventData:{Pairs:[{Key: Value:x} {Key: Value:c:\system volume information\catalog.wci} {Key: Value:100000}]} UserData:{Name:{Space: Local:} Pairs:[]} Message:Master merge was started on c:\system volume information\catalog.wci because more than 100000 documents have changed
since the last master merge.
 Level:Information Task: Opcode: Keywords:[] RenderErrorCode:0 RenderErrorDataItemName: RenderErr:}
2017-02-02T17:47:22-05:00 DBG  pre-rendering Event={Provider:{Name:Ci GUID: EventSourceName:} EventIdentifier:{Qualifiers:16384 ID:4138} Version:0 LevelRaw:4 TaskRaw:1 OpcodeRaw:0 TimeCreated:{SystemTime:2015-08-18 05:56:18 -0400 EDT} RecordID:73153 Correlation:{ActivityID: RelatedActivityID:} Execution:{ProcessID:0 ThreadID:0 ProcessorID:0 SessionID:0 KernelTime:0 UserTime:0 ProcessorTime:0} Channel: Computer:SSAPS3 User:SID Identifier[] Name[] Domain[] Type[] EventData:{Pairs:[{Key: Value:x} {Key: Value:ChangeLog5} {Key: Value:c:\system volume information\catalog.wci}]} UserData:{Name:{Space: Local:} Pairs:[]} Message: Level:Information Task: Opcode: Keywords:[] RenderErrorCode:0 RenderErrorDataItemName: RenderErr:}
2017-02-02T17:47:22-05:00 DBG  source=Ci, messageFiles={SourceName:Ci Err:<nil> Handles:[{File:C:\windows\System32\query.dll Handle:861274113 Err:<nil>}]}
2017-02-02T17:47:22-05:00 DBG  trying FormatMessage with handle=C:\windows\System32\query.dll (861274113) for eventID=1073745962

Going through Windows event viewer, below is the successfully formatted event following the one that crashes the app:

Event Type:	Information
Event Source:	Ci
Event Category:	CI Service 
Event ID:	4109
Date:		8/18/2015
Time:		4:56:17 AM
User:		N/A
Computer:	SSAPS3
Description:
Master merge was started on c:\system volume information\catalog.wci because more than 100000 documents have changed since the last master merge.

For more information, see Help and Support Center at http://go.microsoft.com/fwlink/events.asp.


Event Type:	Information
Event Source:	Ci
Event Category:	CI Service 
Event ID:	4138
Date:		8/18/2015
Time:		4:56:18 AM
User:		N/A
Computer:	SSAPS3
Description:
Content index corruption detected in component ChangeLog5 in catalog c:\system volume information\catalog.wci. Stack trace is %4.

For more information, see Help and Support Center at http://go.microsoft.com/fwlink/events.asp.

Please let me know if you need any additional info and thank you!

gregva · February 2, 2017, 11:29pm

Andrew, what's interesting, is that is appears that another instance of the same type of message was parsed successfully on the same host (the output is search results in Graylog):

facility
    winlogbeat
message
    Content index corruption detected in component RcovStorageObj2 in catalog c:\system volume information\catalog.wci.
    Stack trace is (null).
name
    ssaps13
source
    ssaps13
timestamp
    2015-08-13T17:04:47.000Z
type
    eventlogging
winlogbeat_computer_name
    SSAPS3
winlogbeat_event_data_param1
    x
winlogbeat_event_data_param2
    RcovStorageObj2
winlogbeat_event_data_param3
    c:\system volume information\catalog.wci
winlogbeat_event_id
    4138
winlogbeat_level
    Information
winlogbeat_log_name
    Application
winlogbeat_record_number
    33637
winlogbeat_source_name
    Ci
winlogbeat_type
eventlogging

andrewkroh · February 7, 2017, 4:42pm

Thanks for running the debug binary and posting the logs. Sadly the events being read at the time of the crash look normal. Do you know if it always crashes on the same exact event?

I've been running Winlogbeat on a 32-bit Win2k3 machine for about a week now but haven't seen it occur myself.

Maybe I should be running IIS on my test machine, that's where the "Ci" records come from, right?

gregva · February 9, 2017, 1:01am

Andrew, I do not believe Ci is related to IIS, nor the servers in question have IIS installed. Let me see if the crash is always generated by the same event and perhaps I will be able to export the event log so you can reply it on your machine. Thanks.

system · March 9, 2017, 1:01am

This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.

andrewkroh · February 2, 2018, 5:50pm

@gregva FYI I think we may have found the problem you were having and fixed it.