[SERVER-36777] Excessive logging with sessions in FCV 3.4 Created: 21/Aug/18  Updated: 08/Jan/24  Resolved: 21/Aug/18

Status: Closed
Project: Core Server
Component/s: Sharding
Affects Version/s: 3.6.7
Fix Version/s: 3.6.8

Type: Bug Priority: Major - P3
Reporter: Kevin Pulo Assignee: Misha Tyulenev
Resolution: Fixed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Duplicate
is duplicated by SERVER-37049 MongoDB 3.6.7 arbiters continuously l... Closed
Related
related to SERVER-36248 Do not reject sessions in FCV 3.4 Closed
Backwards Compatibility: Fully Compatible
Operating System: ALL
Sprint: Sharding 2018-08-27
Participants:
Case:

 Description   

SERVER-36248 introduced a "Using sessions while not fully upgraded to FCV3.6" log message at default log level. However, the internal driver in mongod/mongos is still attempting to use sessions, even though FCV is 3.4 and localLogicalSessionTimeoutMinutes is not advertised in the isMaster response.

This causes considerable log spam in replsets/sharded clusters that haven't yet upgraded FCV to 3.6 (from the various ReplSetMonitors, etc). Many users/customers like to run for an extended period (eg. up to weeks) on the previous FCV, since that greatly simplifies downgrade in the event of any issues. The amount of logging will scale with the size of the replset/sharded cluster.

For example, this is the logfile from an idle replset running 3.6.7-rc1 on FCV 3.4:

