Logging is printed twice

[dennygee]

Hi Team,

I am using the flask logger now, and I am working on from local PC (not pushing to Cloud Foundry).

I noticed that after the flask_logging.init, all my logs are printed twice, as such:

2018-07-24 17:20:23,209 cash_app_core.api.app INFO     ===========================================
===========================================
2018-07-24 17:20:37,391 cash_app_core.api.app INFO     Cash Application Core is running: v1
Cash Application Core is running: v1
2018-07-24 17:20:48,156 cash_app_core.api.app INFO     ===========================================
===========================================

Can you explain to me why this behaviour is happening? Can we turn off this printing of logs twice?

[alexpenev-s]

Hi, It usually happens when there are other loggers setup, so each logger will log the same message.

[dennygee]

Hi Alexander,

Let me just paste my test app here now:

test_app.py

from sap.cf_logging import flask_logging
from flask import Flask
import logging
import sys

from test_helper import call_help

app = Flask(__name__)

logging.basicConfig(stream=sys.stdout,
                    level=logging.DEBUG,
                    format='%(asctime)s %(name)-12s %(levelname)-8s %(message)s')
flask_logging.init(app, logging.DEBUG)

logger = logging.getLogger(__name__)

@app.route('/')
def test_route():
    logger.info('Hi')
    call_help()
    return 'ok'

if __name__ == '__main__':
    app.run()

test_helper.py

import logging

logger = logging.getLogger(__name__)

def call_help():
    logger.info("Calling helper method")

When i invoke the endpoint, this is what is printed out:

2018-07-24 22:36:05,189 __main__     INFO     Hi
{"component_id": "-", "component_name": "-", "component_instance": 0, "space_id": "-", "space_name": "-", "container_id": "-", "component_type": "application", "written_at": "2018-07-24T14:36:05.190Z", "written_ts": 1532442965190007000, "correlation_id": "e5499f3a-8f4e-11e8-bfc0-dca9048e7328", "layer": "python", "type": "log", "logger": "__main__", "thread": "MainThread", "level": "INFO", "line_no": 20, "msg": "Hi"}
2018-07-24 22:36:05,190 test_helper  INFO     Calling helper method
Calling helper method
2018-07-24 22:36:05,190 cf.flask.logger INFO     
{"component_id": "-", "component_name": "-", "component_instance": 0, "space_id": "-", "space_name": "-", "container_id": "-", "component_type": "application", "written_at": "2018-07-24T14:36:05.190Z", "written_ts": 1532442965190740000, "correlation_id": "e5499f3a-8f4e-11e8-bfc0-dca9048e7328", "layer": "python", "type": "request", "direction": "IN", "remote_user": "redacted", "request": "/", "referer": "redacted", "x_forwarded_for": "redacted", "protocol": "HTTP/1.1", "method": "GET", "remote_ip": "redacted", "request_size_b": -1, "remote_host": "redacted", "remote_port": "redacted", "request_received_at": "2018-07-24T14:36:05.189Z", "response_sent_at": "2018-07-24T14:36:05.190Z", "response_time_ms": 1, "response_status": 200, "response_size_b": 2, "response_content_type": "text/html; charset=utf-8"}

In the logging part, we are formatting the log so that we can see which module is being called, in this case it will print the helper module.

You can see the helper method is being printed twice, one with the logging format, another is like a print() function which I think came from this python-logger.

• Is there a sequence on when to init the flask logging?
• We are definitely using many vendor libraries like mlpkit, and they too, are all modules that does "import logging", is this an issue?

[alexpenev-s]

The reason for the two messages is that

logging.basicConfig(stream=sys.stdout,
                    level=logging.DEBUG,
                    format='%(asctime)s %(name)-12s %(levelname)-8s %(message)s')

Configures a logger and it displays:

2018-07-24 22:36:05,190 test_helper INFO Calling helper method

flask_logging.init(app, logging.DEBUG)

Configures the JSON logger and it displays the message a second time.

There are two options.

• remove the logging.basicConfig.... line
• move the logging.basicConfig.... line after the flask_logging.init(app, logging.DEBUG) line

[dennygee]

Hi,

I tried out both the option, and below is what was printed out:

{"component_id": "-", "component_name": "-", "component_instance": 0, "space_id": "-", "space_name": "-", "container_id": "-", "component_type": "application", "written_at": "2018-07-25T05:05:24.200Z", "written_ts": 1532495124200846000, "correlation_id": "567b03a2-8fc8-11e8-836a-dca9048e7328", "layer": "python", "type": "log", "logger": "__main__", "thread": "MainThread", "level": "INFO", "line_no": 21, "msg": "Hi"}
Calling helper method
{"component_id": "-", "component_name": "-", "component_instance": 0, "space_id": "-", "space_name": "-", "container_id": "-", "component_type": "application", "written_at": "2018-07-25T05:05:24.201Z", "written_ts": 1532495124201521000, "correlation_id": "567b03a2-8fc8-11e8-836a-dca9048e7328", "layer": "python", "type": "request", "direction": "IN", "remote_user": "redacted", "request": "/", "referer": "redacted", "x_forwarded_for": "redacted", "protocol": "HTTP/1.1", "method": "GET", "remote_ip": "redacted", "request_size_b": -1, "remote_host": "redacted", "remote_port": "redacted", "request_received_at": "2018-07-25T05:05:24.200Z", "response_sent_at": "2018-07-25T05:05:24.201Z", "response_time_ms": 1, "response_status": 200, "response_size_b": 2, "response_content_type": "text/html; charset=utf-8"}

Shouldn't the flask_logging.init() affect all loggers across modules? In this case, I would expect the test_helper module to also output the json logs, but it is not.

[alexpenev-s]

Hi, Yes is does affect all modules. However in the above case - when you call from test_helper import call_help It will execute logger = logging.getLogger(name) before flask_logging.init and this will create a logger not managed by the logging library.

There are two solutions:

• Call flask_logging.init and then import all modules that create loggers
• Move logger = logging.getLogger(name) within the handler ex.

def call_help():
    logger = logging.getLogger(__name__)
    logger.info("Calling helper method")

[dennygee]

Hi,

This works now, and I also understand your point as well. Very appreciated and thank you so much for the help in this issue.

The next step for me is probably to re-sequence how our flask app gets created and inject in the flask_logger.