labca icon indicating copy to clipboard operation
labca copied to clipboard
verified publisher icon hakwerk

Installation crashes during Setup

Open plani-de opened this issue 6 months ago • 4 comments

Having now set up a plain new system based on Debian 12 and installed docker. Following the installation steps, running docker compose etc. everything works fine. Then switching over to the browser, entering credentials for user, uploading and/or generating certificates, the last page won't load and hangs in a loop.

No difference if I upload my root-certificate or generate a new one. After failure I remove everything and restart from beginning. The only hint I find and believe is of interest in the logs is:

boulder-1    | 2025-06-05T12:47:20.856905+00:00Z boulder-ra[458]: 4 boulder-ra ipiciQk [core] [Channel #2 SubChannel #10]grpc: addrConn.createTransport failed to connect to {Addr: "10.77.77.77:9493", ServerName: "0a4d4d4d.addr.dc1.consul.", BalancerAttributes: {"<%!p(pickfirstleaf.managedByPickfirstKeyType={})>": "<%!p(bool=true)>" }}. Err: connection error: desc = "transport: Error while dialing: dial tcp 10.77.77.77:9493: connect: connection refused"\n

Update: This refers to the current version v25.05. Will now try v25.03 too.

plani-de avatar Jun 05 '25 12:06 plani-de

After countless hours of deleting - reinstalling - deleting - re... I want to share a few more hints. I just noticed this entry, quite at the beginning when using docker compose up, that this message appears 2-3 times:

bconsul-1    | ==> Failed to load cert/key pair: open /opt/boulder/labca/certs/ipki/consul.boulder/cert.pem: no such file or directory
bconsul-1 exited with code 0

followed by this

bconsul-1    | ==> Failed to load cert/key pair: open /opt/boulder/labca/certs/ipki/consul.boulder/cert.pem: no such file or directory
boulder-1    | Thu Jun  5 20:32:51 UTC 2025 - still trying to connect to boulder-mysql:3306
bconsul-1 exited with code 1

I then restarted the container for consul, but that didn't help either. An inspection of the consul container showed this:

"Networks": {
                "labca_bouldernet": {
                    "IPAMConfig": {
                        "IPv4Address": "10.77.77.10"
                    },

Shouldn't that be the same IP address as in the request from boulder? Either both 10.77.77.77 or 10.77.77.10?

plani-de avatar Jun 05 '25 21:06 plani-de

And after letting it sit over night and having a look this morning when reloading the /admin/setup page, after login as admin-user, this happens again:

gui-1        | 2025/06/06 06:18:10 GET /setup
nginx-1      | ::ffff:172.28.56.200 - - [06/Jun/2025:06:18:14 +0000] "GET /admin/setup HTTP/1.1" 200 9207 "https://ca.lan/admin/login" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/136.0.0.0 Safari/537.36" "-"
nginx-1      | ::ffff:172.28.56.200 - - [06/Jun/2025:06:18:14 +0000] "GET /admin/static/img/spinner.gif HTTP/1.1" 200 15871 "https://ca.lan/admin/setup" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/136.0.0.0 Safari/537.36" "-"
gui-1        | 2025/06/06 06:18:44 GET /final
nginx-1      | ::ffff:172.28.56.200 - - [06/Jun/2025:06:18:48 +0000] "GET /admin/final HTTP/1.1" 499 0 "https://ca.lan/admin/setup" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/136.0.0.0 Safari/537.36" "-"
gui-1        | 2025/06/06 06:18:49 GET /final
nginx-1      | ::ffff:172.28.56.200 - - [06/Jun/2025:06:18:49 +0000] "GET /admin/final HTTP/1.1" 200 33 "https://ca.lan/admin/setup" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/136.0.0.0 Safari/537.36" "-"
gui-1        | 2025/06/06 06:18:54 GET /final
nginx-1      | ::ffff:172.28.56.200 - - [06/Jun/2025:06:18:54 +0000] "GET /admin/final HTTP/1.1" 200 33 "https://ca.lan/admin/setup" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/136.0.0.0 Safari/537.36" "-"
gui-1        | 2025/06/06 06:18:59 GET /final
nginx-1      | ::ffff:172.28.56.200 - - [06/Jun/2025:06:18:59 +0000] "GET /admin/final HTTP/1.1" 200 33 "https://ca.lan/admin/setup" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/136.0.0.0 Safari/537.36" "-"
gui-1        | 2025/06/06 06:19:04 GET /final
nginx-1      | ::ffff:172.28.56.200 - - [06/Jun/2025:06:19:04 +0000] "GET /admin/final HTTP/1.1" 200 33 "https://ca.lan/admin/setup" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/136.0.0.0 Safari/537.36" "-"
gui-1        | 2025/06/06 06:19:09 GET /final
nginx-1      | ::ffff:172.28.56.200 - - [06/Jun/2025:06:19:09 +0000] "GET /admin/final HTTP/1.1" 200 33 "https://ca.lan/admin/setup" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/136.0.0.0 Safari/537.36" "-"
boulder-1    | 2025-06-06T06:19:09.923226+00:00Z boulder-wfe2[472]: 6 boulder-wfe2 vJfQjw4 POST /acme/new-order 1 400 367 0.0.0.0 JSON={"InternalErrors":["JWS has an invalid anti-replay nonce: \"Zy_ps6C1UK1fRbOK5SW53Y6gO1EKsL8Iy1S6Q-k_qM4XPhC_6z4\""],"Error":"400 :: badNonce :: Unable to validate JWS :: JWS has an invalid anti-replay nonce: \"Zy_ps6C1UK1fRbOK5SW53Y6gO1EKsL8Iy1S6Q-k_qM4XPhC_6z4\"","ua":"CertbotACMEClient/4.0.0 (certbot; Ubuntu 24.04.2 LTS) Authenticator/webroot Installer/None (certonly; flags: n) Py/3.10.17"}
boulder-1    | 2025-06-06T06:19:10.579647+00:00Z boulder-wfe2[472]: 6 boulder-wfe2 qMDskAs POST /acme/new-order 1 201 623 0.0.0.0 JSON={"ua":"CertbotACMEClient/4.0.0 (certbot; Ubuntu 24.04.2 LTS) Authenticator/webroot Installer/None (certonly; flags: n) Py/3.10.17","Created":"3","Identifiers":[{"type":"dns","value":"ca.lan"}]}
boulder-1    | 2025-06-06T06:19:10.688703+00:00Z boulder-wfe2[472]: 6 boulder-wfe2 uoCnSQA POST /acme/authz/ 1 200 83 0.0.0.0 JSON={"Slug":"1/1","ua":"CertbotACMEClient/4.0.0 (certbot; Ubuntu 24.04.2 LTS) Authenticator/webroot Installer/None (certonly; flags: n) Py/3.10.17","Status":"valid","Identifiers":[{"type":"dns","value":"ca.lan"}]}
boulder-1    | 2025-06-06T06:19:11.084950+00:00Z boulder-va[280]: 6 boulder-va mOzr9Qk [AUDIT] Checked CAA records for ca.lan, [Present: false, Account ID: 1, Challenge: http-01, Valid for issuance: true, Found at: ""] Response=""
boulder-1    | 2025-06-06T06:19:11.248188+00:00Z remoteva[261]: 6 remoteva mOzr9Qk [AUDIT] Checked CAA records for ca.lan, [Present: false, Account ID: 1, Challenge: http-01, Valid for issuance: true, Found at: ""] Response=""
boulder-1    | 2025-06-06T06:19:11.270445+00:00Z remoteva[261]: 6 remoteva vsHXkgc [AUDIT] CAA check result JSON={"AuthzID":"","Requester":1,"Identifier":{"type":"dns","value":"ca.lan"},"Challenge":{"type":""},"Latency":0.028}
boulder-1    | 2025-06-06T06:19:11.283375+00:00Z remoteva[180]: 6 remoteva mOzr9Qk [AUDIT] Checked CAA records for ca.lan, [Present: false, Account ID: 1, Challenge: http-01, Valid for issuance: true, Found at: ""] Response=""
boulder-1    | 2025-06-06T06:19:11.288674+00:00Z remoteva[148]: 6 remoteva mOzr9Qk [AUDIT] Checked CAA records for ca.lan, [Present: false, Account ID: 1, Challenge: http-01, Valid for issuance: true, Found at: ""] Response=""
boulder-1    | 2025-06-06T06:19:11.301878+00:00Z remoteva[180]: 6 remoteva 7ezy1wg [AUDIT] CAA check result JSON={"AuthzID":"","Requester":1,"Identifier":{"type":"dns","value":"ca.lan"},"Challenge":{"type":""},"Latency":0.012}
boulder-1    | 2025-06-06T06:19:11.313710+00:00Z remoteva[148]: 6 remoteva pt-hyAY [AUDIT] CAA check result JSON={"AuthzID":"","Requester":1,"Identifier":{"type":"dns","value":"ca.lan"},"Challenge":{"type":""},"Latency":0.019}
boulder-1    | 2025-06-06T06:19:11.328646+00:00Z boulder-va[280]: 6 boulder-va v8KGDAA [AUDIT] CAA check result JSON={"AuthzID":"","Requester":1,"Identifier":{"type":"dns","value":"ca.lan"},"Challenge":{"type":""},"Latency":0.264,"Summary":{"passedPerspectives":["cubist","dadaist","surrealist"],"failedPerspectives":[],"passedRIRs":["ARIN","RIPE"],"quorumResult":"3/3"}}
boulder-1    | 2025-06-06T06:19:11.330463+00:00Z boulder-ra[418]: 6 boulder-ra 4rP-zAM FinalizationCaaCheck JSON={"Requester":1,"Rechecked":1}
bpkimetal-1  | {"level":"info","@timestamp":"2025-06-06T06:19:12.691Z","msg":"Linting Request","client_ip":"10.77.77.77","http_method":"POST","http_status":200,"protocol":"HTTP/1.1","raw_path":"/lintcert","response_body_size":2589,"time_taken_ns":764726294,"request_content_type":"application/x-www-form-urlencoded","user_agent":"Go-http-client/1.1","num_results":13}
boulder-1    | 2025-06-06T06:19:12.708957+00:00Z boulder-ca[399]: 3 boulder-ca o8m1hAM [AUDIT] Preparing precert failed: serial=[6e99ba2005b2ae388288e5f58ac5802c51ab] err=[tbsCertificate linting failed: failed lint(s): e_pkimetal_lint_cabf_serverauth_cert (got 1 lint findings from pkimetal API: error from certlint:unknown_tld_in_san: Unknown TLD in SAN)]
boulder-1    | 2025-06-06T06:19:12.723964+00:00Z boulder-ra[418]: 6 boulder-ra ppaWvQI [AUDIT] Certificate request - error JSON={"ID":"O1wIJLB_-c7pQPKYF7QOAodSiFfZrRj1NRpxnncUGsk","Requester":1,"OrderID":3,"VerifiedFields":["subject.commonName","subjectAltName"],"NotBefore":"0001-01-01T00:00:00Z","NotAfter":"0001-01-01T00:00:00Z","RequestTime":"2025-06-06T06:19:10.772593091Z","ResponseTime":"2025-06-06T06:19:12.723075249Z","Error":"failed to prepare precertificate signing: tbsCertificate linting failed: failed lint(s): e_pkimetal_lint_cabf_serverauth_cert (got 1 lint findings from pkimetal API: error from certlint:unknown_tld_in_san: Unknown TLD in SAN)","Authorizations":{"ca.lan":{"ID":"1","ChallengeType":"http-01"}},"PreviousCertificateIssued":"0001-01-01T00:00:00Z","UserAgent":"CertbotACMEClient/4.0.0 (certbot; Ubuntu 24.04.2 LTS) Authenticator/webroot Installer/None (certonly; flags: n) Py/3.10.17"}
boulder-1    | 2025-06-06T06:19:12.725735+00:00Z boulder-wfe2[472]: 6 boulder-wfe2 iKPpxgo POST /acme/finalize/ 1 500 2005 0.0.0.0 JSON={"Slug":"1/3","InternalErrors":["failed to prepare precertificate signing: tbsCertificate linting failed: failed lint(s): e_pkimetal_lint_cabf_serverauth_cert (got 1 lint findings from pkimetal API: error from certlint:unknown_tld_in_san: Unknown TLD in SAN)"],"Error":"500 :: serverInternal :: Error finalizing order","ua":"CertbotACMEClient/4.0.0 (certbot; Ubuntu 24.04.2 LTS) Authenticator/webroot Installer/None (certonly; flags: n) Py/3.10.17","Extra":{"KeyType":"RSA 2048"},"Identifiers":[{"type":"dns","value":"ca.lan"}]}
gui-1        | 2025/06/06 06:19:13 ERROR: Message from server: 'ERROR! On line 62 in commander script
gui-1        | '
gui-1        | 2025/06/06 06:19:13 errorHandler: err=ERROR! On line 62 in commander script
gui-1        | 
gui-1        | main._hostCommand({0x160d918, 0xc0006e6000}, 0xc0003c23c0, {0x108e5e7, 0xc}, {0x0, 0x0, 0xc00020c8b0?})
gui-1        |  /go/src/labca/main.go:2322 +0x812
gui-1        | main.finalHandler({0x160d918, 0xc0006e6000}, 0xc0003c23c0)
gui-1        |  /go/src/labca/main.go:2870 +0x4bd
gui-1        | net/http.HandlerFunc.ServeHTTP(0xf418c0?, {0x160d918?, 0xc0006e6000?}, 0xc0006e6000?)
gui-1        |  /usr/local/go/src/net/http/server.go:2294 +0x29
gui-1        | main.authorized.func1({0x160d918, 0xc0006e6000}, 0xc0003c23c0)
gui-1        |  /go/src/labca/main.go:3342 +0x32e
gui-1        | net/http.HandlerFunc.ServeHTTP(0xc0003c2280?, {0x160d918?, 0xc0006e6000?}, 0x1e23a80?)
gui-1        |  /usr/local/go/src/net/http/server.go:2294 +0x29
gui-1        | github.com/gorilla/mux.(*Router).ServeHTTP(0xc000d26000, {0x160d918, 0xc0006e6000}, 0xc0003c2000)
gui-1        |  /root/go/pkg/mod/github.com/gorilla/[email protected]/mux.go:212 +0x1e2
gui-1        | net/http.serverHandler.ServeHTTP({0xc0000febd0?}, {0x160d918?, 0xc0006e6000?}, 0x6?)
gui-1        |  /usr/local/go/src/net/http/server.go:3301 +0x8e
gui-1        | net/http.(*conn).serve(0xc0006d0000, {0x160fb20, 0xc000d4c810})
gui-1        |  /usr/local/go/src/net/http/server.go:2102 +0x625
gui-1        | created by net/http.(*Server).Serve in goroutine 1
gui-1        |  /usr/local/go/src/net/http/server.go:3454 +0x485
gui-1        | 2025/06/06 06:19:14 GET /final
nginx-1      | ::ffff:172.28.56.200 - - [06/Jun/2025:06:19:14 +0000] "GET /admin/final HTTP/1.1" 200 33 "https://ca.lan/admin/setup" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/136.0.0.0 Safari/537.36" "-"
gui-1        | 2025/06/06 06:19:16 http: superfluous response.WriteHeader call from main.finalHandler (main.go:2873)
gui-1        | 2025/06/06 06:19:19 GET /final
nginx-1      | ::ffff:172.28.56.200 - - [06/Jun/2025:06:19:19 +0000] "GET /admin/final HTTP/1.1" 200 32 "https://ca.lan/admin/setup" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/136.0.0.0 Safari/537.36" "-"
gui-1        | 2025/06/06 06:19:19 GET /error
gui-1        | 2025/06/06 06:19:19 errorHandler: err=<nil>
gui-1        | main.showErrorHandler({0x160d918?, 0xc0009800e0?}, 0x5?)
gui-1        |  /go/src/labca/main.go:2899 +0x27
gui-1        | net/http.HandlerFunc.ServeHTTP(0xf418c0?, {0x160d918?, 0xc0009800e0?}, 0xc0009800e0?)
gui-1        |  /usr/local/go/src/net/http/server.go:2294 +0x29
gui-1        | main.authorized.func1({0x160d918, 0xc0009800e0}, 0xc0003c3680)
gui-1        |  /go/src/labca/main.go:3342 +0x32e
gui-1        | net/http.HandlerFunc.ServeHTTP(0xc0003c3540?, {0x160d918?, 0xc0009800e0?}, 0x1e23a80?)
gui-1        |  /usr/local/go/src/net/http/server.go:2294 +0x29
gui-1        | github.com/gorilla/mux.(*Router).ServeHTTP(0xc000d26000, {0x160d918, 0xc0009800e0}, 0xc0003c3040)
gui-1        |  /root/go/pkg/mod/github.com/gorilla/[email protected]/mux.go:212 +0x1e2
gui-1        | net/http.serverHandler.ServeHTTP({0xc000d90c00?}, {0x160d918?, 0xc0009800e0?}, 0x6?)
gui-1        |  /usr/local/go/src/net/http/server.go:3301 +0x8e
gui-1        | net/http.(*conn).serve(0xc0006d1050, {0x160fb20, 0xc000d4c810})
gui-1        |  /usr/local/go/src/net/http/server.go:2102 +0x625
gui-1        | created by net/http.(*Server).Serve in goroutine 1
gui-1        |  /usr/local/go/src/net/http/server.go:3454 +0x485
nginx-1      | ::ffff:172.28.56.200 - - [06/Jun/2025:06:19:20 +0000] "GET /admin/error HTTP/1.1" 500 25381 "https://ca.lan/admin/setup" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/136.0.0.0 Safari/537.36" "-"

It's always the last step when generating the 2nd certficate. After the error-page appears, reloading the setup-page states everything is fine and starts to sign a certificate for itself and this then again leads to the errorpage after a while. N.B.: ca.lan is the fqdn

plani-de avatar Jun 06 '25 06:06 plani-de

Just wanted to add: Using Debian 12 on a DellWyse. Docker version 28.2.2, build e6534b4 installed. Anybody any clue?

plani-de avatar Jun 07 '25 13:06 plani-de

After several days trying to understand what docker does and where to dig and taking advice from other (solved) issues, I'm still not getting LabCA up and running and keep hitting two message types. First of all the final message I find in the logs wenn LabCa-WebGUI does the last and final reload :

gui-1        | 2025/06/12 18:35:49 ERROR: Message from server: 'ERROR! On line 62 in commander script
gui-1        | '
gui-1        | 2025/06/12 18:35:49 errorHandler: err=ERROR! On line 62 in commander script
gui-1        | 
gui-1        | main._hostCommand({0x160d918, 0xc000d022a0}, 0xc000d11540, {0x108e5e7, 0xc}, {0x0, 0x0, 0xc00046ebd0?})
gui-1        |  /go/src/labca/main.go:2322 +0x812
gui-1        | main.finalHandler({0x160d918, 0xc000d022a0}, 0xc000d11540)
gui-1        |  /go/src/labca/main.go:2870 +0x4bd
gui-1        | net/http.HandlerFunc.ServeHTTP(0xf418c0?, {0x160d918?, 0xc000d022a0?}, 0xc000d022a0?)
gui-1        |  /usr/local/go/src/net/http/server.go:2294 +0x29
gui-1        | main.authorized.func1({0x160d918, 0xc000d022a0}, 0xc000d11540)
gui-1        |  /go/src/labca/main.go:3342 +0x32e
gui-1        | net/http.HandlerFunc.ServeHTTP(0xc000d11400?, {0x160d918?, 0xc000d022a0?}, 0x1e23a80?)
gui-1        |  /usr/local/go/src/net/http/server.go:2294 +0x29
gui-1        | github.com/gorilla/mux.(*Router).ServeHTTP(0xc000154000, {0x160d918, 0xc000d022a0}, 0xc000d112c0)
gui-1        |  /root/go/pkg/mod/github.com/gorilla/[email protected]/mux.go:212 +0x1e2
gui-1        | net/http.serverHandler.ServeHTTP({0xc000d7c000?}, {0x160d918?, 0xc000d022a0?}, 0x6?)
gui-1        |  /usr/local/go/src/net/http/server.go:3301 +0x8e
gui-1        | net/http.(*conn).serve(0xc00044ce10, {0x160fb20, 0xc0004e1ec0})
gui-1        |  /usr/local/go/src/net/http/server.go:2102 +0x625
gui-1        | created by net/http.(*Server).Serve in goroutine 1
gui-1        |  /usr/local/go/src/net/http/server.go:3454 +0x485
gui-1        | 2025/06/12 18:35:53 http: superfluous response.WriteHeader call from main.finalHandler (main.go:2873)
gui-1        | 2025/06/12 18:35:53 GET /final
nginx-1      | ::ffff:172.28.56.200 - - [12/Jun/2025:18:35:53 +0000] "GET /admin/final HTTP/1.1" 200 32 "https://ca.lan/admin/setup" "Mozilla/5.0 (X11; Linux x86_64; rv:139.0) Gecko/20100101 Firefox/139.0" "-"
gui-1        | 2025/06/12 18:35:53 GET /error
gui-1        | main.showErrorHandler({0x160d918?, 0xc000e341c0?}, 0x5?)
gui-1        |  /go/src/labca/main.go:2899 +0x27
gui-1        | net/http.HandlerFunc.ServeHTTP(0xf418c0?, {0x160d918?, 0xc000e341c0?}, 0xc000e341c0?)
gui-1        |  /usr/local/go/src/net/http/server.go:2294 +0x29
gui-1        | main.authorized.func1({0x160d918, 0xc000e341c0}, 0xc0002fedc0)
gui-1        |  /go/src/labca/main.go:3342 +0x32e
gui-1        | net/http.HandlerFunc.ServeHTTP(0xc0002feb40?, {0x160d918?, 0xc000e341c0?}, 0x1e23a80?)
gui-1        |  /usr/local/go/src/net/http/server.go:2294 +0x29
gui-1        | github.com/gorilla/mux.(*Router).ServeHTTP(0xc000154000, {0x160d918, 0xc000e341c0}, 0xc0002fea00)
gui-1        |  /root/go/pkg/mod/github.com/gorilla/[email protected]/mux.go:212 +0x1e2
gui-1        | net/http.serverHandler.ServeHTTP({0xc000d7d080?}, {0x160d918?, 0xc000e341c0?}, 0x6?)
gui-1        |  /usr/local/go/src/net/http/server.go:3301 +0x8e
gui-1        | net/http.(*conn).serve(0xc00044d5f0, {0x160fb20, 0xc0004e1ec0})
gui-1        |  /usr/local/go/src/net/http/server.go:2102 +0x625
gui-1        | created by net/http.(*Server).Serve in goroutine 1
gui-1        |  /usr/local/go/src/net/http/server.go:3454 +0x485
gui-1        | 2025/06/12 18:35:53 errorHandler: err=<nil>

Second is the different logs regarding connection errors between containers. This is alway:

boulder-1    | health checking ra.boulder (localhost:9594)
boulder-1    | 2025-06-12T18:34:42.283475+00:00Z boulder-ra[323]: 4 boulder-ra 88mJ5go [core] [Channel #3 SubChannel #15]grpc: addrConn.createTransport failed to connect to {Addr: "10.77.77.77:9493", ServerName: "0a4d4d4d.addr.dc1.consul.", BalancerAttributes: {"<%!p(pickfirstleaf.managedByPickfirstKeyType={})>": "<%!p(bool=true)>" }}. Err: connection error: desc = "transport: Error while dialing: dial tcp 10.77.77.77:9493: connect: connection refused"\n
boulder-1    | 2025-06-12T18:34:42.307621+00:00Z boulder-ra[323]: 4 boulder-ra w_X00w0 [core] [Channel #2 SubChannel #11]grpc: addrConn.createTransport failed to connect to {Addr: "10.77.77.77:9393", ServerName: "0a4d4d4d.addr.dc1.consul.", BalancerAttributes: {"<%!p(pickfirstleaf.managedByPickfirstKeyType={})>": "<%!p(bool=true)>" }}. Err: connection error: desc = "transport: Error while dialing: dial tcp 10.77.77.77:9393: connect: connection refused"\n
boulder-1    | 2025-06-12T18:34:42.307923+00:00Z boulder-ra[323]: 4 boulder-ra 6OKbsgc [core] [Channel #1 SubChannel #13]grpc: addrConn.createTransport failed to connect to {Addr: "10.77.77.77:9392", ServerName: "0a4d4d4d.addr.dc1.consul.", BalancerAttributes: {"<%!p(pickfirstleaf.managedByPickfirstKeyType={})>": "<%!p(bool=true)>" }}. Err: connection error: desc = "transport: Error while dialing: dial tcp 10.77.77.77:9392: connect: connection refused"\n
boulder-1    | 2025-06-12T18:34:42.310383+00:00Z boulder-ra[323]: 4 boulder-ra geiJyQ4 [core] [Channel #2 SubChannel #12]grpc: addrConn.createTransport failed to connect to {Addr: "10.77.77.77:9493", ServerName: "0a4d4d4d.addr.dc1.consul.", BalancerAttributes: {"<%!p(pickfirstleaf.managedByPickfirstKeyType={})>": "<%!p(bool=true)>" }}. Err: connection error: desc = "transport: Error while dialing: dial tcp 10.77.77.77:9493: connect: connection refused"\n
boulder-1    | 2025-06-12T18:34:42.311417+00:00Z boulder-ra[323]: 4 boulder-ra sdT0_Ak [core] [Channel #3 SubChannel #16]grpc: addrConn.createTransport failed to connect to {Addr: "10.77.77.77:9393", ServerName: "0a4d4d4d.addr.dc1.consul.", BalancerAttributes: {"<%!p(pickfirstleaf.managedByPickfirstKeyType={})>": "<%!p(bool=true)>" }}. Err: connection error: desc = "transport: Error while dialing: dial tcp 10.77.77.77:9393: connect: connection refused"\n
boulder-1    | 2025-06-12T18:34:42.373149+00:00Z boulder-ra[323]: 4 boulder-ra vJ_NqAs [core] [Channel #1 SubChannel #14]grpc: addrConn.createTransport failed to connect to {Addr: "10.77.77.77:9492", ServerName: "0a4d4d4d.addr.dc1.consul.", BalancerAttributes: {"<%!p(pickfirstleaf.managedByPickfirstKeyType={})>": "<%!p(bool=true)>" }}. Err: connection error: desc = "transport: Error while dialing: dial tcp 10.77.77.77:9492: connect: connection refused"\n
boulder-1    | 2025-06-12T18:34:42.420187+00:00Z boulder-va[339]: 6 boulder-va hvP-2wU Debug server listening on :8104
boulder-1    | 2025-06-12T18:34:42.421605+00:00Z boulder-va[339]: 6 boulder-va 7ZnYqw4 Versions: boulder-va=(release-2025-05-27 +8a7c3193 Sat May 31 10:33:38 UTC 2025) Golang=(go1.24.1) BuildHost=(labca-v25.05)

This got better after doing export BOULDER_TOOLS_TAG=go1.24.1_2025-03-10 as mentnioned in #173 as the error didn't seem to appear on startup, but after starting to create the second certificate. And what I find additionaly before the gui-1-Container error commes is:

boulder-1    | 2025-06-12T18:35:48.827443+00:00Z boulder-ca[402]: 3 boulder-ca 3-qFnAc [AUDIT] Preparing precert failed: serial=[6e5630fa1b879a1bd1e55abffa253b9f2183] err=[tbsCertificate linting failed: failed lint(s): e_pkimetal_lint_cabf_serverauth_cert (making POST request to pkimetal API: Post "http://10.77.77.9:8080/lintcert": context deadline exceeded (timeout 10s))]
boulder-1    | 2025-06-12T18:35:48.846382+00:00Z boulder-ra[450]: 6 boulder-ra rYf-owE [AUDIT] Certificate request - error JSON={"ID":"AA7wJQqJB_uOl6S68g9t8eMuQWfVoupCU4KecaGje7g","Requester":1,"OrderID":1,"VerifiedFields":["subject.commonName","subjectAltName"],"NotBefore":"0001-01-01T00:00:00Z","NotAfter":"0001-01-01T00:00:00Z","RequestTime":"2025-06-12T18:35:38.606115626Z","ResponseTime":"2025-06-12T18:35:48.845614065Z","Error":"failed to prepare precertificate signing: tbsCertificate linting failed: failed lint(s): e_pkimetal_lint_cabf_serverauth_cert (making POST request to pkimetal API: Post \"http://10.77.77.9:8080/lintcert\": context deadline exceeded (timeout 10s))","Authorizations":{"ca.lan":{"ID":"1","ChallengeType":"http-01"}},"PreviousCertificateIssued":"0001-01-01T00:00:00Z","UserAgent":"CertbotACMEClient/4.0.0 (certbot; Ubuntu 24.04.2 LTS) Authenticator/webroot Installer/None (certonly; flags: n) Py/3.10.17"}
boulder-1    | 2025-06-12T18:35:48.848579+00:00Z boulder-wfe2[475]: 6 boulder-wfe2 1JWFkAo POST /acme/finalize/ 1 500 10256 0.0.0.0 JSON={"Slug":"1/1","InternalErrors":["failed to prepare precertificate signing: tbsCertificate linting failed: failed lint(s): e_pkimetal_lint_cabf_serverauth_cert (making POST request to pkimetal API: Post \"http://10.77.77.9:8080/lintcert\": context deadline exceeded (timeout 10s))"],"Error":"500 :: serverInternal :: Error finalizing order","ua":"CertbotACMEClient/4.0.0 (certbot; Ubuntu 24.04.2 LTS) Authenticator/webroot Installer/None (certonly; flags: n) Py/3.10.17","Extra":{"KeyType":"RSA 2048"},"Identifiers":[{"type":"dns","value":"ca.lan"}]}

Maybe this helps to drill down the issue. If not, please let me know what is needed and where to look/test something.

plani-de avatar Jun 12 '25 18:06 plani-de

Still trying to get LabCA to run...without success but trying to avoid a switch to another selfhosted ACME-CA. Partially it looks good for the creation of the second /server certificate if I look at this:

boulder-1 | 2025-07-07T18:56:31.438352+00:00Z remoteva[332]: 6 remoteva 29fY8AM [AUDIT] Validation result JSON={"AuthzID":"1","Requester":1,"Identifier":{"type":"dns","value":"ca.lan"},"Challenge":{"type":"http-01","status":"valid","token":"Y6x7P-pN_qO5xH6dd9M4382Gs76mXMripeeApLNxSE8","validationRecord":[{"url":"http://ca.lan/.well-known/acme-challenge/Y6x7P-pN_qO5xH6dd9M4382Gs76mXMripeeApLNxSE8","hostname":"ca.lan","port":"80","addressesResolved":["172.28.56.19"],"addressUsed":"172.28.56.19","resolverAddrs":["A:172.28.190.220:53","AAAA:172.28.190.220:53"]}]},"Latency":0.023} boulder-1 | 2025-07-07T18:56:31.438497+00:00Z remoteva[251]: 6 remoteva 29fY8AM [AUDIT] Validation result JSON={"AuthzID":"1","Requester":1,"Identifier":{"type":"dns","value":"ca.lan"},"Challenge":{"type":"http-01","status":"valid","token":"Y6x7P-pN_qO5xH6dd9M4382Gs76mXMripeeApLNxSE8","validationRecord":[{"url":"http://ca.lan/.well-known/acme-challenge/Y6x7P-pN_qO5xH6dd9M4382Gs76mXMripeeApLNxSE8","hostname":"ca.lan","port":"80","addressesResolved":["172.28.56.19"],"addressUsed":"172.28.56.19","resolverAddrs":["A:172.28.190.220:53","AAAA:172.28.190.220:53"]}]},"Latency":0.023} boulder-1 | 2025-07-07T18:56:31.438573+00:00Z remoteva[143]: 6 remoteva nPreigc [AUDIT] Validation result JSON={"AuthzID":"1","Requester":1,"Identifier":{"type":"dns","value":"ca.lan"},"Challenge":{"type":"http-01","status":"valid","token":"Y6x7P-pN_qO5xH6dd9M4382Gs76mXMripeeApLNxSE8","validationRecord":[{"url":"http://ca.lan/.well-known/acme-challenge/Y6x7P-pN_qO5xH6dd9M4382Gs76mXMripeeApLNxSE8","hostname":"ca.lan","port":"80","addressesResolved":["172.28.56.19"],"addressUsed":"172.28.56.19","resolverAddrs":["A:172.28.190.220:53","AAAA:172.28.190.220:53"]}]},"Latency":0.024} boulder-1 | 2025-07-07T18:56:31.442376+00:00Z boulder-va[364]: 6 boulder-va 0pm44QI [AUDIT] Validation result JSON={"AuthzID":"1","Requester":1,"Identifier":{"type":"dns","value":"ca.lan"},"Challenge":{"type":"http-01","status":"valid","token":"Y6x7P-pN_qO5xH6dd9M4382Gs76mXMripeeApLNxSE8","validationRecord":[{"url":"http://ca.lan/.well-known/acme-challenge/Y6x7P-pN_qO5xH6dd9M4382Gs76mXMripeeApLNxSE8","hostname":"ca.lan","port":"80","addressesResolved":["172.28.56.19"],"addressUsed":"172.28.56.19","resolverAddrs":["A:172.28.190.220:53","AAAA:172.28.190.220:53"]}]},"Latency":0.143,"Summary":{"passedPerspectives":["cubist","dadaist","surrealist"],"failedPerspectives":[],"passedRIRs":["ARIN","RIPE"],"quorumResult":"3/3"}} boulder-1 | 2025-07-07T18:56:31.451380+00:00Z boulder-va[401]: 6 boulder-va mOzr9Qk [AUDIT] Checked CAA records for ca.lan, [Present: false, Account ID: 1, Challenge: http-01, Valid for issuance: true, Found at: ""] Response="" boulder-1 | 2025-07-07T18:56:31.459755+00:00Z remoteva[251]: 6 remoteva mOzr9Qk [AUDIT] Checked CAA records for ca.lan, [Present: false, Account ID: 1, Challenge: http-01, Valid for issuance: true, Found at: ""] Response="" boulder-1 | 2025-07-07T18:56:31.459868+00:00Z remoteva[251]: 6 remoteva jMnYSAA [AUDIT] CAA check result JSON={"AuthzID":"1","Requester":1,"Identifier":{"type":"dns","value":"ca.lan"},"Challenge":{"type":""},"Latency":0.006} boulder-1 | 2025-07-07T18:56:31.461011+00:00Z remoteva[332]: 6 remoteva mOzr9Qk [AUDIT] Checked CAA records for ca.lan, [Present: false, Account ID: 1, Challenge: http-01, Valid for issuance: true, Found at: ""] Response="" boulder-1 | 2025-07-07T18:56:31.461938+00:00Z remoteva[332]: 6 remoteva gpLUvAk [AUDIT] CAA check result JSON={"AuthzID":"1","Requester":1,"Identifier":{"type":"dns","value":"ca.lan"},"Challenge":{"type":""},"Latency":0.008} boulder-1 | 2025-07-07T18:56:31.462788+00:00Z remoteva[143]: 6 remoteva mOzr9Qk [AUDIT] Checked CAA records for ca.lan, [Present: false, Account ID: 1, Challenge: http-01, Valid for issuance: true, Found at: ""] Response="" boulder-1 | 2025-07-07T18:56:31.463190+00:00Z remoteva[143]: 6 remoteva w_C49Ag [AUDIT] CAA check result JSON={"AuthzID":"1","Requester":1,"Identifier":{"type":"dns","value":"ca.lan"},"Challenge":{"type":""},"Latency":0.009} boulder-1 | 2025-07-07T18:56:31.465533+00:00Z boulder-va[401]: 6 boulder-va 1Nuk1A4 [AUDIT] CAA check result JSON={"AuthzID":"1","Requester":1,"Identifier":{"type":"dns","value":"ca.lan"},"Challenge":{"type":""},"Latency":0.019,"Summary":{"passedPerspectives":["cubist","dadaist","surrealist"],"failedPerspectives":[],"passedRIRs":["ARIN","RIPE"],"quorumResult":"3/3"}} boulder-1 | 2025-07-07T18:56:32.336756+00:00Z boulder-wfe2[470]: 6 boulder-wfe2 3KzjIgA POST /acme/authz/ 1 200 17 0.0.0.0 JSON={"Slug":"1/1","ua":"CertbotACMEClient/4.0.0 (certbot; Ubuntu 24.04.2 LTS) Authenticator/webroot Installer/None (certonly; flags: n) Py/3.10.17","Status":"valid","Identifiers":[{"type":"dns","value":"ca.lan"}]} boulder-1 | 2025-07-07T18:56:32.457144+00:00Z boulder-ra[417]: 6 boulder-ra 9cigmgc FinalizationCaaCheck JSON={"Requester":1,"Reused":1} gui-1 | 2025/07/07 18:56:36 GET /final nginx-1 | ::ffff:172.28.56.200 - - [07/Jul/2025:18:56:36 +0000] "GET /admin/final HTTP/1.1" 200 33 "https://ca.lan/admin/setup" "Mozilla/5.0 (X11; Linux x86_64; rv:140.0) Gecko/20100101 Firefox/140.0" "-"

But it always seems to boil down to these two errors: 1.) Connection error between containers

boulder-1 | 2025-07-07T18:55:50.788551+00:00Z boulder-ra[291]: 4 boulder-ra y6ffqw8 [core] [Channel #3 SubChannel #12]grpc: addrConn.createTransport failed to connect to {Addr: "10.77.77.77:9493", ServerName: "0a4d4d4d.addr.dc1.consul.", BalancerAttributes: {"<%!p(pickfirstleaf.managedByPickfirstKeyType={})>": "<%!p(bool=true)>" }}. Err: connection error: desc = "transport: Error while dialing: dial tcp 10.77.77.77:9493: connect: connection refused"\n boulder-1 | 2025-07-07T18:55:50.817536+00:00Z boulder-ra[291]: 4 boulder-ra 0ZPk2A4 [core] [Channel #1 SubChannel #8]grpc: addrConn.createTransport failed to connect to {Addr: "10.77.77.77:9492", ServerName: "0a4d4d4d.addr.dc1.consul.", BalancerAttributes: {"<%!p(pickfirstleaf.managedByPickfirstKeyType={})>": "<%!p(bool=true)>" }}. Err: connection error: desc = "transport: Error while dialing: dial tcp 10.77.77.77:9492: connect: connection refused"\n boulder-1 | 2025-07-07T18:55:50.845873+00:00Z boulder-ra[291]: 4 boulder-ra mP6Mggo [core] [Channel #1 SubChannel #9]grpc: addrConn.createTransport failed to connect to {Addr: "10.77.77.77:9392", ServerName: "0a4d4d4d.addr.dc1.consul.", BalancerAttributes: {"<%!p(pickfirstleaf.managedByPickfirstKeyType={})>": "<%!p(bool=true)>" }}. Err: connection error: desc = "transport: Error while dialing: dial tcp 10.77.77.77:9392: connect: connection refused"\n boulder-1 | 2025-07-07T18:55:51.117957+00:00Z boulder-ra[291]: 4 boulder-ra 6Mi4_Ak [core] [Channel #6 SubChannel #7]grpc: addrConn.createTransport failed to connect to {Addr: "10.77.77.77:9399", ServerName: "0a4d4d4d.addr.dc1.consul.", BalancerAttributes: {"<%!p(pickfirstleaf.managedByPickfirstKeyType={})>": "<%!p(bool=true)>" }}. Err: connection error: desc = "transport: Error while dialing: dial tcp 10.77.77.77:9399: connect: connection refused"\n

2.) Error in the commander script

gui-1 | 2025/07/07 20:28:34 GET / gui-1 | 2025/07/07 20:28:34 GET /setup gui-1 | 2025/07/07 20:29:09 GET /final gui-1 | 2025/07/07 20:29:14 GET /final gui-1 | 2025/07/07 20:29:19 GET /final gui-1 | 2025/07/07 20:29:24 GET /final gui-1 | 2025/07/07 20:29:29 GET /final gui-1 | 2025/07/07 20:29:34 GET /final gui-1 | 2025/07/07 20:29:37 ERROR: Message from server: 'ERROR! On line 62 in commander script gui-1 | ' gui-1 | 2025/07/07 20:29:37 errorHandler: err=ERROR! On line 62 in commander script gui-1 | gui-1 | main._hostCommand({0x160d918, 0xc000178000}, 0xc0003368c0, {0x108e5e7, 0xc}, {0x0, 0x0, 0xc000c7b980?}) gui-1 | /go/src/labca/main.go:2322 +0x812 gui-1 | main.finalHandler({0x160d918, 0xc000178000}, 0xc0003368c0) gui-1 | /go/src/labca/main.go:2870 +0x4bd gui-1 | net/http.HandlerFunc.ServeHTTP(0xf418c0?, {0x160d918?, 0xc000178000?}, 0xc000178000?) gui-1 | /usr/local/go/src/net/http/server.go:2294 +0x29 gui-1 | main.authorized.func1({0x160d918, 0xc000178000}, 0xc0003368c0) gui-1 | /go/src/labca/main.go:3342 +0x32e gui-1 | net/http.HandlerFunc.ServeHTTP(0xc000336780?, {0x160d918?, 0xc000178000?}, 0x1e23a80?) gui-1 | /usr/local/go/src/net/http/server.go:2294 +0x29 gui-1 | github.com/gorilla/mux.(*Router).ServeHTTP(0xc000220000, {0x160d918, 0xc000178000}, 0xc000336500) gui-1 | /root/go/pkg/mod/github.com/gorilla/[email protected]/mux.go:212 +0x1e2 gui-1 | net/http.serverHandler.ServeHTTP({0xc0000b7860?}, {0x160d918?, 0xc000178000?}, 0x6?) gui-1 | /usr/local/go/src/net/http/server.go:3301 +0x8e gui-1 | net/http.(*conn).serve(0xc000163050, {0x160fb20, 0xc000d5c330}) gui-1 | /usr/local/go/src/net/http/server.go:2102 +0x625 gui-1 | created by net/http.(*Server).Serve in goroutine 1 gui-1 | /usr/local/go/src/net/http/server.go:3454 +0x485 gui-1 | 2025/07/07 20:29:39 http: superfluous response.WriteHeader call from main.finalHandler (main.go:2873) gui-1 | 2025/07/07 20:29:39 GET /final gui-1 | 2025/07/07 20:29:39 GET /error gui-1 | 2025/07/07 20:29:39 errorHandler: err= gui-1 | main.showErrorHandler({0x160d918?, 0xc000bb4000?}, 0x5?) gui-1 | /go/src/labca/main.go:2899 +0x27 gui-1 | net/http.HandlerFunc.ServeHTTP(0xf418c0?, {0x160d918?, 0xc000bb4000?}, 0xc000bb4000?) gui-1 | /usr/local/go/src/net/http/server.go:2294 +0x29 gui-1 | main.authorized.func1({0x160d918, 0xc000bb4000}, 0xc0001f6500) gui-1 | /go/src/labca/main.go:3342 +0x32e gui-1 | net/http.HandlerFunc.ServeHTTP(0xc0001f63c0?, {0x160d918?, 0xc000bb4000?}, 0x1e23a80?) gui-1 | /usr/local/go/src/net/http/server.go:2294 +0x29 gui-1 | github.com/gorilla/mux.(*Router).ServeHTTP(0xc000220000, {0x160d918, 0xc000bb4000}, 0xc0001f6280) gui-1 | /root/go/pkg/mod/github.com/gorilla/[email protected]/mux.go:212 +0x1e2 gui-1 | net/http.serverHandler.ServeHTTP({0xc000c42e40?}, {0x160d918?, 0xc000bb4000?}, 0x6?) gui-1 | /usr/local/go/src/net/http/server.go:3301 +0x8e gui-1 | net/http.(*conn).serve(0xc0006f6120, {0x160fb20, 0xc000d5c330}) gui-1 | /usr/local/go/src/net/http/server.go:2102 +0x625 gui-1 | created by net/http.(*Server).Serve in goroutine 1 gui-1 | /usr/local/go/src/net/http/server.go:3454 +0x485 ok

Any chance to seek help on this? Am I the only one?

plani-de avatar Jul 07 '25 20:07 plani-de

This was not ment to be closed, thus reopened

plani-de avatar Jul 07 '25 20:07 plani-de

Is there anything useful in the certbot log on why the certificate for nginx could not be created?

docker compose exec nginx cat /etc/nginx/ssl/certbot.log

I have seen those "connection refused" errors in the past when the boulder container is starting, but they usually stop after a short while. The reason is that some boulder components have circular dependencies on each other so it is impossible to prevent that error and they disappear once all components are up. If you keep getting those messages then for some reason the boulder container is probably constantly restarting

hakwerk avatar Jul 16 '25 19:07 hakwerk

First of, thanks for taking your time to respond. Regarding your suggestion: When I try docker compose exec nginx cat /etc/nginx/ssl/certbot.log I initially only get: cat: /etc/nginx/ssl/certbot.log: No such file or directory After a while, wenn the final errors occurs I find:

Wed Jul 16 21:40:12 UTC 2025
Saving debug log to /var/log/letsencrypt/letsencrypt.log
Account registered.
Requesting a certificate for ca.lan
An unexpected error occurred:
Error finalizing order
Ask for help or search for solutions at https://community.letsencrypt.org. See the logfile /var/log/letsencrypt/letsencrypt.log or re-run Certbot with -v for more details.

But no Idea where to find /var/log/letsencrypt/letsencrypt.log Regarding the "connection refused" topic: I usually wait until all containers are running an the logfile start to stall because everything is running. But after/while processing the certificate, the errors comes again. Plus, I don't understand the error in the go-file, line 62....

plani-de avatar Jul 16 '25 21:07 plani-de

Well, it is line 62 in the commander script, which calls the renew script, but that is just calling certbot to generate the certificate so that isn't very helpful either :(

I also saw that message about /var/log/letsencrypt/letsencrypt.log in a working instance, and couldn't find that file either :(

What you can try is run certbot manually (or edit the renew script) and then add --debug according to the user guide, but I suspect it will not help much either.

For some reason the server side is not happy but I can't see in the boulder logs why that is. What you could try is to start filtering out the noise, the log messages that do not seem relevant, and then hopefully end up with something that gives us some information. Something like

docker compose logs boulder | grep -v "Error while dialing: dial tcp 10.77.77.77:"

and then keep added | grep -v "....." bits for the stuff that doesn't seem relevant....

But looking again at the logs that you included, the last boulder log message is this:

boulder-1 | 2025-06-06T06:19:12.725735+00:00Z boulder-wfe2[472]: 6 boulder-wfe2 iKPpxgo POST /acme/finalize/ 1 500 2005 0.0.0.0 JSON={"Slug":"1/3","InternalErrors":["failed to prepare precertificate signing: tbsCertificate linting failed: failed lint(s): e_pkimetal_lint_cabf_serverauth_cert (got 1 lint findings from pkimetal API: error from certlint:unknown_tld_in_san: Unknown TLD in SAN)"],"Error":"500 :: serverInternal :: Error finalizing order","ua":"CertbotACMEClient/4.0.0 (certbot; Ubuntu 24.04.2 LTS) Authenticator/webroot Installer/None (certonly; flags: n) Py/3.10.17","Extra":{"KeyType":"RSA 2048"},"Identifiers":[{"type":"dns","value":"ca.lan"}]}

Are you sure that the workaround for putting "certlint:unknown_tld_in_san" in the config/zlint.toml file is still present in your current setup? I'll make a new release now so that that fix will actually be present in the released version, hopefully I or Let's Encrypt haven't introduced too many new issues in that version...

hakwerk avatar Jul 18 '25 07:07 hakwerk