Louis.Kim 의 제 3막

기존 Mongodb Upgrade 와 비슷한 문서이나, Replica set 에서 Archive 목적으로 StandAlone 으로 변경 후 Upgrade 진행 중 발생한 이슈에 대한 문서 입니다.

Replica Set using rpm upgrade (3.4 to 4.2)

• mongod.conf 에서 replica set 제거
• 해당 상태에서 stand alone 형태로 startup 진행
• Version Upgrade 진행

Repo 추가 및 설정

• 하나의 yum Repository 로도 가능하나, 별도의 repository 추가하여 진행 하였습니다. (별다른 이유는 없습니다.)
• 여기 까지는 위의 문서와 동일

cp /etc/yum.repos.d/mongodb-org-3.4.repo /etc/yum.repos.d/mongodb-org-3.6.repo 
$ cp /etc/yum.repos.d/mongodb-org-3.4.repo /etc/yum.repos.d/mongodb-org-4.0.repo 
$ cp /etc/yum.repos.d/mongodb-org-3.4.repo /etc/yum.repos.d/mongodb-org-4.2.repo
# 3.6 추가
$ vi /etc/yum.repos.d/mongodb-org-3.6.repo 

[mongodb-org-3.6] 
name=MongoDB Repository 
baseurl=https://repo.mongodb.org/yum/amazon/2/mongodb-org/3.6/x86_64/ 
gpgcheck=1 
enabled=1 
gpgkey=https://www.mongodb.org/static/pgp/server-3.6.asc

# 4.0 추가
$ vi /etc/yum.repos.d/mongodb-org-4.0.repo 

[mongodb-org-4.0] 
name=MongoDB Repository 
baseurl=https://repo.mongodb.org/yum/amazon/2/mongodb-org/4.0/x86_64/ 
gpgcheck=1 
enabled=1 
gpgkey=https://www.mongodb.org/static/pgp/server-4.0.asc

# 4.2 추가
$ vi /etc/yum.repos.d/mongodb-org-4.2.repo 

[mongodb-org-4.2] 
name=MongoDB Repository 
baseurl=https://repo.mongodb.org/yum/amazon/2/mongodb-org/4.2/x86_64/ 
gpgcheck=1 
enabled=1 
gpgkey=https://www.mongodb.org/static/pgp/server-4.2.asc

# yum 초기화 진행
$ yum clean all 
$ yum update list

MongoDB Replica Set to Standalone 

• 단순히 conf 파일에서 replication 관련 항목을 주석 후 진행 (<- 원인)

$ vi /etc/mongod.conf 
# 아래 replication 내역 주석 처리
...
#replication:
#   replSetName: "replSet"
...

$ systemctl stop mongod.service

MongoDB 3.4 to 4.2 Upgrade 진행

• 해당 문서를 보면서 upgrade 를 진행 한다면 4.0 까지만 upgrade 진행 후 아래 모든 내용의 글을 읽으신 후에 4.2 로 진행 하시기 바랍니다.!!!!!

############ 3.6 ############
# mongo 서버 종료
$ systemctl stop mongod.service

# yum 으로 update 진행
$ yum -y update mongodb-org-3.6.23

# mongodb 서버 시작
$ systemctl start mongod.service

# mongodb 접속 후 확인
$ mongo admin -uadmin -p

# 현재값 확인
> db.adminCommand( { getParameter: 1, featureCompatibilityVersion: 1 } )

# 중요!!!# featureCompatibilityVersion 수정
> db.adminCommand( { setFeatureCompatibilityVersion: "3.6" } )

# 정상적으로 변경되었는지 확인
> db.adminCommand( { getParameter: 1, featureCompatibilityVersion: 1 } )

############ 4.0 ############
# mongo 서버 종료
$ systemctl stop mongod.service

# yum 으로 update 진행
$ yum -y update mongodb-org-4.0.27

# mongodb 서버 시작
$ systemctl start mongod.service

# mongodb 접속 후 확인
$ mongo admin -uadmin -p

# 현재값 확인
> db.adminCommand( { getParameter: 1, featureCompatibilityVersion: 1 } )

# 중요!!!# featureCompatibilityVersion 수정
> db.adminCommand( { setFeatureCompatibilityVersion: "4.0" } )

