Arvados

Response logger now sniffs first 1K of response data and displays it in logs for unsuccessful responses. Resulting logs from the lib/controller tests:

time="2019-10-23T15:48:56.163789440-04:00" level=info msg=response RequestID=req-1q09qxjpgfdaae99fhcm remoteAddr="[::1]:47376" reqBytes=0 reqForwardedFor= reqHost=example.com reqMethod=GET reqPath=arvados/v1/workflows/zzzzz-7fd4e-validworkfloyml reqQuery= respBody="{\"errors\":[\"Not logged in (req-1q09qxjpgfdaae99fhcm)\"],\"error_token\":\"1571860136+b8608b64\"}" respBytes=91 respStatus=Unauthorized respStatusCode=401 timeToStatus=0.006417 timeTotal=0.006471 timeWriteBody=0.000054
time="2019-10-23T15:48:56.164029751-04:00" level=info msg=response RequestID=req-1q09qxjpgfdaae99fhcm remoteAddr="192.0.2.1:1234" reqBytes=0 reqForwardedFor= reqHost=example.com reqMethod=GET reqPath=arvados/v1/workflows/zzzzz-7fd4e-validworkfloyml reqQuery= respBody="{\"errors\":[\"Not logged in (req-1q09qxjpgfdaae99fhcm)\"],\"error_token\":\"1571860136+b8608b64\"}" respBytes=91 respStatus=Unauthorized respStatusCode=401 timeToStatus=0.023134 timeTotal=0.023157 timeWriteBody=0.000024
time="2019-10-23T15:48:56.244552275-04:00" level=info msg=response RequestID=req-1lxc41x7f2rb41cj8gkp remoteAddr="192.0.2.1:1234" reqBytes=165 reqForwardedFor= reqHost=example.com reqMethod=POST reqPath=arvados/v1/container_requests reqQuery="cluster_id=zz404" respBody="{\"errors\":[\"no proxy available for cluster zz404\"]}\n" respBytes=52 respStatus="Not Found" respStatusCode=404 timeToStatus=0.006820 timeTotal=0.006830 timeWriteBody=0.000010
time="2019-10-23T15:48:56.279704006-04:00" level=info msg=response RequestID=req-183xk5csnlb8nq2e0bra remoteAddr="[::1]:49378" reqBytes=0 reqForwardedFor= reqHost=example.com reqMethod=GET reqPath=arvados/v1/collections/99999999999999999999999999999999+99 reqQuery= respBody="{\"errors\":[\"Path not found (req-183xk5csnlb8nq2e0bra)\"],\"error_token\":\"1571860136+ceb8111f\"}" respBytes=92 respStatus="Not Found" respStatusCode=404 timeToStatus=0.010568 timeTotal=0.010621 timeWriteBody=0.000054
time="2019-10-23T15:48:56.279949023-04:00" level=info msg=response RequestID=req-183xk5csnlb8nq2e0bra remoteAddr="192.0.2.1:1234" reqBytes=0 reqForwardedFor= reqHost=example.com reqMethod=GET reqPath=arvados/v1/collections/99999999999999999999999999999999+99 reqQuery= respBody="{\"errors\":[\"404 Not Found\"]}\n" respBytes=29 respStatus="Not Found" respStatusCode=404 timeToStatus=0.023026 timeTotal=0.023094 timeWriteBody=0.000068
time="2019-10-23T15:48:56.290083063-04:00" level=info msg=response RequestID=req-szfku3ygfvd4rj6n40hq remoteAddr="192.0.2.1:1234" reqBytes=0 reqForwardedFor= reqHost=example.com reqMethod=GET reqPath=arvados/v1/collections/99999999999999999999999999999999+99 reqQuery= respBody="{\"errors\":[\"Computed manifest_text hash \\\"cc16c026f32a20f1f6cb6d997cc1fe4e+94\\\" did not match expected hash \\\"99999999999999999999999999999999+99\\\"\"]}\n" respBytes=151 respStatus="Bad Gateway" respStatusCode=502 timeToStatus=0.007620 timeTotal=0.007631 timeWriteBody=0.000011
time="2019-10-23T15:48:56.392730245-04:00" level=info msg=response RequestID=req-sn241m6hcn491u3gow71 remoteAddr="[::1]:46470" reqBytes=0 reqForwardedFor= reqHost=example.com reqMethod=GET reqPath=arvados/v1/collections/zzzzz-4zz18-fakefakefakefak reqQuery= respBody="{\"errors\":[\"Path not found (req-sn241m6hcn491u3gow71)\"],\"error_token\":\"1571860136+9e20185b\"}" respBytes=92 respStatus="Not Found" respStatusCode=404 timeToStatus=0.008158 timeTotal=0.008218 timeWriteBody=0.000060
time="2019-10-23T15:48:56.392984390-04:00" level=info msg=response RequestID=req-sn241m6hcn491u3gow71 remoteAddr="192.0.2.1:1234" reqBytes=0 reqForwardedFor= reqHost=example.com reqMethod=GET reqPath=arvados/v1/collections/zzzzz-4zz18-fakefakefakefak reqQuery= respBody="{\"errors\":[\"Path not found (req-sn241m6hcn491u3gow71)\"],\"error_token\":\"1571860136+9e20185b\"}" respBytes=92 respStatus="Not Found" respStatusCode=404 timeToStatus=0.017781 timeTotal=0.017863 timeWriteBody=0.000082
time="2019-10-23T15:48:56.473706320-04:00" level=info msg=response RequestID=req-81lpy95s79mm1cgzyol1 remoteAddr="192.0.2.1:1234" reqBytes=0 reqForwardedFor= reqHost=example.com reqMethod=GET reqPath=arvados/v1/workflows/zz404-7fd4e-validworkfloyml reqQuery= respBody="{\"errors\":[\"no proxy available for cluster zz404\"]}\n" respBytes=52 respStatus="Not Found" respStatusCode=404 timeToStatus=0.000077 timeTotal=0.000082 timeWriteBody=0.000005
time="2019-10-23T15:48:56.496938547-04:00" level=info msg=response RequestID=req-84fd0s03kvvylquget8r remoteAddr="192.0.2.1:1234" reqBytes=0 reqForwardedFor= reqHost=example.com reqMethod=GET reqPath=arvados/v1/containers reqQuery="count=none&filters=%5B%5B%22uuid%22%2C+%22in%22%2C+%5B%22zzzzz-dz642-queuedcontainer%22%2C+%22zhome-xvhdp-cr5queuedcontnr%22%5D%5D%5D&select=%5B%22uuid%22%2C+%22command%22%5D" respBody="{\"errors\":[\"error fetching from zhome (404 Not Found): EOF\"]}\n" respBytes=62 respStatus="Bad Gateway" respStatusCode=502 timeToStatus=0.019935 timeTotal=0.019943 timeWriteBody=0.000007
time="2019-10-23T15:48:56.501778609-04:00" level=info msg=response RequestID=req-179yrbgxy918dwo4iy33 remoteAddr="192.0.2.1:1234" reqBytes=0 reqForwardedFor= reqHost=example.com reqMethod=GET reqPath=arvados/v1/containers reqQuery="count=none&filters=%5B%5B%22uuid%22%2C+%22in%22%2C+%5B%22zzzzz-dz642-queuedcontainer%22%2C+%22zhome-xvhdp-cr5queuedcontnr%22%5D%5D%5D&limit=1" respBody="{\"errors\":[\"Federated multi-object may not provide 'limit', 'offset' or 'order'.\"]}\n" respBytes=84 respStatus="Bad Request" respStatusCode=400 timeToStatus=0.000285 timeTotal=0.000292 timeWriteBody=0.000007
time="2019-10-23T15:48:56.513132095-04:00" level=info msg=response RequestID=req-14xfgrukv0qfb1y0pn7j remoteAddr="192.0.2.1:1234" reqBytes=0 reqForwardedFor= reqHost=example.com reqMethod=GET reqPath=arvados/v1/containers reqQuery="count=none&filters=%5B%5B%22uuid%22%2C+%22in%22%2C+%5B%22zzzzz-dz642-queuedcontainer%22%2C+%22zhome-xvhdp-cr5queuedcontnr%22%5D%5D%5D&offset=1" respBody="{\"errors\":[\"Federated multi-object may not provide 'limit', 'offset' or 'order'.\"]}\n" respBytes=84 respStatus="Bad Request" respStatusCode=400 timeToStatus=0.000227 timeTotal=0.000239 timeWriteBody=0.000013
time="2019-10-23T15:48:56.520142881-04:00" level=info msg=response RequestID=req-zvxozkpr3r03cxm8i6l3 remoteAddr="192.0.2.1:1234" reqBytes=0 reqForwardedFor= reqHost=example.com reqMethod=GET reqPath=arvados/v1/containers reqQuery="count=none&filters=%5B%5B%22uuid%22%2C+%22in%22%2C+%5B%22zzzzz-dz642-queuedcontainer%22%2C+%22zhome-xvhdp-cr5queuedcontnr%22%5D%5D%5D&order=uuid" respBody="{\"errors\":[\"Federated multi-object may not provide 'limit', 'offset' or 'order'.\"]}\n" respBytes=84 respStatus="Bad Request" respStatusCode=400 timeToStatus=0.000082 timeTotal=0.000087 timeWriteBody=0.000005
time="2019-10-23T15:48:56.526413353-04:00" level=info msg=response RequestID=req-1a09tpgyn2yntoj1kgwh remoteAddr="192.0.2.1:1234" reqBytes=0 reqForwardedFor= reqHost=example.com reqMethod=GET reqPath=arvados/v1/containers reqQuery="count=none&filters=%5B%5B%22uuid%22%2C+%22in%22%2C+%5B%22zzzzz-dz642-queuedcontainer%22%2C+%22zhome-xvhdp-cr5queuedcontnr%22%5D%5D%5D" respBody="{\"errors\":[\"Federated multi-object request for 2 objects which is more than max page size 1.\"]}\n" respBytes=96 respStatus="Bad Request" respStatusCode=400 timeToStatus=0.000093 timeTotal=0.000098 timeWriteBody=0.000005
time="2019-10-23T15:48:56.528888081-04:00" level=info msg=response RequestID=req-1mmeaz64qtsvd1sjwbz8 remoteAddr="192.0.2.1:1234" reqBytes=0 reqForwardedFor= reqHost=example.com reqMethod=GET reqPath=arvados/v1/containers reqQuery="count=none&filters=%5B%5B%22uuid%22%2C+%22in%22%2C+%5B%22zzzzz-dz642-queuedcontainer%22%2C+%22zhome-xvhdp-cr5queuedcontnr%22%5D%5D%5D&select=%5B%22command%22%5D" respBody="{\"errors\":[\"Federated multi-object request must include 'uuid' in 'select'\"]}\n" respBytes=78 respStatus="Bad Request" respStatusCode=400 timeToStatus=0.000102 timeTotal=0.000109 timeWriteBody=0.000007
time="2019-10-23T15:48:56.629760895-04:00" level=info msg=response RequestID=req-1su2x34ow3huq1d6lrjb remoteAddr="192.0.2.1:1234" reqBytes=0 reqForwardedFor= reqHost=example.com reqMethod=GET reqPath=arvados/v1/workflows/zhome-7fd4e-validworkfloyml reqQuery= respBody="{\"errors\":[\"Get http://localhost:1/arvados/v1/workflows/zhome-7fd4e-validworkfloyml: dial tcp [::1]:1: connect: connection refused\"]}\n" respBytes=134 respStatus="Bad Gateway" respStatusCode=502 timeToStatus=0.000443 timeTotal=0.000452 timeWriteBody=0.000010
time="2019-10-23T15:48:56.641325231-04:00" level=info msg=response RequestID=req-y3mh02us5won1drpue21 remoteAddr="192.0.2.1:1234" reqBytes=0 reqForwardedFor= reqHost=example.com reqMethod=GET reqPath=arvados/v1/collections/zmock-4zz18-uukreo9rbgwsujr reqQuery= respBody="{\"errors\":[\"Computed manifest_text hash \\\"d41d8cd98f00b204e9800998ecf8427e+0\\\" did not match expected hash \\\"\\\"\"]}\n" respBytes=115 respStatus="Bad Gateway" respStatusCode=502 timeToStatus=0.001321 timeTotal=0.001330 timeWriteBody=0.000008
time="2019-10-23T15:48:56.660441832-04:00" level=info msg=response RequestID=req-t68cnjm84xis1kz57quc remoteAddr="[::1]:57706" reqBytes=0 reqForwardedFor= reqHost=example.com reqMethod=GET reqPath=arvados/v1/workflows/zzzzz-7fd4e-validworkfloyml reqQuery= respBody="{\"errors\":[\"Path not found (req-t68cnjm84xis1kz57quc)\"],\"error_token\":\"1571860136+7f2e5155\"}" respBytes=92 respStatus="Not Found" respStatusCode=404 timeToStatus=0.009472 timeTotal=0.009567 timeWriteBody=0.000095
time="2019-10-23T15:48:56.660683272-04:00" level=info msg=response RequestID=req-t68cnjm84xis1kz57quc remoteAddr="192.0.2.1:1234" reqBytes=0 reqForwardedFor= reqHost=example.com reqMethod=GET reqPath=arvados/v1/workflows/zzzzz-7fd4e-validworkfloyml reqQuery= respBody="{\"errors\":[\"Path not found (req-t68cnjm84xis1kz57quc)\"],\"error_token\":\"1571860136+7f2e5155\"}" respBytes=92 respStatus="Not Found" respStatusCode=404 timeToStatus=0.016165 timeTotal=0.016208 timeWriteBody=0.000043
time="2019-10-23T15:48:56.668152693-04:00" level=info msg=response RequestID=req-1eoyf3aybf09w1d8bpis remoteAddr="[::1]:50728" reqBytes=0 reqForwardedFor= reqHost=example.com reqMethod=GET reqPath=arvados/v1/workflows/zzzzz-7fd4e-validworkfloyml reqQuery= respBody="{\"errors\":[\"Not logged in (req-1eoyf3aybf09w1d8bpis)\"],\"error_token\":\"1571860136+3fb27233\"}" respBytes=91 respStatus=Unauthorized respStatusCode=401 timeToStatus=0.004582 timeTotal=0.004611 timeWriteBody=0.000029
time="2019-10-23T15:48:56.668398046-04:00" level=info msg=response RequestID=req-1eoyf3aybf09w1d8bpis remoteAddr="192.0.2.1:1234" reqBytes=0 reqForwardedFor= reqHost=example.com reqMethod=GET reqPath=arvados/v1/workflows/zzzzz-7fd4e-validworkfloyml reqQuery= respBody="{\"errors\":[\"Not logged in (req-1eoyf3aybf09w1d8bpis)\"],\"error_token\":\"1571860136+3fb27233\"}" respBytes=91 respStatus=Unauthorized respStatusCode=401 timeToStatus=0.005217 timeTotal=0.005287 timeWriteBody=0.000070
time="2019-10-23T15:48:56.688382816-04:00" level=info msg=response RequestID=req-180diyon6o97bjq64tsx remoteAddr="192.0.2.1:1234" reqBytes=0 reqForwardedFor= reqHost=example.com reqMethod=GET reqPath=arvados/v1/workflows/zzzzz-7fd4e-validworkfloyml reqQuery= respBody="{\"errors\":[\"Get https://[::]:41111/arvados/v1/workflows/zzzzz-7fd4e-validworkfloyml: http: server gave HTTP response to HTTPS client\"]}\n" respBytes=136 respStatus="Bad Gateway" respStatusCode=502 timeToStatus=0.006679 timeTotal=0.006693 timeWriteBody=0.000014
time="2019-10-23T15:48:56.699548984-04:00" level=info msg=response RequestID=req-gtzjzz1fjpr116jqo6vi remoteAddr="192.0.2.1:1234" reqBytes=0 reqForwardedFor= reqHost=example.com reqMethod=GET reqPath=arvados/v1/collections/zmock-4zz18-uukreo9rbgwsujr reqQuery= respBody="{\"errors\":[\"Computed manifest_text hash \\\"d41d8cd98f00b204e9800998ecf8427e+0\\\" did not match expected hash \\\"\\\"\"]}\n" respBytes=115 respStatus="Bad Gateway" respStatusCode=502 timeToStatus=0.001512 timeTotal=0.001526 timeWriteBody=0.000014
time="2019-10-23T15:48:56.750700514-04:00" level=info msg=response RequestID=req-1qthtatgjfmic8e0odv5 remoteAddr="192.0.2.1:1234" reqBytes=0 reqForwardedFor= reqHost=example.com reqMethod=GET reqPath=arvados/v1/collections/99999999999999999999999999999999+99 reqQuery= respBody="{\"errors\":[\"Path not found (req-1qthtatgjfmic8e0odv5)\"],\"error_token\":\"1571860136+f00a204b\"}" respBytes=92 respStatus="Not Found" respStatusCode=404 timeToStatus=0.007321 timeTotal=0.007365 timeWriteBody=0.000044
time="2019-10-23T15:48:56.990414735-04:00" level=info msg=response RequestID=req-1uz4y3i0j7i62bhyqjru remoteAddr="[::1]:38900" reqBytes=0 reqForwardedFor= reqHost=example.com reqMethod=GET reqPath=arvados/v1/workflows/zzzzz-7fd4e-hvwe5szzr8w707t reqQuery= respBody="{\"errors\":[\"Path not found (req-1uz4y3i0j7i62bhyqjru)\"],\"error_token\":\"1571860136+a3d097ce\"}" respBytes=92 respStatus="Not Found" respStatusCode=404 timeToStatus=0.008115 timeTotal=0.008173 timeWriteBody=0.000058
time="2019-10-23T15:48:56.990530906-04:00" level=info msg=response RequestID=req-1uz4y3i0j7i62bhyqjru remoteAddr="192.0.2.1:1234" reqBytes=0 reqForwardedFor= reqHost=example.com reqMethod=GET reqPath=arvados/v1/workflows/zzzzz-7fd4e-hvwe5szzr8w707t reqQuery= respBody="{\"errors\":[\"Path not found (req-1uz4y3i0j7i62bhyqjru)\"],\"error_token\":\"1571860136+a3d097ce\"}" respBytes=92 respStatus="Not Found" respStatusCode=404 timeToStatus=0.009306 timeTotal=0.009321 timeWriteBody=0.000015
time="2019-10-23T15:48:56.998370398-04:00" level=info msg=response RequestID=req-161an2ys02yy1vtdcd16 remoteAddr="192.0.2.1:1234" reqBytes=0 reqForwardedFor= reqHost=example.com reqMethod=DELETE reqPath=arvados/v1/workflows/zzzzz-7fd4e-hvwe5szzr8w707t reqQuery= respBody="{\"errors\":[\"Path not found (req-161an2ys02yy1vtdcd16)\"],\"error_token\":\"1571860136+dff0c5d9\"}" respBytes=92 respStatus="Not Found" respStatusCode=404 timeToStatus=0.007682 timeTotal=0.007784 timeWriteBody=0.000102
time="2019-10-23T15:48:57.091796083-04:00" level=info msg=response RequestID=req-19muugay1s5552sxkpvi remoteAddr="[::1]:34788" reqBytes=0 reqForwardedFor= reqHost=example.com reqMethod=GET reqPath=arvados/v1/workflows/zzzzz-7fd4e-validworkfloyml reqQuery= respBody="{\"errors\":[\"Not logged in (req-19muugay1s5552sxkpvi)\"],\"error_token\":\"1571860137+1d295a24\"}" respBytes=91 respStatus=Unauthorized respStatusCode=401 timeToStatus=0.004334 timeTotal=0.004366 timeWriteBody=0.000032
time="2019-10-23T15:48:57.092089940-04:00" level=info msg=response RequestID=req-19muugay1s5552sxkpvi remoteAddr="192.0.2.1:1234" reqBytes=0 reqForwardedFor= reqHost=example.com reqMethod=GET reqPath=arvados/v1/workflows/zzzzz-7fd4e-validworkfloyml reqQuery= respBody="{\"errors\":[\"Not logged in (req-19muugay1s5552sxkpvi)\"],\"error_token\":\"1571860137+1d295a24\"}" respBytes=91 respStatus=Unauthorized respStatusCode=401 timeToStatus=0.011063 timeTotal=0.011109 timeWriteBody=0.000046
time="2019-10-23T15:48:57.168682845-04:00" level=info msg=response RequestID=req-19a7g0ww8tds15h28iwc remoteAddr="192.0.2.1:1234" reqBytes=165 reqForwardedFor= reqHost=example.com reqMethod=POST reqPath=arvados/v1/container_requests reqQuery="cluster_id=zz404" respBody="{\"errors\":[\"no proxy available for cluster zz404\"]}\n" respBytes=52 respStatus="Not Found" respStatusCode=404 timeToStatus=0.005947 timeTotal=0.005952 timeWriteBody=0.000005
time="2019-10-23T15:48:57.194058252-04:00" level=info msg=response RequestID=req-1dmc2qe2lrsna1yufg9o remoteAddr="[::1]:42312" reqBytes=0 reqForwardedFor= reqHost="[::]:42549" reqMethod=GET reqPath=arvados/v1/collections/99999999999999999999999999999999+99 reqQuery= respBody="{\"errors\":[\"not found\"]}\n" respBytes=25 respStatus="Not Found" respStatusCode=404 timeToStatus=0.011731 timeTotal=0.011742 timeWriteBody=0.000011
time="2019-10-23T15:48:57.194299483-04:00" level=info msg=response RequestID=req-1dmc2qe2lrsna1yufg9o remoteAddr="192.0.2.1:1234" reqBytes=0 reqForwardedFor= reqHost=example.com reqMethod=GET reqPath=arvados/v1/collections/99999999999999999999999999999999+99 reqQuery= respBody="{\"errors\":[\"not found\"]}\n" respBytes=25 respStatus="Not Found" respStatusCode=404 timeToStatus=0.012763 timeTotal=0.012773 timeWriteBody=0.000010
time="2019-10-23T15:48:57.199375189-04:00" level=info msg=response RequestID=req-6izbub74qwwc1x9kmbn2 remoteAddr="192.0.2.1:1234" reqBytes=0 reqForwardedFor= reqHost=example.com reqMethod=GET reqPath=arvados/v1/collections/99999999999999999999999999999999+99 reqQuery= respBody="{\"errors\":[\"errors: [bad portable data hash \\\"cc16c026f32a20f1f6cb6d997cc1fe4e+94\\\" received from remote \\\"zzzzz\\\" (expected \\\"99999999999999999999999999999999+99\\\")]\"]}\n" respBytes=170 respStatus="Bad Gateway" respStatusCode=502 timeToStatus=0.001323 timeTotal=0.001330 timeWriteBody=0.000007
time="2019-10-23T15:48:57.289591949-04:00" level=info msg=response RequestID=req-1s3fy8l0eye6n1u7a6sc remoteAddr="[::1]:54782" reqBytes=0 reqForwardedFor= reqHost="[::]:44413" reqMethod=GET reqPath=arvados/v1/collections/zzzzz-4zz18-fakefakefakefak reqQuery= respBody="{\"errors\":[\"request failed: https://0.0.0.0:41891/arvados/v1/collections/zzzzz-4zz18-fakefakefakefak: 404 Not Found: Path not found (req-1s3fy8l0eye6n1u7a6sc)\"]}\n" respBytes=162 respStatus="Not Found" respStatusCode=404 timeToStatus=0.011766 timeTotal=0.011776 timeWriteBody=0.000010
time="2019-10-23T15:48:57.289778580-04:00" level=info msg=response RequestID=req-1s3fy8l0eye6n1u7a6sc remoteAddr="192.0.2.1:1234" reqBytes=0 reqForwardedFor= reqHost=example.com reqMethod=GET reqPath=arvados/v1/collections/zzzzz-4zz18-fakefakefakefak reqQuery= respBody="{\"errors\":[\"request failed: http://[::]:44413/arvados/v1/collections/zzzzz-4zz18-fakefakefakefak: 404 Not Found: request failed: https://0.0.0.0:41891/arvados/v1/collections/zzzzz-4zz18-fakefakefakefak: 404 Not Found: Path not found (req-1s3fy8l0eye6n1u7a6sc)\"]}\n" respBytes=263 respStatus="Not Found" respStatusCode=404 timeToStatus=0.012848 timeTotal=0.012857 timeWriteBody=0.000009
time="2019-10-23T15:48:57.357362305-04:00" level=info msg=response RequestID=req-1wydlkonp938x2df26ae remoteAddr="192.0.2.1:1234" reqBytes=0 reqForwardedFor= reqHost=example.com reqMethod=GET reqPath=arvados/v1/workflows/zz404-7fd4e-validworkfloyml reqQuery= respBody="{\"errors\":[\"no proxy available for cluster zz404\"]}\n" respBytes=52 respStatus="Not Found" respStatusCode=404 timeToStatus=0.000094 timeTotal=0.000100 timeWriteBody=0.000007
time="2019-10-23T15:48:57.381100412-04:00" level=info msg=response RequestID=req-c8u3z5hursg5qb3zyi5z remoteAddr="192.0.2.1:1234" reqBytes=0 reqForwardedFor= reqHost=example.com reqMethod=GET reqPath=arvados/v1/containers reqQuery="count=none&filters=%5B%5B%22uuid%22%2C+%22in%22%2C+%5B%22zzzzz-dz642-queuedcontainer%22%2C+%22zhome-xvhdp-cr5queuedcontnr%22%5D%5D%5D&select=%5B%22uuid%22%2C+%22command%22%5D" respBody="{\"errors\":[\"error fetching from zhome (404 Not Found): EOF\"]}\n" respBytes=62 respStatus="Bad Gateway" respStatusCode=502 timeToStatus=0.019956 timeTotal=0.019965 timeWriteBody=0.000009
time="2019-10-23T15:48:57.383691256-04:00" level=info msg=response RequestID=req-tg8s8y03g19z1ggiwtxv remoteAddr="192.0.2.1:1234" reqBytes=0 reqForwardedFor= reqHost=example.com reqMethod=GET reqPath=arvados/v1/containers reqQuery="count=none&filters=%5B%5B%22uuid%22%2C+%22in%22%2C+%5B%22zzzzz-dz642-queuedcontainer%22%2C+%22zhome-xvhdp-cr5queuedcontnr%22%5D%5D%5D&limit=1" respBody="{\"errors\":[\"Federated multi-object may not provide 'limit', 'offset' or 'order'.\"]}\n" respBytes=84 respStatus="Bad Request" respStatusCode=400 timeToStatus=0.000090 timeTotal=0.000095 timeWriteBody=0.000005
time="2019-10-23T15:48:57.385810194-04:00" level=info msg=response RequestID=req-pywbh1lqpb72jas1exjh remoteAddr="192.0.2.1:1234" reqBytes=0 reqForwardedFor= reqHost=example.com reqMethod=GET reqPath=arvados/v1/containers reqQuery="count=none&filters=%5B%5B%22uuid%22%2C+%22in%22%2C+%5B%22zzzzz-dz642-queuedcontainer%22%2C+%22zhome-xvhdp-cr5queuedcontnr%22%5D%5D%5D&offset=1" respBody="{\"errors\":[\"Federated multi-object may not provide 'limit', 'offset' or 'order'.\"]}\n" respBytes=84 respStatus="Bad Request" respStatusCode=400 timeToStatus=0.000085 timeTotal=0.000089 timeWriteBody=0.000004
time="2019-10-23T15:48:57.388025214-04:00" level=info msg=response RequestID=req-1t956utet518y1hfrkgl remoteAddr="192.0.2.1:1234" reqBytes=0 reqForwardedFor= reqHost=example.com reqMethod=GET reqPath=arvados/v1/containers reqQuery="count=none&filters=%5B%5B%22uuid%22%2C+%22in%22%2C+%5B%22zzzzz-dz642-queuedcontainer%22%2C+%22zhome-xvhdp-cr5queuedcontnr%22%5D%5D%5D&order=uuid" respBody="{\"errors\":[\"Federated multi-object may not provide 'limit', 'offset' or 'order'.\"]}\n" respBytes=84 respStatus="Bad Request" respStatusCode=400 timeToStatus=0.000076 timeTotal=0.000081 timeWriteBody=0.000005
time="2019-10-23T15:48:57.391704321-04:00" level=info msg=response RequestID=req-qk2odpyri15c1x420ouj remoteAddr="192.0.2.1:1234" reqBytes=0 reqForwardedFor= reqHost=example.com reqMethod=GET reqPath=arvados/v1/containers reqQuery="count=none&filters=%5B%5B%22uuid%22%2C+%22in%22%2C+%5B%22zzzzz-dz642-queuedcontainer%22%2C+%22zhome-xvhdp-cr5queuedcontnr%22%5D%5D%5D" respBody="{\"errors\":[\"Federated multi-object request for 2 objects which is more than max page size 1.\"]}\n" respBytes=96 respStatus="Bad Request" respStatusCode=400 timeToStatus=0.000083 timeTotal=0.000087 timeWriteBody=0.000005
time="2019-10-23T15:48:57.393634569-04:00" level=info msg=response RequestID=req-ez1gx1xyyrsu1e9e1lxl remoteAddr="192.0.2.1:1234" reqBytes=0 reqForwardedFor= reqHost=example.com reqMethod=GET reqPath=arvados/v1/containers reqQuery="count=none&filters=%5B%5B%22uuid%22%2C+%22in%22%2C+%5B%22zzzzz-dz642-queuedcontainer%22%2C+%22zhome-xvhdp-cr5queuedcontnr%22%5D%5D%5D&select=%5B%22command%22%5D" respBody="{\"errors\":[\"Federated multi-object request must include 'uuid' in 'select'\"]}\n" respBytes=78 respStatus="Bad Request" respStatusCode=400 timeToStatus=0.000073 timeTotal=0.000078 timeWriteBody=0.000004
time="2019-10-23T15:48:57.494838337-04:00" level=info msg=response RequestID=req-fym3n2hpts3l1c4ga7fq remoteAddr="192.0.2.1:1234" reqBytes=0 reqForwardedFor= reqHost=example.com reqMethod=GET reqPath=arvados/v1/workflows/zhome-7fd4e-validworkfloyml reqQuery= respBody="{\"errors\":[\"Get http://localhost:1/arvados/v1/workflows/zhome-7fd4e-validworkfloyml: dial tcp [::1]:1: connect: connection refused\"]}\n" respBytes=134 respStatus="Bad Gateway" respStatusCode=502 timeToStatus=0.000598 timeTotal=0.000609 timeWriteBody=0.000011
time="2019-10-23T15:48:57.550426946-04:00" level=info msg=response RequestID=req-1pkgw7bds88z11esdslr remoteAddr="[::1]:55364" reqBytes=0 reqForwardedFor= reqHost=example.com reqMethod=GET reqPath=arvados/v1/workflows/zzzzz-7fd4e-validworkfloyml reqQuery= respBody="{\"errors\":[\"Path not found (req-1pkgw7bds88z11esdslr)\"],\"error_token\":\"1571860137+f255799e\"}" respBytes=92 respStatus="Not Found" respStatusCode=404 timeToStatus=0.008935 timeTotal=0.009632 timeWriteBody=0.000697
time="2019-10-23T15:48:57.551264100-04:00" level=info msg=response RequestID=req-1pkgw7bds88z11esdslr remoteAddr="192.0.2.1:1234" reqBytes=0 reqForwardedFor= reqHost=example.com reqMethod=GET reqPath=arvados/v1/workflows/zzzzz-7fd4e-validworkfloyml reqQuery= respBody="{\"errors\":[\"Path not found (req-1pkgw7bds88z11esdslr)\"],\"error_token\":\"1571860137+f255799e\"}" respBytes=92 respStatus="Not Found" respStatusCode=404 timeToStatus=0.017552 timeTotal=0.017694 timeWriteBody=0.000142
time="2019-10-23T15:48:57.557191500-04:00" level=info msg=response RequestID=req-ihz6ok4xdq7i3qmcadcg remoteAddr="[::1]:34946" reqBytes=0 reqForwardedFor= reqHost=example.com reqMethod=GET reqPath=arvados/v1/workflows/zzzzz-7fd4e-validworkfloyml reqQuery= respBody="{\"errors\":[\"Not logged in (req-ihz6ok4xdq7i3qmcadcg)\"],\"error_token\":\"1571860137+854d1c29\"}" respBytes=91 respStatus=Unauthorized respStatusCode=401 timeToStatus=0.002663 timeTotal=0.002702 timeWriteBody=0.000039
time="2019-10-23T15:48:57.557377774-04:00" level=info msg=response RequestID=req-ihz6ok4xdq7i3qmcadcg remoteAddr="192.0.2.1:1234" reqBytes=0 reqForwardedFor= reqHost=example.com reqMethod=GET reqPath=arvados/v1/workflows/zzzzz-7fd4e-validworkfloyml reqQuery= respBody="{\"errors\":[\"Not logged in (req-ihz6ok4xdq7i3qmcadcg)\"],\"error_token\":\"1571860137+854d1c29\"}" respBytes=91 respStatus=Unauthorized respStatusCode=401 timeToStatus=0.003228 timeTotal=0.003262 timeWriteBody=0.000034
time="2019-10-23T15:48:57.572299048-04:00" level=info msg=response RequestID=req-js62n98hr43py407dfip remoteAddr="192.0.2.1:1234" reqBytes=0 reqForwardedFor= reqHost=example.com reqMethod=GET reqPath=arvados/v1/workflows/zzzzz-7fd4e-validworkfloyml reqQuery= respBody="{\"errors\":[\"Get https://[::]:46029/arvados/v1/workflows/zzzzz-7fd4e-validworkfloyml: http: server gave HTTP response to HTTPS client\"]}\n" respBytes=136 respStatus="Bad Gateway" respStatusCode=502 timeToStatus=0.006462 timeTotal=0.006471 timeWriteBody=0.000009
time="2019-10-23T15:48:57.638165362-04:00" level=info msg=response RequestID=req-1o1y9lb0rrglyrvz528f remoteAddr="[::1]:47486" reqBytes=0 reqForwardedFor= reqHost="[::]:45491" reqMethod=GET reqPath=arvados/v1/collections/99999999999999999999999999999999+99 reqQuery= respBody="{\"errors\":[\"not found\"]}\n" respBytes=25 respStatus="Not Found" respStatusCode=404 timeToStatus=0.010417 timeTotal=0.010425 timeWriteBody=0.000007
time="2019-10-23T15:48:57.638668370-04:00" level=info msg=response RequestID=req-1o1y9lb0rrglyrvz528f remoteAddr="192.0.2.1:1234" reqBytes=0 reqForwardedFor= reqHost=example.com reqMethod=GET reqPath=arvados/v1/collections/99999999999999999999999999999999+99 reqQuery= respBody="{\"errors\":[\"not found\"]}\n" respBytes=25 respStatus="Not Found" respStatusCode=404 timeToStatus=0.021258 timeTotal=0.021266 timeWriteBody=0.000008
time="2019-10-23T15:48:57.882949970-04:00" level=info msg=response RequestID=req-1m982cq91tq3mku59qog remoteAddr="[::1]:46344" reqBytes=0 reqForwardedFor= reqHost=example.com reqMethod=GET reqPath=arvados/v1/workflows/zzzzz-7fd4e-07n72l8yiarar43 reqQuery= respBody="{\"errors\":[\"Path not found (req-1m982cq91tq3mku59qog)\"],\"error_token\":\"1571860137+a9f4a9a0\"}" respBytes=92 respStatus="Not Found" respStatusCode=404 timeToStatus=0.009153 timeTotal=0.009208 timeWriteBody=0.000055
time="2019-10-23T15:48:57.883211197-04:00" level=info msg=response RequestID=req-1m982cq91tq3mku59qog remoteAddr="192.0.2.1:1234" reqBytes=0 reqForwardedFor= reqHost=example.com reqMethod=GET reqPath=arvados/v1/workflows/zzzzz-7fd4e-07n72l8yiarar43 reqQuery= respBody="{\"errors\":[\"Path not found (req-1m982cq91tq3mku59qog)\"],\"error_token\":\"1571860137+a9f4a9a0\"}" respBytes=92 respStatus="Not Found" respStatusCode=404 timeToStatus=0.010632 timeTotal=0.010663 timeWriteBody=0.000031
time="2019-10-23T15:48:57.891443486-04:00" level=info msg=response RequestID=req-1rqlzvl9takjg1qbgl12 remoteAddr="192.0.2.1:1234" reqBytes=0 reqForwardedFor= reqHost=example.com reqMethod=DELETE reqPath=arvados/v1/workflows/zzzzz-7fd4e-07n72l8yiarar43 reqQuery= respBody="{\"errors\":[\"Path not found (req-1rqlzvl9takjg1qbgl12)\"],\"error_token\":\"1571860137+11c819fd\"}" respBytes=92 respStatus="Not Found" respStatusCode=404 timeToStatus=0.008069 timeTotal=0.008119 timeWriteBody=0.000049

• covers controller, dispatchcloud, keepstore, keepproxy, and keep-web in cases where the error is being returned to the caller.

15713-controller-error-log @ 7db3ceda16742b65d73ebbc05d02351a5e0496bd -- https://ci.curoverse.com/view/Developer/job/developer-run-tests/1611/

Just a couple of questions, otherwise LGTM:

• Can sniffing the data be avoided if no error is occurring, to save some memory?
• Have you identified how to make nginx not change the error status? Maybe the documentation can be updated.

Skipped sniffing when response status < 400, and merged.

• Have you identified how to make nginx not change the error status? Maybe the documentation can be updated.

I don't think nginx is doing that. Tested in run-tests and 4xphq: Made RailsAPI .../containers/lock return 503. Controller logged 503, nginx logged 503, client received 503.

1. configuration had MaxConcurrentRequests: 0
2. sdk/go/httpserver bug (fixed in #15721) caused controller to execute the handler, which returned 500, and then (instead of stopping there) also execute the "503 / exceeded MaxConcurrentRequests" code path
3. sdk/go/httpserver bug (fixing here) caused controller to log the status from the last WriteHeader() call (503), instead of the first one (500), which is the only one actually delivered to the client/proxy when there's a "WriteHeader() called multiple times" bug

15713-controller-error-log @ 868833828599674d566e1c9550a035d5d8002076 -- https://ci.curoverse.com/view/Developer/job/developer-run-tests/1613/

Makes sense, 868833828599674d566e1c9550a035d5d8002076 LGTM, please merge. Thanks!