Changes feed: error getting revision body


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!

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 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?

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.

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.
  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
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!