Eventing: Lost events due to 502 Bad Gateway error

[cardil]

Describe the bug
Continuously feeding events to broker with reasonable rate (10 msec interval) with Knative Service configured (by eventing trigger) to receive them I regularly see about 2% loss of events if knative service is scaled to zero (sometimes it passes).

I was using default eventing broker, which by default uses in memory channel. I see the events are lost in default-broker-filter pod logs (full logs in attachment):

{"level":"warn","ts":1578062528.6414907,"logger":"fallback","caller":"http/transport.go:502","msg":"got an error from receiver fn","error":"error sending cloudevent: 502 Bad Gateway"}
{"level":"warn","ts":1578062528.641511,"logger":"fallback","caller":"http/transport.go:594","msg":"error returned from invokeReceiver","error":"error sending cloudevent: 502 Bad Gateway"}

Also, I see related errors in activator pod (full logs in attachment):

{"level":"info","ts":"2020-01-03T14:42:07.525Z","logger":"activator","caller":"net/throttler.go:244","msg":"Updating Revision Throttler with: clusterIP = \"\", trackers = 0, backends = 0 activator pos 0/1","knative.dev/controller":"activator","knative.dev/pod":"activator-947bd7448-9mxxv","knative.dev/key":"event-example/wathola-forwarder-d96jq"}
{"level":"info","ts":"2020-01-03T14:42:07.525Z","logger":"activator","caller":"net/throttler.go:230","msg":"Set capacity to 0 (backends: 0, index: 0/1)","knative.dev/controller":"activator","knative.dev/pod":"activator-947bd7448-9mxxv","knative.dev/key":"event-example/wathola-forwarder-d96jq"}
{"level":"info","ts":"2020-01-03T14:42:08.031Z","logger":"activator","caller":"net/throttler.go:244","msg":"Updating Revision Throttler with: clusterIP = \"\", trackers = 1, backends = 1 activator pos 0/1","knative.dev/controller":"activator","knative.dev/pod":"activator-947bd7448-9mxxv","knative.dev/key":"event-example/wathola-forwarder-d96jq"}
{"level":"info","ts":"2020-01-03T14:42:08.031Z","logger":"activator","caller":"net/throttler.go:230","msg":"Set capacity to 1000 (backends: 1, index: 0/1)","knative.dev/controller":"activator","knative.dev/pod":"activator-947bd7448-9mxxv","knative.dev/key":"event-example/wathola-forwarder-d96jq"}
{"level":"error","ts":"2020-01-03T14:42:08.615Z","logger":"activator","caller":"network/error_handler.go:31","msg":"error reverse proxying request; sockstat: sockets: used 2181\nTCP: inuse 1145 orphan 41 tw 494 alloc 3538 mem 2947\nUDP: inuse 0 mem 35\nUDPLITE: inuse 0\nRAW: inuse 0\nFRAG: inuse 0 memory 0\n","knative.dev/controller":"activator","knative.dev/pod":"activator-947bd7448-9mxxv","knative.dev/key":"event-example/wathola-forwarder-d96jq","error":"read tcp 10.128.4.9:56452->10.131.0.14:8012: read: connection reset by peer","stacktrace":"knative.dev/serving/pkg/network.ErrorHandler.func1\n\t/opt/app-root/src/go/src/knative.dev/serving/pkg/network/error_handler.go:31\nnet/http/httputil.(*ReverseProxy).ServeHTTP\n\t/usr/lib/golang/src/net/http/httputil/reverseproxy.go:251\nknative.dev/serving/pkg/activator/handler.(*activationHandler).proxyRequest\n\t/opt/app-root/src/go/src/knative.dev/serving/pkg/activator/handler/handler.go:155\nknative.dev/serving/pkg/activator/handler.(*activationHandler).ServeHTTP.func1\n\t/opt/app-root/src/go/src/knative.dev/serving/pkg/activator/handler/handler.go:105\nknative.dev/serving/pkg/activator/net.(*revisionThrottler).try.func1\n\t/opt/app-root/src/go/src/knative.dev/serving/pkg/activator/net/throttler.go:177\nknative.dev/serving/pkg/activator/net.(*infiniteBreaker).Maybe\n\t/opt/app-root/src/go/src/knative.dev/serving/pkg/activator/net/throttler.go:630\nknative.dev/serving/pkg/activator/net.(*revisionThrottler).try\n\t/opt/app-root/src/go/src/knative.dev/serving/pkg/activator/net/throttler.go:168\nknative.dev/serving/pkg/activator/net.(*Throttler).Try\n\t/opt/app-root/src/go/src/knative.dev/serving/pkg/activator/net/throttler.go:419\nknative.dev/serving/pkg/activator/handler.(*activationHandler).ServeHTTP\n\t/opt/app-root/src/go/src/knative.dev/serving/pkg/activator/handler/handler.go:95\nknative.dev/serving/pkg/activator/handler.(*RequestEventHandler).ServeHTTP\n\t/opt/app-root/src/go/src/knative.dev/serving/pkg/activator/handler/requestevent_handler.go:67\nknative.dev/serving/vendor/go.opencensus.io/plugin/ochttp.(*Handler).ServeHTTP\n\t/opt/app-root/src/go/src/knative.dev/serving/vendor/go.opencensus.io/plugin/ochttp/server.go:86\nknative.dev/serving/pkg/activator/config.(*storeMiddleware).ServeHTTP\n\t/opt/app-root/src/go/src/knative.dev/serving/pkg/activator/config/store.go:83\nknative.dev/serving/pkg/http.(*RequestLogHandler).ServeHTTP\n\t/opt/app-root/src/go/src/knative.dev/serving/pkg/http/request_log.go:135\nknative.dev/serving/pkg/activator/handler.(*ProbeHandler).ServeHTTP\n\t/opt/app-root/src/go/src/knative.dev/serving/pkg/activator/handler/probe_handler.go:41\nknative.dev/serving/pkg/activator/handler.(*HealthHandler).ServeHTTP\n\t/opt/app-root/src/go/src/knative.dev/serving/pkg/activator/handler/healthz_handler.go:38\nknative.dev/serving/pkg/network.(*handler).ServeHTTP\n\t/opt/app-root/src/go/src/knative.dev/serving/pkg/network/probe_handler.go:40\nknative.dev/serving/pkg/activator/handler.(*MetricHandler).ServeHTTP\n\t/opt/app-root/src/go/src/knative.dev/serving/pkg/activator/handler/metric_handler.go:91\nknative.dev/serving/vendor/golang.org/x/net/http2/h2c.h2cHandler.ServeHTTP\n\t/opt/app-root/src/go/src/knative.dev/serving/vendor/golang.org/x/net/http2/h2c/h2c.go:98\nnet/http.serverHandler.ServeHTTP\n\t/usr/lib/golang/src/net/http/server.go:2802\nnet/http.(*conn).serve\n\t/usr/lib/golang/src/net/http/server.go:1890"}
{"level":"error","ts":"2020-01-03T14:42:08.615Z","logger":"activator","caller":"network/error_handler.go:31","msg":"error reverse proxying request; sockstat: sockets: used 2178\nTCP: inuse 1145 orphan 41 tw 494 alloc 3535 mem 2947\nUDP: inuse 0 mem 35\nUDPLITE: inuse 0\nRAW: inuse 0\nFRAG: inuse 0 memory 0\n","knative.dev/controller":"activator","knative.dev/pod":"activator-947bd7448-9mxxv","knative.dev/key":"event-example/wathola-forwarder-d96jq","error":"read tcp 10.128.4.9:56414->10.131.0.14:8012: read: connection reset by peer","stacktrace":"knative.dev/serving/pkg/network.ErrorHandler.func1\n\t/opt/app-root/src/go/src/knative.dev/serving/pkg/network/error_handler.go:31\nnet/http/httputil.(*ReverseProxy).ServeHTTP\n\t/usr/lib/golang/src/net/http/httputil/reverseproxy.go:251\nknative.dev/serving/pkg/activator/handler.(*activationHandler).proxyRequest\n\t/opt/app-root/src/go/src/knative.dev/serving/pkg/activator/handler/handler.go:155\nknative.dev/serving/pkg/activator/handler.(*activationHandler).ServeHTTP.func1\n\t/opt/app-root/src/go/src/knative.dev/serving/pkg/activator/handler/handler.go:105\nknative.dev/serving/pkg/activator/net.(*revisionThrottler).try.func1\n\t/opt/app-root/src/go/src/knative.dev/serving/pkg/activator/net/throttler.go:177\nknative.dev/serving/pkg/activator/net.(*infiniteBreaker).Maybe\n\t/opt/app-root/src/go/src/knative.dev/serving/pkg/activator/net/throttler.go:630\nknative.dev/serving/pkg/activator/net.(*revisionThrottler).try\n\t/opt/app-root/src/go/src/knative.dev/serving/pkg/activator/net/throttler.go:168\nknative.dev/serving/pkg/activator/net.(*Throttler).Try\n\t/opt/app-root/src/go/src/knative.dev/serving/pkg/activator/net/throttler.go:419\nknative.dev/serving/pkg/activator/handler.(*activationHandler).ServeHTTP\n\t/opt/app-root/src/go/src/knative.dev/serving/pkg/activator/handler/handler.go:95\nknative.dev/serving/pkg/activator/handler.(*RequestEventHandler).ServeHTTP\n\t/opt/app-root/src/go/src/knative.dev/serving/pkg/activator/handler/requestevent_handler.go:67\nknative.dev/serving/vendor/go.opencensus.io/plugin/ochttp.(*Handler).ServeHTTP\n\t/opt/app-root/src/go/src/knative.dev/serving/vendor/go.opencensus.io/plugin/ochttp/server.go:86\nknative.dev/serving/pkg/activator/config.(*storeMiddleware).ServeHTTP\n\t/opt/app-root/src/go/src/knative.dev/serving/pkg/activator/config/store.go:83\nknative.dev/serving/pkg/http.(*RequestLogHandler).ServeHTTP\n\t/opt/app-root/src/go/src/knative.dev/serving/pkg/http/request_log.go:135\nknative.dev/serving/pkg/activator/handler.(*ProbeHandler).ServeHTTP\n\t/opt/app-root/src/go/src/knative.dev/serving/pkg/activator/handler/probe_handler.go:41\nknative.dev/serving/pkg/activator/handler.(*HealthHandler).ServeHTTP\n\t/opt/app-root/src/go/src/knative.dev/serving/pkg/activator/handler/healthz_handler.go:38\nknative.dev/serving/pkg/network.(*handler).ServeHTTP\n\t/opt/app-root/src/go/src/knative.dev/serving/pkg/network/probe_handler.go:40\nknative.dev/serving/pkg/activator/handler.(*MetricHandler).ServeHTTP\n\t/opt/app-root/src/go/src/knative.dev/serving/pkg/activator/handler/metric_handler.go:91\nknative.dev/serving/vendor/golang.org/x/net/http2/h2c.h2cHandler.ServeHTTP\n\t/opt/app-root/src/go/src/knative.dev/serving/vendor/golang.org/x/net/http2/h2c/h2c.go:98\nnet/http.serverHandler.ServeHTTP\n\t/usr/lib/golang/src/net/http/server.go:2802\nnet/http.(*conn).serve\n\t/usr/lib/golang/src/net/http/server.go:1890"}
{"level":"error","ts":"2020-01-03T14:42:08.615Z","logger":"activator","caller":"network/error_handler.go:31","msg":"error reverse proxying request; sockstat: sockets: used 2178\nTCP: inuse 1145 orphan 41 tw 494 alloc 3535 mem 2947\nUDP: inuse 0 mem 35\nUDPLITE: inuse 0\nRAW: inuse 0\nFRAG: inuse 0 memory 0\n","knative.dev/controller":"activator","knative.dev/pod":"activator-947bd7448-9mxxv","knative.dev/key":"event-example/wathola-forwarder-d96jq","error":"read tcp 10.128.4.9:56428->10.131.0.14:8012: read: connection reset by peer","stacktrace":"knative.dev/serving/pkg/network.ErrorHandler.func1\n\t/opt/app-root/src/go/src/knative.dev/serving/pkg/network/error_handler.go:31\nnet/http/httputil.(*ReverseProxy).ServeHTTP\n\t/usr/lib/golang/src/net/http/httputil/reverseproxy.go:251\nknative.dev/serving/pkg/activator/handler.(*activationHandler).proxyRequest\n\t/opt/app-root/src/go/src/knative.dev/serving/pkg/activator/handler/handler.go:155\nknative.dev/serving/pkg/activator/handler.(*activationHandler).ServeHTTP.func1\n\t/opt/app-root/src/go/src/knative.dev/serving/pkg/activator/handler/handler.go:105\nknative.dev/serving/pkg/activator/net.(*revisionThrottler).try.func1\n\t/opt/app-root/src/go/src/knative.dev/serving/pkg/activator/net/throttler.go:177\nknative.dev/serving/pkg/activator/net.(*infiniteBreaker).Maybe\n\t/opt/app-root/src/go/src/knative.dev/serving/pkg/activator/net/throttler.go:630\nknative.dev/serving/pkg/activator/net.(*revisionThrottler).try\n\t/opt/app-root/src/go/src/knative.dev/serving/pkg/activator/net/throttler.go:168\nknative.dev/serving/pkg/activator/net.(*Throttler).Try\n\t/opt/app-root/src/go/src/knative.dev/serving/pkg/activator/net/throttler.go:419\nknative.dev/serving/pkg/activator/handler.(*activationHandler).ServeHTTP\n\t/opt/app-root/src/go/src/knative.dev/serving/pkg/activator/handler/handler.go:95\nknative.dev/serving/pkg/activator/handler.(*RequestEventHandler).ServeHTTP\n\t/opt/app-root/src/go/src/knative.dev/serving/pkg/activator/handler/requestevent_handler.go:67\nknative.dev/serving/vendor/go.opencensus.io/plugin/ochttp.(*Handler).ServeHTTP\n\t/opt/app-root/src/go/src/knative.dev/serving/vendor/go.opencensus.io/plugin/ochttp/server.go:86\nknative.dev/serving/pkg/activator/config.(*storeMiddleware).ServeHTTP\n\t/opt/app-root/src/go/src/knative.dev/serving/pkg/activator/config/store.go:83\nknative.dev/serving/pkg/http.(*RequestLogHandler).ServeHTTP\n\t/opt/app-root/src/go/src/knative.dev/serving/pkg/http/request_log.go:135\nknative.dev/serving/pkg/activator/handler.(*ProbeHandler).ServeHTTP\n\t/opt/app-root/src/go/src/knative.dev/serving/pkg/activator/handler/probe_handler.go:41\nknative.dev/serving/pkg/activator/handler.(*HealthHandler).ServeHTTP\n\t/opt/app-root/src/go/src/knative.dev/serving/pkg/activator/handler/healthz_handler.go:38\nknative.dev/serving/pkg/network.(*handler).ServeHTTP\n\t/opt/app-root/src/go/src/knative.dev/serving/pkg/network/probe_handler.go:40\nknative.dev/serving/pkg/activator/handler.(*MetricHandler).ServeHTTP\n\t/opt/app-root/src/go/src/knative.dev/serving/pkg/activator/handler/metric_handler.go:91\nknative.dev/serving/vendor/golang.org/x/net/http2/h2c.h2cHandler.ServeHTTP\n\t/opt/app-root/src/go/src/knative.dev/serving/vendor/golang.org/x/net/http2/h2c/h2c.go:98\nnet/http.serverHandler.ServeHTTP\n\t/usr/lib/golang/src/net/http/server.go:2802\nnet/http.(*conn).serve\n\t/usr/lib/golang/src/net/http/server.go:1890"}

Expected behavior
Events should not be lost, at least until in memory channel do not crash.

To Reproduce

Preparation of Openshift 4.2 (should be similar on other vendors):

1. Run OCP 4.2 and have oc logged in as admin
2. Checkout repo: git clone --branch v0.1.0 https://github.com/cardil/eventing-upgrade-scratchpad.git
3. Run oc apply -f install/eventing-openshift.yaml
4. Wait until oc get clusterserviceversion -n openshift-operators report succeeded for all operators
5. Run oc apply -f install/eventing-cr.yaml
6. Wait until oc get knativeserving/knative-serving -n knative-serving --template='{{range .status.conditions}}{{printf "%s=%s\n" .type .status}}{{end}}' and oc get knativeeventing/knative-eventing -n knative-eventing --template='{{range .status.conditions}}{{printf "%s=%s\n" .type .status}}{{end}}' reports as Ready
7. Run oc apply -f install/event-example.yaml
8. Wait until oc get broker default -n event-example reports Ready

Reproduction:

1. Run for y in tests/config.yaml tests/trigger.yaml tests/receiver.yaml tests/forwarder.yaml; do oc apply -f $y; done
2. Wait until oc get deployment $(oc get ksvc -n event-example -o jsonpath='{.items[0].status.latestCreatedRevisionName}')-deployment -n event-example report that Knative Service scaled to zero READY: 0/0
3. Run oc apply -f tests/sender.yaml and wait until forwarder pods scale up READY: 14/14

4. Run oc delete -f tests/sender.yaml. Receiver pod should receive finished event and report state. You should observe missing events. Sometimes this pass, in that case delete receiver pod (deployment will recreate it) and reperform from step 2 of reproduction.

   Knative release version
   0.10.x

   Additional context
   Priority: medium.

[mikehelmick]

Related to #2210 ?

[cardil]

Kinda. But retry actually will hide this bug. I think we should not get 502 error in first place.

[cardil]

This issue was confirmed on GCP with code in master in this PR #2388 latest build
https://prow.knative.dev/view/gcs/knative-prow/pr-logs/pull/knative_eventing/2388/pull-knative-eventing-integration-tests/1217883556135571456

[grantr]

I formatted one of those reverse proxy error messages from the activator into a gist here in case that helps anyone gain insight: https://gist.github.com/grantr/86c77b6627e459edb4cdcc6337b45f4d.

Naively, it seems that a 502 indicates a problem with the connection between the activator and the revision pod. A 502 response in this case seems like a bug (in serving) because normally the revision timeout is on the order of minutes, not seconds. @cardil do you have any idea how long those requests waited before getting a 502 response?

[cardil]

I don't know. But, Openshift has now a known performance regression that couse scale from zero time to be around ~10 sec.

But that isn't the case on GCP I believe. Also minikube also spins from zero fast (under a second).

