Why does Google Cloud logging show response of 200 while also tagging log entry as error?

Question

Below is a screenshot from Google Cloud console logging. It shows an error while calling /get_user from my server. However the response status is 200 which should mean SUCCESS. How is this possible? Also what is the actual error? None of the lines below give anything remotely resembling an error message.

{
 httpRequest: {
  status:  200   
 }
 insertId:  "59f27485000f32ab85505e70"  
 labels: {
  clone_id:  "00c61b117c384e485a095752c23b4277d1844399c104ae542bd367f2b52df046b21a56584c7d"   
 }
 logName:  "projects/villagethegame111/logs/appengine.googleapis.com%2Frequest_log"  
 operation: {
  first:  true   
  id:  "59f2748500ff00ff5dbae8f3b5ad0001737e76696c6c61676574686567616d65313131000170726f643230313730393233000100"   
  last:  true   
  producer:  "appengine.googleapis.com/request_id"   
 }
 protoPayload: {
  @type:  "type.googleapis.com/google.appengine.logging.v1.RequestLog"   
  appEngineRelease:  "1.9.54"   
  appId:  "s~villagethegame111"   
  cost:  8.0801e-8   
  endTime:  "2017-10-26T23:49:25.076502Z"   
  finished:  true   
  first:  true   
  host:  "villagethegame111.appspot.com"   
  httpVersion:  "HTTP/1.1"   
  instanceId:  "00c61b117c384e485a095752c23b4277d1844399c104ae542bd367f2b52df046b21a56584c7d"   
  instanceIndex:  -1   
  ip:  "38.102.224.170"   
  latency:  "0.052508s"   
  line: [
   0: {
    logMessage:  "200 OK"     
    severity:  "ERROR"     
    time:  "2017-10-26T23:49:25.068980Z"     
   }
  ]
  megaCycles:  "29"   
  method:  "GET"   
  requestId:  "59f2748500ff00ff5dbae8f3b5ad0001737e76696c6c61676574686567616d65313131000170726f643230313730393233000100"   
  resource:  "/api/get_user"   
  responseSize:  "272"   
  startTime:  "2017-10-26T23:49:25.023994Z"   
  status:  200   
  urlMapEntry:  "village.api.root"   
  userAgent:  "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/61.0.3163.100 Safari/537.36"   
  versionId:  "prod20170923"   
 }
 receiveTimestamp:  "2017-10-26T23:49:26.000113484Z"  
 resource: {
  labels: {
   module_id:  "default"    
   project_id:  "villagethegame111"    
   version_id:  "prod20170923"    
   zone:  "us14"    
  }
  type:  "gae_app"   
 }
 severity:  "ERROR"  
 timestamp:  "2017-10-26T23:49:25.023994Z"  
}

score 3 · Answer 1 · answered Oct 27 '17 at 03:01

This can be perfectly normal if the respective request log also has an app log at the ERROR level attached to it, created by your application code during handling of the request. And as long as the app is able to formulate a response to the request, of course. The request log will be tagged with the "worst" logging level across all app logs attached to it.

Just scroll down a bit more on the page pictured in your snapshot to see if there are app logs attached to that request log.

You can see an illustration of this (with logging level INFO, not ERROR) in Reading Application Logs on Google App Engine from Developer Console.

See also: Request logs vs application logs

score 2 · Answer 2 · answered Oct 27 '17 at 13:46

The double exclamation mark icon !! usually^* signifies that than a log message with log level 'Error' has been logged during the request.

The fact that such a message has been logged does not necessarily mean that the response will have an error status code (500). Within the request handling code an error situation could be encountered, logged, and handled, so the request still succeeds even though an error-level message was logged. For example:

class Handler(webapp2.RequestHandler):

    def get(self):
        foo = request.get('foo')
        try:
            upper_foo = foo.upper()
        except AttributeError:
            # foo could be None
            logging.error('Invalid foo: %r', foo)   
            upper_foo = ''
        self.response.write(upper_foo)

As Dan Cornilescu mentions in his answer, you should be able to see the logged message below the data shown in your screenshot.

^* Output from print statements and some warnings will also be logged as error-level messages.

Why does Google Cloud logging show response of 200 while also tagging log entry as error?

2 Answers2