Opened 8 years ago

Closed 8 years ago

#5093 closed defect (fixed)

Mysterious "Resource temporarily unavailable" errors

Reported by: arma Owned by: asn
Priority: Medium Milestone:
Component: Archived/Obfsproxy Version:
Severity: Keywords:
Cc: twilde@…, c@… Actual Points:
Parent ID: Points:
Reviewer: Sponsor:

Description

ditzydoo saw this in her logs:

2012-02-11 15:07:40 [info] EOF from 127.0.0.1:5001
2012-02-11 15:07:40 [info] EOF from 127.0.0.1:5001
2012-02-11 15:07:40 [info] EOF from 127.0.0.1:5001
2012-02-11 15:07:40 [info] EOF from 127.0.0.1:5001
2012-02-11 15:07:40 [info] EOF from 127.0.0.1:5001
2012-02-11 15:07:40 [info] EOF from 127.0.0.1:5001
2012-02-11 15:07:41 [info] [scrubbed]:51264 (obfs2): trying to connect to 127.0.0.1:5001
2012-02-11 15:07:41 [warn] Error talking to 127.0.0.1:5001: Resource temporarily unavailable
2012-02-11 15:08:44 [info] [scrubbed]:14924 (obfs2): trying to connect to 127.0.0.1:5001
2012-02-11 15:08:44 [warn] Error talking to 127.0.0.1:5001: Resource temporarily unavailable
2012-02-11 15:09:33 [info] [scrubbed]:12792 (obfs2): trying to connect to 127.0.0.1:5001
2012-02-11 15:09:33 [warn] Error talking to 127.0.0.1:5001: Resource temporarily unavailable
2012-02-11 15:09:50 [warn] Error during flush of connection with 127.0.0.1:5001: Broken pipe
2012-02-11 15:10:06 [info] [scrubbed]:50247 (obfs2): trying to connect to 127.0.0.1:5001
2012-02-11 15:10:06 [warn] Error talking to 127.0.0.1:5001: Resource temporarily unavailable
2012-02-11 15:10:51 [info] [scrubbed]:25002 (obfs2): trying to connect to 127.0.0.1:5001
2012-02-11 15:10:51 [warn] Error talking to 127.0.0.1:5001: Resource temporarily unavailable
2012-02-11 15:10:59 [info] [scrubbed]:16450 (obfs2): trying to connect to 127.0.0.1:5001
2012-02-11 15:10:59 [warn] Error talking to 127.0.0.1:5001: Resource temporarily unavailable
2012-02-11 15:11:47 [info] [scrubbed]:16490 (obfs2): trying to connect to 127.0.0.1:5001
2012-02-11 15:11:47 [warn] Error talking to 127.0.0.1:5001: Resource temporarily unavailable
2012-02-11 15:13:02 [info] [scrubbed]:18014 (obfs2): trying to connect to 127.0.0.1:5001
2012-02-11 15:13:02 [warn] Error talking to 127.0.0.1:5001: Resource temporarily unavailable
2012-02-11 15:13:22 [info] [scrubbed]:1236 (obfs2): trying to connect to 127.0.0.1:5001
2012-02-11 15:13:22 [warn] Error talking to 127.0.0.1:5001: Resource temporarily unavailable
2012-02-11 15:13:24 [info] [scrubbed]:16605 (obfs2): trying to connect to 127.0.0.1:5001
2012-02-11 15:13:24 [warn] Error talking to 127.0.0.1:5001: Resource temporarily unavailable
2012-02-11 15:18:12 [info] [scrubbed]:4046 (obfs2): trying to connect to 127.0.0.1:5001
2012-02-11 15:18:12 [warn] Error talking to 127.0.0.1:5001: Resource temporarily unavailable
2012-02-11 15:20:08 [info] Closing all listeners.
2012-02-11 15:20:08 [info] Got SIGINT. Preparing shutdown.
2012-02-11 15:20:08 [info] Exiting.

