Error raised when opening mongod log with mplotqueries

[clegaspi]

Expected behavior

Loading mongod log file successfully with mplotqueries

Actual/current behavior

I get the following traceback when opening a certain mongod log file:

parsing <filename_redacted> [                                        ] 0.0 % Traceback (most recent call last):
  File "/opt/miniconda3/envs/mtools/bin/mplotqueries", line 8, in <module>
    sys.exit(main())
  File "/opt/miniconda3/envs/mtools/lib/python3.6/site-packages/mtools/mplotqueries/mplotqueries.py", line 714, in main
    tool.run()
  File "/opt/miniconda3/envs/mtools/lib/python3.6/site-packages/mtools/mplotqueries/mplotqueries.py", line 146, in run
    self.parse_logevents()
  File "/opt/miniconda3/envs/mtools/lib/python3.6/site-packages/mtools/mplotqueries/mplotqueries.py", line 256, in parse_logevents
    if self.plot_instance.accept_line(logevent):
  File "/opt/miniconda3/envs/mtools/lib/python3.6/site-packages/mtools/mplotqueries/plottypes/scatter_type.py", line 59, in accept_line
    return getattr(logevent, self.field) is not None
  File "/opt/miniconda3/envs/mtools/lib/python3.6/site-packages/mtools/util/logevent.py", line 222, in duration
    self._duration = int(groups.group(1)) * 1000
AttributeError: 'NoneType' object has no attribute 'group'

The same log file loads as expected on mtools 1.5.3. I can explore this error further on my own to identify the log line it has an issue with, and to make sure my Python muscles don't atrophy, but I wanted to make this issue known.

Steps to reproduce the actual/current behavior

1. Create conda environment with python 3.6.9
2. pip install mtools matplotlib
3. mplotqueries <filename>
4. Error occurs

Environment

Software	Version
mtools	1.6.0
MongoDB server	4.2.2 (for log files)
Operating system	Mojave 10.14.6
conda	4.7.12
python	3.6.9
matplotlib	3.1.2

[stennie]

@clegaspi It would be excellent if you can provide a snippet of log that reproduces this issue.

Are you using any other command line options for mplotqueries?

Thanks,
Stennie

[clegaspi]

No, I'm not providing any other options when running. I will try to look into it tomorrow or Sunday to get that log line. Thanks, Christian

…

On Fri, Dec 27, 2019, 7:43 PM Stephen Steneker ***@***.***> wrote: @clegaspi <https://github.com/clegaspi> It would be excellent if you can provide a snippet of log that reproduces this issue. Are you provide any other command line options to mplotqueries? Thanks, Stennie — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#757?email_source=notifications&email_token=AAKUBBUV7A4W5WARQRMTSP3Q23DOVA5CNFSM4KAFOXD2YY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEHYBGSI#issuecomment-569381705>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAKUBBSZBGBEJC2XJFECN23Q23DOVANCNFSM4KAFOXDQ> .

[clegaspi]

Ok, I got the log line

2019-12-26T21:56:49.041+0000 I STORAGE [WTCheckpointThread] WiredTiger message [1577397409:41893][2600:0x7fd43eab3700], file:index-205--8166419544135621535.wt, WT_SESSION.checkpoint: Checkpoint has been running for 20 seconds and wrote: 5000 pages (205 MB)

The LogEvent class tries to parse this as a "Checkpoint took x seconds to complete" line, but it doesn't match the regex. I can see that this check is new in 1.6.0, so 1.5.3 skips this line altogether.

[stennie]

Thanks for tracking down the specific log line @clegaspi. Bug fix on the way :)

[clegaspi]

Cool beans, thanks, Stennie!