[JAVA-4719] Log opening connection message as debug instead of info Created: 31/Aug/22  Updated: 28/Oct/23  Resolved: 01/Sep/22

Status: Closed
Project: Java Driver
Component/s: Logging
Affects Version/s: None
Fix Version/s: 4.8.0

Type: Improvement Priority: Minor - P4
Reporter: Taeyang Jin (Heli) Assignee: Jeffrey Yemin
Resolution: Fixed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Backwards Compatibility: Minor Change
Documentation Changes: Not Needed

 Description   

Change the "Opened connection ..." log message from INFO to DEBUG.

Justification: it's the only remaining connection-related log message that is logged at INFO (e.g. the connection-closed message is logged at DEBUG).

Original Description

I looked around the driver source-code and found "maintenanceTimer" Executor Daemon for sdam(server-discovery-and-monitoring) in DefaultConnectionPool.java

It is also doing maintenance scheduled(fixedRate) and i checked that logic is connection pool prune(clear) -> new connection open.

so every maintenance frequency(default: 1min), Logger is writing logs with info level.

so many unnecessary things are being written in our log files.

Is this log level intended to be info? Or is it a bug?

Additionally, we would like to modify the log level of the logger(org.mongodb.driver.connection) to warn so that the log is not included in our log files.

Is this the best way? (we would like to use the level of the loggers as info)



 Comments   
Comment by Taeyang Jin (Heli) [ 01/Sep/22 ]

oh, ok. i thought it would be bad to keep the connection pool for a long time.

 

thank you Jeffrey ! 😻

Comment by Jeffrey Yemin [ 01/Sep/22 ]

I recommend not setting idle time at all, and only setting it if you're running into issues with either:

  • excessive connections remaining open on the server after a usage spike
  • load balancers or routers between your application and the MongoDB server terminating idle connections
Comment by Jeffrey Yemin [ 01/Sep/22 ]

Thanks for the PR, sun@jupiterflow.com!

Comment by Githook User [ 01/Sep/22 ]

Author:

{'name': 'Taeyang Jin (Heli)', 'email': 'sun@jupiterflow.com', 'username': 'heli-os'}

Message: Change "Opened connection..." log message from INFO to DEBUG (#999)

JAVA-4719
Branch: master
https://github.com/mongodb/mongo-java-driver/commit/29a99613965f250269ade28413a717964b883d08

Comment by Taeyang Jin (Heli) [ 01/Sep/22 ]

Haha, Thank you for your understanding.

Do you have any idle time recommendations? Our company is just setting up a project that uses MongoDB, so I'm curious.😁

Comment by Jeffrey Yemin [ 01/Sep/22 ]

Ah ok. I suspect that's why most others haven't noticed this. That's a pretty short idle time!

Comment by Taeyang Jin (Heli) [ 01/Sep/22 ]

oh.. sorry jeffrey, I was using additional settings. (max-connection-idle-time) 😓

 

val client = MongoClients.create(
    MongoClientSettings.builder()
        .credential(MongoCredential.createCredential("root", "admin", "1234".toCharArray()))
        .applyToConnectionPoolSettings { builder: ConnectionPoolSettings.Builder ->
            builder.minSize(5)
            builder.maxConnectionIdleTime(10000, TimeUnit.MILLISECONDS)
            builder.maxConnectionLifeTime(10000, TimeUnit.MILLISECONDS)
        }
        .build())
 
Thread.sleep(Long.MAX_VALUE) 

 

 

01:07:45.923 [MaintenanceTimer-2-thread-1] INFO  org.mongodb.driver.connection - Opened connection [connectionId{localValue:8, serverValue:247}] to 127.0.0.1:27017
01:07:45.966 [MaintenanceTimer-2-thread-1] INFO  org.mongodb.driver.connection - Opened connection [connectionId{localValue:9, serverValue:248}] to 127.0.0.1:27017
01:07:46.013 [MaintenanceTimer-2-thread-1] INFO  org.mongodb.driver.connection - Opened connection [connectionId{localValue:10, serverValue:249}] to 127.0.0.1:27017
01:07:46.052 [MaintenanceTimer-2-thread-1] INFO  org.mongodb.driver.connection - Opened connection [connectionId{localValue:11, serverValue:250}] to 127.0.0.1:27017
01:07:46.093 [MaintenanceTimer-2-thread-1] INFO  org.mongodb.driver.connection - Opened connection [connectionId{localValue:12, serverValue:251}] to 127.0.0.1:27017
01:08:45.925 [MaintenanceTimer-2-thread-1] INFO  org.mongodb.driver.connection - Opened connection [connectionId{localValue:13, serverValue:252}] to 127.0.0.1:27017
01:08:45.977 [MaintenanceTimer-2-thread-1] INFO  org.mongodb.driver.connection - Opened connection [connectionId{localValue:14, serverValue:253}] to 127.0.0.1:27017
01:08:46.014 [MaintenanceTimer-2-thread-1] INFO  org.mongodb.driver.connection - Opened connection [connectionId{localValue:15, serverValue:254}] to 127.0.0.1:27017
01:08:46.051 [MaintenanceTimer-2-thread-1] INFO  org.mongodb.driver.connection - Opened connection [connectionId{localValue:16, serverValue:255}] to 127.0.0.1:27017
01:08:46.086 [MaintenanceTimer-2-thread-1] INFO  org.mongodb.driver.connection - Opened connection [connectionId{localValue:17, serverValue:256}] to 127.0.0.1:27017

 

Comment by Jeffrey Yemin [ 01/Sep/22 ]

I'm not seeing the same thing as you. With a simple program like:

        var client = MongoClients.create(
                MongoClientSettings.builder()
                        .applyToConnectionPoolSettings(builder ->
                                builder.minSize(10))
                        .build());
 
        Thread.sleep(Long.MAX_VALUE);

and using a standalone mongod, after 10 minutes I see only ten INFO log statements:

08:42:53.824 [MaintenanceTimer-2-thread-1] INFO  org.mongodb.driver.connection - Opened connection [connectionId{localValue:3, serverValue:5322}] to 127.0.0.1:27017
08:42:53.829 [MaintenanceTimer-2-thread-1] INFO  org.mongodb.driver.connection - Opened connection [connectionId{localValue:4, serverValue:5323}] to 127.0.0.1:27017
08:42:53.834 [MaintenanceTimer-2-thread-1] INFO  org.mongodb.driver.connection - Opened connection [connectionId{localValue:5, serverValue:5324}] to 127.0.0.1:27017
08:42:53.840 [MaintenanceTimer-2-thread-1] INFO  org.mongodb.driver.connection - Opened connection [connectionId{localValue:6, serverValue:5325}] to 127.0.0.1:27017
08:42:53.846 [MaintenanceTimer-2-thread-1] INFO  org.mongodb.driver.connection - Opened connection [connectionId{localValue:7, serverValue:5326}] to 127.0.0.1:27017
08:42:53.849 [MaintenanceTimer-2-thread-1] INFO  org.mongodb.driver.connection - Opened connection [connectionId{localValue:8, serverValue:5327}] to 127.0.0.1:27017
08:42:53.854 [MaintenanceTimer-2-thread-1] INFO  org.mongodb.driver.connection - Opened connection [connectionId{localValue:9, serverValue:5328}] to 127.0.0.1:27017
08:42:53.860 [MaintenanceTimer-2-thread-1] INFO  org.mongodb.driver.connection - Opened connection [connectionId{localValue:10, serverValue:5329}] to 127.0.0.1:27017
08:42:53.862 [MaintenanceTimer-2-thread-1] INFO  org.mongodb.driver.connection - Opened connection [connectionId{localValue:11, serverValue:5330}] to 127.0.0.1:27017
08:42:53.869 [MaintenanceTimer-2-thread-1] INFO  org.mongodb.driver.connection - Opened connection [connectionId{localValue:12, serverValue:5331}] to 127.0.0.1:27017

since once the connections are opened they remain open indefinitely and the maintenance thread is basically a no-op. I'm not sure why you're seeing more log messages every minute.

Regardless, I think that we can safely change that message to DEBUG, so I'm going to go ahead and schedule this as an improvement for the next minor release (4.8).

Comment by Taeyang Jin (Heli) [ 01/Sep/22 ]

Thank you for answer. @Jeffrey Yemin

By the way, I'm surprised it's the first complaint.

If connection-pool-min-size: 20 / cluster hosts 3ea, 60 opened connection logs are written every cycle(default 1min).

 

Are other people using the tracing level of the logger as warn? 🤔

Comment by Jeffrey Yemin [ 31/Aug/22 ]

The log level was intentional. Log levels are always a judgement call, and for your scenario it seems like its too verbose for your liking. But so far, this is the first complaint about it that we've received.

You are of course free to change the log level in your application for the org.mongodb.driver.connection component to WARN, using whatever logging configuration mechanisms (it depends on whether you use Log4J, Logback, or something else) you have at your disposal.

Generated at Thu Feb 08 09:02:48 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.