Genieacs-cwmp: CPE not picking up Tasks

1

Good day

I’ve been testing GenieACS for some time, and it works like a charm, except for one issue I cannot get resolved.

Setup:

  • GenieACS 1.1.3 on Ubuntu 18
  • All processes running behind an Nginx reverse proxy which does the TLS
  • Integration between a custom application and the NBI API.

Problem:

My CPE’s (Mikrotik, latest stable RouterOS) occasionally does not pick up tasks in the queue. The behavior I see is as follows:

  1. A device task is created via the NBI API, e.g. to change PPPoE credentials
  2. When the CPE sends it’s next periodic inform, it’s logs indicate that there are no tasks to execute.
  3. Subsequent informs does not execute the task either, which sits in the queue indefinitely

The API-created task looks exactly like the GUI-created tasks in the MongoDB tasks collection, except for the internal IDs and timestamp.

I can do two different things to get the task processed:

a) Add a second task via the GUI to refresh any arbitrary parameter
b) Restart the TR069 client on the CPE

In the first case, the CPE executes the original and the arbitrary task upon the next inform, as expected.

Despite my best efforts, I can’t determine why either of steps (a) or (b) gets the tasks processed, nor why the task is “stuck” in the queue in the first place. I have looked at the server code that fetches queued tasks during a CMWP session, as well as the tasks collection in MongoDB.

Any ideas or pointers will be much appreciated.

Thanks
Hugo

2

genieacs-gui uses the API to push tasks to a device so there must be something you’re doing differently.

3

I finally found the cause of the problem.

When tasks are created via the NBI (version 1.1.3), the API invalidates the relevant items in the cache.

Creating tasks via the Ruby GUI cleared the cache fine. For some reason, when creating the same task from other code, the cache was not cleared. I can’t explain why, but here’s what happened:

For a given device with an empty queue, I create a simple task via GUI, which looks like this in the tasks collection:

{
    "_id" : ObjectId("5cc6570014f67a2e5cd22a3e"),
    "name" : "setParameterValues",
    "parameterValues" : [ 
        [ 
            "Device.PPP.Interface.1.Username", 
            "357@qa"
        ]
    ],
    "timestamp" : ISODate("2019-04-29T01:44:31.000Z"),
    "device" : "E48D8C-hAP%20lite-8CE709B562E6"
}

I then enable tr069 client on the CPE, which sends an inform and processes the username change correctly.

The task queue is empty, and the cache entry now looks like this:

{
    "_id" : "E48D8C-hAP%20lite-8CE709B562E6_tasks_faults_operations",
    "value" : "{}",
    "expire" : ISODate("2019-04-30T01:45:00.817Z")
}

I then create the same task via the NBI from a custom client, which creates the task with a 202 response;

{
    "_id" : ObjectId("5cc657e96f90c82e61546a36"),
    "name" : "setParameterValues",
    "parameterValues" : [ 
        [ 
            "Device.PPP.Interface.1.Username", 
            "357@qa"
        ]
    ],
    "timestamp" : ISODate("2019-04-29T01:48:24.000Z"),
    "device" : "E48D8C-hAP%20lite-8CE709B562E6"
}

However, the cache entry for the device still says:

{
    "_id" : "E48D8C-hAP%20lite-8CE709B562E6_tasks_faults_operations",
    "value" : "{}",
    "expire" : ISODate("2019-04-30T01:45:00.817Z")
}

I wait for the CPE to send another inform, which happens some minutes later. It skips the task as expected:

