[CDRIVER-1235] Don't log username during auth Created: 18/May/16  Updated: 11/Sep/19  Resolved: 19/May/16

Status: Closed
Project: C Driver
Component/s: auth
Affects Version/s: 1.3.5
Fix Version/s: 1.4.0

Type: Task Priority: Major - P3
Reporter: Judy Han [X] Assignee: Unassigned
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Linux xxx 2.6.32-573.18.1.el6.x86_64 #1 SMP Wed Jan 6 11:20:49 EST 2016 x86_64 x86_64 x86_64 GNU/Linux



 Description   

with new C++11 driver, right after retrieving the first doc from first query, following message are prompt to stdout:

2016/05/18 15:15:30.0102: [19782]:     INFO:      cluster: SCRAM: authenticating "XXX" (step 1)
2016/05/18 15:15:30.0124: [19782]:     INFO:      cluster: SCRAM: authenticating "XXX" (step 2)
2016/05/18 15:15:30.0124: [19782]:     INFO:      cluster: SCRAM: authenticating "XXX" (step 3)
2016/05/18 15:15:30.0124: [19782]:     INFO:      cluster: SCRAM: "XXX" authenticated

Looks like it's some debug message that should not be kept in the library. I would like to suppress these information which is directly dumped to stdout. I expect mongocxx library not dump messages directly to stdout. Please let me know if I misunderstood. Please advice if this can be done without redirecting stdout with current library, or is there a plan to fix this soon.

Thanks!
Judy



 Comments   
Comment by Judy Han [X] [ 24/Jun/16 ]

Hi Andrew,
Thanks for the following up. I agree with you that this should not cause memory corruption. However, I do want to get rid of this leak reported by Valgrind, any suggestions? Thanks!
Regarding how we load the libraries: We are calling ACE_DLL::open() to load my application library - libevent_loader.so, the libevent_loader.so is build with -lbsoncxx -lmongocxx -lbson-1.0 -lmongoc-priv, here is the ldd output for the library:
ldd libevent_loader.so |grep mongo
libbsoncxx.so._noabi => /home/jhan/workspace/nonuniqkeywork/publish_linux/opt/mtx/lib/mongocxx-r3.0.1/libbsoncxx.so._noabi (0x00007fd85728d000)
libmongocxx.so._noabi => /home/jhan/workspace/nonuniqkeywork/publish_linux/opt/mtx/lib/mongocxx-r3.0.1/libmongocxx.so._noabi (0x00007fd85704e000)
libbson-1.0.so.0 => /home/jhan/workspace/nonuniqkeywork/publish_linux/opt/mtx/lib/mongocxx-r3.0.1/libbson-1.0.so.0 (0x00007fd856e1d000)
libmongoc-priv.so.0 => /home/jhan/workspace/nonuniqkeywork/publish_linux/opt/mtx/lib/mongocxx-r3.0.1/libmongoc-priv.so.0 (0x00007fd856bd0000)
libmongoc-1.0.so.0 => /home/jhan/workspace/nonuniqkeywork/publish_linux/opt/mtx/lib/mongocxx-r3.0.1/libmongoc-1.0.so.0 (0x00007fd854f94000)
Thanks!
Judy

Comment by Andrew Morrow (Inactive) [ 23/Jun/16 ]

Judy.Han - I don't think that valgrind report suggests the sort of memory corruption I had thought might be in play. I find the behavior you are observing very puzzling. Is it possible that _mongoc_do_init is being called more than once in the lifetime of your process? It appears that you are dynamically opening the mongocxx library (in a mode where it is statically linked to libmongoc). This is a highly unusual way to use the library, and certainly not one that we are testing. Can you explain in more detail what is going on here? Can you set a breakpoint in _mongoc_do_init and count how many times it is invoked?

Comment by Judy Han [X] [ 22/Jun/16 ]

problem reproduced with valgrind ("bar" is reported 2 times while I have 3 threads.)
valgrind reports only one error (memory leak):

