Analytics Startup sometimes results in state Analytics starting = False

[Chiel75]

We use the Analyics.CSharp in an ASP.Net project. After the appPool times out, the memory is cleared. When the website is waking up again because of user activity, the Analytics StartUp() is called again (as it should because we registrered the Analytics as a singleton).

In the logging we can see for a good wake up: 2024-02-05 15:50:59,456 INFO [9] Segment.SegmentAnalytics - Send Identify to Segment 2024-02-05 15:51:04,803 ERROR [7] Segment.SegmentLogger - Exception: at System.Text.Json.ThrowHelper.ReThrowWithPath(ReadStack& state, JsonReaderException ex) at System.Text.Json.Serialization.JsonConverter1.ReadCore(Utf8JsonReader& reader, JsonSerializerOptions options, ReadStack& state) at System.Text.Json.JsonSerializer.ReadFromSpan[TValue](ReadOnlySpan1 utf8Json, JsonTypeInfo jsonTypeInfo, Nullable1 actualByteCount) at System.Text.Json.JsonSerializer.ReadFromSpan[TValue](ReadOnlySpan1 json, JsonTypeInfo jsonTypeInfo) at System.Text.Json.JsonSerializer.Deserialize[TValue](String json, JsonSerializerOptions options) at Segment.Serialization.JsonUtility.FromJson[T](String json) at Segment.Analytics.System.DefaultState(Configuration configuration, IStorage storage) 2024-02-05 15:51:04,807 ERROR [7] Segment.SegmentLogger - Message: Failed to load settings from storage. Switch to default settings provided through configuration. 2024-02-05 15:51:04,815 DEBUG [8] Segment.SegmentLogger - Analytics starting = False 2024-02-05 15:51:04,825 DEBUG [9] Segment.SegmentAnalytics - Segment Analytics: Initialized 2024-02-05 15:51:04,827 DEBUG [9] Segment.SegmentAnalytics - Segment Analytics: Added the event plugin. 2024-02-05 15:51:04,832 INFO [9] Segment.SegmentAnalytics - Send Group to Segment 2024-02-05 15:51:04,833 DEBUG [19] Segment.SegmentLogger - SegmentStartupQueue queueing event 2024-02-05 15:51:04,893 DEBUG [6] Segment.SegmentLogger - Analytics starting = False 2024-02-05 15:51:04,904 DEBUG [6] Segment.SegmentLogger - Segment.io performing flush 2024-02-05 15:51:05,614 DEBUG [8] Segment.SegmentLogger - Analytics starting = False 2024-02-05 15:51:05,623 DEBUG [7] Segment.SegmentLogger - Analytics starting = False 2024-02-05 15:51:05,624 DEBUG [19] Segment.SegmentLogger - Analytics starting = True

Everything works fine and I guess the "Analytics starting = True" should be read as started?

An example of a bad wake up: 2024-02-05 16:16:45,758 INFO [12] Segment.SegmentAnalytics - Send Identify to Segment 2024-02-05 16:16:45,882 ERROR [6] Segment.SegmentLogger - Exception: at System.Text.Json.ThrowHelper.ReThrowWithPath(ReadStack& state, JsonReaderException ex) at System.Text.Json.Serialization.JsonConverter1.ReadCore(Utf8JsonReader& reader, JsonSerializerOptions options, ReadStack& state) at System.Text.Json.JsonSerializer.ReadFromSpan[TValue](ReadOnlySpan1 utf8Json, JsonTypeInfo jsonTypeInfo, Nullable1 actualByteCount) at System.Text.Json.JsonSerializer.ReadFromSpan[TValue](ReadOnlySpan1 json, JsonTypeInfo jsonTypeInfo) at System.Text.Json.JsonSerializer.Deserialize[TValue](String json, JsonSerializerOptions options) at Segment.Serialization.JsonUtility.FromJson[T](String json) at Segment.Analytics.System.DefaultState(Configuration configuration, IStorage storage) 2024-02-05 16:16:45,884 ERROR [6] Segment.SegmentLogger - Message: Failed to load settings from storage. Switch to default settings provided through configuration. 2024-02-05 16:16:45,889 DEBUG [9] Segment.SegmentLogger - Analytics starting = False 2024-02-05 16:16:45,895 DEBUG [12] Segment.SegmentAnalytics - Segment Analytics: Initialized 2024-02-05 16:16:45,896 DEBUG [12] Segment.SegmentAnalytics - Segment Analytics: Added the event plugin. 2024-02-05 16:16:45,899 INFO [12] Segment.SegmentAnalytics - Send Group to Segment 2024-02-05 16:16:45,900 DEBUG [5] Segment.SegmentLogger - SegmentStartupQueue queueing event 2024-02-05 16:16:45,908 DEBUG [5] Segment.SegmentLogger - Analytics starting = False 2024-02-05 16:16:45,917 DEBUG [9] Segment.SegmentLogger - Segment.io performing flush 2024-02-05 16:16:46,613 DEBUG [21] Segment.SegmentLogger - Analytics starting = False 2024-02-05 16:16:46,617 DEBUG [21] Segment.SegmentLogger - Analytics starting = True 2024-02-05 16:16:46,617 DEBUG [5] Segment.SegmentLogger - Analytics starting = False 2024-02-05 16:16:46,617 DEBUG [11] Segment.SegmentLogger - SegmentStartupQueue queueing event 2024-02-05 16:17:15,918 DEBUG [6] Segment.SegmentLogger - Segment.io performing flush

The last state changes of the Analytics starting are at the exact same moment: 2024-02-05 16:16:46,617 Everything is loaded just fine but I think something async is messing with the starting state. After this happens, a SegmentStartupQueue queueing event will appear and my calls will be pushed in that startupqueue and will never be delivered to Segment.

To Reproduce Steps to reproduce the behavior:

1. After a website is started wait for the appPool to timeout (default 20 minutes, default terminates the memory)
2. Wake the website up again and do something that triggers a call
3. See error

Expected behavior Everytime the Analytics client is started because of the appPool cleaned itself from memory should result in an initilaized state again.

Platform (please complete the following information):

• Library Version in use: 2.3.2
• Platform being tested: ASP.Net
• Integrations in use:

Additional context I tested with a change in the source code, when I make this change waking up seems to go fine every time. ` private void Startup() { Add(new StartupQueue()); Add(new ContextPlugin());

        // use semaphore for this coroutine to force completion,
        // since Store must be setup before any event call happened.
        SemaphoreSlim semaphore = new SemaphoreSlim(0);
        AnalyticsScope.Launch(AnalyticsDispatcher, async () =>
        {
            try
            {
                // load memory with initial value
                _userInfo = UserInfo.DefaultState(Storage);
                await Store.Provide(_userInfo);
                await Store.Provide(System.DefaultState(Configuration, Storage));
                await Storage.Initialize();

                // Moved below part to here.
                // check settings over the network
                if (Configuration.AutoAddSegmentDestination)
                {
                    Add(new SegmentDestination());
                }

                await CheckSettings();
                // TODO: Add lifecycle events to call CheckSettings when app is brought to foreground (not launched)
            }
            catch (Exception e)
            {
                ReportInternalError(AnalyticsErrorType.StorageUnknown, e, message: "Unknown Error when restoring settings from storage");
            }
            finally
            {
                semaphore.Release();
            }
        });
        semaphore.Wait();

        //// check settings over the network
        //AnalyticsScope.Launch(AnalyticsDispatcher, async () =>
        //{
        //    if (Configuration.AutoAddSegmentDestination)
        //    {
        //        Add(new SegmentDestination());
        //    }

        //    await CheckSettings();
        //    // TODO: Add lifecycle events to call CheckSettings when app is brought to foreground (not launched)
        //});
    }

`

[wenxi-zeng]

@Chiel75 that's a good catch. the solution you suggested is great and makes sure the plugin and the settings initialized in sync. however, it could potential block the caller and causing webpage to freeze if the settings take too much time to come back. we will take a look at the issue and see if there is a better way to resolve this race condition without degrade the performance.

[Chiel75]

@wenxi-zeng Ah, yes I understand. Hope you can find a better solution :)

[Chiel75]

@wenxi-zeng Are you working on this? The problem is keeping us from going into full production environment

[wenxi-zeng]

hey @Chiel75, sorry for being slow on this. we are in the middle of some other tasks. let me get back to you next week

[wenxi-zeng]

@Chiel75 the issue should be fixed in the latest release 2.3.4. please have a try. thanks for your patient

[Chiel75]

This is great, my problem is resolved thnx for picking it up.