TypeError datetime.date is not JSON serializable (using SQLAlchemy)


#1

Hello everyone!

I am developing a service which returns a guest. I am using SQLAlchemy to define a model class and to query the database. The service is using SimpleIO. Here you are an excerpt of the model class:

class Guest(Base):
    __tablename__ = 'guest'

    id = Column(Integer, primary_key=True)
    name = Column(String(50))
    surname = Column(String(50))
    email = Column(String(255), index=True, unique=True)
    birthdate = Column(Date)
    deleted = Column(DateTime, default=None, index=True)

And this is an excerpt of the service:

class Get(Service):
    """Service class to get a guest by id through channel /genesisng/guests/get/{id}."""

    class SimpleIO(object):
        input_required = ('id')
        output_optional = ('id', 'name', 'surname', 'gender', 'email', 'birthdate', 'deleted')

    def handle(self):
        conn = self.kvdb.conn.get('genesisng:database:connection')
        id_ = self.request.input.id

        with closing(self.outgoing.sql.get(conn).session()) as session:
            result = session.query(Guest).filter(and_(Guest.id == id_, Guest.deleted == None)).one_or_none()

            if result:
                self.response.status_code = OK
                self.response.payload = result
            else:
                self.response.status_code = NOT_FOUND
                self.response.payload = ''

When calling the service:

curl -v -g "http://127.0.0.1:11223/genesisng/guests/get/1"; echo ""

I am getting this error:

TypeError: datetime.date(1976, 1, 1) is not JSON serializable

If the field is NULL on the database, then no error is returned. It happens both with date (birthdate field) and datetime (deleted field):

TypeError: datetime.datetime(2018, 9, 9, 9, 16, 38, 655582) is not JSON serializable

I’ve been searching for information on the Zato docs, the Zato forums, Stack Overflow and elsewhere regarding serialization of dates but I could not find anything useful.

Not sure if it may be related to this post, but I don’t think I am the first person attempting to return a Date or a DateTime from SQLAlchemy through a service, hence I’m confused.

This is the full trace:

2018-09-09 09:11:17,411 DEBG 'zato-server2' stdout output:
2018-09-09 09:11:17,410 - WARNING - 109:DummyThread-40 - zato.server.service:514 - Exception in service `guest.get`, e:`Traceback (most recent call last):
  File "/opt/zato/3.0/code/zato-server/src/zato/server/service/__init__.py", line 503, in update_handle
    response = set_response_func(service, data_format=data_format, transport=transport, **kwargs)
  File "/opt/zato/3.0/code/zato-server/src/zato/server/connection/http_soap/channel.py", line 366, in _set_response_data
    self.set_payload(service.response, data_format, transport, service)
  File "/opt/zato/3.0/code/zato-server/src/zato/server/connection/http_soap/channel.py", line 557, in set_payload
    response.payload = response.payload.getvalue() if response.payload else ''
  File "/opt/zato/3.0/code/zato-server/src/zato/server/service/reqresp/__init__.py", line 447, in getvalue
    return dumps(top)
  File "/opt/zato/3.0/code/local/lib/python2.7/site-packages/anyjson/__init__.py", line 141, in dumps
    return implementation.dumps(value, *args, **kwargs)
  File "/opt/zato/3.0/code/local/lib/python2.7/site-packages/anyjson/__init__.py", line 87, in dumps
    return self._encode(data, *args, **kwargs)
  File "/opt/zato/3.0/code/local/lib/python2.7/site-packages/simplejson/__init__.py", line 354, in dumps
    return _default_encoder.encode(obj)
  File "/opt/zato/3.0/code/local/lib/python2.7/site-packages/simplejson/encoder.py", line 262, in encode
    chunks = self.iterencode(o, _one_shot=True)
  File "/opt/zato/3.0/code/local/lib/python2.7/site-packages/simplejson/encoder.py", line 340, in iterencode
    return _iterencode(o, 0)
  File "/opt/zato/3.0/code/local/lib/python2.7/site-packages/simplejson/encoder.py", line 239, in default
    raise TypeError(repr(o) + " is not JSON serializable")
TypeError: datetime.date(1976, 2, 18) is not JSON serializable
`

