Tested with:

• image: quay.io/ceph/ceph:v18
• imageID: quay.io/ceph/ceph@sha256:06ddc3ef5b66f2dcc6d16e41842d33a3d7f497849981b0842672ef9014a96726

Ilya Dryomov wrote in #note-1:

Hi Nir,

rbd-mirror daemon states that it was unable to connect to the remote cluster. Could it be some kind of pod networking issue that goes away upon restart?

It can be, but rbd mirror should fail (and restart) if pod networking is broken, no?

There is nothing to go on in the attached log -- those errors aren't necessarily fatal. In an ODF environment, the debug levels are typically bumped to "debug ms = 1", "debug rbd = 15" and "debug rbd mirror = 30", both for the local client and the remote client.

This is not ODF environment, this is upstream rook environment.

• deploying rook operator: https://github.com/RamenDR/ramen/tree/main/test/addons/rook-operator
• creating ceph cluster: https://github.com/RamenDR/ramen/tree/main/test/addons/rook-cluster
• creating ceph block pool: https://github.com/RamenDR/ramen/tree/main/test/addons/rook-pool

What do we have to change to bump the log level as you mention?

Also, rbd-mirror daemon is configured to log to actual files with "log file = /var/log/ceph/\$cluster-\$name.log" and we are supposed to get two files: ceph-client.rbd-mirror.a.log and e.g. 62f28287-356f-4f81-87dc-51bb05942553-client.rbd-mirror-peer.log. Did that not happen here?

I don't know the environment was destroyed, and I don't know if it is configured to create these logs.

I can check if these logs exist on a new deployment.

Nir Soffer wrote in #note-3:

It can be, but rbd mirror should fail (and restart) if pod networking is broken, no?

There is code in rbd-mirror for restarting the failed pool replayer, so it's supposed to do that at least in some cases. There is no way to tell whether that code kicked in here or not without verbose logs.

rbd-mirror daemon will never restart itself, so if this is indeed a pod networking issue that disappears when the pod is restarted, no matter what rbd-mirror is doing internally it's never going to be able to resolve it like "kubectl rollout restart" does.

This is not ODF environment, this is upstream rook environment.

You can see the way we deploy and configure here:

• deploying rook operator: https://github.com/RamenDR/ramen/tree/main/test/addons/rook-operator
• creating ceph cluster: https://github.com/RamenDR/ramen/tree/main/test/addons/rook-cluster
• creating ceph block pool: https://github.com/RamenDR/ramen/tree/main/test/addons/rook-pool

What do we have to change to bump the log level as you mention?

It's automated for ODF here:

https://github.com/red-hat-storage/ocs-operator/blob/4a0325d824a409e84fac21ffbf0a1338971d1a70/controllers/storagecluster/cephrbdmirrors.go#L142-L232

You would need to do something close to that.

Ilya Dryomov wrote in #note-4:

This is not ODF environment, this is upstream rook environment.

You can see the way we deploy and configure here:

• deploying rook operator: https://github.com/RamenDR/ramen/tree/main/test/addons/rook-operator
• creating ceph cluster: https://github.com/RamenDR/ramen/tree/main/test/addons/rook-cluster
• creating ceph block pool: https://github.com/RamenDR/ramen/tree/main/test/addons/rook-pool

What do we have to change to bump the log level as you mention?

It's automated for ODF here:

https://github.com/red-hat-storage/ocs-operator/blob/4a0325d824a409e84fac21ffbf0a1338971d1a70/controllers/storagecluster/cephrbdmirrors.go#L142-L232

You would need to do something close to that.

Thanks, we will improve logging and reproduce again.

The current setup look like this:

