ErrorFrameHeader.__init__() got an unexpected keyword argument 't'

[adonoho]

This has been happening every few days, 10/25-11/12. Now happening every several hours.

Traceback (most recent call last):
  File "/Users/awd/miniforge3/envs/bsky/lib/python3.10/site-packages/atproto_firehose/client.py", line 266, in start
    _handle_frame_decoding_error(e)
  File "/Users/awd/miniforge3/envs/bsky/lib/python3.10/site-packages/atproto_firehose/client.py", line 66, in _handle_frame_decoding_error
    raise exception
  File "/Users/awd/miniforge3/envs/bsky/lib/python3.10/site-packages/atproto_firehose/client.py", line 263, in start
    frame = _get_message_frame_from_bytes_or_raise(raw_frame)
  File "/Users/awd/miniforge3/envs/bsky/lib/python3.10/site-packages/atproto_firehose/client.py", line 83, in _get_message_frame_from_bytes_or_raise
    frame = Frame.from_bytes(data)
  File "/Users/awd/miniforge3/envs/bsky/lib/python3.10/site-packages/atproto_firehose/models.py", line 126, in from_bytes
    header = parse_frame_header(raw_header)
  File "/Users/awd/miniforge3/envs/bsky/lib/python3.10/site-packages/atproto_firehose/models.py", line 59, in parse_frame_header
    return get_or_create(raw_header, ErrorFrameHeader)
  File "/Users/awd/miniforge3/envs/bsky/lib/python3.10/site-packages/atproto_client/models/utils.py", line 69, in get_or_create
    raise e
  File "/Users/awd/miniforge3/envs/bsky/lib/python3.10/site-packages/atproto_client/models/utils.py", line 62, in get_or_create
    model_instance = _get_or_create(model_data, model, strict=strict)
  File "/Users/awd/miniforge3/envs/bsky/lib/python3.10/site-packages/atproto_client/models/utils.py", line 101, in _get_or_create
    return model(**model_data)