# REQUEST Mon Apr 29 2019 03:49:26 GMT+0200 (SAST)
{"host":"127.0.0.1:3002","connection":"close","content-length":"1813","authorization":"Basic Og==","content-type":"text/xml","user-agent":"MikroTik"}
<soapenv:Envelope xmlns:soap='http://schemas.xmlsoap.org/soap/encoding/' xmlns:xsd='http://www.w3.org/2001/XMLSchema' xmlns:cwmp='urn:dslforum-org:cwmp-1-0' xmlns:soapenv='http://schemas.xmlsoap.org/soap/envelope/' xmlns:xsi='http://www.w3.org/2001/XMLSchema-instance'><soapenv:Body><cwmp:Inform><DeviceId><Manufacturer>MikroTik</Manufacturer><OUI>E48D8C</OUI><ProductClass>hAP lite</ProductClass><SerialNumber>8CE709B562E6</SerialNumber></DeviceId><Event soap:arrayType='cwmp:EventStruct[1]'><EventStruct><EventCode>1 BOOT</EventCode><CommandKey></CommandKey></EventStruct></Event><MaxEnvelopes>1</MaxEnvelopes><CurrentTime>2019-04-29T03:49:25+02:00</CurrentTime><RetryCount>0</RetryCount><ParameterList soap:arrayType='cwmp:ParameterValueStruct[7]'><ParameterValueStruct><Name>Device.RootDataModelVersion</Name><Value xsi:type='xsd:string'>2.11</Value></ParameterValueStruct><ParameterValueStruct><Name>Device.DeviceInfo.SoftwareVersion</Name><Value xsi:type='xsd:string'>6.44.2</Value></ParameterValueStruct><ParameterValueStruct><Name>Device.DeviceInfo.ProvisioningCode</Name><Value xsi:type='xsd:string'>test04</Value></ParameterValueStruct><ParameterValueStruct><Name>Device.DeviceInfo.HardwareVersion</Name><Value xsi:type='xsd:string'>v1.0</Value></ParameterValueStruct><ParameterValueStruct><Name>Device.ManagementServer.ParameterKey</Name><Value xsi:type='xsd:string'></Value></ParameterValueStruct><ParameterValueStruct><Name>Device.ManagementServer.ConnectionRequestURL</Name><Value xsi:type='xsd:string'>http://10.0.20.253:7547/3310e3879e2788f1f142778cc4766e9c17ce</Value></ParameterValueStruct><ParameterValueStruct><Name>Device.ManagementServer.AliasBasedAddressing</Name><Value xsi:type='xsd:boolean'>0</Value></ParameterValueStruct></ParameterList></cwmp:Inform></soapenv:Body></soapenv:Envelope>

# RESPONSE Mon Apr 29 2019 03:49:26 GMT+0200 (SAST)
{"Server":"GenieACS/1.1.3","SOAPServer":"GenieACS/1.1.3","Content-Type":"text/xml; charset=\"utf-8\"","Set-Cookie":"session=e2624c922d712033"}
<?xml version="1.0" encoding="UTF-8"?>
<soap-env:Envelope xmlns:soap-enc="http://schemas.xmlsoap.org/soap/encoding/" xmlns:soap-env="http://schemas.xmlsoap.org/soap/envelope/" xmlns:xsd="http://www.w3.org/2001/XMLSchema" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:cwmp="urn:dslforum-org:cwmp-1-0"><soap-env:Header><cwmp:ID soap-env:mustUnderstand="1">undefined</cwmp:ID></soap-env:Header><soap-env:Body><cwmp:InformResponse><MaxEnvelopes>1</MaxEnvelopes></cwmp:InformResponse></soap-env:Body></soap-env:Envelope>


# REQUEST Mon Apr 29 2019 03:49:26 GMT+0200 (SAST)
{"host":"127.0.0.1:3002","connection":"close","content-length":"0","authorization":"Basic Og==","cookie":"session=e2624c922d712033","user-agent":"MikroTik"}


# RESPONSE Mon Apr 29 2019 03:49:26 GMT+0200 (SAST)
{"Server":"GenieACS/1.1.3","SOAPServer":"GenieACS/1.1.3","Connection":"close"}


