chatwork (0.10.0): ChatWork is cloud-based business chat tool https://t.co/j04N4Ee7hk
— RubyGems (@rubygems) 2018年8月1日
新機能
ファイルアップロードAPIに対応しています http://developer.chatwork.com/ja/endpoint_rooms.html#POST-rooms-room_id-files
こんな感じでファイルがアップロードできます
ChatWork::File.create(room_id: 11111111, file: Faraday::UploadIO.new("/path/to/file.txt", "text/plain"), message: "Test")
ChatWorkのファイルアップロードAPIでハマってたこと
実装自体はサクッと終わったのですが、謎事象で3週間くらいハマってたのでメモ
事象
ファイルアップロードAPI自体は成功するのだが、ファイルがアップロードできていない
こんな感じでAPIは成功してるように見える
[5] pry(main)> @client.create_file(room_id: 11111111, file: Faraday::UploadIO.new("spec/data/upload.txt", "text/plain"), message: "test") => {"file_id"=>268750101} [9] pry(main)> @client.find_file(room_id: 11111111, file_id: 268750101, create_download_url: true) => {"file_id"=>268750101, "message_id"=>"", "filesize"=>424, "filename"=>"default.dat", "upload_time"=>1531931393, "account"=>{"account_id"=>2739132, "name"=>"sue445", "avatar_image_url"=>"https://appdata.chatwork.com/avatar/2170/2170448.rsz.png"}, "download_url"=>"〜"}
しかし実際にファイルはチャット部屋に投稿されていないし、↑の download_url からファイルもダウンロードできない。
APIを使わずに普通にアップロードしたファイルには全部 message_id がついてたのに、APIからアップロードすると message_id がついていないのもおかしい。
長いので急いでる人は「結論」まで読み飛ばしてください
調査内容1：問題点の切り分け
ChatWorkのAPIが悪いのか、chatwork-ruby の実装が悪いのかの切り分けのために curl でファイル投稿できるか調べることに。
$ curl -s -v -X POST -H "X-ChatWorkToken: ${CHATWORK_API_TOKEN}" -F 'file=@spec/data/upload.txt' "https://api.chatwork.com/v2/rooms/11111111/files"
こういうワンライナーでファイルが投稿できたのでChatWorkのAPIは悪くなさそう（chatwork-rubyの実装が悪い）
調査内容2：ライブラリが悪いのかRubyが悪いのかの切り分け
chatwork-rubyでは faraday を使ってたので、試しにfaradayを使わずにRubyのnet/httpだけでファイルアップロードしてみた
require 'net/https' require "uri" file_path = "/path/to/upload.txt" file = File.open(file_path) content_type = "text/plain" data = [ ["file", file, { filename: File.basename(file_path), content_type: content_type }], ] url = URI.parse("https://api.chatwork.com/v2/rooms/11111111/files") req = Net::HTTP::Post.new(url.path) req.set_form(data, "multipart/form-data") req["X-ChatWorkToken"] = ENV["CHATWORK_API_TOKEN"] res = Net::HTTP.start(url.host, url.port, use_ssl: true) do |http| http.request(req) end file.close pp res pp res.body
こういうスクリプトでファイルはアップロードできたので、faraday側の問題だと特定
調査内容3：ファイル投稿に成功するパターンと失敗するパターンでリクエストに差異があるか調べる
ChatWorkのダミーAPIをsinatraで作って、そこでリクエストの差異を調べた。
実際に使ってたスクリプトはこんな感じ。
require "sinatra" require "sinatra/reloader" if development? get "/" do "It works" end post "/v2/rooms/:room_id/files" do response = "" response << "header =====================================\n" http_headers = request.env http_headers.sort_by{|k,_v| k }.each do |k, v| response << "#{k}=#{v}\n" end response << "body =====================================\n" response << request.body.read response << "\n" response << "params =====================================\n" params.sort_by{|k,_v| k }.each do |k, v| response << "#{k}=#{v}\n" end puts response {file_id: 11111111}.to_json end
さっきまで curl -X POST 〜 "https://api.chatwork.com/v2/rooms/11111111/files" してたけど、そのかわりに curl -X POST 〜 "http://localhost:4567/v2/rooms/11111111/files"して実際にどういうリクエストが投げられてるのか目grepして調べた。（chatwork-rubyでもAPIのエンドポイントをlocalhostに差し替えて調べた）
実際のログはこんな感じ。
header =====================================
CONTENT_LENGTH=304
CONTENT_TYPE=multipart/form-data; boundary=------------------------1f157bfa7da824a5
GATEWAY_INTERFACE=CGI/1.1
HTTP_ACCEPT=*/*
HTTP_HOST=localhost:4567
HTTP_USER_AGENT=curl/7.59.0
HTTP_VERSION=HTTP/1.1
HTTP_X_CHATWORKTOKEN=XXXXXXXXXXXXXXXXXXXX
PATH_INFO=/v2/rooms/11111111/files
QUERY_STRING=
REMOTE_ADDR=::1
REMOTE_HOST=::1
REQUEST_METHOD=POST
REQUEST_PATH=/v2/rooms/11111111/files
REQUEST_URI=http://localhost:4567/v2/rooms/11111111/files
SCRIPT_NAME=
SERVER_NAME=localhost
SERVER_PORT=4567
SERVER_PROTOCOL=HTTP/1.1
SERVER_SOFTWARE=WEBrick/1.4.2 (Ruby/2.5.1/2018-03-29)
rack.errors=#<IO:0x00007f8d640a57a0>
rack.hijack?=true
rack.hijack_io=
rack.input=#<StringIO:0x00007f8d649cb938>
rack.logger=#<Logger:0x00007f8d649785f8>
rack.multiprocess=false
rack.multithread=true
rack.request.form_hash={"file"=>{:filename=>"upload.txt", :type=>"text/plain", :name=>"file", :tempfile=>#<Tempfile:/var/folders/mx/mmp8n_lx48v8_fr294_zjggw0000gn/T/RackMultipart20180722-9549-4azpxv.txt>, :head=>"Content-Disposition: form-data; name=\"file\"; filename=\"upload.txt\"\r\nContent-Type: text/plain\r\n"}, "message"=>"Test"}
rack.request.form_input=#<StringIO:0x00007f8d649cb938>
rack.request.query_hash={}
rack.request.query_string=
rack.run_once=false
rack.tempfiles=[#<Tempfile:/var/folders/mx/mmp8n_lx48v8_fr294_zjggw0000gn/T/RackMultipart20180722-9549-4azpxv.txt>]
rack.url_scheme=http
rack.version=[1, 3]
sinatra.commonlogger=true
sinatra.route=POST /v2/rooms/:room_id/files
body =====================================
--------------------------1f157bfa7da824a5
Content-Disposition: form-data; name="file"; filename="upload.txt"
Content-Type: text/plain
Hello ChatWork!
--------------------------1f157bfa7da824a5
Content-Disposition: form-data; name="message"
Test
--------------------------1f157bfa7da824a5--
params =====================================
file={"filename"=>"upload.txt", "type"=>"text/plain", "name"=>"file", "tempfile"=>#<Tempfile:/var/folders/mx/mmp8n_lx48v8_fr294_zjggw0000gn/T/RackMultipart20180722-9549-4azpxv.txt>, "head"=>"Content-Disposition: form-data; name=\"file\"; filename=\"upload.txt\"\r\nContent-Type: text/plain\r\n"}
message=Test
room_id=93207172
実際にはパラメータを色々変えつつログを見比べて調べてます。だいたい10回くらい調べたけど、boundary以外の差異が特になくて＼(^o^)／ｵﾜﾀ状態。
調査内容4：faradayでファイルアップロードしてる他の事例を調べる
真っ先に思い浮かんだのはslackのgem
https://github.com/slack-ruby/slack-ruby-client
ファイルアップロード部分やfaradayの設定周りをchatwork-rubyと見比べたけどこれといっておかしなところは無し。
- https://github.com/slack-ruby/slack-ruby-client/blob/v0.11.1/lib/slack/web/api/endpoints/files.rb#L141-L143
- https://github.com/slack-ruby/slack-ruby-client/blob/v0.11.1/lib/slack/web/faraday/connection.rb#L7-L31
ここまでくるとChatWork APIが微妙に設定がおかしいのではと思い始めてくる。
調査内容5：net/httpのソースを追う
「調査内容2」のソースで req.set_formしないとChatWorkにファイルがアップロードされないのではと思い、Rubyのnet/httpのソースを追うことにした。
https://github.com/ruby/ruby/blob/v2_5_1/lib/net/http/generic_request.rb#L119-L129
def exec(sock, ver, path) #:nodoc: internal use only if @body send_request_with_body sock, ver, path, @body elsif @body_stream send_request_with_body_stream sock, ver, path, @body_stream elsif @body_data send_request_with_body_data sock, ver, path, @body_data else write_header sock, ver, path end end
req.set_formすると @body_data に値がセットされて send_request_with_body_data側の分岐に入ってmultipart/form-dataのbodyが生成される。しかしfaradayは自分でmultipart/form-dataのbodyを生成して send_request_with_body_stream 側の分岐に入る。
この段階でfaradayが生成したmultipart/form-dataのbodyが微妙におかしいのではとあたりをつけた。
調査段階6：net/httpにブレークポイントを仕込んで調査
ここでようやく問題解決。
ファイルがアップロードできなかった時の分岐のブレークポイント
From: /Users/sue445/.rbenv/versions/2.5.0/lib/ruby/2.5.0/net/http/generic_request.rb @ line 207 Net::HTTPGenericRequest#send_request_with_body_stream: 191: def send_request_with_body_stream(sock, ver, path, f) 192: unless content_length() or chunked? 193: raise ArgumentError, 194: "Content-Length not given and Transfer-Encoding is not `chunked'" 195: end 196: supply_default_content_type 197: write_header sock, ver, path 198: wait_for_continue sock, ver if sock.continue_timeout 199: binding.pry 200: if chunked? 201: chunker = Chunker.new(sock) 202: IO.copy_stream(f, chunker) 203: chunker.finish 204: else 205: # copy_stream can sendfile() to sock.io unless we use SSL. 206: # If sock.io is an SSLSocket, copy_stream will hit SSL_write() => 207: IO.copy_stream(f, sock.io) 208: end 209: end [2] pry(#<Net::HTTP::Post::Multipart>)> f.read => "-------------RubyMultipartPost\r\nContent-Disposition: form-data; name=\"file\"; filename=\"upload.txt\"\r\nContent-Length: 16\r\nContent-Type: text/plain\r\nContent-Transfer-Encoding: binary\r\n\r\nHello ChatWork!\n\r\n-------------RubyMultipartPost--\r\n\r\n"
ファイルがアップロードできた時の分岐のブレークポイント
From: /Users/sue445/.rbenv/versions/2.5.0/lib/ruby/2.5.0/net/http/generic_request.rb @ line 231 Net::HTTPGenericRequest#send_request_with_body_data: 210: def send_request_with_body_data(sock, ver, path, params) 211: binding.pry 212: if /\Amultipart\/form-data\z/i !~ self.content_type 213: self.content_type = 'application/x-www-form-urlencoded' 214: return send_request_with_body(sock, ver, path, URI.encode_www_form(params)) 215: end 216: 217: opt = @form_option.dup 218: require 'securerandom' unless defined?(SecureRandom) 219: opt[:boundary] ||= SecureRandom.urlsafe_base64(40) 220: self.set_content_type(self.content_type, boundary: opt[:boundary]) 221: if chunked? 222: puts "[send_request_with_body_data] debug 2" 223: write_header sock, ver, path 224: encode_multipart_form_data(sock, params, opt) 225: else 226: require 'tempfile' 227: file = Tempfile.new('multipart') 228: file.binmode 229: encode_multipart_form_data(file, params, opt) 230: file.rewind => 231: self.content_length = file.size 232: write_header sock, ver, path 233: IO.copy_stream(file, sock) 234: file.close(true) 235: end 236: end [19] pry(#<Net::HTTP::Post>)> file.read => "--dmpgu3OX7ioTGyZ8xoQo0V5RB8CLM-Kr2IOdw4EqWF2sO_hABe0niQ\r\nContent-Disposition: form-data; name=\"file\"; filename=\"upload.txt\"\r\nContent-Type: text/plain\r\n\r\nHello ChatWork!\n\r\n--dmpgu3OX7ioTGyZ8xoQo0V5RB8CLM-Kr2IOdw4EqWF2sO_hABe0niQ--\r\n"
ｳｰﾝ、bodyの終端の改行の個数がおかしくね？？？
\r\n\r\n だとファイルアップロードできなくて \r\n だとファイルアップロードできてる。
試しにローカルで下記の改行を1つ削って動かしたらファイルアップロード成功 https://github.com/nicksieger/multipart-post/blob/v2.0.0/lib/parts.rb#L92
勝った！第3部完ッ！（AA略
調査内容3で成功するパターンと失敗するパターンでbodyの中身を比較して差異が無いと判断したけど、末尾の改行の個数が違うのは完全に見逃してた。。。
結論
ファイルをPOSTする時にはmultipart/formdataのbodyの末尾が \r\n にする必要がある。（\r\n\r\n だとファイルがアップロードできない）
モンキーパッチ
multipartのbodyの末尾が \r\n\r\nで問題が起きるのは少なくともChatWorkだけっぽいのでmultipart-postにPR投げてもリジェクトされる可能性が高いし *1、かといってさっきの EpiloguePart をオープンクラスで直接書き換えるとchatwork-ruby以外でfaraday使ってた場合にも影響を受けてしまう可能性があったので、別名でクラスを作って差し替えるようにした。
ソース
https://github.com/asonas/chatwork-ruby/blob/v0.10.0/lib/chatwork/multipart.rb
学び
*1:少なくとも multipart-post のissueに問題それっぽいのが書かれてなかったので誰も困ってない
