Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Open
nagata-logly opened this issue Apr 6, 2016 · 13 comments
Open

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

nagata-logly opened this issue Apr 6, 2016 · 13 comments

Comments

@nagata-logly
Copy link

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
kazuho/p5-Server-Starter#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
  • Net::Server Version: 2.008
  • Starman Version: 0.4014
  • Server::Starter Version: 0.32
@nagata-logly
Copy link
Author

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
Copy link
Owner

miyagawa commented Apr 6, 2016

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
Copy link
Author

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
Copy link
Owner

miyagawa commented Apr 6, 2016

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
Copy link
Author

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

@nagata-logly
Copy link
Author

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
Copy link
Owner

miyagawa commented Apr 6, 2016

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
Copy link
Owner

miyagawa commented Apr 6, 2016

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

@kazuho
Copy link
Collaborator

kazuho commented Apr 6, 2016

@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
Copy link
Author

@miyagawa @kazuho
What I should be something?

  • make a new issue to Net::Server::SS::PreFork?
  • wait a release new Starman::Server?
  • or any other thing?

@kazuho kazuho mentioned this issue Apr 6, 2016
Open
@kazuho
Copy link
Collaborator

kazuho commented Apr 6, 2016

@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
Copy link
Owner

miyagawa commented Apr 6, 2016

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

@kazuho
Copy link
Collaborator

kazuho commented Apr 7, 2016

@miyagawa Thank you for stating that.

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@miyagawa @kazuho @nagata-logly