Handle.exe output sometimes does not contain "File"

[wsficke]

It appears that the issue with the changed output of Handle.exe in versions 4.0 and above, reported in rabbitmq/rabbitmq-management-agent#67 and rabbitmq/rabbitmq-management-agent#90, has not been resolved. This issue is relevant only on Windows. The new output no longer matches the expected format and is causing problems for the RabbitMQ agent. We request that this issue be reopened and addressed in a future release.

As mentioned in the original issue, the previous output of Handle.exe included a line starting with "Handle" which was used by the RabbitMQ agent to parse the information. However, the new output does not include this line, causing the agent to fail to parse the information properly. This issue has been discussed on the mailing list, and a possible fix was proposed in rabbitmq/rabbitmq-management-agent#90. However, it appears that this fix has not been implemented in the latest version of RabbitMQ.

We understand that the RabbitMQ team does not use GitHub issues for discussions, but we believe that reopening this issue will help to ensure that the problem is addressed and resolved in a future release. The proposed fix modifies the "find_files_line" function in rabbit_mgmt_external_stats.erl to look for the string "Nthandle" instead of "Handle" in the output of Handle.exe. This change would allow the function to properly parse the output of Handle.exe in versions 4.0 and above, and would help to prevent the problems that have been reported with the RabbitMQ agent on Windows.

Verbose but meaningless logging can have a negative impact on performance and efficiency. When a log contains a large amount of irrelevant information, it can be difficult to identify and troubleshoot actual problems. This can lead to increased time and effort spent searching through the log, and can also cause unnecessary strain on the system as it processes and stores the excessive data. Additionally, verbose but meaningless logging can fill up storage space more quickly, leading to potential issues with storage capacity and availability. It is important to ensure that logs contain only relevant and useful information to maximize the effectiveness of logging.

We appreciate your attention to this matter and thank you for your continued efforts to improve RabbitMQ.

[lukebakken]

Please follow our guidelines and start a discussion before opening an issue.

You don't specify which version of RabbitMQ and Erlang you are using. There is no indication in your report of what error you are actually seeing.

Here is the code that parses the output of handle.exe: https://github.com/rabbitmq/rabbitmq-server/blob/main/deps/rabbitmq_management_agent/src/rabbit_mgmt_external_stats.erl#L162-L188

Note that it does not distinguish between Handle or Nthandle, all it looks for is a line that contains File. Over the years we have gotten reports from RabbitMQ users on Windows who see the handle.exe output did not contain a line beginning with ' File '... message in their log files. The RabbitMQ team has never been able to reproduce this issue. I have contacted @markrussinovich over email to discuss this issue but have not heard back. Presumably he has more important issues to work on.

We would welcome a means to reliably reproduce a case where calling handle.exe on the RabbitMQ PID does NOT have File in the output.

[wsficke]

Sample system logs:

2022-12-09 12:53:20.612000-05:00 [error] <0.819.0> handle.exe output did not contain a line beginning with ' File ', unable to determine used file descriptor count: "\r\nNthandle v4.11 - Handle viewer\r\nCopyright (C) 1997-2017 Mark Russinovich\r\nSysinternals - www.sysinternals.com\r\n\r\nHandle type summary:\r\r\n ALPC Port : 1\r\r\n ALPC Port : 2\r\r\n Desktop : 1\r\r\n Directory : 2\r\r\n EtwRegistration : 26\r\r\n Event : 212\r\r\n Event : 42\r\r\n IoCompletion : 3\r\r\n Key : 9\r\r\n KeyedEvent : 1\r\r\n Mutant : 2\r\r\n Process : 4\r\r\n Thread : 19\r\r\n Timer : 3\r\r\n TpWorkerFactory : 32\r\r\n WindowStation : 2\r\r\nTotal handles: 361\r\r\n"

[lukebakken]

Note that the output you provide does not contain File, which is what the error message means. We still need to know what version of RabbitMQ you are using. Recent versions of RabbitMQ limit the number of times the above is logged, I believe.

[wsficke]

I have checked in with my ops team, and can confirm that we are running rabbit 3.10.7 with otp 25.0.3

[lukebakken]

Thanks for that information

[wsficke]

We have tested with the following versions of handle.exe in conjunction with above rabbit / opt version.

• handle_v3.01.exe
• handle_v3.20.exe
• handle_v3.42.exe
• handle_v3.51.exe
• handle_v4.00.exe
• handle_v4.1.exe
• handle_v4.21.exe
• handle_v4.22.exe
• handle_v5.0.exe

[lukebakken]

Continue here please - #6612 (comment)

[lukebakken]

