Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

fix: cleanup log output #345

Merged
merged 18 commits into from
Oct 14, 2024
Merged

Conversation

mkellerman
Copy link
Contributor

Fix for #272

  • Removal of unneeded lines from autosens output
  • Removal of empty lines throughout console output
  • Added the context of the logs (ie: prepare/autosens.js, Middleware)

Reference to previous PR #331

New output:

OpenAPS.swift - autosense() - 305 DEV: Start autosens
JavaScriptWorker.swift - outputLogs() - 76 DEV: prepare/autosens.js: Using most recent,104,deviations since,Thu Jul 04 2024 19:37:44 GMT-0700 (Pacific Daylight Saving Time)
JavaScriptWorker.swift - outputLogs() - 76 DEV: prepare/autosens.js: 47% of non-meal deviations positive (>50% = resistance)
JavaScriptWorker.swift - outputLogs() - 76 DEV: prepare/autosens.js: 41% of non-meal deviations negative (>50% = sensitivity)
JavaScriptWorker.swift - outputLogs() - 76 DEV: prepare/autosens.js: RMS deviation: 6.68
JavaScriptWorker.swift - outputLogs() - 76 DEV: prepare/autosens.js: Sensitivity normal.
JavaScriptWorker.swift - outputLogs() - 76 DEV: prepare/autosens.js: ISF adjusted from 54 to 54
JavaScriptWorker.swift - outputLogs() - 76 DEV: prepare/autosens.js: Using most recent,288,deviations since,Thu Jul 04 2024 19:37:44 GMT-0700 (Pacific Daylight Saving Time)
JavaScriptWorker.swift - outputLogs() - 76 DEV: prepare/autosens.js: 39% of non-meal deviations positive (>50% = resistance)
JavaScriptWorker.swift - outputLogs() - 76 DEV: prepare/autosens.js: 47% of non-meal deviations negative (>50% = sensitivity)
JavaScriptWorker.swift - outputLogs() - 76 DEV: prepare/autosens.js: RMS deviation: 6.29
JavaScriptWorker.swift - outputLogs() - 76 DEV: prepare/autosens.js: Sensitivity normal.
JavaScriptWorker.swift - outputLogs() - 76 DEV: prepare/autosens.js: ISF adjusted from 54 to 54
OpenAPS.swift - autosense() - 321 DEV: AUTOSENS: {
    "ratio": 1,
    "newisf": 54
}
OpenAPS.swift - determineBasal(currentTemp:clock:) - 21 DEV: Start determineBasal
JavaScriptWorker.swift - outputLogs() - 76 DEV: Middleware: Middleware reason: Nothing changed
JavaScriptWorker.swift - outputLogs() - 76 DEV: Middleware: Pumphistory is empty!
JavaScriptWorker.swift - outputLogs() - 76 DEV: Middleware: insulinFactor set to : 55
JavaScriptWorker.swift - outputLogs() - 76 DEV: Middleware: Using weighted TDD average: 1 U, instead of past 24 h (0 U), weight: 0.65
JavaScriptWorker.swift - outputLogs() - 76 DEV: Middleware: , Dynamic ratios log: Dynamic Settings disabled
JavaScriptWorker.swift - outputLogs() - 76 DEV: Middleware: Default Half Basal Target used: 8.9 mmol/L
JavaScriptWorker.swift - outputLogs() - 76 DEV: Middleware: Autosens ratio: 1;
JavaScriptWorker.swift - outputLogs() - 76 DEV: Middleware: Threshold set to 3.9
JavaScriptWorker.swift - outputLogs() - 76 DEV: Middleware: ISF unchanged: 3
JavaScriptWorker.swift - outputLogs() - 76 DEV: Middleware: CR:10
JavaScriptWorker.swift - outputLogs() - 76 DEV: Middleware: currenttemp:0 lastTempAge:28670558m, tempModulus:8m
JavaScriptWorker.swift - outputLogs() - 76 DEV: Middleware: SMB disabled (no enableSMB preferences active or no condition satisfied)
JavaScriptWorker.swift - outputLogs() - 76 DEV: Middleware: profile.sens:3, sens:3, CSF:5.4
JavaScriptWorker.swift - outputLogs() - 76 DEV: Middleware: Carb Impact:4.1mg/dL per 5m; CI Duration:0hours; remaining CI (1.5h peak):0mg/dL per 5m
JavaScriptWorker.swift - outputLogs() - 76 DEV: Middleware: UAM Impact:4.1mg/dL per 5m; UAM Duration:0.2hours
JavaScriptWorker.swift - outputLogs() - 76 DEV: Middleware: minPredBG: 260 minIOBPredBG: 260 minZTGuardBG: 237
JavaScriptWorker.swift - outputLogs() - 76 DEV: Middleware: avgPredBG:260 COB/Carbs:0/0
JavaScriptWorker.swift - outputLogs() - 76 DEV: Middleware: BG projected to remain above 5.5 for 240minutes
JavaScriptWorker.swift - outputLogs() - 76 DEV: Middleware: naive_eventualBG:,237,bgUndershoot:,-167.5,zeroTempDuration:,240,zeroTempEffect:,216,carbsReq:,-71
JavaScriptWorker.swift - outputLogs() - 76 DEV: Middleware: NaN (. insulinReq: 2.98 U)
JavaScriptWorker.swift - outputLogs() - 76 DEV: Middleware: NaN (. insulinForManualBolus: 3 U)
JavaScriptWorker.swift - outputLogs() - 76 DEV: Middleware: Setting neutral temp basal of 1U/hr
OpenAPS.swift - determineBasal(currentTemp:clock:) - 80 DEV: SUGGESTED: {
    "temp": "absolute",
    "bg": 237,
...

@mkellerman
Copy link
Contributor Author

@marionbarker would you mind running your scripts to see the diff in log size? Thanks!

@marionbarker
Copy link
Contributor

I applied this patch about a day and a half ago to latest Trio - dev (at the time).
Then I got busy.
Attached is a full 24-hour log.

  • iPhone SE running iOS 17.5.1 with rPi DASH simulator and using a test Nightscout site as a CGM (uploaded some significant glucose excursions).
  • My python Omnipod parser works fine with this file. (It automatically renames the log_prev files with the date)

20240706_log_prev.txt

  • wc reports: 66773 510135 5702930 20240706_log_prev.txt

    • for those who don't speak unix: the numbers are lines, words, characters
  • So per hour: 2782 lines; 237k characters.

From this comment, the prior art was about 3.3k lines/hour, 288k characters/hour.

The graphic is the NS site used with this test phone.

ns-trio-with-pr-345

marionbarker
marionbarker previously approved these changes Jul 7, 2024
Copy link
Contributor

@marionbarker marionbarker left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Giving my approval based on the fact it works for providing record of Omnipod messages.

Someone else more familiar with these logs should examine the result for other content.

@mkellerman
Copy link
Contributor Author

I recommend a Squash & Merge. My history is a lot of trial and error.

@mountrcg
Copy link
Contributor

mountrcg commented Jul 7, 2024

I will have a look at the logs tonight

@mountrcg
Copy link
Contributor

looking at the log that Marion attached

  1. there still are still a lot of lines for autosens
Bildschirmfoto 2024-07-10 um 06 55 18
  1. middleware actually only outputs the first green boxed line, the remaining is determine-basal output - you could call that Algorithm or oref
Bildschirmfoto 2024-07-10 um 06 55 55

@mountrcg
Copy link
Contributor

mountrcg commented Jul 11, 2024

@mkellerman The content pf the logging is totally readable and fine with me. I suggest that you give the RED marked part another context e.g. like oref, but not middleware.
I am not sure whether you did not want to achieve more congestions with autosens like putting it all in one long line as Dan suggested - or is this done in the second PR?

Edit: changed green to RED, that was a mistake by me

@mkellerman
Copy link
Contributor Author

@mountrcg, i'm unable to reproduce the autosens logs like you. Mine get trimmed correctly. Maybe something to do with Timezone/Language formatting?

Regarding 'Middleware', this is autogenerated by how we call the JavaScriptWorker... I didn't name these individually.

@mkellerman
Copy link
Contributor Author

@marionbarker @mountrcg posted a new fix that might resolve the issue.

@marionbarker
Copy link
Contributor

Summary:

Log files and time stamps are provided for someone else to review.
The message parser works fine with this code applied.

Configuration:

  • Starting configuration (yesterday) had both this PR (345) and PR 353 installed on top of most recent dev, commit 9672da25
  • This morning rebuild to each phone with the PR 353 patch applied but without this PR (remove the logging changes)

Medtronic Log:

  • This log had PR 345 installed until 06:50 local time
  • Use search term is DEV: Trio Started:
  • 20240718_MDT-log.txt

Omnipod DASH Log:

The Omnipod messages are not affected by the logging changes, the parser still works for code both with and without PR 346 applied.

@mkellerman
Copy link
Contributor Author

Thanks @marionbarker ! I dont get any of those u(xxxx) in my logs, so it's really hard to debug this one on my own. But i did fix the regex to include this pattern. it should be fixed now.

@marionbarker
Copy link
Contributor

Downloaded new patch and built to

  • Medtronic Phone at 2024-07-18 21:37 local
  • Pod Phone at 2024-07-18 21:40 local

Both phones are also running changes from PR 353.

Below are the log files (so since midnight local on 2024-07-19) acquired around 05:50 am

MDT:

Pod:

  • The pod one had a failure of the rPi simulator at 2024-07-19T05:32 (nothing to do with Trio, it just happens sometimes)
  • Resumed the rPi a few minutes before issuing the log
  • Omnipod message parser works fine with the file
  • 2024-07-19-Trio-DASH-with-prs-345-353-log.txt

@marionbarker
Copy link
Contributor

Not seeing much improvement. Still seeing Middleware a lot and I think that's what was making @mountrcg unhappy.

Uploading the log file and the patch I used in case I didn't do the modification correctly.

iPhone 8 running iOS 16.7.8
started with dev commit dff37ac then applied this patch:

I rebuilt a couple of times this morning. The final time was with the patch applied (for sure). Using an rPi DASH simulator as a pump. The Omnipod Message parser still works as expected.

2024-07-25T11:09:08-0700 [Default] FreeAPSApp.swift - init() - 56 - DEV: Trio Started: v0.1.0(1) [buildDate: nil] [buildExpires: Optional(2025-07-21 14:38:28 +0000)]

log file:

@mkellerman
Copy link
Contributor Author

@marionbarker I think i found the line that uses 'Middleware' that might be affecting you (as i dont see it in my logs). Let me know if that resolves it for you now. (no rush, clearly we are focusing on the RC).

@marionbarker
Copy link
Contributor

Configuration

  • Start with Trio-dev commit 08eba43 (tag: 0.2.0-rc1)
  • Phone is using Nightscout as a CGM and rPi DASH simulator
  • Apply this patch.
  • Build started at:
2024-07-30T06:30:15-0700 [Default] FreeAPSApp.swift - init() - 56 - DEV: Trio Started: v0.2.0(1) [buildDate: nil] [buildExpires: Optional(2025-07-28 19:51:50 +0000)]

The Omnipod parser code works fine with this log file.

Trim the log file to start when new build was started.

@mountrcg
Copy link
Contributor

mountrcg commented Aug 1, 2024

Dear @mkellerman I looked at the log output with the current changes. As shown by you further up it is like this:

JavaScriptWorker.swift - outputLogs() - 78 DEV: middleware/determine_basal.js: , Dynamic ratios log: Dynamic Settings disabled

compared to before the changes in this PR

JavaScriptWorker.swift - outputLogs() - 78 DEV: determine_basal.js: , Dynamic ratios log: Dynamic Settings disabled

This does not add any meaningful context, it just increase the logging size by adding the middleware/ part, which is counter-productive to your goal to reduce size.

Middleware here has nothing to do with the log output determine_basal.js creates. middleware as in

only injects certain values into determine_basal.js but does not affect the logging output of those lines you marked at all. Therefore I think those lines should not be marked with middleware/.
The only line it affects is the line after Start determineBasal

OpenAPS.swift - determineBasal(currentTemp:clock:) - 21 DEV: Start determineBasal
JavaScriptWorker.swift - outputLogs() - 78 DEV: middleware/determine_basal.js: Middleware reason: Nothing changed

which is already marked and searchable. I would suggest to skip your middleware marking, without knowing how you do your magic :-)

@bjornoleh
Copy link
Contributor

@mountrcg , I am unsure if @mkellerman knows what middleware is and how it is used in the context of Trio? If so, perhaps you could explain and give an example?

@mkellerman
Copy link
Contributor Author

I'm aware of what middleware does, but I'm printing the script that is executed. I'm not naming things myself. Please look at the code change to see how this value is evaluated.

In my opinion, if we don't want middleware/*.js, we should change the name of the file. The point of the log is to show you what file ran and what console output was provided.

Which shouldn't be part of this fix. This is only to cleanup the autosens logs.

@mountrcg
Copy link
Contributor

Hi @mkellerman ,

@dnzxy and myself looked at again.

Still does the middleware thing via file structure on oref output, as middleware wraps around the oref call to set values that normally be calculated by oref or be profile.settings.
It is misleading to show it in the log, when only the first line comes from middleware adjustments and it even increases the text before the actual information . I think that goes against the original intent. May be ommit the directory information?
That seems to be used only on autotune and determin-basal, may be on autosens too - that hasn't popped for me yet. But even if so the information would be unique without the directory.

OpenAPS.swift - determineBasal(currentTemp:clock:) - 18 DEV: Start determineBasal
JavaScriptWorker.swift - outputLogs() - 78 DEV: middleware/determine_basal.js: Middleware reason: Nothing changed
JavaScriptWorker.swift - outputLogs() - 78 DEV: middleware/determine_basal.js: then minutesAgo = 5 avgDelta = -8
JavaScriptWorker.swift - outputLogs() - 78 DEV: middleware/determine_basal.js: then minutesAgo = 10 avgDelta = -5.5
JavaScriptWorker.swift - outputLogs() - 78 DEV: middleware/determine_basal.js: then minutesAgo = 15 avgDelta = 0.33
JavaScriptWorker.swift - outputLogs() - 78 DEV: middleware/determine_basal.js: then minutesAgo = 20 avgDelta = 0.5
JavaScriptWorker.swift - outputLogs() - 78 DEV: middleware/determine_basal.js: then minutesAgo = 25 avgDelta = 0.6
JavaScriptWorker.swift - outputLogs() - 78 DEV: middleware/determine_basal.js: then minutesAgo = 30 avgDelta = 1.5
JavaScriptWorker.swift - outputLogs() - 78 DEV: middleware/determine_basal.js: then minutesAgo = 35 avgDelta = 2.14
JavaScriptWorker.swift - outputLogs() - 78 DEV: middleware/determine_basal.js: then minutesAgo = 40 avgDelta = 2
JavaScriptWorker.swift - outputLogs() - 78 DEV: middleware/determine_basal.js: then minutesAgo = 45 avgDelta = 1.89
JavaScriptWorker.swift - outputLogs() - 78 DEV: middleware/determine_basal.js: most actual available avgDelta = -8
JavaScriptWorker.swift - outputLogs() - 78 DEV: middleware/determine_basal.js: Basal unchanged: 1;
JavaScriptWorker.swift - outputLogs() - 78 DEV: middleware/determine_basal.js: SMB Threshold set to 0.5 - no SMB's applied below 63

@mkellerman
Copy link
Contributor Author

Sorry for the slow response. Good idea on using only the filename, and not the folder. I'm doing a fix now. Should be up for review shortly!

@mkellerman
Copy link
Contributor Author

Does this work for everyone?

JavaScriptWorker.swift - outputLogs() - 77 DEV: determine_basal.js: Middleware reason: Nothing changed
JavaScriptWorker.swift - outputLogs() - 77 DEV: determine_basal.js: Pumphistory is empty!
JavaScriptWorker.swift - outputLogs() - 77 DEV: determine_basal.js: insulinFactor set to : 55
JavaScriptWorker.swift - outputLogs() - 77 DEV: determine_basal.js: Using weighted TDD average: 1 U, instead of past 24 h (0 U), weight: 0.65
JavaScriptWorker.swift - outputLogs() - 77 DEV: determine_basal.js: , Dynamic ratios log: Dynamic Settings disabled
JavaScriptWorker.swift - outputLogs() - 77 DEV: determine_basal.js: Default Half Basal Target used: 8.9 mmol/L
JavaScriptWorker.swift - outputLogs() - 77 DEV: determine_basal.js: Autosens ratio: 1;
JavaScriptWorker.swift - outputLogs() - 77 DEV: determine_basal.js: Threshold set to 3.9
JavaScriptWorker.swift - outputLogs() - 77 DEV: determine_basal.js: ISF unchanged: 3
JavaScriptWorker.swift - outputLogs() - 77 DEV: determine_basal.js: CR:10
JavaScriptWorker.swift - outputLogs() - 77 DEV: determine_basal.js: currenttemp:0 lastTempAge:28783811m, tempModulus:11m
JavaScriptWorker.swift - outputLogs() - 77 DEV: determine_basal.js: SMB disabled (no enableSMB preferences active or no condition satisfied)
JavaScriptWorker.swift - outputLogs() - 77 DEV: determine_basal.js: profile.sens:3, sens:3, CSF:5.4
JavaScriptWorker.swift - outputLogs() - 77 DEV: determine_basal.js: Carb Impact:-1.2mg/dL per 5m; CI Duration:0hours; remaining CI (1.5h peak):0mg/dL per 5m
JavaScriptWorker.swift - outputLogs() - 77 DEV: determine_basal.js: UAM Impact:-1.2mg/dL per 5m; UAM Duration:0hours
JavaScriptWorker.swift - outputLogs() - 77 DEV: determine_basal.js: minPredBG: 101 minIOBPredBG: 101 minZTGuardBG: 108
JavaScriptWorker.swift - outputLogs() - 77 DEV: determine_basal.js: avgPredBG:108 COB/Carbs:0/0
JavaScriptWorker.swift - outputLogs() - 77 DEV: determine_basal.js: BG projected to remain above 5.5 for 240minutes

@mkellerman
Copy link
Contributor Author

OpenAPS.swift - autosense() - 305 DEV: Start autosens
JavaScriptWorker.swift - outputLogs() - 77 DEV: autosens.js: Using most recent,104,deviations since,Sat Sep 21 2024 11:09:58 GMT-0700 (Pacific Daylight Saving Time
JavaScriptWorker.swift - outputLogs() - 77 DEV: autosens.js: 38% of non-meal deviations positive (>50% = resistance
JavaScriptWorker.swift - outputLogs() - 77 DEV: autosens.js: 46% of non-meal deviations negative (>50% = sensitivity
JavaScriptWorker.swift - outputLogs() - 77 DEV: autosens.js: RMS deviation: 4.93
JavaScriptWorker.swift - outputLogs() - 77 DEV: autosens.js: Sensitivity normal.
JavaScriptWorker.swift - outputLogs() - 77 DEV: autosens.js: ISF adjusted from 54 to 54
JavaScriptWorker.swift - outputLogs() - 77 DEV: autosens.js: Using most recent,288,deviations since,Sat Sep 21 2024 11:09:58 GMT-0700 (Pacific Daylight Saving Time
JavaScriptWorker.swift - outputLogs() - 77 DEV: autosens.js: 41% of non-meal deviations positive (>50% = resistance
JavaScriptWorker.swift - outputLogs() - 77 DEV: autosens.js: 45% of non-meal deviations negative (>50% = sensitivity
JavaScriptWorker.swift - outputLogs() - 77 DEV: autosens.js: RMS deviation: 7.20
JavaScriptWorker.swift - outputLogs() - 77 DEV: autosens.js: Sensitivity normal.
JavaScriptWorker.swift - outputLogs() - 77 DEV: autosens.js: ISF adjusted from 54 to 54
OpenAPS.swift - autosense() - 321 DEV: AUTOSENS: {
    "ratio": 1,
    "newisf": 54
}

@mkellerman
Copy link
Contributor Author

Any other suggestions? Would love to get this one merged in.

@dnzxy
Copy link
Contributor

dnzxy commented Sep 28, 2024

Personally happy with this. Approving.
However, we may want to just move this into TCD (1.0-dev). Either, or, LGTM.

@marionbarker
Copy link
Contributor

Status

Success

Configuration

  • iPhone 8 connected to an Eros pod.
  • Running with Trio dev branch initially.
  • 2024-10-13 16:56 Save a log.txt file before building to new version.
  • 2024-10-13 17:04 switched to fix-autosens-logs, commit b94606cc
  • 2024-10-13 20:25 share logs again

Results

Omnipod parser still works with modified logs.

Log Sizes:

  • initial log.txt was 8.4 MB with ~17 hours of data (0.5 MB/hr)
  • second log.txt was 9.9 MB with additional ~3.5 hours of data
    • delta of 1.5 MB in 4 hours (0.42 MB/hr)
  • some decrease is rate of size/hr

a few side-by-side screen shots.

before-after-log-01

before-after-log-02

before-after-log-03

Log file acquired at 2024-10-13 20:25

  • Time before 2024-10-13 17:04 standard Trio dev branch
  • Time afterwards with fix-autosens-logs version

log-after.txt

@marionbarker
Copy link
Contributor

Here is an additional log with only this build. The phone was locked overnight until just before sharing the log. The log size (2.7 MB) for about 6.5 hours is still in the range of 0.42 MB/hr.

20241014-partial_log.txt

Copy link
Contributor

@Sjoerd-Bo3 Sjoerd-Bo3 left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM, output is way cleaner. And the code and regex are concise. Good work @mkellerman !
Finally we are done with the bloating logs from JS

@Sjoerd-Bo3 Sjoerd-Bo3 merged commit eccd566 into nightscout:dev Oct 14, 2024
1 check passed
@mkellerman mkellerman deleted the fix-autosens-logs branch October 22, 2024 16:40
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

7 participants