[receiver/filelog] Improve receiver logging and monitoring metrics

[ChrsMark]

Component(s)

receiver/filelog

Is your feature request related to a problem? Please describe.

At the moment OTel Collector can collect logs through the filelog receiver.
However the receiver does not log enough details about the file tracking actions nor extensive summary metrics.

Describe the solution you'd like

OTel Collector should be capable to offer the following:

1. Sufficient logging when files are discovered, moved, truncated, etc.: [pkg/stanza] log when files are rotated/moved/truncated #33237
2. Observable metrics about its current state: how many files are opened, being harvested, stale, etc.: [pkg/stanza] Add monitoring metrics for open and harvested files in fileconsumer #31544

Describe alternatives you've considered

No response

Additional context

Sample logs:

log/busybox/foo1.log /var/log/busybox/log3.log /var/log/busybox/simple.log /var/log/busybox/some.log]}	{"kind": "receiver", "name": "filelog", "data_type": "logs", "component": "fileconsumer"}
2024-01-26T12:59:55.586+0200	debug	fileconsumer/file.go:135	matched files%!(EXTRA zapcore.Field={paths 1 0  [/var/log/busybox/bar.log /var/log/busybox/bzr.log /var/log/busybox/foo.1.log /var/log/busybox/foo.log /var/log/busybox/foo1.log /var/log/busybox/log3.log /var/log/busybox/simple.log /var/log/busybox/some.log]})	{"kind": "receiver", "name": "filelog", "data_type": "logs", "component": "fileconsumer"}
2024-01-26T12:59:55.586+0200	debug	fileconsumer/file.go:167	Consuming files{paths 1 0  [/var/log/busybox/bar.log /var/log/busybox/bzr.log /var/log/busybox/foo.1.log /var/log/busybox/foo.log /var/log/busybox/foo1.log /var/log/busybox/log3.log /var/log/busybox/simple.log /var/log/busybox/some.log]}	{"kind": "receiver", "name": "filelog", "data_type": "logs", "component": "fileconsumer"}
2024-01-26T12:59:55.786+0200	debug	fileconsumer/file.go:135	matched files%!(EXTRA zapcore.Field={paths 1 0  [/var/log/busybox/bar.log /var/log/busybox/bzr.log /var/log/busybox/foo.1.log /var/log/busybox/foo.log /var/log/busybox/foo1.log /var/log/busybox/log3.log /var/log/busybox/simple.log /var/log/busybox/some.log]})	{"kind": "receiver", "name": "filelog", "data_type": "logs", "component": "fileconsumer"}
2024-01-26T12:59:55.786+0200	debug	fileconsumer/file.go:167	Consuming files{paths 1 0  [/var/log/busybox/bar.log /var/log/busybox/bzr.log /var/log/busybox/foo.1.log /var/log/busybox/foo.log /var/log/busybox/foo1.log /var/log/busybox/log3.log /var/log/busybox/simple.log /var/log/busybox/some.log]}	{"kind": "receiver", "name": "filelog", "data_type": "logs", "component": "fileconsumer"}
2024-01-26T12:59:55.986+0200	debug	fileconsumer/file.go:135	matched files%!(EXTRA zapcore.Field={paths 1 0  [/var/log/busybox/bar.log /var/log/busybox/bzr.log /var/log/busybox/foo.1.log /var/log/busybox/foo.log /var/log/busybox/foo1.log /var/log/busybox/log3.log /var/log/busybox/simple.log /var/log/busybox/some.log]})	{"kind": "receiver", "name": "filelog", "data_type": "logs", "component": "fileconsumer"}
2024-01-26T12:59:55.986+0200	debug	fileconsumer/file.go:167	Consuming files{paths 1 0  [/var/log/busybox/bar.log /var/log/busybox/bzr.log /var/log/busybox/foo.1.log /var/log/busybox/foo.log /var/log/busybox/foo1.log /var/log/busybox/log3.log /var/log/busybox/simple.log /var/log/busybox/some.log]}	{"kind": "receiver", "name": "filelog", "data_type": "logs", "component": "fileconsumer"}
2024-01-26T12:59:56.185+0200	debug	fileconsumer/file.go:135	matched files%!(EXTRA zapcore.Field={paths 1 0  [/var/log/busybox/bar.log /var/log/busybox/bzr.log /var/log/busybox/foo.1.log /var/log/busybox/foo.log /var/log/busybox/foo1.log /var/log/busybox/log3.log /var/log/busybox/simple.log /var/log/busybox/some.log]})	{"kind": "receiver", "name": "filelog", "data_type": "logs", "component": "fileconsumer"}
2024-01-26T12:59:56.185+0200	debug	fileconsumer/file.go:167	Consuming files{paths 1 0  [/var/log/busybox/bar.log /var/log/busybox/bzr.log /var/log/busybox/foo.1.log /var/log/busybox/foo.log /var/log/busybox/foo1.log /var/log/busybox/log3.log /var/log/busybox/simple.log /var/log/busybox/some.log]}	{"kind": "receiver", "name": "filelog", "data_type": "logs", "component": "fileconsumer"}
2024-01-26T12:59:56.386+0200	debug	fileconsumer/file.go:135	matched files%!(EXTRA zapcore.Field={paths 1 0  [/var/log/busybox/bar.log /var/log/busybox/bzr.log /var/log/busybox/foo.1.log /var/log/busybox/foo.log /var/log/busybox/foo1.log /var/log/busybox/log3.log /var/log/busybox/simple.log /var/log/busybox/some.log]})	{"kind": "receiver", "name": "filelog", "data_type": "logs", "component": "fileconsumer"}
2024-01-26T12:59:56.386+0200	debug	fileconsumer/file.go:167	Consuming files{paths 1 0  [/var/log/busybox/bar.log /var/log/busybox/bzr.log /var/log/busybox/foo.1.log /var/log/busybox/foo.log /var/log/busybox/foo1.log /var/log/busybox/log3.log /var/log/busybox/simple.log /var/log/busybox/some.log]}	{"kind": "receiver", "name": "filelog", "data_type": "logs", "component": "fileconsumer"}
2024-01-26T12:59:56.586+0200	debug	fileconsumer/file.go:135	matched files%!(EXTRA zapcore.Field={paths 1 0  [/var/log/busybox/bar.log /var/log/busybox/bzr.log /var/log/busybox/foo.1.log /var/log/busybox/foo.log /var/log/busybox/foo1.log /var/log/busybox/log3.log /var/log/busybox/simple.log /var/log/busybox/some.log]})	{"kind": "receiver", "name": "filelog", "data_type": "logs", "component": "fileconsumer"}
2024-01-26T12:59:56.586+0200	debug	fileconsumer/file.go:167	Consuming files{paths 1 0  [/var/log/busybox/bar.log /var/log/busybox/bzr.log /var/log/busybox/foo.1.log /var/log/busybox/foo.log /var/log/busybox/foo1.log /var/log/busybox/log3.log /var/log/busybox/simple.log /var/log/busybox/some.log]}	{"kind": "receiver", "name": "filelog", "data_type": "logs", "component": "fileconsumer"}

Sample metrics:

curl http://localhost:8888/metrics
# HELP otelcol_exporter_queue_capacity Fixed capacity of the retry queue (in batches)
# TYPE otelcol_exporter_queue_capacity gauge
otelcol_exporter_queue_capacity{exporter="otlp/elastic",service_instance_id="f9da8915-5bbd-444f-84cf-60a42107a83e",service_name="otelcontribcol",service_version="0.91.0-dev"} 1000
# HELP otelcol_exporter_queue_size Current size of the retry queue (in batches)
# TYPE otelcol_exporter_queue_size gauge
otelcol_exporter_queue_size{exporter="otlp/elastic",service_instance_id="f9da8915-5bbd-444f-84cf-60a42107a83e",service_name="otelcontribcol",service_version="0.91.0-dev"} 0
# HELP otelcol_exporter_sent_log_records Number of log record successfully sent to destination.
# TYPE otelcol_exporter_sent_log_records counter
otelcol_exporter_sent_log_records{exporter="otlp/elastic",service_instance_id="f9da8915-5bbd-444f-84cf-60a42107a83e",service_name="otelcontribcol",service_version="0.91.0-dev"} 11
# HELP otelcol_process_cpu_seconds Total CPU user and system time in seconds
# TYPE otelcol_process_cpu_seconds counter
otelcol_process_cpu_seconds{service_instance_id="f9da8915-5bbd-444f-84cf-60a42107a83e",service_name="otelcontribcol",service_version="0.91.0-dev"} 0.76
# HELP otelcol_process_memory_rss Total physical memory (resident set size)
# TYPE otelcol_process_memory_rss gauge
otelcol_process_memory_rss{service_instance_id="f9da8915-5bbd-444f-84cf-60a42107a83e",service_name="otelcontribcol",service_version="0.91.0-dev"} 1.84000512e+08
# HELP otelcol_process_runtime_heap_alloc_bytes Bytes of allocated heap objects (see 'go doc runtime.MemStats.HeapAlloc')
# TYPE otelcol_process_runtime_heap_alloc_bytes gauge
otelcol_process_runtime_heap_alloc_bytes{service_instance_id="f9da8915-5bbd-444f-84cf-60a42107a83e",service_name="otelcontribcol",service_version="0.91.0-dev"} 4.588912e+07
# HELP otelcol_process_runtime_total_alloc_bytes Cumulative bytes allocated for heap objects (see 'go doc runtime.MemStats.TotalAlloc')
# TYPE otelcol_process_runtime_total_alloc_bytes counter
otelcol_process_runtime_total_alloc_bytes{service_instance_id="f9da8915-5bbd-444f-84cf-60a42107a83e",service_name="otelcontribcol",service_version="0.91.0-dev"} 1.40668584e+08
# HELP otelcol_process_runtime_total_sys_memory_bytes Total bytes of memory obtained from the OS (see 'go doc runtime.MemStats.Sys')
# TYPE otelcol_process_runtime_total_sys_memory_bytes gauge
otelcol_process_runtime_total_sys_memory_bytes{service_instance_id="f9da8915-5bbd-444f-84cf-60a42107a83e",service_name="otelcontribcol",service_version="0.91.0-dev"} 9.3970712e+07
# HELP otelcol_process_uptime Uptime of the process
# TYPE otelcol_process_uptime counter
otelcol_process_uptime{service_instance_id="f9da8915-5bbd-444f-84cf-60a42107a83e",service_name="otelcontribcol",service_version="0.91.0-dev"} 111.114353151
# HELP otelcol_receiver_accepted_log_records Number of log records successfully pushed into the pipeline.
# TYPE otelcol_receiver_accepted_log_records counter
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="f9da8915-5bbd-444f-84cf-60a42107a83e",service_name="otelcontribcol",service_version="0.91.0-dev",transport=""} 11
# HELP otelcol_receiver_refused_log_records Number of log records that could not be pushed into the pipeline.
# TYPE otelcol_receiver_refused_log_records counter
otelcol_receiver_refused_log_records{receiver="filelog",service_instance_id="f9da8915-5bbd-444f-84cf-60a42107a83e",service_name="otelcontribcol",service_version="0.91.0-dev",transport=""} 0

[github-actions]

Pinging code owners:

• receiver/filelog: @djaglowski

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

[djaglowski]

Sufficient logging when files are discovered, moved, truncated, etc

We have some of this already and the rest should be reasonable to add. However, there are some caveats.

• Discovered: already being logged, but we maintain a limited memory of the files we've previously seen.
• Moved: We don't currently log this but we should be able to detect it by crossreferencing file names, which I think we have in the necessary places. It would add some computation so perhaps this should be configurable.
• Truncated: We currently "detect" this but do not log. I think the logic is not perfect and it is possible to miss truncations depending on timing. It'd be helpful to have other perspectives on how this could work performantly.

Observable metrics about its current state: how many files are opened, being harvested, stale, etc

What's your definition of stale?

Up-down counters for open & reading should be straightforward enough to maintain.

[ChrsMark]

What's your definition of stale?

stale when we have reached EOF and the receiver would wait until it looks again for new lines. I'm not sure if this behavior exists though in the receiver. If not, then we can just ignore this metric.

[djaglowski]

stale when we have reached EOF and the receiver would wait until it looks again for new lines. I'm not sure if this behavior exists though in the receiver. If not, then we can just ignore this metric.

This is pretty much the same as open less reading, but maybe there's some more nuance. We can consider when implementing.

In any case, I'm marking this issue as required for ga because I think these are very basic observability signals which we should have in place.

[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.

Pinging code owners:

• receiver/filelog: @djaglowski

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