Opened 13 years ago

Last modified 7 years ago

#355 closed defect (Deferred)

tor server crashes after an hour

Reported by: darkmagess Owned by: phobos
Priority: High Milestone:
Component: Core Tor/Tor Version: 0.1.1.24
Severity: Keywords:
Cc: darkmagess, thalunil, nickm Actual Points:
Parent ID: Points:
Reviewer: Sponsor:

Description

I've set up a tor server with both the latest stable and newest alpha versions. Both crash after about the same amount of time. The error in the log is:
Nov 03 23:19:06:199 [Error] do_main_loop(): libevent call with win32 failed: Invalid argument [WSAEINVAL ] [10022]

In the alpha version there was a similar error related to libevent.
I saw libevent mentioned in the wiki on reporting a bug, but it didn't tell me how I would update something like that.

[Automatically added by flyspray2trac: Operating System: Windows 2k/XP]

Child Tickets

Change History (15)

comment:1 Changed 13 years ago by darkmagess

the line before the crash:

connection_add(): new conn type Directory, socket 7696, nfds 65.

I'd send the whole log, but vidalia crashed when I asked it to output the log file.

comment:2 Changed 13 years ago by darkmagess

I tried to add an attachment to this, but the bug tracker gives me an error, so here it is.

Nov 04 21:26:53:199 [Debug] write_to_buf(): added 48 bytes to buf (now 48 total).
Nov 04 21:26:53:215 [Debug] conn_write_callback(): socket 33444 wants to write.
Nov 04 21:26:53:230 [Debug] _connection_free(): closing fd 33444.
Nov 04 21:26:53:371 [Debug] connection_add(): new conn type Directory, socket 33448, nfds 63.
Nov 04 21:26:53:387 [Debug] conn_read_callback(): socket 33448 wants to read.
Nov 04 21:26:53:402 [Debug] connection_remove(): removing socket -1 (type Directory), nfds now 62
Nov 04 21:26:53:746 [Debug] connection_bucket_refill(): waking up conn (fd 33416)
Nov 04 21:26:53:777 [Debug] connection_or_process_cells_from_inbuf(): 33028: starting, inbuf_datalen 0 (0 pending in tls object).
Nov 04 21:26:53:793 [Debug] conn_write_callback(): socket 33036 wants to write.
Nov 04 21:26:53:808 [Debug] flush_buf_tls_impl(): flushed 512 bytes, 0 ready to flush, 0 remain.
Nov 04 21:26:54:027 [Debug] connection_or_process_cells_from_inbuf(): 32832: starting, inbuf_datalen 0 (0 pending in tls object).
Nov 04 21:26:54:058 [Debug] flush_buf_tls_impl(): flushed 512 bytes, 0 ready to flush, 0 remain.
Nov 04 21:26:54:168 [Debug] connection_or_process_cells_from_inbuf(): 33204: starting, inbuf_datalen 0 (0 pending in tls object).
Nov 04 21:26:54:183 [Debug] conn_write_callback(): socket 33188 wants to write.
Nov 04 21:26:54:199 [Debug] flush_buf_tls_impl(): flushed 512 bytes, 0 ready to flush, 0 remain.
Nov 04 21:26:54:293 [Debug] connection_or_process_cells_from_inbuf(): 33188: starting, inbuf_datalen 0 (0 pending in tls object).
Nov 04 21:26:54:308 [Debug] flush_buf_tls_impl(): flushed 1024 bytes, 0 ready to flush, 0 remain.
Nov 04 21:26:54:590 [Debug] connection_or_process_cells_from_inbuf(): 33036: starting, inbuf_datalen 0 (0 pending in tls object).
Nov 04 21:26:54:605 [Debug] conn_write_callback(): socket 33028 wants to write.
Nov 04 21:26:54:621 [Debug] flush_buf_tls_impl(): flushed 512 bytes, 0 ready to flush, 0 remain.
Nov 04 21:26:54:668 [Debug] connection_or_process_cells_from_inbuf(): 33204: starting, inbuf_datalen 0 (0 pending in tls object).
Nov 04 21:26:54:683 [Debug] conn_write_callback(): socket 33188 wants to write.
Nov 04 21:26:54:699 [Debug] flush_buf_tls_impl(): flushed 1536 bytes, 0 ready to flush, 0 remain.
Nov 04 21:26:54:715 [Debug] connection_or_process_cells_from_inbuf(): 33188: starting, inbuf_datalen 0 (0 pending in tls object).
Nov 04 21:26:54:746 [Debug] flush_buf_tls_impl(): flushed 1024 bytes, 0 ready to flush, 0 remain.
Nov 04 21:26:54:762 [Debug] connection_bucket_refill(): global_write_bucket now 32256.
Nov 04 21:26:54:808 [Debug] connection_or_process_cells_from_inbuf(): 33204: starting, inbuf_datalen 0 (0 pending in tls object).
Nov 04 21:26:54:824 [Debug] connection_or_process_cells_from_inbuf(): 33204: starting, inbuf_datalen 1024 (0 pending in tls object).
Nov 04 21:26:54:840 [Debug] connection_or_process_cells_from_inbuf(): 33204: starting, inbuf_datalen 0 (0 pending in tls object).
Nov 04 21:26:54:855 [Debug] connection_or_process_cells_from_inbuf(): 33204: starting, inbuf_datalen 0 (0 pending in tls object).
Nov 04 21:26:54:933 [Debug] conn_read_callback(): socket 33204 wants to read.
Nov 04 21:26:54:949 [Debug] connection_or_process_cells_from_inbuf(): 33204: starting, inbuf_datalen 0 (0 pending in tls object).
Nov 04 21:26:54:965 [Debug] flush_buf_tls_impl(): flushed 2048 bytes, 0 ready to flush, 0 remain.
Nov 04 21:26:55:074 [Debug] conn_read_callback(): socket 33028 wants to read.
Nov 04 21:26:55:105 [Debug] connection_or_process_cells_from_inbuf(): 33028: starting, inbuf_datalen 0 (0 pending in tls object).
Nov 04 21:26:55:137 [Debug] connection_or_process_cells_from_inbuf(): 33204: starting, inbuf_datalen 0 (0 pending in tls object).
Nov 04 21:26:55:152 [Debug] conn_write_callback(): socket 33188 wants to write.
Nov 04 21:26:55:168 [Debug] flush_buf_tls_impl(): flushed 512 bytes, 0 ready to flush, 0 remain.
Nov 04 21:26:55:215 [Debug] connection_add(): new conn type Directory, socket 33400, nfds 62.
Nov 04 21:26:55:418 [Debug] conn_read_callback(): socket 33204 wants to read.
Nov 04 21:26:55:433 [Debug] connection_or_process_cells_from_inbuf(): 33204: starting, inbuf_datalen 0 (0 pending in tls object).
Nov 04 21:26:55:449 [Debug] flush_buf_tls_impl(): flushed 512 bytes, 0 ready to flush, 0 remain.
Nov 04 21:26:55:527 [Debug] connection_or_process_cells_from_inbuf(): 33036: starting, inbuf_datalen 0 (0 pending in tls object).
Nov 04 21:26:55:558 [Debug] flush_buf_tls_impl(): flushed 512 bytes, 0 ready to flush, 0 remain.
Nov 04 21:26:55:965 [Debug] conn_read_callback(): socket 33028 wants to read.
Nov 04 21:26:55:996 [Debug] connection_or_process_cells_from_inbuf(): 33028: starting, inbuf_datalen 0 (0 pending in tls object).
Nov 04 21:26:56:012 [Debug] conn_write_callback(): socket 33036 wants to write.
Nov 04 21:26:56:027 [Debug] flush_buf_tls_impl(): flushed 512 bytes, 0 ready to flush, 0 remain.
Nov 04 21:26:56:527 [Debug] connection_or_process_cells_from_inbuf(): 33036: starting, inbuf_datalen 0 (0 pending in tls object).
Nov 04 21:26:56:558 [Debug] flush_buf_tls_impl(): flushed 512 bytes, 0 ready to flush, 0 remain.
Nov 04 21:26:56:980 [Debug] connection_or_process_cells_from_inbuf(): 33028: starting, inbuf_datalen 0 (0 pending in tls object).
Nov 04 21:26:56:996 [Debug] conn_write_callback(): socket 33036 wants to write.
Nov 04 21:26:57:012 [Debug] connection_or_process_cells_from_inbuf(): 33028: starting, inbuf_datalen 0 (0 pending in tls object).
Nov 04 21:26:57:043 [Debug] connection_or_process_cells_from_inbuf(): 33028: starting, inbuf_datalen 0 (0 pending in tls object).
Nov 04 21:26:57:074 [Debug] flush_buf_tls_impl(): flushed 1536 bytes, 0 ready to flush, 0 remain.
Nov 04 21:26:57:371 [Debug] conn_read_callback(): socket 33028 wants to read.
Nov 04 21:26:57:387 [Debug] connection_or_process_cells_from_inbuf(): 33028: starting, inbuf_datalen 0 (0 pending in tls object).
Nov 04 21:26:57:418 [Debug] flush_buf_tls_impl(): flushed 512 bytes, 0 ready to flush, 0 remain.
Nov 04 21:26:57:777 [Debug] connection_bucket_refill(): global_read_bucket now 40917.
Nov 04 21:26:58:418 [Debug] connection_tls_continue_handshake(): wanted read
Nov 04 21:26:58:433 [Debug] conn_read_callback(): socket 33036 wants to read.
Nov 04 21:26:58:449 [Debug] connection_or_process_cells_from_inbuf(): 33036: starting, inbuf_datalen 0 (0 pending in tls object).
Nov 04 21:26:58:558 [Debug] connection_or_process_cells_from_inbuf(): 33036: starting, inbuf_datalen 0 (0 pending in tls object).
Nov 04 21:26:58:590 [Debug] connection_or_process_cells_from_inbuf(): 33456: starting, inbuf_datalen 0 (0 pending in tls object).
Nov 04 21:26:58:683 [Debug] conn_read_callback(): socket 33036 wants to read.
Nov 04 21:26:58:715 [Debug] connection_or_process_cells_from_inbuf(): 33036: starting, inbuf_datalen 0 (0 pending in tls object).
Nov 04 21:26:58:746 [Debug] write_to_buf(): added 512 bytes to buf (now 7168 total).
Nov 04 21:26:58:777 [Debug] connection_or_process_cells_from_inbuf(): 33456: starting, inbuf_datalen 0 (0 pending in tls object).
Nov 04 21:26:58:824 [Debug] flush_buf(): 1108: flushed 195 bytes, 0 ready to flush, 0 remain.
Nov 04 21:26:58:840 [Debug] connection_bucket_refill(): global_write_bucket now 27648.
Nov 04 21:26:58:871 [Debug] connection_cpu_process_inbuf(): onionskin_answer succeeded. Yay.
Nov 04 21:26:58:887 [Debug] conn_write_callback(): socket 33456 wants to write.
Nov 04 21:26:58:902 [Debug] flush_buf_tls_impl(): flushed 512 bytes, 0 ready to flush, 0 remain.
Nov 04 21:26:59:027 [Debug] connection_or_process_cells_from_inbuf(): 33036: starting, inbuf_datalen 0 (0 pending in tls object).
Nov 04 21:26:59:043 [Debug] conn_write_callback(): socket 33028 wants to write.
Nov 04 21:26:59:058 [Debug] flush_buf_tls_impl(): flushed 512 bytes, 0 ready to flush, 0 remain.
Nov 04 21:26:59:433 [Debug] connection_or_process_cells_from_inbuf(): 33036: starting, inbuf_datalen 0 (0 pending in tls object).
Nov 04 21:26:59:465 [Debug] connection_or_process_cells_from_inbuf(): 33036: starting, inbuf_datalen 0 (0 pending in tls object).
Nov 04 21:26:59:512 [Debug] conn_read_callback(): socket 1816 wants to read.
Nov 04 21:26:59:527 [Debug] connection_tls_continue_handshake(): wanted read
Nov 04 21:26:59:543 [Debug] conn_read_callback(): socket 33480 wants to read.
Nov 04 21:26:59:558 [Debug] connection_tls_continue_handshake(): wanted read
Nov 04 21:26:59:574 [Debug] connection_or_process_cells_from_inbuf(): 33036: starting, inbuf_datalen 0 (0 pending in tls object).
Nov 04 21:26:59:668 [Debug] connection_or_process_cells_from_inbuf(): 33480: starting, inbuf_datalen 0 (0 pending in tls object).
Nov 04 21:26:59:699 [Debug] connection_or_process_cells_from_inbuf(): 33036: starting, inbuf_datalen 0 (0 pending in tls object).
Nov 04 21:26:59:730 [Debug] write_to_buf(): added 512 bytes to buf (now 7168 total).
Nov 04 21:26:59:762 [Debug] tor_tls_read(): read returned r=-1, err=-2
Nov 04 21:26:59:777 [Debug] connection_or_process_cells_from_inbuf(): 33036: starting, inbuf_datalen 0 (0 pending in tls object).
Nov 04 21:26:59:824 [Debug] connection_or_process_cells_from_inbuf(): 33036: starting, inbuf_datalen 0 (0 pending in tls object).
Nov 04 21:26:59:855 [Debug] circuit_receive_relay_cell(): Passing on unrecognized cell.
Nov 04 21:26:59:887 [Debug] connection_bucket_refill(): waking up conn (fd 33036)
Nov 04 21:26:59:918 [Debug] flush_buf_tls_impl(): flushed 14848 bytes, 0 ready to flush, 0 remain.
Nov 04 21:26:59:965 [Debug] flush_buf(): 1108: flushed 195 bytes, 0 ready to flush, 0 remain.
Nov 04 21:27:00:012 [Debug] connection_cpu_process_inbuf(): onionskin_answer succeeded. Yay.
Nov 04 21:27:00:027 [Debug] conn_write_callback(): socket 33480 wants to write.
Nov 04 21:27:00:043 [Debug] flush_buf_tls_impl(): flushed 512 bytes, 0 ready to flush, 0 remain.
Nov 04 21:27:00:387 [Error] do_main_loop(): libevent call with win32 failed: Invalid argument [WSAEINVAL ] [10022]

