Ext script strange behaviour

1

Dear all,

I have Provision code (see below) , this code is launched every inform (for the tests)
When the script is lunched, it’s work fine (update V.params) , but it doesn’t end properly .
I get The TR-069 session was unsuccessfully terminated on other channels

If in Provison code I remove the ext script calling, it’s OK, the end of the script is done correctly, and the other chanels are executed correctly

Provision code


const now = Date.now();
log('Start provision script');

let provisioned = declare("Tags.Basic_Provisioned", {value: 1});
if (provisioned.value !== undefined) {
    log('CPE is (allegedly) provisioned, returning');
    return;
}

let ip = declare("VirtualParameters.ip", {value: 1}).value[0];
let mac = declare("VirtualParameters.WanMac", {value: 1}).value[0];

let args = {ip: ip, mac: mac};

log('Args ' + JSON.stringify(args));


//Get the params from api
log('Launch ext script');
let config = ext('cpe-config', 'ipdhcp', JSON.stringify(args));
log('Config values from API: ' + JSON.stringify(config));

if (!config) {
    log('No config returned from API');
    return;
}

let circuitid = config.circuitid; //let circuitid = "AZERTYUIOP";
let idur = config.idur; //let idur = "ZZZZZZ";
let dept= config.dept; //let dept= "000";
let contrat = config.contrat; //let contrat = "azzer";
let abonnement = config.abonnement; //let abonnement = "zeertt";

log('Set Option82 (circuitid) to the CPE value with ' + circuitid);
declare("VirtualParameters.Option82", {value: now}, {value: circuitid});

log('Set Idur to the CPE value with ' + idur);
declare("VirtualParameters.Idur", {value: now}, {value: idur});

log('Set VirtualParameters.contrat with ' + contrat);
declare("VirtualParameters.contrat", {value: now}, {value: contrat});

log('Set VirtualParameters.dept with ' + dept);
declare("VirtualParameters.dept", {value: now}, {value: dept});

log('Set VirtualParameters.abo with ' + abonnement);
declare("VirtualParameters.abo", {value: now}, {value: abonnement});

log('Set Tags.Provisioned');
declare("Tags.Basic_Provisioned", null, {value: true});

return;

image
image311×704 21.8 KB

My ext script

//genieacs/config/ext/cpe-config.js
// From https://github.com/genieacs/genieacs/wiki/Example-of-a-Provisioning-Flow
"use strict"

console.log("Run cpe-config.js");


const API_URL = 'http://10.75.10.205:1880/rest/v1/';
const url = require("url");
const http = require(API_URL.split(":", 1)[0]);


function ipdhcp(args, callback) {
    let params = JSON.parse(args[0]);

    const uri = API_URL + "ipdhcp?ip=" + params.ip + '&mac=' + params.mac;

    console.log({ uri: uri, ip: params.ip, mac: params.mac });

    let options = url.parse(uri);
    options.headers = {
        accept: 'application/json',
        "content-type": 'application/json'
    };

    let request = http.get(options, function (response) {
        console.log("response statusCode: " + response.statusCode);
        if (response.statusCode == 404) {
            console.log("Get Error code 404");
            return callback(null, null);
        }

        if (response.statusCode >= 400) {
            console.log("Get Error code >= 400");
            return callback(new Error("Unexpected error. Response Code: " +
                response.statusCode + '. Status Message: ' + response.statusMessage + '. t: ' + typeof response.statusCode));
        }

        let data = "";
        response.on("data", function (d) {
            data = data + d.toString();
        });

        response.on("end", function () {
            let result = JSON.parse(data);

            console.log('Returning data to client', result);
            return callback(null, result);
        });
    });

    request.on("error", function (err) {
        console.log('args');
        console.log(arguments);
        callback(err);
    });
}

exports.ipdhcp = ipdhcp;

My errors

2021-06-15T08:21:40.795Z [INFO] 172.16.75.202 001733-NB7%20Gateway-XU1009020878440350: Script: Start provision script
2021-06-15T08:21:40.843Z [INFO] 172.16.75.202 001733-NB7%20Gateway-XU1009020878440350: Script: Args {"ip":"z.z.z.z","mac":"Z.Z.Z.Z.Z"}
2021-06-15T08:21:40.843Z [INFO] 172.16.75.202 001733-NB7%20Gateway-XU1009020878440350: Script: Launch ext script
2021-06-15T08:21:40.976Z [INFO] 172.16.75.202 001733-NB7%20Gateway-XU1009020878440350: Script: Config values from API: {"dept":"000","idur":"AZERTY","updatetime":"2021-06-14T23:35:27.000Z","circuitid":"AZERTYUIOP","contrat":"ccccc","abonnement":"cccccc","ip":"z.z.z.z","mac":"z.z.Z.z.z"}
2021-06-15T08:21:40.977Z [INFO] 172.16.75.202 001733-NB7%20Gateway-XU1009020878440350: Script: Set Option82 (circuitid) to the CPE value with AZERTYUIOP
2021-06-15T08:21:40.977Z [INFO] 172.16.75.202 001733-NB7%20Gateway-XU1009020878440350: Script: Set Idur to the CPE value with eeeeee
2021-06-15T08:21:40.977Z [INFO] 172.16.75.202 001733-NB7%20Gateway-XU1009020878440350: Script: Set VirtualParameters.contrat with zzzzzz
2021-06-15T08:21:40.977Z [INFO] 172.16.75.202 001733-NB7%20Gateway-XU1009020878440350: Script: Set VirtualParameters.dept with 0000
2021-06-15T08:21:40.977Z [INFO] 172.16.75.202 001733-NB7%20Gateway-XU1009020878440350: Script: Set VirtualParameters.abo with ZZZZ
2021-06-15T08:21:40.977Z [INFO] 172.16.75.202 001733-NB7%20Gateway-XU1009020878440350: Script: Set Tags.Provisioned
2021-06-15T08:21:40.992Z [INFO] 172.16.75.202 001733-NB7%20Gateway-XU1009020878440350: Script: Start VirtualParameters.contrat script
2021-06-15T08:21:40.993Z [INFO] 172.16.75.202 001733-NB7%20Gateway-XU1009020878440350: Script: Start VirtualParameters.dept script
2021-06-15T08:21:40.993Z [INFO] 172.16.75.202 001733-NB7%20Gateway-XU1009020878440350: Script: Start VirtualParameters.Option82 script
2021-06-15T08:21:40.993Z [INFO] 172.16.75.202 001733-NB7%20Gateway-XU1009020878440350: Script: Start VirtualParameters.Idur script
2021-06-15T08:21:40.993Z [INFO] 172.16.75.202 001733-NB7%20Gateway-XU1009020878440350: Script: Start VirtualParameters.abo script
2021-06-15T08:21:41.009Z [INFO] 172.16.75.202 001733-NB7%20Gateway-XU1009020878440350: ACS request; acsRequestId="17a0ec306a80200" acsRequestName="GetParameterValues"
[spoiler]
2021-06-15T08:21:41.011Z [ERROR] 172.16.75.202 001733-NB7%20Gateway-XU1009020878440350: Connection dropped
2021-06-15T08:21:41.011Z [WARN] 172.16.75.202 001733-NB7%20Gateway-XU1009020878440350: Channel has faulted; channel="default" retries=0 faultCode="session_terminated" faultMessage="The TR-069 session was unsuccessfully terminated"
2021-06-15T08:21:41.011Z [WARN] 172.16.75.202 001733-NB7%20Gateway-XU1009020878440350: Channel has faulted; channel="inform" retries=0 faultCode="session_terminated" faultMessage="The TR-069 session was unsuccessfully terminated"
2021-06-15T08:21:41.011Z [WARN] 172.16.75.202 001733-NB7%20Gateway-XU1009020878440350: Channel has faulted; channel="Provisioning" retries=0 faultCode="session_terminated" faultMessage="The TR-069 session was unsuccessfully terminated"
[/spoiler]

image
image994×95 12.8 KB

Thanks for your help

Laurent

2

What happens you run your ext script using the script runner I posted yesterday using the ID of 001733-NB7%20Gateway-XU1009020878440350? Is data returned to the console?

3

Hello,

Yes, when I launch the script (cpe-config) throught ext-runner.js it return the correct values.

root@th2-geniecor-01:/opt/genieacs# node ext/ext-runner.js cpe-config ipdhcp
Run cpe-config.js
Running script ipdhcp
{
  uri: 'http://10.75.10.205:1880/rest/v1/ipdhcp?ip=xxxxxxx&mac=xxxxxxx',
  ip: 'xxxxxxx',
  mac: 'xxxxxxx'
}
response statusCode: 200
{
  dept: 'xxxxxxx',
  idur: 'xxxxxxx',
  updatetime: '2021-06-14T23:35:27.000Z',
  circuitid: 'xxxxxxx',
  contrat: 'xxxxxxx',
  abonnement: 'xxxxxxx',
  ip: 'xxxxxxx',
  mac: 'xxxxxxx'
}

Thanks,

Laurent

4

I don’t understand why some excution are duplicated

For exemple:
at 2021-06-15T22:38:50.684Z

2021-06-15T22:38:49.915Z [INFO] 172.16.75.202 001733-NB7%20Gateway-XU1009020878440350: Inform; cpeRequestId="2021-06-15T22:38:49Z" informEvent="6 CONNECTION REQUEST" informRetryCount=0
2021-06-15T22:38:50.415Z [INFO] 172.16.75.202 001733-NB7%20Gateway-XU1009020878440350: Script: Start provision script
2021-06-15T22:38:50.548Z [INFO] 172.16.75.202 001733-NB7%20Gateway-XU1009020878440350: Script: Args {"ip":"XXXXXX","mac":"XXXXXX"}
2021-06-15T22:38:50.548Z [INFO] 172.16.75.202 001733-NB7%20Gateway-XU1009020878440350: Script: Launch ext script
2021-06-15T22:38:50.684Z [INFO] 172.16.75.202 001733-NB7%20Gateway-XU1009020878440350: Script: Config values from API: {"dept":"XXXXXXX","idur":"XXXXXXX","updatetime":"2021-06-14T23:35:27.000Z","circuitid":"XXXXXXX","contrat":"XXXXXXX","abonnement":"XXXXXXX","ip":"XXXXXXX","mac":"XXXXXXX"}
2021-06-15T22:38:50.684Z [INFO] 172.16.75.202 001733-NB7%20Gateway-XU1009020878440350: Script: Config values from API: {"dept":"XXXXXXX","idur":"XXXXXXX","updatetime":"2021-06-14T23:35:27.000Z","circuitid":"XXXXXXX","contrat":"XXXXXXX","abonnement":"XXXXXXX","ip":"XXXXXXX","mac":"XXXXXXX"}
2021-06-15T22:38:50.684Z [INFO] 172.16.75.202 001733-NB7%20Gateway-XU1009020878440350: Script: Set Option82 (circuitid) to the CPE value with XXXXXXX
2021-06-15T22:38:50.685Z [INFO] 172.16.75.202 001733-NB7%20Gateway-XU1009020878440350: Script: Set Idur to the CPE value with XXXXXXX
2021-06-15T22:38:50.732Z [INFO] 172.16.75.202 001733-NB7%20Gateway-XU1009020878440350: ACS request; acsRequestId="17a11d3c7bf0200" acsRequestName="GetParameterValues"
2021-06-15T22:38:50.734Z [ERROR] 172.16.75.202 001733-NB7%20Gateway-XU1009020878440350: Connection dropped
2021-06-15T22:38:50.734Z [WARN] 172.16.75.202 001733-NB7%20Gateway-XU1009020878440350: Channel has faulted; channel="default" retries=0 faultCode="session_terminated" faultMessage="The TR-069 session was unsuccessfully terminated"
2021-06-15T22:38:50.734Z [WARN] 172.16.75.202 001733-NB7%20Gateway-XU1009020878440350: Channel has faulted; channel="inform" retries=0 faultCode="session_terminated" faultMessage="The TR-069 session was unsuccessfully terminated"
2021-06-15T22:38:50.734Z [WARN] 172.16.75.202 001733-NB7%20Gateway-XU1009020878440350: Channel has faulted; channel="Provisioning" retries=0 faultCode="session_terminated" faultMessage="The TR-069 session was unsuccessfully terminated"

My provision script

const now = Date.now();
log('Start provision script');

let provisioned = declare("Tags.Basic_Provisioned", {value: 1});
if (provisioned.value !== undefined) {
    log('CPE is (allegedly) provisioned, returning');
    return;
}

let ip = declare("VirtualParameters.ip", {value: 1}).value[0];
let mac = declare("VirtualParameters.WanMac", {value: 1}).value[0];

let args = {ip: ip, mac: mac};

log('Args ' + JSON.stringify(args));


//Get the params from api
log('Launch ext script');
let config = ext('cpe-config', 'ipdhcp', JSON.stringify(args));
log('Config values from API: ' + JSON.stringify(config));

if (!config) {
    log('No config returned from API');
    return;
}


//let config = JSON.parse('{"dept":"XXXXXXX","idur":"XXXXXXX","updatetime":"2021-06-14T23:35:27.000Z","circuitid":"XXXXXXX","contrat":"XXXXXXX","abonnement":"XXXXXXX","ip":"XXXXXXX","mac":"XXXXXXX"}');

log('Config values from API: ' + JSON.stringify(config));


setValues(config);


return; //Not explicitly needed, but I want to prevent any extranious code at the bottom from executing...


function setValues(config) {

  log('Set Option82 (circuitid) to the CPE value with ' + config.circuitid);
//declare("VirtualParameters.Option82", {value: now}, {value: config.circuitid});
  declare("Device.ManagementServer.X_SFR_Option82", {value: now}, {value: config.circuitid});

log('Set Idur to the CPE value with ' + config.idur);
//declare("VirtualParameters.Idur", {value: now}, {value: config.idur});
declare("Device.ManagementServer.X_SFR_IDUR", {value: now}, {value: config.idur});

  /*
log('Set VirtualParameters.contrat with ' + config.contrat);
declare("VirtualParameters.contrat", {value: now}, {value: config.contrat});

log('Set VirtualParameters.dept with ' + config.dept);
declare("VirtualParameters.dept", {value: now}, {value: config.dept});

log('Set VirtualParameters.abo with ' + config.abonnement);
declare("VirtualParameters.abo", {value: now}, {value: config.abonnement});
*/ 

commit();
  
setTag(); // Set tag Basic_Provisioned
}


function setTag(){
log('Set Tags.Provisioned');
declare("Tags.Basic_Provisioned", null, {value: true});
}

Laurent

5

Because GenieACS will continue to run a provision script until no more changes are detected.

6

Hi,
in the case when external script is triggered is there a way to avoid errors of type “The TR-069 session was unsuccessfully terminated”? Errors block the channel.
I noticed that script is executed, virtual parameters are set but errors appear anyways.
Thank you

7

That is the same issue I have with an reverse proxy.
The problem is timing. The external script must be very fast. What works for me, are MySQL queries. What won’t work, are requests to other devices or if the MySQL connect needs to be initiated. So the first 8 devices will fail, than it’ll work. The MySQL connect must be initiated outside of the function.

8

I see. Would there be a way to increase timeout in TR069 session so it does not get broken when Genie is talking to external system? Is there a way to make code run outside the TR069 session (some kind of NBI call)? I think some kind of external daemon process will have to be added here (in my case but maybe not a bad idea to add some kind of scheduler inside of genie as well).
Thanks

9

Hi,
since you have been helpful few times I decided to share a script I wrote with you. Script can be used to create virtual parameters in genie based on data from external system. VPs are created directly in mongo and in that way executing external scripts that cause TR069 session breaking is avoided.
Please do not comment the syntax, I did not think much about optimization. It works. Something about looking into teeth of donated horse.
Regards

type or paste code #!/usr/bin/python

# idea of this script is to bypass GenieACS in data enrichment from external system
# when using builtin support for executing external scripts TR069 session
# breaks resulting in an error which further clogs the channel and makes system
# unusable. Idea is to run this script from crontab, make it check if there are
# devices needed to be enriched, fetch data from external system, parse it, modify tags
# and write data into VirtualParams.

import pymongo
import requests
import json
# replace this with your MongoDB connection string

TAG_ENRICHMENT_NEEDED = "EXTEnrReq"
TAG_ENRICHMENT_SUCCESSFUL = "EXTEnrOK"
TAG_ENRICHMENT_FAILED = "EXTEnrFail"

EXT_VIRTUAL_PARAMETERS = {
        "userid" : "EXT_USERID",
        "firstname" : "EXT_FIRSTNAME",
        "lastname" : "EXT_LASTNAME",
        "fullname" : "EXT_FULLNAME",
        "companyname" : "EXT_COMPANYNAME",
        # ...
        }


conn_str = "mongodb://localhost"
################### LOGGING
import logging
from logging.handlers import RotatingFileHandler

logger = logging.getLogger('EXT')
handler = RotatingFileHandler("/root/scripts/ext_sync.log", maxBytes=50*1024*1024, backupCount=3)
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
handler.setFormatter(formatter)
logger.addHandler(handler)
logger.setLevel(logging.DEBUG)
logger.info("################### Enrichment script started #####################")
###################

