uzbek-plus/logs/b7/b7c/c7r/uart-markers.txt
q 8d7721c775 B7: add network time bootstrap and persistent B7C cache
B7A: QMI DMS time vs VNIIFTRI NTP (DMS = UTC - 0.28 s, sigma 1 ms; NITZ = DMS
truncated to 1 s). B7B: a 1970 -> 2026 date -s step is harmless for the modem
stack. B7C: aurora-modem probes DMS/NITZ along the start flow and steps
CLOCK_REALTIME once at the first valid sample (REG registered/attached), never
RTC; background SNTP check (query only) after START OK. 3/3 class-A cold boots
PASS (residual +0.04/+0.36/+0.84 s), cache 14fe453a written (B7C_WRITE_VERIFIED)
and verified by a normal power-on (V1, +0.26 s).

Also publishes the prerequisite R2 (boot-hang / lk eMMC investigation, T4
telnet baseline that B7C builds on) and R3 (autonomous cold boot, NCM loss)
material, and extends tools/publish-sanitize.py to r2/, r3/, b7/.
Binary images, initramfs, busybox and raw logs stay out (see b7/*/SHA256SUMS).
2026-10-02 20:18:25 +03:00

85 lines
7.3 KiB
Text
Raw Permalink Blame History

This file contains invisible Unicode characters

This file contains invisible Unicode characters that are indistinguishable to humans but may be processed differently by a computer. If you think that this is intentional, you can safely ignore this warning. Use the Escape button to reveal them.

19:35:51.671 [ 0.000000] Linux version 7.2.7-aurora-bam1 (q@aiaiai) (aarch64-linux-gnu-gcc (Debian 14.2.0-19) 14.2.0, GNU ld (GNU Binutils for Debian) 2.44) #5 SMP PREEMPT Wed Sep 30 04:59:18 +06 2026
19:35:53.276 [ 1.182027] mmc0: new HS200 MMC card at address 0001
19:35:54.077 EMMC-RO-SUMMARY devices=30 all_ro=YES
19:35:59.279 vali[ 7.206380] [init] T4: telnetd started on 172.16.42.1:23
19:35:59.479 [init] T4: telnetd started on 172.16.42.1:23
19:36:01.681 B1_OK=1
19:36:01.681 ~ # [ 9.493512] [aurora-modem] === START (conf /etc/aurora/modem.conf, apn 'internet.beeline.ru', ip-type ipv4)
19:36:01.681 [ 9.584836] [aurora-modem] STATE OFF -> RMTFS_READY
19:36:01.681 [ 9.590583] [aurora-modem] STATE RMTFS_READY -> MPSS_BOOTING
19:36:02.482 [ 10.272072] [aurora-modem] STATE MPSS_BOOTING -> MPSS_RUNNING
19:36:05.483 [ 13.316803] [aurora-modem] STATE MPSS_RUNNING -> QMI_READY
19:36:05.683 [ 13.422008] [aurora-modem] TIME probe 1 [QMI_READY]: dms_ms=3234 dms_utc=315964803.234 nitz=none dms-nitz=- clock=47 -> INVALID (year<2026)
19:36:05.683 [ 13.471726] [aurora-modem] STATE QMI_READY -> SIM_READY
19:36:05.683 [ 13.577680] [aurora-modem] TIME probe 2 [SIM_READY]: dms_ms=3385 dms_utc=315964803.385 nitz=none dms-nitz=- clock=47 -> INVALID (year<2026)
19:36:09.084 [ 16.832061] [aurora-modem] STATE SIM_READY -> RADIO_ONLINE
19:36:09.084 [ 16.940028] [aurora-modem] TIME probe 3 [RADIO_ONLINE]: dms_ms=6740 dms_utc=315964806.740 nitz=none dms-nitz=- clock=50 -> INVALID (year<2026)
19:36:09.484 [ 17.283190] [aurora-modem] REG t+0.3s: not-registered-searching / PS detached / none (none, ) - pci= si=/ cl=/
19:36:09.485 [ 17.379848] [aurora-modem] TIME probe 4 [REG:not-registered-searching/detached]: dms_ms=7189 dms_utc=315964807.189 nitz=none dms-nitz=- clock=51 -> INVALID (year<2026)
19:36:12.886 [ 20.678257] [aurora-modem] REG t+3.7s: not-registered-searching / PS detached / limited (limited-regional, camped) 250-99 pci=390 si=/156416008 cl=7661/156416008
19:36:12.886 [ 20.791217] [aurora-modem] TIME probe 5 [REG:not-registered-searching/detached]: dms_ms=10592 dms_utc=315964810.592 nitz=1980-01-06 00:00:10 dms-nitz=+0.63 clock=54 -> INVALID (year<2026)
19:36:38.496 [ 46.283885] [aurora-modem] REG t+29.3s: registration-denied / PS detached / limited (none, none) 250-01 pci=47 si=41028/135972149 cl=41028/135972149
19:36:38.496 [ 46.391040] [aurora-modem] TIME probe 6 [REG:registration-denied/detached]: dms_ms=36192 dms_utc=315964836.192 nitz=1980-01-06 00:00:36 dms-nitz=+0.23 clock=80 -> INVALID (year<2026)
19:37:00.904 [ 68.795921] [aurora-modem] REG t+51.8s: registered / PS attached / available (none, ps) 250-99 pci=390 si=7661/156416008 cl=7661/156416008
19:37:01.104 [ 68.900892] [aurora-modem] TIME probe 7 [REG:registered/attached]: dms_ms=1474994220048 dms_utc=1790959020.048 nitz=2026-10-02 16:37:00 dms-nitz=+0.08 clock=102 -> VALID (ok)
19:37:01.904 [ 69.796416] [aurora-modem] TIME SET rc=0 source=qmi-dms phase=REG:registered/attached old=103 (1970-01-01 00:01:43) new=1790959021 (2026-10-02 16:37:01) uptime=69.64 dms-nitz=+0.08 validation=VALID rtc=untouched
19:37:01.904 [ 69.810429] [aurora-modem] registered: MCC: '250' MNC: '99' Description: 'Beeline' MCC: '250' MNC: '99' after 52.9s
19:37:01.904 [ 69.822578] [aurora-modem] STATE RADIO_ONLINE -> REGISTERED
19:37:02.105 [ 69.933408] [aurora-modem] TIME probe 8 [REGISTERED]: dms_ms=1474994221077 dms_utc=1790959021.077 nitz=2026-10-02 16:37:01 dms-nitz=+0.11 clock=1790959021 -> VALID (ok)
19:37:16.346 <<<<<< message = "Allocate CID" (0x0022)
19:37:16.346 <<<<<< message = "Allocate CID" (0x0022)
19:37:16.748 <<<<<< message = "Allocate CID" (0x0022)
19:37:16.748 <<<<<< message = "Release CID" (0x0023)
19:37:16.748 <<<<<< message = "Allocate CID" (0x0022)
19:37:16.949 <<<<<< message = "Allocate CID" (0x0022)
19:37:16.949 <<<<<< message = "Release CID" (0x0023)
19:37:16.949 <<<<<< message = "Allocate CID" (0x0022)
19:37:17.150 <<<<<< message = "Allocate CID" (0x0022)
19:37:17.150 <<<<<< message = "Allocate CID" (0x0022)
19:37:17.350 <<<<<< message = "Allocate CID" (0x0022)
19:37:17.350 <<<<<< message = "Allocate CID" (0x0022)
19:37:17.551 <<<<<< message = "Allocate CID" (0x0022)
19:37:17.552 <<<<<< message = "Allocate CID" (0x0022)
19:37:17.552 <<<<<< message = "Allocate CID" (0x0022)
19:37:17.753 <<<<<< message = "Allocate CID" (0x0022)
19:37:17.753 <<<<<< message = "Allocate CID" (0x0022)
19:37:17.754 <<<<<< message = "Allocate CID" (0x0022)
19:37:17.954 <<<<<< message = "Allocate CID" (0x0022)
19:37:17.954 <<<<<< message = "Allocate CID" (0x0022)
19:37:18.161 <<<<<< message = "Allocate CID" (0x0022)
19:37:18.161 <<<<<< message = "Allocate CID" (0x0022)
19:37:18.162 <<<<<< message = "Allocate CID" (0x0022)
19:37:18.362 <<<<<< message = "Allocate CID" (0x0022)
19:37:25.377 <<<<<< translated = FAILURE: NotSupported
19:37:25.577 [2812]: <dbg> [1790959044.438443] [modem0] setup SIM hot swap (5/8): no need to register for SIM ICCID refresh events
19:37:25.778 <<<<<< translated = FAILURE: NotSupported
19:37:26.180 <<<<<< message = "UIM Get ICCID" (0x003C)
19:37:26.180 <<<<<< message = "UIM Get ICCID" (0x003C)
19:37:26.180 <<<<<< type = "ICCID" (0x01)
19:37:27.183 <<<<<< translated = FAILURE: NotProvisioned
19:37:27.184 <<<<<< translated = FAILURE: NotProvisioned
19:37:27.384 <<<<<< translated = FAILURE: NotProvisioned
19:37:51.213 [ 119.150790] [aurora-modem] STATE REGISTERED -> MM_READY
19:37:52.215 <<<<<< message = "UIM Get ICCID" (0x003C)
19:37:52.415 <<<<<< message = "UIM Get ICCID" (0x003C)
19:37:52.415 <<<<<< type = "ICCID" (0x01)
19:37:53.824 <<<<<< translated = FAILURE: InvalidQmiCommand
19:37:54.630 <<<<<< translated = FAILURE: MissingArgument
19:37:55.032 <<<<<< translated = FAILURE: DeviceNotReady
19:37:55.435 <<<<<< translated = FAILURE: InvalidArgument
19:37:55.437 <<<<<< translated = FAILURE: InvalidArgument
19:37:55.637 <<<<<< translated = FAILURE: MissingArgument
19:37:55.838 <<<<<< translated = FAILURE: DeviceNotReady
19:37:56.040 <<<<<< translated = FAILURE: InvalidArgument
19:37:56.241 <<<<<< translated = FAILURE: InvalidArgument
19:38:00.261 <<<<<< message = "Allocate CID" (0x0022)
19:38:00.261 <<<<<< message = "Allocate CID" (0x0022)
19:38:00.865 <<<<<< message = "Allocate CID" (0x0022)
19:38:01.065 <<<<<< message = "Release CID" (0x0023)
19:38:01.066 <<<<<< message = "Allocate CID" (0x0022)
19:38:01.066 <<<<<< message = "Release CID" (0x0023)
19:38:03.886 [ 131.730780] [aurora-modem] STATE MM_READY -> BEARER_CONNECTED
19:38:03.886 [ 131.743592] [aurora-modem] === START OK in 122.2s (wwan0 10.39.38.118/30, routes: 10.10.22.1 194.186.191.1 77.88.8.8 1.1.1.1 )
19:38:04.087 [ 131.846435] [aurora-modem] TIME probe 9 [BEARER_CONNECTED]: dms_ms=1474994282995 dms_utc=1790959082.995 nitz=2026-10-02 16:38:03 dms-nitz=+0.03 clock=1790959083 -> VALID (ok)
19:38:19.294 [ 147.163126] [aurora-modem] SNTP check ( 89.109.251.21 89.109.251.22 89.109.251.23): 14 replies; best offset delay server: +0.842653 0.057825 89.109.251.21: (offset > 0 = clock behind)
19:38:19.294 [ 147.167669] [aurora-modem] SNTP: |offset| < 1s - clock kept (no slew: STA_UNSYNC stays, RTC_SYSTOHC never engages)