Hey Karsten & Dev team,
I didn't mean to take this off channel, so my apologies for that.
I ran a few more tests this week (and my apologies on the slowness of some of this work - life has been hectic this past month), but I am not finding much of use. I could not find any errors which are not also present in when N23 is disabled. If you want to browse the logs for yourself, I uploaded a partial log from a run to
http://www.charliebelmer.com/scallion.n23.log (730MB).
The most telling entries I found so far are below, but I see the same errors whether UseN23 is set to 1 or not, so it is likely not the root cause. I'll keep digging.
Error 1 (Seems to occur when opening channel):
0:0:49:406270 [thread-2] 0:9:41:348157618 [scallion-info] [4uthority1-73.1.0.0] [scalliontor_logmsg_cb] bw_weights_error_t networkstatus_check_weights(int64_t, int64_t, int64_t, int64_t, int64_t, int64_t, int64_t, int64_t, int64_t, int64_t, int64_t, int64_t, int64_t, int64_t, int)(): Bw weight mismatch 1. G=214 M=12174 E=165 D=27654 T=40207 Wmd=4769 Wme=-724848 Wmg=0 Wed=461 Wee=734848 Wgd=4769 Wgg=10000 Wme=-724848 Wmg=0
0:0:49:407692 [thread-2] 0:9:41:348157618 [scallion-info] [4uthority1-73.1.0.0] [scalliontor_logmsg_cb] bw_weights_error_t networkstatus_check_weights(int64_t, int64_t, int64_t, int64_t, int64_t, int64_t, int64_t, int64_t, int64_t, int64_t, int64_t, int64_t, int64_t, int64_t, int)(): Bw weight mismatch 1. G=214 M=12174 E=165 D=27654 T=40207 Wmd=4769 Wme=-724848 Wmg=0 Wed=461 Wee=734848 Wgd=4769 Wgg=10000 Wme=-724848 Wmg=0
Error 2:
0:0:54:227263 [thread-2] 0:10:55:012000001 [scallion-debug] [4uthority1-73.1.0.0] [scalliontor_logmsg_cb] void conn_read_callback(int, short, void *)(): socket 1000264 wants to read.
0:0:54:227281 [thread-2] 0:10:55:012000001 [scallion-debug] [4uthority1-73.1.0.0] [scalliontor_logmsg_cb] int connection_read_to_buf(connection_t *, ssize_t *, int *)(): 1000264: starting, inbuf_datalen 0 (0 pending in tls object). at_most 16448.
0:0:54:227302 [thread-2] 0:10:55:012000001 [shadow-debug] [4uthority1-73.1.0.0] [_tcp_endOfFileSignalled]
73.1.0.0:10021 (descriptor 1000264) <->
91.1.0.0:9111: signaling close to user, socket no longer usable
0:0:54:227321 [thread-2] 0:10:55:012000001 [scallion-debug] [4uthority1-73.1.0.0] [scalliontor_logmsg_cb] TLS error: unexpected close while reading (SSL negotiation finished successfully)
0:0:54:227338 [thread-2] 0:10:55:012000001 [scallion-debug] [4uthority1-73.1.0.0] [scalliontor_logmsg_cb] int tor_tls_read(tor_tls_t *, char *, size_t)(): read returned r=0, err=-8
0:0:54:227354 [thread-2] 0:10:55:012000001 [scallion-debug] [4uthority1-73.1.0.0] [scalliontor_logmsg_cb] int connection_read_to_buf(connection_t *, ssize_t *, int *)(): TLS connection closed on read. Closing. (Nickname nonexit10, address 91.1.0.0)
0:0:54:227373 [thread-2] 0:10:55:012000001 [scallion-debug] [4uthority1-73.1.0.0] [scalliontor_logmsg_cb] void channel_close_for_error(channel_t *)(): Closing channel 0x7f546d03ce40 due to lower-layer error
0:0:54:227389 [thread-2] 0:10:55:012000001 [scallion-debug] [4uthority1-73.1.0.0] [scalliontor_logmsg_cb] void channel_change_state(channel_t *, channel_state_t)(): Changing state of channel 0x7f546d03ce40 (global ID 21) from "open" to "closing"
0:0:54:227420 [thread-2] 0:10:55:012000001 [scallion-debug] [4uthority1-73.1.0.0] [scalliontor_logmsg_cb] void channel_remove_from_digest_map(channel_t *)(): Removed channel 0x7f546d03ce40 (global ID 21) from identity map in state closing (4) with digest BBF25A366EA5376B0026CE6EDE3DF536211429BE
0:0:54:227440 [thread-2] 0:10:55:012000001 [shadow-debug] [4uthority1-73.1.0.0] [tcp_close]
73.1.0.0:10021 (descriptor 1000264) <->
91.1.0.0:9111: user closed connection
0:0:54:227452 [thread-2] 0:10:55:012000001 [shadow-debug] [4uthority1-73.1.0.0] [_tcp_setState]
73.1.0.0:10021 (descriptor 1000264) <->
91.1.0.0:9111: moved from TCP state 'TCPS_CLOSEWAIT' to 'TCPS_LASTACK'
0:0:54:227473 [thread-2] 0:10:55:012000001 [scallion-debug] [4uthority1-73.1.0.0] [scalliontor_logmsg_cb] void connection_mark_for_close_internal_(connection_t *, int, const char *)(): Calling connection_mark_for_close_internal_() on an OR conn at /home/coffee/shadow/shadow/build/tor/src/or/connection.c:2932
0:0:54:227491 [thread-2] 0:10:55:012000001 [scallion-debug] [4uthority1-73.1.0.0] [scalliontor_logmsg_cb] int conn_close_if_marked(int)(): Cleaning up connection (fd -1).
0:0:54:227509 [thread-2] 0:10:55:012000001 [scallion-debug] [4uthority1-73.1.0.0] [scalliontor_logmsg_cb] void circuit_n_chan_done(channel_t *, int)(): chan to NULL/
91.1.0.0:9111, status=0
0:0:54:227546 [thread-2] 0:10:55:012000001 [scallion-debug] [4uthority1-73.1.0.0] [scalliontor_logmsg_cb] void channel_change_state(channel_t *, channel_state_t)(): Changing state of channel 0x7f546d03ce40 (global ID 21) from "closing" to "channel error"
0:0:54:227565 [thread-2] 0:10:55:012000001 [scallion-debug] [4uthority1-73.1.0.0] [scalliontor_logmsg_cb] int connection_remove(connection_t *)(): removing socket -1 (type OR), n_conns now 26