Skip to content

Add support for replaying logs happen on async server operations#440

Merged
AbanoubGhadban merged 26 commits intomasterfrom
abanoubghadban/pro439-add-support-for-replaying-logs-happen-on-async-server-operations
Nov 1, 2024
Merged

Add support for replaying logs happen on async server operations#440
AbanoubGhadban merged 26 commits intomasterfrom
abanoubghadban/pro439-add-support-for-replaying-logs-happen-on-async-server-operations

Conversation

@AbanoubGhadban
Copy link
Copy Markdown
Contributor

@AbanoubGhadban AbanoubGhadban commented Sep 24, 2024

Summary

This PR introduces support for replaying console logs generated during asynchronous server operations.

Example

Consider the following server-rendered React component (adapted from the SetTimeoutLoggingApp in the dummy app):

import React from 'react';
import { renderToString } from 'react-dom/server';

export default async (_props, _railsContext) => {
  console.log('Console log from SetTimeoutLoggingApp.server.jsx');

  const delayedValue = await new Promise((resolve) => {
    setTimeout(() => {
      console.log('Console log from setTimeout in SetTimeoutLoggingApp.server.jsx');
    }, 1);

    setTimeout(() => {
      console.log('Console log from setTimeout100 in SetTimeoutLoggingApp.server.jsx');
      resolve('this value is set by setTimeout during SSR');
    }, 100);
  });

  const element = <div>Disable javascript in your browser options to confirm {delayedValue}.</div>;
  return renderToString(element);
};

Before
Only the first log ('Console log from SetTimeoutLoggingApp.server.jsx') is replayed on the client side. Logs occurring after any async operations (such as promises or timeouts) were not replayed.
After
All log statements, including those inside asynchronous operations, are now replayed on the client side.

Previous Limitation: Why Async Console Logs Were Not Replayed

  • The Node.js renderer uses the vm module to parse the server bundle and perform server-side rendering of components.
  • Instead of creating a new vm for each rendering request, the renderer creates a single vm, parses the server bundle once, and reuses it across subsequent requests.
  • This design prevents the use of global variables for storing user-specific data, as they persist between renders (to optimize performance, heap data is not cleared).
  • Due to this, the console.history global variable was cleared after the initial synchronous render to avoid data leakage between rendering processes. As a result, console logs from asynchronous operations were lost.

Solution: How the Issue Is Addressed

  • The issue is resolved by leveraging the AsyncLocalStorage module in Node.js.
  • This module enables isolated local storage for each asynchronous operation, allowing us to capture and replay all console logs, even those triggered during async operations, without risking data leakage between renders.

This is an example of using AsyncLocalStorage to separate the local storage of each async operation

const store = { id: 2 };
try {
  asyncLocalStorage.run(store, () => {
    asyncLocalStorage.getStore(); // Returns the store object
    setTimeout(() => {
      asyncLocalStorage.getStore(); // Returns the store object
    }, 200);
    throw new Error();
  });
} catch (e) {
  asyncLocalStorage.getStore(); // Returns undefined
  // The error will be caught here
} 

AsyncLocalStorage Performance Impact

Using AsyncLocalStorage introduces some overhead when creating new async contexts, such as with promises or timeouts. This is particularly noticeable in older Node.js versions (e.g., Node.js 12), where creating async contexts had significant overhead, as detailed in this issue. Starting with Node.js 14, this overhead has been reduced by about 50%.

However, it's important to note that this benchmark focuses on extreme cases (e.g., creating promises without doing significant work). To provide more realistic insight into performance, I conducted the following benchmarks that show minimal impact when using AsyncLocalStorage for various types of workloads:

I/O-Bound Operations Benchmark

const { AsyncLocalStorage } = require('async_hooks');
const asyncLocalStorage = new AsyncLocalStorage();
const fs = require('fs').promises;

let ioBoundTask = async () => {
  const data = 'a'.repeat(1024 * 1024); // 1 MB of data
  await fs.writeFile('/tmp/test.txt', data);
  await fs.readFile('/tmp/test.txt');
};

let runWithExpiry = async (expiry, fn) => {
  let iterations = 0;
  while (Date.now() < expiry) {
    await fn();
    iterations++;
  }
  return iterations;
};

(async () => {
  console.log(`Warming up...`);
  await runWithExpiry(Date.now() + 1000, ioBoundTask);

  let withoutAls = await runWithExpiry(Date.now() + 1000, ioBoundTask);
  console.log(`I/O-bound task without ALS: ${withoutAls} iterations`);

  let withAls = await asyncLocalStorage.run({}, () => runWithExpiry(Date.now() + 1000, ioBoundTask));
  console.log(`I/O-bound task with ALS: ${withAls} iterations`);

  console.log(
    'ALS penalty (I/O-bound): ' +
      Math.round((1 - withAls / withoutAls) * 10000) / 100 +
      '%'
  );
})();

Results: The penalty ranges between -5% to +5%, indicating no significant performance impact, with variations likely caused by disk response times.

CPU-Bound Operations Benchmark

const { AsyncLocalStorage } = require('async_hooks');

const fib = (n) => (n <= 1 ? n : fib(n - 1) + fib(n - 2));

let cpuBoundTask = async () => fib(25);

let runWithExpiry = async (expiry, fn) => {
  let iterations = 0;
  while (Date.now() < expiry) {
    await fn();
    iterations++;
  }
  return iterations;
};

(async () => {
  console.log(`Warming up...`);
  await runWithExpiry(Date.now() + 200, cpuBoundTask);

  let withoutAls = await runWithExpiry(Date.now() + 2000, cpuBoundTask);
  console.log(`CPU-bound task without ALS: ${withoutAls} iterations`);

  const asyncLocalStorage = new AsyncLocalStorage();
  let withAls = await asyncLocalStorage.run({}, () => runWithExpiry(Date.now() + 2000, cpuBoundTask));
  console.log(`CPU-bound task with ALS: ${withAls} iterations`);

  console.log(
    'ALS penalty (CPU-bound): ' +
      Math.round((1 - withAls / withoutAls) * 10000) / 100 +
      '%'
  );
})();

Results: The penalty consistently shows 0%, meaning AsyncLocalStorage has no measurable impact on CPU-bound tasks.

Network-Bound Operations Benchmark

const { AsyncLocalStorage } = require('async_hooks');
const asyncLocalStorage = new AsyncLocalStorage();
const http = require('http');

const PORT = 3000;
let requestCount = 0;

const server = http.createServer((req, res) => {
  asyncLocalStorage.run({}, () => {
    res.end('Hello World');
    requestCount++;
  });
});

server.listen(PORT, async () => {
  console.log(`Server is listening on port ${PORT}`);

  const makeRequests = async (duration) => {
    let iterations = 0;
    const expiry = Date.now() + duration;
    while (Date.now() < expiry) {
      await new Promise((resolve, reject) => {
        http.get(`http://0.0.0.0:${PORT}`, (res) => {
          res.on('data', () => {});
          res.on('end', () => resolve());
          res.on('error', (error) => reject(error));
        }).on('error', (error) => reject(error));
      });
      iterations++;
    }
    return iterations;
  };

  // Warm-up
  await makeRequests(1000);

  // With ALS
  requestCount = 0;
  let withAlsIterations = await asyncLocalStorage.run({}, () => makeRequests(1000));
  console.log(
    `HTTP requests with ALS: ${withAlsIterations} iterations, ${requestCount} requests handled`
  );

  // Without ALS
  asyncLocalStorage.disable();
  requestCount = 0;
  let withoutAlsIterations = await makeRequests(1000);
  console.log(
    `HTTP requests without ALS: ${withoutAlsIterations} iterations, ${requestCount} requests handled`
  );

  console.log(
    'ALS penalty (HTTP server): ' +
      Math.round(
        (1 - withAlsIterations / withoutAlsIterations) * 10000
      ) /
        100 +
      '%'
  );

  server.close(() => {
    console.log('Server closed');
  });
});

Results: The penalty ranges between -5% and +5%, showing no significant performance impact.

Mixed Workload Benchmark

const { AsyncLocalStorage } = require('async_hooks');
const fs = require('fs').promises;

let mixedTask = async () => {
  // CPU-bound operation
  fib(20);

  // I/O-bound operation
  const data = 'a'.repeat(200 * 1024); // 200 KB of data
  await fs.writeFile('/tmp/test.txt', data);
  await fs.readFile('/tmp/test.txt');
};

const fib = (n) => (n <= 1 ? n : fib(n - 1) + fib(n - 2));

let runWithExpiry = async (expiry, fn) => {
  let iterations = 0;
  while (Date.now() < expiry) {
    await fn();
    iterations++;
  }
  return iterations;
};

(async () => {
  console.log(`Warming up...`);
  await runWithExpiry(Date.now() + 1000, mixedTask);

  let withoutAls = await runWithExpiry(Date.now() + 1000, mixedTask);
  console.log(`Mixed task without ALS: ${withoutAls} iterations`);

  const asyncLocalStorage = new AsyncLocalStorage();
  let withAls = await asyncLocalStorage.run({}, () => runWithExpiry(Date.now() + 1000, mixedTask));
  console.log(`Mixed task with ALS: ${withAls} iterations`);

  console.log(
    'ALS penalty (Mixed workload): ' +
      Math.round((1 - withAls / withoutAls) * 10000) / 100 +
      '%'
  );
})();

Results: The penalty varies between -3% and +3%, showing negligible impact for mixed workloads.

Result

Across various benchmarks (I/O-bound, CPU-bound, network-bound, and mixed workloads), the use of AsyncLocalStorage exhibits little to no significant performance penalty. These variations are within acceptable limits and are often due to system factors like disk or network response times. Therefore, the benefits of using AsyncLocalStorage in ensuring proper isolation and log replaying for async operations outweigh the minimal performance overhead observed. Also, to ignore the performance problem completely, we can enable this logging feature in development only.

Summary by CodeRabbit

Release Notes

  • New Features
    • Introduced a new configuration option for replaying console logs from asynchronous operations.
    • Added a new page and React component for displaying console logs in asynchronous server operations.
    • Enhanced console history management within the rendering context.
  • Bug Fixes
    • Increased server-side rendering timeout duration.
  • Documentation
    • Updated CHANGELOG to reflect new features and changes.
  • Dependencies
    • Upgraded react-on-rails dependency to version 15.0.0-alpha.1.

@coderabbitai
Copy link
Copy Markdown

coderabbitai Bot commented Sep 24, 2024

Walkthrough

The changes in this pull request primarily involve updates to the react_on_rails gem and the introduction of new functionality related to console log management in asynchronous server operations. The gem version has been upgraded across multiple files, reflecting a shift to a newer alpha version. Additionally, new classes and components have been added to manage console history, and tests have been implemented to ensure proper handling of console logs in various scenarios. Configuration options for logging behavior have also been enhanced.

Changes

File Path Change Summary
Gemfile.development_dependencies Updated react_on_rails version from 14.0.4 to 15.0.0.alpha.1 and commented out local path.
packages/node-renderer/src/worker/vm.ts Added SharedConsoleHistory instance, removed replayVmConsole, updated buildVM and runInVM.
packages/node-renderer/src/shared/configBuilder.ts Added NODE_ENV constant and replayServerAsyncOperationLogs property to Config interface.
packages/node-renderer/src/shared/sharedConsoleHistory.ts Introduced SharedConsoleHistory class with methods for managing console messages and history.
packages/node-renderer/tests/vm.test.ts Added tests for console log handling in async operations.
spec/dummy/client/app/ror-auto-load-components/SetTimeoutLoggingApp.server.jsx Modified async function to manage console logs with two setTimeout calls.
spec/dummy/package.json Updated react-on-rails version from 14.0.4 to 15.0.0-alpha.1.
spec/dummy/app/controllers/pages_controller.rb Added console_logs_in_async_server method to PagesController.
spec/dummy/app/views/pages/pro/console_logs_in_async_server.html.erb Created new HTML template for console logs in async server operations.
spec/dummy/app/views/shared/_menu.erb Added link to "Console Logs in Async Server" in the menu.
spec/dummy/client/app/components/ConsoleLogsInAsyncServer.jsx Introduced ConsoleLogsInAsyncServer component for displaying console logs.
spec/dummy/client/app/ror-auto-load-components/ConsoleLogsInAsyncServer.client.jsx Created client component that renders ConsoleLogsInAsyncServer.
spec/dummy/client/app/ror-auto-load-components/ConsoleLogsInAsyncServer.server.jsx Added server-side rendering function for ConsoleLogsInAsyncServer.
spec/dummy/client/node-renderer.js Added replayServerAsyncOperationLogs configuration option.
spec/dummy/config/initializers/react_on_rails_pro.rb Updated ssr_timeout from 1 to 10.
spec/dummy/config/routes.rb Added route for console_logs_in_async_server.
CHANGELOG.md Updated with new features and changes, including console log replay support.
package.json Updated react-on-rails version from 14.0.4 to 15.0.0-alpha.1.
packages/node-renderer/src/shared/utils.ts Added isPromise function to check if a value is a Promise.
packages/node-renderer/tests/fixtures/projects/spec-dummy/e5e10d1/consoleLogsInAsyncServerRequest.js Introduced IIFE for server-side rendering of ConsoleLogsInAsyncServer.
react_on_rails_pro.gemspec Updated runtime dependency for react_on_rails to >= 15.0.0.alpha.1.
spec/execjs-compatible-dummy/Gemfile Updated react_on_rails gem version from 14.0.4 to 15.0.0.alpha.1.
spec/execjs-compatible-dummy/package.json Updated react-on-rails version from 14.0.4 to 15.0.0-alpha.1.

Poem

🐇
In the code where rabbits play,
New gems hop in, bright as day.
With logs that dance and history kept,
Async whispers, secrets swept.
A leap of joy, a code delight,
For every change, our hearts take flight!
🌟


📜 Recent review details

Configuration used: CodeRabbit UI
Review profile: CHILL

📥 Commits

Reviewing files that changed from the base of the PR and between 2f5fcca and 155c1f9.

⛔ Files ignored due to path filters (1)
  • spec/dummy/yarn.lock is excluded by !**/yarn.lock, !**/*.lock
📒 Files selected for processing (1)
  • spec/dummy/package.json (3 hunks)

Note

🎁 Summarized by CodeRabbit Free

Your organization is on the Free plan. CodeRabbit will generate a high-level summary and a walkthrough for each pull request. For a comprehensive line-by-line review, please upgrade your subscription to CodeRabbit Pro by visiting https://app.coderabbit.ai/login.

🪧 Tips

Chat

There are 3 ways to chat with CodeRabbit:

  • Review comments: Directly reply to a review comment made by CodeRabbit. Example:
    • I pushed a fix in commit <commit_id>, please review it.
    • Generate unit testing code for this file.
    • Open a follow-up GitHub issue for this discussion.
  • Files and specific lines of code (under the "Files changed" tab): Tag @coderabbitai in a new review comment at the desired location with your query. Examples:
    • @coderabbitai generate unit testing code for this file.
    • @coderabbitai modularize this function.
  • PR comments: Tag @coderabbitai in a new PR comment to ask questions about the PR branch. For the best results, please provide a very specific query, as very limited context is provided in this mode. Examples:
    • @coderabbitai gather interesting stats about this repository and render them as a table. Additionally, render a pie chart showing the language distribution in the codebase.
    • @coderabbitai read src/utils.ts and generate unit testing code.
    • @coderabbitai read the files in the src/scheduler package and generate a class diagram using mermaid and a README in the markdown format.
    • @coderabbitai help me debug CodeRabbit configuration file.

Note: Be mindful of the bot's finite context window. It's strongly recommended to break down tasks such as reading entire modules into smaller chunks. For a focused discussion, use review comments to chat about specific files and their changes, instead of using the PR comments.

CodeRabbit Commands (Invoked using PR comments)

  • @coderabbitai pause to pause the reviews on a PR.
  • @coderabbitai resume to resume the paused reviews.
  • @coderabbitai review to trigger an incremental review. This is useful when automatic reviews are disabled for the repository.
  • @coderabbitai full review to do a full review from scratch and review all the files again.
  • @coderabbitai summary to regenerate the summary of the PR.
  • @coderabbitai resolve resolve all the CodeRabbit review comments.
  • @coderabbitai configuration to show the current CodeRabbit configuration for the repository.
  • @coderabbitai help to get help.

Other keywords and placeholders

  • Add @coderabbitai ignore anywhere in the PR description to prevent this PR from being reviewed.
  • Add @coderabbitai summary to generate the high-level summary at a specific location in the PR description.
  • Add @coderabbitai anywhere in the PR title to generate the title automatically.

CodeRabbit Configuration File (.coderabbit.yaml)

  • You can programmatically configure CodeRabbit by adding a .coderabbit.yaml file to the root of your repository.
  • Please see the configuration documentation for more information.
  • If your editor has YAML language server enabled, you can add the path at the top of this file to enable auto-completion and validation: # yaml-language-server: $schema=https://coderabbit.ai/integrations/schema.v2.json

Documentation and Community

  • Visit our Documentation for detailed information on how to use CodeRabbit.
  • Join our Discord Community to get help, request features, and share feedback.
  • Follow us on X/Twitter for updates and announcements.

Comment thread .circleci/config.yml Outdated
keys:
- v4-package-app-gem-cache-{{ checksum "react_on_rails_pro.gemspec" }}

# Restore react-on-rails from cache
Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ignore all changes in this file, it will be reverted after merging the React on Rails part of this PR.

Comment thread Gemfile.development_dependencies Outdated
ruby '3.3.0'

gem "react_on_rails", "14.0.4" # keep in sync with package.json files
# gem "react_on_rails", "14.0.4" # keep in sync with package.json files
Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ignore all changes in this file, it will be reverted after merging the React on Rails part of this PR.

Comment thread Gemfile.lock Outdated
byebug (~> 11.0)
pry (>= 0.13, < 0.15)

PATH
Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ignore all changes in this file, it will be reverted after merging the React on Rails part of this PR.

Comment thread spec/dummy/Gemfile.lock Outdated
byebug (~> 11.0)
pry (>= 0.13, < 0.15)

PATH
Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ignore all changes in this file, it will be reverted after merging the React on Rails part of this PR.

Comment thread spec/dummy/package.json Outdated
"react-dom": "^18.2.0",
"react-helmet": "^6.0.0-beta.2",
"react-on-rails": "14.0.4",
"react-on-rails": "link:.yalc/react-on-rails",
Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ignore all changes in this file, it will be reverted after merging the React on Rails part of this PR.

Comment thread spec/dummy/yarn.lock Outdated
integrity sha512-/uyC7X5NAJV29Nwr9nVKnmNcWo2yire/PPeWbelZ7gjmgnmJJyykL16OZeDfs8IUMIIbpwPIBkno/1hP7ksTIA==
dependencies:
"@babel/runtime-corejs3" "^7.12.5"
"react-on-rails@link:.yalc/react-on-rails":
Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ignore all changes in this file, it will be reverted after merging the React on Rails part of this PR.

@AbanoubGhadban AbanoubGhadban requested review from Judahmeek, alexeyr-ci and justin808 and removed request for alexeyr-ci September 26, 2024 05:32
Comment thread packages/node-renderer/src/worker/vm.ts
Comment thread packages/node-renderer/src/worker/vm.ts Outdated
return vmBundleFilePath;
}

function replayVmConsole() {
Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

moved to sharedConsoleHistory.ts

Comment thread packages/node-renderer/src/shared/configBuilder.ts Outdated
Comment thread packages/node-renderer/src/shared/sharedConsoleHistory.ts
Comment thread packages/node-renderer/src/shared/sharedConsoleHistory.ts Outdated
Comment thread packages/node-renderer/tests/vm.test.ts Outdated
Comment thread packages/node-renderer/tests/vm.test.ts Outdated
Comment thread packages/node-renderer/src/shared/sharedConsoleHistory.ts
Comment thread packages/node-renderer/src/shared/configBuilder.ts Outdated
AbanoubGhadban added a commit to shakacode/react_on_rails that referenced this pull request Oct 20, 2024
Console replay script generation now awaits the render request promise before generating, allowing it to capture console logs from asynchronous operations. The feature of replaying async console logs is implemented in node-renderer in this PR
shakacode/react_on_rails_pro#440

* add support for console replay of console logs happen in async operations

get console replay messages after promise resolves or rejects

use isPromise to check if the result is a promise

make consoleReplay function accept the list of logs to be added to the script

make consoleHistory argument of consoleReplay optional

add comments

add comments

update comment

remove FlowFixMe comment

* call clear console history from the generated render code

* Revert "call clear console history from the generated render code"

This reverts commit 2697ef7.

* add comment about clearing console history
@AbanoubGhadban AbanoubGhadban merged commit 84554b3 into master Nov 1, 2024
@AbanoubGhadban AbanoubGhadban deleted the abanoubghadban/pro439-add-support-for-replaying-logs-happen-on-async-server-operations branch November 1, 2024 13:44
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants