Debugging copying to Google Drive

philip_rhoades · September 28, 2020, 3:11am

People,

Some days ago I had a problem with copying a large ODT file (~ 400MB with 65 images in it) to my Google Drive folder - the process would hang and then I would eventually have to kill it. So I decided to break the big file up into 65 files with one image each thinking that this would get over any "big file" problems - but I still had problems! I still had the same problems again 10 hours later - even though the error messages would appear to indicate that the problem is on the GD end. This is reported here:

So now I am trying to methodically / systematically do tests to see if I can get a better picture of what is happening / going wrong.

Phil.

philip_rhoades · September 28, 2020, 3:14am

Test #01

A big file about the same size as the original ODT file where I first noticed an issue - but testing an AVI instead of an ODT => success!

$ /usr/bin/rclone -L -vv copy --tpslimit 5 --drive-formats "ods,odt" --drive-import-formats "ods,odt" DolphinsOfSharkBay.avi gd:0_Relatives/Diary_02/

2020/09/28 13:00:48 DEBUG : rclone: Version "v1.53.1" starting with parameters ["/usr/bin/rclone" "-L" "-vv" "copy" "--tpslimit" "5" "--drive-formats" "ods,odt" "--drive-import-formats" "ods,odt" "DolphinsOfSharkBay.avi" "gd:0_Relatives/Diary_02/"]
2020/09/28 13:00:48 DEBUG : Creating backend with remote "DolphinsOfSharkBay.avi"
2020/09/28 13:00:48 DEBUG : Using config file from "/home/phr/.config/rclone/rclone.conf"
2020/09/28 13:00:48 INFO  : Starting HTTP transaction limiter: max 5 transactions/s with burst 1
2020/09/28 13:00:48 DEBUG : fs cache: adding new entry for parent of "DolphinsOfSharkBay.avi", "/home/phr/video"
2020/09/28 13:00:48 DEBUG : Creating backend with remote "gd:0_Relatives/Diary_02/"
2020/09/28 13:00:48 DEBUG : gd: Loaded invalid token from config file - ignoring
2020/09/28 13:00:49 DEBUG : gd: Saved new token in config file
2020/09/28 13:00:49 DEBUG : Google drive root '0_Relatives/Diary_02': root_folder_id = "0AA-FsVZgP3GtUk9PVA" - save this in the config to speed up startup
2020/09/28 13:00:50 DEBUG : fs cache: renaming cache item "gd:0_Relatives/Diary_02/" to be canonical "gd:0_Relatives/Diary_02"
2020/09/28 13:00:51 DEBUG : DolphinsOfSharkBay.avi: Need to transfer - File not found at Destination
2020/09/28 13:00:52 DEBUG : DolphinsOfSharkBay.avi: Sending chunk 0 length 8388608
2020/09/28 13:00:56 DEBUG : DolphinsOfSharkBay.avi: Sending chunk 8388608 length 8388608
2020/09/28 13:01:00 DEBUG : DolphinsOfSharkBay.avi: Sending chunk 16777216 length 8388608
2020/09/28 13:01:03 DEBUG : DolphinsOfSharkBay.avi: Sending chunk 25165824 length 8388608
2020/09/28 13:01:07 DEBUG : DolphinsOfSharkBay.avi: Sending chunk 33554432 length 8388608
2020/09/28 13:01:11 DEBUG : DolphinsOfSharkBay.avi: Sending chunk 41943040 length 8388608
2020/09/28 13:01:15 DEBUG : DolphinsOfSharkBay.avi: Sending chunk 50331648 length 8388608
2020/09/28 13:01:19 DEBUG : DolphinsOfSharkBay.avi: Sending chunk 58720256 length 8388608
2020/09/28 13:01:23 DEBUG : DolphinsOfSharkBay.avi: Sending chunk 67108864 length 8388608
2020/09/28 13:01:27 DEBUG : DolphinsOfSharkBay.avi: Sending chunk 75497472 length 8388608
2020/09/28 13:01:30 DEBUG : DolphinsOfSharkBay.avi: Sending chunk 83886080 length 8388608
2020/09/28 13:01:34 DEBUG : DolphinsOfSharkBay.avi: Sending chunk 92274688 length 8388608
2020/09/28 13:01:38 DEBUG : DolphinsOfSharkBay.avi: Sending chunk 100663296 length 8388608
2020/09/28 13:01:42 DEBUG : DolphinsOfSharkBay.avi: Sending chunk 109051904 length 8388608
2020/09/28 13:01:46 DEBUG : DolphinsOfSharkBay.avi: Sending chunk 117440512 length 8388608
2020/09/28 13:01:50 DEBUG : DolphinsOfSharkBay.avi: Sending chunk 125829120 length 8388608
2020/09/28 13:01:50 INFO  : 
Transferred:   	 120.938M / 366.921 MBytes, 33%, 2.030 MBytes/s, ETA 2m1s
Transferred:            0 / 1, 0%
Elapsed time:       1m1.9s
Transferring:
 *                        DolphinsOfSharkBay.avi: 32% /366.921M, 2.046M/s, 2m0s

2020/09/28 13:01:54 DEBUG : DolphinsOfSharkBay.avi: Sending chunk 134217728 length 8388608
2020/09/28 13:01:58 DEBUG : DolphinsOfSharkBay.avi: Sending chunk 142606336 length 8388608
2020/09/28 13:02:01 DEBUG : DolphinsOfSharkBay.avi: Sending chunk 150994944 length 8388608
2020/09/28 13:02:05 DEBUG : DolphinsOfSharkBay.avi: Sending chunk 159383552 length 8388608
2020/09/28 13:02:09 DEBUG : DolphinsOfSharkBay.avi: Sending chunk 167772160 length 8388608
2020/09/28 13:02:13 DEBUG : DolphinsOfSharkBay.avi: Sending chunk 176160768 length 8388608
2020/09/28 13:02:16 DEBUG : DolphinsOfSharkBay.avi: Sending chunk 184549376 length 8388608
2020/09/28 13:02:20 DEBUG : DolphinsOfSharkBay.avi: Sending chunk 192937984 length 8388608
2020/09/28 13:02:24 DEBUG : DolphinsOfSharkBay.avi: Sending chunk 201326592 length 8388608
2020/09/28 13:02:28 DEBUG : DolphinsOfSharkBay.avi: Sending chunk 209715200 length 8388608
2020/09/28 13:02:32 DEBUG : DolphinsOfSharkBay.avi: Sending chunk 218103808 length 8388608
2020/09/28 13:02:36 DEBUG : DolphinsOfSharkBay.avi: Sending chunk 226492416 length 8388608
2020/09/28 13:02:39 DEBUG : DolphinsOfSharkBay.avi: Sending chunk 234881024 length 8388608
2020/09/28 13:02:43 DEBUG : DolphinsOfSharkBay.avi: Sending chunk 243269632 length 8388608
2020/09/28 13:02:47 DEBUG : DolphinsOfSharkBay.avi: Sending chunk 251658240 length 8388608
2020/09/28 13:02:50 INFO  : 
Transferred:   	     248M / 366.921 MBytes, 68%, 2.074 MBytes/s, ETA 57s
Transferred:            0 / 1, 0%
Elapsed time:       2m1.9s
Transferring:
 *                        DolphinsOfSharkBay.avi: 67% /366.921M, 2.123M/s, 56s

2020/09/28 13:02:51 DEBUG : DolphinsOfSharkBay.avi: Sending chunk 260046848 length 8388608
2020/09/28 13:02:54 DEBUG : DolphinsOfSharkBay.avi: Sending chunk 268435456 length 8388608
2020/09/28 13:02:58 DEBUG : DolphinsOfSharkBay.avi: Sending chunk 276824064 length 8388608
2020/09/28 13:03:02 DEBUG : DolphinsOfSharkBay.avi: Sending chunk 285212672 length 8388608
2020/09/28 13:03:06 DEBUG : DolphinsOfSharkBay.avi: Sending chunk 293601280 length 8388608
2020/09/28 13:03:09 DEBUG : DolphinsOfSharkBay.avi: Sending chunk 301989888 length 8388608
2020/09/28 13:03:13 DEBUG : DolphinsOfSharkBay.avi: Sending chunk 310378496 length 8388608
2020/09/28 13:03:17 DEBUG : DolphinsOfSharkBay.avi: Sending chunk 318767104 length 8388608
2020/09/28 13:03:21 DEBUG : DolphinsOfSharkBay.avi: Sending chunk 327155712 length 8388608
2020/09/28 13:03:24 DEBUG : DolphinsOfSharkBay.avi: Sending chunk 335544320 length 8388608
2020/09/28 13:03:28 DEBUG : DolphinsOfSharkBay.avi: Sending chunk 343932928 length 8388608
2020/09/28 13:03:32 DEBUG : DolphinsOfSharkBay.avi: Sending chunk 352321536 length 8388608
2020/09/28 13:03:36 DEBUG : DolphinsOfSharkBay.avi: Sending chunk 360710144 length 8388608
2020/09/28 13:03:39 DEBUG : DolphinsOfSharkBay.avi: Sending chunk 369098752 length 8388608
2020/09/28 13:03:43 DEBUG : DolphinsOfSharkBay.avi: Sending chunk 377487360 length 7257526
2020/09/28 13:03:49 DEBUG : DolphinsOfSharkBay.avi: MD5 = 37a35eedf6e3bacd03df11db87d6eb2a OK
2020/09/28 13:03:49 INFO  : DolphinsOfSharkBay.avi: Copied (new)
2020/09/28 13:03:49 INFO  : 
Transferred:   	 366.921M / 366.921 MBytes, 100%, 2.061 MBytes/s, ETA 0s
Transferred:            1 / 1, 100%
Elapsed time:       3m0.4s

2020/09/28 13:03:49 DEBUG : 5 go routines active

philip_rhoades · September 28, 2020, 3:31am

Test #02

The original ODT file where I first noticed an issue => FAILURE again! - the copying gets to some (seemingly) random point, has an error and starts sending from the beginning again . .

So it looks, provisionally, like an ODT issue?

/usr/bin/rclone -L -vv copy --tpslimit 5 --drive-formats "ods,odt" --drive-import-formats "ods,odt" tdiary_02.odt gd:0_Relatives/Diary_02/ >t 2>&1

