Materialize: Materialize crashes on possible Avro schema resolution error
What version of Materialize are you using?
$ materialized -v
materialized v0.3.1 (9e4dce4bee6169e8391d9d7a6f5382b998a00625)
How did you install Materialize?
- [ ] Docker image
- [x] Linux release tarball
- [ ] APT package
- [ ] macOS release tarball
- [ ] Homebrew tap
- [ ] Built from source
What was the issue?
materialize crashes when reading from debezium source with confluent schema registry.
Is the issue reproducible? If so, please provide reproduction instructions.
Order of events causing issue:
Create source:
CREATE SOURCE sales_source FROM KAFKA BROKER 'kafka.kafka-cdc.svc.cluster.local:9092' TOPIC 'sales'
FORMAT AVRO USING CONFLUENT SCHEMA REGISTRY 'http://schema-registry-svc.kafka-cdc.svc.cluster.local:8081';
Create View:
CREATE MATERIALIZED VIEW sales_view AS SELECT * FROM sales_source;
Attempt to read data:
SELECT * from sales_view LIMIT 10;
Server then crashed. Subsequent attempts to start the server crash while trying to read from Kafka.
top - 17:32:25 up 347 days, 23:11, 0 users, load average: 5.73, 3.41, 2.32
Tasks: 7 total, 1 running, 6 sleeping, 0 stopped, 0 zombie
%Cpu(s): 4.8 us, 6.4 sy, 0.0 ni, 87.3 id, 1.1 wa, 0.0 hi, 0.3 si, 0.0 st
MiB Mem : 104748.3 total, 2179.1 free, 9079.9 used, 93489.4 buff/cache
MiB Swap: 0.0 total, 0.0 free, 0.0 used. 94883.6 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
4502 root 20 0 5576548 2.7g 60664 S 204.0 2.7 0:48.61 materialized
1 root 20 0 4008 3272 2852 S 0.0 0.0 0:00.02 bash
402 root 20 0 4112 3440 2844 S 0.0 0.0 0:00.05 bash
1593 root 20 0 4008 3308 2736 S 0.0 0.0 0:00.01 bash
4400 root 20 0 21696 7700 6612 S 0.0 0.0 0:00.04 psql
4411 root 20 0 4008 3224 2796 S 0.0 0.0 0:00.01 bash
4419 root 20 0 7976 3100 2668 R 0.0 0.0 0:00.06 top
Please attach any applicable log files.
Jul 08 17:12:42.899 INFO coord::catalog: create source materialize.public.sales_source (u1)
Jul 08 17:14:51.939 INFO coord::catalog: create view materialize.public.sales_view (u2)
Jul 08 17:14:51.939 INFO coord::catalog: create index materialize.public.sales_view_primary_idx (u3)
Jul 08 17:14:52.954 INFO dataflow::source::kafka: New partitions (from 0 to 26) have been detected for topic sales (Source Id: u1/u3)
Jul 08 17:14:52.954 INFO dataflow::source::kafka: Activating Kafka queue for sales [0] (source u1/u3) on worker 0
Jul 08 17:14:52.955 INFO dataflow::source::kafka: Activating Kafka queue for sales [1] (source u1/u3) on worker 0
Jul 08 17:14:52.955 INFO dataflow::source::kafka: Activating Kafka queue for sales [2] (source u1/u3) on worker 0
Jul 08 17:14:52.956 INFO dataflow::source::kafka: Activating Kafka queue for sales [3] (source u1/u3) on worker 0
Jul 08 17:14:52.956 INFO dataflow::source::kafka: Activating Kafka queue for sales [4] (source u1/u3) on worker 0
Jul 08 17:14:52.956 INFO dataflow::source::kafka: Activating Kafka queue for sales [5] (source u1/u3) on worker 0
Jul 08 17:14:52.957 INFO dataflow::source::kafka: Activating Kafka queue for sales [6] (source u1/u3) on worker 0
Jul 08 17:14:52.957 INFO dataflow::source::kafka: Activating Kafka queue for sales [7] (source u1/u3) on worker 0
Jul 08 17:14:52.958 INFO dataflow::source::kafka: Activating Kafka queue for sales [8] (source u1/u3) on worker 0
Jul 08 17:14:52.958 INFO dataflow::source::kafka: Activating Kafka queue for sales [9] (source u1/u3) on worker 0
Jul 08 17:14:52.959 INFO dataflow::source::kafka: Activating Kafka queue for sales [10] (source u1/u3) on worker 0
Jul 08 17:14:52.960 INFO dataflow::source::kafka: Activating Kafka queue for sales [11] (source u1/u3) on worker 0
Jul 08 17:14:52.961 INFO dataflow::source::kafka: Activating Kafka queue for sales [12] (source u1/u3) on worker 0
Jul 08 17:14:52.961 INFO dataflow::source::kafka: Activating Kafka queue for sales [13] (source u1/u3) on worker 0
Jul 08 17:14:52.962 INFO dataflow::source::kafka: Activating Kafka queue for sales [14] (source u1/u3) on worker 0
Jul 08 17:14:52.963 INFO dataflow::source::kafka: Activating Kafka queue for sales [15] (source u1/u3) on worker 0
Jul 08 17:14:52.964 INFO dataflow::source::kafka: Activating Kafka queue for sales [16] (source u1/u3) on worker 0
Jul 08 17:14:52.965 INFO dataflow::source::kafka: Activating Kafka queue for sales [17] (source u1/u3) on worker 0
Jul 08 17:14:52.966 INFO dataflow::source::kafka: Activating Kafka queue for sales [18] (source u1/u3) on worker 0
Jul 08 17:14:52.968 INFO dataflow::source::kafka: Activating Kafka queue for sales [19] (source u1/u3) on worker 0
Jul 08 17:14:52.968 INFO dataflow::source::kafka: Activating Kafka queue for sales [20] (source u1/u3) on worker 0
Jul 08 17:14:52.969 INFO dataflow::source::kafka: Activating Kafka queue for sales [21] (source u1/u3) on worker 0
Jul 08 17:14:52.971 INFO dataflow::source::kafka: Activating Kafka queue for sales [22] (source u1/u3) on worker 0
Jul 08 17:14:52.972 INFO dataflow::source::kafka: Activating Kafka queue for sales [23] (source u1/u3) on worker 0
Jul 08 17:14:52.973 INFO dataflow::source::kafka: Activating Kafka queue for sales [24] (source u1/u3) on worker 0
Jul 08 17:14:52.975 INFO dataflow::source::kafka: Activating Kafka queue for sales [25] (source u1/u3) on worker 0
Jul 08 17:15:15.132Z materialized encountered an internal error and crashed.
We rely on bug reports to diagnose and fix these errors. Please
copy and paste the following details and file a report at:
https://materialize.io/s/bug
To protect your privacy, we do not collect crash reports automatically.
thread: worker thread 0
message: called `Option::unwrap()` on a `None` value
0: materialized::handle_panic
at var/lib/buildkite-agent/builds/buildkite-builders-i-0d6d722cbbde5b348-1/materialize/tests/src/materialized/src/bin/materialized.rs:357
1: core::ops::function::Fn::call
at usr/local/lib/rustlib/src/rust/src/libcore/ops/function.rs:72
2: std::panicking::rust_panic_with_hook
at rustc/c7087fe00d2ba919df1d813c040a5d47e43b0fe7/src/libstd/panicking.rs:515
3: rust_begin_unwind
at rustc/c7087fe00d2ba919df1d813c040a5d47e43b0fe7/src/libstd/panicking.rs:419
4: core::panicking::panic_fmt
at rustc/c7087fe00d2ba919df1d813c040a5d47e43b0fe7/src/libcore/panicking.rs:111
5: core::panicking::panic
at rustc/c7087fe00d2ba919df1d813c040a5d47e43b0fe7/src/libcore/panicking.rs:54
6: core::option::Option<T>::unwrap
at usr/local/lib/rustlib/src/rust/src/libcore/macros/mod.rs:34
core::ops::function::FnMut::call_mut
at usr/local/lib/rustlib/src/rust/src/libcore/ops/function.rs:154
core::iter::adapters::map_fold::{{closure}}
at usr/local/lib/rustlib/src/rust/src/libcore/iter/adapters/mod.rs:786
core::iter::traits::iterator::Iterator::fold::ok::{{closure}}
at usr/local/lib/rustlib/src/rust/src/libcore/iter/traits/iterator.rs:2002
core::iter::traits::iterator::Iterator::try_fold
at usr/local/lib/rustlib/src/rust/src/libcore/iter/traits/iterator.rs:1878
core::iter::traits::iterator::Iterator::fold
at usr/local/lib/rustlib/src/rust/src/libcore/iter/traits/iterator.rs:2005
<core::iter::adapters::Map<I,F> as core::iter::traits::iterator::Iterator>::fold
at usr/local/lib/rustlib/src/rust/src/libcore/iter/adapters/mod.rs:826
7: core::iter::traits::iterator::Iterator::for_each
at usr/local/lib/rustlib/src/rust/src/libcore/iter/traits/iterator.rs:658
<alloc::vec::Vec<T> as alloc::vec::SpecExtend<T,I>>::spec_extend
at usr/local/lib/rustlib/src/rust/src/liballoc/vec.rs:2116
<alloc::vec::Vec<T> as alloc::vec::SpecExtend<T,I>>::from_iter
at usr/local/lib/rustlib/src/rust/src/liballoc/vec.rs:2096
<alloc::vec::Vec<T> as core::iter::traits::collect::FromIterator<T>>::from_iter
at usr/local/lib/rustlib/src/rust/src/liballoc/vec.rs:1981
core::iter::traits::iterator::Iterator::collect
at usr/local/lib/rustlib/src/rust/src/libcore/iter/traits/iterator.rs:1660
avro::schema::resolve_schemas
at var/lib/buildkite-agent/builds/buildkite-builders-i-0d6d722cbbde5b348-1/materialize/tests/src/avro/src/schema.rs:66
8: interchange::avro::SchemaCache::get::{{closure}}
at var/lib/buildkite-agent/builds/buildkite-builders-i-0d6d722cbbde5b348-1/materialize/tests/src/interchange/src/avro.rs:1084
<core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll
at usr/local/lib/rustlib/src/rust/src/libcore/future/mod.rs:66
interchange::avro::Decoder::decode::{{closure}}
at var/lib/buildkite-agent/builds/buildkite-builders-i-0d6d722cbbde5b348-1/materialize/tests/src/interchange/src/avro.rs:786
<core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll
at usr/local/lib/rustlib/src/rust/src/libcore/future/mod.rs:66
9: <dataflow::decode::avro::AvroDecoderState as dataflow::decode::DecoderState>::give_value::__give_value::{{closure}}
at var/lib/buildkite-agent/builds/buildkite-builders-i-0d6d722cbbde5b348-1/materialize/tests/src/dataflow/src/decode/avro.rs:108
<core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll
at usr/local/lib/rustlib/src/rust/src/libcore/future/mod.rs:66
10: <core::pin::Pin<P> as core::future::future::Future>::poll
at usr/local/lib/rustlib/src/rust/src/libcore/future/future.rs:118
futures_executor::local_pool::block_on::{{closure}}
at cargo/registry/src/github.com-1ecc6299db9ec823/futures-executor-0.3.4/src/local_pool.rs:317
futures_executor::local_pool::run_executor::{{closure}}
at cargo/registry/src/github.com-1ecc6299db9ec823/futures-executor-0.3.4/src/local_pool.rs:87
std::thread::local::LocalKey<T>::try_with
at usr/local/lib/rustlib/src/rust/src/libstd/thread/local.rs:263
std::thread::local::LocalKey<T>::with
at usr/local/lib/rustlib/src/rust/src/libstd/thread/local.rs:239
11: futures_executor::local_pool::run_executor
at cargo/registry/src/github.com-1ecc6299db9ec823/futures-executor-0.3.4/src/local_pool.rs:83
futures_executor::local_pool::block_on
at cargo/registry/src/github.com-1ecc6299db9ec823/futures-executor-0.3.4/src/local_pool.rs:317
12: dataflow::decode::decode_values_inner::{{closure}}::{{closure}}::{{closure}}
at var/lib/buildkite-agent/builds/buildkite-builders-i-0d6d722cbbde5b348-1/materialize/tests/src/dataflow/src/decode/mod.rs:403
timely::dataflow::operators::generic::handles::InputHandle<T,D,P>::for_each
at cargo/git/checkouts/timely-dataflow-4c0cc365061cd263/e37923d/timely/src/dataflow/operators/generic/handles.rs:92
dataflow::decode::decode_values_inner::{{closure}}::{{closure}}
at var/lib/buildkite-agent/builds/buildkite-builders-i-0d6d722cbbde5b348-1/materialize/tests/src/dataflow/src/decode/mod.rs:394
<timely::dataflow::stream::Stream<G,D1> as timely::dataflow::operators::generic::operator::Operator<G,D1>>::unary::{{closure}}::{{closure}}
at cargo/git/checkouts/timely-dataflow-4c0cc365061cd263/e37923d/timely/src/dataflow/operators/generic/operator.rs:402
timely::dataflow::operators::generic::builder_rc::OperatorBuilder<G>::build::{{closure}}::{{closure}}
at cargo/git/checkouts/timely-dataflow-4c0cc365061cd263/e37923d/timely/src/dataflow/operators/generic/builder_rc.rs:123
timely::dataflow::operators::generic::builder_rc::OperatorBuilder<G>::build_reschedule::{{closure}}
at cargo/git/checkouts/timely-dataflow-4c0cc365061cd263/e37923d/timely/src/dataflow/operators/generic/builder_rc.rs:163
<timely::dataflow::operators::generic::builder_raw::OperatorCore<T,L> as timely::scheduling::Schedule>::schedule
at cargo/git/checkouts/timely-dataflow-4c0cc365061cd263/e37923d/timely/src/dataflow/operators/generic/builder_raw.rs:203
13: timely::progress::subgraph::PerOperatorState<T>::schedule
at cargo/git/checkouts/timely-dataflow-4c0cc365061cd263/e37923d/timely/src/progress/subgraph.rs:647
14: timely::progress::subgraph::Subgraph<TOuter,TInner>::activate_child
at cargo/git/checkouts/timely-dataflow-4c0cc365061cd263/e37923d/timely/src/progress/subgraph.rs:330
<timely::progress::subgraph::Subgraph<TOuter,TInner> as timely::scheduling::Schedule>::schedule
at cargo/git/checkouts/timely-dataflow-4c0cc365061cd263/e37923d/timely/src/progress/subgraph.rs:296
15: timely::progress::subgraph::PerOperatorState<T>::schedule
at cargo/git/checkouts/timely-dataflow-4c0cc365061cd263/e37923d/timely/src/progress/subgraph.rs:647
16: timely::progress::subgraph::Subgraph<TOuter,TInner>::activate_child
at cargo/git/checkouts/timely-dataflow-4c0cc365061cd263/e37923d/timely/src/progress/subgraph.rs:330
<timely::progress::subgraph::Subgraph<TOuter,TInner> as timely::scheduling::Schedule>::schedule
at cargo/git/checkouts/timely-dataflow-4c0cc365061cd263/e37923d/timely/src/progress/subgraph.rs:296
17: timely::worker::Wrapper::step::{{closure}}
at cargo/git/checkouts/timely-dataflow-4c0cc365061cd263/e37923d/timely/src/worker.rs:526
core::option::Option<T>::map
at usr/local/lib/rustlib/src/rust/src/libcore/option.rs:456
timely::worker::Wrapper::step
at cargo/git/checkouts/timely-dataflow-4c0cc365061cd263/e37923d/timely/src/worker.rs:526
18: timely::worker::Worker<A>::step_or_park
at cargo/git/checkouts/timely-dataflow-4c0cc365061cd263/e37923d/timely/src/worker.rs:235
19: dataflow::server::Worker<A>::run
at var/lib/buildkite-agent/builds/buildkite-builders-i-0d6d722cbbde5b348-1/materialize/tests/src/dataflow/src/server.rs:419
20: dataflow::server::serve::{{closure}}::{{closure}}
at var/lib/buildkite-agent/builds/buildkite-builders-i-0d6d722cbbde5b348-1/materialize/tests/src/dataflow/src/server.rs:234
tokio::runtime::context::enter
at cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.21/src/runtime/context.rs:72
21: tokio::runtime::handle::Handle::enter
at cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.21/src/runtime/handle.rs:76
dataflow::server::serve::{{closure}}
at var/lib/buildkite-agent/builds/buildkite-builders-i-0d6d722cbbde5b348-1/materialize/tests/src/dataflow/src/server.rs:228
timely::execute::execute_from::{{closure}}
at cargo/git/checkouts/timely-dataflow-4c0cc365061cd263/e37923d/timely/src/execute.rs:298
timely_communication::initialize::initialize_from::{{closure}}
at cargo/git/checkouts/timely-dataflow-4c0cc365061cd263/e37923d/communication/src/initialize.rs:269
std::sys_common::backtrace::__rust_begin_short_backtrace
at usr/local/lib/rustlib/src/rust/src/libstd/sys_common/backtrace.rs:130
22: std::thread::Builder::spawn_unchecked::{{closure}}::{{closure}}
at usr/local/lib/rustlib/src/rust/src/libstd/thread/mod.rs:475
<std::panic::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once
at usr/local/lib/rustlib/src/rust/src/libstd/panic.rs:318
std::panicking::try::do_call
at usr/local/lib/rustlib/src/rust/src/libstd/panicking.rs:331
std::panicking::try
at usr/local/lib/rustlib/src/rust/src/libstd/panicking.rs:274
std::panic::catch_unwind
at usr/local/lib/rustlib/src/rust/src/libstd/panic.rs:394
std::thread::Builder::spawn_unchecked::{{closure}}
at usr/local/lib/rustlib/src/rust/src/libstd/thread/mod.rs:474
core::ops::function::FnOnce::call_once{{vtable.shim}}
at usr/local/lib/rustlib/src/rust/src/libcore/ops/function.rs:232
23: <alloc::boxed::Box<F> as core::ops::function::FnOnce<A>>::call_once
at rustc/c7087fe00d2ba919df1d813c040a5d47e43b0fe7/src/liballoc/boxed.rs:1008
<alloc::boxed::Box<F> as core::ops::function::FnOnce<A>>::call_once
at rustc/c7087fe00d2ba919df1d813c040a5d47e43b0fe7/src/liballoc/boxed.rs:1008
std::sys::unix::thread::Thread::new::thread_start
at rustc/c7087fe00d2ba919df1d813c040a5d47e43b0fe7/src/libstd/sys/unix/thread.rs:87
24: start_thread
25: clone
johnjmartin
All 3 comments
Thanks @johnjmartin for filing. A quick conversation with @umanwizard indicates that this is quite likely a schema resolution error, and not something to do with the dataset size. the reason that this error only hits upon materialize view creation is due to some lazy evaluation. We'd need some schema information in order to proceed rapidly, or else we would have to slowly search our way through the stack trace.
rjnn
on 8 Jul 2020
👍1
I believe that this specific crash is fixed by #3555, but I'll wait for John to confirm before closing the issue.
umanwizard
on 8 Jul 2020
I can confirm that the bug is fixed on latest master with your change included!
johnjmartin
on 9 Jul 2020
🎉1
Was this page helpful?
0 / 5 - 0 ratings
Related issues
hden
路
6Comments
maqroll
路
6Comments
frankmcsherry
路
3Comments
JLDLaughlin
路
5Comments
mjibson
路
3Comments