search

neo4j / neo4j-javascript-driver

Neo4j Bolt driver for JavaScript
https://neo4j.com/docs/javascript-manual/current/
Apache License 2.0
854 stars 148 forks source link

All connections from pool are suddenly closed or never released #446

Closed elielr01 closed 4 years ago

elielr01 commented 5 years ago

I have an Express server which do some queries to our Neo4j database. At the very beginning of the server lifetime, I create the neo4j driver singleton as recommended in the docs. After some days of normal use, the driver suddenly closes all the connections of the pool (there is no driver.close(), no reassignation to the driver, nor nothing.. only getting and closing sessions and writeTransactions in the code).

Neo4j Version: 3.4.12 Community
Neo4j Mode: Single instance
Driver version: JS driver 1.7.1
Operating System of DB: CentOS 7 on GCP Operating System of Server using neo4j-driver: Debian GNU/Linux 9 (stretch) on GCP

Pre-requisites

Having a Neo4j DB instance running and the server correctly configured(which I might be doing wrong maybe?) to communicate to the neo4j instance.

Steps to reproduce

  1. Start the server
  2. Some API calls are being correctly served by the server for a couple of days. The server queries using the driver and writeTransactions.
  3. After a couple of days of working correctly, out of a sudden all the connections of the pool are closed
  4. When serving the next API calls, the server throws the error Neo4jError: Connection acquisition timed out in 60000 ms.

    Expected behavior

    All the connections are open during the whole driver's lifecycle (which should be the whole application lifetime according to the docs)

    Actual behavior

    The connections are all closed and I cannot get more connections from the driver.

This is the driver configuration:

const driver = neo4j.driver(
    process.env.NEO4J_URI,
    neo4j.auth.basic(process.env.NEO4J_USER, process.env.NEO4J_PASSWORD),
    {
      maxConnectionLifetime: 60 * 60 * 1000, // 1 hour
      maxConnectionPoolSize: 300,
      encrypted: "ENCRYPTION_ON",
      trust: "TRUST_CUSTOM_CA_SIGNED_CERTIFICATES",
      trustedCertificates: [process.env.NEO4J_TRUSTED_CERTS],
      logging: {
        level: 'debug',
        logger: (level, message) => console.log('+++' + level + ' ' + message)
      }
    }
);

I also implemented the logger as one of the suggestions in the answers you guys gave in one issue. Since it was running for a while, it generated a log of about 210 MB. I split it in 25 log files, the first 24 useless and the last one is where the error can be seen. I'm just quoting the important parts of the log, but I'll also attach the last log file if that helps. The connections closing starts at line 2,700 of the file.

Lastly, I just wanted to say thanks guys for the nice efforts done in this module! I really appreciate the work done here. I just want some help with my issue.

xay.txt

+++debug Connection [5065][] C: PULL_ALL
+++debug Connection [4837][] S: SUCCESS {"signature":112,"fields":[{"result_available_after":{"low":0,"high":0},"fields":[]}]}
+++debug Connection [4837][] S: SUCCESS {"signature":112,"fields":[{}]}
+++debug Connection [4837][] S: SUCCESS {"signature":112,"fields":[{"result_available_after":{"low":0,"high":0},"fields":["p.port_id","p.name","p.longitude","p.latitude"]}]}
+++debug Connection [4837][] S: RECORD {"signature":113,"fields":[[{"low":1847,"high":0},"PORT HEDLAND",118.5769444,-20.31750002]]}
+++debug Connection [4837][] S: SUCCESS {"signature":112,"fields":[{"result_consumed_after":{"low":0,"high":0},"type":"r"}]}
+++debug Connection [4837][] C: RUN COMMIT {}
+++debug Connection [4837][] C: PULL_ALL
+++debug Connection [5065][] S: SUCCESS {"signature":112,"fields":[{"result_available_after":{"low":0,"high":0},"fields":[]}]}
+++debug Connection [5065][] S: SUCCESS {"signature":112,"fields":[{}]}
+++debug Connection [5065][] S: SUCCESS {"signature":112,"fields":[{"result_available_after":{"low":1,"high":0},"fields":["p.port_id","p.name","p.longitude","p.latitude"]}]}
+++debug Connection [5065][] S: RECORD {"signature":113,"fields":[[{"low":2829,"high":0},"PARADIP",86.68,20.26]]}
+++debug Connection [5065][] S: SUCCESS {"signature":112,"fields":[{"result_consumed_after":{"low":0,"high":0},"type":"r"}]}
+++debug Connection [5065][] C: RUN COMMIT {}
+++debug Connection [5065][] C: PULL_ALL
+++debug Connection [4837][] S: SUCCESS {"signature":112,"fields":[{"result_available_after":{"low":0,"high":0},"fields":[]}]}
+++debug Connection [4837][] S: SUCCESS {"signature":112,"fields":[{"bookmark":"neo4j:bookmark:v1:tx1637"}]}
+++debug Connection [4837][] C: RESET
+++debug Connection [5065][] S: SUCCESS {"signature":112,"fields":[{"result_available_after":{"low":0,"high":0},"fields":[]}]}
+++debug Connection [5065][] S: SUCCESS {"signature":112,"fields":[{"bookmark":"neo4j:bookmark:v1:tx1637"}]}
+++debug Connection [5065][] C: RESET
+++debug Connection [4837][] S: SUCCESS {"signature":112,"fields":[{}]}
+++debug Connection [4837][] released to the pool neo4j-prod.theofe.com:7687
+++debug Connection [4837][] acquired from the pool
+++debug Connection [4837][] C: RUN BEGIN {}
+++debug Connection [4837][] C: PULL_ALL
+++debug Connection [4837][] C: RUN WITH point({longitude:118.5769444, latitude:-20.31750002}) AS p, 5000 as distance_nm
        CALL spatial.withinDistance('all_connected_ports', p, distance_nm*1.852)
          YIELD node, distance
          RETURN node.port_id AS port_id, node.name, node.type AS name, distance/1.852 AS distance, node.longitude, node.latitude
          LIMIT 1 {}
+++debug Connection [4837][] C: PULL_ALL
+++debug Connection [5065][] S: SUCCESS {"signature":112,"fields":[{}]}
+++debug Connection [5065][] released to the pool neo4j-prod.theofe.com:7687
+++debug Connection [5065][] acquired from the pool
+++debug Connection [5065][] C: RUN BEGIN {}
+++debug Connection [5065][] C: PULL_ALL
+++debug Connection [5065][] C: RUN WITH point({longitude:86.68, latitude:20.26}) AS p, 5000 as distance_nm
        CALL spatial.withinDistance('all_connected_ports', p, distance_nm*1.852)
          YIELD node, distance
          RETURN node.port_id AS port_id, node.name, node.type AS name, distance/1.852 AS distance, node.longitude, node.latitude
          LIMIT 1 {}
+++debug Connection [5065][] C: PULL_ALL
+++debug Connection [4837][] S: SUCCESS {"signature":112,"fields":[{"result_available_after":{"low":0,"high":0},"fields":[]}]}
+++debug Connection [4837][] S: SUCCESS {"signature":112,"fields":[{}]}
+++debug Connection [4837][] S: SUCCESS {"signature":112,"fields":[{"result_available_after":{"low":2,"high":0},"fields":["port_id","node.name","name","distance","node.longitude","node.latitude"]}]}
+++debug Connection [4837][] S: RECORD {"signature":113,"fields":[[{"low":1803,"high":0},"DAMPIER","P",107.67802056701662,116.695,-20.64666669]]}
+++debug Connection [4837][] S: SUCCESS {"signature":112,"fields":[{"result_consumed_after":{"low":0,"high":0},"type":"rw"}]}
+++debug Connection [4837][] C: RUN COMMIT {}
+++debug Connection [4837][] C: PULL_ALL
+++debug Connection [5065][] S: SUCCESS {"signature":112,"fields":[{"result_available_after":{"low":0,"high":0},"fields":[]}]}
+++debug Connection [5065][] S: SUCCESS {"signature":112,"fields":[{}]}
+++debug Connection [5065][] S: SUCCESS {"signature":112,"fields":[{"result_available_after":{"low":3,"high":0},"fields":["port_id","node.name","name","distance","node.longitude","node.latitude"]}]}
+++debug Connection [5065][] S: RECORD {"signature":113,"fields":[[{"low":2829,"high":0},"PARADIP","P",0.00005126096002483986,86.68,20.26]]}
+++debug Connection [5065][] S: SUCCESS {"signature":112,"fields":[{"result_consumed_after":{"low":0,"high":0},"type":"rw"}]}
+++debug Connection [5065][] C: RUN COMMIT {}
+++debug Connection [5065][] C: PULL_ALL
+++debug Connection [4837][] S: SUCCESS {"signature":112,"fields":[{"result_available_after":{"low":0,"high":0},"fields":[]}]}
+++debug Connection [4837][] S: SUCCESS {"signature":112,"fields":[{"bookmark":"neo4j:bookmark:v1:tx1637"}]}
+++debug Connection [4837][] C: RESET
+++debug Connection [5065][] S: SUCCESS {"signature":112,"fields":[{"result_available_after":{"low":0,"high":0},"fields":[]}]}
+++debug Connection [5065][] S: SUCCESS {"signature":112,"fields":[{"bookmark":"neo4j:bookmark:v1:tx1637"}]}
+++debug Connection [5065][] C: RESET
+++debug Connection [4837][] S: SUCCESS {"signature":112,"fields":[{}]}
+++debug Connection [4837][] released to the pool neo4j-prod.theofe.com:7687
+++debug Connection [5065][] S: SUCCESS {"signature":112,"fields":[{}]}
+++debug Connection [5065][] released to the pool neo4j-prod.theofe.com:7687
+++debug Connection [5065][] acquired from the pool
+++debug Connection [5065][] C: RUN BEGIN {}
+++debug Connection [5065][] C: PULL_ALL
+++debug Connection [5065][] C: RUN MATCH (start:Port{port_id: 1803}), (end:Port{port_id: 2829})
          CALL algo.shortestPath.astar.stream(start, end, 'NM', 'latitude', 'longitude',{relationshipQuery:'DISTANCE',direction:'BOTH'})
          YIELD nodeId, cost
          MATCH (route:Port) WHERE ID(route)=nodeId
          RETURN route.port_id AS port_id, route.name AS name, route.longitude AS longitude, route.latitude AS latitude, cost AS nm {}
+++debug Connection [5065][] C: PULL_ALL
+++debug Connection [5065][] S: SUCCESS {"signature":112,"fields":[{"result_available_after":{"low":0,"high":0},"fields":[]}]}
+++debug Connection [5065][] S: SUCCESS {"signature":112,"fields":[{}]}
+++debug Connection [5065][] S: SUCCESS {"signature":112,"fields":[{"result_available_after":{"low":0,"high":0},"fields":["port_id","name","longitude","latitude","nm"]}]}
+++debug Connection [5065][] S: RECORD {"signature":113,"fields":[[{"low":1803,"high":0},"DAMPIER",116.695,-20.64666669,0]]}
+++debug Connection [5065][] S: RECORD {"signature":113,"fields":[[{"low":4032,"high":0},"SUMBAWA STRAIT",116.6867,-8.5945,720]]}
+++debug Connection [5065][] S: RECORD {"signature":113,"fields":[[{"low":4004,"high":0},"LOMBOK STRAIT",115.8872,-8.3256,802]]}
+++debug Connection [5065][] S: RECORD {"signature":113,"fields":[[{"low":4000,"high":0},"KARIMATA STRAIT",108.6225,-2.0428,1386]]}
+++debug Connection [5065][] S: RECORD {"signature":113,"fields":[[{"low":4019,"high":0},"SINGAPORE STRAIT",103.4689,1.1892,1775]]}
+++debug Connection [5065][] S: RECORD {"signature":113,"fields":[[{"low":8206,"high":0},"WAYPOINT 56",98.12277778,8.07972222,2306]]}
+++debug Connection [5065][] S: RECORD {"signature":113,"fields":[[{"low":8210,"high":0},"WAYPOINT 60",93.59083333,14.22888889,2760]]}
+++debug Connection [5065][] S: RECORD {"signature":113,"fields":[[{"low":8209,"high":0},"WAYPOINT 59",89.81472222,19.31777778,3133]]}
+++debug Connection [5065][] S: RECORD {"signature":113,"fields":[[{"low":2814,"high":0},"HALDIA",88.092874,22.036944,3327]]}
+++debug Connection [5065][] S: RECORD {"signature":113,"fields":[[{"low":2829,"high":0},"PARADIP",86.68,20.26,3466]]}
+++debug Connection [5065][] S: SUCCESS {"signature":112,"fields":[{"result_consumed_after":{"low":8,"high":0},"type":"r"}]}
+++debug Connection [5065][] C: RUN COMMIT {}
+++debug Connection [5065][] C: PULL_ALL
+++debug Connection [5065][] S: SUCCESS {"signature":112,"fields":[{"result_available_after":{"low":0,"high":0},"fields":[]}]}
+++debug Connection [5065][] S: SUCCESS {"signature":112,"fields":[{"bookmark":"neo4j:bookmark:v1:tx1637"}]}
+++debug Connection [5065][] C: RESET
+++debug Connection [5065][] S: SUCCESS {"signature":112,"fields":[{}]}
+++debug Connection [5065][] released to the pool neo4j-prod.theofe.com:7687
+++debug Connection [5065][] acquired from the pool
+++debug Connection [4837][] acquired from the pool
+++debug Connection [5065][] C: RUN BEGIN {}
+++debug Connection [5065][] C: PULL_ALL
+++debug Connection [5065][] C: RUN MATCH (p:Port)
        WHERE p.port_id = 1847
        RETURN p.port_id, p.name, p.longitude, p.latitude LIMIT 1 {}
+++debug Connection [5065][] C: PULL_ALL
+++debug Connection [4837][] C: RUN BEGIN {}
+++debug Connection [4837][] C: PULL_ALL
+++debug Connection [4837][] C: RUN MATCH (p:Port)
        WHERE p.port_id = 300
        RETURN p.port_id, p.name, p.longitude, p.latitude LIMIT 1 {}
+++debug Connection [4837][] C: PULL_ALL
+++debug Connection [5065][] S: SUCCESS {"signature":112,"fields":[{"result_available_after":{"low":0,"high":0},"fields":[]}]}
+++debug Connection [5065][] S: SUCCESS {"signature":112,"fields":[{}]}
+++debug Connection [5065][] S: SUCCESS {"signature":112,"fields":[{"result_available_after":{"low":1,"high":0},"fields":["p.port_id","p.name","p.longitude","p.latitude"]}]}
+++debug Connection [5065][] S: RECORD {"signature":113,"fields":[[{"low":1847,"high":0},"PORT HEDLAND",118.5769444,-20.31750002]]}
+++debug Connection [5065][] S: SUCCESS {"signature":112,"fields":[{"result_consumed_after":{"low":0,"high":0},"type":"r"}]}
+++debug Connection [5065][] C: RUN COMMIT {}
+++debug Connection [5065][] C: PULL_ALL
+++debug Connection [4837][] S: SUCCESS {"signature":112,"fields":[{"result_available_after":{"low":0,"high":0},"fields":[]}]}
+++debug Connection [4837][] S: SUCCESS {"signature":112,"fields":[{}]}
+++debug Connection [4837][] S: SUCCESS {"signature":112,"fields":[{"result_available_after":{"low":0,"high":0},"fields":["p.port_id","p.name","p.longitude","p.latitude"]}]}
+++debug Connection [4837][] S: RECORD {"signature":113,"fields":[[{"low":300,"high":0},"KASHIMA",140.6833,35.909345]]}
+++debug Connection [4837][] S: SUCCESS {"signature":112,"fields":[{"result_consumed_after":{"low":0,"high":0},"type":"r"}]}
+++debug Connection [4837][] C: RUN COMMIT {}
+++debug Connection [4837][] C: PULL_ALL
+++debug Connection [5065][] S: SUCCESS {"signature":112,"fields":[{"result_available_after":{"low":0,"high":0},"fields":[]}]}
+++debug Connection [5065][] S: SUCCESS {"signature":112,"fields":[{"bookmark":"neo4j:bookmark:v1:tx1637"}]}
+++debug Connection [5065][] C: RESET
+++debug Connection [4837][] S: SUCCESS {"signature":112,"fields":[{"result_available_after":{"low":0,"high":0},"fields":[]}]}
+++debug Connection [4837][] S: SUCCESS {"signature":112,"fields":[{"bookmark":"neo4j:bookmark:v1:tx1637"}]}
+++debug Connection [4837][] C: RESET
+++debug Connection [5065][] S: SUCCESS {"signature":112,"fields":[{}]}
+++debug Connection [5065][] released to the pool neo4j-prod.theofe.com:7687
+++debug Connection [5065][] acquired from the pool
+++debug Connection [5065][] C: RUN BEGIN {}
+++debug Connection [5065][] C: PULL_ALL
+++debug Connection [5065][] C: RUN WITH point({longitude:118.5769444, latitude:-20.31750002}) AS p, 5000 as distance_nm
        CALL spatial.withinDistance('all_connected_ports', p, distance_nm*1.852)
          YIELD node, distance
          RETURN node.port_id AS port_id, node.name, node.type AS name, distance/1.852 AS distance, node.longitude, node.latitude
          LIMIT 1 {}
+++debug Connection [5065][] C: PULL_ALL
+++debug Connection [4837][] S: SUCCESS {"signature":112,"fields":[{}]}
+++debug Connection [4837][] released to the pool neo4j-prod.theofe.com:7687
+++debug Connection [4837][] acquired from the pool
+++debug Connection [4837][] C: RUN BEGIN {}
+++debug Connection [4837][] C: PULL_ALL
+++debug Connection [4837][] C: RUN WITH point({longitude:140.6833, latitude:35.909345}) AS p, 5000 as distance_nm
        CALL spatial.withinDistance('all_connected_ports', p, distance_nm*1.852)
          YIELD node, distance
          RETURN node.port_id AS port_id, node.name, node.type AS name, distance/1.852 AS distance, node.longitude, node.latitude
          LIMIT 1 {}
+++debug Connection [4837][] C: PULL_ALL
+++debug Connection [5065][] S: SUCCESS {"signature":112,"fields":[{"result_available_after":{"low":0,"high":0},"fields":[]}]}
+++debug Connection [5065][] S: SUCCESS {"signature":112,"fields":[{}]}
+++debug Connection [5065][] S: SUCCESS {"signature":112,"fields":[{"result_available_after":{"low":2,"high":0},"fields":["port_id","node.name","name","distance","node.longitude","node.latitude"]}]}
+++debug Connection [5065][] S: RECORD {"signature":113,"fields":[[{"low":1803,"high":0},"DAMPIER","P",107.67802056701662,116.695,-20.64666669]]}
+++debug Connection [5065][] S: SUCCESS {"signature":112,"fields":[{"result_consumed_after":{"low":0,"high":0},"type":"rw"}]}
+++debug Connection [5065][] C: RUN COMMIT {}
+++debug Connection [5065][] C: PULL_ALL
+++debug Connection [4837][] S: SUCCESS {"signature":112,"fields":[{"result_available_after":{"low":0,"high":0},"fields":[]}]}
+++debug Connection [4837][] S: SUCCESS {"signature":112,"fields":[{}]}
+++debug Connection [4837][] S: SUCCESS {"signature":112,"fields":[{"result_available_after":{"low":3,"high":0},"fields":["port_id","node.name","name","distance","node.longitude","node.latitude"]}]}
+++debug Connection [4837][] S: RECORD {"signature":113,"fields":[[{"low":2526,"high":0},"CHIBA","P",36.87185405565536,140.059187,35.562222]]}
+++debug Connection [4837][] S: SUCCESS {"signature":112,"fields":[{"result_consumed_after":{"low":0,"high":0},"type":"rw"}]}
+++debug Connection [4837][] C: RUN COMMIT {}
+++debug Connection [4837][] C: PULL_ALL
+++debug Connection [5065][] S: SUCCESS {"signature":112,"fields":[{"result_available_after":{"low":0,"high":0},"fields":[]}]}
+++debug Connection [5065][] S: SUCCESS {"signature":112,"fields":[{"bookmark":"neo4j:bookmark:v1:tx1637"}]}
+++debug Connection [5065][] C: RESET
+++debug Connection [4837][] S: SUCCESS {"signature":112,"fields":[{"result_available_after":{"low":0,"high":0},"fields":[]}]}
+++debug Connection [4837][] S: SUCCESS {"signature":112,"fields":[{"bookmark":"neo4j:bookmark:v1:tx1637"}]}
+++debug Connection [4837][] C: RESET
+++debug Connection [5065][] S: SUCCESS {"signature":112,"fields":[{}]}
+++debug Connection [5065][] released to the pool neo4j-prod.theofe.com:7687
+++debug Connection [4837][] S: SUCCESS {"signature":112,"fields":[{}]}
+++debug Connection [4837][] released to the pool neo4j-prod.theofe.com:7687
+++debug Connection [4837][] acquired from the pool
+++debug Connection [4837][] C: RUN BEGIN {}
+++debug Connection [4837][] C: PULL_ALL
+++debug Connection [4837][] C: RUN MATCH (start:Port{port_id: 1803}), (end:Port{port_id: 2526})
          CALL algo.shortestPath.astar.stream(start, end, 'NM', 'latitude', 'longitude',{relationshipQuery:'DISTANCE',direction:'BOTH'})
          YIELD nodeId, cost
          MATCH (route:Port) WHERE ID(route)=nodeId
          RETURN route.port_id AS port_id, route.name AS name, route.longitude AS longitude, route.latitude AS latitude, cost AS nm {}
+++debug Connection [4837][] C: PULL_ALL
+++debug Connection [4837][] S: SUCCESS {"signature":112,"fields":[{"result_available_after":{"low":0,"high":0},"fields":[]}]}
+++debug Connection [4837][] S: SUCCESS {"signature":112,"fields":[{}]}
+++debug Connection [4837][] S: SUCCESS {"signature":112,"fields":[{"result_available_after":{"low":0,"high":0},"fields":["port_id","name","longitude","latitude","nm"]}]}
+++debug Connection [4837][] S: RECORD {"signature":113,"fields":[[{"low":1803,"high":0},"DAMPIER",116.695,-20.64666669,0]]}
+++debug Connection [4837][] S: RECORD {"signature":113,"fields":[[{"low":4001,"high":0},"KOLANA AREA",125.2411,-8.2211,912]]}
+++debug Connection [4837][] S: RECORD {"signature":113,"fields":[[{"low":3980,"high":0},"EAST MANGOLE",126.5572,-1.8558,1303]]}
+++debug Connection [4837][] S: RECORD {"signature":113,"fields":[[{"low":8238,"high":0},"WAYPOINT 88",128.3052778,3.96861111,1667]]}
+++debug Connection [4837][] S: RECORD {"signature":113,"fields":[[{"low":8239,"high":0},"WAYPOINT 89",131.2980556,12.76305556,2221]]}
+++debug Connection [4837][] S: RECORD {"signature":113,"fields":[[{"low":8240,"high":0},"WAYPOINT 90",134.7,22.32027778,2824]]}
+++debug Connection [4837][] S: RECORD {"signature":113,"fields":[[{"low":2526,"high":0},"CHIBA",140.059187,35.562222,3671]]}
+++debug Connection [4837][] S: SUCCESS {"signature":112,"fields":[{"result_consumed_after":{"low":7,"high":0},"type":"r"}]}
+++debug Connection [4837][] C: RUN COMMIT {}
+++debug Connection [4837][] C: PULL_ALL
+++debug Connection [4837][] S: SUCCESS {"signature":112,"fields":[{"result_available_after":{"low":1,"high":0},"fields":[]}]}
+++debug Connection [4837][] S: SUCCESS {"signature":112,"fields":[{"bookmark":"neo4j:bookmark:v1:tx1637"}]}
+++debug Connection [4837][] C: RESET
+++debug Connection [4837][] S: SUCCESS {"signature":112,"fields":[{}]}
+++debug Connection [4837][] released to the pool neo4j-prod.theofe.com:7687
+++debug Connection [4837][] closing
+++debug Connection [5065][] closing
+++debug Connection [5107][] closing
+++debug Connection [4847][] closing
+++debug Connection [4875][] closing
+++debug Connection [5098][] closing
+++debug Connection [5163][] closing
+++debug Connection [5054][] closing
+++debug Connection [4991][] closing
+++debug Connection [5041][] closing
+++debug Connection [4989][] closing
+++debug Connection [5181][] closing
+++debug Connection [4882][] closing
+++debug Connection [5205][] closing
+++debug Connection [4933][] closing
+++debug Connection [5293][] closing
+++debug Connection [5131][] closing
+++debug Connection [4853][] closing
+++debug Connection [5270][] closing
+++debug Connection [5123][] closing
+++debug Connection [5105][] closing
+++debug Connection [5149][] closing
+++debug Connection [5028][] closing
+++debug Connection [4769][] closing
+++debug Connection [5238][] closing
+++debug Connection [4943][] closing
+++debug Connection [5225][] closing
+++debug Connection [5191][] closing
+++debug Connection [5069][] closing
+++debug Connection [4755][] closing
+++debug Connection [5231][] closing
+++debug Connection [5111][] closing
+++debug Connection [4798][] closing
+++debug Connection [5119][] closing
+++debug Connection [4783][] closing
+++debug Connection [4987][] closing
+++debug Connection [5023][] closing
+++debug Connection [5172][] closing
+++debug Connection [4947][] closing
+++debug Connection [5243][] closing
+++debug Connection [4885][] closing
+++debug Connection [4838][] closing
+++debug Connection [5236][] closing
+++debug Connection [5063][] closing
+++debug Connection [4969][] closing
+++debug Connection [5085][] closing
+++debug Connection [5277][] closing
+++debug Connection [5242][] closing
+++debug Connection [4797][] closing
+++debug Connection [4893][] closing
+++debug Connection [5173][] closing
+++debug Connection [5144][] closing
+++debug Connection [5228][] closing
+++debug Connection [4945][] closing
+++debug Connection [5200][] closing
+++debug Connection [5095][] closing
+++debug Connection [5250][] closing
+++debug Connection [5083][] closing
+++debug Connection [4753][] closing
+++debug Connection [4821][] closing
+++debug Connection [5271][] closing
+++debug Connection [5142][] closing
+++debug Connection [5229][] closing
+++debug Connection [5057][] closing
+++debug Connection [5206][] closing
+++debug Connection [5284][] closing
+++debug Connection [4889][] closing
+++debug Connection [4972][] closing
+++debug Connection [5143][] closing
+++debug Connection [5298][] closing
+++debug Connection [4951][] closing
+++debug Connection [4863][] closing
+++debug Connection [5244][] closing
+++debug Connection [4918][] closing
+++debug Connection [5079][] closing
+++debug Connection [5087][] closing
+++debug Connection [5179][] closing
+++debug Connection [5138][] closing
+++debug Connection [4934][] closing
+++debug Connection [5040][] closing
+++debug Connection [5021][] closing
+++debug Connection [4845][] closing
+++debug Connection [5137][] closing
+++debug Connection [4983][] closing
+++debug Connection [5022][] closing
+++debug Connection [5253][] closing
+++debug Connection [5162][] closing
+++debug Connection [5257][] closing
+++debug Connection [5100][] closing
+++debug Connection [4940][] closing
+++debug Connection [4976][] closing
+++debug Connection [5068][] closing
+++debug Connection [5121][] closing
+++debug Connection [5067][] closing
+++debug Connection [5248][] closing
+++debug Connection [4785][] closing
+++debug Connection [5189][] closing
+++debug Connection [5050][] closing
+++debug Connection [5188][] closing
+++debug Connection [5064][] closing
+++debug Connection [4879][] closing
+++debug Connection [4811][] closing
+++debug Connection [5033][] closing
+++debug Connection [4862][] closing
+++debug Connection [5212][] closing
+++debug Connection [5286][] closing
+++debug Connection [5136][] closing
+++debug Connection [5296][] closing
+++debug Connection [5195][] closing
+++debug Connection [5093][] closing
+++debug Connection [5249][] closing
+++debug Connection [4971][] closing
+++debug Connection [5237][] closing
+++debug Connection [4924][] closing
+++debug Connection [4985][] closing
+++debug Connection [5091][] closing
+++debug Connection [5184][] closing
+++debug Connection [4999][] closing
+++debug Connection [5132][] closing
+++debug Connection [4923][] closing
+++debug Connection [5241][] closing
+++debug Connection [5226][] closing
+++debug Connection [5036][] closing
+++debug Connection [5013][] closing
+++debug Connection [4939][] closing
+++debug Connection [4761][] closing
+++debug Connection [5099][] closing
+++debug Connection [5166][] closing
+++debug Connection [4791][] closing
+++debug Connection [5287][] closing
+++debug Connection [4799][] closing
+++debug Connection [5077][] closing
+++debug Connection [5224][] closing
+++debug Connection [4888][] closing
+++debug Connection [5274][] closing
+++debug Connection [5045][] closing
+++debug Connection [4895][] closing
+++debug Connection [5160][] closing
+++debug Connection [5300][] closing
+++debug Connection [5019][] closing
+++debug Connection [5139][] closing
+++debug Connection [5075][] closing
+++debug Connection [5256][] closing
+++debug Connection [5275][] closing
+++debug Connection [5127][] closing
+++debug Connection [4817][] closing
+++debug Connection [5027][] closing
+++debug Connection [4829][] closing
+++debug Connection [5246][] closing
+++debug Connection [4995][] closing
+++debug Connection [4927][] closing
+++debug Connection [5213][] closing
+++debug Connection [5217][] closing
+++debug Connection [4855][] closing
+++debug Connection [5015][] closing
+++debug Connection [4911][] closing
+++debug Connection [5199][] closing
+++debug Connection [5010][] closing
+++debug Connection [5235][] closing
+++debug Connection [5183][] closing
+++debug Connection [5140][] closing
+++debug Connection [5285][] closing
+++debug Connection [4955][] closing
+++debug Connection [5268][] closing
+++debug Connection [4865][] closing
+++debug Connection [5084][] closing
+++debug Connection [5158][] closing
+++debug Connection [5081][] closing
+++debug Connection [5261][] closing
+++debug Connection [5090][] closing
+++debug Connection [5204][] closing
+++debug Connection [5202][] closing
+++debug Connection [4763][] closing
+++debug Connection [5197][] closing
+++debug Connection [5214][] closing
+++debug Connection [5251][] closing
+++debug Connection [5103][] closing
+++debug Connection [5034][] closing
+++debug Connection [5109][] closing
+++debug Connection [5146][] closing
+++debug Connection [5110][] closing
+++debug Connection [4773][] closing
+++debug Connection [5283][] closing
+++debug Connection [4937][] closing
+++debug Connection [4905][] closing
+++debug Connection [5047][] closing
+++debug Connection [5278][] closing
+++debug Connection [5207][] closing
+++debug Connection [4953][] closing
+++debug Connection [5164][] closing
+++debug Connection [5182][] closing
+++debug Connection [5153][] closing
+++debug Connection [5210][] closing
+++debug Connection [5301][] closing
+++debug Connection [4877][] closing
+++debug Connection [4870][] closing
+++debug Connection [5305][] closing
+++debug Connection [4914][] closing
+++debug Connection [4997][] closing
+++debug Connection [5252][] closing
+++debug Connection [5170][] closing
+++debug Connection [4903][] closing
+++debug Connection [5096][] closing
+++debug Connection [4809][] closing
+++debug Connection [5177][] closing
+++debug Connection [4977][] closing
+++debug Connection [5009][] closing
+++debug Connection [4965][] closing
+++debug Connection [5082][] closing
+++debug Connection [5156][] closing
+++debug Connection [4781][] closing
+++debug Connection [5280][] closing
+++debug Connection [5263][] closing
+++debug Connection [4803][] closing
+++debug Connection [4757][] closing
+++debug Connection [5117][] closing
+++debug Connection [4979][] closing
+++debug Connection [5029][] closing
+++debug Connection [5151][] closing
+++debug Connection [5066][] closing
+++debug Connection [4946][] closing
+++debug Connection [4941][] closing
+++debug Connection [5154][] closing
+++debug Connection [5279][] closing
+++debug Connection [5192][] closing
+++debug Connection [5048][] closing
+++debug Connection [5295][] closing
+++debug Connection [4871][] closing
+++debug Connection [5043][] closing
+++debug Connection [5032][] closing
+++debug Connection [5187][] closing
+++debug Connection [5178][] closing
+++debug Connection [4892][] closing
+++debug Connection [4819][] closing
+++debug Connection [5220][] closing
+++debug Connection [5070][] closing
+++debug Connection [5059][] closing
+++debug Connection [5294][] closing
+++debug Connection [5303][] closing
+++debug Connection [4967][] closing
+++debug Connection [5258][] closing
+++debug Connection [5092][] closing
+++debug Connection [4827][] closing
+++debug Connection [4857][] closing
+++debug Connection [4975][] closing
+++debug Connection [5001][] closing
+++debug Connection [5147][] closing
+++debug Connection [5233][] closing
+++debug Connection [4916][] closing
+++debug Connection [5171][] closing
+++debug Connection [4887][] closing
+++debug Connection [5168][] closing
+++debug Connection [5194][] closing
+++debug Connection [4830][] closing
+++debug Connection [4897][] closing
+++debug Connection [5097][] closing
+++debug Connection [4861][] closing
+++debug Connection [4928][] closing
+++debug Connection [5130][] closing
+++debug Connection [5190][] closing
+++debug Connection [4765][] closing
+++debug Connection [4986][] closing
+++debug Connection [4922][] closing
+++debug Connection [4823][] closing
+++debug Connection [4751][] closing
+++debug Connection [4831][] closing
+++debug Connection [4793][] closing
+++debug Connection [5254][] closing
+++debug Connection [5122][] closing
+++debug Connection [5165][] closing
+++debug Connection [5055][] closing
+++debug Connection [5129][] closing
+++debug Connection [5014][] closing
+++debug Connection [4899][] closing
+++debug Connection [4919][] closing
+++debug Connection [5289][] closing
+++debug Connection [5234][] closing
+++debug Connection [4787][] closing
+++debug Connection [5211][] closing
+++debug Connection [4835][] closing
+++debug Connection [4907][] closing
+++debug Connection [5037][] closing
+++debug Connection [5152][] closing
+++debug Connection [5255][] closing
+++debug Connection [4801][] closing
+++debug Connection [5150][] closing
+++debug Connection [4833][] closing
+++debug Connection [4901][] closing
+++debug Connection [5176][] closing
+++debug Connection [4949][] closing
+++debug Connection [5025][] closing
+++debug Connection [4805][] closing
+++debug Connection [5201][] closing
+++debug Connection [5011][] closing
+++debug Connection [5222][] closing
+++debug Connection [5219][] closing
+++debug Connection [5049][] closing
+++debug Connection [5265][] closing
+++debug Connection [5053][] closing
+++debug Connection [4964][] closing
+++debug Connection [5272][] closing
+++debug Connection [4930][] closing
+++debug Connection [5240][] closing
+++debug Connection [5020][] closing
+++debug Connection [4891][] closing
+++debug Connection [4921][] closing
+++debug Connection [4968][] closing
+++debug Connection [5203][] closing
+++debug Connection [5196][] closing
+++debug Connection [5145][] closing
+++debug Connection [5157][] closing
+++debug Connection [5031][] closing
+++debug Connection [5161][] closing
+++debug Connection [5056][] closing
+++debug Connection [5113][] closing
+++debug Connection [5273][] closing
+++debug Connection [5223][] closing
+++debug Connection [5267][] closing
+++debug Connection [4917][] closing
+++debug Connection [5218][] closing
+++debug Connection [4825][] closing
+++debug Connection [4815][] closing
+++debug Connection [4929][] closing
+++debug Connection [5175][] closing
+++debug Connection [5276][] closing
+++debug Connection [4779][] closing
+++debug Connection [5304][] closing
+++debug Connection [5262][] closing
+++debug Connection [5088][] closing
+++debug Connection [5247][] closing
+++debug Connection [4849][] closing
+++debug Connection [5185][] closing
+++debug Connection [5089][] closing
+++debug Connection [5058][] closing
+++debug Connection [5292][] closing
+++debug Connection [4883][] closing
+++debug Connection [5159][] closing
+++debug Connection [4942][] closing
+++debug Connection [5141][] closing
+++debug Connection [4795][] closing
+++debug Connection [4851][] closing
+++debug Connection [5101][] closing
+++debug Connection [4978][] closing
+++debug Connection [5282][] closing
+++debug Connection [5155][] closing
+++debug Connection [5281][] closing
+++debug Connection [5073][] closing
+++debug Connection [4931][] closing
+++debug Connection [5297][] closing
+++debug Connection [5216][] closing
+++debug Connection [4915][] closing
+++debug Connection [4938][] closing
+++debug Connection [4813][] closing
+++debug Connection [4908][] closing
+++debug Connection [4852][] closing
+++debug Connection [5291][] closing
+++debug Connection [5126][] closing
+++debug Connection [5128][] closing
+++debug Connection [4909][] closing
+++debug Connection [4959][] closing
+++debug Connection [5114][] closing
+++debug Connection [5245][] closing
+++debug Connection [5174][] closing
+++debug Connection [5232][] closing
+++debug Connection [5118][] closing
+++debug Connection [5030][] closing
+++debug Connection [5239][] closing
+++debug Connection [4789][] closing
+++debug Connection [5039][] closing
+++debug Connection [4993][] closing
+++debug Connection [5167][] closing
+++debug Connection [4961][] closing
+++debug Connection [4981][] closing
+++debug Connection [5186][] closing
+++debug Connection [5094][] closing
+++debug Connection [4767][] closing
+++debug Connection [5061][] closing
+++debug Connection [4963][] closing
+++debug Connection [4807][] closing
+++debug Connection [4873][] closing
+++debug Connection [4957][] closing
+++debug Connection [5259][] closing
+++debug Connection [4864][] closing
+++debug Connection [5290][] closing
+++debug Connection [4858][] closing
+++debug Connection [4843][] closing
+++debug Connection [5051][] closing
+++debug Connection [5133][] closing
+++debug Connection [5071][] closing
+++debug Connection [4759][] closing
+++debug Connection [4771][] closing
+++debug Connection [5135][] closing
+++debug Connection [5017][] closing
+++debug Connection [5269][] closing
+++debug Connection [5115][] closing
+++debug Connection [4777][] closing
+++debug Connection [5104][] closing
+++debug Connection [5046][] closing
+++debug Connection [4839][] closing
+++debug Connection [4913][] closing
+++debug Connection [5065][] closed
+++debug Connection [4847][] closed
+++debug Connection [4989][] closed
+++debug Connection [5163][] closed
+++debug Connection [5181][] closed
+++debug Connection [5107][] closed
+++debug Connection [5054][] closed
+++debug Connection [4837][] closed
+++debug Connection [5098][] closed
+++debug Connection [4991][] closed
+++debug Connection [4875][] closed
+++debug Connection [5041][] closed
+++debug Connection [4882][] closed
+++debug Connection [5205][] closed
+++debug Connection [4933][] closed
+++debug Connection [5293][] closed
+++debug Connection [5131][] closed
+++debug Connection [4853][] closed
+++debug Connection [5270][] closed
+++debug Connection [5123][] closed
+++debug Connection [5105][] closed
+++debug Connection [5149][] closed
+++debug Connection [5028][] closed
+++debug Connection [4769][] closed
+++debug Connection [5238][] closed
+++debug Connection [4943][] closed
+++debug Connection [5225][] closed
+++debug Connection [5191][] closed
+++debug Connection [5069][] closed
+++debug Connection [4755][] closed
+++debug Connection [5231][] closed
+++debug Connection [5111][] closed
+++debug Connection [4798][] closed
+++debug Connection [4783][] closed
+++debug Connection [5119][] closed
+++debug Connection [4987][] closed
+++debug Connection [5023][] closed
+++debug Connection [5172][] closed
+++debug Connection [4947][] closed
+++debug Connection [5243][] closed
+++debug Connection [4885][] closed
+++debug Connection [4838][] closed
+++debug Connection [5236][] closed
+++debug Connection [5063][] closed
+++debug Connection [4969][] closed
+++debug Connection [5085][] closed
+++debug Connection [5277][] closed
+++debug Connection [5242][] closed
+++debug Connection [4797][] closed
+++debug Connection [4893][] closed
+++debug Connection [5173][] closed
+++debug Connection [5144][] closed
+++debug Connection [5228][] closed
+++debug Connection [4945][] closed
+++debug Connection [5200][] closed
+++debug Connection [5095][] closed
+++debug Connection [5250][] closed
+++debug Connection [5083][] closed
+++debug Connection [4753][] closed
+++debug Connection [4821][] closed
+++debug Connection [5271][] closed
+++debug Connection [5142][] closed
+++debug Connection [5229][] closed
+++debug Connection [5057][] closed
+++debug Connection [5206][] closed
+++debug Connection [4889][] closed
+++debug Connection [5284][] closed
+++debug Connection [4972][] closed
+++debug Connection [5143][] closed
+++debug Connection [5298][] closed
+++debug Connection [4951][] closed
+++debug Connection [4863][] closed
+++debug Connection [5244][] closed
+++debug Connection [4918][] closed
+++debug Connection [5179][] closed
+++debug Connection [5087][] closed
+++debug Connection [5079][] closed
+++debug Connection [5138][] closed
+++debug Connection [4934][] closed
+++debug Connection [5040][] closed
+++debug Connection [5021][] closed
+++debug Connection [4845][] closed
+++debug Connection [5137][] closed
+++debug Connection [4983][] closed
+++debug Connection [5022][] closed
+++debug Connection [5253][] closed
+++debug Connection [5162][] closed
+++debug Connection [5257][] closed
+++debug Connection [5100][] closed
+++debug Connection [4940][] closed
+++debug Connection [4976][] closed
+++debug Connection [5068][] closed
+++debug Connection [5067][] closed
+++debug Connection [5121][] closed
+++debug Connection [5248][] closed
+++debug Connection [4785][] closed
+++debug Connection [5189][] closed
+++debug Connection [5050][] closed
+++debug Connection [5188][] closed
+++debug Connection [5064][] closed
+++debug Connection [4879][] closed
+++debug Connection [4811][] closed
+++debug Connection [5033][] closed
+++debug Connection [4862][] closed
+++debug Connection [5212][] closed
+++debug Connection [5286][] closed
+++debug Connection [5136][] closed
+++debug Connection [5296][] closed
+++debug Connection [5195][] closed
+++debug Connection [5093][] closed
+++debug Connection [5237][] closed
+++debug Connection [5091][] closed
+++debug Connection [5184][] closed
+++debug Connection [4924][] closed
+++debug Connection [4999][] closed
+++debug Connection [4971][] closed
+++debug Connection [5249][] closed
+++debug Connection [4985][] closed
+++debug Connection [5132][] closed
+++debug Connection [4923][] closed
+++debug Connection [5241][] closed
+++debug Connection [5226][] closed
+++debug Connection [5036][] closed
+++debug Connection [5013][] closed
+++debug Connection [4939][] closed
+++debug Connection [4761][] closed
+++debug Connection [5099][] closed
+++debug Connection [5166][] closed
+++debug Connection [4791][] closed
+++debug Connection [5287][] closed
+++debug Connection [4799][] closed
+++debug Connection [5077][] closed
+++debug Connection [5224][] closed
+++debug Connection [4888][] closed
+++debug Connection [5274][] closed
+++debug Connection [5045][] closed
+++debug Connection [4895][] closed
+++debug Connection [5160][] closed
+++debug Connection [5300][] closed
+++debug Connection [5019][] closed
+++debug Connection [5139][] closed
+++debug Connection [5075][] closed
+++debug Connection [5256][] closed
+++debug Connection [5275][] closed
+++debug Connection [5127][] closed
+++debug Connection [4817][] closed
+++debug Connection [5027][] closed
+++debug Connection [4829][] closed
+++debug Connection [5246][] closed
+++debug Connection [4927][] closed
+++debug Connection [4995][] closed
+++debug Connection [5213][] closed
+++debug Connection [5217][] closed
+++debug Connection [4855][] closed
+++debug Connection [5015][] closed
+++debug Connection [4911][] closed
+++debug Connection [5199][] closed
+++debug Connection [5010][] closed
+++debug Connection [5235][] closed
+++debug Connection [5183][] closed
+++debug Connection [5140][] closed
+++debug Connection [5285][] closed
+++debug Connection [4955][] closed
+++debug Connection [5268][] closed
+++debug Connection [4865][] closed
+++debug Connection [5084][] closed
+++debug Connection [5158][] closed
+++debug Connection [5081][] closed
+++debug Connection [5261][] closed
+++debug Connection [5090][] closed
+++debug Connection [5204][] closed
+++debug Connection [5202][] closed
+++debug Connection [4763][] closed
+++debug Connection [5197][] closed
+++debug Connection [5214][] closed
+++debug Connection [5251][] closed
+++debug Connection [5103][] closed
+++debug Connection [5034][] closed
+++debug Connection [5109][] closed
+++debug Connection [5146][] closed
+++debug Connection [5110][] closed
+++debug Connection [4773][] closed
+++debug Connection [5283][] closed
+++debug Connection [4937][] closed
+++debug Connection [4905][] closed
+++debug Connection [5047][] closed
+++debug Connection [5278][] closed
+++debug Connection [5207][] closed
+++debug Connection [4953][] closed
+++debug Connection [5164][] closed
+++debug Connection [5182][] closed
+++debug Connection [5153][] closed
+++debug Connection [5210][] closed
+++debug Connection [5301][] closed
+++debug Connection [4877][] closed
+++debug Connection [4870][] closed
+++debug Connection [5305][] closed
+++debug Connection [4914][] closed
+++debug Connection [4997][] closed
+++debug Connection [5252][] closed
+++debug Connection [5170][] closed
+++debug Connection [4903][] closed
+++debug Connection [5096][] closed
+++debug Connection [4809][] closed
+++debug Connection [5177][] closed
+++debug Connection [4977][] closed
+++debug Connection [5009][] closed
+++debug Connection [4965][] closed
+++debug Connection [5082][] closed
+++debug Connection [5156][] closed
+++debug Connection [4781][] closed
+++debug Connection [5280][] closed
+++debug Connection [5263][] closed
+++debug Connection [4803][] closed
+++debug Connection [4757][] closed
+++debug Connection [5117][] closed
+++debug Connection [4979][] closed
+++debug Connection [5029][] closed
+++debug Connection [5151][] closed
+++debug Connection [5066][] closed
+++debug Connection [4946][] closed
+++debug Connection [4941][] closed
+++debug Connection [5154][] closed
+++debug Connection [5279][] closed
+++debug Connection [5192][] closed
+++debug Connection [5048][] closed
+++debug Connection [5295][] closed
+++debug Connection [4871][] closed
+++debug Connection [5043][] closed
+++debug Connection [5032][] closed
+++debug Connection [5187][] closed
+++debug Connection [5178][] closed
+++debug Connection [4892][] closed
+++debug Connection [4819][] closed
+++debug Connection [5220][] closed
+++debug Connection [5070][] closed
+++debug Connection [5059][] closed
+++debug Connection [5294][] closed
+++debug Connection [5303][] closed
+++debug Connection [4967][] closed
+++debug Connection [5258][] closed
+++debug Connection [5092][] closed
+++debug Connection [4827][] closed
+++debug Connection [4857][] closed
+++debug Connection [5001][] closed
+++debug Connection [4975][] closed
+++debug Connection [5147][] closed
+++debug Connection [5233][] closed
+++debug Connection [4916][] closed
+++debug Connection [5171][] closed
+++debug Connection [4887][] closed
+++debug Connection [5194][] closed
+++debug Connection [5168][] closed
+++debug Connection [4830][] closed
+++debug Connection [4897][] closed
+++debug Connection [5097][] closed
+++debug Connection [4861][] closed
+++debug Connection [5130][] closed
+++debug Connection [4928][] closed
+++debug Connection [5190][] closed
+++debug Connection [4765][] closed
+++debug Connection [4986][] closed
+++debug Connection [4922][] closed
+++debug Connection [4823][] closed
+++debug Connection [4751][] closed
+++debug Connection [4831][] closed
+++debug Connection [4793][] closed
+++debug Connection [5254][] closed
+++debug Connection [5122][] closed
+++debug Connection [5165][] closed
+++debug Connection [5129][] closed
+++debug Connection [5055][] closed
+++debug Connection [5014][] closed
+++debug Connection [4899][] closed
+++debug Connection [4919][] closed
+++debug Connection [5289][] closed
+++debug Connection [5234][] closed
+++debug Connection [4787][] closed
+++debug Connection [5211][] closed
+++debug Connection [4835][] closed
+++debug Connection [4907][] closed
+++debug Connection [5255][] closed
+++debug Connection [5152][] closed
+++debug Connection [5037][] closed
+++debug Connection [4801][] closed
+++debug Connection [5150][] closed
+++debug Connection [4833][] closed
+++debug Connection [4901][] closed
+++debug Connection [5176][] closed
+++debug Connection [4949][] closed
+++debug Connection [5025][] closed
+++debug Connection [4805][] closed
+++debug Connection [5201][] closed
+++debug Connection [5011][] closed
+++debug Connection [5222][] closed
+++debug Connection [5219][] closed
+++debug Connection [5265][] closed
+++debug Connection [5049][] closed
+++debug Connection [5053][] closed
+++debug Connection [4964][] closed
+++debug Connection [5272][] closed
+++debug Connection [4930][] closed
+++debug Connection [5240][] closed
+++debug Connection [5020][] closed
+++debug Connection [4891][] closed
+++debug Connection [4921][] closed
+++debug Connection [4968][] closed
+++debug Connection [5203][] closed
+++debug Connection [5196][] closed
+++debug Connection [5145][] closed
+++debug Connection [5157][] closed
+++debug Connection [5223][] closed
+++debug Connection [4825][] closed
+++debug Connection [4917][] closed
+++debug Connection [5267][] closed
+++debug Connection [4929][] closed
+++debug Connection [5175][] closed
+++debug Connection [5304][] closed
+++debug Connection [4815][] closed
+++debug Connection [5262][] closed
+++debug Connection [5218][] closed
+++debug Connection [5031][] closed
+++debug Connection [5113][] closed
+++debug Connection [5276][] closed
+++debug Connection [5056][] closed
+++debug Connection [5273][] closed
+++debug Connection [4779][] closed
+++debug Connection [5161][] closed
+++debug Connection [5088][] closed
+++debug Connection [5247][] closed
+++debug Connection [4849][] closed
+++debug Connection [5185][] closed
+++debug Connection [5089][] closed
+++debug Connection [5058][] closed
+++debug Connection [5292][] closed
+++debug Connection [4883][] closed
+++debug Connection [5159][] closed
+++debug Connection [4942][] closed
+++debug Connection [5141][] closed
+++debug Connection [4795][] closed
+++debug Connection [4851][] closed
+++debug Connection [5101][] closed
+++debug Connection [4978][] closed
+++debug Connection [5282][] closed
+++debug Connection [5155][] closed
+++debug Connection [5281][] closed
+++debug Connection [5073][] closed
+++debug Connection [4931][] closed
+++debug Connection [5297][] closed
+++debug Connection [5216][] closed
+++debug Connection [4915][] closed
+++debug Connection [4908][] closed
+++debug Connection [4813][] closed
+++debug Connection [4852][] closed
+++debug Connection [5291][] closed
+++debug Connection [4938][] closed
+++debug Connection [5126][] closed
+++debug Connection [5128][] closed
+++debug Connection [4909][] closed
+++debug Connection [4959][] closed
+++debug Connection [5114][] closed
+++debug Connection [5245][] closed
+++debug Connection [5174][] closed
+++debug Connection [5232][] closed
+++debug Connection [5118][] closed
+++debug Connection [5030][] closed
+++debug Connection [5239][] closed
+++debug Connection [4789][] closed
+++debug Connection [5039][] closed
+++debug Connection [4993][] closed
+++debug Connection [5167][] closed
+++debug Connection [4961][] closed
+++debug Connection [4981][] closed
+++debug Connection [5186][] closed
+++debug Connection [5094][] closed
+++debug Connection [4767][] closed
+++debug Connection [5061][] closed
+++debug Connection [4963][] closed
+++debug Connection [4807][] closed
+++debug Connection [4873][] closed
+++debug Connection [4957][] closed
+++debug Connection [5259][] closed
+++debug Connection [4864][] closed
+++debug Connection [5290][] closed
+++debug Connection [4858][] closed
+++debug Connection [4843][] closed
+++debug Connection [5051][] closed
+++debug Connection [5133][] closed
+++debug Connection [5071][] closed
+++debug Connection [4759][] closed
+++debug Connection [4771][] closed
+++debug Connection [5135][] closed
+++debug Connection [5017][] closed
+++debug Connection [5269][] closed
+++debug Connection [5115][] closed
+++debug Connection [4777][] closed
+++debug Connection [5104][] closed
+++debug Connection [5046][] closed
+++debug Connection [4839][] closed
+++debug Connection [4913][] closed
(node:1) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 252): Neo4jError: Connection acquisition timed out in 60000 ms.
(node:1) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 253): Neo4jError: Connection acquisition timed out in 60000 ms.
(node:1) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 254): Neo4jError: Connection acquisition timed out in 60000 ms.
(node:1) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 255): Neo4jError: Connection acquisition timed out in 60000 ms.
(node:1) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 256): Neo4jError: Connection acquisition timed out in 60000 ms.
(node:1) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 257): Neo4jError: Connection acquisition timed out in 60000 ms.
(node:1) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 258): Neo4jError: Connection acquisition timed out in 60000 ms.
(node:1) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 259): Neo4jError: Connection acquisition timed out in 60000 ms.
(node:1) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 260): Neo4jError: Connection acquisition timed out in 60000 ms.
(node:1) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 261): Neo4jError: Connection acquisition timed out in 60000 ms.
(node:1) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 262): Neo4jError: Connection acquisition timed out in 60000 ms.
(node:1) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 263): Neo4jError: Connection acquisition timed out in 60000 ms.
(node:1) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 264): Neo4jError: Connection acquisition timed out in 60000 ms.
(node:1) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 265): Neo4jError: Connection acquisition timed out in 60000 ms.
(node:1) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 266): Neo4jError: Connection acquisition timed out in 60000 ms.
(node:1) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 267): Neo4jError: Connection acquisition timed out in 60000 ms.
(node:1) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 268): Neo4jError: Connection acquisition timed out in 60000 ms.
(node:1) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 301): Neo4jError: Connection acquisition timed out in 60000 ms.
(node:1) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 302): Neo4jError: Connection acquisition timed out in 60000 ms.
(node:1) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 303): Neo4jError: Connection acquisition timed out in 60000 ms.
(node:1) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 304): Neo4jError: Connection acquisition timed out in 60000 ms.
(node:1) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 305): Neo4jError: Connection acquisition timed out in 60000 ms.
(node:1) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 306): Neo4jError: Connection acquisition timed out in 60000 ms.
(node:1) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 307): Neo4jError: Connection acquisition timed out in 60000 ms.
(node:1) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 308): Neo4jError: Connection acquisition timed out in 60000 ms.
(node:1) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 309): Neo4jError: Connection acquisition timed out in 60000 ms.
(node:1) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 310): Neo4jError: Connection acquisition timed out in 60000 ms.
(node:1) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 311): Neo4jError: Connection acquisition timed out in 60000 ms.
(node:1) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 312): Neo4jError: Connection acquisition timed out in 60000 ms.
(node:1) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 313): Neo4jError: Connection acquisition timed out in 60000 ms.
(node:1) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 314): Neo4jError: Connection acquisition timed out in 60000 ms.
(node:1) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 315): Neo4jError: Connection acquisition timed out in 60000 ms.
(node:1) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 316): Neo4jError: Connection acquisition timed out in 60000 ms.
(node:1) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 329): Neo4jError: Connection acquisition timed out in 60000 ms.
(node:1) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 330): Neo4jError: Connection acquisition timed out in 60000 ms.
(node:1) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 331): Neo4jError: Connection acquisition timed out in 60000 ms.
(node:1) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 332): Neo4jError: Connection acquisition timed out in 60000 ms.
(node:1) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 333): Neo4jError: Connection acquisition timed out in 60000 ms.
(node:1) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 334): Neo4jError: Connection acquisition timed out in 60000 ms.
(node:1) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 349): Neo4jError: Connection acquisition timed out in 60000 ms.
(node:1) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 350): Neo4jError: Connection acquisition timed out in 60000 ms.
(node:1) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 351): Neo4jError: Connection acquisition timed out in 60000 ms.
(node:1) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 352): Neo4jError: Connection acquisition timed out in 60000 ms.
elielr01 commented 5 years ago