error_cb() says

  if (what & BEV_EVENT_ERROR) {
    log_warn("Error talking to %s: %s",
             conn->peername,
             evutil_socket_error_to_string(errcode));
[...]
  error_or_eof(conn);

and error_or_eof's comments say

/**
   Something broke one side of the connection, or we reached EOF.
   We prepare the connection to be closed ASAP.

grep for EAGAIN in the code shows nothing. Are we really hanging up as soon as we get an EAGAIN? Or does libevent magically take care of that for us somehow?

Child Tickets

Change History (18)

comment:1 Changed 8 years ago by twilde

Cc: twilde@… added

comment:2 Changed 8 years ago by nickm

Bufferevents don't treat EAGAIN as a reportable error; EAGAIN don't trigger the bufferevent's eventcb callback.

comment:3 Changed 8 years ago by arma

Summary: obfsproxy treats EAGAIN as EOF?Mysterious "Resource temporarily unavailable" errors

Ok. What do we think "Resource temporarily unavailable" corresponds to in this case then?

comment:4 Changed 8 years ago by nickm

My best guess is that the error callback got invoked for some reason but errno wasn't set from inside libevent, so it's still at the previous value of errno, which tends to be EAGAIN a lot.

comment:5 Changed 8 years ago by arma

So it might be a libevent issue?

She's on openbsd and libevent 2.0.13-stable. Maybe it's enough to point at the older libevent.

comment:6 Changed 8 years ago by nickm

Upgrading the libevent would be the first thing I'd suggest. I don't immediately recall an error like that, but 2.0.13-stable was six months ago, so it's quite possible the problem isn't there any more. In any case, ruling out all already-fixed bugs would make it much easier to find this one if it is still happening.

comment:7 Changed 8 years ago by arma

Summary: Mysterious "Resource temporarily unavailable" errorsMysterious "Resource temporarily unavailable" errors (libevent 2.0.13)

comment:8 Changed 8 years ago by arma

Summary: Mysterious "Resource temporarily unavailable" errors (libevent 2.0.13)Mysterious "Resource temporarily unavailable" errors

I'm seeing it on moria1 too, with libevent 2.0.16. EAGAIN accounts for the majority of the errnos that I see, actually.

$ grep \ error_cb logfile|grep errno=11$|wc -l
796
$ grep \ error_cb logfile|grep -v errno=11$|wc -l
343

comment:9 Changed 8 years ago by arma

(and by moria1 i mean my obfsproxy bridge on moria)

comment:10 Changed 8 years ago by therealditzydoo

Cc: c@… added

I am now running libevent-2.0.17-stable (the latest version) and still get these errors. Here is some example output at debug level.

2012-02-11 15:59:20 [debug] [SCRUBBED A]:38871: transmitted 1684 bytes
2012-02-11 15:59:21 [debug] 127.0.0.1:5001: upstream_read_cb, 586 bytes available
2012-02-11 15:59:21 [debug] obfs2_send: transmitting 586 bytes.
2012-02-11 15:59:21 [debug] obfs2_crypt_and_transmit: Processed 586 bytes.
2012-02-11 15:59:21 [debug] [SCRUBBED A]:38871: transmitted 586 bytes
2012-02-11 15:59:21 [debug] 127.0.0.1:5001: upstream_read_cb, 586 bytes available
2012-02-11 15:59:21 [debug] obfs2_send: transmitting 586 bytes.
2012-02-11 15:59:21 [debug] obfs2_crypt_and_transmit: Processed 586 bytes.
2012-02-11 15:59:21 [debug] [SCRUBBED A]:38871: transmitted 586 bytes
2012-02-11 15:59:21 [debug] 127.0.0.1:5001: upstream_read_cb, 586 bytes available
2012-02-11 15:59:21 [debug] obfs2_send: transmitting 586 bytes.
2012-02-11 15:59:21 [debug] obfs2_crypt_and_transmit: Processed 586 bytes.
2012-02-11 15:59:21 [debug] [SCRUBBED A]:38871: transmitted 586 bytes
2012-02-11 15:59:55 [debug] error_cb for [SCRUBBED B]:57004: what=0x0011 errno=35
2012-02-11 15:59:55 [info] EOF from [SCRUBBED B]:57004
2012-02-11 15:59:55 [debug] error_or_eof for [SCRUBBED B]:57004
2012-02-11 15:59:55 [debug] Closing connection with 127.0.0.1:5001; 5 remaining
2012-02-11 15:59:55 [debug] Closing connection with [SCRUBBED B]:57004; 4 remaining
2012-02-11 16:00:39 [debug] error_cb for [SCRUBBED C]:25101: what=0x0011 errno=35
2012-02-11 16:00:39 [info] EOF from [SCRUBBED C]:25101
2012-02-11 16:00:39 [debug] error_or_eof for [SCRUBBED C]:25101
2012-02-11 16:00:39 [debug] Closing connection with 127.0.0.1:5001; 3 remaining
2012-02-11 16:00:39 [debug] Closing connection with [SCRUBBED C]:25101; 2 remaining
2012-02-11 16:01:29 [debug] 0.0.0.0:29936: new connection from [SCRUBBED C]:25110 (3 total)
2012-02-11 16:01:29 [debug] [SCRUBBED C]:25110: server connection
2012-02-11 16:01:29 [info] [SCRUBBED C]:25110 (obfs2): trying to connect to 127.0.0.1:5001
2012-02-11 16:01:29 [debug] [SCRUBBED C]:25110: setup complete
2012-02-11 16:01:29 [debug] 127.0.0.1:5001: pending_conn_cb
2012-02-11 16:01:29 [debug] 127.0.0.1:5001: Successful connection

comment:11 in reply to:  10 ; Changed 8 years ago by nickm

Replying to therealditzydoo:

I am now running libevent-2.0.17-stable (the latest version) and still get these errors. Here is some example output at debug level.

I'm not seeing any "Resource temporarily available" instances in those logs. Are they showing up in a different section, or am I missing something here?

comment:12 in reply to:  8 Changed 8 years ago by nickm

Replying to arma:

I'm seeing it on moria1 too, with libevent 2.0.16. EAGAIN accounts for the majority of the errnos that I see, actually.

Can you paste some of those? It is okay for errno=EAGAIN to be set, so long as the BEV_EVENT_ERROR flag is not set. If there is no BEV_EVENT_ERROR, then a socket error hasn't occurred (it's probably just an eof or timeout), and so it is okay for errno to be whatever it wants to be.

comment:13 in reply to:  11 ; Changed 8 years ago by arma

Replying to nickm:

Replying to therealditzydoo:

I am now running libevent-2.0.17-stable (the latest version) and still get these errors. Here is some example output at debug level.

I'm not seeing any "Resource temporarily available" instances in those logs. Are they showing up in a different section, or am I missing something here?

Errno 35 is EAGAIN on openbsd.

comment:14 in reply to:  13 ; Changed 8 years ago by nickm

Replying to arma:

Replying to nickm:

Replying to therealditzydoo:

I am now running libevent-2.0.17-stable (the latest version) and still get these errors. Here is some example output at debug level.

I'm not seeing any "Resource temporarily available" instances in those logs. Are they showing up in a different section, or am I missing something here?

Errno 35 is EAGAIN on openbsd.

But those have "what=0x0011 errno=35" ; 0x11 is BEV_EVENT_READING|BEV_EVENT_EOF. There's no error there. As noted above, unless BEV_EVENT_ERROR (0x20) is set in the "what" argument, the value of errno is unlikely to be meaningful.

comment:15 in reply to:  14 Changed 8 years ago by arma

Replying to nickm:

unless BEV_EVENT_ERROR (0x20) is set in the "what" argument, the value of errno is unlikely to be meaningful.

$ tord2@moria:~/obfsproxy$ grep what logfile|grep -v "what=0x0011"|grep "errno=11$"

returns no results.

Looks like no bug.

Maybe we should change the log line to leave off errno if what doesn't include 20?

comment:16 Changed 8 years ago by nickm

Resolution: not a bug
Status: newclosed

Sounds like a reasonable change. Done in 9fe5f1c79b0161a6aecfa3dc7c80204fe9ddfee1. Closing. Thanks for being patient here!

comment:17 Changed 8 years ago by arma

Resolution: not a bug
Status: closedreopened

We're back!

2012-02-13 00:49:50 [warn] Error during flush of connection with x.x.x.x:44654: Resource temporarily unavailable

Seems it happens inside flush_error_cb(). I don't have the debug line that happened earlier in the function.

Is this likely another case of "oops that errno isn't accurate then"? I notice we're calling evutil_socket_error_to_string() on it, so I assume it's a network errno.

comment:18 Changed 8 years ago by nickm

Resolution: fixed
Status: reopenedclosed

It looks like flush_error_cb() doesn't actually check 'what&BEV_EVENT_ERROR'. I'd bet that we've got another EOF here.

I've checked in another patch (fc7008f) to make sure that we actually check for BEV_EVENT_ERROR before logging any strerrors.

Note: See TracTickets for help on using tickets.