TR064 - maconline - presence switch go off randomly

Hello Community,

since, the network binding is not available for OH3 I´m using the TR064 binding with maconline to get my presence tracked, the last two weeks.
After some days I was wondering why all my lights went off couple of times a day - presence off = all lights off.

When I checked the logs I can see that randomly all my devices (Apple products) (for testing only one at the moment) went for some seconds offline in the binding.
In the FritzBox the mac addresses were never offline also disabling WiFi will let the mac address online for up to 5 minutes.

Is there a knowing problem in the binding or a refresh problem (fritzbox 60 seconds; lan device 30 seconds)?
In the network binding I know when you do arpping on Apple devices there must be a special setup for refresh / timeouts but I´m not aware of a config like that in TR064.

I also patched my system to the latest stable version - 3.0.1 but still the same error.

Thank you in advance for some hints.

Greetings
Disaster

Please show the openHab log when this happens.

Here the logs, when the MACs went offline nothing else happened.
What is really weird that the ON/OFF happens all 10/11 minutes - so there must be something with the binding itself.

2021-04-07 08:13:38.917 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Systeminfo_Openhab1_MemoryUsedPercent' changed from 8.4 to 8.3

2021-04-07 08:13:53.922 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Systeminfo_Openhab1_CpuTemperature' changed from 42.8 °C to 43.3 °C

2021-04-07 08:14:04.681 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'iPhone_Diana_Online' changed from ON to OFF

2021-04-07 08:14:04.914 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'iPhone_Steffen_Online' changed from ON to OFF

2021-04-07 08:14:04.918 [INFO ] [hab.event.GroupItemStateChangedEvent] - Item 'G_Presence' changed from ON to OFF through iPhone_Steffen_Online

2021-04-07 08:14:08.939 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Systeminfo_Openhab1_MemoryUsedPercent' changed from 8.3 to 8.4

2021-04-07 08:14:19.838 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Systeminfo_Openhab1_CpuUptime' changed from 662.0 to 663.0

2021-04-07 08:14:23.945 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Systeminfo_Openhab1_CpuTemperature' changed from 43.3 °C to 42.8 °C

2021-04-07 08:14:30.140 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'iPhone_Steffen_Online' changed from OFF to ON

2021-04-07 08:14:30.143 [INFO ] [hab.event.GroupItemStateChangedEvent] - Item 'G_Presence' changed from OFF to ON through iPhone_Steffen_Online

2021-04-07 08:14:30.202 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'iPhone_Diana_Online' changed from OFF to ON

2021-04-07 08:15:08.985 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Systeminfo_Openhab1_CpuTemperature' changed from 42.8 °C to 43.8 °C

2021-04-07 08:15:19.840 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Systeminfo_Openhab1_CpuUptime' changed from 663.0 to 664.0

2021-04-07 08:15:23.996 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Systeminfo_Openhab1_CpuTemperature' changed from 43.8 °C to 43.3 °C
2021-04-07 05:52:45.506 [INFO ] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_48A6B8AE60D801400 is absent (thing sonos:OneSL:RINCON_48A6B8AE60D801400)
2021-04-07 05:52:45.515 [INFO ] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_48A6B8AE5EB801400 is absent (thing sonos:OneSL:RINCON_48A6B8AE5EB801400)
2021-04-07 05:52:45.529 [INFO ] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_48A6B885FC1001400 is absent (thing sonos:One:RINCON_48A6B885FC1001400)
2021-04-07 05:52:46.632 [INFO ] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_48A6B885FC1001400 is present (thing sonos:One:RINCON_48A6B885FC1001400)
2021-04-07 05:52:46.856 [INFO ] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_347E5C93846C01400 is present (thing sonos:Beam:RINCON_347E5C93846C01400)
2021-04-07 05:53:25.162 [INFO ] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_48A6B8AE60D801400 is present (thing sonos:OneSL:RINCON_48A6B8AE60D801400)
2021-04-07 05:53:42.422 [INFO ] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_48A6B8AE5EB801400 is present (thing sonos:OneSL:RINCON_48A6B8AE5EB801400)
2021-04-07 08:03:38.633 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'allgemein.items'

