Branch page items link to already released pages

[shippomx]

Feb  7 02:22:16 localhost dockerd[9618]: time="2023-02-07T02:22:16.932095276+08:00" level=info msg="createNetwork setupMulticastOn"
Feb  7 02:22:20 localhost dockerd[9618]: runtime: goroutine stack exceeds 1000000000-byte limit
Feb  7 02:22:20 localhost dockerd[9618]: fatal error: stack overflow
Feb  7 02:22:20 localhost dockerd[9618]: runtime stack:
Feb  7 02:22:20 localhost dockerd[9618]: runtime.throw(0x193e06d, 0xe)
Feb  7 02:22:20 localhost dockerd[9618]: /usr/local/go/src/runtime/panic.go:617 +0x72
Feb  7 02:22:20 localhost dockerd[9618]: runtime.newstack()
Feb  7 02:22:20 localhost dockerd[9618]: /usr/local/go/src/runtime/stack.go:1041 +0x6f0
Feb  7 02:22:20 localhost dockerd[9618]: runtime.morestack()
Feb  7 02:22:20 localhost dockerd[9618]: /usr/local/go/src/runtime/asm_amd64.s:429 +0x8f
Feb  7 02:22:20 localhost dockerd[9618]: goroutine 1 [running]:
Feb  7 02:22:20 localhost dockerd[9618]: github.com/docker/docker/vendor/github.com/boltdb/bolt.(*Cursor).searchPage.func1(0x7, 0x0)
Feb  7 02:22:20 localhost dockerd[9618]: /root/rpmbuild/BUILD/docker-ce/.gopath/src/github.com/docker/docker/vendor/github.com/boltdb/bolt/cursor.go:299 +0xda fp=0xc024000350 sp=0xc024000348 pc=0xd5c97a
Feb  7 02:22:20 localhost dockerd[9618]: sort.Search(0xf, 0xc0240003c8, 0x0)
Feb  7 02:22:20 localhost dockerd[9618]: /usr/local/go/src/sort/search.go:66 +0x58 fp=0xc024000388 sp=0xc024000350 pc=0x4b84c8
Feb  7 02:22:20 localhost dockerd[9618]: github.com/docker/docker/vendor/github.com/boltdb/bolt.(*Cursor).searchPage(0xc043ffe338, 0xc000ff16b0, 0x24, 0x30, 0x7f41ac043000)
Feb  7 02:22:20 localhost dockerd[9618]: /root/rpmbuild/BUILD/docker-ce/.gopath/src/github.com/docker/docker/vendor/github.com/boltdb/bolt/cursor.go:299 +0xd0 fp=0xc024000418 sp=0xc024000388 pc=0xd4fb10
Feb  7 02:22:20 localhost dockerd[9618]: github.com/docker/docker/vendor/github.com/boltdb/bolt.(*Cursor).search(0xc043ffe338, 0xc000ff16b0, 0x24, 0x30, 0x1b)
Feb  7 02:22:20 localhost dockerd[9618]: /root/rpmbuild/BUILD/docker-ce/.gopath/src/github.com/docker/docker/vendor/github.com/boltdb/bolt/cursor.go:271 +0x18b fp=0xc0240004b8 sp=0xc024000418 pc=0xd4f72b
Feb  7 02:22:20 localhost dockerd[9618]: github.com/docker/docker/vendor/github.com/boltdb/bolt.(*Cursor).searchPage(0xc043ffe338, 0xc000ff16b0, 0x24, 0x30, 0x7f41ac044000)
Feb  7 02:22:20 localhost dockerd[9618]: /root/rpmbuild/BUILD/docker-ce/.gopath/src/github.com/docker/docker/vendor/github.com/boltdb/bolt/cursor.go:314 +0x153 fp=0xc024000548 sp=0xc0240004b8 pc=0xd4fb93
Feb  7 02:22:20 localhost dockerd[9618]: github.com/docker/docker/vendor/github.com/boltdb/bolt.(*Cursor).search(0xc043ffe338, 0xc000ff16b0, 0x24, 0x30, 0x1c)
Feb  7 02:22:20 localhost dockerd[9618]: /root/rpmbuild/BUILD/docker-ce/.gopath/src/github.com/docker/docker/vendor/github.com/boltdb/bolt/cursor.go:271 +0x18b fp=0xc0240005e8 sp=0xc024000548 pc=0xd4f72b
Feb  7 02:22:20 localhost dockerd[9618]: github.com/docker/docker/vendor/github.com/boltdb/bolt.(*Cursor).searchPage(0xc043ffe338, 0xc000ff16b0, 0x24, 0x30, 0x7f41ac03f000)
Feb  7 02:22:20 localhost dockerd[9618]: /root/rpmbuild/BUILD/docker-ce/.gopath/src/github.com/docker/docker/vendor/github.com/boltdb/bolt/cursor.go:314 +0x153 fp=0xc024000678 sp=0xc0240005e8 pc=0xd4fb93
Feb  7 02:22:20 localhost dockerd[9618]: github.com/docker/docker/vendor/github.com/boltdb/bolt.(*Cursor).search(0xc043ffe338, 0xc000ff16b0, 0x24, 0x30, 0x17)
Feb  7 02:22:20 localhost dockerd[9618]: /root/rpmbuild/BUILD/docker-ce/.gopath/src/github.com/docker/docker/vendor/github.com/boltdb/bolt/cursor.go:271 +0x18b fp=0xc024000718 sp=0xc024000678 pc=0xd4f72b
Feb  7 02:22:20 localhost dockerd[9618]: github.com/docker/docker/vendor/github.com/boltdb/bolt.(*Cursor).searchPage(0xc043ffe338, 0xc000ff16b0, 0x24, 0x30, 0x7f41ac043000)
...

