Timeout

[voronchuk]

Timeout

[Voronchuk]

As ad-hoc solution, you can try timeout option in scope of #24

[Voronchuk]

I guess both can be useful, I'll see what can be done about it.

[vpfaulkner]

@Voronchuk any ideas / updates on this? As a fallback I might just catch / retry but certainly not ideal solution.

[nekifirus]

Hello! Any ideas?

[Voronchuk]

@vpfaulkner @nekifirus try to install the master version {:elixir_google_spreadsheets, github: "Voronchuk/elixir_google_spreadsheets"} make read_rows with batch_range: true option (it's disabled by default).

Also I added support for request config options, defaults are:

request_opts: [
        ssl: [{:versions, [:'tlsv1.2']}],
        timeout: :timer.seconds(8),
        recv_timeout: :timer.seconds(5)
    ]

[nekifirus]

Yeah! In our case

-  max_interval: :timer.minutes(100),
-  interval: :timer.minutes(100)
+  max_interval: :timer.seconds(5),
+  interval: 100

[Voronchuk]

@vpfaulkner have you tried batch_range: true?

[vpfaulkner]

@Voronchuk let me try that...

[seddy]

@vpfaulkner - did batch_range: true work for you?

I'm wondering because we're hitting a similar issue on write_rows, even though we've tried upping the recv_timeout.

I'm not sure I understand how having a longer timeout on the http requests is going to help if the GenServer.call still times out at 5s still @Voronchuk; won't we always hit that 5s timeout regardless of http timeout? I may well be misunderstanding how GenServer behaves though, I'm assuming it would timeout if the http takes longer than its timeout.

[vpfaulkner]

@seddy and @Voronchuk we are still running into the same issue even after using batch_range: true.

For full context here is our call:

   GSS.Spreadsheet.read_rows(pid, @legend_row, @ending_row, column_to: @ending_column, batch_range: true)

Once more, after we made an update to the config we started to get the following error in staging:

no function clause matches

gen.erl:150 :in `call`
lib/gen_server.ex:734 :in `call`
lib/elixir_google_spreadsheets/spreadsheet.ex:450 :in `spreadsheet_query`
lib/elixir_google_spreadsheets/spreadsheet.ex:353 :in `handle_call`
gen_server.erl:615 :in `try_handle_call`
gen_server.erl:647 :in `handle_msg`
proc_lib.erl:247 :in `init_p_do_apply`

Here is the dependency:

      {:elixir_google_spreadsheets, github: "Voronchuk/elixir_google_spreadsheets"},

Here is the config:

config :elixir_google_spreadsheets, :client,
  request_workers: 50,
  max_demand: 100,
  max_interval: :timer.minutes(1),
  interval: 100,
  request_opts: [
    timeout: :timer.seconds(60),
    recv_timeout: :timer.seconds(30)
  ]

Concerning your comment @seddy, I naively assumed that this changed the GenServer timeout if recv_timeout was set: https://hexdocs.pm/elixir/GenServer.html#call/3. If that time out is not being changed, then it would seem that having a higher http timeout would not matter.

[Voronchuk]

I'll take a look on weekend, thanks for an update.

[vpfaulkner]

@Voronchuk any update?

[Voronchuk]

sorry, I'm currently busy with other stuff, will try to look on Friday / weekend.

[seddy]

Sorry to pester @Voronchuk - any update? This is causing a reasonable number of errors for us so I'm happy to do a PR which will allow us to set the Genserver timeout appropriately if that helps?

[vpfaulkner]

@seddy same here. If you already have an idea for what the fix might look like, would you mind opening that PR? We might need to use a forked version that has a fix in it if this doesn't get resolved soon.

[Voronchuk]

batch_range: true is an experimental feature which works only for read_rows, it's not related to writes in any way.

@vpfaulkner can you show Google API url which was generated for your request? In my env batch_range: true works for read_rows.

[Voronchuk]

I @vpfaulkner @seddy have added test for this case and got the following query:
14:11:44.712 [debug] send_request https://sheets.googleapis.com/v4/spreadsheets/XXXX/values:batchGet?majorDimension=ROWS&valueRenderOption=FORMATTED_VALUE&dateTimeRenderOption=FORMATTED_STRING&ranges=A2%3AZ250

It works as intended, request looks like GSS.Spreadsheet.read_rows(pid, 2, 250, column_to: 26, batch_range: true)

[Voronchuk]

As for the custom timeout, they are already supported by :result_timeout setting.

case options[:result_timeout] || config(:result_timeout) do
          nil ->
            GenStage.call(__MODULE__, {:request, request})
          result_timeout ->
            GenStage.call(__MODULE__, {:request, request}, result_timeout)
        end

[Voronchuk]

Also, keep in mind the new default config setting max_rows_per_request:

config :elixir_google_spreadsheets,
    max_rows_per_request: 301

[vpfaulkner]

@Voronchuk sorry for the late reply. I think the batch_range: true is working as expected from what I can tell in the URL. I also have result_timeout set: result_timeout: :timer.minutes(10). However, the error I keep seeing (see below) continues to occur 5 seconds after the job begins and shows the GenServer default timeout of 5 seconds. I'm confused how result_timeout could increase the GenServer timeout and that appears to be the timeout causing this issue. It appears that the GenServer call is here: https://github.com/Voronchuk/elixir_google_spreadsheets/blob/master/lib/elixir_google_spreadsheets/spreadsheet.ex#L123 and no third argument is passed for the timeout.

Apr 16 11:00:00 ingredient-planner-production web-10.53.44.9: 11:00:00.348 [info] Importing protein assignments... 
Apr 16 11:00:05 ingredient-planner-production web-10.53.44.9: 11:00:05.351 [error] Task #PID<0.31038.5> started from Quantum terminating 
Apr 16 11:00:05 ingredient-planner-production web-10.53.44.9: ** (EXIT) time out 
Apr 16 11:00:05 ingredient-planner-production web-10.53.44.9: ** (stop) exited in: GenServer.call(#PID<0.31040.5>, {:read_rows, 2, 250, [column_to: 26, batch_range: true]}, 5000) 
Apr 16 11:00:05 ingredient-planner-production web-10.53.44.9: (elixir) lib/gen_server.ex:737: GenServer.call/3 
Apr 16 11:00:05 ingredient-planner-production web-10.53.44.9: (ingredient_planner) lib/ingredient_planner/import_protein_assignments.ex:21: IngredientPlanner.ImportProteinAssignments.run/0 
Apr 16 11:00:05 ingredient-planner-production web-10.53.44.9: (elixir) lib/task/supervised.ex:85: Task.Supervised.do_apply/2 
Apr 16 11:00:05 ingredient-planner-production web-10.53.44.9: (stdlib) proc_lib.erl:247: :proc_lib.init_p_do_apply/3 
Apr 16 11:00:05 ingredient-planner-production web-10.53.44.9: (elixir) lib/task/supervised.ex:36: Task.Supervised.reply/5 
Apr 16 11:00:05 ingredient-planner-production web-10.53.44.9: Function: &Quantum.Executor.execute/2 
Apr 16 11:00:05 ingredient-planner-production web-10.53.44.9: Args: [{"0 * * * *", {IngredientPlanner.ImportProteinAssignments, :run}, [], :utc}, %{d: {2018, 4, 16}, h: 11, jobs: [import_proteins: %Quantum.Job{args: [], name: :import_proteins, nodes: [:nonode@nohost], overlap: true, pid: #PID<0.31027.5>, schedule: "0 * * * *", state: :active, task: {IngredientPlanner.ImportProteinAssignments, :run}, timezone: :utc}, send_daily_digest: %Quantum.Job{args: [], name: :send_daily_digest, nodes: [:nonode@nohost], overlap: true, pid: #PID<0.31028.5>, schedule: "0 9 * * *", state: :active, task: {IngredientPlanner.SendDailyDigestJob, :send_daily_digest}, timezone: :utc}, update_recipe_forecasts: %Quantum.Job{args: [], name: :update_recipe_forecasts, nodes: [:nonode@nohost], overlap: true, pid: #PID<0.31029.5>, schedule: "0 7 * * *", state: :active, task: {IngredientPlanner.UpdateRecipeForecasts, :update}, timezone: :utc}], m: 0, r: 0, w: 1}] 

[Voronchuk]

Finally I got your issue @vpfaulkner I think it should be solved not with GenServer timeout increase but with async Task response, some work for this was done in scope of request_async but was never finished, I'll think how to implement this in a better way.

[vpfaulkner]

@Voronchuk testing the timeout option in staging...

[vpfaulkner]

@Voronchuk sorry, forgot to reply, but it works. Thanks!