WIP Logging service and API.

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

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:

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"])

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)

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
-

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
-  }

api/src/main/sql/migrations/20190227225053-logging-down.sql

@@ -0,0 +1,2 @@
+-- DOWN script for logging (20190227225053)
+drop table client_log_entries;

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");

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,

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;

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;

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';

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;
+}

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;

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();

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;
+  }
+
+}
+
+