Re: XWin.exe: _XSERVTransSocketUNIXAccept: accept() failed

[Jon TURNEY <jon dot turney at dronecode dot org dot uk>]

On 17/02/2012 18:56, Jon TURNEY wrote:
> On 15/02/2012 16:39, Bonggren, Jeffrey L wrote:
>> I have recently noticed that XWin.exe is spinning and maxing out a CPU
>> core.  I checked the log and saw that it is spamming it with
>> "_XSERVTransSocketUNIXAccept: accept() failed" messages at a rate of about
>> one per millisecond.  This is generating a very large log file!
> 
> Thanks for reporting this.
> 
> This  seems to be related in some way to how you start the X server.  Starting
> it using startxwin.exe (the recommended method), I don't observe this problem,
> but using your startxwin.bat, I can reproduce the problem.
> 
> The obvious difference here between these two cases is that we don't have a
> cygwin process as our immediate ancestor when started from a batch file, but
> how that could make a difference is a bit mysterious.
> 
> This seems to be some sort of regression introduced with the cygwin 1.7.10
> DLL, downgrading to 1.7.9 doesn't show the problem (although that is
> problematic as base-files now depends on tzset introduced in 1.7.10)

stracing this is enlightening...

 281 23126144 [main] XWin 3084 cygwin_select: select(255, 0x5FDE80, 0x0, 0x0,
0x22CBB4)
   35 23126179 [main] XWin 3084 dtable::select_read:  fd 0
   32 23126211 [main] XWin 3084 dtable::select_read:  fd 1
  171 23126382 [main] XWin 3084 dtable::select_read: /usr/adm/X0msgs fd 2
   33 23126415 [main] XWin 3084 dtable::select_read: /dev/windows fd 5
   32 23126447 [main] XWin 3084 dtable::select_read:  fd 7
  170 23126617 [main] XWin 3084 dtable::select_read:  fd 9
   32 23126649 [main] XWin 3084 dtable::select_read:  fd 10
   31 23126680 [main] XWin 3084 dtable::select_read:  fd 12
  166 23126846 [main] XWin 3084 cygwin_select: to->tv_sec 560, to->tv_usec
203000, ms 560203
   21 23126867 [main] XWin 3084 cygwin_select: sel.always_ready 1
   25 23126892 [main] XWin 3084 peek_socket: read_ready: 0, write_ready: 0,
except_ready: 0
   21 23126913 [main] XWin 3084 peek_socket: read_ready: 0, write_ready: 0,
except_ready: 0
  211 23127124 [main] XWin 3084 peek_socket: read_ready: 0, write_ready: 0,
except_ready: 0
   25 23127149 [main] XWin 3084 peek_socket: read_ready: 0, write_ready: 0,
except_ready: 0
   18 23127167 [main] XWin 3084 peek_windows: window 5(0x0) not ready
   17 23127184 [main] XWin 3084 set_bits: me 0x20511260, testing fd 2
(/usr/adm/X0msgs)
  206 23127390 [main] XWin 3084 set_bits: ready 1
   25 23127415 [main] XWin 3084 peek_socket: read_ready: 0, write_ready: 0,
except_ready: 0
   22 23127437 [main] XWin 3084 peek_socket: read_ready: 0, write_ready: 0,
except_ready: 0
   17 23127454 [main] XWin 3084 cygwin_select: 1 = select(255, 0x5FDE80,
0x22CA10, 0x22C9E0, 0x22CBB4)
  208 23127662 [main] XWin 3084 select_stuff::cleanup: calling cleanup routines
   20 23127682 [main] XWin 3084 socket_cleanup: si 0x0 si->thread 0x0
   17 23127699 [main] XWin 3084 socket_cleanup: si 0x0 si->thread 0x0
   23 23127722 [main] XWin 3084 socket_cleanup: si 0x0 si->thread 0x0
   17 23127739 [main] XWin 3084 socket_cleanup: si 0x0 si->thread 0x0
   17 23127756 [main] XWin 3084 socket_cleanup: si 0x0 si->thread 0x0
  278 23128034 [main] XWin 3084 socket_cleanup: si 0x0 si->thread 0x0
   22 23128056 [main] XWin 3084 select_stuff::destroy: deleting select records
  279 23128335 [main] XWin 3084 __set_errno: fhandler_socket* get(int):83
setting errno 108
   20 23128355 [main] XWin 3084 cygwin_accept: -1 = accept(2, 0x22C92E,
0x22C99C), errno 108
   92 23128447 [main] XWin 3084 write: write(3, 0x5F93A0, 13)
  161 23128608 [main] XWin 3084 write: 13 = write(3, 0x5F93A0, 13)
  236 23128844 [main] XWin 3084 write: write(3, 0x5F93A0, 11)
   20 23128864 [main] XWin 3084 write: 11 = write(3, 0x5F93A0, 11)
  964 23129828 [main] XWin 3084 write: 45 = write(2, 0x5FA880, 45)
  191 23130019 [main] XWin 3084 write: write(3, 0x5F93A0, 34)
   21 23130040 [main] XWin 3084 write: 34 = write(3, 0x5F93A0, 34)

When started from a Windows parent process, stdin/stdout/stderr are closed, so
the X server opens /usr/adm/X0msgs to write stderr output to.

However, due to a bug in the X server, when doing that we can trample all over
a socket listening on a well-known port, which has already been opened with fd
2.  If that file fd ever shows as ready for reading, we will try to accept a
connection on it, which is always going to fail :-)

This can easily be reproduced using 'X 2>&-', which shows the same spinning
behaviour.

(In OsInit(), we check if fd 2 is writeable, and if not, assume stderr has
been closed, and open /usr/adm/X0msgs for writing, and dup it on to fd 2.
Unfortunately, this happens after CreateWellknownSockets() has opened the
listener sockets, and that may use fd 2)

This bug has been there a long time, I'm not sure why it's problem now,
perhaps the cygwin DLL has changed behaviour so this fd is now always found
ready to read?

I've applied fix to address this, so hopefully this works better now. I've
uploaded a snapshot at [1]. Perhaps you could try that out and see if that
makes a difference?

[1] ftp://cygwin.com/pub/cygwinx/XWin.20120218-git-c3b936a38812f88b.exe.bz2

-- 
Jon TURNEY
Volunteer Cygwin/X X Server maintainer

--
Unsubscribe info:      http://cygwin.com/ml/#unsubscribe-simple
Problem reports:       http://cygwin.com/problems.html
Documentation:         http://x.cygwin.com/docs/
FAQ:                   http://x.cygwin.com/docs/faq/