OPC connection issues with FANUC FASOPC

Ignition
1

Hello.

We have a large number of Fanuc CNC's, and use FASOPC to connect to these machines. We have a server running FASOPC as a service (this also is the same server which runs Ignition and SQL Server, there is not enough traffic yet to require splitting these onto separate machines).

We've been noticing that the tags we pull from FASOPC will all go to dataintegrity = 600 (in the historian, this maps to unknown quality) -- the live tags also go to unknown quality. This happens across all machines simultaneously, so it's not an issue with the connection to one machine. It happens roughly once a day, though not at a prescribed time.

FASOPC does not "notice" that it isn't running, and doesn't take automatic action to reset. It also does not record anything related to losing connectivity in its log files.

Ignition also does not notice anything strange happen. The gateway logs don't have any data related to the OPC connection.

Restarting the FASOPC service brings it back online. Right now, we have a somewhat hacky script running, which polls each machine every 5 minutes for connectivity, and if none of them respond, runs a batch file on the server which restarts FASOPC. This is not a good long term solution.

As a detailed timeline from last night:

  • At 11:33:30, the historian records all the live tags as going to dataintegrity = 600. A script which calls system.opc.getServerState on this change records "FAULTED"
  • At 11:35:01, the manual script detects the connectivity issues, and restarts the FASOPC server
  • At 11:35:16, the OpcUAConncetion logger records "Subscription watchdog timer elapsed", as well as "Subscription transfer failed". (This is due to the FASOPC server being now turned off).
  • After 11:35:22, historian logs all tags as going back to dataintegrity = 192 (good).

Does anyone have any advice to troubleshoot this? Eg, is there a way to collect even more detailed logs on the OPC connection

2

The loggers you find searching for these terms, set to DEBUG level may help:

  • OpcUaConnection
  • OpcUaSubscriptionModel
  • OpcUaSubscriptionSynchronizer

along with a Wireshark capture if you can disable security for the connection(s).

That said... this message:

is already telling me this server has basically stopped responding - that's watchdog timer's job, to detect if we stopped getting even the keep alive notifications for a subscription.

Ignition will try to recover by creating the subscriptions again, etc... but if the server has failed its way into a state where it needs a restart there's nothing you can do from Ignition.

You'll need to upload full log exports now and in the future for more help.

3

Sorry, I don't think I was clear enough on that note. I know why it is turned off, that is because we manually killed the FASOPC server using an external script. I am not sure if a restart is required to get the server responding again, only that it is sufficient to do so.

It stopped responding at 11:33:30. Our script detected this at 11:35, and told the FASOPC server to restart. Only after we told the server to restart, did we get the watchdog timer error.

Are there any dangers to uploading log files to a public forum? And any way to limit the log files to a specific period of time? (those I downloaded from the gateway seem to be for the past 2 months)

4

Only if you're printing out information you think is proprietary for some reason. In that case you'll have to work with support.

Otherwise, no, there's not any kinds of passwords or things like that in the logs.

5

Alright. I've attached the logs for the hour where we had issues. You can safely ignore the tag change script errors, those are from the script I set up to check the status of the connection.

(I used Kindling to get a text version of the logs, for just the period of time in question)

logs.txt (11.8 KB)

6

The only thing remotely relevant in there is:

2025-03-27 23:35:16:594 opc-ua-executor-13837
Subscription watchdog timer elapsed, id=946580724

2025-03-27 23:35:21:558 opc-ua-executor-13840
Subscription transfer failed, id=946580724, status=StatusCode{name=Bad_SubscriptionIdInvalid, value=0x80280000, quality=bad}

2025-03-27 23:35:21:695 opc-ua-executor-13841
ResendData for subscriptionId=2392543966 succeeded.

Hopefully you get some more usable info with those loggers on.

1 Like
7

Yep, but I already know the cause of those.

I'll set the additional loggers to debug, and hopefully capture something over the weekend.

Cheers.

8

For reference, what version of Ignition is this?

9

Ignition Platform8.1.38
OPC-UA Module 9.1.38

10

Ok thanks. Was hoping it was earlier than that; found a ticket that might have been relevant, but it was released as part of 8.1.38.

1 Like
11

I ran the loggers, however they don't seem to have anything more obvious.
For this event, my tag quality went to poor at 15:10:39, and recovered at 15:15:20.

