tree 80bf63a2909b14a65792d815a44f56c8603704a7
parent bfbc29c9d292a537414d8cf8e4a78ef2ee6f07a3
author Andrew Jeffery <andrew@aj.id.au> 1557289969 +0930
committer Andrew Jeffery <andrew@aj.id.au> 1557293873 +0930

btbridged: Empty out timerfd on alarm

While chasing down some failures to boot it was observed that btbridged
exhibited some odd behaviour:

```
[BTBRIDGED 1556110700.790817149] Completed request with seq 0xbe, netfn 0x07, lun 0x00, cmd 0x06, cc 0x00
[BTBRIDGED 1556110700.793924606] Sending dbus signal with seq 0xbf, netfn 0x06, lun 0x00, cmd 0x24
[BTBRIDGED 1556110704.899868679] Sending dbus signal with seq 0xc0, netfn 0x3a, lun 0x00, cmd 0x5a
[BTBRIDGED 1556110705.927016825] Timeout on msg with seq: 0xbf
[BTBRIDGED 1556110705.927279813] Adjusting timer for next element
[BTBRIDGED 1556110705.927460055] Successfully wrote 5 of 5 bytes to /dev/ipmi-bt-host
[BTBRIDGED 1556110705.927600822] Turning off POLLOUT for the BT in poll()
[BTBRIDGED 1556110705.927708377] Completed request with seq 0xbf, netfn 0x07, lun 0x00, cmd 0x24, cc 0xce
[BTBRIDGED 1556110705.927831285] Timeout on msg with seq: 0xc0
[BTBRIDGED 1556110705.928012375] Disabling timer, no elements remain in queue
[BTBRIDGED 1556110705.928195404] Successfully wrote 5 of 5 bytes to /dev/ipmi-bt-host
[BTBRIDGED 1556110705.928335565] Turning off POLLOUT for the BT in poll()
[BTBRIDGED 1556110705.928442110] Completed request with seq 0xc0, netfn 0x3b, lun 0x00, cmd 0x5a, cc 0xce
[BTBRIDGED 1556110705.950386593] Processed 1 dbus events
[BTBRIDGED 1556110706.013493351] Processed 1 dbus events
```

Notably, at 1556110705.927831285 we time out message 0xc0, which only arrived
at 1556110704.899868679, which is well short of the 5 second timeout it should
have been allowed. Message 0xbe arrived at 1556110700.790817149, and is
legitimately timed out at 1556110705.927016825.

The timerfd is re-armed to fire at the appropriate interval as the BT
message queue is pumped, but given we're still seeing messages timed out
early we have other problems.

As it turns out, at no point was the alarm count read out of the
timerfd, which means that POLLIN will forever be true once a single
timeout occurs.

I hackily reproduced the bug with the following patch:

```
$ git diff
diff --git a/btbridged.c b/btbridged.c
index c6a749684f89..c34ecbb41b99 100644

Change-Id: Id021bf86ae6b712711564aeff74395c4dc06f86f
--- a/btbridged.c
+++ b/btbridged.c
@@ -573,11 +578,13 @@ static int dispatch_bt(struct btbridged_context *context)
                }

                /* Note we only actually keep the request data in the queue when debugging */
+#if 0
                r = sd_bus_send(context->bus, msg, NULL);
                if (r < 0) {
                        MSG_ERR("Couldn't emit dbus signal: %s\n", strerror(-r));
                        goto out1_free;
                }
+#endif
                r = 0;
 out1_free:
                sd_bus_message_unref(msg);
```

And then some shell hackery under qemu to emulate some BT messages:

