From e9bdcbffcd8bd81a0ae7172d3686481bff750219 Mon Sep 17 00:00:00 2001 From: Jonathan Bernard Date: Sat, 2 Mar 2019 02:04:51 -0600 Subject: [PATCH] WIP Logging service and API. --- api/Makefile | 7 +- .../main/nim/personal_measure_apipkg/api.nim | 39 ++++++++++- .../main/nim/personal_measure_apipkg/db.nim | 4 +- .../nim/personal_measure_apipkg/db_common.nim | 16 ++--- .../nim/personal_measure_apipkg/db_util.nim | 35 ++++++++-- .../nim/personal_measure_apipkg/models.nim | 22 ++++--- .../20190227225053-logging-down.sql | 2 + .../migrations/20190227225053-logging-up.sql | 12 ++++ web/src/main.ts | 7 +- web/src/services/logging/api-appender.ts | 65 ++++++++++++++++++ web/src/services/logging/console-appender.ts | 30 +++++++++ web/src/services/logging/index.ts | 5 ++ web/src/services/logging/log-appender.ts | 5 ++ web/src/services/logging/log-message.ts | 11 ++++ web/src/services/logging/log-service.ts | 33 ++++++++++ web/src/services/logging/logger.ts | 66 +++++++++++++++++++ 16 files changed, 331 insertions(+), 28 deletions(-) create mode 100644 api/src/main/sql/migrations/20190227225053-logging-down.sql create mode 100644 api/src/main/sql/migrations/20190227225053-logging-up.sql create mode 100644 web/src/services/logging/api-appender.ts create mode 100644 web/src/services/logging/console-appender.ts create mode 100644 web/src/services/logging/index.ts create mode 100644 web/src/services/logging/log-appender.ts create mode 100644 web/src/services/logging/log-message.ts create mode 100644 web/src/services/logging/log-service.ts create mode 100644 web/src/services/logging/logger.ts diff --git a/api/Makefile b/api/Makefile index a8c49b7..0d53ba9 100644 --- a/api/Makefile +++ b/api/Makefile @@ -1,7 +1,9 @@ PGSQL_CONTAINER_ID=`cat postgres.container.id` DB_NAME="personal_measure" +SOURCES=$(wildcard src/main/nim/*.nim) $(wildcard src/main/nim/personal_measure_apipkg/*.nim) -start-db: start-postgres +serve: personal_measure_api start-postgres + ./personal_measure_api serve postgres.container.id: docker run --name postgres-$(DB_NAME) -e POSTGRES_PASSWORD=password -p 5500:5432 -d postgres > postgres.container.id @@ -24,3 +26,6 @@ delete-postgres-container: connect: PGPASSWORD=password psql -p 5500 -U postgres -h localhost ${DB_NAME} + +personal_measure_api: $(SOURCES) + nimble build diff --git a/api/src/main/nim/personal_measure_apipkg/api.nim b/api/src/main/nim/personal_measure_apipkg/api.nim index 8489639..f59f3a3 100644 --- a/api/src/main/nim/personal_measure_apipkg/api.nim +++ b/api/src/main/nim/personal_measure_apipkg/api.nim @@ -153,7 +153,9 @@ proc makeAuthToken*(ctx: PMApiContext, email, pwd: string): string = let users = ctx.db.findUsersByEmail(email) if users.len != 1: raiseEx "" user = users[0] - except: raiseEx AuthError, "invalid username or password" + except: + error "unable to find user", getCurrentExceptionMsg() + raiseEx AuthError, "invalid username or password" if not validatePwd(user, pwd): raiseEx AuthError, "invalid username or password" @@ -510,6 +512,41 @@ proc start*(ctx: PMApiContext): void = error "unable to delete measurement:\n\t" & getCurrentExceptionMsg() jsonResp(Http500) + post "/log": + checkAuth() + + try: + let jsonBody = parseJson(request.body) + let logEntry = ClientLogEntry( + userId: session.user.id, + level: jsonBody.getOrFail("level").getStr, + message: jsonBody.getOrFail("message").getStr, + scope: jsonBody.getOrFail("scope").getStr, + stacktrace: jsonBody.getIfExists("stacktrace").getStr(""), + timestamp: jsonBody.getOrFail("timestampe").getStr.parseIso8601 + ) + resp(Http200, $(%ctx.db.createClientLogEntry(logEntry)), JSON) + except BadRequestError: jsonResp(Http400, getCurrentExceptionMsg()) + except: jsonResp(Http500, getCurrentExceptionMsg()) + + post "/log/batch": + checkAuth() + + try: + let jsonBody = parseJson(request.body); + let respMsgs = jsonBody.getElems.mapIt( + ClientLogEntry( + userId: session.user.id, + level: it.getOrFail("level").getStr, + message: it.getOrFail("message").getStr, + scope: it.getOrFail("scope").getStr, + stacktrace: it.getIfExists("stacktrace").getStr(""), + timestamp: it.getOrFail("timestampe").getStr.parseIso8601 + )) + resp(Http200, $(%respMsgs), JSON) + except BadRequestError: jsonResp(Http400, getCurrentExceptionMsg()) + except: jsonResp(Http500, getCurrentExceptionMsg()) + post "/service/debug/stop": if not ctx.cfg.debug: jsonResp(Http404) else: diff --git a/api/src/main/nim/personal_measure_apipkg/db.nim b/api/src/main/nim/personal_measure_apipkg/db.nim index d69a423..cd29b18 100644 --- a/api/src/main/nim/personal_measure_apipkg/db.nim +++ b/api/src/main/nim/personal_measure_apipkg/db.nim @@ -14,7 +14,7 @@ type proc connect*(connString: string): PMApiDb = result = PMApiDb(conn: open("", "", "", connString)) -generateProcsForModels([User, ApiToken, Measure, Measurement]) +generateProcsForModels([User, ApiToken, Measure, Measurement, ClientLogEntry]) generateLookup(User, @["email"]) @@ -27,3 +27,5 @@ generateLookup(Measure, @["userId", "slug"]) generateLookup(Measurement, @["measureId"]) generateLookup(Measurement, @["measureId", "id"]) + +generateLookup(ClientLogEntry, @["userId"]) diff --git a/api/src/main/nim/personal_measure_apipkg/db_common.nim b/api/src/main/nim/personal_measure_apipkg/db_common.nim index 3854974..08e8f40 100644 --- a/api/src/main/nim/personal_measure_apipkg/db_common.nim +++ b/api/src/main/nim/personal_measure_apipkg/db_common.nim @@ -18,14 +18,13 @@ proc createRecord*[T](db: DbConn, rec: T): T = # Confusingly, getRow allows inserts and updates. We use it to get back the ID # we want from the row. - let newIdStr = db.getValue(sql( + let newRow = db.getRow(sql( "INSERT INTO " & tableName(rec) & " (" & mc.columns.join(",") & ") " & " VALUES (" & mc.placeholders.join(",") & ") " & - " RETURNING id"), mc.values) + " RETURNING *"), mc.values) - result = rec - result.id = parseUUID(newIdStr) + result = rowToModel(T, newRow) proc updateRecord*[T](db: DbConn, rec: T): bool = var mc = newMutateClauses() @@ -39,13 +38,13 @@ proc updateRecord*[T](db: DbConn, rec: T): bool = return numRowsUpdated > 0; -template deleteRecord*(db: DbConn, modelType: type, id: UUID): untyped = +template deleteRecord*(db: DbConn, modelType: type, id: typed): untyped = db.tryExec(sql("DELETE FROM " & tableName(modelType) & " WHERE id = ?"), $id) proc deleteRecord*[T](db: DbConn, rec: T): bool = return db.tryExec(sql("DELETE FROM " & tableName(rec) & " WHERE id = ?"), $rec.id) -template getRecord*(db: DbConn, modelType: type, id: UUID): untyped = +template getRecord*(db: DbConn, modelType: type, id: typed): untyped = let row = db.getRow(sql( "SELECT " & columnNamesForModel(modelType).join(",") & " FROM " & tableName(modelType) & @@ -88,15 +87,16 @@ macro generateProcsForModels*(modelTypes: openarray[type]): untyped = let createName = ident("create" & modelName) let updateName = ident("update" & modelName) let deleteName = ident("delete" & modelName) + let idType = typeOfColumn(t, "id") result.add quote do: - proc `getName`*(db: PMApiDb, id: UUID): `t` = getRecord(db.conn, `t`, id) + proc `getName`*(db: PMApiDb, id: `idType`): `t` = getRecord(db.conn, `t`, id) proc `getAllName`*(db: PMApiDb): seq[`t`] = getAllRecords(db.conn, `t`) proc `findWhereName`*(db: PMApiDb, whereClause: string, values: varargs[string, dbFormat]): seq[`t`] = return findRecordsWhere(db.conn, `t`, whereClause, values) proc `createName`*(db: PMApiDb, rec: `t`): `t` = createRecord(db.conn, rec) proc `updateName`*(db: PMApiDb, rec: `t`): bool = updateRecord(db.conn, rec) proc `deleteName`*(db: PMApiDb, rec: `t`): bool = deleteRecord(db.conn, rec) - proc `deleteName`*(db: PMApiDb, id: UUID): bool = deleteRecord(db.conn, `t`, id) + proc `deleteName`*(db: PMApiDb, id: `idType`): bool = deleteRecord(db.conn, `t`, id) macro generateLookup*(modelType: type, fields: seq[string]): untyped = let fieldNames = fields[1].mapIt($it) diff --git a/api/src/main/nim/personal_measure_apipkg/db_util.nim b/api/src/main/nim/personal_measure_apipkg/db_util.nim index 01822fa..8ef9b18 100644 --- a/api/src/main/nim/personal_measure_apipkg/db_util.nim +++ b/api/src/main/nim/personal_measure_apipkg/db_util.nim @@ -10,6 +10,13 @@ type placeholders*: seq[string] values*: seq[string] +# TODO: more complete implementation +# see https://github.com/blakeembrey/pluralize +proc pluralize(name: string): string = + if name[^2..^1] == "ey": return name[0..^3] & "ies" + if name[^1] == 'y': return name[0..^2] & "ies" + return name & "s" + macro modelName*(model: object): string = return $model.getTypeInst @@ -38,10 +45,10 @@ proc dbNameToIdent*(name: string): string = return @[parts[0]].concat(parts[1..^1].mapIt(capitalize(it))).join("") proc tableName*(modelType: type): string = - return modelName(modelType).identNameToDb & "s" + return pluralize(modelName(modelType).identNameToDb) proc tableName*[T](rec: T): string = - return modelName(rec).identNameToDb & "s" + return pluralize(modelName(rec).identNameToDb) proc dbFormat*(s: string): string = return s @@ -131,8 +138,7 @@ proc createParseStmt*(t, value: NimNode): NimNode = if `value`.len == 0: none[`innerType`]() else: some(`parseStmt`) - else: - error "Unknown value object type: " & $t.getTypeInst + else: error "Unknown value object type: " & $t.getTypeInst elif t.typeKind == ntyRef: @@ -211,6 +217,24 @@ macro listFields*(t: typed): untyped = result = newLit(fields) +proc typeOfColumn*(modelType: NimNode, colName: string): NimNode = + modelType.walkFieldDefs: + if $fieldIdent != colName: continue + + if fieldType.typeKind == ntyObject: + + if fieldType.getType == UUID.getType: return ident("UUID") + elif fieldType.getType == DateTime.getType: return ident("DateTime") + elif fieldType.getType == Option.getType: return ident("Option") + else: error "Unknown column type: " & $fieldType.getTypeInst + + else: return fieldType + + raise newException(Exception, + "model of type '" & $modelType & "' has no column named '" & colName & "'") + +proc isZero(val: int): bool = return val == 0 + macro populateMutateClauses*(t: typed, newRecord: bool, mc: var MutateClauses): untyped = result = newStmtList() @@ -249,6 +273,3 @@ macro populateMutateClauses*(t: typed, newRecord: bool, mc: var MutateClauses): `mc`.columns.add(identNameToDb(`fieldName`)) `mc`.placeholders.add("?") `mc`.values.add(dbFormat(`t`.`fieldIdent`)) - - #echo result.repr - diff --git a/api/src/main/nim/personal_measure_apipkg/models.nim b/api/src/main/nim/personal_measure_apipkg/models.nim index 8a31771..139b505 100644 --- a/api/src/main/nim/personal_measure_apipkg/models.nim +++ b/api/src/main/nim/personal_measure_apipkg/models.nim @@ -35,6 +35,15 @@ type timestamp*: DateTime extData*: JsonNode + ClientLogEntry* = object + id*: int + userId*: UUID + level*: string + message*: string + scope*: string + stacktrace*: string + timestamp*: DateTime + proc `$`*(u: User): string = return "User " & ($u.id)[0..6] & " - " & u.displayName & " <" & u.email & ">" @@ -49,6 +58,10 @@ proc `$`*(m: Measure): string = proc `$`*(v: Measurement): string = return "Measurement " & ($v.id)[0..6] & " - " & ($v.measureId)[0..6] & " = " & $v.value +proc `%`*(uuid: UUID): JsonNode = %($uuid) + +proc `%`*(dt: DateTime): JsonNode = %(dt.formatIso8601) + proc `%`*(u: User): JsonNode = result = %*{ "id": $u.id, @@ -81,12 +94,3 @@ proc `%`*(m: Measure): JsonNode = if m.domainSource.isSome: result["domainSource"] = %(m.domainSource.get) if m.rangeSource.isSome: result["rangeSource"] = %(m.rangeSource.get) - -proc `%`*(v: Measurement): JsonNode = - result = %*{ - "id": $v.id, - "measureId": $v.measureId, - "value": v.value, - "timestamp": v.timestamp.formatIso8601, - "extData": v.extData - } diff --git a/api/src/main/sql/migrations/20190227225053-logging-down.sql b/api/src/main/sql/migrations/20190227225053-logging-down.sql new file mode 100644 index 0000000..1efa8b8 --- /dev/null +++ b/api/src/main/sql/migrations/20190227225053-logging-down.sql @@ -0,0 +1,2 @@ +-- DOWN script for logging (20190227225053) +drop table client_log_entries; diff --git a/api/src/main/sql/migrations/20190227225053-logging-up.sql b/api/src/main/sql/migrations/20190227225053-logging-up.sql new file mode 100644 index 0000000..7860984 --- /dev/null +++ b/api/src/main/sql/migrations/20190227225053-logging-up.sql @@ -0,0 +1,12 @@ +-- UP script for logging (20190227225053) +create table client_log_entries ( + id serial primary key, + user_id uuid not null references users (id), + "level" varchar not null, + "scope" varchar not null, + message varchar not null, + stacktrace varchar not null, + "timestamp" timestamp with time zone not null default current_timestamp +); + +create index client_log_entries_by_level on client_log_entries ("level"); diff --git a/web/src/main.ts b/web/src/main.ts index efa5004..ffbe476 100644 --- a/web/src/main.ts +++ b/web/src/main.ts @@ -3,11 +3,16 @@ import App from './App.vue'; import router from './router'; import store from './store'; import './registerServiceWorker'; +import { LogService, LogLevel, ApiAppender, ConsoleAppender } from './services/logging'; import { FontAwesomeIcon } from '@fortawesome/vue-fontawesome'; Vue.component('fa-icon', FontAwesomeIcon); -Vue.config.productionTip = false; +LogService.getRootLogger().appenders.push( + // TODO: prod/dev config settings for logging? + new ConsoleAppender(LogLevel.DEBUG), + new ApiAppender(process.env.VUE_APP_PM_API_BASE + '/log/batch', '', LogLevel.WARN) +); new Vue({ router, diff --git a/web/src/services/logging/api-appender.ts b/web/src/services/logging/api-appender.ts new file mode 100644 index 0000000..53ab4fd --- /dev/null +++ b/web/src/services/logging/api-appender.ts @@ -0,0 +1,65 @@ +import Axios from 'axios'; + +import { LogMessage, LogLevel } from './log-message'; +import Logger from './logger'; +import LogAppender from './log-appender'; + +interface ApiMessage { + level: string; + message: string; + scope: string; + stacktrace: string; + timestamp: string; +} +export class ApiAppender implements LogAppender { + public batchSize = 10; + public minimumTimePassedInSec = 60; + public maximumTimePassedInSec = 120; + + private http = Axios.create(); + private msgBuffer: ApiMessage[] = []; + private lastSent = 0; + + constructor(public readonly apiEndpoint: string, public authToken: string, public threshold?: LogLevel) { + setInterval(this.checkPost, 1000); + } + + public appendMessage(logger: Logger, msg: LogMessage): void { + if (this.threshold && msg.level < this.threshold) { return; } + + this.msgBuffer.push({ + level: LogLevel[msg.level], + message: msg.message, + scope: logger.name, + stacktrace: msg.stacktrace, + timestamp: msg.timestamp.toISOString() + }); + } + + private checkPost = () => { + const now = Date.now(); + const min = this.lastSent + (this.minimumTimePassedInSec * 1000); + const max = this.lastSent + (this.maximumTimePassedInSec * 1000); + + if ( (this.msgBuffer.length >= this.batchSize && min < now) || + (this.msgBuffer.length > 0 && max < now) ) { + this.doPost(); + } + setInterval(this.checkPost, Math.max(10000, this.minimumTimePassedInSec * 1000)); + } + + private doPost() { + if (this.msgBuffer.length === 0) { return; } + + this.http.post(this.apiEndpoint, this.msgBuffer, + { headers: { + 'Content-Type': 'application/json', + 'Authorization': `Bearer ${this.authToken}` + }}); + + this.lastSent = Date.now(); + this.msgBuffer = []; + } +} + +export default ApiAppender; diff --git a/web/src/services/logging/console-appender.ts b/web/src/services/logging/console-appender.ts new file mode 100644 index 0000000..0dbabff --- /dev/null +++ b/web/src/services/logging/console-appender.ts @@ -0,0 +1,30 @@ +/*tslint:disable:no-console*/ +import { LogMessage, LogLevel} from './log-message'; +import Logger from './logger'; +import LogAppender from './log-appender'; + +export class ConsoleAppender implements LogAppender { + constructor(public threshold?: LogLevel) {} + + public appendMessage(logger: Logger, msg: LogMessage): void { + if (this.threshold && msg.level < this.threshold) { return; } + + let logMethod = console.log; + switch (msg.level) { + case LogLevel.ALL: logMethod = console.trace; break; + case LogLevel.DEBUG: logMethod = console.debug; break; + case LogLevel.INFO: logMethod = console.info; break; + case LogLevel.WARN: logMethod = console.warn; break; + case LogLevel.ERROR: + case LogLevel.FATAL: logMethod = console.trace; break; + } + + if (msg.error) { + logMethod(logger.name, msg.message, msg.error); + } else { + logMethod(logger.name, msg.message, msg.stacktrace); + } + } +} + +export default ConsoleAppender; diff --git a/web/src/services/logging/index.ts b/web/src/services/logging/index.ts new file mode 100644 index 0000000..e961f8c --- /dev/null +++ b/web/src/services/logging/index.ts @@ -0,0 +1,5 @@ +export * from './log-message'; +export * from './log-appender'; +export * from './log-service'; +export * from './console-appender'; +export * from './api-appender'; diff --git a/web/src/services/logging/log-appender.ts b/web/src/services/logging/log-appender.ts new file mode 100644 index 0000000..c3310d8 --- /dev/null +++ b/web/src/services/logging/log-appender.ts @@ -0,0 +1,5 @@ +import { LogLevel, LogMessage } from './log-message'; +import Logger from './logger'; +export default interface LogAppender { + appendMessage(logger: Logger, message: LogMessage): void; +} diff --git a/web/src/services/logging/log-message.ts b/web/src/services/logging/log-message.ts new file mode 100644 index 0000000..fefd46b --- /dev/null +++ b/web/src/services/logging/log-message.ts @@ -0,0 +1,11 @@ +export enum LogLevel { ALL = 0, DEBUG, INFO, WARN, ERROR, FATAL } + +export interface LogMessage { + level: LogLevel; + message: string; + stacktrace: string; + error?: Error; + timestamp: Date; +} + +export default LogMessage; diff --git a/web/src/services/logging/log-service.ts b/web/src/services/logging/log-service.ts new file mode 100644 index 0000000..531769e --- /dev/null +++ b/web/src/services/logging/log-service.ts @@ -0,0 +1,33 @@ +import { LogLevel } from './log-message'; +import Logger from './logger'; +import { default as Axios, AxiosInstance } from 'axios'; + +/* tslint:disable:max-classes-per-file*/ +export class LogService { + + public static getRootLogger(): Logger { return Logger.ROOT_LOGGER; } + + private loggers: { [key: string]: Logger } = { }; + private http: AxiosInstance = Axios.create(); + + public getLogger(name: string, threshold?: LogLevel): Logger { + if (this.loggers.hasOwnProperty(name)) { return this.loggers[name]; } + + let parentLogger: Logger; + + const parentLoggerName = Object.keys(this.loggers) + .filter((n: string) => name.startsWith(n)) + .reduce((acc: string, cur: string) => acc.length > cur.length ? acc : cur); + + if (parentLoggerName) { + parentLogger = this.loggers[parentLoggerName]; + } else { + parentLogger = Logger.ROOT_LOGGER; + } + + this.loggers[name] = parentLogger.createChildLogger(name, threshold); + return this.loggers[name]; + } +} + +export default new LogService(); diff --git a/web/src/services/logging/logger.ts b/web/src/services/logging/logger.ts new file mode 100644 index 0000000..06e99aa --- /dev/null +++ b/web/src/services/logging/logger.ts @@ -0,0 +1,66 @@ +import { LogMessage, LogLevel } from './log-message'; +import LogAppender from './log-appender'; + +export default class Logger { + + public static readonly ROOT_LOGGER = new Logger('ROOT', undefined, LogLevel.ALL); + + public appenders: LogAppender[] = []; + + protected constructor(public readonly name: string, private parentLogger?: Logger, public threshold?: LogLevel) { } + + public createChildLogger(name: string, threshold?: LogLevel): Logger { + return new Logger(name, this, threshold); + } + + public log(level: LogLevel, message: (Error | string), stacktrace?: string): void { + + if (level < this.getEffectiveThreshold()) { return; } + + const logMsg: LogMessage = { level, message: '', stacktrace: '', timestamp: new Date() }; + + if (typeof message === 'string') { + logMsg.message = message; + logMsg.stacktrace = stacktrace == null ? '' : stacktrace; + } else { + logMsg.error = message; + logMsg.message = `${message.name}: ${message.message}`; + logMsg.stacktrace = message.stack == null ? '' : message.stack; + } + + this.appenders.forEach((app) => { + app.appendMessage(this, logMsg); + }); + } + + public debug(message: (Error | string), stacktrace?: string): void { + this.log(LogLevel.DEBUG, message, stacktrace); + } + + public info(message: string, stacktrace?: string): void { + this.log(LogLevel.INFO, message, stacktrace); + } + + public warn(message: string, stacktrace?: string): void { + this.log(LogLevel.WARN, message, stacktrace); + } + + public error(message: string, stacktrace?: string): void { + this.log(LogLevel.ERROR, message, stacktrace); + } + + public fatal(message: string, stacktrace?: string): void { + this.log(LogLevel.FATAL, message, stacktrace); + } + + protected getEffectiveThreshold(): LogLevel { + if (this.threshold) { return this.threshold; } + if (this.parentLogger) { return this.parentLogger.getEffectiveThreshold(); } + + // should never happen (root logger should always have a threshold + return LogLevel.ALL; + } + +} + +