search

syncthing / syncthing

Open Source Continuous File Synchronization
https://syncthing.net/
Mozilla Public License 2.0
63.75k stars 4.22k forks source link

[Android] Renaming file uppercase causes both files to be deleted #7974

Closed jeromecst closed 2 years ago

jeromecst commented 2 years ago

What happened I renamed test.txt to TEST.txt and both files were deleted.

What operating system, operating system version and version of Syncthing you are running jpc device: v1.18.2, Linux (64-bit Intel/AMD)

The same for other connected devices, where relevant jphone device: Syncthing Version: v1.18.2 Syncthing-Android Version: 1.18.2

Screenshot if the issue concerns something visible in the GUI syncth

calmh commented 2 years ago

Please post the config.xml from both sides. This should not happen with reasonable/default settings...

jeromecst commented 2 years ago

Linux device here

<configuration version="35">
    <folder id="reixg-dsqph" label="cours" path="/home/jerome/cours" type="sendreceive" rescanIntervalS="3600" fsWatcherEnabled="true" fsWatcherDelayS="10" ignorePerms="false" autoNormalize="true">
        <filesystemType>basic</filesystemType>
        <device id="CEDTNQ2-ZZVWOVG-FOY6BLN-J3TCDIC-STHMPIK-ECCMC5E-XOTDOBW-64RS3QZ" introducedBy="">
            <encryptionPassword></encryptionPassword>
        </device>
        <device id="57WOA3J-U66ZC5U-OR4MGTE-2Z4YONC-LOSYK7M-ZADGN7J-5WI72UB-LPDIQAX" introducedBy="">
            <encryptionPassword></encryptionPassword>
        </device>
        <device id="7EFK7KM-U7DETJ7-QTHI7UD-5PVHEAD-JPZGN5J-LNPR3IS-73IWI37-QEZ6SA4" introducedBy="">
            <encryptionPassword></encryptionPassword>
        </device>
        <minDiskFree unit="%">1</minDiskFree>
        <versioning>
            <cleanupIntervalS>0</cleanupIntervalS>
            <fsPath></fsPath>
            <fsType>basic</fsType>
        </versioning>
        <copiers>0</copiers>
        <pullerMaxPendingKiB>0</pullerMaxPendingKiB>
        <hashers>0</hashers>
        <order>random</order>
        <ignoreDelete>false</ignoreDelete>
        <scanProgressIntervalS>0</scanProgressIntervalS>
        <pullerPauseS>0</pullerPauseS>
        <maxConflicts>10</maxConflicts>
        <disableSparseFiles>false</disableSparseFiles>
        <disableTempIndexes>false</disableTempIndexes>
        <paused>false</paused>
        <weakHashThresholdPct>25</weakHashThresholdPct>
        <markerName>.stfolder</markerName>
        <copyOwnershipFromParent>false</copyOwnershipFromParent>
        <modTimeWindowS>0</modTimeWindowS>
        <maxConcurrentWrites>2</maxConcurrentWrites>
        <disableFsync>false</disableFsync>
        <blockPullOrder>standard</blockPullOrder>
        <copyRangeMethod>standard</copyRangeMethod>
        <caseSensitiveFS>false</caseSensitiveFS>
        <junctionsAsDirs>false</junctionsAsDirs>
    </folder>
    <device id="CEDTNQ2-ZZVWOVG-FOY6BLN-J3TCDIC-STHMPIK-ECCMC5E-XOTDOBW-64RS3QZ" name="jpc" compression="metadata" introducer="false" skipIntroductionRemovals="false" introducedBy="">
        <address>dynamic</address>
        <paused>false</paused>
        <autoAcceptFolders>false</autoAcceptFolders>
        <maxSendKbps>0</maxSendKbps>
        <maxRecvKbps>0</maxRecvKbps>
        <maxRequestKiB>0</maxRequestKiB>
        <untrusted>false</untrusted>
        <remoteGUIPort>0</remoteGUIPort>
    </device>
    <device id="57WOA3J-U66ZC5U-OR4MGTE-2Z4YONC-LOSYK7M-ZADGN7J-5WI72UB-LPDIQAX" name="phone" compression="metadata" introducer="false" skipIntroductionRemovals="false" introducedBy="">
        <address>dynamic</address>
        <paused>false</paused>
        <autoAcceptFolders>false</autoAcceptFolders>
        <maxSendKbps>0</maxSendKbps>
        <maxRecvKbps>0</maxRecvKbps>
        <maxRequestKiB>0</maxRequestKiB>
        <untrusted>false</untrusted>
        <remoteGUIPort>0</remoteGUIPort>
    </device>
    <gui enabled="true" tls="false" debugging="false">
        <address>127.0.0.1:8384</address>
        <apikey>womMUXyd26cfzxSfQEvw9jkmANRJVFwu</apikey>
        <theme>black</theme>
    </gui>
    <ldap></ldap>
    <options>
        <listenAddress>default</listenAddress>
        <globalAnnounceServer>default</globalAnnounceServer>
        <globalAnnounceEnabled>true</globalAnnounceEnabled>
        <localAnnounceEnabled>true</localAnnounceEnabled>
        <localAnnouncePort>21027</localAnnouncePort>
        <localAnnounceMCAddr>[ff12::8384]:21027</localAnnounceMCAddr>
        <maxSendKbps>0</maxSendKbps>
        <maxRecvKbps>0</maxRecvKbps>
        <reconnectionIntervalS>60</reconnectionIntervalS>
        <relaysEnabled>true</relaysEnabled>
        <relayReconnectIntervalM>10</relayReconnectIntervalM>
        <startBrowser>true</startBrowser>
        <natEnabled>true</natEnabled>
        <natLeaseMinutes>60</natLeaseMinutes>
        <natRenewalMinutes>30</natRenewalMinutes>
        <natTimeoutSeconds>10</natTimeoutSeconds>
        <urAccepted>-1</urAccepted>
        <urSeen>3</urSeen>
        <urUniqueID></urUniqueID>
        <urURL>https://data.syncthing.net/newdata</urURL>
        <urPostInsecurely>false</urPostInsecurely>
        <urInitialDelayS>1800</urInitialDelayS>
        <restartOnWakeup>true</restartOnWakeup>
        <autoUpgradeIntervalH>12</autoUpgradeIntervalH>
        <upgradeToPreReleases>false</upgradeToPreReleases>
        <keepTemporariesH>24</keepTemporariesH>
        <cacheIgnoredFiles>false</cacheIgnoredFiles>
        <progressUpdateIntervalS>5</progressUpdateIntervalS>
        <limitBandwidthInLan>false</limitBandwidthInLan>
        <minHomeDiskFree unit="%">1</minHomeDiskFree>
        <releasesURL>https://upgrades.syncthing.net/meta.json</releasesURL>
        <overwriteRemoteDeviceNamesOnConnect>false</overwriteRemoteDeviceNamesOnConnect>
        <tempIndexMinBlocks>10</tempIndexMinBlocks>
        <trafficClass>0</trafficClass>
        <setLowPriority>true</setLowPriority>
        <maxFolderConcurrency>0</maxFolderConcurrency>
        <crashReportingURL>https://crash.syncthing.net/newcrash</crashReportingURL>
        <crashReportingEnabled>true</crashReportingEnabled>
        <stunKeepaliveStartS>180</stunKeepaliveStartS>
        <stunKeepaliveMinS>20</stunKeepaliveMinS>
        <stunServer>default</stunServer>
        <databaseTuning>auto</databaseTuning>
        <maxConcurrentIncomingRequestKiB>0</maxConcurrentIncomingRequestKiB>
        <announceLANAddresses>true</announceLANAddresses>
        <sendFullIndexOnUpgrade>false</sendFullIndexOnUpgrade>
        <connectionLimitEnough>0</connectionLimitEnough>
        <connectionLimitMax>0</connectionLimitMax>
        <insecureAllowOldTLSVersions>false</insecureAllowOldTLSVersions>
    </options>
    <defaults>
        <folder id="" label="" path="~" type="sendreceive" rescanIntervalS="3600" fsWatcherEnabled="true" fsWatcherDelayS="10" ignorePerms="false" autoNormalize="true">
            <filesystemType>basic</filesystemType>
            <device id="CEDTNQ2-ZZVWOVG-FOY6BLN-J3TCDIC-STHMPIK-ECCMC5E-XOTDOBW-64RS3QZ" introducedBy="">
                <encryptionPassword></encryptionPassword>
            </device>
            <minDiskFree unit="%">1</minDiskFree>
            <versioning>
                <cleanupIntervalS>3600</cleanupIntervalS>
                <fsPath></fsPath>
                <fsType>basic</fsType>
            </versioning>
            <copiers>0</copiers>
            <pullerMaxPendingKiB>0</pullerMaxPendingKiB>
            <hashers>0</hashers>
            <order>random</order>
            <ignoreDelete>false</ignoreDelete>
            <scanProgressIntervalS>0</scanProgressIntervalS>
            <pullerPauseS>0</pullerPauseS>
            <maxConflicts>10</maxConflicts>
            <disableSparseFiles>false</disableSparseFiles>
            <disableTempIndexes>false</disableTempIndexes>
            <paused>false</paused>
            <weakHashThresholdPct>25</weakHashThresholdPct>
            <markerName>.stfolder</markerName>
            <copyOwnershipFromParent>false</copyOwnershipFromParent>
            <modTimeWindowS>0</modTimeWindowS>
            <maxConcurrentWrites>2</maxConcurrentWrites>
            <disableFsync>false</disableFsync>
            <blockPullOrder>standard</blockPullOrder>
            <copyRangeMethod>standard</copyRangeMethod>
            <caseSensitiveFS>false</caseSensitiveFS>
            <junctionsAsDirs>false</junctionsAsDirs>
        </folder>
        <device id="" compression="metadata" introducer="false" skipIntroductionRemovals="false" introducedBy="">
            <address>dynamic</address>
            <paused>false</paused>
            <autoAcceptFolders>false</autoAcceptFolders>
            <maxSendKbps>0</maxSendKbps>
            <maxRecvKbps>0</maxRecvKbps>
            <maxRequestKiB>0</maxRequestKiB>
            <untrusted>false</untrusted>
            <remoteGUIPort>0</remoteGUIPort>
        </device>
    </defaults>
</configuration>

Android device

<?xml version="1.0" encoding="UTF-8"?><configuration version="35">
    <folder id="reixg-dsqph" label="cours" path="/storage/emulated/0/cours" type="sendreceive" rescanIntervalS="3600" fsWatcherEnabled="true" fsWatcherDelayS="10" ignorePerms="true" autoNormalize="true">
        <filesystemType>basic</filesystemType>
        <device id="CEDTNQ2-ZZVWOVG-FOY6BLN-J3TCDIC-STHMPIK-ECCMC5E-XOTDOBW-64RS3QZ" introducedBy="">
            <encryptionPassword/>
        </device>
        <device id="57WOA3J-U66ZC5U-OR4MGTE-2Z4YONC-LOSYK7M-ZADGN7J-5WI72UB-LPDIQAX" introducedBy="">
            <encryptionPassword/>
        </device>
        <device id="7EFK7KM-U7DETJ7-QTHI7UD-5PVHEAD-JPZGN5J-LNPR3IS-73IWI37-QEZ6SA4" introducedBy="">
            <encryptionPassword/>
        </device>
        <minDiskFree unit="%">1</minDiskFree>
        <versioning>
            <cleanupIntervalS>3600</cleanupIntervalS>
            <fsPath/>
            <fsType>basic</fsType>
        </versioning>
        <copiers>0</copiers>
        <pullerMaxPendingKiB>0</pullerMaxPendingKiB>
        <hashers>1</hashers>
        <order>random</order>
        <ignoreDelete>false</ignoreDelete>
        <scanProgressIntervalS>0</scanProgressIntervalS>
        <pullerPauseS>0</pullerPauseS>
        <maxConflicts>10</maxConflicts>
        <disableSparseFiles>false</disableSparseFiles>
        <disableTempIndexes>false</disableTempIndexes>
        <paused>false</paused>
        <weakHashThresholdPct>25</weakHashThresholdPct>
        <markerName>.stfolder</markerName>
        <copyOwnershipFromParent>false</copyOwnershipFromParent>
        <modTimeWindowS>0</modTimeWindowS>
        <maxConcurrentWrites>2</maxConcurrentWrites>
        <disableFsync>false</disableFsync>
        <blockPullOrder>standard</blockPullOrder>
        <copyRangeMethod>standard</copyRangeMethod>
        <caseSensitiveFS>false</caseSensitiveFS>
        <junctionsAsDirs>false</junctionsAsDirs>
    </folder>
    <device id="CEDTNQ2-ZZVWOVG-FOY6BLN-J3TCDIC-STHMPIK-ECCMC5E-XOTDOBW-64RS3QZ" name="desktop" compression="metadata" introducer="true" skipIntroductionRemovals="false" introducedBy="">
        <address>dynamic</address>
        <paused>false</paused>
        <autoAcceptFolders>false</autoAcceptFolders>
        <maxSendKbps>0</maxSendKbps>
        <maxRecvKbps>0</maxRecvKbps>
        <ignoredFolder time="2021-09-23T23:40:54+02:00" id="47nzj-1cntd" label="OpenCamera"/>
        <maxRequestKiB>0</maxRequestKiB>
        <untrusted>false</untrusted>
        <remoteGUIPort>0</remoteGUIPort>
    </device>
    <device id="57WOA3J-U66ZC5U-OR4MGTE-2Z4YONC-LOSYK7M-ZADGN7J-5WI72UB-LPDIQAX" name="SM-A520F" compression="metadata" introducer="false" skipIntroductionRemovals="false" introducedBy="">
        <address>dynamic</address>
        <paused>false</paused>
        <autoAcceptFolders>false</autoAcceptFolders>
        <maxSendKbps>0</maxSendKbps>
        <maxRecvKbps>0</maxRecvKbps>
        <maxRequestKiB>0</maxRequestKiB>
        <untrusted>false</untrusted>
        <remoteGUIPort>0</remoteGUIPort>
    </device>
    <gui enabled="true" tls="true" debugging="false">
        <address>127.0.0.1:8384</address>
        <user>syncthing</user>
        <password>$2a$04$a3RiNTq693qAn05JOMZ5rO72S4pF6XRFdaoaxxfhANUUq55BNTjqe</password>
        <apikey>pFLd6YJTHZrSryLPY2e5wyLZMmATwdcW</apikey>
        <theme>default</theme>
    </gui>
    <ldap/>
    <options>
        <listenAddress>default</listenAddress>
        <globalAnnounceServer>default</globalAnnounceServer>
        <globalAnnounceEnabled>true</globalAnnounceEnabled>
        <localAnnounceEnabled>true</localAnnounceEnabled>
        <localAnnouncePort>21027</localAnnouncePort>
        <localAnnounceMCAddr>[ff12::8384]:21027</localAnnounceMCAddr>
        <maxSendKbps>0</maxSendKbps>
        <maxRecvKbps>0</maxRecvKbps>
        <reconnectionIntervalS>60</reconnectionIntervalS>
        <relaysEnabled>true</relaysEnabled>
        <relayReconnectIntervalM>10</relayReconnectIntervalM>
        <startBrowser>true</startBrowser>
        <natEnabled>true</natEnabled>
        <natLeaseMinutes>60</natLeaseMinutes>
        <natRenewalMinutes>30</natRenewalMinutes>
        <natTimeoutSeconds>10</natTimeoutSeconds>
        <urAccepted>-1</urAccepted>
        <urSeen>0</urSeen>
        <urUniqueID/>
        <urURL>https://data.syncthing.net/newdata</urURL>
        <urPostInsecurely>false</urPostInsecurely>
        <urInitialDelayS>1800</urInitialDelayS>
        <restartOnWakeup>true</restartOnWakeup>
        <autoUpgradeIntervalH>12</autoUpgradeIntervalH>
        <upgradeToPreReleases>false</upgradeToPreReleases>
        <keepTemporariesH>24</keepTemporariesH>
        <cacheIgnoredFiles>false</cacheIgnoredFiles>
        <progressUpdateIntervalS>5</progressUpdateIntervalS>
        <limitBandwidthInLan>false</limitBandwidthInLan>
        <minHomeDiskFree unit="%">1</minHomeDiskFree>
        <releasesURL>https://upgrades.syncthing.net/meta.json</releasesURL>
        <overwriteRemoteDeviceNamesOnConnect>false</overwriteRemoteDeviceNamesOnConnect>
        <tempIndexMinBlocks>10</tempIndexMinBlocks>
        <trafficClass>0</trafficClass>
        <setLowPriority>true</setLowPriority>
        <maxFolderConcurrency>0</maxFolderConcurrency>
        <crashReportingURL>https://crash.syncthing.net/newcrash</crashReportingURL>
        <crashReportingEnabled>true</crashReportingEnabled>
        <stunKeepaliveStartS>180</stunKeepaliveStartS>
        <stunKeepaliveMinS>20</stunKeepaliveMinS>
        <stunServer>default</stunServer>
        <databaseTuning>auto</databaseTuning>
        <maxConcurrentIncomingRequestKiB>0</maxConcurrentIncomingRequestKiB>
        <announceLANAddresses>true</announceLANAddresses>
        <sendFullIndexOnUpgrade>false</sendFullIndexOnUpgrade>
        <connectionLimitEnough>0</connectionLimitEnough>
        <connectionLimitMax>0</connectionLimitMax>
        <insecureAllowOldTLSVersions>false</insecureAllowOldTLSVersions>
    <weakHashSelectionMethod>never</weakHashSelectionMethod></options>
    <remoteIgnoredDevice time="2021-08-28T18:59:13+02:00" id="ILWYUGX-D6M2TL4-3OLORSY-XI6VVC6-I4QGPZK-X3LX7RQ-MBJCTU4-APLBOAL" name="thinkpad" address="192.168.1.27:22000"/>
    <defaults>
        <folder id="" label="" path="~" type="sendreceive" rescanIntervalS="3600" fsWatcherEnabled="true" fsWatcherDelayS="10" ignorePerms="true" autoNormalize="true">
            <filesystemType>basic</filesystemType>
            <device id="57WOA3J-U66ZC5U-OR4MGTE-2Z4YONC-LOSYK7M-ZADGN7J-5WI72UB-LPDIQAX" introducedBy="">
                <encryptionPassword/>
            </device>
            <minDiskFree unit="%">1</minDiskFree>
            <versioning>
                <cleanupIntervalS>3600</cleanupIntervalS>
                <fsPath/>
                <fsType>basic</fsType>
            </versioning>
            <copiers>0</copiers>
            <pullerMaxPendingKiB>0</pullerMaxPendingKiB>
            <hashers>1</hashers>
            <order>random</order>
            <ignoreDelete>false</ignoreDelete>
            <scanProgressIntervalS>0</scanProgressIntervalS>
            <pullerPauseS>0</pullerPauseS>
            <maxConflicts>10</maxConflicts>
            <disableSparseFiles>false</disableSparseFiles>
            <disableTempIndexes>false</disableTempIndexes>
            <paused>false</paused>
            <weakHashThresholdPct>25</weakHashThresholdPct>
            <markerName>.stfolder</markerName>
            <copyOwnershipFromParent>false</copyOwnershipFromParent>
            <modTimeWindowS>0</modTimeWindowS>
            <maxConcurrentWrites>2</maxConcurrentWrites>
            <disableFsync>false</disableFsync>
            <blockPullOrder>standard</blockPullOrder>
            <copyRangeMethod>standard</copyRangeMethod>
            <caseSensitiveFS>false</caseSensitiveFS>
            <junctionsAsDirs>false</junctionsAsDirs>
        </folder>
        <device id="" compression="metadata" introducer="false" skipIntroductionRemovals="false" introducedBy="">
            <address>dynamic</address>
            <paused>false</paused>
            <autoAcceptFolders>false</autoAcceptFolders>
            <maxSendKbps>0</maxSendKbps>
            <maxRecvKbps>0</maxRecvKbps>
            <maxRequestKiB>0</maxRequestKiB>
            <untrusted>false</untrusted>
            <remoteGUIPort>0</remoteGUIPort>
        </device>
    </defaults>
</configuration>
calmh commented 2 years ago

That looks precisely as it should, and we have code to prevent exactly what happened to you, yet here we are. Given the devices involved I'm inclined to suspect that this is a question of Android file system caches lying to us somehow. It could probably be reproduced by someone with an Android inclination and narrowed down closer.

tomasz1986 commented 2 years ago

I can confirm that something seems to be acting up on Android. When I try to rename the file from test.txt to TEST.txt on Windows, and then sync it with Android, I get an error there. However, in my case the file isn't deleted though. The error stays like that for a minute or so, and then just goes away.

image image

Here is a log from the Android device with db,model enabled.

2021-09-27 20:35:17 mgieg-z3mzc Get(TEST.txt)
2021-09-27 20:35:17 mgieg-z3mzc Get(test.txt)
2021-09-27 20:35:17 mgieg-z3mzc GetGlobal(TEST.txt)
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 parent not missing TEST.txt
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 taking rename shortcut test.txt -> TEST.txt
2021-09-27 20:35:17 rename shortcut for TEST.txt failed: file modified but not rescanned; will try again later
2021-09-27 20:35:17 mgieg-z3mzc Availability(TEST.txt)
2021-09-27 20:35:17 mgieg-z3mzc Get(TEST.txt)
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 need file TEST.txt; copy 0, reused 1
2021-09-27 20:35:17 progress emitter: disabled, skip registering
2021-09-27 20:35:17 not weak hashing TEST.txt. file did not contain any weak hashes
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 closing TEST.txt
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 new error for TEST.txt: file does not exist
2021-09-27 20:35:17 progress emitter: disabled, skip deregistering
2021-09-27 20:35:17 mgieg-z3mzc Get(test.txt)
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 Deleting file test.txt
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 new error for test.txt: delete file: file modified but not rescanned; will try again later
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 changed 2 on try 2
2021-09-27 20:35:17 mgieg-z3mzc Snapshot()
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 copiers: 2 pullerPendingKiB: 32768
2021-09-27 20:35:17 mgieg-z3mzc WithNeed(7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4)
2021-09-27 20:35:17 mgieg-z3mzc Get(TEST.txt)
2021-09-27 20:35:17 mgieg-z3mzc Get(test.txt)
2021-09-27 20:35:17 mgieg-z3mzc GetGlobal(TEST.txt)
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 parent not missing TEST.txt
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 taking rename shortcut test.txt -> TEST.txt
2021-09-27 20:35:17 rename shortcut for TEST.txt failed: file modified but not rescanned; will try again later
2021-09-27 20:35:17 mgieg-z3mzc Availability(TEST.txt)
2021-09-27 20:35:17 mgieg-z3mzc Get(TEST.txt)
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 need file TEST.txt; copy 0, reused 1
2021-09-27 20:35:17 progress emitter: disabled, skip registering
2021-09-27 20:35:17 not weak hashing TEST.txt. file did not contain any weak hashes
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 closing TEST.txt
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 new error for TEST.txt: file does not exist
2021-09-27 20:35:17 progress emitter: disabled, skip deregistering
2021-09-27 20:35:17 mgieg-z3mzc Get(test.txt)
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 Deleting file test.txt
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 new error for test.txt: delete file: file modified but not rescanned; will try again later
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 changed 2 on try 3
2021-09-27 20:35:17 Puller (folder "xxx" (mgieg-z3mzc), item "TEST.txt"): syncing: file does not exist
2021-09-27 20:35:17 Puller (folder "xxx" (mgieg-z3mzc), item "test.txt"): syncing: delete file: file modified but not rescanned; will try again later
2021-09-27 20:35:17 "xxx" (mgieg-z3mzc): Failed to sync 2 items
2021-09-27 20:35:17 Folder "xxx" (mgieg-z3mzc) isn't making sync progress - retrying in 1m0s.
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 scheduling scan after pulling for test.txt
2021-09-27 20:35:17 mgieg-z3mzc Snapshot()
2021-09-27 20:35:17 progress emitter: bytes completed for mgieg-z3mzc: 0
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 Running something due to request
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 scanning
2021-09-27 20:35:17 mgieg-z3mzc Snapshot()
2021-09-27 20:35:17 mgieg-z3mzc Snapshot()
2021-09-27 20:35:17 mgieg-z3mzc Snapshot()
2021-09-27 20:35:17 model@0x520830a0 Completion(D4DZUGP, "mgieg-z3mzc"): map[completion:100 globalBytes:40602799 globalItems:88 needBytes:0 needDeletes:0 needItems:0 sequence:1006]
2021-09-27 20:35:17 mgieg-z3mzc Snapshot()
2021-09-27 20:35:17 mgieg-z3mzc WithPrefixedHaveTruncated(7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4, "test.txt")
2021-09-27 20:35:17 marking file as deleted File{Name:"test.txt", Sequence:520, Permissions:0644, ModTime:2021-09-27 20:35:17.425344379 +0900 KST, Version:{[{D4DZUGP 1632742375} {6I7GNCY 1632742517}]}, VersionHash:, Length:0, Deleted:true, Invalid:false, LocalFlags:0x0, NoPermissions:true, BlockSize:131072, Blocks:[], BlocksHash:}
2021-09-27 20:35:17 mgieg-z3mzc GetGlobal(test.txt)
2021-09-27 20:35:17 mgieg-z3mzc Update(7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4, [1])
2021-09-27 20:35:17 removing sequence; folder="mgieg-z3mzc" sequence=520 test.txt
2021-09-27 20:35:17 insert (local); folder="mgieg-z3mzc" File{Name:"test.txt", Sequence:521, Permissions:0644, ModTime:2021-09-27 20:35:17.425344379 +0900 KST, Version:{[{D4DZUGP 1632742375} {6I7GNCY 1632742517}]}, VersionHash:, Length:0, Deleted:true, Invalid:false, LocalFlags:0x0, NoPermissions:true, BlockSize:131072, Blocks:[], BlocksHash:}
2021-09-27 20:35:17 update global; folder="mgieg-z3mzc" device=7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4 file="test.txt" version={[{D4DZUGP 1632742375} {6I7GNCY 1632742517}]} invalid=false
2021-09-27 20:35:17 new global for "test.txt" after update: {{Version:{[{D4DZUGP 1632742375} {6I7GNCY 1632742517}]}, Deleted:true, Devices:{7777777}, Invalid:{}}, {Version:{[{D4DZUGP 1632742508} {6I7GNCY 1632742217}]}, Deleted:true, Devices:{D4DZUGP}, Invalid:{}}}
2021-09-27 20:35:17 local need delete; folder="mgieg-z3mzc", name="test.txt"
2021-09-27 20:35:17 adding sequence; folder="mgieg-z3mzc" sequence=521 test.txt
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 finished scanning, detected 1 changes
2021-09-27 20:35:17 mgieg-z3mzc Snapshot()
2021-09-27 20:35:17 mgieg-z3mzc WithNeed(7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4)
2021-09-27 20:35:17 mgieg-z3mzc Snapshot()
2021-09-27 20:35:17 mgieg-z3mzc WithHaveSequence(521)
2021-09-27 20:35:17 indexHandler@0x5256e3c0 for mgieg-z3mzc to D4DZUGP at [fe80::5e3c:27ff:fe37:988d%wlan0]:22000-[fe80::9868:3753:49ff:a06%wlan0]:22000/tcp-server/TLS1.3-TLS_CHACHA20_POLY1305_SHA256: Sending 1 files (<86 bytes)
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 pulling
2021-09-27 20:35:17 mgieg-z3mzc Snapshot()
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 copiers: 2 pullerPendingKiB: 32768
2021-09-27 20:35:17 mgieg-z3mzc WithNeed(7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4)
2021-09-27 20:35:17 mgieg-z3mzc Get(TEST.txt)
2021-09-27 20:35:17 mgieg-z3mzc GetGlobal(TEST.txt)
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 parent not missing TEST.txt
2021-09-27 20:35:17 mgieg-z3mzc Availability(TEST.txt)
2021-09-27 20:35:17 mgieg-z3mzc Get(TEST.txt)
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 need file TEST.txt; copy 0, reused 1
2021-09-27 20:35:17 progress emitter: disabled, skip registering
2021-09-27 20:35:17 not weak hashing TEST.txt. file did not contain any weak hashes
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 closing TEST.txt
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 new error for TEST.txt: file does not exist
2021-09-27 20:35:17 progress emitter: disabled, skip deregistering
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 changed 1 on try 1
2021-09-27 20:35:17 mgieg-z3mzc Snapshot()
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 copiers: 2 pullerPendingKiB: 32768
2021-09-27 20:35:17 mgieg-z3mzc WithNeed(7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4)
2021-09-27 20:35:17 mgieg-z3mzc Get(TEST.txt)
2021-09-27 20:35:17 mgieg-z3mzc GetGlobal(TEST.txt)
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 parent not missing TEST.txt
2021-09-27 20:35:17 mgieg-z3mzc Availability(TEST.txt)
2021-09-27 20:35:17 mgieg-z3mzc Get(TEST.txt)
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 need file TEST.txt; copy 0, reused 1
2021-09-27 20:35:17 progress emitter: disabled, skip registering
2021-09-27 20:35:17 not weak hashing TEST.txt. file did not contain any weak hashes
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 closing TEST.txt
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 new error for TEST.txt: file does not exist
2021-09-27 20:35:17 progress emitter: disabled, skip deregistering
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 changed 1 on try 2
2021-09-27 20:35:17 mgieg-z3mzc Snapshot()
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 copiers: 2 pullerPendingKiB: 32768
2021-09-27 20:35:17 mgieg-z3mzc WithNeed(7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4)
2021-09-27 20:35:17 mgieg-z3mzc Get(TEST.txt)
2021-09-27 20:35:17 mgieg-z3mzc GetGlobal(TEST.txt)
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 parent not missing TEST.txt
2021-09-27 20:35:17 mgieg-z3mzc Availability(TEST.txt)
2021-09-27 20:35:17 mgieg-z3mzc Get(TEST.txt)
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 need file TEST.txt; copy 0, reused 1
2021-09-27 20:35:17 progress emitter: disabled, skip registering
2021-09-27 20:35:17 not weak hashing TEST.txt. file did not contain any weak hashes
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 closing TEST.txt
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 new error for TEST.txt: file does not exist
2021-09-27 20:35:17 progress emitter: disabled, skip deregistering
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 changed 1 on try 3
2021-09-27 20:35:17 Puller (folder "xxx" (mgieg-z3mzc), item "TEST.txt"): syncing: file does not exist
2021-09-27 20:35:17 "xxx" (mgieg-z3mzc): Failed to sync 1 items
2021-09-27 20:35:17 Folder "xxx" (mgieg-z3mzc) isn't making sync progress - retrying in 1m0s.
2021-09-27 20:35:17 mgieg-z3mzc Snapshot()
2021-09-27 20:35:17 progress emitter: bytes completed for mgieg-z3mzc: 0
2021-09-27 20:35:17 mgieg-z3mzc Snapshot()
2021-09-27 20:35:17 model@0x520830a0 Completion(D4DZUGP, "mgieg-z3mzc"): map[completion:95 globalBytes:40602799 globalItems:88 needBytes:0 needDeletes:1 needItems:0 sequence:1006]
2021-09-27 20:35:17 Index update (in): D4DZUGP / "mgieg-z3mzc": 1 files
2021-09-27 20:35:17 mgieg-z3mzc Update(D4DZUGP, [1])
2021-09-27 20:35:17 insert (remote); folder="mgieg-z3mzc" device=D4DZUGP File{Name:"test.txt", Sequence:1007, Permissions:0644, ModTime:2021-09-27 20:35:17.425344379 +0900 KST, Version:{[{D4DZUGP 1632742375} {6I7GNCY 1632742517}]}, VersionHash:, Length:0, Deleted:true, Invalid:false, LocalFlags:0x0, NoPermissions:true, BlockSize:131072, Blocks:[], BlocksHash:}
2021-09-27 20:35:17 update global; folder="mgieg-z3mzc" device=D4DZUGP file="test.txt" version={[{D4DZUGP 1632742375} {6I7GNCY 1632742517}]} invalid=false
2021-09-27 20:35:17 new global for "test.txt" after update: {{Version:{[{D4DZUGP 1632742375} {6I7GNCY 1632742517}]}, Deleted:true, Devices:{7777777, D4DZUGP}, Invalid:{}}}
2021-09-27 20:35:17 mgieg-z3mzc Snapshot()
2021-09-27 20:35:17 mgieg-z3mzc WithNeed(7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4)
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 pulling
2021-09-27 20:35:17 mgieg-z3mzc Snapshot()
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 copiers: 2 pullerPendingKiB: 32768
2021-09-27 20:35:17 mgieg-z3mzc WithNeed(7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4)
2021-09-27 20:35:17 mgieg-z3mzc Get(TEST.txt)
2021-09-27 20:35:17 mgieg-z3mzc GetGlobal(TEST.txt)
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 parent not missing TEST.txt
2021-09-27 20:35:17 mgieg-z3mzc Availability(TEST.txt)
2021-09-27 20:35:17 mgieg-z3mzc Get(TEST.txt)
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 need file TEST.txt; copy 0, reused 1
2021-09-27 20:35:17 progress emitter: disabled, skip registering
2021-09-27 20:35:17 not weak hashing TEST.txt. file did not contain any weak hashes
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 closing TEST.txt
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 new error for TEST.txt: file does not exist
2021-09-27 20:35:17 progress emitter: disabled, skip deregistering
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 changed 1 on try 1
2021-09-27 20:35:17 mgieg-z3mzc Snapshot()
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 copiers: 2 pullerPendingKiB: 32768
2021-09-27 20:35:17 mgieg-z3mzc WithNeed(7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4)
2021-09-27 20:35:17 mgieg-z3mzc Get(TEST.txt)
2021-09-27 20:35:17 mgieg-z3mzc GetGlobal(TEST.txt)
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 parent not missing TEST.txt
2021-09-27 20:35:17 mgieg-z3mzc Availability(TEST.txt)
2021-09-27 20:35:17 mgieg-z3mzc Get(TEST.txt)
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 need file TEST.txt; copy 0, reused 1
2021-09-27 20:35:17 progress emitter: disabled, skip registering
2021-09-27 20:35:17 not weak hashing TEST.txt. file did not contain any weak hashes
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 closing TEST.txt
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 new error for TEST.txt: file does not exist
2021-09-27 20:35:17 progress emitter: disabled, skip deregistering
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 changed 1 on try 2
2021-09-27 20:35:17 mgieg-z3mzc Snapshot()
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 copiers: 2 pullerPendingKiB: 32768
2021-09-27 20:35:17 mgieg-z3mzc WithNeed(7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4)
2021-09-27 20:35:17 mgieg-z3mzc Get(TEST.txt)
2021-09-27 20:35:17 mgieg-z3mzc GetGlobal(TEST.txt)
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 parent not missing TEST.txt
2021-09-27 20:35:17 mgieg-z3mzc Availability(TEST.txt)
2021-09-27 20:35:17 mgieg-z3mzc Get(TEST.txt)
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 need file TEST.txt; copy 0, reused 1
2021-09-27 20:35:17 progress emitter: disabled, skip registering
2021-09-27 20:35:17 not weak hashing TEST.txt. file did not contain any weak hashes
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 closing TEST.txt
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 new error for TEST.txt: file does not exist
2021-09-27 20:35:17 progress emitter: disabled, skip deregistering
2021-09-27 20:35:17 sendreceive/mgieg-z3mzc@0x523a65a0 changed 1 on try 3
2021-09-27 20:35:17 Puller (folder "xxx" (mgieg-z3mzc), item "TEST.txt"): syncing: file does not exist
2021-09-27 20:35:17 "xxx" (mgieg-z3mzc): Failed to sync 1 items
2021-09-27 20:35:17 Folder "xxx" (mgieg-z3mzc) isn't making sync progress - retrying in 1m0s.
2021-09-27 20:35:17 mgieg-z3mzc Snapshot()
2021-09-27 20:35:17 progress emitter: bytes completed for mgieg-z3mzc: 0
2021-09-27 20:35:17 mgieg-z3mzc Snapshot()
2021-09-27 20:35:17 model@0x520830a0 Completion(D4DZUGP, "mgieg-z3mzc"): map[completion:100 globalBytes:40602799 globalItems:88 needBytes:0 needDeletes:0 needItems:0 sequence:1007]
2021-09-27 20:36:24 mgieg-z3mzc Snapshot()
2021-09-27 20:36:24 mgieg-z3mzc WithNeed(7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4)
2021-09-27 20:36:24 sendreceive/mgieg-z3mzc@0x523a65a0 pulling
2021-09-27 20:36:24 mgieg-z3mzc Snapshot()
2021-09-27 20:36:24 sendreceive/mgieg-z3mzc@0x523a65a0 copiers: 2 pullerPendingKiB: 32768
2021-09-27 20:36:24 mgieg-z3mzc WithNeed(7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4)
2021-09-27 20:36:24 mgieg-z3mzc Get(TEST.txt)
2021-09-27 20:36:24 mgieg-z3mzc GetGlobal(TEST.txt)
2021-09-27 20:36:24 sendreceive/mgieg-z3mzc@0x523a65a0 parent not missing TEST.txt
2021-09-27 20:36:24 mgieg-z3mzc Availability(TEST.txt)
2021-09-27 20:36:24 mgieg-z3mzc Get(TEST.txt)
2021-09-27 20:36:24 sendreceive/mgieg-z3mzc@0x523a65a0 need file TEST.txt; copy 0, reused 1
2021-09-27 20:36:24 progress emitter: disabled, skip registering
2021-09-27 20:36:24 not weak hashing TEST.txt. file did not contain any weak hashes
2021-09-27 20:36:24 sendreceive/mgieg-z3mzc@0x523a65a0 closing TEST.txt
2021-09-27 20:36:24 progress emitter: disabled, skip deregistering
2021-09-27 20:36:24 mgieg-z3mzc Update(7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4, [1])
2021-09-27 20:36:24 removing sequence; folder="mgieg-z3mzc" sequence=519 TEST.txt
2021-09-27 20:36:24 insert (local); folder="mgieg-z3mzc" File{Name:"TEST.txt", Sequence:522, Permissions:0644, ModTime:2021-09-27 20:27:30.425344379 +0900 KST, Version:{[{D4DZUGP 1632742508} {6I7GNCY 1632742383}]}, VersionHash:, Length:1, Deleted:false, Invalid:false, LocalFlags:0x0, NoPermissions:true, BlockSize:131072, Blocks:[Block{0/1/720907/01ba4719c80b6fe911b091a7c05124b64eeece964e09c058ef8f9805daca546b}], BlocksHash:8882be321f134bfc1645b17f523da98cad094e4b17b6aad35776c36f35663ee1}
2021-09-27 20:36:24 update global; folder="mgieg-z3mzc" device=7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4 file="TEST.txt" version={[{D4DZUGP 1632742508} {6I7GNCY 1632742383}]} invalid=false
2021-09-27 20:36:24 new global for "TEST.txt" after update: {{Version:{[{D4DZUGP 1632742508} {6I7GNCY 1632742383}]}, Deleted:false, Devices:{D4DZUGP, 7777777}, Invalid:{}}}
2021-09-27 20:36:24 local need delete; folder="mgieg-z3mzc", name="TEST.txt"
2021-09-27 20:36:24 adding sequence; folder="mgieg-z3mzc" sequence=522 TEST.txt
2021-09-27 20:36:24 sendreceive/mgieg-z3mzc@0x523a65a0 changed 1 on try 1
2021-09-27 20:36:24 mgieg-z3mzc Snapshot()
2021-09-27 20:36:24 mgieg-z3mzc Snapshot()
2021-09-27 20:36:24 mgieg-z3mzc WithHaveSequence(522)
2021-09-27 20:36:24 sendreceive/mgieg-z3mzc@0x523a65a0 copiers: 2 pullerPendingKiB: 32768
2021-09-27 20:36:24 mgieg-z3mzc WithNeed(7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4)
2021-09-27 20:36:24 indexHandler@0x5256e3c0 for mgieg-z3mzc to D4DZUGP at [fe80::5e3c:27ff:fe37:988d%wlan0]:22000-[fe80::9868:3753:49ff:a06%wlan0]:22000/tcp-server/TLS1.3-TLS_CHACHA20_POLY1305_SHA256: Sending 1 files (<163 bytes)
2021-09-27 20:36:24 sendreceive/mgieg-z3mzc@0x523a65a0 changed 0 on try 2
2021-09-27 20:36:24 mgieg-z3mzc Snapshot()
2021-09-27 20:36:24 progress emitter: bytes completed for mgieg-z3mzc: 0
2021-09-27 20:36:24 mgieg-z3mzc Snapshot()
2021-09-27 20:36:24 model@0x520830a0 Completion(D4DZUGP, "mgieg-z3mzc"): map[completion:100 globalBytes:40602799 globalItems:88 needBytes:0 needDeletes:0 needItems:0 sequence:1007]
es20490446e commented 2 years ago

I can reproduce it on Linux<->Android.

tomasz1986 commented 2 years ago

I can reproduce it on Linux<->Android.

If you can, it would be helpful if you could enable db and model debug logging on both sides, then proceed with the reproduction, then upload the logs here. You can enable the two in the Web GUI (which on Android can be accessed from the left slide-out menu).

On my side, as mentioned above, with Android and Windows, there is some funkiness, but none of the files end up being deleted.

es20490446e commented 2 years ago
imsodin commented 2 years ago

This is terrifying. Relevant bits from the mobile:

2021-11-08 16:18:51 sendreceive/mo9mp-yxlxk@0x4000b16a80 taking rename shortcut Projects/syncthing/Test.txt -> Projects/syncthing/test.txt
2021-11-08 16:18:51 insert (local); folder="mo9mp-yxlxk" File{Name:"Projects/syncthing/test.txt", Sequence:10166824, Permissions:0644, ModTime:2021-11-08 16:18:21.505086179 +0000 UTC, Version:{[{2PZEQBA 1636388331}]}, VersionHash:, Length:0, Deleted:false, Invalid:false, LocalFlags:0x0, NoPermissions:false, BlockSize:131072, Blocks:[Block{0/0/0/e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855}], BlocksHash:d3bfe98e8f1ce891614854569a20f5f4508d6ab4025b872b7b3a8282ef75b12a}
2021-11-08 16:18:51 insert (local); folder="mo9mp-yxlxk" File{Name:"Projects/syncthing/Test.txt", Sequence:10166825, Permissions:0644, ModTime:2021-11-08 16:18:51.505086179 +0000 UTC, Version:{[{2PZEQBA 1636388331}]}, VersionHash:, Length:0, Deleted:true, Invalid:false, LocalFlags:0x0, NoPermissions:false, BlockSize:131072, Blocks:[], BlocksHash:}
2021-11-08 16:18:51 insert (local); folder="mo9mp-yxlxk" File{Name:"Projects/syncthing/Test.txt", Sequence:10166825, Permissions:0644, ModTime:2021-11-08 16:18:51.505086179 +0000 UTC, Version:{[{2PZEQBA 1636388331}]}, VersionHash:, Length:0, Deleted:true, Invalid:false, LocalFlags:0x0, NoPermissions:false, BlockSize:131072, Blocks:[], BlocksHash:}
2021-11-08 16:19:06 marking file as deleted File{Name:"Projects/syncthing/test.txt", Sequence:10166824, Permissions:0644, ModTime:2021-11-08 16:19:06.505086179 +0000 UTC, Version:{[{QR54VZV 1636388346} {2PZEQBA 1636388331}]}, VersionHash:, Length:0, Deleted:true, Invalid:false, LocalFlags:0x0, NoPermissions:false, BlockSize:131072, Blocks:[], BlocksHash:}
2021-11-08 16:19:06 insert (local); folder="mo9mp-yxlxk" File{Name:"Projects/syncthing/test.txt", Sequence:10166826, Permissions:0644, ModTime:2021-11-08 16:19:06.505086179 +0000 UTC, Version:{[{QR54VZV 1636388346} {2PZEQBA 1636388331}]}, VersionHash:, Length:0, Deleted:true, Invalid:false, LocalFlags:0x0, NoPermissions:false, BlockSize:131072, Blocks:[], BlocksHash:}

Basically this means it successfully renamed from Test.txt to test.txt at around 16:18:51, and then at 2021-11-08 16:19:06, i.e. a lot later, android is saying test.txt isn't there anymore.
Could you please also enable fs debug logging on the mobile and repro again, to confirm what exactly is happening at the filesystem layer.

And what android version and what brand are you using?

jeromecst commented 2 years ago

If it can help, I began to see issues since I upgraded my phone to Android 11. I'm running Lineage OS 18.1

es20490446e commented 2 years ago

mobile-filesystem-log.txt

es20490446e commented 2 years ago
calmh commented 2 years ago

This is not limited to case-only renames.

https://forum.syncthing.net/t/renaming-caused-file-deletion-bug/17591/2

imsodin commented 2 years ago

This hasn't been fixed, GH just tried to be smart in #8257 but failed.

imsodin commented 2 years ago

Well github might have closed it for the wrong reasons, but nicely it was right: I just tried to repro with https://github.com/syncthing/syncthing/pull/8257 and am unable to. That's suprising to me, as what's fixed there isn't Android specific. As in I'd expect the problem in this issue should also affect e.g. windows (case insensitive too). Probably some combination of case-insensitivity and caching/other android weirdness that caused it. Anyways:

TL;DR: It's fixed :)

es20490446e commented 2 years ago

Thanks again 👌

imsodin commented 2 years ago

Discovered in https://github.com/syncthing/syncthing/issues/8338 that it hasn't actually been fixed.

vcotu commented 2 years ago

I will post here instead of #8338

In linux I am using 'syncthing-bin' AUR archlinux package since regular syncthing manjaro arch package has older version v1.19.1 I have deleted all the old configuration files in both linux and android. I changed config to be as default as possible too.

Issue is still present, and it keeps deleting the file... (only if filename case is changed in the pc)

logs using STTRACE=db,model,fs,walkfs

desktop computer: OS: GNU/Linux 5.10.109-1-MANJARO x86_64 syncthing-bin: syncthing v1.20.1 "Fermium Flea" (go1.18.1 linux-amd64) teamcity@build.syncthing.net

phone (Samsung): OS: Android 11 syncthing android version: v1.20.1

pc-log.txt android-log.txt

es20490446e commented 2 years ago

My wedding photos are gone...

Just joking.

jeromecst commented 2 years ago

You are joking but when I first openned this issue, I actually lost some of my notes. Not big deal ofc but still some data lost.

es20490446e commented 2 years ago

Still better than Ubuntu One. Back in the days it would delete any files unexpectedly. My work at University gone.

It was a trap 🎁

imsodin commented 2 years ago

This causes data loss, so no matter what kind of badness also exists (obviously), this is bad because we don't want this badness in Syncthing. And this also once again proves: Have backups. No need for chatter around it please ;)

There's nothing in Syncthing's code that's doing anything here - the deletion comes from the outside. I kept all relevant filesystem interactions and some other lines from the above log:

2022-05-11 17:38:13 sendreceive/nk3k2-0lylt@0x40001a4a80 taking rename shortcut Health.txt -> health.txt
2022-05-11 17:38:13 folder_sendrecv.go:2060 basic /storage/emulated/0/srv/keep/test Lstat Health.txt {0x4000152600} <nil>
2022-05-11 17:38:13 folder_sendrecv.go:964 basic /storage/emulated/0/srv/keep/test Lstat health.txt <nil> remote "health.txt" uses different upper or lowercase characters than local "Health.txt"; change the casing on either side to match the other
2022-05-11 17:38:13 osutil.go:33 basic /storage/emulated/0/srv/keep/test Rename Health.txt .syncthing.health.txt.tmp <nil>
2022-05-11 17:38:13 basic /storage/emulated/0/srv/keep/test Watch: Sending Health.txt remove
2022-05-11 17:38:13 folder_sendrecv.go:1600 basic /storage/emulated/0/srv/keep/test Lstat health.txt <nil> lstat /storage/emulated/0/srv/keep/test/health.txt: no such file or directory
2022-05-11 17:38:13 osutil.go:33 basic /storage/emulated/0/srv/keep/test Rename .syncthing.health.txt.tmp health.txt <nil>
2022-05-11 17:38:13 basic /storage/emulated/0/srv/keep/test Watch: Sending health.txt non-remove
2022-05-11 17:38:13 folder_sendrecv.go:1634 basic /storage/emulated/0/srv/keep/test Chtimes health.txt 2022-05-11 09:15:22.248196 +0200 CEST 2022-05-11 09:15:22.248196 +0200 CEST <nil>
2022-05-11 17:38:28 basic /storage/emulated/0/srv/keep/test Watch: Sending health.txt remove
2022-05-11 17:38:38 sendreceive/nk3k2-0lylt@0x40001a4a80 Scan due to watcher
2022-05-11 17:38:38 sendreceive/nk3k2-0lylt@0x40001a4a80 scanning
2022-05-11 17:38:38 walkfs.go:142 basic /storage/emulated/0/srv/keep/test Lstat health.txt <nil> lstat /storage/emulated/0/srv/keep/test/health.txt: no such file or directory
2022-05-11 17:38:38 osutil.go:134 basic /storage/emulated/0/srv/keep/test Lstat health.txt <nil> lstat /storage/emulated/0/srv/keep/test/health.txt: no such file or directory
2022-05-11 17:38:38 marking file as deleted File{Name:"health.txt", Sequence:8, Permissions:0644, ModTime:2022-05-11 17:38:38.248196 +0200 CEST, Version:{[{FIMA7VE 1652283518} {X2LD4VE 1652283495}]}, VersionHash:, Length:0, Deleted:true, Invalid:false, LocalFlags:0x0, NoPermissions:false, BlockSize:131072, Blocks:[], BlocksHash:}

Basically all the filesystem calls work just fine, we can even change the mod time without an error on the new file, but 15s later the filesystem watcher notices that the file is removed, and a subsequent Lstat confirms that the file that was there 15s ago is now gone.

I really have no idea what this might be. It's not even that we are doing a case-only rename (one could imagine that could cause badness in android - would be terrible but it's android): The rename happens via a temporary filename.

calmh commented 2 years ago

Yeah that matches previous troubleshooting, and note too that it's not limited to case only renames, also for example renaming underscore to dash (test_a to test-a).

However also note

If I shut down Syncthing after rename but before the disappearance (which happens about 15s after the rename), then the file is not disappeared. So it certainly looks like it’s Syncthing who’s the culprit.

and my next step was going to be to trace all syscalls by Syncthing and/or other processes, to really see where the delete comes from, but I couldn't figure out how to do that on my Android device and gave up.

There was also a later comment,

What I’m noticing is that if I rename or move a file, the resulting file ends up trashed on Android specifically. I believe that this is the case because the file will still exist on Android with a .trashed- prefix to the name.

maybe there's some Android file system layer that wants to act as a trashcan that interferes here somehow.

imsodin commented 2 years ago

Yeah, filesystem interactions do go through a (transparent) filesystem layer at least since targeting the new android API level, probably also before on certain android versions. I'll also try to see what's happening with strace or whatever android utility if that's not available.

vcotu commented 2 years ago

logcat in android shows this when the file is removed:

05-12 14:52:45.967  9031  9031 I EventProcessor: Deleted file from MediaStore: /storage/emulated/0/srv/test/Health.txt
05-12 14:52:46.024  9031 23713 I SyncthingNativeCode: [FIMA7] DEBUG: basic /storage/emulated/0/srv/test Watch: Sending health.txt remove
05-12 14:52:46.061  9031  9031 I EventProcessor: Rescanned file via MediaScanner: /storage/emulated/0/srv/test/health.txt
05-12 14:52:46.071  3438 23633 W ModernMediaScanner: Failed to visit /storage/emulated/0/srv/test/health.txt: java.nio.file.NoSuchFileException: /storage/emulated/0/srv/test/health.txt
05-12 14:52:46.103  9031 24276 D MediaScannerConnection: Scanned /storage/emulated/0/srv/test/health.txt to null
05-12 14:52:56.026  9031 23713 I SyncthingNativeCode: [FIMA7] DEBUG: folderconfiguration.go:115 basic /storage/emulated/0/srv/test Stat . {0x4000362600} <nil>
05-12 14:52:56.028  9031 23713 I SyncthingNativeCode: [FIMA7] DEBUG: folderconfiguration.go:133 basic /storage/emulated/0/srv/test Stat .stfolder {0x40003626c0} <nil>
05-12 14:52:56.029  9031 23713 I SyncthingNativeCode: [FIMA7] DEBUG: ignore.go:385 basic /storage/emulated/0/srv/test Open .stignore <nil> open /storage/emulated/0/srv/test/.stignore: no such file or directory
05-12 14:52:56.030  9031 23713 I SyncthingNativeCode: [FIMA7] DEBUG: walkfs.go:142 basic /storage/emulated/0/srv/test Lstat health.txt <nil> lstat /storage/emulated/0/srv/test/health.txt: no such file or directory
05-12 14:52:56.032  9031 23713 I SyncthingNativeCode: [FIMA7] DEBUG: osutil.go:134 basic /storage/emulated/0/srv/test Lstat health.txt <nil> lstat /storage/emulated/0/srv/test/health.txt: no such file or directory
05-12 14:52:56.033  9031 23713 I SyncthingNativeCode: [FIMA7] DEBUG: folderconfiguration.go:115 basic /storage/emulated/0/srv/test Stat . {0x4000438180} <nil>
05-12 14:52:56.033  9031 23713 I SyncthingNativeCode: [FIMA7] DEBUG: folderconfiguration.go:133 basic /storage/emulated/0/srv/test Stat .stfolder {0x4000438240} <nil>

syncthing does nothing until android EventProcessor shows "Deleted file from MediaStore: /storage/emulated/0/srv/test/Health.txt", and then syncthing decides to remove health.txt

imsodin commented 2 years ago

