search

openfaas / of-watchdog

Reverse proxy for STDIO and HTTP microservices
MIT License
262 stars 115 forks source link

Use bufio.Scanner for reading stderr and stdout #73

Closed cconger closed 5 years ago

cconger commented 5 years ago

Description

Replaced the 256 byte slurping goroutine with a bufio.Scanner powered one. Reduced some code duplication by adding a go routine spawner for passing through logging Made the http executor use cmd.Wait for closing the forked process instead of catching EOFs on stderr/out. Removed a vestigial field Stderr on the HttpRunner

Motivation and Context

This was done to address the gotchas and generally poor user experience I've been having with using stderr and stdout for logging in my wrapped function process. The issues have been listed in #75. There is another proposed solution in #77 which seeks to address the problem by increasing the buffer size (and also allowing writing to stdout).

Where this one is superior is that it allows common log line prefixing to exist for log lines generated by the watchdog itself and those piped from the wrapped function process. It can accomplish this because the scanner splitting on new lines ensures that line breaks from the wrapped function are preserved (up to a single line size of 64Kb). If arbitrary splitting is done based on a buffer size as we currently do with 256 bytes, we're likely to get split lines that did not exist in the original output. If we just increase that buffer size and pass-through from the wrapped process like we do in #77 we now potentially include line breaks and formatting from the wrapped process that result in a non-uniform output in the watchdogs logs.

How Has This Been Tested?

I tested this using a contrived http mode go function named chatty-fn that just logs requests that it receives and a bunch of other extra information. I built the chatty-fn docker container and included different watchdogs to wrap it. I then boot the docker container directly, and issue network requests directly to it.

# Within chatty-fn
docker build -t chatty-fn:latest .
docker run -p 8080:8080 chatty-fn:latest > stdout.log 2> stderr.log
curl -X POST localhost:8080 -H 'Content-Type: application/json' --data '{"hello": "world"}'

When built using the 0.5.3 of-watchdog it yields the following outputs: stdout.log

Forking - /home/app/function []

stderr.log

2019/08/26 23:11:21 Started logging stderr from function.
2019/08/26 23:11:21 Started logging stdout from function.
2019/08/26 23:11:21 OperationalMode: http
2019/08/26 23:11:21 Writing lock-file to: /tmp/.lock
2019/08/26 23:11:21 Metrics server. Port: 8081
2019/08/26 23:11:21 stderr: Starting application server

2019/08/26 23:11:21 stdout: This is a warning to stdout

2019/08/26 23:11:28 stderr: Received request

