PR 164 breaking org-todo

[shouya]

Today I noticed my org-mode started to behave abnormally. The observed behavior is that when marking a heading as DONE with org-todo (C-c C-t), the heading did not get correctly marked as expected.

# before running `org-todo` (point on the heading)
* TODO heading

# after running `org-todo`
*heading

# expected state
* DONE heading

It also errors with args-out-of-range message at this position.

I wasn't suspecting copilot.el initially, but bisecting my config points to copilot.el as the culprit. This is double confirmed by disabling copilot-mode on the org buffer, and then the problem is gone.

I then scanned copilot.el commits and find that it's the most recent commit (#164) that's causing the problem. Before this version everything is fine. I have confirmed the problem on two org versions, namely 9.7-pre (latest) and 9.6.6 (emacs 29.1 built-in).

I'm suspecting the added {before,after}-change-functions hooks may be conflicting with org-todo. That said, I'm expecting the change may break other places as well but I didn't observe any (yet). Sorry that I don't possess the sufficient skill to spot out how exactly how it's broken and patch it.

[shouya]

cc @emil-vdw.

Thanks for that great PR btw, I was really looking forward for this feature - that's why I updated copilot.el as soon as it was merged :)

[emil-vdw]

@shouya Great to hear! Will look into it this weekend.

In the meantime, would you please enable event logging by customize copilot-log-max (to e.g. 1000), then paste related logs in the copilot events and copilot stderr buffer.

[shouya]

Hi @emil-vdw, here's the *copilot events* buffer you asked for.

[client-notification] Thu Aug 31 00:44:17 2023:
(:jsonrpc "2.0" :method "textDocument/didFocus" :params
          (:textDocument
           (:uri "file:///home/shou/tmp/scratch/scratch-1LZkZB.org")))
[client-notification] Thu Aug 31 00:44:19 2023:
(:jsonrpc "2.0" :method "textDocument/didFocus" :params
          (:textDocument
           (:uri "file:///home/shou/tmp/scratch/scratch-1LZkZB.org")))
[client-notification] Thu Aug 31 00:44:21 2023:
(:jsonrpc "2.0" :method "textDocument/didChange" :params
          (:textDocument
           (:uri "file:///home/shou/tmp/scratch/scratch-1LZkZB.org" :version 35)
           :contentChanges
           [(:range
             (:start
              (:line 0 :character 1)
              :end
              (:line 0 :character 2))
             :text "")]))
[client-notification] Thu Aug 31 00:44:21 2023:
(:jsonrpc "2.0" :method "textDocument/didChange" :params
          (:textDocument
           (:uri "file:///home/shou/tmp/scratch/scratch-1LZkZB.org" :version 36)
           :contentChanges
           [(:range
             (:start
              (:line 0 :character 1)
              :end
              (:line 0 :character 1))
             :text " TODO ")]))
[client-notification] Thu Aug 31 00:44:21 2023:
(:jsonrpc "2.0" :method "textDocument/didChange" :params
          (:textDocument
           (:uri "file:///home/shou/tmp/scratch/scratch-1LZkZB.org" :version 37)
           :contentChanges
           [(:range
             (:start
              (:line 0 :character 0)
              :end
              (:line 0 :character 11))
             :text "")]))
[client-notification] Thu Aug 31 00:44:21 2023:
(:jsonrpc "2.0" :method "textDocument/didChange" :params
          (:textDocument
           (:uri "file:///home/shou/tmp/scratch/scratch-1LZkZB.org" :version 38)
           :contentChanges
           [(:range
             (:start
              (:line 0 :character 0)
              :end
              (:line 0 :character 0))
             :text "* TODO test")]))
[client-request] (id:15) Thu Aug 31 00:44:21 2023:
(:jsonrpc "2.0" :id 15 :method "getCompletions" :params
          (:doc
           (:version 38 :tabSize 2 :indentSize 2 :insertSpaces t :path "/home/shou/tmp/scratch/scratch-1LZkZB.org" :uri "file:///home/shou/tmp/scratch/scratch-1LZkZB.org" :relativePath "scratch-1LZkZB.org" :languageId "org" :position
                     (:line 3 :character 0))))
[server-notification] Thu Aug 31 00:44:21 2023:
(:jsonrpc "2.0" :method "LogMessage" :params
          (:level 0 :message "[DEBUG] [getCompletions] [2023-08-30T15:44:21.402Z] Requesting completion at position 3:0, between \"hello world\\n\" and \"\"." :metadataStr "[DEBUG] [getCompletions] [2023-08-30T15:44:21.402Z]" :extra
                  ["Requesting completion at position 3:0, between \"hello world\\n\" and \"\"."]))
[server-notification] Thu Aug 31 00:44:21 2023:
(:jsonrpc "2.0" :method "statusNotification" :params
          (:status "InProgress" :message ""))
[server-notification] Thu Aug 31 00:44:21 2023:
(:jsonrpc "2.0" :method "LogMessage" :params
          (:level 1 :message "[INFO] [default] [2023-08-30T15:44:21.483Z] [fetchCompletions] engine https://copilot-proxy.githubusercontent.com/v1/engines/copilot-codex" :metadataStr "[INFO] [default] [2023-08-30T15:44:21.483Z]" :extra
                  ["[fetchCompletions] engine https://copilot-proxy.githubusercontent.com/v1/engines/copilot-codex"]))
[server-notification] Thu Aug 31 00:44:21 2023:
(:jsonrpc "2.0" :method "LogMessage" :params
          (:level 1 :message "[INFO] [default] [2023-08-30T15:44:21.601Z] request.response: [https://copilot-proxy.githubusercontent.com/v1/engines/copilot-codex/completions] took 117 ms" :metadataStr "[INFO] [default] [2023-08-30T15:44:21.601Z]" :extra
                  ["request.response: [https://copilot-proxy.githubusercontent.com/v1/engines/copilot-codex/completions] took 117 ms"]))
[server-notification] Thu Aug 31 00:44:21 2023:
(:jsonrpc "2.0" :method "LogMessage" :params
          (:level 1 :message "[INFO] [streamChoices] [2023-08-30T15:44:21.603Z] solution 0 returned. finish reason: [stop]" :metadataStr "[INFO] [streamChoices] [2023-08-30T15:44:21.603Z]" :extra
                  ["solution 0 returned. finish reason: [stop]"]))
[server-notification] Thu Aug 31 00:44:21 2023:
(:jsonrpc "2.0" :method "LogMessage" :params
          (:level 1 :message "[INFO] [streamChoices] [2023-08-30T15:44:21.604Z] request done: headerRequestId: [50160273-93c2-47ae-9ff0-b928fefdbd29] model deployment ID: [xca6373c2f5d7]" :metadataStr "[INFO] [streamChoices] [2023-08-30T15:44:21.604Z]" :extra
                  ["request done: headerRequestId: [50160273-93c2-47ae-9ff0-b928fefdbd29] model deployment ID: [xca6373c2f5d7]"]))
[server-notification] Thu Aug 31 00:44:21 2023:
(:jsonrpc "2.0" :method "statusNotification" :params
          (:status "Normal" :message ""))
[server-reply] (id:15) Thu Aug 31 00:44:21 2023:
(:jsonrpc "2.0" :id 15 :result
          (:completions
           []))
[client-notification] Thu Aug 31 00:44:22 2023:
(:jsonrpc "2.0" :method "textDocument/didChange" :params
          (:textDocument
           (:uri "file:///home/shou/tmp/scratch/scratch-1LZkZB.org" :version 39)
           :contentChanges
           [(:range
             (:start
              (:line 0 :character 1)
              :end
              (:line 0 :character 7))
             :text "")]))
[client-request] (id:16) Thu Aug 31 00:44:22 2023:
(:jsonrpc "2.0" :id 16 :method "getCompletions" :params
          (:doc
           (:version 39 :tabSize 2 :indentSize 2 :insertSpaces t :path "/home/shou/tmp/scratch/scratch-1LZkZB.org" :uri "file:///home/shou/tmp/scratch/scratch-1LZkZB.org" :relativePath "scratch-1LZkZB.org" :languageId "org" :position
                     (:line 3 :character 0))))
[server-notification] Thu Aug 31 00:44:22 2023:
(:jsonrpc "2.0" :method "LogMessage" :params
          (:level 0 :message "[DEBUG] [getCompletions] [2023-08-30T15:44:22.566Z] Requesting completion at position 3:0, between \"hello world\\n\" and \"\"." :metadataStr "[DEBUG] [getCompletions] [2023-08-30T15:44:22.566Z]" :extra
                  ["Requesting completion at position 3:0, between \"hello world\\n\" and \"\"."]))
[server-notification] Thu Aug 31 00:44:22 2023:
(:jsonrpc "2.0" :method "statusNotification" :params
          (:status "InProgress" :message ""))
[server-notification] Thu Aug 31 00:44:22 2023:
(:jsonrpc "2.0" :method "LogMessage" :params
          (:level 1 :message "[INFO] [default] [2023-08-30T15:44:22.646Z] [fetchCompletions] engine https://copilot-proxy.githubusercontent.com/v1/engines/copilot-codex" :metadataStr "[INFO] [default] [2023-08-30T15:44:22.646Z]" :extra
                  ["[fetchCompletions] engine https://copilot-proxy.githubusercontent.com/v1/engines/copilot-codex"]))
[server-notification] Thu Aug 31 00:44:22 2023:
(:jsonrpc "2.0" :method "LogMessage" :params
          (:level 1 :message "[INFO] [default] [2023-08-30T15:44:22.893Z] request.response: [https://copilot-proxy.githubusercontent.com/v1/engines/copilot-codex/completions] took 247 ms" :metadataStr "[INFO] [default] [2023-08-30T15:44:22.893Z]" :extra
                  ["request.response: [https://copilot-proxy.githubusercontent.com/v1/engines/copilot-codex/completions] took 247 ms"]))
[server-notification] Thu Aug 31 00:44:22 2023:
(:jsonrpc "2.0" :method "LogMessage" :params
          (:level 1 :message "[INFO] [streamChoices] [2023-08-30T15:44:22.895Z] solution 0 returned. finish reason: [stop]" :metadataStr "[INFO] [streamChoices] [2023-08-30T15:44:22.895Z]" :extra
                  ["solution 0 returned. finish reason: [stop]"]))
[server-notification] Thu Aug 31 00:44:22 2023:
(:jsonrpc "2.0" :method "LogMessage" :params
          (:level 1 :message "[INFO] [streamChoices] [2023-08-30T15:44:22.895Z] request done: headerRequestId: [1ab9371a-a7a1-463a-b39d-34ea084fa8df] model deployment ID: [xca6373c2f5d7]" :metadataStr "[INFO] [streamChoices] [2023-08-30T15:44:22.895Z]" :extra
                  ["request done: headerRequestId: [1ab9371a-a7a1-463a-b39d-34ea084fa8df] model deployment ID: [xca6373c2f5d7]"]))
[server-notification] Thu Aug 31 00:44:22 2023:
(:jsonrpc "2.0" :method "statusNotification" :params
          (:status "Normal" :message ""))
[server-reply] (id:16) Thu Aug 31 00:44:22 2023:
(:jsonrpc "2.0" :id 16 :result
          (:completions
           []))
[stderr] ApplicationInsights:Sender [
[stderr]   'Ingestion endpoint could not be reached. This batch of telemetry items has been lost. Use Disk Retry Caching to enable resending of failed telemetry. Error:',
[stderr]   [
[stderr]     "[object Error]{ stack: 'Error: getaddrinfo ENOTFOUND copilot-telemetry.githubusercontent.com\n" +
[stderr]       "    at GetAddrInfoReqWrap.onlookupall [as oncomplete] (node:dns:118:26)', message: 'getaddrinfo ENOTFOUND copilot-telemetry.githubusercontent.com', name: 'Error'"
[stderr]   ]
[stderr] ]

The Ingestion endpoint could not be reached warning was expected because I blocked the telemetry endpoint at my DNS server. This same warning seems to be harmless because it's the same as in prior versions, and especially here the org header is already broken before this warning shows up.

