CODEWITHSUNDEEP
node.jsjsonfs
ban_javascript
ban_javascript

Reputation: 347

Unexpected errors when rapidly writing to JSON files

I'm trying to implement JSON logs for my Node.js server; however, when I rapidly send requests, JSON.parse() throws errors. I believe that this may be caused by the concurrent reading and writing to my log file, as the fs methods are asynchronous.

One of the errors I received was:

SyntaxError: Unexpected end of JSON input

This would be fixed by slowing down the request rate.

However, other times, the JSON itself gained syntax errors, and the logs could not be parsed until I deleted them and restarted my server:

SyntaxError: Unexpected token [TOKEN] in JSON at position [POSITION]

Sometimes the end of the logs looked like this, ending with an extra ]:

[
    ...,
    {
        "ip": ...,
        "url": ...,
        "ua": ...
    }
]]

Or this:

[
    ...,
    {
        "ip": ...,
        "url": ...,
        "ua": ...
    }
]
]

This is a very simplified version of my server:

"use strict"

const fsp = require("fs").promises
const http = require("http")
const appendJson = async (loc, content) => {
    const data = JSON.parse(
        await fsp.readFile(loc, "utf-8").catch(err => "[]")
    )
    data.push(content)
    fsp.writeFile(loc, JSON.stringify(data))
}
const logReq = async (req, res) => {
    appendJson(__dirname + "/log.json", {
        ip: req.socket.remoteAddress,
        url: req.method + " http://" + req.headers.host + req.url,
        ua: "User-Agent: " + req.headers["user-agent"],
    })
}
const html = `<head><link rel="stylesheet" href="/main.css"></head><script src="/main.js"></script>`
const respond = async (req, res) => {
    res.writeHead(200, { "Content-Type": "text/html" }).end(html)
    logReq(req, res)
}
http.createServer(respond).listen(8080)

I tested sending lots of requests in both Firefox and Chromium (but for some reason, no errors were caused by sending even thousands of requests using cURL) by rapidly refreshing the page, or by opening many tabs in the browser console:

for (let i = 0; i < 200; i++)
    window.open("http://localhost:8080")

Normally, with full HTML pages that made more requests on their own, much fewer requests would cause these errors.

What are the cause of these errors, and how can I fix them, especially the second one?

Upvotes: 2

Views: 593

Answers (1)

O. Jones
O. Jones

Reputation: 108641

Concurrent requests to your appendJson() method are the cause of your problem. While one web request is in progress another one comes in. You must organize access to the log file so only one concurrent access is in progress at any time.

Something like this may work if you have just one log file.

There's a fileAccessInProgress flag and a queue of items to write to the file. Each new item gets appended to the queue. Then, if file access isn't active, the contents of the queue get written out. If new items arrive while access is in progress, they get appended to the queue too.

let fileAccessInProgress = false
let logDataQueue = []
const appendJson = async (loc, content) => {
  logDataQueue.push(content)
  if (fileAccessInProgress) return
  fileAccessInProgress = true
  while (logDataQueue.length > 0) {
    const data = JSON.parse(
      await fsp.readFile(loc, "utf-8").catch(err => "[]")
    )
    while (logDataQueue.length > 0) data.push(logDataQueue.shift()) 
    await fsp.writeFile(loc, JSON.stringify(data))
  }
  fileAccessInProgress = false
}

You can probably get this to work. But it is, with respect, a bad way to handle logging. Why? The CPU and I/O workload of writing each log file item is proportional to the number of items already in the log file. In compsci big-O lingo, that means the writing of the loc file is O(n squared).

That means the more successful your app becomes, the slower it will run.

There's a reason log files contain individual log lines rather than complete JSON objects: to avoid this kind of performance hit. If you need a JSON object to process your log lines, create it when you read the log, not when you write it.

Upvotes: 5

Related Questions