Repeated backup failures with an app

[SansGuidon]

So far the problem seems gone. Backups take quite some time and make me thing the process is sometimes stuck but that's likely related to the storage speed, I guess.
Anyway I consider the situation resolved, for now.

[nebulon]

Glad it works now, possibly something was off on that one folder then, preventing or stalling the delete operation from the backup task.

[SansGuidon]

Having a look at the global backup task log now it seems to take hours and seems stuck.

...
Sep 27 01:44:36 box:tasks update 2644: {"percent":46.45454545454546,"message":"Copying +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/oHYKKHsp5nbpcywk51Jh-qadnitsJW2gf8LvyNVo0p4/JFrg5i70q68kJ2fb9TRxQhKuzyM8e7TIid8hUpVNUnTUO2OC0n9TVKwiecXpntDKgFWTRVg8zyOQHxFtrW9PSg/1Ff2uDiq0FJBiCASx828-rX19mPZIlvvTv9KasnL+Mvpze7LPXu-Aa5KDMUAKrsv2IsmgXUH+SrWKbG2G8cmWg/GVjP4aiFVvSHFik-l75pxFHEU5NkaRki6FhmG+jhGMs/el1yUFt9q+vF7wU+PUorQh+bug+RPb4XPDCqGBLTBwNqqV9oaNgs7sod7Zdv2SS04cAaBlBBAsdoO7YCQNPWoH9hAFMgN1t8IgsSXIGJA+E"}
Sep 27 01:44:36 box:tasks update 2644: {"percent":46.45454545454546,"message":"Copying +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/oHYKKHsp5nbpcywk51Jh-qadnitsJW2gf8LvyNVo0p4/JFrg5i70q68kJ2fb9TRxQhKuzyM8e7TIid8hUpVNUnTUO2OC0n9TVKwiecXpntDKgFWTRVg8zyOQHxFtrW9PSg/1Ff2uDiq0FJBiCASx828-rX19mPZIlvvTv9KasnL+Mvpze7LPXu-Aa5KDMUAKrsv2IsmgXUH+SrWKbG2G8cmWg/GVjP4aiFVvSHFik-l75pxFHEU5NkaRki6FhmG+jhGMs/gR0FKpwmXOTt448s20n9Vdx9u6+X6MkYRsXhspsAlpBk3FiDd2J-KAzccYVT7KBvHDPpJte97we20tfT+68tnMgiqocFrVAFafDmK9IZht0"}
Sep 27 01:44:38 box:tasks update 2644: {"percent":46.45454545454546,"message":"Copying +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/oHYKKHsp5nbpcywk51Jh-qadnitsJW2gf8LvyNVo0p4/JFrg5i70q68kJ2fb9TRxQhKuzyM8e7TIid8hUpVNUnTUO2OC0n9TVKwiecXpntDKgFWTRVg8zyOQHxFtrW9PSg/1Ff2uDiq0FJBiCASx828-rX19mPZIlvvTv9KasnL+Mvpze7LPXu-Aa5KDMUAKrsv2IsmgXUH+SrWKbG2G8cmWg/GVjP4aiFVvSHFik-l75pxFHEU5NkaRki6FhmG+jhGMs/h6ktzTFHvXAhKQZ+Rpo3kADFcNS8datgzudLKX-sLCRuE1tVqUy32talVF9iDgdncfA6pTlC775D2O2A9BNobAnOKSTDdwoMbAxzbygYVSQ"}
Sep 27 01:44:40 box:tasks update 2644: {"percent":46.45454545454546,"message":"Copying +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/oHYKKHsp5nbpcywk51Jh-qadnitsJW2gf8LvyNVo0p4/JFrg5i70q68kJ2fb9TRxQhKuzyM8e7TIid8hUpVNUnTUO2OC0n9TVKwiecXpntDKgFWTRVg8zyOQHxFtrW9PSg/1Ff2uDiq0FJBiCASx828-rX19mPZIlvvTv9KasnL+Mvpze7LPXu-Aa5KDMUAKrsv2IsmgXUH+SrWKbG2G8cmWg/GVjP4aiFVvSHFik-l75pxFHEU5NkaRki6FhmG+jhGMs/hPzcGoNkm2GxUeaTMkz1IiWPuEmsRThMX8c3UfmPrm290IRjwX0rtpRlwdaQSehxB0lcf6iITQjgiq1vkgpmmwyhSoQ17IlyhsM5-1qo6gk"}
...
Sep 27 01:44:52 box:tasks update 2644: {"percent":46.45454545454546,"message":"Copying +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/oHYKKHsp5nbpcywk51Jh-qadnitsJW2gf8LvyNVo0p4/JFrg5i70q68kJ2fb9TRxQhKuzyM8e7TIid8hUpVNUnTUO2OC0n9TVKwiecXpntDKgFWTRVg8zyOQHxFtrW9PSg/1Ff2uDiq0FJBiCASx828-rX19mPZIlvvTv9KasnL+Mvpze7LPXu-Aa5KDMUAKrsv2IsmgXUH+SrWKbG2G8cmWg/GVjP4aiFVvSHFik-l75pxFHEU5NkaRki6FhmG+jhGMs/wgORAkMQVHW4qqcDF08dDJNd5-2MLWPgoCHrqp-QyQy-++08LktkkrBcwMqEuOy4BCrwNKcWGqcD+fiHjdE7RRyNT-i6HpJaVTPoG-O4F04"}
Sep 27 01:44:52 box:tasks update 2644: {"percent":46.45454545454546,"message":"Copying +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/oHYKKHsp5nbpcywk51Jh-qadnitsJW2gf8LvyNVo0p4/JFrg5i70q68kJ2fb9TRxQhKuzyM8e7TIid8hUpVNUnTUO2OC0n9TVKwiecXpntDKgFWTRVg8zyOQHxFtrW9PSg/1Ff2uDiq0FJBiCASx828-rX19mPZIlvvTv9KasnL+Mvpze7LPXu-Aa5KDMUAKrsv2IsmgXUH+SrWKbG2G8cmWg/GVjP4aiFVvSHFik-l75pxFHEU5NkaRki6FhmG+jhGMs/wizHcd-CKCvyUKH4svkmfrplXa-60Z-HA5NkCt71xKlSup+UWMWYLH37Ns086sRdmbPj+YMICTzZ5O6jAK9xn1CG1HuClQe9uHaY5kEY-YU"}
Sep 27 01:44:52 box:tasks update 2644: {"percent":46.45454545454546,"message":"Copying +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/oHYKKHsp5nbpcywk51Jh-qadnitsJW2gf8LvyNVo0p4/JFrg5i70q68kJ2fb9TRxQhKuzyM8e7TIid8hUpVNUnTUO2OC0n9TVKwiecXpntDKgFWTRVg8zyOQHxFtrW9PSg/1Ff2uDiq0FJBiCASx828-rX19mPZIlvvTv9KasnL+Mvpze7LPXu-Aa5KDMUAKrsv2IsmgXUH+SrWKbG2G8cmWg/GVjP4aiFVvSHFik-l75pxFHEU5NkaRki6FhmG+jhGMs/yMYYgXsnQ8fAlolxbAQa0iTygfSYXFFIap2ANUDZFyjwOqxo8SKkBRVDUXMkGXy9FtFgltKqACBLEpry90N8PaItwL4hGcEXIMVvDOUSLh4"}
Sep 27 01:44:52 box:tasks update 2644: {"percent":46.45454545454546,"message":"Copying +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/oHYKKHsp5nbpcywk51Jh-qadnitsJW2gf8LvyNVo0p4/JFrg5i70q68kJ2fb9TRxQhKuzyM8e7TIid8hUpVNUnTUO2OC0n9TVKwiecXpntDKgFWTRVg8zyOQHxFtrW9PSg/1Ff2uDiq0FJBiCASx828-rX19mPZIlvvTv9KasnL+Mvpze7LPXu-Aa5KDMUAKrsv2IsmgXUH+SrWKbG2G8cmWg/GVjP4aiFVvSHFik-l75pxFHEU5NkaRki6FhmG+jhGMs/zad6Ziin-IUOOGGk-bgP4Awxl59Xz4lsVVLBG7u7JVRSzMRktpSo+ecRzP-qlIThIVUgs8sNg6JNgDUfyFYiSw-NZPgKi4z+Gw4Uhp56mfc"}
Sep 27 01:44:52 box:tasks update 2644: {"percent":46.45454545454546,"message":"Copying +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/oHYKKHsp5nbpcywk51Jh-qadnitsJW2gf8LvyNVo0p4/JFrg5i70q68kJ2fb9TRxQhKuzyM8e7TIid8hUpVNUnTUO2OC0n9TVKwiecXpntDKgFWTRVg8zyOQHxFtrW9PSg/1Ff2uDiq0FJBiCASx828-rX19mPZIlvvTv9KasnL+Mvpze7LPXu-Aa5KDMUAKrsv2IsmgXUH+SrWKbG2G8cmWg/GVjP4aiFVvSHFik-l75pxFHEU5NkaRki6FhmG+jhGMs/zj5fRln7KTdIyTG6J1TCBWdxezzyVEJDSFoOqzTI94dnO6Riatt5CRcbYUNo53lh3FOy5AmtJBvpfg7Z+oKFv+SZ4L9qRaMyxoXDgIBo7KE"}
...
Sep 27 03:14:36 box:tasks update 2644: {"percent":46.45454545454546,"message":"Retrying (1) copy of +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/oHYKKHsp5nbpcywk51Jh-qadnitsJW2gf8LvyNVo0p4/JFrg5i70q68kJ2fb9TRxQhKuzyM8e7TIid8hUpVNUnTUO2OC0n9TVKwiecXpntDKgFWTRVg8zyOQHxFtrW9PSg/1Ff2uDiq0FJBiCASx828-rX19mPZIlvvTv9KasnL+Mvpze7LPXu-Aa5KDMUAKrsv2IsmgXUH+SrWKbG2G8cmWg/GVjP4aiFVvSHFik-l75pxFHEU5NkaRki6FhmG+jhGMs/c+jYf5xr76gq81FCK1fDUc4UaSVhb4WTTO6cglNK4GqIiyQ5p5WJWcMhPDFEHreldB-rSc7EC9fYqPXOsvILjjszUIM13ZuWGWH2wPpJLms. Error: 504: null 504"}
...
Sep 27 04:45:17 box:tasks update 2644: {"percent":46.45454545454546,"message":"Retrying (2) copy of +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/oHYKKHsp5nbpcywk51Jh-qadnitsJW2gf8LvyNVo0p4/JFrg5i70q68kJ2fb9TRxQhKuzyM8e7TIid8hUpVNUnTUO2OC0n9TVKwiecXpntDKgFWTRVg8zyOQHxFtrW9PSg/U58FuxWQmXM04fxhZkwwPmOrt7d3+rOSLfCHv07RhU2zX-4cA2Wj-QxqshI1UxxaqIQ7Re4iFVBC+VBOcdleWg/GVjP4aiFVvSHFik-l75pxFHEU5NkaRki6FhmG+jhGMs/YFtYX5hLWzIKz8PIqgtS216yGWBtdNs0+u9PEsKHYgyW9MQdpYxKvHFXWqGiElQnE3EiLZAl2DOVzWrHFGPBhEh9LQLkjK+J24WNb8qcEtI. Error: 504: null 504"}
Sep 27 06:15:15 box:tasks update 2644: {"percent":46.45454545454546,"message":"Retrying (3) copy of +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/oHYKKHsp5nbpcywk51Jh-qadnitsJW2gf8LvyNVo0p4/JFrg5i70q68kJ2fb9TRxQhKuzyM8e7TIid8hUpVNUnTUO2OC0n9TVKwiecXpntDKgFWTRVg8zyOQHxFtrW9PSg/1Ff2uDiq0FJBiCASx828-rX19mPZIlvvTv9KasnL+Mvpze7LPXu-Aa5KDMUAKrsv2IsmgXUH+SrWKbG2G8cmWg/GVjP4aiFVvSHFik-l75pxFHEU5NkaRki6FhmG+jhGMs/c+jYf5xr76gq81FCK1fDUc4UaSVhb4WTTO6cglNK4GqIiyQ5p5WJWcMhPDFEHreldB-rSc7EC9fYqPXOsvILjjszUIM13ZuWGWH2wPpJLms. Error: 504: null 504"}
Sep 27 06:15:15 box:tasks update 2644: {"percent":46.45454545454546,"message":"Retrying (3) copy of +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/oHYKKHsp5nbpcywk51Jh-qadnitsJW2gf8LvyNVo0p4/JFrg5i70q68kJ2fb9TRxQhKuzyM8e7TIid8hUpVNUnTUO2OC0n9TVKwiecXpntDKgFWTRVg8zyOQHxFtrW9PSg/1Ff2uDiq0FJBiCASx828-rX19mPZIlvvTv9KasnL+Mvpze7LPXu-Aa5KDMUAKrsv2IsmgXUH+SrWKbG2G8cmWg/GVjP4aiFVvSHFik-l75pxFHEU5NkaRki6FhmG+jhGMs/ed9-XRtQPFH6Pf9GgV8TPUZWfSTmtHIIxWvxApn-MgMGDN7hu64edxFVB7KVKXfbctH0mKpX3NjzOHT5Z+xQfawNBGLjZNQqrN0LmpY4AGU. Error: 504: null 504"}
Sep 27 06:15:34 box:tasks update 2644: {"percent":46.45454545454546,"message":"Retrying (3) copy of +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/oHYKKHsp5nbpcywk51Jh-qadnitsJW2gf8LvyNVo0p4/JFrg5i70q68kJ2fb9TRxQhKuzyM8e7TIid8hUpVNUnTUO2OC0n9TVKwiecXpntDKgFWTRVg8zyOQHxFtrW9PSg/U58FuxWQmXM04fxhZkwwPmOrt7d3+rOSLfCHv07RhU2zX-4cA2Wj-QxqshI1UxxaqIQ7Re4iFVBC+VBOcdleWg/GVjP4aiFVvSHFik-l75pxFHEU5NkaRki6FhmG+jhGMs/KySiM+lFfMMIsqgY0F6zzeH46Aqt8xCkFCfzuN0odSLoxdyIcZTwiZcAi3FZ3hdrAA-OoG4LkTwcapOtohQCzvjssKpo4dmSeBRLY8rEJDM. Error: 504: null 504"}
Sep 27 06:15:36 box:tasks update 2644: {"percent":46.45454545454546,"message":"Retrying (3) copy of +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/oHYKKHsp5nbpcywk51Jh-qadnitsJW2gf8LvyNVo0p4/JFrg5i70q68kJ2fb9TRxQhKuzyM8e7TIid8hUpVNUnTUO2OC0n9TVKwiecXpntDKgFWTRVg8zyOQHxFtrW9PSg/U58FuxWQmXM04fxhZkwwPmOrt7d3+rOSLfCHv07RhU2zX-4cA2Wj-QxqshI1UxxaqIQ7Re4iFVBC+VBOcdleWg/GVjP4aiFVvSHFik-l75pxFHEU5NkaRki6FhmG+jhGMs/YFtYX5hLWzIKz8PIqgtS216yGWBtdNs0+u9PEsKHYgyW9MQdpYxKvHFXWqGiElQnE3EiLZAl2DOVzWrHFGPBhEh9LQLkjK+J24WNb8qcEtI. Error: 504: null 504"}

Not having my laptop with me to look further until Monday, only other thing I notice is the increasing huge size of backups on remote storage, like 90-100GB of backups for maybe a few hundred MBs worth of data for some apps.

Current status is Retrying (4) copy of +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/oHYKKHsp5nbpcywk51Jh-qadnitsJW2gf8LvyNVo0p4/JFrg5i70q68kJ2fb9TRxQhKuzyM8e7TIid8hUpVNUnTUO2OC0n9TVKwiecXpntDKgFWT

[SansGuidon]

So far it's progressing again, around 20% further, after 3 hours

Sep 27 09:34:54 box:tasks update 2644: {"percent":64.63636363636364,"message":"Copying +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/bCsBHeTNFOA0PMfeHwtd1DqpwCaS0XLjnW+4F8ZpP4g/OZ18TuP+eoUKZmW0j54+-6KQXwFof55visHM89cem4A/kMAZeKzls8+PKNLMRAfK8MAGYpb9DqXiZHcZPkdUaSA/5pa6SeARNoGyhcT1VO4sfWspp5yLCxPK5JkT6fEId9s/hLfwbzJOjjuoazhfyFRSV+OeZ78xlTbZId3UjUrO6aw"}
Sep 27 09:34:55 box:tasks update 2644: {"percent":64.63636363636364,"message":"Copying +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/bCsBHeTNFOA0PMfeHwtd1DqpwCaS0XLjnW+4F8ZpP4g/OZ18TuP+eoUKZmW0j54+-6KQXwFof55visHM89cem4A/kMAZeKzls8+PKNLMRAfK8MAGYpb9DqXiZHcZPkdUaSA/5pa6SeARNoGyhcT1VO4sfWspp5yLCxPK5JkT6fEId9s/hunSoQUKa6Z9QyvaoUtpCzgW5vTHNO6PTJhlSF1vqaQ"}
S
...

[SansGuidon]

@nebulon
I still have recurrent backup issues, it seems my daily backups take the whole night to run because of changedetection backup tasks which itself takes 7 hours

For now I've adapted the backup times and updates times to not overlap, as previously it was setup to update up to 4 times a day (11PM, 1AM, 3AM, 5AM) and backup around 1AM, so I was first worried that that backup and updates time were scheduled at the same hour.

$ rg -N -i "backup.*finished" task-2682.log 
2024-10-01T21:00:13.529Z box:backuptask fullBackup: app calibre.**MYDOMAIN** backup finished. Took 10.956 seconds
2024-10-01T21:07:59.625Z box:backuptask fullBackup: app syncthing.**MYDOMAIN** backup finished. Took 466.094 seconds
2024-10-01T21:32:59.350Z box:backuptask fullBackup: app n8n.**MYDOMAIN** backup finished. Took 1499.725 seconds
2024-10-01T21:33:42.927Z box:backuptask fullBackup: app music.**MYDOMAIN** backup finished. Took 43.576 seconds
2024-10-01T21:36:41.189Z box:backuptask fullBackup: app miniflux.**MYDOMAIN** backup finished. Took 178.262 seconds
2024-10-01T21:37:01.494Z box:backuptask fullBackup: app classic.**MYDOMAIN** backup finished. Took 20.305 seconds
2024-10-01T21:39:12.605Z box:backuptask fullBackup: app rssbridge.**MYDOMAIN** backup finished. Took 131.11 seconds
2024-10-01T23:01:11.683Z box:backuptask fullBackup: app nextcloud.**MYDOMAIN** backup finished. Took 4919.077 seconds
2024-10-01T23:01:36.977Z box:backuptask fullBackup: app todo.**MYDOMAIN** backup finished. Took 25.293 seconds
2024-10-01T23:05:57.089Z box:backuptask fullBackup: app invoice.**MYDOMAIN** backup finished. Took 260.111 seconds
2024-10-02T05:59:52.457Z box:backuptask fullBackup: app changedetection.**MYDOMAIN** backup finished. Took 24835.367 seconds
2024-10-02T05:59:54.625Z box:backuptask fullBackup: app collabora.**MYDOMAIN** backup finished. Took 2.168 seconds
2024-10-02T05:59:56.718Z box:backuptask fullBackup: app shaarli.**MYDOMAIN** backup finished. Took 2.093 seconds
2024-10-02T06:53:37.982Z box:backuptask fullBackup: app morgan.**MYDOMAIN** backup finished. Took 3221.263 seconds
2024-10-02T07:06:48.956Z box:backuptask fullBackup: app gitea.**MYDOMAIN** backup finished. Took 790.973 seconds
2024-10-02T07:28:25.837Z box:backuptask fullBackup: app wallabag.**MYDOMAIN** backup finished. Took 1296.88 seconds
2024-10-02T07:28:29.769Z box:backuptask fullBackup: app ntfy.**MYDOMAIN** backup finished. Took 3.931 seconds
2024-10-02T07:28:34.238Z box:backuptask fullBackup: app privatebin.**MYDOMAIN** backup finished. Took 4.469 seconds
2024-10-02T07:31:56.494Z box:backuptask fullBackup: app vault.**MYDOMAIN** backup finished. Took 202.254 seconds

