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

Concurrency error when trying to get a certificate. #119

Closed
BenjaminSchubert opened this issue Apr 25, 2018 · 7 comments · Fixed by #120
Closed

Concurrency error when trying to get a certificate. #119

BenjaminSchubert opened this issue Apr 25, 2018 · 7 comments · Fixed by #120
Labels
bug

Comments

@BenjaminSchubert
Copy link

Hi,

Launching a pebble server and trying to get a certificate with cerbot gives me the following stacktrace:

[root@acme-v01 pebble]# pebble                                                                                                                                                                                     
Pebble 2018/04/25 19:29:01 Generated new root issuer with serial 30da9aed2261ac54                                                                                                                                  
Pebble 2018/04/25 19:29:02 Generated new intermediate issuer with serial 3669a10806ec4f                                                                                                                            
Pebble 2018/04/25 19:29:02 Configured to reject 15% of good nonces                                                                                                                                                 
Pebble 2018/04/25 19:29:02 Pebble running, listening on: 0.0.0.0:443                                                                                                                                               
Pebble 2018/04/25 19:34:13 GET /directory -> calling handler()                                                                                                                                                     
Pebble 2018/04/25 19:34:13 POST /sign-me-up -> calling handler()                                                                                                                                                   
Pebble 2018/04/25 19:34:13 There are now 1 accounts in memory                                                                                                                                                      
Pebble 2018/04/25 19:34:13 POST /order-plz -> calling handler()                                                                                                                                                    
Pebble 2018/04/25 19:34:13 There are now 1 authorizations in the db                                                                                                                                                
Pebble 2018/04/25 19:34:13 Added order "4PoZTdyfthd602Kjhhh8bqqGgrix2UUqm97mKgmkuVw" to the db                                                                                                                     
Pebble 2018/04/25 19:34:13 There are now 1 orders in the db                                                                                                                                                        
Pebble 2018/04/25 19:34:13 GET /authZ/ckogQJPdBf4suZAhqEGwEoAPo2bqoomU8J7dd7hrDJg -> calling handler()                                                                                                             
Pebble 2018/04/25 19:34:13 POST /chalZ/kePHA1sW3_BxeTn1P88XTRLKzOGTwhetMWZI6Or0IeU -> calling handler()                                                                                                            
Pebble 2018/04/25 19:34:13 Pulled a task from the Tasks queue: &va.vaTask{Identifier:"nyarlathotep.benschubert.me", Challenge:(*core.Challenge)(0xc42006f860), Account:(*core.Account)(0xc420064500)}              
Pebble 2018/04/25 19:34:13 Starting 3 validations.                                                                                                                                                                 
Pebble 2018/04/25 19:34:13 Sleeping for 14s seconds before validating                                                                                                                                              
Pebble 2018/04/25 19:34:13 Sleeping for 1s seconds before validating                                                                                                                                               
Pebble 2018/04/25 19:34:13 Sleeping for 3s seconds before validating                                                                                                                                               
Pebble 2018/04/25 19:34:14 Attempting to validate w/ HTTP: http://nyarlathotep.benschubert.me:5002/.well-known/acme-challenge/slSSG71_vquWaWQ2qnWRK5xDvKsMsVQAaNOpdbmyOTI                                          
fatal error: sync: Unlock of unlocked RWMutex                                                                                                                                                                      
                                                                                                                                                                                                                   
goroutine 15 [running]:                                                                                                                                                                                            
runtime.throw(0x770a27, 0x20)                                                                                                                                                                                      
        /usr/lib/golang/src/runtime/panic.go:605 +0x95 fp=0xc42004be20 sp=0xc42004be00 pc=0x42b9f5                                                                                                                 
sync.throw(0x770a27, 0x20)                          
        /usr/lib/golang/src/runtime/panic.go:594 +0x35 fp=0xc42004be40 sp=0xc42004be20 pc=0x42b955       
sync.(*RWMutex).Unlock(0xc42006f860)                
        /usr/lib/golang/src/sync/rwmutex.go:125 +0xa1 fp=0xc42004be70 sp=0xc42004be40 pc=0x46ed91        
github.com/letsencrypt/pebble/va.VAImpl.setAuthzInvalid(0xc420064280, 0x8ea100, 0x944600, 0x138a, 0x1389, 0xc4200542a0, 0x1, 0xc420102480, 0xc42006f860, 0xc4203f1e60)                                             
        /root/go/src/github.com/letsencrypt/pebble/va/va.go:189 +0x106 fp=0xc42004be98 sp=0xc42004be70 pc=0x6a3fe6                                                                                                 
github.com/letsencrypt/pebble/va.VAImpl.process(0xc420064280, 0x8ea100, 0x944600, 0x138a, 0x1389, 0xc4200542a0, 0x1, 0xc4203ee100)                                                                                 
        /root/go/src/github.com/letsencrypt/pebble/va/va.go:214 +0x3c1 fp=0xc42004bfa0 sp=0xc42004be98 pc=0x6a4431                                                                                                 
runtime.goexit()                                    
        /usr/lib/golang/src/runtime/asm_amd64.s:2337 +0x1 fp=0xc42004bfa8 sp=0xc42004bfa0 pc=0x459441    
created by github.com/letsencrypt/pebble/va.VAImpl.processTasks                                          
        /root/go/src/github.com/letsencrypt/pebble/va/va.go:136 +0x8b                                    

goroutine 1 [IO wait]:                              
internal/poll.runtime_pollWait(0x7fa57b7adf70, 0x72, 0xffffffffffffffff)                                 
        /usr/lib/golang/src/runtime/netpoll.go:173 +0x57                                                 
internal/poll.(*pollDesc).wait(0xc4200e6098, 0x72, 0xc42004d900, 0x0, 0x0)                               
        /usr/lib/golang/src/internal/poll/fd_poll_runtime.go:85 +0xae                                    
internal/poll.(*pollDesc).waitRead(0xc4200e6098, 0xffffffffffffff00, 0x0, 0x0)                           
        /usr/lib/golang/src/internal/poll/fd_poll_runtime.go:90 +0x3d                                    
internal/poll.(*FD).Accept(0xc4200e6080, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)                              
        /usr/lib/golang/src/internal/poll/fd_unix.go:335 +0x1e2                                          
net.(*netFD).accept(0xc4200e6080, 0xc420020070, 0xc420020000, 0xc420064190)                              
        /usr/lib/golang/src/net/fd_unix.go:238 +0x42
net.(*TCPListener).accept(0xc42000e008, 0x42ac66, 0x77e870, 0xc42004dae0)                                
        /usr/lib/golang/src/net/tcpsock_posix.go:136 +0x2e                                               
net.(*TCPListener).AcceptTCP(0xc42000e008, 0x402c01, 0xc42006e120, 0x7016c0)
        /usr/lib/golang/src/net/tcpsock.go:234 +0x49                                                                                                                                                        [27/80]
net/http.tcpKeepAliveListener.Accept(0xc42000e008, 0x434b2b, 0xc42004db20, 0x61f4b8, 0x455f00)
        /usr/lib/golang/src/net/http/server.go:3120 +0x2f
crypto/tls.(*listener).Accept(0xc4203efc00, 0x77e218, 0xc42006e0a0, 0x8e94c0, 0xc4203f0e70)
        /usr/lib/golang/src/crypto/tls/tls.go:52 +0x37
net/http.(*Server).Serve(0xc42006c680, 0x8e8b40, 0xc4203efc00, 0x0, 0x0)
        /usr/lib/golang/src/net/http/server.go:2695 +0x1b2
net/http.(*Server).ServeTLS(0xc42006c680, 0x8e9000, 0xc42000e008, 0xc42001c2a0, 0x30, 0xc42001c2d0, 0x2f, 0x0, 0xc42006c680)
        /usr/lib/golang/src/net/http/server.go:2764 +0x293
net/http.(*Server).ListenAndServeTLS(0xc42006c680, 0xc42001c2a0, 0x30, 0xc42001c2d0, 0x2f, 0x0, 0x0)
        /usr/lib/golang/src/net/http/server.go:2943 +0xd1
