pfSense

Client on LAN, TFTP server on WAN, TFTP proxy enabled on LAN. Client on LAN cannot get files from the TFTP server. The client sees only a timeout.

State table shows that the connection is being redirected to localhost:6969 to the proxy, no exit traffic is observed.

em1 udp 127.0.0.1:6969 (198.51.100.145:69) <- 10.7.0.10:41084       NO_TRAFFIC:SINGLE

Contents of xinetd.conf:

service 6969-udp
{
    type = unlisted
    bind = 127.0.0.1
    port = 6969
    socket_type = dgram
    protocol = udp
    wait = yes
    user = root
    server = /usr/libexec/tftp-proxy
    server_args = -v
}

Running xinetd in debug mode with some extra logging turned up in xinetd.conf:

: /usr/local/sbin/xinetd -d -dontfork -syslog daemon -f /var/etc/xinetd.conf -pidfile /var/run/xinetd.pid
Service defaults
    Bind = All addresses.
    Only from: All sites
    No access: No blocked sites
    No logging

Service configuration: 6969-udp
    id = 6969-udp
    flags = IPv4
    type = UNLISTED
    socket_type = dgram
    Protocol (name,number) = (udp,17)
    port = 6969
    wait = yes
    user = 0
    Groups = no
    PER_SOURCE = -1
    Bind = localhost
    Server = /usr/libexec/tftp-proxy
    Server argv = tftp-proxy -v
    Only from: All sites
    No access: No blocked sites
    Logging to syslog. Facility = daemon, level = info
    Log_on_success flags = HOST DURATION EXIT PID USERID
    Log_on_failure flags = HOST ATTEMPT USERID

16/5/4@11:34:06: DEBUG: 81636 {cnf_start_services} Started service: 6969-udp
16/5/4@11:34:06: DEBUG: 81636 {cnf_start_services} mask_max = 0, services_started = 1
16/5/4@11:34:06: NOTICE: 81636 {main} xinetd Version 2.3.15 started with libwrap loadavg options compiled in.
16/5/4@11:34:06: NOTICE: 81636 {main} Started working: 1 available service
16/5/4@11:34:06: DEBUG: 81636 {main_loop} active_services = 1
16/5/4@11:34:18: DEBUG: 81636 {main_loop} select returned 1
16/5/4@11:34:18: DEBUG: 81636 {svc_suspend} Suspended service 6969-udp
16/5/4@11:34:18: DEBUG: 81636 {server_start} Starting service 6969-udp
16/5/4@11:34:18: DEBUG: 81636 {main_loop} active_services = 0
16/5/4@11:34:18: DEBUG: 81895 {exec_server} duping 0
16/5/4@11:34:18: DEBUG: 81636 {main_loop} active_services = 0
16/5/4@11:34:18: DEBUG: 81636 {main_loop} select returned 1
16/5/4@11:34:18: DEBUG: 81636 {check_pipe} Got signal 20 (Child exited)
16/5/4@11:34:18: DEBUG: 81636 {child_exit} waitpid returned = 81895
16/5/4@11:34:18: DEBUG: 81636 {server_end} 6969-udp server 81895 exited
16/5/4@11:34:18: DEBUG: 81636 {drain} UDP socket should be empty
16/5/4@11:34:18: DEBUG: 81636 {svc_resume} Resumed service 6969-udp
16/5/4@11:34:18: DEBUG: 81636 {child_exit} waitpid returned = -1
16/5/4@11:34:18: DEBUG: 81636 {main_loop} active_services = 1
16/5/4@11:34:23: DEBUG: 81636 {main_loop} select returned 1
16/5/4@11:34:23: DEBUG: 81636 {svc_suspend} Suspended service 6969-udp
16/5/4@11:34:23: DEBUG: 81636 {server_start} Starting service 6969-udp
16/5/4@11:34:23: DEBUG: 81636 {main_loop} active_services = 0
16/5/4@11:34:23: WARNING: 82155 {exec_server} fcntl( 0, clear close-on-exec ) failed: Bad file descriptor (errno = 9)
16/5/4@11:34:23: DEBUG: 82155 {exec_server} duping 0
16/5/4@11:34:23: ERROR: 82155 {exec_server} dup2( 0, 0 ) failed: Bad file descriptor (errno = 9)
16/5/4@11:34:23: DEBUG: 81636 {main_loop} active_services = 0
16/5/4@11:34:23: DEBUG: 81636 {main_loop} select returned 1
16/5/4@11:34:23: DEBUG: 81636 {check_pipe} Got signal 20 (Child exited)
16/5/4@11:34:23: DEBUG: 81636 {child_exit} waitpid returned = 82155
16/5/4@11:34:23: DEBUG: 81636 {server_end} 6969-udp server 82155 exited
16/5/4@11:34:23: DEBUG: 81636 {drain} UDP socket should be empty
16/5/4@11:34:23: DEBUG: 81636 {svc_resume} Resumed service 6969-udp
16/5/4@11:34:23: DEBUG: 81636 {child_exit} waitpid returned = -1
16/5/4@11:34:23: DEBUG: 81636 {main_loop} active_services = 1

