FRITZ!Box 6591 Firmware Bug: Kernel Panic Hashtable

[monofox]

Hallo,

ich habe eine FRITZ!Box 6591 Vodafone-Leihbox in der Firmwareversion 07.29.

Unregelmäßig (eher im Wochen-/Monatsabstand) stürzt die Fritzbox ab (Uhrzeit spielt auch keine Rolle) und startet neu. Das ist ärgerlich - gerade wenn es tagsüber oder bei nächtlichen Backups auftritt.

Das Ereignislog ist nach dem Neustart weg. Aber in der erweiterterten Supportdatei ist folgendes zu finden:

[71309.608763] BUG: internet: ipmasq: FATAL: UDP <ipv4-lan-addr>/37787 (<wan-ipv4-addr>/37787) still in hashtab after unhash
[71309.620344] ------------[ cut here ]------------
[71309.620416] WARNING: CPU: 0 PID: 0 at /GU/NETWORK_SOURCE_atomp7_build/kernelmodules/libs/datapipe/gen/sharedlibs/datapipe/datapipe.c:3708 0xc5056d78 dpmod_bugmsg+0x88/0xd0 [kdsldmod]
[71309.620418] Modules linked in: krtp(PO) xhci_pci xhci_hcd userman_mod(PO) qca_ol(O) umac(O) ath_spectral(PO) ath_dfs(PO) qdf(O) asf(PO) mem_manager(PO) aae(PO) dect_io(P) avm_dect(P) capi_codec(P) isdn_fbox_fon5(P) pcmlink(P) avm_dvbc_drv(O) cable_netdev(O) toe_drv(O) swapi_mod(O) DWC_ETH_QOS_GBE(O) sec_kernel(O) DWC_ETH_QOS veth mux_drv(O) pumalbr0flt_drv(PO) avm_pa_hw(O) puma_lpal(O) cppp(O) wifi_proxy_netdev(O) dpd_netdev(O) puma7_pp_init hil_drv(O) kdsldmod(PO) cchardev(PO) avm_pp_counter(PO) cprocfsmod(PO) sgc_drv(O) pp_drv(O) pdsp_drv(O) Piglet_noemif(P) led_module(PO)
[71309.620463] CPU: 0 PID: 0 Comm: swapper/0 Tainted: P           O    4.9.250 #1
[71309.620464] Hardware name: Intel Corporation PUMA 7 C0 PLATFORM/TBD, BIOS CGM2.86C.627075.R.1910091149 10/09/2019
[71309.620466]  b400bc50 813a6f95 00000000 c5056d78 b400bc68 810eb017 00000e7c b400bc98
[71309.620473]  c513f634 a6135320 b400bc7c 81051b06 00000009 00000000 00000000 b400be9c
[71309.620480]  c5056d78 c5116d04 b400bc98 c5116cf6 aba1e440 c511948f 3a475542 746e6920
[71309.620486] Call Trace:
[71309.620489]  <IRQ> 
[71309.620496]  dump_stack+0x51/0x6c
[71309.620555]  ? dpmod_bugmsg+0x88/0xd0 [kdsldmod]
[71309.620559]  __warn+0xb2/0xc9
[71309.620563]  warn_slowpath_null+0x26/0x30
[71309.620622]  dpmod_bugmsg+0x88/0xd0 [kdsldmod]
[71309.620627]  ? enqueue_task_fair+0x861/0xdb0
[71309.620630]  ? sched_clock_cpu+0x115/0x170
[71309.620634]  ? find_next_bit+0x1b/0x30
[71309.620636]  ? cpumask_next_and+0x24/0x30
[71309.620638]  ? update_sd_lb_stats+0x110/0x490
[71309.620641]  ? number+0x3bc/0x3c0
[71309.620643]  ? update_sd_lb_stats+0x420/0x490
[71309.620646]  ? vsnprintf+0x32c/0x5a0
[71309.620648]  ? snprintf+0x1d/0x20
[71309.620708]  ? ipaddr2str+0x54/0x60 [kdsldmod]
[71309.620769]  masq_release+0x3e2/0x450 [kdsldmod]
[71309.620772]  ? _raw_spin_unlock_bh+0x13/0x20
[71309.620829]  ? ctimer_unsetup_internal+0x15f/0x190 [kdsldmod]
[71309.620890]  masq_expire_timer+0x49/0x90 [kdsldmod]
[71309.620947]  ctimer_internal_docallouts+0x21e/0x340 [kdsldmod]
[71309.620990]  ? pcp_request_handler+0x140/0x140 [kdsldmod]
[71309.621034]  timer_function+0x1d/0xc0 [kdsldmod]
[71309.621078]  ? pcp_request_handler+0x140/0x140 [kdsldmod]
[71309.621082]  call_timer_fn.isra.29+0x29/0xc0
[71309.621084]  ? rebalance_domains+0xe4/0x2a0
[71309.621087]  run_timer_softirq+0x1b8/0x3b0
[71309.621130]  ? pcp_request_handler+0x140/0x140 [kdsldmod]
[71309.621133]  ? run_rebalance_domains+0x118/0x1a0
[71309.621135]  __do_softirq+0xf8/0x370
[71309.621137]  ? takeover_tasklets+0x110/0x110
[71309.621141]  do_softirq_own_stack+0x1d/0x30
[71309.621142]  <EOI> 
[71309.621144]  irq_exit+0xb5/0xc0
[71309.621147]  smp_apic_timer_interrupt+0x4b/0x90
[71309.621150]  apic_timer_interrupt+0x2d/0x34
[71309.621154]  ? ip_tunnel_rcv.cold.38+0x34/0x40
[71309.621157]  ? cpuidle_enter_state+0x14d/0x250
[71309.621159]  cpuidle_enter+0xf/0x20
[71309.621162]  call_cpuidle+0x1c/0x30
[71309.621164]  cpu_startup_entry+0x10f/0x1a0
[71309.621167]  rest_init+0x6c/0x6f
[71309.621170]  start_kernel+0x366/0x370
[71309.621172]  i386_start_kernel+0x43/0x45
[71309.621174] ---[ end trace 34a02f163d3cd56b ]---
[71309.621177] Kernel panic - not syncing: BUG: internet: ipmasq: FATAL: UDP <ipv4-lan-addr>/37787 (<wan-ipv4-addr>/37787) still in hashtab after unhash
[71309.621177] 
[71309.637114] CPU: 0 PID: 0 Comm: swapper/0 Tainted: P        W  O    4.9.250 #1
[71309.645182] Hardware name: Intel Corporation PUMA 7 C0 PLATFORM/TBD, BIOS CGM2.86C.627075.R.1910091149 10/09/2019
[71309.656650]  b400bc64 813a6f95 b400bc00 c513f634 b400bc7c 810eae17 c513f634 b400bc98
[71309.665340]  c513f634 a6135320 b400be9c c5056d88 c511686a b400bc98 c5116cf6 aba1e440
[71309.674047]  c511948f 3a475542 746e6920 656e7265 69203a74 73616d70 46203a71 4c415441
[71309.682737] Call Trace:
[71309.685464]  <IRQ> 
[71309.687600]  dump_stack+0x51/0x6c
[71309.691304]  panic+0x91/0x1b9
[71309.694677]  dpmod_bugmsg+0x98/0xd0 [kdsldmod]
[71309.699641]  ? enqueue_task_fair+0x861/0xdb0
[71309.704413]  ? sched_clock_cpu+0x115/0x170
[71309.708988]  ? find_next_bit+0x1b/0x30
[71309.713173]  ? cpumask_next_and+0x24/0x30
[71309.717650]  ? update_sd_lb_stats+0x110/0x490
[71309.722515]  ? number+0x3bc/0x3c0
[71309.726214]  ? update_sd_lb_stats+0x420/0x490
[71309.731078]  ? vsnprintf+0x32c/0x5a0
[71309.735071]  ? snprintf+0x1d/0x20
[71309.738836]  ? ipaddr2str+0x54/0x60 [kdsldmod]
[71309.743858]  masq_release+0x3e2/0x450 [kdsldmod]
[71309.749016]  ? _raw_spin_unlock_bh+0x13/0x20
[71309.753837]  ? ctimer_unsetup_internal+0x15f/0x190 [kdsldmod]
[71309.760316]  masq_expire_timer+0x49/0x90 [kdsldmod]
[71309.765817]  ctimer_internal_docallouts+0x21e/0x340 [kdsldmod]
[71309.772375]  ? pcp_request_handler+0x140/0x140 [kdsldmod]
[71309.778447]  timer_function+0x1d/0xc0 [kdsldmod]
[71309.783644]  ? pcp_request_handler+0x140/0x140 [kdsldmod]
[71309.789675]  call_timer_fn.isra.29+0x29/0xc0
[71309.794444]  ? rebalance_domains+0xe4/0x2a0
[71309.799114]  run_timer_softirq+0x1b8/0x3b0
[71309.803729]  ? pcp_request_handler+0x140/0x140 [kdsldmod]
[71309.809759]  ? run_rebalance_domains+0x118/0x1a0
[71309.814916]  __do_softirq+0xf8/0x370
[71309.818908]  ? takeover_tasklets+0x110/0x110
[71309.823677]  do_softirq_own_stack+0x1d/0x30
[71309.828348]  <EOI> 
[71309.830493]  irq_exit+0xb5/0xc0
[71309.834002]  smp_apic_timer_interrupt+0x4b/0x90
[71309.839063]  apic_timer_interrupt+0x2d/0x34
[71309.843733]  ? ip_tunnel_rcv.cold.38+0x34/0x40
[71309.848695]  ? cpuidle_enter_state+0x14d/0x250
[71309.853656]  cpuidle_enter+0xf/0x20
[71309.857552]  call_cpuidle+0x1c/0x30
[71309.861445]  cpu_startup_entry+0x10f/0x1a0
[71309.866019]  rest_init+0x6c/0x6f
[71309.869622]  start_kernel+0x366/0x370
[71309.873711]  i386_start_kernel+0x43/0x45
[71309.878091] Remote Queue: Len: 64  Min Free: 59    Local Queue:  Len: 64  Min Free: 37  Dropped: 0
[71309.891089] set_reboot_status: Soft-Reboot(PANIC)  - SHORTPOWERCUT(2) PANIC(1) DOCSIS_OPERATOR(2)SUM(5)UP(71307)UTC(1648017164)FW()HW(233)HWS(8)BV(1.3614)
[71309.906641] Kernel Offset: disabled

Ist der Bug bekannt? Wird daran gearbeitet? An AVM selbst wird das melden ja wahrscheinlich schwierig, weil es sich um eine Vodafone-Leihbox handelt.

Gruß,
Lukas

[Claudia]

Hallo Lukas,

ich habe mal beim Fachbereich angefragt, ob das Thema bekannt ist bzw. was man da machen kann.

Viele Grüße,

Claudia

[monofox]

Hallo,

heute gab es wieder ein Disconnect, ein Neustart war aber nicht erforderlich.

     - 2022-04-08 02:27:49 85 times
   25: 2022-04-08 02:27:53 67070100 error     DBC-ACK not received
   26: 2022-04-08 02:28:49 82000400 critical  Received Response to Broadcast Maintenance Request, But no Unicast Maintenance opportunities received - T4 time out
     - 2022-04-08 02:28:49 4 times
   27: 2022-04-08 02:29:06 82000200 critical  No Ranging Response received - T3 time-out
     - 2022-04-08 02:29:26 6 times
   28: 2022-04-08 02:29:28 90000000 warning   MIMO Event MIMO: Stored MIMO=-1 post cfg file MIMO=-1
   29: 2022-04-08 02:29:30 73050400 warning   REG-RSP-MP Mismatch Between Calculated Value for P1.6hi Compared to CCAP Provided Value
   30: 2022-04-08 02:29:30 82001200 warning   RNG-RSP CCAP Commanded Power in Excess of 6 dB Below the Value Corresponding to the Top of the DRW
     - 2022-04-08 02:29:30 3 times
   31: 2022-04-08 02:29:31 82000200 critical  No Ranging Response received - T3 time-out
     - 2022-04-08 02:29:57 13 times
   32: 2022-04-08 02:29:57 82001200 warning   RNG-RSP CCAP Commanded Power in Excess of 6 dB Below the Value Corresponding to the Top of the DRW
   33: 2022-04-08 02:29:57 82000200 critical  No Ranging Response received - T3 time-out
   34: 2022-04-08 02:29:58 82001200 warning   RNG-RSP CCAP Commanded Power in Excess of 6 dB Below the Value Corresponding to the Top of the DRW
   35: 2022-04-08 02:30:29 85010300 warning   Initializing Channel Timeout Expires - Time the CM can perform initial ranging on all upstream channels in the TCS has expired
   36: 2022-04-08 02:30:29 85010200 warning   TCS Partial Service
   37: 2022-04-08 02:30:59 67050300 warning   DBC-REQ Mismatch Between Calculated Value for P1.6hi Compared to CCAP Provided Value
     - 2022-04-08 02:41:00 2 times
   38: 2022-04-08 02:41:00 82001200 warning   RNG-RSP CCAP Commanded Power in Excess of 6 dB Below the Value Corresponding to the Top of the DRW
   39: 2022-04-08 08:13:32 82000200 critical  No Ranging Response received - T3 time-out

2022-04-08 02:28:55.210 - syncstate: DS/US: 1150000/56710 -> 0/0
2022-04-08 02:28:58.210 - syncstate: InitState: OPERATIONAL -> NOT SYNCHRONIZED
2022-04-08 02:28:58.210 - syncstate: SyncState: showtime -> no-sync
2022-04-08 02:29:01.210 - syncstate: InitState: NOT SYNCHRONIZED -> RANGING IN PROGRESS (DS TOPOLOGY RESOLUTION)
2022-04-08 02:29:01.210 - syncstate: SyncState: no-sync -> training
2022-04-08 02:29:05.210 - syncstate: InitState: RANGING IN PROGRESS (DS TOPOLOGY RESOLUTION) -> RANGING IN PROGRESS
2022-04-08 02:29:38.210 - syncstate: InitState: RANGING IN PROGRESS -> RANGING COMPLETE
2022-04-08 02:29:41.210 - syncstate: InitState: RANGING COMPLETE -> REGISTRATION: DHCPV6 IN PROGRESS
2022-04-08 02:29:28.610 - command ok: docsis edocsis erouter_both edva_off emta_on emta_use_oem edocsis_normal
2022-04-08 02:29:28.790 - syncstate: InitState: REGISTRATION: DHCPV6 IN PROGRESS -> REGISTRATION: CONFIG FILE DOWNLOAD COMPLETE
2022-04-08 02:29:29.200 - command ok: docsis cmcfgfile
2022-04-08 02:29:29.790 - syncstate: InitState: REGISTRATION: CONFIG FILE DOWNLOAD COMPLETE -> REGISTRATION: IN PROGRESS
2022-04-08 02:30:30.790 - syncstate: InitState: REGISTRATION: IN PROGRESS -> NOT OPERATIONAL: REGISTRATION COMPLETE
2022-04-08 02:30:33.790 - syncstate: InitState: NOT OPERATIONAL: REGISTRATION COMPLETE -> OPERATIONAL
2022-04-08 02:30:33.790 - syncstate: SyncState: training -> showtime
2022-04-08 02:30:33.790 - syncstate: DS/US: 0/0 -> 1150000/56710