$ kubectl describe deploy rook-ceph-rbd-mirror-a -n rook-ceph --context dr1
Name:                   rook-ceph-rbd-mirror-a
Namespace:              rook-ceph
CreationTimestamp:      Tue, 16 Apr 2024 00:22:11 +0300
Labels:                 app=rook-ceph-rbd-mirror
                        app.kubernetes.io/component=cephrbdmirrors.ceph.rook.io
                        app.kubernetes.io/created-by=rook-ceph-operator
                        app.kubernetes.io/instance=a
                        app.kubernetes.io/managed-by=rook-ceph-operator
                        app.kubernetes.io/name=ceph-rbd-mirror
                        app.kubernetes.io/part-of=my-rbd-mirror
                        ceph-version=18.2.2-0
                        ceph_daemon_id=a
                        ceph_daemon_type=rbd-mirror
                        rbd-mirror=a
                        rook-version=v1.13.8
                        rook.io/operator-namespace=rook-ceph
                        rook_cluster=rook-ceph
Annotations:            banzaicloud.com/last-applied:
                          UEsDBBQACAAIAAAAAAAAAAAAAAAAAAAAAAAIAAAAb3JpZ2luYWzsWNtu2zgTfpUfxH+xC4jyoWmaCPBF6rhbo/VhnXQXiyIwaGpkc02R6pByYgR+98VIimM7ttNDLhaL3gQy5zzzzQ...
                        deployment.kubernetes.io/revision: 1
Selector:               app=rook-ceph-rbd-mirror,app.kubernetes.io/component=cephrbdmirrors.ceph.rook.io,app.kubernetes.io/created-by=rook-ceph-operator,app.kubernetes.io/instance=a,app.kubernetes.io/managed-by=rook-ceph-operator,app.kubernetes.io/name=ceph-rbd-mirror,app.kubernetes.io/part-of=my-rbd-mirror,ceph_daemon_id=a,ceph_daemon_type=rbd-mirror,rbd-mirror=a,rook.io/operator-namespace=rook-ceph,rook_cluster=rook-ceph
Replicas:               1 desired | 1 updated | 1 total | 1 available | 0 unavailable
StrategyType:           RollingUpdate
MinReadySeconds:        0
RollingUpdateStrategy:  25% max unavailable, 25% max surge
Pod Template:
  Labels:  app=rook-ceph-rbd-mirror
           app.kubernetes.io/component=cephrbdmirrors.ceph.rook.io
           app.kubernetes.io/created-by=rook-ceph-operator
           app.kubernetes.io/instance=a
           app.kubernetes.io/managed-by=rook-ceph-operator
           app.kubernetes.io/name=ceph-rbd-mirror
           app.kubernetes.io/part-of=my-rbd-mirror
           ceph_daemon_id=a
           ceph_daemon_type=rbd-mirror
           rbd-mirror=a
           rook.io/operator-namespace=rook-ceph
           rook_cluster=rook-ceph
  Init Containers:
   chown-container-data-dir:
    Image:      quay.io/ceph/ceph:v18
    Port:       <none>
    Host Port:  <none>
    Command:
      chown
    Args:
      --verbose
      --recursive
      ceph:ceph
      /var/log/ceph
      /var/lib/ceph/crash
      /run/ceph
    Environment:  <none>
    Mounts:
      /etc/ceph from rook-config-override (ro)
      /etc/ceph/keyring-store/ from rook-ceph-rbd-mirror-a-keyring (ro)
      /run/ceph from ceph-daemons-sock-dir (rw)
      /var/lib/ceph/crash from rook-ceph-crash (rw)
      /var/log/ceph from rook-ceph-log (rw)
  Containers:
   rbd-mirror:
    Image:      quay.io/ceph/ceph:v18
    Port:       <none>
    Host Port:  <none>
    Command:
      rbd-mirror
    Args:
      --fsid=ea6c70f1-21d0-4991-829d-bc0c3aad6a2c
      --keyring=/etc/ceph/keyring-store/keyring
      --default-log-to-stderr=true
      --default-err-to-stderr=true
      --default-mon-cluster-log-to-stderr=true
      --default-log-stderr-prefix=debug 
      --default-log-to-file=false
      --default-mon-cluster-log-to-file=false
      --mon-host=$(ROOK_CEPH_MON_HOST)
      --mon-initial-members=$(ROOK_CEPH_MON_INITIAL_MEMBERS)
      --id=a
      --setuser=ceph
      --setgroup=ceph
      --foreground
      --name=client.rbd-mirror.a
    Environment:
      CONTAINER_IMAGE:                quay.io/ceph/ceph:v18
      POD_NAME:                        (v1:metadata.name)
      POD_NAMESPACE:                   (v1:metadata.namespace)
      NODE_NAME:                       (v1:spec.nodeName)
      POD_MEMORY_LIMIT:               node allocatable (limits.memory)
      POD_MEMORY_REQUEST:             0 (requests.memory)
      POD_CPU_LIMIT:                  node allocatable (limits.cpu)
      POD_CPU_REQUEST:                0 (requests.cpu)
      CEPH_USE_RANDOM_NONCE:          true
      ROOK_CEPH_MON_HOST:             <set to the key 'mon_host' in secret 'rook-ceph-config'>             Optional: false
      ROOK_CEPH_MON_INITIAL_MEMBERS:  <set to the key 'mon_initial_members' in secret 'rook-ceph-config'>  Optional: false
    Mounts:
      /etc/ceph from rook-config-override (ro)
      /etc/ceph/keyring-store/ from rook-ceph-rbd-mirror-a-keyring (ro)
      /run/ceph from ceph-daemons-sock-dir (rw)
      /var/lib/ceph/crash from rook-ceph-crash (rw)
      /var/log/ceph from rook-ceph-log (rw)
  Volumes:
   rook-config-override:
    Type:               Projected (a volume that contains injected data from multiple sources)
    ConfigMapName:      rook-config-override
    ConfigMapOptional:  <nil>
   rook-ceph-rbd-mirror-a-keyring:
    Type:        Secret (a volume populated by a Secret)
    SecretName:  rook-ceph-rbd-mirror-a-keyring
    Optional:    false
   ceph-daemons-sock-dir:
    Type:          HostPath (bare host directory volume)
    Path:          /data/rook/exporter
    HostPathType:  DirectoryOrCreate
   rook-ceph-log:
    Type:          HostPath (bare host directory volume)
    Path:          /data/rook/rook-ceph/log
    HostPathType:  
   rook-ceph-crash:
    Type:          HostPath (bare host directory volume)
    Path:          /data/rook/rook-ceph/crash
    HostPathType:  
