Bug 1257459

Summary:	[RFE] Add classification information to error logs and a way to process them in an automated fashion.
Product:	Red Hat Enterprise Linux 7	Reporter:	Raul Mahiques <rmahique>
Component:	389-ds-base	Assignee:	mreynolds
Status:	CLOSED ERRATA	QA Contact:	Viktor Ashirov <vashirov>
Severity:	medium	Docs Contact:
Priority:	unspecified
Version:	7.2	CC:	amsharma, enewland, gparente, mreynolds, nkinder, rmahique, rmeggins
Target Milestone:	pre-dev-freeze	Keywords:	FutureFeature
Target Release:	---
Hardware:	All
OS:	All
URL:	http://www.port389.org/docs/389ds/design/errorlog-format-design.html
Whiteboard:
Fixed In Version:	389-ds-base-1.3.6.1-13.el7	Doc Type:	Enhancement
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2017-08-01 21:10:21 UTC	Type:	Bug
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:

Description Raul Mahiques 2015-08-27 06:30:01 UTC

Description of problem:
Without having an understanding of what each error message means it is not clear for the common user to understand how critical the issues described are, also this makes it more difficult and time consuming to create scripts to process error logs for purposes such as monitoring.

It will be good if error logs have a severity level assigned to them such as
syslog(3) error classification scale:

LOG_EMERG system is unusable
LOG_ALERT action must be taken immediately
LOG_CRIT critical conditions
LOG_ERR error conditions
LOG_WARNING warning conditions
LOG_NOTICE normal, but significant, condition
LOG_INFO informational message
LOG_DEBUG debug-level message

and also if they could be identified by an numeric ID such as:
1234 - the service is shutting down.
4321 - the service is starting up

In this way it would be much easier to automate the processing of the logs to better monitor the status of the service.
This ideally would come with an updated documentation so that normal users can find the meaning of the error without much effort.

Version-Release number of selected component (if applicable):
All versions and releases until now.

How reproducible:
Not relevant.