Reproduction info in case it's needed: This is the initial content of the buffer:

* test

hello world

I pressed C-c C-t (org-todo) twice on the heading to switch the todo state to TODO and to DONE.

[raymond-w-ko]

I've narrowed it to this line: https://github.com/zerolfx/copilot.el/blob/82d52b0314b87b682e44fdfacc90116c8bece491/copilot.el#L657

This is surprising as this is calling a Emacs built-in function.

I'm not an expert in Emacs, but my hypothesis is that sending a jsonrpc input involves some buffer switching internally behind the scenes, and org-mode does not like this.

I also briefly tried changing the progn in the macro to save-excursion, but this did not work for me. I don't know if this has to be changed everywhere.

Unless someone knows how to perfectly preserve state, I think a change queue is needed, and then should be dispatched in the after-change-functions. I may whip something else, but I'm feeling sick and tired right now.

[emil-vdw]

I can't seem to replicate this at all. Will try with your versions. I have: Emacs 28.2 Org 9.5.5

[emil-vdw]

@raymond-w-ko are you also using org >= 9.6.6 ?

[raymond-w-ko]

I am using the latest emacs-29 branch, org 9.6.8, which is part of the official branch: https://github.com/emacs-mirror/emacs/blob/emacs-29/lisp/org/org.el

[raymond-w-ko]

org 9.6.9 came out recently, so I will try to find time and check if I can reproduce the issue with the latest version.

https://git.savannah.gnu.org/cgit/emacs/org-mode.git

[raymond-w-ko]

I didn't quite test on 9.6.9, but 9.7-pre using the straight.el use-package mirror, and I am still getting this issue.

[github-actions[bot]]

This issue is stale because it has been open 30 days with no activity. Remove stale label or comment or this will be closed in 5 days.

[github-actions[bot]]

This issue was closed because it has been stalled for 5 days with no activity.

[shouya]

Sad to see this issue closed without being solved yet.

In the past few weeks I have been running copilot.el outside org-mode. I still really want to get copilot working for org-mode so it'd be helpful for my note-taking.

Then today I have this simple idea to get around the limitation of org-todo, given it's the only known offending function, by masking copilot in an advice to org-todo.

Here's the solution I used, simple but quite effective:

```emacs-lisp (defun shou/advice-mask-copilot (orig-fn &rest args) (cl-letf (((symbol-function 'copilot--on-doc-change) (lambda (&rest args) nil))) (apply orig-fn args))) (advice-add 'org-todo :around #'shou/advice-mask-copilot) ``` Hope it can be of help.

NOT AN EFFECTIVE SOLUTION. SEE THE FOLLOWING COMMENT.

---

I'm not reopening this issue because the maintainers seem to be out of bandwidth to deal with this, and it seems few people are experiencing the same issue. However, since it's just copilot.el that doesn't play well with this particular piece of org-mode feature, my hunch tells me that it may indicate some kind of deep absurdity in either copilot or in org-todo. Maybe in a future time I can really spend some time learning the working of copilot and take a deeper look.

[shouya]

Correcting my above comment - masking copilot--on-doc-change is not a perfect solution. Because it no longer notifies the change to copilot, the completion may stop working after calling org-todo.

So I traced and reached at similar conclusion that @raymond-w-ko discovered. The innocent looking call to jsonrpc-notify seems to be the culprit.

@raymond-w-ko suspected jsonrpc-notify may be switching buffer, but I think it's not the cause - if the PARAMS is '() (instead of the '(:textDocument ...)), then it has no effect on org-todo.

Anyway, I can confirm the fix @raymond-w-ko implemented by introducing a change queue does fix the issue for me. Is there any hope to see it merged? @emil-vdw

[emil-vdw]

@shouya I was planning on testing this before review but have been very busy unfortunately. The change seems pretty safe but I will review this weekend.

[emil-vdw]

@shouya I've made come changes to the PR. Could you help me test if you have time?

[shouya]

@emil-vdw from my basic testing the result looks great! I don't see any broken org structure any more. I'm looking forward to see it merged.