Fix hanging transfers

constraints.txt

@@ -66,7 +66,7 @@ pytest==3.10.1
 pytoml==0.1.19
 pytz==2018.5
 raiden-contracts==0.8.0
-raiden-libs==0.1.14
+raiden-libs==0.1.15
 raiden-webui==0.6
 requests==2.20.0
 rlp==1.0.2

docs/changelog.rst

@@ -2,6 +2,7 @@
 Changelog
 =========
 
+* :bug:`2779` Fixes a long standing bug that could cause payments to hang indefinitely.
 * :bug:`3103` Fixes a bug in matrix which prevented retries of messages.
 * :bug:`3094` Raiden will now properly return payment failure and no longer hang if a payment times out due to a lock expiration.
 * :bug:`3093` Getting raiden payment history will no longer crash raiden for failed sent payment events.

raiden/log_config.py

@@ -6,15 +6,16 @@
 import sys
 from functools import wraps
 from traceback import TracebackException
-from typing import Callable, Dict, FrozenSet, List, Pattern, Tuple
+from typing import Any, Callable, Dict, FrozenSet, List, Pattern, Tuple
 
+import gevent
 import structlog
 
 DEFAULT_LOG_LEVEL = 'INFO'
 MAX_LOG_FILE_SIZE = 20 * 1024 * 1024
 LOG_BACKUP_COUNT = 3
 
-_FIRST_PARTY_PACKAGES = frozenset(['raiden'])
+_FIRST_PARTY_PACKAGES = frozenset(['raiden', 'raiden_libs', 'raiden_contracts'])
 
 
 def _chain(first_func, *funcs) -> Callable:
@@ -102,6 +103,17 @@ def filter(self, record):
         return self._log_filter.should_log(record.name, record.levelname)
 
 
+def add_greenlet_name(logger: str, method_name: str, event_dict: Dict[str, Any]) -> Dict[str, Any]:
+    """
+    Add greenlet_name to the event dict for greenlets that have a non-default name.
+    """
+    current_greenlet = gevent.getcurrent()
+    greenlet_name = getattr(current_greenlet, 'name', None)
+    if greenlet_name is not None and not greenlet_name.startswith('Greenlet-'):
+        event_dict['greenlet_name'] = greenlet_name
+    return event_dict
+
+
 def redactor(blacklist: Dict[Pattern, str]) -> Callable[[str], str]:
     """Returns a function which transforms a str, replacing all matches for its replacement"""
     def processor_wrapper(msg: str) -> str:
@@ -147,8 +159,9 @@ def configure_logging(
     processors = [
         structlog.stdlib.add_logger_name,
         structlog.stdlib.add_log_level,
+        add_greenlet_name,
         structlog.stdlib.PositionalArgumentsFormatter(),
-        structlog.processors.TimeStamper(fmt="%Y-%m-%d %H:%M:%S"),
+        structlog.processors.TimeStamper(fmt="%Y-%m-%d %H:%M:%S.%f"),
         structlog.processors.StackInfoRenderer(),
         structlog.processors.format_exc_info,
     ]

raiden/network/proxies/token_network.py

@@ -548,7 +548,7 @@ def set_total_deposit(
                     f'Current total deposit ({previous_total_deposit}) is already larger '
                     f'than the requested total deposit amount ({total_deposit})'
                 )
-                log.info(f'setTotalDeposit failed, {msg}', **log_details)
+                log.info('setTotalDeposit failed', reason=msg, **log_details)
                 raise DepositMismatch(msg)
 
             if amount_to_deposit <= 0:
@@ -557,7 +557,7 @@ def set_total_deposit(
                     f'new_total_deposit={total_deposit} '
                     f'previous_total_deposit={previous_total_deposit}'
                 )
-                log.info(f'setTotalDeposit failed, {msg}', **log_details)
+                log.info('setTotalDeposit failed', reason=msg, **log_details)
                 raise DepositMismatch(msg)
 
             # A node may be setting up multiple channels for the same token
@@ -579,7 +579,7 @@ def set_total_deposit(
                     f'be larger than the available balance {current_balance}, '
                     f'for token at address {pex(token_address)}'
                 )
-                log.info(f'setTotalDeposit failed, {msg}', **log_details)
+                log.info('setTotalDeposit failed', reason=msg, **log_details)
                 raise DepositMismatch(msg)
 
             # If there are channels being set up concurrenlty either the
@@ -632,18 +632,18 @@ def set_total_deposit(
 
                 if token.allowance(self.node_address, self.address) < amount_to_deposit:
                     log_msg = (
-                        'setTotalDeposit failed. The allowance is insufficient, '
+                        'The allowance is insufficient, '
                         'check concurrent deposits for the same token network '
                         'but different proxies.'
                     )
                 elif token.balance_of(self.node_address) < amount_to_deposit:
-                    log_msg = 'setTotalDeposit failed. The address doesnt have funds'
+                    log_msg = "The address doesn't have enough funds"
                 elif latest_deposit < total_deposit:
-                    log_msg = 'setTotalDeposit failed. The tokens were not transferred'
+                    log_msg = 'The tokens were not transferred'
                 else:
-                    log_msg = 'setTotalDeposit failed'
+                    log_msg = 'unknown'
 
-                log.critical(log_msg, **log_details)
+                log.critical('setTotalDeposit failed', reason=log_msg, **log_details)
 
                 self._check_channel_state_for_deposit(
                     self.node_address,