Skip to content

Commit

Permalink
Simplify LogInfo (#95)
Browse files Browse the repository at this point in the history 
* simplify signature of newLogInfo

# Conflicts:
#	handlers.go

# Conflicts:
#	handlers.go

# Conflicts:
#	handlers.go

# Conflicts:
#	handlers.go

# Conflicts:
#	handlers.go

* loginfo: add log and iOpts

# Conflicts:
#	handlers.go

# Conflicts:
#	handlers.go

# Conflicts:
#	handlers.go

* Remove newloginfo

# Conflicts:
#	handlers.go

# Conflicts:
#	handlers.go

# Conflicts:
#	handlers.go
#	handlers_test.go

# Conflicts:
#	handlers.go
  • Loading branch information
@phbnf
phbnf authored Jan 22, 2025
1 parent c9c70e9 commit 6ecc832
Show file tree
Hide file tree
Showing 2 changed files with 127 additions and 133 deletions.
129 changes: 45 additions & 84 deletions handlers.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -97,22 +97,22 @@ type AppHandler struct {
// does additional common error and stats processing.
func (a AppHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
var statusCode int
label0 := a.Info.Origin
label0 := a.Info.log.origin
label1 := string(a.Name)
reqsCounter.Inc(label0, label1)
startTime := a.Info.TimeSource.Now()
logCtx := a.Info.RequestLog.Start(r.Context())
a.Info.RequestLog.Origin(logCtx, a.Info.Origin)
startTime := a.Info.iOpts.TimeSource.Now()
logCtx := a.Info.iOpts.RequestLog.Start(r.Context())
a.Info.iOpts.RequestLog.Origin(logCtx, a.Info.log.origin)
defer func() {
latency := a.Info.TimeSource.Now().Sub(startTime).Seconds()
latency := a.Info.iOpts.TimeSource.Now().Sub(startTime).Seconds()
rspLatency.Observe(latency, label0, label1, strconv.Itoa(statusCode))
}()
klog.V(2).Infof("%s: request %v %q => %s", a.Info.Origin, r.Method, r.URL, a.Name)
klog.V(2).Infof("%s: request %v %q => %s", a.Info.log.origin, r.Method, r.URL, a.Name)
// TODO(phboneff): add a.Method directly on the handler path and remove this test.
if r.Method != a.Method {
klog.Warningf("%s: %s wrong HTTP method: %v", a.Info.Origin, a.Name, r.Method)
klog.Warningf("%s: %s wrong HTTP method: %v", a.Info.log.origin, a.Name, r.Method)
a.Info.SendHTTPError(w, http.StatusMethodNotAllowed, fmt.Errorf("method not allowed: %s", r.Method))
a.Info.RequestLog.Status(logCtx, http.StatusMethodNotAllowed)
a.Info.iOpts.RequestLog.Status(logCtx, http.StatusMethodNotAllowed)
return
}

Expand All @@ -121,7 +121,7 @@ func (a AppHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
if r.Method == http.MethodGet {
if err := r.ParseForm(); err != nil {
a.Info.SendHTTPError(w, http.StatusBadRequest, fmt.Errorf("failed to parse form data: %s", err))
a.Info.RequestLog.Status(logCtx, http.StatusBadRequest)
a.Info.iOpts.RequestLog.Status(logCtx, http.StatusBadRequest)
return
}
}
Expand All @@ -132,43 +132,27 @@ func (a AppHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {

var err error
statusCode, err = a.Handler(ctx, a.Info, w, r)
a.Info.RequestLog.Status(ctx, statusCode)
klog.V(2).Infof("%s: %s <= st=%d", a.Info.Origin, a.Name, statusCode)
a.Info.iOpts.RequestLog.Status(ctx, statusCode)
klog.V(2).Infof("%s: %s <= st=%d", a.Info.log.origin, a.Name, statusCode)
rspsCounter.Inc(label0, label1, strconv.Itoa(statusCode))
if err != nil {
klog.Warningf("%s: %s handler error: %v", a.Info.Origin, a.Name, err)
klog.Warningf("%s: %s handler error: %v", a.Info.log.origin, a.Name, err)
a.Info.SendHTTPError(w, statusCode, err)
return
}

// Additional check, for consistency the handler must return an error for non-200 st
if statusCode != http.StatusOK {
klog.Warningf("%s: %s handler non 200 without error: %d %v", a.Info.Origin, a.Name, statusCode, err)
klog.Warningf("%s: %s handler non 200 without error: %d %v", a.Info.log.origin, a.Name, statusCode, err)
a.Info.SendHTTPError(w, http.StatusInternalServerError, fmt.Errorf("http handler misbehaved, st: %d", statusCode))
return
}
}

// logInfo holds information for a specific log instance.
type logInfo struct {
// Origin identifies the log, as per https://c2sp.org/static-ct-api
Origin string
// TimeSource is a TimeSource that can be injected for testing
TimeSource TimeSource
// RequestLog is a logger for various request / processing / response debug
// information.
RequestLog RequestLog

// maskInternalErrors controls whether to hide internal errors from clients
maskInternalErrors bool
// deadline is a timeout for HTTP requests.
deadline time.Duration
// validationOpts contains the certificate chain validation parameters.
validationOpts ChainValidationOpts
// storage stores log data.
storage Storage
// signSCT signs SCTs.
signSCT signSCT
log *log
iOpts *HandlerOptions
}

// HandlerOptions describes log handlers options.
Expand All @@ -186,44 +170,21 @@ type HandlerOptions struct {
TimeSource TimeSource
}

// newLogInfo creates a new instance of logInfo.
func newLogInfo(
hOpts HandlerOptions,
validationOpts ChainValidationOpts,
signSCT signSCT,
timeSource TimeSource,
storage Storage,
origin string,
) *logInfo {
func NewPathHandlers(opts *HandlerOptions, log *log) PathHandlers {
li := &logInfo{
Origin: origin,
storage: storage,
signSCT: signSCT,
TimeSource: timeSource,
maskInternalErrors: hOpts.MaskInternalErrors,
deadline: hOpts.Deadline,
validationOpts: validationOpts,
RequestLog: hOpts.RequestLog,
log: log,
iOpts: opts,
}

once.Do(func() { setupMetrics(hOpts.MetricFactory) })
knownLogs.Set(1.0, origin)
once.Do(func() { setupMetrics(opts.MetricFactory) })
knownLogs.Set(1.0, log.origin)

return li
}

func NewPathHandlers(opts *HandlerOptions, log *log) PathHandlers {
// TODO(phboneff): simplify signature of newLogInfo
logInfo := newLogInfo(*opts, log.chainValidationOpts, log.signSCT, opts.TimeSource, log.storage, log.origin)
return logInfo.Handlers(log.origin)
return li.Handlers(log.origin)
}

// Handlers returns a map from URL paths (with the given prefix) and AppHandler instances
// to handle those entrypoints.
func (li *logInfo) Handlers(prefix string) PathHandlers {
if !strings.HasPrefix(prefix, "/") {
prefix = "/" + prefix
}
prefix = strings.TrimRight(prefix, "/")

// Bind the logInfo instance to give an AppHandler instance for each endpoint.
Expand All @@ -239,7 +200,7 @@ func (li *logInfo) Handlers(prefix string) PathHandlers {
// SendHTTPError generates a custom error page to give more information on why something didn't work
func (li *logInfo) SendHTTPError(w http.ResponseWriter, statusCode int, err error) {
errorBody := http.StatusText(statusCode)
if !li.maskInternalErrors || statusCode != http.StatusInternalServerError {
if !li.iOpts.MaskInternalErrors || statusCode != http.StatusInternalServerError {
errorBody += fmt.Sprintf("\n%v", err)
}
http.Error(w, errorBody, statusCode)
Expand Down Expand Up @@ -281,45 +242,45 @@ func addChainInternal(ctx context.Context, li *logInfo, w http.ResponseWriter, r
// Check the contents of the request and convert to slice of certificates.
addChainReq, err := ParseBodyAsJSONChain(r)
if err != nil {
return http.StatusBadRequest, fmt.Errorf("%s: failed to parse add-chain body: %s", li.Origin, err)
return http.StatusBadRequest, fmt.Errorf("%s: failed to parse add-chain body: %s", li.log.origin, err)
}
// Log the DERs now because they might not parse as valid X.509.
for _, der := range addChainReq.Chain {
li.RequestLog.AddDERToChain(ctx, der)
li.iOpts.RequestLog.AddDERToChain(ctx, der)
}
chain, err := verifyAddChain(li, addChainReq, isPrecert)
if err != nil {
return http.StatusBadRequest, fmt.Errorf("failed to verify add-chain contents: %s", err)
}
for _, cert := range chain {
li.RequestLog.AddCertToChain(ctx, cert)
li.iOpts.RequestLog.AddCertToChain(ctx, cert)
}
// Get the current time in the form used throughout RFC6962, namely milliseconds since Unix
// epoch, and use this throughout.
timeMillis := uint64(li.TimeSource.Now().UnixNano() / nanosPerMilli)
timeMillis := uint64(li.iOpts.TimeSource.Now().UnixNano() / nanosPerMilli)

entry, err := entryFromChain(chain, isPrecert, timeMillis)
if err != nil {
return http.StatusBadRequest, fmt.Errorf("failed to build MerkleTreeLeaf: %s", err)
}

klog.V(2).Infof("%s: %s => storage.GetCertIndex", li.Origin, method)
sctDedupInfo, isDup, err := li.storage.GetCertDedupInfo(ctx, chain[0])
klog.V(2).Infof("%s: %s => storage.GetCertIndex", li.log.origin, method)
sctDedupInfo, isDup, err := li.log.storage.GetCertDedupInfo(ctx, chain[0])
idx := sctDedupInfo.Idx
if err != nil {
return http.StatusInternalServerError, fmt.Errorf("couldn't deduplicate the request: %s", err)
}

if isDup {
klog.V(3).Infof("%s: %s - found duplicate entry at index %d", li.Origin, method, idx)
klog.V(3).Infof("%s: %s - found duplicate entry at index %d", li.log.origin, method, idx)
entry.Timestamp = sctDedupInfo.Timestamp
} else {
if err := li.storage.AddIssuerChain(ctx, chain[1:]); err != nil {
if err := li.log.storage.AddIssuerChain(ctx, chain[1:]); err != nil {
return http.StatusInternalServerError, fmt.Errorf("failed to store issuer chain: %s", err)
}

klog.V(2).Infof("%s: %s => storage.Add", li.Origin, method)
idx, err = li.storage.Add(ctx, entry)()
klog.V(2).Infof("%s: %s => storage.Add", li.log.origin, method)
idx, err = li.log.storage.Add(ctx, entry)()
if err != nil {
if errors.Is(err, tessera.ErrPushback) {
w.Header().Add("Retry-After", "1")
Expand All @@ -330,8 +291,8 @@ func addChainInternal(ctx context.Context, li *logInfo, w http.ResponseWriter, r
// We store the index for this certificate in the deduplication storage immediately.
// It might be stored again later, if a local deduplication storage is synced, potentially
// with a smaller value.
klog.V(2).Infof("%s: %s => storage.AddCertIndex", li.Origin, method)
err = li.storage.AddCertDedupInfo(ctx, chain[0], dedup.SCTDedupInfo{Idx: idx, Timestamp: entry.Timestamp})
klog.V(2).Infof("%s: %s => storage.AddCertIndex", li.log.origin, method)
err = li.log.storage.AddCertDedupInfo(ctx, chain[0], dedup.SCTDedupInfo{Idx: idx, Timestamp: entry.Timestamp})
// TODO: block log writes if deduplication breaks
if err != nil {
klog.Warningf("AddCertIndex(): failed to store certificate index: %v", err)
Expand All @@ -350,7 +311,7 @@ func addChainInternal(ctx context.Context, li *logInfo, w http.ResponseWriter, r
// As the Log server has definitely got the Merkle tree leaf, we can
// generate an SCT and respond with it.
// TODO(phboneff): this should work, but double check
sct, err := li.signSCT(&loggedLeaf)
sct, err := li.log.signSCT(&loggedLeaf)
if err != nil {
return http.StatusInternalServerError, fmt.Errorf("failed to generate SCT: %s", err)
}
Expand All @@ -359,15 +320,15 @@ func addChainInternal(ctx context.Context, li *logInfo, w http.ResponseWriter, r
return http.StatusInternalServerError, fmt.Errorf("failed to marshall SCT: %s", err)
}
// We could possibly fail to issue the SCT after this but it's v. unlikely.
li.RequestLog.IssueSCT(ctx, sctBytes)
li.iOpts.RequestLog.IssueSCT(ctx, sctBytes)
err = marshalAndWriteAddChainResponse(sct, w)
if err != nil {
// reason is logged and http status is already set
return http.StatusInternalServerError, fmt.Errorf("failed to write response: %s", err)
}
klog.V(3).Infof("%s: %s <= SCT", li.Origin, method)
klog.V(3).Infof("%s: %s <= SCT", li.log.origin, method)
if sct.Timestamp == timeMillis {
lastSCTTimestamp.Set(float64(sct.Timestamp), li.Origin)
lastSCTTimestamp.Set(float64(sct.Timestamp), li.log.origin)
}

return http.StatusOK, nil
Expand All @@ -383,8 +344,8 @@ func addPreChain(ctx context.Context, li *logInfo, w http.ResponseWriter, r *htt

func getRoots(_ context.Context, li *logInfo, w http.ResponseWriter, _ *http.Request) (int, error) {
// Pull out the raw certificates from the parsed versions
rawCerts := make([][]byte, 0, len(li.validationOpts.trustedRoots.RawCertificates()))
for _, cert := range li.validationOpts.trustedRoots.RawCertificates() {
rawCerts := make([][]byte, 0, len(li.log.chainValidationOpts.trustedRoots.RawCertificates()))
for _, cert := range li.log.chainValidationOpts.trustedRoots.RawCertificates() {
rawCerts = append(rawCerts, cert.Raw)
}

Expand All @@ -393,7 +354,7 @@ func getRoots(_ context.Context, li *logInfo, w http.ResponseWriter, _ *http.Req
enc := json.NewEncoder(w)
err := enc.Encode(jsonMap)
if err != nil {
klog.Warningf("%s: get_roots failed: %v", li.Origin, err)
klog.Warningf("%s: get_roots failed: %v", li.log.origin, err)
return http.StatusInternalServerError, fmt.Errorf("get-roots failed with: %s", err)
}

Expand All @@ -402,14 +363,14 @@ func getRoots(_ context.Context, li *logInfo, w http.ResponseWriter, _ *http.Req

// deadlineTime calculates the future time a request should expire based on our config.
func deadlineTime(li *logInfo) time.Time {
return li.TimeSource.Now().Add(li.deadline)
return li.iOpts.TimeSource.Now().Add(li.iOpts.Deadline)
}

// verifyAddChain is used by add-chain and add-pre-chain. It does the checks that the supplied
// cert is of the correct type and chains to a trusted root.
func verifyAddChain(li *logInfo, req ct.AddChainRequest, expectingPrecert bool) ([]*x509.Certificate, error) {
// We already checked that the chain is not empty so can move on to verification
validPath, err := validateChain(req.Chain, li.validationOpts)
validPath, err := validateChain(req.Chain, li.log.chainValidationOpts)
if err != nil {
// We rejected it because the cert failed checks or we could not find a path to a root etc.
// Lots of possible causes for errors
Expand All @@ -424,9 +385,9 @@ func verifyAddChain(li *logInfo, req ct.AddChainRequest, expectingPrecert bool)
// The type of the leaf must match the one the handler expects
if isPrecert != expectingPrecert {
if expectingPrecert {
klog.Warningf("%s: Cert (or precert with invalid CT ext) submitted as precert chain: %q", li.Origin, req.Chain)
klog.Warningf("%s: Cert (or precert with invalid CT ext) submitted as precert chain: %q", li.log.origin, req.Chain)
} else {
klog.Warningf("%s: Precert (or cert with invalid CT ext) submitted as cert chain: %q", li.Origin, req.Chain)
klog.Warningf("%s: Precert (or cert with invalid CT ext) submitted as cert chain: %q", li.log.origin, req.Chain)
}
return nil, fmt.Errorf("cert / precert mismatch: %T", expectingPrecert)
}
Expand Down
Loading

0 comments on commit 6ecc832

Please sign in to comment.