aaronadams
Dabbler
- Joined
- Apr 17, 2014
- Messages
- 23
At some point, replication stopped between my two FreeNAS devices.
I decided that to begin with, I would try to delete the existing replication task and then create a new one with matching parameters.
So I tried deleting the replication task, which hung the interface, and now my logs are under attack:
It's been going on like that for quite some time (half hour at least). I'll let you know if the replication task actually deletes when it's all said and done.
I'm guessing that's a candidate for improvement.
Then, on the subject of the actual replication failure, here's some sample logs showing my snapshots as well as (I think) my failing replication:
If anybody can help me to determine what the heck is going on here, it would be much appreciated! I really don't understand the "cannot hold snapshot" error message, especially why it would be trying to hold a different four-days-old snapshot each time.
I decided that to begin with, I would try to delete the existing replication task and then create a new one with matching parameters.
So I tried deleting the replication task, which hung the interface, and now my logs are under attack:
Code:
Jul 23 13:02:34 freenas notifier: cannot release hold from snapshot 'storage/.system/cores@auto-20140722.1930-1y': no such tag on this dataset Jul 23 13:02:34 freenas notifier: cannot release hold from snapshot 'storage/.system/cores@auto-20140722.1945-1y': no such tag on this dataset Jul 23 13:02:34 freenas notifier: cannot release hold from snapshot 'storage/.system/cores@auto-20140722.2000-1y': no such tag on this dataset Jul 23 13:02:34 freenas notifier: cannot release hold from snapshot 'storage/.system/cores@auto-20140722.2015-1y': no such tag on this dataset Jul 23 13:02:35 freenas notifier: cannot release hold from snapshot 'storage/.system/cores@auto-20140722.2030-1y': no such tag on this dataset Jul 23 13:02:35 freenas notifier: cannot release hold from snapshot 'storage/.system/cores@auto-20140722.2045-1y': no such tag on this dataset Jul 23 13:02:35 freenas notifier: cannot release hold from snapshot 'storage/.system/cores@auto-20140722.2100-1y': no such tag on this dataset Jul 23 13:02:35 freenas notifier: cannot release hold from snapshot 'storage/.system/cores@auto-20140722.2115-1y': no such tag on this dataset Jul 23 13:02:35 freenas notifier: cannot release hold from snapshot 'storage/.system/cores@auto-20140722.2130-1y': no such tag on this dataset Jul 23 13:02:36 freenas notifier: cannot release hold from snapshot 'storage/.system/cores@auto-20140722.2145-1y': no such tag on this dataset Jul 23 13:02:36 freenas notifier: cannot release hold from snapshot 'storage/.system/cores@auto-20140722.2200-1y': no such tag on this dataset Jul 23 13:02:36 freenas notifier: cannot release hold from snapshot 'storage/.system/cores@auto-20140722.2215-1y': no such tag on this dataset Jul 23 13:02:36 freenas notifier: cannot release hold from snapshot 'storage/.system/cores@auto-20140722.2230-1y': no such tag on this dataset Jul 23 13:02:37 freenas notifier: cannot release hold from snapshot 'storage/.system/cores@auto-20140722.2245-1y': no such tag on this dataset Jul 23 13:02:37 freenas notifier: cannot release hold from snapshot 'storage/.system/cores@auto-20140722.2300-1y': no such tag on this dataset Jul 23 13:02:37 freenas notifier: cannot release hold from snapshot 'storage/.system/cores@auto-20140722.2315-1y': no such tag on this dataset Jul 23 13:02:37 freenas notifier: cannot release hold from snapshot 'storage/.system/cores@auto-20140722.2330-1y': no such tag on this dataset Jul 23 13:02:38 freenas notifier: cannot release hold from snapshot 'storage/.system/cores@auto-20140722.2345-1y': no such tag on this dataset Jul 23 13:02:38 freenas notifier: cannot release hold from snapshot 'storage/.system/cores@auto-20140723.0000-1y': no such tag on this dataset Jul 23 13:02:38 freenas notifier: cannot release hold from snapshot 'storage/.system/cores@auto-20140723.0015-1y': no such tag on this dataset Jul 23 13:02:38 freenas notifier: cannot release hold from snapshot 'storage/.system/cores@auto-20140723.0030-1y': no such tag on this dataset Jul 23 13:02:39 freenas notifier: cannot release hold from snapshot 'storage/.system/cores@auto-20140723.0045-1y': no such tag on this dataset Jul 23 13:02:39 freenas notifier: cannot release hold from snapshot 'storage/.system/cores@auto-20140723.0100-1y': no such tag on this dataset Jul 23 13:02:39 freenas notifier: cannot release hold from snapshot 'storage/.system/cores@auto-20140723.0115-1y': no such tag on this dataset Jul 23 13:02:39 freenas notifier: cannot release hold from snapshot 'storage/.system/cores@auto-20140723.0130-1y': no such tag on this dataset Jul 23 13:02:39 freenas notifier: cannot release hold from snapshot 'storage/.system/cores@auto-20140723.0145-1y': no such tag on this dataset Jul 23 13:02:40 freenas notifier: cannot release hold from snapshot 'storage/.system/cores@auto-20140723.0200-1y': no such tag on this dataset Jul 23 13:02:40 freenas notifier: cannot release hold from snapshot 'storage/.system/cores@auto-20140723.0215-1y': no such tag on this dataset Jul 23 13:02:40 freenas notifier: cannot release hold from snapshot 'storage/.system/cores@auto-20140723.0230-1y': no such tag on this dataset Jul 23 13:02:40 freenas notifier: cannot release hold from snapshot 'storage/.system/cores@auto-20140723.0245-1y': no such tag on this dataset Jul 23 13:02:41 freenas notifier: cannot release hold from snapshot 'storage/.system/cores@auto-20140723.0300-1y': no such tag on this dataset Jul 23 13:02:41 freenas notifier: cannot release hold from snapshot 'storage/.system/cores@auto-20140723.0315-1y': no such tag on this dataset
It's been going on like that for quite some time (half hour at least). I'll let you know if the replication task actually deletes when it's all said and done.
I'm guessing that's a candidate for improvement.
Then, on the subject of the actual replication failure, here's some sample logs showing my snapshots as well as (I think) my failing replication:
Code:
Jul 22 05:30:10 freenas autosnap.py: [tools.autosnap:58] Popen()ing: /sbin/zfs snapshot -r -o freenas:state=NEW storage@auto-20140722.0530-1y Jul 22 05:30:10 freenas autosnap.py: [tools.autosnap:58] Popen()ing: /sbin/zfs hold -r freenas:repl storage@auto-20140722.0530-1y Jul 22 05:45:10 freenas autosnap.py: [tools.autosnap:58] Popen()ing: /sbin/zfs snapshot -r -o freenas:state=NEW storage@auto-20140722.0545-1y Jul 22 05:45:11 freenas autosnap.py: [tools.autosnap:58] Popen()ing: /sbin/zfs hold -r freenas:repl storage@auto-20140722.0545-1y Jul 22 05:47:38 freenas autorepl.py: [common.pipesubr:58] Popen()ing: /usr/bin/ssh -c arcfour256,arcfour128,blowfish-cbc,aes128-ctr,aes192-ctr,aes256-ctr -i /data/ssh/replication -o BatchMode=yes -o StrictHostKeyChecking=yes -o ConnectTimeout=7 -p 22 192.168.0.211 "zfs list -Hr -o name -t snapshot -d 1 storage/remote | tail -n 1 | cut -d@ -f2" Jul 22 05:47:39 freenas autorepl.py: [common.pipesubr:72] Executing: /usr/bin/ssh -c arcfour256,arcfour128,blowfish-cbc,aes128-ctr,aes192-ctr,aes256-ctr -i /data/ssh/replication -o BatchMode=yes -o StrictHostKeyChecking=yes -o ConnectTimeout=7 -p 22 192.168.0.211 "/sbin/zfs inherit freenas:state storage/remote@auto-20140717.1930-1y" Jul 22 05:47:39 freenas autorepl.py: [common.pipesubr:72] Executing: /sbin/zfs inherit freenas:state storage@auto-20140717.1915-1y Jul 22 05:47:39 freenas autorepl.py: [common.pipesubr:72] Executing: /sbin/zfs release -r freenas:repl storage@auto-20140717.1915-1y Jul 22 05:47:39 freenas autorepl.py: [common.pipesubr:72] Executing: /sbin/zfs set freenas:state=LATEST storage@auto-20140717.1930-1y Jul 22 05:47:39 freenas autorepl.py: [common.pipesubr:72] Executing: /sbin/zfs hold -r freenas:repl storage@auto-20140717.1930-1y Jul 22 05:47:39 freenas common.pipesubr: cannot hold snapshot 'storage@auto-20140717.1930-1y': tag already exists on this dataset Jul 22 06:00:12 freenas autosnap.py: [tools.autosnap:58] Popen()ing: /sbin/zfs snapshot -r -o freenas:state=NEW storage@auto-20140722.0600-1y Jul 22 06:00:12 freenas autosnap.py: [tools.autosnap:58] Popen()ing: /sbin/zfs hold -r freenas:repl storage@auto-20140722.0600-1y Jul 22 06:15:11 freenas autosnap.py: [tools.autosnap:58] Popen()ing: /sbin/zfs snapshot -r -o freenas:state=NEW storage@auto-20140722.0615-1y Jul 22 06:15:11 freenas autosnap.py: [tools.autosnap:58] Popen()ing: /sbin/zfs hold -r freenas:repl storage@auto-20140722.0615-1y Jul 22 06:30:11 freenas autosnap.py: [tools.autosnap:58] Popen()ing: /sbin/zfs snapshot -r -o freenas:state=NEW storage@auto-20140722.0630-1y Jul 22 06:30:11 freenas autosnap.py: [tools.autosnap:58] Popen()ing: /sbin/zfs hold -r freenas:repl storage@auto-20140722.0630-1y Jul 22 06:32:52 freenas autorepl.py: [common.pipesubr:58] Popen()ing: /usr/bin/ssh -c arcfour256,arcfour128,blowfish-cbc,aes128-ctr,aes192-ctr,aes256-ctr -i /data/ssh/replication -o BatchMode=yes -o StrictHostKeyChecking=yes -o ConnectTimeout=7 -p 22 192.168.0.211 "zfs list -Hr -o name -t snapshot -d 1 storage/remote | tail -n 1 | cut -d@ -f2" Jul 22 06:32:53 freenas autorepl.py: [common.pipesubr:72] Executing: /usr/bin/ssh -c arcfour256,arcfour128,blowfish-cbc,aes128-ctr,aes192-ctr,aes256-ctr -i /data/ssh/replication -o BatchMode=yes -o StrictHostKeyChecking=yes -o ConnectTimeout=7 -p 22 192.168.0.211 "/sbin/zfs inherit freenas:state storage/remote@auto-20140717.1945-1y" Jul 22 06:32:53 freenas autorepl.py: [common.pipesubr:72] Executing: /sbin/zfs inherit freenas:state storage@auto-20140717.1930-1y Jul 22 06:32:53 freenas autorepl.py: [common.pipesubr:72] Executing: /sbin/zfs release -r freenas:repl storage@auto-20140717.1930-1y Jul 22 06:32:54 freenas autorepl.py: [common.pipesubr:72] Executing: /sbin/zfs set freenas:state=LATEST storage@auto-20140717.1945-1y Jul 22 06:32:54 freenas autorepl.py: [common.pipesubr:72] Executing: /sbin/zfs hold -r freenas:repl storage@auto-20140717.1945-1y Jul 22 06:32:54 freenas common.pipesubr: cannot hold snapshot 'storage@auto-20140717.1945-1y': tag already exists on this dataset Jul 22 06:45:11 freenas autosnap.py: [tools.autosnap:58] Popen()ing: /sbin/zfs snapshot -r -o freenas:state=NEW storage@auto-20140722.0645-1y Jul 22 06:45:11 freenas autosnap.py: [tools.autosnap:58] Popen()ing: /sbin/zfs hold -r freenas:repl storage@auto-20140722.0645-1y
If anybody can help me to determine what the heck is going on here, it would be much appreciated! I really don't understand the "cannot hold snapshot" error message, especially why it would be trying to hold a different four-days-old snapshot each time.