Tests for handling unknown/stale ADS notifications failing with AdsRouterConsole

[crishoj]

Running test/TC3/ads-client.test.js against my PC-based TC3 4024.62, all tests are passing, except the tests related to handling unknown/stale ADS notifications.

The problem appears to be connecting the auxiliary client:

connectToTarget(): Connection failed - failed to set PLC connection. If target is not PLC runtime, use setting "rawClient". If system is in config mode or there is no PLC software yet, you might want to use setting "allowHalfOpen"
ClientError: readPlcUploadInfo(): Reading upload info failed
ClientError: sendAdsCommand(): Response with ADS error received (error 1808 - Symbol not found)

I wonder what prevents the second client from connecting. I am using connection setup 2, with ads-client + AdsRouterConsole on my Mac, connecting to TC on a Windows PC.

Any idea what's preventing the second client from connecting?

[jisotalo]

Hmm, this is odd. Are the tests under controlling TwinCAT system service passing? So is the only issue the client under stale notification handle tests.

ads-client/test/TC3/ads-client.test.js

Line 3595 in 51702a2

describe('controlling TwinCAT system service', () => {

Could you also set the debugging level to 2 and paste the logs.

[jisotalo]

@crishoj I just got the same issue and the reason was that Autostart boot project was not checked.

Can you check that?

[crishoj]

Just made sure Autostart boot project is checked:

Still getting two failing tests:

And the test hangs at the end with this message (from jest option --detectOpenHandles):

[crishoj]

Could you also set the debugging level to 2 and paste the logs.

In the following, I removed most other tests in order to reduce the log volume.

Debug output

~/C/ads-client (v2-dev|✚1) $ DEBUG='ads-client,ads-client:details' AMS_NET_ID=100.70.46.31.1.1 LOCAL_AMS_NET_ID=100.117.55.75.1.1 jest --runInBand TC3/ads-client.test.js
  ads-client connectToTarget(): Connecting to target at 127.0.0.1:48898 (reconnecting: false) +0ms
  ads-client connectToTarget(): Socket connection established to 127.0.0.1:48898 +0ms
  ads-client registerAdsPort(): Registering an ADS port from target router (127.0.0.1:48898) +1ms
  ads-client:details IO out ------> 8 bytes +0ms
  ads-client:details IO in  <------ 14 bytes from 127.0.0.1 +0ms
  ads-client:details parseAmsTcpHeader(): Starting to parse AMS/TCP header +0ms
  ads-client:details parseAmsTcpHeader(): AMS/TCP header parsed: { command: 4096, commandStr: 'AMS_TCP_PORT_CONNECT', length: 8, data: <Buffer 64 75 37 4b 01 01 1a 80> } +0ms
  ads-client:details parseAmsHeader(): Starting to parse AMS header +0ms
  ads-client:details parseAmsHeader(): No AMS header found +0ms
  ads-client:details parseAdsResponse(): Starting to parse ADS data +1ms
  ads-client:details parseAdsData(): Packet has no ADS data +0ms
  ads-client:details onAmsTcpPacketReceived(): AMS packet received with command 4096 +0ms
  ads-client registerAdsPort(): ADS port registered, assigned AMS address is 100.117.55.75.1.1:32794 +1ms
  ads-client connectToTarget(): ADS port registered. Our AMS address is 100.117.55.75.1.1:32794 +0ms
  ads-client readTcSystemState(): Reading TwinCAT system state +0ms
  ads-client:details sendAdsCommand(): Sending an ads command ReadState (0 bytes): { amsTcp: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD' }, ams: { targetAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 10000 }, sourceAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32794 }, adsCommand: 4, adsCommandStr: 'ReadState', stateFlags: 4, stateFlagsStr: 'AdsCommand, Tcp, Request', dataLength: 0, errorCode: 0, invokeId: 0 }, ads: { payload: undefined } } +0ms
  ads-client:details createAmsHeader(): AMS header created (32 bytes) +0ms
  ads-client:details createAmsTcpHeader(): AMS/TCP header created (6 bytes) +0ms
  ads-client:details createAmsTcpRequest(): AMS/TCP request created (38 bytes) +0ms
  ads-client:details IO out ------> 38 bytes +0ms
  ads-client:details IO in  <------ 46 bytes from 127.0.0.1 +18ms
  ads-client:details parseAmsTcpHeader(): Starting to parse AMS/TCP header +0ms
  ads-client:details parseAmsTcpHeader(): AMS/TCP header parsed: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD', length: 40 } +0ms
  ads-client:details parseAmsHeader(): Starting to parse AMS header +0ms
  ads-client:details parseAmsHeader(): AMS header parsed: { targetAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32794 }, sourceAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 10000 }, adsCommand: 4, adsCommandStr: 'ReadState', stateFlags: 5, stateFlagsStr: 'Response, AdsCommand, Tcp', dataLength: 8, errorCode: 0, invokeId: 0, error: false, errorStr: '' } +0ms
  ads-client:details parseAdsResponse(): Starting to parse ADS data +0ms
  ads-client:details parseAdsResponse(): ADS data parsed: { errorCode: 0, payload: { adsState: 5, adsStateStr: 'Run', deviceState: 1 } } +0ms
  ads-client:details onAmsTcpPacketReceived(): AMS packet received with command 0 +0ms
  ads-client:details onAdsCommandReceived(): ADS command received (command: 4) +0ms
  ads-client:details sendAdsCommand(): Response received for command "ReadState" with invokeId 0 +1ms
  ads-client readTcSystemState(): TwinCAT system state read successfully. State is { adsState: 5, adsStateStr: 'Run', deviceState: 1 } +19ms
  ads-client:details addSubscription(): Subscribing { target: { indexGroup: 61696, indexOffset: 0, size: 4 }, callback: [Function: bound onPlcRuntimeStateChanged], cycleTime: 0 } (internal: true) +0ms
  ads-client:details sendAdsCommand(): Sending an ads command AddNotification (40 bytes): { amsTcp: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD' }, ams: { targetAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 851 }, sourceAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32794 }, adsCommand: 6, adsCommandStr: 'AddNotification', stateFlags: 4, stateFlagsStr: 'AdsCommand, Tcp, Request', dataLength: 40, errorCode: 0, invokeId: 1 }, ads: { payload: <Buffer 00 f1 00 00 00 00 00 00 04 00 00 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00> } } +0ms
  ads-client:details createAmsHeader(): AMS header created (32 bytes) +0ms
  ads-client:details createAmsTcpHeader(): AMS/TCP header created (6 bytes) +0ms
  ads-client:details createAmsTcpRequest(): AMS/TCP request created (78 bytes) +0ms
  ads-client:details IO out ------> 78 bytes +0ms
  ads-client:details IO in  <------ 46 bytes from 127.0.0.1 +16ms
  ads-client:details parseAmsTcpHeader(): Starting to parse AMS/TCP header +0ms
  ads-client:details parseAmsTcpHeader(): AMS/TCP header parsed: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD', length: 40 } +0ms
  ads-client:details parseAmsHeader(): Starting to parse AMS header +0ms
  ads-client:details parseAmsHeader(): AMS header parsed: { targetAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32794 }, sourceAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 851 }, adsCommand: 6, adsCommandStr: 'AddNotification', stateFlags: 5, stateFlagsStr: 'Response, AdsCommand, Tcp', dataLength: 8, errorCode: 0, invokeId: 1, error: false, errorStr: '' } +0ms
  ads-client:details parseAdsResponse(): Starting to parse ADS data +0ms
  ads-client:details parseAdsResponse(): ADS data parsed: { errorCode: 0, payload: { notificationHandle: 37 } } +0ms
  ads-client:details onAmsTcpPacketReceived(): AMS packet received with command 0 +0ms
  ads-client:details onAdsCommandReceived(): ADS command received (command: 6) +0ms
  ads-client:details sendAdsCommand(): Response received for command "AddNotification" with invokeId 1 +0ms
  ads-client:details addSubscription(): Subscribed to { indexGroup: 61696, indexOffset: 0, size: 4 } +0ms
  ads-client readDeviceInfo(): Reading device info +16ms
  ads-client:details sendAdsCommand(): Sending an ads command ReadDeviceInfo (0 bytes): { amsTcp: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD' }, ams: { targetAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 851 }, sourceAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32794 }, adsCommand: 1, adsCommandStr: 'ReadDeviceInfo', stateFlags: 4, stateFlagsStr: 'AdsCommand, Tcp, Request', dataLength: 0, errorCode: 0, invokeId: 2 }, ads: { payload: undefined } } +0ms
  ads-client:details createAmsHeader(): AMS header created (32 bytes) +0ms
  ads-client:details createAmsTcpHeader(): AMS/TCP header created (6 bytes) +0ms
  ads-client:details createAmsTcpRequest(): AMS/TCP request created (38 bytes) +0ms
  ads-client:details IO out ------> 38 bytes +0ms
  ads-client:details IO in  <------ 70 bytes from 127.0.0.1 +3ms
  ads-client:details parseAmsTcpHeader(): Starting to parse AMS/TCP header +0ms
  ads-client:details parseAmsTcpHeader(): AMS/TCP header parsed: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD', length: 64 } +0ms
  ads-client:details parseAmsHeader(): Starting to parse AMS header +0ms
  ads-client:details parseAmsHeader(): AMS header parsed: { targetAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32794 }, sourceAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 851 }, adsCommand: 8, adsCommandStr: 'Notification', stateFlags: 4, stateFlagsStr: 'AdsCommand, Tcp, Request', dataLength: 32, errorCode: 0, invokeId: 0, error: false, errorStr: '' } +0ms
  ads-client:details parseAdsResponse(): Starting to parse ADS data +0ms
  ads-client:details parseAdsResponse(): ADS data parsed: { payload: { length: 28, stampCount: 1, stamps: [ [Object] ] } } +0ms
  ads-client:details onAmsTcpPacketReceived(): AMS packet received with command 0 +0ms
  ads-client:details onAdsCommandReceived(): ADS command received (command: 8) +0ms
  ads-client onAdsCommandReceived(): Notification received from 100.70.46.31.1.1:851 for handle 37 ({ indexGroup: 61696, indexOffset: 0, size: 4 }) +3ms
  ads-client handlePlcRuntimeStateChange(): PLC runtime state (adsState) changed from UNKNOWN to Run +0ms
  ads-client handlePlcRuntimeStateChange(): PLC runtime state (deviceState) changed from UNKNOWN to 0 +0ms
  ads-client:details IO in  <------ 62 bytes from 127.0.0.1 +14ms
  ads-client:details parseAmsTcpHeader(): Starting to parse AMS/TCP header +0ms
  ads-client:details parseAmsTcpHeader(): AMS/TCP header parsed: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD', length: 56 } +0ms
  ads-client:details parseAmsHeader(): Starting to parse AMS header +0ms
  ads-client:details parseAmsHeader(): AMS header parsed: { targetAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32794 }, sourceAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 851 }, adsCommand: 1, adsCommandStr: 'ReadDeviceInfo', stateFlags: 5, stateFlagsStr: 'Response, AdsCommand, Tcp', dataLength: 24, errorCode: 0, invokeId: 2, error: false, errorStr: '' } +0ms
  ads-client:details parseAdsResponse(): Starting to parse ADS data +0ms
  ads-client:details parseAdsResponse(): ADS data parsed: { errorCode: 0, payload: { majorVersion: 3, minorVersion: 1, versionBuild: 1966, deviceName: 'Plc30 App' } } +3ms
  ads-client:details onAmsTcpPacketReceived(): AMS packet received with command 0 +0ms
  ads-client:details onAdsCommandReceived(): ADS command received (command: 1) +0ms
  ads-client:details sendAdsCommand(): Response received for command "ReadDeviceInfo" with invokeId 2 +0ms
  ads-client readDeviceInfo(): Device info read successfully. Device is { majorVersion: 3, minorVersion: 1, versionBuild: 1966, deviceName: 'Plc30 App' } +17ms
  ads-client readPlcUploadInfo(): Reading upload info +0ms
  ads-client sendAdsCommandWithFallback(): Sending ADS command with a fallback +0ms
  ads-client:details sendAdsCommand(): Sending an ads command Read (12 bytes): { amsTcp: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD' }, ams: { targetAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 851 }, sourceAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32794 }, adsCommand: 2, adsCommandStr: 'Read', stateFlags: 4, stateFlagsStr: 'AdsCommand, Tcp, Request', dataLength: 12, errorCode: 0, invokeId: 3 }, ads: { payload: <Buffer 0f f0 00 00 00 00 00 00 40 00 00 00> } } +1ms
  ads-client:details createAmsHeader(): AMS header created (32 bytes) +0ms
  ads-client:details createAmsTcpHeader(): AMS/TCP header created (6 bytes) +0ms
  ads-client:details createAmsTcpRequest(): AMS/TCP request created (50 bytes) +0ms
  ads-client:details IO out ------> 50 bytes +0ms
  ads-client:details IO in  <------ 110 bytes from 127.0.0.1 +18ms
  ads-client:details parseAmsTcpHeader(): Starting to parse AMS/TCP header +0ms
  ads-client:details parseAmsTcpHeader(): AMS/TCP header parsed: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD', length: 104 } +0ms
  ads-client:details parseAmsHeader(): Starting to parse AMS header +0ms
  ads-client:details parseAmsHeader(): AMS header parsed: { targetAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32794 }, sourceAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 851 }, adsCommand: 2, adsCommandStr: 'Read', stateFlags: 5, stateFlagsStr: 'Response, AdsCommand, Tcp', dataLength: 72, errorCode: 0, invokeId: 3, error: false, errorStr: '' } +0ms
  ads-client:details parseAdsResponse(): Starting to parse ADS data +0ms
  ads-client:details parseAdsResponse(): ADS data parsed: { errorCode: 0, length: 64, payload: <Buffer af 00 00 00 a8 48 00 00 a0 00 00 00 a8 d7 00 00 d0 07 00 00 00 00 00 00 00 00 00 00 e9 fd 00 00 03 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ... 14 more bytes> } +0ms
  ads-client:details onAmsTcpPacketReceived(): AMS packet received with command 0 +0ms
  ads-client:details onAdsCommandReceived(): ADS command received (command: 2) +0ms
  ads-client:details sendAdsCommand(): Response received for command "Read" with invokeId 3 +0ms
  ads-client readPlcUploadInfo(): Upload info read - fallback was needed: false +19ms
  ads-client readPlcUploadInfo(): Upload info read and parsed for 100.70.46.31.1.1:851 +0ms
  ads-client readPlcSymbolVersion(): Reading PLC runtime symbol version +0ms
  ads-client readRaw(): Reading raw data ({"indexGroup":61448,"indexOffset":0,"size":1}) +0ms
  ads-client:details sendAdsCommand(): Sending an ads command Read (12 bytes): { amsTcp: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD' }, ams: { targetAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 851 }, sourceAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32794 }, adsCommand: 2, adsCommandStr: 'Read', stateFlags: 4, stateFlagsStr: 'AdsCommand, Tcp, Request', dataLength: 12, errorCode: 0, invokeId: 4 }, ads: { payload: <Buffer 08 f0 00 00 00 00 00 00 01 00 00 00> } } +0ms
  ads-client:details createAmsHeader(): AMS header created (32 bytes) +0ms
  ads-client:details createAmsTcpHeader(): AMS/TCP header created (6 bytes) +0ms
  ads-client:details createAmsTcpRequest(): AMS/TCP request created (50 bytes) +0ms
  ads-client:details IO out ------> 50 bytes +0ms
  ads-client:details IO in  <------ 47 bytes from 127.0.0.1 +18ms
  ads-client:details parseAmsTcpHeader(): Starting to parse AMS/TCP header +0ms
  ads-client:details parseAmsTcpHeader(): AMS/TCP header parsed: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD', length: 41 } +0ms
  ads-client:details parseAmsHeader(): Starting to parse AMS header +0ms
  ads-client:details parseAmsHeader(): AMS header parsed: { targetAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32794 }, sourceAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 851 }, adsCommand: 2, adsCommandStr: 'Read', stateFlags: 5, stateFlagsStr: 'Response, AdsCommand, Tcp', dataLength: 9, errorCode: 0, invokeId: 4, error: false, errorStr: '' } +0ms
  ads-client:details parseAdsResponse(): Starting to parse ADS data +0ms
  ads-client:details parseAdsResponse(): ADS data parsed: { errorCode: 0, length: 1, payload: <Buffer 37> } +0ms
  ads-client:details onAmsTcpPacketReceived(): AMS packet received with command 0 +0ms
  ads-client:details onAdsCommandReceived(): ADS command received (command: 2) +0ms
  ads-client:details sendAdsCommand(): Response received for command "Read" with invokeId 4 +0ms
  ads-client readRaw(): Reading raw data ({"indexGroup":61448,"indexOffset":0,"size":1}) done (1 bytes) +18ms
  ads-client readPlcSymbolVersion(): PLC runtime symbol version is now 55 +0ms
  ads-client onPlcSymbolVersionChanged(): PLC runtime symbol version is now 55 +0ms
  ads-client:details addSubscription(): Subscribing { target: { indexGroup: 61448, indexOffset: 0, size: 1 }, callback: [Function: bound onPlcSymbolVersionChanged] AsyncFunction, cycleTime: 0 } (internal: true) +0ms
  ads-client:details sendAdsCommand(): Sending an ads command AddNotification (40 bytes): { amsTcp: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD' }, ams: { targetAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 851 }, sourceAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32794 }, adsCommand: 6, adsCommandStr: 'AddNotification', stateFlags: 4, stateFlagsStr: 'AdsCommand, Tcp, Request', dataLength: 40, errorCode: 0, invokeId: 5 }, ads: { payload: <Buffer 08 f0 00 00 00 00 00 00 01 00 00 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00> } } +0ms
  ads-client:details createAmsHeader(): AMS header created (32 bytes) +0ms
  ads-client:details createAmsTcpHeader(): AMS/TCP header created (6 bytes) +0ms
  ads-client:details createAmsTcpRequest(): AMS/TCP request created (78 bytes) +0ms
  ads-client:details IO out ------> 78 bytes +0ms
  ads-client:details IO in  <------ 46 bytes from 127.0.0.1 +18ms
  ads-client:details parseAmsTcpHeader(): Starting to parse AMS/TCP header +0ms
  ads-client:details parseAmsTcpHeader(): AMS/TCP header parsed: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD', length: 40 } +0ms
  ads-client:details parseAmsHeader(): Starting to parse AMS header +0ms
  ads-client:details parseAmsHeader(): AMS header parsed: { targetAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32794 }, sourceAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 851 }, adsCommand: 6, adsCommandStr: 'AddNotification', stateFlags: 5, stateFlagsStr: 'Response, AdsCommand, Tcp', dataLength: 8, errorCode: 0, invokeId: 5, error: false, errorStr: '' } +0ms
  ads-client:details parseAdsResponse(): Starting to parse ADS data +0ms
  ads-client:details parseAdsResponse(): ADS data parsed: { errorCode: 0, payload: { notificationHandle: 38 } } +0ms
  ads-client:details onAmsTcpPacketReceived(): AMS packet received with command 0 +0ms
  ads-client:details onAdsCommandReceived(): ADS command received (command: 6) +0ms
  ads-client:details sendAdsCommand(): Response received for command "AddNotification" with invokeId 5 +0ms
  ads-client:details addSubscription(): Subscribed to { indexGroup: 61448, indexOffset: 0, size: 1 } +0ms
  ads-client resetPlc(): Resetting PLC runtime at 100.70.46.31.1.1:851 +20ms
  ads-client readPlcRuntimeState(): Reading PLC runtime state +0ms
  ads-client:details sendAdsCommand(): Sending an ads command ReadState (0 bytes): { amsTcp: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD' }, ams: { targetAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 851 }, sourceAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32794 }, adsCommand: 4, adsCommandStr: 'ReadState', stateFlags: 4, stateFlagsStr: 'AdsCommand, Tcp, Request', dataLength: 0, errorCode: 0, invokeId: 6 }, ads: { payload: undefined } } +2ms
  ads-client:details createAmsHeader(): AMS header created (32 bytes) +0ms
  ads-client:details createAmsTcpHeader(): AMS/TCP header created (6 bytes) +0ms
  ads-client:details createAmsTcpRequest(): AMS/TCP request created (38 bytes) +0ms
  ads-client:details IO out ------> 38 bytes +0ms
  ads-client:details IO in  <------ 67 bytes from 127.0.0.1 +5ms
  ads-client:details parseAmsTcpHeader(): Starting to parse AMS/TCP header +1ms
  ads-client:details parseAmsTcpHeader(): AMS/TCP header parsed: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD', length: 61 } +0ms
  ads-client:details parseAmsHeader(): Starting to parse AMS header +0ms
  ads-client:details parseAmsHeader(): AMS header parsed: { targetAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32794 }, sourceAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 851 }, adsCommand: 8, adsCommandStr: 'Notification', stateFlags: 4, stateFlagsStr: 'AdsCommand, Tcp, Request', dataLength: 29, errorCode: 0, invokeId: 0, error: false, errorStr: '' } +0ms
  ads-client:details parseAdsResponse(): Starting to parse ADS data +0ms
  ads-client:details parseAdsResponse(): ADS data parsed: { payload: { length: 25, stampCount: 1, stamps: [ [Object] ] } } +0ms
  ads-client:details onAmsTcpPacketReceived(): AMS packet received with command 0 +0ms
  ads-client:details onAdsCommandReceived(): ADS command received (command: 8) +0ms
  ads-client onAdsCommandReceived(): Notification received from 100.70.46.31.1.1:851 for handle 38 ({ indexGroup: 61448, indexOffset: 0, size: 1 }) +6ms
  ads-client onPlcSymbolVersionChanged(): PLC runtime symbol version received (not changed). Version is now 55 +0ms
  ads-client:details IO in  <------ 46 bytes from 127.0.0.1 +11ms
  ads-client:details parseAmsTcpHeader(): Starting to parse AMS/TCP header +0ms
  ads-client:details parseAmsTcpHeader(): AMS/TCP header parsed: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD', length: 40 } +0ms
  ads-client:details parseAmsHeader(): Starting to parse AMS header +0ms
  ads-client:details parseAmsHeader(): AMS header parsed: { targetAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32794 }, sourceAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 851 }, adsCommand: 4, adsCommandStr: 'ReadState', stateFlags: 5, stateFlagsStr: 'Response, AdsCommand, Tcp', dataLength: 8, errorCode: 0, invokeId: 6, error: false, errorStr: '' } +0ms
  ads-client:details parseAdsResponse(): Starting to parse ADS data +0ms
  ads-client:details parseAdsResponse(): ADS data parsed: { errorCode: 0, payload: { adsState: 5, adsStateStr: 'Run', deviceState: 0 } } +0ms
  ads-client:details onAmsTcpPacketReceived(): AMS packet received with command 0 +0ms
  ads-client:details onAdsCommandReceived(): ADS command received (command: 4) +0ms
  ads-client:details sendAdsCommand(): Response received for command "ReadState" with invokeId 6 +0ms
  ads-client readPlcRuntimeState(): Runtime state read successfully. State is { adsState: 5, adsStateStr: 'Run', deviceState: 0 } +11ms
  ads-client writeControl(): Sending an ADS Write Control command (adsState: 2, deviceState: 0, data: 0 bytes) to 100.70.46.31.1.1:851 +0ms
  ads-client:details sendAdsCommand(): Sending an ads command WriteControl (8 bytes): { amsTcp: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD' }, ams: { targetAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 851 }, sourceAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32794 }, adsCommand: 5, adsCommandStr: 'WriteControl', stateFlags: 4, stateFlagsStr: 'AdsCommand, Tcp, Request', dataLength: 8, errorCode: 0, invokeId: 7 }, ads: { payload: <Buffer 02 00 00 00 00 00 00 00> } } +0ms
  ads-client:details createAmsHeader(): AMS header created (32 bytes) +0ms
  ads-client:details createAmsTcpHeader(): AMS/TCP header created (6 bytes) +0ms
  ads-client:details createAmsTcpRequest(): AMS/TCP request created (46 bytes) +0ms
  ads-client:details IO out ------> 46 bytes +0ms
  ads-client:details IO in  <------ 42 bytes from 127.0.0.1 +18ms
  ads-client:details parseAmsTcpHeader(): Starting to parse AMS/TCP header +0ms
  ads-client:details parseAmsTcpHeader(): AMS/TCP header parsed: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD', length: 36 } +0ms
  ads-client:details parseAmsHeader(): Starting to parse AMS header +0ms
  ads-client:details parseAmsHeader(): AMS header parsed: { targetAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32794 }, sourceAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 851 }, adsCommand: 5, adsCommandStr: 'WriteControl', stateFlags: 5, stateFlagsStr: 'Response, AdsCommand, Tcp', dataLength: 4, errorCode: 0, invokeId: 7, error: false, errorStr: '' } +0ms
  ads-client:details parseAdsResponse(): Starting to parse ADS data +0ms
  ads-client:details parseAdsResponse(): ADS data parsed: { errorCode: 0 } +0ms
  ads-client:details onAmsTcpPacketReceived(): AMS packet received with command 0 +0ms
  ads-client:details onAdsCommandReceived(): ADS command received (command: 5) +0ms
  ads-client:details sendAdsCommand(): Response received for command "WriteControl" with invokeId 7 +0ms
  ads-client writeControl(): Write control command sent to 100.70.46.31.1.1:851 +18ms
  ads-client resetPlc(): PLC runtime reset at 100.70.46.31.1.1:851 +0ms
  ads-client readPlcRuntimeState(): Reading PLC runtime state +0ms
  ads-client:details sendAdsCommand(): Sending an ads command ReadState (0 bytes): { amsTcp: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD' }, ams: { targetAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 851 }, sourceAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32794 }, adsCommand: 4, adsCommandStr: 'ReadState', stateFlags: 4, stateFlagsStr: 'AdsCommand, Tcp, Request', dataLength: 0, errorCode: 0, invokeId: 8 }, ads: { payload: undefined } } +0ms
  ads-client:details createAmsHeader(): AMS header created (32 bytes) +0ms
  ads-client:details createAmsTcpHeader(): AMS/TCP header created (6 bytes) +0ms
  ads-client:details createAmsTcpRequest(): AMS/TCP request created (38 bytes) +0ms
  ads-client:details IO out ------> 38 bytes +0ms
  ads-client:details IO in  <------ 70 bytes from 127.0.0.1 +11ms
  ads-client:details parseAmsTcpHeader(): Starting to parse AMS/TCP header +0ms
  ads-client:details parseAmsTcpHeader(): AMS/TCP header parsed: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD', length: 64 } +0ms
  ads-client:details parseAmsHeader(): Starting to parse AMS header +0ms
  ads-client:details parseAmsHeader(): AMS header parsed: { targetAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32794 }, sourceAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 851 }, adsCommand: 8, adsCommandStr: 'Notification', stateFlags: 4, stateFlagsStr: 'AdsCommand, Tcp, Request', dataLength: 32, errorCode: 0, invokeId: 0, error: false, errorStr: '' } +0ms
  ads-client:details parseAdsResponse(): Starting to parse ADS data +0ms
  ads-client:details parseAdsResponse(): ADS data parsed: { payload: { length: 28, stampCount: 1, stamps: [ [Object] ] } } +0ms
  ads-client:details onAmsTcpPacketReceived(): AMS packet received with command 0 +0ms
  ads-client:details onAdsCommandReceived(): ADS command received (command: 8) +0ms
  ads-client onAdsCommandReceived(): Notification received from 100.70.46.31.1.1:851 for handle 37 ({ indexGroup: 61696, indexOffset: 0, size: 4 }) +11ms
  ads-client handlePlcRuntimeStateChange(): PLC runtime state (adsState) changed from Run to Stop +0ms
  ads-client:details IO in  <------ 46 bytes from 127.0.0.1 +6ms
  ads-client:details parseAmsTcpHeader(): Starting to parse AMS/TCP header +0ms
  ads-client:details parseAmsTcpHeader(): AMS/TCP header parsed: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD', length: 40 } +0ms
  ads-client:details parseAmsHeader(): Starting to parse AMS header +0ms
  ads-client:details parseAmsHeader(): AMS header parsed: { targetAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32794 }, sourceAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 851 }, adsCommand: 4, adsCommandStr: 'ReadState', stateFlags: 5, stateFlagsStr: 'Response, AdsCommand, Tcp', dataLength: 8, errorCode: 0, invokeId: 8, error: false, errorStr: '' } +0ms
  ads-client:details parseAdsResponse(): Starting to parse ADS data +0ms
  ads-client:details parseAdsResponse(): ADS data parsed: { errorCode: 0, payload: { adsState: 6, adsStateStr: 'Stop', deviceState: 0 } } +0ms
  ads-client:details onAmsTcpPacketReceived(): AMS packet received with command 0 +0ms
  ads-client:details onAdsCommandReceived(): ADS command received (command: 4) +0ms
  ads-client:details sendAdsCommand(): Response received for command "ReadState" with invokeId 8 +0ms
  ads-client readPlcRuntimeState(): Runtime state read successfully. State is { adsState: 6, adsStateStr: 'Stop', deviceState: 0 } +6ms
  ads-client startPlc(): Starting PLC runtime at 100.70.46.31.1.1:851 +503ms
  ads-client readPlcRuntimeState(): Reading PLC runtime state +1ms
  ads-client:details sendAdsCommand(): Sending an ads command ReadState (0 bytes): { amsTcp: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD' }, ams: { targetAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 851 }, sourceAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32794 }, adsCommand: 4, adsCommandStr: 'ReadState', stateFlags: 4, stateFlagsStr: 'AdsCommand, Tcp, Request', dataLength: 0, errorCode: 0, invokeId: 9 }, ads: { payload: undefined } } +504ms
  ads-client:details createAmsHeader(): AMS header created (32 bytes) +0ms
  ads-client:details createAmsTcpHeader(): AMS/TCP header created (6 bytes) +0ms
  ads-client:details createAmsTcpRequest(): AMS/TCP request created (38 bytes) +0ms
  ads-client:details IO out ------> 38 bytes +0ms
  ads-client:details IO in  <------ 46 bytes from 127.0.0.1 +21ms
  ads-client:details parseAmsTcpHeader(): Starting to parse AMS/TCP header +0ms
  ads-client:details parseAmsTcpHeader(): AMS/TCP header parsed: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD', length: 40 } +0ms
  ads-client:details parseAmsHeader(): Starting to parse AMS header +0ms
  ads-client:details parseAmsHeader(): AMS header parsed: { targetAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32794 }, sourceAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 851 }, adsCommand: 4, adsCommandStr: 'ReadState', stateFlags: 5, stateFlagsStr: 'Response, AdsCommand, Tcp', dataLength: 8, errorCode: 0, invokeId: 9, error: false, errorStr: '' } +0ms
  ads-client:details parseAdsResponse(): Starting to parse ADS data +1ms
  ads-client:details parseAdsResponse(): ADS data parsed: { errorCode: 0, payload: { adsState: 6, adsStateStr: 'Stop', deviceState: 0 } } +0ms
  ads-client:details onAmsTcpPacketReceived(): AMS packet received with command 0 +0ms
  ads-client:details onAdsCommandReceived(): ADS command received (command: 4) +0ms
  ads-client:details sendAdsCommand(): Response received for command "ReadState" with invokeId 9 +0ms
  ads-client readPlcRuntimeState(): Runtime state read successfully. State is { adsState: 6, adsStateStr: 'Stop', deviceState: 0 } +22ms
  ads-client writeControl(): Sending an ADS Write Control command (adsState: 5, deviceState: 0, data: 0 bytes) to 100.70.46.31.1.1:851 +0ms
  ads-client:details sendAdsCommand(): Sending an ads command WriteControl (8 bytes): { amsTcp: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD' }, ams: { targetAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 851 }, sourceAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32794 }, adsCommand: 5, adsCommandStr: 'WriteControl', stateFlags: 4, stateFlagsStr: 'AdsCommand, Tcp, Request', dataLength: 8, errorCode: 0, invokeId: 10 }, ads: { payload: <Buffer 05 00 00 00 00 00 00 00> } } +0ms
  ads-client:details createAmsHeader(): AMS header created (32 bytes) +1ms
  ads-client:details createAmsTcpHeader(): AMS/TCP header created (6 bytes) +0ms
  ads-client:details createAmsTcpRequest(): AMS/TCP request created (46 bytes) +0ms
  ads-client:details IO out ------> 46 bytes +0ms
  ads-client:details IO in  <------ 42 bytes from 127.0.0.1 +17ms
  ads-client:details parseAmsTcpHeader(): Starting to parse AMS/TCP header +0ms
  ads-client:details parseAmsTcpHeader(): AMS/TCP header parsed: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD', length: 36 } +0ms
  ads-client:details parseAmsHeader(): Starting to parse AMS header +0ms
  ads-client:details parseAmsHeader(): AMS header parsed: { targetAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32794 }, sourceAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 851 }, adsCommand: 5, adsCommandStr: 'WriteControl', stateFlags: 5, stateFlagsStr: 'Response, AdsCommand, Tcp', dataLength: 4, errorCode: 0, invokeId: 10, error: false, errorStr: '' } +0ms
  ads-client:details parseAdsResponse(): Starting to parse ADS data +0ms
  ads-client:details parseAdsResponse(): ADS data parsed: { errorCode: 0 } +0ms
  ads-client:details onAmsTcpPacketReceived(): AMS packet received with command 0 +0ms
  ads-client:details onAdsCommandReceived(): ADS command received (command: 5) +0ms
  ads-client:details sendAdsCommand(): Response received for command "WriteControl" with invokeId 10 +0ms
  ads-client writeControl(): Write control command sent to 100.70.46.31.1.1:851 +18ms
  ads-client startPlc(): PLC runtime started at 100.70.46.31.1.1:851 +0ms
  ads-client readPlcRuntimeState(): Reading PLC runtime state +0ms
  ads-client:details sendAdsCommand(): Sending an ads command ReadState (0 bytes): { amsTcp: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD' }, ams: { targetAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 851 }, sourceAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32794 }, adsCommand: 4, adsCommandStr: 'ReadState', stateFlags: 4, stateFlagsStr: 'AdsCommand, Tcp, Request', dataLength: 0, errorCode: 0, invokeId: 11 }, ads: { payload: undefined } } +0ms
  ads-client:details createAmsHeader(): AMS header created (32 bytes) +0ms
  ads-client:details createAmsTcpHeader(): AMS/TCP header created (6 bytes) +0ms
  ads-client:details createAmsTcpRequest(): AMS/TCP request created (38 bytes) +1ms
  ads-client:details IO out ------> 38 bytes +0ms
  ads-client:details IO in  <------ 46 bytes from 127.0.0.1 +16ms
  ads-client:details parseAmsTcpHeader(): Starting to parse AMS/TCP header +0ms
  ads-client:details parseAmsTcpHeader(): AMS/TCP header parsed: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD', length: 40 } +0ms
  ads-client:details parseAmsHeader(): Starting to parse AMS header +0ms
  ads-client:details parseAmsHeader(): AMS header parsed: { targetAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32794 }, sourceAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 851 }, adsCommand: 4, adsCommandStr: 'ReadState', stateFlags: 5, stateFlagsStr: 'Response, AdsCommand, Tcp', dataLength: 8, errorCode: 0, invokeId: 11, error: false, errorStr: '' } +0ms
  ads-client:details parseAdsResponse(): Starting to parse ADS data +1ms
  ads-client:details parseAdsResponse(): ADS data parsed: { errorCode: 0, payload: { adsState: 5, adsStateStr: 'Run', deviceState: 0 } } +0ms
  ads-client:details onAmsTcpPacketReceived(): AMS packet received with command 0 +0ms
  ads-client:details onAdsCommandReceived(): ADS command received (command: 4) +0ms
  ads-client:details sendAdsCommand(): Response received for command "ReadState" with invokeId 11 +0ms
  ads-client readPlcRuntimeState(): Runtime state read successfully. State is { adsState: 5, adsStateStr: 'Run', deviceState: 0 } +18ms
  ads-client handlePlcRuntimeStateChange(): PLC runtime state (adsState) changed from Stop to Run +0ms
  ads-client:details IO in  <------ 70 bytes from 127.0.0.1 +1ms
  ads-client:details parseAmsTcpHeader(): Starting to parse AMS/TCP header +0ms
  ads-client:details parseAmsTcpHeader(): AMS/TCP header parsed: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD', length: 64 } +0ms
  ads-client:details parseAmsHeader(): Starting to parse AMS header +0ms
  ads-client:details parseAmsHeader(): AMS header parsed: { targetAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32794 }, sourceAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 851 }, adsCommand: 8, adsCommandStr: 'Notification', stateFlags: 4, stateFlagsStr: 'AdsCommand, Tcp, Request', dataLength: 32, errorCode: 0, invokeId: 0, error: false, errorStr: '' } +0ms
  ads-client:details parseAdsResponse(): Starting to parse ADS data +0ms
  ads-client:details parseAdsResponse(): ADS data parsed: { payload: { length: 28, stampCount: 1, stamps: [ [Object] ] } } +1ms
  ads-client:details onAmsTcpPacketReceived(): AMS packet received with command 0 +0ms
  ads-client:details onAdsCommandReceived(): ADS command received (command: 8) +0ms
  ads-client onAdsCommandReceived(): Notification received from 100.70.46.31.1.1:851 for handle 37 ({ indexGroup: 61696, indexOffset: 0, size: 4 }) +2ms
  ads-client readTcSystemState(): Reading TwinCAT system state +292ms
  ads-client:details sendAdsCommand(): Sending an ads command ReadState (0 bytes): { amsTcp: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD' }, ams: { targetAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 10000 }, sourceAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32794 }, adsCommand: 4, adsCommandStr: 'ReadState', stateFlags: 4, stateFlagsStr: 'AdsCommand, Tcp, Request', dataLength: 0, errorCode: 0, invokeId: 12 }, ads: { payload: undefined } } +292ms
  ads-client:details createAmsHeader(): AMS header created (32 bytes) +1ms
  ads-client:details createAmsTcpHeader(): AMS/TCP header created (6 bytes) +0ms
  ads-client:details createAmsTcpRequest(): AMS/TCP request created (38 bytes) +0ms
  ads-client:details IO out ------> 38 bytes +0ms
  ads-client:details IO in  <------ 46 bytes from 127.0.0.1 +18ms
  ads-client:details parseAmsTcpHeader(): Starting to parse AMS/TCP header +0ms
  ads-client:details parseAmsTcpHeader(): AMS/TCP header parsed: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD', length: 40 } +0ms
  ads-client:details parseAmsHeader(): Starting to parse AMS header +1ms
  ads-client:details parseAmsHeader(): AMS header parsed: { targetAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32794 }, sourceAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 10000 }, adsCommand: 4, adsCommandStr: 'ReadState', stateFlags: 5, stateFlagsStr: 'Response, AdsCommand, Tcp', dataLength: 8, errorCode: 0, invokeId: 12, error: false, errorStr: '' } +0ms
  ads-client:details parseAdsResponse(): Starting to parse ADS data +0ms
  ads-client:details parseAdsResponse(): ADS data parsed: { errorCode: 0, payload: { adsState: 5, adsStateStr: 'Run', deviceState: 1 } } +0ms
  ads-client:details onAmsTcpPacketReceived(): AMS packet received with command 0 +0ms
  ads-client:details onAdsCommandReceived(): ADS command received (command: 4) +0ms
  ads-client:details sendAdsCommand(): Response received for command "ReadState" with invokeId 12 +0ms
  ads-client readTcSystemState(): TwinCAT system state read successfully. State is { adsState: 5, adsStateStr: 'Run', deviceState: 1 } +20ms
  ads-client readValue(): Reading value from GVL_AdsClientTests.IsRunning +189ms
  ads-client:details readValue(): Getting symbol for GVL_AdsClientTests.IsRunning +189ms
  ads-client getSymbol(): Symbol requested for GVL_AdsClientTests.IsRunning +0ms
  ads-client getSymbol(): Symbol for GVL_AdsClientTests.IsRunning not cached, reading from target +0ms
  ads-client:details sendAdsCommand(): Sending an ads command ReadWrite (45 bytes): { amsTcp: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD' }, ams: { targetAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 851 }, sourceAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32794 }, adsCommand: 9, adsCommandStr: 'ReadWrite', stateFlags: 4, stateFlagsStr: 'AdsCommand, Tcp, Request', dataLength: 45, errorCode: 0, invokeId: 13 }, ads: { payload: <Buffer 09 f0 00 00 00 00 00 00 ff ff ff ff 1d 00 00 00 47 56 4c 5f 41 64 73 43 6c 69 65 6e 74 54 65 73 74 73 2e 49 73 52 75 6e 6e 69 6e 67 00> } } +1ms
  ads-client:details createAmsHeader(): AMS header created (32 bytes) +0ms
  ads-client:details createAmsTcpHeader(): AMS/TCP header created (6 bytes) +0ms
  ads-client:details createAmsTcpRequest(): AMS/TCP request created (83 bytes) +0ms
  ads-client:details IO out ------> 83 bytes +0ms
  ads-client:details IO in  <------ 134 bytes from 127.0.0.1 +18ms
  ads-client:details parseAmsTcpHeader(): Starting to parse AMS/TCP header +1ms
  ads-client:details parseAmsTcpHeader(): AMS/TCP header parsed: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD', length: 128 } +0ms
  ads-client:details parseAmsHeader(): Starting to parse AMS header +0ms
  ads-client:details parseAmsHeader(): AMS header parsed: { targetAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32794 }, sourceAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 851 }, adsCommand: 9, adsCommandStr: 'ReadWrite', stateFlags: 5, stateFlagsStr: 'Response, AdsCommand, Tcp', dataLength: 96, errorCode: 0, invokeId: 13, error: false, errorStr: '' } +0ms
  ads-client:details parseAdsResponse(): Starting to parse ADS data +0ms
  ads-client:details parseAdsResponse(): ADS data parsed: { errorCode: 0, length: 88, payload: <Buffer 58 00 00 00 40 40 00 00 af de 05 00 01 00 00 00 21 00 00 00 08 00 00 00 1c 00 04 00 00 00 47 56 4c 5f 41 64 73 43 6c 69 65 6e 74 54 65 73 74 73 2e 49 ... 38 more bytes> } +0ms
  ads-client:details onAmsTcpPacketReceived(): AMS packet received with command 0 +0ms
  ads-client:details onAdsCommandReceived(): ADS command received (command: 9) +0ms
  ads-client:details sendAdsCommand(): Response received for command "ReadWrite" with invokeId 13 +0ms
  ads-client:details parseAdsResponseSymbol(): Parsing symbol from data (84 bytes) +1ms
  ads-client:details parseAdsResponseSymbol(): Symbol parsed for GVL_AdsClientTests.IsRunning (BOOL) +0ms
  ads-client getSymbol(): Symbol read and parsed for GVL_AdsClientTests.IsRunning +21ms
  ads-client:details readValue(): Getting data type for GVL_AdsClientTests.IsRunning +0ms
  ads-client buildDataType(): Building data type for BOOL +1ms
  ads-client getDataTypeDeclaration(): Data type declaration requested for BOOL +0ms
  ads-client getDataTypeDeclaration(): Data type declaration for BOOL not cached, reading from target +0ms
  ads-client:details sendAdsCommand(): Sending an ads command ReadWrite (21 bytes): { amsTcp: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD' }, ams: { targetAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 851 }, sourceAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32794 }, adsCommand: 9, adsCommandStr: 'ReadWrite', stateFlags: 4, stateFlagsStr: 'AdsCommand, Tcp, Request', dataLength: 21, errorCode: 0, invokeId: 14 }, ads: { payload: <Buffer 11 f0 00 00 00 00 00 00 ff ff ff ff 05 00 00 00 42 4f 4f 4c 00> } } +1ms
  ads-client:details createAmsHeader(): AMS header created (32 bytes) +1ms
  ads-client:details createAmsTcpHeader(): AMS/TCP header created (6 bytes) +0ms
  ads-client:details createAmsTcpRequest(): AMS/TCP request created (59 bytes) +0ms
  ads-client:details IO out ------> 59 bytes +0ms
  ads-client:details IO in  <------ 158 bytes from 127.0.0.1 +17ms
  ads-client:details parseAmsTcpHeader(): Starting to parse AMS/TCP header +0ms
  ads-client:details parseAmsTcpHeader(): AMS/TCP header parsed: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD', length: 152 } +0ms
  ads-client:details parseAmsHeader(): Starting to parse AMS header +1ms
  ads-client:details parseAmsHeader(): AMS header parsed: { targetAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32794 }, sourceAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 851 }, adsCommand: 9, adsCommandStr: 'ReadWrite', stateFlags: 5, stateFlagsStr: 'Response, AdsCommand, Tcp', dataLength: 120, errorCode: 0, invokeId: 14, error: false, errorStr: '' } +0ms
  ads-client:details parseAdsResponse(): Starting to parse ADS data +0ms
  ads-client:details parseAdsResponse(): ADS data parsed: { errorCode: 0, length: 112, payload: <Buffer 70 00 00 00 01 00 00 00 00 00 00 00 00 00 00 00 01 00 00 00 00 00 00 00 21 00 00 00 81 10 00 00 04 00 04 00 00 00 00 00 00 00 42 4f 4f 4c 00 42 59 54 ... 62 more bytes> } +0ms
  ads-client:details onAmsTcpPacketReceived(): AMS packet received with command 0 +0ms
  ads-client:details onAdsCommandReceived(): ADS command received (command: 9) +0ms
  ads-client:details sendAdsCommand(): Response received for command "ReadWrite" with invokeId 14 +0ms
  ads-client:details parseAdsResponseDataType(): Parsing data type from ADS response (108 bytes) +0ms
  ads-client:details parseAdsResponseDataType(): Data type parsed (result: BOOL) +1ms
  ads-client getDataTypeDeclaration(): Data type declaration read and parsed for BOOL +20ms
  ads-client:details readValue(): Reading raw value from GVL_AdsClientTests.IsRunning +0ms
  ads-client readRaw(): Reading raw data ({"indexGroup":16448,"indexOffset":384687,"size":1}) +0ms
  ads-client:details sendAdsCommand(): Sending an ads command Read (12 bytes): { amsTcp: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD' }, ams: { targetAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 851 }, sourceAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32794 }, adsCommand: 2, adsCommandStr: 'Read', stateFlags: 4, stateFlagsStr: 'AdsCommand, Tcp, Request', dataLength: 12, errorCode: 0, invokeId: 15 }, ads: { payload: <Buffer 40 40 00 00 af de 05 00 01 00 00 00> } } +0ms
  ads-client:details createAmsHeader(): AMS header created (32 bytes) +0ms
  ads-client:details createAmsTcpHeader(): AMS/TCP header created (6 bytes) +0ms
  ads-client:details createAmsTcpRequest(): AMS/TCP request created (50 bytes) +0ms
  ads-client:details IO out ------> 50 bytes +0ms
  ads-client:details IO in  <------ 47 bytes from 127.0.0.1 +17ms
  ads-client:details parseAmsTcpHeader(): Starting to parse AMS/TCP header +0ms
  ads-client:details parseAmsTcpHeader(): AMS/TCP header parsed: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD', length: 41 } +0ms
  ads-client:details parseAmsHeader(): Starting to parse AMS header +0ms
  ads-client:details parseAmsHeader(): AMS header parsed: { targetAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32794 }, sourceAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 851 }, adsCommand: 2, adsCommandStr: 'Read', stateFlags: 5, stateFlagsStr: 'Response, AdsCommand, Tcp', dataLength: 9, errorCode: 0, invokeId: 15, error: false, errorStr: '' } +0ms
  ads-client:details parseAdsResponse(): Starting to parse ADS data +0ms
  ads-client:details parseAdsResponse(): ADS data parsed: { errorCode: 0, length: 1, payload: <Buffer 01> } +0ms
  ads-client:details onAmsTcpPacketReceived(): AMS packet received with command 0 +0ms
  ads-client:details onAdsCommandReceived(): ADS command received (command: 2) +0ms
  ads-client:details sendAdsCommand(): Response received for command "Read" with invokeId 15 +0ms
  ads-client readRaw(): Reading raw data ({"indexGroup":16448,"indexOffset":384687,"size":1}) done (1 bytes) +17ms
  ads-client:details readValue(): Converting raw value to object for GVL_AdsClientTests.IsRunning +0ms
  ads-client readValue(): Reading value from GVL_AdsClientTests.IsRunning done +1ms
  ads-client connectToTarget(): Connecting to target at 127.0.0.1:48898 (reconnecting: false) +0ms
  ads-client connectToTarget(): Socket connection established to 127.0.0.1:48898 +1ms
  ads-client registerAdsPort(): Registering an ADS port from target router (127.0.0.1:48898) +0ms
  ads-client:details IO out ------> 8 bytes +0ms
  ads-client:details IO in  <------ 14 bytes from 127.0.0.1 +1ms
  ads-client:details parseAmsTcpHeader(): Starting to parse AMS/TCP header +0ms
  ads-client:details parseAmsTcpHeader(): AMS/TCP header parsed: { command: 4096, commandStr: 'AMS_TCP_PORT_CONNECT', length: 8, data: <Buffer 64 75 37 4b 01 01 f6 7f> } +0ms
  ads-client:details parseAmsHeader(): Starting to parse AMS header +0ms
  ads-client:details parseAmsHeader(): No AMS header found +0ms
  ads-client:details parseAdsResponse(): Starting to parse ADS data +0ms
  ads-client:details parseAdsData(): Packet has no ADS data +0ms
  ads-client:details onAmsTcpPacketReceived(): AMS packet received with command 4096 +0ms
  ads-client registerAdsPort(): ADS port registered, assigned AMS address is 100.117.55.75.1.1:32758 +1ms
  ads-client connectToTarget(): ADS port registered. Our AMS address is 100.117.55.75.1.1:32758 +0ms
  ads-client readTcSystemState(): Reading TwinCAT system state +0ms
  ads-client:details sendAdsCommand(): Sending an ads command ReadState (0 bytes): { amsTcp: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD' }, ams: { targetAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 10000 }, sourceAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32758 }, adsCommand: 4, adsCommandStr: 'ReadState', stateFlags: 4, stateFlagsStr: 'AdsCommand, Tcp, Request', dataLength: 0, errorCode: 0, invokeId: 0 }, ads: { payload: undefined } } +0ms
  ads-client:details createAmsHeader(): AMS header created (32 bytes) +0ms
  ads-client:details createAmsTcpHeader(): AMS/TCP header created (6 bytes) +0ms
  ads-client:details createAmsTcpRequest(): AMS/TCP request created (38 bytes) +0ms
  ads-client:details IO out ------> 38 bytes +0ms
  ads-client:details IO in  <------ 46 bytes from 127.0.0.1 +19ms
  ads-client:details parseAmsTcpHeader(): Starting to parse AMS/TCP header +0ms
  ads-client:details parseAmsTcpHeader(): AMS/TCP header parsed: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD', length: 40 } +0ms
  ads-client:details parseAmsHeader(): Starting to parse AMS header +0ms
  ads-client:details parseAmsHeader(): AMS header parsed: { targetAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32758 }, sourceAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 10000 }, adsCommand: 4, adsCommandStr: 'ReadState', stateFlags: 5, stateFlagsStr: 'Response, AdsCommand, Tcp', dataLength: 8, errorCode: 0, invokeId: 0, error: false, errorStr: '' } +0ms
  ads-client:details parseAdsResponse(): Starting to parse ADS data +0ms
  ads-client:details parseAdsResponse(): ADS data parsed: { errorCode: 0, payload: { adsState: 5, adsStateStr: 'Run', deviceState: 1 } } +0ms
  ads-client:details onAmsTcpPacketReceived(): AMS packet received with command 0 +0ms
  ads-client:details onAdsCommandReceived(): ADS command received (command: 4) +0ms
  ads-client:details sendAdsCommand(): Response received for command "ReadState" with invokeId 0 +0ms
  ads-client readTcSystemState(): TwinCAT system state read successfully. State is { adsState: 5, adsStateStr: 'Run', deviceState: 1 } +19ms
  ads-client:details addSubscription(): Subscribing { target: { indexGroup: 61696, indexOffset: 0, size: 4 }, callback: [Function: bound onPlcRuntimeStateChanged], cycleTime: 0 } (internal: true) +0ms
  ads-client:details sendAdsCommand(): Sending an ads command AddNotification (40 bytes): { amsTcp: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD' }, ams: { targetAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 851 }, sourceAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32758 }, adsCommand: 6, adsCommandStr: 'AddNotification', stateFlags: 4, stateFlagsStr: 'AdsCommand, Tcp, Request', dataLength: 40, errorCode: 0, invokeId: 1 }, ads: { payload: <Buffer 00 f1 00 00 00 00 00 00 04 00 00 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00> } } +0ms
  ads-client:details createAmsHeader(): AMS header created (32 bytes) +0ms
  ads-client:details createAmsTcpHeader(): AMS/TCP header created (6 bytes) +0ms
  ads-client:details createAmsTcpRequest(): AMS/TCP request created (78 bytes) +0ms
  ads-client:details IO out ------> 78 bytes +0ms
  ads-client:details IO in  <------ 46 bytes from 127.0.0.1 +19ms
  ads-client:details parseAmsTcpHeader(): Starting to parse AMS/TCP header +0ms
  ads-client:details parseAmsTcpHeader(): AMS/TCP header parsed: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD', length: 40 } +0ms
  ads-client:details parseAmsHeader(): Starting to parse AMS header +0ms
  ads-client:details parseAmsHeader(): AMS header parsed: { targetAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32758 }, sourceAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 851 }, adsCommand: 6, adsCommandStr: 'AddNotification', stateFlags: 5, stateFlagsStr: 'Response, AdsCommand, Tcp', dataLength: 8, errorCode: 0, invokeId: 1, error: false, errorStr: '' } +0ms
  ads-client:details parseAdsResponse(): Starting to parse ADS data +0ms
  ads-client:details parseAdsResponse(): ADS data parsed: { errorCode: 0, payload: { notificationHandle: 39 } } +0ms
  ads-client:details onAmsTcpPacketReceived(): AMS packet received with command 0 +0ms
  ads-client:details onAdsCommandReceived(): ADS command received (command: 6) +0ms
  ads-client:details sendAdsCommand(): Response received for command "AddNotification" with invokeId 1 +0ms
  ads-client:details addSubscription(): Subscribed to { indexGroup: 61696, indexOffset: 0, size: 4 } +0ms
  ads-client readDeviceInfo(): Reading device info +19ms
  ads-client:details sendAdsCommand(): Sending an ads command ReadDeviceInfo (0 bytes): { amsTcp: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD' }, ams: { targetAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 851 }, sourceAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32758 }, adsCommand: 1, adsCommandStr: 'ReadDeviceInfo', stateFlags: 4, stateFlagsStr: 'AdsCommand, Tcp, Request', dataLength: 0, errorCode: 0, invokeId: 2 }, ads: { payload: undefined } } +0ms
  ads-client:details createAmsHeader(): AMS header created (32 bytes) +0ms
  ads-client:details createAmsTcpHeader(): AMS/TCP header created (6 bytes) +0ms
  ads-client:details createAmsTcpRequest(): AMS/TCP request created (38 bytes) +0ms
  ads-client:details IO out ------> 38 bytes +0ms
  ads-client:details IO in  <------ 70 bytes from 127.0.0.1 +9ms
  ads-client:details parseAmsTcpHeader(): Starting to parse AMS/TCP header +0ms
  ads-client:details parseAmsTcpHeader(): AMS/TCP header parsed: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD', length: 64 } +0ms
  ads-client:details parseAmsHeader(): Starting to parse AMS header +0ms
  ads-client:details parseAmsHeader(): AMS header parsed: { targetAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32758 }, sourceAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 851 }, adsCommand: 8, adsCommandStr: 'Notification', stateFlags: 4, stateFlagsStr: 'AdsCommand, Tcp, Request', dataLength: 32, errorCode: 0, invokeId: 0, error: false, errorStr: '' } +0ms
  ads-client:details parseAdsResponse(): Starting to parse ADS data +0ms
  ads-client:details parseAdsResponse(): ADS data parsed: { payload: { length: 28, stampCount: 1, stamps: [ [Object] ] } } +0ms
  ads-client:details onAmsTcpPacketReceived(): AMS packet received with command 0 +0ms
  ads-client:details onAdsCommandReceived(): ADS command received (command: 8) +0ms
  ads-client onAdsCommandReceived(): Notification received from 100.70.46.31.1.1:851 for handle 39 ({ indexGroup: 61696, indexOffset: 0, size: 4 }) +9ms
  ads-client handlePlcRuntimeStateChange(): PLC runtime state (adsState) changed from UNKNOWN to Run +0ms
  ads-client handlePlcRuntimeStateChange(): PLC runtime state (deviceState) changed from UNKNOWN to 0 +0ms
  ads-client:details IO in  <------ 62 bytes from 127.0.0.1 +8ms
  ads-client:details parseAmsTcpHeader(): Starting to parse AMS/TCP header +0ms
  ads-client:details parseAmsTcpHeader(): AMS/TCP header parsed: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD', length: 56 } +0ms
  ads-client:details parseAmsHeader(): Starting to parse AMS header +0ms
  ads-client:details parseAmsHeader(): AMS header parsed: { targetAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32758 }, sourceAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 851 }, adsCommand: 1, adsCommandStr: 'ReadDeviceInfo', stateFlags: 5, stateFlagsStr: 'Response, AdsCommand, Tcp', dataLength: 24, errorCode: 0, invokeId: 2, error: false, errorStr: '' } +0ms
  ads-client:details parseAdsResponse(): Starting to parse ADS data +0ms
  ads-client:details parseAdsResponse(): ADS data parsed: { errorCode: 0, payload: { majorVersion: 3, minorVersion: 1, versionBuild: 1966, deviceName: 'Plc30 App' } } +0ms
  ads-client:details onAmsTcpPacketReceived(): AMS packet received with command 0 +0ms
  ads-client:details onAdsCommandReceived(): ADS command received (command: 1) +0ms
  ads-client:details sendAdsCommand(): Response received for command "ReadDeviceInfo" with invokeId 2 +0ms
  ads-client readDeviceInfo(): Device info read successfully. Device is { majorVersion: 3, minorVersion: 1, versionBuild: 1966, deviceName: 'Plc30 App' } +8ms
  ads-client readPlcUploadInfo(): Reading upload info +0ms
  ads-client sendAdsCommandWithFallback(): Sending ADS command with a fallback +0ms
  ads-client:details sendAdsCommand(): Sending an ads command Read (12 bytes): { amsTcp: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD' }, ams: { targetAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 851 }, sourceAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32758 }, adsCommand: 2, adsCommandStr: 'Read', stateFlags: 4, stateFlagsStr: 'AdsCommand, Tcp, Request', dataLength: 12, errorCode: 0, invokeId: 3 }, ads: { payload: <Buffer 0f f0 00 00 00 00 00 00 40 00 00 00> } } +0ms
  ads-client:details createAmsHeader(): AMS header created (32 bytes) +0ms
  ads-client:details createAmsTcpHeader(): AMS/TCP header created (6 bytes) +0ms
  ads-client:details createAmsTcpRequest(): AMS/TCP request created (50 bytes) +0ms
  ads-client:details IO out ------> 50 bytes +0ms
  ads-client:details IO in  <------ 110 bytes from 127.0.0.1 +17ms
  ads-client:details parseAmsTcpHeader(): Starting to parse AMS/TCP header +0ms
  ads-client:details parseAmsTcpHeader(): AMS/TCP header parsed: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD', length: 104 } +0ms
  ads-client:details parseAmsHeader(): Starting to parse AMS header +0ms
  ads-client:details parseAmsHeader(): AMS header parsed: { targetAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32758 }, sourceAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 851 }, adsCommand: 2, adsCommandStr: 'Read', stateFlags: 5, stateFlagsStr: 'Response, AdsCommand, Tcp', dataLength: 72, errorCode: 0, invokeId: 3, error: false, errorStr: '' } +0ms
  ads-client:details parseAdsResponse(): Starting to parse ADS data +0ms
  ads-client:details parseAdsResponse(): ADS data parsed: { errorCode: 0, length: 64, payload: <Buffer af 00 00 00 a8 48 00 00 a0 00 00 00 a8 d7 00 00 d0 07 00 00 00 00 00 00 00 00 00 00 e9 fd 00 00 03 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ... 14 more bytes> } +0ms
  ads-client:details onAmsTcpPacketReceived(): AMS packet received with command 0 +0ms
  ads-client:details onAdsCommandReceived(): ADS command received (command: 2) +0ms
  ads-client:details sendAdsCommand(): Response received for command "Read" with invokeId 3 +0ms
  ads-client readPlcUploadInfo(): Upload info read - fallback was needed: false +17ms
  ads-client readPlcUploadInfo(): Upload info read and parsed for 100.70.46.31.1.1:851 +0ms
  ads-client readPlcSymbolVersion(): Reading PLC runtime symbol version +0ms
  ads-client readRaw(): Reading raw data ({"indexGroup":61448,"indexOffset":0,"size":1}) +0ms
  ads-client:details sendAdsCommand(): Sending an ads command Read (12 bytes): { amsTcp: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD' }, ams: { targetAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 851 }, sourceAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32758 }, adsCommand: 2, adsCommandStr: 'Read', stateFlags: 4, stateFlagsStr: 'AdsCommand, Tcp, Request', dataLength: 12, errorCode: 0, invokeId: 4 }, ads: { payload: <Buffer 08 f0 00 00 00 00 00 00 01 00 00 00> } } +0ms
  ads-client:details createAmsHeader(): AMS header created (32 bytes) +1ms
  ads-client:details createAmsTcpHeader(): AMS/TCP header created (6 bytes) +0ms
  ads-client:details createAmsTcpRequest(): AMS/TCP request created (50 bytes) +0ms
  ads-client:details IO out ------> 50 bytes +0ms
  ads-client:details IO in  <------ 47 bytes from 127.0.0.1 +16ms
  ads-client:details parseAmsTcpHeader(): Starting to parse AMS/TCP header +0ms
  ads-client:details parseAmsTcpHeader(): AMS/TCP header parsed: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD', length: 41 } +0ms
  ads-client:details parseAmsHeader(): Starting to parse AMS header +0ms
  ads-client:details parseAmsHeader(): AMS header parsed: { targetAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32758 }, sourceAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 851 }, adsCommand: 2, adsCommandStr: 'Read', stateFlags: 5, stateFlagsStr: 'Response, AdsCommand, Tcp', dataLength: 9, errorCode: 0, invokeId: 4, error: false, errorStr: '' } +0ms
  ads-client:details parseAdsResponse(): Starting to parse ADS data +0ms
  ads-client:details parseAdsResponse(): ADS data parsed: { errorCode: 0, length: 1, payload: <Buffer 37> } +0ms
  ads-client:details onAmsTcpPacketReceived(): AMS packet received with command 0 +0ms
  ads-client:details onAdsCommandReceived(): ADS command received (command: 2) +0ms
  ads-client:details sendAdsCommand(): Response received for command "Read" with invokeId 4 +0ms
  ads-client readRaw(): Reading raw data ({"indexGroup":61448,"indexOffset":0,"size":1}) done (1 bytes) +17ms
  ads-client readPlcSymbolVersion(): PLC runtime symbol version is now 55 +0ms
  ads-client onPlcSymbolVersionChanged(): PLC runtime symbol version is now 55 +0ms
  ads-client:details addSubscription(): Subscribing { target: { indexGroup: 61448, indexOffset: 0, size: 1 }, callback: [Function: bound onPlcSymbolVersionChanged] AsyncFunction, cycleTime: 0 } (internal: true) +0ms
  ads-client:details sendAdsCommand(): Sending an ads command AddNotification (40 bytes): { amsTcp: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD' }, ams: { targetAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 851 }, sourceAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32758 }, adsCommand: 6, adsCommandStr: 'AddNotification', stateFlags: 4, stateFlagsStr: 'AdsCommand, Tcp, Request', dataLength: 40, errorCode: 0, invokeId: 5 }, ads: { payload: <Buffer 08 f0 00 00 00 00 00 00 01 00 00 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00> } } +0ms
  ads-client:details createAmsHeader(): AMS header created (32 bytes) +0ms
  ads-client:details createAmsTcpHeader(): AMS/TCP header created (6 bytes) +0ms
  ads-client:details createAmsTcpRequest(): AMS/TCP request created (78 bytes) +0ms
  ads-client:details IO out ------> 78 bytes +0ms
  ads-client:details IO in  <------ 46 bytes from 127.0.0.1 +17ms
  ads-client:details parseAmsTcpHeader(): Starting to parse AMS/TCP header +0ms
  ads-client:details parseAmsTcpHeader(): AMS/TCP header parsed: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD', length: 40 } +0ms
  ads-client:details parseAmsHeader(): Starting to parse AMS header +0ms
  ads-client:details parseAmsHeader(): AMS header parsed: { targetAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32758 }, sourceAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 851 }, adsCommand: 6, adsCommandStr: 'AddNotification', stateFlags: 5, stateFlagsStr: 'Response, AdsCommand, Tcp', dataLength: 8, errorCode: 0, invokeId: 5, error: false, errorStr: '' } +0ms
  ads-client:details parseAdsResponse(): Starting to parse ADS data +0ms
  ads-client:details parseAdsResponse(): ADS data parsed: { errorCode: 0, payload: { notificationHandle: 40 } } +0ms
  ads-client:details onAmsTcpPacketReceived(): AMS packet received with command 0 +0ms
  ads-client:details onAdsCommandReceived(): ADS command received (command: 6) +0ms
  ads-client:details sendAdsCommand(): Response received for command "AddNotification" with invokeId 5 +0ms
  ads-client:details addSubscription(): Subscribed to { indexGroup: 61448, indexOffset: 0, size: 1 } +0ms
  ads-client subscribe(): Subscribing to "'GVL_Subscription.NumericValue_100ms'" +18ms
  ads-client:details addSubscription(): Subscribing { target: 'GVL_Subscription.NumericValue_100ms', callback: [AsyncFunction: callback] } (internal: false) +1ms
  ads-client getSymbol(): Symbol requested for GVL_Subscription.NumericValue_100ms +0ms
  ads-client getSymbol(): Symbol for GVL_Subscription.NumericValue_100ms not cached, reading from target +0ms
  ads-client:details sendAdsCommand(): Sending an ads command ReadWrite (52 bytes): { amsTcp: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD' }, ams: { targetAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 851 }, sourceAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32758 }, adsCommand: 9, adsCommandStr: 'ReadWrite', stateFlags: 4, stateFlagsStr: 'AdsCommand, Tcp, Request', dataLength: 52, errorCode: 0, invokeId: 6 }, ads: { payload: <Buffer 09 f0 00 00 00 00 00 00 ff ff ff ff 24 00 00 00 47 56 4c 5f 53 75 62 73 63 72 69 70 74 69 6f 6e 2e 4e 75 6d 65 72 69 63 56 61 6c 75 65 5f 31 30 30 6d ... 2 more bytes> } } +0ms
  ads-client:details createAmsHeader(): AMS header created (32 bytes) +0ms
  ads-client:details createAmsTcpHeader(): AMS/TCP header created (6 bytes) +0ms
  ads-client:details createAmsTcpRequest(): AMS/TCP request created (90 bytes) +0ms
  ads-client:details IO out ------> 90 bytes +0ms
  ads-client:details IO in  <------ 67 bytes from 127.0.0.1 +0ms
  ads-client:details parseAmsTcpHeader(): Starting to parse AMS/TCP header +0ms
  ads-client:details parseAmsTcpHeader(): AMS/TCP header parsed: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD', length: 61 } +0ms
  ads-client:details parseAmsHeader(): Starting to parse AMS header +0ms
  ads-client:details parseAmsHeader(): AMS header parsed: { targetAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32758 }, sourceAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 851 }, adsCommand: 8, adsCommandStr: 'Notification', stateFlags: 4, stateFlagsStr: 'AdsCommand, Tcp, Request', dataLength: 29, errorCode: 0, invokeId: 0, error: false, errorStr: '' } +0ms
  ads-client:details parseAdsResponse(): Starting to parse ADS data +0ms
  ads-client:details parseAdsResponse(): ADS data parsed: { payload: { length: 25, stampCount: 1, stamps: [ [Object] ] } } +0ms
  ads-client:details onAmsTcpPacketReceived(): AMS packet received with command 0 +1ms
  ads-client:details onAdsCommandReceived(): ADS command received (command: 8) +0ms
  ads-client onAdsCommandReceived(): Notification received from 100.70.46.31.1.1:851 for handle 40 ({ indexGroup: 61448, indexOffset: 0, size: 1 }) +1ms
  ads-client onPlcSymbolVersionChanged(): PLC runtime symbol version received (not changed). Version is now 55 +0ms
  ads-client:details IO in  <------ 134 bytes from 127.0.0.1 +18ms
  ads-client:details parseAmsTcpHeader(): Starting to parse AMS/TCP header +0ms
  ads-client:details parseAmsTcpHeader(): AMS/TCP header parsed: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD', length: 128 } +0ms
  ads-client:details parseAmsHeader(): Starting to parse AMS header +0ms
  ads-client:details parseAmsHeader(): AMS header parsed: { targetAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32758 }, sourceAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 851 }, adsCommand: 9, adsCommandStr: 'ReadWrite', stateFlags: 5, stateFlagsStr: 'Response, AdsCommand, Tcp', dataLength: 96, errorCode: 0, invokeId: 6, error: false, errorStr: '' } +0ms
  ads-client:details parseAdsResponse(): Starting to parse ADS data +0ms
  ads-client:details parseAdsResponse(): ADS data parsed: { errorCode: 0, length: 88, payload: <Buffer 58 00 00 00 40 40 00 00 5c e5 05 00 02 00 00 00 02 00 00 00 08 00 00 00 23 00 03 00 00 00 47 56 4c 5f 53 75 62 73 63 72 69 70 74 69 6f 6e 2e 4e 75 6d ... 38 more bytes> } +0ms
  ads-client:details onAmsTcpPacketReceived(): AMS packet received with command 0 +0ms
  ads-client:details onAdsCommandReceived(): ADS command received (command: 9) +0ms
  ads-client:details sendAdsCommand(): Response received for command "ReadWrite" with invokeId 6 +0ms
  ads-client:details parseAdsResponseSymbol(): Parsing symbol from data (84 bytes) +0ms
  ads-client:details parseAdsResponseSymbol(): Symbol parsed for GVL_Subscription.NumericValue_100ms (INT) +0ms
  ads-client getSymbol(): Symbol read and parsed for GVL_Subscription.NumericValue_100ms +18ms
  ads-client getDataType(): Data type requested for INT +1ms
  ads-client buildDataType(): Building data type for INT +0ms
  ads-client getDataTypeDeclaration(): Data type declaration requested for INT +0ms
  ads-client getDataTypeDeclaration(): Data type declaration for INT not cached, reading from target +0ms
  ads-client:details sendAdsCommand(): Sending an ads command ReadWrite (20 bytes): { amsTcp: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD' }, ams: { targetAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 851 }, sourceAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32758 }, adsCommand: 9, adsCommandStr: 'ReadWrite', stateFlags: 4, stateFlagsStr: 'AdsCommand, Tcp, Request', dataLength: 20, errorCode: 0, invokeId: 7 }, ads: { payload: <Buffer 11 f0 00 00 00 00 00 00 ff ff ff ff 04 00 00 00 49 4e 54 00> } } +1ms
  ads-client:details createAmsHeader(): AMS header created (32 bytes) +0ms
  ads-client:details createAmsTcpHeader(): AMS/TCP header created (6 bytes) +0ms
  ads-client:details createAmsTcpRequest(): AMS/TCP request created (58 bytes) +0ms
  ads-client:details IO out ------> 58 bytes +0ms
  ads-client:details IO in  <------ 166 bytes from 127.0.0.1 +16ms
  ads-client:details parseAmsTcpHeader(): Starting to parse AMS/TCP header +0ms
  ads-client:details parseAmsTcpHeader(): AMS/TCP header parsed: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD', length: 160 } +0ms
  ads-client:details parseAmsHeader(): Starting to parse AMS header +0ms
  ads-client:details parseAmsHeader(): AMS header parsed: { targetAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32758 }, sourceAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 851 }, adsCommand: 9, adsCommandStr: 'ReadWrite', stateFlags: 5, stateFlagsStr: 'Response, AdsCommand, Tcp', dataLength: 128, errorCode: 0, invokeId: 7, error: false, errorStr: '' } +0ms
  ads-client:details parseAdsResponse(): Starting to parse ADS data +0ms
  ads-client:details parseAdsResponse(): ADS data parsed: { errorCode: 0, length: 120, payload: <Buffer 78 00 00 00 01 00 00 00 00 00 00 00 00 00 00 00 02 00 00 00 00 00 00 00 02 00 00 00 81 10 00 00 03 00 00 00 00 00 00 00 00 00 49 4e 54 00 00 00 95 19 ... 70 more bytes> } +0ms
  ads-client:details onAmsTcpPacketReceived(): AMS packet received with command 0 +0ms
  ads-client:details onAdsCommandReceived(): ADS command received (command: 9) +0ms
  ads-client:details sendAdsCommand(): Response received for command "ReadWrite" with invokeId 7 +0ms
  ads-client:details parseAdsResponseDataType(): Parsing data type from ADS response (116 bytes) +0ms
  ads-client:details parseAdsResponseDataType(): Data type parsed (result: INT) +0ms
  ads-client getDataTypeDeclaration(): Data type declaration read and parsed for INT +16ms
  ads-client getDataType(): Data type read and built for INT +0ms
  ads-client:details sendAdsCommand(): Sending an ads command AddNotification (40 bytes): { amsTcp: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD' }, ams: { targetAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 851 }, sourceAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32758 }, adsCommand: 6, adsCommandStr: 'AddNotification', stateFlags: 4, stateFlagsStr: 'AdsCommand, Tcp, Request', dataLength: 40, errorCode: 0, invokeId: 8 }, ads: { payload: <Buffer 40 40 00 00 5c e5 05 00 02 00 00 00 04 00 00 00 00 00 00 00 80 84 1e 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00> } } +0ms
  ads-client:details createAmsHeader(): AMS header created (32 bytes) +0ms
  ads-client:details createAmsTcpHeader(): AMS/TCP header created (6 bytes) +0ms
  ads-client:details createAmsTcpRequest(): AMS/TCP request created (78 bytes) +0ms
  ads-client:details IO out ------> 78 bytes +0ms
  ads-client:details IO in  <------ 46 bytes from 127.0.0.1 +16ms
  ads-client:details parseAmsTcpHeader(): Starting to parse AMS/TCP header +0ms
  ads-client:details parseAmsTcpHeader(): AMS/TCP header parsed: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD', length: 40 } +0ms
  ads-client:details parseAmsHeader(): Starting to parse AMS header +0ms
  ads-client:details parseAmsHeader(): AMS header parsed: { targetAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32758 }, sourceAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 851 }, adsCommand: 6, adsCommandStr: 'AddNotification', stateFlags: 5, stateFlagsStr: 'Response, AdsCommand, Tcp', dataLength: 8, errorCode: 0, invokeId: 8, error: false, errorStr: '' } +0ms
  ads-client:details parseAdsResponse(): Starting to parse ADS data +0ms
  ads-client:details parseAdsResponse(): ADS data parsed: { errorCode: 0, payload: { notificationHandle: 41 } } +0ms
  ads-client:details onAmsTcpPacketReceived(): AMS packet received with command 0 +0ms
  ads-client:details onAdsCommandReceived(): ADS command received (command: 6) +0ms
  ads-client:details sendAdsCommand(): Response received for command "AddNotification" with invokeId 8 +0ms
  ads-client:details addSubscription(): Subscribed to 'GVL_Subscription.NumericValue_100ms' +0ms
  ads-client disconnectFromTarget(): Disconnecting (force: true) +16ms
  ads-client connectToTarget(): Connecting to target at 127.0.0.1:48898 (reconnecting: false) +1ms
  ads-client connectToTarget(): Socket connection established to 127.0.0.1:48898 +0ms
  ads-client registerAdsPort(): Registering an ADS port from target router (127.0.0.1:48898) +0ms
  ads-client:details IO out ------> 8 bytes +1ms
  ads-client:details IO in  <------ 14 bytes from 127.0.0.1 +0ms
  ads-client:details parseAmsTcpHeader(): Starting to parse AMS/TCP header +1ms
  ads-client:details parseAmsTcpHeader(): AMS/TCP header parsed: { command: 4096, commandStr: 'AMS_TCP_PORT_CONNECT', length: 8, data: <Buffer 00 00 00 00 00 00 00 00> } +0ms
  ads-client:details parseAmsHeader(): Starting to parse AMS header +0ms
  ads-client:details parseAmsHeader(): No AMS header found +0ms
  ads-client:details parseAdsResponse(): Starting to parse ADS data +0ms
  ads-client:details parseAdsData(): Packet has no ADS data +0ms
  ads-client:details onAmsTcpPacketReceived(): AMS packet received with command 4096 +0ms
  ads-client registerAdsPort(): ADS port registered, assigned AMS address is 0.0.0.0.0.0:0 +1ms
  ads-client connectToTarget(): ADS port registered. Our AMS address is 0.0.0.0.0.0:0 +0ms
  ads-client readTcSystemState(): Reading TwinCAT system state +0ms
  ads-client:details sendAdsCommand(): Sending an ads command ReadState (0 bytes): { amsTcp: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD' }, ams: { targetAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 10000 }, sourceAmsAddress: { amsNetId: '0.0.0.0.0.0', adsPort: 0 }, adsCommand: 4, adsCommandStr: 'ReadState', stateFlags: 4, stateFlagsStr: 'AdsCommand, Tcp, Request', dataLength: 0, errorCode: 0, invokeId: 9 }, ads: { payload: undefined } } +0ms
  ads-client:details createAmsHeader(): AMS header created (32 bytes) +0ms
  ads-client:details createAmsTcpHeader(): AMS/TCP header created (6 bytes) +0ms
  ads-client:details createAmsTcpRequest(): AMS/TCP request created (38 bytes) +0ms
  ads-client:details IO out ------> 38 bytes +0ms
  ads-client readTcSystemState(): Reading TwinCAT system state +752ms
  ads-client:details sendAdsCommand(): Sending an ads command ReadState (0 bytes): { amsTcp: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD' }, ams: { targetAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 10000 }, sourceAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32794 }, adsCommand: 4, adsCommandStr: 'ReadState', stateFlags: 4, stateFlagsStr: 'AdsCommand, Tcp, Request', dataLength: 0, errorCode: 0, invokeId: 16 }, ads: { payload: undefined } } +754ms
  ads-client:details createAmsHeader(): AMS header created (32 bytes) +0ms
  ads-client:details createAmsTcpHeader(): AMS/TCP header created (6 bytes) +1ms
  ads-client:details createAmsTcpRequest(): AMS/TCP request created (38 bytes) +0ms
  ads-client:details IO out ------> 38 bytes +0ms
  ads-client:details IO in  <------ 46 bytes from 127.0.0.1 +18ms
  ads-client:details parseAmsTcpHeader(): Starting to parse AMS/TCP header +1ms
  ads-client:details parseAmsTcpHeader(): AMS/TCP header parsed: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD', length: 40 } +0ms
  ads-client:details parseAmsHeader(): Starting to parse AMS header +0ms
  ads-client:details parseAmsHeader(): AMS header parsed: { targetAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32794 }, sourceAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 10000 }, adsCommand: 4, adsCommandStr: 'ReadState', stateFlags: 5, stateFlagsStr: 'Response, AdsCommand, Tcp', dataLength: 8, errorCode: 0, invokeId: 16, error: false, errorStr: '' } +0ms
  ads-client:details parseAdsResponse(): Starting to parse ADS data +0ms
  ads-client:details parseAdsResponse(): ADS data parsed: { errorCode: 0, payload: { adsState: 5, adsStateStr: 'Run', deviceState: 1 } } +0ms
  ads-client:details onAmsTcpPacketReceived(): AMS packet received with command 0 +0ms
  ads-client:details onAdsCommandReceived(): ADS command received (command: 4) +0ms
  ads-client:details sendAdsCommand(): Response received for command "ReadState" with invokeId 16 +0ms
  ads-client readTcSystemState(): TwinCAT system state read successfully. State is { adsState: 5, adsStateStr: 'Run', deviceState: 1 } +21ms
  ads-client readTcSystemState(): Reading TwinCAT system state +1s
  ads-client:details sendAdsCommand(): Sending an ads command ReadState (0 bytes): { amsTcp: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD' }, ams: { targetAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 10000 }, sourceAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32794 }, adsCommand: 4, adsCommandStr: 'ReadState', stateFlags: 4, stateFlagsStr: 'AdsCommand, Tcp, Request', dataLength: 0, errorCode: 0, invokeId: 17 }, ads: { payload: undefined } } +1s
  ads-client:details createAmsHeader(): AMS header created (32 bytes) +0ms
  ads-client:details createAmsTcpHeader(): AMS/TCP header created (6 bytes) +0ms
  ads-client:details createAmsTcpRequest(): AMS/TCP request created (38 bytes) +0ms
  ads-client:details IO out ------> 38 bytes +1ms
  ads-client:details IO in  <------ 46 bytes from 127.0.0.1 +18ms
  ads-client:details parseAmsTcpHeader(): Starting to parse AMS/TCP header +0ms
  ads-client:details parseAmsTcpHeader(): AMS/TCP header parsed: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD', length: 40 } +0ms
  ads-client:details parseAmsHeader(): Starting to parse AMS header +0ms
  ads-client:details parseAmsHeader(): AMS header parsed: { targetAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32794 }, sourceAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 10000 }, adsCommand: 4, adsCommandStr: 'ReadState', stateFlags: 5, stateFlagsStr: 'Response, AdsCommand, Tcp', dataLength: 8, errorCode: 0, invokeId: 17, error: false, errorStr: '' } +0ms
  ads-client:details parseAdsResponse(): Starting to parse ADS data +0ms
  ads-client:details parseAdsResponse(): ADS data parsed: { errorCode: 0, payload: { adsState: 5, adsStateStr: 'Run', deviceState: 1 } } +0ms
  ads-client:details onAmsTcpPacketReceived(): AMS packet received with command 0 +0ms
  ads-client:details onAdsCommandReceived(): ADS command received (command: 4) +0ms
  ads-client:details sendAdsCommand(): Response received for command "ReadState" with invokeId 17 +0ms
  ads-client readTcSystemState(): TwinCAT system state read successfully. State is { adsState: 5, adsStateStr: 'Run', deviceState: 1 } +19ms
  ads-client sendAdsCommand(): Timeout for command ReadState with invokeId 9 - No response in 2000 ms +2s
  ads-client readTcSystemState(): Reading TwinCAT system state failed: ClientError: sendAdsCommand(): Timeout for command ReadState with invokeId 9 - No response in 2000 ms at Timeout._onTimeout (/Users/christian/Code/ads-client/src/ads-client.ts:3831:25)     at listOnTimeout (node:internal/timers:614:17)     at processTimers (node:internal/timers:549:7) { trace: [ 'sendAdsCommand(): Timeout for command ReadState with invokeId 9 - No response in 2000 ms' ], adsError: { errorCode: undefined, errorStr: undefined } } +0ms
  ads-client subscribe(): Subscribing to "'GVL_Subscription.NumericValue_100ms'" +49ms
  ads-client:details addSubscription(): Subscribing { target: 'GVL_Subscription.NumericValue_100ms', callback: [AsyncFunction: callback] } (internal: false) +2s
  ads-client getSymbol(): Symbol requested for GVL_Subscription.NumericValue_100ms +0ms
  ads-client getSymbol(): Symbol found from cache for GVL_Subscription.NumericValue_100ms +0ms
  ads-client getDataType(): Data type requested for INT +0ms
  ads-client buildDataType(): Building data type for INT +0ms
  ads-client getDataTypeDeclaration(): Data type declaration requested for INT +0ms
  ads-client getDataTypeDeclaration(): Data type declaration found from cache for INT +0ms
  ads-client getDataType(): Data type read and built for INT +0ms
  ads-client:details sendAdsCommand(): Sending an ads command AddNotification (40 bytes): { amsTcp: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD' }, ams: { targetAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 851 }, sourceAmsAddress: { amsNetId: '0.0.0.0.0.0', adsPort: 0 }, adsCommand: 6, adsCommandStr: 'AddNotification', stateFlags: 4, stateFlagsStr: 'AdsCommand, Tcp, Request', dataLength: 40, errorCode: 0, invokeId: 10 }, ads: { payload: <Buffer 40 40 00 00 5c e5 05 00 02 00 00 00 04 00 00 00 00 00 00 00 80 84 1e 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00> } } +0ms
  ads-client:details createAmsHeader(): AMS header created (32 bytes) +0ms
  ads-client:details createAmsTcpHeader(): AMS/TCP header created (6 bytes) +0ms
  ads-client:details createAmsTcpRequest(): AMS/TCP request created (78 bytes) +0ms
  ads-client:details IO out ------> 78 bytes +0ms
  ads-client readTcSystemState(): Reading TwinCAT system state +1s
  ads-client:details sendAdsCommand(): Sending an ads command ReadState (0 bytes): { amsTcp: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD' }, ams: { targetAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 10000 }, sourceAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32794 }, adsCommand: 4, adsCommandStr: 'ReadState', stateFlags: 4, stateFlagsStr: 'AdsCommand, Tcp, Request', dataLength: 0, errorCode: 0, invokeId: 18 }, ads: { payload: undefined } } +1s
  ads-client:details createAmsHeader(): AMS header created (32 bytes) +0ms
  ads-client:details createAmsTcpHeader(): AMS/TCP header created (6 bytes) +0ms
  ads-client:details createAmsTcpRequest(): AMS/TCP request created (38 bytes) +0ms
  ads-client:details IO out ------> 38 bytes +0ms
  ads-client:details IO in  <------ 46 bytes from 127.0.0.1 +19ms
  ads-client:details parseAmsTcpHeader(): Starting to parse AMS/TCP header +0ms
  ads-client:details parseAmsTcpHeader(): AMS/TCP header parsed: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD', length: 40 } +0ms
  ads-client:details parseAmsHeader(): Starting to parse AMS header +0ms
  ads-client:details parseAmsHeader(): AMS header parsed: { targetAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32794 }, sourceAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 10000 }, adsCommand: 4, adsCommandStr: 'ReadState', stateFlags: 5, stateFlagsStr: 'Response, AdsCommand, Tcp', dataLength: 8, errorCode: 0, invokeId: 18, error: false, errorStr: '' } +0ms
  ads-client:details parseAdsResponse(): Starting to parse ADS data +0ms
  ads-client:details parseAdsResponse(): ADS data parsed: { errorCode: 0, payload: { adsState: 5, adsStateStr: 'Run', deviceState: 1 } } +0ms
  ads-client:details onAmsTcpPacketReceived(): AMS packet received with command 0 +0ms
  ads-client:details onAdsCommandReceived(): ADS command received (command: 4) +0ms
  ads-client:details sendAdsCommand(): Response received for command "ReadState" with invokeId 18 +0ms
  ads-client readTcSystemState(): TwinCAT system state read successfully. State is { adsState: 5, adsStateStr: 'Run', deviceState: 1 } +19ms
  ads-client readTcSystemState(): Reading TwinCAT system state +1s
  ads-client:details sendAdsCommand(): Sending an ads command ReadState (0 bytes): { amsTcp: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD' }, ams: { targetAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 10000 }, sourceAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32794 }, adsCommand: 4, adsCommandStr: 'ReadState', stateFlags: 4, stateFlagsStr: 'AdsCommand, Tcp, Request', dataLength: 0, errorCode: 0, invokeId: 19 }, ads: { payload: undefined } } +1s
  ads-client:details createAmsHeader(): AMS header created (32 bytes) +0ms
  ads-client:details createAmsTcpHeader(): AMS/TCP header created (6 bytes) +0ms
  ads-client:details createAmsTcpRequest(): AMS/TCP request created (38 bytes) +0ms
  ads-client:details IO out ------> 38 bytes +1ms
  ads-client:details IO in  <------ 46 bytes from 127.0.0.1 +18ms
  ads-client:details parseAmsTcpHeader(): Starting to parse AMS/TCP header +0ms
  ads-client:details parseAmsTcpHeader(): AMS/TCP header parsed: { command: 0, commandStr: 'AMS_TCP_PORT_AMS_CMD', length: 40 } +0ms
  ads-client:details parseAmsHeader(): Starting to parse AMS header +1ms
  ads-client:details parseAmsHeader(): AMS header parsed: { targetAmsAddress: { amsNetId: '100.117.55.75.1.1', adsPort: 32794 }, sourceAmsAddress: { amsNetId: '100.70.46.31.1.1', adsPort: 10000 }, adsCommand: 4, adsCommandStr: 'ReadState', stateFlags: 5, stateFlagsStr: 'Response, AdsCommand, Tcp', dataLength: 8, errorCode: 0, invokeId: 19, error: false, errorStr: '' } +0ms
  ads-client:details parseAdsResponse(): Starting to parse ADS data +0ms
  ads-client:details parseAdsResponse(): ADS data parsed: { errorCode: 0, payload: { adsState: 5, adsStateStr: 'Run', deviceState: 1 } } +0ms
  ads-client:details onAmsTcpPacketReceived(): AMS packet received with command 0 +0ms
  ads-client:details onAdsCommandReceived(): ADS command received (command: 4) +0ms
  ads-client:details sendAdsCommand(): Response received for command "ReadState" with invokeId 19 +0ms
  ads-client readTcSystemState(): TwinCAT system state read successfully. State is { adsState: 5, adsStateStr: 'Run', deviceState: 1 } +21ms
  ads-client sendAdsCommand(): Timeout for command AddNotification with invokeId 10 - No response in 2000 ms +2s
  ads-client addSubscription(): Subscribing to 'GVL_Subscription.NumericValue_100ms' failed: ClientError: sendAdsCommand(): Timeout for command AddNotification with invokeId 10 - No response in 2000 ms at Timeout._onTimeout (/Users/christian/Code/ads-client/src/ads-client.ts:3831:25)     at listOnTimeout (node:internal/timers:614:17)     at processTimers (node:internal/timers:549:7) { trace: [ 'sendAdsCommand(): Timeout for command AddNotification with invokeId 10 - No response in 2000 ms' ], adsError: { errorCode: undefined, errorStr: undefined } } +1ms
  ads-client disconnectFromTarget(): Disconnecting (force: false) +7ms
  ads-client removeSubscriptions(): Unsubscribing from all active subscriptions (also internals: true) +0ms
  ads-client removeSubscriptions(): Unsubscribed from all 0 subscriptions successfully +0ms
  ads-client:details unregisterAdsPort(): Unregistering ADS port 0 from target 127.0.0.1:48898 +2s
  ads-client disconnectFromTarget(): Connection closed successfully +2ms
 FAIL  test/TC3/ads-client.test.js (5.643 s)
  ✓ IMPORTANT NOTE: This test requires running a specific TwinCAT 3 PLC project (https://github.com/jisotalo/ads-client-test-plc-project) (1 ms)
  connection
    ✓ client is not connected at beginning
    ✓ checking ads client settings
    ✓ connecting to the target (115 ms)
  resetting PLC to original state
    ✓ resetting PLC (554 ms)
    ✓ starting PLC (59 ms)
    ✓ checking that test PLC project is running (563 ms)
  handling unknown/stale ADS notifications
    ✓ connecting (108 ms)
    ✕ creating an unknown notification handle by forced disconnecting (2104 ms)
    ✕ deleting an unknown notification handle automatically (2008 ms)
    ✓ disconnecting (2 ms)

  ● handling unknown/stale ADS notifications › creating an unknown notification handle by forced disconnecting

    ClientError: connectToTarget(): Connection failed - failed to set PLC connection. If target is not PLC runtime, use setting "rawClient". If system is in config mode or there is no PLC software yet, you might want to use setting "allowHalfOpen". Error: readTcSystemState(): Reading TwinCAT system state failed

      564 |           } catch (err) {
      565 |             if (!this.settings.allowHalfOpen) {
    > 566 |               return reject(new ClientError(`connectToTarget(): Connection failed - failed to set PLC connection. If target is not PLC runtime, use setting "rawClient". If system is in config mode or there is no PLC software yet, you might want to use setting "allowHalfOpen". Error: ${(err as ClientError).message}`, err));
          |                             ^
      567 |             }
      568 |
      569 |             //allowHalfOpen allows this, but show some warnings..

      at Socket.<anonymous> (src/ads-client.ts:566:29)
      ClientError: readTcSystemState(): Reading TwinCAT system state failed
      at Client.readTcSystemState (src/ads-client.ts:4567:13)
      at Client.setupPlcConnection (src/ads-client.ts:966:5)
      at Socket.<anonymous> (src/ads-client.ts:563:13)
      ClientError: sendAdsCommand(): Timeout for command ReadState with invokeId 9 - No response in 2000 ms
      at Timeout._onTimeout (src/ads-client.ts:3831:25)

  ● handling unknown/stale ADS notifications › deleting an unknown notification handle automatically

    ClientError: addSubscription(): Subscribing to "GVL_Subscription.NumericValue_100ms" failed

      2150 |     } catch (err) {
      2151 |       this.debug(`addSubscription(): Subscribing to %o failed: %o`, settings.target, err);
    > 2152 |       throw new ClientError(`addSubscription(): Subscribing to ${JSON.stringify(settings.target)} failed`, err);
           |             ^
      2153 |     }
      2154 |   }
      2155 |

      at Client.addSubscription (src/ads-client.ts:2152:13)
      at Object.<anonymous> (test/TC3/ads-client.test.js:227:20)
      ClientError: sendAdsCommand(): Timeout for command AddNotification with invokeId 10 - No response in 2000 ms
      at Timeout._onTimeout (src/ads-client.ts:3831:25)

Test Suites: 1 failed, 1 total
Tests:       2 failed, 9 passed, 11 total
Snapshots:   0 total
Time:        5.656 s, estimated 6 s
Ran all test suites matching /TC3\/ads-client.test.js/i.

[jisotalo]

Hmm, this is a strange issue.

Perhaps it's because of the AdsRouterConsole. Maybe the forced disconnect and then reconnecting again is not working well with it.

The test is currently also doing the reconnect immediately:

 // Forcefully disconnect, without unsubscribing
await client2.disconnect(true);
await client2.connect();

See +1ms:

ads-client disconnectFromTarget(): Disconnecting (force: true) +16ms
ads-client connectToTarget(): Connecting to target at 127.0.0.1:48898 (reconnecting: false) +1ms

That could one option as well. We could try to wait ~1s to see if it helps with

await client2.disconnect(true);
await delay(1000);
await client2.connect();

I need to setup the AdsRouterConsole to test this out.

[jisotalo]

I configured AdsRouterConsole and managed to reproduce the same error. So it's definetely related to the router implementation. I'm used PC<->PC connection instead of Mac.

Delay isn't helping either.

If changing the ADS port in between, the connection works. However the tests obviously not, but this tells us that the router doesn't like using the same port immediately again

await client2.disconnect(true);
client2.settings.localAdsPort = 33000;
await client2.connect();

By looking at the router debug data, we can see the port is still reserved. We probably need to double check if ads-client could handle that PortAlreadyInUse. That won't fix the test either.

warn: TwinCAT.Ads.AdsRouterService.RouterService[0]
      Port '32758' is already in use. Returning Error Code 'PortAlreadyInUse'

To be continued..

[jisotalo]

This might be related to:

• With AdsRouterConsole, connection fails on first attempt #167
• Timing/order issue with multiple clients connecting to different ADS ports Beckhoff/TF6000_ADS_DOTNET_V5_Samples#62

[jisotalo]

I tested with the updated Beckhoff.TwinCAT.Ads.TcpRouter and the issue persists.

Maybe we are just doing things that shouldn't be done. However that test is quite good.

I'm open to any ideas