Steps to Reproduce:
1. Look at the errors log (/var/log/dirsrv/... errors

Actual results:
Error logs are shown as sometimes descriptive strings without clear information about the severity and in multiple lines.

Expected results:
Error logs are shown with an ID and a severity level assigned in a single line together with a short descriptive message

Comment 2 Rich Megginson 2015-08-27 13:30:23 UTC

This is to aid migration from Sun/Oracle DS.  We should see what else Sun/Oracle DS logs to see if there is additional information we can add.

There will need to be a doc component for this - whatever we do in the code, we should do it in such a way that we can generate the docs from the code.

The error code registry should also be in the source code, in a format that can be processed with doxygen.

We will need to make sure that we do not break the console which has an error log parser.

Comment 3 Rich Megginson 2015-08-27 13:32:16 UTC

Upstream ticket:
https://fedorahosted.org/389/ticket/48260

Comment 6 Viktor Ashirov 2017-03-22 16:38:11 UTC

*** Bug 1425881 has been marked as a duplicate of this bug. ***

Comment 8 Viktor Ashirov 2017-04-18 14:52:25 UTC

We have log__error_emergency() that outputs CRITICAL
messages. And LOG_CRIT prints with additional CRITICAL prefix.
I think they should be consistent.
ldap/servers/slapd/log.c
2258:            syslog(LOG_CRIT, "CRITICAL: vslapd_log_emergency_error, Unable to determine system time for message :: %s", msg);
2262:            syslog(LOG_CRIT, "CRITICAL: vslapd_log_emergency_error, Unable to format system time for message :: %s", msg);
2270:            syslog(LOG_CRIT, "CRITICAL: vslapd_log_emergency_error, Unable to format system time for message :: %s", msg);
2335:        log__error_emergency("CRITICAL: vslapd_log_error, Unable to format message", 1 , locked);
2343:            PR_snprintf(buffer, sizeof(buffer), "CRITICAL: vslapd_log_error, Unable to determine system time for message :: %s",
vbuf);
2349:            PR_snprintf(buffer, sizeof(buffer), "CRITICAL: vslapd_log_error, Unable to format system time for message :: %s",
vbuf);
2358:            PR_snprintf(buffer, sizeof(buffer), "CRITICAL: vslapd_log_error, Unable to format system time for message :: %s",
vbuf);
2524:        log__error_emergency("CRITICAL: vslapd_log_access, Unable to format message", 1 ,0);
2533:            PR_snprintf(buffer, sizeof(buffer), "CRITICAL: vslapd_log_access, Unable to determine system time for message :: %s",
vbuf);
2540:            PR_snprintf(buffer, sizeof(buffer), "CRITICAL: vslapd_log_access, Unable to format system time for message :: %s",
vbuf);
2549:            PR_snprintf(buffer, sizeof(buffer), "CRITICAL: vslapd_log_access, Unable to format system time for message :: %s",
vbuf);

ldap/servers/plugins/addn/addn.c
99:        slapi_log_err(SLAPI_LOG_ERR, plugin_name, "addn_get_subconfig: CRITICAL: Unable to allocate search_pblock!!!\n");
111:        slapi_log_err(SLAPI_LOG_ERR, plugin_name, "addn_get_subconfig: CRITICAL: Internal search pblock get failed!!!\n");
122:        slapi_log_err(SLAPI_LOG_PLUGIN, plugin_name, "addn_get_subconfig: CRITICAL: Internal search error occured %d \n",
search_result);
130:        slapi_log_err(SLAPI_LOG_ERR, plugin_name, "addn_get_subconfig: CRITICAL: Unable to retrieve number of entries from
pblock!\n");
144:        slapi_log_err(SLAPI_LOG_ERR, plugin_name, "addn_get_subconfig: CRITICAL: Unable to retrieve entries from pblock!\n");
212:        slapi_log_err(SLAPI_LOG_ERR, plugin_name, "addn_prebind: CRITICAL: Unable to retrieve plugin configuration!\n");
270:        slapi_log_err(SLAPI_LOG_ERR, plugin_name, "addn_prebind: CRITICAL: Failed to validate addn_filter %s for domain %s\n",
config_filter, dn_domain_escaped);
284:        slapi_log_err(SLAPI_LOG_ERR, plugin_name, "addn_prebind: CRITICAL: Unable to allocate search_pblock!!!\n");
297:        slapi_log_err(SLAPI_LOG_ERR, plugin_name, "addn_prebind: CRITICAL: Internal search pblock get failed!!!\n");
317:        slapi_log_err(SLAPI_LOG_PLUGIN, plugin_name, "addn_prebind: CRITICAL: Internal search error occured %d \n",
search_result);
326:        slapi_log_err(SLAPI_LOG_ERR, plugin_name, "addn_prebind: CRITICAL: Unable to retrieve number of entries from pblock!\n");
342:        slapi_log_err(SLAPI_LOG_ERR, plugin_name, "addn_prebind: CRITICAL: Unable to retrieve entries from pblock!\n");
359:        slapi_log_err(SLAPI_LOG_ERR, plugin_name, "addn_prebind: CRITICAL: Unable to set new mapped DN to pblock!\n");
407:        slapi_log_err(SLAPI_LOG_ERR, plugin_name, "addn_start: CRITICAL: Failed to retrieve config entry!\n");
419:                "addn_start: CRITICAL: No default domain in configuration, you must set addn_default_domain!\n");

Comment 9 Amita Sharma 2017-05-03 10:49:19 UTC

I also observed this label is not appropriate -

[03/May/2017:06:42:38.315411654 -0400] - ERR - ldbm_instance_post_delete_instance_entry_callback - Removing 'userRoot'.

This came across while testing - https://bugzilla.redhat.com/show_bug.cgi?id=1391204 and doing 

[0 root@qeos-216 export]# ldapdelete -rx -p 52044 -h localhost -D "cn=Directory Manager" -w Secret123 "cn=userRoot,cn=ldbm database,cn=plugins,cn=config"

It is not an error, just a info?

Comment 10 mreynolds 2017-05-03 13:47:46 UTC

(In reply to Amita Sharma from comment #9)
> I also observed this label is not appropriate -
> 
> [03/May/2017:06:42:38.315411654 -0400] - ERR -
> ldbm_instance_post_delete_instance_entry_callback - Removing 'userRoot'.
> 
> This came across while testing -
> https://bugzilla.redhat.com/show_bug.cgi?id=1391204 and doing 
> 
> [0 root@qeos-216 export]# ldapdelete -rx -p 52044 -h localhost -D
> "cn=Directory Manager" -w Secret123 "cn=userRoot,cn=ldbm
> database,cn=plugins,cn=config"
> 
> It is not an error, just a info?

It's an INFO - I'll change it.

Comment 12 Amita Sharma 2017-06-06 10:56:13 UTC

This is fixed
[05/Jun/2017:08:00:51.593279558 -0400] - INFO - ldbm_instance_post_delete_instance_entry_callback - Removing 'userRoot'.

But issue reported by Viktor in comment#8 did not get fixed.

[root@vm-idm-010 addn]# grep -i "critical" *
addn.c:        slapi_log_err(SLAPI_LOG_ERR, plugin_name, "addn_get_subconfig: CRITICAL: Unable to allocate search_pblock!!!\n");
addn.c:        slapi_log_err(SLAPI_LOG_ERR, plugin_name, "addn_get_subconfig: CRITICAL: Internal search pblock get failed!!!\n");
addn.c:        slapi_log_err(SLAPI_LOG_PLUGIN, plugin_name, "addn_get_subconfig: CRITICAL: Internal search error occured %d \n", search_result);
addn.c:        slapi_log_err(SLAPI_LOG_ERR, plugin_name, "addn_get_subconfig: CRITICAL: Unable to retrieve number of entries from pblock!\n");
addn.c:        slapi_log_err(SLAPI_LOG_ERR, plugin_name, "addn_get_subconfig: CRITICAL: Unable to retrieve entries from pblock!\n");
addn.c:        slapi_log_err(SLAPI_LOG_ERR, plugin_name, "addn_prebind: CRITICAL: Unable to retrieve plugin configuration!\n");
addn.c:        slapi_log_err(SLAPI_LOG_ERR, plugin_name, "addn_prebind: CRITICAL: Failed to validate addn_filter %s for domain %s\n", config_filter, dn_domain_escaped);
addn.c:        slapi_log_err(SLAPI_LOG_ERR, plugin_name, "addn_prebind: CRITICAL: Unable to allocate search_pblock!!!\n");
addn.c:        slapi_log_err(SLAPI_LOG_ERR, plugin_name, "addn_prebind: CRITICAL: Internal search pblock get failed!!!\n");
addn.c:        slapi_log_err(SLAPI_LOG_PLUGIN, plugin_name, "addn_prebind: CRITICAL: Internal search error occured %d \n", search_result);
addn.c:        slapi_log_err(SLAPI_LOG_ERR, plugin_name, "addn_prebind: CRITICAL: Unable to retrieve number of entries from pblock!\n");
addn.c:        slapi_log_err(SLAPI_LOG_ERR, plugin_name, "addn_prebind: CRITICAL: Unable to retrieve entries from pblock!\n");
addn.c:        slapi_log_err(SLAPI_LOG_ERR, plugin_name, "addn_prebind: CRITICAL: Unable to set new mapped DN to pblock!\n");
addn.c:        slapi_log_err(SLAPI_LOG_ERR, plugin_name, "addn_start: CRITICAL: Failed to retrieve config entry!\n");
addn.c:                "addn_start: CRITICAL: No default domain in configuration, you must set addn_default_domain!\n");
==============================

log.c:            syslog(LOG_CRIT, "CRITICAL: vslapd_log_emergency_error, Unable to determine system time for message :: %s", msg);
log.c:            syslog(LOG_CRIT, "CRITICAL: vslapd_log_emergency_error, Unable to format system time for message :: %s", msg);
log.c:            syslog(LOG_CRIT, "CRITICAL: vslapd_log_emergency_error, Unable to format system time for message :: %s", msg);

Hence marking as Assigned.

Comment 13 Amita Sharma 2017-06-12 10:37:36 UTC

Basic functionality is working fine.
Issues logged in above comment can be fixed separately. Hence marking this bug as VERIFIED.

Comment 14 errata-xmlrpc 2017-08-01 21:10:21 UTC

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2017:2086