search

log4mongo / log4mongo-python

python logging handler for mongo database
http://log4mongo.org
Other
111 stars 37 forks source link

Cannot use MongoClient after close #58

Open nabeenb opened 8 months ago

nabeenb commented 8 months ago 
raise InvalidOperation("Cannot use MongoClient after close")

pymongo.errors.InvalidOperation: Cannot use MongoClient after close

I am getting this error while logging from a FastAPI python client with async operation.

NyaMisty commented 6 months ago

Having same issue here. Log looks like this:

--- Logging error ---
Traceback (most recent call last):
  File "XXX/venv/lib/python3.7/site-packages/log4mongo/handlers.py", line 186, in emit
    getattr(self.collection, write_method)(self.format(record))
  File "XXX/venv/lib/python3.7/site-packages/pymongo/collection.py", line 665, in insert_one
    comment=comment,
  File "XXX/venv/lib/python3.7/site-packages/pymongo/collection.py", line 599, in _insert_one
    acknowledged, _insert_command, session, operation=_Op.INSERT
  File "XXX/venv/lib/python3.7/site-packages/pymongo/mongo_client.py", line 1569, in _retryable_write
    return self._retry_with_session(retryable, func, s, bulk, operation, operation_id)
  File "XXX/venv/lib/python3.7/site-packages/pymongo/mongo_client.py", line 1461, in _retry_with_session
    operation_id=operation_id,
  File "XXX/venv/lib/python3.7/site-packages/pymongo/_csot.py", line 108, in csot_wrapper
    return func(self, *args, **kwargs)
  File "XXX/venv/lib/python3.7/site-packages/pymongo/mongo_client.py", line 1500, in _retry_internal
    operation_id=operation_id,
  File "XXX/venv/lib/python3.7/site-packages/pymongo/mongo_client.py", line 2347, in run
    return self._read() if self._is_read else self._write()
  File "XXX/venv/lib/python3.7/site-packages/pymongo/mongo_client.py", line 2450, in _write
    self._server = self._get_server()
  File "XXX/venv/lib/python3.7/site-packages/pymongo/mongo_client.py", line 2439, in _get_server
    operation_id=self._operation_id,
  File "XXX/venv/lib/python3.7/site-packages/pymongo/mongo_client.py", line 1303, in _select_server
    topology = self._get_topology()
  File "XXX/venv/lib/python3.7/site-packages/pymongo/mongo_client.py", line 1246, in _get_topology
    self._topology.open()
  File "XXX/venv/lib/python3.7/site-packages/pymongo/topology.py", line 216, in open
    self._ensure_opened()
  File "XXX/venv/lib/python3.7/site-packages/pymongo/topology.py", line 704, in _ensure_opened
    raise InvalidOperation("Cannot use MongoClient after close")
pymongo.errors.InvalidOperation: Cannot use MongoClient after close
Call stack:
  File "manage.py", line 42, in <module>
    manager.run()
  File "XXX/addons/commands/__init__.py", line 350, in run
    result = self.handle(argv[0], argv[1:])
  File "XXX/addons/commands/__init__.py", line 319, in handle
    res = handle(*args, **config)
  File "XXX/addons/commands/commands.py", line 195, in __call__
    return self.run(*args, **kwargs)
  File "XXX/scripts/task_runner.py", line 47, in run
    self.run_coro(_run())
  File "XXX/scripts/task_runner.py", line 58, in run_coro
    loop.run_until_complete(task)
  File "/usr/lib/python3.7/asyncio/base_events.py", line 566, in run_until_complete
    self.run_forever()
  File "/usr/lib/python3.7/asyncio/base_events.py", line 534, in run_forever
    self._run_once()
  File "/usr/lib/python3.7/asyncio/base_events.py", line 1771, in _run_once
    handle._run()
  File "/usr/lib/python3.7/asyncio/events.py", line 88, in _run
    self._context.run(self._callback, *self._args)
  File "XXX/core/utils.py", line 329, in log_exceptions
    return await awaitable
  File "XXX/core/crawler.py", line 182, in worker
    success = await consumer(wrapped_url)
  File "XXX/core/crawler.py", line 215, in consumer_content_page
    self.logger.warning("Save Detail Event didn't return result, default to success...")
  File "/usr/lib/python3.7/logging/__init__.py", line 1390, in warning
    self._log(WARNING, msg, args, **kwargs)
  File "/usr/lib/python3.7/logging/__init__.py", line 1514, in _log
    self.handle(record)
  File "/usr/lib/python3.7/logging/__init__.py", line 1524, in handle
    self.callHandlers(record)
  File "/usr/lib/python3.7/logging/__init__.py", line 1586, in callHandlers
    hdlr.handle(record)
  File "/usr/lib/python3.7/logging/__init__.py", line 894, in handle
    self.emit(record)
  File "XXX/venv/lib/python3.7/site-packages/log4mongo/handlers.py", line 189, in emit
    self.handleError(record)
Message: "Save Detail Event didn't return result, default to success..."
Arguments: ()
NyaMisty commented 6 months ago

I found the reason: some nasty framework will reconfigure logging, which will then logging.shutdown() to clean all logging handler I patched pymongo's close function to see who's the culprit.

Traceback (most recent call last):
  File "manage.py", line 16, in <module>
    app = Sanic(__name__)
  File "XXX/venv/lib/python3.7/site-packages/sanic/app.py", line 199, in __init__
    logging.config.dictConfig(dict_config)  # type: ignore
  File "/usr/lib/python3.7/logging/config.py", line 800, in dictConfig
    dictConfigClass(config).configure()
  File "/usr/lib/python3.7/logging/config.py", line 536, in configure
    _clearExistingHandlers()
  File "/usr/lib/python3.7/logging/config.py", line 273, in _clearExistingHandlers
    logging.shutdown(logging._handlerList[:])
  File "/usr/lib/python3.7/logging/__init__.py", line 2034, in shutdown
    h.close()
  File "XXX/venv/lib/python3.7/site-packages/log4mongo/handlers.py", line 180, in close
    self.connection.close()
  File "XXX/venv/lib/python3.7/site-packages/pymongo/mongo_client.py", line 1132, in close
    self._topology.close()
  File "XXX/venv/lib/python3.7/site-packages/pymongo/topology.py", line 484, in close
    raise RuntimeError('????hjfhjerhijwkvj')
RuntimeError: ????hjfhjerhijwkvj
Error in atexit._run_exitfuncs:
Traceback (most recent call last):
  File "/usr/lib/python3.7/logging/__init__.py", line 2034, in shutdown
    h.close()
  File "XXX/venv/lib/python3.7/site-packages/log4mongo/handlers.py", line 180, in close
    self.connection.close()
  File "XXX/venv/lib/python3.7/site-packages/pymongo/mongo_client.py", line 1132, in close
    self._topology.close()
  File "XXX/venv/lib/python3.7/site-packages/pymongo/topology.py", line 484, in close
    raise RuntimeError('????hjfhjerhijwkvj')
RuntimeError: ????hjfhjerhijwkvj

log4mongo should actually handle this situation. Currently I solved this problem by disabling log4mongo LogHandler's close() function