Bug 1961508 - pulp-3 to log access logs to another file than /var/log/messages [NEEDINFO]
Summary: pulp-3 to log access logs to another file than /var/log/messages
Keywords:
Status: NEW
Alias: None
Product: Red Hat Satellite
Classification: Red Hat
Component: Pulp
Version: 6.9.0
Hardware: Unspecified
OS: Unspecified
unspecified
medium vote
Target Milestone: Unspecified
Assignee: satellite6-bugs
QA Contact: Vladimír Sedmík
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2021-05-18 06:52 UTC by Pavel Moravec
Modified: 2022-12-02 19:10 UTC (History)
10 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed:
Target Upstream Version:
dalley: needinfo? (lzap)


Attachments (Terms of Use)

Description Pavel Moravec 2021-05-18 06:52:12 UTC
Description of problem:
Currently, pulpcore / pulp-3 does log access log entries to /var/log/messages, like:

May 18 08:44:37 pmoravec-sat69-pulp3 pulpcore-api: pulp [-]:  - - [18/May/2021:06:44:37 +0000] "GET /pulp/api/v3/tasks/5782d0e8-8814-4638-af71-5116328b8589/ HTTP/1.1" 200 1170 "-" "OpenAPI-Generator/3.7.1/ruby"

May 17 20:33:06 pmoravec-sat69-pulp3 pulpcore-api: pulp [-]:  - - [17/May/2021:18:33:06 +0000] "GET /pulp/api/v3/content/rpm/distribution_trees/?repository_version=%2Fpulp%2Fapi%2Fv3%2Frepositories%2Frpm%2Frpm%2F7b561af0-d36b-4147-851e-f428f3c78222%2Fversions%2F0%2F HTTP/1.1" 200 52 "-" "OpenAPI-Generator/3.10.0/ruby"

May 17 23:01:55 pmoravec-sat69-pulp3 pulpcore-api: pulp [-]:  - - [17/May/2021:21:01:55 +0000] "GET /pulp/api/v3/status HTTP/1.1" 301 0 "-" "rest-client/2.0.2 (linux-gnu x86_64) ruby/2.5.5p157"

/var/log/messages is quite spammed by those log entries, that should be categorized as (and logged to) a dedicated httpd/pulpcore access log.


Version-Release number of selected component (if applicable):
Sat6.9 with pulpcore switched on.


How reproducible:
100%


Steps to Reproduce:
1. Any usual activity like sync a repo from CDN, publish a CV, hammer ping etc.


Actual results:
pulpcore-api logs the access logs to /var/log/messages


Expected results:
the access logs should be logged either in /var/log/httpd/pulp_access.log or a similar file, or in a dedicated /var/log/pulp* log.


Additional info:
I understand the categorization of log entries can be subjective and/or there can be rationale to log them to /var/log/messages . So take this rather as a suggestion than as a bug.

Comment 1 pulp-infra@redhat.com 2021-05-18 16:20:58 UTC
The Pulp upstream bug status is at NEW. Updating the external tracker on this bug.

Comment 2 pulp-infra@redhat.com 2021-05-18 16:20:59 UTC
The Pulp upstream bug priority is at Normal. Updating the external tracker on this bug.

Comment 3 Peter Vreman 2021-06-11 15:35:31 UTC
I know it also exists in pulp2 already like this, but it looks with pulp3 it it getting more

Arguments to have it in dedicated file:
- The amount of pulp logging is too much that it hides real OS system logs
- Pulp has very long lines (currently i can see 8000+ characters) this makes browsing the file with 'less' cumbersome
- It is inconsistent with the other parts of Sat6 like foreman and candlepin

Comment 4 Tanya Tereshchenko 2021-06-11 19:34:56 UTC
(In reply to Peter Vreman from comment #3)
> I know it also exists in pulp2 already like this, but it looks with pulp3 it
> it getting more
> 
> Arguments to have it in dedicated file:
> - The amount of pulp logging is too much that it hides real OS system logs
> - Pulp has very long lines (currently i can see 8000+ characters) this makes
> browsing the file with 'less' cumbersome
> - It is inconsistent with the other parts of Sat6 like foreman and candlepin

Could you provide an example of a really long 8000+ line, please?
And which log level do you have configured?

Comment 5 Peter Vreman 2021-06-12 14:26:32 UTC
I forgot that mongo was still running, the 8000+ line is from mongo.

From pulpcore the longest line ~4000
----
[crash/LI] root@li-lc-2222:/var/log# awk '/2222 pulpcore/ { if (length > max_length) { max_length = length; longest_line = $0 } } END { print longest_line }' messages
Jun 11 13:28:22 li-lc-2222 pulpcore-api[1655]: pulp [-]:  - - [11/Jun/2021:13:28:22 +0000] "GET /pulp/api/v3/pulp2content/?pulp2_id__in=02cf050c-eb83-4f48-a844-e68116b53bfd%2C07f432f6-5033-404f-b193-a6bf3d5d6601%2C1213624e-b1f7-4da0-8b71-e091496f8019%2C1e85c00e-99e2-4704-8b1a-dc5abe7d6bbd%2C221771c9-6e1e-4969-8cd1-23a226ddc5b5%2C2268d2ab-ded5-4c4d-8e3f-6115553f9cfc%2C2f851da7-7516-4879-9bbd-aec270ba8a99%2C38a29591-3a57-4e0a-8e6e-f154f382e7c4%2C48a82b23-0cad-485f-953d-421fa7f8e07d%2C4d6775ba-bcca-49e6-8280-37a23b09fb18%2C594fb66c-c7e5-4f1e-9bcb-b2c2add2aad8%2C6311f150-6cd2-4e2d-a506-cc1214f6fca9%2C71b8158b-1d0b-402b-b444-6c8d140f0bec%2C77c40d4e-1a7f-44de-9662-66ac6a8eb883%2C7a156600-c400-4eb9-bba0-89b5c54f5952%2C8d15ce6b-b9f9-446a-b682-d7e791c81937%2C8e97be9c-69e9-4cc5-b771-b445e5de8e6b%2C8e9f88d4-168e-4856-b95d-9248fceff4ab%2Cad88a11c-183e-4198-b926-17e16c0715e2%2Cb40f15d0-f9e0-4d15-9a82-e95b4c347160%2Cc331bed5-763c-4615-8b7c-23038f466be5%2Cc607fc6e-aafc-4886-a53f-39f7300d74a6%2Cc9f1076f-29a0-42ba-9cf4-3d540c1702e0%2Ccc057cce-94e7-4313-be83-501e819b207b%2Ccc739a88-0d89-497a-ae0a-8e8e830f1d56%2Cd2aa4f67-4f23-4b69-af8a-d04740f76700%2Cdf6ee007-d8f2-4119-8070-89c404a9310a%2Ce03aa084-e8c4-4d30-90f9-de5789546ec1%2Ce3cd880c-0df6-48a1-84ce-b893d6015abe%2Ce4297dae-2a1c-4f96-8fed-21b472dd1cdf%2Cfbc92430-770a-4179-89d6-257c69f8c1f8%2Cff65aa85-bfbc-44a3-a854-946013fe05ab%2C044851c0-d891-4fcf-a50c-65b683853854%2C09961e73-4eeb-4a46-8c15-dfb38aed0df3%2C26e21c88-6d7c-46ae-81ad-a397be16cf64%2C28077dac-d946-4e93-a256-fbcea1cb0310%2C32441daa-2ef3-461e-a9ee-36bec522ba20%2C38c4e5e2-8782-48ef-832d-e0f02edcc88d%2C3e58a2e7-020b-4ba6-a037-1cdcb3a15959%2C41b0dac6-8ca1-4133-981d-8e92bae48ee4%2C41c82f42-685c-4e2f-b46a-67f0848b9225%2C41c9c21e-abac-424d-b550-aa4c756256f4%2C51623476-2b65-4844-ace9-8cce64c2a323%2C633aa7de-46fa-4a68-a80f-15a861e3bf49%2C80308943-43ef-4bd8-874b-5db8b578f185%2C840c0bb9-16eb-4b5b-8376-1241fc4280c2%2C92e57146-853c-428a-8648-d9c48143e7d4%2Ca2a0df14-127b-4151-9e5d-9c6c8a7837c3%2Cab62d486-c7ed-43ee-8cf4-24136fc2b27b%2Cb4d86572-adb9-4774-92d4-b8e537904371%2Ce1f9caf4-755e-4499-b8d9-5f421330e68c%2Cee3d19a7-4c94-4c0c-9d0b-935d42209a9d%2Ceeb08e6f-d8ab-4720-8bbf-04f410604538%2Cf7d067bf-48c6-41b8-bfd2-ef9b8bcb67ce%2Cff1b6264-d225-481a-a99b-b23430ad4b6b%2C038b10af-a29d-4f46-a237-61f7096d5742%2C0962419e-d0e3-45c6-ac81-e315ffef9ec7%2C0b66014e-4bf7-41cf-b2c5-3b7e5444621e%2C0be4ce02-5a16-470a-bbe8-f99b7642e23f%2C0d9d0d3f-ec0a-4afb-8d2b-f73622c55f8c%2C13ed7e15-6cb1-4811-8bfd-402b966e3881%2C1ada2e98-1c02-4a7e-9009-e3585e108890%2C233b0a0e-1088-4788-969d-7523b7e0659e%2C28eb1415-85f6-4f44-bca3-0f0e661914fc%2C2b299854-af66-4b86-98f2-a27778d16bf3%2C2bdc3bf8-6908-4709-a0f4-af6958c920e3%2C2dfcad2a-1720-4699-9305-8cebcf9231a2%2C2e9ef1be-5f33-481d-83c4-c091ffd1f4f7%2C30109b52-ee5e-43b1-8503-7713dc0e8f99%2C3a562094-07d3-4241-ba40-d90dc7475edf%2C3ed49db6-6da5-4b6e-8120-7cbfdfac9234%2C42fe6189-1622-469d-bd58-8dc3fb56b299%2C4a3c7854-3e59-4aa0-8940-0791eaaa5e9d%2C51210d17-3085-4447-9293-a6632714231a%2C512e5485-569c-492a-a50e-6fdb577e478f%2C5679e9eb-9f82-48a7-9f08-2ce41c3c9220%2C56a079ea-150a-4f55-9a69-d2c9c6c27084%2C5ce28dea-a21b-4c85-aa59-a2d89ef3aae0%2C5e82ba5d-06e7-4a0e-b5c7-0da25789ed93%2C6453ec96-ab58-452d-b23a-355087e98940%2C64a08775-7444-4b76-9e22-3d7c8383f848%2C698bd921-cc6d-478b-9b96-9ad31c53b1ae%2C6f6a8e8d-fe58-489c-aa28-e90877890c7e%2C72ea6b56-cadf-4eb5-8a56-4965845d6314%2C7b50b17b-67fe-43da-ac91-55e3e151c670%2C7d826b16-95b1-41e4-b4c6-aef3be834234%2C80857688-0a80-44fa-b979-497494c002f8%2C8c7fa946-4371-41c2-825b-152aac2d3dcc%2C8d45d3ac-7e43-48ca-9f0d-36b4ad69a4b5%2C8faa3114-b228-458c-925c-bd14abd4133c HTTP/1.1" 200 41637 "-" "OpenAPI-Generator/0.10.0/ruby"
[crash/LI] root@li-lc-2222:/var/log#
----

Comment 6 Peter Vreman 2021-06-12 14:31:03 UTC
Sorry, and with the browsing being cumbersome i was confusing it with foreman production.log that has lines of 200000+ characters:

----
[crash/LI] root@li-lc-2222:/var/log# zcat /var/log/foreman/production.log-20210611.gz | wc -L
245308
[crash/LI] root@li-lc-2222:/var/log#
----

Comment 11 Robin Chan 2021-06-29 20:43:45 UTC
Note that some of the recent changes in logging for Pulp were made to allow Satellite to be integrated with other log monitoring services. Changes to logging approach should keep this in mind in addition to ease of individual examination of logs by hand.

Comment 12 Pavel Moravec 2021-06-30 07:17:34 UTC
(In reply to Robin Chan from comment #11)
> Note that some of the recent changes in logging for Pulp were made to allow
> Satellite to be integrated with other log monitoring services. Changes to
> logging approach should keep this in mind in addition to ease of individual
> examination of logs by hand.

I was not aware of such requests. A solution like I suggest can be achieved just by proper rsyslog setting, in case the monitoring services fetch the logs from rsyslog.

Comment 13 Peter Vreman 2021-06-30 16:28:08 UTC
There is no one-size-fits all for logging strategy


The consistency argument is also completly ignored.
- candlepin writes to /var/log/candlepin
- katello/forman writes to /var/log/foreman
- puppet writes to /var/log/puppetlabs/puppetserver

Currently Pulp is the strange-duck the 'satellite-suite' to log to syslog.



In my case i do not want the pulp logs in the syslog:
- The /var/log/messages is flooded and hiding real OS issues, e.g. Basic OS services or also PCP pmie alerts of overall OS performance
- The pulp messages are also included in forwarding to central server where the volume ingested costs money

The user shall be able to chose the 

E.g. a satellite-installer option to chose the destination:
--pulpcore-log-dest=syslog (default, backwards compatible)
--pulpcore-log-dest=files


And please do not come with the excuse that rsyslog has filters. Adding for every application rsyslog filters costs performance and maintenance effort on the shoulder of every satellite-customer.

Comment 14 Lukas Zapletal 2021-07-01 09:48:21 UTC
Hello all,

we have made investments into common Satellite logging experience. From version 6.6, it is possible to configure nearly all components (Foreman, Proxy, Candlepin, Pulp) to send all logs into journald or syslog where further transformation and redirection can be done. The use case was ElasticSearch, a logging target that is often mentioned by our customers. In our example setup, log records can be optionally routed to different files than /var/log/messages:

https://github.com/lzap/foreman-elasticsearch

In the long term, we would like to set all Satellite components to send logs into journald or syslog by default, we are not there yet and this is definitely not happening now when the team is busy with Satellite NEXT, RHEL8 upgrade and Pulp3 upgrade. But after that, I think this is something PMs should be looking into.

In my opinion, all Satellite components should be able to send all logs into journald or syslog in a way that there is a configuration option to do that. This is something that Pulp2 implemented and I believe it is the case for Pulp3 as well. Having said that, I do understand expectations for access logs (or other noisy log records) to go into a separate file by default - this is how Apache http does it as the OS journal/syslog (messages) is not the best target for such logs.

I personally like to mark access logs with a separate source like we do for other logs (app, permissions, audit), however, some libraries makes it really hard. I am not sure if its a library what generates those Pulp logs, but in case of Ruby on Rails, the community has a strong opinion about access logs: they should go into INFO level log and there is no source attached to it (RoR only supports one pile of logs). My proposal/patch to be able to set a different logging level was closed. So in the end, Foreman (Ruby on Rails) also send all access logs into syslog or production.log under INFO level with logger set to APP (application), it is not possible to reasonably filter them out from other (more important) INFO application logs.

My suggestion is to send all web-access-type logs into a separate INFO logger providing an option to turn it off completely, or redirect it into a different file. If these logs are really noisy, then I would consider sending them into a separate file. If Pulp3 uses syslog, then dropping a syslog configuration that will route all these access logs into separate file is needed.

Comment 15 Lukas Zapletal 2021-07-01 09:58:18 UTC
> And please do not come with the excuse that rsyslog has filters. Adding for every application rsyslog filters costs performance and maintenance effort on the shoulder of every satellite-customer.

We have made the decision some time ago that it is not in our interest to maintain 3rd party logging systems adapters. Sending logs into journald (preferably) and/or syslog is the way we would like to go forward. The ultimate goal is to have all Satellite components logging into syslog with configuration to forward logs into separate files on the same pathnames as our customers are used to today to prevent confusion after the switch.

If you have any performance concerns, please reach out to RHEL logging team, but filtering logs based on log level and syslog facility is not a performance issue as far as I know. Yes, more complex filtering based on content can be costly, but this is something we do not aim for in our default setup. The current implementation of ElasticSearch (https://github.com/lzap/foreman-elasticsearch) does perform some transformation because customers asked for a common format across all Satellite apps, but it is also possible to configure rsyslog to simply send logs over to a 3rd party without transformations I believe.

Comment 23 Lukas Zapletal 2021-11-02 08:54:00 UTC
Here is a snippet that is tested on 6.10 and will redirect all
relevant pulp logs from /var/log/messages into /var/log/pulp. Note,
you need to create this directory (can be owned by root) as it does
not exist on 6.10. Also keep in mind that this only configures syslog,
journald will still contain all pulp logs and this is by design -
journald is architected in a way that it stores everything in a binary
blob and then users use its searching and filtering capabilities to
view the data in efficient way.

cat >/etc/rsyslog.d/pulp.conf <<EOF
if $programname == 'pulpcore-api' then {
  *.* /var/log/pulp/pulpcore-api.log
  *.* stop
} else if $programname startswith 'pulpcore-worker' then {
  *.* /var/log/pulp/pulpcore-worker.log
  *.* stop
} else if $programname == 'pulpcore-content' then {
  *.* /var/log/pulp/pulpcore-content.log
  *.* stop
}
EOF

mkdir /var/log/pulp

systemctl restart rsyslog

Hope it helps, cheers.

Comment 27 Brad Buckingham 2022-12-02 18:42:02 UTC
Upon review of our valid but aging backlog the Satellite Team has concluded that this Bugzilla does not meet the criteria for a resolution in the near term, and are planning to close in a month. This message may be a repeat of a previous update and the bug is again being considered to be closed. If you have any concerns about this, please contact your Red Hat Account team.  Thank you.

Comment 28 Daniel Alley 2022-12-02 19:10:37 UTC
(In reply to Lukas Zapletal from comment #23)
> Here is a snippet that is tested on 6.10 and will redirect all
> relevant pulp logs from /var/log/messages into /var/log/pulp. Note,
> you need to create this directory (can be owned by root) as it does
> not exist on 6.10. Also keep in mind that this only configures syslog,
> journald will still contain all pulp logs and this is by design -
> journald is architected in a way that it stores everything in a binary
> blob and then users use its searching and filtering capabilities to
> view the data in efficient way.
> 
> cat >/etc/rsyslog.d/pulp.conf <<EOF
> if $programname == 'pulpcore-api' then {
>   *.* /var/log/pulp/pulpcore-api.log
>   *.* stop
> } else if $programname startswith 'pulpcore-worker' then {
>   *.* /var/log/pulp/pulpcore-worker.log
>   *.* stop
> } else if $programname == 'pulpcore-content' then {
>   *.* /var/log/pulp/pulpcore-content.log
>   *.* stop
> }
> EOF
> 
> mkdir /var/log/pulp
> 
> systemctl restart rsyslog
> 
> Hope it helps, cheers.

Lukas, do you think anything further ought to be done with that configuration?  Is there anything we ought to do on the Pulp side, or can this issue be closed?


Note You need to log in before you can comment on or make changes to this bug.