XO task watcher issue/CR broken

[Andrew]

@julien-f node.js v18.14.0 on Debian 11.6

[julien-f]

@Andrew What kind of remote are you using? And with which configuration (encryption, multiple data blocks, etc)?

[julien-f]

My bad, there is no remote with CR

I have no idea what's going though…

[Andrew]

@julien-f I was just going to say it's another host local storage, not a remote. Desination host is not in the same pool but is on the same 10GB LAN. All hosts are 8.2.1.

[julien-f]

@Andrew I'm unable to reproduce on my end

If you can reproduce with an official XOA, open a support tunnel and I'll investigate further.

[Andrew]

@julien-f I loaded XOA (5.109.0) but it's not new enough to include to problematic code that cause problems in XO source.

[julien-f]

@Andrew If you open a support tunnel, I can deploy a sources XO in your appliance.

[Andrew]

@julien-f ok.

[julien-f]

@Andrew Please test the branch cr-issue and tell me if that helps.

[Andrew]

@julien-f cr-issue branch commit 27d81 resolved this new CR problem for me. Thanks!

[julien-f]

@Andrew I need to understand why it's working now

Which version of XCP-ng/XenServer are you using as source and as the target of the CR?

[Gheppy]

This commit 27d81 is working for me to.
XCP-ng is 8.2.1, up to date

[julien-f]

@Andrew & @Gheppy: I've just pushed a new commit in the cr-issue branch which adds some debug logs, it adds something like that:

putResource(b1imtu1j0y): taskRef: OpaqueRef:10eb89fd-d31e-495b-955d-672c61a4ea48
putResource(b1imtu1j0y): useHack: false
putResource(b1imtu1j0y): body#end
putResource(b1imtu1j0y): request#unpipe
putResource(b1imtu1j0y): request#prefinish
putResource(b1imtu1j0y): request#finish
putResource(b1imtu1j0y): response#resume
putResource(b1imtu1j0y): body#close
putResource(b1imtu1j0y): response#readable
putResource(b1imtu1j0y): response#end
putResource(b1imtu1j0y): response#close
putResource(b1imtu1j0y): request#close

If you could try it and show me the output, that would help me understand what's going on

[olivierlambert]

Eager to read the output, it's weird we can't reproduce here, there's something

[Gheppy]

@julien-f
with command -- journalctl -u xo-server -f -n 70

