Correlation IDs not correlating with invoke_async

Howdy,

I've noticed that CIDs aren't correlating with the returned response from self.invoke_async function in v3.2 like they did in v2.

Example Services (written from the base provided by the docs - https://zato.io/docs/progguide/invoking-services.html) playpen.py:

from __future__ import absolute_import, division, print_function, unicode_literals

from zato.server.service import Service

class MyService(Service):
    def handle(self):
        cid = self.invoke_async('playpen.my-service2', {'thing1' : 'foo'})
        self.logger.info('Got CID {}'.format(cid))

class MyService2(Service):        
    def handle(self):
        #Something that takes time.
        time.sleep(6)
        self.log_input("Let's find out what the input was")
        self.logger.info("self.request.payload: {}".format(self.request))
        self.logger.info('My CID is {}'.format(self.cid))

Response from Requesting playpen.my-service:

2022-01-06 03:06:33,040 - INFO - 21553:DummyThread-171 - playpen.my-service:0 - Got CID 9f1d1c28eede68b406d23376
2022-01-06 03:06:38,840 - INFO - 21553:DummyThread-172 - playpen.my-service2:0 - Let's find out what the input was {'request.payload': {'thing1': 'foo'}, 'channel': 'invoke-async', 'cid': 'b5a9983fa2023d59612f7a2b', 'data_format': 'dict', 'environ': {}, 'impl_name': 'playpen.MyService2', 'invocation_time': datetime.datetime(2022, 1, 6, 3, 6, 32, 839308), 'job_type': None, 'name': 'playpen.my-service2', 'slow_threshold': None, 'usage': 0, 'wsgi_environ': {}}
2022-01-06 03:06:38,840 - INFO - 21553:DummyThread-172 - playpen.my-service2:0 - self.request.payload: <zato.server.service.reqresp.Request object at 0x7fb7b0e78ac0>
2022-01-06 03:06:38,840 - INFO - 21553:DummyThread-172 - playpen.my-service2:0 - My CID is b5a9983fa2023d59612f7a2b

9f1d1c28eede68b406d23376 != b5a9983fa2023d59612f7a2b

I also attempted generating a CID and sending it across, same issue. Updated code for MyService:

from zato.common.util import new_cid

class MyService(Service):
    def handle(self):
        _cid = new_cid()
        cid = self.invoke_async('playpen.my-service2', {'thing1' : 'foo'}, cid=_cid)
        cid = self.invoke_async('playpen.my-service2', {'thing1' : 'foo'})
        self.logger.info('Got CID {}'.format(cid))
        self.logger.info('Gen CID: {}'.format(_cid))

Response:

2022-01-06 03:33:23,693 - INFO - 21553:DummyThread-318 - playpen.my-service:0 - Got CID 6fff022225c2eb7e351b6f70
2022-01-06 03:33:23,694 - INFO - 21553:DummyThread-318 - playpen.my-service:0 - Gen CID: 6fff022225c2eb7e351b6f70
2022-01-06 03:33:29,493 - INFO - 21553:DummyThread-319 - playpen.my-service2:0 - Let's find out what the input was {'request.payload': {'thing1': 'foo'}, 'channel': 'invoke-async', 'cid': 'ed95a2771dc08aff5d2350b6', 'data_format': 'dict', 'environ': {}, 'impl_name': 'playpen.MyService2', 'invocation_time': datetime.datetime(2022, 1, 6, 3, 33, 23, 493392), 'job_type': None, 'name': 'playpen.my-service2', 'slow_threshold': None, 'usage': 0, 'wsgi_environ': {}}
2022-01-06 03:33:29,494 - INFO - 21553:DummyThread-319 - playpen.my-service2:0 - self.request.payload: <zato.server.service.reqresp.Request object at 0x7fb7b0e45100>
2022-01-06 03:33:29,494 - INFO - 21553:DummyThread-319 - playpen.my-service2:0 - My CID is ed95a2771dc08aff5d2350b6

A secondary issue that I found (that might be related) is that after being away for a few weeks, in our production env I searched for a CID and found it being used over and over again. eg, here are an example number of entries, the actual result was around 55400+ log lines across many services, and many days:

grep "29c434c4761e6f0c4ae445bc" /opt/zato/env/qs-1/server1/logs/server.log*
/opt/zato/env/qs-1/server1/logs/server.log.2:2022-01-04 18:12:51,017 - INFO - 2481766:DummyThread-362361 - zato.server.connection.http_soap.outgoing:0 - CID:`29c434c4761e6f0c4ae445bc`,
/opt/zato/env/qs-1/server1/logs/server.log.2:2022-01-04 19:17:39,468 - INFO - 2481766:DummyThread-363328 - zato.server.connection.http_soap.outgoing:0 - CID:`29c434c4761e6f0c4ae445bc`
/opt/zato/env/qs-1/server1/logs/server.log.10:2022-01-03 11:30:50,691 - INFO - 2481766:DummyThread-335607 - zato.server.connection.http_soap.outgoing:0 - CID:`29c434c4761e6f0c4ae445bc`

Test Environment: (all fresh for this test) Hardware: AWS VPS OS: Ubuntu 20.04 LTS Zato 3.2+rev.97cd83fd-py3.8.10-ubuntu.20.04-focal

Zato Installed locally via these instructions: https://zato.io/docs/admin/guide/install/ubuntu.html

ODB: MySQL 5.7 KVDB: Redis 6.2.6

Redis and MySQL running within docker on the same machine. I can provide the docker-compose file if need be.

Quickstart cluster: zato quickstart create ~/env/qs-1 mysql localhost 6379 --odb_host localhost --odb_port 3306 --odb_user myodb_user --odb_pass myodb_pass --odb_db myodb --servers 2

Thoughts? Anything obvious that I'm missing?

zatosource / zato

Correlation IDs not correlating with invoke_async #1181