2021-02-14 Borg Backup Exception

Today I had an exception in my logs for Borg backup. 😱

Feb 14 09:16:12 melanobombus systemd[1]: Starting automatic-backup.service...
Feb 14 09:16:17 melanobombus run.sh[9191]: Disk bb1c034e-dd21-48e7-a496-1b95685a094d is a backup disk
Feb 14 09:16:17 melanobombus run.sh[9191]: /dev/sdb1 on /mnt/backup type ext4 (rw,nosuid,nodev,relatime,x-gvfs-show)
Feb 14 09:16:17 melanobombus run.sh[9191]: Drive path: /dev/sdb1
Feb 14 09:16:17 melanobombus run.sh[9191]: borgbackup version 1.1.9
Feb 14 09:39:36 melanobombus run.sh[9191]: Exception ignored in: <function Repository.__del__ at 0x7f4254351d90>
Feb 14 09:39:36 melanobombus run.sh[9191]: Traceback (most recent call last):
Feb 14 09:39:36 melanobombus run.sh[9191]:   File "/usr/lib/python3/dist-packages/borg/repository.py", line 178, in __del__
Feb 14 09:39:36 melanobombus run.sh[9191]:     self.close()
Feb 14 09:39:36 melanobombus run.sh[9191]:   File "/usr/lib/python3/dist-packages/borg/repository.py", line 427, in close
Feb 14 09:39:36 melanobombus run.sh[9191]:     self.lock.release()
Feb 14 09:39:36 melanobombus run.sh[9191]:   File "/usr/lib/python3/dist-packages/borg/locking.py", line 383, in release
Feb 14 09:39:36 melanobombus run.sh[9191]:     self._roster.modify(EXCLUSIVE, REMOVE)
Feb 14 09:39:36 melanobombus run.sh[9191]:   File "/usr/lib/python3/dist-packages/borg/locking.py", line 282, in modify
Feb 14 09:39:36 melanobombus run.sh[9191]:     elements.remove(self.id)
Feb 14 09:39:36 melanobombus run.sh[9191]: KeyError: (('melanobombus@27278930346555', 9230, 0),)
Feb 14 09:39:36 melanobombus run.sh[9191]: Local Exception
Feb 14 09:39:36 melanobombus run.sh[9191]: Traceback (most recent call last):
Feb 14 09:39:36 melanobombus run.sh[9191]:   File "/usr/lib/python3/dist-packages/borg/archiver.py", line 154, in wrapper
Feb 14 09:39:36 melanobombus run.sh[9191]:     return method(self, args, repository=repository, **kwargs)
Feb 14 09:39:36 melanobombus run.sh[9191]:   File "/usr/lib/python3/dist-packages/borg/archiver.py", line 557, in do_create
Feb 14 09:39:36 melanobombus run.sh[9191]:     create_inner(archive, cache)
Feb 14 09:39:36 melanobombus run.sh[9191]:   File "/usr/lib/python3/dist-packages/borg/archiver.py", line 520, in create_inner
Feb 14 09:39:36 melanobombus run.sh[9191]:     read_special=args.read_special, dry_run=dry_run, st=st)
Feb 14 09:39:36 melanobombus run.sh[9191]:   File "/usr/lib/python3/dist-packages/borg/archiver.py", line 634, in _process
Feb 14 09:39:36 melanobombus run.sh[9191]:     read_special=read_special, dry_run=dry_run)
Feb 14 09:39:36 melanobombus run.sh[9191]:   File "/usr/lib/python3/dist-packages/borg/archiver.py", line 634, in _process
Feb 14 09:39:36 melanobombus run.sh[9191]:     read_special=read_special, dry_run=dry_run)
Feb 14 09:39:36 melanobombus run.sh[9191]:   File "/usr/lib/python3/dist-packages/borg/archiver.py", line 634, in _process
Feb 14 09:39:36 melanobombus run.sh[9191]:     read_special=read_special, dry_run=dry_run)
Feb 14 09:39:36 melanobombus run.sh[9191]:   [Previous line repeated 3 more times]
Feb 14 09:39:36 melanobombus run.sh[9191]:   File "/usr/lib/python3/dist-packages/borg/archiver.py", line 608, in _process
Feb 14 09:39:36 melanobombus run.sh[9191]:     status = archive.process_file(path, st, cache)
Feb 14 09:39:36 melanobombus run.sh[9191]:   File "/usr/lib/python3/dist-packages/borg/archive.py", line 1034, in process_file
Feb 14 09:39:36 melanobombus run.sh[9191]:     self.chunk_file(item, cache, self.stats, backup_io_iter(self.chunker.chunkify(fd, fh)))
Feb 14 09:39:36 melanobombus run.sh[9191]:   File "/usr/lib/python3/dist-packages/borg/archive.py", line 962, in chunk_file
Feb 14 09:39:36 melanobombus run.sh[9191]:     item.chunks.append(chunk_processor(data))
Feb 14 09:39:36 melanobombus run.sh[9191]:   File "/usr/lib/python3/dist-packages/borg/archive.py", line 950, in chunk_processor
Feb 14 09:39:36 melanobombus run.sh[9191]:     chunk_entry = cache.add_chunk(self.key.id_hash(data), data, stats, wait=False)
Feb 14 09:39:36 melanobombus run.sh[9191]:   File "/usr/lib/python3/dist-packages/borg/cache.py", line 899, in add_chunk
Feb 14 09:39:36 melanobombus run.sh[9191]:     self.repository.put(id, data, wait=wait)
Feb 14 09:39:36 melanobombus run.sh[9191]:   File "/usr/lib/python3/dist-packages/borg/repository.py", line 1101, in put
Feb 14 09:39:36 melanobombus run.sh[9191]:     segment, offset = self.io.write_put(id, data)
Feb 14 09:39:36 melanobombus run.sh[9191]:   File "/usr/lib/python3/dist-packages/borg/repository.py", line 1482, in write_put
Feb 14 09:39:36 melanobombus run.sh[9191]:     fd.write(b''.join((crc, header, id, data)))
Feb 14 09:39:36 melanobombus run.sh[9191]:   File "src/borg/platform/linux.pyx", line 283, in borg.platform.linux.SyncFile.write
Feb 14 09:39:36 melanobombus run.sh[9191]:   File "src/borg/platform/linux.pyx", line 236, in borg.platform.linux._sync_file_range
Feb 14 09:39:36 melanobombus run.sh[9191]: OSError: [Errno 5] Input/output error
Feb 14 09:39:36 melanobombus run.sh[9191]: During handling of the above exception, another exception occurred:
Feb 14 09:39:36 melanobombus run.sh[9191]: Traceback (most recent call last):
Feb 14 09:39:36 melanobombus run.sh[9191]:   File "/usr/lib/python3/dist-packages/borg/platform/base.py", line 136, in close
Feb 14 09:39:36 melanobombus run.sh[9191]:     self.sync()
Feb 14 09:39:36 melanobombus run.sh[9191]:   File "src/borg/platform/linux.pyx", line 292, in borg.platform.linux.SyncFile.sync
Feb 14 09:39:36 melanobombus run.sh[9191]: OSError: [Errno 5] Input/output error
Feb 14 09:39:36 melanobombus run.sh[9191]: During handling of the above exception, another exception occurred:
Feb 14 09:39:36 melanobombus run.sh[9191]: Traceback (most recent call last):
Feb 14 09:39:36 melanobombus run.sh[9191]:   File "/usr/lib/python3/dist-packages/borg/archiver.py", line 4455, in main
Feb 14 09:39:36 melanobombus run.sh[9191]:     exit_code = archiver.run(args)
Feb 14 09:39:36 melanobombus run.sh[9191]:   File "/usr/lib/python3/dist-packages/borg/archiver.py", line 4387, in run
Feb 14 09:39:36 melanobombus run.sh[9191]:     return set_ec(func(args))
Feb 14 09:39:36 melanobombus run.sh[9191]:   File "/usr/lib/python3/dist-packages/borg/archiver.py", line 154, in wrapper
Feb 14 09:39:36 melanobombus run.sh[9191]:     return method(self, args, repository=repository, **kwargs)
Feb 14 09:39:36 melanobombus run.sh[9191]:   File "/usr/lib/python3/dist-packages/borg/repository.py", line 203, in __exit__
Feb 14 09:39:36 melanobombus run.sh[9191]:     self.close()
Feb 14 09:39:36 melanobombus run.sh[9191]:   File "/usr/lib/python3/dist-packages/borg/repository.py", line 425, in close
Feb 14 09:39:36 melanobombus run.sh[9191]:     self.io.close()
Feb 14 09:39:36 melanobombus run.sh[9191]:   File "/usr/lib/python3/dist-packages/borg/repository.py", line 1176, in close
Feb 14 09:39:36 melanobombus run.sh[9191]:     self.close_segment()
Feb 14 09:39:36 melanobombus run.sh[9191]:   File "/usr/lib/python3/dist-packages/borg/repository.py", line 1307, in close_segment
Feb 14 09:39:36 melanobombus run.sh[9191]:     fd.close()
Feb 14 09:39:36 melanobombus run.sh[9191]:   File "/usr/lib/python3/dist-packages/borg/platform/base.py", line 140, in close
Feb 14 09:39:36 melanobombus run.sh[9191]:     platform.sync_dir(dirname)
Feb 14 09:39:36 melanobombus run.sh[9191]:   File "/usr/lib/python3/dist-packages/borg/platform/base.py", line 58, in sync_dir
Feb 14 09:39:36 melanobombus run.sh[9191]:     fd = os.open(path, os.O_RDONLY)
Feb 14 09:39:36 melanobombus run.sh[9191]: FileNotFoundError: [Errno 2] No such file or directory: '/mnt/backup/borg-backups/backup.borg/data/1'
Feb 14 09:39:36 melanobombus run.sh[9191]: Platform: Linux melanobombus 4.19.0-14-amd64 #1 SMP Debian 4.19.171-2 (2021-01-30) x86_64
Feb 14 09:39:36 melanobombus run.sh[9191]: Linux: PureOS 9 amber
Feb 14 09:39:36 melanobombus run.sh[9191]: Borg: 1.1.9  Python: CPython 3.7.3
Feb 14 09:39:36 melanobombus run.sh[9191]: PID: 9230  CWD: /
Feb 14 09:39:36 melanobombus run.sh[9191]: sys.argv: ['/usr/bin/borg', 'create', '--stats', '--one-file-system', '--compression', 'lz4', '--show-version', '--exclude', '/root/.cache', '--exclude', '/var/cache', '/mnt/backup/borg-backups/backup.borg::{utcnow}-{hostname}', '/']
Feb 14 09:39:36 melanobombus run.sh[9191]: SSH_ORIGINAL_COMMAND: None
Feb 14 09:39:36 melanobombus systemd[1]: automatic-backup.service: Main process exited, code=exited, status=2/INVALIDARGUMENT
Feb 14 09:39:36 melanobombus systemd[1]: automatic-backup.service: Failed with result 'exit-code'.
Feb 14 09:39:36 melanobombus systemd[1]: Failed to start automatic-backup.service.
Feb 14 09:39:36 melanobombus systemd[1]: Starting automatic-backup.service...
Feb 14 09:39:41 melanobombus run.sh[9897]: Disk bb1c034e-dd21-48e7-a496-1b95685a094d is a backup disk
Feb 14 09:39:41 melanobombus run.sh[9897]: /dev/sdb1 on /mnt/backup type ext4 (rw,nosuid,nodev,relatime,x-gvfs-show)
Feb 14 09:39:41 melanobombus run.sh[9897]: Drive path: /dev/sdb1
Feb 14 09:39:42 melanobombus run.sh[9897]: borgbackup version 1.1.9
Feb 14 09:39:42 melanobombus run.sh[9897]: Killed stale lock melanobombus@27278930346555.9230-0.
Feb 14 09:39:42 melanobombus run.sh[9897]: Removed stale exclusive roster lock for host melanobombus@27278930346555 pid 9230 thread 0.
Feb 14 09:39:42 melanobombus run.sh[9897]: Removed stale exclusive roster lock for host melanobombus@27278930346555 pid 9230 thread 0.

