From 7dc7eb31e63a4f399407c538515de932352a6a10 Mon Sep 17 00:00:00 2001 From: "David E. Wheeler" Date: Fri, 16 Feb 2024 17:25:10 -0500 Subject: [PATCH] Add proper logger to consumer and handlers Create (hidden) package PGXN::API::Consumer::Log and set it up with log level as the first argument to its `log` method, and suppress logging according to verbosity. Teach Consumer to use it, then also teach the Mastodon and Twitter handlers. Add tests to ensure it all works, including time mocking in the Mastodon and Twitter tests. Note that the handlers no longer throw an error on failure, but simply log it. The Consumer still wraps the handlers in `try`/`catch` in order to log any unexpected errors and continue runnnig. This will mean additional log information from the handlers, in particular, which did no logging previously. Will be helpful when something happens to the consumer and we can see in the log what the last release to be processed was. While at it, remove unnecessary uses of Carp. --- Changes | 3 + lib/PGXN/Manager/Consumer.pm | 134 +++++++++++++++----------- lib/PGXN/Manager/Consumer/mastodon.pm | 18 +++- lib/PGXN/Manager/Consumer/twitter.pm | 20 +++- lib/PGXN/Manager/Maint.pm | 3 +- t/consumer.t | 67 +++++++------ t/maint.t | 2 +- t/mastodon.t | 88 ++++++++++++++--- t/twitter.t | 82 ++++++++++++++-- 9 files changed, 300 insertions(+), 117 deletions(-) diff --git a/Changes b/Changes index 7fe28db..b30445c 100644 --- a/Changes +++ b/Changes @@ -5,6 +5,9 @@ Revision history for Perl extension PGXN::Manager output. - Configured handlers for INT, TERM, and QUIT signals to log flagging for shutdown in the next loop. + - Fixed invalid license example in the META spec. + - Added a logger to the Consumer and the Mastodon and Twitter handlers, + so that they now log debug and info messages about what's being sent. 0.31.1 2023-10-07T21:40:53Z - Restored the writing of the pgxn_consumer PID file, accidentally diff --git a/lib/PGXN/Manager/Consumer.pm b/lib/PGXN/Manager/Consumer.pm index 89719a3..017ce51 100644 --- a/lib/PGXN/Manager/Consumer.pm +++ b/lib/PGXN/Manager/Consumer.pm @@ -8,32 +8,34 @@ use Moose; use JSON::XS; use Try::Tiny; use Encode qw(encode_utf8); -use Carp; use Time::HiRes qw(sleep); use PGXN::Manager; use Proc::Daemon; use IO::File; -use POSIX (); -use Fcntl qw(:flock); use Cwd; use namespace::autoclean; our $VERSION = v0.31.2; use constant CHANNELS => qw(release new_user new_mirror); -has verbose => (is => 'ro', isa => 'Int', required => 1, default => 0); -has interval => (is => 'ro', isa => 'Num', required => 1, default => 5); +has verbose => (is => 'ro', isa => 'Int', required => 1, default => 0); +has interval => (is => 'ro', isa => 'Num', required => 1, default => 5); has continue => (is => 'rw', isa => 'Bool', required => 1, default => 1); has pid_file => (is => 'rw', isa => 'Str'); -has log_fh => (is => 'ro', isa => 'IO::Handle', required => 1, default => sub { - _log_fh() -}); +has logger => ( + is => 'ro', + isa => 'PGXN::Manager::Consumer::Log', + required => 1, + lazy => 1, + default => sub { PGXN::Manager::Consumer::Log->new(verbose => $_[0]->verbose) }, +); + has conn => (is => 'ro', isa => 'DBIx::Connector', lazy => 1, default => sub { # Use our own connetion instead of $pgxn->conn in order to add the callback. my $self = shift; my $cb = $self->verbose ? sub { $_[0]->do("LISTEN pgxn_$_") for CHANNELS; - $self->log("INFO: Listening on ", join ', ', map { s/^pgxn_//r } @{ + $self->log(INFO => 'Listening on ', join ', ', map { s/^pgxn_//r } @{ $_[0]->selectcol_arrayref('SELECT * FROM pg_listening_channels()') }); return; @@ -48,15 +50,6 @@ has conn => (is => 'ro', isa => 'DBIx::Connector', lazy => 1, default => sub }); }); -sub _log_fh { - my $fn = shift; - my $fh = $fn ? IO::File->new($fn, '>>:utf8') - : IO::Handle->new_from_fd(fileno STDOUT, 'w'); - binmode $fh, ":utf8"; - $fh->autoflush(1); - $fh; -} - sub go { my $class = shift; my $cfg = $class->_config; @@ -69,16 +62,19 @@ sub go { ); if (my $pid = $daemon->Init) { my $pid_file = $cfg->{'pid-file'} || 'STDOUT'; - _log( - _log_fh($cfg->{'log-file'}), - "INFO: Forked PID $pid written to $pid_file", - ); + PGXN::Manager::Consumer::Log->new( + verbose => $cfg->{verbose}, + file => $cfg->{'log-file'}, + )->log(INFO => "Forked PID $pid written to $pid_file"); return 0; } } - # In the child process. Set up log file handle and go. - $cfg->{log_fh} = _log_fh delete $cfg->{'log-file'}; + # In the child process. Set up logger and go. + $cfg->{logger} = PGXN::Manager::Consumer::Log->new( + verbose => $cfg->{verbose}, + file => delete $cfg->{'log-file'}, + ); $cfg->{pid_file} = delete $cfg->{'pid-file'} if exists $cfg->{'pid-file'}; my $cmd = $class->new( $cfg ); $SIG{$_} = $cmd->_signal_handler($_) for qw(TERM INT QUIT); @@ -88,7 +84,7 @@ sub go { sub _signal_handler { my ($self, $sig) = @_; return sub { - $self->log("INFO: $sig signal caught; flagging shutdown for next loop"); + $self->log(INFO => "$sig signal caught; flagging shutdown for next loop"); $self->continue(0); }; } @@ -102,10 +98,10 @@ sub DEMOLISH { sub run { my $self = shift; - $self->log(sprintf "INFO: Starting %s %s", __PACKAGE__, __PACKAGE__->VERSION); + $self->log(INFO => sprintf "Starting %s %s", __PACKAGE__, __PACKAGE__->VERSION); my $pgxn = PGXN::Manager->instance; my $cfg = $pgxn->config->{consumers} || do { - $self->log("WARN: No consumers configured; messages will be dropped"); + $self->log(WARN => 'No consumers configured; messages will be dropped'); undef }; @@ -118,7 +114,7 @@ sub run { sleep($self->interval); } - $self->log("INFO: Shutting down"); + $self->log(INFO => 'Shutting down'); return 0; } @@ -129,17 +125,17 @@ sub load_consumers { my $type = delete $cfg->{type} or die "No type specified for event consumer\n"; my $pkg = __PACKAGE__ . "::$type"; - $self->log("INFO: Loading $pkg") if $self->verbose > 1; + $self->log(DEBUG => "Loading $pkg"); eval "use $pkg"; die "Error loading $pkg: $@\n" if $@; my $events = delete $cfg->{events}; my $consumer = $pkg->new( - verbose => $self->verbose, - config => $cfg, + logger => $self->logger, + config => $cfg, ); for my $e (@{ $events }) { - $self->log("INFO: Configuring $pkg for $e") if $self->verbose > 1; + $self->log(DEBUG => "Configuring $pkg for $e"); push @{ $consumers{$e} ||= [] } => $consumer; } } @@ -154,20 +150,18 @@ sub consume { # Notify payload treated as UTF-8 text, so already decoded from UTF-8 bytes. my $json = JSON::XS->new->utf8(0); my $dbh = shift; - $self->log("INFO: Consuming") if $self->verbose > 2; + $self->log(DEBUG => 'Consuming'); while (my $notify = $dbh->pg_notifies) { my ($name, $pid, $msg) = @{ $notify }; - $self->log("INFO: Received “$name” event from PID $pid") - if $self->verbose; + $self->log(INFO => "Received “$name” event from PID $pid"); unless ($name =~ s/^pgxn_//) { - $self->log("WARN: Unknown channel “$name”; skipping"); + $self->log(WARN => "Unknown channel “$name”; skipping"); next; } my $handlers = $consumers_for->{$name} || do { - $self->log( - "INFO: No handlers configured for ", - "pgxn_$name channel; skipping", - )if $self->verbose; + $self->log(INFO => + "No handlers configured for pgxn_$name channel; skipping", + ); next; }; @@ -175,36 +169,26 @@ sub consume { my $meta = try { $json->decode($msg); } catch { - $self->log("ERORR: Cannot decode JSON: $_"); + $self->log(ERORR => "Cannot decode JSON: $_"); undef; }; next unless $meta; # Run all the handlers. for my $h (@{ $handlers }) { - $self->log("INFO: Sending to ", $h->name, " handler") - if $self->verbose; + $self->log(INFO => 'Sending to ', $h->name, " handler"); try { $h->handle($name, $meta) } - catch { $self->log("ERROR: $_") }; + catch { $self->log(ERROR => $_) }; } } }); } catch { - $self->log("ERROR: $_"); + $self->log(ERROR => $_); }; return 1; } -sub log { - _log(shift->log_fh, @_); -} - -sub _log { - my $fh = shift; - flock $fh, LOCK_EX; - say {$fh} POSIX::strftime('%Y-%m-%dT%H:%M:%SZ - ', gmtime), join '', @_; - flock $fh, LOCK_UN; -} +sub log { shift->logger->log(@_) } sub _config { my $self = shift; @@ -262,6 +246,46 @@ sub _pod2usage { ); } +package + PGXN::Manager::Consumer::Log; + +use 5.10.0; +use strict; +use warnings; +use utf8; +use Moose; +use Fcntl qw(:flock); + +has verbose => (is => 'ro', isa => 'Int', required => 1, default => 0); +has log_fh => (is => 'ro', isa => 'FileHandle', required => 1, default => sub { + _log_fh() +}); + +around BUILDARGS => sub { + my ($orig, $class, %args) = @_; + my $fn = delete $args{file} or return $class->$orig(%args); + return $class->$orig(%args, log_fh => _log_fh($fn)); +}; + +sub log { + my ($self, $level) = (shift, shift); + return if $level eq 'INFO' && $self->verbose < 1; + return if $level eq 'DEBUG' && $self->verbose < 2; + my $fh = $self->log_fh; + flock $fh, LOCK_EX; + say {$fh} POSIX::strftime("%Y-%m-%dT%H:%M:%SZ - $level: ", gmtime), join '', @_; + flock $fh, LOCK_UN; +} + +sub _log_fh { + my $fn = shift; + my $fh = $fn ? IO::File->new($fn, '>>:utf8') + : IO::Handle->new_from_fd(fileno STDOUT, 'w'); + binmode $fh, ":utf8"; + $fh->autoflush(1); + $fh; +} + 1; __END__ diff --git a/lib/PGXN/Manager/Consumer/mastodon.pm b/lib/PGXN/Manager/Consumer/mastodon.pm index f8401c2..cf040cc 100644 --- a/lib/PGXN/Manager/Consumer/mastodon.pm +++ b/lib/PGXN/Manager/Consumer/mastodon.pm @@ -19,6 +19,7 @@ our $VERSION = v0.31.2; has server => (is => 'ro', required => 1, isa => 'Str'); has ua => (is => 'ro', required => 1, isa => 'LWP::UserAgent'); has delay => (is => 'ro', required => 0, isa => 'Int', default => 0); +has logger => (is => 'ro', required => 1, isa => 'PGXN::Manager::Consumer::Log'); around BUILDARGS => sub { my ($orig, $class, %args) = @_; @@ -50,7 +51,13 @@ my %EMOJI = ( sub handle { my ($self, $type, $meta) = @_; - return unless $type eq 'release'; + if ($type ne 'release') { + $self->logger->log(DEBUG => "Mastodon skiping $type notification"); + return; + }; + + my $release = lc "$meta->{name}-$meta->{version}"; + $self->logger->log(INFO => "Posting $release to Mastodon"); my $link = PGXN::Manager->instance->config->{release_permalink}; my $url = URI::Template->new($link)->process({ @@ -59,7 +66,7 @@ sub handle { }); my %emo = map { $_ => $EMOJI{$_}[rand @{ $EMOJI{$_} }] } keys %EMOJI; - $self->toot(join("\n\n", + $self->toot($release, join("\n\n", "$emo{send} Released: $meta->{name} $meta->{version}", "$emo{info} $meta->{abstract}", "$emo{user} By $meta->{user}", @@ -68,7 +75,7 @@ sub handle { } sub toot { - my ($self, $body) = @_; + my ($self, $release, $body) = @_; my $res = $self->ua->post( $self->server . '/api/v1/statuses', @@ -78,7 +85,10 @@ sub toot { }, ); return 1 if $res->is_success; - die "Error posting to Mastodon: " . $res->decoded_content . "\n"; + + $self->logger->log(ERROR => + "Error posting $release to Mastodon: " . $res->decoded_content + ); } sub scheduled_at { diff --git a/lib/PGXN/Manager/Consumer/twitter.pm b/lib/PGXN/Manager/Consumer/twitter.pm index f1595c2..0fa275d 100644 --- a/lib/PGXN/Manager/Consumer/twitter.pm +++ b/lib/PGXN/Manager/Consumer/twitter.pm @@ -16,8 +16,8 @@ our $VERSION = v0.31.2; subtype MaybeTwitterAPI => as maybe_type class_type 'Net::Twitter::Lite'; -has verbose => (is => 'ro', required => 1, isa => 'Int', default => 0); has client => (is => 'ro', required => 1, isa => 'Net::Twitter::Lite'); +has logger => (is => 'ro', required => 1, isa => 'PGXN::Manager::Consumer::Log'); around BUILDARGS => sub { my ($orig, $class, %args) = @_; @@ -45,11 +45,16 @@ around BUILDARGS => sub { }; sub handle { - my ($self, $channel, $meta) = @_; - return unless $channel eq 'release'; + my ($self, $type, $meta) = @_; + if ($type ne 'release') { + $self->logger->log(DEBUG => "Twitter skiping $type notification"); + return; + }; + my $client = $self->client or return; my $pgxn = PGXN::Manager->instance; + $self->logger->log(DEBUG => "Fetching Twitter username for $meta->{user}"); my $nick = $pgxn->conn->run(sub { shift->selectcol_arrayref( 'SELECT twitter FROM users WHERE nickname = ?', @@ -59,11 +64,18 @@ sub handle { $nick = $nick ? "\@$nick" : $meta->{user}; + my $release = lc "$meta->{name}-$meta->{version}"; + $self->logger->log(INFO => "Posting $release to Twitter"); + my $url = URI::Template->new($pgxn->config->{release_permalink})->process({ dist => lc $meta->{name}, version => lc $meta->{version}, }); - $client->update( "$meta->{name} $meta->{version} released by $nick: $url" ); + try { + $client->update( "$meta->{name} $meta->{version} released by $nick: $url" ); + } catch { + $self->logger->log(ERROR => "Error posting $release to Twitter: $_"); + }; } 1; diff --git a/lib/PGXN/Manager/Maint.pm b/lib/PGXN/Manager/Maint.pm index 863e2bb..090288a 100644 --- a/lib/PGXN/Manager/Maint.pm +++ b/lib/PGXN/Manager/Maint.pm @@ -8,7 +8,6 @@ use File::Spec; use File::Path qw(make_path remove_tree); use File::Basename qw(dirname basename); use Encode qw(encode_utf8); -use Carp; use namespace::autoclean; our $VERSION = v0.31.2; @@ -50,7 +49,7 @@ sub run { my ($self, $command) = (shift, shift); $command =~ s/-/_/g; my $meth = $self->can($command) - or croak qq{PGXN Maint: "$command" is not a command}; + or die qq{PGXN Maint: "$command" is not a command}; require PGXN::Manager; $self->$meth(@_); } diff --git a/t/consumer.t b/t/consumer.t index 2a39f41..2cbadbd 100644 --- a/t/consumer.t +++ b/t/consumer.t @@ -8,7 +8,7 @@ use Encode qw(encode_utf8); use JSON::XS; use File::Temp (); -use Test::More tests => 121; +use Test::More tests => 122; # use Test::More 'no_plan'; use Test::Output; use Test::MockModule; @@ -47,6 +47,24 @@ can_ok $CLASS => qw( _config ); +############################################################################## +# Mock log destination. +my $log_output = ''; +my $log_fh = IO::File->new(\$log_output, 'w'); +$log_fh->binmode(':utf8'); +sub output { + my $ret = $log_output; + $log_fh->seek(0, 0); + $log_output = ''; + return $ret // ''; +} + +# Set up a logger. +my $logger = PGXN::Manager::Consumer::Log->new( + verbose => 1, + log_fh => $log_fh, +); + ############################################################################## # Instantiate and test config. DEFAULTS: { @@ -55,12 +73,12 @@ DEFAULTS: { 'Default options should be correct'; local $ENV{PLACK_ENV} = 'test'; - my $consumer = new_ok $CLASS; + my $consumer = new_ok $CLASS, [ logger => $logger ]; is $consumer->verbose, 0, 'Default verbosity is 0'; is $consumer->interval, 5, 'Default interval is 5'; is $consumer->continue, 1, 'Default continue is 1'; is $consumer->pid_file, undef, 'Default pid file is undef'; - ok $consumer->log_fh, 'Should have log file handle'; + is $consumer->logger, $logger, 'Should have logger'; } # Grab the timestamp that will appear in logs. @@ -73,30 +91,22 @@ is POSIX::strftime('%Y-%m-%dT%H:%M:%SZ', gmtime), $logtime, # Test and then mock log STDOUT: { my $consumer = $CLASS->new(); - stdout_is { ok $consumer->log("Hello there 😀"), 'log' } - encode_utf8 "$logtime - Hello there 😀\n", + stdout_is { ok $consumer->log(WARN => "Hello there 😀"), 'log' } + encode_utf8 "$logtime - WARN: Hello there 😀\n", "log should encode text"; } LOGFILE: { my $tmp = File::Temp->new; - my $consumer = $CLASS->new(log_fh => PGXN::Manager::Consumer::_log_fh($tmp->filename)); - ok $consumer->log("Hello there 😀"), 'log to file'; - file_contents_eq $tmp->filename, "$logtime - Hello there 😀\n", + my $consumer = $CLASS->new( + logger => PGXN::Manager::Consumer::Log->new(file => $tmp->filename), + ); + ok $consumer->log(WARN => "Hello there 😀"), 'log to file'; + file_contents_eq $tmp->filename, "$logtime - WARN: Hello there 😀\n", { encoding => 'UTF-8' }, 'Should have written message to log file'; } -# Mock log file. -my $log_output = ''; -my $log_fh = IO::File->new(\$log_output, 'w'); -$log_fh->binmode(':utf8'); -sub output { - my $ret = $log_output; - $log_fh->seek(0, 0); - $log_output = ''; - return $ret // ''; -} my $chans = join(', ', PGXN::Manager::Consumer::CHANNELS); ############################################################################## @@ -105,7 +115,7 @@ PID: { my $tmp = File::Temp->new(UNLINK => 0); my $fn = $tmp->filename; do { - my $consumer = $CLASS->new(log_fh => $log_fh, pid_file => $fn); + my $consumer = $CLASS->new(logger => $logger, pid_file => $fn); file_exists_ok $fn, 'PID file should exist'; }; file_not_exists_ok $fn, 'PID file be gone'; @@ -160,7 +170,7 @@ CONFIG: { # Test load_consumers. LOAD: { my $conf = load_config; - my $consumer = $CLASS->new(log_fh => $log_fh); + my $consumer = $CLASS->new(logger => $logger); my $handlers = $consumer->load_consumers($conf->{consumers}); is_deeply [keys %{ $handlers }], ["release"], 'Should have one key'; is @{ $handlers->{release} }, 2, 'Should have two release handlers'; @@ -246,7 +256,7 @@ DAEMONIZE: { file_exists_ok $pid_file, 'PID file should exist'; $mock_proc->mock(Init => 42); $ran = 0; - @ARGV = (qw(-D --pid-file), $pid_file); + @ARGV = (qw(-VD --pid-file), $pid_file); stdout_is { is $CLASS->go, 0, 'Should get zero from go' } "$logtime - INFO: Forked PID 42 written to $pid_file\n", 'Should have emitted PID'; @@ -263,7 +273,7 @@ DAEMONIZE: { # Try with no PID file (shoud log it was written to STDOUT). $ran = 0; - @ARGV = qw(-D); + @ARGV = qw(-VD); stdout_is { is $CLASS->go, 0, 'Should get zero from go' } "$logtime - INFO: Forked PID 42 written to STDOUT\n", 'Should have emitted PID'; @@ -320,11 +330,12 @@ RUN: { # Run it. local @ARGV = qw(--env test --interval 0); my $cfg = $CLASS->_config; - $cfg->{log_fh} = $log_fh; + $cfg->{logger} = $logger; my $consumer = $CLASS->new($cfg); is $consumer->interval, 0, 'Should have interval 0'; is $consumer->continue, 1, 'Should have default continue 1'; is $consumer->verbose, 0, 'Should have default verbose 0'; + is $consumer->logger, $logger, 'Should have set logger'; is $consumer->run, 0, 'Run consumer'; is_deeply output(), join("\n", @@ -366,7 +377,7 @@ RUN: { $db_mocker->mock(selectcol_arrayref => sub { [PGXN::Manager::Consumer::CHANNELS] }); - $consumer = $CLASS->new(interval => 0, verbose => 1, log_fh => $log_fh); + $consumer = $CLASS->new(interval => 0, verbose => 1, logger => $logger); is $consumer->verbose, 1, 'Should have verbosity 1'; is $consumer->run, 0, 'Run consumer'; is_deeply output(), join("", map { "$logtime - $_\n" } @@ -393,7 +404,7 @@ CONSUME: { # Wrap the constuctor to listen for our test handlers. my @channels = keys %{ $handlers }; my $new_consumer = sub { - my $c = $CLASS->new(@_, log_fh => $log_fh); + my $c = $CLASS->new(@_, logger => $logger); $c->conn->run(sub { $_[0]->do("LISTEN pgxn_$_") for @channels }); $c; }; @@ -401,7 +412,7 @@ CONSUME: { # Set up a notification. my $json1 = '{"name": "Julie ❤️"}'; my $payload1 = {name => 'Julie ❤️'}; - my $consumer = $new_consumer->(verbose => 2, log_fh => $log_fh); + my $consumer = $new_consumer->(verbose => 2, logger => $logger); $consumer->conn->run(sub { $_->do("SELECT pg_notify(?, ?)", undef, 'pgxn_release', $json1); }); @@ -444,7 +455,8 @@ CONSUME: { # Go quiet, send a drop. my $json3 = '{"drop": "out"}'; my $payload3 = {drop => 'out'}; - $consumer = $new_consumer->(verbose => 0, log_fh => $log_fh); + $logger->{verbose} = 0; + $consumer = $new_consumer->(verbose => 0, logger => $logger); $consumer->conn->run(sub { $_->do("SELECT pg_notify(?, ?)", undef, 'pgxn_drop', $json3); }); @@ -480,6 +492,7 @@ CONSUME: { # Remove a handlers. delete $handlers->{drop}; + $logger->{verbose} = 1; $consumer = $new_consumer->(verbose => 1); $consumer->conn->run(sub { $_->do("SELECT pg_notify(?, ?)", undef, 'pgxn_drop', $json3); diff --git a/t/maint.t b/t/maint.t index 25f2c36..046959b 100644 --- a/t/maint.t +++ b/t/maint.t @@ -111,7 +111,7 @@ RUN: { ok $maint->run('update-stats', 'now'), 'Run update-stats'; is_deeply $params, ['now'], 'Should have called update_stats'; - # Make sure we croak for an unknown command. + # Make sure we die for an unknown command. local $@; eval { $maint->run('nonexistent') }; like $@, qr{PGXN Maint: "nonexistent" is not a command}, diff --git a/t/mastodon.t b/t/mastodon.t index de6c1fa..a407da0 100644 --- a/t/mastodon.t +++ b/t/mastodon.t @@ -5,7 +5,7 @@ use strict; use warnings; use utf8; -use Test::More tests => 27; +use Test::More tests => 37; # use Test::More 'no_plan'; use JSON::XS; use Test::Exception; @@ -13,8 +13,25 @@ use Test::MockModule; use lib 't/lib'; use TxnTest; +############################################################################## +# Mock time. +my (@gmtime, $time); +BEGIN { + $time = CORE::time(); + @gmtime = CORE::gmtime($time); + *CORE::GLOBAL::time = sub() { return $time }; + *CORE::GLOBAL::gmtime = sub (;$) { return @gmtime } +} + +sub mktime { + POSIX::strftime '%Y-%m-%dT%H:%M:%SZ', gmtime time + shift; +} + +############################################################################## +# Load the class. BEGIN { use_ok 'PGXN::Manager' or die; + use_ok 'PGXN::Manager::Consumer' or die; use_ok 'PGXN::Manager::Consumer::mastodon' or die; } @@ -28,16 +45,33 @@ can_ok 'PGXN::Manager::Consumer::mastodon', qw( scheduled_at ); -# Mock time. -our $time = CORE::time(); -*CORE::GLOBAL::time = sub() { return $time }; -sub mktime { - POSIX::strftime '%Y-%m-%dT%H:%M:%SZ', gmtime time + shift; -} - # Silence "used only once" warning by using CORE::GLOBAL::time. is CORE::GLOBAL::time(), time, 'Time should be mocked'; +# Grab the timestamp that will appear in logs. +my $logtime = POSIX::strftime '%Y-%m-%dT%H:%M:%SZ', gmtime $time; +is time, $time, 'Should have mocked time'; +is POSIX::strftime('%Y-%m-%dT%H:%M:%SZ', gmtime), $logtime, + 'Should have mocked gmtime'; + +############################################################################## +# Mock log destination. +my $log_output = ''; +my $log_fh = IO::File->new(\$log_output, 'w'); +$log_fh->binmode(':utf8'); +sub output { + my $ret = $log_output; + $log_fh->seek(0, 0); + $log_output = ''; + return $ret // ''; +} + +# Set up a logger. +my $logger = PGXN::Manager::Consumer::Log->new( + verbose => 1, + log_fh => $log_fh, +); + open my $fh, '<:raw', 'conf/test.json' or die "Cannot open conf/test.json: $!\n"; my $conf = do { local $/; @@ -51,7 +85,10 @@ while (@{ $conf->{consumers} } && $cfg->{type} ne 'mastodon') { } die "No mastodon config found in conf/test.json\n" unless $cfg; delete $cfg->{events}; -my $mastodon = PGXN::Manager::Consumer::mastodon->new(config => $cfg); +my $mastodon = PGXN::Manager::Consumer::mastodon->new( + config => $cfg, + logger => $logger, +); is $mastodon->server, $cfg->{server}, 'The server should be loaded'; is $mastodon->delay, $cfg->{delay}, "The delay should be set"; @@ -72,7 +109,11 @@ is_deeply $ua->default_headers, { # Test scheduled_at. for my $i (200, 300, 400, 500, 600, 1000) { - my $m = PGXN::Manager::Consumer::mastodon->new(config => $cfg, delay => $i); + my $m = PGXN::Manager::Consumer::mastodon->new( + config => $cfg, + logger => $logger, + delay => $i, + ); is_deeply [$m->scheduled_at], [scheduled_at => mktime($i)], "Should get scheduled_at delay $i"; } @@ -88,6 +129,7 @@ CONFIG: { } # Test tooting. +is output(), '', 'Should have no output yet'; my $ua_mock = Test::MockModule->new('LWP::UserAgent'); my $toot = 'Hey man'; $ua_mock->mock(post => sub { @@ -102,14 +144,24 @@ $ua_mock->mock(post => sub { return HTTP::Response->new(200); }); -ok $mastodon->toot($toot), 'Send a toot!'; +ok $mastodon->toot("release_name", $toot), 'Send a toot!'; +is output(), '', 'Should still have no output'; + +# Test toot with error. +$ua_mock->mock(post => sub { + return HTTP::Response->new(404, 'not found', undef, 'oops'); +}); +ok !$mastodon->toot("release_name", $toot), 'Toot send should fail'; +is output(), + "$logtime - ERROR: Error posting release_name to Mastodon: oops\n", + 'Should have error log message'; # Test handler. my $meta = { - user => 'theory', - name => 'pgTAP', + user => 'theory', + name => 'pgTAP', abstract => "Unit testing for PostgreSQL", - version => '1.3.5', + version => '1.3.5', }; my $pgxn = PGXN::Manager->instance; my $url = URI::Template->new($pgxn->config->{release_permalink})->process({ @@ -120,15 +172,19 @@ my $url = URI::Template->new($pgxn->config->{release_permalink})->process({ # Start with unkown event. is $mastodon->handle(nonesuch => $meta), undef, 'Should send no message for unknown event'; +is output(), '', 'Should have no output'; # Send release event. SEND: { my $mock_masto = Test::MockModule->new('PGXN::Manager::Consumer::mastodon'); - my $msg; - $mock_masto->mock(toot => sub { $msg = $_[1] }); + my ($rel, $msg); + $mock_masto->mock(toot => sub { ($rel, $msg) = ($_[1], $_[2]) }); ok $mastodon->handle(release => $meta), 'Should send release message'; + is $rel, lc("$meta->{name}-$meta->{version}"), 'Release should have been passed'; like $msg, qr/\S+ \QReleased: $meta->{name} $meta->{version}\E\n\n\S+ \Q$meta->{abstract}\E\n\n\S+ \QBy $meta->{user}\E\n\n$url/ms, 'Should have sent the formatted message'; + is output(), "$logtime - INFO: Posting pgtap-1.3.5 to Mastodon\n", + 'Should have info log message'; } # Have Mastodon throw an exception. diff --git a/t/twitter.t b/t/twitter.t index 847b13a..baa51fa 100644 --- a/t/twitter.t +++ b/t/twitter.t @@ -5,7 +5,7 @@ use strict; use warnings; use utf8; -use Test::More tests => 20; +use Test::More tests => 31; # use Test::More 'no_plan'; use JSON::XS; use Test::Exception; @@ -13,8 +13,21 @@ use Test::MockModule; use lib 't/lib'; use TxnTest; +############################################################################## +# Mock time. +my (@gmtime, $time); +BEGIN { + $time = CORE::time(); + @gmtime = CORE::gmtime($time); + *CORE::GLOBAL::time = sub() { return $time }; + *CORE::GLOBAL::gmtime = sub (;$) { return @gmtime } +} + +############################################################################## +# Load the class. BEGIN { use_ok 'PGXN::Manager' or die; + use_ok 'PGXN::Manager::Consumer' or die; use_ok 'PGXN::Manager::Consumer::twitter' or die; } @@ -24,6 +37,33 @@ can_ok 'PGXN::Manager::Consumer::twitter', qw( handle ); +# Silence "used only once" warning by using CORE::GLOBAL::time. +is CORE::GLOBAL::time(), time, 'Time should be mocked'; + +# Grab the timestamp that will appear in logs. +my $logtime = POSIX::strftime '%Y-%m-%dT%H:%M:%SZ', gmtime $time; +is time, $time, 'Should have mocked time'; +is POSIX::strftime('%Y-%m-%dT%H:%M:%SZ', gmtime), $logtime, + 'Should have mocked gmtime'; + +############################################################################## +# Mock log destination. +my $log_output = ''; +my $log_fh = IO::File->new(\$log_output, 'w'); +$log_fh->binmode(':utf8'); +sub output { + my $ret = $log_output; + $log_fh->seek(0, 0); + $log_output = ''; + return $ret // ''; +} + +# Set up a logger. +my $logger = PGXN::Manager::Consumer::Log->new( + verbose => 1, + log_fh => $log_fh, +); + open my $fh, '<:raw', 'conf/test.json' or die "Cannot open conf/test.json: $!\n"; my $conf = do { local $/; @@ -37,20 +77,24 @@ while (@{ $conf->{consumers} } && $cfg->{type} ne 'twitter') { } die "No twitter config found in conf/test.json\n" unless $cfg; delete $cfg->{events}; -my $twitter = PGXN::Manager::Consumer::twitter->new( config => $cfg ); +my $twitter = PGXN::Manager::Consumer::twitter->new( + config => $cfg, + logger => $logger, +); is $twitter->name, 'twitter', 'Should have name method'; # Should get an exception for missing API config. CONFIG: { for my $key (qw(consumer_key consumer_secret access_token access_token_secret)) { my $val = delete $cfg->{$key}; - throws_ok { PGXN::Manager::Consumer::twitter->new(config => $cfg) } - qr/Missing Twitter API $key/, "Should have no clent when no $key"; + throws_ok { PGXN::Manager::Consumer::twitter->new( + config => $cfg, + logger => $logger, + ) } qr/Missing Twitter API $key/, "Should have no clent when no $key"; $cfg->{$key} = $val; } } - # Test tweeting. my $twitter_mock = Test::MockModule->new('Net::Twitter::Lite::WithAPIv1_1'); # Force the class to load. @@ -86,18 +130,40 @@ $twitter_mock->mock(update => sub { return $nt; }); -# Start with unkown event. +# Start with unknown event. +is output(), '', 'Should have no output so far'; +is $twitter->handle(nonesuch => $meta), undef, + 'Should send no message for unknown event'; +is output(), '', 'Should have no log for unknown event'; + +# Try it with debug verbosity. +$logger->{verbose} = 2; is $twitter->handle(nonesuch => $meta), undef, 'Should send no message for unknown event'; +is output(), + "$logtime - DEBUG: Twitter skiping nonesuch notification\n", + 'Should have unknown event log message'; # Send release event. ok $twitter->handle(release => $meta), 'Should send release message'; +is output(), + "$logtime - DEBUG: Fetching Twitter username for $meta->{user}\n" . + "$logtime - INFO: Posting \L$meta->{name}-$meta->{version}\E to Twitter\n", + 'Should have DEBUG username lookup and INFO message for posting'; # Look up the Twitter username in the database. +$logger->{verbose} = 1; $meta->{user} = TxnTest->user; $tweet = "$meta->{name} $meta->{version} released by \@notHere: $url"; ok $twitter->handle(release => $meta), 'Should send message with Twitter nick'; +is output(), + "$logtime - INFO: Posting \L$meta->{name}-$meta->{version}\E to Twitter\n", + 'Should have INFO message for posting'; # Have Twitter throw an exception. -$twitter_mock->mock(update => sub { die 'WTF!' }); -throws_ok {$twitter->client->update('hi!') } qr/WTF!/, 'Fail to send a tweet'; +$twitter_mock->mock(update => sub { die "WTF!\n" }); +ok !$twitter->handle(release => $meta), 'Should not send message'; +is output(), + "$logtime - INFO: Posting \L$meta->{name}-$meta->{version}\E to Twitter\n" . + "$logtime - ERROR: Error posting \L$meta->{name}-$meta->{version}\E to Twitter: WTF!\n\n", + 'Should have INFO message and ERROR message';