# 정상적으로 변경되었는지 확인
> db.adminCommand( { getParameter: 1, featureCompatibilityVersion: 1 } )

############ 4.2 ############
# mongo 서버 종료
$ systemctl stop mongod.service

# yum 으로 update 진행
$ yum -y update mongodb-org-4.2.18

# mongodb 서버 시작
$ systemctl start mongod.service
############################### 에러 발생하면서 startup 이 안되는 이슈 발생

발생 이슈

• 전제 : 기존 Replica Set에서 StandAlone 형태로 변경 후 버전 업그레이드 진행
  • cf) Replica set 에서 업그레이드 진행시 다음과 같은 문제는 발생하지 않음
• 문제 : 4.0 에서 4.2로 업그레이드 진행 후 startup 진행 시 startup 이 되지 않는 이슈
• 에러 내역 (로그)
  • 주요 에러 내역
    • shutting down with code:100
    • exception in initAndListen: Location40415: BSON field 'MinValidDocument.oplogDeleteFromPoint' is an unknown field., terminating

$ systemctl start mongod.service
-> error 발생하면서 startup 이 되지 않음

mongod.log

2022-07-01T17:02:59.368+0900 I  CONTROL  [main] ***** SERVER RESTARTED *****
2022-07-01T17:02:59.370+0900 I  CONTROL  [main] Automatically disabling TLS 1.0, to force-enable TLS 1.0 specify --sslDisabledProtocols 'none'
2022-07-01T17:02:59.373+0900 W  ASIO     [main] No TransportLayer configured during NetworkInterface startup
2022-07-01T17:02:59.373+0900 I  CONTROL  [initandlisten] MongoDB starting : pid=36325 port=27017 dbpath=/data/mongo/repl_0 64-bit host=192.168.0.1
2022-07-01T17:02:59.373+0900 I  CONTROL  [initandlisten] db version v4.2.21
2022-07-01T17:02:59.373+0900 I  CONTROL  [initandlisten] git version: b0aeed9445ff41af57e1f231bce990b3
2022-07-01T17:02:59.373+0900 I  CONTROL  [initandlisten] OpenSSL version: OpenSSL 1.0.2k-fips  26 Jan 2017
2022-07-01T17:02:59.373+0900 I  CONTROL  [initandlisten] allocator: tcmalloc
2022-07-01T17:02:59.373+0900 I  CONTROL  [initandlisten] modules: none
2022-07-01T17:02:59.373+0900 I  CONTROL  [initandlisten] build environment:
2022-07-01T17:02:59.373+0900 I  CONTROL  [initandlisten]     distmod: amazon2
2022-07-01T17:02:59.373+0900 I  CONTROL  [initandlisten]     distarch: x86_64
2022-07-01T17:02:59.373+0900 I  CONTROL  [initandlisten]     target_arch: x86_64
2022-07-01T17:02:59.373+0900 I  CONTROL  [initandlisten] options: { config: "/etc/mongod.conf", net: { bindIp: "0.0.0.0", port: 27017 }, processManagement: { fork: true, pidFilePath: "/var/run/mongodb/mongod.pid" }, security: { authorization: "enabled" }, storage: { dbPath: "/data/mongo/repl_0", journal: { enabled: true } }, systemLog: { destination: "file", logAppend: true, path: "/var/log/mongodb/mongod.log", quiet: true } }
2022-07-01T17:02:59.373+0900 I  STORAGE  [initandlisten] Detected data files in /data/mongo/repl_0 created by the 'wiredTiger' storage engine, so setting the active storage engine to 'wiredTiger'.
2022-07-01T17:02:59.373+0900 I  STORAGE  [initandlisten] wiredtiger_open config: create,cache_size=7360M,cache_overflow=(file_max=0M),session_max=33000,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,close_scan_interval=10,close_handle_minimum=250),statistics_log=(wait=0),verbose=[recovery_progress,checkpoint_progress],
2022-07-01T17:02:59.914+0900 I  STORAGE  [initandlisten] WiredTiger message [1656662579:914502][36325:0x7ff6d143a080], txn-recover: Recovering log 71644 through 71645
2022-07-01T17:02:59.985+0900 I  STORAGE  [initandlisten] WiredTiger message [1656662579:985670][36325:0x7ff6d143a080], txn-recover: Recovering log 71645 through 71645
...
2022-07-01T17:03:00.247+0900 I  STORAGE  [initandlisten] WiredTiger message [1656662580:247926][36325:0x7ff6d143a080], txn-recover: Set global recovery timestamp: (0, 0)
2022-07-01T17:03:00.258+0900 I  RECOVERY [initandlisten] WiredTiger recoveryTimestamp. Ts: Timestamp(0, 0)
2022-07-01T17:03:00.260+0900 I  STORAGE  [initandlisten] No table logging settings modifications are required for existing WiredTiger tables. Logging enabled? 1
2022-07-01T17:03:00.267+0900 I  STORAGE  [initandlisten] Starting OplogTruncaterThread local.oplog.rs
2022-07-01T17:03:00.267+0900 I  STORAGE  [initandlisten] The size storer reports that the oplog contains 44774827 records totaling to 53269933556 bytes
2022-07-01T17:03:00.267+0900 I  STORAGE  [initandlisten] Sampling the oplog to determine where to place markers for truncation
2022-07-01T17:03:00.269+0900 I  STORAGE  [initandlisten] Sampling from the oplog between Jun 12 09:53:56:57 and Jun 30 10:45:36:1 to determine where to place markers for truncation
2022-07-01T17:03:00.269+0900 I  STORAGE  [initandlisten] Taking 992 samples and assuming that each section of oplog contains approximately 451255 records totaling to 536871395 bytes
2022-07-01T17:03:00.743+0900 I  STORAGE  [initandlisten] Placing a marker at optime Jun 12 13:10:49:4
2022-07-01T17:03:00.743+0900 I  STORAGE  [initandlisten] Placing a marker at optime Jun 12 17:58:42:4
....
2022-07-01T17:03:00.743+0900 I  STORAGE  [initandlisten] Placing a marker at optime Jun 30 08:04:48:175
2022-07-01T17:03:00.743+0900 I  STORAGE  [initandlisten] WiredTiger record store oplog processing took 475ms
2022-07-01T17:03:00.744+0900 I  STORAGE  [initandlisten] Timestamp monitor starting
2022-07-01T17:03:00.771+0900 I  STORAGE  [initandlisten] exception in initAndListen: Location40415: BSON field 'MinValidDocument.oplogDeleteFromPoint' is an unknown field., terminating
2022-07-01T17:03:00.771+0900 I  REPL     [initandlisten] Stepping down the ReplicationCoordinator for shutdown, waitTime: 10000ms
2022-07-01T17:03:00.771+0900 I  SHARDING [initandlisten] Shutting down the WaitForMajorityService
2022-07-01T17:03:00.771+0900 I  NETWORK  [initandlisten] shutdown: going to close listening sockets...
2022-07-01T17:03:00.771+0900 I  NETWORK  [initandlisten] Shutting down the global connection pool
2022-07-01T17:03:00.771+0900 I  STORAGE  [initandlisten] Shutting down the FlowControlTicketholder
2022-07-01T17:03:00.771+0900 I  -        [initandlisten] Stopping further Flow Control ticket acquisitions.
2022-07-01T17:03:00.771+0900 I  STORAGE  [initandlisten] Shutting down the PeriodicThreadToAbortExpiredTransactions
2022-07-01T17:03:00.771+0900 I  STORAGE  [initandlisten] Shutting down the PeriodicThreadToDecreaseSnapshotHistoryIfNotNeeded
2022-07-01T17:03:00.771+0900 I  REPL     [initandlisten] Shutting down the ReplicationCoordinator
2022-07-01T17:03:00.771+0900 I  SHARDING [initandlisten] Shutting down the ShardingInitializationMongoD
2022-07-01T17:03:00.771+0900 I  REPL     [initandlisten] Enqueuing the ReplicationStateTransitionLock for shutdown
2022-07-01T17:03:00.771+0900 I  -        [initandlisten] Killing all operations for shutdown
...
2022-07-01T17:03:01.196+0900 I  STORAGE  [initandlisten] WiredTiger message [1656662581:196670][36325:0x7ff6d143a080], txn-recover: Set global recovery timestamp: (0, 0)
2022-07-01T17:03:01.335+0900 I  STORAGE  [initandlisten] shutdown: removing fs lock...
2022-07-01T17:03:01.335+0900 I  -        [initandlisten] Dropping the scope cache for shutdown
2022-07-01T17:03:01.335+0900 I  CONTROL  [initandlisten] now exiting
2022-07-01T17:03:01.335+0900 I  CONTROL  [initandlisten] shutting down with code:100

