Received-SPF: pass (google.com: best guess record for domain of linux-bluetooth-owner@vger.kernel.org designates 209.132.180.67 as permitted sender) client-ip=209.132.180.67;
MIME-Version: 1.0
References: <20200125004350.4640-1-brian.gix@intel.com>
In-Reply-To: <20200125004350.4640-1-brian.gix@intel.com>
From:   =?UTF-8?B?UmFmYcWCIEdhamRh?= <rafal.gajda@silvair.com>
Date:   Mon, 27 Jan 2020 22:27:04 +0100
Message-ID: <CAFcXi1x4skUJuCgQLDswFQm20Hqo8XdAwmGv8qTg+ywKyjPGxg@mail.gmail.com>
Subject: Re: [PATCH BlueZ v2 0/5] mesh: Add NVM storage of Replay Protection List
To:     Brian Gix <brian.gix@intel.com>
Cc:     linux-bluetooth@vger.kernel.org, inga.stotland@intel.com
Content-Type: text/plain; charset="UTF-8"
Content-Transfer-Encoding: quoted-printable
Sender: linux-bluetooth-owner@vger.kernel.org
Precedence: bulk

Hi,

sob., 25 sty 2020 o 01:44 Brian Gix <brian.gix@intel.com> napisa=C5=82(a):
>
> Version 2: Fix path construction code when first reading RPL from NVM
>
>
> An oversight led to losing our Replay Protection List with every
> re-boot. This patch-set makes a number of Replay Protect List
> modifications that culminate in adding rpl.c/h, which stores the latest
> iv_index/sequence values for each node that handles an incoming packet.
>
> The first 4 patches, does some maintenance required to handle RPL
> according the the Mesh Specification.

While testing this patch set I've come across the following problem:

After importing and attaching new node to the daemon I tried to
configure new application key by sending dev key message
ConfigOpcode.APPKEY_ADD to self.
This previously resulted in DevKeyMessageReceived reply.

16:40:24.045 MESHD.stderr          INFO 2020-01-27 16:40:24.045
mesh.c:622  attach_call                mesh/mesh.c:attach_call()
Attach
16:40:24.045 DBUS.in              DEBUG /
org.freedesktop.DBus.ObjectManager::GetManagedObjects()
16:40:24.046 MESHD.stderr          INFO 2020-01-27 16:40:24.046
node.c:1311 get_app_properties
mesh/node.c:get_app_properties() path /com/silvair/application
16:40:24.046 MESHD.stderr          INFO 2020-01-27 16:40:24.046
node.c:1158 get_element_properties
mesh/node.c:get_element_properties() path
/com/silvair/application/element0
16:40:24.048 MESHD.stderr          INFO 2020-01-27 16:40:24.046
node.c:1797 build_element_config
mesh/node.c:build_element_config() Element 0
16:40:24.048 DBUS.out             DEBUG /org/bluez/mesh
org.bluez.mesh.Network1::Attach('/', 1141961045074800157) =3D
('/org/bluez/mesh/node83bf3b46810345a28bcce70d8d0b46d3', [[0, []]])
16:40:24.054 DBUS.out             DEBUG
/org/bluez/mesh/node83bf3b46810345a28bcce70d8d0b46d3
org.freedesktop.DBus.Properties::Get('org.bluez.mesh.Node1',
'Addresses') =3D (<dbus_next.signature.Variant object at
0x7f11eaece150>,)
16:40:24.054 APPLICATION           INFO Attached to node
/org/bluez/mesh/node83bf3b46810345a28bcce70d8d0b46d3, address: 05f2,
configuration: {0: {}}
16:40:24.056 MESHD.stderr          INFO 2020-01-27 16:40:24.055
keyring.c:209  keyring_put_remote_dev_key
mesh/keyring.c:keyring_put_remote_dev_key() Put Dev Key
/tmp/pytest-of-ragajda/pytest-74/test_rpl_persistence_after_res0/config/83b=
f3b46810345a28bcce70d8d0b46d3/dev_keys/05f2
16:40:24.057 DBUS.out             DEBUG
/org/bluez/mesh/node83bf3b46810345a28bcce70d8d0b46d3
org.bluez.mesh.Management1::ImportRemoteNode(1522, 1,
b'\x9dm\xd0\xe9n\xb2]\xc1\x9a@\xed\x99\x14\xf8\xf0?') =3D ()
16:40:24.060 APPLICATION.Element0.ConfigClient DEBUG Sending:
/com/silvair/application/element0 -> 05f2 [remote True, net_index 0]
ConfigOpcode.APPKEY_ADD Container(app_key_index=3D0, net_key_index=3D0,
app_key=3Db'c\x96GqsO\xbdv\xe3\xb4\x05\x19\xd1\xd9JH')
16:40:24.060 APPLICATION.Element0.ConfigClient DEBUG Sending:
/com/silvair/application/element0 - > 0001 [remote 1522, net_index 0]
0000000063964771734fbd76e3b40519d1d94a48
16:40:24.063 MESHD.stderr          INFO 2020-01-27 16:40:24.062
node.c:1891 dev_key_send_call          mesh/node.c:dev_key_send_call()
DevKeySend
16:40:24.064 MESHD.stderr          INFO 2020-01-27 16:40:24.063
model.c:604  msg_send                   mesh/model.c:msg_send() (6fff)
0x7ffffffa9fa0
16:40:24.064 MESHD.stderr          INFO 2020-01-27 16:40:24.063
model.c:605  msg_send                   mesh/model.c:msg_send()
net_idx 0
16:40:24.064 MESHD.stderr          INFO 2020-01-27 16:40:24.063
model.c:957  mesh_model_rx              mesh/model.c:mesh_model_rx()
iv_index 00000000 key_aid =3D 00
16:40:24.064 MESHD.stderr          INFO 2020-01-27 16:40:24.063
util.c:46   print_packet               mesh/util.c:print_packet()
39624.063 Clr Rx: 0000000063964771734fbd76e3b40519d1d94a48
16:40:24.065 MESHD.stderr          INFO 2020-01-27 16:40:24.063
model.c:370  forward_model              mesh/model.c:forward_model()
model ffff0000 with idx 7fff
16:40:24.065 MESHD.stderr          INFO 2020-01-27 16:40:24.063
cfgmod-server.c:783  cfg_srv_pkt
mesh/cfgmod-server.c:cfg_srv_pkt() CONFIG-SRV-opcode 0x0 size 19 idx
000
16:40:24.065 MESHD.stderr          INFO 2020-01-27 16:40:24.065
cfgmod-server.c:1036 cfg_srv_pkt
mesh/cfgmod-server.c:cfg_srv_pkt() Add/Update AppKey success: Net_Idx
000, App_Idx 000
16:40:24.065 MESHD.stderr          INFO 2020-01-27 16:40:24.065
model.c:604  msg_send                   mesh/model.c:msg_send() (7fff)
0x5564327d323c
16:40:24.066 MESHD.stderr          INFO 2020-01-27 16:40:24.065
model.c:605  msg_send                   mesh/model.c:msg_send()
net_idx 0
16:40:24.066 MESHD.stderr          INFO 2020-01-27 16:40:24.065
model.c:957  mesh_model_rx              mesh/model.c:mesh_model_rx()
iv_index 00000000 key_aid =3D 00
16:40:24.066 MESHD.stderr          INFO 2020-01-27 16:40:24.065
util.c:46   print_packet               mesh/util.c:print_packet()
39624.065 Clr Rx: 800300000000
16:40:24.066 MESHD.stderr          INFO 2020-01-27 16:40:24.065
cfgmod-server.c:783  cfg_srv_pkt
mesh/cfgmod-server.c:cfg_srv_pkt() CONFIG-SRV-opcode 0x8003 size 4 idx
000
16:40:24.067 MESHD.stderr          INFO 2020-01-27 16:40:24.065
model.c:871  send_dev_key_msg_rcvd
mesh/model.c:send_dev_key_msg_rcvd() Send "DevKeyMessageReceived"
16:40:24.067 MESHD.stderr          INFO 2020-01-27 16:40:24.065
mesh-config-json.c:2111 mesh_config_write_seq_number
mesh/mesh-config-json.c:mesh_config_write_seq_number() Seq Cache: 1 ->
14286

After applying the patch set the same procedure results in:

16:41:04.102 MESHD.stderr          INFO mesh/mesh.c:attach_call() Attach
16:41:04.103 DBUS.in              DEBUG /
org.freedesktop.DBus.ObjectManager::GetManagedObjects()
16:41:04.103 MESHD.stderr          INFO
mesh/node.c:get_app_properties() path /com/silvair/application
16:41:04.104 MESHD.stderr          INFO
mesh/node.c:get_element_properties() path
/com/silvair/application/element0
16:41:04.105 MESHD.stderr          INFO
mesh/node.c:build_element_config() Element 0
16:41:04.105 DBUS.out             DEBUG /org/bluez/mesh
org.bluez.mesh.Network1::Attach('/', 11095264700132944744) =3D
('/org/bluez/mesh/node83bf3b46810345a28bcce70d8d0b46d3', [[0, []]])
16:41:04.110 DBUS.out             DEBUG
/org/bluez/mesh/node83bf3b46810345a28bcce70d8d0b46d3
org.freedesktop.DBus.Properties::Get('org.bluez.mesh.Node1',
'Addresses') =3D (<dbus_next.signature.Variant object at
0x7f27613a2990>,)
16:41:04.110 APPLICATION           INFO Attached to node
/org/bluez/mesh/node83bf3b46810345a28bcce70d8d0b46d3, address: 05f2,
configuration: {0: {}}
16:41:04.111 MESHD.stderr          INFO
mesh/keyring.c:keyring_put_remote_dev_key() Put Dev Key
/tmp/pytest-of-ragajda/pytest-75/test_rpl_persistence_after_res0/config/83b=
f3b46810345a28bcce70d8d0b46d3/dev_keys/05f2
16:41:04.112 DBUS.out             DEBUG
/org/bluez/mesh/node83bf3b46810345a28bcce70d8d0b46d3
org.bluez.mesh.Management1::ImportRemoteNode(1522, 1,
b'\x9dm\xd0\xe9n\xb2]\xc1\x9a@\xed\x99\x14\xf8\xf0?') =3D ()
16:41:04.113 APPLICATION.Element0.ConfigClient DEBUG Sending:
/com/silvair/application/element0 -> 05f2 [remote True, net_index 0]
ConfigOpcode.APPKEY_ADD Container(app_key_index=3D0, net_key_index=3D0,
app_key=3Db'c\x96GqsO\xbdv\xe3\xb4\x05\x19\xd1\xd9JH')
16:41:04.113 APPLICATION.Element0.ConfigClient DEBUG Sending:
/com/silvair/application/element0 - > 0001 [remote 1522, net_index 0]
0000000063964771734fbd76e3b40519d1d94a48
16:41:04.113 MESHD.stderr          INFO
mesh/node.c:dev_key_send_call() DevKeySend
16:41:04.114 MESHD.stderr          INFO mesh/model.c:msg_send() (6fff)
0x7ffffce69290
16:41:04.114 MESHD.stderr          INFO mesh/model.c:msg_send() net_idx 0
16:41:04.114 MESHD.stderr          INFO
mesh/mesh-config-json.c:mesh_config_write_seq_number() Seq Cache: 1 ->
25001
16:41:04.114 MESHD.stderr          INFO mesh/model.c:mesh_model_rx()
iv_index 00000000 key_aid =3D 00
16:41:04.115 MESHD.stderr          INFO
mesh/net.c:net_msg_in_replay_cache() Test Replay src: 05f2 seq: 000001
iv: 00000000
16:41:04.115 MESHD.stderr          INFO
mesh/net.c:net_msg_in_replay_cache() New Entry for 05f2
16:41:04.115 MESHD.stderr          INFO mesh/util.c:print_packet()
39664.115 Clr Rx: 0000000063964771734fbd76e3b40519d1d94a48
16:41:04.115 MESHD.stderr          INFO mesh/model.c:forward_model()
model ffff0000 with idx 7fff
16:41:04.115 MESHD.stderr          INFO
mesh/cfgmod-server.c:cfg_srv_pkt() CONFIG-SRV-opcode 0x0 size 19 idx
000
16:41:04.115 MESHD.stderr          INFO
mesh/cfgmod-server.c:cfg_srv_pkt() Add/Update AppKey success: Net_Idx
000, App_Idx 000
16:41:04.115 MESHD.stderr          INFO mesh/model.c:msg_send() (7fff)
0x55639ab9c8ec
16:41:04.115 MESHD.stderr          INFO mesh/model.c:msg_send() net_idx 0
16:41:04.116 MESHD.stderr          INFO mesh/model.c:mesh_model_rx()
iv_index 00000000 key_aid =3D 00
16:41:04.116 MESHD.stderr          INFO
mesh/net.c:net_msg_in_replay_cache() Test Replay src: 05f2 seq: 000001
iv: 00000000
16:41:04.116 MESHD.stderr          INFO
mesh/net.c:net_msg_in_replay_cache() Message already processed
(duplicate)

It looks like sequence number is correctly incremented when calling
DevKeySend but it isn't incremented at all when ConfigModel sends the
reply back.

--=20

Rafa=C5=82 Gajda
Silvair Sp. z o.o.