Closed mkellerman closed 1 month ago
@marionbarker would you mind running your scripts to see the diff in log size? Thanks!
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.
wc reports: 66773 510135 5702930 20240706_log_prev.txt
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.
I recommend a Squash & Merge. My history is a lot of trial and error.
I will have a look at the logs tonight
looking at the log that Marion attached
there still are still a lot of lines for autosens
middleware actually only outputs the first green boxed line, the remaining is determine-basal output - you could call that Algorithm or oref
@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
@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.
@marionbarker @mountrcg posted a new fix that might resolve the issue.
Log files and time stamps are provided for someone else to review. The message parser works fine with this code applied.
9672da25
DEV: Trio Started:
DEV: Trio Started:
The Omnipod messages are not affected by the logging changes, the parser still works for code both with and without PR 346 applied.
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.
Downloaded new patch and built to
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:
2024-07-19T05:32
(nothing to do with Trio, it just happens sometimes)MDT logs:
024-07-19T00:52:38-0700 [OpenAPS] OpenAPS.swift - makeProfiles(useAutotune:) - 376 - DEV: Start makeProfiles
2024-07-19T00:52:38-0700 [OpenAPS] OpenAPS.swift - autosense() - 305 - DEV: Start autosens
2024-07-19T00:52:39-0700 [Nightscout] TidepoolManager.swift - uploadDose() - 305 - DEV: Success synchronizing Dose data:
2024-07-19T00:52:40-0700 [OpenAPS] JavaScriptWorker.swift - outputLogs() - 78 - DEV: prepare/autosens.js: Using most recent,35,deviations since,Thu Jul 18 2024 00:52:38 GMT-0700 (Pacific Daylight Time
2024-07-19T00:52:40-0700 [OpenAPS] JavaScriptWorker.swift - outputLogs() - 78 - DEV: prepare/autosens.js: Adding,11,more zero deviations
2024-07-19T00:52:40-0700 [OpenAPS] JavaScriptWorker.swift - outputLogs() - 78 - DEV: prepare/autosens.js: 29% of non-meal deviations positive (>50% = resistance
2024-07-19T00:52:40-0700 [OpenAPS] JavaScriptWorker.swift - outputLogs() - 78 - DEV: prepare/autosens.js: 23% of non-meal deviations negative (>50% = sensitivity
2024-07-19T00:52:40-0700 [OpenAPS] JavaScriptWorker.swift - outputLogs() - 78 - DEV: prepare/autosens.js: RMS deviation: 1.29
2024-07-19T00:52:40-0700 [OpenAPS] JavaScriptWorker.swift - outputLogs() - 78 - DEV: prepare/autosens.js: Sensitivity normal.
2024-07-19T00:52:40-0700 [OpenAPS] JavaScriptWorker.swift - outputLogs() - 78 - DEV: prepare/autosens.js: ISF adjusted from 70 to 70
2024-07-19T00:52:40-0700 [OpenAPS] JavaScriptWorker.swift - outputLogs() - 78 - DEV: prepare/autosens.js: Using most recent,35,deviations since,Thu Jul 18 2024 00:52:39 GMT-0700 (Pacific Daylight Time
2024-07-19T00:52:40-0700 [OpenAPS] JavaScriptWorker.swift - outputLogs() - 78 - DEV: prepare/autosens.js: Adding,11,more zero deviations
2024-07-19T00:52:40-0700 [OpenAPS] JavaScriptWorker.swift - outputLogs() - 78 - DEV: prepare/autosens.js: 29% of non-meal deviations positive (>50% = resistance
2024-07-19T00:52:40-0700 [OpenAPS] JavaScriptWorker.swift - outputLogs() - 78 - DEV: prepare/autosens.js: 23% of non-meal deviations negative (>50% = sensitivity
2024-07-19T00:52:40-0700 [OpenAPS] JavaScriptWorker.swift - outputLogs() - 78 - DEV: prepare/autosens.js: RMS deviation: 1.29
2024-07-19T00:52:40-0700 [OpenAPS] JavaScriptWorker.swift - outputLogs() - 78 - DEV: prepare/autosens.js: Sensitivity normal.
2024-07-19T00:52:40-0700 [OpenAPS] JavaScriptWorker.swift - outputLogs() - 78 - DEV: prepare/autosens.js: ISF adjusted from 70 to 70
2024-07-19T00:52:40-0700 [OpenAPS] OpenAPS.swift - autosense() - 321 - DEV: AUTOSENS: {
"ratio": 1,
"newisf": 70
}
2024-07-19T00:52:40-0700 [OpenAPS] OpenAPS.swift - determineBasal(currentTemp:clock:) - 21 - DEV: Start determineBasal
DASH logs:
2024-07-19T00:26:28-0700 [OpenAPS] OpenAPS.swift - makeProfiles(useAutotune:) - 376 - DEV: Start makeProfiles
2024-07-19T00:26:28-0700 [OpenAPS] OpenAPS.swift - autosense() - 305 - DEV: Start autosens
2024-07-19T00:26:30-0700 [OpenAPS] JavaScriptWorker.swift - outputLogs() - 78 - DEV: prepare/autosens.js: Using most recent,97,deviations since,Thu Jul 18 2024 00:26:28 GMT-0700 (Pacific Daylight Time
2024-07-19T00:26:30-0700 [OpenAPS] JavaScriptWorker.swift - outputLogs() - 78 - DEV: prepare/autosens.js: 77% of non-meal deviations positive (>50% = resistance
2024-07-19T00:26:30-0700 [OpenAPS] JavaScriptWorker.swift - outputLogs() - 78 - DEV: prepare/autosens.js: 17% of non-meal deviations negative (>50% = sensitivity
2024-07-19T00:26:30-0700 [OpenAPS] JavaScriptWorker.swift - outputLogs() - 78 - DEV: prepare/autosens.js: RMS deviation: 3.77
2024-07-19T00:26:30-0700 [OpenAPS] JavaScriptWorker.swift - outputLogs() - 78 - DEV: prepare/autosens.js: Insulin resistance detected:
2024-07-19T00:26:30-0700 [OpenAPS] JavaScriptWorker.swift - outputLogs() - 78 - DEV: prepare/autosens.js: Ratio limited from 1.5019607843137255 to 1.2
2024-07-19T00:26:30-0700 [OpenAPS] JavaScriptWorker.swift - outputLogs() - 78 - DEV: prepare/autosens.js: ISF adjusted from 72 to 60
2024-07-19T00:26:30-0700 [OpenAPS] JavaScriptWorker.swift - outputLogs() - 78 - DEV: prepare/autosens.js: Using most recent,192,deviations since,Thu Jul 18 2024 00:26:29 GMT-0700 (Pacific Daylight Time
2024-07-19T00:26:30-0700 [OpenAPS] JavaScriptWorker.swift - outputLogs() - 78 - DEV: prepare/autosens.js: 72% of non-meal deviations positive (>50% = resistance
2024-07-19T00:26:30-0700 [OpenAPS] JavaScriptWorker.swift - outputLogs() - 78 - DEV: prepare/autosens.js: 22% of non-meal deviations negative (>50% = sensitivity
2024-07-19T00:26:30-0700 [OpenAPS] JavaScriptWorker.swift - outputLogs() - 78 - DEV: prepare/autosens.js: RMS deviation: 4.12
2024-07-19T00:26:30-0700 [OpenAPS] JavaScriptWorker.swift - outputLogs() - 78 - DEV: prepare/autosens.js: Insulin resistance detected:
2024-07-19T00:26:30-0700 [OpenAPS] JavaScriptWorker.swift - outputLogs() - 78 - DEV: prepare/autosens.js: Ratio limited from 1.380392156862745 to 1.2
2024-07-19T00:26:30-0700 [OpenAPS] JavaScriptWorker.swift - outputLogs() - 78 - DEV: prepare/autosens.js: ISF adjusted from 72 to 60
2024-07-19T00:26:30-0700 [OpenAPS] OpenAPS.swift - autosense() - 321 - DEV: AUTOSENS: {
"ratio": 1.2,
"newisf": 60
}
2024-07-19T00:26:30-0700 [OpenAPS] OpenAPS.swift - determineBasal(currentTemp:clock:) - 21 - DEV: Start determineBasal
I think this does the expected behaviour! Thanks @marionbarker for all the testing!
@mkellerman I am quite sorry you must be frustrated and I admire your efforts and also would not how to do anything ... that said I can still not understand the intention of the new labeling and the definition of those labels in the messages. Middleware is a quite defined name for injecting some totally algorythm overriding code. That is only displayed in the log as exactly one line. In the example below the first one. All other log outputs below come from a file determine-basal, which basically is 90% of oref. Labelling that log output Middleware is quite misleading and does not reflect that this small this small injection js code snippet only does a very limited thing and not all of those calcs and so on ...
2024-07-20T16:10:53+0200 [OpenAPS] JavaScriptWorker.swift - outputLogs() - 78 - DEV: Middleware: Middleware reason: MW did something dangerous to ISF!
2024-07-20T16:10:53+0200 [OpenAPS] JavaScriptWorker.swift - outputLogs() - 78 - DEV: Middleware: currenttemp:0 lastTempAge:2m, tempModulus:29m
2024-07-20T16:10:53+0200 [OpenAPS] JavaScriptWorker.swift - outputLogs() - 78 - DEV: Middleware: profile.sens:1, sens:51, CSF:5.1
2024-07-20T16:10:53+0200 [OpenAPS] JavaScriptWorker.swift - outputLogs() - 78 - DEV: Middleware: Carb Impact:-5mg/dL per 5m; CI Duration:0hours; remaining CI (1.5h peak):,0mg/dL per 5m
2024-07-20T16:10:53+0200 [OpenAPS] JavaScriptWorker.swift - outputLogs() - 78 - DEV: Middleware: UAM Impact:-5mg/dL per 5m; UAM Duration:0hours
2024-07-20T16:10:53+0200 [OpenAPS] JavaScriptWorker.swift - outputLogs() - 78 - DEV: Middleware: minPredBG: 53 minIOBPredBG: 40 minZTGuardBG: 66
I did not intend to propose my hack as a real change - just to show that got rid of the inappropriate Middleware
label.
I'm not sure @mountrcg will approve this PR with the Middleware
labeling issue.
It would be better for you to find and fix the error now, then I think this could get merged.
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 dff37ac2 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:
@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).
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.
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 :-)
@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?
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.
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
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!
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
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
}
Any other suggestions? Would love to get this one merged in.
Personally happy with this. Approving. However, we may want to just move this into TCD (1.0-dev). Either, or, LGTM.
Success
b94606cc
Omnipod parser still works with modified logs.
Log Sizes:
a few side-by-side screen shots.
Log file acquired at 2024-10-13 20:25
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.
Fix for #272
prepare/autosens.js
,Middleware
)Reference to previous PR #331
New output: