Add debug logger and assert

buffer.go

@@ -1,8 +1,9 @@
 package prompt
 
 import (
-	"log"
 	"strings"
+
+	"github.com/c-bata/go-prompt/internal/debug"
 )
 
 // Buffer emulates the console buffer.
@@ -63,9 +64,7 @@ func (b *Buffer) InsertText(v string, overwrite bool, moveCursor bool) {
 // (When doing this, make sure that the cursor_position is valid for this text.
 // text/cursor_position should be consistent at any time, otherwise set a Document instead.)
 func (b *Buffer) setText(v string) {
-	if b.cursorPosition > len([]rune(v)) {
-		log.Print("[ERROR] The length of input value should be shorter than the position of cursor.")
-	}
+	debug.Assert(b.cursorPosition <= len([]rune(v)), "length of input should be shorter than cursor position")
 	o := b.workingLines[b.workingIndex]
 	b.workingLines[b.workingIndex] = v
 
@@ -138,9 +137,7 @@ func (b *Buffer) CursorDown(count int) {
 
 // DeleteBeforeCursor delete specified number of characters before cursor and return the deleted text.
 func (b *Buffer) DeleteBeforeCursor(count int) (deleted string) {
-	if count <= 0 {
-		log.Print("[ERROR] The count argument on DeleteBeforeCursor should grater than 0.")
-	}
+	debug.Assert(count > 0, "count should be grater than 0")
 	r := []rune(b.Text())
 
 	if b.cursorPosition > 0 {

completion.go

@@ -1,9 +1,9 @@
 package prompt
 
 import (
-	"log"
 	"strings"
 
+	"github.com/c-bata/go-prompt/internal/debug"
 	runewidth "github.com/mattn/go-runewidth"
 )
 
@@ -44,7 +44,7 @@ func (c *CompletionManager) GetSelectedSuggestion() (s Suggest, ok bool) {
 	if c.selected == -1 {
 		return Suggest{}, false
 	} else if c.selected < -1 {
-		log.Printf("[ERROR] shoud be reached here, selected=%d", c.selected)
+		debug.Assert(true, "must not reach here")
 		c.selected = -1
 		return Suggest{}, false
 	}
@@ -136,7 +136,6 @@ func formatTexts(o []string, max int, prefix, suffix string) (new []string, widt
 		return n, 0
 	}
 	if min >= max {
-		log.Println("[WARN] formatTexts: max is lower than length of prefix and suffix.")
 		return n, 0
 	}
 	if lenPrefix+width+lenSuffix > max {

emacs.go

@@ -1,5 +1,7 @@
 package prompt
 
+import "github.com/c-bata/go-prompt/internal/debug"
+
 /*
 
 ========
@@ -112,7 +114,8 @@ var emacsKeyBindings = []KeyBind{
 		Fn: func(buf *Buffer) {
 			consoleWriter.EraseScreen()
 			consoleWriter.CursorGoTo(0, 0)
-			consoleWriter.Flush()
+			err := consoleWriter.Flush()
+			debug.Assert(err == nil, err)
 		},
 	},
 }

input_posix.go

@@ -4,7 +4,6 @@ package prompt
 
 import (
 	"bytes"
-	"log"
 	"syscall"
 	"unsafe"
 
@@ -23,11 +22,9 @@ type PosixParser struct {
 func (t *PosixParser) Setup() error {
 	// Set NonBlocking mode because if syscall.Read block this goroutine, it cannot receive data from stopCh.
 	if err := syscall.SetNonblock(t.fd, true); err != nil {
-		log.Println("[ERROR] Cannot set non blocking mode.")
 		return err
 	}
 	if err := t.setRawMode(); err != nil {
-		log.Println("[ERROR] Cannot set raw mode.")
 		return err
 	}
 	return nil
@@ -36,11 +33,9 @@ func (t *PosixParser) Setup() error {
 // TearDown should be called after stopping input
 func (t *PosixParser) TearDown() error {
 	if err := syscall.SetNonblock(t.fd, false); err != nil {
-		log.Println("[ERROR] Cannot set blocking mode.")
 		return err
 	}
 	if err := t.resetRawMode(); err != nil {
-		log.Println("[ERROR] Cannot reset from raw mode.")
 		return err
 	}
 	return nil

internal/debug/assert.go

@@ -0,0 +1,51 @@
+package debug
+
+import (
+	"fmt"
+	"os"
+)
+
+const (
+	envAssertPanic = "GO_PROMPT_ENABLE_ASSERT"
+)
+
+var (
+	assertFunc = assertLog
+)
+
+func init() {
+	enableAssert := os.Getenv(envAssertPanic)
+	if enableAssert == "true" || enableAssert == "1" {
+		assertFunc = assertPanic
+	}
+}
+
+func assertPanic(msg interface{}) {
+	panic(msg)
+}
+
+func assertLog(msg interface{}) {
+	calldepth := 3
+	writeWithSync(calldepth, "[ASSERT] "+toString(msg))
+}
+
+// Assert raise panic or write log if cond is false.
+func Assert(cond bool, msg interface{}) {
+	if cond {
+		return
+	}
+	assertFunc(msg)
+}
+
+func toString(v interface{}) string {
+	switch a := v.(type) {
+	case func() string:
+		return a()
+	case string:
+		return a
+	case fmt.Stringer:
+		return a.String()
+	default:
+		return fmt.Sprintf("unexpected type, %t", v)
+	}
+}

internal/debug/log.go

@@ -0,0 +1,53 @@
+package debug
+
+import (
+	"io/ioutil"
+	"log"
+	"os"
+)
+
+const (
+	envEnableLog = "GO_PROMPT_ENABLE_LOG"
+	logFileName  = "go-prompt.log"
+)
+
+var (
+	logfile *os.File
+	logger  *log.Logger
+)
+
+func init() {
+	enableLog := os.Getenv(envEnableLog)
+	if enableLog == "true" || enableLog == "1" {
+		var err error
+		logfile, err = os.OpenFile(logFileName, os.O_WRONLY|os.O_CREATE|os.O_APPEND, 0666)
+		if err == nil {
+			logger = log.New(logfile, "", log.Llongfile)
+			return
+		}
+	}
+	logger = log.New(ioutil.Discard, "", log.Llongfile)
+}
+
+// Teardown to close logfile
+func Teardown() {
+	if logfile == nil {
+		return
+	}
+	_ = logfile.Close()
+}
+
+func writeWithSync(calldepth int, msg string) {
+	calldepth++
+	if logfile == nil {
+		return
+	}
+	_ = logger.Output(calldepth, msg)
+	_ = logfile.Sync() // immediately write msg
+}
+
+// Log to output message
+func Log(msg string) {
+	calldepth := 2
+	writeWithSync(calldepth, msg)
+}

output_posix.go

@@ -3,7 +3,6 @@
 package prompt
 
 import (
-	"log"
 	"syscall"
 )
 
@@ -24,7 +23,6 @@ func (w *PosixWriter) Flush() error {
 	for {
 		n, err := syscall.Write(w.fd, w.buffer[offset:])
 		if err != nil {
-			log.Printf("[DEBUG] flush error: %s", err)
 			if retry < flushMaxRetryCount {
 				retry++
 				continue

prompt.go

@@ -2,14 +2,10 @@ package prompt
 
 import (
 	"bytes"
-	"io/ioutil"
-	"log"
 	"os"
 	"time"
-)
 
-const (
-	envDebugLogPath = "GO_PROMPT_LOG_PATH"
+	"github.com/c-bata/go-prompt/internal/debug"
 )
 
 // Executor is called when user input something text.
@@ -38,16 +34,8 @@ type Exec struct {
 
 // Run starts prompt.
 func (p *Prompt) Run() {
-	if l := os.Getenv(envDebugLogPath); l == "" {
-		log.SetOutput(ioutil.Discard)
-	} else if f, err := os.OpenFile(l, os.O_WRONLY|os.O_CREATE|os.O_APPEND, 0666); err != nil {
-		log.SetOutput(ioutil.Discard)
-	} else {
-		defer f.Close()
-		log.SetOutput(f)
-		log.Println("[INFO] Logging is enabled.")
-	}
-
+	defer debug.Teardown()
+	debug.Log("start prompt")
 	p.setUp()
 	defer p.tearDown()
 
@@ -81,14 +69,16 @@ func (p *Prompt) Run() {
 
 				// Unset raw mode
 				// Reset to Blocking mode because returned EAGAIN when still set non-blocking mode.
-				p.in.TearDown()
+				err := p.in.TearDown()
+				debug.Assert(err == nil, err)
 				p.executor(e.input)
 
 				p.completion.Update(*p.buf.Document())
 				p.renderer.Render(p.buf, p.completion)
 
 				// Set raw mode
-				p.in.Setup()
+				err = p.in.Setup()
+				debug.Assert(err == nil, err)
 				go p.readBuffer(bufCh, stopReadBufCh)
 				go p.handleSignals(exitCh, winSizeCh, stopHandleSignalCh)
 			} else {
@@ -120,7 +110,6 @@ func (p *Prompt) feed(b []byte) (shouldExit bool, exec *Exec) {
 		p.renderer.BreakLine(p.buf)
 
 		exec = &Exec{input: p.buf.Text()}
-		log.Printf("[History] %s", p.buf.Text())
 		p.buf = NewBuffer()
 		if exec.input != "" {
 			p.history.Add(exec.input)
@@ -223,16 +212,8 @@ func (p *Prompt) handleASCIICodeBinding(b []byte) bool {
 
 // Input just returns user input text.
 func (p *Prompt) Input() string {
-	if l := os.Getenv(envDebugLogPath); l == "" {
-		log.SetOutput(ioutil.Discard)
-	} else if f, err := os.OpenFile(l, os.O_WRONLY|os.O_CREATE|os.O_APPEND, 0666); err != nil {
-		log.SetOutput(ioutil.Discard)
-	} else {
-		defer f.Close()
-		log.SetOutput(f)
-		log.Println("[INFO] Logging is enabled.")
-	}
-
+	defer debug.Teardown()
+	debug.Log("start prompt")
 	p.setUp()
 	defer p.tearDown()
 
@@ -267,11 +248,11 @@ func (p *Prompt) Input() string {
 }
 
 func (p *Prompt) readBuffer(bufCh chan []byte, stopCh chan struct{}) {
-	log.Printf("[INFO] readBuffer start")
+	debug.Log("start reading buffer")
 	for {
 		select {
 		case <-stopCh:
-			log.Print("[INFO] stop readBuffer")
+			debug.Log("stop reading buffer")
 			return
 		default:
 			if b, err := p.in.Read(); err == nil && !(len(b) == 1 && b[0] == 0) {
@@ -283,12 +264,14 @@ func (p *Prompt) readBuffer(bufCh chan []byte, stopCh chan struct{}) {
 }
 
 func (p *Prompt) setUp() {
-	p.in.Setup()
+	err := p.in.Setup()
+	debug.Assert(err == nil, err)
 	p.renderer.Setup()
 	p.renderer.UpdateWinSize(p.in.GetWinSize())
 }
 
 func (p *Prompt) tearDown() {
-	p.in.TearDown()
+	err := p.in.TearDown()
+	debug.Assert(err == nil, err)
 	p.renderer.TearDown()
 }

render.go

@@ -3,6 +3,7 @@ package prompt
 import (
 	"runtime"
 
+	"github.com/c-bata/go-prompt/internal/debug"
 	runewidth "github.com/mattn/go-runewidth"
 )
 
@@ -40,7 +41,8 @@ type Render struct {
 func (r *Render) Setup() {
 	if r.title != "" {
 		r.out.SetTitle(r.title)
-		r.out.Flush()
+		err := r.out.Flush()
+		debug.Assert(err == nil, err)
 	}
 }
 
@@ -63,7 +65,8 @@ func (r *Render) renderPrefix() {
 func (r *Render) TearDown() {
 	r.out.ClearTitle()
 	r.out.EraseDown()
-	r.out.Flush()
+	err := r.out.Flush()
+	debug.Assert(err == nil, err)
 }
 
 func (r *Render) prepareArea(lines int) {
@@ -175,7 +178,10 @@ func (r *Render) Render(buffer *Buffer, completion *CompletionManager) {
 	if r.col == 0 {
 		return
 	}
-	defer r.out.Flush()
+	defer func() {
+		err := r.out.Flush()
+		debug.Assert(err == nil, err)
+	}()
 	r.move(r.previousCursor, 0)
 
 	line := buffer.Text()
@@ -233,7 +239,8 @@ func (r *Render) BreakLine(buffer *Buffer) {
 	r.out.SetColor(r.inputTextColor, r.inputBGColor, false)
 	r.out.WriteStr(buffer.Document().Text + "\n")
 	r.out.SetColor(DefaultColor, DefaultColor, false)
-	r.out.Flush()
+	err := r.out.Flush()
+	debug.Assert(err == nil, err)
 
 	r.previousCursor = 0
 }

signal_posix.go

@@ -3,10 +3,11 @@
 package prompt
 
 import (
-	"log"
 	"os"
 	"os/signal"
 	"syscall"
+
+	"github.com/c-bata/go-prompt/internal/debug"
 )
 
 func (p *Prompt) handleSignals(exitCh chan int, winSizeCh chan *WinSize, stop chan struct{}) {
@@ -23,24 +24,24 @@ func (p *Prompt) handleSignals(exitCh chan int, winSizeCh chan *WinSize, stop ch
 	for {
 		select {
 		case <-stop:
-			log.Println("[INFO] stop handleSignals")
+			debug.Log("stop handleSignals")
 			return
 		case s := <-sigCh:
 			switch s {
 			case syscall.SIGINT: // kill -SIGINT XXXX or Ctrl+c
-				log.Println("[SIGNAL] Catch SIGINT")
+				debug.Log("Catch SIGINT")
 				exitCh <- 0
 
 			case syscall.SIGTERM: // kill -SIGTERM XXXX
-				log.Println("[SIGNAL] Catch SIGTERM")
+				debug.Log("Catch SIGTERM")
 				exitCh <- 1
 
 			case syscall.SIGQUIT: // kill -SIGQUIT XXXX
-				log.Println("[SIGNAL] Catch SIGQUIT")
+				debug.Log("Catch SIGQUIT")
 				exitCh <- 0
 
 			case syscall.SIGWINCH:
-				log.Println("[SIGNAL] Catch SIGWINCH")
+				debug.Log("Catch SIGWINCH")
 				winSizeCh <- in.GetWinSize()
 			}
 		}

signal_windows.go

@@ -3,10 +3,11 @@
 package prompt
 
 import (
-	"log"
 	"os"
 	"os/signal"
 	"syscall"
+
+	"github.com/c-bata/go-prompt/internal/debug"
 )
 
 func (p *Prompt) handleSignals(exitCh chan int, winSizeCh chan *WinSize, stop chan struct{}) {
@@ -21,21 +22,21 @@ func (p *Prompt) handleSignals(exitCh chan int, winSizeCh chan *WinSize, stop ch
 	for {
 		select {
 		case <-stop:
-			log.Println("[INFO] stop handleSignals")
+			debug.Log("stop handleSignals")
 			return
 		case s := <-sigCh:
 			switch s {
 
 			case syscall.SIGINT: // kill -SIGINT XXXX or Ctrl+c
-				log.Println("[SIGNAL] Catch SIGINT")
+				debug.Log("Catch SIGINT")
 				exitCh <- 0
 
 			case syscall.SIGTERM: // kill -SIGTERM XXXX
-				log.Println("[SIGNAL] Catch SIGTERM")
+				debug.Log("Catch SIGTERM")
 				exitCh <- 1
 
 			case syscall.SIGQUIT: // kill -SIGQUIT XXXX
-				log.Println("[SIGNAL] Catch SIGQUIT")
+				debug.Log("Catch SIGQUIT")
 				exitCh <- 0
 			}
 		}