Field test with German Corona Warn App

[mariohock]

Thanks for releasing the first Alpha. I downloaded harbour-contrac-0.0.1-1.armv7hl.rpm (30/07/2020 - 22:54) and installed it directly, since I don't have a packet manager for open-repos.

I put the phone for quite some time next to my Android tablet with the German Corona Warn App on it. And I enabled "Scan and send active", also I enabled Bluetooth on may Sailfish Device (Xperia X).

I'm not sure if I did everything correct, but I see: "Contact Beacons, Sent: 3; Received: 0". Is there a way to get more debug output?

[llewelld]

Thanks for testing out the software, and for the useful report. Installing manually shouldn't have any effect on it working.

The "Sent" indicator will increment every 10 mins, and Android sends out beacons every 10-15 mins, so you should have received at least one beacon in that time. There are a couple of things you can do that would be useful to help figure out what's going wrong.

1. Run the daemon in the console and collect the output. To do this, close the app, then enter the following commands:

systemctl --user stop contracd
contracd

Re-open the app and set it to scan/send again. If you could post the output here, that would be useful.

2. Use your Android device to check whether beacons are being sent properly. I use nRF Connect or RaMBLE for this. You may have to be quite patient to notice the beacons. In nRF Connect you can identify them by the service UUID of 0xFD6F and the fact that the beacon name will be a 16-digit hex number that matches the first portion of the Service Data. On RaMBLE they'll be marked as "Exposure Notification" beacons.

If you could do this, I can also test it out on the Xperia X I have here. I've heard reports of Bluetooth peculiarities on the X with other software, so it could be related to that.

[mariohock]

$ contracd
[D] unknown:0 - QML debugging is enabled. Only use this in a safe environment.
[D] ExposureNotificationPrivate::ExposureNotificationPrivate:64 - Contrac
[D] ExposureNotificationPrivate::ExposureNotificationPrivate:66 - Controller
[D] BleAdvertisement::setServiceData:178 - Service data value: "48656c6c6f"
[D] BleAdvertisement::registerDBus:45 - Registering: "/uk/co/flypig/advert1"
[D] BleAdvertisement::registerDBus:48 - Connecting
[D] BleAdvertisement::registerDBus:56 - Registering object
[D] BleAdvertisementManager::connectDBus:28 - Registering interface
[D] BleAdvertisementManager::connectDBus:35 - Connecting property change
[D] ExposureNotificationPrivate::ExposureNotificationPrivate:68 - Scanner
[D] BleScanner::BleScanner:17 - Registering interface
[D] ExposureNotificationPrivate::ExposureNotificationPrivate:70 - Contacts
[D] ExposureNotificationPrivate::ExposureNotificationPrivate:72 - Timer
[D] ExposureNotificationPrivate::ExposureNotificationPrivate:77 - Load
[D] ExposureNotificationPrivate::ExposureNotificationPrivate:84 - Connections
[D] DBusInterface::DBusInterface:13 - CONTRAC: Initialising the dbus interface
[D] DBusInterface::DBusInterface:29 - CONTRAC: service registration: true
[D] DBusInterface::DBusInterface:33 - CONTRAC: object registration: true
[D] DBusInterface::DBusInterface:36 - CONTRAC: DBus registered: true
[W] unknown:0 - Invalid return type in method "status"
[D] DBusInterface::isEnabled:82 - CONTRAC: isEnabled()
[D] DBusInterface::isBusy:88 - CONTRAC: isBusy()
[D] DBusInterface::start:64 - CONTRAC: start()
[D] ExposureNotification::onRpiChanged:479 - CONTRAC: onRpiChanged
[D] BleAdvertisement::setServiceData:178 - Service data value: "e3db2987885559392912096836d70b7c"
[D] DBusInterface::incrementSentCount:157 - CONTRAC: incrementSentCount()
[D] DBusInterface::incrementSentCount:159 - CONTRAC: receiveCount: 1
[D] ContactStorage::onTimeChanged:38 - Storage day set to 18482
[D] ContactStorage::harvestOldData:107 - Harvesting file: "00000000.dat"
[D] BleScanner::applyDiscoveryFilter:97 - Setting up discovery filter
[D] Controller::registerAdvert:42 - Registering advertisement
[D] BleAdvertisementManager::registerAdvertisement:65 - Registering advertisement: "/uk/co/flypig/advert1"
[D] BleScanner::applyDiscoveryFilter()::<lambda:108 - DBus SetDiscoveryFilter returned
[D] BleScanner::applyDiscoveryFilter()::<lambda:115 - Filtering not supported
[D] BleScanner::startDiscovery:147 - Starting discovery
[D] DBusInterface::isBusy:88 - CONTRAC: isBusy()
[D] BleAdvertisementManager::registerAdvertisement(BleAdvertisement*)::<lambda:75 - DBus RegisterAdvertisement call returned
[D] BleAdvertisementManager::registerAdvertisement(BleAdvertisement*)::<lambda:79 - Error: "Maximum advertisements reached"
[D] BleScanner::startDiscovery()::<lambda:155 - DBus StartDiscovery returned
[D] BleScanner::startDiscovery()::<lambda:162 - No error
[D] DBusInterface::isBusy:88 - CONTRAC: isBusy()
[D] DBusInterface::isEnabled:82 - CONTRAC: isEnabled()
[D] ExposureNotification::intervalUpdate:470 - intervalUpdate
[D] ExposureNotification::intervalUpdate:470 - intervalUpdate
[D] ExposureNotification::intervalUpdate:470 - intervalUpdate
[D] ExposureNotification::intervalUpdate:470 - intervalUpdate
[D] ExposureNotification::intervalUpdate:470 - intervalUpdate
[D] ExposureNotification::intervalUpdate:470 - intervalUpdate
[D] ExposureNotification::intervalUpdate:470 - intervalUpdate
[D] ExposureNotification::intervalUpdate:470 - intervalUpdate
[D] ExposureNotification::intervalUpdate:470 - intervalUpdate
[D] ExposureNotification::intervalUpdate:470 - intervalUpdate
[D] ExposureNotification::intervalUpdate:470 - intervalUpdate
[D] ExposureNotification::intervalUpdate:470 - intervalUpdate
[D] ExposureNotification::intervalUpdate:470 - intervalUpdate
[D] ExposureNotification::intervalUpdate:470 - intervalUpdate
[D] ExposureNotification::intervalUpdate:470 - intervalUpdate
[D] ExposureNotification::intervalUpdate:470 - intervalUpdate
[D] ExposureNotification::intervalUpdate:470 - intervalUpdate
[D] ExposureNotification::intervalUpdate:470 - intervalUpdate
[D] ExposureNotification::intervalUpdate:470 - intervalUpdate

[mariohock]

[D] ExposureNotification::onRpiChanged:479 - CONTRAC: onRpiChanged
[D] Controller::setRpi:64 - CONTRAC: unregistering
[D] Controller::unRegisterAdvert:52 - Unregistering advertisement
[D] BleAdvertisementManager::unRegisterAdvertisement:90 - Unregistering advertisement: "/uk/co/flypig/advert1"
[D] BleAdvertisement::setServiceData:178 - Service data value: "bed9f51a3751956213cf65b2e8f82c8d"
[D] Controller::registerAdvert:42 - Registering advertisement
[D] BleAdvertisementManager::registerAdvertisement:65 - Registering advertisement: "/uk/co/flypig/advert1"
[D] DBusInterface::incrementSentCount:157 - CONTRAC: incrementSentCount()
[D] DBusInterface::incrementSentCount:159 - CONTRAC: receiveCount: 2
[D] BleAdvertisementManager::unRegisterAdvertisement(BleAdvertisement*)::<lambda:100 - DBus UnregisterAdvertisement call returned
[D] BleAdvertisementManager::unRegisterAdvertisement(BleAdvertisement*)::<lambda:104 - Error: "Does Not Exist"
[D] BleAdvertisementManager::registerAdvertisement(BleAdvertisement*)::<lambda:75 - DBus RegisterAdvertisement call returned
[D] BleAdvertisementManager::registerAdvertisement(BleAdvertisement*)::<lambda:79 - Error: "Maximum advertisements reached"
[D] ExposureNotification::intervalUpdate:470 - intervalUpdate
[D] ExposureNotification::intervalUpdate:470 - intervalUpdate

[mariohock]

[D] ExposureNotification::intervalUpdate:470 - intervalUpdate
[D] ExposureNotification::intervalUpdate:470 - intervalUpdate
[D] ExposureNotification::onRpiChanged:479 - CONTRAC: onRpiChanged
[D] Controller::setRpi:64 - CONTRAC: unregistering
[D] Controller::unRegisterAdvert:52 - Unregistering advertisement
[D] BleAdvertisementManager::unRegisterAdvertisement:90 - Unregistering advertisement: "/uk/co/flypig/advert1"
[D] BleAdvertisement::setServiceData:178 - Service data value: "4cd1e2a7fea2ea7bf7aa521683eceb60"
[D] Controller::registerAdvert:42 - Registering advertisement
[D] BleAdvertisementManager::registerAdvertisement:65 - Registering advertisement: "/uk/co/flypig/advert1"
[D] DBusInterface::incrementSentCount:157 - CONTRAC: incrementSentCount()
[D] DBusInterface::incrementSentCount:159 - CONTRAC: receiveCount: 3
[D] BleAdvertisementManager::unRegisterAdvertisement(BleAdvertisement*)::<lambda:100 - DBus UnregisterAdvertisement call returned
[D] BleAdvertisementManager::unRegisterAdvertisement(BleAdvertisement*)::<lambda:104 - Error: "Does Not Exist"
[D] BleAdvertisementManager::registerAdvertisement(BleAdvertisement*)::<lambda:75 - DBus RegisterAdvertisement call returned
[D] BleAdvertisementManager::registerAdvertisement(BleAdvertisement*)::<lambda:79 - Error: "Maximum advertisements reached"
[D] ExposureNotification::intervalUpdate:470 - intervalUpdate
[D] ExposureNotification::intervalUpdate:470 - intervalUpdate

[llewelld]

Thanks for the logs, they're very helpful. It's clear from them that there are issues here both scanning and setting up advertisements. The relevant lines are the following:

 [D] BleScanner::applyDiscoveryFilter()::<lambda:108 - DBus SetDiscoveryFilter returned
 [D] BleScanner::applyDiscoveryFilter()::<lambda:115 - Filtering not supported

 [D] BleAdvertisementManager::registerAdvertisement(BleAdvertisement*)::<lambda:75 - DBus RegisterAdvertisement call returned
 [D] BleAdvertisementManager::registerAdvertisement(BleAdvertisement*)::<lambda:79 - Error: "Maximum advertisements reached"

Both of these are errors returned by bluez5 suggesting that the Bluetooth hardware/driver doesn't support what's needed. I got similar errors on a Jolla C, but I wasn't expecting them on the X. I'll have to try it on my X here, but if it is this, then it may not be easy/possible to work around. I'll post what I discover here.

The only other thing I could think of is if you're running any other software that uses BLE (e.g. Amazfish). Could that be the case?

[mariohock]

I'm quite sure I don't use any BLE services. My wife just tried it with her Xperia XA2 and immediately got "Sent: 1, Received: 1", after she started »contrac« next to an Android tablet with the Corona Warn App. Does the official Corona App / the protocol answers the beacon? Otherwise this would be a strange coincident.. Now it shows "Sent: 1, Received: 2". However, my Xperia X in close proximity still shows "Received: 0".

[triessner]

Hi David,
thanks a lot for your work. I just installed your contrac app on my Xperia XA2 dual SIM, Sailfish OS 3.3.0.16 and it worked out of the box. Sent and received counters increase regularly. Can I do something more to support you? Is there a function on the German android app that shows some useful information?
Keep on your great work :-)
Thilo

[llewelld]

Thank you both @mariohock and @triessner for your feedback.

@mariohock

Does the official Corona App / the protocol answers the beacon?

There's no answers, it's entirely passive. Given this it may seem strange but the reason the beacons may appear to be in sync is because the same beacon is retransmitted very often. The counter only goes up when the beacon is different, and they'll go out of sync because the time between new beacons is "a random value that is greater than 10 minutes and less than 20 minutes" (from the specification).

I've not had a chance to investigate the issues you're experiencing with the Xperia X, but I will do.

@triessner

Can I do something more to support you?

Thanks for the offer, and your report of things working is already helpful. There's a new version of the app, and if you could please test out uploading and downloading keys to/from the test server and let me know if there are any errors or issues, that would be very useful.

Is there a function on the German android app that shows some useful information?

Unfortunately not that I'm aware of. The Android implementation is very secretive about its data, quite-rightly for privacy reasons. What I'd love to know is whether the Android app is receiving the beacons Contrac sends out, but as far as I'm aware there's no way to access this info, sadly.

[triessner]

I downloaded the new version and made some tests.

