tests(zipkin): addressing flakiness (#10907)

* tests(zipkin): span order induced flakiness

this test relied on the order of spans returned, this sometimes changed
making the test fail. This commit fixes the test by "searching" for the
expected spans in the returned array.

* tests(zipkin): timeout induced flakiness

spec/03-plugins/34-zipkin/zipkin_spec.lua

@@ -70,16 +70,15 @@ local function wait_for_spans(zipkin_client, number_of_spans, remoteServiceName,
     end
   end)
 
-  return utils.unpack(spans)
+  return spans
 end
 
 
 -- the following assertions should be true on any span list, even in error mode
-local function assert_span_invariants(request_span, proxy_span, expected_name, traceid_len, start_s, service_name, phase_duration_flavor)
+local function assert_span_invariants(request_span, proxy_span, traceid_len, start_s, service_name, phase_duration_flavor)
   -- request_span
   assert.same("table", type(request_span))
   assert.same("string", type(request_span.id))
-  assert.same(expected_name, request_span.name)
   assert.same(request_span.id, proxy_span.parentId)
 
   assert.same("SERVER", request_span.kind)
@@ -148,6 +147,15 @@ local function assert_span_invariants(request_span, proxy_span, expected_name, t
   end
 end
 
+local function get_span(name, spans)
+  for _, span in ipairs(spans) do
+    if span.name == name then
+      return span
+    end
+  end
+  return nil
+end
+
 
 for _, strategy in helpers.each_strategy() do
   describe("plugin configuration", function()
@@ -216,10 +224,12 @@ for _, strategy in helpers.each_strategy() do
       })
       assert.response(r).has.status(200)
 
-      local _, proxy_span, request_span =
-        wait_for_spans(zipkin_client, 3, service.name)
+      local spans = wait_for_spans(zipkin_client, 3, service.name)
+      local request_span = assert(get_span("get", spans), "request span missing")
+      local proxy_span = assert(get_span("get (proxy)", spans), "proxy span missing")
+
       -- common assertions for request_span and proxy_span
-      assert_span_invariants(request_span, proxy_span, "get", 16 * 2, start_s, "kong")
+      assert_span_invariants(request_span, proxy_span, 16 * 2, start_s, "kong")
     end)
   end)
 end
@@ -281,10 +291,12 @@ for _, strategy in helpers.each_strategy() do
       })
       assert.response(r).has.status(200)
 
-      local _, proxy_span, request_span =
-        wait_for_spans(zipkin_client, 3, service.name)
+      local spans = wait_for_spans(zipkin_client, 3, service.name)
+      local request_span = assert(get_span("get", spans), "request span missing")
+      local proxy_span = assert(get_span("get (proxy)", spans), "proxy span missing")
+
       -- common assertions for request_span and proxy_span
-      assert_span_invariants(request_span, proxy_span, "get", 16 * 2, start_s, "custom-service-name")
+      assert_span_invariants(request_span, proxy_span, 16 * 2, start_s, "custom-service-name")
     end)
   end)
 end
@@ -398,7 +410,7 @@ for _, strategy in helpers.each_strategy() do
       -- wait for zero-delay timer
       helpers.wait_timer("zipkin", true, "any-finish")
 
-      assert.logfile().has.line("[zipkin] reporter flush failed to request: timeout", true, 2)
+      assert.logfile().has.line("[zipkin] reporter flush failed to request: timeout", true, 10)
     end)
 
     it("times out if upstream zipkin server takes too long to respond", function()
@@ -414,7 +426,7 @@ for _, strategy in helpers.each_strategy() do
       -- wait for zero-delay timer
       helpers.wait_timer("zipkin", true, "any-finish")
 
-      assert.logfile().has.line("[zipkin] reporter flush failed to request: timeout", true, 2)
+      assert.logfile().has.line("[zipkin] reporter flush failed to request: timeout", true, 10)
     end)
 
     it("connection refused if upstream zipkin server is not listening", function()
@@ -430,7 +442,7 @@ for _, strategy in helpers.each_strategy() do
       -- wait for zero-delay timer
       helpers.wait_timer("zipkin", true, "any-finish")
 
-      assert.logfile().has.line("[zipkin] reporter flush failed to request: connection refused", true, 2)
+      assert.logfile().has.line("[zipkin] reporter flush failed to request: connection refused", true, 10)
     end)
   end)
 end
@@ -549,10 +561,12 @@ for _, strategy in helpers.each_strategy() do
 
       assert.response(r).has.status(200)
 
-      local _, proxy_span, request_span =
-        wait_for_spans(zipkin_client, 3, service.name)
+      local spans = wait_for_spans(zipkin_client, 3, service.name)
+      local request_span = assert(get_span("get /", spans), "request span missing")
+      local proxy_span = assert(get_span("get / (proxy)", spans), "proxy span missing")
+
       -- common assertions for request_span and proxy_span
