<p>After following
<a href="https://cloud.google.com/endpoints/docs/openapi/get-started-kubernetes-engine" rel="nofollow noreferrer">Getting started with Cloud Endpoints on GKE</a> and <a href="https://cloud.google.com/endpoints/docs/openapi/get-started-kubernetes-engine#deploy_backend" rel="nofollow noreferrer">deploying the API and backend</a> everything <em>looks like</em> it's working (spoiler alert, it's not);</p>

<ul>
<li>My application's deployed on a cluster.</li>
<li>A single pod is deployed in Kubernetes.</li>
<li>The pod is running two containers (<a href="https://cloud.google.com/endpoints/docs/openapi/glossary#extensible_service_proxy" rel="nofollow noreferrer">ESP</a> and my GPRC service)

<ol>
<li><code>gcr.io/endpoints-release/endpoints-runtime:1</code></li>
<li><code>gcr.io/my-app/server:latest</code></li>
</ol></li>
</ul>

<p>...both are running; <code>kubectl get pods</code> yields:</p>

<pre><code>NAME                          READY   STATUS    RESTARTS   AGE
my-app-855d8447f-nnvz8        2/2     Running   0          24m
</code></pre>

<p><a href="https://github.com/GoogleCloudPlatform/endpoints-samples/issues/52" rel="nofollow noreferrer">Need improved/HTTPS-centric GKE Ingress + ESP + gRPC example</a> was very helpful in getting me this far.</p>

<p>Bad news; HTTP requests from my Angular app (running on <code>http://localhost:4200</code>) result in <strong>500 Internal Server Error</strong>.</p>

<p>I ran through <a href="https://cloud.google.com/endpoints/docs/openapi/troubleshoot-gke-deployment" rel="nofollow noreferrer">Troubleshooting Cloud Endpoints in GKE</a> and couldn't see anything that applied (there is nothing obviously wrong). </p>

<p>OK. Time to debug.</p>

<p>Looking at the ESP (Docker container) logs with <code>kubectl logs -f my-app-855d8447f-nnvz8 -c esp</code>, I can see the preflight request (<code>OPTIONS</code>) and subsequent HTTP <code>POST</code> request.</p>

<pre><code>INFO:Fetching an access token from the metadata service
INFO:Fetching the service config ID from the rollouts service
INFO:Fetching the service configuration from the service management service
INFO:Attribute zone: us-central1-a
INFO:Attribute project_id: my-cloud-project
INFO:Attribute kube_env: KUBE_ENV

nginx: [warn] Using trusted CA certificates file: /etc/nginx/trusted-ca-certificates.crt

143.159.55.199 - - [12/Jan/2020:17:34:11 +0000] "OPTIONS /v1/documents?key=Ei2ZvlV5zASIkuRf4LRl&amp;format=JSON&amp;showDefaults=false HTTP/1.1" 204 0 "http://localhost:4200/" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/79.0.3945.88 Safari/537.36"
143.159.55.199 - - [12/Jan/2020:17:34:11 +0000] "POST /v1/documents?key=Ei2ZvlV5zASIkuRf4LRl&amp;format=JSON&amp;showDefaults=false HTTP/1.1" 500 242 "http://localhost:4200/" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/79.0.3945.88 Safari/537.36"
</code></pre>

<p>The CORS (<code>OPTIONS</code>) request results in HTTP 204, however the <code>POST</code> request is HTTP 500. So there's clearly a problem here.</p>

<p>Despite plenty of logging, there are no logs in my grpc server; <code>kubectl logs -f my-app-855d8447f-nnvz8 -c server</code> yields nothing. So</p>

<ul>
<li>The Kubernetes pod is healthy and both containers arerunning.</li>
<li>The ESP is starting and successfully using the metadata service</li>
<li>CORS is working (it's wide-open while I'm developing)</li>
<li>The gRPC service is running but not being hit (no logs)</li>
</ul>

<p>Somewhere between CORS and POST HTTP requests, it's going wrong and the gRPC service never gets called.</p>

<p>I can't find any errors; How can I debug what's going on between ESP/nginx and my gRPC server?</p>

<p>For completeness, here's my deployment yaml (with added comments):</p>

<pre><code>apiVersion: extensions/v1beta1
kind: Deployment
metadata:
  name: my-app
  namespace: default
spec:
  replicas: 1
  template:
    metadata:
      labels:
        app: my-app
    spec:
      containers:
      - name: esp
        image: gcr.io/endpoints-release/endpoints-runtime:1
        # The default value for the backend address is http://127.0.0.1:8080
        args: [
          "--http_port=8081",

          # My gPRC service is running on port 8080 on the same VM.
          "--backend=grpc://127.0.0.1:8080",
          "--service=my-project.endpoints.my-project-dev.cloud.goog",
          "--rollout_strategy=managed",

          # Makes ESP return code 200 for location /healthz,
          # instead of forwarding the request to the backend.
          "--healthz=healthz",

          # Wide-open CORS during development.
          "--cors_preset=basic",
          "--cors_allow_origin=*",
        ]
        # HEALTH CHECK START
        # Used by ingress to perform health check
        readinessProbe:
          httpGet:
            path: /healthz
            port: 8081
        ports:
          - containerPort: 8081
        # HEALTH CHECK END
      - name: server
        image: gcr.io/my-project-dev/server:latest
        imagePullPolicy: Always
        ports:
          - containerPort: 8080
</code></pre>

<p>The CORS response headers from the ESP/nginx container are:</p>

<pre><code>Access-Control-Allow-Headers: DNT,User-Agent,X-Requested-With,If-Modified-Since,Cache-Control,Content-Type,Range,Authorization
Access-Control-Allow-Methods: GET, POST, PUT, PATCH, DELETE, OPTIONS
Access-Control-Allow-Origin: *
Access-Control-Expose-Headers: Content-Length,Content-Range
Content-Type: application/json
Date: Sun, 12 Jan 2020 17:34:11 GMT
Server: nginx
Transfer-Encoding: chunked
Via: 1.1 google
</code></pre>

<p>I don't expect anyone to magic-up an answer, but right now I'm unsure of how to debug this any further when everthing looks good?</p>

<p>A new day and a solution. I'll briefly explain the solution, but focus more on <em>how</em> I discovered it and what I would do differently.</p>

<p><strong>Problem</strong></p>

<p>The "Compute Engine default service account" was missing some permissions. <a href="https://cloud.google.com/endpoints/docs/openapi/get-started-kubernetes-engine" rel="nofollow noreferrer">Getting started with Cloud Endpoints on GKE</a> does <em>not</em> use Datastore. My app does. Simply going to IAM &amp; admin > IAM, and adding the "Cloud Datastore User" role to the service account fixed my problem.</p>

<p><strong>Lessons</strong></p>

<p><strong>1.</strong> Logging in <code>__init__</code> of the Python gPRC server doesn't provide as much cover as it seems. AFAICT, the main gRPC service module was being called/loaded in some way but the insufficient permissions meant <code>from google.cloud import datastore</code> prevented my Cloud log statements from being executed:</p>

<pre class="lang-py prettyprint-override"><code># This requires "Cloud Datastore User" role.
from google.cloud import datastore

class MyServer(myservice_pb2_grpc.MyServer):
    """Implements the GRPC interface to handle client calls."""

    def __init__(self):
        # Logging using CloudLoggingHandler was never executed.
        logger.info('__init__')

def serve():
    """Runs a gRPC server to handle client calls."""
    server = grpc.server(futures.ThreadPoolExecutor(max_workers=10))
    myservice_pb2_grpc.add_MyServiceServicer_to_server(MyServer(), server)

    # The default value for the backend address is http://127.0.0.1:8080
    server.add_insecure_port('[::]:8080')
    server.start()
    server.wait_for_termination()

if __name__ == '__main__':
    serve()
</code></pre>

<p><strong>2.</strong> While the Container logs did include a very helpful error message, it was hidden by the default Stackdriver filters:</p>

<pre><code>resource.type="container"
resource.labels.cluster_name="standard-cluster-2"
resource.labels.namespace_id="default"
resource.labels.project_id="my-project-dev"
resource.labels.zone:"us-central1-a"
resource.labels.container_name=("esp" OR "server")
resource.labels.pod_id="my-app-855d8447f-nnvz8"
</code></pre>

<p>Seeing my error required a <code>resource.type</code> of <code>api</code>. Moreover, only the <code>project_id</code> of the resource labels was relevant. I strongly recommend viewing <strong>api</strong> logs for your project. Don't just view <strong>container</strong> logs:</p>

<pre><code>resource.type="api"
resource.labels.project_id="json-schema-dev"
</code></pre>

<p>In my case, the exact error could be found with Stackdriver filters set to</p>

<pre><code>resource.type="api"
resource.labels.project_id="json-schema-dev"
jsonPayload.log_message:("Exception calling application: 403 Missing or insufficient permissions.")
</code></pre>

<p><strong>3.</strong> Given that I couldn't find the error in the Stackdriver logs, where did I find it? The browser console. The humble browser console. I was looking only at the network tab of the Developer Console, seeing the HTTP 500 response, and going straight to the Cloud Console. </p>

<p><strong>4.</strong> View the full error message. The error received by the browser may render as:</p>

<pre><code>headers: HttpHeaders {normalizedNames: Map(0), lazyUpdate: null, lazyInit: ƒ}
status: 500
statusText: "Internal Server Error"
url:"http://34.107.225.145/v1/documents:inferkey=123&amp;format=JSON&amp;showDefaults=false"
ok: false
name: "HttpErrorResponse"
message: "Http failure response for http://123.456.789.342 500 Internal Server Error".
error: {code: 2, message:...
</code></pre>

<p>I didn't expand the <code>error</code> property which was truncated with ellipsis. Upon expanding this I got:</p>

<pre><code>code: 2
message: "Exception calling application: 403 Missing or insufficient permissions."
</code></pre>

<p><strong>Summary</strong></p>

<ul>
<li>Logging in <code>__init__</code> may not be enough.

<ul>
<li>Consider logging in <code>serve()</code></li>
</ul></li>
<li>Merely importing a module for which you have insufficient permissions may prevent log statements from being executed.</li>
<li>Check <code>api</code> logs, not just <code>container</code> logs.

<ul>
<li>Kubernetes links to Container logs for convenience, but the default filters are decidedly inconvenient.</li>
</ul></li>
<li>Spend more time looking the client error, and don't be so quick to move to the server.

<ul>
<li>Expand the console error message as much as possible (go beyond the response code) </li>
</ul></li>
</ul>