Looks like it’s running again. But still. How disconerting.

Did it unmount itself by accident? The missing directory is back, in any case:

$ sudo ls /mnt/backup/borg-backups/backup.borg/data/1
1000  1013  1026  1039	1052  1065  1081  1094	1107  1120  1133  1146	1159  1175
1001  1014  1027  1040	1053  1066  1082  1095	1108  1121  1134  1147	1160  1176
1002  1015  1028  1041	1054  1068  1083  1096	1109  1122  1135  1148	1161  1177
1003  1016  1029  1042	1055  1070  1084  1097	1110  1123  1136  1149	1162  1178
1004  1017  1030  1043	1056  1072  1085  1098	1111  1124  1137  1150	1163  1179
1005  1018  1031  1044	1057  1073  1086  1099	1112  1125  1138  1151	1165  1180
1006  1019  1032  1045	1058  1074  1087  1100	1113  1126  1139  1152	1166  1181
1007  1020  1033  1046	1059  1075  1088  1101	1114  1127  1140  1153	1167  1182
1008  1021  1034  1047	1060  1076  1089  1102	1115  1128  1141  1154	1168  1183
1009  1022  1035  1048	1061  1077  1090  1103	1116  1129  1142  1155	1169  1184
1010  1023  1036  1049	1062  1078  1091  1104	1117  1130  1143  1156	1171  1185
1011  1024  1037  1050	1063  1079  1092  1105	1118  1131  1144  1157	1173  1186
1012  1025  1038  1051	1064  1080  1093  1106	1119  1132  1145  1158	1174  1187

Well, it seems to have worked now, so let’s hope this doesn’t happen again. 😰

Feb 14 09:39:36 melanobombus systemd[1]: Starting automatic-backup.service...
Feb 14 09:39:41 melanobombus run.sh[9897]: Disk bb1c034e-dd21-48e7-a496-1b95685a094d is a backup disk
Feb 14 09:39:41 melanobombus run.sh[9897]: /dev/sdb1 on /mnt/backup type ext4 (rw,nosuid,nodev,relatime,x-gvfs-show)
Feb 14 09:39:41 melanobombus run.sh[9897]: Drive path: /dev/sdb1
Feb 14 09:39:42 melanobombus run.sh[9897]: borgbackup version 1.1.9
Feb 14 09:39:42 melanobombus run.sh[9897]: Killed stale lock melanobombus@27278930346555.9230-0.
Feb 14 09:39:42 melanobombus run.sh[9897]: Removed stale exclusive roster lock for host melanobombus@27278930346555 pid 9230 thread 0.
Feb 14 09:39:42 melanobombus run.sh[9897]: Removed stale exclusive roster lock for host melanobombus@27278930346555 pid 9230 thread 0.
Feb 14 10:29:09 melanobombus run.sh[9897]: ------------------------------------------------------------------------------
Feb 14 10:29:09 melanobombus run.sh[9897]: Archive name: 2021-02-14T08:39:42-melanobombus
Feb 14 10:29:09 melanobombus run.sh[9897]: Archive fingerprint: b544aa2865c56d6ed899ab53e945d27b2e72632f3b03a9918fb770b8af323c60
Feb 14 10:29:09 melanobombus run.sh[9897]: Time (start): Sun, 2021-02-14 09:39:50
Feb 14 10:29:09 melanobombus run.sh[9897]: Time (end):   Sun, 2021-02-14 10:28:54
Feb 14 10:29:09 melanobombus run.sh[9897]: Duration: 49 minutes 4.44 seconds
Feb 14 10:29:09 melanobombus run.sh[9897]: Number of files: 2014188
Feb 14 10:29:09 melanobombus run.sh[9897]: Utilization of max. archive size: 1%
Feb 14 10:29:09 melanobombus run.sh[9897]: ------------------------------------------------------------------------------
Feb 14 10:29:09 melanobombus run.sh[9897]:                        Original size      Compressed size    Deduplicated size
Feb 14 10:29:09 melanobombus run.sh[9897]: This archive:              400.10 GB            370.87 GB             54.13 GB
Feb 14 10:29:09 melanobombus run.sh[9897]: All archives:                3.38 TB              2.98 TB            586.15 GB
Feb 14 10:29:09 melanobombus run.sh[9897]:                        Unique chunks         Total chunks
Feb 14 10:29:09 melanobombus run.sh[9897]: Chunk index:                 2857053             25178069
Feb 14 10:29:09 melanobombus run.sh[9897]: ------------------------------------------------------------------------------
Feb 14 10:29:10 melanobombus run.sh[9897]: Keeping archive: 2021-02-14T08:39:42-melanobombus     Sun, 2021-02-14 09:39:50 [b544aa2865c56d6ed899ab53e945d27b2e72632f3b03a9918fb770b8af323c60]
Feb 14 10:29:10 melanobombus run.sh[9897]: Keeping archive: 2020-12-30T14:14:40-melanobombus     Wed, 2020-12-30 15:14:48 [e5d798a2f8f7d434c4c189abcf34416f25e56c2256be5ae5e2f159d6cea1bc10]
Feb 14 10:29:10 melanobombus run.sh[9897]: Keeping archive: 2020-11-29T16:11:52-melanobombus     Sun, 2020-11-29 17:12:00 [1a6d898cf8d0d762114a17c29485fae7cb8a1643b1bf958ebe0839efe10745ad]
Feb 14 10:29:10 melanobombus run.sh[9897]: Keeping archive: 2020-10-04T09:55:59-melanobombus     Sun, 2020-10-04 11:56:07 [6ae0f02f4db55f391068ef1e0597a70f7de74e88a9532e74cb8e3eb2f5b4996a]
Feb 14 10:29:10 melanobombus run.sh[9897]: Keeping archive: 2020-07-03T09:09:33-melanobombus     Fri, 2020-07-03 11:09:43 [02580a4055bf0eabf9244d7716679623c9ce6cfd2292146fca4f49283233345b]
Feb 14 10:29:10 melanobombus run.sh[9897]: Keeping archive: 2020-04-19T13:59:25-melanobombus     Sun, 2020-04-19 15:59:30 [48aff2806989e7e911438f9c0162d6e25052f1768e974c37035bbfec5887129b]
Feb 14 10:29:10 melanobombus run.sh[9897]: Keeping archive: 2020-01-01T18:11:38-melanobombus     Wed, 2020-01-01 19:11:47 [e1825d82ecefefda0ea9af7727f4df7b54d34b4a650b43a80a3ceb243426d9cf]
Feb 14 10:29:10 melanobombus run.sh[9897]: Keeping archive: 2019-10-01T20:01:46-melanobombus     Tue, 2019-10-01 22:01:53 [7b5b8e050e44d74f1bb2907cfcb49a1da78dd7e2b1777341bbb300066447b143]
Feb 14 10:29:10 melanobombus run.sh[9897]: Keeping archive: 2019-07-22T06:43:53-melanobombus     Mon, 2019-07-22 08:43:57 [b4c3007f18e14877984371787a55269f313a326205157a66d6045b4cfc7e514b]
Feb 14 10:29:10 melanobombus run.sh[9897]: Keeping archive: 2019-07-04T13:09:14-melanobombus     Thu, 2019-07-04 15:09:20 [bbd16ceece7396db68a9e0f2d2ecb397b2b30abd2e2aa0b47ba19e0c93fbca07]
Feb 14 10:29:10 melanobombus run.sh[9897]: Keeping archive: 2019-04-07T12:42:54-melanobombus     Sun, 2019-04-07 14:42:58 [94dec06bad944a1399c4b62ef3142627a334cdb937a8f54231a3547a4fbd8d6e]
Feb 14 10:29:10 melanobombus run.sh[9897]: Keeping archive: 2019-01-18T09:02:49-melanobombus     Fri, 2019-01-18 10:02:52 [55f42cec0f207580a0f8cf9e9453a60c38f7adcce8848e63cbbc42668c1a76c7]
Feb 14 10:29:10 melanobombus run.sh[9897]: Keeping archive: 2018-10-01T19:15:46-melanobombus     Mon, 2018-10-01 21:15:51 [fae71c41681ee1137e3b7df00ab9be34aff2544f3c37742fbfd2433cc67e4286]
Feb 14 10:29:10 melanobombus run.sh[9897]: Keeping archive: 2018-08-06T10:18:29-melanobombus     Mon, 2018-08-06 12:18:32 [df059b51998a17455727c131aba794c386827a275a373a46128b91680a66099a]
Feb 14 10:29:10 melanobombus run.sh[9897]: Keeping archive: 2018-07-24T11:42:35-melanobombus     Tue, 2018-07-24 13:42:40 [1debbaea26d5b721a0a0a87dcbeb5a1af86a19d5b3302fcf57189013f3aef461]
Feb 14 10:29:10 melanobombus run.sh[9897]: Keeping archive: 2018-06-28T15:19:01-melanobombus     Thu, 2018-06-28 17:19:05 [52450fda61601e22a8b96edb5c29aafc7a44a48de76c46bd77f521eb1c0c140f]
Feb 14 10:29:10 melanobombus run.sh[9897]: Keeping archive: 2018-05-01T11:57:49-melanobombus     Tue, 2018-05-01 13:57:51 [4e6aea1a8b90e363e51fc42a28bb6d0b3e02623fa3a196c80f5dc71251793f0e]
Feb 14 10:29:10 melanobombus run.sh[9897]: Pruning archive: 2018-03-16T16:41:37-melanobombus     Fri, 2018-03-16 17:41:39 [5df8d3b05427f89416db0bd322519b6991eb6b16eb05b80fb7ba3cb436da6835] (1/1)
Feb 14 10:35:26 melanobombus run.sh[9897]: ------------------------------------------------------------------------------
Feb 14 10:35:26 melanobombus run.sh[9897]:                        Original size      Compressed size    Deduplicated size
Feb 14 10:35:26 melanobombus run.sh[9897]: Deleted data:              -31.49 GB            -24.37 GB             -4.81 GB
Feb 14 10:35:26 melanobombus run.sh[9897]: All archives:                3.35 TB              2.95 TB            581.34 GB
Feb 14 10:35:26 melanobombus run.sh[9897]:                        Unique chunks         Total chunks
Feb 14 10:35:26 melanobombus run.sh[9897]: Chunk index:                 2755971             24549735
Feb 14 10:35:26 melanobombus run.sh[9897]: ------------------------------------------------------------------------------
Feb 14 10:35:26 melanobombus run.sh[9897]: terminating with success status, rc 0
Feb 14 10:35:27 melanobombus run.sh[9897]: /dev/sdb1:
Feb 14 10:35:27 melanobombus run.sh[9897]:  issuing sleep command
Feb 14 10:35:27 melanobombus systemd[1]: automatic-backup.service: Succeeded.
Feb 14 10:35:27 melanobombus systemd[1]: Started automatic-backup.service.

Comments


Please make sure you contribute only your own work, or work licensed under the GNU Free Documentation License. Note: in order to facilitate peer review and fight vandalism, we will store your IP number for a number of days. See Privacy Policy for more information. See Info for text formatting rules. You can edit the comment page if you need to fix typos. You can subscribe to new comments by email without leaving a comment.

To save this page you must answer this question:

Just say HELLO