8000 Code example for Log Processors doesn't work (anymore) · Issue #7897 · symfony/symfony-docs · GitHub
[go: up one dir, main page]
Skip to content

Code example for Log Processors doesn't work (anymore) #7897

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

Jump to bottom
Closed
leonboot opened this issue May 11, 2017 · 2 comments
Closed

Code example for Log Processors doesn't work (anymore) #7897

leonboot opened this issue May 11, 2017 · 2 comments
Labels
bug hasPR A Pull Request has already been submitted for this issue.
Milestone
2.7

Comments

@leonboot
Copy link
leonboot commented May 11, 2017 •
edited
Loading

To illustrate what you can do with log processors, there's a code example in logging/processors.rst which adds a token to the log entry based on the session ID. This allows the administrator to match different log entries, possibly even in different log files, to a single request, or even multiple requests in one session:

namespace AppBundle;

use Symfony\Component\HttpFoundation\Session\Session;

class SessionRequestProcessor
{
    private $session;
    private $token;

    public function __construct(Session $session)
    {
        $this->session = $session;
    }

    public function processRecord(array $record)
    {
        if (null === $this->token) {
            try {
                $this->token = substr($this->session->getId(), 0, 8);
            } catch (\RuntimeException $e) {
                $this->token = '????????';
            }
            $this->token .= '-' . substr(uniqid(), -8);
        }
        $record['extra']['token'] = $this->token;

        return $record;
    }
}

The processor adds a 'token' value to the 'extra' part of the log record. The token is comprised of the first 8 characters from the session ID, and another 8 random hexadecimal characters. If there's no started session (which is tested by catching any exception caused by $this->session->getId(). Should this throw an exception, the session ID part will be replaced by '????????'.

So, the expected result would be a token like abcd1234-def567889 for a request with a started session, and ????????-abcd1234 for a request with no started session.

However, it seems that, regardless the session state, the first part of the token is blank, resulting in tokens like -abcd1234. It seems Symfony\Component\HttpFoundation\Session\Session->getId() simply returns an empty string if the session has not been started yet. So there's no exception to be caught. This could be solved by checking if the result of Session->getId() is empty instead of trying to catch an exception. This leads us to the next issue: the session is never started when the log processor is called. Even for requests which require authentication (ie. a started session is required), the session ID part is blank.

One could start the session from the processor, this actually gives us the desired results; log entries have a token which allows us to distinguish the session and specific request the entry belongs to. However, this is a very, very dirty hack and leads to undesired side effects. In our case, all our behat tests started to fail.

Either this simply does not work anymore (I can't tell whether it had worked at some point) because the processors are being called too early on, or it could still work with some alterations. Either way, I think this page needs some attention.
@leonboot
Copy link
Author

Some extra info: I tried to get the session ID by reading the PHPSESSID (or whatever session_name() returns) cookie, which actually seems to work. I tried doing it gracefully by injecting the '@request_stack' service so I could use the Request->cookie object, but the processor seems to receive an empty stack with no requests in it. All in all it seems the processor is called really early on when hardly anything seems to be bootstrapped. This kind of defies the purpose of the log processors, their main purpose being to enrich the log entries with metadata from the application.

@HeahDude HeahDude added the bug label Jul 25, 2017
@HeahDude HeahDude added this to the 2.7 milestone Jul 25, 2017
@HeahDude HeahDude mentioned this issue Jul 25, 2017
Merged
@HeahDude
Copy link
Contributor

Thanks for the report @leonboot, I've opened #8226 to fix this issue.

@HeahDude HeahDude added the hasPR A Pull Request has already been submitted for this issue. label Jul 25, 2017
xabbuh added a commit that referenced this issue Sep 3, 2017
@xabbuh
minor #8226 Fixed logger processor example (HeahDude)
7bb1e1a 
This PR was merged into the 2.7 branch.

Discussion
----------

Fixed logger processor example

Fixes #7897.

Commits
-------

24ddb64 Fixed logger processor example
@xabbuh xabbuh closed this as completed Sep 3, 2017
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
441A
Labels
bug hasPR A Pull Request has already been submitted for this issue.
Projects
None yet
Milestone
2.7
Development

No branches or pull requests
4 participants
@leonboot @xabbuh @HeahDude @carsonbot
0