Conditions:
  Type           Status  Reason
  ----           ------  ------
  Available      True    MinimumReplicasAvailable
  Progressing    True    NewReplicaSetAvailable
OldReplicaSets:  <none>
NewReplicaSet:   rook-ceph-rbd-mirror-a-7c677bd5bf (1/1 replicas created)
Events:
  Type    Reason             Age   From                   Message
  ----    ------             ----  ----                   -------
  Normal  ScalingReplicaSet  28m   deployment-controller  Scaled up replica set rook-ceph-rbd-mirror-a-7c677bd5bf to 1

Nir Soffer wrote in #note-6:

The other log file (e.g. 62f28287-356f-4f81-87dc-51bb05942553-client.rbd-mirror-peer.log) is
not created.

Hi Nir,

The above needs to be done of both clusters. The configuration on cluster A affects logging on cluster B because rbd-mirror daemon is just another client from cluster A's perspective.

Few questions:
- Any change needed to get enough info when we reproduce the issue again?

Let's obtain both log files and go from there.

- Why we need debug_rbd_mirror = 30 when the highest log level is 20? (also documented to be 20)

I don't think there is such a thing as the highest log level. rbd-mirror daemon certainly has a few log messages at 30.

Overall, Ceph is pretty lax about log levels and how they are used varies greatly from subsystem to subsystem.

- Do we really need the log file? it is much easier to work with kubectl logs, and this setup is used for short living clusters during CI or manual testing. We don't expect to debug issues that happened more than 1-2 hours ago.

Unfortunately, we do. Once you get to rbd-mirror actually syncing an image, you would see that kubectl can sustain only 1-2 minutes worth of verbose logs.

Ilya Dryomov wrote in #note-7:

Nir Soffer wrote in #note-6:

The other log file (e.g. 62f28287-356f-4f81-87dc-51bb05942553-client.rbd-mirror-peer.log) is
not created.

Hi Nir,

The above needs to be done of both clusters. The configuration on cluster A affects logging on cluster B because rbd-mirror daemon is just another client from cluster A's perspective.

Yes, the configuration is applied to both clusters. If I understand correctly,
The mentioned 62f28287-356f-4f81-87dc-51bb05942553-client.rbd-mirror-peer.log
file is the ceph-client.rbd-mirror.a.log from the other cluster? Maybe odf
must-gather is creating this file?

Few questions:
- Any change needed to get enough info when we reproduce the issue again?

Let's obtain both log files and go from there.

- Why we need debug_rbd_mirror = 30 when the highest log level is 20? (also documented to be 20)

I don't think there is such a thing as the highest log level. rbd-mirror daemon certainly has a few log messages at 30.

OK, I was confused by the note here saying "Log levels range from 0 to 20"
https://docs.ceph.com/en/latest/rados/configuration/ceph-conf/#runtime-changes

- Do we really need the log file? it is much easier to work with kubectl logs, and this setup is used for short living clusters during CI or manual testing. We don't expect to debug issues that happened more than 1-2 hours ago.

Unfortunately, we do. Once you get to rbd-mirror actually syncing an image, you would see that kubectl can sustain only 1-2 minutes worth of verbose logs.

OK

I'll try to reproduce with this configuration and collect the full log from
both clusters on errors.

Nir Soffer wrote in #note-8:

Yes, the configuration is applied to both clusters. If I understand correctly,
The mentioned 62f28287-356f-4f81-87dc-51bb05942553-client.rbd-mirror-peer.log
file is the ceph-client.rbd-mirror.a.log from the other cluster?

62f28287-356f-4f81-87dc-51bb05942553 was just an example -- I copied that from the log that you provided previously. Since the clusters have presumably been redeployed from scratch, look for any file named <UUID>-client.rbd-mirror-peer.log.

Maybe odf must-gather is creating this file?

No, it's created by rbd-mirror daemon.

Ilya Dryomov wrote in #note-9:

Nir Soffer wrote in #note-8:

Yes, the configuration is applied to both clusters. If I understand correctly,
The mentioned 62f28287-356f-4f81-87dc-51bb05942553-client.rbd-mirror-peer.log
file is the ceph-client.rbd-mirror.a.log from the other cluster?

62f28287-356f-4f81-87dc-51bb05942553 was just an example -- I copied that from the log that you provided previously. Since the clusters have presumably been redeployed from scratch, look for any file named <UUID>-client.rbd-mirror-peer.log.

Maybe odf must-gather is creating this file?

No, it's created by rbd-mirror daemon.

I see, but it is was not created using the configuration I shared here.

Both clusters are configured, and I run a full DR flow with failover and relocate.
In every step we wait for the first replication. Maybe something is wrong with this
configuration?

    [client.rbd-mirror-peer]
    debug_ms = 1
    debug_rbd = 15
    debug_rbd_mirror = 30
    log_to_file = true
    log_file = /var/log/ceph/$cluster-$name.log

Hi Nir,

I think the problem is the method you used to set these config options. Note that the way it's done in ODF is via "ceph config set" commands, while you did it through a "data: config: " override which simply injects the snippet verbatim into ceph.conf file. Ordinarily there would be almost no difference, but in this case it matters because there are two different clusters in play and their names don't match up, at least as far as rbd-mirror daemon is concerned.

Ilya Dryomov wrote in #note-11:

Hi Nir,

