diff --git a/changes/15168-scheduled-outside-fleet b/changes/15168-scheduled-outside-fleet new file mode 100644 index 0000000000..4b469ab252 --- /dev/null +++ b/changes/15168-scheduled-outside-fleet @@ -0,0 +1 @@ +* Fixed logging of results for scheduled queries configured outside of Fleet, when `server_settings.query_reports_disabled` is set to `true`. diff --git a/server/service/osquery.go b/server/service/osquery.go index 08f8ab970d..0d9661e901 100644 --- a/server/service/osquery.go +++ b/server/service/osquery.go @@ -1402,15 +1402,44 @@ func submitLogsEndpoint(ctx context.Context, request interface{}, svc fleet.Serv return submitLogsResponse{Err: err}, nil } -func (svc *Service) preProcessOsqueryResults(ctx context.Context, osqueryResults []json.RawMessage, queryReportsDisabled bool) (unmarshaledResults []*fleet.ScheduledQueryResult, queriesDBData map[string]*fleet.Query) { +// preProcessOsqueryResults will attempt to unmarshal `osqueryResults` and will return: +// - `unmarshaledResults` with each result unmarshaled to `fleet.ScheduledQueryResult`s, where if an item is `nil` it means the corresponding +// `osqueryResults` item could not be unmarshaled. +// - queriesDBData has the corresponding DB query to each unmarshalled result in `osqueryResults`. +// +// If queryReportsDisabled is true then it returns only t he `unmarshaledResults` without querying the DB. +func (svc *Service) preProcessOsqueryResults( + ctx context.Context, + osqueryResults []json.RawMessage, + queryReportsDisabled bool, +) (unmarshaledResults []*fleet.ScheduledQueryResult, queriesDBData map[string]*fleet.Query) { // skipauth: Authorization is currently for user endpoints only. svc.authz.SkipAuthorization(ctx) + lograw := func(raw json.RawMessage) string { + logr := raw + if len(raw) >= 64 { + logr = raw[:64] + } + return string(logr) + } + for _, raw := range osqueryResults { var result *fleet.ScheduledQueryResult if err := json.Unmarshal(raw, &result); err != nil { - level.Error(svc.logger).Log("msg", "unmarshalling result", "err", err) - // Note we store a nil item if the result could not be unmarshaled. + level.Debug(svc.logger).Log("msg", "unmarshalling result", "err", err, "result", lograw(raw)) + // Note that if err != nil we have two scenarios: + // - result == nil: which means the result could not be unmarshalled, e.g. not JSON. + // - result != nil: which means that the result was (partially) unmarshalled but some specific + // field could not be unmarshalled. + // + // In both scenarios we want to add `result` to `unmarshaledResults`. + } else { + // If the unmarshaled result doesn't have a "name" field then we ignore the result. + if result != nil && result.QueryName == "" { + level.Debug(svc.logger).Log("msg", "missing name field", "result", lograw(raw)) + result = nil + } } unmarshaledResults = append(unmarshaledResults, result) } @@ -1427,7 +1456,7 @@ func (svc *Service) preProcessOsqueryResults(ctx context.Context, osqueryResults } teamID, queryName, err := getQueryNameAndTeamIDFromResult(queryResult.QueryName) if err != nil { - level.Error(svc.logger).Log("msg", "querying name and team ID from result", "err", err) + level.Debug(svc.logger).Log("msg", "querying name and team ID from result", "err", err) continue } if _, ok := queriesDBData[queryResult.QueryName]; ok { @@ -1463,6 +1492,9 @@ func (svc *Service) SubmitResultLogs(ctx context.Context, logs []json.RawMessage // otherwise the results will never clear from its local DB and // will keep retrying forever. // + // We do return errors if we fail to write to the external logging destination, + // so that the logs are not lost and osquery retries on its next log interval. + // var queryReportsDisabled bool appConfig, err := svc.ds.AppConfig(ctx) @@ -1486,32 +1518,35 @@ func (svc *Service) SubmitResultLogs(ctx context.Context, logs []json.RawMessage // Ignore results that could not be unmarshaled. continue } + if queryReportsDisabled { - // If query_reports_disabled=true we write the logs - // to the logging destination without any extra processing. + // If query_reports_disabled=true we write the logs to the logging destination without any extra processing. // - // If a query has automations_enabled = 0 we may still write the results for it here. - // Eventually the query will be removed from the host schedule and thus Fleet - // won't receive any further results anymore (/api/v1/osquery/config). + // If a query was recently configured with automations_enabled = 0 we may still write + // the results for it here. Eventually the query will be removed from the host schedule + // and thus Fleet won't receive any further results anymore. filteredLogs = append(filteredLogs, logs[i]) continue } - // - // If query_reports_disabled=false then we need to filter - // the queries that have automations_enabled=false because - // the query might have been scheduled because of discard_data=false. - // - dbQuery, ok := queriesDBData[unmarshaledResult.QueryName] if !ok { - // Ignore results for unknown queries. + // If Fleet doesn't know of the query we write the logs to the logging destination + // without any extra processing. This is to support osquery nodes that load their + // config from elsewhere (e.g. using `--config_plugin=filesystem`). + // + // If a query was configured from Fleet but was recently removed, we may still write + // the results for it here. Eventually the query will be removed from the host schedule + // and thus Fleet won't receive any further results anymore. + filteredLogs = append(filteredLogs, logs[i]) continue } + if !dbQuery.AutomationsEnabled { // Ignore results for queries that have automations disabled. continue } + filteredLogs = append(filteredLogs, logs[i]) } @@ -1646,7 +1681,7 @@ func getQueryNameAndTeamIDFromResult(path string) (*uint, string, error) { if strings.HasPrefix(path, "pack/team-") { parts := strings.SplitN(path, "/", 3) if len(parts) != 3 { - return nil, "", fmt.Errorf("unknown format: %s", path) + return nil, "", fmt.Errorf("unknown format: %q", path) } teamNumberStr := strings.TrimPrefix(parts[1], "team-") @@ -1663,11 +1698,11 @@ func getQueryNameAndTeamIDFromResult(path string) (*uint, string, error) { if strings.HasPrefix(path, "pack/") { parts := strings.SplitN(path, "/", 3) if len(parts) != 3 { - return nil, "", fmt.Errorf("unknown format: %s", path) + return nil, "", fmt.Errorf("unknown format: %q", path) } return nil, parts[2], nil } // If none of the above patterns match, return error - return nil, "", fmt.Errorf("unknown format: %s", path) + return nil, "", fmt.Errorf("unknown format: %q", path) } diff --git a/server/service/osquery_test.go b/server/service/osquery_test.go index 78107ce698..9566721faa 100644 --- a/server/service/osquery_test.go +++ b/server/service/osquery_test.go @@ -7,6 +7,7 @@ import ( "errors" "fmt" "io" + "os" "reflect" "sort" "strconv" @@ -533,7 +534,7 @@ func TestSubmitStatusLogs(t *testing.T) { func TestSubmitResultLogs(t *testing.T) { ds := new(mock.Store) - svc, ctx := newTestService(t, ds, nil, nil) + svc, ctx := newTestService(t, ds, nil, nil, &TestServerOpts{Logger: log.NewJSONLogger(os.Stdout)}) ds.AppConfigFunc = func(ctx context.Context) (*fleet.AppConfig, error) { return &fleet.AppConfig{}, nil @@ -614,60 +615,65 @@ func TestSubmitResultLogs(t *testing.T) { serv.osqueryLogWriter = &OsqueryLogger{Result: testLogger} validLogResults := []string{ - `{"name":"pack/Global/system_info","hostIdentifier":"some_uuid","calendarTime":"Fri Sep 30 17:55:15 2016 UTC","unixTime":"1475258115","decorations":{"host_uuid":"some_uuid","username":"zwass"},"columns":{"cpu_brand":"Intel(R) Core(TM) i7-4770HQ CPU @ 2.20GHz","hostname":"hostimus","physical_memory":"17179869184"},"action":"added"}`, + `{"name":"pack/Global/system_info","hostIdentifier":"some_uuid","calendarTime":"Fri Sep 30 17:55:15 2016 UTC","unixTime":1475258115,"decorations":{"host_uuid":"some_uuid","username":"zwass"},"columns":{"cpu_brand":"Intel(R) Core(TM) i7-4770HQ CPU @ 2.20GHz","hostname":"hostimus","physical_memory":"17179869184"},"action":"added"}`, - `{"name":"pack/SomePack/encrypted","hostIdentifier":"some_uuid","calendarTime":"Fri Sep 30 21:19:15 2016 UTC","unixTime":"1475270355","decorations":{"host_uuid":"4740D59F-699E-5B29-960B-979AAF9BBEEB","username":"zwass"},"columns":{"encrypted":"1","name":"\/dev\/disk1","type":"AES-XTS","uid":"","user_uuid":"","uuid":"some_uuid"},"action":"added"}`, - `{"name":"pack/SomePack/encrypted","hostIdentifier":"some_uuid","calendarTime":"Fri Sep 30 21:19:14 2016 UTC","unixTime":"1475270354","decorations":{"host_uuid":"4740D59F-699E-5B29-960B-979AAF9BBEEB","username":"zwass"},"columns":{"encrypted":"1","name":"\/dev\/disk1","type":"AES-XTS","uid":"","user_uuid":"","uuid":"some_uuid"},"action":"added"}`, + `{"name":"pack/SomePack/encrypted","hostIdentifier":"some_uuid","calendarTime":"Fri Sep 30 21:19:15 2016 UTC","unixTime":1475270355,"decorations":{"host_uuid":"4740D59F-699E-5B29-960B-979AAF9BBEEB","username":"zwass"},"columns":{"encrypted":"1","name":"\/dev\/disk1","type":"AES-XTS","uid":"","user_uuid":"","uuid":"some_uuid"},"action":"added"}`, + `{"name":"pack/SomePack/encrypted","hostIdentifier":"some_uuid","calendarTime":"Fri Sep 30 21:19:14 2016 UTC","unixTime":1475270354,"decorations":{"host_uuid":"4740D59F-699E-5B29-960B-979AAF9BBEEB","username":"zwass"},"columns":{"encrypted":"1","name":"\/dev\/disk1","type":"AES-XTS","uid":"","user_uuid":"","uuid":"some_uuid"},"action":"added"}`, // These results belong to the same query but have 1 second difference. `{"snapshot":[{"hour":"20","minutes":"8"}],"action":"snapshot","name":"pack/Global/time","hostIdentifier":"1379f59d98f4","calendarTime":"Tue Jan 10 20:08:51 2017 UTC","unixTime":1484078931,"decorations":{"host_uuid":"EB714C9D-C1F8-A436-B6DA-3F853C5502EA"}}`, `{"snapshot":[{"hour":"20","minutes":"8"}],"action":"snapshot","name":"pack/Global/time","hostIdentifier":"1379f59d98f4","calendarTime":"Tue Jan 10 20:08:50 2017 UTC","unixTime":1484078930,"decorations":{"host_uuid":"EB714C9D-C1F8-A436-B6DA-3F853C5502EA"}}`, `{"snapshot":[{"hour":"20","minutes":"8"}],"action":"snapshot","name":"pack/Global/time","hostIdentifier":"1379f59d98f4","calendarTime":"Tue Jan 10 20:08:52 2017 UTC","unixTime":1484078932,"decorations":{"host_uuid":"EB714C9D-C1F8-A436-B6DA-3F853C5502EA"}}`, - `{"diffResults":{"removed":[{"address":"127.0.0.1","hostnames":"kl.groob.io"}],"added":""},"name":"pack\/team-1/hosts","hostIdentifier":"FA01680E-98CA-5557-8F59-7716ECFEE964","calendarTime":"Sun Nov 19 00:02:08 2017 UTC","unixTime":"1511049728","epoch":"0","counter":"10","decorations":{"host_uuid":"FA01680E-98CA-5557-8F59-7716ECFEE964","hostname":"kl.groob.io"}}`, + `{"diffResults":{"removed":[{"address":"127.0.0.1","hostnames":"kl.groob.io"}],"added":""},"name":"pack\/team-1/hosts","hostIdentifier":"FA01680E-98CA-5557-8F59-7716ECFEE964","calendarTime":"Sun Nov 19 00:02:08 2017 UTC","unixTime":1511049728,"epoch":"0","counter":"10","decorations":{"host_uuid":"FA01680E-98CA-5557-8F59-7716ECFEE964","hostname":"kl.groob.io"}}`, `{"snapshot":[{"hour":"20","minutes":"8"}],"action":"snapshot","name":"pack/Global/query_should_be_saved_and_submitted","hostIdentifier":"1379f59d98f4","calendarTime":"Tue Jan 10 20:08:51 2017 UTC","unixTime":1484078931,"decorations":{"host_uuid":"EB714C9D-C1F8-A436-B6DA-3F853C5502EA"}}`, - //`{"snapshot":[],"action":"snapshot","name":"pack/Global/query_no_rows","hostIdentifier":"1379f59d98f4","calendarTime":"Tue Jan 10 20:08:51 2017 UTC","unixTime":1484078931,"decorations":{"host_uuid":"EB714C9D-C1F8-A436-B6DA-3F853C5502EA"}}`, + // Fleet doesn't know of this query, so this result should be streamed as is (This is to support streaming results for osquery nodes that are configured outside of Fleet, e.g. `--config_plugin=filesystem`). + `{"snapshot":[{"hour":"20","minutes":"8"}],"action":"snapshot","name":"pack/Global/doesntexist","hostIdentifier":"1379f59d98f4","calendarTime":"Tue Jan 10 20:08:51 2017 UTC","unixTime":1484078931,"decorations":{"host_uuid":"EB714C9D-C1F8-A436-B6DA-3F853C5502EA"}}`, + + // The "name" field has invalid format, so this result will be streamed as is (This is to support streaming results for osquery nodes that are configured outside of Fleet, e.g. `--config_plugin=filesystem`). + `{"snapshot":[{"hour":"20","minutes":"8"}],"action":"snapshot","name":"some_name","hostIdentifier":"1379f59d98f4","calendarTime":"Tue Jan 10 20:08:51 2017 UTC","unixTime":1484078931,"decorations":{"host_uuid":"EB714C9D-C1F8-A436-B6DA-3F853C5502EA"}}`, + `{"snapshot":[{"hour":"20","minutes":"8"}],"action":"snapshot","name":"pack/team-foo/bar","hostIdentifier":"1379f59d98f4","calendarTime":"Tue Jan 10 20:08:51 2017 UTC","unixTime":1484078931,"decorations":{"host_uuid":"EB714C9D-C1F8-A436-B6DA-3F853C5502EA"}}`, + `{"snapshot":[{"hour":"20","minutes":"8"}],"action":"snapshot","name":"pack/team-","hostIdentifier":"1379f59d98f4","calendarTime":"Tue Jan 10 20:08:51 2017 UTC","unixTime":1484078931,"decorations":{"host_uuid":"EB714C9D-C1F8-A436-B6DA-3F853C5502EA"}}`, + `{"snapshot":[{"hour":"20","minutes":"8"}],"action":"snapshot","name":"pack/PackName","hostIdentifier":"1379f59d98f4","calendarTime":"Tue Jan 10 20:08:51 2017 UTC","unixTime":1484078931,"decorations":{"host_uuid":"EB714C9D-C1F8-A436-B6DA-3F853C5502EA"}}`, } logJSON := fmt.Sprintf("[%s]", strings.Join(validLogResults, ",")) resultWithInvalidJSON := []byte("foobar:\n\t123") + resultWithInvalidJSONLong := []byte("foobar:\n\t1233333333333333333333333333333333333333333333333333333333") // The "name" field will be empty, so this result will be ignored. resultWithoutName := []byte(`{"unknown":{"foo": [] }}`) - // The "name" field has invalid format, so this result will be ignored. - resultWithInvalidNameFmt1 := []byte(`{"snapshot":[{"hour":"20","minutes":"8"}],"action":"snapshot","name":"pack/team-foo/bar","hostIdentifier":"1379f59d98f4","calendarTime":"Tue Jan 10 20:08:51 2017 UTC","unixTime":"1484078931","decorations":{"host_uuid":"EB714C9D-C1F8-A436-B6DA-3F853C5502EA"}}`) - resultWithInvalidNameFmt2 := []byte(`{"snapshot":[{"hour":"20","minutes":"8"}],"action":"snapshot","name":"pack/team-","hostIdentifier":"1379f59d98f4","calendarTime":"Tue Jan 10 20:08:51 2017 UTC","unixTime":"1484078931","decorations":{"host_uuid":"EB714C9D-C1F8-A436-B6DA-3F853C5502EA"}}`) - resultWithInvalidNameFmt3 := []byte(`{"snapshot":[{"hour":"20","minutes":"8"}],"action":"snapshot","name":"pack/PackName","hostIdentifier":"1379f59d98f4","calendarTime":"Tue Jan 10 20:08:51 2017 UTC","unixTime":"1484078931","decorations":{"host_uuid":"EB714C9D-C1F8-A436-B6DA-3F853C5502EA"}}`) - // The query doesn't exist, so this result will be ignored. - resultWithQueryDoesNotExist := []byte(`{"snapshot":[{"hour":"20","minutes":"8"}],"action":"snapshot","name":"pack/Global/doesntexist","hostIdentifier":"1379f59d98f4","calendarTime":"Tue Jan 10 20:08:51 2017 UTC","unixTime":"1484078931","decorations":{"host_uuid":"EB714C9D-C1F8-A436-B6DA-3F853C5502EA"}}`) // The query was configured with automations disabled, so this result will be ignored. - resultWithQueryNotAutomated := []byte(`{"snapshot":[{"hour":"20","minutes":"8"}],"action":"snapshot","name":"pack/Global/query_not_automated","hostIdentifier":"1379f59d98f4","calendarTime":"Tue Jan 10 20:08:51 2017 UTC","unixTime":"1484078931","decorations":{"host_uuid":"EB714C9D-C1F8-A436-B6DA-3F853C5502EA"}}`) + resultWithQueryNotAutomated := []byte(`{"snapshot":[{"hour":"20","minutes":"8"}],"action":"snapshot","name":"pack/Global/query_not_automated","hostIdentifier":"1379f59d98f4","calendarTime":"Tue Jan 10 20:08:51 2017 UTC","unixTime":1484078931,"decorations":{"host_uuid":"EB714C9D-C1F8-A436-B6DA-3F853C5502EA"}}`) // The query is supposed to be saved but with automations disabled (and has two columns). resultWithQuerySavedNotAutomated := []byte(`{"snapshot":[{"hour":"20","minutes":"8"},{"hour":"21","minutes":"9"}],"action":"snapshot","name":"pack/Global/query_should_be_saved_but_not_submitted","hostIdentifier":"1379f59d98f4","calendarTime":"Tue Jan 10 20:08:51 2017 UTC","unixTime":1484078931,"decorations":{"host_uuid":"EB714C9D-C1F8-A436-B6DA-3F853C5502EA"}}`) - var results []json.RawMessage - err := json.Unmarshal([]byte(logJSON), &results) + var validResults []json.RawMessage + err := json.Unmarshal([]byte(logJSON), &validResults) require.NoError(t, err) host := fleet.Host{ ID: 999, } ctx = hostctx.NewContext(ctx, &host) - // Submit valid and invalid log results mixed. - err = serv.SubmitResultLogs(ctx, append(append(results[:3], - resultWithInvalidJSON, - resultWithoutName, - resultWithInvalidNameFmt1, - resultWithInvalidNameFmt2, - resultWithInvalidNameFmt3, - resultWithQueryDoesNotExist, - resultWithQueryNotAutomated, - resultWithQuerySavedNotAutomated, - ), results[3:]...)) + + // Submit valid, invalid and to-be-ignored log results mixed. + validAndInvalidResults := make([]json.RawMessage, 0, len(validResults)+5) + for i, result := range validResults { + validAndInvalidResults = append(validAndInvalidResults, result) + if i == 2 { + validAndInvalidResults = append(validAndInvalidResults, + resultWithInvalidJSON, resultWithInvalidJSONLong, + resultWithoutName, resultWithQueryNotAutomated, + resultWithQuerySavedNotAutomated, + ) + } + } + err = serv.SubmitResultLogs(ctx, validAndInvalidResults) require.NoError(t, err) - assert.Equal(t, results, testLogger.logs) + assert.Equal(t, validResults, testLogger.logs) } func TestSaveResultLogsToQueryReports(t *testing.T) {