[ENBD] can't write to nb device - nbd_get_req blocking req
John Repass
enbd@lists.community.tummy.com
Fri, 25 Apr 2003 13:02:04 -0600
hi Peter,
I was testing to localhost yesterday because I was trying to rule out a network problem.
After I saw your response I took 2 freshly installed debian woody machines, built and installed the apps and driver again, and successfully ran make test with one of them the server and one the client. Everything appeared to work perfectly.
Then I started the server and client on the same machines like this:
enbd-server 1111 -t 120 -b 1024 -0 -w 10000 -i john /dev/hda8 (on the server machine, poppy)
enbd-client poppy 1111 -n 4 -b 1024 -i john -t 120 -p 5 -d 1 /dev/nda (on the client where I had just run make test)
I used the same options as the clients started by make test.
Then just for the heck of it, before trying anything with nda I ran enbd-test /dev/ndb, which was still up from make test, and everything passed. Then I tried enbd-test /dev/nda, which is the client that I started, and it froze after the second "flushing buffers.." again. I get a similar result trying to make a filesystem.
Seems like an obvious case of user error, but I can't figure out what I'm doing wrong...
here's the output from enbd-test:
-----------------------------
lily:/usr/src/test/nbd-2.4.31# enbd-test /dev/ndb
/dev/ndb has 4194304 bytes in 4096 blocks of 1024 bytes each
flushing buffers..done
writing....5%....10%....15%....20%....25%....30%....35%....40%....45%....50%....55%....60%....65%....70%....75%....80%....85%....90%....95%....done
test 1 succeeded: 0 incorrect blocks
flushing buffers..done
reading....5%....10%....15%....20%....25%....30%....35%....40%....45%....50%....55%....60%....65%....70%....75%....80%....85%....90%....95%....done
test 2 succeeded: 0 incorrect blocks
flushing buffers..done
writing....5%....10%....15%....20%....25%....30%....35%....40%....45%....50%....55%....60%....65%....70%....75%....80%....85%....90%....95%....done
test 3 succeeded: 0 incorrect blocks
flushing buffers..done
reading....5%....10%....15%....20%....25%....30%....35%....40%....45%....50%....55%....60%....65%....70%....75%....80%....85%....90%....95%....done
test 4 succeeded: 0 incorrect blocks
lily:/usr/src/test/nbd-2.4.31# enbd-test /dev/nda
/dev/nda has 435907584 bytes in 425691 blocks of 1024 bytes each
flushing buffers..done
writing....5%....10%....15%....20%....25%....30%....35%....40%....45%....50%....55%....60%....65%....70%....75%....80%....85%....90%....95%....done
test 1 succeeded: 0 incorrect blocks
flushing buffers..
-----------
and it hangs forever.
here is nbdinfo from the client machine:
-----------
Device a: Open
[a] State: signed, rw, merge requests, enabled, validated, plug, acct, last
error 0, lives 0, bp 0
[a] Queued: +0R/41W curr (check 0R/48W) +1R/64W max
[a] Buffersize: 262144 (sectors=512, blocks=256)
[a] Blocksize: 1024 (log=10)
[a] Size: 425691KB
[a] Blocks: 425691
[a] Groups: 1 (0_) (0_) (0_) (0_)
[a] Sockets: 4 (-) (-) (.) (-)
[a] Requested: 217.09K (54.7K) (54.4K) (53.8K) (52.4K) 4R/217.0KW max 34
[a] Despatched: 215.52K (54.7K) (54.4K) (53.8K) (52.4K) 4R/215.5KW md5 2.22KW (0 eq, 2.22K ne, 0 dn)
[a] Errored: 0 (0) (0) (0) (0) 0+0
[a] Pending: 238 (0) (0) (0) (0) 0R/238W+0R/1600W
[a] B/s now: 0 (0R+0W)
[a] B/s ave: 219K (0R+219KW)
[a] B/s max: 7.94M (11.0KR+7.94MW)
[a] Spectrum: 2%2 97%34
[a] Kthreads: 0 (0 waiting/0 running/1 max)
[a] Cthreads: 0 (-) (-) (-) (-)
[a] Cpids: 0 (0) (0) (0) (0)
Device b: Open
[b] State: signed, rw, merge requests, enabled, validated, plug, acct, last
error 0, lives 0, bp 0
[b] Queued: +0R/0W curr (check 0R/0W) +1R/64W max
[b] Buffersize: 262144 (sectors=512, blocks=256)
[b] Blocksize: 1024 (log=10)
[b] Size: 4096KB
[b] Blocks: 4096
[b] Groups: 1 (0) (0) (0) (0)
[b] Sockets: 4 (*) (-) (+) (+)
[b] Requested: 12.011K (2.92K) (3.02K) (3.02K) (3.03K) 12R/12.00KW max 34
[b] Despatched: 12.011K (2.92K) (3.02K) (3.02K) (3.03K) 12R/12.00KW md5 0W (0 eq, 0 ne, 0 dn)
[b] Errored: 0 (0) (0) (0) (0) 0+0
[b] Pending: 0 (0) (0) (0) (0) 0R/0W+0R/0W
[b] B/s now: 0 (0R+0W)
[b] B/s ave: 11.0K (0R+11.0KW)
[b] B/s max: 6.91M (20.0KR+6.89MW)
[b] Spectrum: 2%1 1%4 95%34
[b] Kthreads: 0 (0 waiting/0 running/1 max)
[b] Cthreads: 3 (+) (-) (+) (+)
[b] Cpids: 3 (1655) (0) (1602) (1603)
Device c-p: Closed
----------------
here is a tail of kern.log on the client:
----------------
Apr 25 11:48:45 lily kernel: ENBD enbd.c #3117[3]: nbd_get_req gave up waiting for validation req!
Apr 25 11:48:45 lily kernel: ENBD enbd.c #1689[80]: nbd_rollback rollback req f7e17740, type 0, sector 2, 1 blks, 2 sectors from slot 0!
Apr 25 11:48:46 lily kernel: ENBD enbd.c #3111[113]: nbd_get_req blocking req on
sector 2 while waiting for sector 0!
Apr 25 11:48:46 lily kernel: ENBD enbd.c #3117[4]: nbd_get_req gave up waiting for validation req!
Apr 25 11:48:46 lily kernel: ENBD enbd.c #1689[81]: nbd_rollback rollback req f7e17740, type 0, sector 2, 1 blks, 2 sectors from slot 1!
Apr 25 11:48:46 lily kernel: ENBD enbd.c #3998[20]: repoint_preferred_group no active group, preferring 0
Apr 25 11:48:46 lily kernel: ENBD enbd.c #4001[41]: repoint_preferred_group reset active group to 0
Apr 25 12:05:03 lily kernel: ENBD enbd.c #5181[4]: nbd_soft_reset rollback queue
on slot nda0
Apr 25 12:05:03 lily kernel: ENBD enbd.c #5181[5]: nbd_soft_reset rollback queue
on slot nda1
Apr 25 12:05:03 lily kernel: ENBD enbd.c #5181[6]: nbd_soft_reset rollback queue
on slot nda2
Apr 25 12:05:03 lily kernel: ENBD enbd.c #5181[7]: nbd_soft_reset rollback queue
on slot nda3
Apr 25 12:05:03 lily kernel: ENBD enbd.c #5110[1]: nbd_disable disabled device nda
Apr 25 12:05:03 lily kernel: ENBD enbd.c #3477[61]: nbd_clr_queue unqueued 1 reqsApr 25 12:05:03 lily kernel: ENBD enbd.c #3477[62]: nbd_clr_queue unqueued 1 reqsApr 25 12:05:03 lily kernel: ENBD enbd.c #3477[63]: nbd_clr_queue unqueued 1 reqsApr 25 12:05:03 lily kernel: ENBD enbd.c #3477[64]: nbd_clr_queue unqueued 0 reqsApr 25 12:05:03 lily kernel: ENBD enbd.c #5197[1]: nbd_soft_reset invalidating buffers on device nda
Apr 25 12:05:03 lily kernel: ENBD enbd.c #3586[32720]: do_nbd_request device not
enabled.
Apr 25 12:05:03 lily kernel: ENBD enbd.c #3685[32720]: do_nbd_request ending req
f7e17740 with prejudice
Apr 25 12:05:03 lily kernel: ENBD enbd.c #3586[32721]: do_nbd_request device not
enabled.
Apr 25 12:05:03 lily kernel: ENBD enbd.c #3685[32721]: do_nbd_request ending req
f7e15440 with prejudice
Apr 25 12:05:03 lily kernel: ENBD enbd.c #3586[32722]: do_nbd_request device not
enabled.
Apr 25 12:05:03 lily kernel: ENBD enbd.c #3685[32722]: do_nbd_request ending req
f7e1de40 with prejudice
Apr 25 12:05:03 lily kernel: ENBD enbd.c #3586[32723]: do_nbd_request device not
enabled.
Apr 25 12:05:03 lily kernel: ENBD enbd.c #3685[32723]: do_nbd_request ending req
f7e16120 with prejudice
Apr 25 12:16:47 lily kernel: ENBD enbd.c #8425[0]: nbd_init Network Block Device
support by pavel@elf.mj.gts.cz
Apr 25 12:16:47 lily kernel: ENBD enbd.c #8426[0]: nbd_init Network Block Device
port to 2.0 by ptb@it.uc3m.es
Apr 25 12:16:47 lily kernel: ENBD enbd.c #8428[0]: nbd_init Network Block Device
move networking to user space by amarin@it.uc3m.es
Apr 25 12:16:47 lily kernel: ENBD enbd.c #8430[0]: nbd_init Enhanced Network Block Device 2.4.30 $Date: 2002/10/28 09:41:29 $ by ptb@it.uc3m.es
Apr 25 12:16:47 lily kernel: ENBD enbd.c #8448[0]: nbd_init registered device at
major 43
Apr 25 12:16:47 lily kernel: ENBD enbd.c #1280[0]: nbd_open setup device 1
Apr 25 12:16:52 lily kernel: ENBD enbd.c #4671[0]: nbd_set_sock increased socket
count to 1
Apr 25 12:16:52 lily kernel: ENBD enbd.c #4675[0]: nbd_set_sock increased group count to 1
Apr 25 12:16:52 lily kernel: ENBD enbd.c #4002[0]: repoint_preferred_group reset
active group to 0
Apr 25 12:16:52 lily kernel: ENBD enbd.c #3963[0]: nbd_enable enabled device ndb
Apr 25 12:16:52 lily kernel: ENBD enbd.c #1178[0]: nbd_reread_partitions partition check on device ndb
Apr 25 12:16:52 lily kernel: ndb:<1>ENBD enbd.c #3104[0]: nbd_get_req validation req for sector 0 seen OK!
Apr 25 12:16:52 lily kernel: ENBD enbd.c #4671[1]: nbd_set_sock increased socket
count to 3
Apr 25 12:16:52 lily kernel: ENBD enbd.c #4671[2]: nbd_set_sock increased socket
count to 4
Apr 25 12:17:40 lily kernel: ENBD enbd.c #3999[0]: repoint_preferred_group no active group, preferring 0
Apr 25 12:17:40 lily kernel: ENBD enbd.c #4002[1]: repoint_preferred_group reset
active group to 0
Apr 25 12:18:33 lily kernel: ENBD enbd.c #4002[2]: repoint_preferred_group reset
active group to 0
Apr 25 12:24:21 lily kernel: ENBD enbd.c #1280[1]: nbd_open setup device 0
Apr 25 12:24:26 lily kernel: ENBD enbd.c #4671[3]: nbd_set_sock increased socket
count to 1
Apr 25 12:24:26 lily kernel: ENBD enbd.c #4675[1]: nbd_set_sock increased group count to 1
Apr 25 12:24:26 lily kernel: ENBD enbd.c #4002[3]: repoint_preferred_group reset
active group to 0
Apr 25 12:24:26 lily kernel: ENBD enbd.c #3963[1]: nbd_enable enabled device nda
Apr 25 12:24:26 lily kernel: ENBD enbd.c #1178[1]: nbd_reread_partitions partition check on device nda
Apr 25 12:24:26 lily kernel: nda:<6>ENBD enbd.c #4671[4]: nbd_set_sock increased socket count to 2
Apr 25 12:24:26 lily kernel: ENBD enbd.c #3104[1]: nbd_get_req validation req for sector 0 seen OK!
Apr 25 12:24:26 lily kernel: ENBD enbd.c #4671[5]: nbd_set_sock increased socket
count to 3
Apr 25 12:24:26 lily kernel: ENBD enbd.c #4671[6]: nbd_set_sock increased socket
count to 4
Apr 25 12:25:42 lily kernel: ENBD enbd.c #1690[0]: nbd_rollback rollback req f7e10280, type 1, sector 441540, 34 blks, 68 sectors from slot 0!
Apr 25 12:25:42 lily kernel: ENBD enbd.c #1690[1]: nbd_rollback rollback req f7e10480, type 1, sector 441608, 34 blks, 68 sectors from slot 1!
Apr 25 12:25:42 lily kernel: ENBD enbd.c #1690[2]: nbd_rollback rollback req f7e16d00, type 1, sector 441404, 34 blks, 68 sectors from slot 2!
Apr 25 12:25:42 lily kernel: ENBD enbd.c #1690[3]: nbd_rollback rollback req f7e16f00, type 1, sector 441472, 34 blks, 68 sectors from slot 3!
Apr 25 12:25:56 lily kernel: ENBD enbd.c #2409[0]: nbd_ack ignoring ack of req f7e16d00 which slot does not have
Apr 25 12:26:06 lily kernel: ENBD enbd.c #1690[4]: nbd_rollback rollback req f7e10680, type 1, sector 441676, 34 blks, 68 sectors from slot 2!
Apr 25 12:26:11 lily kernel: ENBD enbd.c #3999[1]: repoint_preferred_group no active group, preferring 0
Apr 25 12:26:11 lily kernel: ENBD enbd.c #4002[4]: repoint_preferred_group reset
active group to 0
Apr 25 12:26:26 lily kernel: ENBD enbd.c #3999[2]: repoint_preferred_group no active group, preferring 0
Apr 25 12:26:26 lily kernel: ENBD enbd.c #4002[5]: repoint_preferred_group reset
active group to 0
Apr 25 12:26:53 lily kernel: ENBD enbd.c #4002[6]: repoint_preferred_group reset
active group to 0
Apr 25 12:26:57 lily kernel: ENBD enbd.c #4002[7]: repoint_preferred_group reset
active group to 0
Apr 25 12:27:03 lily kernel: ENBD enbd.c #1690[5]: nbd_rollback rollback req f7e16f00, type 1, sector 441472, 34 blks, 68 sectors from slot 3!
Apr 25 12:27:23 lily kernel: ENBD enbd.c #3999[3]: repoint_preferred_group no active group, preferring 0
Apr 25 12:27:23 lily kernel: ENBD enbd.c #4002[8]: repoint_preferred_group reset
active group to 0
Apr 25 12:27:32 lily kernel: ENBD enbd.c #4002[9]: repoint_preferred_group reset
active group to 0
Apr 25 12:27:42 lily kernel: ENBD enbd.c #1690[6]: nbd_rollback rollback req f7e16d00, type 1, sector 441404, 34 blks, 68 sectors from slot 2!
Apr 25 12:28:02 lily kernel: ENBD enbd.c #3999[4]: repoint_preferred_group no active group, preferring 0
Apr 25 12:28:02 lily kernel: ENBD enbd.c #4002[10]: repoint_preferred_group reset active group to 0
Apr 25 12:41:52 lily kernel: ENBD enbd.c #7260[0]: nbd_read_proc : altered queued count to 48 from 41
----------
and syslog on the server:
--------------
Apr 25 12:39:05 poppy enbd-server: enbd-server: server (1) sent hello ok
Apr 25 12:39:11 poppy enbd-server: enbd-server: server (3) set default signal handlers for slave server 4295
Apr 25 12:39:11 poppy enbd-server: enbd-server: server (3) opened port 1112 (socket 4) for client 69.20.189.55
Apr 25 12:39:11 poppy enbd-server: enbd-server: server (3) sent hello ok
Apr 25 12:39:18 poppy enbd-server: enbd-server 4319: <#1972> talk_sign Introduction failed: Broken pipe
Apr 25 12:39:23 poppy enbd-server: enbd-server: server (3) set default signal handlers for slave server 4319
Apr 25 12:39:23 poppy enbd-server: enbd-server: server (3) opened port 3034 (socket 4) for client 69.20.189.55
Apr 25 12:39:37 poppy enbd-server: enbd-server: server (1) set default signal handlers for slave server 4294
Apr 25 12:39:37 poppy enbd-server: enbd-server: server (1) opened port 1112 (socket 4) for client 69.20.189.55
Apr 25 12:39:37 poppy enbd-server: enbd-server: server (1) sent hello ok
Apr 25 12:39:42 poppy enbd-server: enbd-server: server (3) set default signal handlers for slave server 4295
Apr 25 12:39:42 poppy enbd-server: enbd-server: server (3) opened port 1112 (socket 4) for client 69.20.189.55
Apr 25 12:39:42 poppy enbd-server: enbd-server: server (3) sent hello ok
Apr 25 12:40:00 poppy enbd-server: enbd-server: server (3) set default signal handlers for slave server 4319
Apr 25 12:40:00 poppy enbd-server: enbd-server: server (3) opened port 3034 (socket 4) for client 69.20.189.55
Apr 25 12:40:10 poppy enbd-server: enbd-server: server (1) set default signal handlers for slave server 4294
Apr 25 12:40:10 poppy enbd-server: enbd-server: server (1) opened port 1112 (socket 4) for client 69.20.189.55
Apr 25 12:40:10 poppy enbd-server: enbd-server: server (1) sent hello ok
Apr 25 12:40:16 poppy enbd-server: enbd-server: server (3) set default signal handlers for slave server 4295
Apr 25 12:40:16 poppy enbd-server: enbd-server: server (3) opened port 1112 (socket 4) for client 69.20.189.55
Apr 25 12:40:16 poppy enbd-server: enbd-server: server (3) sent hello ok
Apr 25 12:40:35 poppy enbd-server: enbd-server: server (3) set default signal handlers for slave server 4319
Apr 25 12:40:35 poppy enbd-server: enbd-server: server (3) opened port 3034 (socket 4) for client 69.20.189.55
Apr 25 12:40:35 poppy enbd-server: enbd-server: server (3) sent hello ok
Apr 25 12:40:35 poppy enbd-server: enbd-server: server (3) sent passwd ok
Apr 25 12:40:35 poppy enbd-server: enbd-server: server (3) got cliserv magic ok
Apr 25 12:40:42 poppy enbd-server: enbd-server: server (1) set default signal handlers for slave server 4294
Apr 25 12:40:42 poppy enbd-server: enbd-server: server (1) opened port 1112 (socket 4) for client 69.20.189.55
Apr 25 12:40:42 poppy enbd-server: enbd-server: server (1) sent hello ok
Apr 25 12:40:48 poppy enbd-server: enbd-server: server (3) set default signal handlers for slave server 4295
Apr 25 12:40:48 poppy enbd-server: enbd-server: server (3) opened port 1112 (socket 4) for client 69.20.189.55
Apr 25 12:40:48 poppy enbd-server: enbd-server: server (3) sent hello ok
Apr 25 12:41:06 poppy enbd-server: enbd-server 4319: <#1972> talk_sign Introduction failed: Broken pipe
Apr 25 12:41:11 poppy enbd-server: enbd-server: server (3) set default signal handlers for slave server 4319
Apr 25 12:41:11 poppy enbd-server: enbd-server: server (3) opened port 3034 (socket 4) for client 69.20.189.55
Apr 25 12:41:22 poppy enbd-server: enbd-server: server (1) set default signal handlers for slave server 4294
Apr 25 12:41:22 poppy enbd-server: enbd-server: server (1) opened port 1112 (socket 4) for client 69.20.189.55
Apr 25 12:41:22 poppy enbd-server: enbd-server: server (1) sent hello ok
Apr 25 12:41:27 poppy enbd-server: enbd-server: server (3) set default signal handlers for slave server 4295
Apr 25 12:41:27 poppy enbd-server: enbd-server: server (3) opened port 1112 (socket 4) for client 69.20.189.55
Apr 25 12:41:27 poppy enbd-server: enbd-server: server (3) sent hello ok
Apr 25 12:41:51 poppy enbd-server: enbd-server: server (3) set default signal handlers for slave server 4319
Apr 25 12:41:51 poppy enbd-server: enbd-server: server (3) opened port 3034 (socket 4) for client 69.20.189.55
Apr 25 12:41:54 poppy enbd-server: enbd-server: server (1) set default signal handlers for slave server 4294
Apr 25 12:41:54 poppy enbd-server: enbd-server: server (1) opened port 1112 (socket 4) for client 69.20.189.55
Apr 25 12:41:54 poppy enbd-server: enbd-server: server (1) sent hello ok
Apr 25 12:42:00 poppy enbd-server: enbd-server: server (3) set default signal handlers for slave server 4295
Apr 25 12:42:00 poppy enbd-server: enbd-server: server (3) opened port 1112 (socket 4) for client 69.20.189.55
Apr 25 12:42:00 poppy enbd-server: enbd-server: server (3) sent hello ok
Apr 25 12:42:29 poppy enbd-server: enbd-server: server (1) set default signal handlers for slave server 4294
Apr 25 12:42:29 poppy enbd-server: enbd-server: server (1) opened port 1112 (socket 4) for client 69.20.189.55
Apr 25 12:42:29 poppy enbd-server: enbd-server: server (1) sent hello ok
Apr 25 12:42:32 poppy enbd-server: enbd-server: server (3) set default signal handlers for slave server 4319
Apr 25 12:42:32 poppy enbd-server: enbd-server: server (3) opened port 3034 (socket 4) for client 69.20.189.55
Apr 25 12:42:35 poppy enbd-server: enbd-server: server (3) set default signal handlers for slave server 4295
Apr 25 12:42:35 poppy enbd-server: enbd-server: server (3) opened port 1112 (socket 4) for client 69.20.189.55
Apr 25 12:42:35 poppy enbd-server: enbd-server: server (3) sent hello ok
Apr 25 12:43:01 poppy enbd-server: enbd-server: server (1) set default signal handlers for slave server 4294
Apr 25 12:43:01 poppy enbd-server: enbd-server: server (1) opened port 1112 (socket 4) for client 69.20.189.55
Apr 25 12:43:01 poppy enbd-server: enbd-server: server (1) sent hello ok
Apr 25 12:43:07 poppy enbd-server: enbd-server: server (3) set default signal handlers for slave server 4295
Apr 25 12:43:07 poppy enbd-server: enbd-server: server (3) opened port 1112 (socket 4) for client 69.20.189.55
Apr 25 12:43:07 poppy enbd-server: enbd-server: server (3) sent hello ok
Apr 25 12:43:09 poppy enbd-server: enbd-server: server (3) set default signal handlers for slave server 4319
Apr 25 12:43:09 poppy enbd-server: enbd-server: server (3) opened port 3034 (socket 4) for client 69.20.189.55
Apr 25 12:43:34 poppy enbd-server: enbd-server: server (1) set default signal handlers for slave server 4294
Apr 25 12:43:34 poppy enbd-server: enbd-server: server (1) opened port 1112 (socket 4) for client 69.20.189.55
Apr 25 12:43:34 poppy enbd-server: enbd-server: server (1) sent hello ok
Apr 25 12:43:39 poppy enbd-server: enbd-server: server (3) set default signal handlers for slave server 4295
Apr 25 12:43:39 poppy enbd-server: enbd-server: server (3) opened port 1112 (socket 4) for client 69.20.189.55
Apr 25 12:43:39 poppy enbd-server: enbd-server: server (3) sent hello ok
Apr 25 12:43:47 poppy enbd-server: enbd-server: server (3) set default signal handlers for slave server 4319
Apr 25 12:43:47 poppy enbd-server: enbd-server: server (3) opened port 3034 (socket 4) for client 69.20.189.55
Apr 25 12:43:47 poppy enbd-server: enbd-server: server (3) sent hello ok
Apr 25 12:43:47 poppy enbd-server: enbd-server: server (3) sent passwd ok
Apr 25 12:43:47 poppy enbd-server: enbd-server: server (3) got cliserv magic ok
--------------
I haven't made the change to shmem.c that you suggested yesterday yet, because I thought I was probably doing something to cause the errors... still do, but I'm not sure what.
Anyway, I'll try that now.
--John