comment:3 Changed 12 years ago by phobos

How did you install Tor? Package or compile it yourself?

comment:4 Changed 12 years ago by DarkMagess

I installed it with the package. I'm running windows, so I wouldn't know how to compile it myself anyway.

comment:5 Changed 12 years ago by phobos

Is this still a problem with the current version of tor? stable or alpha?

comment:6 Changed 12 years ago by DarkMagess

I installed the newest alpha and now it seems that Vidalia just takes up 100% of the CPU. I can't open anything related to it, so I can't check the message logs to even see if it's doing anything.

comment:7 Changed 12 years ago by knappo

I have the same here. Vidalia is unable to handle the logs of Tor if you set it to show [DEBUG]-level log entries. This is no problem of tor but of Vidalia. I think it just can't handle the amount of log entries comming from tor. You have to start Vidalia, kill tor via the Task Manager and disbale the logging of DEBUG messages. Afterwards you can restart vidalia and tor and it will work again.

comment:8 Changed 12 years ago by knappo

I hate this linefeedlessflyspraytool..........ARGH.

Sorry for that....

!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
SAME TEXT AS ABOVE WITH LINEFEEDS
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
I have the same here. Vidalia is unable to handle the logs of Tor

if you set it to show [DEBUG]-level log entries. This is no problem
of tor but of Vidalia. I think it just can't handle the amount of log
entries comming from tor. You have to start Vidalia, kill tor via the
Task Manager and disbale the logging of DEBUG messages. Afterwards you
can restart vidalia and tor and it will work again.

