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.

Sign up for GitHub

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

Context building slog sender #10300

Merged
merged 31 commits into from
Oct 29, 2024
Merged

Context building slog sender #10300

Show file tree
Hide file tree
Changes from 3 commits
Commits
Show all changes
31 commits
Select commit Hold shift + click to select a range
2181df1
some cases with logging to file
usmanmani1122 Oct 18, 2024
aba689a
cases handled, remaining persistence and reporting to otel libraries
usmanmani1122 Oct 20, 2024
b285bf3
Merge branch 'master' into usman/context-aware-slogs
usmanmani1122 Oct 21, 2024
36eeddf
persistence
usmanmani1122 Oct 21, 2024
99cbfa7
otel reporting
usmanmani1122 Oct 21, 2024
f258b97
minor final slog changes and incorporate scaling considerations
usmanmani1122 Oct 22, 2024
1d40420
cleanup
usmanmani1122 Oct 22, 2024
175affb
Merge branch 'master' into usman/context-aware-slogs
usmanmani1122 Oct 22, 2024
7d4a9b4
remove unnecessary async usage
usmanmani1122 Oct 22, 2024
696d937
move context data to labels
usmanmani1122 Oct 22, 2024
43fec2d
address mathieu comments
usmanmani1122 Oct 23, 2024
5b432dd
merge master
usmanmani1122 Oct 23, 2024
00bc5e4
yarn
usmanmani1122 Oct 23, 2024
14deff7
remove async usage
usmanmani1122 Oct 23, 2024
638d536
address mathieu comments 2.0
usmanmani1122 Oct 24, 2024
67d577a
local runner script
usmanmani1122 Oct 24, 2024
bc8baa1
remove local runner script
usmanmani1122 Oct 24, 2024
c92efa1
Merge branch 'master' into usman/context-aware-slogs
usmanmani1122 Oct 25, 2024
5f7c7b8
address mathieu comments 3.0 + fix timestamp issue
usmanmani1122 Oct 25, 2024
4cb1b6f
fix timestamp reporting
usmanmani1122 Oct 25, 2024
f5d5722
address mathieu comments 4.0
usmanmani1122 Oct 26, 2024
6b6927f
revert temp file
usmanmani1122 Oct 26, 2024
8eea7b9
Merge branch 'master' into usman/context-aware-slogs
usmanmani1122 Oct 26, 2024
f47d99c
address mathieu comments 4.1
usmanmani1122 Oct 27, 2024
d432dea
Merge branch 'master' into usman/context-aware-slogs
usmanmani1122 Oct 27, 2024
d10fccd
address mathieu comments 4.0
usmanmani1122 Oct 28, 2024
e292196
Merge branch 'master' into usman/context-aware-slogs
usmanmani1122 Oct 28, 2024
301e3bf
Merge branch 'master' into usman/context-aware-slogs
usmanmani1122 Oct 28, 2024
4392faa
address mathien comments 6.0
usmanmani1122 Oct 28, 2024
25723d6
Merge branch 'master' into usman/context-aware-slogs
usmanmani1122 Oct 28, 2024
3ddcc6d
bound methods
usmanmani1122 Oct 28, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
63 changes: 31 additions & 32 deletions packages/telemetry/src/context-aware-slog.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -23,10 +23,8 @@
* } Context
*
* @typedef {{
* 'chain-id': string;
* 'crank.syscallNum'?: Slog['syscallNum'];
* 'process.uptime': Slog['monotime'];
* timestamp: Slog['time'];
* } & Context} LogAttributes
*
* @typedef {{
Expand Down Expand Up @@ -95,12 +93,14 @@ const SLOG_TYPES = {
};

/**
* @param {(log: { attributes: LogAttributes, body: Partial<Slog> }) => void} emitLog
* @param {Partial<{ persistContext: (context: Context) => void; restoreContext: () => Context | null; }>?} persistenceUtils
* @template {Record<string, any>} [T={}]
* @param {T} [staticContext]
* @param {Partial<{ persistContext: (context: Context) => void; restoreContext: () => Context | null; }>} [persistenceUtils]
*/
export const logCreator = (emitLog, persistenceUtils = {}) => {
const { CHAIN_ID } = process.env;

export const makeContextualSlogProcessor = (
staticContext,
persistenceUtils = {},
) => {
/** @type Array<Context | null> */
let [
blockContext,
Expand Down Expand Up @@ -128,6 +128,7 @@ export const logCreator = (emitLog, persistenceUtils = {}) => {

/**
* @param {Slog} slog
* @returns {{ attributes: T & LogAttributes, body: Partial<Slog>; timestamp: Slog['time'] }}
*/
const slogProcessor = ({ monotime, time: timestamp, ...body }) => {
const finalBody = { ...body };
Expand All @@ -151,20 +152,6 @@ export const logCreator = (emitLog, persistenceUtils = {}) => {
};
break;
}
case SLOG_TYPES.COSMIC_SWINGSET.END_BLOCK.START: {
assert(!!blockContext);
break;
}
case SLOG_TYPES.COSMIC_SWINGSET.END_BLOCK.FINISH:
case SLOG_TYPES.COSMIC_SWINGSET.COMMIT.START:
case SLOG_TYPES.COSMIC_SWINGSET.COMMIT.FINISH: {
assert(!!blockContext);
break;
}
case SLOG_TYPES.COSMIC_SWINGSET.AFTER_COMMIT_STATS: {
assert(!!blockContext && !triggerContext);
break;
}
case SLOG_TYPES.COSMIC_SWINGSET.BOOTSTRAP_BLOCK.START: {
mhofman marked this conversation as resolved.
Show resolved Hide resolved
blockContext = {
'block.height': finalBody.blockHeight || 0,
Expand All @@ -178,7 +165,15 @@ export const logCreator = (emitLog, persistenceUtils = {}) => {
};
break;
}
case SLOG_TYPES.COSMIC_SWINGSET.BOOTSTRAP_BLOCK.FINISH: {
case SLOG_TYPES.COSMIC_SWINGSET.END_BLOCK.START: {
assert(!!blockContext);
break;
}
mhofman marked this conversation as resolved.
Show resolved Hide resolved
case SLOG_TYPES.COSMIC_SWINGSET.END_BLOCK.FINISH:
case SLOG_TYPES.COSMIC_SWINGSET.BOOTSTRAP_BLOCK.FINISH:
case SLOG_TYPES.COSMIC_SWINGSET.COMMIT.START:
case SLOG_TYPES.COSMIC_SWINGSET.COMMIT.FINISH:
case SLOG_TYPES.COSMIC_SWINGSET.AFTER_COMMIT_STATS: {
assert(!!blockContext && !triggerContext);
break;
}
Expand Down Expand Up @@ -207,12 +202,14 @@ export const logCreator = (emitLog, persistenceUtils = {}) => {
case SLOG_TYPES.COSMIC_SWINGSET.RUN.START: {
if (!triggerContext && finalBody.runNum !== 0) {
mhofman marked this conversation as resolved.
Show resolved Hide resolved
assert(!!blockContext);
// TBD: add explicit slog events of both timer poll and install bundle
// TODO: add explicit slog events of both timer poll and install bundle
// https://github.com/Agoric/agoric-sdk/issues/10332
triggerContext = {
'run.num': null,
'run.id': `timer-${finalBody.blockHeight}`,
'run.trigger.type': 'timer',
'run.id': `unknown-${finalBody.blockHeight}-${finalBody.runNum}`,
'run.trigger.type': 'unknown',
'run.trigger.time': blockContext['block.time'],
mhofman marked this conversation as resolved.
Show resolved Hide resolved
'run.trigger.blockHeight': finalBody.blockHeight,
};
persistContext(triggerContext);
mhofman marked this conversation as resolved.
Show resolved Hide resolved
}
Expand Down Expand Up @@ -243,15 +240,15 @@ export const logCreator = (emitLog, persistenceUtils = {}) => {
assert(finalBody.replay);
replayContext = {
...replayContext,
'crank.deliveryNum': finalBody.deliveryNum,
'crank.vatID': finalBody.vatID,
'crank.deliveryNum': finalBody.deliveryNum,
};
} else {
assert(!!crankContext && !finalBody.replay);
crankContext = {
...crankContext,
'crank.deliveryNum': finalBody.deliveryNum,
'crank.vatID': finalBody.vatID,
'crank.deliveryNum': finalBody.deliveryNum,
};
}

Expand Down Expand Up @@ -291,21 +288,17 @@ export const logCreator = (emitLog, persistenceUtils = {}) => {
break;
mhofman marked this conversation as resolved.
Show resolved Hide resolved
}

/** @type {LogAttributes} */
usmanmani1122 marked this conversation as resolved.
Show resolved Hide resolved
const logAttributes = {
'chain-id': String(CHAIN_ID),
'process.uptime': monotime,
...initContext, // Optional prelude
...blockContext, // Block is the first level of execution nesting
...triggerContext, // run and trigger info is nested next
...crankContext, // Finally cranks are the last level of nesting
...replayContext, // Replay is a substitute for crank context during vat page in
...eventLogAttributes,
timestamp,
...staticContext,
mhofman marked this conversation as resolved.
Show resolved Hide resolved
};

emitLog({ attributes: logAttributes, body: finalBody });

/**
* Add any after report operations here
* like resetting context data
Expand Down Expand Up @@ -343,6 +336,12 @@ export const logCreator = (emitLog, persistenceUtils = {}) => {
default:
break;
}

return {
attributes: /** @type {T & LogAttributes} */ (logAttributes),
body: finalBody,
timestamp,
};
};
mhofman marked this conversation as resolved.
Show resolved Hide resolved

return slogProcessor;
Expand Down
32 changes: 24 additions & 8 deletions packages/telemetry/src/otel-context-aware-slog.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -7,7 +7,7 @@ import {
SimpleLogRecordProcessor,
} from '@opentelemetry/sdk-logs';
import { readFileSync, writeFileSync } from 'fs';
import { logCreator } from './context-aware-slog.js';
import { makeContextualSlogProcessor } from './context-aware-slog.js';
import { getResourceAttributes } from './index.js';
import { serializeSlogObj } from './serialize-slog-obj.js';

Expand Down Expand Up @@ -54,7 +54,7 @@ export const getContextFilePersistenceUtils = filePath => {
* @param {Options} options
*/
export const makeSlogSender = async options => {
const { OTEL_EXPORTER_OTLP_ENDPOINT } = options.env || {};
const { CHAIN_ID, OTEL_EXPORTER_OTLP_ENDPOINT } = options.env || {};
if (!(OTEL_EXPORTER_OTLP_ENDPOINT && options.stateDir))
return console.warn(
mhofman marked this conversation as resolved.
Show resolved Hide resolved
'Ignoring invocation of slogger "context-aware-slog" without the presence of "OTEL_EXPORTER_OTLP_ENDPOINT" and "stateDir"',
Expand All @@ -77,15 +77,31 @@ export const makeSlogSender = async options => {
`${options.stateDir}/${DEFAULT_CONTEXT_FILE}`,
);

const slogSender = logCreator(
logRecord =>
logger.emit({
...JSON.parse(serializeSlogObj(logRecord)),
severityNumber: SeverityNumber.INFO,
}),
const contextualSlogProcessor = makeContextualSlogProcessor(
{ 'chain-id': CHAIN_ID },
persistenceUtils,
);

/**
* @param {import('./context-aware-slog.js').Slog} slog
*/
const slogSender = slog => {
const { timestamp, ...logRecord } = contextualSlogProcessor(slog);

const [secondsStr, fractionStr] = String(timestamp).split('.');
const seconds = parseInt(secondsStr, 10);
const nanoSeconds = parseInt(
(fractionStr || String(0)).padEnd(9, String(0)),
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 trust numbers, and want to be resilient in case the fractionStr is more than 9 chars already.

In general I prefer string literals where possible

Suggested change
(fractionStr || String(0)).padEnd(9, String(0)),
(fractionStr.substr(0, 9) || '').padEnd(9, '0'),

Copy link
Contributor Author

Choose a reason for hiding this comment

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

According to microtime.nowDouble documentation, it returns microseconds precision so I don't think we should ever get 9 decimal places right?

Copy link
Member

Choose a reason for hiding this comment

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

Precision of the source data doesn't mean anything for the representation as an IEEE 754 number. Those tend to do weird things often enough that I wouldn't bet on there being a max of 9 digits when stringified.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Done

10,
);

return logger.emit({
mhofman marked this conversation as resolved.
Show resolved Hide resolved
...JSON.parse(serializeSlogObj(logRecord)),
severityNumber: SeverityNumber.INFO,
timestamp: [seconds, nanoSeconds],
});
};

return Object.assign(slogSender, {
forceFlush: () => logRecordProcessor.forceFlush(),
shutdown: () =>
Expand Down
Loading