Skip to content

Fix long messages to stdout/stderr getting truncated #1076

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
wants to merge 1 commit into from
Closed

Fix long messages to stdout/stderr getting truncated #1076

Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
14 changes: 10 additions & 4 deletions sapi/fpm/fpm/fpm_stdio.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -119,6 +119,8 @@ static void fpm_stdio_child_said(struct fpm_event_s *ev, short which, void *arg)
int is_last_message = 0;
int in_buf = 0;
int res;
char fmt_buf[max_buf_size];
int fmt_len = 0;

if (!arg) {
return;
Expand All @@ -130,10 +132,15 @@ static void fpm_stdio_child_said(struct fpm_event_s *ev, short which, void *arg)
} else {
event = &child->ev_stderr;
}

/* calculate how long the "child 123 said into ..." prefix is so we can subtract its length from max_buf_size */
fmt_len = snprintf(fmt_buf, max_buf_size, "[pool %s] child %d said into %s: \"%%s\"%%s", child->wp->config->name, (int) child->pid, is_stdout ? "stdout" : "stderr");
/* subtract two characters each for the two "%s", then add character counts for "WARNING: " added by zlog and "[11-Feb-2015 15:58:20] " added by zlog; we're ignoring the potential extra length in log_level=DEBUG */
fmt_len = fmt_len - 2 - 2 + 9 + 23;
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Seems definitively uggly and not robust...
Need a better solution

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Please, use sizeof() or strlen() for litterals , it is more understandable than a comment

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

About robustness, if sometime in the future we change the prefix format in the child part, we will have to update the parent side...

Need to find a robust solution to know a length of this prefix.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What's your suggestion then, @remicollet? I poked around for a while but there was no obvious simple way. We could reduce FPM_LOG_BUFFER; alternatively, the "child said into" stuff could be printed on its own line before the actual message. Or parse the line using sscanf()?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I should note that the "WARNING: " and date/time prefixes (for which the lengths are calculated) are not from the child message, @remicollet. They are added by the zlog call.

Another alternative would be to completely remove the line wrapping logic here (and maybe elsewhere, haven't looked), remove the length terminator logic ("..." and cut-off) from zlog, and wrap longer lines entirely in zlog instead. Would that be better? /cc @jpauli @Tyrael

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

yeah I know, I'm just mentioning that picking the 1024 limit can be deliberate and we should be careful if we wan't to remove that. how would your proposed solution for allowing error messages longer than 1024 bytes work when error_log is set to "syslog" for fpm?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Well this issue right now is only in fpm_stdio_child_said, which calls zlog, and that's responsible for either writing to syslog, or to a file. Right now, zlog cuts off any long messages using "...", but it could just as well split at 1024 characters and write those chunks separately, no?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

So, what do we do?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@Tyrael just reading this again and realised that it doesn't really makes much sense today as 1024 (that is specified in RFC3164) limit was obsoleted by RFC5424 where there is no such limit. So this reason should no longer be valid.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Actually old syslogd and things like papertrail still has got that limit but rsyslog for example can handle that. Anyway I don't think we should have such strict limitation.


while (fifo_in || fifo_out) {
if (fifo_in) {
res = read(fd, buf + in_buf, max_buf_size - 1 - in_buf);
res = read(fd, buf + in_buf, max_buf_size - fmt_len - 1 - in_buf);
if (res <= 0) { /* no data */
fifo_in = 0;
if (res < 0 && (errno == EAGAIN || errno == EWOULDBLOCK)) {
Expand Down Expand Up @@ -171,7 +178,7 @@ static void fpm_stdio_child_said(struct fpm_event_s *ev, short which, void *arg)
/* FIXME: there might be binary data */

/* we should print if no more space in the buffer */
if (in_buf == max_buf_size - 1) {
if (in_buf == max_buf_size - fmt_len - 1) {
should_print = 1;
}

Expand All @@ -187,8 +194,7 @@ static void fpm_stdio_child_said(struct fpm_event_s *ev, short which, void *arg)
*nl = '\0';
}

zlog(ZLOG_WARNING, "[pool %s] child %d said into %s: \"%s\"%s", child->wp->config->name,
(int) child->pid, is_stdout ? "stdout" : "stderr", buf, is_last_message ? ", pipe is closed" : "");
zlog(ZLOG_WARNING, fmt_buf, buf, is_last_message ? ", pipe is closed" : "");

if (nl) {
int out_buf = 1 + nl - buf;
Expand Down