Warning: row count limit (50 rows) reached

[habub]

Hi,
I sometimes get an output message: bitbuffer_add_bit: Warning: row count limit (50 rows) reached although there should be only 1 row (which decodes correctly). Not sure if it's a decoder/bitbuffer glitch or something in my code?
Also, shouldn't this type of message be part of stderr and not stdout?
See example below (3 consecutive packets).

model : Remote1 count : 1 num_rows : 1 rows :
len : 215 data : aaaae2cca656969a9aa99aa9aa6a5aaa6a99555555fffffe000000
codes : {215}aaaae2cca656969a9aa99aa9aa6a5aaa6a99555555fffffe000000
bitbuffer_add_bit: Warning: row count limit (50 rows) reached
bitbuffer_add_bit: Warning: row count limit (50 rows) reached
bitbuffer_add_bit: Warning: row count limit (50 rows) reached
bitbuffer_add_bit: Warning: row count limit (50 rows) reached

---

model : Remote1 count : 1 num_rows : 1 rows :
len : 843 data : fffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffaaaae2cca656969a96a99aa9aa6a5aa96965695555fffffe000000
codes : {843}fffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffaaaae2cca656969a96a99aa9aa6a5aa96965695555fffffe000000

---

model : Remote1 count : 1 num_rows : 1 rows :
len : 215 data : aaaae2cca656969a9aa99aa9aa6a5aaa6965555555fffffe000000
codes : {215}aaaae2cca656969a9aa99aa9aa6a5aaa6965555555fffffe000000
bitbuffer_add_bit: Warning: row count limit (50 rows) reached

---

[zuckschwerdt]

It's just a waring and can be ignored if you are not expecting to get more than 50 rows -- that won't work.
The output is (and always was) stderr.

[rct]

Yesterday I upgraded an instance to the current head in git as of 2023-03-07: rtl_433 version nightly branch master at 202303071313 inputs file rtl_tcp RTL-SDR

The prior code I was running on that RPI was pretty old: rtl_433 version 21.12-160-geee869e7 branch master at 202210252023 inputs file rtl_tcp RTL-SDR

With the old code I was seeing the message at most once a day. Since upgrading, I saw that message 43 times in 18 hours.

So my questions:

Am I potentially losing data each time this is logged? (This is with "stable" based on what's currently committed.)

What's the lifecycle for bit buffers? When do they get created/destroyed relative to running the bit slicers and the decoders that match?

Is some decoder's choice of gap limit making this error occur more frequently?

If this any warning like this is worth printing, shouldn't it get time stamped?

I see at some point this was a print_logf() instead of an fprintf(stderr,...)

        if (bits->free_row == BITBUF_ROWS - 1) {
            //print_logf(LOG_WARNING, __func__, "Warning: row count limit (%d rows) reached", \
BITBUF_ROWS);
            fprintf(stderr, "%s: Warning: row count limit (%d rows) reached\n", __func__, BITB\
UF_ROWS);
        }
        if (bits->free_row < BITBUF_ROWS) {
            bits->free_row++;
        }
        else {
            // fprintf(stderr, "%s: Could not add more rows\n", __func__);
            return;
        }

[zuckschwerdt]

A first simple step would be to bitbuffer_print(bits) just after the warning.

But you won't know which caller caused this (my guess: always pulse_slicer_pcm()). Lazy way out: access a null pointer or div by zero after the warning and run a debug build to get a trace like this:

    #2 0x10a4e1403 in bitbuffer_add_bit bitbuffer.c:45
    #3 0x10a69dcf9 in pulse_slicer_pcm pulse_slicer.c:221
    #4 0x10a6cedac in run_ook_demods r_api.c:507

So OOK PCM as expected. But for me that was the last overflow in more than a day now :/

[rct]

Thanks I'll try the bitbuffer_print(bits), but as this is a main rtl instance, I'll skip trying to cause a segfault in order to get a stack trace.

However, did that stack track yield any easily accessible clues for which decoder it was slicing bits for?

But for me that was the last overflow in more than a day now :/

I'm seeing about 50 a day now on that instance with the current code.

[zuckschwerdt]

Not sure why it's up so much. I don't see any commits that might cause this.

I had three traces in total: 2x OOK PCM, 1x FSK PCM. Which could easily be a long beep or something and PCM will the slice that into way to many bits.

Maybe we could dump a file when this happens. I need to think about how to do that.

[zuckschwerdt]

The https://github.com/merbanan/rtl_433/tree/wip-bbdbg branch now has code to intercept and output the overflow warnings. You get info about the calling slicer and a pulse data print. The one instance I saw was genuine data strangely.

[zuckschwerdt]

I updated the branch to output pulse text (ook) so we can inspect the buffers better.
For me this were partly overlapping regular messages that were decoded but then some PCM slicer failed.
E.g. long pulses and short gaps seem to be bad for PCM protocols: they don't trip gap or reset limits but the pulses produce way many bits.

[rct]

Thanks, I have a bunch of pulse data in the log now, but I'm not sure how to interpret it. Should I attach a log file here?

Also I noticed that this tends to happen more frequently when rtl_433 is first started, then becomes more sporadic over time.

Here I'm using line number in the log file (combined STDOUT/STDERR) to give an idea of when/how often this was logged:

$ FILE=out-whb-rpi-20230308.txt && wc -l $FILE && egrep -n rows $FILE
104587 out-whb-rpi-20230308.txt
23:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
27:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
28:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
32:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
40:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
41:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
45:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
48:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
49:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
59:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
64:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
66:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
78:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
82:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
86:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
88:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
95:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
99:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
13030:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
25659:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
31088:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
32376:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
42947:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
44063:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
48842:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
49217:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
51966:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
53139:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
57255:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
57411:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
57917:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
60222:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
61521:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
62941:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
65047:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
70637:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
70812:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
73293:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
75452:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
75703:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
76906:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
76907:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
77330:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
77337:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
80408:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
80653:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
81079:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
82838:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
82917:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
85832:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
92238:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
100345:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
102469:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
102475:bitbuffer_add_bit: Warning: row count limit (50 rows) reached

above file was from 2023-03-08 08:01:45 to 2023-03-09 10:09:53

$ FILE=out-whb-rpi-20230309.txt && wc -l $FILE && egrep -n rows $FILE 
96675 out-whb-rpi-20230309.txt
63:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
65:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
66:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
76:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
80:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
81:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
87:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
89:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
93:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
97:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
108:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
111:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
121:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
128:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
132:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
133:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
137:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
138:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
146:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
148:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
152:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
159:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
160:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
169:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
175:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
179:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
189:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
198:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
199:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
203:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
210:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
23320:bitbuffer_add_bit: Warning: row count limit (50 rows) reached
24644:bitbuffer_add_bit: Warning: row count limit (50 rows) reached

Above file was from 2023-03-09 10:24:55 to 2023-03-10 10:20:05. The last row warning was logged around 2023-03-09 17:04:56, so there were many hours without that occurring.

[zuckschwerdt]

When you look at the warnings there should be valid decodes nearby if the pulse data looks "regular".
I've not seen any "strange" data so far, it's just the PCM slicer that allows nearly everything to be used.
Still puzzling why this is much more visible now.

If you log pulse text then just copy those sections to files. You can read them back with rtl_433 file.ook to replay the event. Or maybe drop some on https://triq.org/pdv/ to inspect.

[rct]

When you look at the warnings there should be valid decodes nearby if the pulse data looks "regular".
I've not seen any "strange" data so far, it's just the PCM slicer that allows nearly everything to be used.

Would nearby be before or after? It's hard to tell without timestamps on the warning. The new OOK data has a timestamp but only to seconds resolution

from egrep -B 2 -A 1 \;received\|\;end out-whb-rpi-20230310.txt

{"time" : "2023-03-10 10:39:54.719358", "model" : "Acurite-Atlas", "id" : 924, "channel" : "C", "sequence_num" : 1, "battery_ok" : 1, "message_type" : 37, "wind_avg_mi_h" : 4.000, "temperature_F" : 45.100, "humidity" : 71, "strike_count" : 2, "strike_distance" : 7, "exception" : 0, "raw_msg" : "079c6582065347004771", "mod" : "ASK", "freq" : 433.972, "rssi" : -0.276, "snr" : 30.173, "noise" : -30.449}
bitbuffer_add_bit: Warning: row count limit (50 rows) reached
;received 2023-03-10 10:40:00-0500
;ook 483 pulses
--
556 44
0 20
;end
{"time" : "2023-03-10 10:40:00.347036", "model" : "Acurite-Tower", "id" : 2633, "channel" : "A", "battery_ok" : 1, "temperature_C" : 17.400, "humidity" : 38, "mic" : "CHECKSUM", "mod" : "ASK", "freq" : 433.956, "rssi" : -0.508, "snr" : 29.460, "noise" : -29.968}
{"time" : "2023-03-10 10:40:00.347036", "model" : "Acurite-Tower", "id" : 2633, "channel" : "A", "battery_ok" : 1, "temperature_C" : 17.400, "humidity" : 38, "mic" : "CHECKSUM", "mod" : "ASK", "freq" : 433.956, "rssi" : -0.508, "snr" : 29.460, "noise" : -29.968}
{"time" : "2023-03-10 10:40:00.347036", "model" : "Acurite-Tower", "id" : 2633, "channel" : "A", "battery_ok" : 1, "temperature_C" : 17.400, "humidity" : 38, "mic" : "CHECKSUM", "mod" : "ASK", "freq" : 433.956, "rssi" : -0.508, "snr" : 29.460, "noise" : -29.968}
;received 2023-03-10 10:40:05-0500
;ook 290 pulses
--
98092 56
0 24
;end
{"time" : "2023-03-10 10:40:06.283274", "model" : "Acurite-Atlas", "id" : 924, "channel" : "C", "sequence_num" : 0, "battery_ok" : 1, "message_type" : 38, "wind_avg_mi_h" : 4.000, "wind_dir_deg" : 130.000, "rain_in" : 4.950, "strike_count" : 2, "strike_distance" : 7, "exception" : 0, "raw_msg" : "039c6682848b6f00474c", "mod" : "ASK", "freq" : 433.941, "rssi" : -0.255, "snr" : 29.163, "noise" : -29.418}
--
{"time" : "2023-03-10 10:40:09.163761", "model" : "Acurite-Tower", "id" : 9884, "channel" : "B", "battery_ok" : 0, "temperature_C" : 21.500, "humidity" : 32, "mic" : "CHECKSUM", "mod" : "ASK", "freq" : 433.955, "rssi" : -3.093, "snr" : 25.460, "noise" : -28.553}
bitbuffer_add_bit: Warning: row count limit (50 rows) reached
;received 2023-03-10 10:40:12-0500
;ook 201 pulses
--
4360 44
0 28
;end
;received 2023-03-10 10:40:15-0500
;ook 407 pulses
--
548 84
0 24
;end
{"time" : "2023-03-10 10:40:16.670240", "model" : "Acurite-Tower", "id" : 2633, "channel" : "A", "battery_ok" : 1, "temperature_C" : 17.400, "humidity" : 38, "mic" : "CHECKSUM", "mod" : "ASK", "freq" : 433.954, "rssi" : -0.355, "snr" : 27.386, "noise" : -27.741}
--
{"time" : "2023-03-10 10:40:19.470849", "model" : "Ambientweather-F007TH", "id" : 241, "channel" : 3, "battery_ok" : 1, "temperature_F" : 56.000, "humidity" : 60, "mic" : "CRC", "mod" : "ASK", "freq" : 433.923, "rssi" : -0.406, "snr" : 26.993, "noise" : -27.399}
bitbuffer_add_bit: Warning: row count limit (50 rows) reached
;received 2023-03-10 10:40:22-0500
;ook 357 pulses
--
3104 48
0 16
;end
{"time" : "2023-03-10 10:40:21.834623", "model" : "Ambientweather-F007TH", "id" : 115, "channel" : 8, "battery_ok" : 0, "temperature_F" : 63.200, "humidity" : 42, "mic" : "CRC", "mod" : "ASK", "freq" : 433.926, "rssi" : -0.446, "snr" : 26.517, "noise" : -26.963}
--
{"time" : "2023-03-10 10:40:32.336239", "model" : "Acurite-Tower", "id" : 2633, "channel" : "A", "battery_ok" : 1, "temperature_C" : 17.400, "humidity" : 38, "mic" : "CHECKSUM", "mod" : "ASK", "freq" : 433.953, "rssi" : -0.494, "snr" : 24.826, "noise" : -25.320}
bitbuffer_add_bit: Warning: row count limit (50 rows) reached
;received 2023-03-10 10:40:35-0500
;ook 375 pulses
--
1832 48
0 16
;end
{"time" : "2023-03-10 10:40:38.180332", "model" : "Ambientweather-F007TH", "id" : 64, "channel" : 2, "battery_ok" : 1, "temperature_F" : 68.400, "humidity" : 36, "mic" : "CRC", "mod" : "ASK", "freq" : 433.934, "rssi" : -0.246, "snr" : 24.748, "noise" : -24.994}

[rct]

I'll need to split those ook files out. Spot checking the metadata in there yields a possible clue, at least about why so many of these are logged near start up but then decrease once auto parameters stabilize:

$ egrep '^\;|^[0-9]' out-whb-rpi-20230310.txt  > /tmp/ooks

$ egrep freq1 /tmp/ooks 
;freq1 433952288
;freq1 433933376
;freq1 433923552
;freq1 433964320
;freq1 433878816
;freq1 433958464
;freq1 433877248
;freq1 433880320
;freq1 433923648
;freq1 433925728
;freq1 433933920
;freq1 433876480
;freq1 433930784
;freq1 433928640

$ egrep snr /tmp/ooks 
;snr 38.2 dB
;snr 37.4 dB
;snr 24.9 dB
;snr 34.3 dB
;snr 20.5 dB
;snr 31.5 dB
;snr 18.9 dB
;snr 18.7 dB
;snr 17.9 dB
;snr 17.6 dB
;snr 16.0 dB
;snr 15.8 dB
;snr 15.0 dB
;snr 13.1 dB

$ egrep noise /tmp/ooks 
;noise -39.3 dB
;noise -37.9 dB
;noise -37.1 dB
;noise -34.7 dB
;noise -32.6 dB
;noise -31.8 dB
;noise -31.1 dB
;noise -30.8 dB
;noise -30.1 dB
;noise -29.8 dB
;noise -28.2 dB
;noise -28.0 dB
;noise -27.1 dB
;noise -25.3 dB


$ egrep rssi /tmp/ooks 
;rssi -1.1 dB
;rssi -0.5 dB
;rssi -12.1 dB
;rssi -0.4 dB
;rssi -12.1 dB
;rssi -0.4 dB
;rssi -12.1 dB
;rssi -12.1 dB
;rssi -12.1 dB
;rssi -12.1 dB
;rssi -12.1 dB
;rssi -12.1 dB
;rssi -12.1 dB
;rssi -12.1 dB

$ egrep ook /tmp/ooks 
;ook 778 pulses
;ook 315 pulses
;ook 95 pulses
;ook 273 pulses
;ook 125 pulses
;ook 401 pulses
;ook 174 pulses
;ook 156 pulses
;ook 483 pulses
;ook 290 pulses
;ook 201 pulses
;ook 407 pulses
;ook 357 pulses
;ook 375 pulses

[rct]

Ok, so if I'm interpreting the results correctly, Neptune R900 flow meter (228) is triggering this:

$ ./src/rtl_433  /tmp/r*.ook 2>&1 | egrep -i bitb
bitbuffer_add_bit: Warning: row count limit (50 rows) reached
[pulse_slicer_pcm] Bitbuffer overflow on Neptune R900 flow meters
bitbuffer_add_bit: Warning: row count limit (50 rows) reached
[pulse_slicer_pcm] Bitbuffer overflow on Neptune R900 flow meters
bitbuffer_add_bit: Warning: row count limit (50 rows) reached
[pulse_slicer_pcm] Bitbuffer overflow on Neptune R900 flow meters
bitbuffer_add_bit: Warning: row count limit (50 rows) reached
[pulse_slicer_pcm] Bitbuffer overflow on Neptune R900 flow meters
bitbuffer_add_bit: Warning: row count limit (50 rows) reached
[pulse_slicer_pcm] Bitbuffer overflow on Neptune R900 flow meters
bitbuffer_add_bit: Warning: row count limit (50 rows) reached
[pulse_slicer_pcm] Bitbuffer overflow on Neptune R900 flow meters
bitbuffer_add_bit: Warning: row count limit (50 rows) reached
[pulse_slicer_pcm] Bitbuffer overflow on Neptune R900 flow meters
bitbuffer_add_bit: Warning: row count limit (50 rows) reached
[pulse_slicer_pcm] Bitbuffer overflow on Neptune R900 flow meters
bitbuffer_add_bit: Warning: row count limit (50 rows) reached
[pulse_slicer_pcm] Bitbuffer overflow on Neptune R900 flow meters
bitbuffer_add_bit: Warning: row count limit (50 rows) reached
[pulse_slicer_pcm] Bitbuffer overflow on Neptune R900 flow meters
bitbuffer_add_bit: Warning: row count limit (50 rows) reached
[pulse_slicer_pcm] Bitbuffer overflow on Neptune R900 flow meters
bitbuffer_add_bit: Warning: row count limit (50 rows) reached
[pulse_slicer_pcm] Bitbuffer overflow on Neptune R900 flow meters

And if I disable 228, no output

$ ./src/rtl_433 -R -228  /tmp/r*.ook 2>&1 | egrep -i bitb

[zuckschwerdt]

For me it's also Neptune R900 and Proflame2. Maybe those two just need stricter tolerance or something.
Before/After is hard to say, it depends on decoder order.

[rct]

If I'm reading the PDV results correctly, those OOK recordings were all 3+ seconds long.