def get_EXT_data(serialnumber):
    """ get data from EXT system"""
    # basically any protocol can be used here ...
    result = {}
    EXT_url = "https://foobar/somepath"
    post_data = {"secret" : "foobar", "serialnumber" : serialnumber}
    try:
        resp = requests.post(EXT_url, json=post_data)
    except Exception, e:
        logger.error("Error when calling url %s" % str(e))
    code = resp.status_code
    text = resp.text
    if code == 200 and text != "No result found":
        try:
            r = json.loads(text)
        except Exception, e:
            logger.error("Unable to parse JSON from EXT %s" % text)
        # parse interesting params
        # result["userid"] = r.get("userid", None)
        # result["firstname"] = r.get("firstname", None)
        # result["lastname"] = r.get("lastname", None)
        for k in EXT_VIRTUAL_PARAMETERS.keys():
            result[k] = r.get(k, None)
    else:
        logger.error("EXT did not return proper response")
        logger.debug("Result from get_EXT_data %s" % str(result))
    return result


def add_mongo_tag(collection, device, tag):
    try:
        device["_tags"].append(tag)
        collection.save(device)
        logger.info("Added tag %s" % tag)
    except Exception, e:
        logger.error("Unable to add tag %s" % tag)

def remove_mongo_tag(collection, device, tag):
    try:
        device["_tags"].remove(tag)
        collection.save(device)
        logger.info("Removed tag %s" % tag)
    except Exception, e:
        logger.error("Unable to remove tag %s" % tag)


def virt_param_struct(value):
    import datetime
    now = datetime.datetime.utcnow()
    return {
            "_object" : False,
            "_timestamp" : now,
            "_type" : "xsd:string",
            "_value" : value,
            "_writable" : False
            }

def add_mongo_VPs(collection, device, virtual_parameters):
    if not virtual_parameters:
        # do nothing
        return
    else:
        try:
            for k, v in virtual_parameters.items():
                device["VirtualParameters"][k] = virt_param_struct(v)
            collection.save(device)
            logger.info("Created virtual params")
        except Exception, e:
            logger.error("Failed to create virtual param")
        logger.debug("virtual_parameters = %s" % str(virtual_parameters))


def remove_mongo_VP(collection, device):
    pass

# set a 5-second connection timeout
try:
    # logger.info("After try statement")
    client = pymongo.MongoClient(conn_str, serverSelectionTimeoutMS=5000)
    # print(client.server_info())

    # list all devices
    genieacs_db = client.genieacs
    devices = genieacs_db.devices
    # print devices.find_one()
    # print ""
    r = devices.find({"_tags" : {"$eq" : TAG_ENRICHMENT_NEEDED}})
    
    enrichment_needed_list = [i for i in r]
    if len(enrichment_needed_list) == 0:
        logger.info("0 Devices pending enrichment.")
    else:
        logger.info("%s Devices pending enrichment." % len(enrichment_needed_list))
        # if there are devices for enrichment
        for device in enrichment_needed_list:
            _id = device.get("_id", None)
            if _id is not None:
                _, _, serialnumber = _id.split("-")
                logger.info("Working on device %s" % _id)
                data = get_EXT_data(serialnumber)
                if data:
                    # update mongo VirtualParameters and _tags
                    # we mapped data names to virtualparameters above
                    add_mongo_VPs(devices, device, {EXT_VIRTUAL_PARAMETERS[k] : v \
                            for k, v in data.items() if k in EXT_VIRTUAL_PARAMETERS})

                    # remove current tag, add new one
                    remove_mongo_tag(devices, device, TAG_ENRICHMENT_NEEDED)
                    add_mongo_tag(devices, device, TAG_ENRICHMENT_SUCCESSFUL)
                else:
                    logger.error("Unable to fetch data from EXT for device %s" % str(serialnumber))
                    remove_mongo_tag(devices, device, TAG_ENRICHMENT_NEEDED)
                    add_mongo_tag(devices, device, TAG_ENRICHMENT_FAILED)
            else:
                # could not get _id
                logger.error("Unable to get _id for device %s" % str(serialnumber))
                remove_mongo_tag(devices, device, TAG_ENRICHMENT_NEEDED)
                add_mongo_tag(devices, device, TAG_ENRICHMENT_FAILED)
    # close connection
    client.close()

    logger.info("############################ DONE with ENRICHMENT SCRIPT #############################")

except Exception, e:
    logger.error("Unable to connect to the server. %s" % str(e))
here
1 Like