panic: store new item in finalized indexB

[darkskiez]

Output of restic version

restic 0.7.2 (v0.7.2-0-g5b1e4df1)
compiled with go1.8.3 on linux/amd64

How did you run restic exactly?

restic -r /home/restic backup /mnt/media

What backend/server/service did you use?

localfile

Expected behavior

not to panic

Actual behavior

scanned 270 directories, 7193 files in 0:00
panic: store new item in finalized indexB / 1.341 TiB  2719 / 7463 items  0 errors  ETA 24:32 

goroutine 1266676 [running]:
github.com/restic/restic/internal/repository.(*Index).Store(0xc43b47e1c0, 0x1, 0x137244, 0xed5be426c2b4400a, 0xf0d573c30a46e61a, 0xd8395f58b032a2a0, 0x524e794418239f8c, 0x2d4c74, 0x221ad52c4ab6c05d, 0xf2342afbc820faf8, ...)
	src/github.com/restic/restic/internal/repository/index.go:103 +0x441
github.com/restic/restic/internal/repository.(*MasterIndex).Store(0xc4201cc720, 0x1, 0x137244, 0xed5be426c2b4400a, 0xf0d573c30a46e61a, 0xd8395f58b032a2a0, 0x524e794418239f8c, 0x2d4c74, 0x221ad52c4ab6c05d, 0xf2342afbc820faf8, ...)
	src/github.com/restic/restic/internal/repository/master_index.go:127 +0x2a2
github.com/restic/restic/internal/repository.(*Repository).savePacker(0xc420075680, 0xc462e90240, 0xd573c30a46e61aed, 0x395f58b032a2a0f0)
	src/github.com/restic/restic/internal/repository/packer_manager.go:151 +0x778
github.com/restic/restic/internal/repository.(*Repository).SaveAndEncrypt(0xc420075680, 0xdc8e00, 0xc4200183f8, 0x6d859b01, 0xc49420a000, 0x137224, 0x4ae000, 0xc46d859d10, 0x0, 0x0, ...)
	src/github.com/restic/restic/internal/repository/repository.go:203 +0x34e
github.com/restic/restic/internal/repository.(*Repository).SaveBlob(0xc420075680, 0xdc8e00, 0xc4200183f8, 0xd8395f58b032a201, 0xc49420a000, 0x137224, 0x4ae000, 0xed5be426c2b4400a, 0xf0d573c30a46e61a, 0xd8395f58b032a2a0, ...)
	src/github.com/restic/restic/internal/repository/repository.go:529 +0x18b
github.com/restic/restic/internal/archiver.(*Archiver).Save(0xc46d82a230, 0xdc8e00, 0xc4200183f8, 0xed5be426c2b44001, 0xc49420a000, 0x137224, 0x4ae000, 0xed5be426c2b4400a, 0xf0d573c30a46e61a, 0xd8395f58b032a2a0, ...)
	src/github.com/restic/restic/internal/archiver/archiver.go:104 +0x1de
github.com/restic/restic/internal/archiver.(*Archiver).saveChunk(0xc46d82a230, 0xdc8e00, 0xc4200183f8, 0xd2a0714d, 0x137224, 0x74c2ce1e00000, 0xc49420a000, 0x137224, 0x4ae000, 0xc47a41a840, ...)
	src/github.com/restic/restic/internal/archiver/archiver.go:161 +0x135
created by github.com/restic/restic/internal/archiver.(*Archiver).SaveFile
	src/github.com/restic/restic/internal/archiver/archiver.go:239 +0x38c

Steps to reproduce the behavior

Do you have any idea what may have caused this?

Do you have an idea how to solve the issue?

[fd0]

Dang, this is a bug, thanks for reporting it! I thought we had resolved this error by now, meh.

[felix9]

I took a look at this, and my first guess is that it's a race here:
https://github.com/restic/restic/blob/master/internal/repository/master_index.go#L125

Two worker threads find the same index that isn't final yet.
One writes to it, filling it up.
The index saver thread finds the full index and finalizes it.
Then the other worker thread tries to write to it, and panics.

One straightforward fix is to have MasterIndex.Store do Lock instead of RLock.
Another fix is to optimistically try Index.Store, and retry if the index became finalized.

I can code up either if you like, but I'm unsure how to write a test for this.

[fd0]

I think you're right, thanks a lot for the analysis!

Let's use Lock instead of RLock and submit that as a PR. And I don't have an idea on how to test this either.

I'd like to refactor/rework the whole index handling thing anyway.