q/uzbek-plus
1
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity Actions
uzbek-plus/logs/b7/b7b/b7b-observe.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

82 lines
10 KiB
Text
Raw Blame History

# every 5 s: up clock pids state wwan0 lte_ping host_ping lifecycle_lines dmesg_lines rtc; every 15 s mm
up=2928.08 clk=09:45:04 MM=1655 rmtfs=1056 qp=1701 tel=615 state=BEARER_CONNECTED wwan0=10.41.212.24/28 lte=ok host=up lc=35 dmesg=312 rtc=2930 mm=connected/home/ bearer1=yes
up=2933.48 clk=09:45:09 MM=1655 rmtfs=1056 qp=1701 tel=615 state=BEARER_CONNECTED wwan0=10.41.212.24/28 lte=ok host=up lc=35 dmesg=312 rtc=2936
up=2938.64 clk=09:45:14 MM=1655 rmtfs=1056 qp=1701 tel=615 state=BEARER_CONNECTED wwan0=10.41.212.24/28 lte=ok host=up lc=35 dmesg=312 rtc=2941
up=2943.79 clk=09:45:19 MM=1655 rmtfs=1056 qp=1701 tel=615 state=BEARER_CONNECTED wwan0=10.41.212.24/28 lte=ok host=up lc=35 dmesg=312 rtc=2946 mm=connected/home/ bearer1=yes
up=2949.06 clk=09:45:25 MM=1655 rmtfs=1056 qp=1701 tel=615 state=BEARER_CONNECTED wwan0=10.41.212.24/28 lte=ok host=up lc=35 dmesg=312 rtc=2951
up=2954.21 clk=09:45:30 MM=1655 rmtfs=1056 qp=1701 tel=615 state=BEARER_CONNECTED wwan0=10.41.212.24/28 lte=ok host=up lc=35 dmesg=312 rtc=2956
up=2959.38 clk=09:45:35 MM=1655 rmtfs=1056 qp=1701 tel=615 state=BEARER_CONNECTED wwan0=10.41.212.24/28 lte=ok host=up lc=35 dmesg=312 rtc=2961 mm=connected/home/ bearer1=yes
up=2964.64 clk=09:45:40 MM=1655 rmtfs=1056 qp=1701 tel=615 state=BEARER_CONNECTED wwan0=10.41.212.24/28 lte=ok host=up lc=35 dmesg=312 rtc=2967
up=2969.80 clk=09:45:45 MM=1655 rmtfs=1056 qp=1701 tel=615 state=BEARER_CONNECTED wwan0=10.41.212.24/28 lte=ok host=up lc=35 dmesg=312 rtc=2972
up=2974.95 clk=09:45:50 MM=1655 rmtfs=1056 qp=1701 tel=615 state=BEARER_CONNECTED wwan0=10.41.212.24/28 lte=ok host=up lc=35 dmesg=312 rtc=2977 mm=connected/home/ bearer1=yes
up=2980.21 clk=09:45:56 MM=1655 rmtfs=1056 qp=1701 tel=615 state=BEARER_CONNECTED wwan0=10.41.212.24/28 lte=ok host=up lc=35 dmesg=312 rtc=2982
up=2985.37 clk=09:46:01 MM=1655 rmtfs=1056 qp=1701 tel=615 state=BEARER_CONNECTED wwan0=10.41.212.24/28 lte=ok host=up lc=35 dmesg=312 rtc=2987
up=2990.54 clk=09:46:06 MM=1655 rmtfs=1056 qp=1701 tel=615 state=BEARER_CONNECTED wwan0=10.41.212.24/28 lte=ok host=up lc=35 dmesg=312 rtc=2993 mm=connected/home/ bearer1=yes
up=2995.80 clk=09:46:11 MM=1655 rmtfs=1056 qp=1701 tel=615 state=BEARER_CONNECTED wwan0=10.41.212.24/28 lte=ok host=up lc=35 dmesg=312 rtc=2998
up=3000.95 clk=09:46:16 MM=1655 rmtfs=1056 qp=1701 tel=615 state=BEARER_CONNECTED wwan0=10.41.212.24/28 lte=ok host=up lc=35 dmesg=312 rtc=3003
up=3006.11 clk=09:46:22 MM=1655 rmtfs=1056 qp=1701 tel=615 state=BEARER_CONNECTED wwan0=10.41.212.24/28 lte=ok host=up lc=35 dmesg=312 rtc=3008 mm=connected/home/ bearer1=yes
up=3011.36 clk=09:46:27 MM=1655 rmtfs=1056 qp=1701 tel=615 state=BEARER_CONNECTED wwan0=10.41.212.24/28 lte=ok host=up lc=35 dmesg=312 rtc=3013
up=3016.51 clk=09:46:32 MM=1655 rmtfs=1056 qp=1701 tel=615 state=BEARER_CONNECTED wwan0=10.41.212.24/28 lte=ok host=up lc=35 dmesg=312 rtc=3019
up=3021.67 clk=09:46:37 MM=1655 rmtfs=1056 qp=1701 tel=615 state=BEARER_CONNECTED wwan0=10.41.212.24/28 lte=ok host=up lc=35 dmesg=312 rtc=3024 mm=connected/home/ bearer1=yes
up=3026.93 clk=09:46:42 MM=1655 rmtfs=1056 qp=1701 tel=615 state=BEARER_CONNECTED wwan0=10.41.212.24/28 lte=ok host=up lc=35 dmesg=312 rtc=3029
up=3032.08 clk=09:46:48 MM=1655 rmtfs=1056 qp=1701 tel=615 state=BEARER_CONNECTED wwan0=10.41.212.24/28 lte=ok host=up lc=35 dmesg=312 rtc=3034
up=3037.24 clk=09:46:53 MM=1655 rmtfs=1056 qp=1701 tel=615 state=BEARER_CONNECTED wwan0=10.41.212.24/28 lte=ok host=up lc=35 dmesg=312 rtc=3039 mm=connected/home/ bearer1=yes
up=3042.49 clk=09:46:58 MM=1655 rmtfs=1056 qp=1701 tel=615 state=BEARER_CONNECTED wwan0=10.41.212.24/28 lte=ok host=up lc=35 dmesg=312 rtc=3045
up=3047.65 clk=09:47:03 MM=1655 rmtfs=1056 qp=1701 tel=615 state=BEARER_CONNECTED wwan0=10.41.212.24/28 lte=ok host=up lc=35 dmesg=312 rtc=3050
up=3052.79 clk=09:47:08 MM=1655 rmtfs=1056 qp=1701 tel=615 state=BEARER_CONNECTED wwan0=10.41.212.24/28 lte=ok host=up lc=35 dmesg=312 rtc=3055 mm=connected/home/ bearer1=yes
up=3058.05 clk=09:47:14 MM=1655 rmtfs=1056 qp=1701 tel=615 state=BEARER_CONNECTED wwan0=10.41.212.24/28 lte=ok host=up lc=35 dmesg=312 rtc=3060
up=3063.21 clk=09:47:19 MM=1655 rmtfs=1056 qp=1701 tel=615 state=BEARER_CONNECTED wwan0=10.41.212.24/28 lte=ok host=up lc=35 dmesg=312 rtc=3065
up=3068.38 clk=09:47:24 MM=1655 rmtfs=1056 qp=1701 tel=615 state=BEARER_CONNECTED wwan0=10.41.212.24/28 lte=ok host=up lc=35 dmesg=312 rtc=3070 mm=connected/home/ bearer1=yes
up=3073.64 clk=09:47:29 MM=1655 rmtfs=1056 qp=1701 tel=615 state=BEARER_CONNECTED wwan0=10.41.212.24/28 lte=ok host=up lc=35 dmesg=312 rtc=3076
up=3078.79 clk=09:47:34 MM=1655 rmtfs=1056 qp=1701 tel=615 state=BEARER_CONNECTED wwan0=10.41.212.24/28 lte=ok host=up lc=35 dmesg=312 rtc=3081
up=3083.95 clk=09:47:39 MM=1655 rmtfs=1056 qp=1701 tel=615 state=BEARER_CONNECTED wwan0=10.41.212.24/28 lte=ok host=up lc=35 dmesg=312 rtc=3086 mm=connected/home/ bearer1=yes
up=3089.22 clk=09:47:45 MM=1655 rmtfs=1056 qp=1701 tel=615 state=BEARER_CONNECTED wwan0=10.41.212.24/28 lte=ok host=up lc=35 dmesg=312 rtc=3091
up=3094.37 clk=09:47:50 MM=1655 rmtfs=1056 qp=1701 tel=615 state=BEARER_CONNECTED wwan0=10.41.212.24/28 lte=ok host=up lc=35 dmesg=312 rtc=3096
up=3099.55 clk=09:47:55 MM=1655 rmtfs=1056 qp=1701 tel=615 state=BEARER_CONNECTED wwan0=10.41.212.24/28 lte=ok host=up lc=35 dmesg=312 rtc=3102 mm=connected/home/ bearer1=yes
up=3104.81 clk=09:48:00 MM=1655 rmtfs=1056 qp=1701 tel=615 state=BEARER_CONNECTED wwan0=10.41.212.24/28 lte=ok host=up lc=35 dmesg=312 rtc=3107
up=3109.96 clk=09:48:05 MM=1655 rmtfs=1056 qp=1701 tel=615 state=BEARER_CONNECTED wwan0=10.41.212.24/28 lte=ok host=up lc=35 dmesg=312 rtc=3112
=== dmesg since step (from line 309)
[ 2925.810641] [b7b] step plan: N=1790934303 (Fri Oct 2 09:45:03 UTC 2026) local_target=2929.956601 wait_us=1385635
[ 2927.218618] [b7b] date -u -s @1790934303 rc=0 out='Fri Oct 2 09:45:03 UTC 2026' clk_before=2929.968714 clk_after=1790934303.002845 (no hwclock, RTC untouched)
[ 2928.227351] [b7b] post snapshot done; RTC since_epoch before step 2928, now 2930
=== mm-0.log since step (grep time|clock|timeout|error|warn)
[1655]: <dbg> [000000037.794541] [plugin-manager] task 0: extra probing time elapsed
[1655]: <wrn> [000000042.136055] [location-cache] Error loading cached location from /var/lib/ModemManager/location.ini: No such file or directory
[1655]: <dbg> [000000048.917039] [modem0] couldn't load carrier config: Operation timed out
[1655]: <dbg> [000000050.018452] [modem0] slot status retrieval failed: QMI protocol error (94): 'NotSupported'
[1655]: <dbg> [000000051.552255] [modem0/sim0] couldn't load GID1: Couldn't read data from UIM: QMI protocol error (16): 'NotProvisioned'
[1655]: <dbg> [000000051.558170] [modem0/sim0] couldn't load GID2: Couldn't read data from UIM: QMI protocol error (16): 'NotProvisioned'
[1655]: <dbg> [000000051.941247] [modem0] couldn't load list of own numbers: Couldn't get MSISDN: QMI protocol error (16): 'NotProvisioned'
<<<<<< message = "Get Network Time" (0x007D)
<<<<<< message = "Get Network Time" (0x007D)
<<<<<< type = "3GPP Time" (0x11)
<<<<<< translated = [ universal_time = '[ year = '2026' month = '10' day = '2' hour = '8' minute = '57' second = '7' day_of_week = 'friday' ]' timezone_offset = '12' daylight_savings_adjustment = 'none' radio_interface = 'lte' ]
<<<<<< translated = inject-time-request, inject-position-request
[1655]: <dbg> [000000069.372680] [modem0] couldn't enable unsolicited profile management events: QMI protocol error (71): 'InvalidQmiCommand'
[1655]: <dbg> [000000070.417738] [modem0] couldn't read SMS messages: QMI protocol error (17): 'MissingArgument'
[1655]: <dbg> [000000070.423116] [modem0] couldn't read SMS messages: QMI protocol error (52): 'DeviceNotReady'
[1655]: <dbg> [000000070.772808] [modem0] couldn't read SMS messages: QMI protocol error (48): 'InvalidArgument'
[1655]: <dbg> [000000071.112502] [modem0] couldn't read SMS messages: QMI protocol error (48): 'InvalidArgument'
[1655]: <dbg> [000000071.118144] [modem0] couldn't read SMS messages: QMI protocol error (17): 'MissingArgument'
[1655]: <dbg> [000000071.461339] [modem0] couldn't read SMS messages: QMI protocol error (52): 'DeviceNotReady'
[1655]: <dbg> [000000071.811082] [modem0] couldn't read SMS messages: QMI protocol error (48): 'InvalidArgument'
[1655]: <dbg> [000000071.817169] [modem0] couldn't read SMS messages: QMI protocol error (48): 'InvalidArgument'
[1655]: <dbg> [000000071.821993] [modem0/wwan0at1/at] <-- '<CR><LF>+CMS ERROR: 303<CR><LF>'
[1655]: <dbg> [000000071.927544] [modem0/wwan0at0/at] <-- '<CR><LF>+CMS ERROR: 303<CR><LF>'
[1655]: <dbg> [000000071.939381] [modem0] modem has time capabilities, enabling the Time interface...
[1655]: <dbg> [000000072.289994] [modem0] cleaning up extended signal information thresholds: interface enabled, rssi threshold 0 dBm, error rate threshold disabled
[1655]: <dbg> [000000073.689709] [modem0] network timezone polling started
<<<<<< message = "Get Network Time" (0x007D)
<<<<<< message = "Get Network Time" (0x007D)
<<<<<< type = "3GPP Time" (0x11)
<<<<<< translated = [ universal_time = '[ year = '2026' month = '10' day = '2' hour = '8' minute = '57' second = '31' day_of_week = 'friday' ]' timezone_offset = '12' daylight_savings_adjustment = 'none' radio_interface = 'lte' ]
[1655]: <inf> [000001262.938932] [modem0] processing user request to load network time...
<<<<<< message = "Get Network Time" (0x007D)
<<<<<< message = "Get Network Time" (0x007D)
<<<<<< type = "3GPP Time" (0x11)
<<<<<< translated = [ universal_time = '[ year = '2026' month = '10' day = '2' hour = '9' minute = '17' second = '15' day_of_week = 'friday' ]' timezone_offset = '12' daylight_savings_adjustment = 'none' radio_interface = 'lte' ]
[1655]: <inf> [000001355.111653] [modem0] processing user request to load network time...
<<<<<< message = "Get Network Time" (0x007D)
<<<<<< message = "Get Network Time" (0x007D)
<<<<<< type = "3GPP Time" (0x11)
<<<<<< translated = [ universal_time = '[ year = '2026' month = '10' day = '2' hour = '9' minute = '18' second = '48' day_of_week = 'friday' ]' timezone_offset = '12' daylight_savings_adjustment = 'none' radio_interface = 'lte' ]
Reference in a new issue View git blame Copy permalink