flipperzero-firmware icon indicating copy to clipboard operation
flipperzero-firmware copied to clipboard

Desktop auto lock time causes freeze/crash

Open Tomi2965 opened this issue 9 months ago • 10 comments

Describe the bug.

When I set auto lock time to any value, FZ always freeze after some time. Same behavior after reboot. FZ lock's automaticaly (or I lock it manually), then after some time is FZ totally unresponsive, and I must apply reboot. No error message on screen before/after reboot.

No difference between dev/stable/pre-release. FZ works well with auto lock timer off + lock manually.

Reproduction

This way is tested 3x, FZ always freeze:

  1. set autolock time to 30s
  2. wait for autolock or lock manually
  3. after lock, do reboot (LEFT+BACK)
  4. wait appx. 30 seconds, FZ will freeze
  5. again reboot (LEFT+BACK)
  6. wait appx. 30 seconds, FZ again freeze
  7. do reboot (LEFT+BACK)
  8. set autolock time to OFF
  9. lock manually
  10. FZ will not freeze after 30s

Target

No response

Logs

No response

Anything else?

No response

Tomi2965 avatar Apr 29 '24 07:04 Tomi2965

@Tomi2965 I can't reproduce it on my devices. Can you get logs from device(serial console on GPIO) when it freezes?

@doomwastaken can you try to reproduce?

skotopes avatar Apr 29 '24 09:04 skotopes

Log via devboard. Connected, rebooted - log starts at boot.

0 [I][FuriHalRtc] Init OK 3 [I][FuriHalInterrupt] Init OK 7 [W][FuriHalFlash] FLASH->SR 0x00008000(Known ERRATA) 13 [I][FuriHalResources] Init OK 16 [I][FuriHalVersion] Init OK 20 [I][FuriHalSpiConfig] Init OK 24 [I][FuriHalIbutton] Init OK 28 [I][FuriHalSpeaker] Init OK 31 [I][FuriHalCrypto] Init OK 35 [I][FuriHalI2c] Init OK 42 [I][Gauge] Device Number 0220 45 [I][Gauge] Verifying data memory 107 [I][Gauge] Data memory verification complete 113 [I][FuriHalPower] Init OK 118 [I][FuriHalBt] Start BT initialization 122 [I][FuriHalMemory] SRAM2A: 0x20031378, 13448 127 [I][Core2] Core2 started 130 [I][FuriHalMemory] SRAM2B: 0x20038000, 11264 136 [I][FuriHalMemory] SRAM2A clear 141 [I][FuriHalMemory] SRAM2B clear 146 [I][FuriHalMemory] Enabled 149 [I][FuriHalUsb] Init OK 153 [I][FuriHalVibro] Init OK 157 [I][FuriHalSubGhz] Init OK 161 [I][FuriHalNfc] Adjusting regulators 172 [I][Flipper] Firmware version: unknown Build date: 25-04-2024 Git Commit: 43c43818 (0) Git Branch: dev 182 [I][Flipper] Boot mode 0, starting services 189 [I][SavedStruct] Loading "/int/.bt.settings" 197 [I][Loader] Executing system start hooks 203 [I][SavedStruct] Loading "/int/.dolphin.state" 208 [I][Flipper] Startup complete 212 [I][CliVcp] Init OK 215 [I][StorageInt] Starting 218 [I][StorageInt] Config: start 080B8000, read 8, write 8, page size: 4096, page count: 31, cycles: 10000 230 [I][FuriHalUsb] USB Mode change done 235 [I][StorageInt] Mounted 238 [I][StorageExt] card detected 716 [I][StorageExt] card mounted 721 [I][NotificationSrv] loading settings from "/int/.notification.settings" 781 [I][NotificationSrv] load success 838 [I][SavedStruct] Loading "/int/.bt.keys" 855 [I][Core2] C2 boot completed, mode: Stack 859 [I][Core2] Core2: FUS: 1.2.0, mem 16/0, flash 6 pages 865 [I][Core2] Core2: Stack: 1.19.0, branch 0, reltype 2, stacktype 3, flash 29 pages 875 [I][SubGhzOnStart] Add allowed band: start 433050000Hz, stop 434790000Hz, power_limit 12dBm, duty_cycle 50% 885 [I][Core2] Radio stack started 889 [I][BleExtraBeacon] Init 896 [I][SubGhzOnStart] Add allowed band: start 868150000Hz, stop 868550000Hz, power_limit 12dBm, duty_cycle 50% 908 [I][SavedStruct] Loading "/int/.expansion.settings" 924 [I][BleGap] Start advertising 1293 [I][AnimationManager] Select 'L1_Waves_128x50' animation 1315 [I][SavedStruct] Loading "/int/.desktop.settings" 1775 [I][AnimationManager] Select 'L3_Hijack_radio_128x64' animation 1783 [I][FuriHalUsb] Mode unlock 2298 [I][SavedStruct] Loading "/int/.desktop.settings" 2332 [W][ViewPort] ViewPort lockup: see applications/services/gui/view_port.c:180 2342 [W][ViewPort] ViewPort lockup: see applications/services/gui/view_port.c:180 3368 [I][Storage] SD card mount 3373 [I][Loader] Starting StorageMoveToSd 3378 [I][AnimationManager] Unload animation 'L3_Hijack_radio_128x64' 3426 [I][MoveToSd] Nothing to move 3440 [I][Loader] App returned: 0 3443 [I][Loader] Application stopped. Free heap: 149464 3743 [I][AnimationManager] Select 'L3_Hijack_radio_128x64' animation 3753 [I][AnimationManager] Load animation 'L3_Hijack_radio_128x64' 3777 [I][SavedStruct] Loading "/int/.desktop.settings" 5303 [I][BleGap] Connection parameters: Connection Interval: 39 (48 ms), Slave Latency: 0, Supervision Timeout: 500 5313 [W][BleGap] Unsupported connection interval. Request connection parameters update 5819 [I][BleGap] Connection parameters event complete 5824 [I][BleGap] Connection parameters: Connection Interval: 12 (15 ms), Slave Latency: 0, Supervision Timeout: 500 5835 [W][BleGap] Unsupported connection interval. Request connection parameters update 5844 [E][BleGap] Failed to request connection parameters update 5923 [I][BleGap] Pairing complete 5928 [I][BtSrv] Open RPC connection 6987 [I][BleGap] Rx MTU size: 414 33832 [I][SavedStruct] Loading "/int/.desktop.settings"

[CRASH][DesktopSrv] furi_assert failed r0 : 2000a150 r1 : 20033dd0 r2 : 2000024c r3 : 1 r4 : 2000a048 r5 : 1 r6 : 4 r7 : a5a5a5a5 r8 : a5a5a5a5 r9 : a5a5a5a5 r10 : a5a5a5a5 r11 : 20031364 lr : 8072ee9 stack watermark: 744 heap total: 185568 heap free: 134848 heap watermark: 133360 core2: not faulted System halted. Connect debugger for more info

Tomi2965 avatar Apr 29 '24 11:04 Tomi2965

Can you reproduce it with latest release-candidate 0.101.2-rc? On 0.101.2-rc can you test it with BLE disabled? Also can you provide info on your phone: Vendor, Model, OS Version? Do you have ISP debugger(wifi board/stlink/jlink)?

skotopes avatar Apr 29 '24 11:04 skotopes

Latest rc (0.101.2) - OK - but - after reboot a "locked" animation is played, then after 30s is played again Back on latest dev 7414e6d4 with BLE disabled - same crash My phone: CAT S75, Andorid 12, Flipper App - latest dev (beta). Yes, I have a WiFi dev board.

Tomi2965 avatar Apr 29 '24 12:04 Tomi2965

@skotopes I forgot, sorry. Small edit: Latest rc 0.101.2 with BLE enabled- OK - but - after reboot a "locked" animation is played, then after 30s is played again Latest rc 0.101.2 with BLE disabled - OK - but - after reboot a "locked" animation is played, then after 30s is played again

Tomi2965 avatar Apr 29 '24 12:04 Tomi2965

https://docs.flipper.net/development/hardware/wifi-developer-board

  • Get firmware source code
  • Flash with ./fbt flash
  • Reproduce crash
  • Debug ./fbt debug
  • In debug cli: bt, thread apply all bt
  • bring output here

skotopes avatar Apr 29 '24 13:04 skotopes

@skotopes I'm not sure, if this is right or I do a mistake. Please see attached images. I am using a virtual machine (VMWare Player, Debian 12 - fresh install). Same results on older Debian at my laptop. Installed all required (fbt, ufbt, python3-full, git, ...). Board flashed sucessfully. Downloaded FW, build OK, flash OK, then run debug. See image 1. Exit, then run ./fbt blackmagic. See image 2.

Any ideas what can be wrong? I'm seriously sorry, I'm not much experienced about debugging. Thanks a lot.

debug bm

Tomi2965 avatar Apr 29 '24 16:04 Tomi2965

I've reproduced issue. Will be fixed in next release(0.102)

skotopes avatar Apr 29 '24 16:04 skotopes

@skotopes thanks for info.

It's possible, that this issue may cause freezing when I enter menu-settings-desktop? Sometimes when I open this menu my FZ just stuck, sometimes just freeze for few seconds.

Tomi2965 avatar Apr 29 '24 16:04 Tomi2965

There are 2 issues:

  • desktop locking itself twice and crashing on state assert
  • BLE interval negotiation ends with too small connection interval which causes core2 to lock flash controller to prevent radio deadline miss, which causes internal storage lockup and crash.

There will be 2 separate fixes.

skotopes avatar Apr 29 '24 17:04 skotopes

@Tomi2965 Can I ask you to check something?

There is a PR: https://github.com/flipperdevices/flipperzero-firmware/pull/3644 that changes connection parameters negotiation scheme. This should allow to negotiate connection interval in acceptable range.

Please flash this PR and attach flipper logs, I'm interested in [BleGap] Connection parameters part.

skotopes avatar May 11 '24 12:05 skotopes

@skotopes see attached log (debug=on, loglevel=debug). If u need anything else, just ask.

log.txt

Tomi2965 avatar May 12 '24 10:05 Tomi2965

@Tomi2965 There were no BLE connection established in your logs. Please connect your phone and show me BleGap part of it.

skotopes avatar May 12 '24 10:05 skotopes

Example of what are we looking for:

71201267 [I][BleGap] Connection parameters: Connection Interval: 36 (45 ms), Slave Latency: 0, Supervision Timeout: 500
71201273 [I][BleGap] Connection interval suites us. Spent 0 rounds to negotiate
71201447 [D][BleGap] Slave security initiated
71201717 [I][BleGap] Pairing complete
71201721 [I][BtSrv] Open RPC connection
71201723 [D][GattChar] Updating Flow control char
71201726 [D][RpcSrv] Session started
71201728 [D][GattChar] Updating RPC status char
71201731 [D][GattChar] Updating Battery Level char
71203067 [I][BleGap] Rx MTU size: 414
71203517 [I][BleGap] Connection parameters event complete
71203520 [I][BleGap] Connection parameters: Connection Interval: 12 (15 ms), Slave Latency: 0, Supervision Timeout: 500
71203526 [W][BleGap] Connection interval doesn't suite us. Trying to negotiate, round 1
71203593 [D][BleGap] Procedure complete event
71203682 [I][BleGap] Connection parameters event complete
71203685 [I][BleGap] Connection parameters: Connection Interval: 24 (30 ms), Slave Latency: 0, Supervision Timeout: 500
71203691 [I][BleGap] Connection interval suites us. Spent 1 rounds to negotiate

skotopes avatar May 12 '24 10:05 skotopes

@skotopes I'm really sorry, my fault. Attaching full log.

log2.txt

Tomi2965 avatar May 12 '24 10:05 Tomi2965

That's quite interesting. Now your phone BLE stack behaves as it should. Looks like all issues were fixed. All changes will be included in next release.

skotopes avatar May 12 '24 10:05 skotopes

Thanks a lot! :)

One small problem still remains. During my testing of #3643 and later #3644, my FZ sometimes freeze in settings-desktop-aulock time. I just changed value (not depends on value change from/to), then I press randomly up/down or back, FZ just stuck. IDK why, for now I am unable to reproduce it to check logs. I will try it again after next release. If problem remains, I will open new issue with info.

Tomi2965 avatar May 12 '24 11:05 Tomi2965