Are operations meant do be deleted?

1

I’m just trying to understand how GenieACS works.

When I create a task for Download RPC (3 vendor configuration file), the CPE downloads the file, then the task gets deleted and then I have an operation created that stays there even after the device is rebooted. Isn’t that operation meant to be deleted? Or it will just sits there forever?

I may have a problem here. I didn’t get the steps to reproduce it yet, but sometimes, several minutes after a 3 vendor configuration file (like 20-30 minutes), the CPE just sends a “Download timeout” on the next session and then GenieACS mistakenly pushes the reconfig again.

2

Do a debug capture of the SOAP conversation (also turn on cwmp logging). I bet the CPE isn’t properly closing the connection. Rarely, I’ve encountered a random CPE that gets stuck in a loop like this and I have to manually delete the download task.

3

The operation object remains in the database until the device sends a TransferComplete message (or after a certain timeout). This will determine whether the download was successful or not. In case of failure, the download will be reattempted.

4

Thanks zaidka for the explanation.

akcoder I will come with more info once I understand more of what’s happening

5

Ok, so it seems to be happening pretty consistently. Is this all being caused because that session timeout after the TransferComplete ? If yes, how to I work around it?

The symptom is:
I send a 3 Vendor Config File. All happens as it should. Device gets reconfig and talks normally to ACS after. After 1 hour, the next session will log a faultMessage=“Download operation timed out” and will push the 3 Vendor Config File again. And it loops like that.

Using:
GenieACS 1.2.1
Mikrotik hAPac2 RouterOS 6.47.3

CWMP access log:

 PUSH
2020-09-18T15:21:38.797Z [INFO] maskedip E48D8C-hAP%20ac%C2%B2-maskedserial: Inform; informEvent="6 CONNECTION REQUEST" informRetryCount=0
2020-09-18T15:21:38.826Z [INFO] maskedip E48D8C-hAP%20ac%C2%B2-maskedserial: ACS request; acsRequestId="174a1ce7ee10000" acsRequestName="Download" acsRequestCommandKey="174a1ce7ee10000"
2020-09-18T15:21:39.171Z [INFO] maskedip E48D8C-hAP%20ac%C2%B2-maskedserial: Inform; informEvent="7 TRANSFER COMPLETE,M Download" informRetryCount=0
2020-09-18T15:21:39.190Z [INFO] maskedip E48D8C-hAP%20ac%C2%B2-maskedserial: CPE request; cpeRequestName="TransferComplete" cpeRequestCommandKey="174a1ce7ee10000"

AFTER CPE DOWNLOAD AND REBOOT
2020-09-18T15:22:10.199Z [ERROR] maskedip: Session timeout; sessionTimestamp=1600442499163 deviceId="E48D8C-hAP%20ac%C2%B2-maskedserial"
2020-09-18T15:22:56.547Z [INFO] maskedip E48D8C-hAP%20ac%C2%B2-maskedserial: Inform; informEvent="0 BOOTSTRAP,1 BOOT" informRetryCount=2
2020-09-18T15:23:07.437Z [INFO] maskedip E48D8C-hAP%20ac%C2%B2-maskedserial: Inform; informEvent="1 BOOT" informRetryCount=0

AFTER 1 HOUR
2020-09-18T16:21:57.121Z [INFO] maskedip E48D8C-hAP%20ac%C2%B2-maskedserial: Inform; informEvent="2 PERIODIC" informRetryCount=0
2020-09-18T16:21:57.139Z [WARN] maskedip E48D8C-hAP%20ac%C2%B2-maskedserial: Channel has faulted; channel="task_5f64d0823c7f78c4a11bf4fb" retries=0 faultCode="timeout" faultMessage="Download operation timed out"
2020-09-18T16:21:57.141Z [INFO] maskedip E48D8C-hAP%20ac%C2%B2-maskedserial: ACS request; acsRequestId="174a205b4fe0000" acsRequestName="Download" acsRequestCommandKey="174a205b4fe0000"
2020-09-18T16:21:57.478Z [INFO] maskedip E48D8C-hAP%20ac%C2%B2-maskedserial: Inform; informEvent="7 TRANSFER COMPLETE,M Download" informRetryCount=0
2020-09-18T16:21:57.497Z [INFO] maskedip E48D8C-hAP%20ac%C2%B2-maskedserial: CPE request; cpeRequestName="TransferComplete" cpeRequestCommandKey="174a205b4fe0000"
2020-09-18T16:22:28.508Z [ERROR] maskedip: Session timeout; sessionTimestamp=1600446117473 deviceId="E48D8C-hAP%20ac%C2%B2-maskedserial"
2020-09-18T16:23:14.967Z [INFO] maskedip E48D8C-hAP%20ac%C2%B2-maskedserial: Inform; informEvent="0 BOOTSTRAP,1 BOOT" informRetryCount=2

Packets contents (For the Transfer Complete part)
POST / HTTP/1.1
Content-Length: 584
Content-Type: text/xml
Cookie: session=fb05e9fdb079d6f6
Host: routeracs.mcsnet.ca
SOAPAction:
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:TransferComplete>
            <CommandKey>174a2213d480000</CommandKey>
            <FaultStruct><FaultCode>0</FaultCode>
            <FaultString></FaultString></FaultStruct>
            <StartTime>2020-09-18T09:52:01-07:00</StartTime>
            <CompleteTime>2020-09-18T09:52:01-07:00</CompleteTime>
        </cwmp:TransferComplete>
    </soapenv:Body>
</soapenv:Envelope>


HTTP/1.1 200 OK
Content-Length: 514
Server: GenieACS/1.2.1+20200915161641
SOAPServer: GenieACS/1.2.1+20200915161641
Content-Type: text/xml; charset="utf-8"
Date: Fri, 18 Sep 2020 16:52:01 GMT
Connection: keep-alive

<?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">null</cwmp:ID>
    </soap-env:Header>
    <soap-env:Body>
        <cwmp:TransferCompleteResponse></cwmp:TransferCompleteResponse>
    </soap-env:Body>
</soap-env:Envelope>

---------- NO PACKET AFTER THIS UNTIL CPE BOOT ------------------

From mongo (after the reconfig and reboot went well) , device download ts didn’t upload neither the operation delete
{
“_id” : “E48D8C-hAP%20ac%C2%B2-maskedserial”,
“Device” : {
“DeviceInfo” : {
“HardwareVersion” : {
“_object” : false,
“_timestamp” : ISODate(“2020-09-18T15:15:40.934Z”),
“_type” : “xsd:string”,
“_value” : “v1.0”
},
“ProvisioningCode” : {
“_object” : false,
“_timestamp” : ISODate(“2020-09-18T15:15:40.934Z”),
“_type” : “xsd:string”,
“_value” : “”
},
“SoftwareVersion” : {
“_object” : false,
“_timestamp” : ISODate(“2020-09-18T15:15:40.934Z”),
“_type” : “xsd:string”,
“_value” : “6.47.3”
},
“_object” : true
},
“ManagementServer” : {
“AliasBasedAddressing” : {
“_object” : false,
“_timestamp” : ISODate(“2020-09-18T15:15:40.934Z”),
“_type” : “xsd:boolean”,
“_value” : false
},
“ConnectionRequestURL” : {
“_object” : false,
“_timestamp” : ISODate(“2020-09-18T15:15:40.934Z”),
“_type” : “xsd:string”,
“_value” : “http://maskedip:7547/maskedhash”
},
“ParameterKey” : {
“_object” : false,
“_timestamp” : ISODate(“2020-09-18T15:15:40.934Z”),
“_type” : “xsd:string”,
“_value” : “”
},
“_object” : true
},
“RootDataModelVersion” : {
“_object” : false,
“_timestamp” : ISODate(“2020-09-18T15:15:40.934Z”),
“_type” : “xsd:string”,
“_value” : “2.11”
},
“_object” : true
},
“_deviceId” : {
“_Manufacturer” : “MikroTik”,
“_OUI” : “E48D8C”,
“_ProductClass” : “hAP ac²”,
“_SerialNumber” : “maskedserial”
},
“_lastBoot” : ISODate(“2020-09-18T15:15:40.933Z”),
“_lastInform” : ISODate(“2020-09-18T15:15:40.933Z”),
“_registered” : ISODate(“2020-09-18T15:14:07.444Z”),
“Downloads” : {
“1” : {
“CompleteTime” : {
“_object” : false,
“_timestamp” : ISODate(“2020-09-18T15:14:23.103Z”),
“_type” : “xsd:dateTime”,
“_value” : ISODate(“1970-01-01T00:00:00Z”),
“_writable” : false
},
“Download” : {
“_object” : false,
“_timestamp” : ISODate(“2020-09-18T15:14:23.105Z”),
“_type” : “xsd:dateTime”,
“_value” : ISODate(“2020-09-18T15:14:23.100Z”),
“_writable” : true
},
“FileName” : {
“_object” : false,
“_timestamp” : ISODate(“2020-09-18T15:14:23.103Z”),
“_type” : “xsd:string”,
“_value” : “routerconfig.rsc”,
“_writable” : true
},
“FileType” : {
“_object” : false,
“_timestamp” : ISODate(“2020-09-18T15:14:23.103Z”),
“_type” : “xsd:string”,
“_value” : “3 Vendor Configuration File”,
“_writable” : true
},
“LastDownload” : {
“_object” : false,
“_timestamp” : ISODate(“2020-09-18T15:14:23.103Z”),
“_type” : “xsd:dateTime”,
“_value” : ISODate(“1970-01-01T00:00:00Z”),
“_writable” : false
},
“LastFileName” : {
“_object” : false,
“_timestamp” : ISODate(“2020-09-18T15:14:23.103Z”),
“_type” : “xsd:string”,
“_value” : “”,
“_writable” : false
},
“LastFileType” : {
“_object” : false,
“_timestamp” : ISODate(“2020-09-18T15:14:23.103Z”),
“_type” : “xsd:string”,
“_value” : “”,
“_writable” : false
},
“LastTargetFileName” : {
“_object” : false,
“_timestamp” : ISODate(“2020-09-18T15:14:23.103Z”),
“_type” : “xsd:string”,
“_value” : “”,
“_writable” : false
},
“StartTime” : {
“_object” : false,
“_timestamp” : ISODate(“2020-09-18T15:14:23.103Z”),
“_type” : “xsd:dateTime”,
“_value” : ISODate(“1970-01-01T00:00:00Z”),
“_writable” : false
},
“TargetFileName” : {
“_object” : false,
“_timestamp” : ISODate(“2020-09-18T15:14:23.103Z”),
“_type” : “xsd:string”,
“_value” : “”,
“_writable” : true
},
“_object” : true,
“_timestamp” : ISODate(“2020-09-18T15:14:23.100Z”),
“_writable” : true
},
“_object” : true,
“_writable” : true
},
“_lastBootstrap” : ISODate(“2020-09-18T15:15:40.933Z”)

    > db.operations.find().pretty()
{
    "_id" : "E48D8C-hAP%20ac%C2%B2-maskedserial:174a1ce7ee10000",
    "name" : "Download",
    "timestamp" : ISODate("2020-09-18T15:21:38.785Z"),
    "provisions" : "[[\"download\",\"3 Vendor Configuration File\",\"routerconfig.rsc\",\"\"]]",
    "channels" : {
            "task_5f64d0823c7f78c4a11bf4fb" : 1
    },
    "retries" : "{}",
    "args" : "{\"instance\":\"1\",\"fileType\":\"3 Vendor Configuration File\",\"fileName\":\"routerconfig.rsc\",\"targetFileName\":\"\"}"
}
>
6

@zaidka are the changes written on the database “on a call basis” or they are all “commited” at the end of the session? If that’s the case, a “not properly closed” session like this session timeout would “rollback” the changes, right?

7

Correct. Although it shouldn’t be like that. In the case of events (e.g. 0 BOOTSTRAP) and transfer complete messages, the CPE will not resend them if original session wasn’t properly closed. Genie needs to commit that information even in case of session timeout.

8

Are you currently working on this? Otherwise I will try to figure it out

9

Ok, well I’ll try to code a solution for that

10

It probably won’t be properly fixed soon unfortunately. As a temporary workaround you can patch your fork to make it preemptively terminate the session whenever a TransferComplete is received. Add something like the following code snippet towards the end of transferComplete function in cwmp.ts:

if (sessionContext.deviceId.startsWith("ABCDEF-123-")) {
  logger.accessWarn({
    sessionContext: sessionContext,
    message: "Terminating session preemptively"
  });
  return writeResponse(sessionContext, res, true);
}
1 Like
11

Thanks Zaid,

This is very helpful. Works like a charm