Kibana does not return logs that start with "::" #29640

olalonde · 2016-07-26T22:06:58Z

I installed k8s using cluster/kube-up.sh with AWS provider.

I have a container which outputs logs in this format:

::ffff:10.244.2.8 - - [26/Jul/2016:21:18:30 +0000] "GET / HTTP/1.1" 200 15563 "-" "Pingdom.com_bot_version_1.4_(http://www.pingdom.com/)"

For some reason, logs that look like this are not visible through Kibana but other logs are (e.g. User just registered!). After changing my log format to something more simple the logs start showing up in Kibana, e.g.:

GET / 200 - 0.429 ms

I have no idea how to dig further into this issue as I'm new to k8s, kibana, fluentd and elasticsearch.

The text was updated successfully, but these errors were encountered:

jimmidyson · 2016-07-29T13:43:44Z

Can you share the fluentd pod logs?

jimmidyson · 2016-07-29T13:51:47Z

I'm wondering if this is something to do with Elasticsearch rather than fluentd - ES logs would be useful too.

olalonde · 2016-07-29T21:41:37Z

Some potentially relevant logs:

$ ks logs fluentd-elasticsearch-ip-172-20-0-129.us-west-1.compute.internal
[...]
2016-07-29 21:19:28 +0000 [info]: Connection opened to Elasticsearch cluster => {:host=>"elasticsearch-logging", :port=>9200, :scheme=>"http"}
2016-07-29 21:19:21 +0000 [info]: reading config file path="/etc/td-agent/td-agent.conf"
2016-07-29 21:19:21 +0000 [info]: starting fluentd-0.12.19
2016-07-29 21:19:21 +0000 [info]: gem 'fluent-mixin-config-placeholders' version '0.3.0'
2016-07-29 21:19:21 +0000 [info]: gem 'fluent-mixin-plaintextformatter' version '0.2.6'
2016-07-29 21:19:21 +0000 [info]: gem 'fluent-plugin-docker_metadata_filter' version '0.1.1'
2016-07-29 21:19:21 +0000 [info]: gem 'fluent-plugin-elasticsearch' version '1.3.0'
2016-07-29 21:19:21 +0000 [info]: gem 'fluent-plugin-kubernetes_metadata_filter' version '0.14.0'
2016-07-29 21:19:21 +0000 [info]: gem 'fluent-plugin-mongo' version '0.7.11'
2016-07-29 21:19:21 +0000 [info]: gem 'fluent-plugin-rewrite-tag-filter' version '1.5.3'
2016-07-29 21:19:21 +0000 [info]: gem 'fluent-plugin-s3' version '0.6.4'
2016-07-29 21:19:21 +0000 [info]: gem 'fluent-plugin-scribe' version '0.10.14'
2016-07-29 21:19:21 +0000 [info]: gem 'fluent-plugin-td' version '0.10.28'
2016-07-29 21:19:21 +0000 [info]: gem 'fluent-plugin-td-monitoring' version '0.2.1'
2016-07-29 21:19:21 +0000 [info]: gem 'fluent-plugin-webhdfs' version '0.4.1'
2016-07-29 21:19:21 +0000 [info]: gem 'fluentd' version '0.12.19'
2016-07-29 21:19:21 +0000 [info]: adding match pattern="fluent.**" type="null"
2016-07-29 21:19:21 +0000 [info]: adding filter pattern="kubernetes.**" type="kubernetes_metadata"
2016-07-29 21:19:22 +0000 [info]: adding match pattern="**" type="elasticsearch"
2016-07-29 21:19:22 +0000 [info]: adding source type="tail"
2016-07-29 21:19:22 +0000 [info]: adding source type="tail"
2016-07-29 21:19:22 +0000 [info]: adding source type="tail"
2016-07-29 21:19:22 +0000 [info]: adding source type="tail"
2016-07-29 21:19:22 +0000 [info]: adding source type="tail"
2016-07-29 21:19:22 +0000 [info]: adding source type="tail"
2016-07-29 21:19:22 +0000 [info]: adding source type="tail"
2016-07-29 21:19:22 +0000 [info]: adding source type="tail"
2016-07-29 21:19:22 +0000 [info]: adding source type="tail"
2016-07-29 21:19:22 +0000 [info]: using configuration file: <ROOT>
  <match fluent.**>
    type null
  </match>
  <source>
    type tail
    path /var/log/containers/*.log
    pos_file /var/log/es-containers.log.pos
    time_format %Y-%m-%dT%H:%M:%S.%NZ
    tag kubernetes.*
    format json
    read_from_head true
  </source>
  <source>
    type tail
    format /^(?<time>[^ ]* [^ ,]*)[^\[]*\[[^\]]*\]\[(?<severity>[^ \]]*) *\] (?<message>.*)$/
    time_format %Y-%m-%d %H:%M:%S
    path /var/log/salt/minion
    pos_file /var/log/gcp-salt.pos
    tag salt
  </source>
  <source>
    type tail
    format syslog
    path /var/log/startupscript.log
    pos_file /var/log/es-startupscript.log.pos
    tag startupscript
  </source>
  <source>
    type tail
    format /^time="(?<time>[^)]*)" level=(?<severity>[^ ]*) msg="(?<message>[^"]*)"( err="(?<error>[^"]*)")?( statusCode=($<status_code>\d+))?/
    time_format %Y-%m-%dT%H:%M:%S.%NZ
    path /var/log/docker.log
    pos_file /var/log/es-docker.log.pos
    tag docker
  </source>
  <source>
    type tail
    format none
    path /var/log/etcd.log
    pos_file /var/log/es-etcd.log.pos
    tag etcd
  </source>
  <source>
    type tail
    format multiline
    format_firstline /^\w\d{4}/
    format1 /^(?<severity>\w)(?<time>\d{4} [^\s]*)\s+(?<pid>\d+)\s+(?<source>[^ \]]+)\] (?<message>.*)/
    time_format %m%d %H:%M:%S.%N
    path /var/log/kubelet.log
    pos_file /var/log/es-kubelet.log.pos
    tag kubelet
  </source>
  <source>
    type tail
    format multiline
    format_firstline /^\w\d{4}/
    format1 /^(?<severity>\w)(?<time>\d{4} [^\s]*)\s+(?<pid>\d+)\s+(?<source>[^ \]]+)\] (?<message>.*)/
    time_format %m%d %H:%M:%S.%N
    path /var/log/kube-apiserver.log
    pos_file /var/log/es-kube-apiserver.log.pos
    tag kube-apiserver
  </source>
  <source>
    type tail
    format multiline
    format_firstline /^\w\d{4}/
    format1 /^(?<severity>\w)(?<time>\d{4} [^\s]*)\s+(?<pid>\d+)\s+(?<source>[^ \]]+)\] (?<message>.*)/
    time_format %m%d %H:%M:%S.%N
    path /var/log/kube-controller-manager.log
    pos_file /var/log/es-kube-controller-manager.log.pos
    tag kube-controller-manager
  </source>
  <source>
    type tail
    format multiline
    format_firstline /^\w\d{4}/
    format1 /^(?<severity>\w)(?<time>\d{4} [^\s]*)\s+(?<pid>\d+)\s+(?<source>[^ \]]+)\] (?<message>.*)/
    time_format %m%d %H:%M:%S.%N
    path /var/log/kube-scheduler.log
    pos_file /var/log/es-kube-scheduler.log.pos
    tag kube-scheduler
  </source>
  <filter kubernetes.**>
    type kubernetes_metadata
  </filter>
  <match **>
    type elasticsearch
    log_level info
    include_tag_key true
    host elasticsearch-logging
    port 9200
    logstash_format true
    buffer_chunk_limit 2M
    buffer_queue_limit 32
    flush_interval 5s
    max_retry_wait 30
    disable_retry_limit
  </match>
</ROOT>
[...]
2016-07-29 21:21:22 +0000 [warn]: /var/log/containers/deis-monitor-telegraf-8kzp9_deis_deis-monitor-telegraf-6e6188d2e9f0383f54d7426ce6cc6d0fd1f2d91464dc3041c4086aafcaa2ba2f.log unreadable. It is excluded and would be examined next time.
2016-07-29 21:21:22 +0000 [warn]: /var/log/containers/blockai-api-v13-twitterbot-tl8x7_blockai-api_blockai-api-twitterbot-88ea286b58defc41bfda0ba1c44d3d69e4944e9ad159807b16eb4f3ace7ae90f.log unreadable. It is excluded and would be examined next time.
2016-07-29 21:21:22 +0000 [warn]: /var/log/containers/blockai-api-v13-twitterbot-tl8x7_blockai-api_POD-04e58818c771dd1cb09bfc5aa4db2450350f054026c9dc528fc41d0dcd16887a.log unreadable. It is excluded and would be examined next time.
2016-07-29 21:21:22 +0000 [warn]: /var/log/containers/blockai-api-v13-web-wlgiq_blockai-api_blockai-api-web-8147ef340a9eb87b9135e4f5c242d528af9f986f77dbac263bd5a1f387ca1718.log unreadable. It is excluded and would be examined next time.
2016-07-29 21:21:22 +0000 [warn]: /var/log/containers/slugbuild-blockai-api-f9c59d2a-d5d500f2_deis_POD-801dfdaa7899ba58f89987e40308f313d91ffa97e006106c0859c3d822dee655.log unreadable. It is excluded and would be examined next time.
2016-07-29 21:21:22 +0000 [warn]: /var/log/containers/blockstampd-v7-web-49dls_blockstampd_blockstampd-web-2ce985ed87a7bb17b4ce224b20fdae553aa34fb4d3eaf44af170788670994b63.log unreadable. It is excluded and would be examined next time.
[...]

~$ ks logs elasticsearch-logging-v1-pt8h6
[2016-07-29 01:15:38,724][INFO ][cluster.metadata         ] [Mystique] [logstash-2016.07.29] update_mapping [fluentd] (dynamic)
[2016-07-29 01:15:38,751][INFO ][cluster.metadata         ] [Mystique] [logstash-2016.07.29] update_mapping [fluentd] (dynamic)
[2016-07-29 01:19:38,773][INFO ][cluster.metadata         ] [Mystique] [logstash-2016.07.29] update_mapping [fluentd] (dynamic)
[2016-07-29 21:30:52,113][INFO ][cluster.metadata         ] [Mystique] [logstash-2016.07.29] update_mapping [fluentd] (dynamic)
[2016-07-29 21:30:56,734][INFO ][cluster.metadata         ] [Mystique] [logstash-2016.07.29] update_mapping [fluentd] (dynamic)

Also frequently seeing this in fluentd pod:

2016-07-28 14:47:55 +0000 [warn]: emit transaction failed: error_class=NoMethodError error="undefined method `strip\' for #<Symbol:0x000000033f370c>" tag="kubernetes.var.log.containers.blockai-ui-v6-web-7a4hq_blockai-ui_blockai-ui-web-39b0262bb5ba550fa6e7d824d337ff3b3cdb77d4c0a50b4221405cdae2be0475.log"\

jimmidyson · 2016-07-29T21:45:07Z

That last error I think is caused by the (very old) version of Kubernetes metadata filter fluentd plugin using symbols rather than strings for keys. This is fixed in later versions & the image needs updating to use a recent release (latest release is 0.24.0).

olalonde · 2016-08-08T23:41:24Z

Fixed in fluent/fluentd#1147

jimmidyson · 2016-08-09T06:46:04Z

Ah brilliant. Will have to wait for new fluentd release, unless they've made one already? That's a nasty bug.

spiffxp · 2017-06-23T21:47:01Z

/sig instrumentation
because elasticsearch-fluentd addon

fejta-bot · 2017-12-30T00:36:38Z

Issues go stale after 90d of inactivity.
Mark the issue as fresh with /remove-lifecycle stale.
Stale issues rot after an additional 30d of inactivity and eventually close.

Prevent issues from auto-closing with an /lifecycle frozen comment.

If this issue is safe to close now please do so with /close.

Send feedback to sig-testing, kubernetes/test-infra and/or @fejta.
/lifecycle stale

fejta-bot · 2018-01-29T00:45:15Z

Stale issues rot after 30d of inactivity.
Mark the issue as fresh with /remove-lifecycle rotten.
Rotten issues close after an additional 30d of inactivity.

If this issue is safe to close now please do so with /close.

Send feedback to sig-testing, kubernetes/test-infra and/or fejta.
/lifecycle rotten
/remove-lifecycle stale

fejta-bot · 2018-02-28T01:30:51Z

Rotten issues close after 30d of inactivity.
Reopen the issue with /reopen.
Mark the issue as fresh with /remove-lifecycle rotten.

Send feedback to sig-testing, kubernetes/test-infra and/or fejta.
/close

k8s-github-robot added area/apiserver team/cluster labels Aug 3, 2016

k8s-github-robot added the needs-sig Indicates an issue or PR lacks a `sig/foo` label and requires one. label May 31, 2017

k8s-ci-robot added the sig/instrumentation Categorizes an issue or PR as relevant to SIG Instrumentation. label Jun 23, 2017

k8s-github-robot removed the needs-sig Indicates an issue or PR lacks a `sig/foo` label and requires one. label Jun 23, 2017

k8s-ci-robot added the lifecycle/stale Denotes an issue or PR has remained open with no activity and has become stale. label Dec 30, 2017

k8s-ci-robot added lifecycle/rotten Denotes an issue or PR that has aged beyond stale and will be auto-closed. and removed lifecycle/stale Denotes an issue or PR has remained open with no activity and has become stale. labels Jan 29, 2018

k8s-ci-robot closed this as completed Feb 28, 2018

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Kibana does not return logs that start with "::" #29640

Kibana does not return logs that start with "::" #29640

olalonde commented Jul 26, 2016 •

edited

jimmidyson commented Jul 29, 2016

jimmidyson commented Jul 29, 2016

olalonde commented Jul 29, 2016 •

edited

jimmidyson commented Jul 29, 2016

olalonde commented Aug 8, 2016

jimmidyson commented Aug 9, 2016

spiffxp commented Jun 23, 2017

fejta-bot commented Dec 30, 2017

fejta-bot commented Jan 29, 2018

fejta-bot commented Feb 28, 2018

Kibana does not return logs that start with "::" #29640

Kibana does not return logs that start with "::" #29640

Comments

olalonde commented Jul 26, 2016 • edited

jimmidyson commented Jul 29, 2016

jimmidyson commented Jul 29, 2016

olalonde commented Jul 29, 2016 • edited

jimmidyson commented Jul 29, 2016

olalonde commented Aug 8, 2016

jimmidyson commented Aug 9, 2016

spiffxp commented Jun 23, 2017

fejta-bot commented Dec 30, 2017

fejta-bot commented Jan 29, 2018

fejta-bot commented Feb 28, 2018

olalonde commented Jul 26, 2016 •

edited

olalonde commented Jul 29, 2016 •

edited