comment:9 Changed 12 years ago by phobos

So, is this a libevent bug or a vidalia issue?

Tor-0.1.2.8-beta uses libevent-1.3a. 0.1.1.26-stable uses libevent-1.1b. If this is a libevent issue,
you may want to try the latest beta.

comment:10 Changed 12 years ago by phobos

Are you still having problems?

comment:11 Changed 12 years ago by DarkMagess

Well, it's gone back to the previous set of errors with the newest beta release.
I came back to this error and Tor being closed while Vidalia was still running.

Mar 10 15:12:28:875 [Info] eventdns: Resolve requested.
Mar 10 15:12:28:906 [Info] eventdns: Setting timeout for request 1322da0
Mar 10 15:12:28:921 [Info] connection_edge_finished_connecting(): Exit connection to [scrubbed]:80 ([scrubbed]) established.
Mar 10 15:12:28:937 [Info] connection_edge_finished_connecting(): Exit connection to [scrubbed]:80 ([scrubbed]) established.
Mar 10 15:12:28:953 [Info] connection_edge_finished_connecting(): Exit connection to [scrubbed]:80 ([scrubbed]) established.
Mar 10 15:12:28:984 [Info] connection_edge_finished_connecting(): Exit connection to [scrubbed]:80 ([scrubbed]) established.
Mar 10 15:12:29:000 [Info] connection_edge_finished_connecting(): Exit connection to [scrubbed]:80 ([scrubbed]) established.
Mar 10 15:12:29:031 [Info] connection_edge_finished_connecting(): Exit connection to [scrubbed]:80 ([scrubbed]) established.
Mar 10 15:12:29:046 [Info] connection_edge_finished_connecting(): Exit connection to [scrubbed]:80 ([scrubbed]) established.
Mar 10 15:12:29:062 [Info] eventdns: Removing timeout for request 187b980
Mar 10 15:12:29:093 [Info] eventdns: Request 1843350 timed out
Mar 10 15:12:29:109 [Info] eventdns: Setting timeout for request 1843350
Mar 10 15:12:29:125 [Info] eventdns: Request 18aca90 timed out
Mar 10 15:12:29:140 [Info] eventdns: Setting timeout for request 18aca90
Mar 10 15:12:29:156 [Info] connection_edge_finished_connecting(): Exit connection to [scrubbed]:80 ([scrubbed]) established.
Mar 10 15:12:29:187 [Info] eventdns: Removing timeout for request 1843350
Mar 10 15:12:29:203 [Info] eventdns: Removing timeout for request 18aca90
Mar 10 15:12:29:218 [Error] libevent call with win32 failed: Invalid argument [WSAEINVAL ] [10022]

comment:12 Changed 12 years ago by phobos

Is this still happening on 0.1.2.12-rc?

comment:13 Changed 12 years ago by nickm

Is this still happening on 0.1.2.14?

comment:14 Changed 12 years ago by phobos

flyspray2trac: bug closed.
Never heard back.

comment:15 Changed 7 years ago by nickm

Component: Tor RelayTor
Note: See TracTickets for help on using tickets.