Bug - Driver workProc strange behavior

[CyaNn]

Hello all,

I am actually facing a really strange bug with an "home made" driver.

I configured 2 points in the DB with different addresses for each chains.
Each point must be updated by each chain respectively every 20s
I've correctly configured the config.redu for both points related to both chain to give the possibility to passive chain to write on active and give its status.
I've connected 2 "watch dogs" mecanisms on each point to check if point is regularly updated (watch dog timeout 50s, that tolerate 2,5 cycles, if timeout expired it set it to default value)

About twice a day, passive point watch dog fall into timeout an set the data to default one.
But if I check the driver logs, driver seems to have written the data correctly every 20s with no time gap or anything else.

Please, help me.... I am at the end of my skills for this point

[CyaNn]

Here is the "storeToDb" method that is responsive to store data to database :

Code: Select all

HWObject* MQDriverHWService::storeToDB(Message* message) {

	if (!message) {
		Logger::getInstance().error(QString("MQDriverHWService::storeToDB: Message is null !"));
		return NULL;
	}

	HWObject *obj = new HWObject();

	obj->setDlen(strlen(message->value));
	obj->setAddress(message->address);
	obj->setData(message->value);

	HWMapper* mapper = (HWMapper*)DrvManager::getHWMapperPtr();
	if ( mapper ) {
		HWObject* addrObj = mapper->findHWObject(obj);

		if ( addrObj ) {
			try {
				DrvManager::getSelfPtr()->toDp(obj, addrObj);
				Logger::getInstance().debug(QString("MQDriverHWService::storeToDB: Message stored to db: [%1:%2]").arg(message->address).arg(message->value));
			} catch (std::exception& ex) {
				Logger::getInstance().error(QString("MQDriverHWService::storeToDB: Exception occured %1").arg(ex.what()));
			} catch (...) {
				Logger::getInstance().error(QString("MQDriverHWService::storeToDB: Unexpected exception"));
			}
		} else {
			if (!unknownAddress.contains(message->address)) {
				Logger::getInstance().warning(QString("Unknown address received: %1").arg(message->address));
			} else {
				Logger::getInstance().debug(QString("Unknown address received: %1").arg(message->address));
			}
			unknownAddress.insert(message->address);
		}
	} else {
		Logger::getInstance().warning(QString("Unknown hwMapper for address: %1").arg(message->address));
	}

	if (message) {
		delete message->address;
		// do not delete message->value, seems to be already deleted by DrvManager
		delete message;
		message = NULL;
	}
	delete obj;

	return NULL;
}

Message* message is a key / value tuple that represent address / value
It is called by void MQDriverHWService::workProc() that dequeue a messages queue (to respect Driver thread architecture)

here is the work proc

Code: Select all

void MQDriverHWService::workProc()
{
	mutex->lock();

	Logger::getInstance().debug(QString("MQDriverHWService::workProc: Will treat: [%1] messages and [%2] dpValues").arg(messages.length()).arg(dpValues.length()));

	// messages
	while (messages.length() > 0) {
		struct Message *message = messages.dequeue();
		storeToDB(message);
	}

	Logger::getInstance().debug(QString("MQDriverHWService::workProc: messages and dpValues treated"));

	mutex->unlock();
}

[CyaNn]

Here are the Logs on passive chain (ISup-G-A)

the watch dog trace

Code: Select all

FwUtils.SystemHistory	10/11/19	18:13:48	SYSTEM:  	sgWDChecker >> Watch dog: ISup.RawData.ActiveMQStatusA has expired	 
ISup.History	10/11/19	18:13:49	CRITICAL:	ServerA:ActiveMQ changed from SBY to UKN	Unknown

and an evidence that driver is writing every 20s

Code: Select all

2019-11-10 18:10:18,614 [DEBUG] MQDriverHWService::storeToDB: Message stored to db: [jmx.status.ISUP-G-A.Health:Good]
2019-11-10 18:10:38,621 [DEBUG] MQDriverHWService::storeToDB: Message stored to db: [jmx.status.ISUP-G-A.Health:Good]
2019-11-10 18:10:58,618 [DEBUG] MQDriverHWService::storeToDB: Message stored to db: [jmx.status.ISUP-G-A.Health:Good]
2019-11-10 18:11:18,625 [DEBUG] MQDriverHWService::storeToDB: Message stored to db: [jmx.status.ISUP-G-A.Health:Good]
2019-11-10 18:11:38,621 [DEBUG] MQDriverHWService::storeToDB: Message stored to db: [jmx.status.ISUP-G-A.Health:Good]
2019-11-10 18:11:58,619 [DEBUG] MQDriverHWService::storeToDB: Message stored to db: [jmx.status.ISUP-G-A.Health:Good]
2019-11-10 18:12:18,624 [DEBUG] MQDriverHWService::storeToDB: Message stored to db: [jmx.status.ISUP-G-A.Health:Good]
2019-11-10 18:12:38,622 [DEBUG] MQDriverHWService::storeToDB: Message stored to db: [jmx.status.ISUP-G-A.Health:Good]
2019-11-10 18:12:58,629 [DEBUG] MQDriverHWService::storeToDB: Message stored to db: [jmx.status.ISUP-G-A.Health:Good]
2019-11-10 18:13:18,625 [DEBUG] MQDriverHWService::storeToDB: Message stored to db: [jmx.status.ISUP-G-A.Health:Good]
2019-11-10 18:13:38,623 [DEBUG] MQDriverHWService::storeToDB: Message stored to db: [jmx.status.ISUP-G-A.Health:Good]
2019-11-10 18:13:58,629 [DEBUG] MQDriverHWService::storeToDB: Message stored to db: [jmx.status.ISUP-G-A.Health:Good]
2019-11-10 18:14:18,626 [DEBUG] MQDriverHWService::storeToDB: Message stored to db: [jmx.status.ISUP-G-A.Health:Good]
2019-11-10 18:14:38,625 [DEBUG] MQDriverHWService::storeToDB: Message stored to db: [jmx.status.ISUP-G-A.Health:Good]
2019-11-10 18:14:58,630 [DEBUG] MQDriverHWService::storeToDB: Message stored to db: [jmx.status.ISUP-G-A.Health:Good]

[CyaNn]

I've juste reproduced the bug, now I have two hypothesis :

- The driver is not able to write the point, even if it say yes !
- I face a redundancy problem, passive chain does not execute the forwardDp correctly sometimes.

For this last hypothesis, is it possible to log the redundancy trafic ?

[leoknipp]

As a first step you can activate "-snd 2" at the driver to see which data the driver sends to the Event Manager. Possibly with "-rcv 2" you can see answer messages if your dpSet() requires an answer.

Maybe the driver is sending several items in one message and therefore forwarding the value does not work.
If I remember correctly WinCC OA checks the first item in the message if it needs to be forwarded or not and then applies the result to all items in the message.

Best Regards
Leopold Knipp
Senior Support Specialist

[CyaNn]

Hello Leoknipp,

Thanks a lot for your great reply.

Maybe the driver is sending several items in one message

Yes ! With "-snd 2" parameter, I can see that messages contains several items. As MQTT is by design asynchronous, it explains perfectly why the problem appears sometime and most frequently on stressed system (with many messages from several sources).

A solution can be to filter messages on passive chain that only allow replicated one.
What do you think about that ?

[gschijndel]

Values sent by 'DrvManager::getSelfPtr()->toDp(...)' are not affected by 'forwardDp(Type)' config entries. They are simply discarded from the passive driver.
For a driver (watchdog) status use 'dpSet(...)' to set an internal driver (watchdog) datapoint element.