[SERVER-32521] standalone keeps trying to create lsidTTLIndex, printing log messages Created: 02/Jan/18  Updated: 08/Jan/24  Resolved: 03/May/18

Status: Closed
Project: Core Server
Component/s: None
Affects Version/s: 3.6.0
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Asya Kamsky Assignee: Mira Carey
Resolution: Gone away Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Operating System: ALL
Participants:

 Description   

2018-01-02T15:33:38.526-0500 I COMMAND  [thread3] command config.$cmd command: createIndexes { createIndexes: "system.sessions", indexes: [ { key: { lastUse: 1 }, name: "lsidTTLIndex", expireAfterSeconds: 1800 } ], $db: "config" } numYields:0 reslen:134 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { W: 1 } } } protocol:op_msg 0ms
2018-01-02T15:38:38.529-0500 I COMMAND  [thread3] command config.$cmd command: createIndexes { createIndexes: "system.sessions", indexes: [ { key: { lastUse: 1 }, name: "lsidTTLIndex", expireAfterSeconds: 1800 } ], $db: "config" } numYields:0 reslen:134 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { W: 1 } } } protocol:op_msg 0ms
2018-01-02T15:43:38.532-0500 I COMMAND  [thread2] command config.$cmd command: createIndexes { createIndexes: "system.sessions", indexes: [ { key: { lastUse: 1 }, name: "lsidTTLIndex", expireAfterSeconds: 1800 } ], $db: "config" } numYields:0 reslen:134 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { W: 1 } } } protocol:op_msg 0ms
2018-01-02T15:48:38.535-0500 I COMMAND  [thread3] command config.$cmd command: createIndexes { createIndexes: "system.sessions", indexes: [ { key: { lastUse: 1 }, name: "lsidTTLIndex", expireAfterSeconds: 1800 } ], $db: "config" } numYields:0 reslen:134 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { W: 1 } } } protocol:op_msg 0ms
2018-01-02T15:53:38.536-0500 I COMMAND  [thread2] command config.$cmd command: createIndexes { createIndexes: "system.sessions", indexes: [ { key: { lastUse: 1 }, name: "lsidTTLIndex", expireAfterSeconds: 1800 } ], $db: "config" } numYields:0 reslen:134 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { W: 1 } } } protocol:op_msg 0ms
2018-01-02T15:58:38.540-0500 I COMMAND  [thread2] command config.$cmd command: createIndexes { createIndexes: "system.sessions", indexes: [ { key: { lastUse: 1 }, name: "lsidTTLIndex", expireAfterSeconds: 1800 } ], $db: "config" } numYields:0 reslen:134 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { W: 1 } } } protocol:op_msg 0ms
2018-01-02T16:03:38.540-0500 I COMMAND  [thread3] command config.$cmd command: createIndexes { createIndexes: "system.sessions", indexes: [ { key: { lastUse: 1 }, name: "lsidTTLIndex", expireAfterSeconds: 1800 } ], $db: "config" } numYields:0 reslen:134 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { W: 1 } } } protocol:op_msg 0ms
2018-01-02T16:08:38.550-0500 I COMMAND  [thread2] command config.$cmd command: createIndexes { createIndexes: "system.sessions", indexes: [ { key: { lastUse: 1 }, name: "lsidTTLIndex", expireAfterSeconds: 1800 } ], $db: "config" } numYields:0 reslen:134 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { W: 1 } } } protocol:op_msg 0ms
2018-01-02T16:13:38.557-0500 I COMMAND  [thread2] command config.$cmd command: createIndexes { createIndexes: "system.sessions", indexes: [ { key: { lastUse: 1 }, name: "lsidTTLIndex", expireAfterSeconds: 1800 } ], $db: "config" } numYields:0 reslen:134 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { W: 1 } } } protocol:op_msg 0ms
2018-01-02T16:18:38.567-0500 I COMMAND  [thread3] command config.$cmd command: createIndexes { createIndexes: "system.sessions", indexes: [ { key: { lastUse: 1 }, name: "lsidTTLIndex", expireAfterSeconds: 1800 } ], $db: "config" } numYields:0 reslen:134 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { W: 1 } } } protocol:op_msg 0ms
2018-01-02T16:23:38.577-0500 I COMMAND  [thread2] command config.$cmd command: createIndexes { createIndexes: "system.sessions", indexes: [ { key: { lastUse: 1 }, name: "lsidTTLIndex", expireAfterSeconds: 1800 } ], $db: "config" } numYields:0 reslen:134 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { W: 1 } } } protocol:op_msg 0ms
2018-01-02T16:28:38.584-0500 I COMMAND  [thread2] command config.$cmd command: createIndexes { createIndexes: "system.sessions", indexes: [ { key: { lastUse: 1 }, name: "lsidTTLIndex", expireAfterSeconds: 1800 } ], $db: "config" } numYields:0 reslen:134 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { W: 1 } } } protocol:op_msg 0ms
2018-01-02T16:33:38.592-0500 I COMMAND  [thread3] command config.$cmd command: createIndexes { createIndexes: "system.sessions", indexes: [ { key: { lastUse: 1 }, name: "lsidTTLIndex", expireAfterSeconds: 1800 } ], $db: "config" } numYields:0 reslen:134 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { W: 1 } } } protocol:op_msg 0ms
2018-01-02T16:38:38.599-0500 I COMMAND  [thread2] command config.$cmd command: createIndexes { createIndexes: "system.sessions", indexes: [ { key: { lastUse: 1 }, name: "lsidTTLIndex", expireAfterSeconds: 1800 } ], $db: "config" } numYields:0 reslen:134 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { W: 1 } } } protocol:op_msg 0ms
2018-01-02T16:43:38.609-0500 I COMMAND  [thread2] command config.$cmd command: createIndexes { createIndexes: "system.sessions", indexes: [ { key: { lastUse: 1 }, name: "lsidTTLIndex", expireAfterSeconds: 1800 } ], $db: "config" } numYields:0 reslen:134 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { W: 1 } } } protocol:op_msg 0ms

No special options, version 3.6.0. Mac OS X.



 Comments   
Comment by Mira Carey [ 03/May/18 ]

Can't reproduce in 4.0, marking this as gone away

Comment by Asya Kamsky [ 13/Feb/18 ]

Previous version used on this dbpath was v3.5.13-160-g280981d - if we can't reproduce this then maybe it's an artifact of a bug in one of the development versions and I'm okay with closing this as gone away or can't reproduce.

Comment by Asya Kamsky [ 13/Feb/18 ]

The data files were through several versions, it looks like these messages started with 3.6.0-rc1 on this startup:

2017-10-31T16:34:10.675-0400 I CONTROL  [initandlisten] MongoDB starting : pid=41518 port=27017 dbpath=/data/db 64-bit host=Asyas-MacBook-Pro.local
2017-10-31T16:34:10.676-0400 I CONTROL  [initandlisten] db version v3.6.0-rc1
2017-10-31T16:34:10.676-0400 I CONTROL  [initandlisten] git version: 979ee612682b77d9cabaafae10787fbb578cd32a
2017-10-31T16:34:10.676-0400 I CONTROL  [initandlisten] OpenSSL version: OpenSSL 0.9.8zh 14 Jan 2016
2017-10-31T16:34:10.676-0400 I CONTROL  [initandlisten] allocator: system
2017-10-31T16:34:10.676-0400 I CONTROL  [initandlisten] modules: none
2017-10-31T16:34:10.676-0400 I CONTROL  [initandlisten] build environment:
2017-10-31T16:34:10.676-0400 I CONTROL  [initandlisten]     distarch: x86_64
2017-10-31T16:34:10.676-0400 I CONTROL  [initandlisten]     target_arch: x86_64
2017-10-31T16:34:10.676-0400 I CONTROL  [initandlisten] options: { processManagement: { fork: true }, storage: { wiredTiger: { engineConfig: { cacheSizeGB: 3.0 } } }, systemLog: { destination: "file", path: "/data/logs/360rc1.log" } }
2017-10-31T16:34:10.678-0400 I -        [initandlisten] Detected data files in /data/db created by the 'wiredTiger' storage engine, so setting the active storage engine to 'wiredTiger'.
2017-10-31T16:34:10.678-0400 I STORAGE  [initandlisten] wiredtiger_open config: create,cache_size=3072M,session_max=20000,eviction=(threads_min=4,threads_max=4),config_base=false,statistics=(fast),log=(enabled=true,archive=true,path=journal,compressor=snappy),file_manager=(close_idle_time=100000),statistics_log=(wait=0),verbose=(recovery_progress),
2017-10-31T16:34:10.932-0400 I STORAGE  [initandlisten] WiredTiger message [1509482050:932437][41518:0x7fffb6c393c0], txn-recover: Main recovery loop: starting at 129/4139520
2017-10-31T16:34:10.932-0400 I STORAGE  [initandlisten] WiredTiger message [1509482050:932951][41518:0x7fffb6c393c0], txn-recover: Recovering log 129 through 130
2017-10-31T16:34:10.944-0400 I STORAGE  [initandlisten] WiredTiger message [1509482050:944031][41518:0x7fffb6c393c0], txn-recover: Recovering log 130 through 130
2017-10-31T16:34:11.669-0400 I CONTROL  [initandlisten]
2017-10-31T16:34:11.670-0400 I CONTROL  [initandlisten] ** WARNING: Access control is not enabled for the database.
2017-10-31T16:34:11.670-0400 I CONTROL  [initandlisten] **          Read and write access to data and configuration is unrestricted.
2017-10-31T16:34:11.670-0400 I CONTROL  [initandlisten]
2017-10-31T16:34:11.670-0400 I CONTROL  [initandlisten] ** WARNING: This server is bound to localhost.
2017-10-31T16:34:11.670-0400 I CONTROL  [initandlisten] **          Remote systems will be unable to connect to this server.
2017-10-31T16:34:11.670-0400 I CONTROL  [initandlisten] **          Start the server with --bind_ip <address> to specify which IP
2017-10-31T16:34:11.671-0400 I CONTROL  [initandlisten] **          addresses it should serve responses from, or with --bind_ip_all to
2017-10-31T16:34:11.671-0400 I CONTROL  [initandlisten] **          bind to all interfaces. If this behavior is desired, start the
2017-10-31T16:34:11.671-0400 I CONTROL  [initandlisten] **          server with --bind_ip 127.0.0.1 to disable this warning.
2017-10-31T16:34:11.671-0400 I CONTROL  [initandlisten]
2017-10-31T16:34:12.089-0400 I FTDC     [initandlisten] Initializing full-time diagnostic data capture with directory '/data/db/diagnostic.data'
2017-10-31T16:34:12.091-0400 I NETWORK  [initandlisten] waiting for connections on port 27017
2017-10-31T16:39:12.112-0400 I STORAGE  [thread1] createCollection: config.system.sessions with UUID: e6be18dc-52cf-4afc-b973-2c1bb544dfaa
2017-10-31T16:39:12.196-0400 I INDEX    [thread1] build index on: config.system.sessions properties: { v: 2, key: { lastUse: 1 }, name: "lsidTTLIndex", ns: "config.system.sessions", expireAfterSeconds: 1800 }

Comment by Asya Kamsky [ 13/Feb/18 ]

Here were my startup options:

2017-12-28T11:33:47.907-0500 I CONTROL  [conn106] pid=26148 port=27017 64-bit host=Asyas-MacBook-Pro.local
2017-12-28T11:33:47.907-0500 I CONTROL  [conn106] db version v3.6.0
2017-12-28T11:33:47.907-0500 I CONTROL  [conn106] git version: a57d8e71e6998a2d0afde7edc11bd23e5661c915
2017-12-28T11:33:47.908-0500 I CONTROL  [conn106] OpenSSL version: OpenSSL 0.9.8zh 14 Jan 2016
2017-12-28T11:33:47.908-0500 I CONTROL  [conn106] allocator: system
2017-12-28T11:33:47.908-0500 I CONTROL  [conn106] modules: none
2017-12-28T11:33:47.908-0500 I CONTROL  [conn106] build environment:
2017-12-28T11:33:47.908-0500 I CONTROL  [conn106]     distarch: x86_64
2017-12-28T11:33:47.908-0500 I CONTROL  [conn106]     target_arch: x86_64
2017-12-28T11:33:47.908-0500 I CONTROL  [conn106] options: { processManagement: { fork: true }, storage: { wiredTiger: { engineConfig: { cacheSizeGB: 3.0 } } }, systemLog: { destination: "file", path: "/data/logs/360.log" } }
2017-12-28T11:33:47.908-0500 I COMMAND  [conn106] command admin.$cmd appName: "MongoDB Shell" command: logRotate { logRotate: 1.0, $db: "admin" } numYields:0 reslen:22 locks:{} protocol:op_msg 4ms

Files were created with earlier version, does that matter potentially?

Comment by Ramon Fernandez Marina [ 12/Feb/18 ]

I'm not able to reproduce this in 3.6.2:

  • Started a stand-alone server with mlaunch init --single
  • Inserted a few documents: mgenerate '{"a": "$number"}' -d test -c foo -n 1000000
  • Waited 4h
  • Inserted another 1000000 docs like above

Any particular options you started the server with?

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