v0.6.14 : Add meta_back_error support

openldap-log-parser.go

@@ -18,7 +18,7 @@ const (
 	// FIXME: Not very strict
 	IPv6RE            = `(?:(?:[0-9a-fA-F]{1,4}\:){7})[0-9a-fA-F]{1,4}`
 	HostRE            = `([0-9A-Za-z\-\_\.]*)`
-	ProcessRE         = `(slapd\[[0-9]{1,5}\])`
+	ProcessRE         = `(slapd\[[0-9]{1,7}\])(?:\:)?`
 	// group[4]
 	ConnIdRE          = `conn=([0-9]{4,10})`
 	ConnFdRE          = `(?:fd=([0-9]{1,10}))?`
@@ -47,10 +47,12 @@ const (
 	AddDnRE           = `(?:ADD dn="(.*)")?`
 	// group[42]
 	DelDnRE           = `(?:DEL dn="(.*)")?`
-	
+	// group[43], 44, 45, 46
+	MetaBackOpErrorRE = `(?:meta_back_search\[([0-9]+)\] match="(.*)" err=([0-9]+) \(Operations error\) text="([^\"]*)")?`
+
 	LogLineRE = SyslogPri + TimeRE + ` ` + HostRE + ` ` + ProcessRE + ` ` + ConnIdRE + ` ` + ConnFdRE + OperationIdRE + ` ` +
 				AcceptRE + STARTTLSRE + BindMethodRE + BindMechRE + ResultRE + SearchBaseRE + SearchAttrRE + SearchResultRE + ModDnRE + ModAttrRE + 
-				PassModRE + UnbindRE + ConnClosedRE + AddDnRE + DelDnRE
+				PassModRE + UnbindRE + ConnClosedRE + AddDnRE + DelDnRE + MetaBackOpErrorRE
 )
 
 type (
@@ -58,7 +60,7 @@ type (
 		LogFormat LogFormat
 		Regexp    *regexp.Regexp
 	}
-	
+
 	LogFormat struct {
 		Time           *time.Time `json:"time"`
 		Hostname       string     `json:"hostname"`
@@ -100,6 +102,10 @@ type (
 		SearchResETime string     `json:"search_res_etime"`
 		SearchResNEntries int     `json:"search_res_nentries"`
 		SearchResText  string     `json:"search_res_text"`
+		ErrorBackend   int        `json:"err_backend"`
+		ErrorMatch     string     `json:"err_match"`
+		ErrorErr       int        `json:"err_error"`
+		ErrorText      string     `json:"err_text"`
 	}
 )
 
@@ -150,7 +156,12 @@ func (o *OpenldapLog) Parse(text []byte) (LogFormat, error) {
 	}
 	serr,_ := strconv.Atoi(string(group[31]))
 	srentries, _ := strconv.Atoi(string(group[34]))
-	
+
+	// 0 even if no error, so don't use this for error testing
+	backend, _ := strconv.Atoi(string(group[43]))
+	// 0 if no error, so use this instead
+	backerr, _ := strconv.Atoi(string(group[45]))
+
 	logFormat := LogFormat{
 		Time:         &t,
 		Hostname:     string(group[2]),
@@ -192,6 +203,10 @@ func (o *OpenldapLog) Parse(text []byte) (LogFormat, error) {
 		PassModDN:         string(group[38]),
 		AddDN:             string(group[41]),
 		DelDN:             string(group[42]),
+		ErrorBackend:      backend,
+		ErrorMatch:        string(group[44]),
+		ErrorErr:          backerr,
+		ErrorText:         string(group[46]),
 	}
 
 	// Now handle Operation Type
@@ -215,6 +230,8 @@ func (o *OpenldapLog) Parse(text []byte) (LogFormat, error) {
 		logFormat.OpType = "add"
 	} else if len(group[42]) > 0 {
 		logFormat.OpType = "del"
+	} else if logFormat.ErrorErr != 0 {
+		logFormat.OpType = "error"
 	}
 
 	return logFormat, nil

openldap-log-parser/cmd/root.go

@@ -64,10 +64,10 @@ type (
 		ResOid         string     `json:"result_oid,omitempty"`
 		// To use "omitempty" on int, they have to be pointers 
 		// This way it willl be displayed when set to 0, and not display when not set (null)
-		ResErr         *int        `json:"result_err,omitempty"`
+		ResErr         *int       `json:"result_err,omitempty"`
 		ResQTime       string     `json:"result_qtime,omitempty"`
 		ResETime       string     `json:"result_etime,omitempty"`
-		ResNEntries    *int        `json:"result_nentries,omitempty"`
+		ResNEntries    *int       `json:"result_nentries,omitempty"`
 		ResText        string     `json:"result_text,omitempty"`
 		SearchBase     string     `json:"search_base,omitempty"`
 		SearchScope    string     `json:"search_scope,omitempty"`
@@ -75,11 +75,15 @@ type (
 		SearchFilter   string     `json:"search_filter,omitempty"`
 		SearchAttr     string     `json:"search_attr,omitempty"`
 		SearchResTag   string     `json:"search_res_tag,omitempty"`
-		SearchResErr   *int        `json:"search_res_err,omitempty"`
+		SearchResErr   *int       `json:"search_res_err,omitempty"`
 		SearchResQTime string     `json:"search_res_qtime,omitempty"`
 		SearchResETime string     `json:"search_res_etime,omitempty"`
-		SearchResNEntries *int     `json:"search_res_nentries,omitempty"`
+		SearchResNEntries *int    `json:"search_res_nentries,omitempty"`
 		SearchResText  string     `json:"search_res_text,omitempty"`
+		ErrorBackend   *int       `json:"err_backend,omitempty"`
+		ErrorMatch     string     `json:"err_match,omitempty"`
+		ErrorErr       *int       `json:"err_error,omitempty"`
+		ErrorText      string     `json:"err_text,omitempty"`
 	}
 
 	OpenLdapConnectionFlat struct {
@@ -122,6 +126,10 @@ type (
 		SearchResETime string     `json:"search_res_etime,omitempty"`
 		SearchResNEntries *int    `json:"search_res_nentries,omitempty"`
 		SearchResText  string     `json:"search_res_text,omitempty"`
+		ErrorBackend   *int       `json:"err_backend,omitempty"`
+		ErrorMatch     string     `json:"err_match,omitempty"`
+		ErrorErr       *int       `json:"err_error,omitempty"`
+		ErrorText      string     `json:"err_text,omitempty"`
 	}
 )
 
@@ -129,7 +137,7 @@ var (
 	File   os.File
 	Writer *bufio.Writer
 
-	Version = "0.6.11"
+	Version = "0.6.14"
 
 	BuildInfo = promauto.NewGaugeVec(prometheus.GaugeOpts{
 		Name: "openldaplogparser_build_info",
@@ -195,6 +203,10 @@ var (
 		Name: "openldaplogparser_starttlscount",
 		Help: "Number of STARTTLS commands executed",
 	}, []string{"host"})
+	ErrorCnt = promauto.NewCounterVec(prometheus.CounterOpts{
+		Name: "openldaplogparser_error_count",
+		Help: "Number of errors",
+	}, []string{"host","type"})
 
 	rootCmd = &cobra.Command{
 		Use:   "openldap-log-parser",
@@ -309,6 +321,11 @@ func OlcToFlat(olc *OpenLdapConnection) []OpenLdapConnectionFlat {
 				olcf[i].ResQTime = olc.Operations[i].ResQTime
 				olcf[i].ResETime = olc.Operations[i].ResETime
 				olcf[i].ResText = olc.Operations[i].ResText
+			case "error":
+				olcf[i].ErrorBackend = olc.Operations[i].ErrorBackend
+				olcf[i].ErrorMatch = olc.Operations[i].ErrorMatch
+				olcf[i].ErrorErr = olc.Operations[i].ErrorErr
+				olcf[i].ErrorText = olc.Operations[i].ErrorText
 		}  
 	}
 
@@ -354,7 +371,8 @@ func cleanMQueue(mqueue map[string]*OpenLdapConnection, mqMtx *sync.Mutex, age t
 
 	log.Printf("Start cleaning queue task: %d items in queue", len(mqueue))
 
-	// Do we need read lock?
+	// We need lock here
+	mqMtx.Lock()
 	for uid, ldcon := range mqueue {
 		ok = false
 		// Check if a close operation exist
@@ -366,11 +384,11 @@ func cleanMQueue(mqueue map[string]*OpenLdapConnection, mqMtx *sync.Mutex, age t
 			}
 		}
 		if ok == true {
-			mqMtx.Lock()
+			// We already in RW lock
 			delete(mqueue, uid)
-			mqMtx.Unlock()
 		}
 	}
+	mqMtx.Unlock()
 	log.Printf("Finished cleaning queue task: %d items in queue", len(mqueue))
 }
 
@@ -909,10 +927,66 @@ func parseStoreAndWrite(input []byte, mq map[string]*OpenLdapConnection, mqMtx *
 				}
 				// Then remove operation from OpenLDAPConnection so it wont output again
 				olc.Operations = olc.Operations[:len(olc.Operations)-1]
-				UnbindCnt.WithLabelValues(olc.Hostname).Inc()
 			}
+			UnbindCnt.WithLabelValues(olc.Hostname).Inc()
 		}
 		mqMtx.Unlock()
+		return nil
+	}
+
+	/* 2022-07-18T09:25:35.224779+02:00 ldap.domain.org slapd[82581] conn=1512 op=2 meta_back_search[0] match="" err=1 (Operations error) text="000004DC: LdapErr: DSID-0C090BA8, comment: In order to perform this operation a successful bind must be completed on the connection., data 0, v3839".*/
+	if logFormat.ErrorErr != 0 {
+		op := &Operation{
+			Time:           logFormat.Time,
+			OpType:         logFormat.OpType,
+			OpId:           &logFormat.OpId,
+			ErrorBackend:   &logFormat.ErrorBackend,
+			ErrorMatch:     logFormat.ErrorMatch,
+			ErrorErr:       &logFormat.ErrorErr,
+			ErrorText:      logFormat.ErrorText,
+		}
+		mqMtx.Lock()
+		// Do this connection exists ?
+		olc, ok := mq[fmt.Sprintf("%s:%d", logFormat.Hostname, logFormat.ConnId)]
+		if false == ok {
+			if false == gDispUnkConn {
+				mqMtx.Unlock()
+				return nil
+			} else {
+				// Create connection
+				olc = &OpenLdapConnection{
+					Time:           logFormat.Time,
+					Hostname:       logFormat.Hostname,
+					Process:        logFormat.Process,
+					ConnId:         logFormat.ConnId,
+					ConnFd:         logFormat.ConnFd,
+					ClientIp:       logFormat.ClientIp,
+					ClientPort:     logFormat.ClientPort,
+					ServerIp:       logFormat.ServerIp,
+					ServerPort:     logFormat.ServerPort,
+				}
+				mq[fmt.Sprintf("%s:%d", logFormat.Hostname, logFormat.ConnId)] = olc
+			}
+		}
+		olc.Operations = append(olc.Operations, op)
+		// Dump to stdout if gFlatten, b/c this is a standalone event
+		if gFlatten == true {
+			jsonBytes, err := json.Marshal(OlcToFlat(olc)[len(olc.Operations)-1])
+			if err != nil {
+				log.Fatal(err)
+			}
+			outfMtx.Lock()
+			err = writeOut(string(jsonBytes), gOutputFile)
+			outfMtx.Unlock()
+			if err != nil {
+				log.Fatal(err)
+			}
+			// Then remove operation from OpenLDAPConnection so it wont output again
+			olc.Operations = olc.Operations[:len(olc.Operations)-1]
+		}
+		mqMtx.Unlock()
+		ErrorCnt.WithLabelValues(olc.Hostname, "meta_back_search").Inc()
+		return nil
 	}
   
 	/*

rsyslog/openldap-log-parser.conf

@@ -0,0 +1,165 @@
+module(load="imfile")       # lecture slapd.log.json
+module(load="mmjsonparse")  # parsing slapd.log.json
+
+# Template de mise en forme JSON
+template(name="sendJsonToGrayLogTemplate"
+    type="list" option.json="on") {
+    constant(value="{ ")
+    constant(value="\"facility\":\"local4\", ")
+    constant(value="\"facility_num\":\"20\", ")
+    constant(value="\"level\":\"6\", ")
+    constant(value="\"type\":\"")
+    property(name="programname")
+    constant(value="\", ")
+    # on renomme les proprietes venant de openldap-log-parser
+    constant(value="\"time\":\"")
+    property(name="$!time")
+    constant(value="\", ")
+    constant(value="\"source\":\"")
+    property(name="$!hostname")
+    constant(value="\", ")
+    constant(value="\"process\":\"")
+    property(name="$!process")
+    constant(value="\", ")
+    constant(value="\"client_ip\":\"")
+    property(name="$!client_ip")
+    constant(value="\", ")
+    constant(value="\"client_port\":\"")
+    property(name="$!client_port")
+    constant(value="\", ")
+    constant(value="\"server_ip\":\"")
+    property(name="$!server_ip")
+    constant(value="\", ")
+    constant(value="\"server_port\":\"")
+    property(name="$!server_port")
+    constant(value="\", ")
+    constant(value="\"bind_dn\":\"")
+    property(name="$!bind_dn")
+    constant(value="\", ")
+    constant(value="\"conn_id\":\"")
+    property(name="$!conn_id")
+    constant(value="\", ")
+    constant(value="\"conn_fd\":\"")
+    property(name="$!conn_fd")
+    constant(value="\", ")
+    constant(value="\"op_id\":\"")
+    property(name="$!op_id")
+    constant(value="\", ")
+    constant(value="\"op_type\":\"")
+    property(name="$!op_type")
+    constant(value="\", ")
+    constant(value="\"bind_method\":\"")
+    property(name="$!bind_method")
+    constant(value="\", ")
+    constant(value="\"bind_mech\":\"")
+    property(name="$!bind_mech")
+    constant(value="\", ")
+    constant(value="\"bind_ssf\":\"")
+    property(name="$!bind_ssf")
+    constant(value="\", ")
+    constant(value="\"ssf\":\"")
+    property(name="$!ssf")
+    constant(value="\", ")
+    constant(value="\"starttls\":\"")
+    property(name="$!starttls")
+    constant(value="\", ")
+    constant(value="\"mod_dn\":\"")
+    property(name="$!mod_dn")
+    constant(value="\", ")
+    constant(value="\"mod_attr\":\"")
+    property(name="$!mod_attr")
+    constant(value="\", ")
+    constant(value="\"add_dn\":\"")
+    property(name="$!add_dn")
+    constant(value="\", ")
+    constant(value="\"del_dn\":\"")
+    property(name="$!del_dn")
+    constant(value="\", ")
+    constant(value="\"passmod_dn\":\"")
+    property(name="$!passmod_dn")
+    constant(value="\", ")
+    constant(value="\"res_tag\":\"")
+    property(name="$!result_tag")
+    constant(value="\", ")
+    constant(value="\"res_oid\":\"")
+    property(name="$!result_oid")
+    constant(value="\", ")
+    constant(value="\"res_err\":\"")
+    property(name="$!result_err")
+    constant(value="\", ")
+    constant(value="\"res_qtime\":\"")
+    property(name="$!result_qtime")
+    constant(value="\", ")
+    constant(value="\"res_etime\":\"")
+    property(name="$!result_etime")
+    constant(value="\", ")
+    constant(value="\"res_text\":\"")
+    property(name="$!result_text")
+    constant(value="\", ")
+    constant(value="\"search_base\":\"")
+    property(name="$!search_base")
+    constant(value="\", ")
+    constant(value="\"search_scope\":\"")
+    property(name="$!search_scope")
+    constant(value="\", ")
+    constant(value="\"search_deref\":\"")
+    property(name="$!search_deref")
+    constant(value="\", ")
+    constant(value="\"search_filter\":\"")
+    property(name="$!search_filter")
+    constant(value="\", ")
+    constant(value="\"search_attr\":\"")
+    property(name="$!search_attr")
+    constant(value="\", ")
+    constant(value="\"search_res_tag\":\"")
+    property(name="$!search_res_tag")
+    constant(value="\", ")
+    constant(value="\"search_res_err\":\"")
+    property(name="$!search_res_err")
+    constant(value="\", ")
+    constant(value="\"search_res_qtime\":\"")
+    property(name="$!search_res_qtime")
+    constant(value="\", ")
+    constant(value="\"search_res_etime\":\"")
+    property(name="$!search_res_etime")
+    constant(value="\", ")
+    constant(value="\"search_res_nentries\":\"")
+    property(name="$!search_res_nentries")
+    constant(value="\", ")
+    constant(value="\"search_res_text\":\"")
+    property(name="$!search_res_text")
+    constant(value="\", ")
+    constant(value="\"message\":\"")
+    property(name="$!message")
+    constant(value="\" ")
+    constant(value=" }")
+}
+
+# On envoit les logs ldap vers openldap-log-parser qui tourne en tant que service
+if $programname == 'slapd' then action(
+    type="omfwd"
+    Target="127.0.0.1"
+    Port="6514"
+    Protocol="tcp"
+    template="RSYSLOG_FileFormat")
+
+# Le flux post openldap-log-parser, qu'on relit pour envoyer vers graylog
+input(type="imfile"
+    File="/var/log/slapd.log.json"
+    Tag="openldap-agg"
+    addMetadata="on"
+    ruleset="remoteAllJsonLog"
+)
+
+ruleset(name="remoteAllJsonLog") {
+    action(type="mmjsonparse" cookie="")
+    action(
+        type="omfwd"
+        Target="graylog.example.org"
+        Port="2514"
+        Protocol="tcp"
+        template="sendJsonToGrayLogTemplate"
+    )
+    stop
+}
+

test/slapd-add.log

@@ -0,0 +1,4 @@
+2022-07-18T09:23:20.160516+02:00 ldap.domain.org slapd[82581] conn=1512 fd=10 ACCEPT from IP=10.11.12.16:64482 (IP=0.0.0.0:389)
+2022-07-18T09:25:35.224767+02:00 ldap.domain.org slapd[82581] conn=1512 op=3 ADD dn="cn=coincoin,dc=domain,dc=org"
+2022-07-18T09:25:35.224843+02:00 ldap.domain.org slapd[82581] conn=1512 op=3 RESULT tag=105 err=0 qtime=0.000008 etime=0.016597 text=
+2022-07-18T09:23:20.226352+02:00 ldap.domain.org slapd[82581] conn=1512 fd=10 closed

test/slapd-del.log

@@ -0,0 +1,4 @@
+2022-07-18T09:23:20.160516+02:00 ldap.domain.org slapd[82581] conn=1513 fd=11 ACCEPT from IP=10.11.12.16:64485(IP=0.0.0.0:389)
+2022-07-18T09:25:35.224767+02:00 ldap.domain.org slapd[82581] conn=1513 op=3 DEL dn="cn=coincoin,dc=domain,dc=org"
+2022-07-18T09:25:35.224843+02:00 ldap.domain.org slapd[82581] conn=1513 op=3 RESULT tag=107 err=0 qtime=0.000008 etime=0.016597 text=
+2022-07-18T09:23:20.226352+02:00 ldap.domain.org slapd[82581] conn=1513 fd=11 closed

test/slapd-op-err.log

@@ -0,0 +1,7 @@
+2022-07-18T09:23:20.160516+02:00 ldap.domain.org slapd[82581] conn=1512 fd=10 ACCEPT from IP=10.11.12.16:64482 (IP=0.0.0.0:389)
+2022-07-18T09:25:35.224767+02:00 ldap.domain.org slapd[82581] conn=1512 op=2 SRCH base="ou=users,dc=domain,dc=org" scope=2 deref=0 filter="(&(objectClass=person)(cn=pika))"
+2022-07-18T09:25:35.224779+02:00 ldap.domain.org slapd[82581] conn=1512 op=2 SRCH attr=objectClass userPrincipalName userAccountControl mail rfc822Mailbox entryUUID uid cn
+2022-07-18T09:25:35.224781+02:00 ldap.domain.org slapd[82581] conn=1512 op=2 meta_back_search[0] match="" err=1 (Operations error) text="000004DC: LdapErr: DSID-0C090BA8, comment: In order to perform this operation a successful bind must be completed on the connection., data 0, v3839".
+2022-07-18T09:25:35.224843+02:00 ldap.domain.org slapd[82581] conn=1512 op=2 SEARCH RESULT tag=101 err=0 nentries=0 text=
+2022-07-18T09:26:20.226352+02:00 ldap.domain.org slapd[82581] conn=1512 fd=10 closed
+