```
root@witherspoon:~# for i in a b; do echo -n $( echo -n ??; echo -n $i; yes ? | tr -d '\n' | dd bs=61 count=1 ) | dd bs=64 count=1; sleep 3; done | /tmp/btbridged --vv --d /dev/stdin
[BTBRIDGED 1557293495.775887696] Debug logging
[BTBRIDGED 1557293495.776840496] Starting
[BTBRIDGED 1557293495.816003184] Registering dbus methods/signals
[BTBRIDGED 1557293495.817261760] Requesting dbus name: org.openbmc.HostIpmi
[BTBRIDGED 1557293495.842606534] Getting dbus file descriptors
[BTBRIDGED 1557293495.843622809] Opening /dev/stdin
[BTBRIDGED 1557293495.845227524] Creating timer fd
[BTBRIDGED 1557293495.847197691] Entering polling loop
1+0 records in
1+0 records out
[BTBRIDGED 1557293495.875593512] Processed 1 dbus events
[BTBRIDGED 1557293495.877544568] Processed 1 dbus events
[BTBRIDGED 1557293495.885870039] Processed 1 dbus events
[BTBRIDGED 1557293495.891684660] Processed 1 dbus events
1+0 records in
1+0 records out
[BTBRIDGED 1557293495.920918697] Processed 1 dbus events
[BTBRIDGED 1557293495.922578725] Sending dbus signal with seq 0x61, netfn 0x0f, lun 0x03, cmd 0x3f
[BTBRIDGED 1557293495.923731282]        0x3f 0x3f 0x3f 0x3f 0x3f 0x3f 0x3f 0x3f
[BTBRIDGED 1557293495.926144192]        0x3f 0x3f 0x3f 0x3f 0x3f 0x3f 0x3f 0x3f
[BTBRIDGED 1557293495.940668484]        0x3f 0x3f 0x3f 0x3f 0x3f 0x3f 0x3f 0x3f
[BTBRIDGED 1557293495.943877389]        0x3f 0x3f 0x3f 0x3f 0x3f 0x3f 0x3f 0x3f
[BTBRIDGED 1557293495.945245499]        0x3f 0x3f 0x3f 0x3f 0x3f 0x3f 0x3f 0x3f
[BTBRIDGED 1557293495.946143553]        0x3f 0x3f 0x3f 0x3f 0x3f 0x3f 0x3f 0x3f
[BTBRIDGED 1557293495.947038900]        0x3f 0x3f 0x3f 0x3f 0x3f 0x3f 0x3f 0x3f
[BTBRIDGED 1557293495.950191643]        0x3f 0x3f 0x3f 0x3f
[BTBRIDGED 1557293495.957989078] Processed 1 dbus events
[BTBRIDGED 1557293495.966219600] Processed 1 dbus events
1+0 records in
1+0 records out
1+0 records in
1+0 records out
[BTBRIDGED 1557293499.057933902] Sending dbus signal with seq 0x62, netfn 0x0f, lun 0x03, cmd 0x3f
[BTBRIDGED 1557293499.058611231]        0x3f 0x3f 0x3f 0x3f 0x3f 0x3f 0x3f 0x3f
[BTBRIDGED 1557293499.059376316]        0x3f 0x3f 0x3f 0x3f 0x3f 0x3f 0x3f 0x3f
[BTBRIDGED 1557293499.060071947]        0x3f 0x3f 0x3f 0x3f 0x3f 0x3f 0x3f 0x3f
[BTBRIDGED 1557293499.061051535]        0x3f 0x3f 0x3f 0x3f 0x3f 0x3f 0x3f 0x3f
[BTBRIDGED 1557293499.067664737]        0x3f 0x3f 0x3f 0x3f 0x3f 0x3f 0x3f 0x3f
[BTBRIDGED 1557293499.068453296]        0x3f 0x3f 0x3f 0x3f 0x3f 0x3f 0x3f 0x3f
[BTBRIDGED 1557293499.069132483]        0x3f 0x3f 0x3f 0x3f 0x3f 0x3f 0x3f 0x3f
[BTBRIDGED 1557293499.069834457]        0x3f 0x3f 0x3f 0x3f
[BTBRIDGED 1557293500.925481584] Timeout on msg with seq: 0x61
[BTBRIDGED 1557293500.929968742] Adjusting timer for next element
[BTBRIDGED 1557293500.936309380] Successfully wrote 5 of 5 bytes to /dev/stdin
[BTBRIDGED 1557293500.939482567] Turning off POLLOUT for the BT in poll()
[BTBRIDGED 1557293500.942887753] Completed request with seq 0x61, netfn 0x10, lun 0x03, cmd 0x3f, cc 0xce
[BTBRIDGED 1557293500.946057103] Timeout on msg with seq: 0x62
[BTBRIDGED 1557293500.950179980] Sending dbus signal with seq 0x61, netfn 0x10, lun 0x03, cmd 0x3f
[BTBRIDGED 1557293500.953666296]        0xce
[BTBRIDGED 1557293500.957920607] Adjusting timer for next element
[BTBRIDGED 1557293500.959637523] Successfully wrote 5 of 5 bytes to /dev/stdin
[BTBRIDGED 1557293500.961051977] Turning off POLLOUT for the BT in poll()
[BTBRIDGED 1557293500.962846347] Completed request with seq 0x62, netfn 0x10, lun 0x03, cmd 0x3f, cc 0xce
[BTBRIDGED 1557293500.964777807] Sending dbus signal with seq 0x62, netfn 0x10, lun 0x03, cmd 0x3f
[BTBRIDGED 1557293500.965874687]        0xce

...
```

From this we see that the timeout for message 0x62 is processed in 2 seconds,
rather than the 5 seconds it should be allocated.

Subsequent to the patch we get the following:

```
root@witherspoon:~# for i in a b; do echo -n $( echo -n ??; echo -n $i; yes ? | tr -d '\n' | dd bs=61 count=1 ) | dd bs=64 count=1; sleep 3; done | /tmp/btbridged --vv --d /dev/stdin
[BTBRIDGED 1557293375.976924218] Debug logging
[BTBRIDGED 1557293375.977834675] Starting
[BTBRIDGED 1557293376.006553426] Registering dbus methods/signals
[BTBRIDGED 1557293376.007820971] Requesting dbus name: org.openbmc.HostIpmi
[BTBRIDGED 1557293376.029322731] Getting dbus file descriptors
[BTBRIDGED 1557293376.044355980] Opening /dev/stdin
[BTBRIDGED 1557293376.046642547] Creating timer fd
[BTBRIDGED 1557293376.048234089] Entering polling loop
[BTBRIDGED 1557293376.066814944] Processed 1 dbus events
[BTBRIDGED 1557293376.067628554] Processed 1 dbus events
[BTBRIDGED 1557293376.074939645] Processed 1 dbus events
1+0 records in
1+0 records out
[BTBRIDGED 1557293376.093224260] Processed 1 dbus events
[BTBRIDGED 1557293376.095118345] Processed 1 dbus events
1+0 records in
1+0 records out
[BTBRIDGED 1557293376.125548961] Processed 1 dbus events
[BTBRIDGED 1557293376.126759011] Sending dbus signal with seq 0x61, netfn 0x0f, lun 0x03, cmd 0x3f
[BTBRIDGED 1557293376.127621307]        0x3f 0x3f 0x3f 0x3f 0x3f 0x3f 0x3f 0x3f
[BTBRIDGED 1557293376.128784166]        0x3f 0x3f 0x3f 0x3f 0x3f 0x3f 0x3f 0x3f
[BTBRIDGED 1557293376.129727956]        0x3f 0x3f 0x3f 0x3f 0x3f 0x3f 0x3f 0x3f
[BTBRIDGED 1557293376.130708635]        0x3f 0x3f 0x3f 0x3f 0x3f 0x3f 0x3f 0x3f
[BTBRIDGED 1557293376.131657960]        0x3f 0x3f 0x3f 0x3f 0x3f 0x3f 0x3f 0x3f
[BTBRIDGED 1557293376.143128410]        0x3f 0x3f 0x3f 0x3f 0x3f 0x3f 0x3f 0x3f
[BTBRIDGED 1557293376.144343915]        0x3f 0x3f 0x3f 0x3f 0x3f 0x3f 0x3f 0x3f
[BTBRIDGED 1557293376.145665965]        0x3f 0x3f 0x3f 0x3f
[BTBRIDGED 1557293376.167327482] Processed 1 dbus events
1+0 records in
1+0 records out
1+0 records in
1+0 records out
[BTBRIDGED 1557293379.287334223] Sending dbus signal with seq 0x62, netfn 0x0f, lun 0x03, cmd 0x3f
[BTBRIDGED 1557293379.288042581]        0x3f 0x3f 0x3f 0x3f 0x3f 0x3f 0x3f 0x3f
[BTBRIDGED 1557293379.288843301]        0x3f 0x3f 0x3f 0x3f 0x3f 0x3f 0x3f 0x3f
[BTBRIDGED 1557293379.289562730]        0x3f 0x3f 0x3f 0x3f 0x3f 0x3f 0x3f 0x3f
[BTBRIDGED 1557293379.304280143]        0x3f 0x3f 0x3f 0x3f 0x3f 0x3f 0x3f 0x3f
[BTBRIDGED 1557293379.305032985]        0x3f 0x3f 0x3f 0x3f 0x3f 0x3f 0x3f 0x3f
[BTBRIDGED 1557293379.305826877]        0x3f 0x3f 0x3f 0x3f 0x3f 0x3f 0x3f 0x3f
[BTBRIDGED 1557293379.306642790]        0x3f 0x3f 0x3f 0x3f 0x3f 0x3f 0x3f 0x3f
[BTBRIDGED 1557293379.307781568]        0x3f 0x3f 0x3f 0x3f
[BTBRIDGED 1557293381.127091191] Timer fired 1 times
[BTBRIDGED 1557293381.127770782] Timeout on msg with seq: 0x61
[BTBRIDGED 1557293381.128476028] Adjusting timer for next element
[BTBRIDGED 1557293381.129388223] Successfully wrote 5 of 5 bytes to /dev/stdin
[BTBRIDGED 1557293381.130146196] Turning off POLLOUT for the BT in poll()
[BTBRIDGED 1557293381.130854312] Completed request with seq 0x61, netfn 0x10, lun 0x03, cmd 0x3f, cc 0xce
[BTBRIDGED 1557293381.132305370] Sending dbus signal with seq 0x61, netfn 0x10, lun 0x03, cmd 0x3f
[BTBRIDGED 1557293381.133141202]        0xce
[BTBRIDGED 1557293384.288225639] Timer fired 1 times
[BTBRIDGED 1557293384.290146754] Timeout on msg with seq: 0x62
[BTBRIDGED 1557293384.291676115] Adjusting timer for next element
[BTBRIDGED 1557293384.293973834] Successfully wrote 5 of 5 bytes to /dev/stdin
[BTBRIDGED 1557293384.295833616] Turning off POLLOUT for the BT in poll()
[BTBRIDGED 1557293384.297688267] Completed request with seq 0x62, netfn 0x10, lun 0x03, cmd 0x3f, cc 0xce
[BTBRIDGED 1557293384.300722101] Sending dbus signal with seq 0x62, netfn 0x10, lun 0x03, cmd 0x3f
[BTBRIDGED 1557293384.303198202]        0xce
```

Here message 0x62 is correctly being timed out 5 seconds after its
arrival.

Change-Id: Iac3d46d153d6677a1036de726c5ef30cbec33934
Signed-off-by: Andrew Jeffery <andrew@aj.id.au>