Front page

errors reported on backup but no idea what they are

456d5625fda8457ebcc840b0d7b374ec
CRUSADE HAZARDOUS EGGHEAD

From: Jonathan Dowland <jon+obnam-support@alcopop.org>
Date: Sun, 24 Apr 2016 09:47:17 +0100

   Below is a log of a backup run. Obnam (1.8-1/jessie) reports an error
   R4C3BCX, but I am having trouble finding what the error actually was.
   The full backup log is 44,784 lines long. The first occurance of R4C3BCX
   is at the end (as per the quoted log below); attempting to grep for
   'error' etc. is not proving useful (lots of false positives from files
   in the data set with 'error' in their names or paths somewhere)
   
   It may also seem odd to you that there was no chunk data uploaded: this
   was because it was a backup of something which I had just restored
   recently, and not changed at all. However, in between the generation I
   restored and then re-backed up, I had accidentally backed up the mount
   point whilst it was empty, so the most recent generation was blank.
   
   Apr 24 04:19:51 phobos obnam[17281]: INFO Making checkpoint
   Apr 24 04:24:22 phobos obnam[17281]: INFO Opening repository: /backup/archive.obnam
   Apr 24 04:24:23 phobos obnam[17281]: INFO Locking client phobos
   Apr 24 04:26:37 phobos obnam[17281]: INFO Backup performance statistics:
   Apr 24 04:26:37 phobos obnam[17281]: INFO * files found: 397227
   Apr 24 04:26:37 phobos obnam[17281]: INFO * files backed up: 397226
   Apr 24 04:26:37 phobos obnam[17281]: INFO * uploaded chunk data: 0 bytes (0.0 B)
   Apr 24 04:26:37 phobos obnam[17281]: INFO * total uploaded data (incl. metadata): 229972425097 bytes (214 GiB)
   Apr 24 04:26:37 phobos obnam[17281]: INFO * total downloaded data (incl. metadata): 257430410550 bytes (239 GiB)
   Apr 24 04:26:37 phobos obnam[17281]: INFO * transfer overhead: 487402835647 bytes (453 GiB)
   Apr 24 04:26:37 phobos obnam[17281]: INFO * duration: 56616.4555259 s (15h43m36s)
   Apr 24 04:26:37 phobos obnam[17281]: INFO * average speed: 0.0 B/s
   Apr 24 04:26:37 phobos obnam[17281]: INFO Backup finished.
   Apr 24 04:26:37 phobos obnam[17281]: CRITICAL R4C3BCX: There were errors during the backup
   Apr 24 04:26:37 phobos obnam[17281]: ERROR: R4C3BCX: There were errors during the backup
   Apr 24 04:26:37 phobos systemd[1]: backup-archive.service: main process exited, code=exited, status=1/FAILURE
   Apr 24 04:26:37 phobos systemd[1]: Unit backup-archive.service entered failed state.
   
   _______________________________________________
   obnam-support mailing list
   obnam-support@obnam.org
   http://listmaster.pepperfish.net/cgi-bin/mailman/listinfo/obnam-support-obnam.org
