Adding proxy-logging to the pipeline is not enough for access logging

[David Hill]

Adding proxy-logging to the pipeline is not enough for access logging.

According to this chunk of code:
  108 access_log_conf = {}
  109 for key in ('log_facility', 'log_name', 'log_level', 'log_udp_host',
  110 'log_udp_port', 'log_statsd_host', 'log_statsd_port',
  111 'log_statsd_default_sample_rate',
  112 'log_statsd_sample_rate_factor',
  113 'log_statsd_metric_prefix'):
  114 value = conf.get('access_' + key, conf.get(key, None))
  115 if value:
  116 access_log_conf[key] = value
  117 self.access_logger = logger or get_logger(access_log_conf,
  118 log_route='proxy-access')

http://fossies.org/linux/swift/swift/common/middleware/proxy_logging.py

The following configuration parameter are required to turn it on:

access_log_facility
access_log_level

Dave

[clayg (clay-gerrard)]

So the proxy-logging middleware is there to emit access long lines at the INFO level to the configured logger - you don't *have* to configure a separate access logger - most of the time the middleware will just use logger already configured for your proxy server.

You can even do some syslog config to redirect *just* INFO lines on the configured log_facility to a separate file so you have a "access.log" that you can use just for processing proxy request logs.

But there's a *few* other messages the proxy daemon will also log at INFO level. So you have the *option* of *also* configuring a *separate* logger instance that will *only* be used for access log messages. You can set that to a different facility if it simplifies your syslog config to redirect those to a different file that is just for access logs - if you want - it's an option.

You may have known all of that. Or maybe it's no longer working as intended. I'm not really sure what the bug being reported is exactly?

[David Hill (david-hill-ubisoft)]

Well, no matter what we've tried , until we defined access_log_facility and access_log_level in the swift proxy configuration file, no access requests were logged. This is more or less obvious when we expect that adding proxy-logging to the pipeline should log something to the default syslog facillity... If you deem this is not a bug, you can close this bug report ... but google will index this and may help some other people save some time...

[clayg (clay-gerrard)]

oh, ok - that's very helpful - thanks for clarifying that for me.

I guess I didn't read your initial report correctly because there's so many counter examples to the issue you experienced - where configurations which do NOT provide a value for those configuration options still get the proxy-logging middleware to emit access logs.

Sounds like you experienced a strange behavior indeed - but I'd need more information to understand what was going on. It may very well be a bug. Or a weird interaction between multiple issues. Or even a simple mis-configuration. I'm not syslog/ops expert - but others can probably help.

Can you say which syslog daemon you're running (popular choices rsyslog or syslog-ng), and provide their configuration files as well as your proyx-server configuration file(s)?

Swift folks hang out on freenode in #openstack-swift if you're available to join for some more interactive QA - we can always post more information here.

[David Hill (david-hill-ubisoft)]

We have a default swift configuration and I've managed to catch all syslog message within a fifo pipe in order to debug this. By reading the chunk of code I pasted in the initial report, I've noticed that access_* wasn't set at all anywhere and there's no default configuration to access_* log configuration parameters. When I added the listed 2 parameter, I started receiving the syslog notifications.

It's indeed rsyslog running on ubuntu. In all the configuration examples I've looked at so far, access_* is never set anywhere so I assumed that by adding proxy-logging to the pipeline, it should log the acccesses out of the box but it appears it didn't.

[David Hill (david-hill-ubisoft)]

This comment here (https://github.com/openstack/swift/blob/icehouse-eol/etc/proxy-server.conf-sample)
# If not set, logging directives from [DEFAULT] without "access_" will be used
# access_log_name = swift
# access_log_facility = LOG_LOCAL0
# access_log_level = INFO
# access_log_address = /dev/log

is confusing as it didn't use the [DEFAULT] configuration settings we added (log_name, log_facility, log_level)

[clayg (clay-gerrard)]

Thank you for the additional information.

With a proxy server config like this:

    [DEFAULT]
    user = vagrant
    bind_port = 8080
    log_facility = LOG_LOCAL1

    [pipeline:main]
    pipeline = proxy-logging proxy-server

    [filter:proxy-logging]
    use = egg:swift#proxy_logging

    [app:proxy-server]
    use = egg:swift#proxy

... and an rsyslog.d/10_swift.conf file like this:

    local1.info /var/log/swift/proxy_access.log

I get lines in /var/log/swift/proxy_access.log like this:

    Jul 22 19:44:17 saio proxy-server: 127.0.0.1 127.0.0.1 22/Jul/2015/19/44/17 GET /info HTTP/1.0 200 - curl/7.35.0 - - 549 - tx205769e99f9641d28947c-0055aff291 - 0.0006 - - 1437594257.211971045 1437594257.212539911 -

I'm not sure if this demonstrates or contradicts the issue you've experienced. But it does look like what I would describe as "access logging" and you will note the provided configuration does not include any options prefixed with "access_".

I this point, without having seen the config, I would hazard a *guess* that maybe you set log_facility in the DEFAULT section, but *also* set log_facility to something *different* in the filter:proxy-logging and expected the log_facility option in that section to override the DEFAULT - but unfortunately it does not unless you use a special paste configuration syntax [1].

Using the access_log_facility option is another good option since the swift code will use that with higher precedence that the DEFAULT option which shadows the local option of the same name.

1. http://docs.openstack.org/developer/swift/deployment_guide.html?highlight=paste%20set%20default%20option#general-server-configuration

[David Hill (david-hill-ubisoft)]

Well, the lines are commented out in [filter:proxy-logging] and were only defined in the [DEFAULT] part without the "access_" part ... and it didn't work. Perhaps there's something about the packages/configuration files that is weird ... anyhow, if it's only affecting this setup, I guess you can close this bug report.