2022-04-08 02:28:42.521 - MAP  complete FORW     IP [2a02:8106:***********]/57 iface 0 "fw01" -  error (network failure)
2022-04-08 02:28:42.527 - MAP  complete ARGO     TCP [2a02:8106:***********]:50910 iface 0 use_ifaceaddr "argo.TCP.50910" -  error (network failure)
2022-04-08 02:28:42.548 - MAP  complete FORW     IP [2a02:8106:***********] iface 0 "Exposed fw01" -  error (network failure)
2022-04-08 02:28:42.548 - MAP  complete FORW     ICMPv6 [2a02:8106:***********]:128 iface 0 "Ping fw01" -  error (network failure)
2022-04-08 02:28:46.635 - MAP  complete TR069    TCP [10.xxx.xx.1]:8089 iface 1 "tr069.TCP.8089" -  error (network failure)
2022-04-08 02:29:14.312 - MAP  complete IGDPROBE TCP [10.xxx.xx.1]:9 iface 0 use_ifaceaddr "IGDPROBE4" -  error (network failure)
2022-04-08 02:29:24.979 - MAP  complete FORW     IP [10.xxx.xx.2] iface 0 "IP 0" -  error (network failure)
2022-04-08 02:29:25.701 - MAP  complete ARGO     TCP [10.xxx.xx.1]:50910 iface 0 "argo.TCP.50910" -  error (network failure)
2022-04-08 02:30:34.583 - MAP  complete ARGO     TCP [10.xxx.xx.1]:50910 iface 0 "argo.TCP.50910": external [24.xxx.x.xxx]:50910
2022-04-08 02:30:34.583 - MAP  complete IGDPROBE TCP [10.xxx.xx.1]:9 iface 0 use_ifaceaddr "IGDPROBE4": external [24.xxx.x.xxx]:9
2022-04-08 02:30:34.590 - MAP  complete FORW     IP [10.xxx.xx.2] iface 0 "IP 0": external [24.xxx.x.xxx]
2022-04-08 02:30:34.590 - MAP  complete TR069    TCP [10.xxx.xx.1]:8089 iface 1 "tr069.TCP.8089": external [10.xxx.xxx.37]:8089
2022-04-08 02:30:39.574 - MAP  complete FORW     IP [2a02:8106:***:***::]/57 iface 0 "fw01": external [2a02:8106:***:***::]/57
2022-04-08 02:30:39.576 - MAP  complete ARGO     TCP [2a02:8106:***:***:1eed:6fff:fecb:4c5]:50910 iface 0 use_ifaceaddr "argo.TCP.50910": external [2a02:810b::81:5009:8ce1:3b82:a9c7]:50910
2022-04-08 02:30:39.580 - MAP  complete FORW     IP [2a02:8106:***********] iface 0 "Exposed fw01": external [2a02:8106:***********]
2022-04-08 02:30:39.582 - MAP  complete FORW     ICMPv6 [2a02:8106:***********]:128 iface 0 "Ping fw01": external [2a02:8106:***********]:128

Dementsprechend war es nach 2 Minuten wieder online. Es gibt kein Crashlog oder dergleichen.

[Claudia]

Hallo Lukas,

die Kollegen wollen sich das genauer anschauen. Ziehe bitte ein Supportfile von der Fritzbox und lade es zum Beispiel in einer Cloud hoch. Schicke mir den Link dann bitte per PN und melde Dich hier nochmal. Auch wenn das ein Leihgerät ist, kannst Du hier auch mal bei AVM nachfragen.

Viele Grüße,

Claudia

[monofox]

Hallo Claudia,

danke für Deine Rückmeldung. Die PN ist raus.

Viele Grüße,

Lukas

[Moni_GK]

Hallo monofox,

wir haben es an die Fachabteilung gegeben. Diese müssen es nun prüfen. Allerdings kann das leider etwas dauern.

Grüße Moni

[monofox]

Hallo Moni,

danke für die Info.

Seit dem letzten Verbindungsabbruch gab es bisweilen auch keine weiteren Hardwareabstürze. Hoffen wir das Beste.

Dafür ändert sich die Leistung stellenweise aktuell erheblich:

Die Upstream-Modulation ist im "Keller":

Das hat sich seit dem 08.04. verstetigt:

Am letzten WE war Ruhe.

Zum Vergleich die Gesamtkurve seit 28.03. (blaue Linie ist der Zeitpunkt des FritzBox Tauschs):

Die Paketverluste sind entsprechend (~ 14 - 20 %).

Ich nehme an, das hat aber nichts mit der FritzBox zu tun, oder? In den Zeiten der Kurve, wo alle auf 64QAM stehen, habe ich keinerlei Einschränkungen.

In den Logs taucht nur auf:

   39: 2022-04-08 08:13:32 82000200 critical  No Ranging Response received - T3 time-out
     - 2022-04-11 00:13:47 190 times
   40: 2022-04-11 09:38:51 74010100 notice    CM-STATUS message sent.  Event Type Code: 24
     - 2022-04-11 09:43:08 4 times
   41: 2022-04-11 15:58:19 82000200 critical  No Ranging Response received - T3 time-out
     - 2022-04-11 21:17:31 15 times

Gruß,
Lukas (monofox)

[RobertP]

da liegt ein sog. Rückwegstörer vor

[monofox]

Hallo Vodafone-Team!

ich denke, ihr könnt das Ticket jetzt schließen. Die Fritz-Box lief jetzt 8 Wochen durch und es treten nur noch Rückwärtsstörer auf.

Danke für eure Unterstützung.

Gruß,
Lukas

[Manu]

Hallo monofox,

viele Dank für Deine Rückmeldung. Freut mich, dass alles soweit gut läuft. Ich schließe damit hier ab.

Viele Grüße, Manu