Skip to content

log: Add "%_" to print message with escaped newlines#13832

Merged
mattklein123 merged 15 commits intoenvoyproxy:masterfrom
dio:log-custom-flag
Nov 12, 2020
Merged

log: Add "%_" to print message with escaped newlines#13832
mattklein123 merged 15 commits intoenvoyproxy:masterfrom
dio:log-custom-flag

Conversation

@dio
Copy link
Copy Markdown
Member

@dio dio commented Oct 30, 2020

Commit Message: This patch adds a new custom flag %_ to the log pattern to print the actual message to log, but with escaped newlines.

Additional description: This escapes newlines for the msg.payload part only, not the whole log line. Further description of the use case: #13636.
Risk Level: Low
Testing: Unit
Docs Changes: Updated
Release Notes: Added
Fixes #13636.

Signed-off-by: Dhi Aurrahman dio@tetrate.io

dio added 2 commits October 30, 2020 13:52
This patch adds a new custom flag `%_` to the log pattern to print the
actual message to log, but with escaped newlines.

Signed-off-by: Dhi Aurrahman <dio@tetrate.io>
Signed-off-by: Dhi Aurrahman <dio@tetrate.io>
@dio
Copy link
Copy Markdown
Member Author

dio commented Oct 30, 2020

In my local, running envoy with this patch applied:

$ envoy -c configs/envoyproxy_io_proxy.yaml --log-format '{"level":"%l","time":"%Y-%m-%dT%T.%fZ","scope":"%n","msg":"%_"}' 2>&1 
{"level":"info","time":"2020-10-30T14:11:13.909652Z","scope":"main","msg":"initializing epoch 0 (base id=0, hot restart version=11.104)"}
{"level":"info","time":"2020-10-30T14:11:13.909748Z","scope":"main","msg":"statically linked extensions:"}
{"level":"info","time":"2020-10-30T14:11:13.909794Z","scope":"main","msg":"  envoy.filters.network: envoy.client_ssl_auth, envoy.echo, envoy.ext_authz, envoy.filters.network.client_ssl_auth, envoy.filters.network.direct_response, envoy.filters.network.dubbo_proxy, envoy.filters.network.echo, envoy.filters.network.ext_authz, envoy.filters.network.http_connection_manager, envoy.filters.network.kafka_broker, envoy.filters.network.local_ratelimit, envoy.filters.network.mongo_proxy, envoy.filters.network.mysql_proxy, envoy.filters.network.postgres_proxy, envoy.filters.network.ratelimit, envoy.filters.network.rbac, envoy.filters.network.redis_proxy, envoy.filters.network.rocketmq_proxy, envoy.filters.network.sni_cluster, envoy.filters.network.sni_dynamic_forward_proxy, envoy.filters.network.tcp_proxy, envoy.filters.network.thrift_proxy, envoy.filters.network.wasm, envoy.filters.network.zookeeper_proxy, envoy.http_connection_manager, envoy.mongo_proxy, envoy.ratelimit, envoy.redis_proxy, envoy.tcp_proxy"}
{"level":"info","time":"2020-10-30T14:11:13.909825Z","scope":"main","msg":"  envoy.udp_packet_writers: udp_default_writer, udp_gso_batch_writer"}
{"level":"info","time":"2020-10-30T14:11:13.909844Z","scope":"main","msg":"  envoy.resolvers: envoy.ip"}
{"level":"info","time":"2020-10-30T14:11:13.909861Z","scope":"main","msg":"  envoy.guarddog_actions: envoy.watchdog.abort_action, envoy.watchdog.profile_action"}
{"level":"info","time":"2020-10-30T14:11:13.909879Z","scope":"main","msg":"  envoy.bootstrap: envoy.bootstrap.wasm, envoy.extensions.network.socket_interface.default_socket_interface"}
{"level":"info","time":"2020-10-30T14:11:13.909901Z","scope":"main","msg":"  envoy.stats_sinks: envoy.dog_statsd, envoy.metrics_service, envoy.stat_sinks.dog_statsd, envoy.stat_sinks.hystrix, envoy.stat_sinks.metrics_service, envoy.stat_sinks.statsd, envoy.stat_sinks.wasm, envoy.statsd"}
{"level":"info","time":"2020-10-30T14:11:13.909930Z","scope":"main","msg":"  envoy.filters.listener: envoy.filters.listener.http_inspector, envoy.filters.listener.original_dst, envoy.filters.listener.original_src, envoy.filters.listener.proxy_protocol, envoy.filters.listener.tls_inspector, envoy.listener.http_inspector, envoy.listener.original_dst, envoy.listener.original_src, envoy.listener.proxy_protocol, envoy.listener.tls_inspector"}
{"level":"info","time":"2020-10-30T14:11:13.909981Z","scope":"main","msg":"  envoy.access_loggers: envoy.access_loggers.file, envoy.access_loggers.http_grpc, envoy.access_loggers.tcp_grpc, envoy.access_loggers.wasm, envoy.file_access_log, envoy.http_grpc_access_log, envoy.tcp_grpc_access_log, envoy.wasm_access_log"}
{"level":"info","time":"2020-10-30T14:11:13.910005Z","scope":"main","msg":"  envoy.retry_host_predicates: envoy.retry_host_predicates.omit_canary_hosts, envoy.retry_host_predicates.omit_host_metadata, envoy.retry_host_predicates.previous_hosts"}
{"level":"info","time":"2020-10-30T14:11:13.910023Z","scope":"main","msg":"  envoy.http.cache: envoy.extensions.http.cache.simple"}
{"level":"info","time":"2020-10-30T14:11:13.910040Z","scope":"main","msg":"  envoy.dubbo_proxy.protocols: dubbo"}
{"level":"info","time":"2020-10-30T14:11:13.910057Z","scope":"main","msg":"  envoy.dubbo_proxy.route_matchers: default"}
{"level":"info","time":"2020-10-30T14:11:13.910076Z","scope":"main","msg":"  envoy.compression.compressor: envoy.compression.gzip.compressor"}
{"level":"info","time":"2020-10-30T14:11:13.910094Z","scope":"main","msg":"  envoy.quic_client_codec: quiche"}
{"level":"info","time":"2020-10-30T14:11:13.910115Z","scope":"main","msg":"  envoy.thrift_proxy.protocols: auto, binary, binary/non-strict, compact, twitter"}
{"level":"info","time":"2020-10-30T14:11:13.910135Z","scope":"main","msg":"  envoy.compression.decompressor: envoy.compression.gzip.decompressor"}
{"level":"info","time":"2020-10-30T14:11:13.910156Z","scope":"main","msg":"  envoy.quic_server_codec: quiche"}
{"level":"info","time":"2020-10-30T14:11:13.910174Z","scope":"main","msg":"  envoy.dubbo_proxy.filters: envoy.filters.dubbo.router"}
{"level":"info","time":"2020-10-30T14:11:13.910194Z","scope":"main","msg":"  envoy.transport_sockets.downstream: envoy.transport_sockets.alts, envoy.transport_sockets.quic, envoy.transport_sockets.raw_buffer, envoy.transport_sockets.tap, envoy.transport_sockets.tls, raw_buffer, tls"}
{"level":"info","time":"2020-10-30T14:11:13.910259Z","scope":"main","msg":"  envoy.filters.http: envoy.buffer, envoy.cors, envoy.csrf, envoy.ext_authz, envoy.fault, envoy.filters.http.adaptive_concurrency, envoy.filters.http.admission_control, envoy.filters.http.aws_lambda, envoy.filters.http.aws_request_signing, envoy.filters.http.buffer, envoy.filters.http.cache, envoy.filters.http.cdn_loop, envoy.filters.http.compressor, envoy.filters.http.cors, envoy.filters.http.csrf, envoy.filters.http.decompressor, envoy.filters.http.dynamic_forward_proxy, envoy.filters.http.dynamo, envoy.filters.http.ext_authz, envoy.filters.http.fault, envoy.filters.http.grpc_http1_bridge, envoy.filters.http.grpc_http1_reverse_bridge, envoy.filters.http.grpc_json_transcoder, envoy.filters.http.grpc_stats, envoy.filters.http.grpc_web, envoy.filters.http.gzip, envoy.filters.http.header_to_metadata, envoy.filters.http.health_check, envoy.filters.http.ip_tagging, envoy.filters.http.jwt_authn, envoy.filters.http.local_ratelimit, envoy.filters.http.lua, envoy.filters.http.oauth2, envoy.filters.http.on_demand, envoy.filters.http.original_src, envoy.filters.http.ratelimit, envoy.filters.http.rbac, envoy.filters.http.router, envoy.filters.http.squash, envoy.filters.http.tap, envoy.filters.http.wasm, envoy.grpc_http1_bridge, envoy.grpc_json_transcoder, envoy.grpc_web, envoy.gzip, envoy.health_check, envoy.http_dynamo_filter, envoy.ip_tagging, envoy.local_rate_limit, envoy.lua, envoy.rate_limit, envoy.router, envoy.squash"}
{"level":"info","time":"2020-10-30T14:11:13.910316Z","scope":"main","msg":"  envoy.thrift_proxy.filters: envoy.filters.thrift.rate_limit, envoy.filters.thrift.router"}
{"level":"info","time":"2020-10-30T14:11:13.910336Z","scope":"main","msg":"  envoy.health_checkers: envoy.health_checkers.redis"}
{"level":"info","time":"2020-10-30T14:11:13.910355Z","scope":"main","msg":"  envoy.resource_monitors: envoy.resource_monitors.fixed_heap, envoy.resource_monitors.injected_resource"}
{"level":"info","time":"2020-10-30T14:11:13.910374Z","scope":"main","msg":"  envoy.retry_priorities: envoy.retry_priorities.previous_priorities"}
{"level":"info","time":"2020-10-30T14:11:13.910396Z","scope":"main","msg":"  envoy.transport_sockets.upstream: envoy.transport_sockets.alts, envoy.transport_sockets.quic, envoy.transport_sockets.raw_buffer, envoy.transport_sockets.tap, envoy.transport_sockets.tls, envoy.transport_sockets.upstream_proxy_protocol, raw_buffer, tls"}
{"level":"info","time":"2020-10-30T14:11:13.910424Z","scope":"main","msg":"  envoy.clusters: envoy.cluster.eds, envoy.cluster.logical_dns, envoy.cluster.original_dst, envoy.cluster.static, envoy.cluster.strict_dns, envoy.clusters.aggregate, envoy.clusters.dynamic_forward_proxy, envoy.clusters.redis"}
{"level":"info","time":"2020-10-30T14:11:13.910449Z","scope":"main","msg":"  envoy.upstreams: envoy.filters.connection_pools.http.generic, envoy.filters.connection_pools.http.http, envoy.filters.connection_pools.http.tcp"}
{"level":"info","time":"2020-10-30T14:11:13.910475Z","scope":"main","msg":"  envoy.tracers: envoy.dynamic.ot, envoy.lightstep, envoy.tracers.datadog, envoy.tracers.dynamic_ot, envoy.tracers.lightstep, envoy.tracers.opencensus, envoy.tracers.xray, envoy.tracers.zipkin, envoy.zipkin"}
{"level":"info","time":"2020-10-30T14:11:13.910499Z","scope":"main","msg":"  envoy.dubbo_proxy.serializers: dubbo.hessian2"}
{"level":"info","time":"2020-10-30T14:11:13.910518Z","scope":"main","msg":"  envoy.internal_redirect_predicates: envoy.internal_redirect_predicates.allow_listed_routes, envoy.internal_redirect_predicates.previous_routes, envoy.internal_redirect_predicates.safe_cross_scheme"}
{"level":"info","time":"2020-10-30T14:11:13.910541Z","scope":"main","msg":"  envoy.filters.udp_listener: envoy.filters.udp.dns_filter, envoy.filters.udp_listener.udp_proxy"}
{"level":"info","time":"2020-10-30T14:11:13.910563Z","scope":"main","msg":"  envoy.grpc_credentials: envoy.grpc_credentials.aws_iam, envoy.grpc_credentials.default, envoy.grpc_credentials.file_based_metadata"}
{"level":"info","time":"2020-10-30T14:11:13.910586Z","scope":"main","msg":"  envoy.thrift_proxy.transports: auto, framed, header, unframed"}
{"level":"info","time":"2020-10-30T14:11:13.910607Z","scope":"main","msg":"  envoy.udp_listeners: quiche_quic_listener, raw_udp_listener"}
{"level":"info","time":"2020-10-30T14:11:13.946745Z","scope":"main","msg":"HTTP header map info:"}
{"level":"warning","time":"2020-10-30T14:11:13.950333Z","scope":"runtime","msg":"Unable to use runtime singleton for feature envoy.http.headermap.lazy_map_min_size"}
{"level":"warning","time":"2020-10-30T14:11:13.950419Z","scope":"runtime","msg":"Unable to use runtime singleton for feature envoy.http.headermap.lazy_map_min_size"}
{"level":"warning","time":"2020-10-30T14:11:13.952510Z","scope":"runtime","msg":"Unable to use runtime singleton for feature envoy.http.headermap.lazy_map_min_size"}
{"level":"warning","time":"2020-10-30T14:11:13.952721Z","scope":"runtime","msg":"Unable to use runtime singleton for feature envoy.http.headermap.lazy_map_min_size"}
{"level":"info","time":"2020-10-30T14:11:13.952759Z","scope":"main","msg":"  request header map: 608 bytes: :authority,:method,:path,:protocol,:scheme,accept,accept-encoding,access-control-request-method,authorization,cache-control,cdn-loop,connection,content-encoding,content-length,content-type,expect,grpc-accept-encoding,grpc-timeout,if-match,if-modified-since,if-none-match,if-range,if-unmodified-since,keep-alive,origin,pragma,proxy-connection,referer,te,transfer-encoding,upgrade,user-agent,via,x-client-trace-id,x-envoy-attempt-count,x-envoy-decorator-operation,x-envoy-downstream-service-cluster,x-envoy-downstream-service-node,x-envoy-expected-rq-timeout-ms,x-envoy-external-address,x-envoy-force-trace,x-envoy-hedge-on-per-try-timeout,x-envoy-internal,x-envoy-ip-tags,x-envoy-max-retries,x-envoy-original-path,x-envoy-original-url,x-envoy-retriable-header-names,x-envoy-retriable-status-codes,x-envoy-retry-grpc-on,x-envoy-retry-on,x-envoy-upstream-alt-stat-name,x-envoy-upstream-rq-per-try-timeout-ms,x-envoy-upstream-rq-timeout-alt-response,x-envoy-upstream-rq-timeout-ms,x-forwarded-client-cert,x-forwarded-for,x-forwarded-proto,x-ot-span-context,x-request-id"}
{"level":"info","time":"2020-10-30T14:11:13.952793Z","scope":"main","msg":"  request trailer map: 128 bytes: "}
{"level":"info","time":"2020-10-30T14:11:13.952814Z","scope":"main","msg":"  response header map: 424 bytes: :status,access-control-allow-credentials,access-control-allow-headers,access-control-allow-methods,access-control-allow-origin,access-control-expose-headers,access-control-max-age,age,cache-control,connection,content-encoding,content-length,content-type,date,etag,expires,grpc-message,grpc-status,keep-alive,last-modified,location,proxy-connection,server,transfer-encoding,upgrade,vary,via,x-envoy-attempt-count,x-envoy-decorator-operation,x-envoy-degraded,x-envoy-immediate-health-check-fail,x-envoy-ratelimited,x-envoy-upstream-canary,x-envoy-upstream-healthchecked-cluster,x-envoy-upstream-service-time,x-request-id"}
{"level":"info","time":"2020-10-30T14:11:13.952849Z","scope":"main","msg":"  response trailer map: 152 bytes: grpc-message,grpc-status"}
{"level":"info","time":"2020-10-30T14:11:13.964908Z","scope":"main","msg":"admin address: 0.0.0.0:9901"}
{"level":"info","time":"2020-10-30T14:11:13.969130Z","scope":"main","msg":"runtime: layers:\n  - name: base\n    static_layer:\n      {}\n  - name: admin\n    admin_layer:\n      {}"}
{"level":"info","time":"2020-10-30T14:11:13.970201Z","scope":"config","msg":"loading tracing configuration"}
{"level":"info","time":"2020-10-30T14:11:13.970252Z","scope":"config","msg":"loading 0 static secret(s)"}
{"level":"info","time":"2020-10-30T14:11:13.970265Z","scope":"config","msg":"loading 1 cluster(s)"}
{"level":"info","time":"2020-10-30T14:11:13.986278Z","scope":"config","msg":"loading 1 listener(s)"}
{"level":"info","time":"2020-10-30T14:11:14.006558Z","scope":"config","msg":"loading stats sink configuration"}
{"level":"info","time":"2020-10-30T14:11:14.007562Z","scope":"main","msg":"starting main dispatch loop"}
{"level":"info","time":"2020-10-30T14:11:14.078132Z","scope":"runtime","msg":"RTDS has finished initialization"}
{"level":"info","time":"2020-10-30T14:11:14.078186Z","scope":"upstream","msg":"cm init: all clusters initialized"}
{"level":"info","time":"2020-10-30T14:11:14.078236Z","scope":"main","msg":"all clusters initialized. initializing init manager"}
{"level":"info","time":"2020-10-30T14:11:14.078290Z","scope":"config","msg":"all dependencies initialized. starting workers"}
{"level":"warning","time":"2020-10-30T14:11:14.079034Z","scope":"main","msg":"there is no configured limit to the number of allowed active connections. Set a limit via the runtime key overload.global_downstream_max_connections"}
^C{"level":"warning","time":"2020-10-30T14:11:16.046109Z","scope":"main","msg":"caught SIGINT"}
{"level":"info","time":"2020-10-30T14:11:16.046188Z","scope":"main","msg":"shutting down server instance"}
{"level":"info","time":"2020-10-30T14:11:16.046246Z","scope":"main","msg":"main dispatch loop exited"}
{"level":"info","time":"2020-10-30T14:11:16.050072Z","scope":"main","msg":"exiting"}

cc. @howardjohn

@dio dio marked this pull request as ready for review October 30, 2020 15:14
dio added 4 commits October 31, 2020 02:23
Signed-off-by: Dhi Aurrahman <dio@tetrate.io>
Signed-off-by: Dhi Aurrahman <dio@tetrate.io>
Signed-off-by: Dhi Aurrahman <dio@tetrate.io>
dio added 3 commits October 31, 2020 23:28
Signed-off-by: Dhi Aurrahman <dio@tetrate.io>
Signed-off-by: Dhi Aurrahman <dio@tetrate.io>
Signed-off-by: Dhi Aurrahman <dio@tetrate.io>
zuercher
zuercher previously approved these changes Nov 3, 2020
Copy link
Copy Markdown
Member

@zuercher zuercher left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

One nit, but otherwise looks good.

The supported format flags are (with example output):

:%v: The actual message to log ("some user text")
:%_: The actual message to log, but with escaped newlines (from (if using ``%v``) "some user text\nbelow", to "some user text\\nbelow")
Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

nit: Keep the spacing consistent?

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Oops. Updated. Thanks for the review!

Signed-off-by: Dhi Aurrahman <dio@tetrate.io>
dio added 3 commits November 4, 2020 00:38
Signed-off-by: Dhi Aurrahman <dio@tetrate.io>
Signed-off-by: Dhi Aurrahman <dio@tetrate.io>
@dio
Copy link
Copy Markdown
Member Author

