Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

backup.sh seems to mess zfs pool (multiple datasets). #7

Open
pefribeiro opened this issue Jun 11, 2017 · 13 comments
Open

backup.sh seems to mess zfs pool (multiple datasets). #7

pefribeiro opened this issue Jun 11, 2017 · 13 comments

Comments

@pefribeiro
Copy link

pefribeiro commented Jun 11, 2017 •
edited
Loading

Hi,

Thanks for the nice guide. I've followed most of the steps exactly as described, up to the point where I got the initial backup from my FreeNAS installation to an intel NUC running 11.0-RELEASE-p9. I observe that I have more than one dataset, but only one volume.

I then downloaded your script backup.sh, and after executing it a few times eventually the remote system becomes unable to gracefully export the pool. For example:

local@freenas:~ % echo "master@2017-06-11T23:13:19Z" > .sunflower-last-sent 
local@freenas:~ % ./backup.sh snapback
Estimated Size: 47.6M
46.8MiB 0:00:04 [11.6MiB/s] [==============================================================================================================================>   ] 98%            
local@freenas:~ % ./backup.sh snapback
Estimated Size: 30.5K
74.8KiB 0:00:00 [82.2KiB/s] [=================================================================================================================================] 245%            
cannot export 'master': pool is busy
geli: Cannot destroy device da0.eli (error=16).

I've tried changing geli's command not to 'auto-detach' following this report but even then I still get the same issue.

Following a reboot of the target system I then see 'UNAVAIL' for the pool.

root@sunflower:~ # zpool list
NAME     SIZE  ALLOC   FREE  EXPANDSZ   FRAG    CAP  DEDUP  HEALTH  ALTROOT
master      -      -      -         -      -      -      -  UNAVAIL  -

root@sunflower:~ # zpool status
  pool: master
 state: UNAVAIL
status: One or more devices could not be opened.  There are insufficient
	replicas for the pool to continue functioning.
action: Attach the missing device and online it using 'zpool online'.
   see: http://illumos.org/msg/ZFS-8000-3C
  scan: none requested
config:

	NAME                   STATE     READ WRITE CKSUM
	master                 UNAVAIL      0     0     0
	  1568430436390657639  UNAVAIL      0     0     0  was /dev/da0.eli

I then manually copy the key to the target system and ask geli to attach the volume.

It then comes back online:

root@sunflower:~ # zpool status
  pool: master
 state: ONLINE
  scan: none requested
config:

	NAME        STATE     READ WRITE CKSUM
	master      ONLINE       0     0     0
	  da0.eli   ONLINE       0     0     0

However, if I then mount the volume by doing zfs mount master I can then only see the top-level folders corresponding to each of the original datasets, but not any files or folders saved within this zfs volume, which seems to indicate to me that something is seriously messed up.

I then do zfs umount master followed by zpool export master and `zpool import master```. At this point the contents in the datasets are visible again at the mount point.

I am not sure what is causing the problem with the pool becoming 'unexportable' upon the first time altogether. I'm fairly new to ZFS so I would appreciate some guidance as to whether I'm doing something wrong with multiple datasets and your backup.sh script. For reference, here is my current ```zfs-receive.sh`` script:

#!/bin/sh

geli attach -pk /tmp/k /dev/da0
zpool export master 2>/dev/null
zpool import -N master
zfs receive -Fu master
zpool export master
geli detach /dev/da0

Thanks
@hughobrien
Copy link
Owner

hughobrien commented Jun 12, 2017 via email

@pefribeiro
Copy link
Author

Sure, I'm just testing this with random data, no serious issues with real data yet :-)

Regarding the 'snapback' runs, yes, I ran them not that far apart.. so that may be part of the problem, I'm not sure. But again, right now there isn't much data in the pool and I'm doing everything locally over my LAN.

It's just that I still cannot export the pool (no matter how long I wait), unless I reboot the system. I've been Googling around, but haven't found anything quite like this. At some point I started doubting that there could be a problem with the fact I'm using an external USB 3.0 hard-drive for this purpose, but then again, there are no obvious error messages in dmesg to indicate a problem with the controller.

I've also activated AES-NI hardware offloading for geli, but don't suppose that's a source of problems..

Thanks for the quick response at this time of the day, well appreciated :-)

@pefribeiro
Copy link
Author

I've done some further testing and..

root@sunflower:~ # geli attach -pk /tmp/key /dev/da0
root@sunflower:~ # zpool import -N master
root@sunflower:~ # zpool export master
root@sunflower:~ # zpool import -N master
root@sunflower:~ # zpool export master
cannot export 'master': pool is busy
root@sunflower:~ # zpool export master
cannot export 'master': pool is busy
root@sunflower:~ # zpool export master
cannot export 'master': pool is busy
root@sunflower:~ # zpool export master
cannot export 'master': pool is busy
root@sunflower:~ # zpool export -f master
cannot export 'master': pool is busy

I seriously do not know why importing/exporting too often makes it impossible to then export it. Why is FreeBSD having these kinds of issues? Makes me rather worried about the stability of things going forward..

@pefribeiro
Copy link
Author

I have now posted this problem on the FreeBSD forums https://forums.freebsd.org/threads/61291/ because I seem to be getting nowhere while trying to debug this. There aren't any obvious errors in the logs that I can see, and sadly I haven't been able to find anyone with the same problem :(

@pefribeiro
Copy link
Author

pefribeiro commented Jun 13, 2017 •
edited
Loading

Further debugging, if I may.

I decided to try and destroy the pool, and try with it empty, both without and with geli, and things work so far:

root@sunflower:~ # geli attach -pk /tmp/key /dev/da0
root@sunflower:~ # zpool destroy master
root@sunflower:~ # geli detach /dev/da0
root@sunflower:~ # zpool create -O atime=off -O compression=lz4 master da0
root@sunflower:~ # zpool list
NAME     SIZE  ALLOC   FREE  EXPANDSZ   FRAG    CAP  DEDUP  HEALTH  ALTROOT
master  7.25T   320K  7.25T         -     0%     0%  1.00x  ONLINE  -
zroot   51.5G  1.11G  50.4G         -     0%     2%  1.00x  ONLINE  -
root@sunflower:~ # zpool export master
root@sunflower:~ # zpool import master
root@sunflower:~ # zpool export master
root@sunflower:~ # zpool import master
root@sunflower:~ # zpool export master
root@sunflower:~ # zpool import master
root@sunflower:~ # zpool export master
root@sunflower:~ # zpool import master
root@sunflower:~ # zpool export master
root@sunflower:~ # zpool import master
root@sunflower:~ # zpool export master
root@sunflower:~ # zpool import master
root@sunflower:~ # zpool export master
root@sunflower:~ # zpool import master
root@sunflower:~ # zpool destroy master
root@sunflower:~ # geli init -s 4096 -PK /tmp/key /dev/da0

Metadata backup can be found in /var/backups/da0.eli and
can be restored with the following command:

	# geli restore /var/backups/da0.eli /dev/da0

root@sunflower:~ # geli attach -pk /tmp/key /dev/da0
root@sunflower:~ # zpool create -O atime=off -O compression=lz4 master da0.eli
root@sunflower:~ # zpool list
NAME     SIZE  ALLOC   FREE  EXPANDSZ   FRAG    CAP  DEDUP  HEALTH  ALTROOT
master  7.25T   332K  7.25T         -     0%     0%  1.00x  ONLINE  -
zroot   51.5G  1.11G  50.4G         -     0%     2%  1.00x  ONLINE  -
root@sunflower:~ # zpool export master
root@sunflower:~ # zpool import master
root@sunflower:~ # zpool export master
root@sunflower:~ # zpool import master
root@sunflower:~ # zpool export master
root@sunflower:~ # zpool import master
root@sunflower:~ # zpool export master
root@sunflower:~ # zpool import master
root@sunflower:~ # zpool export master
root@sunflower:~ # zpool import master
root@sunflower:~ # zpool export master
root@sunflower:~ # zpool import master
root@sunflower:~ # zpool export master
root@sunflower:~ # zpool import master
root@sunflower:~ # zpool export master
^[[Aroot@sunflower:~ # zpool import master
root@sunflower:~ #

So I then destroyed the pool once more, and created the pool without geli (ie, using da0 directly). I then modify zfs-receive.sh to comment out the geli stuff as follows:

#!/bin/sh

#dd if=/dev/da0 of=/dev/null bs=1m count=3 2>/dev/null
#geli attach -pk /tmp/k /dev/da0
zpool import -N master
zfs receive -Fu master
zpool export master
#geli detach /dev/da0

I then follow your instructions to create a fresh snapshot and send it:


[local@freenas ~]$ snapname="$(date -u '+%FT%TZ')"
[local@freenas ~]$ zfs snapshot -r "master@$snapname"
[local@freenas ~]$ zfs send -Rev "master@$snapname" | ssh sunflower-send
Pseudo-terminal will not be allocated because stdin is not a terminal.
full send of master@2017-06-11T17:43:33Z estimated size is 36.5K
...

Question: I don't suppose the datasets prefixed with '.' such as .system/syslog-530fc3acab424f40b24e1db3a7827a67@2017-06-11T18:54:25Z and the like from FreeNAS mess things up?

I then waited some time as up to 1.26GB were transferred. And following the zfs-receive.sh script at the remote end, the pool was exported successfully first time round. So far so good:

root@sunflower:~ # zpool import -N master
root@sunflower:~ # zpool status
  pool: master
 state: ONLINE
  scan: none requested
config:

	NAME        STATE     READ WRITE CKSUM
	master      ONLINE       0     0     0
	  da0       ONLINE       0     0     0

errors: No known data errors

Also no obvious errors on dmesg or anything suspicious in /var/log/messages:

Jun 13 22:10:28 sunflower ZFS: vdev state changed, pool_guid=13923819482409385151 vdev_guid=7878106175006208276

I then follow with some runs:

root@sunflower:~ # zpool export master
root@sunflower:~ # zpool import -N master
root@sunflower:~ # zpool export master
root@sunflower:~ # zpool import -N master
root@sunflower:~ # zpool export master
root@sunflower:~ # zpool import -N master
root@sunflower:~ # zpool export master
root@sunflower:~ # zpool import -N master
root@sunflower:~ # zpool export master

All good so far. So I now save the latest snapshot identifier to .sunflower-last-sent:

[local@freenas ~]$ echo "master@$snapname" > .sunflower-last-sent

I am now in a position to run backup.sh snapback, which I do and it completes successfully with the pool exported at the remote end!

[local@freenas ~]$ echo "master@$snapname" > .sunflower-last-sent
[local@freenas ~]$ ./backup.sh snapback
Estimated Size: 48.2M
47.5MiB 0:00:04 [  11MiB/s] [=============================================================================================================================================>   ] 98%            
[local@freenas ~]$

I then do:

root@sunflower:~ # zpool import -N master
root@sunflower:~ # zpool list
NAME     SIZE  ALLOC   FREE  EXPANDSZ   FRAG    CAP  DEDUP  HEALTH  ALTROOT
master  7.25T   192M  7.25T         -     0%     0%  1.00x  ONLINE  -
zroot   51.5G  1.11G  50.4G         -     0%     2%  1.00x  ONLINE  -
root@sunflower:~ # zpool export master
cannot export 'master': pool is busy

And.. bang, the problem is back. Now there must be something special about the data received, or how it is received through backup.sh that is causing some issue. Or maybe I'm wrong, I don't know. But for sure, it isn't geli where the problem is.

Next steps I intend to try:

  1. Not using backup.sh, but just issuing the snapshot commands manually.
  2. Somehow fully ruling out problems stemming from the use of an USB3.0 hard-drive, by mouting a volume from a file (can I do this easily?)

Thanks

@pefribeiro
Copy link
Author

Further debugging, part 2.

I went ahead and destroyed the pool at the remote location and recreated it again:

root@sunflower:~ # zpool destroy master
root@sunflower:~ # zpool create -O atime=off -O compression=lz4 master da0
root@sunflower:~ # zpool status
  pool: master
 state: ONLINE
  scan: none requested
config:

	NAME        STATE     READ WRITE CKSUM
	master      ONLINE       0     0     0
	  da0       ONLINE       0     0     0

errors: No known data errors

I then resent the snapshot manually again:

[local@freenas ~]$ rm .sunflower-last-sent 
[local@freenas ~]$ snapname="$(date -u '+%FT%TZ')"
[local@freenas ~]$ zfs snapshot -r "master@$snapname"
[local@freenas ~]$ zfs send -Rev "master@$snapname" | ssh -q sunflower-send
full send of master@2017-06-11T17:43:33Z estimated size is 36.5K
...
(omitted output)

This time I note that I used the parameter -q to ssh, which should not really matter, I think. I waited a while till the transfer completed, and eventually it succeeded with the master pool at the remote location being exported. (Further note: I'm using a drive that supposedly uses SMR technology, but I doubt that should matter based on anecdotal evidence found through Google.)

I then ran my usual sequence of test commands:

root@sunflower:~ # zpool import -N master
root@sunflower:~ # zpool list
NAME     SIZE  ALLOC   FREE  EXPANDSZ   FRAG    CAP  DEDUP  HEALTH  ALTROOT
master  7.25T   201M  7.25T         -     0%     0%  1.00x  ONLINE  -
zroot   51.5G  1.11G  50.4G         -     0%     2%  1.00x  ONLINE  -
root@sunflower:~ # zpool export master
root@sunflower:~ # zpool import -N master
root@sunflower:~ # zpool export master
cannot export 'master': pool is busy
root@sunflower:~ # zpool export master
cannot export 'master': pool is busy

And to my surprise we're bang on the problem again, despite not having used backup.sh.

Further debugging, part 2.
I redid everything as described up to this point in this comment, but omitted -q from the ssh command, and so far I can import/export:

root@sunflower:~ # zpool import -N master
root@sunflower:~ # zpool export master
root@sunflower:~ # zpool import -N master
root@sunflower:~ # zpool export master
root@sunflower:~ # zpool import -N master
root@sunflower:~ # zpool export master
root@sunflower:~ # zpool import master
... (and so on..)

Further debugging, part 3.
I redid everything as in part 2, again omitting the -q, and again import/export works as expected.

Further debugging, part 4.
I redid everything as in part 2, this time using -q as a parameter to ssh and..

root@sunflower:~ # zpool export master
root@sunflower:~ # zpool import master
root@sunflower:~ # zpool export master
cannot export 'master': pool is busy

I cannot ascertain for sure this -q parameter is the source of the problem, but based on the few rounds of testing I've done, it is seeming likely.. and of course I would not know why.

@pefribeiro
Copy link
Author

Further debugging, part 5.

Ok, this problem is now completely arbitrary...

root@sunflower:~ # zpool export master
root@sunflower:~ # zpool import master
^[[A^[[Aroot@sunflower:~ # zpool export master
root@sunflower:~ # zpool import master
root@sunflower:~ # zpool export master
root@sunflower:~ # zpool import master
root@sunflower:~ # zpool export master
root@sunflower:~ # zpool import master
root@sunflower:~ # zpool export master
root@sunflower:~ # zpool import master
root@sunflower:~ # zpool export master
root@sunflower:~ # zpool import master
root@sunflower:~ # zpool export master
root@sunflower:~ # zpool import master
root@sunflower:~ # zpool export master
root@sunflower:~ # zpool import master
root@sunflower:~ # zpool export master
^[[A^[[Aroot@sunflower:~ # zpool import master
^[[A^[[Aroot@sunflower:~ # zpool export master
root@sunflower:~ # zpool import master
root@sunflower:~ # zpool export master
root@sunflower:~ # zpool import master
root@sunflower:~ # zpool export master
root@sunflower:~ # zpool import master
root@sunflower:~ # zpool export master
cannot export 'master': pool is busy
root@sunflower:~ # zpool export master
cannot export 'master': pool is busy

Unless there are any good sources of logging I can tap into then this is becoming increasingly difficult to debug. There is obviously something wrong, somewhere.

@pefribeiro
Copy link
Author

Small update, I've now reproduced this bug on the same machine between my external USB device and a USB stick. It's looking more and more likely to be a bug in FreeBSD.

I wonder if you could help me try and reproduce it on your machine or FreeBSD version?

Thanks

@hughobrien
Copy link
Owner

hughobrien commented Jun 15, 2017 via email

@pefribeiro
Copy link
Author

Hi @hughobrien,

Just to update you, I've now ruled out usb devices as the problem sources. I've created a virtual devices out of files on the same machine, and following a zfs send | zfs recv with the flags like in your guide, I get the "pool is busy" problem. I've tried the sync call but to no avail.

Further details available at: https://forums.freebsd.org/threads/61291/#post-353225

I would very much appreciate if you could confirm whether you can reproduce this issue by following the instructions in my forum post.

Thanks!

@pefribeiro
Copy link
Author

pefribeiro commented Jun 22, 2017 •
edited
Loading

Quick follow up.. to reproduce this bug you need at least two cores, one of which should be mostly idle. I've now reproduced this on a FreeBSD VM (both 11.0-RELEASE and 11.1-BETA-2) on ESXi as well. Both my FreeBSD bug report and the linked forum post contain further details about my set-up (including a testing script).

@hughobrien
Copy link
Owner

Hi there,

I'm just getting back around to updating this project -- did you have any success filing a bug with FreeBSD for the above issue?

Hugh

@pefribeiro
Copy link
Author

Hi Hugh,

I did report it at https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=219972 however there hasn't been much progress, and I myself haven't had time to tinker with the issue again. At the time I narrowed it down to a race condition of sorts, but as I am not familiar with the internals of ZFS nor FreeBSD it became impossible for me to probe further. It would be amazing if someone could take it further :-)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@hughobrien @pefribeiro