rclone subprocess signal handling on Windows: tons of "rclone stdio connection already closed" when Ctrl+C

[cqjjjzr]

Output of restic version

• restic 0.12.1 compiled with go1.16.6 on windows/amd64
• restic 0.12.1-dev (compiled manually) compiled with go1.17.5 on windows/amd64 (complied with Asynchronously upload pack files #3489 and Add backup --file-read-concurrency flag #2750)

How did you run restic exactly?

• Windows 10 x64 21H1 version 19043 Simplified Chinese

• PowerShell 7.2.0

• Environment: DEBUG_LOG = test.log

• rclone v1.57.0 with go/version: go1.17.2

• Repo init: restic init -r rclone:(some rclone path)

• Backup: restic backup -r rclone:(some rclone path) C:\........(some big directory) --verbose=3 -o rclone.args="serve restic --stdio --log-file=rclonelog.log --log-level=DEBUG"

What backend/server/service did you use to store the repository?

rclone v1.57.0, using OneDrive for Business with a shakey and unstable network as backend.

Expected behavior

When I press Ctrl+C in the console while backing up, restic should clean up and exit gracefully.

Actual behavior

restic never stops, outputting:

signal interrupt received, cleaning up
Remove(<lock/4d3fcb853f>) returned error, retrying after 720.254544ms: client.Do: Delete "http://localhost/locks/4d3fcb853f23f615aa2234b5cf59e9372c1c0dda8454831f07dc66950cd83304": unexpected EOF
Remove(<lock/4d3fcb853f>) returned error, retrying after 873.42004ms: client.Do: Delete "http://localhost/locks/4d3fcb853f23f615aa2234b5cf59e9372c1c0dda8454831f07dc66950cd83304": rclone stdio connection already closed
.................................(repeating)

The lock file in the OneDrive folder never got deleted.

In the rustic logfile (from the dev version of rustic):

2021/12/22 12:59:29 restic/cleanup.go:60	main.CleanupHandler	35	signal interrupt received, cleaning up
2021/12/22 12:59:29 restic/lock.go:119	main.unlockAll	35	unlocking 1 locks
2021/12/22 12:59:29 archiver/blob_saver.go:125	archiver.(*BlobSaver).worker	168	saveBlob returned error, exiting: context canceled
2021/12/22 12:59:29 cache/backend.go:37	cache.(*Backend).Remove	35	cache Remove(<lock/e66f9bd6b6>)
2021/12/22 12:59:29 archiver/file_saver.go:115	archiver.(*FileSaver).Save	125	not sending job, context is cancelled: context canceled
(lots of logs reporting context canceled)
2021/12/22 12:59:29 debug/round_tripper_debug.go:82	debug.loggingRoundTripper.RoundTrip	35	------------  HTTP REQUEST -----------
DELETE /locks/e66f9bd6b6b972fb26061f27e89d425532a3d76f49fa1702d9ec7643396f8b12 HTTP/1.1
Host: localhost
User-Agent: Go-http-client/1.1
Accept: application/vnd.x.restic.rest.v2
Accept-Encoding: gzip

(lots of logs reporting context canceled)
2021/12/22 12:59:29 debug/round_tripper_debug.go:87	debug.loggingRoundTripper.RoundTrip	35	RoundTrip() returned error: unexpected EOF
2021/12/22 12:59:29 rclone/stdio_conn.go:35	rclone.(*StdioConn).Close.func1	82	close stdio send connection
(non-related logs omitted)
2021/12/22 12:59:29 archiver/archiver.go:826	archiver.(*Archiver).Snapshot.func1	124	err is context canceled
2021/12/22 12:59:29 archiver/archiver.go:829	archiver.(*Archiver).Snapshot.func1	124	error while saving tree: context canceled
2021/12/22 12:59:29 rclone/backend.go:199	rclone.newBackend.func2	20	Wait returned exit status 2
2021/12/22 12:59:29 rclone/stdio_conn.go:47	rclone.(*StdioConn).CloseAll.func1	20	close stdio receive connection
2021/12/22 12:59:29 debug/round_tripper_debug.go:82	debug.loggingRoundTripper.RoundTrip	35	------------  HTTP REQUEST -----------
DELETE /locks/e66f9bd6b6b972fb26061f27e89d425532a3d76f49fa1702d9ec7643396f8b12 HTTP/1.1
Host: localhost
User-Agent: Go-http-client/1.1
Accept: application/vnd.x.restic.rest.v2
Accept-Encoding: gzip

(repeating)

Note these 4 lines:

2021/12/22 12:59:29 debug/round_tripper_debug.go:87	debug.loggingRoundTripper.RoundTrip	35	RoundTrip() returned error: unexpected EOF
2021/12/22 12:59:29 rclone/stdio_conn.go:35	rclone.(*StdioConn).Close.func1	82	close stdio send connection
2021/12/22 12:59:29 rclone/backend.go:199	rclone.newBackend.func2	20	Wait returned exit status 2
2021/12/22 12:59:29 rclone/stdio_conn.go:47	rclone.(*StdioConn).CloseAll.func1	20	close stdio receive connection

On the other hand, in the rclone logfile:

2021/12/22 13:25:47 INFO  : Signal received: interrupt
2021/12/22 13:25:47 INFO  : Exiting...

Steps to reproduce the behavior

Using the same environment and command above, when backing up some big file, press Ctrl+C midway backing up.

Do you have any idea what may have caused this?

According to the rclone logfile, restic and rclone received an interrupt signal at the same time. As a result, rclone exits prematurely, breaking the std pipes between restic and rclone (explaining the unexpected EOF error). At such point, stdio pipes would have been closed. And then, restic fails in all subsequent DELETE requests.

According to https://docs.microsoft.com/en-us/windows/console/ctrl-c-and-ctrl-break-signals the Ctrl+C signal is sent to all attached processes in a console, that explains why rclone also received the signal.

Do you have an idea how to solve the issue?

For Windows API calling, the subprocess must be created by CreateProcess with DETACHED_PROCESS flag on. I'll soon submit a PR containing the fix.

Did restic help you today? Did it make you happy in any way?

I just discovered restic and autorestic to be the center component of my personal backup solution. Restic is definitely an awesome project. I'm looking forward to restic getting more and more improvements!

btw, could I ask that when will the compression function be completed? :P