Bunch of Handoff requested log for HEAD in proxy-server.
Is this on purpose ????
proxy.error:Mar 25 03:17:21 PACO1 proxy-server: Handoff requested (1) (txn: txd53d195092a04b049834f-00533157b1) (client_ip: 192.168.56.21)
proxy.error:Mar 25 03:17:21 PACO1 proxy-server: Handoff requested (1) (txn: tx914443cd8eb6440493aca-00533157b1) (client_ip: 192.168.56.21)
proxy.error:Mar 25 03:17:21 PACO1 proxy-server: Handoff requested (1) (txn: tx2cb1143a44b24ab19788f-00533157b1) (client_ip: 192.168.56.21)
proxy.error:Mar 25 03:17:21 PACO1 proxy-server: Handoff requested (1) (txn: txdc509e8f3618462b96c0e-00533157b1) (client_ip: 192.168.56.21)
proxy.error:Mar 25 03:17:21 PACO1 proxy-server: Handoff requested (1) (txn: txcc9c2eaaf0154aa9a5cd1-00533157b1) (client_ip: 192.168.56.21)
proxy.error:Mar 25 03:17:21 PACO1 proxy-server: Handoff requested (1) (txn: tx7b8e19fefaa9466582e60-00533157b1) (client_ip: 192.168.56.21)
proxy.error:Mar 25 03:17:21 PACO1 proxy-server: Handoff requested (1) (txn: txcd74db04f337405ba8ad4-00533157b1) (client_ip: 192.168.56.21)
proxy.error:Mar 25 03:17:21 PACO1 proxy-server: Handoff requested (1) (txn: tx20c83ac2cfc14adc9cd11-00533157b1) (client_ip: 192.168.56.21)
proxy.error:Mar 25 03:17:21 PACO1 proxy-server: Handoff requested (1) (txn: tx189851f41b4b485ba05c6-00533157b1) (client_ip: 192.168.56.21)
proxy.error:Mar 25 03:17:21 PACO1 proxy-server: Handoff requested (1) (txn: tx20aa5c08db854a0d8acba-00533157b1) (client_ip: 192.168.56.21)
proxy.error:Mar 25 03:17:21 PACO1 proxy-server: Handoff requested (1) (txn: tx5143dd47d65b45d6a2416-00533157b1) (client_ip: 192.168.56.21)
proxy.error:Mar 25 03:53:33 PACO1 proxy-server: Handoff requested (1) (txn: txff62a0c5f688481d9b520-005331602d)
root@PACO1:/var/log/swift# grep txff62a0c5f688481d9b520-005331602d *
proxy.error:Mar 25 03:53:33 PACO1 proxy-server: STDOUT: HUGOHUGOHUGOHUGO (txn: txff62a0c5f688481d9b520-005331602d)
proxy.error:Mar 25 03:53:33 PACO1 proxy-server: Handoff requested (1) (txn: txff62a0c5f688481d9b520-005331602d)
proxy.log:Mar 25 03:53:33 PACO1 proxy-server: Calling Swift3 Middleware (txn: txff62a0c5f688481d9b520-005331602d)
proxy.log:Mar 25 03:53:33 PACO1 proxy-server: {'headers': {'Accept-Encoding': 'gzip, deflate, compress', 'Accept': '*/*', 'User-Agent': 'python-requests/2.2.1 CPython/2.7.3 Linux/3.5.0-23-generic', 'Host': 'localhost', 'X-Auth-Token': 'AUTH_tk2bd513aa449c47fa896ff45556d61b3a', 'Content-Type': None}, 'environ': {'SCRIPT_NAME': '', 'REQUEST_METHOD': 'HEAD', 'PATH_INFO': '/v1/AUTH_val/1/ssl-val_val.source', 'SERVER_PROTOCOL': 'HTTP/1.0', 'REMOTE_ADDR': '127.0.0.1', 'HTTP_X_AUTH_TOKEN': 'AUTH_tk2bd513aa449c47fa896ff45556d61b3a', 'HTTP_USER_AGENT': 'python-requests/2.2.1 CPython/2.7.3 Linux/3.5.0-23-generic', 'eventlet.posthooks': [], 'RAW_PATH_INFO': '/v1/AUTH_val/1/ssl-val_val.source', 'REMOTE_PORT': '45359', 'eventlet.input': <eventlet.wsgi.Input object at 0x27eb210>, 'wsgi.url_scheme': 'https', 'SERVER_PORT': '443', 'wsgi.input': <swift.common.utils.InputProxy object at 0x29c6750>, 'HTTP_HOST': 'localhost', 'swift.cache': <swift.common.memcached.MemcacheRing object at 0x27c8810>, 'HTTPS': 'on', 'wsgi.multithread': True, 'HTTP_ACCEPT': '*/*', 'wsgi.version': (1, 0), 'SERVER_NAME': '127.0.0.1', 'GATEWAY_INTERFACE': 'CGI/1.1', 'wsgi.run_once': False, 'wsgi.errors': <swift.common.utils.LoggerFileObject object at 0x234bb90>, 'wsgi.multiprocess': False, 'swift.trans_id': 'txff62a0c5f688481d9b520-005331602d', 'CONTENT_TYPE': None, 'HTTP_ACCEPT_ENCODING': 'gzip, deflate, compress', 'swift.copy_response_hook': <function slo_hook at 0x27eaa28>}}
proxy.log:Mar 25 03:53:33 PACO1 proxy-server: User: val uses token AUTH_tk2bd513aa449c47fa896ff45556d61b3a (trans_id txff62a0c5f688481d9b520-005331602d)
proxy.log:Mar 25 03:53:33 PACO1 proxy-server: User val:val has reseller admin authorizing. (txn: txff62a0c5f688481d9b520-005331602d) (client_ip: 127.0.0.1)
proxy.log:Mar 25 03:53:33 PACO1 proxy-server: 127.0.0.1 127.0.0.1 25/Mar/2014/10/53/33 HEAD /v1/AUTH_val/1/ssl-val_val.source HTTP/1.0 404 - python-requests/2.2.1%20CPython/2.7.3%20Linux/3.5.0-23-generic AUTH_tk2bd513aa449c47fa896ff45556d61b3a - - - txff62a0c5f688481d9b520-005331602d - 0.0142 - - 1395744813.805253029 1395744813.819473028
storage1.log:Mar 25 03:53:33 PACO1 object-server: 127.0.0.1 - - [25/Mar/2014:10:53:33 +0000] "HEAD /d1/827/AUTH_val/1/ssl-val_val.source" 404 - "HEAD https://localhost/v1/AUTH_val/1/ssl-val_val.source" "txff62a0c5f688481d9b520-005331602d" "proxy-server 3499" 0.0002
storage2.log:Mar 25 03:53:33 PACO1 container-server: 127.0.0.1 - - [25/Mar/2014:10:53:33 +0000] "HEAD /d2/774/AUTH_val/1" 204 - "txff62a0c5f688481d9b520-005331602d" "HEAD http://localhost/v1/AUTH_val/1" "proxy-server 3499" 0.0011
storage2.log:Mar 25 03:53:33 PACO1 object-server: 127.0.0.1 - - [25/Mar/2014:10:53:33 +0000] "HEAD /d2/827/AUTH_val/1/ssl-val_val.source" 404 - "HEAD https://localhost/v1/AUTH_val/1/ssl-val_val.source" "txff62a0c5f688481d9b520-005331602d" "proxy-server 3499" 0.0002
storage3.log:Mar 25 03:53:33 PACO1 object-server: 127.0.0.1 - - [25/Mar/2014:10:53:33 +0000] "HEAD /d3/827/AUTH_val/1/ssl-val_val.source" 404 - "HEAD https://localhost/v1/AUTH_val/1/ssl-val_val.source" "txff62a0c5f688481d9b520-005331602d" "proxy-server 3499" 0.0003
storage4.log:Mar 25 03:53:33 PACO1 object-server: 127.0.0.1 - - [25/Mar/2014:10:53:33 +0000] "HEAD /d4/827/AUTH_val/1/ssl-val_val.source" 404 - "HEAD https://localhost/v1/AUTH_val/1/ssl-val_val.source" "txff62a0c5f688481d9b520-005331602d" "proxy-server 3499" 0.0002
root@PACO1:/var/log/swift#
Yep, this logging is unhelpful.
A long time ago, the proxy would mostly talk to primary nodes, but it would talk to handoffs when a primary was down. This applied to all HTTP verbs. Handoff logging was added so that operators could see how often requests went to handoffs; if one were to look at the ratio of handoffs/requests, one could get a sense of how well their cluster was doing with availability.
A shorter time ago, the proxy started talking to handoffs on GET/HEAD requests when the primaries gave 404s. This way, even if a write went to handoffs, the object would still be available for reads. By default, the proxy will request things from the 3 primaries and then the first 3 handoffs (but it's configurable). Unfortunately, this means the handoffs/requests ratio isn't particularly useful right now.
What should happen:
On GET/HEAD requests, the first 3 handoffs shouldn't be logged, as they're normal. For other verbs, all handoffs should be logged.
Some examples with the default config:
GET talks to 3 primaries and 3 handoffs: no handoffs logged
GET talks to 2 primaries (one's down) and 4 handoffs: 1 handoff logged
GET talks to 1 primary (two are down) and 5 handoffs: 2 handoffs logged
GET talks to 0 primaries (all down) and 6 handoffs: 3 handoffs logged, 1 handoff_all logged
PUT talks to 3 primaries and 0 handoffs: no handoffs logged
PUT talks to 2 primaries (one's down) and 1 handoff: 1 handoff logged
PUT talks to 0 primaries (all down) and 3 handoffs: 3 handoffs logged, 1 handoff_all logged