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

Some programs can't resolve #26

Closed
xergio opened this issue Apr 2, 2014 · 36 comments
Closed

Some programs can't resolve #26

xergio opened this issue Apr 2, 2014 · 36 comments

Comments

@xergio
Copy link

xergio commented Apr 2, 2014

Hi. I'm having an issue with some programs like "svn", "ntpdate", or "telnet". This programs can't resolve any host, while "ping", "host", "dig" or many other can.

My setup is:

  • Debian 7
  • Ruby 1.9.1
  • /etc/resolv.conf nameserver 127.0.0.1
  • passthrough! to our DNS

The script i've created is very simple, I can attach it if needed. Is something like follows:

require 'rubygems'

require 'rexec'
require 'rexec/daemon'

require 'rubydns'
require 'rubydns/system'


if RExec.current_user != "root"
    $stderr.puts "Arracanlo como root!"
    exit 1
end


class DNSMovilidad < RExec::Daemon::Base

    INTERFACES = [
        [:udp, "0.0.0.0", 53],
        [:tcp, "0.0.0.0", 53]
    ]

    JME_DNS = [
        [:tcp, "172.16.22.3", 53]
    ]

    #UPSTREAM_JME = RubyDNS::Resolver.new(RubyDNS::System::nameservers)
    UPSTREAM_JME = RubyDNS::Resolver.new(JME_DNS)

    Name = Resolv::DNS::Name
    IN = Resolv::DNS::Resource::IN

    def self.run
        # Don't buffer output (for debug purposes)
        $stderr.sync = true

        etc_hosts = RubyDNS::System::Hosts.local()
        eh_mtime = File.mtime(RubyDNS::System::HOSTS)

        RubyDNS::run_server(:listen => INTERFACES) do
            on(:start) do
                #@logger.level = Logger::INFO
                #RExec.change_user(RUN_AS)

                @logger = Logger.new('/LOGS/dns.log', 'weekly')
                if ARGV.include?("--debug")
                    @logger.level = Logger::DEBUG
                else
                    @logger.level = Logger::INFO
                end
            end

            match(//) do |transaction| # catch all!!

                if eh_mtime != File.mtime(RubyDNS::System::HOSTS)
                    etc_hosts = RubyDNS::System::Hosts.local()
                    eh_mtime = File.mtime(RubyDNS::System::HOSTS)
                    @logger.info "/etc/hosts cambiado #{eh_mtime}"
                end

                @logger.info "TEST #{transaction}"

                in_local = etc_hosts.lookup(transaction.name())


                if in_local
                    @logger.debug "Dominio en local #{in_local}"
                    transaction.respond!(in_local)


                elsif /^cms\-([a-z]+)\..*/.match(transaction.name())
                    @logger.debug "Dominio clasico lab-id02"
                    transaction.respond!("10.10.22.111") # lab-id02

                elsif /^(.*)\-([a-z]+)(\-([0-9a-z\.]+))?\.mov$/.match(transaction.name())
                    @logger.debug "Dominio nuevo enjuto1"
                    transaction.respond!("10.10.20.48") # enjuto1

# removed some patterns

                else
                    logger.debug "npi, UPSTREAM_JME"
                    transaction.passthrough!(UPSTREAM_JME)
                end
            end

            otherwise do |transaction|
                logger.debug "mmmm? UPSTREAM_JME"
                transaction.passthrough!(UPSTREAM_JME)
            end
        end

    end
end

DNSMovilidad.daemonize

As I said, all works fine except for some programs, I cant understand why "svn" cant resolve and "ping" can.

Thank you!

@ioquatix
Copy link
Member

ioquatix commented Apr 2, 2014

Thanks - can you make the simplest possible test server that still fails?

On 2/04/2014, at 8:50 pm, Sergio Álvarez notifications@github.com wrote:

Hi. I'm having an issue with some programs like "svn", "ntpdate", or "telnet". This programs can't resolve any host, while "ping", "host", "dig" or many other can.

My setup is:

Debian 7
Ruby 1.9.1
/etc/resolv.conf nameserver 127.0.0.1
passthrough! to our DNS
The script i've created is very simple, I can attach it if needed. Is something like follows:

require 'rubygems'

require 'rexec'
require 'rexec/daemon'

require 'rubydns'
require 'rubydns/system'

if RExec.current_user != "root"
$stderr.puts "Arracanlo como root!"
exit 1
end

class DNSMovilidad < RExec::Daemon::Base

INTERFACES = [
    [:udp, "0.0.0.0", 53],
    [:tcp, "0.0.0.0", 53]
]

JME_DNS = [
    [:tcp, "172.16.22.3", 53]
]

#UPSTREAM_JME = RubyDNS::Resolver.new(RubyDNS::System::nameservers)
UPSTREAM_JME = RubyDNS::Resolver.new(JME_DNS)

Name = Resolv::DNS::Name
IN = Resolv::DNS::Resource::IN

def self.run
    # Don't buffer output (for debug purposes)
    $stderr.sync = true

    etc_hosts = RubyDNS::System::Hosts.local()
    eh_mtime = File.mtime(RubyDNS::System::HOSTS)

    RubyDNS::run_server(:listen => INTERFACES) do
        on(:start) do
            #@logger.level = Logger::INFO
            #RExec.change_user(RUN_AS)

            @logger = Logger.new('/LOGS/dns.log', 'weekly')
            if ARGV.include?("--debug")
                @logger.level = Logger::DEBUG
            else
                @logger.level = Logger::INFO
            end
        end

        match(//) do |transaction| # catch all!!

            if eh_mtime != File.mtime(RubyDNS::System::HOSTS)
                etc_hosts = RubyDNS::System::Hosts.local()
                eh_mtime = File.mtime(RubyDNS::System::HOSTS)
                @logger.info "/etc/hosts cambiado #{eh_mtime}"
            end

            @logger.info "TEST #{transaction}"

            in_local = etc_hosts.lookup(transaction.name())


            if in_local
                @logger.debug "Dominio en local #{in_local}"
                transaction.respond!(in_local)


            elsif /^cms\-([a-z]+)\..*/.match(transaction.name())
                @logger.debug "Dominio clasico lab-id02"
                transaction.respond!("10.10.22.111") # lab-id02

            elsif /^(.*)\-([a-z]+)(\-([0-9a-z\.]+))?\.mov$/.match(transaction.name())
                @logger.debug "Dominio nuevo enjuto1"
                transaction.respond!("10.10.20.48") # enjuto1

removed some patterns

            else
                logger.debug "npi, UPSTREAM_JME"
                transaction.passthrough!(UPSTREAM_JME)
            end
        end

        otherwise do |transaction|
            logger.debug "mmmm? UPSTREAM_JME"
            transaction.passthrough!(UPSTREAM_JME)
        end
    end

end

end

DNSMovilidad.daemonize
As I said, all works fine except for some programs, I cant understand why "svn" cant resolve and "ping" can.

Thank you!


Reply to this email directly or view it on GitHub.

@xergio
Copy link
Author

xergio commented Apr 2, 2014

I can try, give me a moment.

@xergio
Copy link
Author

xergio commented Apr 2, 2014

I simplified the script:

require 'rubygems'

require 'rubydns'
require 'rubydns/system'


UPSTREAM_JME = RubyDNS::Resolver.new([[:tcp, "172.16.22.3", 53]])

etc_hosts = RubyDNS::System::Hosts.local()

RubyDNS::run_server() do

    match(//) do |transaction|

        @logger.info "TEST #{transaction}"

        in_local = etc_hosts.lookup(transaction.name())
        if in_local
            @logger.debug "Dominio en local #{in_local}"
            transaction.respond!(in_local)


        elsif /^(.*)\-([a-z]+)(\-([0-9a-z\.]+))?\.mov$/.match(transaction.name())
            @logger.debug "Dominio nuevo enjuto1"
            transaction.respond!("10.10.20.48") # enjuto1


        else
            logger.debug "npi, UPSTREAM_JME"
            transaction.passthrough!(UPSTREAM_JME)
        end
    end
end

I test it with ntpdate, host hora.roa.es, this is the log:

~ # ruby1.9.1 /home/salvarez/misc/trunk/dns-dev/dns-simplest.rb 
I, [2014-04-02T10:35:07.163015 #3403]  INFO -- : Starting RubyDNS server (v0.7.0)...
I, [2014-04-02T10:35:07.163134 #3403]  INFO -- : Listening on udp:0.0.0.0:53
I, [2014-04-02T10:35:07.163344 #3403]  INFO -- : Listening on tcp:0.0.0.0:53

TEST 1

~ # dig hora.roa.es

; <<>> DiG 9.8.4-rpz2+rl005.12-P1 <<>> hora.roa.es
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 33868
;; flags: qr rd; QUERY: 1, ANSWER: 1, AUTHORITY: 6, ADDITIONAL: 8
;; WARNING: recursion requested but not available

;; QUESTION SECTION:
;hora.roa.es.           IN  A

;; ANSWER SECTION:
hora.roa.es.        66039   IN  A   150.214.94.5

;; AUTHORITY SECTION:
roa.es.         48038   IN  NS  chico.rediris.es.
roa.es.         48038   IN  NS  sun.rediris.es.
roa.es.         48038   IN  NS  dns2.cica.es.
roa.es.         48038   IN  NS  roasf.roa.es.
roa.es.         48038   IN  NS  dns1.cica.es.
roa.es.         48038   IN  NS  roasf2.roa.es.

;; ADDITIONAL SECTION:
sun.rediris.es.     4839    IN  A   130.206.1.2
dns1.cica.es.       91239   IN  A   150.214.5.83
dns1.cica.es.       91239   IN  AAAA    2a00:9ac0:c1ca:6::83
dns2.cica.es.       91239   IN  A   150.214.4.35
dns2.cica.es.       91239   IN  AAAA    2a00:9ac0:c1ca:51::35
chico.rediris.es.   4839    IN  A   130.206.1.3
roasf.roa.es.       48038   IN  A   150.214.94.3
roasf2.roa.es.      48038   IN  A   150.214.94.12

;; Query time: 5 msec
;; SERVER: 127.0.0.1#53(127.0.0.1)
;; WHEN: Wed Apr  2 10:39:23 2014
;; MSG SIZE  rcvd: 327

Log:

D, [2014-04-02T10:39:23.328437 #3425] DEBUG -- : Receiving incoming query (29 bytes)...
D, [2014-04-02T10:39:23.328688 #3425] DEBUG -- : Processing question hora.roa.es Resolv::DNS::Resource::IN::A...
D, [2014-04-02T10:39:23.328738 #3425] DEBUG -- : Searching for hora.roa.es Resolv::DNS::Resource::IN::A
D, [2014-04-02T10:39:23.328781 #3425] DEBUG -- : Checking rule [//]...
D, [2014-04-02T10:39:23.328843 #3425] DEBUG -- : Regexp pattern matched with #<MatchData "">.
I, [2014-04-02T10:39:23.328886 #3425]  INFO -- : TEST hora.roa.es Resolv::DNS::Resource::IN::A
D, [2014-04-02T10:39:23.328950 #3425] DEBUG -- : npi, UPSTREAM_JME
D, [2014-04-02T10:39:23.333669 #3425] DEBUG -- : Writing response to client (327 bytes) via UDP...

Perfect.

TEST 2

~ # /usr/sbin/ntpdate hora.roa.es
Error resolving hora.roa.es: No address associated with hostname (-5)
 2 Apr 10:42:14 ntpdate[3448]: Can't find host hora.roa.es: No address associated with hostname (-5)
 2 Apr 10:42:14 ntpdate[3448]: no servers can be used, exiting

Log:

D, [2014-04-02T10:42:14.645223 #3425] DEBUG -- : Receiving incoming query (29 bytes)...
D, [2014-04-02T10:42:14.645426 #3425] DEBUG -- : Processing question hora.roa.es Resolv::DNS::Resource::IN::A...
D, [2014-04-02T10:42:14.645591 #3425] DEBUG -- : Searching for hora.roa.es Resolv::DNS::Resource::IN::A
D, [2014-04-02T10:42:14.645635 #3425] DEBUG -- : Checking rule [//]...
D, [2014-04-02T10:42:14.645820 #3425] DEBUG -- : Regexp pattern matched with #<MatchData "">.
I, [2014-04-02T10:42:14.647963 #3425]  INFO -- : TEST hora.roa.es Resolv::DNS::Resource::IN::A
D, [2014-04-02T10:42:14.648069 #3425] DEBUG -- : npi, UPSTREAM_JME
D, [2014-04-02T10:42:14.648430 #3425] DEBUG -- : Receiving incoming query (29 bytes)...
D, [2014-04-02T10:42:14.648576 #3425] DEBUG -- : Processing question hora.roa.es Resolv::DNS::Resource::IN::AAAA...
D, [2014-04-02T10:42:14.648729 #3425] DEBUG -- : Searching for hora.roa.es Resolv::DNS::Resource::IN::AAAA
D, [2014-04-02T10:42:14.648785 #3425] DEBUG -- : Checking rule [//]...
D, [2014-04-02T10:42:14.648925 #3425] DEBUG -- : Regexp pattern matched with #<MatchData "">.
I, [2014-04-02T10:42:14.648973 #3425]  INFO -- : TEST hora.roa.es Resolv::DNS::Resource::IN::AAAA
D, [2014-04-02T10:42:14.649083 #3425] DEBUG -- : npi, UPSTREAM_JME
D, [2014-04-02T10:42:14.680692 #3425] DEBUG -- : Writing response to client (327 bytes) via UDP...
D, [2014-04-02T10:42:14.682228 #3425] DEBUG -- : Writing response to client (82 bytes) via UDP...
D, [2014-04-02T10:42:14.682777 #3425] DEBUG -- : Receiving incoming query (29 bytes)...
D, [2014-04-02T10:42:14.682909 #3425] DEBUG -- : Processing question hora.roa.es Resolv::DNS::Resource::IN::A...
D, [2014-04-02T10:42:14.683000 #3425] DEBUG -- : Searching for hora.roa.es Resolv::DNS::Resource::IN::A
D, [2014-04-02T10:42:14.683063 #3425] DEBUG -- : Checking rule [//]...
D, [2014-04-02T10:42:14.683252 #3425] DEBUG -- : Regexp pattern matched with #<MatchData "">.
I, [2014-04-02T10:42:14.683314 #3425]  INFO -- : TEST hora.roa.es Resolv::DNS::Resource::IN::A
D, [2014-04-02T10:42:14.683396 #3425] DEBUG -- : npi, UPSTREAM_JME
D, [2014-04-02T10:42:14.683655 #3425] DEBUG -- : Receiving incoming query (29 bytes)...
D, [2014-04-02T10:42:14.683783 #3425] DEBUG -- : Processing question hora.roa.es Resolv::DNS::Resource::IN::AAAA...
D, [2014-04-02T10:42:14.683865 #3425] DEBUG -- : Searching for hora.roa.es Resolv::DNS::Resource::IN::AAAA
D, [2014-04-02T10:42:14.683905 #3425] DEBUG -- : Checking rule [//]...
D, [2014-04-02T10:42:14.683960 #3425] DEBUG -- : Regexp pattern matched with #<MatchData "">.
I, [2014-04-02T10:42:14.684036 #3425]  INFO -- : TEST hora.roa.es Resolv::DNS::Resource::IN::AAAA
D, [2014-04-02T10:42:14.684104 #3425] DEBUG -- : npi, UPSTREAM_JME
D, [2014-04-02T10:42:14.717919 #3425] DEBUG -- : Writing response to client (327 bytes) via UDP...
D, [2014-04-02T10:42:14.718286 #3425] DEBUG -- : Writing response to client (82 bytes) via UDP...

This command in other machine with a "normal" DNS works fine, the only difference is the DNS server used.

In addition, ping and host can resolve hora.roa.es. So, I don't know where is the problem. Commands like svn or telnet have the same issue (I don't test other commands).

Thank you!

@ioquatix
Copy link
Member

ioquatix commented Apr 2, 2014

Can I access the DNS server that the script is using for upstream requests from New Zealand? e.g. is it public or private?

Can you try using Google's DNS, 8.8.8.8? If that still has issues, it is a bug in RubyDNS and I'll sort it out.

@ioquatix
Copy link
Member

ioquatix commented Apr 2, 2014

Try this server:

require 'rubygems'

require 'rubydns'
require 'rubydns/system'


GOOGLE = RubyDNS::Resolver.new([[:tcp, "8.8.8.8", 53]])

RubyDNS::run_server() do
    otherwise do |transaction|
        @logger.info "Upstream: #{transaction}"
        transaction.passthrough!(GOOGLE)
    end
end

@ioquatix
Copy link
Member

ioquatix commented Apr 2, 2014

I am just wondering if it is something to do with only providing :tcp for the upstream connection - I haven't tested this case I don't think.

@ioquatix
Copy link
Member

ioquatix commented Apr 2, 2014

Okay great. I won't have time to look at this until the weekend, but thanks for reporting the issue, I will sort it out.

@xergio
Copy link
Author

xergio commented Apr 2, 2014

Wait wait! I pasted the wrong log: This is the correct, no changes:

~ # /usr/sbin/ntpdate hora.roa.es
Error resolving hora.roa.es: No address associated with hostname (-5)
 2 Apr 11:13:23 ntpdate[3562]: Can't find host hora.roa.es: No address associated with hostname (-5)
 2 Apr 11:13:23 ntpdate[3562]: no servers can be used, exiting

Log:

D, [2014-04-02T11:13:22.974838 #3556] DEBUG -- : Receiving incoming query (29 bytes)...
D, [2014-04-02T11:13:22.975069 #3556] DEBUG -- : Processing question hora.roa.es Resolv::DNS::Resource::IN::A...
D, [2014-04-02T11:13:22.975118 #3556] DEBUG -- : Searching for hora.roa.es Resolv::DNS::Resource::IN::A
I, [2014-04-02T11:13:22.975158 #3556]  INFO -- : Upstream: hora.roa.es Resolv::DNS::Resource::IN::A
D, [2014-04-02T11:13:22.975452 #3556] DEBUG -- : Receiving incoming query (29 bytes)...
D, [2014-04-02T11:13:22.975567 #3556] DEBUG -- : Processing question hora.roa.es Resolv::DNS::Resource::IN::AAAA...
D, [2014-04-02T11:13:22.975610 #3556] DEBUG -- : Searching for hora.roa.es Resolv::DNS::Resource::IN::AAAA
I, [2014-04-02T11:13:22.975646 #3556]  INFO -- : Upstream: hora.roa.es Resolv::DNS::Resource::IN::AAAA
D, [2014-04-02T11:13:23.029153 #3556] DEBUG -- : Writing response to client (82 bytes) via UDP...
D, [2014-04-02T11:13:23.029750 #3556] DEBUG -- : Receiving incoming query (29 bytes)...
D, [2014-04-02T11:13:23.029938 #3556] DEBUG -- : Processing question hora.roa.es Resolv::DNS::Resource::IN::A...
D, [2014-04-02T11:13:23.030010 #3556] DEBUG -- : Searching for hora.roa.es Resolv::DNS::Resource::IN::A
I, [2014-04-02T11:13:23.030054 #3556]  INFO -- : Upstream: hora.roa.es Resolv::DNS::Resource::IN::A
D, [2014-04-02T11:13:23.030298 #3556] DEBUG -- : Receiving incoming query (29 bytes)...
D, [2014-04-02T11:13:23.030487 #3556] DEBUG -- : Processing question hora.roa.es Resolv::DNS::Resource::IN::AAAA...
D, [2014-04-02T11:13:23.030565 #3556] DEBUG -- : Searching for hora.roa.es Resolv::DNS::Resource::IN::AAAA
I, [2014-04-02T11:13:23.030614 #3556]  INFO -- : Upstream: hora.roa.es Resolv::DNS::Resource::IN::AAAA
D, [2014-04-02T11:13:23.035773 #3556] DEBUG -- : Writing response to client (45 bytes) via UDP...
D, [2014-04-02T11:13:23.084401 #3556] DEBUG -- : Writing response to client (45 bytes) via UDP...
D, [2014-04-02T11:13:23.091970 #3556] DEBUG -- : Writing response to client (82 bytes) via UDP...
D, [2014-04-02T11:13:23.092491 #3556] DEBUG -- : Receiving incoming query (29 bytes)...
D, [2014-04-02T11:13:23.092642 #3556] DEBUG -- : Processing question hora.roa.es Resolv::DNS::Resource::IN::A...
D, [2014-04-02T11:13:23.092725 #3556] DEBUG -- : Searching for hora.roa.es Resolv::DNS::Resource::IN::A
I, [2014-04-02T11:13:23.092796 #3556]  INFO -- : Upstream: hora.roa.es Resolv::DNS::Resource::IN::A
D, [2014-04-02T11:13:23.093103 #3556] DEBUG -- : Receiving incoming query (29 bytes)...
D, [2014-04-02T11:13:23.093210 #3556] DEBUG -- : Processing question hora.roa.es Resolv::DNS::Resource::IN::AAAA...
D, [2014-04-02T11:13:23.093262 #3556] DEBUG -- : Searching for hora.roa.es Resolv::DNS::Resource::IN::AAAA
I, [2014-04-02T11:13:23.093326 #3556]  INFO -- : Upstream: hora.roa.es Resolv::DNS::Resource::IN::AAAA
D, [2014-04-02T11:13:23.147240 #3556] DEBUG -- : Writing response to client (82 bytes) via UDP...
D, [2014-04-02T11:13:23.147806 #3556] DEBUG -- : Receiving incoming query (29 bytes)...
D, [2014-04-02T11:13:23.147946 #3556] DEBUG -- : Processing question hora.roa.es Resolv::DNS::Resource::IN::A...
D, [2014-04-02T11:13:23.148024 #3556] DEBUG -- : Searching for hora.roa.es Resolv::DNS::Resource::IN::A
I, [2014-04-02T11:13:23.148067 #3556]  INFO -- : Upstream: hora.roa.es Resolv::DNS::Resource::IN::A
D, [2014-04-02T11:13:23.148273 #3556] DEBUG -- : Receiving incoming query (29 bytes)...
D, [2014-04-02T11:13:23.148399 #3556] DEBUG -- : Processing question hora.roa.es Resolv::DNS::Resource::IN::AAAA...
D, [2014-04-02T11:13:23.148467 #3556] DEBUG -- : Searching for hora.roa.es Resolv::DNS::Resource::IN::AAAA
I, [2014-04-02T11:13:23.148509 #3556]  INFO -- : Upstream: hora.roa.es Resolv::DNS::Resource::IN::AAAA
D, [2014-04-02T11:13:23.153696 #3556] DEBUG -- : Writing response to client (45 bytes) via UDP...
D, [2014-04-02T11:13:23.202225 #3556] DEBUG -- : Writing response to client (45 bytes) via UDP...
D, [2014-04-02T11:13:23.210046 #3556] DEBUG -- : Writing response to client (82 bytes) via UDP...

@ioquatix
Copy link
Member

ioquatix commented Apr 8, 2014

@xergio Did you try my very simple test case using Google's DNS? I've tried that script locally and haven't had any problems running ntpdate.

@xergio
Copy link
Author

xergio commented Apr 8, 2014

Yes, I've test it again:

15:20:14 root@enjuto2:/opt/misc # cat /etc/resolv.conf
domain jme
search jme
nameserver 127.0.0.1
15:20:16 root@enjuto2:/opt/misc # 

15:20:17 root@enjuto2:/opt/misc # cat /DATA/mounts/salvarez/misc/trunk/dns-dev/dns-ioquatix.rb 
require 'rubygems'

require 'rubydns'
require 'rubydns/system'


GOOGLE = RubyDNS::Resolver.new([[:tcp, "8.8.8.8", 53]])

RubyDNS::run_server() do
    otherwise do |transaction|
        @logger.info "Upstream: #{transaction}"
        transaction.passthrough!(GOOGLE)
    end
end15:20:21 root@enjuto2:/opt/misc # 

15:20:21 root@enjuto2:/opt/misc # ruby1.9.1 /DATA/mounts/salvarez/misc/trunk/dns-dev/dns-ioquatix.rb 
I, [2014-04-08T15:20:24.561229 #20828]  INFO -- : Starting RubyDNS server (v0.7.0)...
I, [2014-04-08T15:20:24.561361 #20828]  INFO -- : Listening on udp:0.0.0.0:53
I, [2014-04-08T15:20:24.561490 #20828]  INFO -- : Listening on tcp:0.0.0.0:53

D, [2014-04-08T15:20:37.754448 #20828] DEBUG -- : Receiving incoming query (29 bytes)...
D, [2014-04-08T15:20:37.754764 #20828] DEBUG -- : Processing question hora.roa.es Resolv::DNS::Resource::IN::A...
D, [2014-04-08T15:20:37.754825 #20828] DEBUG -- : Searching for hora.roa.es Resolv::DNS::Resource::IN::A
I, [2014-04-08T15:20:37.754868 #20828]  INFO -- : Upstream: hora.roa.es Resolv::DNS::Resource::IN::A
D, [2014-04-08T15:20:37.755258 #20828] DEBUG -- : Receiving incoming query (29 bytes)...
D, [2014-04-08T15:20:37.755381 #20828] DEBUG -- : Processing question hora.roa.es Resolv::DNS::Resource::IN::AAAA...
D, [2014-04-08T15:20:37.755425 #20828] DEBUG -- : Searching for hora.roa.es Resolv::DNS::Resource::IN::AAAA
I, [2014-04-08T15:20:37.755463 #20828]  INFO -- : Upstream: hora.roa.es Resolv::DNS::Resource::IN::AAAA
D, [2014-04-08T15:20:37.809313 #20828] DEBUG -- : Writing response to client (82 bytes) via UDP...
D, [2014-04-08T15:20:37.809647 #20828] DEBUG -- : Writing response to client (45 bytes) via UDP...
D, [2014-04-08T15:20:37.809865 #20828] DEBUG -- : Receiving incoming query (29 bytes)...
D, [2014-04-08T15:20:37.809951 #20828] DEBUG -- : Processing question hora.roa.es Resolv::DNS::Resource::IN::A...
D, [2014-04-08T15:20:37.809994 #20828] DEBUG -- : Searching for hora.roa.es Resolv::DNS::Resource::IN::A
I, [2014-04-08T15:20:37.810031 #20828]  INFO -- : Upstream: hora.roa.es Resolv::DNS::Resource::IN::A
D, [2014-04-08T15:20:37.810333 #20828] DEBUG -- : Receiving incoming query (29 bytes)...
D, [2014-04-08T15:20:37.810413 #20828] DEBUG -- : Processing question hora.roa.es Resolv::DNS::Resource::IN::AAAA...
D, [2014-04-08T15:20:37.810453 #20828] DEBUG -- : Searching for hora.roa.es Resolv::DNS::Resource::IN::AAAA
I, [2014-04-08T15:20:37.810489 #20828]  INFO -- : Upstream: hora.roa.es Resolv::DNS::Resource::IN::AAAA
D, [2014-04-08T15:20:37.871331 #20828] DEBUG -- : Writing response to client (45 bytes) via UDP...
D, [2014-04-08T15:20:37.871727 #20828] DEBUG -- : Writing response to client (82 bytes) via UDP...
D, [2014-04-08T15:20:37.872134 #20828] DEBUG -- : Receiving incoming query (33 bytes)...
D, [2014-04-08T15:20:37.872300 #20828] DEBUG -- : Processing question hora.roa.es.jme Resolv::DNS::Resource::IN::A...
D, [2014-04-08T15:20:37.872375 #20828] DEBUG -- : Searching for hora.roa.es.jme Resolv::DNS::Resource::IN::A
I, [2014-04-08T15:20:37.872436 #20828]  INFO -- : Upstream: hora.roa.es.jme Resolv::DNS::Resource::IN::A
D, [2014-04-08T15:20:37.872698 #20828] DEBUG -- : Receiving incoming query (33 bytes)...
D, [2014-04-08T15:20:37.872841 #20828] DEBUG -- : Processing question hora.roa.es.jme Resolv::DNS::Resource::IN::AAAA...
D, [2014-04-08T15:20:37.872911 #20828] DEBUG -- : Searching for hora.roa.es.jme Resolv::DNS::Resource::IN::AAAA
I, [2014-04-08T15:20:37.872955 #20828]  INFO -- : Upstream: hora.roa.es.jme Resolv::DNS::Resource::IN::AAAA
D, [2014-04-08T15:20:37.942077 #20828] DEBUG -- : Writing response to client (108 bytes) via UDP...
D, [2014-04-08T15:20:37.999002 #20828] DEBUG -- : Writing response to client (108 bytes) via UDP...
^C/var/lib/gems/1.9.1/gems/eventmachine-1.0.3/lib/eventmachine.rb:187:in `run_machine': Interrupt
    from /var/lib/gems/1.9.1/gems/eventmachine-1.0.3/lib/eventmachine.rb:187:in `run'
    from /var/lib/gems/1.9.1/gems/rubydns-0.7.0/lib/rubydns.rb:41:in `run_server'
    from /DATA/mounts/salvarez/misc/trunk/dns-dev/dns-ioquatix.rb:9:in `<main>'

15:20:40 root@enjuto2:/opt/misc #

Command output:

15:20:12 root@enjuto2:~ # /usr/sbin/ntpdate hora.roa.es
Error resolving hora.roa.es: No address associated with hostname (-5)
 8 Apr 15:20:37 ntpdate[20831]: Can't find host hora.roa.es: No address associated with hostname (-5)
 8 Apr 15:20:37 ntpdate[20831]: no servers can be used, exiting

Commands like svn or telnet fails too resolving other hostnames

@ioquatix
Copy link
Member

ioquatix commented Apr 8, 2014

What is the output of ruby -v?

@xergio
Copy link
Author

xergio commented Apr 8, 2014

15:20:40 root@enjuto2:/opt/misc # ruby1.9.1 -v
ruby 1.9.3p194 (2012-04-20 revision 35410) [x86_64-linux]

15:26:19 root@enjuto2:/opt/misc # whereis ruby1.9.1
ruby1.9: /usr/bin/ruby1.9.1 /usr/bin/X11/ruby1.9.1

15:26:54 root@enjuto2:/opt/misc # ll /usr/bin/ruby1.9.1
-rwxr-xr-x 1 root root 6336 Dec  2 04:22 /usr/bin/ruby1.9.1*

15:26:59 root@enjuto2:/opt/misc # uname -a
Linux enjuto2 3.2.0-4-amd64 #1 SMP Debian 3.2.54-2 x86_64 GNU/Linux

15:27:43 root@enjuto2:/opt/misc # cat /etc/debian_version 
7.4

15:28:33 root@enjuto2:/opt/misc # aptitude show ruby1.9.1
Package: ruby1.9.1                       
State: installed
Automatically installed: yes
Version: 1.9.3.194-8.1+deb7u2
Priority: optional
Section: ruby
Maintainer: akira yamada <akira@debian.org>
Architecture: amd64
Uncompressed Size: 259 k
Depends: libruby1.9.1 (= 1.9.3.194-8.1+deb7u2), libc6 (>= 2.2.5)
Suggests: ruby1.9.1-examples, ri1.9.1, graphviz, ruby1.9.1-dev, ruby-switch
Conflicts: irb1.9.1 (< 1.9.1.378-2~), rdoc1.9.1 (< 1.9.1.378-2~), ri (<= 4.5), ri1.9.1 (< 1.9.2.180-3~), ruby (<= 4.5), rubygems1.9.1
Breaks: apt-listbugs (< 0.1.6)
Replaces: irb1.9.1, rdoc1.9.1, rubygems1.9.1
Provides: irb1.9.1, rdoc1.9.1, ruby-interpreter, rubygems1.9.1
Description: Interpreter of object-oriented scripting language Ruby
 Ruby is the interpreted scripting language for quick and easy object-oriented programming.  It has many features to process text files and to do system management tasks (as in
 perl).  It is simple, straight-forward, and extensible. 

 In the name of this package, `1.9.1' indicates the Ruby library compatibility version. This package currently provides the `1.9.3' branch of Ruby, which is compatible with the
 `1.9.1' branch.
Homepage: http://www.ruby-lang.org/

@ioquatix
Copy link
Member

ioquatix commented Apr 8, 2014

So, I don't have the exact same version of Ruby or Linux, but I've run my laptop (Mac OS X 10.9) through the simple google DNS server listed above for 12 hours and haven't had any issues. I'm using Ruby 1.9.3-p448 installed by RVM for this test to match the same version of Ruby. In particular, I've tried ntpdate and had no issues.

That doesn't mean there isn't a problem, it just means I've failed to reproduce it so far. I'll try my linux box tonight.

@xergio
Copy link
Author

xergio commented Apr 9, 2014

Ok, I think there are something wrong in the network (in my work). I'm going to try 2 thing:

  1. To try you build, in addition I'll try ruby 2.1.1.
  2. To test it in my home.

But now I have to run to my work, it's too late!

Thank you for your patience, you are awesome ^^

@xergio
Copy link
Author

xergio commented Apr 9, 2014

Ok, ruby 2.1.1 have the same issue:

09:24:48 root@enjuto3:~ # ping -c1 hora.roa.es
PING hora.roa.es (150.214.94.5) 56(84) bytes of data.
64 bytes from hora.roa.es (150.214.94.5): icmp_req=1 ttl=52 time=30.2 ms

--- hora.roa.es ping statistics ---
1 packets transmitted, 1 received, 0% packet loss, time 0ms
rtt min/avg/max/mdev = 30.265/30.265/30.265/0.000 ms

09:24:58 root@enjuto3:~ # /usr/sbin/ntpdate hora.roa.es
Error resolving hora.roa.es: No address associated with hostname (-5)
 9 Apr 09:25:06 ntpdate[14264]: Can't find host hora.roa.es: No address associated with hostname (-5)
 9 Apr 09:25:06 ntpdate[14264]: no servers can be used, exiting

Log:

09:24:31 root@enjuto3:/opt/SOURCES/ruby-2.1.1 # /opt/ruby-2.1.1/bin/ruby /opt/dns-dev/dns-ioquatix.rb 
I, [2014-04-09T09:24:34.427938 #14243]  INFO -- : Starting RubyDNS server (v0.7.0)...
I, [2014-04-09T09:24:34.428218 #14243]  INFO -- : Listening on udp:0.0.0.0:53
I, [2014-04-09T09:24:34.428557 #14243]  INFO -- : Listening on tcp:0.0.0.0:53
D, [2014-04-09T09:24:58.518080 #14243] DEBUG -- : Receiving incoming query (29 bytes)...
D, [2014-04-09T09:24:58.518322 #14243] DEBUG -- : Processing question hora.roa.es Resolv::DNS::Resource::IN::A...
D, [2014-04-09T09:24:58.518360 #14243] DEBUG -- : Searching for hora.roa.es Resolv::DNS::Resource::IN::A
I, [2014-04-09T09:24:58.518392 #14243]  INFO -- : Upstream: hora.roa.es Resolv::DNS::Resource::IN::A
D, [2014-04-09T09:24:58.573967 #14243] DEBUG -- : Writing response to client (45 bytes) via UDP...
D, [2014-04-09T09:24:58.604990 #14243] DEBUG -- : Receiving incoming query (43 bytes)...
D, [2014-04-09T09:24:58.605459 #14243] DEBUG -- : Processing question 5.94.214.150.in-addr.arpa Resolv::DNS::Resource::IN::PTR...
D, [2014-04-09T09:24:58.605707 #14243] DEBUG -- : Searching for 5.94.214.150.in-addr.arpa Resolv::DNS::Resource::IN::PTR
I, [2014-04-09T09:24:58.606047 #14243]  INFO -- : Upstream: 5.94.214.150.in-addr.arpa Resolv::DNS::Resource::IN::PTR
D, [2014-04-09T09:24:58.669754 #14243] DEBUG -- : Writing response to client (89 bytes) via UDP...

D, [2014-04-09T09:25:06.474105 #14243] DEBUG -- : Receiving incoming query (29 bytes)...
D, [2014-04-09T09:25:06.474305 #14243] DEBUG -- : Processing question hora.roa.es Resolv::DNS::Resource::IN::A...
D, [2014-04-09T09:25:06.474342 #14243] DEBUG -- : Searching for hora.roa.es Resolv::DNS::Resource::IN::A
I, [2014-04-09T09:25:06.474366 #14243]  INFO -- : Upstream: hora.roa.es Resolv::DNS::Resource::IN::A
D, [2014-04-09T09:25:06.474883 #14243] DEBUG -- : Receiving incoming query (29 bytes)...
D, [2014-04-09T09:25:06.474987 #14243] DEBUG -- : Processing question hora.roa.es Resolv::DNS::Resource::IN::AAAA...
D, [2014-04-09T09:25:06.475018 #14243] DEBUG -- : Searching for hora.roa.es Resolv::DNS::Resource::IN::AAAA
I, [2014-04-09T09:25:06.475046 #14243]  INFO -- : Upstream: hora.roa.es Resolv::DNS::Resource::IN::AAAA
D, [2014-04-09T09:25:06.527641 #14243] DEBUG -- : Writing response to client (45 bytes) via UDP...
D, [2014-04-09T09:25:06.538171 #14243] DEBUG -- : Writing response to client (82 bytes) via UDP...
D, [2014-04-09T09:25:06.538569 #14243] DEBUG -- : Receiving incoming query (33 bytes)...
D, [2014-04-09T09:25:06.538824 #14243] DEBUG -- : Processing question hora.roa.es.jme Resolv::DNS::Resource::IN::A...
D, [2014-04-09T09:25:06.539045 #14243] DEBUG -- : Searching for hora.roa.es.jme Resolv::DNS::Resource::IN::A
I, [2014-04-09T09:25:06.539238 #14243]  INFO -- : Upstream: hora.roa.es.jme Resolv::DNS::Resource::IN::A
D, [2014-04-09T09:25:06.539773 #14243] DEBUG -- : Receiving incoming query (33 bytes)...
D, [2014-04-09T09:25:06.540099 #14243] DEBUG -- : Processing question hora.roa.es.jme Resolv::DNS::Resource::IN::AAAA...
D, [2014-04-09T09:25:06.540286 #14243] DEBUG -- : Searching for hora.roa.es.jme Resolv::DNS::Resource::IN::AAAA
I, [2014-04-09T09:25:06.540477 #14243]  INFO -- : Upstream: hora.roa.es.jme Resolv::DNS::Resource::IN::AAAA
D, [2014-04-09T09:25:06.618573 #14243] DEBUG -- : Writing response to client (108 bytes) via UDP...
D, [2014-04-09T09:25:06.624151 #14243] DEBUG -- : Writing response to client (108 bytes) via UDP...
^C/opt/ruby-2.1.1/lib/ruby/gems/2.1.0/gems/eventmachine-1.0.3/lib/eventmachine.rb:187:in `run_machine': Interrupt
    from /opt/ruby-2.1.1/lib/ruby/gems/2.1.0/gems/eventmachine-1.0.3/lib/eventmachine.rb:187:in `run'
    from /opt/ruby-2.1.1/lib/ruby/gems/2.1.0/gems/rubydns-0.7.0/lib/rubydns.rb:41:in `run_server'
    from /opt/dns-dev/dns-ioquatix.rb:9:in `<main>'

I suspect the network is doing something with the packets. Usually the sysadmins enable some "security profiles" in the firewall and I think this is another case.

I'm gona try this issue in my home.

@ioquatix
Copy link
Member

ioquatix commented Apr 9, 2014

You should try enabling UDP for the upstream connection - currently it is rewriting all requests into TCP requests - perhaps there is something going on with the TCP requests which isn't affecting UDP requests?

@xergio
Copy link
Author

xergio commented Apr 9, 2014

I've just test it in my home, no firewall, no extrange configurations, with a virtual machine installed from the scratch. Same build, debian 7, ruby 1.9.3, resolv.conf to 127.0.0.1, and your script. Can't resolve hostnames, for example apt can't resolve as well (I tried to install ntpdate to test it):

root@pupu:~# aptitude install ntpdate
The following NEW packages will be installed:
  lockfile-progs{a} ntpdate 
0 packages upgraded, 2 newly installed, 0 to remove and 0 not upgraded.
Need to get 93.6 kB of archives. After unpacking 305 kB will be used.
Do you want to continue? [Y/n/?] 
Err http://ftp.es.debian.org/debian/ wheezy/main ntpdate amd64 1:4.2.6.p5+dfsg-2
  Something wicked happened resolving 'ftp.es.debian.org:80' (-5 - No address associated with hostname)
Err http://ftp.es.debian.org/debian/ wheezy/main lockfile-progs amd64 0.1.17
  Something wicked happened resolving 'ftp.es.debian.org:http' (-5 - No address associated with hostname)

So, isn't a "ntpdate issue", there are more programs failing to resolve hostnames with this simple example.

All they report the same error: -5 No address associated with hostname, this is not, for example, a -2 Name or service not known or similar. Is like the program receive a response from the dns, but something is wrong in the packet and they can't extract the proper ip.

I don't know, I'm confused.

@ioquatix
Copy link
Member

ioquatix commented Apr 9, 2014

Okay, I'll try this setup to see if I can reproduce the issue.

@xergio
Copy link
Author

xergio commented Apr 9, 2014

If your script respond the IP statically with transaction.respond!("150.214.94.5") for example, it's works, The problem, I think, is with the passthrough, when the library delegate the resolv to another DNS server.

For example:

root@pupu:~# cat dns-simple.rb 
require 'rubygems'

require 'rubydns'
require 'rubydns/system'


GOOGLE = RubyDNS::Resolver.new([[:tcp, "8.8.8.8", 53]])

RubyDNS::run_server() do
    otherwise do |transaction|
        @logger.info "Upstream: #{transaction}"
        #transaction.passthrough!(GOOGLE)
        transaction.respond!("150.214.94.5")
    end
end

Now I execute ntpdate:

root@pupu:~# ntpdate hora.roa.es
 9 Apr 13:20:19 ntpdate[10599]: adjust time server 150.214.94.5 offset -0.007165 sec

It works!!

Log:

root@pupu:~# ruby1.9.3 dns-simple.rb 
I, [2014-04-09T13:20:04.557974 #10597]  INFO -- : Starting RubyDNS server (v0.7.0)...
I, [2014-04-09T13:20:04.558365 #10597]  INFO -- : Listening on udp:0.0.0.0:53
I, [2014-04-09T13:20:04.558803 #10597]  INFO -- : Listening on tcp:0.0.0.0:53

D, [2014-04-09T13:20:13.652463 #10597] DEBUG -- : Receiving incoming query (29 bytes)...
D, [2014-04-09T13:20:13.652745 #10597] DEBUG -- : Processing question hora.roa.es Resolv::DNS::Resource::IN::A...
D, [2014-04-09T13:20:13.652785 #10597] DEBUG -- : Searching for hora.roa.es Resolv::DNS::Resource::IN::A
I, [2014-04-09T13:20:13.652813 #10597]  INFO -- : Upstream: hora.roa.es Resolv::DNS::Resource::IN::A
I, [2014-04-09T13:20:13.652843 #10597]  INFO -- : Resource class: Resolv::DNS::Resource::IN::A
I, [2014-04-09T13:20:13.652911 #10597]  INFO -- : Resource: #<Resolv::DNS::Resource::IN::A:0x0000000220e1d8 @address=#<Resolv::IPv4 150.214.94.5>>
D, [2014-04-09T13:20:13.652962 #10597] DEBUG -- : add_answer: #<Resolv::DNS::Resource::IN::A:0x0000000220e1d8 @address=#<Resolv::IPv4 150.214.94.5>> 1 1
D, [2014-04-09T13:20:13.653099 #10597] DEBUG -- : Writing response to client (45 bytes) via UDP...


D, [2014-04-09T13:20:13.653326 #10597] DEBUG -- : Receiving incoming query (29 bytes)...
D, [2014-04-09T13:20:13.653411 #10597] DEBUG -- : Processing question hora.roa.es Resolv::DNS::Resource::IN::AAAA...
D, [2014-04-09T13:20:13.653437 #10597] DEBUG -- : Searching for hora.roa.es Resolv::DNS::Resource::IN::AAAA
I, [2014-04-09T13:20:13.653460 #10597]  INFO -- : Upstream: hora.roa.es Resolv::DNS::Resource::IN::AAAA
I, [2014-04-09T13:20:13.653482 #10597]  INFO -- : Resource class: Resolv::DNS::Resource::IN::AAAA
E, [2014-04-09T13:20:13.653548 #10597] ERROR -- : Exception thrown while processing hora.roa.es Resolv::DNS::Resource::IN::AAAA!
E, [2014-04-09T13:20:13.653574 #10597] ERROR -- : ArgumentError: not numeric IPv6 address: 150.214.94.5
E, [2014-04-09T13:20:13.653594 #10597] ERROR -- : /usr/lib/ruby/1.9.1/resolv.rb:2297:in `create'
E, [2014-04-09T13:20:13.653611 #10597] ERROR -- : /usr/lib/ruby/1.9.1/resolv.rb:2034:in `initialize'
E, [2014-04-09T13:20:13.653628 #10597] ERROR -- : /var/lib/gems/1.9.1/gems/rubydns-0.7.0/lib/rubydns/transaction.rb:144:in `new'
E, [2014-04-09T13:20:13.653645 #10597] ERROR -- : /var/lib/gems/1.9.1/gems/rubydns-0.7.0/lib/rubydns/transaction.rb:144:in `respond!'
E, [2014-04-09T13:20:13.653663 #10597] ERROR -- : dns-simple.rb:13:in `block (2 levels) in <main>'
E, [2014-04-09T13:20:13.653682 #10597] ERROR -- : /var/lib/gems/1.9.1/gems/rubydns-0.7.0/lib/rubydns/server.rb:282:in `call'
E, [2014-04-09T13:20:13.653700 #10597] ERROR -- : /var/lib/gems/1.9.1/gems/rubydns-0.7.0/lib/rubydns/server.rb:282:in `process'
E, [2014-04-09T13:20:13.653717 #10597] ERROR -- : /var/lib/gems/1.9.1/gems/rubydns-0.7.0/lib/rubydns/transaction.rb:206:in `process'
E, [2014-04-09T13:20:13.653735 #10597] ERROR -- : /var/lib/gems/1.9.1/gems/rubydns-0.7.0/lib/rubydns/server.rb:317:in `block (2 levels) in process_query'
E, [2014-04-09T13:20:13.653753 #10597] ERROR -- : /var/lib/gems/1.9.1/gems/rubydns-0.7.0/lib/rubydns/server.rb:312:in `each'
E, [2014-04-09T13:20:13.653770 #10597] ERROR -- : /var/lib/gems/1.9.1/gems/rubydns-0.7.0/lib/rubydns/server.rb:312:in `block in process_query'
D, [2014-04-09T13:20:13.653816 #10597] DEBUG -- : Writing response to client (29 bytes) via UDP...

I don't know why this show and error, I think that is becouse ntpdate try to resolve via IPv6 and there is no resolution. Anyway, resolving statically the IP, ntpdate works.

Sorry, I'm not a Ruby expert, I cant make tests easily wit the library code.. :(

@ioquatix
Copy link
Member

ioquatix commented Apr 9, 2014

The error occurs because you are matching all requests including IPv6 but responding with only IPv4. If you request MX record or CNAME, you'll also have issues :D

@ioquatix
Copy link
Member

ioquatix commented Apr 9, 2014

Okay so I just tried this on my linux dev box which is running the latest arch linux and it worked perfectly.

Are you able to send me a copy of the VM?

@ioquatix
Copy link
Member

ioquatix commented Apr 9, 2014

koyoko% uname -a
Linux koyoko 3.13.8-1-ARCH #1 SMP PREEMPT Tue Apr 1 12:19:51 CEST 2014 x86_64 GNU/Linux

@ioquatix
Copy link
Member

ioquatix commented Apr 9, 2014

I was using the latest version of event machine, I think v1.0.3?

@xergio
Copy link
Author

xergio commented Apr 9, 2014

root@pupu:~# gem1.9.3 install rubydns
Building native extensions.  This could take a while...
Fetching: rubydns-0.7.0.gem (100%)
Successfully installed eventmachine-1.0.3
Successfully installed rubydns-0.7.0
2 gems installed
Installing ri documentation for eventmachine-1.0.3...
Installing ri documentation for rubydns-0.7.0...
Installing RDoc documentation for eventmachine-1.0.3...
Installing RDoc documentation for rubydns-0.7.0...

Of course! give me 5 minutes and I'll get you a link to download the full VM (~1GB). The "disk" is a .vmdk, from VMware, but it works in Virtualbox as well.

Some setups:

root@pupu:~# uname -a
Linux pupu 3.2.0-4-amd64 #1 SMP Debian 3.2.54-2 x86_64 GNU/Linux

root@pupu:~# ifconfig
eth0      Link encap:Ethernet  HWaddr 00:0c:29:58:89:76  
          inet addr:192.168.1.90  Bcast:192.168.1.255  Mask:255.255.255.0
          inet6 addr: fe80::20c:29ff:fe58:8976/64 Scope:Link
          UP BROADCAST RUNNING MULTICAST  MTU:1500  Metric:1
          RX packets:65757 errors:0 dropped:0 overruns:0 frame:0
          TX packets:21693 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:1000 
          RX bytes:93106665 (88.7 MiB)  TX bytes:1935641 (1.8 MiB)

lo        Link encap:Local Loopback  
          inet addr:127.0.0.1  Mask:255.0.0.0
          inet6 addr: ::1/128 Scope:Host
          UP LOOPBACK RUNNING  MTU:16436  Metric:1
          RX packets:107 errors:0 dropped:0 overruns:0 frame:0
          TX packets:107 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:0 
          RX bytes:8085 (7.8 KiB)  TX bytes:8085 (7.8 KiB)

root@pupu:~# cat /etc/resolv.conf 
#domain lan_dn
#search lan_dn
#nameserver 62.81.16.213
#nameserver 62.81.29.254
nameserver 127.0.0.1

root@pupu:~# cat /etc/hosts
127.0.0.1   localhost
127.0.1.1   pupu

# The following lines are desirable for IPv6 capable hosts
::1     localhost ip6-localhost ip6-loopback
ff02::1 ip6-allnodes
ff02::2 ip6-allrouters
root@pupu:~#

@xergio
Copy link
Author

xergio commented Apr 9, 2014

Ok, the links:

Single disk: http://files.xrg.es/Debian%207%2064-bit.vmdk
VM setup: http://i.imgur.com/hMVkcNx.png (sorry, I'm obligated to use Windows at home...)

If you have problems using the disk, I've exported the VM to OVF format, links:

I cant create the VM with virtualbox too if you want, here in my work (I use Linux here). It takes only 5-10 mins of my time.

All the files are in http://files.xrg.es/ , this server are in my home, so the download can be a bit slow :/

@xergio
Copy link
Author

xergio commented Apr 9, 2014

Oh, I forgot.

For the VM, user: root, pass: q. Yes, a single q. In /root there are your script, execute it with ruby1.9.3 dns-simple.rb for example.

@ioquatix
Copy link
Member

ioquatix commented Apr 9, 2014

Okay, I have VMware so the vmdk should be fine, thanks, I am downloading now.

@xergio
Copy link
Author

xergio commented Apr 9, 2014

I'm checking the code. I saw that resolver.rb have some debug that I dont see in the output. I added some debug extra to your example:

GOOGLE = RubyDNS::Resolver.new([[:tcp, "8.8.8.8", 53]], {:logger => Logger.new($stderr)})

Now this is the output for a single request:

root@pupu:~# ruby1.9.3 dns-simple.rb 
I, [2014-04-09T16:54:06.524003 #5081]  INFO -- : Starting RubyDNS server (v0.7.0)...
I, [2014-04-09T16:54:06.524577 #5081]  INFO -- : Listening on udp:0.0.0.0:53
I, [2014-04-09T16:54:06.524983 #5081]  INFO -- : Listening on tcp:0.0.0.0:53
D, [2014-04-09T16:54:10.035167 #5081] DEBUG -- : Receiving incoming query (29 bytes)...
D, [2014-04-09T16:54:10.035483 #5081] DEBUG -- : Processing question hora.roa.es Resolv::DNS::Resource::IN::A...
D, [2014-04-09T16:54:10.035531 #5081] DEBUG -- : Searching for hora.roa.es Resolv::DNS::Resource::IN::A
I, [2014-04-09T16:54:10.035564 #5081]  INFO -- : Upstream: hora.roa.es Resolv::DNS::Resource::IN::A
D, [2014-04-09T16:54:10.035721 #5081] DEBUG -- : [1] Sending request to server [:tcp, "8.8.8.8", 53]
D, [2014-04-09T16:54:10.036140 #5081] DEBUG -- : Receiving incoming query (29 bytes)...
D, [2014-04-09T16:54:10.036487 #5081] DEBUG -- : Processing question hora.roa.es Resolv::DNS::Resource::IN::AAAA...
D, [2014-04-09T16:54:10.036658 #5081] DEBUG -- : Searching for hora.roa.es Resolv::DNS::Resource::IN::AAAA
I, [2014-04-09T16:54:10.036831 #5081]  INFO -- : Upstream: hora.roa.es Resolv::DNS::Resource::IN::AAAA
D, [2014-04-09T16:54:10.037070 #5081] DEBUG -- : [2] Sending request to server [:tcp, "8.8.8.8", 53]
D, [2014-04-09T16:54:10.111957 #5081] DEBUG -- : [1] Received valid response #<Resolv::DNS::Message:0x00000001518c80 @id=1, @qr=1, @opcode=0, @aa=0, @tc=0, @rd=1, @ra=1, @rcode=0, @question=[[#<Resolv::DNS::Name: hora.roa.es.>, Resolv::DNS::Resource::IN::A]], @answer=[[#<Resolv::DNS::Name: hora.roa.es.>, 1928, #<Resolv::DNS::Resource::IN::A:0x0000000151ebd0 @address=#<Resolv::IPv4 150.214.94.5>, @ttl=1928>]], @authority=[], @additional=[]>
D, [2014-04-09T16:54:10.112279 #5081] DEBUG -- : Writing response to client (45 bytes) via UDP...
D, [2014-04-09T16:54:10.322509 #5081] DEBUG -- : [2] Received valid response #<Resolv::DNS::Message:0x0000000151c560 @id=2, @qr=1, @opcode=0, @aa=0, @tc=0, @rd=1, @ra=1, @rcode=0, @question=[[#<Resolv::DNS::Name: hora.roa.es.>, Resolv::DNS::Resource::IN::AAAA]], @answer=[], @authority=[[#<Resolv::DNS::Name: roa.es.>, 1799, #<Resolv::DNS::Resource::IN::SOA:0x000000015219c0 @mname=#<Resolv::DNS::Name: roasf.roa.es.>, @rname=#<Resolv::DNS::Name: postmaster.roa.es.>, @serial=2012120501, @refresh=86400, @retry=7200, @expire=2419200, @minimum=172800, @ttl=1799>]], @additional=[]>
D, [2014-04-09T16:54:10.322837 #5081] DEBUG -- : Writing response to client (82 bytes) via UDP...
D, [2014-04-09T16:54:10.323164 #5081] DEBUG -- : Receiving incoming query (29 bytes)...
D, [2014-04-09T16:54:10.323389 #5081] DEBUG -- : Processing question hora.roa.es Resolv::DNS::Resource::IN::A...
D, [2014-04-09T16:54:10.323657 #5081] DEBUG -- : Searching for hora.roa.es Resolv::DNS::Resource::IN::A
I, [2014-04-09T16:54:10.323813 #5081]  INFO -- : Upstream: hora.roa.es Resolv::DNS::Resource::IN::A
D, [2014-04-09T16:54:10.324039 #5081] DEBUG -- : [3] Sending request to server [:tcp, "8.8.8.8", 53]
D, [2014-04-09T16:54:10.324299 #5081] DEBUG -- : Receiving incoming query (29 bytes)...
D, [2014-04-09T16:54:10.324623 #5081] DEBUG -- : Processing question hora.roa.es Resolv::DNS::Resource::IN::AAAA...
D, [2014-04-09T16:54:10.324782 #5081] DEBUG -- : Searching for hora.roa.es Resolv::DNS::Resource::IN::AAAA
I, [2014-04-09T16:54:10.324975 #5081]  INFO -- : Upstream: hora.roa.es Resolv::DNS::Resource::IN::AAAA
D, [2014-04-09T16:54:10.325214 #5081] DEBUG -- : [4] Sending request to server [:tcp, "8.8.8.8", 53]
D, [2014-04-09T16:54:10.404989 #5081] DEBUG -- : [3] Received valid response #<Resolv::DNS::Message:0x000000016daf00 @id=3, @qr=1, @opcode=0, @aa=0, @tc=0, @rd=1, @ra=1, @rcode=0, @question=[[#<Resolv::DNS::Name: hora.roa.es.>, Resolv::DNS::Resource::IN::A]], @answer=[[#<Resolv::DNS::Name: hora.roa.es.>, 4369, #<Resolv::DNS::Resource::IN::A:0x000000016e5fb8 @address=#<Resolv::IPv4 150.214.94.5>, @ttl=4369>]], @authority=[], @additional=[]>
D, [2014-04-09T16:54:10.405288 #5081] DEBUG -- : Writing response to client (45 bytes) via UDP...
D, [2014-04-09T16:54:10.408764 #5081] DEBUG -- : [4] Received valid response #<Resolv::DNS::Message:0x00000001617d98 @id=4, @qr=1, @opcode=0, @aa=0, @tc=0, @rd=1, @ra=1, @rcode=0, @question=[[#<Resolv::DNS::Name: hora.roa.es.>, Resolv::DNS::Resource::IN::AAAA]], @answer=[], @authority=[[#<Resolv::DNS::Name: roa.es.>, 1328, #<Resolv::DNS::Resource::IN::SOA:0x00000001636d60 @mname=#<Resolv::DNS::Name: roasf.roa.es.>, @rname=#<Resolv::DNS::Name: postmaster.roa.es.>, @serial=2012120501, @refresh=86400, @retry=7200, @expire=2419200, @minimum=172800, @ttl=1328>]], @additional=[]>
D, [2014-04-09T16:54:10.409042 #5081] DEBUG -- : Writing response to client (82 bytes) via UDP...

I hope this will be useful.

@xergio
Copy link
Author

xergio commented Apr 9, 2014

Oh, I forced an error. Line 126 of resolver.rb file:

resolver.rb:126:in `process_response!': undefined local variable or method `exception' for #<RubyDNS::Resolver::Request:0x00000001e9f790> (NameError)

This exception variable should be response, I think.

@ioquatix
Copy link
Member

ioquatix commented Apr 9, 2014

v0.7.1 fixes that bug, thanks for reporting it. Can you try again and see if you get an error message?

The number in the square brackets is the message ID as it travels through the resolver. It seems strange to me that for the same request there are different response lengths:

Writing response to client (45 bytes) via UDP...
Writing response to client (82 bytes) via UDP...

There is a special function in RubyDNS for logging bad messages - I don't think it is useful in this case, but can you try prepending to your script:

RubyDNS::log_bad_messages!("path/to/file.log")

The log file would get any bad packets - this can be very high volume so it isn't a good idea to use it in production. I also have the VM so I will take a look at it today.

@ioquatix
Copy link
Member

ioquatix commented Apr 9, 2014

Okay the bug was reproduced in the VM, now I'll take a closer look.

Sent from my phone.

On 10/04/2014, at 3:37 am, Sergio Álvarez notifications@github.com wrote:

Oh, I forced an error. Line 126 of resolver.rb file:

resolver.rb:126:in process_response!': undefined local variable or methodexception' for #RubyDNS::Resolver::Request:0x00000001e9f790 (NameError)
This exception variable should be response, I think.


Reply to this email directly or view it on GitHub.

@xergio
Copy link
Author

xergio commented Apr 10, 2014

Good news! I hope you will find the problem (or my problem).

I'll test the fix in a moment, is not critical. I forced it hacking the code, so it's not a common usage of the library.

@ioquatix
Copy link
Member

Managed to reproduce the issue with relative ease:

> Socket::gethostbyname("ftp.es.debian.org")
SocketError: getaddrinfo: No address associated with hostname
    from (irb):5:in `gethostbyname'
    from (irb):5
    from /usr/bin/irb:12:in `<main>'

Now just need to figure out what is going wrong..

@ioquatix
Copy link
Member

Okay, think I found the issue. On some versions of glibc(?) the resolver fails to work correctly if the result of the DNS query isn't advertised to be recursive. Simply add this to the block which includes recursive lookups:

# Name server supports recursion:
transaction.answer.ra = 1

Not sure why this causes so much trouble on this particular combination, but it does. Perhaps we should include a warning if the user does passthrough! but doesn't advertise that recursion is being used.. Obviously whether recursion is being used or not shouldn't matter to the resolver as long as the response is valid (and it IS providing a valid response in both cases). Perhaps looking in the code for gethostbyname might tell us what is going on.

@ioquatix
Copy link
Member

My bad, the first commit, the fix was commented out :D

@xergio
Copy link
Author

xergio commented Apr 11, 2014

Excelent! Now all is working as intended. Great job!

I'll make more tests this weekend with my original script.

Thank you very much for you patience.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants