FactoryReset Loop

1

Hi,

I am currently trying to investigate a factory reset loop between at least AVM devices and GenieACS v1.1.3 and v1.2.3. In fact I just updated to v1.2.3 to see if this issues was fixed. But unfortunately it seems the problem still persists. I am trying to factory reset a device via CWMP and later provision it using a preset matching the serial number pointing to a provision, which reacts on the EVENT “0 BOOTSTRAP”.

PRESET:
{"_id":“prov-2”,“weight”:0,“precondition”:"DeviceID.SerialNumber = “3810D5697542"”,“events”:{“0 BOOTSTRAP”:true},“configurations”:[{“type”:“provision”,“name”:“prov-2”,“args”:null}]}

I initiated the factory reset using the API. The following task can be retrieved:
{"_id":“5fd11bb5c334895a945152b8”,“name”:“factoryReset”,“device”:“00040E-FRITZ%21Box-3810D5697542”,“timestamp”:“2020-12-09T18:47:17.430Z”}

On next Inform (I didn’t use connection_request) GenieACS correctly tries to factory reset the device. However, the task is never removed. Thus, on next Bootstrap Inform (since the device did a factory reset) it will be factory reset again. This leads to a factory reset loop of the device. In effect it will be never be provisioned and remains unusable unless I manually remove the task.

I upload a pcap file (https://apackets.com/pcaps?pcap=219f86032cf97227b8849c23f0c76c7f.pcap&view=charts) showing three factory resets. Looking closely at the first TCP session, one can see, that there is no FactoryResetRespone from the device. I can understand, that GenieACS won’t remove the task unless a FactoryResetRespone is received.

However, in the next two retries one can clearly see the response (packet number 23 and 81). You may want to filter for ‘xml.tag == “cwmp:FactoryResetResponse/”’. GenieACS furthermore is trying to get parameter names and values after the factory reset was initiated. This will of course time out at some point, since the devices is resetting. From my point of view GenieACS should only do the FactoryReset, without further commands.

Even if this fails (and maybe as a workaround), I would expect that GenieACS deletes all FactoryReset tasks if the device sends an Inform with event “0 BOOTSTRAP”.

Below you can find the Log during the three factory resets:

LOOP0

2020-12-09T18:50:05.881Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: Inform; cpeRequestId=“100” informEvent=“4 VALUE CHANGE,1 BOOT,0 BOOTSTRAP” informRetryCount=0
2020-12-09T18:50:05.887Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648d6cead0000” acsRequestName=“FactoryReset”
2020-12-09T18:50:35.890Z [ERROR] 127.0.0.1: Session timeout; sessionTimestamp=1607539805869 deviceId=“00040E-FRITZ%21Box-3810D5697542”

LOOP1

2020-12-09T18:52:56.135Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: Inform; cpeRequestId=“100” informEvent=“4 VALUE CHANGE,1 BOOT,0 BOOTSTRAP” informRetryCount=0
2020-12-09T18:52:56.142Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648d967c00000” acsRequestName=“FactoryReset”
2020-12-09T18:52:56.382Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648d967c00200” acsRequestName=“GetParameterNames”
2020-12-09T18:52:56.403Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648d967c00201” acsRequestName=“GetParameterNames”
2020-12-09T18:52:56.430Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648d967c00202” acsRequestName=“GetParameterNames”
2020-12-09T18:52:56.468Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648d967c00203” acsRequestName=“GetParameterNames”
2020-12-09T18:52:56.488Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648d967c00204” acsRequestName=“GetParameterNames”
2020-12-09T18:52:56.496Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648d967c00205” acsRequestName=“GetParameterNames”
2020-12-09T18:52:56.547Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648d967c00206” acsRequestName=“GetParameterNames”
2020-12-09T18:52:56.555Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648d967c00207” acsRequestName=“GetParameterValues”
2020-12-09T18:52:56.609Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648d967c00208” acsRequestName=“GetParameterNames”
2020-12-09T18:52:56.661Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648d967c00209” acsRequestName=“GetParameterNames”
2020-12-09T18:52:56.713Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648d967c0020a” acsRequestName=“GetParameterNames”
2020-12-09T18:52:56.721Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648d967c0020b” acsRequestName=“GetParameterNames”
2020-12-09T18:52:56.735Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648d967c0020c” acsRequestName=“GetParameterValues”
2020-12-09T18:52:56.786Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648d967c0020d” acsRequestName=“GetParameterNames”
2020-12-09T18:52:56.801Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648d967c0020e” acsRequestName=“GetParameterNames”
2020-12-09T18:52:56.851Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648d967c0020f” acsRequestName=“GetParameterValues”
2020-12-09T18:52:56.915Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648d967c00210” acsRequestName=“GetParameterNames”
2020-12-09T18:53:26.916Z [ERROR] 127.0.0.1: Session timeout; sessionTimestamp=1607539976128 deviceId=“00040E-FRITZ%21Box-3810D5697542”

LOOP2

2020-12-09T18:55:49.017Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: Inform; cpeRequestId=“100” informEvent=“4 VALUE CHANGE,1 BOOT,0 BOOTSTRAP” informRetryCount=0
2020-12-09T18:55:49.023Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648dc0b100000” acsRequestName=“FactoryReset”
2020-12-09T18:55:49.204Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648dc0b100200” acsRequestName=“GetParameterNames”
2020-12-09T18:55:49.219Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648dc0b100201” acsRequestName=“GetParameterNames”
2020-12-09T18:55:49.240Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648dc0b100202” acsRequestName=“GetParameterNames”
2020-12-09T18:55:49.267Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648dc0b100203” acsRequestName=“GetParameterNames”
2020-12-09T18:55:49.282Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648dc0b100204” acsRequestName=“GetParameterNames”
2020-12-09T18:55:49.289Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648dc0b100205” acsRequestName=“GetParameterNames”
2020-12-09T18:55:49.337Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648dc0b100206” acsRequestName=“GetParameterNames”
2020-12-09T18:55:49.343Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648dc0b100207” acsRequestName=“GetParameterValues”
2020-12-09T18:55:49.393Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648dc0b100208” acsRequestName=“GetParameterNames”
2020-12-09T18:55:49.442Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648dc0b100209” acsRequestName=“GetParameterNames”
2020-12-09T18:56:19.443Z [ERROR] 127.0.0.1: Session timeout; sessionTimestamp=1607540149008 deviceId=“00040E-FRITZ%21Box-3810D5697542”

TASK removed

2020-12-09T18:58:46.189Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: Inform; cpeRequestId=“100” informEvent=“4 VALUE CHANGE,1 BOOT,0 BOOTSTRAP” informRetryCount=0
2020-12-09T18:58:46.209Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648debf250100” acsRequestName=“GetParameterNames”
2020-12-09T18:58:46.266Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648debf250101” acsRequestName=“GetParameterNames”
2020-12-09T18:58:46.287Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648debf250102” acsRequestName=“GetParameterNames”
2020-12-09T18:58:46.314Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648debf250103” acsRequestName=“GetParameterNames”
2020-12-09T18:58:46.329Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648debf250104” acsRequestName=“GetParameterNames”
2020-12-09T18:58:46.336Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648debf250105” acsRequestName=“GetParameterNames”
2020-12-09T18:58:46.384Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648debf250106” acsRequestName=“GetParameterNames”
2020-12-09T18:58:46.391Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648debf250107” acsRequestName=“GetParameterValues”
2020-12-09T18:58:46.440Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648debf250108” acsRequestName=“GetParameterNames”
2020-12-09T18:58:46.489Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648debf250109” acsRequestName=“GetParameterNames”
2020-12-09T18:58:46.538Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648debf25010a” acsRequestName=“GetParameterNames”
2020-12-09T18:58:46.544Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648debf25010b” acsRequestName=“GetParameterNames”
2020-12-09T18:58:46.554Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648debf25010c” acsRequestName=“GetParameterValues”
2020-12-09T18:58:46.605Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648debf25010d” acsRequestName=“GetParameterNames”
2020-12-09T18:58:46.615Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648debf25010e” acsRequestName=“GetParameterNames”
2020-12-09T18:58:46.663Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648debf25010f” acsRequestName=“GetParameterValues”
2020-12-09T18:58:46.722Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648debf250110” acsRequestName=“GetParameterNames”
2020-12-09T18:58:46.753Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648debf250111” acsRequestName=“GetParameterNames”
2020-12-09T18:58:49.076Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648debf250112” acsRequestName=“GetParameterNames”
2020-12-09T18:58:49.320Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648debf250113” acsRequestName=“GetParameterNames”
2020-12-09T18:58:49.499Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648debf250114” acsRequestName=“GetParameterValues”
2020-12-09T18:58:49.568Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648debf250115” acsRequestName=“AddObject”
2020-12-09T18:58:49.593Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648debf250116” acsRequestName=“GetParameterValues”
2020-12-09T18:58:49.624Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648debf250117” acsRequestName=“SetParameterValues”
2020-12-09T18:58:49.939Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648debf250118” acsRequestName=“GetParameterNames”
2020-12-09T18:58:50.669Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648debf250119” acsRequestName=“SetParameterValues”
2020-12-09T18:58:50.806Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648debf25011a” acsRequestName=“GetParameterNames”
2020-12-09T18:58:50.882Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648debf25011b” acsRequestName=“GetParameterValues”
2020-12-09T18:58:50.981Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648debf25011c” acsRequestName=“GetParameterValues”
2020-12-09T18:58:51.034Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648debf25011d” acsRequestName=“SetParameterValues”
2020-12-09T18:59:20.212Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: Inform; cpeRequestId=“101” informEvent=“4 VALUE CHANGE” informRetryCount=0
2020-12-09T18:59:59.397Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-444E6D6FACE4: Inform; cpeRequestId=“2179” informEvent=“2 PERIODIC” informRetryCount=0
2020-12-09T18:59:59.414Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-444E6D6FACE4: ACS request; acsRequestId=“17648dfdd1b0100” acsRequestName=“GetParameterValues”
2020-12-09T19:03:25.901Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-444E6DA82E4F: Inform; cpeRequestId=“1616” informEvent=“2 PERIODIC” informRetryCount=0
2020-12-09T19:03:25.915Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-444E6DA82E4F: ACS request; acsRequestId=“17648e303c70100” acsRequestName=“GetParameterValues”
2020-12-09T19:03:51.453Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: Inform; cpeRequestId=“102” informEvent=“2 PERIODIC” informRetryCount=0
2020-12-09T19:03:51.471Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648e367680100” acsRequestName=“GetParameterNames”
2020-12-09T19:03:51.495Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648e367680101” acsRequestName=“GetParameterNames”
2020-12-09T19:03:51.546Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648e367680102” acsRequestName=“GetParameterValues”
2020-12-09T19:03:51.571Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648e367680103” acsRequestName=“GetParameterNames”
2020-12-09T19:03:51.577Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648e367680104” acsRequestName=“GetParameterValues”
2020-12-09T19:03:51.599Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648e367680105” acsRequestName=“GetParameterNames”
2020-12-09T19:03:51.605Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648e367680106” acsRequestName=“GetParameterNames”
2020-12-09T19:03:51.615Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648e367680107” acsRequestName=“GetParameterNames”
2020-12-09T19:03:52.661Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17648e367680108” acsRequestName=“GetParameterValues”

2

Try the latest master branch. It should resolve this issue (for the most part). Let me explain:

The issue here seems to be that the CPE is disconnecting after the FactoryReset command and before the TR-069 session is considered to be successfully terminated. Hence the session eventually times out and Genie simply forgets all updates that took place during the session. That is why you get repeating factory reset commands. The latest patches address this by committing the session state even if the session does not terminate successfully.

I would argue that this is a CPE bug as well. While the ACS should tolerate unsuccessful session termination, the client should not exploit measures that are clearly meant for handling exceptional cases in its normal operation. But regardless, as per the spec:

The CPE MUST initiate the factory reset procedure only after successful completion of the Session.

Although I hate to rely on a strict literal interpretation of the spec to get the point across. The spec does seem to be vague and potentially even contradictory at times when it comes to the behavior around successful vs unsuccessful sessions.

Unfortunately that may not be possible. What if there are other tasks in the queue? And what about the presets that it still needs to process after competing the tasks?

3

I think you meant “considered to be unsuccessfully terminated”, not “successfully”.

4

Thanks, the spec seems pretty clear on that point. I’ll try contacting the vendor regarding this issue.

In the meantime I tried the master branch. The task is deleted and a fault is created, when the session times out. Unfortunately, approximately three minutes later on the next BOOTSTRAP (09:15:30.152Z), GenieACS won’t retry the fault/provision. It answers with InformResponse and afterwards with “No Content”. Instead, I would expect GenieACS to retry the fault/provision.

Luckily, 15 minutes later (09:30:34.539Z) the CPE sends a VALUE CHANGE, after which GenieACS runs the provision and clears the fault. Generally, the devices won’t perform periodic informs after factory reset. Thus, it may happen that the fault/provision won’t be re-run anytime soon. This would potentially leave the devices unprovisioned for a long time.

I guess what I’m asking is: Why is the fault/provision not retried on the next BOOTSTRAP (09:15:30.152Z)?

2020-12-14T09:12:49.797Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: Inform; cpeRequestId=“100” informEvent=“4 VALUE CHANGE,1 BOOT,0 BOOTSTRAP” informRetryCount=0
2020-12-14T09:12:49.827Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“176608619420000” acsRequestName=“FactoryReset”
2020-12-14T09:12:50.036Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“176608619420200” acsRequestName=“GetParameterNames”
2020-12-14T09:12:50.272Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“176608619420201” acsRequestName=“GetParameterNames”
2020-12-14T09:12:50.316Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“176608619420202” acsRequestName=“GetParameterNames”
2020-12-14T09:12:50.358Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“176608619420203” acsRequestName=“GetParameterNames”
2020-12-14T09:12:50.379Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“176608619420204” acsRequestName=“GetParameterNames”
2020-12-14T09:12:50.390Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“176608619420205” acsRequestName=“GetParameterNames”
2020-12-14T09:12:50.442Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“176608619420206” acsRequestName=“GetParameterNames”
2020-12-14T09:12:50.451Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“176608619420207” acsRequestName=“GetParameterValues”
2020-12-14T09:12:50.519Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“176608619420208” acsRequestName=“GetParameterNames”
2020-12-14T09:12:50.570Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“176608619420209” acsRequestName=“GetParameterNames”
2020-12-14T09:12:50.623Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17660861942020a” acsRequestName=“GetParameterNames”
2020-12-14T09:12:50.633Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17660861942020b” acsRequestName=“GetParameterNames”
2020-12-14T09:12:50.648Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“17660861942020c” acsRequestName=“GetParameterValues”
2020-12-14T09:13:20.652Z [ERROR] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: Session timeout; sessionTimestamp=1607937169730
2020-12-14T09:13:20.653Z [WARN] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: Channel has faulted; channel=“default” retries=0 faultCode=“session_terminated” faultMessage=“The TR-069 session was unsuccessfully terminated”

2020-12-14T09:15:30.152Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: Inform; cpeRequestId=“100” informEvent=“4 VALUE CHANGE,1 BOOT,0 BOOTSTRAP” informRetryCount=0

2020-12-14T09:30:34.539Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: Inform; cpeRequestId=“101” informEvent=“4 VALUE CHANGE” informRetryCount=0
2020-12-14T09:30:34.551Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“176609658a40000” acsRequestName=“GetParameterNames”
2020-12-14T09:30:34.567Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“176609658a40001” acsRequestName=“GetParameterNames”
2020-12-14T09:30:34.588Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“176609658a40002” acsRequestName=“GetParameterNames”
2020-12-14T09:30:34.613Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“176609658a40003” acsRequestName=“GetParameterNames”
2020-12-14T09:30:34.625Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“176609658a40004” acsRequestName=“GetParameterNames”
2020-12-14T09:30:34.631Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“176609658a40005” acsRequestName=“GetParameterNames”
2020-12-14T09:30:34.680Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“176609658a40006” acsRequestName=“GetParameterNames”
2020-12-14T09:30:34.686Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“176609658a40007” acsRequestName=“GetParameterValues”
2020-12-14T09:30:34.737Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“176609658a40008” acsRequestName=“GetParameterNames”
2020-12-14T09:30:34.786Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“176609658a40009” acsRequestName=“GetParameterNames”
2020-12-14T09:30:34.838Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“176609658a4000a” acsRequestName=“GetParameterNames”
2020-12-14T09:30:34.848Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“176609658a4000b” acsRequestName=“GetParameterNames”
2020-12-14T09:30:34.861Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“176609658a4000c” acsRequestName=“GetParameterValues”
2020-12-14T09:30:34.913Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“176609658a4000d” acsRequestName=“GetParameterNames”
2020-12-14T09:30:34.933Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“176609658a4000e” acsRequestName=“GetParameterNames”
2020-12-14T09:30:34.987Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“176609658a4000f” acsRequestName=“GetParameterValues”
2020-12-14T09:30:35.045Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“176609658a40010” acsRequestName=“GetParameterNames”
2020-12-14T09:30:35.092Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“176609658a40011” acsRequestName=“GetParameterNames”
2020-12-14T09:30:35.826Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“176609658a40012” acsRequestName=“GetParameterNames”
2020-12-14T09:30:35.954Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“176609658a40013” acsRequestName=“GetParameterNames”
2020-12-14T09:30:36.081Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“176609658a40014” acsRequestName=“GetParameterValues”
2020-12-14T09:30:36.167Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“176609658a40015” acsRequestName=“AddObject”
2020-12-14T09:30:36.178Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“176609658a40016” acsRequestName=“GetParameterValues”
2020-12-14T09:30:36.205Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“176609658a40017” acsRequestName=“SetParameterValues”
2020-12-14T09:30:36.502Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“176609658a40018” acsRequestName=“GetParameterNames”
2020-12-14T09:30:37.175Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“176609658a40019” acsRequestName=“SetParameterValues”
2020-12-14T09:30:37.313Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“176609658a4001a” acsRequestName=“GetParameterNames”
2020-12-14T09:30:37.389Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“176609658a4001b” acsRequestName=“GetParameterValues”
2020-12-14T09:30:37.448Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“176609658a4001c” acsRequestName=“GetParameterValues”
2020-12-14T09:30:37.501Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: ACS request; acsRequestId=“176609658a4001d” acsRequestName=“SetParameterValues”
2020-12-14T09:31:04.576Z [INFO] 127.0.0.1 00040E-FRITZ%21Box-3810D5697542: Inform; cpeRequestId=“102” informEvent=“4 VALUE CHANGE” informRetryCount=0

5

I switched from 1.2.2 to 1.2.4 and now I get very often the error message:
“The TR-069 session was unsuccessfully terminated”

I have not started debugging.

Instance A runs behind a nginx reverse proxy (https), with zyxel devices. There I get this error message.

Instance B is directly accessed over HTTP. There I did not see this message jet. It does only have 2 Clients, a phone and a FRITZ!Box

6

@olebowle
Is your GenieACS instance behind a reverse proxy?

7

Yes, we do reverse proxy GenieACS and thus, terminate TLS of the CWMP session with Apache. On localhost it is unencrypted for debugging purpose.

1 Like
8

Ok, it looks like, there is a problem with reverse proxies.
I have created for this issue a own topic:

It appears from 1.2.3 upwards.

9

I have a problem, when using a Nnginx proxy pass to local cwmp host I get an error:

Channel has faulted; channel = “default” retries = 0 faultCode = “session_terminated” faultMessage = “The TR-069 session was unsuccessfully terminated”