backrest icon indicating copy to clipboard operation
backrest copied to clipboard

On Error hook not triggered by warnings

Open modem opened this issue 9 months ago • 5 comments

I've set a hook for Discord notification in case of error in a plan (and repo), but it seems it's not being triggered. image

In the log, I don't see any reference to the hook when an error occurs. In these last days, the plan failed 2 times due to an error accessing some files.

Here's the log of today's error:

2024-04-29T11:26:32.044+0100	DEBUG	got snapshots for plan	{"repo": "Backup_Config", "repo": "Backup_Config", "count": 7, "plan": "Config_Data", "tag": "plan:Config_Data"}
2024-04-29T11:26:30.335+0100	INFO	Starting backup	{"plan": "Config_Data", "opId": 1797572856140269327}
2024-04-29T11:26:30.335+0100	DEBUG	repo orchestrator starting backup	{"repo": "Backup_Config"}
2024-04-29T11:49:53.187+0100	WARN	an unknown error was encountered in processing item: /raid/Config_Data/prowdata/config/prowdata.db-shm
2024-04-29T11:49:53.187+0100	WARN	an unknown error was encountered in processing item: /raid/Config_Data/prowdata/config/prowdata.db-wal
2024-04-29T11:50:34.655+0100	DEBUG	wrote operation log to 2024-04-29-logs.tar/18432
2024-04-29T11:50:34.787+0100	INFO	task finished	{"task": "backup for plan \"Config_Data\"", "duration": "24m4.636364665s"}
2024-04-29T11:50:34.907+0100	INFO	scheduling task	{"task": "backup for plan \"Config_Data\"", "runAt": "2024-04-30T11:00:00+01:00"}
2024-04-29T11:50:34.907+0100	INFO	running task	{"task": "forget for plan \"Config_Data\""}
2024-04-29T11:50:36.309+0100	DEBUG	forget snapshots	{"plan": "Config_Data", "count": 1, "policy": "policy_keep_last_n:7"}
2024-04-29T11:50:37.068+0100	DEBUG	indexed known snapshot IDs for repo Backup_Config in 585.332µs
2024-04-29T11:50:36.369+0100	INFO	task finished	{"task": "forget for plan \"Config_Data\"", "duration": "1.462489529s"}
2024-04-29T11:50:36.361+0100	DEBUG	wrote operation log to 2024-04-29-logs.tar/21504
2024-04-29T11:50:34.319+0100	INFO	Backup complete	{"plan": "Config_Data", "duration": "24m3.984502802s", "summary": "summary:{files_new:497  files_changed:892  files_unmodified:148552  dirs_new:61  dirs_changed:443  dirs_unmodified:219431  data_blobs:2737  tree_blobs:475  data_added:1688255741  total_files_processed:149941  total_bytes_processed:24676371628  total_duration:1441.720401441  snapshot_id:\"44c63b58cf348be66abcf40be3fbd6f6c4a514eb730344cb6832eca2828da5bd\"}"}
2024-04-29T11:50:37.084+0100	INFO	task finished	{"task": "index snapshots for plan \"Backup_Config\"", "duration": "714.210209ms"}
2024-04-29T11:50:34.555+0100	INFO	scheduling task	{"task": "index snapshots for plan \"Backup_Config\"", "runAt": "2024-04-29T11:50:34+01:00"}
2024-04-29T11:50:34.555+0100	INFO	scheduling task	{"task": "forget for plan \"Config_Data\"", "runAt": "2024-04-29T11:50:34+01:00"}
2024-04-29T11:50:36.369+0100	INFO	running task	{"task": "index snapshots for plan \"Backup_Config\""}
2024-04-29T11:50:37.083+0100	DEBUG	indexed snapshots	{"repo": "Backup_Config", "duration": "14.993076ms", "alreadyIndexed": 6, "newlyAdded": 1, "markedForgotten": 0}

I just edited the plan to trigger the same notification in case of a plan start and end, just to test the notification connection, and it got triggered at the backup start and at the backup end.

2024-04-29T13:27:01.908+0100	INFO	Starting backup	{"plan": "Config_Data", "opId": 1797672006457493292}
2024-04-29T13:27:01.908+0100	INFO	running hook	{"plan": "Config_Data", "opId": 0, "hook": "plan/Config_Data/hook/0"}
2024-04-29T13:27:03.166+0100	DEBUG	repo orchestrator starting backup	{"repo": "Backup_Config"}
2024-04-29T13:27:23.028+0100	DEBUG	got snapshots for plan	{"repo": "Backup_Config", "repo": "Backup_Config", "count": 7, "plan": "Config_Data", "tag": "plan:Config_Data"}
2024-04-29T13:38:43.666+0100	DEBUG	Backup completed	{"repo": "Backup_Config", "repo": "Backup_Config", "duration": "11m20.637998906s"}
2024-04-29T13:38:43.666+0100	INFO	running hook	{"plan": "Config_Data", "opId": 0, "hook": "plan/Config_Data/hook/0"}
2024-04-29T13:38:44.575+0100	INFO	Backup complete	{"plan": "Config_Data", "duration": "11m42.666992214s", "summary": "summary:{files_new:9  files_changed:625  files_unmodified:149314  dirs_changed:62  dirs_unmodified:219873  data_blobs:498  tree_blobs:62  data_added:356318587  total_files_processed:149948  total_bytes_processed:24669174726  total_duration:680.116178011  snapshot_id:\"24e68206cf0c180114cfe35f057b0de3cf11363fd1a71a993f493cb78ec59d41\"}"}

Expected behavior I expect the trigger to occur in case of a backup failure. This trigger has already worked in the past.

Platform Info

  • Docker
  • Backrest Version 0.17.2

modem avatar Apr 29 '24 12:04 modem