letsencrypt
/
boulder
mirror of https://github.com/letsencrypt/boulder.git
1
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

Refactor log package (#1717) 

- Remove error signatures from log methods. This means fewer places where errcheck will show ignored errors.
- Pull in latest cfssl to be compatible with errorless log messages.
- Reduce the number of message priorities we support to just those we actually use.
- AuditNotice -> AuditInfo
- Remove InfoObject (only one use, switched to Info)
- Remove EmergencyExit and related functions in favor of panic
- Remove SyslogWriter / AuditLogger separate types in favor of a single interface, Logger, that has all the logging methods on it.
- Merge mock log into logger. This allows us to unexport the internals but still override them in the mock.
- Shorten names to be compatible with Go style: New, Set, Get, Logger, NewMock, etc.
- Use a shorter log format for stdout logs.
- Remove "... Starting" log messages. We have better information in the "Versions" message logged at startup.

Motivation: The AuditLogger / SyslogWriter distinction was confusing and exposed internals only necessary for tests. Some components accepted one type and some accepted the other. This made it hard to consistently use mock loggers in tests. Also, the unnecessarily fat interface for AuditLogger made it hard to meaningfully mock out.
This commit is contained in:
Jacob Hoffman-Andrews 2016-04-08 16:12:20 -07:00
parent 9ae81ab073
commit ecc04e8e61
59 changed files with 636 additions and 952 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

28
Godeps/Godeps.json generated
View File

@ -13,59 +13,59 @@
},
{
"ImportPath": "github.com/cloudflare/cfssl/auth",
"Rev": "4a19f107ed1c1d503180100d354598895252580e"
"Rev": "31c7d21b04cb891fbe30e001a093addbb37c8192"
},
{
"ImportPath": "github.com/cloudflare/cfssl/certdb",
"Rev": "4a19f107ed1c1d503180100d354598895252580e"
"Rev": "31c7d21b04cb891fbe30e001a093addbb37c8192"
},
{
"ImportPath": "github.com/cloudflare/cfssl/config",
"Rev": "4a19f107ed1c1d503180100d354598895252580e"
"Rev": "31c7d21b04cb891fbe30e001a093addbb37c8192"
},
{
"ImportPath": "github.com/cloudflare/cfssl/crypto/pkcs7",
"Rev": "4a19f107ed1c1d503180100d354598895252580e"
"Rev": "31c7d21b04cb891fbe30e001a093addbb37c8192"
},
{
"ImportPath": "github.com/cloudflare/cfssl/csr",
"Rev": "4a19f107ed1c1d503180100d354598895252580e"
"Rev": "31c7d21b04cb891fbe30e001a093addbb37c8192"
},
{
"ImportPath": "github.com/cloudflare/cfssl/errors",
"Rev": "4a19f107ed1c1d503180100d354598895252580e"
"Rev": "31c7d21b04cb891fbe30e001a093addbb37c8192"
},
{
"ImportPath": "github.com/cloudflare/cfssl/helpers",
"Rev": "4a19f107ed1c1d503180100d354598895252580e"
"Rev": "31c7d21b04cb891fbe30e001a093addbb37c8192"
},
{
"ImportPath": "github.com/cloudflare/cfssl/helpers/derhelpers",
"Rev": "4a19f107ed1c1d503180100d354598895252580e"
"Rev": "31c7d21b04cb891fbe30e001a093addbb37c8192"
},
{
"ImportPath": "github.com/cloudflare/cfssl/info",
"Rev": "4a19f107ed1c1d503180100d354598895252580e"
"Rev": "31c7d21b04cb891fbe30e001a093addbb37c8192"
},
{
"ImportPath": "github.com/cloudflare/cfssl/log",
"Rev": "4a19f107ed1c1d503180100d354598895252580e"
"Rev": "31c7d21b04cb891fbe30e001a093addbb37c8192"
},
{
"ImportPath": "github.com/cloudflare/cfssl/ocsp",
"Rev": "4a19f107ed1c1d503180100d354598895252580e"
"Rev": "31c7d21b04cb891fbe30e001a093addbb37c8192"
},
{
"ImportPath": "github.com/cloudflare/cfssl/ocsp/config",
"Rev": "4a19f107ed1c1d503180100d354598895252580e"
"Rev": "31c7d21b04cb891fbe30e001a093addbb37c8192"
},
{
"ImportPath": "github.com/cloudflare/cfssl/signer",
"Rev": "4a19f107ed1c1d503180100d354598895252580e"
"Rev": "31c7d21b04cb891fbe30e001a093addbb37c8192"
},
{
"ImportPath": "github.com/cloudflare/cfssl/signer/local",
"Rev": "4a19f107ed1c1d503180100d354598895252580e"
"Rev": "31c7d21b04cb891fbe30e001a093addbb37c8192"
},
{
"ImportPath": "github.com/codegangsta/cli",

6
Godeps/_workspace/src/github.com/cloudflare/cfssl/csr/csr.go generated vendored
View File

@ -129,8 +129,9 @@ func (kr *BasicKeyRequest) SigAlgo() x509.SignatureAlgorithm {
// CAConfig is a section used in the requests initialising a new CA.
type CAConfig struct {
PathLength int `json:"pathlen"`
Expiry string `json:"expiry"`
PathLength int `json:"pathlen"`
PathLenZero bool `json:"pathlenzero"`
Expiry string `json:"expiry"`
}
// A CertificateRequest encapsulates the API interface to the
@ -265,6 +266,7 @@ func ExtractCertificateRequest(cert *x509.Certificate) *CertificateRequest {
// issue date and expiry date.
req.CA.Expiry = cert.NotAfter.Sub(cert.NotBefore).String()
req.CA.PathLength = cert.MaxPathLen
req.CA.PathLenZero = cert.MaxPathLenZero
}
return req

28
Godeps/_workspace/src/github.com/cloudflare/cfssl/log/log.go generated vendored
View File

@ -45,12 +45,12 @@ var Level = LevelInfo
//
// SyslogWriter is satisfied by *syslog.Writer.
type SyslogWriter interface {
Debug(string) error
Info(string) error
Warning(string) error
Err(string) error
Crit(string) error
Emerg(string) error
Debug(string)
Info(string)
Warning(string)
Err(string)
Crit(string)
Emerg(string)
}
// syslogWriter stores the SetLogger() parameter.
@ -73,23 +73,19 @@ func init() {
func print(l int, msg string) {
if l >= Level {
if syslogWriter != nil {
var err error
switch l {
case LevelDebug:
err = syslogWriter.Debug(msg)
syslogWriter.Debug(msg)
case LevelInfo:
err = syslogWriter.Info(msg)
syslogWriter.Info(msg)
case LevelWarning:
err = syslogWriter.Warning(msg)
syslogWriter.Warning(msg)
case LevelError:
err = syslogWriter.Err(msg)
syslogWriter.Err(msg)
case LevelCritical:
err = syslogWriter.Crit(msg)
syslogWriter.Crit(msg)
case LevelFatal:
err = syslogWriter.Emerg(msg)
}
if err != nil {
log.Printf("Unable to write syslog: %v for msg: %s\n", err, msg)
syslogWriter.Emerg(msg)
}
} else {
log.Printf("[%s] %s", levelPrefix[l], msg)

1
Godeps/_workspace/src/github.com/cloudflare/cfssl/signer/local/local.go generated vendored
View File

@ -112,6 +112,7 @@ func (s *Signer) sign(template *x509.Certificate, profile *config.SigningProfile
s.ca = template
initRoot = true
template.MaxPathLen = signer.MaxPathLen
template.MaxPathLenZero = signer.MaxPathLenZero
} else if template.IsCA {
template.MaxPathLen = 1
template.DNSNames = nil

3
Godeps/_workspace/src/github.com/cloudflare/cfssl/signer/signer.go generated vendored
View File

@ -26,6 +26,9 @@ import (
// MaxPathLen is the default path length for a new CA certificate.
var MaxPathLen = 2
// MaxPathLenZero indicates whether a new CA certificate has pathlen=0
var MaxPathLenZero = false
// Subject contains the information that should be used to override the
// subject information when signing a certificate.
type Subject struct {

4
akamai/cache-client.go
View File

@ -51,7 +51,7 @@ type CachePurgeClient struct {
accessToken string
retries int
retryBackoff time.Duration
log *blog.AuditLogger
log blog.Logger
stats statsd.Statter
clk clock.Clock
}
@ -76,7 +76,7 @@ func NewCachePurgeClient(
accessToken string,
retries int,
retryBackoff time.Duration,
log *blog.AuditLogger,
log blog.Logger,
stats statsd.Statter,
) (*CachePurgeClient, error) {
if strings.HasSuffix(endpoint, "/") {

15
ca/certificate-authority.go
View File

@ -135,7 +135,7 @@ type CertificateAuthorityImpl struct {
Publisher core.Publisher
keyPolicy core.KeyPolicy
clk clock.Clock
log *blog.AuditLogger
log blog.Logger
stats statsd.Statter
prefix int // Prepended to the serial number
validityPeriod time.Duration
@ -207,8 +207,7 @@ func NewCertificateAuthorityImpl(
) (*CertificateAuthorityImpl, error) {
var ca *CertificateAuthorityImpl
var err error
logger := blog.GetAuditLogger()
logger.Notice("Certificate Authority Starting")
logger := blog.Get()
if config.SerialPrefix <= 0 || config.SerialPrefix >= 256 {
err = errors.New("Must have a positive non-zero serial prefix less than 256 for CA.")
@ -453,9 +452,9 @@ func (ca *CertificateAuthorityImpl) IssueCertificate(csr x509.CertificateRequest
}
if ca.maxNames > 0 && len(hostNames) > ca.maxNames {
err := core.MalformedRequestError(fmt.Sprintf("Certificate request has %d names, maximum is %d.", len(hostNames), ca.maxNames))
ca.log.WarningErr(err)
return emptyCert, err
msg := fmt.Sprintf("Certificate request has %d names, maximum is %d.", len(hostNames), ca.maxNames)
ca.log.Info(msg)
return emptyCert, core.MalformedRequestError(msg)
}
// Verify that names are allowed by policy
@ -538,7 +537,7 @@ func (ca *CertificateAuthorityImpl) IssueCertificate(csr x509.CertificateRequest
req.Subject.SerialNumber = serialHex
}
ca.log.AuditNotice(fmt.Sprintf("Signing: serial=[%s] names=[%s] csr=[%s]",
ca.log.AuditInfo(fmt.Sprintf("Signing: serial=[%s] names=[%s] csr=[%s]",
serialHex, strings.Join(hostNames, ", "), csrPEM))
certPEM, err := issuer.eeSigner.Sign(req)
@ -550,7 +549,7 @@ func (ca *CertificateAuthorityImpl) IssueCertificate(csr x509.CertificateRequest
return emptyCert, err
}
ca.log.AuditNotice(fmt.Sprintf("Signing success: serial=[%s] names=[%s] csr=[%s] pem=[%s]",
ca.log.AuditInfo(fmt.Sprintf("Signing success: serial=[%s] names=[%s] csr=[%s] pem=[%s]",
serialHex, strings.Join(hostNames, ", "), csrPEM,
certPEM))

3
ca/certificate-authority_test.go
View File

@ -23,6 +23,7 @@ import (
"github.com/letsencrypt/boulder/cmd"
"github.com/letsencrypt/boulder/core"
blog "github.com/letsencrypt/boulder/log"
"github.com/letsencrypt/boulder/mocks"
"github.com/letsencrypt/boulder/policy"
"github.com/letsencrypt/boulder/sa"
@ -133,7 +134,7 @@ var (
// * DNSNames = [none]
LongCNCSR = mustRead("./testdata/long_cn.der.csr")
log = mocks.UseMockLog()
log = blog.UseMock()
)
// CFSSL config

24
cmd/admin-revoker/main.go
View File

@ -40,11 +40,11 @@ func loadConfig(c *cli.Context) (config cmd.Config, err error) {
const clientName = "AdminRevoker"
func setupContext(context *cli.Context) (rpc.RegistrationAuthorityClient, *blog.AuditLogger, *gorp.DbMap, rpc.StorageAuthorityClient, statsd.Statter) {
func setupContext(context *cli.Context) (rpc.RegistrationAuthorityClient, blog.Logger, *gorp.DbMap, rpc.StorageAuthorityClient, statsd.Statter) {
c, err := loadConfig(context)
cmd.FailOnError(err, "Failed to load Boulder configuration")
stats, auditlogger := cmd.StatsAndLogging(c.Statsd, c.Syslog)
stats, logger := cmd.StatsAndLogging(c.Statsd, c.Syslog)
amqpConf := c.Revoker.AMQP
rac, err := rpc.NewRegistrationAuthorityClient(clientName, amqpConf, stats)
@ -58,7 +58,7 @@ func setupContext(context *cli.Context) (rpc.RegistrationAuthorityClient, *blog.
sac, err := rpc.NewStorageAuthorityClient(clientName, amqpConf, stats)
cmd.FailOnError(err, "Failed to create SA client")
return *rac, auditlogger, dbMap, *sac, stats
return *rac, logger, dbMap, *sac, stats
}
func addDeniedNames(tx *gorp.Transaction, names []string) (err error) {
@ -69,7 +69,7 @@ func addDeniedNames(tx *gorp.Transaction, names []string) (err error) {
return
}
func revokeBySerial(serial string, reasonCode core.RevocationCode, deny bool, rac rpc.RegistrationAuthorityClient, auditlogger *blog.AuditLogger, tx *gorp.Transaction) (err error) {
func revokeBySerial(serial string, reasonCode core.RevocationCode, deny bool, rac rpc.RegistrationAuthorityClient, logger blog.Logger, tx *gorp.Transaction) (err error) {
if reasonCode < 0 || reasonCode == 7 || reasonCode > 10 {
panic(fmt.Sprintf("Invalid reason code: %d", reasonCode))
}
@ -101,11 +101,11 @@ func revokeBySerial(serial string, reasonCode core.RevocationCode, deny bool, ra
return
}
auditlogger.Info(fmt.Sprintf("Revoked certificate %s with reason '%s'", serial, core.RevocationReasons[reasonCode]))
logger.Info(fmt.Sprintf("Revoked certificate %s with reason '%s'", serial, core.RevocationReasons[reasonCode]))
return
}
func revokeByReg(regID int64, reasonCode core.RevocationCode, deny bool, rac rpc.RegistrationAuthorityClient, auditlogger *blog.AuditLogger, tx *gorp.Transaction) (err error) {
func revokeByReg(regID int64, reasonCode core.RevocationCode, deny bool, rac rpc.RegistrationAuthorityClient, logger blog.Logger, tx *gorp.Transaction) (err error) {
var certs []core.Certificate
_, err = tx.Select(&certs, "SELECT serial FROM certificates WHERE registrationID = :regID", map[string]interface{}{"regID": regID})
if err != nil {
@ -113,7 +113,7 @@ func revokeByReg(regID int64, reasonCode core.RevocationCode, deny bool, rac rpc
}
for _, cert := range certs {
err = revokeBySerial(cert.Serial, reasonCode, deny, rac, auditlogger, tx)
err = revokeBySerial(cert.Serial, reasonCode, deny, rac, logger, tx)
if err != nil {
return
}
@ -160,7 +160,7 @@ func main() {
cmd.FailOnError(err, "Reason code argument must be an integer")
deny := c.GlobalBool("deny")
cac, auditlogger, dbMap, _, _ := setupContext(c)
cac, logger, dbMap, _, _ := setupContext(c)
tx, err := dbMap.Begin()
if err != nil {
@ -168,7 +168,7 @@ func main() {
}
cmd.FailOnError(err, "Couldn't begin transaction")
err = revokeBySerial(serial, core.RevocationCode(reasonCode), deny, cac, auditlogger, tx)
err = revokeBySerial(serial, core.RevocationCode(reasonCode), deny, cac, logger, tx)
if err != nil {
tx.Rollback()
}
@ -189,9 +189,9 @@ func main() {
cmd.FailOnError(err, "Reason code argument must be an integer")
deny := c.GlobalBool("deny")
cac, auditlogger, dbMap, sac, _ := setupContext(c)
cac, logger, dbMap, sac, _ := setupContext(c)
// AUDIT[ Error Conditions ] 9cc4d537-8534-4970-8665-4b382abe82f3
defer auditlogger.AuditPanic()
defer logger.AuditPanic()
tx, err := dbMap.Begin()
if err != nil {
@ -204,7 +204,7 @@ func main() {
cmd.FailOnError(err, "Couldn't fetch registration")
}
err = revokeByReg(regID, core.RevocationCode(reasonCode), deny, cac, auditlogger, tx)
err = revokeByReg(regID, core.RevocationCode(reasonCode), deny, cac, logger, tx)
if err != nil {
tx.Rollback()
}

2
cmd/boulder-ca/main.go
View File

@ -108,7 +108,7 @@ func loadSigner(issuerConfig cmd.IssuerConfig) (crypto.Signer, error) {
func main() {
app := cmd.NewAppShell("boulder-ca", "Handles issuance operations")
app.Action = func(c cmd.Config, stats metrics.Statter, auditlogger *blog.AuditLogger) {
app.Action = func(c cmd.Config, stats metrics.Statter, logger blog.Logger) {
// Validate PA config and set defaults if needed
cmd.FailOnError(c.PA.CheckChallenges(), "Invalid PA configuration")

6
cmd/boulder-publisher/main.go
View File

@ -22,7 +22,7 @@ const clientName = "Publisher"
func main() {
app := cmd.NewAppShell("boulder-publisher", "Submits issued certificates to CT logs")
app.Action = func(c cmd.Config, stats metrics.Statter, auditlogger *blog.AuditLogger) {
app.Action = func(c cmd.Config, stats metrics.Statter, logger blog.Logger) {
logs := make([]*publisher.Log, len(c.Common.CT.Logs))
var err error
for i, ld := range c.Common.CT.Logs {
@ -31,7 +31,7 @@ func main() {
}
if c.Common.CT.IntermediateBundleFilename == "" {
auditlogger.Err("No CT submission bundle provided")
logger.Err("No CT submission bundle provided")
os.Exit(1)
}
pemBundle, err := core.LoadCertBundle(c.Common.CT.IntermediateBundleFilename)
@ -41,7 +41,7 @@ func main() {
bundle = append(bundle, ct.ASN1Cert(cert.Raw))
}
pubi := publisher.New(bundle, logs, c.Publisher.SubmissionTimeout.Duration)
pubi := publisher.New(bundle, logs, c.Publisher.SubmissionTimeout.Duration, logger)
go cmd.DebugServer(c.Publisher.DebugAddr)
go cmd.ProfileCmd("Publisher", stats)

4
cmd/boulder-ra/main.go
View File

@ -25,7 +25,7 @@ const clientName = "RA"
func main() {
app := cmd.NewAppShell("boulder-ra", "Handles service orchestration")
app.Action = func(c cmd.Config, stats metrics.Statter, auditlogger *blog.AuditLogger) {
app.Action = func(c cmd.Config, stats metrics.Statter, logger blog.Logger) {
// Validate PA config and set defaults if needed
cmd.FailOnError(c.PA.CheckChallenges(), "Invalid PA configuration")
@ -66,7 +66,7 @@ func main() {
dc = &ra.DomainCheck{VA: vac}
}
rai := ra.NewRegistrationAuthorityImpl(clock.Default(), auditlogger, stats,
rai := ra.NewRegistrationAuthorityImpl(clock.Default(), logger, stats,
dc, rateLimitPolicies, c.RA.MaxContactsPerRegistration, c.KeyPolicy(),
c.RA.UseNewVARPC)
rai.PA = pa

4
cmd/boulder-sa/main.go
View File

@ -17,7 +17,7 @@ import (
func main() {
app := cmd.NewAppShell("boulder-sa", "Handles SQL operations")
app.Action = func(c cmd.Config, stats metrics.Statter, auditlogger *blog.AuditLogger) {
app.Action = func(c cmd.Config, stats metrics.Statter, logger blog.Logger) {
saConf := c.SA
go cmd.DebugServer(saConf.DebugAddr)
@ -26,7 +26,7 @@ func main() {
dbMap, err := sa.NewDbMap(dbURL)
cmd.FailOnError(err, "Couldn't connect to SA database")
sai, err := sa.NewSQLStorageAuthority(dbMap, clock.Default(), auditlogger)
sai, err := sa.NewSQLStorageAuthority(dbMap, clock.Default(), logger)
cmd.FailOnError(err, "Failed to create SA impl")
go cmd.ProfileCmd("SA", stats)

2
cmd/boulder-va/main.go
View File

@ -22,7 +22,7 @@ const clientName = "VA"
func main() {
app := cmd.NewAppShell("boulder-va", "Handles challenge validation")
app.Action = func(c cmd.Config, stats metrics.Statter, auditlogger *blog.AuditLogger) {
app.Action = func(c cmd.Config, stats metrics.Statter, logger blog.Logger) {
go cmd.DebugServer(c.VA.DebugAddr)
go cmd.ProfileCmd("VA", stats)

10
cmd/boulder-wfe/main.go
View File

@ -23,7 +23,7 @@ import (
const clientName = "WFE"
func setupWFE(c cmd.Config, logger *blog.AuditLogger, stats metrics.Statter) (*rpc.RegistrationAuthorityClient, *rpc.StorageAuthorityClient) {
func setupWFE(c cmd.Config, logger blog.Logger, stats metrics.Statter) (*rpc.RegistrationAuthorityClient, *rpc.StorageAuthorityClient) {
amqpConf := c.WFE.AMQP
rac, err := rpc.NewRegistrationAuthorityClient(clientName, amqpConf, stats)
cmd.FailOnError(err, "Unable to create RA client")
@ -49,12 +49,12 @@ func main() {
}
return config
}
app.Action = func(c cmd.Config, stats metrics.Statter, auditlogger *blog.AuditLogger) {
app.Action = func(c cmd.Config, stats metrics.Statter, logger blog.Logger) {
go cmd.DebugServer(c.WFE.DebugAddr)
wfe, err := wfe.NewWebFrontEndImpl(stats, clock.Default(), c.KeyPolicy())
cmd.FailOnError(err, "Unable to create WFE")
rac, sac := setupWFE(c, auditlogger, stats)
rac, sac := setupWFE(c, logger, stats)
wfe.RA = rac
wfe.SA = sac
wfe.SubscriberAgreementURL = c.SubscriberAgreementURL
@ -78,7 +78,7 @@ func main() {
wfe.IssuerCert, err = cmd.LoadCert(c.Common.IssuerCert)
cmd.FailOnError(err, fmt.Sprintf("Couldn't read issuer cert [%s]", c.Common.IssuerCert))
auditlogger.Info(fmt.Sprintf("WFE using key policy: %#v", c.KeyPolicy()))
logger.Info(fmt.Sprintf("WFE using key policy: %#v", c.KeyPolicy()))
go cmd.ProfileCmd("WFE", stats)
@ -89,7 +89,7 @@ func main() {
httpMonitor := metrics.NewHTTPMonitor(stats, h, "WFE")
auditlogger.Info(fmt.Sprintf("Server running, listening on %s...\n", c.WFE.ListenAddress))
logger.Info(fmt.Sprintf("Server running, listening on %s...\n", c.WFE.ListenAddress))
srv := &http.Server{
Addr: c.WFE.ListenAddress,
Handler: httpMonitor,

4
cmd/cert-checker/main.go
View File

@ -279,9 +279,9 @@ func main() {
cmd.FailOnError(err, "Failed to create StatsD client")
syslogger, err := syslog.Dial("", "", syslog.LOG_INFO|syslog.LOG_LOCAL0, "")
cmd.FailOnError(err, "Failed to dial syslog")
logger, err := blog.NewAuditLogger(syslogger, stats, 0)
logger, err := blog.New(syslogger, 0)
cmd.FailOnError(err, "Failed to construct logger")
err = blog.SetAuditLogger(logger)
err = blog.Set(logger)
cmd.FailOnError(err, "Failed to set audit logger")
if connect := c.GlobalString("db-connect"); connect != "" {

4
cmd/cert-checker/main_test.go
View File

@ -20,7 +20,7 @@ import (
"github.com/letsencrypt/boulder/Godeps/_workspace/src/github.com/jmhodges/clock"
"github.com/letsencrypt/boulder/core"
"github.com/letsencrypt/boulder/mocks"
blog "github.com/letsencrypt/boulder/log"
"github.com/letsencrypt/boulder/sa"
"github.com/letsencrypt/boulder/sa/satest"
"github.com/letsencrypt/boulder/test"
@ -179,7 +179,7 @@ func TestGetAndProcessCerts(t *testing.T) {
fc := clock.NewFake()
checker := newChecker(saDbMap, paDbMap, fc, false, nil, expectedValidityPeriod)
sa, err := sa.NewSQLStorageAuthority(saDbMap, fc, mocks.UseMockLog())
sa, err := sa.NewSQLStorageAuthority(saDbMap, fc, blog.NewMock())
test.AssertNotError(t, err, "Couldn't create SA to insert certificates")
saCleanUp := test.ResetSATestDatabase(t)
paCleanUp := test.ResetPolicyTestDatabase(t)

2
cmd/clock_integration.go
View File

@ -23,7 +23,7 @@ func Clock() clock.Clock {
cl := clock.NewFake()
cl.Set(targetTime)
blog.GetAuditLogger().Notice(fmt.Sprintf("Time was set to %v via FAKECLOCK", targetTime))
blog.Get().Info(fmt.Sprintf("Time was set to %v via FAKECLOCK", targetTime))
return cl
}
return clock.Default()

12
cmd/expiration-mailer/main.go
View File

@ -46,7 +46,7 @@ type regStore interface {
type mailer struct {
stats statsd.Statter
log *blog.AuditLogger
log blog.Logger
dbMap *gorp.DbMap
rs regStore
mailer mail.Mailer
@ -300,7 +300,7 @@ func main() {
return config
}
app.Action = func(c cmd.Config, stats metrics.Statter, auditlogger *blog.AuditLogger) {
app.Action = func(c cmd.Config, stats metrics.Statter, logger blog.Logger) {
go cmd.DebugServer(c.Mailer.DebugAddr)
// Configure DB
@ -333,7 +333,7 @@ func main() {
if s := c.Mailer.NagCheckInterval; s != "" {
nagCheckInterval, err = time.ParseDuration(s)
if err != nil {
auditlogger.Err(fmt.Sprintf("Failed to parse NagCheckInterval string %q: %s", s, err))
logger.Err(fmt.Sprintf("Failed to parse NagCheckInterval string %q: %s", s, err))
return
}
}
@ -342,7 +342,7 @@ func main() {
for _, nagDuration := range c.Mailer.NagTimes {
dur, err := time.ParseDuration(nagDuration)
if err != nil {
auditlogger.Err(fmt.Sprintf("Failed to parse nag duration string [%s]: %s", nagDuration, err))
logger.Err(fmt.Sprintf("Failed to parse nag duration string [%s]: %s", nagDuration, err))
return
}
nags = append(nags, dur+nagCheckInterval)
@ -357,7 +357,7 @@ func main() {
m := mailer{
stats: stats,
subject: subject,
log: auditlogger,
log: logger,
dbMap: dbMap,
rs: sac,
mailer: &mailClient,
@ -367,7 +367,7 @@ func main() {
clk: cmd.Clock(),
}
auditlogger.Info("expiration-mailer: Starting")
logger.Info("expiration-mailer: Starting")
err = m.findExpiringCertificates()
cmd.FailOnError(err, "expiration-mailer has failed")
}

4
cmd/expiration-mailer/main_test.go
View File

@ -91,7 +91,7 @@ var (
"n":"z8bp-jPtHt4lKBqepeKF28g_QAEOuEsCIou6sZ9ndsQsEjxEOQxQ0xNOQezsKa63eogw8YS3vzjUcPP5BJuVzfPfGd5NVUdT-vSSwxk3wvk_jtNqhrpcoG0elRPQfMVsQWmxCAXCVRz3xbcFI8GTe-syynG3l-g1IzYIIZVNI6jdljCZML1HOMTTW4f7uJJ8mM-08oQCeHbr5ejK7O2yMSSYxW03zY-Tj1iVEebROeMv6IEEJNFSS4yM-hLpNAqVuQxFGetwtwjDMC1Drs1dTWrPuUAAjKGrP151z1_dE74M5evpAhZUmpKv1hY-x85DC6N0hFPgowsanmTNNiV75w",
"e":"AAEAAQ"
}`)
log = mocks.UseMockLog()
log = blog.UseMock()
tmpl = template.Must(template.New("expiry-email").Parse(testTmpl))
)
@ -723,7 +723,7 @@ func setup(t *testing.T, nagTimes []time.Duration) *testCtx {
}
m := &mailer{
log: blog.GetAuditLogger(),
log: log,
stats: stats,
mailer: mc,
emailTemplate: tmpl,

2
cmd/external-cert-importer/main.go
View File

@ -148,7 +148,7 @@ func main() {
return config
}
app.Action = func(c cmd.Config, stats metrics.Statter, auditlogger *blog.AuditLogger) {
app.Action = func(c cmd.Config, stats metrics.Statter, logger blog.Logger) {
// Configure DB
dbURL, err := c.PA.DBConfig.URL()
cmd.FailOnError(err, "Couldn't load DB URL")

2
cmd/nameset-backfill/main.go
View File

@ -30,7 +30,7 @@ type backfiller struct {
sa core.StorageAuthority
dbMap *gorp.DbMap
stats statsd.Statter
log *blog.AuditLogger
log blog.Logger
clk clock.Clock
}

7
cmd/nameset-backfill/main_test.go
View File

@ -10,14 +10,13 @@ import (
"github.com/letsencrypt/boulder/core"
blog "github.com/letsencrypt/boulder/log"
"github.com/letsencrypt/boulder/mocks"
"github.com/letsencrypt/boulder/sa"
"github.com/letsencrypt/boulder/sa/satest"
"github.com/letsencrypt/boulder/test"
"github.com/letsencrypt/boulder/test/vars"
)
var log = mocks.UseMockLog()
var log = blog.UseMock()
func TestBackfill(t *testing.T) {
stats, _ := statsd.NewNoopClient()
@ -29,12 +28,12 @@ func TestBackfill(t *testing.T) {
}
fc := clock.NewFake()
fc.Add(1 * time.Hour)
sa, err := sa.NewSQLStorageAuthority(dbMap, fc, blog.GetAuditLogger())
sa, err := sa.NewSQLStorageAuthority(dbMap, fc, log)
if err != nil {
t.Fatalf("Failed to create SA: %s", err)
}
defer test.ResetSATestDatabase(t)
b := backfiller{sa, dbMap, stats, blog.GetAuditLogger(), fc}
b := backfiller{sa, dbMap, stats, log, fc}
certDER, err := ioutil.ReadFile("test-cert.der")
test.AssertNotError(t, err, "Couldn't read example cert DER")

14
cmd/ocsp-responder/main.go
View File

@ -47,7 +47,7 @@ serialNumber field, since we will always query on it.
type DBSource struct {
dbMap dbSelector
caKeyHash []byte
log blog.SyslogWriter
log blog.Logger
}
// Since the only thing we use from gorp is the SelectOne method on the
@ -60,7 +60,7 @@ type dbSelector interface {
// NewSourceFromDatabase produces a DBSource representing the binding of a
// given DB schema to a CA key.
func NewSourceFromDatabase(dbMap dbSelector, caKeyHash []byte, log blog.SyslogWriter) (src *DBSource, err error) {
func NewSourceFromDatabase(dbMap dbSelector, caKeyHash []byte, log blog.Logger) (src *DBSource, err error) {
src = &DBSource{dbMap: dbMap, caKeyHash: caKeyHash, log: log}
return
}
@ -97,7 +97,7 @@ func (src *DBSource) Response(req *ocsp.Request) ([]byte, bool) {
return response, true
}
func makeDBSource(dbMap dbSelector, issuerCert string, log blog.SyslogWriter) (*DBSource, error) {
func makeDBSource(dbMap dbSelector, issuerCert string, log blog.Logger) (*DBSource, error) {
// Load the CA's key so we can store its SubjectKey in the DB
caCertDER, err := cmd.LoadCert(issuerCert)
if err != nil {
@ -117,7 +117,7 @@ func makeDBSource(dbMap dbSelector, issuerCert string, log blog.SyslogWriter) (*
func main() {
app := cmd.NewAppShell("boulder-ocsp-responder", "Handles OCSP requests")
app.Action = func(c cmd.Config, stats metrics.Statter, log *blog.AuditLogger) {
app.Action = func(c cmd.Config, stats metrics.Statter, logger blog.Logger) {
go cmd.DebugServer(c.OCSPResponder.DebugAddr)
go cmd.ProfileCmd("OCSP", stats)
@ -135,11 +135,11 @@ func main() {
cmd.FailOnError(err, fmt.Sprintf("Source was not a URL: %s", config.Source))
if url.Scheme == "mysql+tcp" {
log.Debug(fmt.Sprintf("Loading OCSP Database for CA Cert: %s", c.Common.IssuerCert))
logger.Info(fmt.Sprintf("Loading OCSP Database for CA Cert: %s", c.Common.IssuerCert))
dbMap, err := sa.NewDbMap(config.Source)
cmd.FailOnError(err, "Could not connect to database")
sa.SetSQLDebug(dbMap, log)
source, err = makeDBSource(dbMap, c.Common.IssuerCert, log)
sa.SetSQLDebug(dbMap, logger)
source, err = makeDBSource(dbMap, c.Common.IssuerCert, logger)
cmd.FailOnError(err, "Couldn't load OCSP DB")
} else if url.Scheme == "file" {
filename := url.Path

10
cmd/ocsp-responder/main_test.go
View File

@ -13,7 +13,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"
blog "github.com/letsencrypt/boulder/log"
"github.com/letsencrypt/boulder/mocks"
"github.com/letsencrypt/boulder/test"
)
@ -21,7 +20,6 @@ var (
req = mustRead("./testdata/ocsp.req")
resp = mustRead("./testdata/ocsp.resp")
stats, _ = statsd.NewNoopClient()
log = mocks.UseMockLog()
)
func TestMux(t *testing.T) {
@ -57,7 +55,7 @@ func TestMux(t *testing.T) {
}
func TestDBHandler(t *testing.T) {
src, err := makeDBSource(mockSelector{}, "./testdata/test-ca.der.pem", blog.GetAuditLogger())
src, err := makeDBSource(mockSelector{}, "./testdata/test-ca.der.pem", blog.NewMock())
if err != nil {
t.Fatalf("makeDBSource: %s", err)
}
@ -98,8 +96,8 @@ func (bs brokenSelector) SelectOne(_ interface{}, _ string, _ ...interface{}) er
}
func TestErrorLog(t *testing.T) {
log.Clear()
src, err := makeDBSource(brokenSelector{}, "./testdata/test-ca.der.pem", log)
mockLog := blog.NewMock()
src, err := makeDBSource(brokenSelector{}, "./testdata/test-ca.der.pem", mockLog)
test.AssertNotError(t, err, "Failed to create broken dbMap")
ocspReq, err := ocsp.ParseRequest(req)
@ -108,7 +106,7 @@ func TestErrorLog(t *testing.T) {
_, found := src.Response(ocspReq)
test.Assert(t, !found, "Somehow found OCSP response")
test.AssertEquals(t, len(log.GetAllMatching("Failed to retrieve response from certificateStatus table")), 1)
test.AssertEquals(t, len(mockLog.GetAllMatching("Failed to retrieve response from certificateStatus table")), 1)
}
func mustRead(path string) []byte {

6
cmd/ocsp-updater/main.go
View File

@ -31,7 +31,7 @@ import (
// OCSPUpdater contains the useful objects for the Updater
type OCSPUpdater struct {
stats statsd.Statter
log *blog.AuditLogger
log blog.Logger
clk clock.Clock
dbMap *gorp.DbMap
@ -77,7 +77,7 @@ func newUpdater(
return nil, fmt.Errorf("Loop window sizes must be non-zero")
}
log := blog.GetAuditLogger()
log := blog.Get()
updater := OCSPUpdater{
stats: stats,
@ -560,7 +560,7 @@ func setupClients(c cmd.OCSPUpdaterConfig, stats metrics.Statter) (
func main() {
app := cmd.NewAppShell("ocsp-updater", "Generates and updates OCSP responses")
app.Action = func(c cmd.Config, stats metrics.Statter, auditlogger *blog.AuditLogger) {
app.Action = func(c cmd.Config, stats metrics.Statter, auditlogger blog.Logger) {
conf := c.OCSPUpdater
go cmd.DebugServer(conf.DebugAddr)
go cmd.ProfileCmd("OCSP-Updater", stats)

4
cmd/ocsp-updater/main_test.go
View File

@ -12,7 +12,7 @@ import (
"github.com/letsencrypt/boulder/cmd"
"github.com/letsencrypt/boulder/core"
"github.com/letsencrypt/boulder/mocks"
blog "github.com/letsencrypt/boulder/log"
"github.com/letsencrypt/boulder/sa"
"github.com/letsencrypt/boulder/sa/satest"
"github.com/letsencrypt/boulder/test"
@ -51,7 +51,7 @@ func (p *mockPub) SubmitToCT(_ []byte) error {
return p.sa.AddSCTReceipt(sct)
}
var log = mocks.UseMockLog()
var log = blog.UseMock()
func setup(t *testing.T) (*OCSPUpdater, core.StorageAuthority, *gorp.DbMap, clock.FakeClock, func()) {
dbMap, err := sa.NewDbMap(vars.DBConnSA)

4
cmd/orphan-finder/main.go
View File

@ -52,7 +52,7 @@ func checkDER(sai certificateStorage, der []byte) error {
return fmt.Errorf("Existing certificate lookup failed: %s", err)
}
func parseLogLine(sa certificateStorage, logger blog.SyslogWriter, line string) (found bool, added bool) {
func parseLogLine(sa certificateStorage, logger blog.Logger, line string) (found bool, added bool) {
if !strings.Contains(line, "b64der=") || !strings.Contains(line, "orphaning certificate") {
return false, false
}
@ -94,7 +94,7 @@ func parseLogLine(sa certificateStorage, logger blog.SyslogWriter, line string)
return true, true
}
func setup(c *cli.Context) (statsd.Statter, blog.SyslogWriter, *rpc.StorageAuthorityClient) {
func setup(c *cli.Context) (statsd.Statter, blog.Logger, *rpc.StorageAuthorityClient) {
configJSON, err := ioutil.ReadFile(c.GlobalString("config"))
cmd.FailOnError(err, "Failed to read config file")
var conf config

4
cmd/orphan-finder/main_test.go
View File

@ -7,11 +7,11 @@ import (
"github.com/letsencrypt/boulder/Godeps/_workspace/src/github.com/jmhodges/clock"
"github.com/letsencrypt/boulder/core"
"github.com/letsencrypt/boulder/mocks"
blog "github.com/letsencrypt/boulder/log"
"github.com/letsencrypt/boulder/test"
)
var log = mocks.UseMockLog()
var log = blog.UseMock()
type mockSA struct {
certificate core.Certificate

43
cmd/shell.go
View File

@ -27,7 +27,6 @@ import (
"errors"
_ "expvar" // For DebugServer, below.
"fmt"
"github.com/letsencrypt/boulder/Godeps/_workspace/src/github.com/go-sql-driver/mysql"
"io/ioutil"
"log"
"log/syslog"
@ -39,6 +38,8 @@ import (
"runtime"
"time"
"github.com/letsencrypt/boulder/Godeps/_workspace/src/github.com/go-sql-driver/mysql"
cfsslLog "github.com/letsencrypt/boulder/Godeps/_workspace/src/github.com/cloudflare/cfssl/log"
"github.com/letsencrypt/boulder/Godeps/_workspace/src/github.com/codegangsta/cli"
@ -49,7 +50,7 @@ import (
// AppShell contains CLI Metadata
type AppShell struct {
Action func(Config, metrics.Statter, *blog.AuditLogger)
Action func(Config, metrics.Statter, blog.Logger)
Config func(*cli.Context, Config) Config
App *cli.App
}
@ -141,14 +142,14 @@ func (as *AppShell) Run() {
}
}
stats, auditlogger := StatsAndLogging(config.Statsd, config.Syslog)
auditlogger.Info(as.VersionString())
stats, logger := StatsAndLogging(config.Statsd, config.Syslog)
logger.Info(as.VersionString())
// If as.Action generates a panic, this will log it to syslog.
// AUDIT[ Error Conditions ] 9cc4d537-8534-4970-8665-4b382abe82f3
defer auditlogger.AuditPanic()
defer logger.AuditPanic()
as.Action(config, stats, auditlogger)
as.Action(config, stats, logger)
}
err := as.App.Run(os.Args)
@ -157,17 +158,31 @@ func (as *AppShell) Run() {
// mysqlLogger proxies blog.AuditLogger to provide a Print(...) method.
type mysqlLogger struct {
*blog.AuditLogger
blog.Logger
}
func (m mysqlLogger) Print(v ...interface{}) {
m.Err(fmt.Sprintf("[mysql] %s", fmt.Sprint(v...)))
}
// cfsslLogger provides two additional methods that are expected by CFSSL's
// logger but not supported by Boulder's Logger.
type cfsslLogger struct {
blog.Logger
}
func (cl cfsslLogger) Crit(msg string) {
cl.Err(msg)
}
func (cl cfsslLogger) Emerg(msg string) {
cl.Err(msg)
}
// StatsAndLogging constructs a Statter and an AuditLogger based on its config
// parameters, and return them both. Crashes if any setup fails.
// Also sets the constructed AuditLogger as the default logger.
func StatsAndLogging(statConf StatsdConfig, logConf SyslogConfig) (metrics.Statter, *blog.AuditLogger) {
func StatsAndLogging(statConf StatsdConfig, logConf SyslogConfig) (metrics.Statter, blog.Logger) {
stats, err := metrics.NewStatter(statConf.Server, statConf.Prefix)
FailOnError(err, "Couldn't connect to statsd")
@ -182,14 +197,14 @@ func StatsAndLogging(statConf StatsdConfig, logConf SyslogConfig) (metrics.Statt
if logConf.StdoutLevel != nil {
level = *logConf.StdoutLevel
}
auditLogger, err := blog.NewAuditLogger(syslogger, stats, level)
logger, err := blog.New(syslogger, level)
FailOnError(err, "Could not connect to Syslog")
blog.SetAuditLogger(auditLogger)
cfsslLog.SetLogger(auditLogger)
mysql.SetLogger(mysqlLogger{auditLogger})
blog.Set(logger)
cfsslLog.SetLogger(cfsslLogger{logger})
mysql.SetLogger(mysqlLogger{logger})
return stats, auditLogger
return stats, logger
}
// VersionString produces a friendly Application version string
@ -201,7 +216,7 @@ func (as *AppShell) VersionString() string {
func FailOnError(err error, msg string) {
if err != nil {
// AUDIT[ Error Conditions ] 9cc4d537-8534-4970-8665-4b382abe82f3
logger := blog.GetAuditLogger()
logger := blog.Get()
logger.Err(fmt.Sprintf("%s: %s", msg, err))
fmt.Fprintf(os.Stderr, "%s: %s\n", msg, err)
os.Exit(1)

6
core/util.go
View File

@ -157,9 +157,7 @@ func RandomString(byteLength int) string {
b := make([]byte, byteLength)
_, err := io.ReadFull(rand.Reader, b)
if err != nil {
ohdear := "RandomString entropy failure? " + err.Error()
logger := blog.GetAuditLogger()
logger.EmergencyExit(ohdear)
panic(fmt.Sprintf("Error reading random bytes: %s", err))
}
return base64.RawURLEncoding.EncodeToString(b)
}
@ -201,7 +199,7 @@ func KeyDigest(key crypto.PublicKey) (string, error) {
default:
keyDER, err := x509.MarshalPKIXPublicKey(key)
if err != nil {
logger := blog.GetAuditLogger()
logger := blog.Get()
logger.Debug(fmt.Sprintf("Problem marshaling public key: %s", err))
return "", err
}

151
docs/metrics/README.md
View File

@ -1,151 +0,0 @@
Boulder can provide various activity and performance metrics using StatsD if a server address is provided in the Boulder configuration file. This configuration object should look something like:
```
"statsd": {
"server": "localhost:8125",
"prefix": "Boulder"
}
```
The prefix will be prepended to all sent metrics to differentiate different sets of Boulder instances submitting metrics to the same StatsD server.
## List of collected metrics
This list is split up into metric topics with the names of the clients that submit these metrics.
* Logging (`cmd/boulder-*` + `cmd/ocsp-responder` + `cmd/ocsp-updater` + `cmd/admin-revoker`
+ `cmd/expiration-mailer` + `cmd/external-cert-importer`)
```
[counter] Boulder.Logging.Audit
[counter] Boulder.Logging.Alert
[counter] Boulder.Logging.Crit
[counter] Boulder.Logging.Debug
[counter] Boulder.Logging.Emerg
[counter] Boulder.Logging.Err
[counter] Boulder.Logging.Info
[counter] Boulder.Logging.Warning
```
* RPC activity (all RPC servers/clients)
```
[counter] Boulder.RPC.Rate.Success
[counter] Boulder.RPC.Rate.Error
[counter] Boulder.RPC.Traffic
[counter] Boulder.RPC.Timeouts
[gauge] Boulder.RPC.CallsWaiting
[timing] Boulder.RPC.Latency.{RPC method name}
```
* HTTP activity (`cmd/boulder-wfe` + `cmd/ocsp-responder`)
```
[counter] Boulder.{WFE/OCSP}.HTTP.Rate
[gauge] Boulder.{WFE/OCSP}.HTTP.ConnectionsInFlight
[gauge] Boulder.{WFE/OCSP}.HTTP.OpenConnections
[timing] Boulder.{WFE/OCSP}.HTTP.ResponseTime.{http endpoint}
[timing] Boulder.{WFE/OCSP}.HTTP.ResponseTime.Failed
```
* HTTP errors (`cmd/boulder-wfe`)
```
[counter] Boulder.WFE.HTTP.ErrorCodes.{3 digit code}
[counter] Boulder.WFE.HTTP.ProblemTypes.{problem type}
```
* DNS activity (`cmd/boulder-va` + `cmd/boulder-ra`)
```
(VA)
[counter] Boulder.VA.DNS.Rate
[timing] Boulder.VA.DNS.RTT.A
[timing] Boulder.VA.DNS.RTT.CAA
[timing] Boulder.VA.DNS.RTT.CNAME
[timing] Boulder.VA.DNS.RTT.TXT
(RA)
[counter] Boulder.RA.DNS.Rate
[timing] Boulder.RA.DNS.RTT.MX
```
* Validation attempts (`cmd/boulder-va`)
```
[timing] Boulder.VA.Validations.{challenge type}.{challenge status}
```
* Registration authority activity (`cmd/boulder-ra`)
```
[counter] Boulder.RA.NewRegistrations
[counter] Boulder.RA.NewPendingAuthorizations
[counter] Boulder.RA.NewCertificates
[counter] Boulder.RA.UpdatedRegistrations
[counter] Boulder.RA.UpdatedPendingAuthorizations
[counter] Boulder.RA.RevokedCertificates
[counter] Boulder.RA.FinalizedAuthorizations
```
* Client performance profiling (`cmd/boulder-*`)
```
[counter] Boulder.{cmd-name}.Gostats.Gc.Rate
[gauge] Boulder.{cmd-name}.Gostats.Goroutines
[gauge] Boulder.{cmd-name}.Gostats.Heap.Alloc
[gauge] Boulder.{cmd-name}.Gostats.Heap.Objects
[gauge] Boulder.{cmd-name}.Gostats.Heap.Idle
[gauge] Boulder.{cmd-name}.Gostats.Heap.InUse
[gauge] Boulder.{cmd-name}.Gostats.Heap.Released
[gauge] Boulder.{cmd-name}.Gostats.Gc.NextAt
[gauge] Boulder.{cmd-name}.Gostats.Gc.Count
[gauge] Boulder.{cmd-name}.Gostats.Gc.LastPause
[timing] Boulder.{cmd-name}.Gostats.Gc.PauseAvg
```
* External certificate store loading (`cmd/external-cert-importer`)
```
[counter] Boulder.ExistingCert.Certs.Imported
[counter] Boulder.ExistingCert.Domains.Imported
[counter] Boulder.ExistingCert.Removed
[timing] Boulder.ExistingCert.Certs.ImportLatency
[timing] Boulder.ExistingCert.Domains.ImportLatency
[timing] Boulder.ExistingCert.Certs.DeleteLatency
[timing] Boulder.ExistingCert.Domains.DeleteLatency
```
* OCSP response updating (`cmd/ocsp-updater`)
```
[counter] Boulder.OCSP.Updates.Processed
[counter] Boulder.OCSP.Updates.Failed
[counter] Boulder.OCSP.Updates.BatchesProcessed
[timing] Boulder.OCSP.Updates.UpdateLatency
[timing] Boulder.OCSP.Updates.BatchLatency
```
* Certificate expiration mailing (`cmd/expiration-mailer`)
```
[counter] Boulder.Mailer.Expiration.Sent
[counter] Boulder.Mailer.Expiration.Errors.SendingNag.TemplateFailure
[counter] Boulder.Mailer.Expiration.Errors.SendingNag.SendFailure
[counter] Boulder.Mailer.Expiration.Errors.GetRegistration
[counter] Boulder.Mailer.Expiration.Errors.ParseCertificate
[counter] Boulder.Mailer.Expiration.Errors.UpdateCertificateStatus
[timing] Boulder.Mailer.Expiration.SendLatency
[timing] Boulder.Mailer.Expiration.ProcessingCertificatesLatency
```

331
log/audit-logger.go
View File

@ -1,331 +0,0 @@
// Copyright 2015 ISRG. All rights reserved
// This Source Code Form is subject to the terms of the Mozilla Public
// License, v. 2.0. If a copy of the MPL was not distributed with this
// file, You can obtain one at http://mozilla.org/MPL/2.0/.
package log
import (
"encoding/json"
"errors"
"fmt"
"log"
"log/syslog"
"os"
"path"
"runtime"
"strings"
"sync"
"github.com/letsencrypt/boulder/Godeps/_workspace/src/github.com/cactus/go-statsd-client/statsd"
"github.com/letsencrypt/boulder/Godeps/_workspace/src/github.com/jmhodges/clock"
)
// A SyslogWriter logs messages with explicit priority levels. It is
// implemented by a logging back-end like syslog.Writer or
// mocks.SyslogWriter.
type SyslogWriter interface {
Close() error
Alert(m string) error
Crit(m string) error
Debug(m string) error
Emerg(m string) error
Err(m string) error
Info(m string) error
Notice(m string) error
Warning(m string) error
}
// singleton defines the object of a Singleton pattern
type singleton struct {
once sync.Once
log *AuditLogger
}
// _Singleton is the single AuditLogger entity in memory
var _Singleton singleton
// The constant used to identify audit-specific messages
const auditTag = "[AUDIT]"
// Constant used to indicate an emergency exit to the executor
const emergencyReturnValue = 13
// exitFunction closes the running system
type exitFunction func()
// Default to calling os.Exit()
func defaultEmergencyExit() {
os.Exit(emergencyReturnValue)
}
// AuditLogger implements SyslogWriter, and has additional
// audit-specific methods, like Audit(), for indicating which messages
// should be classified as audit events.
type AuditLogger struct {
SyslogWriter
Stats statsd.Statter
exitFunction exitFunction
stdoutLogLevel int
clk clock.Clock
}
const defaultPriority = syslog.LOG_INFO | syslog.LOG_LOCAL0
// NewAuditLogger returns a new AuditLogger that uses the given
// SyslogWriter as a backend.
func NewAuditLogger(log SyslogWriter, stats statsd.Statter, stdoutLogLevel int) (*AuditLogger, error) {
if log == nil {
return nil, errors.New("Attempted to use a nil System Logger.")
}
audit := &AuditLogger{
log,
stats,
defaultEmergencyExit,
stdoutLogLevel,
clock.Default(),
}
return audit, nil
}
// initializeAuditLogger should only be used in unit tests.
func initializeAuditLogger() {
stats, err := statsd.NewNoopClient(nil)
if err != nil {
log.Fatalf("Initializing stats for AuditLogger: %s", err)
}
syslogger, err := syslog.Dial("", "", defaultPriority, "test")
if err != nil {
log.Fatalf("Initializing SyslogWriter for AuditLogger: %s", err)
}
audit, err := NewAuditLogger(syslogger, stats, int(syslog.LOG_DEBUG))
if err != nil {
log.Fatalf("Initializing AuditLogger: %s", err)
}
SetAuditLogger(audit)
}
// SetAuditLogger configures the singleton audit logger. This method
// must only be called once, and before calling GetAuditLogger the
// first time.
func SetAuditLogger(logger *AuditLogger) (err error) {
if _Singleton.log != nil {
err = errors.New("You may not call SetAuditLogger after it has already been implicitly or explicitly set.")
_Singleton.log.WarningErr(err)
} else {
_Singleton.log = logger
}
return
}
// GetAuditLogger obtains the singleton audit logger. If SetAuditLogger
// has not been called first, this method initializes with basic defaults.
// The basic defaults cannot error, and subsequent access to an already-set
// AuditLogger also cannot error, so this method is error-safe.
func GetAuditLogger() *AuditLogger {
_Singleton.once.Do(func() {
if _Singleton.log == nil {
initializeAuditLogger()
}
})
return _Singleton.log
}
// Log the provided message at the appropriate level, writing to
// both stdout and the Logger, as well as informing statsd.
func (log *AuditLogger) logAtLevel(level syslog.Priority, msg string) error {
var name, color string
var err error
const red = "\033[31m"
const yellow = "\033[33m"
switch level {
case syslog.LOG_ALERT:
err = log.SyslogWriter.Alert(msg)
name = "ALERT"
color = red
case syslog.LOG_CRIT:
err = log.SyslogWriter.Crit(msg)
name = "CRIT"
color = red
case syslog.LOG_DEBUG:
err = log.SyslogWriter.Debug(msg)
name = "DEBUG"
case syslog.LOG_EMERG:
err = log.SyslogWriter.Emerg(msg)
name = "EMERG"
color = red
case syslog.LOG_ERR:
err = log.SyslogWriter.Err(msg)
name = "ERR"
color = red
case syslog.LOG_INFO:
err = log.SyslogWriter.Info(msg)
name = "INFO"
case syslog.LOG_WARNING:
err = log.SyslogWriter.Warning(msg)
name = "WARNING"
color = yellow
case syslog.LOG_NOTICE:
err = log.SyslogWriter.Notice(msg)
name = "NOTICE"
default:
err = fmt.Errorf("Unknown logging level: %d", int(level))
}
var reset string
if color != "" {
reset = "\033[0m"
}
if int(level) <= log.stdoutLogLevel {
fmt.Printf("%s%s %s %s %s%s\n",
color,
log.clk.Now().Format("15:04:05"),
path.Base(os.Args[0]),
name,
msg,
reset)
}
return err
}
// AUDIT[ Error Conditions ] 9cc4d537-8534-4970-8665-4b382abe82f3
func (log *AuditLogger) auditAtLevel(level syslog.Priority, msg string) (err error) {
// Submit a separate counter that marks an Audit event
log.Stats.Inc("Logging.Audit", 1, 1.0)
text := fmt.Sprintf("%s %s", auditTag, msg)
return log.logAtLevel(level, text)
}
// Return short format caller info for panic events, skipping to before the
// panic handler.
func caller(level int) string {
_, file, line, _ := runtime.Caller(level)
splits := strings.Split(file, "/")
filename := splits[len(splits)-1]
return fmt.Sprintf("%s:%d:", filename, line)
}
// AuditPanic catches panicking executables. This method should be added
// in a defer statement as early as possible
// AUDIT[ Error Conditions ] 9cc4d537-8534-4970-8665-4b382abe82f3
func (log *AuditLogger) AuditPanic() {
if err := recover(); err != nil {
buf := make([]byte, 8192)
log.AuditErr(fmt.Errorf("Panic caused by err: %s", err))
runtime.Stack(buf, false)
log.AuditErr(fmt.Errorf("Stack Trace (Current frame) %s", buf))
runtime.Stack(buf, true)
log.Warning(fmt.Sprintf("Stack Trace (All frames): %s", buf))
}
}
// WarningErr formats an error for the Warn level.
func (log *AuditLogger) WarningErr(msg error) (err error) {
return log.logAtLevel(syslog.LOG_WARNING, msg.Error())
}
// Alert level messages pass through normally.
func (log *AuditLogger) Alert(msg string) (err error) {
return log.logAtLevel(syslog.LOG_ALERT, msg)
}
// Crit level messages are automatically marked for audit
func (log *AuditLogger) Crit(msg string) (err error) {
return log.auditAtLevel(syslog.LOG_CRIT, msg)
}
// Debug level messages pass through normally.
func (log *AuditLogger) Debug(msg string) (err error) {
return log.logAtLevel(syslog.LOG_DEBUG, msg)
}
// Emerg level messages are automatically marked for audit
func (log *AuditLogger) Emerg(msg string) (err error) {
return log.auditAtLevel(syslog.LOG_EMERG, msg)
}
// Err level messages are automatically marked for audit
func (log *AuditLogger) Err(msg string) (err error) {
return log.auditAtLevel(syslog.LOG_ERR, msg)
}
// Info level messages pass through normally.
func (log *AuditLogger) Info(msg string) (err error) {
return log.logAtLevel(syslog.LOG_INFO, msg)
}
// Warning level messages pass through normally.
func (log *AuditLogger) Warning(msg string) (err error) {
return log.logAtLevel(syslog.LOG_WARNING, msg)
}
// Notice level messages pass through normally.
func (log *AuditLogger) Notice(msg string) (err error) {
return log.logAtLevel(syslog.LOG_NOTICE, msg)
}
// AuditNotice sends a NOTICE-severity message that is prefixed with the
// audit tag, for special handling at the upstream system logger.
func (log *AuditLogger) AuditNotice(msg string) (err error) {
return log.auditAtLevel(syslog.LOG_NOTICE, msg)
}
func (log *AuditLogger) formatObjectMessage(msg string, obj interface{}) (string, error) {
jsonObj, err := json.Marshal(obj)
if err != nil {
// AUDIT[ Error Conditions ] 9cc4d537-8534-4970-8665-4b382abe82f3
log.auditAtLevel(syslog.LOG_ERR, fmt.Sprintf("Object could not be serialized to JSON. Raw: %+v", obj))
return "", err
}
return fmt.Sprintf("%s JSON=%s", msg, jsonObj), nil
}
// AuditObject sends a NOTICE-severity JSON-serialized object message that is prefixed
// with the audit tag, for special handling at the upstream system logger.
func (log *AuditLogger) AuditObject(msg string, obj interface{}) (err error) {
formattedEvent, logErr := log.formatObjectMessage(msg, obj)
if logErr != nil {
return logErr
}
return log.auditAtLevel(syslog.LOG_NOTICE, formattedEvent)
}
// InfoObject sends an INFO-severity JSON-serialized object message.
func (log *AuditLogger) InfoObject(msg string, obj interface{}) (err error) {
formattedEvent, logErr := log.formatObjectMessage(msg, obj)
if logErr != nil {
return logErr
}
return log.logAtLevel(syslog.LOG_INFO, formattedEvent)
}
// AuditErr can format an error for auditing; it does so at ERR level.
// AUDIT[ Error Conditions ] 9cc4d537-8534-4970-8665-4b382abe82f3
func (log *AuditLogger) AuditErr(msg error) (err error) {
return log.auditAtLevel(syslog.LOG_ERR, msg.Error())
}
// SetEmergencyExitFunc changes the systems' behavior on an emergency exit.
func (log *AuditLogger) SetEmergencyExitFunc(exit exitFunction) {
log.exitFunction = exit
}
// EmergencyExit triggers an immediate Boulder shutdown in the event of serious
// errors. This function will provide the necessary housekeeping.
// Currently, make an emergency log entry and exit.
// AUDIT[ Error Conditions ] 9cc4d537-8534-4970-8665-4b382abe82f3
func (log *AuditLogger) EmergencyExit(msg string) {
log.auditAtLevel(syslog.LOG_EMERG, msg)
log.exitFunction()
}

238
log/log.go Normal file
View File

@ -0,0 +1,238 @@
// Copyright 2015 ISRG. All rights reserved
// This Source Code Form is subject to the terms of the Mozilla Public
// License, v. 2.0. If a copy of the MPL was not distributed with this
// file, You can obtain one at http://mozilla.org/MPL/2.0/.
package log
import (
"encoding/json"
"errors"
"fmt"
"log/syslog"
"os"
"path"
"runtime"
"strings"
"sync"
"github.com/letsencrypt/boulder/Godeps/_workspace/src/github.com/jmhodges/clock"
)
// A Logger logs messages with explicit priority levels. It is
// implemented by a logging back-end as provided by New() or
// NewMock().
type Logger interface {
Err(m string)
Warning(m string)
Info(m string)
Debug(m string)
AuditPanic()
AuditInfo(string)
AuditObject(string, interface{})
AuditErr(error)
}
// impl implements Logger.
type impl struct {
w writer
}
// singleton defines the object of a Singleton pattern
type singleton struct {
once sync.Once
log Logger
}
// _Singleton is the single impl entity in memory
var _Singleton singleton
// The constant used to identify audit-specific messages
const auditTag = "[AUDIT]"
// New returns a new Logger that uses the given syslog.Writer as a backend.
func New(log *syslog.Writer, stdoutLogLevel int) (Logger, error) {
if log == nil {
return nil, errors.New("Attempted to use a nil System Logger.")
}
return &impl{
&bothWriter{log, stdoutLogLevel, clock.Default()},
}, nil
}
// initialize should only be used in unit tests.
func initialize() {
// defaultPriority is never used because we always use specific priority-based
// logging methods.
const defaultPriority = syslog.LOG_INFO | syslog.LOG_LOCAL0
syslogger, err := syslog.Dial("", "", defaultPriority, "test")
if err != nil {
panic(err)
}
logger, err := New(syslogger, int(syslog.LOG_DEBUG))
if err != nil {
panic(err)
}
Set(logger)
}
// Set configures the singleton Logger. This method
// must only be called once, and before calling Get the
// first time.
func Set(logger Logger) (err error) {
if _Singleton.log != nil {
err = errors.New("You may not call Set after it has already been implicitly or explicitly set.")
_Singleton.log.Warning(err.Error())
} else {
_Singleton.log = logger
}
return
}
// Get obtains the singleton Logger. If Set has not been called first, this
// method initializes with basic defaults. The basic defaults cannot error, and
// subsequent access to an already-set Logger also cannot error, so this method is
// error-safe.
func Get() Logger {
_Singleton.once.Do(func() {
if _Singleton.log == nil {
initialize()
}
})
return _Singleton.log
}
type writer interface {
logAtLevel(syslog.Priority, string)
}
// bothWriter implements writer and writes to both syslog and stdout.
type bothWriter struct {
*syslog.Writer
stdoutLevel int
clk clock.Clock
}
// Log the provided message at the appropriate level, writing to
// both stdout and the Logger, as well as informing statsd.
func (w *bothWriter) logAtLevel(level syslog.Priority, msg string) {
var prefix string
var err error
const red = "\033[31m\033[1m"
const yellow = "\033[33m"
switch level {
case syslog.LOG_ERR:
err = w.Err(msg)
prefix = red + "E"
case syslog.LOG_WARNING:
err = w.Warning(msg)
prefix = yellow + "W"
case syslog.LOG_INFO:
err = w.Info(msg)
prefix = "I"
case syslog.LOG_DEBUG:
err = w.Debug(msg)
prefix = "D"
default:
err = w.Err(fmt.Sprintf("%s (unknown logging level: %d)", msg, int(level)))
}
if err != nil {
fmt.Fprintf(os.Stderr, "Failed to write to syslog: %s (%s)", msg, err)
}
var reset string
if strings.HasPrefix(prefix, "\033") {
reset = "\033[0m"
}
if int(level) <= w.stdoutLevel {
fmt.Printf("%s%s %s %s%s\n",
prefix,
w.clk.Now().Format("150405"),
path.Base(os.Args[0]),
msg,
reset)
}
}
// AUDIT[ Error Conditions ] 9cc4d537-8534-4970-8665-4b382abe82f3
func (log *impl) auditAtLevel(level syslog.Priority, msg string) {
text := fmt.Sprintf("%s %s", auditTag, msg)
log.w.logAtLevel(level, text)
}
// Return short format caller info for panic events, skipping to before the
// panic handler.
func caller(level int) string {
_, file, line, _ := runtime.Caller(level)
splits := strings.Split(file, "/")
filename := splits[len(splits)-1]
return fmt.Sprintf("%s:%d:", filename, line)
}
// AuditPanic catches panicking executables. This method should be added
// in a defer statement as early as possible
// AUDIT[ Error Conditions ] 9cc4d537-8534-4970-8665-4b382abe82f3
func (log *impl) AuditPanic() {
if err := recover(); err != nil {
buf := make([]byte, 8192)
log.AuditErr(fmt.Errorf("Panic caused by err: %s", err))
runtime.Stack(buf, false)
log.AuditErr(fmt.Errorf("Stack Trace (Current frame) %s", buf))
runtime.Stack(buf, true)
log.Warning(fmt.Sprintf("Stack Trace (All frames): %s", buf))
}
}
// Err level messages are always marked with the audit tag, for special handling
// at the upstream system logger.
func (log *impl) Err(msg string) {
log.auditAtLevel(syslog.LOG_ERR, msg)
}
// Warning level messages pass through normally.
func (log *impl) Warning(msg string) {
log.w.logAtLevel(syslog.LOG_WARNING, msg)
}
// Info level messages pass through normally.
func (log *impl) Info(msg string) {
log.w.logAtLevel(syslog.LOG_INFO, msg)
}
// Debug level messages pass through normally.
func (log *impl) Debug(msg string) {
log.w.logAtLevel(syslog.LOG_DEBUG, msg)
}
// AuditInfo sends an INFO-severity message that is prefixed with the
// audit tag, for special handling at the upstream system logger.
func (log *impl) AuditInfo(msg string) {
log.auditAtLevel(syslog.LOG_INFO, msg)
}
// AuditObject sends an INFO-severity JSON-serialized object message that is prefixed
// with the audit tag, for special handling at the upstream system logger.
func (log *impl) AuditObject(msg string, obj interface{}) {
jsonObj, err := json.Marshal(obj)
if err != nil {
// AUDIT[ Error Conditions ] 9cc4d537-8534-4970-8665-4b382abe82f3
log.auditAtLevel(syslog.LOG_ERR, fmt.Sprintf("Object could not be serialized to JSON. Raw: %+v", obj))
return
}
log.auditAtLevel(syslog.LOG_INFO, fmt.Sprintf("%s JSON=%s", msg, jsonObj))
}
// AuditErr can format an error for auditing; it does so at ERR level.
// AUDIT[ Error Conditions ] 9cc4d537-8534-4970-8665-4b382abe82f3
func (log *impl) AuditErr(msg error) {
log.auditAtLevel(syslog.LOG_ERR, msg.Error())
}

159
log/audit-logger_test.go → log/log_test.go
View File

@ -13,23 +13,25 @@ import (
"testing"
"time"
"github.com/letsencrypt/boulder/Godeps/_workspace/src/github.com/cactus/go-statsd-client/statsd"
"github.com/letsencrypt/boulder/Godeps/_workspace/src/github.com/jmhodges/clock"
"github.com/letsencrypt/boulder/test"
)
const stdoutLevel = 7
func setup(t *testing.T) *AuditLogger {
func setup(t *testing.T) *impl {
// Write all logs to UDP on a high port so as to not bother the system
// which is running the test, particularly for Emerg()
// which is running the test
writer, err := syslog.Dial("udp", "127.0.0.1:65530", syslog.LOG_INFO|syslog.LOG_LOCAL0, "")
test.AssertNotError(t, err, "Could not construct syslog object")
stats, _ := statsd.NewNoopClient(nil)
audit, err := NewAuditLogger(writer, stats, stdoutLevel)
logger, err := New(writer, stdoutLevel)
test.AssertNotError(t, err, "Could not construct syslog object")
return audit
impl, ok := logger.(*impl)
if !ok {
t.Fatalf("Wrong type returned from New: %T", logger)
}
return impl
}
func TestConstruction(t *testing.T) {
@ -39,20 +41,20 @@ func TestConstruction(t *testing.T) {
func TestSingleton(t *testing.T) {
t.Parallel()
log1 := GetAuditLogger()
log1 := Get()
test.AssertNotNil(t, log1, "Logger shouldn't be nil")
log2 := GetAuditLogger()
log2 := Get()
test.AssertEquals(t, log1, log2)
audit := setup(t)
// Should not work
err := SetAuditLogger(audit)
err := Set(audit)
test.AssertError(t, err, "Can't re-set")
// Verify no change
log4 := GetAuditLogger()
log4 := Get()
// Verify that log4 != log3
test.AssertNotEquals(t, log4, audit)
@ -64,8 +66,7 @@ func TestSingleton(t *testing.T) {
func TestConstructionNil(t *testing.T) {
t.Parallel()
stats, _ := statsd.NewNoopClient(nil)
_, err := NewAuditLogger(nil, stats, stdoutLevel)
_, err := New(nil, stdoutLevel)
test.AssertError(t, err, "Nil shouldn't be permitted.")
}
@ -73,104 +74,93 @@ func TestEmit(t *testing.T) {
t.Parallel()
log := setup(t)
log.AuditNotice("test message")
log.AuditInfo("test message")
}
func TestEmitEmpty(t *testing.T) {
t.Parallel()
log := setup(t)
log.AuditNotice("")
log.AuditInfo("")
}
func ExampleAuditLogger() {
audit := setup(nil)
func ExampleLogger() {
impl := setup(nil)
audit.clk = clock.NewFake()
audit.AuditErr(errors.New("Error Audit"))
audit.WarningErr(errors.New("Warning Audit"))
// Output: 00:00:00 log.test ERR [AUDIT] Error Audit
// 00:00:00 log.test WARNING Warning Audit
}
func TestEmitErrors(t *testing.T) {
t.Parallel()
audit := setup(t)
audit.AuditErr(errors.New("Error Audit"))
audit.WarningErr(errors.New("Warning Audit"))
bw, ok := impl.w.(*bothWriter)
if !ok {
fmt.Printf("Wrong type of impl's writer: %T\n", impl.w)
return
}
bw.clk = clock.NewFake()
impl.AuditErr(errors.New("Error Audit"))
impl.Warning("Warning Audit")
// Output:
// E000000 log.test [AUDIT] Error Audit
// W000000 log.test Warning Audit
}
func TestSyslogMethods(t *testing.T) {
t.Parallel()
audit := setup(t)
impl := setup(t)
audit.AuditNotice("audit-logger_test.go: audit-notice")
audit.AuditErr(errors.New("audit-logger_test.go: audit-err"))
audit.Crit("audit-logger_test.go: critical")
audit.Debug("audit-logger_test.go: debug")
audit.Emerg("audit-logger_test.go: emerg")
audit.Err("audit-logger_test.go: err")
audit.Info("audit-logger_test.go: info")
audit.Notice("audit-logger_test.go: notice")
audit.Warning("audit-logger_test.go: warning")
audit.Alert("audit-logger_test.go: alert")
impl.AuditInfo("audit-logger_test.go: audit-info")
impl.AuditErr(errors.New("audit-logger_test.go: audit-err"))
impl.Debug("audit-logger_test.go: debug")
impl.Err("audit-logger_test.go: err")
impl.Info("audit-logger_test.go: info")
impl.Warning("audit-logger_test.go: warning")
}
func TestPanic(t *testing.T) {
t.Parallel()
audit := setup(t)
defer audit.AuditPanic()
impl := setup(t)
defer impl.AuditPanic()
panic("Test panic")
// Can't assert anything here or golint gets angry
}
func TestAuditObject(t *testing.T) {
t.Parallel()
audit := setup(t)
log := NewMock()
// Test a simple object
err := audit.AuditObject("Prefix", "String")
test.AssertNotError(t, err, "Simple objects should be serializable")
log.AuditObject("Prefix", "String")
if len(log.GetAllMatching("[AUDIT]")) != 1 {
t.Errorf("Failed to audit log simple object")
}
// Test a system object
err = audit.AuditObject("Prefix", t)
test.AssertNotError(t, err, "System objects should be serializable")
log.Clear()
log.AuditObject("Prefix", t)
if len(log.GetAllMatching("[AUDIT]")) != 1 {
t.Errorf("Failed to audit log system object")
}
// Test a complex object
log.Clear()
type validObj struct {
A string
B string
}
var valid = validObj{A: "B", B: "C"}
err = audit.AuditObject("Prefix", valid)
test.AssertNotError(t, err, "Complex objects should be serializable")
log.AuditObject("Prefix", valid)
if len(log.GetAllMatching("[AUDIT]")) != 1 {
t.Errorf("Failed to audit log complex object")
}
// Test logging an unserializable object
log.Clear()
type invalidObj struct {
A chan string
}
var invalid = invalidObj{A: make(chan string)}
err = audit.AuditObject("Prefix", invalid)
test.AssertError(t, err, "Invalid objects should fail serialization")
}
func TestEmergencyExit(t *testing.T) {
t.Parallel()
audit := setup(t)
called := false
audit.SetEmergencyExitFunc(func() { called = true })
audit.EmergencyExit("Emergency!")
test.AssertEquals(t, called, true)
}
func TestUnknownLoggingLevel(t *testing.T) {
t.Parallel()
audit := setup(t)
err := audit.logAtLevel(1000, "string")
test.AssertError(t, err, "Should have been unknown.")
log.AuditObject("Prefix", invalid)
if len(log.GetAllMatching("[AUDIT]")) != 1 {
t.Errorf("Failed to audit log unserializable object %v", log.GetAllMatching("[AUDIT]"))
}
}
func TestTransmission(t *testing.T) {
@ -180,53 +170,36 @@ func TestTransmission(t *testing.T) {
test.AssertNotError(t, err, "Failed to open log server")
defer l.Close()
stats, _ := statsd.NewNoopClient(nil)
fmt.Printf("Going to %s\n", l.LocalAddr().String())
writer, err := syslog.Dial("udp", l.LocalAddr().String(), syslog.LOG_INFO|syslog.LOG_LOCAL0, "")
test.AssertNotError(t, err, "Failed to find connect to log server")
audit, err := NewAuditLogger(writer, stats, stdoutLevel)
impl, err := New(writer, stdoutLevel)
test.AssertNotError(t, err, "Failed to construct audit logger")
data := make([]byte, 128)
audit.AuditNotice("audit-logger_test.go: audit-notice")
impl.AuditInfo("audit-logger_test.go: audit-notice")
_, _, err = l.ReadFrom(data)
test.AssertNotError(t, err, "Failed to find packet")
audit.AuditErr(errors.New("audit-logger_test.go: audit-err"))
impl.AuditErr(errors.New("audit-logger_test.go: audit-err"))
_, _, err = l.ReadFrom(data)
test.AssertNotError(t, err, "Failed to find packet")
audit.Crit("audit-logger_test.go: critical")
impl.Debug("audit-logger_test.go: debug")
_, _, err = l.ReadFrom(data)
test.AssertNotError(t, err, "Failed to find packet")
audit.Debug("audit-logger_test.go: debug")
impl.Err("audit-logger_test.go: err")
_, _, err = l.ReadFrom(data)
test.AssertNotError(t, err, "Failed to find packet")
audit.Emerg("audit-logger_test.go: emerg")
impl.Info("audit-logger_test.go: info")
_, _, err = l.ReadFrom(data)
test.AssertNotError(t, err, "Failed to find packet")
audit.Err("audit-logger_test.go: err")
_, _, err = l.ReadFrom(data)
test.AssertNotError(t, err, "Failed to find packet")
audit.Info("audit-logger_test.go: info")
_, _, err = l.ReadFrom(data)
test.AssertNotError(t, err, "Failed to find packet")
audit.Notice("audit-logger_test.go: notice")
_, _, err = l.ReadFrom(data)
test.AssertNotError(t, err, "Failed to find packet")
audit.Warning("audit-logger_test.go: warning")
_, _, err = l.ReadFrom(data)
test.AssertNotError(t, err, "Failed to find packet")
audit.Alert("audit-logger_test.go: alert")
impl.Warning("audit-logger_test.go: warning")
_, _, err = l.ReadFrom(data)
test.AssertNotError(t, err, "Failed to find packet")
}

115
log/mock.go Normal file
View File

@ -0,0 +1,115 @@
// Copyright 2015 ISRG. All rights reserved
// This Source Code Form is subject to the terms of the Mozilla Public
// License, v. 2.0. If a copy of the MPL was not distributed with this
// file, You can obtain one at http://mozilla.org/MPL/2.0/.
package log
import (
"fmt"
"log/syslog"
"regexp"
)
// UseMock sets a mock logger as the default logger, and returns it.
func UseMock() *Mock {
m := NewMock()
_ = Set(m)
return m
}
// NewMock creates a mock logger.
func NewMock() *Mock {
return &Mock{impl{newMockWriter()}}
}
// Mock is a logger that stores all log messages in memory to be examined by a
// test.
type Mock struct {
impl
}
// Mock implements the writer interface. It
// stores all logged messages in a buffer for inspection by test
// functions (via GetAll()) instead of sending them to syslog.
type mockWriter struct {
logged []string
msgChan chan<- string
getChan <-chan []string
clearChan chan<- struct{}
closeChan chan<- struct{}
}
var levelName = map[syslog.Priority]string{
syslog.LOG_ERR: "ERR",
syslog.LOG_WARNING: "WARNING",
syslog.LOG_INFO: "INFO",
syslog.LOG_DEBUG: "DEBUG",
}
func (w *mockWriter) logAtLevel(p syslog.Priority, msg string) {
w.msgChan <- fmt.Sprintf("%s: %s", levelName[p&7], msg)
}
// newMockWriter returns a new mockWriter
func newMockWriter() *mockWriter {
msgChan := make(chan string)
getChan := make(chan []string)
clearChan := make(chan struct{})
closeChan := make(chan struct{})
w := &mockWriter{
logged: []string{},
msgChan: msgChan,
getChan: getChan,
clearChan: clearChan,
closeChan: closeChan,
}
go func() {
for {
select {
case logMsg := <-msgChan:
w.logged = append(w.logged, logMsg)
case getChan <- w.logged:
case <-clearChan:
w.logged = []string{}
case <-closeChan:
close(getChan)
return
}
}
}()
return w
}
// GetAll returns all messages logged since insantiation or the last call to
// Clear().
//
// The caller must not modify the returned slice or its elements.
func (m *Mock) GetAll() []string {
w := m.w.(*mockWriter)
return <-w.getChan
}
// GetAllMatching returns all messages logged since instantiation or the last
// Clear() whose text matches the given regexp. The regexp is
// accepted as a string and compiled on the fly, because convenience
// is more important than performance.
//
// The caller must not modify the elements of the returned slice.
func (m *Mock) GetAllMatching(reString string) []string {
var matches []string
w := m.w.(*mockWriter)
re := regexp.MustCompile(reString)
for _, logMsg := range <-w.getChan {
if re.MatchString(logMsg) {
matches = append(matches, logMsg)
}
}
return matches
}
// Clear resets the log buffer.
func (m *Mock) Clear() {
w := m.w.(*mockWriter)
w.clearChan <- struct{}{}
}

170
mocks/log.go
View File

@ -1,170 +0,0 @@
// Copyright 2015 ISRG. All rights reserved
// This Source Code Form is subject to the terms of the Mozilla Public
// License, v. 2.0. If a copy of the MPL was not distributed with this
// file, You can obtain one at http://mozilla.org/MPL/2.0/.
package mocks
import (
"log/syslog"
"regexp"
blog "github.com/letsencrypt/boulder/log"
)
// SyslogWriter implements the blog.SyslogWriter interface. It
// stores all logged messages in a buffer for inspection by test
// functions (via GetAll()) instead of sending them to syslog.
type SyslogWriter struct {
logged []*LogMessage
msgChan chan<- *LogMessage
getChan <-chan []*LogMessage
clearChan chan<- struct{}
closeChan chan<- struct{}
}
// LogMessage is a log entry that has been sent to a SyslogWriter.
type LogMessage struct {
Priority syslog.Priority // aka Log level
Message string // content of log message
}
var levelName = map[syslog.Priority]string{
syslog.LOG_EMERG: "EMERG",
syslog.LOG_ALERT: "ALERT",
syslog.LOG_CRIT: "CRIT",
syslog.LOG_ERR: "ERR",
syslog.LOG_WARNING: "WARNING",
syslog.LOG_NOTICE: "NOTICE",
syslog.LOG_INFO: "INFO",
syslog.LOG_DEBUG: "DEBUG",
}
func (lm *LogMessage) String() string {
return levelName[lm.Priority&7] + ": " + lm.Message
}
// UseMockLog changes the SyslogWriter used by the current singleton
// audit logger to a new mock logger, and returns the mock. Example:
//
// var log = mocks.UseMockLog()
// func TestFoo(t *testing.T) {
// log.Clear()
// // ...
// Assert(t, len(log.GetAll()) > 0, "Should have logged something")
// }
func UseMockLog() *SyslogWriter {
sw := NewSyslogWriter()
blog.GetAuditLogger().SyslogWriter = sw
return sw
}
// NewSyslogWriter returns a new SyslogWriter.
func NewSyslogWriter() *SyslogWriter {
msgChan := make(chan *LogMessage)
getChan := make(chan []*LogMessage)
clearChan := make(chan struct{})
closeChan := make(chan struct{})
msw := &SyslogWriter{
logged: []*LogMessage{},
msgChan: msgChan,
getChan: getChan,
clearChan: clearChan,
closeChan: closeChan,
}
go func() {
for {
select {
case logMsg := <-msgChan:
msw.logged = append(msw.logged, logMsg)
case getChan <- msw.logged:
case <-clearChan:
msw.logged = []*LogMessage{}
case <-closeChan:
close(getChan)
return
}
}
}()
return msw
}
func (msw *SyslogWriter) write(m string, priority syslog.Priority) error {
msw.msgChan <- &LogMessage{Message: m, Priority: priority}
return nil
}
// GetAll returns all LogMessages logged (since the last call to
// Clear(), if applicable).
//
// The caller must not modify the returned slice or its elements.
func (msw *SyslogWriter) GetAll() []*LogMessage {
return <-msw.getChan
}
// GetAllMatching returns all LogMessages logged (since the last
// Clear()) whose text matches the given regexp. The regexp is
// accepted as a string and compiled on the fly, because convenience
// is more important than performance.
//
// The caller must not modify the elements of the returned slice.
func (msw *SyslogWriter) GetAllMatching(reString string) (matches []*LogMessage) {
re := regexp.MustCompile(reString)
for _, logMsg := range <-msw.getChan {
if re.MatchString(logMsg.String()) {
matches = append(matches, logMsg)
}
}
return
}
// Clear resets the log buffer.
func (msw *SyslogWriter) Clear() {
msw.clearChan <- struct{}{}
}
// Close releases resources. No other methods may be called after this.
func (msw *SyslogWriter) Close() error {
msw.closeChan <- struct{}{}
return nil
}
// Alert logs at LOG_ALERT
func (msw *SyslogWriter) Alert(m string) error {
return msw.write(m, syslog.LOG_ALERT)
}
// Crit logs at LOG_CRIT
func (msw *SyslogWriter) Crit(m string) error {
return msw.write(m, syslog.LOG_CRIT)
}
// Debug logs at LOG_DEBUG
func (msw *SyslogWriter) Debug(m string) error {
return msw.write(m, syslog.LOG_DEBUG)
}
// Emerg logs at LOG_EMERG
func (msw *SyslogWriter) Emerg(m string) error {
return msw.write(m, syslog.LOG_EMERG)
}
// Err logs at LOG_ERR
func (msw *SyslogWriter) Err(m string) error {
return msw.write(m, syslog.LOG_ERR)
}
// Info logs at LOG_INFO
func (msw *SyslogWriter) Info(m string) error {
return msw.write(m, syslog.LOG_INFO)
}
// Notice logs at LOG_NOTICE
func (msw *SyslogWriter) Notice(m string) error {
return msw.write(m, syslog.LOG_NOTICE)
}
// Warning logs at LOG_WARNING
func (msw *SyslogWriter) Warning(m string) error {
return msw.write(m, syslog.LOG_WARNING)
}

4
policy/policy-authority-data.go
View File

@ -53,14 +53,14 @@ type gorpDbMap interface {
// AuthorityDatabaseImpl enforces policy decisions based on various rule
// lists
type AuthorityDatabaseImpl struct {
log *blog.AuditLogger
log blog.Logger
dbMap gorpDbMap
}
// NewAuthorityDatabaseImpl constructs a Policy Authority Database (and
// creates tables if they are non-existent)
func NewAuthorityDatabaseImpl(dbMap gorpDbMap) (padb *AuthorityDatabaseImpl, err error) {
logger := blog.GetAuditLogger()
logger := blog.Get()
dbMap.AddTableWithName(BlacklistRule{}, "blacklist")
dbMap.AddTableWithName(WhitelistRule{}, "whitelist")

5
policy/policy-authority.go
View File

@ -26,7 +26,7 @@ import (
// AuthorityImpl enforces CA policy decisions.
type AuthorityImpl struct {
log *blog.AuditLogger
log blog.Logger
DB *AuthorityDatabaseImpl
blacklist map[string]bool
@ -40,8 +40,7 @@ type AuthorityImpl struct {
// TODO(https://github.com/letsencrypt/boulder/issues/1616): Remove the _ bool
// argument (used to be enforceWhitelist). Update all callers.
func New(dbMap *gorp.DbMap, _ bool, challengeTypes map[string]bool) (*AuthorityImpl, error) {
logger := blog.GetAuditLogger()
logger.Notice("Policy Authority Starting")
logger := blog.Get()
var padb *AuthorityDatabaseImpl
if dbMap != nil {

4
policy/policy-authority_test.go
View File

@ -13,13 +13,13 @@ import (
"github.com/letsencrypt/boulder/Godeps/_workspace/src/gopkg.in/gorp.v1"
"github.com/letsencrypt/boulder/core"
"github.com/letsencrypt/boulder/mocks"
blog "github.com/letsencrypt/boulder/log"
"github.com/letsencrypt/boulder/sa"
"github.com/letsencrypt/boulder/test"
"github.com/letsencrypt/boulder/test/vars"
)
var log = mocks.UseMockLog()
var log = blog.UseMock()
var enabledChallenges = map[string]bool{
core.ChallengeTypeHTTP01: true,

17
publisher/publisher.go
View File

@ -58,7 +58,7 @@ type ctSubmissionRequest struct {
// Impl defines a Publisher
type Impl struct {
log *blog.AuditLogger
log blog.Logger
client *http.Client
issuerBundle []ct.ASN1Cert
ctLogs []*Log
@ -69,10 +69,7 @@ type Impl struct {
// New creates a Publisher that will submit certificates
// to any CT logs configured in CTConfig
func New(bundle []ct.ASN1Cert, logs []*Log, submissionTimeout time.Duration) *Impl {
logger := blog.GetAuditLogger()
logger.Notice("Publisher Authority Starting")
func New(bundle []ct.ASN1Cert, logs []*Log, submissionTimeout time.Duration, logger blog.Logger) *Impl {
if submissionTimeout == 0 {
submissionTimeout = time.Hour * 12
}
@ -89,7 +86,7 @@ func New(bundle []ct.ASN1Cert, logs []*Log, submissionTimeout time.Duration) *Im
func (pub *Impl) SubmitToCT(der []byte) error {
cert, err := x509.ParseCertificate(der)
if err != nil {
pub.log.AuditErr(fmt.Errorf("Failed to parse certificate: %s", err))
pub.log.Err(fmt.Sprintf("Failed to parse certificate: %s", err))
return err
}
@ -100,7 +97,7 @@ func (pub *Impl) SubmitToCT(der []byte) error {
sct, err := ctLog.client.AddChainWithContext(ctx, chain)
if err != nil {
// AUDIT[ Error Conditions ] 9cc4d537-8534-4970-8665-4b382abe82f3
pub.log.AuditErr(fmt.Errorf("Failed to submit certificate to CT log at %s: %s", ctLog.uri, err))
pub.log.Err(fmt.Sprintf("Failed to submit certificate to CT log at %s: %s", ctLog.uri, err))
continue
}
@ -115,21 +112,21 @@ func (pub *Impl) SubmitToCT(der []byte) error {
})
if err != nil {
// AUDIT[ Error Conditions ] 9cc4d537-8534-4970-8665-4b382abe82f3
pub.log.AuditErr(fmt.Errorf("Failed to verify SCT receipt: %s", err))
pub.log.Err(fmt.Sprintf("Failed to verify SCT receipt: %s", err))
continue
}
internalSCT, err := sctToInternal(sct, core.SerialToString(cert.SerialNumber))
if err != nil {
// AUDIT[ Error Conditions ] 9cc4d537-8534-4970-8665-4b382abe82f3
pub.log.AuditErr(fmt.Errorf("Failed to convert SCT receipt: %s", err))
pub.log.Err(fmt.Sprintf("Failed to convert SCT receipt: %s", err))
continue
}
err = pub.SA.AddSCTReceipt(internalSCT)
if err != nil {
// AUDIT[ Error Conditions ] 9cc4d537-8534-4970-8665-4b382abe82f3
pub.log.AuditErr(fmt.Errorf("Failed to store SCT receipt in database: %s", err))
pub.log.Err(fmt.Sprintf("Failed to store SCT receipt in database: %s", err))
continue
}
}

5
publisher/publisher_test.go
View File

@ -28,6 +28,7 @@ import (
ct "github.com/letsencrypt/boulder/Godeps/_workspace/src/github.com/google/certificate-transparency/go"
"github.com/letsencrypt/boulder/Godeps/_workspace/src/github.com/jmhodges/clock"
blog "github.com/letsencrypt/boulder/log"
"github.com/letsencrypt/boulder/mocks"
"github.com/letsencrypt/boulder/test"
)
@ -115,7 +116,7 @@ OY8B7wwvZTLzU6WWs781TJXx2CE04PneeeArLpVLkiGIWjk=
const issuerPath = "../test/test-ca.pem"
var log = mocks.UseMockLog()
var log = blog.UseMock()
func getPort(hs *httptest.Server) (int, error) {
url, err := url.Parse(hs.URL)
@ -256,7 +257,7 @@ func badLogSrv() *httptest.Server {
func setup(t *testing.T) (*Impl, *x509.Certificate, *ecdsa.PrivateKey) {
intermediatePEM, _ := pem.Decode([]byte(testIntermediate))
pub := New(nil, nil, 0)
pub := New(nil, nil, 0, log)
pub.issuerBundle = append(pub.issuerBundle, ct.ASN1Cert(intermediatePEM.Bytes))
pub.SA = mocks.NewStorageAuthority(clock.NewFake())

8
ra/registration-authority.go
View File

@ -53,7 +53,7 @@ type RegistrationAuthorityImpl struct {
stats statsd.Statter
DNSResolver bdns.DNSResolver
clk clock.Clock
log *blog.AuditLogger
log blog.Logger
dc *DomainCheck
keyPolicy core.KeyPolicy
// How long before a newly created authorization expires.
@ -73,7 +73,7 @@ type RegistrationAuthorityImpl struct {
}
// NewRegistrationAuthorityImpl constructs a new RA object.
func NewRegistrationAuthorityImpl(clk clock.Clock, logger *blog.AuditLogger, stats statsd.Statter, dc *DomainCheck, policies cmd.RateLimitConfig, maxContactsPerReg int, keyPolicy core.KeyPolicy, newVARPC bool) *RegistrationAuthorityImpl {
func NewRegistrationAuthorityImpl(clk clock.Clock, logger blog.Logger, stats statsd.Statter, dc *DomainCheck, policies cmd.RateLimitConfig, maxContactsPerReg int, keyPolicy core.KeyPolicy, newVARPC bool) *RegistrationAuthorityImpl {
// TODO(jmhodges): making RA take a "RA" stats.Scope, not Statter
scope := metrics.NewStatsdScope(stats, "RA")
ra := &RegistrationAuthorityImpl{
@ -853,7 +853,7 @@ func (ra *RegistrationAuthorityImpl) RevokeCertificateWithReg(cert x509.Certific
// Revocation reason
// Registration ID of requester
// Error (if there was one)
ra.log.AuditNotice(fmt.Sprintf(
ra.log.AuditInfo(fmt.Sprintf(
"%s, Request by registration ID: %d",
revokeEvent(state, serialString, cert.Subject.CommonName, cert.DNSNames, revocationCode),
regID,
@ -886,7 +886,7 @@ func (ra *RegistrationAuthorityImpl) AdministrativelyRevokeCertificate(cert x509
// Revocation reason
// Name of admin-revoker user
// Error (if there was one)
ra.log.AuditNotice(fmt.Sprintf(
ra.log.AuditInfo(fmt.Sprintf(
"%s, admin-revoker user: %s",
revokeEvent(state, serialString, cert.Subject.CommonName, cert.DNSNames, revocationCode),
user,

4
ra/registration-authority_test.go
View File

@ -134,7 +134,7 @@ var (
}
AuthzFinal = core.Authorization{}
log = mocks.UseMockLog()
log = blog.UseMock()
)
func makeResponse(ch core.Challenge) (out core.Challenge, err error) {
@ -209,7 +209,7 @@ func initAuthorities(t *testing.T) (*DummyValidationAuthority, *sa.SQLStorageAut
})
ra := NewRegistrationAuthorityImpl(fc,
blog.GetAuditLogger(),
log,
stats,
&DomainCheck{va},
cmd.RateLimitConfig{

10
rpc/amqp-rpc.go
View File

@ -114,7 +114,7 @@ type messageHandler func([]byte) ([]byte, error)
type AmqpRPCServer struct {
serverQueue string
connection *amqpConnector
log *blog.AuditLogger
log blog.Logger
handleDelivery DeliveryHandler
// Servers that just care about messages (method + body) add entries to
// dispatchTable
@ -134,7 +134,7 @@ const wildcardRoutingKey = "#"
// NewAmqpRPCServer creates a new RPC server for the given queue and will begin
// consuming requests from the queue. To start the server you must call Start().
func NewAmqpRPCServer(amqpConf *cmd.AMQPConfig, maxConcurrentRPCServerRequests int64, stats statsd.Statter) (*AmqpRPCServer, error) {
log := blog.GetAuditLogger()
log := blog.Get()
reconnectBase := amqpConf.ReconnectTimeouts.Base.Duration
if reconnectBase == 0 {
@ -274,7 +274,7 @@ func makeAmqpChannel(conf *cmd.AMQPConfig) (*amqp.Channel, error) {
var conn *amqp.Connection
var err error
log := blog.GetAuditLogger()
log := blog.Get()
serverURL, err := conf.ServerURL()
if err != nil {
@ -497,7 +497,7 @@ type AmqpRPCCLient struct {
clientQueue string
connection *amqpConnector
timeout time.Duration
log *blog.AuditLogger
log blog.Logger
mu sync.RWMutex
pending map[string]chan []byte
@ -544,7 +544,7 @@ func NewAmqpRPCClient(
connection: newAMQPConnector(clientQueue, reconnectBase, reconnectMax),
pending: make(map[string]chan []byte),
timeout: timeout,
log: blog.GetAuditLogger(),
log: blog.Get(),
stats: stats,
}

2
rpc/connection.go
View File

@ -89,7 +89,7 @@ func (ac *amqpConnector) connect(config *cmd.AMQPConfig) error {
// reconnect attempts repeatedly to connect and subscribe to the named queue. It
// will loop forever until it succeeds. This is used for a running server, where
// we don't want to shut down because we lost our AMQP connection.
func (ac *amqpConnector) reconnect(config *cmd.AMQPConfig, log blog.SyslogWriter) {
func (ac *amqpConnector) reconnect(config *cmd.AMQPConfig, log blog.Logger) {
for i := 0; ; i++ {
ac.clk.Sleep(core.RetryBackoff(i, ac.retryTimeoutBase, ac.retryTimeoutMax, 2))
log.Info(fmt.Sprintf(" [!] attempting reconnect for %s", ac.queueName))

4
rpc/connection_test.go
View File

@ -9,7 +9,7 @@ import (
"github.com/letsencrypt/boulder/Godeps/_workspace/src/github.com/jmhodges/clock"
"github.com/letsencrypt/boulder/Godeps/_workspace/src/github.com/streadway/amqp"
"github.com/letsencrypt/boulder/cmd"
"github.com/letsencrypt/boulder/mocks"
blog "github.com/letsencrypt/boulder/log"
)
// mockChannelMaker always returns the given amqpChannel
@ -87,7 +87,7 @@ func TestReconnect(t *testing.T) {
mockChannel.EXPECT().Consume("fooqueue", consumerName, AmqpAutoAck, AmqpExclusive, AmqpNoLocal, AmqpNoWait, nil).Return(make(<-chan amqp.Delivery), nil)
mockChannel.EXPECT().NotifyClose(gomock.Any()).Return(make(chan *amqp.Error))
log = mocks.UseMockLog()
log = blog.UseMock()
ac.reconnect(&cmd.AMQPConfig{}, log)
if ac.channel != mockChannel {

6
rpc/rpc-wrappers.go
View File

@ -222,17 +222,17 @@ type fqdnSetExistsResponse struct {
}
func improperMessage(method string, err error, obj interface{}) {
log := blog.GetAuditLogger()
log := blog.Get()
log.AuditErr(fmt.Errorf("Improper message. method: %s err: %s data: %+v", method, err, obj))
}
func errorCondition(method string, err error, obj interface{}) {
log := blog.GetAuditLogger()
log := blog.Get()
log.AuditErr(fmt.Errorf("Error condition. method: %s err: %s data: %+v", method, err, obj))
}
// NewRegistrationAuthorityServer constructs an RPC server
func NewRegistrationAuthorityServer(rpc Server, impl core.RegistrationAuthority) error {
log := blog.GetAuditLogger()
log := blog.Get()
rpc.Handle(MethodNewRegistration, func(req []byte) (response []byte, err error) {
var rr registrationRequest

4
rpc/rpc-wrappers_test.go
View File

@ -11,11 +11,11 @@ import (
jose "github.com/letsencrypt/boulder/Godeps/_workspace/src/github.com/square/go-jose"
"github.com/letsencrypt/boulder/core"
"github.com/letsencrypt/boulder/mocks"
blog "github.com/letsencrypt/boulder/log"
"github.com/letsencrypt/boulder/test"
)
var log = mocks.UseMockLog()
var log = blog.UseMock()
const JWK1JSON = `{
"kty": "RSA",

8
sa/database.go
View File

@ -130,18 +130,18 @@ func recombineCustomMySQLURL(dbConnect string) (string, error) {
}
// SetSQLDebug enables GORP SQL-level Debugging
func SetSQLDebug(dbMap *gorp.DbMap, log blog.SyslogWriter) {
func SetSQLDebug(dbMap *gorp.DbMap, log blog.Logger) {
dbMap.TraceOn("SQL: ", &SQLLogger{log})
}
// SQLLogger adapts the AuditLogger to a format GORP can use.
// SQLLogger adapts the Boulder Logger to a format GORP can use.
type SQLLogger struct {
log blog.SyslogWriter
blog.Logger
}
// Printf adapts the AuditLogger to GORP's interface
func (log *SQLLogger) Printf(format string, v ...interface{}) {
log.log.Debug(fmt.Sprintf(format, v...))
log.Debug(fmt.Sprintf(format, v...))
}
// initTables constructs the table map for the ORM.

5
sa/storage-authority.go
View File

@ -32,7 +32,7 @@ const getChallengesQuery = "SELECT * FROM challenges WHERE authorizationID = :au
type SQLStorageAuthority struct {
dbMap *gorp.DbMap
clk clock.Clock
log blog.SyslogWriter
log blog.Logger
}
func digest256(data []byte) []byte {
@ -54,8 +54,7 @@ type authzModel struct {
// NewSQLStorageAuthority provides persistence using a SQL backend for
// Boulder. It will modify the given gorp.DbMap by adding relevant tables.
func NewSQLStorageAuthority(dbMap *gorp.DbMap, clk clock.Clock, logger blog.SyslogWriter) (*SQLStorageAuthority, error) {
logger.Notice("Storage Authority Starting")
func NewSQLStorageAuthority(dbMap *gorp.DbMap, clk clock.Clock, logger blog.Logger) (*SQLStorageAuthority, error) {
SetSQLDebug(dbMap, logger)
ssa := &SQLStorageAuthority{

4
sa/storage-authority_test.go
View File

@ -27,13 +27,13 @@ import (
jose "github.com/letsencrypt/boulder/Godeps/_workspace/src/github.com/square/go-jose"
"github.com/letsencrypt/boulder/core"
"github.com/letsencrypt/boulder/mocks"
blog "github.com/letsencrypt/boulder/log"
"github.com/letsencrypt/boulder/sa/satest"
"github.com/letsencrypt/boulder/test"
"github.com/letsencrypt/boulder/test/vars"
)
var log = mocks.UseMockLog()
var log = blog.UseMock()
// initSA constructs a SQLStorageAuthority and a clean up function
// that should be defer'ed to the end of the test.

1
test/dns-test-srv/main.go
View File

@ -178,7 +178,6 @@ func (ts *testSrv) serveTestResolver() {
}
func main() {
fmt.Println("dns-srv: Starting test DNS server")
ts := testSrv{mu: new(sync.RWMutex), txtRecords: make(map[string]string)}
ts.serveTestResolver()
forever := make(chan bool, 1)

2
test/mail-test-srv/main.go
View File

@ -46,7 +46,7 @@ var smtpOk250 = []byte("250 OK \r\n")
func handleConn(conn net.Conn) {
defer conn.Close()
auditlogger := blog.GetAuditLogger()
auditlogger := blog.Get()
auditlogger.Info(fmt.Sprintf("mail-test-srv: Got connection from %s", conn.RemoteAddr()))
readBuf := bufio.NewReader(conn)

13
va/validation-authority.go
View File

@ -40,7 +40,7 @@ var validationTimeout = time.Second * 5
// ValidationAuthorityImpl represents a VA
type ValidationAuthorityImpl struct {
RA core.RegistrationAuthority
log *blog.AuditLogger
log blog.Logger
DNSResolver bdns.DNSResolver
IssuerDomain string
SafeBrowsing SafeBrowsing
@ -62,8 +62,7 @@ type PortConfig struct {
// NewValidationAuthorityImpl constructs a new VA
func NewValidationAuthorityImpl(pc *PortConfig, sbc SafeBrowsing, stats statsd.Statter, clk clock.Clock) *ValidationAuthorityImpl {
logger := blog.GetAuditLogger()
logger.Notice("Validation Authority Starting")
logger := blog.Get()
return &ValidationAuthorityImpl{
SafeBrowsing: sbc,
log: logger,
@ -165,7 +164,7 @@ func (va *ValidationAuthorityImpl) fetchHTTP(ctx context.Context, identifier cor
}
// AUDIT[ Certificate Requests ] 11917fa4-10ef-4e0d-9105-bacbe7836a3c
va.log.AuditNotice(fmt.Sprintf("Attempting to validate %s for %s", challenge.Type, url))
va.log.AuditInfo(fmt.Sprintf("Attempting to validate %s for %s", challenge.Type, url))
httpRequest, err := http.NewRequest("GET", url.String(), nil)
if err != nil {
va.log.Info(fmt.Sprintf("Failed to parse URL '%s'. err=[%#v] errStr=[%s]", identifier, err, err))
@ -300,7 +299,7 @@ func (va *ValidationAuthorityImpl) validateTLSWithZName(ctx context.Context, ide
portString := strconv.Itoa(va.tlsPort)
hostPort := net.JoinHostPort(addr.String(), portString)
validationRecords[0].Port = portString
va.log.Notice(fmt.Sprintf("%s [%s] Attempting to validate for %s %s", challenge.Type, identifier, hostPort, zName))
va.log.Info(fmt.Sprintf("%s [%s] Attempting to validate for %s %s", challenge.Type, identifier, hostPort, zName))
conn, err := tls.DialWithDialer(&net.Dialer{Timeout: validationTimeout}, "tcp", hostPort, &tls.Config{
ServerName: zName,
InsecureSkipVerify: true,
@ -468,7 +467,7 @@ func (va *ValidationAuthorityImpl) checkCAA(ctx context.Context, identifier core
return bdns.ProblemDetailsFromDNSError(err)
}
// AUDIT[ Certificate Requests ] 11917fa4-10ef-4e0d-9105-bacbe7836a3c
va.log.AuditNotice(fmt.Sprintf("Checked CAA records for %s, [Present: %t, Valid for issuance: %t]", identifier.Value, present, valid))
va.log.AuditInfo(fmt.Sprintf("Checked CAA records for %s, [Present: %t, Valid for issuance: %t]", identifier.Value, present, valid))
if !valid {
return &probs.ProblemDetails{
Type: probs.ConnectionProblem,
@ -510,7 +509,7 @@ func (va *ValidationAuthorityImpl) validate(ctx context.Context, authz core.Auth
// AUDIT[ Certificate Requests ] 11917fa4-10ef-4e0d-9105-bacbe7836a3c
va.log.AuditObject("Validation result", logEvent)
va.log.Notice(fmt.Sprintf("Validations: %+v", authz))
va.log.Info(fmt.Sprintf("Validations: %+v", authz))
va.RA.OnValidationUpdate(authz)
}

4
va/validation-authority_test.go
View File

@ -35,7 +35,7 @@ import (
"github.com/letsencrypt/boulder/probs"
"github.com/letsencrypt/boulder/core"
"github.com/letsencrypt/boulder/mocks"
blog "github.com/letsencrypt/boulder/log"
"github.com/letsencrypt/boulder/test"
)
@ -66,7 +66,7 @@ var accountKey = &jose.JsonWebKey{Key: TheKey.Public()}
var ident = core.AcmeIdentifier{Type: core.IdentifierDNS, Value: "localhost"}
var log = mocks.UseMockLog()
var log = blog.UseMock()
// All paths that get assigned to tokens MUST be valid tokens
const expectedToken = "LoqXcYV8q5ONbJQxbmR7SCTNo3tiAXDfowyjxAjEuX0"

10
wfe/context.go
View File

@ -1,6 +1,7 @@
package wfe
import (
"encoding/json"
"fmt"
"net/http"
"time"
@ -43,7 +44,7 @@ type wfeHandler interface {
type topHandler struct {
wfe wfeHandler
log *blog.AuditLogger
log blog.Logger
clk clock.Clock
}
@ -73,7 +74,12 @@ func (th *topHandler) logEvent(logEvent *requestEvent) {
} else {
msg = "Successful request"
}
th.log.InfoObject(msg, logEvent)
jsonEvent, err := json.Marshal(logEvent)
if err != nil {
th.log.Err(fmt.Sprintf("%s - failed to marshal logEvent - %s", msg, err))
return
}
th.log.Info(fmt.Sprintf("%s JSON=%s", msg, jsonEvent))
}
// Comma-separated list of HTTP clients involved in making this

5
wfe/web-front-end.go
View File

@ -50,7 +50,7 @@ type WebFrontEndImpl struct {
RA core.RegistrationAuthority
SA core.StorageGetter
stats statsd.Statter
log *blog.AuditLogger
log blog.Logger
clk clock.Clock
// URL configuration parameters
@ -94,8 +94,7 @@ type WebFrontEndImpl struct {
// NewWebFrontEndImpl constructs a web service for Boulder
func NewWebFrontEndImpl(stats statsd.Statter, clk clock.Clock, keyPolicy core.KeyPolicy) (WebFrontEndImpl, error) {
logger := blog.GetAuditLogger()
logger.Notice("Web Front End Starting")
logger := blog.Get()
nonceService, err := core.NewNonceService()
if err != nil {

31
wfe/web-front-end_test.go
View File

@ -15,7 +15,6 @@ import (
"fmt"
"io"
"io/ioutil"
"log/syslog"
"net/http"
"net/http/httptest"
"net/url"
@ -32,6 +31,7 @@ import (
"github.com/letsencrypt/boulder/cmd"
"github.com/letsencrypt/boulder/core"
blog "github.com/letsencrypt/boulder/log"
"github.com/letsencrypt/boulder/mocks"
"github.com/letsencrypt/boulder/ra"
"github.com/letsencrypt/boulder/test"
@ -224,7 +224,7 @@ func setupWFE(t *testing.T) (WebFrontEndImpl, clock.FakeClock) {
wfe.NewCert = wfe.BaseURL + NewCertPath
wfe.CertBase = wfe.BaseURL + CertPath
wfe.SubscriberAgreementURL = agreementURL
wfe.log.SyslogWriter = mocks.NewSyslogWriter()
wfe.log = blog.NewMock()
wfe.RA = &MockRegistrationAuthority{}
wfe.SA = mocks.NewStorageAuthority(fc)
@ -546,7 +546,7 @@ func TestIssueCertificate(t *testing.T) {
wfe, fc := setupWFE(t)
mux, err := wfe.Handler()
test.AssertNotError(t, err, "Problem setting up HTTP handlers")
mockLog := wfe.log.SyslogWriter.(*mocks.SyslogWriter)
mockLog := wfe.log.(*blog.Mock)
// The mock CA we use always returns the same test certificate, with a Not
// Before of 2015-09-22. Since we're currently using a real RA instead of a
@ -678,9 +678,9 @@ func TestIssueCertificate(t *testing.T) {
"application/pkix-cert")
reqlogs := mockLog.GetAllMatching(`Certificate request - successful`)
test.AssertEquals(t, len(reqlogs), 1)
test.AssertEquals(t, reqlogs[0].Priority, syslog.LOG_NOTICE)
test.AssertContains(t, reqlogs[0].Message, `[AUDIT] `)
test.AssertContains(t, reqlogs[0].Message, `"CommonName":"not-an-example.com",`)
test.AssertContains(t, reqlogs[0], `INFO: `)
test.AssertContains(t, reqlogs[0], `[AUDIT] `)
test.AssertContains(t, reqlogs[0], `"CommonName":"not-an-example.com",`)
}
func TestGetChallenge(t *testing.T) {
@ -1328,7 +1328,7 @@ func TestGetCertificate(t *testing.T) {
responseWriter := httptest.NewRecorder()
mockLog := wfe.log.SyslogWriter.(*mocks.SyslogWriter)
mockLog := wfe.log.(*blog.Mock)
mockLog.Clear()
// Valid serial, cached
@ -1343,8 +1343,8 @@ func TestGetCertificate(t *testing.T) {
t.Logf("UGH %#v", mockLog.GetAll()[0])
reqlogs := mockLog.GetAllMatching(`Successful request`)
test.AssertEquals(t, len(reqlogs), 1)
test.AssertEquals(t, reqlogs[0].Priority, syslog.LOG_INFO)
test.AssertContains(t, reqlogs[0].Message, `"ClientAddr":"192.168.0.1"`)
test.AssertContains(t, reqlogs[0], `INFO: `)
test.AssertContains(t, reqlogs[0], `"ClientAddr":"192.168.0.1"`)
// Unused serial, no cache
mockLog.Clear()
@ -1359,8 +1359,8 @@ func TestGetCertificate(t *testing.T) {
reqlogs = mockLog.GetAllMatching(`Terminated request`)
test.AssertEquals(t, len(reqlogs), 1)
test.AssertEquals(t, reqlogs[0].Priority, syslog.LOG_INFO)
test.AssertContains(t, reqlogs[0].Message, `"ClientAddr":"192.168.99.99,192.168.0.1"`)
test.AssertContains(t, reqlogs[0], `INFO: `)
test.AssertContains(t, reqlogs[0], `"ClientAddr":"192.168.99.99,192.168.0.1"`)
// Invalid serial, no cache
responseWriter = httptest.NewRecorder()
@ -1379,12 +1379,11 @@ func TestGetCertificate(t *testing.T) {
test.AssertEquals(t, responseWriter.Body.String(), `{"type":"urn:acme:error:malformed","detail":"Certificate not found","status":404}`)
}
func assertCsrLogged(t *testing.T, mockLog *mocks.SyslogWriter) {
matches := mockLog.GetAllMatching("^NOTICE: \\[AUDIT\\] Certificate request JSON=")
func assertCsrLogged(t *testing.T, mockLog *blog.Mock) {
matches := mockLog.GetAllMatching("^INFO: \\[AUDIT\\] Certificate request JSON=")
test.Assert(t, len(matches) == 1,
fmt.Sprintf("Incorrect number of certificate request log entries: %d",
len(matches)))
test.AssertEquals(t, matches[0].Priority, syslog.LOG_NOTICE)
}
func TestLogCsrPem(t *testing.T) {
@ -1405,7 +1404,7 @@ func TestLogCsrPem(t *testing.T) {
req.RemoteAddr = "12.34.98.76"
req.Header.Set("X-Forwarded-For", "10.0.0.1,172.16.0.1")
mockLog := wfe.log.SyslogWriter.(*mocks.SyslogWriter)
mockLog := wfe.log.(*blog.Mock)
mockLog.Clear()
wfe.logCsr(req, certificateRequest, reg)
@ -1473,7 +1472,7 @@ func TestGetCertificateHEADHasCorrectBodyLength(t *testing.T) {
certPemBytes, _ := ioutil.ReadFile("test/178.crt")
certBlock, _ := pem.Decode(certPemBytes)
mockLog := wfe.log.SyslogWriter.(*mocks.SyslogWriter)
mockLog := wfe.log.(*blog.Mock)
mockLog.Clear()
mux, _ := wfe.Handler()