2019/08/26 23:11:28 stdout: This is me writing to stdout on request: {"Method":"POST","URL":"/","Proto":"HTTP/1.1","Host":"localhost:8080","RemoteAddr":"127.0.0.1:51310","ContentLength":-1,"Body":"{\"hello\": \"world\"}","Headers":{"Accept":["*/*"],"Accept-Encoding":["gzip"],"Content
2019/08/26 23:11:28 stderr: Request: {"Method":"POST","URL":"/","Proto":"HTTP/1.1","Host":"localhost:8080","RemoteAddr":"127.0.0.1:51310","ContentLength":-1,"Body":"{\"hello\": \"world\"}","Headers":{"Accept":["*/*"],"Accept-Encoding":["gzip"],"Content-Type":["application/json"],"Use
2019/08/26 23:11:28 stdout: -Type":["application/json"],"User-Agent":["curl/7.54.0"]},"ReceivedAt":"2019-08-26T23:11:28.2348614Z"}
I liked what I got... so I'm gonna 200 OK

2019/08/26 23:11:28 stderr: r-Agent":["curl/7.54.0"]},"ReceivedAt":"2019-08-26T23:11:28.2348614Z"}

2019/08/26 23:11:28 POST / - 200 OK - ContentLength: 2

When building with this branch the resulting log lines look like: stdout.log

Forking - /home/app/function []
2019/08/26 23:06:20 This is a warning to stdout
2019/08/26 23:06:25 This is me writing to stdout on request: {"Method":"POST","URL":"/","Proto":"HTTP/1.1","Host":"localhost:8080","RemoteAddr":"127.0.0.1:49484","ContentLength":-1,"Body":"{\"hello\": \"world\"}","Headers":{"Accept":["*/*"],"Accept-Encoding":["gzip"],"Content-Type":["application/json"],"User-Agent":["curl/7.54.0"]},"ReceivedAt":"2019-08-26T23:06:25.2655911Z"}
2019/08/26 23:06:25 I liked what I got... so I'm gonna 200 OK

stderr.log

2019/08/26 23:06:20 Started logging stderr from function.
2019/08/26 23:06:20 Started logging stdout from function.
2019/08/26 23:06:20 OperationalMode: http
2019/08/26 23:06:20 Timeouts: read: 10s, write: 10s hard: 10s.
2019/08/26 23:06:20 Listening on port: 8080
2019/08/26 23:06:20 Writing lock-file to: /tmp/.lock
2019/08/26 23:06:20 Metrics listening on port: 8081
2019/08/26 23:06:20 Starting application server
2019/08/26 23:06:25 Received request
2019/08/26 23:06:25 Request: {"Method":"POST","URL":"/","Proto":"HTTP/1.1","Host":"localhost:8080","RemoteAddr":"127.0.0.1:49484","ContentLength":-1,"Body":"{\"hello\": \"world\"}","Headers":{"Accept":["*/*"],"Accept-Encoding":["gzip"],"Content-Type":["application/json"],"User-Agent":["curl/7.54.0"]},"ReceivedAt":"2019-08-26T23:06:25.2655911Z"}
2019/08/26 23:06:25 POST / - 200 OK - ContentLength: 2

Testing on Kubernetes

Additionally I've published two docker images for chatty-fn on Docker Hub cconger/chatty-fn:0.5.3 and cconger/chatty-fn:latest.

I deployed them onto Kubernetes based deployment of Openfaas.

I tested reading the logs via kubectl. Original

> kubectl kubectl --namespace openfaas-fn logs logger-original-84b6fdcbf9-vb7l5
Forking - /home/app/function []
2019/08/27 00:34:58 Started logging stderr from function.
2019/08/27 00:34:58 OperationalMode: http
2019/08/27 00:34:58 Started logging stdout from function.
2019/08/27 00:34:58 Writing lock-file to: /tmp/.lock
2019/08/27 00:34:58 Metrics server. Port: 8081
2019/08/27 00:34:58 stdout: This is a warning to stdout

2019/08/27 00:34:58 stderr: Starting application server

2019/08/27 00:35:06 stdout: This is me writing to stdout on request: {"Method":"POST","URL":"/","Proto":"HTTP/1.1","Host":"logger-original.openfaas-fn.svc.cluster.local:8080","RemoteAddr":"127.0.0.1:55764","ContentLength":-1,"Body":"{'hello': 'world'}","Headers":{"Accept":["applicati
2019/08/27 00:35:06 stdout: on/json, text/plain, */*"],"Accept-Encoding":["gzip, deflate, br"],"Accept-Language":["en-US,en;q=0.9"],"Content-Type":["application/json"],"Origin":["http://localhost:31112"],"Referer":["http://localhost:31112/ui/"],"Sec-Fetch-Mode":["cors"],"Sec-Fetch-Si
2019/08/27 00:35:06 stdout: te":["same-origin"],"User-Agent":["Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36"],"X-Call-Id":["857ca38b-941f-46a7-a034-93437f81cbf8"],"X-Forwarded-For":["192.168.65.3:59938"],"X-
2019/08/27 00:35:06 stdout: Forwarded-Host":["localhost:31112"],"X-Start-Time":["1566866106940407400"]},"ReceivedAt":"2019-08-27T00:35:06.9480898Z"}
I liked what I got... so I'm gonna 200 OK

2019/08/27 00:35:06 POST / - 200 OK - ContentLength: 2
2019/08/27 00:35:06 stderr: Received request
Request: {"Method":"POST","URL":"/","Proto":"HTTP/1.1","Host":"logger-original.openfaas-fn.svc.cluster.local:8080","RemoteAddr":"127.0.0.1:55764","ContentLength":-1,"Body":"{'hello': 'world'}","Headers":{"Accept":["application/json, text/p
2019/08/27 00:35:06 stderr: lain, */*"],"Accept-Encoding":["gzip, deflate, br"],"Accept-Language":["en-US,en;q=0.9"],"Content-Type":["application/json"],"Origin":["http://localhost:31112"],"Referer":["http://localhost:31112/ui/"],"Sec-Fetch-Mode":["cors"],"Sec-Fetch-Site":["same-orig
2019/08/27 00:35:06 stderr: in"],"User-Agent":["Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36"],"X-Call-Id":["857ca38b-941f-46a7-a034-93437f81cbf8"],"X-Forwarded-For":["192.168.65.3:59938"],"X-Forwarded-Host"
2019/08/27 00:35:06 stderr: :["localhost:31112"],"X-Start-Time":["1566866106940407400"]},"ReceivedAt":"2019-08-27T00:35:06.9480898Z"}

New

> kubectl --namespace openfaas-fn logs logger-65985b8697-mg64m
Forking - /home/app/function []
2019/08/27 00:30:59 Started logging stderr from function.
2019/08/27 00:30:59 Started logging stdout from function.
2019/08/27 00:30:59 OperationalMode: http
2019/08/27 00:30:59 Timeouts: read: 10s, write: 10s hard: 10s.
2019/08/27 00:30:59 Listening on port: 8080
2019/08/27 00:30:59 Writing lock-file to: /tmp/.lock
2019/08/27 00:30:59 Metrics listening on port: 8081
2019/08/27 00:30:59 Starting application server
2019/08/27 00:30:59 This is a warning to stdout
2019/08/27 00:31:12 Received request
2019/08/27 00:31:12 This is me writing to stdout on request: {"Method":"POST","URL":"/","Proto":"HTTP/1.1","Host":"logger.openfaas-fn.svc.cluster.local:8080","RemoteAddr":"127.0.0.1:53308","ContentLength":-1,"Body":"{\"hello\": \"world\"}","Headers":{"Accept":["application/json, text/plain, */*"],"Accept-Encoding":["gzip, deflate, br"],"Accept-Language":["en-US,en;q=0.9"],"Content-Type":["application/json"],"Origin":["http://localhost:31112"],"Referer":["http://localhost:31112/ui/"],"Sec-Fetch-Mode":["cors"],"Sec-Fetch-Site":["same-origin"],"User-Agent":["Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36"],"X-Call-Id":["4951f4e6-9da7-4ecf-aa7b-660ba30f868b"],"X-Forwarded-For":["192.168.65.3:34074"],"X-Forwarded-Host":["localhost:31112"],"X-Start-Time":["1566865872612459700"]},"ReceivedAt":"2019-08-27T00:31:12.6205404Z"}
2019/08/27 00:31:12 I liked what I got... so I'm gonna 200 OK
2019/08/27 00:31:12 Request: {"Method":"POST","URL":"/","Proto":"HTTP/1.1","Host":"logger.openfaas-fn.svc.cluster.local:8080","RemoteAddr":"127.0.0.1:53308","ContentLength":-1,"Body":"{\"hello\": \"world\"}","Headers":{"Accept":["application/json, text/plain, */*"],"Accept-Encoding":["gzip, deflate, br"],"Accept-Language":["en-US,en;q=0.9"],"Content-Type":["application/json"],"Origin":["http://localhost:31112"],"Referer":["http://localhost:31112/ui/"],"Sec-Fetch-Mode":["cors"],"Sec-Fetch-Site":["same-origin"],"User-Agent":["Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36"],"X-Call-Id":["4951f4e6-9da7-4ecf-aa7b-660ba30f868b"],"X-Forwarded-For":["192.168.65.3:34074"],"X-Forwarded-Host":["localhost:31112"],"X-Start-Time":["1566865872612459700"]},"ReceivedAt":"2019-08-27T00:31:12.6205404Z"}
2019/08/27 00:31:12 POST / - 200 OK - ContentLength: 2

And via faas-cli logs:

Original

> faas-cli logs logger-original
WARNING! Communication is not secure, please consider using HTTPS. Letsencrypt.org offers free SSL/TLS certificates.
2019-08-27T00:45:11Z logger-original (logger-original-84b6fdcbf9-vb7l5) 2019/08/27 00:45:11 stderr: Received request
2019-08-27T00:45:11Z logger-original (logger-original-84b6fdcbf9-vb7l5)
2019-08-27T00:45:11Z logger-original (logger-original-84b6fdcbf9-vb7l5) 2019/08/27 00:45:11 stderr: Request: {"Method":"POST","URL":"/","Proto":"HTTP/1.1","Host":"logger-original.openfaas-fn.svc.cluster.local:8080","RemoteAddr":"127.0.0.1:34898","ContentLength":-1,"Body":"{\"hello\": \"world\"}","Headers":{"Accept":["application/json, text/plain, */*"],"
2019-08-27T00:45:11Z logger-original (logger-original-84b6fdcbf9-vb7l5) 2019/08/27 00:45:11 stderr: Accept-Encoding":["gzip, deflate, br"],"Accept-Language":["en-US,en;q=0.9"],"Content-Type":["application/json"],"Origin":["http://localhost:31112"],"Referer":["http://localhost:31112/ui/"],"Sec-Fetch-Mode":["cors"],"Sec-Fetch-Site":["same-origin"],"User-Ag
2019-08-27T00:45:11Z logger-original (logger-original-84b6fdcbf9-vb7l5) 2019/08/27 00:45:11 stderr: ent":["Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36"],"X-Call-Id":["319ceca3-35d8-47de-a15a-2f6cf9b58daa"],"X-Forwarded-For":["192.168.65.3:34074"],"X-Forwarded-Host":["localhost:
2019-08-27T00:45:11Z logger-original (logger-original-84b6fdcbf9-vb7l5) 2019/08/27 00:45:11 stderr: 31112"],"X-Start-Time":["1566866711001639600"]},"ReceivedAt":"2019-08-27T00:45:11.0082648Z"}
2019-08-27T00:45:11Z logger-original (logger-original-84b6fdcbf9-vb7l5)
2019-08-27T00:45:11Z logger-original (logger-original-84b6fdcbf9-vb7l5) 2019/08/27 00:45:11 POST / - 200 OK - ContentLength: 2
2019-08-27T00:45:11Z logger-original (logger-original-84b6fdcbf9-vb7l5) 2019/08/27 00:45:11 stdout: This is me writing to stdout on request: {"Method":"POST","URL":"/","Proto":"HTTP/1.1","Host":"logger-original.openfaas-fn.svc.cluster.local:8080","RemoteAddr":"127.0.0.1:34898","ContentLength":-1,"Body":"{\"hello\": \"world\"}","Headers":{"Accept":["appli
2019-08-27T00:45:11Z logger-original (logger-original-84b6fdcbf9-vb7l5) 2019/08/27 00:45:11 stdout: cation/json, text/plain, */*"],"Accept-Encoding":["gzip, deflate, br"],"Accept-Language":["en-US,en;q=0.9"],"Content-Type":["application/json"],"Origin":["http://localhost:31112"],"Referer":["http://localhost:31112/ui/"],"Sec-Fetch-Mode":["cors"],"Sec-Fetc
2019-08-27T00:45:11Z logger-original (logger-original-84b6fdcbf9-vb7l5) 2019/08/27 00:45:11 stdout: h-Site":["same-origin"],"User-Agent":["Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36"],"X-Call-Id":["319ceca3-35d8-47de-a15a-2f6cf9b58daa"],"X-Forwarded-For":["192.168.65.3:34074"]
2019-08-27T00:45:11Z logger-original (logger-original-84b6fdcbf9-vb7l5) 2019/08/27 00:45:11 stdout: ,"X-Forwarded-Host":["localhost:31112"],"X-Start-Time":["1566866711001639600"]},"ReceivedAt":"2019-08-27T00:45:11.0082648Z"}
2019-08-27T00:45:11Z logger-original (logger-original-84b6fdcbf9-vb7l5) I liked what I got... so I'm gonna 200 OK
2019-08-27T00:45:11Z logger-original (logger-original-84b6fdcbf9-vb7l5)

New

> faas-cli logs logger
WARNING! Communication is not secure, please consider using HTTPS. Letsencrypt.org offers free SSL/TLS certificates.
2019-08-27T00:42:21Z logger (logger-65985b8697-mg64m) 2019/08/27 00:42:21 Received request
2019-08-27T00:42:21Z logger (logger-65985b8697-mg64m) 2019/08/27 00:42:21 This is me writing to stdout on request: {"Method":"POST","URL":"/","Proto":"HTTP/1.1","Host":"logger.openfaas-fn.svc.cluster.local:8080","RemoteAddr":"127.0.0.1:32812","ContentLength":-1,"Body":"{\"hello\": \"world\"}","Headers":{"Accept":["application/json, text/plain, */*"],"Accept-Encoding":["gzip, deflate, br"],"Accept-Language":["en-US,en;q=0.9"],"Content-Type":["application/json"],"Origin":["http://localhost:31112"],"Referer":["http://localhost:31112/ui/"],"Sec-Fetch-Mode":["cors"],"Sec-Fetch-Site":["same-origin"],"User-Agent":["Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36"],"X-Call-Id":["ae9ebe9d-1ff3-499a-b70f-578792e6e0b6"],"X-Forwarded-For":["192.168.65.3:59938"],"X-Forwarded-Host":["localhost:31112"],"X-Start-Time":["1566866541494492800"]},"ReceivedAt":"2019-08-27T00:42:21.500499Z"}
2019-08-27T00:42:21Z logger (logger-65985b8697-mg64m) 2019/08/27 00:42:21 I liked what I got... so I'm gonna 200 OK
2019-08-27T00:42:21Z logger (logger-65985b8697-mg64m) 2019/08/27 00:42:21 Request: {"Method":"POST","URL":"/","Proto":"HTTP/1.1","Host":"logger.openfaas-fn.svc.cluster.local:8080","RemoteAddr":"127.0.0.1:32812","ContentLength":-1,"Body":"{\"hello\": \"world\"}","Headers":{"Accept":["application/json, text/plain, */*"],"Accept-Encoding":["gzip, deflate, br"],"Accept-Language":["en-US,en;q=0.9"],"Content-Type":["application/json"],"Origin":["http://localhost:31112"],"Referer":["http://localhost:31112/ui/"],"Sec-Fetch-Mode":["cors"],"Sec-Fetch-Site":["same-origin"],"User-Agent":["Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36"],"X-Call-Id":["ae9ebe9d-1ff3-499a-b70f-578792e6e0b6"],"X-Forwarded-For":["192.168.65.3:59938"],"X-Forwarded-Host":["localhost:31112"],"X-Start-Time":["1566866541494492800"]},"ReceivedAt":"2019-08-27T00:42:21.500499Z"}
2019-08-27T00:42:21Z logger (logger-65985b8697-mg64m) 2019/08/27 00:42:21 POST / - 200 OK - ContentLength: 2
2019-08-27T00:44:30Z logger (logger-65985b8697-mg64m) 2019/08/27 00:44:30 Received request
2019-08-27T00:44:30Z logger (logger-65985b8697-mg64m) 2019/08/27 00:44:30 This is me writing to stdout on request: {"Method":"POST","URL":"/","Proto":"HTTP/1.1","Host":"logger.openfaas-fn.svc.cluster.local:8080","RemoteAddr":"127.0.0.1:34396","ContentLength":-1,"Body":"{\"hello\": \"world\"}","Headers":{"Accept":["application/json, text/plain, */*"],"Accept-Encoding":["gzip, deflate, br"],"Accept-Language":["en-US,en;q=0.9"],"Content-Type":["application/json"],"Origin":["http://localhost:31112"],"Referer":["http://localhost:31112/ui/"],"Sec-Fetch-Mode":["cors"],"Sec-Fetch-Site":["same-origin"],"User-Agent":["Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36"],"X-Call-Id":["62bc86ec-134e-4012-a456-da94f5485162"],"X-Forwarded-For":["192.168.65.3:59938"],"X-Forwarded-Host":["localhost:31112"],"X-Start-Time":["1566866670567143700"]},"ReceivedAt":"2019-08-27T00:44:30.572722Z"}
2019-08-27T00:44:30Z logger (logger-65985b8697-mg64m) 2019/08/27 00:44:30 I liked what I got... so I'm gonna 200 OK
2019-08-27T00:44:30Z logger (logger-65985b8697-mg64m) 2019/08/27 00:44:30 Request: {"Method":"POST","URL":"/","Proto":"HTTP/1.1","Host":"logger.openfaas-fn.svc.cluster.local:8080","RemoteAddr":"127.0.0.1:34396","ContentLength":-1,"Body":"{\"hello\": \"world\"}","Headers":{"Accept":["application/json, text/plain, */*"],"Accept-Encoding":["gzip, deflate, br"],"Accept-Language":["en-US,en;q=0.9"],"Content-Type":["application/json"],"Origin":["http://localhost:31112"],"Referer":["http://localhost:31112/ui/"],"Sec-Fetch-Mode":["cors"],"Sec-Fetch-Site":["same-origin"],"User-Agent":["Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36"],"X-Call-Id":["62bc86ec-134e-4012-a456-da94f5485162"],"X-Forwarded-For":["192.168.65.3:59938"],"X-Forwarded-Host":["localhost:31112"],"X-Start-Time":["1566866670567143700"]},"ReceivedAt":"2019-08-27T00:44:30.572722Z"}
2019-08-27T00:44:30Z logger (logger-65985b8697-mg64m) 2019/08/27 00:44:30 POST / - 200 OK - ContentLength: 2

Types of changes

This is a breaking change since it changes the default output location (things can actually appear in stdout now) and drastically changes the shape of output logs.

Documentation or release notes should likely be updated to alert consumers to this behavior change.

Checklist:

derek[bot] commented 5 years ago

Thank you for your contribution. I've just checked and your commit doesn't appear to be signed-off. That's something we need before your Pull Request can be merged. Please see our contributing guide. Tip: if you only have one commit so far then run: git commit --amend --signoff and then git push --force.

cconger commented 5 years ago

Since the log lines are properly preserved from the underlying application I would be ok to reintroduce the stderr: and stdout: prefixes because they do get mashed together in kubernetes however it might be reasonable to put the burden on the producer to generate that depending on the function author's use case.

alexellis commented 5 years ago

You will be able to retrieve this change through the following release https://github.com/openfaas-incubator/of-watchdog/releases/tag/0.7.0

A multi-arch Docker image can be used (faster, simpler), or you can pull the binary from the releases URL (the older way)

alexellis commented 5 years ago

Please could you try the new version with one of the existing templates like the node10-express and golang-http templates available via faas-cli template store list / pull?

cconger commented 5 years ago

Doing that now against 0.7.0

cconger commented 5 years ago

Tested generating a new golang-http function: • faas new --lang golang-http go-new-fn • Modifying the template Dockerfile to use of-watchdog:0.7.0 • Added a write to stdout in the handler • faas up -f go-new-fn • faas invoke go-new-fn • faas logs go-new-fn

WARNING! Communication is not secure, please consider using HTTPS. Letsencrypt.org offers free SSL/TLS certificates.
2019-08-29T21:02:41Z go-new-fn (go-new-fn-5bb8c94959-87vn8) Forking - ./handler []
2019-08-29T21:02:41Z go-new-fn (go-new-fn-5bb8c94959-87vn8) 2019/08/29 21:02:41 Started logging stderr from function.
2019-08-29T21:02:41Z go-new-fn (go-new-fn-5bb8c94959-87vn8) 2019/08/29 21:02:41 Started logging stdout from function.
2019-08-29T21:02:41Z go-new-fn (go-new-fn-5bb8c94959-87vn8) 2019/08/29 21:02:41 OperationalMode: http
2019-08-29T21:02:41Z go-new-fn (go-new-fn-5bb8c94959-87vn8) 2019/08/29 21:02:41 Timeouts: read: 10s, write: 10s hard: 10s.
2019-08-29T21:02:41Z go-new-fn (go-new-fn-5bb8c94959-87vn8) 2019/08/29 21:02:41 Listening on port: 8080
2019-08-29T21:02:41Z go-new-fn (go-new-fn-5bb8c94959-87vn8) 2019/08/29 21:02:41 Writing lock-file to: /tmp/.lock
2019-08-29T21:02:41Z go-new-fn (go-new-fn-5bb8c94959-87vn8) 2019/08/29 21:02:41 Metrics listening on port: 8081
2019-08-29T21:02:52Z go-new-fn (go-new-fn-5bb8c94959-87vn8) 2019/08/29 21:02:52 Returning Hello world, input was: test
2019-08-29T21:02:52Z go-new-fn (go-new-fn-5bb8c94959-87vn8) 2019/08/29 21:02:52 POST / - 200 OK - ContentLength: 28
alexellis commented 5 years ago

Thanks for doing that.

What I think is hard to distinguish now, is whether we're seeing output from stdout or stderr. There is also no good way to determine if the output was from the watchdog or the function process.

This is unrelated, but the verbosity of the logs command can be turned down a bit with --instance=false --name=false.

cconger commented 5 years ago

Tested generating a new node10-express:

faas new --lang node10-express test-js-fn
# update Dockerfile in template/node10-express to use of-watchdog:0.7.0
# update image-name to cconger/test-js-fn:latest
# add console.log to invocation body
faas up -f test-js-fn.yml
faas invoke test-js-fn
faas logs test-js-fn --instance=false --name=false

Results in:

WARNING! Communication is not secure, please consider using HTTPS. Letsencrypt.org offers free SSL/TLS certificates.
2019-08-29T21:17:59Z Forking - node [index.js]
2019-08-29T21:17:59Z 2019/08/29 21:17:59 Started logging stderr from function.
2019-08-29T21:17:59Z 2019/08/29 21:17:59 Started logging stdout from function.
2019-08-29T21:17:59Z 2019/08/29 21:17:59 OperationalMode: http
2019-08-29T21:17:59Z 2019/08/29 21:17:59 Timeouts: read: 15s, write: 15s hard: 10s.
2019-08-29T21:17:59Z 2019/08/29 21:17:59 Listening on port: 8080
2019-08-29T21:17:59Z 2019/08/29 21:17:59 Metrics listening on port: 8081
2019-08-29T21:17:59Z 2019/08/29 21:17:59 Writing lock-file to: /tmp/.lock
2019-08-29T21:17:59Z 2019/08/29 21:17:59 OpenFaaS Node.js listening on port: 3000
2019-08-29T21:18:29Z 2019/08/29 21:18:29 From app: { status: 'You said: "test\\n"' }
2019-08-29T21:18:29Z 2019/08/29 21:18:29 POST / - 200 OK - ContentLength: 34

I didn't know about those flags, very helpful!

cconger commented 5 years ago

I agree with your point about hard to differentiate (especially since I added "From app" to my own logging output. I'm very ok with returning stderr: stdout: for the lines now that we've reached line consistency. Especially since they are collated by kubernetes without annotation.

alexellis commented 5 years ago

The flags were part of the OpenFaaS Insiders updates. I can send you one or two of the past issues. Also publicly available on the release notes on the repo, but harder to keep track of all of them. https://github.com/users/alexellis/sponsorship

alexellis commented 5 years ago

I would like structured logging to be well supported. What do you think if the prefixes are enabled by default, but easy to disable?

cconger commented 5 years ago

Adding the prefix indicating the fd of origin should not be any more detrimental than the timestamp prefix already being included which will only come into play if a single payload is larger than 64Kb. I'm happy to have it be the default without an option (working on this PR now), but if you think it should be controllable I can add that as well.

If going the controllable route it might be nice to control all prefixes or none.

cconger commented 5 years ago

Opened #80 to re-add them on by default.