--- deliantra/server/lib/cf.pm 2010/04/28 11:28:22 1.529 +++ deliantra/server/lib/cf.pm 2010/05/05 09:05:03 1.542 @@ -22,9 +22,7 @@ package cf; -use 5.10.0; -use utf8; -use strict qw(vars subs); +use common::sense; use Symbol; use List::Util; @@ -80,6 +78,8 @@ sub WF_AUTOCANCEL () { 1 } # automatically cancel this watcher on reload +our @ORIG_INC; + our %COMMAND = (); our %COMMAND_TIME = (); @@ -108,7 +108,7 @@ our $PIDFILE = "$LOCALDIR/pid"; our $RUNTIMEFILE = "$LOCALDIR/runtime"; -our %RESOURCE; +our %RESOURCE; # unused our $OUTPUT_RATE_MIN = 3000; our $OUTPUT_RATE_MAX = 1000000; @@ -254,6 +254,12 @@ =cut +sub error(@) { LOG llevError, join "", @_ } +sub warn (@) { LOG llevWarn , join "", @_ } +sub info (@) { LOG llevInfo , join "", @_ } +sub debug(@) { LOG llevDebug, join "", @_ } +sub trace(@) { LOG llevTrace, join "", @_ } + $Coro::State::WARNHOOK = sub { my $msg = join "", @_; @@ -262,16 +268,16 @@ $msg =~ s/([\x00-\x08\x0b-\x1f])/sprintf "\\x%02x", ord $1/ge; - LOG llevError, $msg; + LOG llevWarn, $msg; }; $Coro::State::DIEHOOK = sub { return unless $^S eq 0; # "eq", not "==" - warn Carp::longmess $_[0]; + error Carp::longmess $_[0]; if (in_main) {#d# - warn "DIEHOOK called in main context, Coro bug?\n";#d# + error "DIEHOOK called in main context, Coro bug?\n";#d# return;#d# }#d# @@ -514,13 +520,13 @@ sub sync_job(&) { my ($job) = @_; - if ($Coro::current == $Coro::main) { + if (in_main) { my $time = AE::time; # this is the main coro, too bad, we have to block # till the operation succeeds, freezing the server :/ - LOG llevError, Carp::longmess "sync job";#d# + #LOG llevError, Carp::longmess "sync job";#d# my $freeze_guard = freeze_mainloop; @@ -530,7 +536,7 @@ (async { $Coro::current->desc ("sync job coro"); @res = eval { $job->() }; - warn $@ if $@; + error $@ if $@; undef $busy; })->prio (Coro::PRIO_MAX); @@ -653,6 +659,9 @@ =cut sub db_table($) { + cf::error "db_get called from main context" + if $Coro::current == $Coro::main; + my ($name) = @_; my $db = BDB::db_create $DB_ENV; @@ -672,20 +681,19 @@ our $DB; sub db_init { - cf::sync_job { - $DB ||= db_table "db"; - }; + $DB ||= db_table "db"; } sub db_get($$) { my $key = "$_[0]/$_[1]"; - cf::sync_job { - BDB::db_get $DB, undef, $key, my $data; + cf::error "db_get called from main context" + if $Coro::current == $Coro::main; - $! ? () - : $data - } + BDB::db_get $DB, undef, $key, my $data; + + $! ? () + : $data } sub db_put($$$) { @@ -751,7 +759,7 @@ my $data = $process->(\@data); my $t2 = Time::HiRes::time; - warn "cache: '$id' processed in ", $t2 - $t1, "s\n"; + info "cache: '$id' processed in ", $t2 - $t1, "s\n"; db_put cache => "$id/data", $data; db_put cache => "$id/md5" , $md5; @@ -771,7 +779,7 @@ sub datalog($@) { my ($type, %kv) = @_; - warn "DATALOG ", JSON::XS->new->ascii->encode ({ %kv, type => $type }); + info "DATALOG ", JSON::XS->new->ascii->encode ({ %kv, type => $type }); } =back @@ -976,11 +984,11 @@ _attach_cb $registry, $cb_id{$type}, $prio, shift @arg; } elsif (ref $type) { - warn "attaching objects not supported, ignoring.\n"; + error "attaching objects not supported, ignoring.\n"; } else { shift @arg; - warn "attach argument '$type' not supported, ignoring.\n"; + error "attach argument '$type' not supported, ignoring.\n"; } } } @@ -1000,7 +1008,7 @@ $obj->{$name} = \%arg; } else { - warn "object uses attachment '$name' which is not available, postponing.\n"; + info "object uses attachment '$name' which is not available, postponing.\n"; } $obj->{_attachment}{$name} = undef; @@ -1069,8 +1077,7 @@ eval { &{$_->[1]} }; if ($@) { - warn "$@"; - warn "... while processing $EVENT[$event][0](@_) event, skipping processing altogether.\n"; + error "$@", "... while processing $EVENT[$event][0](@_) event, skipping processing altogether.\n"; override; } @@ -1159,7 +1166,7 @@ _attach $registry, $klass, @attach; } } else { - warn "object uses attachment '$name' that is not available, postponing.\n"; + info "object uses attachment '$name' that is not available, postponing.\n"; } } } @@ -1196,8 +1203,8 @@ sync_job { if (length $$rdata) { utf8::decode (my $decname = $filename); - warn sprintf "saving %s (%d,%d)\n", - $decname, length $$rdata, scalar @$objs + trace sprintf "saving %s (%d,%d)\n", + $decname, length $$rdata, scalar @$objs if $VERBOSE_IO; if (my $fh = aio_open "$filename~", O_WRONLY | O_CREAT, 0600) { @@ -1230,7 +1237,7 @@ $filename =~ s%/[^/]+$%%; aio_pathsync $filename if $cf::USE_FSYNC; } else { - warn "unable to save objects: $filename~: $!\n"; + error "unable to save objects: $filename~: $!\n"; } } else { aio_unlink $filename; @@ -1264,8 +1271,8 @@ } utf8::decode (my $decname = $filename); - warn sprintf "loading %s (%d,%d)\n", - $decname, length $data, scalar @{$av || []} + trace sprintf "loading %s (%d,%d)\n", + $decname, length $data, scalar @{$av || []} if $VERBOSE_IO; ($data, $av) @@ -1368,7 +1375,7 @@ if $reply; } else { - warn "player " . ($pl->ob->name) . " sent unparseable ext message: <$buf>\n"; + error "player " . ($pl->ob->name) . " sent unparseable ext message: <$buf>\n"; } cf::override; @@ -1389,6 +1396,8 @@ } sub load_extensions { + info "loading extensions..."; + cf::sync_job { my %todo; @@ -1416,7 +1425,7 @@ if $source =~ /\A#!.*?perl.*?#\s*(.*)$/m; $ext{source} = - "package $pkg; use 5.10.0; use strict 'vars', 'subs'; use utf8;\n" + "package $pkg; use common::sense;\n" . "#line 1 \"$path\"\n{\n" . $source . "\n};\n1"; @@ -1438,12 +1447,12 @@ unless exists $done{$_}; } - warn "... pass $pass, loading '$k' into '$v->{pkg}'\n"; + trace "... pass $pass, loading '$k' into '$v->{pkg}'\n"; my $active = eval $v->{source}; if (length $@) { - warn "$v->{path}: $@\n"; + error "$v->{path}: $@\n"; cf::cleanup "mandatory extension '$k' failed to load, exiting." if exists $v->{meta}{mandatory}; @@ -1455,7 +1464,7 @@ push @EXTS, $v->{pkg}; $progress = 1; - warn "$v->{base}: extension inactive.\n" + info "$v->{base}: extension inactive.\n" unless $active; } } @@ -1841,7 +1850,6 @@ my (undef, $regex, $prio) = @_; my $pkg = caller; - no strict; push @{"$pkg\::ISA"}, __PACKAGE__; $EXT_MAP{$pkg} = [$prio, qr<$regex>]; @@ -2185,16 +2193,19 @@ sub find_sync { my ($path, $origin) = @_; - cf::sync_job { find $path, $origin } + return cf::LOG cf::llevError | cf::logBacktrace, "do_find_sync" + if $Coro::current == $Coro::main; + + find $path, $origin } sub do_load_sync { my ($map) = @_; - cf::LOG cf::llevDebug | cf::logBacktrace, "do_load_sync" + return cf::LOG cf::llevError | cf::logBacktrace, "do_load_sync" if $Coro::current == $Coro::main; - cf::sync_job { $map->load }; + $map->load; } our %MAP_PREFETCH; @@ -2316,7 +2327,7 @@ return if $self->players; - warn "resetting map ", $self->path, "\n"; + cf::trace "resetting map ", $self->path, "\n"; $self->in_memory (cf::MAP_SWAPPED); @@ -2691,7 +2702,7 @@ my ($self, $path, $x, $y, $check, $done) = @_; if ($self->{_link_recursion} >= $MAX_LINKS) { - warn "FATAL: link recursion exceeded, ", $self->name, " goto $path $x $y, redirecting."; + error "FATAL: link recursion exceeded, ", $self->name, " goto $path $x $y, redirecting."; $self->failmsg ("Something went wrong inside the server - please contact an administrator!"); ($path, $x, $y) = @$EMERGENCY_POSITION; } @@ -2849,7 +2860,7 @@ . "Please report this to the dungeon master!", cf::NDI_UNIQUE | cf::NDI_RED); - warn "ERROR in enter_exit: $@"; + error "ERROR in enter_exit: $@"; $self->leave_link; } })->prio (1); @@ -3172,7 +3183,7 @@ if $reply; } else { - warn "client " . ($ns->pl ? $ns->pl->ob->name : $ns->host) . " sent unparseable exti message: <$buf>\n"; + error "client " . ($ns->pl ? $ns->pl->ob->name : $ns->host) . " sent unparseable exti message: <$buf>\n"; } cf::override; @@ -3263,7 +3274,6 @@ ["cf::player" => qw(peaceful send_msg)], ["cf::map" => qw(trigger)], ) { - no strict 'refs'; my ($pkg, @funs) = @$_; *{"safe::$pkg\::$_"} = $safe_hole->wrap (\&{"$pkg\::$_"}) for @funs; @@ -3312,9 +3322,9 @@ } if ($@) { - warn "$@"; - warn "while executing safe code '$code'\n"; - warn "with arguments " . (join " ", %vars) . "\n"; + warn "$@", + "while executing safe code '$code'\n", + "with arguments " . (join " ", %vars) . "\n"; } wantarray ? @res : $res[0] @@ -3349,6 +3359,48 @@ ############################################################################# # the server's init and main functions +# async inc loader. yay. +sub inc_loader { + my $mod = $_[1]; + + if (in_main && !tick_inhibit) { + Carp::cluck "ERROR: attempted synchronous perl module load ($mod)"; + } else { + debug "loading perl module $mod\n"; + } + + # 1. find real file + for my $dir (@ORIG_INC) { + ref $dir and next; + 0 <= Coro::AIO::aio_load "$dir/$mod", my $data + or next; + + $data = "#line 1 $dir/$mod\n$data"; + + open my $fh, "<", \$data or die; + + return $fh; + } + + () +} + +sub init_inc { + # save original @INC + @ORIG_INC = ($LIBDIR, @INC) unless @ORIG_INC; + + # make sure we can do scalar-opens + open my $dummy, "<", \my $dummy2; + + # execute some stuff so perl load's some of the core modules + /Ü/ =~ /ü/i; + eval { &Storable::nstore_fd }; + + @INC = (\&inc_loader, @ORIG_INC); # @ORIG_INC is needed for DynaLoader, AutoLoad etc. + + debug "module loading will be asynchronous from this point on."; +} + sub load_facedata($) { my ($path) = @_; @@ -3358,7 +3410,7 @@ my $enc = JSON::XS->new->utf8->canonical->relaxed; - warn "loading facedata from $path\n"; + trace "loading facedata from $path\n"; my $facedata; 0 < aio_load $path, $facedata @@ -3402,7 +3454,7 @@ cf::face::set_smooth $idx, $smooth; cf::face::set_smoothlevel $idx, $info->{smoothlevel}; } else { - warn "smooth face '$info->{smooth}' not found for face '$face'"; + error "smooth face '$info->{smooth}' not found for face '$face'"; } cf::cede_to_tick; @@ -3430,7 +3482,7 @@ cf::face::set_data $idx, 0, $info->{data}, $info->{hash}; cf::face::set_type $idx, $info->{type}; } else { - $RESOURCE{$name} = $info; + $RESOURCE{$name} = $info; # unused } cf::cede_to_tick; @@ -3442,26 +3494,6 @@ 1 } -cf::global->attach (on_resource_update => sub { - if (my $soundconf = $RESOURCE{"res/sound.conf"}) { - $soundconf = JSON::XS->new->utf8->relaxed->decode ($soundconf->{data}); - - for (0 .. SOUND_CAST_SPELL_0 - 1) { - my $sound = $soundconf->{compat}[$_] - or next; - - my $face = cf::face::find "sound/$sound->[1]"; - cf::sound::set $sound->[0] => $face; - cf::sound::old_sound_index $_, $face; # gcfclient-compat - } - - while (my ($k, $v) = each %{$soundconf->{event}}) { - my $face = cf::face::find "sound/$v"; - cf::sound::set $k => $face; - } - } -}); - register_exticmd fx_want => sub { my ($ns, $want) = @_; @@ -3509,19 +3541,43 @@ or die "unable to load treasurelists\n"; } +sub reload_sound { + trace "loading sound config from $DATADIR/sound\n"; + + 0 < Coro::AIO::aio_load "$DATADIR/sound", my $data + or die "$DATADIR/sound $!"; + + my $soundconf = JSON::XS->new->utf8->relaxed->decode ($data); + + for (0 .. SOUND_CAST_SPELL_0 - 1) { + my $sound = $soundconf->{compat}[$_] + or next; + + my $face = cf::face::find "sound/$sound->[1]"; + cf::sound::set $sound->[0] => $face; + cf::sound::old_sound_index $_, $face; # gcfclient-compat + } + + while (my ($k, $v) = each %{$soundconf->{event}}) { + my $face = cf::face::find "sound/$v"; + cf::sound::set $k => $face; + } +} + sub reload_resources { - warn "reloading resource files...\n"; + trace "reloading resource files...\n"; reload_facedata; + reload_sound; reload_archetypes; reload_regions; reload_treasures; - warn "finished reloading resource files\n"; + trace "finished reloading resource files\n"; } sub reload_config { - warn "reloading config file...\n"; + trace "reloading config file...\n"; open my $fh, "<:utf8", "$CONFDIR/config" or return; @@ -3542,7 +3598,7 @@ warn $@ if $@; } - warn "finished reloading resource files\n"; + trace "finished reloading resource files\n"; } sub pidfile() { @@ -3565,11 +3621,11 @@ } sub main_loop { - warn "EV::loop starting\n"; + trace "EV::loop starting\n"; if (1) { EV::loop; } - warn "EV::loop returned\n"; + trace "EV::loop returned\n"; goto &main_loop unless $REALLY_UNLOOP; } @@ -3577,7 +3633,7 @@ cf::init_globals; # initialise logging LOG llevInfo, "Welcome to Deliantra, v" . VERSION; - LOG llevInfo, "Copyright (C) 2005-2008 Marc Alexander Lehmann / Robin Redeker / the Deliantra team."; + LOG llevInfo, "Copyright (C) 2005-2010 Marc Alexander Lehmann / Robin Redeker / the Deliantra team."; LOG llevInfo, "Copyright (C) 1994 Mark Wedel."; LOG llevInfo, "Copyright (C) 1992 Frank Tore Johansen."; @@ -3595,6 +3651,8 @@ evthread_start IO::AIO::poll_fileno; cf::sync_job { + init_inc; + cf::init_experience; cf::init_anim; cf::init_attackmess; @@ -3627,9 +3685,14 @@ }; cf::object::thawer::errors_are_fatal 0; - warn "parse errors in files are no longer fatal from this point on.\n"; + info "parse errors in files are no longer fatal from this point on.\n"; + + my $free_main; $free_main = EV::idle sub { + undef $free_main; + undef &main; # free gobs of memory :) + }; - main_loop; + goto &main_loop; } ############################################################################# @@ -3678,7 +3741,7 @@ aio_rename "$RUNTIMEFILE~", $RUNTIMEFILE and return; - warn sprintf "runtime file written (%gs).\n", AE::time - $t0; + trace sprintf "runtime file written (%gs).\n", AE::time - $t0; 1 } @@ -3700,7 +3763,7 @@ my $value = uuid_seq uuid_cur; unless ($value) { - warn "cowardly refusing to write zero uuid value!\n"; + info "cowardly refusing to write zero uuid value!\n"; return; } @@ -3720,7 +3783,7 @@ aio_rename "$uuid~", $uuid and return; - warn "uuid file written ($value).\n"; + trace "uuid file written ($value).\n"; 1 @@ -3736,55 +3799,77 @@ sub emergency_save() { my $freeze_guard = cf::freeze_mainloop; - warn "emergency_perl_save: enter\n"; + info "emergency_perl_save: enter\n"; + + # this is a trade-off: we want to be very quick here, so + # save all maps without fsync, and later call a global sync + # (which in turn might be very very slow) + local $USE_FSYNC = 0; cf::sync_job { - # this is a trade-off: we want to be very quick here, so - # save all maps without fsync, and later call a global sync - # (which in turn might be very very slow) - local $USE_FSYNC = 0; + cf::write_runtime_sync; # external watchdog should not bark # use a peculiar iteration method to avoid tripping on perl # refcount bugs in for. also avoids problems with players # and maps saved/destroyed asynchronously. - warn "emergency_perl_save: begin player save\n"; + info "emergency_perl_save: begin player save\n"; for my $login (keys %cf::PLAYER) { my $pl = $cf::PLAYER{$login} or next; $pl->valid or next; delete $pl->{unclean_save}; # not strictly necessary, but cannot hurt $pl->save; } - warn "emergency_perl_save: end player save\n"; + info "emergency_perl_save: end player save\n"; + + cf::write_runtime_sync; # external watchdog should not bark - warn "emergency_perl_save: begin map save\n"; + info "emergency_perl_save: begin map save\n"; for my $path (keys %cf::MAP) { my $map = $cf::MAP{$path} or next; $map->valid or next; $map->save; } - warn "emergency_perl_save: end map save\n"; + info "emergency_perl_save: end map save\n"; + + cf::write_runtime_sync; # external watchdog should not bark - warn "emergency_perl_save: begin database checkpoint\n"; + info "emergency_perl_save: begin database checkpoint\n"; BDB::db_env_txn_checkpoint $DB_ENV; - warn "emergency_perl_save: end database checkpoint\n"; + info "emergency_perl_save: end database checkpoint\n"; - warn "emergency_perl_save: begin write uuid\n"; + info "emergency_perl_save: begin write uuid\n"; write_uuid_sync 1; - warn "emergency_perl_save: end write uuid\n"; - }; + info "emergency_perl_save: end write uuid\n"; + + cf::write_runtime_sync; # external watchdog should not bark + + trace "emergency_perl_save: syncing database to disk"; + BDB::db_env_txn_checkpoint $DB_ENV; + + info "emergency_perl_save: starting sync\n"; + IO::AIO::aio_sync sub { + info "emergency_perl_save: finished sync\n"; + }; - warn "emergency_perl_save: starting sync()\n"; - IO::AIO::aio_sync sub { - warn "emergency_perl_save: finished sync()\n"; + cf::write_runtime_sync; # external watchdog should not bark + + trace "emergency_perl_save: flushing outstanding aio requests"; + while (IO::AIO::nreqs || BDB::nreqs) { + Coro::EV::timer_once 0.01; # let the sync_job do it's thing + } + + cf::write_runtime_sync; # external watchdog should not bark }; - warn "emergency_perl_save: leave\n"; + info "emergency_perl_save: leave\n"; } sub post_cleanup { my ($make_core) = @_; - warn Carp::longmess "post_cleanup backtrace" + IO::AIO::flush; + + error Carp::longmess "post_cleanup backtrace" if $make_core; my $fh = pidfile; @@ -3819,7 +3904,7 @@ sub do_reload_perl() { # can/must only be called in main if (in_main) { - warn "can only reload from main coroutine"; + error "can only reload from main coroutine"; return; } @@ -3828,56 +3913,44 @@ my $t1 = AE::time; while ($RELOAD) { - warn "reloading..."; + info "reloading..."; - warn "entering sync_job"; + trace "entering sync_job"; cf::sync_job { - cf::write_runtime_sync; # external watchdog should not bark cf::emergency_save; - cf::write_runtime_sync; # external watchdog should not bark - - warn "syncing database to disk"; - BDB::db_env_txn_checkpoint $DB_ENV; - # if anything goes wrong in here, we should simply crash as we already saved - - warn "flushing outstanding aio requests"; - while (IO::AIO::nreqs || BDB::nreqs) { - Coro::EV::timer_once 0.01; # let the sync_job do it's thing - } - - warn "cancelling all extension coros"; + trace "cancelling all extension coros"; $_->cancel for values %EXT_CORO; %EXT_CORO = (); - warn "removing commands"; + trace "removing commands"; %COMMAND = (); - warn "removing ext/exti commands"; + trace "removing ext/exti commands"; %EXTCMD = (); %EXTICMD = (); - warn "unloading/nuking all extensions"; + trace "unloading/nuking all extensions"; for my $pkg (@EXTS) { - warn "... unloading $pkg"; + trace "... unloading $pkg"; if (my $cb = $pkg->can ("unload")) { eval { $cb->($pkg); 1 - } or warn "$pkg unloaded, but with errors: $@"; + } or error "$pkg unloaded, but with errors: $@"; } - warn "... clearing $pkg"; + trace "... clearing $pkg"; clear_package $pkg; } - warn "unloading all perl modules loaded from $LIBDIR"; + trace "unloading all perl modules loaded from $LIBDIR"; while (my ($k, $v) = each %INC) { next unless $v =~ /^\Q$LIBDIR\E\/.*\.pm$/; - warn "... unloading $k"; + trace "... unloading $k"; delete $INC{$k}; $k =~ s/\.pm$//; @@ -3890,11 +3963,11 @@ clear_package $k; } - warn "getting rid of safe::, as good as possible"; + trace "getting rid of safe::, as good as possible"; clear_package "safe::$_" for qw(cf::attachable cf::object cf::object::player cf::client cf::player cf::map cf::party cf::region); - warn "unloading cf.pm \"a bit\""; + trace "unloading cf.pm \"a bit\""; delete $INC{"cf.pm"}; delete $INC{"cf/$_.pm"} for @EXTRA_MODULES; @@ -3902,44 +3975,44 @@ # and global variables created in xs #clear_package __PACKAGE__; - warn "unload completed, starting to reload now"; + info "unload completed, starting to reload now"; - warn "reloading cf.pm"; + trace "reloading cf.pm"; require cf; cf::_connect_to_perl_1; - warn "loading config and database again"; + trace "loading config and database again"; cf::reload_config; - warn "loading extensions"; + trace "loading extensions"; cf::load_extensions; if ($REATTACH_ON_RELOAD) { - warn "reattaching attachments to objects/players"; + trace "reattaching attachments to objects/players"; _global_reattach; # objects, sockets - warn "reattaching attachments to maps"; + trace "reattaching attachments to maps"; reattach $_ for values %MAP; - warn "reattaching attachments to players"; + trace "reattaching attachments to players"; reattach $_ for values %PLAYER; } - warn "running post_init jobs"; + trace "running post_init jobs"; (pop @POST_INIT)->(1) while @POST_INIT; - warn "leaving sync_job"; + trace "leaving sync_job"; 1 } or do { - warn $@; + error $@; cf::cleanup "error while reloading, exiting."; }; - warn "reloaded"; + info "reloaded"; --$RELOAD; } $t1 = AE::time - $t1; - warn "reload completed in ${t1}s\n"; + info "reload completed in ${t1}s\n"; }; our $RELOAD_WATCHER; # used only during reload @@ -3970,7 +4043,7 @@ } }; -unshift @INC, $LIBDIR; +############################################################################# my $bug_warning = 0; @@ -4009,7 +4082,7 @@ Coro::async_pool { $Coro::current->{desc} = "runtime saver"; write_runtime_sync - or warn "ERROR: unable to write runtime file: $!"; + or error "ERROR: unable to write runtime file: $!"; }; } @@ -4027,7 +4100,7 @@ if ($NEXT_TICK) { my $jitter = $TICK_START - $NEXT_TICK; $JITTER = $JITTER * 0.75 + $jitter * 0.25; - warn "jitter $JITTER\n";#d# + debug "jitter $JITTER\n";#d# } } }