2

I connect to a RHEL 5.7 server via Putty or VNC (not sure it matters) but when I try to run screen, it takes forever (on order of 20-30 secs). Same thing if I run screen -ls, takes just as long.

I don't know if it has to do with where screen is configured? But when I go to $HOME, there was no .screenrc file. (So where is it? I read I can define my own location, so maybe this is a minor point...)

screen -v gives Screen version 4.00.03 (FAU) 23-Oct-06

Does anyone have ideas on what the issue could be or is it just the way it is?


Update 2

  1. I've tried setting environment variables $SCREENDIR and $SCREENRC to ~/.screenrc and to a location on the server /home/myusername = no change
  2. I've tried a blank .screenrc file = no change
  3. I've tried adding defnonblock on to .screenrc = no change
  4. Also tried running strace with the additional -f option, but didn't notice any new info?

strace file #2, snippet 1, first occurrence of that funny number 4294967295

11:24:23 connect(4, {sa_family=AF_FILE, path="/dev/log"...}, 110) = 0
11:24:23 sendto(4, "<14>Jun 25 11:24:23 screen: nss_"..., 129, MSG_NOSIGNAL, NULL, 0) = 129
11:24:23 write(3, "\27\3\1\0\33\331\331\30\274MD\374s\375ia\341!\200\16\4&\205\177\320\274\213\224gz\376l", 32) = 32
11:24:23 write(3, "\25\3\1\0\26\304\345w\317\273\257\256\322\314.\20T\372;'EQ\222\10z\375\234", 27) = 27
11:24:23 shutdown(3, 2 /* send and receive */) = 0
11:24:23 close(3)                       = 0
11:24:23 read(4294967295, 0xe5d3350, 5) = -1 EBADF (Bad file descriptor)
11:24:23 shutdown(4294967295, 2 /* send and receive */) = -1 EBADF (Bad file descriptor)
11:24:23 close(4294967295)              = -1 EBADF (Bad file descriptor)
11:24:23 stat("/etc/ldap.conf", {st_mode=S_IFREG|0644, st_size=10681, ...}) = 0
11:24:23 geteuid()                      = 287621
11:24:23 open("/etc/hosts", O_RDONLY)   = 3

New theory : In-between those nanosleep calls, I see it's doing something with a unix auth server. What is it doing or why... I don't know. But then this line appears

sendto(4, "<14>Jun 25 11:24:28 screen: nss_"..., 129, MSG_NOSIGNAL, NULL, 0) = 129

and I can't read the entire error message?? Then, the "Bad file descriptor" lines showup, and bam, going to sleep again. Could understanding what it's doing with the unix auth server be key to understanding these delays?

strace file #2, snippet 2, zooming in on what happens before the sleeps occur. Changed the company name and IP addresses to dummy values.

11:24:28 recvfrom(3, "\266!\201\200\0\1\0\2\0\0\0\0\10unixauth\2cs\6company\3"..., 1024, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("987.654.321.09")}, [16]) = 86
11:24:28 close(3)                       = 0
11:24:28 socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 3
11:24:28 fcntl(3, F_SETFD, FD_CLOEXEC)  = 0
11:24:28 setsockopt(3, SOL_SOCKET, SO_KEEPALIVE, [1], 4) = 0
11:24:28 setsockopt(3, SOL_TCP, TCP_NODELAY, [1], 4) = 0
11:24:28 fcntl(3, F_GETFL)              = 0x2 (flags O_RDWR)
11:24:28 fcntl(3, F_SETFL, O_RDWR|O_NONBLOCK) = 0
11:24:28 connect(3, {sa_family=AF_INET, sin_port=htons(636), sin_addr=inet_addr("123.456.789.01")}, 16) = -1 EINPROGRESS (Operation now in progress)
11:24:28 poll([{fd=3, events=POLLOUT|POLLERR|POLLHUP}], 1, 90000) = 1 ([{fd=3, revents=POLLOUT}])
11:24:28 getpeername(3, {sa_family=AF_INET, sin_port=htons(636), sin_addr=inet_addr("123.456.789.01")}, [4294967312]) = 0
11:24:28 fcntl(3, F_GETFL)              = 0x802 (flags O_RDWR|O_NONBLOCK)
11:24:28 fcntl(3, F_SETFL, O_RDWR)      = 0
11:24:28 write(3, "\200w\1\3\1\0N\0\0\0 \0\0009\0\0008\0\0005\0\0\26\0\0\23\0\0\n\7\0\300"..., 121) = 121
11:24:28 read(3, "\26\3\1\0Q\2\0", 7)   = 7
11:24:28 read(3, "\0M\3\1^\270\3\2\277\353\23\377\211\336\255Q\213\342\272\236@\242\252\5\357T\254\207\326\377Jl"..., 79) = 79
11:24:28 read(3, "\26\3\1\16\356", 5)   = 5
11:24:28 read(3, "\v\0\16\352\0\16\347\0\4\2520\202\4\2460\202\3\216\240\3\2\1\2\2\3\v\334/0\r\6\t"..., 3822) = 3822
11:24:28 read(3, "\26\3\1\0\4", 5)      = 5
11:24:28 read(3, "\16\0\0\0", 4)        = 4
11:24:28 write(3, "\26\3\1\0\206\20\0\0\202\0\200+\34JE5\2234\204I\233g@&m\4\232\317\335\323\373\366"..., 186) = 186
11:24:28 read(3, "\24\3\1\0\1", 5)      = 5
11:24:28 read(3, "\1", 1)               = 1
11:24:28 read(3, "\26\3\1\0$", 5)       = 5
11:24:28 read(3, "j\213\362\240R\244\35\257\243/\311\307\360\206\362\314\3\227\353\351\243\242=\222k\0y\367\20\\[\245"..., 36) = 36
11:24:28 write(3, "\27\3\1\0\214\216\374\314\342\264p\205j?\311\356#d\200\25]1\256\371\341\215\325\275jj\26\273"..., 145) = 145
11:24:28 poll([{fd=3, events=POLLIN|POLLPRI|POLLERR|POLLHUP}], 1, 90000) = 1 ([{fd=3, revents=POLLIN}])
11:24:28 read(3, "\27\3\1\0\255", 5)    = 5
11:24:28 read(3, "s\315\357J\363\342\37\10\r\251\333v\302\357\207\3429\3633\345\5\17j\35*K\216\300\225,\r\265"..., 173) = 173
11:24:28 sendto(4, "<14>Jun 25 11:24:28 screen: nss_"..., 129, MSG_NOSIGNAL, NULL, 0) = 129
11:24:28 write(3, "\27\3\1\0\33H\6eq\267(\356\35\366i\364H\372m\17O\7\307d;&\37\345f\212\320H", 32) = 32
11:24:28 write(3, "\25\3\1\0\26\245\267\236\270a\356\227\233\243e\0[3\372\226\33\342f\306\257[ ", 27) = 27
11:24:28 shutdown(3, 2 /* send and receive */) = 0
11:24:28 close(3)                       = 0
11:24:28 read(4294967295, 0xe5d3350, 5) = -1 EBADF (Bad file descriptor)
11:24:28 shutdown(4294967295, 2 /* send and receive */) = -1 EBADF (Bad file descriptor)
11:24:28 close(4294967295)              = -1 EBADF (Bad file descriptor)
11:24:28 sendto(4, "<14>Jun 25 11:24:28 screen: nss_"..., 89, MSG_NOSIGNAL, NULL, 0) = 89
11:24:28 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
11:24:28 rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0
11:24:28 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
11:24:28 nanosleep({8, 0}, {8, 0})      = 0

Update 1 Here's the strace interesting bits... I see it's doing nanosleep repeatedly (each doubling the sleep time) but why?

09:10:05 read(4294967295, 0xca3b350, 5) = -1 EBADF (Bad file descriptor)
09:10:05 shutdown(4294967295, 2 /* send and receive */) = -1 EBADF (Bad file descriptor)
09:10:05 close(4294967295)              = -1 EBADF (Bad file descriptor)
09:10:05 sendto(4, "<14>Jun 25 09:10:05 screen: nss_"..., 89, MSG_NOSIGNAL, NULL, 0) = 89
09:10:05 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
09:10:05 rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0
09:10:05 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
09:10:05 nanosleep({4, 0}, {4, 0})      = 0
09:10:12 stat("/etc/ldap.conf", {st_mode=S_IFREG|0644, st_size=10681, ...}) = 0
09:10:12 geteuid()                      = 287621
09:10:12 open("/etc/hosts", O_RDONLY)   = 3
09:10:12 fcntl(3, F_GETFD)              = 0
...
09:10:20 read(4294967295, 0xca3b350, 5) = -1 EBADF (Bad file descriptor)
09:10:20 shutdown(4294967295, 2 /* send and receive */) = -1 EBADF (Bad file descriptor)
09:10:20 close(4294967295)              = -1 EBADF (Bad file descriptor)
09:10:20 sendto(4, "<14>Jun 25 09:10:20 screen: nss_"..., 90, MSG_NOSIGNAL, NULL, 0) = 90
09:10:20 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
09:10:20 rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0
09:10:20 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
09:10:20 nanosleep({16, 0}, {16, 0})    = 0
09:10:36 stat("/etc/ldap.conf", {st_mode=S_IFREG|0644, st_size=10681, ...}) = 0
09:10:36 geteuid()                      = 287621
09:10:36 open("/etc/hosts", O_RDONLY)   = 3
09:10:36 fcntl(3, F_GETFD)              = 0
...
09:10:36 write(3, "\27\3\1\0\33P\314s\21L-y\316\324\0\345!hd\212\351Q\33\345\335K\3\22\260r\312\332", 32) = 32 
09:10:36 write(3, "\25\3\1\0\26V\20\224{t2\364\250k\241\363\363\337V\370\236m\261I\240xw", 27) = 27 
09:10:36 shutdown(3, 2 /* send and receive */) = 0 
09:10:36 close(3)                       = 0 
09:10:36 read(4294967295, 0xca3b350, 5) = -1 EBADF (Bad file descriptor) 
09:10:36 shutdown(4294967295, 2 /* send and receive */) = -1 EBADF (Bad file descriptor) 
09:10:36 close(4294967295)              = -1 EBADF (Bad file descriptor) 
09:10:36 sendto(4, "<14>Jun 25 09:10:36 screen: nss_"..., 90, MSG_NOSIGNAL, NULL, 0) = 90 
09:10:36 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0 
09:10:36 rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0 
09:10:36 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 
09:10:36 nanosleep({32, 0}, {32, 0})    = 0 
09:11:08 stat("/etc/ldap.conf", {st_mode=S_IFREG|0644, st_size=10681, ...}) = 0 
09:11:08 geteuid()                      = 287621 
09:11:08 open("/etc/hosts", O_RDONLY)   = 3 
09:11:08 fcntl(3, F_GETFD)              = 0 
09:11:08 fcntl(3, F_SETFD, FD_CLOEXEC)  = 0 
...
09:11:08 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0 
09:11:08 rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0 
09:11:08 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 
09:11:08 nanosleep({64, 0}, {64, 0})    = 0 
09:12:12 stat("/etc/ldap.conf", {st_mode=S_IFREG|0644, st_size=10681, ...}) = 0 
09:12:12 geteuid()                      = 287621 
09:12:12 open("/etc/hosts", O_RDONLY)   = 3 
09:12:12 fcntl(3, F_GETFD)              = 0 
  • 1
    Run it through strace and post the part around the delay (if there is a special one): strace -t -o screen.strace screen -ls – Hauke Laging Jun 25 '13 at 15:33
  • Is it only screen takes so long time or your server is highly loaded and any command runs a long time? – rush Jun 25 '13 at 15:36
  • @HaukeLaging - I get this error with the command you provided: "Directory '/var/run/screen' must have mode 777." – slm Jun 25 '13 at 15:54
  • @slm: then you should chmod 777 /var/run/screen. After all, it's no big deal to change permissions to something else than the rpm provides. :-) (with which I agree, by the way) – Bananguin Jun 25 '13 at 16:15
  • @slm But screen works for you, the error message does not appear without strace? Here ls -ld /var/run/screens/ /var/run/uscreens/ leads to 755 and 1777. – Hauke Laging Jun 25 '13 at 16:16
0

When we encountered this, our resident ops genius narrowed it down to a slow LDAP server. The short-term fix was to remove the offending LDAP server from the /etc/ldap.conf file.

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.