[filelogreceiver] - ERROR: error finding files: no files match the configured criteria

[cwegener]

Component(s)

pkg/stanza, receiver/filelog

What happened?

Description

After upgrading the OTel Collector from 0.82.0 to 0.84.0, the filelog receiver started producing error messages when the matching rules result in NO files being matched for consuming.

Steps to Reproduce

1. Create config file:

receivers:
  filelog:
    include: [ /tmp/simple.log ]
    operators:
      - type: regex_parser
        regex: '^(?P<time>\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}) (?P<sev>[A-Z]*) (?P<msg>.*)$'
        timestamp:
          parse_from: attributes.time
          layout: '%Y-%m-%d %H:%M:%S'
        severity:
          parse_from: attributes.sev
exporters:
  logging:
service:
  pipelines:
    logs:
      receivers:
        - filelog
      processors: []
      exporters:
        - logging

2. Run OTel Collector 0.82.0 with above config

3. Run OTel Collector 0.84.0 with above config

4. Compare results

Expected Result

No errors logged that zero files were matched. And 1 warning logged during startup that zero files were matched.

Actual Result

1 error per second logged that zero files were matched.

Collector version

v0.84.0

Environment information

Environment

OS: "Ubuntu 22.04", "Windows Server 2022", "Archlinux"
Compiler(if manually compiled): go 1.21.0

OpenTelemetry Collector configuration

receivers:
  filelog:
    include: [ /tmp/simple.log ]
    operators:
      - type: regex_parser
        regex: '^(?P<time>\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}) (?P<sev>[A-Z]*) (?P<msg>.*)$'
        timestamp:
          parse_from: attributes.time
          layout: '%Y-%m-%d %H:%M:%S'
        severity:
          parse_from: attributes.sev
exporters:
  logging:
service:
  pipelines:
    logs:
      receivers:
        - filelog
      processors: []
      exporters:
        - logging

Log output

