[FIX] Add a timeout when trying to retrieve dcm2bids version #154

po09i · 2022-04-11T21:07:58Z

Description

This PR adresses #149.

There is a bug that causes dcm2bids to hang when your computer is connected via ethernet to another device, but that device does not provide internet. The bug occurs when fetching the version of dcm2bids or dcm2niix. To fix this, a timeout is added to prevent hanging. While investigating, I noticed the internet() function always returns True and is not necessary, so it was removed. In more details this PR:

Adds a timeout option when calling check_github_latest() to prevent hanging indefinitely
Removes the internet() function as it does nothing and is not useful
- Removes all (1) tests of the internet() function

Note:
We realized the problem does not occur for everyone, it happens when using a vpn, or at least on Cisco anyconnect.. See this #149 (comment) for more detail.

To replicate the problem scenario

Connect your computer to your router using an ethernet cable
Disconnect from the router the cable providing internet to your router
Run dcm2bids

Linked issues

Fixes #149

arnaudbore · 2022-04-13T20:00:44Z

Hi @po09i,

Thank you for your PR. I'm not able to replicate the issue on my laptop.
Everything seems to work as expected, when no access to internet internet() returns False within 3s. I will let your PR a little bit longer to see if more people have the same issue.

SamGuay

I tried the PR on my machine and when I'm offline, I get an error:
Thus, I'm suggesting we ping first, then curl.

For some reason, I couldn't suggest changes throughout the files, so it needs a bit of tidying.

