404's logged multiple times

[PhilDye]

v3.13.1 from nuget

We're seeing each genuine 404 request (ie falling right through, with no redirect) being logged 44 times. This is adding significant subsequent rows for subsequent queries to search, and hitting performance hard, especially as we've just launched it in a new site, that is generating significant 404's.

Possibly related to #166 ?

[PhilDye]

Correction; the 44 repeated log entries isn't consistent - it changes, always in the order of "tens" of entries. Suspect this may be retry handling in the DatabaseContext perhaps (we're using Azure SQL)?

[daniel-chenery]

@PhilDye I can confirm 404s are being logged multiple times for me as well. However, it's only logging each 404 3 times.
I'll see if I can spin-up an Azure site sometime soon to replicate on there, and see if it is more logging.

In the meantime, if it is the same URL, you could potentially add it to the ignore list

[daniel-chenery]

@PhilDye I've a suspicion I know what's going on here. Would you mind telling me how many times the following is in your log file please? "UrlTracker HttpModule | Subscribed to AcquireRequestState and EndRequest events"

[PhilDye]

@daniel-chenery We'll need to turn up the logging; this site is now in production, so not running at INFO level currently... // @michaelchart

[daniel-chenery]

@PhilDye If it's not doable, then no worries :)

I've a suspicion it's down the the Modules being registered multiple times. I can only assume, Azure, being Shared Hosting has more AppPools, and therefore loads it an excessive amount of times.
Sadly, since the EndRequest is now moved to the UmbracoModule, this is also loaded multiple times so I can't easily determine if we've subscribed to it or not 🙄

[daniel-chenery]

@PhilDye Would you mind giving the latest BETA version and spin and see if this fixes it for you? :)

[PhilDye]

Running this locally first, I'm seeing every log entry (at least) duplicated, but even allowing for that, multiple Subscribed to AcquireRequestState events logged on start (see attached log)
umbracoTraceLog.txt

On the plus side, I do see each 404 getting inserted to the db only once, from some simple tests.

[PhilDye]

Is the duplicate Subscribed to AcquireRequestState simply down to this line being duplicated https://github.com/kipusoep/UrlTracker/blob/master/Modules/UrlTrackerModule.cs#L63 ?!

[daniel-chenery]

Yupp :)

If I pop that in the lock, it causes an (apparently) unknown YSOD.
Was bugging me for ages.

Thanks for the merge, I'll take a look shortly! :)