Update in this issue:

I was checking the rest of the logs, and I saw several errors like this some hours before all the connections were suddenly closed.

+++debug Connection [2065][] S: FAILURE {"signature":127,"fields":[{"code":"Neo.TransientError.Request.NoThreadsAvailable","message":"There are no available threads to serve this request at the moment. You can retry at a later time or consider increasing max thread pool size for bolt connector(s)."}]}
+++error Connection [2065][] experienced a fatal error {"code":"ProtocolError","name":"Neo4jError"}
+++debug Connection [2065][] destroyed and can't be released to the pool neo4j-prod.theofe.com:7687 because it is not functional
+++debug Connection [2065][] closing
+++debug Connection [1586][] acquired from the pool

Does this could be the cause that all the connections from the driver are suddenly closed?

elielr01 commented 5 years ago

Update in this issue:

I changed the configuration of the Neo4j Database, setting thread_pool_min_size=400 and thread_pool_max_size=800 and it stopped causing problems to the driver. So, apparently when reaching the max thread pool size, this caused the driver to close all connections in some point (Which I still think is not the expected behaviour)

elielr01 commented 5 years ago

Update in this issue:

Even with the new configuration of thread_pool_min_size=400 and thread_pool_max_size=800, it stops working and throws a lot of errors like this:

{ Neo4jError: Connection acquisition timed out in 60000 ms.

    at captureStacktrace (/app/node_modules/neo4j-driver/lib/v1/result.js:200:15)
    at new Result (/app/node_modules/neo4j-driver/lib/v1/result.js:73:19)
    at _newRunResult (/app/node_modules/neo4j-driver/lib/v1/transaction.js:344:10)
    at Object.run (/app/node_modules/neo4j-driver/lib/v1/transaction.js:253:14)
    at Transaction.run (/app/node_modules/neo4j-driver/lib/v1/transaction.js:122:26)
    at neo4jsession.writeTransaction.tx (/app/core/neo4jhelper.js:44:71)
    at TransactionExecutor._safeExecuteTransactionWork (/app/node_modules/neo4j-driver/lib/v1/internal/transaction-executor.js:136:22)
    at TransactionExecutor._executeTransactionInsidePromise (/app/node_modules/neo4j-driver/lib/v1/internal/transaction-executor.js:124:32)
    at /app/node_modules/neo4j-driver/lib/v1/internal/transaction-executor.js:67:15
    at new Promise (<anonymous>)
    at new F (/app/node_modules/core-js/library/modules/_export.js:36:28)
    at TransactionExecutor.execute (/app/node_modules/neo4j-driver/lib/v1/internal/transaction-executor.js:66:14)
    at Session._runTransaction (/app/node_modules/neo4j-driver/lib/v1/session.js:276:40)
    at Session.writeTransaction (/app/node_modules/neo4j-driver/lib/v1/session.js:269:19)
    at Promise (/app/core/neo4jhelper.js:44:45)
    at new Promise (<anonymous>) code: 'N/A', name: 'Neo4jError' }

