[Starlingx-discuss] [QUERY] Worker nodes in reboot loop due to heartbeat miss as per hbsAgent.log

Gaur, Shubham Shubham.Gaur at commscope.com
Thu Nov 5 17:01:02 UTC 2020


Hi All,



Setup:      Distributed StarlingX 4.0.

Problem: Central cloud is up and running, but in the edge cloud we see the continuous reboot of worker nodes.

  *   Edge cloud configuration: 1 Controller and 2 Worker.
  *   Attached logs of HBSAgent. (Couldn't find anything within puppet logs)
  *   Tried locking-unlocking the worker nodes as per the alarm raised within fm alarm-list.
  *   Couldn't resolve the issue.
  *   Is there any other logs to look after? Help required!

──────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────



FM Alarm-List

​+----------+-------------------------------------------------------------------------+------------------------------+----------+---------------+

| Alarm ID | Reason Text                                                             | Entity ID                    | Severity | Time Stamp    |

+----------+-------------------------------------------------------------------------+------------------------------+----------+---------------+

| 200.004  | worker-1 experienced a service-affecting failure. Auto-recovery in      | host=worker-1                | critical | 2020-11-05T14 |

|          | progress. Manual Lock and Unlock may be required if auto-recovery is    |                              |          | :15:55.127546 |

|          | unsuccessful.                                                           |                              |          |               |

|          |                                                                         |                              |          |               |

| 200.005  | worker-1 experienced a persistent critical 'Management Network'         | host=worker-1.network=       | critical | 2020-11-05T14 |

|          | communication failure.                                                  | Management                   |          | :15:45.610330 |

+------------------------------------------------------------------------------------+------------------------------+----------+---------------+



──────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────



WORKER 1

---------After Unlock-------

worker-1:~$ uptime

 09:41:11 up 4 min,  1 user,  load average: 0.75, 1.07, 0.52



worker-1:~$ tail -f /var/log/hbsClient.log

2020-11-05T09:38:31.754 [31382.00028] worker-1 hbsClient --- daemon_main.cpp   ( 434) main                    : Info : Build Date  : Thu Jul  2 16:51:50 UTC 2020

2020-11-05T09:38:31.754 [31382.00029] worker-1 hbsClient --- daemon_main.cpp   ( 435) main                    : Info : ------------------------------------------------------

2020-11-05T09:38:31.754 [31382.00030] worker-1 hbsClient --- nlEvent.cpp       ( 291) open_netlink_socket     : Info : NLMon Groups: 1

2020-11-05T09:38:31.754 [31382.00031] worker-1 hbsClient hbs hbsClient.cpp     (1349) daemon_service_run      : Info : Pmon Pulse Counter Timer init with 600 seconds timeout

2020-11-05T09:38:31.754 [31382.00032] worker-1 hbsClient hbs hbsClient.cpp     (1353) daemon_service_run      : Info : Process Stall-Monitor starting in 600 seconds

2020-11-05T09:38:31.754 [31382.00033] worker-1 hbsClient hbs hbsClient.cpp     (1356) daemon_service_run      : Info : Ready Event Period 5 seconds

2020-11-05T09:38:31.754 [31382.00034] worker-1 hbsClient hbs hbsClient.cpp     (1359) daemon_service_run      : Info : Sending Heartbeat Ready Event

2020-11-05T09:38:31.783 [31382.00035] worker-1 hbsClient hbs hbsClient.cpp     ( 913) _service_pulse_request  : Info : Caching New RRI: 3 (from controller-0)

2020-11-05T09:38:31.783 [31382.00036] worker-1 hbsClient hbs hbsClient.cpp     (1045) _service_pulse_request  : Warn : controller-0 Mgmnt proividing no cluster history

2020-11-05T09:38:36.514 [31382.00037] worker-1 hbsClient hbs hbsClient.cpp     (1037) _service_pulse_request  : Info : controller-0 Mgmnt providing cluster history

...

...

2020-11-05T09:43:07.144 [31382.00038] worker-1 hbsClient sig daemon_signal.cpp ( 172) daemon_signal_hdlr      : Info : Received SIGTERM

2020-11-05T09:43:07.144 [31382.00039] worker-1 hbsClient --- daemon_config.cpp ( 301) daemon_dump_cfg         : Info : Configuration Settings ...

2020-11-05T09:43:07.144 [31382.00040] worker-1 hbsClient --- daemon_config.cpp ( 302) daemon_dump_cfg         : Info : scheduling_priority   = 99

2020-11-05T09:43:07.144 [31382.00041] worker-1 hbsClient --- daemon_config.cpp ( 314) daemon_dump_cfg         : Info : mgmnt_iface           = vlan143

2020-11-05T09:43:07.144 [31382.00042] worker-1 hbsClient --- daemon_config.cpp ( 315) daemon_dump_cfg         : Info : clstr_iface           = vlan143

2020-11-05T09:43:07.144 [31382.00043] worker-1 hbsClient --- daemon_config.cpp ( 316) daemon_dump_cfg         : Info : multicast             = 239.1.1.2

2020-11-05T09:43:07.144 [31382.00044] worker-1 hbsClient --- daemon_config.cpp ( 327) daemon_dump_cfg         : Info : uri_path              =

2020-11-05T09:43:07.144 [31382.00045] worker-1 hbsClient --- daemon_config.cpp ( 328) daemon_dump_cfg         : Info : keystone_prefix_path  =

2020-11-05T09:43:07.144 [31382.00046] worker-1 hbsClient --- daemon_config.cpp ( 329) daemon_dump_cfg         : Info : keystone_auth_host    =

2020-11-05T09:43:07.144 [31382.00047] worker-1 hbsClient --- daemon_config.cpp ( 330) daemon_dump_cfg         : Info : keystone_identity_uri =

2020-11-05T09:43:07.144 [31382.00048] worker-1 hbsClient --- daemon_config.cpp ( 331) daemon_dump_cfg         : Info : keystone_auth_uri     =

2020-11-05T09:43:07.144 [31382.00049] worker-1 hbsClient --- daemon_config.cpp ( 336) daemon_dump_cfg         : Info : keystone_region_name  = none

2020-11-05T09:43:07.144 [31382.00050] worker-1 hbsClient --- daemon_config.cpp ( 338) daemon_dump_cfg         : Info : barbican_api_host     = none

2020-11-05T09:43:07.144 [31382.00051] worker-1 hbsClient --- daemon_config.cpp ( 340) daemon_dump_cfg         : Info : mtc_rx_mgmnt_port     = 2101

2020-11-05T09:43:07.144 [31382.00052] worker-1 hbsClient --- daemon_config.cpp ( 358) daemon_dump_cfg         : Info : pmon_pulse_port       = 2109

2020-11-05T09:43:07.144 [31382.00053] worker-1 hbsClient --- daemon_config.cpp ( 362) daemon_dump_cfg         : Info : start_delay           = 600

2020-11-05T09:43:07.144 [31382.00054] worker-1 hbsClient --- daemon_config.cpp ( 366) daemon_dump_cfg         : Info : mask                  = 1180003c

2020-11-05T09:43:07.144 [31382.00055] worker-1 hbsClient --- daemon_config.cpp ( 367) daemon_dump_cfg         : Info : mode                  = none

2020-11-05T09:43:07.144 [31382.00056] worker-1 hbsClient --- daemon_config.cpp ( 370) daemon_dump_cfg         : Info : stall_pmon_thld       = 1250

2020-11-05T09:43:07.144 [31382.00057] worker-1 hbsClient --- daemon_config.cpp ( 371) daemon_dump_cfg         : Info : stall_mon_period      = 120

2020-11-05T09:43:07.144 [31382.00058] worker-1 hbsClient --- daemon_config.cpp ( 372) daemon_dump_cfg         : Info : stall_poll_period     = 20

2020-11-05T09:43:07.144 [31382.00059] worker-1 hbsClient --- daemon_config.cpp ( 373) daemon_dump_cfg         : Info : stall_rec_thld        = 2

2020-11-05T09:43:07.144 [31382.00060] worker-1 hbsClient --- daemon_config.cpp ( 404) daemon_dump_cfg         : Info : debug_filter          = none

2020-11-05T09:43:07.144 [31382.00061] worker-1 hbsClient --- daemon_config.cpp ( 405) daemon_dump_cfg         : Info : debug_event           = none

2020-11-05T09:43:07.144 -----------------------------------------------------------------------------------------

2020-11-05T09:43:07.144 Service State and Traceback -------------------------------------------------------------

2020-11-05T09:43:07.144 -----------------------------------------------------------------------------------------

packet_write_wait: Connection to 192.168.22.105 port 22: Broken pipe



Session stopped

    - Press <return> to exit tab

    - Press R to restart session

    - Press S to save terminal output to file



───────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────



CONTROLLER-0: SYSTEM: edge



------Before Unlocking Worker-----

[root at controller-0 log(keystone_admin)]# tail -f /var/log/hbsAgent.log

2020-11-05T08:19:12.739 +--------------+-----+-------+-------+-------+-------+------------+----------+-----------------+

2020-11-05T09:19:12.739 +--------------+-----+-------+-------+-------+-------+------------+----------+-----------------+

2020-11-05T09:19:12.739 | Mgmnt:    3  | Mon |  Mis  |  Max  |  Deg  | Fail  | Pulses Tot |  Pulses  | Enabled  ( 100) |

2020-11-05T09:19:12.739 +--------------+-----+-------+-------+-------+-------+------------+----------+-----------------+

2020-11-05T09:19:12.739 | controller-0 |  n  |     0 |     0 |     0 |     0 |          0 |        0 | 100 msec

2020-11-05T09:19:12.739 | worker-0     |  n  |     0 |     0 |    12 |    12 |       1d2c |       31 | 100 msec

2020-11-05T09:19:12.739 | worker-1     |  n  |     0 |     0 |     8 |     8 |       1750 |      42f | 100 msec

2020-11-05T09:19:12.739 +--------------+-----+-------+-------+-------+-------+------------+----------+-----------------+

2020-11-05T09:33:29.862 [85778.00574] controller-0 hbsAgent hbs nodeClass.cpp     (7761) mon_host                : Info : worker-1 heartbeat stop

2020-11-05T09:33:29.862 [85778.00575] controller-0 hbsAgent hbs hbsAgent.cpp      (2004) daemon_service_run      : Info : worker-1 heartbeat service disabled by stop command



------After Unlocking Worker-----

[root at controller-0 log(keystone_admin)]# tail -f /var/log/hbsAgent.log

2020-11-05T09:33:29.862 [85778.00574] controller-0 hbsAgent hbs nodeClass.cpp     (7761) mon_host                : Info : worker-1 heartbeat stop

2020-11-05T09:33:29.862 [85778.00575] controller-0 hbsAgent hbs hbsAgent.cpp      (2004) daemon_service_run      : Info : worker-1 heartbeat service disabled by stop command

2020-11-05T09:38:36.442 [85778.00576] controller-0 hbsAgent hbs hbsCluster.cpp    ( 265) hbs_cluster_add         : Info : worker-1 added to cluster

2020-11-05T09:38:36.442 [85778.00577] controller-0 hbsAgent hbs hbsCluster.cpp    ( 201) cluster_list            : Info : cluster: worker-1

2020-11-05T09:38:36.442 [85778.00578] controller-0 hbsAgent hbs nodeClass.cpp     (7749) mon_host                : Info : worker-1 heartbeat start

2020-11-05T09:38:36.539 [85778.00579] controller-0 hbsAgent hbs hbsCluster.cpp    ( 453) hbs_cluster_update      : Info : controller-0 added new controller-0:Mgmnt history to vault ; now have 1 network views

2020-11-05T09:38:36.544 [85778.00580] controller-0 hbsAgent hbs hbsCluster.cpp    ( 631) hbs_cluster_send        : Info : cluster state notification Reason: worker-1 Mgmnt heartbeat start

2020-11-05T09:38:36.544 Cluster Vault : C0 Mgmnt  [1:1]>[0:0] [0:0] [0:0] [0:0] [0:0] [0:0] [0:0] [0:0] [0:0] [0:0] [0:0] [0:0] [0:0] [0:0] [0:0] [0:0] [0:0] [0:0] [0:0]

2020-11-05T09:38:37.490 [85778.00581] controller-0 hbsAgent hbs hbsCluster.cpp    ( 631) hbs_cluster_send        : Info : cluster state notification Reason: worker-1 Mgmnt heartbeat pass

2020-11-05T09:38:37.490 Cluster Vault : C0 Mgmnt  [1:1] [1:1] [1:1] [1:1] [1:1] [1:1] [1:1] [1:1] [1:1] [1:1]>[0:0] [0:0] [0:0] [0:0] [0:0] [0:0] [0:0] [0:0] [0:0] [0:0]

2020-11-05T09:42:51.607 [85778.00582] controller-0 hbsAgent hbs nodeClass.cpp     (8593) lost_pulses             : Info : worker-1 Mgmnt Pulse Miss (  2) (max:  1)

2020-11-05T09:42:51.713 [85778.00583] controller-0 hbsAgent hbs nodeClass.cpp     (8593) lost_pulses             : Info : worker-1 Mgmnt Pulse Miss (  3) (max:  2)

2020-11-05T09:42:51.818 [85778.00584] controller-0 hbsAgent hbs nodeClass.cpp     (8593) lost_pulses             : Info : worker-1 Mgmnt Pulse Miss (  4) (max:  3)

2020-11-05T09:42:51.818 [85778.00585] controller-0 hbsAgent hbs nodeClass.cpp     (8616) lost_pulses             : Warn : worker-1 Mgmnt -> MINOR

2020-11-05T09:42:51.923 [85778.00586] controller-0 hbsAgent hbs nodeClass.cpp     (8586) lost_pulses             : Info : worker-1 Mgmnt Pulse Miss (  5) (max:  4) (in minor)

2020-11-05T09:42:52.028 [85778.00587] controller-0 hbsAgent hbs nodeClass.cpp     (8586) lost_pulses             : Info : worker-1 Mgmnt Pulse Miss (  6) (max:  5) (in minor)

2020-11-05T09:42:52.028 [85778.00588] controller-0 hbsAgent alm alarm.cpp         ( 146) alarm_                  : Info : worker-1 Management set major 200.005

2020-11-05T09:42:52.028 [85778.00589] controller-0 hbsAgent hbs nodeClass.cpp     (8635) lost_pulses             : Warn : worker-1 Mgmnt -> DEGRADED

2020-11-05T09:42:52.133 [85778.00590] controller-0 hbsAgent hbs nodeClass.cpp     (8579) lost_pulses             : Info : worker-1 Mgmnt Pulse Miss (  7) (max:  6) (in degrade)

2020-11-05T09:42:52.238 [85778.00591] controller-0 hbsAgent hbs nodeClass.cpp     (8579) lost_pulses             : Info : worker-1 Mgmnt Pulse Miss (  8) (max:  7) (in degrade)

2020-11-05T09:42:52.343 [85778.00592] controller-0 hbsAgent hbs nodeClass.cpp     (8579) lost_pulses             : Info : worker-1 Mgmnt Pulse Miss (  9) (max:  8) (in degrade)

2020-11-05T09:42:52.448 [85778.00593] controller-0 hbsAgent hbs nodeClass.cpp     (8562) lost_pulses             : Info : worker-1 Mgmnt Pulse Miss (10) (log throttled to every 4095)

2020-11-05T09:42:52.448 [85778.00594] controller-0 hbsAgent hbs nodeClass.cpp     (8705) lost_pulses             :Error : worker-1 Mgmnt *** Heartbeat Loss ***

2020-11-05T09:42:52.448 [85778.00595] controller-0 hbsAgent alm alarm.cpp         ( 146) alarm_                  : Info : worker-1 Management set critical 200.005

2020-11-05T09:42:52.448 controller-0 view from controller-0 event Mgmnt: 1:1 . . . . . . . . . . 1:0 . . . . . . . .

2020-11-05T09:42:52.448 [85778.00596] controller-0 hbsAgent hbs hbsCluster.cpp    ( 631) hbs_cluster_send        : Info : cluster state notification Reason: worker-1 heartbeat loss

2020-11-05T09:42:52.448 Cluster Vault : C0 Mgmnt  [1:1] [1:1] [1:1] [1:1] [1:1] [1:1] [1:0] [1:0] [1:0] [1:0] [1:0] [1:0] [1:0] [1:0] [1:0]>[1:1] [1:1] [1:1] [1:1] [1:1]

2020-11-05T09:42:52.449 [85778.00597] controller-0 hbsAgent hbs nodeClass.cpp     (7761) mon_host                : Info : worker-1 heartbeat stop

2020-11-05T09:42:52.449 [85778.00598] controller-0 hbsAgent hbs hbsCluster.cpp    ( 329) hbs_cluster_del         : Info : worker-1 deleted from cluster

2020-11-05T09:42:52.449 [85778.00599] controller-0 hbsAgent hbs hbsCluster.cpp    ( 201) cluster_list            : Info : cluster:

2020-11-05T09:42:52.449 [85778.00600] controller-0 hbsAgent hbs hbsCluster.cpp    ( 631) hbs_cluster_send        : Info : cluster state notification Reason: worker-1 deleted

2020-11-05T09:42:52.449 [85778.00601] controller-0 hbsAgent hbs hbsAgent.cpp      (2004) daemon_service_run      : Info : worker-1 heartbeat service disabled by stop command



Thanks and regards,

Shubham

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.starlingx.io/pipermail/starlingx-discuss/attachments/20201105/d3bea6c4/attachment-0001.html>


More information about the Starlingx-discuss mailing list