[avmfritz] Call monitoring does not work

[maniac103]

Expected Behavior

When connecting an Item to the incoming_call channel of the Fritz!Box thing, the Item should be updated whenever there is an incoming call.

Current Behavior

Item stays at NULL permanently.

Steps to Reproduce (for Bugs)

• Set up Fritz!Box bridge thing via UI
• Connect channel to Item via items file: Call FonIncomingCall "Anruf [%s]" {channel="avmfritz:fritzbox:192_168_178_1:incoming_call" }
• Monitor that Item via UI

Your Environment

• openHAB 3.0 (deb package)
• OpenJDK 11
• Ubuntu 18.04

Relevant log excerpt on binding restart (with org.openhab.core.thing and org.openhab.binding.avmfritz set to DEBUG)

2021-01-06 13:31:51.356 [DEBUG] [core.thing.internal.ThingManagerImpl] - Thing handler factory 'AVMFritzHandlerFactory' added
2021-01-06 13:31:51.358 [DEBUG] [core.thing.internal.ThingManagerImpl] - Not registering a handler at this point. The thing types of bundle 'org.openhab.binding.avmfritz' are not fully loaded yet.
2021-01-06 13:31:51.363 [DEBUG] [ery.AVMFritzUpnpDiscoveryParticipant] - discovered on /192.168.178.10
2021-01-06 13:31:51.364 [DEBUG] [ery.AVMFritzUpnpDiscoveryParticipant] - discovered: AVM Berlin FRITZ!Box 7590 (UI) 1und1 (FRITZ!Box 7590 (UI)) at 192.168.178.1
2021-01-06 13:31:51.364 [DEBUG] [core.thing.internal.ThingManagerImpl] - Calling 'AVMFritzHandlerFactory.registerHandler()' for thing 'avmfritz:fritzbox:192_168_178_1'.
2021-01-06 13:31:51.369 [DEBUG] [core.thing.internal.ThingManagerImpl] - Configuration of 'avmfritz:fritzbox:192_168_178_1' needs [ipAddress], has [syncTimeout, protocol, password, asyncTimeout, ipAddress, pollingInterval].
2021-01-06 13:31:51.370 [DEBUG] [core.thing.internal.ThingManagerImpl] - Config description for 'avmfritz:incoming_call' is not resolvable, assuming 'avmfritz:fritzbox:192_168_178_1:incoming_call' is initializable
2021-01-06 13:31:51.370 [DEBUG] [core.thing.internal.ThingManagerImpl] - Config description for 'avmfritz:outgoing_call' is not resolvable, assuming 'avmfritz:fritzbox:192_168_178_1:outgoing_call' is initializable
2021-01-06 13:31:51.370 [DEBUG] [core.thing.internal.ThingManagerImpl] - Config description for 'avmfritz:active_call' is not resolvable, assuming 'avmfritz:fritzbox:192_168_178_1:active_call' is initializable
2021-01-06 13:31:51.371 [DEBUG] [core.thing.internal.ThingManagerImpl] - Config description for 'avmfritz:call_state' is not resolvable, assuming 'avmfritz:fritzbox:192_168_100_1:call_state' is initializable
2021-01-06 13:31:51.371 [DEBUG] [core.thing.internal.ThingManagerImpl] - Config description for 'avmfritz:apply_template' is not resolvable, assuming 'avmfritz:fritzbox:192_168_178_1:apply_template' is initializable
2021-01-06 13:31:51.372 [DEBUG] [core.thing.internal.ThingManagerImpl] - Calling initialize handler for thing 'avmfritz:fritzbox:192_168_178_1' at 'org.openhab.binding.avmfritz.internal.handler.BoxHandler@693a325a'.
2021-01-06 13:31:51.779 [DEBUG] [ternal.hardware.FritzAhaWebInterface] - GET response complete: <?xml version="1.0" encoding="utf-8"?><SessionInfo><SID>0000000000000000</SID><Challenge>d05fc326</Challenge><BlockTime>0</BlockTime><Rights></Rights></SessionInfo>
2021-01-06 13:31:52.065 [DEBUG] [ternal.hardware.FritzAhaWebInterface] - GET response complete: <?xml version="1.0" encoding="utf-8"?><SessionInfo><SID>85419d00e2cde7ef</SID><Challenge>ec07c812</Challenge><BlockTime>0</BlockTime><Rights><Name>Dial</Name><Access>2</Access><Name>App</Name><Access>2</Access><Name>HomeAuto</Name><Access>2</Access><Name>BoxAdmin</Name><Access>2</Access><Name>Phone</Name><Access>2</Access><Name>NAS</Name><Access>2</Access></Rights></SessionInfo>
2021-01-06 13:31:52.067 [DEBUG] [ternal.hardware.FritzAhaWebInterface] - Starting with SID 85419d00e2cde7ef
2021-01-06 13:31:52.067 [DEBUG] [al.handler.AVMFritzBaseBridgeHandler] - Start polling job at interval 15s
2021-01-06 13:31:53.068 [DEBUG] [al.handler.AVMFritzBaseBridgeHandler] - Poll FRITZ!Box for updates avmfritz:fritzbox:192_168_178_1
2021-01-06 13:31:53.625 [DEBUG] [nal.hardware.FritzAhaContentExchange] - HTTPS response: 200
2021-01-06 13:31:53.632 [DEBUG] [nal.hardware.FritzAhaContentExchange] - HTTPS response: 200
2021-01-06 13:31:53.632 [DEBUG] [nal.hardware.FritzAhaContentExchange] - response complete: <devicelist version="1" fwversion="7.21"></devicelist>
2021-01-06 13:31:56.640 [DEBUG] [itz.internal.callmonitor.CallMonitor] - Received raw call string from fbox: 06.01.21 13:32:52;RING;0;REDACTED;REDACTED;SIP0;
2021-01-06 13:31:56.644 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler BoxHandler of thing avmfritz:fritzbox:192_168_178_1 tried updating channel incoming_call although the handler was already disposed.
2021-01-06 13:31:56.644 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler BoxHandler of thing avmfritz:fritzbox:192_168_178_1 tried updating channel outgoing_call although the handler was already disposed.
2021-01-06 13:31:56.645 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler BoxHandler of thing avmfritz:fritzbox:192_168_178_1 tried updating channel active_call although the handler was already disposed.
2021-01-06 13:31:56.645 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler BoxHandler of thing avmfritz:fritzbox:192_168_178_1 tried updating channel call_state although the handler was already disposed.
2021-01-06 13:31:57.646 [DEBUG] [itz.internal.callmonitor.CallMonitor] - Received raw call string from fbox: 06.01.21 13:32:53;DISCONNECT;0;0;
2021-01-06 13:31:57.647 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler BoxHandler of thing avmfritz:fritzbox:192_168_178_1 tried updating channel incoming_call although the handler was already disposed.
2021-01-06 13:31:57.647 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler BoxHandler of thing avmfritz:fritzbox:192_168_178_1 tried updating channel outgoing_call although the handler was already disposed.
2021-01-06 13:31:57.648 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler BoxHandler of thing avmfritz:fritzbox:192_168_178_1 tried updating channel active_call although the handler was already disposed.
2021-01-06 13:31:57.648 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler BoxHandler of thing avmfritz:fritzbox:192_168_178_1 tried updating channel call_state although the handler was already disposed.
2021-01-06 13:32:08.070 [DEBUG] [al.handler.AVMFritzBaseBridgeHandler] - Poll FRITZ!Box for updates avmfritz:fritzbox:192_168_178_1
2021-01-06 13:32:08.618 [DEBUG] [nal.hardware.FritzAhaContentExchange] - HTTPS response: 200
2021-01-06 13:32:08.625 [DEBUG] [nal.hardware.FritzAhaContentExchange] - HTTPS response: 200
2021-01-06 13:32:08.626 [DEBUG] [nal.hardware.FritzAhaContentExchange] - response complete: <devicelist version="1" fwversion="7.21"></devicelist>

