Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

ERL-253: httpc session update error #3499

Closed
OTP-Maintainer opened this issue Sep 15, 2016 · 9 comments
Closed

ERL-253: httpc session update error #3499

OTP-Maintainer opened this issue Sep 15, 2016 · 9 comments
Assignees
@IngelaAndin
Labels
bug Issue is reported as a bug priority:medium team:PS Assigned to OTP team PS
Milestone
OTP-19.2

Comments

@OTP-Maintainer
Copy link

Original reporter: ericmj
Affected version: OTP-19.0
Fixed in version: OTP-19.2
Component: inets
Migrated from: https://bugs.erlang.org/browse/ERL-253

There seems to be a race condition when updating the session in httpc. It's hard to reproduce since the error does not show up often, it happens when installing Rebar or Hex in Elixir with `mix local.rebar --force` or `mix local.hex --force`. All http requests complete successfully, the issue only shows up because of the error messages in the terminal.

I think it happens when trying to update the session while the httpc manager is shutting down / has shut down because it only happens at the very end of the command. 


{noformat}
18:41:13.254 [error] Failed updating session:
       ProfileName: :httpc_mix
       SessionId:   {{'repo.hex.pm', 443}, #PID<0.113.0>}
       Pos:         7
       Value:       0
       when
       Session (db) info: :undefined
       Session (db):      {:session, {{'repo.hex.pm', 443}, #PID<0.113.0>}, false, :https,
       {:sslsocket, {:gen_tcp, #Port<0.4608>, :tls_connection, :undefined},
       #PID<0.114.0>}, {:essl, []}, 1, :keep_alive, true}
       Session (record):  {:EXIT,
       {:badarg,
       [{:ets, :lookup,
       [:httpc_mix__session_db, {{'repo.hex.pm', 443}, #PID<0.113.0>}], []},
       {:httpc_manager, :lookup_session, 2, [file: 'httpc_manager.erl', line: 189]},
       {:httpc_handler, :update_session, 4,
       [file: 'httpc_handler.erl', line: 1909]},
       {:httpc_handler, :handle_empty_queue, 4,
       [file: 'httpc_handler.erl', line: 1368]},
       {:httpc_handler, :handle_info, 2, [file: 'httpc_handler.erl', line: 471]},
       {:gen_server, :try_dispatch, 4, [file: 'gen_server.erl', line: 601]},
       {:gen_server, :handle_msg, 5, [file: 'gen_server.erl', line: 667]},
       {:proc_lib, :init_p_do_apply, 3, [file: 'proc_lib.erl', line: 247]}]}}
       T: :error
       E: :badarg

       18:41:13.259 [error] Failed updating session:
       ProfileName: :httpc_mix
       SessionId:   {{'repo.hex.pm', 443}, #PID<0.113.0>}
       Pos:         9
       Value:       true
       when
       Session (db) info: :undefined
       Session (db):      {:session, {{'repo.hex.pm', 443}, #PID<0.113.0>}, false, :https,
       {:sslsocket, {:gen_tcp, #Port<0.4608>, :tls_connection, :undefined},
       #PID<0.114.0>}, {:essl, []}, 1, :keep_alive, false}
       Session (record):  {:EXIT,
       {:badarg,
       [{:ets, :lookup,
       [:httpc_mix__session_db, {{'repo.hex.pm', 443}, #PID<0.113.0>}], []},
       {:httpc_manager, :lookup_session, 2, [file: 'httpc_manager.erl', line: 189]},
       {:httpc_handler, :update_session, 4,
       [file: 'httpc_handler.erl', line: 1909]},
       {:httpc_handler, :maybe_make_session_available, 2,
       [file: 'httpc_handler.erl', line: 1516]},
       {:httpc_handler, :answer_request, 3,
       [file: 'httpc_handler.erl', line: 1507]},
       {:httpc_handler, :terminate, 2, [file: 'httpc_handler.erl', line: 759]},
       {:gen_server, :try_terminate, 3, [file: 'gen_server.erl', line: 629]},
       {:gen_server, :terminate, 7, [file: 'gen_server.erl', line: 795]}]}}
       T: :error
       E: :badarg

       18:41:13.286 [error] GenServer #PID<0.113.0> terminating
       ** (stop) {:failed_updating_session, [profile: :httpc_mix, session_id: {{'repo.hex.pm', 443}, #PID<0.113.0>}, pos: 9, value: true, etype: :error, error: :badarg, stacktrace: [{:ets, :update_element, [:httpc_mix__session_db, {{'repo.hex.pm', 443}, #PID<0.113.0>}, {9, true}], []}, {:httpc_manager, :update_session, 4, [file: 'httpc_manager.erl', line: 210]}, {:httpc_handler, :update_session, 4, [file: 'httpc_handler.erl', line: 1887]}, {:httpc_handler, :maybe_make_session_available, 2, [file: 'httpc_handler.erl', line: 1516]}, {:httpc_handler, :answer_request, 3, [file: 'httpc_handler.erl', line: 1507]}, {:httpc_handler, :terminate, 2, [file: 'httpc_handler.erl', line: 759]}, {:gen_server, :try_terminate, 3, [file: 'gen_server.erl', line: 629]}, {:gen_server, :terminate, 7, [file: 'gen_server.erl', line: 795]}]]}
       (inets) httpc_handler.erl:1911: :httpc_handler.update_session/4
       (inets) httpc_handler.erl:1516: :httpc_handler.maybe_make_session_available/2
       (inets) httpc_handler.erl:1507: :httpc_handler.answer_request/3
       (inets) httpc_handler.erl:759: :httpc_handler.terminate/2
       (stdlib) gen_server.erl:629: :gen_server.try_terminate/3
       (stdlib) gen_server.erl:795: :gen_server.terminate/7
       (stdlib) proc_lib.erl:247: :proc_lib.init_p_do_apply/3
       Last message: {:ssl, {:sslsocket, {:gen_tcp, #Port<0.4608>, :tls_connection, :undefined}, #PID<0.114.0>}, <<233, 251, 153, 0, 82, 93, 50, 60, 58, 0, 128, 5, 239, 47, 63, 133, 71, 133, 103, 240, 196, 73, 237, 239, 91, 119, 46, 250, 122, 120, 246, 182, 250, 120, 150, 22, 102, 206, 207, 177, 139, 223, 233, 74, 246, 227, 27, 63, ...>>}
       State: {:state, {:request, #Reference<0.0.1.196>, #PID<0.71.0>, 0, :https, {'repo.hex.pm', 443}, '/installs/1.3.0/hex-0.13.0.ez', [], :get, {:http_request_h, :undefined, 'keep-alive', :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, 'repo.hex.pm', :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, [], 'Mix/1.3.2', :undefined, :undefined, :undefined, '0', :undefined, :undefined, :undefined, :undefined, :undefined, ...}, {[], []}, {:http_options, 'HTTP/1.1', :infinity, true, {:essl, []}, :undefined, true, :infinity, false}, 'https://repo.hex.pm/installs/1.3.0/hex-0.13.0.ez', [], :none, [], 1470076873124, :undefined, :undefined, false}, {:session, {{'repo.hex.pm', 443}, #PID<0.113.0>}, false, :https, {:sslsocket, {:gen_tcp, #Port<0.4608>, :tls_connection, :undefined}, #PID<0.114.0>}, {:essl, []}, 1, :keep_alive, false}, {'HTTP/1.1', 200, 'OK'}, {:http_response_h, 'public, max-age=604800', 'keep-alive', 'Mon, 01 Aug 2016 18:41:13 GMT', :undefined, :undefined, :undefined, :undefined, '1.1 varnish', :undefined, 'bytes', '156864', '"001b2fb3d69b3d93616ac0241b5610aa"', :undefined, :undefined, :undefined, 'AmazonS3', :undefined, :undefined, :undefined, :undefined, :undefined, '372935', :undefined, :undefined, :undefined, 'application/andrew-inset', :undefined, 'Sat, 30 Jul 2016 23:05:49 GMT', [{'x-amz-id-2', '35bqzJpDJSMCfFdtmtw93YpKVHwWjgAASzWdolYr0E1vUvmmgJAZNy2SSdeg3zJVo0B0S0Z7/6I='}, {'x-amz-request-id', '92BBEB674531C133'}, {'x-amz-replication-status', 'PENDING'}, {'x-amz-meta-surrogate-key', 'installs'}, {'x-amz-version-id', 'Ua76o_1PQ.oYxmlDyoqJCh_SeGbu.P6p'}, {'x-served-by', 'cache-iad2628-IAD'}, {'x-cache', 'HIT'}, {'x-cache-hits', '1'}, {'x-timer', 'S1470076873.189701,VS0,VE1'}]}, :undefined, {:httpc_response, :whole_body, [<<80, 75, 3, 4, 20, 0, 0, 0, 0, 0, 171, 8, 255, 72, 200, 108, 91, 120, 153, 9, 0, 0, 153, 9, 0, 0, 23, 0, 0, 0, 104, 101, 120, 45, 48, 46, 49, 51, 46, 48, ...>>, 372935]}, {[], []}, {[], []}, :new, [], :nolimit, :nolimit, {:options, {:undefined, []}, {:undefined, []}, 0, 2, 5, 120000, 2, :disabled, false, :inet, :default, :default, []}, {:timers, [], :undefined}, :httpc_mix, :inactive}
{noformat}
@OTP-Maintainer
Copy link
Author

essen said:

I have also seen this after I switched to using profiles in order to avoid intermittent failures I had with just the default profile. I receive the following unexpected message:

{code:erlang}
        {http,
            {#Ref<0.0.2.20087>,
             {error,
                 {failed_updating_session,
                     [{profile,'httpc_$request545'},
                      {session_id,{{"localhost",8443},<0.6421.0>}},
                      {pos,7},
                      {value,0},
                      {etype,error},
                      {error,badarg},
                      {stacktrace,
                          [{ets,update_element,
                               ['httpc_$request545__session_db',
                                {{"localhost",8443},<0.6421.0>},
                                {7,0}],
                               []},
                           {httpc_manager,update_session,4,
                               [{file,"httpc_manager.erl"},{line,210}]},
                           {httpc_handler,update_session,4,
                               [{file,"httpc_handler.erl"},{line,1887}]},
                           {httpc_handler,handle_empty_queue,4,
                               [{file,"httpc_handler.erl"},{line,1368}]},
                           {httpc_handler,handle_info,2,
                               [{file,"httpc_handler.erl"},{line,471}]},
                           {gen_server,try_dispatch,4,
                               [{file,"gen_server.erl"},{line,615}]},
                           {gen_server,handle_msg,5,
                               [{file,"gen_server.erl"},{line,681}]},
                           {proc_lib,init_p_do_apply,3,
                               [{file,"proc_lib.erl"},{line,240}]}]}]}}}}
{code}

@OTP-Maintainer
Copy link
Author

ericmj said:

I can confirm what @essen said. I have only seen this issue when using profiles.

@OTP-Maintainer
Copy link
Author

ingela said:

This sounds like an error handling error. As the handler process tries to write to a public ets-table
of the manager it should handle a shutdown of the manager as a normal shutdown of itself (the handler).

I suggest the following, what do you think?


{code:java}
diff --git a/lib/inets/src/http_client/httpc_handler.erl b/lib/inets/src/http_client/httpc_handler.erl
index d1c52dc..5d3993c 100644
--- a/lib/inets/src/http_client/httpc_handler.erl
+++ b/lib/inets/src/http_client/httpc_handler.erl
@@ -1887,10 +1887,13 @@ update_session(ProfileName, #session{id = SessionId} = Session, Pos, Value) ->
 	    httpc_manager:update_session(ProfileName, SessionId, Pos, Value)
 	end
     catch
-	error:undef -> % This could happen during code upgrade
+	error:undef -> %% This could happen during code upgrade
 	    Session2 = erlang:setelement(Pos, Session, Value),
 	    insert_session(Session2, ProfileName);
-	  T:E ->
+	error:badarg ->
+	    exit(normal); %% Manager has been shutdown
+	T:E -> 
+	    %% Unexpected this must be an error!  
             Stacktrace = erlang:get_stacktrace(),
             error_logger:error_msg("Failed updating session: "
                                    "~n   ProfileName: ~p"
{code}

@OTP-Maintainer
Copy link
Author

ingela said:

Suggested solution see previous comment

@OTP-Maintainer
Copy link
Author

ingela said:

I merged the suggested solution as we think it will make things better, and nobody  said otherwise.

@OTP-Maintainer
Copy link
Author

ericmj said:

We see another version of this error on 19.2. Now we see the error message from the exit(normal) instead:

{noformat}
10:39:01.480 [error] GenServer #PID<0.142.0> terminating
** (stop) normal
    (inets) httpc_handler.erl:1855: :httpc_handler.update_session/4
    (inets) httpc_handler.erl:1475: :httpc_handler.maybe_make_session_available/2
    (inets) httpc_handler.erl:1466: :httpc_handler.answer_request/3
    (inets) httpc_handler.erl:761: :httpc_handler.terminate/2
    (stdlib) gen_server.erl:629: :gen_server.try_terminate/3
    (stdlib) gen_server.erl:795: :gen_server.terminate/7
    (stdlib) proc_lib.erl:247: :proc_lib.init_p_do_apply/3
Last message: {:ssl, {:sslsocket, {:gen_tcp, #Port<0.6040>, :tls_connection, :undefined}, #PID<0.146.0>}, "HTTP/1.1 200 OK\r\nx-amz-id-2: ql+XFZxQXyk3oFDHNtyNminvIEEetT988ZIjTEW070Wzo1VWcJFFUIdR5VjghVmQ1K2+Td3rEnM=\r\nx-amz-request-id: 4D12A5072116F9CB\r\nx-amz-replication-status: COMPLETED\r\nLast-Modified: Tue, 28 Jun 2016 23:59:12 GMT\r\nETag: \"a5e57ed81098cf777bc319d6118eff50\"\r\nCache-Control: public, max-age=604800\r\nx-amz-meta-surrogate-key: installs\r\nx-amz-version-id: _0bG9Pxir6pB8zBlmt_v1mDuB_StPz9A\r\nContent-Type: text/csv\r\nServer: AmazonS3\r\nVia: 1.1 varnish\r\nFastly-Debug-Digest: 600581fd82da8d7f958c0fc69a76b5f37d0408f6e59492f56cddc3c4a4eb106c\r\nContent-Length: 282\r\nAccept-Ranges: bytes\r\nDate: Wed, 01 Mar 2017 09:39:01 GMT\r\nVia: 1.1 varnish\r\nAge: 430963\r\nConnection: keep-alive\r\nX-Served-By: cache-iad2141-IAD, cache-bma7033-BMA\r\nX-Cache: HIT, HIT\r\nX-Cache-Hits: 1, 1\r\nX-Timer: S1488361141.705807,VS0,VE0\r\n\r\n2.6.2,ff1c5ddfce1fcfd73fd65b8bfc0ff1c13aefc2e98921d528cbc1f35e86c9caa1c9c4e848b9ce6404d9a81c50cfcf0e45dd0dddb23cd42708664c41fce6618900,1.0.0\n2.6.2,ff1c5ddfce1fcfd73fd65b8bfc0ff1c13aefc2e98921d528cbc1f35e86c9caa1c9c4e848b9ce6404d9a81c50cfcf0e45dd0dddb23cd42708664c41fce6618900,1.0.0\n"}
State: {:state, {:request, #Reference<0.0.6.653>, #PID<0.70.0>, 0, :https, {'repo.hex.pm', 443}, '/installs/rebar-1.x.csv', [], :get, {:http_request_h, :undefined, 'keep-alive', :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, 'repo.hex.pm', :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, [], 'Mix/1.5.0-dev', :undefined, :undefined, :undefined, '0', :undefined, :undefined, :undefined, :undefined, :undefined, ...}, {[], []}, {:http_options, 'HTTP/1.1', :infinity, true, {:essl, []}, :undefined, true, :infinity, false}, 'https://repo.hex.pm/installs/rebar-1.x.csv', [], :none, [], 1488361141231, :undefined, :undefined, false}, {:session, {{'repo.hex.pm', 443}, #PID<0.142.0>}, false, :https, {:sslsocket, {:gen_tcp, #Port<0.6040>, :tls_connection, :undefined}, #PID<0.146.0>}, {:essl, []}, 1, :keep_alive, false}, :undefined, :undefined, :undefined, {:httpc_response, :parse, [:nolimit, true]}, {[], []}, {[], []}, :new, [], :nolimit, :nolimit, {:options, {:undefined, []}, {:undefined, []}, 0, 2, 5, 120000, 2, :disabled, false, :inet, :default, :default, []}, {:timers, [], :undefined}, :httpc_mix, :inactive}

10:39:01.570 [error] GenServer #PID<0.149.0> terminating
** (stop) normal
    (inets) httpc_handler.erl:1855: :httpc_handler.update_session/4
    (inets) httpc_handler.erl:1475: :httpc_handler.maybe_make_session_available/2
    (inets) httpc_handler.erl:1466: :httpc_handler.answer_request/3
    (inets) httpc_handler.erl:761: :httpc_handler.terminate/2
    (stdlib) gen_server.erl:629: :gen_server.try_terminate/3
    (stdlib) gen_server.erl:795: :gen_server.terminate/7
    (stdlib) proc_lib.erl:247: :proc_lib.init_p_do_apply/3
Last message: {:ssl, {:sslsocket, {:gen_tcp, #Port<0.6838>, :tls_connection, :undefined}, #PID<0.150.0>}, "HTTP/1.1 200 OK\r\nx-amz-id-2: Ma92xvjYvbBfDpxNtNjvScXXcAaP9pphME14paEJq5pIULiCRigh2jfT3NU3lBcvJ5Y2+E0ZIuk=\r\nx-amz-request-id: DA219DCF86AD19FF\r\nx-amz-replication-status: COMPLETED\r\nLast-Modified: Tue, 28 Jun 2016 23:59:13 GMT\r\nETag: \"0537e095e3db68e52cf054bf83190ee7\"\r\nCache-Control: public, max-age=604800\r\nx-amz-meta-surrogate-key: installs\r\nx-amz-version-id: E_Ixqh.m5j72bG3FTXuR4qXr5kf277MQ\r\nContent-Type: binary/octet-stream\r\nServer: AmazonS3\r\nVia: 1.1 varnish\r\nFastly-Debug-Digest: 8025a25b21acfce8d080645a90dcac45b6142ecd374e9f845fe845a7f6a4097f\r\nContent-Length: 350\r\nAccept-Ranges: bytes\r\nDate: Wed, 01 Mar 2017 09:39:01 GMT\r\nVia: 1.1 varnish\r\nAge: 430962\r\nConnection: keep-alive\r\nX-Served-By: cache-iad2121-IAD, cache-bma7025-BMA\r\nX-Cache: HIT, HIT\r\nX-Cache-Hits: 1, 1\r\nX-Timer: S1488361141.809105,VS0,VE0\r\n\r\nqc0Jirc+cvQTzArHDejmNxqsxFKx74uBMrS/0VBkMAnR30bgHM571ChHHRBHDqAn\nXiqVWjULStbyUd75AkOncca0XCMCsY5DQrC2qnfwebtNVAXVvbMpr2pK832qGpxS\nVgi5ibZ/DApuLsBXa3nkHjnIze3KOKq08CUZcC389JL0k1ky0QU2IjxRXMoxet9O\nO1G6PEnRmeQLMtF4uiXqA9M0r0TSG5Bi6zAtKo9LOv+ycrBwBMlrPXCJ0x+kEKh7\n4pvtDxxF6xJ77X3peVpWAEWnSm5v3HDQsgsfyYKObhEnMllDWlqCKXas+igVAgUw\nldZ7uCiBSB36GXE7R/hHvA==\n"}
State: {:state, {:request, #Reference<0.0.5.24>, #PID<0.70.0>, 0, :https, {'repo.hex.pm', 443}, '/installs/rebar-1.x.csv.signed', [], :get, {:http_request_h, :undefined, 'keep-alive', :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, 'repo.hex.pm', :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, [], 'Mix/1.5.0-dev', :undefined, :undefined, :undefined, '0', :undefined, :undefined, :undefined, :undefined, :undefined, ...}, {[], []}, {:http_options, 'HTTP/1.1', :infinity, true, {:essl, []}, :undefined, true, :infinity, false}, 'https://repo.hex.pm/installs/rebar-1.x.csv.signed', [], :none, [], 1488361141456, :undefined, :undefined, false}, {:session, {{'repo.hex.pm', 443}, #PID<0.149.0>}, false, :https, {:sslsocket, {:gen_tcp, #Port<0.6838>, :tls_connection, :undefined}, #PID<0.150.0>}, {:essl, []}, 1, :keep_alive, false}, :undefined, :undefined, :undefined, {:httpc_response, :parse, [:nolimit, true]}, {[], []}, {[], []}, :new, [], :nolimit, :nolimit, {:options, {:undefined, []}, {:undefined, []}, 0, 2, 5, 120000, 2, :disabled, false, :inet, :default, :default, []}, {:timers, [], :undefined}, :httpc_mix, :inactive}
{noformat}

@OTP-Maintainer
Copy link
Author

ericmj said:

Should I open a new issue for this or reopen this issue?

@OTP-Maintainer
Copy link
Author

ingela said:

As the symptom is new, even if it is similar please make a new issue.  Also is this an inets error report? Terminating normal should no cause error reports.

@OTP-Maintainer
Copy link
Author

ericmj said:

You are of course right that normal exits should not cause reports. I will reopen if I can reliably reproduce again and have confirmed that it's not an Elixir issue.

@OTP-Maintainer OTP-Maintainer added bug Issue is reported as a bug team:PS Assigned to OTP team PS priority:medium labels Feb 10, 2021
@OTP-Maintainer OTP-Maintainer added this to the OTP-19.2 milestone Feb 10, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@IngelaAndin IngelaAndin

Labels
bug Issue is reported as a bug priority:medium team:PS Assigned to OTP team PS
Projects
None yet
Milestone
OTP-19.2
Development

No branches or pull requests
2 participants
@IngelaAndin @OTP-Maintainer