(Migrated) Logs written randomly

(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

On 05/05/2014 07:29 PM, Coeuz wrote:

This is my scenario:
I have a zato quickstart cluster running a single server, using the
default logging configuration.

Hi Carles,

before starting to analyze it (yes, I got to the end nevertheless) - the
single server, how many gunicorn_workers does it have in
./config/repo/server.conf?

thamls.

On 05/05/2014 07:29 PM, Coeuz wrote:

This is my scenario:
I have a zato quickstart cluster running a single server, using the
default logging configuration.

Hi Carles,

before starting to analyze it (yes, I got to the end nevertheless) - the
single server, how many gunicorn_workers does it have in
./config/repo/server.conf?

thamls.