Trace Log in Java SDK 3.0

Java SDK
1

I’m having difficulty configuring trace logging in Java SDK 3.0. The articles on the website are for SDK 2.7 and respective classes are missing in 3.0.

My Couchbase cluster on AWS (community edition) is reporting OrphansRecordedEvent warnings. What are these and could somebody provide an explanation as to what the included json properties mean as they only have one letter names. Here is an example from the log that keep on repeating:

2020-03-03 16:33:10.932 | WARN | cb-events | [com.couchbase.tracing][OrphansRecordedEvent][10s] Orphaned requests found: [{“top”:[{“b”:“automatrics”,“r”:“172.31.42.14:11210”,“s”:“carrierbucketconfig”,“c”:“0000000000000001/000000005D8C0C6F”,“t”:2500,“i”:“0x3d2”,“l”:“172.31.30.80:32908”}],“service”:“kv”,“count”:1}]

2

Sorry, the orphans should be covered in the docs but seem not to be I filed an issue to track fixing it.

The specification is open though, so maybe you can read about it there and let us know if you have any questions see SDK3 Response Time Observability in the sdk-rfcs.

3

Hi,

Thanks for quick reply. I read the chapter about Response time Observability and I know how to configure the tracer in SDK 3.0. However the rfcs does not explain why this warning is there in the first place. I have couchbase server running on my local machine (Ubuntu VM on Mac host) and I don’t see those warnings. I see them when I deploy a two-server cluster on AWS. It’s only 2 servers as it’s for testing.

Do you have a documentation that would help me understand this warning and ultimately fix the underlying cause behind it?

Cheers,

Pawel

4

@Ratlake_Pawel we tried to load a config but couldn’t in the specified timeout. Actually I’m going to file an enhancement on that because having those ops in the orphan log are not very helpful and (as in your case) may cause more confusion than harm - and we can log better for those cases.

Did you see other timeouts/errors in your logs?

5

Hi,

So the source of the warning is the Java SDK not the couchbase server. Is that statement correct? If it is then there should be a way to make the timeout longer. I control timeouts using the following statement:

    environment = ClusterEnvironment.builder().timeoutConfig(
            TimeoutConfig.kvTimeout(Duration.ofMillis(opTimeout))
                    .connectTimeout(Duration.ofMillis(connectTimeout))
                    .queryTimeout(Duration.ofMillis(queryTimeout))
            )
            .build();

There are some more methods available on the TimeoutConfig object (e.g. analyticsTimeout() and managementTimeout()). Will either of those work? While you’re tidying up the SDK I can stop the warnings by increasing the timeout so the config can be loaded before the timeout expires.

And to answer your question- no, no other warnings in the log.

Cheers,

Pawel

PS: I appreciate your quick replies on this so far. I’ve been using Couchabse for a while and on number of projects and the support has always been very good!

1 Like
6

@Ratlake_Pawel this specific operation uses the connectTimeout on the timeout settings, you can make that longer for now but I’m trying to change the code so you don’t have to worry about it.

7

Oh, OK. This timeout is already at 20 seconds so something is running pretty lowly. It must be because I’m using the smallest AWS instance (this is test environment only). I will increase the connection timeout to 60 seconds and hopefully the warnings will stop.

Will the code, you’re changing, be available as a new SDK version on maven? Presumably all I will need to do is to change the version in my pom file?

Pawel

8

Does this mean a micro instance? Also, is the cluster local to the client (e.g., same AWS region)? We do have some experience with some warnings like this being logged in very resource constrained environments. For testing, that should be fine and you’ll just need to adjust tune-ables.

9

Yes, the Java app is on micro instances but the DB cluster runs on two medium size instances. They are all in one AWS region but in different availability zones.

10

I’ll defer to @daschl, but because of how micro instances run, I bet it wouldn’t be unusual to see the occasional timeout for a config request while your other requests are actually being done with higher timeouts. The config request is intentionally low because in regular execution, it plays a role in fast failover.

11

Something is definitely wrong in the way those tracing events work. Or it could be my configuration but I’d like to get to the bottom of it and understand how to fix “the problem”. It’s either tracing is wrong or the cluster config (SDK config) is wrong.

I did some more tests and I noticed that the warnings appear even if I increase the timeout to 60 seconds. I then increased the size of AWS instances to t3 medium and finally to t3.xlarge. It made ABSOLUTELY no difference. The warnings still appear with 20 seconds regularity. It’s always the same: the “s” property has the value of “carrierbucketconfig”. The system is completely idle- only servicing healthcheck requests from the load balancer. These health checks hit Couchbase DB. I did it on purpose for the load balancer to kill an instance if it loses connection to Couchbase server. However there’s a healthcheck hit every 3 minutes so it’s pretty much zero load.

I never notice those when I run the system locally on a bunch of VMs running on my Mac. In this setup there’s one Ubuntu VM to run Couchbase and the Java app runs natively on the Mac.

12

Here is an example from the log taken from t3.xlarge instance:

------ Inside filter --------
Request URL = http://172.31.46.150:8080/api/v1/open/healthcheck
—> Token passed: null
2020-03-05 10:43:18.065 | WARN | cb-events | [com.couchbase.tracing][OrphansRecordedEvent][10s] Orphaned requests found: [{“top”:[{“b”:“automatrics”,“r”:“172.31.20.48:11210”,“s”:“carrierbucketconfig”,“c”:“0000000000000001/00000000AFA94E1A”,“t”:2500,“i”:“0x110”,“l”:“172.31.46.150:50160”}],“service”:“kv”,“count”:1}]
2020-03-05 10:43:28.078 | WARN | cb-events | [com.couchbase.tracing][OrphansRecordedEvent][10s] Orphaned requests found: [{“top”:[{“b”:“automatrics”,“r”:“172.31.20.48:11210”,“s”:“carrierbucketconfig”,“c”:“0000000000000001/00000000AFA94E1A”,“t”:2500,“i”:“0x118”,“l”:“172.31.46.150:50160”}],“service”:“kv”,“count”:1}]
2020-03-05 10:43:38.091 | WARN | cb-events | [com.couchbase.tracing][OrphansRecordedEvent][10s] Orphaned requests found: [{“top”:[{“b”:“automatrics”,“r”:“172.31.20.48:11210”,“s”:“carrierbucketconfig”,“c”:“0000000000000001/00000000AFA94E1A”,“t”:2500,“i”:“0x11c”,“l”:“172.31.46.150:50160”},{“b”:“automatrics”,“r”:“172.31.20.48:11210”,“s”:“carrierbucketconfig”,“c”:“0000000000000001/00000000AFA94E1A”,“t”:2500,“i”:“0x120”,“l”:“172.31.46.150:50160”}],“service”:“kv”,“count”:2}]
2020-03-05 10:43:48.103 | WARN | cb-events | [com.couchbase.tracing][OrphansRecordedEvent][10s] Orphaned requests found: [{“top”:[{“b”:“automatrics”,“r”:“172.31.20.48:11210”,“s”:“carrierbucketconfig”,“c”:“0000000000000001/00000000AFA94E1A”,“t”:2500,“i”:“0x125”,“l”:“172.31.46.150:50160”}],“service”:“kv”,“count”:1}]
------ Inside filter --------
Request URL = http://172.31.46.150:8080/api/v1/open/healthcheck
—> Token passed: null
2020-03-05 10:43:58.114 | WARN | cb-events | [com.couchbase.tracing][OrphansRecordedEvent][10s] Orphaned requests found: [{“top”:[{“b”:“automatrics”,“r”:“172.31.20.48:11210”,“s”:“carrierbucketconfig”,“c”:“0000000000000001/00000000AFA94E1A”,“t”:2500,“i”:“0x12e”,“l”:“172.31.46.150:50160”}],“service”:“kv”,“count”:1}]
2020-03-05 10:44:38.160 | WARN | cb-events | [com.couchbase.tracing][OrphansRecordedEvent][10s] Orphaned requests found: [{“top”:[{“b”:“automatrics”,“r”:“172.31.20.48:11210”,“s”:“carrierbucketconfig”,“c”:“0000000000000001/00000000AFA94E1A”,“t”:2500,“i”:“0x145”,“l”:“172.31.46.150:50160”}],“service”:“kv”,“count”:1}]
2020-03-05 10:44:48.172 | WARN | cb-events | [com.couchbase.tracing][OrphansRecordedEvent][10s] Orphaned requests found: [{“top”:[{“b”:“automatrics”,“r”:“172.31.20.48:11210”,“s”:“carrierbucketconfig”,“c”:“0000000000000001/00000000AFA94E1A”,“t”:2500,“i”:“0x151”,“l”:“172.31.46.150:50160”}],“service”:“kv”,“count”:1}]
2020-03-05 10:45:08.196 | WARN | cb-events | [com.couchbase.tracing][OrphansRecordedEvent][10s] Orphaned requests found: [{“top”:[{“b”:“automatrics”,“r”:“172.31.20.48:11210”,“s”:“carrierbucketconfig”,“c”:“0000000000000001/00000000AFA94E1A”,“t”:2500,“i”:“0x15d”,“l”:“172.31.46.150:50160”}],“service”:“kv”,“count”:1}]
2020-03-05 10:45:28.219 | WARN | cb-events | [com.couchbase.tracing][OrphansRecordedEvent][10s] Orphaned requests found: [{“top”:[{“b”:“automatrics”,“r”:“172.31.20.48:11210”,“s”:“carrierbucketconfig”,“c”:“0000000000000001/00000000AFA94E1A”,“t”:2500,“i”:“0x166”,“l”:“172.31.46.150:50160”},{“b”:“automatrics”,“r”:“172.31.20.48:11210”,“s”:“carrierbucketconfig”,“c”:“0000000000000001/00000000AFA94E1A”,“t”:2500,“i”:“0x169”,“l”:“172.31.46.150:50160”},{“b”:“automatrics”,“r”:“172.31.20.48:11210”,“s”:“carrierbucketconfig”,“c”:“0000000000000001/00000000AFA94E1A”,“t”:2500,“i”:“0x16a”,“l”:“172.31.46.150:50160”}],“service”:“kv”,“count”:3}]
2020-03-05 10:45:38.230 | WARN | cb-events | [com.couchbase.tracing][OrphansRecordedEvent][10s] Orphaned requests found: [{“top”:[{“b”:“automatrics”,“r”:“172.31.20.48:11210”,“s”:“carrierbucketconfig”,“c”:“0000000000000001/00000000AFA94E1A”,“t”:2500,“i”:“0x16d”,“l”:“172.31.46.150:50160”}],“service”:“kv”,“count”:1}]
------ Inside filter --------
Request URL = http://172.31.46.150:8080/api/v1/open/healthcheck
—> Token passed: null
2020-03-05 10:45:48.241 | WARN | cb-events | [com.couchbase.tracing][OrphansRecordedEvent][10s] Orphaned requests found: [{“top”:[{“b”:“automatrics”,“r”:“172.31.20.48:11210”,“s”:“carrierbucketconfig”,“c”:“0000000000000001/00000000AFA94E1A”,“t”:2500,“i”:“0x172”,“l”:“172.31.46.150:50160”}],“service”:“kv”,“count”:1}]
2020-03-05 10:45:58.252 | WARN | cb-events | [com.couchbase.tracing][OrphansRecordedEvent][10s] Orphaned requests found: [{“top”:[{“b”:“automatrics”,“r”:“172.31.20.48:11210”,“s”:“carrierbucketconfig”,“c”:“0000000000000001/00000000AFA94E1A”,“t”:2500,“i”:“0x17b”,“l”:“172.31.46.150:50160”},{“b”:“automatrics”,“r”:“172.31.20.48:11210”,“s”:“carrierbucketconfig”,“c”:“0000000000000001/00000000AFA94E1A”,“t”:2500,“i”:“0x17e”,“l”:“172.31.46.150:50160”},{“b”:“automatrics”,“r”:“172.31.20.48:11210”,“s”:“carrierbucketconfig”,“c”:“0000000000000001/00000000AFA94E1A”,“t”:2500,“i”:“0x17f”,“l”:“172.31.46.150:50160”}],“service”:“kv”,“count”:3}]
2020-03-05 10:46:08.265 | WARN | cb-events | [com.couchbase.tracing][OrphansRecordedEvent][10s] Orphaned requests found: [{“top”:[{“b”:“automatrics”,“r”:“172.31.20.48:11210”,“s”:“carrierbucketconfig”,“c”:“0000000000000001/00000000AFA94E1A”,“t”:2500,“i”:“0x186”,“l”:“172.31.46.150:50160”}],“service”:“kv”,“count”:1}]
2020-03-05 10:46:18.277 | WARN | cb-events | [com.couchbase.tracing][OrphansRecordedEvent][10s] Orphaned requests found: [{“top”:[{“b”:“automatrics”,“r”:“172.31.20.48:11210”,“s”:“carrierbucketconfig”,“c”:“0000000000000001/00000000AFA94E1A”,“t”:2500,“i”:“0x18e”,“l”:“172.31.46.150:50160”}],“service”:“kv”,“count”:1}]
2020-03-05 10:46:28.289 | WARN | cb-events | [com.couchbase.tracing][OrphansRecordedEvent][10s] Orphaned requests found: [{“top”:[{“b”:“automatrics”,“r”:“172.31.20.48:11210”,“s”:“carrierbucketconfig”,“c”:“0000000000000001/00000000AFA94E1A”,“t”:2500,“i”:“0x192”,“l”:“172.31.46.150:50160”}],“service”:“kv”,“count”:1}]
2020-03-05 10:46:48.312 | WARN | cb-events | [com.couchbase.tracing][OrphansRecordedEvent][10s] Orphaned requests found: [{“top”:[{“b”:“automatrics”,“r”:“172.31.20.48:11210”,“s”:“carrierbucketconfig”,“c”:“0000000000000001/00000000AFA94E1A”,“t”:2500,“i”:“0x19b”,“l”:“172.31.46.150:50160”},{“b”:“automatrics”,“r”:“172.31.20.48:11210”,“s”:“carrierbucketconfig”,“c”:“0000000000000001/00000000AFA94E1A”,“t”:2500,“i”:“0x19e”,“l”:“172.31.46.150:50160”},{“b”:“automatrics”,“r”:“172.31.20.48:11210”,“s”:“carrierbucketconfig”,“c”:“0000000000000001/00000000AFA94E1A”,“t”:2500,“i”:“0x19f”,“l”:“172.31.46.150:50160”},{“b”:“automatrics”,“r”:“172.31.20.48:11210”,“s”:“carrierbucketconfig”,“c”:“0000000000000001/00000000AFA94E1A”,“t”:2500,“i”:“0x1a2”,“l”:“172.31.46.150:50160”}],“service”:“kv”,“count”:4}]
2020-03-05 10:47:18.347 | WARN | cb-events | [com.couchbase.tracing][OrphansRecordedEvent][10s] Orphaned requests found: [{“top”:[{“b”:“automatrics”,“r”:“172.31.20.48:11210”,“s”:“carrierbucketconfig”,“c”:“0000000000000001/00000000AFA94E1A”,“t”:2500,“i”:“0x1b2”,“l”:“172.31.46.150:50160”}],“service”:“kv”,“count”:1}]
2020-03-05 10:47:28.358 | WARN | cb-events | [com.couchbase.tracing][OrphansRecordedEvent][10s] Orphaned requests found: [{“top”:[{“b”:“automatrics”,“r”:“172.31.20.48:11210”,“s”:“carrierbucketconfig”,“c”:“0000000000000001/00000000AFA94E1A”,“t”:2500,“i”:“0x1ba”,“l”:“172.31.46.150:50160”}],“service”:“kv”,“count”:1}]
2020-03-05 10:47:38.370 | WARN | cb-events | [com.couchbase.tracing][OrphansRecordedEvent][10s] Orphaned requests found: [{“top”:[{“b”:“automatrics”,“r”:“172.31.20.48:11210”,“s”:“carrierbucketconfig”,“c”:“0000000000000001/00000000AFA94E1A”,“t”:2500,“i”:“0x1be”,“l”:“172.31.46.150:50160”},{“b”:“automatrics”,“r”:“172.31.20.48:11210”,“s”:“carrierbucketconfig”,“c”:“0000000000000001/00000000AFA94E1A”,“t”:2500,“i”:“0x1c2”,“l”:“172.31.46.150:50160”}],“service”:“kv”,“count”:2}]
2020-03-05 10:47:48.382 | WARN | cb-events | [com.couchbase.tracing][OrphansRecordedEvent][10s] Orphaned requests found: [{“top”:[{“b”:“automatrics”,“r”:“172.31.20.48:11210”,“s”:“carrierbucketconfig”,“c”:“0000000000000001/00000000AFA94E1A”,“t”:2500,“i”:“0x1c6”,“l”:“172.31.46.150:50160”},{“b”:“automatrics”,“r”:“172.31.20.48:11210”,“s”:“carrierbucketconfig”,“c”:“0000000000000001/00000000AFA94E1A”,“t”:2500,“i”:“0x1ca”,“l”:“172.31.46.150:50160”}],“service”:“kv”,“count”:2}]
2020-03-05 10:47:58.394 | WARN | cb-events | [com.couchbase.tracing][OrphansRecordedEvent][10s] Orphaned requests found: [{“top”:[{“b”:“automatrics”,“r”:“172.31.20.48:11210”,“s”:“carrierbucketconfig”,“c”:“0000000000000001/00000000AFA94E1A”,“t”:2500,“i”:“0x1cf”,“l”:“172.31.46.150:50160”}],“service”:“kv”,“count”:1}]
2020-03-05 10:48:08.407 | WARN | cb-events | [com.couchbase.tracing][OrphansRecordedEvent][10s] Orphaned requests found: [{“top”:[{“b”:“automatrics”,“r”:“172.31.20.48:11210”,“s”:“carrierbucketconfig”,“c”:“0000000000000001/00000000AFA94E1A”,“t”:2500,“i”:“0x1d3”,“l”:“172.31.46.150:50160”},{“b”:“automatrics”,“r”:“172.31.20.48:11210”,“s”:“carrierbucketconfig”,“c”:“0000000000000001/00000000AFA94E1A”,“t”:2500,“i”:“0x1d6”,“l”:“172.31.46.150:50160”}],“service”:“kv”,“count”:2}]
2020-03-05 10:48:18.417 | WARN | cb-events | [com.couchbase.tracing][OrphansRecordedEvent][10s] Orphaned requests found: [{“top”:[{“b”:“automatrics”,“r”:“172.31.20.48:11210”,“s”:“carrierbucketconfig”,“c”:“0000000000000001/00000000AFA94E1A”,“t”:2500,“i”:“0x1da”,“l”:“172.31.46.150:50160”}],“service”:“kv”,“count”:1}]
2020-03-05 10:48:28.428 | WARN | cb-events | [com.couchbase.tracing][OrphansRecordedEvent][10s] Orphaned requests found: [{“top”:[{“b”:“automatrics”,“r”:“172.31.20.48:11210”,“s”:“carrierbucketconfig”,“c”:“0000000000000001/00000000AFA94E1A”,“t”:2500,“i”:“0x1e2”,“l”:“172.31.46.150:50160”}],“service”:“kv”,“count”:1}]
2020-03-05 10:48:38.439 | WARN | cb-events | [com.couchbase.tracing][OrphansRecordedEvent][10s] Orphaned requests found: [{“top”:[{“b”:“automatrics”,“r”:“172.31.20.48:11210”,“s”:“carrierbucketconfig”,“c”:“0000000000000001/00000000AFA94E1A”,“t”:2500,“i”:“0x1e6”,“l”:“172.31.46.150:50160”},{“b”:“automatrics”,“r”:“172.31.20.48:11210”,“s”:“carrierbucketconfig”,“c”:“0000000000000001/00000000AFA94E1A”,“t”:2500,“i”:“0x1ea”,“l”:“172.31.46.150:50160”}],“service”:“kv”,“count”:2}]
2020-03-05 10:48:48.450 | WARN | cb-events | [com.couchbase.tracing][OrphansRecordedEvent][10s] Orphaned requests found: [{“top”:[{“b”:“automatrics”,“r”:“172.31.20.48:11210”,“s”:“carrierbucketconfig”,“c”:“0000000000000001/00000000AFA94E1A”,“t”:2500,“i”:“0x1ee”,“l”:“172.31.46.150:50160”},{“b”:“automatrics”,“r”:“172.31.20.48:11210”,“s”:“carrierbucketconfig”,“c”:“0000000000000001/00000000AFA94E1A”,“t”:2500,“i”:“0x1f2”,“l”:“172.31.46.150:50160”}],“service”:“kv”,“count”:2}]
------ Inside filter --------
Request URL = http://172.31.46.150:8080/api/v1/open/healthcheck
—> Token passed: null
2020-03-05 10:48:58.360 | WARN | cb-events | [com.couchbase.tracing][OrphansRecordedEvent][10s] Orphaned requests found: [{“top”:[{“b”:“automatrics”,“r”:“172.31.20.48:11210”,“s”:“carrierbucketconfig”,“c”:“0000000000000001/00000000AFA94E1A”,“t”:2500,“i”:“0x1f8”,“l”:“172.31.46.150:50160”}],“service”:“kv”,“count”:1}]
2020-03-05 10:49:08.371 | WARN | cb-events | [com.couchbase.tracing][OrphansRecordedEvent][10s] Orphaned requests found: [{“top”:[{“b”:“automatrics”,“r”:“172.31.20.48:11210”,“s”:“carrierbucketconfig”,“c”:“0000000000000001/00000000AFA94E1A”,“t”:2500,“i”:“0x1ff”,“l”:“172.31.46.150:50160”}],“service”:“kv”,“count”:1}]
2020-03-05 10:49:38.504 | WARN | cb-events | [com.couchbase.tracing][OrphansRecordedEvent][10s] Orphaned requests found: [{“top”:[{“b”:“automatrics”,“r”:“172.31.40.163:11210”,“s”:“carrierbucketconfig”,“c”:“0000000000000001/0000000013BAB853”,“t”:2500,“i”:“0x20e”,“l”:“172.31.46.150:59704”},{“b”:“automatrics”,“r”:“172.31.20.48:11210”,“s”:“carrierbucketconfig”,“c”:“0000000000000001/00000000AFA94E1A”,“t”:2500,“i”:“0x213”,“l”:“172.31.46.150:50160”}],“service”:“kv”,“count”:2}]
2020-03-05 10:50:08.436 | WARN | cb-events | [com.couchbase.tracing][OrphansRecordedEvent][10s] Orphaned requests found: [{“top”:[{“b”:“automatrics”,“r”:“172.31.20.48:11210”,“s”:“carrierbucketconfig”,“c”:“0000000000000001/00000000AFA94E1A”,“t”:2500,“i”:“0x227”,“l”:“172.31.46.150:50160”}],“service”:“kv”,“count”:1}]
2020-03-05 10:50:18.448 | WARN | cb-events | [com.couchbase.tracing][OrphansRecordedEvent][10s] Orphaned requests found: [{“top”:[{“b”:“automatrics”,“r”:“172.31.20.48:11210”,“s”:“carrierbucketconfig”,“c”:“0000000000000001/00000000AFA94E1A”,“t”:2500,“i”:“0x22c”,“l”:“172.31.46.150:50160”}],“service”:“kv”,“count”:1}]
2020-03-05 10:50:28.458 | WARN | cb-events | [com.couchbase.tracing][OrphansRecordedEvent][10s] Orphaned requests found: [{“top”:[{“b”:“automatrics”,“r”:“172.31.20.48:11210”,“s”:“carrierbucketconfig”,“c”:“0000000000000001/00000000AFA94E1A”,“t”:2500,“i”:“0x234”,“l”:“172.31.46.150:50160”}],“service”:“kv”,“count”:1}]
2020-03-05 10:50:38.467 | WARN | cb-events | [com.couchbase.tracing][OrphansRecordedEvent][10s] Orphaned requests found: [{“top”:[{“b”:“automatrics”,“r”:“172.31.20.48:11210”,“s”:“carrierbucketconfig”,“c”:“0000000000000001/00000000AFA94E1A”,“t”:2500,“i”:“0x23b”,“l”:“172.31.46.150:50160”}],“service”:“kv”,“count”:1}]
------ Inside filter --------
Request URL = http://172.31.46.150:8080/api/v1/open/healthcheck
—> Token passed: null
2020-03-05 10:50:48.478 | WARN | cb-events | [com.couchbase.tracing][OrphansRecordedEvent][10s] Orphaned requests found: [{“top”:[{“b”:“automatrics”,“r”:“172.31.20.48:11210”,“s”:“carrierbucketconfig”,“c”:“0000000000000001/00000000AFA94E1A”,“t”:2500,“i”:“0x23f”,“l”:“172.31.46.150:50160”}],“service”:“kv”,“count”:1}]
2020-03-05 10:51:58.557 | WARN | cb-events | [com.couchbase.tracing][OrphansRecordedEvent][10s] Orphaned requests found: [{“top”:[{“b”:“automatrics”,“r”:“172.31.20.48:11210”,“s”:“carrierbucketconfig”,“c”:“0000000000000001/00000000AFA94E1A”,“t”:2500,“i”:“0x270”,“l”:“172.31.46.150:50160”}],“service”:“kv”,“count”:1}]
2020-03-05 10:52:08.568 | WARN | cb-events | [com.couchbase.tracing][OrphansRecordedEvent][10s] Orphaned requests found: [{“top”:[{“b”:“automatrics”,“r”:“172.31.20.48:11210”,“s”:“carrierbucketconfig”,“c”:“0000000000000001/00000000AFA94E1A”,“t”:2500,“i”:“0x274”,“l”:“172.31.46.150:50160”}],“service”:“kv”,“count”:1}]

13

@Ratlake_Pawel did you bump the connectTimeout up on the env and it still shows up?

14

Yes, it doesn’t make a difference. I made it 60 seconds on smaller boxes but only tested 20 seconds timeout on the extra large box. The warnings show up regardless. AWS t3.medium has 2 CPUs and 4 GB memory so I don’t think it’s the limitation here. Network could be. Thinking of it- that’s the only significant difference between tests on localhost and on AWS- the “network distance” between instances. However, the overall cluster performance on AWS is very good. t3.medium for Couchbase and Java gets me document retrieval average time of 30 millisecond.

15

Just to clarify the code to measure this average time looks like that:

    Instant t1 = Instant.now();
    Folder root = folderDb.getRootFolder();
    Instant t2 = Instant.now();

Where getRootFolder() is:

public Folder getRootFolder() {
    Bucket bucket = connection.getBucket();
    Collection collection = bucket.defaultCollection();
    Folder ret = null;
    Rson rson = new Rson();

    GetResult result = collection.get(Folder.ROOT, GetOptions.getOptions().transcoder(RawJsonTranscoder.INSTANCE));
    String json = result.contentAs(String.class);
    if (json != null)
        ret = rson.fromJson(json, Folder.class);

    return ret;
}

The difference between t2 and t1 is 30 milliseconds on average.

