bisente

[Solved] Corrupted Files With "assert Failed"

Recommended Posts

Hi

 

I keept looking into the issue I described at http://forum.bittorrent.com/topic/39034-cannot-identify-the-destination-folder-related-to-low-memory-also-possible-syncid-corruption/ a couple of days ago, and found out the "assert failed" corruption not only affected .sync/ID, but also some of the synced files!!!

 

This a serious issue. If btsync is randomly appending these messages to some of the synced files (sometimes completely overwriting the files), it can't be trusted. This needs attention, and needs to be fixed.

 

E.g. I found this at the end of a keepass (binary) file:

 

[20150602 20:40:12.521] Disconnect: Is seed
[20150602 20:40:12.521] assert failed /mnt/jenkins/workspace/Build-Sync-x64/fileutil.cpp:109
[20150602 20:40:12.521] assert failed /mnt/jenkins/workspace/Build-Sync-x64/wincompat.h:409
 
Notice the date and the "Build-Sync-x64". I did modify the keepass file at that time on one of the Macs, but it seems the file got corrupted during sync to my Linux server (the assert for a Mac build is different, Build-Sync-Mac instead of Build-Sync-x64). And then the file was synced back to all systems, including the Mac where I did the edit.
 
This happened just two days ago, running sync 2.0.120 PRO on all systems.
 
Any sync representative can shed some light on this issue? Is it being investigated? .sync/ID corruption is annoying, but synced file corruption is a nasty bug.
 
Regards
 
 

Share this post


Link to post
Share on other sites

@bisente

I've shared a workaround to you in another topic your started. While I already got some similar requests from our user, none complained that user files were corrupt, only Sync service data was affected.

 

Do you get any confirmed case when Sync put the wrong data into file? Could please send such a file to me for inspection?

Share this post


Link to post
Share on other sites

Hi @RomanZ

 

Thanks for your answer. Glad to know you're already aware of the ID issue and working on it.

 

In any case I'm sorry to report that I'm still having corrupt IDs even after enabling debug move. Yesterday I disconnected/removed all shares and deleted all .sync folders from all my systems, and started creating the shares again and connecting all the systems one by one. In some cases I've got ID corruption again. Then I deleted those folders again, re added, and sometimes they finished syncing without corruption. This doesn't happen 100% of the times, sometimes the folders sync right and stay OK. Sometimes the ID gets corrupted during the initial sync, sometimes after some hours/days it seems.

 

If I have some time this weekend I'll pay attention to the logs and try to reproduce the issue again. I mean, I don't have a recipe like "go here, do this, do that and it fails". But after disconnecting/connecting a share, 1 out of 5-6 times I end up with corrupted IDs. Specially on the Synology (ARM), it's just a matter of time until the ID gets corrupted. I'll email some logs to support if I can pinpoint exactly when (how?) the corruption occurs.

 

As for the corruption to other (synced) files, please see the following links (couldn't find how to attach to the post):

 

http://files.bisente.com/btsync/apuntes-analytics.txt

That one was a simple text file with some notes. Completely overwritten by the log messages.

 

http://files.bisente.com/btsync/it.follows.%282014%29.eng.1cd.%286191435%29.zip

Zip file. In this case the log message is prepended to the actual file content. Run "head -n2 file.zip" or strings on Linux to see what I mean.

 

I've also seen cases where the logs have been appended to the end of the file, can't locate samples now.

 

Corruption to synced files is rare, but it happens. 

Share this post


Link to post
Share on other sites

Thanks @bisente

 

It looks like we've managed to locate and fix the issue. Please see if you want to test experimental build with a fix. Links are provided in ticket.

Share this post


Link to post
Share on other sites

@RomanZ, just updated to 2.0.125.

 

Everything OK so far, but I've noted the version number on both the Mac, Linux and Synology builds says 2.0.125 (32). That (32) wasn't there in previous builds. Thinking it might mean a 32bit build I've verified all the binaries with "file" but they're 64bit.

 

Just wondering what that means. :-)

Share this post


Link to post
Share on other sites

I still get assert failed errors...

 

[20150619 03:21:01.619] SyncReq[0x00007fca6820b090][0000] [0000]: Unable to uncompress incoming data, err = -5
[20150619 03:21:01.620] assert failed /mnt/jenkins/workspace/Build-Sync-x64/SyncConn.cpp:180

Share this post


Link to post
Share on other sites

In the sync.log file. The entire contents is as follows:

 

version: 2.0.125.32
[20150619 03:17:35.817] total physical memory 536870912 max disk cache 2097152
[20150619 03:17:35.840] Loading config file version 2.0.124
[20150619 03:17:35.840] My PeerID: 10701E21939E86F984C250F5A2C5777061118D35
[20150619 03:17:46.686] Error while adding folder /var/btsync/chrisvdb/Documents: Selected folder is already added to BitTorrent Sync.
[20150619 03:17:46.686] Error while adding folder /var/btsync/chrisvdb/Pictures: Selected folder is already added to BitTorrent Sync.
[20150619 03:17:47.680] PeerConnection[0x00007fca68001d60] incoming connection from 220.241.70.37:61921
[20150619 03:17:47.996] PeerConnection[0x00007fca68202800] incoming connection from 220.241.70.37:47009
[20150619 03:17:48.726] PeerConnection[0x00007fca68202800] incoming connection from 220.241.70.37:61921
[20150619 03:21:01.619] SyncReq[0x00007fca6820b090][0000] [0000]: Unable to uncompress incoming data, err = -5
[20150619 03:21:01.620] assert failed /mnt/jenkins/workspace/Build-Sync-x64/SyncConn.cpp:180
[20150619 03:21:02.425] PeerConnection[0x00007fca68001d60] incoming connection from 220.241.70.37:61921
[20150619 03:21:41.152] Received shutdown request via signal 15
[20150619 03:21:42.213] Shutdown. Saving config sync.dat

 
This machine is called Timbuktu, runs Ubuntu Server 15.04 (64-bit). It has two 1.4 folders (read-only encrypted) configured.
 
The client on the other side (220.241.70.37) was running the same btsync version, also on Linux. It has only the Documents folder (read-write) configured.
 
I didn't see this error in 2.0.124 but did get other assert errors which brought me to this topic in the first place.
 
Chris.

Share this post


Link to post
Share on other sites

@chrisvdb

Actually, the sync.log file is a good place for these asserts. This topic is about the fact that asserts popped up in "ID" files, where they should not be.

 

Is there something not working well for you in Sync 2.0.125?

Share this post


Link to post
Share on other sites

Understood. Yeah, looks like 2.0.125 is not working for me... the 'unable to uncompress incoming data' repeats every 3 min (nothing much else seems to happen).

 

Timbuktu:

platform: Linux 3.19.0-20-generic #20-Ubuntu SMP Fri May 29 10:10:47 UTC 2015 x86_64 version: 2.0.125.32[20150619 11:54:03.603] total physical memory 536870912 max disk cache 2097152[20150619 11:54:03.603] Loading config file version 2.0.125[20150619 11:54:03.603] My PeerID: 10701E21939E86F984C250F5A2C5777061118D35[20150619 11:54:10.532] Error while adding folder /var/btsync/chrisvdb/Documents: Selected folder is already added to BitTorrent Sync.[20150619 11:54:10.532] Error while adding folder /var/btsync/chrisvdb/Pictures: Selected folder is already added to BitTorrent Sync.[20150619 11:55:10.067] PeerConnection[0x00007f01640051f0] incoming connection from 220.241.70.37:43879[20150619 11:55:11.067] PeerConnection[0x00007f01640051f0] incoming connection from 220.241.70.37:43879[20150619 11:55:12.360] PeerConnection[0x00007f0164208d00] incoming connection from 220.241.70.37:3182[20150619 11:56:49.476] SyncReq[0x00007f0164004b40][0000] [0000]: Unable to uncompress incoming data, err = -5[20150619 11:56:49.477] assert failed /mnt/jenkins/workspace/Build-Sync-x64/SyncConn.cpp:180[20150619 11:56:50.313] PeerConnection[0x00007f01642065f0] incoming connection from 220.241.70.37:3182[20150619 11:59:55.992] SyncReq[0x00007f0164208060][0000] [0000]: Unable to uncompress incoming data, err = -5[20150619 11:59:55.992] assert failed /mnt/jenkins/workspace/Build-Sync-x64/SyncConn.cpp:180[20150619 11:59:57.440] PeerConnection[0x00007f0164004a30] incoming connection from 220.241.70.37:3182[20150619 12:03:02.082] SyncReq[0x00007f0164211d80][0000] [0000]: Unable to uncompress incoming data, err = -5[20150619 12:03:02.082] assert failed /mnt/jenkins/workspace/Build-Sync-x64/SyncConn.cpp:180[20150619 12:03:03.547] PeerConnection[0x00007f01640039d0] incoming connection from 220.241.70.37:3182[20150619 12:06:01.931] SyncReq[0x00007f0164205840][0000] [0000]: Unable to uncompress incoming data, err = -5[20150619 12:06:01.931] assert failed /mnt/jenkins/workspace/Build-Sync-x64/SyncConn.cpp:180[20150619 12:06:03.333] PeerConnection[0x00007f01640039d0] incoming connection from 220.241.70.37:3182[20150619 12:09:05.213] SyncReq[0x00007f0164205840][0000] [0000]: Unable to uncompress incoming data, err = -5[20150619 12:09:05.214] assert failed /mnt/jenkins/workspace/Build-Sync-x64/SyncConn.cpp:180[20150619 12:09:05.629] PeerConnection[0x00007f01640039d0] incoming connection from 220.241.70.37:3182[20150619 12:12:05.936] SyncReq[0x00007f0164205840][0000] [0000]: Unable to uncompress incoming data, err = -5[20150619 12:12:05.936] assert failed /mnt/jenkins/workspace/Build-Sync-x64/SyncConn.cpp:180[20150619 12:12:07.569] PeerConnection[0x00007f01640039d0] incoming connection from 220.241.70.37:3182[20150619 12:15:11.207] SyncReq[0x00007f0164205840][0000] [0000]: Unable to uncompress incoming data, err = -5[20150619 12:15:11.207] assert failed /mnt/jenkins/workspace/Build-Sync-x64/SyncConn.cpp:180[20150619 12:15:12.307] PeerConnection[0x00007f01640039d0] incoming connection from 220.241.70.37:3182
 
My laptop:
 
My PeerID: 10C59E0DECCC36495E90ABC844E4044B23F98E4E platform: Linux 3.19.0-21-generic #21-Ubuntu SMP Sun Jun 14 18:31:11 UTC 2015 x86_64version: 2.0.125.32[20150619 18:15:56.786] MC[3D70] [8D35]: processing nodes message for /DXSMVS5N5PD2AN27JS6VCCAGQSANAW7CG7BXZXI/CNQJAZLLR3MOWJQZUH3AT2JRNM/5NIX4DYAAZK5DCVB6FY6PQ45IM/KLPGJEP36FGUPIN4VU4ZIC5SJ6WHMQDESC6LKKOXXZ4E45WD5A6Q/ZPJSG2MIB2FJ3S7TZSOZ2HTRNA/DC2MRSTKCNWFLYU7K5WRTMGUUU/AYIWSZNVCFNXN5F3ASBZL2M7HU[20150619 18:15:56.786] MC[3D70] [8D35]: will request files for /DXSMVS5N5PD2AN27JS6VCCAGQSANAW7CG7BXZXI/CNQJAZLLR3MOWJQZUH3AT2JRNM/5NIX4DYAAZK5DCVB6FY6PQ45IM/KLPGJEP36FGUPIN4VU4ZIC5SJ6WHMQDESC6LKKOXXZ4E45WD5A6Q/ZPJSG2MIB2FJ3S7TZSOZ2HTRNA/DC2MRSTKCNWFLYU7K5WRTMGUUU/AYIWSZNVCFNXN5F3ASBZL2M7HU[20150619 18:15:56.786] MC[3D70] [8D35]: processing nodes message for /DXSMVS5N5PD2AN27JS6VCCAGQSANAW7CG7BXZXI/CNQJAZLLR3MOWJQZUH3AT2JRNM/5NIX4DYAAZK5DCVB6FY6PQ45IM/KLPGJEP36FGUPIN4VU4ZIC5SJ6WHMQDESC6LKKOXXZ4E45WD5A6Q/ZPJSG2MIB2FJ3S7TZSOZ2HTRNA/DC2MRSTKCNWFLYU7K5WRTMGUUU/L5DPQOYMJLIAOHKELIG67UTCU4[20150619 18:15:56.786] MC[3D70] [8D35]: will request files for /DXSMVS5N5PD2AN27JS6VCCAGQSANAW7CG7BXZXI/CNQJAZLLR3MOWJQZUH3AT2JRNM/5NIX4DYAAZK5DCVB6FY6PQ45IM/KLPGJEP36FGUPIN4VU4ZIC5SJ6WHMQDESC6LKKOXXZ4E45WD5A6Q/ZPJSG2MIB2FJ3S7TZSOZ2HTRNA/DC2MRSTKCNWFLYU7K5WRTMGUUU/L5DPQOYMJLIAOHKELIG67UTCU4[20150619 18:15:56.786] MC[3D70] [8D35]: processing nodes message for /DXSMVS5N5PD2AN27JS6VCCAGQSANAW7CG7BXZXI/CNQJAZLLR3MOWJQZUH3AT2JRNM/5NIX4DYAAZK5DCVB6FY6PQ45IM/KLPGJEP36FGUPIN4VU4ZIC5SJ6WHMQDESC6LKKOXXZ4E45WD5A6Q/ZPJSG2MIB2FJ3S7TZSOZ2HTRNA/DC2MRSTKCNWFLYU7K5WRTMGUUU/VWTRMJEIT4J5WJFS3GYLLJSU7Q[20150619 18:15:56.786] MC[3D70] [8D35]: will request files for /DXSMVS5N5PD2AN27JS6VCCAGQSANAW7CG7BXZXI/CNQJAZLLR3MOWJQZUH3AT2JRNM/5NIX4DYAAZK5DCVB6FY6PQ45IM/KLPGJEP36FGUPIN4VU4ZIC5SJ6WHMQDESC6LKKOXXZ4E45WD5A6Q/ZPJSG2MIB2FJ3S7TZSOZ2HTRNA/DC2MRSTKCNWFLYU7K5WRTMGUUU/VWTRMJEIT4J5WJFS3GYLLJSU7Q[20150619 18:15:56.786] MC[3D70] [8D35]: processing nodes message for /DXSMVS5N5PD2AN27JS6VCCAGQSANAW7CG7BXZXI/CNQJAZLLR3MOWJQZUH3AT2JRNM/5NIX4DYAAZK5DCVB6FY6PQ45IM/KLPGJEP36FGUPIN4VU4ZIC5SJ6WHMQDESC6LKKOXXZ4E45WD5A6Q/ZPJSG2MIB2FJ3S7TZSOZ2HTRNA/MTMP576WBVZ37XYRX4C4ZJRH4Q/O2FO65HYLZ7TN2TXQSKP5Z7C6A[20150619 18:15:56.786] MC[3D70] [8D35]: will request files for /DXSMVS5N5PD2AN27JS6VCCAGQSANAW7CG7BXZXI/CNQJAZLLR3MOWJQZUH3AT2JRNM/5NIX4DYAAZK5DCVB6FY6PQ45IM/KLPGJEP36FGUPIN4VU4ZIC5SJ6WHMQDESC6LKKOXXZ4E45WD5A6Q/ZPJSG2MIB2FJ3S7TZSOZ2HTRNA/MTMP576WBVZ37XYRX4C4ZJRH4Q/O2FO65HYLZ7TN2TXQSKP5Z7C6A<snip>[20150619 18:16:30.739] MC[3D70] [8D35]: will request files for /YLS35NJ2GG23AXHFFDQXMLCMICBCBAA6RY3UAMY/5GRKAKTSSQQKUOTSKDGLGYXUDQ/MEHS4KLVSPFRH2MKYBS4SWAA3Q/UIHMC3TZ5ESLBGNVDZ6BZWYXVA/ZJ43EW4ZXQYC6DRHC22R6PPCA3T6R7RT32DPTSNZDCFFE7SQ4EFQ/KQ3SORBPT3SFTBQLRUEEHDBJ7U/DWZIMFHFA7GEXSETNC4W6XCUTA/GSBJ5IYQJXMY7MGFFOYAOM4LVU/3LOEAFFYEV47UA7FXGZ3BYNDGE/5VDHBCUX7G6XHVWUSUCDVXI5XQ[20150619 18:16:30.739] MC[3D70] [8D35]: will request nodes for /YLS35NJ2GG23AXHFFDQXMLCMICBCBAA6RY3UAMY/5GRKAKTSSQQKUOTSKDGLGYXUDQ/MEHS4KLVSPFRH2MKYBS4SWAA3Q/UIHMC3TZ5ESLBGNVDZ6BZWYXVA/ZJ43EW4ZXQYC6DRHC22R6PPCA3T6R7RT32DPTSNZDCFFE7SQ4EFQ/KQ3SORBPT3SFTBQLRUEEHDBJ7U/DWZIMFHFA7GEXSETNC4W6XCUTA/GSBJ5IYQJXMY7MGFFOYAOM4LVU/3LOEAFFYEV47UA7FXGZ3BYNDGE/5VDHBCUX7G6XHVWUSUCDVXI5XQ/6SP2DVP2OI3JGNGWZXVNWN6EOLSU3NKEVKVC35KBZ2GXGVGUOW2Q[20150619 18:16:30.739] MC[3D70] [8D35]: processing nodes message for /YLS35NJ2GG23AXHFFDQXMLCMICBCBAA6RY3UAMY/5GRKAKTSSQQKUOTSKDGLGYXUDQ/MEHS4KLVSPFRH2MKYBS4SWAA3Q/UIHMC3TZ5ESLBGNVDZ6BZWYXVA/ZJ43EW4ZXQYC6DRHC22R6PPCA3T6R7RT32DPTSNZDCFFE7SQ4EFQ/KQ3SORBPT3SFTBQLRUEEHDBJ7U/DWZIMFHFA7GEXSETNC4W6XCUTA/GSBJ5IYQJXMY7MGFFOYAOM4LVU/3LOEAFFYEV47UA7FXGZ3BYNDGE/6CPAECARAGAZDCTKONM5NGC5NM[20150619 18:16:30.739] MC[3D70] [8D35]: will request files for /YLS35NJ2GG23AXHFFDQXMLCMICBCBAA6RY3UAMY/5GRKAKTSSQQKUOTSKDGLGYXUDQ/MEHS4KLVSPFRH2MKYBS4SWAA3Q/UIHMC3TZ5ESLBGNVDZ6BZWYXVA/ZJ43EW4ZXQYC6DRHC22R6PPCA3T6R7RT32DPTSNZDCFFE7SQ4EFQ/KQ3SORBPT3SFTBQLRUEEHDBJ7U/DWZIMFHFA7GEXSETNC4W6XCUTA/GSBJ5IYQJXMY7MGFFOYAOM4LVU/3LOEAFFYEV47UA7FXGZ3BYNDGE/6CPAECARAGAZDCTKONM5NGC5NM[20150619 18:16:30.739] MC[3D70] [8D35]: will request nodes for /YLS35NJ2GG23AXHFFDQXMLCMICBCBAA6RY3UAMY/5GRKAKTSSQQKUOTSKDGLGYXUDQ/MEHS4KLVSPFRH2MKYBS4SWAA3Q/UIHMC3TZ5ESLBGNVDZ6BZWYXVA/ZJ43EW4ZXQYC6DRHC22R6PPCA3T6R7RT32DPTSNZDCFFE7SQ4EFQ/KQ3SORBPT3SFTBQLRUEEHDBJ7U/DWZIMFHFA7GEXSETNC4W6XCUTA/GSBJ5IYQJXMY7MGFFOYAOM4LVU/3LOEAFFYEV47UA7FXGZ3BYNDGE/6CPAECARAGAZDCTKONM5NGC5NM/LP4BW4XP2527ODOOSP4VUAONJQ[20150619 18:16:30.739] MC[3D70] [8D35]: will request nodes for /YLS35NJ2GG23AXHFFDQXMLCMICBCBAA6RY3UAMY/5GRKAKTSSQQKUOTSKDGLGYXUDQ/MEHS4KLVSPFRH2MKYBS4SWAA3Q/UIHMC3TZ5ESLBGNVDZ6BZWYXVA/ZJ43EW4ZXQYC6DRHC22R6PPCA3T6R7RT32DPTSNZDCFFE7SQ4EFQ/KQ3SORBPT3SFTBQLRUEEHDBJ7U/DWZIMFHFA7GEXSETNC4W6XCUTA/GSBJ5IYQJXMY7MGFFOYAOM4LVU/3LOEAFFYEV47UA7FXGZ3BYNDGE/6CPAECARAGAZDCTKONM5NGC5NM/QXZAUOH4IH2BJ5WA44OLAORFMU[20150619 18:16:30.739] MC[3D70] [8D35]: will request nodes for /YLS35NJ2GG23AXHFFDQXMLCMICBCBAA6RY3UAMY/5GRKAKTSSQQKUOTSKDGLGYXUDQ/MEHS4KLVSPFRH2MKYBS4SWAA3Q/UIHMC3TZ5ESLBGNVDZ6BZWYXVA/ZJ43EW4ZXQYC6DRHC22R6PPCA3T6R7RT32DPTSNZDCFFE7SQ4EFQ/KQ3SORBPT3SFTBQLRUEEHDBJ7U/DWZIMFHFA7GEXSETNC4W6XCUTA/GSBJ5IYQJXMY7MGFFOYAOM4LVU/3LOEAFFYEV47UA7FXGZ3BYNDGE/6CPAECARAGAZDCTKONM5NGC5NM/S4L24IACDVLYI3KQMKCQ4ZKGQM[20150619 18:16:30.739] MC[3D70] [8D35]: sending get_nodes message[20150619 18:16:30.771] SF[3D70] [8D35]: SyncStateWithPeer - already pending FB1F5E50[20150619 18:16:31.281] SF[3D70] [8D35]: SyncStateWithPeer - already pending FB1F5E50[20150619 18:16:32.108] SF[3D70] [8D35]: SyncStateWithPeer - already pending FB1F5E50

