So on our machines we noticed something odd. Our services log normally, but these messages seem to be grouped into packs of specific sizes. For instance, one command of our service generates only 1 line in the log. Another command generates about 5 lines.
Using journalctl -u service -f, the single lines only show up if there is enough of them, while the messages of 5 lines always show up as soon as you invoke the command. Consider this example:
I invoke the short command 4 times and nothing shows up in journalctl. Then I invoke the longer command and all 4 entries of the short commands as well as the new longer command show up immediately. However, they all have basically the exact same timestamp (factoring in writing speed), even if I send invoke them seconds apart!
[712708.862606] <hostname> <custom_service>[1020]: keys finished
[712708.902052] <hostname> <custom_service>[1020]: keys finished
[712708.902409] <hostname> <custom_service>[1020]: keys finished
[712708.902717] <hostname> <custom_service>[1020]: keys finished
[712708.903025] <hostname> <custom_service>[1020]: ERROR:JSONRPCTCP:Error calling handler db.keys
[712708.903377] <hostname> <custom_service>[1020]: ERROR:JSONRPCTCP:Request: {"jsonrpc": "2.0", "method": "db.keys", "id": "9fc6e420-4d6a-4654-a439-5c89fb4839a4"}
[712708.903730] <hostname> <custom_service>[1020]: ERROR:JSONRPCTCP:Traceback (most recent call last):
[712708.904100] <hostname> <custom_service>[1020]: File "/opt/<product>/lib/python2.7/site-packages/<service>/server.py", line 321, in parse_call
[712708.904417] <hostname> <custom_service>[1020]: response = handler(*params, **kwargs)
[712708.904729] <hostname> <custom_service>[1020]: TypeError: keys() takes at least 2 arguments (1 given)
This is tricky for debugging as you can't really rely on messages showing up when they actually happen. What am I missing here? Is there any way to force these log messages to appear in journalctl when they actually happen?
