[SERVER-30709] mongo can't start in kubernetes when start from last clean shutdown Created: 17/Aug/17  Updated: 04/Oct/18  Resolved: 07/Sep/17

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

Type: Bug Priority: Major - P3
Reporter: Jennings Assignee: Mark Agarunov
Resolution: Cannot Reproduce Votes: 0
Labels: RF
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: File WiredTiger.wt     File mongod.SERVER-30709.strace     File repair-SERVER-30709.tar.gz    
Issue Links:
Related
is related to SERVER-37473 mongo can't start in kubernetes after... Closed
Operating System: ALL
Participants:

 Description   

I use mongo:3.4 to start mongo in kubernetes with arguments
mongod --replSet rs0 --smallfiles --noprealloc --storageEngine=wiredTiger --wiredTigerCacheSizeGB=0.5 -vvvvvv

the volumes contains the old data, copy from other instance (which is clean shutdown), but still got following error:

note: noprealloc may hurt performance in many applications
2017-08-17T05:08:20.654+0000 I CONTROL  [initandlisten] MongoDB starting : pid=1 port=27017 dbpath=/data/db 64-bit host=mongo-0
2017-08-17T05:08:20.654+0000 I CONTROL  [initandlisten] db version v3.4.7
2017-08-17T05:08:20.654+0000 I CONTROL  [initandlisten] git version: cf38c1b8a0a8dca4a11737581beafef4fe120bcd
2017-08-17T05:08:20.654+0000 I CONTROL  [initandlisten] OpenSSL version: OpenSSL 1.0.1t  3 May 2016
2017-08-17T05:08:20.654+0000 I CONTROL  [initandlisten] allocator: tcmalloc
2017-08-17T05:08:20.654+0000 I CONTROL  [initandlisten] modules: none
2017-08-17T05:08:20.654+0000 I CONTROL  [initandlisten] build environment:
2017-08-17T05:08:20.654+0000 I CONTROL  [initandlisten]     distmod: debian81
2017-08-17T05:08:20.654+0000 I CONTROL  [initandlisten]     distarch: x86_64
2017-08-17T05:08:20.654+0000 I CONTROL  [initandlisten]     target_arch: x86_64
2017-08-17T05:08:20.654+0000 I CONTROL  [initandlisten] options: { replication: { replSet: "rs0" }, storage: { engine: "wiredTiger", mmapv1: { preallocDataFiles: false, smallFiles: true }, wiredTiger: { engineConfig: { cacheSizeGB: 0.5 } } }, systemLog: { verbosity: 6 } }
2017-08-17T05:08:20.657+0000 D NETWORK  [initandlisten] fd limit hard:65536 soft:65536 max conn: 52428
2017-08-17T05:08:20.699+0000 I STORAGE  [initandlisten] wiredtiger_open config: create,cache_size=512M,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),checkpoint=(wait=60,log_size=2GB),statistics_log=(wait=0),
2017-08-17T05:08:20.700+0000 E STORAGE  [initandlisten] WiredTiger error (22) [1502946500:700558][1:0x7f8ec0c5bd00], wiredtiger_open: /data/db/WiredTiger.lock: handle-open: open: Invalid argument
2017-08-17T05:08:20.700+0000 I -        [initandlisten] Fatal Assertion 28561 at src/mongo/db/storage/wiredtiger/wiredtiger_kv_engine.cpp 266
2017-08-17T05:08:20.700+0000 I -        [initandlisten]
***aborting after fassert() failure

and the content of WiredTiger.turtle are:

WiredTiger version string
WiredTiger 2.9.2: (December 23, 2016)
WiredTiger version
major=2,minor=9,patch=2
file:WiredTiger.wt
access_pattern_hint=none,allocation_size=4KB,app_metadata=,block_allocation=best,block_compressor=,cache_resident=false,checkpoint=(WiredTigerCheckpoint.27=(addr="018081e4c9ed60ba8181e42c703ca38281e41ca436b0808080e3010fc0e23fc0",order=27,time=1502946391,size=28672,write_gen=54)),checkpoint_lsn=(1,103808),checksum=uncompressed,collator=,columns=,dictionary=0,encryption=(keyid=,name=),format=btree,huffman_key=,huffman_value=,id=0,ignore_in_memory_cache_size=false,internal_item_max=0,internal_key_max=0,internal_key_truncate=true,internal_page_max=4KB,key_format=S,key_gap=10,leaf_item_max=0,leaf_key_max=0,leaf_page_max=32KB,leaf_value_max=0,log=(enabled=true),memory_page_max=5MB,os_cache_dirty_max=0,os_cache_max=0,prefix_compression=false,prefix_compression_min=4,split_deepen_min_child=0,split_deepen_per_child=0,split_pct=90,value_format=S,version=(major=1,minor=1)



 Comments   
Comment by Henrique Barcellos [ 04/Oct/18 ]

Hello,

I have the same problem running mongo on k8s as StatefulSet with NFS PersistentVolume and I can provide the .strace file: mongod.SERVER-30709.strace

Comment by Mark Agarunov [ 07/Sep/17 ]

Hello jenningsloy318,

Thank you for the additional information. Unfortunately without the strace I can't proceed with a diagnoses of this issue. However, if adding bg,nolock,noatime to the mount options helps this issue, this is a good indicator that the underlying cause of this issue is outside of MongoDB. As we cannot diagnose or reproduce this issue, I've closed this ticket as "Cannot Reproduce" for the time being. If any additional information comes to light, please let me know and we will continue investigating this.

Thanks,
Mark

Comment by Jennings [ 22/Aug/17 ]

Hi Mark Agarunov,

since I am running mongodb in pod, it is not convinent to use strace insdie pod. but after I add "bg,nolock,noatime" to the nfs mount option, things got better. I can restart/recreate mongo via deployment/replicaset. but statefulset is still not working. I will continure to investigate it.

if you have experence in running it inside statefulset, can you share something about it?

Comment by Mark Agarunov [ 18/Aug/17 ]

Hello jenningsloy318,

Thank you for providing the additional information. As you mentioned the filesystem is over NFS, I suspect there may be a flag causing open(2) to fail. If possible, please strace the mongod process and provide the resulting file:

strace -ttt -f -o mongod.SERVER-30709.strace /usr/bin/mongod <usual startup options>

This should let us see which calls are being made with which flags, and if any are failing.

Thanks,
Mark

Comment by Jennings [ 18/Aug/17 ]

Hi @Mark Agarunov

Thanks for your reply.

I still got the same error:

 kubectl logs mongo-0 -n owl  -c mongo
note: noprealloc may hurt performance in many applications
2017-08-18T06:08:41.074+0000 I CONTROL  [initandlisten] MongoDB starting : pid=1 port=27017 dbpath=/data/db 64-bit host=mongo-0
2017-08-18T06:08:41.078+0000 I CONTROL  [initandlisten] db version v3.4.7
2017-08-18T06:08:41.078+0000 I CONTROL  [initandlisten] git version: cf38c1b8a0a8dca4a11737581beafef4fe120bcd
2017-08-18T06:08:41.078+0000 I CONTROL  [initandlisten] OpenSSL version: OpenSSL 1.0.1t  3 May 2016
2017-08-18T06:08:41.078+0000 I CONTROL  [initandlisten] allocator: tcmalloc
2017-08-18T06:08:41.078+0000 I CONTROL  [initandlisten] modules: none
2017-08-18T06:08:41.078+0000 I CONTROL  [initandlisten] build environment:
2017-08-18T06:08:41.078+0000 I CONTROL  [initandlisten]     distmod: debian81
2017-08-18T06:08:41.078+0000 I CONTROL  [initandlisten]     distarch: x86_64
2017-08-18T06:08:41.078+0000 I CONTROL  [initandlisten]     target_arch: x86_64
2017-08-18T06:08:41.078+0000 I CONTROL  [initandlisten] options: { replication: { replSet: "rs0" }, storage: { engine: "wiredTiger", mmapv1: { preallocDataFiles: false, smallFiles: true }, wiredTiger: { engineConfig: { cacheSizeGB: 0.5 } } }, systemLog: { verbosity: 6 } }
2017-08-18T06:08:41.081+0000 D NETWORK  [initandlisten] fd limit hard:65536 soft:65536 max conn: 52428
2017-08-18T06:08:41.126+0000 I STORAGE  [initandlisten] wiredtiger_open config: create,cache_size=512M,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),checkpoint=(wait=60,log_size=2GB),statistics_log=(wait=0),
2017-08-18T06:08:41.128+0000 E STORAGE  [initandlisten] WiredTiger error (22) [1503036521:128271][1:0x7ff58a281d00], wiredtiger_open: /data/db/WiredTiger.lock: handle-open: open: Invalid argument
2017-08-18T06:08:41.128+0000 I -        [initandlisten] Fatal Assertion 28561 at src/mongo/db/storage/wiredtiger/wiredtiger_kv_engine.cpp 266
2017-08-18T06:08:41.128+0000 I -        [initandlisten]
***aborting after fassert() failure

for the questions, here are my reply:

1. I am running kubernetes, and the backend storage is exported nfs volume which the backend storage a raid1 btree fs, it is HDD.

2. currently the disk is working well, since we have other applications running on these share nfs volumes.

3. Yes, we always running the same version.

4. no, I didn't modify it.

5. no restore.

6. none.

7. since this filesystem is used only for 2 months, I think it is healthy.

And I may have same situations that running mongodb in a statefulset in a kubernetes cluster, when some pods encounter some problems, and it can't restart anymoe, I enable preStop in each pod so each shutdown of the pod is clean. since the monod.lock is 0 which means the shutdown is clean. I am not sure if it is correct . I used following three methods to shtudown the mongodb in the preStop hook, not sure if other parameter needed. and what if we want to start from the the last shutdown, what is the paramter shall we use?

  • /usr/bin/mongod --shutdown
  • mongo --eval "db.getSiblingDB('admin').adminCommand( {shutdown:1,timeoutSecs:5}

    )

  • mongo --eval "db.getSiblingDB('admin').shutdownServer( {timeoutSecs:10}

    )"

Comment by Mark Agarunov [ 17/Aug/17 ]

Hello jenningsloy318,

Thank you for the report. I've attached a repair attempt of the files you've provided. Would you please extract these files and replace them in your $dbpath and let us know if it resolves the issue? If you are still seeing errors after replacing these files, please provide the complete logs from mongod so that we can further investigate. Additionally, if this issue persists, please provide the following information:

  1. What kind of underlying storage mechanism are you using? Are the storage devices attached locally or over the network? Are the disks SSDs or HDDs? What kind of RAID and/or volume management system are you using?
  2. Would you please check the integrity of your disks?
  3. Has the database always been running this version of MongoDB? If not please describe the upgrade/downgrade cycles the database has been through.
  4. Have you manipulated (copied or moved) the underlying database files? If so, was mongod running?
  5. Have you ever restored this instance from backups?
  6. What method do you use to create backups?
  7. When was the underlying filesystem last checked and is it currently marked clean?

Thanks,
Mark

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