16

@Ratlake_Pawel actually I have an idea what’s going on. Can you try set the configPollInterval on the IoConfig to 5 seconds please? By default we poll every 2.5s and if a response takes longer we discard it and read the next one, that’s what you see in the orphans. Would be great to verify, thanks!

17

@daschl - I changed the ioConfig polling interval as advised. The environment setup that I used in Java app is as follows:

    environment = ClusterEnvironment.builder()
            .timeoutConfig(
                    TimeoutConfig.kvTimeout(Duration.ofMillis(opTimeout))
                            .connectTimeout(Duration.ofMillis(connectTimeout))
                            .queryTimeout(Duration.ofMillis(queryTimeout))
            )
            .ioConfig(IoConfig.configPollInterval(Duration.ofMillis(ioPollingInterval)))
            .build();

I ran on test on t3.xlarge instances for Couchbase cluster and for the Java app. The Couchbase cluster is made up of two boxes and so is the Java app cluster.

The change you suggested didn’t make much of a difference. The warnings are rarer but only marginally. I decided to bump up the polling interval even further, to 10 seconds, but it looks like any value over 5 seconds is ignored. The warnings I see now are:

2020-03-09 10:02:52.564 | WARN | cb-events | [com.couchbase.tracing][OrphansRecordedEvent][10s] Orphaned requests found: [{“top”:[{“b”:“automatrics”,“r”:“172.31.19.178:11210”,“s”:“carrierbucketconfig”,“c”:“0000000000000001/00000000A7311A8F”,“t”:5000,“i”:“0xb65”,“l”:“172.31.47.248:33994”}],“service”:“kv”,“count”:1}]

The “t” property of the JSON in the warning changed from 2500 ms which it was before to 5000 ms. However it stays at 5000 ms even if I changed the polling interval to a higher value. That’s why I think anything above 5 seconds is ignored.

This is happening on completely idle system. The only thing that it does is answering to load balancer health checks which happen every 5 minutes. Each health involves a Couchbase get operation. But there are several warnings in between health check requests.

18

Setup:
Couchbase Server 6.0 CE
Java SDK 3.0.2

I run into exactly the same issue. There’s a new warning every 10 seconds in the logs:

12-Mar-2020 11:28:04.811 WARNING [cb-events] com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger.warn [com.couchbase.tracing][OrphansRecordedEvent][10s] Orphaned requests found: [{"top":[{"b":"my_bucket","r":"10.0.0.31:11210","s":"carrierbucketconfig","c":"77994FD100000001/00000000674DB0D6","t":2500,"i":"0x15f","l":"10.0.0.10:58686"},{"b":"my_bucket","r":"10.0.0.32:11210","s":"carrierbucketconfig","c":"77994FD100000001/00000000F4030507","t":2500,"i":"0x162","l":"10.0.0.10:44944"},{"b":"my_bucket","r":"10.0.0.30:11210","s":"carrierbucketconfig","c":"77994FD100000001/0000000096DAA86D","t":2500,"i":"0x160","l":"10.0.0.10:48642"}],"service":"kv","count":3}]
12-Mar-2020 11:28:14.827 WARNING [cb-events] com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger.warn [com.couchbase.tracing][OrphansRecordedEvent][10s] Orphaned requests found: [{"top":[{"b":"my_bucket","r":"10.0.0.34:11210","s":"carrierbucketconfig","c":"77994FD100000001/000000008A2CE249","t":2500,"i":"0x168","l":"10.0.0.10:52314"},{"b":"my_bucket","r":"10.0.0.30:11210","s":"carrierbucketconfig","c":"77994FD100000001/0000000096DAA86D","t":2500,"i":"0x16b","l":"10.0.0.10:48642"},{"b":"my_bucket","r":"10.0.0.30:11210","s":"carrierbucketconfig","c":"77994FD100000001/0000000096DAA86D","t":2500,"i":"0x16d","l":"10.0.0.10:48642"}],"service":"kv","count":3}]
12-Mar-2020 11:28:24.842 WARNING [cb-events] com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger.warn [com.couchbase.tracing][OrphansRecordedEvent][10s] Orphaned requests found: [{"top":[{"b":"my_bucket","r":"10.0.0.31:11210","s":"carrierbucketconfig","c":"77994FD100000001/00000000674DB0D6","t":2500,"i":"0x172","l":"10.0.0.10:58686"}],"service":"kv","count":1}]
12-Mar-2020 11:28:34.856 WARNING [cb-events] com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger.warn [com.couchbase.tracing][OrphansRecordedEvent][10s] Orphaned requests found: [{"top":[{"b":"my_bucket","r":"10.0.0.34:11210","s":"carrierbucketconfig","c":"77994FD100000001/000000008A2CE249","t":2500,"i":"0x17b","l":"10.0.0.10:52314"},{"b":"my_bucket","r":"10.0.0.30:11210","s":"carrierbucketconfig","c":"77994FD100000001/0000000096DAA86D","t":2500,"i":"0x17c","l":"10.0.0.10:48642"}],"service":"kv","count":2}]
12-Mar-2020 11:28:44.971 WARNING [cb-events] com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger.warn [com.couchbase.tracing][OrphansRecordedEvent][10s] Orphaned requests found: [{"top":[{"b":"my_bucket","r":"10.0.0.30:11210","s":"carrierbucketconfig","c":"77994FD100000001/0000000096DAA86D","t":2500,"i":"0x18b","l":"10.0.0.10:48642"}],"service":"kv","count":1}]
12-Mar-2020 11:28:54.883 WARNING [cb-events] com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger.warn [com.couchbase.tracing][OrphansRecordedEvent][10s] Orphaned requests found: [{"top":[{"b":"my_bucket","r":"10.0.0.33:11210","s":"carrierbucketconfig","c":"77994FD100000001/000000008D29D7FF","t":2500,"i":"0x192","l":"10.0.0.10:43430"}],"service":"kv","count":1}]
12-Mar-2020 11:29:04.897 WARNING [cb-events] com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger.warn [com.couchbase.tracing][OrphansRecordedEvent][10s] Orphaned requests found: [{"top":[{"b":"my_bucket","r":"10.0.0.30:11210","s":"carrierbucketconfig","c":"77994FD100000001/0000000096DAA86D","t":2500,"i":"0x198","l":"10.0.0.10:48642"},{"b":"my_bucket","r":"10.0.0.34:11210","s":"carrierbucketconfig","c":"77994FD100000001/000000008A2CE249","t":2500,"i":"0x199","l":"10.0.0.10:52314"},{"b":"my_bucket","r":"10.0.0.30:11210","s":"carrierbucketconfig","c":"77994FD100000001/0000000096DAA86D","t":2500,"i":"0x19a","l":"10.0.0.10:48642"},{"b":"my_bucket","r":"10.0.0.30:11210","s":"carrierbucketconfig","c":"77994FD100000001/0000000096DAA86D","t":2500,"i":"0x19c","l":"10.0.0.10:48642"},{"b":"my_bucket","r":"10.0.0.33:11210","s":"carrierbucketconfig","c":"77994FD100000001/000000008D29D7FF","t":2500,"i":"0x1a1","l":"10.0.0.10:43430"}],"service":"kv","count":5}]
12-Mar-2020 11:29:14.934 WARNING [cb-events] com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger.warn [com.couchbase.tracing][OrphansRecordedEvent][10s] Orphaned requests found: [{"top":[{"b":"my_bucket","r":"10.0.0.33:11210","s":"carrierbucketconfig","c":"77994FD100000001/000000008D29D7FF","t":2500,"i":"0x1a5","l":"10.0.0.10:43430"},{"b":"my_bucket","r":"10.0.0.30:11210","s":"carrierbucketconfig","c":"77994FD100000001/0000000096DAA86D","t":2500,"i":"0x1a9","l":"10.0.0.10:48642"}],"service":"kv","count":2}]
12-Mar-2020 11:29:25.048 WARNING [cb-events] com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger.warn [com.couchbase.tracing][OrphansRecordedEvent][10s] Orphaned requests found: [{"top":[{"b":"my_bucket","r":"10.0.0.30:11210","s":"carrierbucketconfig","c":"77994FD100000001/0000000096DAA86D","t":2500,"i":"0x1ab","l":"10.0.0.10:48642"},{"b":"my_bucket","r":"10.0.0.33:11210","s":"carrierbucketconfig","c":"77994FD100000001/000000008D29D7FF","t":2500,"i":"0x1b0","l":"10.0.0.10:43430"}],"service":"kv","count":2}]
12-Mar-2020 11:29:34.962 WARNING [cb-events] com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger.warn [com.couchbase.tracing][OrphansRecordedEvent][10s] Orphaned requests found: [{"top":[{"b":"my_bucket","r":"10.0.0.30:11210","s":"carrierbucketconfig","c":"77994FD100000001/0000000096DAA86D","t":2500,"i":"0x1b6","l":"10.0.0.10:48642"},{"b":"my_bucket","r":"10.0.0.30:11210","s":"carrierbucketconfig","c":"77994FD100000001/0000000096DAA86D","t":2500,"i":"0x1ba","l":"10.0.0.10:48642"},{"b":"my_bucket","r":"10.0.0.31:11210","s":"carrierbucketconfig","c":"77994FD100000001/00000000674DB0D6","t":2500,"i":"0x1bd","l":"10.0.0.10:58686"}],"service":"kv","count":3}]
12-Mar-2020 11:29:44.983 WARNING [cb-events] com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger.warn [com.couchbase.tracing][OrphansRecordedEvent][10s] Orphaned requests found: [{"top":[{"b":"my_bucket","r":"10.0.0.32:11210","s":"carrierbucketconfig","c":"77994FD100000001/00000000F4030507","t":2500,"i":"0x1c0","l":"10.0.0.10:44944"},{"b":"my_bucket","r":"10.0.0.34:11210","s":"carrierbucketconfig","c":"77994FD100000001/000000008A2CE249","t":2500,"i":"0x1c2","l":"10.0.0.10:52314"},{"b":"my_bucket","r":"10.0.0.30:11210","s":"carrierbucketconfig","c":"77994FD100000001/0000000096DAA86D","t":2500,"i":"0x1c5","l":"10.0.0.10:48642"},{"b":"my_bucket","r":"10.0.0.31:11210","s":"carrierbucketconfig","c":"77994FD100000001/00000000674DB0D6","t":2500,"i":"0x1c8","l":"10.0.0.10:58686"}],"service":"kv","count":4}]

Setup code:

clusterEnvironment = ClusterEnvironment.builder().build();

This is run only once in ServletContextListener. So only once when the app code is first run. Connection is only closed when app is destroyed:

@Override
public void contextDestroyed(ServletContextEvent sce) {
    cluster.disconnect();
    clusterEnvironment.shutdown();
}

Time to send a request, run query and receive response is taking about 50ms - 150ms.

1 Like
19

I am also facing the same issue. The logs are getting written every 10 seconds. I have disabled them in logger file for now.

20

Are there any updates on this issue? I’m trying to go through logs right now and the orphan logs make it difficult.