git clone http:// fails some times with "Request for d53.. aborted"

even when (v 2.7.0) ran on the box where the server is, so unlikely to be network issue

or from my laptop (v 2.9.3) with ok but wifi with a weakish signal to the access point:

$> ( set -e; for s in {1..100}; do rm -rf fbirn_phaseIII ; git clone http://datasets.datalad.org/nidm/fbirn_phaseIII/.git; done; ) Cloning into 'fbirn_phaseIII'...
Checking connectivity... done.
Cloning into 'fbirn_phaseIII'...
error: Request for d53302dfc7ad13b786923927021039d21a10d5bd aborted
error: Unable to find d53302dfc7ad13b786923927021039d21a10d5bd under http://datasets.datalad.org/nidm/fbirn_phaseIII/.git
Cannot obtain needed tree d53302dfc7ad13b786923927021039d21a10d5bd
while processing commit 22dd4c49417cad6f4082ac2aebef45da8b6e473d.
error: fetch failed.

even if I build fresh 2.10.0, discovered that we can trace now CURL calls

$> export PATH=$HOME/proj/misc/git:$PATH
$> git version
git version 2.10.0
$> ( set -e; for s in {1..100}; do rm -rf fbirn_phaseIII ; GIT_TRACE_CURL=/tmp/git-trace-curl-failed.log git clone http://datasets.datalad.org/nidm/fbirn_phaseIII/.git && mv /tmp/git-trace-curl-failed.log /tmp/git-trace-curl-good.log || exit 1; done; ) Cloning into 'fbirn_phaseIII'...
warning: templates not found /home/yoh/share/git-core/templates
... a few more ...
Cloning into 'fbirn_phaseIII'...
warning: templates not found /home/yoh/share/git-core/templates
error: Request for d53302dfc7ad13b786923927021039d21a10d5bd aborted
error: Unable to find d53302dfc7ad13b786923927021039d21a10d5bd under http://datasets.datalad.org/nidm/fbirn_phaseIII/.git
Cannot obtain needed tree d53302dfc7ad13b786923927021039d21a10d5bd
while processing commit 22dd4c49417cad6f4082ac2aebef45da8b6e473d.
error: fetch failed.
( set -e; for s in {1..100}; do; rm -rf fbirn_phaseIII; GIT_TRACE_CURL= git ) 18.70s user 8.01s system 34% cpu 1:16.84 total

NB
- note that it is d53302dfc7ad13b786923927021039d21a10d5bd all the time!
- that one corresponds to a tree
$> git show d53302dfc7ad13b786923927021039d21a10d5bd
tree d53302dfc7ad13b786923927021039d21a10d5bd

1ec/
da9/
- I do not see that object being reported as failed to be found on the server:

$> grep d5/3302dfc7ad13b786923927021039d21a10d5bd /var/log/apache2/datasets.datalad.org-error.log
$> grep d5/3302dfc7ad13b786923927021039d21a10d5bd /var/log/apache2/datasets.datalad.org-access.log
129.170.31.34 - - [09/Sep/2016:14:14:25 -0400] "GET /nidm/fbirn_phaseIII/.git/objects/d5/3302dfc7ad13b786923927021039d21a10d5bd HTTP/1.1" 200 72
...
- and the logs say that only "good" run had it requested:

$> zgrep 3302dfc7ad13b786923927021039d21a10d5bd git-trace-curl-*.log.gz
git-trace-curl-good.log.gz:18:09:13.749268 http.c:517 => Send header: GET /nidm/fbirn_phaseIII/.git/objects/d5/3302dfc7ad13b786923927021039d21a10d5bd HTTP/1.1

and here are those two GIT_TRACE_CURL traces from good and bad runs -- may be someone with a better clue could figure it out or any other information I should provide to help pin point why that "request for d5... aborted" ;)

http://www.onerussian.com/tmp/git-trace-curl-good.log.gz
http://www.onerussian.com/tmp/git-trace-curl-failed.log.gz

Thanks in advance and please CC me in replies

Yaroslav O. Halchenko
Center for Open Neuroscience     http://centerforopenneuroscience.org
Dartmouth College, 419 Moore Hall, Hinman Box 6207, Hanover, NH 03755
Phone: +1 (603) 646-9834                       Fax: +1 (603) 646-1419
WWW:   http://www.linkedin.com/in/yarik        

(Not sure how much time I'll have to continue in the next few weeks,
just jotting down my debugging progress so far...)

Also, GIT_CURL_VERBOSE=1 is useful, too

And GIT_HTTP_MAX_REQUESTS=1 (default 5) can be used to limit concurrency if there's a suspected concurrency bug.

Initially, I was worried some of my 2.10.0 http-walker speedups were responsible, but it does not seem to be the case since it happens on old versions, too...

I'm trying with the following to track state==ABORTED requests:

index 0b24255..4f25b07 100644
@@ -56,6 +56,7 @@ static void start_object_request(struct walker *walker,
 
 	req = new_http_object_request(obj_req->repo->base, obj_req->sha1);
 	if (req == NULL) {
+		warning("obj aborted at %d", __LINE__);
 		obj_req->state = ABORTED;
 		return;
 	}

index cd40b01..cac5db9 100644
@@ -1022,6 +1022,8 @@ int start_active_slot(struct active_request_slot *slot)
 
 	if (curlm_result != CURLM_OK &&
 	    curlm_result != CURLM_CALL_MULTI_PERFORM) {
+		warning("curl_multi_add_handle failed: %s",
+			curl_multi_strerror(curlm_result));
 		active_requests--;
 		slot->in_use = 0;
 		return 0;

And getting a few of the following:

warning: curl_multi_add_handle failed: The easy handle is already added to a multi handle

(error code: CURLM_ADDED_ALREADY)

I suspect there is some state management bug. And yes, it's
intermittent, I'm testing from my server (dcvr.yhbt.net) with good connectivity and it does not happen all the time.

It also happens regardless of GIT_HTTP_MAX_REQUESTS being 1 or 5 (default), too.

So yeah, hopefully this info is helpful to someone else on the list in case I don't return soon.

(I have some hours online today, so I decided to work on this)

The key patch here is 3/3 which seems like an obvious fix to adding the problem of adding a curl easy handle to a curl multi handle repeatedly.

What is unclear to me is how only Yaroslav's repository seems to trigger this bug after all these years...

However, I am fairly sure this fixes the bug Yaroslav encountered. This patch series is also needed for 2.9.3 and perhaps older maintenance tracks for distros.

In PATCH 2/3, I originally had error checking, but removed it after noticing it was causing failures on wheezy.

I will investigate those failures in a week or two when I regain regular computer access.

These patches are needed for 2.9.x (and probably earlier), too.

The following changes since commit cda1bbd474805e653dda8a71d4ea3790e2a66cbb:

Sync with maint (2016-09-08 22:00:53 -0700)

are available in the git repository at:

git://bogomips.org/git-svn.git dumb-http-release

for you to fetch changes up to 3f561d0f0f78fd841708b5e81122e9d825919fd3:

http: always remove curl easy from curlm session on release (2016-09-12 23:59:35 +0000)

----------------------------------------------------------------
Eric Wong (3):
http: warn on curl_multi_add_handle failures
http: consolidate #ifdefs for curl_multi_remove_handle
http: always remove curl easy from curlm session on release

 http.c | 29 ++++++++++++++++++-----------
 1 file changed, 18 insertions(+), 11 deletions(-)

EW

This will be useful for tracking down curl usage errors.

---
 http.c | 2 ++
 1 file changed, 2 insertions(+)

index cd40b01..cac5db9 100644
@@ -1022,6 +1022,8 @@ int start_active_slot(struct active_request_slot *slot)
 
 	if (curlm_result != CURLM_OK &&
 	    curlm_result != CURLM_CALL_MULTI_PERFORM) {
+		warning("curl_multi_add_handle failed: %s",
+			curl_multi_strerror(curlm_result));
 		active_requests--;
 		slot->in_use = 0;
 		return 0;

EW

I find #ifdefs makes code difficult-to-follow.

An early version of this patch had error checking for curl_multi_remove_handle calls, but caused some tests (e.g. t5541) to fail under curl 7.26.0 on old Debian wheezy.

---
 http.c | 17 ++++++++++-------
 1 file changed, 10 insertions(+), 7 deletions(-)

index cac5db9..a7eaf7b 100644
@@ -201,6 +201,13 @@ static void finish_active_slot(struct active_request_slot *slot)
 		slot->callback_func(slot->callback_data);
 }
 
+static void xmulti_remove_handle(struct active_request_slot *slot)
+{
+#ifdef USE_CURL_MULTI
+	curl_multi_remove_handle(curlm, slot->curl);
+#endif
+}
+
 #ifdef USE_CURL_MULTI
 static void process_curl_messages(void)
 {

@@ -216,7 +223,7 @@ static void process_curl_messages(void)
 			       slot->curl != curl_message->easy_handle)
 				slot = slot->next;
 			if (slot != NULL) {
-				curl_multi_remove_handle(curlm, slot->curl);
+				xmulti_remove_handle(slot);
 				slot->curl_result = curl_result;
 				finish_active_slot(slot);
 			} else {

@@ -881,9 +888,7 @@ void http_cleanup(void)
 	while (slot != NULL) {
 		struct active_request_slot *next = slot->next;
 		if (slot->curl != NULL) {
-#ifdef USE_CURL_MULTI
-			curl_multi_remove_handle(curlm, slot->curl);
-#endif
+			xmulti_remove_handle(slot);
 			curl_easy_cleanup(slot->curl);
 		}
 		free(slot);

@@ -1164,9 +1169,7 @@ static void release_active_slot(struct active_request_slot *slot)
 {
 	closedown_active_slot(slot);
 	if (slot->curl && curl_session_count > min_curl_sessions) {
-#ifdef USE_CURL_MULTI
-		curl_multi_remove_handle(curlm, slot->curl);
-#endif
+		xmulti_remove_handle(slot);
 		curl_easy_cleanup(slot->curl);
 		slot->curl = NULL;
 		curl_session_count--;

EW

We must call curl_multi_remove_handle when releasing the slot to prevent subsequent calls to curl_multi_add_handle from failing with CURLM_ADDED_ALREADY (in curl 7.32.1+; older versions returned CURLM_BAD_EASY_HANDLE)

---
 http.c | 10 ++++++----
 1 file changed, 6 insertions(+), 4 deletions(-)

index a7eaf7b..3c4c3f5 100644
@@ -1168,11 +1168,13 @@ void run_active_slot(struct active_request_slot *slot)
 static void release_active_slot(struct active_request_slot *slot)
 {
 	closedown_active_slot(slot);
-	if (slot->curl && curl_session_count > min_curl_sessions) {
+	if (slot->curl) {
 		xmulti_remove_handle(slot);
-		curl_easy_cleanup(slot->curl);
-		slot->curl = NULL;
-		curl_session_count--;
+		if (curl_session_count > min_curl_sessions) {
+			curl_easy_cleanup(slot->curl);
+			slot->curl = NULL;
+			curl_session_count--;
+		}
 	}
 #ifdef USE_CURL_MULTI
 	fill_active_slots();

EW

Yeah, sounds like the right thing to do and 2/3 makes it really easy to read the resulting code.

Thanks. Will tentatively queue on 'pu' and wait for updates.

I'm comfortable with the original 3 patch series in 'next' and being merged to 'master' and 'maint', soon.

I don't think the following 4/3 is strictly necessary now, so I'd be more comfortable with it being tested in 'pu' or 'next' for a longer period.

(online today, but not much tomorrow or another few days after)

-----------8<-----------
Subject: [PATCH] http: check curl_multi_remove_handle error code

This should help detect bugs in future changes. While we're at it, fix a (probably innocuous) bug in our http_cleanup function for users of older curl.

curl_multi_remove_handle was not idempotent until curl 7.33.0 with commit 84f3b3dd448399f9548468676e1bd1475dba8de5 ("curl_multi_remove_handle: allow multiple removes"), so we track the "curlm" membership of the curl easy handle ourselves with a new "in_multi" flag.

Tested with curl 7.26.0 and 7.38.0 on Debian 7.x (wheezy) and Debian 8.x (jessie) respectively.

---
 http.c | 12 ++++++++++--
 http.h |  1 +
 2 files changed, 11 insertions(+), 2 deletions(-)

index 82ed542..9f97749 100644
@@ -204,7 +204,12 @@ static void finish_active_slot(struct active_request_slot *slot)
 static void xmulti_remove_handle(struct active_request_slot *slot)
 {
 #ifdef USE_CURL_MULTI
-	curl_multi_remove_handle(curlm, slot->curl);
+	CURLMcode code = curl_multi_remove_handle(curlm, slot->curl);
+
+	if (code != CURLM_OK)
+		die("curl_multi_remove_handle failed (%p): %s",
+			slot->curl, curl_multi_strerror(code));
+	slot->in_multi = 0;
 #endif
 }
 

@@ -888,7 +893,8 @@ void http_cleanup(void)
 	while (slot != NULL) {
 		struct active_request_slot *next = slot->next;
 		if (slot->curl != NULL) {
-			xmulti_remove_handle(slot);
+			if (slot->in_multi)
+				xmulti_remove_handle(slot);
 			curl_easy_cleanup(slot->curl);
 		}
 		free(slot);

@@ -965,6 +971,7 @@ struct active_request_slot *get_active_slot(void)
 		newslot = xmalloc(sizeof(*newslot));
 		newslot->curl = NULL;
 		newslot->in_use = 0;
+		newslot->in_multi = 0;
 		newslot->next = NULL;
 
 		slot = active_queue_head;

@@ -1033,6 +1040,7 @@ int start_active_slot(struct active_request_slot *slot)
 		slot->in_use = 0;
 		return 0;
 	}
+	slot->in_multi = 1;
 
 	/*
 	 * We know there must be something to do, since we just added

index 5ab9d9c..3339d70 100644
@@ -60,6 +60,7 @@ struct slot_results {
 struct active_request_slot {
 	CURL *curl;
 	int in_use;
+	int in_multi;
 	CURLcode curl_result;
 	long http_code;
 	int *finished;

EW

Does curl provide a meaningful error here? I'm just wondering if we could simply let curl handle this, and just ignore the error that comes from older versions. We're basically just replicating curl's own state data here.

-Peff

curl before 7.33.0 returned CURLM_BAD_EASY_HANDLE. This error code also happens if we pass a bad/corrupt easy handle; so it could be hiding an error on our end.

Hmm, yeah. So we would want to make it conditional on the version anyway, so that we detected such bugs on more modern systems. That still doesn't seem unreasonable to me, but your patch is also not very big, so it's probably fine (the major risk with yours is simply that our state and curl's state get out of sync).

-Peff

Thank you Eric very much for tracking down this issue! Since issue is intermittent, I guess people just didn't bother going through reporting if they got an error once in a while, and/or could have attributed to somehow misran update-server-info.

FWIW I have tested your branch locally - and do not observe that bug any longer. Thanks again!

Yaroslav O. Halchenko
Center for Open Neuroscience     http://centerforopenneuroscience.org
Dartmouth College, 419 Moore Hall, Hinman Box 6207, Hanover, NH 03755
Phone: +1 (603) 646-9834                       Fax: +1 (603) 646-1419
WWW:   http://www.linkedin.com/in/yarik        

I have spent some time chasing the wild goose (well - the .gitignore file) after getting:

$> git-submodule add --name fcx-1 ./fcx-1/ ./fcx-1/ The following path is ignored by one of your .gitignore files:
fcx-1
Use -f if you really want to add it.

long story short -- the culprit is this piece of code in git-submodule:

if test -z "$force" && ! git add --dry-run --ignore-missing "$sm_path" > /dev/null 2>&1 then
eval_gettextln "The following path is ignored by one of your .gitignore files:
\$sm_path
Use -f if you really want to add it." >&2
exit 1
fi

so if anything goes wrong in git add, it just reports this error message.

FTR -- actual problem in my case was:

$> git add --dry-run --ignore-missing fcx-1
fatal: Unable to create '/mnt/datasets/datalad/crawl/crcns/.git/index.lock': File exists.

Another git process seems to be running in this repository, e.g. an editor opened by 'git commit'. Please make sure all processes are terminated then try again. If it still fails, a git process may have crashed in this repository earlier:
remove the file manually to continue.

;-)

Cheers!
P.S. Please CC me in replies

Yaroslav O. Halchenko
Center for Open Neuroscience     http://centerforopenneuroscience.org
Dartmouth College, 419 Moore Hall, Hinman Box 6207, Hanover, NH 03755
Phone: +1 (603) 646-9834                       Fax: +1 (603) 646-1419
WWW:   http://www.linkedin.com/in/yarik        

Thanks for the bug report!
I think we could chop off "2>&1" as that would have exposed the underlying error.

Another way to go would be to use verbose git-add and grep for the string "add '$sm_path'".

     if test -z "$force" && ! git add --verbose --dry-run

--ignore-missing "$sm_path" |grep "add $sm_path"

git-add already gives the correct (the same error message) for the ignored files, so maybe we'd just do:

    # no need for a if, but this single line will do:
    test -z "$force" && git add --dry-run git.o >/dev/null || exit 1

On September 14, 2016 3:32:11 PM EDT, Stefan Beller <[email protected]> wrote:
!

FWIW Imho exposing error is good but not sufficient alone, since custom gitignore message would still be confusing.

Sent from a phone which beats iPhone.