dio commented Nov 4, 2020

@zuercher sorry for dismissing your review, there was a typo hence I introduced further changes. When you have time please take a look. Thanks!

@dio dio requested a review from zuercher November 5, 2020 02:35
@mattklein123 mattklein123 merged commit 15db921 into envoyproxy:master Nov 12, 2020
gargnupur pushed a commit to gargnupur/envoy that referenced this pull request Dec 10, 2020
This patch adds a new custom flag `%_` to the log pattern to print the
actual message to log, but with escaped newlines.

Signed-off-by: Dhi Aurrahman <dio@tetrate.io>
bianpengyuan pushed a commit to bianpengyuan/envoy that referenced this pull request Dec 11, 2020
This patch adds a new custom flag `%_` to the log pattern to print the
actual message to log, but with escaped newlines.

Signed-off-by: Dhi Aurrahman <dio@tetrate.io>
istio-testing pushed a commit to istio/envoy that referenced this pull request Dec 11, 2020
… (#288)

This patch adds a new custom flag `%_` to the log pattern to print the
actual message to log, but with escaped newlines.

Signed-off-by: Dhi Aurrahman <dio@tetrate.io>

Co-authored-by: Dhi Aurrahman <dio@tetrate.io>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

Allow json output for logging (not access logs)

3 participants