Add a whole lot more logging to the backend

src/MemoryCache.ts

@@ -1,4 +1,5 @@
 import * as memoryCache from "memory-cache";
+import { LogService } from "matrix-js-snippets";
 
 export class MemoryCache {
 
@@ -30,6 +31,7 @@ class _CacheManager {
     public for(namespace: string): MemoryCache {
         let cache = this.caches[namespace];
         if (!cache) {
+            LogService.info("MemoryCache", "Creating a new cache for namespace: " + namespace);
             cache = this.caches[namespace] = new MemoryCache();
         }
 

src/api/Webserver.ts

@@ -62,7 +62,7 @@ export default class Webserver {
                 parsedUrl.query["scalar_token"] = "redacted";
                 parsedUrl.search = undefined; // to force URL.format to use `query`
             }
-            LogService.verbose("Webserver", "Incoming request: " + req.method + " " + URL.format(parsedUrl));
+            LogService.info("Webserver", "Incoming request: " + req.method + " " + URL.format(parsedUrl));
             next();
         });
         this.app.use((_req, res, next) => {

src/api/admin/AdminAppserviceService.ts

@@ -47,7 +47,7 @@ export class AdminAppserviceService {
     @POST
     @Path("new")
     public async createAppservice(@QueryParam("scalar_token") scalarToken: string, request: AppserviceCreateRequest): Promise<AppserviceResponse> {
-        await AdminService.validateAndGetAdminTokenOwner(scalarToken);
+        const userId = await AdminService.validateAndGetAdminTokenOwner(scalarToken);
 
         // Trim off the @ sign if it's on the prefix
         if (request.userPrefix[0] === "@") {
@@ -60,6 +60,7 @@ export class AdminAppserviceService {
         }
 
         const appservice = await AppserviceStore.create(AppserviceStore.getSafeUserId(request.userPrefix));
+        LogService.info("AdminAppserviceService", userId + " created an application service");
         return this.mapAppservice(appservice);
     }
 

src/api/admin/AdminIntegrationsService.ts

@@ -5,6 +5,7 @@ import { DimensionIntegrationsService } from "../dimension/DimensionIntegrations
 import { WidgetStore } from "../../db/WidgetStore";
 import { Cache, CACHE_INTEGRATIONS } from "../../MemoryCache";
 import { Integration } from "../../integrations/Integration";
+import { LogService } from "matrix-js-snippets";
 
 interface SetEnabledRequest {
     enabled: boolean;
@@ -24,11 +25,12 @@ export class AdminIntegrationsService {
     @POST
     @Path(":category/:type/options")
     public async setOptions(@QueryParam("scalar_token") scalarToken: string, @PathParam("category") category: string, @PathParam("type") type: string, body: SetOptionsRequest): Promise<any> {
-        await AdminService.validateAndGetAdminTokenOwner(scalarToken);
+        const userId = await AdminService.validateAndGetAdminTokenOwner(scalarToken);
 
         if (category === "widget") await WidgetStore.setOptions(type, body.options);
         else throw new ApiError(400, "Unrecognized category");
 
+        LogService.info("AdminIntegrationsService", userId + " updated the integration options for " + category + "/" + type);
         Cache.for(CACHE_INTEGRATIONS).clear();
         return {}; // 200 OK
     }
@@ -37,11 +39,12 @@ export class AdminIntegrationsService {
     @POST
     @Path(":category/:type/enabled")
     public async setEnabled(@QueryParam("scalar_token") scalarToken: string, @PathParam("category") category: string, @PathParam("type") type: string, body: SetEnabledRequest): Promise<any> {
-        await AdminService.validateAndGetAdminTokenOwner(scalarToken);
+        const userId = await AdminService.validateAndGetAdminTokenOwner(scalarToken);
 
         if (category === "widget") await WidgetStore.setEnabled(type, body.enabled);
         else throw new ApiError(400, "Unrecognized category");
 
+        LogService.info("AdminIntegrationsService", userId + " set " + category + "/" + type + " to " + (body.enabled ? "enabled" : "disabled"));
         Cache.for(CACHE_INTEGRATIONS).clear();
         return {}; // 200 OK
     }

src/api/admin/AdminNebService.ts

@@ -51,8 +51,11 @@ export class AdminNebService {
     @POST
     @Path(":id/integration/:type/enabled")
     public async setIntegrationEnabled(@QueryParam("scalar_token") scalarToken: string, @PathParam("id") nebId: number, @PathParam("type") integrationType: string, request: SetEnabledRequest): Promise<any> {
-        await AdminService.validateAndGetAdminTokenOwner(scalarToken);
+        const userId = await AdminService.validateAndGetAdminTokenOwner(scalarToken);
+
         await NebStore.setIntegrationEnabled(nebId, integrationType, request.enabled);
+        LogService.info("AdminNebService", userId + " set the " + integrationType + " on NEB " + nebId + " to " + (request.enabled ? "enabled" : "disabled"));
+
         Cache.for(CACHE_NEB).clear();
         Cache.for(CACHE_INTEGRATIONS).clear();
         return {}; // 200 OK
@@ -61,8 +64,11 @@ export class AdminNebService {
     @POST
     @Path(":id/integration/:type/config")
     public async setIntegrationConfig(@QueryParam("scalar_token") scalarToken: string, @PathParam("id") nebId: number, @PathParam("type") integrationType: string, newConfig: any): Promise<any> {
-        await AdminService.validateAndGetAdminTokenOwner(scalarToken);
+        const userId = await AdminService.validateAndGetAdminTokenOwner(scalarToken);
+
         await NebStore.setIntegrationConfig(nebId, integrationType, newConfig);
+        LogService.info("AdminNebService", userId + " updated the configuration for " + integrationType + " on NEB " + nebId);
+
         Cache.for(CACHE_NEB).clear();
         Cache.for(CACHE_INTEGRATIONS).clear();
         return {}; // 200 OK
@@ -78,10 +84,12 @@ export class AdminNebService {
     @POST
     @Path("new/upstream")
     public async newConfigForUpstream(@QueryParam("scalar_token") scalarToken: string, request: CreateWithUpstream): Promise<NebConfig> {
-        await AdminService.validateAndGetAdminTokenOwner(scalarToken);
+        const userId = await AdminService.validateAndGetAdminTokenOwner(scalarToken);
 
         try {
             const neb = await NebStore.createForUpstream(request.upstreamId);
+            LogService.info("AdminNebService", userId + " created a new NEB instance from upstream " + request.upstreamId);
+
             Cache.for(CACHE_NEB).clear();
             Cache.for(CACHE_INTEGRATIONS).clear();
             return neb;
@@ -94,10 +102,12 @@ export class AdminNebService {
     @POST
     @Path("new/appservice")
     public async newConfigForAppservice(@QueryParam("scalar_token") scalarToken: string, request: CreateWithAppservice): Promise<NebConfig> {
-        await AdminService.validateAndGetAdminTokenOwner(scalarToken);
+        const userId = await AdminService.validateAndGetAdminTokenOwner(scalarToken);
 
         try {
             const neb = await NebStore.createForAppservice(request.appserviceId, request.adminUrl);
+            LogService.info("AdminNebService", userId + " created a new NEB instance from appservice " + request.appserviceId);
+
             Cache.for(CACHE_NEB).clear();
             Cache.for(CACHE_INTEGRATIONS).clear();
             return neb;

src/api/admin/AdminUpstreamService.ts

@@ -2,6 +2,7 @@ import { GET, Path, POST, QueryParam } from "typescript-rest";
 import { AdminService } from "./AdminService";
 import { Cache, CACHE_UPSTREAM } from "../../MemoryCache";
 import Upstream from "../../db/models/Upstream";
+import { LogService } from "matrix-js-snippets";
 
 interface UpstreamRepsonse {
     id: number;
@@ -42,7 +43,7 @@ export class AdminUpstreamService {
     @POST
     @Path("new")
     public async createUpstream(@QueryParam("scalar_token") scalarToken: string, request: NewUpstreamRequest): Promise<UpstreamRepsonse> {
-        await AdminService.validateAndGetAdminTokenOwner(scalarToken);
+        const userId = await AdminService.validateAndGetAdminTokenOwner(scalarToken);
 
         const upstream = await Upstream.create({
             name: request.name,
@@ -51,6 +52,7 @@ export class AdminUpstreamService {
             apiUrl: request.apiUrl,
         });
 
+        LogService.info("AdminUpstreamService", userId + " created a new upstream");
         Cache.for(CACHE_UPSTREAM).clear();
         return this.mapUpstream(upstream);
     }

src/api/dimension/DimensionHealthService.ts

@@ -1,4 +1,5 @@
 import { GET, Path } from "typescript-rest";
+import { LogService } from "matrix-js-snippets";
 
 /**
  * API for the health of Dimension
@@ -9,6 +10,7 @@ export class DimensionHealthService {
     @GET
     @Path("heartbeat")
     public async heartbeat(): Promise<any> {
+        LogService.info("DimensionHealthService", "Heartbeat called");
         return {}; // 200 OK
     }
 }

src/api/scalar/ScalarService.ts

@@ -84,6 +84,7 @@ export class ScalarService {
             isDimensionToken: true,
         });
 
+        LogService.info("ScalarService", mxUserId + " has registered for a scalar token successfully");
         return {scalar_token: dimensionScalarToken.scalarToken};
     }
 

src/db/AppserviceStore.ts

@@ -2,6 +2,7 @@ import AppService from "./models/AppService";
 import AppServiceUser from "./models/AppServiceUser";
 import * as randomString from "random-string";
 import { MatrixAppserviceClient } from "../matrix/MatrixAppserviceClient";
+import { LogService } from "matrix-js-snippets";
 
 export class AppserviceStore {
 
@@ -37,22 +38,25 @@ export class AppserviceStore {
     public static getSafeUserId(userIdOrPrefix: string): string {
         // Force user IDs to be lowercase and strip out characters that aren't permitted
         // https://matrix.org/docs/spec/appendices.html#user-identifiers
-        return userIdOrPrefix.toLowerCase().replace(/[^a-z0-9._\-=]/g, '.');
+        if (userIdOrPrefix.startsWith('@')) {
+            // we only change out the parts we care about. The rest will be crushed down.
+            userIdOrPrefix = userIdOrPrefix.replace(/@/g, '=40');
+            userIdOrPrefix = userIdOrPrefix.replace(/:/g, '=3A');
         }
-
+        return userIdOrPrefix.toLowerCase().replace(/[^a-z0-9._\-=]/g, '.');
-    public static async getUsers(appserviceId: string): Promise<AppServiceUser[]> {
-        return AppServiceUser.findAll({where: {appserviceId: appserviceId}});
     }
 
     public static async registerUser(appserviceId: string, userId: string): Promise<AppServiceUser> {
         const appservice = await AppService.findOne({where: {id: appserviceId}});
         if (!appservice) throw new Error("Appservice not found");
 
+        LogService.info("AppserviceStore", "Registering to own " + userId + " in appservice " + appserviceId);
         const client = new MatrixAppserviceClient(appservice);
         const localpart = AppserviceStore.getSafeUserId(userId.substring(1).split(":")[0]);
         const response = await client.registerUser(localpart);
+        LogService.info("AppserviceStore", "Successfully registered " + userId);
 
-        return AppServiceUser.create({
+        return await AppServiceUser.create({
             id: userId,
             appserviceId: appserviceId,
             accessToken: response.access_token,

src/matrix/helpers.ts

@@ -48,6 +48,7 @@ export async function getFederationUrl(serverName: string): Promise<string> {
 
 export async function doFederatedApiCall(method: string, serverName: string, endpoint: string, query?: object, body?: object): Promise<any> {
     const federationUrl = await  getFederationUrl(serverName);
+    LogService.info("matrix", "Doing federated API call: " + federationUrl + endpoint);
     return new Promise((resolve, reject) => {
         request({
             method: method,
@@ -74,6 +75,7 @@ export async function doFederatedApiCall(method: string, serverName: string, end
 export async function doClientApiCall(method: string, endpoint: string, query?: object, body?: object): Promise<any> {
     let url = config.homeserver.clientServerUrl;
     if (url.endsWith("/")) url = url.substring(0, url.length - 1);
+    LogService.info("matrix", "Doing client API call: " + url + endpoint);
 
     return new Promise((resolve, reject) => {
         request({

src/neb/NebClient.ts

@@ -60,6 +60,7 @@ export class NebClient {
     private doRequest<T>(endpoint: string, body: any): Promise<T> {
         const adminUrl = (this.neb.adminUrl.endsWith("/") ? this.neb.adminUrl.substring(0, this.neb.adminUrl.length - 1) : this.neb.adminUrl);
         if (!endpoint.startsWith("/")) endpoint = "/" + endpoint;
+        LogService.info("NebClient", "Doing NEB call: " + adminUrl + endpoint);
 
         return new Promise((resolve, reject) => {
             request({

src/neb/NebProxy.ts

@@ -27,7 +27,6 @@ interface InternalTravisCiConfig {
 
 export class NebProxy {
     constructor(private neb: NebConfig, private requestingUserId: string) {
-
     }
 
     public async getBotUserId(integration: NebIntegration): Promise<string> {
@@ -324,6 +323,7 @@ export class NebProxy {
 
         const apiUrl = upstream.apiUrl.endsWith("/") ? upstream.apiUrl.substring(0, upstream.apiUrl.length - 1) : upstream.apiUrl;
         const url = apiUrl + (endpoint.startsWith("/") ? endpoint : "/" + endpoint);
+        LogService.info("NebProxy", "Doing upstream NEB request: " + url);
 
         return new Promise<T>((resolve, reject) => {
             request({

src/scalar/ScalarClient.ts

@@ -9,6 +9,7 @@ export class ScalarClient {
     }
 
     public register(openId: OpenId): Promise<ScalarRegisterResponse> {
+        LogService.info("ScalarClient", "Doing upstream scalar request: " + this.upstream.scalarUrl + "/register");
         return new Promise((resolve, reject) => {
             request({
                 method: "POST",

src/version.ts

@@ -1,12 +1,20 @@
-import { LogService } from "matrix-js-snippets";
 import * as git from "git-rev-sync";
 
 let version = "Unknown";
+let gitHash = null;
 
 try {
     version = "v" + require("../../package.json").version;
 } catch (error) {
-    LogService.error("version", error);
+    // The log service isn't set up by the time we require this file
+    console.error("version", error);
 }
 
-export const CURRENT_VERSION = version + "-" + git.short();
+try {
+    gitHash = git.short();
+} catch (error) {
+    // The log service isn't set up by the time we require this file
+    console.error("version", error);
+}
+
+export const CURRENT_VERSION = version + (gitHash ? "-" + gitHash : "");