From e7c71bb7ac92e5cf874fc7ff015faf3d55026d8d Mon Sep 17 00:00:00 2001 From: Roland Shoemaker Date: Fri, 16 Oct 2015 11:59:04 -0700 Subject: [PATCH 1/4] 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/4] 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/4] 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 d24c73bb1bd50b932426fa40ef248725297dc3fa Mon Sep 17 00:00:00 2001 From: Roland Shoemaker Date: Tue, 20 Oct 2015 19:15:39 -0700 Subject: [PATCH 4/4] 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()