Can't capture stderr after upgrading to glog v1.1.0

[Stuart McLean]

Hi there,

With glog v1.0.0 I used to be able to easily capture stderr logs for in integration tests. With the upgraded version this no longer works. I tried various suggestions that I found online and even this library: https://github.com/zenizh/go-capturer but nothing seems to work.

Is there a way to configure glog to write to a specific file that I can read from after?

Thanks for your time,
Stuart McLean

[Ian Lance Taylor]

[ + jba ]

> --
> You received this message because you are subscribed to the Google Groups "golang-nuts" group.
> To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts...@googlegroups.com.
> To view this discussion on the web visit https://groups.google.com/d/msgid/golang-nuts/20CCAFD5-6400-4C68-BFBC-AB41F7FA7853%40mac.com.

[Chressie Himpel]

On Thu, Mar 16, 2023 at 5:27 PM Ian Lance Taylor <ia...@golang.org> wrote:
>
> [ + jba ]
>
> On Thu, Mar 16, 2023 at 8:56 AM 'Stuart McLean' via golang-nuts
> <golan...@googlegroups.com> wrote:
> >
> > Hi there,
> >
> > With glog v1.0.0 I used to be able to easily capture stderr logs for in integration tests. With the upgraded version this no longer works. I tried various suggestions that I found online and even this library: https://github.com/zenizh/go-capturer but nothing seems to work.

By default glog only prints ERROR level and above to stderr. Did you
try to pass the -alsologtostderr flag to your program (or set it via
flag.Set("alsologtostderr", "true"))?

> >
> > Is there a way to configure glog to write to a specific file that I can read from after?
> >
> > Thanks for your time,
> > Stuart McLean
> >
> > --
> > You received this message because you are subscribed to the Google Groups "golang-nuts" group.
> > To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts...@googlegroups.com.
> > To view this discussion on the web visit https://groups.google.com/d/msgid/golang-nuts/20CCAFD5-6400-4C68-BFBC-AB41F7FA7853%40mac.com.
>
> --
> You received this message because you are subscribed to the Google Groups "golang-nuts" group.
> To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts...@googlegroups.com.

> To view this discussion on the web visit https://groups.google.com/d/msgid/golang-nuts/CAOyqgcVMFDOoqW82mwkab-4KYFPZ6H3So6xoKuudRhK%3D49niQw%40mail.gmail.com.

[Stuart McLean]

Thanks so much for the quick answers. I did try setting the `alsologtostderr` flag (and adding `flag.Parse()` after) but it doesn’t make a difference. I’m trying to capture error logs anyway. I’ve tried stepping through the glog code and it looks like messages are being written to a buffer for stderr, but it doesn’t seem like that buffer is being flushed in time for my tests to pick it up. I even tried adding some sleep calls to see if that made a difference, but that didn’t help either. I don’t see any way to flush the stderr buffer manually. It looks like we can only manually flush the file buffer.

[Stuart McLean]

I’m not sure where to add os.Stderr.Sync() so I tried in a few spots, including directly after my call to glog.Error

Here’s playground version: https://go.dev/play/p/sHEATjMRhtN

It outputs:
E1110 23:00:00.000000 11 prog.go:26] foo bar
captured:

When I run the same code with glog v1.0.0 it outputs what we want:
captured: E0317 12:27:12.440817 11892 main.go:26] foo bar

> On 17. Mar 2023, at 11:03, Chressie Himpel <chre...@google.com> wrote:

>
> On Fri, Mar 17, 2023 at 10:16 AM Stuart McLean <stuart...@mac.com> wrote:
>>
>> Thanks so much for the quick answers. I did try setting the `alsologtostderr` flag (and adding `flag.Parse()` after) but it doesn’t make a difference. I’m trying to capture error logs anyway. I’ve tried stepping through the glog code and it looks like messages are being written to a buffer for stderr, but it doesn’t seem like that buffer is being flushed in time for my tests to pick it up. I even tried adding some sleep calls to see if that made a difference, but that didn’t help either. I don’t see any way to flush the stderr buffer manually. It looks like we can only manually flush the file buffer.
>

