search

grafana / agent

Vendor-neutral programmable observability pipelines.
https://grafana.com/docs/agent/
Apache License 2.0
1.6k stars 487 forks source link

`filename` label intermittently missing after `pack` stage #4080

Closed mateuszdrab closed 1 year ago

mateuszdrab commented 1 year ago

What's wrong?

I've set up a river flow to capture some Exchange Server logs into Loki. Due to the sheer amount of files, initial attempts at submitting the series to Loki failed to due too many series error. To remediate this, I added a pack stage to pack the filename label (which I believe is good practice anyway since I don't care about the actual file names) and reduced the amount of files I'll be ingesting.

After running this for a day, I noticed that majority of the logs do not have the filename label in the packed json (just the message itself is there), after removing the pack stage, the label is there. I've been running the agent for 24h with the pack stage removed and all logs have the filename label.

It's worth noting that as part of relabeling, I also regex the filename label to extract the directory name and put that in a directory label. This label is always there in each log but it is not packed.

Steps to reproduce

Apply pack stage as below when digesting logs to Loki:

  stage.pack {
     labels = ["filename"]
     ingest_timestamp = false
   }

This is applied as one of the last processing steps, after extracting the directory from the filename using relabeling.

System information

Windows Server 2019

Software version

Grafana Agent v0.33.2

Configuration

logging {
  level = "debug"
}

// Collect and send metrics to a Prometheus remote_write endpoint.
prometheus.remote_write "default" {
  endpoint {

    }
  }
}

loki.write "default" {
  endpoint {

    }
  }
  endpoint {

    }
  }
}

prometheus.relabel "default" {
  forward_to      = [prometheus.remote_write.default.receiver]

  rule {
    action        = "replace"
    replacement   = constants.hostname
    target_label  = "instance"
  }

  rule {
    action        = "replace"
    replacement   = constants.hostname
    target_label  = "agent_hostname"
  }
}

loki.relabel "default" {
  forward_to      = [loki.process.final.receiver]

  rule {
    action        = "replace"
    replacement   = constants.hostname
    target_label  = "hostname"
  }

  rule {
    action        = "replace"
    replacement   = constants.hostname
    target_label  = "agent_hostname"
  }

  rule {
    action        = "labeldrop"
    regex         = "computer"
  }
}

loki.process "final" {
  forward_to      = [loki.write.default.receiver]

  stage.drop {
    older_than  = "24h"
    drop_counter_reason = "line_too_old"
  }
}

loki.relabel "file" {
  forward_to      = [loki.process.file.receiver]

  rule {
    action        = "replace"
    replacement   = "file"
    target_label  = "job"
  }

  rule {
    action        = "replace"
    regex         = "(.*)\\\\.*"
    replacement   = "$1"
    target_label  = "directory"
    source_labels = ["filename"]
  }

}

loki.process "file" {
  forward_to      = [loki.relabel.default.receiver]

   stage.pack {
     labels = ["filename"]
     ingest_timestamp = false
   }
}

loki.relabel "eventlog" {
  forward_to      = [loki.relabel.default.receiver]

  rule {
    action        = "replace"
    replacement   = "event-log"
    target_label  = "job"
  }
}

prometheus.exporter.windows "default" {
  // enabled_collectors = ["cpu", "cpu_info", "cs", "logical_disk", "net", "os", "service", "system", "time", "tcp", "process", "memory", "iis"]
  enabled_collectors = ["cpu", "cpu_info", "cs", "logical_disk", "net", "os", "service", "system", "time", "tcp", "process", "memory", "iis", "vmware", "dns", "dhcp", "dfsr", "ad", "adfs", "terminal_services", "exchange"]
}

// Configure a prometheus.scrape component to collect metrics.
prometheus.scrape "default" {
  targets         = prometheus.exporter.windows.default.targets
  forward_to      = [ prometheus.relabel.default.receiver ]
  scrape_interval = "60s"
  scrape_timeout  = "60s"
}

prometheus.scrape "agent" {
  targets         = [ {"__address__" = "127.0.0.1:12345", "job" = "integrations/agent"} ]
  forward_to      = [ prometheus.relabel.default.receiver ]
}

prometheus.scrape "vscode" {
  targets         = [ {"__address__" = "127.0.0.1:9931", "job" = "vscode"} ]
  forward_to      = [ prometheus.relabel.default.receiver ]
}

loki.source.windowsevent "application"  {
  eventlog_name = "Application"
  forward_to = [ loki.process.eventlog.receiver ]    
}

loki.source.windowsevent "system"  {
  eventlog_name = "System"
  forward_to = [ loki.process.eventlog.receiver ]    
}

loki.source.windowsevent "security"  {
  eventlog_name = "Security"
  forward_to = [ loki.process.eventlog.receiver ]     
}

loki.process "eventlog" {
  forward_to = [ loki.relabel.eventlog.receiver ]

  stage.json {
    expressions = {source = "source"}
  }

  stage.labels {
    values = { source  = "source" }
  }  
}

loki.process "winacme" {
  forward_to = [ loki.relabel.file.receiver ]

  stage.multiline {
      firstline     = "^\\d{4}-\\d{2}-\\d{2} \\d{1,2}:\\d{2}:\\d{2}.\\d{3} \\+\\d{2}:\\d{2} \\[\\w+\\]"
      max_wait_time = "10s"
  }

  stage.regex {
      expression = "^(?P<time>^\\d{4}-\\d{2}-\\d{2} \\d{1,2}:\\d{2}:\\d{2}.\\d{3} \\+\\d{2}:\\d{2}) (?P<level>\\[\\w+\\])"
  }

  stage.timestamp {
    source = "time"
    format = "2006-01-02 15:04:05.000 -07:00"
  }

}

discovery.file "winacme" {
  path_targets = [{__path__ = "C:/ProgramData/win-acme/acme-v02.api.letsencrypt.org/log/**", "app" = "win-acme"},]
  sync_period  = "600s"
}

loki.source.file "winacme" {
  forward_to = [ loki.process.winacme.receiver ]
  targets    = discovery.file.winacme.targets
}

loki.process "exchange" {
  forward_to = [ loki.relabel.exchange.receiver ]

  stage.drop {
      expression  = "^#"
  }

  stage.regex {
      expression = "^(?P<time>[^,]+)(?P<msg>.*),"
  }

  stage.timestamp {
    source = "time"
    format = "2006-01-02T15:04:05.000Z"
  }
}

loki.relabel "exchange" {
  forward_to      = [ loki.relabel.file.receiver ]

  rule {
    action        = "replace"
    replacement   = "exchange"
    target_label  = "app"
  }

  rule {
    action        = "replace"
    regex         = ".+V\\d{2}\\\\(.*)\\\\.*"
    replacement   = "$1"
    target_label  = "component"
    source_labels = ["filename"]
  }
}

discovery.file "exchange" {
  path_targets = [
    // {__path__ = "C:/Program Files/Microsoft/Exchange Server/V15/Logging/**/*.log", "app" = "exchange"},
    // {__path__ = "C:/Program Files/Microsoft/Exchange Server/V15/Logging/**/*.LOG", "app" = "exchange"},
    {__path__ = "C:/Program Files/Microsoft/Exchange Server/V15/TransportRoles/Logs/**/*.LOG"},
    ]
  sync_period  = "600s"
}

loki.source.file "exchange" {
  forward_to = [ loki.process.exchange.receiver ]
  targets    = discovery.file.exchange.targets
}

Logs

ts=2023-06-07T09:52:36.1498347Z level=info msg="config reloaded"
ts=2023-06-07T09:52:36.1524267Z level=info msg="scheduling loaded components"
ts=2023-06-07T09:52:38.7320395Z component=loki.process.exchange level=debug component=stage type=drop msg="line will not be dropped, the provided regular expression did not match the log line"
ts=2023-06-07T09:52:38.738043Z component=loki.process.exchange level=debug component=stage type=regex msg="extracted data debug in regex stage" extracteddata="map[filename:C:\\Program Files\\Microsoft\\Exchange Server\\V15\\TransportRoles\\Logs\\Hub\\QueueViewer\\TRANSPORTQUEUE20230607-1.LOG msg:,,SUMMARY,,,,,,,,,,,,,,,,,,TotalMessageCount = 0; PoisonMessageCount = 0 time:2023-06-07T09:52:36.634Z]"
ts=2023-06-07T09:52:38.7690426Z component=loki.process.final level=debug component=stage type=drop msg="line will not be dropped, it did not meet drop criteria for age; current time=2023-06-07 10:52:38.7400441 +0100 BST m=+204.920166901, drop before=2023-06-06 10:52:38.7400441 +0100 BST m=-86195.079833099, log timestamp=2023-06-07 09:52:36.634 +0000 UTC"
ts=2023-06-07T09:52:43.0229715Z component=loki.process.final level=debug component=stage type=drop msg="line will not be dropped, it did not meet drop criteria for age; current time=2023-06-07 10:52:43.0229715 +0100 BST m=+209.203198401, drop before=2023-06-06 10:52:43.0229715 +0100 BST m=-86190.796801599, log timestamp=2023-06-07 10:52:43.0219391 +0100 BST m=+209.202166001"
ts=2023-06-07T09:53:00.8290335Z component=loki.process.exchange level=debug component=stage type=drop msg="line will not be dropped, the provided regular expression did not match the log line"
ts=2023-06-07T09:53:00.8393633Z component=loki.process.exchange level=debug component=stage type=drop msg="line will not be dropped, the provided regular expression did not match the log line"
ts=2023-06-07T09:53:00.8399853Z component=loki.process.exchange level=debug component=stage type=regex msg="extracted data debug in regex stage" extracteddata="map[filename:C:\\Program Files\\Microsoft\\Exchange Server\\V15\\TransportRoles\\Logs\\FrontEnd\\ProtocolLog\\SmtpReceive\\RECV2023060709-1.LOG msg:,redacted\\Outbound Proxy Frontend redacted,08DB5B925BC90A4A,0,192.168.64.130:717,192.168.64.130:47283,+, time:2023-06-07T09:52:00.318Z]"
ts=2023-06-07T09:53:00.8545369Z component=loki.process.exchange level=debug component=stage type=regex msg="extracted data debug in regex stage" extracteddata="map[filename:C:\\Program Files\\Microsoft\\Exchange Server\\V15\\TransportRoles\\Logs\\FrontEnd\\ProtocolLog\\SmtpReceive\\RECV2023060709-1.LOG msg:,redacted\\Default Frontend redacted,08DB5B925BC90A4B,0,127.0.0.1:25,127.0.0.1:47284,+, time:2023-06-07T09:52:00.320Z]"
ts=2023-06-07T09:53:00.8565822Z component=loki.process.exchange level=debug component=stage type=drop msg="line will not be dropped, the provided regular expression did not match the log line"
ts=2023-06-07T09:53:00.8565822Z component=loki.process.final level=debug component=stage type=drop msg="line will not be dropped, it did not meet drop criteria for age; current time=2023-06-07 10:53:00.8565822 +0100 BST m=+227.037242401, drop before=2023-06-06 10:53:00.8565822 +0100 BST m=-86172.962757599, log timestamp=2023-06-07 09:52:00.318 +0000 UTC"
ts=2023-06-07T09:53:00.8612692Z component=loki.process.exchange level=debug component=stage type=drop msg="line will not be dropped, the provided regular expression did not match the log line"
ts=2023-06-07T09:53:00.8612692Z component=loki.process.exchange level=debug component=stage type=regex msg="extracted data debug in regex stage" extracteddata="map[filename:C:\\Program Files\\Microsoft\\Exchange Server\\V15\\TransportRoles\\Logs\\FrontEnd\\ProtocolLog\\SmtpReceive\\RECV2023060709-1.LOG msg:,redacted\\Outbound Proxy Frontend redacted,08DB5B925BC90A4A,1,192.168.64.130:717,192.168.64.130:47283,>,\"220 redacted.redacted Microsoft ESMTP MAIL Service ready at Wed, 7 Jun 2023 10:51:59 +0100\" time:2023-06-07T09:52:00.321Z]"
ts=2023-06-07T09:53:00.8982542Z component=loki.process.exchange level=debug component=stage type=regex msg="extracted data debug in regex stage" extracteddata="map[filename:C:\\Program Files\\Microsoft\\Exchange Server\\V15\\TransportRoles\\Logs\\FrontEnd\\ProtocolLog\\SmtpReceive\\RECV2023060709-1.LOG msg:,redacted\\Default Frontend redacted,08DB5B925BC90A4B,1,127.0.0.1:25,127.0.0.1:47284,>,\"220 redacted.redacted Microsoft ESMTP MAIL Service ready at Wed, 7 Jun 2023 10:51:59 +0100\" time:2023-06-07T09:52:00.321Z]"
ts=2023-06-07T09:53:00.8637836Z component=loki.process.final level=debug component=stage type=drop msg="line will not be dropped, it did not meet drop criteria for age; current time=2023-06-07 10:53:00.8637206 +0100 BST m=+227.044381001, drop before=2023-06-06 10:53:00.8637206 +0100 BST m=-86172.955618999, log timestamp=2023-06-07 09:52:00.32 +0000 UTC"
ts=2023-06-07T09:53:00.9083109Z component=loki.process.exchange level=debug component=stage type=drop msg="line will not be dropped, the provided regular expression did not match the log line"
ts=2023-06-07T09:53:00.9163522Z component=loki.process.final level=debug component=stage type=drop msg="line will not be dropped, it did not meet drop criteria for age; current time=2023-06-07 10:53:00.9163522 +0100 BST m=+227.097013901, drop before=2023-06-06 10:53:00.9163522 +0100 BST m=-86172.902986099, log timestamp=2023-06-07 09:52:00.321 +0000 UTC"
ts=2023-06-07T09:53:00.927357Z component=loki.process.exchange level=debug component=stage type=drop msg="line will not be dropped, the provided regular expression did not match the log line"
ts=2023-06-07T09:53:00.9313591Z component=loki.process.exchange level=debug component=stage type=regex msg="extracted data debug in regex stage" extracteddata="map[filename:C:\\Program Files\\Microsoft\\Exchange Server\\V15\\TransportRoles\\Logs\\FrontEnd\\ProtocolLog\\SmtpReceive\\RECV2023060709-1.LOG msg:,redacted\\Outbound Proxy Frontend redacted,08DB5B925BC90A4A,2,192.168.64.130:717,192.168.64.130:47283,<,EHLO smtp.availability.contoso.com time:2023-06-07T09:52:00.322Z]"
ts=2023-06-07T09:53:00.9348484Z component=loki.process.final level=debug component=stage type=drop msg="line will not be dropped, it did not meet drop criteria for age; current time=2023-06-07 10:53:00.9344072 +0100 BST m=+227.115069301, drop before=2023-06-06 10:53:00.9344072 +0100 BST m=-86172.884930699, log timestamp=2023-06-07 09:52:00.321 +0000 UTC"
ts=2023-06-07T09:53:00.9375001Z component=loki.process.exchange level=debug component=stage type=regex msg="extracted data debug in regex stage" extracteddata="map[filename:C:\\Program Files\\Microsoft\\Exchange Server\\V15\\TransportRoles\\Logs\\FrontEnd\\ProtocolLog\\SmtpReceive\\RECV2023060709-1.LOG msg:,redacted\\Default Frontend redacted,08DB5B925BC90A4B,2,127.0.0.1:25,127.0.0.1:47284,<,EHLO time:2023-06-07T09:52:00.322Z]"
ts=2023-06-07T09:53:00.9375001Z component=loki.process.exchange level=debug component=stage type=drop msg="line will not be dropped, the provided regular expression did not match the log line"
ts=2023-06-07T09:53:00.9404249Z component=loki.process.exchange level=debug component=stage type=drop msg="line will not be dropped, the provided regular expression did not match the log line"
ts=2023-06-07T09:53:00.938444Z component=loki.process.final level=debug component=stage type=drop msg="line will not be dropped, it did not meet drop criteria for age; current time=2023-06-07 10:53:00.938444 +0100 BST m=+227.119106201, drop before=2023-06-06 10:53:00.938444 +0100 BST m=-86172.880893799, log timestamp=2023-06-07 09:52:00.322 +0000 UTC"
ts=2023-06-07T09:53:00.9404249Z component=loki.process.exchange level=debug component=stage type=regex msg="extracted data debug in regex stage" extracteddata="map[filename:C:\\Program Files\\Microsoft\\Exchange Server\\V15\\TransportRoles\\Logs\\FrontEnd\\ProtocolLog\\SmtpReceive\\RECV2023060709-1.LOG msg:,redacted\\Outbound Proxy Frontend redacted,08DB5B925BC90A4A,3,192.168.64.130:717,192.168.64.130:47283,>,250  redacted.redacted Hello [192.168.64.130] SIZE 37748736 PIPELINING DSN ENHANCEDSTATUSCODES STARTTLS X-ANONYMOUSTLS AUTH NTLM X-EXPS GSSAPI NTLM 8BITMIME BINARYMIME CHUNKING SMTPUTF8 XRDST time:2023-06-07T09:52:00.322Z]"
ts=2023-06-07T09:53:00.9424332Z component=loki.process.final level=debug component=stage type=drop msg="line will not be dropped, it did not meet drop criteria for age; current time=2023-06-07 10:53:00.9424332 +0100 BST m=+227.123095501, drop before=2023-06-06 10:53:00.9424332 +0100 BST m=-86172.876904499, log timestamp=2023-06-07 09:52:00.322 +0000 UTC"
ts=2023-06-07T09:53:00.9447609Z component=loki.process.exchange level=debug component=stage type=regex msg="extracted data debug in regex stage" extracteddata="map[filename:C:\\Program Files\\Microsoft\\Exchange Server\\V15\\TransportRoles\\Logs\\FrontEnd\\ProtocolLog\\SmtpReceive\\RECV2023060709-1.LOG msg:,redacted\\Default Frontend redacted,08DB5B925BC90A4B,3,127.0.0.1:25,127.0.0.1:47284,>,250  redacted.redacted Hello [127.0.0.1] SIZE 104857600 PIPELINING DSN ENHANCEDSTATUSCODES STARTTLS X-ANONYMOUSTLS AUTH NTLM X-EXPS GSSAPI NTLM 8BITMIME BINARYMIME CHUNKING SMTPUTF8 XRDST time:2023-06-07T09:52:00.322Z]"
ts=2023-06-07T09:53:00.9447609Z component=loki.process.exchange level=debug component=stage type=drop msg="line will not be dropped, the provided regular expression did not match the log line"
ts=2023-06-07T09:53:00.9585088Z component=loki.process.final level=debug component=stage type=drop msg="line will not be dropped, it did not meet drop criteria for age; current time=2023-06-07 10:53:00.9579705 +0100 BST m=+227.138633201, drop before=2023-06-06 10:53:00.9579705 +0100 BST m=-86172.861366799, log timestamp=2023-06-07 09:52:00.322 +0000 UTC"
ts=2023-06-07T09:53:00.9636146Z component=loki.process.final level=debug component=stage type=drop msg="line will not be dropped, it did not meet drop criteria for age; current time=2023-06-07 10:53:00.9636146 +0100 BST m=+227.144277401, drop before=2023-06-06 10:53:00.9636146 +0100 BST m=-86172.855722599, log timestamp=2023-06-07 09:52:00.322 +0000 UTC"
ts=2023-06-07T09:53:00.9610368Z component=loki.process.exchange level=debug component=stage type=drop msg="line will not be dropped, the provided regular expression did not match the log line"
ts=2023-06-07T09:53:00.9610368Z component=loki.process.exchange level=debug component=stage type=regex msg="extracted data debug in regex stage" extracteddata="map[filename:C:\\Program Files\\Microsoft\\Exchange Server\\V15\\TransportRoles\\Logs\\FrontEnd\\ProtocolLog\\SmtpReceive\\RECV2023060709-1.LOG msg:,redacted\\Outbound Proxy Frontend redacted,08DB5B925BC90A4A,4,192.168.64.130:717,192.168.64.130:47283,<,QUIT time:2023-06-07T09:52:00.323Z]"
ts=2023-06-07T09:53:00.978402Z component=loki.process.exchange level=debug component=stage type=drop msg="line will not be dropped, the provided regular expression did not match the log line"
ts=2023-06-07T09:53:00.9777723Z component=loki.process.exchange level=debug component=stage type=regex msg="extracted data debug in regex stage" extracteddata="map[filename:C:\\Program Files\\Microsoft\\Exchange Server\\V15\\TransportRoles\\Logs\\FrontEnd\\ProtocolLog\\SmtpReceive\\RECV2023060709-1.LOG msg:,redacted\\Outbound Proxy Frontend redacted,08DB5B925BC90A4A,5,192.168.64.130:717,192.168.64.130:47283,>,221 2.0.0 Service closing transmission channel time:2023-06-07T09:52:00.324Z]"
ts=2023-06-07T09:53:00.9786062Z component=loki.process.final level=debug component=stage type=drop msg="line will not be dropped, it did not meet drop criteria for age; current time=2023-06-07 10:53:00.978402 +0100 BST m=+227.159065201, drop before=2023-06-06 10:53:00.978402 +0100 BST m=-86172.840934799, log timestamp=2023-06-07 09:52:00.323 +0000 UTC"
ts=2023-06-07T09:53:00.9842768Z component=loki.process.final level=debug component=stage type=drop msg="line will not be dropped, it did not meet drop criteria for age; current time=2023-06-07 10:53:00.9842768 +0100 BST m=+227.164940201, drop before=2023-06-06 10:53:00.9842768 +0100 BST m=-86172.835059799, log timestamp=2023-06-07 09:52:00.324 +0000 UTC"
ts=2023-06-07T09:53:00.983025Z component=loki.process.exchange level=debug component=stage type=drop msg="line will not be dropped, the provided regular expression did not match the log line"
ts=2023-06-07T09:53:00.983025Z component=loki.process.exchange level=debug component=stage type=regex msg="extracted data debug in regex stage" extracteddata="map[filename:C:\\Program Files\\Microsoft\\Exchange Server\\V15\\TransportRoles\\Logs\\FrontEnd\\ProtocolLog\\SmtpReceive\\RECV2023060709-1.LOG msg:,redacted\\Outbound Proxy Frontend redacted,08DB5B925BC90A4A,6,192.168.64.130:717,192.168.64.130:47283,-, time:2023-06-07T09:52:00.324Z]"
ts=2023-06-07T09:53:01.0108431Z component=loki.process.exchange level=debug component=stage type=drop msg="line will not be dropped, the provided regular expression did not match the log line"
ts=2023-06-07T09:53:01.0109989Z component=loki.process.final level=debug component=stage type=drop msg="line will not be dropped, it did not meet drop criteria for age; current time=2023-06-07 10:53:01.0109989 +0100 BST m=+227.191662901, drop before=2023-06-06 10:53:01.0109989 +0100 BST m=-86172.808337099, log timestamp=2023-06-07 09:52:00.324 +0000 UTC"
ts=2023-06-07T09:53:01.0109989Z component=loki.process.exchange level=debug component=stage type=regex msg="extracted data debug in regex stage" extracteddata="map[filename:C:\\Program Files\\Microsoft\\Exchange Server\\V15\\TransportRoles\\Logs\\FrontEnd\\ProtocolLog\\SmtpReceive\\RECV2023060709-1.LOG msg:,redacted\\Default Frontend redacted,08DB5B925BC90A4B,4,127.0.0.1:25,127.0.0.1:47284,<,QUIT time:2023-06-07T09:52:00.324Z]"
ts=2023-06-07T09:53:01.013663Z component=loki.process.exchange level=debug component=stage type=regex msg="extracted data debug in regex stage" extracteddata="map[filename:C:\\Program Files\\Microsoft\\Exchange Server\\V15\\TransportRoles\\Logs\\FrontEnd\\ProtocolLog\\SmtpReceive\\RECV2023060709-1.LOG msg:,redacted\\Default Frontend redacted,08DB5B925BC90A4B,5,127.0.0.1:25,127.0.0.1:47284,>,221 2.0.0 Service closing transmission channel time:2023-06-07T09:52:00.324Z]"
ts=2023-06-07T09:53:01.0142023Z component=loki.process.exchange level=debug component=stage type=drop msg="line will not be dropped, the provided regular expression did not match the log line"
ts=2023-06-07T09:53:01.0142023Z component=loki.process.final level=debug component=stage type=drop msg="line will not be dropped, it did not meet drop criteria for age; current time=2023-06-07 10:53:01.0142023 +0100 BST m=+227.194866401, drop before=2023-06-06 10:53:01.0142023 +0100 BST m=-86172.805133599, log timestamp=2023-06-07 09:52:00.324 +0000 UTC"
ts=2023-06-07T09:53:01.160088Z component=loki.process.final level=debug component=stage type=drop msg="line will not be dropped, it did not meet drop criteria for age; current time=2023-06-07 10:53:01.160088 +0100 BST m=+227.340755601, drop before=2023-06-06 10:53:01.160088 +0100 BST m=-86172.659244399, log timestamp=2023-06-07 09:52:00.324 +0000 UTC"
ts=2023-06-07T09:53:01.1135148Z component=loki.process.exchange level=debug component=stage type=drop msg="line will not be dropped, the provided regular expression did not match the log line"
ts=2023-06-07T09:53:01.1135148Z component=loki.process.exchange level=debug component=stage type=regex msg="extracted data debug in regex stage" extracteddata="map[filename:C:\\Program Files\\Microsoft\\Exchange Server\\V15\\TransportRoles\\Logs\\FrontEnd\\ProtocolLog\\SmtpReceive\\RECV2023060709-1.LOG msg:,redacted\\Default Frontend redacted,08DB5B925BC90A4B,6,127.0.0.1:25,127.0.0.1:47284,-, time:2023-06-07T09:52:00.324Z]"
ts=2023-06-07T09:53:01.2318655Z component=loki.process.exchange level=debug component=stage type=regex msg="extracted data debug in regex stage" extracteddata="map[filename:C:\\Program Files\\Microsoft\\Exchange Server\\V15\\TransportRoles\\Logs\\FrontEnd\\ProtocolLog\\SmtpReceive\\RECV2023060709-1.LOG msg:,redacted\\Anonymous Relay,08DB5B925BC90A4C,0,192.168.64.130:25,192.168.64.130:47313,+, time:2023-06-07T09:52:42.691Z]"
ts=2023-06-07T09:53:01.2318655Z component=loki.process.exchange level=debug component=stage type=drop msg="line will not be dropped, the provided regular expression did not match the log line"
ts=2023-06-07T09:53:01.2318655Z component=loki.process.final level=debug component=stage type=drop msg="line will not be dropped, it did not meet drop criteria for age; current time=2023-06-07 10:53:01.2318655 +0100 BST m=+227.412534901, drop before=2023-06-06 10:53:01.2318655 +0100 BST m=-86172.587465099, log timestamp=2023-06-07 09:52:00.324 +0000 UTC"
ts=2023-06-07T09:53:01.2361238Z component=loki.process.exchange level=debug component=stage type=drop msg="line will not be dropped, the provided regular expression did not match the log line"
ts=2023-06-07T09:53:01.2366619Z component=loki.process.exchange level=debug component=stage type=regex msg="extracted data debug in regex stage" extracteddata="map[filename:C:\\Program Files\\Microsoft\\Exchange Server\\V15\\TransportRoles\\Logs\\FrontEnd\\ProtocolLog\\SmtpReceive\\RECV2023060709-1.LOG msg:,redacted\\Anonymous Relay,08DB5B925BC90A4C,1,192.168.64.130:25,192.168.64.130:47313,*,SMTPSubmit SMTPAcceptAnyRecipient SMTPAcceptAuthenticationFlag SMTPAcceptAnySender SMTPAcceptAuthoritativeDomainSender BypassAntiSpam BypassMessageSizeLimit SMTPAcceptEXCH50 AcceptRoutingHeaders time:2023-06-07T09:52:42.692Z]"
ts=2023-06-07T09:53:01.247116Z component=loki.process.final level=debug component=stage type=drop msg="line will not be dropped, it did not meet drop criteria for age; current time=2023-06-07 10:53:01.2465601 +0100 BST m=+227.427229801, drop before=2023-06-06 10:53:01.2465601 +0100 BST m=-86172.572770199, log timestamp=2023-06-07 09:52:42.691 +0000 UTC"
ts=2023-06-07T09:53:01.2527213Z component=loki.process.exchange level=debug component=stage type=regex msg="extracted data debug in regex stage" extracteddata="map[filename:C:\\Program Files\\Microsoft\\Exchange Server\\V15\\TransportRoles\\Logs\\FrontEnd\\ProtocolLog\\SmtpReceive\\RECV2023060709-1.LOG msg:,redacted\\Anonymous Relay,08DB5B925BC90A4C,2,192.168.64.130:25,192.168.64.130:47313,>,\"220 redacted.redacted Microsoft ESMTP MAIL Service ready at Wed, 7 Jun 2023 10:52:41 +0100\" time:2023-06-07T09:52:42.693Z]"
ts=2023-06-07T09:53:01.2532787Z component=loki.process.exchange level=debug component=stage type=drop msg="line will not be dropped, the provided regular expression did not match the log line"
ts=2023-06-07T09:53:01.2622555Z component=loki.process.final level=debug component=stage type=drop msg="line will not be dropped, it did not meet drop criteria for age; current time=2023-06-07 10:53:01.2622555 +0100 BST m=+227.442925601, drop before=2023-06-06 10:53:01.2622555 +0100 BST m=-86172.557074399, log timestamp=2023-06-07 09:52:42.692 +0000 UTC"
ts=2023-06-07T09:53:01.2654418Z component=loki.process.exchange level=debug component=stage type=drop msg="line will not be dropped, the provided regular expression did not match the log line"
ts=2023-06-07T09:53:01.2654418Z component=loki.process.exchange level=debug component=stage type=regex msg="extracted data debug in regex stage" extracteddata="map[filename:C:\\Program Files\\Microsoft\\Exchange Server\\V15\\TransportRoles\\Logs\\FrontEnd\\ProtocolLog\\SmtpReceive\\RECV2023060709-1.LOG msg:,redacted\\Anonymous Relay,08DB5B925BC90A4C,3,192.168.64.130:25,192.168.64.130:47313,<,EHLO smtp.availability.contoso.com time:2023-06-07T09:52:42.693Z]"
ts=2023-06-07T09:53:01.2667879Z component=loki.process.final level=debug component=stage type=drop msg="line will not be dropped, it did not meet drop criteria for age; current time=2023-06-07 10:53:01.2667879 +0100 BST m=+227.447458101, drop before=2023-06-06 10:53:01.2667879 +0100 BST m=-86172.552541899, log timestamp=2023-06-07 09:52:42.693 +0000 UTC"
ts=2023-06-07T09:53:01.2799845Z component=loki.process.final level=debug component=stage type=drop msg="line will not be dropped, it did not meet drop criteria for age; current time=2023-06-07 10:53:01.2799845 +0100 BST m=+227.460655001, drop before=2023-06-06 10:53:01.2799845 +0100 BST m=-86172.539344999, log timestamp=2023-06-07 09:52:42.693 +0000 UTC"
ts=2023-06-07T09:53:01.2697455Z component=loki.process.exchange level=debug component=stage type=drop msg="line will not be dropped, the provided regular expression did not match the log line"
ts=2023-06-07T09:53:01.2702783Z component=loki.process.exchange level=debug component=stage type=regex msg="extracted data debug in regex stage" extracteddata="map[filename:C:\\Program Files\\Microsoft\\Exchange Server\\V15\\TransportRoles\\Logs\\FrontEnd\\ProtocolLog\\SmtpReceive\\RECV2023060709-1.LOG msg:,redacted\\Anonymous Relay,08DB5B925BC90A4C,4,192.168.64.130:25,192.168.64.130:47313,>,250  redacted.redacted Hello [192.168.64.130] SIZE 37748736 PIPELINING DSN ENHANCEDSTATUSCODES 8BITMIME BINARYMIME CHUNKING SMTPUTF8 time:2023-06-07T09:52:42.694Z]"
ts=2023-06-07T09:53:01.2966817Z component=loki.process.exchange level=debug component=stage type=regex msg="extracted data debug in regex stage" extracteddata="map[filename:C:\\Program Files\\Microsoft\\Exchange Server\\V15\\TransportRoles\\Logs\\FrontEnd\\ProtocolLog\\SmtpReceive\\RECV2023060709-1.LOG msg:,redacted\\Anonymous Relay,08DB5B925BC90A4C,5,192.168.64.130:25,192.168.64.130:47313,<,QUIT time:2023-06-07T09:52:42.697Z]"
ts=2023-06-07T09:53:01.2966817Z component=loki.process.final level=debug component=stage type=drop msg="line will not be dropped, it did not meet drop criteria for age; current time=2023-06-07 10:53:01.2966817 +0100 BST m=+227.477352601, drop before=2023-06-06 10:53:01.2966817 +0100 BST m=-86172.522647399, log timestamp=2023-06-07 09:52:42.694 +0000 UTC"
ts=2023-06-07T09:53:01.3461084Z component=loki.process.final level=debug component=stage type=drop msg="line will not be dropped, it did not meet drop criteria for age; current time=2023-06-07 10:53:01.345279 +0100 BST m=+227.525951101, drop before=2023-06-06 10:53:01.345279 +0100 BST m=-86172.474048899, log timestamp=2023-06-07 09:52:42.697 +0000 UTC"
ts=2023-06-07T09:53:01.2966817Z component=loki.process.exchange level=debug component=stage type=drop msg="line will not be dropped, the provided regular expression did not match the log line"
ts=2023-06-07T09:53:01.4180275Z component=loki.process.exchange level=debug component=stage type=drop msg="line will not be dropped, the provided regular expression did not match the log line"
ts=2023-06-07T09:53:01.4180275Z component=loki.process.exchange level=debug component=stage type=regex msg="extracted data debug in regex stage" extracteddata="map[filename:C:\\Program Files\\Microsoft\\Exchange Server\\V15\\TransportRoles\\Logs\\FrontEnd\\ProtocolLog\\SmtpReceive\\RECV2023060709-1.LOG msg:,redacted\\Anonymous Relay,08DB5B925BC90A4C,6,192.168.64.130:25,192.168.64.130:47313,>,221 2.0.0 Service closing transmission channel time:2023-06-07T09:52:42.698Z]"
ts=2023-06-07T09:53:01.4293901Z component=loki.process.exchange level=debug component=stage type=regex msg="extracted data debug in regex stage" extracteddata="map[filename:C:\\Program Files\\Microsoft\\Exchange Server\\V15\\TransportRoles\\Logs\\FrontEnd\\ProtocolLog\\SmtpReceive\\RECV2023060709-1.LOG msg:,redacted\\Anonymous Relay,08DB5B925BC90A4C,7,192.168.64.130:25,192.168.64.130:47313,-, time:2023-06-07T09:52:42.698Z]"
ts=2023-06-07T09:53:01.4293901Z component=loki.process.final level=debug component=stage type=drop msg="line will not be dropped, it did not meet drop criteria for age; current time=2023-06-07 10:53:01.4293901 +0100 BST m=+227.610064301, drop before=2023-06-06 10:53:01.4293901 +0100 BST m=-86172.389935699, log timestamp=2023-06-07 09:52:42.698 +0000 UTC"
ts=2023-06-07T09:53:01.4409726Z component=loki.process.final level=debug component=stage type=drop msg="line will not be dropped, it did not meet drop criteria for age; current time=2023-06-07 10:53:01.4404319 +0100 BST m=+227.621106301, drop before=2023-06-06 10:53:01.4404319 +0100 BST m=-86172.378893699, log timestamp=2023-06-07 09:52:42.698 +0000 UTC"
rfratto commented 1 year ago

Thanks for reporting. This smells similar to a problem we've been having where we noticed that loki.process was modifying shared memory, which could lead to issues like this.

I'm not sure what the state of that fix is; @tpaschalis would know for sure but he's on PTO until next week.

mateuszdrab commented 1 year ago

Thanks for reporting. This smells similar to a problem we've been having where we noticed that loki.process was modifying shared memory, which could lead to issues like this.

I'm not sure what the state of that fix is; @tpaschalis would know for sure but he's on PTO until next week.

Thanks for the update. This could potentially explain a few crashes I've observed on the agent which could be due to mentioned memory corruption.

Let's await for an update from @tpaschalis when he returns next week

tpaschalis commented 1 year ago

@mateuszdrab hey there, thanks for the report!

On a first glance, it sounds like it could be the same issue; I'm taking another look at the configuration and logs to see if anything seems weird. The fix on 67692153c9037d5892dcec9347973b6ce6354be9 is available on v0.34, is there a chance you could update and see if the issue is still present?

mateuszdrab commented 1 year ago

Sorry to take a long time to report back; however, the good news is that it seems to work fine now therefore I'll close this issue.

Thanks guys