Logfile wächst ohne Grund auf mehrere MB bis GB in kurzer Zeit

Shopware 6 (German) Allgemein
1

Hallo,

In unserem Testsystem (Produktiv-Installiert. aber nicht öffentlich) wächst das Logfile in wenigen Stunden und Tagen auf viele hundert MB und in einigen Tagen auf einige GB an. Es gibt keine Plugins oder Module. Keine Prozesse oder Crons. Keine User. Das System läuft einfach nur und müllt den Server zu. (var/log/dev.log)

[2020-02-26 10:22:46] app.DEBUG: continue with last used saleschannel 2ae0ed25f7aa48f988ad8d9369396ecc 2fbb5fe2e29a4d70aa5854ce7ce3e20b [] []
[2020-02-26 10:22:46] messenger.INFO: Sending message Shopware\Core\Content\Sitemap\ScheduledTask\SitemapMessage with Enqueue\MessengerAdapter\QueueInteropTransport {"message":"[object] (Shopware\\Core\\Content\\Sitemap\\ScheduledTask\\SitemapMessage: {})","class":"Shopware\\Core\\Content\\Sitemap\\ScheduledTask\\SitemapMessage","sender":"Enqueue\\MessengerAdapter\\QueueInteropTransport"} []
[2020-02-26 10:22:46] messenger.INFO: Message Shopware\Core\Content\Sitemap\ScheduledTask\SitemapMessage handled by Shopware\Core\Content\Sitemap\ScheduledTask\SitemapGenerateTaskHandler::__invoke {"message":"[object] (Shopware\\Core\\Content\\Sitemap\\ScheduledTask\\SitemapMessage: {})","class":"Shopware\\Core\\Content\\Sitemap\\ScheduledTask\\SitemapMessage","handler":"Shopware\\Core\\Content\\Sitemap\\ScheduledTask\\SitemapGenerateTaskHandler::__invoke"} []
[2020-02-26 10:22:46] messenger.INFO: Received message Shopware\Core\Content\Sitemap\ScheduledTask\SitemapMessage {"message":"[object] (Shopware\\Core\\Content\\Sitemap\\ScheduledTask\\SitemapMessage: {})","class":"Shopware\\Core\\Content\\Sitemap\\ScheduledTask\\SitemapMessage"} []
[2020-02-26 10:22:46] app.DEBUG: continue with last used saleschannel 2ae0ed25f7aa48f988ad8d9369396ecc 2fbb5fe2e29a4d70aa5854ce7ce3e20b [] []
[2020-02-26 10:22:46] messenger.INFO: Sending message Shopware\Core\Content\Sitemap\ScheduledTask\SitemapMessage with Enqueue\MessengerAdapter\QueueInteropTransport {"message":"[object] (Shopware\\Core\\Content\\Sitemap\\ScheduledTask\\SitemapMessage: {})","class":"Shopware\\Core\\Content\\Sitemap\\ScheduledTask\\SitemapMessage","sender":"Enqueue\\MessengerAdapter\\QueueInteropTransport"} []
[2020-02-26 10:22:46] messenger.INFO: Message Shopware\Core\Content\Sitemap\ScheduledTask\SitemapMessage handled by Shopware\Core\Content\Sitemap\ScheduledTask\SitemapGenerateTaskHandler::__invoke {"message":"[object] (Shopware\\Core\\Content\\Sitemap\\ScheduledTask\\SitemapMessage: {})","class":"Shopware\\Core\\Content\\Sitemap\\ScheduledTask\\SitemapMessage","handler":"Shopware\\Core\\Content\\Sitemap\\ScheduledTask\\SitemapGenerateTaskHandler::__invoke"} []
[2020-02-26 10:22:46] messenger.INFO: Received message Shopware\Core\Content\Sitemap\ScheduledTask\SitemapMessage {"message":"[object] (Shopware\\Core\\Content\\Sitemap\\ScheduledTask\\SitemapMessage: {})","class":"Shopware\\Core\\Content\\Sitemap\\ScheduledTask\\SitemapMessage"} []
[2020-02-26 10:22:46] messenger.INFO: Sending message Shopware\Core\Content\Sitemap\ScheduledTask\SitemapMessage with Enqueue\MessengerAdapter\QueueInteropTransport {"message":"[object] (Shopware\\Core\\Content\\Sitemap\\ScheduledTask\\SitemapMessage: {})","class":"Shopware\\Core\\Content\\Sitemap\\ScheduledTask\\SitemapMessage","sender":"Enqueue\\MessengerAdapter\\QueueInteropTransport"} []
[2020-02-26 10:22:46] messenger.INFO: Message Shopware\Core\Content\Sitemap\ScheduledTask\SitemapMessage handled by Shopware\Core\Content\Sitemap\ScheduledTask\SitemapGenerateTaskHandler::__invoke {"message":"[object] (Shopware\\Core\\Content\\Sitemap\\ScheduledTask\\SitemapMessage: {})","class":"Shopware\\Core\\Content\\Sitemap\\ScheduledTask\\SitemapMessage","handler":"Shopware\\Core\\Content\\Sitemap\\ScheduledTask\\SitemapGenerateTaskHandler::__invoke"} []
[2020-02-26 10:22:46] messenger.IN

sieht nach irgendwas mit der Sitemap aus. Ein solcher “Schwung” an Logs folgt eigentlich jede einzelne Sekunde.

919×433 5.16 KB

2

Hast du zufälligerweise den DEV Modus in der .env Datei aktiviert? Dann wird im Debug Modus geloggt - stell mal am Besten auf “prod” um.

3

Hallo @AndreHerking‍

APP_ENV=dev

ja, unsere .env ist so eingestellt. Da wir ein normal installiertes Produkttivsystem haben, aber aktiv daran Plugins und Themes weiterentwickeln und integrieren. Es ist für uns nicht praktikabel, für jedes Projekt ein “echtes” Dev-System zu machen.

Ist natürlich trotzdem blöd, wenn dann der Server während der Umsetzung dauert zugemüllt wird. Kann man das Loggin einschränken?

4

Eine Einstellung gibt es da speziell nicht - solltest du aber jetzt den Scheduled Task Runner am Laufen haben, müsste der die Logs täglich löschen. Dafür gibt’s zumindestens einen Task https://github.com/shopware/platform/blob/6.1/src/Core/Framework/Log/ScheduledTask/LogCleanupTask.php

5

Scheduled Task Runner am Laufen haben

muss ich dafür speziell was einstellen oder reicht, wenn ich via Server-Cronjob über die CLI: bin/console scheduled-task:run ausführe?

6

Es reicht wenn du über Server Cronjob den Befehl ausführen lässt. Bei mir hat er zumindest gerade die alten Log Einträge entfernt, sollte also dann auch bei dir klappen.

7

Hallo zusammen,

ich würd mich hier gerne mal anhängen. Wir haben auf einem Testsystem (momten auch dev-Modus) ständig (unter Sekundentakt) Messages in der enque Tabelle, und zwar:

\Sitemap\ScheduledTask\SitemapMessage

Das führt dazu dass der Server quasi durchgehend einen Core nur dazu verwendet auf diese Nachrichten zu pollen und diese abzuarbeiten. Der folgende Post:

POST /api/v2/_action/message-queue/consume

 Belegt einen Apachen mit 90% CPU Load.

Bei der Sitemap Generierung haben wir nichts umgestellt.

Kann mir irgendjemand erklären wo diese ständigen Messages herkommen?