==00:00:00:54.578 2310== 71 bytes in 1 blocks are definitely lost in loss record 542 of 620
==00:00:00:54.578 2310==    at 0x4A06A2E: malloc (vg_replace_malloc.c:270)
==00:00:00:54.578 2310==    by 0x3D06E0E394: _dl_signal_error (in /lib64/ld-2.12.so)
==00:00:00:54.578 2310==    by 0x3D06E0E559: _dl_signal_cerror (in /lib64/ld-2.12.so)
==00:00:00:54.578 2310==    by 0x3D06E0A379: _dl_lookup_symbol_x (in /lib64/ld-2.12.so)
==00:00:00:54.578 2310==    by 0x3D07327015: do_sym (in /lib64/libc-2.12.so)
==00:00:00:54.578 2310==    by 0x3D07E010C3: dlsym_doit (in /lib64/libdl-2.12.so)
==00:00:00:54.578 2310==    by 0x3D06E0E285: _dl_catch_error (in /lib64/ld-2.12.so)
==00:00:00:54.578 2310==    by 0x3D07E0129B: _dlerror_run (in /lib64/libdl-2.12.so)
==00:00:00:54.578 2310==    by 0x3D07E01079: dlsym (in /lib64/libdl-2.12.so)
==00:00:00:54.578 2310==    by 0x3D1961299E: _sasl_locate_entry (in /usr/lib64/libsasl2.so.2.0.23)
==00:00:00:54.578 2310==    by 0x3D19612E85: _sasl_load_plugins (in /usr/lib64/libsasl2.so.2.0.23)
==00:00:00:54.578 2310==    by 0x3D19609158: sasl_client_init (in /usr/lib64/libsasl2.so.2.0.23)
==00:00:00:54.578 2310==    by 0xE025E17: _mongoc_do_init (in /xxxxxx/mongocxx-r3.0.1/libmongoc-priv.so.0.0.0)
==00:00:00:54.578 2310==    by 0x3D07A0CE02: pthread_once (in /lib64/libpthread-2.12.so)
==00:00:00:54.578 2310==    by 0x3D06E0E66E: _dl_init (in /lib64/ld-2.12.so)
==00:00:00:54.578 2310==    by 0x3D06E12E94: dl_open_worker (in /lib64/ld-2.12.so)
==00:00:00:54.578 2310==    by 0x3D06E0E285: _dl_catch_error (in /lib64/ld-2.12.so)
==00:00:00:54.578 2310==    by 0x3D06E12639: _dl_open (in /lib64/ld-2.12.so)
==00:00:00:54.578 2310==    by 0x3D07E00F65: dlopen_doit (in /lib64/libdl-2.12.so)
==00:00:00:54.578 2310==    by 0x3D06E0E285: _dl_catch_error (in /lib64/ld-2.12.so)
==00:00:00:54.578 2310==    by 0x3D07E0129B: _dlerror_run (in /lib64/libdl-2.12.so)
==00:00:00:54.578 2310==    by 0x3D07E00EE0: dlopen@@GLIBC_2.2.5 (in /lib64/libdl-2.12.so)
==00:00:00:54.578 2310==    by 0x6D94FCB: ACE_OS::dlopen(char const*, int) (OS_NS_dlfcn.inl:124)
==00:00:00:54.578 2310==    by 0x6D931C0: ACE_DLL_Handle::open(char const*, int, void*) (DLL_Manager.cpp:120)
==00:00:00:54.578 2310==    by 0x6D947DF: ACE_DLL_Manager::open_dll(char const*, int, void*) (DLL_Manager.cpp:575)
==00:00:00:54.578 2310==    by 0x6D92AF3: ACE_DLL::open_i(char const*, int, bool, void*) (DLL.cpp:167)
==00:00:00:54.578 2310==    by 0x6D92996: ACE_DLL::open(char const*, int, bool) (DLL.cpp:127)
==00:00:00:54.578 2310==    by 0x419020: MtxRpf::Framework::initServiceController(MtxUtil::EcbsmiID const&, char const*, char const*, int, int) (Framework.cpp:302)
==00:00:00:54.578 2310==    by 0x4174FD: MtxRpf::Framework::init(MtxUtil::EcbsmiID const&, char const*, char const*, int, int) (Framework.cpp:105)
==00:00:00:54.578 2310==    by 0x41428B: main (mtx.cpp:256)

