Search code examples
c#multithreadingpageload

Why is my method being called twice (or more) from Page_Load()


(This is a repost of a question I asked a few hours ago which did not have enough detail and was closed)

I have an import routine that takes content from a json file and uses JsonConvert.Deserialize() to read the content into a dynamic variable called "items". Here's a snippet of the code (some stuff removed for brevity - this routine is 800 lines long....)

It is triggered from the Page_Load event like so;


        protected void Page_Load(object sender, EventArgs e)
        {
            
            if (Helpers.RequestString("task") == "importData") // Helpers is a function I have created to sanitize query string input
            {
                ImportData_new(); // this is the process being called
            }
        }

I am appending to a StringBuilder object during this process then writing the contents of the string builder to a log file at the end of looping through the items in the json.

Now the method itself;

private void ImportData_new()
        {
            _importGroup = DateTime.Now.ToString("yyyy-MM-dd HH:mm:ss");
            _logOutput.Clear();
            _logOutput.Append(string.Format("{0}: {1}{2}", DateTime.Now.ToString("yyyy-MM-dd HH:mm:ss"), "###################### INITIALISING IMPORT ROUTINE #######################", Environment.NewLine));
            //File.AppendAllText(_logPath, _logOutput.ToString());
            var OK = true;

            // Grab the text file contents
            var file_content = "";

            try
            {
                file_content = System.IO.File.ReadAllText(_filePath + "testjson.json");
            }
            catch (Exception e)
            {
                OK = false;
                //_logOutput.Clear();
                _logOutput.Append(string.Format("{0}: {1}{2}{3}################# IMPORT ABORTED #################{3}", DateTime.Now.ToString("yyyy-MM-dd HH:mm:ss"), "Import aborted: Unable to read text from text file. Error: ", e.Message, Environment.NewLine));
                File.AppendAllText(_logPath, _logOutput.ToString());
            }
            var file_content = System.IO.File.ReadAllText(_filePath + "testjson.json");
            dynamic items = JsonConvert.DeserializeObject(file_content);
            foreach (dynamic item in items){
                // read values from the "item" dynamic object and use them to create a database record/row
                // Here's one example of the numerous sections I am processing
                var DayNightValue = item["TabA OperationalHours"] != null && item["TabA OperationalHours"].Value != null && item["TabA OperationalHours"].Value != "" && item["TabA OperationalHours"].Value.ToString().Trim() != "" ? item["TabA OperationalHours"].Value.ToString().Trim() : "";
                        if (DayNightValue != "")
                        {
                            if (DayNightValue.ToString().ToLower().StartsWith("day"))
                            {
                                _logOutput.Append(string.Format("{0}: {1}{2}", DateTime.Now.ToString("yyyy-MM-dd HH:mm:ss"), "Item " + counter + ": Day/Night: Day", Environment.NewLine));
                                hems.DayNightVal = "Day";
                            }
                            if (DayNightValue.ToString().ToLower().StartsWith("night"))
                            {
                                _logOutput.Append(string.Format("{0}: {1}{2}", DateTime.Now.ToString("yyyy-MM-dd HH:mm:ss"), "Item " + counter + ": Day/Night: Night", Environment.NewLine));
                                hems.DayNightVal = "Night";
                            }
                        }
                        else
                        {
                            hems.DayNightVal = null;
                            _logOutput.Append(string.Format("{0}: {1}{2}", DateTime.Now.ToString("yyyy-MM-dd HH:mm:ss"), "## WARNING for Item " + counter + ": Day/Night value is empty. Setting as null.", Environment.NewLine));
                        }
                ...process the rest of the properties in the json item
            } // end of the for loop.
}
....<snipped>

At the end of the routine I output the log info to a text file. The log file shows that one loop is running but before it completes another one starts, so the log file shows information from one loop mixed in with another. There should be 3 records written to the log per import (testing with only 3 records). But what is happening is that the routine starts one import but then a secondary import seems to happen alongside it - see below (my notes are in CAPS surrounded by square braces). Note the out of order writing of the line (see time stamps).

[**IMPORT STARTS**]
2020-08-06 13:18:12: ###################### INITIALISING IMPORT ROUTINE #######################
2020-08-06 13:18:12: 3 rows found.....
2020-08-06 13:18:12: Importing Item 1: Flight Record: xxxx, Mission Date: 4/08/2020 12:00:00 AM, Mission Number: 343, Patient: xxxx
2020-08-06 13:18:12: Item 1: Mission Authorised By Airdesk (Value Yes).
2020-08-06 13:18:12: Item 1: Service Item Code Value: (Supplied: ETA11) Actual ID:6888
2020-08-06 13:18:12: Item 1: Day/Night: Day
2020-08-06 13:18:12: Item 1: Reason for use of Helicopter (Value: Multi reasons), actual ID: 8.
2020-08-06 13:18:12: Item 1: Mission Type Value: (Supplied: Pre Hospital Trauma) Actual ID:6906
2020-08-06 13:18:12: Item 1: Patient Outcome Value: (Supplied: Life saved) Actual ID:7134
[**......SNIPPED SOME OF THE ROWS**]
[**LOG GOES THROUGH FIRST ITEM IN IMPORT BUT THEN INSTEAD OF SHOWING THE NEXT TWO ITEMS, SHOWS THE FINISHED NOTIFICATION**]
2020-08-06 13:18:12: ############ IMPORT FINISHED ############
[**THEN SHOWS ANOTHER ONE STARTING - NOTE IT SAYS "Item 1" again...**]
2020-08-06 13:18:12: ###################### INITIALISING IMPORT ROUTINE #######################
2020-08-06 13:18:12: 3 rows found.....
2020-08-06 13:18:12: Importing Item 1: Flight Record: 5676, Mission Date: 4/08/2020 12:00:00 AM, Mission Number: 343, Patient: xxxx
2020-08-06 13:18:12: Item 1: Mission Authorised By Airdesk (Value Yes).
2020-08-06 13:18:12: Item 1: Service Item Code Value: (Supplied: ETA11) Actual ID:6888
2020-08-06 13:18:12: Item 1: Day/Night: Day
[**......SNIPPED SOME OF THE ROWS - SAYS IT'S FINISHED AFTER 1 ITEM AGAIN**]
2020-08-06 13:18:12: ############ IMPORT FINISHED ############
[**NOW THE TIME IN THE LOG CHANGES TO 27 SECONDS AFTER THE IMPORT STARTED - BUT THIS TIME SEEMINGLY STARTING ON Item 2**]
2020-08-06 13:18:29: Importing Item 2: Flight Record: 5678, Mission Date: 4/08/2020 12:00:00 AM, Mission Number: 474, Patient: xxxx
2020-08-06 13:18:29: Item 2: Mission Authorised By Airdesk (Value Yes).
2020-08-06 13:18:29: Item 2: Service Item Code Value: (Supplied: METAT11) Actual ID:6902
2020-08-06 13:18:29: Item 2: Day/Night: Night
[**......SNIPPED SOME OF THE ROWS**]
[**FINISHES AFTER ITEM 2 THIS TIME**]
2020-08-06 13:18:29: ############ IMPORT FINISHED ############
2020-08-06 13:18:12: ###################### INITIALISING IMPORT ROUTINE #######################
2020-08-06 13:18:12: 3 rows found.....
[**IMPORT STARTS AGAIN - AND NOTE THE TIME STAMP HAS GONE IN REVERSE**]
[**FINISHES AGAIN AFTER ONLY ONE ITEM**]
2020-08-06 13:18:12: ############ IMPORT FINISHED ############
[**NOTE THE TIME HAS CHANGED YET AGAIN**]
2020-08-06 13:18:29: Importing Item 2: Flight Record: 5678, Mission Date: 4/08/2020 12:00:00 AM, Mission Number: 474, Patient: xxxx
2020-08-06 13:18:29: Item 2: Mission Authorised By Airdesk (Value Yes).
2020-08-06 13:18:29: Item 2: Service Item Code Value: (Supplied: METAT11) Actual ID:6902
2020-08-06 13:18:29: Item 2: Day/Night: Night
2020-08-06 13:18:29: Item 2: Reason for use of Helicopter (Value: Time), actual ID: 3.
2020-08-06 13:18:29: Item 2: Mission Type Value: (Supplied: IHT) Actual ID:6908
2020-08-06 13:18:29: Item 2: Patient Outcome Value: (Supplied: Further complications avoided) Actual ID:6973
[**CONTINUES TILL DONE - BUT ERRORS ON THE BROWSER PAGE AS IT WOULD SEEM THAT TWO THREADS ARE ATTEMPTING TO OPEN THE LOGGING TXT FILE AT ONCE**]

So, it looks like there are indeed at least two (possibly more, looking at the log as an indication) processes running the ImportData_new() method. Could there be an issue with the Page_Load here? It is the only process calling the method.

Cliff


Solution

  • Just in case anyone views this in future. Here's what my problem actually was.

    1. I was using Visual Studio's inbuilt web server (Cassini)
    2. I was using a 'dynamic' variable to read the JSON data I was receiving and then looping through that dynamic
    3. I changed the debugger to use IIS instead of Cassini. That fixed the issue momentarily (I understand that Cassini has less memory allocation space than IIS - apparently)
    4. It seems as though the use of the dynamic variable type lead to some form of memory over-run and it crashed the debugger with a stackoverflow condition.
    5. Changing my dynamic var to a class-mapped JSON arrangement seemed to fix the issue.

    I am unsure as to 'why' this was the case as even with just one item in the JSON object, the dynamic would cause the stackoverflow. Once I moved away from the dynamic, it ran fine - and has run fine for the last 3 weeks.

    Hope this info helps someone.