search

urbandroid-team / Sleep-as-Android-Garmin-Addon

Code for both Android part and Garmin part of the Sleep as Android Garmin smartwatch integration
49 stars 15 forks source link

Sleep tracking crashes about a quarter into the night #10

Closed aaronjwood closed 2 years ago

aaronjwood commented 6 years ago

Since the rewrite was released everything was working for me. Just recently things stopped working and now sleep tracking crashes a few hours after I've fallen asleep. I wake up in the morning to see my watch on my default widget. This happens regardless of how I start tracking (from the phone/watch) and is now consistent every time I use the app. I've tried to look for logs in the device but didn't see anything from this addon. I did find something in the ERR_LOG.TXT file under GARMIN/DEBUG:

2697 (fenix 5) SW ver: 1000
Build Type: RELEASE
Commit:bef5fea663aeec52575bd5b5b91e2d15afc92b7d
ESN: 3962006839
10/07/18 02:17:42
RTL
errnum: 0x00a
r0: 0x2005bd40
r1: 0x00000063
r2: 0x0000007e
r3: 0x0000007f
r4: 0x000a4a49
Stack frame PC, SP: 0x000cceb9, 0x2005b948
Call Stack - SP at 0x2005b948:
    0x000704cf
    0x000a4a49
    0x0008cba5
    0x000a4a49
    0x000a4a49
    0x0008d82d
    0x000a551d
    0x0001011d
    0x0000b475
    0x00070675
    0x0008d82d
    0x0008d82d
    0x0008d6bd
    0x00020075
    0x000a4c89
    0x00027983
    0x0002621b
    0x0001fdeb
    0x0008d82d
    0x0008d6bd
    0x0008d6db
    0x0008e9a5
    0x0004f255
    0x0004f0ad
    0x0005d523
    0x00011985
    0x0005d571
    0x0005d57d
    0x0008ea8b
    0x000e5b47
    0x0008b80d
    0x00000000
Uptime: 4880819

It looks like I should be seeing a log file specifically for the app. If you guys make another release with logging enabled I'd be happy to share the logs and help debug the issue.

Artaud commented 6 years ago

Thanks, I've posted this stack trace on the Garmin CIQ forums as this is something the Garmin people need to decipher. Link to the thread: https://forums.garmin.com/forum/developers/connect-iq/1411125-watch-app-stops-randomly-after-running-for-1-hour

As far as I know, it is not possible to do debug logs in a release version of the app, so I cannot gather logs from users who download the app via the Connect IQ store. If you want to do debug logging, you need to sideload the app. Can you build it for yourself? Or I can build it for you if you want.

aaronjwood commented 6 years ago

Sure, I'll build + sideload it. Give me a few weeks and I should hopefully have some logs for you.

hAmpzter commented 6 years ago

Hey. What Watch are you running it on @aaronjwood ? I'm using a Fenix 5 and are having the same issue. Is it a big task to compile and sideload an application for and Garmin-device? If I could do the same and maybe be able to give some more help.. Edit: I now saw at the top of the log-file that it says that you have a Fenix 5.. Lol! Anyhow question 2 still valid.

aaronjwood commented 6 years ago

I'm using a Fenix 5 as well. I don't think it should be a big task, I just haven't had the time to get to it yet.

hAmpzter commented 6 years ago

Is it the garmind.debug.xml that you need or how do I enable debugging?

MrFly commented 6 years ago

Same issues here with VA3. Can I help you?

hAmpzter commented 6 years ago

I tried with a own compiled app on my watch yesterday but I don't now how to get good logging of the Garmin-eco-system. Do you know @MrFly ?

MrFly commented 6 years ago

I'm sorry, no. Think it has to he enabled in the app (programatically), then there could be many good log files on the watch.

aaronjwood commented 6 years ago

Was thinking we could make use of https://github.com/urbandroid-team/Sleep-as-Android-Garmin-Addon/blob/6ee44db814ffb86370c92b56c7bf0ba8fd29c6c4/SleepGarmin-watch/source/SleepApp.mc#L48

Need to create the log file yourself though. I'm not seeing an API to create this file, it looks like the user has to go in and create the file manually through USB mode?!?!

MrFly commented 6 years ago

Seems that it is only possible with a manually deployed debug version of the app (comment on the following line)

aaronjwood commented 6 years ago

Yeah, hoping it's as easy as building a debug version, loading it to the watch, and creating the text file for logs.

@Artaud where did you guys find that logs only work in debug builds? I've seen some of the Garmin devs on their forums say that Sys.println() should still work in release builds, it's just on the user to create that log file themselves.

aaronjwood commented 6 years ago

Just tried this out, all you need to do is create the log file on the device. No need for a debug build. I just created 88G34652.txt in the LOGS folder and ran a super quick sleep tracking event:

1539676388: Registering for Phone Messages
1539676388: Incoming mail: SetAlarm;1539013200000
1539676388: Alarm set to 2147483647
1539676388: Incoming mail: StopApp
1539676389: Message not handledStopApp
1539676389: --onStart--
1539676389: free: 104568
1539676389: Adding to q:STARTING outQ: [STARTING]
1539676389: getInitialView
1539676389: SleepMainView initialize
1539676389: SleepMainDelegate initialize
1539676389: 2
1539676389: onUpdate
1539676389: onUpdate
1539676389: onUpdate
1539676389: Send next message STARTING
1539676389: onUpdate
1539676390: msgQ: []
1539676390: STARTINGsent OK
1539676391: onKey: 8
1539676391: scrollUp
1539676391: Refreshing View
1539676391: onUpdate
1539676392: onKey: 8
1539676392: scrollUp
1539676392: Refreshing View
1539676392: onUpdate
1539676393: onKey: 8
1539676393: scrollUp
1539676393: Refreshing View
1539676393: onUpdate
1539676394: Incoming mail: SetAlarm;1539704400000
1539676394: Alarm set to 2147483647
1539676394: onKey: 8
1539676394: scrollUp
1539676394: Refreshing View
1539676394: onUpdate
1539676397: Incoming mail: StartHRTracking
1539676397: Switched trackingBool to true
1539676397: changed view to tracking
1539676397: onUpdate
1539676401: Incoming mail: StartTracking
1539676405: onKey: 4
1539676405: onSelect
1539676405: returnCentre
1539676405: Refreshing View
1539676405: changed view to tracking
1539676405: onUpdate
1539676405: Incoming mail: Pause;1539677289965
1539676407: onKey: 8
1539676407: scrollUp
1539676407: Refreshing View
1539676407: changed view to tracking
1539676407: onUpdate
1539676408: onKey: 8
1539676408: scrollUp
1539676408: Refreshing View
1539676408: changed view to tracking
1539676408: onUpdate
1539676409: onKey: 4
1539676409: onSelect
1539676409: free: 102000
1539676409: Adding to q:PAUSE outQ: [PAUSE]
1539676409: returnCentre
1539676409: Refreshing View
1539676409: changed view to tracking
1539676409: onUpdate
1539676409: Send next message PAUSE
1539676409: Incoming mail: SetAlarm;1539704400000
1539676409: Alarm set to 2147483647
1539676410: msgQ: []
1539676410: PAUSEsent OK
1539676412: Incoming mail: Pause;1539677589965
1539676412: onKey: 8
1539676412: scrollUp
1539676412: Refreshing View
1539676412: changed view to tracking
1539676412: onUpdate
1539676412: onKey: 8
1539676412: scrollUp
1539676412: Refreshing View
1539676412: changed view to tracking
1539676412: onUpdate
1539676413: onKey: 4
1539676413: onSelect
1539676413: free: 101984
1539676413: Adding to q:PAUSE outQ: [PAUSE]
1539676413: returnCentre
1539676413: Refreshing View
1539676413: changed view to tracking
1539676413: onUpdate
1539676413: Send next message PAUSE
1539676414: msgQ: []
1539676414: PAUSEsent OK
1539676416: onKey: 8
1539676416: scrollUp
1539676416: Refreshing View
1539676416: changed view to tracking
1539676416: onUpdate
1539676416: onKey: 8
1539676416: scrollUp
1539676416: Refreshing View
1539676416: changed view to tracking
1539676416: onUpdate
1539676417: Incoming mail: StartHRTracking
1539676417: onKey: 8
1539676417: scrollUp
1539676417: Refreshing View
1539676417: changed view to tracking
1539676417: onUpdate
1539676418: onKey: 8
1539676418: scrollUp
1539676418: Refreshing View
1539676418: changed view to tracking
1539676418: onUpdate
1539676419: onKey: 13
1539676419: scrollDown
1539676419: Refreshing View
1539676419: changed view to tracking
1539676419: onUpdate
1539676420: onKey: 4
1539676420: onSelect
1539676420: free: 101984
1539676420: Adding to q:RESUME outQ: [RESUME]
1539676420: returnCentre
1539676420: Refreshing View
1539676420: changed view to tracking
1539676420: onUpdate
1539676420: Send next message RESUME
1539676421: Incoming mail: StartTracking
1539676421: msgQ: []
1539676421: RESUMEsent OK
1539676423: Incoming mail: Pause;1539677889965
1539676425: onKey: 8
1539676425: scrollUp
1539676425: Refreshing View
1539676425: changed view to tracking
1539676425: onUpdate
1539676426: onKey: 4
1539676426: onSelect
1539676426: Normal Exit
1539676426: returnCentre
1539676426: Refreshing View
1539676426: changed view to tracking
1539676426: onUpdate
1539676427: STOPPING sent OK
1539676427: Incoming mail: Pause;0
1539676430: Incoming mail: StopApp
1539676430: SleepMainView initialize
1539676430: SleepMainDelegate initialize
1539676430: 2
1539676430: changed view to tracking
1539676430: onUpdate
1539676430: changed view to tracking
1539676430: onUpdate
1539676432: onStop

I'll use the tracker tonight and see what I get in the morning but I'm guessing there might need to be more log statements to catch the issue. Garmin also has this limitation: When any log file exceeds 5kb, it will automatically be archived to <LOGNAME>.BAK, and a new log will be started. Any old .BAK files will be overwritten when the archive occurs, so the max space a log can reach is ~10kb.

hAmpzter commented 6 years ago

Alright. I'll create it and try this on my device this night! :)

Artaud commented 6 years ago

@aaronjwood That's great - the issue is that the log file name has to be different for every user who downloads the app, it changes every time you download the app, and (I'm not sure about this) will also change with each update. The way you did it is working perfectly, but not suitable for mass user logging. But we're on Github here, so yay!

I also have got a wild idea what might be causing some of the issues. Seeing now how much logging is going on in there in the release version, maybe there is a memory leak on some watches when you don't have the log files created. That said, I've never encountered this issue on my Vivoactive, neither debug nor release build.

aaronjwood commented 6 years ago

Funny you mention that, I was thinking the same thing. The logs I posted last night showed my free memory dipping each time log is called to check the memory. I saw some people on the forums talking about removing printlns to save memory but I didn't see anything about them causing a leak.

I had the app crash on me again last night so I'll post the logs from my watch ASAP.

Artaud commented 6 years ago

Perfect. To remove the logging, the only thing needed is to toggle the debug flag at https://github.com/urbandroid-team/Sleep-as-Android-Garmin-Addon/blob/a947e16b81c4399ee302f48ae2fb1f80aa07a92c/SleepGarmin-watch/source/SleepApp.mc#L14

I've built the .prg for Fenix 5 that would do no logging: https://github.com/urbandroid-team/Sleep-as-Android-Garmin-Addon/blob/master/watch-releases/20180918-debug-Fenix5-nologging.prg

aaronjwood commented 6 years ago

Hmm unfortunately (at least from the logs) it doesn't look like it's a memory issue for me. Here's the .BAK file with the rotated logs:

1539680820: changed view to tracking
1539680820: onUpdate
1539680820: changed view to tracking
1539680820: onUpdate
1539680820: changed view to tracking
1539680820: onUpdate
1539680820: changed view to tracking
1539680820: onUpdate
1539680820: changed view to tracking
1539680820: onUpdate
1539680820: changed view to tracking
1539680820: onUpdate
1539680820: changed view to tracking
1539680820: onUpdate
1539680820: changed view to tracking
1539680820: onUpdate
1539680820: changed view to tracking
1539680820: onUpdate
1539680820: changed view to tracking
1539680821: onUpdate
1539680880: changed view to tracking
1539680880: onUpdate
1539680880: changed view to tracking
1539680880: onUpdate
1539680880: changed view to tracking
1539680880: onUpdate
1539680880: changed view to tracking
1539680880: onUpdate
1539680880: changed view to tracking
1539680880: onUpdate
1539680880: changed view to tracking
1539680880: onUpdate
1539680880: changed view to tracking
1539680880: onUpdate
1539680904: free: 101880
1539680904: Adding to q:[DATA, [32, 40, 39, 44, 40, 39, 52, 44, 44, 36, 44, 43]] outQ: [[DATA, [32, 40, 39, 44, 40, 39, 52, 44, 44, 36, 44, 43]]]
1539680904: free: 101872
1539680904: Adding to q:[DATA_NEW, [1031, 1032, 1032, 1033, 1033, 1031, 1041, 1032, 1032, 1036, 1034, 1034]] outQ: [[DATA, [32, 40, 39, 44, 40, 39, 52, 44, 44, 36, 44, 43]], [DATA_NEW, [1031, 1032, 1032, 1033, 1033, 1031, 1041, 1032, 1032, 1036, 1034, 1034]]]
1539680904: Send next message [DATA, [32, 40, 39, 44, 40, 39, 52, 44, 44, 36, 44, 43]]
1539680905: msgQ: [[DATA_NEW, [1031, 1032, 1032, 1033, 1033, 1031, 1041, 1032, 1032, 1036, 1034, 1034]]]
1539680905: [DATA, [32, 40, 39, 44, 40, 39, 52, 44, 44, 36, 44, 43]]sent OK
1539680905: Send next message [DATA_NEW, [1031, 1032, 1032, 1033, 1033, 1031, 1041, 1032, 1032, 1036, 1034, 1034]]
1539680906: msgQ: []
1539680906: [DATA_NEW, [1031, 1032, 1032, 1033, 1033, 1031, 1041, 1032, 1032, 1036, 1034, 1034]]sent OK
1539680914: free: 102248
1539680914: Adding to q:[HR, 52] outQ: [[HR, 52]]
1539680914: Send next message [HR, 52]
1539680915: msgQ: []
1539680915: [HR, 52]sent OK
1539680940: changed view to tracking
1539680940: onUpdate
1539680940: changed view to tracking
1539680940: onUpdate
1539680940: changed view to tracking
1539680940: onUpdate
1539680940: changed view to tracking
1539680940: onUpdate
1539680940: changed view to tracking
1539680940: onUpdate
1539681000: changed view to tracking
1539681000: onUpdate
1539681000: changed view to tracking
1539681000: onUpdate
1539681000: changed view to tracking
1539681000: onUpdate
1539681000: changed view to tracking
1539681000: onUpdate
1539681000: changed view to tracking
1539681000: onUpdate
1539681000: changed view to tracking
1539681000: onUpdate
1539681000: changed view to tracking
1539681000: onUpdate
1539681000: changed view to tracking
1539681000: onUpdate
1539681000: changed view to tracking
1539681000: onUpdate
1539681000: changed view to tracking
1539681000: onUpdate
1539681025: free: 101880
1539681025: Adding to q:[DATA, [40, 32, 36, 40, 40, 32, 44, 36, 40, 36, 56, 35]] outQ: [[DATA, [40, 32, 36, 40, 40, 32, 44, 36, 40, 36, 56, 35]]]
1539681025: free: 101872
1539681025: Adding to q:[DATA_NEW, [1034, 1028, 1031, 1030, 1031, 1032, 1036, 1029, 1028, 1032, 1032, 1032]] outQ: [[DATA, [40, 32, 36, 40, 40, 32, 44, 36, 40, 36, 56, 35]], [DATA_NEW, [1034, 1028, 1031, 1030, 1031, 1032, 1036, 1029, 1028, 1032, 1032, 1032]]]
1539681025: Send next message [DATA, [40, 32, 36, 40, 40, 32, 44, 36, 40, 36, 56, 35]]
1539681026: msgQ: [[DATA_NEW, [1034, 1028, 1031, 1030, 1031, 1032, 1036, 1029, 1028, 1032, 1032, 1032]]]
1539681026: [DATA, [40, 32, 36, 40, 40, 32, 44, 36, 40, 36, 56, 35]]sent OK
1539681026: Send next message [DATA_NEW, [1034, 1028, 1031, 1030, 1031, 1032, 1036, 1029, 1028, 1032, 1032, 1032]]
1539681027: msgQ: []
1539681027: [DATA_NEW, [1034, 1028, 1031, 1030, 1031, 1032, 1036, 1029, 1028, 1032, 1032, 1032]]sent OK
1539681060: changed view to tracking
1539681060: onUpdate
1539681060: changed view to tracking
1539681060: onUpdate
1539681060: changed view to tracking
1539681060: onUpdate
1539681060: changed view to tracking
1539681060: onUpdate
1539681060: changed view to tracking
1539681060: onUpdate
1539681060: changed view to tracking
1539681060: onUpdate
1539681060: changed view to tracking
1539681060: onUpdate
1539681060: changed view to tracking
1539681060: onUpdate
1539681060: changed view to tracking
1539681060: onUpdate
1539681120: changed view to tracking
1539681120: onUpdate
1539681120: changed view to tracking
1539681120: onUpdate
1539681120: changed view to tracking
1539681120: onUpdate
1539681120: changed view to tracking
1539681120: onUpdate
1539681120: changed view to tracking
1539681120: onUpdate
1539681146: free: 101880
1539681146: Adding to q:[DATA, [40, 44, 40, 32, 36, 40, 43, 52, 32, 40, 36, 35]] outQ: [[DATA, [40, 44, 40, 32, 36, 40, 43, 52, 32, 40, 36, 35]]]
1539681146: free: 101872
1539681146: Adding to q:[DATA_NEW, [1033, 1030, 1033, 1029, 1033, 1032, 1029, 1035, 1030, 1033, 1032, 1029]] outQ: [[DATA, [40, 44, 40, 32, 36, 40, 43, 52, 32, 40, 36, 35]], [DATA_NEW, [1033, 1030, 1033, 1029, 1033, 1032, 1029, 1035, 1030, 1033, 1032, 1029]]]

I wonder if optimizing the logging would help with device battery life. From the above it looks like the app logs all night on every onUpdate call. Here's the regular .TXT file with the most recent logs right before the crash:

1539681146: Send next message [DATA, [40, 44, 40, 32, 36, 40, 43, 52, 32, 40, 36, 35]]
1539681147: msgQ: [[DATA_NEW, [1033, 1030, 1033, 1029, 1033, 1032, 1029, 1035, 1030, 1033, 1032, 1029]]]
1539681147: [DATA, [40, 44, 40, 32, 36, 40, 43, 52, 32, 40, 36, 35]]sent OK
1539681147: Send next message [DATA_NEW, [1033, 1030, 1033, 1029, 1033, 1032, 1029, 1035, 1030, 1033, 1032, 1029]]
1539681148: msgQ: []
1539681148: [DATA_NEW, [1033, 1030, 1033, 1029, 1033, 1032, 1029, 1035, 1030, 1033, 1032, 1029]]sent OK
1539681180: changed view to tracking
1539681180: onUpdate
1539681180: changed view to tracking
1539681180: onUpdate
1539681180: changed view to tracking
1539681180: onUpdate
1539681180: changed view to tracking
1539681180: onUpdate
1539681180: changed view to tracking
1539681180: onUpdate
1539681180: changed view to tracking
1539681180: onUpdate
1539681180: changed view to tracking
1539681180: onUpdate
1539681180: changed view to tracking
1539681180: onUpdate
1539681180: changed view to tracking
1539681180: onUpdate
1539681180: changed view to tracking
1539681180: onUpdate
1539681240: changed view to tracking
1539681240: onUpdate
1539681240: changed view to tracking
1539681240: onUpdate
1539681240: changed view to tracking
1539681240: onUpdate
1539681240: changed view to tracking
1539681240: onUpdate
1539681240: changed view to tracking
1539681240: onUpdate
1539681267: free: 101880
1539681267: Adding to q:[DATA, [32, 44, 40, 40, 36, 40, 48, 36, 36, 44, 36, 64]] outQ: [[DATA, [32, 44, 40, 40, 36, 40, 48, 36, 36, 44, 36, 64]]]
1539681267: free: 101872
1539681267: Adding to q:[DATA_NEW, [1031, 1036, 1030, 1031, 1036, 1032, 1034, 1032, 1029, 1036, 1032, 1038]] outQ: [[DATA, [32, 44, 40, 40, 36, 40, 48, 36, 36, 44, 36, 64]], [DATA_NEW, [1031, 1036, 1030, 1031, 1036, 1032, 1034, 1032, 1029, 1036, 1032, 1038]]]
1539681267: Send next message [DATA, [32, 44, 40, 40, 36, 40, 48, 36, 36, 44, 36, 64]]
1539681267: msgQ: [[DATA_NEW, [1031, 1036, 1030, 1031, 1036, 1032, 1034, 1032, 1029, 1036, 1032, 1038]]]
1539681267: [DATA, [32, 44, 40, 40, 36, 40, 48, 36, 36, 44, 36, 64]]sent OK
1539681268: Send next message [DATA_NEW, [1031, 1036, 1030, 1031, 1036, 1032, 1034, 1032, 1029, 1036, 1032, 1038]]
1539681269: msgQ: []
1539681269: [DATA_NEW, [1031, 1036, 1030, 1031, 1036, 1032, 1034, 1032, 1029, 1036, 1032, 1038]]sent OK
1539681277: free: 102248
1539681277: Adding to q:[HR, 52] outQ: [[HR, 52]]
1539681277: Send next message [HR, 52]
1539681278: msgQ: []
1539681278: [HR, 52]sent OK
1539681300: changed view to tracking
1539681300: onUpdate
1539681300: changed view to tracking
1539681300: onUpdate
1539681300: changed view to tracking
1539681300: onUpdate
1539681300: changed view to tracking
1539681300: onUpdate
1539681300: changed view to tracking
1539681300: onUpdate
1539681360: changed view to tracking
1539681360: onUpdate
1539681360: changed view to tracking
1539681360: onUpdate
1539681360: changed view to tracking
1539681360: onUpdate
1539681360: changed view to tracking
1539681360: onUpdate
1539681360: changed view to tracking
1539681360: onUpdate
1539681360: changed view to tracking
1539681360: onUpdate
1539681360: changed view to tracking
1539681360: onUpdate
1539681360: changed view to tracking
1539681360: onUpdate
1539681360: changed view to tracking
1539681360: onUpdate
1539681360: changed view to tracking
1539681360: onUpdate
1539681387: free: 101896
1539681387: Adding to q:[DATA, [2783, 1671, 47, 309, 43, 59, 47, 43, 51, 51, 47, 55]] outQ: [[DATA, [2783, 1671, 47, 309, 43, 59, 47, 43, 51, 51, 47, 55]]]
1539681387: free: 101888
1539681387: Adding to q:[DATA_NEW, [1659, 1456, 996, 1021, 992, 992, 994, 989, 989, 991, 994, 991]] outQ: [[DATA, [2783, 1671, 47, 309, 43, 59, 47, 43, 51, 51, 47, 55]], [DATA_NEW, [1659, 1456, 996, 1021, 992, 992, 994, 989, 989, 991, 994, 991]]]
1539681387: Send next message [DATA, [2783, 1671, 47, 309, 43, 59, 47, 43, 51, 51, 47, 55]]

But you know what? I had a crash in the watch again. This is from GARMIN/DEBUG/ERR_LOG.BAK:


2697 (fenix 5) SW ver: 1100
Build Type: RELEASE
Commit:9b90c64df0cf6f9498c472ce547c0986c1d446c0
ESN: 3962006839
10/16/18 02:16:28
RTL
errnum: 0x00a
r0: 0x2005b560
r1: 0x000000c4
r2: 0x0000007e
r3: 0x0000007f
r4: 0x000a5dbd
Stack frame PC, SP: 0x000ce22d, 0x2005b168
Call Stack - SP at 0x2005b168:
    0x0007134f
    0x000a5dbd
    0x0008df0d
    0x000a5dbd
    0x000a5dbd
    0x0008eb95
    0x000a6891
    0x0001011d
    0x0000b4bd
    0x00076d81
    0x0008eb95
    0x0008eb95
    0x0008ea25
    0x0008eb95
    0x000200bd
    0x0008ea25
    0x000a5ffd
    0x00028247
    0x00026993
    0x0001fe33
    0x0008eb95
    0x0008ea25
    0x0008ea43
    0x0008fd31
    0x000500d5
    0x0004ff2d
    0x0005e3a3
    0x00011985
    0x0005e3f1
    0x0005e3fd
    0x0008fe17
    0x000e6d27
Uptime: 533715925

The timestamp on that log directly relates to when the sleep app crashed for me. This morning I saw that the app had only tracked about 5% of my night before it crashed and it was around 2:15 AM that the chart showed tracking had stopped. So now the question is how is the sleep app causing the watch to crash internally? @hAmpzter can you check this log file as well to see if your Fenix 5 is internally crashing?

@Artaud wondering if there's an issue with Garmin's CIQ where excessive logging for hours can cause a crash in the underlying system. Maybe they have a leak somewhere themselves...?

Artaud commented 6 years ago

wondering if there's an issue with Garmin's CIQ where excessive logging for hours can cause a crash in the underlying system. Maybe they have a leak somewhere themselves...?

@aaronjwood Exactly, that's what I was thinking, and we could confirm that by testing the non-logging version. I got only a cryptic response from Coleman on the Garmin team when I posted your crash stack trace on the Garmin forum, but it seems that it's not an isolated issue.

I actually thought that when I build a release version of the app (there is a release flag on the compiler), then all logging would be disabled, so these issues wouldn't present themselves. But that does not seem to be the case.

Could you please test the non-logging version tonight on your F5 (up here)?

Big thanks

aaronjwood commented 6 years ago

Will do! I'll post back tomorrow after a night with the version you posted.

MrFly commented 6 years ago

@artaud does this version work with the VA3 too?

Artaud commented 6 years ago

This build is specifically for F5, but the only difference is in image resources so you can try it, it would probably work, but the layout and the launcher icon may be distorted. On 16 Oct 2018 20:09, "Hans" notifications@github.com wrote:

@Artaud https://github.com/Artaud does this version work with the VA3 too?

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/urbandroid-team/Sleep-as-Android-Garmin-Addon/issues/10#issuecomment-430338992, or mute the thread https://github.com/notifications/unsubscribe-auth/ADuCVlVORDJyOWdQJvA0ovN3D7_LC3vrks5uliDfgaJpZM4XL9tW .

MrFly commented 6 years ago

Ok. Anything to do, except install this file?

MrFly commented 6 years ago

@Artaud Ok, just installed it and started sleep for a first test. The images are nearly the same than before, so this should work without problems. I'll give it a try this night. Tomorrow in the morning I will give feedback about it...

MrFly commented 6 years ago

@artaud great! I think, you almost got it! The tracking worked till about three o'clock like a charm. That's 4 hours more than before

aaronjwood commented 6 years ago

@MrFly do you have a crash in your GARMIN/DEBUG/ERR_LOG file around the time that tracking stopped working?

MrFly commented 6 years ago

@aaronjwood yes, there is one

2700 (vívoactive 3) SW ver: 540
Build Type: RELEASE
Commit:38eeb66ab91c4dbbb90282ab9eea0f28012192aa
ESN: 3961220313
10/17/18 03:38:50
RTL
errnum: 0x800a
r0: 0x00000090
r1: 0x0000007e
r2: 0x0000007f
r3: 0x0016bf53
r4: 0x00000000
r5: 0x00000000
r6: 0x00000000
r7: 0x00000000
r8: 0x00000000
r9: 0x00000000
r10: 0x00000000
r11: 0x00000000
r12: 0x00000000
r13: 0x00000000
r14: 0x00000000
r15: 0x00000000
r16: 0x00000000
r17: 0x00000000
r18: 0x00000000
r19: 0x00000000
r20: 0x00000000
r21: 0x00000000
r22: 0x00000000
r23: 0x00000000
Stack frame PC, SP: 0x00197fcd, 0x1fff2398
Call Stack - SP at 0x1fff2398:
    0x00198571
    0x0016bf53
    0x001480d7
    0x0002729f
    0x0013076b
    0x0016bf53
    0x00148129
    0x0016bf53
    0x0016bf53
    0x00148d4b
    0x0016c867
    0x00148a0b
    0x0000f07d
    0x044ec9e1
    0x00148d4b
    0x00148d4b
    0x00025e43
    0x0016c155
    0x0003b8a1
    0x0003a1e1
    0x00025b03
    0x00148d4b
    0x00148d4b
    0x00148bad
    0x00148bad
    0x00149d83
    0x000ff243
    0x00148bad
    0x0010c857
    0x00011985
    0x0010c885
    0x0010c891
Uptime: 21545082
hAmpzter commented 6 years ago

Hey. My logs are exactly the same problem as @aaronjwood is having.

Last pieces of SLEEP.BAK:

1539736260: changed view to tracking
1539736260: onUpdate
1539736287: free: 100128
1539736287: Adding to q:[DATA, [3177, 51, 42, 47, 51, 35, 39, 55, 42, 43, 43, 46]] outQ: [[DATA, [3177, 51, 42, 47, 51, 35, 39, 55, 42, 43, 43, 46]]]

And in the: GARMIN\DEBUG\ERR_LOG.BAK:

2697 (fenix 5) SW ver: 1100
Build Type: RELEASE
Commit:9b90c64df0cf6f9498c472ce547c0986c1d446c0
ESN: 3951293740
10/17/18 02:31:29
RTL
errnum: 0x00a
r0: 0x2005b560
r1: 0x00000084
r2: 0x0000007e
r3: 0x0000007f
r4: 0x000a5dbd
Stack frame PC, SP: 0x000ce22d, 0x2005b168
Call Stack - SP at 0x2005b168:
    0x0007134f
    0x000a5dbd
    0x0008df0d
    0x000a5dbd
    0x000a5dbd
    0x0008eb95
    0x000a6891
    0x0006f66b
    0x0000b25b
    0x00076d81
    0x0008eb95
    0x0008eb95
    0x0008ea25
    0x0008eb95
    0x000200bd
    0x0008ea25
    0x000a5ffd
    0x00028247
    0x00026993
    0x0001fe33
    0x0008eb95
    0x0008ea25
    0x0008ea43
    0x0008fd31
    0x000500d5
    0x0004ff2d
    0x0005e3a3
    0x00011985
    0x0005e3f1
    0x0005e3fd
    0x0008fe17
    0x000e6d27
Uptime: 89095622
aaronjwood commented 6 years ago

I crashed again last night using the version posted above. I only made it about 2 hours in so I didn't get much further than usual.

alexmihaila64 commented 6 years ago

Same for me on 645m. Actually it was better since watch app did not quit, but it stopped recording or sending HR. Version before oct 2 worked fine on my watch for more than 2 weeks, than after update crash started to happen. Since i am not good at programming, it's difficult for me to see what was changed in order to revert the changes and have a version whiched worked ok. Maybe if it's not to much to ask, can someone compile that version to sideload it and test it again?

MrFly commented 6 years ago

@Artaud Here's the crash log from this night:

2700 (vívoactive 3) SW ver: 540
Build Type: RELEASE
Commit:38eeb66ab91c4dbbb90282ab9eea0f28012192aa
ESN: 3961220313
10/18/18 03:41:09
RTL
errnum: 0x800a
r0: 0x000000d5
r1: 0x0000007e
r2: 0x0000007f
r3: 0x0016bf53
r4: 0x00000000
r5: 0x00000000
r6: 0x00000000
r7: 0x00000000
r8: 0x00000000
r9: 0x00000000
r10: 0x00000000
r11: 0x00000000
r12: 0x00000000
r13: 0x00000000
r14: 0x00000000
r15: 0x00000000
r16: 0x00000000
r17: 0x00000000
r18: 0x00000000
r19: 0x00000000
r20: 0x00000000
r21: 0x00000000
r22: 0x00000000
r23: 0x00000000
Stack frame PC, SP: 0x00197fcd, 0x1fff2398
Call Stack - SP at 0x1fff2398:
    0x00198571
    0x0002729f
    0x0013076b
    0x0016bf53
    0x00148129
    0x0016bf53
    0x0016bf53
    0x00148d4b
    0x0016c867
    0x0000f07d
    0x001d3a65
    0x044ec9e1
    0x00148d4b
    0x00148d4b
    0x00025e43
    0x0016c155
    0x0003b8a1
    0x0003a1e1
    0x00025b03
    0x00148d4b
    0x00148d4b
    0x00148bad
    0x00148bad
    0x00149d83
    0x000ff243
    0x00148bad
    0x0010c857
    0x00011985
    0x0010c885
    0x0010c891
    0x0014a01b
    0x0000e075
Uptime: 23668067

Also I found an older (two nights) error in CIQ_LOG:

---
Error: Unhandled Exception
Time: 2018-10-16T19:38:28Z
Part-Number: 006-B2700-00
Firmware-Version: '5.40'
Language-Code: deu
ConnectIQ-Version: 3.0.3
Filename: 201809~1
Appname: Sleep
Message: 'UnexpectedTypeException: Expected Number/Float/Long/Double, given null/Float'
Stack:
  - pc: 0x1000276c
    File: '/home/artaud/prog/urbandroid/source/SleepGarmin/SleepGarmin-watch/source/SleepMainDelegate.mc'
    Line: 55
    Function: onTap
  - pc: 0x30001d0d
MrFly commented 6 years ago

Good morning, guys. Some new logs for you. @Artaud I've already sent the wearable report and an error report from SaA.

ERR_LOG.TXT:

2700 (vívoactive 3) SW ver: 540
Build Type: RELEASE
Commit:38eeb66ab91c4dbbb90282ab9eea0f28012192aa
ESN: 3961220313
10/19/18 00:22:31
RTL
errnum: 0x800a
r0: 0x000000dc
r1: 0x0000007e
r2: 0x0000007f
r3: 0x0016bf53
r4: 0x00000000
r5: 0x00000000
r6: 0x00000000
r7: 0x00000000
r8: 0x00000000
r9: 0x00000000
r10: 0x00000000
r11: 0x00000000
r12: 0x00000000
r13: 0x00000000
r14: 0x00000000
r15: 0x00000000
r16: 0x00000000
r17: 0x00000000
r18: 0x00000000
r19: 0x00000000
r20: 0x00000000
r21: 0x00000000
r22: 0x00000000
r23: 0x00000000
Stack frame PC, SP: 0x00197fcd, 0x1fff2398
Call Stack - SP at 0x1fff2398:
    0x00198571
    0x0002729f
    0x0013076b
    0x0016bf53
    0x00148129
    0x0016bf53
    0x0016bf53
    0x00148d4b
    0x0016c867
    0x00130099
    0x0000ee41
    0x0013090d
    0x00148d4b
    0x00148d4b
    0x00025e43
    0x0016c155
    0x0003b8a1
    0x0003a1e1
    0x00025b03
    0x00148d4b
    0x00148d4b
    0x00148bad
    0x00148bad
    0x00149d83
    0x000ff243
    0x00148bad
    0x0010c857
    0x00011985
    0x0010c885
    0x0010c891
    0x0014a01b
    0x0000e075
Uptime: 74480733
hAmpzter commented 6 years ago

Hey. I have now made a version without any logging enabled and tried that for two nights. It seems to last just a tiny bit longer, but not much. I'll try again with a bit different type of logging next.

MrFly commented 6 years ago

@Artaud Should we use this debugging version above for a time or better revert to the release now?

Artaud commented 6 years ago

Same for me on 645m. Actually it was better since watch app did not quit, but it stopped recording or sending HR. Version before oct 2 worked fine on my watch for more than 2 weeks, than after update crash started to happen. Since i am not good at programming, it's difficult for me to see what was changed in order to revert the changes and have a version whiched worked ok. Maybe if it's not to much to ask, can someone compile that version to sideload it and test it again?

@alexmihaila64 This one is from 31 Aug, I'm not sure which model it is for since I extracted it from the published .iq package but it should work okay. sleep-20180831-notsurewhichmodel.zip

Make sure to unzip the file before sideloading. Let me know if it works better for you! I'd be surprised since literally the only thing I added is one line in the manifest, but hey, you never know.

Artaud commented 6 years ago

@Artaud Should we use this debugging version above for a time or better revert to the release now?

Actually what would really help is if anybody would be so suicidal to factory reset their watch, load the release (no other apps) and track for one or two nights. I understand it is a lot to ask, so no pressure!

alexmihaila64 commented 6 years ago

Ok, i got it working (2 of 3 nights) on my 645m. Key to succes was to revert everything to configuration that worked before latest updates. my curent config is: GC latest version. SaA beta from 2018.08.18 (latest have an annoing bug that prevent me to add manual sleep it starts tracking instaed) SaA Garmin Addon version 20180620 downloaded from APKpure SaA Garmin start latest version from playstore Garmin watch app 20180831 extracted from iq file from github, random 53k since i don't know which is which. Phone memory cleared berore sleep and all battery optimizations for above programs disabled. Then start all programs and sync watch before starting tracking. It worked 2 nights, in the night that quit after 1 hr, watch app was stiill running in the morning, but i found that SaA Garmin Addon app was not running, maybe it crashed or being killed by system. as soon as i started GA, data started to come again. So maybe the problem is with Android Garmin Addon. I will keep my curent config since i am tired to test continuously; In September worked more than 2 weeks every night so it's ok with me. As a note, the same config is not working on my VAHR, so i remove it from GC Hope this help Alex

MrFly commented 6 years ago

How did you notice, that Garmin Addon was not running? I mean, it's an addon, not a standalone app, so it isn't actually "running" at all. I'm only interested in this, maybe I can try your solution with my equipment...

alexmihaila64 commented 6 years ago

It's an Android app, and i always start it before starting SaA app (in fact i start SaA by pressing setup tracking in addon). On my phone (Huawei Mate 10 Pro), when i bring the history list with previous programs, all programs which are running or are cached show; there i have the option to prevent system to close it by pressing the lock key). The day in which tracking was incomplete, the program was not in the list among the other two, when it worked, all three program are were the list (they are all locked so system will not killed them) .

MrFly commented 6 years ago

Ah! Good explanation, thanks.

skros89 commented 6 years ago

@Artaud Should we use this debugging version above for a time or better revert to the release now?

Actually what would really help is if anybody would be so suicidal to factory reset their watch, load the release (no other apps) and track for one or two nights. I understand it is a lot to ask, so no pressure!

Did this tonight on the vivoactive 3 (factory reset) and the tracking stopped after one hour. Going to create a log file now and try again. screenshot_20181023-031237_sleep

MrFly commented 6 years ago

Tried the other way tonight and locked the apps including Garmin addon. Changed nothing with the current versions.

skros89 commented 6 years ago

Did this tonight on the vivoactive 3 (factory reset) and the tracking stopped after one hour. Going to create a log file now and try again.

Same thing happened the second time around. GARMIN\DEBUG\ERR_LOG.TXT:

Build Type: RELEASE
Commit:38eeb66ab91c4dbbb90282ab9eea0f28012192aa
ESN: 3962248612
10/23/18 01:08:39
RTL
errnum: 0x800a
r0: 0x00000092
r1: 0x0000007e
r2: 0x0000007f
r3: 0x0016bf53
r4: 0x00000000
r5: 0x00000000
r6: 0x00000000
r7: 0x00000000
r8: 0x00000000
r9: 0x00000000
r10: 0x00000000
r11: 0x00000000
r12: 0x00000000
r13: 0x00000000
r14: 0x00000000
r15: 0x00000000
r16: 0x00000000
r17: 0x00000000
r18: 0x00000000
r19: 0x00000000
r20: 0x00000000
r21: 0x00000000
r22: 0x00000000
r23: 0x00000000
Stack frame PC, SP: 0x00197fcd, 0x1fff2398
Call Stack - SP at 0x1fff2398:
    0x00198571
    0x0002729f
    0x0013076b
    0x0016bf53
    0x00148129
    0x0016bf53
    0x0016bf53
    0x00148d4b
    0x0016c867
    0x0000f07d
    0x0000ffff
    0x044ec9e1
    0x00148d4b
    0x00148d4b
    0x00025e43
    0x0016c155
    0x0003b8a1
    0x0003a1e1
    0x00025b03
    0x00148d4b
    0x00148d4b
    0x00148bad
    0x00148bad
    0x00149d83
    0x000ff243
    0x00148bad
    0x0010c857
    0x00011985
    0x0010c885
    0x0010c891
    0x0014a01b
    0x0000e075
Uptime: 18437299

2700 (vívoactive 3) SW ver: 540
Build Type: RELEASE
Commit:38eeb66ab91c4dbbb90282ab9eea0f28012192aa
ESN: 3962248612
10/23/18 04:45:16
RTL
errnum: 0x800a
r0: 0x00000099
r1: 0x0000007e
r2: 0x0000007f
r3: 0x0016bf53
r4: 0x00000000
r5: 0x00000000
r6: 0x00000000
r7: 0x00000000
r8: 0x00000000
r9: 0x00000000
r10: 0x00000000
r11: 0x00000000
r12: 0x00000000
r13: 0x00000000
r14: 0x00000000
r15: 0x00000000
r16: 0x00000000
r17: 0x00000000
r18: 0x00000000
r19: 0x00000000
r20: 0x00000000
r21: 0x00000000
r22: 0x00000000
r23: 0x00000000
Stack frame PC, SP: 0x00197fcd, 0x1fff2398
Call Stack - SP at 0x1fff2398:
    0x00198571
    0x0002729f
    0x0013076b
    0x0016bf53
    0x00148129
    0x0016bf53
    0x0016bf53
    0x00148d4b
    0x0016c867
    0x00130099
    0x0000f07d
    0x044ec9e1
    0x00148d4b
    0x00148d4b
    0x00025e43
    0x0016c155
    0x0003b8a1
    0x0003a1e1
    0x00025b03
    0x00148d4b
    0x00148d4b
    0x00148bad
    0x00148bad
    0x00149d83
    0x000ff243
    0x00148bad
    0x0010c857
    0x00011985
    0x0010c885
    0x0010c891
    0x0014a01b
    0x0000e075
Uptime: 12996360

And the App's log GARMIN\APPS\LOGS\8AMI0650.TXT:

1540262713: Send next message [DATA_NEW, [941, 941, 935, 940, 935, 935, 936, 936, 954, 949, 944, 946]]
1540262714: msgQ: []
1540262714: [DATA_NEW, [941, 941, 935, 940, 935, 935, 936, 936, 954, 949, 944, 946]]sent OK
1540262716: free: 102272
1540262716: Adding to q:[HR, 71] outQ: [[HR, 71]]
1540262716: Send next message [HR, 71]
MrFly commented 6 years ago

Only an idea: how did you (all) set the hr measurement interval? Mine is set to "always". Is there a difference if it's set to "smart" (don't know how this is labelled in english)

gcupic commented 6 years ago

mine is set to smart and I've seen the crashes or to be more precise my Garmin Fenix 3 HR SaA app can't close and stops sending sleep data to SaA on my OnePlus 6. Both are running fresh and un-modified SWs and OSs.

skros89 commented 6 years ago

You mean on the watch right? I think I always had it set to smart. After the factory reset it was definitely on smart (default).

MrFly commented 6 years ago

Yes, I meant on the watch. Ok, at least this should not be the problem...

skros89 commented 6 years ago

Ok, I finally narrowed this down a bit. It is related to the internet permissions (AndroidManifest.xml) that is being commented out for the release builds. If I build the current code, or the september release of the garmin addon and leave in the internet permissions it doesn't crash. This was tested using the latest release of the watch app from IQ store and latest SaA from play store.

aaronjwood commented 6 years ago

Interesting...so the Android side of the codebase is causing the Garmin side to crash?

Artaud commented 6 years ago

Hmmm...that's really interesting. Can you really confirm @skros89 that the watch app holds for the whole night? Did you change anything else in your build or just this? The internet permission was never included in any release build, even if earlier we did not observe this issue. According to Android docs, the internet permission "Allows applications to open network sockets.", I don't see how this might crash the watchapp, but hey, if it works :) All I can say now is that I have the permission in my build manifest and I'm currently running tracking for about three hours without crash.

skros89 commented 6 years ago

For both builds (september release and current), I only changed that one line. They both ran for around 3 hours of tracking without crashing, whereas before it always crashed after 1 hour. But that was just testing during the day. Tonight I'm gonna test to see if it lasts the whole night, I'll let you know tomorrow. As to why it happens; I have no idea. I don't have any experience with android development, so unfortunately I won't be much help in finding out either.