FreeBSD 8.1 and HAST

[Mikolaj Golub]

On Sun, 13 Jun 2010 12:24:01 +0200 Pawel Jakub Dawidek wrote:

 >> Jun 13 16:25:37 sv01A hastd: [zfshast] (primary) Header contains no 'seq' field.

 PJD> This is the most important bit from the primary node.

 PJD> The header either does not contain 'seq' field or this field is 0. It
 PJD> can only be 0 if you have old kernel. With recent kernel geom_gate.ko
 PJD> was modified to start seq at 1, so this should not happen.

I am a bit confused how this seq is supposed to work. For sync thread. I have
set up hast on 8-STABLE (before I used it on 9-CURRENT only) and have the same
issue as hiroshi@ does. I have added 

 pjdlog_debug(2, "remote_send: seq is %llu.", (uint64_t)ggio->gctl_seq);

after 

 nv_add_uint64(nv, (uint64_t)ggio->gctl_seq, "seq");

in primary/remote_send thread and observe the following:

Jun 14 00:12:54 zhuzha hastd: [storage] (primary) Unable to receive reply header: Resource temporarily unavailable.
Jun 14 00:12:54 zhuzha kernel: Jun 14 00:12:54 zhuzha hastd: [storage] (primary) Unable to receive reply header: Resource temporarily unavailable.
Jun 14 00:12:54 zhuzha hastd: [storage] (primary) Closing old incoming connection to tcp4://192.168.120.6.
Jun 14 00:12:54 zhuzha hastd: [storage] (primary) Closing old outgoing connection to tcp4://192.168.120.6.
Jun 14 00:12:54 zhuzha hastd: [storage] (primary) remote_recv: No requests, waiting.
Jun 14 00:12:54 zhuzha hastd: [storage] (primary) remote_guard: Checking connections.
Jun 14 00:12:54 zhuzha hastd: [storage] (primary) remote_guard: Reconnecting to tcp4://192.168.120.6.
Jun 14 00:12:54 zhuzha hastd: [storage] (primary) Unable to write synchronization data: Invalid argument.
Jun 14 00:12:54 zhuzha kernel: Jun 14 00:12:54 zhuzha hastd: [storage] (primary) Unable to write synchronization data: Invalid argument.
Jun 14 00:12:54 zhuzha hastd: [storage] (primary) sync: (0x284f0080) Moving request to the free queue.
Jun 14 00:12:54 zhuzha hastd: [storage] (primary) Connected to tcp4://192.168.120.6.
Jun 14 00:12:54 zhuzha hastd: [storage] (primary) Successfully reconnected to tcp4://192.168.120.6.
Jun 14 00:12:54 zhuzha hastd: [storage] (primary) Synchronization started. 10485760 bytes to go.
Jun 14 00:12:54 zhuzha hastd: [storage] (primary) sync: Taking free request.
Jun 14 00:12:54 zhuzha hastd: [storage] (primary) sync: (0x284f0040) Got free request.
Jun 14 00:12:54 zhuzha hastd: [storage] (primary) sync: (0x284f0040) Sending sync request: READ(0, 131072).
Jun 14 00:12:54 zhuzha hastd: [storage] (primary) sync: (0x284f0040) Moving request to the send queue.
Jun 14 00:12:54 zhuzha hastd: [storage] (primary) local_send: (0x284f0040) Got request.
Jun 14 00:12:54 zhuzha hastd: [storage] (primary) local_send: Taking request.
Jun 14 00:12:54 zhuzha hastd: [storage] (primary) sync: (0x284f0040) Sending sync request: WRITE(0, 131072).
Jun 14 00:12:54 zhuzha hastd: [storage] (primary) sync: (0x284f0040) Moving request to the send queue.
Jun 14 00:12:54 zhuzha hastd: [storage] (primary) sync: (0x284f0040) Moving request to the send queues.
Jun 14 00:12:54 zhuzha hastd: [storage] (primary) remote_send: (0x284f0040) Got request.
Jun 14 00:12:54 zhuzha hastd: [storage] (primary) remote_send: seq is 0.
Jun 14 00:12:54 zhuzha hastd: [storage] (primary) remote_send: (0x284f0040) Moving request to the recv queue.
Jun 14 00:12:54 zhuzha hastd: [storage] (primary) remote_send: Taking request.
Jun 14 00:12:54 zhuzha hastd: [storage] (primary) Header contains no 'seq' field.
Jun 14 00:12:54 zhuzha kernel: Jun 14 00:12:54 zhuzha hastd: [storage] (primary) Header contains no 'seq' field.

This lasts for some time (usually more then a half of a hour) and at some
moment seq is set to 1 (but one time I saw when it was set to 19) and after
this sychroniztion to secondary starts to work (seq is increasing by one for
the next request).

Jun 14 00:29:23 zhuzha hastd: [storage] (primary) Unable to receive reply header: Resource tempor
arily unavailable.
Jun 14 00:29:23 zhuzha kernel: Jun 14 00:29:23 zhuzha hastd: [storage] (primary) Unable to receiv
e reply header: Resource temporarily unavailable.
Jun 14 00:29:23 zhuzha hastd: [storage] (primary) Closing old incoming connection to tcp4://192.1
68.120.6.
Jun 14 00:29:23 zhuzha hastd: [storage] (primary) Closing old outgoing connection to tcp4://192.1
68.120.6.
Jun 14 00:29:23 zhuzha hastd: [storage] (primary) remote_recv: No requests, waiting.
Jun 14 00:29:23 zhuzha hastd: [storage] (primary) remote_guard: Checking connections.
Jun 14 00:29:23 zhuzha hastd: [storage] (primary) remote_guard: Reconnecting to tcp4://192.168.12
0.6.
Jun 14 00:29:23 zhuzha hastd: [storage] (primary) Unable to write synchronization data: Invalid a
rgument.
Jun 14 00:29:23 zhuzha kernel: Jun 14 00:29:23 zhuzha hastd: [storage] (primary) Unable to write 
synchronization data: Invalid argument.
Jun 14 00:29:23 zhuzha hastd: [storage] (primary) sync: (0x28441580) Moving request to the free q
ueue.
Jun 14 00:29:23 zhuzha hastd: [storage] (primary) Connected to tcp4://192.168.120.6.
Jun 14 00:29:23 zhuzha hastd: [storage] (primary) Successfully reconnected to tcp4://192.168.120.
6.
Jun 14 00:29:23 zhuzha hastd: [storage] (primary) Synchronization started. 10485760 bytes to go.
Jun 14 00:29:23 zhuzha hastd: [storage] (primary) sync: Taking free request.
Jun 14 00:29:23 zhuzha hastd: [storage] (primary) sync: (0x284f1640) Got free request.
Jun 14 00:29:23 zhuzha hastd: [storage] (primary) sync: (0x284f1640) Sending sync request: READ(0
, 131072).
Jun 14 00:29:23 zhuzha hastd: [storage] (primary) sync: (0x284f1640) Moving request to the send q
ueue.
Jun 14 00:29:23 zhuzha hastd: [storage] (primary) local_send: (0x284f1640) Got request.
Jun 14 00:29:23 zhuzha hastd: [storage] (primary) local_send: Taking request.
Jun 14 00:29:23 zhuzha hastd: [storage] (primary) sync: (0x284f1640) Sending sync request: WRITE(
0, 131072).
Jun 14 00:29:23 zhuzha hastd: [storage] (primary) sync: (0x284f1640) Moving request to the send q
ueue.
Jun 14 00:29:23 zhuzha hastd: [storage] (primary) sync: (0x284f1640) Moving request to the send q
ueues.
Jun 14 00:29:23 zhuzha hastd: [storage] (primary) remote_send: (0x284f1640) Got request.
Jun 14 00:29:23 zhuzha hastd: [storage] (primary) remote_send: seq is 1.
Jun 14 00:29:23 zhuzha hastd: [storage] (primary) remote_send: (0x284f1640) Moving request to the recv queue.
Jun 14 00:29:23 zhuzha hastd: [storage] (primary) remote_send: Taking request.
Jun 14 00:29:24 zhuzha hastd: [storage] (primary) remote_recv: No requests, waiting.
Jun 14 00:29:24 zhuzha hastd: [storage] (primary) sync: (0x284f1640) Moving request to the free queue.
Jun 14 00:29:24 zhuzha hastd: [storage] (primary) sync: Taking free request.
Jun 14 00:29:24 zhuzha hastd: [storage] (primary) sync: (0x284f15c0) Got free request.
Jun 14 00:29:24 zhuzha hastd: [storage] (primary) sync: (0x284f15c0) Sending sync request: READ(131072, 131072).
Jun 14 00:29:24 zhuzha hastd: [storage] (primary) sync: (0x284f15c0) Moving request to the send queue.
Jun 14 00:29:24 zhuzha hastd: [storage] (primary) local_send: (0x284f15c0) Got request.
Jun 14 00:29:24 zhuzha hastd: [storage] (primary) local_send: Taking request.
Jun 14 00:29:24 zhuzha hastd: [storage] (primary) sync: (0x284f15c0) Sending sync request: WRITE(131072, 131072).
Jun 14 00:29:24 zhuzha hastd: [storage] (primary) sync: (0x284f15c0) Moving request to the send queue.
Jun 14 00:29:24 zhuzha hastd: [storage] (primary) sync: (0x284f15c0) Moving request to the send queues.
Jun 14 00:29:24 zhuzha hastd: [storage] (primary) remote_send: (0x284f15c0) Got request.
Jun 14 00:29:24 zhuzha hastd: [storage] (primary) remote_send: seq is 2.
Jun 14 00:29:24 zhuzha hastd: [storage] (primary) remote_send: (0x284f15c0) Moving request to the recv queue.
...

Adding seq logging on CURRENT I observe seq having the same value 2779096485 (0xa5a5a5a5): 

Jun 14 03:35:45 lolek hastd: [test] (primary) remote_send: (0x287f44c0) Got request.
Jun 14 03:35:45 lolek hastd: [test] (primary) remote_send: seq is 2779096485.
Jun 14 03:35:45 lolek hastd: [test] (primary) remote_send: (0x287f44c0) Moving request to the recv queue.

So it looks like seq is just contents of unitialized memory and this works
under CURRENT only because memory is initialized to 0xa5 by malloc here.

This test program returns "*p is 0xa5a5a5a5" under my CURRENT and "*p is 0x0"
under 8-STABLE.

#include <err.h>
#include <stdio.h>
#include <stdlib.h>

int
main(int argc, char *argv[])
{
        unsigned long *p;

        p = malloc(sizeof(*p));
        if (p == NULL)
                err(1,"malloc failed");
        printf ("*p is 0x%lx\n", *p);

        return 0;
}

-- 
Mikolaj Golub