Review logging (dev and prod settings) #124

samlesu · 2020-01-24T16:05:06Z

add a log for each request done to the ledger
no more calls to root logger (logging.info(...)), use a module logger instead: it will allow better logging configuration and tuning
review dev settings for log configuration:
- remove mail and file handlers: they are not used in dev mode
- add substrapp logger
- set custom configuration for external library when needed (hfc,
  celery, ...)
- ensure all emitted logs to the console have the same formatters (in all services)
review prod settings for log configuration
- remove unused handlers and formatters
- update default formatter
add settings/env variables to:
- disable SQL query logs
- disable worker printing tuple workerspace

jmorel

Thanks, this should help greatly when debugging the platform. We'll need to decide what to do precisely with prod settings, but otherwise 👍

samlesu · 2020-01-27T15:35:47Z

⚠️ Without printing SQL queries and without printing worker workspaces.

Prod examples

Without printing SQL queries and without printing worker workspaces:

server:

substra-backend INFO 2020-01-27 15:28:08,812 substrapp.ledger_utils 74 140549382207232 smartcontract query:queryCompositeAlgos; elaps=40.70ms; error=None
substra-backend [pid: 74|app: 0|req: 35/124] 10.1.3.150 () {46 vars in 767 bytes} [Mon Jan 27 15:28:08 2020] GET /composite_algo/ => generated 2757 bytes in 59 msecs (HTTP/1.1 200) 5 headers in 157 bytes (1 switches on core 1)
substra-backend [pid: 82|app: 0|req: 20/125] 10.1.3.150 () {48 vars in 769 bytes} [Mon Jan 27 15:28:08 2020] POST /api-token-auth/ => generated 79 bytes in 105 msecs (HTTP/1.1 200) 5 headers in 136 bytes (1 switches on core 0)
substra-backend INFO 2020-01-27 15:28:09,192 substrapp.ledger_utils 92 140549781981056 smartcontract query:queryAlgos; elaps=42.24ms; error=None
substra-backend [pid: 92|app: 0|req: 47/126] 10.1.3.150 () {46 vars in 747 bytes} [Mon Jan 27 15:28:09 2020] GET /algo/ => generated 10047 bytes in 59 msecs (HTTP/1.1 200) 5 headers in 158 bytes (1 switches on core 0)
substra-backend [pid: 82|app: 0|req: 21/127] 10.1.3.150 () {48 vars in 769 bytes} [Mon Jan 27 15:28:09 2020] POST /api-token-auth/ => generated 80 bytes in 107 msecs (HTTP/1.1 200) 5 headers in 136 bytes (1 switches on core 1)
substra-backend INFO 2020-01-27 15:28:09,546 substrapp.ledger_utils 74 140549781981056 smartcontract query:queryAggregateAlgos; elaps=29.43ms; error=None
substra-backend [pid: 74|app: 0|req: 36/128] 10.1.3.150 () {46 vars in 767 bytes} [Mon Jan 27 15:28:09 2020] GET /aggregate_algo/ => generated 4 bytes in 61 msecs (HTTP/1.1 200) 5 headers in 154 bytes (1 switches on core 0)
substra-backend [pid: 92|app: 0|req: 48/129] 10.1.3.150 () {48 vars in 769 bytes} [Mon Jan 27 15:28:09 2020] POST /api-token-auth/ => generated 80 bytes in 82 msecs (HTTP/1.1 200) 5 headers in 136 bytes (1 switches on core 1)
substra-backend INFO 2020-01-27 15:28:09,809 substrapp.ledger_utils 82 140549781981056 smartcontract query:queryAggregatetuples; elaps=19.53ms; error=None
substra-backend [pid: 82|app: 0|req: 22/130] 10.1.3.150 () {46 vars in 767 bytes} [Mon Jan 27 15:28:09 2020] GET /aggregatetuple/ => generated 4 bytes in 31 msecs (HTTP/1.1 200) 5 headers in 154 bytes (1 switches on core 0)
substra-backend [pid: 74|app: 0|req: 37/131] 10.1.3.150 () {48 vars in 769 bytes} [Mon Jan 27 15:28:09 2020] POST /api-token-auth/ => generated 80 bytes in 76 msecs (HTTP/1.1 200) 5 headers in 136 bytes (1 switches on core 1)
substra-backend INFO 2020-01-27 15:28:10,082 substrapp.ledger_utils 74 140549781981056 smartcontract query:queryCompositeAlgos; elaps=28.17ms; error=None
substra-backend [pid: 74|app: 0|req: 38/132] 10.1.3.150 () {46 vars in 767 bytes} [Mon Jan 27 15:28:10 2020] GET /composite_algo/ => generated 2757 bytes in 54 msecs (HTTP/1.1 200) 5 headers in 157 bytes (1 switches on core 0)

Note: the different log formats for the requests/apps is due to the usage of uwsgi.

worker

INFO 2020-01-27 15:27:45,342 substrapp.tasks.tasks 33 139625782822720 Prepare materials for traintuple task
INFO 2020-01-27 15:27:45,383 substrapp.ledger_utils 33 139625782822720 smartcontract query:queryAlgo; elaps=22.49ms; error=None
INFO 2020-01-27 15:27:45,713 substrapp.tasks.tasks 33 139625782822720 Prepare materials for traintuple task: success
INFO 2020-01-27 15:27:46,798 substrapp.tasks.utils 33 139625782822720 [traintuple_ab1f2522_train] Traceback (most recent call last):
INFO 2020-01-27 15:27:46,798 substrapp.tasks.utils 33 139625782822720 [traintuple_ab1f2522_train]   File "algo.py", line 30, in <module>
INFO 2020-01-27 15:27:46,798 substrapp.tasks.utils 33 139625782822720 [traintuple_ab1f2522_train]     raise Exception("Intentionally keep on failing until we have failed 2 time(s). The algo has now             failed " + str(counter) + " time(s).")
INFO 2020-01-27 15:27:46,798 substrapp.tasks.utils 33 139625782822720 [traintuple_ab1f2522_train] Exception: Intentionally keep on failing until we have failed 2 time(s). The algo has now             failed 1 time(s).
INFO 2020-01-27 15:27:46,799 substrapp.tasks.utils 33 139625782822720 [traintuple_ab1f2522_train]
INFO 2020-01-27 15:27:46,832 substrapp.tasks.tasks 33 139625782822720 Remove subtuple materials
INFO 2020-01-27 15:27:50,077 substrapp.tasks.tasks 33 139625782822720 Prepare materials for traintuple task

Dev examples

server

substra-backend INFO - 2020-01-27 15:34:16,261 - substrapp.ledger_utils - smartcontract invoke:registerDataSample; elaps=87.13ms; error=None
substra-backend INFO - 2020-01-27 15:34:16,277 - django.server - "POST /data_sample/ HTTP/1.1" 201 200
substra-backend INFO - 2020-01-27 15:34:16,490 - substrapp.ledger_utils - smartcontract query:createTraintuple; elaps=22.37ms; error=None
substra-backend INFO - 2020-01-27 15:34:16,564 - events.apps - Processing task 0543d7b8a532211c60176cb826d908da3b3716768191194f00e96fec67792699: type=traintuple status=todo
substra-backend INFO - 2020-01-27 15:34:16,584 - substrapp.ledger_utils - smartcontract invoke:createTraintuple; elaps=93.47ms; error=None
substra-backend INFO - 2020-01-27 15:34:16,586 - django.server - "POST /traintuple/ HTTP/1.1" 201 77
substra-backend INFO - 2020-01-27 15:34:16,643 - substrapp.ledger_utils - smartcontract query:queryTraintuple; elaps=33.06ms; error=None
substra-backend INFO - 2020-01-27 15:34:16,646 - django.server - "GET /traintuple/0543d7b8a532211c60176cb826d908da3b3716768191194f00e96fec67792699/ HTTP/1.1" 200 784
substra-backend INFO - 2020-01-27 15:34:17,199 - substrapp.ledger_utils - smartcontract query:queryTraintuple; elaps=28.44ms; error=None
substra-backend INFO - 2020-01-27 15:34:17,200 - django.server - "GET /traintuple/0543d7b8a532211c60176cb826d908da3b3716768191194f00e96fec67792699/ HTTP/1.1" 200 785
substra-backend INFO - 2020-01-27 15:34:17,756 - substrapp.ledger_utils - smartcontract query:queryTraintuple; elaps=40.00ms; error=None
substra-backend INFO - 2020-01-27 15:34:17,761 - django.server - "GET /traintuple/0543d7b8a532211c60176cb826d908da3b3716768191194f00e96fec67792699/ HTTP/1.1" 200 785

worker

INFO - 2020-01-27 15:33:42,507 - substrapp.ledger_utils - smartcontract invoke:logStartTrain; elaps=68.53ms; error=None
INFO - 2020-01-27 15:33:42,538 - substrapp.tasks.tasks - Prepare materials for traintuple task
INFO - 2020-01-27 15:33:42,574 - substrapp.ledger_utils - smartcontract query:queryAlgo; elaps=24.69ms; error=None
INFO - 2020-01-27 15:33:42,932 - substrapp.ledger_utils - smartcontract query:queryModelDetails; elaps=39.66ms; error=None
INFO - 2020-01-27 15:33:43,187 - substrapp.ledger_utils - smartcontract query:queryModelDetails; elaps=25.91ms; error=None
INFO - 2020-01-27 15:33:43,423 - substrapp.tasks.tasks - Prepare materials for traintuple task: success
INFO - 2020-01-27 15:33:44,272 - substrapp.tasks.utils - [traintuple_edea3b8a_train]
INFO - 2020-01-27 15:33:44,307 - substrapp.tasks.tasks - Remove subtuple materials

jmorel

I'm more than fine with the changes, but maybe someone who participated in creating the previous conf should weigh in.

Kelvin-M · 2020-01-29T10:30:54Z

Need to be rebased @samlesu

- add a log for each request done to the ledger - no more calls to root logger (logging.info(...)), use a module logger instead: it will allow better logs configuration and tuning - review debug log configuration: - remove mail and file handlers: they are not used in dev mode - add substrapp logger - set custom configuration for external library when needed (hfc, celery, ...) - add settings/env variables to: - disable SQL query logss - disable worker printing tuple workerspace

- remove unused handlers

samlesu · 2020-01-29T10:35:11Z

Need to be rebased @samlesu

Thanks, done.

Kelvin-M · 2020-01-29T10:52:27Z

I let you merge if you think it's the log level you need to debug :)

samlesu · 2020-01-29T10:57:26Z

I let you merge if you think it's the log level you need to debug :)

Could you be more precise? Do you think we should increase or decrease some logger levels in dev or prod settings ?

Kelvin-M · 2020-01-29T10:59:17Z

Nope, all I mean is, if you do not need to make any change to the log level feel free to merge ! I don't know if you're still ajusting the log level :)

samlesu · 2020-01-29T11:02:28Z

Nope, all I mean is, if you do not need to make any change to the log level feel free to merge ! I don't know if you're still ajusting the log level :)

Thanks for the clarification ! I think this PR is great start to improve our logs in dev and production. It will have to be updated according to our needs. I will be happy to merge once I have an approval from either you, @inalgnu, or @GuillaumeCisco before merging.

inelgnu

thank you @samlesu 👍

GuillaumeCisco · 2020-01-29T13:25:20Z

backend/substrapp/tasks/utils.py

@@ -182,6 +182,8 @@ def container_format_log(container_name, container_logs):


 def list_files(startpath):
+    if not settings.TASK['LIST_WORKSPACE']:
+        return


We should never return nothing.
Why not simply use if settings.TASK['LIST_WORKSPACE']:

backend/backend/settings/common.py

samlesu requested review from inelgnu, jmorel and Kelvin-M January 24, 2020 16:05

samlesu changed the title ~~logs all request to ledger~~ logs all requests to ledger Jan 24, 2020

jmorel previously approved these changes Jan 27, 2020

View reviewed changes

samlesu dismissed jmorel’s stale review via d361e2c January 27, 2020 10:54

samlesu force-pushed the logs-and-logs branch 3 times, most recently from 45d47a4 to b887d27 Compare January 27, 2020 14:13

samlesu marked this pull request as ready for review January 27, 2020 15:36

samlesu requested a review from GuillaumeCisco as a code owner January 27, 2020 15:36

samlesu requested review from jmorel and thibaultrobert January 27, 2020 15:36

samlesu changed the title ~~logs all requests to ledger~~ Review logging (dev and prod settings) Jan 27, 2020

jmorel previously approved these changes Jan 28, 2020

View reviewed changes

samlesu added 2 commits January 29, 2020 11:34

update prod logging settings

648f917

- remove unused handlers

samlesu dismissed jmorel’s stale review via 648f917 January 29, 2020 10:34

samlesu force-pushed the logs-and-logs branch from 6294957 to 648f917 Compare January 29, 2020 10:34

jmorel approved these changes Jan 29, 2020

View reviewed changes

inelgnu approved these changes Jan 29, 2020

View reviewed changes

samlesu merged commit 5b784a4 into master Jan 29, 2020

GuillaumeCisco reviewed Jan 29, 2020

View reviewed changes

samlesu deleted the logs-and-logs branch January 29, 2020 13:37

This was referenced Apr 13, 2020

Worker: missing information in logs #214

Closed

Don't swallow celery logs #213

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Review logging (dev and prod settings) #124

Review logging (dev and prod settings) #124

samlesu commented Jan 24, 2020 •

edited

Loading

jmorel left a comment

samlesu commented Jan 27, 2020 •

edited

Loading

jmorel left a comment

Kelvin-M commented Jan 29, 2020

samlesu commented Jan 29, 2020

Kelvin-M commented Jan 29, 2020

samlesu commented Jan 29, 2020

Kelvin-M commented Jan 29, 2020

samlesu commented Jan 29, 2020

inelgnu left a comment

GuillaumeCisco Jan 29, 2020

Review logging (dev and prod settings) #124

Review logging (dev and prod settings) #124

Conversation

samlesu commented Jan 24, 2020 • edited Loading

jmorel left a comment

Choose a reason for hiding this comment

samlesu commented Jan 27, 2020 • edited Loading

Prod examples

server:

worker

Dev examples

server

worker

jmorel left a comment

Choose a reason for hiding this comment

Kelvin-M commented Jan 29, 2020

samlesu commented Jan 29, 2020

Kelvin-M commented Jan 29, 2020

samlesu commented Jan 29, 2020

Kelvin-M commented Jan 29, 2020

samlesu commented Jan 29, 2020

inelgnu left a comment

Choose a reason for hiding this comment

GuillaumeCisco Jan 29, 2020

Choose a reason for hiding this comment

samlesu commented Jan 24, 2020 •

edited

Loading

samlesu commented Jan 27, 2020 •

edited

Loading