search

prplfoundation / prplMesh

This repository moved to https://gitlab.com/prpl-foundation/prplmesh/prplMesh
Other
65 stars 31 forks source link

[TASK] Pass test MAP-4.8.1_ETH_FH5GH in testbed #937

Closed rmelotte closed 4 years ago

rmelotte commented 4 years ago

This issue is to keep track of the 5GH variant of test 4.8.1. The original issue for 4.8.1 was here: https://github.com/prplfoundation/prplMesh/issues/400

A job where the test is failing is here: https://gitlab.com/prpl-foundation/prplMesh/-/jobs/464453896

It currently fails with:

No association request from CTT STA to MAUT

It has never passed yet, and I suspect prplMesh is not operating on the correct channel.

If it's the case, it's probably not specific to 4.8.1 and will be fixed when fixing this issue: https://github.com/prplfoundation/prplMesh/issues/368

tomereli commented 4 years ago 
DEBUG 15:25:09:631 <2002279200> son_slave_thread.cpp[4594] --> Received CHANNEL_SELECTION_REQUEST_MESSAGE, mid=1788
DEBUG 15:25:09:632 <2002279200> son_slave_thread.cpp[4559] --> operating class=81, preference=0, reason=0, channel_list={}
DEBUG 15:25:09:632 <2002279200> son_slave_thread.cpp[4559] --> operating class=82, preference=0, reason=0, channel_list={}
DEBUG 15:25:09:633 <2002279200> son_slave_thread.cpp[4559] --> operating class=83, preference=0, reason=0, channel_list={}
DEBUG 15:25:09:633 <2002279200> son_slave_thread.cpp[4559] --> operating class=84, preference=0, reason=0, channel_list={}
DEBUG 15:25:09:633 <2002279200> son_slave_thread.cpp[4559] --> operating class=115, preference=0, reason=0, channel_list={}
DEBUG 15:25:09:634 <2002279200> son_slave_thread.cpp[4559] --> operating class=116, preference=0, reason=0, channel_list={}
DEBUG 15:25:09:634 <2002279200> son_slave_thread.cpp[4559] --> operating class=117, preference=0, reason=0, channel_list={}
DEBUG 15:25:09:635 <2002279200> son_slave_thread.cpp[4559] --> operating class=118, preference=0, reason=0, channel_list={}
DEBUG 15:25:09:635 <2002279200> son_slave_thread.cpp[4559] --> operating class=119, preference=0, reason=0, channel_list={}
DEBUG 15:25:09:636 <2002279200> son_slave_thread.cpp[4559] --> operating class=120, preference=0, reason=0, channel_list={}
DEBUG 15:25:09:636 <2002279200> son_slave_thread.cpp[4559] --> operating class=121, preference=0, reason=0, channel_list={}
DEBUG 15:25:09:640 <2002279200> son_slave_thread.cpp[4559] --> operating class=122, preference=0, reason=0, channel_list={}
DEBUG 15:25:09:640 <2002279200> son_slave_thread.cpp[4559] --> operating class=123, preference=0, reason=0, channel_list={}
DEBUG 15:25:09:641 <2002279200> son_slave_thread.cpp[4559] --> operating class=124, preference=0, reason=0, channel_list={153,157,161}
DEBUG 15:25:09:641 <2002279200> son_slave_thread.cpp[4559] --> operating class=125, preference=0, reason=0, channel_list={153,157,161,165,169}
DEBUG 15:25:09:642 <2002279200> son_slave_thread.cpp[4559] --> operating class=126, preference=0, reason=0, channel_list={157}
DEBUG 15:25:09:643 <2002279200> son_slave_thread.cpp[4559] --> operating class=127, preference=0, reason=0, channel_list={}
DEBUG 15:25:09:643 <2002279200> son_slave_thread.cpp[4559] --> operating class=128, preference=0, reason=0, channel_list={42,58,106,122,138}
DEBUG 15:25:09:644 <2002279200> son_slave_thread.cpp[4559] --> operating class=129, preference=0, reason=0, channel_list={}
DEBUG 15:25:09:653 <2002279200> son_slave_thread.cpp[4559] --> operating class=130, preference=0, reason=0, channel_list={}
DEBUG 15:25:09:654 <2002279200> son_slave_thread.cpp[4584] --> received tlvTransmitPowerLimit 20
INFO 15:25:09:654 <2002279200> son_slave_thread.cpp[4500] --> Current channel 36 not restricted, channel switch not required

The bug is that we don't consider channel 36 to be restricted, so we don't move, although it is reported as non-operable since it is part of operating classes 115 and 116 which are both non-operable. https://docs.google.com/spreadsheets/d/1J2IYuGjFX_OQQpgb4OgsyDx73klAUk6qSmeB4acJ5us/edit#gid=0

tomereli commented 4 years ago

With #938 debug information we can see that we still don't treat channel 36 as non operable although it is part of a non-operable operating class:

DEBUG 22:54:00:018 <1988852512> son_slave_thread.cpp[4601] --> Received CHANNEL_SELECTION_REQUEST_MESSAGE, mid=54703
DEBUG 22:54:00:019 <1988852512> son_slave_thread.cpp[4566] --> operating class=81, preference=0, reason=0, channel_list={}
DEBUG 22:54:00:020 <1988852512> son_slave_thread.cpp[4566] --> operating class=82, preference=0, reason=0, channel_list={}
DEBUG 22:54:00:020 <1988852512> son_slave_thread.cpp[4566] --> operating class=83, preference=0, reason=0, channel_list={}
DEBUG 22:54:00:021 <1988852512> son_slave_thread.cpp[4566] --> operating class=84, preference=0, reason=0, channel_list={}
DEBUG 22:54:00:021 <1988852512> son_slave_thread.cpp[4566] --> operating class=115, preference=0, reason=0, channel_list={}
DEBUG 22:54:00:022 <1988852512> son_slave_thread.cpp[4566] --> operating class=116, preference=0, reason=0, channel_list={}
DEBUG 22:54:00:022 <1988852512> son_slave_thread.cpp[4566] --> operating class=117, preference=0, reason=0, channel_list={}
DEBUG 22:54:00:023 <1988852512> son_slave_thread.cpp[4566] --> operating class=118, preference=0, reason=0, channel_list={}
DEBUG 22:54:00:023 <1988852512> son_slave_thread.cpp[4566] --> operating class=119, preference=0, reason=0, channel_list={}
DEBUG 22:54:00:024 <1988852512> son_slave_thread.cpp[4566] --> operating class=120, preference=0, reason=0, channel_list={}
DEBUG 22:54:00:024 <1988852512> son_slave_thread.cpp[4566] --> operating class=121, preference=0, reason=0, channel_list={}
DEBUG 22:54:00:025 <1988852512> son_slave_thread.cpp[4566] --> operating class=122, preference=0, reason=0, channel_list={}
DEBUG 22:54:00:025 <1988852512> son_slave_thread.cpp[4566] --> operating class=123, preference=0, reason=0, channel_list={}
DEBUG 22:54:00:026 <1988852512> son_slave_thread.cpp[4566] --> operating class=124, preference=0, reason=0, channel_list={153,157,161}
DEBUG 22:54:00:026 <1988852512> son_slave_thread.cpp[4566] --> operating class=125, preference=0, reason=0, channel_list={153,157,161,165,169}
DEBUG 22:54:00:027 <1988852512> son_slave_thread.cpp[4566] --> operating class=126, preference=0, reason=0, channel_list={157}
DEBUG 22:54:00:027 <1988852512> son_slave_thread.cpp[4566] --> operating class=127, preference=0, reason=0, channel_list={}
DEBUG 22:54:00:028 <1988852512> son_slave_thread.cpp[4566] --> operating class=128, preference=0, reason=0, channel_list={42,58,106,122,138}
DEBUG 22:54:00:028 <1988852512> son_slave_thread.cpp[4566] --> operating class=129, preference=0, reason=0, channel_list={}
DEBUG 22:54:00:029 <1988852512> son_slave_thread.cpp[4566] --> operating class=130, preference=0, reason=0, channel_list={}
DEBUG 22:54:00:029 <1988852512> son_slave_thread.cpp[4591] --> received tlvTransmitPowerLimit 20
INFO 22:54:00:030 <1988852512> son_slave_thread.cpp[4476] --> Current channel 36 bw 2 oper_class 128
INFO 22:54:00:030 <1988852512> son_slave_thread.cpp[4479] --> preference oper_class 81 non-operable 1
INFO 22:54:00:031 <1988852512> son_slave_thread.cpp[4479] --> preference oper_class 82 non-operable 1
INFO 22:54:00:031 <1988852512> son_slave_thread.cpp[4479] --> preference oper_class 83 non-operable 1
INFO 22:54:00:031 <1988852512> son_slave_thread.cpp[4479] --> preference oper_class 84 non-operable 1
INFO 22:54:00:032 <1988852512> son_slave_thread.cpp[4479] --> preference oper_class 115 non-operable 1
INFO 22:54:00:032 <1988852512> son_slave_thread.cpp[4479] --> preference oper_class 116 non-operable 1
INFO 22:54:00:033 <1988852512> son_slave_thread.cpp[4479] --> preference oper_class 117 non-operable 1
INFO 22:54:00:033 <1988852512> son_slave_thread.cpp[4479] --> preference oper_class 118 non-operable 1
INFO 22:54:00:034 <1988852512> son_slave_thread.cpp[4479] --> preference oper_class 119 non-operable 1
INFO 22:54:00:034 <1988852512> son_slave_thread.cpp[4479] --> preference oper_class 120 non-operable 1
INFO 22:54:00:034 <1988852512> son_slave_thread.cpp[4479] --> preference oper_class 121 non-operable 1
INFO 22:54:00:035 <1988852512> son_slave_thread.cpp[4479] --> preference oper_class 122 non-operable 1
INFO 22:54:00:035 <1988852512> son_slave_thread.cpp[4479] --> preference oper_class 123 non-operable 1
INFO 22:54:00:036 <1988852512> son_slave_thread.cpp[4479] --> preference oper_class 124 non-operable 0
INFO 22:54:00:036 <1988852512> son_slave_thread.cpp[4479] --> preference oper_class 125 non-operable 0
INFO 22:54:00:037 <1988852512> son_slave_thread.cpp[4479] --> preference oper_class 126 non-operable 0
INFO 22:54:00:037 <1988852512> son_slave_thread.cpp[4479] --> preference oper_class 127 non-operable 1
INFO 22:54:00:038 <1988852512> son_slave_thread.cpp[4479] --> preference oper_class 128 non-operable 0
INFO 22:54:00:038 <1988852512> son_slave_thread.cpp[4479] --> preference oper_class 129 non-operable 1
INFO 22:54:00:039 <1988852512> son_slave_thread.cpp[4479] --> preference oper_class 130 non-operable 1
INFO 22:54:00:039 <1988852512> son_slave_thread.cpp[4507] --> Current channel 36 not restricted, channel switch not required
INFO 22:54:00:041 <1988852512> son_slave_thread.cpp[4664] --> Channel switch not required, sending operating channel report
DEBUG 22:54:00:044 <1988852512> son_slave_thread.cpp[4679] --> send ACTION_APMANAGER_HOSTAP_CHANNEL_SWITCH_ACS_START
DEBUG 22:54:00:045 <1984736528> ap_manager_thread.cpp[580] --> ACTION_APMANAGER_HOSTAP_CHANNEL_SWITCH_ACS_START: requested channel=36 bandwidth=20
DEBUG 22:54:00:046 <1984736528> ap_wlan_hal_dwpal.cpp[1593] --> set_tx_power_limit(): missing function implementation

