Proxy logs wrong request method when validating SLO segments

[Tim Burke]

During segment validation, the object servers log things like

Jan 17 20:30:11 saio object-6020: 127.0.0.1 - - [17/Jan/2017:20:30:11 +0000] "HEAD /sdb6/32/AUTH_test/c/seg1" 200 82 "HEAD http://saio:8090/v1/AUTH_test/c/seg1" "txd3e5cb5d39144da6b35af-00587e7ed3" "proxy-server 4489" 0.0008 "-" 4500 0
Jan 17 20:30:11 saio object-6020: STDERR: 127.0.0.1 - - [17/Jan/2017 20:30:11] "HEAD /sdb6/32/AUTH_test/c/seg1 HTTP/1.1" 200 674 0.001456 (txn: txd3e5cb5d39144da6b35af-00587e7ed3)
Jan 17 20:30:11 saio object-6020: 127.0.0.1 - - [17/Jan/2017:20:30:11 +0000] "HEAD /sdb2/85/AUTH_test/c/seg2" 200 82 "HEAD http://saio:8090/v1/AUTH_test/c/seg2" "txd3e5cb5d39144da6b35af-00587e7ed3" "proxy-server 4489" 0.0004 "-" 4500 0
Jan 17 20:30:11 saio object-6020: STDERR: 127.0.0.1 - - [17/Jan/2017 20:30:11] "HEAD /sdb2/85/AUTH_test/c/seg2 HTTP/1.1" 200 674 0.000587 (txn: txd3e5cb5d39144da6b35af-00587e7ed3)

But the proxy logs the same subrequests as *PUTs* (I guess reflecting the client method):

Jan 17 20:30:11 saio proxy-server: - - 17/Jan/2017/20/30/11 PUT /v1/AUTH_test/c/seg1 HTTP/1.0 200 - curl/7.51.0%20SLO%20MultipartPUT - - - - txd3e5cb5d39144da6b35af-00587e7ed3 ... 0.0261 SLO - 1484685011.904774904 1484685011.930879116 0
Jan 17 20:30:11 saio proxy-server: - - 17/Jan/2017/20/30/11 PUT /v1/AUTH_test/c/seg2 HTTP/1.0 200 - curl/7.51.0%20SLO%20MultipartPUT - - - - txd3e5cb5d39144da6b35af-00587e7ed3 ... 0.0306 SLO - 1484685011.905210018 1484685011.935823917 0

This is confusing and misleading; I don't think any other middlewares behave that way. *Maybe* copy does some re-writing for POST-as-COPY?

[Romain LE DISEZ (rledisez)]

I see the same behavior. It logs the wrong method and also sends an invalid statsd metric (having PUT returning 200 feels weird in the dashboards... :)).

The behavior changed between 2.7 and 2.12 (no issue running 2.7, started since upgrade to 2.12)

The same behavior is observed from the copy middleware:

Feb 13 18:15:48 localhost proxy-server: Copying object from /v1/AUTH_76ad686e615fa7b08e18884214f71d8c/default/a to /v1/AUTH_76ad686e615fa7b08e18884214f71d8c/default/b (txn: tx174c1300d31e4c7d8b09f-0058a1e9c4)

Feb 13 18:15:49 localhost proxy-server: - - 13/Feb/2017/17/15/49 PUT /v1/AUTH_76ad686e615fa7b08e18884214f71d8c HTTP/1.0 204 - Swift - - - - tx174c1300d31e4c7d8b09f-0058a1e9c4 - 0.0120 - - 1487006149.166141033 1487006149.178188086 -

Feb 13 18:15:55 localhost proxy-server: 1.2.3.4 - 13/Feb/2017/17/15/55 PUT /v1/AUTH_76ad686e615fa7b08e18884214f71d8c/default/a HTTP/1.0 200 - - - - 863570 67913cc02d9742cdae9f35c9378d5e04 tx174c1300d31e4c7d8b09f-0058a1e9c4 - 7.3553 SSC - 1487006148.156651020 1487006155.511914968 1

Feb 13 18:15:59 localhost proxy-server: 1.2.3.4 5.196.84.6 13/Feb/2017/17/15/59 PUT /v1/AUTH_76ad686e615fa7b08e18884214f71d8c/default/b HTTP/1.0 201 - - - - - 67913cc02d9742cdae9f35c9378d5e04 tx174c1300d31e4c7d8b09f-0058a1e9c4 - 11.4158 - - 1487006148.153633118 1487006159.569468021 -

[Tim Burke (1-tim-z)]

So the regression definitely seems to have been introduced by https://review.openstack.org/#/c/156923/

I see three different ways we could address it, but I'm not sure which is best. Maybe some combination?

1. Make copy more picky about when it sets orig_req_method, as in http://paste.openstack.org/show/601652/

2. Make SLO consciously opt out of any orig_req_method that may be set, as in http://paste.openstack.org/show/601653/

3. Make proxy-logging only respect orig_req_method when swift.source is unset (i.e., for client requests), as in http://paste.openstack.org/show/601654/

[clayg (clay-gerrard)]

I get that if we change the request method the client sent we might want the outgoing log of *that* request to reflect the request they sent (maybe? probably?)

But where is the logic in translating the method of subrequests?

https://gist.github.com/clayg/7e34254b9da22713d46f112f178119be

[clayg (clay-gerrard)]

The situation on the ground is that lots of requests are getting logged wrong:

