Setup celery logging

[tomaszszymanski129]

I want to merge this change because it sets up logging of celery so we can reference particular async task by ID / name of task.

when task succeeds and contains logging:

{"asctime": "2021-05-07T10:56:46Z", "levelname": "INFO", "celeryTaskId": "bfc58e8f-35b2-42c2-b015-33fb164a1f9f", "celeryTaskName": "saleor.product.thumbnails.create_product_thumbnails", "message": "Creating thumbnails for 120", "hostname": "linuz"} 

{"asctime": "2021-05-07T10:56:46Z", "levelname": "INFO", "celeryTaskId": "bfc58e8f-35b2-42c2-b015-33fb164a1f9f", "celeryTaskName": "saleor.product.thumbnails.create_product_thumbnails", "message": "Created 6 thumbnails", "hostname": "linuz"} 

{"asctime": "2021-05-07T10:56:46Z", "levelname": "INFO", "celeryTaskId": "bfc58e8f-35b2-42c2-b015-33fb164a1f9f", "celeryTaskName": "saleor.product.thumbnails.create_product_thumbnails", "celeryTaskRuntime": 0.12916755300102523, "hostname": "linuz"}

So we see logs entry sharing same celeryTaskId, first two contains messages, last one even contains celeryTaskRuntime so we can easily know how long it took

In case task fails during execution we see:

{"asctime": "2021-05-07T11:00:22Z", "levelname": "ERROR", "celeryTaskId": "12d1a7e3-f7bf-43ba-91d2-e73a1a7de7d1", "celeryTaskName": "saleor.product.thumbnails.create_product_thumbnails", "exc_info": "Here we see the traceback", "hostname": "linuz"}

Impact

• New migrations
• New/Updated API fields or mutations
• Deprecated API fields or mutations
• Removed API types, fields, or mutations
• Documentation needs to be updated

Pull Request Checklist

• Privileged queries and mutations are guarded by proper permission checks
• Database queries are optimized and the number of queries is constant
• Database migration files are up to date
• The changes are tested
• GraphQL schema and type definitions are up to date
• Changes are mentioned in the changelog

[patrys]

Task linked: SALEOR-2855 Have JSON logging in Celery

[db-queries]

Here is the report for a2885df (mirumee:SALEOR-2855-json-celery-logging)
Base comparison is 1b7ca01.

No differences were found.

# saleor.graphql.accountbenchmark account
  test name                                                  	left count 	right count	duplicate count
  -----------------------------------------------------------	-----------	-----------	---------------
  delete staff members                                       	         32	         32	              0
  query staff user                                           	         18	         18	              3
  staff create                                               	         23	         23	              3
  staff update groups and permissions                        	         32	         32	              4

# saleor.graphql.accountbenchmark permission group
  test name                                                  	left count 	right count	duplicate count
  -----------------------------------------------------------	-----------	-----------	---------------
  permission group create                                    	         19	         19	              2
  permission group delete                                    	         20	         20	              3
  permission group query                                     	          7	          7	              0
  permission group update                                    	         33	         33	              1
  permission group update remove users with manage staff     	         27	         27	              3

# saleor.graphql.attributebenchmark attribute
  test name                                                  	left count 	right count	duplicate count
  -----------------------------------------------------------	-----------	-----------	---------------
  attribute translation                                      	          5	          5	              0
  attribute value translation                                	         26	         26	              0
  query attribute                                            	          6	          6	              0
  query attributes                                           	          8	          8	              0

# saleor.graphql.checkoutbenchmark checkout mutations
  test name                                                  	left count 	right count	duplicate count
  -----------------------------------------------------------	-----------	-----------	---------------
  add billing address to checkout                            	         51	         51	              5
  add checkout lines                                         	         49	         49	              8
  add shipping to checkout                                   	         64	         64	              9
  checkout email update                                      	         25	         25	              0
  checkout payment charge                                    	         42	         42	             16
  checkout shipping address update                           	         69	         69	             13
  checkout voucher code                                      	         70	         70	             12
  complete checkout                                          	        109	        109	             13
  complete checkout with single line                         	        111	        111	             13
  create checkout                                            	         73	         73	             12
  customer complete checkout                                 	        155	        155	             42
  update checkout lines                                      	         51	         51	              8

# saleor.graphql.checkoutbenchmark homepage
  test name                                                  	left count 	right count	duplicate count
  -----------------------------------------------------------	-----------	-----------	---------------
  user checkout details                                      	         41	         41	              2

# saleor.graphql.discountbenchmark sales
  test name                                                  	left count 	right count	duplicate count
  -----------------------------------------------------------	-----------	-----------	---------------
  sales query with channel slug                              	         16	         16	              0
  sales query withot channel slug                            	         15	         15	              0

# saleor.graphql.discountbenchmark vouchers
  test name                                                  	left count 	right count	duplicate count
  -----------------------------------------------------------	-----------	-----------	---------------
  vouchers query with channel slug                           	         16	         16	              0
  vouchers query withot channel slug                         	         15	         15	              0

# saleor.graphql.orderbenchmark fulfillment refund and return products
  test name                                                  	left count 	right count	duplicate count
  -----------------------------------------------------------	-----------	-----------	---------------
  fulfillment refund products order lines                    	         53	         53	              2
  fulfillment return products order lines                    	        101	        101	             14

# saleor.graphql.orderbenchmark order
  test name                                                  	left count 	right count	duplicate count
  -----------------------------------------------------------	-----------	-----------	---------------
  staff multiple draft orders                                	        432	        432	            337
  staff multiple orders                                      	        152	        152	             76
  staff order details                                        	         46	         46	              7
  user order details                                         	         42	         42	              7

# saleor.graphql.pagebenchmark page type
  test name                                                  	left count 	right count	duplicate count
  -----------------------------------------------------------	-----------	-----------	---------------
  query page type                                            	         19	         19	              7
  query page types                                           	         25	         25	             12

# saleor.graphql.productbenchmark category
  test name                                                  	left count 	right count	duplicate count
  -----------------------------------------------------------	-----------	-----------	---------------
  categories children                                        	          3	          3	              0
  category delete                                            	        108	        108	             27
  category view                                              	         27	         27	              1

# saleor.graphql.productbenchmark collection
  test name                                                  	left count 	right count	duplicate count
  -----------------------------------------------------------	-----------	-----------	---------------
  collection add products                                    	         44	         44	             10
  collection bulk delete                                     	         51	         51	             10
  collection view                                            	          6	          6	              0
  create collection                                          	         47	         47	             12
  delete collection                                          	         46	         46	             11
  remove products from collection                            	         41	         41	             10
  retrieve collection channel listings                       	          4	          4	              0

# saleor.graphql.productbenchmark homepage
  test name                                                  	left count 	right count	duplicate count
  -----------------------------------------------------------	-----------	-----------	---------------
  report product sales                                       	         10	         10	              3
  retrieve product list                                      	          4	          4	              0

# saleor.graphql.productbenchmark product
  test name                                                  	left count 	right count	duplicate count
  -----------------------------------------------------------	-----------	-----------	---------------
  filter products by attributes                              	          9	          9	              0
  filter products by boolean attributes                      	         19	         19	              0
  filter products by numeric attributes                      	         18	         18	              0
  product create                                             	         70	         70	              3
  product details                                            	         31	         31	              0
  product translations                                       	          5	          5	              0
  retrieve channel listings                                  	         19	         19	              0
  retrieve product attributes                                	          9	          9	              0
  retrieve product images                                    	          4	          4	              0
  retrieve product media                                     	          4	          4	              0
  retrive products with product types and attributes         	          7	          7	              0
  update product                                             	         46	         46	              4

# saleor.graphql.productbenchmark product variant channel listing update
  test name                                                  	left count 	right count	duplicate count
  -----------------------------------------------------------	-----------	-----------	---------------
  variant channel listing update                             	         50	         50	              5

# saleor.graphql.productbenchmark variant
  test name                                                  	left count 	right count	duplicate count
  -----------------------------------------------------------	-----------	-----------	---------------
  product variant bulk create                                	         63	         63	              2
  product variant create                                     	         75	         75	              6
  retrieve variant list                                      	         25	         25	              0
  update product variant                                     	         79	         79	             12

# saleor.graphql.productbenchmark variant stocks
  test name                                                  	left count 	right count	duplicate count
  -----------------------------------------------------------	-----------	-----------	---------------
  product variants stocks create                             	         22	         22	              5
  product variants stocks delete                             	         19	         19	              5
  product variants stocks update                             	         27	         27	              5
  query product variants stocks                              	         14	         14	              4

# saleor.graphql.producttest product sorting attributes
  test name                                                  	left count 	right count	duplicate count
  -----------------------------------------------------------	-----------	-----------	---------------
  sort product not having attribute data                     	         23	         23	              0

# saleor.graphql.shippingbenchmark shipping methods
  test name                                                  	left count 	right count	duplicate count
  -----------------------------------------------------------	-----------	-----------	---------------
  vouchers query with channel slug                           	         10	         10	              0
  vouchers query without channel slug                        	          9	          9	              0

# saleor.graphql.shopbenchmark homepage
  test name                                                  	left count 	right count	duplicate count
  -----------------------------------------------------------	-----------	-----------	---------------
  retrieve shop                                              	          6	          6	              0

[codecov]

Codecov Report

Merging #7251 (a2885df) into master (1b7ca01) will decrease coverage by 0.01%.
The diff coverage is 66.66%.

@@            Coverage Diff             @@
##           master    #7251      +/-   ##
==========================================
- Coverage   93.33%   93.31%   -0.02%     
==========================================
  Files         460      460              
  Lines       34815    34835      +20     
  Branches     3582     3583       +1     
==========================================
+ Hits        32496    32508      +12     
- Misses       1607     1615       +8     
  Partials      712      712              

Impacted Files	Coverage Δ
saleor/settings.py	72.68% <ø> (ø)
saleor/core/logging.py	57.89% <45.45%> (-17.11%)	⬇️
saleor/celeryconf.py	81.25% <71.42%> (-7.64%)	⬇️
saleor/plugins/avatax/tasks.py	90.90% <75.00%> (ø)
saleor/core/utils/__init__.py	87.50% <80.00%> (ø)
saleor/plugins/webhook/tasks.py	92.45% <100.00%> (+0.14%)	⬆️

---

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 1b7ca01...a2885df. Read the comment docs.

[NyanKiyoshi]

Not everything is logged in JSON:

[2021-04-29 10:29:28,444: INFO/MainProcess] Received task: saleor.foo[taskID]
[2021-04-29 10:29:48,556: INFO/ForkPoolWorker-1] Creating thumbnails for  1

[patrys]

Task linked: SALEOR-3518 Error on saving long pages

[tomaszszymanski129]

Seems to be all working now.
Messages like "Received task: ...id" should no longer appear - however updated environment is necessary - we've bumped celery from 5.0.5 to 5.1.0 and that solved it.
There are two loggers defined for celery.app.trace that handles celery internal logs and celery.task defined for task logging.
Tasks have to use task_logger instead of logger to log things properly, couldn't really find more generic solution (and this approach is stated in celery docs).

CC @NyanKiyoshi