Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

panic: bug: lookup of nonexistent device ID #3873

Closed
ghost opened this issue Jan 4, 2017 · 2 comments
Closed

panic: bug: lookup of nonexistent device ID #3873

ghost opened this issue Jan 4, 2017 · 2 comments
Labels
frozen-due-to-age Issues closed and untouched for a long time, together with being locked for discussion

Comments

@ghost
Copy link

ghost commented Jan 4, 2017

References #3584 #3869

~> set -x STTRACE all
~> syncthing -no-browser -no-restart -logflags=0
15:26:36 DEBUG: Enabling lock logging at 100ms threshold
[start] DEBUG: subscribe Unknown
[start] DEBUG: subscribe LocalChangeDetected
[start] DEBUG: poll 1m0s
[start] DEBUG: poll 1m0s
[xxxxx] INFO: syncthing v0.14.15 "Dysprosium Dragonfly" (go1.7.4 linux-amd64) portage@machine.local 2017-01-04 21:25:31 UTC
[xxxxx] INFO: My ID: xxxxx
[xxxxx] DEBUG: Dialer logging disabled, as no proxy was detected
[xxxxx] INFO: Single thread hash performance is 391 MB/s using minio/sha256-simd (389 MB/s using crypto/sha256).
[xxxxx] DEBUG: log 0 Starting map[home:/home/user/.config/syncthing myID:xxxxx]
[xxxxx] DEBUG: poll 1m0s
[xxxxx] INFO: Archiving a copy of old config file format at: /home/user/.config/syncthing/config.xml.v16
[xxxxx] DEBUG: log 1 ConfigSaved {x}
[xxxxx] DEBUG: poll 1m0s
[xxxxx] DEBUG: progress emitter: updated interval 5s
[xxxxx] DEBUG: db check completed for "alpha"
[xxxxx] DEBUG: loaded sequence for "alpha": 0
[xxxxx] DEBUG: progress emitter: timer - looking after 0
[xxxxx] DEBUG: progress emitter: nothing new
[xxxxx] INFO: Ready to synchronize alpha (readwrite)
[xxxxx] DEBUG: db check completed for "beta"
[xxxxx] DEBUG: loaded sequence for "beta": 0
[xxxxx] INFO: Ready to synchronize beta (readwrite)
[xxxxx] DEBUG: db check completed for "delta"
[xxxxx] DEBUG: loaded sequence for "delta": 0
[xxxxx] INFO: Ready to synchronize delta (readwrite)
[xxxxx] DEBUG: db check completed for "echo"
[xxxxx] DEBUG: loaded sequence for "echo": 0
[xxxxx] INFO: Ready to synchronize echo (readwrite)
[xxxxx] DEBUG: db check completed for "foxtrot"
[xxxxx] DEBUG: loaded sequence for "foxtrot": 0
[xxxxx] INFO: Ready to synchronize foxtrot (readwrite)
[xxxxx] DEBUG: db check completed for "golf"
[xxxxx] DEBUG: loaded sequence for "golf": 0
[xxxxx] DEBUG: instantiated versioner.Simple{keep:5, folderPath:"x"}
[xxxxx] INFO: Ready to synchronize golf (readwrite)
[xxxxx] DEBUG: db check completed for "hotel"
[xxxxx] DEBUG: loaded sequence for "hotel": 0
[xxxxx] INFO: Ready to synchronize hotel (readwrite)
[xxxxx] DEBUG: db check completed for "juliet"
[xxxxx] DEBUG: loaded sequence for "juliet": 0
[xxxxx] DEBUG: using default dir .stversions
[xxxxx] DEBUG: instantiated versioner.Staggered{versionsPath:"x", cleanInterval:3600, folderPath:"x", interval:[4]versioner.Interval{versioner.Interval{step:30, end:3600}, versioner.Interval{step:3600, end:86400}, versioner.Interval{step:86400, end:592000}, versioner.Interval{step:604800, end:31536000}}, mutex:(*sync.loggedMutex)(0xc4201b49c0)}
[xxxxx] INFO: Ready to synchronize juliet (readwrite)
[xxxxx] DEBUG: Versioner clean: Waiting for lock on x
[xxxxx] DEBUG: db check completed for "indigo"
[xxxxx] DEBUG: Versioner clean: Cleaning x
[xxxxx] DEBUG: loaded sequence for "indigo": 0
[xxxxx] INFO: Ready to synchronize indigo (readwrite)
[xxxxx] DEBUG: db check completed for "charlie"
[xxxxx] DEBUG: loaded sequence for "charlie": 0
[xxxxx] DEBUG: Versioner: Expiring versions [x]
[xxxxx] DEBUG: Versioner: Expiring versions [x]
[xxxxx] DEBUG: Versioner: Expiring versions [x]
[xxxxx] DEBUG: Versioner: Expiring versions [x]
[xxxxx] DEBUG: Versioner: Expiring versions [x]
[xxxxx] DEBUG: Versioner: Expiring versions [x x x x]
[xxxxx] DEBUG: Versioner: Expiring versions [x x x x]
[xxxxx] DEBUG: Versioner: Expiring versions [x x x x]
[xxxxx] DEBUG: Versioner: Expiring versions [x]
[xxxxx] DEBUG: Versioner: Expiring versions [x]
[xxxxx] DEBUG: Versioner: Expiring versions [x x]
[xxxxx] DEBUG: Versioner: Expiring versions [x x x x]
[xxxxx] DEBUG: Cleaner: Finished cleaning x
[xxxxx] INFO: Ready to synchronize charlie (readwrite)
[xxxxx] DEBUG: db check completed for "kilo"
[xxxxx] DEBUG: loaded sequence for "kilo": 0
[xxxxx] DEBUG: instantiated versioner.Simple{keep:2, folderPath:"x"}
[xxxxx] INFO: Ready to synchronize kilo (readwrite)
[xxxxx] DEBUG: db check completed for "lima"
[xxxxx] DEBUG: loaded sequence for "lima": 0
[xxxxx] INFO: Ready to synchronize lima (readwrite)
[xxxxx] DEBUG: db check completed for "mike"
panic: bug: lookup of nonexistent device ID

goroutine 1 [running]:
panic(0x9c83a0, 0xc420016640)
	/usr/lib/go/src/runtime/panic.go:500 +0x1a1
github.com/syncthing/syncthing/lib/db.(*Instance).deviceKeyDevice(0xc4201b05a0, 0xc420011480, 0x20, 0x20, 0xc420328000, 0x0, 0x0)
	/var/tmp/portage/net-p2p/syncthing-0.14.15/work/syncthing-0.14.15/src/github.com/syncthing/syncthing/lib/db/leveldb_dbinstance.go:660 +0x115
github.com/syncthing/syncthing/lib/db.(*Instance).withAllFolderTruncated(0xc4201b05a0, 0xc420016580, 0xc, 0x10, 0xc420264188)
	/var/tmp/portage/net-p2p/syncthing-0.14.15/work/syncthing-0.14.15/src/github.com/syncthing/syncthing/lib/db/leveldb_dbinstance.go:281 +0x226
github.com/syncthing/syncthing/lib/db.NewFileSet(0xc420356794, 0xc, 0xc4201b05a0, 0xc4202644f0)
	/var/tmp/portage/net-p2p/syncthing-0.14.15/work/syncthing-0.14.15/src/github.com/syncthing/syncthing/lib/db/set.go:139 +0x2e8
github.com/syncthing/syncthing/lib/model.(*Model).addFolderLocked(0xc4200b6640, 0xc420356794, 0xc, 0x0, 0x0, 0xc420019ce0, 0x23, 0x0, 0xc420353d00, 0x2, ...)
	/var/tmp/portage/net-p2p/syncthing-0.14.15/work/syncthing-0.14.15/src/github.com/syncthing/syncthing/lib/model/model.go:307 +0xd2
github.com/syncthing/syncthing/lib/model.(*Model).AddFolder(0xc4200b6640, 0xc420356794, 0xc, 0x0, 0x0, 0xc420019ce0, 0x23, 0x0, 0xc420353d00, 0x2, ...)
	/var/tmp/portage/net-p2p/syncthing-0.14.15/work/syncthing-0.14.15/src/github.com/syncthing/syncthing/lib/model/model.go:301 +0xa1
