DBG #12 R: 123 (5,759 Debug messages)

1

I noticed that there is 5,759 debug lines (can be more or less depending upon razor page) of the same/similar Log.Debug messages that happen right after: (github link)

[21:22:30 DBG] CreateRequestAsync/requestParams:

The item logged 5759 (or more or less) is similar to:
[21:22:30 DBG] #12 R: $192

I’m not sure what the #12 is as it seems to change (increments up).
I’m also unsure of what the R: designates.

Sample:

[21:22:30 INF] Request starting HTTP/2.0 GET https://localhost:44333/my-page/  
[21:22:30 DBG] CreateRequestAsync/requestParams:
[21:22:30 DBG] #12 R: $192
[21:22:30 DBG] #12 R: 260
[21:22:30 DBG] #12 R: 4
[21:22:30 DBG] #12 R: 16
[21:22:30 DBG] #12 R: $16
[21:22:30 DBG] #12 R: 6
... // 1,000's of similar messages
[21:23:02 DBG] #12 R: 2
[21:23:02 DBG] #12 R: 21
[21:23:02 DBG] #12 R: $21
[21:23:02 DBG] #12 R: 20
[21:23:02 DBG] #12 R: $20
The thread 0x5a25 has exited with code 0 (0x0).

This particular project doesn’t have any Log.Debug logging and I cannot seem to find where in ServiceStack it is happening as it seems excessive with 5,759 messages.

To note:

  1. The project uses async requests
  2. The project was recently updated to 5.7.0 version and don’t remember this happening in 5.6.0.
    UPDATE: Doesn’t happen in 5.6.0 only in 5.7.0
  3. It’s possible it could be coming from ServiceStack.OrmLite or Redis, but I didn’t find anything when searching GitHub.
  4. This project also uses npgsql and it looks like that was updated from 4.0.9 to 4.1.0.

Where is this coming from? Is this a bug? Seems excessive and seems to cause debugging to be slow (~33 seconds from the first of that log messages to the last).

UPDATE:

This seems to happen after upgrading to 5.7.0 from 5.6.0.
Note: Still using ASP.NET Core 2.2.0

Before:

    <PackageReference Include="Npgsql" Version="4.0.9" />
    <PackageReference Include="ServiceStack" Version="5.6.0" />
    <PackageReference Include="ServiceStack.OrmLite.PostgreSQL.Core" Version="5.6.0" />
    <PackageReference Include="ServiceStack.Redis.Core" Version="5.6.0" />
    <PackageReference Include="ServiceStack.Server.Core" Version="5.6.0" />
    <PackageReference Include="ServiceStack.Mvc" Version="5.6.0" />

After:

    <PackageReference Include="Npgsql" Version="4.1.0" />
    <PackageReference Include="ServiceStack" Version="5.7.0" />
    <PackageReference Include="ServiceStack.OrmLite.PostgreSQL.Core" Version="5.7.0" />
    <PackageReference Include="ServiceStack.Redis.Core" Version="5.7.0" />
    <PackageReference Include="ServiceStack.Server.Core" Version="5.7.0" />
    <PackageReference Include="ServiceStack.Mvc" Version="5.7.0" />
2

ahh annoying, it’s from the Redis Detailed Debug log which only should be logged if RedisConfig.EnableVerboseLogging=true but the flag was flipped in the refactor, resolved with this commit.

The debug logger is logged under the ServiceStack.Redis.RedisNativeClient type which you should be able to filter out from the logging provider configuration you’re using alternatively you can trigger the static RedisNativeClient initializer before configuring logging (i.e. in Program.cs) with:

RedisNativeClient.ServerVersionNumber = 0;

Which is a noop but will force static initialization and configure the class with the default null logger which will ignore all logging within that class. Otherwise you can upgrade to v5.7.1 on MyGet with the above fix.