Hide Forgot
Description of problem: This is a regression logging correctness issue on OCP 3.4, not previously observed on OCP 3.3. When logging with logger from inside a docker container, and when the logger tag string contains a trailing colon, the trailing colon gets truncated in Elasticsearch when stored in the systemd.u.SYSLOG_IDENTIFIER field. (Note in OCP 3.3, the ident field was used). The trailing colon is still retained in syslog and journal, and should not be truncated in Elasticsearch. Version-Release number of selected component (if applicable): openshift v3.4.0.24+52fd77b kubernetes v1.4.0+776c994 Elasticsearch version" : { "number" : "2.4.1", "build_hash" : "945a6e093cc306cec722eb0207b671962b6d8905", "build_timestamp" : "2016-11-17T20:39:42Z", "build_snapshot" : false, "lucene_version" : "5.5.2" } How reproducible: Reproducible Steps to Reproduce: 1. on any OpenShift 3.4 node, run the following commands: uuid=`uuidgen` docker run -v /dev/log:/dev/log -it --privileged -d --log-driver=journald ${container_image} logger -s -t EFK: $uuid Example: docker run -v /dev/log:/dev/log -it --privileged -d --log-driver=journald gcr.io/google_containers/busybox:1.24 logger -s -t EFK: $uuid 2. Check journal: journalctl -o export MESSAGE=$uuid You should see: SYSLOG_IDENTIFIER=EFK: Check syslog: grep $uuid /var/log/messages Nov 28 18:22:55 <ip_address> EFK:: <$uuid> You should see two colons since one is a delimiter Wait a few minutes for logs to get stored in ES 3. Check on ES: oc exec logging-es-<some_characters> -- curl -s -k --cert /etc/elasticsearch/secret/admin-cert --key /etc/elasticsearch/secret/admin-key https://logging-es:9200/.operations.*/_search\?q=message:$uuid|python -mjson.tool Actual results: "systemd": { "u": { "SYSLOG_IDENTIFIER": "EFK" } Expected results: note trailing colon after "EFK": "systemd": { "u": { "SYSLOG_IDENTIFIER": "EFK:" } Additional info: This is the top part of the response with ip addresses masked out: { "_shards": { "failed": 0, "successful": 11, "total": 11 }, "hits": { "hits": [ { "_id": "AVitP5g1Y3Ya11aMWwVG", "_index": ".operations.2016.11.28", "_score": 28.127335, "_source": { "@timestamp": "2016-11-28T18:22:55-05:00", "hostname": "ip-X-X-X-X", "message": ": 7999021a-fedd-4626-9ac5-a92ad0e514f1", "pipeline_metadata": { "collector": { "inputname": "fluent-plugin-in_tail", "ipaddr4": "X.X.X.X", "ipaddr6": "XXXX::XXXX:XXXX:XXXX:XXXX", "name": "fluentd openshift", "received_at": "2016-11-28T18:22:55-05:00", "version": "0.12.29 1.4.0" } }, "systemd": { "u": { "SYSLOG_IDENTIFIER": "EFK" } } }, "_type": "com.redhat.viaq.common" }
Note: it works as expected in the latest upstream version. $ logger -i -p local6.info -t 'EFK:' test-message $ journalctl |egrep EFK Jul 14 19:55:22 ip-172-18-14-14.ec2.internal EFK:[21643]: test-message snippet of search result: "@timestamp": "2017-07-14T23:55:22.870298+00:00", "hostname": "ip-172-18-14-14.ec2.internal", "level": "info", "message": "test-message", "pipeline_metadata": { "collector": { "inputname": "fluent-plugin-systemd", -- }, "u": { "SYSLOG_FACILITY": "22", "SYSLOG_IDENTIFIER": "EFK:", "SYSLOG_PID": "21643" }
@nhosoi Thanks!