Couchbase tracing not logging server_us time

.NET SDK
1

I have web api I am using CouchbaseNet Client 2.7.18 nuget package.
I have enabled couchbase threshold tracing by using below code.

 var tracer = new ThresholdLoggingTracer
            {
                KvThreshold = 1, // 1 microsecond
                N1qlThreshold = 1,
                SearchThreshold = 1,
                SampleSize = int.MaxValue,
                Interval = 1000 // 1 second
            };
          
            bucket.Cluster.Configuration.Tracer = tracer;

I am getting below logs

Operations that exceeded service threshold: [{“service”:“n1ql”,“count”:1,“top”:[{“operation_name”:“n1ql”,“last_operaion_id”:“1::2”,“last_dispatch_us”:147602,“total_us”:307280,“encode_us”:1142,“dispatch_us”:147602,“decode_us”:32124}]}]

but in above logs some logs are missing specially server related logs for e.g.

“last_local_address”
“last_remote_address”
“server_us” etc.

Please help me to log above logs

2

Hi @Wahid_Kazi,

I was able to see last_local_address, last_remote_address, server_us, etc, when I tried this locally. Here’s the code that I ran:

        static async Task Main(string[] args)
        {
            ILoggerFactory loggerFactory = new LoggerFactory();
            loggerFactory.AddNLog(new NLogProviderOptions
            {
                CaptureMessageTemplates = true,
                CaptureMessageProperties = true
            });
            NLog.LogManager.LoadConfiguration("nlog.config");

            var tracer = new ThresholdLoggingTracer
            {
                KvThreshold = 1, // 1 ms
                N1qlThreshold = 1,
                SearchThreshold = 1,
                SampleSize = int.MaxValue,
                Interval = 1000 // 1 second
            };

            var cluster = new Cluster(new ClientConfiguration
            {
                LoggerFactory = loggerFactory,
                Servers = new List<Uri> {  new Uri("http://localhost:8091")},
                Tracer = tracer
            });
            cluster.Authenticate("Administrator", "password");

            var bucket = cluster.OpenBucket("tests");

            for (var i = 0; i < 5; i++)
                bucket.Insert<dynamic>(Guid.NewGuid().ToString(), new {foo = "bar"});

            Thread.Sleep(TimeSpan.FromMinutes(1));

            cluster.Dispose();
        }

(I’m using NLog.Extensions.Logging 1.2.0 and CouchbaseNetClient 2.7.18 in a .NET Core 3.1 console app). Here is a relevant snippet from the log file:

2020/07/23 11:29:57.484|INFO|Operations that exceeded service threshold: [{“service”:“kv”,“count”:5,“top”:[{“operation_name”:“Add”,“last_operaion_id”:“0x9”,“last_local_address”:“127.0.0.1:50726”,“last_remote_address”:“127.0.0.1:11210”,“last_local_id”:“18ec8862612f61b2/725447caf44fd5be”,“last_dispatch_us”:436,“total_us”:12721,“encode_us”:61,“dispatch_us”:436,“server_us”:231,“decode_us”:13},{“operation_name”:“Add”,“last_operaion_id”:“0xa”,“last_local_address”:“127.0.0.1:50725”,“last_remote_address”:“127.0.0.1:11210”,“last_local_id”:“18ec8862612f61b2/0846a4a1209d3dd9”,“last_dispatch_us”:331,“total_us”:4683,“encode_us”:39,“dispatch_us”:331,“server_us”:135,“decode_us”:7},{“operation_name”:“Add”,“last_operaion_id”:“0x7”,“last_local_address”:“127.0.0.1:50725”,“last_remote_address”:“127.0.0.1:11210”,“last_local_id”:“18ec8862612f61b2/0846a4a1209d3dd9”,“last_dispatch_us”:336,“total_us”:14665,“encode_us”:4206,“dispatch_us”:336,“server_us”:108,“decode_us”:304}]}]

So, I’m not able to replicate the problem that you’re seeing. Are there any more details that you can provide?

3

I am not using NLog logging instead I am using log4net logging. can that be a issue?

4

This is the code I am using in my startup.cs class
private static readonly ILog Logs = LogManager.GetLogger(typeof(Startup));

public void ConfigureServices(IServiceCollection services)
{
services.AddCouchbase(Configuration.GetSection(“Couchbase”));
services.AddMvc().SetCompatibilityVersion(CompatibilityVersion.Version_2_2);
}

below is my appsetting.config
“Couchbase”: {
“UserName”: “username”,
“Password”: “pwd”,
“Servers”: [
“couchbase server”
],
“Bucket”: “bucketname”,

5

I just tried it again, using log4net instead, and again I still see last_local_address, last_remote_address, server_us, etc.

Here’s the code, for reference:

    class Program
    {
        static async Task Main(string[] args)
        {
            LoggerFactory loggerFactory = new LoggerFactory();
            loggerFactory.AddLog4Net("log4net.config");

            var tracer = new ThresholdLoggingTracer
            {
                KvThreshold = 1, // 1 ms
                N1qlThreshold = 1,
                SearchThreshold = 1,
                SampleSize = int.MaxValue,
                Interval = 1000 // 1 second
            };

            var cluster = new Cluster(new ClientConfiguration
            {
                LoggerFactory = loggerFactory,
                Servers = new List<Uri> {  new Uri("http://localhost:8091")},
                Tracer = tracer
            });
            cluster.Authenticate("Administrator", "password");

            var bucket = cluster.OpenBucket("tests");

            for (var i = 0; i < 5; i++)
                bucket.Insert<dynamic>(Guid.NewGuid().ToString(), new {foo = "bar"});

            Thread.Sleep(TimeSpan.FromMinutes(1));

            cluster.Dispose();
        }
    }

And here’s my log4net config:

<log4net>
  <appender name="RollingFile" type="log4net.Appender.RollingFileAppender">
    <file value="console-example-log4net.log" />
    <appendToFile value="true" />
    <maximumFileSize value="100KB" />
    <maxSizeRollBackups value="2" />

    <layout type="log4net.Layout.PatternLayout">
      <conversionPattern value="%level %thread %logger - %message%newline" />
    </layout>
  </appender>

  <root>
    <level value="ALL" />
    <appender-ref ref="RollingFile" />
  </root>
</log4net>

So, I don’t think it’s a matter of log4net vs NLog. Is it possible there’s something in your log4net config that might be messing with those fields? Another thing to try is to maybe create a simple, minimum console app that reproduces the issue? If there’s a bug, then this would be helpful in identifying that.