(es sind 4 solche Messages die in enqueue geinserted werden pro Sekunde. Der Aufbau der Sitemap steht aber auch „manuell“.

 

1 „Gefällt mir“
8

Hallo zusammen, 

ich habe ebenfalls das Problem, dass im Prod-System die CPU-Last auf annähernd 100% steht und die Sitemap-Generierung permanent läuft. 

Der AdminWorker wurde nach Anleitung in der Dokumentation in config/packages/shopware.yaml ausgeschaltet und einen Hintergrunddienst läuft bis zur RAM-Limitierung oder Zeitlimitierung

bin/console messenger:consume laufen. Hierbei sieht man dauerhaft Sitemap-Messages durch die Logs rasseln. Das ist vermutlich nicht so gewollt.

Edit: messenger:consume eingefügt

1 „Gefällt mir“
9

Wir haben ebenfalls ab jetzt „enable_admin_worker“ auf „false“ gesetzt, und stattdessen zwei Cronjobs eingerichtet:

*/5 * * * * shopware/bin/console scheduled-task:run --time-limit=30 >>shopware/var/log/crontab.log 2>&1
*/5 * * * * shopware/bin/console messenger:consume --time-limit=30 >>shopware/var/log/crontab.log 2>&1

Seit kurzem folgende ständig wiederholende Fehler:

WARNING [php] Warning: file_get_contents(/tmp/sitemap-1.xml.gz): failed to open stream: No such file or directory ["exception" => ErrorException { …}]

Edit: das passiert wohl wenn „enable_admin_worker“ auf „true“ steht, während jemand im  Backend eingeloggt ist und zeitgleich der cronjob läuft.

Ein Blick in /tmp zeigt mir zwei riesige sitemap-category Zips:

13:09:47 c-157 ~ $ ll /tmp/sitemap-*
-rw-rw-r-- 1 web-user web-user 11K May 19 16:21 /tmp/sitemap-category-1.xml.gz
-rw-r--r-- 1 web-user web-user 2.4G May 19 16:23 /tmp/sitemap-category-2.xml.gz
-rw-r--r-- 1 web-user web-user 2.1G May 19 16:23 /tmp/sitemap-category-3.xml.gz
-rw-r--r-- 1 web-user web-user 120 May 18 16:21 /tmp/sitemap-custom-1.xml.gz
-rw-r--r-- 1 web-user web-user 387 May 18 16:21 /tmp/sitemap-product-1.xml.gz

Die Frage ist nur woher und warum es permanent diese SitemapMessages gibt.

1 „Gefällt mir“
10

Wir haben hier das gleiche Problem. Es rasseln ständig Sitemap Messages durch die Queue.

16:46:24 INFO      [messenger] Message Shopware\Core\Content\Sitemap\ScheduledTask\SitemapMessage handled by Shopware\Core\Content\Sitemap\ScheduledTask\SitemapGenerateTaskHandler::__invoke [„message“ => Shopware\Core\Content\Sitemap\ScheduledTask\SitemapMessage^ { …},„class“ => „Shopware\Core\Content\Sitemap\ScheduledTask\SitemapMessage“,„handler“ => „Shopwar
e\Core\Content\Sitemap\ScheduledTask\SitemapGenerateTaskHandler::__invoke“]                                                                                                                                                                                                                                                                                                
16:46:24 INFO      [messenger] Shopware\Core\Content\Sitemap\ScheduledTask\SitemapMessage was handled successfully (acknowledging to transport). [„message“ => Shopware\Core\Content\Sitemap\ScheduledTask\SitemapMessage^ { …},„class“ => „Shopware\Core\Content\Sitemap\ScheduledTask\SitemapMessage“]
16:46:24 INFO      [messenger] Received message Shopware\Core\Content\Sitemap\ScheduledTask\SitemapMessage [„message“ => Shopware\Core\Content\Sitemap\ScheduledTask\SitemapMessage^ { …},„class“ => „Shopware\Core\Content\Sitemap\ScheduledTask\SitemapMessage“]
16:46:24 INFO      [messenger] Sending message Shopware\Core\Content\Sitemap\ScheduledTask\SitemapMessage with Enqueue\MessengerAdapter\QueueInteropTransport [„message“ => Shopware\Core\Content\Sitemap\ScheduledTask\SitemapMessage^ { …},„class“ => „Shopware\Core\Content\Sitemap\ScheduledTask\SitemapMessage“,„sender“ => „Enqueue\MessengerAdapter\QueueInteropTra
nsport“]                                                                                                                                                                                                                                                                                                                                                                   
16:46:24 INFO      [messenger] Message Shopware\Core\Content\Sitemap\ScheduledTask\SitemapMessage handled by Shopware\Core\Content\Sitemap\ScheduledTask\SitemapGenerateTaskHandler::__invoke [„message“ => Shopware\Core\Content\Sitemap\ScheduledTask\SitemapMessage^ { …},„class“ => „Shopware\Core\Content\Sitemap\ScheduledTask\SitemapMessage“,„handler“ => „Shopwar
e\Core\Content\Sitemap\ScheduledTask\SitemapGenerateTaskHandler::__invoke“]                                                                                                                                                                                                                                                                                                
16:46:24 INFO      [messenger] Shopware\Core\Content\Sitemap\ScheduledTask\SitemapMessage was handled successfully (acknowledging to transport). [„message“ => Shopware\Core\Content\Sitemap\ScheduledTask\SitemapMessage^ { …},„class“ => „Shopware\Core\Content\Sitemap\ScheduledTask\SitemapMessage“]
16:46:24 INFO      [messenger] Received message Shopware\Core\Content\Sitemap\ScheduledTask\SitemapMessage [„message“ => Shopware\Core\Content\Sitemap\ScheduledTask\SitemapMessage^ { …},„class“ => „Shopware\Core\Content\Sitemap\ScheduledTask\SitemapMessage“]
16:46:25 INFO      [messenger] Sending message Shopware\Core\Content\Sitemap\ScheduledTask\SitemapMessage with Enqueue\MessengerAdapter\QueueInteropTransport [„message“ => Shopware\Core\Content\Sitemap\ScheduledTask\SitemapMessage^ { …},„class“ => „Shopware\Core\Content\Sitemap\ScheduledTask\SitemapMessage“,„sender“ => „Enqueue\MessengerAdapter\QueueInteropTra
nsport“] 

Gibt es dafür eine Lösung?

11

@hw_dwalter schrieb:

Wir haben hier das gleiche Problem. Es rasseln ständig Sitemap Messages durch die Queue.

16:46:24 INFO      [messenger] Message Shopware\Core\Content\Sitemap\ScheduledTask\SitemapMessage handled by Shopware\Core\Content\Sitemap\ScheduledTask\SitemapGenerateTaskHandler::__invoke [„message“ => Shopware\Core\Content\Sitemap\ScheduledTask\SitemapMessage^ { …},„class“ => „Shopware\Core\Content\Sitemap\ScheduledTask\SitemapMessage“,„handler“ => „Shopwar
e\Core\Content\Sitemap\ScheduledTask\SitemapGenerateTaskHandler::__invoke“]                                                                                                                                                                                                                                                                                                
16:46:24 INFO      [messenger] Shopware\Core\Content\Sitemap\ScheduledTask\SitemapMessage was handled successfully (acknowledging to transport). [„message“ => Shopware\Core\Content\Sitemap\ScheduledTask\SitemapMessage^ { …},„class“ => „Shopware\Core\Content\Sitemap\ScheduledTask\SitemapMessage“]
16:46:24 INFO      [messenger] Received message Shopware\Core\Content\Sitemap\ScheduledTask\SitemapMessage [„message“ => Shopware\Core\Content\Sitemap\ScheduledTask\SitemapMessage^ { …},„class“ => „Shopware\Core\Content\Sitemap\ScheduledTask\SitemapMessage“]
16:46:24 INFO      [messenger] Sending message Shopware\Core\Content\Sitemap\ScheduledTask\SitemapMessage with Enqueue\MessengerAdapter\QueueInteropTransport [„message“ => Shopware\Core\Content\Sitemap\ScheduledTask\SitemapMessage^ { …},„class“ => „Shopware\Core\Content\Sitemap\ScheduledTask\SitemapMessage“,„sender“ => „Enqueue\MessengerAdapter\QueueInteropTra
nsport“]                                                                                                                                                                                                                                                                                                                                                                   
16:46:24 INFO      [messenger] Message Shopware\Core\Content\Sitemap\ScheduledTask\SitemapMessage handled by Shopware\Core\Content\Sitemap\ScheduledTask\SitemapGenerateTaskHandler::__invoke [„message“ => Shopware\Core\Content\Sitemap\ScheduledTask\SitemapMessage^ { …},„class“ => „Shopware\Core\Content\Sitemap\ScheduledTask\SitemapMessage“,„handler“ => „Shopwar
e\Core\Content\Sitemap\ScheduledTask\SitemapGenerateTaskHandler::__invoke“]                                                                                                                                                                                                                                                                                                
16:46:24 INFO      [messenger] Shopware\Core\Content\Sitemap\ScheduledTask\SitemapMessage was handled successfully (acknowledging to transport). [„message“ => Shopware\Core\Content\Sitemap\ScheduledTask\SitemapMessage^ { …},„class“ => „Shopware\Core\Content\Sitemap\ScheduledTask\SitemapMessage“]
16:46:24 INFO      [messenger] Received message Shopware\Core\Content\Sitemap\ScheduledTask\SitemapMessage [„message“ => Shopware\Core\Content\Sitemap\ScheduledTask\SitemapMessage^ { …},„class“ => „Shopware\Core\Content\Sitemap\ScheduledTask\SitemapMessage“]
16:46:25 INFO      [messenger] Sending message Shopware\Core\Content\Sitemap\ScheduledTask\SitemapMessage with Enqueue\MessengerAdapter\QueueInteropTransport [„message“ => Shopware\Core\Content\Sitemap\ScheduledTask\SitemapMessage^ { …},„class“ => „Shopware\Core\Content\Sitemap\ScheduledTask\SitemapMessage“,„sender“ => „Enqueue\MessengerAdapter\QueueInteropTra
nsport“] 

Gibt es dafür eine Lösung?

Wir haben genau das gleiche Problem… Wären also auch sehr interessiert, ob hier jemand eine Info zu hat.