2020/09/28 13:23:05 DEBUG : rclone: Version "v1.53.1" starting with parameters ["/usr/bin/rclone" "-L" "-vv" "copy" "--tpslimit" "5" "--drive-formats" "ods,odt" "--drive-import-formats" "ods,odt" "tdiary_02.odt" "gd:0_Relatives/Diary_02/"]
2020/09/28 13:23:05 DEBUG : Creating backend with remote "tdiary_02.odt"
2020/09/28 13:23:05 DEBUG : Using config file from "/home/phr/.config/rclone/rclone.conf"
2020/09/28 13:23:05 INFO  : Starting HTTP transaction limiter: max 5 transactions/s with burst 1
2020/09/28 13:23:05 DEBUG : fs cache: adding new entry for parent of "tdiary_02.odt", "/home/phr/0_relatives/MumDiaries/Diary_02"
2020/09/28 13:23:05 DEBUG : Creating backend with remote "gd:0_Relatives/Diary_02/"
2020/09/28 13:23:05 DEBUG : Google drive root '0_Relatives/Diary_02': root_folder_id = "0AA-FsVZgP3GtUk9PVA" - save this in the config to speed up startup
2020/09/28 13:23:08 DEBUG : fs cache: renaming cache item "gd:0_Relatives/Diary_02/" to be canonical "gd:0_Relatives/Diary_02"
2020/09/28 13:23:08 DEBUG : tdiary_02.odt: Need to transfer - File not found at Destination
2020/09/28 13:23:09 DEBUG : tdiary_02: Sending chunk 0 length 8388608
2020/09/28 13:23:13 DEBUG : tdiary_02: Sending chunk 8388608 length 8388608
2020/09/28 13:23:17 DEBUG : tdiary_02: Sending chunk 16777216 length 8388608
2020/09/28 13:23:21 DEBUG : tdiary_02: Sending chunk 25165824 length 8388608
2020/09/28 13:23:24 DEBUG : tdiary_02: Sending chunk 33554432 length 8388608
2020/09/28 13:23:28 DEBUG : tdiary_02: Sending chunk 41943040 length 8388608
2020/09/28 13:23:32 DEBUG : tdiary_02: Sending chunk 50331648 length 8388608
2020/09/28 13:23:36 DEBUG : tdiary_02: Sending chunk 58720256 length 8388608
2020/09/28 13:23:39 DEBUG : tdiary_02: Sending chunk 67108864 length 8388608
2020/09/28 13:23:43 DEBUG : tdiary_02: Sending chunk 75497472 length 8388608
2020/09/28 13:23:47 DEBUG : tdiary_02: Sending chunk 83886080 length 8388608
2020/09/28 13:23:51 DEBUG : tdiary_02: Sending chunk 92274688 length 8388608
2020/09/28 13:23:54 DEBUG : tdiary_02: Sending chunk 100663296 length 8388608
2020/09/28 13:23:58 DEBUG : tdiary_02: Sending chunk 109051904 length 8388608
2020/09/28 13:24:02 DEBUG : tdiary_02: Sending chunk 117440512 length 8388608
2020/09/28 13:24:06 DEBUG : tdiary_02: Sending chunk 125829120 length 8388608
2020/09/28 13:24:08 INFO  : 
Transferred:   	  124.684M / 312.890 MBytes, 40%, 2.091 MBytes/s, ETA 1m29s
Transferred:            0 / 1, 0%
Elapsed time:       1m2.8s
Transferring:
 *                                 tdiary_02.odt: 39% /312.890M, 2.124M/s, 1m28s

2020/09/28 13:24:09 DEBUG : tdiary_02: Sending chunk 134217728 length 8388608
2020/09/28 13:24:13 DEBUG : tdiary_02: Sending chunk 142606336 length 8388608
2020/09/28 13:24:17 DEBUG : tdiary_02: Sending chunk 150994944 length 8388608
2020/09/28 13:24:21 DEBUG : tdiary_02: Sending chunk 159383552 length 8388608
2020/09/28 13:24:24 DEBUG : tdiary_02: Sending chunk 167772160 length 8388608
2020/09/28 13:24:28 DEBUG : tdiary_02: Sending chunk 176160768 length 8388608
2020/09/28 13:24:32 DEBUG : tdiary_02: Sending chunk 184549376 length 8388608
2020/09/28 13:24:36 DEBUG : tdiary_02: Sending chunk 192937984 length 8388608
2020/09/28 13:24:39 DEBUG : tdiary_02: Sending chunk 201326592 length 8388608
2020/09/28 13:24:43 DEBUG : tdiary_02: Sending chunk 209715200 length 8388608
2020/09/28 13:24:47 DEBUG : tdiary_02: Sending chunk 218103808 length 8388608
2020/09/28 13:24:51 DEBUG : tdiary_02: Sending chunk 226492416 length 8388608
2020/09/28 13:24:54 DEBUG : tdiary_02: Sending chunk 234881024 length 8388608
2020/09/28 13:24:58 DEBUG : tdiary_02: Sending chunk 243269632 length 8388608
2020/09/28 13:25:02 DEBUG : tdiary_02: Sending chunk 251658240 length 8388608
2020/09/28 13:25:06 DEBUG : tdiary_02: Sending chunk 260046848 length 8388608
2020/09/28 13:25:08 INFO  : 
Transferred:   	  252.684M / 312.890 MBytes, 81%, 2.112 MBytes/s, ETA 28s
Transferred:            0 / 1, 0%
Elapsed time:       2m2.8s
Transferring:
 *                                 tdiary_02.odt: 80% /312.890M, 2.123M/s, 28s

2020/09/28 13:25:10 DEBUG : tdiary_02: Sending chunk 268435456 length 8388608
2020/09/28 13:25:13 DEBUG : tdiary_02: Sending chunk 276824064 length 8388608
2020/09/28 13:25:17 DEBUG : tdiary_02: Sending chunk 285212672 length 8388608
2020/09/28 13:25:21 DEBUG : tdiary_02: Sending chunk 293601280 length 8388608
2020/09/28 13:25:25 DEBUG : tdiary_02: Sending chunk 301989888 length 8388608
2020/09/28 13:25:28 DEBUG : tdiary_02: Sending chunk 310378496 length 8388608
2020/09/28 13:25:32 DEBUG : tdiary_02: Sending chunk 318767104 length 8388608
2020/09/28 13:25:36 DEBUG : tdiary_02: Sending chunk 327155712 length 932903
2020/09/28 13:25:37 ERROR : tdiary_02.odt: Failed to copy: googleapi: Error 400: Bad Request, badRequest
2020/09/28 13:25:37 ERROR : Attempt 1/3 failed with 1 errors and: googleapi: Error 400: Bad Request, badRequest
2020/09/28 13:25:38 DEBUG : tdiary_02.odt: Need to transfer - File not found at Destination
2020/09/28 13:25:39 DEBUG : tdiary_02: Sending chunk 0 length 8388608
2020/09/28 13:25:43 DEBUG : tdiary_02: Sending chunk 8388608 length 8388608
2020/09/28 13:25:46 DEBUG : tdiary_02: Sending chunk 16777216 length 8388608
2020/09/28 13:25:50 DEBUG : tdiary_02: Sending chunk 25165824 length 8388608
2020/09/28 13:25:54 DEBUG : tdiary_02: Sending chunk 33554432 length 8388608
2020/09/28 13:25:58 DEBUG : tdiary_02: Sending chunk 41943040 length 8388608
2020/09/28 13:26:01 DEBUG : tdiary_02: Sending chunk 50331648 length 8388608
2020/09/28 13:26:05 DEBUG : tdiary_02: Sending chunk 58720256 length 8388608
2020/09/28 13:26:08 INFO  : 
Transferred:   	  375.292M / 625.779 MBytes, 60%, 2.095 MBytes/s, ETA 1m59s
Transferred:            0 / 1, 0%
Elapsed time:       3m2.8s
Transferring:
 *                                 tdiary_02.odt: 19% /312.890M, 2.107M/s, 1m58s

2020/09/28 13:26:09 DEBUG : tdiary_02: Sending chunk 67108864 length 8388608
2020/09/28 13:26:12 DEBUG : tdiary_02: Sending chunk 75497472 length 8388608
2020/09/28 13:26:16 DEBUG : tdiary_02: Sending chunk 83886080 length 8388608
2020/09/28 13:26:20 DEBUG : tdiary_02: Sending chunk 92274688 length 8388608
2020/09/28 13:26:24 DEBUG : tdiary_02: Sending chunk 100663296 length 8388608
2020/09/28 13:26:27 DEBUG : tdiary_02: Sending chunk 109051904 length 8388608
2020/09/28 13:26:31 DEBUG : tdiary_02: Sending chunk 117440512 length 8388608
2020/09/28 13:26:35 DEBUG : tdiary_02: Sending chunk 125829120 length 8388608
2020/09/28 13:26:39 DEBUG : tdiary_02: Sending chunk 134217728 length 8388608
2020/09/28 13:26:42 DEBUG : tdiary_02: Sending chunk 142606336 length 8388608
2020/09/28 13:26:46 DEBUG : tdiary_02: Sending chunk 150994944 length 8388608
2020/09/28 13:26:50 DEBUG : tdiary_02: Sending chunk 159383552 length 8388608
2020/09/28 13:26:54 DEBUG : tdiary_02: Sending chunk 167772160 length 8388608
2020/09/28 13:26:58 DEBUG : tdiary_02: Sending chunk 176160768 length 8388608
2020/09/28 13:27:01 DEBUG : tdiary_02: Sending chunk 184549376 length 8388608
2020/09/28 13:27:05 DEBUG : tdiary_02: Sending chunk 192937984 length 8388608
2020/09/28 13:27:08 INFO  : 
Transferred:   	  503.292M / 625.779 MBytes, 80%, 2.105 MBytes/s, ETA 58s
Transferred:            0 / 1, 0%
Elapsed time:       4m2.8s
Transferring:
 *                                 tdiary_02.odt: 60% /312.890M, 2.128M/s, 57s

