fmrest-ruby icon indicating copy to clipboard operation
fmrest-ruby copied to clipboard
verified publisher icon beezwax

Spyke::ConnectionError occurs with empty log array in find_one

Open YudaiNoda3576 opened this issue 1 year ago • 5 comments

Hello, I am currently using the fmrest-ruby gem with FileMaker Pro 19's Data API, and I've encountered an issue where a Spyke::ConnectionError is raised with an empty log array. The error occurs when calling the find_one method. Below are the details.

I call the find_one method to fetch a single record from FileMaker. Occasionally, the method raises a Spyke::ConnectionError, and the log shows an empty array, as seen below:

Spyke::ConnectionError
Spyke (65284.7ms) POST  []

Relevant code snippet:

def find_one(options = {})
  @find_one ||=
    if primary_key_set?
      without_collection_params { super() }
    else
      klass.new_collection_from_result(limit(1).fetch(options)).first
    end
rescue ::Spyke::ConnectionError => error
  fallback_or_reraise(error, default: nil)
end

Additional details:

I have checked the FileMaker API logs, and there are no errors or failed requests recorded on the server side, which suggests that the request is not reaching the server or is being silently rejected. This makes it difficult to diagnose the root cause from the FileMaker logs alone.

Possible cause:

I suspect this might be related to an authentication issue with the FileMaker Data API, where the connection attempt is either unauthorized or unsuccessful. However, I'm not sure why the log array is empty, and I would like some clarification on this behavior.

Questions:

Could you provide insight into why the log array might be empty when a Spyke::ConnectionError occurs? Is there a recommended way to handle this error more effectively, or to gather more detailed logs when this happens? Are there any known issues related to authentication that might cause this error, even though the FileMaker API logs show no errors?

Environment:

Ruby version: 3.2.2 FileMaker Pro version: 19

Thank you for your time and assistance!

YudaiNoda3576 avatar Sep 10 '24 09:09 YudaiNoda3576

Hi @YudaiNoda3576, I need more information to be able to diagnose the problem. Could you provide the following?

  • Your fmrest-ruby, Spyke and Faraday gem versions
  • Your FmRest configuration (with sensitive data removed of course), especially how you've set up your token store
  • If possible, a minimal code example of where it fails, using this template:
require "bundler/inline"

gemfile do
  source "https://rubygems.org"
  gem "fmrest"
end

FmRest.token_store = FmRest::TokenStore::Memory

class MyLayout < FmRest::Layout("MyLayout")
  self.fmrest_config = {
    host: "",
    database: "",
    username: "",
    password: "",
    log: true
  }
end

MyLayout.find_one

👆 Put that in a test.rb file and run it with ruby test.rb.

Also, could you try enabling Faraday logging of raw HTTP requests as described in the Logging section of the README? After that you should see these kid of log messages:

