Struct pack throw exception for negative timestamp

[Lefix2]

When using multiple raccoon devices, it happens that read time on a device result in a negative timestamp. https://github.com/bluekitchen/raccoon/blob/5bff11e9d0ef88a496b95824be7de9798e13005a/pyclient/raccoon.py#L522

For that, pack function of struct is bad formatted https://github.com/bluekitchen/raccoon/blob/5bff11e9d0ef88a496b95824be7de9798e13005a/pyclient/pcap.py#L56 It can be a signed int so line become: payload_data = pack( '<BBBBHi', 10, flags, channel, rssi, ecount, delta ) + packet

[mringwal]

I've tried to make the timestamps monotonic increasing, the delta should not be negative. Could you try with a higher log_delay (e.g. 1s) and check if it still happens? If yes, please check the code here

https://github.com/bluekitchen/raccoon/blob/5bff11e9d0ef88a496b95824be7de9798e13005a/pyclient/raccoon.py#L473

It waits at least log_delay and then processes the event with the earliest timestamp, then, start over. Anything wrong with the logic?

[Lefix2]

Yes it still happen with log_delay at 1s. Logic seems good for me, i logged times and all are correct. But what make these negative value happen is this line: https://github.com/bluekitchen/raccoon/blob/5bff11e9d0ef88a496b95824be7de9798e13005a/pyclient/raccoon.py#L523 With this line it happen computed value is greater than next event timestamp:

earliest : 2979594
delta_ts 379
new last_timestamp_us 2979970

earliest : 2980482
delta_ts 512
new last_timestamp_us 2980858

earliest : 2987132
delta_ts 6274
new last_timestamp_us 2987476

earliest : 2987808
delta_ts 332
new last_timestamp_us 2988152

earliest : 2988616
delta_ts 464
new last_timestamp_us 2988960

earliest : 3058861
earliest : 3058861
delta_ts 69901
new last_timestamp_us 3059101

earliest : 3059391
delta_ts 290
new last_timestamp_us 3059631

earliest : 3060052
delta_ts 421
new last_timestamp_us 3060292

earliest : 3081342
delta_ts 21050
new last_timestamp_us 3081718

earliest : 3082097
delta_ts 379
new last_timestamp_us 3082473

earliest : 3082458
delta_ts -15
new last_timestamp_us 3082802

Edit: setting this line to last_timestamp_us = timestamp_log_us prevent bug from happening

[Lefix2]

I think i figured out what you wanted to do. The error is to substract re-adjusted last_timestamp_us with arriving timestamp. It will be more correct to re-adjust timestamp_log_us then allway deal with message-end timestamp?

    # finally, log event
    (arrival_time, start_offset_us, tag, data) = earliest_event_sniffer.get_event()
    length = len(data)
    timestamp_log_us = earliest_event_timestamp_us + 5 * 8 + ( length - 12 ) * 8 # ts is at start of message, move it to the end

    if tag == TAG_MSG_TERMINATE:
        ui.log_info("Restart sniffer on channel #%u" % earliest_event_sniffer.channel)
        earliest_event_sniffer.write( pack('<BHIBII6s', TAG_CMD_SNIFF_CHANNEL, 19, 0, earliest_event_sniffer.channel, ADVERTISING_RADIO_ACCESS_ADDRESS, ADVERTISING_CRC_INIT, filter_mac ) )

    if tag == TAG_DATA:

        # parse header
        timestamp_sniffer_us, channel, flags, rssi_negative, aa = unpack_from( "<IBBBxI", data )
        packet  = data[8:]

        # dump packet
        # print( tag, length, timestamp_log_us, channel, flags, rssi, as_hex(packet) )

        # direction count - what is it used for?
        direction = flags & 0x3
        direction_count[ direction ] += 1

        # delta and event count needed for pcap
        delta_ts = timestamp_log_us - last_timestamp_us
        last_timestamp_us = timestamp_log_us
        event_cnt += 1

        # write packet
        ts_sec  = log_start_sec + int(timestamp_log_us/1000000)
        ts_usec = timestamp_log_us % 1000000
        output.write_packet( ts_sec, ts_usec, flags, channel, rssi_negative, event_cnt, delta_ts, packet )

[mringwal]

Hi. Thanks for the feedback. I'm slowly remembering :) The idea was to sort the events by time of arrival, but the delta-ts was the time between the last packet and the current. If you use a single sniffer, this works either way. With two sniffers that observe packets that overlap, the delta-ts is actually negative (the end of the previous packet comes after the beginning of the current packet).

So, I think your suggestion of using 'i' instead of 'I' is correct. I've pushed your change. Thx.