LOG-372 - rsyslog - support improved undefined field handling

- Refactoring undefined_field.go and adding undefined_field_test.go by Rich Megginson <[email protected]>.
- Adding the undefined field related env vars including USE_MMEXTERNAL and SKIP_EMPTY to rsyslog/README.md.
- Adding multi-container support to the rsyslog logs utility.
- Ingoring SIGPIPE in wait_for_journal_apps_ops_msg and wait_for_ops_log_message in hack/testing/util.sh.
- Adding undefined_field test cases to zzz-rsyslog.sh with updating test-viaq-data-model.py and viaq-data-model.sh.
  Setting kubernetes to CDM_KEEP_EMPTY_FIELDS to keep "openshift_io/node-selector": "" in
  kubernetes.namespace_annotations.openshift_io/node-selector.
  Note: If the type of the undefined field's value has changed (e.g., nested json to json string or vice versa),
        the field name should be updated.

Bug fixes:
-  Bug 1730207 - Too many "No Action Needed for xxxxxxxxx" logs in rsyslog pod.
   The undefined_field mmexternal program should be quiet if undefined_debug is not set

- Bug 1733011 - Inappropriate message when view rsyslog pod logs by `oc exec $rsyslog-pod
  -- logs` after setting `LOGGING_FILE_PATH=console`

hack/testing/test-viaq-data-model.py

@@ -41,7 +41,8 @@ def empty(thing):
                   "undefined23": False
               },
               "undefined4": "undefined4",
-              "undefined5": "undefined5"
+              "undefined5": "undefined5",
+              "undefined.6": "undefined6"
     },
     "test2": {"undefined":
               {"undefined1": "undefined1",
@@ -53,7 +54,8 @@ def empty(thing):
                    "undefined23": False
                },
                "undefined4": "undefined4",
-               "undefined5": "undefined5"
+               "undefined5": "undefined5",
+               "undefined.6": "undefined6"
               }
     },
     "test3": {"undefined":
@@ -64,7 +66,8 @@ def empty(thing):
                    "undefined2": "undefined2",
                    "undefined22": 2222,
                    "undefined23": False
-               }
+               },
+               "undefined.6": "undefined6"
               },
               "undefined4": "undefined4",
               "undefined5": "undefined5"
@@ -77,7 +80,8 @@ def empty(thing):
                    "undefined2": "undefined2",
                    "undefined22": 2222,
                    "undefined23": False
-               }
+               },
+               "undefined.6": "undefined6"
               },
               "undefined4": "undefined4",
               "undefined5": "undefined5"
@@ -90,12 +94,36 @@ def empty(thing):
                    "undefined2": "undefined2",
                    "undefined22": 2222,
                    "undefined23": False
-               }
+               },
+               "undefined.6": "undefined6"
+              },
+              "undefined4": "undefined4",
+              "undefined5": "undefined5",
+              "empty1": "",
+              "undefined3": {"emptyvalue": ""}
+    },
+    "test6": {"myname":
+              {"undefined1": "undefined1",
+               "undefined11": 1111,
+               "undefined12": True,
+               "undefined2": {
+                   "undefined2": "undefined2",
+                   "undefined22": 2222,
+                   "undefined23": False
+               },
+               "undefined_6": "undefined6"
               },
               "undefined4": "undefined4",
               "undefined5": "undefined5",
               "empty1": "",
               "undefined3": {"emptyvalue": ""}
+    },
+    "test7": {"undefString":
+              "{\"undefined.6\":\"undefined6\",\"undefined1\":\"undefined1\",\"undefined11\":1111,\"undefined12\":true,\"undefined2\":{\"\":\"\",\"undefined2\":\"undefined2\",\"undefined22\":2222,\"undefined23\":false}}",
+              "undefined4": "undefined4",
+              "undefined5": "undefined5",
+              "empty1": "",
+              "undefined3": {"emptyvalue": ""}
     }
 }
 
@@ -111,7 +139,7 @@ def empty(thing):
         if xx not in dd['_source']:
             print "Error: input does not have the field [%s]" % xx
             sys.exit(1)
-        if not match[xx] == dd['_source'][xx]:
+        if not match[xx] == dd['_source'][xx] and not json.loads(match[xx]) == json.loads(dd['_source'][xx]):
             print "Error: input field [%s] expected value [%s] does not match actual value [%s]" % (xx, match[xx], dd['_source'][xx])
             sys.exit(1)
 

hack/testing/util.sh

@@ -433,6 +433,10 @@ function flush_fluentd_pos_files() {
     os::cmd::expect_success "oal_sudo rm -f /var/log/journal.pos /var/log/journal_pos.json"
 }
 
