System wakes-up immediately alter suspend

Can’t put S905X box to suspend - it wakes up immediately.

dmesg while trying suspend: http://ix.io/1XbZ
UART boot log: http://ix.io/1QsW

Please help.

@Portisch @anon88919003 any thoughts what it can be? Is it necessary related to BL301?
Android doesn’t have such problem but uses newer kernel.

I guess it’s a “faulty” bootloader. Only a UART log will help.
It can’t be related to our BL301 as S905X & arm-Amlogic is not supported by inject_bl301.

@Portisch The logs are in the OP. Thanks

No there are not. This is a kernel log, not a bootloader log.

Do you need full boot log or something else?

Only the UART log starting before enter suspend and stopping after leaving suspend.

I’ve updated the OP, please see if you need my further assistance.
During the suspend cycle, no output appeared on UART. Should I increase verbose level maybe?

@Portisch I’ve increased verbose level on UART:

CoreELEC:~ # dmesg -n 8
CoreELEC:~ # [ 3886.553400@3] request_suspend_state: sleep (0->3) at 3885992580991 (2019-10-02 14:42:03.201389603 UTC)
[ 3886.557055@3] request_suspend_state,164,old_sleep=0,new_state=3
[ 3886.557090@0] early_suspend: call handlers
[ 3886.580882@0] avmute set to 2
[ 3886.680953@0] hdmitx: system: HDMITX: early suspend
[ 3886.681003@0] hdmitx: system: unmux DDC for gpio read edid
[ 3886.685965@2] 
[ 3886.685965@2] vdac_enable: on:0,module_sel:8
[ 3886.692482@2] fb: osd_suspended
[ 3886.692487@2] gxbb_pm: meson_system_early_suspend
[ 3886.692488@2] early_suspend: sync
[ 3886.696915@2] PM: suspend entry 2019-10-02 14:42:03.344872102 UTC
[ 3886.697767@2] PM: Syncing filesystems ... done.
[ 3887.708112@2] Freezing user space processes ... (elapsed 0.199 seconds) done.
[ 3887.911895@2] Freezing remaining freezable tasks ... (elapsed 0.002 seconds) done.
[ 3887.918394@2] cpufreq: cpufreq_suspend: Failed to stop governor for policy: ffffffc061630600
[ 3887.924861@2] cpufreq: cpufreq_suspend: Failed to stop governor for policy: ffffffc061630600
[ 3887.933181@2] cpufreq: cpufreq_suspend: Failed to stop governor for policy: ffffffc061630600
[ 3887.971567@1] cfg80211: Calling CRDA to update world regulatory domain
[ 3888.054959@3] aml_snd_card: enter aml_suspend_pre
[ 3888.055175@3] aml_snd_card: enter aml_suspend_pre set pin_ctl suspend state
[ 3888.065024@1] aml_T9015_audio_suspend!
[ 3888.065225@1] aml_snd_card: enter aml_suspend_post
[ 3888.070579@0] amvecm: suspend module
[ 3888.073353@0] DI: di: di_suspend
[ 3888.077356@0] PM: suspend of devices complete after 158.988 msecs
[ 3888.082385@0] gxbb_pm: enter meson_pm_prepare!
[ 3888.088774@0] PM: late suspend of devices complete after 2.073 msecs
[ 3888.095996@0] PM: noirq suspend of devices complete after 2.836 msecs
[ 3888.099356@0] Disabling non-boot CPUs ...
[ 3888.107983@3] CPU1: shutdown
[ 3888.115994@0] CPU2: shutdown
[ 3888.123663@0] CPU3: shutdown
[ 3888.128065@0] gxbb_pm: enter meson_pm_suspend!
[ 3888.128065@0] gxbb_pm: late_suspend: call handlers
[ 3888.128065@0] gxbb_pm: late_suspend: sync
[ 3888.128065@0] gxbb_pm: late_resume: call handlers
[ 3888.128065@0] gxbb_pm: late_resume: done
[ 3888.128065@0] gxbb_pm: ... wake up
[ 3888.128317@0] Enabling non-boot CPUs ...
[ 3888.132968@1] CPU1: Booted secondary processor
[ 3888.135173@0] CPU1 is up
[ 3888.139178@2] CPU2: Booted secondary processor
[ 3888.141876@0] CPU2 is up
[ 3888.146097@3] CPU3: Booted secondary processor
[ 3888.148943@0] CPU3 is up
[ 3888.154621@0] PM: noirq resume of devices complete after 2.057 msecs
[ 3888.160865@0] PM: early resume of devices complete after 1.515 msecs
[ 3888.165019@0] gxbb_pm: enter meson_pm_finish!
[ 3888.170714@0] DI: di_hdmirx: resume module
[ 3888.173699@0] amvecm: resume module
[ 3888.176762@0] amhdmitx: resume module 3475
[ 3888.180988@0] aml_snd_card: enter aml_resume_pre
[ 3888.185368@0] aml_T9015_audio_resume!
[ 3888.261853@1] libphy: set driving length c
[ 3888.262118@1] libphy: set PLL minimum jitter
[ 3888.391584@3] emmc: trying cali 0-th time(s)
[ 3888.395647@0] aml_snd_card: enter aml_resume_post
[ 3888.395876@0] aml_snd_card: enter aml_resume_post set pin_ctl working state
[ 3888.406895@3] emmc: delay[0]= 1200 padding= 4, bidx=1
[ 3888.407101@3] emmc: delay[1]= 1600 padding= 2, bidx=1
[ 3888.412009@3] emmc: delay[2]= 1200 padding= 4, bidx=1
[ 3888.416925@3] emmc: delay[3]= 1600 padding= 2, bidx=1
[ 3888.421985@3] emmc: delay[4]= 1600 padding= 2, bidx=1
[ 3888.426929@3] emmc: delay[5]= 1600 padding= 2, bidx=1
[ 3888.431984@3] emmc: delay[6]= 1600 padding= 2, bidx=1
[ 3888.436935@3] emmc: delay[7]= 1400 padding= 3, bidx=1
[ 3888.441987@3] emmc: calibration result @ 0: max(1600), min(1200)
[ 3888.447889@3] emmc: line_delay =0x10000202, max_cal_result =1600
[ 3888.453883@3] emmc: base_index_max 1, base_index_min 1
[ 3888.458940@3] emmc: clk 100000000 SDR mode tuning start
[ 3888.465898@3] emmc: rx_tuning_result[0] = 10
[ 3888.469856@3] emmc: rx_tuning_result[1] = 10
[ 3888.474325@3] emmc: rx_tuning_result[2] = 10
[ 3888.478309@3] emmc: rx_tuning_result[3] = 10
[ 3888.482774@3] emmc: rx_tuning_result[4] = 10
[ 3888.486753@3] emmc: rx_tuning_result[5] = 10
[ 3888.490971@3] emmc: rx_tuning_result[6] = 10
[ 3888.495447@3] emmc: rx_tuning_result[7] = 10
[ 3888.499424@3] emmc: rx_tuning_result[8] = 10
[ 3888.503902@3] emmc: rx_tuning_result[9] = 10
[ 3888.506361@3] emmc: best_win_start =0, best_win_size =10
[ 3888.511731@3] emmc: sd_emmc_regs->gclock=0x100024a,sd_emmc_regs->gadjust=0x2000
[ 3888.518878@3] emmc: gclock =0x100024a, gdelay=0x10000202, gadjust=0x2000
[ 3888.526280@3] emmc: support driver strength type 1
[ 3888.530587@3] emmc: try set sd/emmc to DDR mode
[ 3888.534823@3] emmc: try set sd/emmc to DDR mode
[ 3888.541732@3] PM: resume of devices complete after 372.483 msecs
[ 3888.547803@0] cpufreq: cpufreq_resume: Failed to start governor for policy: ffffffc061630600
[ 3888.553526@0] cpufreq: cpufreq_resume: Failed to start governor for policy: ffffffc061630600
[ 3888.561961@0] cpufreq: cpufreq_resume: Failed to start governor for policy: ffffffc061630600
[ 3888.570588@0] Restarting tasks ... done.
[ 3888.574755@0] PM: suspend exit 2019-10-02 14:42:05.309646340 UTC
[ 3888.580115@0] suspend: exit suspend, ret = 0 (2019-10-02 14:42:05.315010545 UTC)
[ 3888.580118@0] wakeup wake lock: unknown_wakeups
[ 3888.580130@0] request_suspend_state: wakeup (3->0) at 3888019022850 (2019-10-02 14:42:05.315025500 UTC)
[ 3888.580132@0] request_suspend_state,164,old_sleep=1,new_state=0
[ 3888.580444@0] late_resume: call handlers
[ 3888.580447@0] gxbb_pm: meson_system_late_resume
[ 3888.580452@0] fb: osd_resumed
[ 3888.580457@0] tv_vout: tv_set_current_vmode[919]fps_target_mode=16
[ 3888.580461@0] tv_vout: mode is 16,sync_duration_den=1,sync_duration_num=60
[ 3888.580470@0] tv_vout: TV mode 1080p60hz selected.
[ 3888.580473@0] 
[ 3888.580473@0] vdac_enable: on:0,module_sel:8
[ 3888.580478@0] 
[ 3888.580478@0] vdac_enable: on:0,module_sel:8
[ 3888.580483@0] tv_vout: new mode =1080p60hz set ok
[ 3888.580494@0] hdmitx: invalid doesn't have frac_rate
[ 3888.580497@0] hdmitx: set clk: VIC = 512  cd = 4  cs = 2 frac_rate = 0
[ 3888.580503@0] config HPLL = 3450000
[ 3888.580528@0] HPLL: 0xc000028f
[ 3888.580529@0] config HPLL done
[ 3888.580535@0] set_hpll_od3_clk_div[442] div = 6
[ 3888.580541@0] j = 9  vid_clk_div = 1
[ 3888.608186@0] EDID Parser:
[ 3888.608295@0] dump_dtd_info[1786]
[ 3888.608297@0] pixel_clock 10800
[ 3888.608298@0] h_active 1280
[ 3888.608299@0] h_blank 408
[ 3888.608300@0] v_active 1024
[ 3888.608301@0] v_blank 42
[ 3888.608302@0] h_sync_offset 48
[ 3888.608303@0] h_sync 112
[ 3888.608304@0] v_sync_offset 1
[ 3888.608305@0] v_sync 3
[ 3888.608309@0] EDID BlockCount=0
[ 3888.608310@0] hdmitx: edid: HDMI: set default vic
[ 3888.608311@0] hdmitx: edid: Setting maxTMDSclock from range block
[ 3888.608313@0] hdmitx: edid: edid blk0 checksum:0 ext_flag:0
[ 3888.608317@0] hdmitx: edid: check sum valid
[ 3888.608320@0] hdmitx: edid: blk0 raw data
[ 3888.608354@0] 00ffffffffffff0009d10479455400000712010380261e782ecc25a557499b25
[ 3888.608354@0] 115054a56b8071008100814001010101010101010101302a009851002a403070
[ 3888.608354@0] 1300782d1100001e000000ff005632383135333536534c300a20000000fd0037
[ 3888.608354@0] 4c1f530e000a202020202020000000fc0042656e5120453930300a0a0a0a0055
[ 3888.608354@0] 
[ 3888.608354@0] 
[ 3888.608377@0] hdmitx: video: auto - get current mode: 1080p60hz vmode_e 16
[ 3888.608379@0] hdmitx: stream colourdepth was 8 in para 0x01d75f38 (1920x1080p60hz)
[ 3888.608381@0] hdmitx: display colourdepth was 8 in cur_param 0x01d73cb0 (VIC: 16)
[ 3888.608384@0] hdmitx: update rx hdr info 0
[ 3888.608385@0] hdmitx: update physcial size: 380 300
[ 3888.608402@0] Colourspace is set to Y444 but display does not support it
[ 3888.608402@0] hdmitx: hdev->para now = para at 0x01d75f38
[ 3888.608405@0] hdmitx: display colourdepth is 10 in cur_param 0x01d73cb0 (VIC: 16)
[ 3888.608409@0] Bitdepth is set to 10 bits but display does not support deep colour
[ 3888.608409@0] hdmitx: Stream colourdepth is 8 in para 0x01d75f38 (1920x1080p60hz - VIC: 16)
[ 3888.608447@0] hdmitx: video: vinfo: 1080p60hz 60 1
[ 3888.608450@0] hdmitx: video: vinfo recalc: 1080p60hz 60 1
[ 3888.608456@0] hdmitx: system: already init VIC = 0  Now VIC = 16
[ 3888.608459@0] hdmitx: system: params found at 0x01d73cb0
[ 3888.608461@0] hdmitx: system: cur_param = param at 0x01d73cb0 colourdepth 8 colourspace 0
[ 3888.608465@0] hdmitx: video: pixel freq 148500, tmds clock 148500, MaxClock1 140000, HF_IEEEOUI 0x000000, MaxClock2 0
[ 3888.608468@0] hdmitx: rx no SCDC present indicator
[ 3888.610478@0] hdmitx: ddc rd8b error 0x54 0x01
[ 3888.612491@0] hdmitx: ddc rd8b error 0x54 0x01
[ 3888.612496@0] hdmirx version is 1.4 or below
[ 3888.612498@0] hdmitx div40: 0
[ 3888.641229@0] hdmitx: system: set pll
[ 3888.641234@0] hdmitx: system: param->VIC:16
[ 3888.641243@0] hdmitx: set clk: VIC = 16  cd = 4  cs = 0 frac_rate = 0
[ 3888.641250@0] config HPLL = 2970000
[ 3888.641271@0] HPLL: 0xc000027b
[ 3888.641272@0] config HPLL done
[ 3888.641281@0] set_hpll_od3_clk_div[442] div = 6
[ 3888.641289@0] j = 4  vid_clk_div = 1
[ 3888.641298@0] hdmitx: set enc for VIC: 16
[ 3888.641319@0] hdmitx_set_hw[4905] set VIC = 16
[ 3888.641446@0] Set rgb_ycc to 0
[ 3888.641598@0] hdmitx: system: irq 80000001
[ 3888.653186@0] hdmitx: ddc w1b error 0x54 0x20 0x00
[ 3888.655196@0] hdmitx: ddc w1b error 0x54 0x20 0x00
[ 3888.657205@0] hdmitx: ddc rd8b error 0x54 0x21
[ 3888.658261@0] Start = 0x10000100   End = 0x100001ff
[ 3888.658270@0] [0x10000104]: 0x00000001
[ 3888.658446@0] [0x10000180]: 0x000000ff
[ 3888.658449@0] [0x10000181]: 0x000000ff
[ 3888.658451@0] [0x10000182]: 0x00000003
[ 3888.658454@0] [0x10000183]: 0x00000007
[ 3888.658456@0] [0x10000184]: 0x0000003f
[ 3888.658459@0] [0x10000185]: 0x00000002
[ 3888.658462@0] [0x10000187]: 0x000000ff
[ 3888.658465@0] [0x10000188]: 0x00000003
[ 3888.773207@0] hdmitx: system: PHY Setting Done
[ 3888.777223@0] Sink is DVI device
[ 3888.777261@0] Set rgb_ycc to 0
[ 3888.777268@0] hdmitx: system: packet: can't get vendor data
[ 3888.777272@0] hdmtix: set audio
[ 3888.777280@0] hdmitx tx_aud_src = 0
[ 3888.777306@0] hdmitx: fs = 2, cd = 4, tmds_clk = 148500
[ 3888.777309@0] hdmitx aud_n_para = 6272
[ 3888.777326@0] hdmitx set channel status
[ 3888.777383@0] hdmitx: audio: Audio Type: PCM
[ 3888.777390@0] hdmitx: video: VIC: 16 (16) 1920x1080p60hz
[ 3888.777399@0] hdmitx: video: Bit depth: 8-bit, Colour range RGB: limited, YCC: limited, Colourspace: RGB
[ 3888.777403@0] hdmitx: video: Colorimetry: bt709
[ 3888.777408@0] hdmitx: video: PLL clock: 0xc000027b, Vid clock div 0x000a339c
[ 3888.778273@2] amhdmitx: late resume module 216
[ 3888.778341@2] hdmitx: swrstzreq
[ 3888.778343@2] hdmitx: system: late resume
[ 3889.099903@3] aml_spdif_dai: aml_hw_iec958_init,runtime->rate=44100, runtime->channels=2, same source mode(1)
[ 3889.099907@3] aml_spdif_dai: share the same clock
[ 3889.099913@3] aml_audio_hw: IEC958 PCM32
[ 3889.099917@3] hdmitx: audio: aout notify rate 44100
[ 3889.099919@3] hdmitx: audio: aout notify size 32
[ 3889.099920@3] hdmitx: audio: no update
[ 3889.099929@3] aml_snd_m8_card aml_m8_snd.47: i2s/958 same source
[ 3889.100166@3] aml_spdif_dai: aml_hw_iec958_init,runtime->rate=44100, runtime->channels=2, same source mode(1)
[ 3889.100168@3] aml_spdif_dai: share the same clock
[ 3889.100174@3] aml_audio_hw: IEC958 PCM32
[ 3889.100177@3] hdmitx: audio: aout notify rate 44100
[ 3889.100178@3] hdmitx: audio: aout notify size 32
[ 3889.100179@3] hdmitx: audio: no update
[ 3889.100185@3] aml_snd_m8_card aml_m8_snd.47: i2s/958 same source
[ 3889.100279@3] channel count should be 8, we got 2 aborting
[ 3889.413452@2] late_resume: done

@Portisch is it what you need?