Mount point disappear while copying files

Suspected Bug
1

What is the problem you are having with rclone?

Mount point disappear when i tried to use "copyto" or "move" command to copy files to OneDrive

I mounted my onedrive with this option
rclone mount onedrive_KMS: /Shared_KMS --allow-non-empty --allow-other --daemon

What is your rclone version (output from rclone version)

it happened in v1.55 and 1.56 beta

rclone v1.56.0-beta.5405.6366d3dfc
- os/version: ubuntu 20.04 (64 bit)
- os/kernel: 5.4.0-1041-gcp (x86_64)
- os/type: linux
- os/arch: amd64
- go/version: go1.16.3
- go/linking: static
- go/tags: none

Which OS you are using and how many bits (eg Windows 7, 64 bit)

Distributor ID: Ubuntu
Description: Ubuntu 20.04.2 LTS
Release: 20.04
Codename: focal

5.4.0-1041-gcp #44-Ubuntu

Which cloud storage system are you using? (eg Google Drive)

OneDrvie

The command you were trying to run (eg rclone copy /tmp remote:tmp)

rclone move -vv "$FROM" "$TO" --retries 1 --delete-after --log-file=$LOGFILE

The rclone config contents with secrets removed.

[onedrive_KMS]
type = onedrive
region = global
token = {"access_token":"!!!!!!token value!!!!!"}
drive_id = !!!!!!drive_id!!!!
drive_type = business

A log from the command with the -vv flag

16.04.2021 03:00:00 RCLONE UPLOAD STARTED
2021/04/16 03:00:00 DEBUG : Using config file from "/root/.config/rclone/rclone.conf"
2021/04/16 03:00:00 DEBUG : rclone: Version "v1.56.0-beta.5405.6366d3dfc" starting with parameters ["rclone" "move" "/KMS" "/Shared_KMS" "--retries" "1" "--delete-after" "--log-file=/var/log/rclone-upload.log" "--log-level" "DEBUG"]
2021/04/16 03:00:00 DEBUG : Creating backend with remote "/KMS"
2021/04/16 03:00:00 DEBUG : Creating backend with remote "/Shared_KMS"
2021/04/16 03:00:00 DEBUG : Local file system at /Shared_KMS: Using server-side directory move
2021/04/16 03:00:00 INFO  : Local file system at /Shared_KMS: Server side directory move failed - fallback to file moves: can't copy directory - destination already exists
2021/04/16 03:00:00 DEBUG : Local file system at /Shared_KMS: Waiting for checks to finish
2021/04/16 03:00:00 DEBUG : Local file system at /Shared_KMS: Waiting for transfers to finish
2021/04/16 03:00:00 DEBUG : BBBBBBBBB.mkv: Can't move: rename /KMS/BBBBBBBBB.mkv /Shared_KMS/BBBBBBBB.mkv: invalid cross-device link: trying copy
2021/04/16 03:00:00 DEBUG : BBBBBBBB.mkv: Can't move, switching to copy
2021/04/16 03:00:00 DEBUG : AAAAAAAA.mkv: Can't move: rename /KMS/AAAAAAAA.mkv /Shared_KMS/AAAAAAAA.mkv: invalid cross-device link: trying copy
2021/04/16 03:00:00 DEBUG : AAAAAAAA.mkv: Can't move, switching to copy
2021/04/16 03:00:00 DEBUG : preAllocate: got error on fallocate, trying combination 1/2: operation not supported
2021/04/16 03:00:00 DEBUG : preAllocate: got error on fallocate, trying combination 2/2: operation not supported

2021/04/16 03:07:01 INFO  : 
Transferred:        6.218G / 7.156 GBytes, 87%, 15.128 MBytes/s, ETA 1m3s
Checks:                 0 / 2, 0%
Transferred:            0 / 2, 0%
Elapsed time:       7m0.9s
Checking:
Transferring:
 * BBBBBBBB.mkv: 82% /3.727G, 6.179M/s, 1m45s
 * AAAAAAAAAA.mkv: 91% /3.429G, 6.060M/s, 51s
2021/04/16 03:08:02 INFO  : 
Transferred:        6.870G / 7.156 GBytes, 96%, 14.614 MBytes/s, ETA 20s
Checks:                 0 / 2, 0%
Transferred:            0 / 2, 0%
Elapsed time:       8m1.5s
Checking:
Transferring:
 * BBBBBBBB.mkv: 92% /3.727G, 5.979M/s, 49s
 * AAAAAAAAAA.mkv:100% /3.429G, 3.558M/s, 0s

2021/04/16 03:55:19 NOTICE: AAAAAAAA.mkv: Removing partially written file on error: close /Shared_KMS/AAAAAAAA.mkv: software caused connection abort
2021/04/16 03:55:19 NOTICE: BBBBBBBB.mkv: Removing partially written file on error: write /Shared_KMS/BBBBBBBB.mkv: software caused connection abort
2021/04/16 03:55:20 ERROR : BBBBBBBB.mkv: Failed to remove partially written file: remove /Shared_KMS/BBBBBBBB.mkv: transport endpoint is not connected
2021/04/16 03:55:20 ERROR : AAAAAAAAA.mkv: Failed to remove partially written file: remove /Shared_KMS/AAAAAAAA.mkv: transport endpoint is not connected
2021/04/16 03:55:21 INFO  : 
Transferred:        6.964G / 7.156 GBytes, 97%, 12.795 MBytes/s, ETA 15s
Checks:                 0 / 2, 0%
Transferred:            0 / 2, 0%
Elapsed time:      9m17.9s
Checking:

Transferring:
 * BBBBBBBB.mkv: 94% /3.727G, 103.198k/s, 32m29s
 * AAAAAAAAAA.mkv:100% /3.429G, 22.243k/s, 0s
2021/04/16 03:55:22 INFO  : 
Transferred:        6.964G / 7.156 GBytes, 97%, 2.147 MBytes/s, ETA 1m31s
Checks:                 0 / 2, 0%
Transferred:            0 / 2, 0%
Elapsed time:     55m21.2s
Checking:
Transferring:
 * BBBBBBBB.mkv: 94% /3.727G, 85.032k/s, 39m26s
 * AAAAAAAAAA.mkv:100% /3.429G, 20.854k/s, 0s
