This is running on an EC2 instance, and these are the ephemeral drive(s). Filesystem 1K-blocks Used Available Use% Mounted on /dev/xvda1 8256952 1618248 6219276 21% / udev 1912272 8 1912264 1% /dev tmpfs 768100 180 767920 1% /run none 5120 0 5120 0% /run/lock none 1920244 0 1920244 0% /run/shm /dev/xvdb 412814512 1127172 390717564 1% /mnt
ubuntu@ip-foo:~$ cat /etc/fstab LABEL=cloudimg-rootfs / ext4 defaults 0 0 /dev/xvdb /mnt auto defaults,nobootwait,comment=cloudconfig 0 2 ubuntu@ip-foo:~$ ubuntu@ip-foo:~$ mount /dev/xvda1 on / type ext4 (rw) proc on /proc type proc (rw,noexec,nosuid,nodev) sysfs on /sys type sysfs (rw,noexec,nosuid,nodev) none on /sys/fs/fuse/connections type fusectl (rw) none on /sys/kernel/debug type debugfs (rw) none on /sys/kernel/security type securityfs (rw) udev on /dev type devtmpfs (rw,mode=0755) devpts on /dev/pts type devpts (rw,noexec,nosuid,gid=5,mode=0620) tmpfs on /run type tmpfs (rw,noexec,nosuid,size=10%,mode=0755) none on /run/lock type tmpfs (rw,noexec,nosuid,nodev,size=5242880) none on /run/shm type tmpfs (rw,nosuid,nodev) /dev/xvdb on /mnt type ext3 (rw) I do see that / is ext4 and /mnt is ext3.....hmm, not sure it matters. Dano On Tue, Nov 20, 2012 at 10:01 AM, Brock Noland <[email protected]> wrote: > Are /var/log and /mnt/flume on the same file system? mv across file > systems is a cp and then delete. > > On Tue, Nov 20, 2012 at 10:59 AM, Dan Young <[email protected]> wrote: > > Coolio, thank you Brock. > > > > Did a quick test with a mv vs cp.....this is one test, repeated a few > > times....the smaller file (~60M) seemed to work fine w/ a mv, but a > larger > > file we're seeing the same behavior.... > > > > > > Start with no logs in the SpoolingDirectory: > > > > ls -lrt /mnt/flume/clickstream > > > > /mnt/flume/clickstream: > > total 0 > > > > > > > > Review the logs that will be rotated via logrotate.d into the respective > > directory; /mnt/flume/clickstream > > > > ls -lrt /var/log/clickstream > > /var/log/clickstream: > > total 64112 > > -rw-rw-r-- 1 ubuntu ubuntu 65648336 Nov 20 16:05 clickstream.log > > > > > > > > Review logrotate config in /etc/logrotate.d. Note here, I changed from > cp -p > > to a mv..... > > > > /var/log/clickstream/clickstream.log > > { > > missingok > > rotate 3 > > compress > > delaycompress > > copytruncate > > notifempty > > size 50M > > dateext > > dateformat -%Y-%m-%d-%s > > create 666 ubuntu ubuntu > > postrotate > > mv $1 /mnt/flume/clickstream/ 2>&1 > > endscript > > } > > > > > > I run logrotate.d/clickstream.POST with the ~60MB file, and everything > > looked fine....now I try a ~190MB file.... > > > > > > > > ls -lrt /var/log/clickstream > > /var/log/clickstream: > > total 192336 > > -rw-rw-r-- 1 ubuntu ubuntu 196945008 Nov 20 16:42 clickstream.log > > > > > > Run logrotate.d/clickstream.POST, and we see the WARNING in the FLume > log. > > > > .... > > .... > > 20 Nov 2012 16:45:07,117 WARN [pool-13-thread-1] > > (org.apache.flume.client.avro.SpoolingFileLineReader.getNextFile:328) - > > Could not find file: > > /mnt/flume/clickstream/clickstream.log-2012-11-20-1353429906 > > java.io.FileNotFoundException: > > /mnt/flume/clickstream/clickstream.log-2012-11-20-1353429906 (Permission > > denied) > > at java.io.FileInputStream.open(Native Method) > > at java.io.FileInputStream.<init>(FileInputStream.java:138) > > at java.io.FileReader.<init>(FileReader.java:72) > > at > > > org.apache.flume.client.avro.SpoolingFileLineReader.getNextFile(SpoolingFileLineReader.java:322) > > at > > > org.apache.flume.client.avro.SpoolingFileLineReader.readLines(SpoolingFileLineReader.java:172) > > at > > > org.apache.flume.source.SpoolDirectorySource$SpoolDirectoryRunnable.run(SpoolDirectorySource.java:135) > > at > java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) > > at > > > java.util.concurrent.FutureTask$Sync.innerRunAndReset(FutureTask.java:351) > > at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:178) > > at > > > java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:178) > > at > > > java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) > > at > > > java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110) > > at > > > java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603) > > at java.lang.Thread.run(Thread.java:722) > > 20 Nov 2012 16:45:13,174 INFO [hdfs-c1s3-call-runner-5] > > (org.apache.flume.sink.hdfs.BucketWriter.doOpen:205) - Creating > > s3n://X:Y@my-bucket > /clicks/2012/11/clicks-2012-11-20-16-40-10.145.184.200-.1353429913104.gz.tmp > > .... > > .... > > > > But it seems that FLume did process the log..... > > > > ls -lrt /mnt/flume/clickstream/ > > total 256704 > > -rw-rw-r-- 1 ubuntu ubuntu 65648336 Nov 20 16:25 > > clickstream.log-2012-11-20-1353428715.COMPLETED > > -rw-rw-r-- 1 ubuntu ubuntu 196945008 Nov 20 16:45 > > clickstream.log-2012-11-20-1353429906.COMPLETED > > > > > > Regards, > > > > Dano > > > > > > > > > > > > On Tue, Nov 20, 2012 at 9:21 AM, Brock Noland <[email protected]> > wrote: > >> > >> Yeah I think that makes sense, I have created a JIRA for this > >> > >> https://issues.apache.org/jira/browse/FLUME-1733 > >> > >> Brock > >> > >> On Tue, Nov 20, 2012 at 9:02 AM, Dan Young <[email protected]> wrote: > >> > Hey Brock, > >> > > >> > I can do some more testing on my side with smaller files as well as > >> > doing a > >> > mv vs a cp . I do believe that a slight delay would be helpful since > >> > people > >> > will be moving/copying large files around. > >> > > >> > Regards , > >> > > >> > Dano > >> > > >> > On Nov 20, 2012 5:26 AM, "Brock Noland" <[email protected]> wrote: > >> >> > >> >> Thinking about this more, I think it's probably going to be quite > >> >> common for people to cp large files into the spooling directory. > >> >> Patrick, what do you think about waiting until the mtime is say 1 > >> >> second old? > >> >> > >> >> Brock > >> >> > >> >> On Mon, Nov 19, 2012 at 5:29 PM, Brock Noland <[email protected]> > >> >> wrote: > >> >> > My guess is that the file does not have the correct permissions > while > >> >> > being copied. > >> >> > > >> >> > [noland@localhost cp-test]$ cp -p test-0 test-1 & sleep 0.1; ls > -al > >> >> > test* > >> >> > [1] 18780 > >> >> > -rw-rw-r-- 1 noland noland 1048576000 Nov 19 17:25 test-0 > >> >> > -rw------- 1 noland noland 52334592 Nov 19 17:27 test-1 > >> >> > > >> >> > > >> >> > For large files, it probably makes sense to copy the file in as > .file > >> >> > and then rename it to file. > >> >> > > >> >> > Brock > >> >> > > >> >> > On Mon, Nov 19, 2012 at 5:04 PM, Patrick Wendell < > [email protected]> > >> >> > wrote: > >> >> >> The spooling source gets a directory listing, then reads each > file, > >> >> >> then > >> >> >> renames it to X.COMPLETED. Is it possible some other process > deleted > >> >> >> that > >> >> >> file between when Flume listed the directory and when it tried to > >> >> >> open > >> >> >> the > >> >> >> file? Otherwise, I'm confused why the file would not be present in > >> >> >> the > >> >> >> listing you give here. > >> >> >> > >> >> >> > >> >> >> On Mon, Nov 19, 2012 at 6:03 PM, Patrick Wendell > >> >> >> <[email protected]> > >> >> >> wrote: > >> >> >>> > >> >> >>> Hey Dan, > >> >> >>> > >> >> >>> You say that it seems like Flume has already processed the log... > >> >> >>> why > >> >> >>> do > >> >> >>> you think that? > >> >> >>> > >> >> >>> When you listed the directory contents I don't see the original > or > >> >> >>> the > >> >> >>> COMPLETED version of the file that Flume is complaining about: > >> >> >>> > >> >> >>> /clickstream.log-2012-11-17-1353163623 > >> >> >>> > >> >> >>> doesn't appear in the > >> >> >>> > >> >> >>> /mnt/flume/clickstream/ > >> >> >>> > >> >> >>> directory listing anywhere. > >> >> >>> > >> >> >>> > >> >> >>> On Mon, Nov 19, 2012 at 2:33 PM, Dan Young <[email protected]> > >> >> >>> wrote: > >> >> >>>> > >> >> >>>> Hello Brock, > >> >> >>>> > >> >> >>>> It seems like we get this message each time that logrotate runs > >> >> >>>> and > >> >> >>>> is in > >> >> >>>> the process of copying the file to the SpoolingDirectory. It > seems > >> >> >>>> that > >> >> >>>> Flume starts reading the file as soon as it shows up in the > >> >> >>>> SpoolingDirectory..... Maybe it's trying to read the file while > >> >> >>>> it's > >> >> >>>> still > >> >> >>>> being written to???? > >> >> >>>> > >> >> >>>> 2012-11-19 19:27:27,924 (pool-12-thread-1) [WARN - > >> >> >>>> > >> >> >>>> > >> >> >>>> > org.apache.flume.client.avro.SpoolingFileLineReader.getNextFile(SpoolingFileLineReader.java:328)] > >> >> >>>> Could not find file: > >> >> >>>> /mnt/flume/clickstream2/clickstream2.log-2012-11-19-1353353239 > >> >> >>>> java.io.FileNotFoundException: > >> >> >>>> /mnt/flume/clickstream2/clickstream2.log-2012-11-19-1353353239 > >> >> >>>> (Permission > >> >> >>>> denied) > >> >> >>>> at java.io.FileInputStream.open(Native Method) > >> >> >>>> at java.io.FileInputStream.<init>(FileInputStream.java:138) > >> >> >>>> at java.io.FileReader.<init>(FileReader.java:72) > >> >> >>>> at > >> >> >>>> > >> >> >>>> > >> >> >>>> > org.apache.flume.client.avro.SpoolingFileLineReader.getNextFile(SpoolingFileLineReader.java:322) > >> >> >>>> at > >> >> >>>> > >> >> >>>> > >> >> >>>> > org.apache.flume.client.avro.SpoolingFileLineReader.readLines(SpoolingFileLineReader.java:172) > >> >> >>>> at > >> >> >>>> > >> >> >>>> > >> >> >>>> > org.apache.flume.source.SpoolDirectorySource$SpoolDirectoryRunnable.run(SpoolDirectorySource.java:135) > >> >> >>>> at > >> >> >>>> > >> >> >>>> > >> >> >>>> > java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) > >> >> >>>> at > >> >> >>>> > >> >> >>>> > >> >> >>>> > java.util.concurrent.FutureTask$Sync.innerRunAndReset(FutureTask.java:351) > >> >> >>>> at > >> >> >>>> java.util.concurrent.FutureTask.runAndReset(FutureTask.java:178) > >> >> >>>> at > >> >> >>>> > >> >> >>>> > >> >> >>>> > java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:178) > >> >> >>>> at > >> >> >>>> > >> >> >>>> > >> >> >>>> > java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) > >> >> >>>> at > >> >> >>>> > >> >> >>>> > >> >> >>>> > java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110) > >> >> >>>> at > >> >> >>>> > >> >> >>>> > >> >> >>>> > java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603) > >> >> >>>> at java.lang.Thread.run(Thread.java:722) > >> >> >>>> > >> >> >>>> > >> >> >>>> > >> >> >>>> > >> >> >>>> On Sat, Nov 17, 2012 at 9:15 AM, Brock Noland < > [email protected]> > >> >> >>>> wrote: > >> >> >>>>> > >> >> >>>>> Ok, do you mind sharing your log rotate config to see if we can > >> >> >>>>> reproduce? > >> >> >>>>> > >> >> >>>>> -- > >> >> >>>>> Brock Noland > >> >> >>>>> Sent with Sparrow > >> >> >>>>> > >> >> >>>>> On Saturday, November 17, 2012 at 10:01 AM, Dan Young wrote: > >> >> >>>>> > >> >> >>>>> Hey Brock, > >> >> >>>>> > >> >> >>>>> No I have not modified the conf while the agent was running. > >> >> >>>>> > >> >> >>>>> /mnt/flume is local. Note that this is running on an ec2 > instance > >> >> >>>>> and > >> >> >>>>> the disk is the ephemeral drive, not EBS. > >> >> >>>>> > >> >> >>>>> Regards , > >> >> >>>>> > >> >> >>>>> Dano > >> >> >>>>> > >> >> >>>>> On Nov 17, 2012 8:58 AM, "Brock Noland" <[email protected]> > >> >> >>>>> wrote: > >> >> >>>>> > >> >> >>>>> Hi, > >> >> >>>>> > >> >> >>>>> I highly doubt it's related to > >> >> >>>>> (https://issues.apache.org/jira/browse/FLUME-1721) but have > you > >> >> >>>>> modified the configuration file since starting the agent? If > so, > >> >> >>>>> can > >> >> >>>>> you restart the agent and see if the error continues? > >> >> >>>>> > >> >> >>>>> Also, is /mnt/flume local disk or NAS? > >> >> >>>>> > >> >> >>>>> Brock > >> >> >>>>> > >> >> >>>>> On Sat, Nov 17, 2012 at 9:02 AM, Dan Young < > [email protected]> > >> >> >>>>> wrote: > >> >> >>>>> > First a bit of context, I'm using logrotate to monitor and > copy > >> >> >>>>> > (cp > >> >> >>>>> > -p) log > >> >> >>>>> > files to a flume spooling directory source. So every hour, > >> >> >>>>> > logrotate > >> >> >>>>> > checks > >> >> >>>>> > for and copies a file from the source to the flume > destination. > >> >> >>>>> > I > >> >> >>>>> > see > >> >> >>>>> > the > >> >> >>>>> > following warning message in the flume logs. > >> >> >>>>> > > >> >> >>>>> > > >> >> >>>>> > 17 Nov 2012 14:47:07,682 WARN [pool-10-thread-1] > >> >> >>>>> > > >> >> >>>>> > > >> >> >>>>> > > (org.apache.flume.client.avro.SpoolingFileLineReader.getNextFile:328) > >> >> >>>>> > - > >> >> >>>>> > Could not find file: > >> >> >>>>> > /mnt/flume/clickstream/clickstream.log-2012-11-17-1353163623 > >> >> >>>>> > java.io.FileNotFoundException: > >> >> >>>>> > /mnt/flume/clickstream/clickstream.log-2012-11-17-1353163623 > >> >> >>>>> > (Permission > >> >> >>>>> > denied) > >> >> >>>>> > at java.io.FileInputStream.open(Native Method) > >> >> >>>>> > at java.io.FileInputStream.<init>(FileInputStream.java:138) > >> >> >>>>> > at java.io.FileReader.<init>(FileReader.java:72) > >> >> >>>>> > at > >> >> >>>>> > > >> >> >>>>> > > >> >> >>>>> > > >> >> >>>>> > > org.apache.flume.client.avro.SpoolingFileLineReader.getNextFile(SpoolingFileLineReader.java:322) > >> >> >>>>> > at > >> >> >>>>> > > >> >> >>>>> > > >> >> >>>>> > > >> >> >>>>> > > org.apache.flume.client.avro.SpoolingFileLineReader.readLines(SpoolingFileLineReader.java:172) > >> >> >>>>> > at > >> >> >>>>> > > >> >> >>>>> > > >> >> >>>>> > > >> >> >>>>> > > org.apache.flume.source.SpoolDirectorySource$SpoolDirectoryRunnable.run(SpoolDirectorySource.java:135) > >> >> >>>>> > at > >> >> >>>>> > > >> >> >>>>> > > >> >> >>>>> > > java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) > >> >> >>>>> > at > >> >> >>>>> > > >> >> >>>>> > > >> >> >>>>> > > >> >> >>>>> > > java.util.concurrent.FutureTask$Sync.innerRunAndReset(FutureTask.java:351) > >> >> >>>>> > at > >> >> >>>>> > > >> >> >>>>> > > java.util.concurrent.FutureTask.runAndReset(FutureTask.java:178) > >> >> >>>>> > at > >> >> >>>>> > > >> >> >>>>> > > >> >> >>>>> > > >> >> >>>>> > > java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:178) > >> >> >>>>> > at > >> >> >>>>> > > >> >> >>>>> > > >> >> >>>>> > > >> >> >>>>> > > java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) > >> >> >>>>> > at > >> >> >>>>> > > >> >> >>>>> > > >> >> >>>>> > > >> >> >>>>> > > java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110) > >> >> >>>>> > at > >> >> >>>>> > > >> >> >>>>> > > >> >> >>>>> > > >> >> >>>>> > > java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603) > >> >> >>>>> > at java.lang.Thread.run(Thread.java:722) > >> >> >>>>> > > >> >> >>>>> > > >> >> >>>>> > Although it appears that Flume processes the log, I'm curious > >> >> >>>>> > why > >> >> >>>>> > I''m > >> >> >>>>> > seeing this and if I have anything with permissions > incorrect? > >> >> >>>>> > > >> >> >>>>> > > >> >> >>>>> > > >> >> >>>>> > Here's the permissions: > >> >> >>>>> > > >> >> >>>>> > source log directory under /var/log: > >> >> >>>>> > drwxrwxr-x 2 ubuntu ubuntu 4096 Nov 17 14:47 clickstream > >> >> >>>>> > > >> >> >>>>> > source files: > >> >> >>>>> > -rw-rw-r-- 1 ubuntu ubuntu 9055750 Nov 17 13:29 > >> >> >>>>> > clickstream.log-2012-11-17-1353158953.gz > >> >> >>>>> > -rw-rw-r-- 1 ubuntu ubuntu 13583565 Nov 17 14:17 > >> >> >>>>> > clickstream.log-2012-11-17-1353161821.gz > >> >> >>>>> > -rw-rw-r-- 1 ubuntu ubuntu 131296672 Nov 17 14:47 > >> >> >>>>> > clickstream.log-2012-11-17-1353163623 > >> >> >>>>> > -rw-rw-r-- 1 ubuntu ubuntu 65648336 Nov 17 14:52 > >> >> >>>>> > clickstream.log > >> >> >>>>> > > >> >> >>>>> > flume source directory under /mnt/flume: > >> >> >>>>> > drwxrwxr-x 2 ubuntu ubuntu 4096 Nov 17 14:48 clickstream > >> >> >>>>> > > >> >> >>>>> > flume source files: > >> >> >>>>> > -rw-rw-r-- 1 ubuntu ubuntu 131296672 Nov 17 13:29 > >> >> >>>>> > clickstream.log-2012-11-17-1353158953.COMPLETED > >> >> >>>>> > -rw-rw-r-- 1 ubuntu ubuntu 196945008 Nov 17 14:17 > >> >> >>>>> > clickstream.log-2012-11-17-1353161821.COMPLETED > >> >> >>>>> > -rw-rw-r-- 1 ubuntu ubuntu 131296672 Nov 17 14:47 > >> >> >>>>> > clickstream.log-2012-11-17-1353163623.COMPLETED > >> >> >>>>> > > >> >> >>>>> > Any insight would be appreciated. > >> >> >>>>> > > >> >> >>>>> > Regards, > >> >> >>>>> > > >> >> >>>>> > Dan > >> >> >>>>> > >> >> >>>>> > >> >> >>>>> > >> >> >>>>> -- > >> >> >>>>> Apache MRUnit - Unit testing MapReduce - > >> >> >>>>> http://incubator.apache.org/mrunit/ > >> >> >>>>> > >> >> >>>>> > >> >> >>>> > >> >> >>> > >> >> >> > >> >> > > >> >> > > >> >> > > >> >> > -- > >> >> > Apache MRUnit - Unit testing MapReduce - > >> >> > http://incubator.apache.org/mrunit/ > >> >> > >> >> > >> >> > >> >> -- > >> >> Apache MRUnit - Unit testing MapReduce - > >> >> http://incubator.apache.org/mrunit/ > >> > >> > >> > >> -- > >> Apache MRUnit - Unit testing MapReduce - > >> http://incubator.apache.org/mrunit/ > > > > > > > > -- > Apache MRUnit - Unit testing MapReduce - > http://incubator.apache.org/mrunit/ >
