search

miyagawa / Starman

Starman is a high-performance preforking Perl PSGI web server
http://search.cpan.org/dist/Starman
Other
287 stars 84 forks source link

Crashing when listening on a socket with Server::Starter #120

Open nagata-logly opened 8 years ago

nagata-logly commented 8 years ago

I tried Starman with Server::Starter by unix socket. But it didn't work. error is here.

Bad arg length for Socket::unpack_sockaddr_in, length is 24, should be 16 at /home/hoge/perl5/perlbrew/perls/perl-5.16.0/lib/5.16.0/x86_64-linux/Socket.pm line 780.

And I found similar issue in Server::Starter https://github.com/kazuho/p5-Server-Starter/issues/27 But @kazuho say 「This is likely a bug in Starman」

When I tried only Starman by unix socket. It work fine.

starman --listen /tmp/hoge.sock hoge.psgi

When I tried Starman with Server::Starter by unix socket. It not work.

start_server --path=/tmp/hoge.sock -- starman hoge.psgi
nagata-logly commented 8 years ago

I find debug message from Plack::Runner

Starman: Accepting connections at http://0:5000/

My cmd is start_server --path=/tmp/hoge.sock -- starman hoge.psgi But why port 500 ?

So I change my cmd.

start_server --path=/tmp/hoge.sock -- starman --listen /tmp/hoge.sock hoge.psgi

And find debug message from Plack::Runner

Starman: Accepting connections at unix://localhost:/tmp/hoge.sock/

But It has same error.

Bad arg length for Socket::unpack_sockaddr_in, length is 24, should be 16 at /home/hoge/perl5/perlbrew/perls/perl-5.16.0/lib/5.16.0/x86_64-linux/Socket.pm line 780.
miyagawa commented 8 years ago

about your later comment - you can't use the same UNIX socket for start_server and starman. Starman will automatically open the fd that start_server passes to starman. About the message, it just uses the default port of 0:5000 for the display purpose and i don't think it actually uses that port number.

Can you try installing Devel::Confess and try running with perl -d:Confess -s start_server --path=/tmp/foo.sock -- starman so you can get a full stacktrace?

nagata-logly commented 8 years ago

I find other debug message from Net::Server::Proto::UNIX When I tried only Starman by unix socket.

Binding to UNIX socket file "/tmp/hoge.sock"

But there is no message with Server::Starter

So I compare options in Net::Server.

sub run {
    my $self = ref($_[0]) ? shift() : shift->new;  # pass package or object
    $self->{'server'}->{'_run_args'} = [@_ == 1 ? %{$_[0]} : @_];
    $self->_initialize;         # configure all parameters

    printf("net::server self  = %s\n", Dumper($self));

When I tried Starman with Server::Starter by unix socket.

2016-04-06 12:52:52.075556500 net::server self  = $VAR1 = bless( {
2016-04-06 12:52:52.075557500                  'app' => sub { "DUMMY" },
2016-04-06 12:52:52.075559500                  'options' => {
2016-04-06 12:52:52.075560500                                 'read_timeout' => 5,
2016-04-06 12:52:52.075561500                                 'server_ready' => sub { "DUMMY" },
2016-04-06 12:52:52.075562500                                 'workers' => '1',
2016-04-06 12:52:52.075586500                                 'keepalive_timeout' => 1,
2016-04-06 12:52:52.075588500                                 'port' => undef,
2016-04-06 12:52:52.075589500                                 'host' => undef,
2016-04-06 12:52:52.075591500                                 'socket' => '/tmp/hoge.sock',
2016-04-06 12:52:52.075597500                                 'psgi_app_builder' => sub { "DUMMY" },
2016-04-06 12:52:52.075598500                                 'listen' => [
2016-04-06 12:52:52.075599500                                               '/tmp/hoge.sock'
2016-04-06 12:52:52.075601500                                             ],
2016-04-06 12:52:52.075602500                                 'argv' => [
2016-04-06 12:52:52.075603500                                             '-E',
2016-04-06 12:52:52.075606500                                             'development',
2016-04-06 12:52:52.075608500                                             '--listen',
2016-04-06 12:52:52.075609500                                             '/tmp/hoge.sock',
2016-04-06 12:52:52.075611500                                             '--workers=1',
2016-04-06 12:52:52.075612500                                             '--disable-keepalive',
2016-04-06 12:52:52.075618500                                             'hoge.psgi'
2016-04-06 12:52:52.075620500                                           ],
2016-04-06 12:52:52.075621500                                 'keepalive' => '',
2016-04-06 12:52:52.075623500                                 'proctitle' => 1
2016-04-06 12:52:52.075624500                               },
2016-04-06 12:52:52.075625500                  'server' => {
2016-04-06 12:52:52.075628500                                'conf_file' => undef,
2016-04-06 12:52:52.075631500                                'reverse_lookups' => undef,
2016-04-06 12:52:52.075633500                                'setsid' => undef,
2016-04-06 12:52:52.075634500                                'pid_file' => undef,
2016-04-06 12:52:52.075635500                                'listen' => 1024,
2016-04-06 12:52:52.075637500                                'user' => '5000',
2016-04-06 12:52:52.075638500                                'ipv' => [],
2016-04-06 12:52:52.075641500                                'proto' => [
2016-04-06 12:52:52.075642500                                             'tcp'
2016-04-06 12:52:52.075643500                                           ],
2016-04-06 12:52:52.075644500                                'chroot' => undef,
2016-04-06 12:52:52.075646500                                'deny' => [],
2016-04-06 12:52:52.075647500                                'min_child_ttl' => 10,
2016-04-06 12:52:52.075650500                                'tied_stdout_callback' => undef,
2016-04-06 12:52:52.075651500                                'port' => [
2016-04-06 12:52:52.075652500                                            {
2016-04-06 12:52:52.075653500                                              'proto' => 'unix',
2016-04-06 12:52:52.075655500                                              'port' => '/tmp/hoge.sock',
2016-04-06 12:52:52.075656500                                              'host' => 'localhost'
2016-04-06 12:52:52.075659500                                            }
2016-04-06 12:52:52.075662500                                          ],
2016-04-06 12:52:52.075664500                                'no_client_stdout' => 1,
2016-04-06 12:52:52.075665500                                'check_for_dead' => 30,
2016-04-06 12:52:52.075666500                                'max_requests' => 1000,
2016-04-06 12:52:52.075667500                                'cidr_deny' => [],
2016-04-06 12:52:52.075669500                                'min_spare_servers' => 0,
2016-04-06 12:52:52.075671500                                'lock_file' => undef,
2016-04-06 12:52:52.075673500                                'cidr_allow' => [],
2016-04-06 12:52:52.075674500                                'child_communication' => undef,
2016-04-06 12:52:52.075675500                                'min_servers' => 1,
2016-04-06 12:52:52.075676500                                'serialize' => 'none',
2016-04-06 12:52:52.075678500                                'check_for_dequeue' => undef,
2016-04-06 12:52:52.075685500                                'group' => '10 10',
2016-04-06 12:52:52.075686500                                'leave_children_open_on_hup' => undef,
2016-04-06 12:52:52.075687500                                'max_servers' => 1,
2016-04-06 12:52:52.075689500                                'log_level' => 2,
2016-04-06 12:52:52.075690500                                'tie_client_stdout' => undef,
2016-04-06 12:52:52.075691500                                'spare_servers' => undef,
2016-04-06 12:52:52.075694500                                'sock' => [
2016-04-06 12:52:52.075697500                                            bless( \*Symbol::GEN0, 'Net::Server::Proto::TCP' )
2016-04-06 12:52:52.075699500                                          ],
2016-04-06 12:52:52.075700500                                'max_spare_servers' => 0,
2016-04-06 12:52:52.075701500                                '_run_args' => [],
2016-04-06 12:52:52.075703500                                'background' => undef,
2016-04-06 12:52:52.075704500                                'check_for_waiting' => 1,
2016-04-06 12:52:52.075707500                                'sig_passthrough' => [],
2016-04-06 12:52:52.075708500                                'log_file' => '',
2016-04-06 12:52:52.075709500                                'host' => [
2016-04-06 12:52:52.075710500                                            '*'
2016-04-06 12:52:52.075712500                                          ],
2016-04-06 12:52:52.075713500                                'check_for_spawn' => 30,
2016-04-06 12:52:52.075716500                                'ppid' => '14383',
2016-04-06 12:52:52.075717500                                'max_dequeue' => undef,
2016-04-06 12:52:52.075718500                                'no_close_by_child' => undef,
2016-04-06 12:52:52.075719500                                'allow' => [],
2016-04-06 12:52:52.075721500                                'tied_stdin_callback' => undef,
2016-04-06 12:52:52.075722500                                'commandline' => [
2016-04-06 12:52:52.075725500                                                   'starman'
2016-04-06 12:52:52.075730500                                                 ]
2016-04-06 12:52:52.075731500                              }
2016-04-06 12:52:52.075732500                }, 'Starman::Server' );

When I tried only Starman by unix socket.

2016-04-06 12:54:02.805959500 net::server self  = $VAR1 = bless( {
2016-04-06 12:54:02.805960500                  'app' => sub { "DUMMY" },
2016-04-06 12:54:02.805961500                  'options' => {
2016-04-06 12:54:02.805963500                                 'read_timeout' => 5,
2016-04-06 12:54:02.805964500                                 'server_ready' => sub { "DUMMY" },
2016-04-06 12:54:02.805965500                                 'workers' => '1',
2016-04-06 12:54:02.805975500                                 'keepalive_timeout' => 1,
2016-04-06 12:54:02.805977500                                 'port' => undef,
2016-04-06 12:54:02.805978500                                 'host' => undef,
2016-04-06 12:54:02.805979500                                 'socket' => '/tmp/hoge.sock',
2016-04-06 12:54:02.805983500                                 'psgi_app_builder' => sub { "DUMMY" },
2016-04-06 12:54:02.805985500                                 'listen' => [
2016-04-06 12:54:02.805986500                                               '/tmp/hoge.sock'
2016-04-06 12:54:02.805987500                                             ],
2016-04-06 12:54:02.805989500                                 'argv' => [
2016-04-06 12:54:02.805990500                                             '-E',
2016-04-06 12:54:02.805992500                                             'development',
2016-04-06 12:54:02.805994500                                             '--listen',
2016-04-06 12:54:02.805995500                                             '/tmp/hoge.sock',
2016-04-06 12:54:02.805996500                                             '--workers=1',
2016-04-06 12:54:02.805998500                                             '--disable-keepalive',
2016-04-06 12:54:02.806000500                                             'hoge.psgi'
2016-04-06 12:54:02.806002500                                           ],
2016-04-06 12:54:02.806003500                                 'keepalive' => '',
2016-04-06 12:54:02.806004500                                 'proctitle' => 1
2016-04-06 12:54:02.806006500                               },
2016-04-06 12:54:02.806007500                  'server' => {
2016-04-06 12:54:02.806010500                                'conf_file' => undef,
2016-04-06 12:54:02.806014500                                'reverse_lookups' => undef,
2016-04-06 12:54:02.806015500                                'setsid' => undef,
2016-04-06 12:54:02.806017500                                'pid_file' => undef,
2016-04-06 12:54:02.806018500                                'listen' => 1024,
2016-04-06 12:54:02.806019500                                'unix_path' => undef,
2016-04-06 12:54:02.806020500                                '_bind' => [
2016-04-06 12:54:02.806023500                                             {
2016-04-06 12:54:02.806024500                                               'proto' => 'unix',
2016-04-06 12:54:02.806026500                                               'ipv' => '*',
2016-04-06 12:54:02.806027500                                               'port' => 'hoge.sock',
2016-04-06 12:54:02.806028500                                               'host' => 'localhost'
2016-04-06 12:54:02.806031500                                             }
2016-04-06 12:54:02.806032500                                           ],
2016-04-06 12:54:02.806034500                                'user' => '5000',
2016-04-06 12:54:02.806035500                                'ipv' => [],
2016-04-06 12:54:02.806036500                                'proto' => [
2016-04-06 12:54:02.806037500                                             'tcp'
2016-04-06 12:54:02.806040500                                           ],
2016-04-06 12:54:02.806041500                                'chroot' => undef,
2016-04-06 12:54:02.806045500                                'deny' => [],
2016-04-06 12:54:02.806046500                                'min_child_ttl' => 10,
2016-04-06 12:54:02.806047500                                'tied_stdout_callback' => undef,
2016-04-06 12:54:02.806049500                                'port' => [
2016-04-06 12:54:02.806050500                                            {
2016-04-06 12:54:02.806051500                                              'proto' => 'unix',
2016-04-06 12:54:02.806056500                                              'port' => 'hoge.sock',
2016-04-06 12:54:02.806058500                                              'host' => 'localhost'
2016-04-06 12:54:02.806059500                                            }
2016-04-06 12:54:02.806060500                                          ],
2016-04-06 12:54:02.806062500                                'no_client_stdout' => 1,
2016-04-06 12:54:02.806063500                                'unix_type' => undef,
2016-04-06 12:54:02.806066500                                'check_for_dead' => 30,
2016-04-06 12:54:02.806067500                                'max_requests' => 1000,
2016-04-06 12:54:02.806068500                                'cidr_deny' => [],
2016-04-06 12:54:02.806070500                                'min_spare_servers' => 0,
2016-04-06 12:54:02.806071500                                'lock_file' => undef,
2016-04-06 12:54:02.806072500                                'cidr_allow' => [],
2016-04-06 12:54:02.806075500                                'child_communication' => undef,
2016-04-06 12:54:02.806078500                                'min_servers' => 1,
2016-04-06 12:54:02.806080500                                'serialize' => 'none',
2016-04-06 12:54:02.806081500                                'check_for_dequeue' => undef,
2016-04-06 12:54:02.806082500                                'group' => '10 10',
2016-04-06 12:54:02.806084500                                'leave_children_open_on_hup' => undef,
2016-04-06 12:54:02.806085500                                'max_servers' => 1,
2016-04-06 12:54:02.806087500                                'log_level' => 2,
2016-04-06 12:54:02.806089500                                'tie_client_stdout' => undef,
2016-04-06 12:54:02.806090500                                'spare_servers' => undef,
2016-04-06 12:54:02.806091500                                'sock' => [
2016-04-06 12:54:02.806093500                                            bless( \*Symbol::GEN0, 'Net::Server::Proto::UNIX' )
2016-04-06 12:54:02.806094500                                          ],
2016-04-06 12:54:02.806097500                                'max_spare_servers' => 0,
2016-04-06 12:54:02.806098500                                '_run_args' => [],
2016-04-06 12:54:02.806099500                                'background' => undef,
2016-04-06 12:54:02.806101500                                'check_for_waiting' => 1,
2016-04-06 12:54:02.806102500                                'sig_passthrough' => [],
2016-04-06 12:54:02.806103500                                'log_file' => '',
2016-04-06 12:54:02.806107500                                'host' => [
2016-04-06 12:54:02.806108500                                            '*'
2016-04-06 12:54:02.806109500                                          ],
2016-04-06 12:54:02.806111500                                'check_for_spawn' => 30,
2016-04-06 12:54:02.806112500                                'ppid' => '25517',
2016-04-06 12:54:02.806113500                                'max_dequeue' => undef,
2016-04-06 12:54:02.806116500                                'no_close_by_child' => undef,
2016-04-06 12:54:02.806117500                                'allow' => [],
2016-04-06 12:54:02.806118500                                'tied_stdin_callback' => undef,
2016-04-06 12:54:02.806120500                                'commandline' => [
2016-04-06 12:54:02.806121500                                                   'starman'
2016-04-06 12:54:02.806124500                                                 ]
2016-04-06 12:54:02.806125500                              }
2016-04-06 12:54:02.806126500                }, 'Starman::Server' );
2016-04-06 12:54:02.806128500
miyagawa commented 8 years ago

Also try STARMAN_DEBUG=1.

I cannot reproduce the error, it seems to work fine. When exactly do you get that error? When a client connects to the start_server? via nginx or something?

nagata-logly commented 8 years ago

Oh I find your comment now. I use nginx. OK I will try Devel::Confess after.

nagata-logly commented 8 years ago

But I have call stack from cluck to only load psgi.

called at lib/perl5/Plack/Runner.pm line 179            Plack::Util::load_psgi('hoge.psgi') 
called at lib/perl5/Plack/Runner.pm line 24         Plack::Runner::__ANON__() 
called at lib/perl5/Plack/Runner.pm line 24         Plack::Runner::__ANON__() 
called at lib/perl5/Plack/Runner.pm line 24         Plack::Runner::__ANON__() 
called at lib/perl5/Plack/Runner.pm line 24         Plack::Runner::__ANON__() 
called at lib/perl5/Starman/Server.pm line 177
called at lib/perl5/Net/Server/PreFork.pm line 222  Starman::Server::child_init_hook('Starman::Server=HASH(0x1d965e8)') 
called at lib/perl5/Net/Server/PreFork.pm line 187  Net::Server::PreFork::run_child('Starman::Server=HASH(0x1d965e8)') 
called at lib/perl5/Net/Server/PreFork.pm line 111  Net::Server::PreFork::run_n_children('Starman::Server=HASH(0x1d965e8)', 1) 
called at lib/perl5/Net/Server.pm line 60           Net::Server::PreFork::loop('Starman::Server=HASH(0x1d965e8)') 
called at lib/perl5/Starman/Server.pm line 97           Net::Server::run('Starman::Server=HASH(0x1d965e8)', 'port', 'ARRAY(0x239a678)', 'host', '*', 'proto', 'tcp', 'serialize', 'none', ...) 
called at lib/perl5/Plack/Handler/Starman.pm line 25    Starman::Server::run('Starman::Server=HASH(0x1d965e8)', 'CODE(0x205a2f0)', 'HASH(0x23ce070)') 
called at lib/perl5/Plack/Loader/Delayed.pm line 20 Plack::Handler::Starman::run('Plack::Handler::Starman=HASH(0x205a3b0)', 'CODE(0x205a2f0)') 
called at lib/perl5/Plack/Runner.pm line 283            Plack::Loader::Delayed::run('Plack::Loader::Delayed=HASH(0x1d06f20)', 'Plack::Handler::Starman=HASH(0x205a3b0)') 
called at bin/starman line 38                           Plack::Runner::run('Plack::Runner=HASH(0x1d46d48)')
miyagawa commented 8 years ago

I got this:

Starting "1" children
Bad arg length for Socket::unpack_sockaddr_in, length is 106, should be 16 at /Users/miyagawa/.plenv/versions/5.20.1/lib/perl5/site_perl/5.20.1/darwin-2level/Socket.pm line 831.
    Socket::sockaddr_in("j\x{1}/tmp/backend.sock\x{0}\x{0}\x{0}\x{0}\x{0}\x{0}\x{0}\x{0}\x{0}\x{0}\x{0}\x{0}\x{0}\x{0}\x{0}\x{0}\x{0}\x{0}\x{0}\x{0}\x{0}\x{0}\x{0}\x{0}\x{0}\x{0}\x{0}\x{0}\x{0}\x{0}\x{0}\x{0}\x{0}\x{0}\x{0}\x{0}\x{0}\x{0}\x{0}\x{0}\x{0}\x{0}"...) called at /Users/miyagawa/.plenv/versions/5.20.1/lib/perl5/5.20.1/darwin-2level/IO/Socket/INET.pm line 271
    IO::Socket::INET::sockaddr(Net::Server::Proto::TCP=GLOB(0x7ffa32309168)) called at /Users/miyagawa/.plenv/versions/5.20.1/lib/perl5/5.20.1/darwin-2level/IO/Socket/INET.pm line 284
    IO::Socket::INET::sockhost(Net::Server::Proto::TCP=GLOB(0x7ffa32309168)) called at /Users/miyagawa/.plenv/versions/5.20.1/lib/perl5/site_perl/5.20.1/Net/Server.pm line 521
    Net::Server::get_client_info(Starman::Server=HASH(0x7ffa32103690), Net::Server::Proto::TCP=GLOB(0x7ffa32309168)) called at /Users/miyagawa/.plenv/versions/5.20.1/lib/perl5/site_perl/5.20.1/Net/Server.pm line 70
    Net::Server::run_client_connection(Starman::Server=HASH(0x7ffa32103690)) called at /Users/miyagawa/.plenv/versions/5.20.1/lib/perl5/site_perl/5.20.1/Net/Server/PreFork.pm line 229
    eval {...} called at /Users/miyagawa/.plenv/versions/5.20.1/lib/perl5/site_perl/5.20.1/Net/Server/PreFork.pm line 229
    Net::Server::PreFork::run_child(Starman::Server=HASH(0x7ffa32103690)) called at /Users/miyagawa/.plenv/versions/5.20.1/lib/perl5/site_perl/5.20.1/Net/Server/PreFork.pm line 187
    Net::Server::PreFork::run_n_children(Starman::Server=HASH(0x7ffa32103690), 5) called at /Users/miyagawa/.plenv/versions/5.20.1/lib/perl5/site_perl/5.20.1/Net/Server/PreFork.pm line 111
    Net::Server::PreFork::loop(Starman::Server=HASH(0x7ffa32103690)) called at /Users/miyagawa/.plenv/versions/5.20.1/lib/perl5/site_perl/5.20.1/Net/Server.pm line 60
    Net::Server::run(Starman::Server=HASH(0x7ffa32103690), "port", ARRAY(0x7ffa319669c8), "host", "*", "proto", "tcp", "serialize", ...) called at /Users/miyagawa/.plenv/versions/5.20.1/lib/perl5/site_perl/5.20.1/Starman/Server.pm line 94
    Starman::Server::run(Starman::Server=HASH(0x7ffa32103690), CODE(0x7ffa321033f0), HASH(0x7ffa31994908)) called at /Users/miyagawa/.plenv/versions/5.20.1/lib/perl5/site_perl/5.20.1/Plack/Handler/Starman.pm line 25
miyagawa commented 8 years ago

Net::Server(::SS) assumes that the client is a TCP socket.

kazuho commented 8 years ago

@miyagawa @nagata-logly So it turns out to be an issue of Net::Server::SS::PreFork, a module related to Server::Starter. Thank you very much for identifying the cause.

I have just imported the source code of the module from CodeRepos to github. Looking at it (PreFork.pm line 20), it is obivous that the module only expects a TCP socket to be passed over.

nagata-logly commented 8 years ago

@miyagawa @kazuho What I should be something?

kazuho commented 8 years ago

@nagata-logly Sorry I wasn't clear of the next steps.

I've opened a issue (see ^^). You could just wait for someone to fix the issue, or you could implement a fix by yourself and file a PR!

FWIW, you can use Socket::sockaddr_family to determine the type of the socket (see https://github.com/kazuho/Starlet/blob/master/lib/Starlet/Server.pm#L99-L100).

miyagawa commented 8 years ago

the alternative to use Starlet, assuming that's supported there.

kazuho commented 8 years ago

@miyagawa Thank you for stating that.

Thanks to @nagata-logly we have a working fix on https://github.com/kazuho/p5-Net-Server-SS-PreFork/pull/2, so people can use Starman + Server::Starter with Unix sockets :+1: