Project

General

Profile

Bug #49876

[luks] sporadic failure in TestLibRBD.TestEncryptionLUKS2

Added by Jason Dillaman about 3 years ago. Updated over 2 years ago.

Status:
Resolved
Priority:
Normal
Assignee:
-
Target version:
-
% Done:

0%

Source:
Tags:
Backport:
pacific
Regression:
No
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
Pull request ID:
Crash signature (v1):
Crash signature (v2):

Description

http://qa-proxy.ceph.com/teuthology/jdillaman-2021-03-17_18:18:23-rbd-wip-jd-testing-distro-basic-smithi/5974535/teuthology.log

[ RUN      ] TestLibRBD.TestEncryptionLUKS2
using new format!
Allocating context for crypt device /proc/1870387/fd/43.
Trying to open and read device /proc/1870387/fd/43 with direct-io.
Trying to open device /proc/1870387/fd/43 without direct-io.
Initialising device-mapper backend library.
/dev/mapper/control: open failed: Permission denied
Failure to communicate with kernel device-mapper driver.
Incompatible libdevmapper 1.02.171 (2020-03-26) and kernel driver (unknown version).
wrote: 512
wrote: 512
wrote: 512
wrote: 512
wrote: 512
created completion
started write
write completion cb called!
return value is: 0
finished write
created completion
started write
write completion cb called!
return value is: 0
finished write
created completion
started write
write completion cb called!
return value is: 0
finished write
created completion
started write
write completion cb called!
return value is: 0
finished write
created completion
started write
write completion cb called!
return value is: 0
finished write
start compare and write
compare and  wrote: 512
start compare and write
compare and  wrote: 512
start compare and write
compare and  wrote: 512
start compare and write
compare and  wrote: 512
start compare and write
compare and  wrote: 512
created completion
started aio compare and write
write completion cb called!
return value is: 0
finished aio compare and write
created completion
started aio compare and write
write completion cb called!
return value is: 0
finished aio compare and write
created completion
started aio compare and write
write completion cb called!
return value is: 0
finished aio compare and write
created completion
started aio compare and write
write completion cb called!
return value is: 0
finished aio compare and write
created completion
started aio compare and write
write completion cb called!
return value is: 0
finished aio compare and write
read: 512
read: 512
read: 512
read: 512
read: 512
created completion
started read
read completion cb called!
return value is: 512
created completion
started read
read completion cb called!
return value is: 512
created completion
started read
read completion cb called!
return value is: 512
created completion
started read
read completion cb called!
return value is: 512
created completion
started read
read completion cb called!
return value is: 512
discard: 512~512 = 512
write completion cb called!
aio discard: 1536~512 = 0
read: 512
read: 512
read: 512
read: 512
read: 512
wrote: 0
to verify the data
verified
wrote: 0
to verify the data
verified
wrote: 16384
to verify the data
verified
wrote: 16384
to verify the data
verified
expected fail, finished writesame
expected fail, finished writesame
wrote: 49152
to verify the data
verified
wrote: 49152
to verify the data
verified
wrote: 65536
to verify the data
verified
wrote: 65536
to verify the data
verified
expected fail, finished writesame
expected fail, finished writesame
wrote: 98304
to verify the data
verified
wrote: 98304
to verify the data
verified
wrote: 114688
to verify the data
verified
wrote: 114688
to verify the data
verified
expected fail, finished writesame
expected fail, finished writesame
wrote: 147456
to verify the data
verified
wrote: 147456
to verify the data
verified
wrote: 163840
to verify the data
verified
wrote: 163840
to verify the data
verified
expected fail, finished writesame
expected fail, finished writesame
wrote: 196608
to verify the data
verified
wrote: 196608
to verify the data
verified
wrote: 212992
to verify the data
verified
wrote: 212992
to verify the data
verified
expected fail, finished writesame
expected fail, finished writesame
created completion
started writesame
write completion cb called!
return value is: 0
finished writesame
to verify the data
verified
created completion
started writesame
write completion cb called!
return value is: 0
finished writesame
to verify the data
verified
created completion
started writesame
write completion cb called!
return value is: 0
finished writesame
to verify the data
verified
created completion
started writesame
write completion cb called!
return value is: 0
finished writesame
to verify the data
verified
created completion
started writesame
expected fail, finished writesame
created completion
started writesame
expected fail, finished writesame
created completion
started writesame
write completion cb called!
return value is: 0
finished writesame
to verify the data
verified
created completion
started writesame
write completion cb called!
return value is: 0
finished writesame
to verify the data
verified
created completion
started writesame
write completion cb called!
return value is: 0
finished writesame
to verify the data
verified
created completion
started writesame
write completion cb called!
return value is: 0
finished writesame
to verify the data
verified
created completion
started writesame
expected fail, finished writesame
created completion
started writesame
expected fail, finished writesame
created completion
started writesame
write completion cb called!
return value is: 0
finished writesame
to verify the data
verified
created completion
started writesame
write completion cb called!
return value is: 0
finished writesame
to verify the data
verified
created completion
started writesame
write completion cb called!
return value is: 0
finished writesame
to verify the data
verified
created completion
started writesame
write completion cb called!
return value is: 0
finished writesame
to verify the data
verified
created completion
started writesame
expected fail, finished writesame
created completion
started writesame
expected fail, finished writesame
created completion
started writesame
write completion cb called!
return value is: 0
finished writesame
to verify the data
verified
created completion
started writesame
write completion cb called!
return value is: 0
finished writesame
to verify the data
verified
created completion
started writesame
write completion cb called!
return value is: 0
finished writesame
to verify the data
verified
created completion
started writesame
write completion cb called!
return value is: 0
finished writesame
to verify the data
verified
created completion
started writesame
expected fail, finished writesame
created completion
started writesame
expected fail, finished writesame
created completion
started writesame
write completion cb called!
return value is: 0
finished writesame
to verify the data
verified
created completion
started writesame
write completion cb called!
return value is: 0
finished writesame
to verify the data
verified
created completion
started writesame
write completion cb called!
return value is: 0
finished writesame
to verify the data
verified
created completion
started writesame
write completion cb called!
return value is: 0
finished writesame
to verify the data
verified
created completion
started writesame
expected fail, finished writesame
created completion
started writesame
expected fail, finished writesame
read completion cb called!
read completion cb called!
wrote: 512
read completion cb called!
wrote: 4
Allocating context for crypt device /proc/1870387/fd/43.
Trying to open and read device /proc/1870387/fd/43 with direct-io.
Trying to open device /proc/1870387/fd/43 without direct-io.
Initialising device-mapper backend library.
read: 4
read: 
expected: test
../src/test/librbd/test_librbd.cc:364: Failure
Expected equality of these values:
  0
  memcmp(result, expected, len)
    Which is: -1
[  FAILED  ] TestLibRBD.TestEncryptionLUKS2 (16843 ms)
[----------] 1 test from TestLibRBD (16843 ms total)

[----------] Global test environment tear-down
[==========] 1 test from 1 test suite ran. (17897 ms total)
[  PASSED  ] 0 tests.
[  FAILED  ] 1 test, listed below:
[  FAILED  ] TestLibRBD.TestEncryptionLUKS2

client.admin.1870387.log.xz (385 KB) Jason Dillaman, 03/18/2021 01:06 AM


Related issues

Related to rbd - Bug #52511: [pwl ssd] flush cause io re-oreder to writeback layer Resolved
Related to rbd - Bug #53108: [pwl] TestMigration.Stress* failure with pwl cache Duplicate

History

#1 Updated by Jason Dillaman about 3 years ago

#2 Updated by Ilya Dryomov almost 3 years ago

http://qa-proxy.ceph.com/teuthology/dis-2021-04-28_17:10:10-rbd-wip-dis-testing-distro-basic-smithi/6079915/teuthology.log

