Autosnap replication every seccond?

[Glorious1]

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]

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]

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?

 

[dlavigne]

Which FreeNAS version?

 

[Glorious1]

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).

 

[Sneffets]

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

 

[Sneffets]

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...

 

[zamana]

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?

 

[zamana]

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]

Have you figured out what to do about this?

In a way; I just ignore it.