[#115] Improved log file auto rotation; now attaching last 2 files to user reports #116

ssawchenko · 2023-07-28T23:35:36Z

Related Issue: #115

Summary of Problem:

We wanted to add a second log file to our User Reports to cover the case where we have just cycled our logs due to the auto rotate expiry period rolling over.
I noticed while testing this that our auto rotate logic wasn't working 100% correctly, such that files were not actually expiring when expected; I decided to fix that here as well.
- We don't have access to a file's "created time"; because of this we were using lastModified time to determine expiry which was causing us to re-select the most recent log to use instead of rotating to the next log.

Proposed Solution:

SteamclogThrowableWrapper now takes a attachLogFiles boolean (instead of the logAttachmentUrl File); if true the ExternalLogFileDestination will determine the URLs for the log files to attach (ie. the most recent 2).
getLogFiles now allows us to sort by lastModified time ascending and descending
findAvailableLogFile now filters out the current log from being an option when determining the next log to rotate to
Updated sample app to make it easier to test out auto rotation

Testing Steps:

Spark up the sample app; the sample app is now set to rotate through logs every 10 seconds
Every 10 seconds or so do the following: press "Add logs" and then "Show file dump"
Make sure that the logs listed appear to cycle every 10 seconds:
Go to the Sentry page for the sample app: https://steamclock-software.sentry.io/issues/?project=5399932
Select all issues, click the triple dot and delete them to make a clean slate
Go back to the sample app, change the log level to Release
Press the "Report Single Error" and "Send User Report" buttons and then press the "Show File Dump" button again
Wait a few seconds for Sentry to update and make sure you see two reports:
Drill into the "This is my user report" and the scroll all the way to the bottom. Make sure the two reports listed match the two most recent logs shown in the dump. They don't need to be in the same "order", but the files included should match.

Sentry Attachments	Listed in Sample app

ssawchenko · 2023-07-28T23:43:49Z

app/src/main/java/com/steamclock/steamclogsample/MainActivity.kt

+        }
+
+        logMetaData += "\nFull Content:\n\n" + SteamcLog.getFullLogContents()
+        binding.demoText.text = logMetaData


Updating sample app to print out the list of log files so I can properly test the auto rotation feature

ssawchenko · 2023-07-28T23:56:13Z

steamclog/src/main/java/com/steamclock/steamclog/Steamclog.kt

-        return externalLogFileTree.getExternalFile()
-    }
-
-    fun deleteLogFile() {


We don't actually support manual delete due to auto rotation; removing to avoid confusion

ssawchenko · 2023-07-28T23:56:47Z

steamclog/src/main/java/com/steamclock/steamclog/LogSort.kt

+enum class LogSort {
+    LastModifiedAsc,
+    LastModifiedDesc
+}


We need to sort the logs in different orders in various places, so I made the setting explicit

ssawchenko · 2023-07-28T23:58:44Z

steamclog/src/main/java/com/steamclock/steamclog/Destinations.kt

-        currentLogFileCachedTime = Date().time
+        // Only update if we are changing files; this helps us simulate when a file was "created" so
+        // that we can cycle every 10 mins
+        if (currentLogFile == file) { return }


Before we were not checking for this, which was causing the currentLogFileCachedTime value to be incorrectly updated each time, meaning that the expiry calculation couldn't succeed as expected if the app was continually writing logs.

ssawchenko · 2023-07-29T00:21:07Z

steamclog/src/main/java/com/steamclock/steamclog/Destinations.kt

-    private var currentLogFileCachedTime: Long? = null
+    // Since we cannot get a file's created time, we make note of the timestamp when the
+    // logFile was originally marked as being "current".
+    private var logFileCreatedTimeEstimate: Long? = null


Renamed to indicate we're trying to spoof the created time

nbrooke

Logic looks correct / matching iOS to me (minus the known difference in rotation behaviour due to iOS using creation time and Android only having modified time), but @phileo should definitely too a more careful pass on the actual Kotlin / Android code.

phileo · 2023-08-02T03:11:51Z

steamclog/src/main/java/com/steamclock/steamclog/Destinations.kt

-        return currentFile
+        // Find new available log file and update cached variables
+        cachedCurrentLogFile = findAvailableLogFile(expiryMs)
+        logFileCreatedTimeEstimate = Date().time


what kind of problems would using cachedCurrentLogFile.lastModifiedTime() cause

Also, this seems to imply that all 10 log files will have the same logFileCreatedTimeEstimate even though each logfile could be selected at different times, is that expected behaviour

what kind of problems would using cachedCurrentLogFile.lastModifiedTime() cause

Honestly I'm using Date().time here because that was what was being set before in the original code implemented by Julie... but you're right - the file returned by findAvailableLogFile will either be within the valid expiry window OR will have just been cleared such that the last modified date essentially is now. I'll play around with this and see if it has any side effects I can't think of.

Edit: I've updated the code to use lastModifiedTime instead and everything seems to function correctly. Since this is a better value to use for an estimated creation date let's go with it!

Also, this seems to imply that all 10 log files will have the same logFileCreatedTimeEstimate even though each logfile could be selected at different times, is that expected behaviour

Yes, technically any of the files could be selected to be used as the next available file (although the logic attempts to pick the oldest one), so in theory, yes that was the expected behaviour when the code was first written I believe.

With the changes I have made in your first comment though, this will no longer be the case. Now a selected file should have a logFileCreatedTimeEstimate of the last modified time so they would not all be the same.

phileo · 2023-08-02T03:14:42Z

steamclog/src/main/java/com/steamclock/steamclog/Destinations.kt

-        val currentLogFileCachedTime = currentLogFileCachedTime
-        return cachedCurrentLogFile != null &&
+        val currentLogFileCachedTime = logFileCreatedTimeEstimate
+        return logFileCreatedTimeEstimate != null &&
                currentLogFileCachedTime != null &&


not sure I understand the logic behind this, you just assigned currentLogFileCachedTime = logFileCreatedTimeEstimate, so aren't we checking the same thing twice?

This was done to avoid the IDE error:

Smart cast to 'Long' is impossible, because 'logFileCreatedTimeEstimate' is a mutable property that could have been changed by this time

I looked around online and it seemed like creating a local variable was a reasonable way to work around this: https://stackoverflow.com/questions/44595529/smart-cast-to-type-is-impossible-because-variable-is-a-mutable-property-tha

The return statement then makes sure that both the file and the estimated start time have been set (ie. aren't null) and then that that the file has not yet expired, so I don't think we're checking anything twice, but let me know if I'm missing something.

Ah, I see.
What about doing it this way:

val currentLogFileCachedTime = logFileCreatedTimeEstimate ?: return false

I think that should ensure both the file and the estimated start time have been set, and then you should be able to remove both null checks

Whoops I totally see the duplication! Also that's a good idea. Makes it much cleaner! Done :)

ssawchenko · 2023-08-03T20:16:06Z

@phileo Fixed up your final comment, and I also fixed an issue I found due to the lastModification value not being set on new files (was causing the first file to be auto cycled too quickly).

phileo

looks good!
👍

ssawchenko added 4 commits July 28, 2023 13:31

Initial implementation

cc9595e

Fixed issue with autorotate

2c26bed

Small code cleanup

5b74f8d

Reduced some lines of code

025e8c1

ssawchenko commented Jul 28, 2023

View reviewed changes

No longer passing number of attachments

2cd6a1e

ssawchenko commented Jul 28, 2023

View reviewed changes

ssawchenko added 4 commits July 28, 2023 17:04

Small cleanup

24636fa

Removed extra function

bb01d8d

Changed method name back

a55271f

Renames

c5217e9

ssawchenko commented Jul 29, 2023

View reviewed changes

Updated changelog

877054b

ssawchenko requested review from nbrooke and phileo July 29, 2023 00:40

ssawchenko assigned phileo and nbrooke Jul 29, 2023

Ran auto update from gradle 7.2 to 7.6

13ec85a

nbrooke approved these changes Aug 1, 2023

View reviewed changes

nbrooke removed their assignment Aug 1, 2023

phileo reviewed Aug 2, 2023

View reviewed changes

Using lastModified time as estimated creation date

2ad3e03

ssawchenko requested a review from phileo August 2, 2023 17:27

phileo assigned ssawchenko and unassigned phileo Aug 3, 2023

Fixed isCachedLogFileValid logic; properly set lastModified on new files

7030f58

ssawchenko assigned phileo Aug 3, 2023

phileo approved these changes Aug 3, 2023

View reviewed changes

ssawchenko merged commit ed0899e into main Aug 14, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[#115] Improved log file auto rotation; now attaching last 2 files to user reports #116

[#115] Improved log file auto rotation; now attaching last 2 files to user reports #116

ssawchenko commented Jul 28, 2023 •

edited

Loading

ssawchenko Jul 28, 2023

ssawchenko Jul 28, 2023

ssawchenko Jul 28, 2023

ssawchenko Jul 28, 2023 •

edited

Loading

ssawchenko Jul 29, 2023

nbrooke left a comment

phileo Aug 2, 2023

phileo Aug 2, 2023

ssawchenko Aug 2, 2023 •

edited

Loading

ssawchenko Aug 2, 2023

phileo Aug 2, 2023

ssawchenko Aug 2, 2023 •

edited

Loading

phileo Aug 2, 2023

ssawchenko Aug 3, 2023 •

edited

Loading

ssawchenko commented Aug 3, 2023

phileo left a comment

[#115] Improved log file auto rotation; now attaching last 2 files to user reports #116

[#115] Improved log file auto rotation; now attaching last 2 files to user reports #116

Conversation

ssawchenko commented Jul 28, 2023 • edited Loading

Related Issue: #115

Summary of Problem:

Proposed Solution:

Testing Steps:

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ssawchenko Jul 28, 2023 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

nbrooke left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ssawchenko Aug 2, 2023 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ssawchenko Aug 2, 2023 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ssawchenko Aug 3, 2023 • edited Loading

Choose a reason for hiding this comment

ssawchenko commented Aug 3, 2023

phileo left a comment

Choose a reason for hiding this comment

ssawchenko commented Jul 28, 2023 •

edited

Loading

ssawchenko Jul 28, 2023 •

edited

Loading

ssawchenko Aug 2, 2023 •

edited

Loading

ssawchenko Aug 2, 2023 •

edited

Loading

ssawchenko Aug 3, 2023 •

edited

Loading