was da zum Zeitpunkt der 168 Sekunde geladen werden will
Das verstehe ich nicht ... oder ich rechne falsch.
Die Meldung tritt nach 212 Sekunden Laufzeit der Box auf (die Uhrzeit startet um 01:00:00 Uhr und zum Zeitpunkt, wo der Watchdog zuschlägt, ist es 01:03:32 Uhr lt. Protokoll) - ich verstehe das mal so, daß die Meldung:
Watchdog triggered 168 seconds ago
vermutlich den Zeitpunkt angeben soll, wann der zuletzt "zurückgesetzt" bzw. "eingerichtet" wurde (wenn die Aktion erst 168 Sekunden nach Ablauf und "Kippen" des Triggers zum Tragen käme, wäre so ein Watchdog je recht ineffektiv) und das wäre dann der Zeitpunkt 212 Sekunden - 168 Sekunden = 44 Sekunden nach dem Start des Timers im Kernel, wo dieser "wdt" gestartet wurde. Das mag ein paar Sekunden länger sein ab "power-on" (weil auch der Kernel erst mal entpackt werden muß und die "grace period" von EVA, wo auf FTP-Clients gewartet wird, auch noch dazu kommt), aber bis zur 168. Sekunden reicht das dann vermutlich doch nicht.
Wobei der Watchdog ohnehin im "ctlmgr" liegen sollte (wenn ich den "short dump" wieder richtig interpretiere - dort setzt der geforkte Thread für den abgelaufenen Timer dann halt im "ctlmgr"-Kontext fort) und der wird über die "E46-net" schon in etwa zu diesem Zeitpunkt gestartet. Nur scheint eben ein Thread innerhalb dieses Prozesses dann zu hängen und daher den Timer nicht zurückzusetzen - bei AVM läuft in dieser "group 4" in etwa so etwas ab (kein Freetz-Image, nur eigene Modifikationen - auf einer 7490, wobei ich langsam ohnehin nicht mehr durchblicke, weil es ja im Thread eigentlich um die 7590 gehen sollte und da ist das Timing ein wenig anders ... wenn auch nicht kriegsentscheidend):
Code:
source files in group 4 ...
[ 25.210000][0]udevd[1408]: starting version 175
/etc/init.d/S42-ptest /etc/init.d/S45-configd
/etc/init.d/S44-hostname /etc/init.d/S46-usb
source /etc/init.d/S42-ptest
source /etc/init.d/S44-hostname
source /etc/init.d/S45-configd
source /etc/init.d/S46-usb
[ 25.550000][1][module-alloc-by-name] give 0x1000 bytes at 0x81246000 to module 'usb_common' (0x6c9000 total bytes left)
[ 25.640000][1][ifx_hsnand_command] read block is critical (column: 0x0 page: 0x45d0)
[ 25.760000][1][module-alloc-by-name] give 0x39000 bytes at 0x81247000 to module 'usbcore' (0x690000 total bytes left)
[ 25.780000][1]usbcore: registered new interface driver usbfs
[ 25.780000][1]usbcore: registered new interface driver hub
[ 25.790000][1]usbcore: registered new device driver usb
mount: mounting usbfs on /proc/bus/usb failed: No such file or directory
starting XHCI driver
[ 26.070000][1][module-alloc-by-name] give 0x1c000 bytes at 0x81280000 to module 'xhci_hcd' (0x674000 total bytes left)
[ 26.070000][1]xhci_hcd 0000:01:00.0: xHCI Host Controller
[ 26.070000][1]xhci_hcd 0000:01:00.0: new USB bus registered, assigned bus number 1
[ 26.150000][1]usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
[ 26.150000][1]usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[ 26.150000][1]usb usb1: Product: xHCI Host Controller
[ 26.150000][1]usb usb1: Manufacturer: Linux 3.10.107 xhci_hcd
[ 26.150000][1]usb usb1: SerialNumber: 0000:01:00.0
[ 26.150000][1]hub 1-0:1.0: USB hub found
[ 26.150000][1]hub 1-0:1.0: 2 ports detected
[ 26.150000][1]avm_net_trace: New net trace device 'usb1' registered with minor 161.
[ 26.150000][1]xhci_hcd 0000:01:00.0: xHCI Host Controller
[ 26.150000][1]xhci_hcd 0000:01:00.0: new USB bus registered, assigned bus number 2
[ 26.150000][1]xHCI: delay VBUS POWER on for 100 ms
[ 26.150000][1]usb usb2: New USB device found, idVendor=1d6b, idProduct=0003
[ 26.150000][1]usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[ 26.150000][1]usb usb2: Product: xHCI Host Controller
[ 26.150000][1]usb usb2: Manufacturer: Linux 3.10.107 xhci_hcd
[ 26.150000][1]usb usb2: SerialNumber: 0000:01:00.0
[ 26.170000][1]hub 2-0:1.0: USB hub found
[ 26.170000][1]hub 2-0:1.0: 2 ports detected
[ 26.170000][1]AVM: disable USB3 bus#2 port#1 config=1
[ 26.170000][1]avm_net_trace: New net trace device 'usb2' registered with minor 162.
XHCI USB 3.0 Host with port_config:1 started
[ 26.250000][1]xHCI: delayed VBUS POWER on
[ 26.420000][0][0]system-load 6 loadavg 0.99 0.24 0.8 - 62 tasks:27 % curr:udevadm(0 %)max:migration/0(21 %, pid:7) pgstat: sum=60199 free=52803 slab=1702 alloc=557/s fault=1270/s (sleep 2)
[ 27.200000][1][1]system-load 4 loadavg 0.99 0.24 0.8 - 83 tasks:3 % curr:blkid(0 %)max:udevadm(0 %, pid:1462) pgstat: sum=59983 free=51429 slab=2029 alloc=202/s fault=345/s (sleep 4)
execute files in group 4 ...
/etc/init.d/E40-avmipc /etc/init.d/E46-net
/etc/init.d/E40-dsl /etc/init.d/E47-cpunet
/etc/init.d/E41-capi /etc/init.d/E47-voip
/etc/init.d/E45-avmnexusd /etc/init.d/E48-mesh
/etc/init.d/E45-psetd
execute /etc/init.d/E40-avmipc
execute /etc/init.d/E40-dsl
[dsl sus] setting up avm_fiber_if!
[ 29.730000][0][module-alloc-by-name] give 0x1000 bytes at 0x8129c000 to module 'avm_fiber_if' (0x673000 total bytes left)
[dsl sus] dsl line test calib factory file available
[dsl get xtse] ANNEX=B DSLMODE=0
[dsl get xtse] setting ADSL Annex B/J and VDSL2 oISDN
[dsl get xtse] 10 00 10 40 00 04 01 07
[dsl sus] AVM MEI diag enabled
[dsl sus] starting vr9 dsp...
[dsl sus] ANNEX=B DSLMODE=0
[ 30.190000][1][module-alloc-by-name] give 0x2e000 bytes at 0x8129d000 to module 'mei_vr9' (0x645000 total bytes left)
[ 30.200000] [dsl_mei] Lantiq (VRX) DSL CPE MEI driver, version 1.4.4, (c) 2013 Lantiq Deutschland GmbH
[ 30.210000][1][dsl mei] tried to set GDBG Level to 4
[dsl mei] debug_level=4, Global UsrDbgLevel=4 MEI_DRV UsrDbgLevel=4 MEI_MEI_ACCESS UsrDbgLevel=4
[ 30.210000][1][dsl mei] debug_level=4, Global IntDbgLevel=4 MEI_DRV IntDbgLevel=4 MEI_MEI_ACCESS IntDbgLevel=4
[ 30.210000][1][dsl_vr9] AVM_MEI_PowerUpDSLSubsystem enable power domain 'DSL + DFE'
[ 30.210000][1][AVM_MEI_PowerUpDSLSubsystem] power up 'PPE TC, PPE EMA, LEDC, DFEV1, DFEV0'
[ 30.220000][1]usb 1-2: new high-speed USB device number 2 using xhci_hcd
[ 30.230000][1][dsl_vr9] AVM_MEI_PowerUpDSLSubsystem unreset 'DSL, DFE, AFE, VOICE, DSLTC, ARC'
[dsl sus] loaded vr9 mei driver: mei_vr9.ko with params: , avmDslDiagEnabled=1
[ 30.240000][1]usb 1-2: New USB device found, idVendor=067b, idProduct=2506
[ 30.240000][1]usb 1-2: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 30.240000][1]usb 1-2: Product: Mass Storage Device
[ 30.240000][1]usb 1-2: Manufacturer: Prolific Technology Inc.
[ 30.240000][1]usb 1-2: SerialNumber: 0
[ 30.240000][1]Port#2 connect: AVM Powermeter changed to 100 mA
[ 30.250000][1]Port#2 config: AVM Powermeter changed to 100 mA
[ 30.490000][1][module-alloc-by-name] give 0x4d000 bytes at 0x812cb000 to module 'dsl_vr9' (0x5f8000 total bytes left)
[dsl sus] loaded vr9 dsl driver: .ko with params:
[dsl sus] created vr9 dsl device node /dev/dsl_vr9/0 (major: 238 , minor: 0)
[dsl sus] created vr9 mei device node /dev/mei_vr9 (major: 239 , minor: 0)
[dsl sus] invoke /sbin/notify_avmnet --broadband_type DSL hw_start_tm_ptm
[ 30.840000][0][module-alloc-by-name] give 0x26000 bytes at 0x81318000 to module 'ifxmips_ppa_datapath_vr9_e5' (0x5d2000 total bytes left)
[ 30.860000][0]drivers/net/ethernet/avm/avm_cpmac/switch/ifx/vr9/ifxmips_ppa_datapath_vr9_e5.c:3076:init_local_variables: [init_local_variables] g_eth_wan_mode=0
[ 30.860000][0]
[ 30.860000][0]drivers/net/ethernet/avm/avm_cpmac/switch/ifx/vr9/ifxmips_ppa_datapath_vr9_e5.c:3135:init_local_variables: g_wan_itf=0x80, g_wanqos_en=8
[ 30.860000][0]
[ 30.880000][0]CPU_TO_WAN_TX_DESC_BASE[0] =0xbe227400
[ 30.880000][0][avmnet] [avmnet_swi_7port_disable_learning] Configuring CPU-port to receive all unknown unicast frames 0x48
[ 30.880000][0][avmnet] [avmnet_swi_7port_disable_learning] Configuring CPU-port to receive all unknown multicast frames 0x48
[dsl sus] started dsl_control (configuration: -i10_00_10_40_00_04_01_07 -f/lib/modules/dsp_vr9/vr9-B-dsl.bin -n/etc/dsl/notify/dsl_notify.sh )
nohup: appending output to nohup.out
FIO_MEI_FW_MODE_STAT_GET failed!: Operation not permitted
0
[dsl sus] started dsl_monitor
[dsl sus] ....vr9 dsp started
execute /etc/init.d/E41-capi
[ 32.080000][0][module-alloc-by-name] give 0x7c000 bytes at 0x8133e000 to module 'pcmlink' (0x556000 total bytes left)
[ 32.690000][0][module-alloc-by-name] give 0x24000 bytes at 0x813ba000 to module 'scsi_mod' (0x532000 total bytes left)
[ 32.760000][0]SCSI subsystem initialized
[ 32.790000][0][module-alloc-by-name] give 0xb000 bytes at 0x813de000 to module 'sd_mod' (0x527000 total bytes left)
[ 32.880000][0][module-alloc-by-name] give 0xe000 bytes at 0x813e9000 to module 'usb_storage' (0x519000 total bytes left)
[ 32.890000][0]usb-storage 1-2:1.0: USB Mass Storage device detected
[ 32.890000][0]scsi0 : usb-storage 1-2:1.0
[ 32.900000][0]usbcore: registered new interface driver usb-storage
[ 33.070000][1][module-alloc-by-name] give 0xfd000 bytes at 0x813f7000 to module 'isdn_fbox_fon5' (0x41c000 total bytes left)
[ 33.160000][1][capi_oslib]avm_stack_attach: cpu1 -> cpu1
[ 33.160000][1][pcmlink]chrony-support
[ 33.180000][1][isdn]PCMLINK: (fpga2) Codecslots=13 Slics=2 Pots=1 TE=2 NT=2 DECT=4 (CLARE2) DSP-EC: 0
[ 33.580000][0][module-alloc-by-name] give 0x6a000 bytes at 0x814f4000 to module 'capi_codec' (0x3b2000 total bytes left)
[ 33.800000][0][module-alloc-by-name] give 0x5b000 bytes at 0x8155e000 to module 'avm_dect' (0x357000 total bytes left)
[ 33.830000][1][module-alloc-by-name] give 0x5000 bytes at 0x815b9000 to module 'dect_io' (0x352000 total bytes left)
[ 33.850000][1][DECTDRV_ERR] fpCap ext data queueSize 5120, avmTpui 4096/34305, etsiTpui 38401/2560
execute /etc/init.d/E45-avmnexusd
1970-01-01 01:00:34 avmnexusd[2563]: ready (0sec)
execute /etc/init.d/E45-psetd
execute /etc/init.d/E46-net
Neuroptima unavailable... setting (and upon event resetting) default parameters from file '/etc/psetd.cfg'.
[ 34.720000][0][module-alloc-by-name] give 0x3000 bytes at 0x815be000 to module 'cprocfsmod' (0x34f000 total bytes left)
[ 34.780000][0][ifx_hsnand_command] read block is critical (column: 0x0 page: 0x4228)
[ 35.760000][0][module-alloc-by-name] give 0x1e4000 bytes at 0x815c1000 to module 'kdsldmod' (0x16b000 total bytes left)
[ 35.910000][0]kdsldmod: init start (sizeof(struct sk_buff) = 448)
[ 35.920000][1]userman: device registerd (userman_url) with major=231
[ 35.920000][1]kdsld: ttychannel: ldisc 8 registered
[ 35.920000][1]PCP_NL: PCP netlink interface (multicast group 1)
[ 35.920000][1]kdsldmod: init done
1970-01-01 01:00:37 l2tpv3d[2714]: ready (0sec)
[ 37.760000][0][0]system-load 100% loadavg 1.38 0.35 0.12 - 98 tasks:62 % curr:ctlmgr(3 %)max:dsl_control(6 %, pid:2459) pgstat: sum=59660 free=43098 slab=3682 alloc=3098/s fault=4048/s (sleep 2)
[ 37.930000][1]scsi 0:0:0:0: Direct-Access WDC WD25 00BEVE-00WZT0 01.0 PQ: 0 ANSI: 0
[ 37.940000][1]sd 0:0:0:0: [sda] 488397168 512-byte logical blocks: (250 GB/232 GiB)
[ 37.950000][1]sd 0:0:0:0: [sda] Write Protect is off
[ 37.950000][1]sd 0:0:0:0: [sda] No Caching mode page found
[ 37.950000][1]sd 0:0:0:0: [sda] Assuming drive cache: write through
[ 38.000000][1]sd 0:0:0:0: [sda] No Caching mode page found
[ 38.000000][1]sd 0:0:0:0: [sda] Assuming drive cache: write through
[ 38.100000][1] sda: sda1 sda2 sda3
[ 38.120000][1]sd 0:0:0:0: [sda] No Caching mode page found
[ 38.120000][1]sd 0:0:0:0: [sda] Assuming drive cache: write through
[ 38.120000][1]sd 0:0:0:0: [sda] Attached SCSI disk
1970-01-01 01:00:38 upnpd[2748]: ready (0sec)
[ 39.340000][1][1]system-load 4 loadavg 1.38 0.35 0.12 - 111 tasks:13 % curr:blkid(0 %)max:ctlmgr(4 %, pid:2730) pgstat: sum=59998 free=41922 slab=3842 alloc=556/s fault=938/s (sleep 4)
Mounting [system] to device /dev/sda2...
MOUNT: use blkid to get device /dev/sda2 data
MOUNT: filesystem type is: ext3
MOUNT:mount -t 'extX' /dev/sda2 /var/media/ftp/system
[ 40.040000][0]kjournald starting. Commit interval 5 seconds
[ 40.040000][0]EXT3-fs (sda2): using internal journal
[ 40.040000][0]EXT3-fs (sda2): mounted filesystem with writeback data mode
starting hd-idle with 1200 seconds
grep: /var/tmp/medialabels: No such file or directory
killall: ftpd: no process killed
grep: /var/tmp/inetd.conf: No such file or directory
killall: inetd: no process killed
1970-01-01 01:00:42 tr069starter[2958]: ready (0sec)
[ 42.390000][0]IPv6: ADDRCONF(NETDEV_UP): lan: link is not ready
[ 42.400000][0]IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
[ 42.420000][0]IPv6: ADDRCONF(NETDEV_UP): eth1: link is not ready
killall: nmbd: no process killed
killall: inetd: no process killed
[ 42.930000][1]IPv6: ADDRCONF(NETDEV_UP): eth2: link is not ready
[ 43.440000][0]IPv6: ADDRCONF(NETDEV_UP): eth3: link is not ready
1970-01-01 01:00:43 multid[2890]: ready (2sec)
1970-01-01 01:00:44 ddnsd[3003]: [3003]: Daemon start failed (0sec)
FATAL: ddnsd not running after started
1970-01-01 01:00:44 pcpd[3026]: ready (0sec)
rc.wlan: Start WLAN...
[ 44.810000][1]IPv6: ADDRCONF(NETDEV_UP): wasp: link is not ready
[ 44.850000][1]IPv6: ADDRCONF(NETDEV_UP): wasp: link is not ready
WLAND:[03070]:01:00.45/[0045.036]:[VER]Registered new module default, DEFAULT, 0
WLAND:[03070]:01:00.45/[0045.036]:[VER]Registered new module global, GLOBAL, 0
WLAND:[03070]:01:00.45/[0045.036]:[ALW]BUILD: Sep 10 2018, 11:06:51
[ 45.470000][1]IPv6: ADDRCONF(NETDEV_CHANGE): wasp: link becomes ready
[ 45.470000][1]IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[ 45.470000][1]IPv6: ADDRCONF(NETDEV_CHANGE): lan: link becomes ready
[ 45.490000][1][dma_device_write] auto open tx_chan_no:2
[ 46.130000][0]Re-init AVM Net Common Datapath Driver 7Port Switch ...... [ 46.130000][0][init_hw] ppe_hw_init=0xff successful
[ 46.140000][0][avmnet] [avmnet_swi_7port_disable_learning] Configuring CPU-port to receive all unknown unicast frames 0x48
[ 46.140000][0][avmnet] [avmnet_swi_7port_disable_learning] Configuring CPU-port to receive all unknown multicast frames 0x48
[ 46.140000][0][reinit_7port_common_eth] Succeeded!
[ 46.170000][0]drivers/net/ethernet/avm/avm_cpmac/switch/ifx/vr9/ifxmips_ppa_datapath_vr9_e5.c:3076:init_local_variables: [init_local_variables] g_eth_wan_mode=3
[ 46.170000][0]
[ 46.170000][0]drivers/net/ethernet/avm/avm_cpmac/switch/ifx/vr9/ifxmips_ppa_datapath_vr9_e5.c:3135:init_local_variables: g_wan_itf=0x2, g_wanqos_en=8
[ 46.170000][0]
[ 46.190000][0]CPU_TO_WAN_TX_DESC_BASE[0] =0xbe227400
[ 46.190000][0][avmnet] [avmnet_swi_7port_disable_learning] Configuring CPU-port to receive all unknown unicast frames 0x48
[ 46.190000][0][avmnet] [avmnet_swi_7port_disable_learning] Configuring CPU-port to receive all unknown multicast frames 0x48
[ 46.280000][0][module-alloc-by-name] give 0x13000 bytes at 0x817a5000 to module 'ifxmips_ppa_hal_vr9_e5' (0x158000 total bytes left)
[ 46.380000][0][module-alloc-by-name] give 0x16000 bytes at 0x817b8000 to module 'ifx_ppa_mini_sessions' (0x142000 total bytes left)
[ 46.390000] [ifx_ppa_mini_session_init]
[ 46.390000][0][ifx_ppa_mini_session_init] avm_pa sessionh_lookup table
[ 46.390000][0]max_lan_entries 192
[ 46.390000][0]max_wan_entries 192
[ 46.390000][0]max_mc_entries 32
[ 46.390000][0]max_bridging_entries 2048
[ 46.390000][0]max_ipv6_addr_entries 128
[ 46.390000][0]max_fw_queue 8
[ 46.390000][0]max_6rd_entries 4
[ 46.440000][1][module-alloc-by-name] give 0x2000 bytes at 0x817ce000 to module 'ifx_ppa_mini_qos' (0x140000 total bytes left)
[ 46.450000][0]kdsld: flushing internet sessions
[ 46.470000][0]IPv6: ADDRCONF(NETDEV_CHANGE): eth2: link becomes ready
1970-01-01 01:00:46 dsld[3083]: ready (0sec)
Mounting [YourFritz] to device /dev/sda3...
MOUNT: use blkid to get device /dev/sda3 data
MOUNT: filesystem type is: ext3
MOUNT:mount -t 'extX' /dev/sda3 /var/media/ftp/YourFritz
[ 47.090000][1]kjournald starting. Commit interval 5 seconds
[ 47.090000][0]EXT3-fs (sda3): using internal journal
[ 47.090000][0]EXT3-fs (sda3): mounted filesystem with writeback data mode
cloudmsgd not running after started
[ 47.220000][0][dma_device_write] auto open tx_chan_no:2
[ 47.360000][1]start slab_allocator-trace now (use cat /proc/slab_allocators)
1970-01-01 01:00:47 deviceinfod[3184]: ready (0sec)
execute /etc/init.d/E47-cpunet
execute /etc/init.d/E47-voip
[ 47.820000][0][0]system-load 100% loadavg 1.86 0.48 0.16 - 99 tasks:63 % curr:ksoftirqd/0(1 %)max:ctlmgr(18 %, pid:2730) pgstat: sum=61068 free=38977 slab=4087 alloc=2798/s fault=5264/s ai_sys:0.60/s 0x804e72c8 skb_flow_dissect+0x1a8)
killall: ftpd: no process killed
[ 49.510000][1][1]system-load 9 loadavg 1.86 0.48 0.16 - 100 tasks:23 % curr:multid(1 %)max:ctlmgr(4 %, pid:2730) pgstat: sum=61034 free=38160 slab=4136 alloc=412/s fault=524/s (sleep 4)
killall: inetd: no process killed
1970-01-01 01:00:50 tr069starter[3242]: ready (0sec)
telefon: SIGCHLD PID 3251 received!
telefon: SIGCHLD PID 3273 received!
killall: nmbd: no process killed
killall: inetd: no process killed
[ 53.200000][0]lan: received packet on eth0 with own address as source address
[ 53.200000][0]lan: received packet on eth0 with own address as source address
[ 53.200000][0]lan: received packet on eth0 with own address as source address
[ 53.200000][0]lan: received packet on eth0 with own address as source address
[ 53.200000][0]lan: received packet on eth0 with own address as source address
[ 53.200000][0]lan: received packet on eth0 with own address as source address
[ 53.200000][0]lan: received packet on eth0 with own address as source address
[ 53.200000][0]lan: received packet on eth0 with own address as source address
[ 53.200000][0]lan: received packet on eth0 with own address as source address
[ 53.200000][0]lan: received packet on eth0 with own address as source address
[ 54.290000][0][DECTDRV_ERR] API_FP_MAC_START_STOP_REQ 255 -> 1
[ 54.310000][0][DECTDRV_ERR] fpCap ext data queueSize 5120, avmTpui 4096/34305, etsiTpui 38401/2560
[ 54.560000][1][module-alloc-by-name] give 0x43000 bytes at 0x817d0000 to module 'krtp' (0xfd000 total bytes left)
1970-01-01 01:00:54 voipd[3260]: ready (2sec)
execute /etc/init.d/E48-mesh
[ 56.160000][1][module-alloc-by-name] give 0xb000 bytes at 0x81813000 to module 'ulpcmlink' (0xf2000 total bytes left)
playerd_tables, find MP3
[ 56.200000][0]nla_init
[ 56.200000][1]nla_init-Success
playerd_tables, /var/tmp/ffmpeg_mp3.tables written
[ 57.860000][0][0]system-load 100% loadavg 3.11 0.80 0.27 - 113 tasks:119 % curr:ksoftirqd/0(6 %)max:ctlmgr(20 %, pid:2730) pgstat: sum=62553 free=32881 slab=4384 alloc=1962/s fault=2765/s ai_sys:1.20/s 0x804e72c8 skb_flow_dissect+0x1)
Mounting [WDCWD25-00BEVE-00WZT0-01] to device /dev/sda1...
MOUNT: use blkid to get device /dev/sda1 data
[ 59.110000][1][ifx_hsnand_command] read block is critical (column: 0x0 page: 0x2b0f)
[ 59.280000][0]net_ratelimit: 102 callbacks suppressed
[ 59.280000][0]lan: received packet on eth0 with own address as source address
[ 59.290000][0]lan: received packet on eth0 with own address as source address
[ 59.290000][0]lan: received packet on eth0 with own address as source address
[ 59.290000][0]lan: received packet on eth0 with own address as source address
[ 59.300000][0]lan: received packet on eth0 with own address as source address
[ 59.300000][0]lan: received packet on eth0 with own address as source address
[ 59.300000][0]lan: received packet on eth0 with own address as source address
[ 59.300000][0]lan: received packet on eth0 with own address as source address
[ 59.300000][0]lan: received packet on eth0 with own address as source address
[ 59.300000][0]lan: received packet on eth0 with own address as source address
MOUNT: filesystem type is: swap
MOUNT: try to add swap
[ 59.630000][1][1]system-load 100% loadavg 3.11 0.80 0.27 - 115 tasks:29 % curr:meshd(2 %)max:feedd(4 %, pid:3330) pgstat: sum=62595 free=31576 slab=4409 alloc=498/s fault=598/s (sleep 7)
MOUNT: swap added
[ 59.720000][0]Adding 2097148k swap on /dev/sda1. Priority:-1 extents:1 across:2097148k
2018-11-14 21:04:52 meshd[3321]: ready (1sec)
group 4 done ...
Wenn ich selbst hier irgendetwas suchen sollte, würde ich mit der "libctlmgr" beginnen - die soll ja als Hook für die Benutzerverwaltung des "ctlmgr" dienen und bedient sich des "preloadings" über "LD_PRELOAD" für die C-Library (neue Version uClibc-ng 1.0.14 seit 07.0x), um die "rename"-Funktion zu überladen. Da braucht bloß irgendwas im Interface der C-Library nicht mehr wie bisher funktionieren (ich habe die beiden "rename"-Implementierungen (
https://git.uclibc.org/uClibc/tree/libc/sysdeps/linux/common/rename.c vs.
https://github.com/wbx-github/uclibc-ng/blob/master/libc/sysdeps/linux/common/rename.c) nicht weiter untersucht, nur grob verglichen) und es knallt beim Überlagern.
Das kennt sicherlich jeder, der solche Libs zum Erkunden fremder Software ohne Quellen einsetzt und damit Funktionsaufrufe protokollieren läßt, zur Genüge, daß das immer eine "echte Fummelei" ist, so etwas korrekt zu überlagern, auch wenn hier die Aufrufparameter nicht erst geraten werden müssen für das "rename".
Das vermute ich aber alles auch nur aus der Überlegung heraus, wo sich der "ctlmgr" in Freetz von dem originalen bei AVM unterscheiden könnte und was den dazu veranlassen könnte, daß eine gestartete Aktivität (für die ja auch etwas mehr Zeit eingeplant war, denn 168 Sekunden wären schon ein deutliche Zeitspanne - wenn auch eine "ziemlich krumme") nicht rechtzeitig beendet wurde. Etwas komisch (und wieder in den Zusammenhang mit LD_PRELOAD und dem DSO-Handling passend) finde ich aber auch diese Zeile im "back-trace":
Code:
[bt] caller return <= _ftext: 00000000 00000000 (?)
... wobei ich keine Lust habe, mir das von AVM verwendete Backtrace-Modul, aus dem dieser Dump ja stammen muß, genauer anzusehen. Das kann also genauso gut auch eine wunderbare Sackgasse sein, in die ich da steuern würde - das ist nun mal Schicksal bei solchen Fehleranalysen, wenn man die Quellen der Software nicht kennt.
-----------------------------------------------------------------------------------------------------------------------------------------
Gestartet wird der "ctlmgr" jedenfalls in etwa zu diesem Zeitpunkt (hier taucht er in Sekunde 37 das erste Mal bei der Auslastung auf) und bis zum Ende von "group 4" ist er auch einigermaßen gut beschäftigt ... in irgendeinem Thread wirft er wohl einen Watchdog für eine Aktivität an, die verzögert zum Abschluß kommen müßte und das aber nach diesen ominösen 168 Sekunden noch nicht getan hat. Ein Kandidat könnte aber auch der "avmnexusd" sein oder der "wland" - beide starten in etwas zum fraglichen Zeitpunkt und die wären ja auch neu (bzw. heftigst überarbeitet von AVM) seit der 06.93.
Andererseits kann das auch so etwas simples wie ein fehlschlagendes "mount" für ein Volume sein, weil das Fehler hat ... worauf der "ctlmgr" genau ein Auge wirft im Startprozess, ist ja weitgehend nur durch Deduktion zu ermitteln und die Zeitspanne, bis der Watchdog auslöst, paßt ja eher zu längeren Aktionen, die keine definierte Dauer haben - dazu gehört das Mounten von mehreren Volumes eben auch.
Ich würde hier also auch die größten Variablen mal aus dem Spiel nehmen - dazu gehört dann der gesamte USB-Stack (bei einer 7490 braucht man (auch mit "externals") ja nicht unbedingt ein solches Volume), auch wenn der asynchron über den "udevd" weiterläuft nach dem Starten desselben.
Außerdem hat AVM bei der 07.0x am Startvorgang dahingehend geändert, daß die Ausführung der letzten Schritte jetzt etwas anders erfolgt ... falls es doch der initiale Watchdog füt den Boot-Prozess sein sollte - wobei der eigenttlich so gg. Sekunde 10-11 gestartet werden sollte mit 240 Sekunden, nachdem der Kernel so gg. Sekunde 6-7 initialisiert ist; also das "rootfs" ist gemountet (hier bei der 7490 ist das der Wrapper) und der "unused kernel memory" aus der Initialisierung wird freigegeben. Damit kann es der hier:
Code:
[ 10.940000] AVM_WATCHDOG: System Init Ueberwachung 240 Sekunden
eigentlich nicht sein, denn der wäre nach 212 Sekunden total (wovon noch mal die knapp 11 Sekunden abgehen für den Zeitpunkt, wann der überhaupt aktiviert wurde - dann sind wir eher bei 200 Sekunden) noch etwas sehr früh dran. Damit glaube ich erst mal auch nicht wirklich an ein Problem, bei dem der Initialisierungsprozess nicht zum Ende kommt.