Message Handler in Perspective View Executed Twice on One Call

Ignition Version: 8.1.10

During testing today we saw some odd behavior that I hope someone can help me identify a cause.
In this case, a view button component script calls a Project Library script. The Library script does validation of parts and runs, and if determined appropriate, the part is added to the current run by means of calling a message hander in the view. The message handler calls a function to add the part information to a DB table that contains the parts in association with the run id (as a FK to the runs table).
What we saw this morning was about a dozen parts, when submitted by the tester, were added twice to the DB table. Some parts did NOT do this, about a half dozen. There were about 3 that added normally before the duplicates started, and then 2 more after the duplicates ended.
Each of the duplicate pairs were added at the exact same time, or within a few milliseconds (e.g. both entries for part A were added to the table at 09:33:35.322).

aligner_id runId in_tumbler machine_id created_at
103000L14A 281 0 93 2021-11-16 07:38:02.887
103000L14A 281 0 93 2021-11-16 07:38:02.887
103000L13A 281 0 93 2021-11-16 07:38:00.403
103000L13A 281 0 93 2021-11-16 07:38:00.400
103000L12A 281 0 93 2021-11-16 07:37:04.860
103000L11A 281 0 93 2021-11-16 07:37:01.720
103000L10A 281 0 93 2021-11-16 07:36:56.113

Looking at the logs, the process looks like it was flowing normally until the message handler in the view was called. At this point every log entry was duplicated.


In the imager above the green boxed area shows log entries that occur once each, and are accurate for the scripts that logged them. The log entries in the red boxed area are the logs generated by message handler and a custom method the message handler calls. Note that these are duplicated and have timestamps that match. The last entry in the green box is logged immediately prior to the script executing the sendMessage function that calls the message handler.
That code looks like this:

if addToRun:
	#add aid to run and mark as in tumber
	payload = {'aid': aid, 'runId': runId, 'machineId': machId, 'assetId': assetId}
	msg = 'Calling addAIDtoRun. Sending data: Run Id - ' + str(runId) + ', AID "' + aid + '", Machine Id - ' + str(machId) + ', Asset Id - ' + str(assetId)
	util.log(ln, msg, ssn)
	system.perspective.sendMessage('AddAlignerToRun', payload=payload, scope='session')

The message handler script is as follows:

import util

ln = 'TumbleStep_AddAID_msgHdlr'
runId = payload['runId']
aid = payload['aid']
machineId = payload['machineId']
assetId = payload['assetId']
msg = 'Adding aligner "' + aid + '" to Run Id ' + str(runId) + 'at Asset Id ' + str(assetId) + ' with Id ' + str(machineId) + '.'
util.log(ln, msg)
self.addAIDtoRun(runId, aid, machineId, assetId)

So the message handler seems to be executing twice in the case of these duplicate entries, resulting in the duplicate log entries and the duplicate items added to the DB table.

I searched through the project to find all places where the message handler is called and there are only 3. Each place that calls this message hander is “mutually exclusive”, meaning that due to the flow of the scripts and what scripts are called, only one of these message handler calls is ever executed.

The source of the execution of the message handler in these cases all stem from the call in the first script segment above.
The message handler is configure for a scope of “session” only.

All that said, is there any known issues with message handler being executed multiple times on a single call from a sendMessage function?
Is there any other reason a sendMessage to a message handler script would cause the script to run multiple times?
Is there anywhere I can look to get more detail on what is causing a message handler to be executed (what function executed the sendMessage, etc.)?

Thanks.

Where is this being called? A submit button press?

Each place that calls this message hander is “mutually exclusive”, meaning that due to the flow of the scripts and what scripts are called, only one of these message handler calls is ever executed.

Given your multiple entries you may want to revisit those areas and make sure that is the case as it would explain this.

For your three mutually exclusive messageHandlers - add another piece to the payload like payload['source']='messageHandlerSource1 for one of them, payload['source']='messageHandlerSource2 for the second and so on. Log this info - it will help you to see if you are getting duplicates due to one message firing twice, or if two separate ones are being fired.

Related to the problem of duplicate rows - what would you say the natural/semantic key of your database table is? From your post, it sounds like you should only have a unique combination of (aligner_id, runId, machine_id) - you should make this, or whatever the unique combination of columns you want on the table, to be a UNIQUE database constraint on the table. Creating UNIQUE database constraints is really the only way to ever be sure you don’t get duplicate rows in a table, and generally speaking database constraints are the only reliable way to ensure structures of database tables, scripts are not enough, double button clicks happen unexpectedly , a tag change event might run twice when you expect it to run once, etc.

Thanks for the suggestions on the additional payload params and table constraints. I’ll add some additional parameters to get more info on the calling entity. I’ll confer with the IT folks about adding constraints to the tables. We’ll have to evaluate the exact configuration, but I’m thinking just the aligner_id and the runId will likely suffice, but I need to verify that and then get it implemented.

That said, it still concerns me that the msg hdlr would seemingly fire off twice when it was only called the one time. Since my original post, the tester has ran through this scenario dozens of more times and the duplication has NOT occurred again. We did have the server rebooted prior to this additional testing.

Just for clarity, there is a single message handler that can be called from one of three different places in the code. Here is a simple diagram of that process flow:


Two of these location are either in or are called from the processAligner script.

  1. The normal flow, if the time since last part added is <= 10 minutes, simply calls the message handler.
  2. If the time since last part added is > 10 minutes, a popup is opened. The “YES” button in the popup then calls the message handler.

The third location is called from a completely different script, the addAlignerByModelRunId script
3. Each item in the Model Run is evaluated to see if it can be added, and if so, the message handler is called for that item