elasticsearch-py icon indicating copy to clipboard operation
elasticsearch-py copied to clipboard

Published 20 hours ago • verified publisher icon elastic

Infinite loop of logs when using elasticsearch in logging.Handler

Open Kremzon opened this issue 1 year ago • 2 comments

Elasticsearch version (bin/elasticsearch --version): Version: 8.6.2, Build: docker/2d58d0f136141f03239816a4e360a8d17b6d8f29/2023-02-13T09:35:20.314882762Z, JVM: 19.0.2 elasticsearch-py version (elasticsearch.__versionstr__): '8.6.2'

Description of the problem including expected versus actual behavior: I want to send all the logs to ES so I created a log handler that sends all logs to an index. The problem is for every post request the library makes to ES to save the log, another log gets written and it becomes an infinite loop of logs that spams the server.

2023-03-13 14:48:30 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.022s]
2023-03-13 14:48:30 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.004s]
2023-03-13 14:48:30 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:30 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.004s]
2023-03-13 14:48:30 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:30 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.050s]
2023-03-13 14:48:30 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:30 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:30 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.004s]
2023-03-13 14:48:30 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:30 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:30 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:30 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:30 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.002s]
2023-03-13 14:48:30 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:30 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:30 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:30 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.004s]
2023-03-13 14:48:30 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.005s]
2023-03-13 14:48:30 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.005s]
2023-03-13 14:48:30 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.004s]
2023-03-13 14:48:30 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.004s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.049s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.002s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.004s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.004s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.005s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.004s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.060s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.002s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.004s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.004s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.004s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.004s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.050s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.051s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.004s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.004s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.004s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.004s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.004s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.004s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.004s]
2023-03-13 14:48:31 INFO     28440 POST http://localhost:9200/my_index/_doc [status:201 duration:0.003s]

I found a workaround by running logging.getLogger('elastic_transport.transport').setLevel(logging.WARNING)

Steps to reproduce: Here is the code to reproduce

import datetime
import logging
import time

from elasticsearch import Elasticsearch


class ElasticsearchHandler(logging.Handler):
    def __init__(self):
        super().__init__()
        self._elasticSearch = None

        self._elasticSearch = Elasticsearch("http://localhost:9200")

    def emit(self, record: logging.LogRecord):
        try:
            body = {
                "timestamp": datetime.datetime.now(),
                "message": record.getMessage()
            }

            self._elasticSearch.index(index="my_index", document=body)
        except Exception:
            self.handleError(record)

    def close(self):
        if self._elasticSearch is not None:
            self._elasticSearch.close()

logging.basicConfig(level=logging.INFO)
logger = logging.getLogger()

esHandler = ElasticsearchHandler()
logger.addHandler(esHandler)

logging.info("Hello")

time.sleep(10)

esHandler.close()

Kremzon avatar Mar 13 '23 12:03 Kremzon

@Kremzon this is happening because the logger is used in the perform_request() function of the transport that is executed by the

self._elasticSearch.index(index="my_index", document=body)

of your ElasticsearchHandler. That means each time the logger is trigger by an endpoint, your handler will call index that will trigger another logger call and so on. If you want to send log in Elasticsearch the best option is to use Elastic Common Schema (ECS) logger for the Python logging library. We have also an example for this use case here.

ezimuel avatar Mar 16 '23 20:03 ezimuel

@ezimuel What if I don't want to use files?

Kremzon avatar Apr 10 '23 05:04 Kremzon