Replicator with couchbase lite android 2.0

Mobile Couchbase Lite
1

Hello,
I developped an Android application based on couchbase lite 1.5.
I actualy migrate the application on 2.0 version but I have some problems/questions with new Replicator class.

My application use several replicators and some times I need to close database. I correctly call stop on all my replicators and wait for ActivityLevel.STOPPED on each of them, but only the last replicator instanciated passed to STOPPED.
This cause this backtrace when I call close method on database :

04-18 12:01:56.270 11570-11585/mapotempo.com.fleet.test W/System.err: CouchbaseLiteException{domain='CouchbaseLite', code=16, msg=Cannot close the database.  Please stop all of the replicators before closing the database.}
04-18 12:01:56.272 11570-11585/mapotempo.com.fleet.test W/System.err:     at com.couchbase.lite.AbstractDatabase.close(AbstractDatabase.java:440)
04-18 12:01:56.272 11570-11585/mapotempo.com.fleet.test W/System.err:     at com.couchbase.lite.Database.close(Database.java:25)
04-18 12:01:56.272 11570-11585/mapotempo.com.fleet.test W/System.err:     at mapotempo.com.fleet.core.DabaseHandler.release(DabaseHandler.java:235)
04-18 12:01:56.273 11570-11585/mapotempo.com.fleet.test W/System.err:     at mapotempo.com.fleet.ExampleInstrumentedTest.useAppContext(ExampleInstrumentedTest.java:100)
04-18 12:01:56.273 11570-11585/mapotempo.com.fleet.test W/System.err:     at java.lang.reflect.Method.invoke(Native Method)
04-18 12:01:56.274 11570-11585/mapotempo.com.fleet.test W/System.err:     at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
04-18 12:01:56.274 11570-11585/mapotempo.com.fleet.test W/System.err:     at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
04-18 12:01:56.275 11570-11585/mapotempo.com.fleet.test W/System.err:     at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
04-18 12:01:56.275 11570-11585/mapotempo.com.fleet.test W/System.err:     at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
04-18 12:01:56.276 11570-11585/mapotempo.com.fleet.test W/System.err:     at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
04-18 12:01:56.276 11570-11585/mapotempo.com.fleet.test W/System.err:     at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
04-18 12:01:56.277 11570-11585/mapotempo.com.fleet.test W/System.err:     at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
04-18 12:01:56.277 11570-11585/mapotempo.com.fleet.test W/System.err:     at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
04-18 12:01:56.277 11570-11585/mapotempo.com.fleet.test W/System.err:     at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
04-18 12:01:56.278 11570-11585/mapotempo.com.fleet.test W/System.err:     at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
04-18 12:01:56.278 11570-11585/mapotempo.com.fleet.test W/System.err:     at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
04-18 12:01:56.279 11570-11585/mapotempo.com.fleet.test W/System.err:     at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
04-18 12:01:56.279 11570-11585/mapotempo.com.fleet.test W/System.err:     at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
04-18 12:01:56.280 11570-11585/mapotempo.com.fleet.test W/System.err:     at org.junit.runners.Suite.runChild(Suite.java:128)
04-18 12:01:56.281 11570-11585/mapotempo.com.fleet.test W/System.err:     at org.junit.runners.Suite.runChild(Suite.java:27)
04-18 12:01:56.282 11570-11585/mapotempo.com.fleet.test W/System.err:     at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
04-18 12:01:56.283 11570-11585/mapotempo.com.fleet.test W/System.err:     at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
04-18 12:01:56.284 11570-11585/mapotempo.com.fleet.test W/System.err:     at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
04-18 12:01:56.284 11570-11585/mapotempo.com.fleet.test W/System.err:     at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
04-18 12:01:56.285 11570-11585/mapotempo.com.fleet.test W/System.err:     at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
04-18 12:01:56.285 11570-11585/mapotempo.com.fleet.test W/System.err:     at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
04-18 12:01:56.286 11570-11585/mapotempo.com.fleet.test W/System.err:     at org.junit.runners.Suite.runChild(Suite.java:128)
04-18 12:01:56.286 11570-11585/mapotempo.com.fleet.test W/System.err:     at org.junit.runners.Suite.runChild(Suite.java:27)
04-18 12:01:56.286 11570-11585/mapotempo.com.fleet.test W/System.err:     at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
04-18 12:01:56.287 11570-11585/mapotempo.com.fleet.test W/System.err:     at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
04-18 12:01:56.287 11570-11585/mapotempo.com.fleet.test W/System.err:     at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
04-18 12:01:56.288 11570-11585/mapotempo.com.fleet.test W/System.err:     at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
04-18 12:01:56.288 11570-11585/mapotempo.com.fleet.test W/System.err:     at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
04-18 12:01:56.289 11570-11585/mapotempo.com.fleet.test W/System.err:     at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
04-18 12:01:56.289 11570-11585/mapotempo.com.fleet.test W/System.err:     at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
04-18 12:01:56.289 11570-11585/mapotempo.com.fleet.test W/System.err:     at org.junit.runner.JUnitCore.run(JUnitCore.java:115)
04-18 12:01:56.290 11570-11585/mapotempo.com.fleet.test W/System.err:     at android.support.test.internal.runner.TestExecutor.execute(TestExecutor.java:58)
04-18 12:01:56.290 11570-11585/mapotempo.com.fleet.test W/System.err:     at android.support.test.runner.AndroidJUnitRunner.onStart(AndroidJUnitRunner.java:375)
04-18 12:01:56.291 11570-11585/mapotempo.com.fleet.test W/System.err:     at android.app.Instrumentation$InstrumentationThread.run(Instrumentation.java:2075)

What is the good way to use Replicator class ?

2

The pattern that you are following is correct - you must stop all replicators and wait for activity level to be stopped and then close database. You are getting the exception because apparently some of replicators weren’t not closed properly (for whatever reason).

Can you share the code snippet that demonstrates how you are handling this ?

This is an example of how you would do this. Please enable appropriate log level in your Android app and share your logcat logs.


try {
 // Call this method for each active replicator
   stopContinuousReplicator(myRepl)
}
finally {
   myDB.close();
}


 void stopContinuousReplicator(Replicator repl) throws InterruptedException {
        final CountDownLatch latch = new CountDownLatch(1);
        ListenerToken token = repl.addChangeListener(new ReplicatorChangeListener() {
            @Override
            public void changed(ReplicatorChange change) {
                Replicator.Status status = change.getStatus();
                if (status.getActivityLevel() == Replicator.ActivityLevel.STOPPED) {
                    latch.countDown();
                }
            }
        });
        try {
            repl.stop();
            assertTrue(latch.await(timeout, TimeUnit.SECONDS));
        } finally {
            repl.removeChangeListener(token);
        }
    }
3

Thank you for the answer

I create two replicator with this functions, in the same class :


    public void configureUserReplication() throws FleetException {
        ReplicatorConfiguration replConfig = new ReplicatorConfiguration(mDatabase, mTargetEndpoint);
        replConfig.setReplicatorType(ReplicatorConfiguration.ReplicatorType.PUSH_AND_PULL);
        replConfig.setContinuous(true);
        replConfig.setAuthenticator(new BasicAuthenticator(mUser, mPassword));
        List<String> channels = new ArrayList<>();
        channels.add("!");
        channels.add("user:" + mUser);
        replConfig.setChannels(channels);

        mUserReplicator = new Replicator(replConfig);
        ListenerToken tk = mUserReplicator.addChangeListener(new ReplicatorChangeListener() {
            @Override
            public void changed(ReplicatorChange change) {
                if (change.getStatus().getError() != null) {
                    Log.i(TAG, "Error code ::  " + change.getStatus().getError().getCode());
                    switch (change.getStatus().getError().getCode()) {
                        case 10401:
                            mOnCatchLoginError.CatchLoginError();
                            break;
                        default:
                            break;
                    }
                }
            }
        });
        mUserReplicator.start();

        mReplicatorList.add(mUserReplicator);
    }

    public void configureCompanyReplication(String companyId) throws FleetException {
        ReplicatorConfiguration replConfig = new ReplicatorConfiguration(mDatabase, mTargetEndpoint);
        replConfig.setReplicatorType(ReplicatorConfiguration.ReplicatorType.PUSH_AND_PULL);
        replConfig.setContinuous(true);
        replConfig.setAuthenticator(new BasicAuthenticator(mUser, mPassword));
        List<String> channels = new ArrayList<>();
        channels.add("company:" + companyId);
        channels.add("mission_status_type:" + companyId);
        channels.add("mission_action_type:" + companyId);
        replConfig.setChannels(channels);
        mCompanyReplicator = new Replicator(replConfig);
        mCompanyReplicator.start();
        mReplicatorList.add(mCompanyReplicator);
    }

and here my release function :


    /**
     * Close database and delete if required.
     * This function is blocking.
     *
     * @param deleteDB database deleting option
     * @throws FleetException
     */
    public void release(final boolean deleteDB) throws FleetException {
        for (Replicator r : mReplicatorList) {
            try {
                stopContinuousReplicator(r);
            } catch (InterruptedException e) {
                e.printStackTrace();
            }
        }

        try {
            if (deleteDB)
                mDatabase.delete();
            else
                mDatabase.close();
        } catch (CouchbaseLiteException e) {
            throw new FleetException("Error during database closing", e);
        }
    }

    private void stopContinuousReplicator(Replicator repl) throws InterruptedException {
        final CountDownLatch latch = new CountDownLatch(1);
        ListenerToken token = repl.addChangeListener(new ReplicatorChangeListener() {
            @Override
            public void changed(ReplicatorChange change) {
                Replicator.Status status = change.getStatus();
                if (status.getActivityLevel() == Replicator.ActivityLevel.STOPPED) {
                    latch.countDown();
                }
            }
        });
        try {
            repl.stop();
            latch.await(10, TimeUnit.SECONDS);
        } finally {
            repl.removeChangeListener(token);
        }
    }

Sometimes the timeout exceed and mDatabase.close() is caled during a replicator is running (I tryed with with longer timeout > 1 hour).

4

Looks like you are tracking this here ?

5

Note the ReplicatorChangeListener gets called when the replication state makes a transition. If any of your replications have stopped before you call stopContinuousReplicator it looks to me like your code will miss it. This could explain waiting indefinitely on the latch.

6

It’s my issue :grinning:

7

All replicators are stop only once in the release function.

8

Here the log between close execution and the timeout :

04-19 10:21:51.317 5601-5616/mapotempo.com.fleet.test I/mapotempo.com.fleet.core.DatabaseHandler:     >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>> try latch
    04-19 10:21:51.318 5601-5616/mapotempo.com.fleet.test I/LiteCoreJNI: [NATIVE] C4Replicator.stop() repl -> 0xa2e20c00
    04-19 10:21:51.318 5601-5621/mapotempo.com.fleet.test I/LiteCore [Sync]: {Repl#1} Told to stop!
    04-19 10:21:51.318 5601-5621/mapotempo.com.fleet.test I/LiteCore [BLIP]: {N8litecore4blip10ConnectionE#1} Close connection
    04-19 10:21:51.318 5601-5621/mapotempo.com.fleet.test I/LiteCore [Sync]: {Repl#1} activityLevel=busy: connectionState=3
    04-19 10:21:51.318 5601-5621/mapotempo.com.fleet.test I/LiteCore [Sync]: {Repl#1} now busy
    04-19 10:21:51.318 5601-5621/mapotempo.com.fleet.test I/LiteCoreJNI: [NATIVE] C4Replicator.statusChangedCallback() repl -> 0x0x7ea2e20c00 status -> 4
    04-19 10:21:51.319 5601-5620/mapotempo.com.fleet.test I/LiteCore [WS]: {N8litecore9websocket12C4SocketImplE#1}==> N8litecore9websocket12C4SocketImplE ws:192.168.1.252:4984/db/_blipsync
    04-19 10:21:51.319 5601-5620/mapotempo.com.fleet.test I/LiteCore [WS]: {N8litecore9websocket12C4SocketImplE#1} Requesting close with status=1000, message=''
    04-19 10:21:51.321 5601-5621/mapotempo.com.fleet.test I/Sync: C4ReplicatorListener.statusChanged() status -> C4ReplicatorStatus{activityLevel=4, progressUnitsCompleted=0, progressUnitsTotal=0, progressDocumentCount=0, errorDomain=0, errorCode=0, errorInternalInfo=0}
    04-19 10:21:51.323 5601-5624/mapotempo.com.fleet.test I/LiteCoreJNI: [NATIVE] C4Replicator.getResponseHeaders() repl -> 0xa2e20c00
    04-19 10:21:51.323 5601-5624/mapotempo.com.fleet.test I/Sync: statusChanged() c4Status -> C4ReplicatorStatus{activityLevel=4, progressUnitsCompleted=0, progressUnitsTotal=0, progressDocumentCount=0, errorDomain=0, errorCode=0, errorInternalInfo=0}
    04-19 10:21:51.328 5601-5624/mapotempo.com.fleet.test I/Sync: Replicator[<*> Database@52ef085{name='database_c8cc2442d38d969'} URLEndpoint{url=ws://192.168.1.252:4984/db}] is busy, progress 0/0, error: null
    04-19 10:21:51.435 5601-5627/mapotempo.com.fleet.test V/WS: WebSocketListener.onClosing() code -> 1000, reason -> 
    04-19 10:21:51.436 5601-5627/mapotempo.com.fleet.test W/WS: CBLWebSocket.requestClose() Failed to attempt to initiate a graceful shutdown of this web socket.
    04-19 10:21:51.437 5601-5627/mapotempo.com.fleet.test V/WS: WebSocketListener.onClosed() code -> 1000, reason -> 
    04-19 10:21:51.437 5601-5627/mapotempo.com.fleet.test I/LiteCore [WS]: {N8litecore9websocket12C4SocketImplE#2}==> N8litecore9websocket12C4SocketImplE ws:192.168.1.252:4984/db/_blipsync
    04-19 10:21:51.438 5601-5627/mapotempo.com.fleet.test I/LiteCore [WS]: {N8litecore9websocket12C4SocketImplE#2} sent 733 bytes, rcvd 8075, in 1.975 sec (371/sec, 4088/sec)
    04-19 10:21:51.438 5601-5623/mapotempo.com.fleet.test I/LiteCore [BLIP]: {N8litecore4blip10ConnectionE#2} Closed with WebSocket status 1000: 
    04-19 10:21:51.438 5601-5622/mapotempo.com.fleet.test I/LiteCore [Sync]: {Repl#2} Connection closed with WebSocket status 1000: "" (state=2)
    04-19 10:21:51.438 5601-5622/mapotempo.com.fleet.test I/LiteCore [Sync]: {Repl#2} I didn't initiate the close; treating this as code 1001 (GoingAway)
    04-19 10:21:51.438 5601-5618/mapotempo.com.fleet.test I/LiteCore [Sync]: {DBWorker#3} activityLevel=idle: pendingResponseCount=0, eventCount=1
    04-19 10:21:51.439 5601-5618/mapotempo.com.fleet.test I/LiteCore [Sync]: {Push#5} activityLevel=idle: pendingResponseCount=0, caughtUp=1, changeLists=0, revsInFlight=0, blobsInFlight=0, awaitingReply=0, revsToSend=0, pendingSequences=0
    04-19 10:21:51.439 5601-5622/mapotempo.com.fleet.test E/LiteCore [Sync]: {Repl#2} Got LiteCore error: WebSocket connection closed by peer (6/1001)
    04-19 10:21:51.439 5601-5622/mapotempo.com.fleet.test I/LiteCore [Sync]: {Repl#2} activityLevel=stopped: connectionState=0
    04-19 10:21:51.439 5601-5622/mapotempo.com.fleet.test I/LiteCore [Sync]: {Repl#2} now stopped
    04-19 10:21:51.439 5601-5618/mapotempo.com.fleet.test I/LiteCore [BLIP]: {N8litecore4blip6BLIPIOE#3}==> N8litecore4blip6BLIPIOE 0x7ea2e924c8
    04-19 10:21:51.439 5601-5618/mapotempo.com.fleet.test I/LiteCore [BLIP]: {N8litecore4blip6BLIPIOE#3} ~BLIPIO: Sent 733 bytes, rcvd 8075. Max outbox depth was 1, avg 1.00
    04-19 10:21:51.440 5601-5622/mapotempo.com.fleet.test I/LiteCoreJNI: [NATIVE] C4Replicator.statusChangedCallback() repl -> 0x0x7ea2e215a0 status -> 0
    04-19 10:21:51.440 5601-5618/mapotempo.com.fleet.test I/LiteCore [Sync]: {Pull#4} activityLevel=idle: pendingResponseCount=0, _caughtUp=1, _waitingForChangesCallback=0, _pendingRevMessages=0, _activeIncomingRevs=0
    04-19 10:21:51.441 5601-5618/mapotempo.com.fleet.test I/LiteCore [DB]: Closing database /data/user/0/mapotempo.com.fleet.test/files/database_c8cc2442d38d969.cblite2/db.sqlite3
    04-19 10:21:51.442 5601-5622/mapotempo.com.fleet.test I/Sync: C4ReplicatorListener.statusChanged() status -> C4ReplicatorStatus{activityLevel=0, progressUnitsCompleted=33, progressUnitsTotal=66, progressDocumentCount=66, errorDomain=6, errorCode=1001, errorInternalInfo=1000}
    04-19 10:21:51.444 5601-5625/mapotempo.com.fleet.test I/Sync: statusChanged() c4Status -> C4ReplicatorStatus{activityLevel=0, progressUnitsCompleted=33, progressUnitsTotal=66, progressDocumentCount=66, errorDomain=6, errorCode=1001, errorInternalInfo=1000}
    04-19 10:21:51.446 5601-5625/mapotempo.com.fleet.test I/LiteCoreJNI: [NATIVE] C4Replicator.free() repl -> 0xa2e215a0
    04-19 10:21:51.446 5601-5619/mapotempo.com.fleet.test I/LiteCore [Sync]: {Repl#2} activityLevel=stopped: connectionState=0
    04-19 10:21:51.450 5601-5625/mapotempo.com.fleet.test I/Sync: Replicator[<*> Database@52ef085{name='database_c8cc2442d38d969'} URLEndpoint{url=ws://192.168.1.252:4984/db}]: Transient error (C4Error{domain=6, code=1001, internalInfo=1000}); will retry in 2 sec...
    04-19 10:21:51.454 5601-5625/mapotempo.com.fleet.test V/Sync: com.couchbase.lite.AndroidNetworkReachabilityManager@270f28a: startListening() registering com.couchbase.lite.AndroidNetworkReachabilityManager$NetworkReceiver@4b980fb with context android.app.ContextImpl@5befbff
    04-19 10:21:51.460 5601-5625/mapotempo.com.fleet.test I/Sync: Replicator[<*> Database@52ef085{name='database_c8cc2442d38d969'} URLEndpoint{url=ws://192.168.1.252:4984/db}] is offline, progress 33/66, error: CouchbaseLiteException{domain='CouchbaseLite', code=11001, msg=null}
    04-19 10:21:51.461 5601-5601/mapotempo.com.fleet.test V/Sync: NetworkReceiver.onReceive() Online -> true
    04-19 10:21:51.462 5601-5601/mapotempo.com.fleet.test I/Sync: Replicator[<*> Database@52ef085{name='database_c8cc2442d38d969'} URLEndpoint{url=ws://192.168.1.252:4984/db}]: Server may now be reachable; retrying...
    04-19 10:21:51.463 5601-5601/mapotempo.com.fleet.test I/Sync: Replicator[<*> Database@52ef085{name='database_c8cc2442d38d969'} URLEndpoint{url=ws://192.168.1.252:4984/db}]: Retrying...
    04-19 10:21:51.464 5601-5601/mapotempo.com.fleet.test I/LiteCoreJNI: [NATIVE] C4Replicator.create()
    04-19 10:21:51.465 5601-5601/mapotempo.com.fleet.test I/LiteCore [DB]: Opening database /data/user/0/mapotempo.com.fleet.test/files/database_c8cc2442d38d969.cblite2/db.sqlite3
    04-19 10:21:51.467 5601-5601/mapotempo.com.fleet.test I/LiteCore [BLIP]: {N8litecore4blip10ConnectionE#4}==> N8litecore4blip10ConnectionE ->ws:192.168.1.252:4984/db/_blipsync
    04-19 10:21:51.467 5601-5601/mapotempo.com.fleet.test I/LiteCore [BLIP]: {N8litecore4blip10ConnectionE#4} Opening connection...
    04-19 10:21:51.468 5601-5601/mapotempo.com.fleet.test I/LiteCore [Sync]: {Repl#6}==> N8litecore4repl10ReplicatorE /data/user/0/mapotempo.com.fleet.test/files/database_c8cc2442d38d969.cblite2/ ->ws:192.168.1.252:4984/db/_blipsync
    04-19 10:21:51.468 5601-5601/mapotempo.com.fleet.test I/LiteCore [Sync]: {Repl#6} Push=continuous, Pull=continuous, Options={"WS-Protocols":"BLIP_3+CBMobile_2",auth:{password:"123456",type:"Basic",username:"5ffbb992f9c44a4e7a50897f785c5f63d38e587130f7cf86a07359d609dc50dd"},channels:["company:company-dzC-REbyrC","mission_status_type:company-dzC-REbyrC","mission_action_type:company-dzC-REbyrC"],headers:{"User-Agent":"CouchbaseLite/2.0.0-457 (Java; Android 8.1.0; Nexus 5X) Build/0 Commit/8dd6674 LiteCore/ (457)"}}
    04-19 10:21:51.468 5601-5601/mapotempo.com.fleet.test I/LiteCoreJNI: [NATIVE] C4Replicator.create() repl -> 0x0x7ea023fb40
    04-19 10:21:51.469 5601-5601/mapotempo.com.fleet.test I/LiteCoreJNI: [NATIVE] C4Replicator.getStatus() repl -> 0xa023fb40
    04-19 10:21:51.471 5601-5601/mapotempo.com.fleet.test I/Sync: Replicator[<*> Database@52ef085{name='database_c8cc2442d38d969'} URLEndpoint{url=ws://192.168.1.252:4984/db}] is connecting, progress 0/0, error: null
    04-19 10:21:51.471 5601-5601/mapotempo.com.fleet.test I/Sync: C4ReplicatorListener.statusChanged() status -> C4ReplicatorStatus{activityLevel=2, progressUnitsCompleted=0, progressUnitsTotal=0, progressDocumentCount=0, errorDomain=0, errorCode=0, errorInternalInfo=0}
    04-19 10:21:51.472 5601-5625/mapotempo.com.fleet.test I/Sync: statusChanged() c4Status -> C4ReplicatorStatus{activityLevel=2, progressUnitsCompleted=0, progressUnitsTotal=0, progressDocumentCount=0, errorDomain=0, errorCode=0, errorInternalInfo=0}
    04-19 10:21:51.474 5601-5625/mapotempo.com.fleet.test I/Sync: Replicator[<*> Database@52ef085{name='database_c8cc2442d38d969'} URLEndpoint{url=ws://192.168.1.252:4984/db}] is connecting, progress 0/0, error: null
    04-19 10:21:51.475 5601-5623/mapotempo.com.fleet.test V/WS: CBLWebSocket connecting to ws://192.168.1.252:4984/db/_blipsync...
    04-19 10:21:51.482 5601-5623/mapotempo.com.fleet.test I/LiteCore [Sync]: {Repl#6} activityLevel=connecting: connectionState=1
    04-19 10:21:51.535 5601-5632/mapotempo.com.fleet.test V/WS: Authenticating for response: Response{protocol=http/1.1, code=401, message=Unauthorized, url=http://192.168.1.252:4984/db/_blipsync}
    04-19 10:21:51.536 5601-5632/mapotempo.com.fleet.test V/WS: Challenges: [Basic realm="Couchbase Sync Gateway" charset="ISO-8859-1"]
    04-19 10:21:51.556 5601-5632/mapotempo.com.fleet.test V/WS: WebSocketListener.onOpen() response -> Response{protocol=http/1.1, code=101, message=Switching Protocols, url=http://192.168.1.252:4984/db/_blipsync}
    04-19 10:21:51.557 5601-5632/mapotempo.com.fleet.test V/WS: receivedHTTPResponse() httpStatus -> 101
    04-19 10:21:51.558 5601-5632/mapotempo.com.fleet.test I/WS: CBLWebSocket CONNECTED!
    04-19 10:21:51.558 5601-5618/mapotempo.com.fleet.test I/LiteCore [Sync]: {Repl#6} activityLevel=connecting: connectionState=1
    04-19 10:21:51.558 5601-5632/mapotempo.com.fleet.test I/LiteCore [BLIP]: {N8litecore4blip10ConnectionE#4} Connected!
    04-19 10:21:51.558 5601-5622/mapotempo.com.fleet.test I/LiteCore [Sync]: {Repl#6} Connected!
    04-19 10:21:51.558 5601-5622/mapotempo.com.fleet.test I/LiteCore [Sync]: {Repl#6} activityLevel=busy: connectionState=2
    04-19 10:21:51.558 5601-5622/mapotempo.com.fleet.test I/LiteCore [Sync]: {Repl#6} now busy
    04-19 10:21:51.558 5601-5622/mapotempo.com.fleet.test I/LiteCoreJNI: [NATIVE] C4Replicator.statusChangedCallback() repl -> 0x0x7ea023fb40 status -> 4
    04-19 10:21:51.560 5601-5622/mapotempo.com.fleet.test I/Sync: C4ReplicatorListener.statusChanged() status -> C4ReplicatorStatus{activityLevel=4, progressUnitsCompleted=0, progressUnitsTotal=0, progressDocumentCount=0, errorDomain=0, errorCode=0, errorInternalInfo=0}
    04-19 10:21:51.562 5601-5625/mapotempo.com.fleet.test I/Sync: statusChanged() c4Status -> C4ReplicatorStatus{activityLevel=4, progressUnitsCompleted=0, progressUnitsTotal=0, progressDocumentCount=0, errorDomain=0, errorCode=0, errorInternalInfo=0}
    04-19 10:21:51.564 5601-5625/mapotempo.com.fleet.test V/Sync: com.couchbase.lite.AndroidNetworkReachabilityManager@270f28a: stopListening() unregistering com.couchbase.lite.AndroidNetworkReachabilityManager$NetworkReceiver@4b980fb with context android.app.ContextImpl@5befbff
    04-19 10:21:51.566 5601-5622/mapotempo.com.fleet.test I/LiteCore [Sync]: {DBWorker#7}==> N8litecore4repl8DBWorkerE ->ws:192.168.1.252:4984/db/_blipsync
    04-19 10:21:51.566 5601-5622/mapotempo.com.fleet.test I/LiteCore [Sync]: {DBWorker#7} activityLevel=idle: pendingResponseCount=0, eventCount=1
    04-19 10:21:51.566 5601-5619/mapotempo.com.fleet.test I/LiteCore [Sync]: {Repl#6} Local checkpoint 'cp-omc6U6UKXrkCveuXxTfV7Y6xuQ0=' is [0, '49']; getting remote ...
    04-19 10:21:51.567 5601-5619/mapotempo.com.fleet.test I/LiteCore [Sync]: {Repl#6} activityLevel=busy: connectionState=2
    04-19 10:21:51.567 5601-5619/mapotempo.com.fleet.test I/LiteCore [Sync]: {Repl#6} pushStatus=busy, pullStatus=busy, dbStatus=idle, progress=0/0
    04-19 10:21:51.567 5601-5619/mapotempo.com.fleet.test I/LiteCore [Sync]: {Repl#6} activityLevel=busy: connectionState=2
    04-19 10:21:51.567 5601-5619/mapotempo.com.fleet.test I/LiteCore [Sync]: {Repl#6} activityLevel=busy: connectionState=2
    04-19 10:21:51.569 5601-5625/mapotempo.com.fleet.test I/Sync: Replicator[<*> Database@52ef085{name='database_c8cc2442d38d969'} URLEndpoint{url=ws://192.168.1.252:4984/db}] is busy, progress 0/0, error: null
    04-19 10:21:51.582 5601-5632/mapotempo.com.fleet.test V/WS: WebSocketListener.onMessage() bytes -> 0109522b4a2d6330d0356470cecf2b49cd2bd10da92c4865482c28c8c94c4e2cc9cccfd3cf2acecf63a8562a4acdcd2f4955b232b1ac05009a55eff1
    04-19 10:21:51.583 5601-5618/mapotempo.com.fleet.test I/LiteCore [Sync]: {Repl#6} Received remote checkpoint: [0, '49'] rev='0-1'
    04-19 10:21:51.583 5601-5618/mapotempo.com.fleet.test I/LiteCore [Sync]: {Repl#6} activityLevel=busy: connectionState=2
    04-19 10:21:51.583 5601-5618/mapotempo.com.fleet.test I/LiteCore [Sync]: {Push#8}==> N8litecore4repl6PusherE ->ws:192.168.1.252:4984/db/_blipsync
    04-19 10:21:51.583 5601-5618/mapotempo.com.fleet.test I/LiteCore [Sync]: {Push#8} Starting continuous push from local seq #1
    04-19 10:21:51.583 5601-5618/mapotempo.com.fleet.test I/LiteCore [Sync]: {Push#8} activityLevel=busy: pendingResponseCount=0, caughtUp=0, changeLists=1, revsInFlight=0, blobsInFlight=0, awaitingReply=0, revsToSend=0, pendingSequences=0
    04-19 10:21:51.583 5601-5618/mapotempo.com.fleet.test I/LiteCore [Sync]: {Pull#9}==> N8litecore4repl6PullerE ->ws:192.168.1.252:4984/db/_blipsync
    04-19 10:21:51.583 5601-5618/mapotempo.com.fleet.test I/LiteCore [Sync]: {Pull#9} Starting pull from remote seq 49
    04-19 10:21:51.584 5601-5618/mapotempo.com.fleet.test I/LiteCore [Sync]: {Pull#9} activityLevel=busy: pendingResponseCount=1, _caughtUp=0, _waitingForChangesCallback=0, _pendingRevMessages=0, _activeIncomingRevs=0
    04-19 10:21:51.586 5601-5618/mapotempo.com.fleet.test I/LiteCore [Sync]: {DBWorker#7} activityLevel=idle: pendingResponseCount=0, eventCount=1
    04-19 10:21:51.586 5601-5618/mapotempo.com.fleet.test I/LiteCore [Sync]: {Repl#6} pushStatus=busy, pullStatus=busy, dbStatus=idle, progress=0/0
    04-19 10:21:51.586 5601-5618/mapotempo.com.fleet.test I/LiteCore [Sync]: {Repl#6} activityLevel=busy: connectionState=2
    04-19 10:21:51.588 5601-5619/mapotempo.com.fleet.test I/LiteCore [Sync]: {Push#8} Found 0 changes up to #33
    04-19 10:21:51.588 5601-5619/mapotempo.com.fleet.test I/LiteCore [Sync]: {Push#8} Caught up, at lastSequence #33
    04-19 10:21:51.589 5601-5619/mapotempo.com.fleet.test I/LiteCore [Sync]: {Push#8} activityLevel=idle: pendingResponseCount=0, caughtUp=1, changeLists=0, revsInFlight=0, blobsInFlight=0, awaitingReply=0, revsToSend=0, pendingSequences=0
    04-19 10:21:51.589 5601-5619/mapotempo.com.fleet.test I/LiteCore [Sync]: {Repl#6} pushStatus=busy, pullStatus=busy, dbStatus=idle, progress=0/0
    04-19 10:21:51.589 5601-5619/mapotempo.com.fleet.test I/LiteCore [Sync]: {Repl#6} activityLevel=busy: connectionState=2
    04-19 10:21:51.589 5601-5619/mapotempo.com.fleet.test I/LiteCore [Sync]: {Pull#9} activityLevel=busy: pendingResponseCount=1, _caughtUp=0, _waitingForChangesCallback=0, _pendingRevMessages=0, _activeIncomingRevs=0
    04-19 10:21:51.589 5601-5619/mapotempo.com.fleet.test I/LiteCore [Sync]: {Repl#6} pushStatus=idle, pullStatus=busy, dbStatus=idle, progress=0/0
    04-19 10:21:51.589 5601-5619/mapotempo.com.fleet.test I/LiteCore [Sync]: {Repl#6} activityLevel=busy: connectionState=2
    04-19 10:21:51.589 5601-5619/mapotempo.com.fleet.test I/LiteCore [Sync]: {Repl#6} activityLevel=busy: connectionState=2
    04-19 10:21:51.592 5601-5622/mapotempo.com.fleet.test I/LiteCore [Sync]: {Repl#6} activityLevel=busy: connectionState=2
    04-19 10:21:51.602 5601-5632/mapotempo.com.fleet.test V/WS: WebSocketListener.onMessage() bytes -> 020100182278e8
    04-19 10:21:51.602 5601-5620/mapotempo.com.fleet.test I/LiteCore [Sync]: {Pull#9} activityLevel=busy: pendingResponseCount=0, _caughtUp=0, _waitingForChangesCallback=0, _pendingRevMessages=0, _activeIncomingRevs=0
    04-19 10:21:51.608 5601-5632/mapotempo.com.fleet.test V/WS: WebSocketListener.onMessage() bytes -> 0128d2c3af36a0283f2d332795213923312f3db59821af34270700ab275962
    04-19 10:21:51.608 5601-5621/mapotempo.com.fleet.test I/LiteCore [Sync]: {Pull#9} Caught up with remote changes
    04-19 10:21:51.608 5601-5621/mapotempo.com.fleet.test I/LiteCore [Sync]: {Pull#9} activityLevel=idle: pendingResponseCount=0, _caughtUp=1, _waitingForChangesCallback=0, _pendingRevMessages=0, _activeIncomingRevs=0
    04-19 10:21:51.608 5601-5621/mapotempo.com.fleet.test I/LiteCore [Sync]: {Repl#6} pushStatus=idle, pullStatus=idle, dbStatus=idle, progress=0/0
    04-19 10:21:51.609 5601-5621/mapotempo.com.fleet.test I/LiteCore [Sync]: {Repl#6} activityLevel=busy: connectionState=2
    04-19 10:21:51.619 5601-5632/mapotempo.com.fleet.test V/WS: WebSocketListener.onMessage() bytes -> 04010872657600302d3200dba27356
    04-19 10:21:51.619 5601-5618/mapotempo.com.fleet.test I/LiteCore [Sync]: {Repl#6} Saved remote checkpoint cp-omc6U6UKXrkCveuXxTfV7Y6xuQ0= as rev='0-2'
    04-19 10:21:51.619 5601-5618/mapotempo.com.fleet.test I/LiteCore [Sync]: {Repl#6} activityLevel=busy: connectionState=2
    04-19 10:21:51.621 5601-5618/mapotempo.com.fleet.test I/LiteCore [Sync]: {DBWorker#7} Saved local checkpoint cp-omc6U6UKXrkCveuXxTfV7Y6xuQ0= to db
    04-19 10:21:51.621 5601-5618/mapotempo.com.fleet.test I/LiteCore [Sync]: {DBWorker#7} activityLevel=idle: pendingResponseCount=0, eventCount=1
    04-19 10:21:51.621 5601-5622/mapotempo.com.fleet.test I/LiteCore [Sync]: {Repl#6} activityLevel=idle: connectionState=2
    04-19 10:21:51.621 5601-5622/mapotempo.com.fleet.test I/LiteCore [Sync]: {Repl#6} now idle
    04-19 10:21:51.621 5601-5622/mapotempo.com.fleet.test I/LiteCoreJNI: [NATIVE] C4Replicator.statusChangedCallback() repl -> 0x0x7ea023fb40 status -> 3
    04-19 10:21:51.623 5601-5622/mapotempo.com.fleet.test I/Sync: C4ReplicatorListener.statusChanged() status -> C4ReplicatorStatus{activityLevel=3, progressUnitsCompleted=0, progressUnitsTotal=0, progressDocumentCount=0, errorDomain=0, errorCode=0, errorInternalInfo=0}
    04-19 10:21:51.625 5601-5625/mapotempo.com.fleet.test I/Sync: statusChanged() c4Status -> C4ReplicatorStatus{activityLevel=3, progressUnitsCompleted=0, progressUnitsTotal=0, progressDocumentCount=0, errorDomain=0, errorCode=0, errorInternalInfo=0}
    04-19 10:21:51.628 5601-5625/mapotempo.com.fleet.test I/Sync: Replicator[<*> Database@52ef085{name='database_c8cc2442d38d969'} URLEndpoint{url=ws://192.168.1.252:4984/db}] is idle, progress 0/0, error: null
    04-19 10:22:01.319 5601-5616/mapotempo.com.fleet.test I/mapotempo.com.fleet.core.DatabaseHandler: >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>> latch one false
9

When I init only one replicator, the probleme doesn’t appear.

10

OK. From statements below, its unclear to me if this is still an issue.

What happens if you remove the timeout. Do all the replicators eventually stop. Because as you observe at some point if it times out, the db will close.

I am not an expert on latches but it would seem that you could initialize the latch to a counter corresponding to number of replicators and then issue the replicator stop request on the various replicators concurrently . When countdown is zero indicating that the replicators were stopped, then you issue a db close.

11

Sorry I am unclear
Yes it is still an issue.

I have two replicators but I am waiting the first was closed to stop the second. I could stoped all replicators at same time and init the CountDowLatch to 2 but I think issue would be same, I will try.
If I remove the timeout mDatabase.close() throw a CouchbaseLiteException.

I inspected ActivityLevel status during the issue and it was in BUSY mode, it look like replicator was blocked.

I will push my test code.

12

@jean-maxime how many replications are running when the logs start in post 8?

I’m not sure if I’m reading it correctly, but it looks like a replication starts in the middle of the logs.

13

There was two replications.

14

Looks like we are tracking this in two places (Github and forum) and duplicating comments and probably worse, missing comments. Can we please track this in one place only .

15

Yes we can continue on forum, sorry for issue duplication, I don’t know where to post my issue.

16

This is looking like a real bug to me. Can we follow up on GitHub instead? This is the link for the issue: https://github.com/couchbase/couchbase-lite-android/issues/1722

17

Ok I switch on github.

18

No worries.

For future reference :

  • Use the forums when you have questions for clarifications , if you are uncertain if something is an issue on your end or Couchbase side. Basically, do not file a ticket on GitHub if you are unsure if and where the issue lies.
  • If through the process of investigation on the Forums, we determine that this very likely is a bug on Couchbase Lite, then , file a ticket on Github .

In this particular case, it looks like an issue on our end, so GitHub is where we track it.

19

Hi, I found the problem but the issue 1722 doesn’t exist. The ‘addChangeListener’ is running by default in main thread. But the ‘CountDownLatch’ blocks the main thread by ‘await’ method. You should set an Executor with single thread.

try {
 // Call this method for each active replicator
   stopContinuousReplicator(myRepl)
}
finally {
   myDB.close();
}


 void stopContinuousReplicator(Replicator repl) throws InterruptedException {
        final CountDownLatch latch = new CountDownLatch(1);
        ListenerToken token = repl.addChangeListener(Executors.newSingleThreadExecutor(), 
         new ReplicatorChangeListener() {
            @Override
            public void changed(ReplicatorChange change) {
                Replicator.Status status = change.getStatus();
                if (status.getActivityLevel() == Replicator.ActivityLevel.STOPPED) {
                    latch.countDown();
                }
            }
        });
        try {
            repl.stop();
            assertTrue(latch.await(timeout, TimeUnit.SECONDS));
        } finally {
            repl.removeChangeListener(token);
        }
    }
2 Likes