Please set the bindings log level to TRACE, of it happens that often, you should be able to manage the amount of logs collected. Please show the requests before the macs go offline.

I´m not that openHab special, so can you explain how…

  • enable trace for the binding
  • where can I see the advance logs then

Thanks for a quick update

Logging | openHAB

log:set TRACE org.openhab.binding.tr064

I recommend looking at the karaf console.

i’m not sure what that means, since the network binding is available and i’m using it for presence:

Ah you are right, I never checked it after I upgraded it to 3.0 - on the beginning it was not available.
In the past I did it as well BUT Apple Devices / Fritz Box and Fritz Repeater in Mesh are doing stupid stuff. I setuped a static IP on the Fritz for my Apple devices but they don´t like it and when I walk in the house and connect to another repeater it will get a DHCP address for a 2nd MAC address… so I thought the MACONLINE would be a good solution.

I don´t see that binding:

openhab> log:list
Logger                                             │ Level
───────────────────────────────────────────────────┼──────
ROOT                                               │ INFO
javax.jmdns                                        │ ERROR
javax.mail                                         │ ERROR
openhab.event                                      │ INFO
openhab.event.AddonEvent                           │ ERROR
openhab.event.InboxUpdatedEvent                    │ ERROR
openhab.event.ItemAddedEvent                       │ ERROR
openhab.event.ItemChannelLinkAddedEvent            │ ERROR
openhab.event.ItemChannelLinkRemovedEvent          │ ERROR
openhab.event.ItemRemovedEvent                     │ ERROR
openhab.event.ItemStateEvent                       │ ERROR
openhab.event.RuleAddedEvent                       │ ERROR
openhab.event.RuleRemovedEvent                     │ ERROR
openhab.event.RuleStatusInfoEvent                  │ ERROR
openhab.event.StartlevelEvent                      │ ERROR
openhab.event.ThingAddedEvent                      │ ERROR
openhab.event.ThingRemovedEvent                    │ ERROR
openhab.event.ThingStatusInfoEvent                 │ ERROR
openhab.event.ThingUpdatedEvent                    │ ERROR
org.apache.cxf.jaxrs.sse.SseEventSinkImpl          │ ERROR
org.apache.karaf.jaas.modules.audit                │ INFO
org.apache.karaf.kar.internal.KarServiceImpl       │ ERROR
org.apache.karaf.shell.ssh.SshUtils                │ ERROR
org.apache.karaf.shell.support                     │ OFF
org.apache.sshd                                    │ ERROR
org.eclipse.lsp4j                                  │ OFF
org.jupnp                                          │ ERROR
org.openhab                                        │ INFO
org.ops4j.pax.url.mvn.internal.AetherBasedResolver │ ERROR
org.ops4j.pax.web.pax-web-runtime                  │ OFF
su.litvak.chromecast.api.v2.Channel                │ ERROR

It will be added if you set type the command above

1 Like

I didn´t find something special, the only thing which reappears hundreds of time is

<NewHostName>Dianas-iPhone</NewHostName>
<NewHostName>Dianas-iPhone</NewHostName>
<NewHostName>Dianas-iPhone</NewHostName>
<NewHostName>Dianas-iPhone</NewHostName>

PS: log:set OFF org.openhab.binding.tr064 is ok or must it be on ERROR, once I´m done with checking.

It´s happening between two refreshes of the Sub Device Lan - but still nothing special :expressionless::

