Cleaning up console output from tests

CHANGELOG.md

@@ -13,7 +13,7 @@ x.x.x Release notes (yyyy-MM-dd)
 * File format: Generates Realms with format v9 (Reads and upgrades all previous formats)
 
 ### Internal
-* None.
+* Cleaned up the console output produced by `./tests`. ([#2548](https://github.com/realm/realm-js/pull/2548))
 
 3.2.0 Release notes (2019-9-30)
 =============================================================

CONTRIBUTING.md

@@ -146,6 +146,11 @@ Iterative development requires performing more of the steps manually:
 
 After making changes to the C++ source files rerun `npm run build-changes` to rebuild the files which have changed. Changes to JS or TS files don't require any manual steps beyond rerunning the tests.
 
+If you want the Realm JS Sync client's logs in the console, run your command with the `DEBUG=realm` environment variable set (i.e. `DEBUG=realm npm run js-tests`)
+To adjust the lowest log level set the `REALM_LOG_LEVEL` environment variable (defaults to `info`).
+
+Some tests have been instrumented with detailed logging, run your command with the `DEBUG=tests:*` environment variable set to see these (i.e. `DEBUG=tests:* npm run js-tests`)
+
 ### How To: Debug React Native Unit tests
 
 This guide assumes that development is happening on a Mac.

tests/js/adapter-tests.ts

@@ -124,7 +124,6 @@ jasmine.getEnv().addReporter({
         currentTestName = result.fullName.replace(/ /g, '_').replace('Adapter', realmNamePrefix);
     }
 });
-Realm.Sync.setLogLevel('error');
 
 describe('Adapter', () => {
     beforeEach(async () => {
@@ -146,7 +145,6 @@ describe('Adapter', () => {
             adapter.close();
         }
         await rosController.shutdown();
-        Realm.clearTestState();
         tmpDir.removeCallback();
     });
 

tests/js/index.js

@@ -20,7 +20,7 @@
 
 const Realm = require('realm');
 
-if( typeof Realm.Sync !== 'undefined' && Realm.Sync !== null ) {
+if (typeof Realm.Sync !== 'undefined' && Realm.Sync !== null) {
     global.WARNING = "global is not available in React Native. Use it only in tests";
     global.enableSyncTests = true;
 }
@@ -37,8 +37,8 @@ if (isNodeProcess && process.platform === 'win32') {
 // catching segfaults during testing can help debugging
 //uncomment to enable segfault handler
 //if (isNodeProcess) {
-    //const SegfaultHandler = node_require('segfault-handler');
-    //SegfaultHandler.registerHandler("crash.log");
+//const SegfaultHandler = node_require('segfault-handler');
+//SegfaultHandler.registerHandler("crash.log");
 //}
 
 var TESTS = {
@@ -86,27 +86,27 @@ var SPECIAL_METHODS = {
     afterEach: true,
 };
 
-exports.getTestNames = function() {
+exports.getTestNames = function () {
     var testNames = {};
 
     for (var suiteName in TESTS) {
         var testSuite = TESTS[suiteName];
 
-        testNames[suiteName] = Object.keys(testSuite).filter(function(testName) {
+        testNames[suiteName] = Object.keys(testSuite).filter(function (testName) {
             return !(testName in SPECIAL_METHODS) && typeof testSuite[testName] == 'function';
         });
     }
 
     return testNames;
 };
 
-exports.registerTests = function(tests) {
+exports.registerTests = function (tests) {
     for (var suiteName in tests) {
         TESTS[suiteName] = tests[suiteName];
     }
 };
 
-exports.prepare = function(done) {
+exports.prepare = function (done) {
     if (!global.enableSyncTests || !isNodeProcess || global.testAdminUserInfo) {
         done();
         return;
@@ -124,13 +124,12 @@ exports.prepare = function(done) {
         });
 };
 
-exports.runTest = function(suiteName, testName) {
+exports.runTest = function (suiteName, testName) {
     const testSuite = TESTS[suiteName];
     const testMethod = testSuite && testSuite[testName];
 
     if (testMethod) {
         Realm.clearTestState();
-        console.warn("Starting test " + testName);
         return testMethod.call(testSuite);
     }
     if (!testSuite || !(testName in SPECIAL_METHODS)) {

tests/js/notifier-tests.ts

@@ -88,7 +88,6 @@ function addAvailableListener(regex, ros, expectedRealms = undefined) {
     return new Promise(async (resolve, reject) => {
         let timeout;
         const callback = (path) => {
-            console.log('callback', path);
             if (expectedRealms) {
                 for (let i = 0; i < expectedRealms.length; i++) {
                     if (!path.match(notificationFilterPrefix + expectedRealms[i])) {
@@ -193,10 +192,6 @@ describe('Notifier', () => {
         Realm.clearTestState();
         this.tmpListenerDir = tmp.dirSync({ unsafeCleanup: true });
         Realm.Sync.setListenerDirectory(this.tmpListenerDir.name);
-        Realm.Sync.setSyncLogger((level, message) => {
-            console.log('test-client: %s', message);
-        });
-        Realm.Sync.setLogLevel('info');
 
         if (useTestServer) {
             rosController = new TestObjectServer();
@@ -802,10 +797,6 @@ describe('Multi-process Notifier', () => {
         this.tmpIpcDir = tmp.dirSync({ unsafeCleanup: true });
         tmpIpcPath = this.tmpIpcDir.name + '/test.realm';
         Realm.Sync.setListenerDirectory(this.tmpListenerDir.name);
-        Realm.Sync.setSyncLogger((level, message) => {
-            console.log('test-client: %s', message);
-        });
-        Realm.Sync.setLogLevel('info');
 
         worker = new Realm.Worker(__dirname + '/support/notification-worker.ts', {
             execArgv: ['-r', 'ts-node/register'],

tests/js/open-behavior-tests.js

@@ -25,8 +25,6 @@ const TestCase = require('./asserts');
 const schemas = require('./schemas');
 const Utils = require('./test-utils');
 
-Realm.Sync.setLogLevel('debug');
-
 // Returns a user that looks valid but isn't able to establish a connection to the server
 function getLoggedOutUser() {
     return Realm.Sync.User.login('http://127.0.0.1:9080', Realm.Sync.Credentials.nickname("admin", true))

tests/js/session-tests.js

@@ -22,7 +22,11 @@
 
 /* global REALM_MODULE_PATH */
 
+// Run these tests with the `DEBUG=tests:session` environment variable set to get the stdout of sub-processes.
+
+const debug = require('debug')('tests:session');
 const Realm = require('realm');
+
 const TestCase = require('./asserts');
 const Utils = require('./test-utils');
 let schemas = require('./schemas');
@@ -59,17 +63,17 @@ function copyFileToTempDir(filename) {
 function runOutOfProcess() {
     const args = Array.prototype.slice.call(arguments);
     let tmpDir = tmp.dirSync();
-    console.log(`runOutOfProcess : ${args.join(' ')}`);
+    debug(`runOutOfProcess : ${args.join(' ')}`);
     return new Promise((resolve, reject) => {
         try {
-            execFile(process.execPath, args, {cwd: tmpDir.name}, (error, stdout, stderr) => {
+            execFile(process.execPath, args, { cwd: tmpDir.name }, (error, stdout, stderr) => {
                 if (error) {
                     console.error("runOutOfProcess failed\n", error, stdout, stderr);
                     reject(new Error(`Running ${args[0]} failed. error: ${error}`));
                     return;
                 }
 
-                console.log('runOutOfProcess success\n' + stdout);
+                debug('runOutOfProcess success\n' + stdout);
                 resolve();
             });
         }

tests/js/support/test-object-server.js

@@ -99,7 +99,6 @@ global.TestObjectServer = module.exports = class TestObjectServer extends EventE
     constructor() {
         super();
         const SyncServer = require('realm-sync-server').RealmSyncServer;
-        Realm.Sync.setLogLevel('error');
 
         this._key = new NodeRSA({b: 2048});
         this.adminToken = signAdminToken(this._key, token);

tests/package.json

@@ -4,13 +4,16 @@
   "private": true,
   "dependencies": {
     "@types/jasmine": "^3.3.9",
+    "debug": "^4.1.1",
     "es6-promise": "^3.2.1",
+    "http-proxy": "^1.18.0",
     "jasmine": "^3.4.0",
     "jasmine-console-reporter": "^3.1.0",
     "jasmine-spec-reporter": "^4.2.1",
     "jasmine-xml-reporter": "^1.2.1",
     "jsonwebtoken": "^8.5.1",
     "needle": "^1.3.0",
+    "node-rsa": "^1.0.6",
     "segfault-handler": "^1.3.0",
     "spawn-sync": "^2.0.0",
     "terminate": "^1.0.8",

tests/spec/helpers/realm-logging.js

@@ -0,0 +1,38 @@
+"use strict";
+
+const debug = require('debug');
+
+const REALM_LOG_LEVELS = ['all', 'trace', 'debug', 'detail', 'info', 'warn', 'error', 'fatal', 'off'];
+const realmDebug = debug('realm');
+
+/**
+ * Sets up the Realm.Sync logger and log level
+ */
+function setupLogging(Realm) {
+    Realm.Sync.setLogger((level, message) => {
+        const levelName = REALM_LOG_LEVELS[level];
+        realmDebug(`[${levelName}] ${message}`);
+    });
+    // Set the log level if running on NodeJS
+    if (process && process.env) {
+        Realm.Sync.setLogLevel(process.env.REALM_LOG_LEVEL || 'info');
+    }
+}
+
+function patch(Realm) {
+    // Run only if Realm was build with sync enabled.
+    if (Realm.Sync) {
+        // Monkey-patching clearTestState, because the sync sessions logger gets reset.
+        // @see https://github.com/realm/realm-object-store/blob/d7e0867626a6868749e7e8bf55c64c6fbb2e3189/src/sync/sync_manager.cpp#L239-L240
+        const originalClearTestState = Realm.clearTestState;
+        Realm.clearTestState = function patchedClearTestState() {
+            originalClearTestState.call(Realm);
+            setupLogging(Realm);
+        }
+
+        // Setup the logger initially
+        setupLogging(Realm);
+    }
+}
+
+module.exports = { patch };

tests/spec/helpers/reporters.js

@@ -1,11 +1,12 @@
 'use strict';
 
 const jasmineReporters = require('jasmine-reporters');
-const SpecReporter = require('jasmine-spec-reporter').SpecReporter;
+const { SpecReporter } = require('jasmine-spec-reporter');
 
+jasmine.getEnv().clearReporters();
 jasmine.getEnv().addReporter(new jasmineReporters.JUnitXmlReporter({
-    savePath: '.',
-    consolidateAll: false
+  savePath: '.',
+  consolidateAll: false
 }));
 jasmine.getEnv().addReporter(new SpecReporter({
   spec: {