Closed progval closed 3 months ago
Interleaved clients and server logs:
uid=1001 2023-10-03T17:58:50.587719Z INFO sync_task: sable_network::sync::network: No peers available to propagate message 2023-10-03T17:58:50.588581Z DEBUG run:apply_event{event=Event { id: EventId(ServerId(1), EpochId(1696355929), 0), timestamp: 1696355930, clock: EventClock({}), target: Server(ServerId(1)), details: NewServer(NewServer { epoch: EpochId(1696355929), name: ServerName("My.Little.Server"), ts: 1696355930, flags: (empty), version: "sable-0.1.0-dcf8b53cac54f460b86861908d36d67969cf1eb2" }) }}:handle_new_server{entry=HistoryLogEntry { id: 0, timestamp: 1696355930, source_event: EventId(ServerId(1), EpochId(1696355929), 0), details: NewServer(NewServer { server: Server { id: ServerId(1), epoch: EpochId(1696355929), name: ServerName("My.Little.Server"), last_ping: 1696355930, flags: (empty), version: "sable-0.1.0-dcf8b53cac54f460b86861908d36d67969cf1eb2" } }) } detail=NewServer { server: Server { id: ServerId(1), epoch: EpochId(1696355929), name: ServerName("My.Little.Server"), last_ping: 1696355930, flags: (empty), version: "sable-0.1.0-dcf8b53cac54f460b86861908d36d67969cf1eb2" } }}: sable_network::sync::network: enabling peer My.Little.Server 2023-10-03T17:58:50.588804Z INFO sync_task: sable_network::sync::network: No peers available to propagate message 2023-10-03T17:58:50.588865Z TRACE do_run: sable_ircd::server: ...from history_receiver res=Some(NewEntry(0)) 2023-10-03T17:58:50.588957Z TRACE do_run: sable_ircd::server::update_handler: Got history update update=NewEntry(0) 2023-10-03T17:58:50.589007Z TRACE do_run: sable_ircd::server: ...from history_receiver res=Some(NewEntry(1)) 2023-10-03T17:58:50.589032Z TRACE do_run: sable_ircd::server::update_handler: Got history update update=NewEntry(1) 2023-10-03T17:58:50.589096Z TRACE do_run: sable_ircd::server: ...from history_receiver res=Some(NewEntry(2)) 2023-10-03T17:58:50.589124Z TRACE do_run: sable_ircd::server::update_handler: Got history update update=NewEntry(2) 2023-10-03T17:58:50.593977Z TRACE do_run: sable_ircd::server: ...from reap_preclients_timer 2023-10-03T17:58:51.535965Z DEBUG run_communication_task: client_listener::listener_collection: got new connection data=ConnectionData { id: ConnectionId(ListenerId(0), 1), remote_addr: 127.0.0.1, tls_info: None } 2023-10-03T17:58:51.536125Z TRACE do_run: sable_ircd::server: ...from connection_events 2023-10-03T17:58:51.536282Z TRACE do_run:process_connection_event{source=ConnectionId(ListenerId(0), 1)}: sable_ircd::server: Got new connection 2023-10-03T17:58:51.536358Z TRACE do_run:process_connection_event{source=ConnectionId(ListenerId(0), 1)}: sable_ircd::client: Sending to ConnectionId(ListenerId(0), 1): :My.Little.Server NOTICE * :*** Looking up your hostname 2023-10-03T17:58:51.536686Z TRACE do_run: sable_ircd::server: ...from connection_events 2023-10-03T17:58:51.536761Z TRACE do_run:process_connection_event{source=ConnectionId(ListenerId(0), 1)}: sable_ircd::server: Got message msg="QUIT :chkport" 2023-10-03T17:58:51.536920Z TRACE do_run: sable_ircd::client: Sending to ConnectionId(ListenerId(0), 1): ERROR :Client quit 2023-10-03T17:58:51.537034Z TRACE do_run: sable_ircd::server: Got pending CommandAction act=CloseConnection(ConnectionId(ListenerId(0), 1)) 2023-10-03T17:58:51.537073Z TRACE do_run: sable_ircd::connection_collection: Removing connection ConnectionId(ListenerId(0), 1) 2023-10-03T17:58:51.537796Z TRACE do_run: sable_ircd::server: ...from auth_events 2023-10-03T17:58:51.538007Z DEBUG run_communication_task: client_listener::listener_collection: Connection error connection=ConnectionId(ListenerId(0), 1) error=Closed 2023-10-03T17:58:51.538089Z TRACE do_run: sable_ircd::server: ...from connection_events 1696355931.548 1: connects to server. 1696355931.548 2: connects to server. 1696355931.548 2 -> S: NICK sender 1696355931.548 2 -> S: USER username * * :Realname 2023-10-03T17:58:51.548713Z DEBUG run_communication_task: client_listener::listener_collection: got new connection data=ConnectionData { id: ConnectionId(ListenerId(0), 3), remote_addr: 127.0.0.1, tls_info: None } 2023-10-03T17:58:51.548780Z DEBUG run_communication_task: client_listener::listener_collection: got new connection data=ConnectionData { id: ConnectionId(ListenerId(0), 2), remote_addr: 127.0.0.1, tls_info: None } 2023-10-03T17:58:51.548890Z TRACE do_run: sable_ircd::server: ...from connection_events 2023-10-03T17:58:51.548958Z TRACE do_run:process_connection_event{source=ConnectionId(ListenerId(0), 3)}: sable_ircd::server: Got new connection 2023-10-03T17:58:51.548997Z TRACE do_run:process_connection_event{source=ConnectionId(ListenerId(0), 3)}: sable_ircd::client: Sending to ConnectionId(ListenerId(0), 3): :My.Little.Server NOTICE * :*** Looking up your hostname 2023-10-03T17:58:51.549127Z TRACE do_run: sable_ircd::server: ...from connection_events 2023-10-03T17:58:51.549178Z TRACE do_run:process_connection_event{source=ConnectionId(ListenerId(0), 2)}: sable_ircd::server: Got new connection 2023-10-03T17:58:51.549220Z TRACE do_run:process_connection_event{source=ConnectionId(ListenerId(0), 2)}: sable_ircd::client: Sending to ConnectionId(ListenerId(0), 2): :My.Little.Server NOTICE * :*** Looking up your hostname 2023-10-03T17:58:51.549322Z TRACE do_run: sable_ircd::server: ...from connection_events 2023-10-03T17:58:51.549387Z TRACE do_run:process_connection_event{source=ConnectionId(ListenerId(0), 3)}: sable_ircd::server: Got message msg="NICK sender" 2023-10-03T17:58:51.549526Z TRACE do_run: sable_ircd::client: PreClient::can_register self=PreClient { connected_at: Instant { tv_sec: 313, tv_nsec: 820830686 }, user: OnceLock(<uninit>), nick: OnceLock(Nickname("sender")), realname: OnceLock(<uninit>), hostname: OnceLock(<uninit>), sasl_session: OnceLock(<uninit>), sasl_account: OnceLock(<uninit>), progress_flags: 0 } result=false 2023-10-03T17:58:51.549594Z TRACE do_run: sable_ircd::server: ...from async_handlers 2023-10-03T17:58:51.549646Z TRACE do_run: sable_ircd::server: ...from connection_events 2023-10-03T17:58:51.549691Z TRACE do_run:process_connection_event{source=ConnectionId(ListenerId(0), 3)}: sable_ircd::server: Got message msg="USER username * * :Realname" 2023-10-03T17:58:51.549778Z TRACE do_run: sable_ircd::client: PreClient::can_register self=PreClient { connected_at: Instant { tv_sec: 313, tv_nsec: 820830686 }, user: OnceLock(Username("username")), nick: OnceLock(Nickname("sender")), realname: OnceLock(Realname("Realname")), hostname: OnceLock(<uninit>), sasl_session: OnceLock(<uninit>), sasl_account: OnceLock(<uninit>), progress_flags: 0 } result=false 2023-10-03T17:58:51.550542Z TRACE do_run: sable_ircd::server: ...from auth_events 2023-10-03T17:58:51.550587Z TRACE do_run: sable_ircd::server: DNS lookup finished for ConnectionId(ListenerId(0), 3): 127.0.0.1/Some(Hostname("localhost")) 2023-10-03T17:58:51.550626Z TRACE do_run: sable_ircd::client: Sending to ConnectionId(ListenerId(0), 3): :My.Little.Server NOTICE * :*** Found your hostname: localhost 2023-10-03T17:58:51.550674Z TRACE do_run: sable_ircd::client: PreClient::can_register self=PreClient { connected_at: Instant { tv_sec: 313, tv_nsec: 820830686 }, user: OnceLock(Username("username")), nick: OnceLock(Nickname("sender")), realname: OnceLock(Realname("Realname")), hostname: OnceLock(Hostname("localhost")), sasl_session: OnceLock(<uninit>), sasl_account: OnceLock(<uninit>), progress_flags: 0 } result=true 2023-10-03T17:58:51.550724Z TRACE do_run: sable_ircd::server: Got pending CommandAction act=RegisterClient(ConnectionId(ListenerId(0), 3)) 2023-10-03T17:58:51.550911Z INFO sync_task: sable_network::sync::network: No peers available to propagate message 2023-10-03T17:58:51.551310Z TRACE do_run: sable_ircd::server: ...from history_receiver res=Some(NewEntry(3)) 2023-10-03T17:58:51.551346Z TRACE do_run: sable_ircd::server::update_handler: Got history update update=NewEntry(3) 2023-10-03T17:58:51.551421Z TRACE do_run: sable_ircd::client: Sending to ConnectionId(ListenerId(0), 3): :My.Little.Server 001 sender :Welcome to the test Internet Relay Chat network, sender 2023-10-03T17:58:51.551479Z TRACE do_run: sable_ircd::client: Sending to ConnectionId(ListenerId(0), 3): :My.Little.Server 002 sender :Your host is My.Little.Server, running version sable-0.1.0-dcf8b53cac54f460b86861908d36d67969cf1eb2 2023-10-03T17:58:51.551556Z TRACE do_run: sable_ircd::client: Sending to ConnectionId(ListenerId(0), 3): :My.Little.Server 003 sender :This server was created 2023-10-03 17:58:51.551503601 UTC 2023-10-03T17:58:51.551589Z TRACE do_run: sable_ircd::client: Sending to ConnectionId(ListenerId(0), 3): :My.Little.Server 004 sender My.Little.Server sable-0.1.0-dcf8b53cac54f460b86861908d36d67969cf1eb2 ioZ ntsim bqeIkov 2023-10-03T17:58:51.551638Z TRACE do_run: sable_ircd::client: Sending to ConnectionId(ListenerId(0), 3): :My.Little.Server 005 sender EXCEPTS INVEX FNC CASEMAPPING=ascii HOSTLEN=64 NICKLEN=15 USERLEN=10 CHANMODES=bqeI,k,,ntsim PREFIX=(ov)@+ :are supported by this server 2023-10-03T17:58:51.551681Z TRACE do_run: sable_ircd::client: Sending to ConnectionId(ListenerId(0), 3): :My.Little.Server 422 sender :MOTD File is missing 2023-10-03T17:58:51.551714Z TRACE do_run: sable_ircd::client: Sending to ConnectionId(ListenerId(0), 3): :sender!username@localhost MODE sender + 2023-10-03T17:58:51.551740Z TRACE do_run: sable_ircd::client: Sending to ConnectionId(ListenerId(0), 3): :My.Little.Server NOTICE sender :The network is currently running in debug mode. Do not send any sensitive information such as passwords. 2023-10-03T17:58:51.551785Z TRACE do_run: sable_ircd::server: ...from history_receiver res=Some(NewEntry(4)) 2023-10-03T17:58:51.551809Z TRACE do_run: sable_ircd::server::update_handler: Got history update update=NewEntry(4) 1696355931.552 S -> 2: :My.Little.Server NOTICE * :*** Looking up your hostname 1696355931.553 S -> 2: :My.Little.Server NOTICE * :*** Found your hostname: localhost 1696355931.553 S -> 2: :My.Little.Server 001 sender :Welcome to the test Internet Relay Chat network, sender 1696355931.553 S -> 2: :My.Little.Server 002 sender :Your host is My.Little.Server, running version sable-0.1.0-dcf8b53cac54f460b86861908d36d67969cf1eb2 1696355931.553 S -> 2: :My.Little.Server 003 sender :This server was created 2023-10-03 17:58:51.551503601 UTC 1696355931.553 S -> 2: :My.Little.Server 004 sender My.Little.Server sable-0.1.0-dcf8b53cac54f460b86861908d36d67969cf1eb2 ioZ ntsim bqeIkov 1696355931.553 S -> 2: :My.Little.Server 005 sender EXCEPTS INVEX FNC CASEMAPPING=ascii HOSTLEN=64 NICKLEN=15 USERLEN=10 CHANMODES=bqeI,k,,ntsim PREFIX=(ov)@+ :are supported by this server 1696355931.553 S -> 2: :My.Little.Server 422 sender :MOTD File is missing 1696355931.553 S -> 2: :sender!username@localhost MODE sender + 1696355931.553 S -> 2: :My.Little.Server NOTICE sender :The network is currently running in debug mode. Do not send any sensitive information such as passwords. 1696355931.553 2 -> S: PING foo 2023-10-03T17:58:51.553070Z TRACE do_run: sable_ircd::server: ...from connection_events 2023-10-03T17:58:51.553130Z TRACE do_run:process_connection_event{source=ConnectionId(ListenerId(0), 3)}: sable_ircd::server: Got message msg="PING foo" 2023-10-03T17:58:51.553229Z TRACE do_run: sable_ircd::client: Sending to ConnectionId(ListenerId(0), 3): :My.Little.Server PONG My.Little.Server :foo 1696355932.357 2 -> S: PING synchronize314.628550171 1696355932.357 S -> 2: :My.Little.Server PONG My.Little.Server :foo 2023-10-03T17:58:52.359207Z TRACE do_run: sable_ircd::server: ...from connection_events 2023-10-03T17:58:52.359295Z TRACE do_run:process_connection_event{source=ConnectionId(ListenerId(0), 3)}: sable_ircd::server: Got message msg="PING synchronize314.628550171" 2023-10-03T17:58:52.359443Z TRACE do_run: sable_ircd::client: Sending to ConnectionId(ListenerId(0), 3): :My.Little.Server PONG My.Little.Server :synchronize314.628550171 1696355932.362 S -> 2: :My.Little.Server PONG My.Little.Server :synchronize314.628550171 1696355932.362 1 -> S: CAP LS 302 1696355932.362 S -> 1: :My.Little.Server NOTICE * :*** Looking up your hostname 2023-10-03T17:58:52.362407Z TRACE do_run: sable_ircd::server: ...from connection_events 2023-10-03T17:58:52.362508Z TRACE do_run:process_connection_event{source=ConnectionId(ListenerId(0), 2)}: sable_ircd::server: Got message msg="CAP LS 302" 2023-10-03T17:58:52.362664Z TRACE do_run: sable_ircd::client: Sending to ConnectionId(ListenerId(0), 2): :My.Little.Server CAP * LS :server-time echo-message batch labeled-response userhost-in-names away-notify account-tag draft/chathistory sable.libera.chat/persistent-session draft/account-registration draft/channel-rename 1696355932.363 S -> 1: :My.Little.Server CAP * LS :server-time echo-message batch labeled-response userhost-in-names away-notify account-tag draft/chathistory sable.libera.chat/persistent-session draft/account-registration draft/channel-rename 1696355932.363 1 -> S: CAP REQ :echo-message server-time 1696355932.363 1 -> S: nick bar 1696355932.363 1 -> S: user user 0 * realname 1696355932.363 1 -> S: CAP END 2023-10-03T17:58:52.363581Z TRACE do_run: sable_ircd::server: ...from connection_events 2023-10-03T17:58:52.363638Z TRACE do_run:process_connection_event{source=ConnectionId(ListenerId(0), 2)}: sable_ircd::server: Got message msg="CAP REQ :echo-message server-time" 2023-10-03T17:58:52.363808Z TRACE do_run: sable_ircd::client: Sending to ConnectionId(ListenerId(0), 2): :My.Little.Server CAP * ACK :echo-message server-time 2023-10-03T17:58:52.363856Z TRACE do_run: sable_ircd::server: Got pending CommandAction act=UpdateConnectionCaps(ConnectionId(ListenerId(0), 2), ClientCapabilitySet(6)) 2023-10-03T17:58:52.363907Z TRACE do_run: sable_ircd::server: ...from connection_events 2023-10-03T17:58:52.363960Z TRACE do_run:process_connection_event{source=ConnectionId(ListenerId(0), 2)}: sable_ircd::server: Got message msg="nick bar" 2023-10-03T17:58:52.364277Z TRACE do_run: sable_ircd::client: PreClient::can_register self=PreClient { connected_at: Instant { tv_sec: 313, tv_nsec: 821049387 }, user: OnceLock(<uninit>), nick: OnceLock(Nickname("bar")), realname: OnceLock(<uninit>), hostname: OnceLock(<uninit>), sasl_session: OnceLock(<uninit>), sasl_account: OnceLock(<uninit>), progress_flags: 1 } result=false 2023-10-03T17:58:52.364342Z TRACE do_run: sable_ircd::server: ...from async_handlers 2023-10-03T17:58:52.364391Z TRACE do_run: sable_ircd::server: ...from connection_events 2023-10-03T17:58:52.364439Z TRACE do_run:process_connection_event{source=ConnectionId(ListenerId(0), 2)}: sable_ircd::server: Got message msg="user user 0 * realname" 2023-10-03T17:58:52.364820Z TRACE do_run: sable_ircd::client: PreClient::can_register self=PreClient { connected_at: Instant { tv_sec: 313, tv_nsec: 821049387 }, user: OnceLock(Username("user")), nick: OnceLock(Nickname("bar")), realname: OnceLock(Realname("realname")), hostname: OnceLock(<uninit>), sasl_session: OnceLock(<uninit>), sasl_account: OnceLock(<uninit>), progress_flags: 1 } result=false 2023-10-03T17:58:52.364906Z TRACE do_run: sable_ircd::server: ...from connection_events 2023-10-03T17:58:52.364957Z TRACE do_run:process_connection_event{source=ConnectionId(ListenerId(0), 2)}: sable_ircd::server: Got message msg="CAP END" 1696355932.368 S -> 1: :My.Little.Server CAP * ACK :echo-message server-time 2023-10-03T17:58:53.118337Z TRACE do_run: sable_ircd::client: PreClient::complete_progress self=PreClient { connected_at: Instant { tv_sec: 313, tv_nsec: 821049387 }, user: OnceLock(Username("user")), nick: OnceLock(Nickname("bar")), realname: OnceLock(Realname("realname")), hostname: OnceLock(<uninit>), sasl_session: OnceLock(<uninit>), sasl_account: OnceLock(<uninit>), progress_flags: 0 } flag=CapNegotiation result=false 1696355933.368 1: waiting… 1696355934.369 1: waiting… 1696355935.370 1: waiting… 1696355936.371 1: waiting… 1696355937.372 1: waiting… 1696355938.373 1: waiting… 1696355939.374 1: waiting… 1696355940.375 1: waiting… 1696355941.377 1: waiting… 1696355942.378 1: waiting… 1696355943.379 1: waiting… 1696355944.381 1: waiting… 1696355945.382 1: waiting… 1696355946.384 1: waiting… 1696355947.384 1: waiting… 1696355948.385 1: waiting… 1696355949.386 1: waiting… 1696355950.388 1: waiting… 1696355951.388 1: waiting… 1696355952.389 1: waiting… 1696355953.390 1: waiting… 1696355954.391 1: waiting… 1696355955.393 1: waiting… 1696355956.394 1: waiting… 1696355957.397 1: waiting… 1696355958.398 1: waiting… 1696355959.399 1: waiting… 1696355960.400 1: waiting… 1696355961.402 1: waiting… 1696355962.403 1: waiting… 1696355963.404 1: waiting… 1696355964.406 1: waiting… 1696355965.407 1: waiting… 1696355966.408 1: waiting… 1696355967.409 1: waiting… 1696355968.410 1: waiting… 1696355969.412 1: waiting… 1696355970.412 1: waiting… 1696355971.413 1: waiting… 1696355972.414 1: waiting… 1696355973.415 1: waiting… 1696355974.416 1: waiting… 1696355975.416 1: waiting… 1696355976.417 1: waiting… 1696355977.418 1: waiting… 1696355978.420 1: waiting… 1696355979.421 1: waiting… 1696355980.422 1: waiting… 1696355981.423 1: waiting… 1696355982.424 1: waiting… 1696355983.424 1: waiting… 1696355984.425 1: waiting… 1696355985.426 1: waiting… 1696355986.428 1: waiting… 1696355987.428 1: waiting… 1696355988.429 1: waiting… 1696355989.431 1: waiting… 1696355990.432 1: waiting… 2023-10-03T17:59:50.588555Z INFO sync_task: sable_network::sync::network: No peers available to propagate message 2023-10-03T17:59:50.589050Z TRACE do_run: sable_ircd::server: ...from history_receiver res=Some(NewEntry(5)) 2023-10-03T17:59:50.589086Z TRACE do_run: sable_ircd::server::update_handler: Got history update update=NewEntry(5) 2023-10-03T17:59:50.590089Z TRACE do_run: sable_ircd::server: ...from reap_preclients_timer 1696355991.432 1: waiting… 1696355992.433 1: waiting… 1696355993.435 1: waiting… 1696355994.436 1: waiting… 1696355995.437 1: waiting… 1696355996.438 1: waiting… 1696355997.439 1: waiting… 1696355998.440 1: waiting… 1696355999.442 1: waiting… 1696356000.443 1: waiting… 1696356001.444 1: waiting… 1696356002.445 1: waiting… 1696356003.447 1: waiting… 1696356004.448 1: waiting… 1696356005.448 1: waiting… 1696356006.450 1: waiting… 1696356007.451 1: waiting… 1696356008.451 1: waiting… 1696356009.453 1: waiting… 1696356010.454 1: waiting… 1696356011.455 1: waiting… 1696356012.456 1: waiting… 1696356013.457 1: waiting… 1696356014.459 1: waiting… 1696356015.460 1: waiting… 1696356016.461 1: waiting… 1696356017.462 1: waiting… 1696356018.463 1: waiting… 1696356019.465 1: waiting… 1696356020.465 1: waiting… 1696356021.466 1: waiting… 1696356022.467 1: waiting… 1696356023.469 1: waiting… 1696356024.470 1: waiting… 1696356025.471 1: waiting… 1696356026.472 1: waiting… 1696356027.473 1: waiting… 1696356028.475 1: waiting… 1696356029.476 1: waiting… 1696356030.477 1: waiting… 1696356031.478 1: waiting… 1696356032.479 1: waiting… 1696356033.481 1: waiting… 1696356034.482 1: waiting… 1696356035.483 1: waiting… 1696356036.484 1: waiting… 1696356037.486 1: waiting… 1696356038.487 1: waiting… 1696356039.488 1: waiting… 1696356040.489 1: waiting… 1696356041.490 1: waiting… 1696356042.491 1: waiting… 1696356043.493 1: waiting… 1696356044.494 1: waiting… 1696356045.495 1: waiting… 1696356046.496 1: waiting… 1696356047.497 1: waiting… 1696356048.498 1: waiting… 1696356049.500 1: waiting… 1696356050.501 1: waiting… 2023-10-03T18:00:50.588767Z INFO sync_task: sable_network::sync::network: No peers available to propagate message 2023-10-03T18:00:50.589271Z TRACE do_run: sable_ircd::server: ...from history_receiver res=Some(NewEntry(6)) 2023-10-03T18:00:50.589311Z TRACE do_run: sable_ircd::server::update_handler: Got history update update=NewEntry(6) 2023-10-03T18:00:50.590290Z TRACE do_run: sable_ircd::server: ...from reap_preclients_timer 1696356051.502 1: waiting… 1696356052.503 1: waiting… 1696356053.504 1: waiting… 1696356054.505 1: waiting… 1696356055.506 1: waiting… 1696356056.507 1: waiting… 1696356057.508 1: waiting… 1696356058.510 1: waiting… 1696356059.511 1: waiting… 1696356060.512 1: waiting… 1696356061.513 1: waiting… 1696356062.514 1: waiting… 1696356063.516 1: waiting… 1696356064.517 1: waiting… 1696356065.518 1: waiting… 1696356066.519 1: waiting… 1696356067.520 1: waiting… 1696356068.522 1: waiting… 1696356069.523 1: waiting… 1696356070.524 1: waiting… 1696356071.525 1: waiting… 1696356072.526 1: waiting… 1696356073.528 1: waiting… 1696356074.529 1: waiting… 1696356075.530 1: waiting… 1696356076.531 1: waiting… 1696356077.533 1: waiting… 1696356078.534 1: waiting… 1696356079.535 1: waiting… 1696356080.536 1: waiting… 1696356081.537 1: waiting… 1696356082.539 1: waiting… 1696356083.540 1: waiting… 1696356084.541 1: waiting… 1696356085.542 1: waiting… 1696356086.543 1: waiting… 1696356087.545 1: waiting… 1696356088.546 1: waiting… 1696356089.547 1: waiting… 1696356090.548 1: waiting… 1696356091.549 1: waiting… 1696356092.551 1: waiting… 1696356093.552 1: waiting… 1696356094.553 1: waiting… 1696356095.554 1: waiting… 1696356096.555 1: waiting… 1696356097.557 1: waiting… 1696356098.558 1: waiting… 1696356099.559 1: waiting… 1696356100.560 1: waiting… 1696356101.562 1: waiting… 1696356102.563 1: waiting… 1696356103.564 1: waiting… 1696356104.565 1: waiting… 1696356105.567 1: waiting… 1696356106.568 1: waiting… 1696356107.568 1: waiting… 1696356108.570 1: waiting… 1696356109.571 1: waiting… 1696356110.572 1: waiting… 2023-10-03T18:01:50.589090Z INFO sync_task: sable_network::sync::network: No peers available to propagate message 2023-10-03T18:01:50.589600Z TRACE do_run: sable_ircd::server: ...from history_receiver res=Some(NewEntry(7)) 2023-10-03T18:01:50.589656Z TRACE do_run: sable_ircd::server::update_handler: Got history update update=NewEntry(7) 2023-10-03T18:01:50.590553Z TRACE do_run: sable_ircd::server: ...from reap_preclients_timer 2023-10-03T18:01:50.590712Z DEBUG reap_preclients: sable_ircd::server: ConnectionId(ListenerId(0), 2) registration timed out 2023-10-03T18:01:50.590757Z TRACE reap_preclients: sable_ircd::client: Sending to ConnectionId(ListenerId(0), 2): ERROR :Registration timed out 1696356110.591 S -> 1: ERROR :Registration timed out 2023-10-03T18:01:50.841824Z TRACE do_run: sable_ircd::server: Got pending CommandAction act=CloseConnection(ConnectionId(ListenerId(0), 2)) 2023-10-03T18:01:50.841917Z TRACE do_run: sable_ircd::connection_collection: Removing connection ConnectionId(ListenerId(0), 2) 2023-10-03T18:01:50.842769Z DEBUG run_communication_task: client_listener::listener_collection: Connection error connection=ConnectionId(ListenerId(0), 2) error=Closed 2023-10-03T18:01:50.842891Z TRACE do_run: sable_ircd::server: ...from connection_events
Given that the last line before hanging is:
2023-10-03T17:58:53.118337Z TRACE do_run: sable_ircd::client: PreClient::complete_progress self=PreClient { connected_at: Instant { tv_sec: 313, tv_nsec: 821049387 }, user: OnceLock(Username("user")), nick: OnceLock(Nickname("bar")), realname: OnceLock(Realname("realname")), hostname: OnceLock(), sasl_session: OnceLock(), sasl_account: OnceLock(), progress_flags: 0 } flag=CapNegotiation result=false
it looks like Sable never manages to resolve the hostname or abort the resolution
Not happening anymore
progval
commented
3 months ago progval
commented
3 months ago
Interleaved clients and server logs:
Given that the last line before hanging is:
it looks like Sable never manages to resolve the hostname or abort the resolution