# Using extension scripts always leads to unsuccessfully terminated session

**URL:** <https://forum.genieacs.com/t/using-extension-scripts-always-leads-to-unsuccessfully-terminated-session/1937>\
**Category:** Uncategorized\
**Created:** [August 11, 2021, 3:23pm UTC](https://forum.genieacs.com/t/using-extension-scripts-always-leads-to-unsuccessfully-terminated-session/1937 "2021-08-11T15:23:44Z")\
**Posts on this page:** 9\
**Page:** 1

<div class="post-metadata">

**Author:** ![olebowle](https://avatars.discourse-cdn.com/v4/letter/o/bcef8e/32.png) [@olebowle](https://forum.genieacs.com/u/olebowle)\
**Post date:** [August 11, 2021, 3:23pm UTC](https://forum.genieacs.com/t/using-extension-scripts-always-leads-to-unsuccessfully-terminated-session/1937/1 "2021-08-11T15:23:44Z")

</div>

I’m trying to call a tiny extension script from a provision. Whenever it is being called the session is terminated unsuccessfully. I read this might be related to the script having a long runtime, but I stripped it down to the bare minimum:

ext/pppmon.js:

```auto
function addVals(args, callback) {
    callback(null, {});
}

exports.addValues = addVals;

```

The provision calling the extension only gets one parameter and passes it to the extension:

```auto
let manufacturer = declare('InternetGatewayDevice.DeviceInfo.Manufacturer', {value: Date.now() - (50 * 1000)}).value[0];
ext('pppmon', 'addValues', manufacturer)

```

If I comment the extension call, the log file looks fine:

```auto
2021-08-11T14:12:22.449Z [INFO] 100.64.32.191 00040E-FRITZ%21Box-444E6D6F0761: Inform; cpeRequestId="1498" informEvent="2 PERIODIC" informRetryCount=0
2021-08-11T14:12:22.807Z [INFO] 100.64.32.191 00040E-FRITZ%21Box-444E6D6F0761: ACS request; acsRequestId="17b358e96dd0100" acsRequestName="GetParameterValues"

```

When calling the extension I get:

```auto
2021-08-11T14:13:22.460Z [INFO] 100.64.32.191 00040E-FRITZ%21Box-444E6D6F0761: Inform; cpeRequestId="1499" informEvent="2 PERIODIC" informRetryCount=0
2021-08-11T14:13:22.821Z [INFO] 100.64.32.191 00040E-FRITZ%21Box-444E6D6F0761: ACS request; acsRequestId="17b358f81430100" acsRequestName="GetParameterValues"
2021-08-11T14:13:23.277Z [ERROR] 100.64.32.191 00040E-FRITZ%21Box-444E6D6F0761: Connection dropped
2021-08-11T14:13:23.278Z [WARN] 100.64.32.191 00040E-FRITZ%21Box-444E6D6F0761: Channel has faulted; channel="default" retries=0 faultCode="session_terminated" faultMessage="The TR-069 session was unsuccessfully terminated"
2021-08-11T14:13:23.323Z [ERROR] 100.64.32.191: Invalid session

```

We are at v1.2.3 and use Apache as a reverse proxy with disablereuse=On. I couldn’t attach PCAP files for pass and fail so I uploaded them here: [WeTransfer](https://we.tl/t-Zs6AdhqzhE)

---

<div class="post-metadata">

**Author:** ![JonasGhost](https://yyz1.discourse-cdn.com/flex035/user_avatar/forum.genieacs.com/jonasghost/32/286_2.png) [@JonasGhost](https://forum.genieacs.com/u/JonasGhost)\
**Post date:** [August 11, 2021, 7:34pm UTC](https://forum.genieacs.com/t/using-extension-scripts-always-leads-to-unsuccessfully-terminated-session/1937/2 "2021-08-11T19:34:00Z")

</div>

Genieacs runs multiple cwmp processes and per cwmp process it will launch the ext script at first use. This loading processes takes time. (I thought I have this issue, because on load my scripts connect to mariadb)  
So at my production ACS on reboot the first 16-20 devices will have the problem of an unterminated Connection, but it does not matter for me.

If it is a new device, it will not receive the provisioned tag.  
As long it does not have that tag, I set an inform Intervall of 30 seconds. So it will try again in 30 seconds.

I am running behind nginx.

---

<div class="post-metadata">

**Author:** ![olebowle](https://avatars.discourse-cdn.com/v4/letter/o/bcef8e/32.png) [@olebowle](https://forum.genieacs.com/u/olebowle)\
**Post date:** [August 12, 2021, 9:29am UTC](https://forum.genieacs.com/t/using-extension-scripts-always-leads-to-unsuccessfully-terminated-session/1937/3 "2021-08-12T09:29:15Z")

</div>

Thanks, I did set the number of CWMP workers to one (`GENIEACS_CWMP_WORKER_PROCESSES=1`) and restarted genieacs-cwmp. As you said, the first time I’ll get a `session_terminated`. For the next couple of informs it seems fine. However, I still get an occasional `session_terminated` roughly in 10% of the cases. From my observation GenieACS won’t try to run the provision for next five informs after a fault happend. Afterwards the fault is cleared and normal operation continues.

In my tests I’m using a “monitoring” provision, which reacts on `2 PERIODIC` and queries a couple of PHY parameters. This is used to draw diagrams of that device. So far I queried the NBI for the values. However, that doesn’t scale well when talking about thousands of devices.

So my idea was to let the provision call an extension script storing the preprocessed information in a file named after the serial number. Another external process will later loop over the files, gets the content, deletes the file and pushes the content into a times series database, from which our diagrams are created.

Getting a fault means that I’ll loose 5 datapoints in 10% of the cases, which is not ideal.

The provision + extension looks like:

```auto
let values = {};
const serialNumber = declare('DeviceID.SerialNumber', {value: Date.now()}).value[0];

// DeviceLog is not used for diagrams but for over stuff
declare('InternetGatewayDevice.DeviceInfo.DeviceLog', {value: Date.now()});
values['avg_ds_pwr'] = declare('InternetGatewayDevice.WANDevice.1.X_AVM-DE_Optical.Interface.1.OpticalSignalLevel', {value: Date.now()}).value[0] / 1000;
values['avg_us_pwr'] = declare('InternetGatewayDevice.WANDevice.1.X_AVM-DE_Optical.Interface.1.TransmitOpticalLevel', {value: Date.now()}).value[0] / 1000;

ext('pppmon', 'addValues', serialNumber, JSON.stringify(values));

```

The extension script is:

```auto
'use strict';

const fs = require('fs');

function addVals(args, callback) {
    const serial_num = args[0];
    const values = JSON.parse(args[1]);
    const columns = ['avg_ds_pwr', 'avg_ds_snr', 'avg_us_pwr', 'avg_us_snr'];

    fs.writeFile('/tmp/genieacs/' + serial_num, columns.map(k => (k in values) ? values[k] : 'null').join(','), () => {});
    callback(null, {});
}

exports.addValues = addVals;

```

Of course I could also use the `log()` function of a provision to get rid of the extension altogether:

```auto
let values = {};
const columns = ['avg_ds_pwr', 'avg_ds_snr', 'avg_us_pwr', 'avg_us_snr'];

declare('InternetGatewayDevice.DeviceInfo.DeviceLog', {value: Date.now()});
values['avg_ds_pwr'] = declare('InternetGatewayDevice.WANDevice.1.X_AVM-DE_Optical.Interface.1.OpticalSignalLevel', {value: Date.now()}).value[0] / 1000;
values['avg_us_pwr'] = declare('InternetGatewayDevice.WANDevice.1.X_AVM-DE_Optical.Interface.1.TransmitOpticalLevel', {value: Date.now()}).value[0] / 1000;

log(columns.map(k => (k in values) ? values[k] : 'null').join(','));

```

This seems much more stable. But this would mean I’ll spam the log and the external process needs to go through the whole log to find the last line of a device/serialnumber to push that into the time-series database.

---

<div class="post-metadata">

**Author:** ![JonasGhost](https://yyz1.discourse-cdn.com/flex035/user_avatar/forum.genieacs.com/jonasghost/32/286_2.png) [@JonasGhost](https://forum.genieacs.com/u/JonasGhost)\
**Post date:** [August 12, 2021, 7:23pm UTC](https://forum.genieacs.com/t/using-extension-scripts-always-leads-to-unsuccessfully-terminated-session/1937/4 "2021-08-12T19:23:36Z")

</div>

Oh, your are using as fiber optic FRITZ!Box. I am looking forward to use them in my network.

Back to the topic, I only use logging for trouble devices. There I use a special provision to load the data into genieacs and the export it over the api from genieacs in an asynchronous way.

If your logging/monitoring system can will remove duplicated entry with the same timestamp, you could use the api in a similar way. Especially if your using numeric values.

The api also carries a timestamp for every value.  
For those devices I have an inform time of 5 minutes and my cronjob with curl runs every 7 minutes. So I have a file for ever 7 minutes timestamp. (I store the compressed)  
Unfortunately this is the best solution for my problem, because I want to preserve the logs from the device, especially if the device has a flipping connect.

---

<div class="post-metadata">

**Author:** ![JonasGhost](https://yyz1.discourse-cdn.com/flex035/user_avatar/forum.genieacs.com/jonasghost/32/286_2.png) [@JonasGhost](https://forum.genieacs.com/u/JonasGhost)\
**Post date:** [August 13, 2021, 9:35am UTC](https://forum.genieacs.com/t/using-extension-scripts-always-leads-to-unsuccessfully-terminated-session/1937/5 "2021-08-13T09:35:42Z")

</div>

> [@olebowle](#):
>
> This seems much more stable. But this would mean I’ll spam the log and the external process needs to go through the whole log to find the last line of a device/serialnumber to push that into the time-series database.

I am using that approach to connect the serialnumbers to ip addresses from the device. I switched the logformat to json, to make automated process easy. I run a script every hour for that. In a day, I generate about 270M of logs, bevor compression.

It would also be possible to use a file watcher, e.g. inside node js, to parse the log.  
[https://nodejs.org/docs/latest/api/fs.html#fs\_fs\_watch\_filename\_options\_listener](https://nodejs.org/docs/latest/api/fs.html#fs_fs_watch_filename_options_listener)

What inform intervals are you using for your standard devices?

---

<div class="post-metadata">

**Author:** ![olebowle](https://avatars.discourse-cdn.com/v4/letter/o/bcef8e/32.png) [@olebowle](https://forum.genieacs.com/u/olebowle)\
**Post date:** [August 16, 2021, 12:52pm UTC](https://forum.genieacs.com/t/using-extension-scripts-always-leads-to-unsuccessfully-terminated-session/1937/6 "2021-08-16T12:52:08Z")

</div>

Right now we are using a 5 minute inform interval, since we are coming from DOCSIS with a 5 minute SNMP polling cycle.

JSON logformat would be better for programmatic access. However, the format is less readable in case one needs to debug an ill-behaving device.

Can’t you query ManagementServer.ConnectionRequestURL to get the IP address? I think this is what GenieACS is using internally as well to retrieve the IP address of a device. We can query our RADIUS server for this, since all our CWMP devices are also using PPPoE.

---

<div class="post-metadata">

**Author:** ![JonasGhost](https://yyz1.discourse-cdn.com/flex035/user_avatar/forum.genieacs.com/jonasghost/32/286_2.png) [@JonasGhost](https://forum.genieacs.com/u/JonasGhost)\
**Post date:** [August 16, 2021, 1:16pm UTC](https://forum.genieacs.com/t/using-extension-scripts-always-leads-to-unsuccessfully-terminated-session/1937/7 "2021-08-16T13:16:55Z")

</div>

> [@olebowle](#):
>
> Can’t you query ManagementServer.ConnectionRequestURL to get the IP address? I think this is what GenieACS is using internally as well to retrieve the IP address of a device. We can query our RADIUS server for this, since all our CWMP devices are also using PPPoE.

Yes and no. I am using TR181 and TR098 devices and some devices are reporting wrong addresses or will report wrong addresses in the future.  
e.G. when a device is running in dhcp mode with CGNAT and PCP it will report the external address from the pcp server as connection request url. In our network architecture it is possible, that some devices are only reachable over NAT/PCP and others are directly connection to the acs. So I need the IP that is connection to the acs.  
Or if the devices is behind undetected nat, it will report the internal ip of that nat zone. In some cases it is behind the customers nat.  
Currently, we are not running PCP on our CGNAT System but it is planed.

We are also using dynamic device / customer linking for provisioning with some of our partner networks. For debugging we have the possibility to use dynamic linking with almost every partner network. This allows us to work with customer-provided equipment.

---

<div class="post-metadata">

**Author:** ![zaidka](https://yyz1.discourse-cdn.com/flex035/user_avatar/forum.genieacs.com/zaidka/32/9_2.png) [@zaidka](https://forum.genieacs.com/u/zaidka)\
**Post date:** [September 15, 2021, 2:19am UTC](https://forum.genieacs.com/t/using-extension-scripts-always-leads-to-unsuccessfully-terminated-session/1937/8 "2021-09-15T02:19:31Z")

</div>

The ‘Connection dropped’ error is fixed in the latest master branch. v1.2.6 will be out very soon and will include the fix for this issue.

---

<div class="post-metadata">

**Author:** ![olebowle](https://avatars.discourse-cdn.com/v4/letter/o/bcef8e/32.png) [@olebowle](https://forum.genieacs.com/u/olebowle)\
**Post date:** [September 15, 2021, 9:37am UTC](https://forum.genieacs.com/t/using-extension-scripts-always-leads-to-unsuccessfully-terminated-session/1937/9 "2021-09-15T09:37:27Z")

</div>

Thx @zaidka . 🙂 Looking forward to the new release!