Is there anything special I need to do regarding unload the library, maybe?
Thanks,
Judy

Comment by Andrew Morrow (Inactive) [ 21/Jun/16 ]

I recommend running your program under address sanitizer or valgrind. I suspect memory corruption.

Comment by Judy Han [X] [ 20/Jun/16 ]

an update:
with your debug code, only "mongocxx: libmongoc logging callback enabled" message is consistently logged (once), the log message I added ("bar") is not always logged, sometimes it's logged once, sometimes it's logged 3 times, sometimes it's not logged at all.
the strange thing is using the same logger class, my stand alone small program always logs correctly, one of the differences between the stand alone small program and my loader app is that the loader app is writing a bunch of log messages to a separate file. I would not expect that to interfere with this log though.
Thanks,
Judy

Comment by Judy Han [X] [ 20/Jun/16 ]

Hi Andrew,
Thank you very much for the follow up.
Sorry I made a mistake, now with your debug line, I got following message in my log as expected:
2016/06/20 13:30:34.0152: [25710]: INFO: mongocxx: libmongoc logging callback enabled

In my code I called following in each thread:
mongoc_log(::MONGOC_LOG_LEVEL_ERROR, "foo", "bar");
This message got logged 3 times as expected as well (I have 3 threads).

However, when I revert back to the original library, the above "bar" is not logged. (I think it got logged one time but I can not reproduced it).

The auth related logs are not logged in all tests, even though a stand alone test shows the log related message in the log:
SCRAM: authenticating "MtxEventLoader" (step 1)
etc...

suggestions?
Thanks!
Judy

Comment by Andrew Morrow (Inactive) [ 13/Jun/16 ]

Judy.Han - Could you try pulling the latest code from master and working with that? I've added a line that is always logged when the logger is configured:

https://github.com/mongodb/mongo-cxx-driver/blob/master/src/mongocxx/instance.cpp#L75

That should help determine whether your logger is just not logging because there is nothing to log (as now there always will be), or something else is going wrong.

Also, please be aware that I'm expecting to make some changes to how the 'instance' object is managed, per CXX-890. In particular, the instance::current method is likely to go away.

Comment by Judy Han [X] [ 07/Jun/16 ]

Hi Andrew,
Thank you very much for following up even though the ticket is marked resolved. You are right, I am still not able to get the log to work in my loader app. I tried to reproduce the problem with a simple app, but I am not able to reproduce it. I wrote a simple multi-threaded app and it works. The main difference that I think could contribute to the problem between my loader app and the simple app is that the simple app uses pthread directly while my loader app is using ACE thread via ACE tasks. I will continue looking into it. If you have any suggestions, please let me know.
Thanks!
Judy

Comment by Andrew Morrow (Inactive) [ 04/Jun/16 ]

Hi Judy.Han - This ticket is resolved, but I notice that you have an open question on it. Do you still need help enabling logging?

Comment by Judy Han [X] [ 25/May/16 ]

Hi Andrew,
I followed the instructions (cmake and make, etc) before and I tried it again, the build directory is empty both times.
Thanks,
Judy

Comment by Andrew Morrow (Inactive) [ 25/May/16 ]

Judy.Han - If you build with CMake and then make, the object files should be there unless you removed the build directory. You can regenerate them by rebuilding and re-installing.

Comment by Judy Han [X] [ 22/May/16 ]

ah, looks that I am not able to break in src/mongocxx/instance.cpp:59 because there is no object file for it (not sure why, I followed the build instructions), how do I regenerate the object files?
Thanks!
Judy

Comment by Judy Han [X] [ 22/May/16 ]

btw, not sure if this information is helpful - when I was not calling mongocxx::instance, the authentication message showed up in stdout 3 times, one for each thread.

Also I tried to add:

mongoc_log(::MONGOC_LOG_LEVEL_ERROR, "foo", "bar");

But still fail to break in src/mongocxx/instance.cpp:59
but "bar" is logged in the single threaded app.

