[SERVER-48392] High frequency print logs Created: 25/May/20  Updated: 27/Oct/23  Resolved: 30/Jun/20

Status: Closed
Project: Core Server
Component/s: Logging
Affects Version/s: 3.4.18
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Li xin Assignee: Dmitry Agranat
Resolution: Community Answered Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: PNG File image-2020-05-25-19-09-03-690.png    
Operating System: ALL
Participants:

 Description   

Online,I call "rs.remove()"  repeatedly,mongos will print huge amounts of log like this(1GB+ logs everyminute

):

2020-05-25T18:30:42.175+0800 I ASIO [NetworkInterfaceASIO-TaskExecutorPool-0-0] Connecting to 127.0.0.1:15452
2020-05-25T18:30:42.175+0800 I ASIO [NetworkInterfaceASIO-TaskExecutorPool-0-0] Connecting to 127.0.0.1:15452
2020-05-25T18:30:42.175+0800 I ASIO [NetworkInterfaceASIO-TaskExecutorPool-0-0] Failed to connect to 127.0.0.1:15452 - HostUnreachable: Connection refused
2020-05-25T18:30:42.175+0800 D ASIO [NetworkInterfaceASIO-TaskExecutorPool-0-0] Request 176106 finished with response: HostUnreachable: Connection refused
2020-05-25T18:30:42.175+0800 D ASIO [NetworkInterfaceASIO-TaskExecutorPool-0-0] Request 176106, db:admin, request.cmdobj: { isMaster: 1 },request.metadata:{}
2020-05-25T18:30:42.175+0800 I ASIO [NetworkInterfaceASIO-TaskExecutorPool-0-0] Dropping all pooled connections to 127.0.0.1:15452 due to failed operation on a connection
2020-05-25T18:30:42.175+0800 I ASIO [NetworkInterfaceASIO-TaskExecutorPool-0-0] Failed to connect to 127.0.0.1:15452 - HostUnreachable: Connection refused
2020-05-25T18:30:42.176+0800 D ASIO [NetworkInterfaceASIO-TaskExecutorPool-0-0] Request 176107 finished with response: HostUnreachable: Connection refused
2020-05-25T18:30:42.176+0800 D ASIO [NetworkInterfaceASIO-TaskExecutorPool-0-0] Request 176107, db:admin, request.cmdobj: { isMaster: 1 },request.metadata:{}
2020-05-25T18:30:42.176+0800 I ASIO [NetworkInterfaceASIO-TaskExecutorPool-0-0] Connecting to 127.0.0.1:15452
2020-05-25T18:30:42.176+0800 I ASIO [NetworkInterfaceASIO-TaskExecutorPool-0-0] Connecting to 127.0.0.1:15452
2020-05-25T18:30:42.177+0800 I ASIO [NetworkInterfaceASIO-TaskExecutorPool-0-0] Failed to connect to 127.0.0.1:15452 - HostUnreachable: Connection refused
2020-05-25T18:30:42.177+0800 D ASIO [NetworkInterfaceASIO-TaskExecutorPool-0-0] Request 176108 finished with response: HostUnreachable: Connection refused
2020-05-25T18:30:42.177+0800 D ASIO [NetworkInterfaceASIO-TaskExecutorPool-0-0] Request 176108, db:admin, request.cmdobj: { isMaster: 1 },request.metadata:{}
2020-05-25T18:30:42.177+0800 I ASIO [NetworkInterfaceASIO-TaskExecutorPool-0-0] Dropping all pooled connections to 127.0.0.1:15452 due to failed operation on a connection
2020-05-25T18:30:42.177+0800 I ASIO [NetworkInterfaceASIO-TaskExecutorPool-0-0] Failed to connect to 127.0.0.1:15452 - HostUnreachable: Connection refused
2020-05-25T18:30:42.177+0800 D ASIO [NetworkInterfaceASIO-TaskExecutorPool-0-0] Request 176109 finished with response: HostUnreachable: Connection refused
2020-05-25T18:30:42.177+0800 D ASIO [NetworkInterfaceASIO-TaskExecutorPool-0-0] Request 176109, db:admin, request.cmdobj: { isMaster: 1 },request.metadata:{}
2020-05-25T18:30:42.178+0800 I ASIO [NetworkInterfaceASIO-TaskExecutorPool-0-0] Connecting to 127.0.0.1:15452
2020-05-25T18:30:42.178+0800 I ASIO [NetworkInterfaceASIO-TaskExecutorPool-0-0] Connecting to 127.0.0.1:15452
2020-05-25T18:30:42.179+0800 I ASIO [NetworkInterfaceASIO-TaskExecutorPool-0-0] Failed to connect to 127.0.0.1:15452 - HostUnreachable: Connection refused
2020-05-25T18:30:42.179+0800 D ASIO [NetworkInterfaceASIO-TaskExecutorPool-0-0] Request 176110 finished with response: HostUnreachable: Connection refused
2020-05-25T18:30:42.179+0800 D ASIO [NetworkInterfaceASIO-TaskExecutorPool-0-0] Request 176110, db:admin, request.cmdobj: { isMaster: 1 },request.metadata:{}
2020-05-25T18:30:42.179+0800 I ASIO [NetworkInterfaceASIO-TaskExecutorPool-0-0] Dropping all pooled connections to 127.0.0.1:15452 due to failed operation on a connection
2020-05-25T18:30:42.179+0800 I ASIO [NetworkInterfaceASIO-TaskExecutorPool-0-0] Failed to connect to 127.0.0.1:15452 - HostUnreachable: Connection refused
2020-05-25T18:30:42.179+0800 D ASIO [NetworkInterfaceASIO-TaskExecutorPool-0-0] Request 176111 finished with response: HostUnreachable: Connection refused
2020-05-25T18:30:42.179+0800 D ASIO [NetworkInterfaceASIO-TaskExecutorPool-0-0] Request 176111, db:admin, request.cmdobj: { isMaster: 1 },request.metadata:{}
2020-05-25T18:30:42.179+0800 I ASIO [NetworkInterfaceASIO-TaskExecutorPool-0-0] Connecting to 127.0.0.1:15452
2020-05-25T18:30:42.179+0800 I ASIO [NetworkInterfaceASIO-TaskExecutorPool-0-0] Connecting to 127.0.0.1:15452
2020-05-25T18:30:42.180+0800 I ASIO [NetworkInterfaceASIO-TaskExecutorPool-0-0] Failed to connect to 127.0.0.1:15452 - HostUnreachable: Connection refused
2020-05-25T18:30:42.180+0800 D ASIO [NetworkInterfaceASIO-TaskExecutorPool-0-0] Request 176112 finished with response: HostUnreachable: Connection refused
2020-05-25T18:30:42.180+0800 D ASIO [NetworkInterfaceASIO-TaskExecutorPool-0-0] Request 176112, db:admin, request.cmdobj: { isMaster: 1 },request.metadata:{}
2020-05-25T18:30:42.180+0800 I ASIO [NetworkInterfaceASIO-TaskExecutorPool-0-0] Dropping all pooled connections to 127.0.0.1:15452 due to failed operation on a connection
2020-05-25T18:30:42.180+0800 I ASIO [NetworkInterfaceASIO-TaskExecutorPool-0-0] Failed to connect to 127.0.0.1:15452 - HostUnreachable: Connection refused
2020-05-25T18:30:42.180+0800 D ASIO [NetworkInterfaceASIO-TaskExecutorPool-0-0] Request 176113 finished with response: HostUnreachable: Connection refused
2020-05-25T18:30:42.180+0800 D ASIO [NetworkInterfaceASIO-TaskExecutorPool-0-0] Request 176113, db:admin, request.cmdobj: { isMaster: 1 },request.metadata:{}
2020-05-25T18:30:42.180+0800 I ASIO [NetworkInterfaceASIO-TaskExecutorPool-0-0] Connecting to 127.0.0.1:15452
2020-05-25T18:30:42.180+0800 I ASIO [NetworkInterfaceASIO-TaskExecutorPool-0-0] Connecting to 127.0.0.1:15452

 

I reproduce the problem local.

1.mongos set db.getMongo().setReadPref('secondary')

2.make breakpoint at   NetworkInterfaceASIO::_asyncRunCommand  ‘s

asyncSendMessage(cmd->conn().stream(), &cmd->toSend(), std::move(sendMessageCallback));

3.exec find operate,like:db.test.find()

4.when hit the  breakpoint(step 2), shutdown the secondary which the find operate target。

5.Then  huge amounts of log will print and will not stop。

 



 Comments   
Comment by Dmitry Agranat [ 02/Jun/20 ]

Anything above 3.4 is fine but the recommendation is for the latest MongoDB version, which is currently 4.2.

Comment by Li xin [ 31/May/20 ]

Is version 3.6 still under maintenance? We use rocksdb engine,so I can try v3.6.

Comment by Dmitry Agranat [ 31/May/20 ]

Hi bingfeng198878@163.com, as MongoDB 3.4 has already reached EOL, would you re-run this on MongoDB 4.2.7 and let us know if you still see this issue?

Thanks,
Dima

Comment by Li xin [ 26/May/20 ]

infinite loop 

Generated at Thu Feb 08 05:16:59 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.