search

dotnet / runtime

.NET is a cross-platform runtime for cloud, mobile, desktop, and IoT apps.
https://docs.microsoft.com/dotnet/core/
MIT License
15.36k stars 4.75k forks source link

EventLogEntry Message Property getter hangs #50853

Open vsfeedback opened 3 years ago

vsfeedback commented 3 years ago

This issue has been moved from a ticket on Developer Community.

Reading the Event Message from a certain EventLogEntry hangs infinite. When using a 32-bit Application it throws a OutOfMemoryException after minutes:

System.OutOfMemoryException: Eine Ausnahme vom Typ "System.OutOfMemoryException" wurde ausgelöst.
bei System.Number.FormatInt32(Int32 value, String format, NumberFormatInfo info)
bei System.Int32.ToString()
bei System.String.Concat(Object arg0, Object arg1)
bei System.Diagnostics.EventLog.TryFormatMessage(SafeLibraryHandle hModule, UInt32 messageNum, String[] insertionStrings)
bei System.Diagnostics.EventLogInternal.FormatMessageWrapper(String dllNameList, UInt32 messageNum, String[] insertionStrings)
bei System.Diagnostics.EventLogEntry.get_Message()
bei WITecCreateSupportZipApp.WindowsEventHelper.writeWindowsEventsToStream(String aEventLogName, StreamWriter sw, ProgressReportSteps aReportSteps)

Unfortunately this happens only on a certain customer pc, so I can’t reproduce it with my own event log.
I created a dump file and the thread hangs when accessing the EventLogEntry.Message property (in System.Diagnostics.EventLog.TryFormatMessage()).

Original Comments

Henning Dampel on 10/15/2020, 06:44 AM:

(private comment, text removed)

Feedback Bot on 10/15/2020, 07:44 PM:

We have directed your feedback to the appropriate engineering team for further evaluation. The team will review the feedback and notify you about the next steps.

Tarek Mahmoud Sayed [MSFT] on 10/21/2020, 00:37 PM:

Thanks for reporting the issue. Unfortunately it is hard to know what is going on using the provided information. Out of memory exception means there is something consuming a lot of memory and not necessary what you have in the stack is the root cause.
Also, it is not clear what you mean by I created a dump file and the thread hangs when accessing the EventLogEntry.Message property (in System.Diagnostics.EventLog.TryFormatMessage()).. How did you know from the dump is the thread is hanging? or do you mean something else?

I would suggest to you is either create a full dump when the problem happen and share it or you can run any memory profiler on the process when the problem occur which can help telling which part allocating a lot of memory.
Last, this may be limitation on x86 process when opening a very big events log file. we cannot tell for sure without more information here. Thanks.

Henning Dampel on 11/25/2020, 06:42 AM:

(private comment, text removed)

Henning Dampel on 10/22/2020, 01:09 AM:

(private comment, text removed)

Tarek Mahmoud Sayed [MSFT] on 11/2/2020, 02:56 PM:

Henning Dampel I have looked at the dump file you shared. I am seeing the only thread has CLR in the stack is

