Many circuits are created and almost immediately destroyed by the exit nodes due to inactivity

[devos50]

In #4088, I've added a feature to log some information about the circuits at the exit nodes. A run of a few minutes results in the following CSV file. The first column is the circuit ID, the second column indicates the time the circuit lived, the third/fourth column shows the bytes_up and bytes_down and the last column shows the reason for circuit destruction.

2078322086,27.007186,0,0,no activity
1893005884,54.359702,446,324,no activity
2955128466,29.505862,65,68,no activity
3093337375,22.897331,20,0,no activity
2955128466,34.507234,65,68,no activity
3093337375,27.898658,20,0,no activity
2750601554,20.742546,0,0,no activity
2750601554,25.740851,0,0,no activity
3623719494,24.257649,0,0,no activity
1783216353,29.231921,104,0,no activity
4223814626,2.814926,0,0,
1623748364,20.743114,0,0,no activity
3623719494,29.257975,0,0,no activity
498520663,44.992106,16,0,no activity
1783216353,34.232439,104,0,no activity
1623748364,25.743260,0,0,no activity
498520663,49.992044,16,0,no activity
2929674975,33.386279,104,0,no activity
1797339303,23.820674,0,0,no activity
2929674975,38.385843,104,0,no activity
3455615041,23.383245,104,0,no activity
1797339303,28.823811,0,0,no activity
1646479237,39.233357,718,1431,no activity
3455615041,28.380437,104,0,no activity
4061579083,44.084484,104,300,no activity
1646479237,44.235536,718,1431,no activity
4061579083,49.086648,104,300,no activity
1194448914,0.676341,0,0,
1409582478,0.013410,0,0,
2290753024,24.514742,104,0,no activity
2238496621,46.475364,208,610,no activity
1735764104,0.288948,0,0,
2290753024,29.514712,104,0,no activity
232656410,43.953024,208,317,no activity
3844038346,23.616915,0,0,no activity
2238496621,51.475535,208,610,no activity
2411362442,23.259081,0,0,no activity
3192865431,22.080801,0,0,no activity
232656410,48.954999,208,317,no activity
3844038346,28.618872,0,0,no activity
2411362442,28.257300,0,0,no activity
3192865431,27.078936,0,0,no activity
4008470744,35.287260,104,0,no activity
4008470744,40.287311,104,0,no activity
417013631,23.402928,0,0,no activity
2318845883,24.543171,0,0,no activity
3456353663,24.250833,0,0,no activity
4242009580,25.944144,104,0,no activity
2293278025,286.691194,38451,385282,
2673112534,24.745116,0,0,no activity
3456353663,29.247763,0,0,no activity
3347002322,24.191714,104,283,no activity
3670008918,64.345773,332,0,no activity
4242009580,30.941272,104,0,no activity
2673112534,29.745325,0,0,no activity
303768077,24.116485,0,0,no activity
2802279222,23.382389,0,0,no activity
2137252041,42.981208,2496,1746,no activity
3670008918,69.346372,332,0,no activity

As we see, there are many circuits which are destroyed due to inactivity. This is a problem since these circuits take up slots which could be used by circuits that actually download something.

@egbertbouman do you have an explanation for this behavior?

[qstokkink]

As I recall the reason for destruction is always 0 right?

[qstokkink]

Possibly the circuit or exit_socket's last_incoming is not set correctly?

[qstokkink]

It seems the keep-alive interval is 15 seconds:

https://github.com/Tribler/py-ipv8/blob/75b6a311a09bf29c203eab98048e955c70305069/ipv8/messaging/anonymization/tunnel.py#L42

And the circuit drop time is 20 seconds:

https://github.com/Tribler/py-ipv8/blob/d58ffb8a4bdae1e0fe0f057ccaa9e1a6e7f3d613/ipv8/messaging/anonymization/community.py#L97

Seems to me that, especially under high load, this is a bit close together. We might want to change the inactive period to something like a minute.

[synctext]

Good details. Feel free to fix this and do a 7.2.3 release (my 2-hop downloads are now stuck for 2 days).

[egbertbouman]

After some investigation, it turns out that the exit nodes were timing out because no traffic was being sent over them. I fixed this by also updating the ExitSocket timestamp in the on_ping. I think Tribler is now more affected by this then before, since we are no longer waiting to start the download until after circuit creation (#4165).