You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@pulsar.apache.org by GitBox <gi...@apache.org> on 2021/06/19 07:18:09 UTC
[GitHub] [pulsar] lbenc135 opened a new pull request #10981: [python-client] Fixed crash when using Python logger
lbenc135 opened a new pull request #10981:
URL: https://github.com/apache/pulsar/pull/10981
### Motivation
In some cases, the Python client would crash when using the new `logger` option. This happens when a Pulsar message is sent asynchronously, but soon after the program exits (and even then, not always).
For example, when doing Django migrations which include sending a message:
```
...
[2021-06-19 06:53:57.691] [INFO]: Created connection for pulsar://localhost:6650
[2021-06-19 06:53:57.693] [INFO]: [127.0.0.1:36536 -> 127.0.0.1:6650] Connected to broker
[2021-06-19 06:53:57.695] [INFO]: [persistent://public/default/dashboard-global_context-emit, ] Getting connection from pool
[2021-06-19 06:53:57.707] [INFO]: [persistent://public/default/dashboard-global_context-emit, ] Created producer on broker [127.0.0.1:36536 -> 127.0.0.1:6650]
...
[2021-06-19 06:53:57.728] [DEBUG]: Sending message to topic .....
Applying dashboard.0001_initial... OK
Applying templating.0001_initial... OK
Error in sys.excepthook:
Original exception was:
Failed to migrate dashboard! Return code was: -6
```
This happens because Pulsar tries to log messages after Python already started finalizing, so the client can't get a GIL lock, which crashes the whole client.
### Modifications
Following the instructions at https://docs.python.org/3/c-api/init.html#c.PyGILState_Ensure, I added a check for when Python is finalizing, and if it is, we fallback to the default console logger (the log level is still respected correctly).
Now it looks like this:
```
...
[2021-06-19 06:45:15.561] [INFO]: Created connection for pulsar://localhost:6650
[2021-06-19 06:45:15.563] [INFO]: [127.0.0.1:35930 -> 127.0.0.1:6650] Connected to broker
[2021-06-19 06:45:15.568] [INFO]: [persistent://public/default/dashboard-global_context-emit, ] Getting connection from pool
[2021-06-19 06:45:15.586] [INFO]: [persistent://public/default/zaba-dashboard-global_context-emit, ] Created producer on broker [127.0.0.1:35930 -> 127.0.0.1:6650]
...
[2021-06-19 06:45:15.604] [DEBUG]: Sending message to topic .....
Applying dashboard.0001_initial... OK
Applying templating.0001_initial... OK
2021-06-19 06:45:16.200 INFO [139853253269312] ClientConnection:1446 | [127.0.0.1:35930 -> 127.0.0.1:6650] Connection closed
2021-06-19 06:45:16.200 ERROR [139853099652672] ClientConnection:531 | [127.0.0.1:35930 -> 127.0.0.1:6650] Read failed: Operation canceled
2021-06-19 06:45:16.201 INFO [139853253269312] ClientConnection:261 | [127.0.0.1:35930 -> 127.0.0.1:6650] Destroyed connection
2021-06-19 06:45:16.201 INFO [139853253269312] ProducerImpl:561 | Producer - [persistent://public/default/dashboard-global_context-emit, standalone-0-120] , [batchMessageContainer = { BatchMessageContainer [size = 0] [bytes = 0] [maxSize = 1000] [maxBytes = 131072] [topicName = persistent://public/default/dashboard-global_context-emit] [numberOfBatchesSent_ = 1] [averageBatchSize_ = 1] }]
Successfully migrated dashboard
```
### Verifying this change
- [ ] Make sure that the change passes the CI checks.
It's very hard to write a test for this, or at least I have no idea how to do it.
### Does this pull request potentially affect one of the following parts:
Doesn't affect anything.
### Documentation
No documentation needed, it's a bugfix.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [pulsar] BewareMyPower commented on pull request #10981: [python-client] Fixed crash when using Python logger
Posted by GitBox <gi...@apache.org>.
BewareMyPower commented on pull request #10981:
URL: https://github.com/apache/pulsar/pull/10981#issuecomment-866480642
There're a chance of memory leak theoretically but **it might never happen**.
```c++
// copy constructor
LoggerWrapper(const LoggerWrapper& other) {
/* ... */
fallbackLogger = other.fallbackLogger;
}
// copy assignment operator
LoggerWrapper& operator=(const LoggerWrapper& other) { /* ... */ }
```
If you managed a raw pointer `fallbackLogger`, these methods may cause that two `LoggerWrapper` objects share the same `fallbackLogger` but no reference count is recorded. So the pointer (`fallbackLogger`) could be deleted twice for each destructor of `LoggerWrapper`.
There're two ways to fix it. One way is just to remove these two methods. Because currently no copy of `Logger` happens in Pulsar C++ library's implementation. These two methods could never be called so I said the memory leak might never happen before.
The other way is use a `std::shared_ptr<Logger>` instead the raw pointer `Logger`. `std::shared_ptr` maintains a reference count for the pointer and the destructor would be called only once when the reference count became zero.
Just change
```c++
Logger* fallbackLogger;
```
to
```c++
std::shared_ptr<Logger> fallbackLogger;
```
And change
```c++
fallbackLogger = factory->getLogger(filename);
```
to
```c++
fallbackLogger.reset(factory->getLogger(filename));
```
Finally remove `delete fallbackLogger` in the destructor.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [pulsar] sijie merged pull request #10981: [python-client] Fixed crash when using Python logger
Posted by GitBox <gi...@apache.org>.
sijie merged pull request #10981:
URL: https://github.com/apache/pulsar/pull/10981
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@pulsar.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [pulsar] BewareMyPower commented on a change in pull request #10981: [python-client] Fixed crash when using Python logger
Posted by GitBox <gi...@apache.org>.
BewareMyPower commented on a change in pull request #10981:
URL: https://github.com/apache/pulsar/pull/10981#discussion_r656716009
##########
File path: pulsar-client-cpp/python/src/config.cc
##########
@@ -110,21 +112,29 @@ class LoggerWrapper: public Logger {
public:
- LoggerWrapper(const std::string &logger, PyObject* pyLogger) {
+ LoggerWrapper(const std::string &filename, PyObject* pyLogger) {
_pyLogger = pyLogger;
Py_XINCREF(_pyLogger);
+ fallbackLogger = (new ConsoleLoggerFactory())->getLogger(filename);
Review comment:
What I said about singleton is to create a global `ConsoleLoggerFactory` object and reuse it, in C++ it can be implemented simply like:
```c++
inline ConsoleLoggerFactory& globalConsoleLoggerFactory() {
static ConsoleLoggerFactory factory; // the object exists during the whole lifetime of the process
return factory;
}
```
Then you only need to call `globalConsoleLoggerFactory().getLogger("xxx")` to create a logger from the factory.
But your fix is also OK, you create a `ConsoleLoggerFactory` and delete it every time a `LoggerWrapper` object is constructed and destructed. Since the logger created by it doesn't bind to the factory, your fix is also OK.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [pulsar] BewareMyPower commented on a change in pull request #10981: [python-client] Fixed crash when using Python logger
Posted by GitBox <gi...@apache.org>.
BewareMyPower commented on a change in pull request #10981:
URL: https://github.com/apache/pulsar/pull/10981#discussion_r655484022
##########
File path: pulsar-client-cpp/python/src/config.cc
##########
@@ -110,21 +112,29 @@ class LoggerWrapper: public Logger {
public:
- LoggerWrapper(const std::string &logger, PyObject* pyLogger) {
+ LoggerWrapper(const std::string &filename, PyObject* pyLogger) {
_pyLogger = pyLogger;
Py_XINCREF(_pyLogger);
+ fallbackLogger = (new ConsoleLoggerFactory())->getLogger(filename);
Review comment:
`new ConsoleLoggerFactory()` will cause memory leak. `getLogger` method will also cause memory leak, see the implementation in `lib/ConsoleLoggerFactoryImpl.h`:
```c++
Logger* getLogger(const std::string& fileName) { return new SimpleLogger(std::cout, fileName, level_); }
```
The implementation is okay in C++ client because what `getLogger` returns will be passed to the constructor of a thread local `std::unique_ptr` in `lib/LogUtils.h`:
```c++
#define DECLARE_LOG_OBJECT() \
static pulsar::Logger* logger() { \
static thread_local std::unique_ptr<pulsar::Logger> threadSpecificLogPtr; \
pulsar::Logger* ptr = threadSpecificLogPtr.get(); \
if (PULSAR_UNLIKELY(!ptr)) { \
std::string logger = pulsar::LogUtils::getLoggerName(__FILE__); \
threadSpecificLogPtr.reset(pulsar::LogUtils::getLoggerFactory()->getLogger(logger)); \
ptr = threadSpecificLogPtr.get(); \
} \
return ptr; \
}
```
And the what `new ConsoleLoggerFactory` returns will be passed to `ClientConfiguration::setLogger`, which wraps the raw pointer into a `std::shared_ptr`. See `lib/ClientConfiguration.cc`:
```c++
ClientConfiguration& ClientConfiguration::setLogger(LoggerFactory* loggerFactory) {
impl_->loggerFactory.reset(loggerFactory);
return *this;
}
```
However, in Python wrapper, only the allocated `LoggerWrapper` will be passed to the `setLogger`.
Therefore, you need to clean up the `fallbackLogger` in the destructor of `LoggerWrapper`. As for the `ConsoleLoggerFactory`, it's better to use a singleton.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [pulsar] lbenc135 commented on a change in pull request #10981: [python-client] Fixed crash when using Python logger
Posted by GitBox <gi...@apache.org>.
lbenc135 commented on a change in pull request #10981:
URL: https://github.com/apache/pulsar/pull/10981#discussion_r656499782
##########
File path: pulsar-client-cpp/python/src/config.cc
##########
@@ -110,21 +112,29 @@ class LoggerWrapper: public Logger {
public:
- LoggerWrapper(const std::string &logger, PyObject* pyLogger) {
+ LoggerWrapper(const std::string &filename, PyObject* pyLogger) {
_pyLogger = pyLogger;
Py_XINCREF(_pyLogger);
+ fallbackLogger = (new ConsoleLoggerFactory())->getLogger(filename);
Review comment:
Thanks @BewareMyPower for the detailed explanation, C++ is not my first language (nor second) so I appreciate it. Can you take a look again? I think I fixed it, although I'm not sure which singleton you were referring to.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [pulsar] BewareMyPower commented on a change in pull request #10981: [python-client] Fixed crash when using Python logger
Posted by GitBox <gi...@apache.org>.
BewareMyPower commented on a change in pull request #10981:
URL: https://github.com/apache/pulsar/pull/10981#discussion_r655484022
##########
File path: pulsar-client-cpp/python/src/config.cc
##########
@@ -110,21 +112,29 @@ class LoggerWrapper: public Logger {
public:
- LoggerWrapper(const std::string &logger, PyObject* pyLogger) {
+ LoggerWrapper(const std::string &filename, PyObject* pyLogger) {
_pyLogger = pyLogger;
Py_XINCREF(_pyLogger);
+ fallbackLogger = (new ConsoleLoggerFactory())->getLogger(filename);
Review comment:
`new ConsoleLoggerFactory()` will cause memory leak. `getLogger` method will also cause memory leak, see the implementation in `lib/ConsoleLoggerFactoryImpl.h`:
```c++
Logger* getLogger(const std::string& fileName) { return new SimpleLogger(std::cout, fileName, level_); }
```
The implementation is okay in C++ client because what `getLogger` returns will be passed to the constructor of a thread local `std::unique_ptr` in `lib/LogUtils.h`:
```c++
#define DECLARE_LOG_OBJECT() \
static pulsar::Logger* logger() { \
static thread_local std::unique_ptr<pulsar::Logger> threadSpecificLogPtr; \
pulsar::Logger* ptr = threadSpecificLogPtr.get(); \
if (PULSAR_UNLIKELY(!ptr)) { \
std::string logger = pulsar::LogUtils::getLoggerName(__FILE__); \
threadSpecificLogPtr.reset(pulsar::LogUtils::getLoggerFactory()->getLogger(logger)); \
ptr = threadSpecificLogPtr.get(); \
} \
return ptr; \
}
```
And the what `new ConsoleLoggerFactory` returns will be passed to `ClientConfiguration::setLogger`, which wraps the raw pointer into a `std::shared_ptr`. See `lib/ClientConfiguration.cc`:
```c++
ClientConfiguration& ClientConfiguration::setLogger(LoggerFactory* loggerFactory) {
impl_->loggerFactory.reset(loggerFactory);
return *this;
}
```
However, in Python wrapper, only the allocated `LoggerWrapper` will be passed to the `setLogger`.
Therefore, you need to clean up the `fallbackLogger` in the destructor of `LoggerWrapper`. As for the `ConsoleLoggerFactory`, it's better to use a singleton.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [pulsar] lbenc135 commented on a change in pull request #10981: [python-client] Fixed crash when using Python logger
Posted by GitBox <gi...@apache.org>.
lbenc135 commented on a change in pull request #10981:
URL: https://github.com/apache/pulsar/pull/10981#discussion_r656822634
##########
File path: pulsar-client-cpp/python/src/config.cc
##########
@@ -110,61 +112,76 @@ class LoggerWrapper: public Logger {
public:
- LoggerWrapper(const std::string &logger, PyObject* pyLogger) {
+ LoggerWrapper(const std::string &filename, PyObject* pyLogger) {
_pyLogger = pyLogger;
Py_XINCREF(_pyLogger);
+ std::unique_ptr<LoggerFactory> factory(new ConsoleLoggerFactory());
+ fallbackLogger = factory->getLogger(filename);
+
_updateCurrentPythonLogLevel();
}
- LoggerWrapper(const LoggerWrapper& other) {
+ LoggerWrapper(LoggerWrapper& other) {
Review comment:
I removed the whole method to avoid bloating the code unnecessarily and the potential memory leak.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [pulsar] BewareMyPower commented on a change in pull request #10981: [python-client] Fixed crash when using Python logger
Posted by GitBox <gi...@apache.org>.
BewareMyPower commented on a change in pull request #10981:
URL: https://github.com/apache/pulsar/pull/10981#discussion_r656713894
##########
File path: pulsar-client-cpp/python/src/config.cc
##########
@@ -110,61 +112,76 @@ class LoggerWrapper: public Logger {
public:
- LoggerWrapper(const std::string &logger, PyObject* pyLogger) {
+ LoggerWrapper(const std::string &filename, PyObject* pyLogger) {
_pyLogger = pyLogger;
Py_XINCREF(_pyLogger);
+ std::unique_ptr<LoggerFactory> factory(new ConsoleLoggerFactory());
+ fallbackLogger = factory->getLogger(filename);
+
_updateCurrentPythonLogLevel();
}
- LoggerWrapper(const LoggerWrapper& other) {
+ LoggerWrapper(LoggerWrapper& other) {
Review comment:
```suggestion
LoggerWrapper(const LoggerWrapper& other) {
```
Don't remove the const qualifier. Or do you have any reason to remove it?
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org