Fix and extend logging of light modules load errors (#14706) (#16775)

Two things are solved here:

* Errors were being logged with logp.Error that doesn't actually log
  anything, use a local logger and its Errorf method instead.
* Log errors also when listing modules for string representation.

This was hiding errors, what was specially confusing when permissions
are not correct during development and testing, now errors are logged
if permissions are not correct.

Some errors have been rephrased so logged errors start with uppercase,
and "failed to" is not logged in all nested errors.

(cherry picked from commit 10da237)

CHANGELOG.next.asciidoc

@@ -148,6 +148,7 @@ https://github.com/elastic/beats/compare/v7.0.0-alpha2...master[Check the HEAD d
 - Made `logstash-xpack` module once again have parity with internally-collected Logstash monitoring data. {pull}16198[16198]
 - Change sqs metricset to use average as statistic method. {pull}16438[16438]
 - Revert changes in `docker` module: add size flag to docker.container. {pull}16600[16600]
+- Fix detection and logging of some error cases with light modules. {pull}14706[14706]
 - Add dashboard for `redisenterprise` module. {pull}16752[16752]
 
 *Packetbeat*

metricbeat/mb/lightmodules.go

@@ -39,12 +39,14 @@ const (
 // LightModulesSource loads module definitions from files in the provided paths
 type LightModulesSource struct {
 	paths []string
+	log   *logp.Logger
 }
 
 // NewLightModulesSource creates a new LightModulesSource
 func NewLightModulesSource(paths ...string) *LightModulesSource {
 	return &LightModulesSource{
 		paths: paths,
+		log:   logp.NewLogger("registry.lightmodules"),
 	}
 }
 
@@ -57,7 +59,7 @@ func (s *LightModulesSource) Modules() ([]string, error) {
 func (s *LightModulesSource) HasModule(moduleName string) bool {
 	names, err := s.moduleNames()
 	if err != nil {
-		logp.Error(errors.Wrap(err, "failed to get list of light module names"))
+		s.log.Errorf("Failed to get list of light module names: %v", err)
 		return false
 	}
 	for _, name := range names {
@@ -72,7 +74,7 @@ func (s *LightModulesSource) HasModule(moduleName string) bool {
 func (s *LightModulesSource) DefaultMetricSets(r *Register, moduleName string) ([]string, error) {
 	module, err := s.loadModule(r, moduleName)
 	if err != nil {
-		return nil, errors.Wrapf(err, "failed to get default metricsets for module '%s'", moduleName)
+		return nil, errors.Wrapf(err, "getting default metricsets for module '%s'", moduleName)
 	}
 	var metricsets []string
 	for _, ms := range module.MetricSets {
@@ -87,7 +89,7 @@ func (s *LightModulesSource) DefaultMetricSets(r *Register, moduleName string) (
 func (s *LightModulesSource) MetricSets(r *Register, moduleName string) ([]string, error) {
 	module, err := s.loadModule(r, moduleName)
 	if err != nil {
-		return nil, errors.Wrapf(err, "failed to get metricsets for module '%s'", moduleName)
+		return nil, errors.Wrapf(err, "getting metricsets for module '%s'", moduleName)
 	}
 	metricsets := make([]string, 0, len(module.MetricSets))
 	for _, ms := range module.MetricSets {
@@ -105,7 +107,7 @@ func (s *LightModulesSource) HasMetricSet(moduleName, metricSetName string) bool
 
 	moduleConfig, err := s.loadModuleConfig(modulePath)
 	if err != nil {
-		logp.Error(errors.Wrapf(err, "failed to load module config for module '%s'", moduleName))
+		s.log.Errorf("Failed to load module config for module '%s': %v", moduleName, err)
 		return false
 	}
 
@@ -121,7 +123,7 @@ func (s *LightModulesSource) HasMetricSet(moduleName, metricSetName string) bool
 func (s *LightModulesSource) MetricSetRegistration(register *Register, moduleName, metricSetName string) (MetricSetRegistration, error) {
 	lightModule, err := s.loadModule(register, moduleName)
 	if err != nil {
-		return MetricSetRegistration{}, errors.Wrapf(err, "failed to load module '%s'", moduleName)
+		return MetricSetRegistration{}, errors.Wrapf(err, "loading module '%s'", moduleName)
 	}
 
 	ms, found := lightModule.MetricSets[metricSetName]
@@ -135,9 +137,15 @@ func (s *LightModulesSource) MetricSetRegistration(register *Register, moduleNam
 // ModulesInfo returns a string representation of this source, with a list of known metricsets
 func (s *LightModulesSource) ModulesInfo(r *Register) string {
 	var metricSets []string
-	modules, _ := s.Modules()
+	modules, err := s.Modules()
+	if err != nil {
+		s.log.Errorf("Failed to list modules: %s", err)
+	}
 	for _, module := range modules {
-		moduleMetricSets, _ := s.MetricSets(r, module)
+		moduleMetricSets, err := s.MetricSets(r, module)
+		if err != nil {
+			s.log.Errorf("Failed to list light metricsets for module %s: %v", module, err)
+		}
 		for _, name := range moduleMetricSets {
 			metricSets = append(metricSets, fmt.Sprintf("%s/%s", module, name))
 		}
@@ -155,7 +163,7 @@ type lightModuleConfig struct {
 func (s *LightModulesSource) ProcessorsForMetricSet(r *Register, moduleName string, metricSetName string) (*processors.Processors, error) {
 	module, err := s.loadModule(r, moduleName)
 	if err != nil {
-		return nil, errors.Wrapf(err, "reading processors for metricset '%s' in module '%s' failed", metricSetName, moduleName)
+		return nil, errors.Wrapf(err, "reading processors for metricset '%s' in module '%s'", metricSetName, moduleName)
 	}
 	metricSet, ok := module.MetricSets[metricSetName]
 	if !ok {
@@ -178,12 +186,12 @@ func (s *LightModulesSource) loadModule(register *Register, moduleName string) (
 
 	moduleConfig, err := s.loadModuleConfig(modulePath)
 	if err != nil {
-		return nil, errors.Wrapf(err, "failed to load light module '%s' definition", moduleName)
+		return nil, errors.Wrapf(err, "loading light module '%s' definition", moduleName)
 	}
 
 	metricSets, err := s.loadMetricSets(register, filepath.Dir(modulePath), moduleConfig.Name, moduleConfig.MetricSets)
 	if err != nil {
-		return nil, errors.Wrapf(err, "failed to load metric sets for light module '%s'", moduleName)
+		return nil, errors.Wrapf(err, "loading metric sets for light module '%s'", moduleName)
 	}
 
 	return &LightModule{Name: moduleName, MetricSets: metricSets}, nil
@@ -202,12 +210,12 @@ func (s *LightModulesSource) findModulePath(moduleName string) (string, bool) {
 func (s *LightModulesSource) loadModuleConfig(modulePath string) (*lightModuleConfig, error) {
 	config, err := common.LoadFile(modulePath)
 	if err != nil {
-		return nil, errors.Wrapf(err, "failed to load module configuration from '%s'", modulePath)
+		return nil, errors.Wrapf(err, "loading module configuration from '%s'", modulePath)
 	}
 
 	var moduleConfig lightModuleConfig
 	if err = config.Unpack(&moduleConfig); err != nil {
-		return nil, errors.Wrapf(err, "failed to parse light module definition from '%s'", modulePath)
+		return nil, errors.Wrapf(err, "parsing light module definition from '%s'", modulePath)
 	}
 	return &moduleConfig, nil
 }
@@ -225,7 +233,7 @@ func (s *LightModulesSource) loadMetricSets(register *Register, moduleDirPath, m
 
 		metricSetConfig, err := s.loadMetricSetConfig(manifestPath)
 		if err != nil {
-			return nil, errors.Wrapf(err, "failed to load light metricset '%s'", metricSet)
+			return nil, errors.Wrapf(err, "loading light metricset '%s'", metricSet)
 		}
 		metricSetConfig.Name = metricSet
 		metricSetConfig.Module = moduleName
@@ -238,23 +246,30 @@ func (s *LightModulesSource) loadMetricSets(register *Register, moduleDirPath, m
 func (s *LightModulesSource) loadMetricSetConfig(manifestPath string) (ms LightMetricSet, err error) {
 	config, err := common.LoadFile(manifestPath)
 	if err != nil {
-		return ms, errors.Wrapf(err, "failed to load metricset manifest from '%s'", manifestPath)
+		return ms, errors.Wrapf(err, "loading metricset manifest from '%s'", manifestPath)
 	}
 
 	if err := config.Unpack(&ms); err != nil {
-		return ms, errors.Wrapf(err, "failed to parse metricset manifest from '%s'", manifestPath)
+		return ms, errors.Wrapf(err, "parsing metricset manifest from '%s'", manifestPath)
 	}
 	return
 }
 
 func (s *LightModulesSource) moduleNames() ([]string, error) {
 	modules := make(map[string]bool)
 	for _, dir := range s.paths {
+		if _, err := os.Stat(dir); os.IsNotExist(err) {
+			s.log.Debugf("Light modules directory '%d' doesn't exist", dir)
+			continue
+		}
 		files, err := ioutil.ReadDir(dir)
 		if err != nil {
-			return nil, errors.Wrapf(err, "failed to list modules on path '%s'", dir)
+			return nil, errors.Wrapf(err, "listing modules on path '%s'", dir)
 		}
 		for _, f := range files {
+			if !f.IsDir() {
+				continue
+			}
 			modulePath := filepath.Join(dir, f.Name(), moduleYML)
 			if _, err := os.Stat(modulePath); os.IsNotExist(err) {
 				continue

metricbeat/mb/lightmodules_test.go

@@ -425,6 +425,26 @@ func TestProcessorsForMetricSet_ProcessorsRead(t *testing.T) {
 	require.Len(t, procs.List, 1)
 }
 
+func TestProcessorsForMetricSet_ListModules(t *testing.T) {
+	source := NewLightModulesSource("testdata/lightmodules")
+	modules, err := source.Modules()
+	require.NoError(t, err)
+
+	// Check that regular file in directory is not listed as module
+	require.FileExists(t, "testdata/lightmodules/regular_file")
+	assert.NotContains(t, modules, "regular_file")
+
+	expectedModules := []string{
+		"broken",
+		"httpextended",
+		"mixed",
+		"mixedbroken",
+		"service",
+		"unpack",
+	}
+	assert.ElementsMatch(t, expectedModules, modules, "Modules found: %v", modules)
+}
+
 type metricSetWithOption struct {
 	BaseMetricSet
 	Option string

metricbeat/module/ceph/test_ceph.py

@@ -51,7 +51,7 @@ def test_ceph_mgr(self, metricset):
             return
 
         self.render_config_template(modules=[self.get_ceph_mgr_module_config(metricset)])
-        proc = self.start_beat(home=self.beat_path)
+        proc = self.start_beat()
         self.wait_until(lambda: self.output_lines() > 0)
         proc.check_kill_and_wait()
         self.assert_no_logged_warnings(replace=['SSL/TLS verifications disabled.'])