@wsficke please read my comment - #6612 (comment)

As I said, we do not know the cause of this issue. I have some questions about RabbitMQ in the environment where you see the unable to determine message in your logs:

• What is the exact version of Windows that you are using?
• Are you using any antivirus, security scanning, or other similar tools on the servers running RabbitMQ?
• Has this issue always occurred in your environment, or did this environment work for a period of time without the log message?
• How often do you see the message in your log files? Are there stretches of time where the message is not logged, meaning that handle.exe is working as expected?

[lukebakken]

No problem! I have no idea what happened to your response, but this is in my email so I'll post it here:

---

We are running Windows Server 2008 R2 and Windows Server 2016. We are using Symantec enterprise security products. We are new rabbitmq adopters, so this issue was caught in the production environment post-release (recently).

There seems to be a longstanding, often-ignored broken integration.

The core problem is verbosity of logging. Some of my hosts complain,

"Could not find handle.exe, please install from sysinternals".

Accordingly, we have installed sysinternals.

Then, they complain

handle.exe output did not contain a line beginning with ' File ', unable to determine used file descriptor count: "\r\nNthandle v4.11 - Handle viewer\r\nCopyright (C) 1997-2017 Mark Russinovich\r\nSysinternals - [www.sysinternals.com\r\n\r\nHandle](http://www.sysinternals.com%5Cr%5Cn%5Cr%5Cnhandle/) type summary:\r\r\n ALPC Port : 2\r\r\n Desktop : 1\r\r\n Directory : 2\r\r\n EtwRegistration : 26\r\r\n Event : 186\r\r\n IoCompletion : 3\r\r\n Key : 9\r\r\n KeyedEvent : 1\r\r\n Mutant : 2\r\r\n Process : 4\r\r\n Section : 1\r\r\n Thread : 16\r\r\n Timer : 3\r\r\n Token : 40\r\r\n TpWorkerFactory : 24\r\r\n WindowStation : 2\r\r\nTotal handles: 322\r\r\n"

I am not interested in having a conflict with you and would appreciate a positive attitude in this discussion. We aren't asking you to do free work for us; in fact we are interested to raise a PR to fix the issue ourselves after discussion.

[lukebakken]

I am not interested in having a conflict with you and would appreciate a positive attitude in this discussion

I don't know why you think there is a conflict. I have outlined the history of the issue, and believe me, it is frustrating to not be able to resolve it. Most Windows users do not see this issue!

I have some questions here that should be answered - #6612 (comment). It is very important to know if this issue has always happened or started after some point. Since you're new RabbitMQ adopters I'm assuming it's always been there but I would like to confirm it.

If you wish to resolve the issue immediately, and aren't concerned about exhausting file handles on Windows (which rarely is an issue), then the workaround posted here is actually pretty clever:

rabbitmq/rabbitmq-management-agent#90 (comment)

I will double-check how frequently the messages are logged and will see if there is a way to reduce that.

[lukebakken]

The error messages should not be logged more frequently than every 10 minutes.

[wsficke]

I have some questions here that should be answered - #6612 (comment). It is very important to know if this issue has always happened or started after some point. Since you're new RabbitMQ adopters I'm assuming it's always been there but I would like to confirm it.

This ramp-up is explained by our rollout to production of RMQ, which involves incremental adoption over a business quarter

[lukebakken]

For now, I suggest filtering the log message since it can be safely ignored. It has no ill effect on RabbitMQ and the information gathered is used for statistics reporting only.

#6613 will resolve this for good.

[lukebakken]

I'm tired of dealing with handle.exe issues! See #6613

[gjohnso]

@wsficke asked me to chime in here. We do see this issue on multiple servers but I will be focusing on only one of them.

1. Windows Server 2022 OS build 20348.1249
2. Symantec Endpoint Protection v14.3 MP1 build 14.3.1169.0100
3. First occurrence of the error was appx 2 days after first install.
4. Frequency is intermittent, as low as 15 minutes to as long as 15 days. I have 22 events from 11/3/2022 to present, the last one early this morning.

Other servers we have it occurs more frequently, however if you are thinking it is being caused by other software or other issues in the Windows environment then this server is the best to look at.

[lukebakken]

If you could disable every antivirus, scanner, security product, etc and see if that resolves the issue, that would be very interesting. I have a workaround that I'm going to implement - #6613

My guess is that a security scanner like Symantec sees the handle.exe process make certain Win32 API calls that it deems "risky", and blocks them.

[gjohnso]

I have removed the software and checked for any others. It's wait and see now.

[lukebakken]

Great, the results will be very informative. I appreciate you doing that.