Why can't some of my modules do log output to a file?

[LittleJack]

This is yet more puzzlement about a large and almost-completely-undocumented Perl application I'm working on.

There's a cron-like process which runs constantly, polling for jobs. When it gets a job, it instantiates one of various modules (depending on the job type) and runs some processes.

My current puzzle is this. In some of the modules, to figure out what's happening, I can put pretty crude logging along the lines of:

use Data::Dumper;
open(LOG,'>>','/some/log/file.log') or die "can't log";
print LOG 'Some object: ' . Dumper($some_object);
close(LOG);

I'm aware this is far from ideal but it should work, right?

But in some of the modules, when I add this, I get no output at all. It doesn't die, it doesn't fail, the operation concludes. In others it works and I get output. There's definitely nothing wrong with the logfile, its location and permissions etc. all allow it to be written to.

The modules which apparently can't do output are mostly ones to do with an API which fetches JSON from AWS.

Where can I start looking to figure out why this would be?

[kcott]

G'day LittleJack,

Put these lines near the start of your code:

use strict;
use warnings;
use autodie;

Use a lexical filehandle in a limited scope. The package variable LOG may be used elsewhere and could be interfering in some way. A subroutine would be a good choice; something like this untested code:

sub _log_object {
    my ($obj) = @_;
    open my $log_fh, '>>', '/some/log/file.log';
    print $log_fh 'Some object: ', Dumper($obj);
    return;
}

This answers the "Where can I start looking ...?" question. It might fix your problem; if not, you may at least get a bit more feedback on problems. Report back with more information and further advice, not based on guesswork, may be forthcoming (follow the guidelines in "How do I post a question effectively?").

[haukex]

it should work, right?

In addition to the comments by the others, I would suggest using flock, turning on Data::Dumper's Useqq option, and adding more error checking.

use warnings;
use strict;
use Fcntl qw/:flock/;
use Data::Dumper;

sub write_log {
    my ($file, $obj) = @_;
    open my $fh, '>>', $file or die "open $file: $!";
    flock($fh, LOCK_EX) or die "flock $file: $!";
    print {$fh} Data::Dumper->new([$obj])->Useqq(1)->Dump
        or die "print $file: $!";
    close $fh or die "close $file: $!";
}

write_log("/tmp/log.txt", {hello=>"world"});

If that didn't work or die, personally I would assume the code really wasn't being run, or perhaps that some other process was messing with the logfile. (Note it's been a while since I've used flock on Windows, but I assume you're on *NIX based on your filename.)

There's definitely nothing wrong with the logfile

Well now that you've said that, I have to ask ;-) Are you sure? SELinux? Are all the processes spawned by the script running as the same user?

[LanX]

I'm wondering if it's efficient to open close the file each time, the handle could be kept in the closure.

And flock would cover problems with concurrent use.

Although ... IIRC there are also OS dependencies to consider.

[haukex]

I'm wondering if it's efficient to open close the file each time, the handle could be kept in the closure. And flock would cover problems with concurrent use.

Opening and closing each time is indeed less efficient. Keeping the file open would require a lock-seek-write-flush-unlock sequence, which introduces more complexity, and given that the OP is debugging "weird" behavior, I thought it best to give the simpler, albeit less efficient, method that uses only simple filesystem operations. I perhaps should have clairifed that my suggestion is one for debugging and not for high-performance logging. (Also, I seem to remember that keeping the file open does not work on Windows when multiple processes are accessing it, though I'm not yet sure whether that's the case here.)

[eyepopslikeamosquito]

I would suggest using flock, turning on Data::Dumper's Useqq option, and adding more error checking

Excellent advice! Whenever I use logging for troubleshooting, as a matter of reflex, I tend to further turn on autoflush on the logfile.

BTW, in addition to providing portable locking across Unix and Windows, flock enriches Perl poems, as demonstrated by pjf in this immortal line:

join flock($other,@chickens) if split /from others/;

from his classic Perl poem my @chickens.

[LittleJack]

Hi, thanks for your reply. I don't really understand what the Useqq option does for me in this instance? Are you assuming there might be problematic characters in the output causing this unusual behaviour?

[haukex]

I don't really understand what the Useqq option does for me in this instance?

Without Useqq, the module will output some characters literally, which may cause garbled output and could in theory even cause it to appear that certain log messages weren't being output, e.g. when showing a logfile with cat or tail.

$ perl -MData::Dumper -e 'print Dumper("Hello,\rWorld!")'
World!';'Hello,
$ perl -MData::Dumper -e '$Data::Dumper::Useqq=1; print Dumper("Hello,
+\rWorld!")'
$VAR1 = "Hello,\rWorld!";

Are you assuming there might be problematic characters in the output causing this unusual behaviour?

Actually, I think those characters are the least likely explanation, but I wanted to have all bases covered. I'd be much more curious about the results of my other suggestions?

[AnomalousMonk]

... what the Useqq option does for me ... Are you assuming there might be problematic characters in the output ...

Taking the liberty of responding for haukex: I don't think problematic characters are necessarily assumed to be present, but if they're there, Useqq will help you see them. See also Data::Dump.

[AnomalousMonk]

In addition to kcott's reference here to advice about asking effective questions, consider constructing a Short, Self-Contained, Correct Example. Just the process of constructing an SSCCE may give you enough insight to solve the problem, and if it doesn't, at least you'll have an example to clearly demonstrate the problem to others. But try to keep it short.

[LittleJack]

I thought I had provided a short, self-contained, correct example?

I can't really provide a seventeen-layered SSCCE of Foo.pm calling Bar.pm calling Baz.pm calling Bax.pm etc. etc. where it's turtles all the way down.

[AnomalousMonk]

I thought I had provided a short, self-contained, correct example?

The only code that I can see that you've provided so far in the thread is the code in the OP. This code is not self-contained and executable (under strict-ures and warnings). If it were made so, I very much doubt it would manifest any error/warning messages at all. Please see the SSCCE discussion.

I can't really provide a seventeen-layered SSCCE ...

But apparently the monks are expected to do so.

[haukex]

I thought I had provided a short, self-contained, correct example?

An SSCCE should be runnable on its own, and it must reproduce the problem. Especially the latter is a very important debugging step: removing as much code as possible while still keeping the problem present will help you focus on the source of the problem.