daily Continuous Replication backup in XO
-
@julien-f can we reproduce?
-
I've setup some tests, we should know more in a couple of hours.
-
Cannot reproduce.
-
@julien-f What is needed from me to understand what's happening? Today restarted my xo after os updates.
-
It would help if you could reproduce the issue with the official XOA, because we know the environment and how it was built.
Or give me a step by step process (with all the backup config) to reproduce the issue.
-
Also, can you go into the directory of
xo-serverand show me the output of this command please:> node -p '[require("./package").version, require("@xen-orchestra/cron/package").version]' -
@julien-f said in daily Continuous Replication backup in XO:
node -p '[require("./package").version, require("@xen-orchestra/cron/package").version]'
[ '5.50.1', '1.0.4' ]The best (or worst), last night after XO restart all backups went without problems. Yesterday I upgraded Ubuntu kernel. And expanded XO disk, because initially it was set too small and there was almost no free space left.
-
@julien-f I have no XOA. I installed XO on top of Ubuntu 18.04 using this script:
https://github.com/Jarli01/xenorchestra_installer
Upgrades are made using another script:
https://github.com/Jarli01/xenorchestra_updater
How to send config to You? -
@karlisi said in daily Continuous Replication backup in XO:
Yesterday I upgraded Ubuntu kernel. And expanded XO disk, because initially it was set too small and there was almost no free space left.
Funny.... I did the exact same thing yesterday in order to upgrade to Ubuntu 19.10. Now my Delta backup job has exhibited this same behavior of running twice after restarting XO.
-
@julien-f said in daily Continuous Replication backup in XO:
It would help if you could reproduce the issue with the official XOA, because we know the environment and how it was built.
I've just replicated it on the latest release channel of XOA. Let me know if you want me to also test it on the stable channel or if you want to remote into the VM to examine the setup.
-
@Danp Thank you,
latestis fine, do you have by any chance a sure process to replicate the issue? -
@julien-f said in daily Continuous Replication backup in XO:
a sure process to replicate the issue
I'm able to replicate it on demand in my environment. Not sure how to translate that into something that would fail elsewhere.
Here's what I did --
- Export config from my XO (sources) VM
- Import config into XOA
- Edit my standard delta backup job to run at new time
- Reboot XOA VM
Here's the screen clip of both jobs --
Here's the failed job's log --
{ "data": { "mode": "delta", "reportWhen": "failure" }, "id": "1571917200008", "jobId": "dfe75d18-94ac-4bd1-a1c7-fb2170e75154", "jobName": "Nightly", "message": "backup", "scheduleId": "cf8b562c-7b0e-46e6-9b53-f78e9c15156c", "start": 1571917200008, "status": "failure", "end": 1571917200031, "result": { "message": "the job (dfe75d18-94ac-4bd1-a1c7-fb2170e75154) is already running", "name": "Error", "stack": "Error: the job (dfe75d18-94ac-4bd1-a1c7-fb2170e75154) is already running\n at /usr/local/lib/node_modules/xo-server/src/xo-mixins/jobs/index.js:272:14\n at Generator.next (<anonymous>)\n at asyncGeneratorStep (/usr/local/lib/node_modules/xo-server/dist/xo-mixins/jobs/index.js:30:103)\n at _next (/usr/local/lib/node_modules/xo-server/dist/xo-mixins/jobs/index.js:32:194)\n at /usr/local/lib/node_modules/xo-server/dist/xo-mixins/jobs/index.js:32:364\n at Promise._execute (/usr/local/lib/node_modules/xo-server/node_modules/bluebird/js/release/debuggability.js:303:9)\n at Promise._resolveFromExecutor (/usr/local/lib/node_modules/xo-server/node_modules/bluebird/js/release/promise.js:483:18)\n at new Promise (/usr/local/lib/node_modules/xo-server/node_modules/bluebird/js/release/promise.js:79:10)\n at /usr/local/lib/node_modules/xo-server/dist/xo-mixins/jobs/index.js:32:97\n at Jobs._runJob (/usr/local/lib/node_modules/xo-server/src/xo-mixins/jobs/index.js:245:60)\n at /usr/local/lib/node_modules/xo-server/src/xo-mixins/jobs/index.js:352:17\n at Generator.next (<anonymous>)\n at asyncGeneratorStep (/usr/local/lib/node_modules/xo-server/dist/xo-mixins/jobs/index.js:30:103)\n at _next (/usr/local/lib/node_modules/xo-server/dist/xo-mixins/jobs/index.js:32:194)\n at tryCatcher (/usr/local/lib/node_modules/xo-server/node_modules/bluebird/js/release/util.js:16:23)\n at Promise._settlePromiseFromHandler (/usr/local/lib/node_modules/xo-server/node_modules/bluebird/js/release/promise.js:512:31)\n at Promise._settlePromise (/usr/local/lib/node_modules/xo-server/node_modules/bluebird/js/release/promise.js:569:18)\n at Promise._settlePromise0 (/usr/local/lib/node_modules/xo-server/node_modules/bluebird/js/release/promise.js:614:10)\n at Promise._settlePromises (/usr/local/lib/node_modules/xo-server/node_modules/bluebird/js/release/promise.js:693:18)\n at Promise._fulfill (/usr/local/lib/node_modules/xo-server/node_modules/bluebird/js/release/promise.js:638:18)\n at PromiseArray._resolve (/usr/local/lib/node_modules/xo-server/node_modules/bluebird/js/release/promise_array.js:126:19)\n at PromiseArray._promiseFulfilled (/usr/local/lib/node_modules/xo-server/node_modules/bluebird/js/release/promise_array.js:144:14)\n at Promise._settlePromise (/usr/local/lib/node_modules/xo-server/node_modules/bluebird/js/release/promise.js:574:26)\n at Promise._settlePromise0 (/usr/local/lib/node_modules/xo-server/node_modules/bluebird/js/release/promise.js:614:10)\n at Promise._settlePromises (/usr/local/lib/node_modules/xo-server/node_modules/bluebird/js/release/promise.js:693:18)\n at Async._drainQueue (/usr/local/lib/node_modules/xo-server/node_modules/bluebird/js/release/async.js:133:16)\n at Async._drainQueues (/usr/local/lib/node_modules/xo-server/node_modules/bluebird/js/release/async.js:143:10)\n at Immediate.Async.drainQueues (/usr/local/lib/node_modules/xo-server/node_modules/bluebird/js/release/async.js:17:14)\n at runCallback (timers.js:810:20)\n at tryOnImmediate (timers.js:768:5)\n at processImmediate [as _immediateCallback] (timers.js:745:5)" } } -
@Danp can you show me the full config of your job please?
-
@julien-f Here's a screenshot. Let me know if that isn't what you meant.
-
@Danp Perfect, thank you for your help
I think this may be an old issue that has become visible since https://github.com/vatesfr/xen-orchestra/issues/4497
-
@Danp Please open a support tunnel in the appliance having the issue, I would like to check the database directly:
xoa support tunnel -
I think I understand how the job can run twice.
What I still don't understand though is how the job can run so soon (14 seconds before) or even exactly one minute before scheduled…
-
-
We've just merged a potential fix, if you could try it that would be great
-
@julien-f Unfortunately, my experience with this latest fix has not been a positive one --
- GUI is unresponsive (spinning graphic only)
- Backup job kicks off improperly (scheduled for midnight)
- Weekly XO report has been generated multiple times
- Timeout show in logs
Oct 25 12:48:31 ubuntutest xo-server[93776]: 2019-10-25T12:48:31.583Z xo:perf INFO blocked for 28525ms Oct 25 12:49:01 ubuntutest xo-server[93776]: _watchEvents { TimeoutError: operation timed out Oct 25 12:49:01 ubuntutest xo-server[93776]: at Promise.timeout (/opt/xen-orchestra/node_modules/promise-toolbox/timeout.js:13:16 ) Oct 25 12:49:01 ubuntutest xo-server[93776]: at /opt/xen-orchestra/packages/xen-api/src/index.js:620:36 Oct 25 12:49:01 ubuntutest xo-server[93776]: at Generator.next (<anonymous>) Oct 25 12:49:01 ubuntutest xo-server[93776]: at asyncGeneratorStep (/opt/xen-orchestra/packages/xen-api/dist/index.js:58:103) Oct 25 12:49:01 ubuntutest xo-server[93776]: at _next (/opt/xen-orchestra/packages/xen-api/dist/index.js:60:194) Oct 25 12:49:01 ubuntutest xo-server[93776]: at /opt/xen-orchestra/packages/xen-api/dist/index.js:60:364 Oct 25 12:49:01 ubuntutest xo-server[93776]: at Promise._execute (/opt/xen-orchestra/node_modules/bluebird/js/release/debuggabili ty.js:427:9) Oct 25 12:49:01 ubuntutest xo-server[93776]: at Promise._resolveFromExecutor (/opt/xen-orchestra/node_modules/bluebird/js/release /promise.js:518:18) Oct 25 12:49:01 ubuntutest xo-server[93776]: at new Promise (/opt/xen-orchestra/node_modules/bluebird/js/release/promise.js:103:1 0) Oct 25 12:49:01 ubuntutest xo-server[93776]: at /opt/xen-orchestra/packages/xen-api/dist/index.js:60:97 Oct 25 12:49:01 ubuntutest xo-server[93776]: at Xapi._call (/opt/xen-orchestra/packages/xen-api/src/index.js:617:71) Oct 25 12:49:01 ubuntutest xo-server[93776]: at /opt/xen-orchestra/packages/xen-api/src/index.js:958:30 Oct 25 12:49:01 ubuntutest xo-server[93776]: at Generator.next (<anonymous>) Oct 25 12:49:01 ubuntutest xo-server[93776]: at asyncGeneratorStep (/opt/xen-orchestra/packages/xen-api/dist/index.js:58:103) Oct 25 12:49:01 ubuntutest xo-server[93776]: at _next (/opt/xen-orchestra/packages/xen-api/dist/index.js:60:194) Oct 25 12:49:01 ubuntutest xo-server[93776]: at tryCatcher (/opt/xen-orchestra/node_modules/bluebird/js/release/util.js:16:23) Oct 25 12:49:01 ubuntutest xo-server[93776]: at Promise._settlePromiseFromHandler (/opt/xen-orchestra/node_modules/bluebird/js/re lease/promise.js:547:31) Oct 25 12:49:01 ubuntutest xo-server[93776]: at Promise._settlePromise (/opt/xen-orchestra/node_modules/bluebird/js/release/promi se.js:604:18) Oct 25 12:49:01 ubuntutest xo-server[93776]: at Promise._settlePromiseCtx (/opt/xen-orchestra/node_modules/bluebird/js/release/pr omise.js:641:10) Oct 25 12:49:01 ubuntutest xo-server[93776]: at _drainQueueStep (/opt/xen-orchestra/node_modules/bluebird/js/release/async.js:97: 12) Oct 25 12:49:01 ubuntutest xo-server[93776]: at _drainQueue (/opt/xen-orchestra/node_modules/bluebird/js/release/async.js:86:9) Oct 25 12:49:01 ubuntutest xo-server[93776]: at Async._drainQueues (/opt/xen-orchestra/node_modules/bluebird/js/release/async.js: 102:5) Oct 25 12:49:01 ubuntutest xo-server[93776]: at Immediate.Async.drainQueues [as _onImmediate] (/opt/xen-orchestra/node_modules/bl uebird/js/release/async.js:15:14) Oct 25 12:49:01 ubuntutest xo-server[93776]: at runCallback (timers.js:810:20) Oct 25 12:49:01 ubuntutest xo-server[93776]: at tryOnImmediate (timers.js:768:5) Oct 25 12:49:01 ubuntutest xo-server[93776]: at processImmediate [as _immediateCallback] (timers.js:745:5) Oct 25 12:49:01 ubuntutest xo-server[93776]: call: Oct 25 12:49:01 ubuntutest xo-server[93776]: { method: 'event.from', Oct 25 12:49:01 ubuntutest xo-server[93776]: params: [ [Array], '00000000000088155376,00000000000088111756', 60.1 ] }, Oct 25 12:49:01 ubuntutest xo-server[93776]: [Symbol(originalCallSite)]: Oct 25 12:49:01 ubuntutest xo-server[93776]: [ CallSite {}, Oct 25 12:49:01 ubuntutest xo-server[93776]: CallSite {}, Oct 25 12:49:01 ubuntutest xo-server[93776]: CallSite {} ], Oct 25 12:49:01 ubuntutest xo-server[93776]: [Symbol(mutatedCallSite)]: Oct 25 12:49:01 ubuntutest xo-server[93776]: [ CallSite {}, Oct 25 12:49:01 ubuntutest xo-server[93776]: CallSite { Oct 25 12:49:01 ubuntutest xo-server[93776]: constructor: [Function: CallSite], Oct 25 12:49:01 ubuntutest xo-server[93776]: getColumnNumber: [Function], Oct 25 12:49:01 ubuntutest xo-server[93776]: getEvalOrigin: [Object], Oct 25 12:49:01 ubuntutest xo-server[93776]: getFileName: [Function], Oct 25 12:49:01 ubuntutest xo-server[93776]: getFunction: [Object], Oct 25 12:49:01 ubuntutest xo-server[93776]: getFunctionName: [Object], Oct 25 12:49:01 ubuntutest xo-server[93776]: getLineNumber: [Function], Oct 25 12:49:01 ubuntutest xo-server[93776]: getMethodName: [Object], Oct 25 12:49:01 ubuntutest xo-server[93776]: getPosition: [Object], Oct 25 12:49:01 ubuntutest xo-server[93776]: getScriptNameOrSourceURL: [Function], Oct 25 12:49:01 ubuntutest xo-server[93776]: getThis: [Object], Oct 25 12:49:01 ubuntutest xo-server[93776]: getTypeName: [Object], Oct 25 12:49:01 ubuntutest xo-server[93776]: isConstructor: [Object], Oct 25 12:49:01 ubuntutest xo-server[93776]: isEval: [Object], Oct 25 12:49:01 ubuntutest xo-server[93776]: isNative: [Object], Oct 25 12:49:01 ubuntutest xo-server[93776]: isToplevel: [Object], Oct 25 12:49:01 ubuntutest xo-server[93776]: toString: [Function: CallSiteToString] }, Oct 25 12:49:01 ubuntutest xo-server[93776]: CallSite {}, Oct 25 12:49:01 ubuntutest xo-server[93776]: CallSite { Oct 25 12:49:01 ubuntutest xo-server[93776]: constructor: [Function: CallSite], Oct 25 12:49:01 ubuntutest xo-server[93776]: getColumnNumber: [Function], Oct 25 12:49:01 ubuntutest xo-server[93776]: getEvalOrigin: [Object], Oct 25 12:49:01 ubuntutest xo-server[93776]: getFileName: [Function], Oct 25 12:49:01 ubuntutest xo-server[93776]: getFunction: [Object], Oct 25 12:49:01 ubuntutest xo-server[93776]: getFunctionName: [Object], Oct 25 12:49:01 ubuntutest xo-server[93776]: getLineNumber: [Function], Oct 25 12:49:01 ubuntutest xo-server[93776]: getMethodName: [Object], Oct 25 12:49:01 ubuntutest xo-server[93776]: getPosition: [Object], Oct 25 12:49:01 ubuntutest xo-server[93776]: getScriptNameOrSourceURL: [Function], Oct 25 12:49:01 ubuntutest xo-server[93776]: getThis: [Object], Oct 25 12:49:01 ubuntutest xo-server[93776]: getTypeName: [Object], Oct 25 12:49:01 ubuntutest xo-server[93776]: isConstructor: [Object], Oct 25 12:49:01 ubuntutest xo-server[93776]: isEval: [Object], Oct 25 12:49:01 ubuntutest xo-server[93776]: isNative: [Object], Oct 25 12:49:01 ubuntutest xo-server[93776]: isToplevel: [Object], Oct 25 12:49:01 ubuntutest xo-server[93776]: toString: [Function: CallSiteToString] }, Oct 25 12:49:01 ubuntutest xo-server[93776]: CallSite { Oct 25 12:49:01 ubuntutest xo-server[93776]: constructor: [Function: CallSite], Oct 25 12:49:01 ubuntutest xo-server[93776]: getColumnNumber: [Function], Oct 25 12:49:01 ubuntutest xo-server[93776]: getEvalOrigin: [Object], Oct 25 12:49:01 ubuntutest xo-server[93776]: getFileName: [Function], Oct 25 12:49:01 ubuntutest xo-server[93776]: getFunction: [Object], Oct 25 12:49:01 ubuntutest xo-server[93776]: getFunctionName: [Object], Oct 25 12:49:01 ubuntutest xo-server[93776]: getLineNumber: [Function], Oct 25 12:49:01 ubuntutest xo-server[93776]: getMethodName: [Object], Oct 25 12:49:01 ubuntutest xo-server[93776]: getPosition: [Object], Oct 25 12:49:01 ubuntutest xo-server[93776]: getScriptNameOrSourceURL: [Function], Oct 25 12:49:01 ubuntutest xo-server[93776]: getThis: [Object], Oct 25 12:49:01 ubuntutest xo-server[93776]: getTypeName: [Object], Oct 25 12:49:01 ubuntutest xo-server[93776]: isConstructor: [Object], Oct 25 12:49:01 ubuntutest xo-server[93776]: isEval: [Object], Oct 25 12:49:01 ubuntutest xo-server[93776]: isNative: [Object], Oct 25 12:49:01 ubuntutest xo-server[93776]: isToplevel: [Object], Oct 25 12:49:01 ubuntutest xo-server[93776]: toString: [Function: CallSiteToString] }, Oct 25 12:49:01 ubuntutest xo-server[93776]: CallSite {}, Oct 25 12:49:01 ubuntutest xo-server[93776]: CallSite {} ] } Oct 25 12:49:01 ubuntutest xo-server[93776]: 2019-10-25T12:49:01.999Z xo:perf INFO blocked for 30316ms- System crashes / restarts
Oct 25 12:50:57 ubuntutest xo-server[93776]: <--- Last few GCs ---> Oct 25 12:50:57 ubuntutest xo-server[93776]: [93776:0x2d80740] 454655 ms: Mark-sweep 1367.1 (1460.1) -> 1367.0 (1460.1) MB, 3439.6 / 0.1 ms allocation failure GC in old space requested Oct 25 12:50:57 ubuntutest xo-server[93776]: [93776:0x2d80740] 457817 ms: Mark-sweep 1367.0 (1460.1) -> 1367.0 (1427.1) MB, 3161.9 / 0.9 ms last resort GC in old space requested Oct 25 12:50:57 ubuntutest xo-server[93776]: [93776:0x2d80740] 459992 ms: Mark-sweep 1367.0 (1427.1) -> 1367.0 (1427.1) MB, 2175.0 / 0.0 ms last resort GC in old space requested Oct 25 12:50:57 ubuntutest xo-server[93776]: <--- JS stacktrace ---> Oct 25 12:50:57 ubuntutest xo-server[93776]: ==== JS stack trace ========================================= Oct 25 12:50:57 ubuntutest xo-server[93776]: Security context: 0x305f21fa5891 <JSObject> Oct 25 12:50:57 ubuntutest xo-server[93776]: 1: /* anonymous */ [/opt/xen-orchestra/packages/xo-server/dist/xo-mixins/logs/index.js:~63] [pc=0x148d528b15e5](this=0x38730f1c8101 <Stream map = 0x2677818c9d71>,data=0x161e745a92a9 <Object map = 0x32a34867fbe9>) Oct 25 12:50:57 ubuntutest xo-server[93776]: 2: emitOne(aka emitOne) [events.js:~114] [pc=0x148d528c5f98](this=0x956b0d822d1 <undefined>,handler=0x38730f1ded49 <JSFunction logger.createReadStream.on.data (sfi = 0x5c6aef025... Oct 25 12:50:57 ubuntutest xo-server[93776]: FATAL ERROR: CALL_AND_RETRY_LAST Allocation failed - JavaScript heap out of memory Oct 25 12:50:57 ubuntutest xo-server[93776]: 1: node::Abort() [/usr/local/bin/node] Oct 25 12:50:57 ubuntutest xo-server[93776]: 2: 0x8cd14c [/usr/local/bin/node] Oct 25 12:50:57 ubuntutest xo-server[93776]: 3: v8::Utils::ReportOOMFailure(char const*, bool) [/usr/local/bin/node] Oct 25 12:50:57 ubuntutest xo-server[93776]: 4: v8::internal::V8::FatalProcessOutOfMemory(char const*, bool) [/usr/local/bin/node] Oct 25 12:50:57 ubuntutest xo-server[93776]: 5: v8::internal::Factory::NewFixedArray(int, v8::internal::PretenureFlag) [/usr/local/bin/node] Oct 25 12:50:57 ubuntutest xo-server[93776]: 6: v8::internal::HashTable<v8::internal::NameDictionary, v8::internal::NameDictionaryShape>::New(v8::internal::Isolate*, int, v8::internal::PretenureFlag, v8::internal::MinimumCapacity) [/usr/local/bin/node] Oct 25 12:50:57 ubuntutest xo-server[93776]: 7: v8::internal::HashTable<v8::internal::NameDictionary, v8::internal::NameDictionaryShape>::EnsureCapacity(v8::internal::Handle<v8::internal::NameDictionary>, int, v8::internal::PretenureFlag) [/usr/local/bin/node] Oct 25 12:50:57 ubuntutest xo-server[93776]: 8: v8::internal::BaseNameDictionary<v8::internal::NameDictionary, v8::internal::NameDictionaryShape>::EnsureCapacity(v8::internal::Handle<v8::internal::NameDictionary>, int) [/usr/local/bin/node] Oct 25 12:50:57 ubuntutest xo-server[93776]: 9: v8::internal::BaseNameDictionary<v8::internal::NameDictionary, v8::internal::NameDictionaryShape>::Add(v8::internal::Handle<v8::internal::NameDictionary>, v8::internal::Handle<v8::internal::Name>, v8::internal::Handle<v8::internal::Object>, v8::internal::PropertyDetails, int*) [/usr/local/bin/node] Oct 25 12:50:57 ubuntutest xo-server[93776]: 10: v8::internal::LookupIterator::ApplyTransitionToDataProperty(v8::internal::Handle<v8::internal::JSObject>) [/usr/local/bin/node] Oct 25 12:50:57 ubuntutest xo-server[93776]: 11: v8::internal::Object::AddDataProperty(v8::internal::LookupIterator*, v8::internal::Handle<v8::internal::Object>, v8::internal::PropertyAttributes, v8::internal::Object::ShouldThrow, v8::internal::Object::StoreFromKeyed) [/usr/local/bin/node] Oct 25 12:50:57 ubuntutest xo-server[93776]: 12: v8::internal::Object::SetProperty(v8::internal::LookupIterator*, v8::internal::Handle<v8::internal::Object>, v8::internal::LanguageMode, v8::internal::Object::StoreFromKeyed) [/usr/local/bin/node] Oct 25 12:50:57 ubuntutest xo-server[93776]: 13: v8::internal::Runtime_SetProperty(int, v8::internal::Object**, v8::internal::Isolate*) [/usr/local/bin/node] Oct 25 12:50:57 ubuntutest xo-server[93776]: 14: 0x148d525842fd Oct 25 12:50:58 ubuntutest systemd[1]: xo-server.service: Main process exited, code=dumped, status=6/ABRT Oct 25 12:50:58 ubuntutest systemd[1]: xo-server.service: Failed with result 'core-dump'. Oct 25 12:50:58 ubuntutest systemd[1]: xo-server.service: Service RestartSec=100ms expired, scheduling restart. Oct 25 12:50:58 ubuntutest systemd[1]: xo-server.service: Scheduled restart job, restart counter is at 1. Oct 25 12:50:58 ubuntutest systemd[1]: Stopped XO Server. Oct 25 12:50:58 ubuntutest systemd[1]: Started XO Server. Oct 25 12:51:08 ubuntutest xo-server[93989]: 2019-10-25T12:51:08.660Z app-conf /opt/xen-orchestra/packages/xo-server/config.toml Oct 25 12:51:08 ubuntutest xo-server[93989]: 2019-10-25T12:51:08.692Z xo:main INFO Configuration loaded.
