Шаблон сервера включает:

Архитектура адаптера REST API к IBM MQ укрупненно показана на следующем рисунке.

Обработка ошибок

Структура ошибки

Структура для хранения ошибки:

type Error struct {
	ID       uint64 // уникальный номер ошибки
	Code     string // код ошибки
	Msg      string // текст ошибки
	Caller   string // файл, строка и наименование метода в месте создания ошибки
	Args     string // строка аргументов
	CauseErr error  // ошибка - причина
	CauseMsg string // текст ошибки - причины
	Trace    string // стек вызова в месте создания ошибки
}

Мне удобно работать с типизированными ошибками, поэтому код ошибки выделен отдельным атрибутом. В адаптере IBM MQ, использовался простой 4 символьный числовой код. Например, ошибки начинающиеся с "8ххх" относились к HTTP, с "7ххх" - к IBM MQ.

Caller - место регистрации ошибки, если нет необходимости выводить полный стек. Пример вывода:

httpserver.go:[209] - (*Server).Run()

Вычисляется функцией

func caller(depth int) string {
	pc := make([]uintptr, 15)
	n := runtime.Callers(depth+1, pc)
	frame, _ := runtime.CallersFrames(pc[:n]).Next()
	idxFile := strings.LastIndexByte(frame.File, '/')
	idx := strings.LastIndexByte(frame.Function, '/')
	idxName := strings.IndexByte(frame.Function[idx+1:], '.') + idx + 1

	return frame.File[idxFile+1:] + ":[" + strconv.Itoa(frame.Line) + "] - " + frame.Function[idxName+1:] + "()"
}

Args - отдельная строка аргументов, которые можно добавить к сообщению при создании ошибок. Используется для целей отладки.

CauseErr и CauseMsg - исходная ошибка и сообщение. Используется, если оборачиваем чужую ошибку в свою структуру.

Trace - стандартный трейс стека. Для его получения использовал своеобразный подход. При регистрации ошибки создавал пустую ошибку из пакета github.com/pkg/errors и печатал ее с ключом '%+v'. В этом режиме она выводит стек.

fmt.Sprintf("'%+v'", pkgerr.New("")

Форматирование ошибок

Для соответствия интерфейсу Error используется вывод в сокращенном формате.

func (e *Error) Error() string {
	mes := fmt.Sprintf("ID=[%v], code=[%s], mes=[%s]", e.ID, e.Code, e.Msg)
	if e.Args != "" {
		mes = fmt.Sprintf("%s, args=[%s]", mes, e.Args)
	}
	if e.CauseMsg != "" {
		mes = fmt.Sprintf("%s, causemes=[%s]", mes, e.CauseMsg)
	}
	return mes
}

Пример вывода в сокращенном формате

ID=[1], code=[8004], mes=[Error message], args=['arg1', 'arg2', 'arg3']

Для форматированного вывода используются ключи

// %s    print the error code, message, arguments, and cause message.
// %v    in addition to %s, print caller
// %+v   extended format. Each Frame of the error's StackTrace will be printed in detail.
func (e *Error) Format(s fmt.State, verb rune) {
	switch verb {
	case 'v':
		fmt.Fprint(s, e.Error())
		fmt.Fprintf(s, ", caller=[%s]", e.Caller)
		if s.Flag('+') {
			fmt.Fprintf(s, ", trace=%s", e.Trace)
			return
		}
	case 's':
		fmt.Fprint(s, e.Error())
	case 'q':
		fmt.Fprint(s, e.Error())
	}
}

Пример вывода с ключом '%+v'

ID=[1], code=[8004], mes=[Error message], args=['arg1', 'arg2', 'arg3'], caller=[handler_echo.go:[31] - (*Service).EchoHandler.func1()], trace='
github.com/romapres2010/httpserver/error.New
        D:/golang/src/github.com/romapres2010/httpserver/error/error.go:72
github.com/romapres2010/httpserver/httpserver/httpservice.(*Service).EchoHandler.func1
        D:/golang/src/github.com/romapres2010/httpserver/httpserver/httpservice/handler_echo.go:31
        ...

Предложенный формат вывода не полностью соответствует подходу структурированного логирования, это сделано специально для более удобного чтения лога в ходе отладки. Если нужнем боле строгий формат - достаточно поправить в одном месте метод Format.

Регистрация ошибок

Используются два метода для регистрации ошибок:

Дополнительные аргументы можно либо встроить в сообщение ошибки, либо передать дополнительными параметрами в args ...interface{}.

Все ошибки от сторонних и стандартных пакетов оборачиваются в кастомную ошибку в месте возникновения. Исходная ошибка вкладывается внутрь кастомной.

myerr = myerror.WithCause("8001", "Failed to read HTTP body: reqID", err, reqID)

Логирование и обработка ошибок

Использовался следующий подход:

Например, при ошибке чтения тела HTTP запроса:

requestBuf, err := ioutil.ReadAll(r.Body)
if err != nil {
    myerr = myerror.WithCause("8001", "Failed to read HTTP body: reqID", err, reqID)
    mylog.PrintfErrorInfo(myerr) // стандартное сокращенное логирование ошибки
    s.processError(myerr, w, http.StatusInternalServerError, reqID) // расширенное логирование ошибки в HTTP response
    return myerr
}

Методом processError дополнительно ошибка может логироваться в заголовок HTTP ответа и/или тело ответа. Необходимость такого логирования настраивается в конфигурационном файле сервера - параметр HTTPErrLog, или динамически вызовом POST на /httperrlog.

POST /httperrlog HTTP/1.1
Host: 127.0.0.1:3000
HTTP-Err-Log: HEADER | BODY

При логировании в header ответа нужно исключить все управляющие символы

// carriage return (CR, ASCII 0xd), line feed (LF, ASCII 0xa), and the zero character (NUL, ASCII 0x0)
headerReplacer := strings.NewReplacer("\x0a", " ", "\x0d", " ", "\x00", " ")

w.Header().Set("Err-Trace", headerReplacer.Replace(myerr.Trace))

Логирование

Для управления уровнями логирования использовался пакет github.com/hashicorp/logutils. Из рекомендованного списка уровней логирования RFC 5424 — The Syslog Protocol, оставил только 3:

Кастомной пакет логирования получился крайне простым - всего 100 строк

Куда логируем

Все логирование идет через стандартный пакет "log". Но для него подменяется вывод на кастомный логер github.com/hashicorp/logutils.

// logFilter represent a custom logger seting
var logFilter = &logutils.LevelFilter{
	Levels:   []logutils.LogLevel{"DEBUG", "INFO", "ERROR"},
	MinLevel: logutils.LogLevel("INFO"), // initial setting
	Writer:   os.Stderr,                 // initial setting
}

// InitLogger init custom logger
func InitLogger(wrt io.Writer) {
	logFilter.Writer = wrt   // custom logger
	log.SetOutput(logFilter) // set std logger to our custom
}

При необходимости, можно параллельно логировать в файл, для этого на уровне main создается лог файл и устанавливается MultiWriter

// настраиваем параллельное логирование в файл
if logFileFlag != "" {
    // добавляем в имя лог файла дату и время
    logFileFlag = strings.Replace(logFileFlag, "%s", time.Now().Format("2006_01_02_150405"), 1)

    // открываем лог файл на запись в режиме APPEND
    logFile, err := os.OpenFile(logFileFlag, os.O_RDWR|os.O_CREATE|os.O_APPEND, 0666)
    if err != nil {
        myerr := myerror.WithCause("6020", "Error open log file: Filename", err, logFileFlag)
        mylog.PrintfErrorMsg(fmt.Sprintf("%+v", myerr))
        return myerr
    }
    if logFile != nil {
        defer logFile.Close()
    }

    wrt := io.MultiWriter(os.Stderr, logFile) // параллельно пишем в os.Stderr и файл

    mylog.InitLogger(wrt) // переопределяем стандратный логер на кастомный
} else {
    mylog.InitLogger(os.Stderr)
}

Формат логирования

Логирование в режиме INFO и DEBUG сделано немного более дружественным чем логирование ошибок.

2020/03/10 17:56:39 [INFO] - httpserver.go:[61] - New() - Creating new HTTP server
2020/03/10 17:56:39 [INFO] - httpserver.go:[141] - New() - Created new TCP listener: network = 'tcp', address ['127.0.0.1:3000']
2020/03/10 17:56:39 [INFO] - httpserver.go:[155] - New() - Handler is registered: Path, Method ['/echo', 'POST']
2020/03/10 17:56:39 [INFO] - httpserver.go:[155] - New() - Handler is registered: Path, Method ['/signin', 'POST']
2020/03/10 17:56:39 [INFO] - httpserver.go:[155] - New() - Handler is registered: Path, Method ['/refresh', 'POST']
2020/03/10 17:56:39 [INFO] - httpserver.go:[179] - New() - HTTP server is created
2020/03/10 17:56:39 [INFO] - daemon.go:[121] - New() - New daemon is created
2020/03/10 17:56:39 [INFO] - daemon.go:[128] - (*Daemon).Run() - Starting daemon
2020/03/10 17:56:39 [INFO] - daemon.go:[133] - (*Daemon).Run() - Daemon is running. For exit <CTRL-c>
2020/03/10 17:56:39 [INFO] - httpserver.go:[209] - (*Server).Run() - Starting HTTP server
2020/03/10 17:57:22 [INFO] - daemon.go:[142] - (*Daemon).Run() - Exiting, got signal ['interrupt']
2020/03/10 17:57:22 [INFO] - daemon.go:[155] - (*Daemon).Shutdown() - Shutting down daemon
2020/03/10 17:57:22 [INFO] - httpserver.go:[215] - (*Server).Shutdown() - Waiting for shutdown HTTP Server: sec ['30']
2020/03/10 17:57:22 [INFO] - httpserver.go:[231] - (*Server).Shutdown() - HTTP Server shutdown successfuly
2020/03/10 17:57:22 [INFO] - daemon.go:[167] - (*Daemon).Shutdown() - Daemon is shutdown
2020/03/10 17:57:22 [INFO] - main.go:[163] - main.func1() - Server is shutdown

В режиме ERROR используется формат из раздела выше про обработку ошибок.

Как логируем

Для каждого уровня логирования сделаны отдельные функции:

func PrintfInfoMsg(mes string, args ...interface{}) {
	printfMsg("[INFO]", 0, mes, args...)
}
func PrintfDebugMsg(mes string, args ...interface{}) {
	printfMsg("[DEBUG]", 0, mes, args...)
}
func PrintfErrorMsg(mes string, args ...interface{}) {
	printfMsg("[ERROR]", 0, mes, args...)
}

Это оказалось удобнее, чем в каждой точке логирования указывать уровень. Еще один плюс - легко централизовано отключить вывод DEBUG сообщений при переходе в продуктив.

Чтобы снизить затраты на логирование INFO и DEBUG, лучше отказаться от форматирования строк в точке вызова.
Вместо

mylog.PrintfInfoMsg(fmt.Sprintf("Create new TCP listener network='tcp', address='%s'", serverCfg.ListenSpec))

использовать

mylog.PrintfInfoMsg("Created new TCP listener: network = 'tcp', address", cfg.ListenSpec)

Тесты показали, что накладные расходы на вызовы логирования DEBUG в режиме INFO не превысили 1%, поэтому я перестал вычищать код от DEBUG вызовов перед переносом на прод. В этом есть существенный положительный момент - можно динамически изменить уровень с INFO на DEBUG без остановки сервера.

Дополнительное логирование трафика

Для анализа сложных ситуаций полезно иметь возможность логирования трафика проходящего через сервер. В пакете httplog собраны методы для логирования заголовков и тела:

Настройка типа логирования и лог файла может задаваться в конфигруационном файле - параметры HttpLog и HTTPLogType, или динамически вызовом POST на /httplog.

POST /httplog HTTP/1.1
Host: 127.0.0.1:3000
Http-Log: TRUE
Http-Log-Type: INREQ | OUTREQ | INRESP | OUTRESP | BODY

Аутентификация и JSON Web Token

В шаблон включены два способа аутентификации: HTTP Basic Authentication или MS AD Authentication. Для последней использовалась библиотека gopkg.in/korylprince/go-ad-auth.v2.
На уровне конфигурационного файла сервера можно задать тип аутентификации и параметры подключения к серверу MS AD.

[AUTHENTIFICATION]
AuthType = INTERNAL | MSAD | NONE
MSADServer = company.com
MSADPort = 389
MSADBaseDN = OU=company, DC=dc, DC=corp
MSADSecurity = SecurityNone

Пользователь и пароль для проверки HTTP Basic Authentication передается через командую строку при старте сервера.

Использование JSON Web Token (JWT) задается на уровне конфигурационного файла сервера. Время жизни токена задается JWTExpiresAt. Если JWTExpiresAt=0, то время жизни не огранчено. Секретная строка для генерации JWT передается через командую строку при старте сервера.

[JWT]
UseJWT = true
JWTExpiresAt = 20000

Для работы с JWT используется библиотека github.com/dgrijalva/jwt-go. Используется только один дополнительный JSON Web Token Claims - Username.
Вся обработка JWT: создание, проверка, формирование cookie собрано в небольшой кастомный пакет jwt

Для передачи токена клиенту использовалась cookie "token".

Если включен режим аутентификации без использования JWT токена, то проверять пользователя и пароль каждый раз