OneDrive process receiving 130 signal and stopped abruptly

[IsmaelSF]

Hi!

I'm facing a very rare issue trying to sync a big folder to OneDrive. These versions are being use:

• v2.5.2 onedrive client
• v8.10.1 libcurl

My client config is:

sync_dir="/root/OneDrive/LinuxServerBackup/"
upload_only = "true"
debug_https = "false"
enable_logging = "true"
ip_protocol_version = "1"
force_http_11 = "false"
skip_dir="*/Maildir"
skip_dir="*/MaildirSPAM"

Starting process from command line (same behavior from systemd) with nohup and debug redirected to a file:

$  nohup onedrive --synchronize --verbose --verbose > debug_output.log 2>&1 &

After two hours of syncronizing (more than 700.000 files so time is expected...), process finish with:

[1]+  Exit 130              nohup onedrive --synchronize --verbose --verbose > debug_output.log 2>&1

It seems like anyone press CTRL+C in terminal but is not the case (nohup was used to launch it)

Last lines of the debug file:

> DEBUG: OneDrive API releaseCurlEngine() Called
> Due to a termination signal, internal processing stopped abruptly. The application will now exit in a unclean manner.
> DEBUG: CurlEngine releaseEngine() called on instance id: pbxvgOhTZ2qXWAEl
> DEBUG: CurlEngine curlEnginePool size before release: 1
> DEBUG: CurlEngine cleanup() called on instance id: pbxvgOhTZ2qXWAEl
> DEBUG: CurlEngine curlEnginePool size after release: 2
> DEBUG: File Size: 1546152 Bytes
> DEBUG: Upload Duration: 1.644 Seconds
> DEBUG: Upload Speed: 0.896913 Mbps (approx)
> **Due to a termination signal, internal processing stopped abruptly. The application will now exit in a unclean manner.**
> DEBUG: Uploaded local file matches reported online size and hash values
> DEBUG: CurlEngine getCurlInstance() called
> **Due to a termination signal, internal processing stopped abruptly. The application will now exit in a unclean manner.**
> DEBUG: CurlEngine curlEnginePool current size: 2
> DEBUG: CurlEngine was in a valid state - returning existing CurlEngine instance
> DEBUG: CurlEngine instance ID: pbxvgOhTZ2qXWAEl

Anybody has any clue?

P.D. After exiting this way I have found some corruption in sqllite db with items,mtime column with garbage or blank. I dont know if both behaviors are linked or not but before openning a bug I would like to hear from you.

Regards

[abraunegg]

@IsmaelSF
This sounds similar to #2874 ...

I would downgrade your curl version to 8.9.1 and retest.

Secondly, 700K items is double and then some what Microsoft recommend (300K maximum). You will also need 7GB+ of free system memory to run v2.5.x

[IsmaelSF]

Ok, let me downgrade curllib and retest

[IsmaelSF]

