backup mail report says INTERRUPTED but it's not ?

Pilow

we have a strange behavior in the mail reports of XOA Backup.

the backup is done, we see the delta point on the remote, in XOA it's all green, no sign of INTERRUPTED, but the mail report tells otherwise :

the "INTERRUPTION" seems to happen on the remote

the point in the remote :
in XOA logs :

other backups are okay, this same one will be okay too tonight...

what is happening ?
false alarm ? @florent @bastien-nollet

{
  "data": {
    "mode": "delta",
    "reportWhen": "always"
  },
  "id": "1766680469800",
  "jobId": "87966399-d428-431d-a067-bb99a8fdd67a",
  "jobName": "BCK_C_xxxx",
  "message": "backup",
  "proxyId": "5359db6e-841b-4a6d-b5e6-a5d19f43b6c0",
  "scheduleId": "56872f53-4c20-47fc-8542-2cd9aed2fdde",
  "start": 1766680469800,
  "status": "success",
  "infos": [
    {
      "data": {
        "vms": [
          "b1eef06b-52c1-e02a-4f59-1692194e2376"
        ]
      },
      "message": "vms"
    }
  ],
  "tasks": [
    {
      "data": {
        "type": "VM",
        "id": "b1eef06b-52c1-e02a-4f59-1692194e2376",
        "name_label": "xxxx"
      },
      "id": "1766680472044",
      "message": "backup VM",
      "start": 1766680472044,
      "status": "success",
      "tasks": [
        {
          "id": "1766680472050",
          "message": "clean-vm",
          "start": 1766680472050,
          "status": "success",
          "end": 1766680473396,
          "result": {
            "merge": false
          }
        },
        {
          "id": "1766680474042",
          "message": "snapshot",
          "start": 1766680474042,
          "status": "success",
          "end": 1766680504544,
          "result": "c4b42a79-532e-c376-833b-22707ddad571"
        },
        {
          "data": {
            "id": "92ed64a4-e073-4fe9-8db9-11770b7ea2da",
            "isFull": false,
            "type": "remote"
          },
          "id": "1766680504544:0",
          "message": "export",
          "start": 1766680504544,
          "status": "success",
          "tasks": [
            {
              "id": "1766680511990",
              "message": "transfer",
              "start": 1766680511990,
              "status": "success",
              "end": 1766680515706,
              "result": {
                "size": 423624704
              }
            },
            {
              "id": "1766680521053",
              "message": "clean-vm",
              "start": 1766680521053,
              "status": "success",
              "tasks": [
                {
                  "id": "1766680521895",
                  "message": "merge",
                  "start": 1766680521895,
                  "status": "success",
                  "end": 1766680530887
                }
              ],
              "end": 1766680531173,
              "result": {
                "merge": true
              }
            }
          ],
          "end": 1766680531192
        }
      ],
      "infos": [
        {
          "message": "Transfer data using NBD"
        },
        {
          "message": "will delete snapshot data"
        },
        {
          "data": {
            "vdiRef": "OpaqueRef:d8aef4c9-5514-6623-1cda-f5e879c4990f"
          },
          "message": "Snapshot data has been deleted"
        }
      ],
      "end": 1766680531211
    }
  ],
  "end": 1766680531267
}

Pilow

some timeout or race condition between the end of the job and the mail generation ?

perhaps putting 10sec delay to send mail ?

Pilow

seeing more and more of this INTERRUPTED issue in mail reports.. anyone has this also ?

florent

@Pilow the run logs ( in backups ) are marked as success ?

Pilow

@florent yes they are, I screenshoted earlier in the thread

Bastien Nollet

Hi @pilow,

Currently, I don't know what would cause this or why this would happen more frequently.

Could you test on your own to add some delay before sending the report, to see if it's indeed a race condition?

To do that, you just need to edit the file packages/xo-server-backup-reports/dist/index.js by adding these two lines:

const delay = ms => new Promise(resolve => setTimeout(resolve, ms));
await delay(10000);

at the beginning of the _report function, like this:

  async _report(runJobId, {
    type
  } = {}, force) {
    const delay = ms => new Promise(resolve => setTimeout(resolve, ms));
    await delay(10000);
    if (type === 'call') {
      return;
    }

then just restart xo-server.

Pilow

@Bastien-Nollet said in backup mail report says INTERRUPTED but it's not ?:

file packages/xo-server-backup-reports/dist/index.js by a

modification done, will give feedback

Pilow

here is a first feedback of this annoying INTERRUPTED random issue (╯‵□′)╯︵┻━┻

Started 12/10/2025 to appear (filtered view of mail inbox on word INTERRUPTED)

All these backups are indeed SUCCESS in XOA, are present on the remotes, are restorable.
We have 14 backup reports each day. As you can see, some days no interrupted, some days multiple ones.
Backups are spanned from noon to late at night.

Today (after applying your patch code) was either a good day, or patch succedeed ¯\_(ツ)_/¯

Will keep looking for rogue INTERRUPTIONs

olivierlambert

@Pilow Thanks, it's promising but we'll wait for more runs on your side If it's that, at least it's not a biggie in the end!

Bastien Nollet

I agree, let's wait for more runs.

If it's indeed a race condition, we'll still have to figure out a better way to settle this than just adding delay

Pilow

@Bastien-Nollet new day without false INTERRUPTED

the scrutiny of backup email reports made me find a new bug in backups (not reports this time)
i'll create a new topic about the dreaded BACKUP FELL BACK TO A FULL --> can provoke it on purpose !

Bastien Nollet

Thanks @Pilow for the tests.

We'll have to investigate this to fix it more properly than adding a ugly delay.

Pilow

@Bastien-Nollet another good day

I think i'll swap to feedback if problem is back than problem is not here anymore

on your side to find something sexier than delay ^^' but it seems to be a race condition

Bastien Nollet

Hi @Pilow,

Thanks again for the feedback, I think now we have enough data to be sure it's indeed a race condition.

We noticed that the log you sent earlier in this topic is a backup job using a proxy. Could you tell if the backup jobs that ended up with a wrong status in the report were all using a proxy, or not all of them?

Pilow

@Bastien-Nollet 100% of our backup jobs are done by proxy
we offload that of main XOA that is purely for administration/management

Bastien Nollet

Hi @Pilow,

I've done some more testing and looked at the code, and I wasn't able to reproduce this behaviour once. It's also unclear to me why it can happen.

We may just add the delay as you did, but 10s is probably too long. Could you try to replace it by a 1s delay instead, and tell us if it's enough?

Pilow

@Bastien-Nollet okay i'll do that tonight and will report back

Pilow

26 backups in a row without interruption, spanning 2 days
And i'm on the 1 second fix

guess it is enough...

@Bastien-Nollet said in backup mail report says INTERRUPTED but it's not ?:

I've done some more testing and looked at the code, and I wasn't able to reproduce this behaviour once. It's also unclear to me why it can happen.

I didn't tell but my Remotes are S3 Remotes... could it be because of that ?

Bastien Nollet

Thanks again @Pilow

I don't think the remotes being S3 changes something here.

Pilow

@Bastien-Nollet oopsy.

sadly, INTERRUPTED is back....

this is what I see in the backup report (a backup job of 12VMs to same S3 remote, only 1 interrupted...)

backup JOB in XOA is all green :
03abdc57-a761-48d8-8792-0de26dc0f926-{54BD11D9-3000-47FA-A097-8BD0FC6B8AC9}.png

621c5379-13a5-4966-af10-3cc37ccf20e0-{0406BF7F-B18D-41E8-AD2A-587E6D4AFCC1}.png