# REQUEST Mon Apr 29 2019 03:49:26 GMT+0200 (SAST)
{"host":"127.0.0.1:3002","connection":"close","content-length":"1821","authorization":"Basic Og==","content-type":"text/xml","user-agent":"MikroTik"}
<soapenv:Envelope xmlns:soap='http://schemas.xmlsoap.org/soap/encoding/' xmlns:xsd='http://www.w3.org/2001/XMLSchema' xmlns:cwmp='urn:dslforum-org:cwmp-1-0' xmlns:soapenv='http://schemas.xmlsoap.org/soap/envelope/' xmlns:xsi='http://www.w3.org/2001/XMLSchema-instance'><soapenv:Body><cwmp:Inform><DeviceId><Manufacturer>MikroTik</Manufacturer><OUI>E48D8C</OUI><ProductClass>hAP lite</ProductClass><SerialNumber>8CE709B562E6</SerialNumber></DeviceId><Event soap:arrayType='cwmp:EventStruct[1]'><EventStruct><EventCode>4 VALUE CHANGE</EventCode><CommandKey></CommandKey></EventStruct></Event><MaxEnvelopes>1</MaxEnvelopes><CurrentTime>2019-04-29T03:49:26+02:00</CurrentTime><RetryCount>0</RetryCount><ParameterList soap:arrayType='cwmp:ParameterValueStruct[7]'><ParameterValueStruct><Name>Device.RootDataModelVersion</Name><Value xsi:type='xsd:string'>2.11</Value></ParameterValueStruct><ParameterValueStruct><Name>Device.DeviceInfo.SoftwareVersion</Name><Value xsi:type='xsd:string'>6.44.2</Value></ParameterValueStruct><ParameterValueStruct><Name>Device.DeviceInfo.ProvisioningCode</Name><Value xsi:type='xsd:string'>test04</Value></ParameterValueStruct><ParameterValueStruct><Name>Device.DeviceInfo.HardwareVersion</Name><Value xsi:type='xsd:string'>v1.0</Value></ParameterValueStruct><ParameterValueStruct><Name>Device.ManagementServer.ParameterKey</Name><Value xsi:type='xsd:string'></Value></ParameterValueStruct><ParameterValueStruct><Name>Device.ManagementServer.ConnectionRequestURL</Name><Value xsi:type='xsd:string'>http://10.0.20.253:7547/3310e3879e2788f1f142778cc4766e9c17ce</Value></ParameterValueStruct><ParameterValueStruct><Name>Device.ManagementServer.AliasBasedAddressing</Name><Value xsi:type='xsd:boolean'>0</Value></ParameterValueStruct></ParameterList></cwmp:Inform></soapenv:Body></soapenv:Envelope>

# RESPONSE Mon Apr 29 2019 03:49:26 GMT+0200 (SAST)
{"Server":"GenieACS/1.1.3","SOAPServer":"GenieACS/1.1.3","Content-Type":"text/xml; charset=\"utf-8\"","Set-Cookie":"session=ad902951e802c3e1"}
<?xml version="1.0" encoding="UTF-8"?>
<soap-env:Envelope xmlns:soap-enc="http://schemas.xmlsoap.org/soap/encoding/" xmlns:soap-env="http://schemas.xmlsoap.org/soap/envelope/" xmlns:xsd="http://www.w3.org/2001/XMLSchema" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:cwmp="urn:dslforum-org:cwmp-1-0"><soap-env:Header><cwmp:ID soap-env:mustUnderstand="1">undefined</cwmp:ID></soap-env:Header><soap-env:Body><cwmp:InformResponse><MaxEnvelopes>1</MaxEnvelopes></cwmp:InformResponse></soap-env:Body></soap-env:Envelope>


# REQUEST Mon Apr 29 2019 03:49:26 GMT+0200 (SAST)
{"host":"127.0.0.1:3002","connection":"close","content-length":"0","authorization":"Basic Og==","cookie":"session=ad902951e802c3e1","user-agent":"MikroTik"}


# RESPONSE Mon Apr 29 2019 03:49:26 GMT+0200 (SAST)
{"Server":"GenieACS/1.1.3","SOAPServer":"GenieACS/1.1.3","Connection":"close"}

When creating another task via the GUI, the cache is cleared and the device picks it up. I have no idea how this is happening, since it’s the same code in /lib/nbi.coffee doing the task creation.

As a work around, I’m setting the MAX_CACHE_TTL in config.json to something smaller than my inform interval.

Regards