해결 방안

• 4.0 Downgrade 진행 및 local DB의 replset.minvalid 컬렉션의 oplogDeleteFromPoint 필드 unset 진행

# 4.0 Downgrade 진행
$ yum -y downgrade mongodb-org-4.0.27

# mongodb startup 진행
$ systemctl start mongod.service

# mongodb 접속 후 확인
$ mongo admin -uadmin -p

# local 에서 replset.minvalid Collection 의 oplogDeleteFromPoint 필드 $unset 진행
> use local
switched to db local

> db.replset.minvalid.find({}).pretty ();
{
        "_id" : ObjectId("5ec3b7c56db7b066b3f5d5e3"),
        "ts" : Timestamp(1643225280, 1),
        "t" : NumberLong(7),
        "oplogDeleteFromPoint" : Timestamp(0, 0)
}

# update 진행 검색 조건은 _id 결과로 $unset 진행
> db.replset.minvalid.update(
...  { "_id" : ObjectId("5ec3b7c56db7b066b3f5d5e3")},
...    { $unset: { oplogDeleteFromPoint: ""} }
... );
WriteResult({ "nMatched" : 1, "nUpserted" : 0, "nModified" : 1 })

# 해당 필드 값 확인
> db.replset.minvalid.find({}).pretty ();
{
        "_id" : ObjectId("5ec3b7c56db7b066b3f5d5e3"),
        "ts" : Timestamp(1643225280, 1),
        "t" : NumberLong(7)
}
> exit

