tor is stucked for couple of minutes [was Re: tor inside vmm, horribly slow?!]

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
4 messages Options
Reply | Threaded
Open this post in threaded view
|

tor is stucked for couple of minutes [was Re: tor inside vmm, horribly slow?!]

Jiri B-2
On Mon, Feb 12, 2018 at 10:02:52PM +0100, Thomas Weinbrenner wrote:
> Perhaps this has nothing to do with vmm.

I can confirm too that this Tor issue - being stucked for cca 2 minutes -
happens also on baremetal.

Thus moving from misc@ to ports@ as this is more appropriate, CC tor port
maintainer (sorry for multiple mails).

If anybody has a recommendation, please share it. Is it OpenBSD specific
problem?

Not sure if Thomas findings below are relevant:

> [...]
> Since upgrading OpenBSD from
>
> | OpenBSD 6.2-current (GENERIC.MP) #399: Fri Feb  2 18:28:58 MST 2018
> |    [hidden email]:/usr/src/sys/arch/amd64/compile/GENERIC.MP
>
> to
>
> | OpenBSD 6.2-current (GENERIC.MP) #4: Sat Feb 10 18:04:19 MST 2018
> |    [hidden email]:/usr/src/sys/arch/amd64/compile/GENERIC.MP
>
> my tor server also has problems.
>
> /var/log/daemon:
> | Feb 11 20:15:50 server Tor[54286]: Your system clock just jumped 115 seconds forward; assuming established circuits no longer work.
> | Feb 11 20:16:02 server Tor[54286]: Tor has successfully opened a circuit. Looks like client functionality is working.
> | Feb 11 20:16:02 server Tor[54286]: Tor has successfully opened a circuit. Looks like client functionality is working.
> | Feb 11 20:24:43 server Tor[54286]: Your system clock just jumped 299 seconds forward; assuming established circuits no longer work.
> | Feb 11 20:26:24 server Tor[54286]: tor_assertion_failed_: Bug: src/or/channel.c:1503: channel_closed: Assertion CHANNEL_CONDEMNED(chan) failed; aborting. (on Tor 0.3.2.9 9e8b762fcecfece6)
> | Feb 11 20:26:24 server Tor[54286]: Bug: Assertion CHANNEL_CONDEMNED(chan) failed in channel_closed at src/or/channel.c:1503. (Stack trace not available) (on Tor 0.3.2.9 9e8b762fcecfece6)

What I see is that lines with 'circuit_consider_stop_edge_reading: considering layer_hint->package_window <number>'
are last ones before Tor gets stucked with tor-0.3.2.9p0.

# awk '/18:15:31.*circuit_consider_stop_edge_reading: considering layer_hint->package_window 99/ { print; getline; print }' /data/services/onion/archive/tor/logs/debug.log  
Feb 13 18:15:31.000 [debug] circuit_consider_stop_edge_reading: considering layer_hint->package_window 999
Feb 13 18:18:31.000 [debug] read_to_chunk: Read 596 bytes. 876 on inbuf.

^^ 3 mins now

An attempt to ktrace it:

...
 13589 tor      1518542131.362968 GIO   fd 6 wrote 95 bytes
       "Feb 13 18:15:31.000 [debug] connection_edge_package_raw_inbuf: conn->package_window is now 499
       "
 13589 tor      1518542131.362972 RET   write 95/0x5f
 13589 tor      1518542131.362981 CALL  gettimeofday(0x7f7ffffbfa28,0)
 13589 tor      1518542131.362988 STRU  struct timeval { 1518542131<"Feb 13 18:15:31 2018">.362985 }
 13589 tor      1518542131.363012 RET   gettimeofday 0
 13589 tor      1518542131.363020 CALL  write(6,0x7f7ffffbfae0,0x6b)
 13589 tor      1518542131.363032 GIO   fd 6 wrote 107 bytes
       "Feb 13 18:15:31.000 [debug] circuit_consider_stop_edge_reading: considering layer_hint->package_window 999
       "
 13589 tor      1518542131.363044 RET   write 107/0x6b
 13589 tor      1518542131.363056 CALL  recvfrom(4,0x12664c160336,0x3cf6,0,0,0)

