Logs: Add request_id on debug #1156
Merged
Conversation
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
eloycoto
force-pushed
the
Customlogging
branch
2 times, most recently
from
1ca4cc0 to
1552838
Compare
davidor
reviewed
Jan 17, 2020
t/apicast-log.t
Outdated
| use lib 't'; | ||
| use Test::APIcast::Blackbox 'no_plan'; | ||
|
|
||
| # Can't run twice because one of the test checks the contents of the cache, and |
There was a problem hiding this comment.
This does not apply to this test file, right?
t/apicast-log.t
Outdated
|
|
||
|
|
||
|
|
||
| === TEST 2: Custom logs are not present if LOG_LEVEL!=debug. |
There was a problem hiding this comment.
Should it mention "request id" instead of custom logs to be more clear?
|
|
||
| _M.log = send_log | ||
|
|
||
| function _M:patch_ngx_log() |
There was a problem hiding this comment.
Shouldn't this function be local?
There was a problem hiding this comment.
I make it public if in the future we want to patch in any case, or support wants to add always, etc.
gateway/src/resty/log/log.lua
Outdated
|
|
||
| -- Only append the request_id if it's a request, if not will raise an | ||
| -- exception. | ||
| local r = is_valid_request() |
There was a problem hiding this comment.
We could use this without assigning it to a var, right? Te name of the var is not informative, but the name of the function is.
t/apicast-log.t
Outdated
| yay, api backend: test:$TEST_NGINX_SERVER_PORT | ||
| --- error_code: 200 | ||
| --- error_log | ||
| requestID= |
There was a problem hiding this comment.
Would be good to check more parts of the response. At least to make it clear that the requestID is written at the end of the line.
gateway/src/resty/log/log.lua
Outdated
| end | ||
|
|
||
| local id = C.ngx_http_lua_ffi_req_get_method(r) | ||
| if id == FFI_BAD_CONTEXT then |
There was a problem hiding this comment.
This can be simplified to return id != FFI_BAD_CONTEXT.
When running APICast with a lot of requests is hard to know what log is from each HTTP request, and it's hard to grep the logs easily. This PR, patch ngx.log to use a custom implementation in Lua, that provides the same info, but it appends a request_id in all log messages produced by Lua, so it's easy to understand what happens. This feature has a performance impact, so this is only enabled in *debug* log level, so users will not be affected at all. Sadly, some Nginx errors will not change, the HTTP log handler[1] does not allow any outside interaction, but hopefully, this will help to debug some complex scenarios like THREESCALE-4078 Example log request: ```` 2020/01/17 11:23:11 [debug] 1377#1377: *9 executor.lua:26: rewrite(): executor phase: rewrite, requestID=547d2de951bb8a27912fd39327e0f9e8 2020/01/17 11:23:11 [debug] 1377#1377: *9 policy_chain.lua:199: rewrite(): policy chain execute phase: rewrite, policy: Load Configuration, i: 1, requestID=547d2de951bb8a27912fd39327e0f9e8 2020/01/17 11:23:11 [debug] 1377#1377: *9 policy_chain.lua:199: rewrite(): policy chain execute phase: rewrite, policy: Find Service Policy, i: 2, requestID=547d2de951bb8a27912fd39327e0f9e8 2020/01/17 11:23:11 [warn] 1377#1377: *9 find_service.lua:43: Using service id=42, requestID=547d2de951bb8a27912fd39327e0f9e8, client: 172.19.0.1, server: _, request: "GET /lola/?user_key=132&sleep=1 HTTP/1.1", host: "one" 2020/01/17 11:23:11 [debug] 1377#1377: *9 policy_chain.lua:199: rewrite(): policy chain execute phase: rewrite, policy: Local Policy Chain, i: 3, requestID=547d2de951bb8a27912fd39327e0f9e8 2020/01/17 11:23:11 [debug] 1377#1377: *9 env.lua:86: fetch(): env: APICAST_BACKEND_CACHE_HANDLER = nil, requestID=547d2de951bb8a27912fd39327e0f9e8 2020/01/17 11:23:11 [debug] 1377#1377: *9 cache_handler.lua:23: new(): backend cache handler: strict, requestID=547d2de951bb8a27912fd39327e0f9e8 2020/01/17 11:23:11 [debug] 1377#1377: *9 policy_chain.lua:199: rewrite(): policy chain execute phase: rewrite, policy: APIcast, i: 1, requestID=547d2de951bb8a27912fd39327e0f9e8 2020/01/17 11:23:11 [debug] 1377#1377: *9 service.lua:236: get_usage(): [mapping] service 42 has 1 rules, requestID=547d2de951bb8a27912fd39327e0f9e8 2020/01/17 11:23:11 [debug] 1377#1377: *9 policy_chain.lua:199: rewrite(): policy chain execute phase: rewrite, policy: Metrics, i: 4, requestID=547d2de951bb8a27912fd39327e0f9e8 2020/01/17 11:23:11 [debug] 1377#1377: *9 executor.lua:26: access(): executor phase: access, requestID=547d2de951bb8a27912fd39327e0f9e8 2020/01/17 11:23:11 [debug] 1377#1377: *9 policy_chain.lua:199: access(): policy chain execute phase: access, policy: Load Configuration, i: 1, requestID=547d2de951bb8a27912fd39327e0f9e8 2020/01/17 11:23:11 [debug] 1377#1377: *9 policy_chain.lua:199: access(): policy chain execute phase: access, policy: Find Service Policy, i: 2, requestID=547d2de951bb8a27912fd39327e0f9e8 2020/01/17 11:23:11 [debug] 1377#1377: *9 policy_chain.lua:199: access(): policy chain execute phase: access, policy: Local Policy Chain, i: 3, requestID=547d2de951bb8a27912fd39327e0f9e8 2020/01/17 11:23:11 [debug] 1377#1377: *9 policy_chain.lua:199: policy chain execute phase: access, policy: APIcast, i: 1, requestID=547d2de951bb8a27912fd39327e0f9e8 2020/01/17 11:23:11 [info] 1377#1377: *9 proxy.lua:82: output_debug_headers(): usage: usage%5Bhits%5D=2 credentials: user_key=132, requestID=547d2de951bb8a27912fd39327e0f9e8, client: 172.19.0.1, server: _, request: "GET /lola/?user_key=132&sleep=1 HTTP/1.1", host: "one" 2020/01/17 11:23:11 [info] 1377#1377: *9 proxy.lua:136: apicast cache miss key: 42:132:usage%5Bhits%5D=2 value: nil, requestID=547d2de951bb8a27912fd39327e0f9e8, client: 172.19.0.1, server: _, request: "GET /lola/?user_key=132&sleep=1 HTTP/1.1", host: "one" 2020/01/17 11:23:11 [debug] 1377#1377: *9 resolver.lua:195: new(): resolver search domains: , requestID=547d2de951bb8a27912fd39327e0f9e8 2020/01/17 11:23:11 [debug] 1377#1377: *9 resolver.lua:326: lookup(): resolver query: echo-api.3scale.net, requestID=547d2de951bb8a27912fd39327e0f9e8 2020/01/17 11:23:11 [debug] 1377#1377: *9 cache.lua:122: fetch_answers(): resolver cache miss echo-api.3scale.net, requestID=547d2de951bb8a27912fd39327e0f9e8 2020/01/17 11:23:11 [debug] 1377#1377: *9 cache.lua:188: get(): resolver cache miss: echo-api.3scale.net, requestID=547d2de951bb8a27912fd39327e0f9e8 2020/01/17 11:23:11 [debug] 1377#1377: *9 resolver.lua:292: search_dns(): resolver query: echo-api.3scale.net search: query: echo-api.3scale.net., requestID=547d2de951bb8a27912fd39327e0f9e8 2020/01/17 11:23:11 [debug] 1377#1377: *9 cache.lua:122: fetch_answers(): resolver cache miss echo-api.3scale.net., requestID=547d2de951bb8a27912fd39327e0f9e8 2020/01/17 11:23:11 [debug] 1377#1377: *9 cache.lua:188: get(): resolver cache miss: echo-api.3scale.net., requestID=547d2de951bb8a27912fd39327e0f9e8 2020/01/17 11:23:11 [debug] 1377#1377: *9 dns_client.lua:43: init_resolvers(): initializing 2 nameservers, requestID=547d2de951bb8a27912fd39327e0f9e8 2020/01/17 11:23:11 [debug] 1377#1377: *9 dns_client.lua:56: init_resolvers(): nameserver 127.0.0.11:53 initialized, requestID=547d2de951bb8a27912fd39327e0f9e8 2020/01/17 11:23:11 [debug] 1377#1377: *9 dns_client.lua:56: init_resolvers(): nameserver 127.0.0.11:53 initialized, requestID=547d2de951bb8a27912fd39327e0f9e8 2020/01/17 11:23:11 [debug] 1377#1377: *9 dns_client.lua:68: query(): resolver query: echo-api.3scale.net. nameserver: 127.0.0.11:53, requestID=547d2de951bb8a27912fd39327e0f9e8 2020/01/17 11:23:11 [debug] 1377#1377: *9 cache.lua:74: store(): resolver cache write echo-api.3scale.net with TLL 300, requestID=547d2de951bb8a27912fd39327e0f9e8 2020/01/17 11:23:11 [debug] 1377#1377: *9 cache.lua:74: store(): resolver cache write tf-lb-0081dad066b2afef5328e0256a-2081992367.us-east-1.elb.amazonaws.com with TLL 60, requestID=547d2de951bb8a27912fd39327e0f9e8 2020/01/17 11:23:11 [debug] 1377#1377: *9 resolver.lua:346: lookup(): resolver query: echo-api.3scale.net finished with 3 answers, requestID=547d2de951bb8a27912fd39327e0f9e8 2020/01/17 11:23:11 [debug] 1377#1377: *9 resolver.lua:386: get_servers(): query for echo-api.3scale.net finished with 3 answers, requestID=547d2de951bb8a27912fd39327e0f9e8 2020/01/17 11:23:11 [debug] 1377#1377: *9 resolver.lua:326: lookup(): resolver query: 54.86.250.161, requestID=547d2de951bb8a27912fd39327e0f9e8 2020/01/17 11:23:11 [debug] 1377#1377: *9 resolver.lua:331: lookup(): host is ip address: 54.86.250.161, requestID=547d2de951bb8a27912fd39327e0f9e8 ``` Signed-off-by: Eloy Coto <[email protected]>
eloycoto
force-pushed
the
Customlogging
branch
from
1552838 to
c5c2361
Compare
davidor
approved these changes
Jan 23, 2020
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
When running APICast with a lot of requests is hard to know what log is
from each HTTP request, and it's hard to grep the logs easily.
This PR, patch ngx.log to use a custom implementation in Lua, that
provides the same info, but it appends a request_id in all log messages
produced by Lua, so it's easy to understand what happens.
This feature has a performance impact, so this is only enabled in
debug log level, so users will not be affected at all.
Sadly, some Nginx errors will not change, the HTTP log handler[1] does
not allow any outside interaction, but hopefully, this will help to
debug some complex scenarios like THREESCALE-4078
Example log request: