runtime: program re-enables SIGHUP

[gopherbot]

by alexandre.normand@opower.com:

I'm hoping someone can shed some light on this one but I, unfortunately, can't provide
that much details nor an example that could be tried outside of our organisation. 

Here's the story:
I have a small go program that uses encoding/json and net/http to submit jobs to one of
our apps. After submission, the program polls that same app (using http/json) until it
sees the jobs going to completion (or failure). This has been implemented using channels
and go routines (one go routine sees that a job gets submitted and waits for its
completion). It gets fancier with the notion of checkpoints that have been implemented
by simply waiting for some jobs to complete before starting other jobs (again, via new
go routines). At any given time, there are never more than 10 go routines running in
parallel (which sleep for 1 minute between each http call). 

The program runs fine when executed on my MacBook Pro but since it can run for 10+ hours
before completion, I've been trying to run that on one of the many Linux servers using
{{{nohup}}}. It looks like when starting the process with nohup and logging out of the
system, the program never runs to completion. The stdout/stderr is redirected to a file
and it looks like the process vanishes after a few hours at most (sometimes after less
than 1 hour). I can't really tell what the exit code is either since not having an open
session when that happens, I'm not seeing it. 

To add to the mystery, when keeping a session open on that host running the program and
tailing the log file, it seems to _then_ be able to run to completion. I can't rule out
something killing that process but it I'm very confident that it's not the case since
I'm running other scripts on those machines which have been running for days without
interruption.  

What steps will reproduce the problem?
1. Use a go program that's a mix of http/json/log statements/sleeps/go routines.
2. Start it using {{{nohup program > output.log 2>&1 &}}}
3. Wait for it...and it's gone before it completes. 

What is the expected output?
The program should either go to completion or print a panic.

What do you see instead?
Nothing, the process just ends abruptly with no trace. This looks like I'm running
through some os.Exit() call somewhere in the go packages I'm using but it's not clear
what that would be and why. 

Which compiler are you using (5g, 6g, 8g, gccgo)?
6g

Which operating system are you using?
Linux  2.6.32-220.7.1.el6.x86_64

Which version are you using?  (run 'go version')
go1.0.3

Please provide any additional information below.
I can provide my code (one main go source and an additional package) but I would have to
remove urls and obfuscate some of it which would render it pretty much usable except for
visual inspection.

[rsc]

Comment 1:

It is possible that the signal initialization in Go programs
re-enables SIGHUP, so that running it under nohup does not protect it
from your logging out. That would be the first thing I would try. If
that's the case then a simple Go program that just does
for {
    time.Sleep(1*time.Minute)
}
would demonstrate the same mysterious disappearances.

[gopherbot]

Comment 2 by alexandre.normand@opower.com:

I'm running that test right now (I just added a log statement too, just so I could tell
when it stopped). I'll post later with the results. 
For reference, here's the actual code:
package main
import (
        "log"
        "time"
)
func main() {
        for {
                time.Sleep(1 * time.Minute)
                log.Print("Waiting for 1 minute again")
        }
}

[gopherbot]

Comment 3 by alexandre.normand@opower.com:

The first test mentioned above is still running fine with nohup and I added one more
that just adds a go routine to the mix:
package main
import (
        "log"
        "time"
)
func main() {
        callback := make(chan int)
        go sleepAndPrint(callback)
        <-callback
}
func sleepAndPrint(communication chan int) {
        for i := 0; i < 10000; i++ {
                log.Printf("waiting for 1 minute with count = %d\n", i)
                time.Sleep(1 * time.Minute)
        }
        communication <- 1
}
Both are still running after logging out and back again. I'm going to leave them running
both to see if anything can come out of this.

[gopherbot]

Comment 4 by alexandre.normand@opower.com:

The two versions of the test mentioned above are still running fine with nohup. I wonder
if this could be that something in the packages my original app is using is doing a
Exit() call without logging anything first.
For reference, here are my imports:
import (
        "bytes"
        "encoding/json"
        "fmt"
        "io/ioutil"
        "log"
        "os"
        "net/http"
        "strings"
        "time"
)

[rsc]

Comment 5:

I just checked via grep: nothing in the standard library calls os.Exit
without printing a message. The only calls outside tests are in flag
and log.

[rsc]

Comment 6:

Is it possible that the program is using too much memory and being killed by the Linux
kernel? Look in the output of dmesg.

Labels changed: added priority-later, go1.1maybe, removed priority-triage, go1.1.

Status changed to WaitingForReply.

[gopherbot]

Comment 7 by alexandre.normand@opower.com:

There's no indication in dmesg that the program got killed by the kernel. I did see that
the box I'm running in on right now has only 375 MB of free physical ram but I was
initially running it on another box that has more than 1.7 GB of free physical RAM and I
had made the switch to try and see if there was something wrong with the first one. 
Also, wouldn't the memory usage be the same regardless of whether I'm logged in/tailing
the output log than if I'm logged out?
The current status is that this is still occurring as per my initial description. If I
kill my remote ssh session to the box running it, it eventually disappears but if I'm
logged in and tailing the log, it stays there up to the normal program termination.

[alberts]

Comment 8:

10 writes to stdout/stderr getting EPIPE and then the program exits?

[gopherbot]

Comment 9 by alexandre.normand@opower.com:

If that was a case of 10 writes getting IPIPE causing the exit, wouldn't the simple test
cases from the earlier comments have shown the same problem? 
I'd like to provide some example that reproduces the issue. Since I can't use the
program I'm currently working on, I might put together an example that just does http
get/posts using a similar pattern. It might take a while before I can have something to
reproduce it just because of the nature of the problem (if I'm logged in and waiting for
it to vanish, it's just going to remain alive).

[alberts]

Comment 10:

ssh and it dying when you log out smelled a bit like epipecheck.
You could perhaps see if you can strace the program until it exits?
strace -v -s1000 -tt -ostrace.log -p <pid>

[alberts]

Comment 11:

also -f

[gopherbot]

Comment 12 by alexandre.normand@opower.com:

I stripped much of what was specific to my organisation from my program and replaced it
with calls to the flickr REST api (it's the first thing that came to my mind). I'm
currently running this one the same way I was running my original program and I'm doing
the strace to get that info if that turns out to effectively reproduce the issue. This
test is still not using all features that I was using in the original but that's
probably a good first attempt.
For reference (and so I don't lose it), I started the test with:
nohup ./pollrunner > run-`date +%F-%H-%M`.log 2>&1 &
and the strace with the following:
nohup strace -v -f -s1000 -tt -otrace.log -p 6834 &

[gopherbot]

Comment 13 by alexandre.normand@opower.com:

I have the strace output for the current run of the original program which did exit
about 15 minutes after I logged out of the box on which it was running (my first attempt
at reproducing it using a simple version that can be tested by anyone hasn't been
successful).
It's the first time I use strace myself so I'm not sure what to expect/look at. That
said, one of the last lines printed is: 
1551  11:15:11.836543 --- SIGHUP (Hangup) @ 0 (0) ---
Does that mean it got a hang-up signal and exited even if it was executed with nohup?

Attachments:

1. trace_obfuscated.log (9466838 bytes)

[rsc]

Comment 14:

Yes, that's what it means. That's progress at least.

[rsc]

Comment 15:

It looks like the log does not include process startup. Can you grep
for SIGHUP in the full log and see if any sigaction calls turn up?