2018-08-21T11:39:46.151+1000 I NETWORK  [listener] connection accepted from 127.0.0.1:55448 #1 (1 connection now open)
2018-08-21T11:39:46.151+1000 I NETWORK  [conn1] received client metadata from 127.0.0.1:55448 conn1: { driver: { name: "PyMongo", version: "3.7.1" }, os: { type: "Linux", name: "Ubuntu 16.04 xenial", architecture: "x86_64", version: "4.15.0-32-generic" }, platform: "CPython 2.7.12.final.0" }
2018-08-21T11:39:46.152+1000 I NETWORK  [listener] connection accepted from 127.0.0.1:55452 #2 (2 connections now open)
2018-08-21T11:39:46.152+1000 I NETWORK  [conn2] received client metadata from 127.0.0.1:55452 conn2: { driver: { name: "PyMongo", version: "3.7.1" }, os: { type: "Linux", name: "Ubuntu 16.04 xenial", architecture: "x86_64", version: "4.15.0-32-generic" }, platform: "CPython 2.7.12.final.0" }
2018-08-21T11:39:46.153+1000 I NETWORK  [conn2] end connection 127.0.0.1:55452 (1 connection now open)
2018-08-21T11:39:46.153+1000 I NETWORK  [conn1] end connection 127.0.0.1:55448 (0 connections now open)
2018-08-21T11:39:46.156+1000 I NETWORK  [listener] connection accepted from 127.0.0.1:55458 #3 (1 connection now open)
2018-08-21T11:39:46.156+1000 I NETWORK  [conn3] received client metadata from 127.0.0.1:55458 conn3: { driver: { name: "PyMongo", version: "3.7.1" }, os: { type: "Linux", name: "Ubuntu 16.04 xenial", architecture: "x86_64", version: "4.15.0-32-generic" }, platform: "CPython 2.7.12.final.0" }
2018-08-21T11:39:46.157+1000 I NETWORK  [listener] connection accepted from 127.0.0.1:55464 #4 (2 connections now open)
2018-08-21T11:39:46.158+1000 I NETWORK  [conn4] received client metadata from 127.0.0.1:55464 conn4: { driver: { name: "PyMongo", version: "3.7.1" }, os: { type: "Linux", name: "Ubuntu 16.04 xenial", architecture: "x86_64", version: "4.15.0-32-generic" }, platform: "CPython 2.7.12.final.0" }
2018-08-21T11:39:46.158+1000 I NETWORK  [conn4] end connection 127.0.0.1:55464 (1 connection now open)
2018-08-21T11:39:46.158+1000 I NETWORK  [conn3] end connection 127.0.0.1:55458 (0 connections now open)
2018-08-21T11:39:46.164+1000 I NETWORK  [listener] connection accepted from 127.0.0.1:55474 #5 (1 connection now open)
2018-08-21T11:39:46.164+1000 I NETWORK  [conn5] received client metadata from 127.0.0.1:55474 conn5: { driver: { name: "PyMongo", version: "3.7.1" }, os: { type: "Linux", name: "Ubuntu 16.04 xenial", architecture: "x86_64", version: "4.15.0-32-generic" }, platform: "CPython 2.7.12.final.0" }
2018-08-21T11:39:46.166+1000 I NETWORK  [listener] connection accepted from 127.0.0.1:55476 #6 (2 connections now open)
2018-08-21T11:39:46.166+1000 I NETWORK  [conn6] received client metadata from 127.0.0.1:55476 conn6: { driver: { name: "PyMongo", version: "3.7.1" }, os: { type: "Linux", name: "Ubuntu 16.04 xenial", architecture: "x86_64", version: "4.15.0-32-generic" }, platform: "CPython 2.7.12.final.0" }
2018-08-21T11:39:46.166+1000 I NETWORK  [conn6] end connection 127.0.0.1:55476 (1 connection now open)
2018-08-21T11:39:46.166+1000 I NETWORK  [conn5] end connection 127.0.0.1:55474 (0 connections now open)
2018-08-21T11:39:46.167+1000 I NETWORK  [listener] connection accepted from 127.0.0.1:55478 #7 (1 connection now open)
2018-08-21T11:39:46.167+1000 I NETWORK  [conn7] received client metadata from 127.0.0.1:55478 conn7: { driver: { name: "PyMongo", version: "3.7.1" }, os: { type: "Linux", name: "Ubuntu 16.04 xenial", architecture: "x86_64", version: "4.15.0-32-generic" }, platform: "CPython 2.7.12.final.0" }
2018-08-21T11:39:46.168+1000 I NETWORK  [conn7] end connection 127.0.0.1:55478 (0 connections now open)
2018-08-21T11:39:46.350+1000 I NETWORK  [listener] connection accepted from 127.0.0.1:55484 #8 (1 connection now open)
2018-08-21T11:39:46.350+1000 I NETWORK  [conn8] received client metadata from 127.0.0.1:55484 conn8: { driver: { name: "NetworkInterfaceASIO-Replication", version: "3.6.7-rc1" }, os: { type: "Linux", name: "Ubuntu", architecture: "x86_64", version: "16.04" } }
2018-08-21T11:39:46.350+1000 I -        [conn8] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:39:46.504+1000 I NETWORK  [listener] connection accepted from 127.0.0.1:55486 #9 (2 connections now open)
2018-08-21T11:39:46.504+1000 I NETWORK  [conn9] received client metadata from 127.0.0.1:55486 conn9: { driver: { name: "NetworkInterfaceASIO-Replication", version: "3.6.7-rc1" }, os: { type: "Linux", name: "Ubuntu", architecture: "x86_64", version: "16.04" } }
2018-08-21T11:39:46.504+1000 I -        [conn9] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:39:46.851+1000 I -        [conn8] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:39:47.004+1000 I -        [conn9] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:39:47.351+1000 I -        [conn8] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:39:47.505+1000 I -        [conn9] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:39:47.851+1000 I -        [conn8] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:39:48.005+1000 I -        [conn9] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:39:48.351+1000 I -        [conn8] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:39:48.505+1000 I -        [conn9] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:39:48.852+1000 I -        [conn8] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:39:49.005+1000 I -        [conn9] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:39:49.352+1000 I -        [conn8] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:39:49.506+1000 I -        [conn9] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:39:49.853+1000 I -        [conn8] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:39:50.006+1000 I -        [conn9] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:39:50.353+1000 I -        [conn8] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:39:50.506+1000 I -        [conn9] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:39:50.854+1000 I -        [conn8] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:39:51.007+1000 I -        [conn9] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:39:51.354+1000 I -        [conn8] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:39:51.507+1000 I -        [conn9] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:39:51.855+1000 I -        [conn8] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:39:52.008+1000 I -        [conn9] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:39:52.355+1000 I -        [conn8] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:39:52.508+1000 I -        [conn9] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:39:52.855+1000 I -        [conn8] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:39:53.009+1000 I -        [conn9] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:39:53.356+1000 I -        [conn8] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:39:53.509+1000 I -        [conn9] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:39:53.856+1000 I -        [conn8] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:39:54.009+1000 I -        [conn9] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:39:54.151+1000 I -        [conn8] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:39:54.156+1000 I -        [conn8] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:39:54.160+1000 I -        [conn8] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:39:54.510+1000 I -        [conn9] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:39:54.653+1000 I REPL     [replexec-1] Member localhost:12345 is now in state PRIMARY
2018-08-21T11:39:55.010+1000 I -        [conn9] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:39:55.510+1000 I -        [conn9] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:39:56.010+1000 I -        [conn9] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:39:56.161+1000 I -        [conn8] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:39:56.511+1000 I -        [conn9] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:39:57.011+1000 I -        [conn9] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:39:57.148+1000 I REPL     [rsBackgroundSync] sync source candidate: localhost:12345
2018-08-21T11:39:57.148+1000 I ASIO     [NetworkInterfaceASIO-RS-0] Connecting to localhost:12345
2018-08-21T11:39:57.149+1000 I ASIO     [NetworkInterfaceASIO-RS-0] Successfully connected to localhost:12345, took 1ms (1 connections now open to localhost:12345)
2018-08-21T11:39:57.150+1000 I REPL     [rsBackgroundSync] Changed sync source from empty to localhost:12345
2018-08-21T11:39:57.150+1000 I ASIO     [NetworkInterfaceASIO-RS-0] Connecting to localhost:12345
2018-08-21T11:39:57.150+1000 I ASIO     [NetworkInterfaceASIO-RS-0] Successfully connected to localhost:12345, took 0ms (2 connections now open to localhost:12345)
2018-08-21T11:39:58.161+1000 I -        [conn8] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:39:59.011+1000 I -        [conn9] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:40:00.162+1000 I -        [conn8] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:40:01.012+1000 I -        [conn9] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:40:02.162+1000 I -        [conn8] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:40:03.012+1000 I -        [conn9] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:40:04.163+1000 I -        [conn8] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:40:05.013+1000 I -        [conn9] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:40:06.163+1000 I -        [conn8] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:40:07.013+1000 I -        [conn9] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:40:08.164+1000 I -        [conn8] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:40:09.013+1000 I -        [conn9] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:40:10.164+1000 I -        [conn8] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:40:11.014+1000 I -        [conn9] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:40:12.164+1000 I -        [conn8] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:40:13.015+1000 I -        [conn9] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:40:14.165+1000 I -        [conn8] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:40:15.016+1000 I -        [conn9] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:40:16.165+1000 I -        [conn8] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:40:17.016+1000 I -        [conn9] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:40:18.166+1000 I -        [conn8] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:40:19.016+1000 I -        [conn9] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:40:20.166+1000 I -        [conn8] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:40:21.017+1000 I -        [conn9] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:40:22.167+1000 I -        [conn8] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:40:23.017+1000 I -        [conn9] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:40:24.167+1000 I -        [conn8] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:40:25.018+1000 I -        [conn9] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:40:26.168+1000 I -        [conn8] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:40:27.018+1000 I -        [conn9] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:40:28.168+1000 I -        [conn8] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:40:29.022+1000 I -        [conn9] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:40:30.169+1000 I -        [conn8] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:40:31.022+1000 I -        [conn9] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:40:32.169+1000 I -        [conn8] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:40:33.022+1000 I -        [conn9] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:40:34.170+1000 I -        [conn8] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:40:35.025+1000 I -        [conn9] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:40:36.170+1000 I -        [conn8] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:40:37.026+1000 I -        [conn9] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:40:38.170+1000 I -        [conn8] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:40:39.026+1000 I -        [conn9] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:40:40.171+1000 I -        [conn8] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:40:41.026+1000 I -        [conn9] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:40:42.171+1000 I -        [conn8] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:40:43.026+1000 I -        [conn9] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:40:44.172+1000 I -        [conn8] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:40:45.027+1000 I -        [conn9] Using sessions while not fully upgraded to FCV3.6
2018-08-21T11:40:46.172+1000 I -        [conn8] Using sessions while not fully upgraded to FCV3.6

