Tokio hangs when opening TIFF

[maxrjones]

This example seems to hang, @kylebarron suggested in may relate to the intersection between exceptions, panics, and async futures

from async_tiff import TIFF
from async_tiff.store import HTTPStore
from urllib.parse import urlparse
import asyncio

year = 2000
file_name = "50N_120W"
url = f"https://storage.googleapis.com/earthenginepartners-hansen/GLCLU2000-2020/v2/{year}/{file_name}.tif"
parsed = urlparse(url)
store = HTTPStore.from_url(f"{parsed.scheme}://{parsed.netloc}")
async def open_tiff(*, store, path):
    return await TIFF.open(path, store=store)

tiff = asyncio.run(open_tiff(store=store, path=parsed.path))
print(tiff)

fyi @TomNicholas

[kylebarron]

FWIW I saw this issue apache/arrow-rs-object-store#343 which linked to this upstream issue rust-lang/rust#136932. When I was debugging this issue, I remember seeing a panic somewhere with u16::Display. I was super confused at the time, but I'm curious if maybe this was a regression with rustc? Maybe we should test with another rust version

[weiji14]

Tested on rust 1.86 and 1.87, getting the same hang behaviour on both so don't think it's related to those issues. I can reproduce this purely on the rust side too (when working on #101 (comment)), so at least we can deduce that it's not something with pyo3.

[kylebarron]

Yeah... I'm kinda stumped about this hanging 😔

[yutannihilation]

After some very primitive print debugging around this function, I found the process doesn't actually hang but it's just slow.

async-tiff/src/metadata/reader.rs

Lines 257 to 280 in fac684f

	async fn read_tag<F: MetadataFetch>(
	fetch: &F,
	tag_offset: u64,
	endianness: Endianness,
	bigtiff: bool,
	) -> AsyncTiffResult<(Tag, Value)> {
	let mut cursor = MetadataCursor::new_with_offset(fetch, endianness, tag_offset);
	let tag_name = Tag::from_u16_exhaustive(cursor.read_u16().await?);
	let tag_type_code = cursor.read_u16().await?;
	let tag_type = Type::from_u16(tag_type_code).expect(
	"Unknown tag type {tag_type_code}. TODO: we should skip entries with unknown tag types.",
	);
	let count = if bigtiff {
	cursor.read_u64().await?
	} else {
	cursor.read_u32().await?.into()
	};
	let tag_value = read_tag_value(&mut cursor, tag_type, count, bigtiff).await?;
	Ok((tag_name, tag_value))
	}

The fifth tag (and similar tags will come after this) is of 40,000 values.

tag_idx: 5
tag_offset: 70, endianness: LittleEndian, bigtiff: false
tag_name: StripOffsets
tag_type_code: 4
tag_type: LONG
count: 40000
value_byte_length: 160000

I'm not sure why this is so slow, but it seems each cursor.read_u32().await? takes time. Maybe it can fetch values by batch to improve the performance? (I don't know well about the internals. Sorry if it already does!)

async-tiff/src/metadata/reader.rs

Lines 532 to 538 in fac684f

	Type::LONG => {
	let mut v = Vec::with_capacity(count as _);
	for _ in 0..count {
	v.push(Value::Unsigned(cursor.read_u32().await?))
	}
	Ok(Value::List(v))
	}

[yutannihilation]

Regarding the batch reading (while this might not matter much), this is my attempt in case this is useful.

main...yutannihilation:async-tiff:tmp

[kylebarron]

Thanks for helping track down these bugs!

Indeed the issue here was that we're making too many individual requests once the PrefetchBuffer wasn't enough data in the cache.

I validated that #140 fixes this issue:

from async_tiff import TIFF
from async_tiff.store import HTTPStore
from urllib.parse import urlparse

year = 2000
file_name = "50N_120W"
url = f"https://storage.googleapis.com/earthenginepartners-hansen/GLCLU2000-2020/v2/{year}/{file_name}.tif"
parsed = urlparse(url)
store = HTTPStore.from_url(f"{parsed.scheme}://{parsed.netloc}")

tiff = await TIFF.open(parsed.path, store=store)

This takes 3 seconds to open the tiff (on moderate internet from New Zealand), so I think we can consider this fixed.

Aside from the unit tests we're adding in #140 , I'm not sure the best way to test this, because we can't really add public HTTP tests directly on CI