apache / apache/incubator-pegasus

fix duplicating&learning(4/n): plog in `/learn` path of learning may be lost at start copy plog process when duplicating

Open
#764 0 comments 0 reactions 0 assignees View on GitHub
duplicating&learning type/bug
Dominant language
C++
Stars
2.1k
Forks
328
PR merge metrics
No merged PRs in 30d

Description

## Bug Report
when I fix `reset_from` bug in testing https://github.com/XiaoMi/rdsn/pull/845, I found the `learn plog` may be incomplete. the follow log show the log learned may be incomplete to start at the source(learnee node).

**Learnee:**
Learnee receve learn request and find should step back("last_max_decree(9217992) vs learn_start_decree(7255649)" in log, learn_start_decree step back to be equal with last confirmed decree for duplicating), and plog file selected is index 292("learned files count 1 (292 => 292)" in log)
```
D2021-06-11 15:40:06.539 (1623397206539476516 119869) replica.replica17.0400d3f800032c69: mutation_log.cpp:1148:get_learn_state(): gpid(265.18) get_learn_state returns false, private logs count 73 (220 => 292), learned files count 1 (292 => 292): learned_file_start_offset(8504932039) >= valid_start_offset(8504932039) && last_max_decree(9217992) > 0 && last_max_decree(9217992) < learn_start_decree(7255649)

D2021-06-11 15:40:06.539 (1623397206539545453 119869) replica.replica17.0400d3f800032c69: replica_learn.cpp:482:on_learn(): 265.18@10.132.5.5:32801: on_learn[0000006c00000002]: learner = 10.132.5.21:32801, choose to learn private logs, because learn_start_decree steps back for duplication
```
the index 292 log infomation(size=33MB):
```
mi mi 33M 6月 11 17:21 log.292.8504932039
```
context as follow, that is to say, the start decree is 9217993, but not 7255649
```
mutation: gpid=265.18, ballot=106, decree=9217993, timestamp=2021-06-11 15:39:42.084, last_committed_decree=9217992
```

**Learnee:**
Learnee receved the response and start copy remote plog file
```
D2021-06-11 15:40:06.540 (1623397206540251920 51589) replica.replica17.0405001100000283: replica_learn.cpp:601:on_learn_reply(): 265.18@10.132.5.21:32801: on_learn_reply_start=>jiashuo_debug[0000006c00000002]: learnee = 10.132.5.5:32801, learn_duration = 0 ms, response_err = ERR_OK, remote_committed_decree = 9220655, prepare_start_decree = -1, learn_type = replication::learn_type::LT_LOG, learned_buffer_size = 5828, learned_file_count = 1, to_decree_included = 9220655, learn_start_decree = 7255649[9217971], current_learning_status = replication::learner_status::LearningWithoutPrepare

D2021-06-11 15:40:06.565 (1623397206565705781 51624) replica.rep_long2.0405001100000285: replica_learn.cpp:1065:on_copy_remote_state_completed(): 265.18@10.132.5.21:32801: on_copy_remote_state_completed[0000006c00000002]: learnee = 10.132.5.5:32801, learn_duration = 26 ms, copy remote state done, err = ERR_OK, copy_file_count = 1, copy_file_size = 3501690, copy_time_used = 20 ms, local_committed_decree = 9217971, app_committed_decree = 9217971, app_durable_decree = 9217971, prepare_start_decree = -1, current_learning_status = replication::learner_status::LearningWithoutPrepare
```
the file size info is(file size only has 3.4MB(same with result of log, that is "copy_file_size = 3501690")):
```
mi mi 3.4M 6月 11 15:51 log.292.8504932039
```
file context is:
```
mutation: gpid=265.18, ballot=106, decree=9217993, timestamp=2021-06-11 15:39:42.084, last_committed_decree=9217992
```

**That is to say**
* the plog selected whic need learned start decree is not equal or less `true start_decree of duplicating`
* learnee's log send remote, but learner receved file size is not equal with origin file

so when replay the log, it will core dump for mutaion loss:
```
E2021-06-11 15:40:06.588 (1623397206588520392 51624) replica.rep_long2.0405001100000285: replica_learn.cpp:1617:apply_learned_state_from_private_log(): [265.18@10.132.5.21:32801] repaly_before=>jiashuo_debug: step back=true, last_commit_decree=9217971, dup=true
D2021-06-11 15:40:06.588 (1623397206588854941 51624) replica.rep_long2.0405001100000285: mutation_log_replay.cpp:36:replay(): start to replay mutation log /home/work/ssd10/pegasus/c4tst-tune/replica/reps/265.18.pegasus/plog/log.292.8504932039, offset = [8504932039, 8508433729), size = 3501690
F2021-06-11 15:40:06.589 (1623397206589160526 51624) replica.rep_long2.0405001100000285: prepare_list.cpp:155:commit(): assertion expression: mu != nullptr && mu->is_logged()
F2021-06-11 15:40:06.589 (1623397206589180244 51624) replica.rep_long2.0405001100000285: prepare_list.cpp:155:commit(): [265.18@10.132.5.21:32801] mutation 9217972 is missing in prepare list
```

I don't know this bug whether caused only by learn or cause by duplicating, mark it and test later

### Vresion
https://github.com/apache/incubator-pegasus/tree/v2.2.0-RC0

Contributor guide

Open the contributing guide

Research direction

Start by examining the reported flow in mutation_log.cpp and replica_learn.cpp, using the provided learner and learnee logs from v2.2.0-RC0. Then trace replay through mutation_log_replay.cpp and the assertion in prepare_list.cpp, and reproduce the duplication or learning case if possible. Done means the copied plog contains the required mutations and replay no longer reports mutation 9217972 as missing.

Written by the indexing model from the issue text.

Assessment

Tech stack
cpp
Domain
databases, distributed-systems
Issue type
Bug
Difficulty
5/5
Estimated time
Over a week
Activity status
Stale
Clarity
Needs clarification
Newbie friendliness
25/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.