Nginx Access Logs => Metrics?

[Zren]

Do you have access to /var/log/nginx/*.log files? You could perform some wizardry with those files to count the meta/update/install requests filtered by timestamp / ip / user agent.

[Martii]

Nope. (as in doesn't exist)

[Martii]

I would be open to having to viability/feasibility results on https://www.npmjs.com/package/throttled-request if it's worth it... it's about the only thing on npmjs.com that I've found.

There's also this, https://www.npmjs.com/package/throttle-function, but it's even older.

---

If I can one of these confirmed as usable and possibly a PR for it... I can release the @updateURL requirement.

[Zren]

I meant for serverside logs. You dont have console access? Bleh. I mean, we could do a web ui for it too but it would use cron to schedule a task to generate a page.

Then do you have a log dump with morgan logging turned on of the past hour/24h? I could parse out all the other crap and format it nicely so we'd have an idea of the number of requests were getting.

If you are interested, send it to my email since there might be something in there. Otherwise i could just write some scripts for you to run. On 11 Apr 2016 3:32 a.m., "Marti Martz" notifications@github.com wrote:

I would be open to having to viability on https://www.npmjs.com/package/throttled-request if it's worth it... it's about the only thing on npmjs.com that I've found.

There's also this, https://www.npmjs.com/package/throttle-function, but it's even older.

— You are receiving this because you authored the thread. Reply to this email directly or view it on GitHub https://github.com/OpenUserJs/OpenUserJS.org/issues/966#issuecomment-208202141

[Martii]

You dont have console access?

I do... however still prefer to keep this inside the project and off the OS CLI as much as possible for cross-platform considerations... although it's been a really long time since I've tried Windows with our project with Git Bash.

Then do you have a log dump with morgan logging turned on of the past hour/24h?

I do not. See here and #430 esp. the dismissal but I'm willing to consider this a new day. The stdout and stderr messages are inclusive with the console object.

Otherwise i could just write some scripts for you to run.

I'd be willing to look at them for sure to ease up some typing.

[Zren]

I do...

cool

I'd be willing to look at them for sure to ease up some typing.

So will the scripts be able to parse /var/log/nginx/access.log? Or is it another file? Does Nodejitsu use even use nginx? cd /var/log/nginx/ && ls

[Martii]

Does Nodejitsu use even use nginx? cd /var/log/nginx/ && ls

It's not nodejitsu anymore ... if you do a $ whois on our domain name it will tell you who it is... the VPS doesn't have that folder from the "Nope" that I put above.

I've already just blocked two new IPs in the 21 minutes I've been on the keyboard as the manual instance in my shell was filling up with it.

[Zren]

So what's your tech stack then? Just a node instance on a DO droplet?

the manual instance in my shell was filling up

You log stdout to a file right, or do you have to start a new instance with debug enabled whenever you want to check the logs? If you log to file, you can use the tail -f filename.log to watch it.

[Martii]

node instance

Correct and usually a process manager to keep it alive... one of them which strips out date/times too which is annoying. We had to roll back to forever because the other one lost all instances launched when memory went away but I might have that more managed with the recent kernel update and this code.

log stdout to a file right

See here again and this as to why we're not logging fully in production. nodejitsu had this issue as well and I'd rather not store something that could be handled in memory and or with a throttling package. e.g. if the function is requested too many times from the same ip send them off to 503... or the request itself... however that package I mentioned doesn't appear to support the express .get and .put shortcuts... just reading though haven't tried it yet.

do you have to start a new instance with debug enabled whenever you want to check the logs?

This is a last resort as that sends out tons of info and is why I created #430 along with debug, dev and pro modes... plus you would see dbg on production next to OpenUserJS in the upper left corner.

Right now I'm twiddling with logging, to the terminal for now, the requests to .user.js ... the IP, the Accept header, script route, and UA. That's how I'm establishing monitoring statistics for #957.

you can use the tail -f filename.log to watch it.

Been a while since I've seen that command... thanks for the tip... will help if we log for sure and need a quick shell snapshot. I'm contemplating doing something similar in the Admin tools as well but not sure how much bandwidth that would use.

[Zren]

If you don't want requests being logged with the other logs, log them directly to file.

• https://github.com/expressjs/morgan#single-file

Then rotate the log file + compress them. I'm sure it should have a way to limit the size taken up somewhere as well. Nginx uses logrotate but that won't work for us since the filestream needs to be restarted probably. It looks like there's a https://github.com/dstokes/logrotate-stream package that could work.

So something like this:

var logrotateStream = require('logrotate-stream');
var accessLogStream = logrotateStream({
  file: './logs/app.log',
  size: '1m', // Should sate your worries about that issue
  keep: 100, // 100mb dedicated to logs
  compress: true, // well not really 100mb
});
app.use(morgan('combine', { stream: accessLogStream }));

I haven't tested this, I don't even have node installed atm I think. I'll setup a load test in a bit.

[Zren]

So with the following app:

var express = require('express')
var fs = require('fs')
var morgan = require('morgan')

var app = express()

var logrotateStream = require('logrotate-stream');
var accessLogStream = logrotateStream({
  file: './logs/app.log',
  size: '1m',
  keep: 100,
  compress: true,
});
app.use(morgan('combined', { stream: accessLogStream }));

app.get('/', function (req, res) {
  res.send('hello, world!')
})

app.listen(3000);

and using loadtest with loadtest http://localhost:3000 (requesting ~900 requests/sec) filled a 1 mb log every 30s or so. They crunched to 3kb but that's not very helpful since it's the same thing repeated.

Edit: The combined format is probably good enough for this. It has ip, timestamp, method, path, responseCode and userAgent. We could probably look into seeing if we can log certain headers as well.

::ffff:127.0.0.1 - - [11/Apr/2016:20:47:08 +0000] "GET / HTTP/1.1" 200 13 "-" "loadtest/1.3.5"

[Martii]

They crunched to 3kb but that's not very helpful since it's the same thing repeated.

What do you mean by this?

logrotate-stream

If we do log anything this massive I would want the rotate to tar.xz these on rotation automatically. e.g. not a cron job. This is a reason why we should keep these things in the project and not on the OS CLI. (P.S. I had to move exec calls to private because on low memory it would crash the server... so native node would be nice to have)

We could probably look into seeing if we can log certain headers as well.

This in mandatory right now.

Let me think about it some more... working on a few other ideas that may help. Appreciate the package refs as the terminology is all over the place with this kind of system management.

[Martii]

[11/Apr/2016:20:47:08 +0000]

Our other process manager date/times stamps too... and eventually we'll go back to that.

[Zren]

What do you mean by this?

When a log is rotated out when it hits the maximum filesize, it gets zipped.

Edit: Should note that I set it to size: '10m', so it wasn't rotating out so quickly. They zipped to half a megabyte which ain't bad.

If we do log anything this massive I would want the rotate to tar.xz these on rotation automatically. e.g. not a cron job. This is a reason why we should keep these things in the project and not on the OS CLI.

That's what logrotate-stream does. It's a pure Node.JS solution. It's basically the same thing as logging to a file except it checks the filesize of the log after writing to it, and rotates it out. Rotating means it renames it to filename.0 then compresses it then renames it to filename.1 or whatever is available.

It should also limit the amount of logs rotated out as well keep: 100 will keep 100 old logs before it starts deleting the oldest.

[Martii]

Sure would be nice if it did xz... that's usually about 60% smaller for these types of logs. I already have a rotate function in for some things CLI but will look into it for this application.

[Martii]

Just for stats pre analysis I logged ~ 12 minutes and that generated an uncompressed log of 494028B (482KiB) with a routine I have in place to with the filtering of the problematic IPs with this sort of output :

::ffff:xxx.xxx.xxx.xxx text/x-userscript, */* /install/Kizuna/Nyaa_Magnet_Links.user.js Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/51.0.2683.0 Safari/537.36

[Zren]

So you can use :req[Accept] in morgan to log that header. Eg:

var logFormat = ':remote-addr :date[iso] :method ":url" ":referrer"\\n\\t":user-agent"\\n\\t:req[Accept]\\n\\t:status :res[content-length] - :response-time ms'
app.use(morgan(logFormat, { stream: accessLogStream }));

With both loadtest http://localhost:3000/ -H "Accept:bleh" and the previous command running without the header, the logs look like this:

::ffff:127.0.0.1 2016-04-11T21:36:54.297Z GET "/" "-"
        "loadtest/1.3.5"
        bleh
        200 13 - 0.078 ms
::ffff:127.0.0.1 2016-04-11T21:36:54.297Z GET "/" "-"
        "loadtest/1.3.5"
        */*
        200 13 - 0.085 ms
::ffff:127.0.0.1 2016-04-11T21:36:54.298Z GET "/" "-"
        "loadtest/1.3.5"
        bleh
        200 13 - 0.083 ms
::ffff:127.0.0.1 2016-04-11T21:36:54.298Z GET "/" "-"
        "loadtest/1.3.5"
        */*
        200 13 - 0.081 ms
::ffff:127.0.0.1 2016-04-11T21:36:54.299Z GET "/" "-"
        "loadtest/1.3.5"
        bleh
        200 13 - 0.082 ms
::ffff:127.0.0.1 2016-04-11T21:36:54.299Z GET "/" "-"

Edit: oh I see you found out about :req[header] already.

[Martii]

Keep in mind I'm capturing only the script sources too... at this time I really don't care about any other route as that's not the problem with TM right now... although perhaps a configurable match would be good for future expanding outwards if we can't detect what's happening.

Would a aReq work in app.use(morgan(logFormat, { stream: accessLogStream })); e.g. encapsulate it with

app.use(
  function (aReq, aRes, aNext) {
    if (/^\/install\//.test(aReq._parsedUrl.pathname) ) {  // Basic source route... there are others
      morgan(logFormat, { stream: accessLogStream }); // Only then use morgan?
    }
  }
);