Changing the configuration only seems to delay this error regarding connection acquisition. Please help, I don't know if I am not using the sessions correctly. This is an example of how I am using them in every call:

isPortConnected: portId => {
    return new Promise((resolve, reject) => {
      var neo4jsession = driver.session();
      var connectedPortCountPromise = neo4jsession.writeTransaction(tx =>
        tx.run(`
          MATCH (p:Port)-[:DISTANCE]-()
          WHERE p.port_id = ${portId}
          RETURN count(p)`
        )
      );

      connectedPortCountPromise.then(connectedPortCount => {
        resolve(!(
          connectedPortCount &&
          Array.isArray(connectedPortCount.records) &&
          connectedPortCount.records.length > 0 &&
          connectedPortCount.records[0].get("count(p)").isZero()
        ));
      }).catch(e => {
        console.error(e);
        reject(e);
      }).then(() => {
        neo4jsession.close();
      });
    });
  },

I am following the docs on how to use the sessions, so I am expecting that the connections are released as soon as I do a .close(). However, it seems that the connections are never released.

zhenlineo commented 5 years ago

Hi @elielr01 Your code of using the driver looks correct. So there might be a bug in the driver that does not release the connection properly. It might relate to the Protocol error that you mentioned. Maybe the pool does not remove the connection count that is directly destroyed after a protocol error. We will have a look and come back to you as soon as possible. Thanks for the detailed logs!

We will keep you updated.

zhenlineo commented 5 years ago

Hi @elielr01,

We identified one js bug that could cause your problem. The js bug is fixed in this PR https://github.com/neo4j/neo4j-javascript-driver/pull/453. We might not release the connection when the connection is failed to establish in this line.

We will do a patch release soon. It would be great if you could verify if the fix addresses your issue in the coming release.

Cheers, Zhen

GlacianNex commented 5 years ago

We have encountered exactly the same problem in our deployment. I have tried deploying 1.7.4 to our containers, but within two hours the same issue came back.

ali-ince commented 5 years ago

Hi @GlacianNex & @elielr01,

Have you tried the latest driver release 1.7.5? Do you still experience the same problem?

Thanks.

elielr01 commented 5 years ago

Hi @ali-ince

Unfortunately, we changed our service and stop using neo4j some months ago, so I'm not sure if I can replicate my issue. Although I did check the patch in the PR and it looked as that did solve the problem.

matthewoden commented 5 years ago

We're doing something similar, getting basically verbatim results to @elielr01, while using 1.7.5.

If we exceed our thread pool limits, we get errors - and understandably so. However, once this event occurs, a chunk of our driver's connection pool is never released.

I was digging into the internals to try and understand how a session's lifecycle worked, in case we might be missing something. Under connectionHolders - it seems that if there's an error in releasing the connection, the promise is caught, and the error is suppressed?

Should any errors that occur here get logged, rather than ignored?

https://github.com/neo4j/neo4j-javascript-driver/blob/4.0/src/internal/connection-holder.js#L129 (edit, I was on the 1.7 branch - the error handler is still there though)

whostolebenfrog commented 5 years ago

As another data point we just hit this today also using 1.7.5. As far as we can see it never recovers.

GlacianNex commented 5 years ago

Yeah likewise, we ended up coding around it (resetting the connection where it enters that state).

On Fri, Sep 27, 2019 at 4:10 AM Ben Griffiths notifications@github.com wrote:

As another data point we just hit this today also using 1.7.5. As far as we can see it never recovers.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/neo4j/neo4j-javascript-driver/issues/446?email_source=notifications&email_token=AA2RFDILDPUOMMYRPJK7KQDQLW5X5A5CNFSM4HBV44H2YY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOD7YEGLQ#issuecomment-535839534, or mute the thread https://github.com/notifications/unsubscribe-auth/AA2RFDOHCUOBTQ5IQ4QL7ADQLW5X5ANCNFSM4HBV44HQ .

matthewoden commented 5 years ago

@GlacianNex - any chance you can share how you wrote around it?

GlacianNex commented 5 years ago

In our case the application is stateless and is running a docker container. Once we start experiencing the connection pool issues we just stop the entire application and restart the container.

When the container comes back the problem seems to be resolved. I am REALLY not happy with the solution but we have spent too much time on this problem internally and this allowed us to move forward.

I hope this helps.

matthewoden commented 5 years ago

@GlacianNex Thanks! That's basically what we did. We recorded the driver's internals to get an idea of when/how often/why we got into this state, and then scheduled rolling deployments to reset the driver state at intervals.

Hopefully @ali-ince @zhenlineo and the rest of the team can figure this one out.

gpierrick commented 4 years ago

Running into this issue as well under heavy load

Driver: 1.7.6

Connection acquisition timed out in 60000 ms.
gpierrick commented 4 years ago

Is there a version of the driver that doesn't have this issue?

fedevela commented 4 years ago

This issue is severe enough for our team that we are not going to develop our application based on this driver, rather we are going to use: https://github.com/thingdom/node-neo4j which appears to be more stable, or at least does not have a critical error that only appears in production under high loads.

