Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

config files (newrelic.config, app.config, etc.) UTF-8 encoded with Byte Order Mark can't be parsed on Linux #267

Closed
nr-ahemsath opened this issue Sep 30, 2020 · 2 comments · Fixed by #492
Assignees
Labels
bug Something isn't working good first issue Good for newcomers

Comments

@nr-ahemsath
Copy link
Member

nr-ahemsath commented Sep 30, 2020

Description
The profiler component of the agent has a problem parsing newrelic.config or other config files (e.g app.config for a profiled application) if it is encoded in UTF-8 with BOM (Byte Order Mark: https://en.wikipedia.org/wiki/Byte_order_mark)

The symptom of the issue is that a profiler log will only have the following lines:

[Info ] 2020-02-19 11:33:36 Logger initialized.
[Trace] 2020-02-19 11:33:36 New Relic .NET CoreCLR Agent
[Info ] 2020-02-19 11:33:36 Found newrelic.config at: /usr/local/newrelic-netcore20-agent/newrelic.config

Expected Behavior
The agent should start normally if the config file is in UTF-8 with BOM.

Steps to Reproduce

  1. Get a newrelic.config file encoded in UTF-8 with BOM. You can do this easily with VS Code. Open the config file in VS Code, click the encoding in the lower right hand corner, choose "Save with encoding" from the dialog that opens, and select "UTF-8 with BOM" to save the file as. You can confirm that this worked by installing the "Hexdump" extension and viewing the file as a hexdump and confirming that the first three bytes of the file are "EF BB BF".
  2. Use this file as the global newrelic.config file in /usr/local/newrelic-netcore20-agent in a Linux environment, and run any .NET Core application with profiling enabled. Look at the resulting profiler log and note that it stops after the first three lines.

Initial debugging with extra logging statements shows that the breakdown is occurring somewhere when trying to read the resultant xstring_t from the ReadFile() method in ICorProfilerCallbackBase.h. xstring_t is a custom typedef we use to handle Windows/Linux cross-compatibility, it's defined in xplat.h.

For Windows:

typedef wchar_t xchar_t;
typedef std::basic_string<xchar_t> xstring_t;

For Linux:

typedef std::u16string::value_type xchar_t;
typedef std::u16string xstring_t;

Your Environment
.NET Core agent on Linux

@nr-ahemsath nr-ahemsath added bug Something isn't working good first issue Good for newcomers labels Sep 30, 2020
@angelatan2 angelatan2 added this to the Q4 Bug Smash Kanban milestone Nov 13, 2020
@nr-ahemsath nr-ahemsath self-assigned this Mar 2, 2021
@nr-ahemsath
Copy link
Member Author

An update on my progress analyzing and debugging this issue:

This issue really only seems to be reproducible in a Linux environment. I created a C++ test application in Visual Studio on Windows, and forklifted the relevant code from the profiler that is in the path of this issue...the ReadFile() method in ICorProfilerCallbackBase.h, the RapidXML project, and the relevant macro definitions from xplat.h. Running it on Windows, even when using the definitions of xchar_t and xstring_t that are used in the Linux profiler, a config file encoded with "utf8-with-bom" is still readable and parseable.

However, by adding a bunch of debugging printouts and running the profiler in Linux, I've found the following:

  1. There is a parse_bom() method in the RapidXML parser:
    void parse_bom(Ch *&text)
    {
    // UTF-8?
    if (static_cast<unsigned char>(text[0]) == 0xEF &&
    static_cast<unsigned char>(text[1]) == 0xBB &&
    static_cast<unsigned char>(text[2]) == 0xBF)
    {
    text += 3; // Skup utf-8 bom
    }
    }
    When this code executes on Linux, the three unsigned chars read from the "text" argument do not match the three magic hex bytes it is looking for, and so the BOM does not get skipped.
  2. Any attempt to use one of the logging macros to print out a part of the xstring_t that is returned from ReadFile() causes the profiler to hang. The RapidXML parse() method is throwing an exception, but it's not being logged out because the LogError() call in the catch block contains a part of the bad data:
    } catch (const rapidxml::parse_error& exception) {
    LogError(L"Exception thrown while attempting to parse main newrelic.config file. ", exception.what(), L" at ", exception.where<wchar_t>());
    throw ConfigurationException();
    }
    (as a side note: if we can't fix this bug by detecting the BOM when read in Linux and skipping it, at least we should update this code to be able to successfully log an error message and suggest to the user to fix their config file(s) encoding.)
  3. I am starting to think that the proper place to fix this is going to be in the ReadFile() method. It looks like all code paths which read an XML config file from disk (including instrumentation files) go through this method. I'm hoping there's some way to examine the raw bytes somewhere in here, between the .rdbuf() (raw device buffer) and the .str(), detect the BOM, and strip it out:
    xostringstream result;
    result << fileStream.rdbuf();
    fileStream.close();
    // return the results
    return result.str();

@equist
Copy link

equist commented Aug 22, 2022

I'm still seeing this in the Log Stream of Azure App Service Linux:

[Info ] 2022-08-22 09:41:35 Found newrelic.config at: /home/site/wwwroot/newrelic/newrelic.config
[Info ] 2022-08-22 09:41:35 Found newrelic.config at: ./newrelic.config
[Debug] 2022-08-22 09:41:35 ReadFile (./newrelic.config) detected UTF-8 BOM, skipping.
[Info ] 2022-08-22 09:41:35 Global config agentEnabled=true

I'm testing New Relic for the first time and I try to change the log level from info to warn and have created a local newrelic.config file in Visual Studio 2022. When changing the file to not include BOM it seems to work in the regards that I don't see the Debug message anymore. It still logs on Info level though.

[Info ] 2022-08-22 10:33:52 ICorProfilerInfo10 available
[Info ] 2022-08-22 10:33:52 Found newrelic.config at: /home/site/wwwroot/newrelic/newrelic.config
[Info ] 2022-08-22 10:33:52 <-- New logging level set: Info
[Info ] 2022-08-22 10:33:52 Loading instrumentation from /home/site/wwwroot/newrelic/extensions
[Info ] 2022-08-22 10:33:53 Identified 182 Instrumentation points in .xml files
[Info ] 2022-08-22 10:33:53 Command line: ./DiagServer
[Info ] 2022-08-22 10:33:53 Profiler initialized
[Info ] 2022-08-22 10:33:54 Unable to find Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker for rejit. HR:-2146234064
[Info ] 2022-08-22 10:33:57 Logger initialized.
[Trace] 2022-08-22 10:33:57 New Relic .NET CoreCLR Agent
[Info ] 2022-08-22 10:33:57 Initializing ThreadProfiler
[Info ] 2022-08-22 10:33:57 ICorProfilerInfo10 available
[Info ] 2022-08-22 10:33:57 Found newrelic.config at: /home/site/wwwroot/newrelic/newrelic.config
[Info ] 2022-08-22 10:33:57 Found newrelic.config at: ./newrelic.config
[Info ] 2022-08-22 10:33:57 Global config agentEnabled=true

I'm running the 10.0 version of the Agent.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working good first issue Good for newcomers
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants