Skip to content

Commit

Permalink
Add logOperationResult to API handler
Browse files Browse the repository at this point in the history
This is prefixed with the request ID, just like the response logs
generated by logApiResponse. This means we can see both internally what
happened to any given operation, and tie it to the HTTP response we sent
back.
  • Loading branch information
mbland committed Apr 4, 2023
1 parent 31b143d commit 03b99d4
Show file tree
Hide file tree
Showing 2 changed files with 78 additions and 9 deletions.
17 changes: 15 additions & 2 deletions handler/api.go
Original file line number Diff line number Diff line change
Expand Up @@ -210,7 +210,7 @@ func (h *apiHandler) handleApiRequest(

if op, err := parseApiRequest(req); err != nil {
return h.respondToParseError(res, err)
} else if result, err := h.performOperation(op); err != nil {
} else if result, err := h.performOperation(req.RequestId, op); err != nil {
return nil, err
} else if op.OneClick {
res.StatusCode = http.StatusOK
Expand Down Expand Up @@ -245,7 +245,7 @@ func (h *apiHandler) respondToParseError(
}

func (h *apiHandler) performOperation(
op *eventOperation,
requestId string, op *eventOperation,
) (result ops.OperationResult, err error) {
switch op.Type {
case SubscribeOp:
Expand All @@ -257,9 +257,22 @@ func (h *apiHandler) performOperation(
default:
err = fmt.Errorf("can't handle operation type: %s", op.Type)
}
logOperationResult(requestId, op, result, err)

if opErr, ok := err.(*ops.OperationErrorExternal); ok {
err = &errorWithStatus{http.StatusBadGateway, opErr.Error()}
}
return result, err
}

func logOperationResult(
requestId string, op *eventOperation, result ops.OperationResult, err error,
) {
prefix := "result"
errMsg := ""
if err != nil {
prefix = "ERROR"
errMsg = ": " + err.Error()
}
log.Printf("%s: %s: %s: %s%s", requestId, prefix, op, result, errMsg)
}
70 changes: 63 additions & 7 deletions handler/api_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -296,63 +296,119 @@ func TestRespondToParseError(t *testing.T) {
})
}

func TestLogOperationResult(t *testing.T) {
op := &eventOperation{
Type: VerifyOp, Email: "mbland@acm.org", Uid: testValidUid,
}
logs, teardown := captureLogs()
defer teardown()

t.Run("SuccessfulResult", func(t *testing.T) {
defer logs.Reset()

logOperationResult("deadbeef", op, ops.Subscribed, nil)

expected := "deadbeef: result: Verify: mbland@acm.org " +
testValidUidStr + ": Subscribed"
assert.Assert(t, is.Contains(logs.String(), expected))
})

t.Run("SuccessfulResult", func(t *testing.T) {
defer logs.Reset()

logOperationResult(
"deadbeef", op, ops.Subscribed, errors.New("whoops..."),
)

expected := "deadbeef: ERROR: Verify: mbland@acm.org " +
testValidUidStr + ": Subscribed: whoops..."
assert.Assert(t, is.Contains(logs.String(), expected))
})
}

func TestPerformOperation(t *testing.T) {
logs, teardown := captureLogs()
defer teardown()

t.Run("SubscribeSucceeds", func(t *testing.T) {
defer logs.Reset()
f := newApiHandlerFixture()
f.agent.ReturnValue = ops.VerifyLinkSent

result, err := f.handler.performOperation(
"deadbeef",
&eventOperation{Type: SubscribeOp, Email: "mbland@acm.org"},
)

assert.NilError(t, err)
assert.Equal(t, ops.VerifyLinkSent, result)
expectedLog := "deadbeef: result: Subscribe"
assert.Assert(t, is.Contains(logs.String(), expectedLog))
})

t.Run("VerifySucceeds", func(t *testing.T) {
defer logs.Reset()
f := newApiHandlerFixture()
f.agent.ReturnValue = ops.Subscribed

result, err := f.handler.performOperation(&eventOperation{
Type: VerifyOp, Email: "mbland@acm.org", Uid: testValidUid,
})
result, err := f.handler.performOperation(
"deadbeef",
&eventOperation{
Type: VerifyOp, Email: "mbland@acm.org", Uid: testValidUid,
},
)

assert.NilError(t, err)
assert.Equal(t, ops.Subscribed, result)
assert.Assert(t, is.Contains(logs.String(), "deadbeef: result: Verify"))
})

t.Run("UnsubscribeSucceeds", func(t *testing.T) {
defer logs.Reset()
f := newApiHandlerFixture()
f.agent.ReturnValue = ops.Unsubscribed

result, err := f.handler.performOperation(&eventOperation{
Type: UnsubscribeOp, Email: "mbland@acm.org", Uid: testValidUid,
})
result, err := f.handler.performOperation(
"deadbeef",
&eventOperation{
Type: UnsubscribeOp, Email: "mbland@acm.org", Uid: testValidUid,
},
)

assert.NilError(t, err)
assert.Equal(t, ops.Unsubscribed, result)
expectedLog := "deadbeef: result: Unsubscribe"
assert.Assert(t, is.Contains(logs.String(), expectedLog))
})

t.Run("RaisesErrorIfCantHandleOpType", func(t *testing.T) {
defer logs.Reset()
f := newApiHandlerFixture()

result, err := f.handler.performOperation(&eventOperation{})
result, err := f.handler.performOperation("deadbeef", &eventOperation{})

assert.Equal(t, ops.Invalid, result)
assert.ErrorContains(t, err, "can't handle operation type: Undefined")
expectedLog := "deadbeef: ERROR: Undefined: Invalid: can't handle"
assert.Assert(t, is.Contains(logs.String(), expectedLog))
})

t.Run("SetsErrorWithStatusIfExternalOpError", func(t *testing.T) {
defer logs.Reset()
f := newApiHandlerFixture()
f.agent.Error = &ops.OperationErrorExternal{Message: "not our fault..."}

result, err := f.handler.performOperation(
"deadbeef",
&eventOperation{Type: SubscribeOp, Email: "mbland@acm.org"},
)

assert.Equal(t, ops.Invalid, result)
expected := &errorWithStatus{http.StatusBadGateway, "not our fault..."}
assert.DeepEqual(t, err, expected)
expectedLog := "deadbeef: ERROR: Subscribe: mbland@acm.org: " +
"Invalid: not our fault..."
assert.Assert(t, is.Contains(logs.String(), expectedLog))
})
}

Expand Down

0 comments on commit 03b99d4

Please sign in to comment.