Ceph » Linux kernel client

<4>[48385.225000] CPU: 0 PID: 22717 Comm: kworker/0:0 Not tainted 4.14.19-coreos #1

filename:       /lib/modules/4.14.32-coreos/kernel/net/ceph/libceph.ko

maybe not, i had this errors on 3 machines,
but i noticed the error checking the logs after an update, will let you know if this happens again with kernel 4.14.32

Can you describe what the workload is -- it looks like this is cephfs? Are those "osd up/down" and "session lost" messages still present? If so, do you see the corresponding "osd up/down" messages in the cluster log?

It looks like CoreOS buildbot compiler is doing some really weird inlining. The backtrace doesn't make any sense: ceph_msg_new() is not what gets run on ceph-msgr workqueue. The only other instance of such a crappy backtrace in the tracker is http://tracker.ceph.com/issues/14360, so it's definitely a CoreOS kernel "feature".

That said, I managed to find what I hope is the correct kernel module and "ceph_msg_new+0x108e/0x2470" appears to be the call to kernel_sendmsg() in ceph_tcp_sendmsg(). What we are looking at is probably

  con_work
    try_write
      write_partial_kvec
        ceph_tcp_sendmsg
          kernel_sendmsg

Ilya Dryomov wrote:

That said, I managed to find what I hope is the correct kernel module and "ceph_msg_new+0x108e/0x2470" appears to be the call to kernel_sendmsg() in ceph_tcp_sendmsg(). What we are looking at is probably
[...]where ceph_tcp_sendmsg() got called with a NULL sock, meaning that con->sock was NULL all along, but that is just a guess.

That's my finding too. It came in via con->sock.

@Ilya Dryomov
the woarkload is very very low, osd up/down seems to happen from time to time on read and write, but the session lost message occurs every 30s or less.
In cluster logs only "cluster [INF] overall HEALTH_OK" during same time periods.

Do you see "session lost" on every machine you mount cephfs on or on just some of them?

The "session lost" is logged on every (3) machines.
It seems to start when a monitor came down then up or is replaced by an other.

I mount cephfs using a DNS record with A entries automatically populated with monitors IPs.
Cephfs is mounted about 50 times with several paths by kubernetes for about 50 containers with very low activities.

The weird thing is that the session is lost on IPs corresponding to monitors that or totally fine (not down then up or replaced).

Ilya Dryomov wrote:

[...]where ceph_tcp_sendmsg() got called with a NULL sock, meaning that con->sock was NULL all along, but that is just a guess.

Maybe. I'll note that con_close_socket() also sets con->sock to NULL. Is it possible that a call to that raced in somehow?

Yeah:

cancel_con calls cancel_delayed_work, but that can return while the work is still running. So, suppose a call to ceph_con_close races in just before ceph_con_workfn runs, takes the mutex and closes the socket, setting con->sock to NULL and clearing CON_FLAG_SOCK_CLOSED.

Eventually the mutex is dropped, and ceph_con_workfn runs, and hits the null ptr deref here. There is a call to con_sock_closed but that flag gets cleared in con_close. I think that check needs to be re-thought.

@Ilya
I guess this is a bad thing but the monitors are run in containers, one on each machine.
Times to times we stop the containers to perform a coreos update.

When the container is restarted the mon came up again,
but when it fail we just delete the container and create a new one to replace it and this become a new mon for ceph.

We meet the same panic:

=================

2129 [11093.424272] Call Trace:
2130 [11093.424438] [<ffffffffa050dea5>] ? ceph_tcp_recvmsg+0x55/0x80 [libceph]
2131 [11093.424614] [<ffffffffa0520a4f>] ? dispatch+0x5f/0x470 [libceph]
2132 [11093.424782] [<ffffffff81555147>] kernel_sendmsg+0x37/0x50
2133 [11093.424951] [<ffffffffa050df29>] ceph_tcp_sendmsg+0x59/0x80 [libceph]
2134 [11093.425124] [<ffffffffa050ffa9>] try_write+0x279/0xe60 [libceph]
2135 [11093.425293] [<ffffffff810cbcdc>] ? set_next_entity+0x3c/0xe0
2136 [11093.425464] [<ffffffffa0512d29>] ceph_con_workfn+0xc9/0x650 [libceph]
2137 [11093.425634] [<ffffffff810a7f3b>] process_one_work+0x17b/0x470
2138 [11093.425800] [<ffffffff810a8d76>] worker_thread+0x126/0x410
2139 [11093.425966] [<ffffffff810a8c50>] ? rescuer_thread+0x460/0x460
2140 [11093.426133] [<ffffffff810b052f>] kthread+0xcf/0xe0
2141 [11093.426298] [<ffffffff810b0460>] ? kthread_create_on_node+0x140/0x140
2142 [11093.426467] [<ffffffff81696418>] ret_from_fork+0x58/0x90
2143 [11093.426633] [<ffffffff810b0460>] ? kthread_create_on_node+0x140/0x140
2144 [11093.426800] Code: c0 75 33 48 8b 84 24 c0 00 00 00 4c 89 f1 4c 89 ea 4c 89 e6 48 89 df 4c 89 60 18 48 c7 40 28 00 00 00 00 4c 89 68 30 44 89 70 14 <4 9> 8b 44 24 28 ff 90 88 00 00 00 3d ef fd ff ff 74 29 48 8b 8c
2145 [11093.427517] RIP [<ffffffff815550c5>] sock_sendmsg+0xa5/0xf0

2103 [11093.418995] BUG: unable to handle kernel NULL pointer dereference at 0000000000000028
2104 [11093.419024] IP: [<ffffffff815550c5>] sock_sendmsg+0xa5/0xf0
2105 [11093.419046] PGD 0

2110 [11093.420165] Hardware name: OEM PR4036TG/SC612DI-8F, BIOS 2.0b 06/09/2017
2111 [11093.420343] Workqueue: ceph-msgr ceph_con_workfn [libceph]
2112 [11093.420511] task: ffff880fbac2de20 ti: ffff880ee4b38000 task.ti: ffff880ee4b38000
2113 [11093.420826] RIP: 0010:[<ffffffff815550c5>] [<ffffffff815550c5>] sock_sendmsg+0xa5/0xf0

==============================

ceph_con_close : 
1) set connection flag CON_STATE_CLOSED 
2) delay connect works to ceph_con_workfn's queue 
3) con_close_socket  close connection->sock, clear CON_STATE_CLOSED

step 2 is async, if step 3 is early run ceph_con_workfn execute the works with cancel_connection,
the ceph_con_workfn found flag is cleared, will do the try_write method use the already set to null ptr session->sock?

did it like happen to this ?

ceph_con_workfn will continue to do the below if no flag settled in connections?

write_partial_kvec
ceph_tcp_sendmsg

I'm working on a fix. What I'm wondering is why has it popped up now and not in the past.

Yong, which kernel is that? Do you also see "session lost, hunting for new mon" or something similar in dmesg?

os centos 7.3 kernel version 3.10.514
not found session lost near the panic timestamp
libceph print a lot of osds up and down

which maybe happened we have done a performance testing ，
in that env，if some osds down which detected by our monitor shell process，the。sh will restart it by systemctl restart.

which restart operations maybe many times

Bertrand, Yong, what is the output of

ceph daemon mon.a config get ms_type
ceph daemon osd.0 config get ms_type

Thanks i will follow #23537 :)

I must have some serious config error when i run

ceph daemon mon.a config get ms_type
or
ceph daemon osd.0 config get ms_type

i have this error :

admin_socket: exception getting command descriptions: [Errno 2] No such file or directory

so i just run on one mon and one osd command like :

ceph --admin-daemon /var/run/ceph/[...].asok config get ms_type

not sure if this is the same as what you whant ?

result on mon:

{
    "ms_type": "async+posix" 
}

result on osd:

{
    "ms_type": "async+posix" 
}

Yes, I wanted to make sure you were using async messenger.

I'm still looking into the crash. Did it happen just once or did you see it more than once?

Can you share what proceeded "<1>[48385.115715] BUG: unable to handle kernel NULL pointer dereference at 0000000000000020" in the kernel log? 100-200 lines at least.

It happened at least 9 times (from Jan 8 to Mar 31), i have only 3 last crash logs on the 3 servers.

<6>[33859.830433] libceph: osd1 up
<6>[33859.833683] libceph: osd2 down
<6>[33859.837099] libceph: osd2 up
<6>[33859.840330] libceph: osd0 down
<6>[33859.843754] libceph: osd0 up
<6>[33859.847145] libceph: osd1 down
<6>[33859.850626] libceph: osd1 up
<6>[33859.853872] libceph: osd0 down
<6>[33859.857284] libceph: osd0 up
<6>[33859.860532] libceph: osd2 down
<6>[33859.863990] libceph: osd2 up
<6>[33859.867230] libceph: osd1 down
<6>[33859.870656] libceph: osd1 up
<6>[33859.873896] libceph: osd0 down
<6>[33859.877327] libceph: osd0 up
<6>[33859.880551] libceph: osd2 down
<6>[33859.884045] libceph: osd2 up
<6>[34200.599876] libceph: osd1 down
<6>[34205.260202] libceph: osd0 down
<6>[34205.263644] libceph: osd1 up
<6>[34211.300661] libceph: osd0 up
<6>[34413.401422] libceph: osd1 down
<6>[34413.404841] libceph: osd0 down
<6>[34413.408291] libceph: osd1 up
<6>[34413.411539] libceph: osd0 up
<6>[34822.730351] libceph: osd2 down
<6>[34822.733804] libceph: osd2 up
<6>[35058.407999] libceph: osd2 down
<6>[35058.411415] libceph: osd2 up
<6>[35705.727712] libceph: osd1 down
<6>[35709.489983] libceph: osd1 up
<6>[35712.425469] libceph: osd0 down
<6>[35712.428871] libceph: osd0 up
<6>[35724.584535] libceph: osd1 down
<6>[35724.588091] libceph: osd1 up
<6>[35724.591372] libceph: osd0 down
<6>[35724.594845] libceph: osd0 up
<6>[36317.309428] libceph: osd2 down
<6>[36324.126199] libceph: osd2 down
<6>[36324.129677] libceph: osd2 up
<6>[36349.212749] libceph: osd2 up
<6>[36915.934773] libceph: osd0 down
<6>[36918.521912] libceph: osd0 up
<6>[36938.439294] libceph: osd0 down
<6>[36938.442704] libceph: osd0 up
<6>[37210.876180] libceph: osd1 down
<6>[37214.554897] libceph: osd1 up
<6>[37263.439478] libceph: osd1 down
<6>[37263.442974] libceph: osd1 up
<6>[37834.500143] libceph: osd2 down
<6>[37834.503591] libceph: osd2 up
<6>[37888.449206] libceph: osd2 down
<6>[37888.452677] libceph: osd2 up
<6>[38421.706242] libceph: osd0 down
<6>[38424.732614] libceph: osd0 up
<6>[38523.456237] libceph: osd0 down
<6>[38523.459702] libceph: osd0 up
<6>[38716.146609] libceph: osd1 down
<6>[38720.889830] libceph: osd1 up
<6>[38843.462045] libceph: osd1 down
<6>[38843.465463] libceph: osd1 up
<6>[39334.635184] libceph: osd2 down
<6>[39334.638629] libceph: osd2 up
<6>[39468.470135] libceph: osd2 down
<6>[39468.473568] libceph: osd2 up
<6>[39926.861035] libceph: osd0 down
<6>[39931.974642] libceph: osd0 up
<6>[40103.477392] libceph: osd0 down
<6>[40103.480863] libceph: osd0 up
<6>[40221.345070] libceph: osd1 down
<6>[40227.073390] libceph: osd1 up
<6>[40413.486392] libceph: osd1 down
<6>[40413.489901] libceph: osd1 up
<6>[40839.636382] libceph: osd2 down
<6>[40839.639873] libceph: osd2 up
<6>[41048.494340] libceph: osd2 down
<6>[41048.497811] libceph: osd2 up
<6>[41433.012282] libceph: osd0 down
<6>[41433.015711] libceph: osd0 up
<6>[41683.502513] libceph: osd0 down
<6>[41683.505930] libceph: osd0 up
<6>[41726.393681] libceph: osd1 down
<6>[41729.349261] libceph: osd1 up
<6>[41993.503127] libceph: osd1 down
<6>[41993.506567] libceph: osd1 up
<6>[42345.145224] libceph: osd2 down
<6>[42345.148645] libceph: osd2 up
<6>[42359.480810] libceph: osd2 down
<6>[42359.484284] libceph: osd2 up
<6>[42632.125267] libceph: osd1 down
<6>[42637.144798] libceph: osd0 down
<6>[42637.148210] libceph: osd1 up
<6>[42640.181789] libceph: osd0 up
<6>[42646.576589] libceph: osd1 down
<6>[42646.580038] libceph: osd0 down
<6>[42646.583465] libceph: osd1 up
<6>[42646.586719] libceph: osd0 up
<6>[43251.370149] libceph: osd2 down
<6>[43251.373595] libceph: osd2 up
<6>[43268.530098] libceph: osd2 down
<6>[43268.533527] libceph: osd2 up
<6>[44136.495407] libceph: osd1 down
<6>[44141.339506] libceph: osd0 down
<6>[44141.342912] libceph: osd1 up
<6>[44145.306534] libceph: osd0 up
<6>[44218.536885] libceph: osd1 down
<6>[44218.540344] libceph: osd0 down
<6>[44218.543798] libceph: osd1 up
<6>[44218.547073] libceph: osd0 up
<6>[44751.047162] libceph: osd2 down
<6>[44751.050580] libceph: osd2 up
<6>[44848.544635] libceph: osd2 down
<6>[44848.548042] libceph: osd2 up
<6>[45341.653282] libceph: osd1 down
<6>[45345.619921] libceph: osd1 up
<6>[45483.555981] libceph: osd1 down
<6>[45483.559422] libceph: osd1 up
<6>[45647.459034] libceph: osd0 down
<6>[45651.835601] libceph: osd0 up
<6>[45803.557147] libceph: osd0 down
<6>[45803.560582] libceph: osd0 up
<6>[45959.552620] libceph: osd2 down
<6>[45959.556080] libceph: osd2 up
<6>[46118.566233] libceph: osd2 down
<6>[46118.569655] libceph: osd2 up
<6>[46846.651413] libceph: osd1 down
<6>[46852.309630] libceph: osd1 up
<6>[47063.576190] libceph: osd1 down
<6>[47063.579620] libceph: osd1 up
<6>[47152.066313] libceph: osd0 down
<6>[47157.408840] libceph: osd0 up
<6>[47383.584001] libceph: osd0 down
<6>[47383.587431] libceph: osd0 up
<6>[47464.808598] libceph: osd2 down
<6>[47464.812064] libceph: osd2 up
<6>[47708.042212] libceph: osd2 down
<6>[47708.045640] libceph: osd2 up
<6>[48352.227750] libceph: osd1 down
<6>[48354.774997] libceph: osd1 up
<6>[48385.108799] libceph: osd1 down
<6>[48385.112342] libceph: osd1 up
<1>[48385.115715] BUG: unable to handle kernel NULL pointer dereference at 0000000000000020

other example:

<6>[107816.810500] libceph: mon2 10.244.73.5:6789 session lost, hunting for new mon
<6>[107816.819016] libceph: mon0 10.244.43.19:6789 session established
<6>[107847.530010] libceph: mon0 10.244.43.19:6789 session lost, hunting for new mon
<6>[107847.540894] libceph: mon1 10.244.46.5:6789 session established
<6>[107877.737478] libceph: mon1 10.244.46.5:6789 session lost, hunting for new mon
<6>[107877.745951] libceph: mon0 10.244.43.19:6789 session established
<6>[107907.945902] libceph: mon0 10.244.43.19:6789 session lost, hunting for new mon
<6>[107907.961754] libceph: mon2 10.244.73.5:6789 session established
<6>[107922.925352] libceph: osd1 down
<6>[107922.928898] libceph: osd1 up
<6>[107938.664482] libceph: mon2 10.244.73.5:6789 session lost, hunting for new mon
<6>[107938.673853] libceph: mon1 10.244.46.5:6789 session established
<6>[107968.871892] libceph: mon1 10.244.46.5:6789 session lost, hunting for new mon
<6>[107968.880434] libceph: mon0 10.244.43.19:6789 session established
<6>[107978.088073] libceph: osd2 down
<6>[107978.091571] libceph: osd2 up
<6>[107999.591411] libceph: mon0 10.244.43.19:6789 session lost, hunting for new mon
<6>[107999.601418] libceph: mon1 10.244.46.5:6789 session established
<6>[108029.798914] libceph: mon1 10.244.46.5:6789 session lost, hunting for new mon
<6>[108029.807352] libceph: mon0 10.244.43.19:6789 session established
<6>[108060.518451] libceph: mon0 10.244.43.19:6789 session lost, hunting for new mon
<6>[108060.528611] libceph: mon1 10.244.46.5:6789 session established
<6>[108090.725949] libceph: mon1 10.244.46.5:6789 session lost, hunting for new mon
<6>[108090.741469] libceph: mon2 10.244.73.5:6789 session established
<6>[108120.933272] libceph: mon2 10.244.73.5:6789 session lost, hunting for new mon
<6>[108120.946075] libceph: mon1 10.244.46.5:6789 session established
<6>[108151.652839] libceph: mon1 10.244.46.5:6789 session lost, hunting for new mon
<6>[108151.661568] libceph: mon0 10.244.43.19:6789 session established
<6>[108181.860214] libceph: mon0 10.244.43.19:6789 session lost, hunting for new mon
<6>[108181.870050] libceph: mon1 10.244.46.5:6789 session established
<6>[108212.579774] libceph: mon1 10.244.46.5:6789 session lost, hunting for new mon
<6>[108212.595162] libceph: mon2 10.244.73.5:6789 session established
<6>[108237.929683] libceph: osd2 down
<6>[108237.933191] libceph: osd2 up
<6>[108242.787232] libceph: mon2 10.244.73.5:6789 session lost, hunting for new mon
<6>[108242.795585] libceph: mon0 10.244.43.19:6789 session established
<6>[108274.018737] libceph: mon0 10.244.43.19:6789 session lost, hunting for new mon
<6>[108274.029022] libceph: mon1 10.244.46.5:6789 session established
<6>[108304.738176] libceph: mon1 10.244.46.5:6789 session lost, hunting for new mon
<6>[108304.753807] libceph: mon2 10.244.73.5:6789 session established
<6>[108307.120205] libceph: osd0 down
<6>[108309.221068] libceph: osd0 up
<6>[108334.945685] libceph: mon2 10.244.73.5:6789 session lost, hunting for new mon
<6>[108334.955824] libceph: mon1 10.244.46.5:6789 session established
<6>[108365.665155] libceph: mon1 10.244.46.5:6789 session lost, hunting for new mon
<6>[108365.673680] libceph: mon0 10.244.43.19:6789 session established
<6>[108395.872716] libceph: mon0 10.244.43.19:6789 session lost, hunting for new mon
<6>[108395.888236] libceph: mon2 10.244.73.5:6789 session established
<6>[108426.592138] libceph: mon2 10.244.73.5:6789 session lost, hunting for new mon
<6>[108426.601693] libceph: mon1 10.244.46.5:6789 session established
<6>[108456.799599] libceph: mon1 10.244.46.5:6789 session lost, hunting for new mon
<6>[108456.808223] libceph: mon0 10.244.43.19:6789 session established
<6>[108487.519117] libceph: mon0 10.244.43.19:6789 session lost, hunting for new mon
<6>[108487.529368] libceph: mon1 10.244.46.5:6789 session established
<6>[108517.726546] libceph: mon1 10.244.46.5:6789 session lost, hunting for new mon
<6>[108517.763518] libceph: mon2 10.244.73.5:6789 session established
<6>[108547.934045] libceph: mon2 10.244.73.5:6789 session lost, hunting for new mon
<6>[108547.943733] libceph: mon1 10.244.46.5:6789 session established
<6>[108557.935462] libceph: osd0 down
<6>[108557.938973] libceph: osd0 up
<6>[108578.653569] libceph: mon1 10.244.46.5:6789 session lost, hunting for new mon
<6>[108578.669309] libceph: mon2 10.244.73.5:6789 session established
<6>[108608.861070] libceph: mon2 10.244.73.5:6789 session lost, hunting for new mon
<6>[108608.869755] libceph: mon0 10.244.43.19:6789 session established
<6>[108639.580564] libceph: mon0 10.244.43.19:6789 session lost, hunting for new mon
<6>[108639.596916] libceph: mon2 10.244.73.5:6789 session established
<6>[108669.788029] libceph: mon2 10.244.73.5:6789 session lost, hunting for new mon
<6>[108669.798025] libceph: mon1 10.244.46.5:6789 session established
<6>[108700.507460] libceph: mon1 10.244.46.5:6789 session lost, hunting for new mon
<6>[108700.516060] libceph: mon0 10.244.43.19:6789 session established
<6>[108730.714927] libceph: mon0 10.244.43.19:6789 session lost, hunting for new mon
<6>[108730.752570] libceph: mon2 10.244.73.5:6789 session established
<6>[108760.922494] libceph: mon2 10.244.73.5:6789 session lost, hunting for new mon
<6>[108760.932407] libceph: mon1 10.244.46.5:6789 session established
<6>[108791.641993] libceph: mon1 10.244.46.5:6789 session lost, hunting for new mon
<6>[108791.650457] libceph: mon0 10.244.43.19:6789 session established
<6>[108821.849454] libceph: mon0 10.244.43.19:6789 session lost, hunting for new mon
<6>[108821.859946] libceph: mon1 10.244.46.5:6789 session established
<6>[108852.568957] libceph: mon1 10.244.46.5:6789 session lost, hunting for new mon
<6>[108852.584115] libceph: mon2 10.244.73.5:6789 session established
<6>[108882.776430] libceph: mon2 10.244.73.5:6789 session lost, hunting for new mon
<6>[108882.784883] libceph: mon0 10.244.43.19:6789 session established
<6>[108914.007844] libceph: mon0 10.244.43.19:6789 session lost, hunting for new mon
<6>[108914.023208] libceph: mon2 10.244.73.5:6789 session established
<6>[108944.727405] libceph: mon2 10.244.73.5:6789 session lost, hunting for new mon
<6>[108944.735744] libceph: mon0 10.244.43.19:6789 session established
<6>[108974.934869] libceph: mon0 10.244.43.19:6789 session lost, hunting for new mon
<6>[108974.945659] libceph: mon1 10.244.46.5:6789 session established
<6>[109005.654332] libceph: mon1 10.244.46.5:6789 session lost, hunting for new mon
<6>[109005.662772] libceph: mon0 10.244.43.19:6789 session established
<6>[109035.861854] libceph: mon0 10.244.43.19:6789 session lost, hunting for new mon
<6>[109035.876942] libceph: mon2 10.244.73.5:6789 session established
<6>[109066.581352] libceph: mon2 10.244.73.5:6789 session lost, hunting for new mon
<6>[109066.589879] libceph: mon0 10.244.43.19:6789 session established
<6>[109096.788856] libceph: mon0 10.244.43.19:6789 session lost, hunting for new mon
<6>[109096.798779] libceph: mon1 10.244.46.5:6789 session established
<6>[109127.508368] libceph: mon1 10.244.46.5:6789 session lost, hunting for new mon
<6>[109127.516839] libceph: mon0 10.244.43.19:6789 session established
<6>[109157.715831] libceph: mon0 10.244.43.19:6789 session lost, hunting for new mon
<6>[109157.726082] libceph: mon1 10.244.46.5:6789 session established
<6>[109187.923236] libceph: mon1 10.244.46.5:6789 session lost, hunting for new mon
<6>[109187.931814] libceph: mon0 10.244.43.19:6789 session established
<6>[109208.247685] libceph: osd1 down
<6>[109208.251194] libceph: osd1 up
<6>[109208.404093] libceph: osd1 down
<6>[109208.407726] libceph: osd1 up
<1>[109208.411194] BUG: unable to handle kernel NULL pointer dereference at 0000000000000020

