v6, DrvDsMqtt not publishing anything.

[zzz]

Oh the direction is wrong, too much focus has been put on the MQTT part.
I did some debugging, and got some new clue, but not sure where to dig now:

// ScadaComm/OpenDrivers/DrvDsMqtt.Logic/MqttDSL.cs
// around line :114

                dsLog.WriteInfo("lineTopic={0}", lineTopic);
                foreach (DeviceLogic deviceLogic in devices)
                {
                    string deviceTopic = lineTopic + CommUtils.GetDeviceLogFileName(deviceLogic.DeviceNum, "") + "/";
                    DeviceTopics deviceTopics = new();
                    dsLog.WriteInfo("deviceTopic={0}", deviceTopic);

                    foreach (DeviceTag deviceTag in deviceLogic.DeviceTags)
                    { // <------- NEVER ENTERED, code fall through with no hint in log.
                        dsLog.WriteInfo("deviceTag {0},{1},{2}", deviceTag.Name, deviceTag.Code, deviceTag.TagNum);
                        if (!string.IsNullOrEmpty(deviceTag.Code))
                            deviceTopics[deviceTag.Code] = deviceTopic + deviceTag.Code;
                    }

                    dsLog.WriteInfo("topicByDevice[{0}]=topics[{1}]", deviceLogic.DeviceNum, deviceTopics.Count);
                    if (deviceTopics.Count > 0)
                        topicByDevice[deviceLogic.DeviceNum] = deviceTopics;
                }

In the DrvDsMqtt log now I get

2022-11-03 11:52:38 MQTT data source stopped
--------------------------------------------------------------------------------
--------------------------------------------------------------------------------
2022-11-03 11:52:51 MQTT data source started
2022-11-03 11:52:51 lineTopic=Communicator/line001/
2022-11-03 11:52:51 deviceTopic=Communicator/line001/device001/
2022-11-03 11:52:51 topicByDevice[1]=topics[0]
2022-11-03 11:52:51 lineTopic=Communicator/line002/
2022-11-03 11:52:51 deviceTopic=Communicator/line002/device002/
2022-11-03 11:52:51 topicByDevice[2]=topics[0]

2022-11-03 11:52:51 Connect to 127.0.0.1:1883
Connected successfully

2022-11-03 11:52:51 Subscribe to command topic
2022-11-03 11:52:51 TryPeek.got tags_len73, cnl_len73, desc, dev#1, ts11/3/2022 3:52:51 AM
2022-11-03 11:52:51 PublishDeviceSlice returns true
2022-11-03 11:52:51 PublishCurrentData.Dequeue
2022-11-03 11:52:51 TryPeek.got tags_len49, cnl_len49, desc, dev#2, ts11/3/2022 3:52:51 AM
2022-11-03 11:52:51 PublishDeviceSlice returns true
2022-11-03 11:52:51 PublishCurrentData.Dequeue
....

After I noticed deviceTag.Code is being used,
I filled the Code column in ConfDatabase\Devices which used to be empty. Re-upload and restarted the communicator, nothing changed,
then re-upload and restarted server + communicator, nothing changed.

My device setting

  <Device>
    <DeviceNum>    1</DeviceNum>
    <Name>         Sta1</Name>
    <Code>         sta1</Code>
    <DevTypeID>    214</DevTypeID>
    <NumAddress>   1</NumAddress>
    <StrAddress>   192.168.1.1</StrAddress>
    <CommLineNum>  1</CommLineNum>
    <Descr>        STA1</Descr>
  </Device>
  <Device>
    <DeviceNum>    2</DeviceNum>
    <Name>         Sta2</Name>
    <Code>         sta2</Code>
    <DevTypeID>    214</DevTypeID>
    <NumAddress>   1</NumAddress>
    <StrAddress>   192.168.2.1</StrAddress>
    <CommLineNum>  2</CommLineNum>
    <Descr>        STA2</Descr>
  </Device>
</ArrayOfDevice>

Below is how one of my two device templates looks like, they are similar

<DeviceTemplate>
  <Options>... </Options>
  <ElemGroups>
    <ElemGroup active="true" dataBlock="DiscreteInputs" address="0" name="Runs">
<!-- Unused registers have their name left "" -->
      <Elem tagCode="C6_RUN"   name="M0" />
      <Elem tagCode="C6_ALMR"  name="M1" />
      <Elem tagCode="C7_RUN"   name="M2" />
      <Elem tagCode="C7_ALMR"  name="M3" />
...
      <Elem tagCode="RSV1"     name="" />
      <Elem tagCode="RSV2"     name="" />
...
      <Elem tagCode="Z1_RUN"   name="M66" />
      <Elem tagCode="Z6_ALMR"  name="M67" />
      <Elem tagCode="RSV19"    name="" />
      <Elem tagCode="RSV20"    name="" />
      <Elem tagCode="RSV21"    name="" />
      <Elem tagCode="RSV22"    name="" />

• This reply was modified 1 year, 5 months ago by zzz.

[Mikhail]

Could you provide steps how to modify the HelloWorld project to reproduce the issue?

[zzz]

The server’s project is not modified from HelloWorld. I just copy the compiled version to server, managed to get it running and choose download the project and build from there.

I think playing with the project configuration is taking too much time.
I’d rather spend some time debugging from the code side.
I am not saying the code has any issue, but looks like its easier to find the cause, otherwise I would still be stuck here wondering what is going on inside the mqtt plugin.
Also it helps to understand how the v6 works.

Do you have any suggestion of what could be causing the issue, which part of the code or what object worth inspection from where ? I just need some hints.

[zzz]

I see the tags are populated via device driver’s InitDeviceTags() call.

// ScadaComm/OpenDrivers/DrvModbus.Logic/DevModbusLogic.cs
// around line 310
                    // add device tag
                    tagGroup.AddTag(elemConfig.TagCode, elemConfig.Name).SetFormat(GetTagFormat(elemConfig));
                    Log.WriteInfo("tagGrp.AddTag {0},{1}", elemConfig.TagCode, elemConfig.Name);

                    elemIndex++;
                }

                if (groupActive)
                {
                    elemGroup.InitReqPDU();
                    elemGroup.InitReqADU(deviceModel.Addr, transMode);
                    deviceModel.ElemGroups.Add(elemGroup);
                }

                DeviceTags.AddGroup(tagGroup);
                Log.WriteInfo("DeviceTags.AddGroup(name={0})", tagGroup.Name);

            }
            Log.WriteInfo("DeviceTags.Count={0}", DeviceTags.Count);

2022-11-04 11:31:44 Communication line [2] Bus2 is stopped
--------------------------------------------------------------------------------
--------------------------------------------------------------------------------
2022-11-04 11:31:48 Start communication line [2] Bus2
Load device template from file KpModbus_BeiChenFxConv_STA2.xml
2022-11-04 11:31:48 tagGrp.AddTag D16_RUN,M0
2022-11-04 11:31:48 tagGrp.AddTag D16_ALMR,M1
2022-11-04 11:31:48 tagGrp.AddTag D17_RUN,M2
2022-11-04 11:31:48 tagGrp.AddTag D17_ALMR,M3
...
2022-11-04 11:31:48 tagGrp.AddTag RV1,
2022-11-04 11:31:48 tagGrp.AddTag RV2,
...
2022-11-04 11:31:48 DeviceTags.AddGroup(grp_name=Runs)
2022-11-04 11:31:48 DeviceTags.Count=48   
                                    ^^^
DevModbusLogic.DeviceTags.Count IS NOT ZERO after InitDeviceTags()
Everything looks fine in Communicator line00x.txt and line00x.log

Any ideas ?

[zzz]

The DeviceTags is passed around many places, this will take some time without help.
So I just did a simple test with diagslave – a modbus slave simulator (./diagslave -m enc -a 1 -p 50502, enc: RTU over TCP mode ). Added a CommLine:MBBus, Device:MBDevice, Channel:V1 in HelloWorld project on the helloworld debian10 box, the simulator’s line001/xxx topics published as usual, but there is no topic about newly added modbus line002,
scadacomm and scadaserver service both have been restarted many times .

• This reply was modified 1 year, 5 months ago by zzz.

[zzz]

Argh, there seems to be a sequence issue, DrvDsMqtt’s topics are populated before Modbus Driver’s deviceTags are populated.

Is there any event or flag that DrvDsMqtt could listen/wait for before FillDeviceTopics() in Start() ?

// ScadaComm/ScadaComm/ScadaCommEngine/CommLine.cs

// around L192
        /// <summary>
        /// Adds the device to the communication line, eliminating duplication of devices.
        /// </summary>
        private void AddDevice(DeviceLogic deviceLogic)
        {
            Log.WriteInfo("AddDevice: #{0} T{1}", deviceLogic.DeviceNum, deviceLogic.Title);
            if (!deviceMap.ContainsKey(deviceLogic.DeviceNum))
            {
                Log.WriteInfo("AddDevice not in devMap: #{0} TagCnt:{1}", deviceLogic.DeviceNum, deviceLogic.DeviceTags.Count);
                DeviceWrapper deviceWrapper = new DeviceWrapper(deviceLogic, Log)
                {
                    DeviceIndex = devices.Count,
                    InfoFileName = Path.Combine(coreLogic.AppDirs.LogDir,
                        CommUtils.GetDeviceLogFileName(deviceLogic.DeviceNum, ".txt"))
                };
                Log.WriteInfo("AddDevice > deviceWrapper.DeviceLogic: #{0} TagCnt:{1}", 
                    deviceWrapper.DeviceLogic.DeviceNum, 
                    deviceWrapper.DeviceLogic.DeviceTags.Count);

// around L813

        /// <summary>
        /// Selects all devices on the communication line.
        /// </summary>
        public IEnumerable<DeviceLogic> SelectDevices()
        {
            foreach (DeviceWrapper dw in devices)
            {
                Log.WriteInfo("SelectDevices:devices.deviceLogic.DeviceTags len={0}", dw.DeviceLogic.DeviceTags.Count);
                foreach (DeviceTag deviceTag in dw.DeviceLogic.DeviceTags)
                {
                    Log.WriteInfo("SelectDevices:devices.deviceLogic.DeviceTags.deviceTag {0},{1},{2}", deviceTag.Name, deviceTag.Code, deviceTag.TagNum);
                }
            }
            return devices.Select(dw => dw.DeviceLogic);
        }

2022-11-04 14:28:15 Communication line [1] Bus1 is stopped
--------------------------------------------------------------------------------
2022-11-04 14:28:19 AddDevice: #1 T[1] Sta1
2022-11-04 14:28:19 AddDevice not in devMap: #1 TagCnt:0
2022-11-04 14:28:19 AddDevice > deviceWrapper.DeviceLogic: #1 TagCnt:0
2022-11-04 14:28:20 SelectDevices:devices.deviceLogic.DeviceTags len=0 
2022-11-04 14:28:20 SelectDevices:devices.deviceLogic.DeviceTags len=0
2022-11-04 14:28:20 SelectDevices:devices.deviceLogic.DeviceTags len=0
--------------------------------------------------------------------------------
2022-11-04 14:28:20 Start communication line [1] Bus1
Load device template from file KpModbus_BeiChenFxConv_STA1.xml
2022-11-04 14:28:20 SelectDevices:devices.deviceLogic.DeviceTags len=0  <-- SelectDeivces() happens before .AddDeveices() ?
2022-11-04 14:28:20 tagGrp.AddTag C6_RUN,M0
2022-11-04 14:28:20 tagGrp.AddTag C6_ALMR,M1
2022-11-04 14:28:20 tagGrp.AddTag C7_RUN,M2
2022-11-04 14:28:20 tagGrp.AddTag C7_ALMR,M3

meanwhile in drvdsmqtt’s log

2022-11-04 14:28:16 MQTT data source stopped
--------------------------------------------------------------------------------
--------------------------------------------------------------------------------
2022-11-04 14:28:20 MQTT data source started
2022-11-04 14:28:20 lineTopic=Communicator/line001/
2022-11-04 14:28:20 deviceTopic=Communicator/line001/device001/
2022-11-04 14:28:20 topicByDevice[1]=topics[0]
2022-11-04 14:28:20 lineTopic=Communicator/line002/
2022-11-04 14:28:20 deviceTopic=Communicator/line002/device002/
2022-11-04 14:28:20 topicByDevice[2]=topics[0]

2022-11-04 14:28:20 Connect to 127.0.0.1:1883
Connected successfully

• This reply was modified 1 year, 5 months ago by zzz.

[zzz]

Ok, it seems that a 3 seconds sleep before FillDeviceTopics() fixes things most of the time.

But I only have 77 tags. there could be 777,777 tags or more, waiting for a proper fix. I can’t find any tag population completion indicator on CommLine or DeviceLogic.

Considering that v6 is supposed to support millions of tags, this could become an issue when an project reaches that scale.

• This reply was modified 1 year, 5 months ago by zzz.

[Mikhail]

Do you have any suggestion of what could be causing the issue, which part of the code or what object worth inspection from where ?

My thoughts are:
1. The issue is related to Communicator only. I mean you can unset “Application is bound to the configuration database” and stop other services except Communicator.
2. In Data Sources disable ScadaServer data source and activate OpcUaServer. Check if OpcUaServer works correctly or not, comparing with MQTT data source.
3. Change Communicator settings from HelloWorld project to your project to detect the configuration change that causes the problem.

[zzz]

This issue can be closed now.

Root cause is the racing condition, when DrvDsMQTT Start() calls InitDeviceTags() before Modbus driver finished populating the deviceTags.
(all SelectDeivces()>devices.Select() calls happened before the first tagGroup.AddTag call in log)

Dumb fix is adding a few to tens of seconds of waits before InitDeviceTags() call in Start(), depending on the device templates’ size.

Proper fix needs a mechanism for extension/driver/plugins to tell if device/all devices of a commline has finished populating the device tags.
or blocks IContext iteration until the tag population is completed or ?

[Mikhail]

I will check it and write here. Thank you.

[Mikhail]

The fix has been uploaded to GitHub (link).
Could you build and check it?

• This reply was modified 1 year, 5 months ago by Mikhail.

[zzz]

Hi Mik, Thanks, the new on-demand approach seems to work as expected.

--------------------------------------------------------------------------------
2022-11-08 10:04:59 MQTT data source started
2022-11-08 10:04:59 lineTopic=Communicator/line001/
2022-11-08 10:04:59 lineTopic=Communicator/line002/

2022-11-08 10:04:59 Connect to 127.0.0.1:1883
Connected successfully

2022-11-08 10:04:59 Subscribe to command topic
2022-11-08 10:05:00 TryPeek.got tags_len49, cnl_len49, desc, dev#2, ts11/8/2022 2:05:00 AM
2022-11-08 10:05:00 DeviceTopics.Initialize(): deviceTags len=49
2022-11-08 10:05:00 DeviceTopics.Initialize(): deviceTag M0,D16_RUN,1
2022-11-08 10:05:00 DeviceTopics.Initialize(): deviceTag M1,D16_ALMR,2
...
2022-11-08 10:05:00 deviceSlice.ts=11/8/2022 2:05:00 AM,tag_len=49,cnldat_len=49
2022-11-08 10:05:00 deviceTag.code=D16_RUN,name=M0,cnl=Scada.Data.Entities.Cnl, dlen=1
2022-11-08 10:05:00 topic=Communicator/line002/device002/D16_RUN
2022-11-08 10:05:00 payload=0
2022-11-08 10:05:00 Send Communicator/line002/device002/D16_RUN = 0
2022-11-08 10:05:00 deviceTag.code=D16_ALMR,name=M1,cnl=Scada.Data.Entities.Cnl, dlen=1
2022-11-08 10:05:00 topic=Communicator/line002/device002/D16_ALMR
2022-11-08 10:05:00 payload=0
...
2022-11-08 10:05:00 PublishDeviceSlice returns true
2022-11-08 10:05:00 PublishCurrentData.Dequeue
2022-11-08 10:05:00 TryPeek.got tags_len73, cnl_len73, desc, dev#1, ts11/8/2022 2:05:00 AM
2022-11-08 10:05:00 DeviceTopics.Initialize(): deviceTags len=73
2022-11-08 10:05:00 DeviceTopics.Initialize(): deviceTag M0,C6_RUN,1
2022-11-08 10:05:00 DeviceTopics.Initialize(): deviceTag M1,C6_ALMR,2
2022-11-08 10:05:00 deviceSlice.ts=11/8/2022 2:05:00 AM,tag_len=73,cnldat_len=73
2022-11-08 10:05:00 deviceTag.code=C6_RUN,name=M0,cnl=Scada.Data.Entities.Cnl, dlen=1
2022-11-08 10:05:00 topic=Communicator/line001/device001/C6_RUN
2022-11-08 10:05:00 payload=0
2022-11-08 10:05:00 Send Communicator/line001/device001/C6_RUN = 0
2022-11-08 10:05:00 deviceTag.code=C6_ALMR,name=M1,cnl=Scada.Data.Entities.Cnl, dlen=1
2022-11-08 10:05:00 topic=Communicator/line001/device001/C6_ALMR
...

[Mikhail]

Thank you for finding the error and testing.

[kumajaya]

Glad to hear the issue get solved.

[zzz]

Just found this in the log, maybe of some value ?

2022-11-16 15:16:21 [wst1][appstack][ACT] Communicator 6.0.0.0 started
2022-11-16 15:16:22 [wst1][appstack][ACT] Storage FileStorage 6.0.0.0 loaded from file /app/appstack/rapidscada6/Linux/scada/ScadaComm/FileStora
ge.dll
2022-11-16 15:16:22 [wst1][appstack][ACT] Start logic processing
2022-11-16 15:16:23 [wst1][appstack][ACT] Driver DrvCnlBasic 6.0.0.0 loaded from file /app/appstack/rapidscada6/Linux/scada/ScadaComm/Drv/DrvCnl
Basic.Logic.dllaz
2022-11-16 15:16:23 [wst1][appstack][ACT] Driver DrvDsMqtt 6.0.0.0 loaded from file /app/appstack/rapidscada6/Linux/scada/ScadaComm/Drv/DrvDsMqt
t.Logic.dll
2022-11-16 15:16:23 [wst1][appstack][ACT] Driver DrvDsScadaServer 6.0.0.0 loaded from file /app/appstack/rapidscada6/Linux/scada/ScadaComm/Drv/D
rvDsScadaServer.Logic.dll
2022-11-16 15:16:23 [wst1][appstack][ACT] Driver DrvModbus 6.0.0.0 loaded from file /app/appstack/rapidscada6/Linux/scada/ScadaComm/Drv/DrvModbu
s.Logic.dll
2022-11-16 15:16:23 [wst1][appstack][ACT] Data source ScadaServer initialized successfully
2022-11-16 15:16:28 [wst1][appstack][ACT] Data source MqttServer initialized successfully
2022-11-16 15:16:28 [wst1][appstack][ACT] Data source ScadaServer: Receive the configuration database
2022-11-16 15:16:29 [wst1][appstack][ERR] Data source ScadaServer: Error checking server connection:
Connection refused [::ffff:127.0.0.1]:10000
2022-11-16 15:16:29 [wst1][appstack][ERR] Unable to start communication lines because the configuration database is not received
2022-11-16 15:16:38 [wst1][appstack][ACT] Data source ScadaServer: Receive the configuration database
2022-11-16 15:16:38 [wst1][appstack][ERR] Data source ScadaServer: Error checking server connection:
Connection refused [::ffff:127.0.0.1]:10000
2022-11-16 15:16:38 [wst1][appstack][ERR] Unable to start communication lines because the configuration database is not received
2022-11-16 15:16:48 [wst1][appstack][ACT] Data source ScadaServer: Receive the configuration database
2022-11-16 15:16:51 [wst1][appstack][ACT] Data source ScadaServer: The configuration database has been received successfully
2022-11-16 15:16:51 [wst1][appstack][ACT] Start communication lines
2022-11-16 15:16:52 [wst1][appstack][ERR] Error calling the Start method of the MqttServer data source:
System.InvalidOperationException: Collection was modified; enumeration operation may not execute.
   at System.Collections.Generic.List
1.Enumerator.MoveNext()
   at Scada.Comm.Engine.CommLine.SelectDevices()
   at Scada.Comm.Drivers.DrvDsMqtt.Logic.MqttDSL.FillDeviceTopics()
   at Scada.Comm.Drivers.DrvDsMqtt.Logic.MqttDSL.Start()
   at Scada.Comm.Engine.DataSourceHolder.Start()
2022-11-16 15:16:52 [wst1][appstack][ACT] Start reading commands from files
2022-11-16 15:16:52 [wst1][appstack][ACT] Data source ScadaServer: Connection state is Logged In
2022-11-18 10:08:30 [wst1][appstack][ERR] Data source ScadaServer: Error receiving telecontrol commands:
Incorrect format of data received from the server: unable to read data packet header
2022-11-18 10:08:30 [wst1][appstack][ACT] Data source ScadaServer: Connection state is Error
2022-11-18 10:08:30 [wst1][appstack][ERR] Data source ScadaServer: Error receiving telecontrol commands:
Unable to write data to the transport connection: Broken pipe.
2022-11-18 10:08:30 [wst1][appstack][ERR] Data source ScadaServer: Error receiving telecontrol commands:
Connection refused [::ffff:127.0.0.1]:10000
2022-11-18 10:08:35 [wst1][appstack][ERR] Data source ScadaServer: Error receiving telecontrol commands:
Connection refused [::ffff:127.0.0.1]:10000
2022-11-18 10:08:40 [wst1][appstack][ACT] Data source ScadaServer: Connection state is Logged In
2022-11-21 09:07:21 [wst1][appstack][ACT] Stop communication lines
2022-11-21 09:07:21 [wst1][appstack][ACT] All communication lines are stopped
2022-11-21 09:07:21 [wst1][appstack][ACT] Logic processing is stopped
2022-11-21 09:07:21 [wst1][appstack][ACT] Communicator is stopped

What have you done ? Not sure its days ago.

• This reply was modified 1 year, 5 months ago by zzz.
• This reply was modified 1 year, 5 months ago by zzz.

[Author]

Posts