I'm working on an exitmap module that wants to feed order of 5000 short-lived streams through each exit relay. I think this is running foul of some sort of upper limit (in STEM, or in Tor itself, not sure) on the number of streams a circuit can be used for, or how long, or something. What I see in the logs (note: I've modified eventhandler.py for more detailed debug logs) looks like
2016-04-22 16:07:53,306 [DEBUG]: Circuit status change: CIRC 6 LAUNCHED PURPOSE=GENERAL TIME_CREATED=2016-04-22T20:07:53.305851 2016-04-22 16:07:53,325 [DEBUG]: Circuit status change: CIRC 6 EXTENDED [fp] PURPOSE=GENERAL TIME_CREATED=2016-04-22T20:07:53.305851 2016-04-22 16:07:54,114 [DEBUG]: Circuit status change: CIRC 6 EXTENDED [fp],[fp] PURPOSE=GENERAL TIME_CREATED=2016-04-22T20:07:53.305851 2016-04-22 16:07:54,115 [DEBUG]: Circuit status change: CIRC 6 BUILT [fp],[fp] PURPOSE=GENERAL TIME_CREATED=2016-04-22T20:07:53.305851 2016-04-22 16:07:54,136 [DEBUG]: Port 47488 preparing to attach to circuit 6 2016-04-22 16:07:54,136 [DEBUG]: Port 47488 circuit 6 waiting for stream. 2016-04-22 16:07:54,155 [DEBUG]: Attempting to attach stream 65 to circuit 6. 2016-04-22 16:07:54,387 [DEBUG]: Port 47492 preparing to attach to circuit 6 2016-04-22 16:07:54,387 [DEBUG]: Port 47492 circuit 6 waiting for stream. 2016-04-22 16:07:54,388 [DEBUG]: Attempting to attach stream 67 to circuit 6. 2016-04-22 16:07:54,809 [DEBUG]: Port 47496 preparing to attach to circuit 6 2016-04-22 16:07:54,810 [DEBUG]: Port 47496 circuit 6 waiting for stream. 2016-04-22 16:07:54,810 [DEBUG]: Attempting to attach stream 69 to circuit 6. 2016-04-22 16:07:55,060 [DEBUG]: Port 47502 preparing to attach to circuit 6 2016-04-22 16:07:55,060 [DEBUG]: Port 47502 circuit 6 waiting for stream. 2016-04-22 16:07:55,061 [DEBUG]: Attempting to attach stream 72 to circuit 6. 2016-04-22 16:07:55,468 [DEBUG]: Port 47506 preparing to attach to circuit 6 2016-04-22 16:07:55,468 [DEBUG]: Port 47506 circuit 6 waiting for stream. 2016-04-22 16:07:55,469 [DEBUG]: Attempting to attach stream 74 to circuit 6. 2016-04-22 16:07:55,720 [DEBUG]: Port 47508 preparing to attach to circuit 6 2016-04-22 16:07:55,720 [DEBUG]: Port 47508 circuit 6 waiting for stream. 2016-04-22 16:07:55,990 [DEBUG]: Port 47512 preparing to attach to circuit 6 2016-04-22 16:07:55,990 [DEBUG]: Port 47512 circuit 6 waiting for stream. 2016-04-22 16:07:55,990 [DEBUG]: Attempting to attach stream 77 to circuit 6. 2016-04-22 16:07:56,241 [DEBUG]: Port 47518 preparing to attach to circuit 6 2016-04-22 16:07:56,241 [DEBUG]: Port 47518 circuit 6 waiting for stream. 2016-04-22 16:07:56,242 [DEBUG]: Attempting to attach stream 80 to circuit 6. 2016-04-22 16:07:56,492 [DEBUG]: Port 47528 preparing to attach to circuit 6 2016-04-22 16:07:56,492 [DEBUG]: Port 47528 circuit 6 waiting for stream. 2016-04-22 16:07:56,495 [DEBUG]: Attempting to attach stream 85 to circuit 6. 2016-04-22 16:07:56,836 [DEBUG]: Port 47536 preparing to attach to circuit 6 2016-04-22 16:07:56,836 [DEBUG]: Port 47536 circuit 6 waiting for stream. 2016-04-22 16:07:56,836 [DEBUG]: Attempting to attach stream 89 to circuit 6. 2016-04-22 16:07:57,100 [DEBUG]: Port 47540 preparing to attach to circuit 6 2016-04-22 16:07:57,100 [DEBUG]: Attempting to attach stream 91 to circuit 6. 2016-04-22 16:07:57,351 [DEBUG]: Port 47544 preparing to attach to circuit 6 2016-04-22 16:07:57,351 [DEBUG]: Port 47544 circuit 6 waiting for stream. 2016-04-22 16:07:57,352 [DEBUG]: Attempting to attach stream 93 to circuit 6. 2016-04-22 16:07:57,769 [DEBUG]: Port 47550 preparing to attach to circuit 6 2016-04-22 16:07:57,769 [DEBUG]: Port 47550 circuit 6 waiting for stream. 2016-04-22 16:07:57,769 [DEBUG]: Attempting to attach stream 96 to circuit 6. 2016-04-22 16:07:58,118 [DEBUG]: Port 47554 preparing to attach to circuit 6 2016-04-22 16:07:58,118 [DEBUG]: Port 47554 circuit 6 waiting for stream. 2016-04-22 16:07:58,118 [DEBUG]: Attempting to attach stream 98 to circuit 6. 2016-04-22 16:08:04,697 [DEBUG]: Circuit status change: CIRC 6 CLOSED [fp],[fp] PURPOSE=PATH_BIAS_TESTING TIME_CREATED=2016-04-22T20:07:53.305851 REASON=FINISHED 2016-04-22 16:08:05,878 [DEBUG]: Port 47690 preparing to attach to circuit 6 2016-04-22 16:08:05,878 [DEBUG]: Port 47690 circuit 6 waiting for stream. 2016-04-22 16:08:05,879 [DEBUG]: Attempting to attach stream 166 to circuit 6. 2016-04-22 16:08:05,879 [WARNING]: Failed to attach stream because: Unknown circuit "6"
You can see that circuit 6 is no longer available, but the module is still trying to use it. It looks like it lasted for almost exactly ten seconds, which smells like a time limit, but I can't find any relevant configuration parameters in the documentation.
Rather than trying to make a circuit survive as long as necessary, which might not even be possible, it'd probably be better if exitmap could notice that it's lost a circuit that's still in use and create a new one. However, I'm not sure how to do that in the current architecture. The existing code has "one circuit per module invocation = one circuit per exit node" as a pretty deeply embedded design constraint.
Anyone have any ideas? Full logfile available on request, but it's huge.
zw