Ceph » RADOS

I wonder whether this is a fallout from the public_bind changes (for the overlapping IP problem) but it looks the branch is from 22 Feb while we started testing of the quincy backport on 27 Feb.

Verified whether the testing branch had the public_bind_addr support in OSD:

rzarz@ubulap:~/dev/ceph$ git checkout cbccb547f47ec697c2e2ecf23392cc636ea19450
M    src/crypto/isa-l/isa-l_crypto
M    src/fmt
M    src/rapidjson
M    src/s3select
M    src/seastar
HEAD is now at cbccb547f47 Merge branch 'wip-58212-quincy' of https://github.com/cfsnyder/ceph into wip-yuri4-testing-2023-02-22-0817-quincy
rzarz@ubulap:~/dev/ceph$ grep -r CEPH_PICK_ADDRESS_PUBLIC_BIND src; echo $?
1

There changes were NOT there -- the issue is unrelated.

The heartbeat msgr instances started with the INADDR_ANY addresses.

rzarzynski@teuthology:/a/yuriw-2023-02-22_20:55:15-rados-wip-yuri4-testing-2023-02-22-0817-quincy-distro-default-smithi/7184640$ less ./remote/smithi156/log/ceph-osd.3.log.gz
...
2023-02-23T07:07:23.874+0000 7f46c1884700 20 osd.3 51  initial client_addrs [v2:172.21.15.156:6824/132919,v1:172.21.15.156:6825/132919], cluster_addrs [v2:0.0.0.0:6826/132919,v1:0.0.0.0:6827/132919], hb_back_addrs [v2:0.0.0.0:6830/132919,v1:0.0.0.0:6831/132919], hb_front_addrs [v2:0.0.0.0:6828/132919,v1:0.0.0.0:6829/132919]
...
2023-02-23T07:07:23.874+0000 7f46c82e0700  1 --2- [v2:0.0.0.0:6828/132919,v1:0.0.0.0:6829/132919] >>  conn(0x555603f64000 0x555603f6a000 unknown :-1 s=HELLO_ACCEPTING pgs=0 cs=0 l=1 rev1=1 crypto rx=0 tx=0 comp rx=0 tx=0).handle_hello peer v2:172.21.15.156:54094/0 says I am v2:172.21.15.156:6828/70876 (socket says 172.21.15.156:6828)
...
2023-02-23T07:07:23.874+0000 7f46c1884700  1 -- [v2:0.0.0.0:6830/132919,v1:0.0.0.0:6831/132919] set_addr_unknowns assuming my addr v2:0.0.0.0:6830/132919 matches provided addr v2:172.21.15.156:6826/132919
2023-02-23T07:07:23.874+0000 7f46c1884700  1 -- [v2:0.0.0.0:6830/132919,v1:0.0.0.0:6831/132919] set_addr_unknowns assuming my addr v1:0.0.0.0:6831/132919 matches provided addr v2:172.21.15.156:6826/132919
2023-02-23T07:07:23.874+0000 7f46c82e0700  1 -- [v2:172.21.15.156:6828/132919,v1:172.21.15.156:6829/132919] learned_addr learned my addr [v2:172.21.15.156:6828/132919,v1:172.21.15.156:6829/132919] (peer_addr_for_me v2:172.21.15.156:0/70876)
...

Why the the nonce in the peer's-addr-for-me is 70876?

Just after learning the addrs:

