Warnings & errors in journalctl

julien-f

First, the INFO entries are normal, they indicate the work the merge worker is doing.

The open/EEXIST error may be because more than one task are created at the same time, which appears unlikely but not impossible, we'll handle this.

The rename/ENOENT error is not normal, I don't get how it can happen, it means that the source file right after the parent directory was listed, and I don't understand how that could be. The related code:

let taskFiles
while ((taskFiles = await listRetry()) !== undefined) {
  const taskFileBasename = min(taskFiles)
  const taskFile = join(CLEAN_VM_QUEUE, '_' + taskFileBasename)

  // move this task to the end
  await handler.rename(join(CLEAN_VM_QUEUE, taskFileBasename), taskFile)

The merging warning should not be a real problem, it can occur because for now XO only knows to merge one delta VHD at a time which, in certain cases may not be enough, we are working to handle this

Danp

@julien-f said in Warnings & errors in journalctl:

the INFO entries are normal

I knew this. I just left them in for context.

The rename/ENOENT error is not normal

Could this be caused by the same issue you mentioned above where more than one task is running?

Let me know if there is anything I can do to assist further, such as capturing more details logs.

Thanks for your quick response!

Regards, Dan

Danp

@julien-f What about this one?

Dec 07 00:00:11 xo-server[209172]: 2021-12-07T06:00:11.341Z xo:backups:MixinBackupWriter WARN the parent /xo-vm-backups/821044bd-8e41-009c-abeb-23bc347a2833/vdis/dfe75d18-94ac-4bd1-a1c7-fb2170e75154/f21b0b14-924d-4b62-ba23-23792d34a3f3/20211124T060033Z.vhd of the child /xo-vm-backups/821044bd-8e41-009c-abeb-23bc347a2833/vdis/dfe75d18-94ac-4bd1-a1c7-fb2170e75154/f21b0b14-924d-4b62-ba23-23792d34a3f3/20211125T060112Z.vhd is unused

julien-f

@danp It means that there is a VHD left to merge, this is normal and we'll try to remove these useless warnings

Danp

@julien-f Here's a new one from today's backup --

Dec 09 00:00:38 xo-server[268840]: 2021-12-09T06:00:38.235Z xo:backups:MixinBackupWriter WARN the parent /xo-vm-backups/787ada5e-e49d-716f-bdf9-ac7d3fb76195/vdis/dfe75d18-94ac-4bd1-a1c7-fb2170e75154/33e87f85-1afd-4d49-be23-8d88e9ce6bd9/20211128T060025Z.vhd of the child /xo-vm-backups/787ada5e-e49d-716f-bdf9-ac7d3fb76195/vdis/dfe75d18-94ac-4bd1-a1c7-fb2170e75154/33e87f85-1afd-4d49-be23-8d88e9ce6bd9/20211129T060035Z.vhd is unused
Dec 09 00:00:40 xo-server[268840]: 2021-12-09T06:00:40.718Z xo:backups:MixinBackupWriter WARN the parent /xo-vm-backups/12fb9fcb-edd2-a349-c1a3-af0b39a4bee3/vdis/dfe75d18-94ac-4bd1-a1c7-fb2170e75154/afdb2817-02ef-4003-b5cd-a54eef270b69/20211128T060021Z.vhd of the child /xo-vm-backups/12fb9fcb-edd2-a349-c1a3-af0b39a4bee3/vdis/dfe75d18-94ac-4bd1-a1c7-fb2170e75154/afdb2817-02ef-4003-b5cd-a54eef270b69/20211129T060015Z.vhd is unused
Dec 09 00:00:41 xo-server[268913]: 2021-12-09T06:00:41.320Z xo:backups:mergeWorker INFO starting
Dec 09 00:00:41 xo-server[268913]: 2021-12-09T06:00:41.463Z xo:backups:mergeWorker INFO the parent /xo-vm-backups/787ada5e-e49d-716f-bdf9-ac7d3fb76195/vdis/dfe75d18-94ac-4bd1-a1c7-fb2170e75154/33e87f85-1afd-4d49-be23-8d88e9ce6bd9/20211128T060025Z.vhd of the child /xo-vm-backups/787ada5e-e49d-716f-bdf9-ac7d3fb76195/vdis/dfe75d18-94ac-4bd1-a1c7-fb2170e75154/33e87f85-1afd-4d49-be23-8d88e9ce6bd9/20211129T060035Z.vhd is unused
Dec 09 00:00:41 xo-server[268913]: 2021-12-09T06:00:41.464Z xo:backups:mergeWorker INFO merging /xo-vm-backups/787ada5e-e49d-716f-bdf9-ac7d3fb76195/vdis/dfe75d18-94ac-4bd1-a1c7-fb2170e75154/33e87f85-1afd-4d49-be23-8d88e9ce6bd9/20211129T060035Z.vhd into /xo-vm-backups/787ada5e-e49d-716f-bdf9-ac7d3fb76195/vdis/dfe75d18-94ac-4bd1-a1c7-fb2170e75154/33e87f85-1afd-4d49-be23-8d88e9ce6bd9/20211128T060025Z.vhd
Dec 09 00:00:41 xo-server[268920]: 2021-12-09T06:00:41.625Z xo:backups:mergeWorker INFO starting
Dec 09 00:00:41 xo-server[268920]: 2021-12-09T06:00:41.654Z xo:backups:mergeWorker FATAL Lock file is already being held {
Dec 09 00:00:41 xo-server[268920]:   error: Error: Lock file is already being held
Dec 09 00:00:41 xo-server[268920]:       at /opt/xen-orchestra/node_modules/proper-lockfile/lib/lockfile.js:68:47
Dec 09 00:00:41 xo-server[268920]:       at callback (/opt/xen-orchestra/node_modules/graceful-fs/polyfills.js:299:20)
Dec 09 00:00:41 xo-server[268920]:       at FSReqCallback.oncomplete (node:fs:199:5)
Dec 09 00:00:41 xo-server[268920]:       at FSReqCallback.callbackTrampoline (node:internal/async_hooks:130:17) {
Dec 09 00:00:41 xo-server[268920]:     code: 'ELOCKED',
Dec 09 00:00:41 xo-server[268920]:     file: '/run/xo-server/mounts/remote-2/xo-vm-backups/.queue/clean-vm'
Dec 09 00:00:41 xo-server[268920]:   }
Dec 09 00:00:41 xo-server[268920]: }

Danp

@julien-f said in Warnings & errors in journalctl:

The rename/ENOENT error is not normal

Had this occur again today.

olivierlambert

Do you have multiple XOs accessing the same remote?

julien-f

@danp Latest version contains the fix for multiple tasks at the same second (commit), I would love to see if that helps with it.

Danp

@julien-f Don't think so as I was already on commit f3eeeef.

julien-f

@danp

Do you have an XOA from which I could investigate?

Danp

@julien-f Yes, the free version. Check your PM for support channel details.

julien-f

@danp Just to be clear, the ELOCKED error is not a big deal, it just means that another merge worker is handling this remote, I'm going to change this error to warning instead of fatal

julien-f

@Danp Regarding the rename error, unfortunately I don't see anything on your remote and as this appliance is not the one running the backup or the merge, I don't think I'll be able to gather more info.

Danp

@olivierlambert said in Warnings & errors in journalctl:

Do you have multiple XOs accessing the same remote?

There's only one backup job running from my XO VM. There is an active instance of XOA, but it is just used for testing and is sitting idle.