2024-10-15T01:20:15.177Z | <Matt> Thanks for your reply,
There is no difference that we are aware of - the initial read when output to stdout appears complete & valid (based on a copy into a text editor - there are no json syntax errors), however when read into the json parser directly it finds syntax errors. I will discuss with @John today and look to see if we can add some SHA based checking on the reads. Will report back with status updates asap 🙂 |
2024-10-15T02:03:48.638Z | <John> Hi,
I am running a CephFS filesystem on Kubernetes orchestrated using Rook and I am coming up against an issue
that I am struggling to debug.
The CephFS is running on PVCs, currently using the EBS CSI with IO2 block devices that have 6000 IOPS provisioned.
The cluster has come up and is healthy and the file system is successfully being mounted, written to and read
from by workloads. The workloads are K8s Pods related to the GitHub Actions Runner Controller. In our case, the containers
run in workflows are spun up in separate pods which Kubernetes will schedule to a node in the cluster (sometimes the
workflow pod might be scheduled to the same node as the runner pod). For the shared volume to pass files between the
runner and the workflow pods, we are using a CephFS volume here and it is mounted with `ReadWriteMany` to allow both
pods to write to the volume (this is required).
This is where the issue comes in, in one specific case we are seeing an issue reading a file from the shared volume. The
runner (which is C#) will write the event context to a JSON file, which the checkout action (which is NodeJs) will read
and Parse. The parsing will fail with an error:
```undefined:1
SyntaxError: Unexpected end of JSON input
at JSON.parse (<anonymous>)
at new Context (/__w/_actions/actions/checkout/1d96c772d19495a3b5c517cd2bc0cb401ea0529f/dist/index.js:4787:37)
...```
[The C# code that writes that file](https://github.com/actions/runner/blob/9b3b554758c26bf2caa8121278ec94a6f0d97de5/src/Runner.Worker/ExecutionContext.cs#L1176) is using `File.WriteAllText(...)`, which closes the file when it completes and it
should throw an exception if the return from closing the file is unsuccessful.
There are two interesting things here, firstly if the reading pod is scheduled to the same node as the writing pod, then
the error reading from the shared volume does not occur. Secondly, is I forked the checkout action to try and debug what
might be going on and I tried to log out the contents of the JSON file by updating the code to this:
```// Read and check the content of the file
const data = (0, fs_1.readFileSync)(process.env.GITHUB_EVENT_PATH, { encoding: 'utf8' });
console.log(data);
// Read the contents of the file from the volume again and parse it
this.payload = JSON.parse((0, fs_1.readFileSync)(process.env.GITHUB_EVENT_PATH, { encoding: 'utf8' }));```
Reading the file twice and only attempting to parse the second read succeeds and the error from before is no longer
present. The logged data appears to be correct, but if I attempt to parse rather than log it it fails.
This double read is not required when using another shared filesystem. Originally we'd been using AWS EFS, but it was
very slow, nearly 10 times slower for large checkouts.
We have tried:
• We were originally using GP3 block devices in the storage class for the PVCs, we changed to IO2 to test having higher IOPs, that didn't help.
• I mounted the volumes using various mount options: [read_from_replica=localize, noasyncreaddir, sync], none of them helped
• I tried running `sync /path/to/file` from a sidecar container in the writer's pod in a loop to try and diagnose the issue, that didn't help.
I am not sure why other files written to the shared volume can be read but this particular one is consistently causing issues. We were not the
first ones to encounter this issue using the Actions Runner Controller with Rook and CephFs, someone else encountered this, it appears that
they didn't resolve the issue either: <https://github.com/actions/runner-container-hooks/issues/145>.
Any advice to help debug this issue would be greatly appreciated! |
2024-10-15T03:41:37.527Z | <John> I had a bit of dig here and found that the constructor that is reading the JSON file is called twice by two different
libraries. The read happens in the constructor of a Context class and the two libraries each create a Context object.
I'd mistakenly not realized this before, so when I logged the output of the first read originally I'd missed
that in the first call the data that is read is empty, then the second call contains the data which was being logged.
Attaching a trace id to the output and digging into the data that is read to look for differences showed that the
very first read of the file contains no data at all (but the file does exist as there's no error opening it to read),
then the next read contains the data is able to be parsed.
I updated the code where the data is read to be:
```const traceId = crypto.randomUUID();
const trace = (msg) => console.log(`[${traceId}] ${msg}`);
if ((0, fs_1.existsSync)(process.env.GITHUB_EVENT_PATH)) {
const firstRead = (0, fs_1.readFileSync)(process.env.GITHUB_EVENT_PATH, { encoding: 'utf8' });
const secondRead = (0, fs_1.readFileSync)(process.env.GITHUB_EVENT_PATH, { encoding: 'utf8' });
if (firstRead !== secondRead) {
trace("The reads are different in the first check");
} else {
trace("The reads are the same in the first check");
}
try {
const firstParsed = JSON.parse(firstRead);
trace("The first read parsed successfully");
} catch (error) {
console.error(error);
trace("Parsing the first has errored");
trace(firstRead !== secondRead ? "The reads are different" : "The reads are the same, so why fail to parse?");
trace(`First read length: ${firstRead.length}`);
trace(`Second read length: ${secondRead.length}`);
}
trace("Parsing the second read now");
this.payload = JSON.parse(secondRead);
console.error();
}```
that produced the following output:
```[8be2d2ad-3c7d-4e1c-a195-9c5ea64ccbc2] The reads are different in the first check
[8be2d2ad-3c7d-4e1c-a195-9c5ea64ccbc2] Parsing the first has errored
SyntaxError: Unexpected end of JSON input
at JSON.parse (<anonymous>)
at new Context (/__w/_actions/johndrega/checkout/debug/dist/index.js:4955:46)
at 3030 (/__w/_actions/johndrega/checkout/debug/dist/index.js:5172:19)
at __nccwpck_require__ (/__w/_actions/johndrega/checkout/debug/dist/index.js:38193:43)
at 5438 (/__w/_actions/johndrega/checkout/debug/dist/index.js:5042:17)
at __nccwpck_require__ (/__w/_actions/johndrega/checkout/debug/dist/index.js:38193:43)
at 8601 (/__w/_actions/johndrega/checkout/debug/dist/index.js:1975:29)
at __nccwpck_require__ (/__w/_actions/johndrega/checkout/debug/dist/index.js:38193:43)
at 738 (/__w/_actions/johndrega/checkout/debug/dist/index.js:484:32)
at __nccwpck_require__ (/__w/_actions/johndrega/checkout/debug/dist/index.js:38193:43)
[8be2d2ad-3c7d-4e1c-a195-9c5ea64ccbc2] The reads are different
[8be2d2ad-3c7d-4e1c-a195-9c5ea64ccbc2] First read length: 0
[8be2d2ad-3c7d-4e1c-a195-9c5ea64ccbc2] Second read length: 28370
[8be2d2ad-3c7d-4e1c-a195-9c5ea64ccbc2] Parsing the second read now
[1bdc3a3c-0ab4-43cd-a055-c44822ee8cc9] The reads are the same in the first check
[1bdc3a3c-0ab4-43cd-a055-c44822ee8cc9] The first read parsed successfully
[1bdc3a3c-0ab4-43cd-a055-c44822ee8cc9] Parsing the second read now```
Is it possible that the first read, that has no data, causes something to be synced and then subsequent reads will
contain the data that is expected to be there? |
2024-10-15T04:14:30.768Z | <gregsfortytwo> Yeah, there’s a good chance somebody will recognize this overnight as the rest of the world gets to work |
2024-10-15T08:02:50.489Z | <Dhairya Parmar> hey, im sure you're done with this now but these are sometimes intermittent failures and you'd have to run make check multiple times before it finally succeeds 😕 |
2024-10-15T08:03:09.645Z | <Igor Golikov> thanks for that, will try |
2024-10-15T21:41:02.115Z | <erikth> Hi, I'm trying set up cephfs mirroring and having some troubles. We have two clusters on quincy and I've tried creating setting up cephfs-mirror according to the docs here: <https://docs.ceph.com/en/quincy/dev/cephfs-mirroring/>
The mirror daemon is up and running, and I've created the users and bootstrapped peers according to the docs. But when I mount up the fs on the source cluster and write some files, the files are never created in the target cluster.
The peer status always shows the state as `idle` and `snaps_synced` never gets above `0`. Any suggestions? \ |
2024-10-15T21:41:03.700Z | <erikth> Hi, I'm trying set up cephfs mirroring and having some troubles. We have two clusters on quincy and I've tried creating setting up cephfs-mirror according to the docs here: <https://docs.ceph.com/en/quincy/dev/cephfs-mirroring/>
The mirror daemon is up and running, and I've created the users and bootstrapped peers according to the docs. But when I mount up the fs on the source cluster and write some files, the files are never created in the target cluster.
The peer status always shows the state as `idle` and `snaps_synced` never gets above `0`. Any suggestions? |
2024-10-15T21:41:18.241Z | <erikth> Hi, I'm trying set up cephfs mirroring and having some troubles. We have two clusters on quincy and I've tried creating setting up cephfs-mirror according to the docs here: <https://docs.ceph.com/en/quincy/dev/cephfs-mirroring/>
The mirror daemon is up and running, and I've created the users and bootstrapped peers according to the docs. But when I mount up the fs on the source cluster and write some files, the files are never created in the target cluster.
The peer status always shows the state as `idle` and `snaps_synced` never gets above `0`. Any suggestions? |
2024-10-15T21:42:19.193Z | <erikth> ```# ceph fs snapshot mirror daemon status | jq
[
{
"daemon_id": 56433190,
"filesystems": [
{
"filesystem_id": 15,
"name": "test_repl",
"directory_count": 2,
"peers": [
{
"uuid": "77ccd184-c328-49a4-892b-2e8b8858b3e4",
"remote": {
"client_name": "client.test_repl_dal",
"cluster_name": "dallas",
"fs_name": "test_repl"
},
"stats": {
"failure_count": 0,
"recovery_count": 0
}
}
]
}
]
}
]```
|
2024-10-15T21:42:39.032Z | <erikth> ```# ceph fs snapshot mirror daemon status | jq
[
{
"daemon_id": 56433190,
"filesystems": [
{
"filesystem_id": 15,
"name": "test_repl",
"directory_count": 2,
"peers": [
{
"uuid": "77ccd184-c328-49a4-892b-2e8b8858b3e4",
"remote": {
"client_name": "client.test_repl_dal",
"cluster_name": "dallas",
"fs_name": "test_repl"
},
"stats": {
"failure_count": 0,
"recovery_count": 0
}
}
]
}
]
}
]```
```# ceph --admin-daemon /var/run/ceph/ceph-client.cephfs-mirror.follo.qqxufz.7.94652605216656.asok fs mirror status test_repl@15
{ "rados_inst": "10.3.5.57:0/3005246238",
"peers": {
"77ccd184-c328-49a4-892b-2e8b8858b3e4": {
"remote": {
"client_name": "client.test_repl_dal",
"cluster_name": "dallas",
"fs_name": "test_repl"
}
}
},
"snap_dirs": {
"dir_count": 2
}
} ```
```# ceph --admin-daemon /var/run/ceph/ceph-client.cephfs-mirror.follo.qqxufz.7.94652605216656.asok fs mirror peer status test_repl@15 77ccd184-c3
28-49a4-892b-2e8b8858b3e4
{
"/foo": {
"state": "idle",
"snaps_synced": 0,
"snaps_deleted": 0,
"snaps_renamed": 0
},
"/mirror": {
"state": "idle",
"snaps_synced": 0,
"snaps_deleted": 0,
"snaps_renamed": 0
}
}``` |
2024-10-15T23:05:26.823Z | <gregsfortytwo> You need to generate your own snapshots before anything will be synchronized. You can use snap-schedule for that if you want |