Publish functions as expected, but results in continuous, very heavy
HCI traffic (~every .7ms per btmon log). I don't think it's my
application as the problem persists after the application disconnects
from dbus and exits.
The calls to LE Set Adv Param all fail. Prior to the Publish call, LE
Set Param calls succeed. The only difference I can see is the failing
ones have an interval of 50ms and the ones that succeed have 100ms. A
successful one is appended.
I'm at current Bluez head (65231892cd). The platform is a rpi4.
Below is a pretty normal looking meshd log, a btmon dump and some more
normal looking dbus traffic.
Steve
Dec 22 09:22:56 mesh0 bluetooth-meshd[38760]: mesh/node.c:publish_call() Publish
Dec 22 09:22:56 mesh0 bluetooth-meshd[38760]: mesh/mesh-config-json.c:mesh_config_write_seq_number() Seq Cache: 210 -> 274
Dec 22 09:22:56 mesh0 bluetooth-meshd[38760]: mesh/model.c:mesh_model_rx() iv_index 00000000 key_aid = 6e
Dec 22 09:22:56 mesh0 bluetooth-meshd[38760]: mesh/util.c:print_packet() 46976.692 Used App Key: dae814b7da47ab8c992fcc03a60c100b
Dec 22 09:22:56 mesh0 bluetooth-meshd[38760]: mesh/util.c:print_packet() 46976.692 Clr Rx: 820200030064
Dec 22 09:22:56 mesh0 bluetooth-meshd[38760]: mesh/net.c:send_seg() segN 0 segment 0 seg_off 0
Dec 22 09:22:56 mesh0 bluetooth-meshd[38760]: mesh/util.c:print_packet() 46976.692 Clr-Net Tx: 00080000d10001c0006eaaffbb7633799725e9d600000000
Dec 22 09:22:56 mesh0 bluetooth-meshd[38760]: mesh/util.c:print_packet() 46976.693 RX: Network [enc] :: 7eb235f367ed0172ca7d0345f4a1d9ce42d116f80ab00b0e
Dec 22 09:22:56 mesh0 bluetooth-meshd[38760]: mesh/util.c:print_packet() 46976.693 RX: Network [clr] :: 7e080000d10001c0006eaaffbb7633799725e9d6
Dec 22 09:22:56 mesh0 bluetooth-meshd[38760]: mesh/util.c:print_packet() 46976.715 RX: Network [enc] :: 7e6e7c8a337f4355f2921b9d8fd3e7eb3a866af261fc46d1
Dec 22 09:22:56 mesh0 bluetooth-meshd[38760]: mesh/util.c:print_packet() 46976.715 RX: Network [clr] :: 7e070000d10001c0006eaaffbb7633799725e9d6
Dec 22 09:22:57 mesh0 bluetooth-meshd[38760]: mesh/util.c:print_packet() 46977.097 RX: Network [enc] :: 7e3a351647d646ec107415b165540e1057fdc9847c
Dec 22 09:22:57 mesh0 bluetooth-meshd[38760]: mesh/util.c:print_packet() 46977.097 RX: Network [clr] :: 7e0a00007d010000016e8961a6de509fb1
Dec 22 09:22:57 mesh0 bluetooth-meshd[38760]: mesh/net.c:msg_in_cache() Add 0100 + 00007d + 6e8961a6
Dec 22 09:22:57 mesh0 bluetooth-meshd[38760]: mesh/net.c:packet_received() RX: Network 0100 -> 0001 : TTL 0x0a : IV : 00000000 SEQ 0x00007d
Dec 22 09:22:57 mesh0 bluetooth-meshd[38760]: mesh/net.c:packet_received() RX: App 0x0100 -> 0x0001 : TTL 0x0a : SEQ 0x00007d
Dec 22 09:22:57 mesh0 bluetooth-meshd[38760]: mesh/model.c:mesh_model_rx() iv_index 00000000 key_aid = 6e
Dec 22 09:22:57 mesh0 bluetooth-meshd[38760]: mesh/util.c:print_packet() 46977.097 Used App Key: dae814b7da47ab8c992fcc03a60c100b
Dec 22 09:22:57 mesh0 bluetooth-meshd[38760]: mesh/util.c:print_packet() 46977.097 Clr Rx: 820400
Dec 22 09:22:57 mesh0 bluetooth-meshd[38760]: mesh/model.c:send_msg_rcvd() Send "MessageReceived"
============================================================================================================================
btmon output after Publish call:
< HCI Command: LE Set Advertising Parameters (0x08|0x0006) plen 15 #1756 [hci0] 60.253779
Min advertising interval: 50.000 msec (0x0050)
Max advertising interval: 50.000 msec (0x0050)
Type: Non connectable undirected - ADV_NONCONN_IND (0x03)
Own address type: Random (0x01)
Direct address type: Public (0x00)
Direct address: 00:00:00:00:00:00 (OUI 00-00-00)
Channel map: 37, 38, 39 (0x07)
Filter policy: Allow Scan Request from White List Only, Allow Connect Request from White List Only (0x03)
> HCI Event: Command Complete (0x0e) plen 4 #1757 [hci0] 60.254089
LE Set Advertising Parameters (0x08|0x0006) ncmd 1
Status: Invalid HCI Command Parameters (0x12)
< HCI Command: LE Set Advertising Data (0x08|0x0008) plen 32 #1758 [hci0] 60.254304
Length: 26
Mesh Data: 7eb235f367ed0172ca7d0345f4a1d9ce42d116f80ab00b0e
IVI: 0
NID: 0x7e
b2 35 f3 67 ed 01 72 ca 7d 03 45 f4 a1 d9 ce 42 .5.g..r.}.E....B
d1 16 f8 0a b0 0b 0e .......
> HCI Event: Command Complete (0x0e) plen 4 #1759 [hci0] 60.254686
LE Set Advertising Data (0x08|0x0008) ncmd 1
Status: Success (0x00)
< HCI Command: LE Set Advertise Enable (0x08|0x000a) plen 1 #1760 [hci0] 60.254874
Advertising: Enabled (0x01)
> HCI Event: Command Complete (0x0e) plen 4 #1761 [hci0] 60.255170
LE Set Advertise Enable (0x08|0x000a) ncmd 1
Status: Success (0x00)
< HCI Command: LE Set Advertise Enable (0x08|0x000a) plen 1 #1762 [hci0] 60.302847
Advertising: Disabled (0x00)
> HCI Event: Command Complete (0x0e) plen 4 #1763 [hci0] 60.303586
LE Set Advertise Enable (0x08|0x000a) ncmd 1
Status: Success (0x00)
< HCI Command: LE Set Advertising Parameters (0x08|0x0006) plen 15 #1764 [hci0] 60.303744
Min advertising interval: 50.000 msec (0x0050)
Max advertising interval: 50.000 msec (0x0050)
Type: Non connectable undirected - ADV_NONCONN_IND (0x03)
Own address type: Random (0x01)
Direct address type: Public (0x00)
Direct address: 00:00:00:00:00:00 (OUI 00-00-00)
Channel map: 37, 38, 39 (0x07)
Filter policy: Allow Scan Request from White List Only, Allow Connect Request from White List Only (0x03)
> HCI Event: Command Complete (0x0e) plen 4 #1765 [hci0] 60.304053
LE Set Advertising Parameters (0x08|0x0006) ncmd 1
=====================================================================================================
dbus-monitor output
method call time=1608649585.797421 sender=:1.223 -> destination=org.bluez.mesh serial=21 path=/org/bluez/mesh/nodeb3f28276086958109ac1e2cbd76fbf7e; interface=org.bluez.mesh.Node1; member=Publish
object path "/com/silvair/sample/element0"
uint16 4097
array [
]
array of bytes [
82 02 00 03 00 64
]
method return time=1608649585.798741 sender=:1.221 -> destination=:1.223 serial=29 reply_serial=21
method call time=1608649586.337429 sender=:1.221 -> destination=:1.223 serial=30 path=/com/silvair/sample/element0; interface=org.bluez.mesh.Element1; member=MessageReceived
uint16 256
uint16 1
variant uint16 1
array of bytes [
82 04 00
]
===================================================================================
Successful LE Set Adv Param
< HCI Command: LE Set Advertising Parameters (0x08|0x0006) plen 15 #90 [hci0] 6.392018
Min advertising interval: 100.000 msec (0x00a0)
Max advertising interval: 100.000 msec (0x00a0)
Type: Non connectable undirected - ADV_NONCONN_IND (0x03)
Own address type: Random (0x01)
Direct address type: Public (0x00)
Direct address: 00:00:00:00:00:00 (OUI 00-00-00)
Channel map: 37, 38, 39 (0x07)
Filter policy: Allow Scan Request from White List Only, Allow Connect Request from White List Only (0x03)
> HCI Event: Command Complete (0x0e) plen 4 #91 [hci0] 6.392399
LE Set Advertising Parameters (0x08|0x0006) ncmd 1
Status: Success (0x00)
Hi Steve, I will investigate on my RPI4
-----Original Message-----
From: Steve Brown <[email protected]>
Sent: Tuesday, December 22, 2020 7:57 AM
To: [email protected]
Subject: mesh: call to Publish triggers apparent output loop in mesh/mesh-io-generic.c
Publish functions as expected, but results in continuous, very heavy
HCI traffic (~every .7ms per btmon log). I don't think it's my
application as the problem persists after the application disconnects
from dbus and exits.
The calls to LE Set Adv Param all fail. Prior to the Publish call, LE
Set Param calls succeed. The only difference I can see is the failing
ones have an interval of 50ms and the ones that succeed have 100ms. A
successful one is appended.
I'm at current Bluez head (65231892cd). The platform is a rpi4.
Below is a pretty normal looking meshd log, a btmon dump and some more
normal looking dbus traffic.
Steve
Dec 22 09:22:56 mesh0 bluetooth-meshd[38760]: mesh/node.c:publish_call() Publish
Dec 22 09:22:56 mesh0 bluetooth-meshd[38760]: mesh/mesh-config-json.c:mesh_config_write_seq_number() Seq Cache: 210 -> 274
Dec 22 09:22:56 mesh0 bluetooth-meshd[38760]: mesh/model.c:mesh_model_rx() iv_index 00000000 key_aid = 6e
Dec 22 09:22:56 mesh0 bluetooth-meshd[38760]: mesh/util.c:print_packet() 46976.692 Used App Key: dae814b7da47ab8c992fcc03a60c100b
Dec 22 09:22:56 mesh0 bluetooth-meshd[38760]: mesh/util.c:print_packet() 46976.692 Clr Rx: 820200030064
Dec 22 09:22:56 mesh0 bluetooth-meshd[38760]: mesh/net.c:send_seg() segN 0 segment 0 seg_off 0
Dec 22 09:22:56 mesh0 bluetooth-meshd[38760]: mesh/util.c:print_packet() 46976.692 Clr-Net Tx: 00080000d10001c0006eaaffbb7633799725e9d600000000
Dec 22 09:22:56 mesh0 bluetooth-meshd[38760]: mesh/util.c:print_packet() 46976.693 RX: Network [enc] :: 7eb235f367ed0172ca7d0345f4a1d9ce42d116f80ab00b0e
Dec 22 09:22:56 mesh0 bluetooth-meshd[38760]: mesh/util.c:print_packet() 46976.693 RX: Network [clr] :: 7e080000d10001c0006eaaffbb7633799725e9d6
Dec 22 09:22:56 mesh0 bluetooth-meshd[38760]: mesh/util.c:print_packet() 46976.715 RX: Network [enc] :: 7e6e7c8a337f4355f2921b9d8fd3e7eb3a866af261fc46d1
Dec 22 09:22:56 mesh0 bluetooth-meshd[38760]: mesh/util.c:print_packet() 46976.715 RX: Network [clr] :: 7e070000d10001c0006eaaffbb7633799725e9d6
Dec 22 09:22:57 mesh0 bluetooth-meshd[38760]: mesh/util.c:print_packet() 46977.097 RX: Network [enc] :: 7e3a351647d646ec107415b165540e1057fdc9847c
Dec 22 09:22:57 mesh0 bluetooth-meshd[38760]: mesh/util.c:print_packet() 46977.097 RX: Network [clr] :: 7e0a00007d010000016e8961a6de509fb1
Dec 22 09:22:57 mesh0 bluetooth-meshd[38760]: mesh/net.c:msg_in_cache() Add 0100 + 00007d + 6e8961a6
Dec 22 09:22:57 mesh0 bluetooth-meshd[38760]: mesh/net.c:packet_received() RX: Network 0100 -> 0001 : TTL 0x0a : IV : 00000000 SEQ 0x00007d
Dec 22 09:22:57 mesh0 bluetooth-meshd[38760]: mesh/net.c:packet_received() RX: App 0x0100 -> 0x0001 : TTL 0x0a : SEQ 0x00007d
Dec 22 09:22:57 mesh0 bluetooth-meshd[38760]: mesh/model.c:mesh_model_rx() iv_index 00000000 key_aid = 6e
Dec 22 09:22:57 mesh0 bluetooth-meshd[38760]: mesh/util.c:print_packet() 46977.097 Used App Key: dae814b7da47ab8c992fcc03a60c100b
Dec 22 09:22:57 mesh0 bluetooth-meshd[38760]: mesh/util.c:print_packet() 46977.097 Clr Rx: 820400
Dec 22 09:22:57 mesh0 bluetooth-meshd[38760]: mesh/model.c:send_msg_rcvd() Send "MessageReceived"
============================================================================================================================
btmon output after Publish call:
< HCI Command: LE Set Advertising Parameters (0x08|0x0006) plen 15 #1756 [hci0] 60.253779
Min advertising interval: 50.000 msec (0x0050)
Max advertising interval: 50.000 msec (0x0050)
Type: Non connectable undirected - ADV_NONCONN_IND (0x03)
Own address type: Random (0x01)
Direct address type: Public (0x00)
Direct address: 00:00:00:00:00:00 (OUI 00-00-00)
Channel map: 37, 38, 39 (0x07)
Filter policy: Allow Scan Request from White List Only, Allow Connect Request from White List Only (0x03)
> HCI Event: Command Complete (0x0e) plen 4 #1757 [hci0] 60.254089
LE Set Advertising Parameters (0x08|0x0006) ncmd 1
Status: Invalid HCI Command Parameters (0x12)
< HCI Command: LE Set Advertising Data (0x08|0x0008) plen 32 #1758 [hci0] 60.254304
Length: 26
Mesh Data: 7eb235f367ed0172ca7d0345f4a1d9ce42d116f80ab00b0e
IVI: 0
NID: 0x7e
b2 35 f3 67 ed 01 72 ca 7d 03 45 f4 a1 d9 ce 42 .5.g..r.}.E....B
d1 16 f8 0a b0 0b 0e .......
> HCI Event: Command Complete (0x0e) plen 4 #1759 [hci0] 60.254686
LE Set Advertising Data (0x08|0x0008) ncmd 1
Status: Success (0x00)
< HCI Command: LE Set Advertise Enable (0x08|0x000a) plen 1 #1760 [hci0] 60.254874
Advertising: Enabled (0x01)
> HCI Event: Command Complete (0x0e) plen 4 #1761 [hci0] 60.255170
LE Set Advertise Enable (0x08|0x000a) ncmd 1
Status: Success (0x00)
< HCI Command: LE Set Advertise Enable (0x08|0x000a) plen 1 #1762 [hci0] 60.302847
Advertising: Disabled (0x00)
> HCI Event: Command Complete (0x0e) plen 4 #1763 [hci0] 60.303586
LE Set Advertise Enable (0x08|0x000a) ncmd 1
Status: Success (0x00)
< HCI Command: LE Set Advertising Parameters (0x08|0x0006) plen 15 #1764 [hci0] 60.303744
Min advertising interval: 50.000 msec (0x0050)
Max advertising interval: 50.000 msec (0x0050)
Type: Non connectable undirected - ADV_NONCONN_IND (0x03)
Own address type: Random (0x01)
Direct address type: Public (0x00)
Direct address: 00:00:00:00:00:00 (OUI 00-00-00)
Channel map: 37, 38, 39 (0x07)
Filter policy: Allow Scan Request from White List Only, Allow Connect Request from White List Only (0x03)
> HCI Event: Command Complete (0x0e) plen 4 #1765 [hci0] 60.304053
LE Set Advertising Parameters (0x08|0x0006) ncmd 1
=====================================================================================================
dbus-monitor output
method call time=1608649585.797421 sender=:1.223 -> destination=org.bluez.mesh serial=21 path=/org/bluez/mesh/nodeb3f28276086958109ac1e2cbd76fbf7e; interface=org.bluez.mesh.Node1; member=Publish
object path "/com/silvair/sample/element0"
uint16 4097
array [
]
array of bytes [
82 02 00 03 00 64
]
method return time=1608649585.798741 sender=:1.221 -> destination=:1.223 serial=29 reply_serial=21
method call time=1608649586.337429 sender=:1.221 -> destination=:1.223 serial=30 path=/com/silvair/sample/element0; interface=org.bluez.mesh.Element1; member=MessageReceived
uint16 256
uint16 1
variant uint16 1
array of bytes [
82 04 00
]
===================================================================================
Successful LE Set Adv Param
< HCI Command: LE Set Advertising Parameters (0x08|0x0006) plen 15 #90 [hci0] 6.392018
Min advertising interval: 100.000 msec (0x00a0)
Max advertising interval: 100.000 msec (0x00a0)
Type: Non connectable undirected - ADV_NONCONN_IND (0x03)
Own address type: Random (0x01)
Direct address type: Public (0x00)
Direct address: 00:00:00:00:00:00 (OUI 00-00-00)
Channel map: 37, 38, 39 (0x07)
Filter policy: Allow Scan Request from White List Only, Allow Connect Request from White List Only (0x03)
> HCI Event: Command Complete (0x0e) plen 4 #91 [hci0] 6.392399
LE Set Advertising Parameters (0x08|0x0006) ncmd 1
Status: Success (0x00)
Hi Brian,
On Tue, 2020-12-22 at 18:43 +0000, Gix, Brian wrote:
> Hi Steve, I will investigate on my RPI4
>
> -----Original Message-----
> From: Steve Brown <[email protected]>
> Sent: Tuesday, December 22, 2020 7:57 AM
> To: [email protected]
> Subject: mesh: call to Publish triggers apparent output loop in
> mesh/mesh-io-generic.c
>
> Publish functions as expected, but results in continuous, very heavy
> HCI traffic (~every .7ms per btmon log). I don't think it's my
> application as the problem persists after the application disconnects
> from dbus and exits.
>
> The calls to LE Set Adv Param all fail. Prior to the Publish call, LE
> Set Param calls succeed. The only difference I can see is the failing
> ones have an interval of 50ms and the ones that succeed have 100ms. A
> successful one is appended.
>
> I'm at current Bluez head (65231892cd). The platform is a rpi4.
>
> Below is a pretty normal looking meshd log, a btmon dump and some
> more
> normal looking dbus traffic.
>
> Steve
I think I found my problem. My retransmit count was set to zero.
If the publish retransmit count is 0, mesh-io-generic.c:tx_to() repeats
the message indefinitely. However, 4.2.2.6 of the mesh profile spec
V1.0 seems to state that 0 means no retransmissions.
Steve
On Thu, 2020-12-24 at 04:23 -0500, Steve Brown wrote:
> Hi Brian,
>
> On Tue, 2020-12-22 at 18:43 +0000, Gix, Brian wrote:
> > Hi Steve, I will investigate on my RPI4
> >
> > -----Original Message-----
> > From: Steve Brown <[email protected]>
> > Sent: Tuesday, December 22, 2020 7:57 AM
> > To: [email protected]
> > Subject: mesh: call to Publish triggers apparent output loop in
> > mesh/mesh-io-generic.c
> >
> > Publish functions as expected, but results in continuous, very heavy
> > HCI traffic (~every .7ms per btmon log). I don't think it's my
> > application as the problem persists after the application disconnects
> > from dbus and exits.
> >
> > The calls to LE Set Adv Param all fail. Prior to the Publish call, LE
> > Set Param calls succeed. The only difference I can see is the failing
> > ones have an interval of 50ms and the ones that succeed have 100ms. A
> > successful one is appended.
> >
> > I'm at current Bluez head (65231892cd). The platform is a rpi4.
> >
> > Below is a pretty normal looking meshd log, a btmon dump and some
> > more
> > normal looking dbus traffic.
> >
> > Steve
>
> I think I found my problem. My retransmit count was set to zero.
That's a good catch, Steve. The CNT value from the Publish message is supposed to be the number of *RE* -
transmissions, not the total number of transmits. 0 is special cased internally as "Infinite", so we need to
add 1 to the CNT value for the actual total transmissions.
I will talk with Inga to see where we want to make this tweek.
>
> If the publish retransmit count is 0, mesh-io-generic.c:tx_to() repeats
> the message indefinitely. However, 4.2.2.6 of the mesh profile spec
> V1.0 seems to state that 0 means no retransmissions.
>
> Steve
>
>