You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@zookeeper.apache.org by "Marshall McMullen (Created) (JIRA)" <ji...@apache.org> on 2012/02/23 23:19:50 UTC
[jira] [Created] (ZOOKEEPER-1400) Allow logging via callback
instead of raw FILE pointer
Allow logging via callback instead of raw FILE pointer
------------------------------------------------------
Key: ZOOKEEPER-1400
URL: https://issues.apache.org/jira/browse/ZOOKEEPER-1400
Project: ZooKeeper
Issue Type: Improvement
Components: c client
Affects Versions: 3.4.2
Environment: Linux
Reporter: Marshall McMullen
Fix For: 3.4.2
Attachments: case-2739.patch
The existing logging framework inside the C client uses a raw FILE*. Using a FILE* is very limiting and potentially dangerous. A safer alternative is to just provide a callback that the C client will call for each message. In our environment, we saw some really nasty issues with multiple threads all connecting to zookeeper via the C Client related to the use of a raw FILE*. Specifically, if the FILE * is closed and that file descriptor is reused by the kernel before the C client is notified then the C client will use it's static global logStream pointer for subsequent logging messages. That FILE* is now a loose cannon! In our environment, we saw zookeeper log messages ending up in other sockets and even in our core data path. Clearly this is dangerous. In our particular case, we'd omitted a call to zoo_set_log_stream(NULL) to notify C client that the FILE* has been closed. However, even with that bug fixed, there's still a race condition where log messages in flight may be sent before the C client is notified of the FILE closure, and the same problem can happen.
Other issues we've seen involved multiple threads, wherein one would close the FILE*, and that's a global change that affects all threads connected within that process. That's a pretty nasty limitation as well.
My proposed change is to allow setting a callback for log messages. A callback is used in preference to a raw FILE*. If no callback is set, then it will fallback to the existing FILE*. If that's not set, then it falls back to stderr as it always has.
While refactoring this code, I removed the need for the double parens in all the LOG macros as that wasn't necessary and didn't fit with my new approach.
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Assigned] (ZOOKEEPER-1400) Allow logging via callback
instead of raw FILE pointer
Posted by "Patrick Hunt (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/ZOOKEEPER-1400?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Patrick Hunt reassigned ZOOKEEPER-1400:
---------------------------------------
Assignee: Marshall McMullen
> Allow logging via callback instead of raw FILE pointer
> ------------------------------------------------------
>
> Key: ZOOKEEPER-1400
> URL: https://issues.apache.org/jira/browse/ZOOKEEPER-1400
> Project: ZooKeeper
> Issue Type: Improvement
> Components: c client
> Affects Versions: 3.5.0
> Environment: Linux
> Reporter: Marshall McMullen
> Assignee: Marshall McMullen
> Fix For: 3.5.0
>
> Attachments: ZOOKEEPER-1400-1.patch, ZOOKEEPER-1400.patch
>
>
> The existing logging framework inside the C client uses a raw FILE*. Using a FILE* is very limiting and potentially dangerous. A safer alternative is to just provide a callback that the C client will call for each message. In our environment, we saw some really nasty issues with multiple threads all connecting to zookeeper via the C Client related to the use of a raw FILE*. Specifically, if the FILE * is closed and that file descriptor is reused by the kernel before the C client is notified then the C client will use it's static global logStream pointer for subsequent logging messages. That FILE* is now a loose cannon! In our environment, we saw zookeeper log messages ending up in other sockets and even in our core data path. Clearly this is dangerous. In our particular case, we'd omitted a call to zoo_set_log_stream(NULL) to notify C client that the FILE* has been closed. However, even with that bug fixed, there's still a race condition where log messages in flight may be sent before the C client is notified of the FILE closure, and the same problem can happen.
> Other issues we've seen involved multiple threads, wherein one would close the FILE*, and that's a global change that affects all threads connected within that process. That's a pretty nasty limitation as well.
> My proposed change is to allow setting a callback for log messages. A callback is used in preference to a raw FILE*. If no callback is set, then it will fallback to the existing FILE*. If that's not set, then it falls back to stderr as it always has.
> While refactoring this code, I removed the need for the double parens in all the LOG macros as that wasn't necessary and didn't fit with my new approach.
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (ZOOKEEPER-1400) Allow logging via callback
instead of raw FILE pointer
Posted by "Michi Mutsuzaki (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/ZOOKEEPER-1400?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13263546#comment-13263546 ]
Michi Mutsuzaki commented on ZOOKEEPER-1400:
--------------------------------------------
Hi Marshall,
Sorry for the late response. This is a great patch! Here are my comments:
* The documentation for {{zoo_set_log_callback()}} should make it clear that the callback will be invoked by multiple threads and therefore it needs to be thread-safe.
* We probably want to log something if {{get_format_log_buffer()}} returns NULL, something similar to "format_log_message: Unable to allocate memory buffer".
* Do you need to pass {{FORMAT_LOG_BUF_SIZE-1}} to {{snprintf()}}, or would {{FORMAT_LOG_BUF_SIZE}} work? I thought {{snprintf()}} guarantees that the output is null-terminated.
* This patch should be unit-tested (now that it's much easier to unit test the logging code with the callback :)).
* It would be great if you can share how you are using the callback for your logging on our wiki page. I'm pretty sure many people will find it very useful.
* {quote}
While refactoring this code, I removed the need for the double parens in all the LOG macros as that wasn't necessary and didn't fit with my new approach.
{quote}
Cool!
Regarding Stephen's comment:
* Yes, please put per-connection logging on a separate jira.
* {quote}
This means there is now a limit on log size that wasn't there before. Have you made sure this buffer can handle all possible log messages?
{quote}
The longest line I got from the unit test was less than 500 characters. I also eyeballed all the LOG_* calls, and they all look much less than 4096 characters. It's difficult to be absolutely sure since the log message is not fixed length, but I think it would be ok.
* {quote}
Maybe those should be reserved for a separate change just to keep things tidy?
{quote}
Yes, I generally prefer patches without cosmetic changes.
Thanks!
--Michi
> Allow logging via callback instead of raw FILE pointer
> ------------------------------------------------------
>
> Key: ZOOKEEPER-1400
> URL: https://issues.apache.org/jira/browse/ZOOKEEPER-1400
> Project: ZooKeeper
> Issue Type: Improvement
> Components: c client
> Affects Versions: 3.4.2
> Environment: Linux
> Reporter: Marshall McMullen
> Fix For: 3.4.2
>
> Attachments: case-2739.patch
>
>
> The existing logging framework inside the C client uses a raw FILE*. Using a FILE* is very limiting and potentially dangerous. A safer alternative is to just provide a callback that the C client will call for each message. In our environment, we saw some really nasty issues with multiple threads all connecting to zookeeper via the C Client related to the use of a raw FILE*. Specifically, if the FILE * is closed and that file descriptor is reused by the kernel before the C client is notified then the C client will use it's static global logStream pointer for subsequent logging messages. That FILE* is now a loose cannon! In our environment, we saw zookeeper log messages ending up in other sockets and even in our core data path. Clearly this is dangerous. In our particular case, we'd omitted a call to zoo_set_log_stream(NULL) to notify C client that the FILE* has been closed. However, even with that bug fixed, there's still a race condition where log messages in flight may be sent before the C client is notified of the FILE closure, and the same problem can happen.
> Other issues we've seen involved multiple threads, wherein one would close the FILE*, and that's a global change that affects all threads connected within that process. That's a pretty nasty limitation as well.
> My proposed change is to allow setting a callback for log messages. A callback is used in preference to a raw FILE*. If no callback is set, then it will fallback to the existing FILE*. If that's not set, then it falls back to stderr as it always has.
> While refactoring this code, I removed the need for the double parens in all the LOG macros as that wasn't necessary and didn't fit with my new approach.
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (ZOOKEEPER-1400) Allow logging via callback
instead of raw FILE pointer
Posted by "Stephen Tyree (Commented) (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/ZOOKEEPER-1400?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13215686#comment-13215686 ]
Stephen Tyree commented on ZOOKEEPER-1400:
------------------------------------------
This is a really great change. I've gone so far as to both create a global FILE* singleton instance to prevent race conditions from closing the handle and to create a pipe that is written to from a FILE* and read from a part of my code to deal with this interface's shortcomings. If we're going this far, might I also suggest we add logging on a per connection basis? For a large application using Zookeeper, there might be multiple consumers/connections who want to manage logs each in their own special way.
> Allow logging via callback instead of raw FILE pointer
> ------------------------------------------------------
>
> Key: ZOOKEEPER-1400
> URL: https://issues.apache.org/jira/browse/ZOOKEEPER-1400
> Project: ZooKeeper
> Issue Type: Improvement
> Components: c client
> Affects Versions: 3.4.2
> Environment: Linux
> Reporter: Marshall McMullen
> Fix For: 3.4.2
>
> Attachments: case-2739.patch
>
>
> The existing logging framework inside the C client uses a raw FILE*. Using a FILE* is very limiting and potentially dangerous. A safer alternative is to just provide a callback that the C client will call for each message. In our environment, we saw some really nasty issues with multiple threads all connecting to zookeeper via the C Client related to the use of a raw FILE*. Specifically, if the FILE * is closed and that file descriptor is reused by the kernel before the C client is notified then the C client will use it's static global logStream pointer for subsequent logging messages. That FILE* is now a loose cannon! In our environment, we saw zookeeper log messages ending up in other sockets and even in our core data path. Clearly this is dangerous. In our particular case, we'd omitted a call to zoo_set_log_stream(NULL) to notify C client that the FILE* has been closed. However, even with that bug fixed, there's still a race condition where log messages in flight may be sent before the C client is notified of the FILE closure, and the same problem can happen.
> Other issues we've seen involved multiple threads, wherein one would close the FILE*, and that's a global change that affects all threads connected within that process. That's a pretty nasty limitation as well.
> My proposed change is to allow setting a callback for log messages. A callback is used in preference to a raw FILE*. If no callback is set, then it will fallback to the existing FILE*. If that's not set, then it falls back to stderr as it always has.
> While refactoring this code, I removed the need for the double parens in all the LOG macros as that wasn't necessary and didn't fit with my new approach.
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (ZOOKEEPER-1400) Allow logging via callback
instead of raw FILE pointer
Posted by "Marshall McMullen (Commented) (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/ZOOKEEPER-1400?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13215121#comment-13215121 ]
Marshall McMullen commented on ZOOKEEPER-1400:
----------------------------------------------
Please see attached path that provides my new proposed functionality.
> Allow logging via callback instead of raw FILE pointer
> ------------------------------------------------------
>
> Key: ZOOKEEPER-1400
> URL: https://issues.apache.org/jira/browse/ZOOKEEPER-1400
> Project: ZooKeeper
> Issue Type: Improvement
> Components: c client
> Affects Versions: 3.4.2
> Environment: Linux
> Reporter: Marshall McMullen
> Fix For: 3.4.2
>
> Attachments: case-2739.patch
>
>
> The existing logging framework inside the C client uses a raw FILE*. Using a FILE* is very limiting and potentially dangerous. A safer alternative is to just provide a callback that the C client will call for each message. In our environment, we saw some really nasty issues with multiple threads all connecting to zookeeper via the C Client related to the use of a raw FILE*. Specifically, if the FILE * is closed and that file descriptor is reused by the kernel before the C client is notified then the C client will use it's static global logStream pointer for subsequent logging messages. That FILE* is now a loose cannon! In our environment, we saw zookeeper log messages ending up in other sockets and even in our core data path. Clearly this is dangerous. In our particular case, we'd omitted a call to zoo_set_log_stream(NULL) to notify C client that the FILE* has been closed. However, even with that bug fixed, there's still a race condition where log messages in flight may be sent before the C client is notified of the FILE closure, and the same problem can happen.
> Other issues we've seen involved multiple threads, wherein one would close the FILE*, and that's a global change that affects all threads connected within that process. That's a pretty nasty limitation as well.
> My proposed change is to allow setting a callback for log messages. A callback is used in preference to a raw FILE*. If no callback is set, then it will fallback to the existing FILE*. If that's not set, then it falls back to stderr as it always has.
> While refactoring this code, I removed the need for the double parens in all the LOG macros as that wasn't necessary and didn't fit with my new approach.
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Updated] (ZOOKEEPER-1400) Allow logging via callback
instead of raw FILE pointer
Posted by "Marshall McMullen (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/ZOOKEEPER-1400?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Marshall McMullen updated ZOOKEEPER-1400:
-----------------------------------------
Attachment: ZOOKEEPER-1400-1.patch
Updated patch that should apply cleanly to trunk.
> Allow logging via callback instead of raw FILE pointer
> ------------------------------------------------------
>
> Key: ZOOKEEPER-1400
> URL: https://issues.apache.org/jira/browse/ZOOKEEPER-1400
> Project: ZooKeeper
> Issue Type: Improvement
> Components: c client
> Affects Versions: 3.5.0
> Environment: Linux
> Reporter: Marshall McMullen
> Fix For: 3.5.0
>
> Attachments: ZOOKEEPER-1400-1.patch, ZOOKEEPER-1400.patch
>
>
> The existing logging framework inside the C client uses a raw FILE*. Using a FILE* is very limiting and potentially dangerous. A safer alternative is to just provide a callback that the C client will call for each message. In our environment, we saw some really nasty issues with multiple threads all connecting to zookeeper via the C Client related to the use of a raw FILE*. Specifically, if the FILE * is closed and that file descriptor is reused by the kernel before the C client is notified then the C client will use it's static global logStream pointer for subsequent logging messages. That FILE* is now a loose cannon! In our environment, we saw zookeeper log messages ending up in other sockets and even in our core data path. Clearly this is dangerous. In our particular case, we'd omitted a call to zoo_set_log_stream(NULL) to notify C client that the FILE* has been closed. However, even with that bug fixed, there's still a race condition where log messages in flight may be sent before the C client is notified of the FILE closure, and the same problem can happen.
> Other issues we've seen involved multiple threads, wherein one would close the FILE*, and that's a global change that affects all threads connected within that process. That's a pretty nasty limitation as well.
> My proposed change is to allow setting a callback for log messages. A callback is used in preference to a raw FILE*. If no callback is set, then it will fallback to the existing FILE*. If that's not set, then it falls back to stderr as it always has.
> While refactoring this code, I removed the need for the double parens in all the LOG macros as that wasn't necessary and didn't fit with my new approach.
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (ZOOKEEPER-1400) Allow logging via callback
instead of raw FILE pointer
Posted by "Hadoop QA (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/ZOOKEEPER-1400?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13505568#comment-13505568 ]
Hadoop QA commented on ZOOKEEPER-1400:
--------------------------------------
-1 overall. Here are the results of testing the latest attachment
http://issues.apache.org/jira/secure/attachment/12533125/ZOOKEEPER-1400-1.patch
against trunk revision 1414566.
+1 @author. The patch does not contain any @author tags.
+1 tests included. The patch appears to include 13 new or modified tests.
-1 patch. The patch command could not apply the patch.
Console output: https://builds.apache.org/job/PreCommit-ZOOKEEPER-Build/1275//console
This message is automatically generated.
> Allow logging via callback instead of raw FILE pointer
> ------------------------------------------------------
>
> Key: ZOOKEEPER-1400
> URL: https://issues.apache.org/jira/browse/ZOOKEEPER-1400
> Project: ZooKeeper
> Issue Type: Improvement
> Components: c client
> Affects Versions: 3.5.0
> Environment: Linux
> Reporter: Marshall McMullen
> Assignee: Marshall McMullen
> Fix For: 3.5.0
>
> Attachments: ZOOKEEPER-1400-1.patch, ZOOKEEPER-1400.patch
>
>
> The existing logging framework inside the C client uses a raw FILE*. Using a FILE* is very limiting and potentially dangerous. A safer alternative is to just provide a callback that the C client will call for each message. In our environment, we saw some really nasty issues with multiple threads all connecting to zookeeper via the C Client related to the use of a raw FILE*. Specifically, if the FILE * is closed and that file descriptor is reused by the kernel before the C client is notified then the C client will use it's static global logStream pointer for subsequent logging messages. That FILE* is now a loose cannon! In our environment, we saw zookeeper log messages ending up in other sockets and even in our core data path. Clearly this is dangerous. In our particular case, we'd omitted a call to zoo_set_log_stream(NULL) to notify C client that the FILE* has been closed. However, even with that bug fixed, there's still a race condition where log messages in flight may be sent before the C client is notified of the FILE closure, and the same problem can happen.
> Other issues we've seen involved multiple threads, wherein one would close the FILE*, and that's a global change that affects all threads connected within that process. That's a pretty nasty limitation as well.
> My proposed change is to allow setting a callback for log messages. A callback is used in preference to a raw FILE*. If no callback is set, then it will fallback to the existing FILE*. If that's not set, then it falls back to stderr as it always has.
> While refactoring this code, I removed the need for the double parens in all the LOG macros as that wasn't necessary and didn't fit with my new approach.
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (ZOOKEEPER-1400) Allow logging via callback
instead of raw FILE pointer
Posted by "Marshall McMullen (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/ZOOKEEPER-1400?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13399535#comment-13399535 ]
Marshall McMullen commented on ZOOKEEPER-1400:
----------------------------------------------
BTW, I haven't yet had time to address the additional very good comments from Stephen and Michi. Been super swamped at work... I'll add an updated patch which addresses their concerns when things quiet down for me a bit.
> Allow logging via callback instead of raw FILE pointer
> ------------------------------------------------------
>
> Key: ZOOKEEPER-1400
> URL: https://issues.apache.org/jira/browse/ZOOKEEPER-1400
> Project: ZooKeeper
> Issue Type: Improvement
> Components: c client
> Affects Versions: 3.4.2
> Environment: Linux
> Reporter: Marshall McMullen
> Fix For: 3.4.2
>
> Attachments: ZOOKEEPER-1400.patch
>
>
> The existing logging framework inside the C client uses a raw FILE*. Using a FILE* is very limiting and potentially dangerous. A safer alternative is to just provide a callback that the C client will call for each message. In our environment, we saw some really nasty issues with multiple threads all connecting to zookeeper via the C Client related to the use of a raw FILE*. Specifically, if the FILE * is closed and that file descriptor is reused by the kernel before the C client is notified then the C client will use it's static global logStream pointer for subsequent logging messages. That FILE* is now a loose cannon! In our environment, we saw zookeeper log messages ending up in other sockets and even in our core data path. Clearly this is dangerous. In our particular case, we'd omitted a call to zoo_set_log_stream(NULL) to notify C client that the FILE* has been closed. However, even with that bug fixed, there's still a race condition where log messages in flight may be sent before the C client is notified of the FILE closure, and the same problem can happen.
> Other issues we've seen involved multiple threads, wherein one would close the FILE*, and that's a global change that affects all threads connected within that process. That's a pretty nasty limitation as well.
> My proposed change is to allow setting a callback for log messages. A callback is used in preference to a raw FILE*. If no callback is set, then it will fallback to the existing FILE*. If that's not set, then it falls back to stderr as it always has.
> While refactoring this code, I removed the need for the double parens in all the LOG macros as that wasn't necessary and didn't fit with my new approach.
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Updated] (ZOOKEEPER-1400) Allow logging via callback
instead of raw FILE pointer
Posted by "Marshall McMullen (Updated) (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/ZOOKEEPER-1400?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Marshall McMullen updated ZOOKEEPER-1400:
-----------------------------------------
Attachment: case-2739.patch
> Allow logging via callback instead of raw FILE pointer
> ------------------------------------------------------
>
> Key: ZOOKEEPER-1400
> URL: https://issues.apache.org/jira/browse/ZOOKEEPER-1400
> Project: ZooKeeper
> Issue Type: Improvement
> Components: c client
> Affects Versions: 3.4.2
> Environment: Linux
> Reporter: Marshall McMullen
> Fix For: 3.4.2
>
> Attachments: case-2739.patch
>
>
> The existing logging framework inside the C client uses a raw FILE*. Using a FILE* is very limiting and potentially dangerous. A safer alternative is to just provide a callback that the C client will call for each message. In our environment, we saw some really nasty issues with multiple threads all connecting to zookeeper via the C Client related to the use of a raw FILE*. Specifically, if the FILE * is closed and that file descriptor is reused by the kernel before the C client is notified then the C client will use it's static global logStream pointer for subsequent logging messages. That FILE* is now a loose cannon! In our environment, we saw zookeeper log messages ending up in other sockets and even in our core data path. Clearly this is dangerous. In our particular case, we'd omitted a call to zoo_set_log_stream(NULL) to notify C client that the FILE* has been closed. However, even with that bug fixed, there's still a race condition where log messages in flight may be sent before the C client is notified of the FILE closure, and the same problem can happen.
> Other issues we've seen involved multiple threads, wherein one would close the FILE*, and that's a global change that affects all threads connected within that process. That's a pretty nasty limitation as well.
> My proposed change is to allow setting a callback for log messages. A callback is used in preference to a raw FILE*. If no callback is set, then it will fallback to the existing FILE*. If that's not set, then it falls back to stderr as it always has.
> While refactoring this code, I removed the need for the double parens in all the LOG macros as that wasn't necessary and didn't fit with my new approach.
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (ZOOKEEPER-1400) Allow logging via callback
instead of raw FILE pointer
Posted by "Hadoop QA (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/ZOOKEEPER-1400?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13399721#comment-13399721 ]
Hadoop QA commented on ZOOKEEPER-1400:
--------------------------------------
+1 overall. Here are the results of testing the latest attachment
http://issues.apache.org/jira/secure/attachment/12533125/ZOOKEEPER-1400-1.patch
against trunk revision 1351541.
+1 @author. The patch does not contain any @author tags.
+1 tests included. The patch appears to include 13 new or modified tests.
+1 javadoc. The javadoc tool did not generate any warning messages.
+1 javac. The applied patch does not increase the total number of javac compiler warnings.
+1 findbugs. The patch does not introduce any new Findbugs (version 1.3.9) warnings.
+1 release audit. The applied patch does not increase the total number of release audit warnings.
+1 core tests. The patch passed core unit tests.
+1 contrib tests. The patch passed contrib unit tests.
Test results: https://builds.apache.org/job/PreCommit-ZOOKEEPER-Build/1111//testReport/
Findbugs warnings: https://builds.apache.org/job/PreCommit-ZOOKEEPER-Build/1111//artifact/trunk/build/test/findbugs/newPatchFindbugsWarnings.html
Console output: https://builds.apache.org/job/PreCommit-ZOOKEEPER-Build/1111//console
This message is automatically generated.
> Allow logging via callback instead of raw FILE pointer
> ------------------------------------------------------
>
> Key: ZOOKEEPER-1400
> URL: https://issues.apache.org/jira/browse/ZOOKEEPER-1400
> Project: ZooKeeper
> Issue Type: Improvement
> Components: c client
> Affects Versions: 3.5.0
> Environment: Linux
> Reporter: Marshall McMullen
> Fix For: 3.5.0
>
> Attachments: ZOOKEEPER-1400-1.patch, ZOOKEEPER-1400.patch
>
>
> The existing logging framework inside the C client uses a raw FILE*. Using a FILE* is very limiting and potentially dangerous. A safer alternative is to just provide a callback that the C client will call for each message. In our environment, we saw some really nasty issues with multiple threads all connecting to zookeeper via the C Client related to the use of a raw FILE*. Specifically, if the FILE * is closed and that file descriptor is reused by the kernel before the C client is notified then the C client will use it's static global logStream pointer for subsequent logging messages. That FILE* is now a loose cannon! In our environment, we saw zookeeper log messages ending up in other sockets and even in our core data path. Clearly this is dangerous. In our particular case, we'd omitted a call to zoo_set_log_stream(NULL) to notify C client that the FILE* has been closed. However, even with that bug fixed, there's still a race condition where log messages in flight may be sent before the C client is notified of the FILE closure, and the same problem can happen.
> Other issues we've seen involved multiple threads, wherein one would close the FILE*, and that's a global change that affects all threads connected within that process. That's a pretty nasty limitation as well.
> My proposed change is to allow setting a callback for log messages. A callback is used in preference to a raw FILE*. If no callback is set, then it will fallback to the existing FILE*. If that's not set, then it falls back to stderr as it always has.
> While refactoring this code, I removed the need for the double parens in all the LOG macros as that wasn't necessary and didn't fit with my new approach.
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Updated] (ZOOKEEPER-1400) Allow logging via callback
instead of raw FILE pointer
Posted by "Marshall McMullen (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/ZOOKEEPER-1400?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Marshall McMullen updated ZOOKEEPER-1400:
-----------------------------------------
Affects Version/s: (was: 3.4.2)
3.5.0
Fix Version/s: (was: 3.4.2)
3.5.0
My patch should apply cleanly to trunk.
> Allow logging via callback instead of raw FILE pointer
> ------------------------------------------------------
>
> Key: ZOOKEEPER-1400
> URL: https://issues.apache.org/jira/browse/ZOOKEEPER-1400
> Project: ZooKeeper
> Issue Type: Improvement
> Components: c client
> Affects Versions: 3.5.0
> Environment: Linux
> Reporter: Marshall McMullen
> Fix For: 3.5.0
>
> Attachments: ZOOKEEPER-1400.patch
>
>
> The existing logging framework inside the C client uses a raw FILE*. Using a FILE* is very limiting and potentially dangerous. A safer alternative is to just provide a callback that the C client will call for each message. In our environment, we saw some really nasty issues with multiple threads all connecting to zookeeper via the C Client related to the use of a raw FILE*. Specifically, if the FILE * is closed and that file descriptor is reused by the kernel before the C client is notified then the C client will use it's static global logStream pointer for subsequent logging messages. That FILE* is now a loose cannon! In our environment, we saw zookeeper log messages ending up in other sockets and even in our core data path. Clearly this is dangerous. In our particular case, we'd omitted a call to zoo_set_log_stream(NULL) to notify C client that the FILE* has been closed. However, even with that bug fixed, there's still a race condition where log messages in flight may be sent before the C client is notified of the FILE closure, and the same problem can happen.
> Other issues we've seen involved multiple threads, wherein one would close the FILE*, and that's a global change that affects all threads connected within that process. That's a pretty nasty limitation as well.
> My proposed change is to allow setting a callback for log messages. A callback is used in preference to a raw FILE*. If no callback is set, then it will fallback to the existing FILE*. If that's not set, then it falls back to stderr as it always has.
> While refactoring this code, I removed the need for the double parens in all the LOG macros as that wasn't necessary and didn't fit with my new approach.
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (ZOOKEEPER-1400) Allow logging via callback
instead of raw FILE pointer
Posted by "Marshall McMullen (Commented) (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/ZOOKEEPER-1400?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13215748#comment-13215748 ]
Marshall McMullen commented on ZOOKEEPER-1400:
----------------------------------------------
Thanks for the great feedback. I absolutely agree that the logging should be on a connection basis. I was hesitant to make an even more drastic change than I already had. Do you think changing the logging to be per-connection should be a separate JIRA or does it make sense to do it as part of this case as well?
> Allow logging via callback instead of raw FILE pointer
> ------------------------------------------------------
>
> Key: ZOOKEEPER-1400
> URL: https://issues.apache.org/jira/browse/ZOOKEEPER-1400
> Project: ZooKeeper
> Issue Type: Improvement
> Components: c client
> Affects Versions: 3.4.2
> Environment: Linux
> Reporter: Marshall McMullen
> Fix For: 3.4.2
>
> Attachments: case-2739.patch
>
>
> The existing logging framework inside the C client uses a raw FILE*. Using a FILE* is very limiting and potentially dangerous. A safer alternative is to just provide a callback that the C client will call for each message. In our environment, we saw some really nasty issues with multiple threads all connecting to zookeeper via the C Client related to the use of a raw FILE*. Specifically, if the FILE * is closed and that file descriptor is reused by the kernel before the C client is notified then the C client will use it's static global logStream pointer for subsequent logging messages. That FILE* is now a loose cannon! In our environment, we saw zookeeper log messages ending up in other sockets and even in our core data path. Clearly this is dangerous. In our particular case, we'd omitted a call to zoo_set_log_stream(NULL) to notify C client that the FILE* has been closed. However, even with that bug fixed, there's still a race condition where log messages in flight may be sent before the C client is notified of the FILE closure, and the same problem can happen.
> Other issues we've seen involved multiple threads, wherein one would close the FILE*, and that's a global change that affects all threads connected within that process. That's a pretty nasty limitation as well.
> My proposed change is to allow setting a callback for log messages. A callback is used in preference to a raw FILE*. If no callback is set, then it will fallback to the existing FILE*. If that's not set, then it falls back to stderr as it always has.
> While refactoring this code, I removed the need for the double parens in all the LOG macros as that wasn't necessary and didn't fit with my new approach.
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (ZOOKEEPER-1400) Allow logging via callback
instead of raw FILE pointer
Posted by "Marshall McMullen (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/ZOOKEEPER-1400?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13399673#comment-13399673 ]
Marshall McMullen commented on ZOOKEEPER-1400:
----------------------------------------------
Oops, I had other patches in my version so the patch isn't perfect. I'll get a new version updated momentarily.
> Allow logging via callback instead of raw FILE pointer
> ------------------------------------------------------
>
> Key: ZOOKEEPER-1400
> URL: https://issues.apache.org/jira/browse/ZOOKEEPER-1400
> Project: ZooKeeper
> Issue Type: Improvement
> Components: c client
> Affects Versions: 3.5.0
> Environment: Linux
> Reporter: Marshall McMullen
> Fix For: 3.5.0
>
> Attachments: ZOOKEEPER-1400.patch
>
>
> The existing logging framework inside the C client uses a raw FILE*. Using a FILE* is very limiting and potentially dangerous. A safer alternative is to just provide a callback that the C client will call for each message. In our environment, we saw some really nasty issues with multiple threads all connecting to zookeeper via the C Client related to the use of a raw FILE*. Specifically, if the FILE * is closed and that file descriptor is reused by the kernel before the C client is notified then the C client will use it's static global logStream pointer for subsequent logging messages. That FILE* is now a loose cannon! In our environment, we saw zookeeper log messages ending up in other sockets and even in our core data path. Clearly this is dangerous. In our particular case, we'd omitted a call to zoo_set_log_stream(NULL) to notify C client that the FILE* has been closed. However, even with that bug fixed, there's still a race condition where log messages in flight may be sent before the C client is notified of the FILE closure, and the same problem can happen.
> Other issues we've seen involved multiple threads, wherein one would close the FILE*, and that's a global change that affects all threads connected within that process. That's a pretty nasty limitation as well.
> My proposed change is to allow setting a callback for log messages. A callback is used in preference to a raw FILE*. If no callback is set, then it will fallback to the existing FILE*. If that's not set, then it falls back to stderr as it always has.
> While refactoring this code, I removed the need for the double parens in all the LOG macros as that wasn't necessary and didn't fit with my new approach.
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Updated] (ZOOKEEPER-1400) Allow logging via callback
instead of raw FILE pointer
Posted by "Marshall McMullen (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/ZOOKEEPER-1400?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Marshall McMullen updated ZOOKEEPER-1400:
-----------------------------------------
Attachment: ZOOKEEPER-1400.patch
This updated patch incorporates Stephen's suggestion of making the log callback per-handle. There is still a zoo_set_log_callback function, but it now takes a zhandle_t* to associate the callback with.
I've also added a zookeeper_init2 which is the same as zookeeper_init but adds an extra argument for the log callback.
> Allow logging via callback instead of raw FILE pointer
> ------------------------------------------------------
>
> Key: ZOOKEEPER-1400
> URL: https://issues.apache.org/jira/browse/ZOOKEEPER-1400
> Project: ZooKeeper
> Issue Type: Improvement
> Components: c client
> Affects Versions: 3.4.2
> Environment: Linux
> Reporter: Marshall McMullen
> Fix For: 3.4.2
>
> Attachments: ZOOKEEPER-1400.patch
>
>
> The existing logging framework inside the C client uses a raw FILE*. Using a FILE* is very limiting and potentially dangerous. A safer alternative is to just provide a callback that the C client will call for each message. In our environment, we saw some really nasty issues with multiple threads all connecting to zookeeper via the C Client related to the use of a raw FILE*. Specifically, if the FILE * is closed and that file descriptor is reused by the kernel before the C client is notified then the C client will use it's static global logStream pointer for subsequent logging messages. That FILE* is now a loose cannon! In our environment, we saw zookeeper log messages ending up in other sockets and even in our core data path. Clearly this is dangerous. In our particular case, we'd omitted a call to zoo_set_log_stream(NULL) to notify C client that the FILE* has been closed. However, even with that bug fixed, there's still a race condition where log messages in flight may be sent before the C client is notified of the FILE closure, and the same problem can happen.
> Other issues we've seen involved multiple threads, wherein one would close the FILE*, and that's a global change that affects all threads connected within that process. That's a pretty nasty limitation as well.
> My proposed change is to allow setting a callback for log messages. A callback is used in preference to a raw FILE*. If no callback is set, then it will fallback to the existing FILE*. If that's not set, then it falls back to stderr as it always has.
> While refactoring this code, I removed the need for the double parens in all the LOG macros as that wasn't necessary and didn't fit with my new approach.
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (ZOOKEEPER-1400) Allow logging via callback
instead of raw FILE pointer
Posted by "Hadoop QA (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/ZOOKEEPER-1400?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13399539#comment-13399539 ]
Hadoop QA commented on ZOOKEEPER-1400:
--------------------------------------
-1 overall. Here are the results of testing the latest attachment
http://issues.apache.org/jira/secure/attachment/12533092/ZOOKEEPER-1400.patch
against trunk revision 1351541.
+1 @author. The patch does not contain any @author tags.
+1 tests included. The patch appears to include 13 new or modified tests.
-1 patch. The patch command could not apply the patch.
Console output: https://builds.apache.org/job/PreCommit-ZOOKEEPER-Build/1108//console
This message is automatically generated.
> Allow logging via callback instead of raw FILE pointer
> ------------------------------------------------------
>
> Key: ZOOKEEPER-1400
> URL: https://issues.apache.org/jira/browse/ZOOKEEPER-1400
> Project: ZooKeeper
> Issue Type: Improvement
> Components: c client
> Affects Versions: 3.4.2
> Environment: Linux
> Reporter: Marshall McMullen
> Fix For: 3.4.2
>
> Attachments: ZOOKEEPER-1400.patch
>
>
> The existing logging framework inside the C client uses a raw FILE*. Using a FILE* is very limiting and potentially dangerous. A safer alternative is to just provide a callback that the C client will call for each message. In our environment, we saw some really nasty issues with multiple threads all connecting to zookeeper via the C Client related to the use of a raw FILE*. Specifically, if the FILE * is closed and that file descriptor is reused by the kernel before the C client is notified then the C client will use it's static global logStream pointer for subsequent logging messages. That FILE* is now a loose cannon! In our environment, we saw zookeeper log messages ending up in other sockets and even in our core data path. Clearly this is dangerous. In our particular case, we'd omitted a call to zoo_set_log_stream(NULL) to notify C client that the FILE* has been closed. However, even with that bug fixed, there's still a race condition where log messages in flight may be sent before the C client is notified of the FILE closure, and the same problem can happen.
> Other issues we've seen involved multiple threads, wherein one would close the FILE*, and that's a global change that affects all threads connected within that process. That's a pretty nasty limitation as well.
> My proposed change is to allow setting a callback for log messages. A callback is used in preference to a raw FILE*. If no callback is set, then it will fallback to the existing FILE*. If that's not set, then it falls back to stderr as it always has.
> While refactoring this code, I removed the need for the double parens in all the LOG macros as that wasn't necessary and didn't fit with my new approach.
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Updated] (ZOOKEEPER-1400) Allow logging via callback
instead of raw FILE pointer
Posted by "Marshall McMullen (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/ZOOKEEPER-1400?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Marshall McMullen updated ZOOKEEPER-1400:
-----------------------------------------
Attachment: (was: case-2739.patch)
> Allow logging via callback instead of raw FILE pointer
> ------------------------------------------------------
>
> Key: ZOOKEEPER-1400
> URL: https://issues.apache.org/jira/browse/ZOOKEEPER-1400
> Project: ZooKeeper
> Issue Type: Improvement
> Components: c client
> Affects Versions: 3.4.2
> Environment: Linux
> Reporter: Marshall McMullen
> Fix For: 3.4.2
>
> Attachments: ZOOKEEPER-1400.patch
>
>
> The existing logging framework inside the C client uses a raw FILE*. Using a FILE* is very limiting and potentially dangerous. A safer alternative is to just provide a callback that the C client will call for each message. In our environment, we saw some really nasty issues with multiple threads all connecting to zookeeper via the C Client related to the use of a raw FILE*. Specifically, if the FILE * is closed and that file descriptor is reused by the kernel before the C client is notified then the C client will use it's static global logStream pointer for subsequent logging messages. That FILE* is now a loose cannon! In our environment, we saw zookeeper log messages ending up in other sockets and even in our core data path. Clearly this is dangerous. In our particular case, we'd omitted a call to zoo_set_log_stream(NULL) to notify C client that the FILE* has been closed. However, even with that bug fixed, there's still a race condition where log messages in flight may be sent before the C client is notified of the FILE closure, and the same problem can happen.
> Other issues we've seen involved multiple threads, wherein one would close the FILE*, and that's a global change that affects all threads connected within that process. That's a pretty nasty limitation as well.
> My proposed change is to allow setting a callback for log messages. A callback is used in preference to a raw FILE*. If no callback is set, then it will fallback to the existing FILE*. If that's not set, then it falls back to stderr as it always has.
> While refactoring this code, I removed the need for the double parens in all the LOG macros as that wasn't necessary and didn't fit with my new approach.
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (ZOOKEEPER-1400) Allow logging via callback
instead of raw FILE pointer
Posted by "Stephen Tyree (Commented) (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/ZOOKEEPER-1400?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13230364#comment-13230364 ]
Stephen Tyree commented on ZOOKEEPER-1400:
------------------------------------------
Sorry for the delay
I think that would make sense to be a separate JIRA. As far as your change goes it looks good, but a couple of points:
+ char* buf = get_format_log_buffer();
This means there is now a limit on log size that wasn't there before. Have you made sure this buffer can handle all possible log messages?
Also, you made a bunch of formatting changes that seem tangential to the change itself, like the following:
- static const char* dbgLevelStr[]={"ZOO_INVALID","ZOO_ERROR","ZOO_WARN",
- "ZOO_INFO","ZOO_DEBUG"};
+ char* buf = get_format_log_buffer();
+ if(!buf)
+ return;
+
+ static const char* dbgLevelStr[] = {"ZOO_INVALID",
+ "ZOO_ERROR",
+ "ZOO_WARN",
+ "ZOO_INFO",
+ "ZOO_DEBUG"};
Maybe those should be reserved for a separate change just to keep things tidy?
> Allow logging via callback instead of raw FILE pointer
> ------------------------------------------------------
>
> Key: ZOOKEEPER-1400
> URL: https://issues.apache.org/jira/browse/ZOOKEEPER-1400
> Project: ZooKeeper
> Issue Type: Improvement
> Components: c client
> Affects Versions: 3.4.2
> Environment: Linux
> Reporter: Marshall McMullen
> Fix For: 3.4.2
>
> Attachments: case-2739.patch
>
>
> The existing logging framework inside the C client uses a raw FILE*. Using a FILE* is very limiting and potentially dangerous. A safer alternative is to just provide a callback that the C client will call for each message. In our environment, we saw some really nasty issues with multiple threads all connecting to zookeeper via the C Client related to the use of a raw FILE*. Specifically, if the FILE * is closed and that file descriptor is reused by the kernel before the C client is notified then the C client will use it's static global logStream pointer for subsequent logging messages. That FILE* is now a loose cannon! In our environment, we saw zookeeper log messages ending up in other sockets and even in our core data path. Clearly this is dangerous. In our particular case, we'd omitted a call to zoo_set_log_stream(NULL) to notify C client that the FILE* has been closed. However, even with that bug fixed, there's still a race condition where log messages in flight may be sent before the C client is notified of the FILE closure, and the same problem can happen.
> Other issues we've seen involved multiple threads, wherein one would close the FILE*, and that's a global change that affects all threads connected within that process. That's a pretty nasty limitation as well.
> My proposed change is to allow setting a callback for log messages. A callback is used in preference to a raw FILE*. If no callback is set, then it will fallback to the existing FILE*. If that's not set, then it falls back to stderr as it always has.
> While refactoring this code, I removed the need for the double parens in all the LOG macros as that wasn't necessary and didn't fit with my new approach.
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira