The logs forwarding by syslog got lost

[b1tamara]

On our cloud foundry gorouter VMs we are using syslog_forwarder incl. blackbox in order to forward the sys logs to the syslog endpoint (and then to kibana). Recently we noticed that the logs existing on the VM (in the file named access.log) never reached our syslog endpoint.
Gorouter writes a lot of access logs and the log will be rotated once per 15 minutes:

/var/vcap/sys/log/gorouter# ls -l
-rw-r--r-- 1 vcap vcap 224615711 Oct  6 13:01 access.log
-rw-r--r-- 1 vcap vcap  75124871 Oct  6 12:55 access.log.1.gz
-rw-r--r-- 1 vcap vcap  75679972 Oct  6 12:40 access.log.2.gz
-rw-r--r-- 1 vcap vcap  75690773 Oct  6 12:25 access.log.3.gz
-rw-r--r-- 1 vcap vcap  74491604 Oct  6 12:10 access.log.4.gz
-rw-r--r-- 1 vcap vcap  71526913 Oct  6 11:55 access.log.5.gz
-rw-r--r-- 1 vcap vcap  72239490 Oct  6 11:40 access.log.6.gz
-rw-r--r-- 1 vcap vcap  71869401 Oct  6 11:25 access.log.7.gz

The blackbox is configured to pick up all files placed under /var/vcap/sys/log.

We can also see the many logs about truncation of access.log in /var/vcap/sys/log/syslog_forwarder/blackbox/blackbox.stderr.log:

2021/10/06 11:55:05 Re-opening truncated file /var/vcap/sys/log/gorouter/access.log ...
2021/10/06 11:55:05 Successfully reopened truncated /var/vcap/sys/log/gorouter/access.log
2021/10/06 12:25:05 Re-opening truncated file /var/vcap/sys/log/gorouter/access.log ...
2021/10/06 12:25:05 Successfully reopened truncated /var/vcap/sys/log/gorouter/access.log
2021/10/06 12:25:15 Re-opening truncated file /var/vcap/sys/log/gorouter/gorouter.stdout.log ...
2021/10/06 12:25:15 Successfully reopened truncated /var/vcap/sys/log/gorouter/gorouter.stdout.log
2021/10/06 12:55:05 Re-opening truncated file /var/vcap/sys/log/gorouter/access.log ...
2021/10/06 12:55:05 Successfully reopened truncated /var/vcap/sys/log/gorouter/access.log

Config of the blackbox:

hostname: "-"

use_rfc3339: false
syslog:
  destination:

    transport: tcp

    address: 127.0.0.1:514

  source_dir: /var/vcap/sys/log
  log_filename: false

The configaration of the syslog:

$MaxMessageSize 64k
$WorkDirectory /var/vcap/data/syslog_forwarder/buffered # where messages should be buffered on disk

$ActionQueueFileName           agg_backlog            # Spill to disk if queue is full (default: agg_backlog)
$ActionQueueMaxDiskSpace       1280m       # Max size for disk queue (default: 128m)
$ActionQueueSize               500000                 # Store no more than this number syslog messages in memory (default: 100000)
$ActionQueueDiscardMark        487500         # Purge messages of from memory whose severity is greater than or equal to DiscardSeverity (default: 97500)
$ActionQueueDiscardSeverity    0     # This discards every message as soon as the discard mark is reached (default: 0)
$ActionQueueLowWaterMark       2000       # Num messages. Assuming avg size of 512B, this is 1MiB. (default: 2000)
$ActionQueueHighWaterMark      80000      # Num messages. Assuming avg size of 512B, this is 4MiB. (If this is reached, messages will spill to disk until the low watermark is reached). (default: 80000)
$ActionQueueTimeoutEnqueue     86400000      # Discard messages if the queue + disk is full (default: 0)
$ActionQueueCheckpointInterval 100  # write bookkeeping information on checkpoints (every n records) (default: 100)
$ActionResumeInterval          10            # When action is suspended (dest not connected), retry after this number of seconds (default: 10)
$ActionQueueSaveOnShutdown     on   # Save in-memory data to disk if rsyslog shuts down (default: on)

/var/vcap/data/syslog_forwarder/buffered is empty.
We also check our syslog endpoints and they are healthy and we could not detect that the missing logs reached the endpoint.

We guess it is an issue between blackbox and syslog. It might be that the blackbox tries to send the new logs from the file access.log to the syslog but during that the logfile will be rotated and the data got lost.
The timestamps of missing logs correlated with the rotation of the log files, e.g. I observed 2021-10-06T10:25:01.964203+00:00 localhost CRON[25959]: (root) CMD (/usr/bin/logrotate-cron) and I could not find the log in the kibana for the next 10 minutes:

[cf-gitbot]

We have created an issue in Pivotal Tracker to manage this. Unfortunately, the Pivotal Tracker project is private so you may be unable to view the contents of the story.

The labels on this github issue will be updated when the story is started.

[bosh-admin-bot]

This issue was marked as Stale because it has been open for 21 days without any activity. If no activity takes place in the coming 7 days it will automatically be close. To prevent this from happening remove the Stale label or comment below.

[bosh-admin-bot]

This issue was closed because it has been labeled Stale for 7 days without subsequent activity. Feel free to re-open this issue at any time by commenting below.