[fritzbox-tr064] doesn't recognize incoming call

[staehler]

I updated from 2.2.0-20171109111930-1 to 2.3.0-20180129232532-1 and since than my item Active_Call only recognizes some of the events, but not all. So the item Active_Call remains ON after a phone call or it remains OFF during a phone call. items-file:

Switch Active_Call "Telefon klingelt [%s]" {fritzboxtr064="callmonitor_ringing" }
Call    fboxIncomingCall    "Incoming call: [%1$s to %2$s]" {fritzboxtr064="callmonitor_ringing" } 
Call    fboxIncomingCallResolved    "Incoming call: [%1$s to %2$s]" {fritzboxtr064="callmonitor_ringing:resolveName" } 

My rule lookes like

rule "Fritzbox Active Call ON"
when
    Item Active_Call changed from OFF to ON or
then
    if (Active_Call.state==ON) {

        val incCall = fboxIncomingCallResolved.state as StringListType
        val caller = incCall.getValue(1)

        var String text= "Eingehender Anruf: " + caller
... do somethings ...   
end

I think that the rule error has nothing to do with the item error, but maybe it gives a hint or you see an obvious mistake in it? This rule error happend also before the upgrade sometimes.

Expected Behavior

On every call openhab should switch the item Active_Call ON and after the call it should return to OFF.

Current Behavior

As explained above, openhab doesn't recognize every event on the item Active_Call, but some. In this log example you see, that Active_Call didn't switched ON (it was ON because of a call in the last days), but switched OFF after the call.

> 2018-02-12 20:38:09.435 [vent.ItemStateChangedEvent] - fboxIncomingCallResolved changed from 98168691 to 98168691,Lydia, Ziller (Home)
> 2018-02-12 20:38:09.437 [vent.ItemStateChangedEvent] - fboxIncomingCall changed from xxxxx to xxxxx,yyyy
> 2018-02-12 20:39:14.888 [vent.ItemStateChangedEvent] - fboxOutgoingCall changed from  to
> 2018-02-12 20:39:14.893 [vent.ItemStateChangedEvent] - fboxIncomingCallResolved changed from xxxxxx,yyyy, zzzz(Home) to
> 2018-02-12 20:39:14.895 [vent.ItemStateChangedEvent] - Active_Call changed from ON to OFF
> 2018-02-12 20:39:14.900 [vent.ItemStateChangedEvent] - fboxIncomingCall changed from xxxxxx,yyyyy to

Possible Solution

no idea

Steps to Reproduce (for bugs)

Do some calls and observe the behaviour of the item Active_Call.

Context

I'ld like to lower the volume of my music, when a call comes in. Also the resolved phone number shall appear on my squeezebox display.

Your Environment

Linux server 3.16.0-5-amd64 #1 SMP Debian 3.16.51-3+deb8u1 (2018-01-08) x86_64 GNU/Linux

openhab2 2.3.0-20180206033048-1 oracle-java8-installer 8u161-1 webupd8 oracle-java8-set-default 8u161-1 webupd8 java-common 0.52

[staehler]

Now I found the time to support the debug log. This failure is unfortunately unresolved and calles aren't proper closed, so the Call remains ON when the phone call is already finished. Please be aware that the sorting of the log lines is inverted. So the latest events is on the top of the log. tr064_debug.log

[9037568]

Well, this is definitely wrong. It's harmless but missing information:

2018-03-03 19:01:14.358 [DEBUG] [g.fritzboxtr064.internal.CallMonitor] - NO name resolving requested in item fboxTAM0Switch. Setting external no. to

It also appears your rule is broken, unless there's a copy/paste error:

when
    Item Active_Call changed from OFF to ON or
then

[9037568]

Care to try out this test jar? I've fixed the logging issues.

[staehler]

You're right, it's a copy&paste failure. On this OR follows a further trigger but hasn't copied here. The phone number might haven't been resolved, because this was a caller who doesn't transmitt his phone number. Just to clarify, which logging issue do you mean? The inverted loglines came because I filtered and exported them from my splunk (central log collection and log analysing) installation.

[9037568]

The logging issue I was referring to is this one (which the log message I quoted above reveals).

The code fails to provide a placeholder for the final passed method argument, so it never gets displayed.

This:

logger.debug("name resolving requested in item {}. Setting external no. to", itemName,
                                callerName);

should be this:

logger.debug("name resolving requested in item {}. Setting external no. to {}", itemName,
                                callerName);

[staehler]

Thanks for the clarification. I just need to substitute this file /var/lib/openhab2/tmp/mvn/org/openhab/binding/org.openhab.binding.fritzboxtr064/1.12.0-SNAPSHOT/org.openhab.binding.fritzboxtr064-1.12.0-SNAPSHOT.jar Right?

If not please advice. Thank you.

[9037568]

I always just drop it in the addons directory and expect OH to take care of it.

[staehler]

Well, I dropped the file in /usr/share/openhab2/addons but the Console shows me

openhab> bundle:list |grep -i tr064
231 │ Active   │  80 │ 1.12.0.201802180209    │ openHAB FritzboxTr064 Binding

I assume this is not yours ... Do I need to restart openhab? Sorry, for this questions, I didn't do this before.

BTW: /usr/share/openhab2/addons was empty, although I activated lots of bindings.

[9037568]

I think doing a bundle:uninstall followed by a restart should get the update running.

[staehler]

The update runs now, but after uninstall an restart there were two bindings

openhab> bundle:list |grep -i tr064
262 │ Resolved │  80 │ 1.12.0.201803040459    │ openHAB FritzboxTr064 Binding
263 │ Active   │  80 │ 1.12.0.201802180209    │ openHAB FritzboxTr064 Binding

so I needed to uninstall 263 again, and start 262. Might be, that I have two tr064 bindings at the next restart.

[staehler]

Sorry for the delay. It seems both tr064 bindings (yours and the official one) disturb each other. After restarting openhab both bindings were active again, but I recognised this just today.

Nevertheless I made an OH upgrade 2 weeks ago and since then the problem seems reduced. I made a statistics (with splunk) about the length of phone calls. I'm going to watch this further. 2 calls of 31 calls lasted more than 1000 minutes, which shows me that this calls where not correctly recognised despite of the OH upgrade.

Just a remark here, it seems the debugging iterates through all tr064-items (not sure if this makes sense?). The external number is void, might be that the caller didn't transmit its phone number, so don't worry about it.

openhab.log.7:2018-03-12 17:24:44.200 [DEBUG] [g.fritzboxtr064.internal.CallMonitor] - NO name resolving requested in item fboxDslUpstreamNoiseMargin. Setting external no. to
openhab.log.7:2018-03-12 17:24:44.201 [DEBUG] [g.fritzboxtr064.internal.CallMonitor] - NO name resolving requested in item fboxWanPhysicalLinkStatus. Setting external no. to
openhab.log.7:2018-03-12 17:24:44.202 [DEBUG] [g.fritzboxtr064.internal.CallMonitor] - NO name resolving requested in item fboxOutgoingCall. Setting external no. to
openhab.log.7:2018-03-12 17:24:44.203 [DEBUG] [g.fritzboxtr064.internal.CallMonitor] - NO name resolving requested in item fboxDslDownstreamNoiseMargin. Setting external no. to
openhab.log.7:2018-03-12 17:24:44.205 [DEBUG] [g.fritzboxtr064.internal.CallMonitor] - NO name resolving requested in item fboxDslDownstreamAttenuation. Setting external no. to
openhab.log.7:2018-03-12 17:24:44.208 [DEBUG] [g.fritzboxtr064.internal.CallMonitor] - NO name resolving requested in item WLAN24. Setting external no. to
openhab.log.7:2018-03-12 17:24:44.210 [DEBUG] [g.fritzboxtr064.internal.CallMonitor] - NO name resolving requested in item fboxDslEnable. Setting external no. to
openhab.log.7:2018-03-12 17:24:44.212 [DEBUG] [g.fritzboxtr064.internal.CallMonitor] - NO name resolving requested in item fboxDslDownstreamCurrRate. Setting external no. to
openhab.log.7:2018-03-12 17:24:44.214 [DEBUG] [g.fritzboxtr064.internal.CallMonitor] - NO name resolving requested in item fboxDslUpstreamMaxRate. Setting external no. to
openhab.log.7:2018-03-12 17:24:44.216 [DEBUG] [g.fritzboxtr064.internal.CallMonitor] - NO name resolving requested in item fboxName. Setting external no. to
openhab.log.7:2018-03-12 17:24:44.217 [DEBUG] [g.fritzboxtr064.internal.CallMonitor] - NO name resolving requested in item fboxDslUpstreamCurrRate. Setting external no. to
openhab.log.7:2018-03-12 17:24:44.218 [DEBUG] [g.fritzboxtr064.internal.CallMonitor] - NO name resolving requested in item GWLAN. Setting external no. to
openhab.log.7:2018-03-12 17:24:44.220 [DEBUG] [g.fritzboxtr064.internal.CallMonitor] - name resolving requested in item fboxIncomingCallResolved. Setting external no. to
openhab.log.7:2018-03-12 17:24:44.221 [DEBUG] [g.fritzboxtr064.internal.CallMonitor] - NO name resolving requested in item fboxWanLayer1UpstreamMaxBitRate. Setting external no. to
openhab.log.7:2018-03-12 17:24:44.228 [DEBUG] [g.fritzboxtr064.internal.CallMonitor] - NO name resolving requested in item fboxMissedCalls. Setting external no. to
openhab.log.7:2018-03-12 17:24:44.230 [DEBUG] [g.fritzboxtr064.internal.CallMonitor] - NO name resolving requested in item fboxWanLayer1DownstreamMaxBitRate. Setting external no. to
openhab.log.7:2018-03-12 17:24:44.232 [DEBUG] [g.fritzboxtr064.internal.CallMonitor] - NO name resolving requested in item WLAN50. Setting external no. to
openhab.log.7:2018-03-12 17:24:44.235 [DEBUG] [g.fritzboxtr064.internal.CallMonitor] - NO name resolving requested in item Active_Call. Setting external no. to
openhab.log.7:2018-03-12 17:24:44.238 [DEBUG] [g.fritzboxtr064.internal.CallMonitor] - NO name resolving requested in item fboxDslStatus. Setting external no. to
openhab.log.7:2018-03-12 17:24:44.258 [DEBUG] [g.fritzboxtr064.internal.CallMonitor] - NO name resolving requested in item fboxDslHECErrors. Setting external no. to
openhab.log.7:2018-03-12 17:24:44.263 [DEBUG] [g.fritzboxtr064.internal.CallMonitor] - NO name resolving requested in item fboxWanAccessType. Setting external no. to
openhab.log.7:2018-03-12 17:24:44.266 [DEBUG] [g.fritzboxtr064.internal.CallMonitor] - NO name resolving requested in item fboxIncomingCall. Setting external no. to
openhab.log.7:2018-03-12 17:24:44.269 [DEBUG] [g.fritzboxtr064.internal.CallMonitor] - NO name resolving requested in item fboxTAM0Switch. Setting external no. to
openhab.log.7:2018-03-12 17:24:44.274 [DEBUG] [g.fritzboxtr064.internal.CallMonitor] - NO name resolving requested in item fboxDslFECErrors. Setting external no. to
openhab.log.7:2018-03-12 17:24:44.276 [DEBUG] [g.fritzboxtr064.internal.CallMonitor] - NO name resolving requested in item fboxIP. Setting external no. to
openhab.log.7:2018-03-12 17:24:44.279 [DEBUG] [g.fritzboxtr064.internal.CallMonitor] - NO name resolving requested in item fboxDslDownstreamMaxRate. Setting external no. to
openhab.log.7:2018-03-12 17:24:44.282 [DEBUG] [g.fritzboxtr064.internal.CallMonitor] - NO name resolving requested in item Active_Call_Out. Setting external no. to
openhab.log.7:2018-03-12 17:24:44.285 [DEBUG] [g.fritzboxtr064.internal.CallMonitor] - NO name resolving requested in item fboxDslUpstreamAttenuation. Setting external no. to
openhab.log.7:2018-03-12 17:24:44.289 [DEBUG] [g.fritzboxtr064.internal.CallMonitor] - NO name resolving requested in item fboxTAM0NewMsg. Setting external no. to
openhab.log.7:2018-03-12 17:24:44.292 [DEBUG] [g.fritzboxtr064.internal.CallMonitor] - NO name resolving requested in item fboxDslCRCErrors. Setting external no. to
openhab.log.7:2018-03-12 17:24:44.294 [DEBUG] [g.fritzboxtr064.internal.CallMonitor] - NO name resolving requested in item fboxWanTotalBytesSent. Setting external no. to
openhab.log.7:2018-03-12 17:24:44.297 [DEBUG] [g.fritzboxtr064.internal.CallMonitor] - NO name resolving requested in item fboxWanTotalBytesReceived. Setting external no. to

[staehler]

Meanwhile this has obviously been fixed, as it works now.