steamroller used by log4js-node? #136

gee4vee · 2022-05-18T19:51:27Z

Does log4js use steamroller for log file rotation? We are getting a maximum call stack size exceeded error with steamroller calls but we don't explicitly use this package. We do use multiFile appender with a few backups.

"RangeError: Maximum call stack size exceeded
    at Object.mkdirSync (node:fs:1316:19)
    at mkdir (/Users/gvalenc/git/DevX/solutions-sdk-ts/node_modules/streamroller/lib/RollingFileWriteStream.js:246:19)
    at mkdir (/Users/gvalenc/git/DevX/solutions-sdk-ts/node_modules/streamroller/lib/RollingFileWriteStream.js:252:11)
    at mkdir (/Users/gvalenc/git/DevX/solutions-sdk-ts/node_modules/streamroller/lib/RollingFileWriteStream.js:253:18)
    at mkdir (/Users/gvalenc/git/DevX/solutions-sdk-ts/node_modules/streamroller/lib/RollingFileWriteStream.js:253:18)
    at mkdir (/Users/gvalenc/git/DevX/solutions-sdk-ts/node_modules/streamroller/lib/RollingFileWriteStream.js:253:18)
    at mkdir (/Users/gvalenc/git/DevX/solutions-sdk-ts/node_modules/streamroller/lib/RollingFileWriteStream.js:253:18)
    at mkdir (/Users/gvalenc/git/DevX/solutions-sdk-ts/node_modules/streamroller/lib/RollingFileWriteStream.js:253:18)
    at mkdir (/Users/gvalenc/git/DevX/solutions-sdk-ts/node_modules/streamroller/lib/RollingFileWriteStream.js:253:18)
    at mkdir (/Users/gvalenc/git/DevX/solutions-sdk-ts/node_modules/streamroller/lib/RollingFileWriteStream.js:253:18)"

The text was updated successfully, but these errors were encountered:

lamweili · 2022-05-19T04:13:10Z

Yes, log4js uses streamroller under the hood.

What's your Node.js version, log4js version and streamroller version?
- node -v
- node_modules/log4js/package.json
- node_modules/streamroller/package.json
Do you have a code snippet to reproduce the issue?

gee4vee · 2022-05-19T14:41:58Z

node v16.14.0
log4js ^6.4.4
streamroller 3.0.6

This is the code that configures log4js. We import this throughout the codebase whenever logging is needed and just use log4js.getLogger. We also use console.log sometimes for debugging.

import fs from 'fs';
import log4js from 'log4js';

if (fs.existsSync('log4js-config.json')) {
  log4js.configure('log4js-config.json');
} else {
  log4js.configure({
    appenders: {
      app: { type: 'file', filename: 'app.log' },
      out: { type: 'stdout' },
      multi: {
        type: 'multiFile',
        base: 'logs/',
        property: 'categoryName',
        extension: '.log',
        maxLogSize: 1024
      }
    },
    categories: {
      default: {
        appenders: [
          'app',
          'out',
          'multi'
        ],
        level: 'error'
      },
      parse: {
        appenders: [
          'app',
          'out',
          'multi'
        ],
        level: 'error'
      },
      validate: {
        appenders: [
          'app',
          'out',
          'multi'
        ],
        level: 'error'
      },
      cli: {
        appenders: [
          'app',
          'out',
          'multi'
        ],
        level: 'info'
      }
    }
  });
}

export default log4js;

When using a file configuration, we just copy that hard-coded config into a file.

gee4vee · 2022-05-19T15:34:47Z

If I take out the multiFile appender entirely I no longer get the error.

gee4vee · 2022-05-19T15:47:20Z

This configuration also cases the same error:

import fs from "fs";
import * as log4js from "log4js";

if (fs.existsSync("log4js-config.json")) {
  log4js.configure("log4js-config.json");
} else {
  log4js.configure({
    appenders: {
      sblsp: { type: "file", filename: `~/sblsp.log` },
      out: { type: "stdout" },
    },
    categories: {
      default: {
        appenders: ["sblsp", "out"],
        level: "debug",
      },
    },
  });
}

export default log4js;

lamweili · 2022-05-19T15:48:45Z

Did you have this issue previously prior to log4js@^6.4.4? Or is this a new project?
Trying to ascertain if this is a regression.
Would you mind running on [email protected] (which will run [email protected]) and see if the issue persists?
Perhaps it was fixed in the later versions. Try this in parallel while we debug together to save some time.
Now that we have the configuration codes, how can the error be triggered?
logger.getLogger() and try spamming some logs?

gee4vee · 2022-05-19T15:53:10Z

For simplicity I did not have a json file. So only the hard-coded config is being used when I last reproduced.

gee4vee · 2022-05-19T16:02:33Z

Tried with 6.4.7 and removing the if clause and it still reproduces. This is a new project. I dont think we've used prior versions.

lamweili · 2022-05-19T16:37:58Z

Which OS are you on?
Is the streamroller still [email protected]?
It happens when it attempts to roll?

gee4vee · 2022-05-19T17:24:46Z

macOS 12.3.1. With that latest config there's no multiFile appender, so I dont know if it's trying to roll. It did update to 3.0.9.

lamweili · 2022-05-19T17:44:11Z

Can you run the following as app.js file and see if the error happens?
Run with DEBUG=streamroller:RollingFileWriteStream for console verbosity.

Trying to see if it happens on the configure().
It will help if you can upload the screenshot.

`DEBUG=streamroller:RollingFileWriteStream node app.js`

// existing codes
import fs from "fs";
import * as log4js from "log4js";

log4js.configure({
  appenders: {
    sblsp: { type: "file", filename: `~/sblsp.log` },
    out: { type: "stdout" },
  },
  categories: {
    default: {
      appenders: ["sblsp", "out"],
      level: "debug",
    },
  },
});

If it didn't happen, add the following to the end of the file and try again.

// added codes
const logger = log4js.getLogger();
logger.info("Hello World");

gee4vee · 2022-05-19T20:34:14Z

I had to tweak the log4js import like so: import log4js from "log4js"; because I got TypeError: log4js.configure is not a function.

Here is the output. The first one is without a logger.info call and the 2nd is using the logger.info call that you provided. I do not see a ~/sblsp.log file.

~/D/D/p/s/log4js-test ⛅» node app.js                                                                       {15:32:34}
  streamroller:RollingFileWriteStream constructor: creating RollingFileWriteStream. path=~/sblsp.log +0ms
  streamroller:RollingFileWriteStream _parseOption: creating stream with option={"numToKeep":6,"encoding":"utf8","mode":384,"flags":"a","compress":false,"keepFileExt":false,"alwaysIncludePattern":false,"type":"file","filename":"~/sblsp.log","numBackups":5} +1ms
  streamroller:RollingFileWriteStream constructor: create new file ~/sblsp.log, state={"currentSize":0} +1ms
@   api:cloud   R:us-south
~/D/D/p/s/log4js-test ⛅» node app.js                                                                       {15:32:36}
  streamroller:RollingFileWriteStream constructor: creating RollingFileWriteStream. path=~/sblsp.log +0ms
  streamroller:RollingFileWriteStream _parseOption: creating stream with option={"numToKeep":6,"encoding":"utf8","mode":384,"flags":"a","compress":false,"keepFileExt":false,"alwaysIncludePattern":false,"type":"file","filename":"~/sblsp.log","numBackups":5} +2ms
  streamroller:RollingFileWriteStream constructor: create new file ~/sblsp.log, state={"currentSize":0} +0ms
[2022-05-19T15:32:52.874] [INFO] default - Hello World
  streamroller:RollingFileWriteStream _write: writing chunk. file=~/sblsp.log state={"currentSize":0} chunk=[2022-05-19T15:32:52.874] [INFO] default - Hello World
  streamroller:RollingFileWriteStream  +4ms

gee4vee · 2022-05-19T20:59:17Z

Btw, I created a separate NPM project when I ran that, not in our existing project which is a VS Code extension. If I try running our VS Code extension with the DEBUG env var set, I dont get any additional debug output, just the call stack error shortly after starting it up.

lamweili · 2022-05-20T05:39:41Z