2020/09/28 13:27:09 DEBUG : tdiary_02: Sending chunk 201326592 length 8388608
2020/09/28 13:27:12 DEBUG : tdiary_02: Sending chunk 209715200 length 8388608
2020/09/28 13:27:16 DEBUG : tdiary_02: Sending chunk 218103808 length 8388608
2020/09/28 13:27:20 DEBUG : tdiary_02: Sending chunk 226492416 length 8388608
2020/09/28 13:27:24 DEBUG : tdiary_02: Sending chunk 234881024 length 8388608
2020/09/28 13:27:27 DEBUG : tdiary_02: Sending chunk 243269632 length 8388608
2020/09/28 13:27:31 DEBUG : tdiary_02: Sending chunk 251658240 length 8388608
2020/09/28 13:27:35 DEBUG : tdiary_02: Sending chunk 260046848 length 8388608
2020/09/28 13:27:39 DEBUG : tdiary_02: Sending chunk 268435456 length 8388608
2020/09/28 13:27:42 DEBUG : tdiary_02: Sending chunk 276824064 length 8388608
2020/09/28 13:27:46 DEBUG : tdiary_02: Sending chunk 285212672 length 8388608
2020/09/28 13:27:50 DEBUG : tdiary_02: Sending chunk 293601280 length 8388608
2020/09/28 13:27:53 DEBUG : tdiary_02: Sending chunk 301989888 length 8388608
2020/09/28 13:27:57 DEBUG : tdiary_02: Sending chunk 310378496 length 8388608
2020/09/28 13:28:01 DEBUG : tdiary_02: Sending chunk 318767104 length 8388608
2020/09/28 13:28:05 DEBUG : tdiary_02: Sending chunk 327155712 length 932903
2020/09/28 13:28:06 ERROR : tdiary_02.odt: Failed to copy: googleapi: Error 400: Bad Request, badRequest
2020/09/28 13:28:06 ERROR : Attempt 2/3 failed with 1 errors and: googleapi: Error 400: Bad Request, badRequest
2020/09/28 13:28:07 DEBUG : tdiary_02.odt: Need to transfer - File not found at Destination
2020/09/28 13:28:08 INFO  : 
Transferred:   	  625.779M / 938.669 MBytes, 67%, 2.094 MBytes/s, ETA 2m29s
Transferred:            0 / 1, 0%
Elapsed time:       5m2.8s
Transferring:
 *                                 tdiary_02.odt:  0% /312.890M, 0/s, -

2020/09/28 13:28:08 DEBUG : tdiary_02: Sending chunk 0 length 8388608
2020/09/28 13:28:11 DEBUG : tdiary_02: Sending chunk 8388608 length 8388608
2020/09/28 13:28:15 DEBUG : tdiary_02: Sending chunk 16777216 length 8388608
2020/09/28 13:28:19 DEBUG : tdiary_02: Sending chunk 25165824 length 8388608

philip_rhoades · September 28, 2020, 5:05am

Test #03

OK! This test was the same as #02 but without the ODT flags - and it was successful! So it does look like (so far) it is something to do with the processing of ODT files during sending - because it was happening on much smaller files as well (see other thread mentioned in the OP).

/usr/bin/rclone -L -vv copy --tpslimit 5 tdiary_02.odt gd:0_Relatives/Diary_02/ >t 2>&1

2020/09/28 14:58:58 DEBUG : rclone: Version "v1.53.1" starting with parameters ["/usr/bin/rclone" "-L" "-vv" "copy" "--tpslimit" "5" "tdiary_02.odt" "gd:0_Relatives/Diary_02/"]
2020/09/28 14:58:58 DEBUG : Creating backend with remote "tdiary_02.odt"
2020/09/28 14:58:58 DEBUG : Using config file from "/home/phr/.config/rclone/rclone.conf"
2020/09/28 14:58:58 INFO  : Starting HTTP transaction limiter: max 5 transactions/s with burst 1
2020/09/28 14:58:58 DEBUG : fs cache: adding new entry for parent of "tdiary_02.odt", "/home/phr/0_relatives/MumDiaries/Diary_02"
2020/09/28 14:58:58 DEBUG : Creating backend with remote "gd:0_Relatives/Diary_02/"
2020/09/28 14:58:58 DEBUG : gd: Loaded invalid token from config file - ignoring
2020/09/28 14:58:58 DEBUG : gd: Saved new token in config file
2020/09/28 14:58:59 DEBUG : Google drive root '0_Relatives/Diary_02': root_folder_id = "0AA-FsVZgP3GtUk9PVA" - save this in the config to speed up startup
2020/09/28 14:59:00 DEBUG : fs cache: renaming cache item "gd:0_Relatives/Diary_02/" to be canonical "gd:0_Relatives/Diary_02"
2020/09/28 14:59:00 DEBUG : tdiary_02.odt: Need to transfer - File not found at Destination
2020/09/28 14:59:02 DEBUG : tdiary_02.odt: Sending chunk 0 length 8388608
2020/09/28 14:59:05 DEBUG : tdiary_02.odt: Sending chunk 8388608 length 8388608
2020/09/28 14:59:09 DEBUG : tdiary_02.odt: Sending chunk 16777216 length 8388608
2020/09/28 14:59:13 DEBUG : tdiary_02.odt: Sending chunk 25165824 length 8388608
2020/09/28 14:59:17 DEBUG : tdiary_02.odt: Sending chunk 33554432 length 8388608
2020/09/28 14:59:21 DEBUG : tdiary_02.odt: Sending chunk 41943040 length 8388608
2020/09/28 14:59:25 DEBUG : tdiary_02.odt: Sending chunk 50331648 length 8388608
2020/09/28 14:59:28 DEBUG : tdiary_02.odt: Sending chunk 58720256 length 8388608
2020/09/28 14:59:32 DEBUG : tdiary_02.odt: Sending chunk 67108864 length 8388608
2020/09/28 14:59:36 DEBUG : tdiary_02.odt: Sending chunk 75497472 length 8388608
2020/09/28 14:59:40 DEBUG : tdiary_02.odt: Sending chunk 83886080 length 8388608
2020/09/28 14:59:44 DEBUG : tdiary_02.odt: Sending chunk 92274688 length 8388608
2020/09/28 14:59:47 DEBUG : tdiary_02.odt: Sending chunk 100663296 length 8388608
2020/09/28 14:59:51 DEBUG : tdiary_02.odt: Sending chunk 109051904 length 8388608
2020/09/28 14:59:55 DEBUG : tdiary_02.odt: Sending chunk 117440512 length 8388608
2020/09/28 14:59:59 DEBUG : tdiary_02.odt: Sending chunk 125829120 length 8388608
2020/09/28 15:00:00 INFO  : 
Transferred:   	  123.402M / 312.890 MBytes, 39%, 2.069 MBytes/s, ETA 1m31s
Transferred:            0 / 1, 0%
Elapsed time:       1m2.0s
Transferring:
 *                                 tdiary_02.odt: 39% /312.890M, 2.102M/s, 1m30s

2020/09/28 15:00:02 DEBUG : tdiary_02.odt: Sending chunk 134217728 length 8388608
2020/09/28 15:00:06 DEBUG : tdiary_02.odt: Sending chunk 142606336 length 8388608
2020/09/28 15:00:10 DEBUG : tdiary_02.odt: Sending chunk 150994944 length 8388608
2020/09/28 15:00:14 DEBUG : tdiary_02.odt: Sending chunk 159383552 length 8388608
2020/09/28 15:00:17 DEBUG : tdiary_02.odt: Sending chunk 167772160 length 8388608
2020/09/28 15:00:21 DEBUG : tdiary_02.odt: Sending chunk 176160768 length 8388608
2020/09/28 15:00:25 DEBUG : tdiary_02.odt: Sending chunk 184549376 length 8388608
2020/09/28 15:00:29 DEBUG : tdiary_02.odt: Sending chunk 192937984 length 8388608
2020/09/28 15:00:33 DEBUG : tdiary_02.odt: Sending chunk 201326592 length 8388608
2020/09/28 15:00:36 DEBUG : tdiary_02.odt: Sending chunk 209715200 length 8388608
2020/09/28 15:00:40 DEBUG : tdiary_02.odt: Sending chunk 218103808 length 8388608
2020/09/28 15:00:44 DEBUG : tdiary_02.odt: Sending chunk 226492416 length 8388608
2020/09/28 15:00:48 DEBUG : tdiary_02.odt: Sending chunk 234881024 length 8388608
2020/09/28 15:00:51 DEBUG : tdiary_02.odt: Sending chunk 243269632 length 8388608
2020/09/28 15:00:55 DEBUG : tdiary_02.odt: Sending chunk 251658240 length 8388608
2020/09/28 15:00:59 DEBUG : tdiary_02.odt: Sending chunk 260046848 length 8388608
2020/09/28 15:01:00 INFO  : 
Transferred:   	  250.715M / 312.890 MBytes, 80%, 2.096 MBytes/s, ETA 29s
Transferred:            0 / 1, 0%
Elapsed time:       2m2.0s
Transferring:
 *                                 tdiary_02.odt: 80% /312.890M, 2.107M/s, 29s

2020/09/28 15:01:03 DEBUG : tdiary_02.odt: Sending chunk 268435456 length 8388608
2020/09/28 15:01:06 DEBUG : tdiary_02.odt: Sending chunk 276824064 length 8388608
2020/09/28 15:01:10 DEBUG : tdiary_02.odt: Sending chunk 285212672 length 8388608
2020/09/28 15:01:14 DEBUG : tdiary_02.odt: Sending chunk 293601280 length 8388608
2020/09/28 15:01:18 DEBUG : tdiary_02.odt: Sending chunk 301989888 length 8388608
2020/09/28 15:01:21 DEBUG : tdiary_02.odt: Sending chunk 310378496 length 8388608
2020/09/28 15:01:25 DEBUG : tdiary_02.odt: Sending chunk 318767104 length 8388608
2020/09/28 15:01:29 DEBUG : tdiary_02.odt: Sending chunk 327155712 length 932903
2020/09/28 15:01:31 DEBUG : tdiary_02.odt: MD5 = d4c2210f9f39eba2affc902b460eef90 OK
2020/09/28 15:01:31 INFO  : tdiary_02.odt: Copied (new)
2020/09/28 15:01:31 INFO  : 
Transferred:   	  312.890M / 312.890 MBytes, 100%, 2.074 MBytes/s, ETA 0s
Transferred:            1 / 1, 100%
Elapsed time:      2m33.3s

