[SERVER-49232] Confusing log message when fail point is activated Created: 01/Jul/20  Updated: 29/Oct/23  Resolved: 23/Nov/20

Status: Closed
Project: Core Server
Component/s: None
Affects Version/s: 4.4.0-rc11
Fix Version/s: 4.8.1, 4.4.3

Type: Bug Priority: Minor - P4
Reporter: Oleg Pudeyev (Inactive) Assignee: Gabriel Russell (Inactive)
Resolution: Fixed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Backports
Backwards Compatibility: Fully Compatible
Operating System: ALL
Backport Requested:
v4.4
Sprint: Service arch 2020-06-29, Service arch 2020-07-13, Service arch 2020-10-19
Participants:

 Description   

We had a report that the server produces the following fail point-related message in logs:

Line 24160: {
    "t": {
        "$date": "2020-07-01T16:46:48.767+01:00"
    },
    "s": "I",
    "c": "COMMAND",
    "id": 4898500,
    "ctx": "conn5238",
    "msg": "Should activate 'failCommand' failpoint",
    "attr": {
        "data": {
            "failCommands": ["isMaster"],
            "appName": "timeoutMonitorCheckTestAsyncTrue",
            "blockConnection": true,
            "blockTimeMS": 1000
        },
        "threadName": "conn5238",
        "appName": "timeoutMonitorCheckTestAsyncTrue",
        "namespace": "admin",
        "isInternalClient": 0,
        "command": "isMaster"
    }
}

This message is not clear as to what the server is communicating. Is the fail point being activated when the message is logged? Will the fail point be activated at some point in the future? Was the server going to activate the fail point but could not?

As a user of the server I would like the message to be more clear as to what the situation it is referring to is.

Example suggested rewording: "Activating fail point"

The message appears to be produced by CommandHelpers::shouldActivateFailCommandFailPoint.



 Comments   
Comment by Githook User [ 23/Nov/20 ]

Author:

{'name': 'Gabriel Russell', 'email': 'gabriel.russell@mongodb.com', 'username': 'gabrielrussell'}

Message: SERVER-49232 improving failCommand logging
Branch: v4.4
https://github.com/mongodb/mongo/commit/b5f3570ea5f29c103cd54631b4f0d15f5f1e6d15

Comment by Githook User [ 23/Nov/20 ]

Author:

{'name': 'Gabriel Russell', 'email': 'gabriel.russell@mongodb.com', 'username': 'gabrielrussell'}

Message: SERVER-49232 improving failCommand logging
Branch: master
https://github.com/mongodb/mongo/commit/17145e88ad22c4f4097c03be8bbc42125e36ccf9

Comment by Gabriel Russell (Inactive) [ 23/Nov/20 ]

For better or worse, I think that "namespace" is the correct name here. NamespaceString is just the type that we use to hold namepspaces. The namespace in the fail point is populated from the namespace in from the CommandInvocation. In the context of executing CommandInvocations the namespace is just a db when there is no collection name, and a fully qualified collection name when there is a collection name.

Comment by Bruce Lucas (Inactive) [ 20/Nov/20 ]

So maybe "namespaceString" to connect the message field to its origin?

Comment by Gabriel Russell (Inactive) [ 20/Nov/20 ]

bruce.lucas I'm reluctant to change the name to "db". The value being reported is the NamespaceString from the CommandInvocation. It appears to default to the "db" but it's not clear to be that it would always just only be a "db".

Comment by Gabriel Russell (Inactive) [ 20/Nov/20 ]

oleg.pudeyev Yes, it's being activated when the message is logged. I'll replace the message with "Activating 'failCommand' failpoint"".

Comment by Bruce Lucas (Inactive) [ 01/Jul/20 ]

Another minor point on that message: it has a "namespace" attr, but the value is not a namepace, but in stead is a db name, so the attr would be better as "db".

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