logger 499 error - bug in Swift or bad code

[Gil Vernik]

I am not sure if it's something wrong I did or some bug. Here is the summary of what I did.

Consider the following proxy middleware - "logger-499" . This middleware does very minor things - it copy env to new variable, process the original request, than generate new request based on original env and return response back to the user.
I activate it by doing GET on some existing object . Here is the code of the middleware:
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
from swift.common.utils import get_logger, register_swift_info
from swift.common.swob import Request
from swift.common.wsgi import WSGIContext

class Logger499Context(WSGIContext):
    def __init__(self, wsgi_app):
        WSGIContext.__init__(self, wsgi_app)
        self.container_md = container_md

    def handle_original_call(self, env, start_response):
        app_resp = self._app_call(env)
        if self._response_headers is None:
            self._response_headers = []
        start_response(self._response_status,
                       self._response_headers,
                       self._response_exc_info)
        env['swift.original_status'] = self._get_status_int()
        return app_resp

class Logger499Middleware(object):
    def __init__(self, app, conf):
        self.app = app
        self.logger = get_logger(conf, log_route='logger_499')

    def __call__(self, env, start_response):
        '''
        Check the 499 error by doing GET on some existing object.
        If pipeline = ... proxy-logging logger-499... - ALL works fine. Logger prints 200 OK.
        If pipeline = ... logger-499 proxy-logger ... Then:
            Doing GET on existing object, logger will print two lines in log
            499 Error and 200 OK. Client never receive 499, only 200 OK.
        To re-solve this, I need to uncomment the # line. Have no idea why it solves it :)
        '''
        req = Request(env)
        try:
            (version, account, container, obj) = req.split_path(3, 4, True)
        except ValueError:
            return self.app(env, start_response)
        orig_env = req.environ.copy()
        ctx = Logger499Context(self.app)
        original_resp = ctx.handle_original_call(env, start_response)
        original_resp_status = env['swift.original_status']
        #env['swift.proxy_access_log_made'] = True
        del env['swift.original_status']
        ctx = Logger499Context(self.app)
        return ctx.handle_original_call(orig_env, start_response)

def filter_factory(global_conf, **local_conf):
    conf = global_conf.copy()
    conf.update(local_conf)
    swift_info = {}
    register_swift_info('logger_499', False, **swift_info)

    def logger_499_filter(app):
        return Logger499Middleware(app, conf)
    return logger_499_filter

----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
This middleware does very minor things - it copy env to new variable, process the original request, than generate new request based on original env and return response back to the user.
I then activate it by doing GET on existing object

Here is the problem:

If pipeline defined as :

pipeline = .... proxy-logging logger-499 .... proxy-server
Than all works fine and logger prints a single line into proxy-log :

Mar 30 13:47:34 my-laptop proxy-server: 127.0.0.1 127.0.0.1 30/Mar/2014/11/47/34 GET /v1/AUTH_test/contold17031/DSC_0266.JPG HTTP/1.0 200 - - AUTH_tk9331e2ba1b06499e974799f6e6f9a645 - 2730257 -
tx1ffba725a1c347798a2ce-0053380456 - 0.0985 - - 1396180054.443357944 1396180054.541863918

BUT, if I change position of proxy-logging and logger-499, making pipeline to be as
**********************************************************************************************************************
pipeline = .... logger-499 proxy-logging .... proxy-server
Then if I do the same GET i am getting

Mar 30 13:47:34 my-laptop proxy-server: 127.0.0.1 127.0.0.1 30/Mar/2014/11/47/34 GET /v1/AUTH_test/contold17031/DSC_0266.JPG HTTP/1.0 499 - - AUTH_tk9331e2ba1b06499e974799f6e6f9a645 - 65536 - tx1ffba725a1c347798a2ce-0053380456 - 0.0470 - - 1396180054.419362068 1396180054.466345072
Mar 30 13:47:34 my-laptop proxy-server: 127.0.0.1 127.0.0.1 30/Mar/2014/11/47/34 GET /v1/AUTH_test/contold17031/DSC_0266.JPG HTTP/1.0 200 - - AUTH_tk9331e2ba1b06499e974799f6e6f9a645 - 2730257 -
tx1ffba725a1c347798a2ce-0053380456 - 0.0985 - - 1396180054.443357944 1396180054.541863918

To resolve this strange 499 error i need to add
env['swift.proxy_access_log_made'] = True

( see the line #env['swift.proxy_access_log_made'] = True )

Can someone explain me what is wrong with it? Is it something I did wrong or some bug?

[Samuel Merritt (torgomatic)]

I'd like to see the full pipeline, not the abbreviated one, if possible. If there are sensitive filter names in there, of course, redact them.

The typical pipeline starts with "catch_errors gatekeeper proxy_logging", then has a big pile of middleware names, then finishes with "proxy_logging proxy_server". The key thing is that proxy_logging is in there twice. If your middleware isn't between the two, I don't think any requests that it makes will be logged.

The goal is that each request does, in fact, get logged... so for example SLO, there'd be one logged GET that the client made, plus one logged GET for each segment or submanifest.

I'm not sure where the 499 is coming from, but if your middleware is actually making a second request, then there should definitely be two log lines.

[Gil Vernik (gilv)]

The whole pipleline with correct behavior ( a single line with 200 status ) is:
pipeline = catch_errors gatekeeper cache slo tempurl tempauth proxy-logging logger-499 proxy-server

If you want to GET 2 lines in the log, one with with 499, just need to change between proxy-logging and logger-499
pipeline = catch_errors gatekeeper cache slo tempurl tempauth logger-499 proxy-logging proxy-server

My test middleware -logger-499 - does not making additional request. ( See the code in my original description )

[Tim Burke (1-tim-z)]

It certainly *looks* like the middleware makes two requests: one with env, and one with orig_env. The orig_env response gets delivered back to the client, but the env response gets dropped on the floor -- without even trying to close the iterator that was returned.

With the pipeline '... proxy-logging logger-499 proxy-server' only one request/response goes through the proxy-logging, so you only get one log line; with '... logger-499 proxy-logging proxy-server' both requests/responses are properly logged. I expect the object-server logs would have confirmed that there were two requests regardless of pipeline order -- one that would succeed with 200 and one that would 499 because the "client" (i.e., the proxy-server) stopped reading.

As I understand it, subrequest logging like this is part of why we started recommending that you include proxy-logging at both the start and end of the pipeline, and putting most middleware between them. See https://github.com/openstack/swift/commit/a622349, which was included in 1.8.0.