The python functions are not logging

vvijayv commented 3 years ago

My actions before raising this issue

[x] Followed the troubleshooting guide
[x] Read/searched the docs
[x] Searched past issues

Expected Behaviour

The logs written in the function (python) should appear in the kubernetes pod logs. Not sure if this a bug, but I tried it multiple ways (print, logging library) but nothing produces the log.

Current Behaviour

The below is the python code deployed in my openfaas that runs inside my kind kubernetes. The log does not appear in the pod logs.

`import sys

def handle(req): sys.stderr.write("The request payload is, " + req) return req `

Are you a GitHub Sponsor (Yes/No?) No

List All Possible Solutions and Workarounds

I tried using print statement, then python logging library, but all produced no log.

Which Solution Do You Recommend?

Not sure about this

Steps to Reproduce (for bugs)

kind create cluster --name openfaas
kubectl create ns
helm upgrade openfaas --install openfaas/openfaas --namespace openfaas --set basic_auth=true \ --set functionNamespace=openfaas-fn \ --set serviceType=LoadBalancer
fass-cli new python-log --lang=python3 --prefix=<repo>
Write a python function that logs the input using logging or sys.stderr.write
faas-cli up -f python-log.yml
fass-cli logs python-log
From another terminal, echo | faas-cli invoke python-log or curl the function

Context

Could not trace the function execution to identify function bugs

Your Environment

FaaS-CLI version ( Full output from: faas-cli version ): ___ _____ ____ / _ \ _ __ ___ _ __ | ___|_ _ __ _/ ___| | | | | '_ \ / _ \ '_ \| |_ / _ |/ _` _ \ | || | |) | / | | | | (| | (_| |) | \/| ./ _|| ||| _,|_,|____/ ||

CLI: commit: 2cec97955a254358de5443987bedf8ceee272cf8 version: 0.13.9

Gateway uri: http://52.191.39.155:8080 version: 0.20.12 sha: a6dbb4cd0285f6dbc0bc3f43f72ceacdbdf6f227

Provider name: faas-netes orchestration: kubernetes version: 0.13.2 sha: 6caf24ba21f7af171e2ade40daa033b05584b695 Your faas-cli version (0.13.9) may be out of date. Version: 0.13.13 is now available on GitHub. `

Docker version docker version (e.g. Docker 17.0.05 ): `Client: Cloud integration: 1.0.14 Version: 20.10.6 API version: 1.41 Go version: go1.16.3 Git commit: 370c289 Built: Fri Apr 9 22:46:57 2021 OS/Arch: darwin/amd64 Context: default Experimental: true

Server: Docker Engine - Community Engine: Version: 20.10.6 API version: 1.41 (minimum version 1.12) Go version: go1.13.15 Git commit: 8728dd2 Built: Fri Apr 9 22:44:56 2021 OS/Arch: linux/amd64 Experimental: true containerd: Version: 1.4.4 GitCommit: 05f951a3781f4f2c1911b05e61c160e9c30eaa8e runc: Version: 1.0.0-rc93 GitCommit: 12644e614e25b05da6fd08a38ffa0cfe1903fdec docker-init: Version: 0.19.0 GitCommit: de40ad0`

Are you using OpenFaaS on Kubernetes or faasd? Openfaas
Operating System and version (e.g. Linux, Windows, MacOS): MacOS
Code example or link to GitHub repo or gist to reproduce problem: The python function provided above
Other diagnostic information / logs from troubleshooting guide No

kevin-lindsay-1 commented 3 years ago

If I remember correctly, of-watchdog binds the function to stderr and stdout, and I've never had this issue on JavaScript or Go functions.

Is there possibly an environment variable that needs to be set in the python template? You can check using faas template store pull <template-name> and altering the Dockerfile for the template.

Alternatively, you could find the source code and build your own template, maybe even make a PR if you find a bug.

I'm thinking that this might just be python behavior that went unaccounted for.

alexellis commented 2 years ago

Hi, for the python3 template you can learn about logging using the workshop: https://github.com/openfaas/workshop

Look at the logging section. This does work so I'm closing the issue.

jfining commented 2 years ago

For anyone reading this in the future - I was following the python3-http template and couldn't get logging to work without the following:

environment:
  PYTHONUNBUFFERED: "1"

alexellis commented 2 years ago

Hey I think @LucasRoesler uses this with a standard logger. I also know of some customers who do. I don’t think they use that env var?

jfining commented 2 years ago

Hey I think @LucasRoesler uses this with a standard logger. I also know of some customers who do. I don’t think they use that env var?

The behavior is different depending on where and how you're logging. From my reading of the docs, I think this is because of the way stdout is captured from the handler().

Did a bit of testing just now.

Context: Running openfaas in Kubernetes v1.24.3 K8s is running on Ubuntu VMs, which are running on Proxmox

I used the template from: faas-cli template store pull python3-http

Made a contrived handler:

import os
import sys
import logging

log = logging.getLogger(__name__)
log.setLevel(os.environ.get("LOGLEVEL", "DEBUG"))

log.debug("debug at global scope")
log.info("info at global scope")
log.error("error at global scope")
sys.stdout.write("sys.stdout.write at global scope")
sys.stdout.flush()
print("Print at global scope")

def handle(event, context):
    log.debug("debug at handle scope")
    log.info("info at handle scope")
    log.error("error at handle scope")
    sys.stdout.write("sys.stdout.write at handle scope")
    sys.stdout.flush()
    print("Print at handle scope")

    if event.method == "GET":
        return {
            "statusCode": 200,
            "body": "GET request received",
        }
    else:
        return {"statusCode": 405, "body": "Method not allowed"}

With PYTHONUNBUFFERED not set explicitly anywhere, and the only environment variable added is write_debug: true, the logs of the pod show the following:

2022/10/29 21:31:55 Metrics listening on port: 8081
2022/10/29 21:31:56 stderr: error at global scope
2022/10/29 21:32:51 stderr: DEBUG:function.handler:debug at handle scope
2022/10/29 21:32:51 stderr: INFO:function.handler:info at handle scope
2022/10/29 21:32:51 stderr: ERROR:function.handler:error at handle scope
2022/10/29 21:32:51 stdout: sys.stdout.write at global scopePrint at global scope
2022/10/29 21:32:51 GET / - 200 OK - ContentLength: 20B (0.0027s)

With PYTHONUNBUFFERED=1:

2022/10/29 21:47:57 Metrics listening on port: 8081
2022/10/29 21:48:00 stderr: error at global scope
2022/10/29 21:48:00 stdout: sys.stdout.write at global scopePrint at global scope
2022/10/29 21:48:30 stderr: DEBUG:function.handler:debug at handle scope
2022/10/29 21:48:30 stderr: INFO:function.handler:info at handle scope
2022/10/29 21:48:30 stderr: ERROR:function.handler:error at handle scope
2022/10/29 21:48:30 stdout: sys.stdout.write at handle scopePrint at handle scope
2022/10/29 21:48:30 GET / - 200 OK - ContentLength: 20B (0.0030s)

openfaas / faas