diff --git a/exercises/26_Bluetooth_discover/README.md b/exercises/26_Bluetooth_discover/README.md index 1d25217..7ac5993 100644 --- a/exercises/26_Bluetooth_discover/README.md +++ b/exercises/26_Bluetooth_discover/README.md @@ -31,7 +31,8 @@ pio device monitor -b 115200 -p /dev/ttytBOB - Displays heard nodes sorted by rolling RSSI average, strongest first. - Drops stale entries after 20 seconds. - Logs valid accepted advertisements to SD as `/logs/YYYYMMDD_HHMISS_NODE_ble_search.log`. -- Refreshes the receiver GPS position at 1 Hz and logs the last known receiver coordinates plus GPS fix age. Observation rows are written only while the holdover clock and GPS fix age are both valid. +- Refreshes the receiver GPS position at 1 Hz and logs the last known receiver coordinates plus GPS fix age. Observation rows are written while the holdover clock is valid; stale GPS is recorded with `gps_valid=0` instead of suppressing the row. +- Writes periodic `# STATUS` heartbeat lines so a quiet BLE interval can be distinguished from a reset, hang, SD fault, or power interruption. - Starts a WiFi AP and HTTP web service during boot. This does not wait for GPS. Default web addresses: @@ -85,7 +86,7 @@ jlpoole@jp ~/work/tbeam/logs $ ls -lath flo/*_16* jlpoole@jp ~/work/tbeam/logs $ ``` -Here are start and end samples from an earlier trial. These show the previous 12-column schema; current firmware uses the 18-column schema described below. +Here are start and end samples from an earlier trial. These show the previous 12-column schema; current firmware uses the 19-column schema described below. ```bash jlpoole@jp ~/work/tbeam/logs $ cat -n ed/20260525_162217_ED_ble_search.log|head -n 3 1 human_time,epoch_ms,receiver,lat,lon,heard,rssi,avg_rssi,age_s,count,seq,payload @@ -123,6 +124,7 @@ The header represents: | 16 | `seq` | Sequence number advertised by the heard unit. | | 17 | `tx_payload_epoch_ms` | Sender payload generation timestamp from the BLE payload as Unix epoch milliseconds, when available. Legacy v1 payloads report `0` here. | | 18 | `payload` | Raw BLE manufacturer-data string. See Payload Definition below. | +| 19 | `vbat_mv` | Battery voltage reported by the PMU, in millivolts. `-1` means the PMU value was unavailable. | ## Payload definition @@ -165,8 +167,27 @@ Constraints currently enforced by the receiver: BLE survey advertising starts only after startup GPS UTC, GPS coordinates, and PPS-backed RTC discipline have succeeded. Before that point the OLED remains on a blocking GPS/clock status page and the unit does not enter active BLE survey mode. -Observation logging requires both `clock_valid=1` and `gps_valid=1`. The clock uses a holdover model: startup discipline sets `last_discipline_epoch_ms`, and `clock_valid` remains true until `discipline_age_ms` exceeds the configured holdover limit. Temporary GPS loss does not immediately invalidate the clock. GPS validity is tracked separately with `gps_fix_age_ms`; if the fix becomes stale, observation rows are suppressed until GPS freshness returns. +Observation logging requires `clock_valid=1`. The clock uses a holdover model: startup discipline sets `last_discipline_epoch_ms`, and `clock_valid` remains true until `discipline_age_ms` exceeds the configured holdover limit. Temporary GPS loss does not immediately invalidate the clock, and it does not suppress observation rows. GPS validity is tracked separately with `gps_fix_age_ms` and `gps_valid`, so stale-coordinate rows can be filtered later. `rx_epoch_ms` is the receiver's local disciplined-clock time at the moment it writes the observation row. `tx_payload_epoch_ms` is the sender's local disciplined-clock time when it generated and installed that BLE advertising payload. A single payload may be observed many times before the sender replaces it, so `tx_payload_epoch_ms` is useful for correlating logs but is not an RF transmit timestamp. `rx_epoch_ms - tx_payload_epoch_ms` is diagnostic for clock alignment, scheduling, payload age, and repeated-observation behavior. It is not BLE propagation delay. The status fields that prove a row was written under valid survey conditions are `clock_valid`, `gps_valid`, `gps_fix_age_ms`, `discipline_age_ms`, and `last_discipline_epoch_ms`. + +## Event Lines + +Comment-style event lines begin with `# EVENT` and are not normal CSV observation rows. They preserve diagnostic transitions without complicating the ordinary CSV row format. Current event names are: + +- `boot` +- `log_opened` +- `log_closed` +- `gps_stale` +- `gps_fresh` +- `clock_stale` +- `sd_removed` +- `sd_remounted` +- `sd_write_short` +- `sd_write_ok` + +## Status Lines + +Comment-style status lines begin with `# STATUS` and are written about every 10 seconds while the log is open. They are not normal CSV observation rows. They report the unit's clock/GPS state, SD/log state, rows written, heard-node counts, and `vbat_mv`. These heartbeat lines are intended to show whether the firmware was still alive during periods with no BLE observations. diff --git a/exercises/26_Bluetooth_discover/scripts/create_exercise_26_ble_schema.sql b/exercises/26_Bluetooth_discover/scripts/create_exercise_26_ble_schema.sql index a9d1663..b8cb351 100644 --- a/exercises/26_Bluetooth_discover/scripts/create_exercise_26_ble_schema.sql +++ b/exercises/26_Bluetooth_discover/scripts/create_exercise_26_ble_schema.sql @@ -15,12 +15,13 @@ -- -- Current Exercise 26 log format: -- --- human_time,rx_epoch_ms,receiver,rx_lat,rx_lon,rx_gps_age_ms, --- heard,rssi,avg_rssi,age_s,count,seq,tx_epoch_ms,payload +-- human_time,rx_epoch_ms,receiver,rx_lat,rx_lon,gps_fix_age_ms, +-- clock_valid,gps_valid,discipline_age_ms,last_discipline_epoch_ms, +-- heard,rssi,avg_rssi,age_s,count,seq,tx_payload_epoch_ms,payload,vbat_mv -- -- Current payload format: -- --- B2|NODE|SEQ|TX_EPOCH_MS +-- B2|NODE|SEQ|TX_PAYLOAD_EPOCH_MS -- -- Legacy payload format: -- @@ -167,7 +168,11 @@ CREATE TABLE IF NOT EXISTS ble_observation_raw ( receiver TEXT, rx_lat REAL, rx_lon REAL, - rx_gps_age_ms INTEGER, + gps_fix_age_ms INTEGER, + clock_valid INTEGER, + gps_valid INTEGER, + discipline_age_ms INTEGER, + last_discipline_epoch_ms INTEGER, heard TEXT, rssi INTEGER, @@ -175,8 +180,9 @@ CREATE TABLE IF NOT EXISTS ble_observation_raw ( age_s INTEGER, count INTEGER, seq INTEGER, - tx_epoch_ms INTEGER, + tx_payload_epoch_ms INTEGER, payload TEXT, + vbat_mv INTEGER, UNIQUE(log_file_id, source_line_no) ); @@ -216,8 +222,8 @@ CREATE TABLE IF NOT EXISTS ble_observation ( rx_epoch_ms INTEGER NOT NULL, rx_epoch_s REAL NOT NULL, - tx_epoch_ms INTEGER, - tx_epoch_s REAL, + tx_payload_epoch_ms INTEGER, + tx_payload_epoch_s REAL, rx_tx_delta_ms INTEGER, @@ -226,7 +232,12 @@ CREATE TABLE IF NOT EXISTS ble_observation ( rx_lat REAL, rx_lon REAL, - rx_gps_age_ms INTEGER, + gps_fix_age_ms INTEGER, + clock_valid INTEGER, + gps_valid INTEGER, + discipline_age_ms INTEGER, + last_discipline_epoch_ms INTEGER, + vbat_mv INTEGER, rssi INTEGER, avg_rssi INTEGER, @@ -314,9 +325,9 @@ SELECT MAX(rx_lat) - MIN(rx_lat) AS lat_range_deg, MAX(rx_lon) - MIN(rx_lon) AS lon_range_deg, - MIN(rx_gps_age_ms) AS min_rx_gps_age_ms, - AVG(rx_gps_age_ms) AS avg_rx_gps_age_ms, - MAX(rx_gps_age_ms) AS max_rx_gps_age_ms + MIN(gps_fix_age_ms) AS min_gps_fix_age_ms, + AVG(gps_fix_age_ms) AS avg_gps_fix_age_ms, + MAX(gps_fix_age_ms) AS max_gps_fix_age_ms FROM ble_observation GROUP BY trial_id, log_file_id, receiver; @@ -372,8 +383,8 @@ SELECT AVG(rx_tx_delta_ms) AS avg_rx_tx_delta_ms, MAX(rx_tx_delta_ms) AS max_rx_tx_delta_ms FROM ble_observation -WHERE tx_epoch_ms IS NOT NULL - AND tx_epoch_ms > 0 +WHERE tx_payload_epoch_ms IS NOT NULL + AND tx_payload_epoch_ms > 0 GROUP BY trial_id, receiver, heard; -- @@ -393,8 +404,8 @@ SELECT MIN(rx_epoch_ms) AS first_rx_epoch_ms, MAX(rx_epoch_ms) AS last_rx_epoch_ms FROM ble_observation -WHERE tx_epoch_ms IS NOT NULL - AND tx_epoch_ms > 0 +WHERE tx_payload_epoch_ms IS NOT NULL + AND tx_payload_epoch_ms > 0 GROUP BY trial_id, receiver, heard, payload_seq; CREATE VIEW IF NOT EXISTS v_payload_seq_summary AS @@ -423,11 +434,11 @@ SELECT rx_epoch_s, rx_lat, rx_lon, - rx_gps_age_ms, + gps_fix_age_ms, rssi, avg_rssi, payload_seq, - tx_epoch_ms, + tx_payload_epoch_ms, rx_tx_delta_ms FROM ble_observation WHERE rx_lat IS NOT NULL @@ -436,6 +447,29 @@ WHERE rx_lat IS NOT NULL CREATE VIEW IF NOT EXISTS v_map_good_gps_points AS SELECT * FROM v_map_observation_points -WHERE rx_gps_age_ms <= 5000; +WHERE gps_fix_age_ms <= 5000; + + +-- --------------------------------------------------------------------------- +-- v_battery_summary +-- +-- Per receiver battery voltage summary for diagnosing power-related logging +-- interruptions. vbat_mv = -1 means the PMU value was unavailable. +-- --------------------------------------------------------------------------- + +CREATE VIEW IF NOT EXISTS v_battery_summary AS +SELECT + trial_id, + log_file_id, + receiver, + + COUNT(*) AS row_count, + SUM(CASE WHEN vbat_mv IS NOT NULL AND vbat_mv >= 0 THEN 1 ELSE 0 END) AS vbat_sample_count, + + MIN(CASE WHEN vbat_mv >= 0 THEN vbat_mv END) AS min_vbat_mv, + AVG(CASE WHEN vbat_mv >= 0 THEN vbat_mv END) AS avg_vbat_mv, + MAX(CASE WHEN vbat_mv >= 0 THEN vbat_mv END) AS max_vbat_mv +FROM ble_observation +GROUP BY trial_id, log_file_id, receiver; COMMIT; diff --git a/exercises/26_Bluetooth_discover/scripts/import_exercise_26_ble_log.pl b/exercises/26_Bluetooth_discover/scripts/import_exercise_26_ble_log.pl old mode 100644 new mode 100755 index 5cd2d7e..67cab96 --- a/exercises/26_Bluetooth_discover/scripts/import_exercise_26_ble_log.pl +++ b/exercises/26_Bluetooth_discover/scripts/import_exercise_26_ble_log.pl @@ -1,31 +1,29 @@ #!/usr/bin/env perl # $Id$ # $HeadURL$ -# -# Example: -# - =pod - sqlite3 ble_fieldtest_20260525_1945_ed_flo.sqlite < create_exercise_26_ble_schema.sql + Example: + + export DB_BLE=ble_fieldtest_20260526_1859.sqlite + sqlite3 ${DB_BLE} < create_exercise_26_ble_schema.sql + + export LOG_DIR=/home/jlpoole/work/tbeam/logs/20260526_1859 + export BOB_LOG=${LOG_DIR}/20260526_185847_BOB_ble_search.log + export CY_LOG=${LOG_DIR}/20260526_185846_CY_ble_search.log + export ED_LOG=${LOG_DIR}/20260526_185910_ED_ble_search.log + export FLO_LOG=${LOG_DIR}/20260526_185903_FLO_ble_search.log + # smoke test + date; awk -f exercise_26_smoke_test.awk ${BOB_LOG} + date; awk -f exercise_26_smoke_test.awk ${CY_LOG} + date; awk -f exercise_26_smoke_test.awk ${ED_LOG} + date; awk -f exercise_26_smoke_test.awk ${FLO_LOG} + ./import_exercise_26_ble_log.pl \ - --db ble_fieldtest_20260525_1945_ed_flo.sqlite \ - --log "$FLO_LOG" - - ./import_exercise_26_ble_log.pl \ - --db ble_fieldtest_20260525_1945_ed_flo.sqlite \ - --log "$ED_LOG" - - sqlite3 ble_fieldtest_20260526_0334_bob_cy_ed_flo.sqlite < create_exercise_26_ble_schema.sql - export DB_BLE=ble_fieldtest_20260526_0334_bob_cy_ed_flo.sqlite - - export BOB_LOG=/home/jlpoole/work/tbeam/logs/bob/20260526_033431_BOB_ble_search.log - ./import_exercise_26_ble_log.pl \ - --db $DB_BLE \ - --log "$BOB_LOG" + --db ${DB_BLE} \ + --log "${BOB_LOG}" =cut - # Manifest: # # The importer expects a manifest file with the same name as the log plus @@ -33,11 +31,13 @@ # # Example: # flo/20260525_194537_FLO_ble_search.log.manifest +# + =pod Simple key=value format: - trial_name=Peck Cottage ED FLO BLE walk test 20260525_1945 - trial_label=peck_cottage_ed_flo_20260525_1945 + trial_name=Peck Cottage four-unit BLE walk test 20260526_1430 + trial_label=peck_cottage_four_unit_20260526_1430 firmware_exercise=26_Bluetooth_discover firmware_git_commit=unknown field_site=Peck Cottage steps @@ -45,28 +45,12 @@ receiver_role=moving receiver_start_description=upside-down plastic pot at Peck Cottage steps receiver_notes=FLO was hand-carried north and across the street, then returned to base. - test_notes=Two-unit BLE discovery test. ED stationary, FLO moving. - - -An after import smoke test: - -sqlite3 -header -column ble_fieldtest_20260525_1945_ed_flo.sqlite \ - 'SELECT * FROM v_log_file_summary;' - -sqlite3 -header -column ble_fieldtest_20260525_1945_ed_flo.sqlite \ - 'SELECT * FROM v_receiver_gps_summary;' - -sqlite3 -header -column ble_fieldtest_20260525_1945_ed_flo.sqlite \ - 'SELECT * FROM v_link_rssi_summary;' - -sqlite3 -header -column ble_fieldtest_20260525_1945_ed_flo.sqlite \ - 'SELECT * FROM v_rx_tx_timing_summary;' - + test_notes=Four-unit BLE discovery test. ED/BOB stationary, FLO/CY moving. =cut # Purpose: # -# Import Exercise 26 BLE Discovery logs into SQLite. +# Import current 19-column Exercise 26 BLE Discovery logs into SQLite. # # Required Perl modules: # @@ -179,7 +163,7 @@ eval { insert_manifest_kv($dbh, $log_file_id, \%manifest); - import_log_rows( + my $imported_rows = import_log_rows( $dbh, trial_id => $trial_id, log_file_id => $log_file_id, @@ -197,7 +181,8 @@ eval { print " trial_id: $trial_id\n"; print " log_file_id: $log_file_id\n"; print " receiver: $receiver\n"; - print " rows: $log_stats->{source_row_count}\n"; + print " rows scanned: $log_stats->{source_row_count}\n"; + print " rows imported:$imported_rows\n"; print " sha256: $sha256\n"; }; @@ -217,12 +202,16 @@ Usage: $0 --db DATABASE.sqlite --log path/to/log.csv Example: - $0 --db ble_fieldtest_20260525_1945_ed_flo.sqlite --log "\$FLO_LOG" + $0 --db ble_fieldtest_YYYYMMDD_HHMM.sqlite --log "\$FLO_LOG" The importer expects a manifest beside the log: path/to/log.csv.manifest +This importer expects the current 19-column Exercise 26 header: + + human_time,rx_epoch_ms,receiver,rx_lat,rx_lon,gps_fix_age_ms,clock_valid,gps_valid,discipline_age_ms,last_discipline_epoch_ms,heard,rssi,avg_rssi,age_s,count,seq,tx_payload_epoch_ms,payload,vbat_mv + EOF } @@ -291,28 +280,26 @@ sub scan_log_for_stats { open my $fh, '<', $path or die "Could not open log $path: $!\n"; - my $header = <$fh>; - die "Empty log file: $path\n" unless defined $header; - - chomp $header; - $header =~ s/\r\z//; - - my @cols = split /,/, $header, -1; - validate_header(@cols); + my ($header, $header_line_no) = read_and_validate_log_header($fh, $path); my $row_count = 0; my $receiver; my $first_rx_epoch_ms; my $last_rx_epoch_ms; + my $line_no = $header_line_no; + while (my $line = <$fh>) { + $line_no++; chomp $line; $line =~ s/\r\z//; next if $line =~ /^\s*$/; + next if $line =~ /^\s*#/; + next if $line eq $header; my @f = split /,/, $line, -1; - next unless @f >= 14; + next unless @f == 19; $row_count++; @@ -337,6 +324,38 @@ sub scan_log_for_stats { }; } +sub read_and_validate_log_header { + my ($fh, $path) = @_; + + my $line_no = 0; + my $header; + + while (my $line = <$fh>) { + $line_no++; + chomp $line; + $line =~ s/\r\z//; + + next if $line =~ /^\s*$/; + + if ($line =~ /^\#\s*fields=(.*)\z/) { + $header = $1; + last; + } + + next if $line =~ /^\s*#/; + + $header = $line; + last; + } + + die "Could not find CSV header in log file: $path\n" + unless defined $header && $header ne ''; + + validate_header(split /,/, $header, -1); + + return ($header, $line_no); +} + sub validate_header { my (@cols) = @_; @@ -346,22 +365,27 @@ sub validate_header { receiver rx_lat rx_lon - rx_gps_age_ms + gps_fix_age_ms + clock_valid + gps_valid + discipline_age_ms + last_discipline_epoch_ms heard rssi avg_rssi age_s count seq - tx_epoch_ms + tx_payload_epoch_ms payload + vbat_mv ); - die "Unexpected column count in header. Expected 14, got " . scalar(@cols) . "\n" + die __LINE__." Unexpected column count in header. Expected 19, got " . scalar(@cols) . "\n" unless @cols == @expected; for my $i (0 .. $#expected) { - die "Unexpected header column " . ($i + 1) . ". Expected '$expected[$i]', got '$cols[$i]'\n" + die __LINE__." Unexpected header column " . ($i + 1) . ". Expected '$expected[$i]', got '$cols[$i]'\n" unless $cols[$i] eq $expected[$i]; } } @@ -485,12 +509,7 @@ sub import_log_rows { open my $fh, '<', $log_file or die "Could not open log $log_file: $!\n"; - my $header = <$fh>; - die "Empty log file: $log_file\n" unless defined $header; - - chomp $header; - $header =~ s/\r\z//; - validate_header(split /,/, $header, -1); + my ($header, $header_line_no) = read_and_validate_log_header($fh, $log_file); my $raw_sth = $dbh->prepare(q{ INSERT INTO ble_observation_raw ( @@ -502,17 +521,22 @@ sub import_log_rows { receiver, rx_lat, rx_lon, - rx_gps_age_ms, + gps_fix_age_ms, + clock_valid, + gps_valid, + discipline_age_ms, + last_discipline_epoch_ms, heard, rssi, avg_rssi, age_s, count, seq, - tx_epoch_ms, - payload + tx_payload_epoch_ms, + payload, + vbat_mv ) - VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?) + VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?) }); my $obs_sth = $dbh->prepare(q{ @@ -523,14 +547,19 @@ sub import_log_rows { source_line_no, rx_epoch_ms, rx_epoch_s, - tx_epoch_ms, - tx_epoch_s, + tx_payload_epoch_ms, + tx_payload_epoch_s, rx_tx_delta_ms, receiver, heard, rx_lat, rx_lon, - rx_gps_age_ms, + gps_fix_age_ms, + clock_valid, + gps_valid, + discipline_age_ms, + last_discipline_epoch_ms, + vbat_mv, rssi, avg_rssi, age_s, @@ -544,10 +573,10 @@ sub import_log_rows { payload_legacy_uptime, parse_warning ) - VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?) + VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?) }); - my $line_no = 1; + my $line_no = $header_line_no; my $data_rows = 0; while (my $line = <$fh>) { @@ -556,26 +585,33 @@ sub import_log_rows { $line =~ s/\r\z//; next if $line =~ /^\s*$/; + next if $line =~ /^\s*#/; + next if $line eq $header; my @f = split /,/, $line, -1; - die "Line $line_no has too few columns. Expected 14, got " . scalar(@f) . "\n" - unless @f >= 14; + die "Line $line_no has wrong column count. Expected 19, got " . scalar(@f) . "\n" + unless @f == 19; - my $human_time = $f[0]; - my $rx_epoch_ms = to_int_or_undef($f[1]); - my $receiver = $f[2]; - my $rx_lat = to_num_or_undef($f[3]); - my $rx_lon = to_num_or_undef($f[4]); - my $rx_gps_age_ms = to_int_or_undef($f[5]); - my $heard = $f[6]; - my $rssi = to_int_or_undef($f[7]); - my $avg_rssi = to_int_or_undef($f[8]); - my $age_s = to_int_or_undef($f[9]); - my $count = to_int_or_undef($f[10]); - my $seq = to_int_or_undef($f[11]); - my $tx_epoch_ms = to_int_or_undef($f[12]); - my $payload = $f[13]; + my $human_time = $f[0]; + my $rx_epoch_ms = to_int_or_undef($f[1]); + my $receiver = $f[2]; + my $rx_lat = to_num_or_undef($f[3]); + my $rx_lon = to_num_or_undef($f[4]); + my $gps_fix_age_ms = to_int_or_undef($f[5]); + my $clock_valid = to_int_or_undef($f[6]); + my $gps_valid = to_int_or_undef($f[7]); + my $discipline_age_ms = to_int_or_undef($f[8]); + my $last_discipline_epoch_ms = to_int_or_undef($f[9]); + my $heard = $f[10]; + my $rssi = to_int_or_undef($f[11]); + my $avg_rssi = to_int_or_undef($f[12]); + my $age_s = to_int_or_undef($f[13]); + my $count = to_int_or_undef($f[14]); + my $seq = to_int_or_undef($f[15]); + my $tx_payload_epoch_ms = to_int_or_undef($f[16]); + my $payload = $f[17]; + my $vbat_mv = to_int_or_undef($f[18]); die "Line $line_no has no rx_epoch_ms\n" unless defined $rx_epoch_ms; @@ -586,6 +622,12 @@ sub import_log_rows { die "Line $line_no has no heard unit\n" unless defined $heard && $heard ne ''; + die "Line $line_no has invalid clock_valid value\n" + unless defined $clock_valid && ($clock_valid == 0 || $clock_valid == 1); + + die "Line $line_no has invalid gps_valid value\n" + unless defined $gps_valid && ($gps_valid == 0 || $gps_valid == 1); + upsert_unit($dbh, $receiver); upsert_unit($dbh, $heard); @@ -598,15 +640,20 @@ sub import_log_rows { $receiver, $rx_lat, $rx_lon, - $rx_gps_age_ms, + $gps_fix_age_ms, + $clock_valid, + $gps_valid, + $discipline_age_ms, + $last_discipline_epoch_ms, $heard, $rssi, $avg_rssi, $age_s, $count, $seq, - $tx_epoch_ms, + $tx_payload_epoch_ms, $payload, + $vbat_mv, ); my $raw_id = $dbh->sqlite_last_insert_rowid; @@ -615,12 +662,31 @@ sub import_log_rows { my $rx_epoch_s = $rx_epoch_ms / 1000.0; - my $tx_epoch_s; - my $rx_tx_delta_ms; + my $tx_payload_epoch_s; + my $rx_tx_payload_delta_ms; - if (defined $tx_epoch_ms && $tx_epoch_ms > 0) { - $tx_epoch_s = $tx_epoch_ms / 1000.0; - $rx_tx_delta_ms = $rx_epoch_ms - $tx_epoch_ms; + if (defined $tx_payload_epoch_ms && $tx_payload_epoch_ms > 0) { + $tx_payload_epoch_s = $tx_payload_epoch_ms / 1000.0; + $rx_tx_payload_delta_ms = $rx_epoch_ms - $tx_payload_epoch_ms; + } + + if (defined $parsed->{payload_node} + && $parsed->{payload_node} ne '' + && $parsed->{payload_node} ne $heard) { + $parsed->{parse_warning} = append_warning( + $parsed->{parse_warning}, + "payload node '$parsed->{payload_node}' does not match heard '$heard'" + ); + } + + if (defined $parsed->{payload_tx_payload_epoch_ms} + && defined $tx_payload_epoch_ms + && $parsed->{payload_tx_payload_epoch_ms} != $tx_payload_epoch_ms + && $tx_payload_epoch_ms != 0) { + $parsed->{parse_warning} = append_warning( + $parsed->{parse_warning}, + "payload epoch does not match tx_payload_epoch_ms column" + ); } $obs_sth->execute( @@ -630,14 +696,19 @@ sub import_log_rows { $line_no, $rx_epoch_ms, $rx_epoch_s, - $tx_epoch_ms, - $tx_epoch_s, - $rx_tx_delta_ms, + $tx_payload_epoch_ms, + $tx_payload_epoch_s, + $rx_tx_payload_delta_ms, $receiver, $heard, $rx_lat, $rx_lon, - $rx_gps_age_ms, + $gps_fix_age_ms, + $clock_valid, + $gps_valid, + $discipline_age_ms, + $last_discipline_epoch_ms, + $vbat_mv, $rssi, $avg_rssi, $age_s, @@ -647,7 +718,7 @@ sub import_log_rows { $parsed->{payload_kind}, $parsed->{payload_node}, $parsed->{payload_seq}, - $parsed->{payload_tx_epoch_ms}, + $parsed->{payload_tx_payload_epoch_ms}, $parsed->{payload_legacy_uptime}, $parsed->{parse_warning}, ); @@ -664,12 +735,12 @@ sub parse_payload { my ($payload) = @_; my %p = ( - payload_kind => undef, - payload_node => undef, - payload_seq => undef, - payload_tx_epoch_ms => undef, - payload_legacy_uptime => undef, - parse_warning => undef, + payload_kind => undef, + payload_node => undef, + payload_seq => undef, + payload_tx_payload_epoch_ms => undef, + payload_legacy_uptime => undef, + parse_warning => undef, ); if (!defined $payload || $payload eq '') { @@ -680,16 +751,16 @@ sub parse_payload { my @parts = split /\|/, $payload, -1; if (@parts == 4 && $parts[0] eq 'B2') { - $p{payload_kind} = 'B2'; - $p{payload_node} = $parts[1]; - $p{payload_seq} = to_int_or_undef($parts[2]); - $p{payload_tx_epoch_ms} = to_int_or_undef($parts[3]); + $p{payload_kind} = 'B2'; + $p{payload_node} = $parts[1]; + $p{payload_seq} = to_int_or_undef($parts[2]); + $p{payload_tx_payload_epoch_ms} = to_int_or_undef($parts[3]); if (!defined $p{payload_seq}) { $p{parse_warning} = 'B2 payload seq was not numeric'; } - elsif (!defined $p{payload_tx_epoch_ms}) { - $p{parse_warning} = 'B2 payload tx_epoch_ms was not numeric'; + elsif (!defined $p{payload_tx_payload_epoch_ms}) { + $p{parse_warning} = 'B2 payload tx_payload_epoch_ms was not numeric'; } return \%p; @@ -715,6 +786,13 @@ sub parse_payload { return \%p; } +sub append_warning { + my ($old, $new) = @_; + + return $new unless defined $old && $old ne ''; + return "$old; $new"; +} + sub update_trial_time_bounds { my ($dbh, $trial_id) = @_; diff --git a/exercises/26_Bluetooth_discover/src/main.cpp b/exercises/26_Bluetooth_discover/src/main.cpp index 7e518d5..3e898dd 100644 --- a/exercises/26_Bluetooth_discover/src/main.cpp +++ b/exercises/26_Bluetooth_discover/src/main.cpp @@ -30,6 +30,7 @@ #include #include #include +#include #include #include #include @@ -71,10 +72,11 @@ static constexpr uint32_t kDisplayPeriodMs = 1000; static constexpr uint32_t kAdvertisePeriodMs = 1000; static constexpr uint32_t kScanPeriodMs = 2500; static constexpr uint32_t kScanWindowSeconds = 2; -static constexpr uint32_t kLogFlushPeriodMs = 5000; +static constexpr uint32_t kLogFlushPeriodMs = 1000; +static constexpr uint32_t kStatusLogPeriodMs = 10000; static constexpr uint32_t kStartupStatusPeriodMs = 1000; static constexpr uint32_t kGpsRefreshPeriodMs = 1000; -static constexpr uint32_t kMaxGpsFixAgeMs = 5000; +static constexpr uint32_t kMaxGpsFixAgeMs = 30000; static constexpr uint32_t kMaxDisciplineAgeMs = 4UL * 60UL * 60UL * 1000UL; static constexpr uint8_t kRssiWindow = 5; @@ -119,6 +121,10 @@ bool g_sdReady = false; bool g_logReady = false; bool g_webReady = false; bool g_buttonWasPressed = false; +bool g_prevGpsValid = false; +bool g_prevClockValid = false; +bool g_statusInitialized = false; +bool g_lastWriteOk = true; uint8_t g_displayMode = 0; uint32_t g_sequence = 0; volatile uint32_t g_ppsEdgeCount = 0; @@ -127,7 +133,9 @@ uint32_t g_lastAdvertiseMs = 0; uint32_t g_lastScanMs = 0; uint32_t g_lastDisplayMs = 0; uint32_t g_lastFlushMs = 0; +uint32_t g_lastStatusLogMs = 0; uint32_t g_lastGpsRefreshMs = 0; +uint32_t g_rowsWritten = 0; int64_t g_epochBase = 0; uint32_t g_epochBaseMs = 0; int64_t g_lastDisciplineEpochMs = 0; @@ -217,8 +225,118 @@ bool gpsValidNow(uint32_t now) { return g_hasLocation && gpsAgeMs(now) <= kMaxGpsFixAgeMs; } -bool fieldDataValid(uint32_t now) { - return clockValidNow(now) && gpsValidNow(now); +int batteryMillivolts() { + if (!g_pmu) { + return -1; + } + return (int)g_pmu->getBattVoltage(); +} + +uint8_t heardTotal() { + uint8_t count = 0; + for (size_t i = 0; i < sizeof(g_nodes) / sizeof(g_nodes[0]); ++i) { + if (!g_nodes[i].self && g_nodes[i].heard) { + ++count; + } + } + return count; +} + +uint8_t heardFresh(uint32_t now) { + uint8_t count = 0; + for (size_t i = 0; i < sizeof(g_nodes) / sizeof(g_nodes[0]); ++i) { + if (!g_nodes[i].self && freshEnough(g_nodes[i], now)) { + ++count; + } + } + return count; +} + +void emitEvent(const char* event, const char* extra = nullptr) { + char line[256]; + const int64_t epochMs = currentEpochMs(); + const int n = snprintf(line, + sizeof(line), + "# EVENT epoch_ms=%lld ms=%lu unit=%s event=%s vbat_mv=%d%s%s", + (long long)epochMs, + (unsigned long)millis(), + NODE_NAME, + event ? event : "unknown", + batteryMillivolts(), + (extra && extra[0]) ? " " : "", + (extra && extra[0]) ? extra : ""); + Serial.println(line); + if (n > 0 && g_logReady && g_storage.isLogOpen()) { + g_storage.println(line); + } +} + +void emitStatus(bool force = false) { + const uint32_t now = millis(); + if (!force && (uint32_t)(now - g_lastStatusLogMs) < kStatusLogPeriodMs) { + return; + } + g_lastStatusLogMs = now; + + const bool clockValid = clockValidNow(now); + const bool gpsValid = gpsValidNow(now); + char line[256]; + const int n = snprintf(line, + sizeof(line), + "# STATUS epoch_ms=%lld ms=%lu unit=%s clock_valid=%u gps_valid=%u gps_fix_age_ms=%lu discipline_age_ms=%lu last_discipline_epoch_ms=%lld sd_ready=%u log_ready=%u rows_written=%lu heard_total=%u heard_fresh=%u vbat_mv=%d", + (long long)currentEpochMs(), + (unsigned long)now, + NODE_NAME, + clockValid ? 1U : 0U, + gpsValid ? 1U : 0U, + (unsigned long)gpsAgeMs(now), + (unsigned long)disciplineAgeMs(now), + (long long)g_lastDisciplineEpochMs, + g_storage.ready() ? 1U : 0U, + (g_logReady && g_storage.isLogOpen()) ? 1U : 0U, + (unsigned long)g_rowsWritten, + heardTotal(), + heardFresh(now), + batteryMillivolts()); + Serial.println(line); + if (n > 0 && g_logReady && g_storage.isLogOpen()) { + const size_t expected = (size_t)n + 1U; + const size_t wrote = g_storage.println(line); + if (wrote != expected && g_lastWriteOk) { + char extra[96]; + snprintf(extra, sizeof(extra), "bytes_expected=%lu bytes_written=%lu", (unsigned long)expected, (unsigned long)wrote); + emitEvent("sd_write_short", extra); + g_lastWriteOk = false; + } + } +} + +void pollStatusEvents() { + const uint32_t now = millis(); + const bool clockValid = clockValidNow(now); + const bool gpsValid = gpsValidNow(now); + if (!g_statusInitialized) { + g_statusInitialized = true; + g_prevClockValid = clockValid; + g_prevGpsValid = gpsValid; + return; + } + if (g_prevGpsValid && !gpsValid) { + char extra[80]; + snprintf(extra, sizeof(extra), "gps_fix_age_ms=%lu", (unsigned long)gpsAgeMs(now)); + emitEvent("gps_stale", extra); + } else if (!g_prevGpsValid && gpsValid) { + char extra[80]; + snprintf(extra, sizeof(extra), "gps_fix_age_ms=%lu", (unsigned long)gpsAgeMs(now)); + emitEvent("gps_fresh", extra); + } + if (g_prevClockValid && !clockValid) { + char extra[96]; + snprintf(extra, sizeof(extra), "discipline_age_ms=%lu", (unsigned long)disciplineAgeMs(now)); + emitEvent("clock_stale", extra); + } + g_prevGpsValid = gpsValid; + g_prevClockValid = clockValid; } void refreshGpsPosition(bool force = false) { @@ -405,7 +523,7 @@ bool disciplineStartupClock() { } bool openDatedLog() { - if (!fieldDataValid(millis()) || !g_storage.ready()) { + if (!clockValidNow(millis()) || !g_hasLocation || !g_storage.ready()) { return false; } char stamp[24]; @@ -419,10 +537,16 @@ bool openDatedLog() { Serial.printf("sd_log_open_failed path=%s err=%s\n", g_logPath, g_storage.lastError()); return false; } - g_storage.println("human_time,rx_epoch_ms,receiver,rx_lat,rx_lon,gps_fix_age_ms,clock_valid,gps_valid,discipline_age_ms,last_discipline_epoch_ms,heard,rssi,avg_rssi,age_s,count,seq,tx_payload_epoch_ms,payload"); + g_storage.println("# schema_version=2"); + g_storage.println("# fields=human_time,rx_epoch_ms,receiver,rx_lat,rx_lon,gps_fix_age_ms,clock_valid,gps_valid,discipline_age_ms,last_discipline_epoch_ms,heard,rssi,avg_rssi,age_s,count,seq,tx_payload_epoch_ms,payload,vbat_mv"); + g_storage.println("human_time,rx_epoch_ms,receiver,rx_lat,rx_lon,gps_fix_age_ms,clock_valid,gps_valid,discipline_age_ms,last_discipline_epoch_ms,heard,rssi,avg_rssi,age_s,count,seq,tx_payload_epoch_ms,payload,vbat_mv"); g_storage.flush(); Serial.printf("sd_log_open path=%s\n", g_logPath); g_logReady = true; + char extra[160]; + snprintf(extra, sizeof(extra), "reset_reason=%d logfile=%s", (int)esp_reset_reason(), g_logPath); + emitEvent("log_opened", extra); + emitStatus(true); return true; } @@ -538,7 +662,7 @@ void logAcceptedAdvertisement(const NodeState& node, const char* payload) { const uint32_t fixAge = gpsAgeMs(now); const bool gpsValid = gpsValidNow(now); const uint32_t discAge = disciplineAgeMs(now); - if (!clockValid || !gpsValid) { + if (!clockValid) { static uint32_t lastSuppressedMs = 0; if ((uint32_t)(now - lastSuppressedMs) >= 1000U) { lastSuppressedMs = now; @@ -574,28 +698,42 @@ void logAcceptedAdvertisement(const NodeState& node, const char* payload) { if (g_logReady && g_storage.isLogOpen()) { char line[320]; - snprintf(line, - sizeof(line), - "%s,%lld,%s,%.7f,%.7f,%lu,%u,%u,%lu,%lld,%s,%d,%d,%lu,%lu,%lu,%lld,%s", - human, - (long long)epochMs, - NODE_NAME, - g_latitude, - g_longitude, - (unsigned long)fixAge, - clockValid ? 1U : 0U, - gpsValid ? 1U : 0U, - (unsigned long)discAge, - (long long)g_lastDisciplineEpochMs, - node.name, - node.lastRssi, - avg, - (unsigned long)age, - (unsigned long)node.seenCount, - (unsigned long)node.lastSeq, - (long long)node.lastTxPayloadEpochMs, - payload); - g_storage.println(line); + const int n = snprintf(line, + sizeof(line), + "%s,%lld,%s,%.7f,%.7f,%lu,%u,%u,%lu,%lld,%s,%d,%d,%lu,%lu,%lu,%lld,%s,%d", + human, + (long long)epochMs, + NODE_NAME, + g_latitude, + g_longitude, + (unsigned long)fixAge, + clockValid ? 1U : 0U, + gpsValid ? 1U : 0U, + (unsigned long)discAge, + (long long)g_lastDisciplineEpochMs, + node.name, + node.lastRssi, + avg, + (unsigned long)age, + (unsigned long)node.seenCount, + (unsigned long)node.lastSeq, + (long long)node.lastTxPayloadEpochMs, + payload, + batteryMillivolts()); + const size_t expected = n > 0 ? (size_t)n + 1U : 0U; + const size_t wrote = n > 0 ? g_storage.println(line) : 0U; + const bool writeOk = expected > 0 && wrote == expected; + if (!writeOk && g_lastWriteOk) { + char extra[96]; + snprintf(extra, sizeof(extra), "bytes_expected=%lu bytes_written=%lu", (unsigned long)expected, (unsigned long)wrote); + emitEvent("sd_write_short", extra); + } else if (writeOk && !g_lastWriteOk) { + emitEvent("sd_write_ok"); + } + g_lastWriteOk = writeOk; + if (writeOk) { + ++g_rowsWritten; + } } } @@ -684,19 +822,12 @@ void renderDisplay() { char title[32]; makeTitle(title, sizeof(title)); const bool clockValid = clockValidNow(now); - const uint32_t fixAge = gpsAgeMs(now); const bool gpsValid = gpsValidNow(now); if (!clockValid) { showLines(title, "CLOCK STALE", "BLE survey paused", "logging paused"); return; } - if (!gpsValid) { - char ageLine[32]; - snprintf(ageLine, sizeof(ageLine), "gps age:%lus", fixAge == UINT32_MAX ? 9999UL : (unsigned long)(fixAge / 1000UL)); - showLines(title, "GPS STALE", ageLine, "logging paused"); - return; - } if (g_displayMode == 1) { char rows[5][32] = {}; @@ -769,6 +900,8 @@ void renderDisplay() { void pollStorageWeb() { g_storage.update(); if (g_storage.consumeRemovedEvent()) { + emitEvent("log_closed"); + emitEvent("sd_removed"); g_sdReady = false; g_logReady = false; g_logPath[0] = '\0'; @@ -776,9 +909,10 @@ void pollStorageWeb() { } if (g_storage.consumeMountedEvent()) { g_sdReady = true; + emitEvent("sd_remounted"); Serial.println("sd_mounted"); } - if (fieldDataValid(millis()) && g_storage.ready() && !g_logReady) { + if (clockValidNow(millis()) && g_hasLocation && g_storage.ready() && !g_logReady) { g_sdReady = true; g_logReady = openDatedLog(); } @@ -789,6 +923,9 @@ void pollStorageWeb() { g_lastFlushMs = millis(); g_storage.flush(); } + if (g_logReady) { + emitStatus(); + } } } // namespace @@ -801,6 +938,9 @@ void setup() { g_display.begin(); showBootScreen("PMU/OLED ready"); printBootBanner(); + char bootExtra[48]; + snprintf(bootExtra, sizeof(bootExtra), "reset_reason=%d", (int)esp_reset_reason()); + emitEvent("boot", bootExtra); markSelfNode(); pinMode(BUTTON_PIN, INPUT_PULLUP); @@ -825,6 +965,7 @@ void setup() { void loop() { g_gnss.poll(); refreshGpsPosition(); + pollStatusEvents(); pollButton(); pollStorageWeb(); if (g_bleStarted) {