Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

file logger: buffer is full, 5768 dnsmessage(s) dropped #837

Closed
yadavp27 opened this issue Oct 8, 2024 · 17 comments
Closed

file logger: buffer is full, 5768 dnsmessage(s) dropped #837

yadavp27 opened this issue Oct 8, 2024 · 17 comments
Labels
enhancement New feature or request waiting feedback
Milestone

Comments

@yadavp27
Copy link

yadavp27 commented Oct 8, 2024

Hi,

Im using go-dnscollector v1.0.0, getting the warring message buffer is full, 5768 dnsmessage(s) dropped.
tried setting the default values chan-buffer-size: 0 and 30720, below is the config file can some one suggest if any tweak is needed in the config file.

global:
  trace:
    verbose: true

pipelines:
  - name: tap
    dnstap:
      sock-path: /var/run/dnscollector/dnstap.sock
    routing-policy:
      forward: [ file ]

  - name: file
    logfile:
      file-path:  "/var/log/dnscollector/dnstap.log"
      compress: true
      max-size: 30720
      max-files: 7
      mode: json
      flush-interval: 10
      chan-buffer-size: 0
      text-format: "timestamp identity qr operation rcode queryip queryport responseip responseport family protocol length qname qtype latency ttl"

logs:
Oct 07 18:06:16 dnscollector go-dnscollector[3564495]: WARNING: 2024/10/07 18:06:16.724111 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 1596 dnsmessage(s) dropped
Oct 07 18:06:26 dnscollector go-dnscollector[3564495]: WARNING: 2024/10/07 18:06:26.724988 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 6556 dnsmessage(s) dropped
Oct 07 18:06:36 dnscollector go-dnscollector[3564495]: WARNING: 2024/10/07 18:06:36.725535 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 6724 dnsmessage(s) dropped
Oct 07 18:06:46 dnscollector go-dnscollector[3564495]: WARNING: 2024/10/07 18:06:46.726453 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 5972 dnsmessage(s) dropped
Oct 07 18:06:56 dnscollector go-dnscollector[3564495]: WARNING: 2024/10/07 18:06:56.726685 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 7065 dnsmessage(s) dropped
Oct 07 18:07:06 dnscollector go-dnscollector[3564495]: WARNING: 2024/10/07 18:07:06.727064 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 6029 dnsmessage(s) dropped
Oct 07 18:07:16 dnscollector go-dnscollector[3564495]: WARNING: 2024/10/07 18:07:16.727741 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 5829 dnsmessage(s) dropped
Oct 07 18:07:26 dnscollector go-dnscollector[3564495]: WARNING: 2024/10/07 18:07:26.728751 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 6174 dnsmessage(s) dropped
Oct 07 18:07:36 dnscollector go-dnscollector[3564495]: WARNING: 2024/10/07 18:07:36.729660 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 5778 dnsmessage(s) dropped
Oct 07 18:07:46 dnscollector go-dnscollector[3564495]: WARNING: 2024/10/07 18:07:46.730720 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 6140 dnsmessage(s) dropped
Oct 07 18:07:56 dnscollector go-dnscollector[3564495]: WARNING: 2024/10/07 18:07:56.731152 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 6053 dnsmessage(s) dropped
Oct 07 18:08:06 dnscollector go-dnscollector[3564495]: WARNING: 2024/10/07 18:08:06.732230 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 5895 dnsmessage(s) dropped
Oct 07 18:08:16 dnscollector go-dnscollector[3564495]: WARNING: 2024/10/07 18:08:16.732329 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 6083 dnsmessage(s) dropped
Oct 07 18:08:26 dnscollector go-dnscollector[3564495]: WARNING: 2024/10/07 18:08:26.732412 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 6050 dnsmessage(s) dropped
Oct 07 18:08:36 dnscollector go-dnscollector[3564495]: WARNING: 2024/10/07 18:08:36.732935 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 5488 dnsmessage(s) dropped
Oct 07 18:08:46 dnscollector go-dnscollector[3564495]: WARNING: 2024/10/07 18:08:46.733642 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 5914 dnsmessage(s) dropped
Oct 07 18:08:56 dnscollector go-dnscollector[3564495]: WARNING: 2024/10/07 18:08:56.733756 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 7116 dnsmessage(s) dropped
Oct 07 18:09:06 dnscollector go-dnscollector[3564495]: WARNING: 2024/10/07 18:09:06.733896 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 5845 dnsmessage(s) dropped
Oct 07 18:09:16 dnscollector go-dnscollector[3564495]: WARNING: 2024/10/07 18:09:16.733973 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 5587 dnsmessage(s) dropped
Oct 07 18:09:26 dnscollector go-dnscollector[3564495]: WARNING: 2024/10/07 18:09:26.734995 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 5570 dnsmessage(s) dropped
Oct 07 18:09:36 dnscollector go-dnscollector[3564495]: WARNING: 2024/10/07 18:09:36.735098 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 5593 dnsmessage(s) dropped
Oct 07 18:09:46 dnscollector go-dnscollector[3564495]: WARNING: 2024/10/07 18:09:46.735690 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 5701 dnsmessage(s) dropped
Oct 07 18:09:56 dnscollector go-dnscollector[3564495]: WARNING: 2024/10/07 18:09:56.736378 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 5875 dnsmessage(s) dropped
Oct 07 18:10:06 dnscollector go-dnscollector[3564495]: WARNING: 2024/10/07 18:10:06.736505 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 5680 dnsmessage(s) dropped
Oct 07 18:10:16 dnscollector go-dnscollector[3564495]: WARNING: 2024/10/07 18:10:16.737712 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 4175 dnsmessage(s) dropped

can some please help on this.

Thanks.

@dmachard
Copy link
Owner

dmachard commented Oct 9, 2024

Hi,

Could you try to update your config with the following settings ?

global:
  ...
  worker:
    buffer-size: 8192
  telemetry:
    enabled: false

....
  - name: file
    logfile:
      .....
      flush-interval: 1
    

and also use the new beta release https://github.com/dmachard/go-dnscollector/releases/tag/v1.1.0-beta2

@dmachard dmachard added the enhancement New feature or request label Oct 9, 2024
@dmachard dmachard added this to the v1.1.0 milestone Oct 9, 2024
@yadavp27
Copy link
Author

yadavp27 commented Oct 10, 2024

Hello @dmachard,

i Tested with the above changes, still seeing the same below is the config

global:
  trace:
    verbose: true
  worker:
    buffer-size: 8192
  telemetry:
    enabled: false

pipelines:
  - name: tap
    dnstap:
      sock-path: /var/run/dnscollector/dnstap.sock
    routing-policy:
      forward: [ file ]

  - name: file
    logfile:
      file-path:  "/var/log/dnscollector/dnstap.log"
      compress: true
      max-size: 30720
      max-files: 7
      mode: json
      flush-interval: 1
      chan-buffer-size: 0
      text-format: "timestamp identity qr operation rcode queryip queryport responseip responseport family protocol length qname qtype latency ttl"

logs:

Oct 09 23:16:46 dnscollector go-dnscollector[3660579]: WARNING: 2024/10/09 23:16:46.274899 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 5480 dnsmessage(s) dropped
Oct 09 23:16:56 dnscollector go-dnscollector[3660579]: WARNING: 2024/10/09 23:16:56.275917 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 5933 dnsmessage(s) dropped
Oct 09 23:17:06 dnscollector go-dnscollector[3660579]: WARNING: 2024/10/09 23:17:06.276921 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 5931 dnsmessage(s) dropped
Oct 09 23:17:16 dnscollector go-dnscollector[3660579]: WARNING: 2024/10/09 23:17:16.277991 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 6150 dnsmessage(s) dropped
Oct 09 23:17:26 dnscollector go-dnscollector[3660579]: WARNING: 2024/10/09 23:17:26.278450 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 6271 dnsmessage(s) dropped
Oct 09 23:17:36 dnscollector go-dnscollector[3660579]: WARNING: 2024/10/09 23:17:36.279367 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 5834 dnsmessage(s) dropped
Oct 09 23:17:46 dnscollector go-dnscollector[3660579]: WARNING: 2024/10/09 23:17:46.280017 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 5921 dnsmessage(s) dropped
Oct 09 23:17:56 dnscollector go-dnscollector[3660579]: WARNING: 2024/10/09 23:17:56.280257 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 5981 dnsmessage(s) dropped

@dmachard
Copy link
Owner

Are you using the v1.1.0-beta2 ?
How much traffic load is being sent?"

@yadavp27
Copy link
Author

im using V1.0.0,
1083646 QPS.

@dmachard
Copy link
Owner

Please to try the v1.1.0-beta2 or the Head of the repo
I pushed a fix to reduce the number of writes on disk

@dmachard
Copy link
Owner

Any feedback will be appreciated

@yadavp27
Copy link
Author

yadavp27 commented Oct 16, 2024

go-dnscollector -version
1.1.0-beta4

still the same Waring.

Oct 16 07:18:48 dnscollector go-dnscollector[3839624]: WARNING: 2024/10/16 07:18:48.827204 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 1874 dnsmessage(s) dropped
Oct 16 07:18:58 dnscollector go-dnscollector[3839624]: WARNING: 2024/10/16 07:18:58.827837 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 3611 dnsmessage(s) dropped
Oct 16 07:19:08 dnscollector go-dnscollector[3839624]: WARNING: 2024/10/16 07:19:08.828742 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 3892 dnsmessage(s) dropped
Oct 16 07:19:18 dnscollector go-dnscollector[3839624]: WARNING: 2024/10/16 07:19:18.828915 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 3425 dnsmessage(s) dropped
Oct 16 07:19:28 dnscollector go-dnscollector[3839624]: WARNING: 2024/10/16 07:19:28.829205 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 2918 dnsmessage(s) dropped
Oct 16 07:19:38 dnscollector go-dnscollector[3839624]: WARNING: 2024/10/16 07:19:38.829754 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 3746 dnsmessage(s) dropped
Oct 16 07:19:48 dnscollector go-dnscollector[3839624]: WARNING: 2024/10/16 07:19:48.830708 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 3562 dnsmessage(s) dropped
Oct 16 07:19:58 dnscollector go-dnscollector[3839624]: WARNING: 2024/10/16 07:19:58.830855 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 2968 dnsmessage(s) dropped
Oct 16 07:20:08 dnscollector go-dnscollector[3839624]: WARNING: 2024/10/16 07:20:08.831800 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 3625 dnsmessage(s) dropped
Oct 16 07:20:18 dnscollector go-dnscollector[3839624]: WARNING: 2024/10/16 07:20:18.833092 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 4460 dnsmessage(s) dropped
Oct 16 07:20:28 dnscollector go-dnscollector[3839624]: WARNING: 2024/10/16 07:20:28.833395 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 3642 dnsmessage(s) dropped
Oct 16 07:20:38 dnscollector go-dnscollector[3839624]: WARNING: 2024/10/16 07:20:38.833711 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 3425 dnsmessage(s) dropped
Oct 16 07:20:48 dnscollector go-dnscollector[3839624]: WARNING: 2024/10/16 07:20:48.834768 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 3519 dnsmessage(s) dropped
Oct 16 07:20:58 dnscollector go-dnscollector[3839624]: WARNING: 2024/10/16 07:20:58.835572 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 3371 dnsmessage(s) dropped
Oct 16 07:21:08 dnscollector go-dnscollector[3839624]: WARNING: 2024/10/16 07:21:08.835905 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 3431 dnsmessage(s) dropped
Oct 16 07:21:18 dnscollector go-dnscollector[3839624]: WARNING: 2024/10/16 07:21:18.836343 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 3414 dnsmessage(s) dropped
Oct 16 07:21:28 dnscollector go-dnscollector[3839624]: WARNING: 2024/10/16 07:21:28.836897 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 2992 dnsmessage(s) dropped
Oct 16 07:21:38 dnscollector go-dnscollector[3839624]: WARNING: 2024/10/16 07:21:38.837576 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 3629 dnsmessage(s) dropped
Oct 16 07:21:48 dnscollector go-dnscollector[3839624]: WARNING: 2024/10/16 07:21:48.838139 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 3455 dnsmessage(s) dropped
Oct 16 07:21:58 dnscollector go-dnscollector[3839624]: WARNING: 2024/10/16 07:21:58.839217 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 3571 dnsmessage(s) dropped
Oct 16 07:22:08 dnscollector go-dnscollector[3839624]: WARNING: 2024/10/16 07:22:08.839556 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 3910 dnsmessage(s) dropped
Oct 16 07:22:18 dnscollector go-dnscollector[3839624]: WARNING: 2024/10/16 07:22:18.840637 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 3383 dnsmessage(s) dropped
Oct 16 07:22:28 dnscollector go-dnscollector[3839624]: WARNING: 2024/10/16 07:22:28.841005 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 2817 dnsmessage(s) dropped
Oct 16 07:22:38 dnscollector go-dnscollector[3839624]: WARNING: 2024/10/16 07:22:38.841566 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 3709 dnsmessage(s) dropped
Oct 16 07:22:48 dnscollector go-dnscollector[3839624]: WARNING: 2024/10/16 07:22:48.842575 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 3609 dnsmessage(s) dropped
Oct 16 07:22:58 dnscollector go-dnscollector[3839624]: WARNING: 2024/10/16 07:22:58.843503 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 3476 dnsmessage(s) dropped
Oct 16 07:23:08 dnscollector go-dnscollector[3839624]: WARNING: 2024/10/16 07:23:08.843589 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 3981 dnsmessage(s) dropped
Oct 16 07:23:18 dnscollector go-dnscollector[3839624]: WARNING: 2024/10/16 07:23:18.843724 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 3617 dnsmessage(s) dropped
Oct 16 07:23:28 dnscollector go-dnscollector[3839624]: WARNING: 2024/10/16 07:23:28.844797 worker - [tap] (conn #1) dnstap processor - worker[file] buffer is full, 1428 dnsmessage(s) dropped

config:

global:
  trace:
    verbose: true
  worker:
    buffer-size: 8192
  telemetry:
    enabled: false

pipelines:
  - name: tap
    dnstap:
      sock-path: /var/run/dnscollector/dnstap.sock
    routing-policy:
      forward: [ file ]

  - name: file
    logfile:
      file-path:  "/var/log/dnscollector/dnstap.log"
      compress: true
      max-size: 30720
      max-files: 7
      mode: json
      flush-interval: 1
      chan-buffer-size: 0
      text-format: "timestamp identity qr operation rcode queryip queryport responseip responseport family protocol length qname qtype latency ttl"

@dmachard
Copy link
Owner

Could you share more details regarding your server ( disk, ram and cpu)

@yadavp27
Copy link
Author

 lscpu
Architecture:        x86_64
CPU op-mode(s):      32-bit, 64-bit
Byte Order:          Little Endian
CPU(s):              8
On-line CPU(s) list: 0-7
Thread(s) per core:  1
Core(s) per socket:  1
Socket(s):           8

ram : 24gb

lshw -class disk -class storage
  *-ide
       description: IDE interface
       product: 82371AB/EB/MB PIIX4 IDE
       vendor: Intel Corporation
       physical id: 7.1
       bus info: pci@0000:00:07.1
       version: 01
       width: 32 bits
       clock: 33MHz
       capabilities: ide isa_compat_mode pci_native_mode bus_master
       configuration: driver=ata_piix latency=64
       resources: irq:0 ioport:1f0(size=8) ioport:3f6 ioport:170(size=8) ioport:376 ioport:2050(size=16)
  *-sas
       description: Serial Attached SCSI controller
       product: PVSCSI SCSI Controller
       vendor: VMware
       physical id: 0
       bus info: pci@0000:03:00.0
       logical name: scsi0
       version: 02
       width: 64 bits
       clock: 33MHz
       capabilities: sas pciexpress msi pm msix bus_master cap_list rom
       configuration: driver=vmw_pvscsi latency=0
       resources: irq:18 ioport:4000(size=8) memory:fea10000-fea17fff memory:fea00000-fea0ffff
     *-disk:0
          description: SCSI Disk
          product: Virtual disk
          vendor: VMware
          physical id: 0.0.0
          bus info: scsi@0:0.0.0
          logical name: /dev/sda
          version: 2.0
          size: 110GiB (118GB)
          capabilities: gpt-1.00 partitioned partitioned:gpt
          configuration: ansiversion=6 guid=bced0c82-4aa7-4c04-a612-fb4b63ebdcea logicalsectorsize=512 sectorsize=512
     *-disk:1
          description: SCSI Disk
          product: Virtual disk
          vendor: VMware
          physical id: 0.1.0
          bus info: scsi@0:0.1.0
          logical name: /dev/sdb
          version: 2.0
          size: 70GiB (75GB)
          capabilities: partitioned partitioned:dos
          configuration: ansiversion=6 logicalsectorsize=512 sectorsize=512 signature=36688089
          ```

@dmachard
Copy link
Owner

dmachard commented Oct 17, 2024

The beta4 improved the logger but it's not enough in your case. Can you enable the global telemetry and share your dashboard ?

image

I make more tests with and reproduced in my lab with ~70k req/s

@yadavp27
Copy link
Author

yadavp27 commented Oct 25, 2024

Hello @dmachard

This issue occurs when the logs are being rotated. The file is being renamed by dnscollector. During the rename and compress process, the dnstap.log file becomes unavailable and something happens.

To test this, I disabled the compress: false option during log rotation and did not observe any concerning issues.

Here is the output of the "ls -li" command:

total 45804092
136 -rw-r--r--. 1 dnscollector dnscollector  1991368893 Oct 19 05:09 dnstap-1729339380674388499.log.gz
137 -rw-r--r--. 1 dnscollector dnscollector  1852668699 Oct 20 15:42 dnstap-1729463780580942637.log.gz
138 -rw-r--r--. 1 dnscollector dnscollector  2192224271 Oct 21 06:57 dnstap-1729518723535040633.log.gz
139 -rw-r--r--. 1 dnscollector dnscollector  2124991919 Oct 22 01:01 dnstap-1729583707451467441.log.gz
133 -rw-r--r--. 1 dnscollector dnscollector  2163008098 Oct 22 19:09 dnstap-1729649384744867764.log.gz
134 -rw-r--r--. 1 dnscollector dnscollector  2219447496 Oct 24 02:52 dnstap-1729763534150940127.log.gz
131 -rw-r--r--. 1 dnscollector dnscollector 32212245632 Oct 24 21:57 dnstap-1729832230614616098.log
132 -rw-r--r--. 1 dnscollector dnscollector  1433690154 Oct 24 22:33 dnstap.log 
  - name: file
    logfile:
      file-path:  "/var/log/dnscollector/dnstap.log"
      compress: true
      max-size: 30720
      max-files: 7
      mode: json
      flush-interval: 1
      chan-buffer-size: 0
      text-format: "timestamp identity qr operation rcode queryip queryport responseip responseport family protocol length qname qtype latency ttl"

can you please suggest what could be done.

Thanks

@dmachard
Copy link
Owner

Thank you for your feedback. The compressed files are quite large in your case, around ~2GB each.

I've identified two potential actions:

  • Could you try reducing max-size ?, 30720 is in megabytes. The default value is 100
  • The compression process is currently blocking; the larger the file, the longer the block. I'll need to update this on my end to address it.

@dmachard
Copy link
Owner

@yadavp27, could you try the beta release 1.2.0-beta1? I pushed a fix to prevent blocking during compression.

@yadavp27
Copy link
Author

@dmachard
can i use this max-size: 30720 or default value 100 and test this out.

@dmachard
Copy link
Owner

dmachard commented Oct 28, 2024

You can keep your value (30720) but can you test with the beta release provided?

@dmachard
Copy link
Owner

Fixed in release 1.2.0. If you encounter any further issues, please feel free to open a new ticket. Thank you for your feedback!

@yadavp27
Copy link
Author

yadavp27 commented Dec 2, 2024

Fixed in release 1.2.0. If you encounter any further issues, please feel free to open a new ticket. Thank you for your feedback!

Thanks it's working now.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
enhancement New feature or request waiting feedback
Projects
None yet
Development

No branches or pull requests

2 participants