"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).
----------------------------------------------------------------------
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