Log output and user requests

[ssugar]

@Badgerati - Was wondering if you had any thoughts or plans on adding some logging to pode Servers in order to have a historic view of what is being requested, sourceip, ... along the lines of something we'd get if we ran an iis-based web/smtp server with basic logging enabled. I'd be willing to take a first crack at it if you'd like.

[Badgerati]

I was actually just thinking about this a couple days ago 😄

I've had a few thoughts about this one, and it came down to a few questions and ideas:

Questions:

• How would you like the logging to be outputted: to the terminal, to daily files, or tee out to both?
• Make the logging optional, so pass a -Log switch?
• If outputting to a file, how many days to store - make it configurable? (I'm guessing configurable)

Ideas:

• Run a separate runspace for logging - so writing to a file and/or outputting to a terminal doesn't slow down responses

Other than this, what format and information would you like being logged?

• Endpoint
• Method (get, post, patch, etc)
• Source IP
• Port
• Response Status Code
• Timestamp

I was thinking, if storing to a file, store it as a CSV maybe? (so it's simple to import and parse)

[ssugar]

My answers:

• Output should be able to go to terminal and/or daily file (as some users will want to run pode interactive and some unattended). Might also be good to look at the ability to log to fluentd or logstash.
• Optional with a -Log switch makes the most sense to me
• Configurable for how many days to store makes sense, although some users may want to use logrotate or their own log rotation application for this.

Ideas:

• I like your idea of running logging in a separate runspace so responses aren't slowed down. Response time shouldn't be compromised to make way for logging.

Format and Detail

• I think format depends on whether pode would have some log analysis capabilities itself, or if log analysis would be performed by a log analysis application. My gut says to leave log analysis to a specialized app, in which case adopting the Common Log Format would seem to make sense:
  Common Log Format

[Badgerati]

Excellent, thanks! In which case this is what I'm thinking with the above:

• Logging will be optional, and will only be started if the -Log switch is supplied
• Output will go to both the terminal and a daily file (at a pode_logs directory, in the same root as public and views)
  • Either can be disabled with -DisableLogFile or -DisableLogTerminal
  • Log files will store daily, and by default will last forever. A -MaxLogDays <int> can be supplied to specify how long to keep log files (<=0 is to keep forever [default])
  • Log file formats will be in the Common Log Format
• Logging will run in a separate runspace, using a thread safe array (logic can be seen in the async-content branch for locking)

Work on support for sending logs to, say, fluentd/logstash/influxdb/splunk/etc should probably come in a separate issue that can be raised - allowing for this issue to just focus on getting logging to terminal/files in place.

[ssugar]

Started to put together a rough draft of the code for this. Tried to mimic the async-content Add-ContentResponseRunspace code/usage. Currently this just logs to the console if you add a -Log switch to a Server, and it only works for the web server. Not yet able to pull in the response length yet, but was able to get the rest of the data required to log in the Common Log Format.

rough draft

I didn't create a pull request for this as I used the async-content branch and didn't know if you'd want this under a separate branch or not. Just put together this code quickly as a rough draft for you to review and point me in the right direction.

[ssugar]

This change would allow us to log in Combined Log Format
commit for combined log format

[Badgerati]

I was working on something for it last night as well (commit above).

When I was going through it, I was thinking about the extra switches for logging, and decided it might be a bit too much and to only include a -DisableLogging switch. Then made it so you could define Loggers within the server script itself. On the first logger being added, it would enable the logging runspace.

The idea behind the loggers was to allow you to define inbuilt loggers, or defined custom loggers with a custom scriptblock - for tools like logstash/fluentd.

Currently the only ones I threw together were for terminal and file (file currently is just one big file).

Example of a logger:

Server -Port 8085 {
    logger 'terminal'
    logger 'file'

    # GET "localhost:8085/"
    route 'get' '/' {
        param($session)
        view 'simple' -Data @{ 'numbers' = @(1, 2, 3); }
    }
}

logger terminal will just log to the terminal, but logger file could take a hashtable of options - for things like days to keep, etc.

For custom ones, say like logger 'custom_logstash, this could take a scriptblock and receive the logging object (with host/url/code) for you to define custom logic on calling out.

Passing -DisableLogging on the Server would stop the loggers and runspace from being setup.

• Also support the Combined Log Format, similar to yours

[ssugar]

Looks great. I agree that trying to fit everything in as switches/parameters to a Server will get messy quick. Good idea on moving it to defining 'loggers'.

I'm starting to test it all out now. Looks great so far

[Badgerati]

Updated that branch, so support for files is a little better:

logger 'file' @{
    'Path' = '<path-to-put-logs>';
    'MaxDays' = 4;
}

The hashtable is completely optional. If a no Path is supplied then a logs dir will be created at the server script root path, and if MaxDays is <= 0 then log files will be kept forever.

If a Path is supplied, then the logs will be placed there (and any directories along that path created).
If MaxDays it supplied, then once a day Pode will clean-up log files older than that many days.

Also added in support for custom loggers; custom ones must have a name like custom_* and have a supplied scriptblock. When the scriptblock is invoked, the log request object will be passed to it:

logger 'custom_output' {
    param($log)
    $log.Request.Resource | Out-Default
}

The $log object passed will have the following structure:

@{
    'Host' = '10.10.0.3';
    'RfcUserIdentity' = '-';
    'User' = '-';
    'Date' = '14/Jun/2018:20:23:52 +01:00';
    'Request' = @{
        'Method' = 'GET';
        'Resource' = '/api/users';
        'Protocol' = "HTTP/1.1";
        'Referrer' = '-';
        'Agent' = '<user-agent>';
    };
    'Response' = @{
        'StatusCode' = '200';
        'StautsDescription' = 'OK'
        'Size' = '-';
    };
}

[ssugar]

Testing on my end looks good. Looks like some of the json and html responses aren't displaying response.ContentLength64 though.

I sent a pull request to update the Readme on how to use the new logging functionality.

[ssugar]

Regarding json and html responses showing '-' for ContentLength64, I see in Tools\Responses.ps1 in the Attach function the ContentLength64 variable getting set:

    $PodeSession.Web.Response.ContentLength64 = $fs.Length

I didn't see anything similar in the Write-ToResponse function.

I pushed the above commit changing the WriteLine to a Write for Strings in the Write-ToResponse function and also to calculate the buffer. It looks like this works correctly for me, and now the logs are showing the response size.

[Badgerati]

I can manage to get the ContentLength64 being set when using the MemoryStream; but having some difficulties when using the StreamWriter.

Will keep digging.

[ssugar]

check this commit I think I got it working for the StreamWriter in there

[Badgerati]

Ah awesome, github didn't refresh properly so I missed the above comment.

I'll check out the commit in a bit, thanks!

[Badgerati]

@ssugar Got it! Your commit gave me an idea; I scrapped the StreamWriter and just stuck to the MemoryStream. I thought if we're having to convert it into bytes anyway, not much sense keeping both writers 😄

[ssugar]

@Badgerati Elegant solution. It's working well for me now.

[Badgerati]

@ssugar In which case, if we're happy with this, I can put it into tonight's v0.12.0 release later? I've seen the pull request for the documentation, and am happy with it - just needs a conflict resolving 😛

[ssugar]

@Badgerati - I'm very happy with this.