-      assert_span_invariants(request_span, proxy_span, "get /", 16 * 2, start_s, "kong")
+      assert_span_invariants(request_span, proxy_span, 16 * 2, start_s, "kong")
     end)
   end)
 end
@@ -657,10 +671,13 @@ describe("http integration tests with zipkin server [#"
     })
     assert.response(r).has.status(200)
 
-    local balancer_span, proxy_span, request_span =
-      wait_for_spans(zipkin_client, 3, service.name)
+    local spans = wait_for_spans(zipkin_client, 3, service.name)
+    local balancer_span = assert(get_span("get (balancer try 1)", spans), "balancer span missing")
+    local request_span = assert(get_span("get", spans), "request span missing")
+    local proxy_span = assert(get_span("get (proxy)", spans), "proxy span missing")
+
     -- common assertions for request_span and proxy_span
-    assert_span_invariants(request_span, proxy_span, "get", traceid_byte_count * 2, start_s, "kong")
+    assert_span_invariants(request_span, proxy_span, traceid_byte_count * 2, start_s, "kong")
 
     -- specific assertions for request_span
     local request_tags = request_span.tags
@@ -737,10 +754,13 @@ describe("http integration tests with zipkin server [#"
     assert(ok, resp)
     assert.truthy(resp)
 
-    local balancer_span, proxy_span, request_span =
-      wait_for_spans(zipkin_client, 3, grpc_service.name)
+    local spans = wait_for_spans(zipkin_client, 3, grpc_service.name)
+    local balancer_span = assert(get_span("post (balancer try 1)", spans), "balancer span missing")
+    local request_span = assert(get_span("post", spans), "request span missing")
+    local proxy_span = assert(get_span("post (proxy)", spans), "proxy span missing")
+
     -- common assertions for request_span and proxy_span
-    assert_span_invariants(request_span, proxy_span, "post", traceid_byte_count * 2, start_s, "kong")
+    assert_span_invariants(request_span, proxy_span, traceid_byte_count * 2, start_s, "kong")
 
     -- specific assertions for request_span
     local request_tags = request_span.tags
@@ -814,8 +834,10 @@ describe("http integration tests with zipkin server [#"
 
     assert(tcp:close())
 
-    local balancer_span, proxy_span, request_span =
-      wait_for_spans(zipkin_client, 3, tcp_service.name)
+    local spans = wait_for_spans(zipkin_client, 3, tcp_service.name)
+    local balancer_span = assert(get_span("stream (balancer try 1)", spans), "balancer span missing")
+    local request_span = assert(get_span("stream", spans), "request span missing")
+    local proxy_span = assert(get_span("stream (proxy)", spans), "proxy span missing")
 
     -- request span
     assert.same("table", type(request_span))
@@ -923,11 +945,13 @@ describe("http integration tests with zipkin server [#"
     })
     assert.response(r).has.status(404)
 
-    local proxy_span, request_span =
-      wait_for_spans(zipkin_client, 2, nil, trace_id)
+    local spans = wait_for_spans(zipkin_client, 2, nil, trace_id)
+    assert.is_nil(get_span("get (balancer try 1)", spans), "balancer span found")
+    local request_span = assert(get_span("get", spans), "request span missing")
+    local proxy_span = assert(get_span("get (proxy)", spans), "proxy span missing")
 
     -- common assertions for request_span and proxy_span
-    assert_span_invariants(request_span, proxy_span, "get", #trace_id, start_s, "kong")
+    assert_span_invariants(request_span, proxy_span, #trace_id, start_s, "kong")
 
     -- specific assertions for request_span
     local request_tags = request_span.tags
@@ -966,8 +990,10 @@ describe("http integration tests with zipkin server [#"
     })
     assert.response(r).has.status(404)
 
-    local proxy_span, request_span =
-      wait_for_spans(zipkin_client, 2, nil, trace_id)
+    local spans = wait_for_spans(zipkin_client, 2, nil, trace_id)
+    assert.is_nil(get_span("get (balancer try 1)", spans), "balancer span found")
+    local request_span = assert(get_span("get", spans), "request span missing")
+    local proxy_span = assert(get_span("get (proxy)", spans), "proxy span missing")
 
     assert.equals(trace_id, proxy_span.traceId)
     assert.equals(trace_id, request_span.traceId)
@@ -990,8 +1016,10 @@ describe("http integration tests with zipkin server [#"
       local json = cjson.decode(body)
       assert.matches(trace_id .. "%-%x+%-1%-%x+", json.headers.b3)
 
-      local balancer_span, proxy_span, request_span =
-        wait_for_spans(zipkin_client, 3, nil, trace_id)
+      local spans = wait_for_spans(zipkin_client, 3, nil, trace_id)
+      local balancer_span = assert(get_span("get (balancer try 1)", spans), "balancer span missing")
+      local request_span = assert(get_span("get", spans), "request span missing")
+      local proxy_span = assert(get_span("get (proxy)", spans), "proxy span missing")
 
       assert.equals(trace_id, request_span.traceId)
       assert.equals(span_id, request_span.id)
@@ -1020,8 +1048,10 @@ describe("http integration tests with zipkin server [#"
       local json = cjson.decode(body)
       assert.matches(trace_id .. "%-%x+%-1%-%x+", json.headers.b3)
 
-      local balancer_span, proxy_span, request_span =
-        wait_for_spans(zipkin_client, 3, nil, trace_id)
+      local spans = wait_for_spans(zipkin_client, 3, nil, trace_id)
+      local balancer_span = assert(get_span("get (balancer try 1)", spans), "balancer span missing")
+      local request_span = assert(get_span("get", spans), "request span missing")
+      local proxy_span = assert(get_span("get (proxy)", spans), "proxy span missing")
 
       assert.equals(trace_id, request_span.traceId)
       assert.equals(span_id, request_span.id)
@@ -1050,8 +1080,10 @@ describe("http integration tests with zipkin server [#"
       local json = cjson.decode(body)
       assert.matches(trace_id .. "%-%x+%-1%-%x+", json.headers.b3)
 
-      local balancer_span, proxy_span, request_span =
-        wait_for_spans(zipkin_client, 3, nil, trace_id)
+      local spans = wait_for_spans(zipkin_client, 3, nil, trace_id)
+      local balancer_span = assert(get_span("get (balancer try 1)", spans), "balancer span missing")
+      local request_span = assert(get_span("get", spans), "request span missing")
+      local proxy_span = assert(get_span("get (proxy)", spans), "proxy span missing")
 
       assert.equals(trace_id, request_span.traceId)
       assert.equals(span_id, request_span.id)
@@ -1076,8 +1108,10 @@ describe("http integration tests with zipkin server [#"
       })
       assert.response(r).has.status(404)
 
-      local proxy_span, request_span =
-        wait_for_spans(zipkin_client, 2, nil, trace_id)
+      local spans = wait_for_spans(zipkin_client, 2, nil, trace_id)
+      assert.is_nil(get_span("get (balancer try 1)", spans), "balancer span found")
+      local request_span = assert(get_span("get", spans), "request span missing")
+      local proxy_span = assert(get_span("get (proxy)", spans), "proxy span missing")
 
       assert.equals(trace_id, request_span.traceId)
       assert.equals(span_id, request_span.id)
@@ -1104,8 +1138,10 @@ describe("http integration tests with zipkin server [#"
       local json = cjson.decode(body)
       assert.matches("00%-" .. trace_id .. "%-%x+-01", json.headers.traceparent)
 
-      local balancer_span, proxy_span, request_span =
-      wait_for_spans(zipkin_client, 3, nil, trace_id)
+      local spans = wait_for_spans(zipkin_client, 3, nil, trace_id)
+      local balancer_span = assert(get_span("get (balancer try 1)", spans), "balancer span missing")
+      local request_span = assert(get_span("get", spans), "request span missing")
+      local proxy_span = assert(get_span("get (proxy)", spans), "proxy span missing")
 
       assert.equals(trace_id, request_span.traceId)
       assert.equals(parent_id, request_span.parentId)
@@ -1125,8 +1161,10 @@ describe("http integration tests with zipkin server [#"
       })
       assert.response(r).has.status(404)
 
-      local proxy_span, request_span =
-      wait_for_spans(zipkin_client, 2, nil, trace_id)
+      local spans = wait_for_spans(zipkin_client, 2, nil, trace_id)
+      assert.is_nil(get_span("get (balancer try 1)", spans), "balancer span found")
+      local request_span = assert(get_span("get", spans), "request span missing")
+      local proxy_span = assert(get_span("get (proxy)", spans), "proxy span missing")
 
       assert.equals(trace_id, request_span.traceId)
       assert.equals(parent_id, request_span.parentId)
@@ -1151,8 +1189,10 @@ describe("http integration tests with zipkin server [#"
       local json = cjson.decode(body)
       assert.matches(('0'):rep(32-#trace_id) .. trace_id .. ":%x+:" .. span_id .. ":01", json.headers["uber-trace-id"])
 
-      local balancer_span, proxy_span, request_span =
-      wait_for_spans(zipkin_client, 3, nil, trace_id)
+      local spans = wait_for_spans(zipkin_client, 3, nil, trace_id)
+      local balancer_span = assert(get_span("get (balancer try 1)", spans), "balancer span missing")
+      local request_span = assert(get_span("get", spans), "request span missing")
+      local proxy_span = assert(get_span("get (proxy)", spans), "proxy span missing")
 
       assert.equals(trace_id, request_span.traceId)
       assert.equals(span_id, request_span.id)
@@ -1179,8 +1219,10 @@ describe("http integration tests with zipkin server [#"
       })
       assert.response(r).has.status(404)
 
-      local proxy_span, request_span =
-      wait_for_spans(zipkin_client, 2, nil, trace_id)
+      local spans = wait_for_spans(zipkin_client, 2, nil, trace_id)
+      assert.is_nil(get_span("get (balancer try 1)", spans), "balancer span found")
+      local request_span = assert(get_span("get", spans), "request span missing")
+      local proxy_span = assert(get_span("get (proxy)", spans), "proxy span missing")
 
       assert.equals(trace_id, request_span.traceId)
       assert.equals(span_id, request_span.id)
@@ -1210,8 +1252,10 @@ describe("http integration tests with zipkin server [#"
       local json = cjson.decode(body)
       assert.equals(trace_id, json.headers["ot-tracer-traceid"])
 
-      local balancer_span, proxy_span, request_span =
-        wait_for_spans(zipkin_client, 3, nil, trace_id)
+      local spans = wait_for_spans(zipkin_client, 3, nil, trace_id)
+      local balancer_span = assert(get_span("get (balancer try 1)", spans), "balancer span missing")
+      local request_span = assert(get_span("get", spans), "request span missing")
+      local proxy_span = assert(get_span("get (proxy)", spans), "proxy span missing")
 
       assert.equals(trace_id, request_span.traceId)
 
@@ -1232,8 +1276,10 @@ describe("http integration tests with zipkin server [#"
       })
       assert.response(r).has.status(404)
 
-      local proxy_span, request_span =
-        wait_for_spans(zipkin_client, 2, nil, trace_id)
+      local spans = wait_for_spans(zipkin_client, 2, nil, trace_id)
+      assert.is_nil(get_span("get (balancer try 1)", spans), "balancer span found")
+      local request_span = assert(get_span("get", spans), "request span missing")
+      local proxy_span = assert(get_span("get (proxy)", spans), "proxy span missing")
 
       assert.equals(trace_id, request_span.traceId)
       assert.equals(trace_id, proxy_span.traceId)
@@ -1353,10 +1399,12 @@ for _, strategy in helpers.each_strategy() do
       })
       assert.response(r).has.status(200)
 
-      local _, proxy_span, request_span =
-        wait_for_spans(zipkin_client, 3, service.name)
+      local spans = wait_for_spans(zipkin_client, 3, service.name)
+      local request_span = assert(get_span("get", spans), "request span missing")
+      local proxy_span = assert(get_span("get (proxy)", spans), "proxy span missing")
+
       -- common assertions for request_span and proxy_span
-      assert_span_invariants(request_span, proxy_span, "get", traceid_byte_count * 2, start_s, "kong", "tags")
+      assert_span_invariants(request_span, proxy_span, traceid_byte_count * 2, start_s, "kong", "tags")
     end)
 
     it("generates spans, tags and annotations for regular requests (#grpc)", function()
@@ -1375,10 +1423,12 @@ for _, strategy in helpers.each_strategy() do
       assert(ok, resp)
       assert.truthy(resp)
 
-      local _, proxy_span, request_span =
-        wait_for_spans(zipkin_client, 3, grpc_service.name)
+      local spans = wait_for_spans(zipkin_client, 3, grpc_service.name)
+      local request_span = assert(get_span("post", spans), "request span missing")
+      local proxy_span = assert(get_span("post (proxy)", spans), "proxy span missing")
+
       -- common assertions for request_span and proxy_span
-      assert_span_invariants(request_span, proxy_span, "post", traceid_byte_count * 2, start_s, "kong", "tags")
+      assert_span_invariants(request_span, proxy_span, traceid_byte_count * 2, start_s, "kong", "tags")
     end)
 
     it("generates spans, tags and annotations for regular #stream requests", function()
@@ -1392,8 +1442,9 @@ for _, strategy in helpers.each_strategy() do
 
       assert(tcp:close())
 
-      local _, proxy_span, request_span =
-        wait_for_spans(zipkin_client, 3, tcp_service.name)
+      local spans = wait_for_spans(zipkin_client, 3, tcp_service.name)
+      local request_span = assert(get_span("stream", spans), "request span missing")
+      local proxy_span = assert(get_span("stream (proxy)", spans), "proxy span missing")
 
       -- request span
       assert.same("table", type(request_span))