[JAVA-3826] Sometimes the client connection is disconnected abnormally in batches Created: 17/Aug/20  Updated: 27/Oct/23  Resolved: 21/Sep/20

Status: Closed
Project: Java Driver
Component/s: Connection Management
Affects Version/s: None
Fix Version/s: None

Type: Task Priority: Major - P3
Reporter: yunbin liu Assignee: Jeffrey Yemin
Resolution: Gone away Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: Text File client.log     PNG File image-2020-08-17-23-56-01-208.png     PNG File image-2020-08-17-23-58-53-726.png     Text File server.log    

 Description   

We analyzed the switch logs and carried out tCPdump at the host layer, but found no obvious network exception.

The connection string is
"mongodb://resource:%2bfsdfd%2bfsfdfsf%3243fsdve%2b@10.25.148.181:27017,10.25.148.182:27017/resource?replicaSet=testrs&authSource=admin&connectTimeoutMS=100&maxPoolSize=150&waitQueueTimeoutMS=100&socketTimeoutMS=1000&maxIdleTimeMS=5400000&minPoolSize=30"

server log :

2020-08-17T18:53:49.542+0800 I NETWORK [listener] connection accepted from 10.25.148.40:59146 #155475 (2674 connections now open)
2020-08-17T18:53:49.542+0800 I NETWORK [listener] connection accepted from 10.25.148.40:13295 #155476 (2675 connections now open)
2020-08-17T18:53:49.542+0800 I NETWORK [conn155475] received client metadata from 10.25.148.40:59146 conn155475: \{ driver: { name: "mongo-java-driver|legacy", version: "3.12.4" }, os: \{ type: "Linux", name: "Linux", architecture: "amd64", version: "4.9.0-9-amd64" }, platform: "Java/Oracle Corporation/1.8.0_201-b09" }
2020-08-17T18:53:49.542+0800 I NETWORK [listener] connection accepted from 10.25.148.40:46468 #155477 (2676 connections now open)
2020-08-17T18:53:49.542+0800 I NETWORK [conn155476] received client metadata from 10.25.148.40:13295 conn155476: \{ driver: { name: "mongo-java-driver|legacy", version: "3.12.4" }, os: \{ type: "Linux", name: "Linux", architecture: "amd64", version: "4.9.0-9-amd64" }, platform: "Java/Oracle Corporation/1.8.0_201-b09" }
2020-08-17T18:53:49.542+0800 I NETWORK [listener] connection accepted from 10.25.148.40:40538 #155478 (2677 connections now open)
2020-08-17T18:53:49.542+0800 I NETWORK [conn155477] received client metadata from 10.25.148.40:46468 conn155477: \{ driver: { name: "mongo-java-driver|legacy", version: "3.12.4" }, os: \{ type: "Linux", name: "Linux", architecture: "amd64", version: "4.9.0-9-amd64" }, platform: "Java/Oracle Corporation/1.8.0_201-b09" }
2020-08-17T18:53:49.542+0800 I NETWORK [listener] connection accepted from 10.25.148.40:35110 #155479 (2678 connections now open)
2020-08-17T18:53:49.542+0800 I NETWORK [conn155478] received client metadata from 10.25.148.40:40538 conn155478: \{ driver: { name: "mongo-java-driver|legacy", version: "3.12.4" }, os: \{ type: "Linux", name: "Linux", architecture: "amd64", version: "4.9.0-9-amd64" }, platform: "Java/Oracle Corporation/1.8.0_201-b09" }
2020-08-17T18:53:49.543+0800 I NETWORK [conn155479] received client metadata from 10.25.148.40:35110 conn155479: \{ driver: { name: "mongo-java-driver|legacy", version: "3.12.4" }, os: \{ type: "Linux", name: "Linux", architecture: "amd64", version: "4.9.0-9-amd64" }, platform: "Java/Oracle Corporation/1.8.0_201-b09" }
2020-08-17T18:53:49.543+0800 I NETWORK [listener] connection accepted from 10.25.148.40:52853 #155480 (2679 connections now open)
2020-08-17T18:53:49.543+0800 I NETWORK [listener] connection accepted from 10.25.148.40:7166 #155481 (2680 connections now open)
2020-08-17T18:53:49.543+0800 I NETWORK [conn155480] received client metadata from 10.25.148.40:52853 conn155480: \{ driver: { name: "mongo-java-driver|legacy", version: "3.12.4" }, os: \{ type: "Linux", name: "Linux", architecture: "amd64", version: "4.9.0-9-amd64" }, platform: "Java/Oracle Corporation/1.8.0_201-b09" }
2020-08-17T18:53:49.543+0800 I NETWORK [listener] connection accepted from 10.25.148.40:36637 #155482 (2681 connections now open)
2020-08-17T18:53:49.543+0800 I NETWORK [conn155481] received client metadata from 10.25.148.40:7166 conn155481: \{ driver: { name: "mongo-java-driver|legacy", version: "3.12.4" }, os: \{ type: "Linux", name: "Linux", architecture: "amd64", version: "4.9.0-9-amd64" }, platform: "Java/Oracle Corporation/1.8.0_201-b09" }
2020-08-17T18:53:49.544+0800 I NETWORK [conn155482] received client metadata from 10.25.148.40:36637 conn155482: \{ driver: { name: "mongo-java-driver|legacy", version: "3.12.4" }, os: \{ type: "Linux", name: "Linux", architecture: "amd64", version: "4.9.0-9-amd64" }, platform: "Java/Oracle Corporation/1.8.0_201-b09" }
2020-08-17T18:53:49.544+0800 I NETWORK [listener] connection accepted from 10.25.148.40:44956 #155483 (2682 connections now open)
2020-08-17T18:53:49.544+0800 I NETWORK [listener] connection accepted from 10.25.148.40:24088 #155484 (2683 connections now open)
2020-08-17T18:53:49.544+0800 I NETWORK [conn155483] received client metadata from 10.25.148.40:44956 conn155483: \{ driver: { name: "mongo-java-driver|legacy", version: "3.12.4" }, os: \{ type: "Linux", name: "Linux", architecture: "amd64", version: "4.9.0-9-amd64" }, platform: "Java/Oracle Corporation/1.8.0_201-b09" }
2020-08-17T18:53:49.546+0800 I ACCESS [conn155467] Successfully authenticated as principal resource on admin
2020-08-17T18:53:49.547+0800 I ACCESS [conn155473] Successfully authenticated as principal resource on admin
2020-08-17T18:53:49.548+0800 I ACCESS [conn155464] Successfully authenticated as principal resource on admin
2020-08-17T18:53:49.548+0800 D REPL [conn155473] Waiting for write concern. OpTime: \{ ts: Timestamp(0, 0), t: -1 }, write concern: \{ w: 1, wtimeout: 0 }
2020-08-17T18:53:49.548+0800 D REPL [conn155467] Waiting for write concern. OpTime: \{ ts: Timestamp(0, 0), t: -1 }, write concern: \{ w: 1, wtimeout: 0 }
2020-08-17T18:53:49.549+0800 I ACCESS [conn155475] Successfully authenticated as principal resource on admin
2020-08-17T18:53:49.549+0800 I ACCESS [conn155470] Successfully authenticated as principal resource on admin
2020-08-17T18:53:49.549+0800 I ACCESS [conn155466] Successfully authenticated as principal resource on admin
2020-08-17T18:53:49.549+0800 D REPL [conn155464] Waiting for write concern. OpTime: \{ ts: Timestamp(0, 0), t: -1 }, write concern: \{ w: 1, wtimeout: 0 }
2020-08-17T18:53:49.549+0800 I ACCESS [conn155476] Successfully authenticated as principal resource on admin
2020-08-17T18:53:49.549+0800 I ACCESS [conn155483] Successfully authenticated as principal resource on admin
d64", version: "4.9.0-9-amd64" }, platform: "Java/Oracle Corporation/1.8.0_201-b09" }
2020-08-17T18:53:49.544+0800 I NETWORK [listener] connection accepted from 10.25.148.40:44956 #155483 (2682 connections now open)
2020-08-17T18:53:49.544+0800 I NETWORK [listener] connection accepted from 10.25.148.40:24088 #155484 (2683 connections now open)
2020-08-17T18:53:49.544+0800 I NETWORK [conn155483] received client metadata from 10.25.148.40:44956 conn155483: \{ driver: { name: "mongo-java-driver|legacy", version: "3.12.4" }, os: { type: "Linux", name: "Linux", architecture: "am
d64", version: "4.9.0-9-amd64" }, platform: "Java/Oracle Corporation/1.8.0_201-b09" }
2020-08-17T18:53:49.546+0800 I ACCESS [conn155467] Successfully authenticated as principal resource on admin
2020-08-17T18:53:49.547+0800 I ACCESS [conn155473] Successfully authenticated as principal resource on admin
2020-08-17T18:53:49.548+0800 I ACCESS [conn155464] Successfully authenticated as principal resource on admin
2020-08-17T18:53:49.548+0800 D REPL [conn155473] Waiting for write concern. OpTime: \{ ts: Timestamp(0, 0), t: -1 }, write concern: \{ w: 1, wtimeout: 0 }
2020-08-17T18:53:49.548+0800 D REPL [conn155467] Waiting for write concern. OpTime: \{ ts: Timestamp(0, 0), t: -1 }, write concern: \{ w: 1, wtimeout: 0 }
2020-08-17T18:53:49.549+0800 I ACCESS [conn155475] Successfully authenticated as principal resource on admin
2020-08-17T18:53:49.549+0800 I ACCESS [conn155470] Successfully authenticated as principal resource on admin
2020-08-17T18:53:49.549+0800 I ACCESS [conn155466] Successfully authenticated as principal resource on admin
2020-08-17T18:53:49.549+0800 D REPL [conn155464] Waiting for write concern. OpTime: \{ ts: Timestamp(0, 0), t: -1 }, write concern: \{ w: 1, wtimeout: 0 }
2020-08-17T18:53:49.549+0800 I ACCESS [conn155476] Successfully authenticated as principal resource on admin
2020-08-17T18:53:49.549+0800 I ACCESS [conn155483] Successfully authenticated as principal resource on admin
2020-08-17T18:53:49.550+0800 D REPL [conn155475] Waiting for write concern. OpTime: \{ ts: Timestamp(0, 0), t: -1 }, write concern: \{ w: 1, wtimeout: 0 }
2020-08-17T18:53:49.550+0800 I ACCESS [conn155471] Successfully authenticated as principal resource on admin
2020-08-17T18:53:49.551+0800 D REPL [conn155471] Waiting for write concern. OpTime: \{ ts: Timestamp(0, 0), t: -1 }, write concern: \{ w: 1, wtimeout: 0 }
2020-08-17T18:53:49.551+0800 D REPL [conn155476] Waiting for write concern. OpTime: \{ ts: Timestamp(0, 0), t: -1 }, write concern: \{ w: 1, wtimeout: 0 }
2020-08-17T18:53:49.551+0800 D REPL [conn155483] Waiting for write concern. OpTime: \{ ts: Timestamp(0, 0), t: -1 }, write concern: \{ w: 1, wtimeout: 0 }
2020-08-17T18:53:49.552+0800 I ACCESS [conn155469] Successfully authenticated as principal resource on admin
2020-08-17T18:53:49.552+0800 I ACCESS [conn155481] Successfully authenticated as principal resource on admin
2020-08-17T18:53:49.552+0800 I ACCESS [conn155480] Successfully authenticated as principal resource on admin
2020-08-17T18:53:49.554+0800 D REPL [conn155470] Waiting for write concern. OpTime: \{ ts: Timestamp(0, 0), t: -1 }, write concern: \{ w: 1, wtimeout: 0 }
2020-08-17T18:53:49.554+0800 D REPL [conn155480] Waiting for write concern. OpTime: \{ ts: Timestamp(0, 0), t: -1 }, write concern: \{ w: 1, wtimeout: 0 }
2020-08-17T18:53:49.554+0800 I ACCESS [conn155477] Successfully authenticated as principal resource on admin
2020-08-17T18:53:49.555+0800 D REPL [conn155469] Waiting for write concern. OpTime: \{ ts: Timestamp(0, 0), t: -1 }, write concern: \{ w: 1, wtimeout: 0 }
2020-08-17T18:53:49.556+0800 D REPL [conn155477] Waiting for write concern. OpTime: \{ ts: Timestamp(0, 0), t: -1 }, write concern: \{ w: 1, wtimeout: 0 }
2020-08-17T18:53:49.556+0800 I ACCESS [conn155474] Successfully authenticated as principal resource on admin
2020-08-17T18:53:49.556+0800 I ACCESS [conn155482] Successfully authenticated as principal resource on admin
2020-08-17T18:53:49.556+0800 D REPL [conn155481] Waiting for write concern. OpTime: \{ ts: Timestamp(0, 0), t: -1 }, write concern: \{ w: 1, wtimeout: 0 }
2020-08-17T18:53:49.558+0800 D REPL [conn155474] Waiting for write concern. OpTime: \{ ts: Timestamp(0, 0), t: -1 }, write concern: \{ w: 1, wtimeout: 0 }
2020-08-17T18:53:49.561+0800 D REPL [conn155482] Waiting for write concern. OpTime: \{ ts: Timestamp(0, 0), t: -1 }, write concern: \{ w: 1, wtimeout: 0 }
2020-08-17T18:53:49.561+0800 I NETWORK [conn155484] received client metadata from 10.25.148.40:24088 conn155484: \{ driver: { name: "mongo-java-driver|legacy", version: "3.12.4" }, os: \{ type: "Linux", name: "Linux", architecture: "amd64", version: "4.9.0-9-amd64" }, platform: "Java/Oracle Corporation/1.8.0_201-b09" }
2020-08-17T18:53:49.561+0800 D REPL [conn155466] Waiting for write concern. OpTime: \{ ts: Timestamp(0, 0), t: -1 }, write concern: \{ w: 1, wtimeout: 0 }
2020-08-17T18:53:49.566+0800 I ACCESS [conn155472] Successfully authenticated as principal resource on admin
2020-08-17T18:53:49.567+0800 D REPL [conn155472] Waiting for write concern. OpTime: \{ ts: Timestamp(0, 0), t: -1 }, write concern: \{ w: 1, wtimeout: 0 }
2020-08-17T18:53:49.576+0800 I ACCESS [conn155468] Successfully authenticated as principal resource on admin
2020-08-17T18:53:49.577+0800 I ACCESS [conn155484] Successfully authenticated as principal resource on admin
2020-08-17T18:53:49.577+0800 D REPL [conn155468] Waiting for write concern. OpTime: \{ ts: Timestamp(0, 0), t: -1 }, write concern: \{ w: 1, wtimeout: 0 }
2020-08-17T18:53:49.578+0800 D REPL [conn155484] Waiting for write concern. OpTime: \{ ts: Timestamp(0, 0), t: -1 }, write concern: \{ w: 1, wtimeout: 0 }
2020-08-17T18:53:49.581+0800 I ACCESS [conn155479] Successfully authenticated as principal resource on admin
2020-08-17T18:53:49.582+0800 I ACCESS [conn155478] Successfully authenticated as principal resource on admin
2020-08-17T18:53:49.578+0800 D REPL [conn155484] Waiting for write concern. OpTime: \{ ts: Timestamp(0, 0), t: -1 }, write concern: \{ w: 1, wtimeout: 0 }
2020-08-17T18:53:49.581+0800 I ACCESS [conn155479] Successfully authenticated as principal resource on admin
2020-08-17T18:53:49.582+0800 I ACCESS [conn155478] Successfully authenticated as principal resource on admin
2020-08-17T18:53:49.582+0800 D REPL [conn155479] Waiting for write concern. OpTime: \{ ts: Timestamp(0, 0), t: -1 }, write concern: \{ w: 1, wtimeout: 0 }
2020-08-17T18:53:49.587+0800 D REPL [conn155478] Waiting for write concern. OpTime: \{ ts: Timestamp(0, 0), t: -1 }, write concern: \{ w: 1, wtimeout: 0 }
2020-08-17T18:53:49.645+0800 D NETWORK [conn155473] Session from 10.25.148.40:59639 encountered a network error during SourceMessage
2020-08-17T18:53:49.645+0800 I NETWORK [worker-41] end connection 10.25.148.40:59639 (2682 connections now open)
2020-08-17T18:53:49.646+0800 D NETWORK [conn43589] Session from 10.25.148.40:16151 encountered a network error during SourceMessage
2020-08-17T18:53:49.646+0800 I NETWORK [worker-42] end connection 10.25.148.40:16151 (2681 connections now open)
2020-08-17T18:53:49.646+0800 D NETWORK [conn110102] Session from 10.25.148.40:42174 encountered a network error during SourceMessage
2020-08-17T18:53:49.646+0800 I NETWORK [worker-42] end connection 10.25.148.40:42174 (2680 connections now open)
2020-08-17T18:53:49.650+0800 D NETWORK [conn110106] Session from 10.25.148.40:28453 encountered a network error during SourceMessage
2020-08-17T18:53:49.650+0800 I NETWORK [worker-43] end connection 10.25.148.40:28453 (2679 connections now open)
2020-08-17T18:53:49.657+0800 D NETWORK [conn136056] Session from 10.25.148.40:17166 encountered a network error during SourceMessage
2020-08-17T18:53:49.657+0800 D NETWORK [conn155471] Session from 10.25.148.40:37415 encountered a network error during SourceMessage
2020-08-17T18:53:49.657+0800 I NETWORK [worker-41] end connection 10.25.148.40:17166 (2678 connections now open)
2020-08-17T18:53:49.657+0800 I NETWORK [worker-46] end connection 10.25.148.40:37415 (2677 connections now open)
2020-08-17T18:53:49.657+0800 D NETWORK [conn145242] Session from 10.25.148.40:18744 encountered a network error during SourceMessage
2020-08-17T18:53:49.657+0800 D NETWORK [conn155479] Session from 10.25.148.40:35110 encountered a network error during SourceMessage
2020-08-17T18:53:49.657+0800 I NETWORK [worker-41] end connection 10.25.148.40:18744 (2676 connections now open)
2020-08-17T18:53:49.657+0800 D NETWORK [conn155466] Session from 10.25.148.40:38110 encountered a network error during SourceMessage
2020-08-17T18:53:49.658+0800 D NETWORK [conn126344] Session from 10.25.148.40:49536 encountered a network error during SourceMessage
2020-08-17T18:53:49.658+0800 I NETWORK [worker-42] end connection 10.25.148.40:38110 (2674 connections now open)
2020-08-17T18:53:49.657+0800 D NETWORK [conn155467] Session from 10.25.148.40:36242 encountered a network error during SourceMessage
2020-08-17T18:53:49.657+0800 D NETWORK [conn155477] Session from 10.25.148.40:46468 encountered a network error during SourceMessage
2020-08-17T18:53:49.658+0800 D NETWORK [conn155475] Session from 10.25.148.40:59146 encountered a network error during SourceMessage
2020-08-17T18:53:49.658+0800 D NETWORK [conn43582] Session from 10.25.148.40:2026 encountered a network error during SourceMessage
2020-08-17T18:53:49.658+0800 D NETWORK [conn155470] Session from 10.25.148.40:50138 encountered a network error during SourceMessage
2020-08-17T18:53:49.657+0800 I NETWORK [worker-41] end connection 10.25.148.40:35110 (2675 connections now open)
2020-08-17T18:53:49.658+0800 I NETWORK [worker-41] end connection 10.25.148.40:50138 (2668 connections now open)
2020-08-17T18:53:49.658+0800 I NETWORK [worker-42] end connection 10.25.148.40:49536 (2673 connections now open)
2020-08-17T18:53:49.658+0800 I NETWORK [worker-41] end connection 10.25.148.40:36242 (2672 connections now open)
2020-08-17T18:53:49.658+0800 D NETWORK [conn77749] Session from 10.25.148.40:49801 encountered a network error during SourceMessage
2020-08-17T18:53:49.658+0800 D NETWORK [conn129608] Session from 10.25.148.40:48073 encountered a network error during SourceMessage
2020-08-17T18:53:49.658+0800 D NETWORK [conn83124] Session from 10.25.148.40:19305 encountered a network error during SourceMessage
2020-08-17T18:53:49.658+0800 D NETWORK [conn129838] Session from 10.25.148.40:50779 encountered a network error during SourceMessage
2020-08-17T18:53:49.658+0800 I NETWORK [worker-41] end connection 10.25.148.40:19305 (2665 connections now open)
2020-08-17T18:53:49.658+0800 I NETWORK [worker-41] end connection 10.25.148.40:46468 (2671 connections now open)
2020-08-17T18:53:49.658+0800 D NETWORK [conn155464] Session from 10.25.148.40:1816 encountered a network error during SourceMessage
2020-08-17T18:53:49.658+0800 D NETWORK [conn131606] Session from 10.25.148.40:26169 encountered a network error during SourceMessage
2020-08-17T18:53:49.658+0800 I NETWORK [worker-43] end connection 10.25.148.40:1816 (2663 connections now open)
2020-08-17T18:53:49.658+0800 D NETWORK [conn129254] Session from 10.25.148.40:11793 encountered a network error during SourceMessage
2020-08-17T18:53:49.658+0800 I NETWORK [worker-45] end connection 10.25.148.40:49801 (2667 connections now open)
2020-08-17T18:53:49.659+0800 I NETWORK [worker-42] end connection 10.25.148.40:11793 (2661 connections now open)
2020-08-17T18:53:49.659+0800 D NETWORK [conn141442] Session from 10.25.148.40:27984 encountered a network error during SourceMessage
2020-08-17T18:53:49.658+0800 I NETWORK [worker-44] end connection 10.25.148.40:48073 (2666 connections now open)
2020-08-17T18:53:49.658+0800 D NETWORK [conn104958] Session from 10.25.148.40:19755 encountered a network error during SourceMessage
2020-08-17T18:53:49.658+0800 I NETWORK [worker-46] end connection 10.25.148.40:50779 (2664 connections now open)
2020-08-17T18:53:49.658+0800 D NETWORK [conn129832] Session from 10.25.148.40:1650 encountered a network error during SourceMessage
2020-08-17T18:53:49.658+0800 D NETWORK [conn145244] Session from 10.25.148.40:35914 encountered a network error during SourceMessage
2020-08-17T18:53:49.659+0800 I NETWORK [worker-41] end connection 10.25.148.40:1650 (2658 connections now open)
2020-08-17T18:53:49.658+0800 D NETWORK [conn124946] Session from 10.25.148.40:27712 encountered a network error during SourceMessage
2020-08-17T18:53:49.658+0800 D NETWORK [conn129831] Session from 10.25.148.40:4672 encountered a network error during SourceMessage
2020-08-17T18:53:49.659+0800 I NETWORK [worker-41] end connection 10.25.148.40:27712 (2656 connections now open)
2020-08-17T18:53:49.659+0800 I NETWORK [worker-41] end connection 10.25.148.40:4672 (2655 connections now open)
2020-08-17T18:53:49.659+0800 D NETWORK [conn145241] Session from 10.25.148.40:7201 encountered a network error during SourceMessage
2020-08-17T18:53:49.659+0800 I NETWORK [worker-54] end connection 10.25.148.40:26169 (2662 connections now open)
2020-08-17T18:53:49.658+0800 I NETWORK [worker-41] end connection 10.25.148.40:2026 (2669 connections now open)
2020-08-17T18:53:49.658+0800 D NETWORK [conn64687] Session from 10.25.148.40:23805 encountered a network error during SourceMessage
2020-08-17T18:53:49.659+0800 D NETWORK [conn155484] Session from 10.25.148.40:24088 encountered a network error during SourceMessage
2020-08-17T18:53:49.660+0800 D NETWORK [conn64700] Session from 10.25.148.40:39318 encountered a network error during SourceMessage
2020-08-17T18:53:49.659+0800 I NETWORK [worker-42] end connection 10.25.148.40:19755 (2659 connections now open)
2020-08-17T18:53:49.660+0800 I NETWORK [worker-41] end connection 10.25.148.40:39318 (2651 connections now open)
2020-08-17T18:53:49.660+0800 D NETWORK [conn129835] Session from 10.25.148.40:37280 encountered a network error during SourceMessage
2020-08-17T18:53:49.658+0800 D NETWORK [conn126345] Session from 10.25.148.40:57361 encountered a network error during SourceMessage
2020-08-17T18:53:49.659+0800 D NETWORK [conn43583] Session from 10.25.148.40:39571 encountered a network error during SourceMessage
2020-08-17T18:53:49.660+0800 I NETWORK [worker-41] end connection 10.25.148.40:57361 (2649 connections now open)
2020-08-17T18:53:49.659+0800 D NETWORK [conn86700] Session from 10.25.148.40:23294 encountered a network error during SourceMessage
2020-08-17T18:53:49.659+0800 D NETWORK [conn145243] Session from 10.25.148.40:8510 encountered a network error during SourceMessage
2020-08-17T18:53:49.660+0800 I NETWORK [worker-42] end connection 10.25.148.40:23294 (2647 connections now open)
2020-08-17T18:53:49.658+0800 D NETWORK [conn83120] Session from 10.25.148.40:39803 encountered a network error during SourceMessage
2020-08-17T18:53:49.658+0800 I NETWORK [worker-41] end connection 10.25.148.40:59146 (2670 connections now open)
2020-08-17T18:53:49.659+0800 D NETWORK [conn91737] Session from 10.25.148.40:63245 encountered a network error during SourceMessage
2020-08-17T18:53:49.659+0800 D NETWORK [conn104960] Session from 10.25.148.40:43853 encountered a network error during SourceMessage
2020-08-17T18:53:49.659+0800 D NETWORK [conn104959] Session from 10.25.148.40:34012 encountered a network error during SourceMessage
2020-08-17T18:53:49.660+0800 I NETWORK [worker-42] end connection 10.25.148.40:43853 (2643 connections now open)
2020-08-17T18:53:49.659+0800 D NETWORK [conn131607] Session from 10.25.148.40:64970 encountered a network error during SourceMessage
2020-08-17T18:53:49.659+0800 I NETWORK [worker-41] end connection 10.25.148.40:7201 (2654 connections now open)
2020-08-17T18:53:49.659+0800 D NETWORK [conn43580] Session from 10.25.148.40:40143 encountered a network error during SourceMessage
2020-08-17T18:53:49.659+0800 I NETWORK [worker-41] end connection 10.25.148.40:23805 (2653 connections now open)
2020-08-17T18:53:49.659+0800 I NETWORK [worker-43] end connection 10.25.148.40:27984 (2660 connections now open)
2020-08-17T18:53:49.660+0800 I NETWORK [worker-41] end connection 10.25.148.40:24088 (2652 connections now open)
2020-08-17T18:53:49.658+0800 D NETWORK [conn31850] Session from 10.25.148.40:6915 encountered a network error during SourceMessage
2020-08-17T18:53:49.660+0800 D NETWORK [conn145245] Session from 10.25.148.40:37281 encountered a network error during SourceMessage
2020-08-17T18:53:49.659+0800 I NETWORK [worker-41] end connection 10.25.148.40:35914 (2657 connections now open)
2020-08-17T18:53:49.660+0800 D NETWORK [conn155481] Session from 10.25.148.40:7166 encountered a network error during SourceMessage
2020-08-17T18:53:49.660+0800 D NETWORK [conn155478] Session from 10.25.148.40:40538 encountered a network error during SourceMessage

  • Sometimes the client connection is disconnected abnormally in batches,the error message from the client is "there was a socket exception raised on another connection from this pool"
  • The connection may then be created in batches, and the following error may occur "no server chosen by ReadPreferenceServerSelector {ReadRreference=primary}........"
  • At this point, when the server log level is adjusted to level 2, a large number of errors can be found as follows "NETWORK [conn155465] Session from 10.25.148.40:34449 encountered a network error during SourceMessage"
    *


 Comments   
Comment by Jeffrey Yemin [ 21/Sep/20 ]

shazilyb@126.com as we haven't heard back from you we are closing this issue.

Comment by Eric Sedor [ 01/Sep/20 ]

shazilyb@126.com, we can confirm a connection timeout would invalidate other pooled connections, and cause the disconnections you are seeing, and the reconnections are prompted by the minimum pool size setting. We don't see evidence of a bug so far. Does this help?

Comment by Eric Sedor [ 31/Aug/20 ]

I see the following log line:

14:52:24.642	org.mongodb.driver.connection	Closed connection [connectionId{localValue:44}] to 10.25.148.182:27017 because there was a socket exception raised by this connection.

This occurs almost 100ms after connections with localValue 43 and 45 (along with others) are successfully opened. This suggests to me that the configured connectTimeoutMS of 100ms is being hit, possibly as a consequence of specifying that 30 connections be opened simultaneously.

Another possibility is that this could be similar to JAVA-1302, in which case the 1000ms socketTimeoutMS could be prompting the invalidated connections.

You may want to try higher connectTimeoutMS and socketTimeoutMS values to see if that resolves the batch disconnections.

I am going to pass this ticket to the java driver team to see if this is the expected behavior and verify what I am seeing.

Comment by yunbin liu [ 27/Aug/20 ]

Can someone help me analyze this issue  ???

Comment by yunbin liu [ 20/Aug/20 ]

server.logclient.log

^Thanks for your help,^The server and client logs are attached

Comment by Eric Sedor [ 19/Aug/20 ]

Hi shazilyb@126.com,

A set of connection closures with the "there was a socket exception raised on another connection from this pool" is generally expected behavior. A set of re-connections following this is also expected, especially with a specified minPoolSize.

So, we'd want to understand the initial exception that would have invalidated the connections in the pool. Do you have client and server logs covering any initial exception that occurs for one connection before other connections are closed?

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