> Sure thing. On what OS do you run your tests? The underlying writer of
> sinks.stderr is initialized with os.Stderr[0] and writes to it should
> typically be unbuffered (on Linux at least). From that perspective
> there's nothing really to flush here.
>
> I suspect that either the sinks.stderr reports Enabled()==false[1]
> which would cause the internal/logsink package to skip emitting to it,
> or os.Stderr is buffered on your system. In the first case double
> check which flags you're passing and that they're effective (and not
> overwritten somewhere else), and in the second case you can try to
> call os.Stderr.Sync() to force writing to it. If you have a reproducer
> i could also take a look.
>
> [0]: https://github.com/golang/glog/blob/master/glog_file.go#L156
> [1]: https://github.com/golang/glog/blob/master/glog_file.go#L178

[Chressie Himpel]

On Fri, Mar 17, 2023 at 10:16 AM Stuart McLean <stuart...@mac.com> wrote:
>

> Thanks so much for the quick answers. I did try setting the `alsologtostderr` flag (and adding `flag.Parse()` after) but it doesn’t make a difference. I’m trying to capture error logs anyway. I’ve tried stepping through the glog code and it looks like messages are being written to a buffer for stderr, but it doesn’t seem like that buffer is being flushed in time for my tests to pick it up. I even tried adding some sleep calls to see if that made a difference, but that didn’t help either. I don’t see any way to flush the stderr buffer manually. It looks like we can only manually flush the file buffer.

Sure thing. On what OS do you run your tests? The underlying writer of
sinks.stderr is initialized with os.Stderr[0] and writes to it should
typically be unbuffered (on Linux at least). From that perspective
there's nothing really to flush here.

I suspect that either the sinks.stderr reports Enabled()==false[1]
which would cause the internal/logsink package to skip emitting to it,
or os.Stderr is buffered on your system. In the first case double
check which flags you're passing and that they're effective (and not
overwritten somewhere else), and in the second case you can try to
call os.Stderr.Sync() to force writing to it. If you have a reproducer
i could also take a look.

[0]: https://github.com/golang/glog/blob/master/glog_file.go#L156
[1]: https://github.com/golang/glog/blob/master/glog_file.go#L178

>

[Chressie Himpel]

On Fri, Mar 17, 2023 at 1:50 PM Stuart McLean <stuart...@mac.com> wrote:
>
> I’m not sure where to add os.Stderr.Sync() so I tried in a few spots, including directly after my call to glog.Error
>
> Here’s playground version: https://go.dev/play/p/sHEATjMRhtN
>
> It outputs:
> E1110 23:00:00.000000 11 prog.go:26] foo bar
> captured:
>
> When I run the same code with glog v1.0.0 it outputs what we want:
> captured: E0317 12:27:12.440817 11892 main.go:26] foo bar

Ah thanks. I see the issue. You're setting os.Stderr to a different
writer to capture the output, but since v1.1.0 we're storing os.Stderr
at init time in sinks.stderr and hence subsequent logger calls still
go to stderr instead of the pipe. I think that's worth a fix. I'll
prepare a fix.

[Chressie Himpel]

On Fri, Mar 17, 2023 at 3:08 PM Chressie Himpel <chre...@google.com> wrote:
>
> On Fri, Mar 17, 2023 at 1:50 PM Stuart McLean <stuart...@mac.com> wrote:
> >
> > I’m not sure where to add os.Stderr.Sync() so I tried in a few spots, including directly after my call to glog.Error
> >
> > Here’s playground version: https://go.dev/play/p/sHEATjMRhtN
> >
> > It outputs:
> > E1110 23:00:00.000000 11 prog.go:26] foo bar
> > captured:
> >
> > When I run the same code with glog v1.0.0 it outputs what we want:
> > captured: E0317 12:27:12.440817 11892 main.go:26] foo bar
>
> Ah thanks. I see the issue. You're setting os.Stderr to a different
> writer to capture the output, but since v1.1.0 we're storing os.Stderr
> at init time in sinks.stderr and hence subsequent logger calls still
> go to stderr instead of the pipe. I think that's worth a fix. I'll
> prepare a fix.

I just tagged a new release
https://github.com/golang/glog/releases/tag/v1.1.1 that should fix
this issue.

[Stuart McLean]

Thanks so much Chressie! I can confirm that all my existing tests pass with glog v1.1.1.