Data written from Qemu disappears, NO_OBJECT_FOUND occured.
Affects | Status | Importance | Assigned to | Milestone | |
---|---|---|---|---|---|
sheepdog |
In Progress
|
Critical
|
Unassigned |
Bug Description
High load writing it went from Qemu.
Data object file has been deleted unintentionally.
Occurred only if vdi not pre-allocated.
If this is the problem, because data corruption occurs in the IO request from Qemu.
It shows excerpt log of when the problem occurred.
May 14 17:08:42 DEBUG [main] queue_request(486) CREATE_
May 14 17:08:42 DEBUG [io 22310] do_process_
May 14 17:08:42 DEBUG [main] queue_request(486) CREATE_
May 14 17:08:42 DEBUG [io 22311] do_process_
May 14 17:08:42 DEBUG [main] queue_request(486) WRITE_OBJ, 1
May 14 17:08:42 DEBUG [gway 22972] do_process_
May 14 17:08:42 DEBUG [main] queue_request(486) READ_OBJ, 1
May 14 17:08:42 DEBUG [gway 22986] do_process_
May 14 17:08:42 DEBUG [main] queue_request(486) WRITE_OBJ, 1
May 14 17:08:42 DEBUG [gway 22987] do_process_
May 14 17:08:42 DEBUG [main] queue_request(486) READ_OBJ, 1
May 14 17:08:42 DEBUG [gway 22978] do_process_
May 14 17:08:42 DEBUG [main] queue_request(486) READ_OBJ, 1
May 14 17:08:42 DEBUG [gway 22977] do_process_
May 14 17:08:42 DEBUG [main] queue_request(486) WRITE_OBJ, 1
May 14 17:08:42 DEBUG [gway 22970] do_process_
May 14 17:08:42 DEBUG [main] gateway_op_done(99) a number of ongoing inode update request: 1
May 14 17:08:42 DEBUG [main] queue_request(486) READ_OBJ, 1
May 14 17:08:42 DEBUG [gway 22982] do_process_
May 14 17:08:42 DEBUG [main] queue_request(486) WRITE_OBJ, 1
May 14 17:08:42 DEBUG [gway 22274] do_process_
May 14 17:08:42 DEBUG [gway 22972] sd_dec_
May 14 17:08:42 DEBUG [main] queue_request(486) REMOVE_OBJ, 1
May 14 17:08:42 DEBUG [gway 22973] do_process_
look at the sheep.log, REMOVE_OBJ is sent after writing the object.
analysis of update data_vdi_id requests.
new_vid - updated data_vdi_id value sent to the sheep from qemu.
old_vid - previous data_vdi_id value read from inode object in sheep.
idx | data_vdi_id req:1 | data_vdi_id req:2
----+-
| old_vid | new_vid | old_vid | new_vid
... | | | |
11 | 0 | 6de4c4 | |
12 | 0 | 6de4c4 | 6de4c4 | 6de4c4
13 | 0 | 0 | 0 | 0
14 | 0 | 6de4c4 | 6de4c4 | 6de4c4
15 | 0 | 6de4c4 | 6de4c4 | 6de4c4
16 | 0 | 6de4c4 | 6de4c4 | 6de4c4
17 | 0 | 0 | 0 | 0
18 | 0 | 6de4c4 | 6de4c4 | 6de4c4
19 | 0 | 6de4c4 | 6de4c4 | 6de4c4
1a | 0 | 6de4c4 | 6de4c4 | 6de4c4
1b | 0 | 0 | 0 | 0
1c | 0 | 6de4c4 | 6de4c4 | 6de4c4
1d | 0 | 6de4c4 | 6de4c4 | 6de4c4
1e | 0 | 6de4c4 | 6de4c4 | 0 <= back to zero at req:2
1f | | | 0 | 0
20 | | | 0 | 6de4c4
...
In the case to be removed, it is further updated by 0 after updating data_vdi_id the idx in vid.
so the object is judged unnecessary in sd_dec_
It has added a temporary debug log as 'ADD'.
May 14 17:08:42 DEBUG [gway 22984] do_process_
May 14 17:08:42 DEBUG [gway 22970] do_process_
May 14 17:08:42 DEBUG [io 22310] do_process_
May 14 17:08:42 DEBUG [io 22311] do_process_
May 14 17:08:42 DEBUG [gway 22969] do_process_
May 14 17:08:42 DEBUG [gway 22987] do_process_
May 14 17:08:42 DEBUG [gway 22971] do_process_
May 14 17:08:42 DEBUG [gway 22274] do_process_
May 14 17:08:42 DEBUG [io 22267] do_process_
May 14 17:08:42 DEBUG [gway 22631] do_process_
May 14 17:08:42 DEBUG [gway 22978] do_process_
May 14 17:08:42 DEBUG [gway 22977] do_process_
May 14 17:08:42 DEBUG [gway 22981] do_process_
May 14 17:08:42 DEBUG [gway 22284] do_process_
May 14 17:08:42 DEBUG [gway 22976] do_process_
May 14 17:08:42 DEBUG [io 22310] do_process_
May 14 17:08:42 DEBUG [gway 22975] do_process_
May 14 17:08:42 DEBUG [gway 22982] do_process_
May 14 17:08:42 DEBUG [gway 22974] do_process_
May 14 17:08:42 DEBUG [gway 22980] do_process_
May 14 17:08:42 DEBUG [gway 22979] do_process_
May 14 17:08:42 DEBUG [gway 22988] do_process_
May 14 17:08:42 DEBUG [gway 22985] do_process_
May 14 17:08:42 DEBUG [gway 22973] do_process_
May 14 17:08:42 DEBUG [io 22311] do_process_
May 14 17:08:42 DEBUG [gway 22968] do_process_
May 14 17:08:42 DEBUG [gway 22983] do_process_
May 14 17:08:42 DEBUG [io 22267] do_process_
May 14 17:08:42 DEBUG [io 22310] do_process_
May 14 17:08:42 DEBUG [io 22311] do_process_
May 14 17:08:42 DEBUG [gway 22972] do_process_
May 14 17:08:42 DEBUG [gway 22986] do_process_
May 14 17:08:42 DEBUG [gway 22987] do_process_
May 14 17:08:42 DEBUG [gway 22978] do_process_
May 14 17:08:42 DEBUG [gway 22977] do_process_
May 14 17:08:42 DEBUG [gway 22987] update_
May 14 17:08:42 DEBUG [gway 22987] update_
May 14 17:08:42 DEBUG [gway 22987] update_
May 14 17:08:42 DEBUG [gway 22987] update_
May 14 17:08:42 DEBUG [gway 22987] update_
May 14 17:08:42 DEBUG [gway 22987] update_
May 14 17:08:42 DEBUG [gway 22987] update_
May 14 17:08:42 DEBUG [gway 22987] update_
May 14 17:08:42 DEBUG [gway 22987] update_
May 14 17:08:42 DEBUG [gway 22987] update_
May 14 17:08:42 DEBUG [gway 22987] update_
May 14 17:08:42 DEBUG [gway 22987] update_
May 14 17:08:42 DEBUG [gway 22987] update_
May 14 17:08:42 DEBUG [gway 22987] update_
May 14 17:08:42 DEBUG [gway 22987] update_
May 14 17:08:42 DEBUG [gway 22970] do_process_
May 14 17:08:42 DEBUG [gway 22982] do_process_
May 14 17:08:42 DEBUG [gway 22274] do_process_
May 14 17:08:42 DEBUG [gway 22972] update_
May 14 17:08:42 DEBUG [gway 22972] update_
May 14 17:08:42 DEBUG [gway 22972] update_
May 14 17:08:42 DEBUG [gway 22972] update_
May 14 17:08:42 DEBUG [gway 22972] update_
May 14 17:08:42 DEBUG [gway 22972] update_
May 14 17:08:42 DEBUG [gway 22972] update_
May 14 17:08:42 DEBUG [gway 22972] update_
May 14 17:08:42 DEBUG [gway 22972] update_
May 14 17:08:42 DEBUG [gway 22972] update_
May 14 17:08:42 DEBUG [gway 22972] update_
May 14 17:08:42 DEBUG [gway 22972] update_
May 14 17:08:42 DEBUG [gway 22972] update_
May 14 17:08:42 DEBUG [gway 22972] update_
May 14 17:08:42 DEBUG [gway 22973] do_process_
May 14 17:08:42 DEBUG [gway 22972] update_
May 14 17:08:42 DEBUG [gway 22972] update_
Changed in sheepdog-project: | |
status: | New → In Progress |
importance: | Undecided → Critical |
I think we can update this bug, because patch sended to qemu list.