and the lines in error

$ rg -N -i error task-2682.log 
2024-10-01T21:00:04.309Z box:syncer sync: done processing deletes. error: null
2024-10-01T21:00:04.735Z box:syncer sync: done processing adds. error: null
2024-10-01T21:00:04.736Z box:backupupload upload completed. error: null
2024-10-01T21:00:13.523Z box:tasks update 2682: {"percent":5.545454545454546,"message":"Copied 14 files with error: null"}
2024-10-01T21:00:56.018Z box:syncer sync: done processing deletes. error: null
2024-10-01T21:01:32.075Z box:syncer sync: done processing adds. error: null
2024-10-01T21:01:32.076Z box:backupupload upload completed. error: null
2024-10-01T21:07:59.618Z box:tasks update 2682: {"percent":10.090909090909092,"message":"Copied 366 files with error: null"}
2024-10-01T21:08:03.183Z box:syncer sync: done processing deletes. error: null
2024-10-01T21:08:11.832Z box:syncer sync: done processing adds. error: null
2024-10-01T21:08:11.834Z box:backupupload upload completed. error: null
2024-10-01T21:32:59.346Z box:tasks update 2682: {"percent":14.636363636363637,"message":"Copied 4354 files with error: null"}
2024-10-01T21:33:01.587Z box:syncer sync: done processing deletes. error: null
2024-10-01T21:33:05.030Z box:syncer sync: done processing adds. error: null
2024-10-01T21:33:05.031Z box:backupupload upload completed. error: null
2024-10-01T21:33:42.923Z box:tasks update 2682: {"percent":19.181818181818183,"message":"Copied 80 files with error: null"}
2024-10-01T21:33:52.627Z box:syncer sync: done processing deletes. error: null
2024-10-01T21:36:14.400Z box:syncer sync: done processing adds. error: null
2024-10-01T21:36:14.402Z box:backupupload upload completed. error: null
2024-10-01T21:36:41.185Z box:tasks update 2682: {"percent":23.72727272727273,"message":"Copied 4 files with error: null"}
2024-10-01T21:36:42.845Z box:syncer sync: done processing deletes. error: null
2024-10-01T21:36:44.070Z box:syncer sync: done processing adds. error: null
2024-10-01T21:36:44.071Z box:backupupload upload completed. error: null
2024-10-01T21:37:01.490Z box:tasks update 2682: {"percent":28.272727272727277,"message":"Copied 39 files with error: null"}
2024-10-01T21:37:22.150Z box:syncer sync: done processing deletes. error: null
2024-10-01T21:38:27.951Z box:syncer sync: done processing adds. error: null
2024-10-01T21:38:27.952Z box:backupupload upload completed. error: null
2024-10-01T21:39:12.599Z box:tasks update 2682: {"percent":32.81818181818182,"message":"Copied 134 files with error: null"}
2024-10-01T21:39:16.728Z box:syncer sync: done processing deletes. error: null
2024-10-01T21:39:24.566Z box:syncer sync: done processing adds. error: null
2024-10-01T21:39:24.568Z box:backupupload upload completed. error: null
2024-10-01T23:01:11.678Z box:tasks update 2682: {"percent":37.36363636363637,"message":"Copied 16600 files with error: null"}
2024-10-01T23:01:14.762Z box:syncer sync: done processing deletes. error: null
2024-10-01T23:01:25.356Z box:syncer sync: done processing adds. error: null
2024-10-01T23:01:25.356Z box:backupupload upload completed. error: null
2024-10-01T23:01:36.972Z box:tasks update 2682: {"percent":41.909090909090914,"message":"Copied 10 files with error: null"}
2024-10-01T23:01:43.858Z box:syncer sync: done processing deletes. error: null
2024-10-01T23:02:19.004Z box:syncer sync: done processing adds. error: null
2024-10-01T23:02:19.005Z box:backupupload upload completed. error: null
2024-10-01T23:05:57.079Z box:tasks update 2682: {"percent":46.45454545454546,"message":"Copied 121 files with error: null"}
2024-10-01T23:11:41.504Z box:syncer sync: done processing deletes. error: null
2024-10-01T23:11:56.470Z box:backupformat/rsync sync: processing task: {"operation":"add","path":"data/datastore/2f64cba3-c06f-458b-9bdc-b3cc2d5bae9e/last-error.txt","reason":"new","position":43}
2024-10-01T23:11:56.470Z box:backupformat/rsync Adding data/datastore/2f64cba3-c06f-458b-9bdc-b3cc2d5bae9e/last-error.txt position 43 try 1
2024-10-01T23:12:23.597Z box:backupformat/rsync sync: processing task: {"operation":"add","path":"data/datastore/e7b2faad-6ded-479b-9aeb-727a93a2c95c/last-error.txt","reason":"new","position":152}
2024-10-01T23:12:23.597Z box:backupformat/rsync Adding data/datastore/e7b2faad-6ded-479b-9aeb-727a93a2c95c/last-error.txt position 152 try 1
2024-10-01T23:12:24.974Z box:backupformat/rsync sync: processing task: {"operation":"add","path":"data/datastore/f8b18bd9-87a9-424d-947a-859ea75412f6/last-error-screenshot.png","reason":"changed","position":156}
2024-10-01T23:12:24.974Z box:backupformat/rsync Adding data/datastore/f8b18bd9-87a9-424d-947a-859ea75412f6/last-error-screenshot.png position 156 try 1
2024-10-01T23:13:00.011Z box:syncer sync: done processing adds. error: null
2024-10-01T23:13:00.012Z box:backupupload upload completed. error: null
2024-10-02T01:02:54.344Z box:tasks update 2682: {"percent":51.00000000000001,"message":"Retrying (1) copy of +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/l5gkgMssQV3WZN4rGfLDET6XHh1q-3NvNH24UfTUuKI/zTG0KK7-TzPYcHM8n7gP17PHvPHXM42fyDh-cFvRGjPJqZjo5zia+0aptV88Q2hSZyeX3SQB2agrXL5Mk+7sZA/fVakjWVElvE8zFgXT--GiPO1sOkiN9EP08kdlVQs0ofVQ2XYKOKkvRM3znO8hI-K. Error: 504: null 504"}
2024-10-02T01:02:57.908Z box:tasks update 2682: {"percent":51.00000000000001,"message":"Retrying (1) copy of +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/l5gkgMssQV3WZN4rGfLDET6XHh1q-3NvNH24UfTUuKI/zlBri0j-vBuhPEVuyBLawcIZUqIO-rvtJbXK-LY3gXGDAhJoqkU1Er5kSi7Iy3owLQE7nizkWMieGy4+38bdyg/+U2Q-AnDdQL5t-omn0NjxwR-Q2WC64DR70L3qWSkVqY. Error: 504: null 504"}
2024-10-02T02:33:14.073Z box:tasks update 2682: {"percent":51.00000000000001,"message":"Retrying (2) copy of +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/l5gkgMssQV3WZN4rGfLDET6XHh1q-3NvNH24UfTUuKI/zTG0KK7-TzPYcHM8n7gP17PHvPHXM42fyDh-cFvRGjPJqZjo5zia+0aptV88Q2hSZyeX3SQB2agrXL5Mk+7sZA/fVakjWVElvE8zFgXT--GiPO1sOkiN9EP08kdlVQs0ofVQ2XYKOKkvRM3znO8hI-K. Error: 504: null 504"}
2024-10-02T02:33:17.536Z box:tasks update 2682: {"percent":51.00000000000001,"message":"Retrying (2) copy of +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/l5gkgMssQV3WZN4rGfLDET6XHh1q-3NvNH24UfTUuKI/zlBri0j-vBuhPEVuyBLawcIZUqIO-rvtJbXK-LY3gXGDAhJoqkU1Er5kSi7Iy3owLQE7nizkWMieGy4+38bdyg/+U2Q-AnDdQL5t-omn0NjxwR-Q2WC64DR70L3qWSkVqY. Error: 504: null 504"}
2024-10-02T04:03:33.790Z box:tasks update 2682: {"percent":51.00000000000001,"message":"Retrying (3) copy of +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/l5gkgMssQV3WZN4rGfLDET6XHh1q-3NvNH24UfTUuKI/zTG0KK7-TzPYcHM8n7gP17PHvPHXM42fyDh-cFvRGjPJqZjo5zia+0aptV88Q2hSZyeX3SQB2agrXL5Mk+7sZA/fVakjWVElvE8zFgXT--GiPO1sOkiN9EP08kdlVQs0ofVQ2XYKOKkvRM3znO8hI-K. Error: 504: null 504"}
2024-10-02T04:03:37.184Z box:tasks update 2682: {"percent":51.00000000000001,"message":"Retrying (3) copy of +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/l5gkgMssQV3WZN4rGfLDET6XHh1q-3NvNH24UfTUuKI/zlBri0j-vBuhPEVuyBLawcIZUqIO-rvtJbXK-LY3gXGDAhJoqkU1Er5kSi7Iy3owLQE7nizkWMieGy4+38bdyg/+U2Q-AnDdQL5t-omn0NjxwR-Q2WC64DR70L3qWSkVqY. Error: 504: null 504"}
2024-10-02T05:33:53.685Z box:tasks update 2682: {"percent":51.00000000000001,"message":"Retrying (4) copy of +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/l5gkgMssQV3WZN4rGfLDET6XHh1q-3NvNH24UfTUuKI/zTG0KK7-TzPYcHM8n7gP17PHvPHXM42fyDh-cFvRGjPJqZjo5zia+0aptV88Q2hSZyeX3SQB2agrXL5Mk+7sZA/fVakjWVElvE8zFgXT--GiPO1sOkiN9EP08kdlVQs0ofVQ2XYKOKkvRM3znO8hI-K. Error: 504: null 504"}
2024-10-02T05:33:56.993Z box:tasks update 2682: {"percent":51.00000000000001,"message":"Retrying (4) copy of +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/l5gkgMssQV3WZN4rGfLDET6XHh1q-3NvNH24UfTUuKI/zlBri0j-vBuhPEVuyBLawcIZUqIO-rvtJbXK-LY3gXGDAhJoqkU1Er5kSi7Iy3owLQE7nizkWMieGy4+38bdyg/+U2Q-AnDdQL5t-omn0NjxwR-Q2WC64DR70L3qWSkVqY. Error: 504: null 504"}
2024-10-02T05:59:32.267Z box:tasks update 2682: {"percent":51.00000000000001,"message":"Retrying (5) copy of +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/l5gkgMssQV3WZN4rGfLDET6XHh1q-3NvNH24UfTUuKI/zlBri0j-vBuhPEVuyBLawcIZUqIO-rvtJbXK-LY3gXGDAhJoqkU1Er5kSi7Iy3owLQE7nizkWMieGy4+38bdyg/+U2Q-AnDdQL5t-omn0NjxwR-Q2WC64DR70L3qWSkVqY. Error: XMLParserError: Non-whitespace before first tag.\nLine: 0\nColumn: 1\nChar: { 502"}
2024-10-02T05:59:32.274Z box:tasks update 2682: {"percent":51.00000000000001,"message":"Retrying (5) copy of +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/l5gkgMssQV3WZN4rGfLDET6XHh1q-3NvNH24UfTUuKI/zTG0KK7-TzPYcHM8n7gP17PHvPHXM42fyDh-cFvRGjPJqZjo5zia+0aptV88Q2hSZyeX3SQB2agrXL5Mk+7sZA/fVakjWVElvE8zFgXT--GiPO1sOkiN9EP08kdlVQs0ofVQ2XYKOKkvRM3znO8hI-K. Error: XMLParserError: Non-whitespace before first tag.\nLine: 0\nColumn: 1\nChar: { 502"}
2024-10-02T05:59:52.451Z box:tasks update 2682: {"percent":51.00000000000001,"message":"Copied 2607 files with error: null"}
2024-10-02T05:59:53.832Z box:syncer sync: done processing deletes. error: null
2024-10-02T05:59:54.326Z box:syncer sync: done processing adds. error: null
2024-10-02T05:59:54.330Z box:backupupload upload completed. error: null
2024-10-02T05:59:54.622Z box:tasks update 2682: {"percent":55.545454545454554,"message":"Copied 4 files with error: null"}
2024-10-02T05:59:55.789Z box:syncer sync: done processing deletes. error: null
2024-10-02T05:59:56.065Z box:syncer sync: done processing adds. error: null
2024-10-02T05:59:56.066Z box:backupupload upload completed. error: null
2024-10-02T05:59:56.715Z box:tasks update 2682: {"percent":60.0909090909091,"message":"Copied 22 files with error: null"}
2024-10-02T06:00:12.505Z box:syncer sync: done processing deletes. error: null
2024-10-02T06:02:39.143Z box:syncer sync: done processing adds. error: null
2024-10-02T06:02:39.145Z box:backupupload upload completed. error: null
2024-10-02T06:53:37.976Z box:tasks update 2682: {"percent":64.63636363636364,"message":"Copied 13894 files with error: null"}
2024-10-02T06:58:36.013Z box:syncer sync: done processing deletes. error: null
2024-10-02T07:02:37.378Z box:syncer sync: done processing adds. error: null
2024-10-02T07:02:37.380Z box:backupupload upload completed. error: null
2024-10-02T07:06:48.951Z box:tasks update 2682: {"percent":69.18181818181819,"message":"Copied 1553 files with error: null"}
2024-10-02T07:06:53.706Z box:syncer sync: done processing deletes. error: null
2024-10-02T07:06:56.646Z box:syncer sync: done processing adds. error: null
2024-10-02T07:06:56.648Z box:backupupload upload completed. error: null
2024-10-02T07:28:25.828Z box:tasks update 2682: {"percent":73.72727272727273,"message":"Copied 6783 files with error: null"}
2024-10-02T07:28:27.921Z box:syncer sync: done processing deletes. error: null
2024-10-02T07:28:29.538Z box:syncer sync: done processing adds. error: null
2024-10-02T07:28:29.539Z box:backupupload upload completed. error: null
2024-10-02T07:28:29.766Z box:tasks update 2682: {"percent":78.27272727272728,"message":"Copied 6 files with error: null"}
2024-10-02T07:28:31.040Z box:syncer sync: done processing deletes. error: null
2024-10-02T07:28:31.394Z box:syncer sync: done processing adds. error: null
2024-10-02T07:28:31.394Z box:backupupload upload completed. error: null
2024-10-02T07:28:34.235Z box:tasks update 2682: {"percent":82.81818181818183,"message":"Copied 16 files with error: null"}
2024-10-02T07:28:35.893Z box:syncer sync: done processing deletes. error: null
2024-10-02T07:28:38.026Z box:syncer sync: done processing adds. error: null
2024-10-02T07:28:38.027Z box:backupupload upload completed. error: null
2024-10-02T07:31:56.485Z box:tasks update 2682: {"percent":87.36363636363637,"message":"Copied 527 files with error: null"}
2024-10-02T07:31:57.821Z box:syncer sync: done processing deletes. error: null
2024-10-02T07:31:59.458Z box:syncer sync: done processing adds. error: null
2024-10-02T07:31:59.459Z box:backupupload upload completed. error: null
2024-10-02T07:32:00.274Z box:tasks update 2682: {"percent":91.90909090909092,"message":"Copied 7 files with error: null"}
2024-10-02T07:32:02.436Z box:syncer sync: done processing deletes. error: null
2024-10-02T07:32:04.590Z box:syncer sync: done processing adds. error: null
2024-10-02T07:32:04.590Z box:backupupload upload completed. error: null
2024-10-02T07:32:04.716Z box:tasks update 2682: {"percent":96.45454545454547,"message":"Copied 2 files with error: null"}
2024-10-02T07:32:04.719Z box:tasks setCompleted - 2682: {"result":"box_v8.0.6_5071cb76","error":null}
2024-10-02T07:32:04.720Z box:tasks update 2682: {"percent":100,"result":"box_v8.0.6_5071cb76","error":null}

Other details :

• The app is currently using 193.72 MB of storage (as of 05:15).
• There are hundred of watches configured in Changedetection.
• I didn't observe any outage or issue with resource usage during the backup.
  

I'm not sure how to improve this but I become a bit anxious about this. I can provide more details at need.

Thanks in advance !

[nebulon]

Not sure why that one app which doesn't even have that much data would take so incredibly long. If you trigger a backup for just that app, are the lots of retries in the task logs or other indicator why it would be so slow?

[SansGuidon]

When doing a backup for just that app it takes around 20 min to complete...
I don't get it

However I noticed the backup cleaner errored a lot in past days. That might explain also why my used storage only gets bigger for a few weeks, those retention logs rail daily without notification with those errors

box:database Connection 463 error: Packets out of order. Got: 0 Expected: 2 PROTOCOL_PACKETS_OUT_OF_ORDER

Related to https://forum.cloudron.io/topic/12200/backup-failed-packets-out-of-order?_=1727893829155 and more recent https://forum.cloudron.io/topic/12527/backup-fails-about-50-60-of-the-time ?

Not sure if related but I observe also very frequent network issues recently in miniflux with lot of feeds broken daily...

Miniflux is not able to reach this website due to a network error: Get "https://annas-archive.se/blog/rss.xml": dial tcp: lookup annas-archive.se on 127.0.0.11:53: server misbehaving
...
errors - Miniflux is not able to reach this website due to a network error: Get "https://www.green-coding.berlin/blog/index.xml": dial tcp [2a06:98c1:3121::3]:443: connect: network is unreachable
...