2020/09/28 15:01:31 DEBUG : 5 go routines active

ncw · September 28, 2020, 11:30am

Yes I think for reasons unknown, Google's ODT import is blowing up. Whether that is for rate limiting or some other reason, I don't know.

philip_rhoades · September 28, 2020, 11:35am

I think I just messed up Test #04 - trying again . .

philip_rhoades · September 28, 2020, 11:42am

Test #04

Still a problem - does the more verbose log help?

/usr/bin/rclone -L -vv copy --tpslimit 1 --dump responses --checkers 1 --transfers 1 --drive-formats "ods,odt" --drive-import-formats "ods,odt" ./tdiary_02.odt gd:0_Relatives/Diary_02/ >t 2>&1

2020/09/28 21:41:28 DEBUG : rclone: Version "v1.53.1" starting with parameters ["/usr/bin/rclone" "-L" "-vv" "copy" "--tpslimit" "1" "--dump" "responses" "--checkers" "1" "--transfers" "1" "--drive-formats" "ods,odt" "--drive-import-formats" "ods,odt" "./tdiary_02.odt" "gd:0_Relatives/Diary_02/"]
2020/09/28 21:41:28 DEBUG : Creating backend with remote "./tdiary_02.odt"
2020/09/28 21:41:28 DEBUG : Using config file from "/home/phr/.config/rclone/rclone.conf"
2020/09/28 21:41:28 INFO  : Starting HTTP transaction limiter: max 1 transactions/s with burst 1
2020/09/28 21:41:28 DEBUG : fs cache: adding new entry for parent of "./tdiary_02.odt", "/home/phr/0_relatives/MumDiaries/Diary_02"
2020/09/28 21:41:28 DEBUG : Creating backend with remote "gd:0_Relatives/Diary_02/"
2020/09/28 21:41:28 DEBUG : You have specified to dump information. Please be noted that the Accept-Encoding as shown may not be correct in the request and the response may not show Content-Encoding if the go standard libraries auto gzip encoding was in effect. In this case the body of the request will be gunzipped before showing it.
2020/09/28 21:41:28 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2020/09/28 21:41:28 DEBUG : HTTP REQUEST (req 0xc00042c900)
2020/09/28 21:41:28 DEBUG : GET /drive/v3/files/root?alt=json&fields=id&prettyPrint=false&supportsAllDrives=true HTTP/1.1
Host: www.googleapis.com
User-Agent: rclone/v1.53.1
Authorization: XXXX
X-Goog-Api-Client: gl-go/1.15.0 gdcl/20200616
Accept-Encoding: gzip

2020/09/28 21:41:28 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2020/09/28 21:41:29 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2020/09/28 21:41:29 DEBUG : HTTP RESPONSE (req 0xc00042c900)
2020/09/28 21:41:29 DEBUG : HTTP/1.1 200 OK
Transfer-Encoding: chunked
Alt-Svc: h3-Q050=":443"; ma=2592000,h3-29=":443"; ma=2592000,h3-27=":443"; ma=2592000,h3-T051=":443"; ma=2592000,h3-T050=":443"; ma=2592000,h3-Q046=":443"; ma=2592000,h3-Q043=":443"; ma=2592000,quic=":443"; ma=2592000; v="46,43"
Cache-Control: private, max-age=0, must-revalidate, no-transform
Content-Security-Policy: frame-ancestors 'self'
Content-Type: application/json; charset=UTF-8
Date: Mon, 28 Sep 2020 11:41:28 GMT
Expires: Mon, 28 Sep 2020 11:41:28 GMT
Server: GSE
Vary: Origin
Vary: X-Origin
X-Content-Type-Options: nosniff
X-Frame-Options: SAMEORIGIN
X-Xss-Protection: 1; mode=block

1c
{"id":"0AA-FsVZgP3GtUk9PVA"}
0

2020/09/28 21:41:29 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2020/09/28 21:41:29 DEBUG : Google drive root '0_Relatives/Diary_02': root_folder_id = "0AA-FsVZgP3GtUk9PVA" - save this in the config to speed up startup
2020/09/28 21:41:29 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2020/09/28 21:41:29 DEBUG : HTTP REQUEST (req 0xc0000f6700)
2020/09/28 21:41:29 DEBUG : GET /drive/v3/files?alt=json&fields=files%28id%2Cname%2Csize%2Cmd5Checksum%2Ctrashed%2CexplicitlyTrashed%2CmodifiedTime%2CcreatedTime%2CmimeType%2Cparents%2CwebViewLink%2CshortcutDetails%2CexportLinks%29%2CnextPageToken%2CincompleteSearch&includeItemsFromAllDrives=true&pageSize=1000&prettyPrint=false&q=trashed%3Dfalse+and+%28%270AA-FsVZgP3GtUk9PVA%27+in+parents%29+and+%28name%3D%270_Relatives%27%29+and+%28mimeType%3D%27application%2Fvnd.google-apps.folder%27+or+mimeType%3D%27application%2Fvnd.google-apps.shortcut%27%29&supportsAllDrives=true HTTP/1.1
Host: www.googleapis.com
User-Agent: rclone/v1.53.1
Authorization: XXXX
X-Goog-Api-Client: gl-go/1.15.0 gdcl/20200616
Accept-Encoding: gzip

