My upspinserver has been busy for months in the following loop. Sadly I had to restart

`upspinserver` spending months in some sort of a read loop about upspin HOT 7 OPEN

filmil commented on June 3, 2024

`upspinserver` spending months in some sort of a read loop

from upspin.

Comments (7)

adg commented on June 3, 2024

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.

from upspin.

filmil commented on June 3, 2024

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

2019/09/23 16:04:42.460464 rpc/storeserver: "[email protected]": 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

from upspin.

filmil commented on June 3, 2024

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.

from upspin.

n2vi commented on June 3, 2024

Good to see the tree traversal of log recovery here; that's what I imagined from seeing your earlier Get trace. But I'm not expert enough in that part of the code. Maybe presotto@ or adg@ can help? I don't see any actual key material revealed in this dump, but makes me nervous to dump registers during p256PointAddAsm.

…

On Mon, Sep 23, 2019 at 9:19 AM Filip Filmar ***@***.***> wrote: 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. — You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub <#624?email_source=notifications&email_token=ACADPOT3B5DIUR2PPCR2CCTQLDUBRA5CNFSM4IX2PBQ2YY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOD7LNQPY#issuecomment-534173759>, or mute the thread <https://github.com/notifications/unsubscribe-auth/ACADPOWIP5QE5B4KKAWRUATQLDUBRANCNFSM4IX2PBQQ> .

from upspin.

filmil commented on June 3, 2024

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.

from upspin.

filmil commented on June 3, 2024

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

from upspin.

adg commented on June 3, 2024

I think the root issue is that the `upspin.io/dir/server/tree.Tree` type has a String method that does a nontrivial amount of work to stringify the Tree. This involves taking a lock, and possibly printing more log messages that invoke the Stringer again, causing infinite recursion. The straightforward fix is to simplify the Tree's Stringer method to just return a string representation of the Tree's state without mutating it at all. That was a case of bad design in the first place.

from upspin.

`upspinserver` spending months in some sort of a read loop about upspin HOT 7 OPEN

Comments (7)

Related Issues (20)

Recommend Projects

React

Vue.js

Typescript

TensorFlow

Django

Laravel

D3

Recommend Topics

javascript

web

server

Machine learning

Visualization

Game

Recommend Org

Facebook

Microsoft

Google

Alibaba

D3

Tencent