flicd service keeps restarting

[Norien]

I've had this problem for a while now running on a raspberry pi 3, no other bluetooth devices connected with a fresh install of raspbian strech. The flicd service keeps restarting fairly often with this log

Available HCI devices found:
hci0

Trying hci0
Flic server is now up and running!
HCI socket busy, bringing down and then retrying
Successfully bound HCI socket
Initialization of Bluetooth controller done!
Accepted new client

the flic button is installed and working fairly well within home assistant however each time I see a reconnect home assistant must be restarted to once again see the button. I'm not really sure where to start to get this fixed. Any help is appreciated!

[Emill]

That's just the message when it starts. Could you tell what it prints when it quits? Also a btmon log would be nice (run sudo btmon in another terminal).

[Norien]

pi@pi-3:~ $ hciconfig
hci0:   Type: Primary  Bus: UART
        BD Address: B9:27:EB:0C:B9:51  ACL MTU: 1021:8  SCO MTU: 64:1
        UP RUNNING
        RX bytes:6620744 acl:0 sco:0 events:116 errors:0
        TX bytes:10187 acl:8 sco:0 commands:1479 errors:0

this seems to repeat over and over again

> HCI Event: LE Meta Event (0x3e) plen 43                                                                                   [hci0] 54.984937
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Scannable undirected - ADV_SCAN_IND (0x02)
        Address type: Public (0x00)
        Address: 54:60:09:F3:E0:66 (Google, Inc.)
        Data length: 31
        Flags: 0x06
          LE General Discoverable Mode
          BR/EDR Not Supported
        16-bit Service UUIDs (complete): 1 entry
          Google (0xfe9f)
        Service Data (UUID 0xfe9f): 0274655664786b6233476b510000015ea54647f1
        RSSI: -95 dBm (0xa1)
> HCI Event: LE Meta Event (0x3e) plen 43                                                                                   [hci0] 55.034412
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Scannable undirected - ADV_SCAN_IND (0x02)
        Address type: Public (0x00)
        Address: 54:60:09:FF:98:23 (Google, Inc.)
        Data length: 31
        Flags: 0x06
          LE General Discoverable Mode
          BR/EDR Not Supported
        16-bit Service UUIDs (complete): 1 entry
          Google (0xfe9f)
        Service Data (UUID 0xfe9f): 0000000000000000000000000000000000000000
        RSSI: -73 dBm (0xb7)

[Emill]

Please turn off that home assistant option constant scan.

i.e. set "discovery" to false.

[Norien]

home assistant isn't installed on this raspberry pi, it's actually on another Ubuntu server without any Bluetooth at all.

Not sure what you mean by constant scan option...

[Emill]

Just updated my answer ;)

[Emill]

discovery is defined here: https://home-assistant.io/components/binary_sensor.flic/

[Norien]

ok trying that now :)

binary_sensor:
  - platform: flic
    host: 192.168.0.46
    discovery: false

new output for btmon

^Cpi@pi-3:~ $ sudo btmon
Bluetooth monitor ver 5.43
= Note: Linux version 4.9.41-v7+ (armv7l)                                                                                                             0.871447
= Note: Bluetooth subsystem version 2.22                                                                                                              0.871455
= New Index: B9:27:EB:0C:B9:51 (Primary,UART,hci0)                                                                                             [hci0] 0.871458
= Open Index: B9:27:EB:0C:B9:51                                                                                                                [hci0] 0.871461
= Index Info: B9:27:EB:0C:B9:51 (Broadcom Corporation)                                                                                         [hci0] 0.871465
@ USER Open: flicd (privileged) version 2.22                                                                                          {0x0002} [hci0] 0.871468
@ MGMT Open: bluetoothd (privileged) version 1.14                                                                                            {0x0001} 0.871472
@ MGMT Open: btmon (privileged) version 1.14                                                                                                 {0x0003} 0.871701

[Norien]

got some more data from the btmon during a crash

https://hastebin.com/ekijixumel.log

not sure what any of that means but it grabs a couple cycles where it fails

[Emill]

What is the output of flicd when it crashes (quits)?

[Norien]

all I see is the flic.log showing this

Available HCI devices found:
hci0

Trying hci0
Flic server is now up and running!
HCI socket busy, bringing down and then retrying
Successfully bound HCI socket
Initialization of Bluetooth controller done!
Accepted new client

[Emill]

Oh.. It seems the log is cleared every time it restarts in that case. Could you work around that, for example by not restarting it?

[Norien]

I removed the restart lines from the service file and reloaded the daemon, just waiting for it to fail in my daemon.log I'm getting this

Sep 21 15:04:04 pi-3 systemd[1]: Started Session c30 of user pi.
Sep 21 15:04:04 pi-3 systemd[1]: Stopping flicd Service...
Sep 21 15:04:06 pi-3 bluetoothd[6757]: Failed to obtain handles for "Service Changed" characteristic
Sep 21 15:04:06 pi-3 bluetoothd[6757]: Sap driver initialization failed.
Sep 21 15:04:06 pi-3 systemd[1]: Stopped flicd Service.
Sep 21 15:04:06 pi-3 bluetoothd[6757]: sap-server: Operation not permitted (1)
Sep 21 15:04:06 pi-3 systemd[1]: Started flicd Service.
Sep 21 15:04:06 pi-3 bluetoothd[6757]: Failed to set mode: Failed (0x03)

[Emill]

What's the reason behind "Stopping flicd Service..."? Who's doing that?

[Norien]

Every time that flic failed in home assistant I had it restart the flic service delay and restart HASS so the button would still work ( just tried to disable that for testing )

[Emill]

I suggest you turn off home assistant, bluetoothd and all other stuff and just run flicd from the command line and use for example simpleclient. If that turns out to run smoothly then there must be something wrong with your setup when you use home assistant.

[Norien]

here is flic.log after it fails in HASS

Available HCI devices found:
hci0

Trying hci0
Flic server is now up and running!
HCI socket busy, bringing down and then retrying
Successfully bound HCI socket
Initialization of Bluetooth controller done!
Accepted new client
Client EOF
A client was disconnected
Accepted new client

HASS error is

2017-09-21 18:30:01 ERROR (MainThread) [homeassistant.helpers.template] Error parsing value: 'value_json' is undefined (value: , template: {{ value_json.processes.flic }}

[Norien]

System appears to be stable at this point. Not sure what fixed it. Possibly turning off the discovery was relieved enough pressure. I also changed the power supply to the pi to an iPad USB power adapter.