Bug 242337 - iwm - rate 0 causes iwm panic (and work around)
Summary: iwm - rate 0 causes iwm panic (and work around)
Status: New
Alias: None
Product: Base System
Classification: Unclassified
Component: wireless (show other bugs)
Version: 12.1-RELEASE
Hardware: amd64 Any
: --- Affects Some People
Assignee: freebsd-wireless mailing list
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2019-12-01 13:17 UTC by dirkx
Modified: 2020-01-18 20:56 UTC (History)
2 users (show)

See Also:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description dirkx 2019-12-01 13:17:27 UTC

    
Comment 1 dirkx 2019-12-01 13:21:23 UTC
The standard IWM wifi card on a thinkpad X270 panics when it wants to talk to a dutch KPN-Experia ADLS/wifi router (a very common setup in the Netherlands).

Panic/dmesg below.

It then flaps up/down - but is unable to get a stable connection.

iwm0: Start UMAC Error Log Dump:
iwm0: Status: 0x83, count: 7
iwm0: 0x00000070 | ADVANCED_SYSASSERT
iwm0: 0x00000000 | umac branchlink1
iwm0: 0xC008383C | umac branchlink2
iwm0: 0xC008166C | umac interruptlink1
iwm0: 0xC008166C | umac interruptlink2
iwm0: 0x00000800 | umac data1
iwm0: 0xC008166C | umac data2
iwm0: 0xDEADBEEF | umac data3
iwm0: 0x00000016 | umac major
iwm0: 0x00058404 | umac minor
iwm0: 0xC0886280 | frame pointer
iwm0: 0xC0886280 | stack pointer
iwm0: 0x0934004E | last host cmd
iwm0: 0x00000000 | isr status reg
iwm0: driver status:
iwm0:   tx ring  0: qid=0  cur=2   queued=0  
iwm0:   tx ring  1: qid=1  cur=0   queued=0  
iwm0:   tx ring  2: qid=2  cur=0   queued=0  
iwm0:   tx ring  3: qid=3  cur=0   queued=0  
iwm0:   tx ring  4: qid=4  cur=0   queued=0  
iwm0:   tx ring  5: qid=5  cur=0   queued=0  
iwm0:   tx ring  6: qid=6  cur=0   queued=0  
iwm0:   tx ring  7: qid=7  cur=0   queued=0  
iwm0:   tx ring  8: qid=8  cur=0   queued=0  
iwm0:   tx ring  9: qid=9  cur=53  queued=1  
iwm0:   tx ring 10: qid=10 cur=0   queued=0  
iwm0:   tx ring 11: qid=11 cur=0   queued=0  
iwm0:   tx ring 12: qid=12 cur=0   queued=0  
iwm0:   tx ring 13: qid=13 cur=0   queued=0  
iwm0:   tx ring 14: qid=14 cur=0   queued=0  
iwm0:   tx ring 15: qid=15 cur=0   queued=0  
iwm0:   tx ring 16: qid=16 cur=0   queued=0  
iwm0:   tx ring 17: qid=17 cur=0   queued=0  
iwm0:   tx ring 18: qid=18 cur=0   queued=0  
iwm0:   tx ring 19: qid=19 cur=0   queued=0  
iwm0:   tx ring 20: qid=20 cur=0   queued=0  
iwm0:   tx ring 21: qid=21 cur=0   queued=0  
iwm0:   tx ring 22: qid=22 cur=0   queued=0  
iwm0:   tx ring 23: qid=23 cur=0   queued=0  
iwm0:   tx ring 24: qid=24 cur=0   queued=0  
iwm0:   tx ring 25: qid=25 cur=0   queued=0  
iwm0:   tx ring 26: qid=26 cur=0   queued=0  
iwm0:   tx ring 27: qid=27 cur=0   queued=0  
iwm0:   tx ring 28: qid=28 cur=0   queued=0  
iwm0:   tx ring 29: qid=29 cur=0   queued=0  
iwm0:   tx ring 30: qid=30 cur=0   queued=0  
iwm0:   rx ring: cur=80
iwm0:   802.11 state 3
iwm0: iwm_intr: controller panicked, iv_state = 3; restarting
iwm0: iwm_newstate: IWM_LQ_CMD failed: 35
iwm0: iwm_rate2ridx: WARNING: device rate for 0 not found!
iwm0: iwm_rate2ridx: WARNING: device rate for 0 not found!
iwm0: dumping device error log
iwm0: Start Error Log Dump:
iwm0: Status: 0x83, count: 6
iwm0: 0x00002078 | ADVANCED_SYSASSERT          
iwm0: 00A00220 | trm_hw_status0
iwm0: 00000000 | trm_hw_status1
iwm0: 0000E9C8 | branchlink2
iwm0: 0002843C | interruptlink1
iwm0: 00000000 | interruptlink2
iwm0: 00000000 | data1
iwm0: 00000000 | data2
iwm0: DEADBEEF | data3
iwm0: 00014E39 | beacon time
iwm0: 4494D2A2 | tsf low
iwm0: 00000055 | tsf hi
iwm0: 00000000 | time gp1
iwm0: 00E55138 | time gp2
iwm0: 00000000 | uCode revision type
iwm0: 00000016 | uCode version major
iwm0: 00058404 | uCode version minor
iwm0: 00000201 | hw version
iwm0: 00009008 | board version
iwm0: 0936004E | hcmd
iwm0: 24022080 | isr0
iwm0: 01000000 | isr1
iwm0: 08205802 | isr2
iwm0: 00417CC0 | isr3
iwm0: 00000000 | isr4
iwm0: 04000118 | last cmd Id
iwm0: 00000000 | wait_event
iwm0: 00000288 | l2p_control
iwm0: 00018030 | l2p_duration
iwm0: 000000BF | l2p_mhvalid
iwm0: 000000EF | l2p_addr_match
iwm0: 0000000D | lmpm_pmg_sel
iwm0: 03071928 | timestamp
iwm0: 00008090 | flow_handler
iwm0: Start UMAC Error Log Dump:
iwm0: Status: 0x83, count: 7
iwm0: 0x00000070 | ADVANCED_SYSASSERT
iwm0: 0x00000000 | umac branchlink1
iwm0: 0xC008383C | umac branchlink2
iwm0: 0xC008166C | umac interruptlink1
iwm0: 0xC008166C | umac interruptlink2
iwm0: 0x00000800 | umac data1
iwm0: 0xC008166C | umac data2
iwm0: 0xDEADBEEF | umac data3
iwm0: 0x00000016 | umac major
iwm0: 0x00058404 | umac minor
iwm0: 0xC0886280 | frame pointer
iwm0: 0xC0886280 | stack pointer
iwm0: 0x0936004E | last host cmd
iwm0: 0x00000000 | isr status reg
iwm0: driver status:
iwm0:   tx ring  0: qid=0  cur=2   queued=0  
iwm0:   tx ring  1: qid=1  cur=0   queued=0  
iwm0:   tx ring  2: qid=2  cur=0   queued=0  
iwm0:   tx ring  3: qid=3  cur=0   queued=0  
iwm0:   tx ring  4: qid=4  cur=0   queued=0  
iwm0:   tx ring  5: qid=5  cur=0   queued=0  
iwm0:   tx ring  6: qid=6  cur=0   queued=0  
iwm0:   tx ring  7: qid=7  cur=0   queued=0  
iwm0:   tx ring  8: qid=8  cur=0   queued=0  
iwm0:   tx ring  9: qid=9  cur=55  queued=1  
iwm0:   tx ring 10: qid=10 cur=0   queued=0  
iwm0:   tx ring 11: qid=11 cur=0   queued=0  
iwm0:   tx ring 12: qid=12 cur=0   queued=0  
iwm0:   tx ring 13: qid=13 cur=0   queued=0  
iwm0:   tx ring 14: qid=14 cur=0   queued=0  
iwm0:   tx ring 15: qid=15 cur=0   queued=0  
iwm0:   tx ring 16: qid=16 cur=0   queued=0  
iwm0:   tx ring 17: qid=17 cur=0   queued=0  
iwm0:   tx ring 18: qid=18 cur=0   queued=0  
iwm0:   tx ring 19: qid=19 cur=0   queued=0  
iwm0:   tx ring 20: qid=20 cur=0   queued=0  
iwm0:   tx ring 21: qid=21 cur=0   queued=0  
iwm0:   tx ring 22: qid=22 cur=0   queued=0  
iwm0:   tx ring 23: qid=23 cur=0   queued=0  
iwm0:   tx ring 24: qid=24 cur=0   queued=0  
iwm0:   tx ring 25: qid=25 cur=0   queued=0  
iwm0:   tx ring 26: qid=26 cur=0   queued=0  
iwm0:   tx ring 27: qid=27 cur=0   queued=0  
iwm0:   tx ring 28: qid=28 cur=0   queued=0  
iwm0:   tx ring 29: qid=29 cur=0   queued=0  
iwm0:   tx ring 30: qid=30 cur=0   queued=0  
iwm0:   rx ring: cur=134
iwm0:   802.11 state 3
iwm0: iwm_intr: controller panicked, iv_state = 3; restarting
iwm0: iwm_newstate: IWM_LQ_CMD failed: 35
iwm0: iwm_rate2ridx: WARNING: device rate for 0 not found!
iwm0: iwm_rate2ridx: WARNING: device rate for 0 not found!
iwm0: dumping device error log
iwm0: Start Error Log Dump:
iwm0: Status: 0x83, count: 6
iwm0: 0x00002078 | ADVANCED_SYSASSERT          
iwm0: 00A00220 | trm_hw_status0
iwm0: 00000000 | trm_hw_status1
iwm0: 0000E9C8 | branchlink2
iwm0: 0002843C | interruptlink1
iwm0: 00000000 | interruptlink2
iwm0: 00000000 | data1
iwm0: 00000000 | data2
iwm0: DEADBEEF | data3
iwm0: 00017F0F | beacon time
iwm0: 4650619F | tsf low
iwm0: 00000055 | tsf hi
iwm0: 00000000 | time gp1
iwm0: 0137F04B | time gp2
iwm0: 00000000 | uCode revision type
iwm0: 00000016 | uCode version major
iwm0: 00058404 | uCode version minor
iwm0: 00000201 | hw version
iwm0: 00009008 | board version
iwm0: 0937004E | hcmd
iwm0: 24022080 | isr0
iwm0: 01000000 | isr1
iwm0: 08201802 | isr2
iwm0: 00417CC0 | isr3
iwm0: 00000000 | isr4
iwm0: 04000118 | last cmd Id
iwm0: 00000000 | wait_event
iwm0: 00000288 | l2p_control
iwm0: 00018030 | l2p_duration
iwm0: 000000BF | l2p_mhvalid
iwm0: 000000EF | l2p_addr_match
iwm0: 0000000D | lmpm_pmg_sel
iwm0: 03071928 | timestamp
iwm0: 000090A0 | flow_handler
iwm0: Start UMAC Error Log Dump:
iwm0: Status: 0x83, count: 7
iwm0: 0x00000070 | ADVANCED_SYSASSERT
iwm0: 0x00000000 | umac branchlink1
iwm0: 0xC008383C | umac branchlink2
iwm0: 0xC008166C | umac interruptlink1
iwm0: 0xC008166C | umac interruptlink2
iwm0: 0x00000800 | umac data1
iwm0: 0xC008166C | umac data2
iwm0: 0xDEADBEEF | umac data3
iwm0: 0x00000016 | umac major
iwm0: 0x00058404 | umac minor
iwm0: 0xC0886280 | frame pointer
iwm0: 0xC0886280 | stack pointer
iwm0: 0x0937004E | last host cmd
iwm0: 0x00000000 | isr status reg
iwm0: driver status:
iwm0:   tx ring  0: qid=0  cur=2   queued=0  
iwm0:   tx ring  1: qid=1  cur=0   queued=0  
iwm0:   tx ring  2: qid=2  cur=0   queued=0  
iwm0:   tx ring  3: qid=3  cur=0   queued=0  
iwm0:   tx ring  4: qid=4  cur=0   queued=0  
iwm0:   tx ring  5: qid=5  cur=0   queued=0  
iwm0:   tx ring  6: qid=6  cur=0   queued=0  
iwm0:   tx ring  7: qid=7  cur=0   queued=0  
iwm0:   tx ring  8: qid=8  cur=0   queued=0  
iwm0:   tx ring  9: qid=9  cur=56  queued=1  
iwm0:   tx ring 10: qid=10 cur=0   queued=0  
iwm0:   tx ring 11: qid=11 cur=0   queued=0  
iwm0:   tx ring 12: qid=12 cur=0   queued=0  
iwm0:   tx ring 13: qid=13 cur=0   queued=0  
iwm0:   tx ring 14: qid=14 cur=0   queued=0  
iwm0:   tx ring 15: qid=15 cur=0   queued=0  
iwm0:   tx ring 16: qid=16 cur=0   queued=0  
iwm0:   tx ring 17: qid=17 cur=0   queued=0  
iwm0:   tx ring 18: qid=18 cur=0   queued=0  
iwm0:   tx ring 19: qid=19 cur=0   queued=0  
iwm0:   tx ring 20: qid=20 cur=0   queued=0  
iwm0:   tx ring 21: qid=21 cur=0   queued=0  
iwm0:   tx ring 22: qid=22 cur=0   queued=0  
iwm0:   tx ring 23: qid=23 cur=0   queued=0  
iwm0:   tx ring 24: qid=24 cur=0   queued=0  
iwm0:   tx ring 25: qid=25 cur=0   queued=0  
iwm0:   tx ring 26: qid=26 cur=0   queued=0  
iwm0:   tx ring 27: qid=27 cur=0   queued=0  
iwm0:   tx ring 28: qid=28 cur=0   queued=0  
iwm0:   tx ring 29: qid=29 cur=0   queued=0  
iwm0:   tx ring 30: qid=30 cur=0   queued=0  
iwm0:   rx ring: cur=152
iwm0:   802.11 state 3
iwm0: iwm_intr: controller panicked, iv_state = 3; restarting
iwm0: iwm_newstate: IWM_LQ_CMD failed: 35
iwm0: iwm_rate2ridx: WARNING: device rate for 0 not found!
iwm0: iwm_rate2ridx: WARNING: device rate for 0 not found!
iwm0: dumping device error log
iwm0: Start Error Log Dump:
iwm0: Status: 0x83, count: 6
iwm0: 0x00002078 | ADVANCED_SYSASSERT          
iwm0: 00A00220 | trm_hw_status0
iwm0: 00000000 | trm_hw_status1
iwm0: 0000E9C8 | branchlink2
iwm0: 0002843C | interruptlink1
iwm0: 00000000 | interruptlink2
iwm0: 00000000 | data1
iwm0: 00000000 | data2
iwm0: DEADBEEF | data3
iwm0: 0001764F | beacon time
iwm0: 4955DA2D | tsf low
iwm0: 00000055 | tsf hi
iwm0: 00000000 | time gp1
iwm0: 020F98F2 | time gp2
iwm0: 00000000 | uCode revision type
iwm0: 00000016 | uCode version major
iwm0: 00058404 | uCode version minor
iwm0: 00000201 | hw version
iwm0: 00009008 | board version
iwm0: 0939004E | hcmd
iwm0: 24022080 | isr0
iwm0: 01000000 | isr1
iwm0: 08201802 | isr2
iwm0: 00417CC0 | isr3
iwm0: 00000000 | isr4
iwm0: 04000118 | last cmd Id
iwm0: 00000000 | wait_event
iwm0: 00000288 | l2p_control
iwm0: 00018030 | l2p_duration
iwm0: 000000BF | l2p_mhvalid
iwm0: 000000EF | l2p_addr_match
iwm0: 0000000D | lmpm_pmg_sel
iwm0: 03071928 | timestamp
iwm0: 0000C0D0 | flow_handler
iwm0: Start UMAC Error Log Dump:
iwm0: Status: 0x83, count: 7
iwm0: 0x00000070 | ADVANCED_SYSASSERT
iwm0: 0x00000000 | umac branchlink1
iwm0: 0xC008383C | umac branchlink2
iwm0: 0xC008166C | umac interruptlink1
iwm0: 0xC008166C | umac interruptlink2
iwm0: 0x00000800 | umac data1
iwm0: 0xC008166C | umac data2
iwm0: 0xDEADBEEF | umac data3
iwm0: 0x00000016 | umac major
iwm0: 0x00058404 | umac minor
iwm0: 0xC0886280 | frame pointer
iwm0: 0xC0886280 | stack pointer
iwm0: 0x0939004E | last host cmd
iwm0: 0x00000000 | isr status reg
iwm0: driver status:
iwm0:   tx ring  0: qid=0  cur=2   queued=0  
iwm0:   tx ring  1: qid=1  cur=0   queued=0  
iwm0:   tx ring  2: qid=2  cur=0   queued=0  
iwm0:   tx ring  3: qid=3  cur=0   queued=0  
iwm0:   tx ring  4: qid=4  cur=0   queued=0  
iwm0:   tx ring  5: qid=5  cur=0   queued=0  
iwm0:   tx ring  6: qid=6  cur=0   queued=0  
iwm0:   tx ring  7: qid=7  cur=0   queued=0  
iwm0:   tx ring  8: qid=8  cur=0   queued=0  
iwm0:   tx ring  9: qid=9  cur=58  queued=1  
iwm0:   tx ring 10: qid=10 cur=0   queued=0  
iwm0:   tx ring 11: qid=11 cur=0   queued=0  
iwm0:   tx ring 12: qid=12 cur=0   queued=0  
iwm0:   tx ring 13: qid=13 cur=0   queued=0  
iwm0:   tx ring 14: qid=14 cur=0   queued=0  
iwm0:   tx ring 15: qid=15 cur=0   queued=0  
iwm0:   tx ring 16: qid=16 cur=0   queued=0  
iwm0:   tx ring 17: qid=17 cur=0   queued=0  
iwm0:   tx ring 18: qid=18 cur=0   queued=0  
iwm0:   tx ring 19: qid=19 cur=0   queued=0  
iwm0:   tx ring 20: qid=20 cur=0   queued=0  
iwm0:   tx ring 21: qid=21 cur=0   queued=0  
iwm0:   tx ring 22: qid=22 cur=0   queued=0  
iwm0:   tx ring 23: qid=23 cur=0   queued=0  
iwm0:   tx ring 24: qid=24 cur=0   queued=0  
iwm0:   tx ring 25: qid=25 cur=0   queued=0  
iwm0:   tx ring 26: qid=26 cur=0   queued=0  
iwm0:   tx ring 27: qid=27 cur=0   queued=0  
iwm0:   tx ring 28: qid=28 cur=0   queued=0  
iwm0:   tx ring 29: qid=29 cur=0   queued=0  
iwm0:   tx ring 30: qid=30 cur=0   queued=0  
iwm0:   rx ring: cur=197
iwm0:   802.11 state 3
iwm0: iwm_intr: controller panicked, iv_state = 3; restarting
iwm0: iwm_newstate: IWM_LQ_CMD failed: 35
iwm0: detached
Comment 2 dirkx 2019-12-01 13:24:09 UTC
As a workaround - in if_iwm.c -- simply picking the first rate from the table (the slowest) makes things work again although it emits below error:


    iwm0: frame 0/230 b800002c UNHANDLED (this should not happen)
    tun0: link state changed to UP