2018-09-09 09:11:17,411 DEBG 'zato-server2' stdout output:
2018-09-09 09:11:17,411 - ERROR - 109:DummyThread-40 - zato.server.connection.http_soap.channel:324 - Caught an exception, cid:`c191b669a784db822eaeb428`, status_code:`500`, _format_exc:`Traceback (most recent call last):
  File "/opt/zato/3.0/code/zato-server/src/zato/server/connection/http_soap/channel.py", line 268, in dispatch
    payload, worker_store, self.simple_io_config, post_data, path_info, soap_action)
  File "/opt/zato/3.0/code/zato-server/src/zato/server/connection/http_soap/channel.py", line 495, in handle
    params_priority=channel_item.params_pri)
  File "/opt/zato/3.0/code/zato-server/src/zato/server/service/__init__.py", line 521, in update_handle
    raise resp_e
TypeError: datetime.date(1976, 2, 18) is not JSON serializable

Thanks in advance.


#2

Please install latest updates and you will have access to two new SimpleIO types: Date and DateTime that will automatically serialize to string stdlib’s datetime.date and datetime.datetime objects, respectively.


#3

Hi, @dsuch, and thanks for the help. I’ve made the following changes to the code in the opening post:

from zato.server.service import Service, Integer, Date, DateTime

# [..]

class SimpleIO(object):
    input_required = (Integer('id'))
    output_optional = ('id', 'name', 'surname', 'gender', 'email',
                       'passport', Date('birthdate'), 'address1',
                       'address2', 'locality', 'postcode', 'province',
                       'country', 'home_phone', 'mobile_phone',
                       DateTime('deleted'))

When I am making the following call:

curl -v http://127.0.0.1:11223/genesisng/guests/get/2; echo

I am getting the following response:

*   Trying 127.0.0.1...
* TCP_NODELAY set
* Connected to 127.0.0.1 (127.0.0.1) port 11223 (#0)
> GET /genesisng/guests/get/2 HTTP/1.1
> Host: 127.0.0.1:11223
> User-Agent: curl/7.58.0
> Accept: */*
> 
< HTTP/1.1 500 Internal Server Error
< Server: Zato
< Date: Tue, 25 Sep 2018 21:21:06 GMT
< Connection: close
< Transfer-Encoding: chunked
< X-Zato-CID: abd0bce9822a006845c6405b
< 
{"zato_env": {"details": "Traceback (most recent call last):\n  File \"/opt/zato/3.0/code/zato-server/src/zato/server/connection/http_soap/channel.py\", line 268, in dispatch\n    payload, worker_store, self.simple_io_config, post_data, path_info, soap_action)\n  File \"/opt/zato/3.0/code/zato-server/src/zato/server/connection/http_soap/channel.py\", line 495, in handle\n    params_priority=channel_item.params_pri)\n  File \"/opt/zato/3.0/code/zato-server/src/zato/server/service/__init__.py\", line 523, in update_handle\n    raise resp_e\nZatoException: <ZatoException at 0x7fc5e3e90c30 cid:`None`, msg:`Conversion error, param:`<Date at 0x7fc5e3e88050 name:[birthdate]>`, param_name:`birthdate`, repr:`datetime.date(1976, 5, 17)`, type:`<type 'datetime.date'>`, e:`Traceback (most recent call last):\n  File \"/opt/zato/3.0/code/zato-server/src/zato/server/service/reqresp/sio.py\", line 398, in convert_sio\n    value = param.convert(value, param_name, data_format, from_sio_to_external)\n  File \"/opt/zato/3.0/code* Closing connection 0
/zato-server/src/zato/server/service/reqresp/sio.py\", line 98, in convert\n    return self.serialize_dispatch[(from_sio_to_external, data_type)](value, param_name) if value is not None else value\n  File \"/opt/zato/3.0/code/zato-server/src/zato/server/service/reqresp/sio.py\", line 323, in from_json\n    return value.strftime(self.kwargs['format']) if isinstance(value, _stdlib_date) else value\nTypeError: isinstance() arg 2 must be a class, type, or tuple of classes and types\n``>\n", "result": "ZATO_ERROR", "cid": "abd0bce9822a006845c6405b"}}

The trace in the log is as follows:

2018-09-25 21:25:43,825 DEBG 'zato-server2' stdout output:
2018-09-25 21:25:43,824 - WARNING - 151:DummyThread-22 - zato.server.service:516 - Exception in service `guest.get`, e:`Traceback (most recent call last):
  File "/opt/zato/3.0/code/zato-server/src/zato/server/service/__init__.py", line 505, in update_handle
    response = set_response_func(service, data_format=data_format, transport=transport, **kwargs)
  File "/opt/zato/3.0/code/zato-server/src/zato/server/connection/http_soap/channel.py", line 366, in _set_response_data
    self.set_payload(service.response, data_format, transport, service)
  File "/opt/zato/3.0/code/zato-server/src/zato/server/connection/http_soap/channel.py", line 557, in set_payload
    response.payload = response.payload.getvalue() if response.payload else ''
  File "/opt/zato/3.0/code/zato-server/src/zato/server/service/reqresp/__init__.py", line 405, in getvalue
    elem_value = self._getvalue(name, item, is_sa_namedtuple, is_required, leave_as_is)
  File "/opt/zato/3.0/code/zato-server/src/zato/server/service/reqresp/__init__.py", line 360, in _getvalue
    None, None, None, self.zato_data_format, True)
  File "/opt/zato/3.0/code/zato-server/src/zato/server/service/reqresp/sio.py", line 432, in convert
    return convert_sio(*params)
  File "/opt/zato/3.0/code/zato-server/src/zato/server/service/reqresp/sio.py", line 424, in convert_sio
    raise ZatoException(msg=msg)
ZatoException: <ZatoException at 0x7f98d432a910 cid:`None`, msg:`Conversion error, param:`<Date at 0x7f98d561bfd0 name:[birthdate]>`, param_name:`birthdate`, repr:`datetime.date(1976, 5, 17)`, type:`<type 'datetime.date'>`, e:`Traceback (most recent call last):
  File "/opt/zato/3.0/code/zato-server/src/zato/server/service/reqresp/sio.py", line 398, in convert_sio
    value = param.convert(value, param_name, data_format, from_sio_to_external)
  File "/opt/zato/3.0/code/zato-server/src/zato/server/service/reqresp/sio.py", line 98, in convert
    return self.serialize_dispatch[(from_sio_to_external, data_type)](value, param_name) if value is not None else value
  File "/opt/zato/3.0/code/zato-server/src/zato/server/service/reqresp/sio.py", line 323, in from_json
    return value.strftime(self.kwargs['format']) if isinstance(value, _stdlib_date) else value
TypeError: isinstance() arg 2 must be a class, type, or tuple of classes and types
``>
`

2018-09-25 21:25:43,825 DEBG 'zato-server2' stdout output:
2018-09-25 21:25:43,825 - ERROR - 151:DummyThread-22 - zato.server.connection.http_soap.channel:324 - Caught an exception, cid:`91f2f974775daa8afcdcb984`, status_code:`500`, _format_exc:`Traceback (most recent call last):
  File "/opt/zato/3.0/code/zato-server/src/zato/server/connection/http_soap/channel.py", line 268, in dispatch
    payload, worker_store, self.simple_io_config, post_data, path_info, soap_action)
  File "/opt/zato/3.0/code/zato-server/src/zato/server/connection/http_soap/channel.py", line 495, in handle
    params_priority=channel_item.params_pri)
  File "/opt/zato/3.0/code/zato-server/src/zato/server/service/__init__.py", line 523, in update_handle
    raise resp_e
ZatoException: <ZatoException at 0x7f98d432a910 cid:`None`, msg:`Conversion error, param:`<Date at 0x7f98d561bfd0 name:[birthdate]>`, param_name:`birthdate`, repr:`datetime.date(1976, 5, 17)`, type:`<type 'datetime.date'>`, e:`Traceback (most recent call last):
  File "/opt/zato/3.0/code/zato-server/src/zato/server/service/reqresp/sio.py", line 398, in convert_sio
    value = param.convert(value, param_name, data_format, from_sio_to_external)
  File "/opt/zato/3.0/code/zato-server/src/zato/server/service/reqresp/sio.py", line 98, in convert
    return self.serialize_dispatch[(from_sio_to_external, data_type)](value, param_name) if value is not None else value
  File "/opt/zato/3.0/code/zato-server/src/zato/server/service/reqresp/sio.py", line 323, in from_json
    return value.strftime(self.kwargs['format']) if isinstance(value, _stdlib_date) else value
