Skip to content

Don't use nosync for the standard log package. #657

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
Closed
wants to merge 1 commit into from
Closed

Don't use nosync for the standard log package. #657

wants to merge 1 commit into from

Conversation

flimzy
Copy link
Member

@flimzy flimzy commented Jul 8, 2017

TL;DR; The standard library 'log' package uses locks around blocking IO calls which seems like an inappropriate use of the 'nosync' package. Not using 'nosync' for this package fixed a bug observed in one of my applications.

I've just encountered the following error in one of my apps:

main.js:1412 Uncaught Error: nosync: mutex is already locked
    at $callDeferred (main.js:1412)
    at $panic (main.js:1451)
    at Object.$packages.github.com/gopherjs/gopherjs/nosync.Mutex.ptr.Lock (main.js:6755)
    at Object.$packages.log.Logger.ptr.Output (main.js:67759)
    at Object.Printf (main.js:67957)
    at localize (main.js:167345)
    at $goroutine (main.js:1471)
    at $runScheduled (main.js:1511)

My attempts to build a minimal reproduction case have thus far failed, but here's my speculation:

I'm not entirely sure what 'nosync's purpose is, but I guess it's a lighter-weight version of 'sync', to be used when there's no possibility of synchronization being an actual issue, due to JS's single-threaded nature.

The failure:

at Object.$packages.log.Logger.ptr.Output (main.js:67759)

Corresponds to this transpiled code:

67757    file = "";
67758    line = 0;
67759    l.mu.Lock();
67760    $deferred.push([$methodVal(l.mu, "Unlock"), []]);
67761    if (!(((l.flag & 24) === 0))) {
67762        l.mu.Unlock();
67763        ok = false;

Which in turn corresponds to this code in the standard library:

147    var file string
148    var line int
149    l.mu.Lock()
150    defer l.mu.Unlock()
151    if l.flag&(Lshortfile|Llongfile) != 0 {
152        // release lock while getting caller info - it's expensive.
153        l.mu.Unlock()
154        var ok bool
...
168    _, err := l.out.Write(l.buf)
169    return err

If I understand GopherJS's scheduling adequately (also reinforced by my reading of the transpiled log function), it's quite possible for the defer l.mu.Unlock() execution to be significantly delayed in from the rest of the function, since there's a Write() call (on line 168), which triggers a blocking IO checkpoint, allowing other goroutines to be scheduled, leading to a possible race condition.

@flimzy
Copy link
Member Author

flimzy commented Jul 8, 2017

This has the unfortunate side effect of producing a deadlock, where previously it was panicing. So an alternative is probably in order; I'm not sure what that might be.

@flimzy flimzy mentioned this pull request Jul 9, 2017
Open
@dmitshur
Copy link
Member

dmitshur commented Jul 9, 2017 •
edited
Loading

@neelance Do you remember the motivation for using nosync package in log?

Is there an explanation of what nosync is for? I'm not closely familiar with it. My current guess is that it's meant to be used in places where real locking isn't required, because GopherJS runs in a GOMAXPROCS=1 type environment, so certain race conditions are not possible. But that's a guess.

I think it makes sense to remove it from log, if it doesn't belong there (i.e., log requires real sync package). Then we can try to fix the deadlock and restore support for log, if it's viable, since log is supposed to be a supported package as listed in the compatibility table. If we can't get it to work, we'll have no choice but to mark it as unsupported.

@dmitshur
Copy link
Member

dmitshur commented Feb 16, 2018 •
edited
Loading

I ran into this during work on Go 1.10 support as well, in package encoding/gob. It currently uses nosync, and a new test in 1.10 is failing. If it's made to use real sync package, then the test passes.

I've reached out to Richard and asked to learn more about why nosync exists. It's hard to do something about this before understanding the motivation for using nosync in the first place.

@dmitshur dmitshur changed the title Don't use 'nosync' for the standard 'log' package Reconsider use of nosync for the standard log package. Feb 16, 2018
@dmitshur dmitshur changed the title Reconsider use of nosync for the standard log package. Don't use nosync for the standard log package. Feb 16, 2018
@dmitshur dmitshur mentioned this pull request Feb 16, 2018
Open
@flimzy
Copy link
Member Author

flimzy commented Dec 28, 2021

As this is inconclusive, we're closing for now to be considered as part of #754.

@flimzy flimzy closed this Dec 28, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers
No reviews
Assignees
No one assigned
Labels
NeedsDecision NeedsInvestigation
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.
2 participants
@flimzy @dmitshur