DomainKey-Signature: a=rsa-sha1; c=nofws; d=sourceware.org; h=list-id
	:list-unsubscribe:list-subscribe:list-archive:list-post
	:list-help:sender:from:reply-to:to:subject:date:message-id
	:content-type:content-transfer-encoding:mime-version; q=dns; s=
	default; b=vnC0uNxpIJMNcMpA5ZRn0UMceUJhHZDSY15ywaHV6dgns6q3u/Kd9
	Is3rvZlcIpyY+2eT7q1nux5WKj5OiHCW1PP3vbCqQYvBK+wFgWiHeUuI4qeqUUBv
	kGf5IYWyXI/KC+sWTESKluOe7yY5E+v01ZAa8jdoA/sBukwPPhbDIg=
Mailing-List: contact cygwin-help AT cygwin DOT com; run by ezmlm
Sender: cygwin-owner AT cygwin DOT com
Mail-Followup-To: cygwin AT cygwin DOT com
From: "Lavrentiev, Anton (NIH/NLM/NCBI) [C] via cygwin" <cygwin AT cygwin DOT com>
Reply-To: "Lavrentiev, Anton (NIH/NLM/NCBI) [C]" <lavr AT ncbi DOT nlm DOT nih DOT gov>
To: "'cygwin AT cygwin DOT com'" <cygwin AT cygwin DOT com>
Subject: Problem with cygserver (LookupAccountSid()) -- interlocking with its clients
Date: Wed, 13 Feb 2019 20:35:39 +0000
Message-ID: <BL0PR0901MB3236E13F2452747D5F659579A5660@BL0PR0901MB3236.namprd09.prod.outlook.com>
Content-Type: text/plain; charset="us-ascii"
MIME-Version: 1.0
Content-Transfer-Encoding: 8bit

Hi all,

We're having the following problem (on a subset(*) of Windows-10 machines) with running cygserver.

Started afresh, strace shows no activity in it, but should I execute a command (ipcs in the example below), then cygserver begins to experience freezes like these:

5295758 62716455 [unknown (0x2110)] cygserver 7248 pwdgrp::fetch_account_from_windows: LookupAccountSid(S-1-5-5-0-89379457), Win32 error 1332
6965292 69681747 [unknown (0x2110)] cygserver 7248 pwdgrp::fetch_account_from_windows: LookupAccountSid(S-1-5-5-0-89379457), Win32 error 1332
6507155 76188902 [unknown (0x2110)] cygserver 7248 pwdgrp::fetch_account_from_windows: LookupAccountSid(S-1-5-5-0-89379457), Win32 error 1332
4621322 80810224 [unknown (0x2110)] cygserver 7248 pwdgrp::fetch_account_from_windows: LookupAccountSid(S-1-5-5-0-89379457), Win32 error 1332
6610965 87421189 [unknown (0x2110)] cygserver 7248 pwdgrp::fetch_account_from_windows: LookupAccountSid(S-1-5-5-0-89379457), Win32 error 1332
38347515 125768704 [unknown (0x230C)] cygserver 7248 _cygtls::remove: wait 0
--- Process 8788 thread 8972 exited with status 0x0
 1427 125770131 [unknown (0x15F4)] cygserver 7248 _cygtls::remove: wait 0
--- Process 8788 thread 5620 exited with status 0x0
--- Process 8788 thread 8884 created
--- Process 8788 thread 7576 created
84443145 210213276 [unknown (0x2110)] cygserver 7248 pwdgrp::fetch_account_from_windows: LookupAccountSid(S-1-5-5-0-89379457), Win32 error 1332
2157582 212370858 [unknown (0x2110)] cygserver 7248 pwdgrp::fetch_account_from_windows: LookupAccountSid(S-1-5-5-0-89379457), Win32 error 1332
3439388 215810246 [unknown (0x1D98)] cygserver 7248 _cygtls::remove: wait 0

Look at the times, they are ginormous!  We also seem to have no idea what the shown SID is!  It looks very random, and changes when cygserver gets restarted.

On the side of a running ipcs, the above manifests as if the utility worked extremely slowly.  Strace shows the execution is synced with cygserver's delays, and is getting blocked while trying to communicate via the cygserver pipe to obtain the SYSV information, in particular:

  258 2010200 [main] ipcs 872 transport_layer_pipes::connect: Try to connect to named pipe: \\.\pipe\cygwin-dee7f533e22aad30-lpc
2671524 4681724 [main] ipcs 872 time: 1550088230 = time(0x0)
  168 4681892 [main] ipcs 872 stat64: entering
  118 4682010 [main] ipcs 872 normalize_posix_path: src /dev
  113 4682123 [main] ipcs 872 normalize_posix_path: /dev = normalize_posix_path (/dev)
   90 4682213 [main] ipcs 872 mount_info::conv_to_win32_path: conv_to_win32_path (/dev)
   86 4682299 [main] ipcs 872 set_flags: flags: binary (0x2)
   63 4682362 [main] ipcs 872 mount_info::conv_to_win32_path: src_path /dev, dst C:\Apps\Admin_Installs\lbsmd\dev, flags 0x3000A, rc 0
  313 4682675 [main] ipcs 872 symlink_info::check: 0x0 = NtCreateFile (\??\C:\Apps\Admin_Installs\lbsmd\dev)
  106 4682781 [main] ipcs 872 symlink_info::check: not a symlink
   63 4682844 [main] ipcs 872 symlink_info::check: 0 = symlink.check(C:\Apps\Admin_Installs\lbsmd\dev, 0xFFFFACF0) (0x43000A)
  103 4682947 [main] ipcs 872 build_fh_pc: fh 0x1802FB938, dev 000000C1
   65 4683012 [main] ipcs 872 stat_worker: (\??\C:\Apps\Admin_Installs\lbsmd\dev, 0x1802D5A80, 0x1802FB938), file_attributes 16
  235 4683247 [main] ipcs 872 transport_layer_pipes::connect: Try to connect to named pipe: \\.\pipe\cygwin-dee7f533e22aad30-lpc
  581 4683828 [main] ipcs 872 transport_layer_pipes::connect: Try to connect to named pipe: \\.\pipe\cygwin-dee7f533e22aad30-lpc
  577 4684405 [main] ipcs 872 transport_layer_pipes::connect: Try to connect to named pipe: \\.\pipe\cygwin-dee7f533e22aad30-lpc
  605 4685010 [main] ipcs 872 transport_layer_pipes::connect: Try to connect to named pipe: \\.\pipe\cygwin-dee7f533e22aad30-lpc
  461 4685471 [main] ipcs 872 fhandler_base::fstat_helper: 0 = fstat (\??\C:\Apps\Admin_Installs\lbsmd\dev, 0x1802D5A80) st_size=0, st_mode=040770, st_ino=562949953592746st_atim=5742E405.170E8CBC st_ctim=5A01F651.2A2E7320 st_mtim=5A00CCCE.0 st_birthtim=5742E405.170E8CBC
   99 4685570 [main] ipcs 872 stat_worker: 0 = (\??\C:\Apps\Admin_Installs\lbsmd\dev,0x1802D5A80)
  137 4685707 [main] ipcs 872 fstat64: 0 = fstat(1, 0xFFFFC020)
  117 4685824 [main] ipcs 872 isatty: 1 = isatty(1)
  205 4686029 [main] ipcs 872 fhandler_console::write: 0x600042F00, 16
  566 4686595 [main] ipcs 872 fhandler_console::write: 16 = fhandler_console::write(...)
   62 4686657 [main] ipcs 872 write: 16 = write(1, 0x600042F00, 16)
 1370 4688027 [main] ipcs 872 fhandler_console::write: 0x600042F00, 140
 1794 4689821 [main] ipcs 872 fhandler_console::write: 140 = fhandler_console::write(...)
   68 4689889 [main] ipcs 872 write: 140 = write(1, 0x600042F00, 140)
  405 4690294 [main] ipcs 872 fhandler_console::write: 0x600042F00, 1
  775 4691069 [main] ipcs 872 fhandler_console::write: 1 = fhandler_console::write(...)
   63 4691132 [main] ipcs 872 write: 1 = write(1, 0x600042F00, 1)
  229 4691361 [main] ipcs 872 shmctl: shmctl (shmid = 0, cmd = 4099, buf = 0x100408280)
   61 4691422 [main] ipcs 872 getpid: 872 = getpid()
  109 4691531 [main] ipcs 872 transport_layer_pipes::connect: Try to connect to named pipe: \\.\pipe\cygwin-dee7f533e22aad30-lpc
2417832 7109363 [main] ipcs 872 shmctl: shmctl (shmid = 192, cmd = 4099, buf = 0x600052F10)
  190 7109553 [main] ipcs 872 getpid: 872 = getpid()
  199 7109752 [main] ipcs 872 transport_layer_pipes::connect: Try to connect to named pipe: \\.\pipe\cygwin-dee7f533e22aad30-lpc
7253459 14363211 [main] ipcs 872 fhandler_console::write: 0x600042F00, 15
 1325 14364536 [main] ipcs 872 fhandler_console::write: 15 = fhandler_console::write(...)
  139 14364675 [main] ipcs 872 write: 15 = write(1, 0x600042F00, 15)
 1554 14366229 [main] ipcs 872 fhandler_console::write: 0x600042F00, 131
 1789 14368018 [main] ipcs 872 fhandler_console::write: 131 = fhandler_console::write(...)
   65 14368083 [main] ipcs 872 write: 131 = write(1, 0x600042F00, 131)
  408 14368491 [main] ipcs 872 fhandler_console::write: 0x600042F00, 1
  860 14369351 [main] ipcs 872 fhandler_console::write: 1 = fhandler_console::write(...)
   60 14369411 [main] ipcs 872 write: 1 = write(1, 0x600042F00, 1)
  230 14369641 [main] ipcs 872 semctl: semctl (semid = 0, semnum = 0, cmd = 4099, arg = 0x100408240)
   61 14369702 [main] ipcs 872 getpid: 872 = getpid()
  104 14369806 [main] ipcs 872 transport_layer_pipes::connect: Try to connect to named pipe: \\.\pipe\cygwin-dee7f533e22aad30-lpc
2421256 16791062 [main] ipcs 872 semctl: semctl (semid = 10, semnum = 0, cmd = 4099, arg = 0x600058920)
  170 16791232 [main] ipcs 872 getpid: 872 = getpid()
  141 16791373 [main] ipcs 872 transport_layer_pipes::connect: Try to connect to named pipe: \\.\pipe\cygwin-dee7f533e22aad30-lpc
5136742 21928115 [main] ipcs 872 fhandler_console::write: 0x600042F00, 12
 1327 21929442 [main] ipcs 872 fhandler_console::write: 12 = fhandler_console::write(...)
  154 21929596 [main] ipcs 872 write: 12 = write(1, 0x600042F00, 12)
 1352 21930948 [main] ipcs 872 fhandler_console::write: 0x600042F00, 102
 1224 21932172 [main] ipcs 872 fhandler_console::write: 102 = fhandler_console::write(...)
  113 21932285 [main] ipcs 872 write: 102 = write(1, 0x600042F00, 102)
  422 21932707 [main] ipcs 872 fhandler_console::write: 0x600042F00, 1
  794 21933501 [main] ipcs 872 fhandler_console::write: 1 = fhandler_console::write(...)

Interesting that the SID retrieval activity in cygserver does not seem to stop entirely when its only client, ipcs, exits.

Any insights will be highly appreciated.

Thanks,
Anton Lavrentiev

(*)  All Windows-10 machines (~300) that we have here seem to have cygserver's pulling some random SIDs and failing with the same error, 1332.  But that usually happens pretty quickly (yet still, noticeable).  Only on a subset of hosts (less than 5%), we see these extremely long delays, causing the apps failures due to timeouts.


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