Skip to content

Commit 31a148e

Browse files
mitalirawatmitalirawat
authored
Merge pull request #468 from cloudflare/mitali/print-client-info
Add a new field to Operation and log client info from connection
2 parents 78e8c53 + 19e29ea commit 31a148e

File tree

4 files changed

+81
-33
lines changed

4 files changed

+81
-33
lines changed

‎Makefile‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -127,5 +127,5 @@ snapshot:
127127
docker run --rm --privileged -v $(PWD):/go/tmp \
128128
-v /var/run/docker.sock:/var/run/docker.sock \
129129
-w /go/tmp \
130-
ghcr.io/goreleaser/goreleaser-cross:latest --clean --snapshot --skip-publish
130+
ghcr.io/goreleaser/goreleaser-cross:latest --clean --snapshot --skip publish
131131

‎protocol/protocol.go‎

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -414,19 +414,21 @@ type Operation struct {
414414
ServerIP net.IP
415415
SNI string
416416
CertID string
417+
ForwardingSvc int64
417418
CustomFuncName string
418419
JaegerSpan []byte
419420
ReqContext []byte
420421
}
421422

422423
func (o *Operation) String() string {
423-
return fmt.Sprintf("[Opcode: %v, SKI: %v, Digest: %02x, Client IP: %s, Server IP: %s, SNI: %s]",
424+
return fmt.Sprintf("[Opcode: %v, SKI: %v, Digest: %02x, Client IP: %s, Server IP: %s, SNI: %s, Forwarding Service: %v]",
424425
o.Opcode,
425426
o.SKI,
426427
o.Digest,
427428
o.ClientIP,
428429
o.ServerIP,
429430
o.SNI,
431+
o.ForwardingSvc,
430432
)
431433
}
432434

‎server/server.go‎

Lines changed: 76 additions & 31 deletions
Original file line numberDiff line numberDiff line change
@@ -16,6 +16,7 @@ import (
1616
"net"
1717
"net/rpc"
1818
"os"
19+
"strings"
1920
"sync"
2021
"time"
2122

@@ -152,6 +153,12 @@ type Sealer interface {
152153
Unseal(*protocol.Operation) ([]byte, error)
153154
}
154155

156+
// ClientInfo has information on the client of the connection
157+
type ClientInfo struct {
158+
Name string
159+
CertSerial string
160+
}
161+
155162
// handler is associated with a connection and contains bookkeeping
156163
// information used across goroutines. The channel tokens limits the
157164
// concurrency: before reading a request a token is extracted, when
@@ -166,6 +173,7 @@ type handler struct {
166173
conn net.Conn
167174
timeout time.Duration
168175
closed bool
176+
c *ClientInfo
169177
}
170178

171179
func (h *handler) close(err error) {
@@ -197,6 +205,12 @@ func (h *handler) handle(pkt *protocol.Packet, reqTime time.Time) {
197205
} else {
198206
resp = h.s.unlimitedDo(pkt, h.name)
199207
}
208+
209+
if resp.op.ErrorVal() != protocol.ErrNone {
210+
// log the client certificate information on the connection if the request failed so the caller is apparent
211+
reqID, _ := getOperationRequestID(&pkt.Operation)
212+
log.Errorf("operation from client %s client cert serial: %s errored. sni %s ski %s cert %s request-id %s", h.c.Name, h.c.CertSerial, resp.op.SNI, resp.op.SKI.String(), resp.op.CertID, reqID)
213+
}
200214
logRequestExecDuration(pkt.Operation.Opcode, start, resp.op.ErrorVal())
201215
respPkt := protocol.Packet{
202216
Header: protocol.Header{
@@ -289,32 +303,61 @@ func makeErrResponse(pkt *protocol.Packet, err protocol.Error) response {
289303
func addOperationRequestID(op *protocol.Operation) string {
290304
reqContext := make(map[string]interface{})
291305
var reqID string
292-
var gen bool
293306

294307
if len(op.ReqContext) > 0 {
295-
if err := json.Unmarshal(op.ReqContext, &reqContext); err == nil {
296-
if v, ok := reqContext["request_id"]; ok {
297-
return v.(string)
298-
} else {
299-
gen = true
300-
}
301-
} else {
302-
log.Errorf("malformed operation.ReqContext %v, ignoring error", op.ReqContext)
308+
if decodeErr := json.Unmarshal(op.ReqContext, &reqContext); decodeErr != nil {
309+
log.Error(fmt.Errorf("malformed operation.ReqContext %v, ignoring error", op.ReqContext))
310+
return reqID
311+
}
312+
}
313+
314+
if v, ok := reqContext["request_id"]; ok {
315+
return v.(string)
316+
}
317+
318+
reqID = uuid.New().String()
319+
reqContext["request_id"] = reqID
320+
b, err := json.Marshal(reqContext)
321+
if err == nil {
322+
op.ReqContext = b
323+
} else {
324+
log.Errorf("error marshaling operation.ReqContext %v, ignoring error", reqContext)
325+
reqID = ""
326+
}
327+
return reqID
328+
}
329+
330+
func getOperationRequestID(op *protocol.Operation) (reqID string, err error) {
331+
reqContext := make(map[string]interface{})
332+
if len(op.ReqContext) == 0 {
333+
return
334+
}
335+
if decodeErr := json.Unmarshal(op.ReqContext, &reqContext); decodeErr == nil {
336+
if v, ok := reqContext["request_id"]; ok {
337+
return v.(string), nil
303338
}
339+
} else {
340+
err = fmt.Errorf("malformed operation.ReqContext %v, ignoring error", op.ReqContext)
341+
log.Error(err)
342+
return
304343
}
344+
return
345+
}
305346

306-
if len(op.ReqContext) == 0 || gen {
307-
reqID = uuid.New().String()
308-
reqContext["request_id"] = reqID
309-
b, err := json.Marshal(reqContext)
310-
if err == nil {
311-
op.ReqContext = b
347+
func getClientInfoFromCerts(certs []*x509.Certificate) *ClientInfo {
348+
cln := []string(nil)
349+
srls := []string(nil)
350+
for _, cert := range certs {
351+
if cert.Subject.CommonName != "" {
352+
cln = append(cln, cert.Subject.CommonName)
312353
} else {
313-
log.Errorf("error marshaling operation.ReqContext %v, ignoring error", reqContext)
314-
reqID = ""
354+
cln = append(cln, cert.DNSNames...)
315355
}
356+
srls = append(srls, cert.SerialNumber.String())
316357
}
317-
return reqID
358+
name := strings.Join(cln, " , ")
359+
serial := strings.Join(srls, " , ")
360+
return &ClientInfo{Name: name, CertSerial: serial}
318361
}
319362

320363
func (s *Server) unlimitedDo(pkt *protocol.Packet, connName string) response {
@@ -328,7 +371,7 @@ func (s *Server) unlimitedDo(pkt *protocol.Packet, connName string) response {
328371
reqID := addOperationRequestID(&pkt.Operation)
329372
span.SetTag("request_id", reqID)
330373

331-
log.Debugf("connection %s: limited=false opcode=%s id=%d sni=%s ip=%s ski=%v request-id=%s",
374+
log.Debugf("connection %s: limited=false opcode= %s id=%d sni= %s ip= %s ski= %v request-id= %s",
332375
connName,
333376
pkt.Operation.Opcode,
334377
pkt.Header.ID,
@@ -412,14 +455,14 @@ func (s *Server) unlimitedDo(pkt *protocol.Packet, connName string) response {
412455

413456
sig, err := key.Sign(rand.Reader, pkt.Operation.Payload, crypto.Hash(0))
414457
if err != nil {
415-
log.Errorf("Connection: %s: sni=%s ski=%v request-id=%s: Signing error: %v: request-id:%s:", connName, pkt.Operation.SNI, pkt.Operation.SKI, reqID, protocol.ErrCrypto, err, reqID)
458+
log.Errorf("Connection: %s: sni= %s ski= %v request-id= %s: Signing error: %v", connName, pkt.Operation.SNI, pkt.Operation.SKI, reqID, protocol.ErrCrypto, err)
416459
// This indicates that a remote keyserver is being used
417460
var remoteConfigurationErr RemoteConfigurationErr
418461
if errors.As(err, &remoteConfigurationErr) {
419-
log.Errorf("Connection %v: sni=%s ski=%v request-id=%s: %s: Signing error: %v request-id:%s\n", connName, pkt.Operation.SNI, pkt.Operation.SKI, reqID, protocol.ErrRemoteConfiguration, err, reqID)
462+
log.Errorf("Connection %v: sni= %s ski= %v request-id= %s: %s: Signing error: %v\n", connName, pkt.Operation.SNI, pkt.Operation.SKI, reqID, protocol.ErrRemoteConfiguration, err)
420463
return makeErrResponse(pkt, protocol.ErrRemoteConfiguration)
421464
} else {
422-
log.Errorf("Connection %v: sni=%s ski=%v request-id=%s: %s: Signing error: %v request-id:%s\n", connName, pkt.Operation.SNI, pkt.Operation.SKI, reqID, protocol.ErrCrypto, err, reqID)
465+
log.Errorf("Connection %v: sni= %s ski= %v request-id= %s: %s: Signing error: %v\n", connName, pkt.Operation.SNI, pkt.Operation.SKI, reqID, protocol.ErrCrypto, err)
423466
return makeErrResponse(pkt, protocol.ErrCrypto)
424467
}
425468
}
@@ -430,23 +473,23 @@ func (s *Server) unlimitedDo(pkt *protocol.Packet, connName string) response {
430473
key, err := s.keys.Get(ctx, &pkt.Operation)
431474
logKeyLoadDuration(loadStart)
432475
if err != nil {
433-
log.Errorf("failed to load key with sni=%s ip=%s ski=%v request-id=%s: %v", pkt.Operation.SNI, pkt.Operation.ServerIP, pkt.Operation.SKI, reqID, err)
476+
log.Errorf("failed to load key with sni= %s ip= %s ski=%v request-id= %s: %v", pkt.Operation.SNI, pkt.Operation.ServerIP, pkt.Operation.SKI, reqID, err)
434477
return makeErrResponse(pkt, protocol.ErrInternal)
435478
} else if key == nil {
436-
log.Errorf("failed to load key with sni=%s ip=%s ski=%v request-id=%s: %v", pkt.Operation.SNI, pkt.Operation.ServerIP, pkt.Operation.SKI, reqID, protocol.ErrKeyNotFound)
479+
log.Errorf("failed to load key with sni= %s ip= %s ski= %v request-id= %s: %v", pkt.Operation.SNI, pkt.Operation.ServerIP, pkt.Operation.SKI, reqID, protocol.ErrKeyNotFound)
437480
return makeErrResponse(pkt, protocol.ErrKeyNotFound)
438481
}
439482

440483
if _, ok := key.Public().(*rsa.PublicKey); !ok {
441-
log.Errorf("Connection %v: sni=%s request-id=%s: %s: Key is not RSA", connName, pkt.Operation.SNI, reqID, protocol.ErrCrypto)
484+
log.Errorf("Connection %v: sni= %s request-id= %s: %s: Key is not RSA", connName, pkt.Operation.SNI, reqID, protocol.ErrCrypto)
442485
return makeErrResponse(pkt, protocol.ErrCrypto)
443486
}
444487

445488
if rsaKey, ok := key.(*rsa.PrivateKey); ok {
446489
// Decrypt without removing padding; that's the client's responsibility.
447490
ptxt, err := textbook_rsa.Decrypt(rsaKey, pkt.Operation.Payload)
448491
if err != nil {
449-
log.Errorf("connection %v: sni=%s ip=%s ski=%v request-id=%s: %v", connName, pkt.Operation.SNI, pkt.Operation.ServerIP, pkt.Operation.SKI, reqID, err)
492+
log.Errorf("connection %v: sni= %s ip= %s ski= %v request-id= %s: %v", connName, pkt.Operation.SNI, pkt.Operation.ServerIP, pkt.Operation.SKI, reqID, err)
450493
return makeErrResponse(pkt, protocol.ErrCrypto)
451494
}
452495
return makeRespondResponse(pkt, ptxt)
@@ -493,10 +536,10 @@ func (s *Server) unlimitedDo(pkt *protocol.Packet, connName string) response {
493536
key, err := s.keys.Get(ctx, &pkt.Operation)
494537
logKeyLoadDuration(loadStart)
495538
if err != nil {
496-
log.Errorf("failed to load key with sni=%s ip=%s ski=%v request-id=%s: %v", pkt.Operation.SNI, pkt.Operation.ServerIP, pkt.Operation.SKI, reqID, err)
539+
log.Errorf("failed to load key with sni= %s ip= %s ski= %v request-id= %s: %v", pkt.Operation.SNI, pkt.Operation.ServerIP, pkt.Operation.SKI, reqID, err)
497540
return makeErrResponse(pkt, protocol.ErrInternal)
498541
} else if key == nil {
499-
log.Errorf("failed to load key with sni=%s ip=%s ski=%v request-id=%s: %v", pkt.Operation.SNI, pkt.Operation.ServerIP, pkt.Operation.SKI, reqID, protocol.ErrKeyNotFound)
542+
log.Errorf("failed to load key with sni= %s ip= %s ski= %v request-id= %s: %v", pkt.Operation.SNI, pkt.Operation.ServerIP, pkt.Operation.SKI, reqID, protocol.ErrKeyNotFound)
500543
return makeErrResponse(pkt, protocol.ErrKeyNotFound)
501544
}
502545

@@ -526,17 +569,17 @@ func (s *Server) unlimitedDo(pkt *protocol.Packet, connName string) response {
526569
}
527570
if err != nil {
528571
if attempts > 1 {
529-
log.Debugf("Connection %v sni=%s ip=%s ski=%v request-id=%s : failed sign attempt: %s, %d attempt(s) left", connName, pkt.Operation.SNI, pkt.Operation.ServerIP, pkt.Operation.SKI, reqID, err, attempts-1)
572+
log.Debugf("Connection %v sni= %s ip= %s ski= %v request-id= %s : failed sign attempt: %s, %d attempt(s) left", connName, pkt.Operation.SNI, pkt.Operation.ServerIP, pkt.Operation.SKI, reqID, err, attempts-1)
530573
continue
531574
} else {
532575
tracing.LogError(span, err)
533576
// This indicates that a remote keyserver is being used
534577
var remoteConfigurationErr RemoteConfigurationErr
535578
if errors.As(err, &remoteConfigurationErr) {
536-
log.Errorf("Connection %v sni=%s ip=%s ski=%v request-id=%s : %s: Signing error: %v\n", connName, pkt.Operation.SNI, pkt.Operation.ServerIP, pkt.Operation.SKI, reqID, protocol.ErrRemoteConfiguration, err)
579+
log.Errorf("Connection %v sni= %s ip= %s ski= %v request-id= %s : %s: Signing error: %v\n", connName, pkt.Operation.SNI, pkt.Operation.ServerIP, pkt.Operation.SKI, reqID, protocol.ErrRemoteConfiguration, err)
537580
return makeErrResponse(pkt, protocol.ErrRemoteConfiguration)
538581
} else {
539-
log.Errorf("Connection %v sni=%s ip=%s ski=%v request-id=%s : %s: Signing error: %v\n", connName, pkt.Operation.SNI, pkt.Operation.ServerIP, pkt.Operation.SKI, reqID, protocol.ErrCrypto, err)
582+
log.Errorf("Connection %v sni= %s ip= %s ski= %v request-id= %s : %s: Signing error: %v\n", connName, pkt.Operation.SNI, pkt.Operation.ServerIP, pkt.Operation.SKI, reqID, protocol.ErrCrypto, err)
540583
return makeErrResponse(pkt, protocol.ErrCrypto)
541584
}
542585
}
@@ -656,6 +699,7 @@ func (s *Server) spawn(l net.Listener, c net.Conn) {
656699
}
657700
connState := tconn.ConnectionState()
658701
certmetrics.Observe(certmetrics.CertSourceFromCerts(fmt.Sprintf("listener: %s", l.Addr().String()), connState.PeerCertificates)...)
702+
cl := getClientInfoFromCerts(connState.PeerCertificates)
659703
limited, err := s.config.isLimited(connState)
660704
if err != nil {
661705
log.Errorf("connection %v: could not determine if limited: %v", c.RemoteAddr(), err)
@@ -692,6 +736,7 @@ func (s *Server) spawn(l net.Listener, c net.Conn) {
692736
conn: tconn,
693737
listener: l,
694738
timeout: timeout,
739+
c: cl,
695740
}
696741
err = handler.loop()
697742

‎tracing/tracing.go‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -47,6 +47,7 @@ func SetOperationSpanTags(span opentracing.Span, op *protocol.Operation) {
4747
"operation.sni": op.SNI,
4848
"operation.certid": op.CertID,
4949
"operation.customfuncname": op.CustomFuncName,
50+
"operation.forwardingsvc": fmt.Sprintf("%d", op.ForwardingSvc),
5051
}
5152
for k, v := range tags {
5253
span.SetTag(k, v)

0 commit comments

Comments
 (0)