Comment by Judy Han [X] [ 22/May/16 ]

Hi Andrew,
Thanks for the suggestions!
I isolate the code to a simple single threaded app, the log information is written as expected to my log file.
The breakpoint got called at mongoc_log_set_handler(), mongoc_log, but I was not able to break at user_log_handler (I tried using line number).

However, in my multi-threaded app, with the same code, nothing is written to the log file. following calls:

    std::unique_ptr<MongoDbLogger> mongoDbLoggerP(new MongoDbLogger);
    mongocxx::instance inst(std::move(mongoDbLoggerP));

are called before the threads are spawned and I have a new connection for each thread:

static __thread mongocxx::client *mongoPtr_;
mongoPtr_ = new mongocxx::client(mongocxx::uri{uriString});

Would that be a problem?
btw, in the multi-threaded app, as in the simple single threaded case, following break points are also get called: mongoc_log_set_handler(), mongoc_log

Thanks!
Judy

Comment by Andrew Morrow (Inactive) [ 22/May/16 ]

HI Judy.Han -

That looks pretty good, I don't see anything immediately wrong that would explain why it does not appear to be getting called. Two suggestions:

  • Can you set a breakpoint in http://api.mongodb.com/c/0.94.2/mongoc_log_set_handler.html and see if is getting called?
  • Can you set a breakpoint in mongoc_log and see if it is getting called?
  • Could you set a breakpoint in src/mongocxx/instance.cpp in the function user_log_handler (you may need to do that by line number since it is in an unnamed namespace). Does it get called?
  • Could you, from your mainline, after setting the logger, make an explicit call to the C driver function mongoc_log at ERROR level and see if your handler (or user_log_handler) is called?

    mongoc_log(::MONGOC_LOG_LEVEL_ERROR, "foo", "bar");

I think those steps should help reveal where things are going wrong.

Comment by Judy Han [X] [ 20/May/16 ]

Hi Andrew,
Here is my logger class:

namespace EventLoader {
///
/// @class MongoDbLogger
///
///
class MongoDbLogger : public mongocxx::logger {
  public:
    ///
    /// Standard constructor.
    ///
    MongoDbLogger() {
        const char *mtxLogDirP = ::getenv("MTX_LOG_DIR");
        if (mtxLogDirP == NULL) {
            // Assume /var/log/mtx
            mtxLogDirP = "/var/log/mtx";
        }
        ::snprintf(logFileName_, sizeof(logFileName_), "%s/mtx_event_loader_mongo_db.log", mtxLogDirP);
        logStream_.open(logFileName_);
        if (!logStream_.is_open()) {
            std::cout << "fail to open log file" << logFileName_ << std::endl;
        }
    }
    
    ///
    /// Standard destructor.
    ///
    virtual ~MongoDbLogger() {
        if (logStream_.is_open()) {
            logStream_.close();
        }
    }
 
    virtual void operator() (
            mongocxx::log_level   level,
            mongocxx::stdx::string_view   domain,
            mongocxx::stdx::string_view   message)  noexcept {
        if (logStream_.is_open()) {
            logStream_ << message << std::endl;
        }
    }
 
 
  private:
    // The stream for the log.
    std::ofstream logStream_;
    char logFileName_[PATH_MAX];
};
 
} 

And here is my caller:

    std::unique_ptr<MongoDbLogger> mongoDbLoggerP(new MongoDbLogger);
    mongocxx::instance inst(std::move(mongoDbLoggerP));

It looks like the operator() is not called because I tried to print some random info to stdout in operator() and they did not get printed out.
Thanks!
Judy

Comment by Andrew Morrow (Inactive) [ 20/May/16 ]

Hi -

Can you provide the implementation of your logger (should be a subclass of mongocxx:logger) and how you created the instance object? Is your implementation of mongocxx::logger::operator() being called?

Thanks,
Andrew

Comment by Judy Han [X] [ 20/May/16 ]

Hi Andrew,

Thanks for the update and the link. Sorry, my original code did not call mongocxx::instance object. After I added mongocxx::instance there is no messages popping to stdout any more.
Now the trouble is after I added my own logger - just print all messages, no Info message showing as well. Do I need to setup loglevel somewhere?

