Bug 194751 - [PATCH] Calls to syslog() drop the first message sent after syslogd is restarted
Summary: [PATCH] Calls to syslog() drop the first message sent after syslogd is restarted
Status: Closed FIXED
Alias: None
Product: Base System
Classification: Unclassified
Component: bin (show other bugs)
Version: CURRENT
Hardware: Any Any
: --- Affects Many People
Assignee: Xin LI
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2014-11-02 02:01 UTC by pjcreath+freebsd
Modified: 2014-12-09 00:47 UTC (History)
1 user (show)

See Also:


Attachments
proposed patch (1.75 KB, patch)
2014-11-02 02:01 UTC, pjcreath+freebsd
no flags Details | Diff
test case (456 bytes, text/x-python-script)
2014-11-02 02:03 UTC, pjcreath+freebsd
no flags Details

Note You need to log in before you can comment on or make changes to this bug.
Description pjcreath+freebsd 2014-11-02 02:01:56 UTC
Created attachment 148911 [details]
proposed patch

Issue:  Calls to syslog() drop the first message sent after syslogd is restarted.


Effect:  Generally this results in only a single missing message, which is easily overlooked.  However, some server daemons (such as afpd) are quiet until they spawn their children, and the first message of each child is dropped, since they inherit their parent's (broken) connection state.  In the case of afpd, this means that all "Login by" messages are dropped after syslogd is restarted.

This bug affects 9.1-RELEASE and all newer versions, up through at least 10.1-RC4.


Cause:

The following commit was in error and broke r14332:

<http://svnweb.FreeBSD.org/base?view=revision&revision=228193>:
'Tweak the r137233 fix to r136283 -- Code was making two send() attempts
vs. the comment documented "If we are working with a privileged socket,
then take only one attempt".  Make the code match.'

Unfortunately, the code was more correct than the rather ambiguous comment.  The comment raises two cases:  #1 in which syslogd has been restarted, and #2 in which the socket buffers are full (a possible DoS).

To fully cover the case #1, we *need* to resend the message (just once) after reconnection.

Furthermore, looking at the precursor to <http://svnweb.FreeBSD.org/base?view=revision&revision=136283>, we see the original intent of resending once ("one attempt") to address this case.


Turning toward the second half of the rationale for r228193:

'Furthermore, critical privileged applications that [over] log a vast amount
can look like a DoS to this code.  Given it's unlikely the single reattempted
send() will succeeded, avoid usurping the scheduler in a library API for a
single non-critical facility in critical applications.'

The confidence that the single reattempted send() is "unlikely" to succeed is misplaced.  In the case where syslogd has been restarted, it will reliably succeed.  However, as previously coded, the single resend was also being attempted when the buffer was full, which is indeed unlikely to succeed.

Therefore, the proposed patch tries to reconnect and resend once if the failure was not due to a full buffer, without involving the scheduler.  It also corrects and clarifies the comment.  (An alternate approach would be to refactor the code and comments to treat the two cases entirely separately, but this patch aims for the fewest necessary code changes.)

This patch should be applicable to all affected releases (9.1-RELEASE and newer).
Comment 1 pjcreath+freebsd 2014-11-02 02:03:16 UTC
Created attachment 148912 [details]
test case
Comment 2 pjcreath+freebsd 2014-11-09 20:27:18 UTC
I just realized the patch didn't include the full path of syslog.c:


lib/libc/gen/syslog.c
Comment 3 Xin LI freebsd_committer freebsd_triage 2014-11-25 20:31:02 UTC
CR submitted as https://reviews.freebsd.org/D1227
Comment 4 commit-hook freebsd_committer freebsd_triage 2014-11-25 21:00:22 UTC
A commit references this bug:

Author: delphij
Date: Tue Nov 25 20:59:23 UTC 2014
New revision: 275071
URL: https://svnweb.freebsd.org/changeset/base/275071

Log:
  Reinstitate send() after syslogd restarts.

  In r228193 the test of CONNPRIV have been moved to before the _usleep
  and send in vsyslog().  When syslogd restarts, this would prevent the
  message being logged after the disconnect/connect dance for
  scenario #1.

  PR:		194751
  Submitted by:	Peter Creath <pjcreath+freebsd gmail com>
  Reviewed By:	glebius
  MFC after:	2 weeks
  Differential Revision: https://reviews.freebsd.org/D1227

Changes:
  head/lib/libc/gen/syslog.c
Comment 5 Xin LI freebsd_committer freebsd_triage 2014-11-25 21:01:19 UTC
Committed (with some minor style changes), thanks!
Comment 6 commit-hook freebsd_committer freebsd_triage 2014-12-09 00:47:58 UTC
A commit references this bug:

Author: delphij
Date: Tue Dec  9 00:47:03 UTC 2014
New revision: 275626
URL: https://svnweb.freebsd.org/changeset/base/275626

Log:
  MFC r275071:

  Reinstitate send() after syslogd restarts.

  In r228193 the test of CONNPRIV have been moved to before the _usleep
  and send in vsyslog().  When syslogd restarts, this would prevent the
  message being logged after the disconnect/connect dance for
  scenario #1.

  PR:		194751
  Submitted by:	Peter Creath <pjcreath+freebsd gmail com>
  Reviewed By:	glebius

Changes:
_U  stable/10/
  stable/10/lib/libc/gen/syslog.c
Comment 7 commit-hook freebsd_committer freebsd_triage 2014-12-09 00:47:59 UTC
A commit references this bug:

Author: delphij
Date: Tue Dec  9 00:47:47 UTC 2014
New revision: 275627
URL: https://svnweb.freebsd.org/changeset/base/275627

Log:
  MFC r275071:

  Reinstitate send() after syslogd restarts.

  In r228193 the test of CONNPRIV have been moved to before the _usleep
  and send in vsyslog().  When syslogd restarts, this would prevent the
  message being logged after the disconnect/connect dance for
  scenario #1.

  PR:		194751
  Submitted by:	Peter Creath <pjcreath+freebsd gmail com>
  Reviewed By:	glebius

Changes:
_U  stable/9/lib/libc/
  stable/9/lib/libc/gen/syslog.c