:(

matthewoden commented 4 years ago

@fedevela I'd be wary of that, it's:

I get your frustrations. Our team is struggling to handle recoveries with this driver too. And there doesn't seem to be any updates from the neo team around this either.

We've got a new working solution: Our team moved from scheduled redeploys, to rotating out the active driver with a new one.

It's a complicated workaround solution, for sure. And it won't prevent threadpool problems. But it does mean we can recover now without a redeploy, and stay in a stable state. I'd share the exact code, but it's locked down as proprietary.

fedevela commented 4 years ago

It's a complicated workaround solution, for sure. And it won't prevent threadpool problems. But it does mean we can recover now without a redeploy, and stay in a stable state. I'd share the exact code, but it's locked down as proprietary.

@matthewoden thank you for the insight, you have shed a lot of light on the subject, thank you very much

it is frustrating for sure; the old driver has been working for us without problems, i had been considering changing to this, the official driver :/ but will not do so for the near future

We have not yet experienced high loads, nor tested them but the systems have been quite stable for now

thank you very much again!

zhenlineo commented 4 years ago

Hi guys,

Sorry to not back on this problem recently. I will have a closer look at this issue tomorrow. Will keep you guys updated.

Cheers, Zhen

zhenlineo commented 4 years ago

Hi,

We've been looking into this issue. Most of our investigation is based on @elielr01 's logs and problem description. For his original issue, we suspect that his log is missing a info level log for driver.close.

Here might be what happened in his case (Single community server + bolt 1.7.5 driver):

However as so many others are also have the same problem thus we would like to ask for more information from everyone who has this issue:

Thanks in advance. Zhen

zhenlineo commented 4 years ago

Hi @matthewoden,

May I ask if you could help us with this issue by giving us more logs. We are interested in

When doing driver logs, you can also set up a periodic logger where you can print driver connection pool using the following code to help us better know if there are any connection leaks:

log.debug("Active Connections: " + JSON.stringify(driver._pool._activeResourceCounts))
log.debug("Idle Connections: " + JSON.stringify(driver._pool._pools))
log.debug("All Connection count: " + JSON.stringify(Object.keys(driver._openConnections).length))

We've been looking at @elielr01 logs and code, but we unfortunately cannot find a good reason to fully explain the cause of the problem. So we would like to ask everyone here to give us more informations about their running env and logs.

Thanks in advance. Zhen

matthewoden commented 4 years ago

@zhenlineo Fantastic - I'll see what I can do. We currently have a solution that keeps things stable for our users, but I think I understand how we get into this state enough to recreate it on an isolated instance.

Edit: I can say that prior to my driver-rotation solution, we never closed the driver. So unless the driver is closing itself...

matthewoden commented 4 years ago

Ok, so I can recreate the state.

neo4j.conf required to recreate the issue locally:

dbms.connector.bolt.thread_pool_min_size=1
dbms.connector.bolt.thread_pool_max_size=2

(Yes, I know this is impossibly small. But the issue starts for us when the threadpool is exceeded, and this makes that happen pretty much immediately.)

Server logs from running neo in console mode, up to the point of the problem. Small redactions for proprietary nonsense.

2019-11-21 16:00:55.931+0000 INFO  ======== Neo4j 3.4.7 ========
2019-11-21 16:00:55.972+0000 INFO  Starting...
2019-11-21 16:00:57.298+0000 INFO  Initiating metrics...
2019-11-21 16:00:59.790+0000 INFO  Sending metrics to CSV file at /Users/[REDACTED]/neo4j-enterprise-3.4.7/metrics
2019-11-21 16:01:00.046+0000 INFO  Bolt enabled on 127.0.0.1:7687.
2019-11-21 16:01:02.814+0000 WARN  Server thread metrics not available (missing neo4j.server.threads.jetty.all)
2019-11-21 16:01:02.815+0000 WARN  Server thread metrics not available (missing neo4j.server.threads.jetty.idle)
2019-11-21 16:01:07.114+0000 INFO  Started.
2019-11-21 16:01:07.194+0000 INFO  Mounted REST API at: /db/manage
2019-11-21 16:01:07.208+0000 INFO  Mounted unmanaged extension [REDACTED at [/[REDACTED]]
2019-11-21 16:01:07.279+0000 INFO  Server thread metrics has been registered successfully
2019-11-21 16:01:08.304+0000 INFO  Remote interface available at http://localhost:7474/
2019-11-21 16:01:45.915+0000 ERROR Unable to schedule bolt session 'f45c89fffeb319db-00014963-00000006-88f6d86f2e58884e-af7fc114' for execution since there are no available threads to serve it at the moment. You can retry at a later time or consider increasing max thread pool size for bolt connector(s).

Snippet of the driver logs on debug right before the error:

Connection [0][] C: RUN BEGIN {"bookmark":"neo4j:bookmark:v1:tx714297","bookmarks":["neo4j:bookmark:v1:tx714287","neo4j:bookmark:v1:tx714291","neo4j:bookmark:v1:tx714292","neo4j:bookmark:v1:tx714293","neo4j:bookmark:v1:tx714294","neo4j:bookmark:v1:tx714295","neo4j:bookmark:v1:tx714296","neo4j:bookmark:v1:tx714297"]}
Connection [0][] C: PULL_ALL
Connection [0][] C: RUN match (g:Group) where g.id in {groupIds}
        optional match (r1:Application)<-[:OWNS]-(g)
        optional match (r2:Application)<-[:OWNS]-(:Group)-[:APPLIES_TO*]->(g)
        return g.id as key, apoc.coll.union(collect(r1.id), collect(r2.id)) as value {"groupIds":["BUGLE-EMPLOYEES"]}
Connection [0][] C: PULL_ALL
Connection [2][] S: SUCCESS {"signature":112,"fields":[{"result_available_after":{"low":0,"high":0},"fields":[]}]}
Connection [2][] S: SUCCESS {"signature":112,"fields":[{"bookmark":"neo4j:bookmark:v1:tx714297"}]}
Connection [2][] S: SUCCESS {"signature":112,"fields":[{"result_available_after":{"low":1,"high":0},"fields":["key","value"]}]}
Connection [2][] S: SUCCESS {"signature":112,"fields":[{"result_consumed_after":{"low":0,"high":0},"type":"r"}]}
Connection [2][] C: RUN COMMIT {}
Connection [2][] C: PULL_ALL
Connection [1][] S: SUCCESS {"signature":112,"fields":[{"result_available_after":{"low":0,"high":0},"fields":[]}]}
Connection [1][] S: SUCCESS {"signature":112,"fields":[{"bookmark":"neo4j:bookmark:v1:tx714297"}]}
Connection [1][] S: SUCCESS {"signature":112,"fields":[{"result_available_after":{"low":0,"high":0},"fields":["key","value"]}]}
Connection [1][] S: RECORD {"signature":113,"fields":[["BUGLE-EMPLOYEES",[]]]}
Connection [1][] S: SUCCESS {"signature":112,"fields":[{"result_consumed_after":{"low":0,"high":0},"type":"r"}]}
Connection [1][] C: RUN COMMIT {}
Connection [1][] C: PULL_ALL
Connection [2][] S: SUCCESS {"signature":112,"fields":[{"result_available_after":{"low":0,"high":0},"fields":[]}]}
Connection [2][] S: SUCCESS {"signature":112,"fields":[{"bookmark":"neo4j:bookmark:v1:tx714297"}]}
Connection [2][] C: RESET
Connection [1][] S: SUCCESS {"signature":112,"fields":[{"result_available_after":{"low":0,"high":0},"fields":[]}]}
Connection [1][] S: SUCCESS {"signature":112,"fields":[{"bookmark":"neo4j:bookmark:v1:tx714297"}]}
Connection [1][] C: RESET
Connection [2][] S: SUCCESS {"signature":112,"fields":[{}]}
debug Connection [2][] released to the pool localhost:7687
Connection [1][] S: SUCCESS {"signature":112,"fields":[{}]}
debug Connection [1][] released to the pool localhost:7687

At this point, the logs go quiet. Nothing happens. The driver hangs indefinitely. No queries proceed.

Now, I can't log verbatim what you posted there. We've got circular references that need cleaning up, and some pretty deep objects. For other folks running these logs, I used the following to do that:

const clean = (obj) => {
    let i = 0

    return (key, value) => {
        if (i !== 0 && typeof obj === 'object' && typeof value === 'object' && obj == value)
            return '[Circular]'
        // you can't go deeper than 30 nested layers, either.
        if (i >= 29) return '[Unknown]'

        ++i 

        return value
    }
}
const stringify = (obj) => JSON.stringify(obj, clean(obj))

If you need more specific information, let me know what fields.

Anyway, now that I can stringify, it produced the following:

Active Connections: {"localhost:7687":1}
Idle Connections: {"localhost:7687":[]}
All Connection count: 2
Active Connections: {"localhost:7687":2}
Idle Connections: {"localhost:7687":[]}
All Connection count: 2
Active Connections: {}
Idle Connections: {"localhost:7687":[{"id":1,"address":{"_host":"localhost","_resolved":null,"_port":7687,"_hostPort":"localhost:7687","_stringValue":"localhost:7687"},"server":{"address":"localhost:7687","version":"Neo4j/3.4.7"},"creationTimestamp":1574355573504,"_errorHandler":{"_errorCode":"ServiceUnavailable"},"_disableLosslessIntegers":false,"_pendingObservers":[],"_currentObserver":{},"_ch":{"id":1,"_pending":null,"_open":true,"_error":null,"_handleConnectionError":"[Unknown]","_handleConnectionTerminated":"[Unknown]","_connectionErrorCode":"[Unknown]","_conn":"[Unknown]","onerror":"[Unknown]","onmessage":"[Unknown]"},"_dechunker":"[Unknown]","_chunker":"[Unknown]","_log":"[Unknown]","_dbConnectionId":"[Unknown]","_protocol":"[Unknown]","_currentFailure":"[Unknown]","_isBroken":"[Unknown]","_release":"[Unknown]"},"[Unknown]"]}
All Connection count: 2
Active Connections: {}
Idle Connections: {"localhost:7687":[{"id":0,"address":{"_host":"localhost","_resolved":null,"_port":7687,"_hostPort":"localhost:7687","_stringValue":"localhost:7687"},"server":{"address":"localhost:7687","version":"Neo4j/3.4.7"},"creationTimestamp":1574355573394,"_errorHandler":{"_errorCode":"ServiceUnavailable"},"_disableLosslessIntegers":false,"_pendingObservers":[],"_currentObserver":{},"_ch":{"id":0,"_pending":null,"_open":true,"_error":null,"_handleConnectionError":"[Unknown]","_handleConnectionTerminated":"[Unknown]","_connectionErrorCode":"[Unknown]","_conn":"[Unknown]","onerror":"[Unknown]","onmessage":"[Unknown]"},"_dechunker":"[Unknown]","_chunker":"[Unknown]","_log":"[Unknown]","_dbConnectionId":"[Unknown]","_protocol":"[Unknown]","_currentFailure":"[Unknown]","_isBroken":"[Unknown]","_release":"[Unknown]"},"[Unknown]","[Unknown]"]}
All Connection count: 3

That last state is when the driver hangs up - it never changes. I dropped the maxConnectionLifetime to 30 seconds, then let it run for a minute.

Here's that event in isolation, for easier consumption.

Active Connections: {"localhost:7687":1}
Idle Connections: {"localhost:7687":[{"id":1,"address":{"_host":"localhost","_resolved":null,"_port":7687,"_hostPort":"localhost:7687","_stringValue":"localhost:7687"},"server":{"address":"localhost:7687","version":"Neo4j/3.4.7"},"creationTimestamp":1574355573504,"_errorHandler":{"_errorCode":"ServiceUnavailable"},"_disableLosslessIntegers":false,"_pendingObservers":[],"_currentObserver":{},"_ch":{"id":1,"_pending":null,"_open":true,"_error":null,"_handleConnectionError":"[Unknown]","_handleConnectionTerminated":"[Unknown]","_connectionErrorCode":"[Unknown]","_conn":"[Unknown]","onerror":"[Unknown]","onmessage":"[Unknown]"},"_dechunker":"[Unknown]","_chunker":"[Unknown]","_log":"[Unknown]","_dbConnectionId":"[Unknown]","_protocol":"[Unknown]","_currentFailure":"[Unknown]","_isBroken":"[Unknown]","_release":"[Unknown]"},"[Unknown]"]}
All Connection count: 3

Digging deeper into that connection on a second pass, without using stringify

  Connection {
    id: 2,
    address: ServerAddress {
      _host: 'localhost',
      _resolved: null,
      _port: 7687,
      _hostPort: 'localhost:7687',
      _stringValue: 'localhost:7687'
    },
    server: { address: 'localhost:7687', version: 'Neo4j/3.4.7' },
    creationTimestamp: 1574357130760,
    _errorHandler: ConnectionErrorHandler {
      _errorCode: 'ServiceUnavailable',
      _handleUnavailability: [Function: noOpHandler],
      _handleWriteFailure: [Function: noOpHandler]
    },
    _disableLosslessIntegers: false,
    _pendingObservers: [],
    _currentObserver: {
      onError: [Function: onError],
      onCompleted: [Function: NO_OP],
      onNext: [Function: NO_OP]
    },
    _ch: NodeChannel {
      id: 2,
      _pending: null,
      _open: true,
      _error: null,
      _handleConnectionError: [Function: bound _handleConnectionError],
      _handleConnectionTerminated: [Function: bound _handleConnectionTerminated],
      _connectionErrorCode: 'ServiceUnavailable',
      _conn: [TLSSocket],
      onerror: [Function: bound _handleFatalError],
      onmessage: [Function]
    },
    _dechunker: Dechunker {
      _currentMessage: [],
      _partialChunkHeader: 0,
      _state: [Function: AWAITING_CHUNK],
      onmessage: [Function],
      _chunkSize: 3
    },
    _chunker: Chunker {
      position: 7492,
      length: 0,
      _bufferSize: 1400,
      _ch: [NodeChannel],
      _buffer: [NodeBuffer],
      _currentChunkStart: 0,
      _chunkOpen: false
    },
    _log: Logger { _level: 'error', _loggerFunction: [Function: logger] },
    _dbConnectionId: undefined,
    _protocol: BoltProtocol {
      _connection: [Circular],
      _packer: [Packer],
      _unpacker: [Unpacker]
    },
    _currentFailure: null,
    _isBroken: false,
    _release: [Function]
  }

Seems when the threadpool is exceeded, it's a service availability error? The connection is left open, and not marked as an error.

At this point, I dug into the driver to add some extra logging. In there, I found a noOp handler that just returns the error without running any checks. That doesn't seem great.

The connection-holder also has an ignoreError function that straight up swallows the error. I mentioned this upthread. There's no logging, no surfacing any issue to the parent application.

... so yeah, I put some logging in the ignoreError method. Ran my test again and:

    at captureStacktrace ([REDACTED]/node_modules/neo4j-driver/lib/v1/result.js:199:15)
    at new Result ([REDACTED]/node_modules/neo4j-driver/lib/v1/result.js:65:19)
    at finishTransaction ([REDACTED]/node_modules/neo4j-driver/lib/v1/transaction.js:337:10)
    at Object.commit ([REDACTED]/node_modules/neo4j-driver/lib/v1/transaction.js:217:17)
    at Transaction.commit ([REDACTED]/node_modules/neo4j-driver/lib/v1/transaction.js:117:35)
    at [REDACTED]/data/boltClient.js:38:22
    at processTicksAndRejections (internal/process/task_queues.js:93:5)
    at async [REDACTED]/data/boltClient.js:21:26) {
  code: 'Neo.TransientError.Request.NoThreadsAvailable',
  name: 'Neo4jError'

Well, hot damn. The threadpool error!

Now, I had been running on a hot instance. So I shut everything down, and tried to recreate from scratch. Turns out, this error doesn't get returned to the client until the neo server exceeds the threadpool limit 10 times.

Edit: Clarity

zhenlineo commented 4 years ago

Hi @elielr01 , Thanks for the detailed logging. I think this is actually caused by this bug on the server side:

Failure message is not flushed when no free work thread is available When the worker thread pool is full, bolt server will fail new requests from clients. However this error is not flushed correctly to clients. This fix makes bolt server to first flush the failure message to clients and then close the connection to enforce the clients failing fast without waiting for more responses.

The bug was found in 3.5 and then fixed in 3.5.6.

From your logs, it looks like connection 0 sends messages to server but none of the messages was answered by the server. Your later print shows the connection 0 get rejected by server with a NoThreadAvailable error. This error give one reply to one of the sent messages of the driver, but the driver are waiting for more. However server think the conversation is already done, so the server does not pick up any more messages from this connection. Thus we end up with this driver connection is hold up in the middle.

I just verified 3.4 servers all suffers from this bug. I would suggest you to upgrade to latest 3.5 servers. If you cannot upgrade to latest 3.5, and you have a support contract with Neo4j, you shall consider raising a support case there.

Thanks again for the detailed logging to help us understand this issue! Cheers, Zhen

matthewoden commented 4 years ago

@zhenlineo Fantastic! I just ran a test upgrade to 3.5.12, and blew straight past the hangup issue and immediately returned an error.

(Obviously avoiding the threadpool issues is on us)

fedevela commented 4 years ago

@matthewoden We are having neo4j return custom json so we are not running into any issues at all with Neo4J 3.5.12

  • doesn't support neo past 2.1
technige commented 4 years ago

@zhenlineo - looks like this can be closed now, can you confirm?

xihajun commented 2 years ago

mark