CSV出力時にメモリを使い切ってしまう問題を修正

[chihiro-adachi]

概要(Overview・Refs Issue)

#4775 の対応
商品・カテゴリ・受注・会員CSVを対応しました。

方針(Policy)

monologの出力バッファでメモリを使い切っていたため、CSV出力時はログ出力を無効化するように修正しています。

実装に関する補足(Appendix)

テスト（Test)

• memory_limit 128MBで商品点数 15,262件/15,262件を出力できることを確認

相談（Discussion）

マイナーバージョン互換性保持のための制限事項チェックリスト

• 既存機能の仕様変更
• フックポイントの呼び出しタイミングの変更
• フックポイントのパラメータの削除・データ型の変更
• twigファイルに渡しているパラメータの削除・データ型の変更
• Serviceクラスの公開関数の、引数の削除・データ型の変更
• 入出力ファイル(CSVなど)のフォーマット変更

レビュワー確認項目

• 動作確認
• コードレビュー
• E2E/Unit テスト確認(テストの追加・変更が必要かどうか)
• 互換性が保持されているか
• セキュリティ上の問題がないか

[kiy0taka]

@chihiro-adachi ログ出力を無効化しているということはエラー発生時にもログが出ないことになるのでしょうか？

[chihiro-adachi]

@kiy0taka
いえ、無効化しているのはdeperecatedが出力されるphpチャネルのみなので、その他のログはエラー時にも出力されます。
ログを比較すると以下のようになります。

修正前

[2020-12-23 09:17:59] admin.INFO [N/A] [54c9ece] [N/A] [Eccube\Log\Logger:log:64] - INIT [] [GET, /admin/product/export, 127.0.0.1, http://127.0.0.1:8080/admin/product, Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.88 Safari/537.36]
[2020-12-23 09:17:59] request.INFO [N/A] [54c9ece] [N/A] [Symfony\Component\HttpKernel\EventListener\RouterListener:onKernelRequest:123] - Matched route "admin_product_export". {"route":"admin_product_export","route_parameters":{"_controller":"Eccube\\Controller\\Admin\\Product\\ProductController::export","_route":"admin_product_export"},"request_uri":"http://127.0.0.1:8080/admin/product/export","method":"GET"} [GET, /admin/product/export, 127.0.0.1, http://127.0.0.1:8080/admin/product, Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.88 Safari/537.36]
[2020-12-23 09:17:59] security.DEBUG [c38a36aa] [54c9ece] [N/A] [Symfony\Component\Security\Http\Firewall\ContextListener:handle:101] - Read existing security token from the session. {"key":"_security_admin","token_class":"Symfony\\Component\\Security\\Core\\Authentication\\Token\\UsernamePasswordToken"} [GET, /admin/product/export, 127.0.0.1, http://127.0.0.1:8080/admin/product, Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.88 Safari/537.36]
[2020-12-23 09:17:59] security.DEBUG [c38a36aa] [54c9ece] [N/A] [Symfony\Component\Security\Http\Firewall\ContextListener:refreshUser:214] - User was reloaded from a user provider. {"provider":"Eccube\\Security\\Core\\User\\MemberProvider","username":"admin"} [GET, /admin/product/export, 127.0.0.1, http://127.0.0.1:8080/admin/product, Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.88 Safari/537.36]
[2020-12-23 09:17:59] admin.INFO [c38a36aa] [54c9ece] [1] [Eccube\Log\Logger:log:64] - PROCESS START ["admin_product_export"] [GET, /admin/product/export, 127.0.0.1, http://127.0.0.1:8080/admin/product, Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.88 Safari/537.36]
[2020-12-23 09:17:59] admin.DEBUG [c38a36aa] [54c9ece] [1] [Eccube\Log\Logger:log:64] - Begin Transaction. [] [GET, /admin/product/export, 127.0.0.1, http://127.0.0.1:8080/admin/product, Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.88 Safari/537.36]
[2020-12-23 09:17:59] admin.INFO [c38a36aa] [54c9ece] [1] [Eccube\Log\Logger:log:64] - LOGIC START ["admin_product_export"] [GET, /admin/product/export, 127.0.0.1, http://127.0.0.1:8080/admin/product, Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.88 Safari/537.36]
[2020-12-23 09:18:00] php.INFO [c38a36aa] [54c9ece] [1] [Symfony\Component\Debug\ErrorHandler:handleError:532] - User Deprecated: The Eccube\Util\EntityUtil::isNotEmpty method is deprecated. {"exception":"[object] (ErrorException(code: 0): User Deprecated: The Eccube\\Util\\EntityUtil::isNotEmpty method is deprecated. at /Users/chihiro_adachi/repos/eccube4/src/Eccube/Util/EntityUtil.php:68)"} [GET, /admin/product/export, 127.0.0.1, http://127.0.0.1:8080/admin/product, Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.88 Safari/537.36]
[2020-12-23 09:18:00] php.INFO [c38a36aa] [54c9ece] [1] [Symfony\Component\Debug\ErrorHandler:handleError:532] - User Deprecated: The Eccube\Util\EntityUtil::isEmpty method is deprecated. {"exception":"[object] (ErrorException(code: 0): User Deprecated: The Eccube\\Util\\EntityUtil::isEmpty method is deprecated. at /Users/chihiro_adachi/repos/eccube4/src/Eccube/Util/EntityUtil.php:40)"} [GET, /admin/product/export, 127.0.0.1, http://127.0.0.1:8080/admin/product, Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.88 Safari/537.36]
[2020-12-23 09:18:00] php.INFO [c38a36aa] [54c9ece] [1] [Symfony\Component\Debug\ErrorHandler:handleError:532] - User Deprecated: The Eccube\Util\EntityUtil::isNotEmpty method is deprecated. {"exception":"[object] (ErrorException(code: 0): User Deprecated: The Eccube\\Util\\EntityUtil::isNotEmpty method is deprecated. at /Users/chihiro_adachi/repos/eccube4/src/Eccube/Util/EntityUtil.php:68)"} [GET, /admin/product/export, 127.0.0.1, http://127.0.0.1:8080/admin/product, Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.88 Safari/537.36]
[2020-12-23 09:18:00] php.INFO [c38a36aa] [54c9ece] [1] [Symfony\Component\Debug\ErrorHandler:handleError:532] - User Deprecated: The Eccube\Util\EntityUtil::isEmpty method is deprecated. {"exception":"[object] (ErrorException(code: 0): User Deprecated: The Eccube\\Util\\EntityUtil::isEmpty method is deprecated. at /Users/chihiro_adachi/repos/eccube4/src/Eccube/Util/EntityUtil.php:40)"} [GET, /admin/product/export, 127.0.0.1, http://127.0.0.1:8080/admin/product, Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.88 Safari/537.36]
[2020-12-23 09:18:00] php.INFO [c38a36aa] [54c9ece] [1] [Symfony\Component\Debug\ErrorHandler:handleError:532] - User Deprecated: The Eccube\Util\EntityUtil::isNotEmpty method is deprecated. {"exception":"[object] (ErrorException(code: 0): User Deprecated: The Eccube\\Util\\EntityUtil::isNotEmpty method is deprecated. at /Users/chihiro_adachi/repos/eccube4/src/Eccube/Util/EntityUtil.php:68)"} [GET, /admin/product/export, 127.0.0.1, http://127.0.0.1:8080/admin/product, Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.88 Safari/537.36]
[2020-12-23 09:18:00] php.INFO [c38a36aa] [54c9ece] [1] [Symfony\Component\Debug\ErrorHandler:handleError:532] - User Deprecated: The Eccube\Util\EntityUtil::isEmpty method is deprecated. {"exception":"[object] (ErrorException(code: 0): User Deprecated: The Eccube\\Util\\EntityUtil::isEmpty method is deprecated. at /Users/chihiro_adachi/repos/eccube4/src/Eccube/Util/EntityUtil.php:40)"} [GET, /admin/product/export, 127.0.0.1, http://127.0.0.1:8080/admin/product, Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.88 Safari/537.36]
[2020-12-23 09:18:00] php.INFO [c38a36aa] [54c9ece] [1] [Symfony\Component\Debug\ErrorHandler:handleError:532] - User Deprecated: The Eccube\Util\EntityUtil::isNotEmpty method is deprecated. {"exception":"[object] (ErrorException(code: 0): User Deprecated: The Eccube\\Util\\EntityUtil::isNotEmpty method is deprecated. at /Users/chihiro_adachi/repos/eccube4/src/Eccube/Util/EntityUtil.php:68)"} [GET, /admin/product/export, 127.0.0.1, http://127.0.0.1:8080/admin/product, Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.88 Safari/537.36]
[2020-12-23 09:18:00] php.INFO [c38a36aa] [54c9ece] [1] [Symfony\Component\Debug\ErrorHandler:handleError:532] - User Deprecated: The Eccube\Util\EntityUtil::isEmpty method is deprecated. {"exception":"[object] (ErrorException(code: 0): User Deprecated: The Eccube\\Util\\EntityUtil::isEmpty method is deprecated. at /Users/chihiro_adachi/repos/eccube4/src/Eccube/Util/EntityUtil.php:40)"} [GET, /admin/product/export, 127.0.0.1, http://127.0.0.1:8080/admin/product, Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.88 Safari/537.36]
[2020-12-23 09:18:00] php.INFO [c38a36aa] [54c9ece] [1] [Symfony\Component\Debug\ErrorHandler:handleError:532] - User Deprecated: Method Doctrine\ORM\EntityManager::detach() is deprecated and will be removed in Doctrine ORM 3.0. {"exception":"[object] (ErrorException(code: 0): User Deprecated: Method Doctrine\\ORM\\EntityManager::detach() is deprecated and will be removed in Doctrine ORM 3.0. at /Users/chihiro_adachi/repos/eccube4/vendor/doctrine/orm/lib/Doctrine/ORM/EntityManager.php:673)"} [GET, /admin/product/export, 127.0.0.1, http://127.0.0.1:8080/admin/product, Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.88 Safari/537.36]
[2020-12-23 09:18:00] php.INFO [c38a36aa] [54c9ece] [1] [Symfony\Component\Debug\ErrorHandler:handleError:532] - User Deprecated: The Eccube\Util\EntityUtil::isNotEmpty method is deprecated. {"exception":"[object] (ErrorException(code: 0): User Deprecated: The Eccube\\Util\\EntityUtil::isNotEmpty method is deprecated. at /Users/chihiro_adachi/repos/eccube4/src/Eccube/Util/EntityUtil.php:68)"} [GET, /admin/product/export, 127.0.0.1, http://127.0.0.1:8080/admin/product, Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.88 Safari/537.36]
...
[2020-12-23 09:18:03] php.CRITICAL [c38a36aa] [54c9ece] [1] [Symfony\Component\Debug\ErrorHandler:handleException:584] - Fatal Error: Allowed memory size of 134217728 bytes exhausted (tried to allocate 1310720 bytes) {"exception":"[object] (Symfony\\Component\\Debug\\Exception\\OutOfMemoryException(code: 0): Error: Allowed memory size of 134217728 bytes exhausted (tried to allocate 1310720 bytes) at /Users/chihiro_adachi/repos/eccube4/vendor/doctrine/orm/lib/Doctrine/ORM/UnitOfWork.php:2673)"} [GET, /admin/product/export, 127.0.0.1, http://127.0.0.1:8080/admin/product, Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.88 Safari/537.36]
[2020-12-23 09:18:04] admin.ERROR [c38a36aa] [54c9ece] [1] [Eccube\Log\Logger:log:64] - システムエラーが発生しました。 ["Error: Allowed memory size of 134217728 bytes exhausted (tried to allocate 1310720 bytes)","/Users/chihiro_adachi/repos/eccube4/vendor/doctrine/orm/lib/Doctrine/ORM/UnitOfWork.php",2673,"#0 {main}"] [GET, /admin/product/export, 127.0.0.1, http://127.0.0.1:8080/admin/product, Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.88 Safari/537.36]
[2020-12-23 09:18:04] admin.INFO [c38a36aa] [54c9ece] [1] [Eccube\Log\Logger:log:64] - LOGIC END ["admin_product_export"] [GET, /admin/product/export, 127.0.0.1, http://127.0.0.1:8080/admin/product, Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.88 Safari/537.36]
[2020-12-23 09:18:04] security.DEBUG [c38a36aa] [54c9ece] [1] [Symfony\Component\Security\Http\Firewall\ContextListener:onKernelResponse:150] - Stored the security token in the session. {"key":"_security_admin"} [GET, /admin/product/export, 127.0.0.1, http://127.0.0.1:8080/admin/product, Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.88 Safari/537.36]
[2020-12-23 09:18:04] app.INFO [N/A] [54c9ece] [1] [Eccube\Log\Logger:log:68] - PROCESS END ["admin_product_export"] [GET, /admin/product/export, 127.0.0.1, http://127.0.0.1:8080/admin/product, Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.88 Safari/537.36]
[2020-12-23 09:18:04] app.DEBUG [N/A] [54c9ece] [1] [Eccube\Log\Logger:log:68] - Commit executed. [] [GET, /admin/product/export, 127.0.0.1, http://127.0.0.1:8080/admin/product, Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.88 Safari/537.36]

修正後(メモリのエラーは発生しないので、max_executin_timeを設定して代替)

[2020-12-23 09:05:18] admin.INFO [N/A] [f7fd93f] [N/A] [Eccube\Log\Logger:log:64] - INIT [] [GET, /admin/product/export, 127.0.0.1, http://127.0.0.1:8080/admin/product, Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.88 Safari/537.36]
[2020-12-23 09:05:18] request.INFO [N/A] [f7fd93f] [N/A] [Symfony\Component\HttpKernel\EventListener\RouterListener:onKernelRequest:123] - Matched route "admin_product_export". {"route":"admin_product_export","route_parameters":{"_controller":"Eccube\\Controller\\Admin\\Product\\ProductController::export","_route":"admin_product_export"},"request_uri":"http://127.0.0.1:8080/admin/product/export","method":"GET"} [GET, /admin/product/export, 127.0.0.1, http://127.0.0.1:8080/admin/product, Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.88 Safari/537.36]
[2020-12-23 09:05:18] security.DEBUG [c38a36aa] [f7fd93f] [N/A] [Symfony\Component\Security\Http\Firewall\ContextListener:handle:101] - Read existing security token from the session. {"key":"_security_admin","token_class":"Symfony\\Component\\Security\\Core\\Authentication\\Token\\UsernamePasswordToken"} [GET, /admin/product/export, 127.0.0.1, http://127.0.0.1:8080/admin/product, Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.88 Safari/537.36]
[2020-12-23 09:05:18] security.DEBUG [c38a36aa] [f7fd93f] [N/A] [Symfony\Component\Security\Http\Firewall\ContextListener:refreshUser:214] - User was reloaded from a user provider. {"provider":"Eccube\\Security\\Core\\User\\MemberProvider","username":"admin"} [GET, /admin/product/export, 127.0.0.1, http://127.0.0.1:8080/admin/product, Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.88 Safari/537.36]
[2020-12-23 09:05:18] admin.INFO [c38a36aa] [f7fd93f] [1] [Eccube\Log\Logger:log:64] - PROCESS START ["admin_product_export"] [GET, /admin/product/export, 127.0.0.1, http://127.0.0.1:8080/admin/product, Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.88 Safari/537.36]
[2020-12-23 09:05:18] admin.DEBUG [c38a36aa] [f7fd93f] [1] [Eccube\Log\Logger:log:64] - Begin Transaction. [] [GET, /admin/product/export, 127.0.0.1, http://127.0.0.1:8080/admin/product, Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.88 Safari/537.36]
[2020-12-23 09:05:18] admin.INFO [c38a36aa] [f7fd93f] [1] [Eccube\Log\Logger:log:64] - LOGIC START ["admin_product_export"] [GET, /admin/product/export, 127.0.0.1, http://127.0.0.1:8080/admin/product, Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.88 Safari/537.36]
[2020-12-23 09:05:18] php.INFO [c38a36aa] [f7fd93f] [1] [Symfony\Component\Debug\ErrorHandler:handleError:532] - User Deprecated: The "monolog.logger.php" service is private, getting it from the container is deprecated since Symfony 3.2 and will fail in 4.0. You should either make the service public, or stop using the container directly and use dependency injection instead. {"exception":"[object] (ErrorException(code: 0): User Deprecated: The \"monolog.logger.php\" service is private, getting it from the container is deprecated since Symfony 3.2 and will fail in 4.0. You should either make the service public, or stop using the container directly and use dependency injection instead. at /Users/chihiro_adachi/repos/eccube4/vendor/symfony/dependency-injection/Container.php:282)"} [GET, /admin/product/export, 127.0.0.1, http://127.0.0.1:8080/admin/product, Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.88 Safari/537.36]
[2020-12-23 09:05:32] admin.ERROR [c38a36aa] [f7fd93f] [1] [Eccube\Log\Logger:log:64] - システムエラーが発生しました。 ["Error: Maximum execution time of 10 seconds exceeded","/Users/chihiro_adachi/repos/eccube4/vendor/doctrine/dbal/lib/Doctrine/DBAL/Driver/PDOStatement.php",117,"#0 {main}"] [GET, /admin/product/export, 127.0.0.1, http://127.0.0.1:8080/admin/product, Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.88 Safari/537.36]
[2020-12-23 09:05:32] admin.INFO [c38a36aa] [f7fd93f] [1] [Eccube\Log\Logger:log:64] - LOGIC END ["admin_product_export"] [GET, /admin/product/export, 127.0.0.1, http://127.0.0.1:8080/admin/product, Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.88 Safari/537.36]
[2020-12-23 09:05:32] security.DEBUG [c38a36aa] [f7fd93f] [1] [Symfony\Component\Security\Http\Firewall\ContextListener:onKernelResponse:150] - Stored the security token in the session. {"key":"_security_admin"} [GET, /admin/product/export, 127.0.0.1, http://127.0.0.1:8080/admin/product, Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.88 Safari/537.36]
[2020-12-23 09:05:32] app.INFO [N/A] [f7fd93f] [1] [Eccube\Log\Logger:log:68] - PROCESS END ["admin_product_export"] [GET, /admin/product/export, 127.0.0.1, http://127.0.0.1:8080/admin/product, Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.88 Safari/537.36]
[2020-12-23 09:05:32] app.DEBUG [N/A] [f7fd93f] [1] [Eccube\Log\Logger:log:68] - Commit executed. [] [GET, /admin/product/export, 127.0.0.1, http://127.0.0.1:8080/admin/product, Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.88 Safari/537.36]

[chihiro-adachi]

@kiy0taka
#4815 でログ出力をいじらず、trigger_errorを回避する修正を行いました。
ただこちらの修正だと、メモリエラーは発生するようです キャッシュの問題でした。どちらも15,000件超のCSVを出力可能でした。

[kiy0taka]

#4815 を採用しました。