search

abraunegg / onedrive

OneDrive Client for Linux
https://abraunegg.github.io
GNU General Public License v3.0
10.07k stars 859 forks source link

Constantly uploading "modified" binary files when nothing has changed #1260

Closed dtip closed 3 years ago

dtip commented 3 years ago

Bug Report Details

Describe the bug

My Onedrive contains a few binary files in a shared folder. These files were added by a Windows 10 user. Whenever onedrive syncs, it claims these binary files have been modified and uploads them, which causes constant sync activity for all users of the shared folder.

Application and Operating System Details:

Note: Please generate a full debug log whilst reproducing the issue as per https://github.com/abraunegg/onedrive/wiki/Generate-debug-log-for-support and email to support@mynas.com.au

To Reproduce Steps to reproduce the behavior if not causing an application crash:

  1. Boot computer
  2. systemctl starts onedrive
  3. onedrive immediately starts syncing "modified" binary files which have not changed

Complete Verbose Log Output N/A

Application Log Output: N/A

Screenshots N/A

Additional context N/A

Bug Report Checklist

abraunegg commented 3 years ago

@dtip

onedrive immediately starts syncing "modified" binary files which have not changed

Something will be modifying the files.

In the past, it has been found that broken Ubuntu packages and desktop software was indeed modifying the timestamps of the files, thus, causing the files to be re-uploaded as modified - specifically binary files. Please refer to: https://github.com/abraunegg/onedrive/issues/824 - specifically, after looking at debug log files - https://github.com/abraunegg/onedrive/issues/824#issuecomment-603469431

As you have not submitted or provided a verbose log or verbose debug log as per the support requirements, I cannot provide any further details at this stage.

Until you provide more details via a debug log, I am flagging this as a local environment issue & not a bug.

dtip commented 3 years ago

Here's a minimal output of the verbose log showing the problem:

Processing [file].bpn
[DEBUG] skip_file evaluation for: [file].bpn
The file last modified time has changed
The file content has changed
Uploading modified file [file].bpn

ls -l shows the file was last modified on 4th Feb. onedrive has uploaded it approx 100 time since then - looks like it uploads every time it syncs.

stat shows file was last modified 4th Feb and last accessed 2 hours ago (onedrive has uploaded it multiple times since then).

  File: [file].bpn
  Size: 50678240    Blocks: 98984      IO Block: 4096   regular file
Device: fd01h/64769d    Inode: 8652923     Links: 1
Access: (0600/-rw-------)  Uid: ( 1000/    dtip)   Gid: (  100/   users)
Access: 2021-02-06 08:22:26.339641054 +0000
Modify: 2021-02-04 20:37:36.000000000 +0000
Change: 2021-02-04 20:40:11.187741221 +0000
 Birth: -

Does that provide the info you're looking for?

abraunegg commented 3 years ago

@dtip Without seeing the FULL debug log, it is hard to tell you what and why - however - something is telling the client that the file has been modified - but what?

There are 2 places that data comes from - your file system and OneDrive.

You will need to debug your filesystem first and trace each and every file access ... something outside this client is triggering this even though your stat does not show this.

I can generate a PR that adds even more vebose details, but I highly doubt this will be helpful and the modified timestamp is coming from the file itself - thus ... why is your filesystem misreporting this?

dtip commented 3 years ago

I'd love to, but can't redact a full debug log!

How do you recommend tracing file access? What are the possible reasons for onedrive thinking a file has changed over and above what's measured by stat?

abraunegg commented 3 years ago

@dtip

I'd love to, but can't redact a full debug log!

Please stop being overly paranoid ... if you want me to sign a confidentiality agreement - fine, no issue ..

How do you recommend tracing file access?

Suggest that you speak to your OS vendor support folk or the LUKS support team given you are running encryption.

dtip commented 3 years ago

I guess the reason I'm asking you specifically is because I'm trying to understand why your immediate reaction is that this is a problem with the Ubuntu filesystem rather than with the way onedrive is checking for file modifications.

abraunegg commented 3 years ago

@dtip

I guess the reason I'm asking you specifically is because I'm trying to understand why your immediate reaction is that this is a problem with the Ubuntu filesystem rather than with the way onedrive is checking for file modifications.

Because the code, makes a system call to get the file statistics and it is these that it uses to determine if the file has been modified. Your log file extract tells me enough - the client when checking the file, found it to be modified based on its timestamp.

If this was a bug - and there were bugs like this especially with the skilion client which were fixed many releases ago, and if this was a current issue with the current codebase it would be a very hot topic and there would be many reports of this issue well before you raising this issue.

dtip commented 3 years ago

I added some extra logging and rebuilt onedrive:

The local item has a different modified time 2021-Feb-06 10:02:10Z when compared to modified time 2021-Jan-20 16:39:15Z

The itemModifiedTime is clearly wrong (as well as the localModifiedTime). They should either both be 20th Jan or both be 6th Feb. This file has been uploaded to onedrive >10 times already today (6th Feb) and shown by the web interface. Any ideas what could cause that?

abraunegg commented 3 years ago

I added some extra logging and rebuilt onedrive:

The local item has a different modified time 2021-Feb-06 10:02:10Z when compared to modified time 2021-Jan-20 16:39:15Z

Useful - but you are missing (or you have removed and not used) the piece of critical data here - what is the source of where the timestamp is coming from. The original line comes from 2758 in sync.d and includes this piece of data:

code

The itemModifiedTime is clearly wrong (as well as the localModifiedTime). They should either both be 20th Jan or both be 6th Feb. This file has been uploaded to onedrive >10 times already today (6th Feb) and shown by the web interface. Any ideas what could cause that?

As I has said before, to assist you further, a FULL, unredacted debug log is needed to help you work out what is going on. I am not discounting a bug - but all evidence & my experience tells me something on your Ubuntu platform is causing this.

Steps for you do perform:

  1. Find all 'onedrive' binaries and make sure you only have one binary, being the latest 'master' version or latest Ubuntu PPA package built binary present on your platform
    • You are running Ubuntu. You could have installed an older package from the Universe, maybe then from the PPA & finally installed from source. You potentially could have 3 different versions lurking around - check this and confirm this is not your problem. Upgrading the Ubuntu packages (Universe -> PPA) does not remove the old version correctly because they were packaged differently.
  2. Perform a file system trace on all application access to the file(s) that are being impacted by this issue
    • You need to do this to rule out that no other application is mangling your file timestamp data. As per #824 3 different tools were found to be messing with the 'binary' files, causing this sort of situation you are seeing
  3. Make sure you have ZERO file system bugs or ZERO kernel issues
    • Issue #1216 was caused by 'mdadm' and a kernel bug. The raid member would be out of sync, thus, when rebooting, the local item database was out of sync, because the filesystem had not flushed the data correctly, and on reboot, the alternate raid member was then being used = data loss. I suspected right away that this was potentially an issue, and days later the user confirmed that this was the case. To resolve this, the user had to upgrade their kernel - Kernel 5.10.2 can cause trouble with LVM2, BTRFS and MDADM, which is fixed by Kernel 5.10.8. You are running Kernel 5.8.0-41 but does this Kernel have the same bugs as Kernel 5.10.2 ? Potentially .... Do some research & find out
  4. Provide a FULL unredacted debug log
    • This needs to show the multiple file uploads for the file(s) in question to track this through as to what is occurring. It would be good to compare this with other files that right now are also not impacted by this issue you are seeing
    • If you do not want to send the debug log, track the file through yourself, see what the code is doing, what the return responses from the API is doing as, depending on Account Type / location (eg SharePoint) the responses are different and Microsoft modifies your file post upload. The API response is then saved to the local database to future reference.
    • If you wont send the log, I cannot help you any more than I have. As said before I am prepared to sign any confidentiality agreement regarding information disclosure that you are paranoid about. I am not prepared to jeopardise my professional background by leaking someones debug log information and destroying my professional integrity.
  5. Build a brand new system using a different distribution (do not use Ubuntu) - Debian, Arch, CentOS / RHEL and does the exact same issue occur?
    • If yes, then this would confirm that this is a bug of some sort, but, without the FULL debug log I cannot track down where this might be
    • If no, then, this would 100% confirm that this issue is 100% environmental to your setup, not an issue, not a bug and nothing that I can assist with further
abraunegg commented 3 years ago

@dtip Any update on your testing in regards to the 5 points above to work out why you are seeing this sort of action only for a single file type?

Additionally, a .bpn file is an autosaved backup file automatically created at regular intervals by ArchiCAD, when the backup option is set. I spoke with the ArchiCAD support folk locally, and they are surprised that this file is causing an issue. It is also not used at all within the application or day-to-day use.

As such, a work around for your specific issue would be to exclude this type of file from sync operations by adding the following to your client configuration file:

skip_file = "*.bpn"

This will ensure that this file type is skipped from sync operations.

sweharris commented 3 years ago

FWIW, I'm seeing similar. My local machine is CentOS 7.9, and I'm using onedrive v2.4.9-10-g3b87602

Very frequently I can take a picture on my phone, which uploads to onedrive, and then I see it download and upload.

