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.
​#Backup ​#Borg