net/http.ListenAndServeTLS(0xc4200185f0, 0xb, 0xc42001c2a0, 0x30, 0xc42001c2d0, 0x2f, 0x8e47c0, 0xc4203f0780, 0xc4200502c0, 0xc4200115c0)
        /usr/lib/golang/src/net/http/server.go:2915 +0xb1
main.main()
        /root/go/src/github.com/letsencrypt/pebble/cmd/pebble/main.go:58 +0x5d6

goroutine 6 [chan receive]:
github.com/letsencrypt/pebble/va.VAImpl.processTasks(0xc420064280, 0x8ea100, 0x944600, 0x138a, 0x1389, 0xc4200542a0, 0x1)
        /root/go/src/github.com/letsencrypt/pebble/va/va.go:135 +0xa3
created by github.com/letsencrypt/pebble/va.New
        /root/go/src/github.com/letsencrypt/pebble/va/va.go:120 +0x22c

goroutine 7 [IO wait]:
internal/poll.runtime_pollWait(0x7fa57b7adeb0, 0x72, 0x0)
        /usr/lib/golang/src/runtime/netpoll.go:173 +0x57
internal/poll.(*pollDesc).wait(0xc4200e6018, 0x72, 0xffffffffffffff00, 0x8e6180, 0x8e2550)
        /usr/lib/golang/src/internal/poll/fd_poll_runtime.go:85 +0xae
internal/poll.(*pollDesc).waitRead(0xc4200e6018, 0xc4202b2000, 0x1000, 0x1000)
        /usr/lib/golang/src/internal/poll/fd_poll_runtime.go:90 +0x3d
