Skip to content

Commit

Permalink
job logging refinements (#647)
Browse files Browse the repository at this point in the history 
* pass dummy client response for job 'endpoint' in order to avoid 'missing client response' error leading to ERROR log entry in job log

* rename log type 'job' -> 'couper_job' to be consistent with other log types

* document log type 'couper_job'

* md table 'format'

* log error and error type for failed job
  • Loading branch information
@johakoch
johakoch committed Dec 20, 2022
1 parent df9b1c3 commit 5dd027b
Show file tree
Hide file tree
Showing 8 changed files with 70 additions and 20 deletions.
1 change: 1 addition & 0 deletions config/runtime/server.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -133,6 +133,7 @@ func NewServerConfiguration(conf *config.Couper, log *logrus.Entry, memStore *ca
return nil, err
}

endpointOptions.IsJob = true
epHandler := handler.NewEndpoint(endpointOptions, log, nil)

j := definitions.NewJob(job, epHandler, conf.Settings)
Expand Down
10 changes: 9 additions & 1 deletion definitions/job.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -10,6 +10,7 @@ import (

"github.com/avenga/couper/config"
"github.com/avenga/couper/config/request"
"github.com/avenga/couper/errors"
"github.com/avenga/couper/eval"
"github.com/avenga/couper/handler/middleware"
"github.com/avenga/couper/logging"
Expand All @@ -32,7 +33,7 @@ func (j Jobs) Run(ctx context.Context, log *logrus.Entry) {
}

logEntry := log.WithContext(ctx)
logEntry.Data["type"] = "job"
logEntry.Data["type"] = "couper_job"

for _, job := range j {
go job.Run(ctx, logEntry)
Expand Down Expand Up @@ -107,6 +108,13 @@ func run(req *http.Request, h http.Handler, log *logrus.Entry) {
h.ServeHTTP(w, req)

if w.StatusCode() == 0 || w.StatusCode() > 499 {
if ctxErr, ok := req.Context().Value(request.Error).(*errors.Error); ok {
if len(ctxErr.Kinds()) > 0 {
log = log.WithFields(logrus.Fields{"error_type": ctxErr.Kinds()[0]})
}
log.Error(ctxErr.Error())
return
}
log.Error()
return
}
Expand Down
37 changes: 26 additions & 11 deletions docs/website/content/3.observation/logging.md
View file
Original file line number Diff line number Diff line change
Expand Up @@ -14,6 +14,7 @@ Upon the execution of Couper all log events are sent to the standard output. You
| `couper_access_tls` | Provides information about connections via configured [https_dev_proxy](/configuration/block/settings). Compare [Access Fields](#access-fields). |
| `couper_backend` | Provides information about the backend side of things. Compare [Backend Fields](#backend-fields). |
| `couper_daemon` | Provides background information about the execution of Couper. Each printed log of this type contains a `message` entry describing the current actions of Couper. Compare [Daemon Fields](#daemon-fields). |
| `couper_job` | Provides information about [jobs](/configuration/block/job). See [Job Fields](#job-fields). |

## Fields

Expand Down Expand Up @@ -64,7 +65,7 @@ These fields are found in the [Log Types](#log-types) `couper_access` and `coupe
| | `}` | |
| `"server"` | | server name (defined in couper file) |
| `"status"` | | response status code, see [Mozilla HTTP Reference](https://developer.mozilla.org/en-US/docs/Web/HTTP/Status) for more information |
| `"timings":` | | field regarding timing |
| `"timings":` | | field regarding timing [ms] |
| | `{` | |
| | `"total"` | total time taken |
| | `}` | |
Expand Down Expand Up @@ -101,7 +102,7 @@ These fields are found in the [Log Type](#log-types) `couper_backend` in additio
| | `"status"` | response status code, see [Mozilla HTTP Reference](https://developer.mozilla.org/en-US/docs/Web/HTTP/Status) for more information |
| | `}` | |
| `"status"` | | response status code, see [Mozilla HTTP Reference](https://developer.mozilla.org/en-US/docs/Web/HTTP/Status) for more information |
| `"timings":` | | field regarding timing |
| `"timings":` | | field regarding timing [ms] |
| | `{` | |
| | `"dns"` | time taken by dns |
| | `"tcp"` | time taken between attempting and establishing tcp connection |
Expand All @@ -113,21 +114,35 @@ These fields are found in the [Log Type](#log-types) `couper_backend` in additio
| `"token_request_retry"` | | how many `token_request` attempts were made |
| `"uid"` | | unique request id configurable in [Settings](/configuration/block/settings) |
| `"url"` | | complete url (`<proto>://<host>:<port><path>` or `<origin><path>`) |
| `"validation"` | | validation result for open api, see [OpenAPI Block](/configuration/block/open-api) |
| `"validation"` | | validation result for open api, see [OpenAPI Block](/configuration/block/open-api) |

### Daemon Fields

These fields are found in the [Log Type](#log-types) `couper_daemon` in addition to the [Common Fields](#common-fields).

| Name | | Description |
|:-------------|:----------------|:---------------------------------------------------------------------------------------------------------------------------|
| `"deadline"` | | shutdown parameter, see [Health Check](/observation/health) |
| `"delay"` | | shutdown parameter, see [Health Check](/observation/health) |
| Name | | Description |
|:-------------|:----------------|:-----------------------------------------------------------------------------------------------------------------------------------------------|
| `"deadline"` | | shutdown parameter, see [Health Check](/observation/health) |
| `"delay"` | | shutdown parameter, see [Health Check](/observation/health) |
| `"watch":` | | field watching configuration file changes, logs with this field only appear if `watch=true`, more in [Settings](/configuration/block/settings) |
| | `{` | |
| | `"max-retries"` | maximum retry count, see [Global Options](/configuration/command-line#global-options) |
| | `"retry-delay"` | configured delay of each retry, see [Global Options](/configuration/command-line#global-options) |
| | `}` | |
| | `{` | |
| | `"max-retries"` | maximum retry count, see [Global Options](/configuration/command-line#global-options) |
| | `"retry-delay"` | configured delay of each retry, see [Global Options](/configuration/command-line#global-options) |
| | `}` | |

## Job Fields

The following fields are found in the [log type](#log-types) `couper_daemon` in addition to the [common fields](#common-fields).

| Name | | Description |
|:-------------|:-------------|:-------------------------------------------------------------------------------|
| `"name"` | | job name, label of [`beta_job` block](/configuration/block/job) |
| `"timings":` | | field regarding timing [ms] |
| | `{` | |
| | `"interval"` | interval, see [`interval` attribute](/configuration/block/job#attributes) |
| | `"total"` | total time taken |
| | `}` | |
| `“uid"` | | unique request id configurable in [settings](/configuration/block/settings) |

## Custom Logging

Expand Down
3 changes: 3 additions & 0 deletions handler/endpoint.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -38,6 +38,7 @@ type EndpointOptions struct {
ErrorTemplate *errors.Template
ErrorHandler http.Handler
IsErrorHandler bool
IsJob bool
LogHandlerKind string
LogPattern string
ReqBodyLimit int64
Expand Down Expand Up @@ -116,6 +117,8 @@ func (e *Endpoint) ServeHTTP(rw http.ResponseWriter, req *http.Request) {
// assume configured priority, prefer redirect to response and default ones
if e.opts.Redirect != nil {
clientres = e.newRedirect()
} else if e.opts.IsJob {
clientres = &http.Response{StatusCode: http.StatusOK}
} else if e.opts.Response != nil {
_, span := telemetry.NewSpanFromContext(subCtx, "response", trace.WithSpanKind(trace.SpanKindProducer))
defer span.End()
Expand Down
2 changes: 1 addition & 1 deletion logging/hooks/custom_logs.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -41,7 +41,7 @@ func (c *CustomLogs) Fire(entry *logrus.Entry) error {
if entry.Context != nil {
if t, exists := entry.Data["type"]; exists {
switch t {
case "job":
case "couper_job":
fallthrough
case acTypeField:
fireAccess(entry)
Expand Down
21 changes: 16 additions & 5 deletions server/http_definitions_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -25,14 +25,16 @@ func TestDefinitions_Jobs(t *testing.T) {
origin http.Handler
wantErr bool
wantFields logrus.Fields
wantLevel logrus.Level
wantMsg string
}

const basePath = "testdata/definitions"

for _, tc := range []testcase{
{"without label", "01_job.hcl", http.HandlerFunc(nil), true, nil},
{"without interval", "02_job.hcl", http.HandlerFunc(nil), true, nil},
{"with negative interval", "03_job.hcl", http.HandlerFunc(nil), true, nil},
{"without label", "01_job.hcl", http.HandlerFunc(nil), true, nil, logrus.InfoLevel, ""}, // wantLevel not used
{"without interval", "02_job.hcl", http.HandlerFunc(nil), true, nil, logrus.InfoLevel, ""}, // wantLevel not used
{"with negative interval", "03_job.hcl", http.HandlerFunc(nil), true, nil, logrus.InfoLevel, ""}, // wantLevel not used
{"variable reference", "04_job.hcl", http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) {
payload := map[string]string{
"prop1": "val1",
Expand All @@ -55,7 +57,10 @@ func TestDefinitions_Jobs(t *testing.T) {
}), false, logrus.Fields{"custom": logrus.Fields{
"status_a": float64(http.StatusOK),
"status_b": float64(http.StatusOK),
}}},
}}, logrus.InfoLevel, ""},
{"unexpected status", "05_job.hcl", http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) {
w.WriteHeader(http.StatusOK)
}), false, logrus.Fields{"error_type": "unexpected_status"}, logrus.ErrorLevel, "endpoint error"},
} {
t.Run(tc.name, func(st *testing.T) {
origin := httptest.NewServer(tc.origin)
Expand All @@ -78,12 +83,18 @@ func TestDefinitions_Jobs(t *testing.T) {
time.Sleep(time.Second / 4)

for _, entry := range hook.AllEntries() {
if entry.Data["type"] == "job" {
if entry.Data["type"] == "couper_job" {
for k := range tc.wantFields {
if diff := cmp.Diff(entry.Data[k], tc.wantFields[k]); diff != "" {
st.Errorf("expected log fields %q:\n%v", k, diff)
}
}
if entry.Level != tc.wantLevel {
st.Errorf("want level: %d, got: %d", tc.wantLevel, entry.Level)
}
if entry.Message != tc.wantMsg {
st.Errorf("want message: %q, got: %q", tc.wantMsg, entry.Message)
}
continue
}
if entry.Data["status"] != 200 {
Expand Down
4 changes: 2 additions & 2 deletions server/testdata/definitions/04_job.hcl
View file
Original file line number Diff line number Diff line change
Expand Up @@ -8,15 +8,15 @@ definitions {
url = "{{ .origin }}"
}

request {
request "second" {
url = "{{ .origin }}"
method = "POST"
json_body = merge(backend_responses.first.json_body, request)
}

custom_log_fields = {
status_a: backend_responses.first.status,
status_b: backend_responses.default.status,
status_b: backend_responses.second.status,
client: request
}
}
Expand Down
12 changes: 12 additions & 0 deletions server/testdata/definitions/05_job.hcl
View file
Original file line number Diff line number Diff line change
@@ -0,0 +1,12 @@
server {}

definitions {
beta_job "withLabel" {
interval = "1m"

request "first" {
url = "{{ .origin }}"
expected_status = [418]
}
}
}

0 comments on commit 5dd027b

Please sign in to comment.