Couchbase Server

moxi returning 132 and 133 error when loading data during rebalance

Details

Description

we have some tests which
1- start the load on x node
2- add a new node
3- start rebalance operation
4- wait until rebalance is completed and the data loader process is also completed.


this is probably a minor bug because as you can see from the log after few seconds moxi is accepting commands.


sword&ejectedNodes=&user=Administrator&knownNodes=ns_1%40172.16.75.128%2Cns_1%40172.16.75.129
[2011-05-23 09:19:05,023] - [rest_client] [140735087852704] - INFO - rebalance: {'date': 'Mon, 23 May 2011 16:19:05 GMT', 'status': '200', 'content-length': '0', 'server': 'MochiWeb/1.0 (Any of you quaids got a smint?)'}
[2011-05-23 09:19:05,023] - [rest_client] [140735087852704] - INFO - rebalance operation started
[2011-05-23 09:19:05,618] - [rest_client] [140735087852704] - INFO - rebalance percentage : 0.0 %
[2011-05-23 09:19:07,626] - [rest_client] [140735087852704] - INFO - rebalance percentage : 0.0 %
[2011-05-23 09:19:09,637] - [rest_client] [140735087852704] - INFO - rebalance percentage : 0.0 %
[2011-05-23 09:19:11,642] - [rest_client] [140735087852704] - INFO - rebalance percentage : 0.390625 %
[2011-05-23 09:19:12,504] - [data_helper] [4357435392] - INFO - 132
[2011-05-23 09:19:12,506] - [data_helper] [4325953536] - INFO - 132
[2011-05-23 09:19:12,767] - [data_helper] [4326490112] - INFO - 132
[2011-05-23 09:19:12,821] - [data_helper] [4327563264] - INFO - 132
[2011-05-23 09:19:12,903] - [data_helper] [4317777920] - INFO - 132
[2011-05-23 09:19:12,911] - [data_helper] [4321710080] - INFO - 132
[2011-05-23 09:19:12,974] - [data_helper] [4354215936] - INFO - 132
[2011-05-23 09:19:13,124] - [data_helper] [4356362240] - INFO - 132
[2011-05-23 09:19:13,251] - [data_helper] [4325953536] - INFO - 132
[2011-05-23 09:19:13,318] - [data_helper] [4323807232] - INFO - 132
[2011-05-23 09:19:13,453] - [data_helper] [4354752512] - INFO - 132
[2011-05-23 09:19:13,542] - [data_helper] [4357971968] - INFO - 132
[2011-05-23 09:19:13,648] - [rest_client] [140735087852704] - INFO - rebalance percentage : 2.9296875 %
[2011-05-23 09:19:13,699] - [data_helper] [4358508544] - INFO - 132
[2011-05-23 09:19:14,012] - [data_helper] [4317777920] - INFO - 132
[2011-05-23 09:19:14,036] - [data_helper] [4356898816] - INFO - 132
[2011-05-23 09:19:15,665] - [rest_client] [140735087852704] - INFO - rebalance percentage : 4.4921875 %
[2011-05-23 09:19:17,682] - [rest_client] [140735087852704] - INFO - rebalance percentage : 5.2734375 %
[2011-05-23 09:19:18,639] - [data_helper] [4327563264] - INFO - 133
[2011-05-23 09:19:18,640] - [data_helper] [4357971968] - INFO - 133
[2011-05-23 09:19:18,640] - [data_helper] [4324343808] - INFO - 133
[2011-05-23 09:19:18,641] - [data_helper] [4324880384] - INFO - 133
[2011-05-23 09:19:18,841] - [data_helper] [4327563264] - INFO - 133
[2011-05-23 09:19:18,843] - [data_helper] [4324880384] - INFO - 133
[2011-05-23 09:19:18,843] - [data_helper] [4357971968] - INFO - 133
[2011-05-23 09:19:18,844] - [data_helper] [4324343808] - INFO - 133
[2011-05-23 09:19:19,690] - [rest_client] [140735087852704] - INFO - rebalance percentage : 5.6640625 %
[2011-05-23 09:19:21,702] - [rest_client] [140735087852704] - INFO - rebalance percentage : 6.25 %
[2011-05-23 09:19:23,709] - [rest_client] [140735087852704] - INFO - rebalance percentage : 6.8359375 %
[2011-05-23 09:19:25,718] - [rest_client] [140735087852704] - INFO - rebalance percentage : 7.421875 %
[2011-05-23 09:19:27,728] - [rest_client] [140735087852704] - INFO - rebalance percentage : 8.0078125 %
[2011-05-23 09:19:29,740] - [rest_client] [140735087852704] - INFO - rebalance percentage : 8.3984375 %

Issue Links

is duplicated by

Bug - A problem which impairs or prevents the functions of the product. MB-3973 Moxi returns errors during rebalance

  • Critical - Crashes, loss of data, severe memory leak.
  • Resolved - A resolution has been taken, and it is awaiting verification by reporter. From here issues are either reopened, or are closed.

Activity

Ascending order - Click to sort in descending order
Hide
Permalink
Farshid Ghods added a comment -
will attach the diags and more logs from the test.
Show
Farshid Ghods added a comment - will attach the diags and more logs from the test.
Farshid Ghods made changes -
Field Original Value New Value
Fix Version/s 1.7.1 [ 10183 ]
Fix Version/s 1.7 GA [ 10111 ]
Hide
Permalink
Farshid Ghods added a comment -
this bug manifests during memcachetest with these errors :


ASCII set failure: SERVER_ERROR proxy downstream closed 10.32.81.64
Failed to set [3098557]: during populate.
ASCII set failure: SERVER_ERROR proxy downstream closed 10.32.81.64
Failed to set [2116354]: during populate.
ASCII set failure: SERVER_ERROR proxy downstream closed 10.32.81.64
Failed to set [9099801]: during populate.
ASCII set failure: SERVER_ERROR proxy downstream closed 10.32.81.64
Failed to set [4117832]: during populate.
Show
Farshid Ghods added a comment - this bug manifests during memcachetest with these errors : ASCII set failure: SERVER_ERROR proxy downstream closed 10.32.81.64 Failed to set [3098557]: during populate. ASCII set failure: SERVER_ERROR proxy downstream closed 10.32.81.64 Failed to set [2116354]: during populate. ASCII set failure: SERVER_ERROR proxy downstream closed 10.32.81.64 Failed to set [9099801]: during populate. ASCII set failure: SERVER_ERROR proxy downstream closed 10.32.81.64 Failed to set [4117832]: during populate.
Farshid Ghods made changes -
Priority Major [ 3 ] Critical [ 2 ]
Farshid Ghods made changes -
Link This issue is duplicated by MB-3973 [ MB-3973 ]
Farshid Ghods made changes -
Assignee Steve Yen [ steve ]
Farshid Ghods made changes -
Labels 1.7.0-release-notes
Farshid Ghods made changes -
Assignee Steve Yen [ steve ] Mike Wiederhold [ mikew ]
Hide
Permalink
Steve Yen added a comment -
2 server nodes, A (*.12) and B (*.99). memcachetest using ascii protocol...

  /opt/membase/bin/memcachetest -h 127.0.0.1:11211 -i 10000 -c 10000 -l -s hello

Lots of server map REST messages are sent to moxi, which is a difference from 1.6.x.

Tons of propagate failed counts (need to double-check if the numbers add up and re-follow the propagate-failed codepath)....

Every 2.0s: echo stats proxy | nc 10.1.4.12 11211 | grep -v cmd | grep pstd Mon Jun 27 18:39:25 2011

STAT 11211:default:pstd_stats:num_upstream 2
STAT 11211:default:pstd_stats:tot_upstream 1122
STAT 11211:default:pstd_stats:num_downstream_conn 7
STAT 11211:default:pstd_stats:tot_downstream_conn 37
STAT 11211:default:pstd_stats:tot_downstream_conn_acquired 2257723
STAT 11211:default:pstd_stats:tot_downstream_conn_released 2068428
STAT 11211:default:pstd_stats:tot_downstream_released 2251527
STAT 11211:default:pstd_stats:tot_downstream_reserved 2251520
STAT 11211:default:pstd_stats:tot_downstream_reserved_time 0
STAT 11211:default:pstd_stats:max_downstream_reserved_time 0
STAT 11211:default:pstd_stats:tot_downstream_freed 3
STAT 11211:default:pstd_stats:tot_downstream_quit_server 30
STAT 11211:default:pstd_stats:tot_downstream_max_reached 0
STAT 11211:default:pstd_stats:tot_downstream_create_failed 0
STAT 11211:default:pstd_stats:tot_downstream_connect_started 37
STAT 11211:default:pstd_stats:tot_downstream_connect_wait 37
STAT 11211:default:pstd_stats:tot_downstream_connect 22
STAT 11211:default:pstd_stats:tot_downstream_connect_failed 15
STAT 11211:default:pstd_stats:tot_downstream_connect_timeout 7
STAT 11211:default:pstd_stats:tot_downstream_connect_interval 189265
STAT 11211:default:pstd_stats:tot_downstream_connect_max_reached 0
STAT 11211:default:pstd_stats:tot_downstream_waiting_errors 0
STAT 11211:default:pstd_stats:tot_downstream_auth 22
STAT 11211:default:pstd_stats:tot_downstream_auth_failed 8
STAT 11211:default:pstd_stats:tot_downstream_bucket 22
STAT 11211:default:pstd_stats:tot_downstream_bucket_failed 0
STAT 11211:default:pstd_stats:tot_downstream_propagate_failed 189280
STAT 11211:default:pstd_stats:tot_downstream_close_on_upstream_close 0
STAT 11211:default:pstd_stats:tot_downstream_conn_queue_timeout 0
STAT 11211:default:pstd_stats:tot_downstream_conn_queue_add 0
STAT 11211:default:pstd_stats:tot_downstream_conn_queue_remove 0
STAT 11211:default:pstd_stats:tot_downstream_timeout 13
STAT 11211:default:pstd_stats:tot_wait_queue_timeout 0
STAT 11211:default:pstd_stats:tot_auth_timeout 8
STAT 11211:default:pstd_stats:tot_assign_downstream 2251520
STAT 11211:default:pstd_stats:tot_assign_upstream 2251520
STAT 11211:default:pstd_stats:tot_assign_recursion 0
STAT 11211:default:pstd_stats:tot_reset_upstream_avail 0
STAT 11211:default:pstd_stats:tot_multiget_keys 30
STAT 11211:default:pstd_stats:tot_multiget_keys_dedupe 7
STAT 11211:default:pstd_stats:tot_multiget_bytes_dedupe 10
STAT 11211:default:pstd_stats:tot_optimize_sets 0
STAT 11211:default:pstd_stats:tot_retry 6198
STAT 11211:default:pstd_stats:tot_retry_time 0
STAT 11211:default:pstd_stats:max_retry_time 0
STAT 11211:default:pstd_stats:tot_retry_vbucket 6199
STAT 11211:default:pstd_stats:tot_upstream_paused 2251520
STAT 11211:default:pstd_stats:tot_upstream_unpaused 2251520
STAT 11211:default:pstd_stats:err_oom 0
STAT 11211:default:pstd_stats:err_upstream_write_prep 0
STAT 11211:default:pstd_stats:err_downstream_write_prep 0

memcachetest reports runs of many SERVER_ERROR's every once in awhile...

ASCII set failure: SERVER_ERROR proxy write to downstream
ASCII get error: SERVER_ERROR proxy write to downstream
<4645> isn't there anymore
ASCII get error: SERVER_ERROR proxy write to downstream
<6688> isn't there anymore
ASCII set failure: SERVER_ERROR proxy write to downstream
ASCII get error: SERVER_ERROR proxy write to downstream
<214> isn't there anymore
ASCII set failure: SERVER_ERROR proxy write to downstream
ASCII get error: SERVER_ERROR proxy write to downstream
<544> isn't there anymore
ASCII set failure: SERVER_ERROR proxy write to downstream
ASCII set failure: SERVER_ERROR proxy write to downstream
ASCII set failure: SERVER_ERROR proxy write to downstream
ASCII get error: SERVER_ERROR proxy write to downstream

...but heals eventually.

The missing keys are all keys that move from server A to B, confirmed from vbuckettool.
Show
Steve Yen added a comment - 2 server nodes, A (*.12) and B (*.99). memcachetest using ascii protocol...   /opt/membase/bin/memcachetest -h 127.0.0.1:11211 -i 10000 -c 10000 -l -s hello Lots of server map REST messages are sent to moxi, which is a difference from 1.6.x. Tons of propagate failed counts (need to double-check if the numbers add up and re-follow the propagate-failed codepath).... Every 2.0s: echo stats proxy | nc 10.1.4.12 11211 | grep -v cmd | grep pstd Mon Jun 27 18:39:25 2011 STAT 11211:default:pstd_stats:num_upstream 2 STAT 11211:default:pstd_stats:tot_upstream 1122 STAT 11211:default:pstd_stats:num_downstream_conn 7 STAT 11211:default:pstd_stats:tot_downstream_conn 37 STAT 11211:default:pstd_stats:tot_downstream_conn_acquired 2257723 STAT 11211:default:pstd_stats:tot_downstream_conn_released 2068428 STAT 11211:default:pstd_stats:tot_downstream_released 2251527 STAT 11211:default:pstd_stats:tot_downstream_reserved 2251520 STAT 11211:default:pstd_stats:tot_downstream_reserved_time 0 STAT 11211:default:pstd_stats:max_downstream_reserved_time 0 STAT 11211:default:pstd_stats:tot_downstream_freed 3 STAT 11211:default:pstd_stats:tot_downstream_quit_server 30 STAT 11211:default:pstd_stats:tot_downstream_max_reached 0 STAT 11211:default:pstd_stats:tot_downstream_create_failed 0 STAT 11211:default:pstd_stats:tot_downstream_connect_started 37 STAT 11211:default:pstd_stats:tot_downstream_connect_wait 37 STAT 11211:default:pstd_stats:tot_downstream_connect 22 STAT 11211:default:pstd_stats:tot_downstream_connect_failed 15 STAT 11211:default:pstd_stats:tot_downstream_connect_timeout 7 STAT 11211:default:pstd_stats:tot_downstream_connect_interval 189265 STAT 11211:default:pstd_stats:tot_downstream_connect_max_reached 0 STAT 11211:default:pstd_stats:tot_downstream_waiting_errors 0 STAT 11211:default:pstd_stats:tot_downstream_auth 22 STAT 11211:default:pstd_stats:tot_downstream_auth_failed 8 STAT 11211:default:pstd_stats:tot_downstream_bucket 22 STAT 11211:default:pstd_stats:tot_downstream_bucket_failed 0 STAT 11211:default:pstd_stats:tot_downstream_propagate_failed 189280 STAT 11211:default:pstd_stats:tot_downstream_close_on_upstream_close 0 STAT 11211:default:pstd_stats:tot_downstream_conn_queue_timeout 0 STAT 11211:default:pstd_stats:tot_downstream_conn_queue_add 0 STAT 11211:default:pstd_stats:tot_downstream_conn_queue_remove 0 STAT 11211:default:pstd_stats:tot_downstream_timeout 13 STAT 11211:default:pstd_stats:tot_wait_queue_timeout 0 STAT 11211:default:pstd_stats:tot_auth_timeout 8 STAT 11211:default:pstd_stats:tot_assign_downstream 2251520 STAT 11211:default:pstd_stats:tot_assign_upstream 2251520 STAT 11211:default:pstd_stats:tot_assign_recursion 0 STAT 11211:default:pstd_stats:tot_reset_upstream_avail 0 STAT 11211:default:pstd_stats:tot_multiget_keys 30 STAT 11211:default:pstd_stats:tot_multiget_keys_dedupe 7 STAT 11211:default:pstd_stats:tot_multiget_bytes_dedupe 10 STAT 11211:default:pstd_stats:tot_optimize_sets 0 STAT 11211:default:pstd_stats:tot_retry 6198 STAT 11211:default:pstd_stats:tot_retry_time 0 STAT 11211:default:pstd_stats:max_retry_time 0 STAT 11211:default:pstd_stats:tot_retry_vbucket 6199 STAT 11211:default:pstd_stats:tot_upstream_paused 2251520 STAT 11211:default:pstd_stats:tot_upstream_unpaused 2251520 STAT 11211:default:pstd_stats:err_oom 0 STAT 11211:default:pstd_stats:err_upstream_write_prep 0 STAT 11211:default:pstd_stats:err_downstream_write_prep 0 memcachetest reports runs of many SERVER_ERROR's every once in awhile... ASCII set failure: SERVER_ERROR proxy write to downstream ASCII get error: SERVER_ERROR proxy write to downstream <4645> isn't there anymore ASCII get error: SERVER_ERROR proxy write to downstream <6688> isn't there anymore ASCII set failure: SERVER_ERROR proxy write to downstream ASCII get error: SERVER_ERROR proxy write to downstream <214> isn't there anymore ASCII set failure: SERVER_ERROR proxy write to downstream ASCII get error: SERVER_ERROR proxy write to downstream <544> isn't there anymore ASCII set failure: SERVER_ERROR proxy write to downstream ASCII set failure: SERVER_ERROR proxy write to downstream ASCII set failure: SERVER_ERROR proxy write to downstream ASCII get error: SERVER_ERROR proxy write to downstream ...but heals eventually. The missing keys are all keys that move from server A to B, confirmed from vbuckettool.
Steve Yen made changes -
Assignee Mike Wiederhold [ mikew ] Steve Yen [ steve ]
Hide
Permalink
Steve Yen added a comment -
In these runs, it looks like moxi is backing off as designed. The tot_downstream_connect_interval counter is incremented whenever moxi is in backoff mode.

  STAT 11211:default:pstd_stats:tot_downstream_connect_interval 189265

Investigation should shift to why moxi couldn't connect. As configured, 5 connect errors would trigger moxi's backoff mode. Then, backoff mode would last for 30 seconds (the default backoff interval configuration).
  
Show
Steve Yen added a comment - In these runs, it looks like moxi is backing off as designed. The tot_downstream_connect_interval counter is incremented whenever moxi is in backoff mode.   STAT 11211:default:pstd_stats:tot_downstream_connect_interval 189265 Investigation should shift to why moxi couldn't connect. As configured, 5 connect errors would trigger moxi's backoff mode. Then, backoff mode would last for 30 seconds (the default backoff interval configuration).   
Farshid Ghods made changes -
Labels 1.7.0-release-notes 1.7.0-release-notes 1.7.1-release-notes
Farshid Ghods made changes -
Fix Version/s 2.0 Beta [ 10113 ]
Fix Version/s 1.7.1 [ 10183 ]
Hide
Permalink
Steve Yen added a comment -
marking this won't-fix, as by my re-reading of this old bug, moxi's behaving as designed when it starts timing out when it encounters a slow server (such as a cluster that's gummed up by background fetches during a rebalance).
Show
Steve Yen added a comment - marking this won't-fix, as by my re-reading of this old bug, moxi's behaving as designed when it starts timing out when it encounters a slow server (such as a cluster that's gummed up by background fetches during a rebalance).
Steve Yen made changes -
Status Open [ 1 ] Resolved [ 5 ]
Resolution Won't Fix [ 2 ]
Farshid Ghods made changes -
Status Resolved [ 5 ] Closed [ 6 ]

People

  • Assignee:
    Steve Yen
    Reporter:
    Farshid Ghods
Vote (0)
Watch (0)

Dates

  • Created:
    Updated:
    Resolved: