Uploaded image for project: 'Cassandra'
  1. Cassandra
  2. CASSANDRA-1348

Failed to delete commitlog when restarting service

    Details

    • Type: Bug
    • Status: Resolved
    • Priority: Minor
    • Resolution: Fixed
    • Fix Version/s: 0.6.6, 0.7 beta 2
    • Component/s: None
    • Labels:
      None
    • Environment:

      Windows Server 2008 R2 64bit

      Description

      When restarting any Cassandra node we've got exception:

      ERROR 09:42:27,869 Exception encountered during startup.
      java.io.IOException: Failed to delete C:\cassandra\data\commitlog\CommitLog-1280817512228.log
      at org.apache.cassandra.io.util.FileUtils.deleteWithConfirm(FileUtils.java:45)
      at org.apache.cassandra.db.commitlog.CommitLog.recover(CommitLog.java:177)
      at org.apache.cassandra.thrift.CassandraDaemon.setup(CassandraDaemon.java:120)
      at org.apache.cassandra.service.AbstractCassandraDaemon.init(AbstractCassandraDaemon.java:57)
      at org.apache.cassandra.contrib.windows.service.WindowsService.start(Unknown Source)
      at org.apache.cassandra.contrib.windows.service.WindowsService.main(Unknown Source)
      INFO 09:42:27,869 Exception encountered during startup.
      INFO 09:42:27,869 Cassandra Service Finished: Tue Aug 03 09:42:27 EEST 2010

      Aftrer exception was thrown and Cassandra didn't started, within commitlog directory there's only one file: CommitLog-1280817512228.log
      and no CommitLog-1280817512228.log.header. Looks like CommitLog-1280817512228.log was a new file, not the last one after stopping service.

      After few restarts .log file is deleted and Cassandra is working fine until next restart.

      1. 1348.txt
        12 kB
        Jonathan Ellis
      2. 1348-2.txt
        2 kB
        Jonathan Ellis

        Activity

        Hide
        jbellis Jonathan Ellis added a comment -

        windows gets pissy when you try to delete an open file. this patch closes it before the delete.

        Show
        jbellis Jonathan Ellis added a comment - windows gets pissy when you try to delete an open file. this patch closes it before the delete.
        Hide
        gdusbabek Gary Dusbabek added a comment -

        +1

        Show
        gdusbabek Gary Dusbabek added a comment - +1
        Hide
        jbellis Jonathan Ellis added a comment -

        committed

        Show
        jbellis Jonathan Ellis added a comment - committed
        Hide
        hudson Hudson added a comment -

        Integrated in Cassandra #509 (See http://hudson.zones.apache.org/hudson/job/Cassandra/509/)
        close commitlog reader before deleting it
        patch by jbellis; reviewed by gdusbabek for CASSANDRA-1348

        Show
        hudson Hudson added a comment - Integrated in Cassandra #509 (See http://hudson.zones.apache.org/hudson/job/Cassandra/509/ ) close commitlog reader before deleting it patch by jbellis; reviewed by gdusbabek for CASSANDRA-1348
        Hide
        vjevdokimov Viktor Jevdokimov added a comment -

        Still could happen with 0.7 beta 1. Not always, but happens.

        Show
        vjevdokimov Viktor Jevdokimov added a comment - Still could happen with 0.7 beta 1. Not always, but happens.
        Hide
        jbellis Jonathan Ellis added a comment -

        new stacktrace?

        Show
        jbellis Jonathan Ellis added a comment - new stacktrace?
        Hide
        vjevdokimov Viktor Jevdokimov added a comment -

        INFO 13:38:04,311 Received start command
        INFO 13:38:04,311 Cassandra Service Starting: Fri Sep 03 13:38:04 CEST 2010
        INFO 13:38:04,467 DiskAccessMode 'auto' determined to be mmap, indexAccessMode is mmap
        INFO 13:38:04,592 Sampling index for D:\cassandra\data\data\system\Statistics-e-501-<>
        INFO 13:38:04,639 Sampling index for D:\cassandra\data\data\system\Statistics-e-502-<>
        INFO 13:38:04,670 Sampling index for D:\cassandra\data\data\system\Schema-e-1-<>
        INFO 13:38:04,670 Sampling index for D:\cassandra\data\data\system\Schema-e-2-<>
        INFO 13:38:04,670 Sampling index for D:\cassandra\data\data\system\Schema-e-3-<>
        INFO 13:38:04,701 Sampling index for D:\cassandra\data\data\system\Migrations-e-1-<>
        INFO 13:38:04,701 Sampling index for D:\cassandra\data\data\system\Migrations-e-2-<>
        INFO 13:38:04,701 Sampling index for D:\cassandra\data\data\system\Migrations-e-3-<>
        INFO 13:38:04,717 Sampling index for D:\cassandra\data\data\system\LocationInfo-e-9-<>
        INFO 13:38:04,717 Sampling index for D:\cassandra\data\data\system\LocationInfo-e-10-<>
        INFO 13:38:04,717 Sampling index for D:\cassandra\data\data\system\LocationInfo-e-11-<>
        INFO 13:38:04,717 Sampling index for D:\cassandra\data\data\system\HintsColumnFamily-e-24-<>
        INFO 13:38:04,732 Sampling index for D:\cassandra\data\data\system\HintsColumnFamily-e-25-<>
        INFO 13:38:04,732 Sampling index for D:\cassandra\data\data\system\HintsColumnFamily-e-26-<>
        INFO 13:38:04,732 Sampling index for D:\cassandra\data\data\system\HintsColumnFamily-e-28-<>
        INFO 13:38:04,732 Sampling index for D:\cassandra\data\data\system\HintsColumnFamily-e-30-<>
        INFO 13:38:04,732 Sampling index for D:\cassandra\data\data\system\HintsColumnFamily-e-33-<>
        INFO 13:38:04,763 Loading schema version 6e908998-aa17-11df-bf55-cacedb26d926
        INFO 13:38:05,013 Sampling index for D:\cassandra\data\data\BehavioralTargeting\CookieTrackingSetupMemberships-e-25-<>
        INFO 13:38:07,588 Sampling index for D:\cassandra\data\data\BehavioralTargeting\CookieTrackingSetupMemberships-e-150-<>
        INFO 13:38:10,837 Sampling index for D:\cassandra\data\data\BehavioralTargeting\CookieTrackingSetupMemberships-e-279-<>
        INFO 13:38:14,550 Sampling index for D:\cassandra\data\data\BehavioralTargeting\CookieTrackingSetupMemberships-e-412-<>
        INFO 13:38:17,747 Sampling index for D:\cassandra\data\data\BehavioralTargeting\CookieTrackingSetupMemberships-e-461-<>
        INFO 13:38:18,948 Creating new commitlog segment E:/cassandra/data/commitlog\CommitLog-1283513898948.log
        INFO 13:38:18,964 Deleted D:\cassandra\data\data\BehavioralTargeting\CookieTrackingSetupMemberships-e-470-Data.db
        INFO 13:38:18,964 Deleted D:\cassandra\data\data\BehavioralTargeting\CookieTrackingSetupMemberships-e-479-Data.db
        INFO 13:38:18,979 Deleted D:\cassandra\data\data\BehavioralTargeting\CookieTrackingSetupMemberships-e-492-Data.db
        INFO 13:38:18,979 Deleted D:\cassandra\data\data\BehavioralTargeting\CookieTrackingSetupMemberships-e-497-Data.db
        INFO 13:38:18,979 Sampling index for D:\cassandra\data\data\BehavioralTargeting\CookieTrackingSetupMemberships-e-498-<>
        INFO 13:38:20,118 Replaying E:\cassandra\data\commitlog\CommitLog-1283513833929.log, E:\cassandra\data\commitlog\CommitLog-1283513898948.log
        INFO 13:38:20,134 E:\cassandra\data\commitlog\CommitLog-1283513833929.log.header incomplete, missing or corrupt. Everything is ok, don't panic. CommitLog will be replayed from the beginning
        INFO 13:38:20,150 Finished reading E:\cassandra\data\commitlog\CommitLog-1283513833929.log
        INFO 13:38:20,150 Finished reading E:\cassandra\data\commitlog\CommitLog-1283513898948.log
        INFO 13:38:20,150 switching in a fresh Memtable for Statistics at CommitLogContext(file='E:/cassandra/data/commitlog\CommitLog-1283513898948.log', position=592)
        INFO 13:38:20,165 Enqueuing flush of Memtable-Statistics@1582759704(15004 bytes, 4 operations)
        INFO 13:38:20,165 Writing Memtable-Statistics@1582759704(15004 bytes, 4 operations)
        INFO 13:38:20,508 Completed flushing D:\cassandra\data\data\system\Statistics-e-503-Data.db
        INFO 13:38:20,508 Recovery complete
        ERROR 13:38:20,508 Exception encountered during startup.
        java.io.IOException: Failed to delete E:\cassandra\data\commitlog\CommitLog-1283513898948.log
        at org.apache.cassandra.io.util.FileUtils.deleteWithConfirm(FileUtils.java:45)
        at org.apache.cassandra.db.commitlog.CommitLog.recover(CommitLog.java:178)
        at org.apache.cassandra.thrift.CassandraDaemon.setup(CassandraDaemon.java:120)
        at org.apache.cassandra.service.AbstractCassandraDaemon.init(AbstractCassandraDaemon.java:57)
        at org.apache.cassandra.contrib.windows.service.WindowsService.start(Unknown Source)
        at org.apache.cassandra.contrib.windows.service.WindowsService.main(Unknown Source)
        INFO 13:38:20,555 Exception encountered during startup.
        INFO 13:38:20,555 Cassandra Service Finished: Fri Sep 03 13:38:20 CEST 2010

        Show
        vjevdokimov Viktor Jevdokimov added a comment - INFO 13:38:04,311 Received start command INFO 13:38:04,311 Cassandra Service Starting: Fri Sep 03 13:38:04 CEST 2010 INFO 13:38:04,467 DiskAccessMode 'auto' determined to be mmap, indexAccessMode is mmap INFO 13:38:04,592 Sampling index for D:\cassandra\data\data\system\Statistics-e-501-<> INFO 13:38:04,639 Sampling index for D:\cassandra\data\data\system\Statistics-e-502-<> INFO 13:38:04,670 Sampling index for D:\cassandra\data\data\system\Schema-e-1-<> INFO 13:38:04,670 Sampling index for D:\cassandra\data\data\system\Schema-e-2-<> INFO 13:38:04,670 Sampling index for D:\cassandra\data\data\system\Schema-e-3-<> INFO 13:38:04,701 Sampling index for D:\cassandra\data\data\system\Migrations-e-1-<> INFO 13:38:04,701 Sampling index for D:\cassandra\data\data\system\Migrations-e-2-<> INFO 13:38:04,701 Sampling index for D:\cassandra\data\data\system\Migrations-e-3-<> INFO 13:38:04,717 Sampling index for D:\cassandra\data\data\system\LocationInfo-e-9-<> INFO 13:38:04,717 Sampling index for D:\cassandra\data\data\system\LocationInfo-e-10-<> INFO 13:38:04,717 Sampling index for D:\cassandra\data\data\system\LocationInfo-e-11-<> INFO 13:38:04,717 Sampling index for D:\cassandra\data\data\system\HintsColumnFamily-e-24-<> INFO 13:38:04,732 Sampling index for D:\cassandra\data\data\system\HintsColumnFamily-e-25-<> INFO 13:38:04,732 Sampling index for D:\cassandra\data\data\system\HintsColumnFamily-e-26-<> INFO 13:38:04,732 Sampling index for D:\cassandra\data\data\system\HintsColumnFamily-e-28-<> INFO 13:38:04,732 Sampling index for D:\cassandra\data\data\system\HintsColumnFamily-e-30-<> INFO 13:38:04,732 Sampling index for D:\cassandra\data\data\system\HintsColumnFamily-e-33-<> INFO 13:38:04,763 Loading schema version 6e908998-aa17-11df-bf55-cacedb26d926 INFO 13:38:05,013 Sampling index for D:\cassandra\data\data\BehavioralTargeting\CookieTrackingSetupMemberships-e-25-<> INFO 13:38:07,588 Sampling index for D:\cassandra\data\data\BehavioralTargeting\CookieTrackingSetupMemberships-e-150-<> INFO 13:38:10,837 Sampling index for D:\cassandra\data\data\BehavioralTargeting\CookieTrackingSetupMemberships-e-279-<> INFO 13:38:14,550 Sampling index for D:\cassandra\data\data\BehavioralTargeting\CookieTrackingSetupMemberships-e-412-<> INFO 13:38:17,747 Sampling index for D:\cassandra\data\data\BehavioralTargeting\CookieTrackingSetupMemberships-e-461-<> INFO 13:38:18,948 Creating new commitlog segment E:/cassandra/data/commitlog\CommitLog-1283513898948.log INFO 13:38:18,964 Deleted D:\cassandra\data\data\BehavioralTargeting\CookieTrackingSetupMemberships-e-470-Data.db INFO 13:38:18,964 Deleted D:\cassandra\data\data\BehavioralTargeting\CookieTrackingSetupMemberships-e-479-Data.db INFO 13:38:18,979 Deleted D:\cassandra\data\data\BehavioralTargeting\CookieTrackingSetupMemberships-e-492-Data.db INFO 13:38:18,979 Deleted D:\cassandra\data\data\BehavioralTargeting\CookieTrackingSetupMemberships-e-497-Data.db INFO 13:38:18,979 Sampling index for D:\cassandra\data\data\BehavioralTargeting\CookieTrackingSetupMemberships-e-498-<> INFO 13:38:20,118 Replaying E:\cassandra\data\commitlog\CommitLog-1283513833929.log, E:\cassandra\data\commitlog\CommitLog-1283513898948.log INFO 13:38:20,134 E:\cassandra\data\commitlog\CommitLog-1283513833929.log.header incomplete, missing or corrupt. Everything is ok, don't panic. CommitLog will be replayed from the beginning INFO 13:38:20,150 Finished reading E:\cassandra\data\commitlog\CommitLog-1283513833929.log INFO 13:38:20,150 Finished reading E:\cassandra\data\commitlog\CommitLog-1283513898948.log INFO 13:38:20,150 switching in a fresh Memtable for Statistics at CommitLogContext(file='E:/cassandra/data/commitlog\CommitLog-1283513898948.log', position=592) INFO 13:38:20,165 Enqueuing flush of Memtable-Statistics@1582759704(15004 bytes, 4 operations) INFO 13:38:20,165 Writing Memtable-Statistics@1582759704(15004 bytes, 4 operations) INFO 13:38:20,508 Completed flushing D:\cassandra\data\data\system\Statistics-e-503-Data.db INFO 13:38:20,508 Recovery complete ERROR 13:38:20,508 Exception encountered during startup. java.io.IOException: Failed to delete E:\cassandra\data\commitlog\CommitLog-1283513898948.log at org.apache.cassandra.io.util.FileUtils.deleteWithConfirm(FileUtils.java:45) at org.apache.cassandra.db.commitlog.CommitLog.recover(CommitLog.java:178) at org.apache.cassandra.thrift.CassandraDaemon.setup(CassandraDaemon.java:120) at org.apache.cassandra.service.AbstractCassandraDaemon.init(AbstractCassandraDaemon.java:57) at org.apache.cassandra.contrib.windows.service.WindowsService.start(Unknown Source) at org.apache.cassandra.contrib.windows.service.WindowsService.main(Unknown Source) INFO 13:38:20,555 Exception encountered during startup. INFO 13:38:20,555 Cassandra Service Finished: Fri Sep 03 13:38:20 CEST 2010
        Hide
        jbellis Jonathan Ellis added a comment -

        it logs "Finished reading" which means it's successfully closed the reader, so there's nothing in Cassandra blocking the delete. patch -2 makes failure to delete a non-fatal error.

        Show
        jbellis Jonathan Ellis added a comment - it logs "Finished reading" which means it's successfully closed the reader, so there's nothing in Cassandra blocking the delete. patch -2 makes failure to delete a non-fatal error.
        Hide
        jbellis Jonathan Ellis added a comment -

        backported try/finally from original patch to 0.6. (failure to delete is already non-fatal there.)

        Show
        jbellis Jonathan Ellis added a comment - backported try/finally from original patch to 0.6. (failure to delete is already non-fatal there.)
        Hide
        gdusbabek Gary Dusbabek added a comment -

        +1 on the new patch.

        Show
        gdusbabek Gary Dusbabek added a comment - +1 on the new patch.
        Hide
        jbellis Jonathan Ellis added a comment -

        committed

        Show
        jbellis Jonathan Ellis added a comment - committed

          People

          • Assignee:
            jbellis Jonathan Ellis
            Reporter:
            vjevdokimov Viktor Jevdokimov
            Reviewer:
            Gary Dusbabek
          • Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development