2024-10-30T07:06:18.602Z

<ljon> Hello @Ilya Dryomov, I used the above script but with `--debug-rbd 20 --debug-ms 1` and got the below logs. Can you see anything from it?
/code

2024-10-30T07:07:06.913Z

<ljon> Hello @Ilya Dryomov, I used the above script but with `--debug-rbd 20 --debug-ms 1` and got the below logs. Can you see anything from it?
```rbd snap create --debug-rbd 20 --debug-ms 1 volume-ssd/volume-7f7df77d-ea0f-4c93-a357-84bd9b3d7a0f@jun-snap12155

TIME: 2024-10-29 11:14:22
2024-10-29T11:14:22.798-0500 7f9af182eb80 1 Processor -- start
2024-10-29T11:14:22.798-0500 7f9af182eb80 1 -- start start
2024-10-29T11:14:22.798-0500 7f9af182eb80 1 --2- >> [v2:10.250.64.62:3300/0,v1:10.250.64.62:6789/0] conn(0x56281729b600 0x56281729ba10 unknown :-1 s=NONE pgs=0 cs=0 l=0 re
v1=0 crypto rx=0 tx=0 comp rx=0 tx=0).connect
2024-10-29T11:14:22.798-0500 7f9af182eb80 1 --2- >> [v2:10.250.64.60:3300/0,v1:10.250.64.60:6789/0] conn(0x56281729c7f0 0x56281729cc60 unknown :-1 s=NONE pgs=0 cs=0 l=0 re
v1=0 crypto rx=0 tx=0 comp rx=0 tx=0).connect
2024-10-29T11:14:22.798-0500 7f9af182eb80 1 --2- >> [v2:10.250.64.61:3300/0,v1:10.250.64.61:6789/0] conn(0x56281729d1a0 0x5628172a3a40 unknown :-1 s=NONE pgs=0 cs=0 l=0 re
v1=0 crypto rx=0 tx=0 comp rx=0 tx=0).connect
2024-10-29T11:14:22.798-0500 7f9af182eb80 1 -- --> [v2:10.250.64.60:3300/0,v1:10.250.64.60:6789/0] -- mon_getmap magic: 0 v1 -- 0x5628171892f0 con 0x56281729c7f0
2024-10-29T11:14:22.798-0500 7f9af182eb80 1 -- --> [v2:10.250.64.61:3300/0,v1:10.250.64.61:6789/0] -- mon_getmap magic: 0 v1 -- 0x5628171850e0 con 0x56281729d1a0
2024-10-29T11:14:22.798-0500 7f9af182eb80 1 -- --> [v2:10.250.64.62:3300/0,v1:10.250.64.62:6789/0] -- mon_getmap magic: 0 v1 -- 0x56281712bb10 con 0x56281729b600
2024-10-29T11:14:22.799-0500 7f9aeef4d640 1 --2- >> [v2:10.250.64.62:3300/0,v1:10.250.64.62:6789/0] conn(0x56281729b600 0x56281729ba10 unknown :-1 s=BANNER_CONNECTING pgs=
0 cs=0 l=0 rev1=0 crypto rx=0 tx=0 comp rx=0 tx=0)._handle_peer_banner_payload supported=3 required=0
2024-10-29T11:14:22.799-0500 7f9aef74e640 1 --2- >> [v2:10.250.64.61:3300/0,v1:10.250.64.61:6789/0] conn(0x56281729d1a0 0x5628172a3a40 unknown :-1 s=BANNER_CONNECTING pgs=
0 cs=0 l=0 rev1=0 crypto rx=0 tx=0 comp rx=0 tx=0)._handle_peer_banner_payload supported=3 required=0
2024-10-29T11:14:22.799-0500 7f9aeef4d640 1 --2- >> [v2:10.250.64.62:3300/0,v1:10.250.64.62:6789/0] conn(0x56281729b600 0x56281729ba10 unknown :-1 s=HELLO_CONNECTING pgs=0
 cs=0 l=0 rev1=1 crypto rx=0 tx=0 comp rx=0 tx=0).handle_hello peer v2:10.250.64.62:3300/0 says I am v2:10.250.64.33:53450/0 (socket says 10.250.64.33:53450)
2024-10-29T11:14:22.799-0500 7f9aee74c640 1 --2- >> [v2:10.250.64.60:3300/0,v1:10.250.64.60:6789/0] conn(0x56281729c7f0 0x56281729cc60 unknown :-1 s=BANNER_CONNECTING pgs=
0 cs=0 l=0 rev1=0 crypto rx=0 tx=0 comp rx=0 tx=0)._handle_peer_banner_payload supported=3 required=0
2024-10-29T11:14:22.799-0500 7f9aeef4d640 1 -- 10.250.64.33:0/67334410 learned_addr learned my addr 10.250.64.33:0/67334410 (peer_addr_for_me v2:10.250.64.33:0/0)
2024-10-29T11:14:22.799-0500 7f9aeef4d640 1 -- 10.250.64.33:0/67334410 >> [v2:10.250.64.61:3300/0,v1:10.250.64.61:6789/0] conn(0x56281729d1a0 msgr2=0x5628172a3a40 unknown :
-1 s=STATE_CONNECTION_ESTABLISHED l=0).mark_down
2024-10-29T11:14:22.799-0500 7f9aeef4d640 1 --2- 10.250.64.33:0/67334410 >> [v2:10.250.64.61:3300/0,v1:10.250.64.61:6789/0] conn(0x56281729d1a0 0x5628172a3a40 unknown :-1 s
=AUTH_CONNECTING pgs=0 cs=0 l=0 rev1=1 crypto rx=0 tx=0 comp rx=0 tx=0).stop
2024-10-29T11:14:22.799-0500 7f9aeef4d640 1 -- 10.250.64.33:0/67334410 >> [v2:10.250.64.60:3300/0,v1:10.250.64.60:6789/0] conn(0x56281729c7f0 msgr2=0x56281729cc60 unknown :
-1 s=STATE_CONNECTION_ESTABLISHED l=0).mark_down
2024-10-29T11:14:22.799-0500 7f9aeef4d640 1 --2- 10.250.64.33:0/67334410 >> [v2:10.250.64.60:3300/0,v1:10.250.64.60:6789/0] conn(0x56281729c7f0 0x56281729cc60 unknown :-1 s
=AUTH_CONNECTING pgs=0 cs=0 l=0 rev1=1 crypto rx=0 tx=0 comp rx=0 tx=0).stop
2024-10-29T11:14:22.799-0500 7f9aeef4d640 1 -- 10.250.64.33:0/67334410 --> [v2:10.250.64.62:3300/0,v1:10.250.64.62:6789/0] -- mon_subscribe({config=0+,monmap=0+}) v3 -- 0x5
62817151fc0 con 0x56281729b600
2024-10-29T11:14:22.801-0500 7f9aeef4d640 1 --2- 10.250.64.33:0/67334410 >> [v2:10.250.64.62:3300/0,v1:10.250.64.62:6789/0] conn(0x56281729b600 0x56281729ba10 secure :-1 s=
READY pgs=4475830 cs=0 l=1 rev1=1 crypto rx=0x7f9ae000a700 tx=0x7f9ae001cd70 comp rx=0 tx=0).ready entity=mon.2 client_cookie=df0c6bd454c85e35 server_cookie=0 in_seq=0 out_s
eq=0
2024-10-29T11:14:22.801-0500 7f9aedf4b640 1 -- 10.250.64.33:0/67334410 <== mon.2 v2:10.250.64.62:3300/0 1 ==== mon_map magic: 0 v1 ==== 462+0+0 (secure 0 0 0) 0x7f9ae005268
0 con 0x56281729b600
2024-10-29T11:14:22.801-0500 7f9aedf4b640 1 -- 10.250.64.33:0/67334410 <== mon.2 v2:10.250.64.62:3300/0 2 ==== config(11 keys) v1 ==== 385+0+0 (secure 0 0 0) 0x7f9ae00529e0
 con 0x56281729b600
2024-10-29T11:14:22.801-0500 7f9aedf4b640 1 -- 10.250.64.33:0/67334410 <== mon.2 v2:10.250.64.62:3300/0 3 ==== mon_map magic: 0 v1 ==== 462+0+0 (secure 0 0 0) 0x7f9ae00513a
0 con 0x56281729b600
^MCreating snap: 10% complete...^MCreating snap: 100% complete...done.
^MRemoving snap: 100% complete...done.

TIME: 2024-10-29 11:14:27
2024-10-29T11:14:27.827-0500 7fa3cc623b80 1 Processor -- start
2024-10-29T11:14:27.827-0500 7fa3cc623b80 1 -- start start
2024-10-29T11:14:27.827-0500 7fa3cc623b80 1 --2- >> [v2:10.250.64.61:3300/0,v1:10.250.64.61:6789/0] conn(0x5612cb774600 0x5612cb774a10 unknown :-1 s=NONE pgs=0 cs=0 l=0 rev1=0 crypto rx=0 tx=0 comp rx=0 tx=0).connect
2024-10-29T11:14:27.827-0500 7fa3cc623b80 1 --2- >> [v2:10.250.64.62:3300/0,v1:10.250.64.62:6789/0] conn(0x5612cb7757f0 0x5612cb775c60 unknown :-1 s=NONE pgs=0 cs=0 l=0 rev1=0 crypto rx=0 tx=0 comp rx=0 tx=0).connect
2024-10-29T11:14:27.827-0500 7fa3cc623b80 1 --2- >> [v2:10.250.64.60:3300/0,v1:10.250.64.60:6789/0] conn(0x5612cb7761a0 0x5612cb77ca40 unknown :-1 s=NONE pgs=0 cs=0 l=0 rev1=0 crypto rx=0 tx=0 comp rx=0 tx=0).connect
2024-10-29T11:14:27.827-0500 7fa3cc623b80 1 -- --> [v2:10.250.64.60:3300/0,v1:10.250.64.60:6789/0] -- mon_getmap magic: 0 v1 -- 0x5612cb6622f0 con 0x5612cb7761a0
2024-10-29T11:14:27.827-0500 7fa3cc623b80 1 -- --> [v2:10.250.64.61:3300/0,v1:10.250.64.61:6789/0] -- mon_getmap magic: 0 v1 -- 0x5612cb65e0e0 con 0x5612cb774600
2024-10-29T11:14:27.827-0500 7fa3cc623b80 1 -- --> [v2:10.250.64.62:3300/0,v1:10.250.64.62:6789/0] -- mon_getmap magic: 0 v1 -- 0x5612cb604b10 con 0x5612cb7757f0
2024-10-29T11:14:27.827-0500 7fa3c9939640 1 --2- >> [v2:10.250.64.62:3300/0,v1:10.250.64.62:6789/0] conn(0x5612cb7757f0 0x5612cb775c60 unknown :-1 s=BANNER_CONNECTING pgs=0 cs=0 l=0 rev1=0 crypto rx=0 tx=0 comp rx=0 tx=0)._handle_peer_banner_payload supported=3 required=0
2024-10-29T11:14:27.827-0500 7fa3ca93b640 1 --2- >> [v2:10.250.64.60:3300/0,v1:10.250.64.60:6789/0] conn(0x5612cb7761a0 0x5612cb77ca40 unknown :-1 s=BANNER_CONNECTING pgs=0 cs=0 l=0 rev1=0 crypto rx=0 tx=0 comp rx=0 tx=0)._handle_peer_banner_payload supported=3 required=0
2024-10-29T11:14:27.827-0500 7fa3c9939640 1 --2- >> [v2:10.250.64.62:3300/0,v1:10.250.64.62:6789/0] conn(0x5612cb7757f0 0x5612cb775c60 unknown :-1 s=HELLO_CONNECTING pgs=0 cs=0 l=0 rev1=1 crypto rx=0 tx=0 comp rx=0 tx=0).handle_hello peer v2:10.250.64.62:3300/0 says I am v2:10.250.64.33:51590/0 (socket says 10.250.64.33:51590)
2024-10-29T11:14:27.827-0500 7fa3c9939640 1 -- 10.250.64.33:0/653643095 learned_addr learned my addr 10.250.64.33:0/653643095 (peer_addr_for_me v2:10.250.64.33:0/0)
2024-10-29T11:14:27.827-0500 7fa3ca13a640 1 --2- 10.250.64.33:0/653643095 >> [v2:10.250.64.61:3300/0,v1:10.250.64.61:6789/0] conn(0x5612cb774600 0x5612cb774a10 unknown :-1 s=BANNER_CONNECTING pgs=0 cs=0 l=0 rev1=0 crypto rx=0 tx=0 comp rx=0 tx=0)._handle_peer_banner_payload supported=3 required=0
2024-10-29T11:14:27.828-0500 7fa3ca93b640 1 -- 10.250.64.33:0/653643095 >> [v2:10.250.64.62:3300/0,v1:10.250.64.62:6789/0] conn(0x5612cb7757f0 msgr2=0x5612cb775c60 unknown :-1 s=STATE_CONNECTION_ESTABLISHED l=0).mark_down
2024-10-29T11:14:27.828-0500 7fa3ca93b640 1 --2- 10.250.64.33:0/653643095 >> [v2:10.250.64.62:3300/0,v1:10.250.64.62:6789/0] conn(0x5612cb7757f0 0x5612cb775c60 unknown :-1 s=AUTH_CONNECTING pgs=0 cs=0 l=0 rev1=1 crypto rx=0 tx=0 comp rx=0 tx=0).stop
2024-10-29T11:14:27.828-0500 7fa3ca93b640 1 -- 10.250.64.33:0/653643095 >> [v2:10.250.64.61:3300/0,v1:10.250.64.61:6789/0] conn(0x5612cb774600 msgr2=0x5612cb774a10 unknown :-1 s=STATE_CONNECTION_ESTABLISHED l=0).mark_down
2024-10-29T11:14:27.828-0500 7fa3ca93b640 1 --2- 10.250.64.33:0/653643095 >> [v2:10.250.64.61:3300/0,v1:10.250.64.61:6789/0] conn(0x5612cb774600 0x5612cb774a10 unknown :-1 s=AUTH_CONNECTING pgs=0 cs=0 l=0 rev1=1 crypto rx=0 tx=0 comp rx=0 tx=0).stop
2024-10-29T11:14:27.828-0500 7fa3ca93b640 1 -- 10.250.64.33:0/653643095 --> [v2:10.250.64.60:3300/0,v1:10.250.64.60:6789/0] -- mon_subscribe({config=0+,monmap=0+}) v3 -- 0x5612cb62afc0 con 0x5612cb7761a0
2024-10-29T11:14:27.828-0500 7fa3c9939640 1 --2- 10.250.64.33:0/653643095 >> [v2:10.250.64.62:3300/0,v1:10.250.64.62:6789/0] conn(0x5612cb7757f0 0x5612cb775c60 unknown :-1 s=CLOSED pgs=0 cs=0 l=0 rev1=1 crypto rx=0 tx=0 comp rx=0 tx=0).handle_auth_done state changed!
2024-10-29T11:14:27.829-0500 7fa3ca93b640 1 --2- 10.250.64.33:0/653643095 >> [v2:10.250.64.60:3300/0,v1:10.250.64.60:6789/0] conn(0x5612cb7761a0 0x5612cb77ca40 secure :-1 s=READY pgs=4351706 cs=0 l=1 rev1=1 crypto rx=0x7fa3c400a5d0 tx=0x7fa3c401ca00 comp rx=0 tx=0).ready entity=mon.0 client_cookie=500cd82cb6569b12 server_cookie=0 in_seq=0 out_seq=0
2024-10-29T11:14:27.829-0500 7fa3c9138640 1 -- 10.250.64.33:0/653643095 <== mon.0 v2:10.250.64.60:3300/0 1 ==== mon_map magic: 0 v1 ==== 462+0+0 (secure 0 0 0) 0x7fa3c404ae60 con 0x5612cb7761a0
2024-10-29T11:14:27.830-0500 7fa3c9138640 1 -- 10.250.64.33:0/653643095 <== mon.0 v2:10.250.64.60:3300/0 2 ==== config(11 keys) v1 ==== 385+0+0 (secure 0 0 0) 0x7fa3c4052640 con 0x5612cb7761a0
2024-10-29T11:14:27.830-0500 7fa3c9138640 1 -- 10.250.64.33:0/653643095 <== mon.0 v2:10.250.64.60:3300/0 3 ==== mon_map magic: 0 v1 ==== 462+0+0 (secure 0 0 0) 0x7fa3c4052b70 con 0x5612cb7761a0
^MCreating snap: 10% complete...^MCreating snap: 10% complete...failed.
rbd: failed to create snapshot: (1) Operation not permitted```

2024-10-30T14:22:25.426Z

<Ken Dreyer> I see, ok. Thanks for that error text. That helps me understand the problem more.

2024-10-30T15:20:07.862Z

<Casey Bodley> try the `squid` branch. the fix was merged there after 19.2.0 branched: <https://github.com/ceph/ceph/pull/59055>

2024-10-30T15:25:37.034Z

<Casey Bodley> weekly rgw meeting starting in 5m [ <https://pad.ceph.com/p/rgw-weekly](https://meet.google.com/mmj-uzzv-qce> )

2024-10-30T16:30:34.646Z

<Ivveh> just a sanity check before i submit into the tracker:
this commit <https://github.com/ceph/ceph/commit/2415e03217b4afe9e430863da0b4503be254c425> states that it will only restart ganesha in very specific cases when the export is modified but not in cases where the subvolumepath path or ACL for example is modified. when these are modified rados watch object will correctly send a SIGHUP to nfs-ganesha. however.. this is not the case. whenever the function `_apply_export` is called you can see that `need_nfs_service_restart = True` is always set no matter the condition and will send a `service_action` instead of only a `describe_service` restarting the service and breaking all current nfs connections

2024-10-30T16:32:48.227Z

<Ivveh> it is later on unset, but logic doesnt seem to work as it restarts ganesha 🤷

2024-10-30T16:53:13.092Z

<Rost Khudov> btw, you can ignore the second issue with ttl

2024-10-30T16:53:22.121Z

<Rost Khudov> btw, you can ignore the second issue with ttl for 19.2.0 tag

2024-10-30T19:03:45.705Z

<Ilya Dryomov> > Can you see anything from it?
No, these logs seem incomplete to me

2024-10-30T20:22:14.565Z

<badone> I can get you the other error too, will do shortly.

2024-10-30T22:40:23.623Z

<Paulo Castro> Many thanks, a few fixes for python deps plus that cherry-pick on top of the 19.2.0 tag got it building to completion.