21:51:16.161 [TRACE] [ing.tr064.internal.soap.SOAPConnector] - Request: <SOAP-ENV:Envelope xmlns:SOAP-ENV="http://schemas.xmlsoap.org/soap/envelope/" SOAP-ENV:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/"><SOAP-ENV:Header/><SOAP-ENV:Body><u:GetInfo xmlns:u="urn:dslforum-org:service:WLANConfiguration:3"/></SOAP-ENV:Body></SOAP-ENV:Envelope>
21:51:16.186 [TRACE] [ing.tr064.internal.soap.SOAPConnector] - Re-Auth needed.
21:51:16.267 [TRACE] [ing.tr064.internal.soap.SOAPConnector] - Received response: <?xml version="1.0"?>
 <s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/" s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/">
<s:Body>
<u:GetInfoResponse xmlns:u="urn:dslforum-org:service:WLANConfiguration:3">
<NewEnable>0</NewEnable>
<NewStatus>Disabled</NewStatus>
<NewMaxBitRate>Auto</NewMaxBitRate>
<NewChannel>11</NewChannel>
<NewSSID>XXXXXXXXXXXXXXXXXXXX</NewSSID>
<NewBeaconType>11iandWPA3</NewBeaconType>
<NewX_AVM-DE_PossibleBeaconTypes>None,11i,11iandWPA3,OWETrans</NewX_AVM-DE_PossibleBeaconTypes>
<NewMACAddressControlEnabled>0</NewMACAddressControlEnabled>
<NewStandard></NewStandard>
<NewBSSID>XXXXXXXXXXXXXXX</NewBSSID>
<NewBasicEncryptionModes>None</NewBasicEncryptionModes>
<NewBasicAuthenticationMode>None</NewBasicAuthenticationMode>
<NewMaxCharsSSID>32</NewMaxCharsSSID>
<NewMinCharsSSID>1</NewMinCharsSSID>
<NewAllowedCharsSSID>0123456789ABCDEFGHIJKLMNOPQRSTUVWXYZabcdefghijklmnopqrstuvwxyz !&quot;#$%&amp;&apos;()*+,-./:;&lt;=&gt;?@[\]^_`{|}~</NewAllowedCharsSSID>
<NewMinCharsPSK>64</NewMinCharsPSK>
<NewMaxCharsPSK>64</NewMaxCharsPSK>
<NewAllowedCharsPSK>0123456789ABCDEFabcdef</NewAllowedCharsPSK>
</u:GetInfoResponse>
</s:Body>
</s:Envelope>
21:51:23.371 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'iPhone_Diana_Online' changed from ON to OFF
21:51:23.589 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'iPhone_Steffen_Online' changed from ON to OFF
21:51:23.593 [INFO ] [nhab.event.GroupItemStateChangedEvent] - Item 'G_Presence' changed from ON to OFF through iPhone_Steffen_Online
21:51:24.209 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'Systeminfo_Openhab1_CpuTemperature' changed from 43.3 °C to 43.8 °C
21:51:35.614 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'MultisensorEsszimmerTemperature' changed from 23.01 °C to 23.04 °C
21:51:35.628 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'MultisensorEsszimmerHumidity' changed from 32.79 % to 32.71 %
21:51:39.220 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'Systeminfo_Openhab1_CpuTemperature' changed from 43.8 °C to 43.3 °C
21:51:46.296 [TRACE] [ing.tr064.internal.soap.SOAPConnector] - Request: <SOAP-ENV:Envelope xmlns:SOAP-ENV="http://schemas.xmlsoap.org/soap/envelope/" SOAP-ENV:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/"><SOAP-ENV:Header/><SOAP-ENV:Body><u:GetSpecificHostEntry xmlns:u="urn:dslforum-org:service:Hosts:1"><NewMACAddress>XXXXXXXXXXXXXXXXX</NewMACAddress></u:GetSpecificHostEntry></SOAP-ENV:Body></SOAP-ENV:Envelope>
21:51:46.445 [TRACE] [ing.tr064.internal.soap.SOAPConnector] - Received response: <?xml version="1.0"?>
 <s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/" s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/">
<s:Body>
<u:GetSpecificHostEntryResponse xmlns:u="urn:dslforum-org:service:Hosts:1">
<NewIPAddress>XXXXXXXXXXXX</NewIPAddress>
<NewAddressSource>DHCP</NewAddressSource>
<NewLeaseTimeRemaining>862518</NewLeaseTimeRemaining>
<NewInterfaceType>802.11</NewInterfaceType>
<NewActive>1</NewActive>
<NewHostName>sbriemleiPhone</NewHostName>
</u:GetSpecificHostEntryResponse>
</s:Body>
</s:Envelope>

DEFAULT resets the logger to the default value

There must be requests before. Look for GetSpecificHostEntry in the request.

Found it but it´s always the correct MAC address in:

21:51:16.091 [TRACE] [ing.tr064.internal.soap.SOAPConnector] - Request: <SOAP-ENV:Envelope xmlns:SOAP-ENV="http://schemas.xmlsoap.org/soap/envelope/" SOAP-ENV:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/"><SOAP-ENV:Header/><SOAP-ENV:Body><u:GetSpecificHostEntry xmlns:u="urn:dslforum-org:service:Hosts:1"><NewMACAddress>MY_MAC_ADDRESS</NewMACAddress></u:GetSpecificHostEntry></SOAP-ENV:Body></SOAP-ENV:Envelope>

PS: must I generate for each MAC a own SUB-DEVICE (LAN) or can I add multiple like I had it, now?

Yes, because that’s the request. We need to look at the response to that request, because that determines what the channels state is set to.

Several macs on one subdevice are fine.

The response is always my correct IP address and leas times.

21:51:16.121 [TRACE] [ing.tr064.internal.soap.SOAPConnector] - Received response: <?xml version="1.0"?>
 <s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/" s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/">
<s:Body>
<u:GetSpecificHostEntryResponse xmlns:u="urn:dslforum-org:service:Hosts:1">
<NewIPAddress>MY_IP_ADDRESS</NewIPAddress>
<NewAddressSource>DHCP</NewAddressSource>
<NewLeaseTimeRemaining>847661</NewLeaseTimeRemaining>
<NewInterfaceType>802.11</NewInterfaceType>
<NewActive>1</NewActive>
<NewHostName>Dianas-iPhone</NewHostName>
</u:GetSpecificHostEntryResponse>
</s:Body>
</s:Envelope>
21:51:16.161 [TRACE] [ing.tr064.internal.soap.SOAPConnector] - Request: <SOAP-ENV:Envelope xmlns:SOAP-ENV="http://schemas.xmlsoap.org/soap/envelope/" SOAP-ENV:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/"><SOAP-ENV:Header/><SOAP-ENV:Body><u:GetInfo xmlns:u="urn:dslforum-org:service:WLANConfiguration:3"/></SOAP-ENV:Body></SOAP-ENV:Envelope>
21:51:16.186 [TRACE] [ing.tr064.internal.soap.SOAPConnector] - Re-Auth needed.
21:51:16.267 [TRACE] [ing.tr064.internal.soap.SOAPConnector] - Received response: <?xml version="1.0"?>
 <s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/" s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/">
<s:Body>
<u:GetInfoResponse xmlns:u="urn:dslforum-org:service:WLANConfiguration:3">
<NewEnable>0</NewEnable>
<NewStatus>Disabled</NewStatus>
<NewMaxBitRate>Auto</NewMaxBitRate>
<NewChannel>11</NewChannel

And after that the channel is set to OFF? <NewActive>1</NewActive> should result in ON.

The SUB-DEVICE has a refresh of 30 seconds so I get each 30 seconds a

<NewActive>1</NewActive>

also when the state is “ON”

Example:
Refresh at 21:51:16.161
with NewActive = 1
and on 21:51:23.593
the Presence went OFF

Added my Windows 10 Laptop with the MAC, now for testing - maybe it´s like on the network binding Apple related the problem.

From the code it’s nearly impossible that <NewActive>1</NewActive> results in OFF. Maybe a request failed in between?