Function changed below.

static int
iwm_rate2ridx(struct iwm_softc *sc, uint8_t rate)
{
        int i;

        for (i = 0; i <= IWM_RIDX_MAX; i++) {
                if (iwm_rates[i].rate == rate)
                        return i;
        }

        device_printf(sc->sc_dev,
            "%s: WARNING: device rate for %u not found!!\n",
            __func__, rate);

        // On KPN Experia ADSL modems - one somehow gets a rate==0;
        // just picking the first value from the table works.
        if (rate == 0) {
            device_printf(sc->sc_dev,
                "%s: WARNING: using first rate fom the table.\n",
                __func__);
            return 0;
        };
        return -1;
}
Comment 3 dirkx 2019-12-02 11:06:44 UTC
It seems that it is not just the KPN/Telfort/Tele2 Experia v8 boxes that have this issue - but a lot of other Arcadyan based wifi access points as well.
Comment 4 Mark Johnston freebsd_committer 2019-12-02 18:35:07 UTC
Hmm, note that one of the callers of iwm_rate2idx() already contains this logic (i.e., maps an unknown rate to the lowest one).

I guess the problem is with the code which programs the fw rate table.  iwm_setrates() already skips over invalid rates... but the code which fills in the rest of the table is wrong.

Can you try this hack instead?  I did not test it.

There is a larger issue here in that we are ending up with a rate of 0, but we can at least avoid panicking.

diff --git a/sys/dev/iwm/if_iwm.c b/sys/dev/iwm/if_iwm.c
index 06bd66cc3ef6..4bd6547cc57f 100644
--- a/sys/dev/iwm/if_iwm.c
+++ b/sys/dev/iwm/if_iwm.c
@@ -4385,8 +4385,10 @@ iwm_setrates(struct iwm_softc *sc, struct iwm_node *in, int rix)
 
                /* Map 802.11 rate to HW rate index. */
                ridx = iwm_rate2ridx(sc, rate);
-               if (ridx == -1)
+               if (ridx == -1) {
+                       nrates--;
                        continue;
+               }
 
 #if 0
                if (txant == 0)
Comment 5 dirkx 2020-01-18 20:54:28 UTC
Yes - works splendidly & with both types of ADSL modems.
Comment 6 dirkx 2020-01-18 20:56:15 UTC
I do get a few 

  iwm0: frame 2/189 b800002c UNHANDLED (this should not happen)

which I've not seen in that place before.