Re: syslog function: Bad file descriptor
On Aug 5 22:35, D. Boland wrote: Corinna Vinschen wrote: Can you produce another strace for the overwriting case (non-R/O aliases) for comparison? Also, can you do the same strace with no syslogd running? It might be necessary to create a few test versions of Cygwin with more debug output, but let's please see these straces first. I attached all three of them in a zipped file. Thanks. I got it now. AFAICS it's a bug in sendmail. Take a look into your newaliases.strace.txt file. Start at line 260 (stripping off timestamp, thread and process info): 260: normalize_posix_path: src /dev/log Here the syslog() function tries to open a connection to a syslogd listening on /dev/log. 282: cygwin_socket: 3 = socket(1, 2 (flags 0x0), 0) Socket created, file descriptor is 3. 296: connect_syslogd: found /dev/log, fd = 3, type = DGRAM Yes, there's a listener on /dev/log. Now Cygwin stores the info that fd 3 is the connection to the syslog daemon. 332: close: close(3) And at line 332, a file descriptor close orgy starts. sendmail closes all descriptors from 3 to 255. This obviously closes fd 3, but how's Cygwin's syslog() function to know? 2263: open: 3 = open(/etc/mail/aliases, 0x8000) Uh oh! Now fd 3 is reused for the aliases file. Things certainly go downhill. 2651: writev: -1 = writev(3, 0x2287F0, 2), errno 9 This is syslog trying to write the log to the descriptor it knows is connected to /dev/log. Fortunately the aliases file is R/O at this point, but it's pretty much working as designed. Syslog() doesn't know the application broke its connection to the syslog daemon. It dutyfully writes to the syslog descriptor it knows about. As for using a file descriptor inside of syslog, that's perfectly valid behaviour, see http://pubs.opengroup.org/onlinepubs/9699919799/functions/closelog.html: The openlog() and syslog() functions may allocate a file descriptor. Without looking into the sources, I'd assume there's a closelog() call missing prior to the descriptor close orgy. This closelog() call should fix the problem. HTH, Corinna -- Corinna Vinschen Please, send mails regarding Cygwin to Cygwin Maintainer cygwin AT cygwin DOT com Red Hat pgpr_iphwGZWw.pgp Description: PGP signature
Re: syslog function: Bad file descriptor
Hi Corinna, Corinna Vinschen wrote: On Aug 5 22:35, D. Boland wrote: Corinna Vinschen wrote: Can you produce another strace for the overwriting case (non-R/O aliases) for comparison? Also, can you do the same strace with no syslogd running? It might be necessary to create a few test versions of Cygwin with more debug output, but let's please see these straces first. I attached all three of them in a zipped file. Thanks. I got it now. AFAICS it's a bug in sendmail. Take a look into your newaliases.strace.txt file. Start at line 260 (stripping off timestamp, thread and process info): 260: normalize_posix_path: src /dev/log Here the syslog() function tries to open a connection to a syslogd listening on /dev/log. 282: cygwin_socket: 3 = socket(1, 2 (flags 0x0), 0) Socket created, file descriptor is 3. 296: connect_syslogd: found /dev/log, fd = 3, type = DGRAM Yes, there's a listener on /dev/log. Now Cygwin stores the info that fd 3 is the connection to the syslog daemon. 332: close: close(3) And at line 332, a file descriptor close orgy starts. sendmail closes all descriptors from 3 to 255. This obviously closes fd 3, but how's Cygwin's syslog() function to know? 2263: open: 3 = open(/etc/mail/aliases, 0x8000) Uh oh! Now fd 3 is reused for the aliases file. Things certainly go downhill. 2651: writev: -1 = writev(3, 0x2287F0, 2), errno 9 This is syslog trying to write the log to the descriptor it knows is connected to /dev/log. Fortunately the aliases file is R/O at this point, but it's pretty much working as designed. Syslog() doesn't know the application broke its connection to the syslog daemon. It dutyfully writes to the syslog descriptor it knows about. As for using a file descriptor inside of syslog, that's perfectly valid behaviour, see http://pubs.opengroup.org/onlinepubs/9699919799/functions/closelog.html: The openlog() and syslog() functions may allocate a file descriptor. Without looking into the sources, I'd assume there's a closelog() call missing prior to the descriptor close orgy. This closelog() call should fix the problem. It is exactly as you say. I found the close() orgy and put a closelog() prior to it. Now it works perfectly without corrupting the aliases file (writable to sendmail). I'm asking myself if this closing of 253 file descriptors is a sensible thing to do. What would Sendmail be trying to accomplish there? It comments Be shure we have enough file descriptors. And: in 4.4BSD, the table ([of fd's]) can be huge; impose a reasonable limit. Bizarre. Could it be that incoming e-mail is such a volatile process that previous opened file descriptors are not closed quick enough? This feels like a crude hack. Can you give your opinion on this? Thanks for the quick response the time you put into this. Daniel -- 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
Re: syslog function: Bad file descriptor
On Aug 6 13:30, D. Boland wrote: Hi Corinna, Corinna Vinschen wrote: On Aug 5 22:35, D. Boland wrote: Corinna Vinschen wrote: Can you produce another strace for the overwriting case (non-R/O aliases) for comparison? Also, can you do the same strace with no syslogd running? It might be necessary to create a few test versions of Cygwin with more debug output, but let's please see these straces first. I attached all three of them in a zipped file. Thanks. I got it now. AFAICS it's a bug in sendmail. Take a look into your newaliases.strace.txt file. Start at line 260 (stripping off timestamp, thread and process info): [...] Without looking into the sources, I'd assume there's a closelog() call missing prior to the descriptor close orgy. This closelog() call should fix the problem. It is exactly as you say. I found the close() orgy and put a closelog() prior to it. Now it works perfectly without corrupting the aliases file (writable to sendmail). Nice. I'm asking myself if this closing of 253 file descriptors is a sensible thing to do. What would Sendmail be trying to accomplish there? It comments Be shure we have enough file descriptors. And: in 4.4BSD, the table ([of fd's]) can be huge; impose a reasonable limit. Bizarre. I think this is really old stuff, in the sense that this method has been used on UNIXoid systems for ages. It depends on how many open fds sendmail inherited from its parent process (once typically an rc shell script) which was questionable back in the days sendmail was young I guess, and if sendmail forks/execs, it's a way to disallow arbitrary fds inheritance by the child. Could it be that incoming e-mail is such a volatile process that previous opened file descriptors are not closed quick enough? This feels like a crude hack. Sendmail is not the only one doing this. There's similar code in tcsh, for instance, but tcsh doesn't call syslog. The bug here seems to be an upstream bug which just hasn't been catched yet because syslog() works somewhat differently on other systems and hide their file descriptor usage somehow. Corinna -- Corinna Vinschen Please, send mails regarding Cygwin to Cygwin Maintainer cygwin AT cygwin DOT com Red Hat pgpWPeTUzHpjY.pgp Description: PGP signature
Re: syslog function: Bad file descriptor
On 08/06/2014 05:30 AM, D. Boland wrote: Without looking into the sources, I'd assume there's a closelog() call missing prior to the descriptor close orgy. This closelog() call should fix the problem. It is exactly as you say. I found the close() orgy and put a closelog() prior to it. Now it works perfectly without corrupting the aliases file (writable to sendmail). I'm asking myself if this closing of 253 file descriptors is a sensible thing to do. Maybe. There's two schools of thoughts about preventing unintended actions due to accidentally leaked fds: 1. any time a parent forks an unknown child, the parent does an orgy close() between fork() and exec() so that the child starts life clean. 2. any time a child starts from an unknown parent, the child starts with an orgy close() to ensure it starts life clean. [More recently, there is the addition of O_CLOEXEC to open() and other APIs to allow atomic FD_CLOEXEC setting, and then you can avoid the orgy close() in style 1; but that still doesn't stop style 2 paranoid children] What would Sendmail be trying to accomplish there? It comments Be shure we have enough file descriptors. And: in 4.4BSD, the table ([of fd's]) can be huge; impose a reasonable limit. Bizarre. Other programs that I know do an orgy close() on startup: bash, tcsh. So it's not uncommon. But if you do it first, it MUST be first - before you open any fds that must not be accidentally closed. sendmail is indeed buggy for trying to use syslog() (which uses an fd) prior to doing the orgy close. Could it be that incoming e-mail is such a volatile process that previous opened file descriptors are not closed quick enough? This feels like a crude hack. Just because the problem hasn't tripped other platforms does not make it any less of an upstream sendmail bug. -- Eric Blake eblake redhat com+1-919-301-3266 Libvirt virtualization library http://libvirt.org signature.asc Description: OpenPGP digital signature
Re: syslog function: Bad file descriptor
On 08/05/2014 12:28 PM, D. Boland wrote: Hi group, I'm still working on getting Sendmail working for Cygwin. I'm almost done, the devil is in the details... I'm getting the 'Bad file descriptor' system error after building the mail aliases database. The building itself is done successful, but logging the event to the system log fails with this message. Did you mention whether you've installed and configured some syslog service? -- Larry _ A: Yes. Q: Are you sure? A: Because it reverses the logical flow of conversation. Q: Why is top posting annoying in email? -- 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
Re: syslog function: Bad file descriptor
Hi Daniel, On Aug 5 18:28, D. Boland wrote: Hi group, I'm still working on getting Sendmail working for Cygwin. I'm almost done, the devil is in the details... I'm getting the 'Bad file descriptor' system error after building the mail aliases database. The building itself is done successful, but logging the event to the system log fails with this message. Somehow the two are connected. The alias database (aliases.db) is built from a plain text file (aliases). If I leave the aliases file writable to the sendmail user, I find that the error message strings have been put right into the alias text-file: $ cat /etc/mail/aliases 21sendmail: PID 1848: alias database /etc/mail/aliases rebuilt by smmspsenet: root news: root webmaster: root www: root ftp: root abuse: root noc: root security: root root: SYSTEM 22sendmail: PID 1848: /etc/mail/aliases: 9 aliases, longest 6 bytes, 82 bytes total If I make the 'aliases' file read-only, then the file is not corrupted, but the error occurs. I don't see that this has to do with syslog. There's a writev to fd 3, but you stripped the strace so we don't know what fd 3 is connected to. Also, syslog writes the output to the Windows event log by default, unless you have a syslog daemon running, connected to /dev/log. So I guess we first have to know what fd 3 is connected to, and then how to reproduce the issue. Corinna pgpjT1_gv4nU8.pgp Description: PGP signature
Re: syslog function: Bad file descriptor
On Aug 5 12:45, Larry Hall (Cygwin) wrote: On 08/05/2014 12:28 PM, D. Boland wrote: Hi group, I'm still working on getting Sendmail working for Cygwin. I'm almost done, the devil is in the details... I'm getting the 'Bad file descriptor' system error after building the mail aliases database. The building itself is done successful, but logging the event to the system log fails with this message. Did you mention whether you've installed and configured some syslog service? Indeed, that's not visible from the strace, The syslog function won't create any further debug output unless it fails to register with the Windows Event Log. Corinna -- Corinna Vinschen Please, send mails regarding Cygwin to Cygwin Maintainer cygwin AT cygwin DOT com Red Hat pgpADJz0Y0MT1.pgp Description: PGP signature
Re: syslog function: Bad file descriptor
Larry Hall (Cygwin) wrote: On 08/05/2014 12:28 PM, D. Boland wrote: Hi group, I'm still working on getting Sendmail working for Cygwin. I'm almost done, the devil is in the details... I'm getting the 'Bad file descriptor' system error after building the mail aliases database. The building itself is done successful, but logging the event to the system log fails with this message. Did you mention whether you've installed and configured some syslog service? I have syslogd running from the 'inetutils-server' package. D. -- 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
Re: syslog function: Bad file descriptor
On Aug 5 19:43, D. Boland wrote: Corinna Vinschen wrote: Somehow the two are connected. The alias database (aliases.db) is built from a plain text file (aliases). If I leave the aliases file writable to the sendmail user, I find that the error message strings have been put right into the alias text-file: $ cat /etc/mail/aliases 21sendmail: PID 1848: alias database /etc/mail/aliases rebuilt by smmspsenet: root news: root webmaster: root www: root ftp: root abuse: root noc: root security: root root: SYSTEM 22sendmail: PID 1848: /etc/mail/aliases: 9 aliases, longest 6 bytes, 82 bytes total If I make the 'aliases' file read-only, then the file is not corrupted, but the error occurs. I don't see that this has to do with syslog. There's a writev to fd 3, but you stripped the strace so we don't know what fd 3 is connected to. Also, syslog writes the output to the Windows event log by default, unless you have a syslog daemon running, connected to /dev/log. So I guess we first have to know what fd 3 is connected to, and then how to reproduce the issue. I have the syslogd (inetutils-server package) running as a Windows Service, using cygrunsrv. I attached the complete strace output. The 'syslog' function works fine while running as the cyg_server user, but after a setuid/setgid to the Sendmail 'smmsp' user, it fails. The output is quite large. I put in printf(syslog: %s\n) calls to mark the spots where it happens. Can you produce another strace for the overwriting case (non-R/O aliases) for comparison? Also, can you do the same strace with no syslogd running? It might be necessary to create a few test versions of Cygwin with more debug output, but let's please see these straces first. Thanks, Corinna pgpVge_fCLOja.pgp Description: PGP signature
Re: syslog function: Bad file descriptor
Corinna Vinschen wrote: Can you produce another strace for the overwriting case (non-R/O aliases) for comparison? Also, can you do the same strace with no syslogd running? It might be necessary to create a few test versions of Cygwin with more debug output, but let's please see these straces first. I attached all three of them in a zipped file. By the way: my previous strace outputs where from an older version of cygwin1.dll. I put a recent one in and did the attached traces: CYGWIN_NT-5.1 dimension 1.7.31s(0.272/5/3) 20140716 11:15:29 i686 Cygwin Daniel sendmail-test.tar.gz Description: GNU Zip compressed data -- 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