main.syncthingMain(0x0, 0x0, 0x0, 0x0, 0x0, 0x1, 0xaa2444, 0x1, 0x0, 0x0, ...)
	/var/tmp/portage/net-p2p/syncthing-0.14.15/work/syncthing-0.14.15/src/github.com/syncthing/syncthing/cmd/syncthing/main.go:708 +0x1158
main.main()
	/var/tmp/portage/net-p2p/syncthing-0.14.15/work/syncthing-0.14.15/src/github.com/syncthing/syncthing/cmd/syncthing/main.go:376 +0x220

goroutine 17 [syscall, locked to thread]:
runtime.goexit()
	/usr/lib/go/src/runtime/asm_amd64.s:2086 +0x1

goroutine 22 [syscall]:
os/signal.signal_recv(0x0)
	/usr/lib/go/src/runtime/sigqueue.go:116 +0x157
os/signal.loop()
	/usr/lib/go/src/os/signal/signal_unix.go:22 +0x22
created by os/signal.init.1
	/usr/lib/go/src/os/signal/signal_unix.go:28 +0x41

goroutine 24 [chan receive]:
main.trackCPUUsage()
	/var/tmp/portage/net-p2p/syncthing-0.14.15/work/syncthing-0.14.15/src/github.com/syncthing/syncthing/cmd/syncthing/gui_unix.go:24 +0xf9
created by main.init.3
	/var/tmp/portage/net-p2p/syncthing-0.14.15/work/syncthing-0.14.15/src/github.com/syncthing/syncthing/cmd/syncthing/gui_unix.go:17 +0x35

goroutine 25 [select, locked to thread]:
runtime.gopark(0xc796c0, 0x0, 0xaa53f4, 0x6, 0x18, 0x2)
	/usr/lib/go/src/runtime/proc.go:259 +0x13a
runtime.selectgoImpl(0xc42002df30, 0x0, 0x18)
	/usr/lib/go/src/runtime/select.go:423 +0x11d9
runtime.selectgo(0xc42002df30)
	/usr/lib/go/src/runtime/select.go:238 +0x1c
runtime.ensureSigM.func1()
	/usr/lib/go/src/runtime/signal1_unix.go:304 +0x2f3
runtime.goexit()
	/usr/lib/go/src/runtime/asm_amd64.s:2086 +0x1

goroutine 26 [chan receive]:
main.setupSignalHandling.func1(0xc420078900)
	/var/tmp/portage/net-p2p/syncthing-0.14.15/work/syncthing-0.14.15/src/github.com/syncthing/syncthing/cmd/syncthing/main.go:844 +0x40
created by main.setupSignalHandling
	/var/tmp/portage/net-p2p/syncthing-0.14.15/work/syncthing-0.14.15/src/github.com/syncthing/syncthing/cmd/syncthing/main.go:846 +0xfa

goroutine 3 [chan receive]:
main.setupSignalHandling.func2(0xc420078a80)
	/var/tmp/portage/net-p2p/syncthing-0.14.15/work/syncthing-0.14.15/src/github.com/syncthing/syncthing/cmd/syncthing/main.go:854 +0x40
created by main.setupSignalHandling
	/var/tmp/portage/net-p2p/syncthing-0.14.15/work/syncthing-0.14.15/src/github.com/syncthing/syncthing/cmd/syncthing/main.go:856 +0x1f5

goroutine 4 [select]:
github.com/syncthing/syncthing/vendor/github.com/thejerf/suture.(*Supervisor).Serve(0xc42001c0e0)
	/var/tmp/portage/net-p2p/syncthing-0.14.15/work/syncthing-0.14.15/src/github.com/syncthing/syncthing/vendor/github.com/thejerf/suture/supervisor.go:338 +0xe61
created by github.com/syncthing/syncthing/vendor/github.com/thejerf/suture.(*Supervisor).ServeBackground
	/var/tmp/portage/net-p2p/syncthing-0.14.15/work/syncthing-0.14.15/src/github.com/syncthing/syncthing/vendor/github.com/thejerf/suture/supervisor.go:297 +0x43

