Watchdog should be passthrough for function process for logging about of-watchdog HOT 41 CLOSED

I would make the buffer size configurable via an environment variable that can be set in the function definition.

from of-watchdog.

I propose a single env variable for both stdout/err named log_buffer_size.

from of-watchdog.

+1 @stefanprodan

I've found the PR I mentioned on #72, #37 attempted to add configurable buffer sizes

I think that this is the mechanics of what we'd want:

https://github.com/openfaas-incubator/of-watchdog/pull/37/files#diff-194c7aaf3d69dbfd1dc1fb6c6837cd18L72

What is confusing about the old PR, is that it looks like I wrote it, but @canerbasat proposed it in a PR.

In any case, I think I would be open to a single buffer value or potentially two different buffer size values for stdin/stdout.

Alex

from of-watchdog.

the proposal mentions a couple of things

1. buffering (or not) the message and the buffer size
2. the merging of the function stderr and stdout by watchdog
3. watchdog specific logs are interwoven with function logs

for topic (1) I am also in favor of a new env variable log_buffer_size. Increasing the default buffer might also make sense. If a true streaming solution existed, I would prefer that. Also, it is worth noting that io.Copy allocates a 32kb buffer https://golang.org/src/io/io.go?s=12796:12856#L391 so using io.Copy is also a buffered solution.

for (2), I did some digging into the k8s and Swarm docs. Both collect stderr and stdout automatically, so I think it would be fine for watchdog to send the stderr to stderr and stdout to stdout without any prefix.

for (3), in the light of (2), perhaps we can partially address this by having watchdog send all of it's own logs to stderr only

from of-watchdog.

I'm for adding the log_buffer_size param. I would also enjoy both stderr and stdout to be passed to their appropriate outputs sans prefix. I think these two changes make it possible for the end user to control their experience with logging largely.

I want to experiment a little bit, but I believe on posix that the reads will be usually aligned to pipe fd flushes so a sufficiently large buffer affords control to the writer for chunking the output. I think therefore increasing the default buffer size to something like the stdlib uses 32kb (io.Copy) to 64kb (for the Scanner) makes sense in addition to user level control.

from of-watchdog.

I've submitted a new PR that adds this parameter, however while playing with it more I remain a relatively strong proponent of the Scanner approach in #72. It affords a core library solution to a dynamically sizable buffer, with system agnostic handling of new lines. I would however want to update it to write to the appropriate out file (Stdout => Stdout / Stderr => Stderr)

The benefit one gets from using the scanner is that a line as generated from the wrapped process will be guaranteed to be written as a line in the resulting log output if that line is less than 32Kb. You can potentially still get log lines interspersed from the watchdog in your lines from the function process however they'll only ever be interspersed between true lines as generated by my application.

A dichotomy of approach seems to be you can either try to be a true byte passthrough (what I've tried to capture in #77) or you can aggregate the lines which seems more appropriate if the watchdog will be emitting logging during operation. This affords a guarantee on the contents of any given line up to the golang buffer cap (32Kb) and affords a way to filter contents from the watchdog by log parsers.

It also is more reasonable for me as a consumer to properly size what size a log line might be instead of me guessing what a healthy buffer size might be in the case of a GC pause or latency reading the file descriptor from the watchdog. So perhaps a Scanner built on top of a tunable buffer size from the param makes more sense.

from of-watchdog.

Hey there, I'd appreciate some insight into whether the initial assertion of the issue matters to this project. Should the wrapped application function be the responsible for the shape and format of logs? It seems like an obvious win for portability and flexibility to me but if that view isn't held I understand why I seem to be pushing in a different direction than you all.

from of-watchdog.

Hi @cconger

I am concerned about changing the behaviour in this way (scanning for \n), but I need more time to dedicate to your understanding problem and proposal. I have been having to prioritise other work and features.

An alternative to using the of-watchdog, is to use a Dockerfile, you can still use the templating system if you want.

What are your thoughts about this blog post? If you're using the http mode, then it will be relatively straight-forward for you to have complete control over STDIO.

https://www.openfaas.com/blog/stateless-microservices/

Alex

from of-watchdog.

The last comment from Lucas/Stefan/myself was about adding log_buffer_size.

Would you like to send a PR for this? It will be easy to merge, or do you feel that you need the line-scanner for structured logging to work?

from of-watchdog.

for (2), I did some digging into the k8s and Swarm docs. Both collect stderr and stdout automatically, so I think it would be fine for watchdog to send the stderr to stderr and stdout to stdout without any prefix.

@LucasRoesler can you explain the context, or what you mean by this? What has log collection got to do with the use of log.Printf(), which prints a prefix? Pass-through of stdio sounds like it's essential for structured logging.

from of-watchdog.

I have a pr of #77 that does the log_buffer_size. It however raised interesting concerns about preserving lines from the wrapped process and having a consistent prefix for log lines which @LucasRoesler noted in his comment when I removed log.Println. Because I do not easily see how you can have both a guaranteed prefix on each new line (ideal) and also have a 1:1 mapping of lines in of-watchdog's output and the source application's (also ideal) unless you do buffering and tokenizing.

from of-watchdog.

Is there a way that it makes sense to preserve the existing behaviour, and add your tokenised scanner, so that the two code paths work separately?

from of-watchdog.

Certainly, it can be flagged behavior. However, I'm unsure why anyone would prefer the existing behavior. I say that not out of judgement but I just do not see the use case and would enjoy accounting for it.

from of-watchdog.

I guess for backwards compatibility, because this could be a breaking change. Some functions may not write a new-line, in which case, how would the scanner work?

from of-watchdog.

This approach looks fine to me #73

If we wanted to have some level of backwards compatibility then perhaps you could add something like?

bindLoggingPipe - without scanner
bindScanningLoggingPipe - with \n scanner

Given this rather bold statement, I am starting to wonder if I am not understanding something obvious?

I'm unsure why anyone would prefer the existing (code) behavior.

from of-watchdog.

In the case where no newlines were sent the scanner would flush the entire buffer at process conclusion or once the buffer's limit had hit 64Kb.

While I appreciate that its existing behavior its odd to me that someone would expect to write 256 bytes exactly to an output and count on that getting mapped to a line based textual output. In the case that its some streaming protocol thats not textual/line delimited it is already getting mangled by the transformation to line delimited 256 byte blocks and therefore difficult to use by anything consuming it without having to re-extract it which was happening in my structured logging example.

from of-watchdog.

I'm happy to decouple the 2 proposals that are inside of this issue if it helps ease concerns about change.

1. Remapping the output file descriptors (using both stderr and out)
2. Changing output slurping/tokenization from the wrapped file descriptors.

I think 2 is the most important, largely because 1 gets undone by the Kubernetes log driver.

from of-watchdog.

#73 is merged now. I like the solution and the design. It was very refreshing to see the testing and output too, that makes it a lot easier to merge.

I've asked on the PR if you could do a smoke test with two of the more popular templates. Perhaps if that looks good, you could submit a PR to bump of the version in their respective Dockerfiles?

from of-watchdog.

Could you summarise what remaining changes you feel need to be made?

from of-watchdog.

I feel that the issues I was experiencing have been resolved. I feel comfortable writing to the log in an application controlled way and easily parsing the resulting output with existing tools.
I believe we've addressed all three of the original issues raised in the body.
What I am working on:
• I'm following up on your comment on #73 to be able to turn off prefixes (and log flags) via an argument.
• I will follow up on bumping the Dockerfile of-watchdog for the tested templates.

Happy to proceed how you would like, either tie those changes back to this issue, or open new issues to cover those individually and close this one.

from of-watchdog.

@cconger I have stumbled upon this issue, and I haven't even realized that the log is being split, so thanks for raising that.

Following your conversation, I have stumbled on alex's comment, and this is exactly the issue we are facing at the moment.

Our functions are deployed on k8s cluster which has it's logs scraped and sent upstream to log parsers to be indexed and become queryable. Of course for that issue, we must have the logs in their original JSON structure without the prefix.

Where does this issue stand at the moment, and can I assist?

from of-watchdog.

@saginadir please can you open a new issue for your use-case? @cconger is currently filtering out the prefix with his log aggregator tool.

Would also be helpful if you could join Slack and maybe tell us a bit about your use-case to help prioritise.

Alex

from of-watchdog.

/msg: slack

from of-watchdog.

--
Join Slack to connect with the community
https://docs.openfaas.com/community

from of-watchdog.

@alexellis Will do.

Also I requested invitation to the slack channel.

from of-watchdog.

How are we doing with this now @cconger @saginadir @sargun ?

from of-watchdog.

@alexellis For my solution, at the moment I forked the watchdog and made the specific changes I needed

from of-watchdog.

I think that the Netflix guys just used a prefix rule for their logging so that it worked with their ingestion pipeline. Maybe that'd work for others too?

Do you have your fork public for us to compare?

from of-watchdog.

Yes, that's my fork
master...saginadir:master

from of-watchdog.

Thanks.

On this line, how do you ensure that the code doesn't write plain-text? master...saginadir:master#diff-42b34d1af16e4b2190c38ad0ec0e0f54R18

from of-watchdog.

The logger that logs the messages from the function simply pipes the message from the function, and I make sure the function logs JSON.

Can be seen by replacing this:

logger := log.New(output, log.Prefix(), log.Flags())
...
logger.Printf("%s: %s", name, scanner.Text())

With this:

logger := log.New(output, log.Prefix(), 0) // removing flags to remove timestamps
...
logger.Printf("%s", scanner.Text())

And I print the status strings in JSON instead of plain log, which is done by replacing this line:

log.Printf("%s %s - %s - ContentLength: %d", r.Method, r.RequestURI, res.Status, res.ContentLength)		

with this:

log.Printf(`{"method":"%s","request_uri":"%s","status_code":%d,"content_length":%d}`, r.Method, r.RequestURI, res.StatusCode, res.ContentLength)

I avoid using JSON encode for a small performance gain (which is really minor for our current scale, but can matter in larger scales)

from of-watchdog.

In our utilization we were planning on just stripping the included prepended flags, using a regular expression essentially targeting the :

I could see this as a configurable. In the simplest case it could just be a passthrough to the log.Flags call and the user could set LOG_FLAGS=19 as a config environment variable. The downside is users would have parse the bit mask constants https://golang.org/pkg/log/#pkg-constants. Another alternative would be to just be able to enable/disable the default.

from of-watchdog.

I think that enable/disable the default is probably the simplest and most common case. Any other customization of the log output could be implemented in the function by the template/handler

from of-watchdog.

Having the ability to pass through logs from the function and letting the template/handler decide the log format would be super helpful

from of-watchdog.

@Voziv please can you improve the quality of your +1 here by stating what problem you're facing and which of the three outlined solutions would help you?

from of-watchdog.

1. Original of-watchdog as it is today:

cp /home/alex/go/src/github.com/openfaas/of-watchdog/of-watchdog . && mode=http upstream_url=http://127.0.0.1:3000 fprocess="node app.js" ./of-watchdog

2021/02/08 12:49:44 Forking - node [app.js]
2021/02/08 12:49:44 Started logging stderr from function.
2021/02/08 12:49:44 Started logging stdout from function.
2021/02/08 12:49:44 OperationalMode: http
2021/02/08 12:49:44 Timeouts: read: 10s, write: 10s hard: 10s.
2021/02/08 12:49:44 Listening on port: 8080
2021/02/08 12:49:44 Writing lock-file to: /tmp/.lock
2021/02/08 12:49:44 Metrics listening on port: 8081
2021/02/08 12:49:44 stdout: alexellis.io started on port: http://0.0.0.0:3000
2021/02/08 12:49:44 stderr: Disabled etag and x-powered-by
2021/02/08 12:49:47 GET / - 200 OK - ContentLength: 19686
2021/02/08 12:49:47 GET / - 200 OK - ContentLength: 19686
2021/02/08 12:49:48 GET / - 200 OK - ContentLength: 19686

2. Date prefix removed from logger

2021/02/08 12:17:39 Forking - node [app.js]
2021/02/08 12:17:39 Attached to: stderr.
2021/02/08 12:17:39 Attached to: stdout.
2021/02/08 12:17:39 OperationalMode: http
2021/02/08 12:17:39 Timeouts: read: 10s, write: 10s hard: 10s.
2021/02/08 12:17:39 Listening on port: 8080
2021/02/08 12:17:39 Writing lock-file to: /tmp/.lock
2021/02/08 12:17:39 Metrics listening on port: 8081
stdout: alexellis.io started on port: http://0.0.0.0:3000
stderr: Disabled etag and x-powered-by

3. No prefix at all - pass-through for all lines

http://127.0.0.1:3000 fprocess="node app.js" ./of-watchdog
2021/02/08 12:19:22 Forking - node [app.js]
2021/02/08 12:19:22 Attached to: stderr.
2021/02/08 12:19:22 Attached to: stdout.
2021/02/08 12:19:22 OperationalMode: http
2021/02/08 12:19:22 Timeouts: read: 10s, write: 10s hard: 10s.
2021/02/08 12:19:22 Listening on port: 8080
2021/02/08 12:19:22 Writing lock-file to: /tmp/.lock
2021/02/08 12:19:22 Metrics listening on port: 8081

alexellis.io started on port: http://0.0.0.0:3000
Disabled etag and x-powered-by

2021/02/08 12:19:27 GET / - 200 OK - ContentLength: 19686
2021/02/08 12:19:27 GET / - 200 OK - ContentLength: 19686

Note that the watchdog still outputs its own native logs which will have a prefix.

There are mixed requests here that we need to understand more clearly.

4. Do users want the watchdog to print all output in structured JSON, or just get a pass-through?

Note that if we use JSON format, your message will be double encoded as JSON.

{"level":"info","ts":1612788414.757614,"caller":"of-watchdog/main.go:364","msg":"Forking","command":"node","args":["app.js"]}
{"level":"info","ts":1612788414.757807,"caller":"executor/logging.go:13","msg":"Attached to","name":"stderr"}
{"level":"info","ts":1612788414.757837,"caller":"executor/logging.go:13","msg":"Attached to","name":"stdout"}
{"level":"info","ts":1612788414.7582288,"caller":"of-watchdog/main.go:74","msg":"OperationalMode\n","OperationalMode":"http"}
{"level":"info","ts":1612788414.758498,"caller":"of-watchdog/main.go:95","msg":"Timeouts","read":10,"write":10,"exec":10}
{"level":"info","ts":1612788414.75853,"caller":"of-watchdog/main.go:103","msg":"Listening on\n","port":8080}
{"level":"info","ts":1612788414.8450463,"caller":"executor/logging.go:25","msg":"Function output","name":"stdout","msg":"alexellis.io started on port: http://0.0.0.0:3000"}
{"level":"info","ts":1612788414.8452017,"caller":"executor/logging.go:25","msg":"Function output","name":"stderr","msg":"Disabled etag and x-powered-by"}
{"level":"info","ts":1612788417.779004,"caller":"executor/http_runner.go:173","msg":"Invoked","method":"GET","requestURI":"/","status":"200 OK","ContentLength":19686}
{"level":"info","ts":1612788418.3271103,"caller":"executor/http_runner.go:173","msg":"Invoked","method":"GET","requestURI":"/","status":"200 OK","ContentLength":19686}
{"level":"info","ts":1612788418.713564,"caller":"executor/http_runner.go:173","msg":"Invoked","method":"GET","requestURI":"/","status":"200 OK","ContentLength":19686}

Moving completely to JSON feels like a bad user experience for local testing and development of functions, and for the many hobbyist users who don't seem to care about log aggregation beyond the OpenFaaS API.

5. This is what Zap looks like with its "console" / non-JSON mode, pretty hard to read IMHO compared to the original.

1.612788359664378e+09	info	Forking	{"command": "node", "args": ["app.js"]}
1.6127883596645575e+09	info	Attached to	{"name": "stderr"}
1.6127883596645744e+09	info	Attached to	{"name": "stdout"}
1.6127883596648636e+09	info	OperationalMode
	{"OperationalMode": "http"}
1.6127883596650236e+09	info	Timeouts	{"read": 10, "write": 10, "exec": 10}
1.6127883596650379e+09	info	Listening on
	{"port": 8080}
1.6127883597464366e+09	info	Function output	{"name": "stdout", "msg": "alexellis.io started on port: http://0.0.0.0:3000"}
1.6127883597468245e+09	info	Function output	{"name": "stderr", "msg": "Disabled etag and x-powered-by"}
1.6127883614455812e+09	info	Invoked	{"method": "GET", "requestURI": "/", "status": "200 OK", "ContentLength": 19686}

@LucasRoesler and @Waterdrips use Logrus and it appears to have a more friendly console formatter built-in.

6. Finally, as Lucas pointed out, the OpenFaaS API already has a log API which returns text in JSON:

faas-cli logs nodeinfo --since 8h --format json
WARNING! Communication is not secure, please consider using HTTPS. Letsencrypt.org offers free SSL/TLS certificates.
{"name":"nodeinfo","namespace":"openfaas-fn","instance":"30337","timestamp":"2021-02-08T14:08:32.127985Z","text":"2021/02/08 14:08:32 GET / - 200 OK - ContentLength: 88"}
{"name":"nodeinfo","namespace":"openfaas-fn","instance":"30337","timestamp":"2021-02-08T14:08:33.064871Z","text":"2021/02/08 14:08:33 GET / - 200 OK - ContentLength: 88"}

And another example from Go:

{"name":"trove","namespace":"openfaas-fn","instance":"9174","timestamp":"2021-02-08T07:38:59.9926Z","text":"2021/02/08 07:38:59 stderr: 2021/02/08 07:38:59 Path: /login/"}
{"name":"trove","namespace":"openfaas-fn","instance":"9174","timestamp":"2021-02-08T07:38:59.999511Z","text":"2021/02/08 07:38:59 GET /login/?r= - 200 OK - ContentLength: -1"}
{"name":"trove","namespace":"openfaas-fn","instance":"9174","timestamp":"2021-02-08T07:44:10.144041Z","text":"2021/02/08 07:44:10 stderr: 2021/02/08 07:44:10 Path: /login/"}
{"name":"trove","namespace":"openfaas-fn","instance":"9174","timestamp":"2021-02-08T07:44:10.150358Z","text":"2021/02/08 07:44:10 GET /login/?r=// - 200 OK - ContentLength: -1"}
{"name":"trove","namespace":"openfaas-fn","instance":"9174","timestamp":"2021-02-08T07:51:35.67197Z","text":"2021/02/08 07:51:35 stderr: 2021/02/08 07:51:35 Path: /static/card.jpg"}
{"name":"trove","namespace":"openfaas-fn","instance":"9174","timestamp":"2021-02-08T07:51:35.889935Z","text":"2021/02/08 07:51:35 GET /static/card.jpg - 200 OK - ContentLength: 76695"}
{"name":"trove","namespace":"openfaas-fn","instance":"9174","timestamp":"2021-02-08T08:19:06.902559Z","text":"2021/02/08 08:19:06 stderr: 2021/02/08 08:19:06 Path: /static/card.jpg"}
{"name":"trove","namespace":"openfaas-fn","instance":"9174","timestamp":"2021-02-08T08:19:07.120483Z","text":"2021/02/08 08:19:07 GET /static/card.jpg - 200 OK - ContentLength: 76695"}

from of-watchdog.

If we move to a structured logger to output JSON and then some users want to see plaintext for debugging (frankly, I find the JSON hard to read).

Totally agree that json destroys readability if you're looking at the logs directly. Our case we only want to have json where logs are never looked at directly but instead via an aggregator (newrelic-logging in our case).

@Voziv please can you improve the quality of your +1 here by stating what problem you're facing and which of the three outlined solutions would help you?

Absolutely. The main issue I came looking for is the ability to just have template/function logs passed through.

Current State:

2021/02/08 12:30:00 POST / - 200 OK - ContentLength: 16
2021/02/08 13:00:00 stdout: {"message":{} ,"level":"info"}
2021/02/08 13:00:00 stdout: {"message":"Requested function: <snip>", "level":"info"}

So what I can see is we have three different pieces logging

1. 2021/02/08 12:19:22 Forking - node [app.js] - I think this is the of-watchdog image
2. POST / - 200 OK - ContentLength: 16 - I think this is the node template/express output?
3. {"message":{} ,"level":"info"} - The function ouput. Could be considered the same as the template output since the user in control of this.

In my current use case we really only care about the function output being pure json when deployed to the cluster. The other lines will get parsed just fine as-is. So we'd prefer the ability to strip the date/time prefix & stdout/stderr portion just leaving the functions raw output being logged.

While it would be nice for all 3 types of logs to be json to keep things consistent in the cluster, it's less important as the main benefit of json is being able to include extra metadata in the log entries that can be index and searched.

from of-watchdog.

So would this line from the watchdog not break your log parser, if it's expecting a strongly typed JSON output?

2021/02/08 12:30:00 POST / - 200 OK - ContentLength: 16

cc @saginadir if you have time to give your 2c here

from of-watchdog.

Cluster logs are injested from the container log files on the node. At least in the case of newrelic-logging they're parsed by individual lines so lines that are pure json (and likely has a requirement to have a date field + message field) will be parsed as json. Other plain text logs should parsed normally so it should be fine.

I could be wrong about this though.

from of-watchdog.

@alexellis From my experience I needed a log that would look like that:

{"level":"info","ts":1612788414.757807,"caller":"whatever.go:13", "method": "POST", "path": "/", "statusCode": 200, "ContentLength": 15}

For hobbiest it's a terrible experience to read JSON logs like you mentioned. But working in a big organization with a rigid DevOps team can sometimes make you jump through hoops in order to abide by their guidelines. For us, we were using ElasticSearch to aggregate the stdout output of all production nodes in k8s cluster. So I couldn't invoke the faas-cli logs nodeinfo --since 8h --format json command and needed the process itself to print outputs in pure JSON.

I think it's quite common today to have the entire log be printed in JSON, example with zap:

logger, _ = zap.Config{
    Encoding:    "json",
    Level:       zap.NewAtomicLevelAt(zapcore.DebugLevel),
    OutputPaths: []string{"stdout"},
    EncoderConfig: zapcore.EncoderConfig{  
        MessageKey: "message",  // <--
    },
}.Build()

logger.Info("This is an INFO message with fields", zap.String("region", "us-west"), zap.Int("id", 2))

Output: {"message":"This is an INFO message with fields","region":"us-west","id":2}

So at the time I would have greatly appreciated some env variable to pass to the watchdog node like LOG_ENCODING=json and would have the log formatter just print JSON instead of the standard log format. But ended up just hardcoding a fork of watchdog to print JSON.

from of-watchdog.

Please see 51ea0d6 which adds a mechanism to disable prefixes to function logs.

This is option 3 (No prefix at all - pass-through for all lines)

from of-watchdog.