[pkg/stanza] log when files are rotated/moved/truncated #33237

ChrsMark · 2024-05-27T13:13:04Z

Description:

This PR adds the logging part from #31256.
With this addition every time that is identified that file is rotated
either by move/create or copy/truncate, proper logging takes place.

Link to tracking Issue: #31256

Testing:
Updated existing unit tests

How to test this manually

Using the following config:

receivers:
  filelog:
    start_at: beginning
    poll_interval: 5s
    include:
    - /var/log/busybox/monitoring/stable*.log

exporters:
  debug:
    verbosity: detailed

service:
  telemetry:
    logs:
      level: info
  pipelines:
    logs:
      receivers: [filelog]
      exporters: [debug]
      processors: []

Testing truncate (out of pattern)

echo "$(date '+%FT%H:%M:%S.%NZ') some line1" >> /var/log/busybox/monitoring/stable_trunc.log && 
echo "$(date '+%FT%H:%M:%S.%NZ') some line2" >> /var/log/busybox/monitoring/stable_trunc.log &&  
echo "$(date '+%FT%H:%M:%S.%NZ') some line3" >> /var/log/busybox/monitoring/stable_trunc.log && 
sleep 6 && 
cp /var/log/busybox/monitoring/stable_trunc.log /var/log/busybox/monitoring/stable_trunc.log.1 && 
: > /var/log/busybox/monitoring/stable_trunc.log && 
echo "$(date '+%FT%H:%M:%S.%NZ') some line new0" >> /var/log/busybox/monitoring/stable_trunc.log

Testing truncate (in pattern)

echo "$(date '+%FT%H:%M:%S.%NZ') some line1" >> /var/log/busybox/monitoring/stable_trunc.log &&
echo "$(date '+%FT%H:%M:%S.%NZ') some line2" >> /var/log/busybox/monitoring/stable_trunc.log && 
echo "$(date '+%FT%H:%M:%S.%NZ') some line3" >> /var/log/busybox/monitoring/stable_trunc.log &&
sleep 6 &&
cp /var/log/busybox/monitoring/stable_trunc.log /var/log/busybox/monitoring/stable_trunc_1.log &&
: > /var/log/busybox/monitoring/stable_trunc.log &&
echo "$(date '+%FT%H:%M:%S.%NZ') some line new1" >> /var/log/busybox/monitoring/stable_trunc.log

Testing move/create (out of pattern)

echo "$(date '+%FT%H:%M:%S.%NZ') some line1" >> /var/log/busybox/monitoring/stable_trunc.log &&
echo "$(date '+%FT%H:%M:%S.%NZ') some line2" >> /var/log/busybox/monitoring/stable_trunc.log && 
echo "$(date '+%FT%H:%M:%S.%NZ') some line3" >> /var/log/busybox/monitoring/stable_trunc.log &&
sleep 6 &&
mv /var/log/busybox/monitoring/stable_trunc.log /var/log/busybox/monitoring/stable_trunc.log.1 &&
echo "$(date '+%FT%H:%M:%S.%NZ') some line new0" >> /var/log/busybox/monitoring/stable_trunc.log

Testing move/create (in pattern)

echo "$(date '+%FT%H:%M:%S.%NZ') some line1" >> /var/log/busybox/monitoring/stable_trunc.log &&
echo "$(date '+%FT%H:%M:%S.%NZ') some line2" >> /var/log/busybox/monitoring/stable_trunc.log && 
echo "$(date '+%FT%H:%M:%S.%NZ') some line3" >> /var/log/busybox/monitoring/stable_trunc.log &&
sleep 6 &&
mv /var/log/busybox/monitoring/stable_trunc.log /var/log/busybox/monitoring/stable_trunc_1.log &&
echo "$(date '+%FT%H:%M:%S.%NZ') some line new0" >> /var/log/busybox/monitoring/stable_trunc.log

Documentation:
Add some extra notes in the design.md

djaglowski

Should we add actual test cases to make sure we don't regress? We could use zaptest/observer to validated the expected logs.

djaglowski · 2024-05-30T13:36:27Z

pkg/stanza/fileconsumer/file_other.go

 // the Validate method to ensure that the file has not been truncated.
 if !oldReader.Validate() {
+ m.set.Logger.Debug("File has been rotated(truncated)", zap.String("path", newReader.GetFileName()))


I suppose it doesn't technically matter but do you think it would be slightly more readable to use oldReader here, simply because we are communicating to the reader about the old file that is no longer here?

djaglowski · 2024-05-30T15:29:26Z

pkg/stanza/fileconsumer/design.md

+A) When a file it rotated out of pattern via move/create, we detect that
+ our old handle is still valid and we attempt to read from it.
+B) When a file it rotated out of pattern via copy/truncate, we detect that
+ our old handle is invalid and we do not attempt to read from it.
+C) When a file is copied within the pattern with unread logs on the end, then the original is truncated,
+ we get the unread logs on the copy as well as any new logs written to the truncated file
+D) When a file is moved within the pattern with unread logs on the end, then the original is created again,
+ we get the unread logs on the moved as well as any new logs written to the newly created file


Good explainations. Can I suggest we reverse the order so that we start with the simplest case (move/create within pattern) and progress to the most complex (copy/truncate out of pattern)?

djaglowski · 2024-05-30T15:30:09Z

pkg/stanza/fileconsumer/design.md

+In case of the file has been rotated with copy/truncate, the old handle will be pointing
+to the original file which is truncated. So we don't have a handle so as to consume any remaining
+logs from the moved file. This can cause data loss.
+In case of the file has been rotated with move/create, the old handle will be pointing
+to the moved file so we can still consume from it even if it's out of the pattern.


Here as well, I think move/create is simpler to understand since copy/truncate comes with a possible data loss scenario.

Signed-off-by: ChrsMark <[email protected]>

…ry#33237) **Description:** <Describe what has changed.>  This PR adds the logging part from open-telemetry#31256. With this addition every time that is identified that file is rotated either by move/create or copy/truncate, proper logging takes place. **Link to tracking Issue:** <Issue number if applicable> open-telemetry#31256 **Testing:** <Describe what testing was performed and which tests were added.> Updated existing unit tests ### How to test this manually Using the following config: ```yaml receivers: filelog: start_at: beginning poll_interval: 5s include: - /var/log/busybox/monitoring/stable*.log exporters: debug: verbosity: detailed service: telemetry: logs: level: info pipelines: logs: receivers: [filelog] exporters: [debug] processors: [] ``` #### Testing truncate (out of pattern) ```console echo "$(date '+%FT%H:%M:%S.%NZ') some line1" >> /var/log/busybox/monitoring/stable_trunc.log && echo "$(date '+%FT%H:%M:%S.%NZ') some line2" >> /var/log/busybox/monitoring/stable_trunc.log && echo "$(date '+%FT%H:%M:%S.%NZ') some line3" >> /var/log/busybox/monitoring/stable_trunc.log && sleep 6 && cp /var/log/busybox/monitoring/stable_trunc.log /var/log/busybox/monitoring/stable_trunc.log.1 && : > /var/log/busybox/monitoring/stable_trunc.log && echo "$(date '+%FT%H:%M:%S.%NZ') some line new0" >> /var/log/busybox/monitoring/stable_trunc.log ``` #### Testing truncate (in pattern) ```console echo "$(date '+%FT%H:%M:%S.%NZ') some line1" >> /var/log/busybox/monitoring/stable_trunc.log && echo "$(date '+%FT%H:%M:%S.%NZ') some line2" >> /var/log/busybox/monitoring/stable_trunc.log && echo "$(date '+%FT%H:%M:%S.%NZ') some line3" >> /var/log/busybox/monitoring/stable_trunc.log && sleep 6 && cp /var/log/busybox/monitoring/stable_trunc.log /var/log/busybox/monitoring/stable_trunc_1.log && : > /var/log/busybox/monitoring/stable_trunc.log && echo "$(date '+%FT%H:%M:%S.%NZ') some line new1" >> /var/log/busybox/monitoring/stable_trunc.log ``` #### Testing move/create (out of pattern) ```console echo "$(date '+%FT%H:%M:%S.%NZ') some line1" >> /var/log/busybox/monitoring/stable_trunc.log && echo "$(date '+%FT%H:%M:%S.%NZ') some line2" >> /var/log/busybox/monitoring/stable_trunc.log && echo "$(date '+%FT%H:%M:%S.%NZ') some line3" >> /var/log/busybox/monitoring/stable_trunc.log && sleep 6 && mv /var/log/busybox/monitoring/stable_trunc.log /var/log/busybox/monitoring/stable_trunc.log.1 && echo "$(date '+%FT%H:%M:%S.%NZ') some line new0" >> /var/log/busybox/monitoring/stable_trunc.log ``` #### Testing move/create (in pattern) ```console echo "$(date '+%FT%H:%M:%S.%NZ') some line1" >> /var/log/busybox/monitoring/stable_trunc.log && echo "$(date '+%FT%H:%M:%S.%NZ') some line2" >> /var/log/busybox/monitoring/stable_trunc.log && echo "$(date '+%FT%H:%M:%S.%NZ') some line3" >> /var/log/busybox/monitoring/stable_trunc.log && sleep 6 && mv /var/log/busybox/monitoring/stable_trunc.log /var/log/busybox/monitoring/stable_trunc_1.log && echo "$(date '+%FT%H:%M:%S.%NZ') some line new0" >> /var/log/busybox/monitoring/stable_trunc.log ``` **Documentation:** <Describe the documentation added.> Add some extra notes in the `design.md` --------- Signed-off-by: ChrsMark <[email protected]>

github-actions bot added the pkg/stanza label May 27, 2024

github-actions bot requested a review from djaglowski May 27, 2024 13:13

ChrsMark force-pushed the add_filelog_logging branch 2 times, most recently from 08f16a6 to b7343dd Compare May 29, 2024 14:42

ChrsMark mentioned this pull request May 29, 2024

[receiver/filelog] Improve receiver logging and monitoring metrics #31256

Closed

ChrsMark force-pushed the add_filelog_logging branch from b7343dd to 147044a Compare May 29, 2024 15:25

ChrsMark changed the title ~~[wip] [pkg/stanza] log when files are moved/truncated~~ [wip] [pkg/stanza] log when files are rotated/moved/truncated May 29, 2024

ChrsMark changed the title ~~[wip] [pkg/stanza] log when files are rotated/moved/truncated~~ [pkg/stanza] log when files are rotated/moved/truncated May 29, 2024

ChrsMark force-pushed the add_filelog_logging branch from 147044a to 8716076 Compare May 29, 2024 15:25

djaglowski reviewed May 30, 2024

View reviewed changes

ChrsMark force-pushed the add_filelog_logging branch from 8716076 to 1f74fee Compare May 30, 2024 13:57

djaglowski reviewed May 30, 2024

View reviewed changes

ChrsMark force-pushed the add_filelog_logging branch 2 times, most recently from a698bda to 5bd7b4d Compare May 31, 2024 13:40

ChrsMark added 4 commits May 31, 2024 16:50

[pkg/stanza] log when files are rotated/moved/truncated

61095c5

Signed-off-by: ChrsMark <[email protected]>

add some additional docs about the log rotation cases

794263e

Signed-off-by: ChrsMark <[email protected]>

fix cases order

c1699fc

Signed-off-by: ChrsMark <[email protected]>

verify that logging is present on rotation test cases

78f738a

Signed-off-by: ChrsMark <[email protected]>

ChrsMark force-pushed the add_filelog_logging branch from 5bd7b4d to 78f738a Compare May 31, 2024 13:50

ChrsMark marked this pull request as ready for review May 31, 2024 14:16

ChrsMark requested a review from a team as a code owner May 31, 2024 14:16

ChrsMark requested a review from TylerHelmuth May 31, 2024 14:16

github-actions bot assigned crobert-1 May 31, 2024

djaglowski approved these changes May 31, 2024

View reviewed changes

atoulme approved these changes May 31, 2024

View reviewed changes

djaglowski merged commit 0978757 into open-telemetry:main May 31, 2024
164 checks passed

github-actions bot added this to the next release milestone May 31, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[pkg/stanza] log when files are rotated/moved/truncated #33237

[pkg/stanza] log when files are rotated/moved/truncated #33237

ChrsMark commented May 27, 2024 •

edited

Loading

djaglowski left a comment

djaglowski May 30, 2024

djaglowski May 30, 2024

djaglowski May 30, 2024

[pkg/stanza] log when files are rotated/moved/truncated #33237

[pkg/stanza] log when files are rotated/moved/truncated #33237

Conversation

ChrsMark commented May 27, 2024 • edited Loading

How to test this manually

Testing truncate (out of pattern)

Testing truncate (in pattern)

Testing move/create (out of pattern)

Testing move/create (in pattern)

djaglowski left a comment

Choose a reason for hiding this comment

djaglowski May 30, 2024

Choose a reason for hiding this comment

djaglowski May 30, 2024

Choose a reason for hiding this comment

djaglowski May 30, 2024

Choose a reason for hiding this comment

ChrsMark commented May 27, 2024 •

edited

Loading