INFO:dcm2bids.dcm2bids:moving acquisitions into BIDS folder
DEBUG:dcm2bids.version:Checking latest version of unfmontreal/Dcm2Bids was not possible
Traceback (most recent call last):
  File "/home/sam/Projects/Dcm2Bids/dcm2bids/version.py", line 43, in check_github_latest
    output = check_output(shlex.split("curl --silent " + url), timeout=timeout)
  File "/home/sam/miniconda3/envs/dcm2bids-dev/lib/python3.10/subprocess.py", line 420, in check_output
    return run(*popenargs, stdout=PIPE, timeout=timeout, check=True,
  File "/home/sam/miniconda3/envs/dcm2bids-dev/lib/python3.10/subprocess.py", line 524, in run
    raise CalledProcessError(retcode, process.args,
subprocess.CalledProcessError: Command '['curl', '--silent', 'https://github.com/unfmontreal/Dcm2Bids/releases/latest']' returned non-zero exit status 6.
DEBUG:dcm2bids.version:Checking latest version of rordenlab/dcm2niix was not possible
Traceback (most recent call last):
  File "/home/sam/Projects/Dcm2Bids/dcm2bids/version.py", line 43, in check_github_latest
    output = check_output(shlex.split("curl --silent " + url), timeout=timeout)
  File "/home/sam/miniconda3/envs/dcm2bids-dev/lib/python3.10/subprocess.py", line 420, in check_output
    return run(*popenargs, stdout=PIPE, timeout=timeout, check=True,
  File "/home/sam/miniconda3/envs/dcm2bids-dev/lib/python3.10/subprocess.py", line 524, in run
    raise CalledProcessError(retcode, process.args,
subprocess.CalledProcessError: Command '['curl', '--silent', 'https://github.com/rordenlab/dcm2niix/releases/latest']' returned non-zero exit status 6.

SamGuay · 2022-04-23T00:27:49Z

dcm2bids/version.py

+        output = check_output(shlex.split("curl --silent " + url), timeout=timeout)
    except:
        logger.debug(
            "Checking latest version of %s was not possible", githubRepo,


Suggested change

output = check_output(shlex.split("curl --silent " + url), timeout=timeout)

except:

logger.debug(

"Checking latest version of %s was not possible", githubRepo,

try:

if os.name == "nt":

check_call(shlex.split("ping -n 1 8.8.8.8"),

stdout=DEVNULL,

stderr=STDOUT,

timeout=timeout)

else:

check_call(shlex.split("ping -c 1 8.8.8.8"),

stdout=DEVNULL,

stderr=STDOUT,

timeout=timeout)

except:

logger.info(f"Checking latest version of {githubRepo} was not possible")

logger.debug("Can't connect to internet", exc_info=True)

return

try:

output = check_output(shlex.split("curl --silent " + url), timeout=timeout)

return (

need to import
from subprocess import check_output, PIPE, check_call, STDOUT, DEVNULL as well.

The error is the result of the following line while using the -l DEBUG option. It displayed the error but the code handled it.

logger.debug("Checking latest version of %s was not possible", githubRepo, exc_info=True)

When we remove the -l DEBUG, we don't see the error message.

I believe 'pinging' adds an extra layer and extra timeout time for no added benefit. I have opted not to add it until further feedback. However, I have split it up like you suggest to have feedback in 'normal' use cases and output the error message in debug mode:

logger.info(f"Checking latest version of {githubRepo} was not possible") logger.debug("Can't connect to internet", exc_info=True)

po09i · 2022-04-25T22:47:07Z

Here are the different outputs for different use cases (I'm only including the last lines of the output log to not clog up this already big comment):

internet

--No extra output--

No internet (info)

INFO:dcm2bids.version:Checking latest version of unfmontreal/Dcm2Bids was not possible
INFO:dcm2bids.version:Checking latest version of rordenlab/dcm2niix was not possible

No internet (debug)

INFO:dcm2bids.version:Checking latest version of unfmontreal/Dcm2Bids was not possible
DEBUG:dcm2bids.version:Error while 'curl --silent https://github.com/unfmontreal/Dcm2Bids/releases/latest'
Traceback (most recent call last):
  File "/Users/alexandredastous/Documents/School/Polytechnique/Master/project/Dcm2Bids/dcm2bids/version.py", line 43, in check_github_latest
    output = check_output(shlex.split("curl --silent " + url), timeout=timeout)
  File "/Users/alexandredastous/miniconda3/envs/dcm2bids/lib/python3.9/subprocess.py", line 424, in check_output
    return run(*popenargs, stdout=PIPE, timeout=timeout, check=True,
  File "/Users/alexandredastous/miniconda3/envs/dcm2bids/lib/python3.9/subprocess.py", line 528, in run
    raise CalledProcessError(retcode, process.args,
subprocess.CalledProcessError: Command '['curl', '--silent', 'https://github.com/unfmontreal/Dcm2Bids/releases/latest']' returned non-zero exit status 6.
INFO:dcm2bids.version:Checking latest version of rordenlab/dcm2niix was not possible
DEBUG:dcm2bids.version:Error while 'curl --silent https://github.com/rordenlab/dcm2niix/releases/latest'
Traceback (most recent call last):
  File "/Users/alexandredastous/Documents/School/Polytechnique/Master/project/Dcm2Bids/dcm2bids/version.py", line 43, in check_github_latest
    output = check_output(shlex.split("curl --silent " + url), timeout=timeout)
  File "/Users/alexandredastous/miniconda3/envs/dcm2bids/lib/python3.9/subprocess.py", line 424, in check_output
    return run(*popenargs, stdout=PIPE, timeout=timeout, check=True,
  File "/Users/alexandredastous/miniconda3/envs/dcm2bids/lib/python3.9/subprocess.py", line 528, in run
    raise CalledProcessError(retcode, process.args,
subprocess.CalledProcessError: Command '['curl', '--silent', 'https://github.com/rordenlab/dcm2niix/releases/latest']' returned non-zero exit status 6.

No internet but on local network (info) -- It took 6 more seconds due to the timeouts

INFO:dcm2bids.version:Checking latest version of unfmontreal/Dcm2Bids was not possible
INFO:dcm2bids.version:Checking latest version of rordenlab/dcm2niix was not possible

No internet but on local network (debug) -- [Outdated!]

DEBUG:dcm2bids.version:Error while 'curl --silent https://github.com/unfmontreal/Dcm2Bids/releases/latest'
Traceback (most recent call last):
  File "/Users/alexandredastous/Documents/School/Polytechnique/Master/project/Dcm2Bids/dcm2bids/version.py", line 43, in check_github_latest
    output = check_output(shlex.split("curl --silent " + url), timeout=timeout)
  File "/Users/alexandredastous/miniconda3/envs/dcm2bids/lib/python3.9/subprocess.py", line 424, in check_output
    return run(*popenargs, stdout=PIPE, timeout=timeout, check=True,
  File "/Users/alexandredastous/miniconda3/envs/dcm2bids/lib/python3.9/subprocess.py", line 507, in run
    stdout, stderr = process.communicate(input, timeout=timeout)
  File "/Users/alexandredastous/miniconda3/envs/dcm2bids/lib/python3.9/subprocess.py", line 1134, in communicate
    stdout, stderr = self._communicate(input, endtime, timeout)
  File "/Users/alexandredastous/miniconda3/envs/dcm2bids/lib/python3.9/subprocess.py", line 1980, in _communicate
    self._check_timeout(endtime, orig_timeout, stdout, stderr)
  File "/Users/alexandredastous/miniconda3/envs/dcm2bids/lib/python3.9/subprocess.py", line 1178, in _check_timeout
    raise TimeoutExpired(
subprocess.TimeoutExpired: Command '['curl', '--silent', 'https://github.com/unfmontreal/Dcm2Bids/releases/latest']' timed out after 3 seconds
INFO:dcm2bids.version:Checking latest version of rordenlab/dcm2niix was not possible
DEBUG:dcm2bids.version:Error while 'curl --silent https://github.com/rordenlab/dcm2niix/releases/latest'
Traceback (most recent call last):
  File "/Users/alexandredastous/Documents/School/Polytechnique/Master/project/Dcm2Bids/dcm2bids/version.py", line 43, in check_github_latest
    output = check_output(shlex.split("curl --silent " + url), timeout=timeout)
  File "/Users/alexandredastous/miniconda3/envs/dcm2bids/lib/python3.9/subprocess.py", line 424, in check_output
    return run(*popenargs, stdout=PIPE, timeout=timeout, check=True,
  File "/Users/alexandredastous/miniconda3/envs/dcm2bids/lib/python3.9/subprocess.py", line 507, in run
    stdout, stderr = process.communicate(input, timeout=timeout)
  File "/Users/alexandredastous/miniconda3/envs/dcm2bids/lib/python3.9/subprocess.py", line 1134, in communicate
    stdout, stderr = self._communicate(input, endtime, timeout)
  File "/Users/alexandredastous/miniconda3/envs/dcm2bids/lib/python3.9/subprocess.py", line 1980, in _communicate
    self._check_timeout(endtime, orig_timeout, stdout, stderr)
  File "/Users/alexandredastous/miniconda3/envs/dcm2bids/lib/python3.9/subprocess.py", line 1178, in _check_timeout
    raise TimeoutExpired(
subprocess.TimeoutExpired: Command '['curl', '--silent', 'https://github.com/rordenlab/dcm2niix/releases/latest']' timed out after 3 seconds

Note: The error messages are there for debug purposes, they are not an actual error.

SamGuay · 2022-04-28T20:32:03Z

I agree that adding the ping adds another layer.. However not all scenarios raise subprocess.TimeoutExpired: however in one situation, it raises subprocess.CalledProcessError which is the scenario I encountered when testing that led me to add the ping. It works as supposed given there is a bare except at the end but I think it should be for TimeoutExpired..

I don't have strong feeling about it though so I will let @arnaudbore decide 😁

po09i · 2022-04-28T21:01:00Z

@SamGuay

It works as supposed given there is a bare except at the end but I think it should be for TimeoutExpired..

Good point about the empty except clause, I can add both exceptions in the except clause so that we follow proper guidelines.

po09i · 2022-04-28T21:38:00Z

Since I could separated the exceptions, I wrote a different error message for the timeout. Since the timeout is self explanatory, I removed the output of the error message. Here is the updated output following the comments:

No internet but on local network (debug)

Refer to this comment for all other outputs

codecov-commenter · 2022-05-26T16:00:54Z

Codecov Report

❗ No coverage uploaded for pull request base (master@abd6994). Click here to learn what that means.
The diff coverage is n/a.

@@            Coverage Diff            @@
##             master     #154   +/-   ##
=========================================
  Coverage          ?   68.00%           
=========================================
  Files             ?       10           
  Lines             ?      675           
  Branches          ?      108           
=========================================
  Hits              ?      459           
  Misses            ?      185           
  Partials          ?       31

Flag	Coverage Δ
pytest	`68.00% <0.00%> (?)`

Flags with carried forward coverage won't be shown. Click here to find out more.

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update abd6994...e4ad28b. Read the comment docs.

po09i added 2 commits April 11, 2022 16:47

Remove internet() function and add timeout in check_github_latest()

08bc4b1

Remove testing of the internet() function

a82a836

SamGuay mentioned this pull request Apr 15, 2022

dcm2bids hangs when connected via ethernet without internet #149

Closed

SamGuay reviewed Apr 23, 2022

View reviewed changes

Split logging into info and debug

d285794

Add exception names in the except clause

3fa7f4b

po09i added 5 commits May 26, 2022 14:36

Merge branch 'master' into ad/internet

710529b

Remove unused import

9060400

Check versions after initializing the logger

6e7cf4a

Add ability for curl to follow redirect links

357c401

Restrict version to 5 charaters

e4ad28b

arnaudbore merged commit 957dba5 into UNFmontreal:master May 30, 2022

po09i deleted the ad/internet branch January 12, 2023 16:57

po09i mentioned this pull request Jul 10, 2023

Add mp2rage, and more field maps to dcm2bids config file and update to version >= 2.1.7 shimming-toolbox/shimming-toolbox#466

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[FIX] Add a timeout when trying to retrieve dcm2bids version #154

[FIX] Add a timeout when trying to retrieve dcm2bids version #154

po09i commented Apr 11, 2022 •

edited

Loading

arnaudbore commented Apr 13, 2022

SamGuay left a comment

SamGuay Apr 23, 2022

SamGuay Apr 23, 2022

po09i Apr 25, 2022

po09i commented Apr 25, 2022 •

edited

Loading

SamGuay commented Apr 28, 2022

po09i commented Apr 28, 2022 •

edited

Loading

po09i commented Apr 28, 2022 •

edited

Loading

codecov-commenter commented May 26, 2022 •

edited

Loading

-        output = check_output(shlex.split("curl --silent " + url), timeout=timeout)
-    except:
-        logger.debug(
-            "Checking latest version of %s was not possible", githubRepo,
+    try:
+        if os.name == "nt":
+            check_call(shlex.split("ping -n 1 8.8.8.8"),
+                        stdout=DEVNULL,
+                        stderr=STDOUT,
+                        timeout=timeout)
+        else:
+            check_call(shlex.split("ping -c 1 8.8.8.8"),
+                        stdout=DEVNULL,
+                        stderr=STDOUT,
+                        timeout=timeout)
+    except:
+        logger.info(f"Checking latest version of {githubRepo} was not possible")
+        logger.debug("Can't connect to internet", exc_info=True)
+        return
+   try:
+        output = check_output(shlex.split("curl --silent " + url), timeout=timeout)
+        return (

[FIX] Add a timeout when trying to retrieve dcm2bids version #154

[FIX] Add a timeout when trying to retrieve dcm2bids version #154

Conversation

po09i commented Apr 11, 2022 • edited Loading

Description

To replicate the problem scenario

Linked issues

arnaudbore commented Apr 13, 2022

SamGuay left a comment

Choose a reason for hiding this comment

SamGuay Apr 23, 2022

Choose a reason for hiding this comment

SamGuay Apr 23, 2022

Choose a reason for hiding this comment

po09i Apr 25, 2022

Choose a reason for hiding this comment

po09i commented Apr 25, 2022 • edited Loading

SamGuay commented Apr 28, 2022

po09i commented Apr 28, 2022 • edited Loading

po09i commented Apr 28, 2022 • edited Loading

codecov-commenter commented May 26, 2022 • edited Loading

Codecov Report

po09i commented Apr 11, 2022 •

edited

Loading

po09i commented Apr 25, 2022 •

edited

Loading

po09i commented Apr 28, 2022 •

edited

Loading

po09i commented Apr 28, 2022 •

edited

Loading

codecov-commenter commented May 26, 2022 •

edited

Loading