11  Id: 4a8.5c8 Suspend: 0 Teb: 00000000`00d56000 Unfrozen
 # Child-SP          RetAddr           Call Site
00 00000000`0621ee14 4d934110`1910fd00 clr!GetMetaDataPublicInterfaceFromInternal+0x100b4
01 00000000`0621ee1c 00000020`0621eea4 0x4d934110`1910fd00
02 00000000`0621ee24 0621eea0`0621eeb0 0x00000020`0621eea4
03 00000000`0621ee2c 0621eec0`0621eeac 0x0621eea0`0621eeb0
04 00000000`0621ee34 1913f9fc`6c5def85 0x0621eec0`0621eeac
05 00000000`0621ee3c 6c5d9250`00000001 0x1913f9fc`6c5def85
06 00000000`0621ee44 00000000`00000000 0x6c5d9250`00000001

which means .NET is not in any other stacks and I am not seeing any EventLog calls which is telling it is hanging there.

Did you share the right dump? I am seeing the executable used is

0:000> |
.  0   id: 4a8 examine name: C:\Users\Witec\Desktop\CreateSupportZIP5.3_TEST\WITec.CreateSupportZipApp.exe

We need to have a better dump file showing the problem when it is hanging in EventLog to be able to assist. Or at least the dump should show the .NET is used there.

Feedback Bot on 11/10/2020, 07:27 PM:

We will close this report in 14 days because we don’t have enough information to investigate further. To keep the problem open, please provide the requested details.

Henning Dampel on 11/25/2020, 06:47 AM:

(private comment, text removed)

Henning Dampel on 11/25/2020, 06:55 AM:

(private comment, text removed)

Henning Dampel on 2/8/2021, 08:51 AM:

(private comment, text removed)

Tarek Mahmoud Sayed [MSFT] on 2/8/2021, 09:36 AM:

Did you look at all threads??

The dump file that you shared on Nov 25, 2020 was not showing any thread in the CLR stack as I indicated in previous comments.
Now I cannot access the dump file again as the ftp server looks unavailable any more. If you have a dump showing a thread with the stack you mentioned, please share it again and we’ll take another look.

Henning Dampel on 2/9/2021, 01:19 AM:

(private comment, text removed)

Tarek Mahmoud Sayed [MSFT] on 2/9/2021, 04:05 PM:

Henning Dampel thanks for resending the dump file link. I am able to get it and seeing what you are seeing. Looking at the thread 1480 which you are saying it is hanging and I am seeing this thread is not really hanging but it is busy formatting the log entry. Basically, your code is calling EventLogEntry.Message to get the log entry message. The message is coming with %100790275 which is a huge number. and then will execute the code

            if (largestNumber > insertionStrings.Length) {
                string[] newStrings = new string[largestNumber];
                Array.Copy(insertionStrings, newStrings, insertionStrings.Length);
                for (int i = insertionStrings.Length; i < newStrings.Length; i++) {
                    newStrings[i] = "%" + (i + 1);
                }

                insertionStrings = newStrings;
            }

largestNumber is what we parsed from the message and will be equal to 100,790,275. First it allocate the newStrings array which will be a huge array and then will try to fill that string. the value of i in the dump you have shared is i =16,482,572 which means the loop is busy at counter 16,482,572 and will expected to exit when the counter is 100,790,275 and with every iteration is formatting a new string "%" + (i + 1).

The question now is why the logging sending entry with that huge number 100,790,275. who is producing these logs you are listening to?

eventually the loop will exit (if we don’t run out of memory of course).

Henning Dampel on 2/10/2021, 01:02 AM:

(private comment, text removed)

Tarek Mahmoud Sayed [MSFT] on 2/10/2021, 09:20 AM:

Henning Dampel thanks again. From what I saw I am not seeing any problem in the .NET side and .NET is doing what is supposes to do. Anyway, if you get some more info in the future and feel it is .NET problem, feel free to ping us back and we’ll be happy to look at that.

Original Solutions

Feedback Bot solved on 2/25/2021, 00:51 AM, 0 votes:

We are unable to investigate this issue further without the additional information requested. If you are able to provide more information, you can request the issue being reactivate below. See our guidelines for further information about our process.

Roland, Mario on 3/31/2021, 00:51 AM:

(private comment, text removed)

Tarek Mahmoud Sayed [MSFT] on 3/31/2021, 07:32 PM:

Please attach a debugger dump when the problem happens so we can look what is going on. we’ll not be able to tell without a repro or debugger dump. Note that could be a different issue than what is originally reported. Thanks.

Roland, Mario on 4/6/2021, 00:27 AM:

(private comment, text removed)

Tarek Mahmoud Sayed [MSFT] on 4/6/2021, 04:11 PM:

Roland, Mario Thanks a lot for sharing the dump and the code. I ran the code locally but couldn’t repro the hang nor the OOM. But this could be because of the difference in the machine configuration and the amount of the logs you are reading from this machine.

Looking at your dump, I am seeing it is not hanging but busy formatting some data:

00afe9c0 77992f5c [HelperMethodFrame_PROTECTOBJ: 00afe9c0] System.Number.FormatInt32(Int32, System.String, System.Globalization.NumberFormatInfo)
00afeb4c 718ce1e8 System.Int32.ToString() [f:\dd\ndp\clr\src\BCL\system\int32.cs @ 94]
00afeb58 718ce1b9 System.String.Concat(System.Object, System.Object) [f:\dd\ndp\clr\src\BCL\system\string.cs @ 3068]
00afeb68 70ff744c System.Diagnostics.EventLog.TryFormatMessage(Microsoft.Win32.SafeHandles.SafeLibraryHandle, UInt32, System.String[]) [f:\dd\NDP\fx\src\services\monitoring\system\diagnosticts\EventLog.cs @ 1270]
00afeba0 70ff9321 System.Diagnostics.EventLogInternal.FormatMessageWrapper(System.String, UInt32, System.String[]) [f:\dd\NDP\fx\src\services\monitoring\system\diagnosticts\EventLogInternal.cs @ 858]
00afebe0 70ffbebc System.Diagnostics.EventLogEntry.get_Message() [f:\dd\NDP\fx\src\services\monitoring\system\diagnosticts\EventLogEntry.cs @ 225]
00afec00 00be0c09 WindowsEventRead.Program.CreateWindowsEventsLog()
00afed3c 00be0870 WindowsEventRead.Program.Main(System.String[])
00afeeec 7327f036 [GCFrame: 00afeeec]

I looked at the heap status and I am seeing the biggest allocations is coming from the type

71512d74       44    403162576 System.String[]

looking at the root of the allocation of this string is coming from:

0:000> !GCRoot 06361010
Thread 414c:
    00afeb68 70ff744c System.Diagnostics.EventLog.TryFormatMessage(Microsoft.Win32.SafeHandles.SafeLibraryHandle, UInt32, System.String[]) [f:\dd\NDP\fx\src\services\monitoring\system\diagnosticts\EventLog.cs @ 1270]
        edi: 
            ->  06361010 System.String[]

Found 1 unique roots (run '!GCRoot -all' to see all roots).

These all allocated from the EventLogEntry.Message calls. The huge allocation is done because of the size of the logs existed in the machine (especially from Application logs).

Looks your machine has limited memory and in same time has a lot of logs to process. That is why processing the logs putting a lot of pressure on the memory. In normal cases, this allocated memory will get garbage collected and cleaned up by GC. But in your case because you have limited memory, you run to OOM.

The possible workaround is trying to avoid reading the whole logs at one shot. I am seeing from the code you are reading the logs of last 20 days. You may try to wrap the whole code inside a method which read the logs for only one day. and then you cann call this method like 20 times for each day of last 20 days. After each call, you call GC.Collect to ensure collecting un-needed objects to reduce the pressure on the GC and the heap.

Could you please share your machine configuration too? how much memory it has?

Thanks for your report.

Roland, Mario on 4/7/2021, 05:40 AM:

I have reengeniered the problem with code from Microsoft.
It seems that the problem is in the event message itself. Perhaps only in the localized one. Because in the method System.Diagnostics.EventLog.TryFormatMessage the code:

// If you pass in an empty array UnsafeTryFormatMessage will just pull out the message.
string formatString = UnsafeTryFormatMessage(hModule, messageNum, new string[0]);

returns for the libary “C:\Windows\System32\gpprefcl.dll” the german message text:

“Die clientseitige Erweiterung konnte die %2-Richtlinieneinstellungen für %3 nicht %1. Fehlercode: %4%%100790275”

This text leads to that the local variable largestNumber is 100790275.
Which in turn leads to a large memory allocation at the end of the method.

I’ve attached the sample program so you should be able to reproduce it. At least for a German localization.
WindowsEventRead2.zip

ghost commented 3 years ago

Tagging subscribers to this area: @GrabYourPitchForks, @carlossanlop See info in area-owners.md if you want to be subscribed.

Issue Details
_This issue has been moved from [a ticket on Developer Community](https://developercommunity2.visualstudio.com/t/EventLogEntry-Message-Property-getter-ha/1222634)._ ---

Reading the Event Message from a certain EventLogEntry hangs infinite. When using a 32-bit Application it throws a OutOfMemoryException after minutes:

System.OutOfMemoryException: Eine Ausnahme vom Typ "System.OutOfMemoryException" wurde ausgelöst.
bei System.Number.FormatInt32(Int32 value, String format, NumberFormatInfo info)
bei System.Int32.ToString()
bei System.String.Concat(Object arg0, Object arg1)
bei System.Diagnostics.EventLog.TryFormatMessage(SafeLibraryHandle hModule, UInt32 messageNum, String[] insertionStrings)
bei System.Diagnostics.EventLogInternal.FormatMessageWrapper(String dllNameList, UInt32 messageNum, String[] insertionStrings)
bei System.Diagnostics.EventLogEntry.get_Message()
bei WITecCreateSupportZipApp.WindowsEventHelper.writeWindowsEventsToStream(String aEventLogName, StreamWriter sw, ProgressReportSteps aReportSteps)

Unfortunately this happens only on a certain customer pc, so I can’t reproduce it with my own event log.
I created a dump file and the thread hangs when accessing the EventLogEntry.Message property (in System.Diagnostics.EventLog.TryFormatMessage()).

--- ### Original Comments #### Henning Dampel on 10/15/2020, 06:44 AM: (private comment, text removed) #### Feedback Bot on 10/15/2020, 07:44 PM:

We have directed your feedback to the appropriate engineering team for further evaluation. The team will review the feedback and notify you about the next steps.

#### Tarek Mahmoud Sayed [MSFT] on 10/21/2020, 00:37 PM:

Thanks for reporting the issue. Unfortunately it is hard to know what is going on using the provided information. Out of memory exception means there is something consuming a lot of memory and not necessary what you have in the stack is the root cause.
Also, it is not clear what you mean by I created a dump file and the thread hangs when accessing the EventLogEntry.Message property (in System.Diagnostics.EventLog.TryFormatMessage()).. How did you know from the dump is the thread is hanging? or do you mean something else?

I would suggest to you is either create a full dump when the problem happen and share it or you can run any memory profiler on the process when the problem occur which can help telling which part allocating a lot of memory.
Last, this may be limitation on x86 process when opening a very big events log file. we cannot tell for sure without more information here. Thanks.

#### Henning Dampel on 11/25/2020, 06:42 AM: (private comment, text removed) #### Henning Dampel on 10/22/2020, 01:09 AM: (private comment, text removed) #### Tarek Mahmoud Sayed [MSFT] on 11/2/2020, 02:56 PM:

Henning Dampel I have looked at the dump file you shared. I am seeing the only thread has CLR in the stack is

11  Id: 4a8.5c8 Suspend: 0 Teb: 00000000`00d56000 Unfrozen
 # Child-SP          RetAddr           Call Site
