[TT-6202] Golang Virtual Endpoints should not produce runtime error in log message although request and response is normal

[uddmorningsun]

Branch/Environment/Version

root@2121376709b1:/tyk-src# git branch -vvv
* master        5d26bcca [origin/master] Honor tags on loadRPC apidef load code paths (#4187)

Describe the bug

Request Golang Virtual Endpoints APIs will produce runtime error: invalid memory address or nil pointer dereference from GoPluginMiddleware in log message, although request and response is normal, the behavior is not expected for usage.

Reproduction steps

Based on tykio/tyk-gateway:v4.0.0 runtime image, go1.16.5 binary tarball, tyk source:

root@2d50739da59f:/tyk-src# /opt/go/bin/go version
go version go1.16.5 linux/amd64

root@2d50739da59f:/tyk-src# cat 123321/main.go
package main

import (
	"fmt"
	"net/http"
	"runtime"
)

func GoPluginFoo(rw http.ResponseWriter, r *http.Request) {
	var jsonData = []byte(`{"data": ` + fmt.Sprintf("%q", runtime.Version()) + `, "total": 0}`)
	rw.WriteHeader(http.StatusCreated)
	rw.Write(jsonData)
}

func main() {}


root@2d50739da59f:/tyk-src# /opt/go/bin/go build -buildmode=plugin -o 123321/plugin.so 123321/main.go

root@2d50739da59f:/tyk-src# diff -u0 -bB /opt/tyk-gateway/tyk.conf /opt/tyk-gateway/tyk.conf.orig
--- /opt/tyk-gateway/tyk.conf	2022-07-20 14:43:22.151661119 +0000
+++ /opt/tyk-gateway/tyk.conf.orig	2022-02-14 11:57:48.000000000 +0000
@@ -11 +11 @@
-    "host": "192.168.0.200",
+    "host": "localhost",
@@ -14,2 +14,2 @@
-    "password": "root",
-    "database": 10,
+    "password": "",
+    "database": 0,
@@ -19 +19 @@
-  "enable_analytics": true,
+  "enable_analytics": false,

root@2d50739da59f:/tyk-src# cp  /opt/tyk-gateway/apps/app_sample.json /opt/tyk-gateway/apps/app_sample.json.orig

root@2d50739da59f:/tyk-src# diff -u1 -Bb /opt/tyk-gateway/apps/app_sample.{json,json.orig}
--- /opt/tyk-gateway/apps/app_sample.json	2022-07-20 14:42:05.387535086 +0000
+++ /opt/tyk-gateway/apps/app_sample.json.orig	2022-07-20 14:15:12.927899916 +0000
@@ -19,3 +19,5 @@
                 "extended_paths": {
-                    "go_plugin": [{"plugin_path": "123321/plugin.so", "func_name": "GoPluginFoo", "path": "/foo", "method": "GET"}]
+                    "ignored": [],
+                    "white_list": [],
+                    "black_list": []
                 }
@@ -29,5 +31,2 @@
     },
-    "use_standard_auth": false,
-    "use_keyless": true,
-    "do_not_track": false,
     "enable_batch_request_support": true

root@2d50739da59f:/tyk-src# /opt/go/bin/go mod tidy -v && /opt/go/bin/go run -tags="goplugin" main.go start --conf /opt/tyk-gateway/tyk.conf --debug

... ...
[Jul 20 14:23:42] DEBUG Started api_id=1 api_name=Tyk Test API mw=GoPluginMiddleware: : org_id=default origin=172.17.0.1 path=/tyk-api-test/foo ts=1658327022041894229
[Jul 20 14:23:42] DEBUG Go-plugin request processing took ms=0.010736 mwPath=123321/plugin.so mwSymbolName=GoPluginFoo
[Jul 20 14:23:42] ERROR Recovered from panic while running Go-plugin middleware func error=runtime error: invalid memory address or nil pointer dereference mwPath=123321/plugin.so mwSymbolName=GoPluginFoo
[Jul 20 14:23:42] DEBUG Finished api_id=1 api_name=Tyk Test API code=500 error=runtime error: invalid memory address or nil pointer dereference mw=GoPluginMiddleware: : ns=95692 org_id=default origin=172.17.0.1 path=/tyk-api-test/foo

Actual behavior

Although request and response is normal, but log message should not produce runtime error: invalid memory address or nil pointer dereference in mw_go_plugin.go

[root@control-master ~]# curl -vvvv 172.17.0.3:8080/tyk-api-test/foo
* About to connect() to 172.17.0.3 port 8080 (#0)
*   Trying 172.17.0.3...
* Connected to 172.17.0.3 (172.17.0.3) port 8080 (#0)
> GET /tyk-api-test/foo HTTP/1.1
> User-Agent: curl/7.29.0
> Host: 172.17.0.3:8080
> Accept: */*
>
< HTTP/1.1 201 Created
< X-Tyk-Api-Expires: Thu, 02 Jan 3000 15:04:00 UTC
< Date: Wed, 20 Jul 2022 15:39:38 GMT
< Content-Length: 32
< Content-Type: text/plain; charset=utf-8
<
* Connection #0 to host 172.17.0.3 left intact
{"data": "go1.16.5", "total": 0}

[mhuaco]

Hello and welcome! We appreciate you taking the time to report this. I have raised an internal ticket with our team, and we'll keep you posted on the progress.

[PatrickTaibel]

We did run into the same issue last week.

@mhuaco Additionally to the fix from @uddmorningsun for the successHandler there is another issue not present in master but on the 4.0.x branches: ProcessRequests should only use the local logger variable instead of m.logger as that is also nil in this case. It looks like this happend within a merge.

Release 4.0.4: https://github.com/TykTechnologies/tyk/blob/394a3e59937b49c916d8345392c94a1b0aed8b02/gateway/mw_go_plugin.go#L193-L206

Master: https://github.com/TykTechnologies/tyk/blob/5679edddfd884c471c2f9d4549672babc489706c/gateway/mw_go_plugin.go#L204-L217

[uddmorningsun]

@PatrickTaibel Yes, same issue for logger. About the local logger variable instead of m.logger, you can checkout tag v4.0.0 according to my investigation

I'm confused why v4.0.0 has fixed commit https://github.com/TykTechnologies/tyk/pull/3658/files and that v4.0.4 does not 😕

$ git log --oneline --tags --branches |grep 3658
ddc1e899 mw_go_plugin: fix middleware references when using per-path Go plugins (#3658)
f2e0f1cf mw_go_plugin: fix middleware references when using per-path Go plugins (#3658)

# Only included rc version in v4.0.4
$ git tag --contain ddc1e899
v4.0.0
v4.0.0-rc10
... ...
v4.0.4-rc1
v4.0.4-rc2

[uddmorningsun]

@mhuaco Any progress on this issue or PR review comments in your internal team?

[rnivet-vade]

I'm facing the same issue with v4.3.3. Any chance it's getting fixed anytime soon?

[andyo-tyk]

Hi @uddmorningsun,

This will be fixed in Tyk 5.0.8 and Tyk 5.2.3 releases.

Thank you for supporting Tyk!