Mar 6 17:48:14 saio proxy-server: - - 06/Mar/2017/22/48/14 DELETE /v1/AUTH_test/target%3Fformat%3Djson%26prefix%3D004test/%26marker%3D%26reverse%3Don HTTP/1.0 200 - Swift - - 185 - tx25c75caac99a4ee2a9bea-0058bde72e - 0.0110 VW - 1488840494.881216049 1488840494.892184973 0
Mar 6 17:48:14 saio proxy-server: - - 06/Mar/2017/22/48/14 DELETE /v1/AUTH_test/target/004test/1488840384.08505 HTTP/1.0 200 - Swift - - 8 - tx25c75caac99a4ee2a9bea-0058bde72e - 0.0310 VW - 1488840494.893866062 1488840494.924870014 0
Mar 6 17:48:14 saio proxy-server: - - 06/Mar/2017/22/48/14 DELETE /v1/AUTH_test/source/test HTTP/1.0 201 - Swift - 8 - 3867b64ae04ac7d9638abda87cd04c22 tx25c75caac99a4ee2a9bea-0058bde72e - 0.0288 VW - 1488840494.916619062 1488840494.945369959 0
Mar 6 17:48:14 saio proxy-server: - - 06/Mar/2017/22/48/14 DELETE /v1/AUTH_test/target/004test/1488840384.08505 HTTP/1.0 204 - Swift AUTH_tke734e1d66... - - - tx25c75caac99a4ee2a9bea-0058bde72e - 0.0250 VW - 1488840494.946042061 1488840494.971009016 0
Mar 6 17:48:14 saio proxy-server: 127.0.0.1 127.0.0.1 06/Mar/2017/22/48/14 DELETE /v1/AUTH_test/source/test HTTP/1.0 204 - curl/7.47.0 AUTH_tke734e1d66... - - - tx25c75caac99a4ee2a9bea-0058bde72e - 0.0932 - - 1488840494.879107952 1488840494.972348928 -

^ "source" is a stack versioned container, and "target" is the old versioned objects - the final request shows the client making a DELETE request for /source/test with curl - but we log the internal subrequests GET /target/test PUT /source/test DELETE /target/test all incorrectly before logging the "DELETE /source/test" request the client made originally.

[clayg (clay-gerrard)]

I'm channeling timburke here - but I *think* we want:

https://gist.github.com/clayg/7e34254b9da22713d46f112f178119be

http://paste.openstack.org/show/601652/

and tests!

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/444604

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/444604
Committed: https://git.openstack.org/cgit/openstack/swift/commit/?id=108501a8c130f4b013c75603b0263f585f6ba535
Submitter: Jenkins
Branch: master

commit 108501a8c130f4b013c75603b0263f585f6ba535
Author: Janie Richling <email address hidden>
Date: Sat Mar 11 13:30:35 2017 -0600

    Log the correct request type of a subrequest downstream of copy

    Before this change, subrequests made while servicing a copy would
    result in logging the request type from the copy PUT/GET request
    instead of the type from the subrequest being logged.

    In order to have the correct requst type logged for subrequests:
    - Changed subrequest environments to not inherit the orig_req_method
      of the enclosing request.
    - Changed copy to be more picky about when it sets orig_req_method

    In addition, subrequest environments will no longer inherit the
    swift.log_info from the enclosing request. That inheritance had
    been added at Ic96a92e938589a2f6add35a40741fd062f1c29eb
    along with swift.orig_req_method.

    Change-Id: I1ccb2665b6cd2887659e548e55a26aa00de879e3
    Closes-Bug: #1657246

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/ocata
Review: https://review.openstack.org/449824

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/newton
Review: https://review.openstack.org/449837

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/449824
Committed: https://git.openstack.org/cgit/openstack/swift/commit/?id=b7c2a9196009ef78560acfb3826b9106f95d7fdf
Submitter: Jenkins
Branch: stable/ocata

commit b7c2a9196009ef78560acfb3826b9106f95d7fdf
Author: Janie Richling <email address hidden>
Date: Sat Mar 11 13:30:35 2017 -0600

    Log the correct request type of a subrequest downstream of copy

    Before this change, subrequests made while servicing a copy would
    result in logging the request type from the copy PUT/GET request
    instead of the type from the subrequest being logged.

    In order to have the correct requst type logged for subrequests:
    - Changed subrequest environments to not inherit the orig_req_method
      of the enclosing request.
    - Changed copy to be more picky about when it sets orig_req_method

    In addition, subrequest environments will no longer inherit the
    swift.log_info from the enclosing request. That inheritance had
    been added at Ic96a92e938589a2f6add35a40741fd062f1c29eb
    along with swift.orig_req_method.

    Change-Id: I1ccb2665b6cd2887659e548e55a26aa00de879e3
    Closes-Bug: #1657246

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/449837
Committed: https://git.openstack.org/cgit/openstack/swift/commit/?id=faa6890424393183e29409836f673f2782139270
Submitter: Jenkins
Branch: stable/newton

commit faa6890424393183e29409836f673f2782139270
Author: Janie Richling <email address hidden>
Date: Sat Mar 11 13:30:35 2017 -0600

    Log the correct request type of a subrequest downstream of copy

    Before this change, subrequests made while servicing a copy would
    result in logging the request type from the copy PUT/GET request
    instead of the type from the subrequest being logged.

    In order to have the correct requst type logged for subrequests:
    - Changed subrequest environments to not inherit the orig_req_method
      of the enclosing request.
    - Changed copy to be more picky about when it sets orig_req_method

    In addition, subrequest environments will no longer inherit the
    swift.log_info from the enclosing request. That inheritance had
    been added at Ic96a92e938589a2f6add35a40741fd062f1c29eb
    along with swift.orig_req_method.

    Change-Id: I1ccb2665b6cd2887659e548e55a26aa00de879e3
    Closes-Bug: #1657246

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/swift 2.14.0 release.

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/swift 2.10.2 release.

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/swift 2.13.1 release.