Skip to content
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

[RFC]: Log different informations if is on production or staging #43

Closed
arhimede opened this issue Jan 30, 2025 · 2 comments · Fixed by #44
Closed

[RFC]: Log different informations if is on production or staging #43

arhimede opened this issue Jan 30, 2025 · 2 comments · Fixed by #44

Comments

@arhimede
Copy link
Member

RFC

We need to log in errorl_log file different informations in production.
On local we have woops, on server we have server logs but we cannot match it with dotkernel log

Background

Considerations

Proposal(s)

If production , then log
SERVER super global
Session superglobal
Do NOT log stack trace

Appendix
@arhimede arhimede added this to Backlog Jan 30, 2025
@alexmerlin
Copy link
Member

I tried reorganizing the stuff we should log and I have a couple of observations:

  1. We can have environment-based logs by creating a new (JSON) formatter in dot-log.
    This would log only the values we all agree on, in order to provide straightforward answers to the developer.
  2. In order to log session data we must add laminas-session into dot-errrorhandler - personally, I would avoid this.
    The other option is to use the $_SESSION superglobal but this solution is even worse than the first one.
    Thoughts @arhimede ?

See below a full log with all the info we have available at request time.

The root keys timestamp, priority, priorityName, message and extra are currently in use in the log files.
This should not change unless we want to change it completely, for all environments (both locally and on production etc.).
What we should change is the data we store under the extra key.
Let's see what can we add/remove from the below in order to make it usable:

{
  "timestamp": "2025-01-30T11:53:41+00:00",
  "priority": 3,
  "priorityName": "ERR",
  "message": "Frontend\\Page\\Controller\\PageController::indexAction(): Return value must be of type Psr\\Http\\Message\\ResponseInterface, null returned",
  "extra": {
    "file": "/var/www/frontend.dotkernel.localhost/html/src/Page/src/Controller/PageController.php",
    "line": 31,
    "server": {
      "USER": "apache",
      "HOME": "/usr/share/httpd",
      "SCRIPT_NAME": "/index.php",
      "REQUEST_URI": "/",
      "QUERY_STRING": "",
      "REQUEST_METHOD": "GET",
      "SERVER_PROTOCOL": "HTTP/1.1",
      "GATEWAY_INTERFACE": "CGI/1.1",
      "REMOTE_PORT": 51142,
      "SCRIPT_FILENAME": "/var/www/frontend.dotkernel.localhost/html/public/index.php",
      "SERVER_ADMIN": "webmaster@localhost",
      "CONTEXT_DOCUMENT_ROOT": "/var/www/frontend.dotkernel.localhost/html/public",
      "CONTEXT_PREFIX": "",
      "REQUEST_SCHEME": "http",
      "DOCUMENT_ROOT": "/var/www/frontend.dotkernel.localhost/html/public",
      "REMOTE_ADDR": "::1",
      "SERVER_PORT": 80,
      "SERVER_ADDR": "::1",
      "SERVER_NAME": "frontend.dotkernel.localhost",
      "SERVER_SOFTWARE": "Apache/2.4.62 (AlmaLinux)",
      "SERVER_SIGNATURE": "",
      "PATH": "/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin",
      "HTTP_PRIORITY": "u=0, i",
      "HTTP_SEC_FETCH_USER": "?1",
      "HTTP_SEC_FETCH_SITE": "none",
      "HTTP_SEC_FETCH_MODE": "navigate",
      "HTTP_SEC_FETCH_DEST": "document",
      "HTTP_UPGRADE_INSECURE_REQUESTS": 1,
      "HTTP_COOKIE": "FRONTEND_SESSID=feb21b39f9c54e3a49af1f862acc8300; rememberMe=a8ee133be785372156bdb63a68ca82ba40fdef31ea308ca7854986ba98b9d271",
      "HTTP_CONNECTION": "keep-alive",
      "HTTP_SEC_GPC": 1,
      "HTTP_DNT": 1,
      "HTTP_ACCEPT_ENCODING": "gzip, deflate, br, zstd",
      "HTTP_ACCEPT_LANGUAGE": "en-US,en;q=0.5",
      "HTTP_ACCEPT": "text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8",
      "HTTP_USER_AGENT": "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:134.0) Gecko/20100101 Firefox/134.0",
      "HTTP_HOST": "frontend.dotkernel.localhost",
      "proxy-nokeepalive": 1,
      "HTTP_AUTHORIZATION": "",
      "UNIQUE_ID": "Z5toRQq_SOUB4I3i8t1qSAAAAAE",
      "FCGI_ROLE": "RESPONDER",
      "PHP_SELF": "/index.php",
      "REQUEST_TIME_FLOAT": 1738238021.454624,
      "REQUEST_TIME": 1738238021
    },
    "cookie": {
      "FRONTEND_SESSID": "feb21b39f9c54e3a49af1f862acc8300",
      "rememberMe": "a8ee133be785372156bdb63a68ca82ba40fdef31ea308ca7854986ba98b9d271"
    },
    "session": {
      "__Laminas": {
        "_REQUEST_ACCESS_TIME": 1738238021.538802,
        "_VALID": {
          "Laminas\\Session\\Validator\\Id": "feb21b39f9c54e3a49af1f862acc8300"
        },
        "Default": {
          "EXPIRE": 1738068375
        }
      },
      "Default": {},
      "frontend_messenger": {},
      "Laminas_Auth": {}
    },
    "trace": [
      {
        "file": "/var/www/frontend.dotkernel.localhost/html/vendor/dotkernel/dot-controller/src/AbstractActionController.php",
        "line": 38,
        "function": "indexAction",
        "class": "Frontend\\Page\\Controller\\PageController",
        "type": "->"
      },
...
      {
        "file": "/var/www/frontend.dotkernel.localhost/html/public/index.php",
        "line": 34,
        "function": "{closure}"
      }
    ]
  }
}

Additionally, we could reduce the trace to a more compact format, like:

{
  "timestamp": "2025-01-30T12:27:32+00:00",
  "priority": 3,
  "priorityName": "ERR",
  "message": "Frontend\\Page\\Controller\\PageController::indexAction(): Return value must be of type Psr\\Http\\Message\\ResponseInterface, null returned",
  "extra": {
    "file": "/var/www/frontend.dotkernel.localhost/html/src/Page/src/Controller/PageController.php",
    "line": 31,
    "server": {
      "USER": "apache",
      "HOME": "/usr/share/httpd",
      "SCRIPT_NAME": "/index.php",
      "REQUEST_URI": "/",
      "QUERY_STRING": "",
      "REQUEST_METHOD": "GET",
      "SERVER_PROTOCOL": "HTTP/1.1",
      "GATEWAY_INTERFACE": "CGI/1.1",
      "REMOTE_PORT": 45390,
      "SCRIPT_FILENAME": "/var/www/frontend.dotkernel.localhost/html/public/index.php",
      "SERVER_ADMIN": "webmaster@localhost",
      "CONTEXT_DOCUMENT_ROOT": "/var/www/frontend.dotkernel.localhost/html/public",
      "CONTEXT_PREFIX": "",
      "REQUEST_SCHEME": "http",
      "DOCUMENT_ROOT": "/var/www/frontend.dotkernel.localhost/html/public",
      "REMOTE_ADDR": "::1",
      "SERVER_PORT": 80,
      "SERVER_ADDR": "::1",
      "SERVER_NAME": "frontend.dotkernel.localhost",
      "SERVER_SOFTWARE": "Apache/2.4.62 (AlmaLinux)",
      "SERVER_SIGNATURE": "",
      "PATH": "/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin",
      "HTTP_PRIORITY": "u=0, i",
      "HTTP_SEC_FETCH_USER": "?1",
      "HTTP_SEC_FETCH_SITE": "none",
      "HTTP_SEC_FETCH_MODE": "navigate",
      "HTTP_SEC_FETCH_DEST": "document",
      "HTTP_UPGRADE_INSECURE_REQUESTS": 1,
      "HTTP_COOKIE": "FRONTEND_SESSID=feb21b39f9c54e3a49af1f862acc8300; rememberMe=a8ee133be785372156bdb63a68ca82ba40fdef31ea308ca7854986ba98b9d271",
      "HTTP_CONNECTION": "keep-alive",
      "HTTP_SEC_GPC": 1,
      "HTTP_DNT": 1,
      "HTTP_ACCEPT_ENCODING": "gzip, deflate, br, zstd",
      "HTTP_ACCEPT_LANGUAGE": "en-US,en;q=0.5",
      "HTTP_ACCEPT": "text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8",
      "HTTP_USER_AGENT": "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:134.0) Gecko/20100101 Firefox/134.0",
      "HTTP_HOST": "frontend.dotkernel.localhost",
      "proxy-nokeepalive": 1,
      "HTTP_AUTHORIZATION": "",
      "UNIQUE_ID": "Z5twNBAGphlRrq8jebmwVQAAANQ",
      "FCGI_ROLE": "RESPONDER",
      "PHP_SELF": "/index.php",
      "REQUEST_TIME_FLOAT": 1738240052.762322,
      "REQUEST_TIME": 1738240052
    },
    "cookie": {
      "FRONTEND_SESSID": "feb21b39f9c54e3a49af1f862acc8300",
      "rememberMe": "a8ee133be785372156bdb63a68ca82ba40fdef31ea308ca7854986ba98b9d271"
    },
    "session": {
      "__Laminas": {
        "_REQUEST_ACCESS_TIME": 1738240052.834334,
        "_VALID": {
          "Laminas\\Session\\Validator\\Id": "feb21b39f9c54e3a49af1f862acc8300"
        },
        "Default": {
          "EXPIRE": 1738068375
        }
      },
      "Default": {},
      "frontend_messenger": {},
      "Laminas_Auth": {}
    },
    "trace": [
      "Frontend\\Page\\Controller\\PageController->indexAction:38",
      "Dot\\Controller\\AbstractActionController->dispatch:57",
      "Dot\\Controller\\AbstractController->process:26",
      "Mezzio\\Middleware\\LazyLoadingMiddleware->process:52",
      "Laminas\\Stratigility\\Next->handle:77",
      "Laminas\\Stratigility\\MiddlewarePipe->process:79",
      "Mezzio\\Router\\Route->process:109",
      "Mezzio\\Router\\RouteResult->process:32",
      "Mezzio\\Router\\Middleware\\DispatchMiddleware->process:26",
      "Mezzio\\Middleware\\LazyLoadingMiddleware->process:52",
      "Laminas\\Stratigility\\Next->handle:117",
      "Dot\\Rbac\\Guard\\Middleware\\RbacGuardMiddleware->process:26",
      "Mezzio\\Middleware\\LazyLoadingMiddleware->process:52",
      "Laminas\\Stratigility\\Next->handle:64",
      "Dot\\Rbac\\Guard\\Middleware\\ForbiddenHandler->process:26",
      "Mezzio\\Middleware\\LazyLoadingMiddleware->process:52",
      "Laminas\\Stratigility\\Next->handle:60",
      "Frontend\\App\\Middleware\\AuthMiddleware->process:26",
      "Mezzio\\Middleware\\LazyLoadingMiddleware->process:52",
      "Laminas\\Stratigility\\Next->handle:59",
      "Frontend\\App\\Middleware\\RememberMeMiddleware->process:26",
      "Mezzio\\Middleware\\LazyLoadingMiddleware->process:52",
      "Laminas\\Stratigility\\Next->handle:38",
      "Mezzio\\Helper\\UrlHelperMiddleware->process:26",
      "Mezzio\\Middleware\\LazyLoadingMiddleware->process:52",
      "Laminas\\Stratigility\\Next->handle:59",
      "Mezzio\\Router\\Middleware\\MethodNotAllowedMiddleware->process:26",
      "Mezzio\\Middleware\\LazyLoadingMiddleware->process:52",
      "Laminas\\Stratigility\\Next->handle:75",
      "Mezzio\\Router\\Middleware\\ImplicitOptionsMiddleware->process:26",
      "Mezzio\\Middleware\\LazyLoadingMiddleware->process:52",
      "Laminas\\Stratigility\\Next->handle:77",
      "Mezzio\\Router\\Middleware\\ImplicitHeadMiddleware->process:26",
      "Mezzio\\Middleware\\LazyLoadingMiddleware->process:52",
      "Laminas\\Stratigility\\Next->handle:28",
      "Dot\\ResponseHeader\\Middleware\\ResponseHeaderMiddleware->process:26",
      "Mezzio\\Middleware\\LazyLoadingMiddleware->process:52",
      "Laminas\\Stratigility\\Next->handle:50",
      "Mezzio\\Router\\Middleware\\RouteMiddleware->process:26",
      "Mezzio\\Middleware\\LazyLoadingMiddleware->process:52",
      "Laminas\\Stratigility\\Next->handle:57",
      "Mezzio\\Cors\\Middleware\\CorsMiddleware->process:26",
      "Mezzio\\Middleware\\LazyLoadingMiddleware->process:52",
      "Laminas\\Stratigility\\Next->handle:27",
      "Mezzio\\Helper\\ServerUrlMiddleware->process:26",
      "Mezzio\\Middleware\\LazyLoadingMiddleware->process:52",
      "Laminas\\Stratigility\\Next->handle:46",
      "Dot\\Session\\SessionMiddleware->process:26",
      "Mezzio\\Middleware\\LazyLoadingMiddleware->process:52",
      "Laminas\\Stratigility\\Next->handle:64",
      "Dot\\ErrorHandler\\LogErrorHandler->process:26",
      "Mezzio\\Middleware\\LazyLoadingMiddleware->process:52",
      "Laminas\\Stratigility\\Next->handle:77",
      "Laminas\\Stratigility\\MiddlewarePipe->process:66",
      "Laminas\\Stratigility\\MiddlewarePipe->handle:73",
      "Laminas\\HttpHandlerRunner\\RequestHandlerRunner->run:53",
      "Mezzio\\Application->run:33",
      "/var/www/frontend.dotkernel.localhost/html/public/index.php->{closure}:34"
    ]
  }
}

because from the namespace (Frontend\\Page\\Controller\\PageController) we can identify the file (/var/www/frontend.dotkernel.localhost/html/vendor/dotkernel/dot-controller/src/AbstractActionController.php), so it's no need to log that one as well.
@MarioRadu what do you think, would that compact stack trace provide you enough information to debug an issue?

@arhimede
Copy link
Member Author 

2. In order to log session data we must add `laminas-session` into `dot-errrorhandler` - personally, I would avoid this.
   The other option is to use the `$_SESSION` superglobal but this solution is even worse than the first one.
   Thoughts [@arhimede](https://github.com/arhimede) ?

Let's do a conditional check
IF the laminas-session exists, the log the laminas-session container
IF not exists, then use Superglobal $_SESSION

alexmerlin added a commit that referenced this issue Feb 6, 2025
@alexmerlin
Issue #43: Control the contents of 'extra' in error log.
7d408e3 
Signed-off-by: alexmerlin <[email protected]>
@alexmerlin alexmerlin linked a pull request Feb 6, 2025 that will close this issue
Issue #43: Control the contents of extra in error log. #44
Merged
arhimede added a commit that referenced this issue Feb 24, 2025
@arhimede
Merge pull request #44 from dotkernel/issue-43
84f8368 
Issue #43: Control the contents of `extra` in error log.
@github-project-automation github-project-automation bot moved this to Done in Backlog Feb 24, 2025
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
Backlog
Status: Done
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Issue #43: Control the contents of extra in error log. dotkernel/dot-errorhandler
2 participants
@alexmerlin @arhimede