Skip to content

Commit 8809a4a

Browse files
mcdurdinmcdurdin
authored
Merge pull request #536 from keymanapp/feat/service-state
feat: improve logging and handle failures more cleanly
2 parents c7c101a + a6d1990 commit 8809a4a

12 files changed

+77
-47
lines changed

‎package.json‎

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -10,7 +10,8 @@
1010
"build-server": "cd server && npm install && npm run-script build",
1111
"start-client": "cd public && npm run-script start",
1212
"start-server": "cd server && npm run-script start",
13-
"test": "cd server && npx mocha --import=./_mocha_register.js"
13+
"test": "cd server && npx mocha --import=./_mocha_register.js",
14+
"log": "az webapp log tail --resource-group keyman --name com-keyman-status"
1415
},
1516
"author": "Marc Durdin",
1617
"license": "MIT"

‎server/code.ts‎

Lines changed: 7 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -26,6 +26,7 @@ import gitHubMilestonesService from './services/github/github-milestones.js';
2626

2727
import { testUserTestComment } from './keymanapp-test-bot/test-user-test-results-comment.js';
2828
import { performanceLog } from './performance-log.js';
29+
import { consoleLog } from './util/console-log.js';
2930

3031
sms.install();
3132

@@ -34,7 +35,7 @@ export const environment: Environment =
3435
process.env['NODE_ENV'] == 'staging' ? Environment.Staging :
3536
Environment.Development;
3637

37-
console.log(`Running in ${environment} environment`);
38+
consoleLog('main', null, `Running in ${environment} environment`);
3839

3940

4041
const sprintCache = new SprintCache(environment);
@@ -191,7 +192,7 @@ setInterval(() => {
191192
const wsServer = new ws.Server({ noServer: true });
192193
wsServer.on('connection', socket => {
193194
socket.on('message', message => {
194-
console.log(message);
195+
consoleLog('websocket', null, message);
195196
if(message == 'ping')
196197
socket.send('pong');
197198
});
@@ -218,10 +219,11 @@ async function respondGitHubDataChange(request: express.Request) {
218219
try {
219220
const event = request?.headers?.['x-github-event'];
220221
const issueNumber = request?.body?.issue?.number;
222+
const pullNumber = request?.body?.pull_request?.number;
221223
const repo = request?.body?.repository?.name;
222224

223225
if((event == 'issues' || event == 'issue_comment') && !request.body.issue.pull_request) {
224-
console.log(`POST github webhook ${event} : keymanapp/${repo}#${issueNumber}`);
226+
consoleLog('main', 'github', `POST webhook ${event} : keymanapp/${repo}#${issueNumber}`);
225227
try {
226228
if(await statusData.refreshGitHubIssueData(repo, issueNumber)) {
227229
sendWsAlert(true, 'github-issues');
@@ -243,7 +245,7 @@ async function respondGitHubDataChange(request: express.Request) {
243245
const prNumber = request.body?.pull_request?.number;
244246
*/
245247
} else {
246-
console.log(`POST github webhook ${event} : keymanapp/${repo}#${issueNumber}`);
248+
consoleLog('main', 'github', `POST webhook ${event} : keymanapp/${repo}#${issueNumber ?? pullNumber}`);
247249
try {
248250
const hasChanged = await statusData.refreshGitHubStatusData('current');
249251
if(hasChanged) {
@@ -649,7 +651,7 @@ app.all('/{*splat}', (request, response) => {
649651
// app.use(Sentry.Handlers.errorHandler());
650652

651653
if(!debugTestBot) {
652-
console.log(`Starting app listening on ${port}`);
654+
consoleLog('main', null, `Starting app listening on ${port}`);
653655
const server = app.listen(port);
654656

655657
/* Upgrade any websocket connections */

‎server/data/status-data.ts‎

Lines changed: 5 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -24,6 +24,7 @@ import { ServiceStateCache, ServiceState, ServiceIdentifier } from "../../shared
2424
import discourseService from "../services/discourse/discourse.js";
2525
import { performanceLog } from "../performance-log.js";
2626
import siteLivelinessService from "../services/keyman/site-liveliness.js";
27+
import { consoleError, consoleLog } from '../util/console-log.js';
2728

2829
export type ContributionChanges = { issue: boolean, pull: boolean, review: boolean, test: boolean, post: boolean };
2930

@@ -75,10 +76,10 @@ async function logAsync(event, method: () => Promise<any>): Promise<any> {
7576
try {
7677
v = await method();
7778
} catch(e) {
78-
console.error(`Error connecting to ${event}: ${e}`);
79+
consoleError('refresh', event, `Error connecting to ${event}: ${e}`);
7980
if(e.errors) {
8081
// AggregateErrors
81-
console.error(e.errors);
82+
consoleError('refresh', event, e.errors);
8283
}
8384
throw e;
8485
}
@@ -215,7 +216,7 @@ export class StatusData {
215216
return false;
216217
}
217218
if(data == null) {
218-
console.log('[Refresh] GitHub Status EXIT -- null data');
219+
consoleLog('refresh', 'github', 'EXIT ERROR: unexpected null data');
219220
this.setServiceState(ServiceIdentifier.GitHub, ServiceState.error, 'null data');
220221
return false;
221222
}
@@ -333,7 +334,7 @@ export class StatusData {
333334
refreshCommunitySiteData = async (sprintName: string, user?: string): Promise<boolean> => {
334335
const sprint = this.cache.sprints[sprintName];
335336
if(!sprint || !sprint.phase) {
336-
console.error(`[Refresh] Community-Site: invalid sprint ${JSON.stringify(sprint)}`);
337+
consoleError('refresh', 'community-site', `invalid sprint ${JSON.stringify(sprint)}`);
337338
return false;
338339
}
339340

‎server/keymanapp-test-bot/emoji-label.ts‎

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -4,6 +4,7 @@ import emojiRegex from 'emoji-regex';
44

55
import { ProcessEventData } from "./keymanapp-test-bot.js";
66
import { issueLabelTypes, issueLabelScopes, issueValidTitleRegex } from "../../shared/issue-labels.js";
7+
import { consoleLog } from "../util/console-log.js";
78

89
const titleRegex = issueValidTitleRegex;
910
const validTypeLabels = issueLabelTypes;
@@ -25,7 +26,7 @@ const epicRefSubstring = (ref: string) => ref.match(/^epic\//) ? ref.substring('
2526
const epicRefToLabel = (ref: string) => 'epic-'+epicRefSubstring(ref);
2627

2728
function log(issue, s) {
28-
console.log(`[@keymanapp-pr-bot] #${issue.data.number}: ${s}`);
29+
consoleLog('pr-bot', null, `#${issue.data.number}: ${s}`);
2930
}
3031

3132
export async function processEpicLabelsEmoji(

‎server/keymanapp-test-bot/issue-milestone.ts‎

Lines changed: 4 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -4,6 +4,7 @@ import { Issue } from "@octokit/webhooks-types";
44
import { ProcessEventData } from "./keymanapp-test-bot.js";
55
import { getCurrentSprint } from "../current-sprint.js";
66
import { statusData } from '../data/status-data.js';
7+
import { consoleError, consoleLog } from "../util/console-log.js";
78

89
/**
910
* Apply the current milestone to the issue when it is closed,
@@ -14,14 +15,14 @@ export async function updateIssueMilestoneWhenIssueClosed(
1415
data: ProcessEventData,
1516
issue: Issue
1617
): Promise<void> {
17-
console.log(`[@keymanapp-pr-bot] Updating issue #${issue.number} milestone`);
18+
consoleLog('pr-bot', null, `Updating issue #${issue.number} milestone`);
1819
const currentSprint = getCurrentSprint(statusData.cache.sprints?.current?.github?.data);
1920
if(currentSprint) {
20-
console.log(`[@keymanapp-pr-bot] Applying milestone ${currentSprint.title} to issue #${issue.number}`);
21+
consoleLog('pr-bot', null, `Applying milestone ${currentSprint.title} to issue #${issue.number}`);
2122
const milestones = await octokit.rest.issues.listMilestones({...data, state: "open", per_page: 100});
2223
const milestone = milestones.data.find(m => m.title == currentSprint.title);
2324
if(!milestone) {
24-
console.error(`Could not find milestone ${currentSprint.title} in list of milestones`);
25+
consoleError('pr-bot', null, `Could not find milestone ${currentSprint.title} in list of milestones`);
2526
return;
2627
}
2728
await octokit.rest.issues.update({

‎server/keymanapp-test-bot/keymanapp-test-bot-middleware.ts‎

Lines changed: 3 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -12,6 +12,7 @@ import * as keymanappTestBot from './keymanapp-test-bot.js';
1212

1313
import { dirname } from 'node:path';
1414
import { fileURLToPath } from 'node:url';
15+
import { consoleError, consoleLog } from "../util/console-log.js";
1516

1617
const __dirname = dirname(fileURLToPath(import.meta.url));
1718

@@ -21,9 +22,9 @@ const secretFilename = rootPath + '.keymanapp-test-bot.secret';
2122
const appIdFilename = rootPath + '.keymanapp-test-bot.appid';
2223

2324
if(!fs.existsSync(appIdFilename)) {
24-
console.error(`keymanapp-test-bot: appId file ${appIdFilename} does not exist`);
25+
consoleError('test-bot', null, `appId file ${appIdFilename} does not exist`);
2526
} else {
26-
console.log(`keymanapp-test-bot: Reading appId file ${appIdFilename}`);
27+
consoleLog(`test-bot`, null, `Reading appId file ${appIdFilename}`);
2728
}
2829

2930
const appId = fs.existsSync(appIdFilename) ?
@@ -41,9 +42,6 @@ if(fs.existsSync(secretFilename))
4142
else if(env.PROBOT_SECRET)
4243
secret = env.PROBOT_SECRET;
4344

44-
//let buf = Buffer.from(privateKey);
45-
//console.log(buf.toString('base64'));
46-
4745
const probot = new Probot({
4846
appId: appId,
4947
privateKey: privateKey,

‎server/keymanapp-test-bot/keymanapp-test-bot.ts‎

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -15,14 +15,15 @@ import { getArtifactLinksComment } from "./artifact-links-comment.js";
1515
import { processEpicLabelsEmoji } from './emoji-label.js';
1616
import { processPRMilestone } from './pull-request-milestone.js';
1717
import { updateIssueMilestoneWhenIssueClosed } from "./issue-milestone.js";
18+
import { consoleLog } from "../util/console-log.js";
1819

1920
const manualTestRequiredLabelName = 'user-test-required';
2021
const manualTestMissingLabelName = 'user-test-missing';
2122
const manualTestFailedLabelName = 'user-test-failed';
2223
const hasUserTestLabelName = 'has-user-test';
2324

2425
function log(s) {
25-
console.log('[@keymanapp-test-bot] '+s);
26+
consoleLog('test-bot', null, s);
2627
}
2728

2829
export interface ProcessEventData {

‎server/keymanapp-test-bot/pull-request-milestone.ts‎

Lines changed: 4 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -4,6 +4,7 @@ import { GetResponseTypeFromEndpointMethod } from "@octokit/types";
44
import { ProcessEventData } from "./keymanapp-test-bot.js";
55
import { getCurrentSprint } from "../current-sprint.js";
66
import { statusData } from '../data/status-data.js';
7+
import { consoleError, consoleLog } from "../util/console-log.js";
78

89
/**
910
* Apply the current milestone to the PR if no milestone has been set
@@ -14,14 +15,14 @@ export async function processPRMilestone(
1415
issue: GetResponseTypeFromEndpointMethod<typeof octokit.rest.issues.get>,
1516
pull: GetResponseTypeFromEndpointMethod<typeof octokit.rest.pulls.get>,
1617
): Promise<void> {
17-
console.log(`[@keymanapp-pr-bot] Checking PR #${pull.data.number} milestone`);
18+
consoleLog('pr-bot', null, `Checking PR #${pull.data.number} milestone`);
1819
const currentSprint = getCurrentSprint(statusData.cache.sprints?.current?.github?.data);
1920
if(currentSprint && !pull.data.milestone) {
20-
console.log(`[@keymanapp-pr-bot] Applying milestone ${currentSprint.title} to PR #${pull.data.number}`);
21+
consoleLog(`pr-bot`, null, `Applying milestone ${currentSprint.title} to PR #${pull.data.number}`);
2122
const milestones = await octokit.rest.issues.listMilestones({...data, state: "open", per_page: 100});
2223
const milestone = milestones.data.find(m => m.title == currentSprint.title);
2324
if(!milestone) {
24-
console.error(`Could not find milestone ${currentSprint.title} in list of milestones`);
25+
consoleError('pr-bot', null, `Could not find milestone ${currentSprint.title} in list of milestones`);
2526
return;
2627
}
2728
await octokit.rest.issues.update({

‎server/performance-log.ts‎

Lines changed: 2 additions & 15 deletions
Original file line numberDiff line numberDiff line change
@@ -1,25 +1,12 @@
1-
2-
function zeroPad(s, x: number) {
3-
if(typeof s != 'string') s = s.toString();
4-
return ('0'.repeat(x) + s).slice(-x);
5-
}
1+
import { consoleLog } from "./util/console-log.js";
62

73
function spacePad(s, x: number) {
84
if(typeof s != 'string') s = s.toString();
95
return (' '.repeat(x) + s).slice(-x);
106
}
117

12-
function formatDuration(duration){
13-
var seconds = Math.abs(Math.ceil(duration / 1000)),
14-
h = (seconds - seconds % 3600) / 3600,
15-
m = (seconds - seconds % 60) / 60 % 60,
16-
s = seconds % 60,
17-
ms = duration % 1000;
18-
return (duration < 0 ? '-' : '') + h + ':' + zeroPad(m, 2) + ':' + zeroPad(s, 2) + '.' + zeroPad(ms, 4);
19-
}
20-
218
// function formatMsec()
229

2310
export function performanceLog(dt, event) {
24-
console.log(`[${formatDuration(dt)}] ${spacePad(Math.round(performance.now() - dt), 8)}ms ${event}`);
11+
consoleLog('performance', null, `${(Math.round(performance.now() - dt)).toString().padEnd(8)} ${event}`);
2512
}

‎server/util/DataChangeTimingManager.ts‎

Lines changed: 18 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -1,16 +1,23 @@
1+
import { consoleLog } from "./console-log.js";
2+
13
export class DataChangeTimingManager {
24
started: Date[] = [];
35
lastRun: Date[] = [];
46
dataChangeTimeout: NodeJS.Timeout[] = [];
57

8+
private formatDate(date: Date) {
9+
return date ? date.toISOString() : 'unknown';
10+
}
11+
612
isTooSoon = (id: string, minInterval: number, callback: () => void): boolean => {
7-
if (this.started[id] || this.lastRun[id] &&
8-
(new Date()).valueOf() - this.lastRun[id].valueOf() < minInterval) {
13+
const lastRunDelta = this.lastRun[id] ? (new Date()).valueOf() - this.lastRun[id].valueOf() : 1000000;
914

10-
console.log(
11-
`DataChangeTimingManager: Data change for ${id} is ${this.isRunning(id) ? 'still underway' : 'too soon'} `+
12-
`(started at ${(this.started[id] ?? '??').toString()}); waiting ${minInterval} milliseconds`
13-
);
15+
if (this.started[id] || lastRunDelta < minInterval) {
16+
if(this.started[id]) {
17+
consoleLog('timing', id, `Data change is still underway (started at ${this.formatDate(this.started[id])}); waiting ${minInterval} milliseconds`);
18+
} else {
19+
consoleLog('timing', id, `Data change was only ${lastRunDelta} msec ago (finished at ${this.formatDate(this.lastRun[id])}); waiting ${minInterval} milliseconds`);
20+
}
1421

1522
if (this.dataChangeTimeout[id]) {
1623
clearTimeout(this.dataChangeTimeout[id]);
@@ -30,16 +37,19 @@ export class DataChangeTimingManager {
3037

3138
start = (id): void => {
3239
this.started[id] = new Date();
40+
consoleLog('timing', id, `starting at ${this.formatDate(this.started[id])}`);
3341
// this.lastRun[id] = new Date();
3442
};
3543

3644
finish = (id): void => {
37-
this.started[id] = null;
3845
this.lastRun[id] = new Date();
46+
const delta = this.started[id] ? this.lastRun[id].valueOf() - this.started[id].valueOf() : '??';
47+
consoleLog('timing', id, `finished in ${delta} msec at ${this.formatDate(this.lastRun[id])}; started at ${this.formatDate(this.started[id])}`);
48+
this.started[id] = null;
3949
};
4050

4151
reset = (): void => {
42-
console.log('DataChangeTimingManager: Resetting all timeouts');
52+
consoleLog('timing', null, `resetting all timeouts`);
4353
this.started = [];
4454
this.lastRun = [];
4555
this.dataChangeTimeout.forEach(t => clearTimeout(t));

0 commit comments

Comments
 (0)