2023-02-23T07:07:23.874+0000 7f46c82e0700  1 --2- [v2:172.21.15.156:6828/132919,v1:172.21.15.156:6829/132919] >>  conn(0x555603f64000 0x555603f6a000 unknown :-1 s=HELLO_ACCEPTING pgs=0 cs=0 l=1 rev1=1 crypto rx=0 tx=0 comp rx=0 tx=0).handle_hello state changed while learned_addr, mark_down or  replacing must be happened just now
2023-02-23T07:07:23.874+0000 7f46a2045700 10 osd.3 pg_epoch: 51 pg[2.7( empty local-lis/les=38/39 n=0 ec=16/16 lis/c=38/38 les/c/f=39/39/0 sis=38) [3,0] r=0 lpr=39 crt=0'0 mlcod 0'0 peering mbc={}] state<Started/Primary/Peering/GetInfo>:  no prior_set down osds, will clear prior_readable_until_ub before activating
2023-02-23T07:07:23.874+0000 7f46c1884700 10 osd.3 51  assuming hb_back_addrs match cluster_addrs [v2:172.21.15.156:6826/132919,v1:172.21.15.156:6827/132919]
2023-02-23T07:07:23.874+0000 7f46c7adf700  1 --2- [v2:172.21.15.156:6830/132919,v1:172.21.15.156:6831/132919] >>  conn(0x555603f64400 0x555603f6a580 unknown :-1 s=HELLO_ACCEPTING pgs=0 cs=0 l=1 rev1=1 crypto rx=0 tx=0 comp rx=0 tx=0).handle_hello state changed while learned_addr, mark_down or  replacing must be happened just now
2023-02-23T07:07:23.874+0000 7f46a2045700 10 osd.3 pg_epoch: 51 pg[2.7( empty local-lis/les=38/39 n=0 ec=16/16 lis/c=38/38 les/c/f=39/39/0 sis=38) [3,0] r=0 lpr=39 crt=0'0 mlcod 0'0 peering mbc={}] state<Started/Primary/Peering/GetInfo>:  querying info from osd.0
2023-02-23T07:07:23.874+0000 7f46c1884700  1 -- [v2:172.21.15.156:6828/132919,v1:172.21.15.156:6829/132919] set_addr_unknowns [v2:172.21.15.156:6824/132919,v1:172.21.15.156:6825/132919]
2023-02-23T07:07:23.874+0000 7f46a2045700 20 osd.3 pg_epoch: 51 pg[2.7( empty local-lis/les=38/39 n=0 ec=16/16 lis/c=38/38 les/c/f=39/39/0 sis=38) [3,0] r=0 lpr=39 crt=0'0 mlcod 0'0 peering mbc={}] prepare_stats_for_publish reporting purged_snaps []
2023-02-23T07:07:23.874+0000 7f46a2045700 15 osd.3 pg_epoch: 51 pg[2.7( empty local-lis/les=38/39 n=0 ec=16/16 lis/c=38/38 les/c/f=39/39/0 sis=38) [3,0] r=0 lpr=39 crt=0'0 mlcod 0'0 peering mbc={}] publish_stats_to_osd 39:24
2023-02-23T07:07:23.874+0000 7f46c1884700  1 -- [v2:172.21.15.156:6828/132919,v1:172.21.15.156:6829/132919] set_addr_unknowns now [v2:172.21.15.156:6828/132919,v1:172.21.15.156:6829/132919]
...
2023-02-23T07:07:23.874+0000 7f46c1884700 10 osd.3 51  final client_addrs [v2:172.21.15.156:6824/132919,v1:172.21.15.156:6825/132919], cluster_addrs [v2:172.21.15.156:6826/132919,v1:172.21.15.156:6827/132919], hb_back_addrs [v2:172.21.15.156:6830/132919,v1:172.21.15.156:6831/132919], hb_front_addrs [v2:0.0.0.0:6828/132919,v1:0.0.0.0:6829/132919]

So, hb_back_addrs was set but hb_front_addrs remained 0.0.0.0.

The direct reason why the OSDMap got wrong hb address is that the OSD had sent so:

2023-02-23T07:07:23.874+0000 7f46c1884700 10 osd.3 51  final client_addrs [v2:172.21.15.156:6824/132919,v1:172.21.15.156:6825/132919], cluster_addrs [v2:172.21.15.156:6826/132919,v1:172.21.15.156:6827/132919], hb_back_addrs [v2:172.21.15.156:6830/132919,v1:172.21.15.156:6831/132919], hb_front_addrs [v2:0.0.0.0:6828/132919,v1:0.0.0.0:6829/132919]

