Long-running script messes up output after a while

[maleadt]

I have a pretty long-running script (several hours), which is responsible for invoking executables (including julia itself again), and capturing its output. After some hours though, the parent process manages to mess up its output, crashing in some core part library:

Executing ../matlab/demo.m...                                                               
Executing ../c++/build/release/demo...                                                      
Executing ../cuda/build/release/demo...                                                     
Executing ../openmp/build/release/demo...                                                   
Executing ../julia/demo.jl...                                                               
ERROR:                                                                                      
 in abstract_call_gf at inference.jl:603                                                    
 in abstract_call at inference.jl:699                                                       
 in abstract_eval_call at inference.jl:787                                                  
 in abstract_eval at inference.jl:812                                                       
 in abstract_interpret at inference.jl:956                                                  
 in typeinf at inference.jl:1257                                                            
 in abstract_call_gf at inference.jl:621                                                    
 in abstract_call at inference.jl:699                                                       
 in abstract_eval_call at inference.jl:787                                                  
 in abstract_eval at inference.jl:812                                                       
 in abstract_eval_arg at inference.jl:746                                                   
 in typeinf at inference.jl:1322                                                            
 in abstract_call_gf at inference.jl:621                                                    
 in abstract_call at inference.jl:699                                                       
 in abstract_eval_call at inference.jl:787                                                  
 in abstract_eval at inference.jl:812                                                       
 in abstract_interpret at inference.jl:956                                                  
 in typeinf at inference.jl:1257                                                            
 in abstract_call_gf at inference.jl:621                                                    
 in abstract_call at inference.jl:699                                                       
 in abstract_eval_call at inference.jl:787                                                  
 in abstract_eval at inference.jl:812                                                       
 in abstract_interpret at inference.jl:956                                                  
 in typeinf at inference.jl:1257                                                            
 in abstract_call_gf at inference.jl:621                                                    
 in abstract_call at inference.jl:699                                                       
 in abstract_eval_call at inference.jl:787                                                  
 in abstract_eval at inference.jl:812                                                       
 in abstract_interpret at inference.jl:956                                                  
 in typeinf at inference.jl:1257                                                            
 in abstract_call_gf at inference.jl:621                                                    
 in abstract_call at inference.jl:699                                                       
 in abstract_eval_call at inference.jl:787                                                  
 in abstract_eval at inference.jl:812                                                       
 in abstract_eval_arg at inference.jl:746                                                   
 in typeinf at inference.jl:1322                                                            
 in abstract_call_gf at inference.jl:621                                                    
 in abstract_call at inference.jl:699                                                       
 in abstract_eval_call at inference.jl:787                                                  
 in abstract_eval at inference.jl:812                                                       
 in abstract_eval_arg at inference.jl:746                                                   
 in abstract_eval_call at inference.jl:755                                                  
 in abstract_eval at inference.jl:812                                                       
 in abstract_eval_arg at inference.jl:746                                                   
 in abstract_eval_call at inference.jl:755                                                  
 in abstract_eval at inference.jl:812                                                       
 in abstract_eval_arg at inference.jl:746                                                   
 in abstract_eval_call at inference.jl:755                                                  
 in abstract_eval at inference.jl:812                                                       
 in abstract_eval_arg at inference.jl:746                                                   
 in typeinf at inference.jl:1322                                                            
 in abstract_call_gf at inference.jl:621                                                    
 in abstract_call at inference.jl:699                                                       
 in abstract_eval_call at inference.jl:787                                                  
 in abstract_eval at inference.jl:812                                                       
 in abstract_interpret at inference.jl:956                                                  
 in typeinf at inference.jl:1257                                                            
 in abstract_call_gf at inference.jl:621                                                    
 in abstract_call at inference.jl:699                                                       
 in abstract_eval_call at inference.jl:787                                                  
 in abstract_eval at inference.jl:812                                                       
 in abstract_eval_arg at inference.jl:746                                                   
 in abstract_eval_call at inference.jl:755                                                  
 in abstract_eval at inference.jl:812                                                       
 in abstract_interpret at inference.jl:956                                                  
 in typeinf at inference.jl:1257                                                            
 in abstract_call_gf at inference.jl:621                                                    
 in abstract_call at inference.jl:699                                                       
 in abstract_eval_call at inference.jl:787                                                  
 in abstract_eval at inference.jl:812                                                       
 in abstract_eval_arg at inference.jl:746                                                   
 in typeinf at inference.jl:1322                                                            
 in typeinf_ext at inference.jl:1090                                                        
 in include at boot.jl:238                                                                  
 in include_from_node1 at loading.jl:114                                                    
 in process_options at client.jl:303                                                        
 in _start at client.jl:389fatal: error thrown and no exception handler available.
Base.TypeError(func=:subtype, context="", expected=Type{T}, got=(Base.IOBuffer, <?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?::<?:: [snip]

This list of <?::'s goes on for quite a while (hundreds of repetitions), and then it stops. Afterwards, new print entries seem work again: although I don't see the output on my screen, they do end up in the log file STDOUT is redirected to (see invocation command below). This might bee a tee issue though.

I'm using julia 0.2 from the Debian repositories, and the script is launched as following:

./script.jl |& tee -a script.log

[pao]

I'm using julia 0.2 from the Debian repositories

Is this from the juliareleases PPA? (Or just paste in the output from versioninfo()).

Oh wait, Debian. Did Debian get the final 0.2 release in their repositories?

[maleadt]

Yes, Debian unstable ships 0.2 release:

julia> versioninfo()
Julia Version 0.2.0
Commit 05c6461* (2013-11-16 23:44 UTC)
Platform Info:
  System: Linux (x86_64-linux-gnu)
  WORD_SIZE: 64
  BLAS: libblas.so.3
  LAPACK: liblapack.so.3
  LIBM: libopenlibm

$ dpkg -s julia
Package: julia
Status: install ok installed
Priority: extra
Section: science
Installed-Size: 11543
Maintainer: Debian Julia Team <[email protected]>
Architecture: amd64
Version: 0.2.0+dfsg-5

[pao]

cc @JeffBezanson

@maleadt, is it possible to reproduce this if you update to the latest from git? Understand that this may be difficult depending on how long "long-running" means.

[JeffBezanson]

This is probably the same/similar intermittent slippery memory bug that still plagues the tests from time to time.

[ViralBShah]

The debugger would be nice to have here. If the crash dumps you into a debugger, there ids some chance of figuring out what if going on.

[Keno]

It might be enough to run this with MEMDEBUG and AddressSanitizer enabled (If you are willing to do that, I'll post instructions).

[maleadt]

I just tried running with a master checkout, but couldn't replicate the the issue... However, the build differs quite a lot from the Debian-shipped one I use (system libraries, etc). If I can't replicate it I'll have a look at compiling master with the same build options from the Debian package.

EDIT: scratch that, I couldn't replicate it with the Debian build. I'll post here when I have more information.

[vtjnash]

@JeffBezanson could this be related: 4cb1c98 (should be cherry-picked for 0.2)

[JeffBezanson]

I doubt it, since this crash was during a script.

[vtjnash]

Actually, this seems more related: #5069

prior to that fix, is_stable_expr presumably might consider a type tuple to be a stable expressions, and thus might not create a gc root for it, if it somehow was incorrectly convinced that it would be emitted as a stable expression. could that be possible?

[Keno]

That wasn't in the 0.2 release though.

[vtjnash]

@JeffBezanson where is the gc root for such a thing if it could be JIT into the code?

no, but it seems to be exactly the same error, and some tuples were not given gc roots even before your changes.

[maleadt]

Reproduced it finally on 47a1ae5 (master as of this morning).

@loladiro How exactly do I build this debug version, I'm guessing CC=clang CFLAGS="-DMEMDEBUG -fsanitize=address"?

[maleadt]

I tried with the following Make.user:

CC=clang
CXX=clang++

CFLAGS=-g -fsanitize=address -fno-omit-frame-pointer -DMEMDEBUG
CXXFLAGS=$(CFLAGS)
LDFLAGS=-fsanitize=address

... but it fails to link julia-readline:

/usr/bin/ld: usr/bin/julia-readline: local symbol `__asan_init_v3' in /usr/bin/../lib/clang/3.3/lib/linux/libclang_rt.asan-x86_64.a(asan_rtl.o) is referenced by DSO
/usr/bin/ld: final link failed: Bad value
clang: error: linker command failed with exit code 1 (use -v to see invocation)

Any hints?

[rened]

In case somebody can use a reproducible test case to trigger this, please ping me. (I'll have to add you to a private repo)

Also, you can find a valgrind output of that test case here: https://gist.github.com/rened/8472496

[rened]

59bf492 seems to have fixed this! I can no longer reproduce this error.

[StefanKarpinski]

Oh, that's excellent news!

[JeffBezanson]

That's a relief. It's definitely possible that that commit fixes this.

[StefanKarpinski]

If you do notice it happening again, please do reopen (or open a new issue).

[mschauer]

FYI: I got a strange Travis Error which displays the same <?::<?::<?::<?::<?::...
https://travis-ci.org/JuliaLang/julia/jobs/17617554

[maleadt]

I haven't been able to reproduce this bug for a while -- it has always been quite difficult -- so I can't confirm whether 59bf492 has changed anything...

[JeffBezanson]

Something like this still happens on travis intermittently.

[joehuchette]

FYI I got a similar error on 92a3323:
https://gist.github.com/joehuchette/8640589
I haven't been able to reproduce it, unfortunately.

[amitmurthy]

This may or may not be relevant:

On a fork of master with considerable changes in multi.jl, I am seeing my feature specific tests fail / seg fault - each run is failing differently. julia runtests.jl all is fine though. Since I have not touched the C codebase, not executing any low-level stuff, it seems to be a memory corruption elsewhere (and I am at a loss to figure out what exactly is causing it). Posting the valgrind output here in case it is related.

==7284== Syscall param msync(start) points to unaddressable byte(s)
==7284==    at 0x606D3BD: ??? (syscall-template.S:81)
==7284==    by 0x5A72652: msync_validate (in /home/amitm/Work/julia/julia/usr/lib/libjulia.so)
==7284==    by 0x5A7277F: validate_mem (in /home/amitm/Work/julia/julia/usr/lib/libjulia.so)
==7284==    by 0x5A728BC: access_mem (in /home/amitm/Work/julia/julia/usr/lib/libjulia.so)
==7284==    by 0x5A70588: dwarf_get (in /home/amitm/Work/julia/julia/usr/lib/libjulia.so)
==7284==    by 0x5A70842: _ULx86_64_access_reg (in /home/amitm/Work/julia/julia/usr/lib/libjulia.so)
==7284==    by 0x5A7010E: _ULx86_64_get_reg (in /home/amitm/Work/julia/julia/usr/lib/libjulia.so)
==7284==    by 0x5A752F1: apply_reg_state (in /home/amitm/Work/julia/julia/usr/lib/libjulia.so)
==7284==    by 0x5A759E0: _ULx86_64_dwarf_find_save_locs (in /home/amitm/Work/julia/julia/usr/lib/libjulia.so)
==7284==    by 0x5A71D8F: _ULx86_64_dwarf_step (in /home/amitm/Work/julia/julia/usr/lib/libjulia.so)
==7284==    by 0x5A709F9: _ULx86_64_step (in /home/amitm/Work/julia/julia/usr/lib/libjulia.so)
==7284==    by 0x5174447: rec_backtrace_ctx (in /home/amitm/Work/julia/julia/usr/lib/libjulia.so)
==7284==  Address 0x7feffd000 is not stack'd, malloc'd or (recently) free'd

[vtjnash]

Record backtrace generates these false positives from the way it is designed. IF you trap calls to jl_throw, you might get more info I the error

[dcjones]

It looks like the Gadfly tests fail sometimes with the same error, but only occasionally and seemingly at random. Scroll to the bottom here: https://travis-ci.org/dcjones/Gadfly.jl/jobs/19685997

[IainNZ]

PackageEval hit this last night when testing Optim, julia v0.2.1+2

It does something similar to the original issue openers script - long running, shells out to run new copies of Julia on test scripts.

[JeffBezanson]

Believed fixed by #6085.

[timholy]

Woot!

It seems a bit unlikely that this will be the last time we have a gc-unrooted bug. I really don't know the guts of the gc at all, but might it be possible to introduce a mode (through an optional compiler flag, perhaps set to true by make debug) that causes the GC to thoroughly invalidate the object, thereby triggering an immediate error?