I had to tweak the log4js import like so: import log4js from "log4js"; because I got TypeError: log4js.configure is not a function.

Strange, I copied and pasted from your original codes. Doesn't matter now since you got it resolved.

Here is the output. The first one is without a logger.info call and the 2nd is using the logger.info call that you provided. I do not see a ~/sblsp.log file.

Did any trigger the maximum call stack size exceeded error?

Run node in the current directory (where you run the DEBUG=streamroller:RollingFileWriteStream node app.js). Run the following command in the REPL and provide the output. I'm suspecting the ~ (tilde) is causing a problem on your OS.

// note: renamed the sblsp.log to sblsp.new.log to not interfere with previous tests
const filePath = `~/sblsp.new.log`;
const fileObj = path.parse(filePath);
fs.mkdirSync(fileObj.dir, {recursive: true});
fs.createWriteStream(filePath);

In the same directory, run the following command in terminal and provide the output.
This will verify the location of both the original sblsp.log (previous script) and the sblsp.new.log (in REPL).
```
# list *.log in the home directory
ls ~/*.log

# list all in the current directory
ls */
```

This is what I have on my RHEL 8.4. It created a ~ folder in the current directory instead of referring to home.
I didn't face any maximum call stack size exceeded errors.

# list *.log in the home directory
ls ~/*.log

> ls: cannot access '/home/user/*.log': No such file or directory

# list all in the current directory
ls */

> '~/':
> sblsp.log  sblsp.new.log

Lastly, to ascertain if it's ~ issue, try a pathing without tilde (such as ./sblsp.notilde.log).
See if the maximum call stack size exceeded error still persists

gee4vee · 2022-05-20T15:26:27Z

The sblsp.log file is getting generated in a ~ dir like you said. However I don't get the call stack error. When I run my VS Code extension, I do get the call stack error but I dont see a ~ folder.

If I use ./sblsp.log it generates as expected with your sample code but no call stack error. I get different errors in my VS Code extension but no call stack error. I think it is because the current working dir when running the extension is the root of the drive, for some reason:

�[32m[2022-05-20T10:25:01.681] [INFO] sblsp - �[39minitializing server
logger.ts: cwd = /
...
log4js.fileAppender - Writing to file sblsp.log, error happened  [Error: EROFS: read-only file system, open '/sblsp.log'] {
  errno: -30,
  code: 'EROFS',
  syscall: 'open',
  path: '/sblsp.log'
}
log4js.fileAppender - Writing to file sblsp.log, error happened  Error [ERR_STREAM_DESTROYED]: Cannot call write after a stream was destroyed
    at new NodeError (node:internal/errors:371:5)
    at errorBuffer (node:internal/streams/writable:517:14)
    at processTicksAndRejections (node:internal/process/task_queues:82:21) {
  code: 'ERR_STREAM_DESTROYED'
}

With the new code you provided, I get this error:

TypeError: fs.createFileStream is not a function

lamweili · 2022-05-20T17:15:09Z

My bad, it should have been fs.createWriteStream.
My butter fingers kept typing ~~fs.createFileStream~~. 😓

gee4vee · 2022-05-20T17:29:19Z

No problem. Using createWriteStream I see a new ~ directory with sblsp.new.log inside.

lamweili · 2022-05-20T18:03:10Z

Seems like the call stack error is unique to the VS Code extension together with the usage of ~/sblsp.log.
The tilde is not expanded as mentioned in the ~ tilde issue.
Some solutions are provided in place of ~, such as os.homedir() or third-party module like untildify.
Nevertheless, this seems like a good feature to have.

For the ./sblsp.log, you mentioned that the VS Code extension uses the root / directory as the working directory.
When it parses ./sblsp.log, it will attempt to create sblsp.log in the root directory /.
/ is by default 0o555 (r-xr-xr-x) which explains the EROFS error.
Either try to find out why, or you might want to provide the absolute pathing instead.

Out of curiosity, which VS Code extension is that?

gee4vee · 2022-05-20T18:56:26Z

It's one that we are working on internally. It is not yet open sourced. I will try a different path for now and see if the call stack error goes away.

lamweili · 2022-05-20T19:25:33Z

Keep me updated!

Maybe I should expand the tilde manually as a new feature.

gee4vee · 2022-05-20T20:02:23Z

So using os.homedir avoids the call stack error. Thanks for all the help. I think the tilde expansion would be a useful feature because there is no way for me to use tilde in a config JSON file. I have to use code to use os.homedir.

lamweili · 2022-05-22T11:04:03Z

[email protected] (changelog) and [email protected] (changelog) now supports tilde (~) expansions.

This was referenced May 22, 2022

feat: tilde expansion for filename log4js-node/log4js-node#1252

Merged

feat: tilde expansion for filename #135

Merged

lamweili transferred this issue from log4js-node/log4js-node May 22, 2022

lamweili closed this as completed May 22, 2022

lamweili added this to the 3.1.0 milestone Jun 2, 2022

lamweili added the enhancement New feature or request label Jun 2, 2022

gee4vee mentioned this issue Feb 14, 2023

Tilde expansion doesn't properly support Windows #164

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

steamroller used by log4js-node? #136

steamroller used by log4js-node? #136

gee4vee commented May 18, 2022 •

edited by lamweili

Loading

lamweili commented May 19, 2022

gee4vee commented May 19, 2022 •

edited by lamweili

Loading

gee4vee commented May 19, 2022

gee4vee commented May 19, 2022 •

edited by lamweili

Loading

lamweili commented May 19, 2022 •

edited

Loading

gee4vee commented May 19, 2022

gee4vee commented May 19, 2022

lamweili commented May 19, 2022

gee4vee commented May 19, 2022

lamweili commented May 19, 2022 •

edited

Loading

gee4vee commented May 19, 2022 •

edited

Loading

gee4vee commented May 19, 2022

lamweili commented May 20, 2022 •

edited

Loading

gee4vee commented May 20, 2022

lamweili commented May 20, 2022 •

edited

Loading

gee4vee commented May 20, 2022

lamweili commented May 20, 2022 •

edited

Loading

gee4vee commented May 20, 2022

lamweili commented May 20, 2022 •

edited

Loading

gee4vee commented May 20, 2022

lamweili commented May 22, 2022 •

edited

Loading

steamroller used by log4js-node? #136

steamroller used by log4js-node? #136

Comments

gee4vee commented May 18, 2022 • edited by lamweili Loading

lamweili commented May 19, 2022

gee4vee commented May 19, 2022 • edited by lamweili Loading

gee4vee commented May 19, 2022

gee4vee commented May 19, 2022 • edited by lamweili Loading

lamweili commented May 19, 2022 • edited Loading

gee4vee commented May 19, 2022

gee4vee commented May 19, 2022

lamweili commented May 19, 2022

gee4vee commented May 19, 2022

lamweili commented May 19, 2022 • edited Loading

DEBUG=streamroller:RollingFileWriteStream node app.js

gee4vee commented May 19, 2022 • edited Loading

gee4vee commented May 19, 2022

lamweili commented May 20, 2022 • edited Loading

gee4vee commented May 20, 2022

lamweili commented May 20, 2022 • edited Loading

gee4vee commented May 20, 2022

lamweili commented May 20, 2022 • edited Loading

gee4vee commented May 20, 2022

lamweili commented May 20, 2022 • edited Loading

gee4vee commented May 20, 2022

lamweili commented May 22, 2022 • edited Loading

gee4vee commented May 18, 2022 •

edited by lamweili

Loading

gee4vee commented May 19, 2022 •

edited by lamweili

Loading

gee4vee commented May 19, 2022 •

edited by lamweili

Loading

lamweili commented May 19, 2022 •

edited

Loading

lamweili commented May 19, 2022 •

edited

Loading

`DEBUG=streamroller:RollingFileWriteStream node app.js`

gee4vee commented May 19, 2022 •

edited

Loading

lamweili commented May 20, 2022 •

edited

Loading

lamweili commented May 20, 2022 •

edited

Loading

lamweili commented May 20, 2022 •

edited

Loading

lamweili commented May 20, 2022 •

edited

Loading

lamweili commented May 22, 2022 •

edited

Loading