ENDPOINT CLIENT ERROR - REPLY WITH BAD REQUEST [Error: Parse Error: Invalid header value char]

[rkomandu]

Environment info

• NooBaa Version: VERSION
• Platform: Kubernetes 1.14.1 | minikube 1.1.1 | OpenShift 4.1 | other: specify
  noobaa d/s non containerized noobaa-core-5.17.2-20241217.el9.ppc64le

Actual behavior

Nothing is running from S3 IO perspective on the system at the time of error, however observed the following in the node noobaa log.

noobaa.log
-------------------
Dec 18 22:21:20 node-gui0 node[553606]: 2024-12-18 22:21:20.486595 [PID-553606/TID-553646] [L1] FS::FSWorker::Execute: Stat _path=/ibm/fvt_ces_root/ces/s3
-config _uid=0 _gid=0 geteuid()=0 getegid()=0 getuid()=0 getgid()=0
Dec 18 22:21:20 node-gui0 node[553606]: 2024-12-18 22:21:20.486754 [PID-553606/TID-553646] [L1] FS::FSWorker::Execute: Stat _path=/ibm/fvt_ces_root/ces/s3
-config  took: 0.144941 ms
Dec 18 22:21:20 node-gui0 node[553606]: [/553606]   [LOG] CONSOLE:: read_rand_seed: reading 32 bytes from /dev/urandom ...
Dec 18 22:21:20 node-gui0 node[553606]: 2024-12-18 22:21:20.487281 [PID-553606/TID-553606] [L1] FS::Stat::OnOK: _path=/ibm/fvt_ces_root/ces/s3-config _sta
t_res.st_ino=146434 _stat_res.st_size=4096
Dec 18 22:21:20 node-gui0 node[553606]: [/553606]    [L1] core.sdk.config_fs:: create_config_dirs_if_missing: config dir exists: /ibm/fvt_ces_root/ces/s3-
config
Dec 18 22:21:20 node-gui0 node[553606]: 2024-12-18 22:21:20.487484 [PID-553606/TID-553606] [L1] FS::FSWorker::Begin: Stat _path=/ibm/fvt_ces_root/ces/s3-c
onfig/buckets
Dec 18 22:25:56 node-gui0 [244599]: [nsfs/244599] [ERROR] CONSOLE:: ENDPOINT CLIENT ERROR - REPLY WITH BAD REQUEST [Error: Parse Error: Invalid header val
ue char] { bytesParsed: 37, code: 'HPE_INVALID_HEADER_TOKEN', reason: 'Invalid header value char', rawPacket: <Buffer 50 4f 53 54 20 2f 20 48 54 54 50 2f 31 2
e 31 0a 48 6f 73 74 3a 20 39 2e 34 32 2e 39 33 2e 37 32 3a 36 34 34 33 0a 55 73 65 72 2d 41 67 65 6e 74 3a 20 ... 1841 more bytes> }
Dec 18 22:25:56 node-gui0 [244600]: [nsfs/244600]  [WARN] core.util.signature_utils:: Anonymous request: GET / { host: 'node-gui0.rtp.raleigh.ibm.com:
6443', 'accept-charset': 'iso-8859-1,utf-8;q=0.9,*;q=0.1', 'accept-language': 'en', connection: 'Keep-Alive', 'user-agent': 'Mozilla/4.0 (compatible; MSIE 8.0
; Windows NT 5.1; Trident/4.0)', pragma: 'no-cache', accept: 'image/gif, image/x-xbitmap, image/jpeg, image/pjpeg, image/png, */*' }
Dec 18 22:25:56 node-gui0 [244600]: [nsfs/244600]  [WARN] core.util.signature_utils:: Anonymous request: GET / { host: 'node-gui0.rtp.raleigh.ibm.com:
6443', 'accept-charset': 'iso-8859-1,utf-8;q=0.9,*;q=0.1', 'accept-language': 'en', connection: 'Keep-Alive', 'user-agent': 'Mozilla/4.0 (compatible; MSIE 8.0
; Windows NT 5.1; Trident/4.0)', pragma: 'no-cache', accept: 'image/gif, image/x-xbitmap, image/jpeg, image/pjpeg, image/png, */*' }
..
Dec 18 22:29:48 node-gui0 [244600]: 2024-12-18 22:29:48.864224 [PID-244600/TID-244634] [L1] FS::FSWorker::Execute: Readfile _path=/ibm/fvt_ces_root/ces/s3
-config/buckets/..json _uid=0 _gid=0 geteuid()=0 getegid()=0 getuid()=0 getgid()=0
Dec 18 22:29:48 node-gui0 [244600]: 2024-12-18 22:29:48.864247 [PID-244600/TID-244634] [L1] FS::FSWorker::Execute: Readfile _path=/ibm/fvt_ces_root/ces/s3
-config/buckets/..json  took: 0.013404 ms
Dec 18 22:29:48 node-gui0 [244600]: 2024-12-18 22:29:48.864275 [PID-244600/TID-244600] [L1] FS::FSWorker::OnError: Readfile _path=/ibm/fvt_ces_root/ces/s3
-config/buckets/..json  error.Message()=No such file or directory
Dec 18 22:29:48 node-gui0 [244600]: [nsfs/244600]  [WARN] core.sdk.config_fs:: get_config_data: with config_file_path /ibm/fvt_ces_root/ces/s3-config/buck
ets/..json got an error [Error: No such file or directory] { code: 'ENOENT', context: 'Readfile _path=/ibm/fvt_ces_root/ces/s3-config/buckets/..json ' }
Dec 18 22:29:48 node-gui0 [244600]: [nsfs/244600] [ERROR] CONSOLE:: ENDPOINT CLIENT ERROR - REPLY WITH BAD REQUEST [Error: Parse Error: Unexpected start char in url] { bytesParsed: 4, code: 'HPE_INVALID_URL', reason: 'Unexpected start char in url', rawPacket: <Buffer 47 45 54 20 2e 2f 2e 2f 2e 2f 2e 2f 2e 2f 2e 2f 2e 2f 2e 2f 2e 2f 2e 2f 2e 2f 2e 2f 2e 2f 2e 2f 2e 2f 2e 2f 2e 2f 2e 2f 2e 2f 2e 2f 2e 2f 2e 2f 2e 2f ... 477 more bytes> }
Dec 18 22:29:49 node-gui0 [244600]: [nsfs/244600]  [WARN] core.util.signature_utils:: Anonymous request: GET / { host: 'node-gui0.rtp.raleigh.ibm.com:6443', 'accept-charset': 'iso-8859-1,utf-8;q=0.9,*;q=0.1', 'accept-language': 'en', connection: 'Keep-Alive', 'user-agent': 'Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 5.1; Trident/4.0)', pragma: 'no-cache', accept: 'image/gif, image/x-xbitmap, image/jpeg, image/pjpeg, image/png, */*' }
Dec 18 22:29:49 node-gui0 [244600]: [nsfs/244600]  [WARN] core.util.signature_utils:: Anonymous request: GET / { host: 'node-gui0.rtp.raleigh.ibm.com:6443', 'accept-charset': 'iso-8859-1,utf-8;q=0.9,*;q=0.1', 'accept-language': 'en', connection: 'Keep-Alive', 'user-agent': 'Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 5.1; Trident/4.0)', pragma: 'no-cache', accept: 'image/gif, image/x-xbitmap, image/jpeg, image/pjpeg, image/png, */*' }

Nothing relevant in mmfs.log on the node at that time.

2024-12-18_22:23:57.573-0500: [E] Killing connection from 9.46.74.79, err 73
2024-12-18_22:23:57.573-0500: Connection reset by peer
2024-12-18_22:24:23.286-0500: [E] Killing connection from 9.46.74.79, err 73
2024-12-18_22:24:23.286-0500: Connection reset by peer
2024-12-18_22:30:03.358-0500: [E] Killing connection from 9.46.74.79, err 120
2024-12-18_22:30:03.358-0500: Error in communications between mmfsd daemon and client program.
2024-12-18_22:37:56.947-0500: [E] Killing connection from 9.46.74.79, err 73
2024-12-18_22:37:56.947-0500: Connection reset by peer

Expected behavior

Not clear why does this error appeared in logs , when no IO ran from the user side. Could be something triggered, Anonymous user is not created on the cluster as well.

Steps to reproduce

More information - Screenshots / Logs / Other output

Will copy the noobaa.log, gpfs.log on the node into box folder for analysis https://ibm.ent.box.com/folder/299550817338

Note: Noobaa is running at "all" as the log level

[rkomandu]

@romayalon @shirady , as we discussed over Thus evening call, opened this issue.. If you observe about noobaa.log snippet posted above it shows the one time with "'Invalid header value char'" , other time "'Unexpected start char in url"

[shirady]

Hi,
@rkomandu I will share that I still don't know the origin of this client.
Does it happen routinely at a specific time on the running nodes (like at the same time each day)?

Additional Information

I can share what I checked:
I looked at the printings:

Dec 18 22:25:56 node-gui0 [244599]: [nsfs/244599] [ERROR] CONSOLE:: ENDPOINT CLIENT ERROR - REPLY WITH BAD REQUEST [Error: Parse Error: Invalid header val
ue char] { bytesParsed: 37, code: 'HPE_INVALID_HEADER_TOKEN', reason: 'Invalid header value char', rawPacket: <Buffer 50 4f 53 54 20 2f 20 48 54 54 50 2f 31 2
e 31 0a 48 6f 73 74 3a 20 39 2e 34 32 2e 39 33 2e 37 32 3a 36 34 34 33 0a 55 73 65 72 2d 41 67 65 6e 74 3a 20 ... 1841 more bytes> }

Dec 18 22:25:56 node-gui0 [244600]: [nsfs/244600]  [WARN] core.util.signature_utils:: Anonymous request: GET / { host: 'node-gui0.rtp.raleigh.ibm.com:
6443', 'accept-charset': 'iso-8859-1,utf-8;q=0.9,*;q=0.1', 'accept-language': 'en', connection: 'Keep-Alive', 'user-agent': 'Mozilla/4.0 (compatible; MSIE 8.0
; Windows NT 5.1; Trident/4.0)', pragma: 'no-cache', accept: 'image/gif, image/x-xbitmap, image/jpeg, image/pjpeg, image/png, */*' }

For the "ENDPOINT CLIENT ERROR" as you mentioned it is not IO I tried to run a CLI health command (on master branch) on a running NSFS server with sudo node src/cmd/nsfs --debug 5 --forks 2 and sudo node src/cmd/manage_nsfs diagnose health on the server side I didn't see any printings, and I added printings in the health:

     async make_endpoint_health_request(url_path) {
+        console.log('SDSD inside make_endpoint_health_request, url_path', url_path);
+        console.log('SDSD', HOSTNAME, this.https_port, url_path, 'GET');
         const response = await make_https_request({
             HOSTNAME,
             port: this.https_port,
@@ -243,6 +245,9 @@ class NSFSHealth {
             method: 'GET',
             rejectUnauthorized: false,
         });
+        console.log('SDSD response', response);
+        console.log('SDSD response.statusCode', response.statusCode);
+        console.log('SDSD response.rawHeaders', response.rawHeaders);

attached here:
diff.txt

And I saw this (nothing caught my eyes as possible "Invalid header value char"):

Jan-14 9:41:29.189 [/95296]   [LOG] CONSOLE:: SDSD inside make_endpoint_health_request, url_path /total_fork_count
Jan-14 9:41:29.189 [/95296]   [LOG] CONSOLE:: SDSD localhost 6443 /total_fork_count GE
Jan-14 9:41:29.259 [/95296]   [LOG] CONSOLE:: SDSD response.statusCode 200
Jan-14 9:41:29.260 [/95296]   [LOG] CONSOLE:: SDSD response.rawHeaders [ 'Server', 'NooBaa/5.18.0', 'Content-Type', 'application/json', 'Content-Length', '16', 'Date', 'Tue, 14 Jan 2025 07:41:29 GMT', 'Connection', 'close' ]

For the printing in "[WARN] core.util.signature_utils:: Anonymous request" although it runs by another PID (244600, where the previous printing was from PID 244599) I also looked at it and searched in "signature_utils" file the origin of this error printings and saw it was from the function make_auth_token_from_request which is called from every service in the flow of handle_request, and as you wrote there was no user IO, so I don't think it is related to the "ENDPOINT CLIENT ERROR" we saw:

noobaa-core/src/util/signature_utils.js

Line 275 in 30ac4b2

dbg.warn('Anonymous request:', req.method, req.originalUrl, req.headers);