TypeError: ErrorFrameHeader.__init__() got an unexpected keyword argument 't'

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/Users/awd/Projects/PhenomML/BSky2GBQ/main.py", line 341, in <module>
    IOLoop().run_sync(run_it)
  File "/Users/awd/miniforge3/envs/bsky/lib/python3.10/site-packages/tornado/ioloop.py", line 539, in run_sync
    return future_cell[0].result()
  File "/Users/awd/Projects/PhenomML/BSky2GBQ/main.py", line 338, in run_it
    await async_monitor_bsky_firehose (lambda item: is_post (item),
  File "/Users/awd/Projects/PhenomML/BSky2GBQ/main.py", line 307, in async_monitor_bsky_firehose
    await firehose.start(lambda message: async_on_message(message, test_function, handler))
  File "/Users/awd/miniforge3/envs/bsky/lib/python3.10/site-packages/atproto_firehose/client.py", line 271, in start
    should_stop = _handle_websocket_error_or_stop(e)
  File "/Users/awd/miniforge3/envs/bsky/lib/python3.10/site-packages/atproto_firehose/client.py", line 79, in _handle_websocket_error_or_stop
    raise FirehoseError from exception
atproto_firehose.exceptions.FirehoseError

The code that calls the atproto library is straightforward:

async def async_monitor_bsky_firehose(test_function, handler):
    firehose = hose.AsyncFirehoseSubscribeReposClient()
    await firehose.start(lambda message: async_on_message(message, test_function, handler))

Happy to dig deeper.

Anon,
Andrew

[MarshalX]

Interesting. That's a super rare case when firehose returns error frames. Maybe started happened because of some server changes or new load challenges. Probably just a simple deserialization bug around ErrorFrameHeader on SDK side.

[adonoho]

Not as rare an error as you might hope. Happening multiple times since the first issue raise. This is from a few minutes ago.

Traceback (most recent call last):
  File "/Users/awd/miniforge3/envs/bsky/lib/python3.10/site-packages/atproto_firehose/client.py", line 221, in _process_message_frame
    await self._on_message_callback(frame)
  File "/Users/awd/Projects/PhenomML/BSky2GBQ/main.py", line 91, in async_on_message
    blocks = atproto.CAR.from_bytes(message.blocks).blocks
  File "/Users/awd/miniforge3/envs/bsky/lib/python3.10/site-packages/atproto_core/car/car.py", line 51, in from_bytes
    header, blocks = libipld.decode_car(data)
ValueError: Failed to read CAR header. Invalid uvarint
Traceback (most recent call last):
  File "/Users/awd/miniforge3/envs/bsky/lib/python3.10/site-packages/atproto_firehose/client.py", line 266, in start
    _handle_frame_decoding_error(e)
  File "/Users/awd/miniforge3/envs/bsky/lib/python3.10/site-packages/atproto_firehose/client.py", line 66, in _handle_frame_decoding_error
    raise exception
  File "/Users/awd/miniforge3/envs/bsky/lib/python3.10/site-packages/atproto_firehose/client.py", line 263, in start
    frame = _get_message_frame_from_bytes_or_raise(raw_frame)
  File "/Users/awd/miniforge3/envs/bsky/lib/python3.10/site-packages/atproto_firehose/client.py", line 83, in _get_message_frame_from_bytes_or_raise
    frame = Frame.from_bytes(data)
  File "/Users/awd/miniforge3/envs/bsky/lib/python3.10/site-packages/atproto_firehose/models.py", line 126, in from_bytes
    header = parse_frame_header(raw_header)
  File "/Users/awd/miniforge3/envs/bsky/lib/python3.10/site-packages/atproto_firehose/models.py", line 59, in parse_frame_header
    return get_or_create(raw_header, ErrorFrameHeader)
  File "/Users/awd/miniforge3/envs/bsky/lib/python3.10/site-packages/atproto_client/models/utils.py", line 69, in get_or_create
    raise e
  File "/Users/awd/miniforge3/envs/bsky/lib/python3.10/site-packages/atproto_client/models/utils.py", line 62, in get_or_create
    model_instance = _get_or_create(model_data, model, strict=strict)
  File "/Users/awd/miniforge3/envs/bsky/lib/python3.10/site-packages/atproto_client/models/utils.py", line 101, in _get_or_create
    return model(**model_data)
TypeError: ErrorFrameHeader.__init__() got an unexpected keyword argument 't'

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/Users/awd/Projects/PhenomML/BSky2GBQ/main.py", line 341, in <module>
    IOLoop().run_sync(run_it)
  File "/Users/awd/miniforge3/envs/bsky/lib/python3.10/site-packages/tornado/ioloop.py", line 539, in run_sync
    return future_cell[0].result()
  File "/Users/awd/Projects/PhenomML/BSky2GBQ/main.py", line 338, in run_it
    await async_monitor_bsky_firehose (lambda item: is_post (item),
  File "/Users/awd/Projects/PhenomML/BSky2GBQ/main.py", line 307, in async_monitor_bsky_firehose
    await firehose.start(lambda message: async_on_message(message, test_function, handler))
  File "/Users/awd/miniforge3/envs/bsky/lib/python3.10/site-packages/atproto_firehose/client.py", line 271, in start
    should_stop = _handle_websocket_error_or_stop(e)
  File "/Users/awd/miniforge3/envs/bsky/lib/python3.10/site-packages/atproto_firehose/client.py", line 79, in _handle_websocket_error_or_stop
    raise FirehoseError from exception
atproto_firehose.exceptions.FirehoseError

[MarshalX]

Today evening they have maintenance xDD

[MarshalX]

I will look at this closer since we need to fix it first before touching, for example, jet streams

[adonoho]

I am happy to help but I know nothing about this stack. IOW, if you need me to instrument my stack, I'm happy to do so. We capture the firehose as the beginning of a research project at the University with which I volunteer. No one is depending upon 24x7 operation.

[MarshalX]

I checked the code. It looks legit... Super strange that this happens. Maybe another server side bug... So from the docs:

t ("type", string, optional): required if op is 1, indicating the Lexicon sub-type for this message, in short form. Does not include the full Lexicon identifier, just a fragment. Eg: #commit. Should not be included in header if op is -1. (https://atproto.com/specs/event-stream#streaming-wire-protocol-v0)

And we are getting op = -1... because:

atproto/packages/atproto_firehose/models.py

Lines 52 to 59 in d030829

	header_op = int(raw_header.get('op', 0))
	if not FrameType.has_value(header_op):
	raise FirehoseDecodingError('Invalid frame type')
	frame_type = FrameType(header_op)
	if frame_type is FrameType.MESSAGE:
	return get_or_create(raw_header, MessageFrameHeader)
	return get_or_create(raw_header, ErrorFrameHeader)

• line 52 fallback to op 0 if missing
• line 53 checks that the op is 1 or -1
• and we are failing on line 59. which means that op is -1 for sure...

but somehow, header with -1 contains t field. which should not occur at all (according to the official docs)

upd. it will be awesome if you could log the value of "raw_header"!

[justin-pierce]

been experiencing this a lot

when I print raw_header right before the exception, it's simply:

raw_header: {'t': '', 'op': -1}

[MarshalX]

so backend started to send empty string with op=-1... but empty string is not true optional field?

[seanthegeek]

@MarshalX Because this is happening very frequently now, could you add a temporary workaround to the SDK that drops and reestablishes a connection to the firehose until this is fixed server side?

[MarshalX]

@seanthegeek tbh i do not want to put it inside SDK. I want a proper fix from bsky team. In Bluesky feed generator repo we already have additional try catch upon firehose client. Make it reconnect on any exception instead of just logging it. And it will work as expected. Since according to the specs we must reconnect to firehose from scratch in case of an error frame it will fit perfectly

[seanthegeek]

Hmm, if there's already a catch inside the Bluesky feed generator repo, any idea why my feed stops receiving new posts?Sometimes an exception isn't logged, and it still stops receiving new posts, but continues

[MarshalX]

@seanthegeek because as I said you need to add reconnect in this try-catch manually. here: https://github.com/MarshalX/bluesky-feed-generator/blob/c2b37ffa9878ad12b3c7b1beaa1ae5fc2a4e96e5/server/data_stream.py#L49-L56

[seanthegeek]

Is this the right way to do that? seanthegeek/bluesky-infosec-feed@26b118d

If so, maybe include it in the template, or mention it in the README?

[MarshalX]

@seanthegeek the right way will be to just remove raise e. Leave pass or continue or logger.info('reconnecting'). do not call _run since on the next exception it will break again