Upcoming smart proxy logging changes for 1.20

Development
1

This is a bit of an advertisment for my latest PR which I am trying to push into 1.20. Time is ticking! But it is also head up for you guys and to gather further feedback on this.

https://github.com/theforeman/smart-proxy/pull/611

This is continuation of improving logging for Foreman. This patch drops code which uses the simple Ruby logging and replaces it with logging gem which we also use in Foreman core. This brings new features for proxy, for example ability to send logs also to system journal with extended structured fields. I take advantage of this and send REQUEST id along with REMOTE_IP in the initial version of the patch. This is just for starters, in the future we can add more fields for example logs ORG/LOC NAME/ID but smart proxy doesn’t have that available at the moment (Foreman would need to send these along with each request).

The patch does not change behavior of existing configuration values, everything stays as-is. There is new configuration option tho: :log_file: JOURNAL and when set, journald logger is enabled. This weird configuration syntax will need an overhaul but I don’t wan to work on this since we are very close the branching date.

Rolling file appender stays as-is, it should keep 6 files with maximum size of 100 MB (it used to be only 10 MB which was a bit too low and no huge risk - it’s just extra 90 MB * 6). I have decided to change naming convention from proxy.1.log for old (rolled) files to proxy.181004.log which is based on year, month and day. File rolling is based on weekly basis because by default on production instance logging level is at WARN level and log files for proxy are rather empty (only errors).

I took the opportunity to improve logging in general.

I removed access log from stdout sent by webrick and moved logging of begin/end of requests into our own middleware logger which gives us more flexility (debug output, counting time spent in milliseconds similarly like Rails). Of course we also show request id for each individual line in log file (and syslog/journal). Example:

2018-10-04T15:21:52 c6846cfa [I] Started POST /features?test=1&abc=aaa
2018-10-04T15:21:52 c6846cfa [D] Headers: {"HTTP_HOST"=>"localhost:8448", "HTTP_USER_AGENT"=>"curl/7.59.0", "HTTP_ACCEPT"=>"*/*", "HTTP_VERSION"=>"HTTP/1.1"}
2018-10-04T15:21:52 c6846cfa [D] Body: fsdfdssfd
2018-10-04T15:21:52 c6846cfa [I] Finished POST /features (6.68 ms)

The patch also introduces trace logging call which is basically a DEBUG level but it is skipped unless environmental variable FOREMAN_TRACE is provided. Both lines above headers and body are trace-level calls so they are only visible when needed (during extensive debugging). New TraceDecorator singleton is available and used for all Webrick log messages which are kinda useless most of the time. They can still be enabled using FOREMAN_TRACE if needed:

2018-10-05T15:13:16  [D] accept: ::1:49682
2018-10-05T15:13:16  [D] Rack::Handler::WEBrick is invoked.
... application logs ...
2018-10-05T15:13:16  [D] close: ::1:49682

The format of the log line is not changing in this patch, the four columns (date/time, request id, level and message) remains the same, I just dropped milliseconds from time that’s the only change. But I removed Webrick’s noisy AccessLog reporting on the STDOUT which was actually unused in production as far as I can tell.

I vastly simplified LoggerFactory, I removed unit tests for factory tho which I find not very useful.

Proxy log decorator (the main logger object used through the application) now also responds to blocks correctly for faster execution when higher level is set. It also skips logging if message is empty so one can decide in the lazy-evaluated block to skip creating a log entry actually. This is used in the LoggerMiddleware for fastest possible logging of all requests.

All the work goes hand-in-hand with our overall logging initiative - logs gathered via journald can be configured via rsyslog/elasticsearch module to be sent over to central place for archival and indexing. For more info:

I am trying to hit Foreman 1.20 with this patch, review needed. Silent period starts next Monday. @ares @mmoll @tbrisker @ik5 @ekohl

2 Likes