Hi. This may be a libcurl bug, please reassign if needed. We are talking to Bugzilla servers using xmlrpc-c, and we sometimes see strange failures. The code snipped where failure occurs is: update_client(_("Checking for duplicates...")); bug_id = bz_server.check_uuid_in_bugzilla(component, uuid); where check_uuid_in_bugzilla() is: int ctx::check_uuid_in_bugzilla(const char* component, const char* UUID) { xmlrpc_env env; xmlrpc_env_init(&env); std::string query = ssprintf("ALL component:\"%s\" statuswhiteboard:\"%s\"", component, UUID); xmlrpc_value* param = xmlrpc_build_value(&env, "({s:s})", "quicksearch", query.c_str()); throw_if_xml_fault_occurred(&env); // failed to allocate memory xmlrpc_value* result = NULL; xmlrpc_client_call2(&env, m_pClient, m_pServer_info, "Bug.search", param, &result); ... Exactly at this point, looks like xmlrpc_client_call2 sometimes fails. I will attach strace output of successful and failing attempts later. Since you will likely want to see how we initialize m_pClient and m_pServer_info, here is it: struct abrt_xmlrpc_conn { xmlrpc_client* m_pClient; xmlrpc_server_info* m_pServer_info; ... }; void abrt_xmlrpc_conn::new_xmlrpc_client(const char* url, bool no_ssl_verify) { ... struct xmlrpc_curl_xportparms curlParms; memset(&curlParms, 0, sizeof(curlParms)); /* curlParms.network_interface = NULL; - done by memset */ curlParms.no_ssl_verifypeer = no_ssl_verify; curlParms.no_ssl_verifyhost = no_ssl_verify; curlParms.user_agent = "abrt"; struct xmlrpc_clientparms clientParms; memset(&clientParms, 0, sizeof(clientParms)); clientParms.transport = "curl"; clientParms.transportparmsP = &curlParms; clientParms.transportparm_size = XMLRPC_CXPSIZE(user_agent); xmlrpc_client_create(&env, XMLRPC_CLIENT_NO_FLAGS, PACKAGE_NAME, VERSION, &clientParms, XMLRPC_CPSIZE(transportparm_size), &m_pClient); m_pServer_info = xmlrpc_server_info_new(&env, url); ... Back to sometimes-failing xmlrpc_client_call2(&env, m_pClient, m_pServer_info, "Bug.search", param, &result) call. Here is how successful connect looks like in strace. The URL is 'https://bz-web2-test.devel.redhat.com/' and I am showing strace starting from the moment we got a reply from DNS server with IP address of this host, 10.10.36.169: recvfrom(8, "-\315\201\200\0\1\0\0\0\1\0\0\fbz-web2-test\5devel\6redhat\3com\0... close(8) = 0 socket(PF_INET, SOCK_STREAM, IPPROTO_TCP) = 8 fcntl64(8, F_GETFL) = 0x2 (flags O_RDWR) fcntl64(8, F_SETFL, O_RDWR|O_NONBLOCK) = 0 connect(8, {sa_family=AF_INET, sin_port=htons(443), sin_addr=inet_addr("10.10.36.169")}, 16) = -1 EINPROGRESS (Operation now in progress) poll([{fd=8, events=POLLOUT}], 1, 0) = 0 (Timeout) poll([{fd=8, events=POLLOUT}], 1, 0) = 0 (Timeout) pselect6(9, [], [8], [], {3, 0}, {NULL, 8}) = 1 (out [8], left {2, 870868939}) poll([{fd=8, events=POLLOUT}], 1, 0) = 1 ([{fd=8, revents=POLLOUT}]) getsockopt(8, SOL_SOCKET, SO_ERROR, [0], [4]) = 0 stat64("/etc/pki/nssdb", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0 (snip /etc/ld.so.cache mmap) (snip libnsspem.so load) munmap(0xb75d1000, 120142) = 0 socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 9 fcntl64(9, F_GETFL) = 0x2 (flags O_RDWR) fcntl64(9, F_SETFL, O_RDWR|O_NONBLOCK) = 0 getpeername(9, 0xbfb40000, [108]) = -1 ENOTCONN (Transport endpoint is not connected) fcntl64(8, F_GETFL) = 0x802 (flags O_RDWR|O_NONBLOCK) fcntl64(8, F_SETFL, O_RDWR|O_NONBLOCK) = 0 getpeername(8, {sa_family=AF_INET, sin_port=htons(443), sin_addr=inet_addr("10.10.36.169")}, [16]) = 0 close(9) = 0 getpeername(8, {sa_family=AF_INET, sin_port=htons(443), sin_addr=inet_addr("10.10.36.169")}, [16]) = 0 Up to this point, successful and failing xmlrpc_client_call2() look the same. Note that as of now, we only connected to 10.10.36.169:443, we did not send or receive a single data byte. Successful interaction then proceeds like this: socket(PF_NETLINK, SOCK_RAW, 0) = 9 bind(9, {sa_family=AF_NETLINK, pid=0, groups=00000000}, 12) = 0 getsockname(9, {sa_family=AF_NETLINK, pid=28757, groups=00000000}, [12]) sendto(9, "\24\0\0\0\26\0\1\3\30\213qK\0\0\0\0\0\0\0\0", 20, 0, {sa_fami recvmsg(9, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000000}, recvmsg(9, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000000}, recvmsg(9, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000000}, close(9) = 0 socket(PF_NETLINK, SOCK_RAW, 0) = 9 bind(9, {sa_family=AF_NETLINK, pid=0, groups=00000000}, 12) = 0 getsockname(9, {sa_family=AF_NETLINK, pid=28757, groups=00000000}, [12]) sendto(9, "\24\0\0\0\26\0\1\3\30\213qK\0\0\0\0\0\0\0\0", 20, 0, {sa_fami recvmsg(9, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000000}, recvmsg(9, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000000}, recvmsg(9, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000000}, close(9) = 0 send(8, "\26\3\1\0q\1\0\0m\3\1Kq\213\30+\t\261\313u6\374\221W\22\213\34\ recv(8, 0x8424f80, 5, 0) = -1 EAGAIN (Resource temporarily unavailable) poll([{fd=8, events=POLLIN|POLLPRI}], 1, 5000) = 1 ([{fd=8, revents=POLL recv(8, "\26\3\1\0J", 5, 0) = 5 recv(8, "\2\0\0F\3\1Kq\213\30\337-IL\1\3535\300\271\356\340\377\373\200\ recv(8, "\26\3\1\0049", 5, 0) = 5 recv(8, "\v\0\0045\0\0042\0\4/0\202\4+0\202\3\224\240\3\2\1\2\2\t\0\355\ ... whereas failing one closes the connection to 10.10.36.169:443 still without sending or receiving anything, and complains about XML-RPC error: close(8) = 0 send(7, "<27>Feb 9 17:18:56 abrtd: XML-RPC Fault: libcurl failed to execute the HTTP POST transaction. SSL connect error(-504)", 119, MSG_NOSIGNAL) = 119 This looks as a bug. Since we did not talk to server yet, it cannot possibly be related to server. I will attach larger strace output where you can look at all the gory details. The developer where we reproduced this, Karel, will add the information about versions of xmlprc-c and curl libs.
Created attachment 390000 [details] abridged strace output of successful transaction
Created attachment 390001 [details] abridged strace output of failed transaction
Attached strace_success.log and strace_failure.log. These are strace fragments strting at "Checking for duplicates..." being sent over DBUS. time, CLOCK_MONOTONIC, gettimeofday, brk calls are removed in order to declutter the log.
Created attachment 390003 [details] full strace output from program start to transaction failure and then to program termination
Created attachment 390004 [details] full strace output from program start to transaction failure and then to program termination
Created attachment 390005 [details] full strace output from program start to successful transaction and then to program termination
The only difference between successful and failing program invocation is -d "debug" option, which prevents daemonization. I hazard to guess it affects stack and malloc patterns a bit, and if this is indeed a bug and it depends on uninitialized data somewhere, -d happens to trigger it on this particular machine (Karel's one). Karel, please provide version information (Fedora version, xmlrpc-c and libcurl versions etc)
ok; I will look into it. On first glance, the -504 error smells like an HTTP error code (timeout). Can you attach 'ltrace' logs where the libcurl calls are shown? Did you tried 'valgrind'?
$ rpm -q xmlrpc-c xmlrpc-c-1.16.6-3.1582.fc12.i686 $ rpm -q libcurl libcurl-7.19.7-6.fc12.i686 $ uname -a Linux devel 2.6.31.12-174.2.3.fc12.i686.PAE #1 SMP Mon Jan 18 20:06:44 UTC 2010 i686 i686 i386 GNU/Linux
> ok; I will look into it. On first glance, the -504 error smells like an HTTP > error code (timeout). Not possible. Server did not send us anything. We did not even try to talk to server. Look at the strace. There are no read() or recv() calls on the relevant descriptor. Actually, there is a lot of rather dumb things in the strace. From strace_success_full.log.bz2 aroung the transaction in question: Example 1: fcntl64(8, F_GETFL) = 0x802 (flags O_RDWR|O_NONBLOCK) fcntl64(8, F_SETFL, O_RDWR|O_NONBLOCK) = 0 Obviously, this code sets O_NONBLOCK. It just doesn't bother to check whether it is already set, so it does a completely useless syscall. Example 2: socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 9 fcntl64(9, F_GETFL) = 0x2 (flags O_RDWR) fcntl64(9, F_SETFL, O_RDWR|O_NONBLOCK) = 0 getpeername(9, 0xbfb40000, [108]) = -1 ENOTCONN Why asking for peername if you did not even try to connect yet? And to top it off, a bit later we... just close this fd without doing anything: close(9) = 0 What is going on here? Example 3: connect(8, {sa_family=AF_INET, sin_port=htons(443), sin_addr=inet_addr("10.10.36.169")}, 16) = -1 EINPROGRESS (Operation now in progress) poll([{fd=8, events=POLLOUT}], 1, 0) = 0 (Timeout) clock_gettime(CLOCK_MONOTONIC, {106424, 916499514}) = 0 clock_gettime(CLOCK_MONOTONIC, {106424, 916557482}) = 0 clock_gettime(CLOCK_MONOTONIC, {106424, 916609374}) = 0 clock_gettime(CLOCK_MONOTONIC, {106424, 916661196}) = 0 clock_gettime(CLOCK_MONOTONIC, {106424, 916717138}) = 0 clock_gettime(CLOCK_MONOTONIC, {106424, 916769100}) = 0 poll([{fd=8, events=POLLOUT}], 1, 0) = 0 (Timeout) clock_gettime(CLOCK_MONOTONIC, {106424, 916874699}) = 0 gettimeofday({1265732376, 359938}, NULL) = 0 pselect6(9, [], [8], [], {3, 0}, {NULL, 8}) = 1 (out [8], left {2, 870868939}) clock_gettime(CLOCK_MONOTONIC, {106425, 46240496}) = 0 clock_gettime(CLOCK_MONOTONIC, {106425, 46315366}) = 0 poll([{fd=8, events=POLLOUT}], 1, 0) = 1 ([{fd=8, revents=POLLOUT}]) getsockopt(8, SOL_SOCKET, SO_ERROR, [0], [4]) = 0 clock_gettime(CLOCK_MONOTONIC, {106425, 46583345}) = 0 clock_gettime(CLOCK_MONOTONIC, {106425, 46662126}) = 0 How many more times we are going to ask for current time and poll poor fd 8 before we finally write something to it? Why not poll for 3 secs directly after connect and skip all these calls? > Can you attach 'ltrace' logs where the libcurl calls are shown? Did you tried > 'valgrind'? Will try as soon as Karel becomes available - likely tomorrow. On my machine it does not fail.
the strace snapshot of the failing connection happens probably within libnss (neither curl nor xmlrpc-c call getpeername()). I see a nss-nonblock patch for curl in rawhide (but not F12) which touches the code where the corresponding nss functions are called.
Created attachment 390251 [details] full ltrace output with the failed transaction
Created attachment 390252 [details] full ltrace output with the successful transaction
It works fine with: xmlrpc-c-1.16.6-3.1582.fc12.x86_64, but failes with: xmlrpc-c-1.16.24-1200.1840 Jirka
Created attachment 390265 [details] shorter (better isolated) ltrace output with the failed transaction
I looked at Karel's and Jiri's ltrace logs and it does not look useful. ltrace does not even show xmlrpc_client_call2 call... I think we should dig from the strace, it is the most informative clue I see for now. Please see initial description. Basically, strace shows that we open a connection, wait for 3 seconds for it to be established, and when we get confirmation that it is established (in less than 1 sec), we... close it, and declare an error. I'd hazard to guess it happens in libcurl, since it is likely xmlrpc-c itself does not open or close connections and talk HTTP over them, it delegates this to curl. OTOH, maybe xmlrpc-c misinterprets libcurl's error codes or something or feeds it with bad parameter somewhere? Hard to tell... Can we make xmlrpc-c and/or libcurl more talkative? "export LIBCURL_DEBUG=9" or something like this? Do we need to reassign this bug?
there is an XMLRPC_TRACE_CURL environment variable which sets | curl_easy_setopt(curlSessionP, CURLOPT_VERBOSE, 1l); I think (see comment 11), that the connection abort happens somewhere in libnss
Agreed. I inspected the code of xmlrpc-c yesterday and there seems to be no change between versions 1.16.6 (working on test machine) and 1.16.24 (not working on test machine) which could be influencing or causing the issue. So I guess something else (nss/curl?) must have changed as well between these two versions were released.
This bug appears to have been reported against 'rawhide' during the Fedora 13 development cycle. Changing version to '13'. More information and reason for this action is here: http://fedoraproject.org/wiki/BugZappers/HouseKeeping
(In reply to comment #17) > I think (see comment 11), that the connection abort happens somewhere in libnss Why do you think so? /usr/lib/libnsspem.so is loaded and it does some stupid things with getpeername() on unconnected socket, yes, but this happens both on successful and on failed connection attempts.
This message is a reminder that Fedora 13 is nearing its end of life. Approximately 30 (thirty) days from now Fedora will stop maintaining and issuing updates for Fedora 13. It is Fedora's policy to close all bug reports from releases that are no longer maintained. At that time this bug will be closed as WONTFIX if it remains open with a Fedora 'version' of '13'. Package Maintainer: If you wish for this bug to remain open because you plan to fix it in a currently maintained version, simply change the 'version' to a later Fedora version prior to Fedora 13's end of life. Bug Reporter: Thank you for reporting this issue and we are sorry that we may not be able to fix it before Fedora 13 is end of life. If you would still like to see this bug fixed and are able to reproduce it against a later version of Fedora please change the 'version' of this bug to the applicable version. If you are unable to change the version, please add a comment here and someone will do it for you. Although we aim to fix as many bugs as possible during every release's lifetime, sometimes those efforts are overtaken by events. Often a more recent Fedora release includes newer upstream software that fixes bugs or makes them obsolete. The process we are following is described here: http://fedoraproject.org/wiki/BugZappers/HouseKeeping
Fedora 13 changed to end-of-life (EOL) status on 2011-06-25. Fedora 13 is no longer maintained, which means that it will not receive any further security or bug fix updates. As a result we are closing this bug. If you can reproduce this bug against a currently maintained version of Fedora please feel free to reopen this bug against that version. Thank you for reporting this bug and we are sorry it could not be fixed.