Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-53898

High frequency try to connect mongod which shutdown

XMLWordPrintableJSON

    • Type: Icon: Bug Bug
    • Resolution: Incomplete
    • Priority: Icon: Major - P3 Major - P3
    • None
    • Affects Version/s: 3.6 Required, 3.4 Required
    • Component/s: None
    • Labels:
      None
    • ALL
    • Hide

      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({userId:3000})

      4.when hit the  breakpoint（step 2），affirm  op is "IsMaster" and shutdown the secondary which the find operate target。

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

      6. When shut down the target physical machine ，because 5（huge amounts try to connect）from "connect refused" to "physical machine offline", NetworkInterfaceASIO-TaskExecutorPool will very slow to process other op.

      Show
      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({userId:3000}) 4.when hit the  breakpoint（step 2），affirm  op is "IsMaster" and shutdown the secondary which the find operate target。 5.Then  huge amounts of log will print and will not stop  6. When shut down the target physical machine ，because 5（huge amounts try to connect）from "connect refused" to "physical machine offline", NetworkInterfaceASIO-TaskExecutorPool will very slow to process other op.

      1. mongodb_dir.tar.gz
        18.72 MB
        Li xin

          Assignee:
          edwin.zhou@mongodb.com Edwin Zhou
          Reporter:
          bingfeng198878@163.com Li xin
          Votes:
          0 Vote for this issue
          Watchers:
          5 Start watching this issue

            Created:
            Updated:
            Resolved: