-
Notifications
You must be signed in to change notification settings - Fork 7.8k
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.
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
Fix long messages to stdout/stderr getting truncated #1076
Conversation
Bug report: https://bugs.php.net/bug.php?id=69031 |
Expected result, lines wrapped correctly without loss of information:
Actual result, content wrapped to lines of 1023 characters and then truncated each, leading to loss of information:
|
Is that 5.6 related or does it affect 5.5 also ? If so, the PR should be done against 5.5 |
Both 5.5 and 5.6, @jpauli. Should I really open a new one, or can you merge it to the other branch? |
The maximum zlog message length is 1024 including timestamp et cetera. With very long messages over 1024 characters, these get wrapped into multiple chunks correctly, but then the "WARNING: child blah said into blah" gets added and the zlog call truncates the messages using "..." at the end, resulting in a couple dozen bytes getting lost. This change calculates the length at which wrapping needs to occur correctly.
73d2660
to
9aa72b8
Compare
Hello, any updates on this PR ? |
if @remicollet doesn't have anything against the change I'm fine with merging it into PHP-5.6 |
Do it! :) (and to 7+ as well of course). |
@remicollet shouldn't be available for about a week atm. |
Ping @remicollet ;) |
Another bump :) |
/* 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; |
There was a problem hiding this comment.
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
There was a problem hiding this comment.
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
There was a problem hiding this comment.
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.
There was a problem hiding this comment.
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()
?
There was a problem hiding this comment.
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
There was a problem hiding this comment.
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?
There was a problem hiding this comment.
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?
There was a problem hiding this comment.
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?
There was a problem hiding this comment.
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.
There was a problem hiding this comment.
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.
Is it possible to make it configurable like log-errors-max-len, so that no output is truncated or split to multiple lines? I use PHP-FPM in a Docker container (PHP 7.0) and want to log JSON formatted messages to stderr, so Docker can collect the logs. I need an "unlimited" log message size length. By the way, logging to stderr should have the same behaviour as log to a file. In a PHP CLI environment it works perfectly, so why is it in PHP-FPM truncated or split to multiple lines? Are the any solutions for this? |
Hi @remicollet @jpauli, I wonder what's the main motivation for not having this "1024" value to be configurable and instead hardcoded there? I'm in the same situation as @sandrokeil, php-fpm in docker, and unfortunately, lines longer than 1024 are being truncated/chunked. cc: @dzuelke |
Poke @remicollet @Tyrael @jpauli :) |
Another poke for @remicollet and @Tyrael and @jpauli :) Let me know what you think regarding the best fix and I can work on it. |
Would be awesome if this can be fixed soon, so I can log long json formatted messages. |
Can a 5 series RM please take a fresh look at this. /cc @jpauli @smalyshev @Tyrael I am reluctant to merge down that far. |
This commit jpauli@9043ec5 removes truncation in every FPM message. No more (...) and no more bytes lost. Please note however, that any line from fpm_stdio_child_said() above 1024 will be splitted up into as many messages as needed (prefixed with the date etc...). |
Splitting across lines is fine. I vote ship it and close this ;) |
Waiting for other advices. @dzuelke , @remicollet ... |
But wait... now splitting happens twice, right? I have to build with that commit later and test, but @jpauli, could you test this please (might be good as a file_put_contents("php://stderr", "If it were done when 'tis done, then 'twere well // It were done quickly. If the assassination // Could trammel up the consequence, and catch, // With his surcease, success; that but this blow // Might be the be-all and the end-all--here, // But here, upon this bank and shoal of time,-- // We'd jump the life to come. But in these cases // We still have judgement here; that we but teach // Bloody instructions, which being taught, return // To plague the inventor: this even-handed justice // Commends the ingredients of our poison'd chalice // To our own lips. He's here in double trust: // First, as I am his kinsman and his subject, // Strong both against the deed: then, as his host, // Who should against his murderer shut the door, // Not bear the knife myself. Besides, this Duncan // Hath borne his faculties so meek, hath been // So clear in his great office, that his virtues // Will plead like angels, trumpet-tongued, against // The deep damnation of his taking-off: // And pity, like a naked new-born babe, // Striding the blast, or heaven's cherubin, hors'd // Upon the sightless couriers of the air, // Shall blow the horrid deed in every eye, // That tears shall drown the wind.--I have no spur // To prick the sides of my intent, but only // Vaulting ambition, which o'erleaps itself, // And falls on the other. // Is this a dagger which I see before me, // The handle toward my hand? Come, let me clutch thee:-- // I have thee not, and yet I see thee still. // Art thou not, fatal vision, sensible // To feeling as to sight? or art thou but // A dagger of the mind, a false creation, // Proceeding from the heat-oppressed brain? // I see thee yet, in form as palpable // As this which now I draw. // Thou marshall'st me the way that I was going; // And such an instrument I was to use. // Mine eyes are made the fools o' the other senses, // Or else worth all the rest: I see thee still; // And on thy blade and dudgeon gouts of blood, // Which was not so before.--There's no such thing: // It is the bloody business which informs // Thus to mine eyes.--Now o'er the one half-world // Nature seems dead, and wicked dreams abuse // The curtain'd sleep; now witchcraft celebrates // Pale Hecate's offerings; and wither'd murder, // Alarum'd by his sentinel, the wolf, // Whose howl's his watch, thus with his stealthy pace, // With Tarquin's ravishing strides, towards his design // Moves like a ghost.--Thou sure and firm-set earth, // Hear not my steps, which way they walk, for fear // Thy very stones prate of my whereabout, // And take the present horror from the time, // Which now suits with it.--Whiles I threat, he lives; // Words to the heat of deeds too cold breath gives. // "); I believe with your change the output will now be this:
Which is... well... better, but not what I'd call properly fixed, right? ;) |
@dzuelke Yes, that would be the output. If you want it onto one solo line, then I need to patch fpm_stdio_child_said() as well. |
Yeah, well, that was the whole question or discussion ;) What to do... I think it'd be valuable, and consistent, if every logged line, even if wrapped was preceded by But @ingluisjimenez brought up an interesting point... why does the wrapping at 1024 happen in the first place? Is it for syslog? If so, would it make sense to treat syslog separately, and only wrap if that's the log destination? |
Good question. If it was coded like that at first place, this is because we would want to comply with the RFC, so ... |
@jpauli would there be any chance to drive that message length by a php config value? I understand that 1024 is a standard, but, at the same time, I think that the application developer should be able to customize this and be responsible for any performance degradation due to excessive long lines. |
Once it's done of course |
I'd really be in favour of being able to properly use stderr and stdout without any interference by FPM, meaning ideally all "decoration" should be removed from my perspective. If you need it, there are other ways to output the details you want to have as pointed out earlier in here. |
@naderman It needs to be controlled by master process as you could end up with interleaved output otherwise - there is no lock on stdout and you can have multiple children logging at the same time... Of course I would like to make it a bit more configurable so it won't show the prefixes. That would basically do what you are asking but internally it would be logged by master. If you or others have any ideas about the configuration, feel free to comment on #2458 . |
@bukka absolutely, I understand the need for it to pass through master. I just mean it should try and output it as verbatim as possible. |
The centralized logging is fine, @bukka, but IMO we can do away with the decoration altogether. The default should be that there is no decoration. People use simple logging libs like Monolog etc nowadays, which can print info such as the date, time, or process ID. If you write to The only bit of info that's not available from inside a script is the pool name. Also, is it possible to create a new level "STDIO", that's higher than, or distinct from, "ERROR"? Right now, STDIO output is treated as a warning, which IMO makes no sense. |
I agree that no decorating and forwarding to stdout and stderr should be default if you run fpm inside a container (e.g. Docker). However if it's daemonized, then it probably doesn't make much sense. It means that it would make sense to have this configurable and have a different defaults if you run inside container. I would like to introduce a new flag that would set such defaults when running inside the container (maybe something like About the new level I think that it makes sense (mainly if it's daemonized and you want to log it to the file and differentiate it). However I'm a bit worried about BC (e.g. if there are scripts that are already parsing the fpm log and rely on warning level) so might make sense to have this configurable as well. |
Maybe this is a good change to make for 7.2 then @bukka? It sounds like this doesn't need a new flag either then. If the config has |
@remicollet @sgolemon could you review this with a mind for merging in 7.2 please ? |
@dzuelke @krakjoe What I'm working (refactoring of the logger and adding support for variable log limits including decoration customization) in #2458 won't be ready for 7.2 (see this comment). However thinking about this specific PR, if it wraps the magic bit to some macro (counting the size of the trimming), then I don't see any issue and it should be fine for 7.2 or even 7.1 if RM's agree. The main point is just to reduce size of the buffer to not be trimmed by zlog which is fine IMHO. It would be also good to add a test though which shouldn't be too difficult to do. My stuff will then rewrite it but will keep the default functionality in there (no trimming...) so it should be fine too. |
@sgolemon @remicollet could one of you review this for 7.2 please, seems to have approval ... |
Any news on this one? It's really needed for dockerized production environments. |
Looks like there's a workaround for that, that we can use for now, until the fix lands. Although, if the php-fpm process dies - the container would not be stopped. This needs additionally some shell magic or a health check definition. |
It seems this didn't make it to 7.2 :( |
If this does not make it into 7.2 this would really make me #sad. By using |
@bukka: You are our hope! |
I just update #2458 with a progress. Basically I'm slowly working on it as part of FPMi. The progress and changes can be seen here: https://github.com/bukka/fpmi/compare/next |
Any news? |
Is there not a quicker way to get this done rather than to refactor the entire logging output? This is a highly critical part of using Docker, and from what it looks like, this has been an outstanding bug for several years. |
This affects us literally every day via Google App Engine and dockerized PHP piping to GAE's stderr. |
FWIW: I'm also running PHP in Docker (for many years) Below our latest variant of the 'log to file and tail that to stdout instead' workaround. This one should make sure the container stops when either Note: this is a Symfony app using monolog
#!/bin/sh
set -e
# Workaround for bug in php-fpm which prefixes output to logging: https://bugs.php.net/bug.php?id=71880&edit=3
# Let PHP and Symfony write to files and tail them
# Create log files in advance so tail doesn't fail
LOG_FILES="/tmp/app.log /tmp/php.log"
touch ${LOG_FILES}
# In parallel:
# - Tail log files to standard out OR if that fails make sure php-fpm is killed
# - Run php-fpm as the main process, if this fails the container will be stopped automatically.
(tail -q -f ${LOG_FILES} >> /dev/stdout || pkill php-fpm) & exec php-fpm
monolog:
handlers:
main:
type: stream
path: /tmp/app.log |
any news for this PR? |
Comment on behalf of bukka at php.net: This is being addressed in #2458 |
The maximum zlog message length is 1024 including timestamp et cetera.
With very long messages over 1024 characters, these get wrapped into multiple chunks correctly, but then the "WARNING: child blah said into blah" gets added and the zlog call truncates the messages using "..." at the end, resulting in a couple dozen bytes getting lost.
This change calculates the length at which wrapping needs to occur correctly.
To reproduce, log a long message to
stderr
, e.g. a bit of Shakespeare: