Project

General

Profile

Bug #22236

zfsd insanely flooding console and daemon.log

Added by Roland Kletzing over 3 years ago. Updated over 2 years ago.

Status:
Closed
Priority:
No priority
Assignee:
Alexander Motin
Category:
OS
Target version:
Seen in:
Severity:
New
Reason for Closing:
Not Applicable
Reason for Blocked:
Needs QA:
Yes
Needs Doc:
Yes
Needs Merging:
Yes
Needs Automation:
No
Support Suite Ticket:
n/a
Hardware Configuration:
ChangeLog Required:
No

Description

i`m doing a little bit error testing with our freenas by pulling disks out and rebooting etc - and after reboot with one of the sytem + slog/l2arc + hotspare disks pulled (1 hotspare pulled from each of the 2 large pools), console is flooded with messages from zfsd (wih a rate of about 700-800 lines/sec !!!)

i guess i got into a situation zfsd did not expect and which it does not handle well

imho, zfsd is doing wrong here twofoldly:

1. it tries to replace a zil/slog/log device with a hotspare, which zfsd shouldn`t do at all (see https://illumos.org/man/1m/zpool -> Hot Spares -> Spares cannot replace log devices). it does not make sense, anyway - as zil/slog is on a SSD`s partion and the spare disk is an ordinary sas disk which cannot handle the iop`s load anyway.

2. it fails with replacing for any obscure reason, fills daemon.log at insane rate. that fills your root/boot disk quick and makes console unusable. probably this loop also impacts correct function of zfsd (i guess)

from daemon.log :
Mar 15 18:34:50 freenas-bnkw zfsd: CaseFile(14503803357295915280,15547985459888563007,id1,enc@n5003048000aab2fd/type@0/slot@10/elmdesc@Slot_16)
Mar 15 18:34:50 freenas-bnkw zfsd: Vdev State = ONLINE
Mar 15 18:34:50 freenas-bnkw zfsd: Creating new CaseFile:
Mar 15 18:34:50 freenas-bnkw zfsd: CaseFile(14503803357295915280,4415974131613786335,id1,enc@n5003048000aab2fd/type@0/slot@12/elmdesc@Slot_18)
Mar 15 18:34:50 freenas-bnkw zfsd: Vdev State = ONLINE
Mar 15 18:34:50 freenas-bnkw zfsd: Creating new CaseFile:
Mar 15 18:34:50 freenas-bnkw zfsd: CaseFile(6219930425711634761,2393846506341199205,id1,enc@n5003048000aab2fd/type@0/slot@3/elmdesc@Slot_03)
Mar 15 18:34:50 freenas-bnkw zfsd: Vdev State = ONLINE
Mar 15 18:34:50 freenas-bnkw zfsd: CaseFile::ActivateSpare: No spares available for pool freenas-boot
Mar 15 18:34:50 freenas-bnkw zfsd: Replace vdev(zfspool_sas_hitachi/9743223340938606867): cannot replace 9743223340938606867 with /dev/gptid/388dac8b-099c-11e7-9d6d-00259004b150: /dev/gptid/388dac8b-099c-11e7-9d6d-00259004b150 is busy
Mar 15 18:34:50 freenas-bnkw zfsd: Replace vdev(zfspool_sas_seagate/12053336573063160576): cannot replace 12053336573063160576 with /dev/gptid/4f84e3e6-099b-11e7-9d6d-00259004b150: /dev/gptid/4f84e3e6-099b-11e7-9d6d-00259004b150 is busy
Mar 15 18:34:50 freenas-bnkw zfsd: Creating new CaseFile:
Mar 15 18:34:50 freenas-bnkw zfsd: CaseFile(17562155980845608227,691218544469604973,)
Mar 15 18:34:50 freenas-bnkw zfsd: Vdev State = UNAVAIL
Mar 15 18:34:50 freenas-bnkw zfsd: Creating new CaseFile:
Mar 15 18:34:50 freenas-bnkw zfsd: CaseFile(6219930425711634761,9743223340938606867,id1,enc@n5003048000aab2fd/type@0/slot@2/elmdesc@Slot_02)
Mar 15 18:34:50 freenas-bnkw zfsd: Vdev State = UNAVAIL
Mar 15 18:34:50 freenas-bnkw zfsd: Creating new CaseFile:
Mar 15 18:34:50 freenas-bnkw zfsd: CaseFile(14503803357295915280,12053336573063160576,id1,enc@n5003048000aab2fd/type@0/slot@2/elmdesc@Slot_02)
Mar 15 18:34:50 freenas-bnkw zfsd: Vdev State = UNAVAIL
Mar 15 18:34:50 freenas-bnkw zfsd: Creating new CaseFile:
Mar 15 18:34:50 freenas-bnkw zfsd: CaseFile(14503803357295915280,9943536420176618977,id1,enc@n5003048000aab2fd/type@0/slot@11/elmdesc@Slot_17)
Mar 15 18:34:50 freenas-bnkw zfsd: Vdev State = ONLINE
Mar 15 18:34:50 freenas-bnkw zfsd: Creating new CaseFile:
Mar 15 18:34:50 freenas-bnkw zfsd: CaseFile(14503803357295915280,15547985459888563007,id1,enc@n5003048000aab2fd/type@0/slot@10/elmdesc@Slot_16)
Mar 15 18:34:50 freenas-bnkw zfsd: Vdev State = ONLINE
Mar 15 18:34:50 freenas-bnkw zfsd: Creating new CaseFile:
Mar 15 18:34:50 freenas-bnkw zfsd: CaseFile(14503803357295915280,4415974131613786335,id1,enc@n5003048000aab2fd/type@0/slot@12/elmdesc@Slot_18)
Mar 15 18:34:50 freenas-bnkw zfsd: Vdev State = ONLINE
Mar 15 18:34:50 freenas-bnkw zfsd: Creating new CaseFile:
Mar 15 18:34:50 freenas-bnkw zfsd: CaseFile(6219930425711634761,2393846506341199205,id1,enc@n5003048000aab2fd/type@0/slot@3/elmdesc@Slot_03)
Mar 15 18:34:50 freenas-bnkw zfsd: Vdev State = ONLINE
Mar 15 18:34:50 freenas-bnkw zfsd: CaseFile::ActivateSpare: No spares available for pool freenas-boot
Mar 15 18:34:50 freenas-bnkw zfsd: Replace vdev(zfspool_sas_hitachi/9743223340938606867): cannot replace 9743223340938606867 with /dev/gptid/388dac8b-099c-11e7-9d6d-00259004b150: /dev/gptid/388dac8b-099c-11e7-9d6d-00259004b150 is busy
Mar 15 18:34:51 freenas-bnkw zfsd: Replace vdev(zfspool_sas_seagate/12053336573063160576): cannot replace 12053336573063160576 with /dev/gptid/4f84e3e6-099b-11e7-9d6d-00259004b150: /dev/gptid/4f84e3e6-099b-11e7-9d6d-00259004b150 is busy
Mar 15 18:34:51 freenas-bnkw zfsd: Creating new CaseFile:
Mar 15 18:34:51 freenas-bnkw zfsd: CaseFile(17562155980845608227,691218544469604973,)
Mar 15 18:34:51 freenas-bnkw zfsd: Vdev State = UNAVAIL
Mar 15 18:34:51 freenas-bnkw zfsd: Creating new CaseFile:
Mar 15 18:34:51 freenas-bnkw zfsd: CaseFile(6219930425711634761,9743223340938606867,id1,enc@n5003048000aab2fd/type@0/slot@2/elmdesc@Slot_02)
Mar 15 18:34:51 freenas-bnkw zfsd: Vdev State = UNAVAIL
Mar 15 18:34:51 freenas-bnkw zfsd: Creating new CaseFile:
Mar 15 18:34:51 freenas-bnkw zfsd: CaseFile(14503803357295915280,12053336573063160576,id1,enc@n5003048000aab2fd/type@0/slot@2/elmdesc@Slot_02)
Mar 15 18:34:51 freenas-bnkw zfsd: Vdev State = UNAVAIL
Mar 15 18:34:51 freenas-bnkw zfsd: Creating new CaseFile:
Mar 15 18:34:51 freenas-bnkw zfsd: CaseFile(14503803357295915280,9943536420176618977,id1,enc@n5003048000aab2fd/type@0/slot@11/elmdesc@Slot_17)
Mar 15 18:34:51 freenas-bnkw zfsd: Vdev State = ONLINE
Mar 15 18:34:51 freenas-bnkw zfsd: Creating new CaseFile:
Mar 15 18:34:51 freenas-bnkw zfsd: CaseFile(14503803357295915280,15547985459888563007,id1,enc@n5003048000aab2fd/type@0/slot@10/elmdesc@Slot_16)
Mar 15 18:34:51 freenas-bnkw zfsd: Vdev State = ONLINE
Mar 15 18:34:51 freenas-bnkw zfsd: Creating new CaseFile:
Mar 15 18:34:51 freenas-bnkw zfsd: CaseFile(14503803357295915280,4415974131613786335,id1,enc@n5003048000aab2fd/type@0/slot@12/elmdesc@Slot_18)
Mar 15 18:34:51 freenas-bnkw zfsd: Vdev State = ONLINE
Mar 15 18:34:51 freenas-bnkw zfsd: Creating new CaseFile:
Mar 15 18:34:51 freenas-bnkw zfsd: CaseFile(6219930425711634761,2393846506341199205,id1,enc@n5003048000aab2fd/type@0/slot@3/elmdesc@Slot_03)
Mar 15 18:34:51 freenas-bnkw zfsd: Vdev State = ONLINE
Mar 15 18:34:51 freenas-bnkw zfsd: CaseFile::ActivateSpare: No spares available for pool freenas-boot
Mar 15 18:34:51 freenas-bnkw zfsd: Replace vdev(zfspool_sas_hitachi/9743223340938606867): cannot replace 9743223340938606867 with /dev/gptid/388dac8b-099c-11e7-9d6d-00259004b150: /dev/gptid/388dac8b-099c-11e7-9d6d-00259004b150 is busy
Mar 15 18:34:51 freenas-bnkw zfsd: Replace vdev(zfspool_sas_seagate/12053336573063160576): cannot replace 12053336573063160576 with /dev/gptid/4f84e3e6-099b-11e7-9d6d-00259004b150: /dev/gptid/4f84e3e6-099b-11e7-9d6d-00259004b150 is busy

zpool list:

pool: freenas-boot
state: DEGRADED
status: One or more devices could not be opened. Sufficient replicas exist for
the pool to continue functioning in a degraded state.
action: Attach the missing device and online it using 'zpool online'.
see: http://illumos.org/msg/ZFS-8000-2Q
scan: resilvered 328K in 0h0m with 0 errors on Tue Mar 14 17:30:26 2017
config:
NAME                                            STATE     READ WRITE CKSUM
freenas-boot DEGRADED 0 0 0
mirror-0 DEGRADED 0 0 0
gptid/d5b0d697-e94b-11e6-9474-00259004b150 ONLINE 0 0 0
691218544469604973 UNAVAIL 0 0 0 was /dev/gptid/d5c0f0f8-e94b-11e6-9474-00259004b150

errors: No known data errors

pool: zfspool_sas_hitachi
state: DEGRADED
status: One or more devices could not be opened. Sufficient replicas exist for
the pool to continue functioning in a degraded state.
action: Attach the missing device and online it using 'zpool online'.
see: http://illumos.org/msg/ZFS-8000-2Q
scan: resilvered 32K in 0h0m with 0 errors on Wed Mar 15 17:50:52 2017
config:
NAME                                            STATE     READ WRITE CKSUM
zfspool_sas_hitachi DEGRADED 0 0 0
raidz2-0 ONLINE 0 0 0
gptid/b5bc61ca-099b-11e7-9d6d-00259004b150 ONLINE 0 0 0
gptid/b650715b-099b-11e7-9d6d-00259004b150 ONLINE 0 0 0
gptid/b6e71524-099b-11e7-9d6d-00259004b150 ONLINE 0 0 0
gptid/b7759cd4-099b-11e7-9d6d-00259004b150 ONLINE 0 0 0
gptid/b80b116d-099b-11e7-9d6d-00259004b150 ONLINE 0 0 0
gptid/b8a2d7f6-099b-11e7-9d6d-00259004b150 ONLINE 0 0 0
gptid/b933b599-099b-11e7-9d6d-00259004b150 ONLINE 0 0 0
gptid/b9c57444-099b-11e7-9d6d-00259004b150 ONLINE 0 0 0
gptid/ba593c4d-099b-11e7-9d6d-00259004b150 ONLINE 0 0 0
logs
mirror-1 DEGRADED 0 0 0
gptid/713f0662-ee27-11e6-a3b4-00259004b150 ONLINE 0 0 0
9743223340938606867 UNAVAIL 0 0 0 was /dev/gptid/78d3e971-ee27-11e6-a3b4-00259004b150
cache
gptid/50dbad5b-eed4-11e6-8a4a-00259004b150 ONLINE 0 0 0
11557186469487774318 UNAVAIL 0 0 0 was /dev/gptid/57769a1c-eed4-11e6-8a4a-00259004b150
spares
1717188731560675162 UNAVAIL was /dev/gptid/f9e3afff-099b-11e7-9d6d-00259004b150
gptid/388dac8b-099c-11e7-9d6d-00259004b150 AVAIL

errors: No known data errors

pool: zfspool_sas_seagate
state: DEGRADED
status: One or more devices could not be opened. Sufficient replicas exist for
the pool to continue functioning in a degraded state.
action: Attach the missing device and online it using 'zpool online'.
see: http://illumos.org/msg/ZFS-8000-2Q
scan: resilvered 32K in 0h0m with 0 errors on Wed Mar 15 17:50:53 2017
config:
NAME                                            STATE     READ WRITE CKSUM
zfspool_sas_seagate DEGRADED 0 0 0
raidz2-0 ONLINE 0 0 0
gptid/d915dce8-0999-11e7-9d6d-00259004b150 ONLINE 0 0 0
gptid/d9d1f0c2-0999-11e7-9d6d-00259004b150 ONLINE 0 0 0
gptid/dada16ec-0999-11e7-9d6d-00259004b150 ONLINE 0 0 0
gptid/db9d874a-0999-11e7-9d6d-00259004b150 ONLINE 0 0 0
gptid/dc60117b-0999-11e7-9d6d-00259004b150 ONLINE 0 0 0
gptid/dd1ef267-0999-11e7-9d6d-00259004b150 ONLINE 0 0 0
gptid/dde37740-0999-11e7-9d6d-00259004b150 ONLINE 0 0 0
gptid/dea19f5b-0999-11e7-9d6d-00259004b150 ONLINE 0 0 0
gptid/df62fd8c-0999-11e7-9d6d-00259004b150 ONLINE 0 0 0
logs
mirror-1 DEGRADED 0 0 0
gptid/98bdd972-ee27-11e6-a3b4-00259004b150 ONLINE 0 0 0
12053336573063160576 UNAVAIL 0 0 0 was /dev/gptid/9d75100f-ee27-11e6-a3b4-00259004b150
cache
gptid/704a70ee-eed4-11e6-8a4a-00259004b150 ONLINE 0 0 0
18159011032197161 UNAVAIL 0 0 0 was /dev/gptid/73e8d996-eed4-11e6-8a4a-00259004b150
spares
16538455031075281410 UNAVAIL was /dev/gptid/0c2e4b51-099b-11e7-9d6d-00259004b150
gptid/4f84e3e6-099b-11e7-9d6d-00259004b150 AVAIL

errors: No known data errors

History

#1 Avatar?id=14398&size=24x24 Updated by Kris Moore over 3 years ago

  • Assignee set to Alexander Motin
  • Target version set to 9.10.4

#2 Updated by Alexander Motin over 3 years ago

  • Status changed from Unscreened to Screened

I've seen this bug, but it needs deep investigation, for which I can't find time/bravery.

#3 Avatar?id=14398&size=24x24 Updated by Kris Moore over 3 years ago

  • Target version changed from 9.10.4 to 11.1

#4 Updated by Alexander Motin almost 3 years ago

  • Target version changed from 11.1 to 11.2-BETA1

#5 Avatar?id=14398&size=24x24 Updated by Kris Moore over 2 years ago

  • Target version changed from 11.2-BETA1 to 11.3

#6 Avatar?id=14398&size=24x24 Updated by Kris Moore over 2 years ago

  • Status changed from Screened to Not Started

#7 Avatar?id=13649&size=24x24 Updated by Ben Gadd over 2 years ago

  • Target version changed from 11.3 to Backlog

#8 Avatar?id=13649&size=24x24 Updated by Ben Gadd over 2 years ago

  • Severity set to New

#9 Updated by Dru Lavigne over 2 years ago

  • Status changed from Not Started to Closed
  • Target version changed from Backlog to N/A
  • Reason for Closing set to Not Applicable

Roland: we are closing this ticket for now as there have been many ZFS improvements in the 11.1 series which should resolve this issue, with even more improvements coming in the 11.2-BETA1 (due out in a few weeks). If you are still experiencing this issue in 11.1-U4 or in 11.2-BETA1 (once it is out), please attach a debug from the updated system to this ticket.

Also available in: Atom PDF