I've managed to reproduce those errors on minikube with 2msec intervals, today, if I remember correctly.

I think that having more then 1 worker node is helpful in reproduction of those errors.

Tomorrow I will try to debug this more.

[cardil]

I've manage to reproduce errors from PR #2388 on a GCP Kubernetes cluster identical to the one used in Prow.

Below are test results. There ware 10 lost events, 505 total.

I think it might be different cause as I didn't seen there any 502 Bad Gateway errors from activator.

I've published logs (with log level "error" only) here: https://gist.github.com/cardil/1a334495c551fba6300c14ae812d5f01. There are a lot of logs there, I advise to download a ZIP

[grantr]

/label proposal/0.13

[owenthereal]

I just met this error with the same exact error message and stacktrace as mentioned in https://github.com/knative/eventing/issues/2357#issuecomment-575376198. Any update on this?

[grantr]

We just saw a 502 error in tests that seems similar (https://github.com/knative/eventing/issues/3240)

[github-actions[bot]]

This issue is stale because it has been open for 90 days with no
activity. It will automatically close after 30 more days of
inactivity. Reopen the issue with /reopen. Mark the issue as
fresh by adding the comment /remove-lifecycle stale.

[devguyio]

I'd like to work on this
/assign

[devguyio]

/remove-lifecycle stale

[devguyio]

Upgrade Events Loss

The main reason behind this is that the dispatcher can lose events while dispatching if a network error occurs and the dispatcher is in the fire-and-forget mode (the default mode unless retries are configured).
During upgrade the filter pod gets a rolling update and while the event gets published in the channel, there can be a time when the broker filter pod is unreachable and the dispatcher loses the event (see above)
Following trace shows the above mentioned scenario

Kafka Channel Guarantees

Given the current KafkaChannel, with no subscriber based offset, it is impossible to provide at least once delivery guarantees. Retries and dead letter queue are our best options until this issue is addressed knative-sandbox/eventing-kafka#118

Upgrade Test Retries

I added delivery retry to upstream upgrade tests which should make the event loss less likely to happen. Gonna keep an eye on it. #4353

[grantr]

the dispatcher is in the fire-and-forget mode (the default mode unless retries are configured)

Was this an intentional default? Seems to me like the default should lean toward safety, with the more dangerous mode being an explicit choice by the user.

[vaikas]

It was mainly my bad. A long time ago in a galaxy far away, there were too many retries which would mask bugs. So, just like I feel like flaky tests shouldn't be retried, I felt that we should not be retrying around flaky things as a default mode of operation. Now, I feel like we've gotten to a point of much better stability and we _know_ there are cases where things with IMC will get dropped, so having a retry during the upgrade tests makes sense to me.

[lionelvillard]

I agree with @grantr. IMO, the broker implementation should be fixed not the test. An alternative is to make the test configurable and remove the delivery spec for brokers inherently supporting lossless upgrade.

[grantr]

Just to confirm I understand @vaikas, you are saying that you disabled retries in the IMC _during the test_ to increase test sensitivity.

IIUC, @devguyio's research is about something slightly different: The KafkaChannel is implemented so that retry is disabled _in production_ unless explicitly configured.

I'm most concerned about the apparent usability issue if users are expecting the KafkaChannel to retry by default but it does not.

[Ahmed]

Yes?

On Thu, Oct 22, 2020, 16:00 Grant Rodgers [e-mail] wrote:

Just to confirm I understand @vaikas https://github.com/vaikas, you are
saying that you disabled retries in the IMC during the test to increase
test sensitivity.

IIUC, @Ahmed https://github.com/Ahmed's research is about something
slightly different: The KafkaChannel is implemented so that retry is
disabled in production unless explicitly configured.

I'm most concerned about the apparent usability issue if users are
expecting the KafkaChannel to retry by default but it does not.

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
https://github.com/knative/eventing/issues/2357#issuecomment-714728407,
or unsubscribe
https://github.com/notifications/unsubscribe-auth/AAEDHC33BRRSEATVJNDXTOLSMCFOLANCNFSM4KD5FNQQ
.

[grantr]

Sorry @ahmed I accidentally used a slack username as a github username... Please ignore 😅

[vaikas]

@grantr Yes that's what was saying. However, maybe we're mixing a few issues here together. One is adding retries for our upgrade tests and one is the prod config.
I'm just saying that we have found quite a few underlying bugs that would've been masked by retries in the past. Also saying that there are cases where we know there will be failures with say IMC as is, so for the upgrade tests seems totally reasonable to enable retries for them. Not sure if this is clarifying or just further confusing the matter :)

[cardil]

In my opinion default implementation should be resilient. Pods may be rescheduled at any time, so retry should always be the case, by default.

If we feel cocky we can run our tests without retries, but that should be not binding. Currently, it's like that. As any error in event propagation will cause test being skipped. But, apart from that there should be "production" test running with greater load (10msec https://github.com/knative/eventing/blob/2a052db/test/upgrade/prober/prober.go#L31-L33), and retries enabled.

There's also an issue of visibility. Clearly something need to be done, as it's took us as Knative authors many months to pinpoint the issue. If event is dropped, that should be noticed easily, so users can debug. Log such event, write a docs about how to find missing events, maybe create K8s event?!?

[vaikas]

I don't view it as being cocky, but just the exact opposite. When I dug into some of these failures they seemed like real bugs and I did not want to mask them by retrying and making them pass.

I don't understand "that should be not binding" about the tests.

Regarding the visibility absolutely there are gabs in visibility, with Positive Ville talking here, this has been a great motivator to improve some of these short comings, and things have certainly improved. @devguyio has offered to write up more improvement docs so that should improve things also.

But, I also feel like there are multiple issues being mixed in here as well in this issue, so perhaps we should / could open separate issues for them rather than tackle them all into this thread?

[lionelvillard]

FWIW, PingSource creates a k8s event when an CE event couldn't be sent after X retries.

[github-actions[bot]]

This issue is stale because it has been open for 90 days with no
activity. It will automatically close after 30 more days of
inactivity. Reopen the issue with /reopen. Mark the issue as
fresh by adding the comment /remove-lifecycle stale.