internal/poll.(*FD).Read(0xc4200e6000, 0xc4202b2000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
        /usr/lib/golang/src/internal/poll/fd_unix.go:126 +0x18a
net.(*netFD).Read(0xc4200e6000, 0xc4202b2000, 0x1000, 0x1000, 0x7a6693e40ef45edc, 0x7e75dcbb9c348bb2, 0x7a6693e40ef45edc)
        /usr/lib/golang/src/net/fd_unix.go:202 +0x52
net.(*conn).Read(0xc42000e030, 0xc4202b2000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
        /usr/lib/golang/src/net/net.go:176 +0x6d
crypto/tls.(*block).readFromUntil(0xc42005ecf0, 0x7fa57b7bb840, 0xc42000e030, 0x5, 0xc42000e030, 0xc420001800)
        /usr/lib/golang/src/crypto/tls/conn.go:488 +0x95
crypto/tls.(*Conn).readRecord(0xc42007a380, 0x77e817, 0xc42007a4a0, 0xc4202d5b00)
        /usr/lib/golang/src/crypto/tls/conn.go:590 +0xe0
crypto/tls.(*Conn).Read(0xc42007a380, 0xc4200fc000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
        /usr/lib/golang/src/crypto/tls/conn.go:1134 +0x110
net/http.(*connReader).Read(0xc42005f0b0, 0xc4200fc000, 0x1000, 0x1000, 0xc420001800, 0x44abe8, 0x7e13b83b9a)
        /usr/lib/golang/src/net/http/server.go:753 +0x105
bufio.(*Reader).fill(0xc420054540)
        /usr/lib/golang/src/bufio/bufio.go:97 +0x11a
bufio.(*Reader).Peek(0xc420054540, 0x4, 0x0, 0x0, 0x0, 0x0, 0x0)
        /usr/lib/golang/src/bufio/bufio.go:129 +0x3a
net/http.(*conn).readRequest(0xc42006e0a0, 0x8e9400, 0xc420050780, 0x0, 0x0, 0x0)
        /usr/lib/golang/src/net/http/server.go:930 +0xc77
net/http.(*conn).serve(0xc42006e0a0, 0x8e9400, 0xc420050780)
        /usr/lib/golang/src/net/http/server.go:1739 +0x50e
created by net/http.(*Server).Serve
        /usr/lib/golang/src/net/http/server.go:2720 +0x288
goroutine 20 [runnable]:
net/http.setRequestCancel.func3(0x0, 0xc4203f1740, 0xc420051040, 0xc42001975c, 0xc42001ecc0)
        /usr/lib/golang/src/net/http/client.go:320 +0x118
created by net/http.setRequestCancel
        /usr/lib/golang/src/net/http/client.go:319 +0x2bf

goroutine 18 [sleep]:
time.Sleep(0xb2d05e00)
        /usr/lib/golang/src/runtime/time.go:65 +0x130
github.com/jmhodges/clock.(*sysClock).Sleep(0x944600, 0xb2d05e00)
        /root/go/src/github.com/jmhodges/clock/clock.go:76 +0x2b
github.com/letsencrypt/pebble/va.VAImpl.performValidation(0xc420064280, 0x8ea100, 0x944600, 0x138a, 0x1389, 0xc4200542a0, 0x1, 0xc4203ee100, 0xc420054f60)
        /root/go/src/github.com/letsencrypt/pebble/va/va.go:229 +0x551
created by github.com/letsencrypt/pebble/va.VAImpl.process
        /root/go/src/github.com/letsencrypt/pebble/va/va.go:208 +0x31a

goroutine 19 [sleep]:
time.Sleep(0x342770c00)
        /usr/lib/golang/src/runtime/time.go:65 +0x130
github.com/jmhodges/clock.(*sysClock).Sleep(0x944600, 0x342770c00)
        /root/go/src/github.com/jmhodges/clock/clock.go:76 +0x2b
github.com/letsencrypt/pebble/va.VAImpl.performValidation(0xc420064280, 0x8ea100, 0x944600, 0x138a, 0x1389, 0xc4200542a0, 0x1, 0xc4203ee100, 0xc420054f60)
        /root/go/src/github.com/letsencrypt/pebble/va/va.go:229 +0x551
created by github.com/letsencrypt/pebble/va.VAImpl.process
        /root/go/src/github.com/letsencrypt/pebble/va/va.go:208 +0x31a

I sadly don't know enough of go to debug this but I can help in reproducing/testing if needed.
@cpu cpu added the bug label Apr 25, 2018
@cpu
Copy link
Contributor

cpu commented Apr 25, 2018

Thanks for the bug report @BenjaminSchubert 🍰

Can you share the Certbot command line you ran when you produced this Pebble output?

@BenjaminSchubert
Copy link
Author

Ensuring we don't have anything in /etc/letsencrypt; I run:

certbot certonly --standalone -m test@test.com -d test@test.com --agree-tos

On a fedora:27 image up to date.

@BenjaminSchubert
Copy link
Author

BenjaminSchubert commented Apr 25, 2018 •
edited
Loading

@cpu here is a vagrant file that contains my environment and the steps I perform.

To reproduce you can do:

# create Vagrantfile with the content below
vagrant up
vagrant ssh
sudo su
certbot certonly --standalone -m test@test.com -d test@test.com --agree-tos  # will fail
tmux attach  # will allow you to see the error

# -*- mode: ruby -*-
# vi: set ft=ruby :

# All Vagrant configuration is done below. The "2" in Vagrant.configure
# configures the configuration version (we support older styles for
# backwards compatibility). Please don't change it unless you know what
# you're doing.
Vagrant.configure("2") do |config|
  config.vm.box = "fedora/27-cloud-base"

  config.vm.provider :libvirt do |libvirt|
    libvirt.memory = 4096
  end

  config.vm.define "letsencrypt" do |vm0|
    vm0.vm.hostname = "acme-v01.api.letsencrypt.org"

    vm0.vm.provision "shell", inline: <<-SHELL
      dnf update --assumeyes
      dnf install --assumeyes git golang tmux

      echo 10.0.21.244 acme-v01.api.letsencrypt.org >> /etc/hosts
    
      go get -u github.com/letsencrypt/pebble/...
      go get github.com/jsha/minica

      cd /root/go/src/github.com/letsencrypt/pebble

      # update certificates
      cp test/certs/pebble.minica.pem /etc/pki/ca-trust/source/anchors/test.crt
      update-ca-trust

      # use the default directory
      sed -i s:/dir:/directory:g wfe/wfe.go
      go install ./...

      echo 'export PATH=$PATH:/root/go/bin' > /root/.bashrc
      source /root/.bashrc

      cd test/certs
      minica -ca-cert pebble.minica.pem -ca-key pebble.minica.key.pem -domains acme-v01.api.letsencrypt.org
      cd ../..

      sed -i s/14000/443/g test/config/pebble-config.json
      sed -i s/localhost/acme-v01.api.letsencrypt.org/g test/config/pebble-config.json

      tmux new-session -d -s pebble
      tmux send-keys pebble C-m
    SHELL
  end
end

@cpu
Copy link
Contributor

cpu commented Apr 26, 2018

@BenjaminSchubert Thanks for the detailed reproduction notes & the Vagrantfile! That's a great help. I'll try to take a look at this crash this afternoon.

@cpu cpu mentioned this issue Apr 26, 2018
Merged
@cpu
Copy link
Contributor

cpu commented Apr 26, 2018

Hi again @BenjaminSchubert 👋 I was able to reproduce this bug and put a fix out in #120 Thanks again for the bug report!!

certbot certonly --standalone -m test@test.com -d test@test.com --agree-tos

The issue here is that the -d test@test.com argument is invalid. -d is for a domain name. I think Pebble's input validation could use some work because it didn't reject this outright as an invalid domain name, and instead tried to do an HTTP-01 validation to "http://test%40test.com:5002/.well-known/acme-challenge/<token>" which failed. That tickled a bug that we didn't know about that caused Pebble to crash :-)

With the bug fixed applied you'll get a different result:

FailedChallenges: Failed authorization procedure. test@test.com (http-01): urn:ietf:params:acme:error:malformedRequest :: Invalid URL "http://test%40test.com:5002/.well-known/acme-challenge/h3sCmsNTEFS-0yOikQEHrFUPEGCcGVPF4ncS9NwmZio"

As a side-note: You might be able to simplify your Vagrantfile if you use the SERVER and REQUESTS_CA_BUNDLE environment variables with Certbot. That will let you point Certbot at the Pebble CA PEM file and the Pebble listen address without having to change system-wide trust stores or adding /etc/host entries to mock out acme-v01.api.letsencrypt.org.

I run Certbot against Pebble on my localhost like this: REQUESTS_CA_BUNDLE=~/go/src/github.com/letsencrypt/pebble/test/certs/pebble.minica.pem SERVER=https://localhost:14000/dir certbot ...

@jsha jsha closed this as completed in #120 Apr 26, 2018
jsha pushed a commit that referenced this issue Apr 26, 2018
@cpu @jsha
VA: Don't unlock mutex twice (#120)
2223e02 
In `VA.setAuthzInvalid` we `defer` the `Unlock()` of a challenge's `sync.RWMutex`: https://github.com/letsencrypt/pebble/blob/43f6c387dc6278772c54da74f3eb7fb0c1703256/va/va.go#L183

Unfortunately, we also explicitly call `Unlock()` at the end of the function: https://github.com/letsencrypt/pebble/blob/43f6c387dc6278772c54da74f3eb7fb0c1703256/va/va.go#L188

The combination of doing both would panic the `pebble` binary when a challenge validation failed with an error like: `fatal error: sync: Unlock of unlocked RWMutex`

This commit removes the superfluous explicit `Unlock()`, fixes the panic, and resolves #119.

Thanks to @BenjaminSchubert for reporting this bug! 🏆
@cpu
Copy link
Contributor

cpu commented Apr 26, 2018

I created #121 to fix the input validation to reject nonsense domains earlier.

@cpu
Copy link
Contributor

cpu commented Apr 26, 2018

And with #120 now merged this should be fixed in master 👍

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

VA: Don't unlock mutex twice letsencrypt/pebble
2 participants
@cpu @BenjaminSchubert