{"action":"created","issue":{"url":"https://api.github.com/repos/openshift/origin/issues/2348","labels_url":"https://api.github.com/repos/openshift/origin/issues/2348/labels{/name}","comments_url":"https://api.github.com/repos/openshift/origin/issues/2348/comments","events_url":"https://api.github.com/repos/openshift/origin/issues/2348/events","html_url":"https://github.com/openshift/origin/issues/2348","id":78068801,"number":2348,"title":"connection between client and proxy breaks when client is receiving logs","user":{"login":"TomasTomecek","id":1662493,"avatar_url":"https://avatars.githubusercontent.com/u/1662493?v=3","gravatar_id":"","url":"https://api.github.com/users/TomasTomecek","html_url":"https://github.com/TomasTomecek","followers_url":"https://api.github.com/users/TomasTomecek/followers","following_url":"https://api.github.com/users/TomasTomecek/following{/other_user}","gists_url":"https://api.github.com/users/TomasTomecek/gists{/gist_id}","starred_url":"https://api.github.com/users/TomasTomecek/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/TomasTomecek/subscriptions","organizations_url":"https://api.github.com/users/TomasTomecek/orgs","repos_url":"https://api.github.com/users/TomasTomecek/repos","events_url":"https://api.github.com/users/TomasTomecek/events{/privacy}","received_events_url":"https://api.github.com/users/TomasTomecek/received_events","type":"User","site_admin":false},"labels":[{"url":"https://api.github.com/repos/openshift/origin/labels/component/logging","name":"component/logging","color":"0052cc"},{"url":"https://api.github.com/repos/openshift/origin/labels/kind/bug","name":"kind/bug","color":"fc2929"},{"url":"https://api.github.com/repos/openshift/origin/labels/priority/P2","name":"priority/P2","color":"fbca04"}],"state":"open","locked":false,"assignee":{"login":"brenton","id":832,"avatar_url":"https://avatars.githubusercontent.com/u/832?v=3","gravatar_id":"","url":"https://api.github.com/users/brenton","html_url":"https://github.com/brenton","followers_url":"https://api.github.com/users/brenton/followers","following_url":"https://api.github.com/users/brenton/following{/other_user}","gists_url":"https://api.github.com/users/brenton/gists{/gist_id}","starred_url":"https://api.github.com/users/brenton/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/brenton/subscriptions","organizations_url":"https://api.github.com/users/brenton/orgs","repos_url":"https://api.github.com/users/brenton/repos","events_url":"https://api.github.com/users/brenton/events{/privacy}","received_events_url":"https://api.github.com/users/brenton/received_events","type":"User","site_admin":false},"milestone":null,"comments":9,"created_at":"2015-05-19T12:32:19Z","updated_at":"2015-05-19T19:58:04Z","closed_at":null,"body":"We are using httpd as proxy between client and master. Here's the configuration:\r\n\r\n```\r\nSetEnv proxy-sendchunked 1\r\nProxyRequests Off\r\n<Location \"/\">\r\n    ProxyPass https://127.0.0.1:8443/ connectiontimeout=300 timeout=3000\r\n    ProxyPassReverse https://127.0.0.1:8443/\r\n</Location>\r\n```\r\n\r\nUnfortunately, when we are fetching logs, the connection tends to break when pod is stuck on some operation which doesn't produce logs (therefore I thought it's timeout). Then I looked into httpd's logs and saw some errors there:\r\n\r\n```\r\n[Tue May 19 08:13:48.613935 2015] [dumpio:trace7] [pid 14952] mod_dumpio.c(63): [client 10.3.14.233:56997] mod_dumpio:  dumpio_out (data-IMMORTAL): 2 bytes\r\n[Tue May 19 08:13:48.613940 2015] [dumpio:trace7] [pid 14952] mod_dumpio.c(103): [client 10.3.14.233:56997] mod_dumpio:  dumpio_out (data-IMMORTAL): \\r\\n\r\n[Tue May 19 08:13:48.613954 2015] [dumpio:trace7] [pid 14952] mod_dumpio.c(140): [remote 127.0.0.1:8443] mod_dumpio: dumpio_in [getline-nonblocking] 0 readbytes\r\n[Tue May 19 08:13:48.613964 2015] [dumpio:trace7] [pid 14952] mod_dumpio.c(63): [remote 127.0.0.1:8443] mod_dumpio:  dumpio_in (data-TRANSIENT): 2 bytes\r\n[Tue May 19 08:13:48.613968 2015] [dumpio:trace7] [pid 14952] mod_dumpio.c(103): [remote 127.0.0.1:8443] mod_dumpio:  dumpio_in (data-TRANSIENT): \\r\\n\r\n[Tue May 19 08:13:48.613973 2015] [dumpio:trace7] [pid 14952] mod_dumpio.c(140): [remote 127.0.0.1:8443] mod_dumpio: dumpio_in [getline-nonblocking] 0 readbytes\r\n[Tue May 19 08:13:48.613978 2015] [dumpio:trace7] [pid 14952] mod_dumpio.c(63): [remote 127.0.0.1:8443] mod_dumpio:  dumpio_in (data-TRANSIENT): 3 bytes\r\n[Tue May 19 08:13:48.613982 2015] [dumpio:trace7] [pid 14952] mod_dumpio.c(103): [remote 127.0.0.1:8443] mod_dumpio:  dumpio_in (data-TRANSIENT): 0\\r\\n\r\n[Tue May 19 08:13:48.613988 2015] [dumpio:trace7] [pid 14952] mod_dumpio.c(140): [remote 127.0.0.1:8443] mod_dumpio: dumpio_in [getline-blocking] 0 readbytes\r\n[Tue May 19 08:13:48.613992 2015] [dumpio:trace7] [pid 14952] mod_dumpio.c(63): [remote 127.0.0.1:8443] mod_dumpio:  dumpio_in (data-TRANSIENT): 2 bytes\r\n[Tue May 19 08:13:48.613996 2015] [dumpio:trace7] [pid 14952] mod_dumpio.c(103): [remote 127.0.0.1:8443] mod_dumpio:  dumpio_in (data-TRANSIENT): \\r\\n\r\n[Tue May 19 08:13:48.614004 2015] [proxy:debug] [pid 14952] proxy_util.c(2215): AH00943: https: has released connection for (127.0.0.1)\r\n[Tue May 19 08:13:48.614011 2015] [dumpio:trace7] [pid 14952] mod_dumpio.c(164): [client 10.3.14.233:56997] mod_dumpio: dumpio_out\r\n[Tue May 19 08:13:48.614015 2015] [dumpio:trace7] [pid 14952] mod_dumpio.c(63): [client 10.3.14.233:56997] mod_dumpio:  dumpio_out (data-IMMORTAL): 5 bytes\r\n[Tue May 19 08:13:48.614019 2015] [dumpio:trace7] [pid 14952] mod_dumpio.c(103): [client 10.3.14.233:56997] mod_dumpio:  dumpio_out (data-IMMORTAL): 0\\r\\n\\r\\n\r\n[Tue May 19 08:13:48.614023 2015] [dumpio:trace7] [pid 14952] mod_dumpio.c(63): [client 10.3.14.233:56997] mod_dumpio:  dumpio_out (metadata-EOS): 0 bytes\r\n[Tue May 19 08:13:48.614490 2015] [dumpio:trace7] [pid 14952] mod_dumpio.c(164): [client 10.3.14.233:56997] mod_dumpio: dumpio_out\r\n[Tue May 19 08:13:48.614509 2015] [dumpio:trace7] [pid 14952] mod_dumpio.c(63): [client 10.3.14.233:56997] mod_dumpio:  dumpio_out (metadata-EOR): 0 bytes\r\n[Tue May 19 08:13:48.614570 2015] [dumpio:trace7] [pid 14952] mod_dumpio.c(140): [client 10.3.14.233:56997] mod_dumpio: dumpio_in [speculative-nonblocking] 1 readbytes\r\n[Tue May 19 08:13:48.614581 2015] [dumpio:trace7] [pid 14952] mod_dumpio.c(164): [client 10.3.14.233:56997] mod_dumpio: dumpio_out\r\n[Tue May 19 08:13:48.614586 2015] [dumpio:trace7] [pid 14952] mod_dumpio.c(63): [client 10.3.14.233:56997] mod_dumpio:  dumpio_out (metadata-FLUSH): 0 bytes\r\n[Tue May 19 08:13:48.614600 2015] [dumpio:trace7] [pid 14952] mod_dumpio.c(140): [client 10.3.14.233:56997] mod_dumpio: dumpio_in [getline-blocking] 0 readbytes\r\n[Tue May 19 08:13:48.618103 2015] [dumpio:trace7] [pid 14952] mod_dumpio.c(164): [client 10.3.14.233:56997] mod_dumpio: dumpio_out\r\n[Tue May 19 08:13:48.618119 2015] [dumpio:trace7] [pid 14952] mod_dumpio.c(63): [client 10.3.14.233:56997] mod_dumpio:  dumpio_out (metadata-FLUSH): 0 bytes\r\n[Tue May 19 08:13:48.618124 2015] [dumpio:trace7] [pid 14952] mod_dumpio.c(63): [client 10.3.14.233:56997] mod_dumpio:  dumpio_out (metadata-EOC): 0 bytes\r\n[Tue May 19 08:15:44.168840 2015] [ssl:info] [pid 14922] [remote 127.0.0.1:8443] AH01992: SSL library error 1 reading data\r\n[Tue May 19 08:15:44.169071 2015] [ssl:info] [pid 14922] SSL Library Error: error:1408F119:SSL routines:SSL3_GET_RECORD:decryption failed or bad record mac\r\n[Tue May 19 08:15:44.169098 2015] [dumpio:trace7] [pid 14922] mod_dumpio.c(151): [remote 127.0.0.1:8443] mod_dumpio: dumpio_in - 20014\r\n[Tue May 19 08:15:44.169118 2015] [http:info] [pid 14922] (20014)Internal error: [remote 127.0.0.1:8443] AH01590: Error reading chunk--\r\n[Tue May 19 08:15:44.169186 2015] [dumpio:trace7] [pid 14922] mod_dumpio.c(164): [remote 127.0.0.1:8443] mod_dumpio: dumpio_out\r\n[Tue May 19 08:15:44.169200 2015] [dumpio:trace7] [pid 14922] mod_dumpio.c(63): [remote 127.0.0.1:8443] mod_dumpio:  dumpio_out (metadata-ERROR): 0 bytes\r\n[Tue May 19 08:15:44.169212 2015] [dumpio:trace7] [pid 14922] mod_dumpio.c(63): [remote 127.0.0.1:8443] mod_dumpio:  dumpio_out (metadata-EOS): 0 bytes\r\n[Tue May 19 08:15:44.169383 2015] [proxy:debug] [pid 14922] proxy_util.c(2215): AH00943: HTTPS: has released connection for (127.0.0.1)\r\n[Tue May 19 08:15:44.169441 2015] [dumpio:trace7] [pid 14922] mod_dumpio.c(164): [client 10.34.4.200:36793] mod_dumpio: dumpio_out\r\n[Tue May 19 08:15:44.169456 2015] [dumpio:trace7] [pid 14922] mod_dumpio.c(63): [client 10.34.4.200:36793] mod_dumpio:  dumpio_out (data-IMMORTAL): 5 bytes\r\n[Tue May 19 08:15:44.169470 2015] [dumpio:trace7] [pid 14922] mod_dumpio.c(103): [client 10.34.4.200:36793] mod_dumpio:  dumpio_out (data-IMMORTAL): 0\\r\\n\\r\\n\r\n[Tue May 19 08:15:44.169484 2015] [dumpio:trace7] [pid 14922] mod_dumpio.c(63): [client 10.34.4.200:36793] mod_dumpio:  dumpio_out (metadata-EOS): 0 bytes\r\n[Tue May 19 08:15:44.169597 2015] [dumpio:trace7] [pid 14922] mod_dumpio.c(164): [client 10.34.4.200:36793] mod_dumpio: dumpio_out\r\n[Tue May 19 08:15:44.170306 2015] [dumpio:trace7] [pid 14922] mod_dumpio.c(63): [client 10.34.4.200:36793] mod_dumpio:  dumpio_out (metadata-EOR): 0 bytes\r\n[Tue May 19 08:15:44.170424 2015] [dumpio:trace7] [pid 14922] mod_dumpio.c(164): [client 10.34.4.200:36793] mod_dumpio: dumpio_out\r\n[Tue May 19 08:15:44.170436 2015] [dumpio:trace7] [pid 14922] mod_dumpio.c(63): [client 10.34.4.200:36793] mod_dumpio:  dumpio_out (metadata-FLUSH): 0 bytes\r\n[Tue May 19 08:15:44.170456 2015] [dumpio:trace7] [pid 14922] mod_dumpio.c(164): [client 10.34.4.200:36793] mod_dumpio: dumpio_out\r\n[Tue May 19 08:15:44.170466 2015] [dumpio:trace7] [pid 14922] mod_dumpio.c(63): [client 10.34.4.200:36793] mod_dumpio:  dumpio_out (metadata-FLUSH): 0 bytes\r\n[Tue May 19 08:15:44.170476 2015] [dumpio:trace7] [pid 14922] mod_dumpio.c(63): [client 10.34.4.200:36793] mod_dumpio:  dumpio_out (metadata-EOC): 0 bytes\r\n```\r\n\r\nIs it possible that master is sendind invalid chunks to proxy?\r\n\r\n```\r\nInternal error: [remote 127.0.0.1:8443] AH01590: Error reading chunk--\r\n```\r\n\r\nHere are last lines on client:\r\n\r\n```\r\n2015-05-19T12:09:41.491795466Z 2015-05-19 08:09:41,488 - dock.plugins.squash - INFO - Saving image 43cd32a73f3584bd03202d14980320d640f490ed8d77d4dcc6b56801d89e2b06 to /tmp/tmp-docker-squash-q06lc9/image.tar file...\r\n2015-05-19T12:09:41.491795466Z 2015-05-19 08:09:41,488 - dock.plugins.squash - DEBUG - Try #1...\r\n* Closing connection 0\r\n2015-05-19 14:15:45,874 - osbs.http - DEBUG - closing curl multi: 139780675401648\r\n```\r\n"},"comment":{"url":"https://api.github.com/repos/openshift/origin/issues/comments/103651078","html_url":"https://github.com/openshift/origin/issues/2348#issuecomment-103651078","issue_url":"https://api.github.com/repos/openshift/origin/issues/2348","id":103651078,"user":{"login":"brenton","id":832,"avatar_url":"https://avatars.githubusercontent.com/u/832?v=3","gravatar_id":"","url":"https://api.github.com/users/brenton","html_url":"https://github.com/brenton","followers_url":"https://api.github.com/users/brenton/followers","following_url":"https://api.github.com/users/brenton/following{/other_user}","gists_url":"https://api.github.com/users/brenton/gists{/gist_id}","starred_url":"https://api.github.com/users/brenton/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/brenton/subscriptions","organizations_url":"https://api.github.com/users/brenton/orgs","repos_url":"https://api.github.com/users/brenton/repos","events_url":"https://api.github.com/users/brenton/events{/privacy}","received_events_url":"https://api.github.com/users/brenton/received_events","type":"User","site_admin":false},"created_at":"2015-05-19T19:58:04Z","updated_at":"2015-05-19T19:58:04Z","body":"I finally stumbled across ` SetEnv proxy-sendchunked 1` and now I see you already have that in your configuration.  With that set before my proxypass directives I now see:\r\n\r\n~~~\r\n[Tue May 19 15:33:50.212787 2015] [http:info] [pid 11897] (70007)The timeout specified has expired: [remote 192.168.133.2:8080] AH01590: Error reading chunk\r\n~~~\r\n\r\nThat's closer to the error you're seeing.  So far I'm able to tail logs through the proxy however long I set the `ProxyTimeout` so I think things are working as expected.  I'll see if QE has hit this."}}