Do you want the entire logs? If so, where do I send them?

 

Chris.

Share this post


Link to post
Share on other sites

Chris,

 

I mean - what is your experience if you forget about logs for a moment? Is Sync not delivering data, or doing it slowly or peers don't see each other?

Share this post


Link to post
Share on other sites

The devices were sync'ed before I installed 2.0.125, but do not seem to be sync'ing new files. The GUI on my laptop shows Timbuktu as one of the peers, so they do seem to see each other.

 

I now get errors on the laptop as well:

 

[20150619 20:55:15.175] SF[3D70] [8D35]: State sync finished [20150619 20:55:15.175] SyncReq[0x00007fbcf927d440][3D70] [0000]: cancel F927D440 - outgoing merge[20150619 20:55:15.176] SF[3D70] [8D35]: Going to sync state with peer 144.x.x.x:65432[20150619 20:55:15.176] SyncReq[0x00007fbcf921b770][3D70] [0000]: debug F921B770 - outgoing merge[20150619 20:55:15.176] ScheduledTask:SyncState invoked:immediately reason:FinishStateSync - failed (no MC)[20150619 20:55:15.201] SyncReq[0x00007fbcf927d440][3D70] [0000]: destroing F927D440 cbcnt:1 - outgoing merge
 

Share this post


Link to post
Share on other sites

Join the conversation

You can post now and register later. If you have an account, sign in now to post with your account.
Note: Your post will require moderator approval before it will be visible.

Guest
Reply to this topic...

×   Pasted as rich text.   Paste as plain text instead

  Only 75 emoji are allowed.

×   Your link has been automatically embedded.   Display as a link instead

×   Your previous content has been restored.   Clear editor

×   You cannot paste images directly. Upload or insert images from URL.