+function flush_rsyslog_pos_files() {
+    os::cmd::expect_success "oal_sudo rm -f /var/lib/rsyslog.pod/imfile-state* /var/lib/rsyslog.pod/imjournal.state"
+}
+
 # return 0 if given file has size ge given size, otherwise, return 1
 function file_has_size() {
     local f=$1
@@ -457,21 +461,29 @@ function get_journal_pos_cursor() {
 function wait_for_journal_apps_ops_msg() {
     local fullmsg="$1"
     local uuid_es_ops="$2"
+    # ingore pipe failure
+    trap "" PIPE
     oal_sudo journalctl -m -f -o export 2>&1 | \
-        awk -v "es=MESSAGE=.*$fullmsg" -v "es_ops=SYSLOG_IDENTIFIER=$uuid_es_ops" \
-        -v es_out=$ARTIFACT_DIR/es_out.txt -v es_ops_out=$ARTIFACT_DIR/es_ops_out.txt '
+        awk -v "journal=MESSAGE=.*$fullmsg" -v "journal_ops=SYSLOG_IDENTIFIER=$uuid_es_ops" \
+        -v journal_out=$ARTIFACT_DIR/journal_out.txt -v journal_ops_out=$ARTIFACT_DIR/journal_ops_out.txt '
             BEGIN{RS="";FS="\n"};
-            $0 ~ es {print > es_out; app += 1; if (app && op) {exit 0}};
-            $0 ~ es_ops {print > es_ops_out; op += 1; if (app && op) {exit 0}};
+            $0 ~ journal {print > journal_out; app += 1; if (app && op) {exit 0}};
+            $0 ~ journal_ops {print > journal_ops_out; op += 1; if (app && op) {exit 0}};
             '
+    # reset PIPE trap
+    trap - PIPE
 }
 
 function wait_for_ops_log_message() {
     local uuid_es_ops="$1"
+    # ingore pipe failure
+    trap "" PIPE
     oal_sudo journalctl -m -f -o export 2>&1 | \
-        awk -v "es_ops=SYSLOG_IDENTIFIER=$uuid_es_ops" -v es_ops_out=$ARTIFACT_DIR/es_ops_out.txt '
+        awk -v "journal_ops=SYSLOG_IDENTIFIER=$uuid_es_ops" -v journal_ops_out=$ARTIFACT_DIR/journal_ops_out.txt '
             BEGIN{RS="";FS="\n"};
-            $0 ~ es_ops {print > es_ops_out; exit 0}'
+            $0 ~ journal_ops {print > journal_ops_out; exit 0}'
+    # reset PIPE trap
+    trap - PIPE
 }
 
 function wait_for_apps_log_message() {
@@ -755,7 +767,7 @@ get_all_logging_pod_logs() {
            oc exec -n ${LOGGING_NS} -c $container $p -- logs >> $ARTIFACT_DIR/$p.$container.log 2>&1 || :
            ;;
       esac
-	done
+    done
   done
 }
 
@@ -786,6 +798,32 @@ start_fluentd() {
     os::cmd::try_until_text "oc get pods -l component=fluentd" "^(logging-)*fluentd-.* Running " $wait_time
 }
 
+stop_rsyslog() {
+    local rpod=${1:-$( get_running_pod rsyslog )}
+    local wait_time=${2:-$(( 2 * minute ))}
+
+    oc label node -l logging-infra-rsyslog=true --overwrite logging-infra-rsyslog=false
+    os::cmd::try_until_text "oc get $rsyslog_ds -o jsonpath='{ .status.numberReady }'" "0" $wait_time
+    # not sure if it is a bug or a flake, but sometimes .status.numberReady is 0, the rsyslog pod hangs around
+    # in the Terminating state for many seconds, which seems to cause problems with subsequent tests
+    # so, we have to wait for the pod to completely disappear - we cannot rely on .status.numberReady == 0
+    if [ -n "${rpod:-}" ] ; then
+        os::cmd::try_until_failure "oc get pod $rpod > /dev/null 2>&1" $wait_time
+    fi
+}
+
+start_rsyslog() {
+    local cleanfirst=${1:-false}
+    local wait_time=${2:-$(( 2 * minute ))}
+
+    if [ "$cleanfirst" != false ] ; then
+        flush_rsyslog_pos_files
+        oal_sudo rm -f /var/log/rsyslog/* /var/lib/rsyslog.pod/*
+    fi
+    oc label node -l logging-infra-rsyslog=false --overwrite logging-infra-rsyslog=true
+    os::cmd::try_until_text "oc get pods -l component=rsyslog" "^(logging-)*rsyslog-.* Running " $wait_time
+}
+
 get_fluentd_ds_name() {
     if oc -n ${LOGGING_NS} get daemonset fluentd -o name > /dev/null 2>&1 ; then
         echo daemonset/fluentd
@@ -806,6 +844,9 @@ get_fluentd_cm_name() {
 
 fluentd_cm=${fluentd_cm:-$(get_fluentd_cm_name)}
 
+# Hardcode daemonset/rsyslog for the case the rsyslog pod does not exist.
+rsyslog_ds=${rsyslog_ds:-daemonset/rsyslog}
+
 enable_cluster_logging_operator() {
     if oc -n ${LOGGING_NS} get deploy cluster-logging-operator > /dev/null 2>&1 ; then
         oc patch -n ${LOGGING_NS} clusterlogging instance --type=json --patch '[

openshift/ci-operator/build-image/Dockerfile.full

@@ -14,3 +14,4 @@ ADD openshift/ /go/src/github.com/openshift/origin-aggregated-logging/openshift/
 ADD hack/ /go/src/github.com/openshift/origin-aggregated-logging/hack/
 ADD test/ /go/src/github.com/openshift/origin-aggregated-logging/test/
 ADD fluentd/ /go/src/github.com/openshift/origin-aggregated-logging/fluentd/
+ADD rsyslog/ /go/src/github.com/openshift/origin-aggregated-logging/rsyslog/

rsyslog/README.md

@@ -10,6 +10,17 @@ Following are the environment variables that can be modified to adjust the confi
 | `LOGGING_FILE_PATH` | The log file absolute path where Rsyslog is writting its logs. If you want rsyslog to output its logs as Rsyslog does by default (`STDOUT`) set this variable to `console` value. Default value is `/var/log/rsyslog/rsyslog.log`. | `LOGGING_FILE_PATH=console` |
 | `LOGGING_FILE_AGE` | Number of log files that Rsyslog keeps before deleting the oldest file. Default value is `10`. | `LOGGING_FILE_AGE=30` |
 | `LOGGING_FILE_SIZE` | Maximum size of a rsyslog log file in bytes. If the size of the log file is bigger, the log file gets rotated. Default is 1MB | `LOGGING_FILE_SIZE=1024000`
+| `USE_MMEXTERNAL` | Parameter to switch whether mmexternal undefined_field is called or not. default to "false" if CDM parameters are not configured; "true" otherwise.  | `USE_MMEXTERNAL=true`
+| `SKIP_EMPTY` | Parameter to switch whether mmnormalize skip-empty is called or not. default to "true" if CDM parameters are not configured; "false" otherwise. | `SKIP_EMPTY=false`
+| `CDM_USE_UNDEFINED` | Parameter to switch whether undefined fields are moved to the undefined property or not. default to "false". | `CDM_USE_UNDEFINED=true`
+| `CDM_DEFAULT_KEEP_FIELDS` | Default set of fields to be kept in the top level of json.  default to "CEE,time,@timestamp,aushape,ci_job,collectd,docker,fedora-ci,file,foreman,geoip,hostname,ipaddr4,ipaddr6,kubernetes,level,message,namespace_name,namespace_uuid,offset,openstack,ovirt,pid,pipeline_metadata,rsyslog,service,systemd,tags,testcase,tlog,viaq_msg_id",  | -
+| `CDM_EXTRA_KEEP_FIELDS` | Extra set of fields to be kept in the top level of json.  A field not included in ${CDM_DEFAULT_KEEP_FIELDS} nor ${CDM_EXTRA_KEEP_FIELDS} are moved to ${CDM_UNDEFINED_NAME} if CDM_USE_UNDEFINED is "true". default to "" | `CDM_EXTRA_KEEP_FIELDS="broker"` 
+| `CDM_UNDEFINED_NAME` | Undefined property name used when CDM_USE_UNDEFINED is set to "true". default to "undefined". | `CDM_UNDEFINED_NAME="undef"`
+| `CDM_KEEP_EMPTY_FIELDS` | Empty fields are dropped except the fields which names are set to CDM_KEEP_EMPTY_FIELDS in the CSV format. default to "". | `CDM_KEEP_EMPTY_FIELDS="offset"`
+| `CDM_UNDEFINED_TO_STRING` | If set to "true", when CDM_USE_UNDEFINED is "true" and undefined property with ${CDM_UNDEFINED_NAME} is created, the value is converted to the json string. default to "false". | `CDM_UNDEFINED_TO_STRING=true
+| `CDM_UNDEFINED_DOT_REPLACE_CHAR` | A dot character '.' in a property name (key) is replaced with the specified character unless the value is not "UNUSED". default to "UNUSED". Effective when MERGE_JSON_LOG is true. | `CDM_UNDEFINED_DOT_REPLACE_CHAR="_"`
+| `CDM_UNDEFINED_MAX_NUM_FIELDS` | If set to a number greater than -1, and if the number of undefined fields is greater than this number, all of the undefined fields will be converted to their JSON string representation and stored in the undefined_name named field. default to "-1" although not recommended. | `CDM_UNDEFINED_MAX_NUM_FIELDS=2`
+| `UNDEFINED_DEBUG` | Debug flag used in undefined_field as well as the config file calling the plugin.  A debug file /var/log/rsyslog/rsyslog_debug.log is generated.  default to "false". | `UNDEFINED_DEBUG=true`
 
 ## Rsyslog logging to file
 Rsyslog by default writes its logs into a file given by `LOGGING_FILE_PATH` environment variable. You can change the maximum size of a single log file or number of log files to keep(age), by setting `LOGGING_FILE_SIZE` and `LOGGING_FILE_AGE` environment variables accordingly.