We'd also need a way of stating capturing of stdout and stderr via console object as well if there was this type of filtering I think.

morgan has pretty much been neglected by us and I installed it as part of the express3 to 4 upgrade.

[Zren]

The morgan function returns a route handler callback function(req,res,next). So like this maybe?

var logRequestHandler = morgan(logFormat, { stream: accessLogStream });
app.get('/test', function (req, res) {
  logRequestHandler(req, res, function(){}); // empty next() since we want it break out of the function
  res.send('test, world!')
})

[Martii]

Supposed we could just continue using the console object and ignore morgan some more. ;) The callback would be useful to determine pro/dev/dbg modes too. (but we can do that already in the code itself)

The logrotate-stream would have to not crash forever or other process managers during swap out. I'll have to set the log file to a static name in order to use that.

The loadtest worries me with:

Do not use loadtest if the Node.js process is above 100% usage in top, which happens approx. when your load is above 1000~4000 rps.

We can easily be above 100% which is what causes the memory to get eaten up... hence why I check _nodes process user memory (RSS)_ and if it's above 75% of the systems we serve a 503 on managed routes.

[Zren]

Node.JS only uses a single thread no (with an event loop). How are you getting above 100% (1 full core used up)? Also, why would you use loadtest on the production site when it's already had 1 drink too many, are you mad? It's used to send thousands of requests to the url you specify.

if [cpu usages > 100% and memory usage is] above 75% of the systems we serve a 503.

So we're trying to serve too many scripts at once. Does that mean the requests we're trying to keep too mana scripts in memory at once? Aren't we piping the response from AWS to the user (in the case of install)? Do update/meta checks pull the entire source file into memory to read it?

[Zren]

https://github.com/OpenUserJs/OpenUserJS.org/blob/master/controllers/scriptStorage.js#L308

Why aren't we piping on install. We should be serving the exact same data that's on AWS to the user.

https://medium.com/@stockholmux/node-js-streams-proxies-and-amazon-s3-50b4fabdedbd#.l8gssrukz

[Martii]

How are you getting above 100% (1 full core used up)?

See here... had the same reaction as you.

Also, why would you use loadtest on the production site when it's already had 1 drink too many, are you mad?

I haven't... just doing preliminary reading... it does have some API usage instead of just CLI although it's scattered all over the place. Trying to get on the same page as you with a question is all.

Does that mean the requests we're trying to keep too mana scripts in memory at once?

That's part of the kernel issue we had (have?) as well as TM sending out exponential update check requests.

Why aren't we piping on install.

Because that has a verified worse memory leak and was removed because of this entire incident... plus if we encapsulate those scripts without @updateURL or OUJS .user.js with our collected metadata blocks this works.

We should be serving the exact same data that's on AWS to the user.

See previous response in this reply... there's also an issue of UTF-16 which we still accept but we set encoding to UTF-8... but this is all beyond the scope here of logging to do auto-magic wizardry to block (and count) traffic... which none of this logging is addressing that yet.

[Martii]

Btw the one you linked (commit localized) is for the minification routine.

[Martii]

why would you use loadtest on the production site when it's already had 1 drink too many, are you mad?

Additional thoughts...

• If the CPU is above 100% it's very difficult to log in and if I were run it from the terminal once... that's another concern.
• Secondly please be nice and don't imply if asking a question is mad.

[Martii]

Re: Subject of:

Nginx Access Logs => Metrics?

And content of:

... You could perform some wizardry with those files to count the meta/update/install requests filtered by timestamp / ip / user agent.

Labeling as WONTFIX ... we are still being bombarded but I think it's managed now... so the logs would still show 100% of the requests pre-management... that won't happen as previously mentioned about storage getting filled up.

Closing but appreciate the ideas shared.

[Zren]

as previously mentioned about storage getting filled up.

But it won't fill it up. size: '10m' + keep: 3 will only use a maximum of 10mb + (whatever 10mb compresses to * 3) = no more than 40mb of logs.

[Martii]

But it won't fill it up.

Yes it will... issue is ended and won't happen... as I said before I was filtering the problem IPs so the actual log size is probably 1000 times bigger. Not going to happen.

[Zren]

Do you even know how many requests you were serving before and during these problems? Once they subside, you'll have no way of knowing how close you are to your current stack flopping over as you continue to scale. Though I guess you could try to emulate the load with loadtest but it might not distribute the load correctly to trip it.

[Martii]

@Zren I was thinking that maybe a new issue of creating a separate DB (or moving off MongoLab and just do it in the main one) with an IP, script id, and the last time they installed... if it's more than a period don't increment the count. Then a timed job could be done code wise at least once a day... Full time logging of all requests still won't happen due to actual abuse. I'm going to have to run this by @sizzlemctwizzle first though... e.g. not real time live stats. This indirectly leads into #952.

Another option is to turn the install counts to owner and moderator/admin+ and never show them to the public.