Details
-
Bug
-
Resolution: Fixed
-
Critical
-
Cheshire-Cat
-
Untriaged
-
1
-
Yes
Description
Build : 7.0.0-4291
This issue is seen in multiple tests across various components. Upon adding a new node to the cluster during test setup, or within the test, the rest api returns an error - Unexpected server error, request logged
In this case, the timezone set on 172.23.106.116 was WSDT somehow, hence the difference of time in the test log vs. server log.
[2021-01-26 14:55:32,148] - [rest_client:1174] INFO - settings/indexes params : storageMode=plasma
|
[2021-01-26 14:55:32,171] - [fts_base:2215] INFO - 172.23.100.14 will be configured with services fts
|
[2021-01-26 14:55:33,172] - [task:775] INFO - adding node 172.23.100.14:8091 to cluster
|
[2021-01-26 14:55:33,173] - [rest_client:1485] INFO - adding remote node @172.23.100.14:8091 to this cluster @172.23.106.116:8091
|
[2021-01-26 14:55:48,219] - [rest_client:1016] ERROR - POST http://172.23.106.116:8091/controller/addNode body: hostname=http%3A%2F%2F172.23.100.14%3A8091&user=Administrator&password=password&services=fts headers: {'Content-Type': 'application/x-www-form-urlencoded', 'Authorization': 'Basic QWRtaW5pc3RyYXRvcjpwYXNzd29yZA==', 'Accept': '*/*'} error: 500 reason: unknown b'["Unexpected server error, request logged."]' auth: Administrator:password
|
[2021-01-26 14:55:48,246] - [rest_client:3732] INFO - Latest logs from UI on 172.23.106.116:
|
[2021-01-26 14:55:48,247] - [rest_client:3733] ERROR - {'node': 'ns_1@172.23.106.116', 'type': 'info', 'code': 0, 'module': 'ns_cluster', 'tstamp': 1611701733178, 'shortText': 'message', 'text': 'Change of address to "172.23.106.116" is requested.', 'serverTime': '2021-01-27T12:55:33.178Z'}
|
[2021-01-26 14:55:48,247] - [rest_client:3733] ERROR - {'node': 'ns_1@172.23.106.116', 'type': 'warning', 'code': 5, 'module': 'ns_node_disco', 'tstamp': 1611701689413, 'shortText': 'node down', 'text': "Node 'ns_1@172.23.106.116' saw that node 'ns_1@172.23.100.14' went down. Details: [{nodedown_reason,\n connection_closed}]", 'serverTime': '2021-01-27T12:54:49.413Z'}
|
[2021-01-26 14:55:48,247] - [rest_client:3733] ERROR - {'node': 'ns_1@172.23.106.116', 'type': 'info', 'code': 0, 'module': 'mb_master', 'tstamp': 1611701689283, 'shortText': 'message', 'text': "I'm now the only node, so I'm the master.", 'serverTime': '2021-01-27T12:54:49.283Z'}
|
[2021-01-26 14:55:48,247] - [rest_client:3733] ERROR - {'node': 'ns_1@172.23.100.14', 'type': 'info', 'code': 1, 'module': 'ns_cluster', 'tstamp': 1611701689255, 'shortText': 'message', 'text': "Node 'ns_1@172.23.100.14' is leaving cluster.", 'serverTime': '2021-01-26T14:54:49.255Z'}
|
[2021-01-26 14:55:48,247] - [rest_client:3733] ERROR - {'node': 'ns_1@172.23.100.14', 'type': 'info', 'code': 4, 'module': 'ns_cluster', 'tstamp': 1611701689252, 'shortText': 'message', 'text': 'Node ns_1@172.23.100.14 left cluster', 'serverTime': '2021-01-26T14:54:49.252Z'}
|
[2021-01-26 14:55:48,248] - [rest_client:3733] ERROR - {'node': 'ns_1@172.23.100.14', 'type': 'info', 'code': 0, 'module': 'ns_orchestrator', 'tstamp': 1611701689173, 'shortText': 'message', 'text': 'Rebalance completed successfully.\nRebalance Operation Id = 1229c0041625fdca721630ae8b3887d6', 'serverTime': '2021-01-26T14:54:49.173Z'}
|
[2021-01-26 14:55:48,248] - [rest_client:3733] ERROR - {'node': 'ns_1@172.23.100.14', 'type': 'info', 'code': 0, 'module': 'ns_orchestrator', 'tstamp': 1611701678942, 'shortText': 'message', 'text': "Starting rebalance, KeepNodes = ['ns_1@172.23.106.116'], EjectNodes = ['ns_1@172.23.100.14'], Failed over and being ejected nodes = []; no delta recovery nodes; Operation Id = 1229c0041625fdca721630ae8b3887d6", 'serverTime': '2021-01-26T14:54:38.942Z'}
|
[2021-01-26 14:55:48,248] - [rest_client:3733] ERROR - {'node': 'ns_1@172.23.106.116', 'type': 'warning', 'code': 102, 'module': 'menelaus_web', 'tstamp': 1611701678935, 'shortText': 'client-side error report', 'text': 'Client-side error-report for user "Administrator" on node \'ns_1@172.23.106.116\':\nUser-Agent:Python-httplib2/0.13.1 (gzip)\nStarting rebalance from test, ejected nodes [\'ns_1@172.23.100.14\']', 'serverTime': '2021-01-27T12:54:38.935Z'}
|
[2021-01-26 14:55:48,248] - [rest_client:3733] ERROR - {'node': 'ns_1@172.23.106.116', 'type': 'info', 'code': 11, 'module': 'menelaus_web', 'tstamp': 1611701678893, 'shortText': 'message', 'text': 'Deleted bucket "default"\n', 'serverTime': '2021-01-27T12:54:38.893Z'}
|
[2021-01-26 14:55:48,248] - [rest_client:3733] ERROR - {'node': 'ns_1@172.23.106.116', 'type': 'info', 'code': 0, 'module': 'ns_memcached', 'tstamp': 1611701678248, 'shortText': 'message', 'text': 'Shutting down bucket "default" on \'ns_1@172.23.106.116\' for deletion', 'serverTime': '2021-01-27T12:54:38.248Z'}
|
[2021-01-26 14:55:48,270] - [rest_client:3732] INFO - Latest logs from UI on 172.23.100.14:
|
[2021-01-26 14:55:48,270] - [rest_client:3733] ERROR - {'node': 'ns_1@172.23.106.116', 'type': 'info', 'code': 0, 'module': 'ns_cluster', 'tstamp': 1611701733178, 'shortText': 'message', 'text': 'Change of address to "172.23.106.116" is requested.', 'serverTime': '2021-01-27T12:55:33.178Z'}
|
[2021-01-26 14:55:48,271] - [rest_client:3733] ERROR - {'node': 'ns_1@172.23.106.116', 'type': 'warning', 'code': 5, 'module': 'ns_node_disco', 'tstamp': 1611701689413, 'shortText': 'node down', 'text': "Node 'ns_1@172.23.106.116' saw that node 'ns_1@172.23.100.14' went down. Details: [{nodedown_reason,\n connection_closed}]", 'serverTime': '2021-01-27T12:54:49.413Z'}
|
[2021-01-26 14:55:48,271] - [rest_client:3733] ERROR - {'node': 'ns_1@172.23.106.116', 'type': 'info', 'code': 0, 'module': 'mb_master', 'tstamp': 1611701689283, 'shortText': 'message', 'text': "I'm now the only node, so I'm the master.", 'serverTime': '2021-01-27T12:54:49.283Z'}
|
[2021-01-26 14:55:48,271] - [rest_client:3733] ERROR - {'node': 'ns_1@172.23.100.14', 'type': 'info', 'code': 1, 'module': 'ns_cluster', 'tstamp': 1611701689255, 'shortText': 'message', 'text': "Node 'ns_1@172.23.100.14' is leaving cluster.", 'serverTime': '2021-01-26T14:54:49.255Z'}
|
[2021-01-26 14:55:48,271] - [rest_client:3733] ERROR - {'node': 'ns_1@172.23.100.14', 'type': 'info', 'code': 4, 'module': 'ns_cluster', 'tstamp': 1611701689252, 'shortText': 'message', 'text': 'Node ns_1@172.23.100.14 left cluster', 'serverTime': '2021-01-26T14:54:49.252Z'}
|
[2021-01-26 14:55:48,271] - [rest_client:3733] ERROR - {'node': 'ns_1@172.23.100.14', 'type': 'info', 'code': 0, 'module': 'ns_orchestrator', 'tstamp': 1611701689173, 'shortText': 'message', 'text': 'Rebalance completed successfully.\nRebalance Operation Id = 1229c0041625fdca721630ae8b3887d6', 'serverTime': '2021-01-26T14:54:49.173Z'}
|
[2021-01-26 14:55:48,272] - [rest_client:3733] ERROR - {'node': 'ns_1@172.23.100.14', 'type': 'info', 'code': 0, 'module': 'ns_orchestrator', 'tstamp': 1611701678942, 'shortText': 'message', 'text': "Starting rebalance, KeepNodes = ['ns_1@172.23.106.116'], EjectNodes = ['ns_1@172.23.100.14'], Failed over and being ejected nodes = []; no delta recovery nodes; Operation Id = 1229c0041625fdca721630ae8b3887d6", 'serverTime': '2021-01-26T14:54:38.942Z'}
|
[2021-01-26 14:55:48,272] - [rest_client:3733] ERROR - {'node': 'ns_1@172.23.106.116', 'type': 'warning', 'code': 102, 'module': 'menelaus_web', 'tstamp': 1611701678935, 'shortText': 'client-side error report', 'text': 'Client-side error-report for user "Administrator" on node \'ns_1@172.23.106.116\':\nUser-Agent:Python-httplib2/0.13.1 (gzip)\nStarting rebalance from test, ejected nodes [\'ns_1@172.23.100.14\']', 'serverTime': '2021-01-27T12:54:38.935Z'}
|
[2021-01-26 14:55:48,272] - [rest_client:3733] ERROR - {'node': 'ns_1@172.23.106.116', 'type': 'info', 'code': 11, 'module': 'menelaus_web', 'tstamp': 1611701678893, 'shortText': 'message', 'text': 'Deleted bucket "default"\n', 'serverTime': '2021-01-27T12:54:38.893Z'}
|
[2021-01-26 14:55:48,272] - [rest_client:3733] ERROR - {'node': 'ns_1@172.23.106.116', 'type': 'info', 'code': 0, 'module': 'ns_memcached', 'tstamp': 1611701678248, 'shortText': 'message', 'text': 'Shutting down bucket "default" on \'ns_1@172.23.106.116\' for deletion', 'serverTime': '2021-01-27T12:54:38.248Z'}
|
[2021-01-26 14:55:48,272] - [rest_client:1529] ERROR - add_node error : b'["Unexpected server error, request logged."]'
|
In the http_access.log on 172.23.106.116, I see the following entry :
127.0.0.1 - - [27/Jan/2021:12:24:11 +1400] "GET /pools/default/buckets?v=54714639&uuid=a1517b4b7398afedb21f52f4aa4bcbef HTTP/1.1" 500 44 - "Go-http-client/1.1-indexer-projector" 8
|
and then in the projector log on 172.23.106.116, the following is seen -
2021-01-27T12:24:11.556+14:00 [Info] serviceChangeNotifier: Removing the bucket: standard_bucket_2 from book-keeping
|
2021-01-27T12:24:11.556+14:00 [Warn] servicesChangeNotifier: Connection terminated for collection manifest notifier instance of http://%40projector-cbauth@127.0.0.1:8091, default, bucket: standard_bucket_2, (invalid byte in chunk length)
|
2021-01-27T12:24:11.564+14:00 [Warn] servicesChangeNotifier: Connection terminated for collection manifest notifier instance of http://%40projector-cbauth@127.0.0.1:8091, default, bucket: standard_bucket_2, (invalid byte in chunk length)
|
2021-01-27T12:24:11.580+14:00 [Warn] servicesChangeNotifier: Connection terminated for pool notifier instance of http://%40projector-cbauth@127.0.0.1:8091, default (Notifier invalidated due to internal error)
|
2021-01-27T12:24:12.129+14:00 [Warn] servicesChangeNotifier: Connection terminated for buckets notifier instance of http://%40projector-cbauth@127.0.0.1:8091, default (Notifier invalidated due to internal error)
|
2021-01-27T12:24:12.133+14:00 [Warn] servicesChangeNotifier: Connection terminated for collection manifest notifier instance of http://%40projector-cbauth@127.0.0.1:8091, default, bucket: standard_bucket_3, (invalid byte in chunk length)
|
2021-01-27T12:24:12.135+14:00 [Warn] servicesChangeNotifier: Connection terminated for collection manifest notifier instance of http://%40projector-cbauth@127.0.0.1:8091, default, bucket: standard_bucket_3, (invalid byte in chunk length)
|
2021-01-27T12:24:12.404+14:00 [Info] memstats {"Alloc":3408200, "TotalAlloc":557821224, "Sys":72286456, "Lookups":0, "Mallocs":7043015,"Frees":7021561, "HeapAlloc":3408200, "HeapSys":65994752, "HeapIdle":60997632, "HeapInuse":4997120,"HeapReleased":60080128, "HeapObjects":21454,"GCSys":2381824, "LastGC":1611699850739680355,"PauseTotalNs":141783487, "PauseNs":[101652, 36073, 7019367, 22701, 50865, 31555, 32278], "NumGC":320}
|
2021-01-27T12:24:13.117+14:00 [Warn] servicesChangeNotifier: Connection terminated for services notifier instance of http://%40projector-cbauth@127.0.0.1:8091, default (Notifier invalidated due to internal error)
|
2021-01-27T12:24:13.118+14:00 [Warn] servicesChangeNotifier: Connection terminated for services notifier instance of http://%40projector-cbauth@127.0.0.1:8091, default (Notifier invalidated due to internal error)
|
2021-01-27T12:24:13.499+14:00 [Info] Error occured during cluster info update (HTTP error 500 Internal Server Error getting "http://127.0.0.1:8091/pools/default/buckets?v=54714639&uuid=a1517b4b7398afedb21f52f4aa4bcbef": ["Unexpected server error, request logged."]) .. Retrying(1)
|
2021-01-27T12:24:14.535+14:00 [Info] servicesChangeNotifier: Creating new notifier instance for http://%40projector-cbauth@127.0.0.1:8091, default
|
Logs attached.
Attachments
Issue Links
- is duplicated by
-
MB-43837 [Chronicle] Node doesn't get cleaned up after rebalance-out
- Closed
-
MB-43905 After kill memcached, erlang and restart couchbase server, bucket failed to drop after created
- Closed
-
MB-43814 [Chronicle] Add node failed due to "badmatch_already_member"
- Closed
-
MB-43926 "Unexpected server error, request logged" returned on hard failover and ejecting master node
- Closed
For Gerrit Dashboard: MB-43899 | ||||||
---|---|---|---|---|---|---|
# | Subject | Branch | Project | Status | CR | V |
144676,2 | MB-43899 wait for global name before making calls to chronicle_master | master | ns_server | Status: MERGED | +2 | +1 |
144677,2 | MB-43899 wait for master sup to shutdown on ejected leader before | master | ns_server | Status: MERGED | +2 | +1 |