Content-Length is sometimes set incorrectly?

lamrongol commented 1 year ago

I think Content-Length is probably set in line 175 of HttpClientImpl.java, but sometimes the value changes even if I post with the same parameters in misskey4j. I don't know the cause by myself, so please help me if you can. This phenomenon occurs even if I raise the version to 1.1.9 in the build.gradle of misskey4j. Here are the logs of success and failure(Access token is masked).

In case of success: ---------------------------------- [DEBUG]Params: {"text":"Streaming APIの接続がWebSocket EOFに達しました。一時間後にシステムを再起動します。","i":"**"} [DEBUG]Request: [DEBUG]POST https://misskey.io/api/notes/create [DEBUG]Accept: application/json [DEBUG]User-Agent: JHttpClient/1.0 [DEBUG]Response: [DEBUG]HTTP/1.1 200 OK [DEBUG]CF-RAY: 7bc6da3e78f7203d-NRT [DEBUG]Server: cloudflare [DEBUG]vary: Origin [DEBUG]x-frame-options: SAMEORIGIN [DEBUG]Connection: keep-alive [DEBUG]expect-ct: max-age=86400, enforce [DEBUG]x-worker-host: primary-87fc477dd-8n22b [DEBUG]strict-transport-security: max-age=2592000; includeSubDomains; preload [DEBUG]Date: Sun, 23 Apr 2023 14:38:50 GMT [DEBUG]access-control-allow-origin: * [DEBUG]CF-Cache-Status: DYNAMIC [DEBUG]x-xss-protection: 1; mode=block [DEBUG]x-content-type-options: nosniff [DEBUG]Cache-Control: private, max-age=0, must-revalidate [DEBUG]referrer-policy: same-origin [DEBUG]alt-svc: h3=":443"; ma=86400, h3-29=":443"; ma=86400 [DEBUG]Content-Length: 802 [DEBUG]Content-Type: application/json; charset=utf-8 [DEBUG]{"createdNote":{"id":"9dx2x0kb0w","createdAt":"2023-04-23T14:38:50.651Z","userId":"9cgwp1xh1d","user":{"id":"9cgwp1xh1d","name":"話題の言葉","username":"trend_words_jp","host":null,"avatarUrl":"https://nos3.arkjp.net/avatar.webp?url=https%3A%2F%2Fs3.arkjp.net%2Fmisskey%2F19758b76-0b4c-406c-9180-5bbbccb4d233.png&avatar=1","avatarBlurhash":"eaPjGcoe-;t7_3RjWBRjj[IU~qofD%j[IUxuofj[ay-;%Mj[t7fkRj","isBot":true,"isCat":false,"emojis":{},"onlineStatus":"active","badgeRoles":[]},"text":"Streaming APIの接続がWebSocket EOFに達しました。一時間後にシステムを再起動します。","cw":null,"visibility":"public","localOnly":false,"reactionAcceptance":null,"renoteCount":0,"repliesCount":0,"reactions":{},"reactionEmojis":{},"fileIds":[],"files":[],"replyId":null,"renoteId":null}}

In case of failure: --------------------------------- [DEBUG]Params: {"text":"Streaming APIの接続がWebSocket EOFに達しました。一時間後にシステムを再起動します。","i":"**"} [DEBUG]Request: [DEBUG]POST https://misskey.io/api/notes/create [DEBUG]Accept: application/json [DEBUG]User-Agent: JHttpClient/1.0 [DEBUG]Response: [DEBUG]HTTP/1.1 400 Bad Request [DEBUG]CF-RAY: 7bd9bfaedf03afd0-NRT [DEBUG]Server: cloudflare [DEBUG]vary: Origin [DEBUG]x-frame-options: SAMEORIGIN [DEBUG]Connection: keep-alive [DEBUG]expect-ct: max-age=86400, enforce [DEBUG]x-worker-host: primary-87fc477dd-n4qbz [DEBUG]strict-transport-security: max-age=2592000; includeSubDomains; preload [DEBUG]Date: Tue, 25 Apr 2023 21:41:12 GMT [DEBUG]access-control-allow-origin: * [DEBUG]CF-Cache-Status: DYNAMIC [DEBUG]x-xss-protection: 1; mode=block [DEBUG]x-content-type-options: nosniff [DEBUG]Cache-Control: private, max-age=0, must-revalidate [DEBUG]referrer-policy: same-origin [DEBUG]alt-svc: h3=":443"; ma=86400, h3-29=":443"; ma=86400 [DEBUG]Content-Length: 143 [DEBUG]Content-Type: application/json; charset=utf-8 [DEBUG]{"statusCode":400,"code":"FST_ERR_CTP_INVALID_CONTENT_LENGTH","error":"Bad Request","message":"Request body size did not match Content-Length"}

