Project

General

Profile

Bug #6315

tftp-proxy is not functioning properly through xinetd

Added by Jim Pingle over 3 years ago. Updated over 3 years ago.

Status:
Resolved
Priority:
Normal
Category:
Operating System
Target version:
Start date:
05/04/2016
Due date:
% Done:

100%

Estimated time:
Affected Version:
2.3
Affected Architecture:

Description

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.

I have tried:
  • 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

History

#1 Updated by Chris Buechler over 3 years ago

  • Status changed from New to Confirmed

#2 Updated by Bruce Simpson over 3 years ago

Data point: I'm seeing similar behaviour with daytime-dgram on 2.3.1-p1.

Why bring this up in 2016? Well, we need RFC 867 DAYTIME to support an ancient Lantronix console server which does not speak SNTP.

The simple configuration...

service daytime
{     
     disable             = no
     type                = INTERNAL
     id                  = daytime-dgram
     socket_type         = dgram 
     protocol            = udp
     user                = root
     wait                = yes
} 

...yields this when I use a simple daytime UDP client to test the service is running 4 seconds after starting it in debug mode (no syslog output expected or seen, and no RFC 867 response packet):

[2.3.1-RELEASE][root@gw.lab]/root: /usr/local/sbin/xinetd -d -f /root/xinetd-daytime.conf
Service defaults
        Bind = All addresses.
        Only from: All sites
        No access: No blocked sites
        No logging

Service configuration: daytime
        id = daytime-dgram
        flags = IPv4
        type = INTERNAL
        socket_type = dgram
        Protocol (name,number) = (udp,17)
        port = 13
        wait = yes
        user = 0
        Groups = no
        PER_SOURCE = -1
        Bind = All addresses.
        Only from: All sites
        No access: No blocked sites
        No logging

16/6/17@22:41:52: DEBUG: 14464 {cnf_start_services} Started service: daytime-dgram
16/6/17@22:41:52: DEBUG: 14464 {cnf_start_services} mask_max = 0, services_started = 1
16/6/17@22:41:52: NOTICE: 14464 {main} xinetd Version 2.3.15 started with libwrap loadavg options compiled in.
16/6/17@22:41:52: NOTICE: 14464 {main} Started working: 1 available service
16/6/17@22:41:52: DEBUG: 14464 {main_loop} active_services = 1
16/6/17@22:41:56: DEBUG: 14464 {main_loop} select returned 1
16/6/17@22:41:56: DEBUG: 14464 {svc_suspend} Suspended service daytime-dgram
16/6/17@22:41:56: DEBUG: 14464 {svc_resume} Resumed service daytime-dgram
16/6/17@22:41:56: DEBUG: 14464 {drain} UDP socket should be empty
16/6/17@22:41:56: DEBUG: 14464 {main_loop} active_services = 1

...which points towards a possible regression on FreeBSD in the upstream port of xinetd.

#3 Updated by Renato Botelho over 3 years ago

  • Status changed from Confirmed to Assigned
  • Assignee set to Renato Botelho

working on that

#4 Updated by Renato Botelho over 3 years ago

I reproduced it on stock FreeBSD and opened a ticket on FreeBSD's bugzilla - https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=211038

#5 Updated by Renato Botelho over 3 years ago

  • Status changed from Assigned to Feedback
  • % Done changed from 0 to 100

#6 Updated by Renato Botelho over 3 years ago

  • Status changed from Feedback to Resolved

works

Also available in: Atom PDF