"malformed transaction" Message BIND 9.5.0

[bsfinkel at anl.gov]

>> I wrote:
>> 
>> >> I upgraded to BIND 9.5.0 earlier this week, and after the upgrade I
>> >> see a message on one of my BIND 9.5.0 servers:
>> >> 
>> >>      Jun 25 09:44:00 puck.it.anl.gov named[20168]:
>> >>        [ID 873579 daemon.error] malformed transaction:
>> >>        cmt227.rev.jnl last serial 6843 != transaction first serial 6842
>> >> 
>> >> I am looking at the logs, dns traces, and snoop traces now.  I have not
>> >> yet concluded what is happening.  To what address should I send my
>> >> files and summaries?  Thanks.
>> 
>> and Mark Andrews replied:
>> 
>> >	Did you remove the old (possibly corrupted) journal files when
>> >	you upgraded?
>> 
>> I did not remove the jnl files when I upgraded.  I have looked at the
>> various pieces of documentation and I see on puck:
>> 
>>    Jun 25 09:43:18 puck.it.anl.gov named[20168]: [ID 873579 daemon.info]
>>      zone 227.139.146.in-addr.arpa/IN/external: transferred serial 6843
>>    Jun 25 09:43:18 puck.it.anl.gov named[20168]: [ID 873579 daemon.info]
>>      transfer of '227.139.146.in-addr.arpa/IN/external'
>>      from 146.137.64.5#53: Transfer completed: 1 messages, 6 records,
>>      260 bytes, 0.073 secs (3561 bytes/sec)
>> 
>> Then I see on puck 42 seconds later:
>> 
>>    Jun 25 09:44:00 puck Transfer started.
>>    Jun 25 09:44:00 puck.it.anl.gov named[20168]: [ID 873579 daemon.info]
>>      transfer of '227.139.146.in-addr.arpa/IN/argonne'
>>      from 146.137.64.5#53: connected using 146.137.96.100#41543
>>    Jun 25 09:44:00 puck malformed transaction: cmt227.rev.jnl
>>      last serial 6843 != transaction first serial 6842 
>>    Jun 25 09:44:00 puck failed while receiving responses:
>>      unexpected error
>> 
>> The 09:43:18 message with the transfer stats looks ok, the AXFR had
>> one record.  Once the transfer was complete, why did BIND 9.5.0
>> try another zone transfer for the zone 42 seconds later?
>> 
>> The two previous errors for this zone were from the transfers of
>> serial numbers 6841 and 6842, one after 8.5 minutes and one after
>> 6 seconds.  (Some of the messages below have been shortened.)
>> 
>>     Here the "master" server from which the zone was transferred was
>>     BIND 9.4.1-P1.
>> 
>>     Jun 25 00:20:49 puck transferred serial 6841
>>     Jun 25 00:20:49 puck 1 messages, 6 records, 260 bytes, ...
>>     ...
>>     Jun 25 00:29:19 puck Transfer started.
>>     Jun 25 00:29:19 puck malformed transaction: cmt227.rev.jnl
>>       last serial 6841 != transaction first serial 6840
>> 
>> and then
>> 
>>     At 07:08 I upgraded the "master" from 9.4.1-P1 to 9.5.0.
>> 
>>     Jun 25 08:51:30 puck Transfer started.
>>     Jun 25 08:51:30 puck journal file cmt227.rev.jnl does not exist,
>>       creating it
>>     Jun 25 08:51:30 puck transferred serial 6842
>>     Jun 25 08:51:30 puck 1 messages, 6 records, 260 bytes, ...
>>     ...
>>     Jun 25 08:51:36 puck Transfer started.
>>     Jun 25 08:51:36 puck malformed transaction: cmt227.rev.jnl
>>      last serial 6842 != transaction first serial 6841
>> 
>>     When I saw this "malformed" message in the puck syslog, I started
>>     a snoop trace on puck to capture the next failure.
>> 
>> The zone in question is a /24 reverse zone that is mastered on a
>> Windows 2003 DNS Server and dynamically updated by a W2003 DHCP Server.
>> The W2003 DNS Server, when the zone has been updated, sends a NOTIFY
>> to the "master" BIND server from which I am transferring the file.
>> For technical reasons I cannot have the W2003 DNS Server notify
>> puck directly.  I have no problems with the transfer of this zone
>> (on any other of the 44+ AD zones) from the W2003 DNS Server to the
>> BIND server, which serves as the "master" for zone transfers to my
>> internal, external, and off-site BIND slaves (as well as puck).

And Mark Andrews replied:

>	Are you 100% certain both views reference different master
>	files?

My DNS setup is this:

     puck is the BIND hidden master for most of the zones.  Many of the
          zones that are mastered elsewhere are slaved on puck so that
          I can run comparisons on all of the zones.

     titania is the internal BIND server that transfers all of the
             zones from the Windows 2003 Server.  There is one
             forward zone, five /24 reverse zones, and 16 sets of
             Windows AD zones.  The Windows DNS server transfers
             all of its zones to my four on-site public BIND servers.
             For technical reasons I cannot have Windows transfer to
             puck, so I use titania as the "pseudo-master" for the
             one forward and five reverse zones from the Windows DNS.

I am not sure I understand your reply.  I do have split-views on puck,
mainly to introduce different MX records to our internal customers and
our external customers.  There are no split-views for the zones on
the Windows 2003 DNS Server.

I do use titania as the "pseudo-master" to feed the Windows DNS Server
zones to the off-site slaves.  These slave BIND servers are no under
my control, and the administrators have never reported a "malformed
transaction" message.  I need to ask them to look at their BIND logs.

It is only when I transfer these one forward and five reverse zones
from titania to puck that I see the message.  The zones transfer OK
(I assume from the BIND messages), but a short time later the IXFR
is re-attempted (for some as yet unknown reason).  Note that I do not
transfer the AD zones to puck, as I do not need them there for
comparison purposes.
----------------------------------------------------------------------
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