Unknown Question received: Q test_host IN ANY -1 192.0.43.10

[tetherit]

I'm not sure what happened, the pipe used to work and now I'm seeing this:

# ruby dns_pipe2.rb 
Q test_host IN ANY -1 192.0.43.10
LOG Unknown Question received: Q test_host IN ANY -1 192.0.43.10                        
FAIL
Q test_host.xanview.com IN ANY -1 192.0.43.10
LOG Unknown Question received: Q test_host.xanview.com IN ANY -1 192.0.43.10                        
FAIL

The script looks like this:

require 'powerdns_pipe'
PowerDNS::Pipe.new.run! do
  answer name: question.name, type: 'A', ttl: 120, content: "127.0.0.1"
end

Not quite sure what is happening, I'm also seeing this in the PDNS logs:

Dec 31 16:41:03 zanview pdns[30585]: [PIPEBackend] coprocess returned incomplete or empty line in data section for query for -1
Dec 31 16:41:03 zanview pdns[30585]: Database module reported condition which prevented lookup (Format error communicating with coprocess in data section) sending out servfail

Any ideas?

[tetherit]

It seems the question must be tab separated - then it answered. I restarted pdns and now it is working again. But it seems to be very intermittent - a day or two from now it starts to fail and respond with something that PDNS doesn't understand.

I tried to do:

while true; do dig @ns1.zanview.co.uk vpn1.${RANDOM}.xanview.com ; sleep 0.001;  done

I can see the DNS pipes and PDNS in top and it's responding to every single query - so it does not seem to be load related.

Is there anyway to have powerdnes_pipe log every question and answer?

[johnl]

Yeah, the powerdns pipe protocol is tab separated.

I've seen something like this before - my MX records had a tab between the priority rather than a space as required. It permanently broke until a restart, because powerdns kept trying the request and kept getting a bad response.

I have been meaning to add a simple logging feature, as I regularly end up adding it into my apps anyway. I might add it now actually, I've got some spare time.

[tetherit]

That would be fantastic :) - Happy New Year btw!!!

[tetherit]

Saw your recent commit, very nice :) - I'm still experiencing with resolution problems.

For example:

➜  ~  n=1000; while [[ $n -gt 0 ]]; do n=$((n-1)); wget vpn1${RANDOM}.zanview.com -O /dev/null -o /dev/null && echo "true" || echo "false"; sleep 0.001;  done | sort | uniq -c
 280 false
 720 true

So out of 720 tries, 280 failed to resolve :/

No idea what is going on, nothing in the logs.

Any news on the logging functionality? :)

[tetherit]

I've restarted powerdns, running the above again, I get this:

n=1000; while [[ $n -gt 0 ]]; do n=$((n-1)); wget vpn1${RANDOM}.zanview.com -O /dev/null -o /dev/null && echo "true" || echo "false"; sleep 0.001;  done | sort | uniq -c
1000 true

So this seems to happen after a few days, something just seems to go wrong :/

Very frustrating, what is going wrong with PDNS :/

[johnl]

Yeah, my latest commits are just to make sure that when I implement logging that I don't break anything else! I'll also be implementing some sanity checks too, to avoid problems of errant \n and \t characters. I may be able to get something working this weekend.

I'm convinced this is a problem with your app though (coupled with not very good error recovery in my library+pdns). So once logging is done, we'll get a clearer view of the problem!

[tetherit]

It probably is my app, but why would it suddenly become intermittent only after a few days, hmm - and then be fine again when I restart. Here is the full source code:

#!/usr/bin/ruby
require 'powerdns_pipe'
require 'ipaddr'
require 'net/http'

def get_ip
  con = Net::HTTP.new('checkip.dyndns.org', 80)
  body = con.get("/").read_body
  ip = body.match(/\d+\.\d+\.\d+\.\d+/)
  ip[0]
end

server_ip = get_ip # only done at start once
PowerDNS::Pipe.new.run! do
  my_ip = server_ip
  ipp_file = open("/etc/openvpn/log/ipp.txt", "r")
  while (line = ipp_file.gets)
    hostname, ip = line.chomp.split(',')
    if [hostname, "#{hostname}.zanview.com"].include? question.name
      my_ip = ip
      break
    end
  end
  answer name: question.name, type: 'A', ttl: 120, content: my_ip
end

Even if for any reason this threw an exception - wouldn't PDNS restart the pipe?

[tetherit]

I've been trying to debug this more, I've enabled the maximum logging possible in powerdns:

At first, all is working fine, a few days later it is intermittent again:

➜  ~  host proxy.sdgsdg${RANDOM}.zanview.com
Host proxy.sdgsdg18933.zanview.com not found: 2(SERVFAIL)
➜  ~  host proxy.sdgsdg${RANDOM}.zanview.com
proxy.sdgsdg8009.zanview.com has address 89.207.135.250

This is what I see in the logs:

Jan 16 19:34:34 zanview pdns[21613]: Query: 'Q#011proxy.sdgsdg18933.zanview.com#011IN#011SOA#011-1#01162.189.34.89#0110.0.0.0'
Jan 16 19:34:34 zanview pdns[21613]: Query: 'Q#011proxy.sdgsdg18933.zanview.com#011IN#011ANY#011-1#01162.189.34.89#0110.0.0.0'
Jan 16 19:34:41 zanview pdns[21613]: Query: 'Q#011proxy.sdgsdg8009.zanview.com#011IN#011SOA#011-1#01162.189.34.89#0110.0.0.0'
Jan 16 19:34:41 zanview pdns[21613]: Query: 'Q#011proxy.sdgsdg8009.zanview.com#011IN#011ANY#011-1#01162.189.34.89#0110.0.0.0'

Why did the first fail and the second succeed? :/ - What is going on? :(

I tried adding:

$stderr.reopen("/tmp/dnspipe.log", "w")

To my dns_pipe.rb but /tmp/dnspipe.log is blank after the failed resolution :/

Any ideas at all?

[tetherit]

No ideas? :( - I tried posting it on the pdns mailing list - I think maybe it is an issue with the pdns pipe backend?