tail -f throws error msg "no space left on device"??

Message

Skidd · Post by **Skidd** » Wed Dec 09, 2009 3:36 pm

I have a rather strange one I'm hoping someone has seen before.
No amount of google searching has turned up anything at all. This might even be a first?!?

I have 3 gentoo boxes running at home, and only 1 is exhibiting this problem. Just happens to be my file server.

in short, I cant run "tail -f" on any file.
I can "tail -200" or almost any other tail function, just not follow.
I get the following.

Code: Select all

castle ~ # tail -f /var/log/messages
Dec  9 09:07:43 castle postfix/postfix-script[29480]: refreshing the Postfix mail system
Dec  9 09:07:43 castle postfix/master[30949]: reload -- version 2.6.5, configuration /etc/postfix
Dec  9 09:09:07 castle postfix/postfix-script[29779]: stopping the Postfix mail system
Dec  9 09:09:07 castle postfix/master[30949]: terminating on signal 15
Dec  9 09:09:08 castle postfix/postfix-script[29869]: starting the Postfix mail system
Dec  9 09:09:08 castle postfix/master[29870]: daemon started -- version 2.6.5, configuration /etc/postfix
Dec  9 09:25:16 castle dhcpd: Wrote 70 leases to leases file.
Dec  9 09:25:16 castle dhcpd: DHCPREQUEST for 10.0.0.49 from 00:0b:e6:0a:95:cc (Wii) via eth0
Dec  9 09:25:16 castle dhcpd: DHCPACK on 10.0.0.49 to 00:0b:e6:0a:95:cc (Wii) via eth0
tail: cannot watch `/var/log/messages': No space left on device
castle ~ #

I'm not sure what device tail is complaining about, but all of my file systems have plenty of space.

Code: Select all

castle ~ # df
Filesystem           1K-blocks      Used Available Use% Mounted on
/dev/md2             243096064 144765356  98330708  60% /
udev                     10240       104     10136   2% /dev
/dev/md3             2930198056 871312596 2058885460  30% /mnt/md3
/dev/md0                101018      7211     88591   8% /boot

Although it's not a powerfull machine, it has plenty of CPU and RAM for it's purpose.

I tried re-emerging coreutils just now, no affect.
I can't say I know when this started, but it's possible it started around the time I did a "emerge -pvnuND world" & revdep-rebuild
But, like I said, my other 2 Gentoo machines work fine, and I had also done a emerge world on them.

Anybody seen this before?

Cheers
Shane

honp · Post by **honp** » Wed Dec 09, 2009 4:06 pm

It is interesting. How big is your /var/log/message file?

Skidd · Post by **Skidd** » Wed Dec 09, 2009 4:23 pm

It is auto log rotated about 1nce a week.
The current file is only 1M.
This error occurs on any file I try to "tail -f" on any file system on that machine.

I tried peeking into the tail.c source code.
I'm a programmer, but not familiar with the coreutils programs.
I was not able to determine what might cause this particular error.

ccp · Post by **ccp** » Wed Dec 09, 2009 4:46 pm

Just a wild guess, could it be you ulimit setting? running out of file handler?

Skidd · Post by **Skidd** » Wed Dec 09, 2009 5:06 pm

ulimit?
That's a new one on me!
Can you elaborate for me?

Oop... spelling error on my part.
Doing some digging now.

Skidd · Post by **Skidd** » Wed Dec 09, 2009 5:21 pm

Ok, here is the output of ulimit

Code: Select all

# ulimit
unlimited
#

Genone · Post by **Genone** » Wed Dec 09, 2009 5:33 pm

Try running it under strace to see the syscall that is failing.

Skidd · Post by **Skidd** » Wed Dec 09, 2009 5:45 pm

Since the file I tail didn't matter, I used a simple test text file. Here are the results with strace

Code: Select all

castle ~ # tail test.txt 
LINE 1
LINE 2
LINE 3
LINE 4
LINE 5
castle ~ #

Code: Select all

castle ~ # strace tail -f test.txt 
execve("/usr/bin/tail", ["tail", "-f", "test.txt"], [/* 40 vars */]) = 0
brk(0)                                  = 0x8056000
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY)      = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=70009, ...}) = 0
mmap2(NULL, 70009, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7f65000
close(3)                                = 0
open("/lib/libc.so.6", O_RDONLY)        = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0ph\1\0004\0\0\0\244"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=1351964, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7f64000
mmap2(NULL, 1357424, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb7e18000
mmap2(0xb7f5e000, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x146) = 0xb7f5e000
mmap2(0xb7f61000, 9840, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xb7f61000
close(3)                                = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7e17000
set_thread_area({entry_number:-1 -> 6, base_addr:0xb7e176c0, limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1, seg_not_present:0, useable:1}) = 0
mprotect(0xb7f5e000, 8192, PROT_READ)   = 0
mprotect(0x8054000, 4096, PROT_READ)    = 0
mprotect(0xb7f95000, 4096, PROT_READ)   = 0
munmap(0xb7f65000, 70009)               = 0
brk(0)                                  = 0x8056000
brk(0x8077000)                          = 0x8077000
open("/usr/lib/locale/locale-archive", O_RDONLY|O_LARGEFILE) = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=1561088, ...}) = 0
mmap2(NULL, 1561088, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7c99000
close(3)                                = 0
open("/usr/share/locale/locale.alias", O_RDONLY) = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=2570, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7f76000
read(3, "# Locale name alias data base.\n# "..., 4096) = 2570
read(3, ""..., 4096)                    = 0
close(3)                                = 0
munmap(0xb7f76000, 4096)                = 0
open("/usr/lib/locale/en_us.utf8/LC_IDENTIFICATION", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/lib/locale/en_us/LC_IDENTIFICATION", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/lib/locale/en.utf8/LC_IDENTIFICATION", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/lib/locale/en/LC_IDENTIFICATION", O_RDONLY) = -1 ENOENT (No such file or directory)
open("test.txt", O_RDONLY|O_LARGEFILE)  = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=35, ...}) = 0
_llseek(3, 0, [0], SEEK_CUR)            = 0
_llseek(3, 0, [35], SEEK_END)           = 0
_llseek(3, 0, [0], SEEK_SET)            = 0
read(3, "LINE 1\nLINE 2\nLINE 3\nLINE 4\nLINE "..., 35) = 35
_llseek(3, 0, [0], SEEK_SET)            = 0
read(3, "LINE 1\nLINE 2\nLINE 3\nLINE 4\nLINE "..., 35) = 35
fstat64(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 1), ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7f76000
write(1, "LINE 1\n"..., 7LINE 1
)              = 7
write(1, "LINE 2\n"..., 7LINE 2
)              = 7
write(1, "LINE 3\n"..., 7LINE 3
)              = 7
write(1, "LINE 4\n"..., 7LINE 4
)              = 7
write(1, "LINE 5\n"..., 7LINE 5
)              = 7
fstat64(3, {st_mode=S_IFREG|0644, st_size=35, ...}) = 0
inotify_init()                          = 4
inotify_add_watch(4, "test.txt", IN_MODIFY|IN_ATTRIB|IN_DELETE_SELF|IN_MOVE_SELF) = -1 ENOSPC (No space left on device)
write(2, "tail: "..., 6tail: )                = 6
write(2, "cannot watch `test.txt'"..., 23cannot watch `test.txt') = 23
write(2, ": No space left on device"..., 25: No space left on device) = 25
write(2, "\n"..., 1
)                    = 1
close(1)                                = 0
munmap(0xb7f76000, 4096)                = 0
close(2)                                = 0
exit_group(1)                           = ?
castle ~ #

Any theories?

ccp · Post by **ccp** » Wed Dec 09, 2009 6:41 pm

Did you build your own kernel? if you do did you include inotify configuration option?

At the moment is there a lots of process running? according to man page you are running out of inotify watches.

cat /proc/sys/fs/inotify/max_user_watches and /proc/sys/fs/inotify/max_user_instances for your upper limit.

Skidd · Post by **Skidd** » Wed Dec 09, 2009 7:15 pm

Yes, I did build my own kernel. INotify is enabled.

Code: Select all

CONFIG_INOTIFY=y
CONFIG_INOTIFY_USER=y

My process count is low. It's a headless server so not even any X processes.

Code: Select all

castle ~ # ps -eal | wc -l
133
castle ~ #

Mind you, one of the processes is Apache serving up 6 domains!!

Code: Select all

castle ~ # cat /proc/sys/fs/inotify/max_user_watches 
8192
castle ~ #

Seems a little low to me.
Out of curiocity, I ran a "tail -f" as a normal user. No error!!
So, it's only root that barfs. "sudo tail -f" also barfs.
So... this max_user_watches seems like it might be my the culprit.
Now, to figure out how it's set and adjusted!

Code: Select all

castle ~ # cat /proc/sys/fs/inotify/max_user_instances 
128
castle ~ #

I have no idea if this is a good value.

Code: Select all

