Register for the iXsystems Community to get an ad-free experience and exclusive discounts in our eBay Store.

Autosnap replication every seccond?

Glorious1

FreeNAS Guru
Joined
Nov 23, 2014
Messages
906
Thanks
165
#1
Is it normal to have Autosnap replication going every second of every day? I have replication scheduled to occur only during one 15-minute period per day. Here's what I get in /var/log/debug.log:

Code:
May  4 12:31:11 Tabernacle /autorepl.py: [tools.autorepl:221] Autosnap replication started
May  4 12:31:11 Tabernacle /autorepl.py: [tools.autorepl:222] temp log file: /tmp/repl-92885
May  4 12:31:11 Tabernacle /autorepl.py: [tools.autorepl:627] Autosnap replication finished
May  4 12:32:11 Tabernacle /autorepl.py: [tools.autorepl:221] Autosnap replication started
May  4 12:32:11 Tabernacle /autorepl.py: [tools.autorepl:222] temp log file: /tmp/repl-93077
May  4 12:32:11 Tabernacle /autorepl.py: [tools.autorepl:627] Autosnap replication finished
May  4 12:33:11 Tabernacle /autorepl.py: [tools.autorepl:221] Autosnap replication started
May  4 12:33:11 Tabernacle /autorepl.py: [tools.autorepl:222] temp log file: /tmp/repl-93256
May  4 12:33:11 Tabernacle /autorepl.py: [tools.autorepl:627] Autosnap replication finished
May  4 12:34:11 Tabernacle /autorepl.py: [tools.autorepl:221] Autosnap replication started
May  4 12:34:11 Tabernacle /autorepl.py: [tools.autorepl:222] temp log file: /tmp/repl-93716
May  4 12:34:11 Tabernacle /autorepl.py: [tools.autorepl:627] Autosnap replication finished
May  4 12:35:11 Tabernacle /autorepl.py: [tools.autorepl:221] Autosnap replication started
May  4 12:35:11 Tabernacle /autorepl.py: [tools.autorepl:222] temp log file: /tmp/repl-93904
May  4 12:35:11 Tabernacle /autorepl.py: [tools.autorepl:627] Autosnap replication finished
 

sretalla

FreeNAS Expert
Joined
Jan 1, 2016
Messages
1,116
Thanks
294
#2
I think it's checking for changes to the data (probably doing a snapshot to current dataset comparison) and mostly deciding not to do anything.

I'm not sure about the cost of that (CPU/RAM/IOs), so can't comment if that's too much, but the gut feeling is that it may be. Just to be clear, that log shows that it's every minute, not every second.
 

Glorious1

FreeNAS Guru
Joined
Nov 23, 2014
Messages
906
Thanks
165
#3
Just to be clear, that log shows that it's every minute, not every second.
Oh right, about the minute vs. second.
I guess my specific question should have been, does everyone have this in their debug.log, even when no snapshots are scheduled?
 

Glorious1

FreeNAS Guru
Joined
Nov 23, 2014
Messages
906
Thanks
165
#5
I'm in FreeNAS-11.2-U3. Can't update to U4 at the moment (not that it doesn't work; I've just got a long process going that I don't want to interrupt).
 
Joined
Mar 8, 2017
Messages
21
Thanks
2
#6
I am getting the same "issue" on FreeNAS-11.2-U4.1...the Periodic Snapshot Tasks run and are being created, but the Replication Tasks won't start...I can/have manually zfs send the snapshots over for my backup FreeNAS running the same version. I even deleted all fo the Replication Tasks and started over...initially they showed Status = Waiting, then just went blank. The Replication Task should be sending - DataVault/Files_0_F Anyone figure out what the deal is? Any additional logs I can/should look at?

Jun 24 15:50:03 freenas /autorepl.py: [tools.autorepl:291] Checking dataset DataVault/Files_0_F
Jun 24 15:50:06 freenas usbhid-ups[3514]: libusb_get_interrupt: Unknown error
Jun 24 15:50:33 freenas usbhid-ups[3514]: libusb_get_interrupt: Unknown error
Jun 24 15:50:54 freenas usbhid-ups[3514]: libusb_get_interrupt: Unknown error
Jun 24 15:51:00 freenas usbhid-ups[3514]: libusb_get_interrupt: Unknown error
Jun 24 15:51:03 freenas /autorepl.py: [tools.autorepl:172] Checking if process 63277 is still alive
Jun 24 15:51:03 freenas /autorepl.py: [tools.autorepl:179] Process 63277 gone
Jun 24 15:51:03 freenas /autorepl.py: [tools.autorepl:221] Autosnap replication started
Jun 24 15:51:03 freenas /autorepl.py: [tools.autorepl:222] temp log file: /tmp/repl-63408
Jun 24 15:51:03 freenas /autorepl.py: [tools.autorepl:291] Checking dataset DataVault/Files_0_F
Jun 24 15:51:21 freenas usbhid-ups[3514]: libusb_get_interrupt: Unknown error
Jun 24 15:51:27 freenas usbhid-ups[3514]: libusb_get_interrupt: Unknown error
Jun 24 15:51:54 freenas usbhid-ups[3514]: libusb_get_interrupt: Unknown error
Jun 24 15:52:03 freenas /autorepl.py: [tools.autorepl:172] Checking if process 63408 is still alive
Jun 24 15:52:03 freenas /autorepl.py: [tools.autorepl:179] Process 63408 gone
Jun 24 15:52:03 freenas /autorepl.py: [tools.autorepl:221] Autosnap replication started
Jun 24 15:52:03 freenas /autorepl.py: [tools.autorepl:222] temp log file: /tmp/repl-63545
Jun 24 15:52:03 freenas /autorepl.py: [tools.autorepl:291] Checking dataset DataVault/Files_0_F
Jun 24 15:52:21 freenas usbhid-ups[3514]: libusb_get_interrupt: Unknown error
Jun 24 15:52:27 freenas usbhid-ups[3514]: libusb_get_interrupt: Unknown error
Jun 24 15:52:54 freenas usbhid-ups[3514]: libusb_get_interrupt: Unknown error
Jun 24 15:53:02 freenas /autorepl.py: [tools.autorepl:172] Checking if process 63545 is still alive
Jun 24 15:53:02 freenas /autorepl.py: [tools.autorepl:179] Process 63545 gone
Jun 24 15:53:02 freenas /autorepl.py: [tools.autorepl:221] Autosnap replication started
Jun 24 15:53:02 freenas /autorepl.py: [tools.autorepl:222] temp log file: /tmp/repl-64324
Jun 24 15:53:02 freenas /autorepl.py: [tools.autorepl:627] Autosnap replication finished
Jun 24 15:53:21 freenas usbhid-ups[3514]: libusb_get_interrupt: Unknown error
Jun 24 15:53:27 freenas usbhid-ups[3514]: libusb_get_interrupt: Unknown error
Jun 24 15:53:48 freenas usbhid-ups[3514]: libusb_get_interrupt: Unknown error
Jun 24 15:53:54 freenas usbhid-ups[3514]: libusb_get_interrupt: Unknown error
Jun 24 15:54:00 freenas usbhid-ups[3514]: libusb_get_interrupt: Unknown error
Jun 24 15:54:03 freenas /autorepl.py: [tools.autorepl:221] Autosnap replication started
Jun 24 15:54:03 freenas /autorepl.py: [tools.autorepl:222] temp log file: /tmp/repl-65101
Jun 24 15:54:03 freenas /autorepl.py: [tools.autorepl:627] Autosnap replication finished
Jun 24 15:54:27 freenas usbhid-ups[3514]: libusb_get_interrupt: Unknown error
Jun 24 15:55:00 freenas usbhid-ups[3514]: libusb_get_interrupt: Unknown error
Jun 24 15:55:02 freenas /autorepl.py: [tools.autorepl:221] Autosnap replication started
Jun 24 15:55:02 freenas /autorepl.py: [tools.autorepl:222] temp log file: /tmp/repl-65256
Jun 24 15:55:02 freenas /autorepl.py: [tools.autorepl:627] Autosnap replication finished
Jun 24 15:55:33 freenas usbhid-ups[3514]: libusb_get_interrupt: Unknown error
Jun 24 15:55:39 freenas usbhid-ups[3514]: libusb_get_interrupt: Unknown error
Jun 24 15:56:03 freenas /autorepl.py: [tools.autorepl:221] Autosnap replication started
Jun 24 15:56:03 freenas /autorepl.py: [tools.autorepl:222] temp log file: /tmp/repl-65573
Jun 24 15:56:03 freenas /autorepl.py: [tools.autorepl:627] Autosnap replication finished
Jun 24 15:56:06 freenas usbhid-ups[3514]: libusb_get_interrupt: Unknown error
Jun 24 15:56:12 freenas usbhid-ups[3514]: libusb_get_interrupt: Unknown error
Jun 24 15:56:33 freenas usbhid-ups[3514]: libusb_get_interrupt: Unknown error
Jun 24 15:56:39 freenas usbhid-ups[3514]: libusb_get_interrupt: Unknown error
Jun 24 15:56:45 freenas usbhid-ups[3514]: libusb_get_interrupt: Unknown error
Jun 24 15:57:03 freenas /autorepl.py: [tools.autorepl:221] Autosnap replication started
Jun 24 15:57:03 freenas /autorepl.py: [tools.autorepl:222] temp log file: /tmp/repl-65708
Jun 24 15:57:03 freenas /autorepl.py: [tools.autorepl:627] Autosnap replication finished
Jun 24 15:57:12 freenas usbhid-ups[3514]: libusb_get_interrupt: Unknown error
Jun 24 15:57:45 freenas usbhid-ups[3514]: libusb_get_interrupt: Unknown error
Jun 24 15:57:51 freenas usbhid-ups[3514]: libusb_get_interrupt: Unknown error
Jun 24 15:58:02 freenas /autorepl.py: [tools.autorepl:221] Autosnap replication started
Jun 24 15:58:02 freenas /autorepl.py: [tools.autorepl:222] temp log file: /tmp/repl-65836
Jun 24 15:58:03 freenas /autorepl.py: [tools.autorepl:627] Autosnap replication finished
Jun 24 15:58:18 freenas usbhid-ups[3514]: libusb_get_interrupt: Unknown error
Jun 24 15:58:24 freenas usbhid-ups[3514]: libusb_get_interrupt: Unknown error
Jun 24 15:58:51 freenas usbhid-ups[3514]: libusb_get_interrupt: Unknown error
Jun 24 15:59:02 freenas /autorepl.py: [tools.autorepl:221] Autosnap replication started
Jun 24 15:59:02 freenas /autorepl.py: [tools.autorepl:222] temp log file: /tmp/repl-65964
Jun 24 15:59:02 freenas /autorepl.py: [tools.autorepl:627] Autosnap replication finished
Jun 24 15:59:18 freenas usbhid-ups[3514]: libusb_get_interrupt: Unknown error
Jun 24 16:00:03 freenas /autorepl.py: [tools.autorepl:221] Autosnap replication started
Jun 24 16:00:03 freenas /autorepl.py: [tools.autorepl:222] temp log file: /tmp/repl-66116
Jun 24 16:00:03 freenas /autorepl.py: [tools.autorepl:291] Checking dataset DataVault/Files_0_F
Jun 24 16:00:39 freenas usbhid-ups[3514]: libusb_get_interrupt: Unknown error
Jun 24 16:00:45 freenas usbhid-ups[3514]: libusb_get_interrupt: Unknown error
Jun 24 16:01:02 freenas /autorepl.py: [tools.autorepl:172] Checking if process 66116 is still alive
Jun 24 16:01:02 freenas /autorepl.py: [tools.autorepl:179] Process 66116 gone
Jun 24 16:01:02 freenas /autorepl.py: [tools.autorepl:221] Autosnap replication started
Jun 24 16:01:02 freenas /autorepl.py: [tools.autorepl:222] temp log file: /tmp/repl-66464
Jun 24 16:01:02 freenas /autorepl.py: [tools.autorepl:291] Checking dataset DataVault/Files_0_F
Jun 24 16:01:12 freenas usbhid-ups[3514]: libusb_get_interrupt: Unknown error
Jun 24 16:01:33 freenas usbhid-ups[3514]: libusb_get_interrupt: Unknown error
Jun 24 16:01:39 freenas usbhid-ups[3514]: libusb_get_interrupt: Unknown error
Jun 24 16:02:02 freenas /autorepl.py: [tools.autorepl:172] Checking if process 66464 is still alive
Jun 24 16:02:02 freenas /autorepl.py: [tools.autorepl:179] Process 66464 gone
Jun 24 16:02:02 freenas /autorepl.py: [tools.autorepl:221] Autosnap replication started
Jun 24 16:02:02 freenas /autorepl.py: [tools.autorepl:222] temp log file: /tmp/repl-66618
Jun 24 16:02:02 freenas /autorepl.py: [tools.autorepl:291] Checking dataset DataVault/Files_0_F
Jun 24 16:02:06 freenas usbhid-ups[3514]: libusb_get_interrupt: Unknown error
Jun 24 16:02:12 freenas usbhid-ups[3514]: libusb_get_interrupt: Unknown error
Jun 24 16:02:39 freenas usbhid-ups[3514]: libusb_get_interrupt: Unknown error
Jun 24 16:03:03 freenas /autorepl.py: [tools.autorepl:172] Checking if process 66618 is still alive
Jun 24 16:03:03 freenas /autorepl.py: [tools.autorepl:179] Process 66618 gone
Jun 24 16:03:03 freenas /autorepl.py: [tools.autorepl:221] Autosnap replication started
Jun 24 16:03:03 freenas /autorepl.py: [tools.autorepl:222] temp log file: /tmp/repl-66768
Jun 24 16:03:03 freenas /autorepl.py: [tools.autorepl:291] Checking dataset DataVault/Files_0_F
Jun 24 16:03:12 freenas usbhid-ups[3514]: libusb_get_interrupt: Unknown error
 
Last edited:
Joined
Mar 8, 2017
Messages
21
Thanks
2
#7
Figured it out...I ended up deleting all of the replication tasks..and starting over, entering the tokens from the backup server...and they all worked...so it must have been a Remote Hostkey issue...
 
Joined
Jun 4, 2017
Messages
52
Thanks
3
#8
Hi!

I don't know if this is related, but I realized recently that my CPU gets hot every 10 minutes or so, something like from 29C to 43C. When this happens, that's what I got from logs, in a typical situation:

Code:
debug.log:Jul 30 18:09:01 freenas /autorepl.py: [tools.autorepl:221] Autosnap replication started
debug.log:Jul 30 18:09:01 freenas /autorepl.py: [tools.autorepl:222] temp log file: /tmp/repl-29918
debug.log:Jul 30 18:09:01 freenas /autorepl.py: [tools.autorepl:639] Autosnap replication finished
debug.log:Jul 30 18:09:41 freenas sudo:  netdata : TTY=unknown ; PWD=/etc/local/netdata ; USER=root ; COMMAND=/etc/find_alias_for_smtplib.sh -t -f freenas@local -F 'Charlie Root '
debug.log:Jul 30 18:09:42 freenas /find_alias_for_smtplib.py: [urllib3.connectionpool:208] Starting new HTTP connection (1): localhost
debug.log:Jul 30 18:09:42 freenas /find_alias_for_smtplib.py: [urllib3.connectionpool:396] http://localhost:6000 "POST /_upload?auth_token=11b12ac3-9cda-4ded-82cb-ee304c57cf00 HTTP/1.1" 200 16


System/Hardware:
FreeNAS-11.2-U5, on a SuperMicro X11SSL-CF with a Xeon E3-1245 v5, 32GB ECC RAM.

Is this OK?
 
Joined
Jun 4, 2017
Messages
52
Thanks
3
#9
Oh right, about the minute vs. second.
I guess my specific question should have been, does everyone have this in their debug.log, even when no snapshots are scheduled?
Yes, I have.

Code:
Jul 31 21:16:02 freenas /autorepl.py: [tools.autorepl:639] Autosnap replication finished
Jul 31 21:17:01 freenas /autorepl.py: [tools.autorepl:221] Autosnap replication started
Jul 31 21:17:01 freenas /autorepl.py: [tools.autorepl:222] temp log file: /tmp/repl-11121
Jul 31 21:17:01 freenas /autorepl.py: [tools.autorepl:639] Autosnap replication finished
Jul 31 21:18:01 freenas /autorepl.py: [tools.autorepl:221] Autosnap replication started
Jul 31 21:18:01 freenas /autorepl.py: [tools.autorepl:222] temp log file: /tmp/repl-11656
Jul 31 21:18:01 freenas /autorepl.py: [tools.autorepl:639] Autosnap replication finished
Jul 31 21:19:01 freenas /autorepl.py: [tools.autorepl:221] Autosnap replication started
Jul 31 21:19:01 freenas /autorepl.py: [tools.autorepl:222] temp log file: /tmp/repl-12175
Jul 31 21:19:01 freenas /autorepl.py: [tools.autorepl:639] Autosnap replication finished



Have you figured out what to do about this?

Thanks.
 

Glorious1

FreeNAS Guru
Joined
Nov 23, 2014
Messages
906
Thanks
165
#10
Top