Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Infinite loop of logs when using elasticsearch in logging.Handler #2177

Open
Kremzon opened this issue Mar 13, 2023 · 2 comments
Open

Infinite loop of logs when using elasticsearch in logging.Handler #2177

Kremzon opened this issue Mar 13, 2023 · 2 comments

Comments

@Kremzon
Copy link

Kremzon commented Mar 13, 2023

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()
@ezimuel
Copy link
Contributor

ezimuel commented Mar 16, 2023

@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.

@Kremzon
Copy link
Author

Kremzon commented Apr 10, 2023

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@ezimuel @Kremzon