00 00000000`0621ee14 4d934110`1910fd00 clr!GetMetaDataPublicInterfaceFromInternal+0x100b4
01 00000000`0621ee1c 00000020`0621eea4 0x4d934110`1910fd00
02 00000000`0621ee24 0621eea0`0621eeb0 0x00000020`0621eea4
03 00000000`0621ee2c 0621eec0`0621eeac 0x0621eea0`0621eeb0
04 00000000`0621ee34 1913f9fc`6c5def85 0x0621eec0`0621eeac
05 00000000`0621ee3c 6c5d9250`00000001 0x1913f9fc`6c5def85
06 00000000`0621ee44 00000000`00000000 0x6c5d9250`00000001

which means .NET is not in any other stacks and I am not seeing any EventLog calls which is telling it is hanging there.

Did you share the right dump? I am seeing the executable used is

0:000> |
.  0   id: 4a8 examine name: C:\Users\Witec\Desktop\CreateSupportZIP5.3_TEST\WITec.CreateSupportZipApp.exe

We need to have a better dump file showing the problem when it is hanging in EventLog to be able to assist. Or at least the dump should show the .NET is used there.

#### Feedback Bot on 11/10/2020, 07:27 PM: We will close this report in 14 days because we don’t have enough information to investigate further. To keep the problem open, please provide the requested details. #### Henning Dampel on 11/25/2020, 06:47 AM: (private comment, text removed) #### Henning Dampel on 11/25/2020, 06:55 AM: (private comment, text removed) #### Henning Dampel on 2/8/2021, 08:51 AM: (private comment, text removed) #### Tarek Mahmoud Sayed [MSFT] on 2/8/2021, 09:36 AM:

Did you look at all threads??

The dump file that you shared on Nov 25, 2020 was not showing any thread in the CLR stack as I indicated in previous comments.
Now I cannot access the dump file again as the ftp server looks unavailable any more. If you have a dump showing a thread with the stack you mentioned, please share it again and we’ll take another look.

#### Henning Dampel on 2/9/2021, 01:19 AM: (private comment, text removed) #### Tarek Mahmoud Sayed [MSFT] on 2/9/2021, 04:05 PM:

Henning Dampel thanks for resending the dump file link. I am able to get it and seeing what you are seeing. Looking at the thread 1480 which you are saying it is hanging and I am seeing this thread is not really hanging but it is busy formatting the log entry. Basically, your code is calling EventLogEntry.Message to get the log entry message. The message is coming with %100790275 which is a huge number. and then will execute the code

            if (largestNumber > insertionStrings.Length) {
                string[] newStrings = new string[largestNumber];
                Array.Copy(insertionStrings, newStrings, insertionStrings.Length);
                for (int i = insertionStrings.Length; i < newStrings.Length; i++) {
                    newStrings[i] = "%" + (i + 1);
                }

                insertionStrings = newStrings;
            }

largestNumber is what we parsed from the message and will be equal to 100,790,275. First it allocate the newStrings array which will be a huge array and then will try to fill that string. the value of i in the dump you have shared is i =16,482,572 which means the loop is busy at counter 16,482,572 and will expected to exit when the counter is 100,790,275 and with every iteration is formatting a new string "%" + (i + 1).

The question now is why the logging sending entry with that huge number 100,790,275. who is producing these logs you are listening to?

eventually the loop will exit (if we don’t run out of memory of course).

#### Henning Dampel on 2/10/2021, 01:02 AM: (private comment, text removed) #### Tarek Mahmoud Sayed [MSFT] on 2/10/2021, 09:20 AM:

Henning Dampel thanks again. From what I saw I am not seeing any problem in the .NET side and .NET is doing what is supposes to do. Anyway, if you get some more info in the future and feel it is .NET problem, feel free to ping us back and we’ll be happy to look at that.

--- ### Original Solutions #### Feedback Bot solved on 2/25/2021, 00:51 AM, 0 votes: We are unable to investigate this issue further without the additional information requested. If you are able to provide more information, you can request the issue being reactivate below. See our [guidelines](https://aka.ms/vsfeedbackguidelines) for further information about our process. #### Roland, Mario on 3/31/2021, 00:51 AM: (private comment, text removed) #### Tarek Mahmoud Sayed [MSFT] on 3/31/2021, 07:32 PM:

Please attach a debugger dump when the problem happens so we can look what is going on. we’ll not be able to tell without a repro or debugger dump. Note that could be a different issue than what is originally reported. Thanks.

#### Roland, Mario on 4/6/2021, 00:27 AM: (private comment, text removed) #### Tarek Mahmoud Sayed [MSFT] on 4/6/2021, 04:11 PM:

Roland, Mario Thanks a lot for sharing the dump and the code. I ran the code locally but couldn’t repro the hang nor the OOM. But this could be because of the difference in the machine configuration and the amount of the logs you are reading from this machine.

Looking at your dump, I am seeing it is not hanging but busy formatting some data:

00afe9c0 77992f5c [HelperMethodFrame_PROTECTOBJ: 00afe9c0] System.Number.FormatInt32(Int32, System.String, System.Globalization.NumberFormatInfo)
00afeb4c 718ce1e8 System.Int32.ToString() [f:\dd\ndp\clr\src\BCL\system\int32.cs @ 94]
00afeb58 718ce1b9 System.String.Concat(System.Object, System.Object) [f:\dd\ndp\clr\src\BCL\system\string.cs @ 3068]
00afeb68 70ff744c System.Diagnostics.EventLog.TryFormatMessage(Microsoft.Win32.SafeHandles.SafeLibraryHandle, UInt32, System.String[]) [f:\dd\NDP\fx\src\services\monitoring\system\diagnosticts\EventLog.cs @ 1270]
00afeba0 70ff9321 System.Diagnostics.EventLogInternal.FormatMessageWrapper(System.String, UInt32, System.String[]) [f:\dd\NDP\fx\src\services\monitoring\system\diagnosticts\EventLogInternal.cs @ 858]
00afebe0 70ffbebc System.Diagnostics.EventLogEntry.get_Message() [f:\dd\NDP\fx\src\services\monitoring\system\diagnosticts\EventLogEntry.cs @ 225]
00afec00 00be0c09 WindowsEventRead.Program.CreateWindowsEventsLog()
00afed3c 00be0870 WindowsEventRead.Program.Main(System.String[])
00afeeec 7327f036 [GCFrame: 00afeeec]

I looked at the heap status and I am seeing the biggest allocations is coming from the type

71512d74       44    403162576 System.String[]

looking at the root of the allocation of this string is coming from:

0:000> !GCRoot 06361010
Thread 414c:
    00afeb68 70ff744c System.Diagnostics.EventLog.TryFormatMessage(Microsoft.Win32.SafeHandles.SafeLibraryHandle, UInt32, System.String[]) [f:\dd\NDP\fx\src\services\monitoring\system\diagnosticts\EventLog.cs @ 1270]
        edi: 
            ->  06361010 System.String[]

Found 1 unique roots (run '!GCRoot -all' to see all roots).

These all allocated from the EventLogEntry.Message calls. The huge allocation is done because of the size of the logs existed in the machine (especially from Application logs).

Looks your machine has limited memory and in same time has a lot of logs to process. That is why processing the logs putting a lot of pressure on the memory. In normal cases, this allocated memory will get garbage collected and cleaned up by GC. But in your case because you have limited memory, you run to OOM.

The possible workaround is trying to avoid reading the whole logs at one shot. I am seeing from the code you are reading the logs of last 20 days. You may try to wrap the whole code inside a method which read the logs for only one day. and then you cann call this method like 20 times for each day of last 20 days. After each call, you call GC.Collect to ensure collecting un-needed objects to reduce the pressure on the GC and the heap.

Could you please share your machine configuration too? how much memory it has?

Thanks for your report.

#### Roland, Mario on 4/7/2021, 05:40 AM:

I have reengeniered the problem with code from Microsoft.
It seems that the problem is in the event message itself. Perhaps only in the localized one. Because in the method System.Diagnostics.EventLog.TryFormatMessage the code:

// If you pass in an empty array UnsafeTryFormatMessage will just pull out the message.
string formatString = UnsafeTryFormatMessage(hModule, messageNum, new string[0]);

returns for the libary “C:\Windows\System32\gpprefcl.dll” the german message text:

“Die clientseitige Erweiterung konnte die %2-Richtlinieneinstellungen für %3 nicht %1. Fehlercode: %4%%100790275”

This text leads to that the local variable largestNumber is 100790275.
Which in turn leads to a large memory allocation at the end of the method.

I’ve attached the sample program so you should be able to reproduce it. At least for a German localization.
WindowsEventRead2.zip

Author: vsfeedback
Assignees: -
Labels: `area-System.Memory`, `untriaged`
Milestone: -
tarekgh commented 3 years ago

Note the external ticket has more helpful information https://developercommunity.visualstudio.com/t/eventlogentry-message-property-getter-hangs/1222634?from=email&viewtype=all#T-ND1392465