Logs in sg_error.log after upgrading SG 2.1 to 2.5

Mobile Sync Gateway
1

After upgrading I see many logs in sg_error.log. Here are some logs:


2019-08-25T23:11:59.352+02:00 [ERR] 409 Document update conflict -- rest.(*handler).writeError() at handler.go:691
2019-08-25T23:11:59.496+02:00 [ERR] 401 Login required -- rest.(*handler).writeError() at handler.go:691
2019-08-25T23:11:59.534+02:00 [ERR] 409 Document update conflict -- rest.(*handler).writeError() at handler.go:691

The only logs I saw before upgrading were when the SG service was started:

2019-04-09T16:02:54.949+02:00 ==== Couchbase Sync Gateway/2.1.3(4;7143b13) ====

The logs in sg_info.log after starting the SG look fine to me:

2019-08-25T23:01:03.070+02:00 ==== Couchbase Sync Gateway/2.5.1(12;3f5ce5d) CE ====
2019-08-25T23:01:03.070+02:00 [INF] Logging: Console to stderr
2019-08-25T23:01:03.070+02:00 [INF] Logging: Files to /home/sync_gateway/logs
2019-08-25T23:01:03.070+02:00 [INF] Logging: Console level: info
2019-08-25T23:01:03.070+02:00 [INF] Logging: Console keys: [HTTP]
2019-08-25T23:01:03.070+02:00 [INF] Logging: Redaction level: none
2019-08-25T23:01:03.070+02:00 [INF] requestedSoftFDLimit >= currentHardFdLimit (250000 >= 65535) capping at 65535
2019-08-25T23:01:03.071+02:00 [INF] Configured process to allow 65535 open file descriptors
2019-08-25T23:01:03.071+02:00 [INF] Logging stats with frequency: 1m0s
2019-08-25T23:01:03.071+02:00 [INF] Opening db /my_database as bucket "my_bucket", pool "default", server <http://10.0.0.100>
2019-08-25T23:01:03.071+02:00 [INF] GoCBCustomSGTranscoder Opening Couchbase database my_bucket on <http://10.0.0.100> as user "sync_gateway"
2019-08-25T23:01:03.071+02:00 [INF] Auth: Attempting credential authentication http://10.0.0.100?http_idle_conn_timeout=90000&http_max_idle_conns=64000&http_max_idle_conns_per_host=256&n1ql_timeout=75000
2019-08-25T23:01:03.081+02:00 [INF] Successfully opened bucket my_bucket
2019-08-25T23:01:03.081+02:00 [INF] Set query timeouts for bucket my_bucket to cluster:1m15s, bucket:1m15s
2019-08-25T23:01:03.091+02:00 [INF] Initializing indexes with numReplicas: 0...
2019-08-25T23:01:03.427+02:00 [INF] Query: Index sg_syncDocs_x1 doesn't exist, creating...
2019-08-25T23:01:04.590+02:00 [INF] Query: Index sg_syncDocs_x1 created successfully
2019-08-25T23:01:04.752+02:00 [INF] Query: Building deferred indexes: [sg_syncDocs_x1]
2019-08-25T23:03:16.213+02:00 [INF] Verifying index availability for bucket my_bucket...
2019-08-25T23:03:16.236+02:00 [INF] Indexes ready for bucket my_bucket.
2019-08-25T23:03:16.236+02:00 [INF] delta_sync enabled=false with rev_max_age_seconds=86400 for database my_database
2019-08-25T23:03:16.238+02:00 [INF] Cache: Initializing changes cache with options {ChannelCacheOptions:{ChannelCacheMinLength:50 ChannelCacheMaxLength:1000 ChannelCacheAge:1m0s} CachePendingSeqMaxWait:5s CachePendingSeqMaxNum:10000 CacheSkippedSeqMaxWait:1h0m0s}
2019-08-25T23:03:16.238+02:00 [INF] Initializing changes cache for database my_database
2019-08-25T23:03:16.239+02:00 [INF] DCP: Starting mutation feed on bucket my_bucket due to either channel cache mode or doc tracking (auto-import/bucketshadow)
2019-08-25T23:03:16.239+02:00 [INF] DCP: Using DCP feed for bucket: "my_bucket" (based on feed_type specified in config file)
2019-08-25T23:03:16.891+02:00 [INF] Using metadata purge interval of 30.00 days for tombstone compaction.
2019-08-25T23:03:16.914+02:00 [INF] CBGoUtilsLogger: Using plain authentication for user <ud>sync_gateway</ud>
2019-08-25T23:03:16.914+02:00 [INF] CBGoUtilsLogger: Using plain authentication for user <ud>sync_gateway</ud>
2019-08-25T23:03:16.914+02:00 [INF] CBGoUtilsLogger: Using plain authentication for user <ud>sync_gateway</ud>
2019-08-25T23:03:16.914+02:00 [INF] CBGoUtilsLogger: Using plain authentication for user <ud>sync_gateway</ud>
2019-08-25T23:03:16.914+02:00 [INF] CBGoUtilsLogger: Using plain authentication for user <ud>sync_gateway</ud>
2019-08-25T23:03:16.921+02:00 [INF] Reset guest user to config
2019-08-25T23:03:16.921+02:00 [INF] Starting admin server on :4985
2019-08-25T23:03:16.926+02:00 [INF] Starting server on :4984 ...
2019-08-25T23:03:16.926+02:00 [INF] DCP: Backfill in progress: 0% (8 / 8753)
2019-08-25T23:03:16.926+02:00 [INF] Cache: Received #132537979 (unused sequence)

There are additional logs in sg_info.log to pinpoint the cause:

Login required issue

2019-08-25T23:03:50.547+02:00 [INF] HTTP:  #589: GET /my_database/_local/2e6f170363d7d359478abc5e933d9237a3149738 (as GUEST)
2019-08-25T23:03:50.547+02:00 [ERR] 401 Login required -- rest.(*handler).writeError() at handler.go:691
2019-08-25T23:03:50.547+02:00 [INF] HTTP: #589:     --> 401 Login required  (2.1 ms)


and [ERR] 409 Document update conflict

2019-08-25T23:04:06.440+02:00 [INF] HTTP:  #835: PUT /my_database/_local/bb85fcc91a4a561d01a79ab2cedec57a4b8e07d7 (as 0lwu8GhnU6YCy5Le4c2xCP7sRWi1)
2019-08-25T23:04:06.440+02:00 [INF] Cache: getCachedChanges("!", 132416966) --> 0 changes valid from #1
2019-08-25T23:04:06.440+02:00 [INF] Cache: getCachedChanges("XqBnYrjYgRajHJ5i6veOB5jOaIR2", 132416966) --> 0 changes valid from #132416967
2019-08-25T23:04:06.440+02:00 [INF] Cache: getCachedChanges("XqBnYrjYgRajHJ5i6veOB5jOaIR2::oet9emidfyb5", 132416966) --> 0 changes valid from #132416967
2019-08-25T23:04:06.440+02:00 [INF] Changes: c:#834 MultiChangesFeed done   (to XqBnYrjYgRajHJ5i6veOB5jOaIR2)
2019-08-25T23:04:06.440+02:00 [INF] HTTP+: #834:     --> 200 OK  (2.0 ms)
2019-08-25T23:04:06.440+02:00 [ERR] 409 Document update conflict -- rest.(*handler).writeError() at handler.go:691
2019-08-25T23:04:06.440+02:00 [INF] HTTP: #835:     --> 409 Document update conflict  (2.3 ms)
2019-08-25T23:04:06.445+02:00 [INF] HTTP:  #836: PUT /my_database/_local/bb85fcc91a4a561d01a79ab2cedec57a4b8e07d7 (as 0lwu8GhnU6YCy5Le4c2xCP7sRWi1)
2019-08-25T23:04:06.446+02:00 [ERR] 409 Document update conflict -- rest.(*handler).writeError() at handler.go:691
2019-08-25T23:04:06.446+02:00 [INF] HTTP: #836:     --> 409 Document update conflict  (2.2 ms)

There are also username and password fields in the SG config. They had been there before. Only 1 SG config has "import_docs": true

Is there anything I can do about these two issues?

Thanks!

Additional less important info

CPU system time is about 4 times as high as before. Iā€™m guessing there is some kind of upgrade code running. Still the CPU is rather idleing as before. Syncing between two Android clients (CBL 1.4) is about 5-10 seconds slower as before. After updating the sessions on the clients it syncs faster than before.

2

I plan to update to SG 2.6 on Sunday night and report back if the logs disappear.

3

All logs disappeared after upgrading to SG 2.6.

1 Like