lib389 logging tools

[389-ds-bot]

Cloned from Pagure issue: https://pagure.io/389-ds-base/issue/48434

• Created at 2016-01-28 05:49:17 by firstyear (@Firstyear)
• Closed as Fixed
• Assigned to firstyear (@Firstyear)

---

Lib389 should be able to read, process and interpret log outputs as part of it's tests. We should be integrating log pipe facilities to lib389 to enable this.

[389-ds-bot]

Comment from firstyear (@Firstyear) at 2016-04-27 10:16:42

attachment
0001-Ticket-48434-lib389-logging-tools.patch

[389-ds-bot]

Comment from firstyear (@Firstyear) at 2016-04-27 10:18:12

This will be really useful for things like 48007 where we need to detect lines like:

[13/Jan/2015:00:13:23 +0100] NSMMReplicationPlugin - changelog program -
cl5GetOperationCount: found DB object 7f072400df50
[13/Jan/2015:00:18:16 +0100] - Trimmed 5 changes from the changelog

[389-ds-bot]

Comment from spichugi (@droideck) at 2016-05-03 17:47:20

Hi William,

'''dirsrv_log_test.py::test_access_log''' fails with an assertion error:

assert(
            topology.standalone.ds_access_log.parse_line('[27/Apr/2016:12:49:49.736297002 +1000] conn=1 op=4 fd=64 closed - U1') ==
            {'status': 'U1', 'fd': '64', 'action': 'closed', 'timestamp': '[27/Apr/2016:12:49:49.736297002 +1000]', 'conn': '1', 'op': '4'}
        )
E       assert {'action': 'D...op': '4', ...} == {'action': 'cl...op': '4', ...}
E         Common items:
E         {'conn': '1',
E          'fd': '64',
E          'op': '4',
E          'status': 'U1',
E          'timestamp': '[27/Apr/2016:12:49:49.736297002 +1000]'}
E         Differing items:
E         {'action': 'DISCONNECT'} != {'action': 'closed'}
E         Full diff:
E         - {'action': 'DISCONNECT',
E         + {'action': 'closed',
E         'conn': '1',
E         'fd': '64',
E         'op': '4',
E         'status': 'U1',
E         'timestamp': '[27/Apr/2016:12:49:49.736297002 +1000]'}

[389-ds-bot]

Comment from firstyear (@Firstyear) at 2016-05-04 09:22:57

Fix for test case
0001-Ticket-48434-lib389-logging-tools.2.patch

[389-ds-bot]

Comment from firstyear (@Firstyear) at 2016-05-04 09:23:24

This should fix the test case.

[389-ds-bot]

Comment from spichugi (@droideck) at 2016-05-04 20:29:19

Thank you, William.

Looks good to me.

Only one thing. Could you please disable verbose?

standalone = DirSrv(verbose=True)

[389-ds-bot]

Comment from firstyear (@Firstyear) at 2016-05-09 11:15:47

commit 47b9a51c013225790b575dd03a01b8944c589139

[389-ds-bot]

Comment from mreynolds (@mreynolds389) at 2016-05-13 21:52:03

There is something lacking from this implementation that I'd like to see addressed before the next respin of lib389: The log matching only works for the current log, not for rotated logs of that type. For example, it should be able to search "all" the access logs for a pattern, not just the current access log. In some of my tests the value we need might be in a rotated log, so still need an option to allow for searching rotated logs.

Thanks!

[389-ds-bot]

Comment from firstyear (@Firstyear) at 2016-05-16 09:53:16

Supplementary patch to add support for multiple files.
0001-Ticket-48434-lib389-logging-tools.3.patch

[389-ds-bot]

Comment from mreynolds (@mreynolds389) at 2016-05-16 19:33:02

Thanks for adding the ability to check compressed and rotated logs! One issue I noticed, you have a sleep of 60 seconds for log buffering, but log buffering is set to 30 seconds by default. So we can probably reduce this sleep time.

Also, it might be best to ignore the rotationinfo files when processing multiple files: access.rotationinfo

I have another side request(we/I can do this in a separate ticket if you want), and that is to have the ability grab log output for debugging. If there is a failure in a test, it would be nice to be able to grab the last ## lines from the errors log, etc.

Thanks,
Mark

[389-ds-bot]

Comment from firstyear (@Firstyear) at 2016-05-17 06:24:14

Replying to [comment:10 mreynolds389]:

Thanks for adding the ability to check compressed and rotated logs! One issue I noticed, you have a sleep of 60 seconds for log buffering, but log buffering is set to 30 seconds by default. So we can probably reduce this sleep time.

Actually, what would be smarter is to disable logbuffering.

Also, it might be best to ignore the rotationinfo files when processing multiple files: access.rotationinfo

This is ignored already by the pattern match "%s.-" on the files.

I have another side request(we/I can do this in a separate ticket if you want), and that is to have the ability grab log output for debugging. If there is a failure in a test, it would be nice to be able to grab the last ## lines from the errors log, etc.

Ohhhh, I like that idea. I think that might need to go in a fixture somewhere though ..... Definitely a separate ticket item.

[389-ds-bot]

Comment from firstyear (@Firstyear) at 2016-05-17 06:24:54

Disable log buffering to speed up the test.
0001-Ticket-48434-lib389-logging-tools.4.patch

[389-ds-bot]

Comment from firstyear (@Firstyear) at 2016-05-18 11:38:41

attachment
0001-Ticket-48434-lib389-logging-tools.5.patch

[389-ds-bot]

Comment from firstyear (@Firstyear) at 2016-05-18 11:39:01

Latest update adds timestamp parsing code.

[389-ds-bot]

Comment from mreynolds (@mreynolds389) at 2016-05-18 19:36:08

Looks good! Ack, but you could have used this function for disablign the log - they are both one liners so I guess it doesn't really matter:

standalone.setAccessLogBuffering(True/False)

[389-ds-bot]

Comment from firstyear (@Firstyear) at 2016-05-19 05:52:59

commit f320ad53d2b1c973fbc674e0a18705d5ebcfd49a
Writing objects: 100% (6/6), 2.04 KiB | 0 bytes/s, done.
Total 6 (delta 5), reused 0 (delta 0)
To ssh://git.fedorahosted.org/git/389/lib389.git
2aef04f..f320ad5 master -> master

Thanks man, I think I need to write up a design doc, but I want to sit and have a revamp of a few parts of the lib389 library soon, so I'll leave the access log change for the moment ....

[389-ds-bot]

Comment from firstyear (@Firstyear) at 2016-06-01 08:55:29

attachment
0001-Ticket-48434-Fix-for-negative-tz-offsets.patch

[389-ds-bot]

Comment from firstyear (@Firstyear) at 2016-06-02 04:15:05

commit 924de2f2cf94ba149368475aae2798d8dd52e672

Compressing objects: 100% (6/6), done.
Writing objects: 100% (6/6), 764 bytes | 0 bytes/s, done.
Total 6 (delta 5), reused 0 (delta 0)
To ssh://git.fedorahosted.org/git/389/lib389.git
1f88f1d..924de2f master -> master

[389-ds-bot]

Comment from firstyear (@Firstyear) at 2017-02-11 23:05:07

Metadata Update from @Firstyear:

• Issue assigned to Firstyear
• Issue set to the milestone: lib389 1.0.2