[BUG] Missing first lines with File Monitor and non-existing log directory

[Phoosha]

Describe the bug

The first lines from a file monitored by the File source are lost, when the file and directory monitored by LogMonitor are created after LogMonitor was started.

To Reproduce Steps to reproduce the behavior:

1. Monitored directory must not exist (e.g. C:\Logfiles)
2. Start LogMonitor
3. Observe the following expected log output from LogMonitor: INFO: Log directory \\?\c:\Logfiles does not exist. LogMonitor will wait for 300 seconds for the directory to be created.
4. Write to the log file (e.g. C:\Logfiles\test\app.log), which includes creating it as well as parent directories
5. Observe the following expected log output from LogMonitor: INFO: Log directory \\?\c:\Logfiles found after 15 seconds.
6. UNEXPECTED: First lines from the log file are missing (more specifically everything written after 4. but before 5. is lost)

Reproduction hints:

• I could not reproduce this behavior, when pre-creating the directory C:\Logfiles. It was not even necessary to create the sub-directory test or the file, before I started LogMonitor.
• I could reproduce this behavior regardless of the flag includeSubdirectories, i.e. with it set to true and false.

Expected behavior

LogMonitor picks up all lines from a file, even when the directory to monitor is created after startup.

The source code even suggests it should: https://github.com/microsoft/windows-container-tools/blob/aa6ea069f327ca1c63dfc0a672ca4e9ab41c989f/LogMonitor/src/LogMonitor/FileMonitor/FileMonitorUtilities.cpp#L66

Configuration -Tool: LogMonitor -Version: 2.0.2 (and 2.0.0)

Additional context

To reproduce the issue, you may use the following files. Put them in the following directory hierarchy:

• Dockerfile
• buildContext\
  • entrypoint.ps1
  • LogMonitor\
  • LogMonitorConfig.json
  • LogMonitor.exe (v2.0.2)

Then build & run the container image.

Dockerfile

FROM mcr.microsoft.com/dotnet/framework/aspnet:4.8-20240409-windowsservercore-ltsc2019

COPY . C:/

ENTRYPOINT ["C:\\LogMonitor\\LogMonitor.exe", "powershell", "C:\\entrypoint.ps1"]

entrypoint.ps1

$logfile = ".\Logfiles\test\app.log"

# GOOD: With precreate works as expected
# New-Item -Force -ItemType File -Path $logfile

# GOOD: Just precreating the watched directory is also enough
# New-Item -ItemType Directory -Path .\Logfiles

Start-Sleep 20

# BAD: When creating the file late, loglines with i=0 are lost
New-Item -Force -ItemType File -Path $logfile

for ($i = 0; $i -lt 30; $i++) {
    for ($j = 0; $j -lt 10; $j++) {
        "[$(Get-Date -Format "u")] i=${i} j=${j}" | Out-File -Append -FilePath $logfile
    }
    Start-Sleep 5
}

LogMonitorConfig.json

{
  "LogConfig": {
    "sources": [
      {
        "type": "File",
        "directory": "c:\\Logfiles",
        "filter": "*.log",
        "includeSubdirectories": true,
        "includeFileNames": false
      }
    ]
  }
}

Example output

[2024-04-22T09:39:22.000Z][LOGMONITOR] INFO: Log directory \\?\c:\Logfiles does not exist. LogMonitor will wait for 300 seconds for the directory to be created.
{"Source":"Process","LogEntry":{"Logline":"    Directory: C:\\Logfiles\\test"},"SchemaVersion":"1.0.0"}
{"Source":"Process","LogEntry":{"Logline":"Mode                LastWriteTime         Length Name                          "},"SchemaVersion":"1.0.0"}
{"Source":"Process","LogEntry":{"Logline":"----                -------------         ------ ----                          "},"SchemaVersion":"1.0.0"}
{"Source":"Process","LogEntry":{"Logline":"-a----        4/22/2024  11:39 AM              0 app.log                       "},"SchemaVersion":"1.0.0"}
[2024-04-22T09:39:52.000Z][LOGMONITOR] INFO: Log directory \\?\c:\Logfiles found after 15 seconds.
{"Source":"File","LogEntry":{"Logline":"[2024-04-22 11:39:57Z] i=2 j=0","FileName":"test\\app.log"},"SchemaVersion":"1.0.0"}
{"Source":"File","LogEntry":{"Logline":"[2024-04-22 11:39:57Z] i=2 j=1","FileName":"test\\app.log"},"SchemaVersion":"1.0.0"}
{"Source":"File","LogEntry":{"Logline":"[2024-04-22 11:39:57Z] i=2 j=2","FileName":"test\\app.log"},"SchemaVersion":"1.0.0"}
{"Source":"File","LogEntry":{"Logline":"[2024-04-22 11:39:57Z] i=2 j=3","FileName":"test\\app.log"},"SchemaVersion":"1.0.0"}
{"Source":"File","LogEntry":{"Logline":"[2024-04-22 11:39:57Z] i=2 j=4","FileName":"test\\app.log"},"SchemaVersion":"1.0.0"}
{"Source":"File","LogEntry":{"Logline":"[2024-04-22 11:39:57Z] i=2 j=5","FileName":"test\\app.log"},"SchemaVersion":"1.0.0"}
{"Source":"File","LogEntry":{"Logline":"[2024-04-22 11:39:57Z] i=2 j=6","FileName":"test\\app.log"},"SchemaVersion":"1.0.0"}
{"Source":"File","LogEntry":{"Logline":"[2024-04-22 11:39:57Z] i=2 j=7","FileName":"test\\app.log"},"SchemaVersion":"1.0.0"}
{"Source":"File","LogEntry":{"Logline":"[2024-04-22 11:39:57Z] i=2 j=8","FileName":"test\\app.log"},"SchemaVersion":"1.0.0"}
{"Source":"File","LogEntry":{"Logline":"[2024-04-22 11:39:57Z] i=2 j=9","FileName":"test\\app.log"},"SchemaVersion":"1.0.0"}

[bobsira]

Thanks for bring this up. Our team is looking into this!