Feb 10 13:33:31 tb-xoce-e-19 xo-server[32712]: putResource(ty99546973n): body#drain
Feb 10 13:33:31 tb-xoce-e-19 xo-server[32712]: putResource(vcybyae8pn): body#drain
Feb 10 13:33:31 tb-xoce-e-19 xo-server[32712]: putResource(ty99546973n): body#drain
Feb 10 13:33:31 tb-xoce-e-19 xo-server[32712]: putResource(vcybyae8pn): body#drain
Feb 10 13:33:31 tb-xoce-e-19 xo-server[32712]: putResource(ty99546973n): body#drain
Feb 10 13:33:32 tb-xoce-e-19 xo-server[32712]: putResource(ty99546973n): response#readable
Feb 10 13:33:32 tb-xoce-e-19 xo-server[32712]: putResource(ty99546973n): request#close
Feb 10 13:33:32 tb-xoce-e-19 xo-server[32712]: putResource(ty99546973n): request#unpipe
Feb 10 13:33:32 tb-xoce-e-19 xo-server[32712]: putResource(ty99546973n): body#error
Feb 10 13:33:32 tb-xoce-e-19 xo-server[32712]: putResource(ty99546973n): body#unpipe
Feb 10 13:33:32 tb-xoce-e-19 xo-server[32712]: putResource(ty99546973n): body#close
Feb 10 13:33:32 tb-xoce-e-19 xo-server[32712]: putResource(ty99546973n): response#resume
Feb 10 13:33:32 tb-xoce-e-19 xo-server[32712]: putResource(ty99546973n): response#end
Feb 10 13:33:32 tb-xoce-e-19 xo-server[32712]: putResource(ty99546973n): response#close
Feb 10 13:33:32 tb-xoce-e-19 xo-server[32712]: putResource(vcybyae8pn): response#readable
Feb 10 13:33:32 tb-xoce-e-19 xo-server[32712]: putResource(vcybyae8pn): request#close
Feb 10 13:33:32 tb-xoce-e-19 xo-server[32712]: putResource(vcybyae8pn): request#unpipe
Feb 10 13:33:32 tb-xoce-e-19 xo-server[32712]: putResource(vcybyae8pn): body#error
Feb 10 13:33:32 tb-xoce-e-19 xo-server[32712]: putResource(vcybyae8pn): body#unpipe
Feb 10 13:33:32 tb-xoce-e-19 xo-server[32712]: putResource(vcybyae8pn): body#close
Feb 10 13:33:32 tb-xoce-e-19 xo-server[32712]: putResource(vcybyae8pn): response#resume
Feb 10 13:33:32 tb-xoce-e-19 xo-server[32712]: putResource(vcybyae8pn): response#end
Feb 10 13:33:32 tb-xoce-e-19 xo-server[32712]: putResource(vcybyae8pn): response#close
Feb 10 13:34:05 tb-xoce-e-19 xo-server[32617]: [WARN] plugin transport-email: Error: No recipients defined
Feb 10 13:34:05 tb-xoce-e-19 xo-server[32617]:     at SMTPConnection._formatError (/opt/xen-orchestra/node_modules/nodemailer/lib/smtp-connection/index.js:790:19)
Feb 10 13:34:05 tb-xoce-e-19 xo-server[32617]:     at SMTPConnection._setEnvelope (/opt/xen-orchestra/node_modules/nodemailer/lib/smtp-connection/index.js:1007:34)
Feb 10 13:34:05 tb-xoce-e-19 xo-server[32617]:     at SMTPConnection.send (/opt/xen-orchestra/node_modules/nodemailer/lib/smtp-connection/index.js:621:14)
Feb 10 13:34:05 tb-xoce-e-19 xo-server[32617]:     at sendMessage (/opt/xen-orchestra/node_modules/nodemailer/lib/smtp-transport/index.js:228:28)
Feb 10 13:34:05 tb-xoce-e-19 xo-server[32617]:     at /opt/xen-orchestra/node_modules/nodemailer/lib/smtp-transport/index.js:289:21
Feb 10 13:34:05 tb-xoce-e-19 xo-server[32617]:     at SMTPConnection.<anonymous> (/opt/xen-orchestra/node_modules/nodemailer/lib/smtp-connection/index.js:213:17)
Feb 10 13:34:05 tb-xoce-e-19 xo-server[32617]:     at Object.onceWrapper (node:events:627:28)
Feb 10 13:34:05 tb-xoce-e-19 xo-server[32617]:     at SMTPConnection.emit (node:events:513:28)
Feb 10 13:34:05 tb-xoce-e-19 xo-server[32617]:     at SMTPConnection.patchedEmit [as emit] (/opt/xen-orchestra/@xen-orchestra/log/configure.js:52:17)
Feb 10 13:34:05 tb-xoce-e-19 xo-server[32617]:     at SMTPConnection._actionEHLO (/opt/xen-orchestra/node_modules/nodemailer/lib/smtp-connection/index.js:1331:14)
Feb 10 13:34:05 tb-xoce-e-19 xo-server[32617]:     at SMTPConnection._processResponse (/opt/xen-orchestra/node_modules/nodemailer/lib/smtp-connection/index.js:953:20)
Feb 10 13:34:05 tb-xoce-e-19 xo-server[32617]:     at SMTPConnection._onData (/opt/xen-orchestra/node_modules/nodemailer/lib/smtp-connection/index.js:755:14)
Feb 10 13:34:05 tb-xoce-e-19 xo-server[32617]:     at Socket.SMTPConnection._onSocketData (/opt/xen-orchestra/node_modules/nodemailer/lib/smtp-connection/index.js:193:44)
Feb 10 13:34:05 tb-xoce-e-19 xo-server[32617]:     at Socket.emit (node:events:513:28)
Feb 10 13:34:05 tb-xoce-e-19 xo-server[32617]:     at Socket.patchedEmit [as emit] (/opt/xen-orchestra/@xen-orchestra/log/configure.js:52:17)
Feb 10 13:34:05 tb-xoce-e-19 xo-server[32617]:     at addChunk (node:internal/streams/readable:324:12)
Feb 10 13:34:05 tb-xoce-e-19 xo-server[32617]:     at readableAddChunk (node:internal/streams/readable:297:9)
Feb 10 13:34:05 tb-xoce-e-19 xo-server[32617]:     at Socket.Readable.push (node:internal/streams/readable:234:10)
Feb 10 13:34:05 tb-xoce-e-19 xo-server[32617]:     at TCP.onStreamRead (node:internal/stream_base_commons:190:23)
Feb 10 13:34:05 tb-xoce-e-19 xo-server[32617]:     at TCP.callbackTrampoline (node:internal/async_hooks:130:17)
Feb 10 13:34:05 tb-xoce-e-19 xo-server[32617]: 2023-02-10T11:34:05.207Z xo:xo-server WARN possibly unhandled rejection {
Feb 10 13:34:05 tb-xoce-e-19 xo-server[32617]:   error: Error: No recipients defined
Feb 10 13:34:05 tb-xoce-e-19 xo-server[32617]:       at SMTPConnection._formatError (/opt/xen-orchestra/node_modules/nodemailer/lib/smtp-connection/index.js:790:19)
Feb 10 13:34:05 tb-xoce-e-19 xo-server[32617]:       at SMTPConnection._setEnvelope (/opt/xen-orchestra/node_modules/nodemailer/lib/smtp-connection/index.js:1007:34)
Feb 10 13:34:05 tb-xoce-e-19 xo-server[32617]:       at SMTPConnection.send (/opt/xen-orchestra/node_modules/nodemailer/lib/smtp-connection/index.js:621:14)
Feb 10 13:34:05 tb-xoce-e-19 xo-server[32617]:       at sendMessage (/opt/xen-orchestra/node_modules/nodemailer/lib/smtp-transport/index.js:228:28)
Feb 10 13:34:05 tb-xoce-e-19 xo-server[32617]:       at /opt/xen-orchestra/node_modules/nodemailer/lib/smtp-transport/index.js:289:21
Feb 10 13:34:05 tb-xoce-e-19 xo-server[32617]:       at SMTPConnection.<anonymous> (/opt/xen-orchestra/node_modules/nodemailer/lib/smtp-connection/index.js:213:17)
Feb 10 13:34:05 tb-xoce-e-19 xo-server[32617]:       at Object.onceWrapper (node:events:627:28)
Feb 10 13:34:05 tb-xoce-e-19 xo-server[32617]:       at SMTPConnection.emit (node:events:513:28)
Feb 10 13:34:05 tb-xoce-e-19 xo-server[32617]:       at SMTPConnection.patchedEmit [as emit] (/opt/xen-orchestra/@xen-orchestra/log/configure.js:52:17)
Feb 10 13:34:05 tb-xoce-e-19 xo-server[32617]:       at SMTPConnection._actionEHLO (/opt/xen-orchestra/node_modules/nodemailer/lib/smtp-connection/index.js:1331:14)
Feb 10 13:34:05 tb-xoce-e-19 xo-server[32617]:       at SMTPConnection._processResponse (/opt/xen-orchestra/node_modules/nodemailer/lib/smtp-connection/index.js:953:20)
Feb 10 13:34:05 tb-xoce-e-19 xo-server[32617]:       at SMTPConnection._onData (/opt/xen-orchestra/node_modules/nodemailer/lib/smtp-connection/index.js:755:14)
Feb 10 13:34:05 tb-xoce-e-19 xo-server[32617]:       at Socket.SMTPConnection._onSocketData (/opt/xen-orchestra/node_modules/nodemailer/lib/smtp-connection/index.js:193:44)
Feb 10 13:34:05 tb-xoce-e-19 xo-server[32617]:       at Socket.emit (node:events:513:28)
Feb 10 13:34:05 tb-xoce-e-19 xo-server[32617]:       at Socket.patchedEmit [as emit] (/opt/xen-orchestra/@xen-orchestra/log/configure.js:52:17)
Feb 10 13:34:05 tb-xoce-e-19 xo-server[32617]:       at addChunk (node:internal/streams/readable:324:12)
Feb 10 13:34:05 tb-xoce-e-19 xo-server[32617]:       at readableAddChunk (node:internal/streams/readable:297:9)
Feb 10 13:34:05 tb-xoce-e-19 xo-server[32617]:       at Socket.Readable.push (node:internal/streams/readable:234:10)
Feb 10 13:34:05 tb-xoce-e-19 xo-server[32617]:       at TCP.onStreamRead (node:internal/stream_base_commons:190:23)
Feb 10 13:34:05 tb-xoce-e-19 xo-server[32617]:       at TCP.callbackTrampoline (node:internal/async_hooks:130:17) {
Feb 10 13:34:05 tb-xoce-e-19 xo-server[32617]:     code: 'EENVELOPE',
Feb 10 13:34:05 tb-xoce-e-19 xo-server[32617]:     command: 'API'
Feb 10 13:34:05 tb-xoce-e-19 xo-server[32617]:   }
Feb 10 13:34:05 tb-xoce-e-19 xo-server[32617]: }

On backup log I have this

{
  "data": {
    "mode": "delta",
    "reportWhen": "always"
  },
  "id": "1676028066913",
  "jobId": "dca46bf4-dca6-4e07-8dab-dc644d6f47c1",
  "jobName": "productie-Sincronizare-Activa-NU-STERGE",
  "message": "backup",
  "scheduleId": "118e0756-3588-4d70-97d8-f6705bc3785f",
  "start": 1676028066913,
  "status": "success",
  "infos": [
    {
      "data": {
        "vms": [
          "629bdfeb-7700-561c-74ac-e151068721c2"
        ]
      },
      "message": "vms"
    }
  ],
  "tasks": [
    {
      "data": {
        "type": "VM",
        "id": "629bdfeb-7700-561c-74ac-e151068721c2"
      },
      "id": "1676028068026:0",
      "message": "backup VM",
      "start": 1676028068026,
      "status": "success",
      "tasks": [
        {
          "id": "1676028068072",
          "message": "snapshot",
          "start": 1676028068072,
          "status": "success",
          "end": 1676028071566,
          "result": "6f52cc17-328e-589a-82a8-c217ac34d6f1"
        },
        {
          "data": {
            "id": "5148208b-acf6-13f3-4f36-5817e3eb6ab1",
            "isFull": false,
            "type": "SR"
          },
          "id": "1676028071568",
          "message": "export",
          "start": 1676028071568,
          "status": "success",
          "tasks": [
            {
              "id": "1676028071596",
              "message": "transfer",
              "start": 1676028071596,
              "status": "success",
              "end": 1676028094729,
              "result": {
                "size": 162336256
              }
            }
          ],
          "end": 1676028107179
        },
        {
          "data": {
            "id": "7a4829c0-e59a-726c-34bc-1a1052b0334f",
            "isFull": false,
            "type": "SR"
          },
          "id": "1676028071567",
          "message": "export",
          "start": 1676028071567,
          "status": "success",
          "tasks": [
            {
              "id": "1676028071592",
              "message": "transfer",
              "start": 1676028071592,
              "status": "success",
              "end": 1676028094954,
              "result": {
                "size": 162336256
              }
            }
          ],
          "end": 1676028110020
        }
      ],
      "end": 1676028129516
    }
  ],
  "end": 1676028129517
}

[julien-f]

@Gheppy Could you please include all the logs up to the taskRef entry?

[Andrew]

@julien-f Hosts are XCP 8.2.1 and updated.

Here's the logs... It did suppress 373874 messages... only 417267 left...

rename output.txt as output.txt.gz and uncompress.

output.txt

[julien-f]

@Andrew Thank you, I just pushed a new commit in which I suppressed the drain event

[julien-f]

Once filtered, here's what I see:

putResource(hhprvsf5i): taskRef: OpaqueRef:bb9bbc77-8c88-4621-82a7-745197306c3b
putResource(hhprvsf5i): useHack: false
putResource(hhprvsf5i): response#readable
putResource(hhprvsf5i): request#close
putResource(hhprvsf5i): request#unpipe
putResource(hhprvsf5i): body#error
putResource(hhprvsf5i): body#unpipe
putResource(hhprvsf5i): body#close
putResource(hhprvsf5i): response#resume
putResource(hhprvsf5i): response#end
putResource(hhprvsf5i): response#close

I don't understand why there is not a request#finish event like in my test

[julien-f]

It's probably related to the body#error event.

I will add more debug and will keep you posted when the branch is ready.