Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[Reporting] Remove EventLog Dependency #124762

Merged
merged 18 commits into from
Feb 10, 2022

Conversation

tsullivan
Copy link
Member

@tsullivan tsullivan commented Feb 4, 2022

Summary

Closes #124753
Closes #124649

This PR switches the Reporting Event Log integration to a logging DEBUG messages to the Kibana server logs instead. It preserves the shape of the ECS-compliant objects that previously were stored in the .kibana-event-log-* index pattern, and uses those objects as "meta" data for the core logger. (The LogMeta parameter was introduced to the logger API in this PR: #96350)

Test logs from PDF report:

{"event":{"provider":"reporting","timezone":"UTC"},"kibana":{"reporting":{"actionType":"schedule-task","id":"kzdax98m1dfh0763b50dpjcb","jobType":"printable_pdf_v2"},"task":{"id":"4f294b60-886a-11ec-95ba-4f2318be7631"}},"user":{"name":"elastic"},"ecs":{"version":"8.0.0"},"@timestamp":"2022-02-07T16:04:31.774-07:00","message":"queued report kzdax98m1dfh0763b50dpjcb","log":{"level":"DEBUG","logger":"plugins.reporting.reporting-event-log"},"process":{"pid":64061},"trace":{"id":"0b1a8c35af6bff03a72661d4b787c44c"},"transaction":{"id":"cc160bbcbbc232d4"}}
{"event":{"provider":"reporting","timezone":"UTC"},"kibana":{"reporting":{"actionType":"claim-task","id":"kzdax98m1dfh0763b50dpjcb","jobType":"printable_pdf_v2"}},"user":{"name":"elastic"},"ecs":{"version":"8.0.0"},"@timestamp":"2022-02-07T16:04:35.019-07:00","message":"claimed report kzdax98m1dfh0763b50dpjcb","log":{"level":"DEBUG","logger":"plugins.reporting.reporting-event-log"},"process":{"pid":64061},"span":{"id":"567257107dde4943"},"trace":{"id":"0e0eb5c182990afd7f8f0a8427612cae"}}
{"event":{"provider":"reporting","timezone":"UTC"},"kibana":{"reporting":{"actionType":"execute-start","id":"kzdax98m1dfh0763b50dpjcb","jobType":"printable_pdf_v2"}},"user":{"name":"elastic"},"ecs":{"version":"8.0.0"},"@timestamp":"2022-02-07T16:04:35.020-07:00","message":"starting printable_pdf_v2 execution","log":{"level":"DEBUG","logger":"plugins.reporting.reporting-event-log"},"process":{"pid":64061},"span":{"id":"8c10c05504bbc23e"},"trace":{"id":"0e0eb5c182990afd7f8f0a8427612cae"}}
{"event":{"provider":"reporting","duration":41968,"start":"2022-02-07T23:04:35.020Z","end":"2022-02-07T23:05:16.988Z","timezone":"UTC"},"kibana":{"reporting":{"actionType":"execute-complete","byteSize":916186,"id":"kzdax98m1dfh0763b50dpjcb","jobType":"printable_pdf_v2"}},"user":{"name":"elastic"},"ecs":{"version":"8.0.0"},"@timestamp":"2022-02-07T16:05:16.988-07:00","message":"completed printable_pdf_v2 execution","log":{"level":"DEBUG","logger":"plugins.reporting.reporting-event-log"},"process":{"pid":64061}}
{"event":{"provider":"reporting","timezone":"UTC"},"kibana":{"reporting":{"actionType":"save-report","id":"kzdax98m1dfh0763b50dpjcb","jobType":"printable_pdf_v2"}},"user":{"name":"elastic"},"ecs":{"version":"8.0.0"},"@timestamp":"2022-02-07T16:05:17.046-07:00","message":"saved report kzdax98m1dfh0763b50dpjcb","log":{"level":"DEBUG","logger":"plugins.reporting.reporting-event-log"},"process":{"pid":64061}}

Test logs from CSV download:

{"event":{"provider":"reporting"},"kibana":{"reporting":{"actionType":"execute-start","jobType":"csv_searchsource_immediate"}},"user":{"name":"elastic"},"ecs":{"version":"8.0.0"},"@timestamp":"2022-02-07T16:10:28.915-07:00","message":"starting csv_searchsource_immediate execution","log":{"level":"DEBUG","logger":"plugins.reporting.events"},"process":{"pid":65229},"trace":{"id":"0a37705b73b23894fc61208a46e6b138"},"transaction":{"id":"cc74484f3277b0bc"}}
{"event":{"provider":"reporting","duration":642,"start":"2022-02-07T23:10:28.915Z","end":"2022-02-07T23:10:29.557Z"},"kibana":{"reporting":{"actionType":"execute-complete","byteSize":211581,"jobType":"csv_searchsource_immediate"}},"user":{"name":"elastic"},"ecs":{"version":"8.0.0"},"@timestamp":"2022-02-07T16:10:29.557-07:00","message":"completed csv_searchsource_immediate execution","log":{"level":"DEBUG","logger":"plugins.reporting.events"},"process":{"pid":65229},"trace":{"id":"0a37705b73b23894fc61208a46e6b138"},"transaction":{"id":"cc74484f3277b0bc"}}

Viewing the Reporting logs in that format requires this logging configuration:

logging:
  appenders:
    json-layout:
      type: console
      layout:
        type: json
  root:
    appenders: [json-layout]
  loggers:
    - name: plugins.reporting
      level: debug

Using Filebeat, the metric data can be indexed into Elasticsearch for aggregations / visualizations, which will be the path (for now) for Monitoring of Reporting.

@tsullivan tsullivan added blocker release_note:skip Skip the PR/issue when compiling release notes Team:AppServicesUx v8.1.0 v8.2.0 labels Feb 4, 2022
@tsullivan tsullivan marked this pull request as ready for review February 7, 2022 19:15
@tsullivan tsullivan requested review from a team as code owners February 7, 2022 19:15
@elasticmachine
Copy link
Contributor

Pinging @elastic/kibana-app-services (Team:AppServicesUx)

event: { duration, start: start?.toISOString(), end: end?.toISOString() },
};
const mProperties: Partial<IEvent> = deepMerge(lProperties, timing);
logger.debug(JSON.stringify(deepMerge(mProperties, properties)), ['reporting-event-log']);
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This tag controls how users can filter for the event data. Maybe the tag should be something more future-proof than reporting-event-log

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't think I'd put log in there, but reporting-event seems appropriate ...

}
duration = end && start ? end.valueOf() - start.valueOf() : undefined;
const timing: Partial<IEvent> = {
event: { duration, start: start?.toISOString(), end: end?.toISOString() },
Copy link
Member Author

@tsullivan tsullivan Feb 7, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This should include other fields that can be derived, such as Kibana UUID and maybe @timestamp

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Since this is an 8.1 blocker, the changes should be kept minimal. Extra fields can always be added later, if they're really needed.

@stacey-gammon
Copy link
Contributor

I'll leave the code review to the team, but I am on board with no longer storing reporting data in the event log index and using DEBUG level server logs instead. Thanks Tim!

Copy link
Member

@pmuellr pmuellr left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM; main concern is having us log JSONified strings. I've played a bit with this, with the event log itself, and it's ... not pretty. Especially if you get sent Kibana logs with the JSON layout, as then every quote in the JSONified bit is escaped :-)

event: { duration, start: start?.toISOString(), end: end?.toISOString() },
};
const mProperties: Partial<IEvent> = deepMerge(lProperties, timing);
logger.debug(JSON.stringify(deepMerge(mProperties, properties)), ['reporting-event-log']);
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't think I'd put log in there, but reporting-event seems appropriate ...

event: { duration, start: start?.toISOString(), end: end?.toISOString() },
};
const mProperties: Partial<IEvent> = deepMerge(lProperties, timing);
logger.debug(JSON.stringify(deepMerge(mProperties, properties)), ['reporting-event-log']);
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think we should consider making use the second, optional param to the logger methods, which is basically an ECS record. I suspect the fields in the JSONified string are going to be hard to search for, as long as the JSON layout is used for the Kibana logger, it should write the standard (not custom though) fields out.

That might mean changing the string message parameters on these bit, to make them more useful to humans.

I poked around and found this PR which brought some of the "ECS-ish" bits to the Kibana log, which is about the total of my knowledge on this subject. Not clear to me if this would be more useful than the JSONified string, but guessing it could be, at least in some cases ... #96350

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks so much for this insight, @pmuellr! I followed your advice and updated the debug log entries to log a simple message (rather than stringified JSON), and use the LogMega param: 456079c

}
export function registerEventLogProviderActions(eventLog: IEventLogService) {
eventLog.registerProviderActions(PLUGIN_ID, Object.values(ActionType));
EXECUTE_ERROR = 'execute-error',
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This change is not related to this PR. It's a discovered oversight that should have gone into the first Event Log PR for Reporting.

@tsullivan tsullivan requested a review from a team as a code owner February 8, 2022 03:50
@@ -309,19 +309,6 @@
}
}
},
"reporting": {
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Normally, mappings can never be removed, but in this case this mapping was added and being removed in 8.1 PRs.

@tsullivan tsullivan requested a review from pmuellr February 8, 2022 03:54
Copy link
Member

@pmuellr pmuellr left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The changes (reverts) of the event log LGTM.

I think we should get someone in Core to review - I think the log "meta" param, being ECS-ish, is pretty new, would be good to see someone from Core see it used in practice, in case there's some gotchas. One thing I'm wondering about in particular, is using the kibana object property - perhaps that's something that Kibana itself would want to standardize on, and so maybe reporting instead of kibana would be "safer"? Though I think kibana.reporting would be fine. kibana.user might not be a shape core would want. And actually, looking at that user.name field, there are a bunch of user fields in ECS already. Including top-level user.*, but also client.user.*, server.user.*, source.user.*: see https://www.elastic.co/guide/en/ecs/current/ecs-user.html and https://github.com/elastic/ecs/blob/main/generated/csv/fields.csv

Would also be great to try this out in the Kibana-a-la-cart stuff, so we could try this in cloud, before merging. In case there are some tweaks we'd want for usage in when using viewing logs in cloud.

export function reportingEventLoggerFactory(eventLog: IEventLogService) {
const genericLogger = eventLog.getLogger({ event: { provider: PLUGIN_ID } });
export function reportingEventLoggerFactory(logger: LevelLogger) {
const genericLogger = getEventLog(logger, { event: { provider: PLUGIN_ID } });
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why don't we instantiate that directly? The getEventLog function seems redundant in a way.

Suggested change
const genericLogger = getEventLog(logger, { event: { provider: PLUGIN_ID } });
const genericLogger = new EcsLogAdapter(logger, { event: { provider: PLUGIN_ID } });

Copy link
Contributor

@dokmic dokmic left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM 👍

@tsullivan
Copy link
Member Author

there are a bunch of user fields in ECS already. Including top-level user.*, but also ...

@pmuellr Maybe it was a small oversight, but this PR keeps the user field at the top level of the object:

{
  "event": {
    "provider": "reporting",
    "duration": 642,
    "start": "2022-02-07T23:10:28.915Z",
    "end": "2022-02-07T23:10:29.557Z"
  },
  "kibana": {
    "reporting": {
      "actionType": "execute-complete",
      "byteSize": 211581,
      "jobType": "csv_searchsource_immediate"
    }
  },
  "user": {
    "name": "elastic"
  },
  "ecs": {
    "version": "8.0.0"
  },
  "@timestamp": "2022-02-07T16:10:29.557-07:00",
  "message": "completed csv_searchsource_immediate execution",
  "log": {
    "level": "DEBUG",
    "logger": "plugins.reporting.events"
  },
  "process": {
    "pid": 65229
  },
  "trace": {
    "id": "0a37705b73b23894fc61208a46e6b138"
  },
  "transaction": {
    "id": "cc74484f3277b0bc"
  }
}

I also think it's a good idea to have someone in @elastic/kibana-core review this. Initially, I hoped I could customize event.type but in the LogMeta interface, it looks like that field is not touchable. Instead, I have kibana.reporting.actionType

@tsullivan tsullivan requested a review from a team February 8, 2022 20:30
@@ -5,14 +5,14 @@
* 2.0.
*/

import { LoggerFactory } from 'src/core/server';
import { LoggerFactory, LogMeta } from 'src/core/server';
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This file will be removed, hopefully soon: #125011

@tsullivan
Copy link
Member Author

@elasticmachine merge upstream

Copy link
Member

@lukeelmers lukeelmers left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Initially, I hoped I could customize event.type but in the LogMeta interface, it looks like that field is not touchable. Instead, I have kibana.reporting.actionType

Yeah, this one is not touchable because ECS requires it to be one of a predefined list of values, which is why we enforce it as such in the core typings.

x-pack/plugins/reporting/tsconfig.json Show resolved Hide resolved
x-pack/plugins/reporting/server/lib/event_logger/types.ts Outdated Show resolved Hide resolved
@kibana-ci
Copy link
Collaborator

💚 Build Succeeded

Metrics [docs]

Public APIs missing comments

Total count of every public API that lacks a comment. Target amount is 0. Run node scripts/build_api_docs --plugin [yourplugin] --stats comments for more detailed information.

id before after diff
reporting 30 29 -1
Unknown metric groups

API count

id before after diff
reporting 30 29 -1

History

To update your PR or re-run it, just comment with:
@elasticmachine merge upstream

Copy link
Member

@lukeelmers lukeelmers left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Latest changes LGTM! Thanks for pinging us on this one.

@tsullivan tsullivan merged commit 87eaa75 into elastic:main Feb 10, 2022
@tsullivan tsullivan deleted the reporting/revert/event-logger branch February 10, 2022 03:25
tsullivan added a commit to tsullivan/kibana that referenced this pull request Feb 10, 2022
…124762)

* [Reporting] Remove EventLog Dependency

* calculate duration

* use LogMeta interface of core logger

* fix ts

* rename the debug log tag

* clean up return types for testing

* remove reporting fields from the event log mappings

* unwrap code from iife

* add class for log adapter

* remove useless factory fn

* remove eventLog

* user field was meant to be ECS field

* duration is nanoseconds

* fix nanoseconds application and test

Co-authored-by: Kibana Machine <[email protected]>
(cherry picked from commit 87eaa75)
tsullivan added a commit that referenced this pull request Feb 10, 2022
…#125184)

* [Reporting] Remove EventLog Dependency

* calculate duration

* use LogMeta interface of core logger

* fix ts

* rename the debug log tag

* clean up return types for testing

* remove reporting fields from the event log mappings

* unwrap code from iife

* add class for log adapter

* remove useless factory fn

* remove eventLog

* user field was meant to be ECS field

* duration is nanoseconds

* fix nanoseconds application and test

Co-authored-by: Kibana Machine <[email protected]>
(cherry picked from commit 87eaa75)
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
blocker release_note:skip Skip the PR/issue when compiling release notes v8.1.0 v8.2.0
Projects
None yet
8 participants