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.
- is duplicated by
-
SERVER-37049 MongoDB 3.6.7 arbiters continuously log "Using sessions while not fully upgraded to FCV3.6" even though replset is FCV3.6
-
- Closed
-
- related to
-
-
- Closed
-