I use an old version of docker 17.03, and get this error mesage. And yet I add some logs to record this collapse.

 // etcd-io/bbolt/cursor.go:271
func (c *Cursor) search(key []byte, pgid pgid) {
	fmt.Printf("\nsearch: key = %s, pgid = %d\n", string(key), pgid)

 // etcd-io/bbolt/cursor.go:312
func (c *Cursor) searchPage(key []byte, p *page) {
	fmt.Printf("searchPage: key = %s, pgid = %d\n", string(key), p.id)

 // etcd-io/bbolt/cursor.go:323
                ret := bytes.Compare(inodes[i].key(), key)
		if ret == 0 {
			exact = true
		}
		fmt.Printf("\tinodes[%d].key() = %s, ret = %d\n", i, string(inodes[i].key()), ret)
		return ret != -1

and get this logs:

search: key = docker/network/v1.0/macvlan/network/, pgid = 34
searchPage: key = docker/network/v1.0/macvlan/network/, pgid = 34
    inodes[1].key() = docker/network/v1.0/endpoint/b33697a6c83bdf8949f8f6c91060a15114399af3a274090a05c2853558526ad1/97f1c83d06a0cb2ec9a2705829c89964ab611f8d3ff004e1a6eb7336a745de45/, ret = -1
    index = 1, inodes[index].pgid = 29

search: key = docker/network/v1.0/macvlan/network/, pgid = 29
searchPage: key = docker/network/v1.0/macvlan/network/, pgid = 29
    inodes[8].key() = docker/network/v1.0/sandbox/10c76cdf0b7a99e32375cc1d3c4eb38e0f9b564e0f98524c91beabdcff6a67cb/, ret = 1
    inodes[4].key() = docker/network/v1.0/endpoint/fb49c1610068fcbb52209ff50b144ea2a6b97bf8e70985e4971df61463508f3c/97f47d111ec6a95a53494fd2f3b3354e7e6c27d8bfb1a5471fa25f12859e0d2e/, ret = -1
    inodes[6].key() = docker/network/v1.0/network/3aefb08cc24b4dae33c35b7f16edfcce3667a10fb9dfa9e23f5ee3c6a5dde4ff/, ret = 1
    inodes[5].key() = docker/network/v1.0/endpoint/fb49c1610068fcbb52209ff50b144ea2a6b97bf8e70985e4971df61463508f3c/f43012f4ce2d86fc86897bacc4593d38c4bf607ffd85ac7fb03b9f7a6eae845a/, ret = -1
    index = 5, inodes[index].pgid = 23

search: key = docker/network/v1.0/macvlan/network/, pgid = 23
searchPage: key = docker/network/v1.0/macvlan/network/, pgid = 23
    inodes[8].key() = docker/network/v1.0/sandbox/0a36df8c90515a4a81d8f2279eb4e03371441534e52befb6f8dbad5e604d0d73/, ret = 1
    inodes[4].key() = docker/network/v1.0/endpoint/fb49c1610068fcbb52209ff50b144ea2a6b97bf8e70985e4971df61463508f3c/97f47d111ec6a95a53494fd2f3b3354e7e6c27d8bfb1a5471fa25f12859e0d2e/, ret = -1
    inodes[6].key() = docker/network/v1.0/network/3aefb08cc24b4dae33c35b7f16edfcce3667a10fb9dfa9e23f5ee3c6a5dde4ff/, ret = 1
    inodes[5].key() = docker/network/v1.0/endpoint/fb49c1610068fcbb52209ff50b144ea2a6b97bf8e70985e4971df61463508f3c/f43012f4ce2d86fc86897bacc4593d38c4bf607ffd85ac7fb03b9f7a6eae845a/, ret = -1
    index = 5, inodes[index].pgid = 28

search: key = docker/network/v1.0/macvlan/network/, pgid = 28
searchPage: key = docker/network/v1.0/macvlan/network/, pgid = 28
    inodes[1].key() = docker/network/v1.0/endpoint/b33697a6c83bdf8949f8f6c91060a15114399af3a274090a05c2853558526ad1/97f1c83d06a0cb2ec9a2705829c89964ab611f8d3ff004e1a6eb7336a745de45/, ret = -1
    index = 1, inodes[index].pgid = 27

search: key = docker/network/v1.0/macvlan/network/, pgid = 27
searchPage: key = docker/network/v1.0/macvlan/network/, pgid = 27
    inodes[7].key() = docker/network/v1.0/network/fb49c1610068fcbb52209ff50b144ea2a6b97bf8e70985e4971df61463508f3c/, ret = 1
    inodes[3].key() = docker/network/v1.0/endpoint/fb49c1610068fcbb52209ff50b144ea2a6b97bf8e70985e4971df61463508f3c/1158eed39c59a5dfff638074e48e26ce36f4dce086389af02f0ef87a852195b8/, ret = -1
    inodes[5].key() = docker/network/v1.0/endpoint/fb49c1610068fcbb52209ff50b144ea2a6b97bf8e70985e4971df61463508f3c/f43012f4ce2d86fc86897bacc4593d38c4bf607ffd85ac7fb03b9f7a6eae845a/, ret = -1
    inodes[6].key() = docker/network/v1.0/network/3aefb08cc24b4dae33c35b7f16edfcce3667a10fb9dfa9e23f5ee3c6a5dde4ff/, ret = 1
    index = 5, inodes[index].pgid = 23

search: key = docker/network/v1.0/macvlan/network/, pgid = 23
searchPage: key = docker/network/v1.0/macvlan/network/, pgid = 23
    inodes[8].key() = docker/network/v1.0/sandbox/0a36df8c90515a4a81d8f2279eb4e03371441534e52befb6f8dbad5e604d0d73/, ret = 1
    inodes[4].key() = docker/network/v1.0/endpoint/fb49c1610068fcbb52209ff50b144ea2a6b97bf8e70985e4971df61463508f3c/97f47d111ec6a95a53494fd2f3b3354e7e6c27d8bfb1a5471fa25f12859e0d2e/, ret = -1
    inodes[6].key() = docker/network/v1.0/network/3aefb08cc24b4dae33c35b7f16edfcce3667a10fb9dfa9e23f5ee3c6a5dde4ff/, ret = 1
    inodes[5].key() = docker/network/v1.0/endpoint/fb49c1610068fcbb52209ff50b144ea2a6b97bf8e70985e4971df61463508f3c/f43012f4ce2d86fc86897bacc4593d38c4bf607ffd85ac7fb03b9f7a6eae845a/, ret = -1
    index = 5, inodes[index].pgid = 28

I have dumped the db file as follows.
local-kv.db.tar.gz

I know something may result the db broken, but is there some methods to avoid this?

[shippomx]

@benbjohnson Can you give me some advices?

[ahrtr]

The page 23 is freed, but it's still somehow referenced by page 29.

$ bolt pages ./local-kv.db 
ID       TYPE       ITEMS  OVRFLW
======== ========== ====== ======
0        meta       0            
1        meta       0            
2        leaf       3            
3        leaf       5            
4        leaf       3            
5        leaf       2            
6        leaf       2            
7        leaf       2            
8        leaf       2            
9        leaf       3            
10       leaf       5            
11       leaf       2            
12       leaf       2            
13       leaf       3            
14       leaf       4            
15       leaf       4            
16       leaf       2            
17       leaf       4            
18       leaf       7            
19       leaf       4            
20       leaf       3            
21       leaf       3            
22       leaf       2            
23       free                    
24       leaf       6            
25       leaf       3            
26       leaf       2            
27       free                    
28       free                    
29       branch     16           
30       branch     13 
......

$ bolt page ./local-kv.db  29
Page ID:    29
Page Type:  branch
Total Size: 4096 bytes
Overflow pages: 0
Item Count: 16

"docker/network/v1.0/endpoint/b33697a6c83bdf8949f8f6c91060a15114399af3a274090a05c2853558526ad1/97f1c83d06a0cb2ec9a2705829c89964ab611f8d3ff004e1a6eb7336a745de45/": <pgid=35>
"docker/network/v1.0/endpoint/b33697a6c83bdf8949f8f6c91060a15114399af3a274090a05c2853558526ad1/b02586531c17670ca4690990dcc50d87dfd05c5e7f131d5417a528e67497a783/": <pgid=22>
"docker/network/v1.0/endpoint/b33697a6c83bdf8949f8f6c91060a15114399af3a274090a05c2853558526ad1/b9a2e9ca2bc1c7b00d60f3301e6a56993d9b468626e7a1b9ef65c530b9ac5f3c/": <pgid=38>
"docker/network/v1.0/endpoint/fb49c1610068fcbb52209ff50b144ea2a6b97bf8e70985e4971df61463508f3c/1158eed39c59a5dfff638074e48e26ce36f4dce086389af02f0ef87a852195b8/": <pgid=11>
"docker/network/v1.0/endpoint/fb49c1610068fcbb52209ff50b144ea2a6b97bf8e70985e4971df61463508f3c/97f47d111ec6a95a53494fd2f3b3354e7e6c27d8bfb1a5471fa25f12859e0d2e/": <pgid=25>
"docker/network/v1.0/endpoint/fb49c1610068fcbb52209ff50b144ea2a6b97bf8e70985e4971df61463508f3c/f43012f4ce2d86fc86897bacc4593d38c4bf607ffd85ac7fb03b9f7a6eae845a/": <pgid=23>
"docker/network/v1.0/network/3aefb08cc24b4dae33c35b7f16edfcce3667a10fb9dfa9e23f5ee3c6a5dde4ff/": <pgid=5>
"docker/network/v1.0/network/fb49c1610068fcbb52209ff50b144ea2a6b97bf8e70985e4971df61463508f3c/": <pgid=2>
"docker/network/v1.0/sandbox/10c76cdf0b7a99e32375cc1d3c4eb38e0f9b564e0f98524c91beabdcff6a67cb/": <pgid=24>
"docker/network/v1.0/sandbox/183088884b55acbda71c93a883b4fab1d7a0af6533779742b16949fe289b6b16/": <pgid=18>
"docker/network/v1.0/sandbox/3e9292be50bb4fc02369770ed956c6d05f678dd3334a1a289857518c11fd4c74/": <pgid=19>
"docker/network/v1.0/sandbox/6066d5f48d5afe47f47b94f0f41bc69ad9eaaf2a9f050a834789d2e1f76429ec/": <pgid=3>
"docker/network/v1.0/sandbox/a9e41d9429735297326d4d14239b7131e93dcf0af293b5e07bb7af2e5582be09/": <pgid=14>
"docker/network/v1.0/sandbox/c69467c92606a45653f2cd4133b84da325f03d1b7fbba83743bfe1dd1b44df8c/": <pgid=4>
"docker/network/v1.0/sandbox/d8e74c9d9f58689e8abfecbc78197f617c1e95a4643a0005d14b5ce2fb035619/": <pgid=20>
"docker/network/v1.0/sandbox/e5dfbe123d17d8205ee1892b8e452d092501eb05c9338eed7180ef402894320b/": <pgid=32>

There must be something wrong when releasing a page (page 23 in this case). Will take a look later when I get free cycle.

[ahrtr]

The root cause is still under investigation, but there is a tool to fix the corrupted db file. Please read #408, and let me know whether it works for you. @shippomx

[ahrtr]

@shippomx do you have detailed steps or a program to reproduce this issue, and what's the bbolt version on which you reproduced this issue?

[ahrtr]

Usually the difference between the two Txn ID in meta pages should be 1; it doesn't make sense it's 7 (54498 - 54491). Do you run a customized bbolt?

$ bbolt page ./local-kv.db 0
Page ID:    0
Page Type:  meta
Total Size: 4096 bytes
Version:    2
Page Size:  4096 bytes
Flags:      00000000
Root:       <pgid=36>
Freelist:   <pgid=40>
HWM:        <pgid=57>
Txn ID:     54498
Checksum:   a7487e9a0514ba80

$ bbolt page ./local-kv.db 1
Page ID:    1
Page Type:  meta
Total Size: 4096 bytes
Version:    2
Page Size:  4096 bytes
Flags:      00000000
Root:       <pgid=39>
Freelist:   <pgid=40>
HWM:        <pgid=57>
Txn ID:     54491
Checksum:   d19106352fdf1722

[shippomx]

I just use moby (docker). Some unpredictable complex situation may cause the db file broken.

[ahrtr]

Can you answer my previous question? #402 (comment)

1. What's the exact bbolt version on which you ran into this issue?
2. Could you provide detailed step (and program) to reproduce this issue?

[shippomx]

Can you answer my previous question? #402 (comment)

1. What's the exact bbolt version on which you ran into this issue?
   https://github.com/moby/moby/blob/master/vendor.mod#L89
   go.etcd.io/bbolt v1.3.6

2. Could you provide detailed step (and program) to reproduce this issue?
   Step1. build and run the dockerd
   Step2. stop dockerd, replace the /var/lib/docker/network/files/local-kv.db with the file which i attached in this issue.
   Step3. restart dockerd

But i have no idea with how this local-kv.db file broken.

[ptabor]

Moby seems to use raw bbolt:
https://github.com/moby/moby/blob/e068c38618ff94e3be9e572c568be3bed396c263/vendor.mod#L89

It's interesting how this happened. I have no other idea than 7 rolled back transactions and 8th successful in scope of the same binary running. That might suggests rollback are not that safe... and maybe it's how the race on meta-page fixed recently (in 1.3.7) manifests.