Logging: issues with out-of-sync clocks

[crazystick]

I have a couple of related issues with timestamps for Stackdriver logging. I want to log data from devices that might have unreliable clocks but the receiveTimestamp and timestamp fields are always identical to the nanosecond and if the clock is behind then logging seems to fail with errors

Retrying due to 504 Deadline Exceeded, sleeping 0.1s  

Environment details

Linux 5.1.5 + libfaketime
python 3.7.3
google-cloud-logging 1.11.0

Steps to reproduce

1. Write a log entry using the log handler from a client with a date in the future

Code example

class TestLogger:
    def __init__(self):
        logging.debug("starting up")
        os.environ['GOOGLE_APPLICATION_CREDENTIALS'] = '/creds.json'

        self.logging_client = gcplogging.Client()
        cloud_handler = CloudLoggingHandler(self.logging_client,
                                            name='testlog',
                                            resource=gcplogging.resource.Resource(
                                                type='generic_node',
                                                labels={'location': 'us-central', 'namespace': 'xxx', 'node_id': 'yyy'}),
                                            labels={'guid': 'xxxxxx-...})

        cloud_handler.setLevel(logging.DEBUG)
        setup_logging(cloud_handler)
        logging.getLogger().setLevel(logging.DEBUG)  # this is overwritten by setup_logging fn

    def log_something(self, message):
        logging.info(message)


if __name__ == '__main__':
    test_logger = TestLogger()
    test_logger.log_something("testing 123")

Run using libfaketime:

LD_PRELOAD=/lib/faketime/libfaketime.so.1 FAKETIME="+2m" venv/bin/python logger.py

Console Output

2019-06-05 08:07:20,954 root         DEBUG    starting up
2019-06-05 08:07:20,956 google.cloud.logging.handlers.transports.background_thread DEBUG    Background thread started.
2019-06-05 08:07:20,956 root         INFO     testing 123
testing 123
Waiting up to 5 seconds.
Making request: POST https://accounts.google.com/o/oauth2/token
2019-06-05 08:07:21,181 urllib3.connectionpool DEBUG    Starting new HTTPS connection (1): accounts.google.com:443
Starting new HTTPS connection (1): accounts.google.com:443
2019-06-05 08:07:21,409 urllib3.connectionpool DEBUG    https://accounts.google.com:443 "POST /o/oauth2/token HTTP/1.1" 200 None
https://accounts.google.com:443 "POST /o/oauth2/token HTTP/1.1" 200 None
Submitted 1 logs
Submitted 2 logs
Background thread exited gracefully.
Sent all pending logs.

Log Entry

{
 insertId:  "184n0cvfww1xkt"  
 jsonPayload: {…}  
 labels: {…}  
 logName:  "projects/my-project/logs/testlog"  
 receiveTimestamp:  "2019-06-05T07:05:21.429948191Z"  
 resource: {…}  
 severity:  "INFO"  
 timestamp:  "2019-06-05T07:05:21.429948191Z"  
}

[tseaver]

@crazystick Thanks for the report. Can you please show the full traceback for the error? Also, how are you getting to the LogEntry you show? The receiveTimestamp field is normally populated only by the server, so it seems as though the logging call is getting through.

FWIW, timestamp will be identical to it unless you've arranged to set it client side (which your example doesn't do). I don't believe that has anything to do with the 504 you are seeing.

[crazystick]

Hi @tseaver as you say, the log entry did make it to Stackdriver Logging - the first issue was really that the timestamp is not set by the default handler - which my PR #8227 addresses. I will try to investigate the 504 error which happens when the clock is lagging behind real time and maybe open a separate issue to keep things simple.

[tseaver]

@crazystick Great, thanks. Please do post the traceback for the 504 error in the new issue.