Why do empty lines appear intermittently in Stackdriver logs?

Question

I'm running a cloud function every minute.

Blank lines (see logs below) appear in Stackdriver logs intermittently.

I don't believe this is due to the function code I have written.

Bug can be recreated with this main.py:

import logging

logger = logging.getLogger(__name__)
logger.setLevel(logging.INFO)
logger.info(f"Logging {__name__}")


def main(event, context):
    logger.info("Message 1")
    logger.info("Message 2")
    logger.info("Message 3")

This function emitted blanks lines within a couple hours when triggered every minute by Cloud Scheduler.

How can this issue be prevented?

Update: Added two expanded logs

{
 insertId: "000001-redacted-but-identical"  
 labels: {
  execution_id: "894004659398898"   
 }
 logName: "projects/redacted/logs/cloudfunctions.googleapis.com%2Fcloud-functions"  
 receiveTimestamp: "2019-12-13T23:05:01.545007423Z"  
 resource: {
  labels: {
   function_name: "recreate_blank_lines"    
   project_id: "redacted"    
   region: "us-central1"    
  }
  type: "cloud_function"   
 }
 severity: "INFO"  
 timestamp: "2019-12-13T23:05:00.344Z"  
 trace: "projects/redacted/traces/c4ed0267fd9fa4bf9133043bdfe5b1e0"  
}

{
 insertId: "000000-redacted-but-identical"  
 labels: {
  execution_id: "894004659398898"   
 }
 logName: "projects/redacted/logs/cloudfunctions.googleapis.com%2Fcloud-functions"  
 receiveTimestamp: "2019-12-13T23:05:01.545007423Z"  
 resource: {
  labels: {
   function_name: "recreate_blank_lines"    
   project_id: "redacted"    
   region: "us-central1"    
  }
  type: "cloud_function"   
 }
 severity: "INFO"  
 textPayload: "Message 2"  
 timestamp: "2019-12-13T23:05:00.345Z"  
 trace: "projects/redacted/traces/c4ed0267fd9fa4bf9133043bdfe5b1e0"

This sounds like a bug which can be handled by the GCP support team as they'll require further investigation on your issue. Use the following link "https://issuetracker.google.com" to get started — hachemon, Nov 22 '19 at 03:52
Submitted but it's been marked private. Will post results here. Was hoping someone else had solved this problem previously. — ProGirlXOXO, Dec 02 '19 at 21:51
Issuetracker has not been escalated or replied to in over a week. — ProGirlXOXO, Dec 11 '19 at 21:30
Can you expand the log entry so we can see the metadata that goes along with it (plus one of the "Message 3" entries for comparison)? — David, Dec 18 '19 at 21:11
Yes, though not sure which of those fields are sensitive if any — ProGirlXOXO, Dec 18 '19 at 21:15
@David Added two expanded logs. No textPayload is shown for the blank line. — ProGirlXOXO, Dec 18 '19 at 21:26

score 1 · Answer 1 · answered Dec 17 '19 at 17:48

1

In the meantime, you can add a filter to stackdriver to skip logs with empty strings.

answered Dec 17 '19 at 17:48

marcos

4,473
1
10
24

Thanks. If I add a filter like that it becomes a custom metric which is chargeable: https://cloud.google.com/stackdriver/pricing. Ideally this would not happen since I'm just trying to see that the INFO log count is consistent. – ProGirlXOXO Dec 18 '19 at 21:05
1

Oh, well in that case your only hope is that gcp support fixes this because this seems to be something they should handle. – marcos Dec 18 '19 at 21:10

score 0 · Answer 2 · answered Dec 18 '19 at 21:39

0

One possibility is that your code - or a library that you import - print()s a blank line to stdout or stderr as this is also soent to logs.

answered Dec 18 '19 at 21:39

David

9,288
1
20
52

Thanks, double checked. I'm not printing anywhere. – ProGirlXOXO Dec 19 '19 at 20:45

ProGirlXOXO · Accepted Answer · 2020-02-11T22:54:36.240

This issue seems to have disappeared for us as of 2020-02-03 13:44:20.476 PST

From support engineer on issuetracker.google.com

It seems like stackdriver is logging twice with one of the two logs having empty textpayload.

I also learnt that stackdriver will update their log delivery mechanism in Q1 2020, which will likely address this problem.

I will leave this isuee tracker as is for now. You will be notified when the issue is fixed in Q1 2020.

Why do empty lines appear intermittently in Stackdriver logs?

3 Answers3

Linked