(This message has been automatically imported from the retired mailing list)
Hello,
Maybe I’m just facing an expected situation, but I just stumbled into a
behavior which surprised me a lot: The server logs are not being written
consistently!
This is my scenario:
I have a zato quickstart cluster running a single server, using the
default logging configuration.
And I developed three services which were deployed inside the same module:
- WS: a dummy WebService which just forwards the request
asynchronously to the next service
- RawInsert: it inserts the requests into a MongoDB and then
forwards, again asynchronously, the request to another service
- Process: it manipulates the requests and finally inserts it
inside a different collection in MongoDB.
And what happens is that everything works smoothily but the logs are
being randomly written.
To show the behavior I developed the following services, which follow a
similar pattern:
# -*- coding: utf-8 -*-
from __future__ import absolute_import, division, print_function,
unicode_literals
# Zato
from zato.server.service import Service
# Mongo
from pymongo import MongoClient
from bson import json_util
class WS(Service):
def before_handle(self):
self.logger.info('Entering {}'.format(self.name))
def finalize_handle(self):
self.logger.info('{} took {} ms'.format(self.name,
self.processing_time))
def handle(self):
cid = self.invoke_async('test-random-log.first-step',
self.request.raw_request, data_format=None)
class FirstStep(Service):
def before_handle(self):
self.logger.info('Entering {}'.format(self.name))
def finalize_handle(self):
self.logger.info('{} took {} ms'.format(self.name,
self.processing_time))
def handle(self):
input = json_util.loads(self.request.raw_request)
db = MongoClient('localhost',37017).test_random_log
oid = db.first_step.insert(input)
input.update({'_id':oid})
self.invoke_async('test-random-log.second-step',
json_util.dumps(input), data_format=None)
class SecondStep(Service):
def before_handle(self):
self.logger.info('Entering {}'.format(self.name))
def finalize_handle(self):
self.logger.info('{} took {} ms'.format(self.name,
self.processing_time))
def handle(self):
input = json_util.loads(self.request.raw_request)
self.logger.info(input)
input.update({'second_step':'visited'})
db = MongoClient('localhost',37017).test_random_log
self.logger.info(input)
db.second_step.insert(input)
And “recorded” the following session showing this behavior:
First I show that the target MongoDB collection does not have any data
(indeed, it doesn’t yet exist):
zato@zatodev1404:~$ mongo --port 37017
MongoDB shell version: 2.6.0
connecting to: 127.0.0.1:37017/test
> use test_random_log
switched to db test_random_log
> show collections
>
bye
Then I start a tail in the background, so I can compare the requests
with the output which they generate into the logs:
zato@zatodev1404:~$ tail -f -n0 zatotest/server1/logs/server.log |
grep test-random-log &
[1] 32682
And then I start invoking the service from the command line:
zato@zatodev1404:~$ # Call 1
zato@zatodev1404:~$
zato@zatodev1404:~$ zato service invoke --payload
'{"test":"randomlog"}' /opt/zato/zatotest/server1 --data-format JSON
--channel HTTP test-random-log.ws
2014-05-05 18:55:18,538 - INFO - 9860:Dummy-1251 -
test-random-log.second-step:22 - Entering test-random-log.second-step
2014-05-05 18:55:18,538 - INFO - 9860:Dummy-1251 -
test-random-log.second-step:22 - {u'test': u'randomlog', u'_id':
ObjectId('5367c2763540992685370497')}
2014-05-05 18:55:18,539 - INFO - 9860:Dummy-1251 -
test-random-log.second-step:22 - {u'test': u'randomlog',
u'second_step': u'visited', u'_id':
ObjectId('5367c2763540992685370497')}
2014-05-05 18:55:18,602 - INFO - 9860:Dummy-1251 -
test-random-log.second-step:22 - test-random-log.second-step took 63 ms
(None)
zato@zatodev1404:~$
zato@zatodev1404:~$ # Call 2
zato@zatodev1404:~$
zato@zatodev1404:~$ zato service invoke --payload
'{"test":"randomlog"}' /opt/zato/zatotest/server1 --data-format JSON
--channel HTTP test-random-log.ws
2014-05-05 18:55:32,196 - INFO - 9860:Dummy-1254 -
test-random-log.second-step:22 - Entering test-random-log.second-step
2014-05-05 18:55:32,196 - INFO - 9860:Dummy-1254 -
test-random-log.second-step:22 - {u'test': u'randomlog', u'_id':
ObjectId('5367c2843540992685370498')}
2014-05-05 18:55:32,197 - INFO - 9860:Dummy-1254 -
test-random-log.second-step:22 - {u'test': u'randomlog',
u'second_step': u'visited', u'_id':
ObjectId('5367c2843540992685370498')}
2014-05-05 18:55:32,198 - INFO - 9860:Dummy-1254 -
test-random-log.second-step:22 - test-random-log.second-step took 2 ms
(None)
zato@zatodev1404:~$
zato@zatodev1404:~$ # Call 3
zato@zatodev1404:~$
zato@zatodev1404:~$ zato service invoke --payload
'{"test":"randomlog"}' /opt/zato/zatotest/server1 --data-format JSON
--channel HTTP test-random-log.ws
2014-05-05 18:55:34,768 - INFO - 9860:Dummy-1254 -
test-random-log.second-step:22 - Entering test-random-log.second-step
2014-05-05 18:55:34,768 - INFO - 9860:Dummy-1254 -
test-random-log.second-step:22 - {u'test': u'randomlog', u'_id':
ObjectId('5367c2863540992685370499')}
2014-05-05 18:55:34,769 - INFO - 9860:Dummy-1254 -
test-random-log.second-step:22 - {u'test': u'randomlog',
u'second_step': u'visited', u'_id':
ObjectId('5367c2863540992685370499')}
2014-05-05 18:55:34,770 - INFO - 9860:Dummy-1254 -
test-random-log.second-step:22 - test-random-log.second-step took 2 ms
(None)
zato@zatodev1404:~$
zato@zatodev1404:~$ # Call 4
zato@zatodev1404:~$
zato@zatodev1404:~$ zato service invoke --payload
'{"test":"randomlog"}' /opt/zato/zatotest/server1 --data-format JSON
--channel HTTP test-random-log.ws
2014-05-05 18:55:38,263 - INFO - 9860:Dummy-1254 -
test-random-log.second-step:22 - Entering test-random-log.second-step
2014-05-05 18:55:38,263 - INFO - 9860:Dummy-1254 -
test-random-log.second-step:22 - {u'test': u'randomlog', u'_id':
ObjectId('5367c28a354099268537049a')}
2014-05-05 18:55:38,264 - INFO - 9860:Dummy-1254 -
test-random-log.second-step:22 - {u'test': u'randomlog',
u'second_step': u'visited', u'_id':
ObjectId('5367c28a354099268537049a')}
2014-05-05 18:55:38,265 - INFO - 9860:Dummy-1254 -
test-random-log.second-step:22 - test-random-log.second-step took 2 ms
(None)
zato@zatodev1404:~$
zato@zatodev1404:~$ # Call 5
zato@zatodev1404:~$
zato@zatodev1404:~$ zato service invoke --payload
'{"test":"randomlog"}' /opt/zato/zatotest/server1 --data-format JSON
--channel HTTP test-random-log.ws
2014-05-05 18:55:41,169 - INFO - 9860:Dummy-1254 -
zato.service.invoke:22 -
cid:[K337922741093089942529835616774056121897],
name:[zato.service.invoke], SIO request:[{u'name':
u'test-random-log.ws', u'data_format': u'JSON', u'payload':
u'eyJ0ZXN0IjoicmFuZG9tbG9nIn0=\n', u'channel': u'HTTP', u'async':
False, u'id': None, u'transport': None, u'expiration': 15}]
2014-05-05 18:55:41,170 - INFO - 9860:Dummy-1254 -
test-random-log.ws:22 - Entering test-random-log.ws
2014-05-05 18:55:41,171 - INFO - 9860:Dummy-1254 -
test-random-log.ws:22 - test-random-log.ws took 0 ms
2014-05-05 18:55:41,172 - INFO - 9860:Dummy-1255 -
test-random-log.first-step:22 - Entering test-random-log.first-step
2014-05-05 18:55:41,175 - INFO - 9860:Dummy-1255 -
test-random-log.first-step:22 - test-random-log.first-step took 3 ms
(None)
zato@zatodev1404:~$
zato@zatodev1404:~$ # Call 6
zato@zatodev1404:~$
zato@zatodev1404:~$ zato service invoke --payload
'{"test":"randomlog"}' /opt/zato/zatotest/server1 --data-format JSON
--channel HTTP test-random-log.ws
2014-05-05 18:55:48,130 - INFO - 9860:Dummy-1257 -
zato.service.invoke:22 -
cid:[K080612735206087426482253145401367292136],
name:[zato.service.invoke], SIO request:[{u'name':
u'test-random-log.ws', u'data_format': u'JSON', u'payload':
u'eyJ0ZXN0IjoicmFuZG9tbG9nIn0=\n', u'channel': u'HTTP', u'async':
False, u'id': None, u'transport': None, u'expiration': 15}]
2014-05-05 18:55:48,131 - INFO - 9860:Dummy-1257 -
test-random-log.ws:22 - Entering test-random-log.ws
2014-05-05 18:55:48,133 - INFO - 9860:Dummy-1257 -
test-random-log.ws:22 - test-random-log.ws took 0 ms
2014-05-05 18:55:48,136 - INFO - 9860:Dummy-1240 -
test-random-log.second-step:22 - Entering test-random-log.second-step
2014-05-05 18:55:48,137 - INFO - 9860:Dummy-1240 -
test-random-log.second-step:22 - {u'test': u'randomlog', u'_id':
ObjectId('5367c294354099268537049b')}
2014-05-05 18:55:48,137 - INFO - 9860:Dummy-1240 -
test-random-log.second-step:22 - {u'test': u'randomlog',
u'second_step': u'visited', u'_id':
ObjectId('5367c294354099268537049b')}
2014-05-05 18:55:48,138 - INFO - 9860:Dummy-1240 -
test-random-log.second-step:22 - test-random-log.second-step took 2 ms
(None)
zato@zatodev1404:~$
zato@zatodev1404:~$ # Call 7
zato@zatodev1404:~$
zato@zatodev1404:~$ zato service invoke --payload
'{"test":"randomlog"}' /opt/zato/zatotest/server1 --data-format JSON
--channel HTTP test-random-log.ws
2014-05-05 18:55:54,087 - INFO - 9860:Dummy-1240 -
test-random-log.second-step:22 - Entering test-random-log.second-step
2014-05-05 18:55:54,087 - INFO - 9860:Dummy-1240 -
test-random-log.second-step:22 - {u'test': u'randomlog', u'_id':
ObjectId('5367c29a354099268537049c')}
2014-05-05 18:55:54,088 - INFO - 9860:Dummy-1240 -
test-random-log.second-step:22 - {u'test': u'randomlog',
u'second_step': u'visited', u'_id':
ObjectId('5367c29a354099268537049c')}
2014-05-05 18:55:54,089 - INFO - 9860:Dummy-1240 -
test-random-log.second-step:22 - test-random-log.second-step took 2 ms
(None)
zato@zatodev1404:~$
zato@zatodev1404:~$ # Call 8
zato@zatodev1404:~$
zato@zatodev1404:~$ zato service invoke --payload
'{"test":"randomlog"}' /opt/zato/zatotest/server1 --data-format JSON
--channel HTTP test-random-log.ws
2014-05-05 18:55:57,084 - INFO - 9860:Dummy-1240 -
zato.service.invoke:22 -
cid:[K090399771940461612925729846871351491665],
name:[zato.service.invoke], SIO request:[{u'name':
u'test-random-log.ws', u'data_format': u'JSON', u'payload':
u'eyJ0ZXN0IjoicmFuZG9tbG9nIn0=\n', u'channel': u'HTTP', u'async':
False, u'id': None, u'transport': None, u'expiration': 15}]
2014-05-05 18:55:57,085 - INFO - 9860:Dummy-1240 -
test-random-log.ws:22 - Entering test-random-log.ws
2014-05-05 18:55:57,087 - INFO - 9860:Dummy-1240 -
test-random-log.ws:22 - test-random-log.ws took 0 ms
(None)
zato@zatodev1404:~$
zato@zatodev1404:~$ pkill tail
[1]+ Done tail -f -n0
zatotest/server1/logs/server.log | grep --color=auto test-random-log
If you have a close look at the logs, you will notice that:
- SecondStep is able to log in calls 1, 2, 3, 4 and 7.
- WS manages to log in calls 5, 6 and 8.
- And FirstStep is able to reach the log only once, in call 5.
Surprisingly, in this call (5), SecondStep does not log anything, while
the other two do.
- In NO call, the three of them log together.
Finally I go into mongo and see that the 8 calls created the documents
in the corresponding collections, so the services are actually working
right.
zato@zatodev1404:~$ mongo --port 37017
MongoDB shell version: 2.6.0
connecting to: 127.0.0.1:37017/test
> use test_random_log
switched to db test_random_log
> show collections
first_step
second_step
system.indexes
> db.first_step.count()
8
> db.second_step.count()
8
>
bye
zato@zatodev1404:~$
Is this a bug? Or is it the expected behavior?
And, if you reached this point, thank you for the patience of reading
such a looong e-mail!
Regards,
Carles