Fix: Aggregate Logs and formatting #331
Conversation
mkellerman
requested review from
dnzxy,
bjornoleh,
MikePlante1,
aug0211,
AndreasStokholm,
Sjoerd-Bo3 and
t1dude
as code owners
|
Previous Logs: New Logs: |
SummaryThis patch builds and runs. Probably needs a bit more work. testing summary:Before and After patch, logs appended at the end of this message as zip files. After the rebuild (and not before), see this error message in logs: with some extra lines associated with that (I think).
ConfigurationI applied the patch from this PR to the alpha branch (where a number of PR have been accumulating prior to being merged to dev), commit 3ec6176. Testing
Let it run for a while
Configure the python parsing program still works:Success: Run OmniLoopMessageParser on the 2 log files. Note that parser breaks logs into individual pods segments when more than one pod is detected, thus the second pod in the log started just before rebuilding to Trio with patch. The output report for that pod is summarized below.
Log files:Log before the rebuld: Log after the rebuild: |
|
@marionbarker , i've updated the PR. Can you please re-run your script please to validate? |
Summary
Details:
Using the new logger:
|
|
@mkellerman I like the shortening of the js-logging very much. Could you elaborate which benefit you try to reap by converting the console.errors from js into something like "variable": "some statement"? For me it destroys some readability of the js debugging done by the console.error, e.g. But I also have to admit that autoISF has a lot more debugging implemented in a prosa like style, that you are not aware of: |
|
@mountrcg thanks for testing out my PR! I haven’t tested all possible outputs from these JavaScripts, and some will only output based on specific settings. Can you send me your log file from a previous run? Not one from my execution? I’ll attempt to add the fixes for those outputs as well. But if you have the courage, attempt some regex magic and push up a code suggestion! 😂 |
Robert‘s logs stem from a fork of Trio that runs an altered algorithm, thus does not need to be supported by a potential Trio log parser; if wanted or required that will have to be extended within that fork. |
|
Could you provide a full log.txt (maybe let it run for 2-3 loop cycles) with the newly added and changed parser to compare changes made? |
|
I reversed the patch and rebuilt at 06:45 local. The plan is to save logs and split into with and without patch segments of 15 minutes each. |
|
Once all possible outputs have been evaluated from the JS output, it will be great, but in the mean time, do we want the original unprocessed logs to come out into the logs? i have the choice between JSON, INVALID_JSON (which is what you’re seeing now), RAW. |
Log SamplesForgot to restart the rPi DASH simulator after rebuidling. Graphic shows with patch on left and straight dev on the right. (Picked a section with Middleware).
Log with patch (15 minute chunk): Log with no patch (15 minute chunk): Full log in case it is desired: Timing details and selection of log snippets:Decide to define a "cycle" as the line with [DeviceManager] FetchGlucoseManager.swift with 217 - DEV: New glucose found for clarity, do a s/r to remove repeated text below: |
The upper part is standard logging. Readability of the java-logs is a tuned down by omitting spaces in prosa and forcing everything into a |
Yes, that’s what Marc is proposing here to cut the log size down drastically. I guess it’s a subjective thing if this is tuned down or improved. I was referring to the lines of I also brought this up on Discord, where I pointed out that specific entries need to be logged after one another and that there’s a certain "order" of the logging and that needs to be kept so that the log stays readable. |
|
I did not find your comment in discord @dnzxy . I totally think the idea of reducing the the size of the logs is great. An a lot is achieved to delete the trillion chars befor the actual content of the logging. |
|
I have no experience with or opinion on these changes, but some historical context: the oref0 logs were optimized for tailing a log file in real time on a Linux console. The phone use case is quite different, so I wouldn’t be surprised if the optimal logging format is also. |
|
@mountrcg It's probably somewhere buried deep down in the
I'm not sure what you mean by this. If it's the hundreds of
I'm with you in principle, the logs need to be readable and comprehensible, you need to still be able to follow the "oref workflow" from the logs. It does serve a purpose to press it in a "certain scheme". What Marc has proposed here takes the output every loop run prints into the log file from high double digit log entries (lets go with 25 for ease for argument) into 1 single long entry. He is flushing and aggregating the logs. That is meaningful, and a common best practice. What we need to work out, and I'm sure Marc is happy to work on constructive input and ideas, is how to get the best of both worlds: a) aggregated logs, while b) keeping the oref "logging order" intact. @scottleibrand thanks for providing some historical context. I guess tailing here means "following along on stdout", not so much using |
Yes I meant the condesing like Marion showed nicely in her comparison screen:
I am just not happy with changing the content of the logging, like in the purple magnification glas. What purpose does that serve? |
|
Thank you for everyones feedback! Love the discussion. We have a bit of a conflict here. There are 2 issues that is being addressed:
Regarding size, it's clearly doing its job. Regarding formatting, i think most of the confusion is derived by the output when a log line is not in a key/value pair, and i put it under 'unknown'. I had it this way so i can clearly see what i need to fix my regex for. I will be attempting to correct that today, so please expect a change and re-evaluate the output. |
|
I found the discussion in discord, sry that I did not see before. What would be the reason for trying to find the somewhat elegant solution (I like the sound of that!)?
Is to put it in some log analysis that expects key-value pairs? The logging in oref does not just come from determine-basal.js but also from the tempbasal functions und glucose-get-last modules and contains many textual/explanation strings. I pushed a couple PR's to oref0 repo to clean up some of that logging. I guess that can still be done, in contrast to:
|
|
I realize that this might be ambitious, and there are many log outputs that needs to be cleaned up. I was told that we shouldn't be touching the original js scripts, so doing my best to do it post processing. |
autosense() |
determineBasal() |
|
As you can see with the What do people think of this? |
mkellerman
force-pushed
the
fix-aggregatelogs
branch
from
ee481b6
to
d3edb9d
Compare
mkellerman
force-pushed
the
fix-aggregatelogs
branch
from
d3edb9d
to
0415460
Compare
|
Love it. The autosens parsing alone will save another double-digits percentage in log size.
Yes. Logs usually aren't written in prosa. This makes for a way cleaner log and instead of looking for |
|
Also, maybe i'm doing this all wrong, and we should just have a DEBUG=true flag in the settings, and if so, we get the raw output from the JS execution. when DEBUG=false, we could add the actual data that is a result of the execution... for example:
|
|
I like the idea (a bit like ssh-ing into a container and seeing what’s off 😂) but the thing with AID apps is that you want to log as much as you can in case of a sudden issue / crash / fatal error, so you can at least know what went on after the fact. Imagine you suddenly got insulin, you are not sure why, you tend to the FB groups or FB, you describe the situation. If volunteers can’t immediately explain it to you, a good hard look at the logs will always tell people what went on (more often than not user error or unintended things by inputs of an uneducated user), and that is really important. I could totally see something like a more verbose dev outputs that’s even more detailed, but the degree verbosity should probably be kept yet the output cleaned up a bit. |
|
In the event of a crash, i think my implementation might cause issues. It's groupping the output, and processing it, before writing to disk. So if there is any failures during the execution of the JS, then it wont be logged to file. Might be best to consider modifying the original JS files? :| |
|
It will be written to the log file every single loop and every time the algorithm runs, to be more precise when the specific worker is called, so that’s alright; unless I am interpreting things wrong here. I meant that we will at least have output every 5 min loop. If you have to enable debug logging that will be a hard thing to do 😊 |
Tail the logs means something like tail -f pump-loop.log. So yes, real time. The console.error was a node.js workaround IIRC. |
Okay so tailing number of lines, makes sense to make it more prosa read-along like then 👍 thanks again for the insight. Would you accept PRs to the oref repository to change that? Are there still users of the rPi rigs that require these workaround? Could this be changed? |
|
There were some alternative logging formats implemented, which wrote to different log files. You could probably adapt that. I still tail -f pump-loop.log on our rigs. |
|
So, what do we want to do with this PR? |
I'd consider this PR to be an improvement as long as we keep with the "order" of oref log statements. There is a long-term goal of no longer using JavaScript sources but to utilizing the AAPS Kotlin-based oref-rewrite (some time down the road, lol), so I don't think changing JS sources is a win. This is a good compromise and hits the middle ground. Also, with a major rewrite of the persistence layer to core data, logging will inherently [need to] change anyways, so I think an overall look at "how can we improve logging" will be necessary then anyways. Maybe you'd be up to also chime in there and support that effort 🚀 I'm but one opinion here though, lets see what others think 🤔 Thank you for your work here and putting this up as a proposal 👏 |
|
I’m going to split up this PR. There are 2 items:
I’ll tag the PR once I’m done, but let’s not close this PR for now so others can chime in if they want. |
|
I'll convert this into a draft so it still stays open and visible here in the repository, but isn't considered as "we need to look at this, review it, get it merged" type TODO. |
This is my first attempt at swift language. Any criticism welcome!
The formating of javascript console log is not formatted in a way that it is easy for others to read, or created automation around in parsing it. I suggestion here is to us as minimal code as possible to format the logs without it being a word to word regex replacement.
This can be tweaked and tailored, and some 'fixed' values could be addressed in a seperate method, but this is my first implementation.
This should also reduce the size of the log file considerably.
Let me know what you think!