Real-time file monitoring stops working if several files are encrypted at the same time

[billy-shears]

1. Deploy HIDS agent on Windows 2008 server

2. Disable auto_ignore option in ossec server configuration and restart ossec
   /etc/init.d/ossec restart

3. Add real-time monitoring for C:\Data directory in agent ossec.conf
   <directories check_all="yes" realtime="yes">C:\Data</directories>

4. Create C:\Data\Test folder and 200 files inside Test and restart ossec agent service on Windows 2008 server

5. Add real-time monitoring for C:\Data directory in agent ossec.conf and restart agent service
   <directories check_all="yes" realtime="yes">C:\Data</directories>

6. Check that C:\Data directory is being monitored in real time by ossec agent and wait until real-time file monitoring starts
   agent ossec.log

2018/04/13 15:08:00 ossec-syscheckd: INFO: Monitoring directory: 'C:\Data', with options perm | size | owner | group | md5sum | sha1sum | realtime.
..
2018/04/13 14:01:24 ossec-syscheckd: INFO: Real time file monitoring started.

7. Encrypt C:\Data\Test folder and files
   a. Select C:\Data\Test folder
   b. Right-click the file or folder and select Properties.
   c. On the General tab, click the Advanced button.
   d. Check the box for the "Encrypt contents to secure data" option.
   e. Click OK and then Apply.
   f. Select 'Apply changes to this folder, subfolders and files' and click on OK

8. Check the error in ossec.log and if HIDS events are generated when the directory and files are encrypted

Actual Behavior: Real-time file monitoring stops working if several files are encrypted at the same time
Expected Behavior: Real-time file monitoring should not stop working if several files are encrypted at the same time

[billy-shears]

This error appears in agent ossec.log file and after that real-time file monitoring stops working:
2018/04/13 14:15:30 ossec-syscheckd: ERROR: real time call back called, but 0 bytes.

[billy-shears]

Additional info about this defect:

It depends on the number of files encrypted at the same time. Following the steps to reproduce above, if only first 25 files from Test folder are encrypted at the same time the defect doesn't happen

Lab-HIDS:~# tail -f /var/ossec/queue/syscheck/\(W2008\)\ 10.5.1.2-\>syscheck
!++49:33206:0:0:xxx:xxx !1523633883 C:\Data/Test/File1.txt
!++49:33206:0:0:xxx:xxx !1523633883 C:\Data/Test/File2.txt
!++49:33206:0:0:xxx:xxx !1523633883 C:\Data/Test/File3.txt
!++49:33206:0:0:xxx:xxx !1523633883 C:\Data/Test/File4.txt
!++49:33206:0:0:xxx:xxx !1523633883 C:\Data/Test/File5.txt
!++49:33206:0:0:xxx:xxx !1523633883 C:\Data/Test/File6.txt
!++49:33206:0:0:xxx:xxx !1523633883 C:\Data/Test/File7.txt
!++49:33206:0:0:xxx:xxx !1523633883 C:\Data/Test/File8.txt
!++49:33206:0:0:xxx:xxx !1523633883 C:\Data/Test/File9.txt
!++49:33206:0:0:xxx:xxx !1523633883 C:\Data/Test/File10.txt
!++49:33206:0:0:xxx:xxx !1523633883 C:\Data/Test/File11.txt
!++49:33206:0:0:xxx:xxx !1523633883 C:\Data/Test/File12.txt
!++49:33206:0:0:xxx:xxx !1523633883 C:\Data/Test/File13.txt
!++49:33206:0:0:xxx:xxx !1523633883 C:\Data/Test/File14.txt
!++49:33206:0:0:xxx:xxx !1523633883 C:\Data/Test/File15.txt
!++49:33206:0:0:xxx:xxx !1523633883 C:\Data/Test/File16.txt
!++49:33206:0:0:xxx:xxx !1523633883 C:\Data/Test/File17.txt
!++49:33206:0:0:xxx:xxx !1523633883 C:\Data/Test/File18.txt
!++49:33206:0:0:xxx:xxx !1523633883 C:\Data/Test/File19.txt
!++49:33206:0:0:xxx:xxx !1523633883 C:\Data/Test/File20.txt
!++49:33206:0:0:xxx:xxx !1523633883 C:\Data/Test/File21.txt
!++49:33206:0:0:xxx:xxx !1523633883 C:\Data/Test/File22.txt
!++49:33206:0:0:xxx:xxx !1523633883 C:\Data/Test/File23.txt
!++49:33206:0:0:xxx:xxx !1523633883 C:\Data/Test/File24.txt
!++49:33206:0:0:xxx:xxx !1523633883 C:\Data/Test/File25.txt

However if next 50 files from Test folder are encrypted at the same time only one event is forwarded and the error appears in agent ossec.log
!++49:33206:0:0:xxx:xxx !1523633938 C:\Data/Test/File26.txt
2018/04/13 17:03:39 ossec-syscheckd: ERROR: real time call back called, but 0 bytes.

Then, if ossec agent is restarted FMI events are forwarded properly

!++49:33206:0:0:xxx:xxx !1523634336 C:\Data/Test/File27.txt
!++49:33206:0:0:xxx:xxx !1523634336 C:\Data/Test/File28.txt
!++49:33206:0:0:xxx:xxx !1523634336 C:\Data/Test/File29.txt
!++49:33206:0:0:xxx:xxx !1523634336 C:\Data/Test/File30.txt
!++49:33206:0:0:xxx:xxx !1523634336 C:\Data/Test/File31.txt
!++49:33206:0:0:xxx:xxx !1523634336 C:\Data/Test/File32.txt
!++49:33206:0:0:xxx:xxx !1523634336 C:\Data/Test/File33.txt
!++49:33206:0:0:xxx:xxx !1523634338 C:\Data/Test/File34.txt
!++49:33206:0:0:xxx:xxx !1523634338 C:\Data/Test/File35.txt
!++49:33206:0:0:xxx:xxx !1523634338 C:\Data/Test/File36.txt
!++49:33206:0:0:xxx:xxx !1523634338 C:\Data/Test/File37.txt
!++49:33206:0:0:xxx:xxx !1523634338 C:\Data/Test/File38.txt
!++49:33206:0:0:xxx:xxx !1523634338 C:\Data/Test/File39.txt
!++49:33206:0:0:xxx:xxx !1523634338 C:\Data/Test/File40.txt
!++49:33206:0:0:xxx:xxx !1523634338 C:\Data/Test/File41.txt
!++49:33206:0:0:xxx:xxx !1523634338 C:\Data/Test/File42.txt
!++49:33206:0:0:xxx:xxx !1523634338 C:\Data/Test/File43.txt
!++49:33206:0:0:xxx:xxx !1523634338 C:\Data/Test/File44.txt
!++49:33206:0:0:xxx:xxx !1523634338 C:\Data/Test/File45.txt
!++49:33206:0:0:xxx:xxx !1523634338 C:\Data/Test/File46.txt
!++49:33206:0:0:xxx:xxx !1523634338 C:\Data/Test/File47.txt
!++49:33206:0:0:xxx:xxx !1523634340 C:\Data/Test/File48.txt
!++49:33206:0:0:xxx:xxx !1523634340 C:\Data/Test/File49.txt
!++49:33206:0:0:xxx:xxx !1523634340 C:\Data/Test/File50.txt
!++49:33206:0:0:xxx:xxx !1523634340 C:\Data/Test/File51.txt
!++49:33206:0:0:xxx:xxx !1523634340 C:\Data/Test/File52.txt
!++49:33206:0:0:xxx:xxx !1523634340 C:\Data/Test/File53.txt
!++49:33206:0:0:xxx:xxx !1523634340 C:\Data/Test/File54.txt
!++49:33206:0:0:xxx:xxx !1523634340 C:\Data/Test/File55.txt
!++49:33206:0:0:xxx:xxx !1523634340 C:\Data/Test/File56.txt
!++49:33206:0:0:xxx:xxx !1523634340 C:\Data/Test/File57.txt
!++49:33206:0:0:xxx:xxx !1523634340 C:\Data/Test/File58.txt
!++49:33206:0:0:xxx:xxx !1523634340 C:\Data/Test/File59.txt
!++49:33206:0:0:xxx:xxx !1523634340 C:\Data/Test/File60.txt
!++49:33206:0:0:xxx:xxx !1523634342 C:\Data/Test/File61.txt
!++49:33206:0:0:xxx:xxx !1523634342 C:\Data/Test/File62.txt
!++49:33206:0:0:xxx:xxx !1523634342 C:\Data/Test/File63.txt
!++49:33206:0:0:xxx:xxx !1523634342 C:\Data/Test/File64.txt
!++49:33206:0:0:xxx:xxx !1523634342 C:\Data/Test/File65.txt
!++49:33206:0:0:xxx:xxx !1523634342 C:\Data/Test/File66.txt
!++49:33206:0:0:xxx:xxx !1523634342 C:\Data/Test/File67.txt
!++49:33206:0:0:xxx:xxx !1523634342 C:\Data/Test/File68.txt
!++49:33206:0:0:xxx:xxx !1523634342 C:\Data/Test/File69.txt
!++49:33206:0:0:xxx:xxx !1523634342 C:\Data/Test/File70.txt
!++49:33206:0:0:xxx:xxx !1523634342 C:\Data/Test/File71.txt
!++49:33206:0:0:xxx:xxx !1523634342 C:\Data/Test/File72.txt
!++49:33206:0:0:xxx:xxx !1523634342 C:\Data/Test/File73.txt
!++49:33206:0:0:xxx:xxx !1523634342 C:\Data/Test/File74.txt
!++49:33206:0:0:xxx:xxx !1523634344 C:\Data/Test/File75.txt

[billy-shears]

After some investigation:

It looks like the WinAPI function ReadDirectoryChangesW(), which is used in realtime_win32read() in run_realtime.c, is missing file changes when there is a lot of activity.
This appears to be a more or less common problem: e.g., see 1, 2, 3.

Suggested changes are:

• increase size of the buffer passed to ReadDirectoryChangesW() (link);
• as a workaround, flush the volume (link to the MS forum post with readymade code snippet) every time before checking the changed lists

[FreddMadison]

Pull request was created for this issue #1409

[billy-shears]

Thanks. The PR has been merged in already, as far as I could see.
Does this mean that the issue is fixed in next ossec hids release? 2.9.4 or 3.0.0betaX?

[atomicturtle]

So first and foremost, this is one of the best bug reports Ive ever seen. It is both actionable and repeatable. Furthermore, it has brought a new developer to the project. I would be my pleasure to both backport this to the 2.9.X branch and to 3.0. Please let me know which you would prefer @billy-shears

For everyone else, if you're looking to do a bug report, this is the gold standard

[billy-shears]

Thanks a lot, Scott @atomicturtle!
I'd love to have this backported to 2.9.4, if possible :)
Also, please be sure to include #1205 into 2.9.4 as well (it didn't get into 2.9.3 and previous releases somehow). Appropriate comment in #1346 ("v2.9.4 preparation") already exists, but drawing your attention to it, just in case.
Cheers!