2021/04/16 03:55:22 DEBUG : BBBBBBBB.mkv: Received error: write /Shared_KMS/BBBBBBBB.mkv: software caused connection abort - low level retry 1/10
2021/04/16 03:55:22 DEBUG : AAAAAAAA.mkv: Received error: close /Shared_KMS/AAAAAAAA.mkv: software caused connection abort - low level retry 1/10
2021/04/16 03:55:23 ERROR : AAAAAAAA.mkv: Failed to copy: mkdir /Shared_KMS: file exists
2021/04/16 03:55:23 ERROR : BBBBBBBB.mkv: Failed to copy: mkdir /Shared_KMS: file exists
2021/04/16 03:55:23 ERROR : AAAAAAAA.mkv: Not deleting source as copy failed: mkdir /Shared_KMS: file exists
2021/04/16 03:55:23 ERROR : BBBBBBBB.mkv: Not deleting source as copy failed: mkdir /Shared_KMS: file exists
2021/04/16 03:55:24 ERROR : Attempt 1/1 failed with 2 errors and: mkdir /Shared_KMS: file exists
2021/04/16 03:55:24 INFO  : 
Transferred:        6.964G / 6.964 GBytes, 100%, 2.146 MBytes/s, ETA 0s
Errors:                 2 (retrying may help)
Checks:                 2 / 2, 100%
Elapsed time:     55m23.5s
2021/04/16 03:55:24 DEBUG : 4 go routines active
2021/04/16 03:55:24 Failed to move with 2 errors: last error was: mkdir /Shared_KMS: file exists
16.04.2021 03:55:24 RCLONE UPLOAD FINISHED IN 3324 SECONDS
2

You'd need to provide the actual mount command / mount debug log to see why it's stopping.

3

I can't see what is happening to the mount with only the rclone move log - can you supply the mount log too?

4

I'm sure that it is a right log you want.
this is a syslog when my RCLONE UPLOAD failed.
A google VM got hung when file copying reached at 100% and copying is stopped automatically when /Shared_KMS Mount Point disappeared.
it happens in OneDrive only. Google drive is working fine.
my config is so simple and i don't know why it is stopping at 100% everytime.
please help me :sob:

Apr 16 03:55:17 angel collectd[682]: write_gcm: curl_easy_perform() failed: Timeout was reached
Apr 16 03:55:19 angel collectd[682]: write_gcm: Error -1 from wg_curl_get_or_post (Timeseries)
Apr 16 03:55:19 angel snapd[489]: #011/build/snapd/parts/snapd-deb/build/_build/src/github.com/snapcore/snapd/overlord/state/state.go:143 +0x2f
Apr 16 03:55:19 angel snapd[489]: github.com/snapcore/snapd/overlord/standby.(*StandbyOpinions).CanStandby(0xc420485360, 0x4a817c8000)
Apr 16 03:55:19 angel snapd[489]: #011/build/snapd/parts/snapd-deb/build/_build/src/github.com/snapcore/snapd/overlord/standby/standby.go:55 +0x52
Apr 16 03:55:19 angel snapd[489]: github.com/snapcore/snapd/overlord/standby.(*StandbyOpinions).Start.func1(0xc420485360)
Apr 16 03:55:19 angel snapd[489]: #011/build/snapd/parts/snapd-deb/build/_build/src/github.com/snapcore/snapd/overlord/standby/standby.go:101 +0x8f
Apr 16 03:55:19 angel snapd[489]: created by github.com/snapcore/snapd/overlord/standby.(*StandbyOpinions).Start
Apr 16 03:55:19 angel snapd[489]: #011/build/snapd/parts/snapd-deb/build/_build/src/github.com/snapcore/snapd/overlord/standby/standby.go:97 +0xb6
Apr 16 03:55:19 angel snapd[489]: goroutine 24 [runnable]:
Apr 16 03:55:19 angel snapd[489]: reflect.(*rtype).ptrTo(0x557d8e00a5e0, 0x557d8e00a5e0)
Apr 16 03:55:19 angel snapd[489]: #011/usr/lib/go-1.10/src/reflect/type.go:1425 +0x3de
Apr 16 03:55:19 angel snapd[489]: reflect.New(0x557d8e193440, 0x557d8e00a5e0, 0x557d8d2e10d5, 0xc4204f1590, 0x557d8d2789c1)
Apr 16 03:55:19 angel snapd[489]: #011/usr/lib/go-1.10/src/reflect/value.go:2189 +0x7a
Apr 16 03:55:19 angel snapd[489]: reflect.makeString(0x0, 0xc4205a40c0, 0x5, 0x557d8e193440, 0x557d8e00a5e0, 0x5, 0x557d8e00a8a0, 0xc4203fc140)
Apr 16 03:55:19 angel snapd[489]: #011/usr/lib/go-1.10/src/reflect/value.go:2382 +0x3b
Apr 16 03:55:19 angel snapd[489]: reflect.cvtBytesString(0x557d8dffce00, 0xc4205280e0, 0x97, 0x557d8e193440, 0x557d8e00a5e0, 0x557d8e060060, 0x0, 0x16)
Apr 16 03:55:19 angel snapd[489]: #011/usr/lib/go-1.10/src/reflect/value.go:2459 +0xbc
Apr 16 03:55:19 angel snapd[489]: reflect.Value.Convert(0x557d8dffce00, 0xc4205280e0, 0x97, 0x557d8e193440, 0x557d8e00a5e0, 0x16, 0x557d8e060001, 0xc420378080)
Apr 16 03:55:19 angel snapd[489]: #011/usr/lib/go-1.10/src/reflect/value.go:2249 +0xeb
Apr 16 03:55:19 angel snapd[489]: encoding/json.(*decodeState).object(0xc4203fc120, 0x557d8dfe8a00, 0xc4203784d0, 0x16)
Apr 16 03:55:19 angel snapd[489]: #011/usr/lib/go-1.10/src/encoding/json/decode.go:786 +0xb01
Apr 16 03:55:19 angel snapd[489]: encoding/json.(*decodeState).value(0xc4203fc120, 0x557d8dfe8a00, 0xc4203784d0, 0x16)
Apr 16 03:55:19 angel snapd[489]: #011/usr/lib/go-1.10/src/encoding/json/decode.go:408 +0x2d5
Apr 16 03:55:19 angel snapd[489]: encoding/json.(*decodeState).unmarshal(0xc4203fc120, 0x557d8dfe8a00, 0xc4203784d0, 0x0, 0x0)
Apr 16 03:55:19 angel snapd[489]: #011/usr/lib/go-1.10/src/encoding/json/decode.go:189 +0x1e9
Apr 16 03:55:19 angel snapd[489]: encoding/json.Unmarshal(0xc420594000, 0x2b8b, 0x5c9b, 0x557d8dfe8a00, 0xc4203784d0, 0x557d8d25ca2b, 0x8)
Apr 16 03:55:19 angel systemd[1]: snapd.service: Killing process 489 (snapd) with signal SIGABRT.
Apr 16 03:55:19 angel collectd[682]: write_gcm: wg_transmit_unique_segment failed.
Apr 16 03:55:19 angel snapd[489]: #011/usr/lib/go-1.10/src/encoding/json/decode.go:108 +0x14a
Apr 16 03:55:19 angel snapd[489]: github.com/snapcore/snapd/overlord/state.customData.get(0xc420385b90, 0x557d8daaef45, 0x5, 0x557d8dfe8a00, 0xc4203784d0, 0x1, 0xc4203784d0)
Apr 16 03:55:19 angel snapd[489]: #011/build/snapd/parts/snapd-deb/build/_build/src/github.com/snapcore/snapd/overlord/state/state.go:53 +0xa6
Apr 16 03:55:19 angel snapd[489]: github.com/snapcore/snapd/overlord/state.(*State).Get(0xc4203810e0, 0x557d8daaef45, 0x5, 0x557d8dfe8a00, 0xc4203784d0, 0xc420ef3b60, 0x557d8d243ada)
Apr 16 03:55:19 angel snapd[489]: #011/build/snapd/parts/snapd-deb/build/_build/src/github.com/snapcore/snapd/overlord/state/state.go:333 +0x67
Apr 16 03:55:19 angel snapd[489]: github.com/snapcore/snapd/overlord/snapstate.Get(0xc4203810e0, 0x557d8dab641f, 0xb, 0xc420640000, 0x557d8e5b6480, 0xc420ef3bb0)
Apr 16 03:55:19 angel snapd[489]: #011/build/snapd/parts/snapd-deb/build/_build/src/github.com/snapcore/snapd/overlord/snapstate/snapstate.go:2446 +0xd8
Apr 16 03:55:19 angel snapd[489]: github.com/snapcore/snapd/overlord/snapstate.(*SnapManager).ensureUbuntuCoreTransition(0xc420297720, 0x0, 0x0)
Apr 16 03:55:19 angel snapd[489]: #011/build/snapd/parts/snapd-deb/build/_build/src/github.com/snapcore/snapd/overlord/snapstate/snapmgr.go:728 +0xc3
Apr 16 03:55:19 angel snapd[489]: github.com/snapcore/snapd/overlord/snapstate.(*SnapManager).Ensure(0xc420297720, 0x0, 0x0)
Apr 16 03:55:19 angel snapd[489]: #011/build/snapd/parts/snapd-deb/build/_build/src/github.com/snapcore/snapd/overlord/snapstate/snapmgr.go:868 +0xc9
Apr 16 03:55:19 angel snapd[489]: github.com/snapcore/snapd/overlord.(*StateEngine).Ensure(0xc42040a3f0, 0x0, 0x0)
Apr 16 03:55:19 angel snapd[489]: #011/build/snapd/parts/snapd-deb/build/_build/src/github.com/snapcore/snapd/overlord/stateengine.go:148 +0x117
Apr 16 03:55:19 angel snapd[489]: github.com/snapcore/snapd/overlord.(*Overlord).Loop.func1(0x0, 0x0)
Apr 16 03:55:19 angel snapd[489]: #011/build/snapd/parts/snapd-deb/build/_build/src/github.com/snapcore/snapd/overlord/overlord.go:434 +0x66
Apr 16 03:55:19 angel snapd[489]: github.com/snapcore/snapd/vendor/gopkg.in/tomb%2ev2.(*Tomb).run(0xc4202970e0, 0xc420513600)
Apr 16 03:55:19 angel snapd[489]: #011/build/snapd/parts/snapd-deb/build/_build/src/github.com/snapcore/snapd/vendor/gopkg.in/tomb.v2/tomb.go:163 +0x2d
Apr 16 03:55:19 angel snapd[489]: created by github.com/snapcore/snapd/vendor/gopkg.in/tomb%2ev2.(*Tomb).Go
Apr 16 03:55:19 angel snapd[489]: #011/build/snapd/parts/snapd-deb/build/_build/src/github.com/snapcore/snapd/vendor/gopkg.in/tomb.v2/tomb.go:159 +0xbb
Apr 16 03:55:19 angel snapd[489]: goroutine 25 [IO wait, 65 minutes]:
Apr 16 03:55:19 angel collectd[682]: write_gcm: wg_transmit_unique_segments failed. Flushing.
Apr 16 03:55:19 angel snapd[489]: internal/poll.runtime_pollWait(0x7fd4c069ee30, 0x72, 0x0)
Apr 16 03:55:19 angel snapd[489]: #011/usr/lib/go-1.10/src/runtime/netpoll.go:173 +0x59
Apr 16 03:55:19 angel snapd[489]: internal/poll.(*pollDesc).wait(0xc4203b6e18, 0x72, 0xc42007df00, 0x0, 0x0)
Apr 16 03:55:19 angel snapd[489]: #011/usr/lib/go-1.10/src/internal/poll/fd_poll_runtime.go:85 +0x9d
Apr 16 03:55:19 angel snapd[489]: internal/poll.(*pollDesc).waitRead(0xc4203b6e18, 0xffffffffffffff00, 0x0, 0x0)
Apr 16 03:55:19 angel snapd[489]: #011/usr/lib/go-1.10/src/internal/poll/fd_poll_runtime.go:90 +0x3f
Apr 16 03:55:19 angel snapd[489]: internal/poll.(*FD).Accept(0xc4203b6e00, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
Apr 16 03:55:19 angel snapd[489]: #011/usr/lib/go-1.10/src/internal/poll/fd_unix.go:372 +0x1aa
Apr 16 03:55:19 angel snapd[489]: net.(*netFD).accept(0xc4203b6e00, 0xc42005fdd0, 0xc420381710, 0x557d8e17aa48)
Apr 16 03:55:19 angel snapd[489]: #011/usr/lib/go-1.10/src/net/fd_unix.go:238 +0x44
Apr 16 03:55:19 angel snapd[489]: net.(*UnixListener).accept(0xc42047e120, 0x557d8da9a510, 0xc42028cc90, 0xc4203848a0)
Apr 16 03:55:19 angel snapd[489]: #011/usr/lib/go-1.10/src/net/unixsock_posix.go:162 +0x34
Apr 16 03:55:19 angel snapd[489]: net.(*UnixListener).Accept(0xc42047e120, 0xc4205c2060, 0xc42005fe50, 0x557d8daa520a, 0xc42028cc90)
Apr 16 03:55:19 angel snapd[489]: #011/usr/lib/go-1.10/src/net/unixsock.go:253 +0x4b
Apr 16 03:55:19 angel snapd[489]: github.com/snapcore/snapd/daemon.(*ucrednetListener).Accept(0xc42047e180, 0x0, 0x0, 0x0, 0x0)
Apr 16 03:55:19 angel snapd[489]: #011/build/snapd/parts/snapd-deb/build/_build/src/github.com/snapcore/snapd/daemon/ucrednet.go:110 +0x4f
Apr 16 03:55:19 angel snapd[489]: net/http.(*Server).Serve(0xc420432dd0, 0x557d8e18a6e0, 0xc42047e180, 0x0, 0x0)
Apr 16 03:55:19 angel snapd[489]: #011/usr/lib/go-1.10/src/net/http/server.go:2773 +0x1a7
Apr 16 03:55:19 angel snapd[489]: github.com/snapcore/snapd/daemon.(*Daemon).Start.func1(0x0, 0x0)
Apr 16 03:55:19 angel snapd[489]: #011/build/snapd/parts/snapd-deb/build/_build/src/github.com/snapcore/snapd/daemon/daemon.go:478 +0x58
Apr 16 03:55:19 angel snapd[489]: github.com/snapcore/snapd/vendor/gopkg.in/tomb%2ev2.(*Tomb).run(0xc420146f30, 0xc42028ccd0)
Apr 16 03:55:19 angel snapd[489]: #011/build/snapd/parts/snapd-deb/build/_build/src/github.com/snapcore/snapd/vendor/gopkg.in/tomb.v2/tomb.go:163 +0x2d
Apr 16 03:55:19 angel snapd[489]: created by github.com/snapcore/snapd/vendor/gopkg.in/tomb%2ev2.(*Tomb).Go
Apr 16 03:55:19 angel snapd[489]: #011/build/snapd/parts/snapd-deb/build/_build/src/github.com/snapcore/snapd/vendor/gopkg.in/tomb.v2/tomb.go:159 +0xbb
Apr 16 03:55:19 angel snapd[489]: goroutine 26 [runnable]:
Apr 16 03:55:19 angel snapd[489]: net.(*conn).Write(0xc4203784f8, 0xc420ef3eb0, 0xa, 0x20, 0xa, 0x20, 0x0)
Apr 16 03:55:19 angel snapd[489]: #011/usr/lib/go-1.10/src/net/net.go:184 +0x229
Apr 16 03:55:19 angel snapd[489]: github.com/snapcore/snapd/systemd.SdNotify(0x557d8dab4bbf, 0xa, 0x0, 0x0)
Apr 16 03:55:19 angel collectd[682]: write_gcm: curl_easy_perform() failed: Timeout was reached
Apr 16 03:55:19 angel snapd[489]: #011/build/snapd/parts/snapd-deb/build/_build/src/github.com/snapcore/snapd/systemd/sdnotify.go:57 +0x1af
Apr 16 03:55:19 angel snapd[489]: main.runWatchdog.func1(0xc420485450, 0xc420146ee0)
Apr 16 03:55:19 angel snapd[489]: #011/build/snapd/parts/snapd-deb/build/_build/src/github.com/snapcore/snapd/cmd/snapd/main.go:98 +0x4c
Apr 16 03:55:19 angel snapd[489]: created by main.runWatchdog
Apr 16 03:55:19 angel snapd[489]: #011/build/snapd/parts/snapd-deb/build/_build/src/github.com/snapcore/snapd/cmd/snapd/main.go:91 +0x22d
Apr 16 03:55:19 angel snapd[489]: goroutine 27 [IO wait, 65 minutes]:
Apr 16 03:55:19 angel snapd[489]: internal/poll.runtime_pollWait(0x7fd4c069ef00, 0x72, 0x0)
Apr 16 03:55:19 angel snapd[489]: #011/usr/lib/go-1.10/src/runtime/netpoll.go:173 +0x59
Apr 16 03:55:19 angel snapd[489]: internal/poll.(*pollDesc).wait(0xc4203b6f18, 0x72, 0xc42007db00, 0x0, 0x0)
Apr 16 03:55:19 angel snapd[489]: #011/usr/lib/go-1.10/src/internal/poll/fd_poll_runtime.go:85 +0x9d
Apr 16 03:55:19 angel snapd[489]: internal/poll.(*pollDesc).waitRead(0xc4203b6f18, 0xffffffffffffff00, 0x0, 0x0)
Apr 16 03:55:19 angel snapd[489]: #011/usr/lib/go-1.10/src/internal/poll/fd_poll_runtime.go:90 +0x3f
Apr 16 03:55:19 angel snapd[489]: internal/poll.(*FD).Accept(0xc4203b6f00, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
Apr 16 03:55:19 angel snapd[489]: #011/usr/lib/go-1.10/src/internal/poll/fd_unix.go:372 +0x1aa
Apr 16 03:55:19 angel snapd[489]: net.(*netFD).accept(0xc4203b6f00, 0x30, 0x557d8e0f9440, 0xc42007db60)
Apr 16 03:55:19 angel snapd[489]: #011/usr/lib/go-1.10/src/net/fd_unix.go:238 +0x44
Apr 16 03:55:19 angel snapd[489]: net.(*UnixListener).accept(0xc42047e150, 0x0, 0xc4201aac00, 0xc42004a630)
Apr 16 03:55:19 angel snapd[489]: #011/usr/lib/go-1.10/src/net/unixsock_posix.go:162 +0x34
Apr 16 03:55:19 angel collectd[682]: write_gcm: Error -1 from wg_curl_get_or_post (CollectdTimeseries)
Apr 16 03:55:19 angel systemd[1]: snapd.service: Main process exited, code=exited, status=2/INVALIDARGUMENT
Apr 16 03:55:19 angel snapd[489]: net.(*UnixListener).Accept(0xc42047e150, 0xc42004a630, 0xc42004a650, 0x557d8d243ada, 0x30)
Apr 16 03:55:19 angel snapd[489]: #011/usr/lib/go-1.10/src/net/unixsock.go:253 +0x4b
Apr 16 03:55:19 angel snapd[489]: github.com/snapcore/snapd/daemon.(*ucrednetListener).Accept(0xc42047e1b0, 0x0, 0x0, 0x0, 0x0)
Apr 16 03:55:19 angel snapd[489]: #011/build/snapd/parts/snapd-deb/build/_build/src/github.com/snapcore/snapd/daemon/ucrednet.go:110 +0x4f
Apr 16 03:55:19 angel snapd[489]: net/http.(*Server).Serve(0xc420432dd0, 0x557d8e18a6e0, 0xc42047e1b0, 0x0, 0x0)
Apr 16 03:55:19 angel snapd[489]: #011/usr/lib/go-1.10/src/net/http/server.go:2773 +0x1a7
Apr 16 03:55:19 angel snapd[489]: github.com/snapcore/snapd/daemon.(*Daemon).Start.func1.1(0x0, 0x0)
Apr 16 03:55:19 angel snapd[489]: #011/build/snapd/parts/snapd-deb/build/_build/src/github.com/snapcore/snapd/daemon/daemon.go:470 +0x4b
Apr 16 03:55:19 angel snapd[489]: github.com/snapcore/snapd/vendor/gopkg.in/tomb%2ev2.(*Tomb).run(0xc420146f30, 0xc42028d200)
Apr 16 03:55:19 angel snapd[489]: #011/build/snapd/parts/snapd-deb/build/_build/src/github.com/snapcore/snapd/vendor/gopkg.in/tomb.v2/tomb.go:163 +0x2d
Apr 16 03:55:19 angel snapd[489]: created by github.com/snapcore/snapd/vendor/gopkg.in/tomb%2ev2.(*Tomb).Go
Apr 16 03:55:19 angel snapd[489]: #011/build/snapd/parts/snapd-deb/build/_build/src/github.com/snapcore/snapd/vendor/gopkg.in/tomb.v2/tomb.go:159 +0xbb
Apr 16 03:55:19 angel snapd[489]: goroutine 41 [select, 65 minutes]:
Apr 16 03:55:19 angel snapd[489]: github.com/snapcore/snapd/overlord/ifacestate/udevmonitor.(*Monitor).Run.func1(0xc4200ebfa0, 0xc4200ebfc0)
Apr 16 03:55:19 angel snapd[489]: #011/build/snapd/parts/snapd-deb/build/_build/src/github.com/snapcore/snapd/overlord/ifacestate/udevmonitor/udevmon.go:147 +0x35a
Apr 16 03:55:19 angel snapd[489]: github.com/snapcore/snapd/vendor/gopkg.in/tomb%2ev2.(*Tomb).run(0xc42018c630, 0xc420445840)
Apr 16 03:55:19 angel snapd[489]: #011/build/snapd/parts/snapd-deb/build/_build/src/github.com/snapcore/snapd/vendor/gopkg.in/tomb.v2/tomb.go:163 +0x2d
Apr 16 03:55:19 angel snapd[489]: created by github.com/snapcore/snapd/vendor/gopkg.in/tomb%2ev2.(*Tomb).Go
Apr 16 03:55:19 angel snapd[489]: #011/build/snapd/parts/snapd-deb/build/_build/src/github.com/snapcore/snapd/vendor/gopkg.in/tomb.v2/tomb.go:159 +0xbb
Apr 16 03:55:19 angel snapd[489]: goroutine 37 [runnable]:
Apr 16 03:55:19 angel snapd[489]: regexp.(*inputString).index(0xc4203fc438, 0xc4205f21e0, 0x0, 0xc42005eb28)
Apr 16 03:55:19 angel snapd[489]: #011/usr/lib/go-1.10/src/regexp/regexp.go:313 +0x8d
Apr 16 03:55:19 angel snapd[489]: regexp.(*machine).backtrack(0xc4203fc360, 0x557d8e18d7e0, 0xc4203fc438, 0x0, 0x6, 0x0, 0xc420498780)
Apr 16 03:55:19 angel snapd[489]: #011/usr/lib/go-1.10/src/regexp/backtrack.go:335 +0x254
Apr 16 03:55:19 angel collectd[682]: write_gcm: wg_transmit_unique_segment failed.
Apr 16 03:55:19 angel systemd[1]: snapd.service: Failed with result 'watchdog'.
Apr 16 03:55:19 angel snapd[489]: regexp.(*Regexp).doExecute(0xc4205f21e0, 0x0, 0x0, 0x0, 0x0, 0x0, 0xc4205a4050, 0x6, 0x0, 0x0, ...)
Apr 16 03:55:19 angel snapd[489]: #011/usr/lib/go-1.10/src/regexp/exec.go:440 +0x327
Apr 16 03:55:19 angel snapd[489]: regexp.(*Regexp).doMatch(0xc4205f21e0, 0x0, 0x0, 0x0, 0x0, 0x0, 0xc4205a4050, 0x6, 0xc42005ed40)
Apr 16 03:55:19 angel snapd[489]: #011/usr/lib/go-1.10/src/regexp/exec.go:411 +0xb3
Apr 16 03:55:19 angel snapd[489]: regexp.(*Regexp).MatchString(0xc4205f21e0, 0xc4205a4050, 0x6, 0xc42005ed01)
Apr 16 03:55:19 angel snapd[489]: #011/usr/lib/go-1.10/src/regexp/regexp.go:435 +0x57
Apr 16 03:55:19 angel snapd[489]: github.com/snapcore/snapd/osutil/udev/netlink.Env.Evaluate(0xc420346090, 0xc420346000, 0xffffffffffffffff)
Apr 16 03:55:19 angel snapd[489]: #011/build/snapd/parts/snapd-deb/build/_build/src/github.com/snapcore/snapd/osutil/udev/netlink/matcher.go:102 +0x13b
Apr 16 03:55:19 angel snapd[489]: github.com/snapcore/snapd/osutil/udev/netlink.RuleDefinition.EvaluateEnv(0x0, 0xc420326ba0, 0xc42059a000, 0xc420346000, 0x3)
Apr 16 03:55:19 angel snapd[489]: #011/build/snapd/parts/snapd-deb/build/_build/src/github.com/snapcore/snapd/osutil/udev/netlink/matcher.go:56 +0x45
Apr 16 03:55:19 angel snapd[489]: github.com/snapcore/snapd/osutil/udev/netlink.RuleDefinition.Evaluate(0x0, 0xc420326ba0, 0xc42059a000, 0xc4205a4008, 0x3, 0xc42034c080, 0x3d, 0xc420346000, 0xc4200b4040)
Apr 16 03:55:19 angel snapd[489]: #011/build/snapd/parts/snapd-deb/build/_build/src/github.com/snapcore/snapd/osutil/udev/netlink/matcher.go:31 +0xaf
Apr 16 03:55:19 angel snapd[489]: github.com/snapcore/snapd/osutil/udev/netlink.RuleDefinitions.Evaluate(0xc420296960, 0x3, 0x3, 0xc4205a4008, 0x3, 0xc42034c080, 0x3d, 0xc420346000, 0x0)
Apr 16 03:55:19 angel snapd[489]: #011/build/snapd/parts/snapd-deb/build/_build/src/github.com/snapcore/snapd/osutil/udev/netlink/matcher.go:136 +0x9d
Apr 16 03:55:19 angel snapd[489]: github.com/snapcore/snapd/osutil/udev/netlink.(*UEventConn).Monitor.func4(0xc4205b8b80, 0xc42036d920, 0xc42036d980, 0xc42036d9e0, 0xc420171a60, 0x557d8e18d260, 0xc4205b8b60, 0xc42036d8c0)
Apr 16 03:55:19 angel snapd[489]: #011/build/snapd/parts/snapd-deb/build/_build/src/github.com/snapcore/snapd/osutil/udev/netlink/conn.go:164 +0x1c2
Apr 16 03:55:19 angel snapd[489]: created by github.com/snapcore/snapd/osutil/udev/netlink.(*UEventConn).Monitor
Apr 16 03:55:19 angel snapd[489]: #011/build/snapd/parts/snapd-deb/build/_build/src/github.com/snapcore/snapd/osutil/udev/netlink/conn.go:136 +0x233
Apr 16 03:55:19 angel snapd[489]: rax    0xca
Apr 16 03:55:19 angel snapd[489]: rbx    0x557d8e600020
Apr 16 03:55:19 angel snapd[489]: rcx    0x557d8d28f0b3
Apr 16 03:55:19 angel snapd[489]: rdx    0x0
Apr 16 03:55:19 angel snapd[489]: rdi    0x557d8e600168
Apr 16 03:55:19 angel snapd[489]: rsi    0x0
Apr 16 03:55:19 angel snapd[489]: rbp    0x7fff16030420
Apr 16 03:55:19 angel collectd[682]: write_gcm: wg_transmit_unique_segments failed. Flushing.
Apr 16 03:55:19 angel snapd[489]: rsp    0x7fff160303d8
Apr 16 03:55:19 angel snapd[489]: r8     0x0
Apr 16 03:55:19 angel snapd[489]: r9     0x0
Apr 16 03:55:19 angel snapd[489]: r10    0x0
Apr 16 03:55:19 angel snapd[489]: r11    0x286
Apr 16 03:55:19 angel snapd[489]: r12    0xc420050768
Apr 16 03:55:19 angel snapd[489]: r13    0x1
Apr 16 03:55:19 angel snapd[489]: r14    0xc42036cba0
Apr 16 03:55:19 angel snapd[489]: r15    0x1
Apr 16 03:55:19 angel snapd[489]: rip    0x557d8d28f0b1
Apr 16 03:55:19 angel snapd[489]: rflags 0x286
Apr 16 03:55:19 angel snapd[489]: cs     0x33
Apr 16 03:55:19 angel snapd[489]: fs     0x0
Apr 16 03:55:19 angel snapd[489]: gs     0x0
Apr 16 03:55:19 angel collectd[682]: write_gcm: curl_easy_perform() failed: Timeout was reached
Apr 16 03:55:19 angel collectd[682]: write_gcm: Error -1 from wg_curl_get_or_post (CollectdTimeseries)
Apr 16 03:55:19 angel collectd[682]: write_gcm: wg_transmit_unique_segment failed.
Apr 16 03:55:19 angel collectd[682]: write_gcm: wg_transmit_unique_segments failed. Flushing.
Apr 16 03:55:19 angel collectd[682]: write_gcm: curl_easy_perform() failed: Timeout was reached
Apr 16 03:55:19 angel collectd[682]: write_gcm: curl_easy_perform() failed: Timeout was reached
Apr 16 03:55:19 angel collectd[682]: write_gcm: Error -1 from wg_curl_get_or_post (CollectdTimeseries)
Apr 16 03:55:19 angel collectd[682]: write_gcm: wg_transmit_unique_segment failed.
Apr 16 03:55:19 angel collectd[682]: write_gcm: wg_transmit_unique_segments failed. Flushing.
Apr 16 03:55:19 angel collectd[682]: write_gcm: Error -1 from wg_curl_get_or_post (Timeseries)
Apr 16 03:55:19 angel collectd[682]: write_gcm: wg_transmit_unique_segment failed.
Apr 16 03:55:19 angel collectd[682]: write_gcm: wg_transmit_unique_segments failed. Flushing.
Apr 16 03:55:19 angel collectd[682]: uc_update: Value too old: name = /stackdriver_agent-point_count/; value time = 1618543518.606; last cache update = 1618543518.606;
Apr 16 03:55:19 angel collectd[682]: write_gcm: wg_update_stats failed.
Apr 16 03:55:19 angel collectd[682]: uc_update: Value too old: name = angel/processes-all/ps_vm; value time = 1618543765.625; last cache update = 1618543765.626;
Apr 16 03:55:19 angel collectd[682]: plugin_read_thread: read-function of the `processes' plugin took 178.677 seconds, which is above its read interval (60.000 seconds). You might want to adjust the `Interval' or `ReadThreads' settings.
Apr 16 03:55:19 angel collectd[682]: match_throttle_metadata_keys: uc_meta_data_add returned an error
Apr 16 03:55:19 angel collectd[682]: match_throttle_metadata_keys: mtg_update_stats failed.
Apr 16 03:55:19 angel collectd[682]: fc_process_chain (PostCache): A match failed.
Apr 16 03:55:19 angel collectd[682]: plugin_read_thread: read-function of the `processes' plugin took 168.000 seconds, which is above its read interval (60.000 seconds). You might want to adjust the `Interval' or `ReadThreads' settings.
Apr 16 03:55:19 angel collectd[682]: match_throttle_metadata_keys: uc_meta_data_add returned an error
Apr 16 03:55:19 angel collectd[682]: match_throttle_metadata_keys: mtg_update_stats failed.
Apr 16 03:55:19 angel collectd[682]: fc_process_chain (PostCache): A match failed.
Apr 16 03:55:19 angel collectd[682]: plugin_read_thread: read-function of the `processes' plugin took 183.436 seconds, which is above its read interval (60.000 seconds). You might want to adjust the `Interval' or `ReadThreads' settings.
Apr 16 03:55:19 angel collectd[682]: match_throttle_metadata_keys: uc_meta_data_add returned an error
Apr 16 03:55:19 angel collectd[682]: match_throttle_metadata_keys: mtg_update_stats failed.
Apr 16 03:55:19 angel collectd[682]: fc_process_chain (MaybeThrottleProcesses): A match failed.
Apr 16 03:55:19 angel collectd[682]: plugin_read_thread: read-function of the `processes' plugin took 196.423 seconds, which is above its read interval (60.000 seconds). You might want to adjust the `Interval' or `ReadThreads' settings.
Apr 16 03:55:19 angel collectd[682]: statvfs(/Shared_KMS) failed: Software caused connection abort
Apr 16 03:55:19 angel collectd[682]: uc_update: Value too old: name = angel/disk-sda15/disk_ops; value time = 1618545234.906; last cache update = 1618545275.527;
Apr 16 03:55:19 angel collectd[682]: plugin_read_thread: read-function of the `processes' plugin took 73.575 seconds, which is above its read interval (60.000 seconds). You might want to adjust the `Interval' or `ReadThreads' settings.
Apr 16 03:55:19 angel collectd[682]: write_gcm: curl_easy_perform() failed: Timeout was reached
Apr 16 03:55:19 angel collectd[682]: write_gcm: Error -1 from wg_curl_get_or_post (CollectdTimeseries)
Apr 16 03:55:19 angel collectd[682]: write_gcm: wg_transmit_unique_segment failed.
Apr 16 03:55:19 angel collectd[682]: write_gcm: wg_transmit_unique_segments failed. Flushing.
Apr 16 03:55:19 angel collectd[682]: write_gcm: curl_easy_perform() failed: Timeout was reached
Apr 16 03:55:19 angel collectd[682]: write_gcm: Error -1 from wg_curl_get_or_post (Timeseries)
Apr 16 03:55:19 angel collectd[682]: write_gcm: wg_transmit_unique_segment failed.
Apr 16 03:55:19 angel collectd[682]: write_gcm: wg_transmit_unique_segments failed. Flushing.
Apr 16 03:55:19 angel collectd[682]: write_gcm: Asking metadata server for auth token
Apr 16 03:55:19 angel collectd[682]: write_gcm: Server response (CollectdTimeseriesRequest) contains errors:#012{#012  "summary": {#012    "totalPointCount": 464,#012    "successPointCount": 460,#012    "errors": [#012      {#012        "status":
 {#012          "code": 3,#012          "message": "Points must be written in order. One or more of the points specified had an older end time than the most recent point."#012        },#012        "pointCount": 4#012      }#012    ]#012  }#012}
Apr 16 03:55:19 angel collectd[682]: write_gcm: Server response (CollectdTimeseriesRequest) contains errors:#012{#012  "summary": {#012    "totalPointCount": 464,#012    "successPointCount": 463,#012    "errors": [#012      {#012        "status":
 {#012          "code": 3,#012          "message": "Points must be written in order. One or more of the points specified had an older end time than the most recent point."#012        },#012        "pointCount": 1#012      }#012    ]#012  }#012}
Apr 16 03:55:19 angel collectd[682]: write_gcm: Server response (CollectdTimeseriesRequest) contains errors:#012{#012  "summary": {#012    "totalPointCount": 464,#012    "successPointCount": 462,#012    "errors": [#012      {#012        "status":
 {#012          "code": 3,#012          "message": "Points must be written in order. One or more of the points specified had an older end time than the most recent point."#012        },#012        "pointCount": 2#012      }#012    ]#012  }#012}
Apr 16 03:55:19 angel collectd[682]: write_gcm: Server response (CollectdTimeseriesRequest) contains errors:#012{#012  "summary": {#012    "totalPointCount": 464,#012    "successPointCount": 463,#012    "errors": [#012      {#012        "status":
 {#012          "code": 3,#012          "message": "Points must be written in order. One or more of the points specified had an older end time than the most recent point."#012        },#012        "pointCount": 1#012      }#012    ]#012  }#012}
Apr 16 03:55:19 angel collectd[682]: write_gcm: Server response (CollectdTimeseriesRequest) contains errors:#012{#012  "summary": {#012    "totalPointCount": 460,#012    "successPointCount": 457,#012    "errors": [#012      {#012        "status":
 {#012          "code": 3,#012          "message": "Points must be written in order. One or more of the points specified had an older end time than the most recent point."#012        },#012        "pointCount": 3#012      }#012    ]#012  }#012}
Apr 16 03:55:19 angel collectd[682]: write_gcm: Server response (CollectdTimeseriesRequest) contains errors:#012{#012  "summary": {#012    "totalPointCount": 282,#012    "successPointCount": 277,#012    "errors": [#012      {#012        "status":
 {#012          "code": 3,#012          "message": "Points must be written in order. One or more of the points specified had an older end time than the most recent point."#012        },#012        "pointCount": 5#012      }#012    ]#012  }#012}
Apr 16 03:55:19 angel collectd[682]: write_gcm: Server response (CollectdTimeseriesRequest) contains errors:#012{#012  "summary": {#012    "totalPointCount": 157,#012    "successPointCount": 155,#012    "errors": [#012      {#012        "status":
 {#012          "code": 3,#012          "message": "Points must be written in order. One or more of the points specified had an older end time than the most recent point."#012        },#012        "pointCount": 2#012      }#012    ]#012  }#012}
Apr 16 03:55:19 angel collectd[682]: write_gcm: Server response (CollectdTimeseriesRequest) contains errors:#012{#012  "summary": {#012    "totalPointCount": 157,#012    "successPointCount": 155,#012    "errors": [#012      {#012        "status":
 {#012          "code": 3,#012          "message": "Points must be written in order. One or more of the points specified had an older end time than the most recent point."#012        },#012        "pointCount": 2#012      }#012    ]#012  }#012}
Apr 16 03:55:19 angel collectd[682]: write_gcm: Server response (CollectdTimeseriesRequest) contains errors:#012{#012  "summary": {#012    "totalPointCount": 155,#012    "successPointCount": 151,#012    "errors": [#012      {#012        "status":
 {#012          "code": 3,#012          "message": "Points must be written in order. One or more of the points specified had an older end time than the most recent point."#012        },#012        "pointCount": 4#012      }#012    ]#012  }#012}
Apr 16 03:55:19 angel systemd[1]: snapd.service: Scheduled restart job, restart counter is at 1.
Apr 16 03:55:19 angel systemd[1]: Stopped Snap Daemon.
Apr 16 03:55:19 angel systemd[1]: Starting Snap Daemon...
Apr 16 03:55:26 angel collectd[682]: plugin_read_thread: read-function of the `df' plugin took 2825.953 seconds, which is above its read interval (60.000 seconds). You might want to adjust the `Interval' or `ReadThreads' settings.
Apr 16 03:55:26 angel collectd[682]: statvfs(/Shared_KMS) failed: Transport endpoint is not connected
Apr 16 03:55:26 angel snapd[2068]: AppArmor status: apparmor is enabled and all features are available
Apr 16 03:55:27 angel snapd[2068]: AppArmor status: apparmor is enabled and all features are available
Apr 16 03:55:28 angel snapd[2068]: daemon.go:347: started snapd/2.49.2 (series 16; classic) ubuntu/20.04 (amd64) linux/5.4.0-1041-gcp.
Apr 16 03:55:28 angel snapd[2068]: daemon.go:440: adjusting startup timeout by 50s (pessimistic estimate of 30s plus 5s per snap)
Apr 16 03:55:28 angel systemd[1]: tmp-sanity\x2dmountpoint\x2d047216074.mount: Succeeded.
Apr 16 03:55:28 angel systemd[817]: tmp-sanity\x2dmountpoint\x2d047216074.mount: Succeeded.
Apr 16 03:55:28 angel systemd[1]: Started Snap Daemon.
Apr 16 03:56:20 angel collectd[682]: write_gcm: Server response (CollectdTimeseriesRequest) contains errors:#012{#012  "summary": {#012    "totalPointCount": 14,#012    "successPointCount": 8,#012    "errors": [#012      {#012        "status": {#
012          "code": 9,#012          "message": "One or more points were written more frequently than the maximum sampling period configured for the metric."#012        },#012        "pointCount": 6#012      }#012    ]#012  }#012}
Apr 16 03:56:26 angel collectd[682]: statvfs(/Shared_KMS) failed: Transport endpoint is not connected
Apr 16 04:03:26 angel collectd[682]: message repeated 7 times: [ statvfs(/Shared_KMS) failed: Transport endpoint is not connected]
Apr 16 04:04:26 angel collectd[682]: statvfs(/Shared_KMS) failed: Transport endpoint is not connected
Apr 16 04:12:26 angel collectd[682]: message repeated 8 times: [ statvfs(/Shared_KMS) failed: Transport endpoint is not connected]
Apr 16 04:13:26 angel collectd[682]: statvfs(/Shared_KMS) failed: Transport endpoint is not connected
Apr 16 04:04:26 angel collectd[682]: statvfs(/Shared_KMS) failed: Transport endpoint is not connected
Apr 16 04:12:26 angel collectd[682]: message repeated 8 times: [ statvfs(/Shared_KMS) failed: Transport endpoint is not connected]
Apr 16 04:13:26 angel collectd[682]: statvfs(/Shared_KMS) failed: Transport endpoint is not connected
Apr 16 04:16:26 angel collectd[682]: message repeated 3 times: [ statvfs(/Shared_KMS) failed: Transport endpoint is not connected]
Apr 16 04:17:01 angel CRON[2817]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Apr 16 04:17:26 angel collectd[682]: statvfs(/Shared_KMS) failed: Transport endpoint is not connected
Apr 16 04:18:26 angel collectd[682]: statvfs(/Shared_KMS) failed: Transport endpoint is not connected
Apr 16 04:19:22 angel collectd[682]: write_gcm: curl_easy_perform() failed: Timeout was reached
Apr 16 04:19:22 angel collectd[682]: write_gcm: Error -1 from wg_curl_get_or_post (CollectdTimeseries)
Apr 16 04:19:22 angel collectd[682]: write_gcm: wg_transmit_unique_segment failed.
Apr 16 04:19:22 angel collectd[682]: write_gcm: wg_transmit_unique_segments failed. Flushing.
Apr 16 04:19:26 angel collectd[682]: statvfs(/Shared_KMS) failed: Transport endpoint is not connected
Apr 16 04:26:26 angel collectd[682]: message repeated 7 times: [ statvfs(/Shared_KMS) failed: Transport endpoint is not connected]
Apr 16 04:27:26 angel collectd[682]: statvfs(/Shared_KMS) failed: Transport endpoint is not connected
Apr 16 04:29:26 angel collectd[682]: message repeated 2 times: [ statvfs(/Shared_KMS) failed: Transport endpoint is not connected]
5

I need the log from this command to see what is going on - that will say why the mount disappeared.

If you restart it with -vv --log-file rclone.log then that will make a log with the error message in.

7

I found out my rclone hang & unmount problem.
my free GCP server has a 0.6gb ram...
i changed my rclone command like this to avoid hang problem
copying speed is so slow but stable...

rclone move -vv "$FROM" "$TO" --delete-after --log-file=$LOGFILE --checkers 1 --transfers 1 --use-mmap --buffer-s
ize 0M --tpslimit 1 --no-traverse

thank you so much for you help! :grinning:

1 Like
8

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