Syslog from the same period:

May  4 11:33:54 shona xinetd[22248]: Starting reconfiguration
May  4 11:33:54 shona xinetd[22248]: Swapping defaults
May  4 11:33:54 shona xinetd[22248]: readjusting service 6969-udp
May  4 11:33:54 shona xinetd[22248]: Reconfigured: new=0 old=1 dropped=0 (services)
May  4 11:34:18 shona xinetd[81636]: START: 6969-udp pid=81895 from=10.7.0.10
May  4 11:34:18 shona xinetd[81895]: warning: can't get client address: Bad file descriptor
May  4 11:34:18 shona tftp-proxy[81895]: setsockopt(IP_RECVDSTADDR): Protocol not available
May  4 11:34:18 shona xinetd[81636]: EXIT: 6969-udp status=1 pid=81895 duration=0(sec)
May  4 11:34:23 shona xinetd[81636]: START: 6969-udp pid=82155 from=10.7.0.10
May  4 11:34:23 shona xinetd[82155]: warning: can't get client address: Bad file descriptor
May  4 11:34:23 shona xinetd[81636]: EXIT: 6969-udp status=1 pid=82155 duration=0(sec)
May  4 11:34:28 shona xinetd[81636]: START: 6969-udp pid=84276 from=10.7.0.10
May  4 11:34:28 shona xinetd[84276]: warning: can't get client address: Bad file descriptor
May  4 11:34:28 shona xinetd[81636]: EXIT: 6969-udp status=1 pid=84276 duration=0(sec)
May  4 11:34:33 shona xinetd[81636]: START: 6969-udp pid=84444 from=10.7.0.10
May  4 11:34:33 shona xinetd[84444]: warning: can't get client address: Bad file descriptor
May  4 11:34:33 shona xinetd[81636]: EXIT: 6969-udp status=1 pid=84444 duration=0(sec)
May  4 11:34:38 shona xinetd[81636]: START: 6969-udp pid=84603 from=10.7.0.10
May  4 11:34:38 shona xinetd[84603]: warning: can't get client address: Bad file descriptor
May  4 11:34:38 shona xinetd[81636]: EXIT: 6969-udp status=1 pid=84603 duration=0(sec)

Syslog also shows these errors (with the default logging):

May  4 12:02:54 shona xinetd[4287]: warning: can't get client address: Bad file descriptor
May  4 12:02:54 shona xinetd[4287]: fcntl( 0, clear close-on-exec ) failed: Bad file descriptor (errno = 9)
May  4 12:02:54 shona xinetd[4287]: dup2( 0, 0 ) failed: Bad file descriptor (errno = 9)
May  4 12:02:59 shona xinetd[39208]: warning: can't get client address: Bad file descriptor
May  4 12:02:59 shona xinetd[39208]: fcntl( 0, clear close-on-exec ) failed: Bad file descriptor (errno = 9)
May  4 12:02:59 shona xinetd[39208]: dup2( 0, 0 ) failed: Bad file descriptor (errno = 9)
May  4 12:03:04 shona xinetd[39512]: warning: can't get client address: Bad file descriptor
May  4 12:03:04 shona xinetd[39512]: fcntl( 0, clear close-on-exec ) failed: Bad file descriptor (errno = 9)
May  4 12:03:04 shona xinetd[39512]: dup2( 0, 0 ) failed: Bad file descriptor (errno = 9)
May  4 12:03:09 shona xinetd[39605]: warning: can't get client address: Bad file descriptor
May  4 12:03:09 shona xinetd[39605]: fcntl( 0, clear close-on-exec ) failed: Bad file descriptor (errno = 9)
May  4 12:03:09 shona xinetd[39605]: dup2( 0, 0 ) failed: Bad file descriptor (errno = 9)
May  4 12:03:14 shona xinetd[39631]: warning: can't get client address: Bad file descriptor
May  4 12:03:14 shona xinetd[39631]: fcntl( 0, clear close-on-exec ) failed: Bad file descriptor (errno = 9)
May  4 12:03:14 shona xinetd[39631]: dup2( 0, 0 ) failed: Bad file descriptor (errno = 9)

Lots of hits on those file descriptor errors on Google but nothing recent nor relevant. I've tried several variations to the xinetd.conf parameters but haven't had any luck so far in making it work.

• Adding tftp-proxy service to /etc/services and using that for the service name, removing unlisted
• Removing the server_args, or including the executable name (which shouldn't be needed with xinetd, but I tried nonetheless)
• Adding "groups = yes" to xinetd
• Increased logging in xinetd.conf and run in debug mode
• Checked to ensure /var/empty exists (tftp-proxy chroots there), and that its permissions match those on 2.2.x, and that the proxy user exists