Subject: Re: [vserver] Problem with locks
From: Herbert Poetzl <herbert@13thfloor.at>
Date: Fri, 23 Mar 2012 15:30:40 +0100

On Tue, Mar 20, 2012 at 03:23:59PM +0100, PSTM wrote:
> El 19/03/2012 23:31, Adrian Reyer escribió:

>>> I killed all programs except sshd and system (vps, centos 6) still
>>> have no locks for programs.
>> How many connections are shown by 'netstat -anp' or similar?

> Lsof said 729 used files.

> ulimit:
> core file size          (blocks, -c) 0
> data seg size           (kbytes, -d) unlimited
> scheduling priority             (-e) 0
> file size               (blocks, -f) unlimited
> pending signals                 (-i) 63974
> max locked memory       (kbytes, -l) 64
> max memory size         (kbytes, -m) unlimited
> open files                      (-n) 1024
> pipe size            (512 bytes, -p) 8
> POSIX message queues     (bytes, -q) 819200
> real-time priority              (-r) 0
> stack size              (kbytes, -s) 8192
> cpu time               (seconds, -t) unlimited
> max user processes              (-u) 1024
> virtual memory          (kbytes, -v) unlimited
> file locks                      (-x) unlimited


>>> Really I do not know how to trace de problem. I have postfix
>>> running in other servers (fedora 16 no vps) without any
>>> problem.

>>> And as Wietse Venemas said, postfix ask for a lock but kernel
>>> do not provide it.

>> Can you reproduce/force the issue? If so, you can always try
>> and do an 'strace' and see what actually fails.


> lsof:
> ####################
> master    5360    root   85w     FIFO                0,7      0t0 
> 1224753202 pipe
> master    5360    root   11r     FIFO                0,7      0t0 
> 1224753202 pipe



> strace

> ###################
> open("/etc/postfix/master.cf", O_RDONLY) = 11

> ...

> pipe([11, 85])                          = 0
> fcntl(85, F_GETFL)                      = 0x1 (flags O_WRONLY)
> fcntl(85, F_SETFL, O_WRONLY|O_NONBLOCK) = 0
> fcntl(11, F_GETFL)                      = 0 (flags O_RDONLY)
> fcntl(11, F_SETFL, O_RDONLY|O_NONBLOCK) = 0
> fcntl(85, F_GETFD)                      = 0
> fcntl(85, F_SETFD, FD_CLOEXEC)          = 0
> fcntl(11, F_GETFD)                      = 0
> fcntl(11, F_SETFD, FD_CLOEXEC)          = 0


> Good, works
> #################################################
> alarm(333)                              = 333
> epoll_wait(13, {}, 100, 60000)          = 0
> geteuid()                               = 0
> setresgid(-1, 89, -1)                   = 0
> setgroups(1, [89])                      = 0
> setresuid(-1, 89, -1)                   = 0
> open("public/pickup", O_WRONLY|O_NONBLOCK) = 88
> fstat(88, {st_mode=S_IFIFO|0622, st_size=0, ...}) = 0
> lstat("public/pickup", {st_mode=S_IFIFO|0622, st_size=0, ...}) = 0
> fcntl(88, F_GETFL)                      = 0x8801 (flags 
> O_WRONLY|O_NONBLOCK|O_LARGEFILE)
> fcntl(88, F_SETFL, O_WRONLY|O_NONBLOCK|O_LARGEFILE) = 0
> poll([{fd=88, events=POLLOUT}], 1, 1000) = 1 ([{fd=88, revents=POLLOUT}])
> write(88, "W", 1)                       = 1
> close(88)                               = 0
> getgid()                                = 0
> getuid()                                = 0
> geteuid()                               = 89
> setresuid(-1, 0, -1)                    = 0
> setgid(0)                               = 0
> setgroups(1, [0])                       = 0
> setuid(0)                               = 0
> alarm(333)                              = 273


> Error, do not work
> ##############################################
> --- SIGCHLD (Child exited) @ 0 (0) ---
> write(85, "\0", 1)                      = 1
> rt_sigreturn(0x55)                      = -1 EINTR (Interrupted system call)
> alarm(333)                              = 332
> epoll_wait(13, {{EPOLLIN, {u32=11, u64=6482466260943634443}}}, 100, 
> 13000) = 1
> read(11, "\0", 1)                       = 1
> read(11, 0x7fff805466bf, 1)             = -1 EAGAIN (Resource 
> temporarily unavailable)
> wait4(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 1}], WNOHANG, NULL) = 5175
> sendto(3, "<20>Mar 20 11:10:46 postfix/mast"..., 109, MSG_NOSIGNAL, 
> NULL, 0) = 109
> sendto(3, "<20>Mar 20 11:10:46 postfix/mast"..., 113, MSG_NOSIGNAL, 
> NULL, 0) = 113
> wait4(-1, 0x7fff80546b98, WNOHANG, NULL) = 0
> alarm(333)                              = 333
> epoll_wait(13, {}, 100, 13000)          = 0
> geteuid()                               = 0
> setresgid(-1, 89, -1)                   = 0
> setgroups(1, [89])                      = 0
> setresuid(-1, 89, -1)                   = 0
> open("public/pickup", O_WRONLY|O_NONBLOCK) = 88
> fstat(88, {st_mode=S_IFIFO|0622, st_size=0, ...}) = 0
> lstat("public/pickup", {st_mode=S_IFIFO|0622, st_size=0, ...}) = 0
> fcntl(88, F_GETFL)                      = 0x8801 (flags 
> O_WRONLY|O_NONBLOCK|O_LARGEFILE)
> fcntl(88, F_SETFL, O_WRONLY|O_NONBLOCK|O_LARGEFILE) = 0
> poll([{fd=88, events=POLLOUT}], 1, 1000) = 1 ([{fd=88, revents=POLLOUT}])
> write(88, "W", 1)                       = 1
> close(88)                               = 0
> getgid()                                = 0
> getuid()                                = 0
> geteuid()                               = 89
> setresuid(-1, 0, -1)                    = 0
> setgid(0)                               = 0
> setgroups(1, [0])                       = 0
> setuid(0)                               = 0
> alarm(333)                              = 320
> epoll_wait(13, {{EPOLLIN, {u32=17, u64=6540183302777602065}}}, 100, 
> 47000) = 1
> read(17, "\35\r\0\0t\0\0\0\0\0\0\0", 12) = 12
> alarm(333)                              = 333
> epoll_wait(13, {{EPOLLIN, {u32=17, u64=6540183302777602065}}}, 100, 
> 47000) = 1
> read(17, "\35\r\0\0t\0\0\0\1\0\0\0", 12) = 12
> alarm(333)                              = 333
> epoll_wait(13, {}, 100, 47000)          = 0
> epoll_ctl(13, EPOLL_CTL_ADD, 25, {EPOLLIN, {u32=25, 
> u64=6491915257714311193}}) = 0
> alarm(333)                              = 286
> epoll_wait(13, {{EPOLLIN, {u32=25, u64=6491915257714311193}}}, 100, 
> 13000) = 1
> clone(child_stack=0, 
> flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, 
> child_tidptr=0x7f0959f41a90) = 9163
> epoll_ctl(13, EPOLL_CTL_DEL, 25, {EPOLLIN, {u32=25, 
> u64=6312716186899447833}}) = 0
> alarm(333)                              = 333
> epoll_wait(13, 7fff805466e0, 100, 13000) = -1 EINTR (Interrupted system 
> call)
> --- SIGCHLD (Child exited) @ 0 (0) ---



> Not very useful (for me), searching for fd 11 returns to 
> "/etc/postfix/main.cf", but not sure that is that ...
> write(85, "\0", 1)                      = 1

I do not see any process failing to acquire a lock in your
traces, actually I do not even see a process trying to
acquire a lock in those traces ... presuming that Wietse
is right (and he should know :) we are not looking at the
correct traces so far ... 

> 85 is a pipe with write lock

> read(11, "\0", 1)                       = 1
> read(11, 0x7fff805466bf, 1)             = -1 EAGAIN (Resource 
> temporarily unavailable)

I'd wrap the other processes, e.g. the pickup with an
strace shell wrapper, so that we get some information what
is requested and denied from the kernel side ...

HTH,
Herbert

> Seems that no solution it is possible, at customer level.