search

firebase / firebase-functions-python

Apache License 2.0
138 stars 23 forks source link

Sporadic datetime parse error #160

Closed jacobg closed 4 months ago

jacobg commented 1 year ago

The following error occurred once on my pubsub function. It's otherwise run fine hundreds of times without any issue.

Traceback (most recent call last):
  File "/layers/google.python.pip/pip/lib/python3.11/site-packages/flask/app.py", line 2190, in wsgi_app
    response = self.full_dispatch_request()
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/layers/google.python.pip/pip/lib/python3.11/site-packages/flask/app.py", line 1486, in full_dispatch_request
    rv = self.handle_user_exception(e)
         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/layers/google.python.pip/pip/lib/python3.11/site-packages/flask/app.py", line 1484, in full_dispatch_request
    rv = self.dispatch_request()
         ^^^^^^^^^^^^^^^^^^^^^^^
  File "/layers/google.python.pip/pip/lib/python3.11/site-packages/flask/app.py", line 1469, in dispatch_request
    return self.ensure_sync(self.view_functions[rule.endpoint])(**view_args)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/layers/google.python.pip/pip/lib/python3.11/site-packages/functions_framework/__init__.py", line 174, in view_func
    function(event)
  File "/layers/google.python.pip/pip/lib/python3.11/site-packages/firebase_functions/pubsub_fn.py", line 184, in on_message_published_wrapped
    return _message_handler(func, raw)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/layers/google.python.pip/pip/lib/python3.11/site-packages/firebase_functions/pubsub_fn.py", line 108, in _message_handler
    time = _dt.datetime.strptime(
           ^^^^^^^^^^^^^^^^^^^^^^
  File "/layers/google.python.runtime/python/lib/python3.11/_strptime.py", line 568, in _strptime_datetime
    tt, fraction, gmtoff_fraction = _strptime(data_string, format)
                                    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/layers/google.python.runtime/python/lib/python3.11/_strptime.py", line 349, in _strptime
    raise ValueError("time data %r does not match format %r" %
ValueError: time data '2023-11-13T12:30:23Z' does not match format '%Y-%m-%dT%H:%M:%S.%f%z'

Why would that occur?

antont commented 1 year ago

are you using the latest release? https://github.com/firebase/firebase-functions-python/pull/149

jacobg commented 1 year ago 
firebase_functions~=0.1.1

Oh, does 0.1.2 fix this issue? https://github.com/firebase/firebase-functions-python/pull/137/files

jacobg commented 1 year ago

Not sure it's fixed, but checking.... The issue you linked is for firestore, but my error is in pubsub function.

jacobg commented 1 year ago

From examining the firebase-functions-python code and commits, it doesn't seem fixed but maybe I'm missing something. Is your understanding that the issue is also fixed for pubsub functions?

antont commented 1 year ago

From examining the firebase-functions-python code and commits, it doesn't seem fixed but maybe I'm missing something. Is your understanding that the issue is also fixed for pubsub functions?

I don't know, but I'd assume though that datetime parsing is not in many places. I only saw the issue and fix passing by here on github earlier, I don't know anything else.

exaby73 commented 11 months ago

@jacobg Could you confirm on the status of this? If not fixed by 0.1.2, then please let me know and I can investigate further

jacobg commented 11 months ago

Hi @exaby73 I have not seen the error since bumping to 0.1.2, but I'm not sure that's a proof because it only happened once to me in the old version. I think it occurred when the event timestamp was exactly 0 milliseconds and so the formatted string left off the sub-second part.

exaby73 commented 11 months ago

Could you give me an example of a error timestamp you observed to be causing this error? Even if this is fixed, we can add tests for this

koenmtb1 commented 9 months ago

I'm still getting this issue. It seems to happen before it gets to any of the logic in the function itself. It persists between retries. I'm on the latest version firebase-functions = "^0.2.0"

ERROR 2024-02-13T15:30:18.399925Z Traceback (most recent call last): File "/layers/google.python.pip/pip/lib/python3.11/site-packages/flask/app.py", line 1463, in wsgi_app response = self.full_dispatch_request()
DEFAULT 2024-02-13T15:30:18.399930Z ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
DEFAULT 2024-02-13T15:30:18.399936Z File "/layers/google.python.pip/pip/lib/python3.11/site-packages/flask/app.py", line 872, in full_dispatch_request
DEFAULT 2024-02-13T15:30:18.399941Z rv = self.handle_user_exception(e)
DEFAULT 2024-02-13T15:30:18.399945Z ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
DEFAULT 2024-02-13T15:30:18.399950Z File "/layers/google.python.pip/pip/lib/python3.11/site-packages/flask/app.py", line 870, in full_dispatch_request
DEFAULT 2024-02-13T15:30:18.399954Z rv = self.dispatch_request()
DEFAULT 2024-02-13T15:30:18.399959Z ^^^^^^^^^^^^^^^^^^^^^^^
DEFAULT 2024-02-13T15:30:18.399964Z File "/layers/google.python.pip/pip/lib/python3.11/site-packages/flask/app.py", line 855, in dispatch_request
DEFAULT 2024-02-13T15:30:18.399969Z return self.ensure_sync(self.view_functions[rule.endpoint])(**view_args) # type: ignore[no-any-return]
DEFAULT 2024-02-13T15:30:18.399973Z ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
DEFAULT 2024-02-13T15:30:18.399978Z File "/layers/google.python.pip/pip/lib/python3.11/site-packages/functions_framework/__init__.py", line 178, in view_func
DEFAULT 2024-02-13T15:30:18.399982Z function(event)
DEFAULT 2024-02-13T15:30:18.399987Z File "/layers/google.python.pip/pip/lib/python3.11/site-packages/firebase_functions/pubsub_fn.py", line 184, in on_message_published_wrapped
DEFAULT 2024-02-13T15:30:18.399991Z return _message_handler(func, raw)
DEFAULT 2024-02-13T15:30:18.399994Z ^^^^^^^^^^^^^^^^^^^^^^^^^^^
DEFAULT 2024-02-13T15:30:18.400003Z File "/layers/google.python.pip/pip/lib/python3.11/site-packages/firebase_functions/pubsub_fn.py", line 108, in _message_handler
DEFAULT 2024-02-13T15:30:18.400007Z time = _dt.datetime.strptime(
DEFAULT 2024-02-13T15:30:18.400010Z ^^^^^^^^^^^^^^^^^^^^^^
DEFAULT 2024-02-13T15:30:18.400015Z File "/layers/google.python.runtime/python/lib/python3.11/_strptime.py", line 568, in _strptime_datetime
DEFAULT 2024-02-13T15:30:18.400019Z tt, fraction, gmtoff_fraction = _strptime(data_string, format)
DEFAULT 2024-02-13T15:30:18.400024Z ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
DEFAULT 2024-02-13T15:30:18.400028Z File "/layers/google.python.runtime/python/lib/python3.11/_strptime.py", line 349, in _strptime
DEFAULT 2024-02-13T15:30:18.400032Z raise ValueError("time data %r does not match format %r" %
DEFAULT 2024-02-13T15:30:19.463180Z ValueError: time data '2024-02-13T15:07:18Z' does not match format '%Y-%m-%dT%H:%M:%S.%f%z'
scottynoshotty commented 6 months ago

I saw this across 3 of my cloud functions this morning.

ValueError: time data '2024-05-11T05:54:28Z' does not match format '%Y-%m-%dT%H:%M:%S.%f%z'
ValueError: time data '2024-05-11T05:54:28Z' does not match format '%Y-%m-%dT%H:%M:%S.%f%z'
ValueError: time data '2024-05-11T05:54:28Z' does not match format '%Y-%m-%dT%H:%M:%S.%f%z'

Each of them Python Firebase Cloud Functions triggered via pub sub with these dependencies

firebase_functions~=0.4.1
google-cloud-pubsub~=2.18.3
scottynoshotty commented 6 months ago

Saw this again this morning. Here is a more complete stack trace. Appears to error before the function ever starts

DEFAULT 2024-05-12T03:25:44.286622Z ValueError: time data '2024-05-12T03:25:42Z' does not match format '%Y-%m-%dT%H:%M:%S.%f%z'
DEFAULT 2024-05-12T03:25:43.191304Z raise ValueError("time data %r does not match format %r" %
DEFAULT 2024-05-12T03:25:43.191298Z File "/layers/google.python.runtime/python/lib/python3.12/_strptime.py", line 333, in _strptime
DEFAULT 2024-05-12T03:25:43.191295Z ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
DEFAULT 2024-05-12T03:25:43.191291Z tt, fraction, gmtoff_fraction = _strptime(data_string, format)
DEFAULT 2024-05-12T03:25:43.191288Z File "/layers/google.python.runtime/python/lib/python3.12/_strptime.py", line 554, in _strptime_datetime
DEFAULT 2024-05-12T03:25:43.191285Z ^^^^^^^^^^^^^^^^^^^^^^
DEFAULT 2024-05-12T03:25:43.191282Z time = _dt.datetime.strptime(
DEFAULT 2024-05-12T03:25:43.191279Z File "/layers/google.python.pip/pip/lib/python3.12/site-packages/firebase_functions/pubsub_fn.py", line 108, in _message_handler
DEFAULT 2024-05-12T03:25:43.191276Z ^^^^^^^^^^^^^^^^^^^^^^^^^^^
DEFAULT 2024-05-12T03:25:43.191273Z return _message_handler(func, raw)
DEFAULT 2024-05-12T03:25:43.191269Z File "/layers/google.python.pip/pip/lib/python3.12/site-packages/firebase_functions/pubsub_fn.py", line 184, in on_message_published_wrapped
DEFAULT 2024-05-12T03:25:43.191265Z function(event)
DEFAULT 2024-05-12T03:25:43.191261Z File "/layers/google.python.pip/pip/lib/python3.12/site-packages/functions_framework/__init__.py", line 178, in view_func
DEFAULT 2024-05-12T03:25:43.191258Z ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
DEFAULT 2024-05-12T03:25:43.191254Z return self.ensure_sync(self.view_functions[rule.endpoint])(**view_args)
DEFAULT 2024-05-12T03:25:43.191251Z File "/layers/google.python.pip/pip/lib/python3.12/site-packages/flask/app.py", line 1469, in dispatch_request
DEFAULT 2024-05-12T03:25:43.191247Z ^^^^^^^^^^^^^^^^^^^^^^^
DEFAULT 2024-05-12T03:25:43.191244Z rv = self.dispatch_request()
DEFAULT 2024-05-12T03:25:43.191241Z File "/layers/google.python.pip/pip/lib/python3.12/site-packages/flask/app.py", line 1484, in full_dispatch_request
DEFAULT 2024-05-12T03:25:43.191237Z ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
DEFAULT 2024-05-12T03:25:43.191233Z rv = self.handle_user_exception(e)
DEFAULT 2024-05-12T03:25:43.191229Z File "/layers/google.python.pip/pip/lib/python3.12/site-packages/flask/app.py", line 1486, in full_dispatch_request
DEFAULT 2024-05-12T03:25:43.191225Z ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
ERROR 2024-05-12T03:25:43.191215Z Traceback (most recent call last): File "/layers/google.python.pip/pip/lib/python3.12/site-packages/flask/app.py", line 2190, in wsgi_app response = self.full_dispatch_request()
DEFAULT 2024-05-12T03:25:43.191171Z [2024-05-12 03:25:43,178] ERROR in app: Exception on / [POST]
INFO 2024-05-12T03:25:43.150808Z https://publish-post-data-on-feed-reaction-ikiqidi4rq-uc.a.run.app/?__GCP_CloudEventsMode=CUSTOM_PUBSUB_projects%2Fclaptrap-project%2Ftopics%2Fnew-feed-reaction
mrares commented 5 months ago

This issue also affects Firebase Realtime DB functions such as db_fn.on_value_created (the issue is present in the db_fn _db_endpoint_handler method)

mrares commented 5 months ago

In order to protect from this insanity I've created the following function wrapper which I apply on all my cloud functions

import functools, logging

from config import LOG_LEVEL
log = logging.getLogger(__name__)
log.setLevel(LOG_LEVEL)

def timeMolester():

    def timeMolesterDecorator(func):

        @functools.wraps(func)
        def wrapper(raw):

            for timekey in ["time", "publish_time"]:
                time = raw[timekey] if timekey in raw else None

                if time is None:
                    continue

                if "." not in time:
                    after = time.replace("Z", ".000000Z")
                    log.error("Time was PATCHED because Google is stupid (before: %s  after: %s)" % (time, after))
                    raw[timekey] = after

            ret = func(raw)
            return ret
        return wrapper

    return timeMolesterDecorator