The automatic shutdown/start back up of the FASOPC server seems to have happened at 15:15 (I'll add some logging to this script, so I can get a more accurate time estimate)

The relevant logs

2025-04-03 15:10:39:740 opc-ua-executor-16638
handleStoreLastKnownQualities()

2025-04-03 15:12:25:661 opc-ua-executor-16638
handleRemoveSubscription(subscriptionId=1466220523)

2025-04-03 15:12:25:661 opc-ua-executor-16640
Subscription watchdog timer elapsed, id=1466220523

2025-04-03 15:12:25:662 opc-ua-executor-16638
Removed subscription; id=1466220523, name=tag-group-default_default

2025-04-03 15:12:25:662 opc-ua-executor-16640
debounce: synchronize received

2025-04-03 15:12:25:913 opc-ua-executor-16638
debounce: synchronize sent

2025-04-03 15:12:25:913 opc-ua-executor-16632
handleSynchronize()

2025-04-03 15:12:25:913 opc-ua-executor-16632
Creating subscription 'tag-group-default_default' @ publishingInterval=500.0ms

2025-04-03 15:12:39:512 opc-ua-executor-16640
synchronizeSubscriptions() took 13599ms

2025-04-03 15:12:39:512 opc-ua-executor-16640
synchronizeMonitoredItems() took 0ms

2025-04-03 15:12:39:512 opc-ua-executor-16640
synchronizeSettings() took 0ms

2025-04-03 15:12:39:512 opc-ua-executor-16640
synchronized=false; next re-synchronization in 8 seconds

2025-04-03 15:12:39:512 opc-ua-executor-16640
Failed to create subscription 'tag-group-default_default': timed out waiting for acknowledge

2025-04-03 15:12:39:512 opc-ua-executor-16640
subscriptionName=tag-group-default_default, ignSubscription=com.inductiveautomation.ignition.gateway.opcua.client.connection.OpcUaSubscriptionModel$IgnitionSubscription@537daef, opcSubscription=null

2025-04-03 15:12:47:514 opc-ua-executor-16638
handleResynchronize()

2025-04-03 15:12:47:514 opc-ua-executor-16640
debounce: synchronize received

2025-04-03 15:12:47:766 opc-ua-executor-16640
debounce: synchronize sent

2025-04-03 15:12:47:766 opc-ua-executor-16638
handleSynchronize()

2025-04-03 15:12:47:766 opc-ua-executor-16638
Creating subscription 'tag-group-default_default' @ publishingInterval=500.0ms

2025-04-03 15:13:00:611 opc-ua-executor-16632
synchronizeSubscriptions() took 12845ms

2025-04-03 15:13:00:611 opc-ua-executor-16632
synchronizeMonitoredItems() took 0ms

2025-04-03 15:13:00:611 opc-ua-executor-16632
synchronizeSettings() took 0ms

2025-04-03 15:13:00:611 opc-ua-executor-16632
synchronized=false; next re-synchronization in 16 seconds

2025-04-03 15:13:00:611 opc-ua-executor-16632
Failed to create subscription 'tag-group-default_default': timed out waiting for acknowledge

2025-04-03 15:13:00:611 opc-ua-executor-16632
subscriptionName=tag-group-default_default, ignSubscription=com.inductiveautomation.ignition.gateway.opcua.client.connection.OpcUaSubscriptionModel$IgnitionSubscription@537daef, opcSubscription=null

2025-04-03 15:13:16:611 opc-ua-executor-16640
handleResynchronize()

2025-04-03 15:13:16:611 opc-ua-executor-16638
debounce: synchronize received

2025-04-03 15:13:16:862 opc-ua-executor-16638
debounce: synchronize sent

2025-04-03 15:13:16:862 opc-ua-executor-16632
handleSynchronize()

2025-04-03 15:13:16:862 opc-ua-executor-16632
Creating subscription 'tag-group-default_default' @ publishingInterval=500.0ms

2025-04-03 15:13:21:712 opc-ua-executor-16632
synchronizeSubscriptions() took 4850ms

2025-04-03 15:13:21:712 opc-ua-executor-16632
synchronizeMonitoredItems() took 0ms

2025-04-03 15:13:21:712 opc-ua-executor-16632
synchronizeSettings() took 0ms

2025-04-03 15:13:21:712 opc-ua-executor-16632
synchronized=false; next re-synchronization in 32 seconds

2025-04-03 15:13:21:712 opc-ua-executor-16632
Failed to create subscription 'tag-group-default_default': timed out waiting for acknowledge

2025-04-03 15:13:21:712 opc-ua-executor-16632
subscriptionName=tag-group-default_default, ignSubscription=com.inductiveautomation.ignition.gateway.opcua.client.connection.OpcUaSubscriptionModel$IgnitionSubscription@537daef, opcSubscription=null

2025-04-03 15:13:53:712 opc-ua-executor-16641
handleResynchronize()

2025-04-03 15:13:53:712 opc-ua-executor-16640
debounce: synchronize received

2025-04-03 15:13:53:964 opc-ua-executor-16641
debounce: synchronize sent

2025-04-03 15:13:53:964 opc-ua-executor-16640
handleSynchronize()

2025-04-03 15:13:53:964 opc-ua-executor-16640
Creating subscription 'tag-group-default_default' @ publishingInterval=500.0ms

2025-04-03 15:14:03:912 opc-ua-executor-16640
synchronizeSubscriptions() took 9948ms

2025-04-03 15:14:03:912 opc-ua-executor-16640
synchronizeMonitoredItems() took 0ms

2025-04-03 15:14:03:912 opc-ua-executor-16640
synchronizeSettings() took 0ms

2025-04-03 15:14:03:912 opc-ua-executor-16640
synchronized=false; next re-synchronization in 64 seconds

2025-04-03 15:14:03:912 opc-ua-executor-16640
Failed to create subscription 'tag-group-default_default': timed out waiting for acknowledge

2025-04-03 15:14:03:912 opc-ua-executor-16640
subscriptionName=tag-group-default_default, ignSubscription=com.inductiveautomation.ignition.gateway.opcua.client.connection.OpcUaSubscriptionModel$IgnitionSubscription@537daef, opcSubscription=null

2025-04-03 15:15:07:914 opc-ua-executor-16640
handleResynchronize()

2025-04-03 15:15:07:914 opc-ua-executor-16642
debounce: synchronize received

2025-04-03 15:15:08:165 opc-ua-executor-16638
debounce: synchronize sent

2025-04-03 15:15:08:165 opc-ua-executor-16640
handleSynchronize()

2025-04-03 15:15:08:165 opc-ua-executor-16640
Creating subscription 'tag-group-default_default' @ publishingInterval=500.0ms

2025-04-03 15:15:20:122 opc-ua-executor-16638
Subscription transfer failed, id=1466220523, status=StatusCode{name=Bad_SubscriptionIdInvalid, value=0x80280000, quality=bad}

2025-04-03 15:15:20:224 opc-ua-executor-16632
synchronizeSubscriptions() took 12059ms

2025-04-03 15:15:20:224 opc-ua-executor-16632
subscription=tag-group-default_default calculating itemsToCreate and itemsToDelete took 0ms

2025-04-03 15:15:20:224 opc-ua-executor-16632
subscription=tag-group-default_default itemsToCreate.size()=911

2025-04-03 15:15:20:225 opc-ua-executor-16632
subscription=tag-group-default_default itemsToDelete.size()=0

2025-04-03 15:15:20:226 opc-ua-executor-16632
Creating 911 items on subscription 'tag-group-default_default'...

2025-04-03 15:15:20:257 opc-ua-executor-16632
synchronizeMonitoredItems() took 33ms

2025-04-03 15:15:20:257 opc-ua-executor-16632
Setting MonitoringMode.Reporting on 911 items on subscription 'tag-group-default_default'...

2025-04-03 15:15:20:258 opc-ua-executor-16632
synchronizeSettings() took 1ms

2025-04-03 15:15:20:258 opc-ua-executor-16632
handleRemoveSubscription(subscriptionId=1466220523)

2025-04-03 15:15:20:258 opc-ua-executor-16632
Calling ResendData for subscriptionId=3728193898

2025-04-03 15:15:20:258 opc-ua-executor-16638
debounce: synchronize received

2025-04-03 15:15:20:258 opc-ua-executor-16638
handleClearLastKnownQualities(subscriptionId=3728193898)

2025-04-03 15:15:20:258 opc-ua-executor-16638
ResendData for subscriptionId=3728193898 succeeded.

2025-04-03 15:15:20:510 opc-ua-executor-16638
debounce: synchronize sent

2025-04-03 15:15:20:510 opc-ua-executor-16640
handleSynchronize()

2025-04-03 15:15:20:510 opc-ua-executor-16640
synchronizeSubscriptions() took 0ms

2025-04-03 15:15:20:510 opc-ua-executor-16640
subscription=tag-group-default_default calculating itemsToCreate and itemsToDelete took 0ms

2025-04-03 15:15:20:510 opc-ua-executor-16640
subscription=tag-group-default_default itemsToCreate.size()=0

2025-04-03 15:15:20:510 opc-ua-executor-16640
subscription=tag-group-default_default itemsToDelete.size()=0

2025-04-03 15:15:20:510 opc-ua-executor-16640
synchronizeMonitoredItems() took 0ms

2025-04-03 15:15:20:510 opc-ua-executor-16640
synchronizeSettings() took 0ms

12

It looks like this server has just stopped responding at some point.

The opening log message there about storing last know qualities happens in response to an onSessionInactive callback, which happens either when we lost the connection or when the keep alive has failed enough times that we initiate a reconnect.

There's not much to do on the Ignition side besides maybe play with the keep alive settings to see if the server eventually recovers.

If you want objective proof to go to FANUC with then you'll have to work with support and provide unredacted logs and a Wireshark capture.

1 Like
13

Sounds good.

I'd reached out to FANUC a few months ago, but they looked through the FASOPC logs, and weren't able to find anything interesting there either.

Looks like I'll need to bang my head into this problem a little more.

Thanks for the help.

14

That's the problem with logs, from either side.

Wireshark will tell you the truth :slight_smile:

1 Like