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

Increase of user assertions in 5.0.x

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Open
    • Priority: Major - P3
    • Resolution: Unresolved
    • Affects Version/s: 5.0.2, 5.0.3
    • Fix Version/s: Backlog
    • Component/s: None
    • Labels:
      None
    • Operating System:
      ALL
    • Steps To Reproduce:
      Hide

      Set the log verbosity to 5 and execute the command:

       mongo -u user -p password --authenticationDatabase admin --quiet --eval 'db.adminCommand("ping").ok'

      In the logs you will find user assertions relating to HostUnreachable even thought the command return successfully.

      Show
      Set the log verbosity to 5 and execute the command: mongo -u user -p password --authenticationDatabase admin --quiet --eval 'db.adminCommand("ping").ok' In the logs you will find user assertions relating to HostUnreachable even thought the command return successfully.

      Description

      Since the upgrade from 4.4.4 to 5.0.3, we have observed a steadily increasing number of user assertions in the metrics. On debug level, user assertions with the error message "HostUnreachable: Connection closed by peer" became visible.

      As a cause for these user assertions we identified our Kubernetes readiness probe. It is successfully executed every 10 and opens a tcp socket on the mongodb port.

      Further analysis showed that this probe also generates error messages about "HostUnreachable" in 4.4.4, but these messages do not result in user assertions.

      This is the relevant log excerpt from 4.4.4:

      --->> {"t":{"$date":"2021-10-12T14:38:47.811+00:00"},"s":"D2", "c":"NETWORK",  "id":22986,   "ctx":"conn8778","msg":"Session from remote encountered a network error during SourceMessage","attr":{"remote":"172.23.43.233:44014","error":{"code":6,"codeName":"HostUnreachable","errmsg":"Connection closed by peer"}}
      {"t":{"$date":"2021-10-12T14:38:47.811+00:00"},"s":"I",  "c":"NETWORK",  "id":22944,   "ctx":"conn8778","msg":"Connection ended","attr":{"remote":"172.23.43.233:44014","connectionId":8778,"connectionCount":24}}

      And this is the excerpt from 5.0.3:

      {"t":{"$date":"2021-10-12T14:22:34.700+00:00"},"s":"D4", "c":"NETWORK",  "id":4898000, "ctx":"listener","msg":"Setting initial ServiceExecutor context for client","attr":{"client":"conn3385","threadingModel":"dedicated","canUseReserved":false}}
      {"t":{"$date":"2021-10-12T14:22:34.700+00:00"},"s":"D3", "c":"-",        "id":5127801, "ctx":"thread3756","msg":"Setting the Client","attr":{"client":"conn3385"}}
      -->> {"t":{"$date":"2021-10-12T14:22:34.700+00:00"},"s":"D2", "c":"NETWORK",  "id":22986,   "ctx":"conn3385","msg":"Session from remote encountered a network error during SourceMessage","attr":{"remote":"172.23.38.209:53800","error":{"code":6,"codeName":"HostUnreachable","errmsg":"Connection closed by peer"}}}
      {"t":{"$date":"2021-10-12T14:22:34.700+00:00"},"s":"D1", "c":"-",        "id":23074,   "ctx":"conn3385","msg":"User assertion","attr":{"error":"HostUnreachable: Connection closed by peer","file":"src/mongo/transport/service_state_machine.cpp","line":394}}
      {"t":{"$date":"2021-10-12T14:22:34.700+00:00"},"s":"D1", "c":"-",        "id":23074,   "ctx":"conn3385","msg":"User assertion","attr":{"error":"HostUnreachable: Connection closed by peer","file":"src/mongo/transport/service_state_machine.cpp","line":536}}
      {"t":{"$date":"2021-10-12T14:22:34.700+00:00"},"s":"D2", "c":"NETWORK",  "id":5763901, "ctx":"conn3385","msg":"Terminating session due to error","attr":{"error":{"code":6,"codeName":"HostUnreachable","errmsg":"Connection closed by peer"}}}
      {"t":{"$date":"2021-10-12T14:22:34.700+00:00"},"s":"D2", "c":"NETWORK",  "id":5127900, "ctx":"conn3385","msg":"Ending session","attr":{"error":{"code":6,"codeName":"HostUnreachable","errmsg":"Connection closed by peer"}}}
      {"t":{"$date":"2021-10-12T14:22:34.700+00:00"},"s":"D4", "c":"NETWORK",  "id":4898001, "ctx":"conn3385","msg":"Resetting ServiceExecutor context for client","attr":{"client":"conn3385","threadingModel":"dedicated","canUseReserved":false}}
      {"t":{"$date":"2021-10-12T14:22:34.700+00:00"},"s":"D4", "c":"NETWORK",  "id":4898001, "ctx":"conn3385","msg":"Resetting ServiceExecutor context for client","attr":{"client":"conn3385","threadingModel":"dedicated","canUseReserved":false}}
      {"t":{"$date":"2021-10-12T14:22:34.700+00:00"},"s":"I",  "c":"NETWORK",  "id":22944,   "ctx":"conn3385","msg":"Connection ended","attr":{"remote":"172.23.38.209:53800","uuid":"3402de9f-26f6-4a35-aff3-6806a83695c1","connectionId":3385,"connectionCount":30}}
      {"t":{"$date":"2021-10-12T14:22:34.700+00:00"},"s":"D3", "c":"-",        "id":5127803, "ctx":"conn3385","msg":"Released the Client","attr":{"client":"conn3385"}}
      {"t":{"$date":"2021-10-12T14:22:34.700+00:00"},"s":"D3", "c":"-",        "id":5127803, "ctx":"conn3385","msg":"Released the Client","attr":{"client":"conn3385"}}

      Please note how the marked lines appear in both versions but only in 5.0.3 there are the two additional user assertions.

       

      As an attempt to workaround the problem we changed the tcp socket probe to the following command:

      mongo -u user -p password --authenticationDatabase admin --quiet --eval 'db.adminCommand("ping").ok' 

      However, the user assertions persisted.

      Our questions:

      Why do both commands each return successfully but still generate a DEBUG message indicating an error?
      Why is the DEBUG message followed by a user assertion in version 5.0.3?

       

        Attachments

        1. mongod.4.4.10.log
          5 kB
        2. mongod.5.0.3.log
          7 kB
        3. Screen Shot 2021-10-25 at 1.25.38 PM.png
          Screen Shot 2021-10-25 at 1.25.38 PM.png
          130 kB

          Issue Links

            Activity

              People

              Assignee:
              backlog-server-servicearch Backlog - Service Architecture
              Reporter:
              grossmueller@e-spirit.com Tanja Großmüller
              Participants:
              Votes:
              0 Vote for this issue
              Watchers:
              7 Start watching this issue

                Dates

                Created:
                Updated: