huge log file in tmp/dns/daemon/vagrant-dns.output

[alexanderadam]

I just realised that I had a log file with a size of 229.8 GB at tmp/dns/daemon/vagrant-dns.output

Its content looked like this:

Passthrough response: #<Resolv::DNS::Message:0x00007f216e950808 @id=50173, @qr=1, @opcode=0, @aa=0, @tc=0, @rd=1, @ra=1, @rcode=0, @question=[[#<Resolv::DNS::Name: location.services.mozilla.com.>, Resolv::DNS::Resource::IN::A]], @answer=[[#<Resolv::DNS::Name: location.services.mozilla.com.>, 550, #<Resolv::DNS::Resource::IN::CNAME:0x00007f216e956190 @name=#<Resolv::DNS::Name: locprod2-elb-us-west-2.prod.mozaws.net.>, @ttl=550>], [#<Resolv::DNS::Name: locprod2-elb-us-west-2.prod.mozaws.net.>, 10, #<Resolv::DNS::Resource::IN::A:0x00007f216e954f98 @address=#<Resolv::IPv4 44.240.238.241>, @ttl=10>], [#<Resolv::DNS::Name: locprod2-elb-us-west-2.prod.mozaws.net.>, 10, #<Resolv::DNS::Resource::IN::A:0x00007f216e954020 @address=#<Resolv::IPv4 34.209.58.21>, @ttl=10>], [#<Resolv::DNS::Name: locprod2-elb-us-west-2.prod.mozaws.net.>, 10, #<Resolv::DNS::Resource::IN::A:0x00007f216e95b500 @address=#<Resolv::IPv4 44.237.196.225>, @ttl=10>]], @authority=[], @additional=[]>
Passthrough response: #<Resolv::DNS::Message:0x00007f216e963570 @id=34436, @qr=1, @opcode=0, @aa=0, @tc=0, @rd=1, @ra=1, @rcode=0, @question=[[#<Resolv::DNS::Name: location.services.mozilla.com.>, Resolv::DNS::Resource::IN::A]], @answer=[[#<Resolv::DNS::Name: location.services.mozilla.com.>, 550, #<Resolv::DNS::Resource::IN::CNAME:0x00007f216e960e60 @name=#<Resolv::DNS::Name: locprod2-elb-us-west-2.prod.mozaws.net.>, @ttl=550>], [#<Resolv::DNS::Name: locprod2-elb-us-west-2.prod.mozaws.net.>, 10, #<Resolv::DNS::Resource::IN::A:0x00007f216e966db0 @address=#<Resolv::IPv4 44.240.238.241>, @ttl=10>], [#<Resolv::DNS::Name: locprod2-elb-us-west-2.prod.mozaws.net.>, 10, #<Resolv::DNS::Resource::IN::A:0x00007f216e964f10 @address=#<Resolv::IPv4 34.209.58.21>, @ttl=10>], [#<Resolv::DNS::Name: locprod2-elb-us-west-2.prod.mozaws.net.>, 10, #<Resolv::DNS::Resource::IN::A:0x00007f216e96ad48 @address=#<Resolv::IPv4 44.237.196.225>, @ttl=10>]], @authority=[], @additional=[]>
Passthrough response: #<Resolv::DNS::Message:0x00007f216e919bc8 @id=4129, @qr=1, @opcode=0, @aa=0, @tc=0, @rd=1, @ra=1, @rcode=0, @question=[[#<Resolv::DNS::Name: location.services.mozilla.com.>, Resolv::DNS::Resource::IN::AAAA]], @answer=[[#<Resolv::DNS::Name: location.services.mozilla.com.>, 484, #<Resolv::DNS::Resource::IN::CNAME:0x00007f216e91fb18 @name=#<Resolv::DNS::Name: locprod2-elb-us-west-2.prod.mozaws.net.>, @ttl=484>]], @authority=[[#<Resolv::DNS::Name: prod.mozaws.net.>, 184, #<Resolv::DNS::Resource::IN::SOA:0x00007f216e91e0d8 @mname=#<Resolv::DNS::Name: ns-1260.awsdns-29.org.>, @rname=#<Resolv::DNS::Name: awsdns-hostmaster.amazon.com.>, @serial=1, @refresh=7200, @retry=900, @expire=1209600, @minimum=86400, @ttl=184>]], @additional=[]>
Passthrough response: #<Resolv::DNS::Message:0x00007f216e921b98 @id=40200, @qr=1, @opcode=0, @aa=0, @tc=0, @rd=1, @ra=1, @rcode=0, @question=[[#<Resolv::DNS::Name: location.services.mozilla.com.>, Resolv::DNS::Resource::IN::AAAA]], @answer=[[#<Resolv::DNS::Name: location.services.mozilla.com.>, 484, #<Resolv::DNS::Resource::IN::CNAME:0x00007f216e927660 @name=#<Resolv::DNS::Name: locprod2-elb-us-west-2.prod.mozaws.net.>, @ttl=484>]], @authority=[[#<Resolv::DNS::Name: prod.mozaws.net.>, 184, #<Resolv::DNS::Resource::IN::SOA:0x00007f216e924848 @mname=#<Resolv::DNS::Name: ns-1260.awsdns-29.org.>, @rname=#<Resolv::DNS::Name: awsdns-hostmaster.amazon.com.>, @serial=1, @refresh=7200, @retry=900, @expire=1209600, @minimum=86400, @ttl=184>]], @additional=[]>

It grows super-fast too.

Any idea what could be wrong? 🤔

It seems to come from here.

[fnordfish]

What does your config look like? Seems like all(?) queries end up at vagrant-dns?

[alexanderadam]

Wow, you're fast!

  config.dns.tld = 'test'
  config.dns.patterns = [/^(\w+\.)*local\.test$/]

[fnordfish]

Weird. What does your /etc/resolvd/* point to. And does your internet still work, when you kill all vagrant-dns?

[alexanderadam]

I don't have a /etc/resolvd/ — only a /etc/resolv.conf. I'm using Fedora if that makes any difference and I uninstalled the plugin for now.

This means that the log is generally expected grow indefinitely as long as the process is running, right?

[fnordfish]

Well, AFAIR we don’t clean up the log file. Maybe we should.
however, it seems that the systemd integration somehow ended up to catch more queries than it was configured for.

[fnordfish]

(Closed by accident on my phone)

[alexanderadam]

Why does it log non-matching routes anyway? 🤔

Maybe it's just the check missing whether it matches the rule?

[fnordfish]

First of all, queries to atlas’s other than specified shouldn’t end up on the server in the first place. To me, it looks like the systemd configuration vagrant-dns generates might be faulty.
Logging passthrough requests is/was by design. We might want to revisit this.

[fnordfish]

There are at least two issues:

1. systemd sends request for domains other than specified to vagrant-dns
2. Somehow vagrant-dns (can) end up in a loop like this:

Passthrough response: #<Resolv::DNS::Message:0x0000ffff707aae70 @id=55271, @qr=1, @opcode=0, @aa=0, @tc=0, @rd=1, @ra=1, @rcode=0, @question=[[#<Resolv::DNS::Name: 80.144.99.193.in-addr.arpa.>, Resolv::DNS::Resource::IN::PTR]], @answer=[[#<Resolv::DNS::Name: 80.144.99.193.in-addr.arpa.>, 2, #<Resolv::DNS::Resource::IN::PTR:0x0000ffff71113480 @name=#<Resolv::DNS::Name: redirector.heise.de.>, @ttl=2>]], @authority=[], @additional=[]>
Passthrough response: #<Resolv::DNS::Message:0x0000ffff707a6cd0 @id=11241, @qr=1, @opcode=0, @aa=0, @tc=0, @rd=1, @ra=1, @rcode=0, @question=[[#<Resolv::DNS::Name: 80.144.99.193.in-addr.arpa.>, Resolv::DNS::Resource::IN::PTR]], @answer=[[#<Resolv::DNS::Name: 80.144.99.193.in-addr.arpa.>, 2, #<Resolv::DNS::Resource::IN::PTR:0x0000ffff7134cc10 @name=#<Resolv::DNS::Name: redirector.heise.de.>, @ttl=2>]], @authority=[], @additional=[]>
Passthrough response: #<Resolv::DNS::Message:0x0000ffff707fbc30 @id=9480, @qr=1, @opcode=0, @aa=0, @tc=0, @rd=1, @ra=1, @rcode=0, @question=[[#<Resolv::DNS::Name: 80.144.99.193.in-addr.arpa.>, Resolv::DNS::Resource::IN::PTR]], @answer=[[#<Resolv::DNS::Name: 80.144.99.193.in-addr.arpa.>, 2, #<Resolv::DNS::Resource::IN::PTR:0x0000ffff70dfc6e8 @name=#<Resolv::DNS::Name: redirector.heise.de.>, @ttl=2>]], @authority=[], @additional=[]>

eventually crashing:

{
  "time": "2024-02-23T18:01:46+01:00",
  "severity": "error",
  "oid": 52522520,
  "pid": 5553,
  "subject": "Resolv::DNS::Message",
  "message": "Too many open files - socket(2)",
  "error": {
      "kind": "Errno::EMFILE",
      "message": "Too many open files - socket(2)",
      "stack": "/home/robert/.vagrant.d/gems/3.2.2/gems/async-io-1.41.0/lib/async/io/socket.rb:72:in `initialize'\n/home/robert/.vagrant.d/gems/3.2.2/gems/async-io-1.41.0/lib/async/io/socket.rb:72:in `new'\n/home/robert/.vagrant.d/gems/3.2.2/gems/async-io-1.41.0/lib/async/io/socket.rb:72:in `build'\n/home/robert/.vagrant.d/gems/3.2.2/gems/async-io-1.41.0/lib/async/io/socket.rb:108:in `connect'\n/home/robert/.vagrant.d/gems/3.2.2/gems/async-io-1.41.0/lib/async/io/host_endpoint.rb:44:in `block in connect'\n/usr/share/ruby/socket.rb:231:in `each'\n/usr/share/ruby/socket.rb:231:in `foreach'\n/home/robert/.vagrant.d/gems/3.2.2/gems/async-io-1.41.0/lib/async/io/host_endpoint.rb:42:in `connect'\n/home/robert/.vagrant.d/gems/3.2.2/gems/async-dns-1.3.0/lib/async/dns/resolver.rb:188:in `try_server'\n/home/robert/.vagrant.d/gems/3.2.2/gems/async-dns-1.3.0/lib/async/dns/resolver.rb:147:in `block (2 levels) in dispatch_request'\n/home/robert/.vagrant.d/gems/3.2.2/gems/async-1.31.0/lib/async/reactor.rb:340:in `with_timeout'\n/usr/share/ruby/forwardable.rb:240:in `with_timeout'\n/home/robert/.vagrant.d/gems/3.2.2/gems/async-dns-1.3.0/lib/async/dns/resolver.rb:145:in `block in dispatch_request'\n/home/robert/.vagrant.d/gems/3.2.2/gems/async-io-1.41.0/lib/async/io/endpoint/each.rb:35:in `block in each'\n/home/robert/.vagrant.d/gems/3.2.2/gems/async-io-1.41.0/lib/async/io/endpoint/each.rb:34:in `each'\n/home/robert/.vagrant.d/gems/3.2.2/gems/async-io-1.41.0/lib/async/io/endpoint/each.rb:34:in `each'\n/home/robert/.vagrant.d/gems/3.2.2/gems/async-dns-1.3.0/lib/async/dns/resolver.rb:251:in `each'\n/home/robert/.vagrant.d/gems/3.2.2/gems/async-dns-1.3.0/lib/async/dns/resolver.rb:139:in `dispatch_request'\n/home/robert/.vagrant.d/gems/3.2.2/gems/async-dns-1.3.0/lib/async/dns/resolver.rb:89:in `query'\n/home/robert/.vagrant.d/gems/3.2.2/gems/async-dns-1.3.0/lib/async/dns/transaction.rb:109:in `passthrough'\n/home/robert/.vagrant.d/gems/3.2.2/gems/async-dns-1.3.0/lib/async/dns/transaction.rb:83:in `passthrough!'\n/home/robert/.vagrant.d/gems/3.2.2/gems/vagrant-dns-2.4.1/lib/vagrant-dns/server.rb:38:in `block in run'\n/home/robert/.vagrant.d/gems/3.2.2/gems/rubydns-2.0.2/lib/rubydns/rule_based_server.rb:174:in `process'\n/home/robert/.vagrant.d/gems/3.2.2/gems/async-dns-1.3.0/lib/async/dns/transaction.rb:190:in `process'\n/home/robert/.vagrant.d/gems/3.2.2/gems/async-dns-1.3.0/lib/async/dns/server.rb:83:in `block in process_query'\n/home/robert/.vagrant.d/gems/3.2.2/gems/async-dns-1.3.0/lib/async/dns/server.rb:75:in `each'\n/home/robert/.vagrant.d/gems/3.2.2/gems/async-dns-1.3.0/lib/async/dns/server.rb:75:in `process_query'\n/home/robert/.vagrant.d/gems/3.2.2/gems/async-dns-1.3.0/lib/async/dns/handler.rb:60:in `process_query'\n/home/robert/.vagrant.d/gems/3.2.2/gems/async-dns-1.3.0/lib/async/dns/handler.rb:82:in `respond'\n/home/robert/.vagrant.d/gems/3.2.2/gems/async-dns-1.3.0/lib/async/dns/handler.rb:76:in `block in run'\n/home/robert/.vagrant.d/gems/3.2.2/gems/async-1.31.0/lib/async/task.rb:261:in `block in make_fiber'\n"
  }
}

[fnordfish]

@alexanderadam As a quick work-around, set VagrantDNS::Config.passthrough = false

[fnordfish]

@mattiasb Do you have any idea why systemd/resolved directs queries not matching our configured domain to vagrant-dns?

[mattiasb]

@mattiasb Do you have any idea why
systemd/resolved directs queries not
matching our configured domain to
vagrant-dns?

I don't from the top of my head.

I don't use vagrant-dns currently, however I still would like to get to the bottom of this. I might have some time to look at this on Sunday if no one beats me to it.

Please poke me if I seem to forget!

[fnordfish]

Thanks a lot!

[fnordfish]

Regarding logging: The server doesn't log by itself. It uses the logging feature of daemons, which redirects stdout and stderr to a logfile. It also can redirect to syslog, which seems like a nice candidate for linux/systemd systems.
However, this means that we cannot rotate the logfile from within vagrant-dns.

The other, more obvious solution would be to do logging manually e.g. via Logger, which comes with some form of log rotation and cleanup build in.

However, using Daemons logging has the benefit of capturing exception traces.

[fnordfish]

Regarding Passthrough:

It was build in as a default, so that, when you happen to register a route-able (aka public) TLD like .DEV, you'd still be able to internet.

Maybe it's time to disable passthrough by default and maybe print a warning if a public TLD is registered.