Thanks,
Judy

Comment by Githook User [ 19/May/16 ]

Author:

{u'username': u'ajdavis', u'name': u'A. Jesse Jiryu Davis', u'email': u'jesse@mongodb.com'}

Message: CDRIVER-1235 don't log username

Remove username from log messages, lower auth error messages from
INFO to DEBUG level, lower auth success messages from INFO to TRACE.
Branch: master
https://github.com/mongodb/mongo-c-driver/commit/e8f031a6deb7d0fdea10ba2161d9fb5b56fa6e8e

Comment by Andrew Morrow (Inactive) [ 19/May/16 ]

Hi Judy.Han -

If you are using the C++11 driver, you should not make any direct calls to libmongoc functions, especially ones related to initialization and termination. The fact that the C-++11 driver uses the C driver is an implementation detail that is, at least in theory, subject to change.

The correct way to change the logging setup when using the C++11 driver is to provide an object implementing the mongocxx::logger interface when constructing your mongocxx::instance object. Your injected implementation of mongocxx::logger will then be called back with each log message, and can decide what to do with the message.

Please note that we are expecting to make some changes around management of the mongocxx::instance object for the upcoming 3.0.2 release, please see CXX-890 for additional discussion.

Comment by A. Jesse Jiryu Davis [ 19/May/16 ]

Sorry, I missed the fact that you're using the C++11 driver. No, don't add init/cleanup calls. I'll wait for a member of the C++ driver team to comment on how to deal with logging and errors in C++.

The C Driver 1.4.0 will be released in the next few months, and the logging interface won't change. The only change will be that these messages from the authentication system will be changed from INFO to DEBUG level, and the username won't be included in the log messages any more.

Comment by Judy Han [X] [ 19/May/16 ]

Hi Jesse,
Thanks for the information. I have a few follow up questions:

1. I assume in case of error, error code will be passed back to the caller(s)?
If so, I prefer to suppress all the messages to the stdout for now. Is there a way for the caller to get back the message?

2. My current code does not have direct call to mongoc, is it recommended to call mongoc_init() and mongoc_cleanup() regardless if I call mongoc_log_set_handler()?

3. my application is multi-threaded and each thread has it's own client connection, should I call mongoc_init()/mongoc_cleanup() per thread or should I call them only once for the whole program at the entrance of main() before I spawn the threads(for mongoc_init()) and right before exit point in main (for mongoc_cleanup)? Also I am not sure if any mongocxx libraries calls mongoc_init()/cleanup(), what are the rules for calling mongoc_init/cleanup()?

4. Do you know when version 1.4.0 will be available? and What the interface will be like and what impact to apps code? Do I need to remove the mongoc_init()/cleanup() and mongoc_log_default_handler() code?

Thanks in advance!
Judy

Comment by A. Jesse Jiryu Davis [ 19/May/16 ]

Judy, you can suppress INFO-level log messages, and allow more important log messages through, like this:

 
void
my_logger (mongoc_log_level_t  log_level,
           const char         *log_domain,
           const char         *message,
           void               *user_data)
{
   /* smaller values are more important */
   if (log_level < MONGOC_LOG_LEVEL_INFO) {
      mongoc_log_default_handler (log_level, log_domain, message, user_data);
   }
}
 
 
int
main (int   argc,
      char *argv[])
{
   mongoc_init ();
   mongoc_log_set_handler (my_logger, NULL);
 
   /* ... your code ...  */
 
   mongoc_cleanup ();
   return 0;
}

We'll fix this logging in version 1.4.0.

Comment by Judy Han [X] [ 19/May/16 ]

Hi David,
I am using mongo-c-driver-1.3.5
Thanks!
Judy

Comment by David Golden [ 18/May/16 ]

Judy, could you please tell us what version of libmongoc you're compiling against?

Comment by David Golden [ 18/May/16 ]

That's coming from libmongoc. I'll move this ticket to that queue.

Generated at Wed Feb 07 21:11:58 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.