Sometimes this happens because the lock file is not cleared. Did you look
for the .lock file?

Regards
Sab

On 15 Feb 2017 8:59 p.m., "Frank Lyaruu" <flya...@gmail.com> wrote:

> No, it sure isn't... The log file doesn't seem to have been touched for
> hours. The whole log file seems to be of the same millisecond, but hours
> before the stack trace (The stack trace is from 15:25). It seems to have
> barfed out of nowhere without logging anything.
>
> 2017/02/15-12:38:07.061758 7f1cf0101700 RocksDB version: 5.0.1
> 2017/02/15-12:38:07.061812 7f1cf0101700 Git sha rocksdb_build_git_sha:
> 2017/02/15-12:38:07.061816 7f1cf0101700 Compile date Jan  7 2017
> 2017/02/15-12:38:07.061817 7f1cf0101700 DB SUMMARY
> 2017/02/15-12:38:07.061918 7f1cf0101700 CURRENT file:  CURRENT
> 2017/02/15-12:38:07.061920 7f1cf0101700 IDENTITY file:  IDENTITY
> 2017/02/15-12:38:07.061927 7f1cf0101700 MANIFEST file:  MANIFEST-000007
> size: 33335 Bytes
> 2017/02/15-12:38:07.061930 7f1cf0101700 SST files in
> /output/env.managed.repository-master/storage/KNVB-test-generation-175-
> othermatchpersons/1_0/rocksdb/KNVB-test-generation-175-
> personcore-PERSONCORE
> dir, Total Num: 7, files: 000353.sst 000355.sst 000356.sst 000459.sst
> 000489.sst 000498.sst 000499.sst
> 2017/02/15-12:38:07.061932 7f1cf0101700 Write Ahead Log file in
> /output/env.managed.repository-master/storage/KNVB-test-generation-175-
> othermatchpersons/1_0/rocksdb/KNVB-test-generation-175-
> personcore-PERSONCORE:
> 000003.log size: 0 ;
> 2017/02/15-12:38:07.061935 7f1cf0101700
> Options.error_if_exists: 0
> 2017/02/15-12:38:07.061936 7f1cf0101700
> Options.create_if_missing: 1
> 2017/02/15-12:38:07.061937 7f1cf0101700
> Options.paranoid_checks: 1
> 2017/02/15-12:38:07.061938 7f1cf0101700
> Options.env: 0x7f1cefbf8440
> 2017/02/15-12:38:07.061939 7f1cf0101700
>  Options.info_log: 0x7f1cd8649b40
> 2017/02/15-12:38:07.061940 7f1cf0101700
>  Options.max_open_files: -1
> 2017/02/15-12:38:07.061941 7f1cf0101700
>  Options.max_file_opening_threads: 16
> 2017/02/15-12:38:07.061942 7f1cf0101700
> Options.disableDataSync: 0
> 2017/02/15-12:38:07.061943 7f1cf0101700
> Options.use_fsync: 0
> 2017/02/15-12:38:07.061944 7f1cf0101700
> Options.max_log_file_size: 0
> 2017/02/15-12:38:07.061945 7f1cf0101700
>  Options.max_manifest_file_size: 18446744073709551615
> 2017/02/15-12:38:07.061946 7f1cf0101700
> Options.log_file_time_to_roll: 0
> 2017/02/15-12:38:07.061946 7f1cf0101700
> Options.keep_log_file_num: 1000
> 2017/02/15-12:38:07.061947 7f1cf0101700
>  Options.recycle_log_file_num: 0
> 2017/02/15-12:38:07.061948 7f1cf0101700
> Options.allow_os_buffer: 1
> 2017/02/15-12:38:07.061949 7f1cf0101700
>  Options.allow_mmap_reads: 0
> 2017/02/15-12:38:07.061950 7f1cf0101700
> Options.allow_fallocate: 1
> 2017/02/15-12:38:07.061951 7f1cf0101700
> Options.allow_mmap_writes: 0
> 2017/02/15-12:38:07.061952 7f1cf0101700
>  Options.use_direct_reads: 0
> 2017/02/15-12:38:07.061953 7f1cf0101700
>  Options.create_missing_column_families: 0
> 2017/02/15-12:38:07.061954 7f1cf0101700
>  Options.db_log_dir:
> 2017/02/15-12:38:07.061955 7f1cf0101700
> Options.wal_dir:
> /output/env.managed.repository-master/storage/KNVB-test-generation-175-
> othermatchpersons/1_0/rocksdb/KNVB-test-generation-175-
> personcore-PERSONCORE
> 2017/02/15-12:38:07.061956 7f1cf0101700
>  Options.table_cache_numshardbits: 6
> 2017/02/15-12:38:07.061957 7f1cf0101700
> Options.delete_obsolete_files_period_micros: 21600000000
> 2017/02/15-12:38:07.061958 7f1cf0101700
>  Options.max_subcompactions: 1
> 2017/02/15-12:38:07.061958 7f1cf0101700
>  Options.max_background_flushes: 1
> 2017/02/15-12:38:07.061959 7f1cf0101700
> Options.WAL_ttl_seconds: 0
> 2017/02/15-12:38:07.061960 7f1cf0101700
> Options.WAL_size_limit_MB: 0
> 2017/02/15-12:38:07.061961 7f1cf0101700
> Options.manifest_preallocation_size: 4194304
> 2017/02/15-12:38:07.061962 7f1cf0101700
> Options.allow_os_buffer: 1
> 2017/02/15-12:38:07.061963 7f1cf0101700
>  Options.allow_mmap_reads: 0
> 2017/02/15-12:38:07.061964 7f1cf0101700
> Options.allow_mmap_writes: 0
> 2017/02/15-12:38:07.061965 7f1cf0101700
> Options.is_fd_close_on_exec: 1
> 2017/02/15-12:38:07.061992 7f1cf0101700
> Options.stats_dump_period_sec: 600
> 2017/02/15-12:38:07.061994 7f1cf0101700
> Options.advise_random_on_open: 1
> 2017/02/15-12:38:07.061995 7f1cf0101700
>  Options.db_write_buffer_size: 0
> 2017/02/15-12:38:07.061996 7f1cf0101700
> Options.access_hint_on_compaction_start: 1
> 2017/02/15-12:38:07.061997 7f1cf0101700
>  Options.new_table_reader_for_compaction_inputs: 0
> 2017/02/15-12:38:07.061998 7f1cf0101700
> Options.compaction_readahead_size: 0
> 2017/02/15-12:38:07.061999 7f1cf0101700
> Options.random_access_max_buffer_size: 1048576
> 2017/02/15-12:38:07.062000 7f1cf0101700
> Options.writable_file_max_buffer_size: 1048576
> 2017/02/15-12:38:07.062000 7f1cf0101700
>  Options.use_adaptive_mutex: 0
> 2017/02/15-12:38:07.062001 7f1cf0101700
>  Options.rate_limiter: (nil)
> 2017/02/15-12:38:07.062003 7f1cf0101700
> Options.sst_file_manager.rate_bytes_per_sec: 0
> 2017/02/15-12:38:07.062004 7f1cf0101700
>  Options.bytes_per_sync: 0
> 2017/02/15-12:38:07.062004 7f1cf0101700
>  Options.wal_bytes_per_sync: 0
> 2017/02/15-12:38:07.062005 7f1cf0101700
> Options.wal_recovery_mode: 2
> 2017/02/15-12:38:07.062006 7f1cf0101700
>  Options.enable_thread_tracking: 0
> 2017/02/15-12:38:07.062007 7f1cf0101700
> Options.allow_concurrent_memtable_write: 1
> 2017/02/15-12:38:07.062008 7f1cf0101700
>  Options.enable_write_thread_adaptive_yield: 1
> 2017/02/15-12:38:07.062009 7f1cf0101700
> Options.write_thread_max_yield_usec: 100
> 2017/02/15-12:38:07.062010 7f1cf0101700
>  Options.write_thread_slow_yield_usec: 3
> 2017/02/15-12:38:07.062011 7f1cf0101700
> Options.row_cache: None
> 2017/02/15-12:38:07.062012 7f1cf0101700
>  Options.wal_filter: None
> 2017/02/15-12:38:07.062013 7f1cf0101700
> Options.avoid_flush_during_recovery: 0
> 2017/02/15-12:38:07.062014 7f1cf0101700
> Options.base_background_compactions: 1
> 2017/02/15-12:38:07.062015 7f1cf0101700
> Options.max_background_compactions: 1
> 2017/02/15-12:38:07.062016 7f1cf0101700
> Options.avoid_flush_during_shutdown: 0
> 2017/02/15-12:38:07.062017 7f1cf0101700
> Options.delayed_write_rate : 2097152
> 2017/02/15-12:38:07.062018 7f1cf0101700
> Options.max_total_wal_size: 0
> 2017/02/15-12:38:07.062018 7f1cf0101700 Compression algorithms supported:
> 2017/02/15-12:38:07.062020 7f1cf0101700 Snappy supported: 1
> 2017/02/15-12:38:07.062021 7f1cf0101700 Zlib supported: 1
> 2017/02/15-12:38:07.062021 7f1cf0101700 Bzip supported: 1
> 2017/02/15-12:38:07.062022 7f1cf0101700 LZ4 supported: 1
> 2017/02/15-12:38:07.062023 7f1cf0101700 ZSTD supported: 0
> 2017/02/15-12:38:07.062024 7f1cf0101700 Fast CRC32 supported: 0
> 2017/02/15-12:38:07.062512 7f1cf0101700               Options.comparator:
> leveldb.BytewiseComparator
> 2017/02/15-12:38:07.062516 7f1cf0101700           Options.merge_operator:
> None
> 2017/02/15-12:38:07.062518 7f1cf0101700        Options.compaction_filter:
> None
> 2017/02/15-12:38:07.062519 7f1cf0101700
>  Options.compaction_filter_factory: None
> 2017/02/15-12:38:07.062520 7f1cf0101700         Options.memtable_factory:
> SkipListFactory
> 2017/02/15-12:38:07.062521 7f1cf0101700            Options.table_factory:
> BlockBasedTable
> 2017/02/15-12:38:07.062532 7f1cf0101700            table_factory options:
> flush_block_policy_factory: FlushBlockBySizePolicyFactory (0x7f1d18fe03d0)
>   cache_index_and_filter_blocks: 0
>   pin_l0_filter_and_index_blocks_in_cache: 0
>   index_type: 0
>   hash_index_allow_collision: 1
>   checksum: 1
>   no_block_cache: 0
>   block_cache: 0x7f1cc4c8bbd8
>   block_cache_size: 1048576
>   block_cache_compressed: (nil)
>   block_size: 4096
>   block_size_deviation: 10
>   block_restart_interval: 16
>   index_block_restart_interval: 1
>   filter_policy: nullptr
>   whole_key_filtering: 1
>   skip_table_builder_flush: 0
>   format_version: 0
> 2017/02/15-12:38:07.062555 7f1cf0101700        Options.write_buffer_size:
> 3145728
> 2017/02/15-12:38:07.062557 7f1cf0101700  Options.max_write_buffer_number:
> 3
> 2017/02/15-12:38:07.062559 7f1cf0101700          Options.compression: LZ4
> 2017/02/15-12:38:07.062560 7f1cf0101700
>  Options.bottommost_compression: Disabled
> 2017/02/15-12:38:07.062561 7f1cf0101700       Options.prefix_extractor:
> nullptr
> 2017/02/15-12:38:07.062562 7f1cf0101700
> Options.memtable_insert_with_hint_prefix_extractor: nullptr
> 2017/02/15-12:38:07.062563 7f1cf0101700             Options.num_levels: 7
> 2017/02/15-12:38:07.062564 7f1cf0101700
>  Options.min_write_buffer_number_to_merge: 1
> 2017/02/15-12:38:07.062565 7f1cf0101700
> Options.max_write_buffer_number_to_maintain: 0
> 2017/02/15-12:38:07.062566 7f1cf0101700
>  Options.compression_opts.window_bits: -14
> 2017/02/15-12:38:07.062567 7f1cf0101700
>  Options.compression_opts.level: -1
> 2017/02/15-12:38:07.062568 7f1cf0101700
> Options.compression_opts.strategy: 0
> 2017/02/15-12:38:07.062569 7f1cf0101700
> Options.compression_opts.max_dict_bytes: 0
> 2017/02/15-12:38:07.062570 7f1cf0101700
>  Options.level0_file_num_compaction_trigger: 4
> 2017/02/15-12:38:07.062571 7f1cf0101700
>  Options.level0_slowdown_writes_trigger: 20
> 2017/02/15-12:38:07.062572 7f1cf0101700
>  Options.level0_stop_writes_trigger: 32
> 2017/02/15-12:38:07.062572 7f1cf0101700
> Options.target_file_size_base: 67108864
> 2017/02/15-12:38:07.062573 7f1cf0101700
> Options.target_file_size_multiplier: 1
> 2017/02/15-12:38:07.062574 7f1cf0101700
>  Options.max_bytes_for_level_base: 30000000
> 2017/02/15-12:38:07.062575 7f1cf0101700
> Options.level_compaction_dynamic_level_bytes: 0
> 2017/02/15-12:38:07.062576 7f1cf0101700
>  Options.max_bytes_for_level_multiplier: 3.000000
> 2017/02/15-12:38:07.062581 7f1cf0101700
> Options.max_bytes_for_level_multiplier_addtl[0]: 1
> 2017/02/15-12:38:07.062582 7f1cf0101700
> Options.max_bytes_for_level_multiplier_addtl[1]: 1
> 2017/02/15-12:38:07.062583 7f1cf0101700
> Options.max_bytes_for_level_multiplier_addtl[2]: 1
> 2017/02/15-12:38:07.062584 7f1cf0101700
> Options.max_bytes_for_level_multiplier_addtl[3]: 1
> 2017/02/15-12:38:07.062585 7f1cf0101700
> Options.max_bytes_for_level_multiplier_addtl[4]: 1
> 2017/02/15-12:38:07.062585 7f1cf0101700
> Options.max_bytes_for_level_multiplier_addtl[5]: 1
> 2017/02/15-12:38:07.062586 7f1cf0101700
> Options.max_bytes_for_level_multiplier_addtl[6]: 1
> 2017/02/15-12:38:07.062587 7f1cf0101700
> Options.max_sequential_skip_in_iterations: 8
> 2017/02/15-12:38:07.062588 7f1cf0101700
>  Options.max_compaction_bytes: 1677721600
> 2017/02/15-12:38:07.062589 7f1cf0101700
>  Options.arena_block_size: 393216
> 2017/02/15-12:38:07.062590 7f1cf0101700
> Options.soft_pending_compaction_bytes_limit: 68719476736
> 2017/02/15-12:38:07.062591 7f1cf0101700
> Options.hard_pending_compaction_bytes_limit: 274877906944
> 2017/02/15-12:38:07.062592 7f1cf0101700
> Options.rate_limit_delay_max_milliseconds: 1000
> 2017/02/15-12:38:07.062593 7f1cf0101700
>  Options.disable_auto_compactions: 0
> 2017/02/15-12:38:07.062594 7f1cf0101700
> Options.verify_checksums_in_compaction: 1
> 2017/02/15-12:38:07.062595 7f1cf0101700
> Options.compaction_style: 1
> 2017/02/15-12:38:07.062596 7f1cf0101700
> Options.compaction_pri: 0
> 2017/02/15-12:38:07.062597 7f1cf0101700
>  Options.compaction_options_universal.size_ratio: 1
> 2017/02/15-12:38:07.062598 7f1cf0101700
> Options.compaction_options_universal.min_merge_width: 2
> 2017/02/15-12:38:07.062599 7f1cf0101700
> Options.compaction_options_universal.max_merge_width: 4294967295
> 2017/02/15-12:38:07.062600 7f1cf0101700
> Options.compaction_options_universal.max_size_amplification_percent: 200
> 2017/02/15-12:38:07.062601 7f1cf0101700
> Options.compaction_options_universal.compression_size_percent: -1
> 2017/02/15-12:38:07.062602 7f1cf0101700
> Options.compaction_options_fifo.max_table_files_size: 1073741824
> 2017/02/15-12:38:07.062602 7f1cf0101700
> Options.table_properties_collectors:
> 2017/02/15-12:38:07.062615 7f1cf0101700
> Options.inplace_update_support: 0
> 2017/02/15-12:38:07.062616 7f1cf0101700
> Options.inplace_update_num_locks: 10000
> 2017/02/15-12:38:07.062617 7f1cf0101700
> Options.min_partial_merge_operands: 2
> 2017/02/15-12:38:07.062618 7f1cf0101700
> Options.memtable_prefix_bloom_size_ratio: 0.000000
> 2017/02/15-12:38:07.062620 7f1cf0101700   Options.memtable_huge_page_size:
> 0
> 2017/02/15-12:38:07.062621 7f1cf0101700
> Options.bloom_locality: 0
> 2017/02/15-12:38:07.062622 7f1cf0101700
>  Options.max_successive_merges: 0
> 2017/02/15-12:38:07.062623 7f1cf0101700
>  Options.optimize_filters_for_hits: 0
> 2017/02/15-12:38:07.062624 7f1cf0101700
>  Options.paranoid_file_checks: 0
> 2017/02/15-12:38:07.062625 7f1cf0101700
>  Options.force_consistency_checks: 0
> 2017/02/15-12:38:07.062625 7f1cf0101700
>  Options.report_bg_io_stats: 0
>
> On Wed, Feb 15, 2017 at 3:56 PM, Damian Guy <damian....@gmail.com> wrote:
>
> > Hi Frank,
> >
> > Very hard to say from the stack trace. The exception isn't the most
> > informative!
> > Is there anything obvious in the RocksDB LOG?
> >
> > Thanks,
> > Damian
> >
> >
> > On Wed, 15 Feb 2017 at 06:38 Frank Lyaruu <flya...@gmail.com> wrote:
> >
> > > Hi Kafka crew,
> > >
> > > I'm rolling out a Kafka Streams application on a pretty large dataset,
> > and
> > > I see some exceptions that worry me, which I haven't seen with smaller
> > data
> > > sets
> > > (Using Kafka streams trunk of a few days ago)
> > >
> > > 2017-02-15 15:25:14,431 | INFO  | StreamThread-42  | StreamTask
> > >           | 86 - com.dexels.kafka.streams - 0.0.53.201702141103 | task
> > > [9_4] Initializing state stores
> > > 2017-02-15 15:25:14,433 | ERROR | StreamThread-42  |
> ConsumerCoordinator
> > >            | 86 - com.dexels.kafka.streams - 0.0.53.201702141103 | User
> > > provided listener
> > > org.apache.kafka.streams.processor.internals.StreamThread$1 for group
> > > KNVB-test-generation-175-person failed on partition assignment
> > > org.apache.kafka.streams.errors.ProcessorStateException: Error opening
> > > store KNVB-test-generation-175-person-sportlinkkernel-
> > PERSONCOMMUNICATION
> > > at location
> > >
> > > /output/env.managed.repository-master/storage/
> KNVB-test-generation-175-
> > person/9_4/rocksdb/KNVB-test-generation-175-person-sportlinkkernel-
> > PERSONCOMMUNICATION
> > > at
> > >
> > > org.apache.kafka.streams.state.internals.RocksDBStore.
> > openDB(RocksDBStore.java:175)
> > > at
> > >
> > > org.apache.kafka.streams.state.internals.RocksDBStore.
> > openDB(RocksDBStore.java:145)
> > > at
> > >
> > > org.apache.kafka.streams.state.internals.RocksDBStore.
> > init(RocksDBStore.java:150)
> > > at
> > >
> > > org.apache.kafka.streams.state.internals.MeteredKeyValueStore$7.run(
> > MeteredKeyValueStore.java:100)
> > > at
> > >
> > > org.apache.kafka.streams.processor.internals.StreamsMetricsImpl.
> > measureLatencyNs(StreamsMetricsImpl.java:188)
> > > at
> > >
> > > org.apache.kafka.streams.state.internals.MeteredKeyValueStore.init(
> > MeteredKeyValueStore.java:131)
> > > at
> > >
> > > org.apache.kafka.streams.state.internals.CachingKeyValueStore.init(
> > CachingKeyValueStore.java:62)
> > > at
> > >
> > > org.apache.kafka.streams.processor.internals.AbstractTask.
> > initializeStateStores(AbstractTask.java:85)
> > > at
> > >
> > > org.apache.kafka.streams.processor.internals.
> > StreamTask.<init>(StreamTask.java:143)
> > > at
> > >
> > > org.apache.kafka.streams.processor.internals.
> > StreamThread.createStreamTask(StreamThread.java:834)
> > > at
> > >
> > > org.apache.kafka.streams.processor.internals.StreamThread$TaskCreator.
> > createTask(StreamThread.java:1207)
> > > at
> > >
> > > org.apache.kafka.streams.processor.internals.StreamThread$
> > AbstractTaskCreator.retryWithBackoff(StreamThread.java:1180)
> > > at
> > >
> > > org.apache.kafka.streams.processor.internals.
> > StreamThread.addStreamTasks(StreamThread.java:937)
> > > at
> > >
> > > org.apache.kafka.streams.processor.internals.StreamThread.access$500(
> > StreamThread.java:69)
> > > at
> > >
> > > org.apache.kafka.streams.processor.internals.StreamThread$1.
> > onPartitionsAssigned(StreamThread.java:236)
> > > at
> > >
> > > org.apache.kafka.clients.consumer.internals.ConsumerCoordinator.
> > onJoinComplete(ConsumerCoordinator.java:255)
> > > at
> > >
> > > org.apache.kafka.clients.consumer.internals.AbstractCoordinator.
> > joinGroupIfNeeded(AbstractCoordinator.java:339)
> > > at
> > >
> > > org.apache.kafka.clients.consumer.internals.AbstractCoordinator.
> > ensureActiveGroup(AbstractCoordinator.java:303)
> > > at
> > >
> > > org.apache.kafka.clients.consumer.internals.ConsumerCoordinator.poll(
> > ConsumerCoordinator.java:286)
> > > at
> > >
> > > org.apache.kafka.clients.consumer.KafkaConsumer.
> > pollOnce(KafkaConsumer.java:1030)
> > > at
> > >
> > > org.apache.kafka.clients.consumer.KafkaConsumer.poll(
> > KafkaConsumer.java:995)
> > > at
> > >
> > > org.apache.kafka.streams.processor.internals.StreamThread.runLoop(
> > StreamThread.java:582)
> > > at
> > >
> > > org.apache.kafka.streams.processor.internals.
> > StreamThread.run(StreamThread.java:368)
> > > Caused by: org.rocksdb.RocksDBException:
> > > at org.rocksdb.RocksDB.open(Native Method)
> > > at org.rocksdb.RocksDB.open(RocksDB.java:231)
> > > at
> > >
> > > org.apache.kafka.streams.state.internals.RocksDBStore.
> > openDB(RocksDBStore.java:168)
> > > ... 22 more
> > >
> > > I've checked the folder it points to:
> > >
> > > [root@842376-demeter1 KNVB-test-generation-175-personcore-PERSONCORE]#
> > ls
> > > -l
> > > total 223348
> > > -rw-r--r--. 1 431 433 68153335 Feb 15 11:09 000353.sst
> > > -rw-r--r--. 1 431 433 68207125 Feb 15 11:09 000355.sst
> > > -rw-r--r--. 1 431 433  7241027 Feb 15 11:09 000356.sst
> > > -rw-r--r--. 1 431 433 59070938 Feb 15 11:12 000459.sst
> > > -rw-r--r--. 1 431 433 18783280 Feb 15 11:13 000489.sst
> > > -rw-r--r--. 1 431 433        0 Feb 15 11:38 000502.log
> > > -rw-r--r--. 1 431 433  7183476 Feb 15 11:38 000505.sst
> > > -rw-r--r--. 1 431 433       16 Feb 15 11:38 CURRENT
> > > -rw-r--r--. 1 431 433       37 Feb 15 10:57 IDENTITY
> > > -rw-r--r--. 1 431 433        0 Feb 15 10:57 LOCK
> > > -rw-r--r--. 1 431 433    13446 Feb 15 11:38 LOG
> > > -rw-r--r--. 1 431 433    13130 Feb 15 10:57 LOG.old.1487158687061100
> > > -rw-r--r--. 1 431 433      456 Feb 15 11:38 MANIFEST-000501
> > > -rw-r--r--. 1 431 433     4275 Feb 15 10:57 OPTIONS-000005
> > > -rw-r--r--. 1 431 433     4275 Feb 15 11:38 OPTIONS-000504
> > > [root@842376-demeter1 KNVB-test-generation-175-personcore-PERSONCORE]#
> > >
> > > What strikes me as odd is that none of the files have been touched in
> the
> > > last few hours (the stacktrace is from 15:25), so there doesn't appear
> to
> > > have been any logging of that error (on the rocksdb side)
> > >
> > > Any ideas? Or should I post this to RocksDb?
> > >
> > > regards, Frank
> > >
> >
>

Reply via email to