[SERVER-16753] Wrong component for commands Created: 07/Jan/15  Updated: 15/Jan/15  Resolved: 08/Jan/15

Status: Closed
Project: Core Server
Component/s: Logging
Affects Version/s: 2.8.0-rc4
Fix Version/s: 2.8.0-rc5

Type: Bug Priority: Major - P3
Reporter: Thomas Rueckstiess Assignee: Eric Milkie
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Related
is related to SERVER-16755 Global severity seems to overwrite co... Closed
Backwards Compatibility: Fully Compatible
Operating System: ALL
Participants:

 Description   

I'm parsing a 2.8.0-rc4 log file, and find several lines that I'd expect to have the COMMAND component, but they are logged as QUERY instead.

Examples:

2015-01-07T17:35:33.306+1100 I QUERY    [conn30] command admin.$cmd command: _recvChunkCommit { _recvChunkCommit: 1 } ntoreturn:1 keyUpdates:0  reslen:313 451ms

2015-01-07T17:35:40.363+1100 I QUERY    [conn18] command test.$cmd command: insert { insert: "users", documents: 1000, ordered: true, metadata: { shardName: "shard01", shardVersion: [ Timestamp 3000|0, ObjectId('54acd38a9788a22960d0b573') ], session: 0 } } ntoreturn:1 keyUpdates:0  reslen:80 109ms

2015-01-07T17:36:29.213+1100 I QUERY    [conn26] command admin.$cmd command: splitChunk { splitChunk: "test.users", keyPattern: { _id: 1.0 }, min: { _id: ObjectId('54acd3d0fe4dce5012506c9b') }, max: { _id: MaxKey }, from: "shard01", splitKeys: [ { _id: ObjectId('54acd3e0fe4dce501050c8f5') }, { _id: ObjectId('54acd3ecfe4dce501350faad') } ], shardId: "test.users-_id_ObjectId('54acd3d0fe4dce5012506c9b')", configdb: "enter.local:27024", epoch: ObjectId('54acd38a9788a22960d0b573') } ntoreturn:1 keyUpdates:0 reslen:99 300ms

In fact, the only lines with COMMAND component in my file are these:

2015-01-07T17:38:11.815+1100 I COMMAND [conn47] terminating, shutdown command received
2015-01-07T17:38:12.227+1100 I COMMAND [conn47] now exiting
2015-01-07T17:38:12.267+1100 I COMMAND [conn47] dbexit: rc: 0
2015-01-07T17:39:43.245+1100 I COMMAND [conn19] terminating, shutdown command received
2015-01-07T17:39:43.767+1100 I COMMAND [conn19] now exiting
2015-01-07T17:39:43.799+1100 I COMMAND [conn19] dbexit: rc: 0

Which I wouldn't necessarily count as database commands according to this definition but perhaps CONTROL instead.

If this is because commands are internally queries on the $cmd collection, then this is very confusing and we should overwrite the component and force it to be COMMAND instead.



 Comments   
Comment by Githook User [ 08/Jan/15 ]

Author:

{u'username': u'milkie', u'name': u'Eric Milkie', u'email': u'milkie@10gen.com'}

Message: SERVER-16753 fix shutdown log messages to be component CONTROL
Branch: master
https://github.com/mongodb/mongo/commit/faaf37eb10307322cd068c8b87e1aef3008ed4ee

Comment by Githook User [ 08/Jan/15 ]

Author:

{u'username': u'milkie', u'name': u'Eric Milkie', u'email': u'milkie@10gen.com'}

Message: SERVER-16755 SERVER-16753 improvements to query logging
Branch: master
https://github.com/mongodb/mongo/commit/a509c387938bb8aef9a0254fcb464e25e90cbd24

Comment by Eric Milkie [ 07/Jan/15 ]

I linked the related ticket; these are both concerning the complicated logic for logging of queries/commands/writes at their completion.

Generated at Thu Feb 08 03:42:09 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.