1. sometimes, when activating "Scan and send active" the received counter increments
2. it seems, that during a phone call there are some issues with sending and receiving beacons (needs more testing)
3. after being in flight mode the received counter does not increment any more. May be some bluetooth function hangs and the send counter still increments, but the beacons are not really send despite the counter increases? That would be really bad.
4. Download works, upload gave an error and both buttons are greyed out. Maybe I interfered during upload, I'll make an other test in near future.
   It is a pity, that I have only one Xperia, otherwise the tests with two of your apps would be quite easy and give more results.
   Here is a kind of a log-file. The changes happened somewhere between the timestamps (I didn't watch my mobile all the time):
   Send Received
   9:47 start
   9:47 1 1
   9:49 2 1
   10:05 3 2
   10:09 4 2
   10:33 6 4
   10:38 6 5
   2 x decativate and activate
   10:50 8 8
   10:51 9 min phone call
   11:12 10 12
   11:19 11 13
   11:19 19 min phone call
   11:38 12 13
   11:48 13 13
   11:49 2x deactivate and activate
   11:50 14 14
   11:54 flight mode
   12.06 15 14
   12:10 16 14
   12:11 normal mode again
   12:19 17 14
   12:35 18 14

Hope this helps,

[cnlpete]

I can confirm the behaviour with my xperia x,

i also have the log output with the missing filter support

 [D] BleScanner::applyDiscoveryFilter()::<lambda:108 - DBus SetDiscoveryFilter returned
 [D] BleScanner::applyDiscoveryFilter()::<lambda:115 - Filtering not supported
...
 [D] BleAdvertisementManager::registerAdvertisement(BleAdvertisement*)::<lambda:75 - DBus RegisterAdvertisement call returned
 [D] BleAdvertisementManager::registerAdvertisement(BleAdvertisement*)::<lambda:79 - Error: "Maximum advertisements reached"

When i try to stop the "scan and send active", it produces an infinite number of

[D] BleScanner::removeDiscoveryFilter:194 - No discovery filter to remove, moving straight to stop discovery
[D] BleScanner::removeDiscoveryFilter:194 - No discovery filter to remove, moving straight to stop discovery
[D] BleScanner::removeDiscoveryFilter:194 - No discovery filter to remove, moving straight to stop discovery

and ends with Segmentation fault

[thigg]

I think this may belong here, otherwise feel free to make a new issue out of it:

I just reported on the forum, but testing seems to confirm it only happens when I have contrac active. (Germany, XperiaX, otherwise app seems to work fine, except of #26)

Copy from Forum:

REPRODUCIBILITY (100%):
BUILD ID = 3.4.0.24
HARDWARE (Jolla1, Tablet, XA2,…): Xperia X
UI LANGUAGE:Ger
REGRESSION: (compared to previous public release: Yes, No, ?): ?

DESCRIPTION:
My journalctl -a is filled with the messages below. (just copied a few, there are way more)
I (at least) never noticed them before. If I can help debugging anything, just let me know.

Oct 16 12:44:55 XperiaX kernel: [] 0xffffffc000461a18
Oct 16 12:44:55 XperiaX kernel: [] 0xffffffc000461b04
Oct 16 12:44:55 XperiaX kernel: [] 0xffffffc0008bb7d4
Oct 16 12:44:55 XperiaX kernel: [] 0xffffffc0008bc828
Oct 16 12:44:55 XperiaX kernel: [] 0xffffffc0008bd728
Oct 16 12:44:55 XperiaX kernel: [] 0xffffffc0008bd9dc
Oct 16 12:44:55 XperiaX kernel: [] 0xffffffc0008b83f8
Oct 16 12:44:55 XperiaX kernel: [] 0xffffffc0004d3414
Oct 16 12:44:55 XperiaX kernel: [] 0xffffffc0004d3474
Oct 16 12:44:55 XperiaX kernel: [] 0xffffffc0004d484c
Oct 16 12:44:55 XperiaX kernel: [] 0xffffffc0004d62e4
Oct 16 12:44:55 XperiaX kernel: [] 0xffffffc000536b90
Oct 16 12:44:55 XperiaX kernel: [] 0xffffffc00053b154
Oct 16 12:44:55 XperiaX kernel: [] 0xffffffc00053b1e8
Oct 16 12:44:55 XperiaX kernel: [] 0xffffffc00053b90c
Oct 16 12:44:55 XperiaX kernel: [] 0xffffffc00053c190
Oct 16 12:44:55 XperiaX kernel: [] 0xffffffc0004d494c
Oct 16 12:44:55 XperiaX kernel: [] 0xffffffc0004d6414
Oct 16 12:44:55 XperiaX kernel: [] 0xffffffc00082dfc0
Oct 16 12:44:55 XperiaX kernel: [] 0xffffffc00082e4a0
Oct 16 12:44:55 XperiaX kernel: [] 0xffffffc00082cc60
Oct 16 12:44:55 XperiaX kernel: [] 0xffffffc0000b3c20
Oct 16 12:44:55 XperiaX kernel: [] 0xffffffc0000b3f28
Oct 16 12:44:55 XperiaX kernel: [] 0xffffffc0000b9d48
Oct 16 12:44:55 XperiaX kernel: BUG: scheduling while atomic: kworker/0:0/6353/0x00000002
Oct 16 12:44:55 XperiaX kernel: CPU: 0 PID: 6353 Comm: kworker/0:0 Tainted: G W 3.10.84 #1
Oct 16 12:44:55 XperiaX kernel: Workqueue: events 0xffffffc00082cbec

ADDITIONAL INFORMATION:

I grepped kernel from journalctl -a (thus its not the full log, but longer log here) If you need more, let me know.
I did a fresh install to 3.4.0.24, no upgrade.