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.

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

Segfault with http2 with bad connection #2688

Closed
ThomasObenaus opened this Issue Jun 27, 2018 · 57 comments

Comments

Projects
None yet
6 participants
@ThomasObenaus

ThomasObenaus commented Jun 27, 2018

I did this

Application that communicates using http2 (nghttp2) with our backend.
In case the connection is bad (mobile phone with edge/gsm) the application crashes each time with a segfault and the same back-trace.

Precondition

  • Bad connection (low bandwidth) with over mobile phone whose datavolume is empty (fallback to 2G).
  • No connection to the internet (firewall closed).
  • Application starts requesting (to reproduce the problem) a lot of requests.
  • dnsmask already complains about too many requests in parallel (max of 150 reached).
  • Opening the fire wall.
  • Waiting for ~1 min --> segfault.

Curl errors

  • When FW is closed: "Cloud not connect"
  • When FW is open: "Timeout reached"

I expected the following

no segfault

curl/libcurl version

Tested with 7.54.0 and 7.60

Libs

nghttp2 1.17.0
c-ares 1.13.9

@ThomasObenaus

This comment has been minimized.

Show comment
Hide comment
@ThomasObenaus

ThomasObenaus Jun 27, 2018

Backtrace

(gdb) bt
#0 0x0000007f935e0988 in __GI__IO_fwrite (buf=..., size=..., count=..., fp=...) at iofwrite.c:37
#1 0x0000007f956708a8 in showit (data=..., type=..., ptr=..., size=...) at sendf.c:826
#2 0x0000007f95670c18 in Curl_debug (data=..., type=..., ptr=..., size=..., conn=...) at sendf.c:878
#3 0x0000007f95670d50 in Curl_infof (data=..., fmt=...) at sendf.c:234
#4 0x0000007f956a1f9c in on_frame_not_send (session=..., frame=..., lib_error_code=..., userp=...) at http2.c:722
#5 0x0000007f95636380 in nghttp2_session_mem_send_internal (session=..., data_ptr=..., fast_cb=...)
at /home/thomaso/work/projects/bob_nav/dev/src/libs/ext-nghttp2/1/workspace/nghttp2-1.17.0/lib/nghttp2_session.c:2914
#6 0x0000007f95636c04 in nghttp2_session_send (session=...)
at /home/thomaso/work/projects/bob_nav/dev/src/libs/ext-nghttp2/1/workspace/nghttp2-1.17.0/lib/nghttp2_session.c:3215
#7 0x0000007f956a29ec in h2_session_send (data=..., h2=...) at http2.c:1379
#8 0x0000007f956a405c in http2_recv (conn=..., sockindex=..., mem=..., len=..., err=...) at http2.c:1559
#9 0x0000007f95670a64 in Curl_read (conn=..., sockfd=..., buf=..., sizerequested=..., n=...) at sendf.c:747
#10 0x0000007f95684764 in readwrite_data (comeback=..., done=..., didwhat=..., k=..., conn=..., data=...)
at transfer.c:434
#11 Curl_readwrite (conn=..., data=..., done=..., comeback=...) at transfer.c:1102
#12 0x0000007f9568ebac in multi_runsingle (multi=..., now=..., data=...) at multi.c:1908
#13 0x0000007f9568f5a0 in curl_multi_perform (multi=..., running_handles=...) at multi.c:2180
#14 0x00000000017ffeec in tsd::nav::cloud::comm::client::HTTPRequestHandler::main() ()
#15 0x00000000027f5ffc in tsd::nav::cloud::comm::client::HTTPRequestHandler::run() ()
#16 0x0000007f939fc510 in tsd::common::system::Thread::startImpl (arg=...)
at /home/thomaso/work/projects/bob_nav/dev/src/system/tsd-common/1/workspace/tsd.common/src/tsd/common/system/Thread.cpp:310
#17 0x0000007f93a00040 in tsd::common::system::os::thread::pseudoStartThread (arg=...)
at /home/thomaso/work/projects/bob_nav/dev/src/system/tsd-common/1/workspace/tsd.common/src/tsd/common/system/posix/POSIXThread.cpp:367
#18 0x0000007f93955030 in start_thread (arg=...) at pthread_create.c:331
#19 0x0000007f936464c0 in thread_start () at ../sysdeps/unix/sysv/linux/aarch64/clone.S:89

ThomasObenaus commented Jun 27, 2018

Backtrace

(gdb) bt
#0 0x0000007f935e0988 in __GI__IO_fwrite (buf=..., size=..., count=..., fp=...) at iofwrite.c:37
#1 0x0000007f956708a8 in showit (data=..., type=..., ptr=..., size=...) at sendf.c:826
#2 0x0000007f95670c18 in Curl_debug (data=..., type=..., ptr=..., size=..., conn=...) at sendf.c:878
#3 0x0000007f95670d50 in Curl_infof (data=..., fmt=...) at sendf.c:234
#4 0x0000007f956a1f9c in on_frame_not_send (session=..., frame=..., lib_error_code=..., userp=...) at http2.c:722
#5 0x0000007f95636380 in nghttp2_session_mem_send_internal (session=..., data_ptr=..., fast_cb=...)
at /home/thomaso/work/projects/bob_nav/dev/src/libs/ext-nghttp2/1/workspace/nghttp2-1.17.0/lib/nghttp2_session.c:2914
#6 0x0000007f95636c04 in nghttp2_session_send (session=...)
at /home/thomaso/work/projects/bob_nav/dev/src/libs/ext-nghttp2/1/workspace/nghttp2-1.17.0/lib/nghttp2_session.c:3215
#7 0x0000007f956a29ec in h2_session_send (data=..., h2=...) at http2.c:1379
#8 0x0000007f956a405c in http2_recv (conn=..., sockindex=..., mem=..., len=..., err=...) at http2.c:1559
#9 0x0000007f95670a64 in Curl_read (conn=..., sockfd=..., buf=..., sizerequested=..., n=...) at sendf.c:747
#10 0x0000007f95684764 in readwrite_data (comeback=..., done=..., didwhat=..., k=..., conn=..., data=...)
at transfer.c:434
#11 Curl_readwrite (conn=..., data=..., done=..., comeback=...) at transfer.c:1102
#12 0x0000007f9568ebac in multi_runsingle (multi=..., now=..., data=...) at multi.c:1908
#13 0x0000007f9568f5a0 in curl_multi_perform (multi=..., running_handles=...) at multi.c:2180
#14 0x00000000017ffeec in tsd::nav::cloud::comm::client::HTTPRequestHandler::main() ()
#15 0x00000000027f5ffc in tsd::nav::cloud::comm::client::HTTPRequestHandler::run() ()
#16 0x0000007f939fc510 in tsd::common::system::Thread::startImpl (arg=...)
at /home/thomaso/work/projects/bob_nav/dev/src/system/tsd-common/1/workspace/tsd.common/src/tsd/common/system/Thread.cpp:310
#17 0x0000007f93a00040 in tsd::common::system::os::thread::pseudoStartThread (arg=...)
at /home/thomaso/work/projects/bob_nav/dev/src/system/tsd-common/1/workspace/tsd.common/src/tsd/common/system/posix/POSIXThread.cpp:367
#18 0x0000007f93955030 in start_thread (arg=...) at pthread_create.c:331
#19 0x0000007f936464c0 in thread_start () at ../sysdeps/unix/sysv/linux/aarch64/clone.S:89
@bagder

This comment has been minimized.

Show comment
Hide comment
@bagder

bagder Jun 27, 2018

Member

That's a 7.54.0 backtrace, right? The line numbers seems way off from 7.60.0... Did you build with DEBUG_HTTP2 defined?

So what is the problem in the showit() function? The blanked out arguments make it hard to guess.

Member

bagder commented Jun 27, 2018

That's a 7.54.0 backtrace, right? The line numbers seems way off from 7.60.0... Did you build with DEBUG_HTTP2 defined?

So what is the problem in the showit() function? The blanked out arguments make it hard to guess.

@ThomasObenaus

This comment has been minimized.

Show comment
Hide comment
@ThomasObenaus

ThomasObenaus Jun 27, 2018

Current state of investigation

  • The guess is that after we got back the easy_handle from curl_multi_info_read processed it and then freed the easy_handle with curl_multi_remove_handle + curl_easy_cleanup there still seams to come traffic for this easy_handle.

ThomasObenaus commented Jun 27, 2018

Current state of investigation

  • The guess is that after we got back the easy_handle from curl_multi_info_read processed it and then freed the easy_handle with curl_multi_remove_handle + curl_easy_cleanup there still seams to come traffic for this easy_handle.
@ThomasObenaus

This comment has been minimized.

Show comment
Hide comment
@ThomasObenaus

ThomasObenaus Jun 27, 2018

Yes that's the bt from 7.54.0.
In showit() it seams that the easy_handle (data) is damaged.
The magic field shows 0x877b330 instead of 0xc0dedbad.

It chrashes then at fwrite(s_infotype[type], 2, 1, data->set.err); (in: sendf.c) .

ThomasObenaus commented Jun 27, 2018

Yes that's the bt from 7.54.0.
In showit() it seams that the easy_handle (data) is damaged.
The magic field shows 0x877b330 instead of 0xc0dedbad.

It chrashes then at fwrite(s_infotype[type], 2, 1, data->set.err); (in: sendf.c) .

@ThomasObenaus

This comment has been minimized.

Show comment
Hide comment
@ThomasObenaus

ThomasObenaus Jun 27, 2018

  • Even at level of Curl_readwrite (frame 11 in the bt) the connection having a pointer to a stream-map referencing another easy_handle (0x7f08776438) than the easy_handle (0x7f08c62258) that owns this connection.
  • The first easy_handle is invalid (magic should be 0xc0dedbad).
    (gdb) p data->magic
    $6 = 0x877b330
  • It seams that after curl_easy_cleanup was called on the easy_handle (0x7f08776438) it is still part of the nghttp2-stream. Thus when the stream is processed in the next loop it crashes.
  • The question here is: Who adds the "wrong" easy_handle (0x7f08776438) as stream_user_data to the "good" easy_handle (0x7f08c62258)

ThomasObenaus commented Jun 27, 2018

  • Even at level of Curl_readwrite (frame 11 in the bt) the connection having a pointer to a stream-map referencing another easy_handle (0x7f08776438) than the easy_handle (0x7f08c62258) that owns this connection.
  • The first easy_handle is invalid (magic should be 0xc0dedbad).
    (gdb) p data->magic
    $6 = 0x877b330
  • It seams that after curl_easy_cleanup was called on the easy_handle (0x7f08776438) it is still part of the nghttp2-stream. Thus when the stream is processed in the next loop it crashes.
  • The question here is: Who adds the "wrong" easy_handle (0x7f08776438) as stream_user_data to the "good" easy_handle (0x7f08c62258)
@bagder

This comment has been minimized.

Show comment
Hide comment
@bagder

bagder Jun 27, 2018

Member

Since I can't reproduce I can only offer general guidance as how to go ahead and debug this:

  • build with git master, we've already fixed a few problems with removed easy handles from the multi handle
  • define DEBUG_HTTP2 and check if you actually get frames from a stream that is already done/removed when you see this problem - which I think it might be
  • if you get frames from a stream that was owned by an easy handle that is now removed, can you figure out why Curl_http2_done was not called on it (and subsequently nghttp2_session_set_stream_user_data cleared the association from frame id to easy handle), or whatever it is that makes libcurl extract a "dead" easy handle for an incoming h2 frame
Member

bagder commented Jun 27, 2018

Since I can't reproduce I can only offer general guidance as how to go ahead and debug this:

  • build with git master, we've already fixed a few problems with removed easy handles from the multi handle
  • define DEBUG_HTTP2 and check if you actually get frames from a stream that is already done/removed when you see this problem - which I think it might be
  • if you get frames from a stream that was owned by an easy handle that is now removed, can you figure out why Curl_http2_done was not called on it (and subsequently nghttp2_session_set_stream_user_data cleared the association from frame id to easy handle), or whatever it is that makes libcurl extract a "dead" easy handle for an incoming h2 frame
@ThomasObenaus

This comment has been minimized.

Show comment
Hide comment
@ThomasObenaus

ThomasObenaus Jun 27, 2018

Thanks for the quick feedback.
I'll rebuild it with your hints and come back as soon as possible with a status update.

ThomasObenaus commented Jun 27, 2018

Thanks for the quick feedback.
I'll rebuild it with your hints and come back as soon as possible with a status update.

@ThomasObenaus

This comment has been minimized.

Show comment
Hide comment
@ThomasObenaus

ThomasObenaus Jun 27, 2018

Update

I tried it with 7.60.0 and get now the same bt like mentioned in #2674 for two times and another one at the second try.

BT 1

#0  h2_session_send (data=..., h2=...) at http2.c:1470
#1  0x0000007fbb9564e8 in h2_process_pending_input (conn=..., httpc=..., err=...) at http2.c:1303
#2  0x0000007fbb95667c in http2_connisdead (conn=...) at http2.c:219
#3  http2_conncheck (check=..., checks_to_perform=...) at http2.c:236
#4  0x0000007fbb92c760 in extract_if_dead (conn=..., data=...) at url.c:973
#5  0x0000007fbb92c7ec in call_extract_if_dead (conn=..., param=...) at url.c:1003
#6  0x0000007fbb954914 in Curl_conncache_foreach (data=..., connc=..., param=..., func=...) at conncache.c:382
#7  0x0000007fbb9303d8 in prune_dead_connections (data=...) at url.c:1025
#8  create_conn (async=..., in_connect=..., data=...) at url.c:4382
#9  Curl_connect (data=..., in_connect=..., asyncp=..., protocol_done=...) at url.c:4660
#10 0x0000007fbb940db0 in multi_runsingle (multi=..., now=..., data=...) at multi.c:1421
#11 0x0000007fbb941b0c in curl_multi_perform (multi=..., running_handles=...) at multi.c:2159
#12 0x00000000017ffe10 in tsd::nav::cloud::comm::client::HTTPRequestHandler::main() ()
#13 0x00000000027f500c in tsd::nav::cloud::comm::client::HTTPRequestHandler::run() ()
#14 0x0000007fb9cb0510 in tsd::common::system::Thread::startImpl (arg=...)
    at /home/thomaso/work/projects/bob_c_ares/dev/src/system/tsd-common/1/workspace/tsd.common/src/tsd/common/system/Thread.cpp:310
#15 0x0000007fb9cb4040 in tsd::common::system::os::thread::pseudoStartThread (arg=...)
    at /home/thomaso/work/projects/bob_c_ares/dev/src/system/tsd-common/1/workspace/tsd.common/src/tsd/common/system/posix/POSIXThread.cpp:367
#16 0x0000007fb9c09030 in start_thread (arg=...) at pthread_create.c:331
#17 0x0000007fb98fa4c0 in thread_start () at ../sysdeps/unix/sysv/linux/aarch64/clone.S:89

(gdb) p data->magic
$7 = 0x0

BT 2

#0  0x0000007f88db0504 in Curl_multi_connchanged (multi=...) at multi.c:1111
#1  0x0000007f88dc79cc in on_frame_recv (session=..., frame=..., userp=...) at http2.c:586
#2  0x0000007f88d5b620 in session_call_on_frame_received (frame=..., session=...)
    at /home/thomaso/work/projects/bob_c_ares/dev/src/libs/ext-nghttp2/1/workspace/nghttp2-1.17.0/lib/nghttp2_session.c:3271
#3  nghttp2_session_on_settings_received (session=..., frame=..., noack=...)
    at /home/thomaso/work/projects/bob_c_ares/dev/src/libs/ext-nghttp2/1/workspace/nghttp2-1.17.0/lib/nghttp2_session.c:4367
#4  0x0000007f88d5e7a8 in session_process_settings_frame (session=...)
    at /home/thomaso/work/projects/bob_c_ares/dev/src/libs/ext-nghttp2/1/workspace/nghttp2-1.17.0/lib/nghttp2_session.c:4507
#5  nghttp2_session_mem_recv (session=..., in=..., inlen=...)
    at /home/thomaso/work/projects/bob_c_ares/dev/src/libs/ext-nghttp2/1/workspace/nghttp2-1.17.0/lib/nghttp2_session.c:6161
#6  0x0000007f88dc74c0 in h2_process_pending_input (conn=..., httpc=..., err=...) at http2.c:1279
#7  0x0000007f88dc767c in http2_connisdead (conn=...) at http2.c:219
#8  http2_conncheck (check=..., checks_to_perform=...) at http2.c:236
#9  0x0000007f88d9d760 in extract_if_dead (conn=..., data=...) at url.c:973
#10 0x0000007f88d9d7ec in call_extract_if_dead (conn=..., param=...) at url.c:1003
#11 0x0000007f88dc5914 in Curl_conncache_foreach (data=..., connc=..., param=..., func=...) at conncache.c:382
#12 0x0000007f88da13d8 in prune_dead_connections (data=...) at url.c:1025
#13 create_conn (async=..., in_connect=..., data=...) at url.c:4382
#14 Curl_connect (data=..., in_connect=..., asyncp=..., protocol_done=...) at url.c:4660
#15 0x0000007f88db1db0 in multi_runsingle (multi=..., now=..., data=...) at multi.c:1421
#16 0x0000007f88db2b0c in curl_multi_perform (multi=..., running_handles=...) at multi.c:2159
#17 0x00000000017ffe10 in tsd::nav::cloud::comm::client::HTTPRequestHandler::main() ()
#18 0x00000000027f500c in tsd::nav::cloud::comm::client::HTTPRequestHandler::run() ()
#19 0x0000007f87121510 in tsd::common::system::Thread::startImpl (arg=...)
    at /home/thomaso/work/projects/bob_c_ares/dev/src/system/tsd-common/1/workspace/tsd.common/src/tsd/common/system/Thread.cpp:310
#20 0x0000007f87125040 in tsd::common::system::os::thread::pseudoStartThread (arg=...)
    at /home/thomaso/work/projects/bob_c_ares/dev/src/system/tsd-common/1/workspace/tsd.common/src/tsd/common/system/posix/POSIXThread.cpp:367
#21 0x0000007f8707a030 in start_thread (arg=...) at pthread_create.c:331
#22 0x0000007f86d6b4c0 in thread_start () at ../sysdeps/unix/sysv/linux/aarch64/clone.S:89

(gdb) p multi
$1 = (struct Curl_multi *) 0x

ThomasObenaus commented Jun 27, 2018

Update

I tried it with 7.60.0 and get now the same bt like mentioned in #2674 for two times and another one at the second try.

BT 1

#0  h2_session_send (data=..., h2=...) at http2.c:1470
#1  0x0000007fbb9564e8 in h2_process_pending_input (conn=..., httpc=..., err=...) at http2.c:1303
#2  0x0000007fbb95667c in http2_connisdead (conn=...) at http2.c:219
#3  http2_conncheck (check=..., checks_to_perform=...) at http2.c:236
#4  0x0000007fbb92c760 in extract_if_dead (conn=..., data=...) at url.c:973
#5  0x0000007fbb92c7ec in call_extract_if_dead (conn=..., param=...) at url.c:1003
#6  0x0000007fbb954914 in Curl_conncache_foreach (data=..., connc=..., param=..., func=...) at conncache.c:382
#7  0x0000007fbb9303d8 in prune_dead_connections (data=...) at url.c:1025
#8  create_conn (async=..., in_connect=..., data=...) at url.c:4382
#9  Curl_connect (data=..., in_connect=..., asyncp=..., protocol_done=...) at url.c:4660
#10 0x0000007fbb940db0 in multi_runsingle (multi=..., now=..., data=...) at multi.c:1421
#11 0x0000007fbb941b0c in curl_multi_perform (multi=..., running_handles=...) at multi.c:2159
#12 0x00000000017ffe10 in tsd::nav::cloud::comm::client::HTTPRequestHandler::main() ()
#13 0x00000000027f500c in tsd::nav::cloud::comm::client::HTTPRequestHandler::run() ()
#14 0x0000007fb9cb0510 in tsd::common::system::Thread::startImpl (arg=...)
    at /home/thomaso/work/projects/bob_c_ares/dev/src/system/tsd-common/1/workspace/tsd.common/src/tsd/common/system/Thread.cpp:310
#15 0x0000007fb9cb4040 in tsd::common::system::os::thread::pseudoStartThread (arg=...)
    at /home/thomaso/work/projects/bob_c_ares/dev/src/system/tsd-common/1/workspace/tsd.common/src/tsd/common/system/posix/POSIXThread.cpp:367
#16 0x0000007fb9c09030 in start_thread (arg=...) at pthread_create.c:331
#17 0x0000007fb98fa4c0 in thread_start () at ../sysdeps/unix/sysv/linux/aarch64/clone.S:89

(gdb) p data->magic
$7 = 0x0

BT 2

#0  0x0000007f88db0504 in Curl_multi_connchanged (multi=...) at multi.c:1111
#1  0x0000007f88dc79cc in on_frame_recv (session=..., frame=..., userp=...) at http2.c:586
#2  0x0000007f88d5b620 in session_call_on_frame_received (frame=..., session=...)
    at /home/thomaso/work/projects/bob_c_ares/dev/src/libs/ext-nghttp2/1/workspace/nghttp2-1.17.0/lib/nghttp2_session.c:3271
#3  nghttp2_session_on_settings_received (session=..., frame=..., noack=...)
    at /home/thomaso/work/projects/bob_c_ares/dev/src/libs/ext-nghttp2/1/workspace/nghttp2-1.17.0/lib/nghttp2_session.c:4367
#4  0x0000007f88d5e7a8 in session_process_settings_frame (session=...)
    at /home/thomaso/work/projects/bob_c_ares/dev/src/libs/ext-nghttp2/1/workspace/nghttp2-1.17.0/lib/nghttp2_session.c:4507
#5  nghttp2_session_mem_recv (session=..., in=..., inlen=...)
    at /home/thomaso/work/projects/bob_c_ares/dev/src/libs/ext-nghttp2/1/workspace/nghttp2-1.17.0/lib/nghttp2_session.c:6161
#6  0x0000007f88dc74c0 in h2_process_pending_input (conn=..., httpc=..., err=...) at http2.c:1279
#7  0x0000007f88dc767c in http2_connisdead (conn=...) at http2.c:219
#8  http2_conncheck (check=..., checks_to_perform=...) at http2.c:236
#9  0x0000007f88d9d760 in extract_if_dead (conn=..., data=...) at url.c:973
#10 0x0000007f88d9d7ec in call_extract_if_dead (conn=..., param=...) at url.c:1003
#11 0x0000007f88dc5914 in Curl_conncache_foreach (data=..., connc=..., param=..., func=...) at conncache.c:382
#12 0x0000007f88da13d8 in prune_dead_connections (data=...) at url.c:1025
#13 create_conn (async=..., in_connect=..., data=...) at url.c:4382
#14 Curl_connect (data=..., in_connect=..., asyncp=..., protocol_done=...) at url.c:4660
#15 0x0000007f88db1db0 in multi_runsingle (multi=..., now=..., data=...) at multi.c:1421
#16 0x0000007f88db2b0c in curl_multi_perform (multi=..., running_handles=...) at multi.c:2159
#17 0x00000000017ffe10 in tsd::nav::cloud::comm::client::HTTPRequestHandler::main() ()
#18 0x00000000027f500c in tsd::nav::cloud::comm::client::HTTPRequestHandler::run() ()
#19 0x0000007f87121510 in tsd::common::system::Thread::startImpl (arg=...)
    at /home/thomaso/work/projects/bob_c_ares/dev/src/system/tsd-common/1/workspace/tsd.common/src/tsd/common/system/Thread.cpp:310
#20 0x0000007f87125040 in tsd::common::system::os::thread::pseudoStartThread (arg=...)
    at /home/thomaso/work/projects/bob_c_ares/dev/src/system/tsd-common/1/workspace/tsd.common/src/tsd/common/system/posix/POSIXThread.cpp:367
#21 0x0000007f8707a030 in start_thread (arg=...) at pthread_create.c:331
#22 0x0000007f86d6b4c0 in thread_start () at ../sysdeps/unix/sysv/linux/aarch64/clone.S:89

(gdb) p multi
$1 = (struct Curl_multi *) 0x

@ThomasObenaus

This comment has been minimized.

Show comment
Hide comment
@ThomasObenaus

ThomasObenaus Jun 27, 2018

Next step: use master from libcurl

ThomasObenaus commented Jun 27, 2018

Next step: use master from libcurl

@ThomasObenaus

This comment has been minimized.

Show comment
Hide comment
@ThomasObenaus

ThomasObenaus Jun 27, 2018

Still a segfault, even with master from lib-curl:

#0  on_stream_close (session=..., stream_id=..., error_code=..., userp=...) at http2.c:842
#1  0x0000007f8a279c38 in nghttp2_session_close_stream (session=..., stream_id=..., error_code=...)
    at /home/thomaso/work/projects/bob_c_ares/dev/src/libs/ext-nghttp2/1/workspace/nghttp2-1.17.0/lib/nghttp2_session.c:1162
#2  0x0000007f8a27d3ac in nghttp2_session_mem_send_internal (session=..., data_ptr=..., fast_cb=...)
    at /home/thomaso/work/projects/bob_c_ares/dev/src/libs/ext-nghttp2/1/workspace/nghttp2-1.17.0/lib/nghttp2_session.c:2945
#3  0x0000007f8a27dc04 in nghttp2_session_send (session=...)
    at /home/thomaso/work/projects/bob_c_ares/dev/src/libs/ext-nghttp2/1/workspace/nghttp2-1.17.0/lib/nghttp2_session.c:3215
#4  0x0000007f8a2e81ec in h2_session_send (data=..., h2=...) at http2.c:1476
#5  0x0000007f8a2e9924 in http2_recv (conn=..., sockindex=..., mem=..., len=..., err=...) at http2.c:1656
#6  0x0000007f8a2b82e0 in Curl_read (conn=..., sockfd=..., buf=..., sizerequested=..., n=...) at sendf.c:749
#7  0x0000007f8a2c8db0 in readwrite_data (comeback=..., done=..., didwhat=..., k=..., conn=..., data=...)
    at transfer.c:482
#8  Curl_readwrite (conn=..., data=..., done=..., comeback=...) at transfer.c:1125
#9  0x0000007f8a2d3144 in multi_runsingle (multi=..., now=..., data=...) at multi.c:1914
#10 0x0000007f8a2d3b8c in curl_multi_perform (multi=..., running_handles=...) at multi.c:2181
#11 0x00000000017e6ff0 in tsd::nav::cloud::comm::client::HTTPRequestHandler::main() ()
#12 0x00000000027a3ecc in tsd::nav::cloud::comm::client::HTTPRequestHandler::run() ()
#13 0x0000007f88642510 in tsd::common::system::Thread::startImpl (arg=...)
    at /home/thomaso/work/projects/bob_c_ares/dev/src/system/tsd-common/1/workspace/tsd.common/src/tsd/common/system/Thread.cpp:310
#14 0x0000007f88646040 in tsd::common::system::os::thread::pseudoStartThread (arg=...)
    at /home/thomaso/work/projects/bob_c_ares/dev/src/system/tsd-common/1/workspace/tsd.common/src/tsd/common/system/posix/POSIXThread.cpp:367
#15 0x0000007f8859c030 in start_thread (arg=...) at pthread_create.c:331
#16 0x0000007f8828d4c0 in thread_start () at ../sysdeps/unix/sysv/linux/aarch64/clone.S:89

Now the crash: stream->closed = TRUE;

(gdb) p session
$2 = (nghttp2_session *) 0x7f143c79e0
(gdb) p *session
$3 = {
  streams = {
    table = 0x7f14db83f0, 
    mem = 0x7f143c8260, 
    size = 0xb, 
    tablelen = 0x100
  }, 
  root = {
    map_entry = {
      next = 0x0, 
      key = 0x0
    }, 
    pq_entry = {
      index = 0x0
    }, 
    obq = {
      q = 0x7f1458a590, 
      mem = 0x7f143c8260, 
      length = 0x0, 
      capacity = 0x4, 
      less = 0x7f8a277380 <stream_less at /home/thomaso/work/projects/bob_c_ares/dev/src/libs/ext-nghttp2/1/workspace/nghttp2-1.17.0/lib/nghttp2_stream.c:52>
    }, 
    content_length = 0xffffffffffffffff, 
    recv_content_length = 0x0, 
    descendant_last_cycle = 0x0, 
    cycle = 0x0, 
    descendant_next_seq = 0x5b, 
    seq = 0x0, 
    dep_prev = 0x0, 
    dep_next = 0x7f14afac20, 
    sib_prev = 0x0, 
    sib_next = 0x0, 
    closed_prev = 0x0, 
    closed_next = 0x0, 
    stream_user_data = 0x0, 
    item = 0x0, 
    last_writelen = 0x20, 
    stream_id = 0x0, 
    remote_window_size = 0x0, 
    recv_window_size = 0x0, 
    consumed_size = 0x0, 
    recv_reduction = 0x0, 
    local_window_size = 0x0, 
    weight = 0x10, 
    pending_penalty = 0x0, 
    sum_dep_weight = 0xb0, 
    state = NGHTTP2_STREAM_IDLE, 
    status_code = 0xffff, 
    http_flags = 0x0, 
    flags = 0x0, 
    shut_flags = 0x0, 
    queued = 0x0, 
    window_update_queued = 0x0
  }, 
  ob_urgent = {
    head = 0x0, 
    tail = 0x0, 
    n = 0x0
  }, 
  ob_reg = {
    head = 0x0, 
    tail = 0x0, 
    n = 0x0
  }, 
  ob_syn = {
    head = 0x7f14b37f30, 
    tail = 0x7f143a4820, 
    n = 0x99
  }, 
  aob = {
    item = 0x0, 
    framebufs = {
      head = 0x7f14b52ba0, 
      cur = 0x7f14b52ba0, 
      mem = 0x7f143c8260, 
      chunk_length = 0x400a, 
      max_chunk = 0x4, 
      chunk_used = 0x1, 
      chunk_keep = 0x1, 
      offset = 0xa
    }, 
    state = NGHTTP2_OB_POP_ITEM
  }, 
  iframe = {
    frame = {
      hd = {
        length = 0x0, 
        stream_id = 0x0, 
        type = 0x0, 
        flags = 0x0, 
        reserved = 0x0
      }, 
      data = {
        hd = {
          length = 0x0, 
          stream_id = 0x0, 
          type = 0x0, 
          flags = 0x0, 
          reserved = 0x0
        }, 
        padlen = 0x0
      }, 
      headers = {
        hd = {
          length = 0x0, 
          stream_id = 0x0, 
          type = 0x0, 
          flags = 0x0, 
          reserved = 0x0
        }, 
        padlen = 0x0, 
        pri_spec = {
          stream_id = 0x0, 
          weight = 0x0, 
          exclusive = 0x0
        }, 
        nva = 0x0, 
        nvlen = 0x0, 
        cat = NGHTTP2_HCAT_REQUEST
      }, 
      priority = {
        hd = {
          length = 0x0, 
          stream_id = 0x0, 
          type = 0x0, 
          flags = 0x0, 
          reserved = 0x0
        }, 
        pri_spec = {
          stream_id = 0x0, 
          weight = 0x0, 
          exclusive = 0x0
        }
      }, 
      rst_stream = {
        hd = {
          length = 0x0, 
          stream_id = 0x0, 
          type = 0x0, 
          flags = 0x0, 
          reserved = 0x0
        }, 
        error_code = 0x0
      }, 
      settings = {
        hd = {
          length = 0x0, 
          stream_id = 0x0, 
          type = 0x0, 
          flags = 0x0, 
          reserved = 0x0
        }, 
        niv = 0x0, 
        iv = 0x0
      }, 
      push_promise = {
        hd = {
          length = 0x0, 
          stream_id = 0x0, 
          type = 0x0, 
          flags = 0x0, 
          reserved = 0x0
        }, 
        padlen = 0x0, 
        nva = 0x0, 
        nvlen = 0x0, 
        promised_stream_id = 0x0, 
        reserved = 0x0
      }, 
      ping = {
        hd = {
          length = 0x0, 
          stream_id = 0x0, 
          type = 0x0, 
          flags = 0x0, 
          reserved = 0x0
        }, 
        opaque_data = "\000\000\000\000\000\000\000"
      }, 
      goaway = {
        hd = {
          length = 0x0, 
          stream_id = 0x0, 
          type = 0x0, 
          flags = 0x0, 
          reserved = 0x0
        }, 
        last_stream_id = 0x0, 
        error_code = 0x0, 
        opaque_data = 0x0, 
        opaque_data_len = 0x0, 
        reserved = 0x0
      }, 
      window_update = {
        hd = {
          length = 0x0, 
          stream_id = 0x0, 
          type = 0x0, 
          flags = 0x0, 
          reserved = 0x0
        }, 
        window_size_increment = 0x0, 
        reserved = 0x0
      }, 
      ext = {
        hd = {
          length = 0x0, 
          stream_id = 0x0, 
          type = 0x0, 
          flags = 0x0, 
          reserved = 0x0
        }, 
        payload = 0x0
      }
    }, 
    ext_frame_payload = {
      altsvc = {
        origin = 0x0, 
        origin_len = 0x0, 
        field_value = 0x0, 
        field_value_len = 0x0
      }
    }, 
    iv = 0x0, 
    sbuf = {
      begin = 0x7f143c7c5c "", 
      end = 0x7f143c7c65 "", 
      pos = 0x7f143c7c5c "", 
      last = 0x7f143c7c5c "", 
      mark = 0x7f143c7c65 ""
    }, 
    lbuf = {
      begin = 0x0, 
      end = 0x0, 
      pos = 0x0, 
      last = 0x0, 
      mark = 0x0
    }, 
    raw_lbuf = 0x0, 
    niv = 0x0, 
    max_niv = 0x0, 
    payloadleft = 0x0, 
    padlen = 0x0, 
    state = NGHTTP2_IB_READ_HEAD, 
    raw_sbuf = "\000\000\000\000\001\000\000\000U"
  }, 
  hd_deflater = {
    ctx = {
      hd_table = {
        buffer = 0x7f14db7bd0, 
        mask = 0x7f, 
        first = 0xfffffffffffffffc, 
        len = 0x4
      }, 
      mem = 0x7f143c8260, 
      hd_table_bufsize = 0xf1, 
      hd_table_bufsize_max = 0x1000, 
      next_seq = 0x4, 
      bad = 0x0
    }, 
    map = {
      table = {[0x0] = 0x0 <repeats 21 times>, [0x15] = 0x7f15593e80, [0x16] = 0x0, [0x17] = 0x0, [0x18] = 0x0, 
        [0x19] = 0x7f1491ed00, [0x1a] = 0x0 <repeats 15 times>, [0x29] = 0x7f15614570, 
        [0x2a] = 0x0 <repeats 52 times>, [0x5e] = 0x7f15601800, [0x5f] = 0x0 <repeats 33 times>}
    }, 
    deflate_hd_table_bufsize_max = 0x1000, 
    min_hd_table_bufsize_max = 0xffffffff, 
    notify_table_size_change = 0x0
  }, 
  hd_inflater = {
    ctx = {
      hd_table = {
        buffer = 0x7f14db7fe0, 
        mask = 0x7f, 
        first = 0xffffffffffffff82, 
        len = 0x3f
      }, 
      mem = 0x7f143c8260, 
      hd_table_bufsize = 0xfd9, 
      hd_table_bufsize_max = 0x1000, 
      next_seq = 0x7e, 
      bad = 0x0
    }, 
    huff_decode_ctx = {
      state = 0x38, 
      accept = 0x1
    }, 
    namebuf = {
      begin = 0x7f143cbab8 "x-application-context", 
      end = 0x7f143cbad7 "", 
      pos = 0x7f143cbab8 "x-application-context", 
      last = 0x7f143cbacd "", 
      mark = 0x7f143cbab8 "x-application-context"
    }, 
    valuebuf = {
      begin = 0x7f14aefaf8 "application:60124", 
      end = 0x7f14aefb11 "", 
      pos = 0x7f14aefaf8 "application:60124", 
      last = 0x7f14aefb09 "", 
      mark = 0x7f14aefaf8 "application:60124"
    }, 
    namercbuf = 0x0, 
    valuercbuf = 0x0, 
    nv_name_keep = 0x0, 
    nv_value_keep = 0x0, 
    left = 0x0, 
    index = 0x1b, 
    settings_hd_table_bufsize_max = 0x1000, 
    min_hd_table_bufsize_max = 0xffffffff, 
    shift = 0x0, 
    opcode = NGHTTP2_HD_OPCODE_NEWNAME, 
    state = NGHTTP2_HD_STATE_INFLATE_START, 
    huffman_encoded = 0x1, 
    index_required = 0x0, 
    no_index = 0x0
  }, 
  callbacks = {
    send_callback = 0x7f8a2e8320 <send_callback at http2.c:362>, 
    recv_callback = 0x0, 
    on_frame_recv_callback = 0x7f8a2e87f0 <on_frame_recv at http2.c:557>, 
    on_invalid_frame_recv_callback = 0x7f8a2e86f0 <on_invalid_frame_recv>, 
    on_data_chunk_recv_callback = 0x7f8a2e7ef0 <on_data_chunk_recv at http2.c:708>, 
    before_frame_send_callback = 0x7f8a2e8710 <before_frame_send>, 
    on_frame_send_callback = 0x7f8a2e7af0 <on_frame_send at http2.c:788>, 
    on_frame_not_send_callback = 0x7f8a2e7ad0 <on_frame_not_send at http2.c:802>, 
    on_stream_close_callback = 0x7f8a2e83a0 <on_stream_close at http2.c:826>, 
    on_begin_headers_callback = 0x7f8a2e7e80 <on_begin_headers at http2.c:857>, 
    on_header_callback = 0x7f8a2e7b10 <on_header at http2.c:920>, 
    on_header_callback2 = 0x0, 
    on_invalid_header_callback = 0x0, 
    on_invalid_header_callback2 = 0x0, 
    select_padding_callback = 0x0, 
    read_length_callback = 0x0, 
    on_begin_frame_callback = 0x0, 
    send_data_callback = 0x0, 
    pack_extension_callback = 0x0, 
    unpack_extension_callback = 0x0, 
    on_extension_chunk_recv_callback = 0x0, 
    error_callback = 0x7f8a2e7aa0 <error_callback at http2.c:1081>
  }, 
  mem = {
    mem_user_data = 0x0, 
    malloc = 0x7f8a2851f0 <default_malloc at /home/thomaso/work/projects/bob_c_ares/dev/src/libs/ext-nghttp2/1/workspace/nghttp2-1.17.0/lib/nghttp2_mem.c:28>, 
    free = 0x7f8a2851e0 <default_free at /home/thomaso/work/projects/bob_c_ares/dev/src/libs/ext-nghttp2/1/workspace/nghttp2-1.17.0/lib/nghttp2_mem.c:31>, 
    calloc = 0x7f8a2851d0 <default_calloc at /home/thomaso/work/projects/bob_c_ares/dev/src/libs/ext-nghttp2/1/workspace/nghttp2-1.17.0/lib/nghttp2_mem.c:35>, 
    realloc = 0x7f8a2851c0 <default_realloc at /home/thomaso/work/projects/bob_c_ares/dev/src/libs/ext-nghttp2/1/workspace/nghttp2-1.17.0/lib/nghttp2_mem.c:39>
  }, 
  last_cycle = 0x0, 
  user_data = 0x7f14ae7be8, 
  closed_stream_head = 0x0, 
  closed_stream_tail = 0x0, 
  idle_stream_head = 0x0, 
  idle_stream_tail = 0x0, 
  inflight_settings_head = 0x0, 
  num_outgoing_streams = 0xb, 
  num_incoming_streams = 0x0, 
  num_incoming_reserved_streams = 0x0, 
  max_incoming_reserved_streams = 0xc8, 
  num_closed_streams = 0x0, 
  num_idle_streams = 0x0, 
  nvbuflen = 0x0, 
  obq_flood_counter_ = 0x0, 
  max_send_header_block_length = 0x10000, 
  next_stream_id = 0x223, 
  last_sent_stream_id = 0xd1, 
  last_recv_stream_id = 0x0, 
  last_proc_stream_id = 0x0, 
  next_unique_id = 0x0, 
  local_last_stream_id = 0x7fffffff, 
  remote_last_stream_id = 0x7fffffff, 
  remote_window_size = 0x7ffffddc, 
  recv_window_size = 0x2251e, 
  consumed_size = 0x0, 
  recv_reduction = 0x0, 
  local_window_size = 0x40000000, 
  remote_settings = {
    header_table_size = 0x1000, 
    enable_push = 0x1, 
    max_concurrent_streams = 0x80, 
    initial_window_size = 0x10000, 
    max_frame_size = 0xffffff, 
    max_header_list_size = 0xffffffff
  }, 
  local_settings = {
    header_table_size = 0x1000, 
    enable_push = 0x1, 
    max_concurrent_streams = 0x64, 
    initial_window_size = 0x40000000, 
    max_frame_size = 0x4000, 
    max_header_list_size = 0xffffffff
  }, 
  opt_flags = 0x0, 
  pending_local_max_concurrent_stream = 0x64, 
  builtin_recv_ext_types = 0x0, 
  pending_enable_push = 0x1, 
  server = 0x0, 
  goaway_flags = 0x0, 
  window_update_queued = 0x0, 
  user_recv_ext_types = '\000' <repeats 31 times>
}

ThomasObenaus commented Jun 27, 2018

Still a segfault, even with master from lib-curl:

#0  on_stream_close (session=..., stream_id=..., error_code=..., userp=...) at http2.c:842
#1  0x0000007f8a279c38 in nghttp2_session_close_stream (session=..., stream_id=..., error_code=...)
    at /home/thomaso/work/projects/bob_c_ares/dev/src/libs/ext-nghttp2/1/workspace/nghttp2-1.17.0/lib/nghttp2_session.c:1162
#2  0x0000007f8a27d3ac in nghttp2_session_mem_send_internal (session=..., data_ptr=..., fast_cb=...)
    at /home/thomaso/work/projects/bob_c_ares/dev/src/libs/ext-nghttp2/1/workspace/nghttp2-1.17.0/lib/nghttp2_session.c:2945
#3  0x0000007f8a27dc04 in nghttp2_session_send (session=...)
    at /home/thomaso/work/projects/bob_c_ares/dev/src/libs/ext-nghttp2/1/workspace/nghttp2-1.17.0/lib/nghttp2_session.c:3215
#4  0x0000007f8a2e81ec in h2_session_send (data=..., h2=...) at http2.c:1476
#5  0x0000007f8a2e9924 in http2_recv (conn=..., sockindex=..., mem=..., len=..., err=...) at http2.c:1656
#6  0x0000007f8a2b82e0 in Curl_read (conn=..., sockfd=..., buf=..., sizerequested=..., n=...) at sendf.c:749
#7  0x0000007f8a2c8db0 in readwrite_data (comeback=..., done=..., didwhat=..., k=..., conn=..., data=...)
    at transfer.c:482
#8  Curl_readwrite (conn=..., data=..., done=..., comeback=...) at transfer.c:1125
#9  0x0000007f8a2d3144 in multi_runsingle (multi=..., now=..., data=...) at multi.c:1914
#10 0x0000007f8a2d3b8c in curl_multi_perform (multi=..., running_handles=...) at multi.c:2181
#11 0x00000000017e6ff0 in tsd::nav::cloud::comm::client::HTTPRequestHandler::main() ()
#12 0x00000000027a3ecc in tsd::nav::cloud::comm::client::HTTPRequestHandler::run() ()
#13 0x0000007f88642510 in tsd::common::system::Thread::startImpl (arg=...)
    at /home/thomaso/work/projects/bob_c_ares/dev/src/system/tsd-common/1/workspace/tsd.common/src/tsd/common/system/Thread.cpp:310
#14 0x0000007f88646040 in tsd::common::system::os::thread::pseudoStartThread (arg=...)
    at /home/thomaso/work/projects/bob_c_ares/dev/src/system/tsd-common/1/workspace/tsd.common/src/tsd/common/system/posix/POSIXThread.cpp:367
#15 0x0000007f8859c030 in start_thread (arg=...) at pthread_create.c:331
#16 0x0000007f8828d4c0 in thread_start () at ../sysdeps/unix/sysv/linux/aarch64/clone.S:89

Now the crash: stream->closed = TRUE;

(gdb) p session
$2 = (nghttp2_session *) 0x7f143c79e0
(gdb) p *session
$3 = {
  streams = {
    table = 0x7f14db83f0, 
    mem = 0x7f143c8260, 
    size = 0xb, 
    tablelen = 0x100
  }, 
  root = {
    map_entry = {
      next = 0x0, 
      key = 0x0
    }, 
    pq_entry = {
      index = 0x0
    }, 
    obq = {
      q = 0x7f1458a590, 
      mem = 0x7f143c8260, 
      length = 0x0, 
      capacity = 0x4, 
      less = 0x7f8a277380 <stream_less at /home/thomaso/work/projects/bob_c_ares/dev/src/libs/ext-nghttp2/1/workspace/nghttp2-1.17.0/lib/nghttp2_stream.c:52>
    }, 
    content_length = 0xffffffffffffffff, 
    recv_content_length = 0x0, 
    descendant_last_cycle = 0x0, 
    cycle = 0x0, 
    descendant_next_seq = 0x5b, 
    seq = 0x0, 
    dep_prev = 0x0, 
    dep_next = 0x7f14afac20, 
    sib_prev = 0x0, 
    sib_next = 0x0, 
    closed_prev = 0x0, 
    closed_next = 0x0, 
    stream_user_data = 0x0, 
    item = 0x0, 
    last_writelen = 0x20, 
    stream_id = 0x0, 
    remote_window_size = 0x0, 
    recv_window_size = 0x0, 
    consumed_size = 0x0, 
    recv_reduction = 0x0, 
    local_window_size = 0x0, 
    weight = 0x10, 
    pending_penalty = 0x0, 
    sum_dep_weight = 0xb0, 
    state = NGHTTP2_STREAM_IDLE, 
    status_code = 0xffff, 
    http_flags = 0x0, 
    flags = 0x0, 
    shut_flags = 0x0, 
    queued = 0x0, 
    window_update_queued = 0x0
  }, 
  ob_urgent = {
    head = 0x0, 
    tail = 0x0, 
    n = 0x0
  }, 
  ob_reg = {
    head = 0x0, 
    tail = 0x0, 
    n = 0x0
  }, 
  ob_syn = {
    head = 0x7f14b37f30, 
    tail = 0x7f143a4820, 
    n = 0x99
  }, 
  aob = {
    item = 0x0, 
    framebufs = {
      head = 0x7f14b52ba0, 
      cur = 0x7f14b52ba0, 
      mem = 0x7f143c8260, 
      chunk_length = 0x400a, 
      max_chunk = 0x4, 
      chunk_used = 0x1, 
      chunk_keep = 0x1, 
      offset = 0xa
    }, 
    state = NGHTTP2_OB_POP_ITEM
  }, 
  iframe = {
    frame = {
      hd = {
        length = 0x0, 
        stream_id = 0x0, 
        type = 0x0, 
        flags = 0x0, 
        reserved = 0x0
      }, 
      data = {
        hd = {
          length = 0x0, 
          stream_id = 0x0, 
          type = 0x0, 
          flags = 0x0, 
          reserved = 0x0
        }, 
        padlen = 0x0
      }, 
      headers = {
        hd = {
          length = 0x0, 
          stream_id = 0x0, 
          type = 0x0, 
          flags = 0x0, 
          reserved = 0x0
        }, 
        padlen = 0x0, 
        pri_spec = {
          stream_id = 0x0, 
          weight = 0x0, 
          exclusive = 0x0
        }, 
        nva = 0x0, 
        nvlen = 0x0, 
        cat = NGHTTP2_HCAT_REQUEST
      }, 
      priority = {
        hd = {
          length = 0x0, 
          stream_id = 0x0, 
          type = 0x0, 
          flags = 0x0, 
          reserved = 0x0
        }, 
        pri_spec = {
          stream_id = 0x0, 
          weight = 0x0, 
          exclusive = 0x0
        }
      }, 
      rst_stream = {
        hd = {
          length = 0x0, 
          stream_id = 0x0, 
          type = 0x0, 
          flags = 0x0, 
          reserved = 0x0
        }, 
        error_code = 0x0
      }, 
      settings = {
        hd = {
          length = 0x0, 
          stream_id = 0x0, 
          type = 0x0, 
          flags = 0x0, 
          reserved = 0x0
        }, 
        niv = 0x0, 
        iv = 0x0
      }, 
      push_promise = {
        hd = {
          length = 0x0, 
          stream_id = 0x0, 
          type = 0x0, 
          flags = 0x0, 
          reserved = 0x0
        }, 
        padlen = 0x0, 
        nva = 0x0, 
        nvlen = 0x0, 
        promised_stream_id = 0x0, 
        reserved = 0x0
      }, 
      ping = {
        hd = {
          length = 0x0, 
          stream_id = 0x0, 
          type = 0x0, 
          flags = 0x0, 
          reserved = 0x0
        }, 
        opaque_data = "\000\000\000\000\000\000\000"
      }, 
      goaway = {
        hd = {
          length = 0x0, 
          stream_id = 0x0, 
          type = 0x0, 
          flags = 0x0, 
          reserved = 0x0
        }, 
        last_stream_id = 0x0, 
        error_code = 0x0, 
        opaque_data = 0x0, 
        opaque_data_len = 0x0, 
        reserved = 0x0
      }, 
      window_update = {
        hd = {
          length = 0x0, 
          stream_id = 0x0, 
          type = 0x0, 
          flags = 0x0, 
          reserved = 0x0
        }, 
        window_size_increment = 0x0, 
        reserved = 0x0
      }, 
      ext = {
        hd = {
          length = 0x0, 
          stream_id = 0x0, 
          type = 0x0, 
          flags = 0x0, 
          reserved = 0x0
        }, 
        payload = 0x0
      }
    }, 
    ext_frame_payload = {
      altsvc = {
        origin = 0x0, 
        origin_len = 0x0, 
        field_value = 0x0, 
        field_value_len = 0x0
      }
    }, 
    iv = 0x0, 
    sbuf = {
      begin = 0x7f143c7c5c "", 
      end = 0x7f143c7c65 "", 
      pos = 0x7f143c7c5c "", 
      last = 0x7f143c7c5c "", 
      mark = 0x7f143c7c65 ""
    }, 
    lbuf = {
      begin = 0x0, 
      end = 0x0, 
      pos = 0x0, 
      last = 0x0, 
      mark = 0x0
    }, 
    raw_lbuf = 0x0, 
    niv = 0x0, 
    max_niv = 0x0, 
    payloadleft = 0x0, 
    padlen = 0x0, 
    state = NGHTTP2_IB_READ_HEAD, 
    raw_sbuf = "\000\000\000\000\001\000\000\000U"
  }, 
  hd_deflater = {
    ctx = {
      hd_table = {
        buffer = 0x7f14db7bd0, 
        mask = 0x7f, 
        first = 0xfffffffffffffffc, 
        len = 0x4
      }, 
      mem = 0x7f143c8260, 
      hd_table_bufsize = 0xf1, 
      hd_table_bufsize_max = 0x1000, 
      next_seq = 0x4, 
      bad = 0x0
    }, 
    map = {
      table = {[0x0] = 0x0 <repeats 21 times>, [0x15] = 0x7f15593e80, [0x16] = 0x0, [0x17] = 0x0, [0x18] = 0x0, 
        [0x19] = 0x7f1491ed00, [0x1a] = 0x0 <repeats 15 times>, [0x29] = 0x7f15614570, 
        [0x2a] = 0x0 <repeats 52 times>, [0x5e] = 0x7f15601800, [0x5f] = 0x0 <repeats 33 times>}
    }, 
    deflate_hd_table_bufsize_max = 0x1000, 
    min_hd_table_bufsize_max = 0xffffffff, 
    notify_table_size_change = 0x0
  }, 
  hd_inflater = {
    ctx = {
      hd_table = {
        buffer = 0x7f14db7fe0, 
        mask = 0x7f, 
        first = 0xffffffffffffff82, 
        len = 0x3f
      }, 
      mem = 0x7f143c8260, 
      hd_table_bufsize = 0xfd9, 
      hd_table_bufsize_max = 0x1000, 
      next_seq = 0x7e, 
      bad = 0x0
    }, 
    huff_decode_ctx = {
      state = 0x38, 
      accept = 0x1
    }, 
    namebuf = {
      begin = 0x7f143cbab8 "x-application-context", 
      end = 0x7f143cbad7 "", 
      pos = 0x7f143cbab8 "x-application-context", 
      last = 0x7f143cbacd "", 
      mark = 0x7f143cbab8 "x-application-context"
    }, 
    valuebuf = {
      begin = 0x7f14aefaf8 "application:60124", 
      end = 0x7f14aefb11 "", 
      pos = 0x7f14aefaf8 "application:60124", 
      last = 0x7f14aefb09 "", 
      mark = 0x7f14aefaf8 "application:60124"
    }, 
    namercbuf = 0x0, 
    valuercbuf = 0x0, 
    nv_name_keep = 0x0, 
    nv_value_keep = 0x0, 
    left = 0x0, 
    index = 0x1b, 
    settings_hd_table_bufsize_max = 0x1000, 
    min_hd_table_bufsize_max = 0xffffffff, 
    shift = 0x0, 
    opcode = NGHTTP2_HD_OPCODE_NEWNAME, 
    state = NGHTTP2_HD_STATE_INFLATE_START, 
    huffman_encoded = 0x1, 
    index_required = 0x0, 
    no_index = 0x0
  }, 
  callbacks = {
    send_callback = 0x7f8a2e8320 <send_callback at http2.c:362>, 
    recv_callback = 0x0, 
    on_frame_recv_callback = 0x7f8a2e87f0 <on_frame_recv at http2.c:557>, 
    on_invalid_frame_recv_callback = 0x7f8a2e86f0 <on_invalid_frame_recv>, 
    on_data_chunk_recv_callback = 0x7f8a2e7ef0 <on_data_chunk_recv at http2.c:708>, 
    before_frame_send_callback = 0x7f8a2e8710 <before_frame_send>, 
    on_frame_send_callback = 0x7f8a2e7af0 <on_frame_send at http2.c:788>, 
    on_frame_not_send_callback = 0x7f8a2e7ad0 <on_frame_not_send at http2.c:802>, 
    on_stream_close_callback = 0x7f8a2e83a0 <on_stream_close at http2.c:826>, 
    on_begin_headers_callback = 0x7f8a2e7e80 <on_begin_headers at http2.c:857>, 
    on_header_callback = 0x7f8a2e7b10 <on_header at http2.c:920>, 
    on_header_callback2 = 0x0, 
    on_invalid_header_callback = 0x0, 
    on_invalid_header_callback2 = 0x0, 
    select_padding_callback = 0x0, 
    read_length_callback = 0x0, 
    on_begin_frame_callback = 0x0, 
    send_data_callback = 0x0, 
    pack_extension_callback = 0x0, 
    unpack_extension_callback = 0x0, 
    on_extension_chunk_recv_callback = 0x0, 
    error_callback = 0x7f8a2e7aa0 <error_callback at http2.c:1081>
  }, 
  mem = {
    mem_user_data = 0x0, 
    malloc = 0x7f8a2851f0 <default_malloc at /home/thomaso/work/projects/bob_c_ares/dev/src/libs/ext-nghttp2/1/workspace/nghttp2-1.17.0/lib/nghttp2_mem.c:28>, 
    free = 0x7f8a2851e0 <default_free at /home/thomaso/work/projects/bob_c_ares/dev/src/libs/ext-nghttp2/1/workspace/nghttp2-1.17.0/lib/nghttp2_mem.c:31>, 
    calloc = 0x7f8a2851d0 <default_calloc at /home/thomaso/work/projects/bob_c_ares/dev/src/libs/ext-nghttp2/1/workspace/nghttp2-1.17.0/lib/nghttp2_mem.c:35>, 
    realloc = 0x7f8a2851c0 <default_realloc at /home/thomaso/work/projects/bob_c_ares/dev/src/libs/ext-nghttp2/1/workspace/nghttp2-1.17.0/lib/nghttp2_mem.c:39>
  }, 
  last_cycle = 0x0, 
  user_data = 0x7f14ae7be8, 
  closed_stream_head = 0x0, 
  closed_stream_tail = 0x0, 
  idle_stream_head = 0x0, 
  idle_stream_tail = 0x0, 
  inflight_settings_head = 0x0, 
  num_outgoing_streams = 0xb, 
  num_incoming_streams = 0x0, 
  num_incoming_reserved_streams = 0x0, 
  max_incoming_reserved_streams = 0xc8, 
  num_closed_streams = 0x0, 
  num_idle_streams = 0x0, 
  nvbuflen = 0x0, 
  obq_flood_counter_ = 0x0, 
  max_send_header_block_length = 0x10000, 
  next_stream_id = 0x223, 
  last_sent_stream_id = 0xd1, 
  last_recv_stream_id = 0x0, 
  last_proc_stream_id = 0x0, 
  next_unique_id = 0x0, 
  local_last_stream_id = 0x7fffffff, 
  remote_last_stream_id = 0x7fffffff, 
  remote_window_size = 0x7ffffddc, 
  recv_window_size = 0x2251e, 
  consumed_size = 0x0, 
  recv_reduction = 0x0, 
  local_window_size = 0x40000000, 
  remote_settings = {
    header_table_size = 0x1000, 
    enable_push = 0x1, 
    max_concurrent_streams = 0x80, 
    initial_window_size = 0x10000, 
    max_frame_size = 0xffffff, 
    max_header_list_size = 0xffffffff
  }, 
  local_settings = {
    header_table_size = 0x1000, 
    enable_push = 0x1, 
    max_concurrent_streams = 0x64, 
    initial_window_size = 0x40000000, 
    max_frame_size = 0x4000, 
    max_header_list_size = 0xffffffff
  }, 
  opt_flags = 0x0, 
  pending_local_max_concurrent_stream = 0x64, 
  builtin_recv_ext_types = 0x0, 
  pending_enable_push = 0x1, 
  server = 0x0, 
  goaway_flags = 0x0, 
  window_update_queued = 0x0, 
  user_recv_ext_types = '\000' <repeats 31 times>
}
@ThomasObenaus

This comment has been minimized.

Show comment
Hide comment
@ThomasObenaus

ThomasObenaus Jun 27, 2018

@bagder: It looks that I can reproduce it with my setup quite good.
Do you have any more ideas, maybe code locations which I should instrument to track down the issue?

ThomasObenaus commented Jun 27, 2018

@bagder: It looks that I can reproduce it with my setup quite good.
Do you have any more ideas, maybe code locations which I should instrument to track down the issue?

@bagder

This comment has been minimized.

Show comment
Hide comment
@bagder

bagder Jun 27, 2018

Member

That's an incoming stream close. It looks like stream is perhaps pointing to already freed memory there? If that's so, can you figure out why/how it was freed already? It looks like the free in http2_disconnect() is a likely suspect but still seems weird... Can you run your code with valgrind? If so, does it help to point out any problem perhaps earlier?

If you have http2 debugging enabled you can see what stream id that ends there. Can you see anything wrong with that? Is there other streams going on at the same time?

p *session

That's the libnghttp2 handle, I don't think that helps us much because I think the problem is on the curl side.

Member

bagder commented Jun 27, 2018

That's an incoming stream close. It looks like stream is perhaps pointing to already freed memory there? If that's so, can you figure out why/how it was freed already? It looks like the free in http2_disconnect() is a likely suspect but still seems weird... Can you run your code with valgrind? If so, does it help to point out any problem perhaps earlier?

If you have http2 debugging enabled you can see what stream id that ends there. Can you see anything wrong with that? Is there other streams going on at the same time?

p *session

That's the libnghttp2 handle, I don't think that helps us much because I think the problem is on the curl side.

@ThomasObenaus

This comment has been minimized.

Show comment
Hide comment
@ThomasObenaus

ThomasObenaus Jun 28, 2018

With HTTP2_DEBUG enabled

Now I get an assert (only one time) at DEBUGASSERT(httpc->drain_total >= data->state.drain);

(gdb) p httpc->drain_total
$1 = 0x0
(gdb) p data->state.drain
$2 = 0x1
(gdb)

#0  0x0000007faa6851e8 in __GI_raise (sig=...) at ../sysdeps/unix/sysv/linux/raise.c:54
#1  0x0000007faa6865dc in __GI_abort () at abort.c:89
#2  0x0000007faa67e94c in __assert_fail_base (fmt=..., assertion=..., file=..., line=..., function=...) at assert.c:92
#3  0x0000007faa67e9e4 in __GI___assert_fail (assertion=..., file=..., line=..., function=...) at assert.c:101
#4  0x0000007fac775194 in http2_handle_stream_close (conn=..., data=..., stream=..., err=...) at http2.c:1370
#5  0x0000007fac775c68 in http2_recv (conn=..., sockindex=..., mem=..., len=..., err=...) at http2.c:1693
#6  0x0000007fac7442e0 in Curl_read (conn=..., sockfd=..., buf=..., sizerequested=..., n=...) at sendf.c:749
#7  0x0000007fac754db0 in readwrite_data (comeback=..., done=..., didwhat=..., k=..., conn=..., data=...)
    at transfer.c:482
#8  Curl_readwrite (conn=..., data=..., done=..., comeback=...) at transfer.c:1125
#9  0x0000007fac75f144 in multi_runsingle (multi=..., now=..., data=...) at multi.c:1914
#10 0x0000007fac75fb8c in curl_multi_perform (multi=..., running_handles=...) at multi.c:2181
#11 0x00000000017e6ff0 in tsd::nav::cloud::comm::client::HTTPRequestHandler::main() ()
#12 0x00000000027a3ecc in tsd::nav::cloud::comm::client::HTTPRequestHandler::run() ()
#13 0x0000007faaace510 in tsd::common::system::Thread::startImpl (arg=...)
    at /home/thomaso/work/projects/bob_c_ares/dev/src/system/tsd-common/1/workspace/tsd.common/src/tsd/common/system/Thread.cpp:310
#14 0x0000007faaad2040 in tsd::common::system::os::thread::pseudoStartThread (arg=...)
    at /home/thomaso/work/projects/bob_c_ares/dev/src/system/tsd-common/1/workspace/tsd.common/src/tsd/common/system/posix/POSIXThread.cpp:367
#15 0x0000007faaa28030 in start_thread (arg=...) at pthread_create.c:331
#16 0x0000007faa7194c0 in thread_start () at ../sysdeps/unix/sysv/linux/aarch64/clone.S:89

Last Log-Lines

16:50:35.040    [Debug]  [0x7f352d6a88] cURL [TEXT] Using Stream ID: e5 (easy handle 0x7f352d6a88)
16:50:35.040     [Warn]  [0x7f352d6a88] cURL [TEXT] h2 header: Authorization:Bearer bla
16:50:35.040    [Debug]  [0x7f352d6a88] cURL [TEXT] STATE: DO => DO_DONE handle 0x7f352d6a88; line 1695 (connection #3892)
16:50:35.040     [Warn]  [0x7f352d6a88] cURL [HEADER_OUT] GET /api/traffic/v2/tile/134766960/current HTTP/2
16:50:35.040    [Debug]  [0x7f352d6a88] cURL [TEXT] STATE: DO_DONE => WAITPERFORM handle 0x7f352d6a88; line 1822 (connection #3892)
16:50:35.044    [Debug]  [0x7f352d6a88] cURL [TEXT] STATE: WAITPERFORM => PERFORM handle 0x7f352d6a88; line 1837 (connection #3892)
16:50:35.044    [Debug]  [0x7f34657d88] cURL [TEXT] STATE: INIT => CONNECT handle 0x7f34657d88; line 1429 (connection #-5000)
16:50:35.044    [Debug]  [0x7f34657d88] cURL [TEXT] Found bundle for host blubb: 0x7f350ec088 [can multiplex]
16:50:35.044    [Debug]  [0x7f34657d88] cURL [TEXT] MAX_CONCURRENT_STREAMS reached, skip (128)
16:50:35.044    [Debug]  [0x7f34657d88] cURL [TEXT] Conn: 3892 (0x7f34af6ca8) Receive pipe weight: (-1/0), penalized: FALSE
16:50:35.044    [Debug]  [0x7f34657d88] cURL [TEXT] Multiplexed connection found!
16:50:35.044    [Debug]  [0x7f34657d88] cURL [TEXT] Found connection 3892, with requests in the pipe (69)
16:50:35.044    [Debug]  [0x7f34657d88] cURL [TEXT] Re-using existing connection! (#3892) with host blubb
16:50:35.044    [Debug]  [0x7f34657d88] cURL [TEXT] STATE: CONNECT => DO handle 0x7f34657d88; line 1474 (connection #3892)
16:50:35.044    [Debug]  [0x7f34657d88] cURL [TEXT] http2_send len=1074
16:50:35.044    [Debug]  [0x7f34657d88] cURL [TEXT] h2 header: :method:GET
16:50:35.044    [Debug]  [0x7f34657d88] cURL [TEXT] h2 header: :path:/api/traffic/v2/tile/134766962/current
16:50:35.044    [Debug]  [0x7f34657d88] cURL [TEXT] h2 header: :scheme:https
16:50:35.044    [Debug]  [0x7f34657d88] cURL [TEXT] h2 header: :authority:blubb
16:50:35.044    [Debug]  [0x7f34657d88] cURL [TEXT] h2 header: Accept-Encoding:deflate, gzip
16:50:35.045    [Debug]  [0x7f34657d88] cURL [TEXT] h2 header: accept:application/x-protobuf
16:50:35.045    [Debug]  [0x7f34657d88] cURL [TEXT] h2 header: content-type:application/x-protobuf
16:50:35.045    [Debug]  [0x7f34657d88] cURL [TEXT] Using Stream ID: e7 (easy handle 0x7f34657d88)
16:50:35.045     [Warn]  [0x7f34657d88] cURL [TEXT] h2 header: Authorization:Bearer bla
16:50:35.045     [Warn]  [0x7f34657d88] cURL [HEADER_OUT] GET /api/traffic/v2/tile/134766962/current HTTP/2
16:50:35.045    [Debug]  [0x7f34657d88] cURL [TEXT] STATE: DO => DO_DONE handle 0x7f34657d88; line 1695 (connection #3892)
16:50:35.045    [Debug]  [0x7f34657d88] cURL [TEXT] STATE: DO_DONE => WAITPERFORM handle 0x7f34657d88; line 1822 (connection #3892)
16:50:35.045    [Debug]  [0x7f34657d88] cURL [TEXT] STATE: WAITPERFORM => PERFORM handle 0x7f34657d88; line 1837 (connection #3892)
16:50:35.046    [Debug]  [0x7f34c84ab8] cURL [TEXT] Expire cleared
16:50:35.048    [Debug]  [0x7f34c69578] cURL [TEXT] Curl_readwrite: forcibly told to drain data
16:50:35.048    [Debug]  [0x7f34c69578] cURL [TEXT] http2_recv: easy 0x7f34c69578 (stream 411)

ThomasObenaus commented Jun 28, 2018

With HTTP2_DEBUG enabled

Now I get an assert (only one time) at DEBUGASSERT(httpc->drain_total >= data->state.drain);

(gdb) p httpc->drain_total
$1 = 0x0
(gdb) p data->state.drain
$2 = 0x1
(gdb)

#0  0x0000007faa6851e8 in __GI_raise (sig=...) at ../sysdeps/unix/sysv/linux/raise.c:54
#1  0x0000007faa6865dc in __GI_abort () at abort.c:89
#2  0x0000007faa67e94c in __assert_fail_base (fmt=..., assertion=..., file=..., line=..., function=...) at assert.c:92
#3  0x0000007faa67e9e4 in __GI___assert_fail (assertion=..., file=..., line=..., function=...) at assert.c:101
#4  0x0000007fac775194 in http2_handle_stream_close (conn=..., data=..., stream=..., err=...) at http2.c:1370
#5  0x0000007fac775c68 in http2_recv (conn=..., sockindex=..., mem=..., len=..., err=...) at http2.c:1693
#6  0x0000007fac7442e0 in Curl_read (conn=..., sockfd=..., buf=..., sizerequested=..., n=...) at sendf.c:749
#7  0x0000007fac754db0 in readwrite_data (comeback=..., done=..., didwhat=..., k=..., conn=..., data=...)
    at transfer.c:482
#8  Curl_readwrite (conn=..., data=..., done=..., comeback=...) at transfer.c:1125
#9  0x0000007fac75f144 in multi_runsingle (multi=..., now=..., data=...) at multi.c:1914
#10 0x0000007fac75fb8c in curl_multi_perform (multi=..., running_handles=...) at multi.c:2181
#11 0x00000000017e6ff0 in tsd::nav::cloud::comm::client::HTTPRequestHandler::main() ()
#12 0x00000000027a3ecc in tsd::nav::cloud::comm::client::HTTPRequestHandler::run() ()
#13 0x0000007faaace510 in tsd::common::system::Thread::startImpl (arg=...)
    at /home/thomaso/work/projects/bob_c_ares/dev/src/system/tsd-common/1/workspace/tsd.common/src/tsd/common/system/Thread.cpp:310
#14 0x0000007faaad2040 in tsd::common::system::os::thread::pseudoStartThread (arg=...)
    at /home/thomaso/work/projects/bob_c_ares/dev/src/system/tsd-common/1/workspace/tsd.common/src/tsd/common/system/posix/POSIXThread.cpp:367
#15 0x0000007faaa28030 in start_thread (arg=...) at pthread_create.c:331
#16 0x0000007faa7194c0 in thread_start () at ../sysdeps/unix/sysv/linux/aarch64/clone.S:89

Last Log-Lines

16:50:35.040    [Debug]  [0x7f352d6a88] cURL [TEXT] Using Stream ID: e5 (easy handle 0x7f352d6a88)
16:50:35.040     [Warn]  [0x7f352d6a88] cURL [TEXT] h2 header: Authorization:Bearer bla
16:50:35.040    [Debug]  [0x7f352d6a88] cURL [TEXT] STATE: DO => DO_DONE handle 0x7f352d6a88; line 1695 (connection #3892)
16:50:35.040     [Warn]  [0x7f352d6a88] cURL [HEADER_OUT] GET /api/traffic/v2/tile/134766960/current HTTP/2
16:50:35.040    [Debug]  [0x7f352d6a88] cURL [TEXT] STATE: DO_DONE => WAITPERFORM handle 0x7f352d6a88; line 1822 (connection #3892)
16:50:35.044    [Debug]  [0x7f352d6a88] cURL [TEXT] STATE: WAITPERFORM => PERFORM handle 0x7f352d6a88; line 1837 (connection #3892)
16:50:35.044    [Debug]  [0x7f34657d88] cURL [TEXT] STATE: INIT => CONNECT handle 0x7f34657d88; line 1429 (connection #-5000)
16:50:35.044    [Debug]  [0x7f34657d88] cURL [TEXT] Found bundle for host blubb: 0x7f350ec088 [can multiplex]
16:50:35.044    [Debug]  [0x7f34657d88] cURL [TEXT] MAX_CONCURRENT_STREAMS reached, skip (128)
16:50:35.044    [Debug]  [0x7f34657d88] cURL [TEXT] Conn: 3892 (0x7f34af6ca8) Receive pipe weight: (-1/0), penalized: FALSE
16:50:35.044    [Debug]  [0x7f34657d88] cURL [TEXT] Multiplexed connection found!
16:50:35.044    [Debug]  [0x7f34657d88] cURL [TEXT] Found connection 3892, with requests in the pipe (69)
16:50:35.044    [Debug]  [0x7f34657d88] cURL [TEXT] Re-using existing connection! (#3892) with host blubb
16:50:35.044    [Debug]  [0x7f34657d88] cURL [TEXT] STATE: CONNECT => DO handle 0x7f34657d88; line 1474 (connection #3892)
16:50:35.044    [Debug]  [0x7f34657d88] cURL [TEXT] http2_send len=1074
16:50:35.044    [Debug]  [0x7f34657d88] cURL [TEXT] h2 header: :method:GET
16:50:35.044    [Debug]  [0x7f34657d88] cURL [TEXT] h2 header: :path:/api/traffic/v2/tile/134766962/current
16:50:35.044    [Debug]  [0x7f34657d88] cURL [TEXT] h2 header: :scheme:https
16:50:35.044    [Debug]  [0x7f34657d88] cURL [TEXT] h2 header: :authority:blubb
16:50:35.044    [Debug]  [0x7f34657d88] cURL [TEXT] h2 header: Accept-Encoding:deflate, gzip
16:50:35.045    [Debug]  [0x7f34657d88] cURL [TEXT] h2 header: accept:application/x-protobuf
16:50:35.045    [Debug]  [0x7f34657d88] cURL [TEXT] h2 header: content-type:application/x-protobuf
16:50:35.045    [Debug]  [0x7f34657d88] cURL [TEXT] Using Stream ID: e7 (easy handle 0x7f34657d88)
16:50:35.045     [Warn]  [0x7f34657d88] cURL [TEXT] h2 header: Authorization:Bearer bla
16:50:35.045     [Warn]  [0x7f34657d88] cURL [HEADER_OUT] GET /api/traffic/v2/tile/134766962/current HTTP/2
16:50:35.045    [Debug]  [0x7f34657d88] cURL [TEXT] STATE: DO => DO_DONE handle 0x7f34657d88; line 1695 (connection #3892)
16:50:35.045    [Debug]  [0x7f34657d88] cURL [TEXT] STATE: DO_DONE => WAITPERFORM handle 0x7f34657d88; line 1822 (connection #3892)
16:50:35.045    [Debug]  [0x7f34657d88] cURL [TEXT] STATE: WAITPERFORM => PERFORM handle 0x7f34657d88; line 1837 (connection #3892)
16:50:35.046    [Debug]  [0x7f34c84ab8] cURL [TEXT] Expire cleared
16:50:35.048    [Debug]  [0x7f34c69578] cURL [TEXT] Curl_readwrite: forcibly told to drain data
16:50:35.048    [Debug]  [0x7f34c69578] cURL [TEXT] http2_recv: easy 0x7f34c69578 (stream 411)

@ThomasObenaus

This comment has been minimized.

Show comment
Hide comment
@ThomasObenaus

ThomasObenaus Jun 28, 2018

Next time again a segfault at Curl_Debug as in my first post.
Again the easy_handle seams to be destroyed.

#0  __GI__IO_fwrite (buf=..., size=..., count=..., fp=...) at iofwrite.c:37
#1  0x0000007f98d0d484 in Curl_debug (data=..., type=..., ptr=..., size=...) at sendf.c:819
#2  0x0000007f98d0d56c in Curl_infof (data=..., fmt=...) at sendf.c:243
#3  0x0000007f98d3cafc in on_frame_not_send (session=..., frame=..., lib_error_code=..., userp=...) at http2.c:813
#4  0x0000007f98cd2380 in nghttp2_session_mem_send_internal (session=..., data_ptr=..., fast_cb=...) at /home/thomaso/work/projects/bob_c_ares/dev/src/libs/ext-nghttp2/1/workspace/nghttp2-1.17.0/lib/nghttp2_session.c:2914
#5  0x0000007f98cd2c04 in nghttp2_session_send (session=...) at /home/thomaso/work/projects/bob_c_ares/dev/src/libs/ext-nghttp2/1/workspace/nghttp2-1.17.0/lib/nghttp2_session.c:3215
#6  0x0000007f98d3d39c in h2_session_send (data=..., h2=...) at http2.c:1478
#7  0x0000007f98d3ee34 in http2_recv (conn=..., sockindex=..., mem=..., len=..., err=...) at http2.c:1658
#8  0x0000007f98d0d2e0 in Curl_read (conn=..., sockfd=..., buf=..., sizerequested=..., n=...) at sendf.c:749
#9  0x0000007f98d1ddb0 in readwrite_data (comeback=..., done=..., didwhat=..., k=..., conn=..., data=...) at transfer.c:482
#10 Curl_readwrite (conn=..., data=..., done=..., comeback=...) at transfer.c:1125
#11 0x0000007f98d28144 in multi_runsingle (multi=..., now=..., data=...) at multi.c:1914
#12 0x0000007f98d28b8c in curl_multi_perform (multi=..., running_handles=...) at multi.c:2181
#13 0x00000000017e6ff0 in tsd::nav::cloud::comm::client::HTTPRequestHandler::main() ()
#14 0x00000000027a3ecc in tsd::nav::cloud::comm::client::HTTPRequestHandler::run() ()
#15 0x0000007f97097510 in tsd::common::system::Thread::startImpl (arg=...) at /home/thomaso/work/projects/bob_c_ares/dev/src/system/tsd-common/1/workspace/tsd.common/src/tsd/common/system/Thread.cpp:310
#16 0x0000007f9709b040 in tsd::common::system::os::thread::pseudoStartThread (arg=...) at /home/thomaso/work/projects/bob_c_ares/dev/src/system/tsd-common/1/workspace/tsd.common/src/tsd/common/system/posix/POSIXThread.cpp:367
#17 0x0000007f96ff1030 in start_thread (arg=...) at pthread_create.c:331
#18 0x0000007f96ce24c0 in thread_start () at ../sysdeps/unix/sysv/linux/aarch64/clone.S:89
(gdb) p data
Attempt to use a type name as an expression
(gdb) f 1
#1  0x0000007f98d0d484 in Curl_debug (data=..., type=..., ptr=..., size=...) at sendf.c:819
819	      fwrite(s_infotype[type], 2, 1, data->set.err);
(gdb) p data->magic 
$1 = 0x21114638
(gdb) p data
$2 = (struct Curl_easy *) 0x7f2110f368

Last Log-Lines

17:02:20.677    [0x7f20b75738] cURL [TEXT] h2 header: Content-Length:41
17:02:20.677    [0x7f20b75738] cURL [TEXT] Using Stream ID: df (easy handle 0x7f20b75738)
17:02:20.677    [0x7f20b75738] cURL [TEXT] h2 header: Authorization:Bearer bla
17:02:20.677    [0x7f20b75738] cURL [TEXT] STATE: DO => DO_DONE handle 0x7f20b75738; line 1695 (connection #24089)
17:02:20.677    [0x7f20b75738] cURL [TEXT] STATE: DO_DONE => WAITPERFORM handle 0x7f20b75738; line 1822 (connection #24089)
17:02:20.677    [0x7f20b75738] cURL [TEXT] STATE: WAITPERFORM => PERFORM handle 0x7f20b75738; line 1837 (connection #24089)
17:02:20.677    [0x7f20b75738] cURL [HEADER_OUT] POST /api/route/v1/calc/ HTTP/2
17:02:20.677    [0x7f20b90c78] cURL [TEXT] STATE: INIT => CONNECT handle 0x7f20b90c78; line 1429 (connection #-5000)
17:02:20.678    [0x7f20b90c78] cURL [TEXT] Found bundle for host blubb: 0x7f20b0e8a8 [can multiplex]
17:02:20.678    [0x7f20b90c78] cURL [TEXT] Conn: 24089 (0x7f204fa358) Receive pipe weight: (-1/0), penalized: FALSE
17:02:20.678    [0x7f20b90c78] cURL [TEXT] Multiplexed connection found!
17:02:20.678    [0x7f20b90c78] cURL [TEXT] Found connection 24089, with requests in the pipe (98)
17:02:20.678    [0x7f20b90c78] cURL [TEXT] Re-using existing connection! (#24089) with host blubb
17:02:20.678    [0x7f20b90c78] cURL [TEXT] STATE: CONNECT => DO handle 0x7f20b90c78; line 1474 (connection #24089)
17:02:20.678    [0x7f20b90c78] cURL [TEXT] http2_send len=1076
17:02:20.678    [0x7f20b90c78] cURL [TEXT] h2 header: :method:POST
17:02:20.678    [0x7f20b90c78] cURL [TEXT] h2 header: :path:/api/destin/v1/slde
17:02:20.678    [0x7f20b90c78] cURL [TEXT] h2 header: :scheme:https
17:02:20.678    [0x7f20b90c78] cURL [TEXT] h2 header: :authority:blubb
17:02:20.678    [0x7f20b90c78] cURL [TEXT] h2 header: Accept-Encoding:deflate, gzip
17:02:20.678    [0x7f20b90c78] cURL [TEXT] h2 header: accept:application/x-protobuf
17:02:20.678    [0x7f20b90c78] cURL [TEXT] h2 header: content-type:application/x-protobuf
17:02:20.678    [0x7f20b90c78] cURL [TEXT] h2 header: Content-Length:25
17:02:20.678    [0x7f20b90c78] cURL [TEXT] Using Stream ID: e1 (easy handle 0x7f20b90c78)
17:02:20.678    [0x7f20b90c78] cURL [TEXT] h2 header: Authorization:Bearer bla
17:02:20.678    [0x7f20b90c78] cURL [TEXT] STATE: DO => DO_DONE handle 0x7f20b90c78; line 1695 (connection #24089)
17:02:20.678    [0x7f20b90c78] cURL [HEADER_OUT] POST /api/destin/v1/slde HTTP/2
17:02:20.678    [0x7f20b90c78] cURL [TEXT] STATE: DO_DONE => WAITPERFORM handle 0x7f20b90c78; line 1822 (connection #24089)
17:02:20.678    [0x7f20b90c78] cURL [TEXT] STATE: WAITPERFORM => PERFORM handle 0x7f20b90c78; line 1837 (connection #24089)
17:02:20.678    [0x7f20bac1b8] cURL [TEXT] STATE: INIT => CONNECT handle 0x7f20bac1b8; line 1429 (connection #-5000)
17:02:20.678    [0x7f20bac1b8] cURL [TEXT] Found bundle for host blubb: 0x7f20b0e8a8 [can multiplex]
17:02:20.678    [0x7f20bac1b8] cURL [TEXT] Conn: 24089 (0x7f204fa358) Receive pipe weight: (-1/0), penalized: FALSE
17:02:20.678    [0x7f20bac1b8] cURL [TEXT] Multiplexed connection found!
17:02:20.678    [0x7f20bac1b8] cURL [TEXT] Found connection 24089, with requests in the pipe (99)
17:02:20.678    [0x7f20bac1b8] cURL [TEXT] Re-using existing connection! (#24089) with host blubb
17:02:20.679    [0x7f20bac1b8] cURL [TEXT] STATE: CONNECT => DO handle 0x7f20bac1b8; line 1474 (connection #24089)
17:02:20.679    [0x7f20bac1b8] cURL [TEXT] http2_send len=1081
17:02:20.679    [0x7f20bac1b8] cURL [TEXT] h2 header: :method:POST
17:02:20.679    [0x7f20bac1b8] cURL [TEXT] h2 header: :path:/api/poi/parking/v1/list
17:02:20.679    [0x7f20bac1b8] cURL [TEXT] h2 header: :scheme:https
17:02:20.679    [0x7f20bac1b8] cURL [TEXT] h2 header: :authority:blubb
17:02:20.679    [0x7f20bac1b8] cURL [TEXT] h2 header: Accept-Encoding:deflate, gzip
17:02:20.679    [0x7f20bac1b8] cURL [TEXT] h2 header: accept:application/x-protobuf
17:02:20.679    [0x7f20bac1b8] cURL [TEXT] h2 header: content-type:application/x-protobuf
17:02:20.679    [0x7f20bac1b8] cURL [TEXT] h2 header: Content-Length:32
17:02:20.679    [0x7f20bac1b8] cURL [TEXT] Using Stream ID: e3 (easy handle 0x7f20bac1b8)
17:02:20.679    [0x7f20bac1b8] cURL [TEXT] h2 header: Authorization:Bearer bla
17:02:20.679    [0x7f20bac1b8] cURL [TEXT] STATE: DO => DO_DONE handle 0x7f20bac1b8; line 1695 (connection #24089)
17:02:20.679    [0x7f20bac1b8] cURL [HEADER_OUT] POST /api/poi/parking/v1/list HTTP/2
17:02:20.679    [0x7f20bac1b8] cURL [TEXT] STATE: DO_DONE => WAITPERFORM handle 0x7f20bac1b8; line 1822 (connection #24089)
17:02:20.679    [0x7f20bac1b8] cURL [TEXT] STATE: WAITPERFORM => PERFORM handle 0x7f20bac1b8; line 1837 (connection #24089)
17:02:20.679    [0x7f20bc76f8] cURL [TEXT] STATE: INIT => CONNECT handle 0x7f20bc76f8; line 1429 (connection #-5000)
17:02:20.679    [0x7f20bc76f8] cURL [TEXT] Found bundle for host blubb: 0x7f20b0e8a8 [can multiplex]
17:02:20.679    [0x7f20bc76f8] cURL [TEXT] Conn: 24089 (0x7f204fa358) Receive pipe weight: (-1/0), penalized: FALSE
17:02:20.679    [0x7f20bc76f8] cURL [TEXT] Multiplexed connection found!
17:02:20.679    [0x7f20bc76f8] cURL [TEXT] Found connection 24089, with requests in the pipe (100)
17:02:20.679    [0x7f20bc76f8] cURL [TEXT] Re-using existing connection! (#24089) with host blubb
17:02:20.679    [0x7f20bc76f8] cURL [TEXT] STATE: CONNECT => DO handle 0x7f20bc76f8; line 1474 (connection #24089)
17:02:20.679    [0x7f20bc76f8] cURL [TEXT] http2_send len=1062
17:02:20.679    [0x7f20bc76f8] cURL [TEXT] h2 header: :method:GET
17:02:20.679    [0x7f20bc76f8] cURL [TEXT] h2 header: :path:/api/mapupdate/v1/version/
17:02:20.679    [0x7f20bc76f8] cURL [TEXT] h2 header: :scheme:https
17:02:20.679    [0x7f20bc76f8] cURL [TEXT] h2 header: :authority:blubb
17:02:20.679    [0x7f20bc76f8] cURL [TEXT] h2 header: Accept-Encoding:deflate, gzip
17:02:20.680    [0x7f20bc76f8] cURL [TEXT] h2 header: accept:application/x-protobuf
17:02:20.680    [0x7f20bc76f8] cURL [TEXT] h2 header: content-type:application/x-protobuf
17:02:20.680    [0x7f20bc76f8] cURL [TEXT] Using Stream ID: e5 (easy handle 0x7f20bc76f8)
17:02:20.680    [0x7f20bc76f8] cURL [TEXT] h2 header: Authorization:Bearer bla
17:02:20.680    [0x7f20bc76f8] cURL [TEXT] STATE: DO => DO_DONE handle 0x7f20bc76f8; line 1695 (connection #24089)
17:02:20.680    [0x7f20bc76f8] cURL [HEADER_OUT] GET /api/mapupdate/v1/version/ HTTP/2
17:02:20.680    [0x7f20bc76f8] cURL [TEXT] STATE: DO_DONE => WAITPERFORM handle 0x7f20bc76f8; line 1822 (connection #24089)
17:02:20.680    [0x7f20bc76f8] cURL [TEXT] STATE: WAITPERFORM => PERFORM handle 0x7f20bc76f8; line 1837 (connection #24089)
17:02:23.618    [0x7f20b05b58] cURL [TEXT] http2_recv: easy 0x7f20b05b58 (stream 261)
17:02:23.619    [0x7f20b05b58] cURL [TEXT] nread=223
17:02:23.619    [0x7f20b05b58] cURL [TEXT] nghttp2_session_mem_recv() returns 223
17:02:23.619    [0x7f20b05b58] cURL [TEXT] All data in connection buffer processed

All Log-Lines mentioning the weird easy_handle

17:02:05.936 [0x7f2110f368] cURL [TEXT] STATE: INIT => CONNECT handle 0x7f2110f368; line 1429 (connection #-5000)
17:02:05.936 [0x7f2110f368] cURL [TEXT] STATE: CONNECT => DO handle 0x7f2110f368; line 1474 (connection #24088)
17:02:05.937 [0x7f2110f368] cURL [TEXT] Using Stream ID: 51 (easy handle 0x7f2110f368)
17:02:05.937 [0x7f2110f368] cURL [TEXT] STATE: DO => DO_DONE handle 0x7f2110f368; line 1695 (connection #24088)
17:02:05.937 [0x7f2110f368] cURL [TEXT] STATE: DO_DONE => WAITPERFORM handle 0x7f2110f368; line 1822 (connection #24088)
17:02:05.937 [0x7f2110f368] cURL [TEXT] STATE: WAITPERFORM => PERFORM handle 0x7f2110f368; line 1837 (connection #24088)

ThomasObenaus commented Jun 28, 2018

Next time again a segfault at Curl_Debug as in my first post.
Again the easy_handle seams to be destroyed.

#0  __GI__IO_fwrite (buf=..., size=..., count=..., fp=...) at iofwrite.c:37
#1  0x0000007f98d0d484 in Curl_debug (data=..., type=..., ptr=..., size=...) at sendf.c:819
#2  0x0000007f98d0d56c in Curl_infof (data=..., fmt=...) at sendf.c:243
#3  0x0000007f98d3cafc in on_frame_not_send (session=..., frame=..., lib_error_code=..., userp=...) at http2.c:813
#4  0x0000007f98cd2380 in nghttp2_session_mem_send_internal (session=..., data_ptr=..., fast_cb=...) at /home/thomaso/work/projects/bob_c_ares/dev/src/libs/ext-nghttp2/1/workspace/nghttp2-1.17.0/lib/nghttp2_session.c:2914
#5  0x0000007f98cd2c04 in nghttp2_session_send (session=...) at /home/thomaso/work/projects/bob_c_ares/dev/src/libs/ext-nghttp2/1/workspace/nghttp2-1.17.0/lib/nghttp2_session.c:3215
#6  0x0000007f98d3d39c in h2_session_send (data=..., h2=...) at http2.c:1478
#7  0x0000007f98d3ee34 in http2_recv (conn=..., sockindex=..., mem=..., len=..., err=...) at http2.c:1658
#8  0x0000007f98d0d2e0 in Curl_read (conn=..., sockfd=..., buf=..., sizerequested=..., n=...) at sendf.c:749
#9  0x0000007f98d1ddb0 in readwrite_data (comeback=..., done=..., didwhat=..., k=..., conn=..., data=...) at transfer.c:482
#10 Curl_readwrite (conn=..., data=..., done=..., comeback=...) at transfer.c:1125
#11 0x0000007f98d28144 in multi_runsingle (multi=..., now=..., data=...) at multi.c:1914
#12 0x0000007f98d28b8c in curl_multi_perform (multi=..., running_handles=...) at multi.c:2181
#13 0x00000000017e6ff0 in tsd::nav::cloud::comm::client::HTTPRequestHandler::main() ()
#14 0x00000000027a3ecc in tsd::nav::cloud::comm::client::HTTPRequestHandler::run() ()
#15 0x0000007f97097510 in tsd::common::system::Thread::startImpl (arg=...) at /home/thomaso/work/projects/bob_c_ares/dev/src/system/tsd-common/1/workspace/tsd.common/src/tsd/common/system/Thread.cpp:310
#16 0x0000007f9709b040 in tsd::common::system::os::thread::pseudoStartThread (arg=...) at /home/thomaso/work/projects/bob_c_ares/dev/src/system/tsd-common/1/workspace/tsd.common/src/tsd/common/system/posix/POSIXThread.cpp:367
#17 0x0000007f96ff1030 in start_thread (arg=...) at pthread_create.c:331
#18 0x0000007f96ce24c0 in thread_start () at ../sysdeps/unix/sysv/linux/aarch64/clone.S:89
(gdb) p data
Attempt to use a type name as an expression
(gdb) f 1
#1  0x0000007f98d0d484 in Curl_debug (data=..., type=..., ptr=..., size=...) at sendf.c:819
819	      fwrite(s_infotype[type], 2, 1, data->set.err);
(gdb) p data->magic 
$1 = 0x21114638
(gdb) p data
$2 = (struct Curl_easy *) 0x7f2110f368

Last Log-Lines

17:02:20.677    [0x7f20b75738] cURL [TEXT] h2 header: Content-Length:41
17:02:20.677    [0x7f20b75738] cURL [TEXT] Using Stream ID: df (easy handle 0x7f20b75738)
17:02:20.677    [0x7f20b75738] cURL [TEXT] h2 header: Authorization:Bearer bla
17:02:20.677    [0x7f20b75738] cURL [TEXT] STATE: DO => DO_DONE handle 0x7f20b75738; line 1695 (connection #24089)
17:02:20.677    [0x7f20b75738] cURL [TEXT] STATE: DO_DONE => WAITPERFORM handle 0x7f20b75738; line 1822 (connection #24089)
17:02:20.677    [0x7f20b75738] cURL [TEXT] STATE: WAITPERFORM => PERFORM handle 0x7f20b75738; line 1837 (connection #24089)
17:02:20.677    [0x7f20b75738] cURL [HEADER_OUT] POST /api/route/v1/calc/ HTTP/2
17:02:20.677    [0x7f20b90c78] cURL [TEXT] STATE: INIT => CONNECT handle 0x7f20b90c78; line 1429 (connection #-5000)
17:02:20.678    [0x7f20b90c78] cURL [TEXT] Found bundle for host blubb: 0x7f20b0e8a8 [can multiplex]
17:02:20.678    [0x7f20b90c78] cURL [TEXT] Conn: 24089 (0x7f204fa358) Receive pipe weight: (-1/0), penalized: FALSE
17:02:20.678    [0x7f20b90c78] cURL [TEXT] Multiplexed connection found!
17:02:20.678    [0x7f20b90c78] cURL [TEXT] Found connection 24089, with requests in the pipe (98)
17:02:20.678    [0x7f20b90c78] cURL [TEXT] Re-using existing connection! (#24089) with host blubb
17:02:20.678    [0x7f20b90c78] cURL [TEXT] STATE: CONNECT => DO handle 0x7f20b90c78; line 1474 (connection #24089)
17:02:20.678    [0x7f20b90c78] cURL [TEXT] http2_send len=1076
17:02:20.678    [0x7f20b90c78] cURL [TEXT] h2 header: :method:POST
17:02:20.678    [0x7f20b90c78] cURL [TEXT] h2 header: :path:/api/destin/v1/slde
17:02:20.678    [0x7f20b90c78] cURL [TEXT] h2 header: :scheme:https
17:02:20.678    [0x7f20b90c78] cURL [TEXT] h2 header: :authority:blubb
17:02:20.678    [0x7f20b90c78] cURL [TEXT] h2 header: Accept-Encoding:deflate, gzip
17:02:20.678    [0x7f20b90c78] cURL [TEXT] h2 header: accept:application/x-protobuf
17:02:20.678    [0x7f20b90c78] cURL [TEXT] h2 header: content-type:application/x-protobuf
17:02:20.678    [0x7f20b90c78] cURL [TEXT] h2 header: Content-Length:25
17:02:20.678    [0x7f20b90c78] cURL [TEXT] Using Stream ID: e1 (easy handle 0x7f20b90c78)
17:02:20.678    [0x7f20b90c78] cURL [TEXT] h2 header: Authorization:Bearer bla
17:02:20.678    [0x7f20b90c78] cURL [TEXT] STATE: DO => DO_DONE handle 0x7f20b90c78; line 1695 (connection #24089)
17:02:20.678    [0x7f20b90c78] cURL [HEADER_OUT] POST /api/destin/v1/slde HTTP/2
17:02:20.678    [0x7f20b90c78] cURL [TEXT] STATE: DO_DONE => WAITPERFORM handle 0x7f20b90c78; line 1822 (connection #24089)
17:02:20.678    [0x7f20b90c78] cURL [TEXT] STATE: WAITPERFORM => PERFORM handle 0x7f20b90c78; line 1837 (connection #24089)
17:02:20.678    [0x7f20bac1b8] cURL [TEXT] STATE: INIT => CONNECT handle 0x7f20bac1b8; line 1429 (connection #-5000)
17:02:20.678    [0x7f20bac1b8] cURL [TEXT] Found bundle for host blubb: 0x7f20b0e8a8 [can multiplex]
17:02:20.678    [0x7f20bac1b8] cURL [TEXT] Conn: 24089 (0x7f204fa358) Receive pipe weight: (-1/0), penalized: FALSE
17:02:20.678    [0x7f20bac1b8] cURL [TEXT] Multiplexed connection found!
17:02:20.678    [0x7f20bac1b8] cURL [TEXT] Found connection 24089, with requests in the pipe (99)
17:02:20.678    [0x7f20bac1b8] cURL [TEXT] Re-using existing connection! (#24089) with host blubb
17:02:20.679    [0x7f20bac1b8] cURL [TEXT] STATE: CONNECT => DO handle 0x7f20bac1b8; line 1474 (connection #24089)
17:02:20.679    [0x7f20bac1b8] cURL [TEXT] http2_send len=1081
17:02:20.679    [0x7f20bac1b8] cURL [TEXT] h2 header: :method:POST
17:02:20.679    [0x7f20bac1b8] cURL [TEXT] h2 header: :path:/api/poi/parking/v1/list
17:02:20.679    [0x7f20bac1b8] cURL [TEXT] h2 header: :scheme:https
17:02:20.679    [0x7f20bac1b8] cURL [TEXT] h2 header: :authority:blubb
17:02:20.679    [0x7f20bac1b8] cURL [TEXT] h2 header: Accept-Encoding:deflate, gzip
17:02:20.679    [0x7f20bac1b8] cURL [TEXT] h2 header: accept:application/x-protobuf
17:02:20.679    [0x7f20bac1b8] cURL [TEXT] h2 header: content-type:application/x-protobuf
17:02:20.679    [0x7f20bac1b8] cURL [TEXT] h2 header: Content-Length:32
17:02:20.679    [0x7f20bac1b8] cURL [TEXT] Using Stream ID: e3 (easy handle 0x7f20bac1b8)
17:02:20.679    [0x7f20bac1b8] cURL [TEXT] h2 header: Authorization:Bearer bla
17:02:20.679    [0x7f20bac1b8] cURL [TEXT] STATE: DO => DO_DONE handle 0x7f20bac1b8; line 1695 (connection #24089)
17:02:20.679    [0x7f20bac1b8] cURL [HEADER_OUT] POST /api/poi/parking/v1/list HTTP/2
17:02:20.679    [0x7f20bac1b8] cURL [TEXT] STATE: DO_DONE => WAITPERFORM handle 0x7f20bac1b8; line 1822 (connection #24089)
17:02:20.679    [0x7f20bac1b8] cURL [TEXT] STATE: WAITPERFORM => PERFORM handle 0x7f20bac1b8; line 1837 (connection #24089)
17:02:20.679    [0x7f20bc76f8] cURL [TEXT] STATE: INIT => CONNECT handle 0x7f20bc76f8; line 1429 (connection #-5000)
17:02:20.679    [0x7f20bc76f8] cURL [TEXT] Found bundle for host blubb: 0x7f20b0e8a8 [can multiplex]
17:02:20.679    [0x7f20bc76f8] cURL [TEXT] Conn: 24089 (0x7f204fa358) Receive pipe weight: (-1/0), penalized: FALSE
17:02:20.679    [0x7f20bc76f8] cURL [TEXT] Multiplexed connection found!
17:02:20.679    [0x7f20bc76f8] cURL [TEXT] Found connection 24089, with requests in the pipe (100)
17:02:20.679    [0x7f20bc76f8] cURL [TEXT] Re-using existing connection! (#24089) with host blubb
17:02:20.679    [0x7f20bc76f8] cURL [TEXT] STATE: CONNECT => DO handle 0x7f20bc76f8; line 1474 (connection #24089)
17:02:20.679    [0x7f20bc76f8] cURL [TEXT] http2_send len=1062
17:02:20.679    [0x7f20bc76f8] cURL [TEXT] h2 header: :method:GET
17:02:20.679    [0x7f20bc76f8] cURL [TEXT] h2 header: :path:/api/mapupdate/v1/version/
17:02:20.679    [0x7f20bc76f8] cURL [TEXT] h2 header: :scheme:https
17:02:20.679    [0x7f20bc76f8] cURL [TEXT] h2 header: :authority:blubb
17:02:20.679    [0x7f20bc76f8] cURL [TEXT] h2 header: Accept-Encoding:deflate, gzip
17:02:20.680    [0x7f20bc76f8] cURL [TEXT] h2 header: accept:application/x-protobuf
17:02:20.680    [0x7f20bc76f8] cURL [TEXT] h2 header: content-type:application/x-protobuf
17:02:20.680    [0x7f20bc76f8] cURL [TEXT] Using Stream ID: e5 (easy handle 0x7f20bc76f8)
17:02:20.680    [0x7f20bc76f8] cURL [TEXT] h2 header: Authorization:Bearer bla
17:02:20.680    [0x7f20bc76f8] cURL [TEXT] STATE: DO => DO_DONE handle 0x7f20bc76f8; line 1695 (connection #24089)
17:02:20.680    [0x7f20bc76f8] cURL [HEADER_OUT] GET /api/mapupdate/v1/version/ HTTP/2
17:02:20.680    [0x7f20bc76f8] cURL [TEXT] STATE: DO_DONE => WAITPERFORM handle 0x7f20bc76f8; line 1822 (connection #24089)
17:02:20.680    [0x7f20bc76f8] cURL [TEXT] STATE: WAITPERFORM => PERFORM handle 0x7f20bc76f8; line 1837 (connection #24089)
17:02:23.618    [0x7f20b05b58] cURL [TEXT] http2_recv: easy 0x7f20b05b58 (stream 261)
17:02:23.619    [0x7f20b05b58] cURL [TEXT] nread=223
17:02:23.619    [0x7f20b05b58] cURL [TEXT] nghttp2_session_mem_recv() returns 223
17:02:23.619    [0x7f20b05b58] cURL [TEXT] All data in connection buffer processed

All Log-Lines mentioning the weird easy_handle

17:02:05.936 [0x7f2110f368] cURL [TEXT] STATE: INIT => CONNECT handle 0x7f2110f368; line 1429 (connection #-5000)
17:02:05.936 [0x7f2110f368] cURL [TEXT] STATE: CONNECT => DO handle 0x7f2110f368; line 1474 (connection #24088)
17:02:05.937 [0x7f2110f368] cURL [TEXT] Using Stream ID: 51 (easy handle 0x7f2110f368)
17:02:05.937 [0x7f2110f368] cURL [TEXT] STATE: DO => DO_DONE handle 0x7f2110f368; line 1695 (connection #24088)
17:02:05.937 [0x7f2110f368] cURL [TEXT] STATE: DO_DONE => WAITPERFORM handle 0x7f2110f368; line 1822 (connection #24088)
17:02:05.937 [0x7f2110f368] cURL [TEXT] STATE: WAITPERFORM => PERFORM handle 0x7f2110f368; line 1837 (connection #24088)
@bagder

This comment has been minimized.

Show comment
Hide comment
@bagder

bagder Jun 28, 2018

Member

You're not going to find nor fix the bug this way.

I think you need to either dig in and debug this issue when you get the crashes, or you should start working on writing up a separate app that uses libcurl the same way your actual app does, that can reproduce the problem so that you can share that with us and we can help out with the debugging.

Member

bagder commented Jun 28, 2018

You're not going to find nor fix the bug this way.

I think you need to either dig in and debug this issue when you get the crashes, or you should start working on writing up a separate app that uses libcurl the same way your actual app does, that can reproduce the problem so that you can share that with us and we can help out with the debugging.

@ThomasObenaus

This comment has been minimized.

Show comment
Hide comment
@ThomasObenaus

ThomasObenaus Jun 29, 2018

Yes you are right.

7.54.0 vs 7.60.0

The odd thing is that with the newest libcurl version (from master) the crash it seams to 'randomly' on different locations. In contrast to the problem in 7.54.0 for me this looks like a heap-corruption.

Reproduction sample

To reproduce I had with 7.54.0 is really hard. The setup is kind of special. I already tried a lot to strip it down to a small sample, without success. So there I see no option.

For reproducing the 7.60.0 problem I can try it again.

ThomasObenaus commented Jun 29, 2018

Yes you are right.

7.54.0 vs 7.60.0

The odd thing is that with the newest libcurl version (from master) the crash it seams to 'randomly' on different locations. In contrast to the problem in 7.54.0 for me this looks like a heap-corruption.

Reproduction sample

To reproduce I had with 7.54.0 is really hard. The setup is kind of special. I already tried a lot to strip it down to a small sample, without success. So there I see no option.

For reproducing the 7.60.0 problem I can try it again.

@ThomasObenaus

This comment has been minimized.

Show comment
Hide comment
@ThomasObenaus

ThomasObenaus Jun 29, 2018

But anyway can you give me a hint where I can look at (in libcurl) to find the cause of the crashes. I have not enough knowledge about how curl handles the connections and shares them between easy handles.

ThomasObenaus commented Jun 29, 2018

But anyway can you give me a hint where I can look at (in libcurl) to find the cause of the crashes. I have not enough knowledge about how curl handles the connections and shares them between easy handles.

@bagder

This comment has been minimized.

Show comment
Hide comment
@bagder

bagder Jun 29, 2018

Member

I asked questions previously whose answers could help.

You also need to describe with more details what you do with libcurl and what h2 streams that are ongoing (or not) when the problem occurs. Possibly even what exact h2 frame that triggers the problem.

Member

bagder commented Jun 29, 2018

I asked questions previously whose answers could help.

You also need to describe with more details what you do with libcurl and what h2 streams that are ongoing (or not) when the problem occurs. Possibly even what exact h2 frame that triggers the problem.

@ThomasObenaus

This comment has been minimized.

Show comment
Hide comment
@ThomasObenaus

ThomasObenaus Jun 29, 2018

Ok sorry. To answer your questions:

  1. Sadly running it with valgrind is not possible since its a too big application.
  2. I'll try to find the potential h2 frame that causes the problem.
  3. I'll prepare a bit of pseudo-code to give you an idea how I (maybe wrongly) use curl.

ThomasObenaus commented Jun 29, 2018

Ok sorry. To answer your questions:

  1. Sadly running it with valgrind is not possible since its a too big application.
  2. I'll try to find the potential h2 frame that causes the problem.
  3. I'll prepare a bit of pseudo-code to give you an idea how I (maybe wrongly) use curl.
@bagder

This comment has been minimized.

Show comment
Hide comment
@bagder

bagder Jun 29, 2018

Member

When data->magic is wrong, is the rest of the struct also messed up? Since the pointer seems to still be the right one, that would indicate that the memory was either freed or overwritten, right?

Given the log, it seems like that handle should still be alive and have an ongoing associated transfer?

Member

bagder commented Jun 29, 2018

When data->magic is wrong, is the rest of the struct also messed up? Since the pointer seems to still be the right one, that would indicate that the memory was either freed or overwritten, right?

Given the log, it seems like that handle should still be alive and have an ongoing associated transfer?

@ThomasObenaus

This comment has been minimized.

Show comment
Hide comment
@ThomasObenaus

ThomasObenaus Jun 29, 2018

I'll do another run to check this..

ThomasObenaus commented Jun 29, 2018

I'll do another run to check this..

@ThomasObenaus

This comment has been minimized.

Show comment
Hide comment
@ThomasObenaus

ThomasObenaus Jun 29, 2018

How we use curl

class Request
{
private:
  CURL *m_CurlEasyHandle = nullptr;
  std::function<void(std::shared_ptr<Request> request)> m_OnComplete;
};

void init()
{
  MutexGuard lock(m_Mutex);
  m_CurlMultiHandle = curl_multi_init();

  // enable http2 multiplexing (which is the whole purpose of this code)
  curl_multi_setopt(m_CurlMultiHandle, CURLMOPT_PIPELINING, CURLPIPE_MULTIPLEX);

  // enable http2 push
  curl_multi_setopt(m_CurlMultiHandle, CURLMOPT_PUSHFUNCTION, &pushCallback);
  curl_multi_setopt(m_CurlMultiHandle, CURLMOPT_PUSHDATA, this);

  // start performing
  curl_multi_perform(m_CurlMultiHandle, &m_StillRunning);
}

void performRequests(std::queue<std::shared_ptr<Request>> requests)
{
  while (!requests.empty())
  {
    performRequest(requests.front())
        requests.pop();
  }
}

void performRequest(const std::shared_ptr<Request> &request)
{
  if (!request)
    return;

  request->m_CurlEasyHandle = curl_easy_init();
  if (!request->m_CurlEasyHandle)
    return;

  // http request headers
  curl_slist *header = nullptr;
  header = addAccessTokenToHeader(header);
  header = addCommonHeaders(header);

  auto &refHeader = request->m_Request.getHeader();
  if (!refHeader.empty())
  {
    for (auto &refElement : refHeader)
    {
      auto &refHeaderField = refElement.second;
      header = curl_slist_append(header, refHeaderField.toString().c_str());
    }
  }

  // add the header
  curl_easy_setopt(request->m_CurlEasyHandle, CURLOPT_HTTPHEADER, headers);
  curl_easy_setopt(request->m_CurlEasyHandle, CURLOPT_TIMEOUT, 10);
  curl_easy_setopt(request->m_CurlEasyHandle, CURLOPT_DNS_CACHE_TIMEOUT, 60);
  curl_easy_setopt(request->m_CurlEasyHandle, CURLOPT_URL, "https://blubb.com/bla/blubb");
  curl_easy_setopt(request->m_CurlEasyHandle, CURLOPT_FOLLOWLOCATION, 1L);  // follow http 30x redirects
  curl_easy_setopt(request->m_CurlEasyHandle, CURLOPT_ACCEPT_ENCODING, ""); // accept all compression algorithms we know
  curl_easy_setopt(request->m_CurlEasyHandle, CURLOPT_PRIVATE, header);
  curl_easy_setopt(request->m_CurlEasyHandle, CURLOPT_ERRORBUFFER, m_errBuffer); // provide a buffer to store errors in
  m_errBuffer[0] = 0;                                                            // set the error buffer as empty before performing a request
  curl_easy_setopt(request->m_CurlEasyHandle, CURLOPT_NOSIGNAL, 1L);
  // always use http2 without sending an http1.x request first
  curl_easy_setopt(request->m_CurlEasyHandle, CURLOPT_HTTP_VERSION, CURL_HTTP_VERSION_2_PRIOR_KNOWLEDGE);
  curl_easy_setopt(request->m_CurlEasyHandle, CURLOPT_SSL_VERIFYHOST, 0L);
  curl_easy_setopt(request->m_CurlEasyHandle, CURLOPT_SSL_VERIFYPEER, 0L);
  curl_easy_setopt(request->m_CurlEasyHandle, CURLOPT_VERBOSE, 1L);
  curl_easy_setopt(request->m_CurlEasyHandle, CURLOPT_DEBUGFUNCTION, curlDebugCallback);
  curl_easy_setopt(request->m_CurlEasyHandle, CURLOPT_DEBUGDATA, &m_debugLoggingCurlData);
  curl_easy_setopt(request->m_CurlEasyHandle, CURLOPT_WRITEFUNCTION, &writeMessage);
  curl_easy_setopt(request->m_CurlEasyHandle, CURLOPT_WRITEDATA, request.get());
  curl_easy_setopt(request->m_CurlEasyHandle, CURLOPT_HEADERFUNCTION, &readHeader);
  curl_easy_setopt(request->m_CurlEasyHandle, CURLOPT_HEADERDATA, request.get());

  if (request->httpMethod == HttpMethod::GET)
  {
    // no request data, send as GET request
    curl_easy_setopt(request->m_CurlEasyHandle, CURLOPT_HTTPGET, 1);
  }
  else if (request->httpMethod == HttpMethod::POST)
  {
    // send request as POST request
    curl_easy_setopt(request->m_CurlEasyHandle, CURLOPT_POST, 1);
    curl_easy_setopt(request->m_CurlEasyHandle, CURLOPT_POSTFIELDS, request->m_Request.data().data());
    curl_easy_setopt(request->m_CurlEasyHandle, CURLOPT_POSTFIELDSIZE, request->m_Request.data().size());
  }

  curl_multi_add_handle(m_CurlMultiHandle, request->m_CurlEasyHandle);
  m_Requests[request->m_CurlEasyHandle] = request;
}

std::shared_ptr<Request>
httpRequestFind(const CURL *const easy)
{
  auto requestIt = m_Requests.find(easy);
  if (requestIt == m_Requests.end())
  {
    // should never happen
    throw Exception("implementation error: could not find request in list");
  }
  return requestIt->second;
}

void httpRequestDone(const std::shared_ptr<Request> request, const CURLcode &curlCode)
{
  if (request)
  {
    if (curlCode == CURLE_OK)
    {
      long status = 0;
      curl_easy_getinfo(request->m_CurlEasyHandle, CURLINFO_RESPONSE_CODE, &status);
      request->m_Status = HTTPStatusCode(status);
    }
    else
    {
      std::string curlErr(curl_easy_strerror(curlCode));

      std::stringstream ss;
      ss << std::hex << "[" << request->m_CurlEasyHandle << "]"
         << "CurlError: " << curlErr << " (" << curlCode << ")" << &std::endl;
      LOG_ERROR << ss.str();

      auto len = strlen(m_errBuffer);
      if (len)
      {
        std::stringstream ss;
        ss << std::hex << "[" << request->m_CurlEasyHandle << "]"
           << "Error info: " << std::string(m_errBuffer) << &std::endl;
        LOG_ERROR << ss.str();
      }
    }

    // call the requester and put the response to him
    request->m_OnComplete(request);

    // get header and delete
    curl_slist *header = nullptr;
    curl_easy_getinfo(request->m_CurlEasyHandle, CURLINFO_PRIVATE, &header);
    curl_slist_free_all(header);

    const CURLMcode cCode = curl_multi_remove_handle(m_CurlMultiHandle, request->m_CurlEasyHandle);
    auto countErased = m_Requests.erase(request->m_CurlEasyHandle);

    curl_easy_cleanup(request->m_CurlEasyHandle);
    request->m_CurlEasyHandle = nullptr;
  }
}

void mainLoop()
{
  curl_global_init(CURL_GLOBAL_ALL);
  init();
  do
  {
    if (getPendingRequests() < MAX_PENDING_REQUESTS)
      performRequests(popWaitingRequests(MAX_PENDING_REQUESTS));

    fd_set fdRead;
    fd_set fdWrite;
    fd_set fdExcep;

    FD_ZERO(&fdRead);
    FD_ZERO(&fdWrite);
    FD_ZERO(&fdExcep);

    // set a suitable timeout to play around with
    long curlTimeout = -1;
    curl_multi_timeout(m_CurlMultiHandle, &curlTimeout);

    const long maxTimeoutMs = 1000;
    timeval timeout = curlTimeoutToTimeval(curlTimeout, maxTimeoutMs);

    // get file descriptors from the transfers
    int maxfd = -1;
    {
      CURLMcode code = curl_multi_fdset(m_CurlMultiHandle, &fdRead, &fdWrite, &fdExcep, &maxfd);
      if (CURLM_OK != code)
      {
        throw ExceptionCurlMulti(code);
      }
    }

    int rc = 0;
    if (-1 == maxfd)
      sleep(100);
    else
      rc = select(maxfd + 1, &fdRead, &fdWrite, &fdExcep, &timeout);

    if (-1 != rc)
    {
      // timeout or readable/writable sockets
      CURLMcode cCMultiPerform = curl_multi_perform(m_CurlMultiHandle, &m_StillRunning);

      // check curl for messages
      CURLMsg *msg = nullptr;
      do
      {
        // get messages
        int numMessages = 0;
        msg = curl_multi_info_read(m_CurlMultiHandle, &numMessages);

        // check if a request is done
        if (msg && (CURLMSG_DONE == msg->msg))
        {
          const CURLcode code = msg->data.result;
          auto request = httpRequestFind(msg->easy_handle);
          httpRequestDone(request, code);
        }
      } while (msg);
    }

  } while (!m_Shutdown);

  curl_multi_cleanup(m_CurlMultiHandle);
}

ThomasObenaus commented Jun 29, 2018

How we use curl

class Request
{
private:
  CURL *m_CurlEasyHandle = nullptr;
  std::function<void(std::shared_ptr<Request> request)> m_OnComplete;
};

void init()
{
  MutexGuard lock(m_Mutex);
  m_CurlMultiHandle = curl_multi_init();

  // enable http2 multiplexing (which is the whole purpose of this code)
  curl_multi_setopt(m_CurlMultiHandle, CURLMOPT_PIPELINING, CURLPIPE_MULTIPLEX);

  // enable http2 push
  curl_multi_setopt(m_CurlMultiHandle, CURLMOPT_PUSHFUNCTION, &pushCallback);
  curl_multi_setopt(m_CurlMultiHandle, CURLMOPT_PUSHDATA, this);

  // start performing
  curl_multi_perform(m_CurlMultiHandle, &m_StillRunning);
}

void performRequests(std::queue<std::shared_ptr<Request>> requests)
{
  while (!requests.empty())
  {
    performRequest(requests.front())
        requests.pop();
  }
}

void performRequest(const std::shared_ptr<Request> &request)
{
  if (!request)
    return;

  request->m_CurlEasyHandle = curl_easy_init();
  if (!request->m_CurlEasyHandle)
    return;

  // http request headers
  curl_slist *header = nullptr;
  header = addAccessTokenToHeader(header);
  header = addCommonHeaders(header);

  auto &refHeader = request->m_Request.getHeader();
  if (!refHeader.empty())
  {
    for (auto &refElement : refHeader)
    {
      auto &refHeaderField = refElement.second;
      header = curl_slist_append(header, refHeaderField.toString().c_str());
    }
  }

  // add the header
  curl_easy_setopt(request->m_CurlEasyHandle, CURLOPT_HTTPHEADER, headers);
  curl_easy_setopt(request->m_CurlEasyHandle, CURLOPT_TIMEOUT, 10);
  curl_easy_setopt(request->m_CurlEasyHandle, CURLOPT_DNS_CACHE_TIMEOUT, 60);
  curl_easy_setopt(request->m_CurlEasyHandle, CURLOPT_URL, "https://blubb.com/bla/blubb");
  curl_easy_setopt(request->m_CurlEasyHandle, CURLOPT_FOLLOWLOCATION, 1L);  // follow http 30x redirects
  curl_easy_setopt(request->m_CurlEasyHandle, CURLOPT_ACCEPT_ENCODING, ""); // accept all compression algorithms we know
  curl_easy_setopt(request->m_CurlEasyHandle, CURLOPT_PRIVATE, header);
  curl_easy_setopt(request->m_CurlEasyHandle, CURLOPT_ERRORBUFFER, m_errBuffer); // provide a buffer to store errors in
  m_errBuffer[0] = 0;                                                            // set the error buffer as empty before performing a request
  curl_easy_setopt(request->m_CurlEasyHandle, CURLOPT_NOSIGNAL, 1L);
  // always use http2 without sending an http1.x request first
  curl_easy_setopt(request->m_CurlEasyHandle, CURLOPT_HTTP_VERSION, CURL_HTTP_VERSION_2_PRIOR_KNOWLEDGE);
  curl_easy_setopt(request->m_CurlEasyHandle, CURLOPT_SSL_VERIFYHOST, 0L);
  curl_easy_setopt(request->m_CurlEasyHandle, CURLOPT_SSL_VERIFYPEER, 0L);
  curl_easy_setopt(request->m_CurlEasyHandle, CURLOPT_VERBOSE, 1L);
  curl_easy_setopt(request->m_CurlEasyHandle, CURLOPT_DEBUGFUNCTION, curlDebugCallback);
  curl_easy_setopt(request->m_CurlEasyHandle, CURLOPT_DEBUGDATA, &m_debugLoggingCurlData);
  curl_easy_setopt(request->m_CurlEasyHandle, CURLOPT_WRITEFUNCTION, &writeMessage);
  curl_easy_setopt(request->m_CurlEasyHandle, CURLOPT_WRITEDATA, request.get());
  curl_easy_setopt(request->m_CurlEasyHandle, CURLOPT_HEADERFUNCTION, &readHeader);
  curl_easy_setopt(request->m_CurlEasyHandle, CURLOPT_HEADERDATA, request.get());

  if (request->httpMethod == HttpMethod::GET)
  {
    // no request data, send as GET request
    curl_easy_setopt(request->m_CurlEasyHandle, CURLOPT_HTTPGET, 1);
  }
  else if (request->httpMethod == HttpMethod::POST)
  {
    // send request as POST request
    curl_easy_setopt(request->m_CurlEasyHandle, CURLOPT_POST, 1);
    curl_easy_setopt(request->m_CurlEasyHandle, CURLOPT_POSTFIELDS, request->m_Request.data().data());
    curl_easy_setopt(request->m_CurlEasyHandle, CURLOPT_POSTFIELDSIZE, request->m_Request.data().size());
  }

  curl_multi_add_handle(m_CurlMultiHandle, request->m_CurlEasyHandle);
  m_Requests[request->m_CurlEasyHandle] = request;
}

std::shared_ptr<Request>
httpRequestFind(const CURL *const easy)
{
  auto requestIt = m_Requests.find(easy);
  if (requestIt == m_Requests.end())
  {
    // should never happen
    throw Exception("implementation error: could not find request in list");
  }
  return requestIt->second;
}

void httpRequestDone(const std::shared_ptr<Request> request, const CURLcode &curlCode)
{
  if (request)
  {
    if (curlCode == CURLE_OK)
    {
      long status = 0;
      curl_easy_getinfo(request->m_CurlEasyHandle, CURLINFO_RESPONSE_CODE, &status);
      request->m_Status = HTTPStatusCode(status);
    }
    else
    {
      std::string curlErr(curl_easy_strerror(curlCode));

      std::stringstream ss;
      ss << std::hex << "[" << request->m_CurlEasyHandle << "]"
         << "CurlError: " << curlErr << " (" << curlCode << ")" << &std::endl;
      LOG_ERROR << ss.str();

      auto len = strlen(m_errBuffer);
      if (len)
      {
        std::stringstream ss;
        ss << std::hex << "[" << request->m_CurlEasyHandle << "]"
           << "Error info: " << std::string(m_errBuffer) << &std::endl;
        LOG_ERROR << ss.str();
      }
    }

    // call the requester and put the response to him
    request->m_OnComplete(request);

    // get header and delete
    curl_slist *header = nullptr;
    curl_easy_getinfo(request->m_CurlEasyHandle, CURLINFO_PRIVATE, &header);
    curl_slist_free_all(header);

    const CURLMcode cCode = curl_multi_remove_handle(m_CurlMultiHandle, request->m_CurlEasyHandle);
    auto countErased = m_Requests.erase(request->m_CurlEasyHandle);

    curl_easy_cleanup(request->m_CurlEasyHandle);
    request->m_CurlEasyHandle = nullptr;
  }
}

void mainLoop()
{
  curl_global_init(CURL_GLOBAL_ALL);
  init();
  do
  {
    if (getPendingRequests() < MAX_PENDING_REQUESTS)
      performRequests(popWaitingRequests(MAX_PENDING_REQUESTS));

    fd_set fdRead;
    fd_set fdWrite;
    fd_set fdExcep;

    FD_ZERO(&fdRead);
    FD_ZERO(&fdWrite);
    FD_ZERO(&fdExcep);

    // set a suitable timeout to play around with
    long curlTimeout = -1;
    curl_multi_timeout(m_CurlMultiHandle, &curlTimeout);

    const long maxTimeoutMs = 1000;
    timeval timeout = curlTimeoutToTimeval(curlTimeout, maxTimeoutMs);

    // get file descriptors from the transfers
    int maxfd = -1;
    {
      CURLMcode code = curl_multi_fdset(m_CurlMultiHandle, &fdRead, &fdWrite, &fdExcep, &maxfd);
      if (CURLM_OK != code)
      {
        throw ExceptionCurlMulti(code);
      }
    }

    int rc = 0;
    if (-1 == maxfd)
      sleep(100);
    else
      rc = select(maxfd + 1, &fdRead, &fdWrite, &fdExcep, &timeout);

    if (-1 != rc)
    {
      // timeout or readable/writable sockets
      CURLMcode cCMultiPerform = curl_multi_perform(m_CurlMultiHandle, &m_StillRunning);

      // check curl for messages
      CURLMsg *msg = nullptr;
      do
      {
        // get messages
        int numMessages = 0;
        msg = curl_multi_info_read(m_CurlMultiHandle, &numMessages);

        // check if a request is done
        if (msg && (CURLMSG_DONE == msg->msg))
        {
          const CURLcode code = msg->data.result;
          auto request = httpRequestFind(msg->easy_handle);
          httpRequestDone(request, code);
        }
      } while (msg);
    }

  } while (!m_Shutdown);

  curl_multi_cleanup(m_CurlMultiHandle);
}
@ThomasObenaus

This comment has been minimized.

Show comment
Hide comment
@ThomasObenaus

ThomasObenaus Jun 29, 2018

In short

  1. Add easy_handles to multi_handle
// create requests and add them to the multi-handle
for all pending requests
{
  easy_handle = curl_easy_init();
  configure(easy_handle);
  curl_multi_add_handle(m_CurlMultiHandle, request->m_CurlEasyHandle);
}
  1. Wait for curl
// calc how long to wait for curl
curl_multi_timeout(m_CurlMultiHandle, &curlTimeout);

// wait for curl
CURLMcode code = curl_multi_fdset(m_CurlMultiHandle, &fdRead, &fdWrite, &fdExcep, &maxfd);
int rc = select(maxfd + 1, &fdRead, &fdWrite, &fdExcep, &timeout);
  1. Issue curl to process the registered easy_handles
CURLMcode cCMultiPerform = curl_multi_perform(m_CurlMultiHandle, &m_StillRunning);
  1. Handle the easy_handles given back from curl and free them
// check curl for messages
CURLMsg *msg = nullptr;
//for all (easy_handles given back by curl)
do
{
 int numMessages = 0;
 msg = curl_multi_info_read(m_CurlMultiHandle, &numMessages); 
 // check if a request is done
 if (msg && (CURLMSG_DONE == msg->msg))
 {
   const CURLcode code = msg->data.result;
   auto request = httpRequestFind(msg->easy_handle);
   curl_slist *header = nullptr;
   curl_easy_getinfo(request->m_CurlEasyHandle, CURLINFO_PRIVATE, &header);
   curl_slist_free_all(header);

    const CURLMcode cCode = curl_multi_remove_handle(m_CurlMultiHandle, request->m_CurlEasyHandle);
    auto countErased = m_Requests.erase(request->m_CurlEasyHandle);
    curl_easy_cleanup(request->m_CurlEasyHandle);
    request->m_CurlEasyHandle = nullptr;
  }
}while(msg);

ThomasObenaus commented Jun 29, 2018

In short

  1. Add easy_handles to multi_handle
// create requests and add them to the multi-handle
for all pending requests
{
  easy_handle = curl_easy_init();
  configure(easy_handle);
  curl_multi_add_handle(m_CurlMultiHandle, request->m_CurlEasyHandle);
}
  1. Wait for curl
// calc how long to wait for curl
curl_multi_timeout(m_CurlMultiHandle, &curlTimeout);

// wait for curl
CURLMcode code = curl_multi_fdset(m_CurlMultiHandle, &fdRead, &fdWrite, &fdExcep, &maxfd);
int rc = select(maxfd + 1, &fdRead, &fdWrite, &fdExcep, &timeout);
  1. Issue curl to process the registered easy_handles
CURLMcode cCMultiPerform = curl_multi_perform(m_CurlMultiHandle, &m_StillRunning);
  1. Handle the easy_handles given back from curl and free them
// check curl for messages
CURLMsg *msg = nullptr;
//for all (easy_handles given back by curl)
do
{
 int numMessages = 0;
 msg = curl_multi_info_read(m_CurlMultiHandle, &numMessages); 
 // check if a request is done
 if (msg && (CURLMSG_DONE == msg->msg))
 {
   const CURLcode code = msg->data.result;
   auto request = httpRequestFind(msg->easy_handle);
   curl_slist *header = nullptr;
   curl_easy_getinfo(request->m_CurlEasyHandle, CURLINFO_PRIVATE, &header);
   curl_slist_free_all(header);

    const CURLMcode cCode = curl_multi_remove_handle(m_CurlMultiHandle, request->m_CurlEasyHandle);
    auto countErased = m_Requests.erase(request->m_CurlEasyHandle);
    curl_easy_cleanup(request->m_CurlEasyHandle);
    request->m_CurlEasyHandle = nullptr;
  }
}while(msg);
@ThomasObenaus

This comment has been minimized.

Show comment
Hide comment
@ThomasObenaus

ThomasObenaus Jun 29, 2018

@bagder: This looks like the problem:

on_stream_close is called on the easy_handle which was freed with curl_easy_cleanup shortly before

13:39:52.853     [Warn] [user] nav: CURL.H2 [easy_handle=0x7f38a92558,magic=0xc0dedbad,tid=3233] http2_recv: easy 0x7f38a92558 (stream 139)
13:40:13.149     [Warn] [user] nav: HTTPR: httpRequestDone->curl_easy_cleanup (curl_easy=0x7f382a49a8,req=0x7f3007a690,tid=3233)...
13:40:13.149     [Warn] [user] nav: HTTPR: httpRequestDone->curl_easy_cleanup (curl_easy=0x7f382a49a8,req=0x7f3007a690,tid=3233)...done
13:40:21.831     [Warn] [user] nav: CURL.H2 [easy_handle=0x7f382a49a8,magic=(nil),tid=3233] on_stream_close(), STREAM_CLOSED (err 5), stream 139

But how could that happen? We access the easy_handle only from one thread and we only free it (curl_easy_cleanup) after we got the handle back from curl with:

 CURLMsg *msg = curl_multi_info_read(m_CurlMultiHandle, &numMessages); 
 // check if a request is done
 if (msg && (CURLMSG_DONE == msg->msg))
 {
   curl_multi_remove_handle( m_CurlMultiHandle,msg->easy_handle );
   curl_easy_cleanup(msg->easy_handle);
 }

ThomasObenaus commented Jun 29, 2018

@bagder: This looks like the problem:

on_stream_close is called on the easy_handle which was freed with curl_easy_cleanup shortly before

13:39:52.853     [Warn] [user] nav: CURL.H2 [easy_handle=0x7f38a92558,magic=0xc0dedbad,tid=3233] http2_recv: easy 0x7f38a92558 (stream 139)
13:40:13.149     [Warn] [user] nav: HTTPR: httpRequestDone->curl_easy_cleanup (curl_easy=0x7f382a49a8,req=0x7f3007a690,tid=3233)...
13:40:13.149     [Warn] [user] nav: HTTPR: httpRequestDone->curl_easy_cleanup (curl_easy=0x7f382a49a8,req=0x7f3007a690,tid=3233)...done
13:40:21.831     [Warn] [user] nav: CURL.H2 [easy_handle=0x7f382a49a8,magic=(nil),tid=3233] on_stream_close(), STREAM_CLOSED (err 5), stream 139

But how could that happen? We access the easy_handle only from one thread and we only free it (curl_easy_cleanup) after we got the handle back from curl with:

 CURLMsg *msg = curl_multi_info_read(m_CurlMultiHandle, &numMessages); 
 // check if a request is done
 if (msg && (CURLMSG_DONE == msg->msg))
 {
   curl_multi_remove_handle( m_CurlMultiHandle,msg->easy_handle );
   curl_easy_cleanup(msg->easy_handle);
 }
@ThomasObenaus

This comment has been minimized.

Show comment
Hide comment
@ThomasObenaus

ThomasObenaus Jun 29, 2018

Full life-cycle of this easy_handle

13:40:02.988     [Warn] [user] nav: HTTPR: performRequest->curl_easy_init (curl_easy=0x7f382a49a8,req=0x7f3007a690,tid=3233)...done
13:40:02.988     [Warn] [user] nav: HTTPR: performRequest->curl_multi_add_handle (curl_easy=0x7f382a49a8,req=0x7f3007a690,tid=3233)...
13:40:02.988     [Warn] [user] nav: HTTPR: performRequest->curl_multi_add_handle (curl_easy=0x7f382a49a8,req=0x7f3007a690,tid=3233,cCmultiAdd=0)...done
13:40:03.079     [Warn] [user] nav: [0x7f382a49a8] cURL [TEXT] STATE: INIT => CONNECT handle 0x7f382a49a8; line 1429 (connection #-5000)
13:40:03.079     [Warn] [user] nav: [0x7f382a49a8] cURL [TEXT] Found bundle for host blubb: 0x7f3851d858 [can multiplex]
13:40:03.080     [Warn] [user] nav: [0x7f382a49a8] cURL [TEXT] Conn: 8418 (0x7f38afe1d8) Receive pipe weight: (-1/0), penalized: FALSE
13:40:03.080     [Warn] [user] nav: [0x7f382a49a8] cURL [TEXT] Multiplexed connection found!
13:40:03.080     [Warn] [user] nav: [0x7f382a49a8] cURL [TEXT] Found connection 8418, with requests in the pipe (55)
13:40:03.080     [Warn] [user] nav: [0x7f382a49a8] cURL [TEXT] Re-using existing connection! (#8418) with host blubb
13:40:03.080     [Warn] [user] nav: [0x7f382a49a8] cURL [TEXT] STATE: CONNECT => DO handle 0x7f382a49a8; line 1474 (connection #8418)
13:40:03.080     [Warn] [user] nav: CURL.H2 [easy_handle=0x7f382a49a8,magic=0xc0dedbad,tid=3233] http2_send len=1074
13:40:03.080     [Warn] [user] nav: CURL.H2 [easy_handle=0x7f382a49a8,magic=0xc0dedbad,tid=3233] h2 header: :method:GET
13:40:03.080     [Warn] [user] nav: CURL.H2 [easy_handle=0x7f382a49a8,magic=0xc0dedbad,tid=3233] h2 header: :path:/api/traffic/v2/tile/134766962/current
13:40:03.080     [Warn] [user] nav: CURL.H2 [easy_handle=0x7f382a49a8,magic=0xc0dedbad,tid=3233] h2 header: :scheme:https
13:40:03.080     [Warn] [user] nav: CURL.H2 [easy_handle=0x7f382a49a8,magic=0xc0dedbad,tid=3233] h2 header: :authority:blubb
13:40:03.080     [Warn] [user] nav: CURL.H2 [easy_handle=0x7f382a49a8,magic=0xc0dedbad,tid=3233] h2 header: Accept-Encoding:deflate, gzip
13:40:03.080     [Warn] [user] nav: CURL.H2 [easy_handle=0x7f382a49a8,magic=0xc0dedbad,tid=3233] h2 header: accept:application/x-protobuf
13:40:03.080     [Warn] [user] nav: CURL.H2 [easy_handle=0x7f382a49a8,magic=0xc0dedbad,tid=3233] h2 header: content-type:application/x-protobuf
13:40:03.080     [Warn] [user] nav: CURL.NGHTTP2 nghttp2_submit_request session=0x7f39165db0,stream_user_data=0x7f382a49a8,tid=3233
13:40:03.080     [Warn] [user] nav: CURL.NGHTTP2 submit_headers_shared_nva session=0x7f39165db0,stream_user_data=0x7f382a49a8,tid=3233
13:40:03.080     [Warn] [user] nav: CURL.NGHTTP2 submit_headers_shared session=0x7f39165db0,stream_user_data=0x7f382a49a8,tid=3233
13:40:03.080     [Warn] [user] nav: [0x7f382a49a8] cURL [TEXT] Using Stream ID: 8b (easy handle 0x7f382a49a8)
13:40:03.080     [Warn] [user] nav: [0x7f382a49a8] cURL [HEADER_OUT] GET /api/traffic/v2/tile/134766962/current HTTP/2
13:40:03.080     [Warn] [user] nav: [0x7f382a49a8] cURL [TEXT] STATE: DO => DO_DONE handle 0x7f382a49a8; line 1695 (connection #8418)
13:40:03.080     [Warn] [user] nav: [0x7f382a49a8] cURL [TEXT] STATE: DO_DONE => WAITPERFORM handle 0x7f382a49a8; line 1822 (connection #8418)
13:40:03.080     [Warn] [user] nav: [0x7f382a49a8] cURL [TEXT] STATE: WAITPERFORM => PERFORM handle 0x7f382a49a8; line 1837 (connection #8418)
13:40:13.082     [Warn] [user] nav: [0x7f382a49a8] cURL [TEXT] Operation timed out after 10000 milliseconds with 0 bytes received
13:40:13.082     [Warn] [user] nav: [0x7f382a49a8] cURL [TEXT] Kill stream: Disconnected with pending data
13:40:13.082     [Warn] [user] nav: [0x7f382a49a8] cURL [TEXT] multi_done
13:40:13.082     [Warn] [user] nav: [0x7f382a49a8] cURL [TEXT] Connection still in use 0/44, no more multi_done now!
13:40:13.148     [Info] [HTTPRequestHandler] [0x7f382a49a8] Response received from curl.
13:40:13.148    [Error] [HTTPRequestHandler] [0x7f382a49a8]CurlError: Timeout was reached (1c)
13:40:13.148    [Error] [HTTPRequestHandler] [0x7f382a49a8]Error info: Failed sending HTTP POST request
13:40:13.148     [Info] [HTTPRequestHandler] [0x7f382a49a8] httpRequestDone
13:40:13.149     [Warn] [user] nav: HTTPR: main->curl_multi_info_read (curl_multi=0x1e28c988,numMessages=8,tid=3233,msg=0x7f382a4a10easy_handle=0x7f382a49a8msg.msg=1)...done
13:40:13.149     [Warn] [user] nav: HTTPR: main->httpRequestFind (easy_handle=0x7f382a49a8)...
13:40:13.149     [Warn] [user] nav: HTTPR: main->httpRequestFind (easy_handle=0x7f382a49a8,request=0x7f3007a690)...done
13:40:13.149     [Warn] [user] nav: HTTPR: httpRequestDone (curl_easy=0x7f382a49a8,req=0x7f3007a690,tid=3233)...
13:40:13.149     [Warn] [user] nav: HTTPR: httpRequestDone->curl_multi_remove_handle (curl_easy=0x7f382a49a8,req=0x7f3007a690,tid=3233)...
13:40:13.149     [Warn] [user] nav: HTTPR: httpRequestDone->curl_multi_remove_handle (curl_easy=0x7f382a49a8,req=0x7f3007a690,cCode=0,tid=3233)...done
13:40:13.149     [Warn] [user] nav: HTTPR: m_Requests.erase (easy_handle=0x7f382a49a8,request=0x7f3007a690,cCode=0)
13:40:13.149     [Warn] [user] nav: HTTPR: httpRequestDone->curl_easy_cleanup (curl_easy=0x7f382a49a8,req=0x7f3007a690,tid=3233)...
13:40:13.149     [Warn] [user] nav: HTTPR: httpRequestDone->curl_easy_cleanup (curl_easy=0x7f382a49a8,req=0x7f3007a690,tid=3233)...done
13:40:13.149     [Warn] [user] nav: HTTPR: httpRequestDone (curl_easy=0x7f382a49a8,req=0x7f3007a690,tid=3233)...done
13:40:21.831     [Warn] [user] nav: CURL.NGHTTP2 nghttp2_session_open_stream 3 session=0x7f39165db0,stream_user_data=0x7f382a49a8,tid=3233
13:40:21.831     [Warn] [user] nav: CURL.NGHTT2 nghttp2_session_open_stream 3434 session=0x7f39165db0,stream_user_data=0x7f382a49a8,tid=3233
13:40:21.831     [Warn] [user] nav: CURL.NGHTTP2 ->nghttp2_stream_init 5545 session=0x7f39165db0,stream_user_data=0x7f382a49a8,tid=3233
13:40:21.831     [Warn] [user] nav: CURL.NGHTTP2 nghttp2_stream_init stream_user_data=0x7f382a49a8,tid=3233
13:40:21.831     [Warn] [user] nav: CURL.H2 [easy_handle=0x7f382a49a8,magic=(nil),tid=3233] on_frame_not_send() was called, lib_error_code = -511
13:40:21.831     [Warn] [user] nav: CURL.H2 [easy_handle=0x7f382a49a8,magic=(nil),tid=3233] on_stream_close(), STREAM_CLOSED (err 5), stream 139

ThomasObenaus commented Jun 29, 2018

Full life-cycle of this easy_handle

13:40:02.988     [Warn] [user] nav: HTTPR: performRequest->curl_easy_init (curl_easy=0x7f382a49a8,req=0x7f3007a690,tid=3233)...done
13:40:02.988     [Warn] [user] nav: HTTPR: performRequest->curl_multi_add_handle (curl_easy=0x7f382a49a8,req=0x7f3007a690,tid=3233)...
13:40:02.988     [Warn] [user] nav: HTTPR: performRequest->curl_multi_add_handle (curl_easy=0x7f382a49a8,req=0x7f3007a690,tid=3233,cCmultiAdd=0)...done
13:40:03.079     [Warn] [user] nav: [0x7f382a49a8] cURL [TEXT] STATE: INIT => CONNECT handle 0x7f382a49a8; line 1429 (connection #-5000)
13:40:03.079     [Warn] [user] nav: [0x7f382a49a8] cURL [TEXT] Found bundle for host blubb: 0x7f3851d858 [can multiplex]
13:40:03.080     [Warn] [user] nav: [0x7f382a49a8] cURL [TEXT] Conn: 8418 (0x7f38afe1d8) Receive pipe weight: (-1/0), penalized: FALSE
13:40:03.080     [Warn] [user] nav: [0x7f382a49a8] cURL [TEXT] Multiplexed connection found!
13:40:03.080     [Warn] [user] nav: [0x7f382a49a8] cURL [TEXT] Found connection 8418, with requests in the pipe (55)
13:40:03.080     [Warn] [user] nav: [0x7f382a49a8] cURL [TEXT] Re-using existing connection! (#8418) with host blubb
13:40:03.080     [Warn] [user] nav: [0x7f382a49a8] cURL [TEXT] STATE: CONNECT => DO handle 0x7f382a49a8; line 1474 (connection #8418)
13:40:03.080     [Warn] [user] nav: CURL.H2 [easy_handle=0x7f382a49a8,magic=0xc0dedbad,tid=3233] http2_send len=1074
13:40:03.080     [Warn] [user] nav: CURL.H2 [easy_handle=0x7f382a49a8,magic=0xc0dedbad,tid=3233] h2 header: :method:GET
13:40:03.080     [Warn] [user] nav: CURL.H2 [easy_handle=0x7f382a49a8,magic=0xc0dedbad,tid=3233] h2 header: :path:/api/traffic/v2/tile/134766962/current
13:40:03.080     [Warn] [user] nav: CURL.H2 [easy_handle=0x7f382a49a8,magic=0xc0dedbad,tid=3233] h2 header: :scheme:https
13:40:03.080     [Warn] [user] nav: CURL.H2 [easy_handle=0x7f382a49a8,magic=0xc0dedbad,tid=3233] h2 header: :authority:blubb
13:40:03.080     [Warn] [user] nav: CURL.H2 [easy_handle=0x7f382a49a8,magic=0xc0dedbad,tid=3233] h2 header: Accept-Encoding:deflate, gzip
13:40:03.080     [Warn] [user] nav: CURL.H2 [easy_handle=0x7f382a49a8,magic=0xc0dedbad,tid=3233] h2 header: accept:application/x-protobuf
13:40:03.080     [Warn] [user] nav: CURL.H2 [easy_handle=0x7f382a49a8,magic=0xc0dedbad,tid=3233] h2 header: content-type:application/x-protobuf
13:40:03.080     [Warn] [user] nav: CURL.NGHTTP2 nghttp2_submit_request session=0x7f39165db0,stream_user_data=0x7f382a49a8,tid=3233
13:40:03.080     [Warn] [user] nav: CURL.NGHTTP2 submit_headers_shared_nva session=0x7f39165db0,stream_user_data=0x7f382a49a8,tid=3233
13:40:03.080     [Warn] [user] nav: CURL.NGHTTP2 submit_headers_shared session=0x7f39165db0,stream_user_data=0x7f382a49a8,tid=3233
13:40:03.080     [Warn] [user] nav: [0x7f382a49a8] cURL [TEXT] Using Stream ID: 8b (easy handle 0x7f382a49a8)
13:40:03.080     [Warn] [user] nav: [0x7f382a49a8] cURL [HEADER_OUT] GET /api/traffic/v2/tile/134766962/current HTTP/2
13:40:03.080     [Warn] [user] nav: [0x7f382a49a8] cURL [TEXT] STATE: DO => DO_DONE handle 0x7f382a49a8; line 1695 (connection #8418)
13:40:03.080     [Warn] [user] nav: [0x7f382a49a8] cURL [TEXT] STATE: DO_DONE => WAITPERFORM handle 0x7f382a49a8; line 1822 (connection #8418)
13:40:03.080     [Warn] [user] nav: [0x7f382a49a8] cURL [TEXT] STATE: WAITPERFORM => PERFORM handle 0x7f382a49a8; line 1837 (connection #8418)
13:40:13.082     [Warn] [user] nav: [0x7f382a49a8] cURL [TEXT] Operation timed out after 10000 milliseconds with 0 bytes received
13:40:13.082     [Warn] [user] nav: [0x7f382a49a8] cURL [TEXT] Kill stream: Disconnected with pending data
13:40:13.082     [Warn] [user] nav: [0x7f382a49a8] cURL [TEXT] multi_done
13:40:13.082     [Warn] [user] nav: [0x7f382a49a8] cURL [TEXT] Connection still in use 0/44, no more multi_done now!
13:40:13.148     [Info] [HTTPRequestHandler] [0x7f382a49a8] Response received from curl.
13:40:13.148    [Error] [HTTPRequestHandler] [0x7f382a49a8]CurlError: Timeout was reached (1c)
13:40:13.148    [Error] [HTTPRequestHandler] [0x7f382a49a8]Error info: Failed sending HTTP POST request
13:40:13.148     [Info] [HTTPRequestHandler] [0x7f382a49a8] httpRequestDone
13:40:13.149     [Warn] [user] nav: HTTPR: main->curl_multi_info_read (curl_multi=0x1e28c988,numMessages=8,tid=3233,msg=0x7f382a4a10easy_handle=0x7f382a49a8msg.msg=1)...done
13:40:13.149     [Warn] [user] nav: HTTPR: main->httpRequestFind (easy_handle=0x7f382a49a8)...
13:40:13.149     [Warn] [user] nav: HTTPR: main->httpRequestFind (easy_handle=0x7f382a49a8,request=0x7f3007a690)...done
13:40:13.149     [Warn] [user] nav: HTTPR: httpRequestDone (curl_easy=0x7f382a49a8,req=0x7f3007a690,tid=3233)...
13:40:13.149     [Warn] [user] nav: HTTPR: httpRequestDone->curl_multi_remove_handle (curl_easy=0x7f382a49a8,req=0x7f3007a690,tid=3233)...
13:40:13.149     [Warn] [user] nav: HTTPR: httpRequestDone->curl_multi_remove_handle (curl_easy=0x7f382a49a8,req=0x7f3007a690,cCode=0,tid=3233)...done
13:40:13.149     [Warn] [user] nav: HTTPR: m_Requests.erase (easy_handle=0x7f382a49a8,request=0x7f3007a690,cCode=0)
13:40:13.149     [Warn] [user] nav: HTTPR: httpRequestDone->curl_easy_cleanup (curl_easy=0x7f382a49a8,req=0x7f3007a690,tid=3233)...
13:40:13.149     [Warn] [user] nav: HTTPR: httpRequestDone->curl_easy_cleanup (curl_easy=0x7f382a49a8,req=0x7f3007a690,tid=3233)...done
13:40:13.149     [Warn] [user] nav: HTTPR: httpRequestDone (curl_easy=0x7f382a49a8,req=0x7f3007a690,tid=3233)...done
13:40:21.831     [Warn] [user] nav: CURL.NGHTTP2 nghttp2_session_open_stream 3 session=0x7f39165db0,stream_user_data=0x7f382a49a8,tid=3233
13:40:21.831     [Warn] [user] nav: CURL.NGHTT2 nghttp2_session_open_stream 3434 session=0x7f39165db0,stream_user_data=0x7f382a49a8,tid=3233
13:40:21.831     [Warn] [user] nav: CURL.NGHTTP2 ->nghttp2_stream_init 5545 session=0x7f39165db0,stream_user_data=0x7f382a49a8,tid=3233
13:40:21.831     [Warn] [user] nav: CURL.NGHTTP2 nghttp2_stream_init stream_user_data=0x7f382a49a8,tid=3233
13:40:21.831     [Warn] [user] nav: CURL.H2 [easy_handle=0x7f382a49a8,magic=(nil),tid=3233] on_frame_not_send() was called, lib_error_code = -511
13:40:21.831     [Warn] [user] nav: CURL.H2 [easy_handle=0x7f382a49a8,magic=(nil),tid=3233] on_stream_close(), STREAM_CLOSED (err 5), stream 139
@bagder

This comment has been minimized.

Show comment
Hide comment
@bagder

bagder Jun 29, 2018

Member

But how could that happen?

Well, there's a bug somewhere in here...

In the on_stream_close function, it seems the call to nghttp2_session_get_stream_user_data returns the old handle for a handle that is already gone and killed?

First: how come there is frames for that stream arriving after it was deemed done? Probably because the transfer was timed out or otherwise prematurely ended from curl's side.

But more importantly: when a transfer is ended, Curl_http_done should be called, which in turn calls Curl_http2_done. And in there it calls, or should call, nghttp2_session_set_stream_user_data() to clear the association from the stream-id to this now ending transfer (easy handle).

So, the incoming frame on an already completed transfer should not be associated with the old easy handle when things work out. Can you figure out why this logic doesn't work for your scenario?

Member

bagder commented Jun 29, 2018

But how could that happen?

Well, there's a bug somewhere in here...

In the on_stream_close function, it seems the call to nghttp2_session_get_stream_user_data returns the old handle for a handle that is already gone and killed?

First: how come there is frames for that stream arriving after it was deemed done? Probably because the transfer was timed out or otherwise prematurely ended from curl's side.

But more importantly: when a transfer is ended, Curl_http_done should be called, which in turn calls Curl_http2_done. And in there it calls, or should call, nghttp2_session_set_stream_user_data() to clear the association from the stream-id to this now ending transfer (easy handle).

So, the incoming frame on an already completed transfer should not be associated with the old easy handle when things work out. Can you figure out why this logic doesn't work for your scenario?

@ThomasObenaus

This comment has been minimized.

Show comment
Hide comment
@ThomasObenaus

ThomasObenaus Jun 30, 2018

I'll check this on Monday. Sadly currently I don't have access to the setup.

ThomasObenaus commented Jun 30, 2018

I'll check this on Monday. Sadly currently I don't have access to the setup.

@jeroen

This comment has been minimized.

Show comment
Hide comment
@jeroen

jeroen Jul 3, 2018

Contributor

@ThomasObenaus does your application use CURLMOPT_MAX_HOST_CONNECTIONS? I found that this seems to trigger problems in my case.

Contributor

jeroen commented Jul 3, 2018

@ThomasObenaus does your application use CURLMOPT_MAX_HOST_CONNECTIONS? I found that this seems to trigger problems in my case.

@ReneReusner

This comment has been minimized.

Show comment
Hide comment
@ReneReusner

ReneReusner Aug 14, 2018

If I understand you correctly. You have identified a case where a h2 stream is started (and user_data is set), curl stops the stream before it gets added to "the map" and tries to clear the user_data - which fails because it isn't yet in the map. After that, a frame from that stream appears and it then (surprise!) provides the pointer as user_data even though we tried to clear it previously.

Was that a roughly correct description?

YES

nghttp2_session_set_stream_user_data() to zero won't help in this case, cause its added later on.
We now have a maybe deleted Curl_easy* in a callback.

And i wont say "a frame from that stream appears" better "nghttp2 decides it can now send some frames on this streamid (static int before_frame_send callback is called)".

We need to clear the streamid from the session or update the user_handle, while its still not in the stream id hash map. I sdid not read the nghttp manual (only the tutorial), i was asked by ThomasObenaus to assist in debug. At our company i'm in the system group, normaly doing low level stuff, but also called a lot for assist in analyzing some very hard/weird bugs.

Ending work in 20min, so I have no time left, to look how to remove the streamid/user_data from the nghttp2_session. Just call nghttp2_session_set_stream_user_data() is not enough.

ReneReusner commented Aug 14, 2018

If I understand you correctly. You have identified a case where a h2 stream is started (and user_data is set), curl stops the stream before it gets added to "the map" and tries to clear the user_data - which fails because it isn't yet in the map. After that, a frame from that stream appears and it then (surprise!) provides the pointer as user_data even though we tried to clear it previously.

Was that a roughly correct description?

YES

nghttp2_session_set_stream_user_data() to zero won't help in this case, cause its added later on.
We now have a maybe deleted Curl_easy* in a callback.

And i wont say "a frame from that stream appears" better "nghttp2 decides it can now send some frames on this streamid (static int before_frame_send callback is called)".

We need to clear the streamid from the session or update the user_handle, while its still not in the stream id hash map. I sdid not read the nghttp manual (only the tutorial), i was asked by ThomasObenaus to assist in debug. At our company i'm in the system group, normaly doing low level stuff, but also called a lot for assist in analyzing some very hard/weird bugs.

Ending work in 20min, so I have no time left, to look how to remove the streamid/user_data from the nghttp2_session. Just call nghttp2_session_set_stream_user_data() is not enough.

@bagder

This comment has been minimized.

Show comment
Hide comment
@bagder

bagder Aug 14, 2018

Member

nghttp2_session_set_stream_user_data() to zero won't help in this case

Does it return an error for this case? Do you consider this to be a bug in nghttp2? Do we need to add our own map to detect these completed streams that might give us something we don't want?

Member

bagder commented Aug 14, 2018

nghttp2_session_set_stream_user_data() to zero won't help in this case

Does it return an error for this case? Do you consider this to be a bug in nghttp2? Do we need to add our own map to detect these completed streams that might give us something we don't want?

@ReneReusner

This comment has been minimized.

Show comment
Hide comment
@ReneReusner

ReneReusner Aug 14, 2018

Yes it return an error.
But the user_data is still added after this -> BOOM.

One way is: For the curl connection have a own "set" of active and valid streamids, so we can "detect" streamids with invalid user_data.

Or take a look in the nghttp2 manuel, to "remove" a streamid from a session in EVERY case. Only the streamid hash map is not enough.

ReneReusner commented Aug 14, 2018

Yes it return an error.
But the user_data is still added after this -> BOOM.

One way is: For the curl connection have a own "set" of active and valid streamids, so we can "detect" streamids with invalid user_data.

Or take a look in the nghttp2 manuel, to "remove" a streamid from a session in EVERY case. Only the streamid hash map is not enough.

@bagder

This comment has been minimized.

Show comment
Hide comment
@bagder

bagder Aug 14, 2018

Member

@tatsuhiro-t: can this and is it meant to be able to happen? We call nghttp2_submit_request() that adds a stream_id => user_data association (toward the end of the http2_send function) but according to @ReneReusner's findings we can end up calling nghttp2_session_set_stream_user_data() to clear that association before it is actually made, which makes it fail to clear the association and instead we can end up getting that user_data passed anyway if frames from that stream still arrives.

Member

bagder commented Aug 14, 2018

@tatsuhiro-t: can this and is it meant to be able to happen? We call nghttp2_submit_request() that adds a stream_id => user_data association (toward the end of the http2_send function) but according to @ReneReusner's findings we can end up calling nghttp2_session_set_stream_user_data() to clear that association before it is actually made, which makes it fail to clear the association and instead we can end up getting that user_data passed anyway if frames from that stream still arrives.

@ReneReusner

This comment has been minimized.

Show comment
Hide comment
@ReneReusner

ReneReusner Aug 14, 2018

Does it return an error for this case? Do you consider this to be a bug in nghttp2? Do we need to add our own map to detect these completed streams that might give us something we don't want?

After years of debugging alien software, i won't call it a bug, maybe a feature or implementation detail :-).

A own map would help:

One way is: For the curl connection have a own "set" of active and valid streamids, so we can "detect" streamids with invalid user_data.

It feels like "only a workaround". But i did a lot of "workarounds", so i can live with an another workaround.

ReneReusner commented Aug 14, 2018

Does it return an error for this case? Do you consider this to be a bug in nghttp2? Do we need to add our own map to detect these completed streams that might give us something we don't want?

After years of debugging alien software, i won't call it a bug, maybe a feature or implementation detail :-).

A own map would help:

One way is: For the curl connection have a own "set" of active and valid streamids, so we can "detect" streamids with invalid user_data.

It feels like "only a workaround". But i did a lot of "workarounds", so i can live with an another workaround.

@ReneReusner

This comment has been minimized.

Show comment
Hide comment
@ReneReusner

ReneReusner Aug 14, 2018

Back from cinema (mission impossible yay). I hope i can see bugfix after my vacation :-).

But back to topic:

One idea, the place elsewhere before the stream is insert in the map is maybe the "data provider (data_prd) interface" of nghttp2, if i remember correctly from my memory (@home now, no source code). Only when nghttp2 starts sending a stream is insert in the streamid map. The reason why i'm writing this, we need to make sure, there also no remains of a dead stream are left in this interface. In the most cases i would dig deeper, cause i think i'm on the right track, but my 2.5 week vacation starts now.

Have a nice summer and a lot of ice cream.

ReneReusner commented Aug 14, 2018

Back from cinema (mission impossible yay). I hope i can see bugfix after my vacation :-).

But back to topic:

One idea, the place elsewhere before the stream is insert in the map is maybe the "data provider (data_prd) interface" of nghttp2, if i remember correctly from my memory (@home now, no source code). Only when nghttp2 starts sending a stream is insert in the streamid map. The reason why i'm writing this, we need to make sure, there also no remains of a dead stream are left in this interface. In the most cases i would dig deeper, cause i think i'm on the right track, but my 2.5 week vacation starts now.

Have a nice summer and a lot of ice cream.

@tatsuhiro-t

This comment has been minimized.

Show comment
Hide comment
@tatsuhiro-t

tatsuhiro-t Aug 15, 2018

Contributor

@bagder Yes, it can happen if we call nghttp2_set_stream_user_data before sending first HEADERS frame which includes HTTP request. nghttp2_session_set_stream_user_data succeeds only after nghttp2_before_frame_send_callback or nghttp2_on_frame_not_send_callback.
Is Curl_http_done called before sending HTTP request?

Contributor

tatsuhiro-t commented Aug 15, 2018

@bagder Yes, it can happen if we call nghttp2_set_stream_user_data before sending first HEADERS frame which includes HTTP request. nghttp2_session_set_stream_user_data succeeds only after nghttp2_before_frame_send_callback or nghttp2_on_frame_not_send_callback.
Is Curl_http_done called before sending HTTP request?

@tatsuhiro-t

This comment has been minimized.

Show comment
Hide comment
@tatsuhiro-t

tatsuhiro-t Aug 15, 2018

Contributor

nghttp2 has a special handling of nghttp2_submit_rst_stream. If it is used against a stream which is not opened yet (the case we are concerned about), it cancels the stream and no frame is sent.
nghttp2_on_stream_close_callback is still called in that case, and if http->h2 must be deleted before that, we might access dangling pointer.
A possible resolution to this is use another object which binds a stream and http->h2 and use it as stream user data.

struct data_binder {
    typeof(http->h2) *h2;
};

This object is created when we call nghttp2_submit_request and deleted in nghttp2_on_stream_callback. Where we call nghttp2_session_set_stream_user_data(s, id, NULL), we can get the object and assign h2 field to NULL.

Contributor

tatsuhiro-t commented Aug 15, 2018

nghttp2 has a special handling of nghttp2_submit_rst_stream. If it is used against a stream which is not opened yet (the case we are concerned about), it cancels the stream and no frame is sent.
nghttp2_on_stream_close_callback is still called in that case, and if http->h2 must be deleted before that, we might access dangling pointer.
A possible resolution to this is use another object which binds a stream and http->h2 and use it as stream user data.

struct data_binder {
    typeof(http->h2) *h2;
};

This object is created when we call nghttp2_submit_request and deleted in nghttp2_on_stream_callback. Where we call nghttp2_session_set_stream_user_data(s, id, NULL), we can get the object and assign h2 field to NULL.

@bagder

This comment has been minimized.

Show comment
Hide comment
@bagder

bagder Aug 15, 2018

Member

Thanks for these details @tatsuhiro-t !

it can happen if we call nghttp2_set_stream_user_data before sending first HEADERS frame which includes HTTP request

...

A possible resolution to this is use another object

OK, but that possible resolution is then best implemented as a separate hash so that we get a fast lookup for the assign-NULL case. Which feels wrong since nghttp2 already provides this functionality for us, just with this tiny glitch...

This "delayed assignment" behavior is not documented for nghttp2_submit_request. But should it really behave like that? Isn't this an nghttp2 bug?

nghttp2_submit_request knows which stream_id it'll become, as it returns that information just fine, and it knows the user_data pointer. Right?

Member

bagder commented Aug 15, 2018

Thanks for these details @tatsuhiro-t !

it can happen if we call nghttp2_set_stream_user_data before sending first HEADERS frame which includes HTTP request

...

A possible resolution to this is use another object

OK, but that possible resolution is then best implemented as a separate hash so that we get a fast lookup for the assign-NULL case. Which feels wrong since nghttp2 already provides this functionality for us, just with this tiny glitch...

This "delayed assignment" behavior is not documented for nghttp2_submit_request. But should it really behave like that? Isn't this an nghttp2 bug?

nghttp2_submit_request knows which stream_id it'll become, as it returns that information just fine, and it knows the user_data pointer. Right?

bagder added a commit that referenced this issue Aug 15, 2018

bagder added a commit that referenced this issue Aug 15, 2018

@tatsuhiro-t

This comment has been minimized.

Show comment
Hide comment
@tatsuhiro-t

tatsuhiro-t Aug 16, 2018

Contributor

We don't need hash because we know the address of the object. Doubly linked list is enough in this case.

The text:

This function returns assigned stream ID if it succeeds. But that stream is not opened yet. The application must not submit frame to that stream ID before nghttp2_before_frame_send_callback is called for this frame.

implies that stream is not created. It says "not opened" and "not created" so I admit that I didn't write it explicitly.

nghttp2_submit_request knows which stream_id it'll become, as it returns that information just fine, and it knows the user_data pointer. Right?

Well, yes.
I think that I can create idle stream when nghttp2_submit_request is done. The opening of stream is still delayed, but all we want is stream object which we can assign opaque pointer.

It implies extra memory overhead if app issues lots of requests. It is not bounded by max concurrent streams any more. I think it would be better to add a new option to enable this new behaviour. Thoughts?

Contributor

tatsuhiro-t commented Aug 16, 2018

We don't need hash because we know the address of the object. Doubly linked list is enough in this case.

The text:

This function returns assigned stream ID if it succeeds. But that stream is not opened yet. The application must not submit frame to that stream ID before nghttp2_before_frame_send_callback is called for this frame.

implies that stream is not created. It says "not opened" and "not created" so I admit that I didn't write it explicitly.

nghttp2_submit_request knows which stream_id it'll become, as it returns that information just fine, and it knows the user_data pointer. Right?

Well, yes.
I think that I can create idle stream when nghttp2_submit_request is done. The opening of stream is still delayed, but all we want is stream object which we can assign opaque pointer.

It implies extra memory overhead if app issues lots of requests. It is not bounded by max concurrent streams any more. I think it would be better to add a new option to enable this new behaviour. Thoughts?

@bagder

This comment has been minimized.

Show comment
Hide comment
@bagder

bagder Aug 16, 2018

Member

(I still have not personally seen this happen so I'm basing my reasoning on @ReneReusner's discussion above with @tatsuhiro-t's input on nghttp2 details.)

Doubly linked list is enough in this case.

Ah yes you're right. We can point directly to a node a such a linked list.

It implies extra memory overhead

I don't think you need to allocate any more memory, I think this is just a matter of changing some logic - unless I'm misunderstanding something.

You already have the "stream => user_data" association in there in a queue somehow, set in the call to nghttp2_submit_request(). The problem we seem have here is that we can't clear that association with nghttp2_session_set_stream_user_data() immediately.

Can't we make *set_stream_user_data() also scan the queue of pending requests to send and clear the pending association even if the data hasn't already been sent? There's a problem when there are time gaps where we can't clear the associations. It makes them complicated to use.

This said, I'm also prepared to try out the linked-list approach. I suppose we'd then keep the list entry in the list until the on_stream_close_callback is called using it?

Member

bagder commented Aug 16, 2018

(I still have not personally seen this happen so I'm basing my reasoning on @ReneReusner's discussion above with @tatsuhiro-t's input on nghttp2 details.)

Doubly linked list is enough in this case.

Ah yes you're right. We can point directly to a node a such a linked list.

It implies extra memory overhead

I don't think you need to allocate any more memory, I think this is just a matter of changing some logic - unless I'm misunderstanding something.

You already have the "stream => user_data" association in there in a queue somehow, set in the call to nghttp2_submit_request(). The problem we seem have here is that we can't clear that association with nghttp2_session_set_stream_user_data() immediately.

Can't we make *set_stream_user_data() also scan the queue of pending requests to send and clear the pending association even if the data hasn't already been sent? There's a problem when there are time gaps where we can't clear the associations. It makes them complicated to use.

This said, I'm also prepared to try out the linked-list approach. I suppose we'd then keep the list entry in the list until the on_stream_close_callback is called using it?

@tatsuhiro-t

This comment has been minimized.

Show comment
Hide comment
@tatsuhiro-t

tatsuhiro-t Aug 16, 2018

Contributor

Can't we make *set_stream_user_data() also scan the queue of pending requests to send and clear the pending association even if the data hasn't already been sent? There's a problem when there are time gaps where we can't clear the associations. It makes them complicated to use.

The problem is it might take a time because of its linear scan.
But I did it for RST_STREAM already. The range of stream ID is bounded by the next stream ID and the stream ID at the front of the queue. Not sure it costs real performance penalty. It depends on how many outstanding request is queued by app.

Contributor

tatsuhiro-t commented Aug 16, 2018

Can't we make *set_stream_user_data() also scan the queue of pending requests to send and clear the pending association even if the data hasn't already been sent? There's a problem when there are time gaps where we can't clear the associations. It makes them complicated to use.

The problem is it might take a time because of its linear scan.
But I did it for RST_STREAM already. The range of stream ID is bounded by the next stream ID and the stream ID at the front of the queue. Not sure it costs real performance penalty. It depends on how many outstanding request is queued by app.

@ReneReusner

This comment has been minimized.

Show comment
Hide comment
@ReneReusner

ReneReusner Aug 16, 2018

I don't know the design of nghttp2, so my comment below may be nonsense, but just do the simple way?

Why not removing the stream_user_data from the stream object and other queues. Then change the stream id hash map value to a

struct hash_map_entry {
    nghttp2_stream *foo;
    void *stream_user_data;
}

So nghttp2_submit_request will place the stream_user_data in the map but leave foo = NULL. Its assigned when the stream gets opened.

So you can change the stream id <-> stream_user_data association, regardless of the internal stream object state.

ReneReusner commented Aug 16, 2018

I don't know the design of nghttp2, so my comment below may be nonsense, but just do the simple way?

Why not removing the stream_user_data from the stream object and other queues. Then change the stream id hash map value to a

struct hash_map_entry {
    nghttp2_stream *foo;
    void *stream_user_data;
}

So nghttp2_submit_request will place the stream_user_data in the map but leave foo = NULL. Its assigned when the stream gets opened.

So you can change the stream id <-> stream_user_data association, regardless of the internal stream object state.

@tatsuhiro-t

This comment has been minimized.

Show comment
Hide comment
@tatsuhiro-t

tatsuhiro-t Aug 16, 2018

Contributor

We use invasive map entry to reduce the number of allocations. If we add another layer of objects, it incurs one more allocation per stream.

Contributor

tatsuhiro-t commented Aug 16, 2018

We use invasive map entry to reduce the number of allocations. If we add another layer of objects, it incurs one more allocation per stream.

@ReneReusner

This comment has been minimized.

Show comment
Hide comment
@ReneReusner

ReneReusner Aug 17, 2018

I agree, but the discusion over on more alloc is pointless, if we need to do it anyway (a own "set" to track valid stream ids) in libcurl to fix the broken nghttp2_session_set_stream_user_data().

ReneReusner commented Aug 17, 2018

I agree, but the discusion over on more alloc is pointless, if we need to do it anyway (a own "set" to track valid stream ids) in libcurl to fix the broken nghttp2_session_set_stream_user_data().

@bagder

This comment has been minimized.

Show comment
Hide comment
@bagder

bagder Aug 17, 2018

Member

I agree with @ReneReusner. I consider this a nghttp2 "mis-feature" if not a downright bug.

We should probably consider doing the extra layer on top anyway so that we can make sure to work with existing nghttp2 installations everywhere, but I think this nghttp2 behavior should be fixed since it makes using the API really complicated.

Member

bagder commented Aug 17, 2018

I agree with @ReneReusner. I consider this a nghttp2 "mis-feature" if not a downright bug.

We should probably consider doing the extra layer on top anyway so that we can make sure to work with existing nghttp2 installations everywhere, but I think this nghttp2 behavior should be fixed since it makes using the API really complicated.

bagder added a commit that referenced this issue Aug 17, 2018

http2: add easymap layer to avoid stale pointers to freed memory
Instead of passing the easy handle directly to nghttp2 to map from
stream_id to our structs, we create an 'easymap' node (for each new
stream) and add to a per-connection linked list. The easymap struct
itself contains a pointer to the easy handle and the stream id. This
node *MUST* remain in the list until the 'on_stream_close' callback
comes. This node can survive the easy handle.

If we want to remove the association between a stream and an easy handle
before the stream end callback from nghtp2, we now call
disassociate_easymap() which "soft removes" the association in the
easymap struct only.

This is necesary since when nghttp2_submit_request() is called, the
stream<=>easy association isn't immediately done by nghttp2 and if we
then try to clear the assication at once (using
nghttp2_session_set_stream_user_data), that clearing fails and we risk
having the (by now) old assication getting done by nghttp2 and then risk
subsequently fetching a stale pointer to already freed data.

Fixes #2688
Fixes #2894
@tatsuhiro-t

This comment has been minimized.

Show comment
Hide comment
@tatsuhiro-t

tatsuhiro-t Aug 18, 2018

Contributor

Here is the PR to fix this in nghttp2 side as @bagder suggested
nghttp2/nghttp2#1211

Contributor

tatsuhiro-t commented Aug 18, 2018

Here is the PR to fix this in nghttp2 side as @bagder suggested
nghttp2/nghttp2#1211

@bagder

This comment has been minimized.

Show comment
Hide comment
@bagder

bagder Aug 18, 2018

Member

That sounds awesome. Thanks @tatsuhiro-t !

Member

bagder commented Aug 18, 2018

That sounds awesome. Thanks @tatsuhiro-t !

@linusnielsen

This comment has been minimized.

Show comment
Hide comment
@linusnielsen

linusnielsen Aug 21, 2018

Contributor

@tatsuhiro-t It looks like your nghttp2 fix solves this issue. Thanks a lot!

Any chance that you could do an official release of nghttp2 with this fix included?

Contributor

linusnielsen commented Aug 21, 2018

@tatsuhiro-t It looks like your nghttp2 fix solves this issue. Thanks a lot!

Any chance that you could do an official release of nghttp2 with this fix included?

@ThomasObenaus

This comment has been minimized.

Show comment
Hide comment
@ThomasObenaus

ThomasObenaus Aug 21, 2018

Yes many thanks @tatsuhiro-t . Our test setup ran now for ~8h without a crash.

As @linusnielsen lined out it would be really helpful for us if you would be so kind to make an official release of nghttp2.
Then we can integrate the fixed version as soon as possible in our software.

ThomasObenaus commented Aug 21, 2018

Yes many thanks @tatsuhiro-t . Our test setup ran now for ~8h without a crash.

As @linusnielsen lined out it would be really helpful for us if you would be so kind to make an official release of nghttp2.
Then we can integrate the fixed version as soon as possible in our software.

@tatsuhiro-t

This comment has been minimized.

Show comment
Hide comment
@tatsuhiro-t

tatsuhiro-t Aug 22, 2018

Contributor

I will release a patch version within next 7 days.

Contributor

tatsuhiro-t commented Aug 22, 2018

I will release a patch version within next 7 days.

@bagder

This comment has been minimized.

Show comment
Hide comment
@bagder

bagder Aug 22, 2018

Member

As this problem is now fixed, even though the fix is in nghttp2, we can consider this case closed. Thank you all for participating!

Member

bagder commented Aug 22, 2018

As this problem is now fixed, even though the fix is in nghttp2, we can consider this case closed. Thank you all for participating!

@bagder bagder closed this Aug 22, 2018

xquery added a commit to xquery/curl that referenced this issue Sep 3, 2018

falconindy added a commit to falconindy/curl that referenced this issue Sep 10, 2018

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment