I've added more info, probably mainly for myself. I'm not sure where to
go with this information yet.
On Sat, Sep 25, 2021 at 01:31:33AM +0000, Mikolaj Kucharski wrote:
> On Wed, Sep 22, 2021 at 03:00:37PM +0000, Mikolaj Kucharski wrote:
> > Another one, it happened with below diff applied. Didn't had time yet to
> > dive into this.
>
> I have limited time in recent months, so I'm trying to put anything what
> I have in spare moment. This should be more clear, from my previous
> email.
>
> Entries in dmesg, just before and from the panic()
>
> ddb{0}> dmesg
> OpenBSD 7.0 (GENERIC.MP) #4: Mon Sep 20 08:41:30 UTC 2021
>
> [email protected]:/home/mkucharski/openbsd/src/sys/arch/amd64/compile/GENERIC.MP
> ...
> root on sd0a (f4c61a8acb9563fd.a) swap on sd0b dump on sd0b
> MMM: ar5008_tx() [ar5008.c|1521]
> MMM: ar5008_tx() [ar5008.c|1524]: key unset for sw crypto: 0
> MMM: ieee80211_encrypt() [ieee80211_crypto.c|278]: k_id: 0
> MMM: ieee80211_encrypt() [ieee80211_crypto.c|279]: k_flags: 0
> MMM: ieee80211_encrypt() [ieee80211_crypto.c|280]: k_len: 0
> MMM: ieee80211_encrypt() [ieee80211_crypto.c|281]: k_cipher: 0
> MMM: ieee80211_encrypt() [ieee80211_crypto.c|282]: k_key:
> 0x0000000000000000000000000000000000000000000000000000000000000000
> panic: ieee80211_encrypt: key unset for sw crypto: id=0 cipher=0 flags=0x0
> Stopped at db_enter+0x10: popq %rbp
> TID PID UID PRFLAGS PFLAGS CPU COMMAND
> db_enter() at db_enter+0x10
> panic(ffffffff81ea79d7) at panic+0xbf
> ieee80211_encrypt(ffff80000009c048,fffffd80c307ce00,ffff800000d3e1c0) at
> ieee80211_encrypt+0x473
> ar5008_tx(ffff80000009c000,fffffd80c307ce00,ffff800000d3e000,0) at
> ar5008_tx+0x1e7
> athn_start(ffff80000009c048) at athn_start+0x108
> ar5008_intr(ffff80000009c000) at ar5008_intr+0x216
> intr_handler(ffff8000225a6d80,ffff80000008f780) at intr_handler+0x6e
> Xintr_ioapic_level3_untramp() at Xintr_ioapic_level3_untramp+0x193
> acpicpu_idle() at acpicpu_idle+0x11f
> sched_idle(ffffffff821a7ff0) at sched_idle+0x27e
> end trace frame: 0x0, count: 5
>
>
> Below are dmesg entries and code responsible for those entries.
>
> MMM: ar5008_tx() [ar5008.c|1521]
> MMM: ar5008_tx() [ar5008.c|1524]: key unset for sw crypto: 0
>
> 1514 if (wh->i_fc[1] & IEEE80211_FC1_PROTECTED) {
> 1515 k = ieee80211_get_txkey(ic, wh, ni);
> 1516 if (k->k_cipher == IEEE80211_CIPHER_CCMP) {
> 1517 u_int hdrlen = ieee80211_get_hdrlen(wh);
> 1518 if (ar5008_ccmp_encap(m, hdrlen, k) !=
> 0)
> 1519 return (ENOBUFS);
> 1520 } else {
> 1521 printf("MMM: %s() [%s|%d]\n", __func__,
> __FILE_NAME__, __LINE__);
> 1522 if ((k->k_flags &
> IEEE80211_KEY_SWCRYPTO) == 0)
> 1523 printf("MMM: %s() [%s|%d]: key
> unset for sw crypto: %d\n",
> 1524 __func__,
> __FILE_NAME__, __LINE__, k->k_id);
> 1525 if ((m = ieee80211_encrypt(ic, m, k))
> == NULL)
> 1526 return (ENOBUFS);
> 1527 k = NULL; /* skip hardware crypto
> further below */
> 1528 }
> 1529 wh = mtod(m, struct ieee80211_frame *);
> 1530 }
>
> MMM: ieee80211_encrypt() [ieee80211_crypto.c|278]: k_id: 0
> MMM: ieee80211_encrypt() [ieee80211_crypto.c|279]: k_flags: 0
> MMM: ieee80211_encrypt() [ieee80211_crypto.c|280]: k_len: 0
> MMM: ieee80211_encrypt() [ieee80211_crypto.c|281]: k_cipher: 0
> MMM: ieee80211_encrypt() [ieee80211_crypto.c|282]: k_key:
> 0x0000000000000000000000000000000000000000000000000000000000000000
>
> 273 struct mbuf *
> 274 ieee80211_encrypt(struct ieee80211com *ic, struct mbuf *m0,
> 275 struct ieee80211_key *k)
> 276 {
> 277 if ((k->k_flags & IEEE80211_KEY_SWCRYPTO) == 0) {
> 278 printf("MMM: %s() [%s|%d]: k_id: %d\n",
> __func__, __FILE_NAME__, __LINE__, k->k_id);
> 279 printf("MMM: %s() [%s|%d]: k_flags: %d\n",
> __func__, __FILE_NAME__, __LINE__, k->k_flags);
> 280 printf("MMM: %s() [%s|%d]: k_len: %d\n",
> __func__, __FILE_NAME__, __LINE__, k->k_len);
> 281 printf("MMM: %s() [%s|%d]: k_cipher: %d\n",
> __func__, __FILE_NAME__, __LINE__, k->k_cipher);
> 282 printf("MMM: %s() [%s|%d]: k_key: 0x",
> __func__, __FILE_NAME__, __LINE__);
> 283 for (int i = 0; i < sizeof(k->k_key); i++)
> 284 printf("%02x", k->k_key[i]);
> 285 printf("\n");
> 286 }
> 287
> 288 if ((k->k_flags & IEEE80211_KEY_SWCRYPTO) == 0)
> 289 panic("%s: key unset for sw crypto: id=%d
> cipher=%d flags=0x%x",
> 290 __func__, k->k_id, k->k_cipher, k->k_flags);
> 291
>
> panic: ieee80211_encrypt: key unset for sw crypto: id=0 cipher=0 flags=0x0
> Stopped at db_enter+0x10: popq %rbp
> TID PID UID PRFLAGS PFLAGS CPU COMMAND
> db_enter() at db_enter+0x10
> panic(ffffffff81ea79d7) at panic+0xbf
> ieee80211_encrypt(ffff80000009c048,fffffd80c307ce00,ffff800000d3e1c0) at
> ieee80211_encrypt+0x473
> ar5008_tx(ffff80000009c000,fffffd80c307ce00,ffff800000d3e000,0) at
> ar5008_tx+0x1e7
> athn_start(ffff80000009c048) at athn_start+0x108
> ar5008_intr(ffff80000009c000) at ar5008_intr+0x216
> intr_handler(ffff8000225a6d80,ffff80000008f780) at intr_handler+0x6e
> Xintr_ioapic_level3_untramp() at Xintr_ioapic_level3_untramp+0x193
> acpicpu_idle() at acpicpu_idle+0x11f
> sched_idle(ffffffff821a7ff0) at sched_idle+0x27e
>
from `objdump -dlr obj/athn.o` I see that:
0000000000001710 <athn_start>:
athn_start():
.../src/sys/dev/ic/athn.c:2811
...
and athn_start+0x108 is at 0x1818:
.../src/sys/dev/ic/athn.c:2857
1800: 4d 8b 9f a8 2e 00 00 mov 0x2ea8(%r15),%r11
1807: 48 8b 55 b8 mov 0xffffffffffffffb8(%rbp),%rdx
180b: 4c 89 ff mov %r15,%rdi
180e: 4c 89 ee mov %r13,%rsi
1811: 31 c9 xor %ecx,%ecx
1813: e8 00 00 00 00 callq 1818 <athn_start+0x108>
1814: R_X86_64_PLT32
__llvm_retpoline_r11+0xfffffffffffffffc
1818: 85 c0 test %eax,%eax
181a: 0f 84 70 ff ff ff je 1790 <athn_start+0x80>
and I think it means this:
2857 if (sc->ops.tx(sc, m, ni, 0) != 0) {
full function below, with line numbers:
2809 void
2810 athn_start(struct ifnet *ifp)
2811 {
2812 struct athn_softc *sc = ifp->if_softc;
2813 struct ieee80211com *ic = &sc->sc_ic;
2814 struct ieee80211_node *ni;
2815 struct mbuf *m;
2816
2817 if (!(ifp->if_flags & IFF_RUNNING) ||
ifq_is_oactive(&ifp->if_snd))
2818 return;
2819
2820 for (;;) {
2821 if (SIMPLEQ_EMPTY(&sc->txbufs)) {
2822 ifq_set_oactive(&ifp->if_snd);
2823 break;
2824 }
2825 /* Send pending management frames first. */
2826 m = mq_dequeue(&ic->ic_mgtq);
2827 if (m != NULL) {
2828 ni = m->m_pkthdr.ph_cookie;
2829 goto sendit;
2830 }
2831 if (ic->ic_state != IEEE80211_S_RUN)
2832 break;
2833
2834 m = mq_dequeue(&ic->ic_pwrsaveq);
2835 if (m != NULL) {
2836 ni = m->m_pkthdr.ph_cookie;
2837 goto sendit;
2838 }
2839 if (ic->ic_state != IEEE80211_S_RUN)
2840 break;
2841
2842 /* Encapsulate and send data frames. */
2843 m = ifq_dequeue(&ifp->if_snd);
2844 if (m == NULL)
2845 break;
2846 #if NBPFILTER > 0
2847 if (ifp->if_bpf != NULL)
2848 bpf_mtap(ifp->if_bpf, m, BPF_DIRECTION_OUT);
2849 #endif
2850 if ((m = ieee80211_encap(ifp, m, &ni)) == NULL)
2851 continue;
2852 sendit:
2853 #if NBPFILTER > 0
2854 if (ic->ic_rawbpf != NULL)
2855 bpf_mtap(ic->ic_rawbpf, m, BPF_DIRECTION_OUT);
2856 #endif
2857 if (sc->ops.tx(sc, m, ni, 0) != 0) {
2858 ieee80211_release_node(ic, ni);
2859 ifp->if_oerrors++;
2860 continue;
2861 }
2862
2863 sc->sc_tx_timer = 5;
2864 ifp->if_timer = 1;
2865 }
2866 }
from `objdump -dlr obj/ar5008.o` I see that:
0000000000000c30 <ar5008_intr>:
ar5008_intr():
.../src/sys/dev/ic/ar5008.c:1362
...
and ar5008_intr+0x216 is at 0xe46:
ar5008_intr():
.../src/sys/dev/ic/ar5008.c:1407
e46: 4d 8b 9e f0 2d 00 00 mov 0x2df0(%r14),%r11
e4d: 4c 89 f7 mov %r14,%rdi
e50: be d8 00 00 00 mov $0xd8,%esi
e55: e8 00 00 00 00 callq e5a <ar5008_intr+0x22a>
e56: R_X86_64_PLT32
__llvm_retpoline_r11+0xfffffffffffffffc
e5a: 41 bc 01 00 00 00 mov $0x1,%r12d
and I think it means this:
1407 intr5 = AR_READ(sc, AR_ISR_S5_S);
full function below, with line numbers:
1360 int
1361 ar5008_intr(struct athn_softc *sc)
1362 {
1363 uint32_t intr, intr2, intr5, sync;
1364
1365 /* Get pending interrupts. */
1366 intr = AR_READ(sc, AR_INTR_ASYNC_CAUSE);
1367 if (!(intr & AR_INTR_MAC_IRQ) || intr == AR_INTR_SPURIOUS) {
1368 intr = AR_READ(sc, AR_INTR_SYNC_CAUSE);
1369 if (intr == AR_INTR_SPURIOUS || (intr & sc->isync) == 0)
1370 return (0); /* Not for us. */
1371 }
1372
1373 if ((AR_READ(sc, AR_INTR_ASYNC_CAUSE) & AR_INTR_MAC_IRQ) &&
1374 (AR_READ(sc, AR_RTC_STATUS) & AR_RTC_STATUS_M) ==
AR_RTC_STATUS_ON)
1375 intr = AR_READ(sc, AR_ISR);
1376 else
1377 intr = 0;
1378 sync = AR_READ(sc, AR_INTR_SYNC_CAUSE) & sc->isync;
1379 if (intr == 0 && sync == 0)
1380 return (0); /* Not for us. */
1381
1382 if (intr != 0) {
1383 if (intr & AR_ISR_BCNMISC) {
1384 intr2 = AR_READ(sc, AR_ISR_S2);
1385 if (intr2 & AR_ISR_S2_TIM)
1386 /* TBD */;
1387 if (intr2 & AR_ISR_S2_TSFOOR)
1388 /* TBD */;
1389 }
1390 intr = AR_READ(sc, AR_ISR_RAC);
1391 if (intr == AR_INTR_SPURIOUS)
1392 return (1);
1393
1394 #ifndef IEEE80211_STA_ONLY
1395 if (intr & AR_ISR_SWBA)
1396 ar5008_swba_intr(sc);
1397 #endif
1398 if (intr & (AR_ISR_RXMINTR | AR_ISR_RXINTM))
1399 ar5008_rx_intr(sc);
1400 if (intr & (AR_ISR_RXOK | AR_ISR_RXERR | AR_ISR_RXORN))
1401 ar5008_rx_intr(sc);
1402
1403 if (intr & (AR_ISR_TXOK | AR_ISR_TXDESC |
1404 AR_ISR_TXERR | AR_ISR_TXEOL))
1405 ar5008_tx_intr(sc);
1406
1407 intr5 = AR_READ(sc, AR_ISR_S5_S);
1408 if (intr & AR_ISR_GENTMR) {
1409 if (intr5 & AR_ISR_GENTMR) {
1410 DPRINTF(("GENTMR trigger=%d
thresh=%d\n",
1411 MS(intr5, AR_ISR_S5_GENTIMER_TRIG),
1412 MS(intr5,
AR_ISR_S5_GENTIMER_THRESH)));
1413 }
1414 }
1415
1416 if (intr5 & AR_ISR_S5_TIM_TIMER)
1417 /* TBD */;
1418 }
1419 if (sync != 0) {
1420 if (sync & (AR_INTR_SYNC_HOST1_FATAL |
1421 AR_INTR_SYNC_HOST1_PERR))
1422 /* TBD */;
1423
1424 if (sync & AR_INTR_SYNC_RADM_CPL_TIMEOUT) {
1425 AR_WRITE(sc, AR_RC, AR_RC_HOSTIF);
1426 AR_WRITE(sc, AR_RC, 0);
1427 }
1428
1429 if ((sc->flags & ATHN_FLAG_RFSILENT) &&
1430 (sync & AR_INTR_SYNC_GPIO_PIN(sc->rfsilent_pin))) {
1431 struct ifnet *ifp = &sc->sc_ic.ic_if;
1432
1433 printf("%s: radio switch turned off\n",
1434 sc->sc_dev.dv_xname);
1435 /* Turn the interface down. */
1436 athn_stop(ifp, 1);
1437 return (1);
1438 }
1439
1440 AR_WRITE(sc, AR_INTR_SYNC_CAUSE, sync);
1441 (void)AR_READ(sc, AR_INTR_SYNC_CAUSE);
1442 }
1443 return (1);
1444 }
--
Regards,
Mikolaj
