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.

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

upspinserver spending months in some sort of a read loop #624

Open
filmil opened this issue Sep 18, 2019 · 7 comments
Open

upspinserver spending months in some sort of a read loop #624

filmil opened this issue Sep 18, 2019 · 7 comments

Comments

@filmil
Copy link
Contributor

filmil commented Sep 18, 2019

My upspinserver has been busy for months in the following loop. Sadly I had to restart the machine, so only have recent server logs to show. But, this is what transpires. Once upspinserver is started,
it prints the messages below, then goes on to a many-weeks-long read spree. Where the tail end of the log excerpt above is repeated ad infinitum (except, different hashes every time).

In the past, I kept the machine up for months with upspinserver running, and it just kept going.

I wouldn't mind it since it's not a cloud machine; except that the read spree seems to starve completely any other clients that attempt to connect. So upspin utility and upspinfs become unusable as they wait indefinitely for something to happen. What to do?

 LOGLEVEL=debug
+ UPSPINSERVER=/go/bin/upspinserver
+ sudo /go/bin/upspinserver --letscache=/home/f/upspin/letsencrypt --config=/home/f/config --serverconfig=/home/f/upspin/server --http=:33000 --https=:443 --web --log=debug
2019/09/18 06:53:08.714969 Store and Directory servers initialized.
2019/09/18 06:53:08.715331 Store server configuration: backend=Disk basePath=/home/f/upspin/server/storage
2019/09/18 06:53:08.715357 https: serving HTTPS on ":443" using Let's Encrypt certificates
2019/09/18 06:53:08.715364 https: caching Let's Encrypt certificates in /home/f/upspin/letsencrypt
2019/09/18 06:53:08.806556 recoverFromLog: Recovering from log... 260780
2019/09/18 06:53:08.813198 recoverFromLog: Putting dirEntry: "f+snapshot@filmar.us/2019/04/30"
2019/09/18 06:53:08.830271 store/remote("").Dial("upspin@filmar.us", "remote,udir.filmar.us:443")
2019/09/18 06:53:08.830313 store/remote("udir.filmar.us:443").Get("0E845C7852C7E23E8246133F69DD0254AE0BB2B8110928CBF673C20A64E71177")
2019/09/18 06:53:08.830321 store/remote("udir.filmar.us:443").Get("metadata:HTTP-Base")
2019/09/18 06:53:08.980522 rpc/storeserver: "upspin@filmar.us": store.Get("metadata:HTTP-Base")
2019/09/18 06:53:08.980541 rpc/storeserver: "upspin@filmar.us": store.Get("metadata:HTTP-Base")
2019/09/18 06:53:08.980810 rpc/storeserver: "upspin@filmar.us": store.Get("0E845C7852C7E23E8246133F69DD0254AE0BB2B8110928CBF673C20A64E71177")
2019/09/18 06:53:09.103248 store/remote("udir.filmar.us:443").Get("7E8F6C3D714AAF472487E5C655337BC490EA97FA760B1E2280A266C8FE896007")
2019/09/18 06:53:09.103603 rpc/storeserver: "upspin@filmar.us": store.Get("7E8F6C3D714AAF472487E5C655337BC490EA97FA760B1E2280A266C8FE896007")
2019/09/18 06:53:09.213655 store/remote("udir.filmar.us:443").Get("B0B96B9A07EEF38427E8BA50D9313D10B100CBABDAAF8B41997FC3B43413AEB9")
2019/09/18 06:53:09.214000 rpc/storeserver: "upspin@filmar.us": store.Get("B0B96B9A07EEF38427E8BA50D9313D10B100CBABDAAF8B41997FC3B43413AEB9")
2019/09/18 06:53:09.331666 recoverFromLog: Recovering from log... 260853
2019/09/18 06:53:09.331706 recoverFromLog: Putting dirEntry: "f+snapshot@filmar.us/2019/04/30/05:13"
2019/09/18 06:53:09.331721 recoverFromLog: Recovering from log... 261487
2019/09/18 06:53:09.331731 recoverFromLog: 2 entries recovered. Tree is current.
2019/09/18 06:53:09.332043 store/remote("udir.filmar.us:443").Get("DDB6E0761D2BD5A1BF6C8BC2D846E3DB2A7006C9D7D0215662C6B77D47A9FB28")
2019/09/18 06:53:09.332255 rpc/storeserver: "upspin@filmar.us": store.Get("DDB6E0761D2BD5A1BF6C8BC2D846E3DB2A7006C9D7D0215662C6B77D47A9FB28")
2019/09/18 06:53:09.406824 store/remote("udir.filmar.us:443").Get("70609FC23BB6D641DAD109EB994852FC0E0C0071DA3BBDCC3B9D8893058FDDF4")
2019/09/18 06:53:09.406992 rpc/storeserver: "upspin@filmar.us": store.Get("70609FC23BB6D641DAD109EB994852FC0E0C0071DA3BBDCC3B9D8893058FDDF4")
2019/09/18 06:53:09.524942 store/remote("udir.filmar.us:443").Get("092D8A8C8F5A0AA4E2D38F5EF4221204B4356496A3D1F3581E92B0504D9EB0C2")
2019/09/18 06:53:09.525209 rpc/storeserver: "upspin@filmar.us": store.Get("092D8A8C8F5A0AA4E2D38F5EF4221204B4356496A3D1F3581E92B0504D9EB0C2")
2019/09/18 06:53:09.639018 store/remote("udir.filmar.us:443").Get("8186C350FF5CDF38307483D321D85161CA93088227AE7073BE00E14EF6720097")
2019/09/18 06:53:09.639175 rpc/storeserver: "upspin@filmar.us": store.Get("8186C350FF5CDF38307483D321D85161CA93088227AE7073BE00E14EF6720097")
2019/09/18 06:53:09.711634 store/remote("udir.filmar.us:443").Get("A7B1181F6A68DDB44FBD1AC0C8E16AEAD7144AEB9A7DA69303C54FD4D65C73FC")
2019/09/18 06:53:09.711792 rpc/storeserver: "upspin@filmar.us": store.Get("A7B1181F6A68DDB44FBD1AC0C8E16AEAD7144AEB9A7DA69303C54FD4D65C73FC")
2019/09/18 06:53:09.787204 store/remote("udir.filmar.us:443").Get("30F503221DB9533152D0CFE3B38A96F801C032787D6DEB2FC706BACED9946CF4")
2019/09/18 06:53:09.787423 rpc/storeserver: "upspin@filmar.us": store.Get("30F503221DB9533152D0CFE3B38A96F801C032787D6DEB2FC706BACED9946CF4")
2019/09/18 06:53:09.909676 store/remote("udir.filmar.us:443").Get("9DEEC7FE7186E3780BA8752A94B8AC4CC68B24663C47DBD706A64643FC4F6348")
2019/09/18 06:53:09.909841 rpc/storeserver: "upspin@filmar.us": store.Get("9DEEC7FE7186E3780BA8752A94B8AC4CC68B24663C47DBD706A64643FC4F6348")
2019/09/18 06:53:10.023268 store/remote("udir.filmar.us:443").Get("E7DD82026719E4FC986B38F286D41D42EEB2A95351BD99A39A2D00625E656CE7")
2019/09/18 06:53:10.023443 rpc/storeserver: "upspin@filmar.us": store.Get("E7DD82026719E4FC986B38F286D41D42EEB2A95351BD99A39A2D00625E656CE7")
2019/09/18 06:53:10.080387 store/remote("udir.filmar.us:443").Get("6C03C24489607FB59FBDB5B85605A5CE1F149AA4C72BA0FEFA023DBCD1C80C81")
2019/09/18 06:53:10.080557 rpc/storeserver: "upspin@filmar.us": store.Get("6C03C24489607FB59FBDB5B85605A5CE1F149AA4C72BA0FEFA023DBCD1C80C81")
...
@adg
Copy link
Collaborator

adg commented Sep 22, 2019

Did it stop doing this after you restarted it? Or is it reproducible?

You might want to run the server with the environment variable GOTRACEBACK=2 set, and then you can send a SIGQUIT to the process to get a stack trace. It'd be helpful to know what the server think's it's doing. The bug is probably something simple.

@filmil
Copy link
Contributor Author

filmil commented Sep 23, 2019

The stack trace that I got from sending SIGQUIT to the server looks like this.

2019/09/23 16:04:42.460464 rpc/storeserver: "upspin@filmar.us": store.Get("3C4F7032C8A6C66B48280D82452AD0A16F95AA1053B6D8BD19AFD0AD5B4D91F7")                                                                      
SIGQUIT: quit                                                                                                                                                                                                      
PC=0x45c3d3 m=0 sigcode=0                                                                                                                                                                                          
                                                                                                                                                                                                                   
goroutine 10 [syscall]:                                                                                                                                                                                            
runtime.notetsleepg(0xe5e020, 0x12a05ba26, 0x731401)                                                                                                                                                               
        /usr/local/go/src/runtime/lock_futex.go:227 +0x34 fp=0xc00013b760 sp=0xc00013b730 pc=0x40c484                                                                                                              
runtime.timerproc(0xe5e000)                                                                                                                                                                                        
        /usr/local/go/src/runtime/time.go:311 +0x2ea fp=0xc00013b7d8 sp=0xc00013b760 pc=0x44bb1a                                                                                                                   
runtime.goexit()                                                                                                                                                                                                   
        /usr/local/go/src/runtime/asm_amd64.s:1337 +0x1 fp=0xc00013b7e0 sp=0xc00013b7d8 pc=0x45a571                                                                                                                
created by runtime.(*timersBucket).addtimerLocked                                                                                                                                                                  
        /usr/local/go/src/runtime/time.go:169 +0x10e                                                                                                                                                               
                                                                                                                                                                                                                   
goroutine 1 [IO wait]:                                                                                                                                                                                             
internal/poll.runtime_pollWait(0x7fbaca3e1018, 0x72, 0x0)                                                                                                                                                          
        /usr/local/go/src/runtime/netpoll.go:182 +0x56                                                                                                                                                             
internal/poll.(*pollDesc).wait(0xc000020218, 0x72, 0x0, 0x0, 0x9cd8c5)                                                                                                                                             
        /usr/local/go/src/internal/poll/fd_poll_runtime.go:87 +0x9b                                                                                                                                                
internal/poll.(*pollDesc).waitRead(...)                                                                                                                                                                            
        /usr/local/go/src/internal/poll/fd_poll_runtime.go:92                                                                                                                                                      
internal/poll.(*FD).Accept(0xc000020200, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)                                                                                                                                        
        /usr/local/go/src/internal/poll/fd_unix.go:384 +0x1ba                                                                                                                                                      
net.(*netFD).accept(0xc000020200, 0xe5aac0, 0x7fbacc8d26d0, 0x3)                                                                                                                                                   
        /usr/local/go/src/net/fd_unix.go:238 +0x42                                                                                                                                                                 
net.(*TCPListener).accept(0xc0000100e0, 0xc0000ddca8, 0x42d3d1, 0x9f2298)                                                                                                                                          
        /usr/local/go/src/net/tcpsock_posix.go:139 +0x32                                                                                                                                                           
net.(*TCPListener).Accept(0xc0000100e0, 0xc00d5af90c, 0xd5af90c000ddce0, 0x5d88ed06, 0xc0000ddce0)                                                                                                                 
        /usr/local/go/src/net/tcpsock.go:260 +0x48                                                                                                                                                                 
crypto/tls.(*listener).Accept(0xc00000eb60, 0xc0000ddd30, 0x18, 0xc000000180, 0x7464b4)                                                                                                                            
        /usr/local/go/src/crypto/tls/tls.go:62 +0x37                                                                                                                                                               
net/http.(*Server).Serve(0xc0000232b0, 0xa8dc20, 0xc00000eb60, 0x0, 0x0)                                                                                                                                           
        /usr/local/go/src/net/http/server.go:2859 +0x22d                                                                                                                                                           
upspin.io/cloud/https.ListenAndServe(0xc000026060, 0xc000020180)                                                                                                                                                   
        /go/src/upspin.io/cloud/https/https.go:268 +0x646                                                                                                                                                          
upspin.io/cloud/https.ListenAndServeFromFlags(0xc000026060)                                                                                                                                                        
        /go/src/upspin.io/cloud/https/https.go:146 +0x39                                                                                                                                                           
main.main()
        /go/src/upspin.io/cmd/upspinserver/main.go:20 +0x27

goroutine 19 [syscall]:
os/signal.signal_recv(0x0)
        /usr/local/go/src/runtime/sigqueue.go:139 +0x9c
os/signal.loop()
        /usr/local/go/src/os/signal/signal_unix.go:23 +0x22
created by os/signal.init.0
        /usr/local/go/src/os/signal/signal_unix.go:29 +0x41
upspin.io/shutdown.init.0.func1(0xc0000ae660)                                                                                                                                                          [2363/41051]
        /go/src/upspin.io/shutdown/shutdown.go:73 +0x41
