Changes feed: error getting revision body

Mobile Sync Gateway
1

Hi,

Using CBL 1.4, SyncGate 2.1.2 and CBS 6.0.0.
Lately I am seeing a lot of warnings like this (where XXXXX is user name):

Changes feed: error getting revision body for “_user/XXXXX” (): 400 Invalid doc ID – db.(*Database).addDocToChangeEntry() at changes.go:124

This warning appears right away after user creation or at first user login.

  1. Should I be worry about?
  2. Sometimes a new user log in and cant get documents from server. But if he closes app and restart it/restart replication everything is ok. Can this strange behaviour be an echo of this warning?

Thanks in advance!

2

Hi Cyb,

This error is unexpected, although harmless. I’ve dug through the code and we shouldn’t ever be getting to this point for _user/ docs - The issue is described in https://github.com/couchbase/sync_gateway/issues/2151 but was fixed in Sync Gateway 1.5.

Are you able to reproduce this issue by issuing a _changes request through the REST API too?

Is it only seen for a newly created user, and only seen once per-user? Also how is the Sync Gateway user being created?

3

Hi, @bbrks!

  1. I create users at backend via admin rest api. This is just from fresh log for a new user:

2019-02-12T15:59:53.311+03:00 [INF] HTTP: #082: POST /db/user/ (as ADMIN)
2019-02-12T15:59:53.322+03:00 [INF] Access: Computed channels for “1o02XP”: !:1
2019-02-12T15:59:53.328+03:00 [INF] Access: Computed roles for “1o02XP”:
2019-02-12T15:59:53.421+03:00 [INF] Cache: Received #14328 ("user/1o02XP")
2019-02-12T15:59:53.421+03:00 [INF] Cache: #14328 ==> channel “"
2019-02-12T15:59:53.421+03:00 [INF] Cache: getCachedChanges(“!”, 14327) → 0 changes valid from #1
2019-02-12T15:59:53.421+03:00 [INF] Cache: getCachedChanges("”, 14327) → 1 changes valid from #14328
2019-02-12T15:59:53.421+03:00 [WRN] Changes feed: error getting revision body for "user/1o02XP" (): 400 Invalid doc ID – db.(*Database).addDocToChangeEntry() at changes.go:124
2019-02-12T15:59:53.422+03:00 [INF] Changes: sending 1 change(s)
2019-02-12T15:59:53.424+03:00 [INF] Auth: Saved sync:user:1o02XP: &{roleImpl:{Name:1o02XP ExplicitChannels:1o02XP:14328 Channels: Sequence:14328 PreviousChannels_: vbNo:} userImplBody:
2019-02-12T15:59:53.424+03:00 [INF] HTTP+: #082: → 201 Created (113.3 ms)

  1. This is later when fresh user logged in (or you talking about some other changes request?)

2019-02-12T15:59:54.850+03:00 [INF] HTTP: #085: POST /db/_changes?feed=normal&heartbeat=30000&style=all_docs (as 1o02XP)
2019-02-12T15:59:54.850+03:00 [INF] Changes: MultiChangesFeed(channels: {*}, options: {Since:0 Limit:0 Conflicts:true IncludeDocs:false Wait:false Continuous:false Terminator:0xc4202ba8a0 HeartbeatMs:30000 TimeoutMs:30000
2019-02-12T15:59:54.851+03:00 [INF] Cache: Initialized cache for channel “1o02XP” with options: &{ChannelCacheMinLength:50 ChannelCacheMaxLength:500 ChannelCacheAge:1m0s}
2019-02-12T15:59:54.851+03:00 [INF] Cache: getCachedChanges(“1o02XP”, 14328:0) → 0 changes valid from #14320
2019-02-12T15:59:54.851+03:00 [INF] Cache: Querying ‘channels’ view for “1o02XP” (start=#1, end=#14320, limit=0)
2019-02-12T15:59:54.854+03:00 [INF] Cache: Got no rows from query for channel:“1o02XP”
2019-02-12T15:59:54.854+03:00 [INF] Cache: GetChangesInChannel(“1o02XP”) → 0 rows
2019-02-12T15:59:54.854+03:00 [INF] Cache: getCachedChanges(“!”, 0) → 0 changes valid from #1
2019-02-12T15:59:54.854+03:00 [INF] Changes: MultiChangesFeed done (to 1o02XP)
2019-02-12T15:59:54.854+03:00 [INF] HTTP+: #085: → 200 OK (5.0 ms)

  1. Yes.
  2. User is being created by Node backend via admin rest api.

Ps. I should mention that sometimes new user already has access to other channels. The logs above taken for new user without any membership in any channels.

4

Thanks for the detailed logs. I was able to reproduce the error by getting _changes with include_docs=true.

To the original questions:

  1. The error is benign, no need to worry about it, although we will look at fixing it in a future release.
  2. That behaviour sounds unrelated to this error, but is something worth investigating more, as it shouldn’t be happening.
5
  1. Also, when changing user account (e.g. password) the same warning appears (maybe it is channels related):

2019-02-12T08:27:24.513+03:00 [INF] HTTP: #92429: GET /db/_user/Z1aruNc (as ADMIN)
2019-02-12T08:27:24.514+03:00 [INF] HTTP+: #92429: → 200 (1.0 ms)
2019-02-12T08:27:24.516+03:00 [INF] HTTP: #92430: PUT /db/user/Z1aruNc (as ADMIN)
2019-02-12T08:27:24.602+03:00 [INF] Cache: Received #14259 ("user/Z1aruNc")
2019-02-12T08:27:24.603+03:00 [INF] Cache: #14259 ==> channel “*”
2019-02-12T08:27:24.603+03:00 [INF] Auth: Saved sync:user:Z1aruNc: &{roleImpl:{Name:Z1aruNc ExplicitChannels:Z1aruNc:14246 Channels:!:1,Z1aruNc:14246,l.015fda23-2501-45da-a3e2-3364aa802133.Z1aruNc:14248,l.0adb39b4-6a73-44cc-b
2019-02-12T08:27:24.604+03:00 [INF] Cache: getCachedChanges(“*”, 14258) → 1 changes valid from #14259
2019-02-12T08:27:24.604+03:00 [INF] Cache: getCachedChanges(“!”, 14258) → 0 changes valid from #1
2019-02-12T08:27:24.604+03:00 [WRN] Changes feed: error getting revision body for “_user/Z1aruNc” (): 400 Invalid doc ID – db.(*Database).addDocToChangeEntry() at changes.go:124

  1. Still trying to figure out from logs what happening but out of luck :slight_smile:

Anyway, thanks @bbrks!