Mercurial > public > mercurial-scm > hg-stable

comparison mercurial/util.py @ 37047:d3a9036d9ae9

Find changesets by keywords (author, files, the commit message), revision number or hash, or revset expression.
util: don't log low-level I/O calls for HTTP peer `hg debugwireproto` is useful for testing HTTP interactions. Possibly more useful than `get-with-headers.py`. But one thing that makes it annoying for mid-level tests is that it logs all API calls, such as readline(). This makes output - especially headers - overly verbose. This commit teaches our file and socket observers to not log API calls on functions dealing with data. We change the behavior of `hg debugwireproto` to enable this mode by default. --debug can be added to restore the previous behavior. As the test changes demonstrate, this makes tests much easier to read. As a bonus, it also removes some required (glob) over lengths in system call results. One thing that's lacking is knowing which side sent data. But we can fix this in a follow-up once it becomes a problem. Differential Revision: https://phab.mercurial-scm.org/D2842
author Gregory Szorc <gregory.szorc@gmail.com>
date Tue, 13 Mar 2018 11:20:07 -0700
parents 8453699a1f21
children 8c3c47362934
comparison
equal deleted inserted replaced
37046:a8d8cdafe29c 37047:d3a9036d9ae9
760 # proxy using our observer. 760 # proxy using our observer.
761 observer = object.__getattribute__(self, r'_observer') 761 observer = object.__getattribute__(self, r'_observer')
762 return makeloggingfileobject(observer.fh, res, observer.name, 762 return makeloggingfileobject(observer.fh, res, observer.name,
763 reads=observer.reads, 763 reads=observer.reads,
764 writes=observer.writes, 764 writes=observer.writes,
765 logdata=observer.logdata) 765 logdata=observer.logdata,
766 logdataapis=observer.logdataapis)
766 767
767 def recv(self, *args, **kwargs): 768 def recv(self, *args, **kwargs):
768 return object.__getattribute__(self, r'_observedcall')( 769 return object.__getattribute__(self, r'_observedcall')(
769 r'recv', *args, **kwargs) 770 r'recv', *args, **kwargs)
770 771
823 return DATA_ESCAPE_RE.sub(lambda m: DATA_ESCAPE_MAP[m.group(0)], s) 824 return DATA_ESCAPE_RE.sub(lambda m: DATA_ESCAPE_MAP[m.group(0)], s)
824 825
825 class baseproxyobserver(object): 826 class baseproxyobserver(object):
826 def _writedata(self, data): 827 def _writedata(self, data):
827 if not self.logdata: 828 if not self.logdata:
828 self.fh.write('\n') 829 if self.logdataapis:
830 self.fh.write('\n')
831 self.fh.flush()
832 return
833
834 # Simple case writes all data on a single line.
835 if b'\n' not in data:
836 if self.logdataapis:
837 self.fh.write(': %s\n' % escapedata(data))
838 else:
839 self.fh.write('%s> %s\n' % (self.name, escapedata(data)))
829 self.fh.flush() 840 self.fh.flush()
830 return 841 return
831 842
832 # Simple case writes all data on a single line.
833 if b'\n' not in data:
834 self.fh.write(': %s\n' % escapedata(data))
835 self.fh.flush()
836 return
837
838 # Data with newlines is written to multiple lines. 843 # Data with newlines is written to multiple lines.
839 self.fh.write(':\n') 844 if self.logdataapis:
845 self.fh.write(':\n')
846
840 lines = data.splitlines(True) 847 lines = data.splitlines(True)
841 for line in lines: 848 for line in lines:
842 self.fh.write('%s> %s\n' % (self.name, escapedata(line))) 849 self.fh.write('%s> %s\n' % (self.name, escapedata(line)))
843 self.fh.flush() 850 self.fh.flush()
844 851
845 class fileobjectobserver(baseproxyobserver): 852 class fileobjectobserver(baseproxyobserver):
846 """Logs file object activity.""" 853 """Logs file object activity."""
847 def __init__(self, fh, name, reads=True, writes=True, logdata=False): 854 def __init__(self, fh, name, reads=True, writes=True, logdata=False,
855 logdataapis=True):
848 self.fh = fh 856 self.fh = fh
849 self.name = name 857 self.name = name
850 self.logdata = logdata 858 self.logdata = logdata
859 self.logdataapis = logdataapis
851 self.reads = reads 860 self.reads = reads
852 self.writes = writes 861 self.writes = writes
853 862
854 def read(self, res, size=-1): 863 def read(self, res, size=-1):
855 if not self.reads: 864 if not self.reads:
856 return 865 return
857 # Python 3 can return None from reads at EOF instead of empty strings. 866 # Python 3 can return None from reads at EOF instead of empty strings.
858 if res is None: 867 if res is None:
859 res = '' 868 res = ''
860 869
861 self.fh.write('%s> read(%d) -> %d' % (self.name, size, len(res))) 870 if self.logdataapis:
871 self.fh.write('%s> read(%d) -> %d' % (self.name, size, len(res)))
872
862 self._writedata(res) 873 self._writedata(res)
863 874
864 def readline(self, res, limit=-1): 875 def readline(self, res, limit=-1):
865 if not self.reads: 876 if not self.reads:
866 return 877 return
867 878
868 self.fh.write('%s> readline() -> %d' % (self.name, len(res))) 879 if self.logdataapis:
880 self.fh.write('%s> readline() -> %d' % (self.name, len(res)))
881
869 self._writedata(res) 882 self._writedata(res)
870 883
871 def readinto(self, res, dest): 884 def readinto(self, res, dest):
872 if not self.reads: 885 if not self.reads:
873 return 886 return
874 887
875 self.fh.write('%s> readinto(%d) -> %r' % (self.name, len(dest), 888 if self.logdataapis:
876 res)) 889 self.fh.write('%s> readinto(%d) -> %r' % (self.name, len(dest),
890 res))
891
877 data = dest[0:res] if res is not None else b'' 892 data = dest[0:res] if res is not None else b''
878 self._writedata(data) 893 self._writedata(data)
879 894
880 def write(self, res, data): 895 def write(self, res, data):
881 if not self.writes: 896 if not self.writes:
884 # Python 2 returns None from some write() calls. Python 3 (reasonably) 899 # Python 2 returns None from some write() calls. Python 3 (reasonably)
885 # returns the integer bytes written. 900 # returns the integer bytes written.
886 if res is None and data: 901 if res is None and data:
887 res = len(data) 902 res = len(data)
888 903
889 self.fh.write('%s> write(%d) -> %r' % (self.name, len(data), res)) 904 if self.logdataapis:
905 self.fh.write('%s> write(%d) -> %r' % (self.name, len(data), res))
906
890 self._writedata(data) 907 self._writedata(data)
891 908
892 def flush(self, res): 909 def flush(self, res):
893 if not self.writes: 910 if not self.writes:
894 return 911 return
895 912
896 self.fh.write('%s> flush() -> %r\n' % (self.name, res)) 913 self.fh.write('%s> flush() -> %r\n' % (self.name, res))
897 914
898 # For observedbufferedinputpipe. 915 # For observedbufferedinputpipe.
899 def bufferedread(self, res, size): 916 def bufferedread(self, res, size):
900 self.fh.write('%s> bufferedread(%d) -> %d' % ( 917 if not self.reads:
901 self.name, size, len(res))) 918 return
919
920 if self.logdataapis:
921 self.fh.write('%s> bufferedread(%d) -> %d' % (
922 self.name, size, len(res)))
923
902 self._writedata(res) 924 self._writedata(res)
903 925
904 def bufferedreadline(self, res): 926 def bufferedreadline(self, res):
905 self.fh.write('%s> bufferedreadline() -> %d' % (self.name, len(res))) 927 if not self.reads:
928 return
929
930 if self.logdataapis:
931 self.fh.write('%s> bufferedreadline() -> %d' % (
932 self.name, len(res)))
933
906 self._writedata(res) 934 self._writedata(res)
907 935
908 def makeloggingfileobject(logh, fh, name, reads=True, writes=True, 936 def makeloggingfileobject(logh, fh, name, reads=True, writes=True,
909 logdata=False): 937 logdata=False, logdataapis=True):
910 """Turn a file object into a logging file object.""" 938 """Turn a file object into a logging file object."""
911 939
912 observer = fileobjectobserver(logh, name, reads=reads, writes=writes, 940 observer = fileobjectobserver(logh, name, reads=reads, writes=writes,
913 logdata=logdata) 941 logdata=logdata, logdataapis=logdataapis)
914 return fileobjectproxy(fh, observer) 942 return fileobjectproxy(fh, observer)
915 943
916 class socketobserver(baseproxyobserver): 944 class socketobserver(baseproxyobserver):
917 """Logs socket activity.""" 945 """Logs socket activity."""
918 def __init__(self, fh, name, reads=True, writes=True, states=True, 946 def __init__(self, fh, name, reads=True, writes=True, states=True,
919 logdata=False): 947 logdata=False, logdataapis=True):
920 self.fh = fh 948 self.fh = fh
921 self.name = name 949 self.name = name
922 self.reads = reads 950 self.reads = reads
923 self.writes = writes 951 self.writes = writes
924 self.states = states 952 self.states = states
925 self.logdata = logdata 953 self.logdata = logdata
954 self.logdataapis = logdataapis
926 955
927 def makefile(self, res, mode=None, bufsize=None): 956 def makefile(self, res, mode=None, bufsize=None):
928 if not self.states: 957 if not self.states:
929 return 958 return
930 959
933 962
934 def recv(self, res, size, flags=0): 963 def recv(self, res, size, flags=0):
935 if not self.reads: 964 if not self.reads:
936 return 965 return
937 966
938 self.fh.write('%s> recv(%d, %d) -> %d' % ( 967 if self.logdataapis:
939 self.name, size, flags, len(res))) 968 self.fh.write('%s> recv(%d, %d) -> %d' % (
969 self.name, size, flags, len(res)))
940 self._writedata(res) 970 self._writedata(res)
941 971
942 def recvfrom(self, res, size, flags=0): 972 def recvfrom(self, res, size, flags=0):
943 if not self.reads: 973 if not self.reads:
944 return 974 return
945 975
946 self.fh.write('%s> recvfrom(%d, %d) -> %d' % ( 976 if self.logdataapis:
947 self.name, size, flags, len(res[0]))) 977 self.fh.write('%s> recvfrom(%d, %d) -> %d' % (
978 self.name, size, flags, len(res[0])))
979
948 self._writedata(res[0]) 980 self._writedata(res[0])
949 981
950 def recvfrom_into(self, res, buf, size, flags=0): 982 def recvfrom_into(self, res, buf, size, flags=0):
951 if not self.reads: 983 if not self.reads:
952 return 984 return
953 985
954 self.fh.write('%s> recvfrom_into(%d, %d) -> %d' % ( 986 if self.logdataapis:
955 self.name, size, flags, res[0])) 987 self.fh.write('%s> recvfrom_into(%d, %d) -> %d' % (
988 self.name, size, flags, res[0]))
989
956 self._writedata(buf[0:res[0]]) 990 self._writedata(buf[0:res[0]])
957 991
958 def recv_into(self, res, buf, size=0, flags=0): 992 def recv_into(self, res, buf, size=0, flags=0):
959 if not self.reads: 993 if not self.reads:
960 return 994 return
961 995
962 self.fh.write('%s> recv_into(%d, %d) -> %d' % ( 996 if self.logdataapis:
963 self.name, size, flags, res)) 997 self.fh.write('%s> recv_into(%d, %d) -> %d' % (
998 self.name, size, flags, res))
999
964 self._writedata(buf[0:res]) 1000 self._writedata(buf[0:res])
965 1001
966 def send(self, res, data, flags=0): 1002 def send(self, res, data, flags=0):
967 if not self.writes: 1003 if not self.writes:
968 return 1004 return
973 1009
974 def sendall(self, res, data, flags=0): 1010 def sendall(self, res, data, flags=0):
975 if not self.writes: 1011 if not self.writes:
976 return 1012 return
977 1013
978 # Returns None on success. So don't bother reporting return value. 1014 if self.logdataapis:
979 self.fh.write('%s> sendall(%d, %d)' % ( 1015 # Returns None on success. So don't bother reporting return value.
980 self.name, len(data), flags)) 1016 self.fh.write('%s> sendall(%d, %d)' % (
1017 self.name, len(data), flags))
1018
981 self._writedata(data) 1019 self._writedata(data)
982 1020
983 def sendto(self, res, data, flagsoraddress, address=None): 1021 def sendto(self, res, data, flagsoraddress, address=None):
984 if not self.writes: 1022 if not self.writes:
985 return 1023 return
987 if address: 1025 if address:
988 flags = flagsoraddress 1026 flags = flagsoraddress
989 else: 1027 else:
990 flags = 0 1028 flags = 0
991 1029
992 self.fh.write('%s> sendto(%d, %d, %r) -> %d' % ( 1030 if self.logdataapis:
993 self.name, len(data), flags, address, res)) 1031 self.fh.write('%s> sendto(%d, %d, %r) -> %d' % (
1032 self.name, len(data), flags, address, res))
1033
994 self._writedata(data) 1034 self._writedata(data)
995 1035
996 def setblocking(self, res, flag): 1036 def setblocking(self, res, flag):
997 if not self.states: 1037 if not self.states:
998 return 1038 return
1017 1057
1018 self.fh.write('%s> setsockopt(%r, %r, %r) -> %r\n' % ( 1058 self.fh.write('%s> setsockopt(%r, %r, %r) -> %r\n' % (
1019 self.name, level, optname, value)) 1059 self.name, level, optname, value))
1020 1060
1021 def makeloggingsocket(logh, fh, name, reads=True, writes=True, states=True, 1061 def makeloggingsocket(logh, fh, name, reads=True, writes=True, states=True,
1022 logdata=False): 1062 logdata=False, logdataapis=True):
1023 """Turn a socket into a logging socket.""" 1063 """Turn a socket into a logging socket."""
1024 1064
1025 observer = socketobserver(logh, name, reads=reads, writes=writes, 1065 observer = socketobserver(logh, name, reads=reads, writes=writes,
1026 states=states, logdata=logdata) 1066 states=states, logdata=logdata,
1067 logdataapis=logdataapis)
1027 return socketproxy(fh, observer) 1068 return socketproxy(fh, observer)
1028 1069
1029 def version(): 1070 def version():
1030 """Return version information if available.""" 1071 """Return version information if available."""
1031 try: 1072 try: