[SERVER-25903] All internal ops are listed as coming from "MongoDB Shell" Created: 31/Aug/16  Updated: 19/Nov/16  Resolved: 01/Sep/16

Status: Closed
Project: Core Server
Component/s: Internal Client
Affects Version/s: 3.3.12
Fix Version/s: 3.3.14

Type: Bug Priority: Major - P3
Reporter: Eric Milkie Assignee: Mark Benvenuto
Resolution: Done Votes: 1
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Related
related to SERVER-25939 Missing appName in config server log ... Closed
Backwards Compatibility: Fully Compatible
Operating System: ALL
Sprint: Platforms 2016-09-19
Participants:

 Description   

If you run currentOp (the inprog command) and give it the flag to list all ops, even ones that are not "active", you will see that all internal operations have an appName of "MongoDB Shell".

Here is an example:
https://logkeeper.mongodb.org/build/20377e3d59ebcb239f4cb073cd7cefd6/test/57c6eac4be07c434ff040d28#L55396



 Comments   
Comment by Spencer Brody (Inactive) [ 01/Sep/16 ]

Okay, I opened a separate issue, SERVER-25939 to track the missing appName in the log message. Closing this issue out as it does indeed seem like the original issue reported here has been fixed.

Comment by Spencer Brody (Inactive) [ 01/Sep/16 ]

Okay I see, I didn't realize that it's expected that operations run on a mongod by a mongos will share the app name with the mongos operation that initiated the mongod op. In that case, now I'm confused about the _configsvrAddShard log message that doesn't include the shell as the app name. Seems like they all should.

Comment by Mark Benvenuto [ 01/Sep/16 ]

That is a user initiated {{_configsvrAddShard }} which was executed by the shell. The app name associated flows through mongos to mongod.

Comment by Spencer Brody (Inactive) [ 01/Sep/16 ]

Doesn't look like that fixed the issue with logging, at least not in all cases: https://logkeeper.mongodb.org/build/1db4ebc2bf70791b3654fbc8a33e3f57/test/57c88204be07c435af014246#L4498

[js_test:add_invalid_shard] 2016-09-01T19:31:32.177+0000 c23261| 2016-09-01T19:31:28.690+0000 I COMMAND  [conn13] command admin.$cmd appName:MongoDB Shell command: _configsvrAddShard { _configsvrAddShard: "ip-10-109-198-31:23260" } numYields:0 reslen:334 locks:{ Global: { acquireCount: { r: 12, w: 6 } }, Database: { acquireCount: { r: 3, w: 5, W: 1 } }, Collection: { acquireCount: { r: 3, w: 2 } }, Metadata: { acquireCount: { w: 4, W: 1 } }, Mutex: { acquireCount: { W: 1 } }, oplog: { acquireCount: { w: 3 } } } protocol:op_command 725ms

_configsvrAddShard always comes from a mongos, so it should never be printed with the shell as the app name.

Interestingly, earlier in that same run there's a log message of _configsvrAddShard that doesn't include the shell as the app name: https://logkeeper.mongodb.org/build/1db4ebc2bf70791b3654fbc8a33e3f57/test/57c88204be07c435af014246#L3772.

Comment by Githook User [ 01/Sep/16 ]

Author:

{u'username': u'markbenvenuto', u'name': u'Mark Benvenuto', u'email': u'mark.benvenuto@mongodb.com'}

Message: SERVER-25903 Use correct client in currentop list
Branch: master
https://github.com/mongodb/mongo/commit/a36409076c3de29c15e497ca3065e775e7369fa3

Comment by Eric Milkie [ 31/Aug/16 ]

Indeed, it looks like both the use of the internal C++ client to make network connections between internal nodes, and the use of Client/CurOp pairs with no associated network connection are both affected in the same way.

Comment by Spencer Brody (Inactive) [ 31/Aug/16 ]

Also affects log messages:

[js_test:add_invalid_shard] 2016-08-30T23:36:00.783+0000 c23511| 2016-08-30T23:36:00.779+0000 I COMMAND  [conn12] command admin.$cmd appName:MongoDB Shell command: _configsvrAddShard { _configsvrAddShard: "prefix_testReplSet/ip-10-164-212-90:23515,ip-10-164-212-90:23516" } numYields:0 reslen:466 locks:{ Mutex: { acquireCount: { W: 1 } } } protocol:op_command 19532ms

Generated at Thu Feb 08 04:10:34 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.