2023-09-08T12:11:26.478+1000    info    service/telemetry.go:84 Setting up own telemetry...                                                                                                                                                                    2023-09-08T12:11:26.478+1000    info    service/telemetry.go:201        Serving Prometheus metrics      {"address": ":8888", "level": "Basic"}                                                                                                                 2023-09-08T12:11:26.478+1000    info    exporter@v0.84.0/exporter.go:275        Development component. May change in the future.        {"kind": "exporter", "data_type": "logs", "name": "logging"}                                                           2023-09-08T12:11:26.480+1000    info    service/service.go:138  Starting otelcol-atlastix...    {"Version": "0.84.0+atlx.2", "NumCPU": 16}                                                                                                                     2023-09-08T12:11:26.480+1000    info    extensions/extensions.go:31     Starting extensions...                                                                                                                                                                 2023-09-08T12:11:26.480+1000    info    adapter/receiver.go:45  Starting stanza receiver        {"kind": "receiver", "name": "filelog", "data_type": "logs"}                                                                                                   2023-09-08T12:11:26.481+1000    warn    fileconsumer/file.go:61 finding files   {"kind": "receiver", "name": "filelog", "data_type": "logs", "component": "fileconsumer", "error": "no files match the configured criteria"}                                   2023-09-08T12:11:26.481+1000    info    service/service.go:161  Everything is ready. Begin running and processing data.                                                                                                                                        2023-09-08T12:11:26.682+1000    error   fileconsumer/file.go:118        error finding files: no files match the configured criteria     {"kind": "receiver", "name": "filelog", "data_type": "logs", "component": "fileconsumer"}                              github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/fileconsumer.(*Manager).poll                                                                                                                                                                      github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza@v0.84.0/fileconsumer/file.go:118                                                                                                                                                  github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/fileconsumer.(*Manager).startPoller.func1                                                                                                                                                         github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza@v0.84.0/fileconsumer/file.go:99                                                                                                                                                   2023-09-08T12:11:27.882+1000    error   fileconsumer/file.go:118        error finding files: no files match the configured criteria     {"kind": "receiver", "name": "filelog", "data_type": "logs", "component": "fileconsumer"}                              github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/fileconsumer.(*Manager).poll                                                                                                                                                                      github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza@v0.84.0/fileconsumer/file.go:118                                                                                                                                                  github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/fileconsumer.(*Manager).startPoller.func1                                                                                                                                                         github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza@v0.84.0/fileconsumer/file.go:99                                                                                                                                                   2023-09-08T12:11:29.082+1000    error   fileconsumer/file.go:118        error finding files: no files match the configured criteria     {"kind": "receiver", "name": "filelog", "data_type": "logs", "component": "fileconsumer"}                              github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/fileconsumer.(*Manager).poll                                                                                                                                                                      github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza@v0.84.0/fileconsumer/file.go:118                                                                                                                                                  github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/fileconsumer.(*Manager).startPoller.func1                                                                                                                                                         github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza@v0.84.0/fileconsumer/file.go:99                                                                                                                                                   2023-09-08T12:11:30.281+1000    error   fileconsumer/file.go:118        error finding files: no files match the configured criteria     {"kind": "receiver", "name": "filelog", "data_type": "logs", "component": "fileconsumer"}                              github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/fileconsumer.(*Manager).poll                                                                                                                                                                      github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza@v0.84.0/fileconsumer/file.go:118                                                                                                                                                  github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/fileconsumer.(*Manager).startPoller.func1                                                                                                                                                         github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza@v0.84.0/fileconsumer/file.go:99                                                                                                                                                   2023-09-08T12:11:31.282+1000    error   fileconsumer/file.go:118        error finding files: no files match the configured criteria     {"kind": "receiver", "name": "filelog", "data_type": "logs", "component": "fileconsumer"}                              github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/fileconsumer.(*Manager).poll                                                                                                                                                                      github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza@v0.84.0/fileconsumer/file.go:118                                                                                                                                                  github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/fileconsumer.(*Manager).startPoller.func1                                                                                                                                                         github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza@v0.84.0/fileconsumer/file.go:99                                                                                                                                                   2023-09-08T12:11:32.482+1000    error   fileconsumer/file.go:118        error finding files: no files match the configured criteria     {"kind": "receiver", "name": "filelog", "data_type": "logs", "component": "fileconsumer"}                              github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/fileconsumer.(*Manager).poll                                                                                                                                                                      github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza@v0.84.0/fileconsumer/file.go:118                                                                                                                                                  
github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/fileconsumer.(*Manager).startPoller.func1                                                                                                                                                 
        github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza@v0.84.0/fileconsumer/file.go:99                                                                                                                                                   
2023-09-08T12:11:33.681+1000    error   fileconsumer/file.go:118        error finding files: no files match the configured criteria     {"kind": "receiver", "name": "filelog", "data_type": "logs", "component": "fileconsumer"}                              
github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/fileconsumer.(*Manager).poll                                                                                                                                                              
        github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza@v0.84.0/fileconsumer/file.go:118                                                                                                                                                  
github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/fileconsumer.(*Manager).startPoller.func1                                                                                                                                                 
        github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza@v0.84.0/fileconsumer/file.go:99                                                                                                                                                   
2023-09-08T12:11:34.682+1000    error   fileconsumer/file.go:118        error finding files: no files match the configured criteria     {"kind": "receiver", "name": "filelog", "data_type": "logs", "component": "fileconsumer"}                              
github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/fileconsumer.(*Manager).poll                                                                                                                                                              
        github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza@v0.84.0/fileconsumer/file.go:118                                                                                                                                                  
github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/fileconsumer.(*Manager).startPoller.func1                                                                                                                                                 
        github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza@v0.84.0/fileconsumer/file.go:99                                                                                                                                                   
^C2023-09-08T12:11:34.906+1000  info    otelcol/collector.go:250        Received signal from OS {"signal": "interrupt"}                                                                                                                                        
2023-09-08T12:11:34.906+1000    info    service/service.go:170  Starting shutdown...                                                                                                                                                                           
2023-09-08T12:11:34.906+1000    info    adapter/receiver.go:139 Stopping stanza receiver        {"kind": "receiver", "name": "filelog", "data_type": "logs"}                                                                                                   
2023-09-08T12:11:34.907+1000    info    extensions/extensions.go:45     Stopping extensions...                                                                                                                                                                 
2023-09-08T12:11:34.907+1000    info    service/service.go:184  Shutdown complete.

Additional context

No response

[github-actions]

Pinging code owners:

• filelogreceiver: @djaglowski
• pkg/stanza: @djaglowski
• receiver/filelog: @djaglowski

See Adding Labels via Comments if you do not have permissions to add labels yourself.

[djaglowski]

I believe this behavior has been in place for about 3 months. That said, I agree this shouldn't be an error message. I've opened #26526 to reduce this to a warning log.

[cwegener]

I believe this behavior has been in place for about 3 months.

I didn't get a chance to bisect the issue yet. A bit strange that I see the difference when going from 0.82.0 to 0.84.0, considering that the change you've identified was introduced in 0.81.0 0.80.0 0.81.0

I've opened #26526 to reduce this to a warning log

Warning sounds good, considering that it has been a warning before.

Lastly, which part determines the 1 second interval that I'm seeing? I couldn't spot anything in the filelog receiver docs that points to something happening every 1 second.

[kevinnoel-be]

Hello @djaglowski
We've seen this issue happening on our side too when upgrading from v0.76 to v0.84. Reducing to warning doesn't really works for us as we are interested in warning logs and also some of our filelog receivers check for files that are optional, appearing later etc.. Shouldn't this be an option instead? E.g. warn/error if files are required to be present, and lower severity if those files are optional? WDYT?

[djaglowski]

My opinion is that we should not add configuration at the component level to control log levels. This will lead to a lot of complexity and inconsistency across the codebase. I think we can try to choose a reasonable log level but ultimately some folks will need to manipulate or filter their telemetry to meet their needs. Info level may be reasonable, but the downside there is that new users will often miss the immediate feedback they need to get started using the collector.

warn/error if files are required to be present

I don't think the receiver should apply strong expectations in any case. There are too many legitimate situations where log files may not be present, temporarily or otherwise. Again, we can generate the telemetry but users may need to process/react to the telemetry according to their needs.

[kevinnoel-be]

I can understand from the collector side that it may not make sense to introduce|maintain this complexity. We'll drop those on our side then, thanks!

[cwegener]

We've seen this issue happening on our side too when upgrading from v0.76 to v0.84. Reducing to warning doesn't really works for us as we are interested in warning logs and also some of our filelog receivers check for files that are optional, appearing later etc.. Shouldn't this be an option instead? E.g. warn/error if files are required to be present, and lower severity if those files are optional? WDYT?

I think that the original design actually was catering for this use case and it has now changed. Not 100% sure.

This is the part in the design:

opentelemetry-collector-contrib/pkg/stanza/fileconsumer/design.md

Line 89 in 28bce8a

3. As a special case, on the first poll cycle, a warning is printed if no files are matched. Execution continues regardless.

@djaglowski Does the design doc need changing in order to reflect the changed behaviour?

[djaglowski]

@cwegener, I believe the statement is still accurate. We print a warning if no files are found during startup.

[cwegener]

@cwegener, I believe the statement is still accurate. We print a warning if no files are found during startup.

I thought that the warning is now printed on every poll cycle instead of just the first poll cycle. I'll have a quick check to verify.

[kevinnoel-be]

@djaglowski we see this log occurring again on each poll cycle (instead of initial one only) since we've upgraded from v0.94 to v0.96; should we open another issue?

[djaglowski]

Thanks for reporting @kevinnoel-be. I'll look into it.

[djaglowski]

I opened #32011 to fix it. Apologies, this somehow snuck in with #30728.

[github-actions]

This issue has been inactive for 60 days. It will be closed in 60 days if there is no activity. To ping code owners by adding a component label, see Adding Labels via Comments, or if you are unsure of which component this issue relates to, please ping @open-telemetry/collector-contrib-triagers. If this issue is still relevant, please ping the code owners or leave a comment explaining why it is still relevant. Otherwise, please close it.

[djaglowski]

Closed by #32011