Bug Duplicate Logging on Focus Loss

Hi all,

I am currently experiencing an issue with a Unity editor script that I've written to log the total time of usage of the Unity editor. It logs the start and end times of each editor session to a text file and correctly identifies whether each session ended because of a crash or a proper quit.

The script works fine for the most part. However, every time the Unity editor loses focus and then regains focus, two new lines are being added to the log file, always with the reason "Crash".

I have added Debug.Log calls to each method in the script, and they show that each method is only being called once, which is the expected behaviour. The duplicate logging seems to happen independently of these method calls.

Here is the code for my script:

Code (CSharp):

1. using UnityEngine;
2. using UnityEditor;
3. using System.IO;
4. using System;
5.  
6. public class EditorUsageTracker
7. {
8.     static DateTime startTime;
9.     static string sessionStartKey = "EditorSessionStartKey";
10.     static string sessionEndKey = "EditorSessionEndKey";
11.     static string crashKey = "EditorCrashKey";
12.     static string firstTimeKey = "FirstTimeKey";
13.  
14.     [InitializeOnLoadMethod]
15.     private static void OnLoad()
16.     {
17.         bool isFirstTime = SessionState.GetBool(firstTimeKey, true);
18.         if (isFirstTime)
19.         {
20.             long temp = Convert.ToInt64(PlayerPrefs.GetString(sessionStartKey, "0"));
21.             DateTime lastStartTime = DateTime.FromBinary(temp);
22.  
23.             long tempEnd = Convert.ToInt64(PlayerPrefs.GetString(sessionEndKey, "0"));
24.             DateTime lastEndTime = DateTime.FromBinary(tempEnd);
25.  
26.             bool wasCrash = PlayerPrefs.GetInt(crashKey, 0) == 1;
27.  
28.             if (wasCrash)
29.             {
30.                 TimeSpan lastUsageTime = lastEndTime - lastStartTime;
31.                 WriteToLog(lastStartTime, lastEndTime, lastUsageTime, true);
32.             }
33.  
34.             // Set up the current session
35.             startTime = DateTime.Now;
36.             EditorApplication.quitting += OnEditorQuit;
37.  
38.             // Update PlayerPrefs
39.             PlayerPrefs.SetString(sessionStartKey, DateTime.Now.ToBinary().ToString());
40.             PlayerPrefs.SetInt(crashKey, 1);
41.  
42.             // Update SessionState
43.             SessionState.SetBool(firstTimeKey, false);
44.         }
45.     }
46.  
47.     static void OnEditorQuit()
48.     {
49.         TimeSpan usageTime = DateTime.Now - startTime;
50.  
51.         // Write this session to the log
52.         WriteToLog(startTime, DateTime.Now, usageTime, false);
53.  
54.         // Update PlayerPrefs
55.         PlayerPrefs.SetString(sessionEndKey, DateTime.Now.ToBinary().ToString());
56.         PlayerPrefs.SetInt(crashKey, 0);
57.         PlayerPrefs.Save();
58.  
59.         // Reset SessionState
60.         SessionState.SetBool(firstTimeKey, true);
61.     }
62.  
63.     static void WriteToLog(DateTime start, DateTime end, TimeSpan usageTime, bool wasCrash)
64.     {
65.         string path = "Assets/EditorUsageLogs.txt";
66.  
67.         using (StreamWriter writer = new StreamWriter(path, true))
68.         {
69.             writer.WriteLine("Editor session started at " + start + " and ended at " + end);
70.             writer.WriteLine("Total time of usage: " + usageTime.TotalHours.ToString("0.00") + " hours");
71.             writer.WriteLine("Ended because of: " + (wasCrash ? "Crash" : "Proper Quit"));
72.             writer.WriteLine("-------------------------------------------------");
73.         }
74.  
75.         AssetDatabase.Refresh();
76.     }
77. }
78.  

The main methods are OnLoad and OnEditorQuit, which are set to run when the editor starts and when it quits, respectively. The WriteToLog method is used to write a new log entry to the log file.

I am storing the start time of each session in PlayerPrefs when the editor starts and storing the end time of each session in PlayerPrefs when the editor quits. I am also using SessionState to keep track of whether this is the first time the editor has been started in the current session or not.

Despite this, every time the Unity editor loses focus and then regains focus, two new lines are being added to the log file, always with the reason "Crash". I'm not sure why this is happening, as Debug.Log calls in the OnLoad and OnEditorQuit methods show that they are only being called once each.

Has anyone encountered this issue before or have any insight into what might be causing this behaviour?
Any help would be appreciated.
Thanks, Matt

 

That just means it's time to debug. As is obvious this whole "was crash" business is just some dangling flag that may or may not have been serialized to PlayerPrefs. Attach the debugger and find out!

Or if the debugger is too daunting, add more prints... EVERYWHERE...

Time to start debugging! Here is how you can begin your exciting new debugging adventures:

You must find a way to get the information you need in order to reason about what the problem is.

Once you understand what the problem is, you may begin to reason about a solution to the problem.

What is often happening in these cases is one of the following:

- the code you think is executing is not actually executing at all
- the code is executing far EARLIER or LATER than you think
- the code is executing far LESS OFTEN than you think
- the code is executing far MORE OFTEN than you think
- the code is executing on another GameObject than you think it is
- you're getting an error or warning and you haven't noticed it in the console window

To help gain more insight into your problem, I recommend liberally sprinkling

Debug.Log()

statements through your code to display information in realtime.

Doing this should help you answer these types of questions:

- is this code even running? which parts are running? how often does it run? what order does it run in?
- what are the names of the GameObjects or Components involved?
- what are the values of the variables involved? Are they initialized? Are the values reasonable?
- are you meeting ALL the requirements to receive callbacks such as triggers / colliders (review the documentation)

Knowing this information will help you reason about the behavior you are seeing.

You can also supply a second argument to Debug.Log() and when you click the message, it will highlight the object in scene, such as

Debug.Log("Problem!",this);

If your problem would benefit from in-scene or in-game visualization, Debug.DrawRay() or Debug.DrawLine() can help you visualize things like rays (used in raycasting) or distances.

You can also call Debug.Break() to pause the Editor when certain interesting pieces of code run, and then study the scene manually, looking for all the parts, where they are, what scripts are on them, etc.

You can also call GameObject.CreatePrimitive() to emplace debug-marker-ish objects in the scene at runtime.

You could also just display various important quantities in UI Text elements to watch them change as you play the game.

Visit Google for how to see console output from builds. If you are running a mobile device you can also view the console output. Google for how on your particular mobile target, such as this answer or iOS: https://forum.unity.com/threads/how-to-capturing-device-logs-on-ios.529920/ or this answer for Android: https://forum.unity.com/threads/how-to-capturing-device-logs-on-android.528680/

If you are working in VR, it might be useful to make your on onscreen log output, or integrate one from the asset store, so you can see what is happening as you operate your software.

Another useful approach is to temporarily strip out everything besides what is necessary to prove your issue. This can simplify and isolate compounding effects of other items in your scene or prefab.

Here's an example of putting in a laser-focused Debug.Log() and how that can save you a TON of time wallowing around speculating what might be going wrong:

https://forum.unity.com/threads/coroutine-missing-hint-and-error.1103197/#post-7100494

"When in doubt, print it out!(tm)" - Kurt Dekker (and many others)

Note: the

print()

function is an alias for Debug.Log() provided by the MonoBehaviour class.

 

Hello Kurt and thank you for your detailed response.

I appreciate the general debugging tips and understand the value of thorough Debug.Log usage, as well as isolating problems by minimizing the complexity of the project. However, I feel that the issue I'm experiencing is more specific and may be related to nuances in the Unity Editor's lifecycle, PlayerPrefs, or SessionState, rather than the more general potential problems you've outlined.

The core of the issue is that my script is generating duplicate logs stating a "Crash" occurred every time the Unity Editor loses focus and regains it. I've added Debug.Log statements to each method in the script, and the logs confirm that the methods are only being called once each, which is expected.

Here's what I have noticed:

1. On starting the Editor, the log correctly reflects the state in which the last session ended ("Crash" or "Proper Quit").
2. On closing the Editor properly, the log correctly identifies the session as "Proper Quit".
3. However, when the Editor loses focus and regains it, two new lines appear in the log, always indicating a "Crash" event.

From my observations, the Editor doesn't seem to be crashing or restarting, yet the log still states a "Crash" occurred. I suspect this might be tied to how the Editor handles focus loss and regain events, or maybe how PlayerPrefs or SessionState operates under such conditions.

Do you, or does anyone else, have any insight into this specific behaviour or have encountered similar issues before?

Thanks in advance for your help.

 

I solved the problem by creating a simple Windows console to track the time of the Unity process.
If anyone needs it you can find the git here: https://github.com/PixelFireXY/Unity-Editor-Time-Tracker with the exe already built inside the bin/Debug folder
This is just a workaround, if someone knows why Unity behaves like that, please let me know.