2021-04-28T17:43:13.332 INFO:tasks.workunit.client.0.smithi134.stdout:[ RUN      ] TestLibRBD.TestEncryptionLUKS2
2021-04-28T17:43:13.332 INFO:tasks.workunit.client.0.smithi134.stdout:using new format!
2021-04-28T17:43:22.482 INFO:tasks.workunit.client.0.smithi134.stdout:wrote: 512
2021-04-28T17:43:22.482 INFO:tasks.workunit.client.0.smithi134.stdout:wrote: 512
2021-04-28T17:43:22.482 INFO:tasks.workunit.client.0.smithi134.stdout:wrote: 512
2021-04-28T17:43:22.482 INFO:tasks.workunit.client.0.smithi134.stdout:wrote: 512
2021-04-28T17:43:22.482 INFO:tasks.workunit.client.0.smithi134.stdout:wrote: 512
2021-04-28T17:43:22.483 INFO:tasks.workunit.client.0.smithi134.stdout:created completion
2021-04-28T17:43:22.483 INFO:tasks.workunit.client.0.smithi134.stdout:started write
2021-04-28T17:43:22.483 INFO:tasks.workunit.client.0.smithi134.stdout:write completion cb called!
2021-04-28T17:43:22.483 INFO:tasks.workunit.client.0.smithi134.stdout:return value is: 0
2021-04-28T17:43:22.483 INFO:tasks.workunit.client.0.smithi134.stdout:finished write
2021-04-28T17:43:22.483 INFO:tasks.workunit.client.0.smithi134.stdout:created completion
2021-04-28T17:43:22.483 INFO:tasks.workunit.client.0.smithi134.stdout:started write
2021-04-28T17:43:22.483 INFO:tasks.workunit.client.0.smithi134.stdout:write completion cb called!
2021-04-28T17:43:22.483 INFO:tasks.workunit.client.0.smithi134.stdout:return value is: 0
2021-04-28T17:43:22.483 INFO:tasks.workunit.client.0.smithi134.stdout:finished write
2021-04-28T17:43:22.483 INFO:tasks.workunit.client.0.smithi134.stdout:created completion
2021-04-28T17:43:22.484 INFO:tasks.workunit.client.0.smithi134.stdout:started write
2021-04-28T17:43:22.484 INFO:tasks.workunit.client.0.smithi134.stdout:write completion cb called!
2021-04-28T17:43:22.484 INFO:tasks.workunit.client.0.smithi134.stdout:return value is: 0
2021-04-28T17:43:22.484 INFO:tasks.workunit.client.0.smithi134.stdout:finished write
2021-04-28T17:43:22.484 INFO:tasks.workunit.client.0.smithi134.stdout:created completion
2021-04-28T17:43:22.484 INFO:tasks.workunit.client.0.smithi134.stdout:started write
2021-04-28T17:43:22.484 INFO:tasks.workunit.client.0.smithi134.stdout:write completion cb called!
2021-04-28T17:43:22.484 INFO:tasks.workunit.client.0.smithi134.stdout:return value is: 0
2021-04-28T17:43:22.484 INFO:tasks.workunit.client.0.smithi134.stdout:finished write
2021-04-28T17:43:22.484 INFO:tasks.workunit.client.0.smithi134.stdout:created completion
2021-04-28T17:43:22.484 INFO:tasks.workunit.client.0.smithi134.stdout:started write
2021-04-28T17:43:22.484 INFO:tasks.workunit.client.0.smithi134.stdout:write completion cb called!
2021-04-28T17:43:22.485 INFO:tasks.workunit.client.0.smithi134.stdout:return value is: 0
2021-04-28T17:43:22.485 INFO:tasks.workunit.client.0.smithi134.stdout:finished write
2021-04-28T17:43:22.485 INFO:tasks.workunit.client.0.smithi134.stdout:start compare and write
2021-04-28T17:43:22.485 INFO:tasks.workunit.client.0.smithi134.stdout:compare and  wrote: 512
2021-04-28T17:43:22.485 INFO:tasks.workunit.client.0.smithi134.stdout:start compare and write
2021-04-28T17:43:22.485 INFO:tasks.workunit.client.0.smithi134.stdout:compare and  wrote: 512
2021-04-28T17:43:22.485 INFO:tasks.workunit.client.0.smithi134.stdout:start compare and write
2021-04-28T17:43:22.485 INFO:tasks.workunit.client.0.smithi134.stdout:compare and  wrote: 512
2021-04-28T17:43:22.485 INFO:tasks.workunit.client.0.smithi134.stdout:start compare and write
2021-04-28T17:43:22.485 INFO:tasks.workunit.client.0.smithi134.stdout:compare and  wrote: 512
2021-04-28T17:43:22.485 INFO:tasks.workunit.client.0.smithi134.stdout:start compare and write
2021-04-28T17:43:22.485 INFO:tasks.workunit.client.0.smithi134.stdout:compare and  wrote: 512
2021-04-28T17:43:22.486 INFO:tasks.workunit.client.0.smithi134.stdout:created completion
2021-04-28T17:43:22.486 INFO:tasks.workunit.client.0.smithi134.stdout:started aio compare and write
2021-04-28T17:43:22.486 INFO:tasks.workunit.client.0.smithi134.stdout:write completion cb called!
2021-04-28T17:43:22.486 INFO:tasks.workunit.client.0.smithi134.stdout:return value is: 0
2021-04-28T17:43:22.486 INFO:tasks.workunit.client.0.smithi134.stdout:finished aio compare and write
2021-04-28T17:43:22.486 INFO:tasks.workunit.client.0.smithi134.stdout:created completion
2021-04-28T17:43:22.486 INFO:tasks.workunit.client.0.smithi134.stdout:started aio compare and write
2021-04-28T17:43:22.486 INFO:tasks.workunit.client.0.smithi134.stdout:write completion cb called!
2021-04-28T17:43:22.486 INFO:tasks.workunit.client.0.smithi134.stdout:return value is: 0
2021-04-28T17:43:22.486 INFO:tasks.workunit.client.0.smithi134.stdout:finished aio compare and write
2021-04-28T17:43:22.487 INFO:tasks.workunit.client.0.smithi134.stdout:created completion
2021-04-28T17:43:22.487 INFO:tasks.workunit.client.0.smithi134.stdout:started aio compare and write
2021-04-28T17:43:22.487 INFO:tasks.workunit.client.0.smithi134.stdout:write completion cb called!
2021-04-28T17:43:22.487 INFO:tasks.workunit.client.0.smithi134.stdout:return value is: 0
2021-04-28T17:43:22.487 INFO:tasks.workunit.client.0.smithi134.stdout:finished aio compare and write
2021-04-28T17:43:22.487 INFO:tasks.workunit.client.0.smithi134.stdout:created completion
2021-04-28T17:43:22.487 INFO:tasks.workunit.client.0.smithi134.stdout:started aio compare and write
2021-04-28T17:43:22.487 INFO:tasks.workunit.client.0.smithi134.stdout:write completion cb called!
2021-04-28T17:43:22.487 INFO:tasks.workunit.client.0.smithi134.stdout:return value is: 0
2021-04-28T17:43:22.487 INFO:tasks.workunit.client.0.smithi134.stdout:finished aio compare and write
2021-04-28T17:43:22.488 INFO:tasks.workunit.client.0.smithi134.stdout:created completion
2021-04-28T17:43:22.488 INFO:tasks.workunit.client.0.smithi134.stdout:started aio compare and write
2021-04-28T17:43:22.488 INFO:tasks.workunit.client.0.smithi134.stdout:write completion cb called!
2021-04-28T17:43:22.488 INFO:tasks.workunit.client.0.smithi134.stdout:return value is: 0
2021-04-28T17:43:22.488 INFO:tasks.workunit.client.0.smithi134.stdout:finished aio compare and write
2021-04-28T17:43:22.488 INFO:tasks.workunit.client.0.smithi134.stdout:read: 512
2021-04-28T17:43:22.488 INFO:tasks.workunit.client.0.smithi134.stdout:read: 512
2021-04-28T17:43:22.488 INFO:tasks.workunit.client.0.smithi134.stdout:read: 512
2021-04-28T17:43:22.488 INFO:tasks.workunit.client.0.smithi134.stdout:read: 512
2021-04-28T17:43:22.488 INFO:tasks.workunit.client.0.smithi134.stdout:read: 512
2021-04-28T17:43:22.488 INFO:tasks.workunit.client.0.smithi134.stdout:created completion
2021-04-28T17:43:22.489 INFO:tasks.workunit.client.0.smithi134.stdout:started read
2021-04-28T17:43:22.489 INFO:tasks.workunit.client.0.smithi134.stdout:read completion cb called!
2021-04-28T17:43:22.489 INFO:tasks.workunit.client.0.smithi134.stdout:return value is: 512
2021-04-28T17:43:22.489 INFO:tasks.workunit.client.0.smithi134.stdout:created completion
2021-04-28T17:43:22.489 INFO:tasks.workunit.client.0.smithi134.stdout:started read
2021-04-28T17:43:22.489 INFO:tasks.workunit.client.0.smithi134.stdout:read completion cb called!
2021-04-28T17:43:22.489 INFO:tasks.workunit.client.0.smithi134.stdout:return value is: 512
2021-04-28T17:43:22.489 INFO:tasks.workunit.client.0.smithi134.stdout:created completion
2021-04-28T17:43:22.489 INFO:tasks.workunit.client.0.smithi134.stdout:started read
2021-04-28T17:43:22.489 INFO:tasks.workunit.client.0.smithi134.stdout:read completion cb called!
2021-04-28T17:43:22.489 INFO:tasks.workunit.client.0.smithi134.stdout:return value is: 512
2021-04-28T17:43:22.490 INFO:tasks.workunit.client.0.smithi134.stdout:created completion
2021-04-28T17:43:22.490 INFO:tasks.workunit.client.0.smithi134.stdout:started read
2021-04-28T17:43:22.491 INFO:tasks.workunit.client.0.smithi134.stdout:read completion cb called!
2021-04-28T17:43:22.491 INFO:tasks.workunit.client.0.smithi134.stdout:return value is: 512
2021-04-28T17:43:22.491 INFO:tasks.workunit.client.0.smithi134.stdout:created completion
2021-04-28T17:43:22.491 INFO:tasks.workunit.client.0.smithi134.stdout:started read
2021-04-28T17:43:22.491 INFO:tasks.workunit.client.0.smithi134.stdout:read completion cb called!
2021-04-28T17:43:22.491 INFO:tasks.workunit.client.0.smithi134.stdout:return value is: 512
2021-04-28T17:43:22.491 INFO:tasks.workunit.client.0.smithi134.stdout:discard: 512~512 = 512
2021-04-28T17:43:22.491 INFO:tasks.workunit.client.0.smithi134.stdout:write completion cb called!
2021-04-28T17:43:22.491 INFO:tasks.workunit.client.0.smithi134.stdout:aio discard: 1536~512 = 0
2021-04-28T17:43:22.491 INFO:tasks.workunit.client.0.smithi134.stdout:read: 512
2021-04-28T17:43:22.492 INFO:tasks.workunit.client.0.smithi134.stdout:read: 512
2021-04-28T17:43:22.492 INFO:tasks.workunit.client.0.smithi134.stdout:read: 512
2021-04-28T17:43:22.492 INFO:tasks.workunit.client.0.smithi134.stdout:read: 512
2021-04-28T17:43:22.492 INFO:tasks.workunit.client.0.smithi134.stdout:read: 512
2021-04-28T17:43:22.492 INFO:tasks.workunit.client.0.smithi134.stdout:wrote: 0
2021-04-28T17:43:22.492 INFO:tasks.workunit.client.0.smithi134.stdout:to verify the data
2021-04-28T17:43:22.492 INFO:tasks.workunit.client.0.smithi134.stdout:verified
2021-04-28T17:43:22.492 INFO:tasks.workunit.client.0.smithi134.stdout:wrote: 0
2021-04-28T17:43:22.492 INFO:tasks.workunit.client.0.smithi134.stdout:to verify the data
2021-04-28T17:43:22.492 INFO:tasks.workunit.client.0.smithi134.stdout:verified
2021-04-28T17:43:22.492 INFO:tasks.workunit.client.0.smithi134.stdout:wrote: 16384
2021-04-28T17:43:22.492 INFO:tasks.workunit.client.0.smithi134.stdout:to verify the data
2021-04-28T17:43:22.493 INFO:tasks.workunit.client.0.smithi134.stdout:verified
2021-04-28T17:43:22.493 INFO:tasks.workunit.client.0.smithi134.stdout:wrote: 16384
2021-04-28T17:43:22.493 INFO:tasks.workunit.client.0.smithi134.stdout:to verify the data
2021-04-28T17:43:22.493 INFO:tasks.workunit.client.0.smithi134.stdout:verified
2021-04-28T17:43:22.493 INFO:tasks.workunit.client.0.smithi134.stdout:expected fail, finished writesame
2021-04-28T17:43:22.493 INFO:tasks.workunit.client.0.smithi134.stdout:expected fail, finished writesame
2021-04-28T17:43:22.493 INFO:tasks.workunit.client.0.smithi134.stdout:wrote: 49152
2021-04-28T17:43:22.493 INFO:tasks.workunit.client.0.smithi134.stdout:to verify the data
2021-04-28T17:43:22.493 INFO:tasks.workunit.client.0.smithi134.stdout:verified
2021-04-28T17:43:22.493 INFO:tasks.workunit.client.0.smithi134.stdout:wrote: 49152
2021-04-28T17:43:22.493 INFO:tasks.workunit.client.0.smithi134.stdout:to verify the data
2021-04-28T17:43:22.494 INFO:tasks.workunit.client.0.smithi134.stdout:verified
2021-04-28T17:43:22.494 INFO:tasks.workunit.client.0.smithi134.stdout:wrote: 65536
2021-04-28T17:43:22.494 INFO:tasks.workunit.client.0.smithi134.stdout:to verify the data
2021-04-28T17:43:22.494 INFO:tasks.workunit.client.0.smithi134.stdout:verified
2021-04-28T17:43:22.494 INFO:tasks.workunit.client.0.smithi134.stdout:wrote: 65536
2021-04-28T17:43:22.494 INFO:tasks.workunit.client.0.smithi134.stdout:to verify the data
2021-04-28T17:43:22.494 INFO:tasks.workunit.client.0.smithi134.stdout:verified
2021-04-28T17:43:22.494 INFO:tasks.workunit.client.0.smithi134.stdout:expected fail, finished writesame
2021-04-28T17:43:22.494 INFO:tasks.workunit.client.0.smithi134.stdout:expected fail, finished writesame
2021-04-28T17:43:22.494 INFO:tasks.workunit.client.0.smithi134.stdout:wrote: 98304
2021-04-28T17:43:22.494 INFO:tasks.workunit.client.0.smithi134.stdout:to verify the data
2021-04-28T17:43:22.495 INFO:tasks.workunit.client.0.smithi134.stdout:verified
2021-04-28T17:43:22.495 INFO:tasks.workunit.client.0.smithi134.stdout:wrote: 98304
2021-04-28T17:43:22.495 INFO:tasks.workunit.client.0.smithi134.stdout:to verify the data
2021-04-28T17:43:22.495 INFO:tasks.workunit.client.0.smithi134.stdout:verified
2021-04-28T17:43:22.495 INFO:tasks.workunit.client.0.smithi134.stdout:wrote: 114688
2021-04-28T17:43:22.495 INFO:tasks.workunit.client.0.smithi134.stdout:to verify the data
2021-04-28T17:43:22.495 INFO:tasks.workunit.client.0.smithi134.stdout:verified
2021-04-28T17:43:22.495 INFO:tasks.workunit.client.0.smithi134.stdout:wrote: 114688
2021-04-28T17:43:22.495 INFO:tasks.workunit.client.0.smithi134.stdout:to verify the data
2021-04-28T17:43:22.496 INFO:tasks.workunit.client.0.smithi134.stdout:verified
2021-04-28T17:43:22.496 INFO:tasks.workunit.client.0.smithi134.stdout:expected fail, finished writesame
2021-04-28T17:43:22.496 INFO:tasks.workunit.client.0.smithi134.stdout:expected fail, finished writesame
2021-04-28T17:43:22.496 INFO:tasks.workunit.client.0.smithi134.stdout:wrote: 147456
2021-04-28T17:43:22.496 INFO:tasks.workunit.client.0.smithi134.stdout:to verify the data
2021-04-28T17:43:22.496 INFO:tasks.workunit.client.0.smithi134.stdout:verified
2021-04-28T17:43:22.496 INFO:tasks.workunit.client.0.smithi134.stdout:wrote: 147456
2021-04-28T17:43:22.496 INFO:tasks.workunit.client.0.smithi134.stdout:to verify the data
2021-04-28T17:43:22.496 INFO:tasks.workunit.client.0.smithi134.stdout:verified
2021-04-28T17:43:22.496 INFO:tasks.workunit.client.0.smithi134.stdout:wrote: 163840
2021-04-28T17:43:22.496 INFO:tasks.workunit.client.0.smithi134.stdout:to verify the data
2021-04-28T17:43:22.496 INFO:tasks.workunit.client.0.smithi134.stdout:verified
2021-04-28T17:43:22.497 INFO:tasks.workunit.client.0.smithi134.stdout:wrote: 163840
2021-04-28T17:43:22.497 INFO:tasks.workunit.client.0.smithi134.stdout:to verify the data
2021-04-28T17:43:22.497 INFO:tasks.workunit.client.0.smithi134.stdout:verified
2021-04-28T17:43:22.497 INFO:tasks.workunit.client.0.smithi134.stdout:expected fail, finished writesame
2021-04-28T17:43:22.497 INFO:tasks.workunit.client.0.smithi134.stdout:expected fail, finished writesame
2021-04-28T17:43:22.497 INFO:tasks.workunit.client.0.smithi134.stdout:wrote: 196608
2021-04-28T17:43:22.497 INFO:tasks.workunit.client.0.smithi134.stdout:to verify the data
2021-04-28T17:43:22.497 INFO:tasks.workunit.client.0.smithi134.stdout:verified
2021-04-28T17:43:22.497 INFO:tasks.workunit.client.0.smithi134.stdout:wrote: 196608
2021-04-28T17:43:22.497 INFO:tasks.workunit.client.0.smithi134.stdout:to verify the data
2021-04-28T17:43:22.498 INFO:tasks.workunit.client.0.smithi134.stdout:verified
2021-04-28T17:43:22.498 INFO:tasks.workunit.client.0.smithi134.stdout:wrote: 212992
2021-04-28T17:43:22.498 INFO:tasks.workunit.client.0.smithi134.stdout:to verify the data
2021-04-28T17:43:22.498 INFO:tasks.workunit.client.0.smithi134.stdout:verified
2021-04-28T17:43:22.498 INFO:tasks.workunit.client.0.smithi134.stdout:wrote: 212992
2021-04-28T17:43:22.498 INFO:tasks.workunit.client.0.smithi134.stdout:to verify the data
2021-04-28T17:43:22.498 INFO:tasks.workunit.client.0.smithi134.stdout:verified
2021-04-28T17:43:22.498 INFO:tasks.workunit.client.0.smithi134.stdout:expected fail, finished writesame
2021-04-28T17:43:22.498 INFO:tasks.workunit.client.0.smithi134.stdout:expected fail, finished writesame
2021-04-28T17:43:22.498 INFO:tasks.workunit.client.0.smithi134.stdout:created completion
2021-04-28T17:43:22.498 INFO:tasks.workunit.client.0.smithi134.stdout:started writesame
2021-04-28T17:43:22.499 INFO:tasks.workunit.client.0.smithi134.stdout:write completion cb called!
2021-04-28T17:43:22.499 INFO:tasks.workunit.client.0.smithi134.stdout:return value is: 0
2021-04-28T17:43:22.499 INFO:tasks.workunit.client.0.smithi134.stdout:finished writesame
2021-04-28T17:43:22.499 INFO:tasks.workunit.client.0.smithi134.stdout:to verify the data
2021-04-28T17:43:22.499 INFO:tasks.workunit.client.0.smithi134.stdout:verified
2021-04-28T17:43:22.499 INFO:tasks.workunit.client.0.smithi134.stdout:created completion
2021-04-28T17:43:22.499 INFO:tasks.workunit.client.0.smithi134.stdout:started writesame
2021-04-28T17:43:22.499 INFO:tasks.workunit.client.0.smithi134.stdout:write completion cb called!
2021-04-28T17:43:22.499 INFO:tasks.workunit.client.0.smithi134.stdout:return value is: 0
2021-04-28T17:43:22.499 INFO:tasks.workunit.client.0.smithi134.stdout:finished writesame
2021-04-28T17:43:22.499 INFO:tasks.workunit.client.0.smithi134.stdout:to verify the data
2021-04-28T17:43:22.500 INFO:tasks.workunit.client.0.smithi134.stdout:verified
2021-04-28T17:43:22.500 INFO:tasks.workunit.client.0.smithi134.stdout:created completion
2021-04-28T17:43:22.500 INFO:tasks.workunit.client.0.smithi134.stdout:started writesame
2021-04-28T17:43:22.500 INFO:tasks.workunit.client.0.smithi134.stdout:write completion cb called!
2021-04-28T17:43:22.500 INFO:tasks.workunit.client.0.smithi134.stdout:return value is: 0
2021-04-28T17:43:22.500 INFO:tasks.workunit.client.0.smithi134.stdout:finished writesame
2021-04-28T17:43:22.500 INFO:tasks.workunit.client.0.smithi134.stdout:to verify the data
2021-04-28T17:43:22.500 INFO:tasks.workunit.client.0.smithi134.stdout:verified
2021-04-28T17:43:22.500 INFO:tasks.workunit.client.0.smithi134.stdout:created completion
2021-04-28T17:43:22.500 INFO:tasks.workunit.client.0.smithi134.stdout:started writesame
2021-04-28T17:43:22.500 INFO:tasks.workunit.client.0.smithi134.stdout:write completion cb called!
2021-04-28T17:43:22.500 INFO:tasks.workunit.client.0.smithi134.stdout:return value is: 0
2021-04-28T17:43:22.501 INFO:tasks.workunit.client.0.smithi134.stdout:finished writesame
2021-04-28T17:43:22.501 INFO:tasks.workunit.client.0.smithi134.stdout:to verify the data
2021-04-28T17:43:22.501 INFO:tasks.workunit.client.0.smithi134.stdout:verified
2021-04-28T17:43:22.501 INFO:tasks.workunit.client.0.smithi134.stdout:created completion
2021-04-28T17:43:22.501 INFO:tasks.workunit.client.0.smithi134.stdout:started writesame
2021-04-28T17:43:22.501 INFO:tasks.workunit.client.0.smithi134.stdout:expected fail, finished writesame
2021-04-28T17:43:22.501 INFO:tasks.workunit.client.0.smithi134.stdout:created completion
2021-04-28T17:43:22.501 INFO:tasks.workunit.client.0.smithi134.stdout:started writesame
2021-04-28T17:43:22.501 INFO:tasks.workunit.client.0.smithi134.stdout:expected fail, finished writesame
2021-04-28T17:43:22.501 INFO:tasks.workunit.client.0.smithi134.stdout:created completion
2021-04-28T17:43:22.501 INFO:tasks.workunit.client.0.smithi134.stdout:started writesame
2021-04-28T17:43:22.502 INFO:tasks.workunit.client.0.smithi134.stdout:write completion cb called!
2021-04-28T17:43:22.502 INFO:tasks.workunit.client.0.smithi134.stdout:return value is: 0
2021-04-28T17:43:22.502 INFO:tasks.workunit.client.0.smithi134.stdout:finished writesame
2021-04-28T17:43:22.502 INFO:tasks.workunit.client.0.smithi134.stdout:to verify the data
2021-04-28T17:43:22.502 INFO:tasks.workunit.client.0.smithi134.stdout:verified
2021-04-28T17:43:22.502 INFO:tasks.workunit.client.0.smithi134.stdout:created completion
2021-04-28T17:43:22.502 INFO:tasks.workunit.client.0.smithi134.stdout:started writesame
2021-04-28T17:43:22.502 INFO:tasks.workunit.client.0.smithi134.stdout:write completion cb called!
2021-04-28T17:43:22.502 INFO:tasks.workunit.client.0.smithi134.stdout:return value is: 0
2021-04-28T17:43:22.502 INFO:tasks.workunit.client.0.smithi134.stdout:finished writesame
2021-04-28T17:43:22.502 INFO:tasks.workunit.client.0.smithi134.stdout:to verify the data
2021-04-28T17:43:22.502 INFO:tasks.workunit.client.0.smithi134.stdout:verified
2021-04-28T17:43:22.503 INFO:tasks.workunit.client.0.smithi134.stdout:created completion
2021-04-28T17:43:26.418 INFO:tasks.workunit.client.0.smithi134.stdout:started writesame
2021-04-28T17:43:26.419 INFO:tasks.workunit.client.0.smithi134.stdout:write completion cb called!
2021-04-28T17:43:26.419 INFO:tasks.workunit.client.0.smithi134.stdout:return value is: 0
2021-04-28T17:43:26.419 INFO:tasks.workunit.client.0.smithi134.stdout:finished writesame
2021-04-28T17:43:26.419 INFO:tasks.workunit.client.0.smithi134.stdout:to verify the data
2021-04-28T17:43:26.419 INFO:tasks.workunit.client.0.smithi134.stdout:verified
2021-04-28T17:43:26.419 INFO:tasks.workunit.client.0.smithi134.stdout:created completion
2021-04-28T17:43:26.419 INFO:tasks.workunit.client.0.smithi134.stdout:started writesame
2021-04-28T17:43:26.419 INFO:tasks.workunit.client.0.smithi134.stdout:write completion cb called!
2021-04-28T17:43:26.419 INFO:tasks.workunit.client.0.smithi134.stdout:return value is: 0
2021-04-28T17:43:26.419 INFO:tasks.workunit.client.0.smithi134.stdout:finished writesame
2021-04-28T17:43:26.419 INFO:tasks.workunit.client.0.smithi134.stdout:to verify the data
2021-04-28T17:43:26.420 INFO:tasks.workunit.client.0.smithi134.stdout:verified
2021-04-28T17:43:26.420 INFO:tasks.workunit.client.0.smithi134.stdout:created completion
2021-04-28T17:43:26.420 INFO:tasks.workunit.client.0.smithi134.stdout:started writesame
2021-04-28T17:43:26.420 INFO:tasks.workunit.client.0.smithi134.stdout:expected fail, finished writesame
2021-04-28T17:43:26.420 INFO:tasks.workunit.client.0.smithi134.stdout:created completion
2021-04-28T17:43:26.420 INFO:tasks.workunit.client.0.smithi134.stdout:started writesame
2021-04-28T17:43:26.420 INFO:tasks.workunit.client.0.smithi134.stdout:expected fail, finished writesame
2021-04-28T17:43:26.420 INFO:tasks.workunit.client.0.smithi134.stdout:created completion
2021-04-28T17:43:26.420 INFO:tasks.workunit.client.0.smithi134.stdout:started writesame
2021-04-28T17:43:26.420 INFO:tasks.workunit.client.0.smithi134.stdout:write completion cb called!
2021-04-28T17:43:26.420 INFO:tasks.workunit.client.0.smithi134.stdout:return value is: 0
2021-04-28T17:43:26.420 INFO:tasks.workunit.client.0.smithi134.stdout:finished writesame
2021-04-28T17:43:26.420 INFO:tasks.workunit.client.0.smithi134.stdout:to verify the data
2021-04-28T17:43:26.421 INFO:tasks.workunit.client.0.smithi134.stdout:verified
2021-04-28T17:43:26.421 INFO:tasks.workunit.client.0.smithi134.stdout:created completion
2021-04-28T17:43:26.421 INFO:tasks.workunit.client.0.smithi134.stdout:started writesame
2021-04-28T17:43:26.421 INFO:tasks.workunit.client.0.smithi134.stdout:write completion cb called!
2021-04-28T17:43:26.421 INFO:tasks.workunit.client.0.smithi134.stdout:return value is: 0
2021-04-28T17:43:26.421 INFO:tasks.workunit.client.0.smithi134.stdout:finished writesame
2021-04-28T17:43:26.421 INFO:tasks.workunit.client.0.smithi134.stdout:to verify the data
2021-04-28T17:43:26.421 INFO:tasks.workunit.client.0.smithi134.stdout:verified
2021-04-28T17:43:26.421 INFO:tasks.workunit.client.0.smithi134.stdout:created completion
2021-04-28T17:43:26.421 INFO:tasks.workunit.client.0.smithi134.stdout:started writesame
2021-04-28T17:43:26.421 INFO:tasks.workunit.client.0.smithi134.stdout:write completion cb called!
2021-04-28T17:43:26.421 INFO:tasks.workunit.client.0.smithi134.stdout:return value is: 0
2021-04-28T17:43:26.421 INFO:tasks.workunit.client.0.smithi134.stdout:finished writesame
2021-04-28T17:43:26.422 INFO:tasks.workunit.client.0.smithi134.stdout:to verify the data
2021-04-28T17:43:26.422 INFO:tasks.workunit.client.0.smithi134.stdout:verified
2021-04-28T17:43:26.422 INFO:tasks.workunit.client.0.smithi134.stdout:created completion
2021-04-28T17:43:26.422 INFO:tasks.workunit.client.0.smithi134.stdout:started writesame
2021-04-28T17:43:26.422 INFO:tasks.workunit.client.0.smithi134.stdout:write completion cb called!
2021-04-28T17:43:26.422 INFO:tasks.workunit.client.0.smithi134.stdout:return value is: 0
2021-04-28T17:43:26.422 INFO:tasks.workunit.client.0.smithi134.stdout:finished writesame
2021-04-28T17:43:26.422 INFO:tasks.workunit.client.0.smithi134.stdout:to verify the data
2021-04-28T17:43:26.422 INFO:tasks.workunit.client.0.smithi134.stdout:verified
2021-04-28T17:43:26.422 INFO:tasks.workunit.client.0.smithi134.stdout:created completion
2021-04-28T17:43:26.422 INFO:tasks.workunit.client.0.smithi134.stdout:started writesame
2021-04-28T17:43:26.422 INFO:tasks.workunit.client.0.smithi134.stdout:expected fail, finished writesame
2021-04-28T17:43:26.422 INFO:tasks.workunit.client.0.smithi134.stdout:created completion
2021-04-28T17:43:26.422 INFO:tasks.workunit.client.0.smithi134.stdout:started writesame
2021-04-28T17:43:26.423 INFO:tasks.workunit.client.0.smithi134.stdout:expected fail, finished writesame
2021-04-28T17:43:26.423 INFO:tasks.workunit.client.0.smithi134.stdout:created completion
2021-04-28T17:43:26.423 INFO:tasks.workunit.client.0.smithi134.stdout:started writesame
2021-04-28T17:43:26.423 INFO:tasks.workunit.client.0.smithi134.stdout:write completion cb called!
2021-04-28T17:43:26.423 INFO:tasks.workunit.client.0.smithi134.stdout:return value is: 0
2021-04-28T17:43:26.423 INFO:tasks.workunit.client.0.smithi134.stdout:finished writesame
2021-04-28T17:43:26.423 INFO:tasks.workunit.client.0.smithi134.stdout:to verify the data
2021-04-28T17:43:26.423 INFO:tasks.workunit.client.0.smithi134.stdout:verified
2021-04-28T17:43:26.423 INFO:tasks.workunit.client.0.smithi134.stdout:created completion
2021-04-28T17:43:26.423 INFO:tasks.workunit.client.0.smithi134.stdout:started writesame
2021-04-28T17:43:26.423 INFO:tasks.workunit.client.0.smithi134.stdout:write completion cb called!
2021-04-28T17:43:26.423 INFO:tasks.workunit.client.0.smithi134.stdout:return value is: 0
2021-04-28T17:43:26.423 INFO:tasks.workunit.client.0.smithi134.stdout:finished writesame
2021-04-28T17:43:26.424 INFO:tasks.workunit.client.0.smithi134.stdout:to verify the data
2021-04-28T17:43:26.424 INFO:tasks.workunit.client.0.smithi134.stdout:verified
2021-04-28T17:43:26.424 INFO:tasks.workunit.client.0.smithi134.stdout:created completion
2021-04-28T17:43:26.424 INFO:tasks.workunit.client.0.smithi134.stdout:started writesame
2021-04-28T17:43:26.424 INFO:tasks.workunit.client.0.smithi134.stdout:write completion cb called!
2021-04-28T17:43:26.424 INFO:tasks.workunit.client.0.smithi134.stdout:return value is: 0
2021-04-28T17:43:26.424 INFO:tasks.workunit.client.0.smithi134.stdout:finished writesame
2021-04-28T17:43:26.424 INFO:tasks.workunit.client.0.smithi134.stdout:to verify the data
2021-04-28T17:43:26.424 INFO:tasks.workunit.client.0.smithi134.stdout:verified
2021-04-28T17:43:26.424 INFO:tasks.workunit.client.0.smithi134.stdout:created completion
2021-04-28T17:43:26.424 INFO:tasks.workunit.client.0.smithi134.stdout:started writesame
2021-04-28T17:43:26.424 INFO:tasks.workunit.client.0.smithi134.stdout:write completion cb called!
2021-04-28T17:43:26.424 INFO:tasks.workunit.client.0.smithi134.stdout:return value is: 0
2021-04-28T17:43:26.425 INFO:tasks.workunit.client.0.smithi134.stdout:finished writesame
2021-04-28T17:43:26.425 INFO:tasks.workunit.client.0.smithi134.stdout:to verify the data
2021-04-28T17:43:26.425 INFO:tasks.workunit.client.0.smithi134.stdout:verified
2021-04-28T17:43:26.425 INFO:tasks.workunit.client.0.smithi134.stdout:created completion
2021-04-28T17:43:26.425 INFO:tasks.workunit.client.0.smithi134.stdout:started writesame
2021-04-28T17:43:26.425 INFO:tasks.workunit.client.0.smithi134.stdout:expected fail, finished writesame
2021-04-28T17:43:26.425 INFO:tasks.workunit.client.0.smithi134.stdout:created completion
2021-04-28T17:43:26.425 INFO:tasks.workunit.client.0.smithi134.stdout:started writesame
2021-04-28T17:43:26.425 INFO:tasks.workunit.client.0.smithi134.stdout:expected fail, finished writesame
2021-04-28T17:43:26.425 INFO:tasks.workunit.client.0.smithi134.stdout:created completion
2021-04-28T17:43:26.425 INFO:tasks.workunit.client.0.smithi134.stdout:started writesame
2021-04-28T17:43:26.425 INFO:tasks.workunit.client.0.smithi134.stdout:write completion cb called!
2021-04-28T17:43:26.425 INFO:tasks.workunit.client.0.smithi134.stdout:return value is: 0
2021-04-28T17:43:26.426 INFO:tasks.workunit.client.0.smithi134.stdout:finished writesame
2021-04-28T17:43:26.426 INFO:tasks.workunit.client.0.smithi134.stdout:to verify the data
2021-04-28T17:43:26.426 INFO:tasks.workunit.client.0.smithi134.stdout:verified
2021-04-28T17:43:26.426 INFO:tasks.workunit.client.0.smithi134.stdout:created completion
2021-04-28T17:43:26.426 INFO:tasks.workunit.client.0.smithi134.stdout:started writesame
2021-04-28T17:43:26.426 INFO:tasks.workunit.client.0.smithi134.stdout:write completion cb called!
2021-04-28T17:43:26.426 INFO:tasks.workunit.client.0.smithi134.stdout:return value is: 0
2021-04-28T17:43:26.426 INFO:tasks.workunit.client.0.smithi134.stdout:finished writesame
2021-04-28T17:43:26.426 INFO:tasks.workunit.client.0.smithi134.stdout:to verify the data
2021-04-28T17:43:26.426 INFO:tasks.workunit.client.0.smithi134.stdout:verified
2021-04-28T17:43:26.426 INFO:tasks.workunit.client.0.smithi134.stdout:created completion
2021-04-28T17:43:26.426 INFO:tasks.workunit.client.0.smithi134.stdout:started writesame
2021-04-28T17:43:26.426 INFO:tasks.workunit.client.0.smithi134.stdout:write completion cb called!
2021-04-28T17:43:26.427 INFO:tasks.workunit.client.0.smithi134.stdout:return value is: 0
2021-04-28T17:43:26.427 INFO:tasks.workunit.client.0.smithi134.stdout:finished writesame
2021-04-28T17:43:26.427 INFO:tasks.workunit.client.0.smithi134.stdout:to verify the data
2021-04-28T17:43:26.427 INFO:tasks.workunit.client.0.smithi134.stdout:verified
2021-04-28T17:43:26.427 INFO:tasks.workunit.client.0.smithi134.stdout:created completion
2021-04-28T17:43:26.427 INFO:tasks.workunit.client.0.smithi134.stdout:started writesame
2021-04-28T17:43:26.427 INFO:tasks.workunit.client.0.smithi134.stdout:write completion cb called!
2021-04-28T17:43:26.427 INFO:tasks.workunit.client.0.smithi134.stdout:return value is: 0
2021-04-28T17:43:26.427 INFO:tasks.workunit.client.0.smithi134.stdout:finished writesame
2021-04-28T17:43:26.427 INFO:tasks.workunit.client.0.smithi134.stdout:to verify the data
2021-04-28T17:43:26.427 INFO:tasks.workunit.client.0.smithi134.stdout:verified
2021-04-28T17:43:26.427 INFO:tasks.workunit.client.0.smithi134.stdout:created completion
2021-04-28T17:43:26.427 INFO:tasks.workunit.client.0.smithi134.stdout:started writesame
2021-04-28T17:43:26.428 INFO:tasks.workunit.client.0.smithi134.stdout:expected fail, finished writesame
2021-04-28T17:43:26.428 INFO:tasks.workunit.client.0.smithi134.stdout:created completion
2021-04-28T17:43:26.428 INFO:tasks.workunit.client.0.smithi134.stdout:started writesame
2021-04-28T17:43:26.428 INFO:tasks.workunit.client.0.smithi134.stdout:expected fail, finished writesame
2021-04-28T17:43:26.428 INFO:tasks.workunit.client.0.smithi134.stdout:read completion cb called!
2021-04-28T17:43:26.428 INFO:tasks.workunit.client.0.smithi134.stdout:read completion cb called!
2021-04-28T17:43:26.428 INFO:tasks.workunit.client.0.smithi134.stdout:wrote: 512
2021-04-28T17:43:26.428 INFO:tasks.workunit.client.0.smithi134.stdout:read completion cb called!
2021-04-28T17:43:26.428 INFO:tasks.workunit.client.0.smithi134.stdout:wrote: 4
2021-04-28T17:43:26.428 INFO:tasks.workunit.client.0.smithi134.stdout:read: 4
2021-04-28T17:43:26.428 INFO:tasks.workunit.client.0.smithi134.stdout:read:
2021-04-28T17:43:26.428 INFO:tasks.workunit.client.0.smithi134.stdout:expected: test
2021-04-28T17:43:26.428 INFO:tasks.workunit.client.0.smithi134.stdout:/home/jenkins-build/build/workspace/ceph-dev-new-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos8/DIST/centos8/MACHINE_SIZE/gigantic/release/17.0.0-3641-g263d6121/rpm/el8/BUILD/ceph-17.0.0-3641-g263d6121/src/test/librbd/test_librbd.cc:364: Failure
2021-04-28T17:43:26.429 INFO:tasks.workunit.client.0.smithi134.stdout:Expected equality of these values:
2021-04-28T17:43:26.429 INFO:tasks.workunit.client.0.smithi134.stdout:  0
2021-04-28T17:43:26.429 INFO:tasks.workunit.client.0.smithi134.stdout:  memcmp(result, expected, len)
2021-04-28T17:43:26.429 INFO:tasks.workunit.client.0.smithi134.stdout:    Which is: -1
2021-04-28T17:43:26.452 INFO:tasks.workunit.client.0.smithi134.stdout:[  FAILED  ] TestLibRBD.TestEncryptionLUKS2 (13130 ms)

#3 Updated by Deepika Upadhyay almost 3 years ago

  • Assignee set to Deepika Upadhyay

#4 Updated by Deepika Upadhyay almost 3 years ago

looks like, the data is lost while we are trying to decrypt:

2021-06-04T11:50:09.609+0000 7f61edffb700 20 librbd::crypto::CryptoInterface: 0x7f61b2664bf0 decrypt_aligned_extent: decrypt_aligned_extent buf=~P1�rVDC�(t
2mq�~M�ud~5'-޽~J^_^V��[38;5;81m^Yx���[38;5;81m^Q�~E^Z"~_    e�Q~Y~X�v^N�~\�ྨ�p! ^MSAr��^D}�^C^Hq��[38;5;81m^Y�5^?^T<�  ~Rasf�      ~W~EaI1gj�0^K~OK~@~P�:^U/VV
0-�~Gg�[38;5;81m^H^V^TMNV^W� D W^^�[38;5;81m~[~M�bHL~]^D~VP4^Quaj~D�~N岸QO^Z^Z^O�~SH't�~L=!^L~L~P~O~E~C$mӷ�[38;5;81m~H~P"~QbpTɼ�[38;5;81m^P4�[38;5;81m^\c`�~^~^^C�~_,^^~Vʱ^FO]~O�l~T)�^D~V^Mb~@^E*;�[38;5;81m~S�[38;5;81m~@M�;`^]~O^A8~Ke~KXH:!Nlre^M-5I�bl len=4096
2021-06-04T11:50:09.609+0000 7f61edffb700 20 librbd::crypto::CryptoInterface: 0x7f61b2664bf0 decrypt_aligned_extent: decrypt_aligned_extent buf_result=
2021-06-04T11:50:09.609+0000 7f61edffb700 20 librbd::crypto::CryptoObjectDispatch: 0x7f61dc055040 handle_read: aligned read extent buf

while in passed case:

2021-06-04T11:48:59.229+0000 7f3f40d99700 20 librbd::crypto::CryptoInterface: 0x7f3f265db870 decrypt_aligned_extent: decrypt_aligned_extent buf=mV~C^\~Pvi~[hp  �[34m~J�IO^\eۿ
�[34m~D~W5d��[34m^V[+^R!��\̻~PBj~KB^DV���[34m^^eDA�[34m^F~H}~R�[34m^V!�[34m^?~T~E�6�h2�'^?br0~_^Ch>Me-�[34m~Z�^L^\^K~Y���&|�v:�t~E~Uc]6~S@? /^��`,~OC�vK~U~O~OM~T^UU
#�^E���T%.~P�[34m^TJ^UdڦoU~XZJ�y"�~R^FG~@�~S~T^YJ:(^PZ�O�2/xݶr~Pc~N~V| Y2~R�3I^K~Mq~\_W~@�s~EE�R;.�n~K^?�~W~NdS+~_�"2~R5^O�h�8a�[34m~\>�Y^C~BB
B�[34m~X�^V~F~A�~Icr^FO
�[34m~UM
Iz��[34m^B.�q_^KS+8e^^V^Z?#_Mz^�[34m~\`^F9^A^[W��~Wy^D��[34m^X~AqcTe��Nbl len=4096
2021-06-04T11:48:59.229+0000 7f3f40d99700 20 librbd::crypto::CryptoInterface: 0x7f3f265db870 decrypt_aligned_extent: decrypt_aligned_extent buf_result=test_luks2
2021-06-04T11:48:59.229+0000 7f3f40d99700 20 librbd::crypto::CryptoObjectDispatch: 0x7f3f00129100 handle_read: aligned read extent buftest_luks2

#5 Updated by Deepika Upadhyay over 2 years ago

  • Related to Bug #51438: [pwl] possible data corruption in TEST_F(TestLibRBD, TestFUA) added

#7 Updated by Deepika Upadhyay over 2 years ago

when we do CryptoObjectDispatch::handle_read which calls:
decrypt_aligned_extent which gets another handle_read for a write request(`handle_read: unaligned write r=3584`) racing with it.

FAILING


```less
2021-07-13T09:15:28.694+0000 7f64dbfff700 20 librbd::crypto::CryptoObjectDispatch: 0x7f641bbfbf90 handle_read: aligned read extent buftest_luks2fbTYVCGbUDGDvMBCFSEnEaQgSmigqiDWkPlwddCDHEnGllksGdLPHHJoCrYxSzgSrpBVhpuCPZbZSYHKJLcKomCruzETzUBdkrRXrNjphPHVXZnAGusWuqCDnMWdLhztDEMUxJIqQpXhBfNgJAnFIBaXDkHmrkAOopxxZxIYdqAyQBjQiEwiRxYUQEhVIECgdCreyKddfvmRrXDQJUcStQdMBsiZyyZFpTtgtIjvyZZNiPPKRdTjMiXGhBbUkBUpCjplJvmSKetJZiFyeNnoCIuEEcmnJGoUeISsLUfInuruJbnmYxwEoOscvxtFDinwmpimoPTFOEJlIDhRrEbzzBvzmWyyRYpOhHtjlnJnkIoCqeiemqjTmhdNeLnUvQIxySmODapWgLdlfoUHtaXTsvoNQSuaXHzJzdMPPfeFczVNWeIoMfYNnQNPTdBIuQclufGgAqmDLbrJSPHjANTqUvukCWsetBnROOvckzjSwruXBXeWuLcCDWddpPdpP
2021-07-13T09:15:28.694+0000 7f64dbfff700 20 librbd::crypto::CryptoObjectDispatch: 0x7f641bbfbf90 finish: aligned read r=4096
2021-07-13T09:15:28.694+0000 7f64dbfff700 20 librbd::crypto::CryptoObjectDispatch: 0x7f64a001f800 finish: unaligned read r=4096
2021-07-13T09:15:28.694+0000 7f64dbfff700 20 librbd::crypto::CryptoObjectDispatch: 0x7f642b299c30 handle_read: unaligned write r=3584
2021-07-13T09:15:28.694+0000 7f64dbfff700 20 librbd::crypto::CryptoObjectDispatch: 0x7f642b299c30 build_aligned_data:  pre align length=0 post align length=3584
2021-07-13T09:15:28.694+0000 7f64dbfff700 20 librbd::crypto::CryptoObjectDispatch: 0x7f642b299c30 build_aligned_data:  aligned append=
2021-07-13T09:15:28.694+0000 7f64dbfff700 20 librbd::io::util: unsparsify:  data_buffer_before=ddpPdpP
2021-07-13T09:15:28.694+0000 7f64dbfff700 20 librbd::io::util: unsparsify:  data_buffer_after=ddpPdpP
2021-07-13T09:15:28.694+0000 7f64dbfff700 20 librbd::crypto::CryptoObjectDispatch: 0x7f642b299c30 build_aligned_data:  extent bl=
2021-07-13T09:15:28.694+0000 7f64dbfff700 20 librbd::crypto::CryptoObjectDispatch: 0x7f642b299c30 build_aligned_data:  after post align=
2021-07-13T09:15:28.694+0000 7f64dbfff700 20 librbd::crypto::CryptoObjectDispatch: 0x7f642b299c30 handle_read: unaligned write data=

```

PASSING


2021-07-13T09:15:55.818+0000 7ff4e77fe700 20 librbd::crypto::CryptoInterface: 0x7ff4d4003e40 decrypt_aligned_extent: decrypt_aligned_extent buf_result=test_luks2fbTYVCGbUDGDvMBCFSEnEaQgSmigqiDWkPlwddCDHEnGllksGdLPHHJoCrYxSzgSrpBVhpuCPZbZSYHKJLcKomCruzETzUBdkrRXrNjphPHVXZnAGusWuqCDnMWdLhztDEMUxJIqQpXhBfNgJAnFIBaXDkHmrkAOopxxZxIYdqAyQBjQiEwiRxYUQEhVIECgdCreyKddfvmRrXDQJUcStQdMBsiZyyZFpTtgtIjvyZZNiPPKRdTjMiXGhBbUkBUpCjplJvmSKetJZiFyeNnoCIuEEcmnJGoUeISsLUfInuruJbnmYxwEoOscvxtFDinwmpimoPTFOEJlIDhRrEbzzBvzmWyyRYpOhHtjlnJnkIoCqeiemqjTmhdNeLnUvQIxySmODapWgLdlfoUHtaXTsvoNQSuaXHzJzdMPPfeFczVNWeIoMfYNnQNPTdBIuQclufGgAqmDLbrJSPHjANTqUvukCWsetBnROOvckzjSwruXBXeWuLcCDWq
2021-07-13T09:15:55.818+0000 7ff4e77fe700 20 librbd::crypto::CryptoObjectDispatch: 0x7ff4d666e650 handle_read: aligned read extent buftest_luks2fbTYVCGbUDGDvMBCFSEnEaQgSmigqiDWkPlwddCDHEnGllksGdLPHHJoCrYxSzgSrpBVhpuCPZbZSYHKJLcKomCruzETzUBdkrRXrNjphPHVXZnAGusWuqCDnMWdLhztDEMUxJIqQpXhBfNgJAnFIBaXDkHmrkAOopxxZxIYdqAyQBjQiEwiRxYUQEhVIECgdCreyKddfvmRrXDQJUcStQdMBsiZyyZFpTtgtIjvyZZNiPPKRdTjMiXGhBbUkBUpCjplJvmSKetJZiFyeNnoCIuEEcmnJGoUeISsLUfInuruJbnmYxwEoOscvxtFDinwmpimoPTFOEJlIDhRrEbzzBvzmWyyRYpOhHtjlnJnkIoCqeiemqjTmhdNeLnUvQIxySmODapWgLdlfoUHtaXTsvoNQSuaXHzJzdMPPfeFczVNWeIoMfYNnQNPTdBIuQclufGgAqmDLbrJSPHjANTqUvukCWsetBnROOvckzjSwruXBXeWuLcCDWq
2021-07-13T09:15:55.818+0000 7ff4e77fe700 20 librbd::crypto::CryptoObjectDispatch: 0x7ff4d666e650 finish: aligned read r=4096
2021-07-13T09:15:55.818+0000 7ff4e77fe700 20 librbd::crypto::CryptoObjectDispatch: 0x5620a2c388f0 finish: unaligned read r=4096
2021-07-13T09:15:55.818+0000 7ff4e77fe700 10 librbd::io::ReadResult: 0x7ff4d63f4fd0 finish: C_ObjectReadRequest: r=512
2021-07-13T09:15:55.818+0000 7ff4e77fe700 10 librbd::io::ReadResult: 0x7ff4d63f4fd0 finish:  got [0,512] for [0,512] bl 512 bl_val test_luks2fbTYVCGbUDGDvMBCFSEnEaQgSmigqiDWkPlwddCDHEnGllksGdLPHHJoCrYxSzgSrpBVhpuCPZbZSYHKJLcKomCruzETzUBdkrRXrNjphPHVXZnAGusWuqCDnMWdLhztDEMUxJIqQpXhBfNgJAnFIBaXDkHmrkAOopxxZxIYdqAyQBjQiEwiRxYUQEhVIECgdCreyKddfvmRrXDQJUcStQdMBsiZyyZFpTtgtIjvyZZNiPPKRdTjMiXGhBbUkBUpCjplJvmSKetJZiFyeNnoCIuEEcmnJGoUeISsLUfInuruJbnmYxwEoOscvxtFDinwmpimoPTFOEJlIDhRrEbzzBvzmWyyRYpOhHtjlnJnkIoCqeiemqjTmhdNeLnUvQIxySmODapWgLdlfoUHtaXTsvoNQSuaXHzJzdMPPfeFczVNWeIoMfYNnQNPTdBIuQclufGgAqmDLbrJSPHjANTqUvukCWsetBnROOvckzjSwruXBXeWuLcCDWq
2021-07-13T09:15:55.818+0000 7ff4e77fe700 20 librbd::io::ReadResult: 0x7ff4d63f4fd0 finish: data:
2021-07-13T09:15:55.818+0000 7ff4e77fe700 20 librbd::io::ReadResult: 0x7ff4d63f4fd0 finish:

The object is different though! doesn't evidently prove, although in all the failing cases I see the same output

#8 Updated by Deepika Upadhyay over 2 years ago

  • Assignee deleted (Deepika Upadhyay)

#9 Updated by Deepika Upadhyay over 2 years ago

/ceph/teuthology-archive/ideepika-2021-08-16_08:32:04-rbd-wip-deepika-testing-2021-08-13-2138-distro-basic-smithi/6340736/teuthology.log

#10 Updated by jianpeng ma over 2 years ago

@ Deepika Upadhyay, when you met the problem, are you enable pwl_cache or not? I want to know if this problem is related to pwl_cache. Thanks!

#11 Updated by jianpeng ma over 2 years ago

I can reproduce this bug w/ pwl_cache. And found the root reason. I create a new issue(https://tracker.ceph.com/issues/52511)to descript the reason.

#12 Updated by Deepika Upadhyay over 2 years ago

  • Related to Bug #52511: [pwl ssd] flush cause io re-oreder to writeback layer added

#13 Updated by Deepika Upadhyay over 2 years ago

  • Related to deleted (Bug #51438: [pwl] possible data corruption in TEST_F(TestLibRBD, TestFUA))

#14 Updated by Deepika Upadhyay over 2 years ago

- does not reproduce without caching

1175 2021-09-15T11:48:21.852+0000 7f5f24ef8280 20 librbd::api::Io write: ictx=0x556bd4c32120, off=0, len = 512
1176 2021-09-15T11:48:21.852+0000 7f5f24ef8280 10 librbd::api::Io write: write  <86>Qý^?

first workload

1200 2021-09-15T11:48:21.968+0000 7f5f24ef8280 20 librbd::api::Io write: ictx=0x556bd4c32120, off=0, len = 4096
1201 2021-09-15T11:48:21.968+0000 7f5f24ef8280 10 librbd::api::Io write: write¨3²^G

2nd workload

1225 2021-09-15T11:48:22.317+0000 7f5f24ef8280 20 librbd::api::Io write: ictx=0x556bd4c32120, off=0, len = 10
1226 2021-09-15T11:48:22.317+0000 7f5f24ef8280 10 librbd::api::Io write: writetest_luks2

our data

1373 2021-09-15T11:48:22.650+0000 7f5ddd7fa700 20 librbd::crypto::CryptoObjectDispatch: 0x7f5b7400ab10 write: rbd_data.4d3a8e18709.0000000000000004 0~4096 data=test_luks2
1374 2021-09-15T11:48:22.650+0000 7f5ddd7fa700 20 librbd::crypto::BlockCrypto: 0x556bd4c1b600 encrypt: encrypt data=test_luks2

written and encrypted, but then we see 1st workload encryption again, which is
what is read atlast.

1478 2021-09-15T11:48:22.651+0000 7f5ddd7fa700 20 librbd::crypto::CryptoObjectDispatch: 0x7f5b7400ab10 write: rbd_data.4d3a8e18709.0000000000000004 0~4096 data=  <86>Qý^?
1479 2021-09-15T11:48:22.651+0000 7f5ddd7fa700 20 librbd::crypto::BlockCrypto: 0x556bd4c1b600 encrypt: encrypt data=  <86>Qý^?

the initial write api is okay, investigating instances where we send write request from cryptodispatch layer...

without caching enabled, I see only 3 encrypt data logs with test_luks2 as the final write, that means... the problem is why do we have extra : `479 2021-09-15T11:48:22.651+0000 7f5ddd7fa700 20 librbd::crypto::BlockCrypto: 0x556bd4c1b600 encrypt: encrypt data=  <86>Qý^?` call:
without caching pattern:


client.admin.3663489.log:2021-09-21T15:23:44.029+0000 7f427dffb700 20 librbd::crypto::BlockCrypto: 0x55a5008b3500 encrypt: encrypt data=test_luks21v
client.admin.3677402.log:2021-09-21T15:25:17.032+0000 7f3c467fc700 20 librbd::crypto::BlockCrypto: 0x556f8e12f500 encrypt: encrypt data=�K
client.admin.3677402.log:2021-09-21T15:25:17.032+0000 7f3c45ffb700 20 librbd::crypto::BlockCrypto: 0x556f8e12f500 encrypt: encrypt data=@3=
client.admin.3677402.log:2021-09-21T15:25:17.032+0000 7f3c467fc700 20 librbd::crypto::BlockCrypto: 0x556f8e12f500 encrypt: encrypt data=test_luks2
client.admin.3686630.log:2021-09-21T15:26:23.968+0000 7f99c2ffd700 20 librbd::crypto::BlockCrypto: 0x56253f0cb500 encrypt: encrypt data=iC
client.admin.3686630.log:2021-09-21T15:26:23.968+0000 7f99c27fc700 20 librbd::crypto::BlockCrypto: 0x56253f0cb500 encrypt: encrypt data=@#}
client.admin.3686630.log:2021-09-21T15:26:23.968+0000 7f99c27fc700 20 librbd::crypto::BlockCrypto: 0x56253f0cb500 encrypt: encrypt data=test_luks2
client.admin.3664777.log:2021-09-21T15:23:52.325+0000 7f6e5b7fe700 20 librbd::crypto::BlockCrypto: 0x557679579a60 encrypt: encrypt data=P(u
client.admin.3664777.log:2021-09-21T15:23:52.326+0000 7f6e5b7fe700 20 librbd::crypto::BlockCrypto: 0x557679579a60 encrypt: encrypt data=xmo
client.admin.3664777.log:2021-09-21T15:23:52.326+0000 7f6e5affd700 20 librbd::crypto::BlockCrypto: 0x557679579a60 encrypt: encrypt data=test_luks2
client.admin.3684278.log:2021-09-21T15:26:06.583+0000 7f6ffd7fa700 20 librbd::crypto::BlockCrypto: 0x5648b5bf5620 encrypt: encrypt data=0l
client.admin.3684278.log:2021-09-21T15:26:06.583+0000 7f6ffcff9700 20 librbd::crypto::BlockCrypto: 0x5648b5bf5620 encrypt: encrypt data=@s�q
client.admin.3684278.log:2021-09-21T15:26:06.583+0000 7f6ffcff9700 20 librbd::crypto::BlockCrypto: 0x5648b5bf5620 encrypt: encrypt data=test_luks2
client.admin.3679526.log:2021-09-21T15:25:31.812+0000 7fe7ed7fa700 20 librbd::crypto::BlockCrypto: 0x561167d0d4e0 encrypt: encrypt data=@{
client.admin.3679526.log:2021-09-21T15:25:31.812+0000 7fe7ecff9700 20 librbd::crypto::BlockCrypto: 0x561167d0d4e0 encrypt: encrypt data=~
client.admin.3679526.log:2021-09-21T15:25:31.812+0000 7fe7ecff9700 20 librbd::crypto::BlockCrypto: 0x561167d0d4e0 encrypt: encrypt data=test_luks2

with encryption:

client.admin.3837376.log:2021-09-22T06:15:53.974+0000 7fccb97fa700 20 librbd::crypto::BlockCrypto: 0x563bb9ffccd0 encrypt: encrypt data=test_luks2�
client.admin.3843196.log:2021-09-22T06:17:08.611+0000 7f760dffb700 20 librbd::crypto::BlockCrypto: 0x55df80f23cd0 encrypt: encrypt data=@×Tw
client.admin.3843196.log:2021-09-22T06:17:08.611+0000 7f760d7fa700 20 librbd::crypto::BlockCrypto: 0x55df80f23cd0 encrypt: encrypt data=�
client.admin.3843196.log:2021-09-22T06:17:08.611+0000 7f760dffb700 20 librbd::crypto::BlockCrypto: 0x55df80f23cd0 encrypt: encrypt data=test_luks2
client.admin.3843196.log:2021-09-22T06:17:08.612+0000 7f760d7fa700 20 librbd::crypto::BlockCrypto: 0x55df80f23cd0 encrypt: encrypt data=�
client.admin.3838400.log:2021-09-22T06:16:08.586+0000 7f2f997fa700 20 librbd::crypto::BlockCrypto: 0x5632e1413cd0 encrypt: encrypt data=`��

#15 Updated by Or Ozeri over 2 years ago

Near the end of the test there are 2 writes.
One writes 512 (TEST_IO_SIZE) zeros to image offset 0.
The other writes "test" to image offset 0.
Looks like the first write is wrongfully overwriting the first write.
So, when we read after the image was flushed and closed, we expect "test", but instead we get zeros.

Note that even though image extents for the 2 writes are [0~512] and [0~4], the crypto layer actually translates those to [0~4096], [0~4096], since crypto writes for LUKS2 are always 4K-aligned.

#17 Updated by Or Ozeri over 2 years ago

@Deepika The two writes at the end of the test should not race, but rather the second write is expected to begin only AFTER the first write completed.
The first write comes from the line in the test_io function:

ASSERT_PASSED(write_test_data, image, zero_data, 0, TEST_IO_SIZE,
LIBRADOS_OP_FLAG_FADVISE_NOCACHE);

The second write follows from TestEncryptionLUKS2:

write_test_data(image, "test", 0, 4, 0, &passed);

The first write is synchronous, so when it returns the user expects the data to be actually persisted.
Are you suggesting that a bug in ObjectOMap causes the first write to be delayed?
I would expect that while the write is delayed, the calling "image.write" (inside write_test_data) will not return.

#18 Updated by Or Ozeri over 2 years ago

I reproduced this issue with debug enabled on pwl as well.
Looks like that pwl is flushing both writes concurrently, without ensuring that the first write (0~512) is completed before the second one (0~4).


2021-11-21T07:11:55.483-0600 7f346f7fe700 15 librbd::cache::pwl::rwl::WriteLog: 0x7f34380064a0 operator(): flushing:0x7f345c73e060 (Write) ram_entry=[entry_valid=1, sync_point=0, sequenced=0, has_data=1, discard=0, writesame=0, sync_gen_number=2, write_sequence_number=0, image_offset_bytes=0, write_bytes=512, ws_datalen=0, entry_index=76], cache_entry=0x7f33e41c3970, log_entry_index=76, completed=1, sync_point_entry=[(Sync Point) ram_entry=[entry_valid=1, sync_point=1, sequenced=0, has_data=0, discard=0, writesame=0, sync_gen_number=2, write_sequence_number=0, image_offset_bytes=0, write_bytes=0, ws_datalen=0, entry_index=78], cache_entry=0x7f33e41c3a00, log_entry_index=78, completed=1, writes=61, bytes=4271630, writes_completed=61, writes_flushed=0, prior_sync_point_flushed=1, next_sync_point_entry=0x7f345c73dea0], referring_map_entries=1, cache_buffer=0x7f33ea203d90, cache_bp=buffer::ptr(0~512 0x7f33ea203d90 in raw 0x7f33ea203d90 len 512 nref 2), bl_refs=1
2021-11-21T07:11:55.483-0600 7f346effd700 20 librbd::crypto::CryptoObjectDispatch: 0x7f345c00d330 write: rbd_data.382ddd2b0949.0000000000000004 0~217088
2021-11-21T07:11:55.483-0600 7f346f7fe700 20 librbd::ImageWriteback: aio_write: image_extents=[0,512], on_finish=0x7f33dc01a2f0
2021-11-21T07:11:55.483-0600 7f346f7fe700 20 librbd::io::AsyncOperation: 0x7f345c04cf20 start_op
2021-11-21T07:11:55.483-0600 7f346f7fe700 20 librbd::io::Dispatcher: 0x555ca9876230 send: dispatch_spec=0x7f345c04cf80
2021-11-21T07:11:55.483-0600 7f346f7fe700 20 librbd::io::ImageDispatch: 0x555ca984b590 write: image_extents=[0,512]
2021-11-21T07:11:55.483-0600 7f346f7fe700 20 librbd::io::ImageRequest: 0x7f346f7fa340 send: aio_write: ictx=0x555ca987b010, completion=0x7f345c04ce10
2021-11-21T07:11:55.483-0600 7f346f7fe700 20 librbd::io::AioCompletion: 0x7f345c04ce10 set_request_count: pending=1
2021-11-21T07:11:55.483-0600 7f346f7fe700 20 librbd::io::ImageRequest: 0x7f346f7fa340 send_object_requests: rbd_data.382ddd2b0949.0000000000000004 0~512 from [0,512]
2021-11-21T07:11:55.483-0600 7f346f7fe700 20 librbd::io::Dispatcher: 0x7f342c0382c0 send: dispatch_spec=0x7f345c04d070
2021-11-21T07:11:55.483-0600 7f346f7fe700 20 librbd::cache::WriteAroundObjectDispatch: 0x7f345c014b40 write: rbd_data.382ddd2b0949.0000000000000004 0~512
2021-11-21T07:11:55.483-0600 7f346f7fe700 20 librbd::crypto::CryptoObjectDispatch: 0x7f345c00d330 write: rbd_data.382ddd2b0949.0000000000000004 0~512
2021-11-21T07:11:55.483-0600 7f346f7fe700 20 librbd::io::Dispatcher: 0x7f342c0382c0 send: dispatch_spec=0x7f345c04d450
2021-11-21T07:11:55.483-0600 7f346f7fe700 20 librbd::crypto::CryptoObjectDispatch: 0x7f345c00d330 read: rbd_data.382ddd2b0949.0000000000000004 [offset=0, length=4096, buffer_extents=[], bl.length=0, extent_map=[]]
2021-11-21T07:11:55.483-0600 7f346f7fe700 20 librbd::io::Dispatcher: 0x7f342c0382c0 send: dispatch_spec=0x7f345c04d560
2021-11-21T07:11:55.483-0600 7f346f7fe700 20 librbd::io::SimpleSchedulerObjectDispatch: 0x7f346800a7b0 read: rbd_data.382ddd2b0949.0000000000000004 0x7f345c04d370
2021-11-21T07:11:55.483-0600 7f346f7fe700 20 librbd::io::SimpleSchedulerObjectDispatch: 0x7f346800a7b0 intersects: 0
2021-11-21T07:11:55.483-0600 7f346f7fe700 20 librbd::io::ObjectDispatch: 0x555ca984b630 read: object_no=4 [offset=0, length=4096, buffer_extents=[], bl.length=0, extent_map=[]]
2021-11-21T07:11:55.483-0600 7f346f7fe700 20 librbd::io::ObjectRequest: 0x7f345c04d650 send: rbd_data.382ddd2b0949.0000000000000004
2021-11-21T07:11:55.483-0600 7f346f7fe700 20 librbd::ObjectMap: 0x7f3438007f10 object_may_exist: object_no=4 r=1
2021-11-21T07:11:55.483-0600 7f346f7fe700 20 librbd::io::ObjectRequest: 0x7f345c04d650 read_object: rbd_data.382ddd2b0949.0000000000000004 snap_id=18446744073709551614
2021-11-21T07:11:55.483-0600 7f346f7fe700 15 librbd::cache::pwl::rwl::WriteLog: 0x7f34380064a0 operator(): flushing:0x7f343ac549c0 (Write) ram_entry=[entry_valid=1, sync_point=0, sequenced=0, has_data=1, discard=0, writesame=0, sync_gen_number=2, write_sequence_number=0, image_offset_bytes=0, write_bytes=4, ws_datalen=0, entry_index=77], cache_entry=0x7f33e41c39b8, log_entry_index=77, completed=1, sync_point_entry=[(Sync Point) ram_entry=[entry_valid=1, sync_point=1, sequenced=0, has_data=0, discard=0, writesame=0, sync_gen_number=2, write_sequence_number=0, image_offset_bytes=0, write_bytes=0, ws_datalen=0, entry_index=78], cache_entry=0x7f33e41c3a00, log_entry_index=78, completed=1, writes=61, bytes=4271630, writes_completed=61, writes_flushed=0, prior_sync_point_flushed=1, next_sync_point_entry=0x7f345c73dea0], referring_map_entries=1, cache_buffer=0x7f33ea2448d0, cache_bp=buffer:ptr(0~0 no raw), bl_refs=0
2021-11-21T07:11:55.483-0600 7f346f7fe700 20 librbd::ImageWriteback: aio_write: image_extents=[0,4], on_finish=0x7f33dc01a380
2021-11-21T07:11:55.483-0600 7f346f7fe700 20 librbd::io::AsyncOperation: 0x7f345c0609e0 start_op
2021-11-21T07:11:55.483-0600 7f346f7fe700 20 librbd::io::Dispatcher: 0x555ca9876230 send: dispatch_spec=0x7f345c060a40
2021-11-21T07:11:55.483-0600 7f346f7fe700 20 librbd::io::ImageDispatch: 0x555ca984b590 write: image_extents=[0,4]
2021-11-21T07:11:55.483-0600 7f346f7fe700 20 librbd::io::ImageRequest: 0x7f346f7fa340 send: aio_write: ictx=0x555ca987b010, completion=0x7f345c0608d0
2021-11-21T07:11:55.483-0600 7f346f7fe700 20 librbd::io::AioCompletion: 0x7f345c0608d0 set_request_count: pending=1
2021-11-21T07:11:55.483-0600 7f346f7fe700 20 librbd::io::ImageRequest: 0x7f346f7fa340 send_object_requests: rbd_data.382ddd2b0949.0000000000000004 0~4 from [0,4]
2021-11-21T07:11:55.483-0600 7f346f7fe700 20 librbd::io::Dispatcher: 0x7f342c0382c0 send: dispatch_spec=0x7f345c060b50
2021-11-21T07:11:55.483-0600 7f346f7fe700 20 librbd::cache::WriteAroundObjectDispatch: 0x7f345c014b40 write: rbd_data.382ddd2b0949.0000000000000004 0~4
2021-11-21T07:11:55.483-0600 7f346f7fe700 20 librbd::crypto::CryptoObjectDispatch: 0x7f345c00d330 write: rbd_data.382ddd2b0949.0000000000000004 0~4

#19 Updated by Deepika Upadhyay over 2 years ago

  • Related to Bug #53108: [pwl] TestMigration.Stress* failure with pwl cache added

#20 Updated by Deepika Upadhyay over 2 years ago

  • Status changed from New to Resolved

Also available in: Atom PDF