Repository: RPGillespie6/fastcov (language: python)

Issue:
fastcov stuck after json.decoder.JSONDecodeError exception
Hi,

Great program. Keep up the good work. We've added it to our nightly and last night it got stuck with this call stack:

11:52:27 [13.835s] [info]: Found 3034 coverage files (gcda)
11:52:27 [0.261s] [info]: Spawned 6 gcov processes, each processing at most 506 coverage files
12:05:55 Process Process-2:
12:05:55 Traceback (most recent call last):
12:05:55   File "/usr/lib64/python3.6/multiprocessing/process.py", line 258, in _bootstrap
12:05:55     self.run()
12:05:55   File "/usr/lib64/python3.6/multiprocessing/process.py", line 93, in run
12:05:55     self._target(*self._args, **self._kwargs)
12:05:55   File "/usr/local/lib/python3.6/site-packages/fastcov.py", line 135, in gcovWorker
12:05:55     intermediate_json = json.loads(line.decode(sys.stdout.encoding))
12:05:55   File "/usr/lib64/python3.6/json/__init__.py", line 354, in loads
12:05:55     return _default_decoder.decode(s)
12:05:55   File "/usr/lib64/python3.6/json/decoder.py", line 339, in decode
12:05:55     obj, end = self.raw_decode(s, idx=_w(s, 0).end())
12:05:55   File "/usr/lib64/python3.6/json/decoder.py", line 355, in raw_decode
12:05:55     obj, end = self.scan_once(s, idx)
12:05:55 json.decoder.JSONDecodeError: Expecting property name enclosed in double quotes: line 1 column 69632 (char 69631)

I had to kill it manually to unstuck the nightly build. We are using gcc 9.2. Thanks.


Discussion / hints:
What version of fastcov are you using?

Based on the stack trace you provided it looks like python's json parser is choking on what gcc gave it. 

Is this reproducible? If this is reproducible what would really help is if we can get our hands on the JSON that fastcov is choking on. One way we can do that is by modifying fastcov:262 to be:

```
try:
    encoding = sys.stdout.encoding if sys.stdout.encoding else 'UTF-8'
    intermediate_json = json.loads(line.decode(encoding))
except json.decoder.JSONDecodeError as e:
    with open("/tmp/bad_json.txt", "w") as f:
        f.write(encoding)
        f.write(line)
    exit(1)
```

And then after it chokes getting `/tmp/bad_json.txt`

I can enhance fastcov to skip json that it can't parse, but it will probably cause loss of coverage in the final report because if a particular gcc json can't be parsed, the entire file has to be skipped, so I'd like to figure out the root cause first.

We are using fastcov 1.17 and the last nightly passed without problems so, unfortunately, it seems to be a one-time event.

We've used it for like a month or so without issues. If it happens again I'll come back to you.

For our case, skipping the problematic json with some warning message will work fine because otherwise it just gets stuck ;) and we do that every night.

btw with fastcov our coverage report is generated in 25 minutes as opposed to 6+ hours - good job 👍  


Thanks for the kind words!

I will put a try/except on the json parsing and print out an error/return non-zero rc if bad json is encountered. 
Looking back into this issue a bit. Have you confirmed for certain fastcov *doesn't* hang if there is a try/except to catch JSON decode errors in gcov workers? If so... seems like a bug in python itself, since unhandled exceptions are a valid way of bubbling out of a multiprocessing process.
Hello!

We have similar issue (occurs randomly at 1/10 of cases):

```
Resetting code coverage counters to zero.
Processing code coverage counters and generating report.
/usr/local/bin/fastcov --zerocounters
[0.158s] [info]: Found 344 coverage files (gcda)
[0.055s] [info]: Removed 344 .gcda files
/usr/local/bin/fastcov --jobs 8 --exclude /usr/include /root/.conan test/ --process-gcno --lcov --output build/coverage.info.base
[0.082s] [info]: Found 502 coverage files (gcno)
[0.026s] [info]: Spawned 8 gcov processes, each processing at most 63 coverage files
Process Process-5:
Traceback (most recent call last):
  File "/usr/lib64/python3.6/multiprocessing/process.py", line 258, in _bootstrap
    self.run()
  File "/usr/lib64/python3.6/multiprocessing/process.py", line 93, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/local/lib/python3.6/site-packages/fastcov.py", line 262, in gcovWorker
    intermediate_json = json.loads(line.decode(sys.stdout.encoding if sys.stdout.encoding else 'UTF-8'))
  File "/usr/lib64/python3.6/json/__init__.py", line 354, in loads
    return _default_decoder.decode(s)
  File "/usr/lib64/python3.6/json/decoder.py", line 339, in decode
    obj, end = self.raw_decode(s, idx=_w(s, 0).end())
  File "/usr/lib64/python3.6/json/decoder.py", line 355, in raw_decode
    obj, end = self.scan_once(s, idx)
json.decoder.JSONDecodeError: Unterminated string starting at: line 1 column 138846189 (char 138846188)
make[3]: *** [test/CMakeFiles/test_coverage.dir/build.make:83: test/CMakeFiles/test_coverage] Hangup
make[2]: *** [CMakeFiles/Makefile2:5510: test/CMakeFiles/test_coverage.dir/all] Hangup
make[1]: *** [CMakeFiles/Makefile2:5517: test/CMakeFiles/test_coverage.dir/rule] Hangup
make: *** [Makefile:2505: test_coverage] Hangup
```

Centos8
gcc version 9.2.1 20191120 (Red Hat 9.2.1-2)
gcov (GCC) 9.2.1 20191120 (Red Hat 9.2.1-2)
fastcov 1.8