D, [2024-09-14T13:41:39.161030 #84751] DEBUG -- request: POST https://myhost/fmi/data/v1/databases/mydb/sessions
D, [2024-09-14T13:41:39.161078 #84751] DEBUG -- request: User-Agent: "fmrest-ruby/0.26.1 Faraday/2.9.0"
Content-Type: "application/json"
Authorization: "Basic dXNlcjphYmMxMjM="

pilaf avatar Sep 14 '24 04:09 pilaf

@pilaf Thank you for your cooperation!

gem versions

fmrest (0.24.0)
fmrest-core (= 0.24.0)
fmrest-rails (= 0.24.0)
fmrest-spyke (= 0.24.0)
fmrest-cloud (0.24.0)
aws-cognito-srp (>= 0.4.0)
fmrest-core (= 0.24.0)
fmrest-core (0.24.0)
faraday (>= 2.0)
faraday-multipart
fmrest-rails (0.24.0)
fmrest-core (= 0.24.0)
fmrest-spyke (0.24.0)
fmrest-core (= 0.24.0)
spyke (>= 7.0)
spyke (7.1.1)
activemodel (>= 4.0.0)
activesupport (>= 4.0.0)
addressable (>= 2.5.2)
faraday (>= 1.0.0, < 3.0)
faraday-multipart (~> 1.0)
faraday (2.7.10)
faraday-net_http (>= 2.0, < 3.1)
ruby2_keywords (>= 0.0.4)
faraday-multipart (1.0.4)
multipart-post (~> 2)
faraday-net_http (3.0.2)

FmRest Settings

# frozen_string_literal: true

# Use ActiveRecord token store
# FmRest.token_store = FmRest::TokenStore::ActiveRecord

# Use ActiveRecord token store with custom table name
# FmRest.token_store = FmRest::TokenStore::ActiveRecord.new(table_name: “my_token_store”)

# Use Redis token store (requires redis gem)
host = ENV.fetch('REDIS_HOST', nil)
port = ENV.fetch('REDIS_PORT', nil)
TOKEN_STORE_DB = 8
token_store_url = “redis://#{host}:#{port}/#{TOKEN_STORE_DB}」
FmRest.token_store = FmRest::TokenStore::Redis.new(url: token_store_url)

# Use a Redis token store with your own prefix
# FmRest.token_store = FmRest::TokenStore::Redis.new(prefix: “my-fmrest-token:”)

Use the Moneta token store (requires the moneta gem)
# FmRest.token_store = FmRest::TokenStore::Moneta.new(backend: )

Use the Memory token store (not suitable for production environments)
# FmRest.token_store = FmRest::TokenStore::Memory

FmRest.default_connection_settings = {
host: ENV.fetch('FILEMAKER_HOST_SAFTA', nil),
database: ENV.fetch('FILEMAKER_DB_SAFTA', nil),
username: ENV.fetch('CLARIS_ID', nil),
password: ENV.fetch('CLARIS_PASS', nil)
}

The result of running the template

D, [2024-09-21T17:07:29.829409 #85322] DEBUG -- request: POST <https://[REDACTED].account.filemaker-cloud.com/fmi/data/v1/databases/2023-08- 18%28[REDACTED]%E6%A7%98%20% E6%A4%9C%E8%A8%BC%E7%92%B0%E5%A2%83%EF%BC%89safta20220123/sessions>
D, [2024-09-21T17:07:29.830852 #85322] DEBUG -- request: User-Agent: “fmrest-ruby/0.26.1 Faraday/2.12.0”
Content-Type: “application/json”
Authorization: “FMID [REDACTED]
D, [2024-09-21T17:07:30.792095 #85322] DEBUG -- response: Status 200
D, [2024-09-21T17:07:30.792369 #85322] DEBUG -- response: server: “nginx」
Date: “Saturday, September 21, 2024 08:07:30 GMT”
Content-type: “application/json; charset=utf-8”
Content-length: “118”
Connection: “keep-alive”
Cache-control: “no-cache”
x-fm-data-access-token: “[REDACTED]”
etag: “W/\\”76-u/BD690s0Nf4XuydpBHsxpL95fg\\”
vary: “Accept-Encoding”
strict-transport-security: “max-age=31536000; includeSubDomains, max-age=31536000; includeSubDomains; preload”
x-frame-options: “SAMEORIGIN”
x-xss-protection: “1; mode=block”
x-content-type-options: “nosniff”
access-control-allow-origin: “ip-100-66-138-40”
access-control-allow-credentials: “True”
access-control-allow-headers: “Content-Type,Authorization”
D, [2024-09-21T17:07:30.800262 #85322] DEBUG -- response: {“response”=>{“token”=>“[REDACTED]”},
“messages“=>[{ ‘code’=>”0“, ‘message’=>”OK"}]}

D, [2024-09-21T17:07:30.800853 #85322] DEBUG -- request: GET <https://[REDACTED].account.filemaker-cloud.com/fmi/data/v1/databases/2023-08-18%28 [REDACTED]%E6%A7%98%20%E6%A4%9C%E 8%A8%BC%E7 %92%B0%E5%A2%83%EF%BC%89safta20220123/layouts/%E3%80%90 %E3%82%AB%E3%83%E3%80%90%E3%82%A8%E3%83%AB%E3%82%B8%E3%83%BC%E3%83%96%E3%83%AB%E3%82%B 9%E3%82%BF%E3%82%A4%E3%83%AB%E3%82%B9%E3%83%88%E3%82%A2%E3%83%AB%E3%82%B9%E3%82%BF%E3% 83%BC 3%82%AB%E3%83%BC%E3%83%89%E3%80%91A_%E5%8A%A0%E7%9B%9F%E6%A5%AD%E8%80%85/records?_limit=1>
D, [2024-09-21T17:07:30.800934 #85322] DEBUG -- request: User-Agent: “fmrest-ruby/0.26.1 Faraday/2.12.0”
Authorization: “Bearer 64546de60cf586ca9b4f94425155ed4db48cce57228a7b17cf28”

/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/spyke-7.2.2/lib/spyke/http.rb:55:in `rescue in send_request': Spyke::ConnectionError (Spyke::ConnectionError)
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/spyke-7.2.2/lib/spyke/http.rb:44:in `send_request'
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/spyke-7.2.2/lib/spyke/http.rb:24:in `block in request'
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/activesupport-7.2.1/lib/active_support/notifications.rb:212:in `instrument'
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/spyke-7.2.2/lib/spyke/http.rb:23:in `request'
from /Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/fmrest-spyke-0.26.1/lib/fmrest/spyke/model/http.rb:19:in `request'
from /Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/spyke-7.2.2/lib/spyke/http.rb:68:in `scoped_request'
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/spyke-7.2.2/lib/spyke/orm.rb:39:in `fetch'
from /Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/fmrest-spyke-0.26.1/lib/fmrest/spyke/model/orm.rb:63:in `fetch'
from /Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/spyke-7.2.2/lib/spyke/relation.rb:72:in `block in method_missing'
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/spyke-7.2.2/lib/spyke/relation.rb:81:in `scoping'
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/spyke-7.2.2/lib/spyke/relation.rb:72:in `method_missing'
from /Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/fmrest-spyke-0.26.1/lib/fmrest/spyke/relation.rb:379:in `find_one'
from /Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/fmrest-spyke-0.26.1/lib/fmrest/spyke/model/orm.rb:25:in `find_one'
from test.rb:22:in `<main>'
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/3.1.0/net/protocol.rb:219:in `rbuf_fill': Net::ReadTimeout with #<TCPSocket:(closed)> (Faraday::TimeoutError)
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/3.1.0/net/protocol.rb:193:in `readuntil'
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/3.1.0/net/protocol.rb:203:in `readline'
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/net-http-0.4.1/lib/net/http/response.rb:158:in `read_status_line'
from /Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/net-http-0.4.1/lib/net/http/response.rb:147:in `read_new'
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/net-http-0.4.1/lib/net/http.rb:2342:in `block in transport_request'
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/net-http-0.4.1/lib/net/http.rb:2333:in `catch'
from /Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/net-http-0.4.1/lib/net/http.rb:2333:in `transport_request'
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/net-http-0.4.1/lib/net/http.rb:2306:in `request'
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/faraday-net_http-3.3.0/lib/faraday/adapter/net_http.rb:112:in `block in request_with_wrapped_block'
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/net-http-0.4.1/lib/net/http.rb:1570:in `start'
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/faraday-net_http-3.3.0/lib/faraday/adapter/net_http.rb:111:in `request_with_wrapped_block'
from /Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/faraday-net_http-3.3.0/lib/faraday/adapter/net_http.rb:101:in `perform_request'
from /Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/faraday-net_http-3.3.0/lib/faraday/adapter/net_http.rb:65:in `block in call'
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/faraday-2.12.0/lib/faraday/adapter.rb:45:in `connection'
from /Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/faraday-net_http-3.3.0/lib/faraday/adapter/net_http.rb:64:in `call'
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/faraday-2.12.0/lib/faraday/middleware.rb:56:in `call'
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/faraday-2.12.0/lib/faraday/response/logger.rb:23:in `call'
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/faraday-2.12.0/lib/faraday/middleware.rb:56:in `call'
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/faraday-2.12.0/lib/faraday/middleware.rb:56:in `call'
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/faraday-2.12.0/lib/faraday/middleware.rb:56:in `call'
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/faraday-2.12.0/lib/faraday/middleware.rb:56:in `call'
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/faraday-multipart-1.0.4/lib/faraday/multipart/middleware.rb:28:in `call'
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/fmrest-core-0.26.1/lib/fmrest/v1/token_session.rb:33:in `call'
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/faraday-2.12.0/lib/faraday/middleware.rb:56:in `call'
from /Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/faraday-2.12.0/lib/faraday/rack_builder.rb:152:in `build_response'
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/faraday-2.12.0/lib/faraday/connection.rb:452:in `run_request'
from /Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/faraday-2.12.0/lib/faraday/connection.rb:200:in `get'
from /Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/spyke-7.2.2/lib/spyke/http.rb:45:in `send_request'
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/spyke-7.2.2/lib/spyke/http.rb:24:in `block in request'
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/activesupport-7.2.1/lib/active_support/notifications.rb:212:in `instrument'
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/spyke-7.2.2/lib/spyke/http.rb:23:in `request'
from /Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/fmrest-spyke-0.26.1/lib/fmrest/spyke/model/http.rb:19:in `request'
from /Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/spyke-7.2.2/lib/spyke/http.rb:68:in `scoped_request'
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/spyke-7.2.2/lib/spyke/orm.rb:39:in `fetch'
from /Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/fmrest-spyke-0.26.1/lib/fmrest/spyke/model/orm.rb:63:in `fetch'
from /Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/spyke-7.2.2/lib/spyke/relation.rb:72:in `block in method_missing'
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/spyke-7.2.2/lib/spyke/relation.rb:81:in `scoping'
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/spyke-7.2.2/lib/spyke/relation.rb:72:in `method_missing'
from /Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/fmrest-spyke-0.26.1/lib/fmrest/spyke/relation.rb:379:in `find_one'
from /Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/fmrest-spyke-0.26.1/lib/fmrest/spyke/model/orm.rb:25:in `find_one'
from test.rb:22:in `<main>'
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/3.1.0/net/protocol.rb:219:in `rbuf_fill': Net::ReadTimeout with #<TCPSocket:(closed)> (Net::ReadTimeout)
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/3.1.0/net/protocol.rb:193:in `readuntil'
from /Users/yudai/.rbenv/versions/3.1.2/lib/ruby/3.1.0/net/protocol.rb:203:in `readline'
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/net-http-0.4.1/lib/net/http/response.rb:158:in `read_status_line'
from /Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/net-http-0.4.1/lib/net/http/response.rb:147:in `read_new'
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/net-http-0.4.1/lib/net/http.rb:2342:in `block in transport_request'
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/net-http-0.4.1/lib/net/http.rb:2333:in `catch'
from /Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/net-http-0.4.1/lib/net/http.rb:2333:in `transport_request'
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/net-http-0.4.1/lib/net/http.rb:2306:in `request'
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/faraday-net_http-3.3.0/lib/faraday/adapter/net_http.rb:112:in `block in request_with_wrapped_block'
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/net-http-0.4.1/lib/net/http.rb:1570:in `start'
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/faraday-net_http-3.3.0/lib/faraday/adapter/net_http.rb:111:in `request_with_wrapped_block'
from /Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/faraday-net_http-3.3.0/lib/faraday/adapter/net_http.rb:101:in `perform_request'
from /Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/faraday-net_http-3.3.0/lib/faraday/adapter/net_http.rb:65:in `block in call'
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/faraday-2.12.0/lib/faraday/adapter.rb:45:in `connection'
from /Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/faraday-net_http-3.3.0/lib/faraday/adapter/net_http.rb:64:in `call'
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/faraday-2.12.0/lib/faraday/middleware.rb:56:in `call'
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/faraday-2.12.0/lib/faraday/response/logger.rb:23:in `call'
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/faraday-2.12.0/lib/faraday/middleware.rb:56:in `call'
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/faraday-2.12.0/lib/faraday/middleware.rb:56:in `call'
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/faraday-2.12.0/lib/faraday/middleware.rb:56:in `call'
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/faraday-2.12.0/lib/faraday/middleware.rb:56:in `call'
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/faraday-multipart-1.0.4/lib/faraday/multipart/middleware.rb:28:in `call'
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/fmrest-core-0.26.1/lib/fmrest/v1/token_session.rb:33:in `call'
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/faraday-2.12.0/lib/faraday/middleware.rb:56:in `call'
from /Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/faraday-2.12.0/lib/faraday/rack_builder.rb:152:in `build_response'
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/faraday-2.12.0/lib/faraday/connection.rb:452:in `run_request'
from /Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/faraday-2.12.0/lib/faraday/connection.rb:200:in `get'
from /Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/spyke-7.2.2/lib/spyke/http.rb:45:in `send_request'
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/spyke-7.2.2/lib/spyke/http.rb:24:in `block in request'
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/activesupport-7.2.1/lib/active_support/notifications.rb:212:in `instrument'
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/spyke-7.2.2/lib/spyke/http.rb:23:in `request'
from /Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/fmrest-spyke-0.26.1/lib/fmrest/spyke/model/http.rb:19:in `request'
from /Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/spyke-7.2.2/lib/spyke/http.rb:68:in `scoped_request'
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/spyke-7.2.2/lib/spyke/orm.rb:39:in `fetch'
from /Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/fmrest-spyke-0.26.1/lib/fmrest/spyke/model/orm.rb:63:in `fetch'
from /Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/spyke-7.2.2/lib/spyke/relation.rb:72:in `block in method_missing'
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/spyke-7.2.2/lib/spyke/relation.rb:81:in `scoping'
/Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/spyke-7.2.2/lib/spyke/relation.rb:72:in `method_missing'
from /Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/fmrest-spyke-0.26.1/lib/fmrest/spyke/relation.rb:379:in `find_one'
from /Users/yudai/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/fmrest-spyke-0.26.1/lib/fmrest/spyke/model/orm.rb:25:in `find_one'
from test.rb:22:in `<main>'

As a result of setting the log output to true in my application code

POST <https://[REDACTED].account.filemaker-cloud.com/fmi/data/v1/databases/2023-08-18%28[REDACTED]%E6%A7%98%20% E6%A4%9C%E8%A8%BC%E7%92%B0%E5%A2%83%EF%BC%89safta20220123/sessions>
User-Agent: “fmrest-ruby/0.24.0 Faraday/2.7.10”
Content-Type: “application/json”
Authorization: “FMID eyJraWQiOiIya1VScEpvaERlWjJiTGZsXC9CXC9ETjZVVkVMVXZlNUFpRHcwVlFoZ3Q4MFk9IiwiYWxnIjoiUlMyNTYifQ.eyJjdXN0b206Y291bnRyeSI6IkpQIiwic3ViIjo iYzg 5YjE2YTAtMWFjOS00ZTU0LWJkMjgtNGExZjY5Y2YyZDZhIiwiZW1haWxfdmVyaWZpZWQiOnRydWUsImlzcyI6Imh0dHBzOlwvXC9jb2duaXRvLWlkcC51cy13ZXN0LTIuYW1hem9 uYX dz LmNvbVwvdXMtd2VzdC0yX05xa3VaY1hRWSIsInBob25lX251bWJlcl92ZXJpZmllZCI6ZmFsc2UsImN1c3RvbTpwcml2YWN5IjoiMSIsImNvZ25pdG86dXNlcm5hbWU iOi J j ODliMTZhMC0xYWM5LTRlNTQtYmQyOC00YTFmNjljZjJkNmEiLCJnaXZlbl9uYW1lIjoi6ZuE5aSnIiwibG9jYWxlIjoiamEtSlAiLCJvcmlnaW5fanRpIjoiYzIxMTVjNzYtMm JlZS0 0 MGVlLTgzODItNjM4MjU2NmY4MGI3IiwiYXVkIjoiNGw5cnZsNG12NWVzMWVlcDFxZTk3Y2F1dG4iLCJjdXN0b206bWFuYWdlZGJ5IjoiYWRhNTA5NGYtMTI3ZC00Z jM3LT xNWQtZWIyYjNjOGExYmU3IiwiZXZlbnRfaWQiOiJiNjdjMzc2ZC00ZGFiLTQ5MzAtOGE4My0zOTliNTBhYTM2Y2EiLCJ0b2tlbl91c2UiOiJpZCIsImF1dGhfdGltZSI 6MTcyN jg0MDA1NiwiZXhwIjoxNzI2OTA3MTU1LCJpYXQiOjE3MjY5MDM1NTUsImZhbWlseV9uYW1lIjoi6YeO55SwIiwianRpIjoiMzYzYmNmYzAtOWM1My00NGZmLTkyOTYtZDUw NDUx MW MwMjAyIiwiZW1haWwiOiJ5dWRhaW5vZGExOTkyQGdtYWlsLmNvbSJ9.Y65NH_PqvL19ulykmUOopuyzKag8Y7Lg9KgwPBLo8rZYDis1r-wALGLyCWVtpMgmC5WgTsx2ULqRCkvqYl 3 uIK5yZjemDZfdmRvOPUDghhqoSNIn-KSsHz2Xwq3z7HvgPP_4-LP8g33y8BkCWWL-pU-nu_skjT9k0rw1E7T5C0v6JuuIoPTAVMd-9QEjzowffTxmw32eOBroCw4ivY7 1RXS8RM6_AKNAUGmkPz7QssTHIhzdtdqqCyUdljy5cD_fzKUzcO7CXK2v64a2IilHaHbg8W5u09Ok1j4JCRA2-6RxS3LxdtutAle9Lq_PhdTQSDqJ7SUcF7Vn6xKcyQ3j4w」
Status: 200
Server: “nginx”
Date: “Saturday, September 21, 2024 07:58:19 GMT”
Content-Type: “application/json; charset=utf-8”
Content-Length: “118”
Connection: “keep-alive”
Cache-Control: “no-cache”
x-fm-data-access-token: “[REDACTED]”
etag: “W/\\”76-agnPBBjFgg/LSSflmxfymNWTnik\\” ”
vary: “Accept-Encoding”
strict-transport-security: “max-age=31536000; includeSubDomains, max-age=31536000; includeSubDomains; preload”
x-frame-options: “SAMEORIGIN”
x-xss-protection: “1; mode=block”
x-content-type-options: “nosniff”
access-control-allow-origin: “ip-100-66-138-40”
access-control-allow-credentials: “True”
access-control-allow-headers: “Content-Type,Authorization”
{“response”=>{“token”=>“[REDACTED]”},
“messages”=>[{“code”=>“0”, “message”=>“OK”}]}

---

POST <https://[REDACTED].account.filemaker-cloud.com/fmi/data/v1/databases/2023-08-18%28[REDACTED]%E6%A7%98%20%E6%A4%9C%E8%A 8%E7%92%B0%E5%A2%83%EF%BC%89safta20220123/layouts/%E3%80%90%E3%82%AB%E3%83%E3%8 2%B3%E3%83%BC%E3%83%89%E3%80%91A_%E5%8A%A0%E7%9B%9F%E6%A5%AD%E8%80%85/_find>
User-Agent: “fmrest-ruby/0.24.0 Faraday/2.7.10”
Authorization: “Bearer 49d593e979b8ee0cc18375282c48541d8b111af5634102f600c2”
Content-Type: “application/json”
{“limit”:1,“query”:[{“vendor_id”:“SAF006594”}]}
Spyke (60964.4ms) POST []
Spyke::ConnectionError
Completed 500 Internal Server Error in 61024ms (Views: 0.8ms | ActiveRecord: 28.3ms | Spyke: 60964.4ms | Allocations: 8244)

Notes

  • There are times when it succeeds about once every five attempts, and SpykeConnection::Error does not occur for requests immediately after a successful attempt.The conditions for success and failure are unknown.
Status: 200
Server: “nginx”
Date: “Sat, 21 Sep 2024 07:34:53 GMT”
Content-Type: “application/json; charset=utf-8”
Content-Length: “696”
Connection: “keep-alive”
Cache-Control: “no-cache”
etag: “W/\\”2b8-uHaJqnpNb77DqOfIeARj35d7aTA\\"
vary: ‘Accept-Encoding’
strict-transport-security: ”max-age=31536000; includeSubDomains, max-age=31536000; includeSubDomains; preload”
x-frame-options: “SAMEORIGIN”
x-xss-protection: “1; mode=block”
x-content-type-options: “nosniff”
access-control-allow-origin: “ip-100-66-138-40”
access-control-allow-credentials: “True
access-control-allow-headers: ‘Content-Type,Authorization
{ ’response” : { “dataInfo” : { “database” : “2023-08-18 ([REDACTED] verification environment) safta20220123”, “layout” : ” Notice”, ‘table’: ‘Notice’, ‘totalRecordCount’: 24, ‘foundCount’: 1, ‘returnedCount’: 1}, ‘data’: [{ ‘field’: ”The confirmation of the information we received from you is complete. You can now use the service. We will introduce you to customers in turn, so please wait a little longer. “,”Announcement target“:”SAF006594“,”Announcement date“]},”messages“:[{”code“:”0“,”message“:”OK"}]}
Spike (133.5ms) POST <https://[REDACTED].account.filemaker-cloud.com/fmi/data/v1/databases/2023-08-18%28[REDACTED]%E6%A7%98%20%E6%A4%9C%E8%A8%BC% E7%92%B0%E5%A2%83%EF%BC%89safta20220123/layouts/%E3%81%8A%E7%9F%A5%E3%82%89%E3%81%9B/_find> [200]
Contractor Load (0.5ms) SELECT “contractors”.* FROM “contractors” WHERE “contractors”.“id” = $1 LIMIT $2 [[“id”, 2], [“LIMIT”, 1]]
Completed 200 OK in 386ms (Views: 0.2ms | ActiveRecord: 1.3ms | Spyke: 378.7ms | Allocations: 18459)
  • If you get a SpykeConnection::Error, try making the request with PostMan and it should work

YudaiNoda3576 avatar Sep 21 '24 08:09 YudaiNoda3576

Hi @YudaiNoda3576,

thank you for the additional details. I have edited your comment to remove potentially sensitive information (auth tokens, etc).

Looking at your logs, this stands out:

[...]ruby/3.1.0/net/protocol.rb:219:in `rbuf_fill': Net::ReadTimeout with #<TCPSocket:(closed)> (Net::ReadTimeout)

Which shows there was a network timeout when trying to read an API response.

Since you're using the default faraday-net_http adapter, here's the relevant documentation about Net::HTTP's timeout:

https://docs.ruby-lang.org/en/master/Net/HTTP.html#method-i-read_timeout-3D

read_timeout=(sec) Sets the read timeout, in seconds, for self to integer sec; the initial value is 60.

So unless you've changed the timeout value, it should be waiting for 60 seconds before timing out and throwing that error. Does that match what you see?

This sounds to me like either a network problem, or an API request that takes too long to complete. You can try increasing the timeout time to see if that prevents the error, although if you have a request that takes longer than 60 seconds to complete you should consider that a problem to debug (that would be outside the scope of fmrest-ruby).

To change the timeout value you can use this syntax:

class ApplicationFmRest < FmRest::Spyke::Base
  faraday do |conn|
    conn.options.timeout = 120 # seconds
  end
end

☝️ I recommend that you put that in a class from which all your fmrest layout models inherit, so that they all share the same timeout setting.

pilaf avatar Sep 30 '24 00:09 pilaf

@pilaf Thanks for the answer!

I changed the Timeout setting to 120 seconds as you suggested, but the error reappeared.

  • my code
# frozen_string_literal: true

module Safta::Connectable
  extend ActiveSupport::Concern

  included do
    self.fmrest_config = {
      host: ENV.fetch('FILEMAKER_HOST_SAFTA', nil),
      database: ENV.fetch('FILEMAKER_DB_SAFTA', nil),
      username: ENV.fetch('CLARIS_ID', nil),
      password: ENV.fetch('CLARIS_PASS', nil),
      log: true
    }

    faraday do |conn|
      conn.options.timeout = 120 # seconds
    end
  end
end
  • error logs
Processing by Auth::RegistrationController#create as */*
  Parameters: {"contractor_id"=>"SAF006594", "password_confirmation"=>"[FILTERED]", "management_company"=>"safta", "password"=>"[FILTERED]", "email"=>"[email protected]", "exist"=>true, "registered_step"=>"authorized", "confirm_success_url"=>"https://www.google.com/", "registration"=>{"contractor_id"=>"SAF006594", "password_confirmation"=>"[FILTERED]", "management_company"=>"safta", "password"=>"[FILTERED]", "email"=>"[email protected]", "exist"=>true, "registered_step"=>"authorized", "confirm_success_url"=>"https://www.google.com/"}}
Unpermitted parameter: :confirm_success_url. Context: { controller: Auth::RegistrationController, action: create, request: #<ActionDispatch::Request:0x0000ffffae82df30>, params: {"contractor_id"=>"SAF006594", "password_confirmation"=>"[FILTERED]", "management_company"=>"safta", "password"=>"[FILTERED]", "email"=>"[email protected]", "exist"=>true, "registered_step"=>"authorized", "confirm_success_url"=>"https://www.google.com/", "controller"=>"auth/registration", "action"=>"create", "registration"=>{"contractor_id"=>"SAF006594", "password_confirmation"=>"[FILTERED]", "management_company"=>"safta", "password"=>"[FILTERED]", "email"=>"[email protected]", "exist"=>true, "registered_step"=>"authorized", "confirm_success_url"=>"https://www.google.com/"}} }
Unpermitted parameter: :confirm_success_url. Context: { controller: Auth::RegistrationController, action: create, request: #<ActionDispatch::Request:0x0000ffffae82df30>, params: {"contractor_id"=>"SAF006594", "password_confirmation"=>"[FILTERED]", "management_company"=>"safta", "password"=>"[FILTERED]", "email"=>"[email protected]", "exist"=>true, "registered_step"=>"authorized", "confirm_success_url"=>"https://www.google.com/", "controller"=>"auth/registration", "action"=>"create", "registration"=>{"contractor_id"=>"SAF006594", "password_confirmation"=>"[FILTERED]", "management_company"=>"safta", "password"=>"[FILTERED]", "email"=>"[email protected]", "exist"=>true, "registered_step"=>"authorized", "confirm_success_url"=>"https://www.google.com/"}} }
Unpermitted parameter: :confirm_success_url. Context: { controller: Auth::RegistrationController, action: create, request: #<ActionDispatch::Request:0x0000ffffae82df30>, params: {"contractor_id"=>"SAF006594", "password_confirmation"=>"[FILTERED]", "management_company"=>"safta", "password"=>"[FILTERED]", "email"=>"[email protected]", "exist"=>true, "registered_step"=>"authorized", "confirm_success_url"=>"https://www.google.com/", "controller"=>"auth/registration", "action"=>"create", "registration"=>{"contractor_id"=>"SAF006594", "password_confirmation"=>"[FILTERED]", "management_company"=>"safta", "password"=>"[FILTERED]", "email"=>"[email protected]", "exist"=>true, "registered_step"=>"authorized", "confirm_success_url"=>"https://www.google.com/"}} }
Unpermitted parameter: :confirm_success_url. Context: { controller: Auth::RegistrationController, action: create, request: #<ActionDispatch::Request:0x0000ffffae82df30>, params: {"contractor_id"=>"SAF006594", "password_confirmation"=>"[FILTERED]", "management_company"=>"safta", "password"=>"[FILTERED]", "email"=>"[email protected]", "exist"=>true, "registered_step"=>"authorized", "confirm_success_url"=>"https://www.google.com/", "controller"=>"auth/registration", "action"=>"create", "registration"=>{"contractor_id"=>"SAF006594", "password_confirmation"=>"[FILTERED]", "management_company"=>"safta", "password"=>"[FILTERED]", "email"=>"[email protected]", "exist"=>true, "registered_step"=>"authorized", "confirm_success_url"=>"https://www.google.com/"}} }
POST https://raisetech.account.filemaker-cloud.com/fmi/data/v1/databases/2023-08-18%28RaiseTech%E6%A7%98%20%E6%A4%9C%E8%A8%BC%E7%92%B0%E5%A2%83%EF%BC%89safta20220123/sessions
User-Agent: "fmrest-ruby/0.24.0 Faraday/2.7.10"
Content-Type: "application/json"
Authorization: "FMID *****************"
Status 200
server: "nginx"
date: "Mon, 30 Sep 2024 10:02:43 GMT"
content-type: "application/json; charset=utf-8"
content-length: "118"
connection: "keep-alive"
cache-control: "no-cache"
x-fm-data-access-token: "756bb**************"
etag: "W/\"76-CDmbQ6aVL8AnGGOSmd1X9SPmUBU\""
vary: "Accept-Encoding"
strict-transport-security: "max-age=31536000; includeSubDomains, max-age=31536000; includeSubDomains; preload"
x-frame-options: "SAMEORIGIN"
x-xss-protection: "1; mode=block"
x-content-type-options: "nosniff"
access-control-allow-origin: "ip-100-66-138-40"
access-control-allow-credentials: "True"
access-control-allow-headers: "Content-Type,Authorization"
{"response"=>{"token"=>"756**********"},
 "messages"=>[{"code"=>"0", "message"=>"OK"}]}

POST https://raisetech.account.filemaker-cloud.com/fmi/data/v1/databases/2023-08-18%28RaiseTech%E6%A7%98%20%E6%A4%9C%E8%A8%BC%E7%92%B0%E5%A2%83%EF%BC%89safta20220123/layouts/%E3%80%90%E3%82%AB%E3%83%BC%E3%83%89%E3%80%91A_%E5%8A%A0%E7%9B%9F%E6%A5%AD%E8%80%85/_find
User-Agent: "fmrest-ruby/0.24.0 Faraday/2.7.10"
Authorization: "Bearer *********"
Content-Type: "application/json"
{"limit":1,"query":[{"業者ID":"***********"}]}

  Spyke (123704.8ms)  POST  []
Completed 422 Unprocessable Entity in 124002ms (Views: 3.2ms | ActiveRecord: 0.0ms | Spyke: 123704.8ms | Allocations: 476110)

After this error occurred, I made a request to the _find endpoint in Postman with the FMID token set that I was able to get from this request, and the response came back fine. It took a few seconds for the response to come back.

Also, the possible network issue is occurring in other developers' environments besides mine. This problem also occurs in the local environment and on the server. And I have confirmed that the same problem occurs when I switch FM servers.

Is this problem not occurring in your environment?

YudaiNoda3576 avatar Sep 30 '24 10:09 YudaiNoda3576

Hi @YudaiNoda3576 ,

Is this problem not occurring in your environment?

No, we use the gem in various systems but never had problems like the ones you're having.

I still have no idea what the source of your errors is, but I have a few things I'd like to comment on:

  1. Looking more closely at your logs I noticed that the timeout error only happened in the example you made using my script template, but in your own app's logs the errors seem different, a 422 (Unprocessable Entity) in one, and 500 (Internal Server Error) in another one. This is confusing because I can't know if you're having a single problem or 3 different ones. Which error do you get more often? Is it always randomly one of those 3?
  2. Your app is using some outdated gem versions, especially fmrest, spyke, faraday and faraday-net_http. Would you be able to update those gems and see if that changes your results in any way?
  3. Since your FileMaker database is in Japanese, I wonder if that may have to do with the errors you're seeing. I have never worked with a database in Japanese, so if there's a bug in the fmrest gem related to it it's possible that I never encountered it. Do you find any pattern between the errors you get and the presence of Japanese characters in the requests? For example, the query {"limit":1,"query":[{"業者ID":"***"}]}, does it fail the same way if the query part is empty?
  4. Something else you could try is using a different Faraday adapter, in case this is a problem with Net::HTTP. For example, httpx. You can install the gem and set the default Faraday adapter with Faraday.default_adapter = :httpx (docs)

pilaf avatar Oct 01 '24 12:10 pilaf

Hi @YudaiNoda3576, were you able to make progress with this? Unfortunately unless I have a reproducible bug I will have to close this issue.

pilaf avatar Oct 18 '24 02:10 pilaf

@pilaf Sorry for the late reply. As far as I have been able to verify, I get frequent 500 errors, which are always Spyke::ConnectionError. Also, when I changed the Filemaker database name, etc. to English characters and sent the request, the same Spyke::ConnectionError occurred, so it didn't seem to matter if it was Japanese or not.

What we know now is that when we send a request to FileMakerServer, the sessions endpoint log is output in a few seconds, but subsequent endpoint calls, such as _find, are logged after about 3 minutes. As a result, I am currently getting the following error

  Spyke (60426.0ms)  POST  []
Spyke::ConnectionError: Spyke::ConnectionError
from /usr/local/bundle/gems/spyke-7.1.1/lib/spyke/http.rb:55:in `rescue in send_request'
Caused by Faraday::TimeoutError: Net::ReadTimeout with #<TCPSocket:(closed)>
from /usr/local/lib/ruby/3.2.0/net/protocol.rb:229:in `rbuf_fill'
Caused by Net::ReadTimeout: Net::ReadTimeout
from /usr/local/lib/ruby/3.2.0/net/protocol.rb:229:in `rbuf_fill'

Also, I have changed the read_timeout setting of Faraday below, but the error has not changed, so I am beginning to think that it may be that DNS name resolution is taking time.

In summary, the cause of this error is more likely to be a communication problem between me and FMServer than a bug in the gem, so you can close this issue.

Thank you for your kind attention. Thanks to you, I got a lot of hints. I appreciate it.

YudaiNoda3576 avatar Oct 30 '24 09:10 YudaiNoda3576

@YudaiNoda3576 Thank you for the update, I will close the issue now. I hope you find the root of the problem, but if you discover that it's a bug in the gem please reopen this issue (or create a new one).

By the way, if by chance you're attending the Clarisカンファレンス2024 in Tokyo, I will be there on November 14th at the Beezwax booth, you can ask for Pedro.

pilaf avatar Oct 30 '24 15:10 pilaf

@pilaf Thank you very much.

Thanks for the great guidance! However, I will not be able to attend that day and would like to participate when I get the chance. I look forward to meeting you someday.

YudaiNoda3576 avatar Oct 31 '24 14:10 YudaiNoda3576