Recently, I had to diagnose an issue where the only symptom was a failure with ‘mailx’ command from time to time, which caused the following output to be mailed instead of the expected report from a cron job:
Your “cron” job on <Hostname> /path/to/script | mailx my@email.domain
produced the following output:
/tmp/Rs10293: File exists
At this point, it was unclear to me where the “/tmp/Rs10293” file was coming, but apparently, /tmp was containing a lot of these RsXXXXX files.
It became quickly obvious that the command which produced those RsXXXX files was ‘mailx’:
# strings /usr/bin/mailx|grep /tmp/Rs
/tmp/Rs%-ld
Oddly enough, I knew now that the file was created by mailx and that after a while, it was trying to create the same file and quit failing. But how comes this file was left in /tmp ?
I’ve decided to put a wrapper to the mailx command which would dump the ‘truss’ output to /var/tmp and then see what happens:
# mv /usr/bin/mailx /usr/bin/mailx.orig
# cat > /usr/bin/mailx
#!/bin/bash
truss -eafld -vall -wall -rall -xall -u a.out -o /var/tmp/mail.$(date +%Y%m%d_%H%M%S).truss /usr/bin/mailx.orig $@
^D
After a while, I’ve noticed that I got some very short truss output file and gotcha! They were exitting quickly after having created the corresponding ‘/tmp/RsXXXX’ file:
14581/1: 0.3988 openat(0xFFD19553, 0x080865C2, 02402, 0600) = 263
14581/1: 0xFFD19553: AT_FDCWD
14581/1: 0x080865C2: “/tmp/Rs14581”
14581/1: 0.3990 fcntl(263, 1, 0x00000000) = 0
14581/1: 0.3991 openat(0xFFD19553, 0xF0FC7F60, 0, 024) Err#2 ENOENT
14581/1: 0xFFD19553: AT_FDCWD
14581/1: 0xF0FC7F60: “/usr/lib/locale/en_US.UTF-8/LC_MESSAGES/SUNW_OST_OSLIB.mo”
14581/1: 0.3992 write(2, 0x080865C2, 12) = 12
14581/1: 0x080865C2: ” / t m p / R s 1 4 5 8 1″
14581/1: 0.3993 write(2, 0xEF558B90, 2) = 2
14581/1: 0xEF558B90: ” : ”
14581/1: 0.3995 write(2, 0xEF50393A, 19) = 19
14581/1: T o o m a n y o p e n f i l e s
14581/1: 0.3995 write(2, 0xEF558B8C, 1) = 1
14581/1: 0xEF558B8C: “\n”
I also discovered that the utility which was launching theses faulty ‘mailx’ commands was ‘smartmon-ux’ disk monitoring software.
I confirmed that by reloading smartmon-ux and waiting on the console:
/dev/rdsk/c0t5000C50055C78D1Bd0s0 polled at Mon Feb 11 06:18:07 2013 Status:Passed (Temperature = 34C 93F) (Speed: Port0=6.0 G; Port1=6.0 G)
/dev/rdsk/c0t5000C50055C78D43d0s0 polled at Mon Feb 11 06:18:08 2013 Status:Passed (Temperature = 28C 82F) (Speed: Port0=6.0 G; Port1=6.0 G)
/dev/rdsk/c0t5000C50055C791F7d0s0 polled at Mon Feb 11 06:18:08 2013 Status:Passed (Temperature = 28C 82F) (Speed: Port0=6.0 G; Port1=6.0 G)
/dev/rdsk/c0t5000C50055C792EFd0s0 polled at Mon Feb 11 06:18:08 2013 Status:Passed (Temperature = 31C 87F) (Speed: Port0=6.0 G; Port1=6.0 G)
/dev/rdsk/c0t5000C50055C7982Bd0s0 polled at Mon Feb 11 06:18:09 2013 Status:Passed (Temperature = 36C 96F) (Speed: Port0=6.0 G; Port1=6.0 G)
/dev/rdsk/c0t5000C50055C7999Fd0s0 polled at Mon Feb 11 06:18:09 2013 Status:Passed (Temperature = 32C 89F) (Speed: Port0=6.0 G; Port1=6.0 G)
/dev/rdsk/c0t5000C5005A8B8693d0s0 polled at Mon Feb 11 06:18:10 2013 Status:Passed (Temperature = 27C 80F) (Speed: Port0=6.0 G; Port1=<unattached>)
/tmp/Rs16850: Too many open files
Device on /dev/rdsk/c2t0d0s0, Thermal alert. Temperature now at 255C 491F degrees.
/dev/rdsk/c2t0d0s0 polled at Mon Feb 11 06:18:10 2013 Status:Passed (Temperature = 255C 491F)
/tmp/Rs16853: Too many open files
Device on /dev/rdsk/c3t1d0s0, Thermal alert. Temperature now at 255C 491F degrees.
/dev/rdsk/c3t1d0s0 polled at Mon Feb 11 06:18:10 2013 Status:Passed (Temperature = 255C 491F)
/tmp/Rs16856: Too many open files
Device on /dev/rdsk/c6t6d0s0, Thermal alert. Temperature now at 255C 491F degrees.
/dev/rdsk/c6t6d0s0 polled at Mon Feb 11 06:18:10 2013 Status:Passed (Temperature = 255C 491F)
/tmp/Rs16859: Too many open files
Device on /dev/rdsk/c7t7d0s0, Thermal alert. Temperature now at 255C 491F degrees.
/dev/rdsk/c7t7d0s0 polled at Mon Feb 11 06:18:11 2013 Status:Passed (Temperature = 255C 491F)
Right, now we know the “Who”, but why?
The syscall returned ‘Too many open files’ error which was impossible as per our /etc/system:
set rlim_fd_max=900000
set rlim_fd_cur=32768
And checking the current per-process limit:
# plimit $$|grep nofiles
nofiles(descriptors) 32768 900000
So we can open 32k files! How comes smartmon-ux/mailx is complaining?
# pgrep smartmon-ux
16692
# ls -l /proc/16692/fd/*|wc -l
261
So we’re clearly not reaching the 32k file descriptor limit! I’ve then found this blog post from 2006.
Let’s confirm that by compiling this little .c file:
#include <stdio.h>
#define MAXF 65535
int main()
{
char filename[20];
FILE *fds[MAXF];
int i;
for (i = 0; i < MAXF; ++i)
{
sprintf (filename, "./out/%d.log", i);
fds[i] = fopen(filename, "w");
if (fds[i] == NULL)
{
printf("\n** Number of open files = %d. fopen() failed with error: ", i);
perror("");
exit(1);
}
else
{
fprintf (fds[i], "some string");
}
}
return (0);
}
# gcc -o files files.c
# mkdir out
# ./files
** Number of open files = 253. fopen() failed with error: Too many open files
# ls out|wc -l
254
ARGHL… ?
Then, the funny part is comming:
# gcc -o files files.c -m64
# ./files
** Number of open files = 32765. fopen() failed with error: Too many open files
Okay, this is a 32 vs 64 bits problem. Googling again is taking us to the /usr/lib/extendedFILE.so.1 library, which overcomes this bug:
# gcc -o files files.c
# file files
files: ELF 32-bit LSB executable 80386 Version 1 [FPU], dynamically linked, not stripped, no debugging information available
# LD_PRELOAD=/usr/lib/extendedFILE.so.1 ./files
** Number of open files = 32353. fopen() failed with error: Not enough space
And so our problem is fixed! Now let’s change a little bit the smartmon-ux start script to work around our problem:
Edit /etc/init.d/smartmon-ux.d and change line
/etc/smartmon-ux -E -G 45 -link -F 1200 -P -sq -M smartmon-alert@domain.tld
by:
LD_PRELOAD=/usr/lib/secure/extendedFILE.so.1 /etc/smartmon-ux -E -G 45 -link -F 1200 -P -sq -M smartmon-alert@domain.tld
also, symlink libextendedFILE.so.1 in the /usr/lib/secure directory to avoid the system complaining (mailx is setguid!!)
# cd /usr/lib/secure ; ln -s /usr/lib/extendedFILE.so.1
restart smartmon-ux and check it’s been using the library:
# /etc/init.d/smartmon-ux.d restart
# pgrep smartmon-ux
18319
# ls -al /proc/18319/path/|grep extendedFILE
lrwxrwxrwx 1 root root 0 2013-02-11 06:43 zfs.124.65538.134236 -> /usr/lib/extendedFILE.so.1
Then, I’ve begin thinking… what would be the proper and definitive fix for that problem? Would smartmon-ux compiled in 64bit be the fix?
Let’s try with our little .c file slightly modified:
#include <stdio.h>
#define MAXF 252
int main()
{
char filename[20];
FILE *fds[MAXF];
int i;
for (i = 0; i < MAXF; ++i)
{
sprintf (filename, "./out/%d.log", i);
fds[i] = fopen(filename, "w");
if (fds[i] == NULL)
{
printf("\n** Number of open files = %d. fopen() failed with error: ", i);
perror("");
exit(1);
}
else
{
fprintf (fds[i], "some string");
}
}
/* we have MAXF opened FD, now try to send a mail... */
execl("/usr/bin/mailx", "-s", "test files2.c", "-f", "/root/test/mymail", "my@mail.tld", NULL);
return (0);
}
# gcc -o files2 files2.c # ./files2
/tmp/Rs20586: Too many open files
# gcc -o files2_64 files2.c -m64
# ./files2_64
/tmp/Rs20637: Too many open files
Conclusions:
- Smartmon-UX is leaking FDs to mailx process
- Having Smartmon-UX compiled in 64 bits wouldn’t help
- mailx should be fixed to cleanup /tmp/RsXXXXX files before exiting in error
- extendedFILE.so.1 preload could be used as workaround
- Final fix should be fixing smartmon-ux file descriptor leak issue
NOTE: I filed a support case with this, I will let you know the outcome…