created by upspin.io/shutdown.init.0
        /go/src/upspin.io/shutdown/shutdown.go:72 +0xc8

goroutine 4 [runnable]:
crypto/elliptic.p256PointAddAsm(0xc000259a60, 0xc, 0xc, 0xc00025a218, 0xc, 0xc, 0xc000259ac0, 0xc, 0xc, 0x1f)
        /usr/local/go/src/crypto/elliptic/p256_asm_amd64.s:2045 +0x747
crypto/elliptic.(*p256Point).p256ScalarMult(0xc00025a218, 0xc00025a198, 0x4, 0x4)
        /usr/local/go/src/crypto/elliptic/p256_asm.go:569 +0x989
crypto/elliptic.p256Curve.CombinedMult(0xc000066500, 0xc002a12be0, 0xc002a12c00, 0xc001926700, 0x20, 0x20, 0xc001926720, 0x20, 0x20, 0x3f, ...)
        /usr/local/go/src/crypto/elliptic/p256_asm.go:255 +0x310
crypto/ecdsa.Verify(0xc002a12c60, 0xc0019266e0, 0x20, 0x20, 0xc002a12ae0, 0xc002a12b00, 0x5ac09ef3)
        /usr/local/go/src/crypto/ecdsa/ecdsa.go:262 +0x404
upspin.io/pack/ee.ee.Unpack(0xa94e80, 0xc00000e900, 0xc0060d85a0, 0xc000096f10, 0x1400000000000000, 0xa96d00, 0xe768c8)
        /go/src/upspin.io/pack/ee/ee.go:313 +0xfe8
upspin.io/client/clientutil.ReadAll(0xa94e80, 0xc00000e900, 0xc0060d85a0, 0x59, 0x0, 0x0, 0x977840, 0x9)
        /go/src/upspin.io/client/clientutil/readall.go:41 +0x1da
upspin.io/dir/server/tree.(*Tree).load(0xc000176200, 0xc0060d85a0, 0x0, 0x0, 0xa)
        /go/src/upspin.io/dir/server/tree/blocks.go:127 +0xa8
upspin.io/dir/server/tree.(*Tree).loadKids(0xc000176200, 0xc0060d85a0, 0x0, 0x0)
        /go/src/upspin.io/dir/server/tree/tree.go:437 +0x180
upspin.io/dir/server/tree.(*Tree).traverse(0xc000176200, 0xc0060d85a0, 0xb, 0xc0003e6280, 0x0, 0x0)
        /go/src/upspin.io/dir/server/tree/tree.go:870 +0x305
upspin.io/dir/server/tree.(*Tree).traverse(0xc000176200, 0xc002253900, 0xa, 0xc0003e6280, 0x0, 0x0)
        /go/src/upspin.io/dir/server/tree/tree.go:884 +0x27c
upspin.io/dir/server/tree.(*Tree).traverse(0xc000176200, 0xc008493ea0, 0x9, 0xc0003e6280, 0x0, 0x0)
        /go/src/upspin.io/dir/server/tree/tree.go:884 +0x27c
upspin.io/dir/server/tree.(*Tree).traverse(0xc000176200, 0xc0036b1e00, 0x8, 0xc0003e6280, 0x0, 0x0)
        /go/src/upspin.io/dir/server/tree/tree.go:884 +0x27c
upspin.io/dir/server/tree.(*Tree).traverse(0xc000176200, 0xc0083a7720, 0x7, 0xc0003e6280, 0x0, 0x0)
        /go/src/upspin.io/dir/server/tree/tree.go:884 +0x27c
upspin.io/dir/server/tree.(*Tree).traverse(0xc000176200, 0xc0093e6aa0, 0x6, 0xc0003e6280, 0x0, 0x0)
        /go/src/upspin.io/dir/server/tree/tree.go:884 +0x27c
upspin.io/dir/server/tree.(*Tree).traverse(0xc000176200, 0xc009414000, 0x5, 0xc0003e6280, 0x0, 0x0)
        /go/src/upspin.io/dir/server/tree/tree.go:884 +0x27c
upspin.io/dir/server/tree.(*Tree).traverse(0xc000176200, 0xc0093708c0, 0x4, 0xc0003e6280, 0x0, 0x0)
        /go/src/upspin.io/dir/server/tree/tree.go:884 +0x27c
upspin.io/dir/server/tree.(*Tree).traverse(0xc000176200, 0xc000097680, 0x3, 0xc0003e6280, 0x0, 0x0)
        /go/src/upspin.io/dir/server/tree/tree.go:884 +0x27c
upspin.io/dir/server/tree.(*Tree).traverse(0xc000176200, 0xc0003ef0e0, 0x2, 0xc0003e6280, 0x0, 0x1)
        /go/src/upspin.io/dir/server/tree/tree.go:884 +0x27c
upspin.io/dir/server/tree.(*Tree).traverse(0xc000176200, 0xc000379180, 0x1, 0xc0003e6280, 0x10, 0x10)
        /go/src/upspin.io/dir/server/tree/tree.go:884 +0x27c
upspin.io/dir/server/tree.(*Tree).traverse(0xc000176200, 0xc0001685a0, 0x0, 0xc0003e6280, 0x9cad61, 0x7fbaca33b308)
        /go/src/upspin.io/dir/server/tree/tree.go:884 +0x27c
upspin.io/dir/server/tree.(*Tree).String(0xc000176200, 0x0, 0x0)
        /go/src/upspin.io/dir/server/tree/tree.go:854 +0xe8
fmt.(*pp).handleMethods(0xc0000e6180, 0xc000000073, 0x4c1b01)
        /usr/local/go/src/fmt/print.go:616 +0x29b
fmt.(*pp).printArg(0xc0000e6180, 0x9bbc40, 0xc000176200, 0xc000000073)
        /usr/local/go/src/fmt/print.go:699 +0x20a
fmt.(*pp).doPrintf(0xc0000e6180, 0x9d9403, 0x19, 0xc0003e6270, 0x1, 0x1)
        /usr/local/go/src/fmt/print.go:1016 +0x158
fmt.Sprintf(0x9d9403, 0x19, 0xc0003e6270, 0x1, 0x1, 0x9f22a8, 0xe76b70)                                                                                                                                [2309/41051]
        /usr/local/go/src/fmt/print.go:214 +0x66
log.(*Logger).Printf(0xc0000b8190, 0x9d9403, 0x19, 0xc0003e6270, 0x1, 0x1)
        /usr/local/go/src/log/log.go:179 +0x53
upspin.io/log.(*logger).Printf(0xe76908, 0x9d9403, 0x19, 0xc0003e6270, 0x1, 0x1)
        /go/src/upspin.io/log/log.go:158 +0xbf
upspin.io/dir/server/tree.(*Tree).recoverFromLog(0xc000176200, 0xc000176200, 0xc000150120)
        /go/src/upspin.io/dir/server/tree/tree.go:818 +0xa45
upspin.io/dir/server/tree.New(0xa94e80, 0xc00000e900, 0xc000176180, 0x0, 0xa94d00, 0xc00017c140)
        /go/src/upspin.io/dir/server/tree/tree.go:127 +0x48b
upspin.io/dir/server.(*server).loadTreeFor(0xc0001920c0, 0xc000172160, 0x14, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
        /go/src/upspin.io/dir/server/server.go:882 +0x645
upspin.io/dir/server.(*server).shouldSnapshot(0xc0001920c0, 0xc000128960, 0x14, 0xc000128960, 0x0, 0x0, 0x1)
        /go/src/upspin.io/dir/server/snapshot.go:159 +0x1dc
upspin.io/dir/server.(*server).snapshotAll(0xc0001920c0, 0x0, 0x0)
        /go/src/upspin.io/dir/server/snapshot.go:119 +0x2d7
upspin.io/dir/server.(*server).snapshotLoop(0xc0001920c0)
        /go/src/upspin.io/dir/server/snapshot.go:78 +0x40
created by upspin.io/dir/server.(*server).startSnapshotLoop
        /go/src/upspin.io/dir/server/snapshot.go:70 +0x80

goroutine 5 [sleep]:
runtime.goparkunlock(...)
        /usr/local/go/src/runtime/proc.go:307
time.Sleep(0x1bf08eb000)
        /usr/local/go/src/runtime/time.go:105 +0x159
upspin.io/dir/server.(*server).groupRefreshLoop(0xc0001920c0)
        /go/src/upspin.io/dir/server/access.go:289 +0x124
created by upspin.io/dir/server.New
        /go/src/upspin.io/dir/server/server.go:202 +0x99d

goroutine 6 [semacquire]:
sync.runtime_SemacquireMutex(0xc0001b405c, 0x0)
        /usr/local/go/src/runtime/sema.go:71 +0x3d
sync.(*Mutex).Lock(0xc0001b4058)
        /usr/local/go/src/sync/mutex.go:134 +0x109
upspin.io/dir/server.(*server).userLock(0xc0001920c0, 0xc0000241e0, 0x10, 0x0)
        /go/src/upspin.io/dir/server/userlock.go:18 +0x86
upspin.io/dir/server.(*server).loadTreeFor(0xc0001920c0, 0xc000028200, 0x10, 0xc000051d00, 0x1, 0x1, 0x0, 0x0, 0x0)
        /go/src/upspin.io/dir/server/server.go:841 +0x208
upspin.io/dir/server.(*server).lookup(0xc0001920c0, 0xc000028200, 0x1e, 0x1, 0xc000051e40, 0x1, 0x1, 0x0, 0x0, 0x0)
        /go/src/upspin.io/dir/server/server.go:268 +0x139
upspin.io/dir/server.(*server).lookupWithPermissions(0xc0001920c0, 0x9d40dd, 0x11, 0xc000028200, 0x1e, 0xc000051e40, 0x1, 0x1, 0xc0001dc000, 0x0, ...)
        /go/src/upspin.io/dir/server/server.go:220 +0x256
upspin.io/dir/server.(*server).Lookup(0xc0001920c0, 0xc000028200, 0x1e, 0x0, 0x0, 0x0)
        /go/src/upspin.io/dir/server/server.go:211 +0xf1
upspin.io/serverutil/perm.(*Perm).lookup(0xc000186120, 0xc000028200, 0x1e, 0x40784b, 0xc000026060, 0x0)
        /go/src/upspin.io/serverutil/perm/perm.go:323 +0x18a
upspin.io/serverutil/perm.(*Perm).Update(0xc000186120, 0x0, 0x0)
        /go/src/upspin.io/serverutil/perm/perm.go:230 +0x41
upspin.io/serverutil/perm.newPerm.func1(0xc000026060, 0xc000186120, 0x9d9e5f, 0x1a)
        /go/src/upspin.io/serverutil/perm/perm.go:108 +0x49
created by upspin.io/serverutil/perm.newPerm
        /go/src/upspin.io/serverutil/perm/perm.go:106 +0x165

goroutine 7 [IO wait]:
internal/poll.runtime_pollWait(0x7fbaca3e0f48, 0x72, 0x0)
        /usr/local/go/src/runtime/netpoll.go:182 +0x56
internal/poll.(*pollDesc).wait(0xc000020298, 0x72, 0x0, 0x0, 0x9cd8c5)
        /usr/local/go/src/internal/poll/fd_poll_runtime.go:87 +0x9b
internal/poll.(*pollDesc).waitRead(...)
        /usr/local/go/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Accept(0xc000020280, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
        /usr/local/go/src/internal/poll/fd_unix.go:384 +0x1ba
net.(*netFD).accept(0xc000020280, 0xc00002c000, 0xe5aac0, 0x7fbacc8d2008)
        /usr/local/go/src/net/fd_unix.go:238 +0x42
net.(*TCPListener).accept(0xc0000100e8, 0xc000052e70, 0x40de68, 0x30)
        /usr/local/go/src/net/tcpsock_posix.go:139 +0x32
net.(*TCPListener).Accept(0xc0000100e8, 0x9907e0, 0xc000178d20, 0x9312e0, 0xe47b20)
        /usr/local/go/src/net/tcpsock.go:260 +0x48
net/http.(*Server).Serve(0xc0000231e0, 0xa8e9a0, 0xc0000100e8, 0x0, 0x0)
        /usr/local/go/src/net/http/server.go:2859 +0x22d
upspin.io/cloud/https.ListenAndServe.func3(0xc0000231e0, 0xa8e9a0, 0xc0000100e8)
        /go/src/upspin.io/cloud/https/https.go:235 +0x43
created by upspin.io/cloud/https.ListenAndServe
        /go/src/upspin.io/cloud/https/https.go:234 +0xa26

goroutine 36 [chan receive]:
upspin.io/dir/server/serverlog.(*root).saveLoop(0xc00012a480, 0xa908a0, 0xc000054260)
        /go/src/upspin.io/dir/server/serverlog/log.go:198 +0x8b
created by upspin.io/dir/server/serverlog.newRoot
        /go/src/upspin.io/dir/server/serverlog/log.go:181 +0x340

goroutine 26 [IO wait]:
internal/poll.runtime_pollWait(0x7fbaca3e0e78, 0x72, 0xffffffffffffffff)
        /usr/local/go/src/runtime/netpoll.go:182 +0x56
internal/poll.(*pollDesc).wait(0xc000176418, 0x72, 0xd000, 0xd042, 0xffffffffffffffff)
        /usr/local/go/src/internal/poll/fd_poll_runtime.go:87 +0x9b
internal/poll.(*pollDesc).waitRead(...)
        /usr/local/go/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Read(0xc000176400, 0xc000608000, 0xd042, 0xd042, 0x0, 0x0, 0x0)
        /usr/local/go/src/internal/poll/fd_unix.go:169 +0x19b
net.(*netFD).Read(0xc000176400, 0xc000608000, 0xd042, 0xd042, 0x203000, 0x40d5d9, 0xc004569da0)
        /usr/local/go/src/net/fd_unix.go:202 +0x4f
net.(*conn).Read(0xc0001420b0, 0xc000608000, 0xd042, 0xd042, 0x0, 0x0, 0x0)
        /usr/local/go/src/net/net.go:177 +0x69
crypto/tls.(*atLeastReader).Read(0xc002a12a60, 0xc000608000, 0xd042, 0xd042, 0xc004569da0, 0x41491e, 0xc00004d938)
        /usr/local/go/src/crypto/tls/conn.go:761 +0x60
bytes.(*Buffer).ReadFrom(0xc00012c958, 0xa84980, 0xc002a12a60, 0x40b6e5, 0x942080, 0x9b0c00)                                                                                                                      
        /usr/local/go/src/bytes/buffer.go:207 +0xbd
crypto/tls.(*Conn).readFromUntil(0xc00012c700, 0xa84d60, 0xc0001420b0, 0x5, 0xc0001420b0, 0x203001)
        /usr/local/go/src/crypto/tls/conn.go:783 +0xf8
crypto/tls.(*Conn).readRecordOrCCS(0xc00012c700, 0x9f2200, 0xc00012c838, 0xc00004db88)
        /usr/local/go/src/crypto/tls/conn.go:590 +0x125
crypto/tls.(*Conn).readRecord(...)
        /usr/local/go/src/crypto/tls/conn.go:558
crypto/tls.(*Conn).Read(0xc00012c700, 0xc0003d8000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
        /usr/local/go/src/crypto/tls/conn.go:1236 +0x137
net/http.(*persistConn).Read(0xc000160a20, 0xc0003d8000, 0x1000, 0x1000, 0xc00004dc88, 0x406d15, 0xc000026780)                                                                                                    
        /usr/local/go/src/net/http/transport.go:1524 +0x7b
bufio.(*Reader).fill(0xc0000afa40)
        /usr/local/go/src/bufio/bufio.go:100 +0x10f
bufio.(*Reader).Peek(0xc0000afa40, 0x1, 0x0, 0x0, 0x1, 0xc004baa000, 0x0)
        /usr/local/go/src/bufio/bufio.go:138 +0x4f
net/http.(*persistConn).readLoop(0xc000160a20)
        /usr/local/go/src/net/http/transport.go:1677 +0x1a3
created by net/http.(*Transport).dialConn
        /usr/local/go/src/net/http/transport.go:1357 +0xae8

goroutine 22 [IO wait]:
internal/poll.runtime_pollWait(0x7fbaca3e0da8, 0x72, 0xffffffffffffffff)
        /usr/local/go/src/runtime/netpoll.go:182 +0x56
internal/poll.(*pollDesc).wait(0xc0000b2618, 0x72, 0x200, 0x205, 0xffffffffffffffff)
        /usr/local/go/src/internal/poll/fd_poll_runtime.go:87 +0x9b
internal/poll.(*pollDesc).waitRead(...)
        /usr/local/go/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Read(0xc0000b2600, 0xc000290000, 0x205, 0x205, 0x0, 0x0, 0x0)
        /usr/local/go/src/internal/poll/fd_unix.go:169 +0x19b
net.(*netFD).Read(0xc0000b2600, 0xc000290000, 0x205, 0x205, 0x203001, 0xc00007ec00, 0x300000002)
        /usr/local/go/src/net/fd_unix.go:202 +0x4f
net.(*conn).Read(0xc0000ac0b0, 0xc000290000, 0x205, 0x205, 0x0, 0x0, 0x0)
        /usr/local/go/src/net/net.go:177 +0x69
crypto/tls.(*atLeastReader).Read(0xc0040f3180, 0xc000290000, 0x205, 0x205, 0xc0000b2600, 0xc000202000, 0xc0000db9d8)
        /usr/local/go/src/crypto/tls/conn.go:761 +0x60
bytes.(*Buffer).ReadFrom(0xc000075758, 0xa84980, 0xc0040f3180, 0x40b6e5, 0x942080, 0x9b0c00)
        /usr/local/go/src/bytes/buffer.go:207 +0xbd
crypto/tls.(*Conn).readFromUntil(0xc000075500, 0xa84d60, 0xc0000ac0b0, 0x5, 0xc0000ac0b0, 0xc0000b2600)
        /usr/local/go/src/crypto/tls/conn.go:783 +0xf8
crypto/tls.(*Conn).readRecordOrCCS(0xc000075500, 0x9f2200, 0xc000075638, 0x73bc1a)
        /usr/local/go/src/crypto/tls/conn.go:590 +0x125
crypto/tls.(*Conn).readRecord(...)
        /usr/local/go/src/crypto/tls/conn.go:558
crypto/tls.(*Conn).Read(0xc000075500, 0xc0003ca000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
        /usr/local/go/src/crypto/tls/conn.go:1236 +0x137
net/http.(*connReader).Read(0xc000099230, 0xc0003ca000, 0x1000, 0x1000, 0x5fa8c1, 0xc0000ac0b0, 0xbf5a59359b7aaa67)
        /usr/local/go/src/net/http/server.go:787 +0x107
bufio.(*Reader).fill(0xc00012a5a0)
        /usr/local/go/src/bufio/bufio.go:100 +0x10f
bufio.(*Reader).Peek(0xc00012a5a0, 0x4, 0x12afccf7e8, 0xe59b80, 0x0, 0x0, 0xe59b80)
        /usr/local/go/src/bufio/bufio.go:138 +0x4f
net/http.(*conn).serve(0xc000096fa0, 0xa905a0, 0xc000066040)
        /usr/local/go/src/net/http/server.go:1903 +0x9bf
created by net/http.(*Server).Serve
        /usr/local/go/src/net/http/server.go:2884 +0x2f4

goroutine 27 [select]:
net/http.(*persistConn).writeLoop(0xc000160a20)
        /usr/local/go/src/net/http/transport.go:1958 +0x113
created by net/http.(*Transport).dialConn
        /usr/local/go/src/net/http/transport.go:1358 +0xb0d

rax    0xfffffffffffffffc
rbx    0x3b9a9226
rcx    0x45c3d3
rdx    0x0
rdi    0xe5e020
rsi    0x80
rbp    0xc00013b6e8
rsp    0xc00013b6a0
r8     0x0
r9     0x0
r10    0xc00013b6d8
r11    0x202
r12    0x4
r13    0x12
r14    0xa73425
r15    0x0
rip    0x45c3d3
rflags 0x202
cs     0x33
fs     0x0
gs     0x0

@filmil
Copy link
Contributor Author

filmil commented Sep 23, 2019

I see this behavior upon each restart. The server keeps on moving data around and attempts to do something useful in the meantime are starved. Some would eventually be fulfilled but it is a far cry from being able to do something useful.

@n2vi
Copy link
Contributor

n2vi commented Sep 23, 2019 via email

@filmil
Copy link
Contributor Author

filmil commented Sep 23, 2019

Oh, I see it now.

This is because of the --log=debug option I used on the server startup command line. It's trying to printf the entire tree... which is large.

note from the stack trace above: https://github.com/upspin/upspin/blob/master/dir/server/tree/tree.go#L818

upspin.io/dir/server/tree.(*Tree).recoverFromLog(0xc000176200, 0xc000176200, 0xc000150120)
        /go/src/upspin.io/dir/server/tree/tree.go:818 +0xa45

and here: https://github.com/upspin/upspin/blob/master/dir/server/tree/tree.go#L854

upspin.io/dir/server/tree.(*Tree).String(0xc000176200, 0x0, 0x0)
        /go/src/upspin.io/dir/server/tree/tree.go:854 +0xe8

It does not seem practical to traverse the entire tree just to do some printf debugging, at least not in a running server.

@filmil
Copy link
Contributor Author

filmil commented Sep 23, 2019

FWIW, restarting the server with --log=info removes the issue.

@adg
Copy link
Collaborator

adg commented Sep 29, 2019 via email

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants