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.
