Xamarin.Forms - Last documents replication gets stuck

Mobile
1

Hello,

We are developing a Xamarin.Forms cross-platform application which makes one-way replication from a CouchDB server. The CouchDB is quite big and it takes around 2-3 minutes to complete the replication. However, from time to time, the replication gets stuck when only a few documents (<100) are remaining.

This problem is solved stopping and starting again the replication but we’d like to know the reason why it happens and if there’s any way to do it without requesting it to the user.

Currently, we are using Couchbase.Lite v1.4.0b0048.

2

Is that 1.4-b0048 or 1.4.0-b0048 (note the extra 0)? 1.4.0-b0048 is pretty old (it came before we solidified the 1.x numbering scheme) Unfortunately, there is no single answer to that question. The only clues will be in the logs.

1.4 is going to be released any day now (.NET will be releasing 1.4-b0054) and after that most of the effort will be towards the development of 2.0, but if you can show a way to reproduce this with 1.4 after it is released (or 1.4-b0054 now) then I will see if I can find time to take a look.

3

Hi borrrden,

it’s 1.4-b0048 (without extra 0). I’ll put the logs as verbose to see if I can see something…I’ll let you know.

4

Hi!

I’ve just reproduced again the issue with the logs on Verbose level. As you can see below, when it remains only one document the replication hasn’t stopped (no trace about STOPPED status) but it hasn’t done anything else.

I’ve waited several minutes but nothing has happened. Therefore, I’ve decided to stop it and start it again. After that, the replication has been resumed and it has finished in a few seconds.

    [0:] VERBOSE) SYNC (Replication): [36] 2017-3-2 09:53:36.795+01:00 NotifyChangeListeners (2552/2555, state=Running (batch=0, net=3))
    [0:] 09:53:36.809 replicator_ReplicationProgress() - Replication status is Active.
    [0:] 09:53:36.818 Sync: Progress: 2552/2555 (99.88258%)
    [0:] VERBOSE) SYNC (MultipartDocumentReader): [26] 2017-3-2 09:53:36.835+01:00 Couchbase.Lite.Support.MultipartDocumentReader starting attachment #1...
    [0:] INFO) DATABASE (BlobStore): [53] 2017-3-2 09:53:36.844+01:00 [BlobStore: /data/data/myapp/files/.local/share/catalog.cblite2/attachments] created temporary directory /data/data/myapp/files/.local/share/catalog.cblite2/attachments/temp_attachments
    03-02 09:53:36.908 I/art     (25080): Explicit concurrent mark sweep GC freed 99(3KB) AllocSpace objects, 0(0B) LOS objects, 39% free, 8MB/13MB, paused 810us total 27.083ms
    03-02 09:53:36.908 D/Mono    (25080): GC_TAR_BRIDGE bridges 2 objects 2 colors 2 ignored 0 sccs 2 xref 0 cache 0/0 setup 0.13ms tarjan 0.01ms scc-setup 0.04ms gather-xref 0.00ms xref-setup 0.00ms cleanup 0.03ms
    03-02 09:53:36.908 D/Mono    (25080): GC_BRIDGE: Complete, was running for 28.48ms
    03-02 09:53:36.908 D/Mono    (25080): GC_MINOR: (Nursery full) time 5.76ms, stw 6.47ms promoted 48K major size: 5312K in use: 3742K los size: 22076K in use: 16766K
    03-02 09:53:37.028 D/Mono    (25080): GC_TAR_BRIDGE bridges 0 objects 0 colors 0 ignored 0 sccs 0 xref 0 cache 0/0 setup 0.13ms tarjan 0.01ms scc-setup 0.04ms gather-xref 0.00ms xref-setup 0.00ms cleanup 0.01ms
    03-02 09:53:37.028 D/Mono    (25080): GC_BRIDGE: Complete, was running for 0.12ms
    03-02 09:53:37.028 D/Mono    (25080): GC_MINOR: (Nursery full) time 4.69ms, stw 5.23ms promoted 0K major size: 5312K in use: 3742K los size: 22076K in use: 16766K
    03-02 09:53:37.147 D/Mono    (25080): GC_TAR_BRIDGE bridges 0 objects 0 colors 0 ignored 0 sccs 0 xref 0 cache 0/0 setup 0.13ms tarjan 0.01ms scc-setup 0.04ms gather-xref 0.00ms xref-setup 0.00ms cleanup 0.01ms
    03-02 09:53:37.148 D/Mono    (25080): GC_BRIDGE: Complete, was running for 0.12ms
    03-02 09:53:37.148 D/Mono    (25080): GC_MINOR: (Nursery full) time 4.68ms, stw 5.19ms promoted 0K major size: 5312K in use: 3742K los size: 22076K in use: 16766K
    03-02 09:53:37.267 D/Mono    (25080): GC_TAR_BRIDGE bridges 0 objects 0 colors 0 ignored 0 sccs 0 xref 0 cache 0/0 setup 0.13ms tarjan 0.01ms scc-setup 0.04ms gather-xref 0.00ms xref-setup 0.00ms cleanup 0.01ms
    03-02 09:53:37.267 D/Mono    (25080): GC_BRIDGE: Complete, was running for 0.13ms
    03-02 09:53:37.267 D/Mono    (25080): GC_MINOR: (Nursery full) time 4.66ms, stw 5.15ms promoted 0K major size: 5312K in use: 3742K los size: 22076K in use: 16766K
    03-02 09:53:37.387 D/Mono    (25080): GC_TAR_BRIDGE bridges 0 objects 0 colors 0 ignored 0 sccs 0 xref 0 cache 0/0 setup 0.13ms tarjan 0.01ms scc-setup 0.04ms gather-xref 0.00ms xref-setup 0.00ms cleanup 0.00ms
    03-02 09:53:37.387 D/Mono    (25080): GC_BRIDGE: Complete, was running for 0.13ms
    03-02 09:53:37.387 D/Mono    (25080): GC_MINOR: (Nursery full) time 4.67ms, stw 5.17ms promoted 0K major size: 5312K in use: 3742K los size: 22076K in use: 16766K
    03-02 09:53:37.506 D/Mono    (25080): GC_TAR_BRIDGE bridges 0 objects 0 colors 0 ignored 0 sccs 0 xref 0 cache 0/0 setup 0.13ms tarjan 0.01ms scc-setup 0.04ms gather-xref 0.00ms xref-setup 0.00ms cleanup 0.01ms
    03-02 09:53:37.506 D/Mono    (25080): GC_BRIDGE: Complete, was running for 0.12ms
    03-02 09:53:37.506 D/Mono    (25080): GC_MINOR: (Nursery full) time 4.73ms, stw 5.25ms promoted 0K major size: 5312K in use: 3742K los size: 22076K in use: 16766K
    03-02 09:53:37.627 D/Mono    (25080): GC_TAR_BRIDGE bridges 0 objects 0 colors 0 ignored 0 sccs 0 xref 0 cache 0/0 setup 0.13ms tarjan 0.01ms scc-setup 0.04ms gather-xref 0.00ms xref-setup 0.00ms cleanup 0.00ms
    03-02 09:53:37.627 D/Mono    (25080): GC_BRIDGE: Complete, was running for 0.12ms
    03-02 09:53:37.627 D/Mono    (25080): GC_MINOR: (Nursery full) time 4.71ms, stw 5.25ms promoted 0K major size: 5312K in use: 3742K los size: 22076K in use: 16766K
    03-02 09:53:37.746 D/Mono    (25080): GC_TAR_BRIDGE bridges 0 objects 0 colors 0 ignored 0 sccs 0 xref 0 cache 0/0 setup 0.13ms tarjan 0.01ms scc-setup 0.04ms gather-xref 0.00ms xref-setup 0.00ms cleanup 0.00ms
    03-02 09:53:37.746 D/Mono    (25080): GC_BRIDGE: Complete, was running for 0.12ms
    03-02 09:53:37.746 D/Mono    (25080): GC_MINOR: (Nursery full) time 4.72ms, stw 5.24ms promoted 0K major size: 5312K in use: 3742K los size: 22076K in use: 16766K
    03-02 09:53:37.865 D/Mono    (25080): GC_TAR_BRIDGE bridges 0 objects 0 colors 0 ignored 0 sccs 0 xref 0 cache 0/0 setup 0.13ms tarjan 0.01ms scc-setup 0.04ms gather-xref 0.00ms xref-setup 0.00ms cleanup 0.01ms
    03-02 09:53:37.865 D/Mono    (25080): GC_BRIDGE: Complete, was running for 0.13ms
    03-02 09:53:37.865 D/Mono    (25080): GC_MINOR: (Nursery full) time 4.71ms, stw 5.22ms promoted 0K major size: 5312K in use: 3742K los size: 22076K in use: 16766K
    03-02 09:53:37.997 D/Mono    (25080): GC_TAR_BRIDGE bridges 0 objects 0 colors 0 ignored 0 sccs 0 xref 0 cache 0/0 setup 0.13ms tarjan 0.01ms scc-setup 0.04ms gather-xref 0.00ms xref-setup 0.00ms cleanup 0.01ms
    03-02 09:53:37.997 D/Mono    (25080): GC_BRIDGE: Complete, was running for 0.14ms
    03-02 09:53:37.997 D/Mono    (25080): GC_MINOR: (Nursery full) time 4.67ms, stw 5.18ms promoted 0K major size: 5312K in use: 3742K los size: 22076K in use: 16766K
    03-02 09:53:38.134 D/Mono    (25080): GC_TAR_BRIDGE bridges 0 objects 0 colors 0 ignored 0 sccs 0 xref 0 cache 0/0 setup 0.13ms tarjan 0.01ms scc-setup 0.04ms gather-xref 0.00ms xref-setup 0.00ms cleanup 0.01ms
    03-02 09:53:38.134 D/Mono    (25080): GC_BRIDGE: Complete, was running for 0.14ms
    03-02 09:53:38.134 D/Mono    (25080): GC_MINOR: (Nursery full) time 4.75ms, stw 5.25ms promoted 0K major size: 5312K in use: 3742K los size: 22076K in use: 16766K
    [0:] VERBOSE) SYNC (MultipartDocumentReader): [26] 2017-3-2 09:53:38.154+01:00 Couchbase.Lite.Support.MultipartDocumentReader finished attachment #1: BlobStoreWriter len=3880.4912109375kb, digest=md5-7KbpGTXwau5wEI5cnaVi9w==, SHA1=sha1-I46UiODKIgvdjGQ4aBkpxoc9s2I=
    [0:] VERBOSE) SYNC (MultipartDocumentReader): [53] 2017-3-2 09:53:38.163+01:00 Couchbase.Lite.Support.MultipartDocumentReader starting attachment #2...
    [0:] INFO) DATABASE (BlobStore): [26] 2017-3-2 09:53:38.173+01:00 [BlobStore: /data/data/myapp/files/.local/share/catalog.cblite2/attachments] created temporary directory /data/data/myapp/files/.local/share/catalog.cblite2/attachments/temp_attachments
    [0:] VERBOSE) SYNC (MultipartDocumentReader): [53] 2017-3-2 09:53:38.186+01:00 Couchbase.Lite.Support.MultipartDocumentReader finished attachment #2: BlobStoreWriter len=5.2529296875kb, digest=md5-8KMDZ2BXnj2zSVdZyMoeSQ==, SHA1=sha1-Hz/CcjJzGnXCMav4kERoo4DGIOU=
    [0:] VERBOSE) SYNC (MultipartDocumentReader): [47] 2017-3-2 09:53:38.197+01:00 Couchbase.Lite.Support.MultipartDocumentReader finished loading (2 attachments)
    [0:] VERBOSE) SYNC (Puller): [27] 2017-3-2 09:53:38.215+01:00 Puller 2e29edeb-3a5b-4726-bd87-0f400afccd3b inserting 2 revisions...
    [0:] VERBOSE) SYNC (Puller): [26] 2017-3-2 09:53:38.249+01:00 Inserting <redacted> ["5-0bec6d8f7807dc06052a93db10e544ee","4-b2aad2f08d4cb3a4e43a0975e2fd6043","3-13c16236ef6e4b1b538808253ba5c8a2","2-ecce7d1c58be632ccc2d4684197af68b","1-36613249389c20e1dc0aa75bacdb2c42"]
    [0:] VERBOSE) SYNC (Puller): [36] 2017-3-2 09:53:38.267+01:00 Inserting <redacted> ["2-2a9e47e560ec74fbd86e1535032900bb","1-22c90607ee5c518b04d5bcbe399533fd"]
    [0:] VERBOSE) SYNC (Puller): [53] 2017-3-2 09:53:38.279+01:00 Puller 2e29edeb-3a5b-4726-bd87-0f400afccd3b finished inserting 2 revisions
    [0:] INFO) DATABASE (Database): [26] 2017-3-2 09:53:38.294+01:00 Database[/data/data/myapp/files/.local/share/catalog.cblite2] posting change notifications: seq [5544,5546]
    [0:] VERBOSE) SYNC (Puller): [53] 2017-3-2 09:53:38.303+01:00 Finished inserting 2 revisions. Success == True
    [0:] INFO) SYNC (Puller): [53] 2017-3-2 09:53:38.312+01:00 Inserted 2 revs in 59.128 milliseconds
    [0:] VERBOSE) SYNC (Replication): [53] 2017-3-2 09:53:38.320+01:00 NotifyChangeListeners (2554/2555, state=Running (batch=0, net=1))
    [0:] 09:53:38.334 replicator_ReplicationProgress() - Replication status is Active.
    [0:] 09:53:38.343 Sync: Progress: 2554/2555 (99.96086%)
    [0:] INFO) SYNC (RemoteSession): [26] 2017-3-2 09:53:38.352+01:00 [CouchDB: Version=1.6.1]: Server Version: [CouchDB: Version=1.6.1]
    [0:] INFO) SYNC (Replication): [53] 2017-3-2 09:53:38.365+01:00 Puller 2e29edeb-3a5b-4726-bd87-0f400afccd3b saved remote checkpoint '2452' (_rev=0-16)
    03-02 09:53:43.386 D/Mono    (25080): [0x6db728a8] worker finishing
    Thread finished: <Thread Pool> #40
    The thread 'Unknown' (0x28) has exited with code 0 (0x0).
    03-02 09:53:51.804 D/Mono    (25080): [0x6f133a50] worker finishing
    Thread finished: <Thread Pool> #35
    The thread 'Unknown' (0x23) has exited with code 0 (0x0).
    Thread finished: <Thread Pool> #36
    03-02 09:53:58.407 D/Mono    (25080): [0x6fa08cf8] worker finishing
    The thread 'Unknown' (0x24) has exited with code 0 (0x0).
    03-02 09:54:05.505 D/Mono    (25080): [0x6e49a7c0] worker finishing
    Thread finished: <Thread Pool> #28
    The thread 'Unknown' (0x1c) has exited with code 0 (0x0).
    Thread finished: <Thread Pool> #50
    03-02 09:54:10.586 D/Mono    (25080): [0x6f892068] worker finishing
    The thread 'Unknown' (0x32) has exited with code 0 (0x0).
    03-02 09:54:15.678 D/Mono    (25080): [0x6f230008] worker finishing
    Thread finished: <Thread Pool> #26
    The thread 'Unknown' (0x1a) has exited with code 0 (0x0).
    Thread finished: <Thread Pool> #56
    03-02 09:54:25.552 D/Mono    (25080): [0x80e8fd78] worker finishing
    The thread 'Unknown' (0x38) has exited with code 0 (0x0).
    Thread finished: <Thread Pool> #39
    03-02 09:54:32.243 D/Mono    (25080): [0x6f62b2e8] worker finishing
    The thread 'Unknown' (0x27) has exited with code 0 (0x0).
    Thread finished: <Thread Pool> #47
    03-02 09:54:37.383 D/Mono    (25080): [0x6f278648] worker finishing
    The thread 'Unknown' (0x2f) has exited with code 0 (0x0).
    Thread finished: <Thread Pool> #62
    The thread 'Unknown' (0x3e) has exited with code 0 (0x0).
    Thread finished: <Thread Pool> #32
    03-02 09:54:44.135 D/Mono    (25080): [0x6fb094d8] worker finishing
    The thread 'Unknown' (0x20) has exited with code 0 (0x0).
    Thread finished: <Thread Pool> #38
    03-02 09:54:50.275 D/Mono    (25080): [0x6f0ddad8] worker finishing
    The thread 'Unknown' (0x26) has exited with code 0 (0x0).

Is there anything we can do on code for avoiding this actions? It’s weird because I haven’t received any timeout exception and I’ve been waiting for more than a minute. For your information, hereunder the initalization of the one-shot one-way replication:

Replication pull = Manager.SharedInstance.GetDatabase(databaseName).CreatePullReplication(remoteSyncUrl);
pull.Continuous = false;
pull.Changed += replicator_ReplicationProgress;
5

I can’t tell from those logs what the problem might be. If you can make a repro case for it or find any errors in the logs I’d recommend filing a ticket on the .net repo.