e.g.

Feb 07 12:24:42 mercury7.spuddy.org onedrive[1268]: Downloading file Pictures/Camera Roll/IMG_20210207_122356.jpg ... done.
Feb 07 12:24:49 mercury7.spuddy.org onedrive[1268]: Uploading differences of Pictures/Camera Roll/IMG_20210207_122356.jpg
Feb 07 12:24:49 mercury7.spuddy.org onedrive[1268]: Uploading new items of Pictures/Camera Roll/IMG_20210207_122356.jpg

This also happens with files I edit with O365

Feb 09 19:31:54 mercury7.spuddy.org onedrive[9091]: Downloading file tmp/tst.xlsx ... done.
Feb 09 19:32:01 mercury7.spuddy.org onedrive[9091]: Uploading differences of tmp/tst.xlsx
Feb 09 19:32:01 mercury7.spuddy.org onedrive[9091]: Uploading new items of tmp/tst.xlsx

In my case my ~/OneDrive is on an NFS share. Not sure if this is relevant or not (attribute caching?)

I'm not obviously noticing any data corruption, just the unnecessary data transfer.

abraunegg commented 3 years ago

@sweharris If you can generate a verbose debug log for this situation, this can be then investigated. Without the verbose debug log, it is hard to say exactly why this is occurring. I cannot replicate this situation locally.

sweharris commented 3 years ago

I've sent an email support@mynas.com.au with what I think is the relevant extract.

I think something is triggering on the IN_CLOSE_WRITE event created by the act of writing out the new file!

(And, yes, there are filepaths in there that I trust you to keep secret)

EDIT: the file in question is IMG_20210209_201452.jpg

sweharris commented 3 years ago

If it helps and that debug file isn't good enough, I've set up a minimal test environment which can demonstrate the problem with a new account and no files, so it's pretty clean ;-)

Downloading file tst1 ... done.
Uploading differences of ./tst1
Uploading new items of ./tst1
Starting a sync with OneDrive
Syncing changes from OneDrive ...
Sync with OneDrive is complete

And email sent with that much much much smaller debug log

abraunegg commented 3 years ago

@sweharris As confirmed via email - your issue is a logging output inconsistency issue, not the same issue as the original item that was raised.

PR #1265 will resolve this logging output inconsistency.

sweharris commented 3 years ago

Hmm... compiling from fix-issue-1260 branch looks better.

Still some unnecessary directory upload alerts, but the file itself doesn't get flagged.

% onedrive --synchronize
Configuring Global Azure AD Endpoints
Initializing the Synchronization Engine ...
Syncing changes from OneDrive ...
Downloading file tst1 ... done.
Uploading differences of ~/OneDrive
Uploading new items of ~/OneDrive
abraunegg commented 3 years ago

@sweharris That actually now looks 100% normal, as, when --synchronize is used, the process is:

So what you are seeing is 100% normal operation.

sweharris commented 3 years ago

Then I guess it's good :-)

sweharris commented 3 years ago

Although that branch is causing other issues... maybe my test environment is bad?

$ onedrive --synchronize
Configuring Global Azure AD Endpoints
Initializing the Synchronization Engine ...
Syncing changes from OneDrive ...
Uploading differences of ~/OneDrive
Uploading new items of ~/OneDrive

$ onedrive --monitor --monitor-interval 30
Configuring Global Azure AD Endpoints
Initializing the Synchronization Engine ...
Initializing monitor ...
OneDrive monitor interval (seconds): 30
Retry sync count: 1: ~/OneDrive: No such file or directory
Retry sync count: 2: ~/OneDrive: No such file or directory
Giving up on sync after three attempts: ~/OneDrive: No such file or directory
std.file.FileException@/FastData/local/dmd2/linux/bin64/../../src/phobos/std/file.d(2051): ~/OneDrive: No such file or directory
abraunegg commented 3 years ago

@sweharris Yes - this is a different issue ...

sweharris commented 3 years ago

OK :-) As long as you're aware :-)

abraunegg commented 3 years ago

reverted commit to fix your issue - can you open a new issue for your logging problem, and revert to using 'master' for the moment. Master is onedrive v2.4.9-17-g1bfd995

sweharris commented 3 years ago

See https://github.com/abraunegg/onedrive/issues/1266

abraunegg commented 3 years ago

@dtip Please can you respond

dtip commented 3 years ago

Still working on debugging - it's been a busy week

abraunegg commented 3 years ago

@dtip Any update on your debugging?

abraunegg commented 3 years ago

Closing issue for the following reasons:

github-actions[bot] commented 3 years ago

This issue has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.