Exception in thread "遅延タイマー" misskey4j.MisskeyException: net.socialhub.http.HttpException: {"statusCode":400,"code":"FST_ERR_CTP_INVALID_CONTENT_LENGTH","error":"Bad Request","message":"Request body size did not match Content-Length"}

    at misskey4j.internal.api.AbstractResourceImpl.proceed(AbstractResourceImpl.java:90)
    at misskey4j.internal.api.AbstractResourceImpl.post(AbstractResourceImpl.java:98)
    at misskey4j.internal.api.NotesResourceImpl.create(NotesResourceImpl.java:86)
    at lamrongol.misskey.NoteSender.postQueue(NoteSender.java:35)
    at trend_detect.sender.PostSender$1.run(PostSender.java:57)
    at java.base/java.util.TimerThread.mainLoop(Timer.java:566)
    at java.base/java.util.TimerThread.run(Timer.java:516)

Caused by: net.socialhub.http.HttpException: {"statusCode":400,"code":"FST_ERR_CTP_INVALID_CONTENT_LENGTH","error":"Bad Request","message":"Request body size did not match Content-Length"}

    at net.socialhub.http.HttpClientImpl.request(HttpClientImpl.java:208)
    at net.socialhub.http.HttpRequestBuilder.proceed(HttpRequestBuilder.java:136)
    at net.socialhub.http.HttpRequestBuilder.post(HttpRequestBuilder.java:101)
    at misskey4j.internal.api.AbstractResourceImpl.lambda$post$0(AbstractResourceImpl.java:106)
    at misskey4j.internal.api.AbstractResourceImpl.proceed(AbstractResourceImpl.java:78)
    ... 6 more

Content-LengthはおそらくHttpClientImpl.javaの175行目でセットされてると思うのですが、misskey4jで同じパラメータで投稿しても値が変わることがあります。自分では原因がわからないのでよろしければ対応お願いします。なおmisskey4jのbuild.gradleでバージョンを1.1.9に上げてもこの現象が発生します。以下は成功する場合と失敗する場合のログです（アクセストークンはマスクしてます）。

成功した場合---------------------------------- [DEBUG]Params: {"text":"Streaming APIの接続がWebSocket EOFに達しました。一時間後にシステムを再起動します。","i":"**"} [DEBUG]Request: [DEBUG]POST https://misskey.io/api/notes/create [DEBUG]Accept: application/json [DEBUG]User-Agent: JHttpClient/1.0 [DEBUG]Response: [DEBUG]HTTP/1.1 200 OK [DEBUG]CF-RAY: 7bc6da3e78f7203d-NRT [DEBUG]Server: cloudflare [DEBUG]vary: Origin [DEBUG]x-frame-options: SAMEORIGIN [DEBUG]Connection: keep-alive [DEBUG]expect-ct: max-age=86400, enforce [DEBUG]x-worker-host: primary-87fc477dd-8n22b [DEBUG]strict-transport-security: max-age=2592000; includeSubDomains; preload [DEBUG]Date: Sun, 23 Apr 2023 14:38:50 GMT [DEBUG]access-control-allow-origin: * [DEBUG]CF-Cache-Status: DYNAMIC [DEBUG]x-xss-protection: 1; mode=block [DEBUG]x-content-type-options: nosniff [DEBUG]Cache-Control: private, max-age=0, must-revalidate [DEBUG]referrer-policy: same-origin [DEBUG]alt-svc: h3=":443"; ma=86400, h3-29=":443"; ma=86400 [DEBUG]Content-Length: 802 [DEBUG]Content-Type: application/json; charset=utf-8 [DEBUG]{"createdNote":{"id":"9dx2x0kb0w","createdAt":"2023-04-23T14:38:50.651Z","userId":"9cgwp1xh1d","user":{"id":"9cgwp1xh1d","name":"話題の言葉","username":"trend_words_jp","host":null,"avatarUrl":"https://nos3.arkjp.net/avatar.webp?url=https%3A%2F%2Fs3.arkjp.net%2Fmisskey%2F19758b76-0b4c-406c-9180-5bbbccb4d233.png&avatar=1","avatarBlurhash":"eaPjGcoe-;t7_3RjWBRjj[IU~qofD%j[IUxuofj[ay-;%Mj[t7fkRj","isBot":true,"isCat":false,"emojis":{},"onlineStatus":"active","badgeRoles":[]},"text":"Streaming APIの接続がWebSocket EOFに達しました。一時間後にシステムを再起動します。","cw":null,"visibility":"public","localOnly":false,"reactionAcceptance":null,"renoteCount":0,"repliesCount":0,"reactions":{},"reactionEmojis":{},"fileIds":[],"files":[],"replyId":null,"renoteId":null}}

失敗した場合--------------------------------- [DEBUG]Params: {"text":"Streaming APIの接続がWebSocket EOFに達しました。一時間後にシステムを再起動します。","i":"**"} [DEBUG]Request: [DEBUG]POST https://misskey.io/api/notes/create [DEBUG]Accept: application/json [DEBUG]User-Agent: JHttpClient/1.0 [DEBUG]Response: [DEBUG]HTTP/1.1 400 Bad Request [DEBUG]CF-RAY: 7bd9bfaedf03afd0-NRT [DEBUG]Server: cloudflare [DEBUG]vary: Origin [DEBUG]x-frame-options: SAMEORIGIN [DEBUG]Connection: keep-alive [DEBUG]expect-ct: max-age=86400, enforce [DEBUG]x-worker-host: primary-87fc477dd-n4qbz [DEBUG]strict-transport-security: max-age=2592000; includeSubDomains; preload [DEBUG]Date: Tue, 25 Apr 2023 21:41:12 GMT [DEBUG]access-control-allow-origin: * [DEBUG]CF-Cache-Status: DYNAMIC [DEBUG]x-xss-protection: 1; mode=block [DEBUG]x-content-type-options: nosniff [DEBUG]Cache-Control: private, max-age=0, must-revalidate [DEBUG]referrer-policy: same-origin [DEBUG]alt-svc: h3=":443"; ma=86400, h3-29=":443"; ma=86400 [DEBUG]Content-Length: 143 [DEBUG]Content-Type: application/json; charset=utf-8 [DEBUG]{"statusCode":400,"code":"FST_ERR_CTP_INVALID_CONTENT_LENGTH","error":"Bad Request","message":"Request body size did not match Content-Length"}

Exception in thread "遅延タイマー" misskey4j.MisskeyException: net.socialhub.http.HttpException: {"statusCode":400,"code":"FST_ERR_CTP_INVALID_CONTENT_LENGTH","error":"Bad Request","message":"Request body size did not match Content-Length"}

    at misskey4j.internal.api.AbstractResourceImpl.proceed(AbstractResourceImpl.java:90)
    at misskey4j.internal.api.AbstractResourceImpl.post(AbstractResourceImpl.java:98)
    at misskey4j.internal.api.NotesResourceImpl.create(NotesResourceImpl.java:86)
    at lamrongol.misskey.NoteSender.postQueue(NoteSender.java:35)
    at trend_detect.sender.PostSender$1.run(PostSender.java:57)
    at java.base/java.util.TimerThread.mainLoop(Timer.java:566)
    at java.base/java.util.TimerThread.run(Timer.java:516)

Caused by: net.socialhub.http.HttpException: {"statusCode":400,"code":"FST_ERR_CTP_INVALID_CONTENT_LENGTH","error":"Bad Request","message":"Request body size did not match Content-Length"}

    at net.socialhub.http.HttpClientImpl.request(HttpClientImpl.java:208)
    at net.socialhub.http.HttpRequestBuilder.proceed(HttpRequestBuilder.java:136)
    at net.socialhub.http.HttpRequestBuilder.post(HttpRequestBuilder.java:101)
    at misskey4j.internal.api.AbstractResourceImpl.lambda$post$0(AbstractResourceImpl.java:106)
    at misskey4j.internal.api.AbstractResourceImpl.proceed(AbstractResourceImpl.java:78)
    ... 6 more

lamrongol commented 1 year ago

PS: The English message "Streaming API connection is closed. System will reboot after one hour." does not fail. 追記：英語メッセージ「Streaming API connection is closed. System will reboot after one hour.」では失敗しません。

lamrongol commented 1 year ago

I just noticed that the wrong Content-Length is displayed after "[DEBUG]Response:", so it seems to be a server-side problem. 今気づいたんですが「[DEBUG]Response:」の後に誤ったContent-Lengthが表示されてるのでサーバー側の問題のようです。

uakihir0 commented 1 year ago

I'll close it as a server problem.

サーバーの問題ということでクローズします。

lamrongol commented 1 year ago

Sorry, I just checked again with the logger and it seems that the POST from here contains an error and the Content-Length is not set correctly because it goes into an if that contains an isFile() on line 153.

すみません。loggerを入れて再度調べたところこちらからPOSTする内容に誤りが含まれてるらしく、153行目のisFile()を含むif内に入るせいでContent-Lengthが正しく設定されないのではないかと思います。

uakihir0 commented 1 year ago

The following information indicates that the HTTPURLConnection used in this library ignores the Content-Length setting. (It is probably given automatically at the timing of the request.) This seems to be a behavior that cannot be changed in the current situation, since the standard library is configured that way. I can't reproduce this on my end, so this is a bit of speculation, but it may be a server-side behavior or possibly a JDK issue.

https://teratail.com/questions/28295 https://stackoverflow.com/questions/7062349/java-httpurlconnection-and-setting-the-content-length

以下の情報を見ると、本ライブラリで使用しているHTTPURLConnection では Content-Length を設定しても無視されるようです。(おそらくリクエストのタイミングで自動で付与されます) これは標準ライブラリがそのような設定になっているので、現状としては変えられない挙動になりそうです。自分の手元では再現しないので、ちょっと憶測にはなりますが、サーバー側の挙動や、もしかしたら JDK の問題なのかもしれません。

https://teratail.com/questions/28295 https://stackoverflow.com/questions/7062349/java-httpurlconnection-and-setting-the-content-length

uakihir0 / JHttpClient

Content-Length is sometimes set incorrectly? #1