I think the problem is the method you used to set these config options. Note that the way it's done in ODF is via "ceph config set" commands, while you did it through a "data: config: " override which simply injects the snippet verbatim into ceph.conf file. Ordinarily there would be almost no difference, but in this case it matters because there are two different clusters in play and their names don't match up, at least as far as rbd-mirror daemon is concerned.

OK, I will try to do the same changes using same method as ODF.

Nir Soffer wrote in #note-12:

Ilya Dryomov wrote in #note-11:

Hi Nir,

I think the problem is the method you used to set these config options. Note that the way it's done in ODF is via "ceph config set" commands, while you did it through a "data: config: " override which simply injects the snippet verbatim into ceph.conf file. Ordinarily there would be almost no difference, but in this case it matters because there are two different clusters in play and their names don't match up, at least as far as rbd-mirror daemon is concerned.

Changing to dynamic configuration¹ the rbd-mirror-peer log is created:

$ minikube ssh -p dr1 'ls /data/rook/rook-ceph/log'
9e67de2a-c3eb-4a06-a8b5-444bff716362-client.rbd-mirror-peer.log  ceph-client.rbd-mirror.a.log  ceph-volume.log

However unlike ODF, the log files are not created without log_to_file = true. Maybe ODF runs the container with different arguments?

[1] https://github.com/RamenDR/ramen/pull/1346

log_to_file gets set to true by Rook as part of enabling the log collector:

https://github.com/rook/rook/blob/a9fded234575895285779d57763d39086dc497d4/pkg/operator/ceph/config/config.go#L120-L129

The log collector rotates logs. If you don't have it enabled but have verbose logging set up, you would quickly run out of space.

Ilya Dryomov wrote in #note-14:

log_to_file gets set to true by Rook as part of enabling the log collector:

https://github.com/rook/rook/blob/a9fded234575895285779d57763d39086dc497d4/pkg/operator/ceph/config/config.go#L120-L129

The log collector rotates logs. If you don't have it enabled but have verbose logging set up, you would quickly run out of space.

Thanks! This should not be a problem in most cases since the test environment rarely lives more than one day, but may be for people keeping a test environment running for many days.

Hi Nir,

I built a container based on 18.2.3 (an upcoming release). It would be great if you could try it: podman pull quay.ceph.io/ceph-ci/ceph:wip-65487-on-18.2.3

Disable verbose logging since that made the issue harder to reproduce -- I'm interested in just pass/fail (or rather the number of deployments you are able to clock without restarting the daemon).

Ilya Dryomov wrote in #note-20:

Hi Nir,

I built a container based on 18.2.3 (an upcoming release). It would be great if you could try it: podman pull quay.ceph.io/ceph-ci/ceph:wip-65487-on-18.2.3

Disable verbose logging since that made the issue harder to reproduce -- I'm interested in just pass/fail (or rather the number of deployments you are able to clock without restarting the daemon).

Thanks Ilia! I will try this image later this week.

Ilya Dryomov wrote in #note-20:

Hi Nir,

I built a container based on 18.2.3 (an upcoming release). It would be great if you could try it: podman pull quay.ceph.io/ceph-ci/ceph:wip-65487-on-18.2.3

This registry does not have good enough connection - it takes 7-8 minutes to pull it
in the lab use for testing:

rook-ceph                             0s                      Normal    Pulled                             Pod/rook-ceph-detect-version-ms4hn                                                 Successfully pulled image "quay.ceph.io/ceph-ci/ceph:wip-65487-on-18.2.3" in 8m40.521s (8m40.521s including waiting)
...
rook-ceph                             0s                      Normal    Pulled                             Pod/rook-ceph-detect-version-kjbrf                                                 Successfully pulled image "quay.ceph.io/ceph-ci/ceph:wip-65487-on-18.2.3" in 7m5.058s (7m5.058s including waiting)

This causes timeout when creating ceph cluster. We probably need to setup a local registry in this lab.