void OSD::_send_boot()
{ 
  // ...
  MOSDBoot *mboot = new MOSDBoot(
    superblock, get_osdmap_epoch(), service.get_boot_epoch(),
    hb_back_addrs, hb_front_addrs, cluster_addrs,
    CEPH_FEATURES_ALL);
  dout(10) << " final client_addrs " << client_addrs
           << ", cluster_addrs " << cluster_addrs
           << ", hb_back_addrs " << hb_back_addrs
           << ", hb_front_addrs " << hb_front_addrs
           << dendl;
  _collect_metadata(&mboot->metadata);
  monc->send_mon_message(mboot);

What's interesting is that the log contains:

2023-02-23T07:07:23.874+0000 7f46c1884700 10 osd.3 51  assuming hb_back_addrs match cluster_addrs [v2:172.21.15.156:6826/132919,v1:172.21.15.156:6827/132919]

BUT lacks the analogous debug for the front heartbeat messenger:

  local_connection = hb_back_server_messenger->get_loopback_connection().get();
  if (hb_back_server_messenger->set_addr_unknowns(cluster_addrs)) {
    dout(10) << " assuming hb_back_addrs match cluster_addrs " 
             << cluster_addrs << dendl;
    hb_back_addrs = hb_back_server_messenger->get_myaddrs();
  }
  if (auto session = local_connection->get_priv(); !session) {
    hb_back_server_messenger->ms_deliver_handle_fast_connect(local_connection);
  }

  local_connection = hb_front_server_messenger->get_loopback_connection().get();
  if (hb_front_server_messenger->set_addr_unknowns(client_addrs)) {
    dout(10) << " assuming hb_front_addrs match client_addrs " 
             << client_addrs << dendl;
    hb_front_addrs = hb_front_server_messenger->get_myaddrs();
  }

Why the return of set_addr_unknowns turned out to be false?

Why the return of set_addr_unknowns turned out to be false?

Because it was already learnt!

bool AsyncMessenger::set_addr_unknowns(const entity_addrvec_t &addrs)
{
  ldout(cct,1) << __func__ << " " << addrs << dendl;
  bool ret = false;
  std::lock_guard l{lock};

  entity_addrvec_t newaddrs = *my_addrs;
  for (auto& a : newaddrs.v) {
    if (a.is_blank_ip()) {
      int type = a.get_type();
      int port = a.get_port();
      uint32_t nonce = a.get_nonce();
      for (auto& b : addrs.v) {
        if (a.get_family() == b.get_family()) {
          ldout(cct,1) << __func__ << " assuming my addr " << a
                       << " matches provided addr " << b << dendl;
          a = b;
          a.set_nonce(nonce);
          a.set_type(type);
          a.set_port(port);
          ret = true;
          break;
        }
      }
    }
  }
  set_myaddrs(newaddrs);
  if (ret) {
    _init_local_connection();
  }
  ldout(cct,1) << __func__ << " now " << *my_addrs << dendl;
  return ret;
}

The root cause is that we cached the zeroed addresses acquired at the very beginning.

class Messenger {
  // ...
  const entity_addrvec_t& get_myaddrs() {
    return *my_addrs;
  }

Please note the get_myaddrs() return a const reference but hb_front_addrs (and friends, BTW) in OSD::_send_boot() is an lvalue:

void OSD::_send_boot()
{
  dout(10) << "_send_boot" << dendl;
  Connection *local_connection =
    cluster_messenger->get_loopback_connection().get();
  entity_addrvec_t client_addrs = client_messenger->get_myaddrs();
  entity_addrvec_t cluster_addrs = cluster_messenger->get_myaddrs();
  entity_addrvec_t hb_back_addrs = hb_back_server_messenger->get_myaddrs();
  entity_addrvec_t hb_front_addrs = hb_front_server_messenger->get_myaddrs();

  dout(20) << " initial client_addrs " << client_addrs
           << ", cluster_addrs " << cluster_addrs
           << ", hb_back_addrs " << hb_back_addrs
           << ", hb_front_addrs " << hb_front_addrs
           << dendl;
  // ...
  if (hb_front_server_messenger->set_addr_unknowns(client_addrs)) {
    dout(10) << " assuming hb_front_addrs match client_addrs " 
             << client_addrs << dendl;
    hb_front_addrs = hb_front_server_messenger->get_myaddrs();
  }
  // ...
  MOSDBoot *mboot = new MOSDBoot(
    superblock, get_osdmap_epoch(), service.get_boot_epoch(),
    hb_back_addrs, hb_front_addrs, cluster_addrs,
    CEPH_FEATURES_ALL);
  dout(10) << " final client_addrs " << client_addrs
           << ", cluster_addrs " << cluster_addrs
           << ", hb_back_addrs " << hb_back_addrs
           << ", hb_front_addrs " << hb_front_addrs
           << dendl;
  _collect_metadata(&mboot->metadata);
  monc->send_mon_message(mboot);
  set_state(STATE_BOOTING);
}

Pretty sure this is the same stale messenger address issue, except with hb_back_addrs instead of hb_front_address:

/a/yuriw-2024-02-03_16:26:04-rados-wip-yuri10-testing-2024-02-02-1149-pacific-distro-default-smithi/7545493/teuthology.log

2024-02-04T00:42:34.150 INFO:tasks.ceph.osd.4.smithi005.stderr:2024-02-04T00:42:34.145+0000 7f73b2ba5200 -1 osd.4 50 log_to_monitors {default=true}
2024-02-04T00:42:34.463 INFO:tasks.ceph.osd.4.smithi005.stderr:2024-02-04T00:42:34.461+0000 7f73ab0db700 -1 osd.4 50 set_numa_affinity unable to identify public interface '' numa node: (2) No such file or directory
2024-02-04T00:42:36.466 INFO:tasks.ceph.osd.4.smithi005.stderr:2024-02-04T00:42:36.461+0000 7f73a28ca700 -1 log_channel(cluster) log [ERR] : map e69 had wrong heartbeat back addr ([v2:0.0.0.0:6838/129129,v1:0.0.0.0:6839/129129] != my [v2:172.21.15.5:6838/129129,v1:172.21.15.5:6839/129129])

After learning the addrs, hb_front_addrs was set, but hb_back_addrs remained at 0.0.0.0:

2024-02-04T00:42:34.461+0000 7f73b1b6e700  1 --2- [v2:172.21.15.5:6838/129129,v1:172.21.15.5:6839/129129] >>  conn(0x55b7b6d3c800 0x55b7b6cecd00 unknown :-1 s=HELLO_ACCEPTING pgs=0 cs=0 l=1 rev1=1 rx=0 tx=0).handle_hello state changed while learned_addr, mark_down or  replacing must be happened just now
2024-02-04T00:42:34.461+0000 7f73ab0db700  1 -- [v2:0.0.0.0:6834/129129,v1:0.0.0.0:6835/129129] set_addr_unknowns assuming my addr v1:0.0.0.0:6835/129129 matches provided addr v2:172.21.15.5:6832/129129
2024-02-04T00:42:34.461+0000 7f73ab0db700 10 osd.4 50  new session (outgoing) 0x55b7b6d36780 con=0x55b7b56b6c00 addr=v2:172.21.15.5:6834/129129
2024-02-04T00:42:34.461+0000 7f73ab0db700  1 -- [v2:172.21.15.5:6834/129129,v1:172.21.15.5:6835/129129] set_addr_unknowns now [v2:172.21.15.5:6834/129129,v1:172.21.15.5:6835/129129]
2024-02-04T00:42:34.461+0000 7f73ab0db700 10 osd.4 50  assuming cluster_addrs match client_addrs [v2:172.21.15.5:6832/129129,v1:172.21.15.5:6833/129129]
2024-02-04T00:42:34.461+0000 7f73b1b6e700  1 --2- [v2:0.0.0.0:6836/129129,v1:0.0.0.0:6837/129129] >>  conn(0x55b7b6d3cc00 0x55b7b6ced200 unknown :-1 s=NONE pgs=0 cs=0 l=0 rev1=0 rx=0 tx=0).accept
2024-02-04T00:42:34.461+0000 7f73ab0db700  1 -- [v2:172.21.15.5:6838/129129,v1:172.21.15.5:6839/129129] set_addr_unknowns [v2:172.21.15.5:6834/129129,v1:172.21.15.5:6835/129129]
2024-02-04T00:42:34.461+0000 7f73ab0db700  1 -- [v2:172.21.15.5:6838/129129,v1:172.21.15.5:6839/129129] set_addr_unknowns now [v2:172.21.15.5:6838/129129,v1:172.21.15.5:6839/129129]
2024-02-04T00:42:34.461+0000 7f73ab0db700  1 -- [v2:0.0.0.0:6836/129129,v1:0.0.0.0:6837/129129] set_addr_unknowns [v2:172.21.15.5:6832/129129,v1:172.21.15.5:6833/129129]
2024-02-04T00:42:34.461+0000 7f73ab0db700  1 -- [v2:0.0.0.0:6836/129129,v1:0.0.0.0:6837/129129] set_addr_unknowns assuming my addr v2:0.0.0.0:6836/129129 matches provided addr v2:172.21.15.5:6832/129129
2024-02-04T00:42:34.461+0000 7f73ab0db700  1 -- [v2:0.0.0.0:6836/129129,v1:0.0.0.0:6837/129129] set_addr_unknowns assuming my addr v1:0.0.0.0:6837/129129 matches provided addr v2:172.21.15.5:6832/129129
2024-02-04T00:42:34.461+0000 7f73ab0db700  1 -- [v2:172.21.15.5:6836/129129,v1:172.21.15.5:6837/129129] set_addr_unknowns now [v2:172.21.15.5:6836/129129,v1:172.21.15.5:6837/129129]
2024-02-04T00:42:34.461+0000 7f73ab0db700 10 osd.4 50  assuming hb_front_addrs match client_addrs [v2:172.21.15.5:6832/129129,v1:172.21.15.5:6833/129129]

...

2024-02-04T00:42:34.461+0000 7f73ab0db700 -1 osd.4 50 set_numa_affinity unable to identify public interface '' numa node: (2) No such file or directory
2024-02-04T00:42:34.461+0000 7f73ab0db700  1 osd.4 50 set_numa_affinity not setting numa affinity
2024-02-04T00:42:34.461+0000 7f73ab0db700 10 osd.4 50  final client_addrs [v2:172.21.15.5:6832/129129,v1:172.21.15.5:6833/129129], cluster_addrs [v2:172.21.15.5:6834/129129,v1:172.21.15.5:6835/129129], hb_back_addrs [v2:0.0.0.0:6838/129129,v1:0.0.0.0:6839/129129], hb_front_addrs [v2:172.21.15.5:6836/129129,v1:172.21.15.5:6837/129129]

bump up