Ceph » RADOS

2019-07-12T06:59:36.562 INFO:tasks.workunit.client.0.smithi019.stdout:                   api_io: [ RUN      ] LibRadosIoPP.TruncTestPP
2019-07-12T06:59:36.563 INFO:tasks.workunit.client.0.smithi019.stdout:                   api_io: [       OK ] LibRadosIoPP.TruncTestPP (17 ms)
2019-07-12T06:59:36.563 INFO:tasks.workunit.client.0.smithi019.stdout:                   api_io: [ RUN      ] LibRadosIoPP.RemoveTestPP
2019-07-12T06:59:37.397 INFO:tasks.workunit.client.0.smithi019.stdout:                   api_io: [       OK ] LibRadosIoPP.RemoveTestPP (7    delete_pools_parallel: process_1_[9896]: starting.

Still working on this but steps to reproduce...

$ cat << EOF >> orig.config.yaml                                                                                                                                                                                        
interactive-on-error: true
$(tail -n+2 /a/teuthology-2019-07-24_06:00:03-smoke-mimic-testing-basic-smithi/4144267/orig.config.yaml)
EOF

$ rm -rf ~/working/archive/* ;teuthology -v -a ~/working/archive/ --lock orig.config.yaml

Make sure ~/working/archive/ exists.

NOTE: You might need to change machine-type to "mira" if there are no smithis available (that's what I did so maybe just change it anyway?).

Try to take note of the machines that are being used. I just scanned the output for them but there's probably better ways. Let it get to the point where it's running the tests and then log onto each machine (or all at once) and run the following.

$ ps auwwx|grep ceph_test_rados_api_io

Eventually you'll find the process we want to investigate and it will hang around for a long time so you don't have to hurry much. You can also kill the task that started it and I think that will stop it from killing it.

I grabbed a gcore and I'm currently looking at that.

Looking at a live process it doesn't seem to be a deadlock or "hang" but more like some sort of livelock where the 'msgr-worker-1' thread is chewing the CPU and the 'ms_dispatch' and 'log' threads using a little bit of cpu as well.

top - 09:48:20 up  3:14,  1 user,  load average: 0.06, 0.12, 0.11
Threads: 175 total,   1 running, 120 sleeping,   0 stopped,   0 zombie
%Cpu(s):  0.8 us,  1.7 sy,  0.0 ni, 95.7 id,  0.0 wa,  0.0 hi,  1.8 si,  0.0 st
KiB Mem : 16402184 total, 14600708 free,   220520 used,  1580956 buff/cache
KiB Swap:  2097148 total,  2097148 free,        0 used. 15842512 avail Mem 

    PID USER      PR  NI    VIRT    RES    SHR S %CPU %MEM     TIME+ COMMAND                                                                                                                                                                
  10612 ubuntu    20   0 1186956  26604  16680 S  9.6  0.2  20:17.43 msgr-worker-1                                                                                                                                                          
  10624 ubuntu    20   0 1186956  26604  16680 S  1.7  0.2   3:40.29 ms_dispatch                                                                                                                                                            
  10603 ubuntu    20   0 1186956  26604  16680 S  1.0  0.2   2:01.56 log

$ ps axHo stat,pid,tid,pgid,ppid,comm,wchan|grep 9524
Sl      9524    9524    9503    9519 ceph_test_rados -
Sl      9524   10603    9503    9519 log             -
Sl      9524   10611    9503    9519 msgr-worker-0   epoll_wait
Sl      9524   10612    9503    9519 msgr-worker-1   epoll_wait
Sl      9524   10613    9503    9519 msgr-worker-2   epoll_wait
Sl      9524   10621    9503    9519 service         -
Sl      9524   10622    9503    9519 admin_socket    x64_sys_poll
Sl      9524   10623    9503    9519 ceph_test_rados -
Sl      9524   10624    9503    9519 ms_dispatch     -
Sl      9524   10625    9503    9519 ms_local        -
Sl      9524   10626    9503    9519 safe_timer      -
Sl      9524   10627    9503    9519 fn_anonymous    -
Sl      9524   10628    9503    9519 safe_timer      -
Sl      9524   10629    9503    9519 safe_timer      -
Sl      9524   10630    9503    9519 fn-radosclient  -

I dumped out the log (500 lines, attached) almost exclusively this sequence so we're not communicating with osd.3.

2019-07-26 16:52:59.098856 thread: 0x7f5a9fa29700 priority: 0 subsystem: 27 bad crc in data 1465487574 != exp 1041109653 from 172.21.4.108:6804/10042
2019-07-26 16:52:59.098856 thread: 0x7f5a9e226700 priority: 1 subsystem: 14 client.4580.objecter ms_handle_reset 0x7f5a8c01f0f0 session 0x55855d9cc5f0 osd.3
2019-07-26 16:52:59.106857 thread: 0x7f5a9fa29700 priority: 0 subsystem: 27 bad crc in data 1465487574 != exp 1041109653 from 172.21.4.108:6804/10042
2019-07-26 16:52:59.106857 thread: 0x7f5a9e226700 priority: 1 subsystem: 14 client.4580.objecter ms_handle_reset 0x7f5a8c01b7a0 session 0x55855d9cc5f0 osd.3
2019-07-26 16:52:59.110857 thread: 0x7f5a9fa29700 priority: 0 subsystem: 27 bad crc in data 1465487574 != exp 1041109653 from 172.21.4.108:6804/10042
2019-07-26 16:52:59.114857 thread: 0x7f5a9e226700 priority: 1 subsystem: 14 client.4580.objecter ms_handle_reset 0x7f5a8c01f0f0 session 0x55855d9cc5f0 osd.3
2019-07-26 16:52:59.118857 thread: 0x7f5a9fa29700 priority: 0 subsystem: 27 bad crc in data 1465487574 != exp 1041109653 from 172.21.4.108:6804/10042
2019-07-26 16:52:59.118857 thread: 0x7f5a9e226700 priority: 1 subsystem: 14 client.4580.objecter ms_handle_reset 0x7f5a8c01b7a0 session 0x55855d9cc5f0 osd.3
2019-07-26 16:52:59.126857 thread: 0x7f5a9fa29700 priority: 0 subsystem: 27 bad crc in data 1465487574 != exp 1041109653 from 172.21.4.108:6804/10042
2019-07-26 16:52:59.126857 thread: 0x7f5a9e226700 priority: 1 subsystem: 14 client.4580.objecter ms_handle_reset 0x7f5a8c01f0f0 session 0x55855d9cc5f0 osd.3

For the time being you can get the coredump from https://people.redhat.com/~bhubbard/core.9524.gz and osd.3's log at https://people.redhat.com/~bhubbard/ceph-osd.3.log.gz in case someone wants to carry on :)

From the osd log it looks like the client is just retrying a read over and over again and keeps failing.

The 10612 and main thread look like this so they match up with what the logs are saying I guess.

Thread 4 (Thread 0x7f5a9fa29700 (LWP 10612)):
#0  0x00007f5aa50dbbb7 in epoll_wait (epfd=7, events=0x55855d9b13a0, maxevents=5000, timeout=30000) at ../sysdeps/unix/sysv/linux/epoll_wait.c:30
#1  0x00007f5aa5fc475e in EpollDriver::event_wait (this=0x55855d9878d0, fired_events=std::vector of length 0, capacity 0, tvp=<optimized out>) at ./src/msg/async/EventEpoll.cc:122
#2  0x00007f5aa5d81f57 in EventCenter::process_events(unsigned int, std::chrono::duration<unsigned long, std::ratio<1l, 1000000000l> >*) () at ./src/msg/async/Event.cc:401
#3  0x00007f5aa5d84da6 in NetworkStack::<lambda()>::operator() (__closure=0x55855da9b8b8, __closure=0x55855da9b8b8) at ./src/msg/async/Stack.cc:53
#4  std::_Function_handler<void (), NetworkStack::add_thread(unsigned int)::{lambda()#1}>::_M_invoke(std::_Any_data const&) () at /usr/include/c++/8/bits/std_function.h:297
#5  0x00007f5aa568066f in ?? () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
#6  0x00007f5aae9736db in start_thread (arg=0x7f5a9fa29700) at pthread_create.c:463
#7  0x00007f5aa50db88f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Thread 1 (Thread 0x7f5aaed93fc0 (LWP 9524)):
#0  0x00007f5aae9799f3 in futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x7ffd318fb340) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
#1  __pthread_cond_wait_common (abstime=0x0, mutex=0x7ffd318fb378, cond=0x7ffd318fb318) at pthread_cond_wait.c:502
#2  __pthread_cond_wait (cond=cond@entry=0x7ffd318fb318, mutex=mutex@entry=0x7ffd318fb378) at pthread_cond_wait.c:655
#3  0x00007f5aae6b0fd6 in Cond::Wait (this=this@entry=0x7ffd318fb310, mutex=...) at ./src/common/Cond.h:48
#4  0x00007f5aae6a957f in librados::IoCtxImpl::operate_read(object_t const&, ObjectOperation*, ceph::buffer::list*, int) () at ./src/librados/IoCtxImpl.cc:754
#5  0x00007f5aae6692b9 in librados::IoCtx::operate(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, librados::ObjectReadOperation*, ceph::buffer::list*) () at ./src/librados/librados.cc:1521
#6  0x000055855cc20e60 in LibRadosIoPP_CmpExtPP_Test::TestBody() () at /usr/include/c++/8/ext/new_allocator.h:79
#7  0x000055855cc6333a in testing::internal::HandleSehExceptionsInMethodIfSupported<testing::Test, void> (location=0x55855cc8361c "the test body", method=<optimized out>, object=0x55855da02950)
    at ./src/googletest/googletest/src/gtest.cc:2383
#8  testing::internal::HandleExceptionsInMethodIfSupported<testing::Test, void> (object=object@entry=0x55855da02950, method=<optimized out>, location=location@entry=0x55855cc8361c "the test body")
    at ./src/googletest/googletest/src/gtest.cc:2438
#9  0x000055855cc5935a in testing::Test::Run (this=0x55855da02950) at ./src/googletest/googletest/src/gtest.cc:2474
#10 0x000055855cc594a8 in testing::TestInfo::Run (this=0x55855d95a6b0) at ./src/googletest/googletest/src/gtest.cc:2656
#11 0x000055855cc59585 in testing::TestCase::Run (this=0x55855d935e90) at ./src/googletest/googletest/src/gtest.cc:2774
#12 0x000055855cc59aa4 in testing::internal::UnitTestImpl::RunAllTests() () at /usr/include/c++/8/bits/stl_vector.h:930
#13 0x000055855cc6381a in testing::internal::HandleSehExceptionsInMethodIfSupported<testing::internal::UnitTestImpl, bool> (location=0x55855cc84860 "auxiliary test code (environments or event listeners)", method=<optimized out>, 
    object=0x55855d93aad0) at ./src/googletest/googletest/src/gtest.cc:2383
#14 testing::internal::HandleExceptionsInMethodIfSupported<testing::internal::UnitTestImpl, bool> (object=0x55855d93aad0, method=<optimized out>, 
    location=location@entry=0x55855cc84860 "auxiliary test code (environments or event listeners)") at ./src/googletest/googletest/src/gtest.cc:2438
#15 0x000055855cc59bbd in testing::UnitTest::Run() () at ./src/googletest/googletest/include/gtest/gtest.h:1287
#16 0x000055855cc1aff9 in RUN_ALL_TESTS () at ./src/googletest/googletest/include/gtest/gtest.h:2233
#17 main (argc=<optimized out>, argv=0x7ffd318fb928) at ./src/googletest/googlemock/src/gmock_main.cc:53

Client:

2019-07-30 23:49:44.351 7fe779d6d700 20 -- 127.0.0.1:0/2016699731 >> 127.0.0.1:6805/5820 conn(0x5643de7b1540 :-1 s=STATE_OPEN pgs=4 cs=1 l=1).prepare_send_message encoding features 4611087854031667195 0x5643de78af10 osd_op(client.14126.   ⤷ 0:59 2.5 2:b3a108dd:test-rados-api-mira110-6042-31::foo:head [read 0~4] snapc 0=[] ondisk+read+known_if_redirected e21) v8
2019-07-30 23:49:44.351 7fe779d6d700 20 -- 127.0.0.1:0/2016699731 >> 127.0.0.1:6805/5820 conn(0x5643de7b1540 :-1 s=STATE_OPEN pgs=4 cs=1 l=1).write_message signed m=0x5643de78af10): sig = 10196077939576485518
2019-07-30 23:49:44.351 7fe779d6d700 20 -- 127.0.0.1:0/2016699731 >> 127.0.0.1:6805/5820 conn(0x5643de7b1540 :-1 s=STATE_OPEN pgs=4 cs=1 l=1).write_message sending message type=42 src client.14126 front=242 data=0 off 0
2019-07-30 23:49:44.351 7fe779d6d700 20 -- 127.0.0.1:0/2016699731 >> 127.0.0.1:6805/5820 conn(0x5643de7b1540 :-1 s=STATE_OPEN pgs=4 cs=1 l=1).write_message sending 30 0x5643de78af10
2019-07-30 23:49:44.351 7fe779d6d700 10 -- 127.0.0.1:0/2016699731 >> 127.0.0.1:6805/5820 conn(0x5643de7b1540 :-1 s=STATE_OPEN pgs=4 cs=1 l=1)._try_send sent bytes 317 remaining bytes 0
2019-07-30 23:49:44.351 7fe779d6d700 10 -- 127.0.0.1:0/2016699731 >> 127.0.0.1:6805/5820 conn(0x5643de7b1540 :-1 s=STATE_OPEN pgs=4 cs=1 l=1).write_message sending 0x5643de78af10 done.
2019-07-30 23:49:44.351 7fe779d6d700 20 -- 127.0.0.1:0/2016699731 >> 127.0.0.1:6805/5820 conn(0x5643de7b1540 :-1 s=STATE_OPEN pgs=4 cs=1 l=1).process prev state is STATE_OPEN
2019-07-30 23:49:44.352 7fe779d6d700 20 -- 127.0.0.1:0/2016699731 >> 127.0.0.1:6805/5820 conn(0x5643de7b1540 :-1 s=STATE_OPEN_MESSAGE_HEADER pgs=4 cs=1 l=1).process prev state is STATE_OPEN
2019-07-30 23:49:44.352 7fe779d6d700 20 -- 127.0.0.1:0/2016699731 >> 127.0.0.1:6805/5820 conn(0x5643de7b1540 :-1 s=STATE_OPEN_MESSAGE_HEADER pgs=4 cs=1 l=1).process begin MSG
2019-07-30 23:49:44.352 7fe779d6d700 20 -- 127.0.0.1:0/2016699731 >> 127.0.0.1:6805/5820 conn(0x5643de7b1540 :-1 s=STATE_OPEN_MESSAGE_HEADER pgs=4 cs=1 l=1).process got MSG header
2019-07-30 23:49:44.352 7fe779d6d700 20 -- 127.0.0.1:0/2016699731 >> 127.0.0.1:6805/5820 conn(0x5643de7b1540 :-1 s=STATE_OPEN_MESSAGE_HEADER pgs=4 cs=1 l=1).process got envelope type=43 src osd.1 front=147 data=4 off 0
2019-07-30 23:49:44.352 7fe779d6d700 20 -- 127.0.0.1:0/2016699731 >> 127.0.0.1:6805/5820 conn(0x5643de7b1540 :-1 s=STATE_OPEN_MESSAGE_THROTTLE_MESSAGE pgs=4 cs=1 l=1).process prev state is STATE_OPEN_MESSAGE_HEADER
2019-07-30 23:49:44.352 7fe779d6d700 20 -- 127.0.0.1:0/2016699731 >> 127.0.0.1:6805/5820 conn(0x5643de7b1540 :-1 s=STATE_OPEN_MESSAGE_THROTTLE_BYTES pgs=4 cs=1 l=1).process prev state is STATE_OPEN_MESSAGE_THROTTLE_MESSAGE
2019-07-30 23:49:44.352 7fe779d6d700 20 -- 127.0.0.1:0/2016699731 >> 127.0.0.1:6805/5820 conn(0x5643de7b1540 :-1 s=STATE_OPEN_MESSAGE_THROTTLE_DISPATCH_QUEUE pgs=4 cs=1 l=1).process prev state is STATE_OPEN_MESSAGE_THROTTLE_BYTES
2019-07-30 23:49:44.352 7fe779d6d700 20 -- 127.0.0.1:0/2016699731 >> 127.0.0.1:6805/5820 conn(0x5643de7b1540 :-1 s=STATE_OPEN_MESSAGE_READ_FRONT pgs=4 cs=1 l=1).process prev state is STATE_OPEN_MESSAGE_THROTTLE_DISPATCH_QUEUE
2019-07-30 23:49:44.352 7fe779d6d700 20 -- 127.0.0.1:0/2016699731 >> 127.0.0.1:6805/5820 conn(0x5643de7b1540 :-1 s=STATE_OPEN_MESSAGE_READ_FRONT pgs=4 cs=1 l=1).process got front 147
2019-07-30 23:49:44.352 7fe779d6d700 10 -- 127.0.0.1:0/2016699731 >> 127.0.0.1:6805/5820 conn(0x5643de7b1540 :-1 s=STATE_OPEN_MESSAGE_READ_DATA_PREPARE pgs=4 cs=1 l=1).process seleting rx buffer v 2 at offset 0 len 4
2019-07-30 23:49:44.352 7fe779d6d700 10 -- 127.0.0.1:0/2016699731 >> 127.0.0.1:6805/5820 conn(0x5643de7b1540 :-1 s=STATE_OPEN_MESSAGE_READ_FOOTER_AND_DISPATCH pgs=4 cs=1 l=1).process aborted = 0
2019-07-30 23:49:44.352 7fe779d6d700 20 -- 127.0.0.1:0/2016699731 >> 127.0.0.1:6805/5820 conn(0x5643de7b1540 :-1 s=STATE_OPEN_MESSAGE_READ_FOOTER_AND_DISPATCH pgs=4 cs=1 l=1).process got 147 + 0 + 4 byte message
2019-07-30 23:49:44.352 7fe779d6d700  0 bad crc in data 1465487574 != exp 1041109653 from 127.0.0.1:6805/5820
2019-07-30 23:49:44.352 7fe779d6d700 20  00000000  43 45 50 48                                       |CEPH|                                                                                                                                  
00000004

2019-07-30 23:49:44.352 7fe779d6d700  1 -- 127.0.0.1:0/2016699731 >> 127.0.0.1:6805/5820 conn(0x5643de7b1540 :-1 s=STATE_OPEN_MESSAGE_READ_FOOTER_AND_DISPATCH pgs=4 cs=1 l=1).process decode message failed·

OSD:

2019-07-30 23:49:44.351 7f4e49124700  1 -- 127.0.0.1:6805/5820 --> 127.0.0.1:0/2016699731 -- osd_op_reply(59 foo [read 0~4] v0'0 uv3 ondisk = 0) v8 -- 0x55927bd2d080 con 0                                                                  
2019-07-30 23:49:44.351 7f4e49124700 15 -- 127.0.0.1:6805/5820 >> 127.0.0.1:0/2016699731 conn(0x55927ba8de00 :6805 s=STATE_OPEN pgs=5 cs=1 l=1).send_message inline write is denied, reschedule m=0x55927bd2d080                             
2019-07-30 23:49:44.351 7f4e49124700 20 Event(0x55927b4b3c80 nevent=5000 time_id=7).wakeup                                                                                                                                                   
2019-07-30 23:49:44.351 7f4e49124700 10 osd.1 21 dequeue_op 0x55927be1f680 finish                                                                                                                                                            
2019-07-30 23:49:44.351 7f4e49124700 20 osd.1 op_wq(0) _process empty q, waiting                                                                                                                                                             
2019-07-30 23:49:44.351 7f4e65bd1700 10 -- 127.0.0.1:6805/5820 >> 127.0.0.1:0/2016699731 conn(0x55927ba8de00 :6805 s=STATE_OPEN pgs=5 cs=1 l=1).handle_write                                                                                 
2019-07-30 23:49:44.351 7f4e65bd1700 20 -- 127.0.0.1:6805/5820 >> 127.0.0.1:0/2016699731 conn(0x55927ba8de00 :6805 s=STATE_OPEN pgs=5 cs=1 l=1).prepare_send_message m osd_op_reply(59 foo [read 0~4] v0'0 uv3 ondisk = 0) v8                
2019-07-30 23:49:44.351 7f4e65bd1700 20 -- 127.0.0.1:6805/5820 >> 127.0.0.1:0/2016699731 conn(0x55927ba8de00 :6805 s=STATE_OPEN pgs=5 cs=1 l=1).prepare_send_message encoding features 4611087854031667195 0x55927bd2d080 osd_op_reply(59      ⤷ foo [read 0~4] v0'0 uv3 ondisk = 0) v8                                                       
2019-07-30 23:49:44.351 7f4e65bd1700 20 -- 127.0.0.1:6805/5820 >> 127.0.0.1:0/2016699731 conn(0x55927ba8de00 :6805 s=STATE_OPEN pgs=5 cs=1 l=1).write_message signed m=0x55927bd2d080): sig = 2555750077203053029                            
2019-07-30 23:49:44.351 7f4e65bd1700 20 -- 127.0.0.1:6805/5820 >> 127.0.0.1:0/2016699731 conn(0x55927ba8de00 :6805 s=STATE_OPEN pgs=5 cs=1 l=1).write_message sending message type=43 src osd.1 front=147 data=4 off 0                       
2019-07-30 23:49:44.351 7f4e65bd1700 20 -- 127.0.0.1:6805/5820 >> 127.0.0.1:0/2016699731 conn(0x55927ba8de00 :6805 s=STATE_OPEN pgs=5 cs=1 l=1).write_message sending 30 0x55927bd2d080                                                      
2019-07-30 23:49:44.351 7f4e65bd1700 10 -- 127.0.0.1:6805/5820 >> 127.0.0.1:0/2016699731 conn(0x55927ba8de00 :6805 s=STATE_OPEN pgs=5 cs=1 l=1)._try_send sent bytes 226 remaining bytes 0                                                   
2019-07-30 23:49:44.351 7f4e65bd1700 10 -- 127.0.0.1:6805/5820 >> 127.0.0.1:0/2016699731 conn(0x55927ba8de00 :6805 s=STATE_OPEN pgs=5 cs=1 l=1).write_message sending 0x55927bd2d080 done.                                                   
2019-07-30 23:49:44.352 7f4e65bd1700 20 -- 127.0.0.1:6805/5820 >> 127.0.0.1:0/2016699731 conn(0x55927ba8de00 :6805 s=STATE_OPEN pgs=5 cs=1 l=1).process prev state is STATE_OPEN                                                             
2019-07-30 23:49:44.352 7f4e65bd1700  1 -- 127.0.0.1:6805/5820 >> 127.0.0.1:0/2016699731 conn(0x55927ba8de00 :6805 s=STATE_OPEN pgs=5 cs=1 l=1).read_bulk peer close file descriptor 53                                                      
2019-07-30 23:49:44.352 7f4e65bd1700  1 -- 127.0.0.1:6805/5820 >> 127.0.0.1:0/2016699731 conn(0x55927ba8de00 :6805 s=STATE_OPEN pgs=5 cs=1 l=1).read_until read failed                                                                       
2019-07-30 23:49:44.352 7f4e65bd1700  1 -- 127.0.0.1:6805/5820 >> 127.0.0.1:0/2016699731 conn(0x55927ba8de00 :6805 s=STATE_OPEN pgs=5 cs=1 l=1).process read tag failed                                                                      
2019-07-30 23:49:44.352 7f4e65bd1700  1 -- 127.0.0.1:6805/5820 >> 127.0.0.1:0/2016699731 conn(0x55927ba8de00 :6805 s=STATE_OPEN pgs=5 cs=1 l=1).fault on lossy channel, failing                                                              
2019-07-30 23:49:44.352 7f4e65bd1700  2 -- 127.0.0.1:6805/5820 >> 127.0.0.1:0/2016699731 conn(0x55927ba8de00 :6805 s=STATE_OPEN pgs=5 cs=1 l=1)._stop                                                                                        
2019-07-30 23:49:44.352 7f4e65bd1700 10 -- 127.0.0.1:6805/5820 >> 127.0.0.1:0/2016699731 conn(0x55927ba8de00 :6805 s=STATE_OPEN pgs=5 cs=1 l=1).discard_out_queue started

Ok, slowly closing in on this I think.

bad crc in data 1465487574 != exp 1041109653 from 172.21.4.108:6804/10042

That's our error seen during the execution (specifically when doing the read) of the "LibRadosIoPP.CmpExtPP" test which looks like this.

TEST_F(LibRadosIoPP, CmpExtPP) {
  bufferlist bl;
  bl.append("ceph");
  ObjectWriteOperation write1;
  write1.write(0, bl);
  ASSERT_EQ(0, ioctx.operate("foo", &write1));

  bufferlist new_bl;
  new_bl.append("CEPH");
  ObjectWriteOperation write2;
  write2.cmpext(0, bl, nullptr);
  write2.write(0, new_bl);
  ASSERT_EQ(0, ioctx.operate("foo", &write2));

  ObjectReadOperation read;
  read.read(0, bl.length(), NULL, NULL);
  ASSERT_EQ(0, ioctx.operate("foo", &read, &bl));
  ASSERT_EQ(0, memcmp(bl.c_str(), "CEPH", 4));
}

Now if we build and execute the following code.

#include "include/rados/librados.h" 
#include "include/rados/librados.hpp" 
#include <iostream>

using namespace std;
using namespace librados;

int main()
{
  bufferlist bl1, bl2;
  bl1.append("ceph");
  bl2.append("CEPH");
  cout << bl1.c_str() << " = " << bl1.crc32c(0) << std::endl;
  cout << bl2.c_str() << " = " << bl2.crc32c(0) << std::endl;
}

We get this output.

ceph = 1465487574
CEPH = 1041109653

So it looks like we expected the checksum for "CEPH" but got the checksum for "ceph". So what did we actually read?

2019-07-30 23:49:44.352 7fe779d6d700  0 bad crc in data 1465487574 != exp 1041109653 from 127.0.0.1:6805/5820
2019-07-30 23:49:44.352 7fe779d6d700 20  00000000  43 45 50 48                                       |CEPH|

We read "CEPH" so the next question is why would footer.data_crc contain the checksum for "ceph"? Do we have some cache for the checksum that we haven't invalidated when we do the second write?

Simplified test case.

#include "include/rados/librados.h" 
#include "include/rados/librados.hpp" 
#include <iostream>

using namespace std;
using namespace librados;

int main()
{
  Rados rados;
  rados.init("admin");          
  rados.conf_parse_env(NULL);
  rados.conf_read_file(NULL);
  rados.connect();      
  rados.pool_create("test-pool");
  IoCtx ioctx;
  rados.ioctx_create("test-pool", ioctx);

  bufferlist bl;
  bl.append("ceph");
  ObjectWriteOperation write1;
  write1.write(0, bl);
  ioctx.operate("foo", &write1);

  bufferlist new_bl;
  new_bl.append("CEPH");
  ObjectWriteOperation write2;
  write2.write(0, new_bl);
  ioctx.operate("foo", &write2);

  ObjectReadOperation read;
  read.read(0, bl.length(), NULL, NULL);
  ioctx.operate("foo", &read, &bl);
  cout << bl.c_str() << endl;
}

Suspect also in => http://pulpito.ceph.com/teuthology-2019-08-01_02:25:03-upgrade:luminous-x-mimic-distro-basic-smithi/

I was discussing this with Josh Durgin and he noticed the reuse of the bufferlist for the read and mentioned we'd had problems with buffer reuse in the past. Sure enough testing with a new buffer for the read works as does adding "bl.invalidate_crc();" just before the read. I believe the problem is related to some crc caching code in buffer::list::crc32c but I'm still looking into the specifics. Of course a simple fix for the test would be to not reuse the write buffer for the read, but that would be cheating right? ;)

Correcting my statement in comment #12.

    313       __u32 data_crc = data.crc32c(0);
    314       if (data_crc != footer.data_crc) {
    315         if (cct) {
    316           ldout(cct, 0) << "bad crc in data " << data_crc << " != exp " << footer.data_crc << dendl;

We read "CEPH" and footer.data_crc contains 1041109653, which is the correct crc for "CEPH" but ceph::buffer::list::crc32c (called on line 313) returns a cached crc for "ceph" (1465487574). This is because we don't invalidate the crc when we re-use the buffer in AsyncConnection::process(). I have a solution and should have a PR after I test it.