Steps to repro:

mlaunch init --replicaset --nodes 3 --port 12345 --binarypath /omni/3.6.7-rc1/bin
mongo --port 12345 --eval 'db.adminCommand({setFeatureCompatibilityVersion:"3.4"})'
mlaunch restart    # to ensure the internal driver has current isMaster knowledge from remotes
# look at the logfiles, eg:
# $ grep -c 'Using sessions while not fully upgraded' data/replset/rs1/mongod.log ; sleep 60 ; grep -c 'Using sessions while not fully upgraded' data/replset/rs1/mongod.log
# 588
# 720

Either:

  • The internal driver should be fixed to only attempt to use sessions when the remote supports them, or
  • This message should be logged less frequently, to prevent these excessive log lines. For example, as a warning() the first time encountered, and as LOG(1) for subsequent occurrences.


 Comments   
Comment by Adrien Jarthon [ 01/Oct/18 ]

Ah ok, from reading the comment I didn't though this was actually fixed already. I'll try to update once it has synced again.

Comment by Kelsey Schubert [ 01/Oct/18 ]

Hi bigbourin@gmail.com,

I'm sorry you encountered this issue. As this bug only affects MongoDB 3.6.7, my advice would be to upgrade to latest version of MongoDB 3.6, currently 3.6.8, where this issue has been resolved.