^^ see above timestamp, and below reply from httpd (18:18:31.372), this correspond to
   httpd.conf's 'connection request timeout 180'

   but when i tried to access either httpd or sshd (just test) locally, they work
   fine.

 13589 tor      1518542311.372642 GIO   fd 4 read 596 bytes
       "HTTP/1.0 408 Request Timeout\r
        Date: Tue, 13 Feb 2018 17:18:31 GMT\r
        Server: OpenBSD httpd\r
        Connection: close\r
        Content-Type: text/html\r
        Content-Length: 439\r
        \r
        <!DOCTYPE html>
        <html>
        <head>
        <meta http-equiv="Content-Type" content="text/html; charset=utf-8"/>
        <title>408 Request Timeout</title>
        <style type="text/css"><!--
        body { background-color: white; color: black; font-family: 'Comic Sans MS', 'Chalkboard SE', 'Comic Neue', sans-serif; }
        hr { border: 0; border-bottom: 1px dashed; }
       
        --></style>
        </head>
        <body>
        <h1>408 Request Timeout</h1>
        <hr>
        <address>OpenBSD httpd</address>
        </body>
        </html>
       "
 13589 tor      1518542311.372664 RET   recvfrom 596/0x254
 13589 tor      1518542311.372675 CALL  gettimeofday(0x7f7ffffbfd28,0)
 13589 tor      1518542311.372685 STRU  struct timeval { 1518542311<"Feb 13 18:18:31 2018">.372679 }

Jiri

Reply | Threaded
Open this post in threaded view
|

Re: tor is stucked for couple of minutes [was Re: tor inside vmm, horribly slow?!]

George Rosamond
Top-post.

I haven't seen this running 0.3.2.9 on multiple OpenBSD systems.
Nothing immediately apparent to me, although I would confirm ntpd is
running and reasonably accurate.

I'm going to post email contents to Tor's trac.
g


Jiri B:

> On Mon, Feb 12, 2018 at 10:02:52PM +0100, Thomas Weinbrenner wrote:
>> Perhaps this has nothing to do with vmm.
>
> I can confirm too that this Tor issue - being stucked for cca 2 minutes -
> happens also on baremetal.
>
> Thus moving from misc@ to ports@ as this is more appropriate, CC tor port
> maintainer (sorry for multiple mails).
>
> If anybody has a recommendation, please share it. Is it OpenBSD specific
> problem?
>
> Not sure if Thomas findings below are relevant:
>
>> [...]
>> Since upgrading OpenBSD from
>>
>> | OpenBSD 6.2-current (GENERIC.MP) #399: Fri Feb  2 18:28:58 MST 2018
>> |    [hidden email]:/usr/src/sys/arch/amd64/compile/GENERIC.MP
>>
>> to
>>
>> | OpenBSD 6.2-current (GENERIC.MP) #4: Sat Feb 10 18:04:19 MST 2018
>> |    [hidden email]:/usr/src/sys/arch/amd64/compile/GENERIC.MP
>>
>> my tor server also has problems.
>>
>> /var/log/daemon:
>> | Feb 11 20:15:50 server Tor[54286]: Your system clock just jumped 115 seconds forward; assuming established circuits no longer work.
>> | Feb 11 20:16:02 server Tor[54286]: Tor has successfully opened a circuit. Looks like client functionality is working.
>> | Feb 11 20:16:02 server Tor[54286]: Tor has successfully opened a circuit. Looks like client functionality is working.
>> | Feb 11 20:24:43 server Tor[54286]: Your system clock just jumped 299 seconds forward; assuming established circuits no longer work.
>> | Feb 11 20:26:24 server Tor[54286]: tor_assertion_failed_: Bug: src/or/channel.c:1503: channel_closed: Assertion CHANNEL_CONDEMNED(chan) failed; aborting. (on Tor 0.3.2.9 9e8b762fcecfece6)
>> | Feb 11 20:26:24 server Tor[54286]: Bug: Assertion CHANNEL_CONDEMNED(chan) failed in channel_closed at src/or/channel.c:1503. (Stack trace not available) (on Tor 0.3.2.9 9e8b762fcecfece6)
>
> What I see is that lines with 'circuit_consider_stop_edge_reading: considering layer_hint->package_window <number>'
> are last ones before Tor gets stucked with tor-0.3.2.9p0.
>
> # awk '/18:15:31.*circuit_consider_stop_edge_reading: considering layer_hint->package_window 99/ { print; getline; print }' /data/services/onion/archive/tor/logs/debug.log  
> Feb 13 18:15:31.000 [debug] circuit_consider_stop_edge_reading: considering layer_hint->package_window 999
> Feb 13 18:18:31.000 [debug] read_to_chunk: Read 596 bytes. 876 on inbuf.
>
> ^^ 3 mins now
>
> An attempt to ktrace it:
>
> ...
>  13589 tor      1518542131.362968 GIO   fd 6 wrote 95 bytes
>        "Feb 13 18:15:31.000 [debug] connection_edge_package_raw_inbuf: conn->package_window is now 499
>        "
>  13589 tor      1518542131.362972 RET   write 95/0x5f
>  13589 tor      1518542131.362981 CALL  gettimeofday(0x7f7ffffbfa28,0)
>  13589 tor      1518542131.362988 STRU  struct timeval { 1518542131<"Feb 13 18:15:31 2018">.362985 }
>  13589 tor      1518542131.363012 RET   gettimeofday 0
>  13589 tor      1518542131.363020 CALL  write(6,0x7f7ffffbfae0,0x6b)
>  13589 tor      1518542131.363032 GIO   fd 6 wrote 107 bytes
>        "Feb 13 18:15:31.000 [debug] circuit_consider_stop_edge_reading: considering layer_hint->package_window 999
>        "
>  13589 tor      1518542131.363044 RET   write 107/0x6b
>  13589 tor      1518542131.363056 CALL  recvfrom(4,0x12664c160336,0x3cf6,0,0,0)
>
> ^^ see above timestamp, and below reply from httpd (18:18:31.372), this correspond to
>    httpd.conf's 'connection request timeout 180'
>
>    but when i tried to access either httpd or sshd (just test) locally, they work
>    fine.
>
>  13589 tor      1518542311.372642 GIO   fd 4 read 596 bytes
>        "HTTP/1.0 408 Request Timeout\r
>         Date: Tue, 13 Feb 2018 17:18:31 GMT\r
>         Server: OpenBSD httpd\r
>         Connection: close\r
>         Content-Type: text/html\r
>         Content-Length: 439\r
>         \r
>         <!DOCTYPE html>
>         <html>
>         <head>
>         <meta http-equiv="Content-Type" content="text/html; charset=utf-8"/>
>         <title>408 Request Timeout</title>
>         <style type="text/css"><!--
>         body { background-color: white; color: black; font-family: 'Comic Sans MS', 'Chalkboard SE', 'Comic Neue', sans-serif; }
>         hr { border: 0; border-bottom: 1px dashed; }
>        
>         --></style>
>         </head>
>         <body>
>         <h1>408 Request Timeout</h1>
>         <hr>
>         <address>OpenBSD httpd</address>
>         </body>
>         </html>
>        "
>  13589 tor      1518542311.372664 RET   recvfrom 596/0x254
>  13589 tor      1518542311.372675 CALL  gettimeofday(0x7f7ffffbfd28,0)
>  13589 tor      1518542311.372685 STRU  struct timeval { 1518542311<"Feb 13 18:18:31 2018">.372679 }
>
> Jiri
>

Reply | Threaded
Open this post in threaded view
|

Re: tor is stucked for couple of minutes [was Re: tor inside vmm, horribly slow?!]

Stuart Henderson
In reply to this post by Jiri B-2
On 2018/02/13 12:57, Jiri B wrote:

> On Mon, Feb 12, 2018 at 10:02:52PM +0100, Thomas Weinbrenner wrote:
> > Perhaps this has nothing to do with vmm.
>
> I can confirm too that this Tor issue - being stucked for cca 2 minutes -
> happens also on baremetal.
>
> Thus moving from misc@ to ports@ as this is more appropriate, CC tor port
> maintainer (sorry for multiple mails).
>
> If anybody has a recommendation, please share it. Is it OpenBSD specific
> problem?

Try a kernel built from source after 2018/02/11 14:53:57 (uipc_syscalls.c).

Reply | Threaded
Open this post in threaded view
|

[solved] Re: tor is stucked for couple of minutes [was Re: tor inside vmm, horribly slow?!]

Jiri B-2
On Tue, Feb 13, 2018 at 09:02:06PM +0000, Stuart Henderson wrote:

> On 2018/02/13 12:57, Jiri B wrote:
> > On Mon, Feb 12, 2018 at 10:02:52PM +0100, Thomas Weinbrenner wrote:
> > > Perhaps this has nothing to do with vmm.
> >
> > I can confirm too that this Tor issue - being stucked for cca 2 minutes -
> > happens also on baremetal.
> >
> > Thus moving from misc@ to ports@ as this is more appropriate, CC tor port
> > maintainer (sorry for multiple mails).
> >
> > If anybody has a recommendation, please share it. Is it OpenBSD specific
> > problem?
>
> Try a kernel built from source after 2018/02/11 14:53:57 (uipc_syscalls.c).

Thanks to all, with recent kernel everything works as expected.

...
Feb 14 11:54:19.000 [debug] circuit_consider_stop_edge_reading: considering layer_hint->package_window 941
^^ here it was stucked before...
Feb 14 11:54:19.000 [debug] connection_or_process_cells_from_inbuf: 4: starting, inbuf_datalen 0 (0 pending in tls object).
Feb 14 11:54:19.000 [debug] connection_bucket_refill_helper: global_read_bucket now 1073741824.
Feb 14 11:54:19.000 [debug] connection_bucket_refill_helper: or_conn->read_bucket now 1073741824.
Feb 14 11:54:19.000 [debug] circuit_remove_handled_ports: Port 443 is already being handled; removing.
Feb 14 11:54:20.000 [debug] circuit_remove_handled_ports: Port 443 is already being handled; removing.
...

kern.version=OpenBSD 6.2-current (GENERIC.MP) #6: Tue Feb 13 20:16:11 MST 2018
    [hidden email]:/usr/src/sys/arch/amd64/compile/GENERIC.MP

Jiri