Applicationinsights-js: Duplicate logs are coming in appinsights[BUG]

[PraveenVerma17]

Description/Screenshot

Steps to Reproduce
Duplicate logs are appering in appinsights, after checking we can see that track call is sending old logs also in array of new log.
I am also using isStorageUseDisabled true and maxBatchInterval 0. Looks like appinsights are now flusing old logs.

• OS/Browser:
• SDK Version [e.g. 22]:
• How you initialized the SDK:

Expected behavior
Should send only one log instead of old one in track call.

Additional context
Add any other context about the problem here.

[kryalama]

Hello @PraveenVerma17 I am not able to repro the issue. Could you please share a fiddler trace of when the data is sent out. We want to check if the reason for resend was from a response from Breeze that is forcing the SDK to resend the data. Also please add enableDebug: true to your configuration when you capture this.
Note: Please ensure that you dont include any sensitive data in the trace you will be sharing.

[thoo1]

I'm also seeing this, I'll try for a repro but this is only happening to a small set of logs in our application
If it helps, we can observe this in our application insight logs by looking up logs that have the same itemId, this duplication spike at 11/9/2020 7:00AM UTC and 11/9/2020 12:00PM UTC

[thoo1]

@kryalama is there a way to find what the response of our track calls were? I think app insight sdk filters it out on purpose so we dont know if the /track call was successful or not
I think it is probably like you said, the api probably said to resend the data or something

[MSNev]

The easiest would be to view the Network tab on the browser developer console (F12), or if this is in a dev/test environment try using the debug plugin extension (https://github.com/microsoft/ApplicationInsights-JS/tree/master/extensions/applicationinsights-debugplugin-js) as it hooks a lot of the internal components and events and makes it a lot easier to visualize what is going on.

[PraveenVerma17]

Guys,
i have fixed this issue by making small code change. My appinsight TelemetryService class were not singleton earlier , after making it singleton it resolved the issue.

export class TelemetryService {
    constructor() {
        const instance = this.constructor.instance;
        if (instance) {
            return instance;
        }

        let sessionInstrumentationKey =   sessionStorage.getItem('instrumentationKey');
         if(sessionInstrumentationKey){
           this.instrumentationKey = sessionInstrumentationKey;
         }
        const browserHistory = createBrowserHistory({ basename: '' });
        this.reactPlugin = new ReactPlugin();
        this.appInsights = new ApplicationInsights({
            config: {
                instrumentationKey: this.instrumentationKey,
                maxBatchInterval: 0,
                disableFetchTracking: true,
                disableAjaxTracking: true,
                isStorageUseDisabled: true
            },
            extensions: [this.reactPlugin],
            extensionConfig: {
                [this.reactPlugin.identifier]: { history: browserHistory }
            }
        });
        this.appInsights.loadAppInsights();
        this.constructor.instance = this;
    }

}

export function _logInformation(infoMessage)
{
    try{
        let ai = new TelemetryService();
        ai.appInsights.clearAuthenticatedUserContext();

        let telemetryInitializer = getTelemetryInitializer();
        if(telemetryInitializer !== null){
            ai.appInsights.addTelemetryInitializer(getTelemetryInitializer());
        }

        ai.appInsights.trackTrace({ message: `${JSON.stringify(infoMessage)}`, severityLevel: SeverityLevel.Information }, addCustomData());
        ai.appInsights.flush();
    }catch(err)
    {

    }
}

[thoo1]

@MSNev, thanks might try that
The problem for me isn't multiple instances of the appInsights object

I only observed duplicate logs every so often for some users in our application insight logs. Since I can't find a repro of the issue, I'll have to just rely on logs to figure out why this happens

Would the plugin log what the SDK is doing internally so I can root cause this?

[MSNev]

The DebugPlugin is strictly designed for dev/test only, it "logs" to an internal array and provides a visualization of the last 500 events in it's own fullscreen UI (when you show the dashboard). It doesn't get logged anywhere else, so in terms of your issue with "every so often", it may not be overly useful -- unless it's some sort of race condition that you can trigger. We do have plans to eventually allow mocking responses to trigger error cases and extended delays via this plugin, but we haven't implemented that yet.

[MSNev]

Are the duplicates linked to any specific browser / version? Or is there anything else that appears to be common for the duplicated events?

[thoo1]

not linked to browser, something that seems to appear common is that the duplicates happen around the same timeperiod, across users

This might give an indication that there is a server issue? Maybe they are all retrying around the same time period because of an issue?

[thoo1]

I can give you specific timeframes if you want

[MSNev]

@thoo1 If you can supply the timeframe and a couple of the Id's we can forward onto the server team to see if there was an issue of some kind. Has it occurred again (or on a regular schedule etc) or was in some short lived event? (i.e. what is meant by "every so often") @kryalama once we get the data can you follow up with the breeze (internal server) team on whether there was an issue for the supplied events.

Looking at the code, if we assume that the SDK sent it twice then there would have had to have been some very specific XHR return codes https://github.com/microsoft/ApplicationInsights-JS/blob/master/channels/applicationinsights-channel-js/src/Sender.ts#L685, so it might be a case that the SDK sent it once, but for some reason the events go retried (sent to a backup server during ingestion or something) -- I'm not sure what the internal logging exists to detect this.

[thoo1]

for sure!
What I mean by "every so often" is that, these duplicate logs occur within the same short time period, and there are multiple of these time periods throughout each day. There doesn't seem to be any regular schedule when it occurs

For example, here is a scatter plot of duplicate requests, binned by 5 mins for the last 24 hours

There is one notable outlier where it seems to be >8000 duplicate logs within a 5 min time period (between 11/12/2020, 2:00:00 AM - 11/12/2020, 2:05:00 AM). I'll choose this time period since there seem to be a lot more duplicates here

5 itemIds that were duplicated during this time period:
66c12622-24ef-11eb-bcad-a9126105a78a
6df07175-24ef-11eb-9c9f-154b34e6482a
6e3d31ed-24ef-11eb-bfff-eb5796833fb3
6ef51038-24ef-11eb-94e4-513366d01146
72e2ec43-24ef-11eb-8bbd-0f51dc4586ab

Let me know if you want any more time periods or itemIds, thanks for taking a look!

[thoo1]

I'll provide some more itemIds since the previous 5 I gave was using kusto "sample-distinct" which is not a fair, randomly distributed sampling
More itemIds within timeperiod (UTC): 11/12/2020 2:00:00 AM - 11/12/2020 2:05:00AM

1318d269-248b-11eb-b500-7b23722f72f8
26b39711-248b-11eb-b041-63ee4cf0ac94
31e4e2b3-248b-11eb-932e-7f6291401835
37369476-248b-11eb-919d-ff2a4b504b76
30582839-248b-11eb-9a13-a3f5af5d24b8
50ddf681-248b-11eb-8ffa-8108d500fbda
58a16b87-248b-11eb-ae35-2b7ccf05ec56
60f14213-248b-11eb-80f0-d35ce439b65a
6a5e9692-248b-11eb-9207-bb2f686f61f9

[thoo1]

@MSNev @kryalama any update on this? Wondering if you could find anything on the ids

[kryalama]

@thoo1 got a response from the Breeze internal server team. Apparently there are several regions where the ingestion data volume is too high for the pipeline to handle, primarily East US at this point. The response times in these regions are significantly higher and could lead to timeouts (408s). Customers in these regions are likely to experience data duplication when the client, like the JS sdk retries after a timeout. We are looking for some workarounds to mitigate this. Will keep you updated once we have an answer.

[MSNev]

Closing as I think we have answered the outstanding questions, if not please re-open or comment with more additional info and we can re-open etc.

[thoo1]

sounds good, as far as the library is concerned I think you're right to close the issue. I just checked for duplicates in last 2 weeks and see a few but not as many as originally
@kryalama was there any progress on the data duplication issue?