"./vfs.test -test.v -test.timeout 1h0m0s -remote TestSharefile: -verbose -test.run '^TestFileRename$/^(minimal,forceCache=true|writes,forceCache=true)$'" - Starting (try 4/5) === RUN TestFileRename === RUN TestFileRename/minimal,forceCache=true 2020/07/24 09:48:39 INFO : sharefile root 'rclone-test-tunepil3yodifus0juyolaf3': poll-interval is not supported by this remote 2020/07/24 09:48:39 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestSharefile/rclone-test-tunepil3yodifus0juyolaf3" 2020/07/24 09:48:39 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestSharefile/rclone-test-tunepil3yodifus0juyolaf3" 2020/07/24 09:48:39 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2020/07/24 09:48:42 DEBUG : dir/file1: Open: flags=O_RDWR|O_CREATE|O_TRUNC 2020/07/24 09:48:42 DEBUG : dir/file1: newRWFileHandle: 2020/07/24 09:48:42 DEBUG : dir/file1(0xc000114a00): openPending: 2020/07/24 09:48:42 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06.5 +0000 UTC,0ef726ce9b1a7692357ff70dd321d595" against cached fingerprint "" 2020/07/24 09:48:42 DEBUG : dir/file1: vfs cache: truncate to size=14 2020/07/24 09:48:42 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 09:48:42 DEBUG : dir/file1(0xc000114a00): >openPending: err= 2020/07/24 09:48:42 DEBUG : dir/file1: vfs cache: truncate to size=0 2020/07/24 09:48:42 DEBUG : dir/file1: >newRWFileHandle: err= 2020/07/24 09:48:42 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 09:48:42 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/07/24 09:48:42 DEBUG : dir/file1(0xc000114a00): _writeAt: size=14, off=0 2020/07/24 09:48:42 DEBUG : dir/file1(0xc000114a00): >_writeAt: n=14, err= 2020/07/24 09:48:42 DEBUG : dir/file1(0xc000114a00): close: 2020/07/24 09:48:42 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true 2020/07/24 09:48:42 DEBUG : dir/file1: vfs cache: setting modification time to 2020-07-24 09:48:42.755748675 +0000 UTC m=+4.043070642 2020/07/24 09:48:42 INFO : dir/file1: vfs cache: queuing for upload in 100ms 2020/07/24 09:48:42 DEBUG : dir/file1(0xc000114a00): >close: err= 2020/07/24 09:48:42 DEBUG : dir/file1: Open: flags=O_RDONLY 2020/07/24 09:48:42 DEBUG : dir/file1: newRWFileHandle: 2020/07/24 09:48:42 DEBUG : dir/file1: >newRWFileHandle: err= 2020/07/24 09:48:42 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/07/24 09:48:42 DEBUG : dir/file1(0xc000114d40): _readAt: size=512, off=0 2020/07/24 09:48:42 DEBUG : dir/file1(0xc000114d40): openPending: 2020/07/24 09:48:42 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06.5 +0000 UTC,0ef726ce9b1a7692357ff70dd321d595" against cached fingerprint "14,2001-02-03 04:05:06.5 +0000 UTC,0ef726ce9b1a7692357ff70dd321d595" 2020/07/24 09:48:42 DEBUG : dir/file1: vfs cache: truncate to size=14 2020/07/24 09:48:42 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 09:48:42 DEBUG : dir/file1(0xc000114d40): >openPending: err= 2020/07/24 09:48:42 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true 2020/07/24 09:48:42 DEBUG : dir/file1(0xc000114d40): >_readAt: n=14, err=EOF 2020/07/24 09:48:42 DEBUG : dir/file1(0xc000114d40): close: 2020/07/24 09:48:42 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true 2020/07/24 09:48:42 DEBUG : dir/file1: vfs cache: setting modification time to 2020-07-24 09:48:42.755748675 +0000 UTC m=+4.043070642 2020/07/24 09:48:42 INFO : dir/file1: vfs cache: queuing for upload in 100ms 2020/07/24 09:48:42 DEBUG : dir/file1(0xc000114d40): >close: err= 2020/07/24 09:48:42 DEBUG : dir/file1: vfs cache: starting upload 2020/07/24 09:48:43 INFO : dir/file1: Moved (server side) 2020/07/24 09:48:43 DEBUG : dir/file1: vfs cache: cancelling upload 2020/07/24 09:48:43 ERROR : dir/file1: Failed to copy: upload file: Post https://storage-eu-209.sharefile.com/upload.aspx?uploadid=a33cd427-1aa7-456b-a6e1-452200efe881&cid=s_utRtyVfkaNBI7tbnGaBw&tool=rclone%2fv1.52.2-DEV&batchid=dd864f25-2c91-4d80-b194-5fff0c852f80&overwrite=true&raw=1&encparams=V79FwHGgRm4a3_fQ-e2vkNqMLGqvNPdR_ii4JEtW-6kQ7_H89yFMVlHWGMMsf9wrEf9bd6rGulkD5jHS8vta2P4-sZaNHkIwGhiTBoh6I3Y2DSNEA1wZwKT4pesaE3FXV8LPhxMMSyxJtR2uixkkJKO1mpxT5sH17cUSSa4felZ6f3q5-p_2gJdm-lri1FKp7eOIeQHPSC2hlm9iOMpaRHG_2dyoZTi9wwqVzmVuxUySyW8DuyaOJWU89qYBHeDlqhGZRnQABx8rs4XTpgcp5LQAuGlU999zGXc-RbYOYfv1yt-oeCb9j3dKJQXd4Gi4KRW49ejRFWp1AKqyzbFFPHfgoAO62sx1xdPt_RPPKPdq-jJ1t0ml2mSe19ydtXWgMmEp21J_8PjK4DFqK6OkS_BYgMeZsoX0yDgCdIg9s8C8wPCG1WHEGhPpF4Qbl1xw2cX0C4j8_zl8dTKQ_gdsbohlWVCyFGvfqw4_1cR8tOC9n-iI7rB_X8Bd1tKof6CXPm8sjzMWvrBIA24r9k4prMTPWTwh6jZeq58jm5nWWlFDAZFzg6lE6B00kLpcjAGtnHKRKZJM2YY-3L27acebZnXOMMdnH8lJy0wXY_bxNfhHDw8dxL100CDqzAa6T8QDdgUG2oydL3Qe-EQ8OtsK5pIlFigPMZH0R8IYYM8RH36oLsS5NayWfkET-av-7TmiUOFrDVOJ0FEOzny5XEY2uYS1xMrujT-mWn4cTfEi8H1UZzYwuer0oT7GdT4rLB6mHY8kQHXYljiJ4xzAO9yWFI7IdBsBdYstPheCCrZIoK5zuBAycYLDVsoaXGiE&zoneid=zpc3159d90-01f7-41a7-a8ab-3704157466&zsid=FB&h=4zaZeofnIfxHjMO2ApWlC2A6Z3NhVYFfTx4kHVlQp%2Fg%3D&fmt=json: context canceled 2020/07/24 09:48:43 INFO : dir/file1: vfs cache: upload canceled 2020/07/24 09:48:43 DEBUG : dir/file1: vfs cache: cancelled upload 2020/07/24 09:48:43 INFO : dir/file1: vfs cache: renamed in cache to "newLeaf" 2020/07/24 09:48:43 DEBUG : newLeaf: Updating file with newLeaf 0xc00062a0c0 2020/07/24 09:48:43 DEBUG : dir: Added virtual directory entry vDel: "file1" 2020/07/24 09:48:43 DEBUG : : Added virtual directory entry vAdd: "newLeaf" 2020/07/24 09:48:43 DEBUG : newLeaf: vfs cache: starting upload 2020/07/24 09:48:45 INFO : newLeaf: Moved (server side) 2020/07/24 09:48:45 DEBUG : newLeaf: vfs cache: cancelling upload 2020/07/24 09:48:45 ERROR : newLeaf: Failed to copy: upload file: Post https://storage-eu-204.sharefile.com/upload.aspx?uploadid=3dd64102-1e7a-4101-9cbb-82b5a908e261&cid=HA32_YWiHEaRIOKDPA34fg&tool=rclone%2fv1.52.2-DEV&batchid=ac5ff80f-5c6a-4551-ba3c-dc128143e3bd&overwrite=true&raw=1&encparams=INrYwKUIDn9_LeQlDQ5VVfRiu3LeHdquJf8RxkgQaqpLL3G7yvBnfuB02BkoqrEAQ9UDqcXY5dBADg8XQjsUN9uZSvCY99-11wuMIuw93g-k_KYpiTzOiOOMw4KfOfBQRCdU9-3gUFkd0snVXA7CG1-srLFtVwqpycR2oTfptPiBJYSdeG4iuuR1R-1lM_Yow9M3ma5icc5Os6DeLb4gcWlIZB7ou2fuQxts1nXkJHK-S17kqbCX6g2CEnGYbyS8WjxQSMC8YzPtH0Ha8rSYitzKPJ4BwMNmNrOS73wseSrRJQvM1Q2NjxO69XUPv0j-6uV1fXa8BJmEnshkor90CoKdcV_F0DdGB70_HWoIvusIaer81SsZV2EJwsQcqMbJmgg4yP9xsyt4exNRAx6ZHzYIuaVjuXZfWn4dJBX2l_j_NHLMxkdn1Aqeg3Oa22awEEy4dWkAo7PV9I6l3v4apVh1etC2_3N92UogzgHKlT9rFaK9acK9hgJacG6JW3GY_dRBmdJiTHkCnbl43nAp4ob6CaQAtAYMVFT8A2vYBV3xNZ4PuUZ66fgdvIIM1Wk4pn8j9SssghA_TS8dXRakm02TaPATvje9n68r2BZlAnEBwJWfvmS3FAS9yleSNjuiIzo4Bk1bS5Y065Q3ubGzVQYNMOSIZrRrutlXjk_uRdCEIPgaOJ-rlzgrEAm0OmDrDj63I_HTZrImRhFfOYKPxfnRUibcNcYqRK4w1xhqQjwG_wj0ZpS1gzUPDHrdkZe7UCPvBwYRW_JI0EaihY6Lgq5vdGA5ucWuPG76PgBKW63LQYNL1cuWK7UD61rE_00$&zoneid=zpc3159d90-01f7-41a7-a8ab-3704157466&zsid=FB&h=4N9Rn5fCYvSPZ0a5fWm00461mInKP%2B4MrI2p3lL%2FoHA%3D&fmt=json: context canceled 2020/07/24 09:48:45 INFO : newLeaf: vfs cache: upload canceled 2020/07/24 09:48:45 DEBUG : newLeaf: vfs cache: cancelled upload 2020/07/24 09:48:45 INFO : newLeaf: vfs cache: renamed in cache to "dir/file1" 2020/07/24 09:48:45 DEBUG : dir/file1: Updating file with dir/file1 0xc00062a0c0 2020/07/24 09:48:45 DEBUG : : Added virtual directory entry vDel: "newLeaf" 2020/07/24 09:48:45 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 09:48:45 DEBUG : dir/file1: vfs cache: starting upload 2020/07/24 09:48:45 DEBUG : dir/file1: Open: flags=O_WRONLY|O_TRUNC 2020/07/24 09:48:45 DEBUG : dir/file1: newRWFileHandle: 2020/07/24 09:48:45 DEBUG : dir/file1(0xc000482840): openPending: 2020/07/24 09:48:45 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06.5 +0000 UTC,0ef726ce9b1a7692357ff70dd321d595" against cached fingerprint "14,2001-02-03 04:05:06.5 +0000 UTC,0ef726ce9b1a7692357ff70dd321d595" 2020/07/24 09:48:45 DEBUG : dir/file1: vfs cache: truncate to size=14 2020/07/24 09:48:45 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 09:48:45 DEBUG : dir/file1(0xc000482840): >openPending: err= 2020/07/24 09:48:45 DEBUG : dir/file1: vfs cache: truncate to size=0 2020/07/24 09:48:45 DEBUG : dir/file1: vfs cache: cancelling writeback (uploading true) 0xc000182310 item 1 2020/07/24 09:48:45 DEBUG : dir/file1: vfs cache: cancelling upload 2020/07/24 09:48:45 ERROR : dir/file1: Failed to copy: upload file: Post https://storage-eu-203.sharefile.com/upload.aspx?uploadid=7d7accf7-4a62-4faf-a0de-d416660346e6&cid=TTvFZqFHs0Wywm54yP4SRg&tool=rclone%2fv1.52.2-DEV&batchid=d7340a5f-3302-462e-9dcd-58132d79cd96&overwrite=true&raw=1&encparams=FFCfwRlJTNnmJHa1g2TxCfBOJQ1XbF7FobEzl__-QOZ7JIuSFhMxD9DHTR_Laeq1emOBAOf8_En-Xsp_LOSgINQh703XId5a8PNBXjiWFAp3yRL1w54hLS8MK05tj8e77MYHYwQVtAa4_WCb75nJXqI5o-AFG6y7lfPPepP0W-iV188B5_TPspGhi1fe6B4MFyv5TdJ2vHtNYj2gADWmQpIWtZcpvhgDADJvxXT3qpSD_TjVDy3rxd__spdrVSvyHHkFxTGBzeX4t3hjpG319U7FPdAJTPNsYfDQLCPycSB6cYZM0jEE67poaRKq71KPiSp_NnPGmw3KEcQEW17ddO3Raw3WAuyqIRnQ1YzvLOnScy8wjSXh1VgQjGZBSg00o71pOoKVY2IDowkU7jdQajBWx-FMiADxl8GtXgr0Ht9GZNzCca0QVd-2GTKTC8S-3Eo9jv-us4i5PMoodGfTGo-zUoG7SEB2oxF85c4ZO8J-GkWz9Bi-cWi6gsvh9rfyK-I4jUb9kOqaJ8FQw_EPGA16VLUWk4UHq7ZYe8yU6-tAvElnzB0dV37djC-VCzrsJzxTBBUkH1UMWhe8BT4n9vxw2Cu9MmXVX_xIbQwpFn78xbUCmaKk0FKZLoN5y8aUNf8iIv5hbEZa-ssNjP9QI3YLd8PJ38PYb88GYJD8dPLpZ1X5DXlekGgPlbI8q0mxwY0RD4Uo7NqEize22mF0kUbHr6YnbG-Mik_C7Z36y8A9oG2IzpokCa8iXjum0f-NalirZuaXkD-UcDjYbaSqdUfRJkbitwVntlN7vOFB33eJHrAZL0lOfLdqjH-o&zoneid=zpc3159d90-01f7-41a7-a8ab-3704157466&zsid=FB&h=MBsQ%2BvzWDb6b2ueDGr9PDM%2FaGHDJr4Gu5nDRaJ%2FMlpg%3D&fmt=json: context canceled 2020/07/24 09:48:45 INFO : dir/file1: vfs cache: upload canceled 2020/07/24 09:48:45 DEBUG : dir/file1: vfs cache: cancelled upload 2020/07/24 09:48:45 DEBUG : dir/file1: >newRWFileHandle: err= 2020/07/24 09:48:45 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/07/24 09:48:45 DEBUG : dir/file1(0xc000482840): _writeAt: size=25, off=0 2020/07/24 09:48:45 DEBUG : dir/file1(0xc000482840): >_writeAt: n=25, err= 2020/07/24 09:48:46 INFO : dir/file1: Moved (server side) 2020/07/24 09:48:46 INFO : dir/file1: vfs cache: renamed in cache to "newLeaf" 2020/07/24 09:48:46 DEBUG : newLeaf: Updating file with newLeaf 0xc00062a0c0 2020/07/24 09:48:46 DEBUG : dir: Added virtual directory entry vDel: "file1" 2020/07/24 09:48:46 DEBUG : : Added virtual directory entry vAdd: "newLeaf" 2020/07/24 09:48:46 DEBUG : newLeaf(0xc000482840): close: 2020/07/24 09:48:46 DEBUG : vfs cache: looking for range={Pos:0 Size:25} in [{Pos:0 Size:25}] - present true 2020/07/24 09:48:46 DEBUG : newLeaf: vfs cache: setting modification time to 2020-07-24 09:48:45.354869601 +0000 UTC m=+6.642191558 2020/07/24 09:48:46 INFO : newLeaf: vfs cache: queuing for upload in 100ms 2020/07/24 09:48:46 DEBUG : newLeaf(0xc000482840): >close: err= 2020/07/24 09:48:46 DEBUG : WaitForWriters: timeout=10s 2020/07/24 09:48:46 DEBUG : dir: Looking for writers 2020/07/24 09:48:46 DEBUG : : Looking for writers 2020/07/24 09:48:46 DEBUG : dir: reading active writers 2020/07/24 09:48:46 DEBUG : newLeaf: reading active writers 2020/07/24 09:48:46 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2020/07/24 09:48:46 DEBUG : dir: Looking for writers 2020/07/24 09:48:46 DEBUG : : Looking for writers 2020/07/24 09:48:46 DEBUG : dir: reading active writers 2020/07/24 09:48:46 DEBUG : newLeaf: reading active writers 2020/07/24 09:48:46 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2020/07/24 09:48:46 DEBUG : dir: Looking for writers 2020/07/24 09:48:46 DEBUG : : Looking for writers 2020/07/24 09:48:46 DEBUG : newLeaf: reading active writers 2020/07/24 09:48:46 DEBUG : dir: reading active writers 2020/07/24 09:48:46 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2020/07/24 09:48:46 DEBUG : dir: Looking for writers 2020/07/24 09:48:46 DEBUG : : Looking for writers 2020/07/24 09:48:46 DEBUG : dir: reading active writers 2020/07/24 09:48:46 DEBUG : newLeaf: reading active writers 2020/07/24 09:48:46 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2020/07/24 09:48:46 DEBUG : newLeaf: vfs cache: starting upload 2020/07/24 09:48:46 DEBUG : dir: Looking for writers 2020/07/24 09:48:46 DEBUG : : Looking for writers 2020/07/24 09:48:46 DEBUG : dir: reading active writers 2020/07/24 09:48:46 DEBUG : newLeaf: reading active writers 2020/07/24 09:48:46 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2020/07/24 09:48:46 DEBUG : dir: Looking for writers 2020/07/24 09:48:46 DEBUG : : Looking for writers 2020/07/24 09:48:46 DEBUG : newLeaf: reading active writers 2020/07/24 09:48:46 DEBUG : dir: reading active writers 2020/07/24 09:48:46 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2020/07/24 09:48:46 DEBUG : dir: Looking for writers 2020/07/24 09:48:46 DEBUG : : Looking for writers 2020/07/24 09:48:46 DEBUG : dir: reading active writers 2020/07/24 09:48:46 DEBUG : newLeaf: reading active writers 2020/07/24 09:48:46 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2020/07/24 09:48:47 DEBUG : dir: Looking for writers 2020/07/24 09:48:47 DEBUG : : Looking for writers 2020/07/24 09:48:47 DEBUG : dir: reading active writers 2020/07/24 09:48:47 DEBUG : newLeaf: reading active writers 2020/07/24 09:48:47 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2020/07/24 09:48:47 DEBUG : newLeaf: MD5 = c7247bead226dfd7bd970c17229f4044 OK 2020/07/24 09:48:47 INFO : newLeaf: Copied (replaced existing) 2020/07/24 09:48:47 DEBUG : newLeaf: vfs cache: fingerprint now "25,2020-07-24 09:48:45.353 +0000 UTC,c7247bead226dfd7bd970c17229f4044" 2020/07/24 09:48:47 DEBUG : newLeaf: vfs cache: writeback object to VFS layer 2020/07/24 09:48:47 DEBUG : : Added virtual directory entry vAdd: "newLeaf" 2020/07/24 09:48:47 INFO : newLeaf: vfs cache: upload succeeded try #1 2020/07/24 09:48:48 DEBUG : dir: Looking for writers 2020/07/24 09:48:48 DEBUG : : Looking for writers 2020/07/24 09:48:48 DEBUG : dir: reading active writers 2020/07/24 09:48:48 DEBUG : newLeaf: reading active writers 2020/07/24 09:48:48 DEBUG : >WaitForWriters: 2020/07/24 09:48:56 DEBUG : WaitForWriters: timeout=10s 2020/07/24 09:48:56 DEBUG : dir: Looking for writers 2020/07/24 09:48:56 DEBUG : : Looking for writers 2020/07/24 09:48:56 DEBUG : dir: reading active writers 2020/07/24 09:48:56 DEBUG : newLeaf: reading active writers 2020/07/24 09:48:56 DEBUG : >WaitForWriters: 2020/07/24 09:48:56 DEBUG : vfs cache: cleaner exiting === RUN TestFileRename/writes,forceCache=true 2020/07/24 09:48:57 INFO : sharefile root 'rclone-test-tunepil3yodifus0juyolaf3': poll-interval is not supported by this remote 2020/07/24 09:48:57 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestSharefile/rclone-test-tunepil3yodifus0juyolaf3" 2020/07/24 09:48:57 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestSharefile/rclone-test-tunepil3yodifus0juyolaf3" 2020/07/24 09:48:57 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2020/07/24 09:49:03 DEBUG : dir/file1: Open: flags=O_RDWR|O_CREATE|O_TRUNC 2020/07/24 09:49:03 DEBUG : dir/file1: newRWFileHandle: 2020/07/24 09:49:03 DEBUG : dir/file1(0xc00042e740): openPending: 2020/07/24 09:49:03 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06.5 +0000 UTC,0ef726ce9b1a7692357ff70dd321d595" against cached fingerprint "" 2020/07/24 09:49:03 DEBUG : dir/file1: vfs cache: truncate to size=14 2020/07/24 09:49:03 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 09:49:03 DEBUG : dir/file1(0xc00042e740): >openPending: err= 2020/07/24 09:49:03 DEBUG : dir/file1: vfs cache: truncate to size=0 2020/07/24 09:49:03 DEBUG : dir/file1: >newRWFileHandle: err= 2020/07/24 09:49:03 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 09:49:03 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/07/24 09:49:03 DEBUG : dir/file1(0xc00042e740): _writeAt: size=14, off=0 2020/07/24 09:49:03 DEBUG : dir/file1(0xc00042e740): >_writeAt: n=14, err= 2020/07/24 09:49:03 DEBUG : dir/file1(0xc00042e740): close: 2020/07/24 09:49:03 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true 2020/07/24 09:49:03 DEBUG : dir/file1: vfs cache: setting modification time to 2020-07-24 09:49:03.421102654 +0000 UTC m=+24.708424611 2020/07/24 09:49:03 INFO : dir/file1: vfs cache: queuing for upload in 100ms 2020/07/24 09:49:03 DEBUG : dir/file1(0xc00042e740): >close: err= 2020/07/24 09:49:03 DEBUG : dir/file1: Open: flags=O_RDONLY 2020/07/24 09:49:03 DEBUG : dir/file1: newRWFileHandle: 2020/07/24 09:49:03 DEBUG : dir/file1: >newRWFileHandle: err= 2020/07/24 09:49:03 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/07/24 09:49:03 DEBUG : dir/file1(0xc00042ea00): _readAt: size=512, off=0 2020/07/24 09:49:03 DEBUG : dir/file1(0xc00042ea00): openPending: 2020/07/24 09:49:03 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06.5 +0000 UTC,0ef726ce9b1a7692357ff70dd321d595" against cached fingerprint "14,2001-02-03 04:05:06.5 +0000 UTC,0ef726ce9b1a7692357ff70dd321d595" 2020/07/24 09:49:03 DEBUG : dir/file1: vfs cache: truncate to size=14 2020/07/24 09:49:03 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 09:49:03 DEBUG : dir/file1(0xc00042ea00): >openPending: err= 2020/07/24 09:49:03 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true 2020/07/24 09:49:03 DEBUG : dir/file1(0xc00042ea00): >_readAt: n=14, err=EOF 2020/07/24 09:49:03 DEBUG : dir/file1(0xc00042ea00): close: 2020/07/24 09:49:03 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true 2020/07/24 09:49:03 DEBUG : dir/file1: vfs cache: setting modification time to 2020-07-24 09:49:03.421102654 +0000 UTC m=+24.708424611 2020/07/24 09:49:03 INFO : dir/file1: vfs cache: queuing for upload in 100ms 2020/07/24 09:49:03 DEBUG : dir/file1(0xc00042ea00): >close: err= 2020/07/24 09:49:03 DEBUG : dir/file1: vfs cache: starting upload 2020/07/24 09:49:04 INFO : dir/file1: Moved (server side) 2020/07/24 09:49:04 DEBUG : dir/file1: vfs cache: cancelling upload 2020/07/24 09:49:04 ERROR : dir/file1: Failed to copy: upload file: Post https://storage-eu-201.sharefile.com/upload.aspx?uploadid=749a6f63-577e-4ef6-bf42-766d705c880c&cid=7LLyOuPM-Eep9Qa815fDmw&tool=rclone%2fv1.52.2-DEV&batchid=63a1668c-2dfa-48f9-a4e0-cebfa797c650&overwrite=true&raw=1&encparams=whyZzLAI7neudN432N-p2yHsm-YfglqAxxcDwdjXYWIaukTWOaVb1u5QOlzItVtPEiErNV7eujc0lqjaV3RLofNiTrfs5CJl202iujRuqwT68V6Xo0S-Oh5OmH_cha3rO6esr-ZyGNLwv8LZwENvrc-Yjn-AJyuTZUbstoeB4wYDESBCpxz1ase4ANdHUmcDcGH4hNFZafwg196vkAryFixoo_ljidpIOswhYRdTBV-7guVX_ZkgRJ-JBh8z86mzk82t0VrTTezLkT_JXiVNrcnPrPR_yUb6R8Au9HvsA_gIqg6ALVXxTUN-MPwbxdd76RcTbnkLqAASl_W6SOzBD0pHozqlCRpA0QcHbQYlJVkgeDq5cwjl56huzzLkWx9pivgmJJhcU1EmCzVZJBEApCVPo7m0kGdxQnZy-T216p42yp-DdMW-X3O15o_B1KXAfgV-F1mUfRf9U9VGNEk4CFRCAHRYA07v-K2XadPJngF-pObY18zKh8WjXfpxVX2ZFdhF-yZx8XhYbjiovd2rmm10v4YEpgQbXQ4K5i8TiOyzUHgs8czZXRhd_CzC3DmYzKGyGXgoE5yZXTnRtmF7mRcGYfapVAKPN8nC-Svu3oTnGczgj2xhJftBtnURKJLVdNrWl5_5RtyCC952uQDU4M7EiyT6oAI4PFlc8m_pIIxiP6sjbMoJ_9G7bndk-VrL9aPfP35FDPeVFozTZ6no8RlEKRN5UnB9sTC1bRD2iJmYQe7oIVEF2OzwwvA7VAhe8abDzbRCO13dB4Q55V4x2yeNLalgKlf8vtZucD0wwDBjKkKbY2ncgHTbYXvV&zoneid=zpc3159d90-01f7-41a7-a8ab-3704157466&zsid=FB&h=x4Xlq1QX%2BzIr9Vg0GJ0euxX6H3PIDiElSL3KoLGwKkw%3D&fmt=json: context canceled 2020/07/24 09:49:04 INFO : dir/file1: vfs cache: upload canceled 2020/07/24 09:49:04 DEBUG : dir/file1: vfs cache: cancelled upload 2020/07/24 09:49:04 INFO : dir/file1: vfs cache: renamed in cache to "newLeaf" 2020/07/24 09:49:04 DEBUG : newLeaf: Updating file with newLeaf 0xc0006380c0 2020/07/24 09:49:04 DEBUG : dir: Added virtual directory entry vDel: "file1" 2020/07/24 09:49:04 DEBUG : : Added virtual directory entry vAdd: "newLeaf" 2020/07/24 09:49:04 DEBUG : newLeaf: vfs cache: starting upload 2020/07/24 09:49:05 INFO : newLeaf: Moved (server side) 2020/07/24 09:49:05 DEBUG : newLeaf: vfs cache: cancelling upload 2020/07/24 09:49:05 ERROR : newLeaf: Failed to copy: upload file: Post https://storage-eu-200.sharefile.com/upload.aspx?uploadid=b215ae0d-de95-4cad-a765-3981eca92076&cid=UGIHriV-0US297h4C98ODg&tool=rclone%2fv1.52.2-DEV&batchid=8bd9a11e-e785-4115-8256-097152809d34&overwrite=true&raw=1&encparams=t543zf9Bs019JrUXfflJWmCfdoXuaxD1cOss60SATZMlh1sIomW_QPe0A7U0NP5Y9itHJYn2EfFaLCjj7IFzGoO__Unx79N9tuGqDVNdKZtW6eXEdvvpBW269PgdVfwr-9DybF9lESViQpwzBCwAqu-P46WebQLv5twkDiVo5cvumjDYd4Mx7WJRnW5W0co0OsMVFH2PLcMfswjg_BVL_45nEEsDXIrATos9R8GPnHqn8zkpqt6kElm0WDZ7drIzdJNxi05-i3OWgFufbzX8kw1hO9bF0WtjGXoPaH7zmE7CI9RuBquB2O5XJVQVoss5h64uIWYtgG1c9i7UDsbauo443WgMxQVZaHLCZCNcML0zKutgtEl5v8HaWCCpDiwyu40iMaHchBSWg72WXPEz0CVZQkCJ8plOUAcBOSyg9UbHbVE43eqfubQy2XikYFsqjtXDupxwtOer3QDtEofTWVslW7rL3bPTKfI0zI1Wn4-1shr3jLLaOlb4TP0AvO3hllxhEHoUkMQVaxawxjfkWw47h3gWdsYoAjwHNA27UeOnDN_gl5ltk53qd6Qg6k-Tr-6TJpeRElwBGSqXFzKyB-AhNKvqP6HCFeSXQwEkspwWJlyCViHy1XBAPNh7U5omxkl0fyu13Fi2v_7DI3boNGCt69sA6pJuMhKfNP122TJJNha4v9984tN8GaKm5z1enpMtcdOqkaqa4GtOFouGZeti0pOjaNZtv7GsBcicy04xM-mS1d5Zn9UuPopa7gFMAZyWU-ZXvFlLeIqu33ELVc2feJOiNeRFuRIA4D2FNw_Ss2X9GyfWwxRYfCtl6Zs$&zoneid=zpc3159d90-01f7-41a7-a8ab-3704157466&zsid=FB&h=bZtJLl1qASbHEYsW%2BmpA7VxmRmtLu%2BMbFjl36TMHAbU%3D&fmt=json: context canceled 2020/07/24 09:49:05 INFO : newLeaf: vfs cache: upload canceled 2020/07/24 09:49:05 DEBUG : newLeaf: vfs cache: cancelled upload 2020/07/24 09:49:05 INFO : newLeaf: vfs cache: renamed in cache to "dir/file1" 2020/07/24 09:49:05 DEBUG : dir/file1: Updating file with dir/file1 0xc0006380c0 2020/07/24 09:49:05 DEBUG : : Added virtual directory entry vDel: "newLeaf" 2020/07/24 09:49:05 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 09:49:05 DEBUG : dir/file1: vfs cache: starting upload 2020/07/24 09:49:05 DEBUG : dir/file1: Open: flags=O_WRONLY|O_TRUNC 2020/07/24 09:49:05 DEBUG : dir/file1: newRWFileHandle: 2020/07/24 09:49:05 DEBUG : dir/file1(0xc000093180): openPending: 2020/07/24 09:49:05 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06.5 +0000 UTC,0ef726ce9b1a7692357ff70dd321d595" against cached fingerprint "14,2001-02-03 04:05:06.5 +0000 UTC,0ef726ce9b1a7692357ff70dd321d595" 2020/07/24 09:49:05 DEBUG : dir/file1: vfs cache: truncate to size=14 2020/07/24 09:49:05 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 09:49:05 DEBUG : dir/file1(0xc000093180): >openPending: err= 2020/07/24 09:49:05 DEBUG : dir/file1: vfs cache: truncate to size=0 2020/07/24 09:49:05 DEBUG : dir/file1: vfs cache: cancelling writeback (uploading true) 0xc0001eec40 item 1 2020/07/24 09:49:05 DEBUG : dir/file1: vfs cache: cancelling upload 2020/07/24 09:49:05 ERROR : dir/file1: Failed to copy: upload file: Post https://storage-eu-201.sharefile.com/upload.aspx?uploadid=d9b1aa93-4f2c-495c-8207-e2ab5bfd7b4b&cid=KSXJl5F1okygOaTwGCI3TA&tool=rclone%2fv1.52.2-DEV&batchid=6561dc96-67be-4ec9-9f06-3a88b96a772d&overwrite=true&raw=1&encparams=WSHWzf5UTBNdriHOL23ccEys6KArJm2Rveohz7MA-5raYMDMUYr4OQ72GAOf-6pICamcjHXyAzEz3382O4qhBMYvFRJJAqPqnVTRVuZGhWzxpEY_fPm-KM_f0GeTyeBKCqCI_nlO5e2LvDi0J-FYJpa_dBdSdmDiJ53wYGQBJyknGypihD1Emg75MQYW1qRwwSJWUpPuQ4yIurQo5ywtSHpxUGl3P8lIDJ8wUg3R5MihSeL9hayQ8six10IikNzoVBzTDSjodazQzMwK02VVyKyYyhNRrz4zbhDN7bvW9tNsRPcOTh2Ua6iR_eNv1hubH_RkmE7Uvdw9gcBhVfBAWqkKg7bO_4BaY1Atr8yQhRtmH1386Ny6HpBh0S9kUx7LVbxvB7siZnaaU7_6nlPaDk78-A01igRuWbrp3feixEZeGs5FzLUc3ozPAtT2GDQL3MzfuXwKSPJEBfxDMxoZ_67wih3Yh7tUwbTVGK0hFRzEc6M-Wocf6Yasvirs4YUIdsbDthi8q_FpzQ6o9iIjn_b_3n6dRsm2ARonRzw6FShQdIZdQIspH3Ra4HzKBi-R83udkXyDtSWO5wwX4e9KY3fLiGayu6mTXlPGNDSc1vTYtbxTSOs96w-cgwQ8Yt6VrcdpUtVCidxuiArWOlBVmU82qsRplCjF2a2VsCncY30jShVCl0AfN4F3nCNz9A7w3RPnPw_UDYP56TUSLoKi0_2pk81YASyMWh3uwDq9Bj9mQvsb538O4C3UXk_RnKSElHXH9nPCngm00zGf6ww1Ed0LdNFLrmCfNgsR2ae684KKCNDnjwHdMrE-9Ptn&zoneid=zpc3159d90-01f7-41a7-a8ab-3704157466&zsid=FB&h=J6LrvA4fhk5JsV6Vn7l%2F6Dh2R8dZNRWsReLcKaO1IZo%3D&fmt=json: context canceled 2020/07/24 09:49:05 INFO : dir/file1: vfs cache: upload canceled 2020/07/24 09:49:05 DEBUG : dir/file1: vfs cache: cancelled upload 2020/07/24 09:49:05 DEBUG : dir/file1: >newRWFileHandle: err= 2020/07/24 09:49:05 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/07/24 09:49:05 DEBUG : dir/file1(0xc000093180): _writeAt: size=25, off=0 2020/07/24 09:49:05 DEBUG : dir/file1(0xc000093180): >_writeAt: n=25, err= 2020/07/24 09:49:06 INFO : dir/file1: Moved (server side) 2020/07/24 09:49:06 INFO : dir/file1: vfs cache: renamed in cache to "newLeaf" 2020/07/24 09:49:06 DEBUG : newLeaf: Updating file with newLeaf 0xc0006380c0 2020/07/24 09:49:06 DEBUG : dir: Added virtual directory entry vDel: "file1" 2020/07/24 09:49:06 DEBUG : : Added virtual directory entry vAdd: "newLeaf" 2020/07/24 09:49:06 DEBUG : newLeaf(0xc000093180): close: 2020/07/24 09:49:06 DEBUG : vfs cache: looking for range={Pos:0 Size:25} in [{Pos:0 Size:25}] - present true 2020/07/24 09:49:06 DEBUG : newLeaf: vfs cache: setting modification time to 2020-07-24 09:49:05.77576668 +0000 UTC m=+27.063088648 2020/07/24 09:49:06 INFO : newLeaf: vfs cache: queuing for upload in 100ms 2020/07/24 09:49:06 DEBUG : newLeaf(0xc000093180): >close: err= 2020/07/24 09:49:06 DEBUG : WaitForWriters: timeout=10s 2020/07/24 09:49:06 DEBUG : dir: Looking for writers 2020/07/24 09:49:06 DEBUG : : Looking for writers 2020/07/24 09:49:06 DEBUG : dir: reading active writers 2020/07/24 09:49:06 DEBUG : newLeaf: reading active writers 2020/07/24 09:49:06 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2020/07/24 09:49:06 DEBUG : dir: Looking for writers 2020/07/24 09:49:06 DEBUG : : Looking for writers 2020/07/24 09:49:06 DEBUG : dir: reading active writers 2020/07/24 09:49:06 DEBUG : newLeaf: reading active writers 2020/07/24 09:49:06 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2020/07/24 09:49:06 DEBUG : dir: Looking for writers 2020/07/24 09:49:06 DEBUG : : Looking for writers 2020/07/24 09:49:06 DEBUG : dir: reading active writers 2020/07/24 09:49:06 DEBUG : newLeaf: reading active writers 2020/07/24 09:49:06 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2020/07/24 09:49:06 DEBUG : dir: Looking for writers 2020/07/24 09:49:06 DEBUG : : Looking for writers 2020/07/24 09:49:06 DEBUG : dir: reading active writers 2020/07/24 09:49:06 DEBUG : newLeaf: reading active writers 2020/07/24 09:49:06 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2020/07/24 09:49:06 DEBUG : newLeaf: vfs cache: starting upload 2020/07/24 09:49:06 DEBUG : dir: Looking for writers 2020/07/24 09:49:06 DEBUG : : Looking for writers 2020/07/24 09:49:06 DEBUG : dir: reading active writers 2020/07/24 09:49:06 DEBUG : newLeaf: reading active writers 2020/07/24 09:49:06 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2020/07/24 09:49:06 DEBUG : dir: Looking for writers 2020/07/24 09:49:06 DEBUG : : Looking for writers 2020/07/24 09:49:06 DEBUG : dir: reading active writers 2020/07/24 09:49:06 DEBUG : newLeaf: reading active writers 2020/07/24 09:49:06 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2020/07/24 09:49:07 DEBUG : dir: Looking for writers 2020/07/24 09:49:07 DEBUG : : Looking for writers 2020/07/24 09:49:07 DEBUG : dir: reading active writers 2020/07/24 09:49:07 DEBUG : newLeaf: reading active writers 2020/07/24 09:49:07 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2020/07/24 09:49:07 DEBUG : dir: Looking for writers 2020/07/24 09:49:07 DEBUG : : Looking for writers 2020/07/24 09:49:07 DEBUG : newLeaf: reading active writers 2020/07/24 09:49:07 DEBUG : dir: reading active writers 2020/07/24 09:49:07 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2020/07/24 09:49:08 DEBUG : newLeaf: MD5 = c7247bead226dfd7bd970c17229f4044 OK 2020/07/24 09:49:08 INFO : newLeaf: Copied (replaced existing) 2020/07/24 09:49:08 DEBUG : newLeaf: vfs cache: fingerprint now "25,2020-07-24 09:49:05.777 +0000 UTC,c7247bead226dfd7bd970c17229f4044" 2020/07/24 09:49:08 DEBUG : newLeaf: vfs cache: writeback object to VFS layer 2020/07/24 09:49:08 DEBUG : : Added virtual directory entry vAdd: "newLeaf" 2020/07/24 09:49:08 INFO : newLeaf: vfs cache: upload succeeded try #1 2020/07/24 09:49:08 DEBUG : dir: Looking for writers 2020/07/24 09:49:08 DEBUG : : Looking for writers 2020/07/24 09:49:08 DEBUG : dir: reading active writers 2020/07/24 09:49:08 DEBUG : newLeaf: reading active writers 2020/07/24 09:49:08 DEBUG : >WaitForWriters: 2020/07/24 09:49:16 DEBUG : WaitForWriters: timeout=10s 2020/07/24 09:49:16 DEBUG : dir: Looking for writers 2020/07/24 09:49:16 DEBUG : : Looking for writers 2020/07/24 09:49:16 DEBUG : dir: reading active writers 2020/07/24 09:49:16 DEBUG : newLeaf: reading active writers 2020/07/24 09:49:16 DEBUG : >WaitForWriters: 2020/07/24 09:49:16 DEBUG : vfs cache: cleaner exiting --- FAIL: TestFileRename (38.72s) --- FAIL: TestFileRename/minimal,forceCache=true (18.19s) run.go:176: Remote "sharefile root 'rclone-test-tunepil3yodifus0juyolaf3'", Local "Local file system at /tmp/rclone286676600", Modify Window "1s" fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:298: Flushing the directory cache fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:298: Flushing the directory cache fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:298: Flushing the directory cache fstest.go:302: Error Trace: fstest.go:302 fstest.go:335 file_test.go:340 file_test.go:357 Error: Should be true Test: TestFileRename/minimal,forceCache=true Messages: listing wrong, want newLeaf (25) got dir/file1 (14), newLeaf (25) fstest.go:188: Error Trace: fstest.go:188 fstest.go:305 fstest.go:335 file_test.go:340 file_test.go:357 Error: Should be true Test: TestFileRename/minimal,forceCache=true Messages: Unexpected file "dir/file1" --- FAIL: TestFileRename/writes,forceCache=true (20.53s) run.go:176: Remote "sharefile root 'rclone-test-tunepil3yodifus0juyolaf3'", Local "Local file system at /tmp/rclone286676600", Modify Window "1s" fstest.go:124: Error Trace: fstest.go:124 fstest.go:129 fstest.go:148 fstest.go:192 fstest.go:305 fstest.go:335 fstest.go:347 file_test.go:305 file_test.go:357 Error: Should be true Test: TestFileRename/writes,forceCache=true Messages: dir/file1: Modification time difference too big |-170669h43m56.920000001s| > 1s (want 2001-02-03 04:05:06.499999999 +0000 UTC vs got 2020-07-24 09:49:03.42 +0000 UTC) (precision 1s) fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:298: Flushing the directory cache fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:298: Flushing the directory cache fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:298: Flushing the directory cache fstest.go:302: Error Trace: fstest.go:302 fstest.go:335 file_test.go:340 file_test.go:357 Error: Should be true Test: TestFileRename/writes,forceCache=true Messages: listing wrong, want newLeaf (25) got dir/file1 (14), newLeaf (25) fstest.go:188: Error Trace: fstest.go:188 fstest.go:305 fstest.go:335 file_test.go:340 file_test.go:357 Error: Should be true Test: TestFileRename/writes,forceCache=true Messages: Unexpected file "dir/file1" FAIL 2020/07/24 09:49:18 DEBUG : sharefile root 'rclone-test-tunepil3yodifus0juyolaf3': Purge remote "./vfs.test -test.v -test.timeout 1h0m0s -remote TestSharefile: -verbose -test.run '^TestFileRename$/^(minimal,forceCache=true|writes,forceCache=true)$'" - Finished ERROR in 39.582718499s (try 4/5): exit status 1: Failed [TestFileRename/minimal,forceCache=true TestFileRename/writes,forceCache=true]