Kind regards,
Kelsey

Comment by Adrien Jarthon [ 01/Oct/18 ]

Indeed I've just fell on this issue as it filled up my disk and thus just killed my server. There was a monitoring issue on the /var partition of course but nonetheless this is fun to see that it's again mongodb's fault and for something useless. Any workaround right now?

Comment by Githook User [ 21/Aug/18 ]

Author:

{'name': 'Misha Tyulenev', 'email': 'misha@mongodb.com', 'username': 'mikety'}

Message: SERVER-36777 remove logging warnings with sessions in FCV 3.4
Branch: v3.6
https://github.com/mongodb/mongo/commit/29cbaa141b4c7a98faa26f3b64f66ab7d73d1b36

Comment by Misha Tyulenev [ 21/Aug/18 ]

The check for session is missing so its always going to print this message until upgraded to 3.6

Comment by Mira Carey [ 21/Aug/18 ]

I think that log message is actually spurious. If you take a look at: https://github.com/mongodb/mongo/blob/2628472127e9f1826e02c665c1d93880a204075e/src/mongo/db/initialize_operation_session_info.cpp#L119, note that we hit that line regardless of whether we actually sent txnnumber or lsid.

I annotated that log line with the requestBody in a local checkout of 3.6 and you'll see messages like:

Local diff:

diff --git a/src/mongo/db/initialize_operation_session_info.cpp b/src/mongo/db/initialize_oper>
index 0390e4300d..a4520c45f1 100644
--- a/src/mongo/db/initialize_operation_session_info.cpp
+++ b/src/mongo/db/initialize_operation_session_info.cpp
@@ -117,7 +117,7 @@ Status initializeOperationSessionInfo(OperationContext* opCtx,
     }
 
     if (!isFCV36) {
-        log() << "Using sessions while not fully upgraded to FCV3.6";
+        log() << "Using sessions while not fully upgraded to FCV3.6 - " << requestBody;
     }
 
     return Status::OK();

Log messages:

2018-08-21T11:58:47.610-0400 I -        [conn44] Using sessions while not fully upgraded to FCV3.6 - { replSetHeartbeat: "rs", configVersion: 1, from: "localhost:20001", fromId: 1, term: 3, $replData: 1, $clusterTime: { clusterTime: Timestamp(1534867119, 1), signature: { hash: BinData(0, 0000000000000000000000000000000000000000), keyId: 0 } }, $db: "admin" }           

Comment by Kaloian Manassiev [ 21/Aug/18 ]

The idea of this log message was to prompt people who are using the new drivers against a server with old FCV to either bump the FCV or downgrade the driver while they are validating the new server.

mira.carey@mongodb.com, I wasn't aware that the internal NetworkInterface driver uses sessions by default. Is there a flag by any chance to turn that off?

Comment by Kevin Pulo [ 21/Aug/18 ]

Also thanks linda.qin for finding and reporting this problem!

Generated at Thu Feb 08 04:44:03 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.