Hello,
we have continuous problem with the heartbeat for some users.
The endpoint is green and fine but in central it's red.
Here the last log during the problem (heartbeat log)
a 2021-06-23T06:45:27.764Z [5880:8000] - Received request to enable enhanced application control a 2021-06-23T06:45:27.771Z [5880:8000] - Sending login status. a 2021-06-23T06:45:28.098Z [5880:8000] - Received request to disable enhanced application control for C:\program files (x86)\internet explorer\iexplore.exe a 2021-06-23T06:45:28.138Z [5880:8000] - Received request to disable enhanced application control for C:\program files (x86)\internet explorer\iexplore.exe a 2021-06-23T06:45:41.410Z [5880:8000] - Sending health status: {"admin":1, "health":1, "service":1, "threat":1} a 2021-06-23T07:15:11.868Z [5880:8000] - Received request to disable enhanced application control for C:\program files (x86)\google\chrome\application\chrome.exe a 2021-06-23T10:22:33.571Z [5880:7476] - ---------------------------------------------------------------------------------------------------- a 2021-06-23T10:22:33.572Z [5880:7476] - Stopped Heartbeat a 2021-06-23T10:22:33.572Z [5880:7476] - ---------------------------------------------------------------------------------------------------- a 2021-06-23T10:22:37.665Z [19648:19496] - ---------------------------------------------------------------------------------------------------- a 2021-06-23T10:22:37.666Z [19648:19496] - Starting Heartbeat version 1.11.194.0 a 2021-06-23T10:22:37.666Z [19648:19496] - ---------------------------------------------------------------------------------------------------- a 2021-06-23T10:22:38.124Z [19648:16596] - Connection succeeded. a 2021-06-23T10:22:38.125Z [19648:16596] - Connected to '3a343c11-a991-4d63-ab52-1df31f3ce352' at IP address 52.5.76.173 on port 8347 a 2021-06-23T10:22:38.140Z [19648:16596] - Sending network status. Active Interfaces: MAC: 00:FF:39:01:DF:1B - INET: 192.168.181.22 - INET6: fe80::507c:e745:b4b8:e1e7 MAC: 24:41:8C:31:94:12 - INET: 192.168.1.3 - INET6: fe80::10a7:ca61:5e5e:2034 a 2021-06-23T10:22:38.400Z [19648:16596] - Received request to enable enhanced application control a 2021-06-23T10:22:38.400Z [19648:16596] - Sending login status. a 2021-06-23T10:22:52.077Z [19648:16596] - Sending health status: {"health":3} a 2021-06-23T10:51:43.762Z [19648:16596] - Received request to disable enhanced application control for C:\program files (x86)\internet explorer\iexplore.exe a 2021-06-23T11:31:11.576Z [19648:16596] - Received request to disable enhanced application control for C:\program files (x86)\google\chrome\application\chrome.exe a 2021-06-23T12:44:45.877Z [19648:16596] - Received request to disable enhanced application control for C:\program files\internet explorer\iexplore.exe a 2021-06-23T13:58:12.169Z [19648:16596] - Connection closed (network error). a 2021-06-23T13:58:13.181Z [19648:16596] - Connection failed. a 2021-06-23T14:08:02.495Z [19648:16596] - Connection succeeded. a 2021-06-23T14:08:02.496Z [19648:16596] - Connected to '3a343c11-a991-4d63-ab52-1df31f3ce352' at IP address 52.5.76.173 on port 8347 a 2021-06-23T14:08:02.510Z [19648:16596] - Sending network status. Active Interfaces: MAC: 00:FF:39:01:DF:1B - INET: 192.168.181.22 - INET6: fe80::507c:e745:b4b8:e1e7 MAC: 24:41:8C:31:94:12 - INET: 192.168.1.3 - INET6: fe80::10a7:ca61:5e5e:2034 a 2021-06-23T14:08:02.738Z [19648:16596] - Received request to enable enhanced application control a 2021-06-23T14:08:02.741Z [19648:16596] - Sending login status. a 2021-06-23T14:08:03.244Z [19648:16596] - Received request to disable enhanced application control for C:\program files (x86)\google\chrome\application\chrome.exe a 2021-06-23T14:08:13.160Z [19648:16596] - Sending health status: {"health":3} a 2021-06-23T14:54:57.625Z [19648:16596] - Received request to disable enhanced application control for C:\program files (x86)\internet explorer\iexplore.exe a 2021-06-23T14:54:57.655Z [19648:16596] - Received request to disable enhanced application control for C:\program files (x86)\internet explorer\iexplore.exe a 2021-06-23T15:31:08.146Z [19648:16596] - Sending network status. Active Interfaces: MAC: 24:41:8C:31:94:12 - INET: 192.168.1.3 - INET6: fe80::10a7:ca61:5e5e:2034 a 2021-06-23T15:31:15.057Z [19648:16596] - Connection closed (network error). a 2021-06-23T15:31:37.141Z [19648:16596] - Connection failed. a 2021-06-23T15:31:52.423Z [19648:16596] - Connection succeeded. a 2021-06-23T15:31:52.423Z [19648:16596] - Connected to '3a343c11-a991-4d63-ab52-1df31f3ce352' at IP address 52.5.76.173 on port 8347 a 2021-06-23T15:31:52.438Z [19648:16596] - Sending network status. Active Interfaces: MAC: 00:FF:39:01:DF:1B - INET: 192.168.181.9 - INET6: fe80::507c:e745:b4b8:e1e7 MAC: 24:41:8C:31:94:12 - INET: 192.168.1.3 - INET6: fe80::10a7:ca61:5e5e:2034 a 2021-06-23T15:31:52.450Z [19648:16596] - Connection closed (network error). a 2021-06-23T15:31:53.728Z [19648:16596] - Connection succeeded. a 2021-06-23T15:31:53.729Z [19648:16596] - Connected to '3a343c11-a991-4d63-ab52-1df31f3ce352' at IP address 52.5.76.173 on port 8347 a 2021-06-23T15:31:53.747Z [19648:16596] - Sending network status. Active Interfaces: MAC: 00:FF:39:01:DF:1B - INET: 192.168.181.9 - INET6: fe80::507c:e745:b4b8:e1e7 MAC: 24:41:8C:31:94:12 - INET: 192.168.1.3 - INET6: fe80::10a7:ca61:5e5e:2034 a 2021-06-23T15:31:53.761Z [19648:16596] - Connection closed (network error). a 2021-06-23T15:31:55.000Z [19648:16596] - Connection succeeded. a 2021-06-23T15:31:55.000Z [19648:16596] - Connected to '3a343c11-a991-4d63-ab52-1df31f3ce352' at IP address 52.5.76.173 on port 8347 a 2021-06-23T15:31:55.015Z [19648:16596] - Sending network status. Active Interfaces: MAC: 00:FF:39:01:DF:1B - INET: 192.168.181.9 - INET6: fe80::507c:e745:b4b8:e1e7 MAC: 24:41:8C:31:94:12 - INET: 192.168.1.3 - INET6: fe80::10a7:ca61:5e5e:2034 a 2021-06-23T15:31:55.145Z [19648:16596] - Received request to enable enhanced application control a 2021-06-23T15:31:55.146Z [19648:16596] - Sending login status. a 2021-06-23T15:32:03.612Z [19648:16596] - Sending health status: {"health":3} a 2021-06-23T17:38:13.918Z [19648:16596] - Received request to disable enhanced application control for C:\program files (x86)\microsoft\edgeupdate\microsoftedgeupdate.exe a 2021-06-23T21:41:06.153Z [19648:16596] - Connection closed (network error). a 2021-06-24T06:29:22.504Z [19648:16596] - Connection failed. a 2021-06-24T06:31:26.179Z [19648:16596] - Connection succeeded. a 2021-06-24T06:31:26.179Z [19648:16596] - Connected to '3a343c11-a991-4d63-ab52-1df31f3ce352' at IP address 52.5.76.173 on port 8347 a 2021-06-24T06:31:26.193Z [19648:16596] - Sending network status. Active Interfaces: MAC: 00:FF:39:01:DF:1B - INET: 192.168.181.21 - INET6: fe80::507c:e745:b4b8:e1e7 MAC: 24:41:8C:31:94:12 - INET: 192.168.1.3 - INET6: fe80::10a7:ca61:5e5e:2034 a 2021-06-24T06:31:26.483Z [19648:16596] - Received request to enable enhanced application control a 2021-06-24T06:31:26.483Z [19648:16596] - Sending login status. a 2021-06-24T06:31:27.846Z [19648:16596] - Sending health status: {"health":3} a 2021-06-24T06:32:03.946Z [19648:16596] - Received request to disable enhanced application control for C:\program files (x86)\internet explorer\iexplore.exe a 2021-06-24T06:32:03.995Z [19648:16596] - Received request to disable enhanced application control for C:\program files (x86)\internet explorer\iexplore.exe a 2021-06-24T06:32:33.202Z [19648:16596] - Received request to disable enhanced application control for C:\program files\internet explorer\iexplore.exe a 2021-06-24T06:35:38.958Z [19648:16596] - Received request to disable enhanced application control for C:\program files (x86)\google\chrome\application\chrome.exe
We already contact the Sophos support... 1 month to have the reply from the support. You can imagin that we trying different ways to solve the problem, a momentary solution is re install Sophos but it's not for always.
Thank you !
Thanks Julian 100% agree with you regarding the support, slow, scripted and generally useless.
AS you can see, the heartbeat status switching every minutes ! In central it's green fixed...
that's the very same for us. and on the XG it's always flapping between 1 and 3 in heartbeat.log. Maybe this is happening when the computers are idle. It only happens for a small percentage of devices but I want to know why they appear risky to XG.
I will mention your case number in my support case. Currently they want me to re-register the XG into central because they cannot put fwcm-heartbeatd.log into debug. See my post community.sophos.com/.../logging-heartbeat-vs-fwcm-heartbeatd-500-opcode-failed
I will try this command thank you
I executed service fwcm-heartbeatd:debug -ds nosync
But i have this error in the log??
XG330_WP02_SFOS 18.0.5 MR-5-Build586# tail -f heartbeatd.log 2021-06-30 09:48:39 WARN Path.cpp[5602]:68 getExecutableFilename - Parsing executable filename failed. Falling back to full path: System 2021-06-30 09:48:39 WARN Path.cpp[5602]:68 getExecutableFilename - Parsing executable filename failed. Falling back to full path: System 2021-06-30 09:48:46 WARN Path.cpp[5602]:68 getExecutableFilename - Parsing executable filename failed. Falling back to full path: System 2021-06-30 09:48:47 WARN Path.cpp[5602]:68 getExecutableFilename - Parsing executable filename failed. Falling back to full path: System 2021-06-30 09:48:50 WARN Path.cpp[5602]:68 getExecutableFilename - Parsing executable filename failed. Falling back to full path: System 2021-06-30 09:48:55 WARN Path.cpp[5602]:68 getExecutableFilename - Parsing executable filename failed. Falling back to full path: System 2021-06-30 09:48:56 WARN Path.cpp[5602]:68 getExecutableFilename - Parsing executable filename failed. Falling back to full path: System 2021-06-30 09:48:56 WARN Path.cpp[5602]:68 getExecutableFilename - Parsing executable filename failed. Falling back to full path: System 2021-06-30 09:48:58 WARN Path.cpp[5602]:68 getExecutableFilename - Parsing executable filename failed. Falling back to full path: System 2021-06-30 09:48:59 WARN Path.cpp[5602]:68 getExecutableFilename - Parsing executable filename failed. Falling back to full path: System 2021-06-30 09:49:07 WARN Path.cpp[5602]:68 getExecutableFilename - Parsing executable filename failed. Falling back to full path: System 2021-06-30 09:49:07 WARN Path.cpp[5602]:68 getExecutableFilename - Parsing executable filename failed. Falling back to full path: System 2021-06-30 09:49:08 WARN Path.cpp[5602]:68 getExecutableFilename - Parsing executable filename failed. Falling back to full path: System 2021-06-30 09:49:11 WARN Path.cpp[5602]:68 getExecutableFilename - Parsing executable filename failed. Falling back to full path: System 2021-06-30 09:49:12 WARN Path.cpp[5602]:68 getExecutableFilename - Parsing executable filename failed. Falling back to full path: System 2021-06-30 09:49:12 WARN Path.cpp[5602]:68 getExecutableFilename - Parsing executable filename failed. Falling back to full path: System
this is "normal" junk in the heartbeat.log. community.sophos.com/.../heartbeatd-log-flooded-with-getexecutablefilename---parsing-executable-filename-failed-falling-back-to-full-path-system
check if you have entries in the fwcm-heartbeatd.log
For now i see in with an affected ip
XG330_WP02_SFOS 18.0.5 MR-5-Build586# tail -f heartbeatd.log | grep 192.9.220.17 2021-06-30 09:53:17 INFO ModuleStatus.cpp[5602]:138 processMessageStatus - Status request received from endpoint: 7d4ab402-2192-43b1-8640-7d8cfa812909 (192.9.220.17) health: 1 2021-06-30 09:53:20 INFO ModuleStatus.cpp[5602]:138 processMessageStatus - Status request received from endpoint: 7d4ab402-2192-43b1-8640-7d8cfa812909 (192.9.220.17) health: 3
What i have in this log fwcm-heartbeatd.log
Jun 30 09:54:42.323 dbg Flags: in_progress:0, trx_sts:0, grp_id:00000000-0000-0000-0000-000000000000) Jun 30 09:54:42.323 ntc trasaction_id status: (old:0, new:0), in_progress:0. Jun 30 09:54:42.323 dbg Going in poll mode Jun 30 09:55:42.220 dbg Time to punch heartbeat Jun 30 09:55:42.220 dbg Time to punch heartbeat. Will send this data: { "version": 2, "trxId": 0.0, "trxStatus": 0, "fwMetaData": { "capability": 7, "fwVersion": "XG330_WP02_18.0.5.586", "dispVersion": "XG330_WP02_SFOS 18.0.5 MR-5-Build586", "hostname": "X", "ram": 12, "cpuCores": 4, "haStatus": "primary", "haPairApplianceKey": "C33101CQDD32TC9", "haMode": "active-passive" } } Jun 30 09:55:42.220 dbg Preparing to send: URL: https://utm-cloudstation-eu-central-1.prod.hydra.sophos.com/sophos/api/v1/firewalls/heartbeats/3a343c11-a991-4d63-ab52-1df31f3ce352 , Data(321):{ "version": 2, "trxId": 0.0, "trxStatus": 0, "fwMetaData": { "capability": 7, "fwVersion": "XG330_WP02_18.0.5.586", "dispVersion": "XG330_WP02_SFOS 18.0.5 MR-5-Build586", "hostname": "X", "ram": 12, "cpuCores": 4, "haStatus": "primary", "haPairApplianceKey": "C33101CQDD32TC9", "haMode": "active-passive" } } Jun 30 09:55:42.293 dbg Response code: '200' Jun 30 09:55:42.294 dbg Response content len: '547' Jun 30 09:55:42.294 dbg Response content: '{"trxId":0,"customerId":"X","forceSync":false,"skipTransaction":false,"inactiveStatus":false,"firstFailedTime":null,"trxStatus":0,"groupId":null,"exportXGConfig":false,"fwMetaData":{"fwVersion":"XG330_WP02_18.0.5.586","dispVersion":"XG330_WP02_SFOS 18.0.5 MR-5-Build586","hostname":"FWXGAF-WDC-01","ipAddress":null,"ram":12,"cpuCores":4,"haStatus":"primary","haMode":"active-passive","haPairApplianceKey":"C33101CQDD32TC9","capability":7},"receivedTime":"2021-06-30T07:55:42.278+00:00","transactionFailed":false}' Jun 30 09:55:42.294 dbg HB POST returned:0, response_data:{ "trxId": 0, "customerId": "X", "forceSync": false, "skipTransaction": false, "inactiveStatus": false, "firstFailedTime": null, "trxStatus": 0, "groupId": null, "exportXGConfig": false, "fwMetaData": { "fwVersion": "XG330_WP02_18.0.5.586", "dispVersion": "XG330_WP02_SFOS 18.0.5 MR-5-Build586", "hostname": "FWXGAF-WDC-01", "ipAddress": null, "ram": 12, "cpuCores": 4, "haStatus": "primary", "haMode": "active-passive", "haPairApplianceKey": "C33101CQDD32TC9", "capability": 7 }, "receivedTime": "2021-06-30T07:55:42.278+00:00", "transactionFailed": false } Jun 30 09:55:42.294 dbg Flags: in_progress:0, trx_sts:0, grp_id:00000000-0000-0000-0000-000000000000) Jun 30 09:55:42.294 ntc trasaction_id status: (old:0, new:0), in_progress:0. Jun 30 09:55:42.294 dbg Going in poll mode
The EP is reporting a change in the status. So its a EP issue in the first place. Check the heartbeat.log on the endpoint in the installation directory if you can find a reason for the status change.
__________________________________________________________________________________________________________________