log connection info as debug level by default

shadowsocks/common.py

@@ -40,6 +40,7 @@ _chr = chr
 ord = compat_ord
 chr = compat_chr
 
+connect_log = logging.debug
 
 def to_bytes(s):
     if bytes != str:

shadowsocks/shell.py

@@ -242,6 +242,7 @@ def get_config(is_local):
     config['pid-file'] = config.get('pid-file', '/var/run/shadowsocks.pid')
     config['log-file'] = config.get('log-file', '/var/log/shadowsocks.log')
     config['verbose'] = config.get('verbose', False)
+    config['connect_verbose_info'] = config.get('connect_verbose_info', 0)
     config['local_address'] = to_str(config.get('local_address', '127.0.0.1'))
     config['local_port'] = config.get('local_port', 1080)
     if is_local:

shadowsocks/tcprelay.py

@@ -450,7 +450,7 @@ class TCPRelayHandler(object):
                     data = self._handel_protocol_error(self._client_address, ogn_data)
                     header_result = parse_header(data)
             connecttype, remote_addr, remote_port, header_length = header_result
-            logging.info('%s connecting %s:%d from %s:%d' %
+            common.connect_log('%s connecting %s:%d from %s:%d' %
                         ((connecttype == 0) and 'TCP' or 'UDP',
                             common.to_str(remote_addr), remote_port,
                             self._client_address[0], self._client_address[1]))
@@ -849,6 +849,9 @@ class TCPRelay(object):
         self.protocol_data = obfs.obfs(config['protocol']).init_data()
         self.obfs_data = obfs.obfs(config['obfs']).init_data()
 
+        if config.get('connect_verbose_info', 0) > 0:
+            common.connect_log = logging.info
+
         self._timeout = config['timeout']
         self._timeouts = []  # a list for all the handlers
         # we trim the timeouts once a while
@@ -938,10 +941,10 @@ class TCPRelay(object):
                         break
                     else:
                         if handler.remote_address:
-                            logging.warn('timed out: %s:%d' %
+                            logging.debug('timed out: %s:%d' %
                                          handler.remote_address)
                         else:
-                            logging.warn('timed out')
+                            logging.debug('timed out')
                         handler.destroy()
                         self._timeouts[pos] = None  # free memory
                         pos += 1

shadowsocks/udprelay.py

@@ -693,7 +693,7 @@ class TCPRelayHandler(object):
                     self._stage = STAGE_DNS
                     self._dns_resolver.resolve(remote_addr,
                                                self._handle_dns_resolved)
-                    logging.info('TCPonUDP connect %s:%d from %s:%d' % (remote_addr, remote_port, addr[0], addr[1]))
+                    common.connect_log('TCPonUDP connect %s:%d from %s:%d' % (remote_addr, remote_port, addr[0], addr[1]))
                 else:
                     # ileagal request
                     rsp_data = self._pack_rsp_data(CMD_DISCONNECT, RSP_STATE_EMPTY)
@@ -865,6 +865,8 @@ def client_key(source_addr, server_af):
 class UDPRelay(object):
     def __init__(self, config, dns_resolver, is_local, stat_callback=None):
         self._config = config
+        if config.get('connect_verbose_info', 0) > 0:
+            common.connect_log = logging.info
         if is_local:
             self._listen_addr = config['local_address']
             self._listen_port = config['local_port']
@@ -942,12 +944,19 @@ class UDPRelay(object):
 
     def _close_client(self, client):
         if hasattr(client, 'close'):
+            if not self._is_local:
+                if client.fileno() in self._client_fd_to_server_addr:
+                    logging.debug('close_client: %s' %
+                                 (self._client_fd_to_server_addr[client.fileno()],))
+                else:
+                    client.info('close_client')
             self._sockets.remove(client.fileno())
             self._eventloop.remove(client)
             del self._client_fd_to_server_addr[client.fileno()]
             client.close()
         else:
             # just an address
+            client.info('close_client pass %s' % client)
             pass
 
     def _pre_parse_udp_header(self, data):
@@ -1073,7 +1082,7 @@ class UDPRelay(object):
 
             logging.debug('UDP port %5d sockets %d' % (self._listen_port, len(self._sockets)))
 
-            logging.info('UDP data to %s:%d from %s:%d' %
+            common.connect_log('UDP data to %s:%d from %s:%d' %
                         (common.to_str(server_addr), server_port,
                             r_addr[0], r_addr[1]))
 
@@ -1083,7 +1092,7 @@ class UDPRelay(object):
             ref_iv = [encrypt.encrypt_new_iv(self._method)]
             self._protocol.obfs.server_info.iv = ref_iv[0]
             data = self._protocol.client_udp_pre_encrypt(data)
-            logging.info("%s" % (binascii.hexlify(data),))
+            #logging.debug("%s" % (binascii.hexlify(data),))
             data = encrypt.encrypt_all_iv(self._protocol.obfs.server_info.key, self._method, 1, data, ref_iv)
             if not data:
                 return
@@ -1285,10 +1294,10 @@ class UDPRelay(object):
                         break
                     else:
                         if handler.remote_address:
-                            logging.warn('timed out: %s:%d' %
+                            logging.debug('timed out: %s:%d' %
                                          handler.remote_address)
                         else:
-                            logging.warn('timed out')
+                            logging.debug('timed out')
                         handler.destroy()
                         handler.destroy_local()
                         self._timeouts[pos] = None  # free memory