Bug 1400631 - Trailing colon from syslog message truncated when stored in ES systemd.u.SYSLOG_IDENTIFIER field
Summary: Trailing colon from syslog message truncated when stored in ES systemd.u.SYSL...
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: OpenShift Container Platform
Classification: Red Hat
Component: Logging
Version: 3.4.0
Hardware: Unspecified
OS: Linux
low
low
Target Milestone: ---
: ---
Assignee: Peter Portante
QA Contact: Xia Zhao
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2016-12-01 16:36 UTC by Walid A.
Modified: 2017-07-15 00:06 UTC (History)
5 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2017-07-15 00:06:59 UTC
Target Upstream Version:


Attachments (Terms of Use)

Description Walid A. 2016-12-01 16:36:19 UTC
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"
            }

Comment 1 Noriko Hosoi 2017-07-15 00:02:37 UTC
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"
         }

Comment 2 Rich Megginson 2017-07-15 00:06:59 UTC
@nhosoi Thanks!


Note You need to log in before you can comment on or make changes to this bug.