Moving from NodeJs from 0.12 to 8.9.3 - UDF issue

Client Libraries Node.js Client
1

Hi,

We are using Aerospike for our project and using the Node J client. We are using a UDF for our purpose. We are using the old version of Nodejs and aerospike. Now we are moving to newer versions. Below are the version details:

Component Old version New Version Ubuntu 14.04 16.04 NodeJs 0.12.15 8.9.3 Aerospike 3.7.4 3.15.0.2 Aerospike NodeJs Client 1.0.31 3.0.2

We are facing the difficult in running the UDF on the Node JS in the new version. The UDF is running fine on the AQL console, but is failing on the NodeJS. We are able to run the select, query and all the Aerospike features. Just UDFs are failing. Here is the sample code:

We have referred to the example here:

https://github.com/aerospike/aerospike-client-nodejs/blob/master/examples/query_aggregate.js

I am getting the following error:

err: { AerospikeError: UDF: Execution Error 1 at Function.AerospikeError.fromASError (/mnt/canvas/app/releases/canvasproject/canvas.services/node_modules/aerospike/lib/error.js:133:12) at Command.convertError (/mnt/canvas/app/releases/canvasproject/canvas.services/node_modules/aerospike/lib/commands/command.js:42:27) at Command.convertResponse (/mnt/canvas/app/releases/canvasproject/canvas.services/node_modules/aerospike/lib/commands/command.js:50:22) at asCallback (/mnt/canvas/app/releases/canvasproject/canvas.services/node_modules/aerospike/lib/commands/command.js:102:22) message: ‘UDF: Execution Error 1’, code: 100, func: ‘as_query_aggregate’, file: ‘src/main/aerospike/aerospike_query.c’, line: 959 }

I saw the discussion as: AerospikeError: UDF: Execution Error 1 and checked the system path as

“my-nodejs-app-path/node_modules/aerospike/modules/lua-core/src”

Also, I saw in the documentation that we need to register the UDF. Do we really need to register the UDF, as we have registered the UDF using the AQL console. Actually, I have tried registering the UDF on client connect event, but still it did not work.

Could you please help me out?

2

Can somebody please help with this issue?

3

Moved this topic to ‘Node.js’ so that it can be picked up developers monitoring that channel.

4

I saw the discussion as: AerospikeError: UDF: Execution Error 1 1 and checked the system path as /node_modules/aerospike/modules/lua-core/src

Do you set the mod-lua system path explicitly or do you rely on the default path that is set in lib/config.js:

defaultLuaSystemPath () {
    return path.resolve(__dirname, '..', 'modules', 'lua-core', 'src')
}

The path you gave above is an absolute path (i.e. it begins with “/”). Is that the actual path that is being used?

Also, I saw in the documentation that we need to register the UDF. Do we really need to register the UDF, as we have registered the UDF using the AQL console.

If you have already registered the UDF using aql, then you do not need to register it again using the Node.js client.

5

Hi Jan,

Thankyou for your response. I did not set the path. It is the default path, which is:

“my-nodejs-app-path/node_modules/aerospike/modules/lua-core/src”

I have corrected it in the original post as well.

6

There are at least two different error cases, in which the client will return “UDF: Execution Error 1”. (There might be more, that I’m not aware of.)

  1. The client cannot find the mod-lua system files, e.g. if the systemPath setting is not configured correctly. In your case it’s set to the default so presumably that’s not the issue; but can you please double-check that that path you gave does indeed have an aerospike.lua file.

  2. The UDF module you used in the query is not registered on the server. Can you please run an ‘udf-list’ info query using the Node.js client and check that the server’s response includes the module you are using, e.g. by running

const Aerospike = require('aerospike')
Aerospike.connect().then(async client => {
  let info = await client.infoAny('udf-list')
  console.info(info)
  client.close()
})

You should get something like this:

udf-list	filename=test.lua,hash=c96771bd8ce6911a22a592e4857fd47082f14990,type=LUA;

Note that when you are calling query.apply() you need to omit the .lua prefix and just pass test as the UDF module name.

7

Hi Jan, Thankyou for your response.

  1. Yes, i can see the aerospike.lua file in the “my-nodejs-app-path/node_modules/aerospike/modules/lua-core/src” directory
  2. This is what I see in the console log: filename=canvassearch.lua,hash=3cd8dc0d3aeba0f3375b463ce8d62568b7aad1c6,type=LUA; and we are trying to use UDF canvassearch only (without .lua)

Still not working…

8

Anything in the server logs?

Maybe if you increase the log level for the udf subsystem? E.g. in aerospike.conf:

logging {
  file /var/log/aerospike.log {
    context any info
    context udf debug # <== Add this
  }
}
9

Hi Jan, Thankyou for your reply. I have checked the error log file. This is the error I see in the log file:

Apr 22 2018 16:54:48 GMT: WARNING (udf): (src/main/mod_lua.c:802) Lua Runtime Error: /opt/aerospike/usr/udf/lua/canvassearch.lua:44: bad argument #1 to ‘lower’ (string expected, got nil)

Looks like the parameters for the UDF are not getting sent to the UDF. In our old implementation we did this:

var query = function(dbName, setName, statement, cb) { var statement = { filters: [Search.filter(‘indexed’, 1)] }; statement.aggregationUDF = { module: ‘canvassearch’, funcname: ‘search’, args: [search_query, search_context, user_context] //search_query, search_context, user_context are the parameters to the UDF }; var qry = this.client.query(dbName, setName, statement);

var stream = qry.execute();
var res = [];
stream.on('data', function(rec) {
    res.push(rec.bins ? rec.bins : rec);
});
stream.on('error', function(err) {
    logger.error('Error while streaming data from Aerospike', dbName, setName, statement, err);
    return cb(err);
});
stream.on('end', function(end) {
    return cb(null, res);
});

}

So, right now, we are not able to pass the parameters to the UDF from nodejs client. Can you let us know how to do that?

10

I saw another piece of code as follows on the link https://www.aerospike.com/docs/client/nodejs/usage/query/aggregate.html:

client.apply('example', 'count', function (error, result) {
  if (!error) {
    console.log(result)
  }
})

Not sure how to pass the UDF arguments.

11

You need to pass the arguments to Query#apply:

apply(udfModule, udfFunction [, udfArgs] [, policy] [, callback])

udfArgs needs to be an array even if you are passing only a single argument. In your case it might look something like this:

const query = client.query(dbName, setName)
query.apply('canvassearch', 'search', [search_query, search_context, user_context])
    .then(result => console.info('Aggregation result:', result))
    .catch(error => console.error('Error while aggregating data from Aerospike:' error)

The examples unfortunately don’t cover this use-case well, but there is (now) a test case that does:

12

Hi Jan, Thankyou for your response. This is what I tried:

Aerospike.prototype.queryUdf = function(dbName, setName, statement, cb) {
  console.log("result: ",result);
  var options = {
    filters: statement.filters
  }

  var query = client.query(dbName,setName,options);
  console.log("options.filters: ", options.filters);
  console.log("query: ", query);
  
  console.log("statement.aggregationUDF.module: ", statement.aggregationUDF.module);
  console.log("statement.aggregationUDF.funcname: ", statement.aggregationUDF.funcname);
  console.log("statement.aggregationUDF.args: ",statement.aggregationUDF.args);
  
  query.apply(statement.aggregationUDF.module, statement.aggregationUDF.funcname,statement.aggregationUDF.args)
  .then(result => {
    console.log("On query apply complete");    
    cb(null,res);
  })
  .catch(error => {
    console.log("error: ", error);
      cb(error);
  });
}

But still getting the error. Getting the following output:

Inside queryUdf
statement.aggregationUDF.module:  canvassearch
statement.aggregationUDF.funcname:  search
statement.aggregationUDF.args:  [ 'jamesroy', 'all', 'all' ]
Apr 24 2018 16:56:34 GMT: INFO (8926) [query_apply.cc:103] [respond] - Command failed: 100 UDF: Execution Error 1

error:  { AerospikeError: UDF: Execution Error 1
    at Function.AerospikeError.fromASError (/mnt/canvas/app/releases/canvasproject/canvas.services/node_modules/aerospike/lib/error.js:133:12)
    at Command.convertError (/mnt/canvas/app/releases/canvasproject/canvas.services/node_modules/aerospike/lib/commands/command.js:42:27)
    at Command.convertResponse (/mnt/canvas/app/releases/canvasproject/canvas.services/node_modules/aerospike/lib/commands/command.js:50:22)
    at asCallback (/mnt/canvas/app/releases/canvasproject/canvas.services/node_modules/aerospike/lib/commands/command.js:102:22)
  message: 'UDF: Execution Error 1',
  code: 100,
  func: 'as_query_aggregate',
  file: 'src/main/aerospike/aerospike_query.c',
  line: 959 }
13

Your code looks correct.

What puzzles me a bit at the moment, is that you report seeing a Lua Runtime Error in the server logs, but on the client side you get “AerospikeError: UDF: Execution Error 1”. When I try to replicate this issue by triggering a Lua Runtime Error, I am getting a different error message on the client side:

Server log:

Apr 25 2018 02:25:26 GMT: WARNING (udf): (src/main/mod_lua.c:797) Lua Runtime Error: /home/vagrant/as1/var/udf/lua/udf.lua:41: attempt to compare number with nil

Corresponding client error message:

Uncaught AerospikeError: UDF: Execution Error 2 : /home/vagrant/as1/var/udf/lua/udf.lua:41: attempt to compare number with nil

As you can see, the client error and server error match. I am not sure why you are getting a different error on the client side.

Can you add some logging to your Lua function, to print out the exact parameter values it receives? You can find some tips on how to do that in our Lua UDF - Best Bractices development guide. Maybe you could also post the relevant parts of your “search” function that lead to the “bad argument” runtime error?

Also, is there a specific reason why you are using Node.js client version 3.0.2 rather than the latest version 3.2.0?

14

Hi Jan,

I tried putting the trace and debug statements in my UDF like this:

trace('InsideCanvasSearchTrace')
debug('InsideCanvasSearchDebug')

and re-registered the udf with these 2 commands in AQL:

remove module canvassearch.lua
register module 'canvassearch.lua'

The UDF got registered and I have the updated the logging in my /etc/aerospike/aerospike.conf file like this:

logging {
        console {
                context any info
                #context udf debug
        }
        file /var/log/aerospike.log {
        #       #context any info
                context udf debug # <== Add this
        }
}

I see the /var/log/aerospike.log is growing too large ~1GB. I deleted it multiple times, but it getting large very fast. But I don’t see the trace or the debug messages in that file. Am I doing something wrong?

Also, after making the update w.r.t. parameter passing, i am not getting the parameter value nil error now. As I looked at the aerospike.log file, I see the following logging w.r.t canvassearch.lua:

Apr 26 2018 14:58:01 GMT: DEBUG (udf): (udf_cask.c:674) pushing to canvassearch.lua, 5466 bytes [local function get_canvases(record)^M
        --return map {canvasauthor=record.canvasauthor,title=record.canvastitle,postauthor=record.postauthor,posttext=record.posttext}^M
        return map {recordkey=record.recordkey,^M
        userhandle=record.userhandle,^M
        username=record.username,^M
        userprivacy=record.userprivacy,^M
        profilephoto=record.profilephoto,^M
        canvasid=record.canvasid,^M
        canvastitle=record.canvastitle,^M
        canvasowner=record.canvasowner,^M
        postcount=record.postcount,^M
        canvasphoto=record.canvasphoto,^M
        canvasdate=record.canvasdate,^M
        canvasprivacy=record.canvasprivacy,^M
        posttext=record.posttext,^M
        postowner=record.postowner,^M
        postdate=record.postdate,^M
        postembedtitle=record.postembedtitle,^M
        postembeddesc=record.postembeddesc,^M
        postphoto=record.postphoto,^M
        matchtype=record.type,^M
        useridmanik='useridmanik'^M
        }^M
        -- Bins of the searchflat table :^M
        --canvasid,canvastitle,canvasowner,postid,posttext,postowner,userhan^@
Apr 26 2018 14:58:01 GMT: DEBUG (udf): (src/main/mod_lua.c:604) Size of the lua state created for the file canvassearch in KB 65
Apr 26 2018 14:58:01 GMT: DEBUG (udf): (src/main/mod_lua.c:604) Size of the lua state created for the file canvassearch in KB 65
Apr 26 2018 14:58:01 GMT: DEBUG (udf): (src/main/mod_lua.c:604) Size of the lua state created for the file canvassearch in KB 65
Apr 26 2018 14:58:01 GMT: DEBUG (udf): (src/main/mod_lua.c:604) Size of the lua state created for the file canvassearch in KB 65
Apr 26 2018 14:58:01 GMT: DEBUG (udf): (src/main/mod_lua.c:604) Size of the lua state created for the file canvassearch in KB 65
Apr 26 2018 14:58:01 GMT: DEBUG (udf): (src/main/mod_lua.c:604) Size of the lua state created for the file canvassearch in KB 65
Apr 26 2018 14:58:01 GMT: DEBUG (udf): (src/main/mod_lua.c:604) Size of the lua state created for the file canvassearch in KB 65

Apr 26 2018 15:05:32 GMT: DEBUG (udf): (udf_cask.c:222) UDF metadata item[5]: module "UDF" ; key "canvassearch.lua" ; value "{"content64": "bG9jYWwgZnVuY3Rpb24gZ2V0X2NhbnZhc2VzKHJlY29yZCkNCgktLXJldHVybiBtYXAge2NhbnZhc2F1dGhvcj1yZWNvcmQuY2FudmFzYXV0aG9yLHRpdGxlPXJlY29yZC5jYW52YXN0aXRsZSxwb3N0YXV0aG9yPXJlY29yZC5wb3N0YXV0aG9yLHBvc3R0ZXh0PXJlY29yZC5wb3N0dGV4dH0NCglyZXR1cm4gbWFwIHtyZWNvcmRrZXk9cmVjb3JkLnJlY29yZGtleSwNCgl1c2VyaGFuZGxlPXJlY29yZC51c2VyaGFuZGxlLA0KCXVzZXJuYW1lPXJlY29yZC51c2VybmFtZSwNCgl1c2VycHJpdmFjeT1yZWNvcmQudXNlcnByaXZhY3ksDQoJcHJvZmlsZXBob3RvPXJlY29yZC5wcm9maWxlcGhvdG8sDQoJY2FudmFzaWQ9cmVjb3JkLmNhbnZhc2lkLA0KCWNhbnZhc3RpdGxlPXJlY29yZC5jYW52YXN0aXRsZSwNCgljYW52YXNvd25lcj1yZWNvcmQuY2FudmFzb3duZXIsDQoJcG9zdGNvdW50PXJlY29yZC5wb3N0Y291bnQsDQoJY2FudmFzcGhvdG89cmVjb3JkLmNhbnZhc3Bob3RvLA0KCWNhbnZhc2RhdGU9cmVjb3JkLmNhbnZhc2RhdGUsDQoJY2FudmFzcHJpdmFjeT1yZWNvcmQuY2FudmFzcHJpdmFjeSwNCglwb3N0dGV4dD1yZWNvcmQucG9zdHRleHQsDQoJcG9zdG93bmVyPXJlY29yZC5wb3N0b3duZXIsDQoJcG9zdGRhdGU9cmVjb3JkLnBvc3RkYXRlLA0KCXBvc3Rl

15

What’s filling up the logs so fast? UDF debug messages? Are you running this on a production server or some test/dev environment?

Are you seeing any other errors in the server logs instead?

The debug messages you posted don’t really show anything interesting. These are all just messages from when you registered the module using AQL. None of these messages show your attempts to execute the function.

What you want to look out for is any UDF debug logs that appear between the query start and end, e.g. something like this:

Apr 27 2018 02:36:03 GMT: INFO (scan): (scan.c:930) starting aggregation scan job 10949451309221731945 {test:test} priority 2
Apr 27 2018 02:36:03 GMT: DEBUG (udf): (udf_record.c:191) [ENTER] Opening record key:<Digest>:0xf5f86f3d4855adffe8def9a0d902fac71f578b8f
...
Apr 27 2018 02:36:03 GMT: INFO (scan): (scan.c:1041) finished aggregation scan job 10949451309221731945 (0)
16

Hi Jan,

The server log file was too big ~1GB. I just searched for word as canvassearch. Could find these 2 in the logs.

Regards, Manik

17

So are you saying that you do not see any UDF related errors in the server logs?

18

Yes, that is what it looks like.

19

Hi Jan,

Any updates on this?

20

Sorry for the delay.

Since you do not see any errors in the server side logs, let’s see if the client logs can give us any further clues as to what’s going wrong.

Can you please enable debug logging in the client:

Aerospike.setDefaultLogging({ level: Aerospike.log.DETAIL })

Then run your UDF aggregation query and look for the log statements from the mod-lua subsystem in the client logs.