Question: node-driver use to work with a callback in the readTag call. Is this not possible any more?

[gman8a]

Justin,

Questions
"node-drivers" use to work with a callback in the read Tag call.
Is this not possible any more?
I am not sure what "await" does. Does the node executive loop process other functions while waiting ?

  Also, can "node-drivers" talk to a A/B Compact-Logix or Control-Logix PLC ?
   If so, I see no examples of this. Seem like all the necessary low level code is in place for this.

[jmmoser]

Can you share the error you receive when you try to use a callback? You should be able to do something like this without issue:

logix5000.readTag('tagname', function(res) {

});

Async/await is syntax for writing asynchronous JavaScript and is built on top of promises. Here are a few links that cover async/await:

• https://developer.mozilla.org/en-US/docs/Learn/JavaScript/Asynchronous/Async_await
• https://javascript.info/async-await
• https://www.digitalocean.com/community/tutorials/js-async-functions

The node executive loop (event loop) is single threaded and will only process one function at a time, however, I/O runs on separate threads. This means you can run one asynchronous function, then run another ansynchronous function, then wait for both of them to finish. See the code example below:

/**
 * test1 requests the value of tag1 and waits for the response,
 * then requests the value of tag2 and waits for the response
 */
async function test1() {
	const promise1 = logix5000.readTag('tag1');
	const value1 = await promise1;

	const promise2 = logix5000.readTag('tag2');  
	const value2 = await promise2;
}

/**
 * test2 requests the value of tag1, then requests the value of tag2,
 * then waits for the response of tag1, then waits for the response of tag2.
 * This may execute faster than test1 because while it is waiting for tag1's response, tag2's
 * value has already been requested.  It doesn't wait for tag1's response before requesting tag1's value.
 */
async function test2() {
	  const promise1 = logix5000.readTag('tag1');
	  const promise2 = logix5000.readTag('tag2');
	  
	  const value1 = await promise1;
	  const value2 = await promise2;
}

Use the Logix5000 layer on top of the TCP layer to communicate with Control-Logix and Compact-Logix PLCs. The code example is here. The documentation I followed for developing the Logix5000 layer is here.

[gman8a]

I figured it out.
Promises are new to me.

Here is what I wrote

~/wic/plc2$ cat p2.js

//---------------code---------------------
const { TCP, CIP } = require('node-drivers');
const tcpLayer = new TCP('192.168.100.174');

// with eip layer
// const eipLayer = new CIP.EIP(tcpLayer);
// const logix5000 = new CIP.Logix5000(eipLayer);

// w/o eip layer
const cipLayer = new CIP(tcpLayer);
const logix5000 = new CIP.Logix5000(tcpLayer);

console.log( new Date() )
logix5000.readTag('HMI_CC03_FULL[0]').then( (result) => {
console.log(new Date())
console.log(result);

}).catch( (error) => {
	console.log(error);

});
//----------end code ----------------

/*---output
X_Rcv:~/wic/plc2$ node p1.js
2021-10-15T17:28:50.063Z
2021-10-15T17:28:50.167Z
1344

My comment: Is very slow, taking ~ 104ms

vs. another method:

X_Rcv:~/wic/plc2$ echo "mread,0,hmi_cc03_jam[0]/hmi_cc03_full[0];"|nc localhost 9000

0:ok/13ms,MREAD,0,DINT:hmi_cc03_jam[0]=0/DINT:hmi_cc03_full[0]=1344;
^^
## 13ms

Q: Did you ever test speed of callbacks vs promises ?

*/

[jmmoser]

@gman8a Your second example doesn't test the speed of using callbacks in this package and instead appears to be using using a different program. Can you try running the following code? This code first reads the tag using a promise and then reads the same tag using a callback. This still may not be a fair test because there might be some setup happening for the first read that the second read is able to take advantage of.

const { TCP, CIP } = require('node-drivers');

const tcpLayer = new TCP('192.168.100.174');
const logix5000 = new CIP.Logix5000(tcpLayer);

const promiseStart = Date.now();
logix5000.readTag('HMI_CC03_FULL[0]').then(() => {
	const promiseEnd = Date.now();
	console.log('Time elapsed for promise:', promiseEnd - promiseStart);

	const callbackStart = Date.now();
	logix5000.readTag('HMI_CC03_FULL[0]', (err, result) => {
		const callbackEnd = Date.now();
		if (err) {
			console.log('Error reading tag using callback', err);
		} else {
			console.log('Time elapsed for callback:', callbackEnd - callbackStart);
		}
		
		tcpLayer.close();
	});
}).catch((err) => {
	console.log('Error reading tag using promise', err);
	tcpLayer.close();
});

[gman8a]

// output of your test program request:

_Rcv:/wic/plc2$ vim p1.js
_Rcv:/wic/plc2$ node p1.js
2021-10-15T18:18:10.022Z
Time elapsed for promise: 76
Time elapsed for callback: 4
InfoError: Close
at Object.reject (/mnt/WIC/wic_handcraft2/plc2/node_modules/node-drivers/src/utils.js:131:19)
at /mnt/WIC/wic_handcraft2/plc2/node_modules/node-drivers/src/layers/cip/layers/internal/CIPInternalLayer.js:42:22
at /mnt/WIC/wic_handcraft2/plc2/node_modules/node-drivers/src/layers/Layer.js:275:43
at Map.forEach ()
at internalDestroy (/mnt/WIC/wic_handcraft2/plc2/node_modules/node-drivers/src/layers/Layer.js:275:29)
at /mnt/WIC/wic_handcraft2/plc2/node_modules/node-drivers/src/layers/Layer.js:105:7
at processTicksAndRejections (internal/process/task_queues.js:93:5)
at async /mnt/WIC/wic_handcraft2/plc2/node_modules/node-drivers/src/utils.js:157:14 {
info: undefined
}
HMI_CC03_FULL[0]
InfoError: Close
at Object.reject (/mnt/WIC/wic_handcraft2/plc2/node_modules/node-drivers/src/utils.js:131:19)
at /mnt/WIC/wic_handcraft2/plc2/node_modules/node-drivers/src/layers/cip/layers/Logix5000/index.js:206:20
at send (/mnt/WIC/wic_handcraft2/plc2/node_modules/node-drivers/src/layers/cip/layers/Logix5000/index.js:1000:5)
at processTicksAndRejections (internal/process/task_queues.js:93:5) {
info: undefined
}

[gman8a]

So... What is the best code to get minimum overall time from application call to return value into application ?

[gman8a]

I guess it it this, as programmed in your example to me.

const callbackStart = Date.now();
logix5000.readTag('HMI_CC03_FULL[0]', (err, result) => {
const callbackEnd = Date.now();
if (err) {
console.log('Error reading tag using promise', err);
} else {
console.log('Time elapsed for callback:', callbackEnd - callbackStart);
}

	tcpLayer.close();
});

[jmmoser]

Interesting! Try running this as well and let me know the results:

const { TCP, CIP } = require('node-drivers');

const tcpLayer = new TCP('192.168.100.174');
const logix5000 = new CIP.Logix5000(tcpLayer);

const callbackStart = Date.now();
logix5000.readTag('HMI_CC03_FULL[0]', (err, result1) => {
    const callbackEnd = Date.now();
    if (err) {
        console.log('Error reading tag using callback', err);
    } else {
        console.log('Time elapsed for callback:', callbackEnd - callbackStart);
		console.log(result1);
    }

    const promiseStart = Date.now();
    logix5000.readTag('HMI_CC03_FULL[0]').then((result2) => {
        const promiseEnd = Date.now();
        console.log('Time elapsed for promise:', promiseEnd - promiseStart);
		console.log(result2);
    }).catch((err) => {
        console.log('Error reading tag using promise', err);
    }).finally(() => {
        tcpLayer.close();
    });
});

[gman8a]

HMI_CC03_FULL[0]
cnt: 7 Error reading tag using promise InfoError: connection.cip error: ConnectionFailure, Connection in use or duplicate forward open
at Object.reject (/mnt/WIC/wic_handcraft2/plc2/node_modules/node-drivers/src/utils.js:131:19)
at /mnt/WIC/wic_handcraft2/plc2/node_modules/node-drivers/src/layers/cip/layers/Logix5000/index.js:206:20
at send (/mnt/WIC/wic_handcraft2/plc2/node_modules/node-drivers/src/layers/cip/layers/Logix5000/index.js:1000:5)
at processTicksAndRejections (internal/process/task_queues.js:93:5) {
info: undefined
}
InfoError: connection.cip error: ConnectionFailure, Connection in use or duplicate forward open
at Object.reject (/mnt/WIC/wic_handcraft2/plc2/node_modules/node-drivers/src/utils.js:131:19)
at /mnt/WIC/wic_handcraft2/plc2/node_modules/node-drivers/src/layers/cip/layers/internal/CIPInternalLayer.js:42:22
at /mnt/WIC/wic_handcraft2/plc2/node_modules/node-drivers/src/layers/Layer.js:275:43
at Map.forEach ()
at internalDestroy (/mnt/WIC/wic_handcraft2/plc2/node_modules/node-drivers/src/layers/Layer.js:275:29)
at Logix5000.destroy (/mnt/WIC/wic_handcraft2/plc2/node_modules/node-drivers/src/layers/Layer.js:117:5)
at CIPConnectionLayer.destroy (/mnt/WIC/wic_handcraft2/plc2/node_modules/node-drivers/src/layers/Layer.js:114:23)
at /mnt/WIC/wic_handcraft2/plc2/node_modules/node-drivers/src/layers/cip/layers/internal/CIPConnectionLayer.js:575:18
at handleUnconnectedMessage (/mnt/WIC/wic_handcraft2/plc2/node_modules/node-drivers/src/layers/cip/layers/internal/CIPConnectionLayer.js:225:7)
at CIPConnectionLayer.handleData (/mnt/WIC/wic_handcraft2/plc2/node_modules/node-drivers/src/layers/cip/layers/internal/CIPConnectionLayer.js:143:7) {
info: undefined
}
HMI_CC03_FULL[0]
cnt: 8 Error reading tag using promise InfoError: connection.cip error: ConnectionFailure, Connection in use or duplicate forward open
at Object.reject (/mnt/WIC/wic_handcraft2/plc2/node_modules/node-drivers/src/utils.js:131:19)
at /mnt/WIC/wic_handcraft2/plc2/node_modules/node-drivers/src/layers/cip/layers/Logix5000/index.js:206:20
at send (/mnt/WIC/wic_handcraft2/plc2/node_modules/node-drivers/src/layers/cip/layers/Logix5000/index.js:1000:5)
at processTicksAndRejections (internal/process/task_queues.js:93:5) {
info: undefined
}

^^^^^^^^^^^^^ERROR FROMP REVIOUS RUN ABOVE ^^^^^^^^^^^

Rcv:~/wic/plc2$ node p1.js
here 1
here 2
here 3
here 4
here 5
here 6
here 7
here 8
cnt: 2 Time elapsed for callback: 86
cnt: 3 Time elapsed for callback: 91
cnt: 4 Time elapsed for callback: 93
cnt: 5 Time elapsed for callback: 96
cnt: 6 Time elapsed for callback: 99
cnt: 7 Time elapsed for callback: 101
cnt: 8 Time elapsed for callback: 103

-------------CODE---------------------
function f1(cnt){
let callbackStart = Date.now();
console.log('here ', cnt);

	logix5000.readTag('HMI_CC03_FULL[0]', (err, result) => {

		let callbackEnd = Date.now();

			if (err) {
					console.log('cnt:', cnt,'  Error reading tag using promise', err);
			} else {
					
					console.log('cnt:', cnt, '  Time elapsed for callback:', callbackEnd - callbackStart);
			}
				
	});

}//fn

f1(1)
f1(2);
f1(3);
f1(4);
f1(5);
f1(6);
f1(7);
f1(8);

setTimeout( ()=>{

logix5000.close();
cipLayer.close();
tcpLayer.close(); 


process.exit(); 

}, 3000);

-----------END CODE------------------------

[gman8a]

result of your last execution request

Rcv:~/wic/plc2$ node p3.js
Time elapsed for callback: 85
1344
Time elapsed for promise: 6
1344

[jmmoser]

Based on the first test and the second test, the speeds of using callbacks and promises are identical. The reason the first read is slow in both tests is the stack has to establish the TCP connection, then the EIP connection, then the CIP connection, and then it executes the CIP read request. The second read uses the existing TCP/EIP/CIP connections and simply executes the read request.

[gman8a]

...well in my last test w/ consecutive f1() calls, the elapsed times were around 100ms.
what up here.

[jmmoser]

In your consecutive f1() test, you aren't really reading the tag 8 times consecutively. You are really queuing 8 requests to read the tag. f1(2) runs before f1(1) finishes hence why you see all of the logs stating here 1 here 2 here 3... first before you see cnt: 1 Time elapsed for callback: ##....

To make your test read the tags consecutively, do this instead:

function f1(cnt, cb) {
    let callbackStart = Date.now();
    console.log('here ', cnt);

    logix5000.readTag('HMI_CC03_FULL[0]', (err, result) => {

        let callbackEnd = Date.now();

        if (err) {
            console.log('cnt:', cnt, '  Error reading tag using promise', err);
        } else {

            console.log('cnt:', cnt, '  Time elapsed for callback:', callbackEnd - callbackStart);
        }

        if (typeof cb === 'function') cb();
    });
}//fn

/** call f1(1) first */
f1(1, () => {
    /** call f1(2) after f1(1) finishes */
    f1(2, () => {
        /** call f1(3) after f1(2) finishes */
        f1(3, () => {
            /** etc... */
            f1(4, () => {
                f1(5, () => {
                    f1(6, () => {
                        f1(7, () => {
                            f1(8);
                        });
                    });
                });
            });
        });
    });
});

setTimeout(() => {

    logix5000.close();
    cipLayer.close();
    tcpLayer.close();


    process.exit();

}, 3000);

I expect you will see the following:

here 1
Time elapsed for callback: 75 (approximately)
here 2
Time elapsed for callback: 6 (approximately)
here 3
Time elapsed for callback: 4 (approximately)
here 4
Time elapsed for callback: 5 (approximately)
...
here 8
Time elapsed for callback: 5 (approximately)

The first request takes the most time because the stack has to establish the connection to the PLC and then all the remaining requests take a short amount of time.

You should also notice one of the drawbacks of using callbacks in the code above which some people refer to as "callback hell"! With async/await you could rewrite the code above as:

async function f1(cnt) {
    let callbackStart = Date.now();
    console.log('here ', cnt);

    try {
        await logix5000.readTag('HMI_CC03_FULL[0]');
        let callbackEnd = Date.now();
        console.log('cnt:', cnt, '  Time elapsed for callback:', callbackEnd - callbackStart);
    } catch (err) {
        console.log('cnt:', cnt, '  Error reading tag using promise', err);
    }
}//fn


(async () => {
    /** call f1(1) first */
    await f1(1);
    /** call f1(2) after f1(1) finishes */
    await f1(2);
    /** call f1(3) after f1(2) finishes */
    await f1(3);
    /** etc... */
    await f1(4);
    await f1(5);
    await f1(6);
    await f1(7);
    await f1(8);
})();

setTimeout(() => {

    logix5000.close();
    cipLayer.close();
    tcpLayer.close();


    process.exit();

}, 3000);

[gman8a]

///output of your last program request follows

_Rcv:~/wic/plc2$ node p4.js
here 1
cnt: 1 Time elapsed for callback: 99
here 2
cnt: 2 Time elapsed for callback: 6
here 3
cnt: 3 Time elapsed for callback: 4
here 4
cnt: 4 Time elapsed for callback: 4
here 5
cnt: 5 Time elapsed for callback: 4
here 6
cnt: 6 Time elapsed for callback: 4
here 7
cnt: 7 Time elapsed for callback: 4
here 8
cnt: 8 Time elapsed for callback: 4

/plc2/p4.js:49
cipLayer.close();
^

ReferenceError: cipLayer is not defined
at Timeout._onTimeout (/mnt/WIC/wic_handcraft2/plc2/p4.js:49:5)
at listOnTimeout (internal/timers.js:554:17)
at processTimers (internal/timers.js:497:7)

[jmmoser]

Perfect! Does it make sense now?

[gman8a]

...more than it did when i started.

..however my application looks like this:
//////////////////////////
function readmytag(tagname, (result) => {

          ..
          ..
          ...
         plc_result_data_handler(result);

});

readmytag('HMI_CC03_FULL[0]');

//////////////////////

The time from the app call to the handler should be 5ms.
Please code this for me !!