We meet totally twices.

http://tracker.ceph.com/issues/17664
https://github.com/ceph/ceph/pull/11601

do you meaning that async server not response ack msg, and client will destory and create mon session continue?

those session which one has been using but ptr is null?

jewel 10.2.10 hasn't contains this patches.

the patch 11601 must be a solution of the kernel painc?

tks for yours work.

libceph: mon2 10.244.73.5:6789 session lost, hunting for new mon

the above logs will be usual saw in kernel log,but libceph panic meeted total twices.

No, I'll post the patch for the kernel panic later today. The monitor session issue is separate.

Do you see "session lost, hunting for new mon" repeating every ~30 seconds? If so, does it happen right after you map an rbd image or mount cephfs? Note that in Bertrand's case it doesn't happen until a monitor goes down due to an upgrade.

async messenger was still experimental in jewel. If you are on jewel, you should be using simple messenger.

yes.

2018-04-26T11:18:36.435400+08:00 node53 kernel: libceph: mon2 10.0.30.53:6789 session established
2018-04-26T11:19:15.996377+08:00 node53 kernel: libceph: mon2 10.0.30.53:6789 session lost, hunting for new mon
2018-04-26T11:19:16.337370+08:00 node53 kernel: libceph: mon1 10.0.30.52:6789 session established
2018-04-26T11:19:46.044371+08:00 node53 kernel: libceph: mon1 10.0.30.52:6789 session lost, hunting for new mon
2018-04-26T11:19:46.044422+08:00 node53 kernel: libceph: mon2 10.0.30.53:6789 session established
2018-04-26T11:20:16.060373+08:00 node53 kernel: libceph: mon2 10.0.30.53:6789 session lost, hunting for new mon
2018-04-26T11:20:46.012366+08:00 node53 kernel: libceph: mon2 10.0.30.53:6789 session established
2018-04-26T11:21:16.092377+08:00 node53 kernel: libceph: mon2 10.0.30.53:6789 session lost, hunting for new mon
2018-04-26T11:21:16.105367+08:00 node53 kernel: libceph: mon1 10.0.30.52:6789 session established
2018-04-26T11:21:55.996224+08:00 node53 kernel: libceph: mon1 10.0.30.52:6789 session lost, hunting for new mon
2018-04-26T11:22:26.459377+08:00 node53 kernel: libceph: mon2 10.0.30.53:6789 session established
2018-04-26T11:23:06.012391+08:00 node53 kernel: libceph: mon2 10.0.30.53:6789 session lost, hunting for new mon
2018-04-26T11:23:36.001400+08:00 node53 kernel: libceph: mon1 10.0.30.52:6789 session established
2018-04-26T11:24:06.076410+08:00 node53 kernel: libceph: mon1 10.0.30.52:6789 session lost, hunting for new mon
2018-04-26T11:24:36.028375+08:00 node53 kernel: libceph: mon1 10.0.30.52:6789 session established
2018-04-26T11:25:06.044377+08:00 node53 kernel: libceph: mon1 10.0.30.52:6789 session lost, hunting for new mon
2018-04-26T11:25:06.189369+08:00 node53 kernel: libceph: mon2 10.0.30.53:6789 session established
2018-04-26T11:25:46.012374+08:00 node53 kernel: libceph: mon2 10.0.30.53:6789 session lost, hunting for new mon
2018-04-26T11:25:46.255368+08:00 node53 kernel: libceph: mon1 10.0.30.52:6789 session established
2018-04-26T11:26:26.012373+08:00 node53 kernel: libceph: mon1 10.0.30.52:6789 session lost, hunting for new mon
2018-04-26T11:26:26.012434+08:00 node53 kernel: libceph: mon2 10.0.30.53:6789 session established
2018-04-26T11:26:56.060378+08:00 node53 kernel: libceph: mon2 10.0.30.53:6789 session lost, hunting for new mon
2018-04-26T11:27:26.012382+08:00 node53 kernel: libceph: mon2 10.0.30.53:6789 session established
2018-04-26T11:27:56.092397+08:00 node53 kernel: libceph: mon2 10.0.30.53:6789 session lost, hunting for new mon

Does it happen right after you map an rbd image or mount cephfs? If so, and all your monitors are up, you are hitting #17664. Regardless, because you are on jewel, my recommendation is to switch to simple messenger.

we encountered similar problems. I don't know whether they are the same reasons.

Task dump for CPU 14:

Call Trace:
[<ffffffff810a4741>] ? deactivate_task+0x81/0xa0
[<ffffffff81095611>] wq_worker_sleeping+0x11/0x90
[<ffffffff817fbc50>] _schedule+0x650/0xa30
[<ffffffff817fc065>] schedule+0x35/0x80
[<ffffffff8107f166>] do_exit+0x766/0x80
[<ffffffff8107f166>] do_exit+0x766/0xaf0
[<ffffffff8102f991>] oops_end+0xa1/0xd0
[<ffffffff8102fe2b>] die+0x4b/0x70
[<ffffffff8102d479>] do_general_protection+0x28/0x30
[<ffffffff81801e98>] general_protection+0x28/0x30
[<ffffffff813e6a66>] ? memcpy_erms+0x6/0x10
[<ffffffff813ebf6e>] ? copy_to_iter+0x1ce/0x330
[<ffffffff813ed3ea>] copy_page_to_iter+0x7a/0x1c0
[<ffffffff816ec82d>] skb_copy_datagram_iter+0x14d/0x280
[<ffffffff81744989>] tcp_recmsg+0x5e9/0xbc0
[<ffffffff81381230>] ? aa_sk_perm+0x70/0x210
[<ffffffff8177212f>] inet_recvmsg+0x6f/0x80
[<ffffffff816dd54b>] sock_recvmsg+0x3b/0x50
[<ffffffff816dd691>] kernel_recvmsg+0x61/0x80
[<ffffffffc05398ab>] ceph_tcp_recvmsg+0x4b/0x60 [libceph]
[<ffffffffc053cfa1>] kernel_recvmsg+0x61/0x80
[<ffffffffc05398ab>] ceph_tcp_recvmsg+0x4b/0x60 [libceph]
[<ffffffffc053cfa8>] read_partial _message+0x3a8/0x860 [libceph]
[<ffffffffc053d9cb>] ceph_mon_workfn+0x56b/0x18b0 [libceph]
[<ffffffff810b0e6d>] ? dequeue_task_fair+0x51d/0x8b0
[<ffffffff810b2915>] ? _switch_to+0x1cd/ox590
[<ffffffff81094315>] process_one_work+0x165/0x480
[<ffffffff8109467b>] worker_thread+0x4b/0x4c0
[<ffffffff81094630>] ? process_one_work+0x490/0x480
[<ffffffff8109a5d9>] kthread+0xc9/0xe0
[<ffffffff8109a510>] ? kthread_create_on_node+0x1c0/0x1c0
[<ffffffff8100010f>] ret_from_fork+0x3f/0x70
[<ffffffff8109a510>] ? kthread_create_on_node+0x1c0/0x1c0

No, this doesn't look related at first sight. Can you paste more so I can see which kernel, what happened before the crash, etc?

Ilya Dryomov wrote:

No, this doesn't look related at first sight. Can you paste more so I can see which kernel, what happened before the crash, etc?

The kernel version we use is 4.4.0, but we often synchronize the ceph.ko and libceph code from the github. The version of the CEPH code we are using is "12.2.1.6 luminous (stable)" . Monitor and OSD did not down when the system hung. There is a strange phenomenon that two hosts almost at the same time appear this problem. I suspect that some unusual messenger has been received. It's a pity that I didn't open the libceph.ko log.

Bertrand, this patch fixes a crash that is very similar to yours. I wasn't able to trigger it under "normal" conditions though, so feel free to reopen if you continue to see crashes or "session lost" messages repeating every 30 seconds.

i'm monitoring this more closely now i will let you know if it occurs again.
thanks a lot for your work and the prompt responses :)