From 7606fd9725eb37e4546d9c1bd9325866b757dbd9 Mon Sep 17 00:00:00 2001 From: Agniva De Sarker Date: Thu, 8 Dec 2022 21:25:00 +0530 Subject: [PATCH] MM-48651: Log error while queuing telemetry (#21821) We didn't use to handle the error returned from the Enqueue method. We fix that. Additionally, we add a verbosity flag that can allow us to look into verbose logs from the rudder client. This can help us to debug issues regarding telemetry not being sent. https://mattermost.atlassian.net/browse/MM-48651 ```release-note NONE ``` --- app/server.go | 2 +- model/config.go | 5 +++ services/telemetry/telemetry.go | 57 +++++++++++++++------------- services/telemetry/telemetry_test.go | 8 ++-- 4 files changed, 41 insertions(+), 31 deletions(-) diff --git a/app/server.go b/app/server.go index 80b252caff..d39e66705c 100644 --- a/app/server.go +++ b/app/server.go @@ -369,7 +369,7 @@ func NewServer(options ...Option) (*Server, error) { }) s.htmlTemplateWatcher = htmlTemplateWatcher - s.telemetryService = telemetry.New(New(ServerConnector(s.Channels())), s.Store(), s.platform.SearchEngine, s.Log()) + s.telemetryService = telemetry.New(New(ServerConnector(s.Channels())), s.Store(), s.platform.SearchEngine, s.Log(), *s.Config().LogSettings.VerboseDiagnostics) s.platform.SetTelemetryId(s.TelemetryId()) // TODO: move this into platform once telemetry service moved to platform. emailService, err := email.NewService(email.ServiceConfig{ diff --git a/model/config.go b/model/config.go index dd0ad5cfd3..7b9913e976 100644 --- a/model/config.go +++ b/model/config.go @@ -1235,6 +1235,7 @@ type LogSettings struct { FileLocation *string `access:"environment_logging,write_restrictable,cloud_restrictable"` EnableWebhookDebugging *bool `access:"environment_logging,write_restrictable,cloud_restrictable"` EnableDiagnostics *bool `access:"environment_logging,write_restrictable,cloud_restrictable"` // telemetry: none + VerboseDiagnostics *bool `access:"environment_logging,write_restrictable,cloud_restrictable"` // telemetry: none EnableSentry *bool `access:"environment_logging,write_restrictable,cloud_restrictable"` // telemetry: none AdvancedLoggingConfig *string `access:"environment_logging,write_restrictable,cloud_restrictable"` } @@ -1278,6 +1279,10 @@ func (s *LogSettings) SetDefaults() { s.EnableDiagnostics = NewBool(true) } + if s.VerboseDiagnostics == nil { + s.VerboseDiagnostics = NewBool(false) + } + if s.EnableSentry == nil { s.EnableSentry = NewBool(*s.EnableDiagnostics) } diff --git a/services/telemetry/telemetry.go b/services/telemetry/telemetry.go index ce9eb79419..9db3a36d00 100644 --- a/services/telemetry/telemetry.go +++ b/services/telemetry/telemetry.go @@ -101,6 +101,7 @@ type TelemetryService struct { rudderClient rudder.Client TelemetryID string timestampLastTelemetrySent time.Time + verbose bool } type RudderConfig struct { @@ -108,12 +109,13 @@ type RudderConfig struct { DataplaneURL string } -func New(srv ServerIface, dbStore store.Store, searchEngine *searchengine.Broker, log *mlog.Logger) *TelemetryService { +func New(srv ServerIface, dbStore store.Store, searchEngine *searchengine.Broker, log *mlog.Logger, verbose bool) *TelemetryService { service := &TelemetryService{ srv: srv, dbStore: dbStore, searchEngine: searchEngine, log: log, + verbose: verbose, } service.ensureTelemetryID() return service @@ -128,7 +130,7 @@ func (ts *TelemetryService) ensureTelemetryID() { systemID := &model.System{Name: model.SystemTelemetryId, Value: id} systemID, err := ts.dbStore.System().InsertIfExists(systemID) if err != nil { - mlog.Error("unable to get the telemetry ID", mlog.Err(err)) + ts.log.Error("unable to get the telemetry ID", mlog.Err(err)) return } @@ -173,12 +175,15 @@ func (ts *TelemetryService) SendTelemetry(event string, properties map[string]an if installationId := os.Getenv("MM_CLOUD_INSTALLATION_ID"); installationId != "" { context = &rudder.Context{Traits: map[string]any{"installationId": installationId}} } - ts.rudderClient.Enqueue(rudder.Track{ + err := ts.rudderClient.Enqueue(rudder.Track{ Event: event, UserId: ts.TelemetryID, Properties: properties, Context: context, }) + if err != nil { + ts.log.Warn("Error sending telemetry", mlog.Err(err)) + } } } @@ -1145,62 +1150,62 @@ func (ts *TelemetryService) trackElasticsearch() { func (ts *TelemetryService) trackGroups() { groupCount, err := ts.dbStore.Group().GroupCount() if err != nil { - mlog.Debug("Could not get group_count", mlog.Err(err)) + ts.log.Debug("Could not get group_count", mlog.Err(err)) } ldapGroupCount, err := ts.dbStore.Group().GroupCountBySource(model.GroupSourceLdap) if err != nil { - mlog.Debug("Could not get group_count", mlog.Err(err)) + ts.log.Debug("Could not get group_count", mlog.Err(err)) } customGroupCount, err := ts.dbStore.Group().GroupCountBySource(model.GroupSourceCustom) if err != nil { - mlog.Debug("Could not get group_count", mlog.Err(err)) + ts.log.Debug("Could not get group_count", mlog.Err(err)) } groupTeamCount, err := ts.dbStore.Group().GroupTeamCount() if err != nil { - mlog.Debug("Could not get group_team_count", mlog.Err(err)) + ts.log.Debug("Could not get group_team_count", mlog.Err(err)) } groupChannelCount, err := ts.dbStore.Group().GroupChannelCount() if err != nil { - mlog.Debug("Could not get group_channel_count", mlog.Err(err)) + ts.log.Debug("Could not get group_channel_count", mlog.Err(err)) } groupSyncedTeamCount, nErr := ts.dbStore.Team().GroupSyncedTeamCount() if nErr != nil { - mlog.Debug("Could not get group_synced_team_count", mlog.Err(nErr)) + ts.log.Debug("Could not get group_synced_team_count", mlog.Err(nErr)) } groupSyncedChannelCount, nErr := ts.dbStore.Channel().GroupSyncedChannelCount() if nErr != nil { - mlog.Debug("Could not get group_synced_channel_count", mlog.Err(nErr)) + ts.log.Debug("Could not get group_synced_channel_count", mlog.Err(nErr)) } groupMemberCount, err := ts.dbStore.Group().GroupMemberCount() if err != nil { - mlog.Debug("Could not get group_member_count", mlog.Err(err)) + ts.log.Debug("Could not get group_member_count", mlog.Err(err)) } distinctGroupMemberCount, err := ts.dbStore.Group().DistinctGroupMemberCount() if err != nil { - mlog.Debug("Could not get distinct_group_member_count", mlog.Err(err)) + ts.log.Debug("Could not get distinct_group_member_count", mlog.Err(err)) } distinctCustomGroupMemberCount, err := ts.dbStore.Group().DistinctGroupMemberCountForSource(model.GroupSourceCustom) if err != nil { - mlog.Debug("Could not get distinct_custom_group_member_count", mlog.Err(err)) + ts.log.Debug("Could not get distinct_custom_group_member_count", mlog.Err(err)) } distinctLdapGroupMemberCount, err := ts.dbStore.Group().DistinctGroupMemberCountForSource(model.GroupSourceLdap) if err != nil { - mlog.Debug("Could not get distinct_ldap_group_member_count", mlog.Err(err)) + ts.log.Debug("Could not get distinct_ldap_group_member_count", mlog.Err(err)) } groupCountWithAllowReference, err := ts.dbStore.Group().GroupCountWithAllowReference() if err != nil { - mlog.Debug("Could not get group_count_with_allow_reference", mlog.Err(err)) + ts.log.Debug("Could not get group_count_with_allow_reference", mlog.Err(err)) } ts.SendTelemetry(TrackGroups, map[string]any{ @@ -1222,44 +1227,44 @@ func (ts *TelemetryService) trackGroups() { func (ts *TelemetryService) trackChannelModeration() { channelSchemeCount, err := ts.dbStore.Scheme().CountByScope(model.SchemeScopeChannel) if err != nil { - mlog.Debug("Could not get channel_scheme_count", mlog.Err(err)) + ts.log.Debug("Could not get channel_scheme_count", mlog.Err(err)) } createPostUser, err := ts.dbStore.Scheme().CountWithoutPermission(model.SchemeScopeChannel, model.PermissionCreatePost.Id, model.RoleScopeChannel, model.RoleTypeUser) if err != nil { - mlog.Debug("Could not get create_post_user_disabled_count", mlog.Err(err)) + ts.log.Debug("Could not get create_post_user_disabled_count", mlog.Err(err)) } createPostGuest, err := ts.dbStore.Scheme().CountWithoutPermission(model.SchemeScopeChannel, model.PermissionCreatePost.Id, model.RoleScopeChannel, model.RoleTypeGuest) if err != nil { - mlog.Debug("Could not get create_post_guest_disabled_count", mlog.Err(err)) + ts.log.Debug("Could not get create_post_guest_disabled_count", mlog.Err(err)) } // only need to track one of 'add_reaction' or 'remove_reaction` because they're both toggled together by the channel moderation feature postReactionsUser, err := ts.dbStore.Scheme().CountWithoutPermission(model.SchemeScopeChannel, model.PermissionAddReaction.Id, model.RoleScopeChannel, model.RoleTypeUser) if err != nil { - mlog.Debug("Could not get post_reactions_user_disabled_count", mlog.Err(err)) + ts.log.Debug("Could not get post_reactions_user_disabled_count", mlog.Err(err)) } postReactionsGuest, err := ts.dbStore.Scheme().CountWithoutPermission(model.SchemeScopeChannel, model.PermissionAddReaction.Id, model.RoleScopeChannel, model.RoleTypeGuest) if err != nil { - mlog.Debug("Could not get post_reactions_guest_disabled_count", mlog.Err(err)) + ts.log.Debug("Could not get post_reactions_guest_disabled_count", mlog.Err(err)) } // only need to track one of 'manage_public_channel_members' or 'manage_private_channel_members` because they're both toggled together by the channel moderation feature manageMembersUser, err := ts.dbStore.Scheme().CountWithoutPermission(model.SchemeScopeChannel, model.PermissionManagePublicChannelMembers.Id, model.RoleScopeChannel, model.RoleTypeUser) if err != nil { - mlog.Debug("Could not get manage_members_user_disabled_count", mlog.Err(err)) + ts.log.Debug("Could not get manage_members_user_disabled_count", mlog.Err(err)) } useChannelMentionsUser, err := ts.dbStore.Scheme().CountWithoutPermission(model.SchemeScopeChannel, model.PermissionUseChannelMentions.Id, model.RoleScopeChannel, model.RoleTypeUser) if err != nil { - mlog.Debug("Could not get use_channel_mentions_user_disabled_count", mlog.Err(err)) + ts.log.Debug("Could not get use_channel_mentions_user_disabled_count", mlog.Err(err)) } useChannelMentionsGuest, err := ts.dbStore.Scheme().CountWithoutPermission(model.SchemeScopeChannel, model.PermissionUseChannelMentions.Id, model.RoleScopeChannel, model.RoleTypeGuest) if err != nil { - mlog.Debug("Could not get use_channel_mentions_guest_disabled_count", mlog.Err(err)) + ts.log.Debug("Could not get use_channel_mentions_guest_disabled_count", mlog.Err(err)) } ts.SendTelemetry(TrackChannelModeration, map[string]any{ @@ -1283,14 +1288,14 @@ func (ts *TelemetryService) initRudder(endpoint string, rudderKey string) { config := rudder.Config{} config.Logger = rudder.StdLogger(ts.log.With(mlog.String("source", "rudder")).StdLogger(mlog.LvlDebug)) config.Endpoint = endpoint + config.Verbose = ts.verbose // For testing if endpoint != RudderDataplaneURL { - config.Verbose = true config.BatchSize = 1 } client, err := rudder.NewWithConfig(rudderKey, endpoint, config) if err != nil { - mlog.Error("Failed to create Rudder instance", mlog.Err(err)) + ts.log.Error("Failed to create Rudder instance", mlog.Err(err)) return } client.Enqueue(rudder.Identify{ @@ -1416,7 +1421,7 @@ func (ts *TelemetryService) trackPluginConfig(cfg *model.Config, marketplaceURL pluginsEnvironment := ts.srv.GetPluginsEnvironment() if pluginsEnvironment != nil { if plugins, appErr := pluginsEnvironment.Available(); appErr != nil { - mlog.Warn("Unable to add plugin versions to telemetry", mlog.Err(appErr)) + ts.log.Warn("Unable to add plugin versions to telemetry", mlog.Err(appErr)) } else { // If marketplace request failed, use predefined list if marketplacePlugins == nil { diff --git a/services/telemetry/telemetry_test.go b/services/telemetry/telemetry_test.go index 32a86602a3..389cea5f37 100644 --- a/services/telemetry/telemetry_test.go +++ b/services/telemetry/telemetry_test.go @@ -118,7 +118,7 @@ func makeTelemetryServiceAndReceiver(t *testing.T, cloudLicense bool) (*Telemetr pchan <- p })) - service := New(serverIfaceMock, storeMock, searchengine.NewBroker(cfg), testLogger) + service := New(serverIfaceMock, storeMock, searchengine.NewBroker(cfg), testLogger, false) service.TelemetryID = testTelemetryID service.rudderClient = nil service.initRudder(receiver.URL, RudderKey) @@ -295,7 +295,7 @@ func TestEnsureTelemetryID(t *testing.T) { testLogger, _ := mlog.NewLogger() - telemetryService := New(serverIfaceMock, storeMock, searchengine.NewBroker(cfg), testLogger) + telemetryService := New(serverIfaceMock, storeMock, searchengine.NewBroker(cfg), testLogger, false) assert.Equal(t, "test", telemetryService.TelemetryID) telemetryService.ensureTelemetryID() @@ -328,7 +328,7 @@ func TestEnsureTelemetryID(t *testing.T) { testLogger, _ := mlog.NewLogger() - telemetryService := New(serverIfaceMock, storeMock, searchengine.NewBroker(cfg), testLogger) + telemetryService := New(serverIfaceMock, storeMock, searchengine.NewBroker(cfg), testLogger, false) assert.Equal(t, generatedID, telemetryService.TelemetryID) }) @@ -348,7 +348,7 @@ func TestEnsureTelemetryID(t *testing.T) { testLogger, _ := mlog.NewLogger() - telemetryService := New(serverIfaceMock, storeMock, searchengine.NewBroker(cfg), testLogger) + telemetryService := New(serverIfaceMock, storeMock, searchengine.NewBroker(cfg), testLogger, false) assert.Equal(t, "", telemetryService.TelemetryID) }) }