Retested with curllib 8.9.1 and same issue :( , last 3 lines of debug LOG are:

Due to a termination signal, internal processing stopped abruptly. The application will now exit in a unclean manner.
Due to a termination signal, internal processing stopped abruptly. The application will now exit in a unclean manner.
Due to a termination signal, internal processing stopped abruptly. The application will now exit in a unclean manner.

curllib:

$ curl --version
curl 8.9.1 (x86_64-pc-linux-gnu) libcurl/8.9.1 OpenSSL/1.0.2k-fips zlib/1.2.7 libpsl/0.7.0 (+libicu/50.1.2)
Release-Date: 2024-07-31
Protocols: dict file ftp ftps gopher gophers http https imap imaps ipfs ipns mqtt pop3 pop3s rtsp smb smbs smtp smtps telnet tftp
Features: alt-svc AsynchDNS HSTS HTTPS-proxy IPv6 Largefile libz NTLM PSL SSL threadsafe UnixSockets

[abraunegg]

@IsmaelSF

After exiting this way I have found some corruption in sqllite db with items,mtime column with garbage or blank.

This was an issue with v2.5.0 - see issue #2810 and #2813

This was fixed via PR #2816 - so are you actually running v2.5.2 which has this fix ?

[IsmaelSF]

Yes, 2.5.2:

$ onedrive --version
onedrive v2.5.2

This type of corruption...

sqlite> select name,mtime,type from item where mtime not like '2%' and mtime not like '1%';
3DMODEL__20_.JPG||file
PTDC0024.JPG||file
2013-02-05 12.36.49.jpg||file
IMG_3302A.JPG||file
cara.JPG||file
FAMILIA SANCHEZ 02-01-08.pdf||file
IMG_1874.jpg|�"c>|file
IMG_5002.JPG||file
IMG_3816.JPG||file
DSC00976.JPG|0|file
PICT2969.JPG||file

mtime is empty or sometime with binary characters like IMG_1874.jpg. From the debug log I can see that JSON information recovery from MS is correct. One example for IMG_1874.jpg:

{
  "@microsoft.graph.downloadUrl": "XXXXXXXXX ERASED ON PURPOSE XXXXXXXXX",
  "@odata.context": "https://graph.microsoft.com/v1.0/$metadata#drives('4045D2C97D06D165')/items/$entity",
 "cTag": "\"c:{735FB772-0144-44C3-B05B-BFBB1FA7D97E},1\"",
  "createdBy": {
    "application": {
      "displayName": "00000003-0000-0000-c000-000000000000",
      "id": "00000003-0000-0000-c000-000000000000"
    },
    "user": {
      "displayName": "Ismael Sanchez Grudisa",
      "email": "ismael@grudisa.com",
      "id": "4045D2C97D06D165"
    }
  },
  "createdDateTime": "2024-10-02T11:30:11Z",
  "eTag": "\"{735FB772-0144-44C3-B05B-BFBB1FA7D97E},2\"",
  "file": {
    "hashes": {
      "quickXorHash": "8qfILJEqhsNRPLkjp85W2kE63uo="
    },
    "mimeType": "image/jpeg"
  },
  "fileSystemInfo": {
    "createdDateTime": "2024-10-02T11:30:11Z",
    "lastModifiedDateTime": "2005-02-06T23:48:36Z"
  },
  "id": "4045D2C97D06D165!s735fb772014444c3b05bbfbb1fa7d97e",
  "image": {},
  "lastModifiedBy": {
    "application": {
      "displayName": "00000003-0000-0000-c000-000000000000",
      "id": "00000003-0000-0000-c000-000000000000"
    },
    "user": {
      "displayName": "Ismael Sanchez Grudisa",
      "email": "ismael@grudisa.com",
      "id": "4045D2C97D06D165"
    }
  },
  "lastModifiedDateTime": "2005-02-06T23:48:36Z",
  "name": "IMG_1874.jpg",
  "parentReference": {
    "driveId": "4045D2C97D06D165",
    "driveType": "personal",
    "id": "4045D2C97D06D165!sb5d9d890d1ce4d39922ffca1a900bac5",
    "name": "118 CANON",
    "path": "/drives/4045D2C97D06D165/root:/anakin/home/documentos/Archivo FOTOS/FOTOS PERSONAL/FOTOS ROBERTO/118 CANON",
    "siteId": "581e6f48-f2bf-46ba-a448-6b00e4dfb2a3"
  },
  "photo": {},
  "size": 1722933,
  "webUrl": "https://onedrive.live.com?cid=4045D2C97D06D165&id=4045D2C97D06D165!s735fb772014444c3b05bbfbb1fa7d97e"
}

[abraunegg]

mtime is empty or sometime with binary characters like IMG_1874.jpg. From the debug log I can see that JSON information recovery from MS is correct. One example for IMG_1874.jpg:

This bug was fixed with #2816.

So there is either 1 of 2 things occuring:

1. You are running v2.5.0 somewhere or have not restarted your system services and/or somehow maybe running --dry-run which uses a DB copy, and your SQL query is against a v2.5.0 DB that has all that bad data
2. There is still a timestamp bug ... but that would be very hard to fathom because the code added in via Fix issues #2810, #2813, #2822, #2829 #2816 checks to ensure that the 'string' in the database and/or inserted into the database, actually can be converted to a correct timestamp, and if not - it asert the program with a very specific message:

BAD TIMESTAMP (UTF-8 FAIL):
BAD TIMESTAMP (REGEX FAIL):
BAD TIMESTAMP (CONVERSION FAIL):

So .. given you are not getting that message .... I have to suspect 99% that you are not running v2.5.2 .... you might have installed it .... but you are not running it.

So .... actions for you:

1. Confirm all the paths for the 'onedrive' client .... delete all and/or re-install to be sure
2. Run the application with --resync ... do not use --dry-run

This will:

• Ensure you are running v2.5.2
• Ensure that the local database has been cleaned up / replaced and clean entries are being added.

[IsmaelSF]

I'm pretty sure that onedrive client version is the last one. In this last attemp with downgraded libcurl I found again new corruptions (as you can see part of the debug log!!! ):

sqlite> select name,mtime,type from item where mtime not like '2%' and mtime not like '1%';
DSC00988.JPG||file
DSC00932.JPG|�����|file
DSC01039.JPG|����|file
DSC00623.JPG||file
DSC00934.JPG|DEBUG: CurlEngine cu|file
PICT2364.JPG|DEBUG: HTTP Status L|file
DSC01583.JPG|0����|file
DSC00241.JPG|https://graph.micros|file

In the firsts lines of the debug file you can find the version:

DEBUG: Application started
DEBUG: Process ID: 7FE2DB376260
DEBUG: User UID:   0
DEBUG: User GID:   0
DEBUG: User Name:  root
DEBUG: Application Version: onedrive v2.5.2
DEBUG: Application Compiled With: DMD 2099

Can be the case that "exiting in a unclean manner" produce this type of cases? I've checked with logs that items with this type error in mtime field are in the last part of the debug before crashing with "termination signal"

Regards

[abraunegg]

@IsmaelSF

Can be the case that "exiting in a unclean manner" produce this type of cases? I've checked with logs that items with this type error in mtime field are in the last part of the debug before crashing with "termination signal"

The issue here is - have you performed a --resync ? yes or no .. ?

Downgrading libcurl is one aspect to remove the possibility of a curl bug, but using a DB that has not been through a --resync to ensure anything from v2.5.0 has been cleaned out is what needs to be done.

With #2813 (the issue ticket) - this was also something that was 100% non-reproducible at all on my end despite trying.

So, please do the following:

1. Ensure you are doing a proper --resync when starting the application

• Use the same command as above in your original post but please add --resync
• Please email this full debug log to me for analysis as part of the investigation

2. Open a new bug report, fill in all the pertinent details required. This is used to build a system that replicates your system
3. Try the following:

• Downgrade your 'threads' to only a single thread by adding threads = "1" to your config file and then retest
• In Bug: Sync crashes/exits with core.time.TimeException: Invalid ISO Extended String #2813 , when this option was downgraded to 1, no corruption was seen|found

[abraunegg]

@IsmaelSF

Further to testing of your environment, please can you also build your client from the following PR:

git clone https://github.com/abraunegg/onedrive.git
cd onedrive
git fetch origin pull/2882/head:pr2882
git checkout pr2882

To build the PR, please follow the steps to prepare your system to build the client as detailed here: https://github.com/abraunegg/onedrive/blob/master/docs/install.md#building-from-source---high-level-requirements

When building the client, please use the following:

./configure --enable-debug; make clean; make;

When running the PR, your version should be: onedrive v2.5.2-3-g0d082d7 or greater.

This is a slight change to the fix in #2816 which is included already in v2.5.2

@phlibi

If possible could you also test this version given you were also able to reproduce this issue before your proposed fix?

[IsmaelSF]

Quick update, testing is on going but it looks pretty good on pr2882, no more items.mtime corruption were observed in database. Good job! I'll keep you updated.

[abraunegg]

Thanks for the feedback - greatly appreciated.

Please let me know how your testing goes over a number of days, as I would rather get this fix in.

I also have another PR (#2880) that also dramatically improves performance - #2882 is not in that PR, so right now I am thinking that the combination of the 2 will be highly beneficial for your scenario.

[IsmaelSF]

I've finished my two days tests, with more than two hundred thousand files synchronized and only 1 db corruption issue:

[2024-Oct-05 17:47:05.6870304] New items to upload to Microsoft OneDrive: 267828
[2024-Oct-05 18:27:14.3086053] New items to upload to Microsoft OneDrive: 264348
[2024-Oct-05 18:58:20.0705268] New items to upload to Microsoft OneDrive: 260795
[2024-Oct-05 19:24:04.2889823] New items to upload to Microsoft OneDrive: 257898
[2024-Oct-05 19:48:28.9787627] New items to upload to Microsoft OneDrive: 255394
[2024-Oct-05 20:18:40.7698206] New items to upload to Microsoft OneDrive: 251873
[2024-Oct-05 20:32:12.8615864] New items to upload to Microsoft OneDrive: 250649
[2024-Oct-05 21:04:48.2096873] New items to upload to Microsoft OneDrive: 246873
[2024-Oct-05 21:48:28.5790961] New items to upload to Microsoft OneDrive: 241481
[2024-Oct-05 22:25:17.1342645] New items to upload to Microsoft OneDrive: 236945
[2024-Oct-05 23:25:45.3454792] New items to upload to Microsoft OneDrive: 229169
[2024-Oct-06 00:58:49.8841145] New items to upload to Microsoft OneDrive: 220089
[2024-Oct-06 02:04:53.3448692] New items to upload to Microsoft OneDrive: 214825
[2024-Oct-06 03:59:49.9088219] New items to upload to Microsoft OneDrive: 203225
[2024-Oct-06 04:55:29.4360706] New items to upload to Microsoft OneDrive: 199369
[2024-Oct-06 07:09:02.7172458] New items to upload to Microsoft OneDrive: 186404
[2024-Oct-06 07:37:31.8089454] New items to upload to Microsoft OneDrive: 184191
[2024-Oct-06 09:31:37.8846595] New items to upload to Microsoft OneDrive: 172162
[2024-Oct-06 10:17:33.4038889] New items to upload to Microsoft OneDrive: 167925
[2024-Oct-06 10:51:19.6711262] New items to upload to Microsoft OneDrive: 165136
[2024-Oct-06 11:55:10.4002716] New items to upload to Microsoft OneDrive: 158457
[2024-Oct-06 12:40:59.9950578] New items to upload to Microsoft OneDrive: 155111
[2024-Oct-06 15:03:11.2898865] New items to upload to Microsoft OneDrive: 139745
[2024-Oct-06 16:43:54.4102730] New items to upload to Microsoft OneDrive: 128976
[2024-Oct-06 18:48:46.8482335] New items to upload to Microsoft OneDrive: 115565
[2024-Oct-07 08:30:36.7737152] New items to upload to Microsoft OneDrive: 62338
[2024-Oct-07 09:40:36.6638285] New items to upload to Microsoft OneDrive: 56443
[2024-Oct-07 11:54:51.8164461] BAD TIMESTAMP (REGEX FAIL): ^T
[2024-Oct-07 17:45:04.0008651] New items to upload to Microsoft OneDrive: 42929
[2024-Oct-07 18:51:22.7507902] New items to upload to Microsoft OneDrive: 37890

Its clear for me that PR#2882 is working and that case will be a very rare corner case. If you have any idea how to deal with it let me know and I can restart the tests.

I'm going to stop testing, compile with PR#2880/PR#2882 and retest again.

Regards

[abraunegg]

@IsmaelSF
Thanks for the feedback

Both PR's (#2880 and #2882) are merged into 'master' - so the overall benefit should be:

• Reduced execution time - thus, less CPU / overhead / impact on DB if not required
• Use of a proper 'mutex' to ensure the DB is being locked in the most applicable way

[phlibi]

@abraunegg Sorry for the delayed response, I'm currently on vacation with only irregular access to my PC.

I downgraded curl to 7.74.0 on Debian 11, as I got the failure (sudden process exit during downloading) this way last time. The I re-ran the tests and got a surprise:

• onedrive v2.5.0: Reproduced same issue as before (no surprise but good to know)
• onedrive v2.5.2: Unable to reproduce the issue during two full/initial sync runs
• onedrive v2.5.2-3-g0d082d7: The issue reappeared, i.e., the process silently exits while downloading files

So either the issue just didn't reproduce with 2.5.2 by coincidence, or PR 2882 is really a regression that makes it re-appear.

[abraunegg]

@phlibi

the process silently exits while downloading files

This is a known issue with older curl versions - where forcing http/1.1 and IPv4 is required to prevent the application exiting this way.

The issue that @IsmaelSF is / was facing is the DB corruption with mtime.

With v2.5.2 - corruption was being seen, but with the PR , this corruption is fixed.

Are you seeing the DB corruption with the PR ?

[phlibi]

@abraunegg Sorry, I thought the PR was about those failures during download. OK, so I upgraded curl again to 7.88.1 and ran it twice with the PR applied. It succeeded twice, so the patch doesn't seem to make it worse. Is there something special that I should test?

[abraunegg]

@phlibi

It succeeded twice, so the patch doesn't seem to make it worse. Is there something special that I should test?

For PR #2882 - given that you an @IsmaelSF were experiencing DB corruption (and I still cannot replicate this) - and @IsmaelSF still got corruption with the fix that you helped put together, but with #2882 there is now no corruption in the DB .. I will push this to 'master'

The next patch I would like you to test is #2880 (once I add in #2882 shortly) - this is a massive performance PR which it would be great to get some feedback given the issues you both have been having.

[abraunegg]

@IsmaelSF , @phlibi

If you can now test #2880 as this has the #2882 fix that would be greatly appreciated.

[phlibi]

@abraunegg Tested twice with onedrive v2.5.2-6-g59007d5, both runs were successful. However, the issue was already fixed for me with v2.5.2 (without any PR), so I don't know if this result is of much value.

[abraunegg]

@phlibi

It is all about ensuring no regression for yourself for database corruption. PR #2880 should also have been much more friendlier CPU wise, and potentially 12%+ faster in execution time.

[phlibi]

@abraunegg Tested PR 2880 also on another machine which previously showed DB corruption and it completed without trouble. So far, no regression for me.