mloginfo --queries gives AttributeError: 'str' object has no attribute 'items'

[niccottrell]

Actual/current behavior

It looks like the JSON decoder fails with AttributeError: 'str' object has no attribute 'items'

Full output:

$ mloginfo  server2.log --queries
     source: server2.log
       host: unknown
      start: 2019 Dec 03 15:38:58.089
        end: 2019 Dec 03 16:48:23.534
date format: iso8601-local
     length: 200000
     binary: unknown
    version: >= 3.0 (iso8601 format, level, component)
    storage: unknown

QUERIES
 [=                                       ] 2.8 % Traceback (most recent call last):
  File "/apps/mongodb/sysmngtlab1/instance/anaconda3/bin/mloginfo", line 11, in <module>
    load_entry_point('mtools==1.5.3', 'console_scripts', 'mloginfo')()
  File "/apps/mongodb/sysmngtlab1/instance/anaconda3/lib/python3.6/site-packages/mtools-1.5.3-py3.6.egg/mtools/mloginfo/mloginfo.py", line 95, in main
    tool.run()
  File "/apps/mongodb/sysmngtlab1/instance/anaconda3/lib/python3.6/site-packages/mtools-1.5.3-py3.6.egg/mtools/mloginfo/mloginfo.py", line 90, in run
    section.run()
  File "/apps/mongodb/sysmngtlab1/instance/anaconda3/lib/python3.6/site-packages/mtools-1.5.3-py3.6.egg/mtools/mloginfo/sections/query_section.py", line 81, in run
    pattern=le.pattern, duration=le.duration)
  File "/apps/mongodb/sysmngtlab1/instance/anaconda3/lib/python3.6/site-packages/mtools-1.5.3-py3.6.egg/mtools/util/logevent.py", line 439, in pattern
    self._pattern = self._find_pattern('filter: ')
  File "/apps/mongodb/sysmngtlab1/instance/anaconda3/lib/python3.6/site-packages/mtools-1.5.3-py3.6.egg/mtools/util/logevent.py", line 769, in _find_pattern
    return json2pattern(search_str)
  File "/apps/mongodb/sysmngtlab1/instance/anaconda3/lib/python3.6/site-packages/mtools-1.5.3-py3.6.egg/mtools/util/pattern.py", line 87, in json2pattern
    doc = json.loads(s, object_hook=_decode_pattern_dict)
  File "/apps/mongodb/sysmngtlab1/instance/anaconda3/lib/python3.6/json/__init__.py", line 367, in loads
    return cls(**kw).decode(s)
  File "/apps/mongodb/sysmngtlab1/instance/anaconda3/lib/python3.6/json/decoder.py", line 339, in decode
    obj, end = self.raw_decode(s, idx=_w(s, 0).end())
  File "/apps/mongodb/sysmngtlab1/instance/anaconda3/lib/python3.6/json/decoder.py", line 355, in raw_decode
    obj, end = self.scan_once(s, idx)
  File "/apps/mongodb/sysmngtlab1/instance/anaconda3/lib/python3.6/site-packages/mtools-1.5.3-py3.6.egg/mtools/util/pattern.py", line 40, in _decode_pattern_dict
    return _decode_pattern_dict(value)
  File "/apps/mongodb/sysmngtlab1/instance/anaconda3/lib/python3.6/site-packages/mtools-1.5.3-py3.6.egg/mtools/util/pattern.py", line 31, in _decode_pattern_dict
    for key, value in six.iteritems(data):
  File "/apps/mongodb/sysmngtlab1/instance/anaconda3/lib/python3.6/site-packages/six.py", line 581, in iteritems
    return iter(d.items(**kw))
AttributeError: 'str' object has no attribute 'items'

Steps to reproduce the actual/current behavior

Environment

Software	Version
mtools	mtools version 1.5.3
Python	3.6.1, Anaconda 4.4.0 (64-bit)
MongoDB server	Log from server 3.6.12
Operating system	RHEL VM

pip list
DEPRECATION: The default format will switch to columns in the future. You can use --format=(legacy|columns) (or define a format=(legacy|columns) in your pi                                                                                  p.conf under the [list] section) to disable this warning.
alabaster (0.7.10)
anaconda-client (1.6.3)
anaconda-navigator (1.6.2)
anaconda-project (0.6.0)
asn1crypto (0.22.0)
astroid (1.4.9)
astropy (1.3.2)
Babel (2.4.0)
backports.shutil-get-terminal-size (1.0.0)
beautifulsoup4 (4.6.0)
bitarray (0.8.1)
blaze (0.10.1)
bleach (1.5.0)
bokeh (0.12.5)
boto (2.46.1)
Bottleneck (1.2.1)
cffi (1.10.0)
chardet (3.0.3)
click (6.7)
cloudpickle (0.2.2)
clyent (1.2.2)
colorama (0.3.9)
conda (4.3.21)
contextlib2 (0.5.5)
cryptography (1.8.1)
cycler (0.10.0)
Cython (0.25.2)
cytoolz (0.8.2)
dask (0.14.3)
datashape (0.5.4)
decorator (4.0.11)
distributed (1.16.3)
docutils (0.13.1)
entrypoints (0.2.2)
et-xmlfile (1.0.1)
fastcache (1.0.2)
Flask (0.12.2)
Flask-Cors (3.0.2)
gevent (1.2.1)
greenlet (0.4.12)
h5py (2.7.0)
HeapDict (1.0.0)
html5lib (0.999)
idna (2.5)
imagesize (0.7.1)
ipykernel (4.6.1)
ipython (5.3.0)
ipython-genutils (0.2.0)
ipywidgets (6.0.0)
isort (4.2.5)
itsdangerous (0.24)
jdcal (1.3)
jedi (0.10.2)
Jinja2 (2.9.6)
jsonschema (2.6.0)
jupyter (1.0.0)
jupyter-client (5.0.1)
jupyter-console (5.1.0)
jupyter-core (4.3.0)
lazy-object-proxy (1.2.2)
llvmlite (0.18.0)
locket (0.2.0)
lxml (3.7.3)
MarkupSafe (0.23)
matplotlib (2.0.2)
mistune (0.7.4)
mpmath (0.19)
msgpack-python (0.4.8)
mtools (1.5.3)
multipledispatch (0.4.9)
navigator-updater (0.1.0)
nbconvert (5.1.1)
nbformat (4.3.0)
networkx (1.11)
nltk (3.2.3)
nose (1.3.7)
notebook (5.0.0)
numba (0.33.0)
numexpr (2.6.2)
numpy (1.12.1)
numpydoc (0.6.0)
odo (0.5.0)
olefile (0.44)
openpyxl (2.4.7)
packaging (16.8)
pandas (0.20.1)
pandocfilters (1.4.1)
partd (0.3.8)
pathlib2 (2.2.1)
patsy (0.4.1)
pep8 (1.7.0)
pexpect (4.2.1)
pickleshare (0.7.4)
Pillow (4.1.1)
pip (9.0.1)
ply (3.10)
prompt-toolkit (1.0.14)
psutil (5.2.2)
ptyprocess (0.5.1)
py (1.4.33)
pycosat (0.6.2)
pycparser (2.17)
pycrypto (2.6.1)
pycurl (7.43.0)
pyflakes (1.5.0)
Pygments (2.2.0)
pylint (1.6.4)
pyodbc (4.0.16)
pyOpenSSL (17.0.0)
pyparsing (2.1.4)
pytest (3.0.7)
python-dateutil (2.7.0)
pytz (2017.2)
PyWavelets (0.5.2)
PyYAML (3.12)
pyzmq (16.0.2)
QtAwesome (0.4.4)
qtconsole (4.3.0)
QtPy (1.2.1)
requests (2.14.2)
rope-py3k (0.9.4.post1)
scikit-image (0.13.0)
scikit-learn (0.18.1)
scipy (0.19.0)
seaborn (0.7.1)
setuptools (27.2.0)
setuptools-scm (3.3.3)
simplegeneric (0.8.1)
singledispatch (3.4.0.3)
six (1.10.0)
snowballstemmer (1.2.1)
sortedcollections (0.5.3)
sortedcontainers (1.5.7)
Sphinx (1.5.6)
spyder (3.1.4)
SQLAlchemy (1.1.9)
statsmodels (0.8.0)
sympy (1.0)
tables (3.3.0)
tblib (1.3.2)
terminado (0.6)
testpath (0.3)
toolz (0.8.2)
tornado (4.5.1)
traitlets (4.3.2)
unicodecsv (0.14.1)
UNKNOWN (0.0.0)
wcwidth (0.1.7)
Werkzeug (0.12.2)
wheel (0.29.0)
widgetsnbextension (2.0.0)
wrapt (1.10.10)
xlrd (1.0.0)
XlsxWriter (0.9.6)
xlwt (1.2.0)
zict (0.1.2)

$ python -m locale
Locale aliasing:

Locale defaults as determined by getdefaultlocale():
------------------------------------------------------------------------
Language:  en_GB
Encoding:  UTF-8

Locale settings on startup:
------------------------------------------------------------------------
LC_CTYPE ...
   Language:  en_GB
   Encoding:  UTF-8

LC_TIME ...
   Language:  (undefined)
   Encoding:  (undefined)

LC_COLLATE ...
   Language:  (undefined)
   Encoding:  (undefined)

LC_MONETARY ...
   Language:  (undefined)
   Encoding:  (undefined)

LC_MESSAGES ...
   Language:  (undefined)
   Encoding:  (undefined)

LC_NUMERIC ...
   Language:  (undefined)
   Encoding:  (undefined)


Locale settings after calling resetlocale():
------------------------------------------------------------------------
LC_CTYPE ...
   Language:  en_GB
   Encoding:  UTF-8

LC_TIME ...
   Language:  en_GB
   Encoding:  UTF-8

LC_COLLATE ...
   Language:  en_GB
   Encoding:  UTF-8

LC_MONETARY ...
   Language:  en_GB
   Encoding:  UTF-8

LC_MESSAGES ...
   Language:  en_GB
   Encoding:  UTF-8

LC_NUMERIC ...
   Language:  en_GB
   Encoding:  UTF-8


Locale settings after calling setlocale(LC_ALL, ""):
------------------------------------------------------------------------
LC_CTYPE ...
   Language:  en_GB
   Encoding:  UTF-8

LC_TIME ...
   Language:  en_GB
   Encoding:  UTF-8

LC_COLLATE ...
   Language:  en_GB
   Encoding:  UTF-8

LC_MONETARY ...
   Language:  en_GB
   Encoding:  UTF-8

LC_MESSAGES ...
   Language:  en_GB
   Encoding:  UTF-8

LC_NUMERIC ...
   Language:  en_GB
   Encoding:  UTF-8


Number formatting:

123,456,789 is 123456789
3.14 is 3.14

[niccottrell]

I've tracked this down to the following line by replicating on another machine (making the env details above irrelevant):

2019-12-03T15:41:09.181+0000 I COMMAND  [conn250381] command TDSDependencyManager-UAT.activations-uat-3 command: find { find: "activations-uat-3", filter: { subscription: { id: "5dd3089379", query: "latestVersionForTheSameDateAndClassifier", arguments: { datasets: [ "rawldbtrade_init" ], classifier: "source-key" }, client: "RawLdbTrade", priority: 4, group: "tds-spark-transforms" }, result: { datasets: [ { id: "5dfd", name: "rawldbtrade_init", version: "2019120348", date: "20191202" } ], date: "20191202" } }, limit: 1, batchSize: 2147483647, $db: "TDSDependencyManager-UAT" } planSummary: COLLSCAN keysExamined:0 docsExamined:72913 cursorExhausted:1 numYields:569 nreturned:1 reslen:561 locks:{ Global: { acquireCount: { r: 1140 } }, Database: { acquireCount: { r: 570 } }, Collection: { acquireCount: { r: 570 } } } protocol:op_msg 113ms

Is there some invalid JSON in there somewhere? I guess we need to catch and move on from such unexpected lines.

[stennie]

@niccottrell Thanks for narrowing down the log line to repro this. The issue is caused by a field called query which triggers trying to decode the value as a dictionary when it is a string: query: "latestVersionForTheSameDateAndClassifier".

The current (incorrect) assumption appears to be that query: is only used for query params. Will fix the logic & add a test.

Cheers,
Stennie