webroot request hanging about acmetool

[hlandau]

This is weird. By hang, I assume you mean for more than 30 seconds, which should be the worst case time between polling requests.

Can you reproduce this, then send SIGQUIT to the acmetool process? This will cause it to dump a stack trace. (This works for all Go programs.)

[apollo13]

Yes, certainly more than 30 seconds

SIGQUIT: quit
PC=0x46e089 m=0

goroutine 0 [idle]:
runtime.epollwait(0x7ffd00000005, 0x7ffdf3024320, 0xffffffff00000080, 0x0, 0xffffffff, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
    /usr/lib/go/src/runtime/sys_linux_amd64.s:420 +0x19
runtime.netpoll(0xf31101, 0x0)
    /usr/lib/go/src/runtime/netpoll_epoll.go:68 +0x94
runtime.findrunnable(0xc82001b500, 0x0)
    /usr/lib/go/src/runtime/proc1.go:1512 +0x598
runtime.schedule()
    /usr/lib/go/src/runtime/proc1.go:1639 +0x267
runtime.goexit0(0xc820342d80)
    /usr/lib/go/src/runtime/proc1.go:1765 +0x1a2
runtime.mcall(0x7ffdf3024a30)
    /usr/lib/go/src/runtime/asm_amd64.s:204 +0x5b

goroutine 1 [semacquire]:
sync.runtime_Semacquire(0xc820554f1c)
    /usr/lib/go/src/runtime/sema.go:43 +0x26
sync.(*WaitGroup).Wait(0xc820554f10)
    /usr/lib/go/src/sync/waitgroup.go:126 +0xb4
github.com/hlandau/acme/responder.(*httpResponder).Stop(0xc82054c0c0, 0x0, 0x0)
    /home/florian/sources/acme/src/github.com/hlandau/acme/responder/http.go:221 +0x123
github.com/hlandau/acme/solver.CompleteChallenge(0xc820275380, 0xc820576280, 0xc820328350, 0x10, 0xc82031db00, 0x23, 0x7faef51e86a8, 0xf56478, 0xc820421070, 0x7faef41a2c30, ...)
    /home/florian/sources/acme/src/github.com/hlandau/acme/solver/respond.go:157 +0xba3
github.com/hlandau/acme/solver.(*authState).attemptCombination(0xc8201ef900, 0xc8202885a0, 0xc8203e28c0, 0x1, 0x4, 0x0, 0x0, 0x0)
    /home/florian/sources/acme/src/github.com/hlandau/acme/solver/respond.go:79 +0x15a
github.com/hlandau/acme/solver.(*authState).authorize(0xc8201ef900, 0xc8202885a0, 0xc820340000, 0x0, 0x0)
    /home/florian/sources/acme/src/github.com/hlandau/acme/solver/respond.go:62 +0x1ba
github.com/hlandau/acme/solver.Authorize(0xc820275380, 0xc820328350, 0x10, 0xc82031db00, 0x23, 0x0, 0x0, 0xc820421070, 0x7faef41a2c30, 0xc8200707d0, ...)
    /home/florian/sources/acme/src/github.com/hlandau/acme/solver/respond.go:42 +0x136
github.com/hlandau/acme/storage.(*Store).obtainAuthorization(0xc82022a9a0, 0xc820328350, 0x10, 0xc82028ebd0, 0x0, 0x0)
    /home/florian/sources/acme/src/github.com/hlandau/acme/storage/storage.go:1099 +0x208
github.com/hlandau/acme/storage.(*Store).requestCertificateForTarget(0xc82022a9a0, 0xc820320540, 0x0, 0x0)
    /home/florian/sources/acme/src/github.com/hlandau/acme/storage/storage.go:1162 +0x269
github.com/hlandau/acme/storage.(*Store).reconcile(0xc82022a9a0, 0x0, 0x0)
    /home/florian/sources/acme/src/github.com/hlandau/acme/storage/storage.go:874 +0x248
github.com/hlandau/acme/storage.(*Store).Reconcile(0xc82022a9a0, 0x0, 0x0)
    /home/florian/sources/acme/src/github.com/hlandau/acme/storage/storage.go:840 +0x42
main.cmdReconcile()
    /home/florian/sources/acme/src/github.com/hlandau/acme/cmd/acmetool/main.go:119 +0x16a
main.main()
    /home/florian/sources/acme/src/github.com/hlandau/acme/cmd/acmetool/main.go:73 +0xfb

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

goroutine 20 [syscall, 1 minutes]:
os/signal.loop()
    /usr/lib/go/src/os/signal/signal_unix.go:22 +0x18
created by os/signal.init.1
    /usr/lib/go/src/os/signal/signal_unix.go:28 +0x37

goroutine 33 [IO wait]:
net.runtime_pollWait(0x7faef51e9608, 0x72, 0xc8200700e0)
    /usr/lib/go/src/runtime/netpoll.go:157 +0x60
net.(*pollDesc).Wait(0xc82050d1e0, 0x72, 0x0, 0x0)
    /usr/lib/go/src/net/fd_poll_runtime.go:73 +0x3a
net.(*pollDesc).WaitRead(0xc82050d1e0, 0x0, 0x0)
    /usr/lib/go/src/net/fd_poll_runtime.go:78 +0x36
net.(*netFD).accept(0xc82050d180, 0x0, 0x7faef51f2710, 0xc82054e020)
    /usr/lib/go/src/net/fd_unix.go:408 +0x27c
net.(*TCPListener).AcceptTCP(0xc8200921c0, 0x460830, 0x0, 0x0)
    /usr/lib/go/src/net/tcpsock_posix.go:254 +0x4d
net.(*TCPListener).Accept(0xc8200921c0, 0x0, 0x0, 0x0, 0x0)
    /usr/lib/go/src/net/tcpsock_posix.go:264 +0x3d
net/http.(*Server).Serve(0xc820507200, 0x7faef51f7d48, 0xc8200921c0, 0x0, 0x0)
    /usr/lib/go/src/net/http/server.go:1887 +0xb3
gopkg.in/tylerb/graceful%2ev1.(*Server).Serve(0xc82050d110, 0x7faef51f7d48, 0xc8200921c0, 0x0, 0x0)
    /home/florian/sources/acme/src/gopkg.in/tylerb/graceful.v1/graceful.go:234 +0x4f1
github.com/hlandau/acme/responder.(*httpResponder).startListener.func1(0x7faef51f7d48, 0xc8200921c0, 0xc82050d110)
    /home/florian/sources/acme/src/github.com/hlandau/acme/responder/http.go:199 +0x64
created by github.com/hlandau/acme/responder.(*httpResponder).startListener
    /home/florian/sources/acme/src/github.com/hlandau/acme/responder/http.go:200 +0x1df

goroutine 32 [select]:
net/http.(*persistConn).writeLoop(0xc820282580)
    /usr/lib/go/src/net/http/transport.go:1009 +0x40c
created by net/http.(*Transport).dialConn
    /usr/lib/go/src/net/http/transport.go:686 +0xc9d

goroutine 31 [IO wait]:
net.runtime_pollWait(0x7faef51e96c8, 0x72, 0xc8200700e0)
    /usr/lib/go/src/runtime/netpoll.go:157 +0x60
net.(*pollDesc).Wait(0xc8200d5a30, 0x72, 0x0, 0x0)
    /usr/lib/go/src/net/fd_poll_runtime.go:73 +0x3a
net.(*pollDesc).WaitRead(0xc8200d5a30, 0x0, 0x0)
    /usr/lib/go/src/net/fd_poll_runtime.go:78 +0x36
net.(*netFD).Read(0xc8200d59d0, 0xc820285000, 0x800, 0x800, 0x0, 0x7faef51e4140, 0xc8200700e0)
    /usr/lib/go/src/net/fd_unix.go:232 +0x23a
net.(*conn).Read(0xc8200c8248, 0xc820285000, 0x800, 0x800, 0x0, 0x0, 0x0)
    /usr/lib/go/src/net/net.go:172 +0xe4
crypto/tls.(*block).readFromUntil(0xc82035be30, 0x7faef51f2870, 0xc8200c8248, 0x5, 0x0, 0x0)
    /usr/lib/go/src/crypto/tls/conn.go:455 +0xcc
crypto/tls.(*Conn).readRecord(0xc8200bc840, 0xb44817, 0x0, 0x0)
    /usr/lib/go/src/crypto/tls/conn.go:540 +0x2d1
crypto/tls.(*Conn).Read(0xc8200bc840, 0xc820178000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
    /usr/lib/go/src/crypto/tls/conn.go:901 +0x167
net/http.noteEOFReader.Read(0x7faef41a28a8, 0xc8200bc840, 0xc8202825d8, 0xc820178000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
    /usr/lib/go/src/net/http/transport.go:1370 +0x67
net/http.(*noteEOFReader).Read(0xc820162d80, 0xc820178000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
    <autogenerated>:126 +0xd0
bufio.(*Reader).fill(0xc8200186c0)
    /usr/lib/go/src/bufio/bufio.go:97 +0x1e9
bufio.(*Reader).Peek(0xc8200186c0, 0x1, 0x0, 0x0, 0x0, 0x0, 0x0)
    /usr/lib/go/src/bufio/bufio.go:132 +0xcc
net/http.(*persistConn).readLoop(0xc820282580)
    /usr/lib/go/src/net/http/transport.go:876 +0xf7
created by net/http.(*Transport).dialConn
    /usr/lib/go/src/net/http/transport.go:685 +0xc78

goroutine 50 [IO wait]:
net.runtime_pollWait(0x7faef51e9548, 0x72, 0xc8200700e0)
    /usr/lib/go/src/runtime/netpoll.go:157 +0x60
net.(*pollDesc).Wait(0xc82050d2c0, 0x72, 0x0, 0x0)
    /usr/lib/go/src/net/fd_poll_runtime.go:73 +0x3a
net.(*pollDesc).WaitRead(0xc82050d2c0, 0x0, 0x0)
    /usr/lib/go/src/net/fd_poll_runtime.go:78 +0x36
net.(*netFD).accept(0xc82050d260, 0x0, 0x7faef51f2710, 0xc820556020)
    /usr/lib/go/src/net/fd_unix.go:408 +0x27c
net.(*TCPListener).AcceptTCP(0xc8200921d0, 0x460830, 0x0, 0x0)
    /usr/lib/go/src/net/tcpsock_posix.go:254 +0x4d
net.(*TCPListener).Accept(0xc8200921d0, 0x0, 0x0, 0x0, 0x0)
    /usr/lib/go/src/net/tcpsock_posix.go:264 +0x3d
net/http.(*Server).Serve(0xc820507260, 0x7faef51f7d48, 0xc8200921d0, 0x0, 0x0)
    /usr/lib/go/src/net/http/server.go:1887 +0xb3
gopkg.in/tylerb/graceful%2ev1.(*Server).Serve(0xc82050d1f0, 0x7faef51f7d48, 0xc8200921d0, 0x0, 0x0)
    /home/florian/sources/acme/src/gopkg.in/tylerb/graceful.v1/graceful.go:234 +0x4f1
github.com/hlandau/acme/responder.(*httpResponder).startListener.func1(0x7faef51f7d48, 0xc8200921d0, 0xc82050d1f0)
    /home/florian/sources/acme/src/github.com/hlandau/acme/responder/http.go:199 +0x64
created by github.com/hlandau/acme/responder.(*httpResponder).startListener
    /home/florian/sources/acme/src/github.com/hlandau/acme/responder/http.go:200 +0x1df

goroutine 51 [IO wait]:
net.runtime_pollWait(0x7faef51e9488, 0x72, 0xc8200700e0)
    /usr/lib/go/src/runtime/netpoll.go:157 +0x60
net.(*pollDesc).Wait(0xc82050d3a0, 0x72, 0x0, 0x0)
    /usr/lib/go/src/net/fd_poll_runtime.go:73 +0x3a
net.(*pollDesc).WaitRead(0xc82050d3a0, 0x0, 0x0)
    /usr/lib/go/src/net/fd_poll_runtime.go:78 +0x36
net.(*netFD).accept(0xc82050d340, 0x0, 0x7faef51f2710, 0xc82021e5e0)
    /usr/lib/go/src/net/fd_unix.go:408 +0x27c
net.(*TCPListener).AcceptTCP(0xc8200921d8, 0x460830, 0x0, 0x0)
    /usr/lib/go/src/net/tcpsock_posix.go:254 +0x4d
net.(*TCPListener).Accept(0xc8200921d8, 0x0, 0x0, 0x0, 0x0)
    /usr/lib/go/src/net/tcpsock_posix.go:264 +0x3d
net/http.(*Server).Serve(0xc8205072c0, 0x7faef51f7d48, 0xc8200921d8, 0x0, 0x0)
    /usr/lib/go/src/net/http/server.go:1887 +0xb3
gopkg.in/tylerb/graceful%2ev1.(*Server).Serve(0xc82050d2d0, 0x7faef51f7d48, 0xc8200921d8, 0x0, 0x0)
    /home/florian/sources/acme/src/gopkg.in/tylerb/graceful.v1/graceful.go:234 +0x4f1
github.com/hlandau/acme/responder.(*httpResponder).startListener.func1(0x7faef51f7d48, 0xc8200921d8, 0xc82050d2d0)
    /home/florian/sources/acme/src/github.com/hlandau/acme/responder/http.go:199 +0x64
created by github.com/hlandau/acme/responder.(*httpResponder).startListener
    /home/florian/sources/acme/src/github.com/hlandau/acme/responder/http.go:200 +0x1df

goroutine 40 [select]:
gopkg.in/tylerb/graceful%2ev1.(*Server).manageConnections(0xc82050d1f0, 0xc820430060, 0xc8204300c0, 0xc820430120, 0xc820430180)
    /home/florian/sources/acme/src/gopkg.in/tylerb/graceful.v1/graceful.go:272 +0x3d9
created by gopkg.in/tylerb/graceful%2ev1.(*Server).Serve
    /home/florian/sources/acme/src/gopkg.in/tylerb/graceful.v1/graceful.go:223 +0x2c9

goroutine 41 [chan receive]:
gopkg.in/tylerb/graceful%2ev1.(*Server).handleInterrupt(0xc82050d1f0, 0xc8204301e0, 0x7faef51f7d48, 0xc8200921d0)
    /home/florian/sources/acme/src/gopkg.in/tylerb/graceful.v1/graceful.go:306 +0x3a
created by gopkg.in/tylerb/graceful%2ev1.(*Server).Serve
    /home/florian/sources/acme/src/gopkg.in/tylerb/graceful.v1/graceful.go:230 +0x4c3

goroutine 6 [select]:
gopkg.in/tylerb/graceful%2ev1.(*Server).manageConnections(0xc82050d2d0, 0xc820215440, 0xc8202154a0, 0xc820215500, 0xc820215560)
    /home/florian/sources/acme/src/gopkg.in/tylerb/graceful.v1/graceful.go:272 +0x3d9
created by gopkg.in/tylerb/graceful%2ev1.(*Server).Serve
    /home/florian/sources/acme/src/gopkg.in/tylerb/graceful.v1/graceful.go:223 +0x2c9

goroutine 7 [chan receive]:
gopkg.in/tylerb/graceful%2ev1.(*Server).handleInterrupt(0xc82050d2d0, 0xc8202155c0, 0x7faef51f7d48, 0xc8200921d8)
    /home/florian/sources/acme/src/gopkg.in/tylerb/graceful.v1/graceful.go:306 +0x3a
created by gopkg.in/tylerb/graceful%2ev1.(*Server).Serve
    /home/florian/sources/acme/src/gopkg.in/tylerb/graceful.v1/graceful.go:230 +0x4c3

goroutine 68 [chan send]:
gopkg.in/tylerb/graceful%2ev1.(*Server).Stop(0xc82050d3b0, 0x989680)
    /home/florian/sources/acme/src/gopkg.in/tylerb/graceful.v1/graceful.go:252 +0xd2
github.com/hlandau/acme/responder.(*httpResponder).startListener.func2()
    /home/florian/sources/acme/src/github.com/hlandau/acme/responder/http.go:203 +0x2e
github.com/hlandau/acme/responder.(*httpResponder).Stop.func1(0xc820554f10, 0xc8200c80a8)
    /home/florian/sources/acme/src/github.com/hlandau/acme/responder/http.go:218 +0x47
created by github.com/hlandau/acme/responder.(*httpResponder).Stop
    /home/florian/sources/acme/src/github.com/hlandau/acme/responder/http.go:219 +0xfa

goroutine 66 [select]:
gopkg.in/tylerb/graceful%2ev1.(*Server).manageConnections(0xc82050d110, 0xc820336000, 0xc820336060, 0xc8203360c0, 0xc820336180)
    /home/florian/sources/acme/src/gopkg.in/tylerb/graceful.v1/graceful.go:272 +0x3d9
created by gopkg.in/tylerb/graceful%2ev1.(*Server).Serve
    /home/florian/sources/acme/src/gopkg.in/tylerb/graceful.v1/graceful.go:223 +0x2c9

goroutine 67 [chan receive]:
gopkg.in/tylerb/graceful%2ev1.(*Server).handleInterrupt(0xc82050d110, 0xc8203361e0, 0x7faef51f7d48, 0xc8200921c0)
    /home/florian/sources/acme/src/gopkg.in/tylerb/graceful.v1/graceful.go:306 +0x3a
created by gopkg.in/tylerb/graceful%2ev1.(*Server).Serve
    /home/florian/sources/acme/src/gopkg.in/tylerb/graceful.v1/graceful.go:230 +0x4c3

goroutine 71 [semacquire]:
sync.runtime_Semacquire(0xc82050d3f4)
    /usr/lib/go/src/runtime/sema.go:43 +0x26
sync.(*Mutex).Lock(0xc82050d3f0)
    /usr/lib/go/src/sync/mutex.go:82 +0x1c4
gopkg.in/tylerb/graceful%2ev1.(*Server).Stop(0xc82050d3b0, 0x989680)
    /home/florian/sources/acme/src/gopkg.in/tylerb/graceful.v1/graceful.go:249 +0x35
github.com/hlandau/acme/responder.(*httpResponder).startListener.func2()
    /home/florian/sources/acme/src/github.com/hlandau/acme/responder/http.go:203 +0x2e
github.com/hlandau/acme/responder.(*httpResponder).Stop.func1(0xc820554f10, 0xc8200c80a8)
    /home/florian/sources/acme/src/github.com/hlandau/acme/responder/http.go:218 +0x47
created by github.com/hlandau/acme/responder.(*httpResponder).Stop
    /home/florian/sources/acme/src/github.com/hlandau/acme/responder/http.go:219 +0xfa

rax    0xfffffffffffffffc
rbx    0xffffffff
rcx    0xffffffffffffffff
rdx    0x80
rdi    0x5
rsi    0x7ffdf3024320
rbp    0xf31b80
rsp    0x7ffdf30242e0
r8     0x0
r9     0x0
r10    0xffffffff
r11    0x246
r12    0xa
r13    0xb40a0a
r14    0x3d
r15    0x8
rip    0x46e089
rflags 0x246
cs     0x33
fs     0x0
gs     0x0

[apollo13]

Oh btw, those two request to https://acme-v01.api.letsencrypt.org/acme/challenge/qXCrJhNlZupNvU29A-JewLDN7zUVCr8NfiLKBjyJzIM/1031567 are the only two happening, nothing more then in the logs…

[hlandau]

Finally figured it out. I think this should be fixed in master now.

[apollo13]

Yes :) Now I get:

{"type":"urn:acme:error:rateLimited","detail":"Error creating new cert :: Too many certificates already issued for: apolloner.eu","status":429}

Guess I should play a little bit less :D

[hlandau]

Yeah, that was a really annoying bug. I was staring at that stack trace for ages.

If you're curious, it goes like this:

  for _, f := range arrayOfFuncs {
    f2 := f
    go func() {
      f() // not the same as f2()
    }()
  }

In go, the closure will bind to f, but f is a variable which changes for each iteration, so you end up calling the same f multiple times. Which in this case called Stop() for the same HTTP server multiple times. Which, due to the way the HTTP graceful-shutdown library works, causes it to hang forever; it doesn't expect Stop to be called more than once.

[hlandau]

Actually, it sounds like you might have run into this issue as well: hlandau/acme.t#4
I've not been able to reproduce it, though.

[apollo13]

I do not think so, I certainly ran into the ratelimiting with all my tries, but I will retry in a week and see what comes out of it.

[hlandau]

If you could run using a separate state directory --state, using the staging server (which has very high ratelimits) to try and reproduce the issue, that'd be helpful.

The thing to watch out for is excessive subdirectories under certs and keys. Repeated reconcile calls shouldn't result in repeated certificate requests (until the certificates come close to expiry).

I've done this myself but not been able to reproduce it...

[apollo13]

Using a new state directory I could request 10 certificates without any problems from staging.
Running

acmetool --state=/tmp/acme --xlog.severity=debug reconcile

did not result in any output though, does it check how long the certs are valid before it tries to renew them (A yes, I should read what you wrote ;) -- how long is "close to expiry")? The dirs in certs/keys are fine, 10 domains means 10 subdirs, no more…

[apollo13]

Btw, it also works on the live server, desired and keys is properly created with your bugfix, only certs/live is missing, which is due to rate limiting.

On a non-related note:

20151206123908 [DEBUG] acme.solver: challenge start failed: listen tcp :443: bind: address already in use

20151206123908 [NOTICE] acme.responder: failed to listen on :80: listen tcp :80: bind: address already in use

I think you should change notice to debug, to match the 443 part (after all there is no need to bind to anything…)

[hlandau]

For reconcile, there's something of a lack of debug messages, currently. I'll change the notice message to debug.

Close to expiry is 30 days from expiry or 33% of the validity period remaining, whichever is lower.