From a quick glance at the code, I'm not sure how this (handler being considered disposed) could happen though, since no evidence of unregisterHandler being called can be found in the log. Hoping for insight from your side ;-)

[cweitkamp]

Did you try to restart the binding or even openHAB itself?

I figured that there is no initial refresh of the Call Monitor Channels. I added this feature in #9734.

[maniac103]

I tried restarting the binding, yes. I now also tried removing and re-adding the box Thing, after which the call monitor started working (as in: my Item started updating). FWIW, the 'Handler BoxHandler of thing ... tried updating channel call_state although the handler was already disposed.' messages are still there, despite it working. I wonder what's going on there, multiple handlers being activated or something?

[cweitkamp]

Sounds a little bit like an orphaned thread. I hope nothing critical. I am really wondering if it is still present after a full restart. Another possibility will be to create a thread dump.

[maniac103]

Is there a written explanation for doing the thread dump somewhere I can use? I'd do the dump then and try a full restart afterwards.

[cweitkamp]

Have a look here.

[maniac103]

jstack output indeed shows 2 call monitor threads running. Relevant excerpt:

"OH-binding-avmfritz:fritzbox:192_168_178_1" #376866 daemon prio=5 os_prio=0 cpu=777,82ms elapsed=4055,07s tid=0x00007f8600337800 nid=0x35d8 waiting on condition  [0x00007f85849d9000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
        at java.lang.Thread.sleep([email protected]/Native Method)
        at org.openhab.binding.avmfritz.internal.callmonitor.CallMonitor$CallMonitorThread.run(CallMonitor.java:145)

...

"OH-binding-avmfritz:fritzbox:192_168_178_1" #319356 daemon prio=5 os_prio=0 cpu=30406,69ms elapsed=164016,82s tid=0x00007f8600226000 nid=0xde4 waiting on condition  [0x00007f85acf58000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
        at java.lang.Thread.sleep([email protected]/Native Method)
        at org.openhab.binding.avmfritz.internal.callmonitor.CallMonitor$CallMonitorThread.run(CallMonitor.java:145)

If I delete the box Thing, indeed only one of the two threads is gone.
So it looks like the call monitor thread indeed isn't shut down correctly under some conditions. From the code it's not obvious to me how that happened (I only found some minor cleanup potential, see this diff).
I'll leave it up to you whether to close this issue or keeping it open for investigating the orphaned thread (I can leave the system in that state for now and provide data if needed); my immediate problem is solved for now in any case.

[cweitkamp]

Thanks for your research. I improved the thread handling - beside an initial refresh of the channels - in #9734.