TypeError: isinstance() arg 2 must be a class, type, or tuple of classes and types
``>
`

Just incidentally, I don’t know how but suddenly everything is “happening twice”. For instance, when I get a user, which works just fine, the query to the database is being executed twice. I am not sure whether one has anything to do with the other, but I am investigating.

Thanks.


#4

Can you check it now? This will fix the TypeError you reported.

As for queries being executed twice - I do not see any connection. You can check all the commits over here, recently there have been only works on the two matters that you submitted and a few changes to WebSockets and publish/subscribe.

Do let me know if you need further assistance or if the root cause is elsewhere.


#5

Hi, @dsuch.

I can confirm that the TypeError is no longer happening, thus the service is now working as expected, both with dates and datetimes. That is, unless the year is before 1900 :slight_smile:

2018-09-26 17:43:34,960 DEBG 'zato-server1' stdout output:
2018-09-26 17:43:34,960 - ERROR - 134:DummyThread-52 - zato.server.connection.http_soap.channel:324 - Caught an exception, cid:`da09da69e69bab3361f0183e`, status_code:`500`, _format_exc:`Traceback (most recent call last):
  File "/opt/zato/3.0/code/zato-server/src/zato/server/connection/http_soap/channel.py", line 268, in dispatch
    payload, worker_store, self.simple_io_config, post_data, path_info, soap_action)
  File "/opt/zato/3.0/code/zato-server/src/zato/server/connection/http_soap/channel.py", line 495, in handle
    params_priority=channel_item.params_pri)
  File "/opt/zato/3.0/code/zato-server/src/zato/server/service/__init__.py", line 523, in update_handle
    raise resp_e
ZatoException: <ZatoException at 0x7fdbd00c3be0 cid:`None`, msg:`Conversion error, param:`<Date at 0x7fdbd2233910 name:[birthdate]>`, param_name:`birthdate`, repr:`datetime.date(1643, 1, 4)`, type:`<type 'datetime.date'>`, e:`Traceback (most recent call last):
  File "/opt/zato/3.0/code/zato-server/src/zato/server/service/reqresp/sio.py", line 398, in convert_sio
    value = param.convert(value, param_name, data_format, from_sio_to_external)
  File "/opt/zato/3.0/code/zato-server/src/zato/server/service/reqresp/sio.py", line 98, in convert
    return self.serialize_dispatch[(from_sio_to_external, data_type)](value, param_name) if value is not None else value
  File "/opt/zato/3.0/code/zato-server/src/zato/server/service/reqresp/sio.py", line 323, in from_json
    return value.strftime(self.kwargs['format']) if isinstance(value, datetime.date) else value
ValueError: year=1643 is before 1900; the datetime strftime() methods require year >= 1900
``>
`

Regarding the double querying, it’s still happening (the above error appeared twice in the log, both on zato-server1, so it’s Zato doing the work twice). It’s either Zato went nuts with me playing with the updating the source procedure or a Gremlin landed on my computer yesterday. It happens both when there is an error and when there is not. I’ll open a new topic in case I cannot solve it.

Cheers!


#6

Did that message appear twice with exactly the same timestamp, and each time it is the same timestamp repeated, down to microseconds?

Is the correlation ID (CID) the same each time? Above, it was da09da69e69bab3361f0183e - this is a unique identifier assigned to each request that Zato receives.


#7

Hi, @dsuch.

Do you mean the trace related to the the datetime strftime() methods require year >= 1900 error? Or generally speaking?


#8

My apologies - I wrote it in reference to your concern that things were happening twice, I am trying to establish if this is actually taking place or if it is only messages appearing twice in log files. I have never seen such a thing before and I cannot reproduce it.

As for the dates before 1900 - I did not realize myself that strftime could not handle them; I will think about it, the GH ticket is here, there are genuine business cases when dates < 1900 occur frequently so it is worth to support it.


#9

No worries :slight_smile:

So I did all the tests again, from start, both with a guest with birthdate after and before 1900. I added logging right before and right after the query:

with closing(self.outgoing.sql.get(conn).session()) as session:
    self.logger.info("Executing query to get a guest...")
    result = session.query(Guest).\
        filter(and_(Guest.id == id_, Guest.deleted.is_(None))).\
        one_or_none()
    self.logger.info("Query executed but nothing done with the result yet.")

And found out that things are only happening once, but queries are being executed twice.

Now I honestly don’t have any clue why this is happening, and whether it’s been happening for a while and I just noticed, or started after some update, but I’ll dig in and see what I can find. Honestly, I’ve been making a lot changes recently, both in my code and updating Zato’s source, and that doesn’t help.

So thanks for the fix with the dates, and thanks in advance for the future fix for the dates before 1900. I’ll keep testing, playing with Zato and prototyping :slight_smile:


#10

Are you confirming it in the database’s query log?


#11

Yes, the exact same SELECT is being executed twice. When executing:

$ curl -v http://127.0.0.1:11223/genesisng/guests/get/2; echo
*   Trying 127.0.0.1...
* TCP_NODELAY set
* Connected to 127.0.0.1 (127.0.0.1) port 11223 (#0)
> GET /genesisng/guests/get/2 HTTP/1.1
> Host: 127.0.0.1:11223
> User-Agent: curl/7.58.0
> Accept: */*
> 
< HTTP/1.1 200 OK
< Server: Zato
< Date: Thu, 27 Sep 2018 19:01:11 GMT
< Connection: close
< Transfer-Encoding: chunked
< Content-Type: application/json
< X-Zato-CID: 28ae83d630e240ebf23bde33
< 
* Closing connection 0
{"response": {"province": "CV", "mobile_phone": "+44.2079460701", "surname": "Nieves", "name": "Leslie", "locality": "Val\u00e9ncia", "deleted": null, "gender": "1", "address2": null, "home_phone": "+44.2079460702", "birthdate": "1976-05-17", "id": 2, "postcode": "20901", "passport": "1677042392399", "address1": "P.O. Box 610, 571 Mollis Av.", "country": "AF", "email": "Morbi.neque@dolor.org"}}

This is the output on Zato’s log:

2018-09-27 19:01:11,520 DEBG 'zato-server2' stdout output:
2018-09-27 19:01:11,520 - INFO - 108:DummyThread-8 - guest.get:32 - Executing query to get a guest...

2018-09-27 19:01:11,539 DEBG 'zato-server2' stdout output:
2018-09-27 19:01:11,538 - INFO - 108:DummyThread-8 - guest.get:36 - Query executed but nothing done with the result yet.

And this is PostgreSQL’s log:

2018-09-27 19:01:11 UTC [223-35] genesis@genesis LOG:  duration: 0.021 ms  bind pg8000_statement_108_1: begin transaction 
2018-09-27 19:01:11 UTC [223-36] genesis@genesis LOG:  duration: 0.006 ms  execute pg8000_statement_108_1: begin transaction 
2018-09-27 19:01:11 UTC [223-37] genesis@genesis LOG:  duration: 3.947 ms  parse pg8000_statement_108_11: SELECT guest.id AS guest_id, guest.name AS guest_name, guest.surname AS guest_surname, guest.gender AS gu
est_gender, guest.email AS guest_email, guest.passport AS guest_passport, guest.birthdate AS guest_birthdate, guest.address1 AS guest_address1, guest.address2 AS guest_address2, guest.locality AS guest_locality,
 guest.postcode AS guest_postcode, guest.province AS guest_province, guest.country AS guest_country, guest.home_phone AS guest_home_phone, guest.mobile_phone AS guest_mobile_phone, guest.deleted AS guest_deleted
  
        FROM guest  
        WHERE guest.id = $1 AND guest.deleted IS NULL 
2018-09-27 19:01:11 UTC [223-38] genesis@genesis LOG:  duration: 7.466 ms  bind pg8000_statement_108_11: SELECT guest.id AS guest_id, guest.name AS guest_name, guest.surname AS guest_surname, guest.gender AS gue
st_gender, guest.email AS guest_email, guest.passport AS guest_passport, guest.birthdate AS guest_birthdate, guest.address1 AS guest_address1, guest.address2 AS guest_address2, guest.locality AS guest_locality,
guest.postcode AS guest_postcode, guest.province AS guest_province, guest.country AS guest_country, guest.home_phone AS guest_home_phone, guest.mobile_phone AS guest_mobile_phone, guest.deleted AS guest_deleted
 
        FROM guest  
        WHERE guest.id = $1 AND guest.deleted IS NULL 
2018-09-27 19:01:11 UTC [223-39] genesis@genesis DETAIL:  parameters: $1 = '2' 
2018-09-27 19:01:11 UTC [223-40] genesis@genesis LOG:  duration: 0.995 ms  execute pg8000_statement_108_11: SELECT guest.id AS guest_id, guest.name AS guest_name, guest.surname AS guest_surname, guest.gender AS
guest_gender, guest.email AS guest_email, guest.passport AS guest_passport, guest.birthdate AS guest_birthdate, guest.address1 AS guest_address1, guest.address2 AS guest_address2, guest.locality AS guest_localit
y, guest.postcode AS guest_postcode, guest.province AS guest_province, guest.country AS guest_country, guest.home_phone AS guest_home_phone, guest.mobile_phone AS guest_mobile_phone, guest.deleted AS guest_delet
ed  
        FROM guest  
        WHERE guest.id = $1 AND guest.deleted IS NULL 
2018-09-27 19:01:11 UTC [223-41] genesis@genesis DETAIL:  parameters: $1 = '2' 
2018-09-27 19:01:11 UTC [223-42] genesis@genesis LOG:  duration: 0.052 ms  bind pg8000_statement_108_8: rollback 
2018-09-27 19:01:11 UTC [223-43] genesis@genesis LOG:  duration: 0.029 ms  execute pg8000_statement_108_8: rollback

If I try to get guest with id 1 (Sir. Isaac Newton, born 1643), I get this error on Zato’s log:

2018-09-27 19:03:11,674 DEBG 'zato-server1' stdout output:
2018-09-27 19:03:11,673 - INFO - 133:DummyThread-8 - guest.get:32 - Executing query to get a guest...

2018-09-27 19:03:11,681 DEBG 'zato-server1' stdout output:
2018-09-27 19:03:11,681 - INFO - 133:DummyThread-8 - guest.get:36 - Query executed but nothing done with the result yet.

2018-09-27 19:03:11,687 DEBG 'zato-server1' stdout output:
2018-09-27 19:03:11,687 - ERROR - 133:DummyThread-8 - zato.server.service.reqresp.sio:422 - Conversion error, param:`<Date at 0x7f3a75c07a10 name:[birthdate]>`, param_name:`birthdate`, repr:`datetime.date(1643, 1, 4)`, type:`<type 'datetime.date'>`, e:`Traceback (most recent call last):
  File "/opt/zato/3.0/code/zato-server/src/zato/server/service/reqresp/sio.py", line 398, in convert_sio
    value = param.convert(value, param_name, data_format, from_sio_to_external)
  File "/opt/zato/3.0/code/zato-server/src/zato/server/service/reqresp/sio.py", line 98, in convert
    return self.serialize_dispatch[(from_sio_to_external, data_type)](value, param_name) if value is not None else value
  File "/opt/zato/3.0/code/zato-server/src/zato/server/service/reqresp/sio.py", line 323, in from_json
    return value.strftime(self.kwargs['format']) if isinstance(value, datetime.date) else value
ValueError: year=1643 is before 1900; the datetime strftime() methods require year >= 1900
`

2018-09-27 19:03:11,690 DEBG 'zato-server1' stdout output:
2018-09-27 19:03:11,690 - WARNING - 133:DummyThread-8 - zato.server.service:516 - Exception in service `guest.get`, e:`Traceback (most recent call last):
  File "/opt/zato/3.0/code/zato-server/src/zato/server/service/__init__.py", line 505, in update_handle
    response = set_response_func(service, data_format=data_format, transport=transport, **kwargs)
  File "/opt/zato/3.0/code/zato-server/src/zato/server/connection/http_soap/channel.py", line 366, in _set_response_data
    self.set_payload(service.response, data_format, transport, service)
  File "/opt/zato/3.0/code/zato-server/src/zato/server/connection/http_soap/channel.py", line 564, in set_payload
    response.payload = response.payload.getvalue() if response.payload else ''
  File "/opt/zato/3.0/code/zato-server/src/zato/server/service/reqresp/__init__.py", line 405, in getvalue
    elem_value = self._getvalue(name, item, is_sa_namedtuple, is_required, leave_as_is)
  File "/opt/zato/3.0/code/zato-server/src/zato/server/service/reqresp/__init__.py", line 360, in _getvalue
    None, None, None, self.zato_data_format, True)
  File "/opt/zato/3.0/code/zato-server/src/zato/server/service/reqresp/sio.py", line 432, in convert
    return convert_sio(*params)
  File "/opt/zato/3.0/code/zato-server/src/zato/server/service/reqresp/sio.py", line 424, in convert_sio
    raise ZatoException(msg=msg)
ZatoException: <ZatoException at 0x7f3a75a778c0 cid:`None`, msg:`Conversion error, param:`<Date at 0x7f3a75c07a10 name:[birthdate]>`, param_name:`birthdate`, repr:`datetime.date(1643, 1, 4)`, type:`<type 'datetime.date'>`, e:`Traceback (most recent call last):
  File "/opt/zato/3.0/code/zato-server/src/zato/server/service/reqresp/sio.py", line 398, in convert_sio
    value = param.convert(value, param_name, data_format, from_sio_to_external)
  File "/opt/zato/3.0/code/zato-server/src/zato/server/service/reqresp/sio.py", line 98, in convert
    return self.serialize_dispatch[(from_sio_to_external, data_type)](value, param_name) if value is not None else value
  File "/opt/zato/3.0/code/zato-server/src/zato/server/service/reqresp/sio.py", line 323, in from_json
    return value.strftime(self.kwargs['format']) if isinstance(value, datetime.date) else value
ValueError: year=1643 is before 1900; the datetime strftime() methods require year >= 1900
``>
`

2018-09-27 19:03:11,690 DEBG 'zato-server1' stdout output:
2018-09-27 19:03:11,690 - ERROR - 133:DummyThread-8 - zato.server.connection.http_soap.channel:324 - Caught an exception, cid:`bef67acb3e2e388781542277`, status_code:`500`, _format_exc:`Traceback (most recent call last):
  File "/opt/zato/3.0/code/zato-server/src/zato/server/connection/http_soap/channel.py", line 268, in dispatch
    payload, worker_store, self.simple_io_config, post_data, path_info, soap_action)
  File "/opt/zato/3.0/code/zato-server/src/zato/server/connection/http_soap/channel.py", line 502, in handle
    params_priority=channel_item.params_pri)
  File "/opt/zato/3.0/code/zato-server/src/zato/server/service/__init__.py", line 523, in update_handle
    raise resp_e
ZatoException: <ZatoException at 0x7f3a75a778c0 cid:`None`, msg:`Conversion error, param:`<Date at 0x7f3a75c07a10 name:[birthdate]>`, param_name:`birthdate`, repr:`datetime.date(1643, 1, 4)`, type:`<type 'datetime.date'>`, e:`Traceback (most recent call last):
  File "/opt/zato/3.0/code/zato-server/src/zato/server/service/reqresp/sio.py", line 398, in convert_sio
    value = param.convert(value, param_name, data_format, from_sio_to_external)
  File "/opt/zato/3.0/code/zato-server/src/zato/server/service/reqresp/sio.py", line 98, in convert
    return self.serialize_dispatch[(from_sio_to_external, data_type)](value, param_name) if value is not None else value
  File "/opt/zato/3.0/code/zato-server/src/zato/server/service/reqresp/sio.py", line 323, in from_json
    return value.strftime(self.kwargs['format']) if isinstance(value, datetime.date) else value
ValueError: year=1643 is before 1900; the datetime strftime() methods require year >= 1900
``>

And I still see both queries on PostgreSQL’s log:

2018-09-27 19:03:11 UTC [230-35] genesis@genesis LOG:  duration: 0.029 ms  bind pg8000_statement_133_1: begin transaction 
2018-09-27 19:03:11 UTC [230-36] genesis@genesis LOG:  duration: 0.007 ms  execute pg8000_statement_133_1: begin transaction 
2018-09-27 19:03:11 UTC [230-37] genesis@genesis LOG:  duration: 0.526 ms  parse pg8000_statement_133_11: SELECT guest.id AS guest_id, guest.name AS guest_name, guest.surname AS guest_surname, guest.gender AS gu
est_gender, guest.email AS guest_email, guest.passport AS guest_passport, guest.birthdate AS guest_birthdate, guest.address1 AS guest_address1, guest.address2 AS guest_address2, guest.locality AS guest_locality,
 guest.postcode AS guest_postcode, guest.province AS guest_province, guest.country AS guest_country, guest.home_phone AS guest_home_phone, guest.mobile_phone AS guest_mobile_phone, guest.deleted AS guest_deleted
  
        FROM guest  
        WHERE guest.id = $1 AND guest.deleted IS NULL 
2018-09-27 19:03:11 UTC [230-38] genesis@genesis LOG:  duration: 1.164 ms  bind pg8000_statement_133_11: SELECT guest.id AS guest_id, guest.name AS guest_name, guest.surname AS guest_surname, guest.gender AS gue
st_gender, guest.email AS guest_email, guest.passport AS guest_passport, guest.birthdate AS guest_birthdate, guest.address1 AS guest_address1, guest.address2 AS guest_address2, guest.locality AS guest_locality,
guest.postcode AS guest_postcode, guest.province AS guest_province, guest.country AS guest_country, guest.home_phone AS guest_home_phone, guest.mobile_phone AS guest_mobile_phone, guest.deleted AS guest_deleted
 
        FROM guest  
        WHERE guest.id = $1 AND guest.deleted IS NULL 
2018-09-27 19:03:11 UTC [230-39] genesis@genesis DETAIL:  parameters: $1 = '1' 
2018-09-27 19:03:11 UTC [230-40] genesis@genesis LOG:  duration: 0.070 ms  execute pg8000_statement_133_11: SELECT guest.id AS guest_id, guest.name AS guest_name, guest.surname AS guest_surname, guest.gender AS
guest_gender, guest.email AS guest_email, guest.passport AS guest_passport, guest.birthdate AS guest_birthdate, guest.address1 AS guest_address1, guest.address2 AS guest_address2, guest.locality AS guest_localit
y, guest.postcode AS guest_postcode, guest.province AS guest_province, guest.country AS guest_country, guest.home_phone AS guest_home_phone, guest.mobile_phone AS guest_mobile_phone, guest.deleted AS guest_delet
ed  
        FROM guest  
        WHERE guest.id = $1 AND guest.deleted IS NULL 
2018-09-27 19:03:11 UTC [230-41] genesis@genesis DETAIL:  parameters: $1 = '1' 
2018-09-27 19:03:11 UTC [230-42] genesis@genesis LOG:  duration: 0.036 ms  bind pg8000_statement_133_8: rollback 
2018-09-27 19:03:11 UTC [230-43] genesis@genesis LOG:  duration: 0.027 ms  execute pg8000_statement_133_8: rollback

Errors/warnings while installing/running Zato into Docker
#12

I will try to reproduce it but I can see only one query each time with a few log entries about it.

It appears that timestamps differ in Zato logs for each entry and each one was produced by a different part of the server, e.g.:

  • 2018-09-27 19:03:11,687 - ERROR - 133:DummyThread-8 - zato.server.service.reqresp.sio:422
  • 2018-09-27 19:03:11,690 - WARNING - 133:DummyThread-8 - zato.server.service:516

On PostgreSQL’s end, it has two or three entries for each query, one for each parse, bind and execute phase. The second time you invoke the query there are only two entries (bind and execute) because the result of the parsing part was likely cached for the session’s duration during the first query.

Nonetheless, I will try to reproduce it using the Get service from BitBucket.


#13

Thanks for the effort and the help, @dsuch. Sources up there are a bit outdated, as I didn’t have in mind commiting the current state of my local repo. I’ll try to commit and push changes as soon as possible.

During the weekend, if possible, I will try to reinstall the container from scratch, see if it happens again. I will also take PostgreSQL out of the container, just in case.


#14

Hi @jsabater - I really am not able to reproduce this situation, I do not see queries executing twice.

I have an idea - can you modify your services to issue an UPDATE statement rather than a SELECT?

That is, can you create an SQLAlchemy query definition to run something akin to UPDATE table SET column = column + 1 and confirm in an external tool what the values are after you execute your service?

This would possibly resolve the question of whether we are observing log entries twice or if it is indeed an actual query executing twice.


#15

I have just pushed a changeset that makes Date and DateTime elements always use YYYY-MM-DD if serializing values with year < 1900.

This means that custom output formats will work only with years >= 1900 but YYYY-MM-DD seems likely to be a format of choice in most APIs anyway so this is not a huge restriction.

In Python 3, .strftime may use years < 1900 so once we support Python 3, this can be lifted.


#16

Tested it and yes, Sir Isaac Newton can finally be a guest in my hotel :+1:

Cheers!

P.S. Agreed to leave it like that until migration to Python 3 can be completed, which will render the workaround obsolete :slight_smile: