Log why a picture got no thermal frame

Every miss now says how old the newest frame was and whether a NUC was
running; every pause over 500 ms in the frame stream is logged with the
camera's own clock, the polls and getdata answers in it, and NUC_INPROGRESS,
which is watched on every poll; a summary of the stream goes out every ten
minutes, and the NUC configuration at connect. Adds the SDK's NUC parameters
(410-415), for running the NUC on purpose later.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

include/fgc/IrbgrabApi.h

@@ -58,8 +58,16 @@ inline constexpr uint32_t kCameraTempHousing     = 217;   // Kelvin
 inline constexpr uint32_t kFramerateHz           = 240;
 inline constexpr uint32_t kFrameWidth            = 294;
 inline constexpr uint32_t kFrameHeight           = 295;
+// Non-uniformity correction, done in the camera with its own shutter.
+inline constexpr uint32_t kNucActive             = 410;   // R bool: correction applied
+inline constexpr uint32_t kNucPerform            = 411;   // W Int2 {mode, flags}: run one now
+inline constexpr uint32_t kNucInProgress         = 412;   // R bool
+inline constexpr uint32_t kNucInterval           = 415;   // R/W s between automatic ones, 0 = off
 }  // namespace param
 
+// kNucPerform's mode (Int2::value1); value2 takes flags, 0 for none.
+inline constexpr int32_t kNucMode1Point = 2;
+
 #pragma pack(push, 1)
 struct String {
     char*   text;
@@ -73,6 +81,10 @@ struct IdxInt32 {
     int32_t index;
     int32_t value;
 };
+struct Int2 {
+    int32_t value1;
+    int32_t value2;
+};
 // Per-frame information (mem_getinfo). struct_size must be set before the call.
 struct MemInfo {
     int32_t struct_size;
@@ -89,12 +101,14 @@ inline constexpr uint32_t kBaseInt64   = 0x50000000;
 inline constexpr uint32_t kBaseFloat32 = 0xA0000000;
 inline constexpr uint32_t kBaseString  = 0xF0000000;
 inline constexpr uint32_t kExIndex     = 0x01000000;
+inline constexpr uint32_t kExArray2    = 0x02020000;   // a pair
 inline constexpr uint32_t kTypeInt32     = kBaseInt32 | sizeof(int32_t);
 inline constexpr uint32_t kTypeInt64     = kBaseInt64 | sizeof(int64_t);
 inline constexpr uint32_t kTypeSingle    = kBaseFloat32 | sizeof(float);
 inline constexpr uint32_t kTypeString    = kBaseString | sizeof(String);
 inline constexpr uint32_t kTypeIdxString = kExIndex | kBaseString | sizeof(IdxString);
 inline constexpr uint32_t kTypeIdxInt32  = kExIndex | kBaseInt32 | sizeof(IdxInt32);
+inline constexpr uint32_t kType2Int32    = kExArray2 | kBaseInt32 | sizeof(Int2);
 
 // The entry points, as function pointers so a test can stand in for the SDK.
 struct Api {

src/camera/TarisCameraSource.cpp

@@ -13,6 +13,7 @@
 #include <deque>
 #include <clocale>
 #include <fstream>
+#include <map>
 #include <mutex>
 #include <sstream>
 #include <thread>
@@ -70,6 +71,11 @@ private:
 
 constexpr long long kLogEveryMs       = 60000;   // repeated trouble: one line a minute
 constexpr long long kTelemetryEveryMs = 5000;
+// Diagnostics for pictures that get no thermal frame: a pause in the frame
+// stream this long is logged with what the camera said meanwhile, and a summary
+// of the stream goes out this often.
+constexpr long long kGapLogMs         = 500;
+constexpr long long kSummaryEveryMs   = 600000;
 
 }  // namespace
 
@@ -127,6 +133,19 @@ struct TarisCameraSource::Impl {
     bool        zeros_logged      = false;
     std::string last_offline_logged;
 
+    // Stream diagnostics (see kGapLogMs). Since the last frame taken:
+    double      last_cam_ts       = -1.0;  // its MemInfo time, ms
+    long long   polls_since_frame = 0;
+    std::map<Ret, int> codes_since_frame;  // getdata answers other than a new frame
+    bool        nuc_in_gap        = false; // NUC_INPROGRESS seen set meanwhile
+    // NUC_INPROGRESS, read on every poll; -1 = the camera does not answer it.
+    int         nuc_state         = 0;
+    long long   nuc_started_ms    = 0;
+    // For the summary:
+    long long   sum_frames = 0, sum_gaps = 0, sum_nucs = 0, sum_max_gap = 0;
+    double      sum_cam_span      = 0.0;   // camera clock covered by sum_frames
+    long long   sum_since_ms      = 0;
+
     // ---- shared, under m -------------------------------------------------
     std::mutex              m;
     std::condition_variable cv;
@@ -137,14 +156,15 @@ struct TarisCameraSource::Impl {
     CameraDeviceInfo        info;
     std::deque<long long>   arrivals;      // steady ms of recent frames, for fps
     long long               missed_shots  = 0;
-    long long               missed_logged_ms = 0;
-    long long               missed_since_log = 0;
     long long               packets_lost  = 0;
     int                     cal_wanted    = -1;   // a pending setFeature("CalibProfile")
     bool                    cal_done      = false;
     bool                    cal_ok        = false;
     bool                    reset_wanted  = false;
     uint64_t                connects      = 0;
+    bool                    nuc_now       = false;  // NUC_INPROGRESS at the last poll
+    long long               nuc_now_since = 0;      // steady ms it went on
+    long long               missed_window = 0;      // misses since the last summary
 
     std::atomic<bool> running{false};
     std::atomic<bool> gate{false};
@@ -407,9 +427,21 @@ struct TarisCameraSource::Impl {
             if (!model.empty()) info.model = model;
             ++connects;
         }
+        int32_t nuc_active = -1, nuc_interval = -1;
+        getInt32(param::kNucActive, nuc_active);
+        getInt32(param::kNucInterval, nuc_interval);
+        LOG_INFO << "thermal camera: NUC " << (nuc_active == 1 ? "on" : nuc_active == 0 ? "off" : "?")
+                 << ", automatic every "
+                 << (nuc_interval > 0 ? std::to_string(nuc_interval) + " s"
+                                      : nuc_interval == 0 ? std::string("- (off)") : "?");
+
         kpc               = 0.0;
         scale_tries       = 0;
         last_sdk_ts       = -1.0;
+        last_cam_ts       = -1.0;
+        polls_since_frame = 0;
+        codes_since_frame.clear();
+        nuc_in_gap        = false;
         zeros_logged      = false;
         last_frame_steady = steadyMs();   // grace for the first frame
         return true;
@@ -418,12 +450,15 @@ struct TarisCameraSource::Impl {
     // ---- frames ------------------------------------------------------------
     // Take the newest frame from the SDK, if there is one.
     void poll() {
+        ++polls_since_frame;
+        watchNuc();
         // As before every getdata in the vendor's examples: without it the SDK
         // now and then answers 0x80000001 instead of a frame.
         setInt32(param::kPollingEnable, 1);
         Handle mem = 0;
         const Ret r = api->dev_getdata(dev, kMemIrDigitFrame, &mem);
         if (!ok(r)) {
+            ++codes_since_frame[r];
             if (r == kErrNucOrLicence) {
                 ++nuc_or_licence;
                 const long long now = steadyMs();
@@ -461,7 +496,10 @@ struct TarisCameraSource::Impl {
             mi.image_num    = -1;
             mi.timestamp_ms = -1.0;
         }
-        if (mi.timestamp_ms >= 0.0 && mi.timestamp_ms == last_sdk_ts) return;   // seen it
+        if (mi.timestamp_ms >= 0.0 && mi.timestamp_ms == last_sdk_ts) {   // seen it
+            ++codes_since_frame[kSuccess];
+            return;
+        }
         last_sdk_ts = mi.timestamp_ms;
 
         const auto* counts = reinterpret_cast<const uint16_t*>(ptr);
@@ -493,6 +531,7 @@ struct TarisCameraSource::Impl {
         f.thermal          = t;
 
         const long long now = steadyMs();
+        noteFrame(now, mi.timestamp_ms);
         last_frame_steady   = now;
         {
             std::lock_guard<std::mutex> l(m);
@@ -545,6 +584,82 @@ struct TarisCameraSource::Impl {
         }
     }
 
+    // NUC_INPROGRESS on every poll: when the camera corrects itself, and for how
+    // long - the prime suspect for a picture without a thermal frame.
+    void watchNuc() {
+        if (nuc_state < 0) return;
+        int32_t v = 0;
+        if (!getInt32(param::kNucInProgress, v)) {
+            LOG_INFO << "thermal camera: NUC_INPROGRESS not readable; NUC timing not logged";
+            nuc_state = -1;
+            return;
+        }
+        const long long now = steadyMs();
+        const int       on  = v != 0;
+        if (on) nuc_in_gap = true;
+        if (on && !nuc_state) {
+            nuc_started_ms = now;
+            ++sum_nucs;
+            LOG_INFO << "thermal camera: NUC started";
+        } else if (!on && nuc_state) {
+            LOG_INFO << "thermal camera: NUC finished after " << now - nuc_started_ms << " ms";
+        }
+        if (on != nuc_state) {
+            std::lock_guard<std::mutex> l(m);
+            nuc_now       = on;
+            nuc_now_since = now;
+        }
+        nuc_state = on;
+    }
+
+    // A new frame: log the pause before it if it was long, and count it.
+    void noteFrame(long long now, double cam_ts) {
+        const long long host_gap = now - last_frame_steady;
+        const double    cam_gap  = last_cam_ts >= 0.0 && cam_ts >= 0.0 ? cam_ts - last_cam_ts : -1.0;
+        if (last_cam_ts >= 0.0) {
+            ++sum_frames;
+            if (cam_gap > 0.0) sum_cam_span += cam_gap;
+            sum_max_gap = std::max(sum_max_gap, host_gap);
+            if (host_gap > kGapLogMs || cam_gap > kGapLogMs) {
+                ++sum_gaps;
+                std::string codes;
+                for (const auto& [code, n] : codes_since_frame)
+                    codes += (codes.empty() ? "" : ", ") +
+                             (code == kSuccess ? std::string("same frame") : describe(code)) +
+                             " x" + std::to_string(n);
+                LOG_INFO << "thermal camera: frame gap " << host_gap << " ms (camera clock "
+                         << static_cast<long long>(cam_gap) << " ms), " << polls_since_frame
+                         << " polls: " << (codes.empty() ? "-" : codes) << "; NUC "
+                         << (nuc_state < 0 ? "unknown" : nuc_in_gap ? "in progress" : "not seen");
+            }
+        }
+        last_cam_ts       = cam_ts;
+        polls_since_frame = 0;
+        codes_since_frame.clear();
+        nuc_in_gap        = nuc_state > 0;
+        if (now - sum_since_ms >= kSummaryEveryMs) summary(now);
+    }
+
+    void summary(long long now) {
+        if (sum_since_ms != 0 && sum_frames > 0) {
+            long long missed;
+            {
+                std::lock_guard<std::mutex> l(m);
+                missed        = missed_window;
+                missed_window = 0;
+            }
+            const double fps = sum_cam_span > 0.0 ? sum_frames * 1000.0 / sum_cam_span : 0.0;
+            LOG_INFO << "thermal camera, last " << (now - sum_since_ms) / 60000 << " min: "
+                     << sum_frames << " frames (" << std::lround(fps * 10) / 10.0
+                     << " fps by the camera's clock), longest gap " << sum_max_gap << " ms, "
+                     << sum_gaps << " over " << kGapLogMs << " ms, " << sum_nucs << " NUC, "
+                     << missed << " picture(s) without a thermal frame";
+        }
+        sum_frames = sum_gaps = sum_nucs = sum_max_gap = 0;
+        sum_cam_span = 0.0;
+        sum_since_ms = now;
+    }
+
     void telemetry() {
         float k = 0.f;
         if (getSingle(param::kCameraTempHousing, k) && k > 0.f) {
@@ -706,20 +821,25 @@ bool TarisCameraSource::trigger() {
     Frame f;
     {
         std::lock_guard<std::mutex> l(d.m);
-        const bool fresh = d.latest_seq > d.delivered_seq &&
+        const bool new_frame = d.latest_seq > d.delivered_seq;
-                           unixMs() - d.latest.timestamp_ms <= d.o.max_frame_age_ms;
+        const long long age  = d.latest_seq ? unixMs() - d.latest.timestamp_ms : -1;
+        const bool fresh     = new_frame && age <= d.o.max_frame_age_ms;
         if (!fresh) {
+            // Every miss, with what tells its cause apart: the stream paused (and
+            // whether a NUC was running), or nothing came since the last picture.
             ++d.missed_shots;
-            ++d.missed_since_log;
+            ++d.missed_window;
             d.info.frames_dropped = d.missed_shots + d.packets_lost;
             const long long now = steadyMs();
-            if (now - d.missed_logged_ms >= kLogEveryMs) {
+            std::string why = !d.why_offline.empty()
-                LOG_WARN << "thermal camera: no fresh frame for " << d.missed_since_log
+                                  ? d.why_offline
-                         << " picture(s) in the last minute"
+                                  : "newest frame " + std::to_string(age) + " ms old (limit " +
-                         << (d.why_offline.empty() ? "" : " (" + d.why_offline + ")");
+                                        std::to_string(d.o.max_frame_age_ms) + " ms)" +
-                d.missed_logged_ms = now;
+                                        (new_frame ? "" : ", none since the last picture") +
-                d.missed_since_log = 0;
+                                        (d.nuc_now ? ", NUC in progress for " +
-            }
+                                                         std::to_string(now - d.nuc_now_since) + " ms"
+                                                   : ", no NUC running");
+            LOG_WARN << "thermal camera: no thermal frame for this picture: " << why;
             return false;
         }
         f               = d.latest;

tests/test_tariscamerasource.cpp

@@ -35,6 +35,7 @@ struct FakeSdk {
     uint32_t w = 8, h = 4;
     Ret      no_frame = kErrNotFound;    // what getdata says before any frame
     std::atomic<bool> frozen{false};     // stop producing frames (stall)
+    std::atomic<int>  nuc{0};            // NUC_INPROGRESS
 
     void push(uint16_t v, uint16_t hot = 0) {
         std::lock_guard<std::mutex> l(m);
@@ -98,6 +99,9 @@ Ret fGetParam(Handle, uint32_t what, void* data, uint32_t type) {
         return kSuccess;
     }
     if (what == param::kCameraTempHousing && type == kTypeSingle) { *static_cast<float*>(data) = 308.15f; return kSuccess; }
+    if (what == param::kNucInProgress && type == kTypeInt32) { *static_cast<int32_t*>(data) = g->nuc; return kSuccess; }
+    if (what == param::kNucActive && type == kTypeInt32) { *static_cast<int32_t*>(data) = 1; return kSuccess; }
+    if (what == param::kNucInterval && type == kTypeInt32) { *static_cast<int32_t*>(data) = 0; return kSuccess; }
     return kErrNotSupported;
 }
 Ret fSetParam(Handle, uint32_t what, void* data, uint32_t type) {
@@ -368,6 +372,26 @@ TEST_CASE("a camera that goes quiet is reconnected") {
     CHECK(t.sdk.connects >= 2);
 }
 
+TEST_CASE("a NUC pausing the stream costs that picture, and the stream goes on") {
+    auto o = fastOptions();
+    o.max_frame_age_ms = 50;
+    Harness t(o);
+    t.cam.open();
+    t.cam.start();
+    t.sdk.push(29315);
+    REQUIRE(t.shot());
+    // The camera corrects itself: no new frame while it does.
+    t.sdk.nuc    = 1;
+    t.sdk.frozen = true;
+    std::this_thread::sleep_for(std::chrono::milliseconds(120));
+    CHECK_FALSE(t.cam.trigger());
+    CHECK(t.cam.deviceInfo()[0].frames_dropped >= 1);
+    t.sdk.nuc    = 0;
+    t.sdk.frozen = false;
+    t.sdk.push(29400);
+    CHECK(t.shot());
+}
+
 TEST_CASE("a missing SDK library leaves the camera offline, not the program down") {
     auto o    = fastOptions();
     o.library = "libdoes_not_exist_irbgrab.so";