You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@flume.apache.org by Hari Shreedharan <hs...@cloudera.com> on 2013/04/11 03:09:37 UTC

Review Request: FLUME-1986. doTestInflightCorrupts should not commit transactions

-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/10415/
-----------------------------------------------------------

Review request for Flume.


Description
-------

Increase sleeps so forceCheckpoint does not fail because the copy is not completed.


This addresses bug FLUME-1986.
    https://issues.apache.org/jira/browse/FLUME-1986


Diffs
-----

  flume-ng-channels/flume-file-channel/src/test/java/org/apache/flume/channel/file/TestFileChannelRestart.java fb0e208 
  flume-ng-channels/flume-file-channel/src/test/java/org/apache/flume/channel/file/TestUtils.java 7c490b5 

Diff: https://reviews.apache.org/r/10415/diff/


Testing
-------

Ran full tests.


Thanks,

Hari Shreedharan

Re: Review Request: FLUME-1986. doTestInflightCorrupts should not commit transactions

Posted by Juhani Connolly <ju...@gmail.com>.
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/10415/#review19150
-----------------------------------------------------------

Ship it!


Okay, this appears to fix the issues, committing it

- Juhani Connolly


On April 12, 2013, 10:49 p.m., Hari Shreedharan wrote:
> 
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/10415/
> -----------------------------------------------------------
> 
> (Updated April 12, 2013, 10:49 p.m.)
> 
> 
> Review request for Flume.
> 
> 
> Description
> -------
> 
> Increase sleeps so forceCheckpoint does not fail because the copy is not completed.
> 
> 
> This addresses bug FLUME-1986.
>     https://issues.apache.org/jira/browse/FLUME-1986
> 
> 
> Diffs
> -----
> 
>   flume-ng-channels/flume-file-channel/src/test/java/org/apache/flume/channel/file/TestFileChannelRestart.java fb0e208 
>   flume-ng-channels/flume-file-channel/src/test/java/org/apache/flume/channel/file/TestUtils.java 7c490b5 
> 
> Diff: https://reviews.apache.org/r/10415/diff/
> 
> 
> Testing
> -------
> 
> Ran full tests.
> 
> 
> Thanks,
> 
> Hari Shreedharan
> 
>

Re: Review Request: FLUME-1986. doTestInflightCorrupts should not commit transactions

Posted by Hari Shreedharan <hs...@cloudera.com>.
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/10415/
-----------------------------------------------------------

(Updated April 12, 2013, 10:49 p.m.)


Review request for Flume.


Description
-------

Increase sleeps so forceCheckpoint does not fail because the copy is not completed.


This addresses bug FLUME-1986.
    https://issues.apache.org/jira/browse/FLUME-1986


Diffs (updated)
-----

  flume-ng-channels/flume-file-channel/src/test/java/org/apache/flume/channel/file/TestFileChannelRestart.java fb0e208 
  flume-ng-channels/flume-file-channel/src/test/java/org/apache/flume/channel/file/TestUtils.java 7c490b5 

Diff: https://reviews.apache.org/r/10415/diff/


Testing
-------

Ran full tests.


Thanks,

Hari Shreedharan

Re: Review Request: FLUME-1986. doTestInflightCorrupts should not commit transactions

Posted by Hari Shreedharan <hs...@cloudera.com>.

> On April 12, 2013, 9:37 a.m., Juhani Connolly wrote:
> > The tests still don't pass in our environment, failing on the assertion
> >  Assert.assertTrue(!backup || channel.checkpointBackupRestored())
> > 
> > Relevant from the surefire-reports:
> > 
> >   <testcase time="7.258" classname="org.apache.flume.channel.file.TestFileChannelRestart" name="testCorruptInflightTakesWithBackup">
> >     <failure type="java.lang.AssertionError">java.lang.AssertionError
> >         at org.junit.Assert.fail(Assert.java:92)
> >         at org.junit.Assert.assertTrue(Assert.java:43)
> >         at org.junit.Assert.assertTrue(Assert.java:54)
> >         at org.apache.flume.channel.file.TestFileChannelRestart.doTestCorruptInflights(TestFileChannelRestart.java:514)
> >         at org.apache.flume.channel.file.TestFileChannelRestart.testCorruptInflightTakesWithBackup(TestFileChannelRestart.java:431)
> >         at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> >         at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
> >         at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
> >         at java.lang.reflect.Method.invoke(Method.java:597)
> > ...
> > </failure>
> >     <system-out>2013-04-12 18:16:16,498 (main) [INFO - org.apache.flume.channel.file.FileChannel.start(FileChannel.java:281)] Starting FileChannel FileChannel-3d21a8cc-6f46-45c4-8dee-ac5fd530c934 { dataDirs: [/tmp/1365758176497-0/data1, 
> > /tmp/1365758176497-0/data2, /tmp/1365758176497-0/data3] }...
> > 2013-04-12 18:16:16,499 (main) [INFO - org.apache.flume.channel.file.Log.&lt;init&gt;(Log.java:321)] Encryption is not enabled
> > 2013-04-12 18:16:16,499 (main) [INFO - org.apache.flume.channel.file.Log.replay(Log.java:368)] Replay started
> > 2013-04-12 18:16:16,500 (main) [INFO - org.apache.flume.channel.file.Log.replay(Log.java:380)] Found NextFileID 0, from []
> > 2013-04-12 18:16:16,504 (main) [INFO - org.apache.flume.channel.file.EventQueueBackingStoreFile.&lt;init&gt;(EventQueueBackingStoreFile.java:91)] Preallocated /tmp/1365758176497-0/chkpt/checkpoint to 88232 for capacity 10000
> > 2013-04-12 18:16:16,505 (main) [INFO - org.apache.flume.channel.file.EventQueueBackingStoreFileV3.&lt;init&gt;(EventQueueBackingStoreFileV3.java:53)] Starting up with /tmp/1365758176497-0/chkpt/checkpoint and /tmp/1365758176497-0/chkpt/c
> > heckpoint.meta
> > 2013-04-12 18:16:16,507 (main) [INFO - org.apache.flume.channel.file.Log.replay(Log.java:417)] Last Checkpoint Fri Apr 12 18:16:16 JST 2013, queue depth = 0
> > 2013-04-12 18:16:16,507 (main) [INFO - org.apache.flume.channel.file.Log.doReplay(Log.java:498)] Replaying logs with v2 replay logic
> > 2013-04-12 18:16:16,507 (main) [INFO - org.apache.flume.channel.file.ReplayHandler.replayLog(ReplayHandler.java:244)] Starting replay of []
> > 2013-04-12 18:16:16,507 (main) [INFO - org.apache.flume.channel.file.ReplayHandler.replayLog(ReplayHandler.java:338)] read: 0, put: 0, take: 0, rollback: 0, commit: 0, skip: 0, eventCount:0
> > 2013-04-12 18:16:16,508 (main) [INFO - org.apache.flume.channel.file.Log.replay(Log.java:461)] Rolling /tmp/1365758176497-0/data1
> > 2013-04-12 18:16:16,508 (main) [INFO - org.apache.flume.channel.file.Log.roll(Log.java:922)] Roll start /tmp/1365758176497-0/data1
> > 2013-04-12 18:16:16,508 (main) [INFO - org.apache.flume.channel.file.LogFile$Writer.&lt;init&gt;(LogFile.java:169)] Opened /tmp/1365758176497-0/data1/log-1
> > 2013-04-12 18:16:16,510 (main) [INFO - org.apache.flume.channel.file.Log.roll(Log.java:937)] Roll end
> > 2013-04-12 18:16:16,510 (main) [INFO - org.apache.flume.channel.file.Log.replay(Log.java:461)] Rolling /tmp/1365758176497-0/data2
> > 2013-04-12 18:16:16,511 (main) [INFO - org.apache.flume.channel.file.Log.roll(Log.java:922)] Roll start /tmp/1365758176497-0/data2
> > 2013-04-12 18:16:16,511 (main) [INFO - org.apache.flume.channel.file.LogFile$Writer.&lt;init&gt;(LogFile.java:169)] Opened /tmp/1365758176497-0/data2/log-2
> > 2013-04-12 18:16:16,513 (main) [INFO - org.apache.flume.channel.file.Log.roll(Log.java:937)] Roll end
> > 2013-04-12 18:16:16,513 (main) [INFO - org.apache.flume.channel.file.Log.replay(Log.java:461)] Rolling /tmp/1365758176497-0/data3
> > 2013-04-12 18:16:16,513 (main) [INFO - org.apache.flume.channel.file.Log.roll(Log.java:922)] Roll start /tmp/1365758176497-0/data3
> > 2013-04-12 18:16:16,514 (main) [INFO - org.apache.flume.channel.file.LogFile$Writer.&lt;init&gt;(LogFile.java:169)] Opened /tmp/1365758176497-0/data3/log-3
> > 2013-04-12 18:16:16,516 (main) [INFO - org.apache.flume.channel.file.Log.roll(Log.java:937)] Roll end
> > 2013-04-12 18:16:16,516 (main) [INFO - org.apache.flume.channel.file.EventQueueBackingStoreFile.beginCheckpoint(EventQueueBackingStoreFile.java:215)] Start checkpoint for /tmp/1365758176497-0/chkpt/checkpoint, elements to sync = 0
> > 2013-04-12 18:16:16,520 (main) [INFO - org.apache.flume.channel.file.EventQueueBackingStoreFile.checkpoint(EventQueueBackingStoreFile.java:240)] Updating checkpoint metadata: logWriteOrderID: 1365758273442, queueSize: 0, queueHead: 0
> > 2013-04-12 18:16:16,521 (main) [INFO - org.apache.flume.channel.file.EventQueueBackingStoreFile.startBackupThread(EventQueueBackingStoreFile.java:276)] Attempting to back up checkpoint.
> > 2013-04-12 18:16:16,522 ([channel=FileChannel-3d21a8cc-6f46-45c4-8dee-ac5fd530c934] - CheckpointBackUpThread) [INFO - org.apache.flume.channel.file.Serialization.deleteAllFiles(Serialization.java:100)] Skipping in_use.lock because it is 
> > in excludes set
> > 2013-04-12 18:16:16,522 ([channel=FileChannel-3d21a8cc-6f46-45c4-8dee-ac5fd530c934] - CheckpointBackUpThread) [INFO - org.apache.flume.channel.file.Serialization.deleteAllFiles(Serialization.java:113)] Deleted the following files: .
> > 2013-04-12 18:16:16,524 (main) [INFO - org.apache.flume.channel.file.Log.writeCheckpoint(Log.java:997)] Updated checkpoint for file: /tmp/1365758176497-0/data1/log-1 position: 0 logWriteOrderID: 1365758273442
> > 2013-04-12 18:16:16,535 (main) [INFO - org.apache.flume.channel.file.Log.writeCheckpoint(Log.java:997)] Updated checkpoint for file: /tmp/1365758176497-0/data2/log-2 position: 0 logWriteOrderID: 1365758273442
> > 2013-04-12 18:16:16,539 (main) [INFO - org.apache.flume.channel.file.Log.writeCheckpoint(Log.java:997)] Updated checkpoint for file: /tmp/1365758176497-0/data3/log-3 position: 0 logWriteOrderID: 1365758273442
> > 2013-04-12 18:16:16,540 (main) [INFO - org.apache.flume.channel.file.FileChannel.start(FileChannel.java:307)] Queue Size after replay: 0 [channel=FileChannel-3d21a8cc-6f46-45c4-8dee-ac5fd530c934]
> > 2013-04-12 18:16:16,540 ([channel=FileChannel-3d21a8cc-6f46-45c4-8dee-ac5fd530c934] - CheckpointBackUpThread) [INFO - org.apache.flume.channel.file.EventQueueBackingStoreFile$1.run(EventQueueBackingStoreFile.java:291)] Checkpoint backup 
> > completed.
> > 2013-04-12 18:16:16,540 (main) [INFO - org.apache.flume.instrumentation.MonitoredCounterGroup.register(MonitoredCounterGroup.java:89)] Monitoried counter group for type: CHANNEL, name: FileChannel-3d21a8cc-6f46-45c4-8dee-ac5fd530c934, re
> > gistered successfully.
> > 2013-04-12 18:16:16,540 (main) [INFO - org.apache.flume.instrumentation.MonitoredCounterGroup.start(MonitoredCounterGroup.java:73)] Component type: CHANNEL, name: FileChannel-3d21a8cc-6f46-45c4-8dee-ac5fd530c934 started
> > 2013-04-12 18:16:16,541 (main) [DEBUG - org.apache.flume.channel.file.LogFile$Writer.preallocate(LogFile.java:290)] Preallocating at position 0
> > 2013-04-12 18:16:21,544 (main) [INFO - org.apache.flume.channel.file.EventQueueBackingStoreFile.beginCheckpoint(EventQueueBackingStoreFile.java:215)] Start checkpoint for /tmp/1365758176497-0/chkpt/checkpoint, elements to sync = 0
> > 2013-04-12 18:16:21,551 (main) [DEBUG - org.apache.flume.channel.file.FlumeEventQueue$InflightEventWrapper.serializeAndWrite(FlumeEventQueue.java:422)] Number of events inserted into inflights file: 100 file: /tmp/1365758176497-0/chkpt/i
> > nflightputs
> > 2013-04-12 18:16:21,560 (main) [INFO - org.apache.flume.channel.file.EventQueueBackingStoreFile.checkpoint(EventQueueBackingStoreFile.java:240)] Updating checkpoint metadata: logWriteOrderID: 1365758273543, queueSize: 0, queueHead: 0
> > 2013-04-12 18:16:21,566 (main) [INFO - org.apache.flume.channel.file.EventQueueBackingStoreFile.startBackupThread(EventQueueBackingStoreFile.java:276)] Attempting to back up checkpoint.
> > 2013-04-12 18:16:21,570 ([channel=FileChannel-3d21a8cc-6f46-45c4-8dee-ac5fd530c934] - CheckpointBackUpThread) [INFO - org.apache.flume.channel.file.Serialization.deleteAllFiles(Serialization.java:100)] Skipping in_use.lock because it is 
> > in excludes set
> > 2013-04-12 18:16:21,571 ([channel=FileChannel-3d21a8cc-6f46-45c4-8dee-ac5fd530c934] - CheckpointBackUpThread) [INFO - org.apache.flume.channel.file.Serialization.deleteAllFiles(Serialization.java:113)] Deleted the following files: , infl
> > ighttakes, checkpoint.meta, checkpoint, inflightputs.
> > 2013-04-12 18:16:21,580 (main) [INFO - org.apache.flume.channel.file.Log.writeCheckpoint(Log.java:997)] Updated checkpoint for file: /tmp/1365758176497-0/data1/log-1 position: 0 logWriteOrderID: 1365758273543
> > 2013-04-12 18:16:21,587 (main) [INFO - org.apache.flume.channel.file.Log.writeCheckpoint(Log.java:997)] Updated checkpoint for file: /tmp/1365758176497-0/data2/log-2 position: 7800 logWriteOrderID: 1365758273543
> > 2013-04-12 18:16:21,589 (main) [INFO - org.apache.flume.channel.file.Log.writeCheckpoint(Log.java:997)] Updated checkpoint for file: /tmp/1365758176497-0/data3/log-3 position: 0 logWriteOrderID: 1365758273543
> > 2013-04-12 18:16:21,590 (main) [DEBUG - org.apache.flume.channel.file.Log.removeOldLogs(Log.java:1058)] Files currently in use: [1, 2, 3]
> > 2013-04-12 18:16:21,591 ([channel=FileChannel-3d21a8cc-6f46-45c4-8dee-ac5fd530c934] - CheckpointBackUpThread) [INFO - org.apache.flume.channel.file.EventQueueBackingStoreFile$1.run(EventQueueBackingStoreFile.java:291)] Checkpoint backup completed.
> > 2013-04-12 18:16:23,605 (main) [INFO - org.apache.flume.channel.file.FileChannel.stop(FileChannel.java:327)] Stopping FileChannel FileChannel-3d21a8cc-6f46-45c4-8dee-ac5fd530c934 { dataDirs: [/tmp/1365758176497-0/data1, /tmp/1365758176497-0/data2, /tmp/1365758176497-0/data3] }...
> > Attempting to shutdown background worker.
> > 2013-04-12 18:16:23,619 (main) [INFO - org.apache.flume.channel.file.Log.shutdownWorker(Log.java:821)] Attempting to shutdown background worker.
> > 2013-04-12 18:16:23,619 (main) [INFO - org.apache.flume.channel.file.LogFile$Writer.close(LogFile.java:273)] Closing /tmp/1365758176497-0/data1/log-1
> > 2013-04-12 18:16:23,619 (main) [INFO - org.apache.flume.channel.file.LogFile$Writer.close(LogFile.java:273)] Closing /tmp/1365758176497-0/data2/log-2
> > 2013-04-12 18:16:23,619 (main) [INFO - org.apache.flume.channel.file.LogFile$Writer.close(LogFile.java:273)] Closing /tmp/1365758176497-0/data3/log-3
> > 2013-04-12 18:16:23,619 (main) [INFO - org.apache.flume.channel.file.LogFile$RandomReader.close(LogFile.java:354)] Closing RandomReader /tmp/1365758176497-0/data1/log-1
> > 2013-04-12 18:16:23,625 (main) [INFO - org.apache.flume.channel.file.LogFile$RandomReader.close(LogFile.java:354)] Closing RandomReader /tmp/1365758176497-0/data2/log-2
> > 2013-04-12 18:16:23,631 (main) [INFO - org.apache.flume.channel.file.LogFile$RandomReader.close(LogFile.java:354)] Closing RandomReader /tmp/1365758176497-0/data3/log-3
> > 2013-04-12 18:16:23,638 (main) [INFO - org.apache.flume.instrumentation.MonitoredCounterGroup.stop(MonitoredCounterGroup.java:100)] Component type: CHANNEL, name: FileChannel-3d21a8cc-6f46-45c4-8dee-ac5fd530c934 stopped
> > 2013-04-12 18:16:23,638 (main) [INFO - org.apache.flume.channel.file.FileChannel.start(FileChannel.java:281)] Starting FileChannel FileChannel-5de59d23-c19a-424a-a407-9209741e3e00 { dataDirs: [/tmp/1365758176497-0/data1, /tmp/1365758176497-0/data2, /tmp/1365758176497-0/data3] }...
> > 2013-04-12 18:16:23,639 (main) [INFO - org.apache.flume.channel.file.Log.&lt;init&gt;(Log.java:321)] Encryption is not enabled
> > 2013-04-12 18:16:23,639 (main) [INFO - org.apache.flume.channel.file.Log.replay(Log.java:368)] Replay started
> > 2013-04-12 18:16:23,643 (main) [INFO - org.apache.flume.channel.file.Log.replay(Log.java:380)] Found NextFileID 3, from [/tmp/1365758176497-0/data1/log-1, /tmp/1365758176497-0/data2/log-2, /tmp/1365758176497-0/data3/log-3]
> > 2013-04-12 18:16:23,644 (main) [INFO - org.apache.flume.channel.file.EventQueueBackingStoreFileV3.&lt;init&gt;(EventQueueBackingStoreFileV3.java:53)] Starting up with /tmp/1365758176497-0/chkpt/checkpoint and /tmp/1365758176497-0/chkpt/checkpoint.meta
> > 2013-04-12 18:16:23,644 (main) [INFO - org.apache.flume.channel.file.EventQueueBackingStoreFileV3.&lt;init&gt;(EventQueueBackingStoreFileV3.java:57)] Reading checkpoint metadata from /tmp/1365758176497-0/chkpt/checkpoint.meta
> > 2013-04-12 18:16:23,644 (main) [INFO - org.apache.flume.channel.file.Log.replay(Log.java:417)] Last Checkpoint Fri Apr 12 18:16:21 JST 2013, queue depth = 0
> > 2013-04-12 18:16:23,645 (main) [INFO - org.apache.flume.channel.file.Log.doReplay(Log.java:498)] Replaying logs with v2 replay logic
> > 2013-04-12 18:16:23,645 (main) [INFO - org.apache.flume.channel.file.ReplayHandler.replayLog(ReplayHandler.java:244)] Starting replay of [/tmp/1365758176497-0/data1/log-1, /tmp/1365758176497-0/data2/log-2, /tmp/1365758176497-0/data3/log-3]
> > 2013-04-12 18:16:23,645 (main) [DEBUG - org.apache.flume.channel.file.FlumeEventQueue$InflightEventWrapper.deserialize(FlumeEventQueue.java:482)] Reached end of inflights buffer. Long buffer position =104
> > 2013-04-12 18:16:23,646 (main) [DEBUG - org.apache.flume.channel.file.FlumeEventQueue$InflightEventWrapper.deserialize(FlumeEventQueue.java:482)] Reached end of inflights buffer. Long buffer position =2
> > 2013-04-12 18:16:23,646 (main) [INFO - org.apache.flume.channel.file.ReplayHandler.replayLog(ReplayHandler.java:257)] Replaying /tmp/1365758176497-0/data1/log-1
> > 2013-04-12 18:16:23,646 (main) [INFO - org.apache.flume.channel.file.LogFile$SequentialReader.skipToLastCheckpointPosition(LogFile.java:484)] Checkpoint for file(/tmp/1365758176497-0/data1/log-1) is: 1365758273543, which is beyond the requested checkpoint time: 1365758273543 and position 0
> > 2013-04-12 18:16:23,646 (main) [INFO - org.apache.flume.channel.file.ReplayHandler.replayLog(ReplayHandler.java:257)] Replaying /tmp/1365758176497-0/data2/log-2
> > 2013-04-12 18:16:23,647 (main) [INFO - org.apache.flume.channel.file.LogFile$SequentialReader.skipToLastCheckpointPosition(LogFile.java:482)] fast-forward to checkpoint position: 7800
> > 2013-04-12 18:16:23,647 (main) [INFO - org.apache.flume.channel.file.ReplayHandler.replayLog(ReplayHandler.java:257)] Replaying /tmp/1365758176497-0/data3/log-3
> > 2013-04-12 18:16:23,647 (main) [INFO - org.apache.flume.channel.file.LogFile$SequentialReader.skipToLastCheckpointPosition(LogFile.java:484)] Checkpoint for file(/tmp/1365758176497-0/data3/log-3) is: 1365758273543, which is beyond the requested checkpoint time: 1365758273543 and position 0
> > 2013-04-12 18:16:23,647 (main) [INFO - org.apache.flume.channel.file.LogFile$SequentialReader.next(LogFile.java:505)] Encountered EOF at 7836 in /tmp/1365758176497-0/data2/log-2
> > 2013-04-12 18:16:23,647 (main) [INFO - org.apache.flume.channel.file.ReplayHandler.replayLog(ReplayHandler.java:338)] read: 1, put: 0, take: 0, rollback: 0, commit: 1, skip: 0, eventCount:100
> > 2013-04-12 18:16:23,647 (main) [INFO - org.apache.flume.channel.file.Log.replay(Log.java:461)] Rolling /tmp/1365758176497-0/data1
> > 2013-04-12 18:16:23,647 (main) [INFO - org.apache.flume.channel.file.Log.roll(Log.java:922)] Roll start /tmp/1365758176497-0/data1
> > 2013-04-12 18:16:23,648 (main) [INFO - org.apache.flume.channel.file.LogFile$Writer.&lt;init&gt;(LogFile.java:169)] Opened /tmp/1365758176497-0/data1/log-4
> > 2013-04-12 18:16:23,650 (main) [INFO - org.apache.flume.channel.file.Log.roll(Log.java:937)] Roll end
> > 2013-04-12 18:16:23,650 (main) [INFO - org.apache.flume.channel.file.Log.replay(Log.java:461)] Rolling /tmp/1365758176497-0/data2
> > 2013-04-12 18:16:23,650 (main) [INFO - org.apache.flume.channel.file.Log.roll(Log.java:922)] Roll start /tmp/1365758176497-0/data2
> > 2013-04-12 18:16:23,650 (main) [INFO - org.apache.flume.channel.file.LogFile$Writer.&lt;init&gt;(LogFile.java:169)] Opened /tmp/1365758176497-0/data2/log-5
> > 2013-04-12 18:16:23,652 (main) [INFO - org.apache.flume.channel.file.Log.roll(Log.java:937)] Roll end
> > 2013-04-12 18:16:23,652 (main) [INFO - org.apache.flume.channel.file.Log.replay(Log.java:461)] Rolling /tmp/1365758176497-0/data3
> > 2013-04-12 18:16:23,652 (main) [INFO - org.apache.flume.channel.file.Log.roll(Log.java:922)] Roll start /tmp/1365758176497-0/data3
> > 2013-04-12 18:16:23,652 (main) [INFO - org.apache.flume.channel.file.LogFile$Writer.&lt;init&gt;(LogFile.java:169)] Opened /tmp/1365758176497-0/data3/log-6
> > 2013-04-12 18:16:23,654 (main) [INFO - org.apache.flume.channel.file.Log.roll(Log.java:937)] Roll end
> > 2013-04-12 18:16:23,654 (main) [INFO - org.apache.flume.channel.file.EventQueueBackingStoreFile.beginCheckpoint(EventQueueBackingStoreFile.java:215)] Start checkpoint for /tmp/1365758176497-0/chkpt/checkpoint, elements to sync = 100
> > 2013-04-12 18:16:23,658 (main) [INFO - org.apache.flume.channel.file.EventQueueBackingStoreFile.checkpoint(EventQueueBackingStoreFile.java:240)] Updating checkpoint metadata: logWriteOrderID: 1365758273545, queueSize: 100, queueHead: 9998
> > 2013-04-12 18:16:23,660 (main) [INFO - org.apache.flume.channel.file.EventQueueBackingStoreFile.startBackupThread(EventQueueBackingStoreFile.java:276)] Attempting to back up checkpoint.
> > 2013-04-12 18:16:23,661 ([channel=FileChannel-5de59d23-c19a-424a-a407-9209741e3e00] - CheckpointBackUpThread) [INFO - org.apache.flume.channel.file.Serialization.deleteAllFiles(Serialization.java:100)] Skipping in_use.lock because it is in excludes set
> > 2013-04-12 18:16:23,663 ([channel=FileChannel-5de59d23-c19a-424a-a407-9209741e3e00] - CheckpointBackUpThread) [INFO - org.apache.flume.channel.file.Serialization.deleteAllFiles(Serialization.java:113)] Deleted the following files: , inflighttakes, checkpoint.meta, checkpoint, inflightputs.
> > 2013-04-12 18:16:23,663 (main) [INFO - org.apache.flume.channel.file.Log.writeCheckpoint(Log.java:997)] Updated checkpoint for file: /tmp/1365758176497-0/data1/log-4 position: 0 logWriteOrderID: 1365758273545
> > 2013-04-12 18:16:23,673 (main) [INFO - org.apache.flume.channel.file.Log.writeCheckpoint(Log.java:997)] Updated checkpoint for file: /tmp/1365758176497-0/data2/log-5 position: 0 logWriteOrderID: 1365758273545
> > 2013-04-12 18:16:23,677 (main) [INFO - org.apache.flume.channel.file.Log.writeCheckpoint(Log.java:997)] Updated checkpoint for file: /tmp/1365758176497-0/data3/log-6 position: 0 logWriteOrderID: 1365758273545
> > 2013-04-12 18:16:23,678 (main) [INFO - org.apache.flume.channel.file.LogFile$RandomReader.close(LogFile.java:354)] Closing RandomReader /tmp/1365758176497-0/data2/log-2
> > 2013-04-12 18:16:23,682 ([channel=FileChannel-5de59d23-c19a-424a-a407-9209741e3e00] - CheckpointBackUpThread) [INFO - org.apache.flume.channel.file.EventQueueBackingStoreFile$1.run(EventQueueBackingStoreFile.java:291)] Checkpoint backup completed.
> > 2013-04-12 18:16:23,685 (main) [DEBUG - org.apache.flume.channel.file.Log.writeCheckpoint(Log.java:1017)] Updated checkpoint for file: /tmp/1365758176497-0/data2/log-2logWriteOrderID 1365758273545
> > 2013-04-12 18:16:23,686 (main) [INFO - org.apache.flume.channel.file.FileChannel.start(FileChannel.java:307)] Queue Size after replay: 100 [channel=FileChannel-5de59d23-c19a-424a-a407-9209741e3e00]
> > 2013-04-12 18:16:23,686 (main) [INFO - org.apache.flume.instrumentation.MonitoredCounterGroup.register(MonitoredCounterGroup.java:89)] Monitoried counter group for type: CHANNEL, name: FileChannel-5de59d23-c19a-424a-a407-9209741e3e00, registered successfully.
> > 2013-04-12 18:16:23,686 (main) [INFO - org.apache.flume.instrumentation.MonitoredCounterGroup.start(MonitoredCounterGroup.java:73)] Component type: CHANNEL, name: FileChannel-5de59d23-c19a-424a-a407-9209741e3e00 started
> > 2013-04-12 18:16:23,686 (main) [INFO - org.apache.flume.channel.file.FileChannel.stop(FileChannel.java:327)] Stopping FileChannel FileChannel-5de59d23-c19a-424a-a407-9209741e3e00 { dataDirs: [/tmp/1365758176497-0/data1, /tmp/1365758176497-0/data2, /tmp/1365758176497-0/data3] }...
> > Attempting to shutdown background worker.
> > 2013-04-12 18:16:23,686 (main) [INFO - org.apache.flume.channel.file.Log.shutdownWorker(Log.java:821)] Attempting to shutdown background worker.
> > 2013-04-12 18:16:23,687 (main) [INFO - org.apache.flume.channel.file.LogFile$Writer.close(LogFile.java:273)] Closing /tmp/1365758176497-0/data1/log-4
> > 2013-04-12 18:16:23,687 (main) [INFO - org.apache.flume.channel.file.LogFile$Writer.close(LogFile.java:273)] Closing /tmp/1365758176497-0/data2/log-5
> > 2013-04-12 18:16:23,687 (main) [INFO - org.apache.flume.channel.file.LogFile$Writer.close(LogFile.java:273)] Closing /tmp/1365758176497-0/data3/log-6
> > 2013-04-12 18:16:23,687 (main) [INFO - org.apache.flume.channel.file.LogFile$RandomReader.close(LogFile.java:354)] Closing RandomReader /tmp/1365758176497-0/data1/log-1
> > 2013-04-12 18:16:23,692 (main) [INFO - org.apache.flume.channel.file.LogFile$RandomReader.close(LogFile.java:354)] Closing RandomReader /tmp/1365758176497-0/data2/log-2
> > 2013-04-12 18:16:23,698 (main) [INFO - org.apache.flume.channel.file.LogFile$RandomReader.close(LogFile.java:354)] Closing RandomReader /tmp/1365758176497-0/data3/log-3
> > 2013-04-12 18:16:23,704 (main) [INFO - org.apache.flume.channel.file.LogFile$RandomReader.close(LogFile.java:354)] Closing RandomReader /tmp/1365758176497-0/data1/log-4
> > 2013-04-12 18:16:23,711 (main) [INFO - org.apache.flume.channel.file.LogFile$RandomReader.close(LogFile.java:354)] Closing RandomReader /tmp/1365758176497-0/data2/log-5
> > 2013-04-12 18:16:23,716 (main) [INFO - org.apache.flume.channel.file.LogFile$RandomReader.close(LogFile.java:354)] Closing RandomReader /tmp/1365758176497-0/data3/log-6
> > 2013-04-12 18:16:23,723 (main) [INFO - org.apache.flume.instrumentation.MonitoredCounterGroup.stop(MonitoredCounterGroup.java:100)] Component type: CHANNEL, name: FileChannel-5de59d23-c19a-424a-a407-9209741e3e00 stopped
> > </system-out>
> >

Can you give the new patch a try? At this point, I cannot reproduce this issue anymore.


- Hari


-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/10415/#review19059
-----------------------------------------------------------


On April 12, 2013, 10:49 p.m., Hari Shreedharan wrote:
> 
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/10415/
> -----------------------------------------------------------
> 
> (Updated April 12, 2013, 10:49 p.m.)
> 
> 
> Review request for Flume.
> 
> 
> Description
> -------
> 
> Increase sleeps so forceCheckpoint does not fail because the copy is not completed.
> 
> 
> This addresses bug FLUME-1986.
>     https://issues.apache.org/jira/browse/FLUME-1986
> 
> 
> Diffs
> -----
> 
>   flume-ng-channels/flume-file-channel/src/test/java/org/apache/flume/channel/file/TestFileChannelRestart.java fb0e208 
>   flume-ng-channels/flume-file-channel/src/test/java/org/apache/flume/channel/file/TestUtils.java 7c490b5 
> 
> Diff: https://reviews.apache.org/r/10415/diff/
> 
> 
> Testing
> -------
> 
> Ran full tests.
> 
> 
> Thanks,
> 
> Hari Shreedharan
> 
>

Re: Review Request: FLUME-1986. doTestInflightCorrupts should not commit transactions

Posted by Juhani Connolly <ju...@gmail.com>.
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/10415/#review19059
-----------------------------------------------------------


The tests still don't pass in our environment, failing on the assertion
 Assert.assertTrue(!backup || channel.checkpointBackupRestored())

Relevant from the surefire-reports:

  <testcase time="7.258" classname="org.apache.flume.channel.file.TestFileChannelRestart" name="testCorruptInflightTakesWithBackup">
    <failure type="java.lang.AssertionError">java.lang.AssertionError
        at org.junit.Assert.fail(Assert.java:92)
        at org.junit.Assert.assertTrue(Assert.java:43)
        at org.junit.Assert.assertTrue(Assert.java:54)
        at org.apache.flume.channel.file.TestFileChannelRestart.doTestCorruptInflights(TestFileChannelRestart.java:514)
        at org.apache.flume.channel.file.TestFileChannelRestart.testCorruptInflightTakesWithBackup(TestFileChannelRestart.java:431)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:597)
...
</failure>
    <system-out>2013-04-12 18:16:16,498 (main) [INFO - org.apache.flume.channel.file.FileChannel.start(FileChannel.java:281)] Starting FileChannel FileChannel-3d21a8cc-6f46-45c4-8dee-ac5fd530c934 { dataDirs: [/tmp/1365758176497-0/data1, 
/tmp/1365758176497-0/data2, /tmp/1365758176497-0/data3] }...
2013-04-12 18:16:16,499 (main) [INFO - org.apache.flume.channel.file.Log.&lt;init&gt;(Log.java:321)] Encryption is not enabled
2013-04-12 18:16:16,499 (main) [INFO - org.apache.flume.channel.file.Log.replay(Log.java:368)] Replay started
2013-04-12 18:16:16,500 (main) [INFO - org.apache.flume.channel.file.Log.replay(Log.java:380)] Found NextFileID 0, from []
2013-04-12 18:16:16,504 (main) [INFO - org.apache.flume.channel.file.EventQueueBackingStoreFile.&lt;init&gt;(EventQueueBackingStoreFile.java:91)] Preallocated /tmp/1365758176497-0/chkpt/checkpoint to 88232 for capacity 10000
2013-04-12 18:16:16,505 (main) [INFO - org.apache.flume.channel.file.EventQueueBackingStoreFileV3.&lt;init&gt;(EventQueueBackingStoreFileV3.java:53)] Starting up with /tmp/1365758176497-0/chkpt/checkpoint and /tmp/1365758176497-0/chkpt/c
heckpoint.meta
2013-04-12 18:16:16,507 (main) [INFO - org.apache.flume.channel.file.Log.replay(Log.java:417)] Last Checkpoint Fri Apr 12 18:16:16 JST 2013, queue depth = 0
2013-04-12 18:16:16,507 (main) [INFO - org.apache.flume.channel.file.Log.doReplay(Log.java:498)] Replaying logs with v2 replay logic
2013-04-12 18:16:16,507 (main) [INFO - org.apache.flume.channel.file.ReplayHandler.replayLog(ReplayHandler.java:244)] Starting replay of []
2013-04-12 18:16:16,507 (main) [INFO - org.apache.flume.channel.file.ReplayHandler.replayLog(ReplayHandler.java:338)] read: 0, put: 0, take: 0, rollback: 0, commit: 0, skip: 0, eventCount:0
2013-04-12 18:16:16,508 (main) [INFO - org.apache.flume.channel.file.Log.replay(Log.java:461)] Rolling /tmp/1365758176497-0/data1
2013-04-12 18:16:16,508 (main) [INFO - org.apache.flume.channel.file.Log.roll(Log.java:922)] Roll start /tmp/1365758176497-0/data1
2013-04-12 18:16:16,508 (main) [INFO - org.apache.flume.channel.file.LogFile$Writer.&lt;init&gt;(LogFile.java:169)] Opened /tmp/1365758176497-0/data1/log-1
2013-04-12 18:16:16,510 (main) [INFO - org.apache.flume.channel.file.Log.roll(Log.java:937)] Roll end
2013-04-12 18:16:16,510 (main) [INFO - org.apache.flume.channel.file.Log.replay(Log.java:461)] Rolling /tmp/1365758176497-0/data2
2013-04-12 18:16:16,511 (main) [INFO - org.apache.flume.channel.file.Log.roll(Log.java:922)] Roll start /tmp/1365758176497-0/data2
2013-04-12 18:16:16,511 (main) [INFO - org.apache.flume.channel.file.LogFile$Writer.&lt;init&gt;(LogFile.java:169)] Opened /tmp/1365758176497-0/data2/log-2
2013-04-12 18:16:16,513 (main) [INFO - org.apache.flume.channel.file.Log.roll(Log.java:937)] Roll end
2013-04-12 18:16:16,513 (main) [INFO - org.apache.flume.channel.file.Log.replay(Log.java:461)] Rolling /tmp/1365758176497-0/data3
2013-04-12 18:16:16,513 (main) [INFO - org.apache.flume.channel.file.Log.roll(Log.java:922)] Roll start /tmp/1365758176497-0/data3
2013-04-12 18:16:16,514 (main) [INFO - org.apache.flume.channel.file.LogFile$Writer.&lt;init&gt;(LogFile.java:169)] Opened /tmp/1365758176497-0/data3/log-3
2013-04-12 18:16:16,516 (main) [INFO - org.apache.flume.channel.file.Log.roll(Log.java:937)] Roll end
2013-04-12 18:16:16,516 (main) [INFO - org.apache.flume.channel.file.EventQueueBackingStoreFile.beginCheckpoint(EventQueueBackingStoreFile.java:215)] Start checkpoint for /tmp/1365758176497-0/chkpt/checkpoint, elements to sync = 0
2013-04-12 18:16:16,520 (main) [INFO - org.apache.flume.channel.file.EventQueueBackingStoreFile.checkpoint(EventQueueBackingStoreFile.java:240)] Updating checkpoint metadata: logWriteOrderID: 1365758273442, queueSize: 0, queueHead: 0
2013-04-12 18:16:16,521 (main) [INFO - org.apache.flume.channel.file.EventQueueBackingStoreFile.startBackupThread(EventQueueBackingStoreFile.java:276)] Attempting to back up checkpoint.
2013-04-12 18:16:16,522 ([channel=FileChannel-3d21a8cc-6f46-45c4-8dee-ac5fd530c934] - CheckpointBackUpThread) [INFO - org.apache.flume.channel.file.Serialization.deleteAllFiles(Serialization.java:100)] Skipping in_use.lock because it is 
in excludes set
2013-04-12 18:16:16,522 ([channel=FileChannel-3d21a8cc-6f46-45c4-8dee-ac5fd530c934] - CheckpointBackUpThread) [INFO - org.apache.flume.channel.file.Serialization.deleteAllFiles(Serialization.java:113)] Deleted the following files: .
2013-04-12 18:16:16,524 (main) [INFO - org.apache.flume.channel.file.Log.writeCheckpoint(Log.java:997)] Updated checkpoint for file: /tmp/1365758176497-0/data1/log-1 position: 0 logWriteOrderID: 1365758273442
2013-04-12 18:16:16,535 (main) [INFO - org.apache.flume.channel.file.Log.writeCheckpoint(Log.java:997)] Updated checkpoint for file: /tmp/1365758176497-0/data2/log-2 position: 0 logWriteOrderID: 1365758273442
2013-04-12 18:16:16,539 (main) [INFO - org.apache.flume.channel.file.Log.writeCheckpoint(Log.java:997)] Updated checkpoint for file: /tmp/1365758176497-0/data3/log-3 position: 0 logWriteOrderID: 1365758273442
2013-04-12 18:16:16,540 (main) [INFO - org.apache.flume.channel.file.FileChannel.start(FileChannel.java:307)] Queue Size after replay: 0 [channel=FileChannel-3d21a8cc-6f46-45c4-8dee-ac5fd530c934]
2013-04-12 18:16:16,540 ([channel=FileChannel-3d21a8cc-6f46-45c4-8dee-ac5fd530c934] - CheckpointBackUpThread) [INFO - org.apache.flume.channel.file.EventQueueBackingStoreFile$1.run(EventQueueBackingStoreFile.java:291)] Checkpoint backup 
completed.
2013-04-12 18:16:16,540 (main) [INFO - org.apache.flume.instrumentation.MonitoredCounterGroup.register(MonitoredCounterGroup.java:89)] Monitoried counter group for type: CHANNEL, name: FileChannel-3d21a8cc-6f46-45c4-8dee-ac5fd530c934, re
gistered successfully.
2013-04-12 18:16:16,540 (main) [INFO - org.apache.flume.instrumentation.MonitoredCounterGroup.start(MonitoredCounterGroup.java:73)] Component type: CHANNEL, name: FileChannel-3d21a8cc-6f46-45c4-8dee-ac5fd530c934 started
2013-04-12 18:16:16,541 (main) [DEBUG - org.apache.flume.channel.file.LogFile$Writer.preallocate(LogFile.java:290)] Preallocating at position 0
2013-04-12 18:16:21,544 (main) [INFO - org.apache.flume.channel.file.EventQueueBackingStoreFile.beginCheckpoint(EventQueueBackingStoreFile.java:215)] Start checkpoint for /tmp/1365758176497-0/chkpt/checkpoint, elements to sync = 0
2013-04-12 18:16:21,551 (main) [DEBUG - org.apache.flume.channel.file.FlumeEventQueue$InflightEventWrapper.serializeAndWrite(FlumeEventQueue.java:422)] Number of events inserted into inflights file: 100 file: /tmp/1365758176497-0/chkpt/i
nflightputs
2013-04-12 18:16:21,560 (main) [INFO - org.apache.flume.channel.file.EventQueueBackingStoreFile.checkpoint(EventQueueBackingStoreFile.java:240)] Updating checkpoint metadata: logWriteOrderID: 1365758273543, queueSize: 0, queueHead: 0
2013-04-12 18:16:21,566 (main) [INFO - org.apache.flume.channel.file.EventQueueBackingStoreFile.startBackupThread(EventQueueBackingStoreFile.java:276)] Attempting to back up checkpoint.
2013-04-12 18:16:21,570 ([channel=FileChannel-3d21a8cc-6f46-45c4-8dee-ac5fd530c934] - CheckpointBackUpThread) [INFO - org.apache.flume.channel.file.Serialization.deleteAllFiles(Serialization.java:100)] Skipping in_use.lock because it is 
in excludes set
2013-04-12 18:16:21,571 ([channel=FileChannel-3d21a8cc-6f46-45c4-8dee-ac5fd530c934] - CheckpointBackUpThread) [INFO - org.apache.flume.channel.file.Serialization.deleteAllFiles(Serialization.java:113)] Deleted the following files: , infl
ighttakes, checkpoint.meta, checkpoint, inflightputs.
2013-04-12 18:16:21,580 (main) [INFO - org.apache.flume.channel.file.Log.writeCheckpoint(Log.java:997)] Updated checkpoint for file: /tmp/1365758176497-0/data1/log-1 position: 0 logWriteOrderID: 1365758273543
2013-04-12 18:16:21,587 (main) [INFO - org.apache.flume.channel.file.Log.writeCheckpoint(Log.java:997)] Updated checkpoint for file: /tmp/1365758176497-0/data2/log-2 position: 7800 logWriteOrderID: 1365758273543
2013-04-12 18:16:21,589 (main) [INFO - org.apache.flume.channel.file.Log.writeCheckpoint(Log.java:997)] Updated checkpoint for file: /tmp/1365758176497-0/data3/log-3 position: 0 logWriteOrderID: 1365758273543
2013-04-12 18:16:21,590 (main) [DEBUG - org.apache.flume.channel.file.Log.removeOldLogs(Log.java:1058)] Files currently in use: [1, 2, 3]
2013-04-12 18:16:21,591 ([channel=FileChannel-3d21a8cc-6f46-45c4-8dee-ac5fd530c934] - CheckpointBackUpThread) [INFO - org.apache.flume.channel.file.EventQueueBackingStoreFile$1.run(EventQueueBackingStoreFile.java:291)] Checkpoint backup completed.
2013-04-12 18:16:23,605 (main) [INFO - org.apache.flume.channel.file.FileChannel.stop(FileChannel.java:327)] Stopping FileChannel FileChannel-3d21a8cc-6f46-45c4-8dee-ac5fd530c934 { dataDirs: [/tmp/1365758176497-0/data1, /tmp/1365758176497-0/data2, /tmp/1365758176497-0/data3] }...
Attempting to shutdown background worker.
2013-04-12 18:16:23,619 (main) [INFO - org.apache.flume.channel.file.Log.shutdownWorker(Log.java:821)] Attempting to shutdown background worker.
2013-04-12 18:16:23,619 (main) [INFO - org.apache.flume.channel.file.LogFile$Writer.close(LogFile.java:273)] Closing /tmp/1365758176497-0/data1/log-1
2013-04-12 18:16:23,619 (main) [INFO - org.apache.flume.channel.file.LogFile$Writer.close(LogFile.java:273)] Closing /tmp/1365758176497-0/data2/log-2
2013-04-12 18:16:23,619 (main) [INFO - org.apache.flume.channel.file.LogFile$Writer.close(LogFile.java:273)] Closing /tmp/1365758176497-0/data3/log-3
2013-04-12 18:16:23,619 (main) [INFO - org.apache.flume.channel.file.LogFile$RandomReader.close(LogFile.java:354)] Closing RandomReader /tmp/1365758176497-0/data1/log-1
2013-04-12 18:16:23,625 (main) [INFO - org.apache.flume.channel.file.LogFile$RandomReader.close(LogFile.java:354)] Closing RandomReader /tmp/1365758176497-0/data2/log-2
2013-04-12 18:16:23,631 (main) [INFO - org.apache.flume.channel.file.LogFile$RandomReader.close(LogFile.java:354)] Closing RandomReader /tmp/1365758176497-0/data3/log-3
2013-04-12 18:16:23,638 (main) [INFO - org.apache.flume.instrumentation.MonitoredCounterGroup.stop(MonitoredCounterGroup.java:100)] Component type: CHANNEL, name: FileChannel-3d21a8cc-6f46-45c4-8dee-ac5fd530c934 stopped
2013-04-12 18:16:23,638 (main) [INFO - org.apache.flume.channel.file.FileChannel.start(FileChannel.java:281)] Starting FileChannel FileChannel-5de59d23-c19a-424a-a407-9209741e3e00 { dataDirs: [/tmp/1365758176497-0/data1, /tmp/1365758176497-0/data2, /tmp/1365758176497-0/data3] }...
2013-04-12 18:16:23,639 (main) [INFO - org.apache.flume.channel.file.Log.&lt;init&gt;(Log.java:321)] Encryption is not enabled
2013-04-12 18:16:23,639 (main) [INFO - org.apache.flume.channel.file.Log.replay(Log.java:368)] Replay started
2013-04-12 18:16:23,643 (main) [INFO - org.apache.flume.channel.file.Log.replay(Log.java:380)] Found NextFileID 3, from [/tmp/1365758176497-0/data1/log-1, /tmp/1365758176497-0/data2/log-2, /tmp/1365758176497-0/data3/log-3]
2013-04-12 18:16:23,644 (main) [INFO - org.apache.flume.channel.file.EventQueueBackingStoreFileV3.&lt;init&gt;(EventQueueBackingStoreFileV3.java:53)] Starting up with /tmp/1365758176497-0/chkpt/checkpoint and /tmp/1365758176497-0/chkpt/checkpoint.meta
2013-04-12 18:16:23,644 (main) [INFO - org.apache.flume.channel.file.EventQueueBackingStoreFileV3.&lt;init&gt;(EventQueueBackingStoreFileV3.java:57)] Reading checkpoint metadata from /tmp/1365758176497-0/chkpt/checkpoint.meta
2013-04-12 18:16:23,644 (main) [INFO - org.apache.flume.channel.file.Log.replay(Log.java:417)] Last Checkpoint Fri Apr 12 18:16:21 JST 2013, queue depth = 0
2013-04-12 18:16:23,645 (main) [INFO - org.apache.flume.channel.file.Log.doReplay(Log.java:498)] Replaying logs with v2 replay logic
2013-04-12 18:16:23,645 (main) [INFO - org.apache.flume.channel.file.ReplayHandler.replayLog(ReplayHandler.java:244)] Starting replay of [/tmp/1365758176497-0/data1/log-1, /tmp/1365758176497-0/data2/log-2, /tmp/1365758176497-0/data3/log-3]
2013-04-12 18:16:23,645 (main) [DEBUG - org.apache.flume.channel.file.FlumeEventQueue$InflightEventWrapper.deserialize(FlumeEventQueue.java:482)] Reached end of inflights buffer. Long buffer position =104
2013-04-12 18:16:23,646 (main) [DEBUG - org.apache.flume.channel.file.FlumeEventQueue$InflightEventWrapper.deserialize(FlumeEventQueue.java:482)] Reached end of inflights buffer. Long buffer position =2
2013-04-12 18:16:23,646 (main) [INFO - org.apache.flume.channel.file.ReplayHandler.replayLog(ReplayHandler.java:257)] Replaying /tmp/1365758176497-0/data1/log-1
2013-04-12 18:16:23,646 (main) [INFO - org.apache.flume.channel.file.LogFile$SequentialReader.skipToLastCheckpointPosition(LogFile.java:484)] Checkpoint for file(/tmp/1365758176497-0/data1/log-1) is: 1365758273543, which is beyond the requested checkpoint time: 1365758273543 and position 0
2013-04-12 18:16:23,646 (main) [INFO - org.apache.flume.channel.file.ReplayHandler.replayLog(ReplayHandler.java:257)] Replaying /tmp/1365758176497-0/data2/log-2
2013-04-12 18:16:23,647 (main) [INFO - org.apache.flume.channel.file.LogFile$SequentialReader.skipToLastCheckpointPosition(LogFile.java:482)] fast-forward to checkpoint position: 7800
2013-04-12 18:16:23,647 (main) [INFO - org.apache.flume.channel.file.ReplayHandler.replayLog(ReplayHandler.java:257)] Replaying /tmp/1365758176497-0/data3/log-3
2013-04-12 18:16:23,647 (main) [INFO - org.apache.flume.channel.file.LogFile$SequentialReader.skipToLastCheckpointPosition(LogFile.java:484)] Checkpoint for file(/tmp/1365758176497-0/data3/log-3) is: 1365758273543, which is beyond the requested checkpoint time: 1365758273543 and position 0
2013-04-12 18:16:23,647 (main) [INFO - org.apache.flume.channel.file.LogFile$SequentialReader.next(LogFile.java:505)] Encountered EOF at 7836 in /tmp/1365758176497-0/data2/log-2
2013-04-12 18:16:23,647 (main) [INFO - org.apache.flume.channel.file.ReplayHandler.replayLog(ReplayHandler.java:338)] read: 1, put: 0, take: 0, rollback: 0, commit: 1, skip: 0, eventCount:100
2013-04-12 18:16:23,647 (main) [INFO - org.apache.flume.channel.file.Log.replay(Log.java:461)] Rolling /tmp/1365758176497-0/data1
2013-04-12 18:16:23,647 (main) [INFO - org.apache.flume.channel.file.Log.roll(Log.java:922)] Roll start /tmp/1365758176497-0/data1
2013-04-12 18:16:23,648 (main) [INFO - org.apache.flume.channel.file.LogFile$Writer.&lt;init&gt;(LogFile.java:169)] Opened /tmp/1365758176497-0/data1/log-4
2013-04-12 18:16:23,650 (main) [INFO - org.apache.flume.channel.file.Log.roll(Log.java:937)] Roll end
2013-04-12 18:16:23,650 (main) [INFO - org.apache.flume.channel.file.Log.replay(Log.java:461)] Rolling /tmp/1365758176497-0/data2
2013-04-12 18:16:23,650 (main) [INFO - org.apache.flume.channel.file.Log.roll(Log.java:922)] Roll start /tmp/1365758176497-0/data2
2013-04-12 18:16:23,650 (main) [INFO - org.apache.flume.channel.file.LogFile$Writer.&lt;init&gt;(LogFile.java:169)] Opened /tmp/1365758176497-0/data2/log-5
2013-04-12 18:16:23,652 (main) [INFO - org.apache.flume.channel.file.Log.roll(Log.java:937)] Roll end
2013-04-12 18:16:23,652 (main) [INFO - org.apache.flume.channel.file.Log.replay(Log.java:461)] Rolling /tmp/1365758176497-0/data3
2013-04-12 18:16:23,652 (main) [INFO - org.apache.flume.channel.file.Log.roll(Log.java:922)] Roll start /tmp/1365758176497-0/data3
2013-04-12 18:16:23,652 (main) [INFO - org.apache.flume.channel.file.LogFile$Writer.&lt;init&gt;(LogFile.java:169)] Opened /tmp/1365758176497-0/data3/log-6
2013-04-12 18:16:23,654 (main) [INFO - org.apache.flume.channel.file.Log.roll(Log.java:937)] Roll end
2013-04-12 18:16:23,654 (main) [INFO - org.apache.flume.channel.file.EventQueueBackingStoreFile.beginCheckpoint(EventQueueBackingStoreFile.java:215)] Start checkpoint for /tmp/1365758176497-0/chkpt/checkpoint, elements to sync = 100
2013-04-12 18:16:23,658 (main) [INFO - org.apache.flume.channel.file.EventQueueBackingStoreFile.checkpoint(EventQueueBackingStoreFile.java:240)] Updating checkpoint metadata: logWriteOrderID: 1365758273545, queueSize: 100, queueHead: 9998
2013-04-12 18:16:23,660 (main) [INFO - org.apache.flume.channel.file.EventQueueBackingStoreFile.startBackupThread(EventQueueBackingStoreFile.java:276)] Attempting to back up checkpoint.
2013-04-12 18:16:23,661 ([channel=FileChannel-5de59d23-c19a-424a-a407-9209741e3e00] - CheckpointBackUpThread) [INFO - org.apache.flume.channel.file.Serialization.deleteAllFiles(Serialization.java:100)] Skipping in_use.lock because it is in excludes set
2013-04-12 18:16:23,663 ([channel=FileChannel-5de59d23-c19a-424a-a407-9209741e3e00] - CheckpointBackUpThread) [INFO - org.apache.flume.channel.file.Serialization.deleteAllFiles(Serialization.java:113)] Deleted the following files: , inflighttakes, checkpoint.meta, checkpoint, inflightputs.
2013-04-12 18:16:23,663 (main) [INFO - org.apache.flume.channel.file.Log.writeCheckpoint(Log.java:997)] Updated checkpoint for file: /tmp/1365758176497-0/data1/log-4 position: 0 logWriteOrderID: 1365758273545
2013-04-12 18:16:23,673 (main) [INFO - org.apache.flume.channel.file.Log.writeCheckpoint(Log.java:997)] Updated checkpoint for file: /tmp/1365758176497-0/data2/log-5 position: 0 logWriteOrderID: 1365758273545
2013-04-12 18:16:23,677 (main) [INFO - org.apache.flume.channel.file.Log.writeCheckpoint(Log.java:997)] Updated checkpoint for file: /tmp/1365758176497-0/data3/log-6 position: 0 logWriteOrderID: 1365758273545
2013-04-12 18:16:23,678 (main) [INFO - org.apache.flume.channel.file.LogFile$RandomReader.close(LogFile.java:354)] Closing RandomReader /tmp/1365758176497-0/data2/log-2
2013-04-12 18:16:23,682 ([channel=FileChannel-5de59d23-c19a-424a-a407-9209741e3e00] - CheckpointBackUpThread) [INFO - org.apache.flume.channel.file.EventQueueBackingStoreFile$1.run(EventQueueBackingStoreFile.java:291)] Checkpoint backup completed.
2013-04-12 18:16:23,685 (main) [DEBUG - org.apache.flume.channel.file.Log.writeCheckpoint(Log.java:1017)] Updated checkpoint for file: /tmp/1365758176497-0/data2/log-2logWriteOrderID 1365758273545
2013-04-12 18:16:23,686 (main) [INFO - org.apache.flume.channel.file.FileChannel.start(FileChannel.java:307)] Queue Size after replay: 100 [channel=FileChannel-5de59d23-c19a-424a-a407-9209741e3e00]
2013-04-12 18:16:23,686 (main) [INFO - org.apache.flume.instrumentation.MonitoredCounterGroup.register(MonitoredCounterGroup.java:89)] Monitoried counter group for type: CHANNEL, name: FileChannel-5de59d23-c19a-424a-a407-9209741e3e00, registered successfully.
2013-04-12 18:16:23,686 (main) [INFO - org.apache.flume.instrumentation.MonitoredCounterGroup.start(MonitoredCounterGroup.java:73)] Component type: CHANNEL, name: FileChannel-5de59d23-c19a-424a-a407-9209741e3e00 started
2013-04-12 18:16:23,686 (main) [INFO - org.apache.flume.channel.file.FileChannel.stop(FileChannel.java:327)] Stopping FileChannel FileChannel-5de59d23-c19a-424a-a407-9209741e3e00 { dataDirs: [/tmp/1365758176497-0/data1, /tmp/1365758176497-0/data2, /tmp/1365758176497-0/data3] }...
Attempting to shutdown background worker.
2013-04-12 18:16:23,686 (main) [INFO - org.apache.flume.channel.file.Log.shutdownWorker(Log.java:821)] Attempting to shutdown background worker.
2013-04-12 18:16:23,687 (main) [INFO - org.apache.flume.channel.file.LogFile$Writer.close(LogFile.java:273)] Closing /tmp/1365758176497-0/data1/log-4
2013-04-12 18:16:23,687 (main) [INFO - org.apache.flume.channel.file.LogFile$Writer.close(LogFile.java:273)] Closing /tmp/1365758176497-0/data2/log-5
2013-04-12 18:16:23,687 (main) [INFO - org.apache.flume.channel.file.LogFile$Writer.close(LogFile.java:273)] Closing /tmp/1365758176497-0/data3/log-6
2013-04-12 18:16:23,687 (main) [INFO - org.apache.flume.channel.file.LogFile$RandomReader.close(LogFile.java:354)] Closing RandomReader /tmp/1365758176497-0/data1/log-1
2013-04-12 18:16:23,692 (main) [INFO - org.apache.flume.channel.file.LogFile$RandomReader.close(LogFile.java:354)] Closing RandomReader /tmp/1365758176497-0/data2/log-2
2013-04-12 18:16:23,698 (main) [INFO - org.apache.flume.channel.file.LogFile$RandomReader.close(LogFile.java:354)] Closing RandomReader /tmp/1365758176497-0/data3/log-3
2013-04-12 18:16:23,704 (main) [INFO - org.apache.flume.channel.file.LogFile$RandomReader.close(LogFile.java:354)] Closing RandomReader /tmp/1365758176497-0/data1/log-4
2013-04-12 18:16:23,711 (main) [INFO - org.apache.flume.channel.file.LogFile$RandomReader.close(LogFile.java:354)] Closing RandomReader /tmp/1365758176497-0/data2/log-5
2013-04-12 18:16:23,716 (main) [INFO - org.apache.flume.channel.file.LogFile$RandomReader.close(LogFile.java:354)] Closing RandomReader /tmp/1365758176497-0/data3/log-6
2013-04-12 18:16:23,723 (main) [INFO - org.apache.flume.instrumentation.MonitoredCounterGroup.stop(MonitoredCounterGroup.java:100)] Component type: CHANNEL, name: FileChannel-5de59d23-c19a-424a-a407-9209741e3e00 stopped
</system-out>


- Juhani Connolly


On April 11, 2013, 1:09 a.m., Hari Shreedharan wrote:
> 
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/10415/
> -----------------------------------------------------------
> 
> (Updated April 11, 2013, 1:09 a.m.)
> 
> 
> Review request for Flume.
> 
> 
> Description
> -------
> 
> Increase sleeps so forceCheckpoint does not fail because the copy is not completed.
> 
> 
> This addresses bug FLUME-1986.
>     https://issues.apache.org/jira/browse/FLUME-1986
> 
> 
> Diffs
> -----
> 
>   flume-ng-channels/flume-file-channel/src/test/java/org/apache/flume/channel/file/TestFileChannelRestart.java fb0e208 
>   flume-ng-channels/flume-file-channel/src/test/java/org/apache/flume/channel/file/TestUtils.java 7c490b5 
> 
> Diff: https://reviews.apache.org/r/10415/diff/
> 
> 
> Testing
> -------
> 
> Ran full tests.
> 
> 
> Thanks,
> 
> Hari Shreedharan
> 
>