Error in post-command-hook (copilot--complete-post-command): (args-out-of-range 51 52)

[VitalyAnkh]

I use copilot.el to do literate programming in org-mode. It works normally a few days ago but stops working today.

When I open an org file the first time, copilot.el will give a suggestion but then will never give any suggestions again. There is an error message in minibuffer:

Error in post-command-hook (copilot--complete-post-command): (args-out-of-range 51 52)

The full log is:

[Agent] [DEBUG] [agent] [2022-05-18T16:08:25.891Z] Agent service starting
[Initialize] ((error) (capabilities (textDocumentSync (openClose . t) (change . 2)) (workspace (workspaceFolders (supported . :json-false) (changeNotifications . :json-false)))))
[INFO] Discard message without id: ((jsonrpc . "2.0") (method . "statusNotification") (params (status . "InProgress") (message . "")))
[Agent] [INFO] [default] [2022-05-18T16:08:26.646Z] [fetchCompletions] engine https://copilot-proxy.githubusercontent.com/v1/engines/copilot-codex
[Agent] [INFO] [default] [2022-05-18T16:08:28.267Z] request.response: [https://copilot-proxy.githubusercontent.com/v1/engines/copilot-codex/completions] took 1620 ms
[Agent] [INFO] [streamChoices] [2022-05-18T16:08:28.268Z] solution 0 returned. finish reason: ["stop"] finishOffset: [undefined] completionId: [{cmpl-59GVoe30Co5lG78dglmeisUmCmG4k}] created: [{1652890108}]
[INFO] Discard message without id: ((jsonrpc . "2.0") (method . "statusNotification") (params (status . "Normal") (message . "")))
[INFO] Completion: ((error) (completions . [((uuid . "16ce15a7-3810-4982-908f-37fb848e88e2") (text . "import Data.Complex") (range (start (line . 259) (character . 0)) (end (line . 259) (character . 0))) (displayText . "import Data.Complex") (position (line . 259) (character . 0)))]))
[Agent] [INFO] [post-insertion] [2022-05-18T16:08:59.601Z] Could not get document for /home/vitalyr/org/20220214134416-sicp_polyglot.org. Maybe it was closed by the editor.

And here is my configurations for copilot.el:

(customize-set-variable 'copilot-enable-predicates '((lambda () (eq (meow--current-state) 'insert))))
(defun my-tab ()
  (interactive)
  (or (copilot-accept-completion)
      (company-indent-or-complete-common nil)))
;; complete by copilot first, then company-mode
(use-package! copilot
  :hook (prog-mode . copilot-mode)
  :hook (text-mode . copilot-mode)
  :bind (("C-TAB" . 'copilot-accept-completion-by-word)
         ("C-<tab>" . 'copilot-accept-completion-by-word)
         :map company-active-map
         ("<tab>" . 'my-tab)
         ("TAB" . 'my-tab)
         :map company-mode-map
         ("<tab>" . 'my-tab)
         ("TAB" . 'my-tab)))

I have updated to the latest code but it didn't help.

[zerolfx]

To make Copilot work again in this situation (if the bug occurs rarely), you can toggle off and on copilot-mode.

To help me debug the issue, can you try M-x toggle-debug-on-error and provide the backtrace information?

[VitalyAnkh]

It doesn't help to toggle off and on for this error happens every time I begin to edit an Org file.

But I found it's weird that there is no backtrace information showing up even if I run M-x toggle-debug-on-error. But it will still signal an error if other errors happen.

Could you open my file that produces this error and see if it's reproducible? It's here: https://gist.github.com/VitalyAnkh/02292193112bacd87f4e1be5abda4134

[zerolfx]

I failed to reproduce the problem. And I think there is nothing wrong with your configuration, so maybe some other packages (especially those using overlays to display something) conflict with copilot.el?

Can you keep copilot-mode off and try to trigger completion manually using M-x copilot-complete to see if there is any backtrace?

[VitalyAnkh]

I still cannot find the backtrace when I invoke copilot-complete manually: it will show complete suggestion normally like there is no problem. Sorry for that.

But I found the error always happens in org mode's code blocks: the #+begin_src #+end_src part of the Org file. Could you see if you can reproduce this error when typing in the code blocks in that file? Thanks!

[zerolfx]

I still can't reproduce it inside code blocks.

[VitalyAnkh]

I don't know what to do now... Could you give me some advice to debug this?

And I find this error usually happens after a few normal behaviors... Could you edit this file more and see if it makes a difference? Thanks!

And it's a great package for the emacs community! Thank you!

[zerolfx]

I assume you are using doom Emacs. You can try to find a minimal doom Emacs setup (with a few default modules and copilot configurations) that can reproduce the problem, and then I can debug it for you. or I guess the bug is inside copilot-display-overlay-completion, a UI-related function. You can print some information inside it and check whether it works as intended.

[VitalyAnkh]

Today I disabled copilot-mode on default and invoke copilot-complete for several times, then finally I got a error backtrace:

Debugger entered--Lisp error: (wrong-type-argument stringp nil)
  compare-strings("4. 考虑64位系统" 0 10 nil 0 0)
  s-shared-start("4. 考虑64位系统" nil)
  (length (s-shared-start completion cur-line))
  (let* ((cur-line (s-chop-suffix "\n" (thing-at-point 'line))) (common-prefix-len (length (s-shared-start completion cur-line)))) (setq completion (substring completion common-prefix-len)) (forward-char common-prefix-len))
  (save-excursion (widen) (goto-char (point-min)) (if (= (line-end-position line) (1- (point-max))) (progn (goto-char (point-max)) (newline) (forward-char -1)) (forward-line line) (forward-char col)) (let* ((cur-line (s-chop-suffix "\n" (thing-at-point 'line))) (common-prefix-len (length (s-shared-start completion cur-line)))) (setq completion (substring completion common-prefix-len)) (forward-char common-prefix-len)) (if (and (s-present-p completion) (or (= (point) user-pos) (and (< (point) user-pos) (s-blank-p (s-trim (buffer-substring-no-properties ... user-pos)))))) (progn (let* ((ov (make-overlay (point) (1+ ...) nil t t)) (p-completion (propertize completion 'face 'copilot-overlay-face))) (if (= (overlay-start ov) (overlay-end ov)) (overlay-put ov 'after-string p-completion) (overlay-put ov 'display (substring p-completion 0 1)) (overlay-put ov 'after-string (concat (substring p-completion 1) "\n"))) (overlay-put ov 'completion completion) (overlay-put ov 'start (point)) (overlay-put ov 'uuid uuid) (setq copilot--overlay ov) (funcall (copilot--agent-request "notifyShown" (list :uuid uuid)) copilot--ignore-response)))))
  copilot-display-overlay-completion("4. 考虑64位系统" "32cb9b42-417f-44be-8a2b-8f816fefa49a" 111 0 5)
  (let* ((text (alist-get 'text completion)) (uuid (alist-get 'uuid completion)) (range (alist-get 'range completion)) (start (alist-get 'start range)) (start-line (alist-get 'line start)) (start-char (alist-get 'character start))) (copilot-display-overlay-completion text uuid start-line start-char (point)))
  (progn (let* ((text (alist-get 'text completion)) (uuid (alist-get 'uuid completion)) (range (alist-get 'range completion)) (start (alist-get 'start range)) (start-line (alist-get 'line start)) (start-char (alist-get 'character start))) (copilot-display-overlay-completion text uuid start-line start-char (point))))
  (if completion (progn (let* ((text (alist-get 'text completion)) (uuid (alist-get 'uuid completion)) (range (alist-get 'range completion)) (start (alist-get 'start range)) (start-line (alist-get 'line start)) (start-char (alist-get 'character start))) (copilot-display-overlay-completion text uuid start-line start-char (point)))))
  copilot--show-completion(((uuid . "32cb9b42-417f-44be-8a2b-8f816fefa49a") (text . "4. 考虑64位系统") (range (start (line . 111) (character . 0)) (end (line . 111) (character . 5))) (displayText . "64位系统") (position (line . 111) (character . 5))))
  (let* ((completions (alist-get 'completions result)) (completion (if (seq-empty-p completions) nil (seq-elt completions 0)))) (if (and (not completion) called-interactively) (progn (message "No completion is available."))) (copilot--show-completion completion))
  (closure ((called-interactively . t) t) (result) (copilot--log "[INFO] Completion: %S" result) (let* ((completions (alist-get 'completions result)) (completion (if (seq-empty-p completions) nil (seq-elt completions 0)))) (if (and (not completion) called-interactively) (progn (message "No completion is available."))) (copilot--show-completion completion)))(((error) (completions . [((uuid . "32cb9b42-417f-44be-8a2b-8f816fefa49a") (text . "4. 考虑64位系统") (range (start (line . 111) (character . 0)) (end (line . 111) (character . 5))) (displayText . "64位系统") (position (line . 111) (character . 5)))])))
  funcall((closure ((called-interactively . t) t) (result) (copilot--log "[INFO] Completion: %S" result) (let* ((completions (alist-get 'completions result)) (completion (if (seq-empty-p completions) nil (seq-elt completions 0)))) (if (and (not completion) called-interactively) (progn (message "No completion is available."))) (copilot--show-completion completion))) ((error) (completions . [((uuid . "32cb9b42-417f-44be-8a2b-8f816fefa49a") (text . "4. 考虑64位系统") (range (start (line . 111) (character . 0)) (end (line . 111) (character . 5))) (displayText . "64位系统") (position (line . 111) (character . 5)))])))
  (if (not id) (if (equal (alist-get 'method content) "LogMessage") (copilot--log "[Agent] %s" (alist-get 'message (alist-get 'params content))) (copilot--log "[INFO] Discard message without id: %S" content)) (funcall (alist-get id copilot--callbacks) (cons (cons 'error err) result)) (assq-delete-all id copilot--callbacks))
  (let* ((result (alist-get 'result content)) (err (alist-get 'error content)) (id (alist-get 'id content))) (if err (progn (copilot--log "[ERROR] Error in response: %S\n[ERROR] Response:%S\n" err content))) (if (not id) (if (equal (alist-get 'method content) "LogMessage") (copilot--log "[Agent] %s" (alist-get 'message (alist-get 'params content))) (copilot--log "[INFO] Discard message without id: %S" content)) (funcall (alist-get id copilot--callbacks) (cons (cons 'error err) result)) (assq-delete-all id copilot--callbacks)))
  copilot--process-response(((jsonrpc . "2.0") (id . 26) (result (completions . [((uuid . "32cb9b42-417f-44be-8a2b-8f816fefa49a") (text . "4. 考虑64位系统") (range (start ... ...) (end ... ...)) (displayText . "64位系统") (position (line . 111) (character . 5)))]))))
  (if content (copilot--process-response content) (copilot--log "[ERROR] Failed to parse response: %S" content))
  (let ((content (condition-case nil (progn (json-read-from-string content)) (error nil)))) (if content (copilot--process-response content) (copilot--log "[ERROR] Failed to parse response: %S" content)))
  (let ((content (decode-coding-string (substring (encode-coding-string copilot--output-buffer 'raw-text) (length header) full-length) 'utf-8))) (setq copilot--output-buffer (decode-coding-string (substring (encode-coding-string copilot--output-buffer 'raw-text) full-length) 'utf-8)) (let ((content (condition-case nil (progn (json-read-from-string content)) (error nil)))) (if content (copilot--process-response content) (copilot--log "[ERROR] Failed to parse response: %S" content))) (copilot--process-filter process nil))
  (progn (let ((content (decode-coding-string (substring (encode-coding-string copilot--output-buffer 'raw-text) (length header) full-length) 'utf-8))) (setq copilot--output-buffer (decode-coding-string (substring (encode-coding-string copilot--output-buffer 'raw-text) full-length) 'utf-8)) (let ((content (condition-case nil (progn (json-read-from-string content)) (error nil)))) (if content (copilot--process-response content) (copilot--log "[ERROR] Failed to parse response: %S" content))) (copilot--process-filter process nil)))
  (if (>= (length copilot--output-buffer) full-length) (progn (let ((content (decode-coding-string (substring (encode-coding-string copilot--output-buffer ...) (length header) full-length) 'utf-8))) (setq copilot--output-buffer (decode-coding-string (substring (encode-coding-string copilot--output-buffer 'raw-text) full-length) 'utf-8)) (let ((content (condition-case nil (progn ...) (error nil)))) (if content (copilot--process-response content) (copilot--log "[ERROR] Failed to parse response: %S" content))) (copilot--process-filter process nil))))
  (let* ((header (car header-match)) (content-length (string-to-number (car (cdr header-match)))) (full-length (+ (length header) content-length))) (if (>= (length copilot--output-buffer) full-length) (progn (let ((content (decode-coding-string (substring ... ... full-length) 'utf-8))) (setq copilot--output-buffer (decode-coding-string (substring (encode-coding-string copilot--output-buffer ...) full-length) 'utf-8)) (let ((content (condition-case nil ... ...))) (if content (copilot--process-response content) (copilot--log "[ERROR] Failed to parse response: %S" content))) (copilot--process-filter process nil)))))
  (progn (let* ((header (car header-match)) (content-length (string-to-number (car (cdr header-match)))) (full-length (+ (length header) content-length))) (if (>= (length copilot--output-buffer) full-length) (progn (let ((content (decode-coding-string ... ...))) (setq copilot--output-buffer (decode-coding-string (substring ... full-length) 'utf-8)) (let ((content ...)) (if content (copilot--process-response content) (copilot--log "[ERROR] Failed to parse response: %S" content))) (copilot--process-filter process nil))))))
  (if header-match (progn (let* ((header (car header-match)) (content-length (string-to-number (car (cdr header-match)))) (full-length (+ (length header) content-length))) (if (>= (length copilot--output-buffer) full-length) (progn (let ((content ...)) (setq copilot--output-buffer (decode-coding-string ... ...)) (let (...) (if content ... ...)) (copilot--process-filter process nil)))))))
  (if (and (not header-match) (> (length copilot--output-buffer) 50)) (progn (copilot--log "[Warning] Copilot agent output buffer reset.") (copilot--log "[Warning] Before reset: %S\n" copilot--output-buffer) (setq copilot--output-buffer nil)) (if header-match (progn (let* ((header (car header-match)) (content-length (string-to-number (car ...))) (full-length (+ (length header) content-length))) (if (>= (length copilot--output-buffer) full-length) (progn (let (...) (setq copilot--output-buffer ...) (let ... ...) (copilot--process-filter process nil))))))))
  (let ((header-match (s-match "^Content-Length: \\([0-9]+\\)\15?\n\15?\n" copilot--output-buffer))) (if (and (not header-match) (> (length copilot--output-buffer) 50)) (progn (copilot--log "[Warning] Copilot agent output buffer reset.") (copilot--log "[Warning] Before reset: %S\n" copilot--output-buffer) (setq copilot--output-buffer nil)) (if header-match (progn (let* ((header (car header-match)) (content-length (string-to-number ...)) (full-length (+ ... content-length))) (if (>= (length copilot--output-buffer) full-length) (progn (let ... ... ... ...))))))))
  copilot--process-filter(#<process copilot-agent> "Content-Length: 382\n\n{\"jsonrpc\":\"2.0\",\"method\":\"Lo...")
  #<subr completing-read-default>("M-x " #<subr F616e6f6e796d6f75732d6c616d626461_anonymous_lambda_53> #f(compiled-function (sym) #<bytecode -0x1486038087c71aa3>) t nil extended-command-history nil nil)
  apply((#<subr completing-read-default> "M-x " #<subr F616e6f6e796d6f75732d6c616d626461_anonymous_lambda_53> #f(compiled-function (sym) #<bytecode -0x1486038087c71aa3>) t nil extended-command-history nil nil))
  vertico--advice(#<subr completing-read-default> "M-x " #<subr F616e6f6e796d6f75732d6c616d626461_anonymous_lambda_53> #f(compiled-function (sym) #<bytecode -0x1486038087c71aa3>) t nil extended-command-history nil nil)
  apply(vertico--advice #<subr completing-read-default> ("M-x " #<subr F616e6f6e796d6f75732d6c616d626461_anonymous_lambda_53> #f(compiled-function (sym) #<bytecode -0x1486038087c71aa3>) t nil extended-command-history nil nil))
  completing-read-default("M-x " #<subr F616e6f6e796d6f75732d6c616d626461_anonymous_lambda_53> #f(compiled-function (sym) #<bytecode -0x1486038087c71aa3>) t nil extended-command-history nil nil)
  read-extended-command()
  byte-code("\302\30\11\303 \10E)\207" [execute-extended-command--last-typed current-prefix-arg nil read-extended-command] 3)
  command-execute(execute-extended-command)

I also switched from company to corfu now. Is this backtrace helpful for debugging?

[VitalyAnkh]

It seems that it's not copilot.el's error. I met a similar error when I use lsp-mode and rust-analyzer in a rust project:

Warning (lsp-mode): 
Warning (lsp-mode): Failed to parse the following chunk:
’’’
Content-Length: 81

{"jsonrpc":"2.0","id":151,"error":{"code":-32800,"message":"canceled by client"}}
’’’
with message (args-out-of-range 82 83) Disable showing Disable logging

[zerolfx]

The (wrong-type-argument stringp nil) error is a bug of copilot.el (in some special cases, (thing-at-point 'line) will evaluate to nil), and I fixed it.

Since args-out-of-range error seems not caused by copilot.el, I will close the issue and you are welcome to reopen it once you have new findings.

[VitalyAnkh]

I use the trick on emacs-devel to debug errors in post-command-hook, now I have a backtrace!

Debugger entered--Lisp error: (args-out-of-range 51 52)
  remove-text-properties(51 52 (display nil))
  annotate--remove-annotation-property(1 51)
  url-generic-parse-url("/home/vitalyr/org/20220214134416-sicp_polyglot.org")
  url-encode-url("/home/vitalyr/org/20220214134416-sicp_polyglot.org")
  (concat "file://" (url-encode-url buffer-file-name))
  (cond ((not buffer-file-name) "") ((eq system-type 'windows-nt) (concat "file:///" (url-encode-url buffer-file-name))) (t (concat "file://" (url-encode-url buffer-file-name))))
  copilot--get-uri()
  (list :source (concat (buffer-substring-no-properties (point-min) (point-max)) "\n") :tabSize (copilot--infer-indentation-offset) :indentSize (copilot--infer-indentation-offset) :insertSpaces (if indent-tabs-mode :false t) :path (buffer-file-name) :uri (copilot--get-uri) :relativePath (copilot--get-relative-path) :languageId (s-chop-suffix "-mode" (symbol-name major-mode)) :position (list :line (1- (line-number-at-pos)) :character (length (buffer-substring-no-properties (point-at-bol) (point)))))
  copilot--generate-doc()
  (list :doc (copilot--generate-doc))
  (copilot--agent-request "getCompletions" (list :doc (copilot--generate-doc)))
  (funcall (copilot--agent-request "getCompletions" (list :doc (copilot--generate-doc))) callback)
  copilot--get-completion((closure ((called-interactively) t) (result) (copilot--log "[INFO] Completion: %S" result) (let* ((completions (alist-get 'completions result)) (completion (if (seq-empty-p completions) nil (seq-elt completions 0)))) (if (and (not completion) called-interactively) (progn (message "No completion is available."))) (copilot--show-completion completion))))
  (progn (copilot--get-completion #'(lambda (result) (copilot--log "[INFO] Completion: %S" result) (let* ((completions (alist-get ... result)) (completion (if ... nil ...))) (if (and (not completion) called-interactively) (progn (message "No completion is available."))) (copilot--show-completion completion)))))
  (if (buffer-file-name) (progn (copilot--get-completion #'(lambda (result) (copilot--log "[INFO] Completion: %S" result) (let* ((completions ...) (completion ...)) (if (and ... called-interactively) (progn ...)) (copilot--show-completion completion))))))
  (let ((called-interactively (called-interactively-p 'interactive))) (if (buffer-file-name) (progn (copilot--get-completion #'(lambda (result) (copilot--log "[INFO] Completion: %S" result) (let* (... ...) (if ... ...) (copilot--show-completion completion)))))))
  copilot-complete()
  (progn (copilot-complete))
  (if (and (cl-every #'(lambda (pred) (if (functionp pred) (funcall pred) t)) copilot-enable-predicates) (cl-notany #'(lambda (pred) (if (functionp pred) (funcall pred) f)) copilot-disable-predicates)) (progn (copilot-complete)))
  (if (and (symbolp this-command) (s-starts-with-p "copilot-" (symbol-name this-command))) nil (copilot-clear-overlay) (if (and (cl-every #'(lambda (pred) (if (functionp pred) (funcall pred) t)) copilot-enable-predicates) (cl-notany #'(lambda (pred) (if (functionp pred) (funcall pred) f)) copilot-disable-predicates)) (progn (copilot-complete))))
  (progn (if (and (symbolp this-command) (s-starts-with-p "copilot-" (symbol-name this-command))) nil (copilot-clear-overlay) (if (and (cl-every #'(lambda (pred) (if ... ... t)) copilot-enable-predicates) (cl-notany #'(lambda (pred) (if ... ... f)) copilot-disable-predicates)) (progn (copilot-complete)))))
  (if copilot-mode (progn (if (and (symbolp this-command) (s-starts-with-p "copilot-" (symbol-name this-command))) nil (copilot-clear-overlay) (if (and (cl-every #'(lambda ... ...) copilot-enable-predicates) (cl-notany #'(lambda ... ...) copilot-disable-predicates)) (progn (copilot-complete))))))
  (closure (t) nil "Complete in post-command hook." (if copilot-mode (progn (if (and (symbolp this-command) (s-starts-with-p "copilot-" (symbol-name this-command))) nil (copilot-clear-overlay) (if (and (cl-every #'... copilot-enable-predicates) (cl-notany #'... copilot-disable-predicates)) (progn (copilot-complete)))))))()
  ad-Advice-copilot--complete-post-command((closure (t) nil "Complete in post-command hook." (if copilot-mode (progn (if (and (symbolp this-command) (s-starts-with-p "copilot-" (symbol-name this-command))) nil (copilot-clear-overlay) (if (and (cl-every ... copilot-enable-predicates) (cl-notany ... copilot-disable-predicates)) (progn (copilot-complete))))))))
  apply(ad-Advice-copilot--complete-post-command (closure (t) nil "Complete in post-command hook." (if copilot-mode (progn (if (and (symbolp this-command) (s-starts-with-p "copilot-" (symbol-name this-command))) nil (copilot-clear-overlay) (if (and (cl-every ... copilot-enable-predicates) (cl-notany ... copilot-disable-predicates)) (progn (copilot-complete))))))) nil)
  copilot--complete-post-command()

I'm not an emacs-lisp expert and this bulk of code really confuses me... Could you help you solve this? Thanks in advance!

[VitalyAnkh]

I see it's caused by the package annotate.el I use. Removing this package then the error disappears.

But I use annotate.el with copilot.el before and they work well. Why are they not happy with each other now? Could we make them work together?

[zerolfx]

Thank you for the update. I fixed it by reverting to old overlay logic (more details in readme). Can you confirm if the issue is solved?

[jgarte]

Hi, is copilot.el confirmed to work with corfu?

[zerolfx]

Hi, is copilot.el confirmed to work with corfu?

@jgarte Yes. And the good thing is that corfu uses child frames, which provides maximum compatibility.

[jgarte]

OHHH, awesome!