From 534083e4c77f289bfef8a7f3c9358b17a0793da8 Mon Sep 17 00:00:00 2001 From: Jaime Soriano Pastor Date: Fri, 4 Mar 2022 12:06:53 +0100 Subject: [PATCH] Add structured logging (#796) Add structured logging using JSON ECS format. This includes much more information in logs for http requests. As it uses JSON ECS, it doesn't need special parsing. `-log-level` can be used to select log level. `-log-type dev` can be used to enable a logger for development. Logger is a global singleton in the `util` package. --- CHANGELOG.md | 4 + artifacts.go | 9 +- go.mod | 11 ++- go.sum | 32 +++++++- main.go | 101 ++++++++++------------- main_test.go | 5 ++ mime_types.go | 5 +- package_index.go | 10 ++- packages/http.go | 17 ++-- packages/package_test.go | 2 - packages/packages.go | 28 +++++-- signatures.go | 9 +- static.go | 9 +- util/logging.go | 171 ++++++++++++++++++++++++++++++++++++++ util/logging_test.go | 172 +++++++++++++++++++++++++++++++++++++++ 15 files changed, 495 insertions(+), 90 deletions(-) create mode 100644 util/logging.go create mode 100644 util/logging_test.go diff --git a/CHANGELOG.md b/CHANGELOG.md index d0fdd9a4f..fea6ac957 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -8,10 +8,14 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ### Breaking changes +* Structured logging following JSON ECS format. [#796](https://github.com/elastic/package-registry/pull/786). + ### Bugfixes ### Added +* Add `-log-level` and `-log-type` flags to configure logging. [#796](https://github.com/elastic/package-registry/pull/786). + ### Deprecated ### Known Issues diff --git a/artifacts.go b/artifacts.go index eca8ecb7e..ad1f9a6bc 100644 --- a/artifacts.go +++ b/artifacts.go @@ -5,15 +5,16 @@ package main import ( - "log" "net/http" "time" "github.com/Masterminds/semver/v3" "github.com/gorilla/mux" "github.com/pkg/errors" + "go.uber.org/zap" "github.com/elastic/package-registry/packages" + "github.com/elastic/package-registry/util" ) const artifactsRouterPath = "/epr/{packageName}/{packageName:[a-z0-9_]+}-{packageVersion}.zip" @@ -21,6 +22,7 @@ const artifactsRouterPath = "/epr/{packageName}/{packageName:[a-z0-9_]+}-{packag var errArtifactNotFound = errors.New("artifact not found") func artifactsHandler(indexer Indexer, cacheTime time.Duration) func(w http.ResponseWriter, r *http.Request) { + logger := util.Logger() return func(w http.ResponseWriter, r *http.Request) { vars := mux.Vars(r) packageName, ok := vars["packageName"] @@ -44,7 +46,10 @@ func artifactsHandler(indexer Indexer, cacheTime time.Duration) func(w http.Resp opts := packages.NameVersionFilter(packageName, packageVersion) packageList, err := indexer.Get(r.Context(), &opts) if err != nil { - log.Printf("getting package path failed: %v", err) + logger.Error("getting package path failed", + zap.String("package.name", packageName), + zap.String("package.version", packageVersion), + zap.Error(err)) http.Error(w, "internal server error", http.StatusInternalServerError) return } diff --git a/go.mod b/go.mod index 9a28f83a8..caa5bd9d2 100644 --- a/go.mod +++ b/go.mod @@ -6,20 +6,23 @@ require ( github.com/Masterminds/semver/v3 v3.1.0 github.com/elastic/go-licenser v0.3.1 github.com/elastic/go-ucfg v0.8.4-0.20200415140258-1232bd4774a6 + github.com/felixge/httpsnoop v1.0.2 github.com/gorilla/mux v1.8.0 github.com/joeshaw/multierror v0.0.0-20140124173710-69b34d4ec901 github.com/magefile/mage v1.9.0 github.com/pkg/errors v0.9.1 - github.com/stretchr/testify v1.6.1 + github.com/stretchr/testify v1.7.0 go.elastic.co/apm v1.14.0 go.elastic.co/apm/module/apmgorilla v1.14.0 + go.elastic.co/ecszap v1.0.1 + go.uber.org/zap v1.21.0 golang.org/x/tools v0.1.7 gopkg.in/yaml.v2 v2.2.8 ) require ( github.com/armon/go-radix v1.0.0 // indirect - github.com/davecgh/go-spew v1.1.0 // indirect + github.com/davecgh/go-spew v1.1.1 // indirect github.com/elastic/go-sysinfo v1.7.1 // indirect github.com/elastic/go-windows v1.0.1 // indirect github.com/jcchavezs/porto v0.3.0 // indirect @@ -28,10 +31,12 @@ require ( github.com/santhosh-tekuri/jsonschema v1.2.4 // indirect go.elastic.co/apm/module/apmhttp v1.14.0 // indirect go.elastic.co/fastjson v1.1.0 // indirect + go.uber.org/atomic v1.7.0 // indirect + go.uber.org/multierr v1.6.0 // indirect golang.org/x/lint v0.0.0-20210508222113-6edffad5e616 // indirect golang.org/x/mod v0.5.1 // indirect golang.org/x/sys v0.0.0-20211015200801-69063c4bb744 // indirect golang.org/x/xerrors v0.0.0-20200804184101-5ec99f83aff1 // indirect - gopkg.in/yaml.v3 v3.0.0-20200313102051-9f266ea9e77c // indirect + gopkg.in/yaml.v3 v3.0.0-20210107192922-496545a6307b // indirect howett.net/plist v0.0.0-20201203080718-1454fab16a06 // indirect ) diff --git a/go.sum b/go.sum index 969222a8d..a3ad477cf 100644 --- a/go.sum +++ b/go.sum @@ -2,8 +2,11 @@ github.com/Masterminds/semver/v3 v3.1.0 h1:Y2lUDsFKVRSYGojLJ1yLxSXdMmMYTYls0rCvo github.com/Masterminds/semver/v3 v3.1.0/go.mod h1:VPu/7SZ7ePZ3QOrcuXROw5FAcLl4a0cBrbBpGY/8hQs= github.com/armon/go-radix v1.0.0 h1:F4z6KzEeeQIMeLFa97iZU6vupzoecKdU5TX24SNppXI= github.com/armon/go-radix v1.0.0/go.mod h1:ufUuZ+zHj4x4TnLV4JWEpy2hxWSpsRywHrMgIH9cCH8= -github.com/davecgh/go-spew v1.1.0 h1:ZDRjVQ15GmhC3fiQ8ni8+OwkZQO4DARzQgrnXU1Liz8= +github.com/benbjohnson/clock v1.1.0 h1:Q92kusRqC1XV2MjkWETPvjJVqKetz1OzxZB7mHJLju8= +github.com/benbjohnson/clock v1.1.0/go.mod h1:J11/hYXuz8f4ySSvYwY0FKfm+ezbsZBKZxNJlLklBHA= github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= +github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c= +github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= github.com/elastic/go-licenser v0.3.1 h1:RmRukU/JUmts+rpexAw0Fvt2ly7VVu6mw8z4HrEzObU= github.com/elastic/go-licenser v0.3.1/go.mod h1:D8eNQk70FOCVBl3smCGQt/lv7meBeQno2eI1S5apiHQ= github.com/elastic/go-sysinfo v1.1.1/go.mod h1:i1ZYdU10oLNfRzq4vq62BEwD2fH8KaWh6eh0ikPT9F0= @@ -14,6 +17,8 @@ github.com/elastic/go-ucfg v0.8.4-0.20200415140258-1232bd4774a6/go.mod h1:iaiY0N github.com/elastic/go-windows v1.0.0/go.mod h1:TsU0Nrp7/y3+VwE82FoZF8gC/XFg/Elz6CcloAxnPgU= github.com/elastic/go-windows v1.0.1 h1:AlYZOldA+UJ0/2nBuqWdo90GFCgG9xuyw9SYzGUtJm0= github.com/elastic/go-windows v1.0.1/go.mod h1:FoVvqWSun28vaDQPbj2Elfc0JahhPB7WQEGa3c814Ss= +github.com/felixge/httpsnoop v1.0.2 h1:+nS9g82KMXccJ/wp0zyRW9ZBHFETmMGtkk+2CTTrW4o= +github.com/felixge/httpsnoop v1.0.2/go.mod h1:m8KPJKqk1gH5J9DgRY2ASl2lWCfGKXixSwevea8zH2U= github.com/google/go-cmp v0.3.1/go.mod h1:8QqcDgzrUqlUb/G2PQTWiueGozuR1884gddMywk6iLU= github.com/google/go-cmp v0.5.4 h1:L8R9j+yAqZuZjsqh/z+F1NCffTKKLShY6zXTItVIZ8M= github.com/google/go-cmp v0.5.4/go.mod h1:v8dTdLbMG2kIc/vJvl+f65V22dbkXbowE6jgT/gNBxE= @@ -47,9 +52,11 @@ github.com/santhosh-tekuri/jsonschema v1.2.4 h1:hNhW8e7t+H1vgY+1QeEQpveR6D4+OwKP github.com/santhosh-tekuri/jsonschema v1.2.4/go.mod h1:TEAUOeZSmIxTTuHatJzrvARHiuO9LYd+cIxzgEHCQI4= github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME= github.com/stretchr/testify v1.3.0/go.mod h1:M5WIy9Dh21IEIfnGCwXGc5bZfKNJtfHm1UVUgZn+9EI= -github.com/stretchr/testify v1.6.1 h1:hDPOHmpOpP40lSULcqw7IrRb/u7w6RpDC9399XyoNd0= github.com/stretchr/testify v1.6.1/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg= +github.com/stretchr/testify v1.7.0 h1:nwc3DEeHmmLAfoZucVR881uASk0Mfjw8xYJ99tb5CcY= +github.com/stretchr/testify v1.7.0/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg= github.com/yuin/goldmark v1.1.27/go.mod h1:3hX8gzYuyVAZsxl0MRgGTJEmQBFcNTphYh9decYSb74= +github.com/yuin/goldmark v1.3.5/go.mod h1:mwnBkeHKe2W/ZEtQ+71ViKU8L12m81fl3OWwC1Zlc8k= github.com/yuin/goldmark v1.4.0/go.mod h1:mwnBkeHKe2W/ZEtQ+71ViKU8L12m81fl3OWwC1Zlc8k= go.elastic.co/apm v1.14.0 h1:9yilcTbWpqhfyunUj6/SDpZbR4FOVB50xQgODe0TW/0= go.elastic.co/apm v1.14.0/go.mod h1:dylGv2HKR0tiCV+wliJz1KHtDyuD8SPe69oV7VyK6WY= @@ -57,10 +64,21 @@ go.elastic.co/apm/module/apmgorilla v1.14.0 h1:espCHSZ3ibkrffR6KLua+0jMeBSgO/087 go.elastic.co/apm/module/apmgorilla v1.14.0/go.mod h1:+cDGiyPXN3EvTxoh7zcWOL1/Yw6zKhNkUU0a0OGyXsg= go.elastic.co/apm/module/apmhttp v1.14.0 h1:uDSIPr1BJOt1A/T5J9Beq9VtMtQHqOdqQUXCPRQF4C4= go.elastic.co/apm/module/apmhttp v1.14.0/go.mod h1:PY8hyV0X3eKqXYYoN0pyu1pWcvFCwGmh5eUFuS39Zmo= +go.elastic.co/ecszap v1.0.1 h1:mBxqEJAEXBlpi5+scXdzL7LTFGogbuxipJC0KTZicyA= +go.elastic.co/ecszap v1.0.1/go.mod h1:SVjazT+QgNeHSGOCUHvRgN+ZRj5FkB7IXQQsncdF57A= go.elastic.co/fastjson v1.1.0 h1:3MrGBWWVIxe/xvsbpghtkFoPciPhOCmjsR/HfwEeQR4= go.elastic.co/fastjson v1.1.0/go.mod h1:boNGISWMjQsUPy/t6yqt2/1Wx4YNPSe+mZjlyw9vKKI= +go.uber.org/atomic v1.7.0 h1:ADUqmZGgLDDfbSL9ZmPxKTybcoEYHgpYfELNoN+7hsw= +go.uber.org/atomic v1.7.0/go.mod h1:fEN4uk6kAWBTFdckzkM89CLk9XfWZrxpCo0nPH17wJc= +go.uber.org/goleak v1.1.11 h1:wy28qYRKZgnJTxGxvye5/wgWr1EKjmUDGYox5mGlRlI= +go.uber.org/goleak v1.1.11/go.mod h1:cwTWslyiVhfpKIDGSZEM2HlOvcqm+tG4zioyIeLoqMQ= +go.uber.org/multierr v1.6.0 h1:y6IPFStTAIT5Ytl7/XYmHvzXQ7S3g/IeZW9hyZ5thw4= +go.uber.org/multierr v1.6.0/go.mod h1:cdWPpRnG4AhwMwsgIHip0KRBQjJy5kYEpYjJxpXp9iU= +go.uber.org/zap v1.21.0 h1:WefMeulhovoZ2sYXz7st6K0sLj7bBhpiFaud4r4zST8= +go.uber.org/zap v1.21.0/go.mod h1:wjWOCqI0f2ZZrJF/UufIOkiC8ii6tm1iqIsLo76RfJw= golang.org/x/crypto v0.0.0-20190308221718-c2843e01d9a2/go.mod h1:djNgcEr1/C05ACkg1iLfiJU5Ep61QUkGW8qpdssI0+w= golang.org/x/crypto v0.0.0-20191011191535-87dc89f01550/go.mod h1:yigFU9vqHzYiE8UmvKecakEJjdnWj3jj499lnFckfCI= +golang.org/x/lint v0.0.0-20190930215403-16217165b5de/go.mod h1:6SW0HCj/g11FgYtHlgUYUwCkIfeOF89ocIRzGO/8vkc= golang.org/x/lint v0.0.0-20201208152925-83fdc39ff7b5/go.mod h1:3xt1FjdF8hUf6vQPIChWIBhFzV8gjjsPE/fR3IyQdNY= golang.org/x/lint v0.0.0-20210508222113-6edffad5e616 h1:VLliZ0d+/avPrXXH+OakdXhpJuEoBZuwh1m2j7U6Iug= golang.org/x/lint v0.0.0-20210508222113-6edffad5e616/go.mod h1:3xt1FjdF8hUf6vQPIChWIBhFzV8gjjsPE/fR3IyQdNY= @@ -70,9 +88,11 @@ golang.org/x/mod v0.3.0/go.mod h1:s0Qsj1ACt9ePp/hMypM3fl4fZqREWJwdYDEqhRiZZUA= golang.org/x/mod v0.4.2/go.mod h1:s0Qsj1ACt9ePp/hMypM3fl4fZqREWJwdYDEqhRiZZUA= golang.org/x/mod v0.5.1 h1:OJxoQ/rynoF0dcCdI7cLPktw/hR2cueqYfjm43oqK38= golang.org/x/mod v0.5.1/go.mod h1:5OXOZSfqPIIbmVBIIKWRFfZjPR0E5r58TLhUjH0a2Ro= +golang.org/x/net v0.0.0-20190311183353-d8887717615a/go.mod h1:t9HGtf8HONx5eT2rtn7q6eTqICYqUVnKs3thJo3Qplg= golang.org/x/net v0.0.0-20190404232315-eb5bcb51f2a3/go.mod h1:t9HGtf8HONx5eT2rtn7q6eTqICYqUVnKs3thJo3Qplg= golang.org/x/net v0.0.0-20190620200207-3b0461eec859/go.mod h1:z5CRVTTTmAJ677TzLLGU+0bjPO0LkuOLi4/5GtJWs/s= golang.org/x/net v0.0.0-20200226121028-0de0cce0169b/go.mod h1:z5CRVTTTmAJ677TzLLGU+0bjPO0LkuOLi4/5GtJWs/s= +golang.org/x/net v0.0.0-20210405180319-a5a99cb37ef4/go.mod h1:p54w0d4576C0XHj96bSt6lcn1PtDYWL6XObtHCRCNQM= golang.org/x/net v0.0.0-20210805182204-aaa1db679c0d h1:20cMwl2fHAzkJMEA+8J4JgqBQcQGzbisXo31MIeenXI= golang.org/x/net v0.0.0-20210805182204-aaa1db679c0d/go.mod h1:9nx3DQGgdP8bBQD5qxJ1jj9UTztislL4KSBs9R2vV5Y= golang.org/x/sync v0.0.0-20181221193216-37e7f081c4d4/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM= @@ -87,19 +107,24 @@ golang.org/x/sys v0.0.0-20191025021431-6c3a3bfe00ae/go.mod h1:h1NjWce9XRLGQEsW7w golang.org/x/sys v0.0.0-20191204072324-ce4227a45e2e/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= golang.org/x/sys v0.0.0-20201119102817-f84b799fce68/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= golang.org/x/sys v0.0.0-20210124154548-22da62e12c0c/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= +golang.org/x/sys v0.0.0-20210330210617-4fbd30eecc44/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= golang.org/x/sys v0.0.0-20210423082822-04245dca01da/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= +golang.org/x/sys v0.0.0-20210510120138-977fb7262007/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.0.0-20210809222454-d867a43fc93e/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.0.0-20211015200801-69063c4bb744 h1:KzbpndAYEM+4oHRp9JmB2ewj0NHHxO3Z0g7Gus2O1kk= golang.org/x/sys v0.0.0-20211015200801-69063c4bb744/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/term v0.0.0-20201126162022-7de9c90e9dd1/go.mod h1:bj7SfCRtBDWHUb9snDiAeCFNEtKQo2Wmx5Cou7ajbmo= golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ= golang.org/x/text v0.3.2/go.mod h1:bEr9sfX3Q8Zfm5fL9x+3itogRgK3+ptLWKqgva+5dAk= +golang.org/x/text v0.3.3/go.mod h1:5Zoc/QRtKVWzQhOtBMvqHzDpF6irO9z98xDceosuGiQ= golang.org/x/text v0.3.6 h1:aRYxNxv6iGQlyVaZmk6ZgYEDa+Jg18DxebPSrd6bg1M= golang.org/x/text v0.3.6/go.mod h1:5Zoc/QRtKVWzQhOtBMvqHzDpF6irO9z98xDceosuGiQ= golang.org/x/tools v0.0.0-20180917221912-90fa682c2a6e/go.mod h1:n7NCudcB/nEzxVGmLbDWY5pfWTLqBcC2KZ6jyYvM4mQ= +golang.org/x/tools v0.0.0-20190311212946-11955173bddd/go.mod h1:LCzVGOaR6xXOjkQ3onu1FJEFr0SW1gC7cKk1uF8kGRs= golang.org/x/tools v0.0.0-20191119224855-298f0cb1881e/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo= golang.org/x/tools v0.0.0-20200130002326-2f3ba24bd6e7/go.mod h1:TB2adYChydJhpapKDTa4BR/hXlZSLoq2Wpct/0txZ28= golang.org/x/tools v0.0.0-20200509030707-2212a7e161a5/go.mod h1:EkVYQZoAsY45+roYkvgYkIh4xh/qjgUK9TdY2XT94GE= +golang.org/x/tools v0.1.5/go.mod h1:o0xws9oXOQQZyjljx8fwUC0k7L1pTE6eaCbjGeHmOkk= golang.org/x/tools v0.1.7 h1:6j8CgantCy3yc8JGBqkDLMKWqZ0RDU2g1HVgacojGWQ= golang.org/x/tools v0.1.7/go.mod h1:LGqMHiF4EqQNHR1JncWGqT5BVaXmza+X+BDGol+dOxo= golang.org/x/xerrors v0.0.0-20190717185122-a985d3407aa7/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0= @@ -114,8 +139,9 @@ gopkg.in/yaml.v2 v2.2.1/go.mod h1:hI93XBmqTisBFMUTm0b8Fm+jr3Dg1NNxqwp+5A1VGuI= gopkg.in/yaml.v2 v2.2.2/go.mod h1:hI93XBmqTisBFMUTm0b8Fm+jr3Dg1NNxqwp+5A1VGuI= gopkg.in/yaml.v2 v2.2.8 h1:obN1ZagJSUGI0Ek/LBmuj4SNLPfIny3KsKFopxRdj10= gopkg.in/yaml.v2 v2.2.8/go.mod h1:hI93XBmqTisBFMUTm0b8Fm+jr3Dg1NNxqwp+5A1VGuI= -gopkg.in/yaml.v3 v3.0.0-20200313102051-9f266ea9e77c h1:dUUwHk2QECo/6vqA44rthZ8ie2QXMNeKRTHCNY2nXvo= gopkg.in/yaml.v3 v3.0.0-20200313102051-9f266ea9e77c/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM= +gopkg.in/yaml.v3 v3.0.0-20210107192922-496545a6307b h1:h8qDotaEPuJATrMmW04NCwg7v22aHH28wwpauUhK9Oo= +gopkg.in/yaml.v3 v3.0.0-20210107192922-496545a6307b/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM= howett.net/plist v0.0.0-20181124034731-591f970eefbb/go.mod h1:vMygbs4qMhSZSc4lCUl2OEE+rDiIIJAIdR4m7MiMcm0= howett.net/plist v0.0.0-20201203080718-1454fab16a06 h1:QDxUo/w2COstK1wIBYpzQlHX/NqaQTcf9jyz347nI58= howett.net/plist v0.0.0-20201203080718-1454fab16a06/go.mod h1:vMygbs4qMhSZSc4lCUl2OEE+rDiIIJAIdR4m7MiMcm0= diff --git a/main.go b/main.go index 65d6ceccb..6bce4ecf2 100644 --- a/main.go +++ b/main.go @@ -8,7 +8,6 @@ import ( "context" "flag" "fmt" - "log" "net/http" _ "net/http/pprof" "os" @@ -19,6 +18,7 @@ import ( "github.com/gorilla/mux" "github.com/pkg/errors" + "go.uber.org/zap" "go.elastic.co/apm" "go.elastic.co/apm/module/apmgorilla" @@ -26,6 +26,7 @@ import ( ucfgYAML "github.com/elastic/go-ucfg/yaml" "github.com/elastic/package-registry/packages" + "github.com/elastic/package-registry/util" ) const ( @@ -72,16 +73,20 @@ type Config struct { func main() { parseFlags() - log.Println("Package registry started.") - defer log.Println("Package registry stopped.") - initHttpProf() + logger := util.Logger() + defer logger.Sync() - server := initServer() + logger.Info("Package registry started") + defer logger.Info("Package registry stopped") + + initHttpProf(logger) + + server := initServer(logger) go func() { err := runServer(server) if err != nil && err != http.ErrServerClosed { - log.Fatalf("Error occurred while serving: %s", err) + logger.Fatal("error occurred while serving", zap.Error(err)) } }() @@ -89,47 +94,47 @@ func main() { signal.Notify(stop, os.Interrupt, syscall.SIGTERM) <-stop - ctx := context.TODO() + ctx := context.Background() if err := server.Shutdown(ctx); err != nil { - log.Fatal(err) + logger.Fatal("error on shutdown", zap.Error(err)) } } -func initHttpProf() { +func initHttpProf(logger *zap.Logger) { if httpProfAddress == "" { return } - log.Printf("Starting http pprof in %s", httpProfAddress) + logger.Info("Starting http pprof in " + httpProfAddress) go func() { err := http.ListenAndServe(httpProfAddress, nil) if err != nil { - log.Fatalf("failed to start HTTP profiler: %v", err) + logger.Fatal("failed to start HTTP profiler", zap.Error(err)) } }() } -func initServer() *http.Server { - apmTracer := initAPMTracer() +func initServer(logger *zap.Logger) *http.Server { + apmTracer := initAPMTracer(logger) tx := apmTracer.StartTransaction("initServer", "backend.init") defer tx.End() ctx := apm.ContextWithTransaction(context.TODO(), tx) - config := mustLoadConfig() + config := mustLoadConfig(logger) packagesBasePaths := getPackagesBasePaths(config) indexer := NewCombinedIndexer( packages.NewFileSystemIndexer(packagesBasePaths...), packages.NewZipFileSystemIndexer(packagesBasePaths...), ) - ensurePackagesAvailable(ctx, indexer) + ensurePackagesAvailable(ctx, logger, indexer) // If -dry-run=true is set, service stops here after validation if dryRun { os.Exit(0) } - router := mustLoadRouter(config, indexer) + router := mustLoadRouter(logger, config, indexer) apmgorilla.Instrument(router, apmgorilla.WithTracer(apmTracer)) return &http.Server{Addr: address, Handler: router} @@ -142,7 +147,7 @@ func runServer(server *http.Server) error { return server.ListenAndServe() } -func initAPMTracer() *apm.Tracer { +func initAPMTracer(logger *zap.Logger) *apm.Tracer { apm.DefaultTracer.Close() if _, found := os.LookupEnv("ELASTIC_APM_SERVER_URL"); !found { // Don't report anything if the Server URL hasn't been configured. @@ -154,25 +159,24 @@ func initAPMTracer() *apm.Tracer { ServiceVersion: version, }) if err != nil { - log.Fatalf("Failed to initialize APM agent: %v", err) + logger.Fatal("Failed to initialize APM agent", zap.Error(err)) } return tracer } -func mustLoadConfig() *Config { - config, err := getConfig() +func mustLoadConfig(logger *zap.Logger) *Config { + config, err := getConfig(logger) if err != nil { - log.Fatal(err) + logger.Fatal("getting config", zap.Error(err)) } - printConfig(config) + printConfig(logger, config) return config } -func getConfig() (*Config, error) { +func getConfig(logger *zap.Logger) (*Config, error) { cfg, err := ucfgYAML.NewConfigWithFile(configPath) if os.IsNotExist(err) { - log.Printf(`Using default configuration options as "%s" is not available.`, configPath) - return &defaultConfig, nil + logger.Fatal("Configuration file is not available: " + configPath) } if err != nil { return nil, errors.Wrapf(err, "reading config failed (path: %s)", configPath) @@ -192,40 +196,40 @@ func getPackagesBasePaths(config *Config) []string { return paths } -func printConfig(config *Config) { - log.Printf("Packages paths: %s\n", strings.Join(config.PackagePaths, ", ")) - log.Println("Cache time for /search: ", config.CacheTimeSearch) - log.Println("Cache time for /categories: ", config.CacheTimeCategories) - log.Println("Cache time for all others: ", config.CacheTimeCatchAll) +func printConfig(logger *zap.Logger, config *Config) { + logger.Info("Packages paths: " + strings.Join(config.PackagePaths, ", ")) + logger.Info("Cache time for /search: " + config.CacheTimeSearch.String()) + logger.Info("Cache time for /categories: " + config.CacheTimeCategories.String()) + logger.Info("Cache time for all others: " + config.CacheTimeCatchAll.String()) } -func ensurePackagesAvailable(ctx context.Context, indexer Indexer) { +func ensurePackagesAvailable(ctx context.Context, logger *zap.Logger, indexer Indexer) { err := indexer.Init(ctx) if err != nil { - log.Fatal(err) + logger.Fatal("Init failed", zap.Error(err)) } packages, err := indexer.Get(ctx, nil) if err != nil { - log.Fatal(err) + logger.Fatal("Cannot get packages from indexer", zap.Error(err)) } if len(packages) == 0 { - log.Fatal("No packages available") + logger.Fatal("No packages available") } - log.Printf("%v package manifests loaded.\n", len(packages)) + logger.Info(fmt.Sprintf("%v package manifests loaded", len(packages))) } -func mustLoadRouter(config *Config, indexer Indexer) *mux.Router { - router, err := getRouter(config, indexer) +func mustLoadRouter(logger *zap.Logger, config *Config, indexer Indexer) *mux.Router { + router, err := getRouter(logger, config, indexer) if err != nil { - log.Fatal(err) + logger.Fatal("failed go configure router", zap.Error(err)) } return router } -func getRouter(config *Config, indexer Indexer) (*mux.Router, error) { +func getRouter(logger *zap.Logger, config *Config, indexer Indexer) (*mux.Router, error) { artifactsHandler := artifactsHandler(indexer, config.CacheTimeCatchAll) signaturesHandler := signaturesHandler(indexer, config.CacheTimeCatchAll) faviconHandleFunc, err := faviconHandler(config.CacheTimeCatchAll) @@ -252,7 +256,7 @@ func getRouter(config *Config, indexer Indexer) (*mux.Router, error) { router.HandleFunc(signaturesRouterPath, signaturesHandler) router.HandleFunc(packageIndexRouterPath, packageIndexHandler) router.HandleFunc(staticRouterPath, staticHandler) - router.Use(loggingMiddleware) + router.Use(util.LoggingMiddleware(logger)) router.NotFoundHandler = http.Handler(notFoundHandler(fmt.Errorf("404 page not found"))) return router, nil } @@ -260,20 +264,3 @@ func getRouter(config *Config, indexer Indexer) (*mux.Router, error) { // healthHandler is used for Docker/K8s deployments. It returns 200 if the service is live // In addition ?ready=true can be used for a ready request. Currently both are identical. func healthHandler(w http.ResponseWriter, r *http.Request) {} - -// logging middle to log all requests -func loggingMiddleware(next http.Handler) http.Handler { - return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - logRequest(r) - next.ServeHTTP(w, r) - }) -} - -// logRequest converts a request object into a proper logging event -func logRequest(r *http.Request) { - // Do not log requests to the health endpoint - if r.RequestURI == "/health" { - return - } - log.Println(fmt.Sprintf("source.ip: %s, url.original: %s", r.RemoteAddr, r.RequestURI)) -} diff --git a/main_test.go b/main_test.go index 40eb647ee..614302dfd 100644 --- a/main_test.go +++ b/main_test.go @@ -27,6 +27,7 @@ import ( "gopkg.in/yaml.v2" "github.com/elastic/package-registry/packages" + "github.com/elastic/package-registry/util" ) var ( @@ -35,6 +36,10 @@ var ( generatedFilesPath = filepath.Join("testdata", "generated") ) +func init() { + util.UseDevelopmentLogger() +} + func TestEndpoints(t *testing.T) { packagesBasePaths := []string{"./testdata/second_package_path", "./testdata/package"} indexer := packages.NewFileSystemIndexer(packagesBasePaths...) diff --git a/mime_types.go b/mime_types.go index 7757dba9f..fdae59b2a 100644 --- a/mime_types.go +++ b/mime_types.go @@ -5,8 +5,9 @@ package main import ( - "log" "mime" + + "github.com/elastic/package-registry/util" ) // init method defines MIME types important for the package content. Definitions ensure that the same Content-Type @@ -21,6 +22,6 @@ func init() { func mustAddMimeExtensionType(ext, typ string) { err := mime.AddExtensionType(ext, typ) if err != nil { - log.Fatal(err) + util.Logger().Fatal(err.Error()) } } diff --git a/package_index.go b/package_index.go index 924d5ca65..331fe2c50 100644 --- a/package_index.go +++ b/package_index.go @@ -5,11 +5,11 @@ package main import ( - "log" "net/http" "time" "github.com/pkg/errors" + "go.uber.org/zap" "github.com/Masterminds/semver/v3" "github.com/gorilla/mux" @@ -25,6 +25,7 @@ const ( var errPackageRevisionNotFound = errors.New("package revision not found") func packageIndexHandler(indexer Indexer, cacheTime time.Duration) func(w http.ResponseWriter, r *http.Request) { + logger := util.Logger() return func(w http.ResponseWriter, r *http.Request) { vars := mux.Vars(r) packageName, ok := vars["packageName"] @@ -48,7 +49,7 @@ func packageIndexHandler(indexer Indexer, cacheTime time.Duration) func(w http.R opts := packages.NameVersionFilter(packageName, packageVersion) packages, err := indexer.Get(r.Context(), &opts) if err != nil { - log.Printf("getting package path failed: %v", err) + logger.Error("getting package path failed", zap.Error(err)) http.Error(w, "internal server error", http.StatusInternalServerError) return } @@ -62,8 +63,9 @@ func packageIndexHandler(indexer Indexer, cacheTime time.Duration) func(w http.R err = util.WriteJSONPretty(w, packages[0]) if err != nil { - log.Printf("marshaling package index failed (path '%s'): %v", packages[0].BasePath, err) - + logger.Error("marshaling package index failed", + zap.String("package.path", packages[0].BasePath), + zap.Error(err)) http.Error(w, "internal server error", http.StatusInternalServerError) return } diff --git a/packages/http.go b/packages/http.go index 916753833..4601ab6fb 100644 --- a/packages/http.go +++ b/packages/http.go @@ -5,13 +5,14 @@ package packages import ( - "log" "net/http" "os" "go.elastic.co/apm" + "go.uber.org/zap" "github.com/elastic/package-registry/archiver" + "github.com/elastic/package-registry/util" ) func ServePackage(w http.ResponseWriter, r *http.Request, p *Package) { @@ -19,9 +20,11 @@ func ServePackage(w http.ResponseWriter, r *http.Request, p *Package) { defer span.End() packagePath := p.BasePath + logger := util.Logger().With(zap.String("file.name", packagePath)) + f, err := os.Stat(packagePath) if err != nil { - log.Printf("stat package path '%s' failed: %v", packagePath, err) + logger.Error("stat package path failed", zap.Error(err)) http.Error(w, "internal server error", http.StatusInternalServerError) return } @@ -35,7 +38,7 @@ func ServePackage(w http.ResponseWriter, r *http.Request, p *Package) { Path: packagePath, }) if err != nil { - log.Printf("archiving package path '%s' failed: %v", packagePath, err) + logger.Error("archiving package path failed", zap.Error(err)) return } } else { @@ -47,13 +50,15 @@ func ServeFile(w http.ResponseWriter, r *http.Request, p *Package, name string) span, _ := apm.StartSpan(r.Context(), "ServePackage", "app") defer span.End() + logger := util.Logger().With(zap.String("file.name", name)) + fs, err := p.fs() if os.IsNotExist(err) { http.Error(w, "resource not found", http.StatusNotFound) return } if err != nil { - log.Printf("failed to open filesystem for package: %v", err) + logger.Error("failed to open filesystem", zap.Error(err)) http.Error(w, "internal server error", http.StatusInternalServerError) return } @@ -64,14 +69,14 @@ func ServeFile(w http.ResponseWriter, r *http.Request, p *Package, name string) return } if err != nil { - log.Printf("stat failed for %s: %v", name, err) + logger.Error("stat failed", zap.Error(err)) http.Error(w, "internal server error", http.StatusInternalServerError) return } f, err := fs.Open(name) if err != nil { - log.Printf("failed to open file (%s) in package: %v", name, err) + logger.Error("failed to open file", zap.Error(err)) http.Error(w, "internal server error", http.StatusInternalServerError) return } diff --git a/packages/package_test.go b/packages/package_test.go index 988c244b7..701fbe53f 100644 --- a/packages/package_test.go +++ b/packages/package_test.go @@ -5,7 +5,6 @@ package packages import ( - "log" "path/filepath" "testing" @@ -204,7 +203,6 @@ func TestHasKibanaVersion(t *testing.T) { assert.NoError(t, err) check := p.HasKibanaVersion(kibanaVersion) - log.Println(check) assert.Equal(t, tt.check, check) }) diff --git a/packages/packages.go b/packages/packages.go index 7c29bbdc0..2b9306096 100644 --- a/packages/packages.go +++ b/packages/packages.go @@ -7,7 +7,6 @@ package packages import ( "archive/zip" "context" - "log" "os" "path/filepath" "strings" @@ -15,6 +14,7 @@ import ( "github.com/Masterminds/semver/v3" "github.com/pkg/errors" "go.elastic.co/apm" + "go.uber.org/zap" "github.com/elastic/package-registry/util" ) @@ -61,10 +61,13 @@ type FileSystemIndexer struct { // Builder to access the files of a package in this indexer. fsBuilder FileSystemBuilder + + logger *zap.Logger } // NewFileSystemIndexer creates a new FileSystemIndexer for the given paths. func NewFileSystemIndexer(paths ...string) *FileSystemIndexer { + logger := util.Logger() walkerFn := func(basePath, path string, info os.DirEntry) (bool, error) { relativePath, err := filepath.Rel(basePath, path) if err != nil { @@ -80,7 +83,8 @@ func NewFileSystemIndexer(paths ...string) *FileSystemIndexer { versionDir := dirs[1] _, err := semver.StrictNewVersion(versionDir) if err != nil { - log.Printf("warning: unexpected directory: %s, ignoring", path) + logger.Warn("ignoring unexpected directory", + zap.String("file.path", path)) return false, filepath.SkipDir } return true, nil @@ -88,7 +92,7 @@ func NewFileSystemIndexer(paths ...string) *FileSystemIndexer { // Unexpected file, return nil in order to continue processing sibling directories // Fixes an annoying problem when the .DS_Store file is left behind and the package // is not loading without any error information - log.Printf("warning: unexpected file: %s, ignoring", path) + logger.Warn("ignoging unexpected file", zap.String("file.path", path)) return false, nil } fsBuilder := func(p *Package) (PackageFileSystem, error) { @@ -99,11 +103,13 @@ func NewFileSystemIndexer(paths ...string) *FileSystemIndexer { label: "FileSystemIndexer", walkerFn: walkerFn, fsBuilder: fsBuilder, + logger: logger, } } // NewZipFileSystemIndexer creates a new ZipFileSystemIndexer for the given paths. func NewZipFileSystemIndexer(paths ...string) *FileSystemIndexer { + logger := util.Logger() walkerFn := func(basePath, path string, info os.DirEntry) (bool, error) { if info.IsDir() { return false, nil @@ -115,7 +121,8 @@ func NewZipFileSystemIndexer(paths ...string) *FileSystemIndexer { // Check if the file is actually a zip file. r, err := zip.OpenReader(path) if err != nil { - log.Printf("warning: zip file cannot be opened as zip: %s, ignoring: %v", path, err) + logger.Warn("ignoring invalid zip file", + zap.String("file.path", path), zap.Error(err)) return false, nil } defer r.Close() @@ -130,6 +137,7 @@ func NewZipFileSystemIndexer(paths ...string) *FileSystemIndexer { label: "ZipFileSystemIndexer", walkerFn: walkerFn, fsBuilder: fsBuilder, + logger: logger, } } @@ -178,7 +186,7 @@ func (i *FileSystemIndexer) getPackagesFromFileSystem(ctx context.Context) (Pack return nil, err } - log.Printf("Packages in %s:", basePath) + i.logger.Info("Packages in " + basePath + ":") for _, path := range packagePaths { p, err := NewPackage(path, i.fsBuilder) if err != nil { @@ -187,14 +195,20 @@ func (i *FileSystemIndexer) getPackagesFromFileSystem(ctx context.Context) (Pack key := packageKey{name: p.Name, version: p.Version} if _, found := packagesFound[key]; found { - log.Printf("%-20s\t%10s\t%s", p.Name+" (duplicated)", p.Version, p.BasePath) + i.logger.Info("duplicated package", + zap.String("package.name", p.Name), + zap.String("package.version", p.Version), + zap.String("package.path", p.BasePath)) continue } packagesFound[key] = struct{}{} pList = append(pList, p) - log.Printf("%-20s\t%10s\t%s", p.Name, p.Version, p.BasePath) + i.logger.Info("found package", + zap.String("package.name", p.Name), + zap.String("package.version", p.Version), + zap.String("package.path", p.BasePath)) } } return pList, nil diff --git a/signatures.go b/signatures.go index 707a62a14..587ba4bfc 100644 --- a/signatures.go +++ b/signatures.go @@ -5,15 +5,16 @@ package main import ( - "log" "net/http" "time" "github.com/Masterminds/semver/v3" "github.com/gorilla/mux" "github.com/pkg/errors" + "go.uber.org/zap" "github.com/elastic/package-registry/packages" + "github.com/elastic/package-registry/util" ) const signaturesRouterPath = "/epr/{packageName}/{packageName:[a-z0-9_]+}-{packageVersion}.zip.sig" @@ -21,6 +22,7 @@ const signaturesRouterPath = "/epr/{packageName}/{packageName:[a-z0-9_]+}-{packa var errSignatureFileNotFound = errors.New("signature file not found") func signaturesHandler(indexer Indexer, cacheTime time.Duration) func(w http.ResponseWriter, r *http.Request) { + logger := util.Logger() return func(w http.ResponseWriter, r *http.Request) { vars := mux.Vars(r) packageName, ok := vars["packageName"] @@ -44,7 +46,10 @@ func signaturesHandler(indexer Indexer, cacheTime time.Duration) func(w http.Res opts := packages.NameVersionFilter(packageName, packageVersion) packageList, err := indexer.Get(r.Context(), &opts) if err != nil { - log.Printf("getting package path failed: %v", err) + logger.Error("getting package path failed", + zap.String("package.name", packageName), + zap.String("package.version", packageVersion), + zap.Error(err)) http.Error(w, "internal server error", http.StatusInternalServerError) return } diff --git a/static.go b/static.go index 0ef209fb7..aa9c19d30 100644 --- a/static.go +++ b/static.go @@ -6,14 +6,15 @@ package main import ( "errors" - "log" "net/http" "time" "github.com/Masterminds/semver/v3" "github.com/gorilla/mux" + "go.uber.org/zap" "github.com/elastic/package-registry/packages" + "github.com/elastic/package-registry/util" ) const staticRouterPath = "/package/{packageName}/{packageVersion}/{name:.*}" @@ -25,6 +26,7 @@ type staticParams struct { } func staticHandler(indexer Indexer, cacheTime time.Duration) http.HandlerFunc { + logger := util.Logger() return func(w http.ResponseWriter, r *http.Request) { params, err := staticParamsFromRequest(r) if err != nil { @@ -35,7 +37,10 @@ func staticHandler(indexer Indexer, cacheTime time.Duration) http.HandlerFunc { opts := packages.NameVersionFilter(params.packageName, params.packageVersion) packageList, err := indexer.Get(r.Context(), &opts) if err != nil { - log.Printf("getting package path failed: %v", err) + logger.Error("getting package path failed", + zap.String("package.name", params.packageName), + zap.String("package.version", params.packageVersion), + zap.Error(err)) http.Error(w, "internal server error", http.StatusInternalServerError) return } diff --git a/util/logging.go b/util/logging.go new file mode 100644 index 000000000..0995b2e51 --- /dev/null +++ b/util/logging.go @@ -0,0 +1,171 @@ +// Copyright Elasticsearch B.V. and/or licensed to Elasticsearch B.V. under one +// or more contributor license agreements. Licensed under the Elastic License; +// you may not use this file except in compliance with the Elastic License. + +package util + +import ( + "flag" + "net" + "net/http" + "os" + "strconv" + "sync" + + "github.com/felixge/httpsnoop" + "github.com/gorilla/mux" + "go.elastic.co/ecszap" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" +) + +// Types of available loggers. +const ( + ECSLogger = "ecs" + DevLogger = "dev" + + defaultLoggerType = ECSLogger +) + +var logLevel = zap.LevelFlag("log-level", zap.InfoLevel, "log level (default \"info\")") +var logType = flag.String("log-type", defaultLoggerType, "log type (ecs, dev)") + +var logger *zap.Logger +var loggerMutex sync.Mutex + +// UseECSLogger initializes the logger as an JSON ECS logger. It does nothing +// if the logger has been already initialized. +func UseECSLogger() { + loggerMutex.Lock() + defer loggerMutex.Unlock() + + if logger != nil { + return + } + + logger = newECSLogger() +} + +// UseDevelopmentLogger initializes the logger as a development logger. It does nothing +// if the logger has been already initialized. +func UseDevelopmentLogger() { + loggerMutex.Lock() + defer loggerMutex.Unlock() + + if logger != nil { + return + } + + logger = newDevelopmentLogger() +} + +var warnInvalidTypeOnce sync.Once + +// Logger returns a logger singleton. +func Logger() *zap.Logger { + switch *logType { + case ECSLogger: + UseECSLogger() + case DevLogger: + UseDevelopmentLogger() + default: + logger = newECSLogger() + warnInvalidTypeOnce.Do(func() { + logger.Warn("unknown log type " + *logType + " using default") + }) + } + return logger +} + +func newECSLogger() *zap.Logger { + encoderConfig := ecszap.NewDefaultEncoderConfig() + core := ecszap.NewCore(encoderConfig, os.Stderr, *logLevel) + return zap.New(core, zap.AddCaller()) +} + +func newDevelopmentLogger() *zap.Logger { + encoderConfig := zap.NewDevelopmentEncoderConfig() + encoder := zapcore.NewConsoleEncoder(encoderConfig) + core := zapcore.NewCore(encoder, os.Stderr, zap.DebugLevel) + return zap.New(core, zap.AddCaller()) +} + +// LoggingMiddleware is a middleware used to log requests to the given logger. +func LoggingMiddleware(logger *zap.Logger) mux.MiddlewareFunc { + // Disable logging of the file and number of the caller, because it will be the + // one of the helper. + logger = logger.Named("http").WithOptions(zap.WithCaller(false)) + return func(next http.Handler) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + // Do not log requests to the health endpoint + if r.RequestURI == "/health" { + next.ServeHTTP(w, r) + return + } + + logRequest(logger, next, w, r) + }) + } +} + +// logRequest captures information from a handler handling a request, and generates logs +// using this information. +func logRequest(logger *zap.Logger, handler http.Handler, w http.ResponseWriter, req *http.Request) { + message, fields := captureZapFieldsForRequest(handler, w, req) + logger.Info(message, fields...) +} + +// captureZapFieldsForRequest handles a request and captures fields for zap logger. +func captureZapFieldsForRequest(handler http.Handler, w http.ResponseWriter, req *http.Request) (string, []zap.Field) { + resp := httpsnoop.CaptureMetrics(handler, w, req) + + domain, port, err := net.SplitHostPort(req.Host) + if err != nil { + domain = req.Host + } + if ip := net.ParseIP(domain); ip != nil && ip.To16() != nil && ip.To4() == nil { + // For ECS, if the host part of an url is an IPv6, it must keep the brackets + // when stored in `url.domain` (but not when stored in ip fields). + domain = "[" + domain + "]" + } + sourceHost, _, err := net.SplitHostPort(req.RemoteAddr) + if err != nil { + sourceHost = req.RemoteAddr + } + fields := []zap.Field{ + // Request fields. + zap.String("source.address", sourceHost), + zap.String("http.request.method", req.Method), + zap.String("url.path", req.URL.Path), + zap.String("url.domain", domain), + + // Response fields. + zap.Int("http.response.code", resp.Code), + zap.Int64("http.response.body.bytes", resp.Written), + zap.Int64("event.duration", resp.Duration.Nanoseconds()), + } + + // Fields that are not always available. + if ip := net.ParseIP(sourceHost); ip != nil { + fields = append(fields, zap.String("source.ip", sourceHost)) + } else { + fields = append(fields, zap.String("source.domain", sourceHost)) + } + if referer := req.Referer(); referer != "" { + fields = append(fields, zap.String("http.request.referer", referer)) + } + if userAgent := req.UserAgent(); userAgent != "" { + fields = append(fields, zap.String("user_agent.original", userAgent)) + } + if query := req.URL.RawQuery; query != "" { + fields = append(fields, zap.String("url.query", query)) + } + if port != "" { + if intPort, err := strconv.Atoi(port); err == nil && intPort != 0 { + fields = append(fields, zap.Int("url.port", intPort)) + } + } + + message := req.Method + " " + req.URL.Path + " " + req.Proto + return message, fields +} diff --git a/util/logging_test.go b/util/logging_test.go new file mode 100644 index 000000000..251d5c313 --- /dev/null +++ b/util/logging_test.go @@ -0,0 +1,172 @@ +// Copyright Elasticsearch B.V. and/or licensed to Elasticsearch B.V. under one +// or more contributor license agreements. Licensed under the Elastic License; +// you may not use this file except in compliance with the Elastic License. + +package util + +import ( + "net/http" + "net/http/httptest" + "testing" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + "go.uber.org/zap" +) + +func TestCaptureZapFieldsForRequest(t *testing.T) { + cases := []struct { + title string + method string + url string + remoteAddress string + handler http.Handler + expectedMessage string + expectedFields []zap.Field + }{ + { + title: "Normal GET", + handler: http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) { + w.Write([]byte("Hello!")) + }), + method: "GET", + url: "http://epr.elastic.co/search?package=foo&all=true", + remoteAddress: "233.252.0.252:33442", + expectedMessage: "GET /search HTTP/1.1", + expectedFields: []zap.Field{ + zap.Int64("http.response.code", 200), + zap.Int("http.response.body.bytes", 6), + zap.String("http.request.method", "GET"), + zap.String("source.address", "233.252.0.252"), + zap.String("source.ip", "233.252.0.252"), + zap.String("url.domain", "epr.elastic.co"), + zap.String("url.path", "/search"), + zap.String("url.query", "package=foo&all=true"), + }, + }, + { + title: "404", + handler: http.NotFoundHandler(), + method: "GET", + url: "http://epr.elastic.co/foo", + remoteAddress: "233.252.0.252:33442", + expectedMessage: "GET /foo HTTP/1.1", + expectedFields: []zap.Field{ + zap.Int64("http.response.code", 404), + zap.Int("http.response.body.bytes", 19), + zap.String("http.request.method", "GET"), + zap.String("source.address", "233.252.0.252"), + zap.String("source.ip", "233.252.0.252"), + zap.String("url.domain", "epr.elastic.co"), + zap.String("url.path", "/foo"), + }, + }, + { + title: "Empty response on 500 error", + handler: http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) { + w.WriteHeader(http.StatusInternalServerError) + }), + method: "OPTIONS", + url: "http://epr.elastic.co/search", + remoteAddress: "233.252.0.252:33442", + expectedMessage: "OPTIONS /search HTTP/1.1", + expectedFields: []zap.Field{ + zap.Int64("http.response.code", 500), + zap.Int("http.response.body.bytes", 0), + zap.String("http.request.method", "OPTIONS"), + zap.String("source.address", "233.252.0.252"), + zap.String("source.ip", "233.252.0.252"), + zap.String("url.domain", "epr.elastic.co"), + zap.String("url.path", "/search"), + }, + }, + { + title: "IPv4 address", + handler: http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) { + w.Write([]byte("Hello!")) + }), + method: "GET", + url: "http://233.252.0.10:8080/search?package=foo&all=true", + remoteAddress: "233.252.0.252:33442", + expectedMessage: "GET /search HTTP/1.1", + expectedFields: []zap.Field{ + zap.Int64("http.response.code", 200), + zap.Int("http.response.body.bytes", 6), + zap.String("http.request.method", "GET"), + zap.String("source.address", "233.252.0.252"), + zap.String("source.ip", "233.252.0.252"), + zap.String("url.domain", "233.252.0.10"), + zap.Int("url.port", 8080), + zap.String("url.path", "/search"), + zap.String("url.query", "package=foo&all=true"), + }, + }, + { + title: "IPv6 address", + handler: http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) { + w.Write([]byte("Hello!")) + }), + method: "GET", + url: "http://[2001:0DB8::10]/search?package=foo&all=true", + remoteAddress: "[2001:0DB8::CAFE]:33442", + expectedMessage: "GET /search HTTP/1.1", + expectedFields: []zap.Field{ + zap.Int64("http.response.code", 200), + zap.Int("http.response.body.bytes", 6), + zap.String("http.request.method", "GET"), + zap.String("source.address", "2001:0DB8::CAFE"), + zap.String("source.ip", "2001:0DB8::CAFE"), + zap.String("url.domain", "[2001:0DB8::10]"), + zap.String("url.path", "/search"), + zap.String("url.query", "package=foo&all=true"), + }, + }, + } + + for _, c := range cases { + t.Run(c.title, func(t *testing.T) { + req, err := http.NewRequest(c.method, c.url, nil) + require.NoError(t, err) + req.RemoteAddr = c.remoteAddress + + recorder := httptest.NewRecorder() + message, fields := captureZapFieldsForRequest(c.handler, recorder, req) + + // Check only that event.duration is there, and drop it. + durationFound := false + for i, f := range fields { + if f.Key == "event.duration" { + fields = append(fields[:i], fields[i+1:]...) + durationFound = true + } + } + assert.True(t, durationFound, "event.duration expected") + + // Check message. + assert.Equal(t, c.expectedMessage, message) + + // Check fields. + for _, expected := range c.expectedFields { + found := false + for _, field := range fields { + if field.Key == expected.Key { + assert.Equal(t, expected, field, "field "+expected.Key) + found = true + break + } + } + assert.True(t, found, expected.Key+" not found") + } + for _, field := range fields { + found := false + for _, expected := range c.expectedFields { + if field.Key == expected.Key { + found = true + break + } + } + assert.True(t, found, field.Key+" not expected") + } + }) + } +}