Then the same issue is seen in the UCC logs:


2020-03-09 22:48:16.677 - INFO - SNIFFER (192.168.250.5:9999) ---> sniffer_control_filter_capture,InFile,_MAP-4.8.1-FH5GH-STEP4,OutFile,MAP-4.8.1-FH5GH-STEP4,srcmac,00:50:43:22:56:5f,bssid,02:9a:96:fb:59:23,FrameName,AssoReq,nframes,all
2020-03-09 22:48:17.305 - INFO - SNIFFER (192.168.250.5:9999) <-- status,COMPLETE,FilterStatus,NoPacketsFound,FrameCount,0

2020-03-09 22:48:17.313 - INFO - MSG: No association request from CTT STA to MAUT
2020-03-09 22:48:17.313 - INFO -
rmelotte commented 4 years ago

From [this job](Current channel 36 bw 2 oper_class 128) it looks like the issue is still there:

INFO 22:54:00:039 <1988852512> son_slave_thread.cpp[4507] --> Current channel 36 not restricted, channel switch not required

prplMesh also correctly recognize channels 115 and 116 as non-operable, so channel 36 should be non-operable:

INFO 22:54:00:032 <1988852512> son_slave_thread.cpp[4479] --> preference oper_class 115 non-operable 1
INFO 22:54:00:032 <1988852512> son_slave_thread.cpp[4479] --> preference oper_class 116 non-operable 1

However, there is also this:

INFO 22:54:00:030 <1988852512> son_slave_thread.cpp[4476] --> Current channel 36 bw 2 oper_class 128

So it looks like prplMesh doesn't match the correct operating classes associated with channel 36.

rmelotte commented 4 years ago

The definition of operating_classes_list is incorrect:

{128,       {{36,  40,  44,  48,  52,  56,  60,  64,  100, 104, 108, 112, 116, 120, 124, 128, 132, 136, 140, 144, 149, 153, 157, 161}, beerocks::BANDWIDTH_80}},
{129,       {{50, 66, 82, 98, 114},                                        beerocks::BANDWIDTH_160}},
{130,       {{36,  40,  44,  48,  52,  56,  60,  64,  100, 104, 108, 112, 116, 120, 124, 128, 132, 136, 140, 144, 149, 153, 157, 161}, beerocks::BANDWIDTH_160}}};
tomereli commented 4 years ago

From E.1 Country information and operating classes in the 802.11 specification:

The channel set is the list of integer channel numbers that are legal for a regulatory domain and class. A “— ” in the Channel set column of the operating classes tables (Table E-1 through Table E-5) indicates either that the values in the channel center frequency index field apply for calculating channel center frequencies of this operating class, or where both the channel set field and the channel center frequency index field are “—” indicates that the channel set is not defined by the operating class and is derived from regulation.

Relevant part in Table E-4 (Global operating classes): image

So indeed (see https://en.wikipedia.org/wiki/List_of_WLAN_channels), it appears that our definition for the channels is indeed wrong - there is no channel 36 in operating class 128,129,130 - The first channel which overlaps channel 36 in operating class 128 (bw 80) is channel 42, the first channel which overlaps channel 36 in operating class 129 (bw 160) is channel 50, and the first channel

channel 36 is overlapped by channel 42 in operating class 128 and 130 (bandwidth 80) and channel 50 in operating class 129 (bandwidth 160).

If my understanding is correct, this should be the correct channel setting:

{128,       {{42, 58, 106, 122, 138, 155}, beerocks::BANDWIDTH_80}},
{129,       {{50, 114}, beerocks::BANDWIDTH_160}},
{130,       {{42, 58, 106, 122, 138, 155}, beerocks::BANDWIDTH_160}}};

@arnout , @YuriyMasechko please confirm.

However, this still won't solve the issue we see in the Essensium/Mind CI since it appears that channel 36 is selected on bandwidth 80 which as @arnout said just can't be - @rmelotte , can you please provide the output of hostapd_cli -iwlan2 stat and hostapd_cli -iwlan2 radio_info in the RAX40 device in the Essensium/Mind testbed?

rmelotte commented 4 years ago

hostapd_cli -i wlan2 status:

state=ENABLED
phy=phy1
freq=5180
num_sta_non_erp=0
num_sta_no_short_slot_time=0
num_sta_no_short_preamble=0
olbc=0
num_sta_ht_no_gf=0
num_sta_no_ht=0
num_sta_ht_20_mhz=0
num_sta_ht40_intolerant=0
olbc_ht=0
ht_op_mode=0x0
cac_time_seconds=0
cac_time_left_seconds=N/A
channel=36
secondary_channel=1
ieee80211n=1
ieee80211ac=1
ieee80211ax=1
beacon_int=100
dtim_period=2
vht_oper_chwidth=1
vht_oper_centr_freq_seg0_idx=42
vht_oper_centr_freq_seg1_idx=0
vht_caps_info=03a978f6
rx_vht_mcs_map=fffa
tx_vht_mcs_map=fffa
ht_caps_info=08ef
ht_mcs_bitmask=ffff0000010000000000
supported_rates=0c 12 18 24 30 48 60 6c
max_txpower=30

hostapd_cli -i wlan2 radio_info:

Name=wlan2
HostapdEnabled=1
TxEnabled=1
Channel=36
BytesSent=447030
BytesReceived=57882053800
PacketsSent=5734
PacketsReceived=81
ErrorsSent=0
ErrorsReceived=0
DiscardPacketsSent=0
DiscardPacketsReceived=0
PLCPErrorCount=UNKNOWN
FCSErrorCount=0
InvalidMACCount=UNKNOWN
PacketsOtherReceived=UNKNOWN
Noise=0
BSS load=6
TxPower=3335.75
RxAntennas=2
TxAntennas=2
Freq=5180
OperatingChannelBandwidt=80
Cf1=5210
Dfs_chan=0
tomereli commented 4 years ago

Thanks, @rmelotte - it seems I was wrong, hostapd still reports channel 36 although the center frequency is 5210 which is channel 42. It looks like the UCC is using the center channel and not the starting channel:

DEBUG 22:54:00:028 <1988852512> son_slave_thread.cpp[4566] --> operating class=128, preference=0, reason=0, channel_list={42,58,106,122,138}
DEBUG 22:54:00:028 <1988852512> son_slave_thread.cpp[4566] --> operating class=129, preference=0, reason=0, channel_list={}
DEBUG 22:54:00:029 <1988852512> son_slave_thread.cpp[4566] --> operating class=130, preference=0, reason=0, channel_list={}

So we should convert starting channel (which is what we get from BWL) to center channel when we check if the channel is non-operable, if the bandwidth is higher than 20.

arnout commented 4 years ago

So we should convert starting channel (which is what we get from BWL) to center channel when we check if the channel is non-operable, if the bandwidth is higher than 20.

I think that that is only for 80 and 160MHz, i.e. only operclasses 128, 129, 130. The other operclasses do use the starting channel AFAIU.

tomereli commented 4 years ago

So we should convert starting channel (which is what we get from BWL) to center channel when we check if the channel is non-operable, if the bandwidth is higher than 20.

I think that that is only for 80 and 160MHz, i.e. only operclasses 128, 129, 130. The other operclasses do use the starting channel AFAIU.

Exactly. See https://github.com/prplfoundation/prplMesh/pull/938/commits/e89d247a34047fb1fe35c89b49a24d332b0f06e8

rmelotte commented 4 years ago

Passing job (with #938): https://gitlab.com/prpl-foundation/prplMesh/-/jobs/466014120