{"id":409,"date":"2025-02-08T22:49:00","date_gmt":"2025-02-08T21:49:00","guid":{"rendered":"https:\/\/bowfinger.de\/blog\/?p=409"},"modified":"2025-02-10T17:08:05","modified_gmt":"2025-02-10T16:08:05","slug":"massive-nextcloud-log-file-quickly-analysed-using-python","status":"publish","type":"post","link":"https:\/\/bowfinger.de\/blog\/2025\/02\/massive-nextcloud-log-file-quickly-analysed-using-python\/","title":{"rendered":"Massive Nextcloud log file quickly analysed using Python"},"content":{"rendered":"\n

I ran into a problem with quite a buggy Nextcloud instance on a host with limited quota. The Nextcloud log file would baloon at a crazy rate. So at one point, I snatched a 700 MB sample (yeah, that took maybe an hour or so) and wondered: what’s wrong?<\/p>\n\n\n\n

So, first things first: Nextcloud’s log files are JSON files. Which makes them excruciatingly difficult to read. Okay, better than binary, but still, not an eye pleaser. They wouldn’t be easy to grep<\/code> either. So, Python to the rescue as it has the json<\/code> module*.<\/p>\n\n\n\n

First, using head<\/code> I looked at the first 10 lines only. Why? Because I had no idea of the performance of this little script of mine and I wanted to check it out first.<\/p>\n\n\n\n

head -n 10 nextcloud.log > nextcloud.log.10<\/code><\/pre>\n\n\n\n
Because these logs are scattered with user and directory names and specifics of that particular Nextcloud instance (it’ll be NC from here on), I won’t share any of them here. Sorry. But if you have NC yourself, just get it from the \/data\/<\/code> directory of your NC instance.<\/p>\n\n\n\n
I found each line to contain one JSON object (enclosed in curly brackets). So, let’s read this line-by-line and feed it into Python’s JSON parser:<\/p>\n\n\n\n
import json\n\nwith open(\"nextcloud.log.10\", \"r\") as fh:\n    for line in fh:\n        data = json.loads(line)<\/code><\/pre>\n\n\n\n
At this point, you can already get an idea of how long each line is processed. If you’re using Jupyter Notebook, you can place the with<\/code> statement into its own cell and simply use the %%timeit<\/code> cell magic for a good first impression. On my machine it says<\/p>\n\n\n\n
592 \u00b5s \u00b1 7.65 \u00b5s per loop (mean \u00b1 std. dev. of 7 runs, 1,000 loops each)<\/pre>\n\n\n\n
which is okay: roughly 60 \u00b5s per line.<\/p>\n\n\n\n
Next, I wanted to inspect a few lines and make reading easier: pretty print, or pprint<\/code> as its module is called, to the rescue!<\/p>\n\n\n\n
from pprint import pprint\n\npprint(data)<\/code><\/pre>\n\n\n\n
This pretty prints the last line. If you want to access all 10 lines, create for instance an empty array data_lines<\/code> first and do data_lines.append(data)<\/code> inside the for<\/code> loop.<\/p>\n\n\n\n
{'reqId': '<redacted>',\n 'level': 2,\n 'time': '2025-02-06<redacted>',\n 'remoteAddr': '<redacted>',\n 'user': '<redacted>',\n 'app': 'no app in context',\n 'method': 'GET',\n 'url': '\/<redacted>\/apps\/user_status\/api\/<redacted>?format=json',\n 'message': 'Temporary directory \/www\/htdocs\/<redacted>\/tmp\/ is not present or writable',\n 'userAgent': 'Mozilla\/5.0 (Linux) <redacted> (Nextcloud, <redacted>)',\n 'version': '<redacted>',\n 'data': []}<\/code><\/pre>\n\n\n\n
Okay, there is a message<\/code> which might be interesting, but I found another one:<\/p>\n\n\n\n
{'reqId': '',\n'level': 0,\n'time': '2025-02-06T',\n'remoteAddr': '',\n'user': '',\n'app': 'no app in context',\n'method': 'PROPFIND',\n'url': '\/\/',\n'message': 'Calling without parameters is deprecated and will throw soon.',\n'userAgent': 'Mozilla\/5.0 (Linux) (Nextcloud, 4)',\n'version': '',\n'exception': {'Exception': 'Exception',\n   'Message': 'No parameters in call to ',\n    \u2026<\/code><\/pre>\n\n\n\n
Now, this is much more interesting: It contains a key exception<\/code> with a message and a long traceback below.<\/p>\n\n\n\n
I simply want to know:<\/p>\n\n\n\n
    \n
  • How many of these exceptions are there?<\/li>\n\n\n\n
  • How many unique messages are there?<\/li>\n<\/ul>\n\n\n\n
    In other words: Is this a clusterfuck, or can I get this thing silent by fixing a handful of things?<\/p>\n\n\n\n
    So, the idea is simple:<\/p>\n\n\n\n
      \n
    1. Read each line.<\/li>\n\n\n\n
    2. Check if the line contains an exception<\/code> keyword.<\/li>\n\n\n\n
    3. In that case, count it and…<\/li>\n\n\n\n
    4. … append the corresponding message to a list<\/code>.<\/li>\n\n\n\n
    5. Finally, convert that list<\/code> into a set<\/code>.<\/li>\n<\/ol>\n\n\n\n
      And here is how this looks in Python:<\/p>\n\n\n\n
      import json\nfrom pprint import pprint\n\nlines = 0\nexceptions = 0\nex_messages = []\n\nwith open(\"nextcloud.log\", \"r\") as fh:\n    for line in fh:\n        lines += 1\n        data = json.loads(line)\n        \n        if \"exception\" in data.keys():\n            exceptions += 1\n            msg = data[\"exception\"][\"Message\"]\n            ex_messages.append(msg)\n\nprint(f\"{lines:d} read, {exceptions:d} exceptions.\")\n\ns_ex_msg = set(ex_messages)\nprint(f\"{len(s_ex_msg):d} unique message types.\")\n\npprint(s_ex_msg)<\/code><\/pre>\n\n\n\n
      I had<\/p>\n\n\n\n
      37460 read, 32537 exceptions.
      22 unique message types.<\/pre>\n\n\n\n
      That’s a lot of exceptions but a surprisingly small number of unique messages, i.e. possible individual causes.<\/p>\n\n\n\n
      In my case, it mainly showed me what I knew beforehand: The database was a total mess.<\/p>\n\n\n\n
      But see what you find.<\/p>\n\n\n\n
      Exercise<\/em><\/strong>: See how you need to modify the script to count how many<\/em> out of the 32537 exceptions correspond to each of the 22 unique messages. And toot about it.<\/p>\n\n\n\n
      *) I wonder if people will come and propose to use simplejson<\/code>, as I’ve read in the wild, because “it’s faster!!!”. Use %%timeit<\/code> to find out. Anything else is Mumpitz (forum voodoo).<\/p>\n","protected":false},"excerpt":{"rendered":"
      I ran into a problem with quite a buggy Nextcloud instance on a host with limited quota. The Nextcloud log file would baloon at a crazy rate. So at one point, I snatched a 700 MB sample (yeah, that took maybe an hour or so) and wondered: what’s wrong? So, first things first: Nextcloud’s log…<\/p>\n","protected":false},"author":1,"featured_media":0,"comment_status":"closed","ping_status":"open","sticky":false,"template":"","format":"standard","meta":{"inline_featured_image":false,"footnotes":""},"categories":[16,35],"tags":[18,99,12],"class_list":["post-409","post","type-post","status-publish","format-standard","hentry","category-linux","category-python","tag-linux","tag-nextcloud","tag-python"],"_links":{"self":[{"href":"https:\/\/bowfinger.de\/blog\/wp-json\/wp\/v2\/posts\/409","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/bowfinger.de\/blog\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/bowfinger.de\/blog\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/bowfinger.de\/blog\/wp-json\/wp\/v2\/users\/1"}],"replies":[{"embeddable":true,"href":"https:\/\/bowfinger.de\/blog\/wp-json\/wp\/v2\/comments?post=409"}],"version-history":[{"count":8,"href":"https:\/\/bowfinger.de\/blog\/wp-json\/wp\/v2\/posts\/409\/revisions"}],"predecessor-version":[{"id":417,"href":"https:\/\/bowfinger.de\/blog\/wp-json\/wp\/v2\/posts\/409\/revisions\/417"}],"wp:attachment":[{"href":"https:\/\/bowfinger.de\/blog\/wp-json\/wp\/v2\/media?parent=409"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/bowfinger.de\/blog\/wp-json\/wp\/v2\/categories?post=409"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/bowfinger.de\/blog\/wp-json\/wp\/v2\/tags?post=409"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}