castle ~ # cat /proc/sys/fs/inotify/max_queued_events 
16384
castle ~ #

i92guboj · Post by **i92guboj** » Wed Dec 09, 2009 7:18 pm

If you are using an i-node based fs, did you already check the output for df -i? Maybe you are just running out of i-nodes.

Skidd · Post by **Skidd** » Wed Dec 09, 2009 7:35 pm

I don't belive inodes is an issue. But, I'm no expert.
I'm using reiserFS on my main partitions. ext2 on my boot.

Code: Select all

castle ~ # df -i
Filesystem            Inodes   IUsed   IFree IUse% Mounted on
/dev/md2                   0       0       0    -  /
udev                   64271    4902   59369    8% /dev
/dev/md3                   0       0       0    -  /mnt/md3
/dev/md0               26104      35   26069    1% /boot
castle ~ #

Oh yeah.. and, just for reference

Code: Select all

castle ~ # uname -a
Linux castle 2.6.30-gentoo-r6 #1 SMP Sun Sep 13 09:33:56 CDT 2009 i686 Intel(R) Celeron(TM) CPU 1100MHz GenuineIntel GNU/Linux
castle ~ #

I think the fact that tail -f works as a regular user is my key.
Since max_user_watches appears to be based on 1/32 of available low memory, I guess that's where the problem is. My machine has a whopping 512M or RAM. (Motherboard Limited)

ccp · Post by **ccp** » Wed Dec 09, 2009 7:45 pm

as root, you can use this command

sysctl -w fs.inotify.max_user_watches=16384

Skidd · Post by **Skidd** » Wed Dec 09, 2009 7:45 pm

Fixed!!

Code: Select all

castle ~ # sysctl fs.inotify.max_user_watches
fs.inotify.max_user_watches = 8192
castle ~ #
castle ~ # sysctl -w fs.inotify.max_user_watches=16384
fs.inotify.max_user_watches = 16384
castle ~ # tail -f test.txt 
LINE 1
LINE 2
LINE 3
LINE 4
LINE 5

I added the fs.inotify.max_user_watches=16384 to my sysctl.conf file.
Now, the $1,000,000 question, is will this have a detrimental affect on my system in some way?

Thanks for your help guys!
I never would have figured that one out on my own.

ccp · Post by **ccp** » Wed Dec 09, 2009 7:49 pm

inotify system use kernel space memory. so the more you set the less your user space program can use which will increase the likelihood of swap.

I guess in your apache there may be something doing file system monitoring. may be some kind of search engine?

Skidd · Post by **Skidd** » Wed Dec 09, 2009 8:14 pm

ccp wrote:inotify system use kernel space memory. so the more you set the less your user space program can use which will increase the likelihood of swap.

I guess in your apache there may be something doing file system monitoring. may be some kind of search engine?

Ah.. Cheers.
Well, even with only 512M, I have 36M free and am swapping a whopping 71M.
So, I expect I should be just fine.

As for what apache is doing... it's possible it's to blame, but most of it's processes are running as the "apache" use, and not as root.
So, something running as root is to blame, or it's just that the 8K max limit was the reason.

I wonder if CrashPlan is to blame? My file server is also my local CrashPlan server for my client workstations.
It could be the cause. Or, perhaps Samba. Either way, I'm good to go now! And, now I know where to look in the future.

syntax3rror · Post by **syntax3rror** » Tue Jun 28, 2011 8:16 am

Skidd wrote:Fixed!!
Code: Select all
castle ~ # sysctl fs.inotify.max_user_watches
fs.inotify.max_user_watches = 8192
castle ~ #
castle ~ # sysctl -w fs.inotify.max_user_watches=16384
fs.inotify.max_user_watches = 16384
castle ~ # tail -f test.txt 
LINE 1
LINE 2
LINE 3
LINE 4
LINE 5
I added the fs.inotify.max_user_watches=16384 to my sysctl.conf file.
Now, the $1,000,000 question, is will this have a detrimental affect on my system in some way?

Thanks for your help guys!
I never would have figured that one out on my own.

Sounds like this solution is not the right solution all time. I do this past two days ago, it works fine. However for this time I encountering again and higher-up the value again?

BTW, thanks for sharing.

Cheers,
-- Syn

patrix_neo · Post by **patrix_neo** » Tue Jun 28, 2011 8:05 pm

Just an input. Have you looked at dmesg or (F12) console-output while trying tail -f ?

If not, I would, and check for clues.

[edit] Alt-F12
[edit2] a *nix system always use to leave a trail of what's wrong..