3. Strange EPIPE write error

Strange EPIPE write error

  • M

    Hello!

    jsReport version: ^3.1.1

    Recently we have been seeing a peculiar issue. We currently have a web page that gathers some parameters to use as report parameters later on. We then create a file stream on the server using fs.createWriteStream with all default options. We then call our jsReport server's /api/report endpoint via a POST request to render a report and .pipe that response output to our WriteStream object we created earlier. See code snippet below:

    let exportReport = (req, res, next) => {
    let dataObj = req.body || {};
    let fName = `${req.body['options']['title']}-${new Date().toDateString()}.${req.body['options']['extn'] ||'xlsx'}`;
    let ws = fs.createWriteStream(`./temp/${fName}`); // writeable stream
    ws.on('error', (err) => {
        next(err);
    });
    ws.on('finish', () => {
        setTimeout(function() {
            fs.unlink(ws.path, (delErr) => {});
        }, 120000); //delete file after 2 mins
        return res.send(`/tmp/${fName}`);
    });

    request.post({
        headers: {'Content-Type': 'application/json'},
        url: `${jsReportUrl}/api/report`,
        body: JSON.stringify(dataObj)
    }).on('error', (err) => {
        next(err);
    }).pipe(ws);
};

    This all works well and good most of the time. The problem we've been seeing is that sometimes this will fail. The file that gets created on disk will have 0 bytes written to it and the response for this exportRpt function never gets sent. There seems to be a consistent error that is popping up when it does happen: error: uncaughtException: EPIPE: broken pipe, write. We've also noticed it has most recently been happening on Mondays, though checking the error logs reveals that it's not always Mondays, sometimes it was happening on just Tuesdays, other times on just Wednesdays.

    At the same time as this EPIPE error, the jsReport log will look something like this:

    ...
2023-07-23T20:06:40.552Z - info: reporter initialized
2023-07-23T20:06:53.876Z - info: Starting rendering request 1 (user: null) rootId=o130d53vua1o29w, id=o130d53vua1o29w
2023-07-23T20:06:53.877Z - info: Rendering template { name: PortalReportsXlsx, recipe: xlsx, engine: handlebars, preview: false } rootId=o130d53vua1o29w, id=o130d53vua1o29w
2023-07-23T20:07:00.647Z - info: Rendering request 1 finished in 6857 ms rootId=o130d53vua1o29w, id=o130d53vua1o29w
2023-07-24T14:59:32.510Z - info: Starting rendering request 2 (user: null) rootId=eoovg79j2wcrvh3, id=eoovg79j2wcrvh3
2023-07-24T15:00:40.596Z - info: Initializing jsreport (version: 3.2.0, configuration file: jsreport.config.json, nodejs: 16.13.1)
2023-07-24T15:00:40.599Z - info: Searching for available extensions in ****
...

    Rendering request 2 is the one that fails in this instance. Notice the timestamps of rendering request 1 and 2, and also notice that right after rendering request 2 is made, jsReport begins to re-initialize itself. Once jsReport has re-initialized itself, the report will generate correctly, write to the file on disk, and send the response.

    We've been trying to figure this issue out for the past couple of weeks, but since it seems to be happening so infrequently, it's hard to identify the steps to reproduce the failure. Any help with this issue would be greatly appreciated!

    I'll post the relevant section of the error log below for reference:

    ...
2023-07-24T14:59:32.524Z - error: uncaughtException: EPIPE: broken pipe, write
Error: EPIPE: broken pipe, write
    at Socket._write (node:internal/net:55:25)
    at writeOrBuffer (node:internal/streams/writable:389:12)
    at _write (node:internal/streams/writable:330:10)
    at Socket.Writable.write (node:internal/streams/writable:334:10)
    at Console.log (****\node_modules\@jsreport\jsreport-core\node_modules\winston\lib\winston\transports\console.js:79:23)
    at Console._write (****\node_modules\winston-transport\index.js:103:17)
    at doWrite (****\node_modules\winston-transport\node_modules\readable-stream\lib\_stream_writable.js:428:64)
    at writeOrBuffer (****\node_modules\winston-transport\node_modules\readable-stream\lib\_stream_writable.js:417:5)
    at Console.Writable.write (****\node_modules\winston-transport\node_modules\readable-stream\lib\_stream_writable.js:334:11)
    at DerivedLogger.ondata (****\node_modules\@jsreport\jsreport-core\node_modules\readable-stream\lib\_stream_readable.js:681:20)
    at DerivedLogger.emit (node:events:402:35)
    at addChunk (****\node_modules\@jsreport\jsreport-core\node_modules\readable-stream\lib\_stream_readable.js:298:12)
    at readableAddChunk (****\node_modules\@jsreport\jsreport-core\node_modules\readable-stream\lib\_stream_readable.js:280:11)
    at DerivedLogger.Readable.push (****\node_modules\@jsreport\jsreport-core\node_modules\readable-stream\lib\_stream_readable.js:241:10)
    at DerivedLogger.Transform.push (****\node_modules\@jsreport\jsreport-core\node_modules\readable-stream\lib\_stream_transform.js:139:32)
    at DerivedLogger._transform (****\node_modules\@jsreport\jsreport-core\node_modules\winston\lib\winston\logger.js:305:12) error=Error: EPIPE: broken pipe, write, stack=Error: EPIPE: broken pipe, write
    at Socket._write (node:internal/net:55:25)
    at writeOrBuffer (node:internal/streams/writable:389:12)
    at _write (node:internal/streams/writable:330:10)
    at Socket.Writable.write (node:internal/streams/writable:334:10)
    at Console.log (****\node_modules\@jsreport\jsreport-core\node_modules\winston\lib\winston\transports\console.js:79:23)
    at Console._write (****\node_modules\winston-transport\index.js:103:17)
    at doWrite (****\node_modules\winston-transport\node_modules\readable-stream\lib\_stream_writable.js:428:64)
    at writeOrBuffer (****\node_modules\winston-transport\node_modules\readable-stream\lib\_stream_writable.js:417:5)
    at Console.Writable.write (****\node_modules\winston-transport\node_modules\readable-stream\lib\_stream_writable.js:334:11)
    at DerivedLogger.ondata (****\node_modules\@jsreport\jsreport-core\node_modules\readable-stream\lib\_stream_readable.js:681:20)
    at DerivedLogger.emit (node:events:402:35)
    at addChunk (****\node_modules\@jsreport\jsreport-core\node_modules\readable-stream\lib\_stream_readable.js:298:12)
    at readableAddChunk (****\node_modules\@jsreport\jsreport-core\node_modules\readable-stream\lib\_stream_readable.js:280:11)
    at DerivedLogger.Readable.push (****\node_modules\@jsreport\jsreport-core\node_modules\readable-stream\lib\_stream_readable.js:241:10)
    at DerivedLogger.Transform.push (****\node_modules\@jsreport\jsreport-core\node_modules\readable-stream\lib\_stream_transform.js:139:32)
    at DerivedLogger._transform (****\node_modules\@jsreport\jsreport-core\node_modules\winston\lib\winston\logger.js:305:12), exception=true, date=Mon Jul 24 2023 07:59:32 GMT-0700 (Pacific Daylight Time), process=[object Object], os=[object Object], trace=[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object]
...
    0

  • This could be an error in the logging library jsreport use
    https://github.com/winstonjs/winston/issues/1920

    It seems it isn't addressed, but it could help to disable the console/stdout logger.
    In jsreport configuration, do the following update

    "logger": {
    "console": {
      "transport": "console",
      "level": "debug",
      "enabled": false
    }
  }
    0
  • M

    Hello,

    Sorry for the late reply! We made the suggested change in the jsreport.config.json file, however, when we restart the jsReport server so that it can grab the updated configuration information, we get a new error during jsReport initialization:

    2023-07-26T17:37:11.263Z - error: Error occurred during reporter init: DataCloneError: function Format(options = {}) {
    this.options = options;
  } could not be cloned.
    at new Worker (node:internal/worker:235:17)
    at createWorker (****\node_modules\@jsreport\advanced-workers\lib\workersManager.js:14:20)
    at createWorker (****\node_modules\@jsreport\advanced-workers\lib\workersManager.js:33:29)
    at ****\node_modules\@jsreport\advanced-workers\lib\pool.js:16:26
    at ****\node_modules\@jsreport\advanced-workers\lib\pool.js:21:52
    at Array.map (<anonymous>)
    at Object.init (****\node_modules\@jsreport\advanced-workers\lib\pool.js:21:42)
    at Object.init (****\node_modules\@jsreport\advanced-workers\lib\workersManager.js:37:24)
    at MainReporter.init (****\node_modules\@jsreport\jsreport-core\lib\main\reporter.js:256:34)

    We changed the logging back to how it was initially for the time being until we can pin the issue down.

    0

  • I see now you use a bit older version. In the 3.1.1 you need to use silent instead of enabled.

    "logger": {
    "console": {
      "transport": "console",
      "level": "debug",
      "silent": true
    }
    ...
  }
    0
  • M

    Hello,

    That seems to have worked! After disabling the console-level logging (but still having error-level logging enabled), we had another instance of this issue popping up. However, nothing is logged in our error log. Thus, we're assuming that this issue probably doesn't have anything to do with jsReport (possibly a locked file issue instead). We'll continue to monitor the issue but I get the feeling this may be being caused by stale filehandles, since we have also been getting EPERM errors as well related to this issue.

    Thank you for your help!

    0
Log in to reply
 

Looks like your connection to jsreport forum was lost, please wait while we try to reconnect.