The issue started reproducing when we started added more files for coverage.
The issue didn't occur when we had little amount of source files.

I see fastcov reads line by line and JSON-decodes each line separately.
Maybe gcc/gcov just sometimes prints out multi-line JSON documents?
Obviously JSON parser will chock on decoding incomplete JSON documents in this case. 

> Can it be the case that gcc/gcov didn't flush all JSON data to a file while fastcov started reading them?

No, fastcov passes a flag to gcov to tell it to output JSON to `stdout` not, a file. (see `--stdout` on this page: https://gcc.gnu.org/onlinedocs/gcc/Invoking-Gcov.html#Invoking-Gcov). Fastcov parses the JSON directly from gcov's stdout.

To me seems like it's one of these possibilities:
- gcov instance is getting killed somehow (possibly due to out of memory?), which truncates its stdout resulting in invalid json
- gcov is crashing (unlikely, but possible I suppose)
- gcov isn't outputting super large jsons to stdout correctly (i.e. it is breaking with a newline?)

This line:
```
json.decoder.JSONDecodeError: Unterminated string starting at: line 1 column 138846189 (char 138846188)
```

Seems to indicate a JSON data is _at least_ 138 MB big, which is pretty big for JSON. You must have some massive source files for gcov to generate a JSON that big. If there are many large JSONs like this happening in parallel, I wonder how much memory is being used by all of the python/gcov instances combined.

A few other questions:
- Does fastcov hang for a long time when this issue occurs?
- Does reducing the number of cores (and therefore memory usage) affect stability?
Hi, 

sorry for the late response I got carried away. 

We've patched fastcov.py like this: 

```
def gcovWorker(data_q, metrics_q, args, chunk, gcov_filter_options):
    base_report   = {"sources": {}}
    gcovs_total   = 0
    gcovs_skipped = 0
    gcov_args = "-it"
    if args.branchcoverage or args.xbranchcoverage:
        gcov_args += "b"
    p = subprocess.Popen([args.gcov, gcov_args] + chunk, cwd=args.cdirectory, stdout=subprocess.PIPE, stderr=subprocess.DEVNULL)
    for line in iter(p.stdout.readline, b''):
        file_name = line.decode(sys.stdout.encoding)
        try:
            intermediate_json = json.loads(file_name)
        except:
            logging.info("Error reading coverage file: {} ".format(file_name))
            continue
```

and this seems to solve our problem.

As we discussed on email we abruptly kill both our main process and the testing processes which all generate coverage data. So I guess just ignoring the corrupt jsons solves the problem.
@DVMirchev - and you can confirm the try/except fixes the long hang you were seeing (and not just fastcov crash)? Need to find out if @pcapdump's issue is due to same reason, or different reason. Would also like to figure out why letting exception float out hangs, but catching it doesn't...
I was able to reproduce the "hang" part of this issue - it turns out it's because the main fastcov process is blocking trying to pull from a queue, and the worker process exits (via exception) before putting anything into the queue, and so the main process is blocked forever trying to pull something out of a multiprocessing queue:

```python
for p in processes:
    fastcov_jsons.append(data_q.get())
    incrementCounters(*metrics_q.get())
```

So indeed, this is a legitimate issue with fastcov. I didn't mean to auto-close - I pushed a commit to master that should resolve the issue though (which is why it was closed momentarily). I need to add some test cases for this, but otherwise, the latest version on master should not hang on bad JSONs anymore.

Fix patch:
diff --git a/.travis.yml b/.travis.yml
index 4284ad0..d520515 100644
--- a/.travis.yml
+++ b/.travis.yml
@@ -20,7 +20,7 @@ script:
   - docker run -v "$TRAVIS_BUILD_DIR":/mnt/workspace -w /mnt/workspace rpgillespie6/fastcov bash -c "cd ./test && ./run_tests.sh"
 
 after_success:
-  - bash <(curl -s https://codecov.io/bash) -X gcov -X coveragepy -s $TRAVIS_BUILD_DIR # Upload coverage to codecov
+  - bash <(curl -s https://codecov.io/bash) -X coveragepy -s $TRAVIS_BUILD_DIR # Upload coverage to codecov
 
 deploy:
   provider: pypi


Test patch:
diff --git a/test/functional/bad-gcov.sh b/test/functional/bad-gcov.sh
new file mode 100755
index 0000000..e89100e
--- /dev/null
+++ b/test/functional/bad-gcov.sh
@@ -0,0 +1,7 @@
+#!/bin/bash
+
+if [ "$1" == "-v" ]; then
+  echo "gcov (Ubuntu 9.3.0-17ubuntu1~20.04) 9.3.0"
+fi
+
+echo "{bad json" # Pretend gcov crashed or was killed
\ No newline at end of file
diff --git a/test/functional/run_all.sh b/test/functional/run_all.sh
index 3d60493..d0ed005 100755
--- a/test/functional/run_all.sh
+++ b/test/functional/run_all.sh
@@ -165,6 +165,11 @@ rc=0
 coverage run -a ${TEST_DIR}/fastcov.py -C ${TEST_DIR}/expected_results/missing_files.json --scan-exclusion-markers -o missing.json || rc=$?
 test $rc -eq 6
 
+# Test gcov getting killed or crashing midway through JSON output
+rc=0
+coverage run -a ${TEST_DIR}/fastcov.py --exceptional-branch-coverage --gcov ${TEST_DIR}/bad-gcov.sh --source-files ../src/source1.cpp --lcov -o multitest.actual.info || rc=$?
+test $rc -eq 7
+
 # Test (running data from other than build directory)
 RUN_DIR=${PWD}
 pushd ${TEST_DIR}