Sporadic errors in srfi-207 tests

[shirok]

Sporadically, srfi-207-test.scm fails with the following error:

test (%bytestring->SNB test-bstring): expects "#u8\"lorem\"" => got #<<error> "No applicable method for write-object with (#u8(108 111) #t)">

It is perplexing for there seems no randomness involved around the tests. It looks like #t is given as the port argument of write. Couldn't find a path that can cause such a situation.

[shirok]

Nah, 02687aa suppressed the symptom in my local machine but still fails in github actions. Speed or load may be a factor?

[shirok]

• When it happens, it's always in the last test of check-io in srfi-207-test.scm. The exact data that causes the failure vary.
• Isolating that test won't cause the symptom.
• It doesn't seem that a specific code executed prior to the test is a cause. The less is executed, the less chance we observe the failure.
• The last call stack is %write-walk-rec to write-object generic function. At the point of error, port in local env becomes #t. (And the obj argument is somehow always #u8(108 111)).

VM 0x7f2cb45f0c00 -----------------------------------------------------------
   pc: 0x7f2cb50acd80  [  141(0x7f2cb50ac918)] (PRE-CALL(1))
   sp: 0x7f2cb45f23d0  [0x7f2cb45f2000-0x7f2cb45f2000-0x7f2cb4605880]
 argp: 0x7f2cb45f23c0
 val0: #<generic write-object (15)>
 envs:
   0x7f2cb45f2370 (%write-walk-rec obj port tab)
       up=0x7f2cacd42288 size=3
       [ #<hash-table eq? 0x7f2cabc15d20> #t #u8(108 111) ]
   0x7f2cacd42288 #f
       up=(nil) size=1
       [ #<closure ((%write-walk-rec #:G1725) #:G1722)> ]
conts:
   0x7f2cb45f2388
              env = 0x7f2cb45f2370
             size = 0
             base = 0x7f2cb50aa408  %write-walk-rec
               pc = 0x7f2cb50acd80[  141(0x7f2cb50ac918)] (PRE-CALL(1))
   0x7f2cb45f2320::#<prompt-tag "default-prompt-tag">
              env = 0x7f2cb45f22b8
             size = 0
             base = 0x7f2caba6ac60  write-textual-bytestring
               pc = 0x7f2cb51922b0 (RET)
   0x7f2cb45f22d0
              env = 0x7f2cb45f22b8
             size = 0
             base = 0x7f2caba6ac60  write-textual-bytestring
               pc = 0x7f2cabb96780[  240(0x7f2cabb96000)] (PRE-CALL(2))

• However, %write-walk-rec is never called with such argument if we monitor the entry of the function. That suggests the stack is clobbered in some way.
• Another mystery is that, enabling call trace, the immediate call log shows the calls in gauche.vport, related to the output uvector port, whereas write-textual-bytestring does not use it.

Call Trace:
_______________________________________
  0  ((setter getter) #:G39 #:G40 ((cut max <> max-index) (getter  ...
        at "libmacro.scm":834
  1  (uvector-size (%storage-buffer storage))
        at "/home/shiro/src/Gauche/src/../lib/gauche/vport.scm":120
  2  (uvector-size (%storage-buffer storage))
        at "/home/shiro/src/Gauche/src/../lib/gauche/vport.scm":120
  3  (write-textual-bytestring bstring #:G639)
  4  (call-with-output-string (cut write-textual-bytestring bstrin ...
        at "././../../test/include/srfi-207-test.scm":126

[shirok]

It is very unsettling, but it went away. We can't reproduce it anymore, so close this for now.

[shirok]

It started appearing again. Reopening.

[Hamayama]

原因までは分かっていませんが、以下のログが取れたので共有しておきます。

OS : Windows 10 (version 22H2) (64bit)
開発環境 : MSYS2/MinGW-w64 (64bit) (gcc version 13.1.0 (Rev7, Built by MSYS2 project))
Gauche : コミット 3734214 (2023-7-10)

mintty上で実行しました。正常に終了するときもあります。

Gauche は 2023-7-10 のもので少し古いです。

$ gosh test/include/srfi-207-test.scm

;;; Running constructor tests...
Checking (bytestring "lo" #\r 101 #u8(109)), expecting #u8(108 111 114 101 109) => ok
Checking (bytestring), expecting #u8() => ok
Checking (catch-bytestring-error (bytestring 256)), expecting bytestring-error => ok
Checking (catch-bytestring-error (bytestring "λ")), expecting bytestring-error => ok

;;; Running conversion tests...
Checking (bytevector->hex-string test-bstring), expecting "6c6f72656d" => ok
Checking (hex-string->bytevector "6c6f72656d"), expecting #u8(108 111 114 101 109) => ok
Checking (catch-bytestring-error (hex-string->bytevector "c6f72656d")), expecting bytestring-error =
> ok
Checking (catch-bytestring-error (hex-string->bytevector "6czf72656d")), expecting bytestring-error
=> ok
Checking (equal? (hex-string->bytevector (bytevector->hex-string homer)) homer), expecting #t => ok
Checking (hex-string->bytevector (bytevector->hex-string #u8())), expecting #u8() => ok
Checking (bytevector->base64 test-bstring), expecting "bG9yZW0=" => ok
Checking (bytevector->base64 #u8(255 239 255)), expecting "/+//" => ok
Checking (bytevector->base64 #u8(255 239 255) "*@"), expecting "@*@@" => ok
Checking (equal? (bytevector->base64 homer) homer64), expecting #t => ok
Checking (bytevector->base64 #u8(1)), expecting "AQ==" => ok
Checking (bytevector->base64 #u8()), expecting "" => ok
Checking (base64->bytevector "bG9yZW0="), expecting #u8(108 111 114 101 109) => ok
Checking (base64->bytevector "/+//"), expecting #u8(255 239 255) => ok
Checking (base64->bytevector "@*@@" "*@"), expecting #u8(255 239 255) => ok
Checking (equal? (base64->bytevector homer64) homer), expecting #t => ok
Checking (equal? (base64->bytevector homer64-w) homer), expecting #t => ok
Checking (base64->bytevector "AQ=="), expecting #u8(1) => ok
Checking (base64->bytevector ""), expecting #u8() => ok
Checking (base64->bytevector "\n\n\n==\t\r\n"), expecting #u8() => ok
Checking (catch-bytestring-error (base64->bytevector "bG9@frob")), expecting bytestring-error => ok
Checking (bytestring->list #u8()), expecting () => ok
Checking (bytestring->list (bytestring 70 82 0 66)), expecting (#\F #\R 0 #\B) => ok
Checking (bytestring->list (bytestring "\x07;\t\t\n" 200)), expecting (7 9 9 10 200) => ok
Checking (make-bytestring (bytestring->list test-bstring)), expecting #u8(108 111 114 101 109) => ok
Checking (make-bytestring (bytestring->list test-bstring 2)), expecting #u8(114 101 109) => ok
Checking (make-bytestring (bytestring->list test-bstring 1 3)), expecting #u8(111 114) => ok
Checking (begin (make-bytestring! bvec 0 '(108 111 114 101 109)) bvec), expecting #u8(108 111 114 10
1 109) => ok
Checking (begin (make-bytestring! bvec 2 '(*** ERROR: No applicable method for write-object with (#u
8(108 111) #t)
    While loading "./test/include/srfi-207-test.scm" at line 444
Stack Trace:
_______________________________________
  0  (write-object obj port)
  1  (open-input-conversion-port inp fromcode :to-code tocode :buf ...
  2  (ces-convert (x->string str/char) ces2 ces)
        at "C:\\Program Files\\Gauche\\share\\gauche-0.98\\0.9.13_pre4\\lib/os/windows/console/codep
age.scm":187
  3  (string->u8vector (ces-convert (x->string str/char) ces2 ces))
        at "C:\\Program Files\\Gauche\\share\\gauche-0.98\\0.9.13_pre4\\lib/os/windows/console/codep
age.scm":186
  4  (write-uvector (string->u8vector (ces-convert (x->string str/ ...
        at "C:\\Program Files\\Gauche\\share\\gauche-0.98\\0.9.13_pre4\\lib/os/windows/console/codep
age.scm":186
  5  (f argptr port ctrl)
  6  (fmt argptr port ctrl)
  7  #(lvar thunk #f 1 0)
  8  (format #t "Checking ~s, expecting ~s => ok\n" name expected)
        at "C:\\Program Files\\Gauche\\share\\gauche-0.98\\0.9.13_pre4\\lib/srfi/78.scm":95
  9  (do-check *global-results* '(begin (make-bytestring! bvec 2 ' ...
        at "C:\\Program Files\\Gauche\\share\\gauche-0.98\\0.9.13_pre4\\lib/srfi/78.scm":110
        expanded from (check (begin (make-bytestring! bvec 2 '("lo" #\r 101 ...
        at "C:\\Program Files\\Gauche\\share\\gauche-0.98\\0.9.13_pre4\\lib/srfi/78.scm":112
        expanded from (check (begin (make-bytestring! bvec 2 '("lo" #\r 101 ...
        at "./test/include/srfi-207-test.scm":201
 10  (check-conversion)
        at "./test/include/srfi-207-test.scm":433
 11  (eval s #f)
 12  (with-error-handler (lambda (e) (cond (else (let1 e2 (if (con ...
 13  (load-from-port (if ignore-coding port (open-coding-aware-por ...

[shirok]

同じ箇所ですね。アーキテクチャにかかわらず発生するので、ロジックのバグだと思います。#<port> が渡ってくるはずの第二引数が #t になってるんですが、それが起きるパスがどうしても見つけられない。

[Hamayama]

少ししぼり込みました。こちらの環境では、以下のソースでほぼ再現します。

ただ、何回目で発生するかはランダムです。

また、テスト自体は成功しており、そのまま続きのテストを実行していると、
割り込みのような感じでエラーが挙がってくるようです。

＜再現用ソース＞

(import (scheme base))
(import (scheme write))
(import (srfi 207))
(import (srfi 78))

(define-syntax catch-bytestring-error
  (syntax-rules ()
   ((_ expr)
    (guard (condition ((bytestring-error? condition) 'bytestring-error)
                      (else #f))
      expr))))

(let loop ((count 1000))
  (check (catch-bytestring-error
          (base64->bytevector "bG9@frob")) => 'bytestring-error)
  (when (> count 1)
    (loop (- count 1)))))

＜実行結果＞

$ gosh test/include/srfi-207-test.scm
Checking (catch-bytestring-error (base64->bytevector "bG9@frob")), expecting bytestring-error => ok
Checking (catch-bytestring-error (base64->bytevector "bG9@frob")), expecting bytestring-error => ok
Checking (catch-bytestring-error (base64->bytevector "bG9@frob")), expecting bytestring-error => ok
Checking (catch-bytestring-error (base64->bytevector "bG9@frob")), expecting bytestring-error => ok
Checking (catch-bytestring-error (base64->bytevector "bG9@frob")), expecting bytestring-error => ok
Checking (catch-bytestring-error (base64->bytevector "bG9@frob")), expecting bytestring-error => ok
Checking (catch-bytestring-error (base64->bytevector "bG9@frob")), expecting bytestring-error => ok
Checking (catch-bytestring-error (base64->bytevector "bG9@frob")), expecting bytestring-error => ok
Checking (catch-bytestring-error (base64->bytevector "bG9@frob")), expecting bytestring-error => ok
Checking (catch-bytestring-error (base64->bytevector "bG9@frob")), expecting bytestring-error => ok
Checking (catch-bytestring-error (base64->bytevector "bG9@frob")), expecting bytestring-error => ok
Checking (catch-bytestring-error (base64->bytevector "bG9@frob")), expecting bytestring-error => ok
Checking (catch-bytestring-error (base64->bytevector "bG9@frob")), expecting bytestring-error => ok
Checking (catch-bytestring-error (base64->bytevector "bG9@frob")), expecting bytestring-error => ok
Checking (catch-bytestring-error (base64->bytevector "bG9@frob")), expecting bytestring-error => ok
Checking (catch-bytestring-error (base64->bytevector "bG9@frob")), expecting bytestring-error => ok
Checking (catch-bytestring-error (base64->bytevector "bG9@frob")), expecting bytestring-error => ok
Checking (catch-bytestring-error (base64->bytevector "bG9@frob")), expecting bytestring-error*** ERR
OR: No applicable method for write-object with (#u8(108 111) #t)
    While loading "./test/include/srfi-207-test.scm" at line 17
Stack Trace:
_______________________________________
  0  (write-object obj port)
  1  (open-input-conversion-port inp fromcode :to-code tocode :buf ...
  2  (ces-convert (x->string str/char) ces2 ces)
        at "C:\\Program Files\\Gauche\\share\\gauche-0.98\\0.9.13_pre4\\lib/os/windows/console/codep
age.scm":187
  3  (string->u8vector (ces-convert (x->string str/char) ces2 ces))
        at "C:\\Program Files\\Gauche\\share\\gauche-0.98\\0.9.13_pre4\\lib/os/windows/console/codep
age.scm":186
  4  (write-uvector (string->u8vector (ces-convert (x->string str/ ...
        at "C:\\Program Files\\Gauche\\share\\gauche-0.98\\0.9.13_pre4\\lib/os/windows/console/codep
age.scm":186
  5  (f argptr port ctrl)
  6  (fmt argptr port ctrl)
  7  #(lvar thunk #f 1 0)
  8  (format #t "Checking ~s, expecting ~s => ok\n" name expected)
        at "C:\\Program Files\\Gauche\\share\\gauche-0.98\\0.9.13_pre4\\lib/srfi/78.scm":95
  9  (do-check *global-results* '(catch-bytestring-error (base64-> ...
        at "C:\\Program Files\\Gauche\\share\\gauche-0.98\\0.9.13_pre4\\lib/srfi/78.scm":110
        expanded from (check (catch-bytestring-error (base64->bytevector "b"...
        at "C:\\Program Files\\Gauche\\share\\gauche-0.98\\0.9.13_pre4\\lib/srfi/78.scm":112
        expanded from (check (catch-bytestring-error (base64->bytevector "b"...
        at "./test/include/srfi-207-test.scm":14
 10  (eval s #f)
 11  (with-error-handler (lambda (e) (cond (else (let1 e2 (if (con ...
 12  (load-from-port (if ignore-coding port (open-coding-aware-por ...

[Hamayama]

もう少し調べて、gauche.vport のみになりました。

Gauche 0.9.9 でも再現するので、昔からかも。

＜再現用ソース＞

(use gauche.vport)

(let loop ((count 10000))
  (guard (e (else (format #t "~s~%" e)))
    (let ((out (open-output-uvector)))
      (with-output-to-port out
        (lambda ()
          (write-byte  111)
          (write-byte  108)
          (error "TEST-ERROR")
          ))))
  (when (> count 1)
    (loop (- count 1))))

＜実行結果＞

$ gosh test/include/srfi-207-test.scm
#<error "TEST-ERROR">
#<error "TEST-ERROR">
#<error "TEST-ERROR">
#<error "TEST-ERROR">
#<error "TEST-ERROR">
#<error "TEST-ERROR">
#<error "TEST-ERROR">
#<error "TEST-ERROR">
#<error "TEST-ERROR">
#<error "TEST-ERROR">
#<error "TEST-ERROR">
#<error "TEST-ERROR">
#<error "TEST-ERROR">
#<error "TEST-ERROR">
#<error "TEST-ERROR">
#<error "TEST-ERROR">
#<error "TEST-ERROR">
#<error "TEST-ERROR">
#<error "TEST-ERROR">
#<error "TEST-ERROR*** ERROR: No applicable method for write-object with (#u8(111 108) #t)
    While loading "./test/include/srfi-207-test.scm" at line 13
Stack Trace:
_______________________________________
  0  (write-object obj port)
  1  (open-input-conversion-port inp fromcode :to-code tocode :buf ...
  2  (ces-convert (x->string str/char) ces2 ces)
        at "C:\\Program Files\\Gauche\\share\\gauche-0.9Unhandled error occurred during reporting an
 error.  Process aborted.

[shirok]

おお、最後のやつは私の手元でも再現できました。これで捗ります。多謝!

[shirok]

10d5be5 で出るエラーメッセージが変わりますが、エラーの直接原因は同じです。%write-walk-rec のport引数に#tが渡ってくるという。

あと、ファイナライザが関係している可能性があります。上記バグ再現コードで、ループ内で(gc)するようにしたら手元でエラーが出なくなりました。output-uvector-portのゴミがたまってまとめてファイナライズされる時に何か起きてるのかもしれません。ただし、問題のエラーはファイナライザの外で発生します。

[shirok]

OK, we caught it. It's a finalization ordering issue.

When a virtual buffered port is made, a structure struct bport_rec is allocated to hold Scheme handlers and it is set to the port's data field. When the port become unreachable and garbage, the bport_rec structure also becomes garbage (unless it is pointed from elsewhere).

We use unordered mode of the bdwgc's finalizer. That means it is not guaranteed that a heap object pointed from an object being finalized is retained. When a port's finalizer is invoked, it is possible that the object pointed by its data field has already been collected and reused. That's what's happening here.

Finalizers are always a hairy stuff. It should be considered a last resort. All we can do is that vport would check if bport_rec structure is alerady collected, and if so, we just don't do anything. The check can be done using bdwgc's dissapearing link feature, but it's better to have an abstract API instead of directly calling bdwgc's API.