From e7c71bb7ac92e5cf874fc7ff015faf3d55026d8d Mon Sep 17 00:00:00 2001 From: Roland Shoemaker Date: Fri, 16 Oct 2015 11:59:04 -0700 Subject: [PATCH 1/5] Log OCSP responder SQL errors --- cmd/ocsp-responder/main.go | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/cmd/ocsp-responder/main.go b/cmd/ocsp-responder/main.go index 67478d10d..ed160f5e4 100644 --- a/cmd/ocsp-responder/main.go +++ b/cmd/ocsp-responder/main.go @@ -8,6 +8,7 @@ package main import ( "bytes" "crypto/x509" + "database/sql" "encoding/hex" "errors" "fmt" @@ -94,6 +95,9 @@ func (src *DBSource) Response(req *ocsp.Request) ([]byte, bool) { "SELECT ocspResponse FROM certificateStatus WHERE serial = :serial", map[string]interface{}{"serial": serialString}, ) + if err != nil && err != sql.ErrNoRows { + log.Err(fmt.Sprintf("Failed to retrieve response from certificateStatus table: %s", err)) + } // TODO(#970): Delete this ocspResponses check once the table has been removed if len(response) == 0 { // Ignoring possible error, if response hasn't been filled, attempt to find @@ -103,6 +107,9 @@ func (src *DBSource) Response(req *ocsp.Request) ([]byte, bool) { "SELECT response from ocspResponses WHERE serial = :serial ORDER BY id DESC LIMIT 1;", map[string]interface{}{"serial": serialString}, ) + if err != nil && err != sql.ErrNoRows { + log.Err(fmt.Sprintf("Failed to retrieve response from ocspResponses table: %s", err)) + } } if err != nil { return nil, false From 980d87aa14a267b3a2e189cf30e194208161e96d Mon Sep 17 00:00:00 2001 From: Roland Shoemaker Date: Fri, 16 Oct 2015 13:58:16 -0700 Subject: [PATCH 2/5] Add test to catch logging of failed SQL calls --- cmd/ocsp-responder/main.go | 47 ++++++++++++++++++--------------- cmd/ocsp-responder/main_test.go | 37 ++++++++++++++++++++++++-- 2 files changed, 61 insertions(+), 23 deletions(-) diff --git a/cmd/ocsp-responder/main.go b/cmd/ocsp-responder/main.go index ed160f5e4..124f8b4cf 100644 --- a/cmd/ocsp-responder/main.go +++ b/cmd/ocsp-responder/main.go @@ -21,7 +21,6 @@ import ( "github.com/letsencrypt/boulder/Godeps/_workspace/src/github.com/facebookgo/httpdown" "github.com/letsencrypt/boulder/Godeps/_workspace/src/github.com/jmhodges/clock" "github.com/letsencrypt/boulder/Godeps/_workspace/src/golang.org/x/crypto/ocsp" - gorp "github.com/letsencrypt/boulder/Godeps/_workspace/src/gopkg.in/gorp.v1" "github.com/letsencrypt/boulder/metrics" "github.com/letsencrypt/boulder/cmd" @@ -56,34 +55,38 @@ serialNumber field, since we will always query on it. */ type DBSource struct { - dbMap *gorp.DbMap + dbMap dbMapInterface caKeyHash []byte + log *blog.AuditLogger +} + +type dbMapInterface interface { + SelectOne(holder interface{}, query string, args ...interface{}) error + Insert(list ...interface{}) error } // NewSourceFromDatabase produces a DBSource representing the binding of a // given DB schema to a CA key. -func NewSourceFromDatabase(dbMap *gorp.DbMap, caKeyHash []byte) (src *DBSource, err error) { - src = &DBSource{dbMap: dbMap, caKeyHash: caKeyHash} +func NewSourceFromDatabase(dbMap dbMapInterface, caKeyHash []byte, log *blog.AuditLogger) (src *DBSource, err error) { + src = &DBSource{dbMap: dbMap, caKeyHash: caKeyHash, log: log} return } // Response is called by the HTTP server to handle a new OCSP request. func (src *DBSource) Response(req *ocsp.Request) ([]byte, bool) { - log := blog.GetAuditLogger() - // Check that this request is for the proper CA if bytes.Compare(req.IssuerKeyHash, src.caKeyHash) != 0 { - log.Debug(fmt.Sprintf("Request intended for CA Cert ID: %s", hex.EncodeToString(req.IssuerKeyHash))) + src.log.Debug(fmt.Sprintf("Request intended for CA Cert ID: %s", hex.EncodeToString(req.IssuerKeyHash))) return nil, false } serialString := core.SerialToString(req.SerialNumber) - log.Debug(fmt.Sprintf("Searching for OCSP issued by us for serial %s", serialString)) + src.log.Debug(fmt.Sprintf("Searching for OCSP issued by us for serial %s", serialString)) var response []byte defer func() { if len(response) != 0 { - log.Info(fmt.Sprintf("OCSP Response sent for CA=%s, Serial=%s", hex.EncodeToString(src.caKeyHash), serialString)) + src.log.Info(fmt.Sprintf("OCSP Response sent for CA=%s, Serial=%s", hex.EncodeToString(src.caKeyHash), serialString)) } }() // Note: we first check for an OCSP response in the certificateStatus table ( @@ -96,7 +99,7 @@ func (src *DBSource) Response(req *ocsp.Request) ([]byte, bool) { map[string]interface{}{"serial": serialString}, ) if err != nil && err != sql.ErrNoRows { - log.Err(fmt.Sprintf("Failed to retrieve response from certificateStatus table: %s", err)) + src.log.Err(fmt.Sprintf("Failed to retrieve response from certificateStatus table: %s", err)) } // TODO(#970): Delete this ocspResponses check once the table has been removed if len(response) == 0 { @@ -108,7 +111,7 @@ func (src *DBSource) Response(req *ocsp.Request) ([]byte, bool) { map[string]interface{}{"serial": serialString}, ) if err != nil && err != sql.ErrNoRows { - log.Err(fmt.Sprintf("Failed to retrieve response from ocspResponses table: %s", err)) + src.log.Err(fmt.Sprintf("Failed to retrieve response from ocspResponses table: %s", err)) } } if err != nil { @@ -118,14 +121,7 @@ func (src *DBSource) Response(req *ocsp.Request) ([]byte, bool) { return response, true } -func makeDBSource(dbConnect, issuerCert string, sqlDebug bool) (*DBSource, error) { - // Configure DB - dbMap, err := sa.NewDbMap(dbConnect) - if err != nil { - return nil, fmt.Errorf("Could not connect to database: %s", err) - } - sa.SetSQLDebug(dbMap, sqlDebug) - +func makeDBSource(dbMap dbMapInterface, issuerCert string, log *blog.AuditLogger) (*DBSource, error) { // Load the CA's key so we can store its SubjectKey in the DB caCertDER, err := cmd.LoadCert(issuerCert) if err != nil { @@ -140,7 +136,7 @@ func makeDBSource(dbConnect, issuerCert string, sqlDebug bool) (*DBSource, error } // Construct source from DB - return NewSourceFromDatabase(dbMap, caCert.SubjectKeyId) + return NewSourceFromDatabase(dbMap, caCert.SubjectKeyId, log) } func main() { @@ -170,7 +166,16 @@ func main() { if url.Scheme == "mysql+tcp" { auditlogger.Info(fmt.Sprintf("Loading OCSP Database for CA Cert: %s", c.Common.IssuerCert)) - source, err = makeDBSource(config.Source, c.Common.IssuerCert, c.SQL.SQLDebug) + dbMap, err := sa.NewDbMap(config.Source) + cmd.FailOnError(err, "Could not connect to database") + if c.SQL.SQLDebug { + sa.SetSQLDebug(dbMap, true) + } + source, err = makeDBSource( + dbMap, + c.Common.IssuerCert, + auditlogger, + ) cmd.FailOnError(err, "Couldn't load OCSP DB") } else if url.Scheme == "file" { filename := url.Path diff --git a/cmd/ocsp-responder/main_test.go b/cmd/ocsp-responder/main_test.go index 8d9bafdf7..cb86a6d51 100644 --- a/cmd/ocsp-responder/main_test.go +++ b/cmd/ocsp-responder/main_test.go @@ -12,7 +12,12 @@ import ( cfocsp "github.com/letsencrypt/boulder/Godeps/_workspace/src/github.com/cloudflare/cfssl/ocsp" "github.com/letsencrypt/boulder/Godeps/_workspace/src/golang.org/x/crypto/ocsp" + "github.com/letsencrypt/boulder/cmd" + "github.com/letsencrypt/boulder/mocks" + "github.com/letsencrypt/boulder/sa" + "github.com/letsencrypt/boulder/core" + blog "github.com/letsencrypt/boulder/log" "github.com/letsencrypt/boulder/test" ) @@ -61,11 +66,13 @@ func TestHandler(t *testing.T) { } func TestDBHandler(t *testing.T) { - src, err := makeDBSource("mysql+tcp://boulder@localhost:3306/boulder_sa_test", "./testdata/test-ca.der.pem", false) + dbMap, err := sa.NewDbMap("mysql+tcp://boulder@localhost:3306/boulder_sa_test") + cmd.FailOnError(err, "Could not connect to database") + src, err := makeDBSource(dbMap, "./testdata/test-ca.der.pem", blog.GetAuditLogger()) if err != nil { t.Fatalf("makeDBSource: %s", err) } - defer test.ResetTestDatabase(t, src.dbMap.Db) + defer test.ResetTestDatabase(t, dbMap.Db) ocspResp, err := ocsp.ParseResponse(resp, nil) if err != nil { t.Fatalf("ocsp.ParseResponse: %s", err) @@ -94,7 +101,33 @@ func TestDBHandler(t *testing.T) { if !bytes.Equal(w.Body.Bytes(), resp) { t.Errorf("Mismatched body: want %#v, got %#v", resp, w.Body.Bytes()) } +} +type brokenMap struct{} + +func (bm brokenMap) SelectOne(_ interface{}, _ string, _ ...interface{}) error { + return fmt.Errorf("Failure!") +} + +func (bm brokenMap) Insert(_ ...interface{}) error { + return nil +} + +func TestErrorLog(t *testing.T) { + src, err := makeDBSource(brokenMap{}, "./testdata/test-ca.der.pem", blog.GetAuditLogger()) + test.AssertNotError(t, err, "Failed to create broken dbMap") + + src.log.SyslogWriter = mocks.NewSyslogWriter() + mockLog := src.log.SyslogWriter.(*mocks.SyslogWriter) + + ocspReq, err := ocsp.ParseRequest(req) + test.AssertNotError(t, err, "Failed to parse OCSP request") + + _, found := src.Response(ocspReq) + test.Assert(t, !found, "Somehow found OCSP response") + + test.AssertEquals(t, len(mockLog.GetAllMatching("Failed to retrieve response from certificateStatus table")), 1) + test.AssertEquals(t, len(mockLog.GetAllMatching("Failed to retrieve response from ocspResponses table")), 1) } func mustRead(path string) []byte { From 02cd06ad0b94aa85d39d49982f6ecfb5dbcceedc Mon Sep 17 00:00:00 2001 From: Roland Shoemaker Date: Fri, 16 Oct 2015 15:17:51 -0700 Subject: [PATCH 3/5] Rename and cleanup the dbMap wraper interface --- cmd/ocsp-responder/main.go | 9 ++++----- cmd/ocsp-responder/main_test.go | 5 ++--- 2 files changed, 6 insertions(+), 8 deletions(-) diff --git a/cmd/ocsp-responder/main.go b/cmd/ocsp-responder/main.go index 124f8b4cf..1dd2d2085 100644 --- a/cmd/ocsp-responder/main.go +++ b/cmd/ocsp-responder/main.go @@ -55,19 +55,18 @@ serialNumber field, since we will always query on it. */ type DBSource struct { - dbMap dbMapInterface + dbMap dbSelector caKeyHash []byte log *blog.AuditLogger } -type dbMapInterface interface { +type dbSelector interface { SelectOne(holder interface{}, query string, args ...interface{}) error - Insert(list ...interface{}) error } // NewSourceFromDatabase produces a DBSource representing the binding of a // given DB schema to a CA key. -func NewSourceFromDatabase(dbMap dbMapInterface, caKeyHash []byte, log *blog.AuditLogger) (src *DBSource, err error) { +func NewSourceFromDatabase(dbMap dbSelector, caKeyHash []byte, log *blog.AuditLogger) (src *DBSource, err error) { src = &DBSource{dbMap: dbMap, caKeyHash: caKeyHash, log: log} return } @@ -121,7 +120,7 @@ func (src *DBSource) Response(req *ocsp.Request) ([]byte, bool) { return response, true } -func makeDBSource(dbMap dbMapInterface, issuerCert string, log *blog.AuditLogger) (*DBSource, error) { +func makeDBSource(dbMap dbSelector, issuerCert string, log *blog.AuditLogger) (*DBSource, error) { // Load the CA's key so we can store its SubjectKey in the DB caCertDER, err := cmd.LoadCert(issuerCert) if err != nil { diff --git a/cmd/ocsp-responder/main_test.go b/cmd/ocsp-responder/main_test.go index cb86a6d51..6c35d7019 100644 --- a/cmd/ocsp-responder/main_test.go +++ b/cmd/ocsp-responder/main_test.go @@ -12,7 +12,6 @@ import ( cfocsp "github.com/letsencrypt/boulder/Godeps/_workspace/src/github.com/cloudflare/cfssl/ocsp" "github.com/letsencrypt/boulder/Godeps/_workspace/src/golang.org/x/crypto/ocsp" - "github.com/letsencrypt/boulder/cmd" "github.com/letsencrypt/boulder/mocks" "github.com/letsencrypt/boulder/sa" @@ -67,7 +66,7 @@ func TestHandler(t *testing.T) { func TestDBHandler(t *testing.T) { dbMap, err := sa.NewDbMap("mysql+tcp://boulder@localhost:3306/boulder_sa_test") - cmd.FailOnError(err, "Could not connect to database") + test.AssertNotError(t, err, "Could not connect to database") src, err := makeDBSource(dbMap, "./testdata/test-ca.der.pem", blog.GetAuditLogger()) if err != nil { t.Fatalf("makeDBSource: %s", err) @@ -83,7 +82,7 @@ func TestDBHandler(t *testing.T) { OCSPLastUpdated: time.Now(), OCSPResponse: resp, } - err = src.dbMap.Insert(status) + err = dbMap.Insert(status) if err != nil { t.Fatalf("unable to insert response: %s", err) } From ea73b4afeed4a00796ea17c203ae5c1dc6266011 Mon Sep 17 00:00:00 2001 From: Roland Shoemaker Date: Mon, 19 Oct 2015 15:24:44 -0700 Subject: [PATCH 4/5] Fix status guard to just use status.Status, i.e. the status that was set when it was pulled from the DB --- cmd/ocsp-updater/main.go | 8 ++++---- cmd/ocsp-updater/main_test.go | 23 ++++++++++++++++------- 2 files changed, 20 insertions(+), 11 deletions(-) diff --git a/cmd/ocsp-updater/main.go b/cmd/ocsp-updater/main.go index 772d01cd4..209997813 100644 --- a/cmd/ocsp-updater/main.go +++ b/cmd/ocsp-updater/main.go @@ -227,7 +227,7 @@ func (updater *OCSPUpdater) generateRevokedResponse(status core.CertificateStatu return &status, nil } -func (updater *OCSPUpdater) storeResponse(status *core.CertificateStatus, statusGuard core.OCSPStatus) error { +func (updater *OCSPUpdater) storeResponse(status *core.CertificateStatus) error { // Update the certificateStatus table with the new OCSP response, the status // WHERE is used make sure we don't overwrite a revoked response with a one // containing a 'good' status and that we don't do the inverse when the OCSP @@ -240,7 +240,7 @@ func (updater *OCSPUpdater) storeResponse(status *core.CertificateStatus, status status.OCSPResponse, status.OCSPLastUpdated, status.Serial, - string(statusGuard), + string(status.Status), ) return err } @@ -291,7 +291,7 @@ func (updater *OCSPUpdater) revokedCertificatesTick(batchSize int) { updater.stats.Inc("OCSP.Errors.RevokedResponseGeneration", 1, 1.0) continue } - err = updater.storeResponse(meta, core.OCSPStatusRevoked) + err = updater.storeResponse(meta) if err != nil { updater.stats.Inc("OCSP.Errors.StoreRevokedResponse", 1, 1.0) updater.log.AuditErr(fmt.Errorf("Failed to store OCSP response: %s", err)) @@ -309,7 +309,7 @@ func (updater *OCSPUpdater) generateOCSPResponses(statuses []core.CertificateSta continue } updater.stats.Inc("OCSP.GeneratedResponses", 1, 1.0) - err = updater.storeResponse(meta, core.OCSPStatusGood) + err = updater.storeResponse(meta) if err != nil { updater.log.AuditErr(fmt.Errorf("Failed to store OCSP response: %s", err)) updater.stats.Inc("OCSP.Errors.StoreResponse", 1, 1.0) diff --git a/cmd/ocsp-updater/main_test.go b/cmd/ocsp-updater/main_test.go index f4c2a2807..201efdc6e 100644 --- a/cmd/ocsp-updater/main_test.go +++ b/cmd/ocsp-updater/main_test.go @@ -93,12 +93,12 @@ func TestGenerateAndStoreOCSPResponse(t *testing.T) { meta, err := updater.generateResponse(status) test.AssertNotError(t, err, "Couldn't generate OCSP response") - err = updater.storeResponse(meta, core.OCSPStatusGood) + err = updater.storeResponse(meta) test.AssertNotError(t, err, "Couldn't store certificate status") secondMeta, err := updater.generateRevokedResponse(status) test.AssertNotError(t, err, "Couldn't generate revoked OCSP response") - err = updater.storeResponse(secondMeta, core.OCSPStatusGood) + err = updater.storeResponse(secondMeta) test.AssertNotError(t, err, "Couldn't store certificate status") newStatus, err := sa.GetCertificateStatus(status.Serial) @@ -152,7 +152,7 @@ func TestFindStaleOCSPResponses(t *testing.T) { meta, err := updater.generateResponse(status) test.AssertNotError(t, err, "Couldn't generate OCSP response") - err = updater.storeResponse(meta, core.OCSPStatusGood) + err = updater.storeResponse(meta) test.AssertNotError(t, err, "Couldn't store OCSP response") certs, err = updater.findStaleOCSPResponses(earliest, 10) @@ -290,18 +290,27 @@ func TestStoreResponseGuard(t *testing.T) { status, err := sa.GetCertificateStatus(core.SerialToString(parsedCert.SerialNumber)) test.AssertNotError(t, err, "Failed to get certificate status") - status.OCSPResponse = []byte{0} - err = updater.storeResponse(&status, core.OCSPStatusRevoked) + err = sa.MarkCertificateRevoked(core.SerialToString(parsedCert.SerialNumber), 0) + test.AssertNotError(t, err, "Failed to revoked certificate") + + // Attempt to update OCSP response where status.Status is good but stored status + // is revoked, this should fail silently + status.OCSPResponse = []byte{0, 1, 1} + err = updater.storeResponse(&status) test.AssertNotError(t, err, "Failed to update certificate status") + // Make sure the OCSP response hasn't actually changed unchangedStatus, err := sa.GetCertificateStatus(core.SerialToString(parsedCert.SerialNumber)) test.AssertNotError(t, err, "Failed to get certificate status") test.AssertEquals(t, len(unchangedStatus.OCSPResponse), 0) - err = updater.storeResponse(&status, core.OCSPStatusGood) + // Changing the status to the stored status should allow the update to occur + status.Status = core.OCSPStatusRevoked + err = updater.storeResponse(&status) test.AssertNotError(t, err, "Failed to updated certificate status") + // Make sure the OCSP response has been updated changedStatus, err := sa.GetCertificateStatus(core.SerialToString(parsedCert.SerialNumber)) test.AssertNotError(t, err, "Failed to get certificate status") - test.AssertEquals(t, len(changedStatus.OCSPResponse), 1) + test.AssertEquals(t, len(changedStatus.OCSPResponse), 3) } From d24c73bb1bd50b932426fa40ef248725297dc3fa Mon Sep 17 00:00:00 2001 From: Roland Shoemaker Date: Tue, 20 Oct 2015 19:15:39 -0700 Subject: [PATCH 5/5] Review fixes --- cmd/ocsp-responder/main.go | 10 +++++----- cmd/ocsp-responder/main_test.go | 12 +++++------- 2 files changed, 10 insertions(+), 12 deletions(-) diff --git a/cmd/ocsp-responder/main.go b/cmd/ocsp-responder/main.go index 1dd2d2085..28af94b8b 100644 --- a/cmd/ocsp-responder/main.go +++ b/cmd/ocsp-responder/main.go @@ -60,6 +60,10 @@ type DBSource struct { log *blog.AuditLogger } +// Since the only thing we use from gorp is the SelectOne method on the +// gorp.DbMap object, we just define the interface an interface with that method +// instead of importing all of gorp. This also allows us to simulate MySQL failures +// by mocking the interface. type dbSelector interface { SelectOne(holder interface{}, query string, args ...interface{}) error } @@ -170,11 +174,7 @@ func main() { if c.SQL.SQLDebug { sa.SetSQLDebug(dbMap, true) } - source, err = makeDBSource( - dbMap, - c.Common.IssuerCert, - auditlogger, - ) + source, err = makeDBSource(dbMap, c.Common.IssuerCert, auditlogger) cmd.FailOnError(err, "Couldn't load OCSP DB") } else if url.Scheme == "file" { filename := url.Path diff --git a/cmd/ocsp-responder/main_test.go b/cmd/ocsp-responder/main_test.go index 2246b8743..9825f3c1f 100644 --- a/cmd/ocsp-responder/main_test.go +++ b/cmd/ocsp-responder/main_test.go @@ -107,18 +107,16 @@ func TestDBHandler(t *testing.T) { } } -type brokenMap struct{} +// brokenSelector allows us to test what happens when gorp SelectOne statements +// throw errors and satisfies the dbSelector interface +type brokenSelector struct{} -func (bm brokenMap) SelectOne(_ interface{}, _ string, _ ...interface{}) error { +func (bs brokenSelector) SelectOne(_ interface{}, _ string, _ ...interface{}) error { return fmt.Errorf("Failure!") } -func (bm brokenMap) Insert(_ ...interface{}) error { - return nil -} - func TestErrorLog(t *testing.T) { - src, err := makeDBSource(brokenMap{}, "./testdata/test-ca.der.pem", blog.GetAuditLogger()) + src, err := makeDBSource(brokenSelector{}, "./testdata/test-ca.der.pem", blog.GetAuditLogger()) test.AssertNotError(t, err, "Failed to create broken dbMap") src.log.SyslogWriter = mocks.NewSyslogWriter()