Hi Daniel, > This is plain HTTP? It is HTTPS. > I guess it could be intersting to bisect your way all the way to the exact commit that changed the behavior for you... That is a good suggestion. It might be worthwhile doing a git bisect and seeing if we can narrow it down to a single commit. I'll try that out. > It gets stuck forever in a check that is supposed to time-out after 1000 ms? Are you sure? What I meant was that it waits there for a second, then comes out, and then immediately back in for another second and so on until the timeout that we have configured has passed - which is 60 seconds. So taking multiple cores will show the same backtrace because it only leaves the poll for a very short instance. > ... and you're saying that the data is coming without libcurl noticing it? Yes exactly! That is the hunch. I was looking through the core some more and I see the following. I've not yet traced the logic around how the contents of data are updated/manipulated. But it seems odd to me that the regions in the conn->data.state.buffer seem to have the 201 OK response that we are expecting, but curl seems to continue to wait around for more data. I will follow the code, but pasting this here in case it rings any bells. (gdb) where #0  0x0000003dca8dc053 in poll () from /lib64/libc.so.6 #1  0x0000000000586170 in Curl_socket_check (readfd0=315, readfd1=-1, writefd=-1, timeout_ms=1000) at select.c:216 #2  0x00000000005b94c6 in Transfer (conn=0x7fd17c001308) at transfer.c:1384 #3  0x00000000005ba4a6 in Curl_do_perform (data=0x7fd1780008e8) at transfer.c:2109 #4  0x00000000005ba75c in Curl_perform (data=0x7fd1780008e8) at transfer.c:2233 #5  0x000000000057c505 in curl_easy_perform (curl=0x7fd1780008e8) at easy.c:536 .... .... .... .... (gdb) up #3  0x00000000005ba4a6 in Curl_do_perform (data=0x7fd1780008e8) at transfer.c:2109 2109    in transfer.c (gdb) down #2  0x00000000005b94c6 in Transfer (conn=0x7fd17c001308) at transfer.c:1384 1384    in transfer.c (gdb) p *conn->data $3 = {dns = {hostcache = 0x7fd17c000cf8, hostcachetype = HCACHE_PRIVATE}, multi = 0x0, multi_pos = 0x0, share = 0x0, req = {size = -1, bytecountp = 0x7fd178037510, maxdownload = -1, writebytecountp = 0x7fd178037518, bytecount = 0, writebytecount = 65535, headerbytecount = 0, deductheadercount = 0, start = {       tv_sec = 1422248, tv_usec = 480010}, now = {tv_sec = 1422262, tv_usec = 531066}, header = true, badheader = HEADER_NORMAL, headerline = 0, hbufp = 0x7fd17801b6a8 "\r\n", hbuflen = 0, str = 0x0, str_start = 0x0, end_ptr = 0x0, p = 0x0, content_range = false, offset = 0, httpcode = 0, start100 = {tv_sec = 0,       tv_usec = 0}, exp100 = EXP100_SEND_DATA, auto_decoding = 0, zlib_init = ZLIB_UNINIT, z = {next_in = 0x0, avail_in = 0, total_in = 0, next_out = 0x0, avail_out = 0, total_out = 0, msg = 0x0, state = 0x0, zalloc = 0, zfree = 0, opaque = 0x0, data_type = 0, adler = 0, reserved = 0}, timeofdoc = 0,     bodywrites = 0, buf = 0x7fd178001148 "HTTP/1.1 201 Created\r\nTransfer-Encoding: chunked\r\nContent-MD5: VoN1C/RxIFDzBg2vPX3wdQ==\r\nLast-Modified: Thu, 18 Oct 2012 08:22:51 GMT\r\nETag: 0x8CF7B20E6900E5D\r\nServer: Blob Service Version 1.0 Microso"...,     uploadbuf = 0x7fd178005149 "\211\314\317o\207\323\354\214˒ؿ`\032F\t\311\371\210\030\275C\250-\242eH\317ʩ91o\210\336do\263?<\310\340\354\004\323U\230\341A6q\a\326\216@\235\347\036Eq\224\351\320[\306{\237s\350\375\373\362d\372\221\351\344\357\021\244E\224\210\333[\355~\236h\017\317\376Y\263J|\306|\v3\247\b\230\304\327\270\276\005K@)i\017\355\306-\004\271\331H[\021\335\020\320`\037\254\247c\031=g,\217\313Y\363k\361\277\240YI\325\031\"\225\211Kʲ\371\372h=\261I\310\002\241\t\302)\337\301W\037\"\201\221E\372g\031[\320\242\372\310\365{\244g\036\263ż\227\353D\375\216\307 i", <incomplete sequence \327>..., maxfd = 316,     keepon = 1, upload_done = true, ignorebody = false, ignorecl = false, location = 0x0, newurl = 0x0, upload_present = 0,     upload_fromhere = 0x7fd178005149 "\211\314\317o\207\323\354\214˒ؿ`\032F\t\311\371\210\030\275C\250-\242eH\317ʩ91o\210\336do\263?<\310\340\354\004\323U\230\341A6q\a\326\216@\235\347\036Eq\224\351\320[\306{\237s\350\375\373\362d\372\221\351\344\357\021\244E\224\210\333[\355~\236h\017\317\376Y\263J|\306|\v3\247\b\230\304\327\270\276\005K@)i\017\355\306-\004\271\331H[\021\335\020\320`\037\254\247c\031=g,\217\313Y\363k\361\277\240YI\325\031\"\225\211Kʲ\371\372h=\261I\310\002\241\t\302)\337\301W\037\"\201\221E\372g\031[\320\242\372\310\365{\244g\036\263ż\227\353D\375\216\307 i", <incomplete sequence \327>...,     chunk = false, upload_chunky = false, getheader = true, forbidchunk = false}, set = {err = 0x3dcab9b860, debugdata = 0x7fd174400008, errorbuffer = 0x0, proxyport = 1080, out = 0x7fd174400008, in = 0x7fd174400008, writeheader = 0x7fd174400008, rtp_out = 0x0, use_port = 0, httpauth = 1, proxyauth = 1,     followlocation = 0, maxredirs = 10, keep_post = 0, free_referer = false, postfields = 0x0, seek_func = 0x44a1c0 <curl_seek_cb>, postfieldsize = -1, localport = 0, localportrange = 0, fwrite_func = 0x45dcc0 <curl_write_rsp_cb>, fwrite_header = 0x45d320 <curl_header_cb>, fwrite_rtp = 0,     fread_func = 0x45d020 <curl_read_cb>, is_fread_set = 1, is_fwrite_set = 1, fprogress = 0, fdebug = 0x46af40 <curl_debug_cb>, ioctl_func = 0, fsockopt = 0, sockopt_client = 0x0, fopensocket = 0, opensocket_client = 0x0, fclosesocket = 0, closesocket_client = 0x0, seek_client = 0x7fd174400008,     convfromnetwork = 0, convtonetwork = 0, convfromutf8 = 0, progress_client = 0x0, ioctl_client = 0x0, timeout = 60000, connecttimeout = 0, accepttimeout = 0, server_response_timeout = 0, tftp_blksize = 0, infilesize = 65535, low_speed_limit = 0, low_speed_time = 0, max_send_speed = 0, max_recv_speed = 0,     set_resume_from = 0, headers = 0x7fd178036a38, httppost = 0x0, cookiesession = false, crlf = false, quote = 0x0, postquote = 0x0, prequote = 0x0, source_quote = 0x0, source_prequote = 0x0, source_postquote = 0x0, telnet_options = 0x0, resolve = 0x0, timecondition = CURL_TIMECOND_NONE, timevalue = 0,     httpreq = HTTPREQ_PUT, httpversion = 0, ssl = {version = 0, certverifyresult = 0, verifypeer = 0, verifyhost = 2, CApath = 0x0, CAfile = 0x7fd178036c68 "/etc/pki/tls/certs/ca-bundle.crt", CRLfile = 0x0, issuercert = 0x0, random_file = 0x0, egdsocket = 0x0, cipher_list = 0x0, max_ssl_sessions = 5, fsslctx = 0,       fsslctxp = 0x0, sessionid = true, certinfo = false}, proxytype = CURLPROXY_HTTP, dns_cache_timeout = 3600, buffer_size = 0, private_data = 0x7fd174400008, one_easy = 0x0, http200aliases = 0x0, ipver = 1, max_filesize = 0, ftp_filemethod = FTPFILE_MULTICWD, ftp_create_missing_dirs = 0, ssh_keyfunc = 0,     ssh_keyfunc_userp = 0x0, printhost = false, get_filetime = false, tunnel_thru_httpproxy = false, prefer_ascii = false, ftp_append = false, ftp_list_only = false, ftp_use_port = false, hide_progress = true, http_fail_on_error = false, http_follow_location = true, http_transfer_encoding = false,     http_disable_hostname_check_before_authentication = false, include_header = false, http_set_referer = false, http_auto_referer = false, opt_no_body = false, set_port = false, upload = true, use_netrc = CURL_NETRC_IGNORED, verbose = true, krb = false, reuse_forbid = false, reuse_fresh = false,     ftp_use_epsv = true, ftp_use_eprt = true, ftp_use_pret = false, use_ssl = CURLUSESSL_NONE, ftpsslauth = CURLFTPAUTH_DEFAULT, ftp_ccc = CURLFTPSSL_CCC_NONE, no_signal = true, global_dns_cache = false, tcp_nodelay = true, ignorecl = false, ftp_skip_ip = false, connect_only = false, ssl_enable_beast = false,     ssh_auth_types = -1, http_te_skip = false, http_ce_skip = false, new_file_perms = 420, new_directory_perms = 493, proxy_transfer_mode = false, str = {0x0 <repeats 19 times>,       0x7fd178036958 "https://somecloud/ssdput-9c68b92e/utroot/2012-10-18/gautaminstos2ssim1-CSATEST-1350548527/01010101-0101-0101-0101-010101010101-primary/0x93-0", 0x0, 0x7fd178036c68 "/etc/pki/tls/certs/ca-bundle.crt", 0x0 <repeats 16 times>}, scope = 0, allowed_protocols = -1,     redir_protocols = -1041, mail_rcpt = 0x0, rtspreq = RTSPREQ_OPTIONS, rtspversion = 0, wildcardmatch = false, chunk_bgn = 0, chunk_end = 0, fnmatch = 0, fnmatch_data = 0x0, gssapi_delegation = 0, tcp_keepalive = false, tcp_keepidle = 60, tcp_keepintvl = 60}, change = {     url = 0x7fd178036958 "https://somecloud/ssdput-9c68b92e/utroot/2012-10-18/gautaminstos2ssim1-CSATEST-1350548527/01010101-0101-0101-0101-010101010101-primary/0x93-0", url_alloc = false, referer = 0x0, referer_alloc = false, cookielist = 0x0, resolve = 0x0}, cookies = 0x0, progress = {     lastshow = 1422262, size_dl = 0, size_ul = 65535, downloaded = 0, uploaded = 65535, current_speed = 0, callback = false, width = 0, flags = 48, timespent = 14.051094000000001, dlspeed = 0, ulspeed = 4664, t_nslookup = 3.8000000000000002e-05, t_connect = 3.8000000000000002e-05,     t_appconnect = 3.8000000000000002e-05, t_pretransfer = 0.00013200000000000001, t_starttransfer = 0.00014100000000000001, t_redirect = 0, start = {tv_sec = 1422248, tv_usec = 479973}, t_startsingle = {tv_sec = 1422248, tv_usec = 479973}, t_acceptdata = {tv_sec = 0, tv_usec = 0}, speeder = {65535, 65535, 65535,       65535, 65535, 65535}, speeder_time = {{tv_sec = 1422260, tv_usec = 524632}, {tv_sec = 1422261, tv_usec = 526099}, {tv_sec = 1422262, tv_usec = 531067}, {tv_sec = 1422257, tv_usec = 520218}, {tv_sec = 1422258, tv_usec = 521627}, {tv_sec = 1422259, tv_usec = 523125}}, speeder_c = 15}, state = {     used_interface = Curl_if_easy, connc = 0x7fd17c000f58, keeps_speed = {tv_sec = 1422262, tv_usec = 531066}, lastconnect = 0, headerbuff = 0x7fd17801b6a8 "\r\n", headersize = 256,     buffer = "HTTP/1.1 201 Created\r\nTransfer-Encoding: chunked\r\nContent-MD5: VoN1C/RxIFDzBg2vPX3wdQ==\r\nLast-Modified: Thu, 18 Oct 2012 08:22:51 GMT\r\nETag: 0x8CF7B20E6900E5D\r\nServer: Blob Service Version 1.0 Microso"...,     uploadbuffer = "\211\314\317o\207\323\354\214˒ؿ`\032F\t\311\371\210\030\275C\250-\242eH\317ʩ91o\210\336do\263?<\310\340\354\004\323U\230\341A6q\a\326\216@\235\347\036Eq\224\351\320[\306{\237s\350\375\373\362d\372\221\351\344\357\021\244E\224\210\333[\355~\236h\017\317\376Y\263J|\306|\v3\247\b\230\304\327\270\276\005K@)i\017\355\306-\004\271\331H[\021\335\020\320`\037\254\247c\031=g,\217\313Y\363k\361\277\240YI\325\031\"\225\211Kʲ\371\372h=\261I\310\002\241\t\302)\337\301W\037\"\201\221E\372g\031[\320\242\372\310\365{\244g\036\263ż\227\353D\375\216\307
 i\327j<(\231\263\356\340\270\071F\027\006\006\036K)\027\346\323J\220,s\203\277\356\302\005נ<\fh\373'\204\241\214&xF\370\236?o\017\314e\006\230\243Z\376\327g\335T\336\n&ƘI\326V\227\206\237}\230d\263\060\334$\356\224&\302\302\200\222\317\346\266\034\r\276\341\354̉Nc\aMk\346>\202\000m\021\200/ʡ\252,\271\246X\275\255P\206qU\337>\240\360\001\305&V\357\210\336\301F\304\340`\246\370{\232\f\f\361\"\360>\365\277\035\321\345\331Tt\307às\005\312x\237\350\001\226\376\326ʚ3L%]\254\231\270\026\216`\242/`\313\000\345y\220;\242*\245\030\032\254\302}'Ț\004eI\332A\215"..., current_speed = -1, this_is_a_follow = false, first_host = 0x7fd178037468 "ssdput.blob.core.windows.net",     session = 0x7fd17c000fc8, sessionage = 1, tempwrite = 0x0, tempwritesize = 0, tempwritetype = 0, scratch = 0x0, errorbuf = false, os_errno = 0, prev_signal = 0, allow_port = true, digest = {nonce = 0x0, cnonce = 0x0, realm = 0x0, algo = 0, stale = false, opaque = 0x0, qop = 0x0, algorithm = 0x0, nc = 0},     proxydigest = {nonce = 0x0, cnonce = 0x0, realm = 0x0, algo = 0, stale = false, opaque = 0x0, qop = 0x0, algorithm = 0x0, nc = 0}, authhost = {want = 1, picked = 0, avail = 0, done = true, multi = false, iestyle = false}, authproxy = {want = 1, picked = 0, avail = 0, done = true, multi = false,       iestyle = false}, authproblem = false, resolver = 0x7fd178009480, engine = 0x0, expiretime = {tv_sec = 0, tv_usec = 0}, timenode = {smaller = 0x0, larger = 0x0, same = 0x0, key = {tv_sec = 0, tv_usec = 0}, payload = 0x0}, timeoutlist = 0x0, most_recent_ftp_entrypath = 0x0, ftp_trying_alternative = false,     httpversion = 0, expect100header = false, pipe_broke = false, prev_block_had_trailing_cr = false, crlf_conversions = 0, shared_conn = 0x0, closed = false, pathbuffer = 0x7fd178036d28 "/ssdput-9c68b92e/utroot/2012-10-18/gautaminstos2ssim1-CSATEST-1350548527/01010101-0101-0101-0101-010101010101-primary/0x93-0",     path = 0x7fd178036d28 "/ssdput-9c68b92e/utroot/2012-10-18/gautaminstos2ssim1-CSATEST-1350548527/01010101-0101-0101-0101-010101010101-primary/0x93-0", slash_removed = false, use_range = false, rangestringalloc = false, range = 0x0, resume_from = 0, rtsp_next_client_CSeq = 0, rtsp_next_server_CSeq = 0,     rtsp_CSeq_recv = 0, proto = {http = 0x7fd1780374e8, https = 0x7fd1780374e8, rtsp = 0x7fd1780374e8, ftp = 0x7fd1780374e8, file = 0x7fd1780374e8, telnet = 0x7fd1780374e8, generic = 0x7fd1780374e8, ssh = 0x7fd1780374e8, imap = 0x7fd1780374e8, pop3 = 0x7fd1780374e8, smtp = 0x7fd1780374e8},     current_conn = 0x7fd17c001308, ssl_connect_retry = false}, wildcard = {state = CURLWC_INIT, path = 0x0, pattern = 0x0, filelist = 0x0, tmp = 0x0, tmp_dtor = 0, customptr = 0x0}, info = {httpcode = 0, httpproxycode = 0, httpversion = 0, filetime = -1, timecond = false, header_size = 0, request_size = 360,     proxyauthavail = 0, httpauthavail = 0, numconnects = 0, contenttype = 0x0, wouldredirect = 0x0, conn_primary_ip = "<IPCUTOUT>", '\000' <repeats 32 times>, conn_primary_port = 443, conn_local_ip = "10.2.48.74", '\000' <repeats 35 times>, conn_local_port = 40559, certs = {num_of_certs = 0, certinfo = 0x0}},   magic = 3235830701} (gdb) p conn->data.state.buffer $7 = "HTTP/1.1 201 Created\r\nTransfer-Encoding: chunked\r\nContent-MD5: VoN1C/RxIFDzBg2vPX3wdQ==\r\nLast-Modified: Thu, 18 Oct 2012 08:22:51 GMT\r\nETag: 0x8CF7B20E6900E5D\r\nServer: Blob Service Version 1.0 Microsoft-HTTPAPI/2.0\r\nx-ms-request-id: 324c70fd-d140-4bcf-b8ba-04ff00c14406\r\nDate: Thu, 18 Oct 2012 08:22:51 GMT\r\n\r\n0\r\n\r\n", '\000' <repeats 16069 times> ________________________________ From: Daniel Stenberg <daniel_at_haxx.se> To: Gautam Gopinadhan <gautamvsg_at_yahoo.com>; libcurl development <curl-library_at_cool.haxx.se> Sent: Thursday, October 18, 2012 10:51 AM Subject: Re: Intermittent write errors while doing a PUT operation in 7.27.0 On Thu, 18 Oct 2012, Gautam Gopinadhan wrote: > When linked with any version of libcurl until and including 7.23.1, our test code functions exactly as expected - it sends data to the server successfully on every attempt. However from version 7.24.0 onwards, we notice that intermittently one odd connection errors out (after a 60 second timeout due to a setopt) waiting for a 200OK response from the server. This is plain HTTP? I guess it could be intersting to bisect your way all the way to the exact commit that changed the behavior for you... > When viewing the backtrace for a specific failed connection, it seems to wait forever with this backtrace signature. (The line number correspond to 7.27.0) > > (gdb) bt > #0  0x0000003dca8dc053 in poll () from /lib64/libc.so.6 > #1  0x0000000000585fc0 in Curl_socket_check (readfd0=315, readfd1=-1, writefd=-1, timeout_ms=1000) at select.c:216 It gets stuck forever in a check that is supposed to time-out after 1000 ms? Are you sure? > #2  0x00000000005b9316 in Transfer (conn=0x7fadb40012c8) at transfer.c:1384 > #3  0x00000000005ba2f6 in Curl_do_perform (data=0x7fadb00008e8) at transfer.c:2109 > #4  0x00000000005ba5ac in Curl_perform (data=0x7fadb00008e8) at transfer.c:2233 > #5  0x000000000057c355 in curl_easy_perform (curl=0x7fadb00008e8) at easy.c:536 > > This seems to indicate that the thread is waiting for a 200OK from the server after having performed a write.  ... and you're saying that the data is coming without libcurl noticing it? > An interesting observation is that I'm able to recreate this error very consistently and the error happens at the exact same index in the pseudo code while loop above. As mentioned, this is never seen on libcurl 7.23.1 and lower, but it is always seen on all version 7.24.0 and above. I've never seen a report like this before. Between 7.23.1 and 7.24.0 we did 205 commits... -- / daniel.haxx.se

-------------------------------------------------------------------
List admin: http://cool.haxx.se/list/listinfo/curl-library
Etiquette: http://curl.haxx.se/mail/etiquette.html
Received on 2012-10-19