# 이후 다시 mongodb 4.2 upgrade 진행
# mongo 서버 종료
$systemctl stop mongod.service

# yum 으로 update 진행
yum -y update mongodb-org-4.2.18

# mongodb 서버 시작
$ systemctl start mongod.service

# mongodb 접속 후 확인
$ mongo admin -uadmin -p

# 현재값 확인
> db.adminCommand( { getParameter: 1, featureCompatibilityVersion: 1 } )

# 중요!!!# featureCompatibilityVersion 수정
> db.adminCommand( { setFeatureCompatibilityVersion: "4.2" } )

# 정상적으로 변경되었는지 확인
> db.adminCommand( { getParameter: 1, featureCompatibilityVersion: 1 } )

발생 원인

• Replica set 을 정상적으로 삭제 하지 않고 단순 config 파일에서 수정 후 진행하다가 발생한 이유
• mongodb 4.2에서 MinValidDocument.oplogDeleteFromPoint dependency (예상)

발생 방지 방법

• MongoDB Replica set 에서 StandAlone 으로 변경 시 정상적인 방법으로 진행

# 1. 모든 Secondary 삭제 진행
repl_set:PRIMARY> rs.remove("Secondary 호스트 이름:27017")
repl_set:PRIMARY> rs.remove("Arbiter 호스트 이름:27018")

# 2. config 파일에서 replication 주석 처리 또는 제거
$ vi /etc/mongod.conf
...
#replication:
#   replSetName: "replSet"
...

# 3. mongodb 재시작(Primary)
$ systemctl restart mongod.service

# 4. local database 삭제
# mongodb 접속 시 현재 standalone 상태
> use local
> db.dropDatabase()

# 5. mongodb 깔끔하게 확인차 재시작(Primary)
$ systemctl restart mongod.service

결론

• Replica Set의 동작 방식 뿐만 아니라 각 DB(Local, admin 등)들의 역할에 대해서 다시 한번 공부가 필요
• MongoDB에 대한 공부 공부 공부!!!

해당 문제를 해결하는 과정에 많은 도움을 주신 TechPM 박경배 팀장님에게 감사 인사 드립니다.