From: Sharon Kimble <boudiccas@skimble.plus.com>
Date: Sun, 24 Apr 2016 10:44:55 +0100

   Jonathan Dowland <jon+obnam-support@alcopop.org> writes:
   
   > Below is a log of a backup run. Obnam (1.8-1/jessie) reports an error
   > R4C3BCX, but I am having trouble finding what the error actually was.
   > The full backup log is 44,784 lines long. The first occurance of R4C3BCX
   > is at the end (as per the quoted log below); attempting to grep for
   > 'error' etc. is not proving useful (lots of false positives from files
   > in the data set with 'error' in their names or paths somewhere)
   
   According to the 'unofficial' Obnam manual [which I maintain] that error
   code shows -
   
   ╭────
   │R4C3BCX - BackupErrors
   ╰────
   
   which isn't very helpful!
   
   So what happens if you repeat the backup, do you get the same error?
   
   Sharon.
   
   >
   > It may also seem odd to you that there was no chunk data uploaded: this
   > was because it was a backup of something which I had just restored
   > recently, and not changed at all. However, in between the generation I
   > restored and then re-backed up, I had accidentally backed up the mount
   > point whilst it was empty, so the most recent generation was blank.
   >
   > Apr 24 04:19:51 phobos obnam[17281]: INFO Making checkpoint
   > Apr 24 04:24:22 phobos obnam[17281]: INFO Opening repository: /backup/archive.obnam
   > Apr 24 04:24:23 phobos obnam[17281]: INFO Locking client phobos
   > Apr 24 04:26:37 phobos obnam[17281]: INFO Backup performance statistics:
   > Apr 24 04:26:37 phobos obnam[17281]: INFO * files found: 397227
   > Apr 24 04:26:37 phobos obnam[17281]: INFO * files backed up: 397226
   > Apr 24 04:26:37 phobos obnam[17281]: INFO * uploaded chunk data: 0 bytes (0.0 B)
   > Apr 24 04:26:37 phobos obnam[17281]: INFO * total uploaded data (incl. metadata): 229972425097 bytes (214 GiB)
   > Apr 24 04:26:37 phobos obnam[17281]: INFO * total downloaded data (incl. metadata): 257430410550 bytes (239 GiB)
   > Apr 24 04:26:37 phobos obnam[17281]: INFO * transfer overhead: 487402835647 bytes (453 GiB)
   > Apr 24 04:26:37 phobos obnam[17281]: INFO * duration: 56616.4555259 s (15h43m36s)
   > Apr 24 04:26:37 phobos obnam[17281]: INFO * average speed: 0.0 B/s
   > Apr 24 04:26:37 phobos obnam[17281]: INFO Backup finished.
   > Apr 24 04:26:37 phobos obnam[17281]: CRITICAL R4C3BCX: There were errors during the backup
   > Apr 24 04:26:37 phobos obnam[17281]: ERROR: R4C3BCX: There were errors during the backup
   > Apr 24 04:26:37 phobos systemd[1]: backup-archive.service: main process exited, code=exited, status=1/FAILURE
   > Apr 24 04:26:37 phobos systemd[1]: Unit backup-archive.service entered failed state.
   >
   > _______________________________________________
   > obnam-support mailing list
   > obnam-support@obnam.org
   > http://listmaster.pepperfish.net/cgi-bin/mailman/listinfo/obnam-support-obnam.org
From: Björn Persson <Bjorn@xn--rombobjrn-67a.se>
Date: Sun, 24 Apr 2016 15:23:01 +0200

   Jonathan Dowland wrote:
   > Below is a log of a backup run. Obnam (1.8-1/jessie) reports an error
   > R4C3BCX, but I am having trouble finding what the error actually was.
   > The full backup log is 44,784 lines long. The first occurance of
   > R4C3BCX is at the end (as per the quoted log below); attempting to
   > grep for 'error' etc. is not proving useful (lots of false positives
   > from files in the data set with 'error' in their names or paths
   > somewhere)
   
   There's more you can do with Grep. Try «grep -E -v 'obnam[^:]+: INFO'»
   to remove all informational messages. If you see for example "DEBUG"
   everywhere, then use «grep -E -v 'obnam[^:]+: (INFO|DEBUG)'» to remove
   those too. These expressions remove only those lines where "INFO" or
   "DEBUG" occurs immediately after "obnam" and the process ID.
   
   Björn Persson
From: Jonathan Dowland <jon+obnam-support@alcopop.org>
Date: Mon, 25 Apr 2016 08:50:30 +0100

   On Sun, Apr 24, 2016 at 03:23:01PM +0200, Björn Persson wrote:
   > There's more you can do with Grep. Try «grep -E -v 'obnam[^:]+: INFO'»
   > to remove all informational messages.
   
   Thanks. Basically the whole log is informational messages, that only
   listed the CRITICAL, ERROR and systemd-related lines that I included
   earlier, sadly.
   
   _______________________________________________
   obnam-support mailing list
   obnam-support@obnam.org
   http://listmaster.pepperfish.net/cgi-bin/mailman/listinfo/obnam-support-obnam.org
From: Jonathan Dowland <jon+obnam-support@alcopop.org>
Date: Mon, 25 Apr 2016 10:47:49 +0100

   On Sun, Apr 24, 2016 at 10:44:55AM +0100, Sharon Kimble wrote:
   > So what happens if you repeat the backup, do you get the same error?
   
   I've just re-run it and yes I do, but i also see more at the start of
   the log which explains that obnam is choking on lost+found:
   
   > Apr 25 08:52:12 phobos obnam[32285]: ERROR listdir failed: /archive/lost+found: Permission denied
   > Apr 25 08:52:12 phobos obnam[32285]: ERROR Can't back up /archive/lost+found: RD5FA4X: System error: /archive/lost+found: 13: Permission denied
   > Apr 25 08:52:12 phobos obnam[32285]: ERROR OSError(13, 'Permission denied')
   > Apr 25 08:52:12 phobos obnam[32285]: ERROR: Can't back up /archive/lost+found: RD5FA4X: System error: /archive/lost+found: 13: Permission denied
   > Apr 25 10:33:16 phobos obnam[32285]: CRITICAL R4C3BCX: There were errors during the backup
   > Apr 25 10:33:16 phobos obnam[32285]: ERROR: R4C3BCX: There were errors during the backup
   > Apr 25 10:33:16 phobos systemd[1]: backup-archive.service: main process exited, code=exited, status=1/FAILURE
   > Apr 25 10:33:16 phobos systemd[1]: Unit backup-archive.service entered failed state.
   
   Adding an --exclude should fix that (just retrying now).
   
   I'm not sure why this was not included in the logs for my first run.
   
   I also don't know why I'm getting all these INFO lines as I am passing
   --quiet to obnam. I tried removing --syslog this time (running inside a
   systemd unit anyway) but that does not make any difference)
   
   Thanks for your help!
From: Sharon Kimble <boudiccas@skimble.plus.com>
Date: Mon, 25 Apr 2016 12:11:53 +0100

   Jonathan Dowland <jon+obnam-support@alcopop.org> writes:
   
   > On Sun, Apr 24, 2016 at 10:44:55AM +0100, Sharon Kimble wrote:
   >> So what happens if you repeat the backup, do you get the same error?
   >
   > I've just re-run it and yes I do, but i also see more at the start of
   > the log which explains that obnam is choking on lost+found:
   
   In this situation in the past I've found that its because you've got a
   file with root permissions in the trash or lost+found bins. Can you see
   what file its choking on please?
   
   That error message of 'RD5FA4X' is for "RD5FA4X - ObnamSystemError" and
   "ObnamSystemError - RD5FA4X - System error: filename: errno: strerror"
   if that helps?
   
   Sharon.
   
   
   >
   >> Apr 25 08:52:12 phobos obnam[32285]: ERROR listdir failed: /archive/lost+found: Permission denied
   >> Apr 25 08:52:12 phobos obnam[32285]: ERROR Can't back up /archive/lost+found: RD5FA4X: System error: /archive/lost+found: 13: Permission denied
   >> Apr 25 08:52:12 phobos obnam[32285]: ERROR OSError(13, 'Permission denied')
   >> Apr 25 08:52:12 phobos obnam[32285]: ERROR: Can't back up /archive/lost+found: RD5FA4X: System error: /archive/lost+found: 13: Permission denied
   >> Apr 25 10:33:16 phobos obnam[32285]: CRITICAL R4C3BCX: There were errors during the backup
   >> Apr 25 10:33:16 phobos obnam[32285]: ERROR: R4C3BCX: There were errors during the backup
   >> Apr 25 10:33:16 phobos systemd[1]: backup-archive.service: main process exited, code=exited, status=1/FAILURE
   >> Apr 25 10:33:16 phobos systemd[1]: Unit backup-archive.service entered failed state.
   >
   > Adding an --exclude should fix that (just retrying now).
   >
   > I'm not sure why this was not included in the logs for my first run.
   >
   > I also don't know why I'm getting all these INFO lines as I am passing
   > --quiet to obnam. I tried removing --syslog this time (running inside a
   > systemd unit anyway) but that does not make any difference)
   >
   > Thanks for your help!
From: Jonathan Dowland <jon+obnam-support@alcopop.org>
Date: Mon, 25 Apr 2016 14:48:34 +0100

   On Mon, Apr 25, 2016 at 12:11:53PM +0100, Sharon Kimble wrote:
   > In this situation in the past I've found that its because you've got a
   > file with root permissions in the trash or lost+found bins. Can you see
   > what file its choking on please?
   
   I think it is the directory: I'm now trying a run with an --exclude
   which should match the directory itself.
From: Lars Wirzenius <liw@liw.fi>
Date: Mon, 25 Apr 2016 15:34:14 +0300

   On Mon, Apr 25, 2016 at 10:47:49AM +0100, Jonathan Dowland wrote:
   > I also don't know why I'm getting all these INFO lines as I am passing
   > --quiet to obnam. I tried removing --syslog this time (running inside a
   > systemd unit anyway) but that does not make any difference)
   
   The --quiet option affects progress output to terminal, to logging. To
   control logging, use --log-level.
From: Lars Wirzenius <liw@liw.fi>
Date: Mon, 25 Apr 2016 15:37:19 +0300

   On Sun, Apr 24, 2016 at 10:44:55AM +0100, Sharon Kimble wrote:
   > According to the 'unofficial' Obnam manual [which I maintain] that error
   > code shows -
   > 
   > ╭────
   > │R4C3BCX - BackupErrors
   > ╰────
   > 
   > which isn't very helpful!
   
   This quite literally only means there was one or more other errors
   previously which is why the whole backup run failed. The other errors
   will have been logged previously.