Sync function invalidating access for users

[MobDev]

Why Sync function invalidating access of user?

Sync function
channel(doc.channel);   
var owner = doc.userId.toString();
access(owner,doc.channel);


12:26:04.900317 CRUD: Stored doc "654F58D9-70DF-4AF4-8EA1-392DFA5506F7" / "2-84611a8a1b535733e77716652d7acb4b"
12:26:05.108394 CRUD: Stored doc "B34044FC-F077-4EE3-95BE-47C5966207D8" / "1-3b029b17cd7c7c19b3ec8a4d1ea0b5f4"
12:26:05.108521 Access: Rev "B34044FC-F077-4EE3-95BE-47C5966207D8"/"1-3b029b17cd7c7c19b3ec8a4d1ea0b5f4" invalidates channels of [64280295]
12:26:05.109742 Access: Invalidate access of "64280295"
12:26:05.111019 HTTP+: #202:     --> 201   (577.1 ms)
12:26:05.217853 Cache: Received #144684 after 505ms ("654F58D9-70DF-4AF4-8EA1-392DFA5506F7" / "2-84611a8a1b535733e77716652d7acb4b")
12:26:05.218090 Shadow: Pushing "654F58D9-70DF-4AF4-8EA1-392DFA5506F7", rev "2-84611a8a1b535733e77716652d7acb4b"
12:26:05.367295 Cache: Received #144685 after 650ms ("B34044FC-F077-4EE3-95BE-47C5966207D8" / "1-3b029b17cd7c7c19b3ec8a4d1ea0b5f4")
12:26:05.367391 Cache:     #144685 ==> channel "64280295_ST_14_10"
12:26:05.367417 Cache:     #144685 ==> channel "*"
12:26:05.367460 Changes+: Notifying that "sync_gateway" changed (keys="{*, 64280295_ST_14_10}") count=240
12:26:05.367607 Cache: Received #144684 after 655ms ("654F58D9-70DF-4AF4-8EA1-392DFA5506F7" / "2-84611a8a1b535733e77716652d7acb4b")

[Jens Alfke]

On Oct 29, 2014, at 10:33 AM, MobDev <ehdev...@gmail.com> wrote:

Why Sync function invalidating access of user?

That log message just means it invalidated the cache of that user's channel access, so that it'll be recomputed the next time it's needed. This happens any time a sync function affects the channels a user has access to.

—Jens

[MobDev]

Thank you Jens

We are seeing other thing, Server to App sync is not working

Documents have right  access,channel but when I am trying to access from other device, I don't see any documents.

I am not using any pull channels as well.

Partial Document

    "history": {
      "revs": [
        "1-72196c53bccf985cd461a2cd959552b8",
        "2-aec57c61aae2650e28627fc6e7dd5ab9"
      ],
      "parents": [
        -1,
        0
      ],
      "bodies": [
        "",
        ""
      ],
      "channels": [
        [
          "28889696_ST_14_10"
        ],
        [
          "28889696_ST_14_10"
        ]
      ]
    },
    "channels": {
      "28889696_ST_14_10": null
    },
    "access": {
      "28889696": {
        "28889696_ST_14_10": 1053
      }
    },



Sync Gateway Log

15:08:11.739823 Changes+: Notifying that "mcd_sync_gateway" changed (keys="{_sync:user:64280300}") count=658
15:08:11.701725 Changes+: Notifying that "mcd_sync_gateway" changed (keys="{_sync:user:64280300}") count=657
15:08:11.284005 Changes+: Notifying that "mcd_sync_gateway" changed (keys="{_sync:user:64280300}") count=656
15:08:10.464088 HTTP+: #741:     --> 201   (3742.8 ms)
15:08:10.460330 HTTP:  #741: PUT /mcd_sync_gateway/_local/a37c296e6ef89eed257e496ae6a4392cdcf19c48  (as 64280300)
15:08:10.453908 Access: Computed channels for "64280300": 64280300_ST_14_10:144760
2014/10/29 15:08:10 go-couchbase: call to ViewCustom("sync_gateway", "access") in github.com/couchbaselabs/sync_gateway/base.couchbaseBucket.ViewCustom took 3.729959942s
15:08:09.283454 Cache: Received #144909 after 1371ms ("5C7E4199-70EC-4BDF-9987-33B9C4FB2070" / "1-eaf02431d8d1885009ce02d2adae5571")
15:08:08.738971 Cache: Received #144909 after 827ms ("5C7E4199-70EC-4BDF-9987-33B9C4FB2070" / "1-eaf02431d8d1885009ce02d2adae5571")
15:08:08.191874 Changes+: Notifying that "mcd_sync_gateway" changed (keys="{*, 64280300_ST_14_10}") count=655
15:08:08.191835 Cache:     #144909 ==> channel "*"
15:08:08.191817 Cache:     #144909 ==> channel "64280300_ST_14_10"
15:08:08.191777 Cache: Received #144909 after 279ms ("5C7E4199-70EC-4BDF-9987-33B9C4FB2070" / "1-eaf02431d8d1885009ce02d2adae5571")
15:08:07.913036 CRUD: Stored doc "5C7E4199-70EC-4BDF-9987-33B9C4FB2070" / "1-eaf02431d8d1885009ce02d2adae5571"
15:08:07.911970 Cache: SAVING #144909
15:08:07.911589 CRUD+: updateDoc("5C7E4199-70EC-4BDF-9987-33B9C4FB2070"): Rev "1-eaf02431d8d1885009ce02d2adae5571" leaves "1-eaf02431d8d1885009ce02d2adae5571" still current
15:08:07.910094 CRUD+: Invoking sync on doc "5C7E4199-70EC-4BDF-9987-33B9C4FB2070" rev 1-eaf02431d8d1885009ce02d2adae5571
15:08:07.910056 Shadow+: Not pulling "5C7E4199-70EC-4BDF-9987-33B9C4FB2070", CAS=843d9b6bfc7eb (echo of rev "1-eaf02431d8d1885009ce02d2adae5571")
15:08:07.909898 Shadow+: Pulling "5C7E4199-70EC-4BDF-9987-33B9C4FB2070", CAS=843d9b6bfc7eb ... have UpstreamRev="", UpstreamCAS=0
15:08:07.736393 Shadow: Pushing "5C7E4199-70EC-4BDF-9987-33B9C4FB2070", rev "1-eaf02431d8d1885009ce02d2adae5571"
15:08:07.735740 Cache: Received #144908 after 1262ms ("5C7E4199-70EC-4BDF-9987-33B9C4FB2070" / "1-eaf02431d8d1885009ce02d2adae5571")
15:08:07.735537 Changes+: Notifying that "mcd_sync_gateway" changed (keys="{_sync:user:64280300}") count=654
15:08:07.281521 Shadow: Pushing "5C7E4199-70EC-4BDF-9987-33B9C4FB2070", rev "1-eaf02431d8d1885009ce02d2adae5571"
15:08:07.281332 Changes+: Notifying that "mcd_sync_gateway" changed (keys="{_sync:user:64280300}") count=653
15:08:07.281246 Cache: Received #144908 after 808ms ("5C7E4199-70EC-4BDF-9987-33B9C4FB2070" / "1-eaf02431d8d1885009ce02d2adae5571")
15:08:07.189995 Changes+: Notifying that "mcd_sync_gateway" changed (keys="{*, 64280300_ST_14_10}") count=652
15:08:07.189955 Cache:     #144908 ==> channel "*"
15:08:07.189942 Cache: Pruned 1 old entries from channel "*"
15:08:07.189922 Cache:     #144908 ==> channel "64280300_ST_14_10"
15:08:07.189882 Cache: Received #144908 after 715ms ("5C7E4199-70EC-4BDF-9987-33B9C4FB2070" / "1-eaf02431d8d1885009ce02d2adae5571")
15:08:07.189787 Shadow: Pushing "5C7E4199-70EC-4BDF-9987-33B9C4FB2070", rev "1-eaf02431d8d1885009ce02d2adae5571"
15:08:07.189356 Changes+: Notifying that "mcd_sync_gateway" changed (keys="{_sync:user:64280300}") count=651
15:08:06.523963 HTTP+: #740:     --> 201   (62.9 ms)
15:08:06.522656 Access: Invalidate access of "64280300"
15:08:06.520693 Access: Rev "5C7E4199-70EC-4BDF-9987-33B9C4FB2070"/"1-eaf02431d8d1885009ce02d2adae5571" invalidates channels of [64280300]
15:08:06.520538 CRUD: Stored doc "5C7E4199-70EC-4BDF-9987-33B9C4FB2070" / "1-eaf02431d8d1885009ce02d2adae5571"
15:08:06.472786 Cache: SAVING #144908
15:08:06.472458 Access: Doc "5C7E4199-70EC-4BDF-9987-33B9C4FB2070" grants channel access: map[64280300:64280300_ST_14_10:144908]
15:08:06.472380 CRUD:   Doc "5C7E4199-70EC-4BDF-9987-33B9C4FB2070" in channels "{64280300_ST_14_10}"
15:08:06.470397 CRUD+: Invoking sync on doc "5C7E4199-70EC-4BDF-9987-33B9C4FB2070" rev 1-eaf02431d8d1885009ce02d2adae5571
15:08:06.465719 HTTP:  #740: POST /mcd_sync_gateway/_bulk_docs  (as 64280300)
15:08:04.844490 HTTP+: #739:     --> 200   (23.0 ms)
15:08:04.824054 HTTP:  #739: POST /mcd_sync_gateway/_revs_diff  (as 64280300)
15:08:04.650872 HTTP: #738:     --> 404 missing  (3.0 ms)
15:08:04.649894 HTTP:  #738: GET /mcd_sync_gateway/_local/a37c296e6ef89eed257e496ae6a4392cdcf19c48  (as 64280300)
15:08:03.452151 HTTP+: #737:     --> 200   (2.8 ms)
15:08:03.449368 HTTP:  #737: POST /mcd_sync_gateway/_session  (ADMIN)
15:08:02.213872 HTTP: #736:     --> 404 missing  (3.6 ms)
15:08:02.212836 HTTP:  #736: GET /mcd_sync_gateway/_local/979577281de42842ed6b546408bae43f163e2ebb  (as 64280300)
15:08:01.502390 HTTP: #735:     --> 404 missing  (5.5 ms)
15:08:01.501436 HTTP:  #735: GET /mcd_sync_gateway/_local/a37c296e6ef89eed257e496ae6a4392cdcf19c48  (as 64280300)
15:07:59.690172 HTTP+: #734:     --> 200   (41.4 ms)
15:07:59.648791 HTTP:  #734: POST /mcd_sync_gateway/_session  (ADMIN)
15:07:01.543271 HTTP+: #733:     --> 200   (3.5 ms)
15:07:01.542229 HTTP:  #733: GET /mcd_sync_gateway/_local/1da4a0b2f61894f677e4b7daf8a7c3b1dc8fa5ab  (as 64280300)
15:07:01.112796 HTTP: #732:     --> 404 missing  (5.2 ms)
15:07:01.111308 HTTP:  #732: GET /mcd_sync_gateway/_local/ef61c42e0fa1d0490b8d6b4c60c399e93a775200  (as 64280300)
15:06:58.160265 HTTP+: #731:     --> 200   (3.8 ms)
15:06:58.156552 HTTP:  #731: POST /mcd_sync_gateway/_session  (ADMIN)


Thanks,

[Jens Alfke]

On Oct 29, 2014, at 12:27 PM, MobDev <ehdev...@gmail.com> wrote:

    "channels": {
      "28889696_ST_14_10": null
    },
    "access": {
      "28889696": {
        "28889696_ST_14_10": 1053
      }
    },

OK, that shows that the document is in channel 28889696_ST_14_10, and that it grants user 28889696 access to that channel, which seems reasonable.

The Sync Gateway transcript isn't showing any client pull replication, though, only push. (A pull replication would include requests for _changes and _bulk_get.) The client is also logged in as a different user, 64280300.

Logging on the client is usually better for debugging these sorts of problems.

—Jens

[MobDev]

My Apologies, that sample document was not for the same user, but the issue still exists.

Thank you for tip about _change and _bulk_get,  I am not seeing those calls on sync gateway.

We have two environments
EnvA:  I see logs for _changes and _bulk_get  — App-Server and Server-App sync works fine.
EnvB: I don't see _changes and _bulk_get — only App-Server sync works

EnvA : single Sync Gateway and single Couchbase Server
EnvB: cluster of Sync Gateway and cluster of Couchbase Server with load-balancer on SyncGateways and CB Servers

Are these request getting lost? or not getting recognized/identified correctly?


Thanks a lot for you help.


Cheers

[MobDev]

Following to my previous reply:

Is there a way we can debug/log/see if Pull request is reaching to Sync Gateway or not (if it is reaching what is the reason it is failing)?

Thanks,

[Traun Leyden]

I usually use HTTPScoop for debugging the replication between couchbase lite and sync gateway.  Other tools that will also work:

* Charles Proxy

* Wireshark

If you disable websockets, it makes it easier to debug.  (assuming you are on ios)

Kiran

--
You received this message because you are subscribed to the Google Groups "Couchbase Mobile" group.
To unsubscribe from this group and stop receiving emails from it, send an email to mobile-couchba...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/mobile-couchbase/ad89fd41-760a-496d-b279-40d3512eccba%40googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

[Jens Alfke]

On Oct 29, 2014, at 7:31 PM, MobDev <ehdev...@gmail.com> wrote:

Is there a way we can debug/log/see if Pull request is reaching to Sync Gateway or not (if it is reaching what is the reason it is failing)?

As I said yesterday, use client-side logging. (Here's the info for iOS.)

Traun's advice of using an HTTP-level packet-sniffer is also good, but requires some more knowledge of the replication protocol.

—Jens

[MobDev]

Thank you Traun I am using Charles proxy.

Hi Jens, Yes, I have all the logs on iOS app added.

What I am seeing in the Charles proxy that _local request for pull fails with 404 and never gets created so Server to App sync does not work.

Any idea where/what should we looking for?

Thanks

[Jens Alfke]

On Oct 30, 2014, at 12:24 PM, MobDev <ehdev...@gmail.com> wrote:

What I am seeing in the Charles proxy that _local request for pull fails with 404 and never gets created so Server to App sync does not work.

It's expected to get a 404 on the first sync. That resource stores the 'checkpoint' for this replication, and initially it doesn't exist. The replicator doesn't consider that an error.

—Jens

[MobDev]

Thank you Jens.

Yes, I understand 404 is not an error. 
I am trying to understand after 404 why pull continues on one environment and not on another.
And why would it affect just the pull. push works on both the environments, that makes it more complicated.

EnvA
— CBL_Puller log is (Approx 10 CBL_Puller entries in log)
on iOS log last Entry of CBL_Puller
SyncVerbose: CBL_Puller[http://syncgateway.com:4984/sync_gateway] starting ChangeTracker: mode=0, since=(null)

EnvB:
— There are lot more happening on CBL_puller (Approx 60 CBL_Puller entries in log)
SyncVerbose: CBL_Puller[http://syncgateway.com:4984/sync_gateway] starting ChangeTracker: mode=0, since=(null)
Sync: CBL_Puller[http://syncgateway.com:4984/sync_gateway]: Caught up with changes!
Sync: CBL_Puller[http://syncgateway.com:4984/sync_gateway]: ChangeTracker stopped; error=(null)
Sync: CBL_Puller[http://syncgateway.com:4984/sync_gateway] Progress: set active = 0
*
*
*
Sync: CBL_Puller[http://syncgateway.com:4984/sync_gateway] checkpointing sequence=21


Any thoughts on why there is no "starting ChangeTracker: mode=0, since=(null)" log on EnvA?


Thanks a lot.

[Jens Alfke]

On Oct 30, 2014, at 5:13 PM, MobDev <ehdev...@gmail.com> wrote:

Any thoughts on why there is no "starting ChangeTracker: mode=0, since=(null)" log on EnvA?

But there is one; you listed it in your email. ???

Please add "ChangeTracker" to the logging keywords, so we can see what's going on with it. I'm guessing it's not able to connect for some reason and is waiting to retry. It will take the change tracker several minutes to give up after retrying.

—Jens

[MobDev]

it was a problem on the VPN connection.

it is strange that VPN connection was dropping only for the pull-replication


Thanks a lot guys.