Add 'Host' header to fix the watcher

[mindfulmonk]

Hi, I have been debugging an issue with fluent-plugins-nursery/fluent-plugin-kubernetes_metadata_filter#50

I've managed to replicate it with this:

require 'kubeclient'

ssl_options = { verify_ssl: OpenSSL::SSL::VERIFY_NONE }
auth_options = {
  bearer_token_file: 'token'
}
client = Kubeclient::Client.new(
  'https://kubernetes/api/', 'v1', auth_options: auth_options, ssl_options: ssl_options
)

watcher = client.watch_pods
watcher.each do |notice|
  puts notice
end

I'm not sure if this is the best way to resolve this, but it works.

Here is the error message I was getting before:

400 Bad Request: missing required Host header
.gem/ruby/2.4.1/gems/kubeclient-2.4.0/lib/kubeclient/watch_stream.rb:27:in `each': Bad Request (Kubeclient::HttpError)

[simon3z]

@cben @moolitayer please review/approve.

[simon3z]

@mindfulmonk can you squash the PR in a single commit? Thanks.

[cben]

@mindfulmonk have you also seen this problem with create/get/update/delete, or only watch?
(I'm asking because these use different HTTP libs.)

I'm not able to reproduce the underlying problem this PR seems to address:
Both with http 0.9.8 and 2.2.2, Host header is set automatically even if I give a headers hash without it:

> require 'http'
> puts HTTP.get("https://httpbin.org/headers", headers: {"a" => "b"}).body.to_s
{
  "headers": {
    "A": "b", 
    "Connection": "close", 
    "Host": "httpbin.org", 
    "User-Agent": "http.rb/2.2.2"
  }
}

Same with RestClient.get.

I'll try to reproduce by actually using kubeclient later.
Can you show the exact URL you pass — is it actually https://kubernetes/api/? Did you by chance use IP address? Looks so from fluent-plugins-nursery/fluent-plugin-kubernetes_metadata_filter#50, but then I'm not sure how will this PR fix it? Does a Host: 192.168.99.100 header actually make Kubernetes happy?

[mindfulmonk]

I have seen this issue only with watch, for example this works fine:

puts client.get_nodes

I have used the fqdn and tested the API with a curl first to ensure it works.
That being said it fixes the same issue on minishift that I had with using the IP as the fqdn.

When debugging I've put this into /lib/kubeclient/watch_stream.rb

puts @http_options
And you can see that it doesn't pass the Host: header, it only passes the Authorization Bearer.

{:basic_auth_user=>nil, :basic_auth_password=>nil, :headers=>{:Authorization=>"Bearer xxxxxxxxxxxxx\n"}, :http_proxy_uri=>nil, :ssl=>{:ca_file=>nil, :cert=>nil, :cert_store=>nil, :key=>nil, :verify_mode=>0}, :socket_class=>nil, :ssl_socket_class=>nil}

[cben]

According to https://github.com/httprb/http/blob/256539edd9ad8acf0f8a424114ac9fae6fb44782/lib/http/request.rb#L199-L202 http gem also always set a host header (and if we want to set it ourselves we maybe should include non-default port as that code does?) Could you repeat the experiment with logging, before and after your patch (or at least before, I mostly want to understand why it didn't work)? Add to Gemfile: gem "httplog", require: false and bundle install Then *after* requiring kubeclient do: require 'httplog' HttpLog.configure { |config| config.log_headers = true } then do the watch...

[mindfulmonk]

Code used:

require 'kubeclient'
require 'rack'
require 'httplog'

HttpLog.configure { |config| config.log_headers = true }

ssl_options = { verify_ssl: OpenSSL::SSL::VERIFY_NONE }
auth_options = {
  bearer_token_file: 'token2'
}
client = Kubeclient::Client.new(
  'https://example-cluster.com/api/', 'v1', auth_options: auth_options, ssl_options: ssl_options
)

watcher = client.watch_pods
watcher.each do |notice|
end

Result without the fix:

D, [2017-05-30T13:38:28.878764 #2114] DEBUG -- : [httplog] Connecting: example-cluster.com:443
D, [2017-05-30T13:38:28.984403 #2114] DEBUG -- : [httplog] Sending: GET http://example-cluster.com:443/api/v1
D, [2017-05-30T13:38:28.984702 #2114] DEBUG -- : [httplog] Header: accept: */*
D, [2017-05-30T13:38:28.984852 #2114] DEBUG -- : [httplog] Header: accept-encoding: gzip, deflate
D, [2017-05-30T13:38:28.984973 #2114] DEBUG -- : [httplog] Header: user-agent: rest-client/2.0.2 (linux-gnu x86_64) ruby/2.4.1p111
D, [2017-05-30T13:38:28.985078 #2114] DEBUG -- : [httplog] Header: authorization: Bearer xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
D, [2017-05-30T13:38:28.985175 #2114] DEBUG -- : [httplog] Header: host: example-cluster.com
D, [2017-05-30T13:38:28.985426 #2114] DEBUG -- : [httplog] Data: 
D, [2017-05-30T13:38:29.038511 #2114] DEBUG -- : [httplog] Status: 200
D, [2017-05-30T13:38:29.038979 #2114] DEBUG -- : [httplog] Benchmark: 0.034335 seconds
D, [2017-05-30T13:38:29.039213 #2114] DEBUG -- : [httplog] Header: cache-control: no-store
D, [2017-05-30T13:38:29.039360 #2114] DEBUG -- : [httplog] Header: content-type: application/json
D, [2017-05-30T13:38:29.039489 #2114] DEBUG -- : [httplog] Header: date: Tue, 30 May 2017 12:38:27 GMT
D, [2017-05-30T13:38:29.039613 #2114] DEBUG -- : [httplog] Header: transfer-encoding: chunked
D, [2017-05-30T13:38:29.039861 #2114] DEBUG -- : [httplog] Response:
bunch of json here

D, [2017-05-30T13:38:29.049744 #2114] DEBUG -- : [httplog] Sending: GET https://example-cluster.com/api/v1/watch/pods
D, [2017-05-30T13:38:29.049911 #2114] DEBUG -- : [httplog] Header: Authorization: Bearer xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx

D, [2017-05-30T13:38:29.049963 #2114] DEBUG -- : [httplog] Header: Connection: close
D, [2017-05-30T13:38:29.049995 #2114] DEBUG -- : [httplog] Header: Host: example-cluster.com
D, [2017-05-30T13:38:29.050024 #2114] DEBUG -- : [httplog] Header: User-Agent: http.rb/0.9.8
D, [2017-05-30T13:38:29.050070 #2114] DEBUG -- : [httplog] Data: 
D, [2017-05-30T13:38:29.050133 #2114] DEBUG -- : [httplog] Connecting: example-cluster.com
D, [2017-05-30T13:38:29.180762 #2114] DEBUG -- : [httplog] Status: 400
D, [2017-05-30T13:38:29.180969 #2114] DEBUG -- : [httplog] Benchmark: 0.130588 seconds
D, [2017-05-30T13:38:29.181151 #2114] DEBUG -- : [httplog] Header: Content-Type: text/plain
D, [2017-05-30T13:38:29.181268 #2114] DEBUG -- : [httplog] Header: Connection: close
D, [2017-05-30T13:38:29.181904 #2114] DEBUG -- : [httplog] Response:
400 Bad Request: missing required Host header
/home/username/.gem/ruby/2.4.1/gems/kubeclient-2.4.0/lib/kubeclient/watch_stream.rb:20:in `each': Bad Request (KubeException)
	from main.rb:16:in `<main>'

Result with the fix

  D, [2017-05-30T13:38:54.801152 #2173] DEBUG -- : [httplog] Connecting: example-cluster.com:443
  D, [2017-05-30T13:38:54.907112 #2173] DEBUG -- : [httplog] Sending: GET http://example-cluster.com:443/api/v1
  D, [2017-05-30T13:38:54.907357 #2173] DEBUG -- : [httplog] Header: accept: */*
  D, [2017-05-30T13:38:54.907464 #2173] DEBUG -- : [httplog] Header: accept-encoding: gzip, deflate
  D, [2017-05-30T13:38:54.907534 #2173] DEBUG -- : [httplog] Header: user-agent: rest-client/2.0.2 (linux-gnu x86_64) ruby/2.4.1p111
  D, [2017-05-30T13:38:54.907592 #2173] DEBUG -- : [httplog] Header: host: example-cluster.com
  D, [2017-05-30T13:38:54.907648 #2173] DEBUG -- : [httplog] Header: authorization: Bearer xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
  D, [2017-05-30T13:38:54.907747 #2173] DEBUG -- : [httplog] Data: 
  D, [2017-05-30T13:38:54.958801 #2173] DEBUG -- : [httplog] Status: 200
  D, [2017-05-30T13:38:54.958917 #2173] DEBUG -- : [httplog] Benchmark: 0.038313 seconds
  D, [2017-05-30T13:38:54.958970 #2173] DEBUG -- : [httplog] Header: cache-control: no-store
  D, [2017-05-30T13:38:54.958997 #2173] DEBUG -- : [httplog] Header: content-type: application/json
  D, [2017-05-30T13:38:54.959019 #2173] DEBUG -- : [httplog] Header: date: Tue, 30 May 2017 12:38:53 GMT
  D, [2017-05-30T13:38:54.959040 #2173] DEBUG -- : [httplog] Header: transfer-encoding: chunked
  D, [2017-05-30T13:38:54.959103 #2173] DEBUG -- : [httplog] Response:
bunch of json here

  D, [2017-05-30T13:38:54.962331 #2173] DEBUG -- : [httplog] Sending: GET https://example-cluster.com/api/v1/watch/pods
  D, [2017-05-30T13:38:54.962432 #2173] DEBUG -- : [httplog] Header: Host: example-cluster.com
  D, [2017-05-30T13:38:54.962477 #2173] DEBUG -- : [httplog] Header: Authorization: Bearer xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx

  D, [2017-05-30T13:38:54.962509 #2173] DEBUG -- : [httplog] Header: Connection: close
  D, [2017-05-30T13:38:54.962527 #2173] DEBUG -- : [httplog] Header: User-Agent: http.rb/0.9.8
  D, [2017-05-30T13:38:54.962554 #2173] DEBUG -- : [httplog] Data: 
  D, [2017-05-30T13:38:54.962599 #2173] DEBUG -- : [httplog] Connecting: example-cluster.com
  D, [2017-05-30T13:38:55.103207 #2173] DEBUG -- : [httplog] Status: 200
  D, [2017-05-30T13:38:55.103322 #2173] DEBUG -- : [httplog] Benchmark: 0.140598 seconds
  D, [2017-05-30T13:38:55.103463 #2173] DEBUG -- : [httplog] Header: Cache-Control: no-store
  D, [2017-05-30T13:38:55.103518 #2173] DEBUG -- : [httplog] Header: Content-Type: application/json
  D, [2017-05-30T13:38:55.103549 #2173] DEBUG -- : [httplog] Header: Date: Tue, 30 May 2017 12:38:53 GMT
  D, [2017-05-30T13:38:55.103598 #2173] DEBUG -- : [httplog] Header: Transfer-Encoding: chunked
  D, [2017-05-30T13:38:55.104021 #2173] DEBUG -- : [httplog] Response:

  /home/username/.gem/ruby/2.4.1/gems/http-0.9.8/lib/http/response/body.rb:54:in `stream!': body has already been consumed (HTTP::StateError)
  	from /home/username/.gem/ruby/2.4.1/gems/http-0.9.8/lib/http/response/body.rb:20:in `readpartial'
  	from /home/username/.gem/ruby/2.4.1/gems/http-0.9.8/lib/http/response/body.rb:26:in `each'
  	from /home/username/.gem/ruby/2.4.1/gems/kubeclient-2.4.0/lib/kubeclient/watch_stream.rb:24:in `each'
  	from main.rb:16:in `<main>'

[cben]

Sorry, missed your reply and forgot about this.
Fascinating. The log shows exactly same Host: example-cluster.com header sent before and after, yet the result is different.
@ilackarms, you know http and some relevant kubernetes / go http code — any idea what's going on?
Can it be the order of headers matters, requiring Host to be first?

The message seems to come from Go's http lib:
https://github.com/golang/go/blob/88a235042/src/net/http/server.go#L947
which doesn't seem to care about order, req.Header is a Header, alias for map[string][]string.

https://tools.ietf.org/html/rfc7230#section-5.4 says client SHOULD put Host first — isn't a MUST.

[JCotton1123]

I ran into this same exact issue today - when using the fluent-plugin-kubernetes_metadata_filter plugin Fluentd was crashing as a result of trying to setup the watch with the error about the missing host header. I confirmed this patch resolves the issue.

[cben]

Thanks. I'm still reluctant to put in a "magic" fix if I can't explain what's the problem and how it helps... Trying to investigate more... Staring at http code, I really don't see any way it could have missed this.

@JCotton1123 did see this with a numeric IP, or with a domain name?
And what kubernetes version is that?
I'm able to reproduce same headers as mindfulmonk's dump above #249 (comment), but I'm not getting any required Host header errors...

But maybe I should just put something like this in. Please do nag me if I keep this unanswered 😄

• I think if we do force the header, it should be host:port.
  This patch sends Host: 192.168.99.100 where previously it sent Host: 192.168.99.100:8443. Most servers won't care (as you're already connected to correct port), but in principle this is wrong.

• The patch does make Host header come first (due to ruby Hash keeping order). I'll try sending https://github.com/httprb/http a patch to put it first per rfc SHOULD...

[JCotton1123]

We're utilizing hostnames. K8s version 1.13. @cben