guermantes
Patron
- Joined
- Sep 27, 2017
- Messages
- 213
Edit2: bugfixed in 11.3-U1. I have not yet installed to verify it works my end, but it should.
Edit: seems autosnap is involved, see bottom of this post
Here is a weird thing: a ghost inside my box is making copies of my snapshot tasks. This is how it started.
A month after I upgraded from 11.2-U3 to 11.3, I discovered that two of my legacy periodic snapshot tasks were refusing to run like their friends. No matter what I did I could not get them to run at all, so I decided to start afresh. I deleted all replication tasks and all snapshots on my system and then yesterday recreated some of the periodic snapshot tasks. During a few test snaps I noted that the naming schema mechanism would not automatically add the retention time to the end of the snapshot name, so I created my tasks simply adding the retention time suffix string myself ("-1M"). This morning the new tasks (no old tasks were left on the system) have run during the night at 02.00 for the first time and when I check if all is okay I see this:
My new defined tasks have run at 02.00 AM. But some shadow d(a)emon has made snaps of the same datasets at 04.15 AM, and it has added the retention time suffix as well ("-1m") but not used the suffix string I specified. Before I started afresh, I had more tasks snapping other datasets in a similar manner at 02.00. But I am only getting mysterious 04.15 replicas of the tasks I have recreated. None of my previous snapshot tasks were set to run at 04.15.
What is going on?
These are the settings I have used. The ones that are pending only run on Sundays.
middlewared.log:
What is autosnap up to?
cron:
Edit: seems autosnap is involved, see bottom of this post
Here is a weird thing: a ghost inside my box is making copies of my snapshot tasks. This is how it started.
A month after I upgraded from 11.2-U3 to 11.3, I discovered that two of my legacy periodic snapshot tasks were refusing to run like their friends. No matter what I did I could not get them to run at all, so I decided to start afresh. I deleted all replication tasks and all snapshots on my system and then yesterday recreated some of the periodic snapshot tasks. During a few test snaps I noted that the naming schema mechanism would not automatically add the retention time to the end of the snapshot name, so I created my tasks simply adding the retention time suffix string myself ("-1M"). This morning the new tasks (no old tasks were left on the system) have run during the night at 02.00 for the first time and when I check if all is okay I see this:
Code:
root@freenas:~ # zfs list -t snapshot NAME USED AVAIL REFER MOUNTPOINT TANK/dev@auto-20200303-02.00-1M 0 - 9.57G - TANK/dev@auto-20200303.0415-1m 0 - 9.57G - TANK/foto@auto-20200303-02.00-1M 0 - 249G - TANK/foto@auto-20200303.0415-1m 0 - 249G - TANK/hibou@auto-20200303-02.00-1M 0 - 18.7G - TANK/hibou@auto-20200303.0415-1m 0 - 18.7G - TANK/home@auto-20200303-02.00-1M 0 - 94.3G - TANK/home@auto-20200303.0415-1m 0 - 94.3G - TANK/iocage/jails/nextcloud/root@auto-20200303-02.00-1M 559K - 1.47G - TANK/iocage/jails/nextcloud/root@auto-20200303.0415-1m 416K - 1.48G - TANK/iocage/jails/webdev/root@auto-20200303-02.00-1M 13.8M - 1.00G - TANK/iocage/jails/webdev/root@auto-20200303.0415-1m 424K - 1.00G - TANK/iocage/releases/11.2-RELEASE/root@webdev 16.0K - 449M - TANK/iocage/releases/11.3-RELEASE/root@nextcloud 16.0K - 467M - TANK/sysadmin@auto-20200303-02.00-1M 136K - 6.06M - TANK/sysadmin@auto-20200303.0415-1m 136K - 6.06M - freenas-boot/ROOT/11.2-U7@2019-04-06-10:00:20 7.48M - 755M - freenas-boot/ROOT/11.2-U7@2020-02-03-17:30:21 7.67M - 755M - root@freenas:~ #
My new defined tasks have run at 02.00 AM. But some shadow d(a)emon has made snaps of the same datasets at 04.15 AM, and it has added the retention time suffix as well ("-1m") but not used the suffix string I specified. Before I started afresh, I had more tasks snapping other datasets in a similar manner at 02.00. But I am only getting mysterious 04.15 replicas of the tasks I have recreated. None of my previous snapshot tasks were set to run at 04.15.
What is going on?
These are the settings I have used. The ones that are pending only run on Sundays.
middlewared.log:
Code:
[2020/03/03 02:00:00] (DEBUG) ZettareplService._observer_queue_reader():672 - Observer queue got <zettarepl.observer.PeriodicSnapshotTaskStart object at 0x832022310> [2020/03/03 02:00:00] (DEBUG) ZettareplService._observer_queue_reader():672 - Observer queue got <zettarepl.observer.PeriodicSnapshotTaskSuccess object at 0x81bd1b210> [2020/03/03 02:00:00] (DEBUG) ZettareplService._observer_queue_reader():672 - Observer queue got <zettarepl.observer.PeriodicSnapshotTaskStart object at 0x81bd1b610> [2020/03/03 02:00:00] (DEBUG) ZettareplService._observer_queue_reader():672 - Observer queue got <zettarepl.observer.PeriodicSnapshotTaskSuccess object at 0x832022190> [2020/03/03 02:00:00] (DEBUG) ZettareplService._observer_queue_reader():672 - Observer queue got <zettarepl.observer.PeriodicSnapshotTaskStart object at 0x81bd1b8d0> [2020/03/03 02:00:00] (DEBUG) ZettareplService._observer_queue_reader():672 - Observer queue got <zettarepl.observer.PeriodicSnapshotTaskSuccess object at 0x832022190> [2020/03/03 02:00:00] (DEBUG) ZettareplService._observer_queue_reader():672 - Observer queue got <zettarepl.observer.PeriodicSnapshotTaskStart object at 0x832022950> [2020/03/03 02:00:01] (DEBUG) ZettareplService._observer_queue_reader():672 - Observer queue got <zettarepl.observer.PeriodicSnapshotTaskSuccess object at 0x8320228d0> [2020/03/03 02:00:01] (DEBUG) ZettareplService._observer_queue_reader():672 - Observer queue got <zettarepl.observer.PeriodicSnapshotTaskStart object at 0x832022810> [2020/03/03 02:00:01] (DEBUG) ZettareplService._observer_queue_reader():672 - Observer queue got <zettarepl.observer.PeriodicSnapshotTaskSuccess object at 0x8320228d0> [2020/03/03 02:00:01] (DEBUG) ZettareplService._observer_queue_reader():672 - Observer queue got <zettarepl.observer.PeriodicSnapshotTaskStart object at 0x832022f90> [2020/03/03 02:00:01] (DEBUG) ZettareplService._observer_queue_reader():672 - Observer queue got <zettarepl.observer.PeriodicSnapshotTaskSuccess object at 0x832022310> [2020/03/03 02:00:01] (DEBUG) ZettareplService._observer_queue_reader():672 - Observer queue got <zettarepl.observer.PeriodicSnapshotTaskStart object at 0x832022490> [2020/03/03 02:00:01] (DEBUG) ZettareplService._observer_queue_reader():672 - Observer queue got <zettarepl.observer.PeriodicSnapshotTaskSuccess object at 0x832022190> [2020/03/03 03:45:00] (DEBUG) middlewared.plugins.pool.__run():3513 - Pool 'freenas-boot' last scrub datetime.datetime(2020, 3, 2, 3, 45, 6) [2020/03/03 05:30:00] (DEBUG) EtcService.generate():274 - No new changes for /etc/krb5.conf [2020/03/03 05:30:00] (DEBUG) EtcService.generate():274 - No new changes for /etc/krb5.conf
What is autosnap up to?
cron:
Code:
Mar 3 04:15:00 freenas /usr/sbin/cron[74949]: (root) CMD (/usr/local/bin/python /usr/local/www/freenasUI/tools/autosnap.py > /dev/null 2>&1) Mar 3 04:15:00 freenas /usr/sbin/cron[74951]: (root) CMD (/usr/libexec/atrun > /dev/null 2>&1)
Last edited:
