FORMERR Messages in BIND 9.3.2
Barry Finkel
b19141 at achilles.ctd.anl.gov
Tue Jul 11 15:04:11 UTC 2006
>> I wrote on July 5:
>>
>> >I recently upgraded BIND from 9.2.4 to 9.3.2. I am now seeing in the
>> >syslog of two of my DNS servers messages like this:
>> >
>> > Jun 29 13:26:35 titania.ctd.anl.gov named[18180]:
>> > [ID 866145 daemon.info] FORMERR resolving
>> > 'nicholas.8dstar.com/AAAA/IN': 64.250.235.139#53
>> >
>> >I did not see anything in the 9.3.2 CHANGES file about this message.
>> >Is this something new that 9.3.2 catches but that 9.2.4 did not?
>> >Or is it something that was caught in 9.2.4 but not logged.
>> >
>> >I am seeing a large number of these (342,644 since Friday at 03:10),
>> >and I am trying to see how to eliminate logging of the message and to
>> >discover what is causing the message.
>> >
>> >I ran a snoop trace on one of my servers, and I traced one FORMERR.
>> >I see in response to the query:
>> >
>> > What are the NS records for liarignorance.info.?
>> >
>> >that the response packet contains
>> >
>> > 1 question
>> > 0 answers
>> > 4 authority (NS) records
>> > 5 additional records (the addresses of the four nameservers plus
>> > some garbage).
>> >
>>I assume that it is this garbage in the fifth additional record that
>> >is causing the FORMERR message from BIND. I checked the version of
>> >the server that created this response packet -
>> >
>> > "UltraDNS Version 2.9.6.1 Build 5094"
>> >
>> >Is it correct to have the answer appear in the authority section instead
>> >of the answer secion? Would this cause a FORMERR? I did a standard
>> >
>> > dig anl.gov ns
>> >
>> >using one of my BIND slaves, and I get four answer sections and no
>> >authority sections:
>> >
>> > flags: qr aa rd ra; QUERY: 1, ANSWER: 4, AUTHORITY: 0, ADDITIONAL: 4
And yesterday I provided additional information:
>> As there have been no replies, I decided to run some tests. I can run
>> the following query
>>
>> britaine% dig nastyhos.com mx @dns2.anl.gov
>>
>> ; <<>> DiG 8.3 <<>> nastyhos.com mx @dns2.anl.gov
>> ; (3 servers found)
>> ;; res options: init recurs defnam dnsrch
>> ;; got answer:
>> ;; ->>HEADER<<- opcode: QUERY, status: SERVFAIL, id: 6
>> ;; flags: qr rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 0
>> ;; QUERY SECTION:
>> ;; nastyhos.com, type = MX, class = IN
>>
>> ;; Total query time: 106 msec
>> ;; FROM: britaine.ctd.anl.gov to SERVER: dns2.anl.gov 146.137.64.7
>> ;; WHEN: Mon Jul 10 09:57:35 2006
>> ;; MSG SIZE sent: 30 rcvd: 30
>>
>> britaine%
>>
>> and produce the message
>>
>> Jul 10 09:57:41 oberon.ctd.anl.gov named[24253]:
>> [ID 866145 daemon.info] FORMERR resolving 'nastyhos.com/MX/IN':
>> 64.20.33.3#53
>>
>> I run the same command on one of our external DNS servers:
>>
>> britaine% dig nastyhos.com mx @t1dns2.anl.gov
>>
>> ; <<>> DiG 8.3 <<>> nastyhos.com mx @t1dns2.anl.gov
>> ; (1 server found)
>> ;; res options: init recurs defnam dnsrch
>> ;; got answer:
>> ;; ->>HEADER<<- opcode: QUERY, status: SERVFAIL, id: 6
>> ;; flags: qr rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 0
>> ;; QUERY SECTION:
>> ;; nastyhos.com, type = MX, class = IN
>>
>> ;; Total query time: 138 msec
>> ;; FROM: britaine.ctd.anl.gov to SERVER: t1dns2.anl.gov 130.202.101.37
>> ;; WHEN: Mon Jul 10 09:59:21 2006
>> ;; MSG SIZE sent: 30 rcvd: 30
>>
>> britaine%
>>
>> and I do not see any FORMERR message. Note that both queries return
>> SERVFAIL. All of my DNS servers are running BIND 9.3.2, SunOS
>> Generic_118558-23 sun4u sparc SUNW,Sun-Fire-V240. I built BIND 9.3.2
>> on each of the five servers using the same parameters. The executables
>> have different lengths, but an "ldd" command run against all five
>> executables shows the same output.
>>
>> As a further test, I took the executable on dns2 and replaced it with
>> the executable on t1dns2, thinking that there may be problems with the
>> executable on the internal dns1 and dns2, but I still get a FORMERR
>> message on dns2.
>>
>> I have looked at the code, and I am not sure what causes a FORMERR.
>> I have looked at some SNOOP traces, and in some cases I cannot see
>> anything wrong with the packets. I have to assume from the numerous
>> messages that when a FORMERR is detected, nothing in the packet it
>> cached, as subsequent queries again produce a FORMERR message instead of
>> retrieving information from the cache.
>>
>> Can anyone explain what I am seeing? Thanks.
Mark Andrews replied:
> 64.20.33.3 is delegated nastyhos.com but is configured with
> a single root zone. FORMERR is internally generated saying
> we don't like the format of the negative answer we got.
> In this case it was "wrong owner name" but was handled as
> a default error condition.
>
>nastyhos.com. 172800 IN NS ns1.zt-444.com.
>nastyhos.com. 172800 IN NS ns2.zt-444.com.
>nastyhos.com. 172800 IN NS ns3.zt-444.com.
>
>;; ADDITIONAL SECTION:
>ns1.zt-444.com. 172800 IN A 64.20.33.130
>ns2.zt-444.com. 172800 IN A 64.20.33.3
>ns3.zt-444.com. 172800 IN A 64.20.33.114
>
>
>; <<>> DiG 9.3.2 <<>> any nastyhos.com @64.20.33.3
>; (1 server found)
>;; global options: printcmd
>;; Got answer:
>;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 52650
>;; flags: qr aa rd; QUERY: 1, ANSWER: 1, AUTHORITY: 1, ADDITIONAL: 0
>
>;; QUESTION SECTION:
>;nastyhos.com. IN ANY
>
>;; ANSWER SECTION:
>nastyhos.com. 7200 IN A 64.20.33.4
>
>;; AUTHORITY SECTION:
>. 259200 IN NS ns.
>
>;; Query time: 46 msec
>;; SERVER: 64.20.33.3#53(64.20.33.3)
>;; WHEN: Tue Jul 11 04:46:40 2006
>;; MSG SIZE rcvd: 61
>
>
>; <<>> DiG 9.3.2 <<>> nastyhos.com mx +norec @64.20.33.3
>; (1 server found)
>;; global options: printcmd
>;; Got answer:
>;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 26463
>;; flags: qr aa; QUERY: 1, ANSWER: 0, AUTHORITY: 1, ADDITIONAL: 0
>
>;; QUESTION SECTION:
>;nastyhos.com. IN MX
>
>;; AUTHORITY SECTION:
>. 2560 IN SOA ns. hostmaster. 1152476337 16384 2048 1048576 2560
>
>;; Query time: 32 msec
>;; SERVER: 64.20.33.3#53(64.20.33.3)
>;; WHEN: Tue Jul 11 04:41:46 2006
>;; MSG SIZE rcvd: 77
I am not sure that I fully understand the answer; I will have to look at
some of the trace packets I captured. Now I will follow another side of
this problem.
On two of my DNS servers I see the FORMERR messages, and on the other
two I do not. I (and my predecessor hostmasters) configured the BIND
on the servers where I am seeing the FORMERR messages; we configured no
special logging. A colleague configured BIND on the two servers where
I am not seeing the FORMERR messages; he configured this logging:
logging {
channel general-log {
file "/var/log/named.general.log" versions 3 size 200k;
print-category yes;
print-severity yes;
print-time yes;
severity info;
};
channel security-log {
file "/var/log/named.security.log" versions 3 size 200k;
print-category yes;
print-severity yes;
print-time yes;
severity info;
};
channel client-log {
file "/var/log/named.client.log" versions 3 size 200k;
print-category yes;
print-severity yes;
print-time yes;
severity info;
};
channel config-log {
file "/var/log/named.config.log" versions 3 size 200k;
print-category yes;
print-severity yes;
print-time yes;
severity info;
};
channel xfer-log {
file "/var/log/named.xfer.log" versions 3 size 200k;
print-category yes;
print-severity yes;
print-time yes;
severity info;
};
channel notify-log {
file "/var/log/named.notify.log" versions 3 size 200k;
print-category yes;
print-severity yes;
print-time yes;
severity info;
};
category default { general-log; default_syslog; };
category security { security-log; default_syslog; };
category config { config-log; default_syslog; };
category client { client-log; default_syslog; };
category config { config-log; default_syslog; };
category client { client-log; default_syslog; };
category notify { notify-log; default_syslog; };
category xfer-in { xfer-log; default_syslog; };
category xfer-out { xfer-log; default_syslog; };
category lame-servers { null; };
};
I have to assume that it is this special logging that is causing the
FORMERR messages to be omitted from the logs. I do not know into what
category the FORMERR falls. All I see in the logs of the systems that
produce FORMERR messages is
Jul 11 09:51:50 titania.ctd.anl.gov named[18168]:
[ID 866145 daemon.info] FORMERR resolving
'shinhwa.8dstar.com/AAAA/IN': 216.152.252.8#53
All of the BIND messages appear to have "daemon.info". In the
/var/log/syslog file I am getting some (but not all) of the BIND
messages logged twice; I have not been able to determine which
messages are duplicated or how to eliminate the duplications.
----------------------------------------------------------------------
Barry S. Finkel
Computing and Information Systems Division
Argonne National Laboratory Phone: +1 (630) 252-7277
9700 South Cass Avenue Facsimile:+1 (630) 252-4601
Building 222, Room D209 Internet: BSFinkel at anl.gov
Argonne, IL 60439-4828 IBMMAIL: I1004994
More information about the bind-users
mailing list