@@ -714,6 +714,228 @@ which, when run, produces something like:
714
714
2010-09-06 22:38:15,301 d.e.f DEBUG IP: 123.231.231.123 User: fred A message at DEBUG level with 2 parameters
715
715
2010-09-06 22:38:15,301 d.e.f INFO IP: 123.231.231.123 User: fred A message at INFO level with 2 parameters
716
716
717
+ Use of ``contextvars ``
718
+ ----------------------
719
+
720
+ Since Python 3.7, the :mod: `contextvars ` module has provided context-local storage
721
+ which works for both :mod: `threading ` and :mod: `asyncio ` processing needs. This type
722
+ of storage may thus be generally preferable to thread-locals. The following example
723
+ shows how, in a multi-threaded environment, logs can populated with contextual
724
+ information such as, for example, request attributes handled by web applications.
725
+
726
+ For the purposes of illustration, say that you have different web applications, each
727
+ independent of the other but running in the same Python process and using a library
728
+ common to them. How can each of these applications have their own log, where all
729
+ logging messages from the library (and other request processing code) are directed to
730
+ the appropriate application's log file, while including in the log additional
731
+ contextual information such as client IP, HTTP request method and client username?
732
+
733
+ Let's assume that the library can be simulated by the following code:
734
+
735
+ .. code-block :: python
736
+
737
+ # webapplib.py
738
+ import logging
739
+ import time
740
+
741
+ logger = logging.getLogger(__name__ )
742
+
743
+ def useful ():
744
+ # Just a representative event logged from the library
745
+ logger.debug(' Hello from webapplib!' )
746
+ # Just sleep for a bit so other threads get to run
747
+ time.sleep(0.01 )
748
+
749
+ We can simulate the multiple web applications by means of two simple classes,
750
+ ``Request `` and ``WebApp ``. These simulate how real threaded web applications work -
751
+ each request is handled by a thread:
752
+
753
+ .. code-block :: python
754
+
755
+ # main.py
756
+ import argparse
757
+ from contextvars import ContextVar
758
+ import logging
759
+ import os
760
+ from random import choice
761
+ import threading
762
+ import webapplib
763
+
764
+ logger = logging.getLogger(__name__ )
765
+ root = logging.getLogger()
766
+ root.setLevel(logging.DEBUG )
767
+
768
+ class Request :
769
+ """
770
+ A simple dummy request class which just holds dummy HTTP request method,
771
+ client IP address and client username
772
+ """
773
+ def __init__ (self , method , ip , user ):
774
+ self .method = method
775
+ self .ip = ip
776
+ self .user = user
777
+
778
+ # A dummy set of requests which will be used in the simulation - we'll just pick
779
+ # from this list randomly. Note that all GET requests are from 192.168.2.XXX
780
+ # addresses, whereas POST requests are from 192.16.3.XXX addresses. Three users
781
+ # are represented in the sample requests.
782
+
783
+ REQUESTS = [
784
+ Request(' GET' , ' 192.168.2.20' , ' jim' ),
785
+ Request(' POST' , ' 192.168.3.20' , ' fred' ),
786
+ Request(' GET' , ' 192.168.2.21' , ' sheila' ),
787
+ Request(' POST' , ' 192.168.3.21' , ' jim' ),
788
+ Request(' GET' , ' 192.168.2.22' , ' fred' ),
789
+ Request(' POST' , ' 192.168.3.22' , ' sheila' ),
790
+ ]
791
+
792
+ # Note that the format string includes references to request context information
793
+ # such as HTTP method, client IP and username
794
+
795
+ formatter = logging.Formatter(' %(threadName)-11s %(appName)s %(name)-9s %(user)-6s %(ip)s %(method)-4s %(message)s ' )
796
+
797
+ # Create our context variables. These will be filled at the start of request
798
+ # processing, and used in the logging that happens during that processing
799
+
800
+ ctx_request = ContextVar(' request' )
801
+ ctx_appname = ContextVar(' appname' )
802
+
803
+ class InjectingFilter (logging .Filter ):
804
+ """
805
+ A filter which injects context-specific information into logs and ensures
806
+ that only information for a specific webapp is included in its log
807
+ """
808
+ def __init__ (self , app ):
809
+ self .app = app
810
+
811
+ def filter (self , record ):
812
+ request = ctx_request.get()
813
+ record.method = request.method
814
+ record.ip = request.ip
815
+ record.user = request.user
816
+ record.appName = appName = ctx_appname.get()
817
+ return appName == self .app.name
818
+
819
+ class WebApp :
820
+ """
821
+ A dummy web application class which has its own handler and filter for a
822
+ webapp-specific log.
823
+ """
824
+ def __init__ (self , name ):
825
+ self .name = name
826
+ handler = logging.FileHandler(name + ' .log' , ' w' )
827
+ f = InjectingFilter(self )
828
+ handler.setFormatter(formatter)
829
+ handler.addFilter(f)
830
+ root.addHandler(handler)
831
+ self .num_requests = 0
832
+
833
+ def process_request (self , request ):
834
+ """
835
+ This is the dummy method for processing a request. It's called on a
836
+ different thread for every request. We store the context information into
837
+ the context vars before doing anything else.
838
+ """
839
+ ctx_request.set(request)
840
+ ctx_appname.set(self .name)
841
+ self .num_requests += 1
842
+ logger.debug(' Request processing started' )
843
+ webapplib.useful()
844
+ logger.debug(' Request processing finished' )
845
+
846
+ def main ():
847
+ fn = os.path.splitext(os.path.basename(__file__ ))[0 ]
848
+ adhf = argparse.ArgumentDefaultsHelpFormatter
849
+ ap = argparse.ArgumentParser(formatter_class = adhf, prog = fn,
850
+ description = ' Simulate a couple of web '
851
+ ' applications handling some '
852
+ ' requests, showing how request '
853
+ ' context can be used to '
854
+ ' populate logs' )
855
+ aa = ap.add_argument
856
+ aa(' --count' , ' -c' , default = 100 , help = ' How many requests to simulate' )
857
+ options = ap.parse_args()
858
+
859
+ # Create the dummy webapps and put them in a list which we can use to select
860
+ # from randomly
861
+ app1 = WebApp(' app1' )
862
+ app2 = WebApp(' app2' )
863
+ apps = [app1, app2]
864
+ threads = []
865
+ # Add a common handler which will capture all events
866
+ handler = logging.FileHandler(' app.log' , ' w' )
867
+ handler.setFormatter(formatter)
868
+ root.addHandler(handler)
869
+
870
+ # Generate calls to process requests
871
+ for i in range (options.count):
872
+ try :
873
+ # Pick an app at random and a request for it to process
874
+ app = choice(apps)
875
+ request = choice(REQUESTS )
876
+ # Process the request in its own thread
877
+ t = threading.Thread(target = app.process_request, args = (request,))
878
+ threads.append(t)
879
+ t.start()
880
+ except KeyboardInterrupt :
881
+ break
882
+
883
+ # Wait for the threads to terminate
884
+ for t in threads:
885
+ t.join()
886
+
887
+ for app in apps:
888
+ print (' %s processed %s requests' % (app.name, app.num_requests))
889
+
890
+ if __name__ == ' __main__' :
891
+ main()
892
+
893
+ If you run the above, you should find that roughly half the requests go
894
+ into :file: `app1.log ` and the rest into :file: `app2.log `, and the all the requests are
895
+ logged to :file: `app.log `. Each webapp-specific log will contain only log entries for
896
+ only that webapp, and the request information will be displayed consistently in the
897
+ log (i.e. the information in each dummy request will always appear together in a log
898
+ line). This is illustrated by the following shell output:
899
+
900
+ .. code-block :: shell
901
+
902
+ ~ /logging-contextual-webapp$ python main.py
903
+ app1 processed 51 requests
904
+ app2 processed 49 requests
905
+ ~ /logging-contextual-webapp$ wc -l * .log
906
+ 153 app1.log
907
+ 147 app2.log
908
+ 300 app.log
909
+ 600 total
910
+ ~ /logging-contextual-webapp$ head -3 app1.log
911
+ Thread-3 (process_request) app1 __main__ jim 192.168.3.21 POST Request processing started
912
+ Thread-3 (process_request) app1 webapplib jim 192.168.3.21 POST Hello from webapplib!
913
+ Thread-5 (process_request) app1 __main__ jim 192.168.3.21 POST Request processing started
914
+ ~ /logging-contextual-webapp$ head -3 app2.log
915
+ Thread-1 (process_request) app2 __main__ sheila 192.168.2.21 GET Request processing started
916
+ Thread-1 (process_request) app2 webapplib sheila 192.168.2.21 GET Hello from webapplib!
917
+ Thread-2 (process_request) app2 __main__ jim 192.168.2.20 GET Request processing started
918
+ ~ /logging-contextual-webapp$ head app.log
919
+ Thread-1 (process_request) app2 __main__ sheila 192.168.2.21 GET Request processing started
920
+ Thread-1 (process_request) app2 webapplib sheila 192.168.2.21 GET Hello from webapplib!
921
+ Thread-2 (process_request) app2 __main__ jim 192.168.2.20 GET Request processing started
922
+ Thread-3 (process_request) app1 __main__ jim 192.168.3.21 POST Request processing started
923
+ Thread-2 (process_request) app2 webapplib jim 192.168.2.20 GET Hello from webapplib!
924
+ Thread-3 (process_request) app1 webapplib jim 192.168.3.21 POST Hello from webapplib!
925
+ Thread-4 (process_request) app2 __main__ fred 192.168.2.22 GET Request processing started
926
+ Thread-5 (process_request) app1 __main__ jim 192.168.3.21 POST Request processing started
927
+ Thread-4 (process_request) app2 webapplib fred 192.168.2.22 GET Hello from webapplib!
928
+ Thread-6 (process_request) app1 __main__ jim 192.168.3.21 POST Request processing started
929
+ ~ /logging-contextual-webapp$ grep app1 app1.log | wc -l
930
+ 153
931
+ ~ /logging-contextual-webapp$ grep app2 app2.log | wc -l
932
+ 147
933
+ ~ /logging-contextual-webapp$ grep app1 app.log | wc -l
934
+ 153
935
+ ~ /logging-contextual-webapp$ grep app2 app.log | wc -l
936
+ 147
937
+
938
+
717
939
Imparting contextual information in handlers
718
940
--------------------------------------------
719
941
0 commit comments