2020/09/28 21:41:29 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2020/09/28 21:41:30 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2020/09/28 21:41:30 DEBUG : HTTP RESPONSE (req 0xc0000f6700)
2020/09/28 21:41:30 DEBUG : HTTP/1.1 200 OK
Transfer-Encoding: chunked
Alt-Svc: h3-Q050=":443"; ma=2592000,h3-29=":443"; ma=2592000,h3-27=":443"; ma=2592000,h3-T051=":443"; ma=2592000,h3-T050=":443"; ma=2592000,h3-Q046=":443"; ma=2592000,h3-Q043=":443"; ma=2592000,quic=":443"; ma=2592000; v="46,43"
Cache-Control: private, max-age=0, must-revalidate, no-transform
Content-Security-Policy: frame-ancestors 'self'
Content-Type: application/json; charset=UTF-8
Date: Mon, 28 Sep 2020 11:41:29 GMT
Expires: Mon, 28 Sep 2020 11:41:29 GMT
Server: GSE
Vary: Origin
Vary: X-Origin
X-Content-Type-Options: nosniff
X-Frame-Options: SAMEORIGIN
X-Xss-Protection: 1; mode=block

18c
{"incompleteSearch":false,"files":[{"id":"1LZINVWbBpXj46TQt7mik0UZ4U2pSwQj9","name":"0_Relatives","mimeType":"application/vnd.google-apps.folder","trashed":false,"explicitlyTrashed":false,"parents":["0AA-FsVZgP3GtUk9PVA"],"webViewLink":"https://drive.google.com/drive/folders/1LZINVWbBpXj46TQt7mik0UZ4U2pSwQj9","createdTime":"2020-09-18T11:20:18.134Z","modifiedTime":"2020-09-18T11:20:18.134Z"}]}
0

2020/09/28 21:41:30 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2020/09/28 21:41:30 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2020/09/28 21:41:30 DEBUG : HTTP REQUEST (req 0xc00021d800)
2020/09/28 21:41:30 DEBUG : GET /drive/v3/about?alt=json&fields=exportFormats%2CimportFormats&prettyPrint=false HTTP/1.1
Host: www.googleapis.com
User-Agent: rclone/v1.53.1
Authorization: XXXX
X-Goog-Api-Client: gl-go/1.15.0 gdcl/20200616
Accept-Encoding: gzip

2020/09/28 21:41:30 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>

philip_rhoades · September 28, 2020, 11:47am

There is something weird going on here - I saw a lot more stuff when I was tailing but most of that seems to be missing now . . maybe it wasn't scrolling after all but the screen was being re-written?

ncw · September 28, 2020, 3:40pm

That doesn't appear to have the ERROR in

You can use --log-file rclone.log to capture the log file and attach that if it is easier.

philip_rhoades · September 28, 2020, 3:57pm

Test #05

/usr/bin/rclone -L -vv copy --tpslimit 1 --dump responses --checkers 1 --transfers 1 --drive-formats "ods,odt" --drive-import-formats "ods,odt" --log-file rclone.log ./tdiary_02.odt gd:0_Relatives/Diary_02/

Whoa! - that created a different sized file! - . . and it is too big to insert here by about 10x - can I share it with you on Drive or somewhere?

Thanks,
Phil.

Animosity022 · September 28, 2020, 4:10pm

You can use pastebin/google drive link/any of those options would be fine.

philip_rhoades · September 28, 2020, 4:18pm

ncw · September 28, 2020, 5:52pm

Thanks for that!

The error body is the entirely unenlightening

{
 "error": {
  "errors": [
   {
    "domain": "global",
    "reason": "badRequest",
    "message": "Bad Request"
   }
  ],
  "code": 400,
  "message": "Bad Request"
 }
}

So I think it is something about that file google doesn't like, or the rate limiting.

philip_rhoades · September 28, 2020, 5:55pm

I can try again with a one page file but I think the same thing happens - well actually it is a little different - the first one seems to work if I am copying a whole dir - but the second and later ones fail . .

ncw · September 29, 2020, 2:24pm

That is probably a sign of rate limiting...

Did you try setting --transfers 1 so rclone only does one import at a time?

philip_rhoades · October 14, 2020, 5:01am

Sorry about the slow response:

Yes I did but my script copying one file at a time started working so you were probably right that there was some temporary Google problem. However, the final part of the puzzle for the orginal post:

was that I had to install a Google Drive third party app: "Merge Google Documents" which allowed me to concatenate the individual files into one big doc - although if there were more than 80 smaller docs, I had to do it in more than one step . .

ncw · October 14, 2020, 3:17pm

Great - glad you got it sorted

system · December 14, 2020, 11:17am

This topic was automatically closed 60 days after the last reply. New replies are no longer allowed.