Skip to content

Commit

Permalink
Make the server logs more stable by stubbing time and seq info in the…
Browse files Browse the repository at this point in the history
… log (microsoft#53693)
  • Loading branch information
sheetalkamat committed Apr 6, 2023
1 parent 7f63767 commit 85f2024
Show file tree
Hide file tree
Showing 842 changed files with 78,759 additions and 78,747 deletions.
15 changes: 10 additions & 5 deletions src/testRunner/unittests/tsserver/helpers.ts
Original file line number Diff line number Diff line change
Expand Up @@ -74,7 +74,6 @@ export function createHasErrorMessageLogger(): Logger {
function handleLoggerGroup(logger: Logger, host: TestServerHost | undefined): Logger {
let inGroup = false;
let firstInGroup = false;
let seq = 0;
logger.startGroup = () => {
inGroup = true;
firstInGroup = true;
Expand All @@ -88,10 +87,9 @@ function handleLoggerGroup(logger: Logger, host: TestServerHost | undefined): Lo

function msg(s: string, type = ts.server.Msg.Err, write: (s: string) => void) {
s = `[${nowString(logger.host!)}] ${s}`;
if (!inGroup || firstInGroup) s = padStringRight(type + " " + seq.toString(), " ") + s;
if (!inGroup || firstInGroup) s = padStringRight(type + " seq", " ") + s;
if (ts.Debug.isDebugging) console.log(s);
write(s);
if (!inGroup) seq++;
}

function padStringRight(str: string, padding: string) {
Expand All @@ -101,8 +99,8 @@ function handleLoggerGroup(logger: Logger, host: TestServerHost | undefined): Lo

function nowString(host: TestServerHost) {
// E.g. "12:34:56.789"
const d = host.now();
return `${ts.padLeft(d.getUTCHours().toString(), 2, "0")}:${ts.padLeft(d.getUTCMinutes().toString(), 2, "0")}:${ts.padLeft(d.getUTCSeconds().toString(), 2, "0")}.${ts.padLeft(d.getUTCMilliseconds().toString(), 3, "0")}`;
host.now(); // To increment the time but not print it to avoid the baseline updates
return `hh:mm:ss:mss`;
}

export function createLoggerWritingToConsole(host: TestServerHost): Logger {
Expand Down Expand Up @@ -401,15 +399,22 @@ function patchHostTimeouts(

const originalRunQueuedTimeoutCallbacks = host.runQueuedTimeoutCallbacks;
const originalRunQueuedImmediateCallbacks = host.runQueuedImmediateCallbacks;
const originalSetTime = host.setTime;
let hostDiff: ReturnType<TestServerHost["snap"]> | undefined;

host.runQueuedTimeoutCallbacks = runQueuedTimeoutCallbacks;
host.runQueuedImmediateCallbacks = runQueuedImmediateCallbacks;
host.logTimeoutQueueLength = logTimeoutQueueLength;
host.setTime = setTime;
host.baselineHost = baselineHost;
host.patched = true;
return host;

function setTime(time: number) {
logger.log(`Host is moving to new time`);
return originalSetTime.call(host, time);
}

function logTimeoutQueueLength() {
logger.log(host.timeoutCallbacks.log());
host.baselineHost(host.immediateCallbacks.log());
Expand Down

Large diffs are not rendered by default.

Large diffs are not rendered by default.

Large diffs are not rendered by default.

Original file line number Diff line number Diff line change
@@ -1,5 +1,5 @@
currentDirectory:: / useCaseSensitiveFileNames: false
Info 0 [00:00:19.000] Provided types map file "/a/lib/typesMap.json" doesn't exist
Info seq [hh:mm:ss:mss] Provided types map file "/a/lib/typesMap.json" doesn't exist
Before request
//// [/node_modules/@angular/forms/forms.d.ts]
export declare class PatternValidator {}
Expand All @@ -17,7 +17,7 @@ export declare class PatternValidator {}
Info 1 [00:00:20.000] request:
Info seq [hh:mm:ss:mss] request:
{
"command": "open",
"arguments": {
Expand All @@ -26,11 +26,11 @@ Info 1 [00:00:20.000] request:
"seq": 1,
"type": "request"
}
Info 2 [00:00:21.000] Search path: /
Info 3 [00:00:22.000] For info: /index.ts :: Config file name: /tsconfig.json
Info 4 [00:00:23.000] Creating configuration project /tsconfig.json
Info 5 [00:00:24.000] FileWatcher:: Added:: WatchInfo: /tsconfig.json 2000 undefined Project: /tsconfig.json WatchType: Config file
Info 6 [00:00:25.000] Config: /tsconfig.json : {
Info seq [hh:mm:ss:mss] Search path: /
Info seq [hh:mm:ss:mss] For info: /index.ts :: Config file name: /tsconfig.json
Info seq [hh:mm:ss:mss] Creating configuration project /tsconfig.json
Info seq [hh:mm:ss:mss] FileWatcher:: Added:: WatchInfo: /tsconfig.json 2000 undefined Project: /tsconfig.json WatchType: Config file
Info seq [hh:mm:ss:mss] Config: /tsconfig.json : {
"rootNames": [
"/index.ts"
],
Expand All @@ -39,47 +39,47 @@ Info 6 [00:00:25.000] Config: /tsconfig.json : {
"configFilePath": "/tsconfig.json"
}
}
Info 7 [00:00:26.000] DirectoryWatcher:: Added:: WatchInfo: 1 undefined Config: /tsconfig.json WatchType: Wild card directory
Info 8 [00:00:27.000] Elapsed:: *ms DirectoryWatcher:: Added:: WatchInfo: 1 undefined Config: /tsconfig.json WatchType: Wild card directory
Info 9 [00:00:28.000] Starting updateGraphWorker: Project: /tsconfig.json
Info 10 [00:00:29.000] FileWatcher:: Added:: WatchInfo: /a/lib/lib.d.ts 500 undefined Project: /tsconfig.json WatchType: Missing file
Info 11 [00:00:30.000] Finishing updateGraphWorker: Project: /tsconfig.json Version: 1 structureChanged: true structureIsReused:: Not Elapsed:: *ms
Info 12 [00:00:31.000] Project '/tsconfig.json' (Configured)
Info 13 [00:00:32.000] Files (1)
Info seq [hh:mm:ss:mss] DirectoryWatcher:: Added:: WatchInfo: 1 undefined Config: /tsconfig.json WatchType: Wild card directory
Info seq [hh:mm:ss:mss] Elapsed:: *ms DirectoryWatcher:: Added:: WatchInfo: 1 undefined Config: /tsconfig.json WatchType: Wild card directory
Info seq [hh:mm:ss:mss] Starting updateGraphWorker: Project: /tsconfig.json
Info seq [hh:mm:ss:mss] FileWatcher:: Added:: WatchInfo: /a/lib/lib.d.ts 500 undefined Project: /tsconfig.json WatchType: Missing file
Info seq [hh:mm:ss:mss] Finishing updateGraphWorker: Project: /tsconfig.json Version: 1 structureChanged: true structureIsReused:: Not Elapsed:: *ms
Info seq [hh:mm:ss:mss] Project '/tsconfig.json' (Configured)
Info seq [hh:mm:ss:mss] Files (1)
/index.ts SVC-1-0 ""
index.ts
Matched by default include pattern '**/*'

Info 14 [00:00:33.000] -----------------------------------------------
Info 15 [00:00:34.000] FileWatcher:: Added:: WatchInfo: /package.json 250 undefined WatchType: package.json file
Info 16 [00:00:35.000] AutoImportProviderProject: found 1 root files in 1 dependencies in * ms
Info 17 [00:00:36.000] DirectoryWatcher:: Added:: WatchInfo: /node_modules 1 undefined WatchType: node_modules for closed script infos and package.jsons affecting module specifier cache
Info 18 [00:00:37.000] Elapsed:: *ms DirectoryWatcher:: Added:: WatchInfo: /node_modules 1 undefined WatchType: node_modules for closed script infos and package.jsons affecting module specifier cache
Info 19 [00:00:38.000] Starting updateGraphWorker: Project: /dev/null/autoImportProviderProject1*
Info 20 [00:00:39.000] Finishing updateGraphWorker: Project: /dev/null/autoImportProviderProject1* Version: 1 structureChanged: true structureIsReused:: Not Elapsed:: *ms
Info 21 [00:00:40.000] Project '/dev/null/autoImportProviderProject1*' (AutoImportProvider)
Info 22 [00:00:41.000] Files (1)
Info seq [hh:mm:ss:mss] -----------------------------------------------
Info seq [hh:mm:ss:mss] FileWatcher:: Added:: WatchInfo: /package.json 250 undefined WatchType: package.json file
Info seq [hh:mm:ss:mss] AutoImportProviderProject: found 1 root files in 1 dependencies in * ms
Info seq [hh:mm:ss:mss] DirectoryWatcher:: Added:: WatchInfo: /node_modules 1 undefined WatchType: node_modules for closed script infos and package.jsons affecting module specifier cache
Info seq [hh:mm:ss:mss] Elapsed:: *ms DirectoryWatcher:: Added:: WatchInfo: /node_modules 1 undefined WatchType: node_modules for closed script infos and package.jsons affecting module specifier cache
Info seq [hh:mm:ss:mss] Starting updateGraphWorker: Project: /dev/null/autoImportProviderProject1*
Info seq [hh:mm:ss:mss] Finishing updateGraphWorker: Project: /dev/null/autoImportProviderProject1* Version: 1 structureChanged: true structureIsReused:: Not Elapsed:: *ms
Info seq [hh:mm:ss:mss] Project '/dev/null/autoImportProviderProject1*' (AutoImportProvider)
Info seq [hh:mm:ss:mss] Files (1)
/node_modules/@angular/forms/forms.d.ts Text-1 "export declare class PatternValidator {}"


node_modules/@angular/forms/forms.d.ts
Root file specified for compilation

Info 23 [00:00:42.000] -----------------------------------------------
Info 24 [00:00:43.000] Project '/tsconfig.json' (Configured)
Info 24 [00:00:44.000] Files (1)
Info seq [hh:mm:ss:mss] -----------------------------------------------
Info seq [hh:mm:ss:mss] Project '/tsconfig.json' (Configured)
Info seq [hh:mm:ss:mss] Files (1)

Info 24 [00:00:45.000] -----------------------------------------------
Info 24 [00:00:46.000] Project '/dev/null/autoImportProviderProject1*' (AutoImportProvider)
Info 24 [00:00:47.000] Files (1)
Info seq [hh:mm:ss:mss] -----------------------------------------------
Info seq [hh:mm:ss:mss] Project '/dev/null/autoImportProviderProject1*' (AutoImportProvider)
Info seq [hh:mm:ss:mss] Files (1)

Info 24 [00:00:48.000] -----------------------------------------------
Info 24 [00:00:49.000] Open files:
Info 24 [00:00:50.000] FileName: /index.ts ProjectRootPath: undefined
Info 24 [00:00:51.000] Projects: /tsconfig.json
Info 24 [00:00:52.000] response:
Info seq [hh:mm:ss:mss] -----------------------------------------------
Info seq [hh:mm:ss:mss] Open files:
Info seq [hh:mm:ss:mss] FileName: /index.ts ProjectRootPath: undefined
Info seq [hh:mm:ss:mss] Projects: /tsconfig.json
Info seq [hh:mm:ss:mss] response:
{
"responseRequired": false
}
Expand All @@ -101,7 +101,7 @@ FsWatchesRecursive::
/node_modules: *new*
{}

Info 25 [00:00:53.000] DirectoryWatcher:: Close:: WatchInfo: 1 undefined Config: /tsconfig.json WatchType: Wild card directory
Info 26 [00:00:54.000] Elapsed:: *ms DirectoryWatcher:: Close:: WatchInfo: 1 undefined Config: /tsconfig.json WatchType: Wild card directory
Info 27 [00:00:55.000] FileWatcher:: Close:: WatchInfo: /tsconfig.json 2000 undefined Project: /tsconfig.json WatchType: Config file
Info 28 [00:00:56.000] FileWatcher:: Close:: WatchInfo: /a/lib/lib.d.ts 500 undefined Project: /tsconfig.json WatchType: Missing file
Info seq [hh:mm:ss:mss] DirectoryWatcher:: Close:: WatchInfo: 1 undefined Config: /tsconfig.json WatchType: Wild card directory
Info seq [hh:mm:ss:mss] Elapsed:: *ms DirectoryWatcher:: Close:: WatchInfo: 1 undefined Config: /tsconfig.json WatchType: Wild card directory
Info seq [hh:mm:ss:mss] FileWatcher:: Close:: WatchInfo: /tsconfig.json 2000 undefined Project: /tsconfig.json WatchType: Config file
Info seq [hh:mm:ss:mss] FileWatcher:: Close:: WatchInfo: /a/lib/lib.d.ts 500 undefined Project: /tsconfig.json WatchType: Missing file
Original file line number Diff line number Diff line change
@@ -1,5 +1,5 @@
currentDirectory:: / useCaseSensitiveFileNames: false
Info 0 [00:00:23.000] Provided types map file "/a/lib/typesMap.json" doesn't exist
Info seq [hh:mm:ss:mss] Provided types map file "/a/lib/typesMap.json" doesn't exist
Before request
//// [/packages/a/package.json]
{ "dependencies": { "b": "*" } }
Expand All @@ -20,7 +20,7 @@ Before request
export class B {}
Info 1 [00:00:24.000] request:
Info seq [hh:mm:ss:mss] request:
{
"command": "open",
"arguments": {
Expand All @@ -29,11 +29,11 @@ Info 1 [00:00:24.000] request:
"seq": 1,
"type": "request"
}
Info 2 [00:00:25.000] Search path: /packages/a
Info 3 [00:00:26.000] For info: /packages/a/index.ts :: Config file name: /packages/a/tsconfig.json
Info 4 [00:00:27.000] Creating configuration project /packages/a/tsconfig.json
Info 5 [00:00:28.000] FileWatcher:: Added:: WatchInfo: /packages/a/tsconfig.json 2000 undefined Project: /packages/a/tsconfig.json WatchType: Config file
Info 6 [00:00:29.000] Config: /packages/a/tsconfig.json : {
Info seq [hh:mm:ss:mss] Search path: /packages/a
Info seq [hh:mm:ss:mss] For info: /packages/a/index.ts :: Config file name: /packages/a/tsconfig.json
Info seq [hh:mm:ss:mss] Creating configuration project /packages/a/tsconfig.json
Info seq [hh:mm:ss:mss] FileWatcher:: Added:: WatchInfo: /packages/a/tsconfig.json 2000 undefined Project: /packages/a/tsconfig.json WatchType: Config file
Info seq [hh:mm:ss:mss] Config: /packages/a/tsconfig.json : {
"rootNames": [
"/packages/a/index.ts"
],
Expand All @@ -48,10 +48,10 @@ Info 6 [00:00:29.000] Config: /packages/a/tsconfig.json : {
}
]
}
Info 7 [00:00:30.000] DirectoryWatcher:: Added:: WatchInfo: /packages/a 1 undefined Config: /packages/a/tsconfig.json WatchType: Wild card directory
Info 8 [00:00:31.000] Elapsed:: *ms DirectoryWatcher:: Added:: WatchInfo: /packages/a 1 undefined Config: /packages/a/tsconfig.json WatchType: Wild card directory
Info 9 [00:00:32.000] Starting updateGraphWorker: Project: /packages/a/tsconfig.json
Info 10 [00:00:33.000] Config: /packages/a/node_modules/b/tsconfig.json : {
Info seq [hh:mm:ss:mss] DirectoryWatcher:: Added:: WatchInfo: /packages/a 1 undefined Config: /packages/a/tsconfig.json WatchType: Wild card directory
Info seq [hh:mm:ss:mss] Elapsed:: *ms DirectoryWatcher:: Added:: WatchInfo: /packages/a 1 undefined Config: /packages/a/tsconfig.json WatchType: Wild card directory
Info seq [hh:mm:ss:mss] Starting updateGraphWorker: Project: /packages/a/tsconfig.json
Info seq [hh:mm:ss:mss] Config: /packages/a/node_modules/b/tsconfig.json : {
"rootNames": [
"/packages/a/node_modules/b/index.ts"
],
Expand All @@ -61,51 +61,51 @@ Info 10 [00:00:33.000] Config: /packages/a/node_modules/b/tsconfig.json : {
"configFilePath": "/packages/a/node_modules/b/tsconfig.json"
}
}
Info 11 [00:00:34.000] FileWatcher:: Added:: WatchInfo: /packages/a/node_modules/b/tsconfig.json 2000 undefined Project: /packages/a/tsconfig.json WatchType: Config file
Info 12 [00:00:35.000] DirectoryWatcher:: Added:: WatchInfo: /packages/a/node_modules/b 1 undefined Config: /packages/a/node_modules/b/tsconfig.json WatchType: Wild card directory
Info 13 [00:00:36.000] Elapsed:: *ms DirectoryWatcher:: Added:: WatchInfo: /packages/a/node_modules/b 1 undefined Config: /packages/a/node_modules/b/tsconfig.json WatchType: Wild card directory
Info 14 [00:00:37.000] FileWatcher:: Added:: WatchInfo: /a/lib/lib.d.ts 500 undefined Project: /packages/a/tsconfig.json WatchType: Missing file
Info 15 [00:00:38.000] DirectoryWatcher:: Added:: WatchInfo: /packages/a/node_modules/@types 1 undefined Project: /packages/a/tsconfig.json WatchType: Type roots
Info 16 [00:00:39.000] Elapsed:: *ms DirectoryWatcher:: Added:: WatchInfo: /packages/a/node_modules/@types 1 undefined Project: /packages/a/tsconfig.json WatchType: Type roots
Info 17 [00:00:40.000] Finishing updateGraphWorker: Project: /packages/a/tsconfig.json Version: 1 structureChanged: true structureIsReused:: Not Elapsed:: *ms
Info 18 [00:00:41.000] Project '/packages/a/tsconfig.json' (Configured)
Info 19 [00:00:42.000] Files (1)
Info seq [hh:mm:ss:mss] FileWatcher:: Added:: WatchInfo: /packages/a/node_modules/b/tsconfig.json 2000 undefined Project: /packages/a/tsconfig.json WatchType: Config file
Info seq [hh:mm:ss:mss] DirectoryWatcher:: Added:: WatchInfo: /packages/a/node_modules/b 1 undefined Config: /packages/a/node_modules/b/tsconfig.json WatchType: Wild card directory
Info seq [hh:mm:ss:mss] Elapsed:: *ms DirectoryWatcher:: Added:: WatchInfo: /packages/a/node_modules/b 1 undefined Config: /packages/a/node_modules/b/tsconfig.json WatchType: Wild card directory
Info seq [hh:mm:ss:mss] FileWatcher:: Added:: WatchInfo: /a/lib/lib.d.ts 500 undefined Project: /packages/a/tsconfig.json WatchType: Missing file
Info seq [hh:mm:ss:mss] DirectoryWatcher:: Added:: WatchInfo: /packages/a/node_modules/@types 1 undefined Project: /packages/a/tsconfig.json WatchType: Type roots
Info seq [hh:mm:ss:mss] Elapsed:: *ms DirectoryWatcher:: Added:: WatchInfo: /packages/a/node_modules/@types 1 undefined Project: /packages/a/tsconfig.json WatchType: Type roots
Info seq [hh:mm:ss:mss] Finishing updateGraphWorker: Project: /packages/a/tsconfig.json Version: 1 structureChanged: true structureIsReused:: Not Elapsed:: *ms
Info seq [hh:mm:ss:mss] Project '/packages/a/tsconfig.json' (Configured)
Info seq [hh:mm:ss:mss] Files (1)
/packages/a/index.ts SVC-1-0 ""
index.ts
Matched by default include pattern '**/*'

Info 20 [00:00:43.000] -----------------------------------------------
Info 21 [00:00:44.000] FileWatcher:: Added:: WatchInfo: /packages/a/package.json 250 undefined WatchType: package.json file
Info 22 [00:00:45.000] AutoImportProviderProject: found 1 root files in 1 dependencies in * ms
Info 23 [00:00:46.000] Starting updateGraphWorker: Project: /dev/null/autoImportProviderProject1*
Info 24 [00:00:47.000] DirectoryWatcher:: Added:: WatchInfo: /packages/a/node_modules 1 undefined WatchType: node_modules for closed script infos and package.jsons affecting module specifier cache
Info 25 [00:00:48.000] Elapsed:: *ms DirectoryWatcher:: Added:: WatchInfo: /packages/a/node_modules 1 undefined WatchType: node_modules for closed script infos and package.jsons affecting module specifier cache
Info 26 [00:00:49.000] Finishing updateGraphWorker: Project: /dev/null/autoImportProviderProject1* Version: 1 structureChanged: true structureIsReused:: Not Elapsed:: *ms
Info 27 [00:00:50.000] Project '/dev/null/autoImportProviderProject1*' (AutoImportProvider)
Info 28 [00:00:51.000] Files (1)
Info seq [hh:mm:ss:mss] -----------------------------------------------
Info seq [hh:mm:ss:mss] FileWatcher:: Added:: WatchInfo: /packages/a/package.json 250 undefined WatchType: package.json file
Info seq [hh:mm:ss:mss] AutoImportProviderProject: found 1 root files in 1 dependencies in * ms
Info seq [hh:mm:ss:mss] Starting updateGraphWorker: Project: /dev/null/autoImportProviderProject1*
Info seq [hh:mm:ss:mss] DirectoryWatcher:: Added:: WatchInfo: /packages/a/node_modules 1 undefined WatchType: node_modules for closed script infos and package.jsons affecting module specifier cache
Info seq [hh:mm:ss:mss] Elapsed:: *ms DirectoryWatcher:: Added:: WatchInfo: /packages/a/node_modules 1 undefined WatchType: node_modules for closed script infos and package.jsons affecting module specifier cache
Info seq [hh:mm:ss:mss] Finishing updateGraphWorker: Project: /dev/null/autoImportProviderProject1* Version: 1 structureChanged: true structureIsReused:: Not Elapsed:: *ms
Info seq [hh:mm:ss:mss] Project '/dev/null/autoImportProviderProject1*' (AutoImportProvider)
Info seq [hh:mm:ss:mss] Files (1)
/packages/a/node_modules/b/index.ts Text-1 "export class B {}"


node_modules/b/index.ts
Root file specified for compilation

Info 29 [00:00:52.000] -----------------------------------------------
Info 30 [00:00:53.000] Search path: /packages/a
Info 31 [00:00:54.000] For info: /packages/a/tsconfig.json :: No config files found.
Info 32 [00:00:55.000] Project '/packages/a/tsconfig.json' (Configured)
Info 32 [00:00:56.000] Files (1)
Info seq [hh:mm:ss:mss] -----------------------------------------------
Info seq [hh:mm:ss:mss] Search path: /packages/a
Info seq [hh:mm:ss:mss] For info: /packages/a/tsconfig.json :: No config files found.
Info seq [hh:mm:ss:mss] Project '/packages/a/tsconfig.json' (Configured)
Info seq [hh:mm:ss:mss] Files (1)

Info 32 [00:00:57.000] -----------------------------------------------
Info 32 [00:00:58.000] Project '/dev/null/autoImportProviderProject1*' (AutoImportProvider)
Info 32 [00:00:59.000] Files (1)
Info seq [hh:mm:ss:mss] -----------------------------------------------
Info seq [hh:mm:ss:mss] Project '/dev/null/autoImportProviderProject1*' (AutoImportProvider)
Info seq [hh:mm:ss:mss] Files (1)

Info 32 [00:01:00.000] -----------------------------------------------
Info 32 [00:01:01.000] Open files:
Info 32 [00:01:02.000] FileName: /packages/a/index.ts ProjectRootPath: undefined
Info 32 [00:01:03.000] Projects: /packages/a/tsconfig.json
Info 32 [00:01:04.000] response:
Info seq [hh:mm:ss:mss] -----------------------------------------------
Info seq [hh:mm:ss:mss] Open files:
Info seq [hh:mm:ss:mss] FileName: /packages/a/index.ts ProjectRootPath: undefined
Info seq [hh:mm:ss:mss] Projects: /packages/a/tsconfig.json
Info seq [hh:mm:ss:mss] response:
{
"responseRequired": false
}
Expand Down

0 comments on commit 85f2024

Please sign in to comment.