Fix panic when parsing sftp URIs #592

fd0 · 2016-08-28T10:03:13Z

Closes #587

wscott · 2016-08-28T10:47:29Z

my example works well:

$ ./restic -r sftp://p4:backups.restic snapshots
invalid backend "sftp://p4:backups.restic", no directory specified

Thanks.
I see you are still working on the sftp disabled issue.

fd0 · 2016-08-28T10:49:59Z

Yeah, I've opened an issue at pkg/sftp#133, but until that is implemented we'll just test for the string: 451f812#diff-7a06440ed5a9c66f259b47e47bd6f785R62

fd0 · 2016-08-28T10:53:50Z

Could you please disable sftp for your NAS again and run restic? Then please report the error message that is returned, thanks!

wscott · 2016-08-28T11:00:14Z

Hmm. I disabled stfp and the error detection didn't seem to work on this fix-587 branch.

$ ./restic version
restic 0.2.0 (v0.2.0-162-g451f812)
compiled at 2016-08-28 06:44:15 with go1.6

$ ./restic -r sftp://p4/homes/wscott/backups.restic snapshots
subsystem request failed on channel 0
EOF

Also with it enabled I am getting this. Odd because I thought I get this working eventually on Friday...

$ ./restic -r sftp://p4/homes/wscott/backups.restic snapshots
enter password for repository: 
panic: runtime error: invalid memory address or nil pointer dereference
[signal 0xb code=0x1 addr=0x28 pc=0x745bae]

goroutine 1 [running]:
panic(0x9c9200, 0xc82000e1a0)
    /usr/local/go/src/runtime/panic.go:464 +0x3e6
github.com/pkg/sftp.(*File).Write(0x0, 0xc8201882c0, 0xa5, 0xa5, 0xc8221b3130, 0x0, 0x0)
    /tmp/restic-build-428970331/src/github.com/pkg/sftp/client.go:890 +0x4e
restic/backend/sftp.(*SFTP).Save(0xc820162000, 0xa83178, 0x4, 0xc82006c7c0, 0x40, 0xc8201882c0, 0xa5, 0xa5, 0x7f27e4133850, 0xc820014280)
    /tmp/restic-build-428970331/src/restic/backend/sftp/sftp.go:338 +0x393
restic/repository.(*Repository).SaveUnpacked(0xc82006e840, 0xa83178, 0x4, 0xc8200a0090, 0x85, 0x88, 0x2bfffa28df5664a5, 0xb4a6888fae5a6fdc, 0xf1f7e704df07a653, 0x638b8a8706003a3, ...)
    /tmp/restic-build-428970331/src/restic/repository/repository.go:271 +0x245
restic/repository.(*Repository).SaveJSONUnpacked(0xc82006e840, 0xa83178, 0x4, 0xa3c540, 0xc8200b02a0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
    /tmp/restic-build-428970331/src/restic/repository/repository.go:256 +0x33a
restic.(*Lock).createLock(0xc8200b02a0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
    /tmp/restic-build-428970331/src/restic/lock.go:168 +0x8e
restic.newLock(0xc82006e840, 0xc820086000, 0x7f27e41b8528, 0x0, 0x0)
    /tmp/restic-build-428970331/src/restic/lock.go:94 +0x202
restic.NewLock(0xc82006e840, 0x9, 0x0, 0x0)
    /tmp/restic-build-428970331/src/restic/lock.go:61 +0x32
main.lockRepository(0xc82006e840, 0x8ceb00, 0xc8200ed0a0, 0x0, 0x0)
    /tmp/restic-build-428970331/src/cmds/restic/lock.go:35 +0x4f
main.lockRepo(0xc82006e840, 0x25, 0x0, 0x0)
    /tmp/restic-build-428970331/src/cmds/restic/lock.go:22 +0x32
main.CmdSnapshots.Execute(0x0, 0x0, 0x0, 0x0, 0x0, 0xd6f8a0, 0xc8201363f0, 0x0, 0x3, 0x0, ...)
    /tmp/restic-build-428970331/src/cmds/restic/cmd_snapshots.go:81 +0x285
main.(*CmdSnapshots).Execute(0xc820075fb0, 0xc8201363f0, 0x0, 0x3, 0x0, 0x0)
    <autogenerated>:50 +0xc6
github.com/jessevdk/go-flags.(*Parser).ParseArgs(0xc82008a870, 0xc82006c110, 0x3, 0x3, 0x0, 0x0, 0x0, 0x0, 0x0)
    /tmp/restic-build-428970331/src/github.com/jessevdk/go-flags/parser.go:278 +0x8dd
github.com/jessevdk/go-flags.(*Parser).Parse(0xc82008a870, 0x0, 0x0, 0x0, 0x0, 0x0)
    /tmp/restic-build-428970331/src/github.com/jessevdk/go-flags/parser.go:154 +0x9b
main.main()
    /tmp/restic-build-428970331/src/cmds/restic/main.go:32 +0x1e8

Note this last one does require the password so it is getting to the right repo.

I am going to have to run off and won't be back online for another 8 hours.

wscott · 2016-08-28T11:02:18Z

Just looked, that second stacktrace is consistent with what I reported Friday. But we expected the 'sftp disabled' case to generate a message and it didn't. I have been using NFS.

fd0 · 2016-08-28T11:18:56Z

Interesting. I don't see where the error message is generated. The position I identified is slightly different: subsystem request failed on channel 0 vs ssh: subsystem request failed

fd0 · 2016-08-28T11:23:08Z

Oh wow, the stacktrace is caused by a missing error check in my backend code in src/restic/backend/sftp/sftp.go:

    filename, tmpfile, err := r.tempFile()
    debug.Log("sftp.Save", "save %v (%d bytes) to %v", h, len(p), filename)

    n, err := tmpfile.Write(p)
    if err != nil {
        return err
    }

fd0 · 2016-08-28T16:52:18Z

Double-Wow, this check was also missing from the local backend. This gets much better error messages for #93!

This yields the error messages for a full backup location: panic: write /home/fd0/mnt/temp/tmp/temp-987810174: no space left on device Closes #540 Also connected to #574

fd0 · 2016-08-28T16:58:46Z

I've extracted the fixes for the local and sftp backend (the missing error check) into #593 so we can merge them immediately.

local/sftp: Fix broken error handling

Closes #587

wscott · 2016-08-28T17:54:32Z

Yup. Much better, the bad URLs give

$ ./restic version
restic 0.2.0 (v0.2.0-162-g451f812)
compiled at 2016-08-28 13:46:49 with go1.6

$ ./restic -r sftp://p4:backups.restic snapshots
invalid backend "sftp://p4:backups.restic", no directory specified

$ ./restic -r sftp://p4/backups.restic snapshots
backups.restic does not exist

With SFTP disabled I still get a poor message:

$ ./restic -r sftp://p4/backups.restic snapshots
subsystem request failed on channel 0
EOF

The invalid memory address still happens when I actually use the right URL with SFTP enabled.

Also add a prefix for all errors written to stderr by the client

fd0 · 2016-08-28T17:57:46Z

Can you please retry with current commits?

The error message now is:

subprocess ssh: subsystem request failed on channel 1
unable to start the sftp session, error: EOF

wscott · 2016-08-28T17:59:50Z

Ah when I use #593 the invalid memory address goes away and was replaced with this:

 $ ./restic -r sftp://p4/homes/wscott/backups.restic snapshots
enter password for repository: 
creating tempfile "homes/wscott/backups.restic/tmp/temp-a3a2a92b9cc67d4f7184" failed: sftp: "Permission denied" (SSH_FX_PERMISSION_DENIED)

But SFTP disabled still looks like this:

$ ./restic -r sftp://p4/homes/wscott/backups.restic snapshots
subsystem request failed on channel 0
EOF

wscott · 2016-08-28T18:01:53Z

nevermind

$ ./restic -r sftp://p4/homes/wscott/backups.restic snapshots
subprocess ssh: subsystem request failed on channel 0
unable to start the sftp session, error: EOF

with the fix-587 tip.

Thanks.

fd0 · 2016-08-28T18:02:26Z

Great, thanks for the confirmation.

For the record: Comment out the sftp line in the sshd_config file of OpenSSH disables sftp, that's what I used for testing:

#Subsystem sftp internal-sftp

wscott · 2016-08-28T18:08:02Z

With the proper error messages I was able to fix the settings on my NAS to get closer to the right answer.
However what is this last part?

$ ./restic -r sftp://p4/backups.restic snapshots
enter password for repository: 
ID        Date                 Host        Directory
----------------------------------------------------------------------
c7b5156a  2016-08-26 11:19:38  x99         /home/wscott
                                           /space/wscott
7bf90859  2016-08-27 06:47:43  x99         /home/wscott
8f9003ee  2016-08-27 06:56:29  x99         /space/wscott
f1d206fb  2016-08-28 00:01:23  x99         /home/wscott
63aef99c  2016-08-28 00:13:31  x99         /space/wscott
error in cleanup handler: file does not exist

All commands seem to include that file does not exist message. And it seems to leave a stale lock behind. New issue?

fd0 · 2016-08-28T18:12:24Z

Yes, new issue. IRC?

Fix panic when parsing sftp URIs

wscott · 2016-08-28T18:14:56Z

Sorry out of time to play at the moment.

fd0 · 2016-08-28T18:15:30Z

Nevermind, write a debug log and open a new issue later. Oh, and try unlock.

local/sftp: Fix broken error handling

196bbbd

This yields the error messages for a full backup location: panic: write /home/fd0/mnt/temp/tmp/temp-987810174: no space left on device Closes #540 Also connected to #574

fd0 added 8 commits August 28, 2016 19:30

Merge pull request #593 from restic/correct-backend-errors

d097d40

local/sftp: Fix broken error handling

Fix panic when parsing sftp URIs

ed09887

Closes #587

Update sftp library

a7e64af

Vendor github.com/pkg/errors

8de06bd

Improve error handling with the ssh subprocess

5dd137d

Report errors to stderr for tests

db16702

Remove debug output for tests

cdbdf74

sftp: Add debug log messages

22bde5b

Improve error message when sftp fails

83924d0

Also add a prefix for all errors written to stderr by the client

fd0 force-pushed the fix-587 branch from facb481 to 83924d0 Compare August 28, 2016 17:57

fd0 merged commit 83924d0 into master Aug 28, 2016

fd0 added a commit that referenced this pull request Aug 28, 2016

Merge pull request #592 from restic/fix-587

553dd00

Fix panic when parsing sftp URIs

fd0 deleted the fix-587 branch August 28, 2016 18:14

This was referenced Aug 28, 2016

Write operations fail when talking to Synology NAS over SFTP #596

Closed

restic panics if writes to the SFTP backend fail #550

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix panic when parsing sftp URIs #592

Fix panic when parsing sftp URIs #592

fd0 commented Aug 28, 2016

wscott commented Aug 28, 2016

fd0 commented Aug 28, 2016

fd0 commented Aug 28, 2016

wscott commented Aug 28, 2016

wscott commented Aug 28, 2016

fd0 commented Aug 28, 2016

fd0 commented Aug 28, 2016

fd0 commented Aug 28, 2016

fd0 commented Aug 28, 2016

wscott commented Aug 28, 2016

fd0 commented Aug 28, 2016

wscott commented Aug 28, 2016

wscott commented Aug 28, 2016

fd0 commented Aug 28, 2016 •

edited

wscott commented Aug 28, 2016

fd0 commented Aug 28, 2016

wscott commented Aug 28, 2016 •

edited by fd0

fd0 commented Aug 28, 2016

Fix panic when parsing sftp URIs #592

Fix panic when parsing sftp URIs #592

Conversation

fd0 commented Aug 28, 2016

wscott commented Aug 28, 2016

fd0 commented Aug 28, 2016

fd0 commented Aug 28, 2016

wscott commented Aug 28, 2016

wscott commented Aug 28, 2016

fd0 commented Aug 28, 2016

fd0 commented Aug 28, 2016

fd0 commented Aug 28, 2016

fd0 commented Aug 28, 2016

wscott commented Aug 28, 2016

fd0 commented Aug 28, 2016

wscott commented Aug 28, 2016

wscott commented Aug 28, 2016

fd0 commented Aug 28, 2016 • edited

wscott commented Aug 28, 2016

fd0 commented Aug 28, 2016

wscott commented Aug 28, 2016 • edited by fd0

fd0 commented Aug 28, 2016

fd0 commented Aug 28, 2016 •

edited

wscott commented Aug 28, 2016 •

edited by fd0