NFS Lock failing from Linux boxes

[viniciusferrao]

Hello guys,

I'm with a problem with the NFS service in FreeNAS. I first would like to discuss it to make sure it's a FreeNAS bug, and them make a correctly bug report in bugs.freenas.org.

I've a Linux Server running Debian Wheezy with the apt-mirror service. It's a service to create a local mirror. Apt-mirror creates a file named apt-mirror.lock that requires, as I know, an exclusive lock. And when this request is done, apt-mirror just hangs waiting it's request.

This only happens via NFS served from FreeNAS; I've tested moving the lockfile location to the local disk and apt-mirror completed sucessfully, even with it's database mounted via NFS on the FreeNAS Server.

Here is some debugging and output information:

Code:

root@stormwind:/srv/apt-mirror/var# strace apt-mirror
execve("/usr/bin/apt-mirror", ["apt-mirror"], [/* 18 vars */]) = 0
brk(0)                                  = 0x14bf000
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fbdc40eb000
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY)      = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=12168, ...}) = 0
 
--- CUT ---
 
close(4)                                = 0
mprotect(0x7fbdc2adc000, 4096, PROT_READ) = 0
stat("/etc/perl/Exporter/Heavy.pmc", 0x7fff8bbebd10) = -1 ENOENT (No such file or directory)
stat("/etc/perl/Exporter/Heavy.pm", 0x7fff8bbebc60) = -1 ENOENT (No such file or directory)
stat("/usr/local/lib/perl/5.14.2/Exporter/Heavy.pmc", 0x7fff8bbebd10) = -1 ENOENT (No such file or directory)
stat("/usr/local/lib/perl/5.14.2/Exporter/Heavy.pm", 0x7fff8bbebc60) = -1 ENOENT (No such file or directory)
stat("/usr/local/share/perl/5.14.2/Exporter/Heavy.pmc", 0x7fff8bbebd10) = -1 ENOENT (No such file or directory)
stat("/usr/local/share/perl/5.14.2/Exporter/Heavy.pm", 0x7fff8bbebc60) = -1 ENOENT (No such file or directory)
stat("/usr/lib/perl5/Exporter/Heavy.pmc", 0x7fff8bbebd10) = -1 ENOENT (No such file or directory)
stat("/usr/lib/perl5/Exporter/Heavy.pm", 0x7fff8bbebc60) = -1 ENOENT (No such file or directory)
stat("/usr/share/perl5/Exporter/Heavy.pmc", 0x7fff8bbebd10) = -1 ENOENT (No such file or directory)
stat("/usr/share/perl5/Exporter/Heavy.pm", 0x7fff8bbebc60) = -1 ENOENT (No such file or directory)
stat("/usr/lib/perl/5.14/Exporter/Heavy.pmc", 0x7fff8bbebd10) = -1 ENOENT (No such file or directory)
stat("/usr/lib/perl/5.14/Exporter/Heavy.pm", 0x7fff8bbebc60) = -1 ENOENT (No such file or directory)
stat("/usr/share/perl/5.14/Exporter/Heavy.pmc", 0x7fff8bbebd10) = -1 ENOENT (No such file or directory)
stat("/usr/share/perl/5.14/Exporter/Heavy.pm", {st_mode=S_IFREG|0644, st_size=6233, ...}) = 0
open("/usr/share/perl/5.14/Exporter/Heavy.pm", O_RDONLY) = 4
ioctl(4, SNDCTL_TMR_TIMEBASE or TCGETS, 0x7fff8bbeb9f0) = -1 ENOTTY (Inappropriate ioctl for device)
lseek(4, 0, SEEK_CUR)                  = 0
read(4, "package Exporter::Heavy;\n\nuse st"..., 8192) = 6233
brk(0x168d000)                          = 0x168d000
read(4, "", 8192)                      = 0
close(4)                                = 0
brk(0x16ae000)                          = 0x16ae000
read(3, "################################"..., 8192) = 8192
brk(0x16cf000)                          = 0x16cf000
read(3, "bytes = 0;\n\nsub process_symlink "..., 8192) = 3154
brk(0x16f0000)                          = 0x16f0000
read(3, "", 8192)                      = 0
close(3)                                = 0
pipe([3, 4])                            = 0
pipe([5, 6])                            = 0
clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7fbdc40e49d0) = 3599
close(6)                                = 0
close(4)                                = 0
read(5, "", 4)                          = 0
close(5)                                = 0
ioctl(3, SNDCTL_TMR_TIMEBASE or TCGETS, 0x7fff8bbebfe0) = -1 EINVAL (Invalid argument)
lseek(3, 0, SEEK_CUR)                  = -1 ESPIPE (Illegal seek)
fstat(3, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0
read(3, "amd64\n", 8192)                = 6
read(3, "", 8192)                      = 0
--- SIGCHLD (Child exited) @ 0 (0) ---
fstat(3, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0
close(3)                                = 0
rt_sigaction(SIGHUP, {SIG_IGN, [], SA_RESTORER, 0x7fbdc34ba030}, {SIG_DFL, [], 0}, 8) = 0
rt_sigaction(SIGINT, {SIG_IGN, [], SA_RESTORER, 0x7fbdc34ba030}, {SIG_DFL, [], 0}, 8) = 0
rt_sigaction(SIGQUIT, {SIG_IGN, [], SA_RESTORER, 0x7fbdc34ba030}, {SIG_DFL, [], 0}, 8) = 0
wait4(3599, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 3599
rt_sigaction(SIGHUP, {SIG_DFL, [], SA_RESTORER, 0x7fbdc34ba030}, NULL, 8) = 0
rt_sigaction(SIGINT, {SIG_DFL, [], SA_RESTORER, 0x7fbdc34ba030}, NULL, 8) = 0
rt_sigaction(SIGQUIT, {SIG_DFL, [], SA_RESTORER, 0x7fbdc34ba030}, NULL, 8) = 0
open("/etc/apt/mirror.list", O_RDONLY)  = 3
ioctl(3, SNDCTL_TMR_TIMEBASE or TCGETS, 0x7fff8bbebf90) = -1 ENOTTY (Inappropriate ioctl for device)
lseek(3, 0, SEEK_CUR)                  = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=8008, ...}) = 0
fcntl(3, F_SETFD, FD_CLOEXEC)          = 0
read(3, "############# config ###########"..., 8192) = 8008
read(3, "", 8192)                      = 0
close(3)                                = 0
stat("/var/spool/apt-mirror/mirror", {st_mode=S_IFDIR|0755, st_size=5, ...}) = 0
stat("/var/spool/apt-mirror/skel", {st_mode=S_IFDIR|0755, st_size=7, ...}) = 0
stat("/var/spool/apt-mirror/var", {st_mode=S_IFDIR|0755, st_size=89, ...}) = 0
open("/var/spool/apt-mirror/var/apt-mirror.lock", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
ioctl(3, SNDCTL_TMR_TIMEBASE or TCGETS, 0x7fff8bbebf90) = -1 ENOTTY (Inappropriate ioctl for device)
lseek(3, 0, SEEK_CUR)                  = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
fcntl(3, F_SETFD, FD_CLOEXEC)          = 0
flock(3, LOCK_EX|LOCK_NB

strace apt-mirror hangs in this part.

I've done some searchs and found this bug report from @jgreco : https://bugs.freenas.org/issues/927

I don't know exactly if it's related, but theres a problem with this request because there was some problem replicating the issue.

Thanks in advance,

 

[dlavigne]

It looks like that bug is getting some traction. Are you able to upgrade to 9.2.1.4.1 to see if that fixes the issue?

 

[cyberjock]

I've seen the ENONET problem myself. But I dismissed it as me doing something stupid. Unfortunately, I can't remember what I changed to make that problem go away...