Weird enbd failure while updating md superblock

Hi all,

Lately, one of my RAID5-arrays on top of ENBD ran out of sync, causing
it to run in degraded mode (2 of 3 disks available). No problem, of
course, I just hotadded the third device (ndc) again and a resync was
initiated. However, this resync failed while updating the md superblock
on one of the up-and-running devices. From the clientside syslog:

> Jun 13 04:00:12 localhost kernel: ENBD #1163[0]: enbd_rollback (0):
> rollback req c3bc7b8c!
> Jun 13 04:00:12 localhost kernel: ENBD #1163[1]: enbd_rollback (1):
> rollback req c41f65ec!
> Jun 13 04:00:12 localhost kernel: ENBD #1163[2]: enbd_rollback (2):
> rollback req ced2404c!
> Jun 13 04:00:12 localhost kernel: ENBD #1163[3]: enbd_rollback (3):
> rollback req c419f04c!
> Jun 13 04:00:31 localhost enbd-client: enbd-netserver  3127: # 161
> recv_reply: stream read of 131072 bytes returned -110
> Jun 13 04:00:31 localhost enbd-client: enbd-netserver  3127: # 514
> net_read: net_read (1) exits FAIL
> Jun 13 04:00:31 localhost enbd-client: enbd-client  3127: #1654
> handle_server_cmd_err:  (1) cmd failed Input/output error on
> 10.1.0.2:1102 so clear socket
> Jun 13 04:00:31 localhost enbd-client: enbd-client  3127: # 162
> unplug: requested unplug (1) Input/output error on 10.1.0.2:1102 so
> clear socket
> Jun 13 04:00:31 localhost enbd-client: enbd-netserver  3128: # 161
> recv_reply: stream read of 131072 bytes returned -110
> Jun 13 04:00:31 localhost enbd-client: enbd-netserver  3128: # 514
> net_read: net_read (2) exits FAIL
> Jun 13 04:00:31 localhost enbd-client: enbd-client  3128: #1654
> handle_server_cmd_err:  (2) cmd failed Input/output error on
> 10.1.0.2:1102 so clear socket
> Jun 13 04:00:31 localhost enbd-client: enbd-client  3128: # 162
> unplug: requested unplug (2) Input/output error on 10.1.0.2:1102 so
> clear socket
> Jun 13 04:00:31 localhost enbd-client: enbd-netserver  3126: # 161
> recv_reply: stream read of 131072 bytes returned -110
> Jun 13 04:00:31 localhost enbd-client: enbd-netserver  3126: # 514
> net_read: net_read (0) exits FAIL
> Jun 13 04:00:31 localhost enbd-client: enbd-client  3126: #1654
> handle_server_cmd_err:  (0) cmd failed Input/output error on
> 10.1.0.2:1102 so clear socket
> Jun 13 04:00:31 localhost enbd-client: enbd-client  3126: # 162
> unplug: requested unplug (0) Input/output error on 10.1.0.2:1102 so
> clear socket
> Jun 13 04:00:31 localhost enbd-client: enbd-netserver  3129: # 161
> recv_reply: stream read of 131072 bytes returned -110
> Jun 13 04:00:31 localhost enbd-client: enbd-netserver  3129: # 514
> net_read: net_read (3) exits FAIL
> Jun 13 04:00:31 localhost enbd-client: enbd-client  3129: #1654
> handle_server_cmd_err:  (3) cmd failed Input/output error on
> 10.1.0.2:1102 so clear socket
> Jun 13 04:00:31 localhost enbd-client: enbd-client  3129: # 162
> unplug: requested unplug (3) Input/output error on 10.1.0.2:1102 so
> clear socket
> Jun 13 04:00:31 localhost kernel: ENBD #3356[6]: enbd_soft_reset
> DISABLE DEVICE ndb
> Jun 13 04:00:31 localhost kernel: ENBD #3278[4]:
> enbd_disable_and_notify disabled device ndb
> Jun 13 04:00:31 localhost kernel: ENBD #3358[6]: enbd_soft_reset CLEAR
> QUEUE DEVICE ndb
> Jun 13 04:00:31 localhost kernel: raid5: Disk failure on ndb,
> disabling device. Operation continuing on 1 devices



And from the serverside logs (note that the time is not synchronized!):

> Jun 13 04:01:50 localhost enbd-server: enbd-server  4334: #1962
> newproto: (ERROR) net errored (header 128 got 0) on req. Breaking off.
> Jun 13 04:01:51 localhost enbd-server: enbd-server  4335: #1962
> newproto: (ERROR) net errored (header 128 got 0) on req. Breaking off.
> Jun 13 04:01:51 localhost enbd-server: enbd-server  4334: #2236
> mainloop: (ERROR) Server time out waiting 30s in mainloop. Breaking off
> Jun 13 04:01:51 localhost enbd-server: enbd-server  4335: #2236
> mainloop: (ERROR) Server time out waiting 30s in mainloop. Breaking off
> Jun 13 04:01:51 localhost enbd-server: enbd-server  4333: #1962
> newproto: (ERROR) net errored (header 128 got 0) on req. Breaking off.
> Jun 13 04:01:51 localhost enbd-server: nbd/alarm  4336: # 150
> unchain_current_ualarm: signalling ALRM for late (0.000000s) alarm
> 0xbffff9e0 of 30.000000s
> Jun 13 04:01:51 localhost enbd-server: enbd-server  4336: #2236
> mainloop: (ERROR) Server time out waiting 30s in mainloop. Breaking off
> Jun 13 04:01:51 localhost enbd-server: enbd-server  4333: #2236
> mainloop: (ERROR) Server time out waiting 30s in mainloop. Breaking off
> Jun 13 04:01:59 localhost enbd-server: enbd-server  4334: #1190
> slavesighandler: (WARNING) server (1) activates slave sighandler for
> signal 15
> Jun 13 04:02:00 localhost enbd-server: enbd-server: server (1)
> sighandler terminates slave 4334 safely
> Jun 13 04:02:00 localhost enbd-server: enbd-server  4335: #1190
> slavesighandler: (WARNING) server (2) activates slave sighandler for
> signal 15
> Jun 13 04:02:00 localhost enbd-server: enbd-server: server (2)
> sighandler terminates slave 4335 safely
> Jun 13 04:02:00 localhost enbd-server: enbd-server: server (-1)
> session relaunches child after SIGCHLD
> Jun 13 04:02:00 localhost enbd-server: enbd-server: server (-1) slave
> pid 4334 is down, launching new
> Jun 13 04:02:00 localhost enbd-server: enbd-server: server (1) set
> default signal handlers
> Jun 13 04:02:00 localhost enbd-server: enbd-server: server (-1)
> launched slave pid 4361
> Jun 13 04:02:00 localhost enbd-server: enbd-server: server (-1)
> session relaunches child after SIGCHLD
> Jun 13 04:02:00 localhost enbd-server: enbd-server: server (-1) slave
> pid 4335 is down, launching new
> Jun 13 04:02:00 localhost enbd-server: enbd-server: server (2) set
> default signal handlers
> Jun 13 04:02:00 localhost enbd-server: enbd-server: server (-1)
> launched slave pid 4362
> Jun 13 04:02:00 localhost enbd-server: enbd-server  4333: #1190
> slavesighandler: (WARNING) server (0) activates slave sighandler for
> signal 15
> Jun 13 04:02:00 localhost enbd-server: enbd-server: server (0)
> sighandler terminates slave 4333 safely
> Jun 13 04:02:00 localhost enbd-server: enbd-server: server (-1)
> session relaunches child after SIGCHLD
> Jun 13 04:02:00 localhost enbd-server: enbd-server: server (-1) slave
> pid 4333 is down, launching new
> Jun 13 04:02:00 localhost enbd-server: enbd-server: server (0) set
> default signal handlers
> Jun 13 04:02:00 localhost enbd-server: enbd-server: server (-1)
> launched slave pid 4363
> Jun 13 04:02:01 localhost enbd-server: enbd-server  4336: #1190
> slavesighandler: (WARNING) server (3) activates slave sighandler for
> signal 15
> Jun 13 04:02:01 localhost enbd-server: enbd-server: server (3)
> sighandler terminates slave 4336 safely
> Jun 13 04:02:01 localhost enbd-server: enbd-server: server (-1)
> session relaunches child after SIGCHLD
> Jun 13 04:02:01 localhost enbd-server: enbd-server: server (-1) slave
> pid 4336 is down, launching new
> Jun 13 04:02:01 localhost enbd-server: enbd-server: server (3) set
> default signal handlers
> Jun 13 04:02:01 localhost enbd-server: enbd-server: server (-1)
> launched slave pid 4364
> Jun 13 04:03:59 localhost enbd-server: enbd-server  4361: #3131
> negotiate: (ERROR) Server timed out in negotiate

Time currently seems to differ about 1m10s.

Currently I'm running a new resync (hdc and ndb are in-sync, ndc
out-of-sync), I'll report any problems back to the list. Does anyone
have any idea what could be the cause of this? Currently, this setup is
just a "backup of a backup", but it should be stable... By the way: I'm
using the semi-latest 2.4.33pre, which is stable on another "cluster".

-- Bas