Etc.
I probably had to manually refresh 40-50 feeds today. And now I see that 150 feeds are in error. And fixing each takes a few retries with the Refresh.

and WordPress... (Broken link detector plugin seems more flakky and reports false positive)

Also this occured but only once and for first time today

Relay error: Connect to port25check.cloudron.io timed out. Check if port 25 (outbound) is blocked

So I'm keeping faith that somehow those issues and the other backup related issues open in support forum are related and ring a bell to someone.
I see other people have had either DNS or Backup issues recently in the support forum, so I feel not totally isolated. But also I think there are several issues that make it difficult for me to understand. Maybe I should try another VPS and storage...if that could be the problem. At this point every week seems to reveal more issues since the first of September.

BTW is it possible to reopen the thread/question ? it's not resolved in the end

[SansGuidon]

It seems I could reproduce a lot of the network errors / DNS resolution from the VPS's terminal/CLI, so I did some testing and my VPS provider's default DNS setup was the culprit and gave me lot of timeouts. See also https://www.thomasmartens.eu/contabo-dns-lookup-timeouts/ which helped me figure it out.

The solution for DNS so :

• replacing Contabo DNS servers and using instead 1.1.1.1 and 9.9.9.9 in /etc/netplan/01-netcfg.yaml
• run sudo netplan apply
• check resolvectl status

Refreshing all miniflux feeds, after a restart of its app, took only 1-2 secs
I'll retry the backups cleanup now... and wait til next day for the result !

[SansGuidon]

I'm ongoing a migration from Contabo to Hetzner storage (SSHFS) for the backup. I'll keep you posted.

[SansGuidon]

Switching to hetzner feels good enough for now . Full backup takes 30min for 21 apps. I've cancelled contabo storage service.
Hope this stays so snappy for the long run