goroutine 5 [select]:
github.com/syncthing/syncthing/lib/events.(*Subscription).Poll(0xc4200105e0, 0xdf8475800, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
	/var/tmp/portage/net-p2p/syncthing-0.14.15/work/syncthing-0.14.15/src/github.com/syncthing/syncthing/lib/events/events.go:239 +0x3f8
github.com/syncthing/syncthing/lib/events.(*bufferedSubscription).pollingLoop(0xc420020190)
	/var/tmp/portage/net-p2p/syncthing-0.14.15/work/syncthing-0.14.15/src/github.com/syncthing/syncthing/lib/events/events.go:293 +0x55
created by github.com/syncthing/syncthing/lib/events.NewBufferedSubscription
	/var/tmp/portage/net-p2p/syncthing-0.14.15/work/syncthing-0.14.15/src/github.com/syncthing/syncthing/lib/events/events.go:287 +0x1e1

goroutine 6 [select]:
github.com/syncthing/syncthing/lib/events.(*Subscription).Poll(0xc4200106a0, 0xdf8475800, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
	/var/tmp/portage/net-p2p/syncthing-0.14.15/work/syncthing-0.14.15/src/github.com/syncthing/syncthing/lib/events/events.go:239 +0x3f8
github.com/syncthing/syncthing/lib/events.(*bufferedSubscription).pollingLoop(0xc4200201e0)
	/var/tmp/portage/net-p2p/syncthing-0.14.15/work/syncthing-0.14.15/src/github.com/syncthing/syncthing/lib/events/events.go:293 +0x55
created by github.com/syncthing/syncthing/lib/events.NewBufferedSubscription
	/var/tmp/portage/net-p2p/syncthing-0.14.15/work/syncthing-0.14.15/src/github.com/syncthing/syncthing/lib/events/events.go:287 +0x1e1

goroutine 11 [select]:
github.com/syncthing/syncthing/vendor/github.com/syndtr/goleveldb/leveldb/util.(*BufferPool).drain(0xc4200aa0e0)
	/var/tmp/portage/net-p2p/syncthing-0.14.15/work/syncthing-0.14.15/src/github.com/syncthing/syncthing/vendor/github.com/syndtr/goleveldb/leveldb/util/buffer_pool.go:206 +0x247
created by github.com/syncthing/syncthing/vendor/github.com/syndtr/goleveldb/leveldb/util.NewBufferPool
	/var/tmp/portage/net-p2p/syncthing-0.14.15/work/syncthing-0.14.15/src/github.com/syncthing/syncthing/vendor/github.com/syndtr/goleveldb/leveldb/util/buffer_pool.go:237 +0x1bc

goroutine 27 [select]:
github.com/syncthing/syncthing/vendor/github.com/syndtr/goleveldb/leveldb.(*DB).compactionError(0xc4204a9080)
	/var/tmp/portage/net-p2p/syncthing-0.14.15/work/syncthing-0.14.15/src/github.com/syncthing/syncthing/vendor/github.com/syndtr/goleveldb/leveldb/db_compaction.go:90 +0x5e1
created by github.com/syncthing/syncthing/vendor/github.com/syndtr/goleveldb/leveldb.openDB
	/var/tmp/portage/net-p2p/syncthing-0.14.15/work/syncthing-0.14.15/src/github.com/syncthing/syncthing/vendor/github.com/syndtr/goleveldb/leveldb/db.go:141 +0x620

goroutine 28 [select]:
github.com/syncthing/syncthing/vendor/github.com/syndtr/goleveldb/leveldb.(*DB).mpoolDrain(0xc4204a9080)
	/var/tmp/portage/net-p2p/syncthing-0.14.15/work/syncthing-0.14.15/src/github.com/syncthing/syncthing/vendor/github.com/syndtr/goleveldb/leveldb/db_state.go:96 +0x249
created by github.com/syncthing/syncthing/vendor/github.com/syndtr/goleveldb/leveldb.openDB
	/var/tmp/portage/net-p2p/syncthing-0.14.15/work/syncthing-0.14.15/src/github.com/syncthing/syncthing/vendor/github.com/syndtr/goleveldb/leveldb/db.go:142 +0x642

goroutine 29 [select]:
github.com/syncthing/syncthing/vendor/github.com/syndtr/goleveldb/leveldb.(*DB).tCompaction(0xc4204a9080)
	/var/tmp/portage/net-p2p/syncthing-0.14.15/work/syncthing-0.14.15/src/github.com/syncthing/syncthing/vendor/github.com/syndtr/goleveldb/leveldb/db_compaction.go:804 +0x83c
created by github.com/syncthing/syncthing/vendor/github.com/syndtr/goleveldb/leveldb.openDB
	/var/tmp/portage/net-p2p/syncthing-0.14.15/work/syncthing-0.14.15/src/github.com/syncthing/syncthing/vendor/github.com/syndtr/goleveldb/leveldb/db.go:148 +0x7c8

goroutine 30 [select]:
github.com/syncthing/syncthing/vendor/github.com/syndtr/goleveldb/leveldb.(*DB).mCompaction(0xc4204a9080)
	/var/tmp/portage/net-p2p/syncthing-0.14.15/work/syncthing-0.14.15/src/github.com/syncthing/syncthing/vendor/github.com/syndtr/goleveldb/leveldb/db_compaction.go:751 +0x263
created by github.com/syncthing/syncthing/vendor/github.com/syndtr/goleveldb/leveldb.openDB
	/var/tmp/portage/net-p2p/syncthing-0.14.15/work/syncthing-0.14.15/src/github.com/syncthing/syncthing/vendor/github.com/syndtr/goleveldb/leveldb/db.go:149 +0x7ea

goroutine 31 [select]:
github.com/syncthing/syncthing/vendor/github.com/syndtr/goleveldb/leveldb.(*DB).jWriter(0xc4204a9080)
	/var/tmp/portage/net-p2p/syncthing-0.14.15/work/syncthing-0.14.15/src/github.com/syncthing/syncthing/vendor/github.com/syndtr/goleveldb/leveldb/db_write.go:37 +0x1ad
created by github.com/syncthing/syncthing/vendor/github.com/syndtr/goleveldb/leveldb.openDB
	/var/tmp/portage/net-p2p/syncthing-0.14.15/work/syncthing-0.14.15/src/github.com/syncthing/syncthing/vendor/github.com/syndtr/goleveldb/leveldb/db.go:150 +0x80c

goroutine 32 [select]:
github.com/syncthing/syncthing/lib/model.(*ProgressEmitter).Serve(0xc4201ae320)
	/var/tmp/portage/net-p2p/syncthing-0.14.15/work/syncthing-0.14.15/src/github.com/syncthing/syncthing/lib/model/progressemitter.go:56 +0x586
created by github.com/syncthing/syncthing/lib/model.NewModel
	/var/tmp/portage/net-p2p/syncthing-0.14.15/work/syncthing-0.14.15/src/github.com/syncthing/syncthing/lib/model/model.go:166 +0x9dd

goroutine 33 [chan receive]:
github.com/syncthing/syncthing/lib/versioner.NewStaggered.func1(0xc4200a6240, 0x28, 0xe10, 0xc420367e60, 0x1d, 0x1e, 0xe10, 0xe10, 0x15180, 0x15180, ...)
	/var/tmp/portage/net-p2p/syncthing-0.14.15/work/syncthing-0.14.15/src/github.com/syncthing/syncthing/lib/versioner/staggered.go:80 +0xdf
created by github.com/syncthing/syncthing/lib/versioner.NewStaggered
	/var/tmp/portage/net-p2p/syncthing-0.14.15/work/syncthing-0.14.15/src/github.com/syncthing/syncthing/lib/versioner/staggered.go:83 +0x499
@calmh
Copy link
Member

calmh commented Jan 4, 2017

Yeah same/similar but potentially worse. I wonder what happened to your database. Nothing interesting in it's history that you know about?

@ghost
Copy link
Author

ghost commented Jan 4, 2017

I can't think of anything interesting about the use or activity beforehand. (I imagine that's also a product of not knowing what to remember/notice before failure). I only have the snapshot of it in the broken state. I don't recall whether power loss was a factor, though I did lose power earlier in the week and did not lose my current database, so perhaps not.

@calmh calmh closed this as completed Feb 7, 2017
@st-review st-review added the frozen-due-to-age Issues closed and untouched for a long time, together with being locked for discussion label Feb 8, 2018
@syncthing syncthing locked and limited conversation to collaborators Feb 8, 2018
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
frozen-due-to-age Issues closed and untouched for a long time, together with being locked for discussion
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@calmh @st-review