Do you have more lines from before? Nothing there says Syncthing is deleting it, it just sees that it is deleted (the watch doesn't do anything, it notifies about what happens on disk). This one is curious:

05-12 14:52:46.071  3438 23633 W ModernMediaScanner: Failed to visit /storage/emulated/0/srv/test/health.txt: java.nio.file.NoSuchFileException: /storage/emulated/0/srv/test/health.txt

It says the same as syncthing logs, but from an android process: The health.txt file is not there, while the filesystem said it was successfully created just before that. Anyway, maybe those traces will have more helpful info.

vcotu commented 2 years ago

Do you have more lines from before?

This is when the file is removed (not before):

05-12 14:52:45.942  9031  9031 V ApiRequest: Performing request to https://127.0.0.1:8384/rest/events?since=0&limit=1
05-12 14:52:45.943  9031 23704 I System.out: (HTTPLog)-Static: isSBSettingEnabled false
05-12 14:52:45.950  9031  9031 D EventProcessor: Reading events starting with id 256
05-12 14:52:45.950  9031  9031 V ApiRequest: Performing request to https://127.0.0.1:8384/rest/events?since=256&limit=0
05-12 14:52:45.952  9031 23706 I System.out: (HTTPLog)-Static: isSBSettingEnabled false
05-12 14:52:45.967  9031  9031 I EventProcessor: Deleted file from MediaStore: /storage/emulated/0/srv/test/Health.txt
05-12 14:52:46.024  9031 23713 I SyncthingNativeCode: [FIMA7] DEBUG: basic /storage/emulated/0/srv/test Watch: Sending health.txt remove
05-12 14:52:46.058  3438 23633 I MediaProvider: Deleted 0 0 0 0 0 0 1 items on external due to com.nutomic.syncthingandroid
05-12 14:52:46.061  9031  9031 I EventProcessor: Rescanned file via MediaScanner: /storage/emulated/0/srv/test/health.txt
05-12 14:52:46.071  3438 23633 W ModernMediaScanner: Failed to visit /storage/emulated/0/srv/test/health.txt: java.nio.file.NoSuchFileException: /storage/emulated/0/srv/test/health.txt
05-12 14:52:46.099  3438 23633 I MediaProvider: Scanned external_primary due to REASON_DEMAND, found 0 items in 30ms, 0 inserts 0 updates 0 deletes
05-12 14:52:46.103  9031 24276 D MediaScannerConnection: Scanned /storage/emulated/0/srv/test/health.txt to null

Playing around I found something else...

Health.txt created in android:

Health.txt created in pc:

Health.txt created in android or pc, rename in android, file not removed. (LOG-4)

Logs created using logcat inside android adb shell:

LOG: created in android, NO rename

05-12 17:23:01.157  3438 27337 D MediaProvider: CrossUser not enabled.
05-12 17:23:01.193  9031 23713 I SyncthingNativeCode: [FIMA7] DEBUG: basic /storage/emulated/0/srv/test Watch: Sending Health.txt non-remove

LOG-1: created in android, rename in pc 1 time, file not removed

05-12 17:24:46.320  9031 23713 I SyncthingNativeCode: [FIMA7] DEBUG: basic /storage/emulated/0/srv/test Watch: Ignoring .syncthing.health.txt.tmp
05-12 17:24:46.320  9031 23713 I SyncthingNativeCode: [FIMA7] DEBUG: basic /storage/emulated/0/srv/test Watch: Sending Health.txt remove
05-12 17:24:46.325  9031 23713 I SyncthingNativeCode: [FIMA7] DEBUG: basic /storage/emulated/0/srv/test Watch: Sending health.txt non-remove
05-12 17:24:46.326  9031 23713 I SyncthingNativeCode: [FIMA7] DEBUG: basic /storage/emulated/0/srv/test Watch: Ignoring .syncthing.health.txt.tmp
05-12 17:24:46.329  9031 23713 I SyncthingNativeCode: [FIMA7] DEBUG: basic /storage/emulated/0/srv/test Watch: Sending health.txt non-remove
....
05-12 17:25:01.341  9031  9031 I EventProcessor: Deleted file from MediaStore: /storage/emulated/0/srv/test/Health.txt
05-12 17:25:01.444  3438 23633 I MediaProvider: Deleted 0 0 0 0 0 0 0 items on external due to com.nutomic.syncthingandroid
05-12 17:25:01.448  9031  9031 I EventProcessor: Rescanned file via MediaScanner: /storage/emulated/0/srv/test/health.txt
05-12 17:25:01.476  9031 24276 D MediaScannerConnection: Scanned /storage/emulated/0/srv/test/health.txt to content://media/external_primary/file/9923

LOG-2: created in android, renamed in pc a second time (health.txt -> Health.txt), file removed

05-12 17:27:28.459  9031 23713 I SyncthingNativeCode: [FIMA7] DEBUG: basic /storage/emulated/0/srv/test Watch: Ignoring .syncthing.Health.txt.tmp
05-12 17:27:28.460  9031 23713 I SyncthingNativeCode: [FIMA7] DEBUG: basic /storage/emulated/0/srv/test Watch: Sending health.txt remove
05-12 17:27:28.464  9031 23713 I SyncthingNativeCode: [FIMA7] DEBUG: basic /storage/emulated/0/srv/test Watch: Sending Health.txt non-remove
05-12 17:27:28.465  9031 23713 I SyncthingNativeCode: [FIMA7] DEBUG: basic /storage/emulated/0/srv/test Watch: Ignoring .syncthing.Health.txt.tmp
05-12 17:27:28.467  9031 23713 I SyncthingNativeCode: [FIMA7] DEBUG: basic /storage/emulated/0/srv/test Watch: Sending Health.txt non-remove
.....
05-12 17:27:43.477  9031  9031 I EventProcessor: Deleted file from MediaStore: /storage/emulated/0/srv/test/health.txt
05-12 17:27:43.539  9031 23713 I SyncthingNativeCode: [FIMA7] DEBUG: basic /storage/emulated/0/srv/test Watch: Sending Health.txt remove
05-12 17:27:43.572  3438 23633 I MediaProvider: Deleted 0 0 0 0 0 0 1 items on external due to com.nutomic.syncthingandroid
05-12 17:27:43.575  9031  9031 I EventProcessor: Rescanned file via MediaScanner: /storage/emulated/0/srv/test/Health.txt
05-12 17:27:43.584  3438 23633 W ModernMediaScanner: Failed to visit /storage/emulated/0/srv/test/Health.txt: java.nio.file.NoSuchFileException: /storage/emulated/0/srv/test/Health.txt
05-12 17:27:43.605  3438 23633 I MediaProvider: Scanned external_primary due to REASON_DEMAND, found 0 items in 23ms, 0 inserts 0 updates 0 deletes
05-12 17:27:43.606  9031 24276 D MediaScannerConnection: Scanned /storage/emulated/0/srv/test/Health.txt to null

LOG: created in pc, NO rename

05-12 17:04:49.419  9031 23713 I SyncthingNativeCode: [FIMA7] DEBUG: basic /storage/emulated/0/srv/test Watch: Ignoring .syncthing.Health.txt.tmp
05-12 17:04:49.469  9031 23713 I SyncthingNativeCode: [FIMA7] DEBUG: basic /storage/emulated/0/srv/test Watch: Sending Health.txt non-remove
05-12 17:04:49.469  9031 23713 I SyncthingNativeCode: [FIMA7] DEBUG: basic /storage/emulated/0/srv/test Watch: Ignoring .syncthing.Health.txt.tmp
05-12 17:04:49.474  9031 23713 I SyncthingNativeCode: [FIMA7] DEBUG: basic /storage/emulated/0/srv/test Watch: Sending Health.txt non-remove
....
05-12 17:05:01.156  9031  9031 I EventProcessor: Rescanned file via MediaScanner: /storage/emulated/0/srv/test/Health.txt
05-12 17:05:01.182  3438 23633 D MediaProvider: CrossUser not enabled.
05-12 17:05:01.197  9031 24276 D MediaScannerConnection: Scanned /storage/emulated/0/srv/test/Health.txt to content://media/external_primary/file/9921

LOG-3: created in pc, rename in pc, file removed

05-12 17:10:30.846  9031 23713 I SyncthingNativeCode: [FIMA7] DEBUG: basic /storage/emulated/0/srv/test Watch: Ignoring .syncthing.health.txt.tmp
05-12 17:10:30.846  9031 23713 I SyncthingNativeCode: [FIMA7] DEBUG: basic /storage/emulated/0/srv/test Watch: Sending Health.txt remove
05-12 17:10:30.849  9031 23713 I SyncthingNativeCode: [FIMA7] DEBUG: basic /storage/emulated/0/srv/test Watch: Sending health.txt non-remove
05-12 17:10:30.850  9031 23713 I SyncthingNativeCode: [FIMA7] DEBUG: basic /storage/emulated/0/srv/test Watch: Ignoring .syncthing.health.txt.tmp
05-12 17:10:30.853  9031 23713 I SyncthingNativeCode: [FIMA7] DEBUG: basic /storage/emulated/0/srv/test Watch: Sending health.txt non-remove
.....
05-12 17:10:45.602  9031  9031 I EventProcessor: Rescanned file via MediaScanner: /storage/emulated/0/srv/test/health.txt
05-12 17:10:45.605  9031  9031 I EventProcessor: Deleted file from MediaStore: /storage/emulated/0/srv/test/Health.txt
05-12 17:10:45.616  9031 24276 D MediaScannerConnection: Scanned /storage/emulated/0/srv/test/health.txt to content://media/external_primary/file/9921
05-12 17:10:45.625  9031 23713 I SyncthingNativeCode: [FIMA7] DEBUG: basic /storage/emulated/0/srv/test Watch: Sending health.txt remove
05-12 17:10:45.630  9031 24276 D MediaScannerConnection: Scanned /storage/emulated/0/srv/test/health.txt to content://media/external_primary/file/9921
05-12 17:10:45.642  3438 23633 W ModernMediaScanner: Failed to visit /storage/emulated/0/srv/test/health.txt: java.nio.file.NoSuchFileException: /storage/emulated/0/srv/test/health.txt
05-12 17:10:45.644  3438  3507 I MediaProvider: Deleted 0 0 0 0 0 0 1 items on external due to com.nutomic.syncthingandroid
05-12 17:10:45.648  9031  9031 I EventProcessor: Rescanned file via MediaScanner: /storage/emulated/0/srv/test/health.txt
05-12 17:10:45.673  3438 23633 I MediaProvider: Scanned external_primary due to REASON_DEMAND, found 0 items in 35ms, 0 inserts 0 updates 0 deletes
05-12 17:10:45.675  9031 24276 D MediaScannerConnection: Scanned /storage/emulated/0/srv/test/health.txt to null
05-12 17:10:45.681  3438 23633 W ModernMediaScanner: Failed to visit /storage/emulated/0/srv/test/health.txt: java.nio.file.NoSuchFileException: /storage/emulated/0/srv/test/health.txt
05-12 17:10:45.704  3438 23633 I MediaProvider: Scanned external_primary due to REASON_DEMAND, found 0 items in 24ms, 0 inserts 0 updates 0 deletes
05-12 17:10:45.705  9031 24276 D MediaScannerConnection: Scanned /storage/emulated/0/srv/test/health.txt to null

LOG-4: created in pc, rename in android, file not removed

05-12 17:06:11.791  9031 23713 I SyncthingNativeCode: [FIMA7] DEBUG: basic /storage/emulated/0/srv/test Watch: Sending Health.txt.65CB non-remove
05-12 17:06:11.791  9031 23713 I SyncthingNativeCode: [FIMA7] DEBUG: basic /storage/emulated/0/srv/test Watch: Sending Health.txt remove
05-12 17:06:11.792  9031 23713 I SyncthingNativeCode: [FIMA7] DEBUG: basic /storage/emulated/0/srv/test Watch: Sending health.txt non-remove
05-12 17:06:11.793  9031 23713 I SyncthingNativeCode: [FIMA7] DEBUG: basic /storage/emulated/0/srv/test Watch: Sending Health.txt.65CB remove
05-12 17:06:11.830 14792 23632 D MediaScannerConnection: Scanned /storage/emulated/0/srv/test/health.txt to content://media/external_primary/file/9921
imsodin commented 2 years ago

@gwillen found the culprit (lets hope it's "the", not "a"): https://github.com/syncthing/syncthing-android/issues/1801
PR ready, with test apk: https://github.com/syncthing/syncthing-android/issues/1801

imsodin commented 2 years ago

The RC with the mentioned fix is released: https://github.com/syncthing/syncthing-android/releases/tag/1.20.4-rc.1

Everyone that experienced this issue is very welcome to test if they can still reproduce with that release - please report back if you do (also if everything is working fine). Thanks in advance!

vcotu commented 2 years ago

I tried 1.20.4-rc.1, seems fixed (until android devs change something and break it again...)

Tested:

AudriusButkevicius commented 2 years ago

I think this is now fixed.