Skip to content

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

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
elielr01 opened this issue Mar 27, 2019 · 29 comments
Closed

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

elielr01 opened this issue Mar 27, 2019 · 29 comments

Comments

@elielr01
Copy link

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
Copy link
Author

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
Copy link
Author

elielr01 commented Apr 4, 2019

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 elielr01 changed the title All connections from pool are suddenly closed All connections from pool are suddenly closed or never released Apr 30, 2019
@elielr01
Copy link
Author

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
Copy link
Contributor

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
Copy link
Contributor

Hi @elielr01,

We identified one js bug that could cause your problem.
The js bug is fixed in this PR #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
Copy link

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
Copy link
Contributor

Hi @GlacianNex & @elielr01,

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

Thanks.

@elielr01
Copy link
Author

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
Copy link

matthewoden commented Sep 24, 2019

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
Copy link

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

@GlacianNex
Copy link

GlacianNex commented Sep 27, 2019 via email

@matthewoden
Copy link

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

@GlacianNex
Copy link

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
Copy link

@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
Copy link

Running into this issue as well under heavy load

Driver: 1.7.6

Connection acquisition timed out in 60000 ms.

@gpierrick
Copy link

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

@fedevela
Copy link

fedevela commented Nov 18, 2019

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
Copy link

matthewoden commented Nov 18, 2019

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

  • no longer actively developed
  • doesn't use the bolt API (which is probably why you don't have the issue - there's no connection pool)
  • doesn't support neo past 2.1

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.

  • On each new session, do a quick inspection of driver internals. If the driver has 1.5 * maxConnectionPoolSize connections we assume it's potentially in a bad state (that may be overzealous, but it's been working for us).
  • At that point, we create and point the app to a new driver. the Old driver is moved to a driver graveyard. Basically, an array of bad drivers that we periodically inspect and close. They're left alive long enough to let old connections drain, then closed.
  • We use p-queue in front of our session-creation code to queue up database requests. Our max number of sessions per instance is equal to our maxConnectionPoolSize. Basically, we handle the connection backpressure ourselves, rather than relying on the driver to do it for us.
  • we then put in alerts and monitoring to see if we're creating new drivers too often.

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
Copy link

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
Copy link
Contributor

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
Copy link
Contributor

zhenlineo commented Nov 20, 2019

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):

  • Connection pool is drained
  • Somewhere a driver close is called
  • Cannot use driver to create more connection after driver close.
    This would be the expected behaviour for using this 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:

  • Server version, e.g. Community 3.5.10
  • Server mode, e.g. Cluster/Single instance
  • Driver connection scheme, e.g. bolt/bolt+routing
  • Driver version, e.g. 1.7.6

Thanks in advance.
Zhen

@zhenlineo
Copy link
Contributor

Hi @matthewoden,

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

  • full driver logs (like the one given by @elielr01, but also with timestamp), and
  • full database logs including debug and console logs (We can skip query logs).

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
Copy link

matthewoden commented Nov 20, 2019

@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
Copy link

matthewoden commented Nov 21, 2019

Ok, so I can recreate the state.

  • Server version: Enterprise 3.4.7
  • Server mode: Cluster and Single.
  • Driver connection scheme: bolt+routing on cluster, bolt on single
  • Driver version: 1.7.6

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
Copy link
Contributor

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
Copy link

@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
Copy link

fedevela commented Nov 25, 2019

@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
Copy link
Contributor

technige commented Jan 2, 2020

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

@xihajun
Copy link

xihajun commented Sep 20, 2022

mark

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

10 participants