Closed ambasta closed 10 years ago
Are you sure this is 4caab39a27af048d05cfbd1b0946af473a104da6? There are references to APScheduler in the log and APScheduler has been removed from git master in b7ab6437d3b8c5d950f90af6fee679cd9ba434ff, i.e. several days before 4caab39a27af048d05cfbd1b0946af473a104da6.
Hi Dariusz,
Apologies for specified the incorrect log. The correct logs are @ http://bpaste.net/show/403032/
Also please note the db errors raised while running qs
Additionally, relevant log section on uploading the service via Upload a service package.
2014-06-24 18:56:34,796 - DEBUG - 9384:Dummy-9 - zato.server.connection.http_soap.channel:22 - url_match:[<Result () {}>], channel_item:[[('audit_back_log', 1440), ('audit_enabled', False), ('audit_max_payload', 0), ('audit_repl_patt_type', u'json-pointer'), ('connection', u'channel'), ('data_format', u'json'), ('host', None), ('id', 246), ('is_active', True), ('is_internal', True), ('match_target', u':::/zato/admin/invoke'), ('match_target_compiled', <Parser u':::/zato/admin/in...'>), (u'merge_url_params_req', True), ('method', None), ('name', u'admin.invoke.json'), (u'params_pri', u'channel-params-over-msg'), (u'password', u'a8e446c701794286b569c4bb011d708e'), (u'password_type', None), (u'ping_method', u'HEAD'), (u'pool_size', 20), ('replace_patterns_json_pointer', []), ('replace_patterns_xpath', []), ('sec_type', u'basic_auth'), ('security_id', 1), (u'security_name', u'admin.invoke'), (u'serialization_type', u'suds'), (u'service_id', 123), (u'service_impl_name', u'zato.server.service.internal.service.Invoke'), (u'service_name', u'zato.service.invoke'), ('soap_action', u''), ('soap_version', None), ('timeout', 10), ('transport', u'plain_http'), (u'url_params_pri', u'path-over-qs'), ('url_path', u'/zato/admin/invoke'), (u'username', u'admin.invoke')]]
2014-06-24 18:56:34,797 - DEBUG - 9384:Dummy-9 - zato.server.connection.http_soap.channel:22 - channel_params {}
, path_params {}
, _qs {}
2014-06-24 18:56:34,797 - INFO - 9384:Dummy-9 - zato.service.invoke:22 - cid:[K047DCHPRK7MN68PM7HX19R2FD2X], name:[zato.service.invoke], SIO request:[{u'name': u'zato.service.upload-package', u'data_format': u'json', u'id': u'', u'channel': u'invoke', u'async': False, u'payload': u'eyJwYXlsb2FkX25hbWUiOiAibXlfc2VydmljZS5weSIsICJjbHVzdGVyX2lkIjogIjEiLCAicGF5\nbG9hZCI6ICJabkp2YlNCNllYUnZMbk5sY25abGNpNXpaWEoyYVdObElHbHRjRzl5ZENCVFpYSjJh\nV05sQ2dwamJHRnpjeUJIWlhSRGJHbGxiblJFXG5aWFJoYVd4ektGTmxjblpwWTJVcE9nb2dJQ0Fn\nWkdWbUlHaGhibVJzWlNoelpXeG1LVG9LSUNBZ0lDQWdJQ0J6Wld4bUxteHZaMTlwXG5ibkIxZENn\ncENnPT1cbiJ9\n', u'transport': None, u'expiration': 15}]
2014-06-24 18:56:34,798 - INFO - 9384:Dummy-9 - zato.service.upload-package:22 - cid:[K047DCHPRK7MN68PM7HX19R2FD2X], name:[zato.service.upload-package], SIO request:[{u'cluster_id': 1, u'payload_name': u'my_service.py', u'payload': u'ZnJvbSB6YXRvLnNlcnZlci5zZXJ2aWNlIGltcG9ydCBTZXJ2aWNlCgpjbGFzcyBHZXRDbGllbnRE\nZXRhaWxzKFNlcnZpY2UpOgogICAgZGVmIGhhbmRsZShzZWxmKToKICAgICAgICBzZWxmLmxvZ19p\nbnB1dCgpCg==\n'}]
2014-06-24 18:56:34,798 - DEBUG - 9384:Dummy-9 - zato.common.util:22 - About to hot-deploy [/tmp/zato-hd-uOaQoWmy_service.py]
2014-06-24 18:56:34,800 - DEBUG - 9384:Dummy-9 - SQLConnectionPool:22 - Checked out dbapi_conn:<pg8000.core.Connection object at 0x7827f50>, conn_record:<sqlalchemy.pool._ConnectionRecord object at 0x7827f10>, conn_proxy:<sqlalchemy.pool._ConnectionFairy object at 0x7e06650>
2014-06-24 18:56:34,829 - DEBUG - 9384:Dummy-9 - SQLConnectionPool:22 - Checked in dbapi_conn:<pg8000.core.Connection object at 0x7827f50>, conn_record:<sqlalchemy.pool._ConnectionRecord object at 0x7827f10>
2014-06-24 18:56:34,830 - DEBUG - 9384:Dummy-9 - SQLConnectionPool:22 - Checked out dbapi_conn:<pg8000.core.Connection object at 0x7827f50>, conn_record:<sqlalchemy.pool._ConnectionRecord object at 0x7827f10>, conn_proxy:<sqlalchemy.pool._ConnectionFairy object at 0x7ffb2d0>
2014-06-24 18:56:34,833 - DEBUG - 9384:Dummy-9 - SQLConnectionPool:22 - Checked in dbapi_conn:<pg8000.core.Connection object at 0x7827f50>, conn_record:<sqlalchemy.pool._ConnectionRecord object at 0x7827f10>
2014-06-24 18:56:34,834 - DEBUG - 9534:Dummy-3 - zato.broker.client:22 - Got broker message:[channel: /zato/to-parallel/all
data: '{"action": "11000", "package_id": 1, "msg_type": "0002"}'
pattern: null
type: message
]
2014-06-24 18:56:34,834 - DEBUG - 9384:Dummy-3 - zato.broker.client:22 - Got broker message:[channel: /zato/to-parallel/all
data: '{"action": "11000", "package_id": 1, "msg_type": "0002"}'
pattern: null
type: message
]
2014-06-24 18:56:34,835 - DEBUG - 9534:Dummy-3 - zato.broker.client:22 - Got broker message payload [action: '11000'
msg_type: '0002'
package_id: 1
]
2014-06-24 18:56:34,835 - INFO - 9384:Dummy-9 - zato.service.upload-package:22 - cid:[K047DCHPRK7MN68PM7HX19R2FD2X], name:[zato.service.upload-package], response:[]
2014-06-24 18:56:34,835 - DEBUG - 9384:Dummy-3 - zato.broker.client:22 - Got broker message payload [action: '11000'
msg_type: '0002'
package_id: 1
]
2014-06-24 18:56:34,836 - INFO - 9384:Dummy-9 - zato.service.invoke:22 - cid:[K047DCHPRK7MN68PM7HX19R2FD2X], name:[zato.service.invoke], response:[{"zato_service_invoke_response": {"response": ""}}]
2014-06-24 18:56:40,839 - DEBUG - 9384:Dummy-3 - zato.broker.client:22 - Got broker message:[channel: /zato/to-parallel/any
data: zato:broker:to-parallel:any:K06TH9YZFN4WZ58TNCSHPN7PQRW5
pattern: null
type: message
]
2014-06-24 18:56:40,839 - DEBUG - 9534:Dummy-3 - zato.broker.client:22 - Got broker message:[channel: /zato/to-parallel/any
data: zato:broker:to-parallel:any:K06TH9YZFN4WZ58TNCSHPN7PQRW5
pattern: null
type: message
]
2014-06-24 18:56:40,839 - DEBUG - 9384:Dummy-3 - zato.broker.client:22 - No payload in msg:[channel: /zato/to-parallel/any
data: zato:broker:to-parallel:any:K06TH9YZFN4WZ58TNCSHPN7PQRW5
pattern: null
type: message
]
2014-06-24 18:56:40,840 - DEBUG - 9534:Dummy-3 - zato.broker.client:22 - No payload in msg:[channel: /zato/to-parallel/any
data: zato:broker:to-parallel:any:K06TH9YZFN4WZ58TNCSHPN7PQRW5
pattern: null
type: message
]
2014-06-24 18:56:40,840 - DEBUG - 9534:Dummy-3 - zato.broker.client:22 - Got broker message:[channel: /zato/to-parallel/any
data: zato:broker:to-parallel:any:K06WXQQ8V6H639EACV228QF0VPAM
pattern: null
type: message
]
2014-06-24 18:56:40,841 - DEBUG - 9384:Dummy-3 - zato.broker.client:22 - Got broker message:[channel: /zato/to-parallel/any
data: zato:broker:to-parallel:any:K06WXQQ8V6H639EACV228QF0VPAM
pattern: null
type: message
]
2014-06-24 18:56:40,841 - DEBUG - 9534:Dummy-3 - zato.broker.client:22 - No payload in msg:[channel: /zato/to-parallel/any
data: zato:broker:to-parallel:any:K06WXQQ8V6H639EACV228QF0VPAM
pattern: null
type: message
]
2014-06-24 18:56:40,841 - DEBUG - 9384:Dummy-3 - zato.broker.client:22 - No payload in msg:[channel: /zato/to-parallel/any
data: zato:broker:to-parallel:any:K06WXQQ8V6H639EACV228QF0VPAM
pattern: null
type: message
]
2014-06-24 18:56:40,843 - DEBUG - 9534:Dummy-3 - zato.broker.client:22 - Got broker message:[channel: /zato/to-parallel/any
data: zato:broker:to-parallel:any:K06QF6VBC2DW4GH7QCEQCV0P5BX4
pattern: null
type: message
]
2014-06-24 18:56:40,843 - DEBUG - 9384:Dummy-3 - zato.broker.client:22 - Got broker message:[channel: /zato/to-parallel/any
data: zato:broker:to-parallel:any:K06QF6VBC2DW4GH7QCEQCV0P5BX4
pattern: null
type: message
]
2014-06-24 18:56:40,844 - DEBUG - 9534:Dummy-3 - zato.broker.client:22 - No payload in msg:[channel: /zato/to-parallel/any
data: zato:broker:to-parallel:any:K06QF6VBC2DW4GH7QCEQCV0P5BX4
pattern: null
type: message
]
2014-06-24 18:56:40,844 - DEBUG - 9384:Dummy-3 - zato.broker.client:22 - No payload in msg:[channel: /zato/to-parallel/any
data: zato:broker:to-parallel:any:K06QF6VBC2DW4GH7QCEQCV0P5BX4
pattern: null
type: message
]
2014-06-24 18:56:40,845 - DEBUG - 9534:Dummy-3 - zato.broker.client:22 - Got broker message:[channel: /zato/to-parallel/any
data: zato:broker:to-parallel:any:K069K7R5FZNNDTR5E7BSXNJ2SDQG
pattern: null
type: message
]
2014-06-24 18:56:40,845 - DEBUG - 9384:Dummy-3 - zato.broker.client:22 - Got broker message:[channel: /zato/to-parallel/any
data: zato:broker:to-parallel:any:K069K7R5FZNNDTR5E7BSXNJ2SDQG
pattern: null
type: message
]
2014-06-24 18:56:40,846 - DEBUG - 9534:Dummy-3 - zato.broker.client:22 - No payload in msg:[channel: /zato/to-parallel/any
data: zato:broker:to-parallel:any:K069K7R5FZNNDTR5E7BSXNJ2SDQG
pattern: null
type: message
]
2014-06-24 18:56:40,846 - DEBUG - 9384:Dummy-3 - zato.broker.client:22 - No payload in msg:[channel: /zato/to-parallel/any
data: zato:broker:to-parallel:any:K069K7R5FZNNDTR5E7BSXNJ2SDQG
pattern: null
type: message
]
2014-06-24 18:56:40,852 - DEBUG - 9534:Dummy-3 - zato.broker.client:22 - Got broker message:[channel: /zato/to-parallel/any
data: zato:broker:to-parallel:any:K046JDXRQ7YW4S8JFX64WEZ7CWX1
pattern: null
type: message
]
2014-06-24 18:56:40,852 - DEBUG - 9384:Dummy-3 - zato.broker.client:22 - Got broker message:[channel: /zato/to-parallel/any
data: zato:broker:to-parallel:any:K046JDXRQ7YW4S8JFX64WEZ7CWX1
pattern: null
type: message
]
2014-06-24 18:56:40,853 - DEBUG - 9534:Dummy-3 - zato.broker.client:22 - No payload in msg:[channel: /zato/to-parallel/any
data: zato:broker:to-parallel:any:K046JDXRQ7YW4S8JFX64WEZ7CWX1
pattern: null
type: message
]
2014-06-24 18:56:40,853 - DEBUG - 9384:Dummy-3 - zato.broker.client:22 - No payload in msg:[channel: /zato/to-parallel/any
data: zato:broker:to-parallel:any:K046JDXRQ7YW4S8JFX64WEZ7CWX1
pattern: null
type: message
]
2014-06-24 18:56:40,867 - DEBUG - 9534:Dummy-3 - zato.broker.client:22 - Got broker message:[channel: /zato/to-parallel/any
data: zato:broker:to-parallel:any:K073R512J1TT9N55NBAGK2KNJ986
pattern: null
type: message
]
2014-06-24 18:56:40,867 - DEBUG - 9384:Dummy-3 - zato.broker.client:22 - Got broker message:[channel: /zato/to-parallel/any
data: zato:broker:to-parallel:any:K073R512J1TT9N55NBAGK2KNJ986
pattern: null
type: message
]
2014-06-24 18:56:40,868 - DEBUG - 9534:Dummy-3 - zato.broker.client:22 - No payload in msg:[channel: /zato/to-parallel/any
data: zato:broker:to-parallel:any:K073R512J1TT9N55NBAGK2KNJ986
pattern: null
type: message
]
2014-06-24 18:56:40,868 - DEBUG - 9384:Dummy-3 - zato.broker.client:22 - No payload in msg:[channel: /zato/to-parallel/any
data: zato:broker:to-parallel:any:K073R512J1TT9N55NBAGK2KNJ986
pattern: null
type: message
]
2014-06-24 18:56:40,934 - DEBUG - 9534:Dummy-3 - zato.broker.client:22 - Got broker message:[channel: /zato/to-parallel/any
data: zato:broker:to-parallel:any:K07R9BJS5F4WER6DSBH16BVJWSR1
pattern: null
type: message
]
2014-06-24 18:56:40,934 - DEBUG - 9384:Dummy-3 - zato.broker.client:22 - Got broker message:[channel: /zato/to-parallel/any
data: zato:broker:to-parallel:any:K07R9BJS5F4WER6DSBH16BVJWSR1
pattern: null
type: message
]
2014-06-24 18:56:40,935 - DEBUG - 9534:Dummy-3 - zato.broker.client:22 - No payload in msg:[channel: /zato/to-parallel/any
data: zato:broker:to-parallel:any:K07R9BJS5F4WER6DSBH16BVJWSR1
pattern: null
type: message
]
2014-06-24 18:56:40,935 - DEBUG - 9384:Dummy-3 - zato.broker.client:22 - No payload in msg:[channel: /zato/to-parallel/any
data: zato:broker:to-parallel:any:K07R9BJS5F4WER6DSBH16BVJWSR1
pattern: null
type: message
]
2014-06-24 18:56:41,021 - DEBUG - 9384:Dummy-3 - zato.broker.client:22 - Got broker message:[channel: /zato/to-parallel/any
data: zato:broker:to-parallel:any:K07S7GJGP6AFM3FYA50Z01Q776HX
pattern: null
type: message
]
2014-06-24 18:56:41,021 - DEBUG - 9534:Dummy-3 - zato.broker.client:22 - Got broker message:[channel: /zato/to-parallel/any
data: zato:broker:to-parallel:any:K07S7GJGP6AFM3FYA50Z01Q776HX
pattern: null
type: message
]
2014-06-24 18:56:41,022 - DEBUG - 9384:Dummy-3 - zato.broker.client:22 - No payload in msg:[channel: /zato/to-parallel/any
data: zato:broker:to-parallel:any:K07S7GJGP6AFM3FYA50Z01Q776HX
pattern: null
type: message
]
2014-06-24 18:56:41,022 - DEBUG - 9534:Dummy-3 - zato.broker.client:22 - No payload in msg:[channel: /zato/to-parallel/any
data: zato:broker:to-parallel:any:K07S7GJGP6AFM3FYA50Z01Q776HX
pattern: null
type: message
]
2014-06-24 18:56:42,840 - DEBUG - 9384:Dummy-3 - zato.broker.client:22 - Got broker message:[channel: /zato/to-parallel/any
data: zato:broker:to-parallel:any:K06T3CTQ30NA66HF3FDTK9WCXDPD
pattern: null
type: message
]
2014-06-24 18:56:42,840 - DEBUG - 9534:Dummy-3 - zato.broker.client:22 - Got broker message:[channel: /zato/to-parallel/any
data: zato:broker:to-parallel:any:K06T3CTQ30NA66HF3FDTK9WCXDPD
pattern: null
type: message
]
2014-06-24 18:56:42,841 - DEBUG - 9384:Dummy-3 - zato.broker.client:22 - No payload in msg:[channel: /zato/to-parallel/any
data: zato:broker:to-parallel:any:K06T3CTQ30NA66HF3FDTK9WCXDPD
pattern: null
type: message
]
2014-06-24 18:56:42,841 - DEBUG - 9534:Dummy-3 - zato.broker.client:22 - No payload in msg:[channel: /zato/to-parallel/any
data: zato:broker:to-parallel:any:K06T3CTQ30NA66HF3FDTK9WCXDPD
pattern: null
type: message
]
2014-06-24 18:56:42,842 - DEBUG - 9384:Dummy-3 - zato.broker.client:22 - Got broker message:[channel: /zato/to-parallel/any
data: zato:broker:to-parallel:any:K052RHVDRA8CGEQ5GXYP3G7PBQSR
pattern: null
type: message
]
2014-06-24 18:56:42,842 - DEBUG - 9534:Dummy-3 - zato.broker.client:22 - Got broker message:[channel: /zato/to-parallel/any
data: zato:broker:to-parallel:any:K052RHVDRA8CGEQ5GXYP3G7PBQSR
pattern: null
type: message
]
2014-06-24 18:56:42,843 - DEBUG - 9384:Dummy-3 - zato.broker.client:22 - No payload in msg:[channel: /zato/to-parallel/any
data: zato:broker:to-parallel:any:K052RHVDRA8CGEQ5GXYP3G7PBQSR
pattern: null
type: message
]
2014-06-24 18:56:42,843 - DEBUG - 9534:Dummy-3 - zato.broker.client:22 - No payload in msg:[channel: /zato/to-parallel/any
data: zato:broker:to-parallel:any:K052RHVDRA8CGEQ5GXYP3G7PBQSR
pattern: null
type: message
]
Can you please send the body of the service you're deploying? Also, what OS is it exactly? I can't reproduce it on neither Ubuntu 12.04 nor CentOS 6.5.
from zato.server.service import Service
class GetClientDetails(Service): def handle(self): self.log_input()
This is the body of the service.
I am running this on ubuntu 14.04
Hey,
I'd like to debug this further myself. I just wanted a little guidance wrt two items.
Thanks @ambasta - I have just confirmed it on CentOS 6.5
as well so it's not something OS-specific.
Yes, DB conflicts are expected hence they are on DEBUG
.
zato.server.service.internal.hot_deploy.Create.handle
look on_broker_msg_HOT_DEPLOY_CREATE up
in zato-server's worker.py
.
As for what is going on - it looks like only one of the gunicorn_workers gets updated when code is being hot-deployed. So when you have two of them, the service may appear to have been deployed but at times it will seem it's not there. I'll be working on it now as well.
Hmm.. actually I spoke too soon. I'm working on a VM with rather slow I/O and when I was deploying the service the other gunicorn worker simply didn't boot yet.
Now that I understand the the case with the other one is I wait for it to boot, I still cannot reproduce it.
Hi,
What invokes zato.server.service.internal.hot_deploy.Create.handle
I have further debugged the issue and have noticed that common.util.deployment_info
pauses indefinitely at socket.getfqdn
call in common.util.current_host
strace showed
epoll_wait(13, 404f3f0, 64, 999) = -1 EINTR (Interrupted system call) --- SIGWINCH {si_signo=SIGWINCH, si_code=SI_KERNEL} --- rt_sigreturn() = -1 EINTR (Interrupted system call) epoll_wait(13, 404f3f0, 64, 153) = -1 EINTR (Interrupted system call) --- SIGWINCH {si_signo=SIGWINCH, si_code=SI_KERNEL} --- rt_sigreturn() = -1 EINTR (Interrupted system call)
against the relevant gunicorn worker, so I am not sure if its due to a race condition or the thread being killed. Thus I am looking for what function invokes zato.server.service.internal.hot_deploy.Create.handle
I am assuming, this is invoked due to topic_callbacks
subscribing to kvdb.pubsub
?
@ambasta - thank you for diagnosing it thus far!
This is what happens from a moment you place any file in pickup-dir:
zato.server.pickup.gevent_pickup.Pickup.watch
, which uses inotify
, gets notified of it and invokes zato.server.pickup.gevent_pickup.PickupEventProcessor.process
PickupEventProcessor.process
calls zato.common.util.hot_deploy
providing it with a handle to the ParallelServer that found out of the file, path to the file and a flag indicating whether the file should be delete afterwards (read from server.conf's hot_deploy.delete_after_pick_up
)zato.common.util.hot_deploy
does a couple of things:
zato.server.odb.ODBManager.hot_deploy
which stores the picked-up package in ODB (tables deployment_package
and deployment_status
)zato.server.base.parallel.ParallelServer.notify_new_package
.zato.server.base.worker.WorkerStore
with a .on_broker_msg
method inherited from zato.server.base.BrokerMessageReceiver
that gets invoked for all internal messages sent to a server..notify_new_package
was called it published a HOT_DEPLOY.CREATE
message. Upon receiving it by the worker store, its name is translated to the name of a callback function on_broker_msg_HOT_DEPLOY_CREATE
zato.hot-deploy.create`` with the implementation in
zato.server.service.internal.hot_deploy.Create```zato.server.service.store.ServiceStore.import_services_from_file
.import_services_from_file
actually places a service on Python's sys.path
and updates internal structures (self.services
) so the newly deployed services can be referred to by their names.hot_deploy.Create
updates its status in Redis and ODB.So to sum it up - there are several steps, starts with inotify
, goes through the broker which notifies all the gunicorn workers which then update their list of services accordingly.
Again, thanks for your assistance!
Hi,
Thanks for the detailed response.
Now when parallel_server.notify_new_package
was called it published a HOT_DEPLOY.CREATE message
. Upon receiving it by the worker store, its name is translated to the name of a callback function on_broker_msg_HOT_DEPLOY_CREATE
Everything works upto this point. You mention that on receiving by the worker store, which is where my doubts lie.
Is the worker store always listening for new messages. If so, does it fork the callback when it receives a new message, or is it blocking in nature.
If it forks the callback, what is used to create the fork? More gunicorn workers threads, python threading or some redis magic?
Or is message reception signal based. In which case again, are messages blocking or non blocking in nature.
Is the worker store always listening for new messages. If so, does it fork the callback when it receives a new message, or is it blocking in nature.
As it happens, it neither forks nor blocks.
A worker_store is invoked from a server's broker_client
- and that client is defined in zato.broker.client
(not in zato.broker.thread_client
which is used by ZeroMQ, AMQP and JMS WebSphere MQ connectors).
That broker client is a gunicorn greenlet - you'll notice it when a server starts. This greenlet spawns new greenlets upon receiving any messages from the broker. Each spawned greenlet, in this situation, is a single call to one of on_broker_msg_*
in worker store.
2014-07-04 10:29:29,022 - INFO - 4127:Dummy-3 - zato.broker.client:22 - Starting broker client, host:[localhost], port:[6379], name:[parallel-K04WAYTK5CHXJC1K5DEPGRZ7JZ5B], topics:[['/zato/to-parallel/all', '/zato/to-parallel/any', '/zato/to-singleton']]
So at the point on_broker_msg_HOT_DEPLOY_CREATE
is called we are already in a new greenlet and calling any function/method will block only that new greenlet that was spawned to handle that one broker message only.
Awesome, this was the only missing piece of info that I think I need. Pretty sure the greenlet is getting blocked on IO or getting killed. Will debug further and report :dancer:
Yes, my bad on the terminology which is so overloaded.
I meant that the on_broker_msg_HOT_DEPLOY_CREATE
's greenlet wouldn't block other greenlets' IO not that its own IO could not get stuck.
Hey, so adding sleep(2)
after spawn(callback, ...
resolves all issues.
Pretty sure this is the gevent blocking on IO as I said previously. Clearly, this is not the right approach. So you might want to look into monkey patching everything except Threads
I'll try to implement the same on my end as well.
Can you check the following?
logger.warn(self)
call to on_broker_msg_HOT_DEPLOY_CREATE
, right after it starts$ zato start ./server1 --fg
2014-07-04 11:22:16,956 - INFO - 2709:Dummy-1 - gunicorn.error:22 - Booting worker with pid: 2709
(here it's 2709)on_broker_msg_HOT_DEPLOY_CREATE
gets called and prints out itself to the logs, note the greenlet's ID, it will be something like 2709:Dummy-3821
$ kill -s URG 2709
- this will dump a stack trace of all threads and greenletsCurious to see what the greenlet is doing?
2014-07-07 13:01:55,853 - INFO - 6611:Dummy-2 - zato.common.util:22 -
+--------------------------------+--------------------------------------------------------------------------------------------+
| Proc:Thread/Greenlet | Traceback |
+================================+============================================================================================+
| 6611:(No name) | File "/home/amitprakash/delhivery/zato/code/zato-server/src/zato/server/broker/client. |
| | py", line 75, in run |
| | for msg in self.client.listen(): |
| | Arguments: run(self=<zato.broker.client._ClientThread object at 0x6274e10>) |
| | Local variables: |
| | {'msg': {'channel': '/zato/to-parallel/any', |
| | 'data': 'zato:broker:to-parallel:any:K04HJPCX8DBHW3A444A83WH61M7H', |
| | 'pattern': None, |
| | 'type': 'message'}, |
| | 'self': <zato.broker.client._ClientThread object at 0x6274e10>} |
| | File "/home/amitprakash/delhivery/zato/code/eggs/redis-2.9.1-py2.7.egg/redis/client.py", |
| | line 2159, in listen |
| | response = self.handle_message(self.parse_response(block=True)) |
| | Arguments: listen(self=<redis.client.PubSub object at 0x6274810>) |
| | Local variables: |
| | {'response': {'channel': '/zato/to-parallel/any', |
| | 'data': 'zato:broker:to-parallel:any:K04HJPCX8DBHW3A444A83WH61M7H', |
| | 'pattern': None, |
| | 'type': 'message'}, |
| | 'self': <redis.client.PubSub object at 0x6274810>} |
| | File "/home/amitprakash/delhivery/zato/code/eggs/redis-2.9.1-py2.7.egg/redis/client.py", |
| | line 2094, in parse_response |
| | return self._execute(connection, connection.read_response) |
| | Arguments: parse_response(self=<redis.client.PubSub object at 0x6274810>, block=True) |
| | Local variables: |
| | {'block': True, |
| | 'connection': Connection
2014-07-07 13:01:55,853 - INFO - 6611:Dummy-2 - zato.common.util:22 -
+--------------------------------+--------------------------------------------------------------------------------------------+
| Proc:Thread/Greenlet | Traceback |
+================================+============================================================================================+
| 6611:(No name) | File "/home/amitprakash/delhivery/zato/code/zato-server/src/zato/server/broker/client. |
| | py", line 75, in run |
| | for msg in self.client.listen(): |
| | Arguments: run(self=<zato.broker.client._ClientThread object at 0x6274e10>) |
| | Local variables: |
| | {'msg': {'channel': '/zato/to-parallel/any', |
| | 'data': 'zato:broker:to-parallel:any:K04HJPCX8DBHW3A444A83WH61M7H', |
| | 'pattern': None, |
| | 'type': 'message'}, |
| | 'self': <zato.broker.client._ClientThread object at 0x6274e10>} |
| | File "/home/amitprakash/delhivery/zato/code/eggs/redis-2.9.1-py2.7.egg/redis/client.py", |
| | line 2159, in listen |
| | response = self.handle_message(self.parse_response(block=True)) |
| | Arguments: listen(self=<redis.client.PubSub object at 0x6274810>) |
| | Local variables: |
| | {'response': {'channel': '/zato/to-parallel/any', |
| | 'data': 'zato:broker:to-parallel:any:K04HJPCX8DBHW3A444A83WH61M7H', |
| | 'pattern': None, |
| | 'type': 'message'}, |
| | 'self': <redis.client.PubSub object at 0x6274810>} |
| | File "/home/amitprakash/delhivery/zato/code/eggs/redis-2.9.1-py2.7.egg/redis/client.py", |
| | line 2094, in parse_response |
| | return self._execute(connection, connection.read_response) |
| | Arguments: parse_response(self=<redis.client.PubSub object at 0x6274810>, block=True) |
| | Local variables: |
| | {'block': True, |
| | 'connection': Connection
Since the sleep fixes the issues with the broker, I am marking this issue closed.
Hi,
I've been trying to deploy a service as per the tutorial against a gh install. However, while the server does pick up the service from pickup_dir and I can view that the packages are present in the db in deployment_package, the status for each deployment in deployment_status stays stuck at awaiting-deployment.
zato.server.service.internal.hot_deploy.Create.handle never gets called for the service to be deployed.
I am using commit 4caab39a27af048d05cfbd1b0946af473a104da6 and following are the server logs when running in debug mode:
2014-06-24 13:01:13,436 - DEBUG - 6481:Dummy-5 - zato.server.pickup.gevent_pickup:22 - IN_MODIFY event.name:[my_service.py], event:[1: IN_ALL_EVENTS|IN_CLOSE|IN_CLOSE_WRITE] 2014-06-24 13:01:13,437 - DEBUG - 6481:Dummy-5 - zato.common.util:22 - About to hot-deploy [/home/amitprakash/delhivery/done/highway/server1/pickup-dir/my_service.py] 2014-06-24 13:01:13,439 - DEBUG - 6481:Dummy-5 - SQLConnectionPool:22 - Checked out dbapi_conn:<connection object at 0x5d98270; dsn: 'dbname=zato user=zato password=xxxx host=127.0.0.1 port=5432 application_name=parallel/navi/localhost/6481/MainThread', closed: 0>, conn_record:<sqlalchemy.pool._ConnectionRecord object at 0x5e0b850>, conn_proxy:<sqlalchemy.pool._ConnectionFairy object at 0x5edec10> 2014-06-24 13:01:13,485 - DEBUG - 6481:Dummy-5 - SQLConnectionPool:22 - Checked in dbapi_conn:<connection object at 0x5d98270; dsn: 'dbname=zato user=zato password=xxxx host=127.0.0.1 port=5432 application_name=parallel/navi/localhost/6481/MainThread', closed: 0>, conn_record:<sqlalchemy.pool._ConnectionRecord object at 0x5e0b850> 2014-06-24 13:01:13,486 - DEBUG - 6481:Dummy-5 - SQLConnectionPool:22 - Checked out dbapi_conn:<connection object at 0x5d98270; dsn: 'dbname=zato user=zato password=xxxx host=127.0.0.1 port=5432 application_name=parallel/navi/localhost/6481/MainThread', closed: 0>, conn_record:<sqlalchemy.pool._ConnectionRecord object at 0x5e0b850>, conn_proxy:<sqlalchemy.pool._ConnectionFairy object at 0x5173b10> 2014-06-24 13:01:13,487 - DEBUG - 6481:Dummy-5 - SQLConnectionPool:22 - Checked in dbapi_conn:<connection object at 0x5d98270; dsn: 'dbname=zato user=zato password=xxxx host=127.0.0.1 port=5432 application_name=parallel/navi/localhost/6481/MainThread', closed: 0>, conn_record:<sqlalchemy.pool._ConnectionRecord object at 0x5e0b850> 2014-06-24 13:01:13,488 - DEBUG - 6482:Dummy-3 - zato.broker.client:22 - Got broker message:[channel: /zato/to-parallel/all data: '{"action": "11000", "package_id": 8, "msg_type": "0002"}' pattern: null type: message ] 2014-06-24 13:01:13,488 - DEBUG - 6481:Dummy-4 - zato.broker.client:22 - Got broker message:[channel: /zato/to-parallel/all data: '{"action": "11000", "package_id": 8, "msg_type": "0002"}' pattern: null type: message ] 2014-06-24 13:01:13,489 - DEBUG - 6482:Dummy-3 - zato.broker.client:22 - Got broker message payload [action: '11000' msg_type: '0002' package_id: 8 ] 2014-06-24 13:01:13,489 - DEBUG - 6481:Dummy-4 - zato.broker.client:22 - Got broker message payload [action: '11000' msg_type: '0002' package_id: 8 ] 2014-06-24 13:01:13,824 - DEBUG - 6481:Thread-7 - apscheduler.threadpool:22 - Started worker thread 2014-06-24 13:01:13,826 - DEBUG - 6482:Dummy-3 - zato.broker.client:22 - Got broker message:[channel: /zato/to-parallel/any data: zato:broker:to-parallel:any:K00FC7V80A6MVX6E2PBDEE8ZA2TC pattern: null type: message ] 2014-06-24 13:01:13,825 - DEBUG - 6481:Thread-7 - zato.server.scheduler:22 - Sent a job execution request, name [zato.stats.aggregate-by-minute], service [zato.stats.aggregate-by-minute], extra [] 2014-06-24 13:01:13,826 - DEBUG - 6481:Dummy-4 - zato.broker.client:22 - Got broker message:[channel: /zato/to-parallel/any data: zato:broker:to-parallel:any:K00FC7V80A6MVX6E2PBDEE8ZA2TC pattern: null type: message ] 2014-06-24 13:01:13,828 - DEBUG - 6481:Dummy-4 - zato.broker.client:22 - No payload in msg:[channel: /zato/to-parallel/any data: zato:broker:to-parallel:any:K00FC7V80A6MVX6E2PBDEE8ZA2TC pattern: null type: message ] 2014-06-24 13:01:13,828 - DEBUG - 6482:Dummy-3 - zato.broker.client:22 - Got broker message payload [action: '10004' cid: K02DK0NX30GHDV9CE161RAC8JWG1 job_type: interval_based msg_type: '0001' name: zato.stats.aggregate-by-minute payload: '' service: zato.stats.aggregate-by-minute ] 2014-06-24 13:01:13,893 - DEBUG - 6481:Thread-8 - apscheduler.threadpool:22 - Started worker thread 2014-06-24 13:01:13,895 - DEBUG - 6482:Dummy-3 - zato.broker.client:22 - Got broker message:[channel: /zato/to-parallel/any data: zato:broker:to-parallel:any:K03BZ5Q55CEDJA2RGEVVNK8D0VGP pattern: null type: message ] 2014-06-24 13:01:13,894 - DEBUG - 6481:Thread-8 - zato.server.scheduler:22 - Sent a job execution request, name [zato.pattern.delivery.update-counters], service [zato.pattern.delivery.update-counters], extra [] 2014-06-24 13:01:13,895 - DEBUG - 6481:Dummy-4 - zato.broker.client:22 - Got broker message:[channel: /zato/to-parallel/any data: zato:broker:to-parallel:any:K03BZ5Q55CEDJA2RGEVVNK8D0VGP pattern: null type: message ] 2014-06-24 13:01:13,896 - DEBUG - 6482:Dummy-3 - zato.broker.client:22 - Got broker message payload [action: '10004' cid: K00ZAW2QKPH2NPW2FP6FS0GD929M job_type: interval_based msg_type: '0001' name: zato.pattern.delivery.update-counters payload: '' service: zato.pattern.delivery.update-counters ] 2014-06-24 13:01:13,896 - DEBUG - 6481:Dummy-4 - zato.broker.client:22 - No payload in msg:[channel: /zato/to-parallel/any data: zato:broker:to-parallel:any:K03BZ5Q55CEDJA2RGEVVNK8D0VGP pattern: null type: message ] 2014-06-24 13:01:14,827 - DEBUG - 6481:Thread-7 - apscheduler.threadpool:22 - Exiting worker thread 2014-06-24 13:01:14,896 - DEBUG - 6481:Thread-8 - apscheduler.threadpool:22 - Exiting worker thread 2014-06-24 13:01:20,825 - DEBUG - 6481:Thread-9 - apscheduler.threadpool:22 - Started worker thread 2014-06-24 13:01:20,827 - DEBUG - 6482:Dummy-3 - zato.broker.client:22 - Got broker message:[channel: /zato/to-parallel/any data: zato:broker:to-parallel:any:K05RZK4AQHAVZJXS53YJHH5N9TBV pattern: null type: message ] 2014-06-24 13:01:20,826 - DEBUG - 6481:Thread-9 - zato.server.scheduler:22 - Sent a job execution request, name [zato.server.cluster-wide-singleton-keep-alive], service [zato.server.cluster-wide-singleton-keep-alive], extra [server_id:3;cluster_id:2] 2014-06-24 13:01:20,827 - DEBUG - 6481:Dummy-4 - zato.broker.client:22 - Got broker message:[channel: /zato/to-parallel/any data: zato:broker:to-parallel:any:K05RZK4AQHAVZJXS53YJHH5N9TBV pattern: null type: message ] 2014-06-24 13:01:20,828 - DEBUG - 6482:Dummy-3 - zato.broker.client:22 - Got broker message payload [action: '10004' cid: K025P5Y8X4Q5C99A3YAHRMJSFZ4D job_type: interval_based msg_type: '0001' name: zato.server.cluster-wide-singleton-keep-alive payload: server_id:3;cluster_id:2 service: zato.server.cluster-wide-singleton-keep-alive ] 2014-06-24 13:01:20,828 - DEBUG - 6481:Dummy-4 - zato.broker.client:22 - No payload in msg:[channel: /zato/to-parallel/any data: zato:broker:to-parallel:any:K05RZK4AQHAVZJXS53YJHH5N9TBV pattern: null type: message ] 2014-06-24 13:01:21,828 - DEBUG - 6481:Thread-9 - apscheduler.threadpool:22 - Exiting worker thread