::opencensus::stats::MeasureInt64 MeasureStartCount() {
static const ::opencensus::stats::MeasureInt64 start_count =
::opencensus::stats::MeasureInt64::Register(
kMeasureStartCount, kMeasureStartCount, kMeasureStartCount);
return start_count;
}
[ RUN ] ServerLoadReportingEnd2endTest.BasicReport
D0623 13:37:14.313988446 242908 ev_posix.cc:145] Using polling engine: epollex
D0623 13:37:14.314029956 242908 dns_resolver.cc:339] Using native dns resolver
D0623 13:37:14.316311692 242908 ev_posix.cc:145] Using polling engine: epollex
D0623 13:37:14.316343875 242908 dns_resolver.cc:339] Using native dns resolver
I0623 13:37:14.316864980 242908 server_builder.cc:273] Synchronous server. Num CQs: 1, Min pollers: 1, Max Pollers: 2, CQ timeout (msec): 10000
D0623 13:37:14.317355586 242950 load_reporter_async_service_impl.cc:78] [LRS 0x482e70] Starting a fetch-and-sample...
D0623 13:37:14.317411990 242950 load_reporter.cc:490] [LR 0x47fe40] Starts fetching Census view data and sampling LB feedback record.
D0623 13:37:14.317422571 242950 load_reporter.cc:190] [CVP 0x47ff80] Starts fetching Census view data.
D0623 13:37:14.317437870 242950 load_reporter.cc:197] [CVP 0x47ff80] Fetched view data (view: grpc.io/lb_view/start_count).
D0623 13:37:14.317450829 242950 load_reporter.cc:197] [CVP 0x47ff80] Fetched view data (view: grpc.io/lb_view/end_count).
D0623 13:37:14.317461294 242950 load_reporter.cc:197] [CVP 0x47ff80] Fetched view data (view: grpc.io/lb_view/bytes_sent).
D0623 13:37:14.317471768 242950 load_reporter.cc:197] [CVP 0x47ff80] Fetched view data (view: grpc.io/lb_view/bytes_received).
D0623 13:37:14.317481978 242950 load_reporter.cc:197] [CVP 0x47ff80] Fetched view data (view: grpc.io/lb_view/latency_ms).
D0623 13:37:14.317492947 242950 load_reporter.cc:197] [CVP 0x47ff80] Fetched view data (view: grpc.io/lb_view/other_call_metric_count).
D0623 13:37:14.317503341 242950 load_reporter.cc:197] [CVP 0x47ff80] Fetched view data (view: grpc.io/lb_view/other_call_metric_value).
D0623 13:37:14.317708765 242950 load_reporter_async_service_impl.cc:70] [LRS 0x482e70] Next fetch-and-sample scheduled.
D0623 13:37:14.317972062 242908 dns_resolver.cc:280] Start resolving.
I0623 13:37:14.319444295 242948 subchannel.cc:608] New connected subchannel at 0x7ffff0005840 for subchannel 0x7ffff0003e40
I0623 13:37:14.320059301 242908 server_load_reporting_end2end_test.cc:137] Initial request sent.
Attempt to register measure with already-registered name: name: "grpc.io/lb/start_count"; units: "grpc.io/lb/start_count"; description: "grpc.io/lb/start_count"; type: int64
I0623 13:37:15.318668918 242950 server_load_reporting_filter.cc:263] START RECORD 1
D0623 13:37:15.318829598 242950 load_reporter_async_service_impl.cc:78] [LRS 0x482e70] Starting a fetch-and-sample...
D0623 13:37:15.318846352 242950 load_reporter.cc:490] [LR 0x47fe40] Starts fetching Census view data and sampling LB feedback record.
D0623 13:37:15.318859150 242950 load_reporter.cc:190] [CVP 0x47ff80] Starts fetching Census view data.
D0623 13:37:15.318877675 242950 load_reporter.cc:197] [CVP 0x47ff80] Fetched view data (view: grpc.io/lb_view/start_count).
D0623 13:37:15.318889608 242950 load_reporter.cc:197] [CVP 0x47ff80] Fetched view data (view: grpc.io/lb_view/end_count).
D0623 13:37:15.318900901 242950 load_reporter.cc:197] [CVP 0x47ff80] Fetched view data (view: grpc.io/lb_view/bytes_sent).
D0623 13:37:15.318913587 242950 load_reporter.cc:197] [CVP 0x47ff80] Fetched view data (view: grpc.io/lb_view/bytes_received).
D0623 13:37:15.318924346 242950 load_reporter.cc:197] [CVP 0x47ff80] Fetched view data (view: grpc.io/lb_view/latency_ms).
D0623 13:37:15.318935930 242950 load_reporter.cc:197] [CVP 0x47ff80] Fetched view data (view: grpc.io/lb_view/other_call_metric_count).
D0623 13:37:15.318949934 242950 load_reporter.cc:197] [CVP 0x47ff80] Fetched view data (view: grpc.io/lb_view/other_call_metric_value).
D0623 13:37:15.319142178 242950 load_reporter_async_service_impl.cc:70] [LRS 0x482e70] Next fetch-and-sample scheduled.
I0623 13:37:15.319305055 242950 load_reporter_async_service_impl.cc:161] [LRS 0x482e70] Call request delivered (lb_id_: 00000000, handler: 0x7fffe8001960). Start reading the initial request...
I0623 13:37:15.319530627 242950 load_data_store.cc:256] [PerHostStore 0x7fffe8000e80] Re-assigned orphaned store (0x7fffe800b6b0) with original LB ID of <INVALID_LBID_238dsb234890rb> to new receiver 00000000
I0623 13:37:15.319561315 242950 load_reporter.cc:376] [LR 0x47fe40] Report stream created (host: localhost:12746, LB ID: 00000000, load key: LOAD_KEY).
I0623 13:37:15.319572060 242950 load_reporter_async_service_impl.cc:196] [LRS 0x482e70] Initial request received. Start load reporting (load balanced host: localhost:12746, interval: 5000 ms, lb_id_: 00000000, handler: 0x7fffe8001960)...
I0623 13:37:15.319682745 242950 load_reporter_async_service_impl.cc:281] [LRS 0x482e70] Sending load report (lb_id_: 00000000, handler: 0x7fffe8001960, loads count: 0)...
D0623 13:37:15.319710483 242950 load_reporter_async_service_impl.cc:247] [LRS 0x482e70] Next load report scheduled (lb_id_: 00000000, handler: 0x7fffe8001960).
I0623 13:37:15.319819823 242908 server_load_reporting_end2end_test.cc:141] Initial response received (lb_id: 00000000).
D0623 13:37:15.320015339 242908 dns_resolver.cc:280] Start resolving.
I0623 13:37:15.320557951 242950 server_load_reporting_filter.cc:263] START RECORD 1
Attempt to register measure with already-registered name: name: "grpc.io/lb/other_call_metric"; units: "grpc.io/lb/other_call_metric"; description: "grpc.io/lb/other_call_metric"; type: double
Attempt to register measure with already-registered name: name: "grpc.io/lb/end_count"; units: "grpc.io/lb/end_count"; description: "grpc.io/lb/end_count"; type: int64
Attempt to register measure with already-registered name: name: "grpc.io/lb/bytes_sent"; units: "grpc.io/lb/bytes_sent"; description: "grpc.io/lb/bytes_sent"; type: int64
Attempt to register measure with already-registered name: name: "grpc.io/lb/bytes_received"; units: "grpc.io/lb/bytes_received"; description: "grpc.io/lb/bytes_received"; type: int64
Attempt to register measure with already-registered name: name: "grpc.io/lb/latency_ms"; units: "grpc.io/lb/latency_ms"; description: "grpc.io/lb/latency_ms"; type: int64
D0623 13:37:16.320333762 242950 load_reporter_async_service_impl.cc:78] [LRS 0x482e70] Starting a fetch-and-sample...
D0623 13:37:16.320367867 242950 load_reporter.cc:490] [LR 0x47fe40] Starts fetching Census view data and sampling LB feedback record.
D0623 13:37:16.320377374 242950 load_reporter.cc:190] [CVP 0x47ff80] Starts fetching Census view data.
D0623 13:37:16.320395659 242950 load_reporter.cc:197] [CVP 0x47ff80] Fetched view data (view: grpc.io/lb_view/start_count).
D0623 13:37:16.320403838 242950 load_reporter.cc:197] [CVP 0x47ff80] Fetched view data (view: grpc.io/lb_view/end_count).
D0623 13:37:16.320414540 242950 load_reporter.cc:197] [CVP 0x47ff80] Fetched view data (view: grpc.io/lb_view/bytes_sent).
D0623 13:37:16.320425090 242950 load_reporter.cc:197] [CVP 0x47ff80] Fetched view data (view: grpc.io/lb_view/bytes_received).
D0623 13:37:16.320434589 242950 load_reporter.cc:197] [CVP 0x47ff80] Fetched view data (view: grpc.io/lb_view/latency_ms).
D0623 13:37:16.320447617 242950 load_reporter.cc:197] [CVP 0x47ff80] Fetched view data (view: grpc.io/lb_view/other_call_metric_count).
D0623 13:37:16.320457110 242950 load_reporter.cc:197] [CVP 0x47ff80] Fetched view data (view: grpc.io/lb_view/other_call_metric_value).
D0623 13:37:16.320647817 242950 load_reporter_async_service_impl.cc:70] [LRS 0x482e70] Next fetch-and-sample scheduled.
D0623 13:37:17.321343602 242950 load_reporter_async_service_impl.cc:78] [LRS 0x482e70] Starting a fetch-and-sample...
D0623 13:37:17.321377090 242950 load_reporter.cc:490] [LR 0x47fe40] Starts fetching Census view data and sampling LB feedback record.
D0623 13:37:17.321387571 242950 load_reporter.cc:190] [CVP 0x47ff80] Starts fetching Census view data.
D0623 13:37:17.321406578 242950 load_reporter.cc:197] [CVP 0x47ff80] Fetched view data (view: grpc.io/lb_view/start_count).
D0623 13:37:17.321420644 242950 load_reporter.cc:197] [CVP 0x47ff80] Fetched view data (view: grpc.io/lb_view/end_count).
D0623 13:37:17.321436103 242950 load_reporter.cc:197] [CVP 0x47ff80] Fetched view data (view: grpc.io/lb_view/bytes_sent).
D0623 13:37:17.321460326 242950 load_reporter.cc:197] [CVP 0x47ff80] Fetched view data (view: grpc.io/lb_view/bytes_received).
D0623 13:37:17.321474007 242950 load_reporter.cc:197] [CVP 0x47ff80] Fetched view data (view: grpc.io/lb_view/latency_ms).
D0623 13:37:17.321487261 242950 load_reporter.cc:197] [CVP 0x47ff80] Fetched view data (view: grpc.io/lb_view/other_call_metric_count).
D0623 13:37:17.321501110 242950 load_reporter.cc:197] [CVP 0x47ff80] Fetched view data (view: grpc.io/lb_view/other_call_metric_value).
D0623 13:37:17.321731319 242950 load_reporter_async_service_impl.cc:70] [LRS 0x482e70] Next fetch-and-sample scheduled.
D0623 13:37:18.322311673 242950 load_reporter_async_service_impl.cc:78] [LRS 0x482e70] Starting a fetch-and-sample...
D0623 13:37:18.322347372 242950 load_reporter.cc:490] [LR 0x47fe40] Starts fetching Census view data and sampling LB feedback record.
D0623 13:37:18.322360432 242950 load_reporter.cc:190] [CVP 0x47ff80] Starts fetching Census view data.
D0623 13:37:18.322386536 242950 load_reporter.cc:197] [CVP 0x47ff80] Fetched view data (view: grpc.io/lb_view/start_count).
D0623 13:37:18.322398547 242950 load_reporter.cc:197] [CVP 0x47ff80] Fetched view data (view: grpc.io/lb_view/end_count).
D0623 13:37:18.322409583 242950 load_reporter.cc:197] [CVP 0x47ff80] Fetched view data (view: grpc.io/lb_view/bytes_sent).
D0623 13:37:18.322420434 242950 load_reporter.cc:197] [CVP 0x47ff80] Fetched view data (view: grpc.io/lb_view/bytes_received).
D0623 13:37:18.322431306 242950 load_reporter.cc:197] [CVP 0x47ff80] Fetched view data (view: grpc.io/lb_view/latency_ms).
D0623 13:37:18.322442936 242950 load_reporter.cc:197] [CVP 0x47ff80] Fetched view data (view: grpc.io/lb_view/other_call_metric_count).
D0623 13:37:18.322454099 242950 load_reporter.cc:197] [CVP 0x47ff80] Fetched view data (view: grpc.io/lb_view/other_call_metric_value).
I0623 13:37:18.322466875 242950 load_reporter.cc:396] START_COUNT GOT 1
D0623 13:37:18.322608830 242950 load_data_store.cc:146] [PerBalancerStore 0x7fffe800b6b0] Load data merged (Key: [lb_id_=<INVALID_LBID_238dsb234890rb>, lb_tag_=, user_id_=, client_ip_hex_=00000000000000000000000000000001], Value: [start_count_=1, ok_count_=0, error_count_=0, bytes_sent_=0, bytes_recv_=0, latency_ms_=0]).
I0623 13:37:18.322626284 242950 load_reporter.cc:396] START_COUNT GOT 24
D0623 13:37:18.322645735 242950 load_data_store.cc:146] [PerBalancerStore 0x7fffe8001760] Load data merged (Key: [lb_id_=00000000, lb_tag_=LB_TAG, user_id_=, client_ip_hex_=00000000000000000000000000000001], Value: [start_count_=24, ok_count_=0, error_count_=0, bytes_sent_=0, bytes_recv_=0, latency_ms_=0]).
D0623 13:37:18.322805456 242950 load_reporter_async_service_impl.cc:70] [LRS 0x482e70] Next fetch-and-sample scheduled.
D0623 13:37:19.323293284 242950 load_reporter_async_service_impl.cc:78] [LRS 0x482e70] Starting a fetch-and-sample...
D0623 13:37:19.323324559 242950 load_reporter.cc:490] [LR 0x47fe40] Starts fetching Census view data and sampling LB feedback record.
D0623 13:37:19.323335550 242950 load_reporter.cc:190] [CVP 0x47ff80] Starts fetching Census view data.
D0623 13:37:19.323355241 242950 load_reporter.cc:197] [CVP 0x47ff80] Fetched view data (view: grpc.io/lb_view/start_count).
D0623 13:37:19.323365399 242950 load_reporter.cc:197] [CVP 0x47ff80] Fetched view data (view: grpc.io/lb_view/end_count).
D0623 13:37:19.323375394 242950 load_reporter.cc:197] [CVP 0x47ff80] Fetched view data (view: grpc.io/lb_view/bytes_sent).
D0623 13:37:19.323385084 242950 load_reporter.cc:197] [CVP 0x47ff80] Fetched view data (view: grpc.io/lb_view/bytes_received).
D0623 13:37:19.323394732 242950 load_reporter.cc:197] [CVP 0x47ff80] Fetched view data (view: grpc.io/lb_view/latency_ms).
D0623 13:37:19.323404314 242950 load_reporter.cc:197] [CVP 0x47ff80] Fetched view data (view: grpc.io/lb_view/other_call_metric_count).
D0623 13:37:19.323414000 242950 load_reporter.cc:197] [CVP 0x47ff80] Fetched view data (view: grpc.io/lb_view/other_call_metric_value).
D0623 13:37:19.323586229 242950 load_reporter_async_service_impl.cc:70] [LRS 0x482e70] Next fetch-and-sample scheduled.
I0623 13:37:20.320542192 242950 load_reporter_async_service_impl.cc:281] [LRS 0x482e70] Sending load report (lb_id_: 00000000, handler: 0x7fffe8001960, loads count: 4)...
D0623 13:37:20.320607894 242950 load_reporter_async_service_impl.cc:247] [LRS 0x482e70] Next load report scheduled (lb_id_: 00000000, handler: 0x7fffe8001960).
test/cpp/end2end/server_load_reporting_end2end_test.cc:146: Failure
Expected: response.load().size()
Which is: 4
To be equal to: 3
I0623 13:37:20.321082956 242950 load_reporter_async_service_impl.cc:291] [LRS 0x482e70] Shutting down the handler (lb_id_: 00000000, handler: 0x7fffe8001960, reason: OnReadDone).
D0623 13:37:20.321106585 242950 load_data_store.cc:166] [PerBalancerStore 0x7fffe8001760] Suspended.
D0623 13:37:20.321116969 242950 load_data_store.cc:166] [PerBalancerStore 0x7fffe800b6b0] Suspended.
I0623 13:37:20.321128956 242950 load_reporter.cc:385] [LR 0x47fe40] Report stream closed (host: localhost:12746, LB ID: 00000000).
I0623 13:37:20.321171552 242950 load_reporter_async_service_impl.cc:334] [LRS 0x482e70] Load reporting call is notified done (handler: 0x7fffe8001960, is_cancelled: 1).
I0623 13:37:20.321293431 242950 load_reporter_async_service_impl.cc:291] [LRS 0x482e70] Shutting down the handler (lb_id_: , handler: 0x7fffe800bcc0, reason: OnRequestDelivered).
I0623 13:37:20.321577390 242950 load_reporter_async_service_impl.cc:75] [LRS 0x482e70] Fetch-and-sample is stopped.
[ FAILED ] ServerLoadReportingEnd2endTest.BasicReport (6008 ms)
When I tried to debug this issue with logging each access to the measures, this issue disappears... 😞