WVMQWENWS_6D91C42F
source=WEBVM
time=2026-11-08T06:16:19+00:00
stage=PI_WRAPPER_FINISHED
[2026-11-08T06:11:57+00:00] PI_WRAPPER_STARTED tag=WVMQWENWS_6D91C42F script=pi.py
[2026-11-08T06:12:10+00:00] PI_IMPL_FETCHED source=main characters=37335
[2026-11-08T06:12:11+00:00] booting.
[2026-11-08T06:12:11+00:00] booting..
[2026-11-08T06:12:13+00:00] IO_LOOP_SOURCE_FETCHED file=controller.py attempt=1/10 characters=35203
[2026-11-08T06:12:14+00:00] IO_LOOP_SOURCE_FETCHED file=agent.py attempt=1/10 characters=10376
[2026-11-08T06:12:15+00:00] IO_LOOP_SOURCE_FETCHED file=tcp_socks5.py attempt=1/10 characters=19593
[2026-11-08T06:12:15+00:00] RX_TX_PROOF_SKIPPED already_validated=1 override=WEBVM_RUN_RX_TX_PROOF=1
[2026-11-08T06:12:15+00:00] TCP_LINK_CONTROLLER_START kernel_id=simonday/webvm-tcp-link
[2026-11-08T06:12:19+00:00] IO_LOOP_CONTROLLER {"dataset_id": "simonday/webvm-io-loop-rx", "event": "RUN_BEGIN", "kernel_id": "simonday/webvm-tcp-link", "poll_seconds": 10, "time": "2026-11-08T06:12:18.899+00:00", "timeout_seconds": 900}
[2026-11-08T06:12:19+00:00] IO_LOOP_CONTROLLER {"attempt": "configured_environment", "command": ["kaggle", "kernels", "status", "simonday/webvm-tcp-link"], "event": "API_REQUEST_START", "proxy_vars_removed": false, "time": "2026-11-08T06:12:18.912+00:00", "timeout_seconds": 20}
[2026-11-08T06:12:40+00:00] IO_LOOP_CONTROLLER {"attempt": "configured_environment", "command": ["kaggle", "kernels", "status", "simonday/webvm-tcp-link"], "duration_ms": 21472.44, "event": "API_REQUEST_TIMEOUT", "output_tail": "", "time": "2026-11-08T06:12:40.393+00:00"}
[2026-11-08T06:12:40+00:00] IO_LOOP_CONTROLLER {"attempt": "proxy_bypass", "command": ["kaggle", "kernels", "status", "simonday/webvm-tcp-link"], "event": "API_REQUEST_START", "proxy_vars_removed": true, "time": "2026-11-08T06:12:40.398+00:00", "timeout_seconds": 20}
[2026-11-08T06:13:00+00:00] IO_LOOP_CONTROLLER {"attempt": "proxy_bypass", "command": ["kaggle", "kernels", "status", "simonday/webvm-tcp-link"], "duration_ms": 20335.88, "event": "API_REQUEST_TIMEOUT", "output_tail": "", "time": "2026-11-08T06:13:00.735+00:00"}
[2026-11-08T06:13:00+00:00] IO_LOOP_CONTROLLER {"attempts": 2, "command": ["kaggle", "kernels", "status", "simonday/webvm-tcp-link"], "elapsed_ms": 41831.136, "event": "API_REQUEST_EXHAUSTED", "read_only": true, "reason": "all permitted attempts timed out", "time": "2026-11-08T06:13:00.742+00:00"}
[2026-11-08T06:13:00+00:00] IO_LOOP_CONTROLLER {"error": "Kaggle read-only API command timed out in configured and proxy-bypass attempts: kaggle kernels status simonday/webvm-tcp-link", "event": "TCP_LINK_PREDEPLOY_STATUS_UNKNOWN", "kernel_id": "simonday/webvm-tcp-link", "note": "Continuing with the explicit deployment request", "time": "2026-11-08T06:13:00.745+00:00"}
[2026-11-08T06:13:01+00:00] IO_LOOP_CONTROLLER {"event": "POC_FILES_WRITTEN", "notebook_bytes": 33344, "service": "tailscale-serve-tcp-to-http-connect-socks5", "time": "2026-11-08T06:13:01.518+00:00"}
[2026-11-08T06:13:01+00:00] IO_LOOP_CONTROLLER {"attempt": "configured_environment", "command": ["kaggle", "kernels", "push", "-p", "/home/user/kaggle-tcp-link-run/kernel"], "event": "API_REQUEST_START", "proxy_vars_removed": false, "time": "2026-11-08T06:13:01.524+00:00", "timeout_seconds": 300}
[2026-11-08T06:13:38+00:00] IO_LOOP_CONTROLLER {"attempt": "configured_environment", "command": ["kaggle", "kernels", "push", "-p", "/home/user/kaggle-tcp-link-run/kernel"], "duration_ms": 36638.274, "event": "API_REQUEST_RESULT", "exit_code": 0, "output_tail": "Kernel version 6 successfully pushed.  Please check progress at https://www.kaggle.com/code/simonday/webvm-tcp-link\n", "time": "2026-11-08T06:13:38.163+00:00"}
[2026-11-08T06:13:45+00:00] IO_LOOP_CONTROLLER {"event": "KERNEL_SUBMITTED", "kernel_id": "simonday/webvm-tcp-link", "time": "2026-11-08T06:13:38.170+00:00"}
[2026-11-08T06:13:45+00:00] IO_LOOP_CONTROLLER {"event": "TCP_LINK_KERNEL_SUBMITTED", "kernel_id": "simonday/webvm-tcp-link", "local_port": 8889, "service": "tailscale-serve-tcp-to-http-connect-socks5", "tailnet_port": 18088, "time": "2026-11-08T06:13:38.172+00:00", "wait_for_completion": false}
[2026-11-08T06:13:45+00:00] TCP_LINK_KERNEL_SUBMITTED kernel_id=simonday/webvm-tcp-link local_port=8889 tailnet_port=18088
[2026-11-08T06:13:45+00:00] IO_LOOP_CONTROLLER {"attempt": "configured_environment", "command": ["kaggle", "kernels", "status", "simonday/webvm-tcp-link"], "event": "API_REQUEST_START", "proxy_vars_removed": false, "time": "2026-11-08T06:13:38.178+00:00", "timeout_seconds": 15}
[2026-11-08T06:13:54+00:00] IO_LOOP_CONTROLLER {"attempt": "configured_environment", "command": ["kaggle", "kernels", "status", "simonday/webvm-tcp-link"], "duration_ms": 16042.844, "event": "API_REQUEST_TIMEOUT", "output_tail": "", "time": "2026-11-08T06:13:54.223+00:00"}
[2026-11-08T06:13:54+00:00] IO_LOOP_CONTROLLER {"attempt": "proxy_bypass", "command": ["kaggle", "kernels", "status", "simonday/webvm-tcp-link"], "event": "API_REQUEST_START", "proxy_vars_removed": true, "time": "2026-11-08T06:13:54.229+00:00", "timeout_seconds": 15}
[2026-11-08T06:14:10+00:00] IO_LOOP_CONTROLLER {"attempt": "proxy_bypass", "command": ["kaggle", "kernels", "status", "simonday/webvm-tcp-link"], "duration_ms": 15643.295, "event": "API_REQUEST_TIMEOUT", "output_tail": "", "time": "2026-11-08T06:14:09.884+00:00"}
[2026-11-08T06:14:10+00:00] IO_LOOP_CONTROLLER {"attempts": 2, "command": ["kaggle", "kernels", "status", "simonday/webvm-tcp-link"], "elapsed_ms": 31938.41, "event": "API_REQUEST_EXHAUSTED", "read_only": true, "reason": "all permitted attempts timed out", "time": "2026-11-08T06:14:10.115+00:00"}
[2026-11-08T06:14:10+00:00] IO_LOOP_CONTROLLER {"error": "Kaggle read-only API command timed out in configured and proxy-bypass attempts: kaggle kernels status simonday/webvm-tcp-link", "event": "TCP_LINK_STATUS_POLL_TIMEOUT", "kernel_id": "simonday/webvm-tcp-link", "note": "Retrying until the startup deadline instead of aborting the controller", "time": "2026-11-08T06:14:10.120+00:00", "waited_seconds": 31.9}
[2026-11-08T06:14:15+00:00] IO_LOOP_CONTROLLER {"attempt": "configured_environment", "command": ["kaggle", "kernels", "status", "simonday/webvm-tcp-link"], "event": "API_REQUEST_START", "proxy_vars_removed": false, "time": "2026-11-08T06:14:15.144+00:00", "timeout_seconds": 15}
[2026-11-08T06:14:30+00:00] IO_LOOP_CONTROLLER {"attempt": "configured_environment", "command": ["kaggle", "kernels", "status", "simonday/webvm-tcp-link"], "duration_ms": 15253.404, "event": "API_REQUEST_TIMEOUT", "output_tail": "", "time": "2026-11-08T06:14:30.399+00:00"}
[2026-11-08T06:14:30+00:00] IO_LOOP_CONTROLLER {"attempt": "proxy_bypass", "command": ["kaggle", "kernels", "status", "simonday/webvm-tcp-link"], "event": "API_REQUEST_START", "proxy_vars_removed": true, "time": "2026-11-08T06:14:30.406+00:00", "timeout_seconds": 15}
[2026-11-08T06:14:45+00:00] IO_LOOP_CONTROLLER {"attempt": "proxy_bypass", "command": ["kaggle", "kernels", "status", "simonday/webvm-tcp-link"], "duration_ms": 15255.886, "event": "API_REQUEST_TIMEOUT", "output_tail": "", "time": "2026-11-08T06:14:45.674+00:00"}
[2026-11-08T06:14:48+00:00] IO_LOOP_CONTROLLER {"attempts": 2, "command": ["kaggle", "kernels", "status", "simonday/webvm-tcp-link"], "elapsed_ms": 30564.366, "event": "API_REQUEST_EXHAUSTED", "read_only": true, "reason": "all permitted attempts timed out", "time": "2026-11-08T06:14:45.694+00:00"}
[2026-11-08T06:14:48+00:00] IO_LOOP_CONTROLLER {"error": "Kaggle read-only API command timed out in configured and proxy-bypass attempts: kaggle kernels status simonday/webvm-tcp-link", "event": "TCP_LINK_STATUS_POLL_TIMEOUT", "kernel_id": "simonday/webvm-tcp-link", "note": "Retrying until the startup deadline instead of aborting the controller", "time": "2026-11-08T06:14:45.698+00:00", "waited_seconds": 67.5}
[2026-11-08T06:14:50+00:00] IO_LOOP_CONTROLLER {"attempt": "configured_environment", "command": ["kaggle", "kernels", "status", "simonday/webvm-tcp-link"], "event": "API_REQUEST_START", "proxy_vars_removed": false, "time": "2026-11-08T06:14:50.716+00:00", "timeout_seconds": 15}
[2026-11-08T06:15:06+00:00] IO_LOOP_CONTROLLER {"attempt": "configured_environment", "command": ["kaggle", "kernels", "status", "simonday/webvm-tcp-link"], "duration_ms": 15265.785, "event": "API_REQUEST_TIMEOUT", "output_tail": "", "time": "2026-11-08T06:15:05.984+00:00"}
[2026-11-08T06:15:06+00:00] IO_LOOP_CONTROLLER {"attempt": "proxy_bypass", "command": ["kaggle", "kernels", "status", "simonday/webvm-tcp-link"], "event": "API_REQUEST_START", "proxy_vars_removed": true, "time": "2026-11-08T06:15:05.994+00:00", "timeout_seconds": 15}
[2026-11-08T06:15:21+00:00] IO_LOOP_CONTROLLER {"attempt": "proxy_bypass", "command": ["kaggle", "kernels", "status", "simonday/webvm-tcp-link"], "duration_ms": 15322.826, "event": "API_REQUEST_TIMEOUT", "output_tail": "", "time": "2026-11-08T06:15:21.329+00:00"}
[2026-11-08T06:15:21+00:00] IO_LOOP_CONTROLLER {"attempts": 2, "command": ["kaggle", "kernels", "status", "simonday/webvm-tcp-link"], "elapsed_ms": 30667.495, "event": "API_REQUEST_EXHAUSTED", "read_only": true, "reason": "all permitted attempts timed out", "time": "2026-11-08T06:15:21.376+00:00"}
[2026-11-08T06:15:21+00:00] IO_LOOP_CONTROLLER {"error": "Kaggle read-only API command timed out in configured and proxy-bypass attempts: kaggle kernels status simonday/webvm-tcp-link", "event": "TCP_LINK_STATUS_POLL_TIMEOUT", "kernel_id": "simonday/webvm-tcp-link", "note": "Retrying until the startup deadline instead of aborting the controller", "time": "2026-11-08T06:15:21.383+00:00", "waited_seconds": 103.2}
[2026-11-08T06:15:26+00:00] IO_LOOP_CONTROLLER {"event": "TCP_LINK_STARTUP_PENDING", "kernel_id": "simonday/webvm-tcp-link", "status_tail": "", "time": "2026-11-08T06:15:26.396+00:00", "waited_seconds": 108.2}
[2026-11-08T06:15:26+00:00] TCP_LINK_STARTUP_PENDING kernel_id=simonday/webvm-tcp-link
[2026-11-08T06:15:26+00:00] IO_LOOP_CONTROLLER {"attempt": "configured_environment", "command": ["kaggle", "kernels", "output", "simonday/webvm-tcp-link", "-p", "/home/user/kaggle-tcp-link-run/output/tcp_link_status_pending", "-o", "--file-pattern", "^tcp_link_status\\\\.json$"], "event": "API_REQUEST_START", "proxy_vars_removed": false, "time": "2026-11-08T06:15:26.420+00:00", "timeout_seconds": 45}
[2026-11-08T06:15:53+00:00] IO_LOOP_CONTROLLER {"attempt": "configured_environment", "command": ["kaggle", "kernels", "output", "simonday/webvm-tcp-link", "-p", "/home/user/kaggle-tcp-link-run/output/tcp_link_status_pending", "-o", "--file-pattern", "^tcp_link_status\\\\.json$"], "duration_ms": 26515.225, "event": "API_REQUEST_RESULT", "exit_code": 0, "output_tail": "Kernel log downloaded to /home/user/kaggle-tcp-link-run/output/tcp_link_status_pending/webvm-tcp-link.log \n", "time": "2026-11-08T06:15:52.936+00:00"}
[2026-11-08T06:15:57+00:00] IO_LOOP_CONTROLLER {"event": "TCP_LINK_PENDING_ARTIFACT_MISSING", "kernel_id": "simonday/webvm-tcp-link", "output_exit_code": 0, "output_tail": "Kernel log downloaded to /home/user/kaggle-tcp-link-run/output/tcp_link_status_pending/webvm-tcp-link.log \n", "time": "2026-11-08T06:15:52.954+00:00"}
[2026-11-08T06:15:57+00:00] IO_LOOP_CONTROLLER {"event": "TCP_LINK_KERNEL_LOG_DIAGNOSTICS", "kernel_id": "simonday/webvm-tcp-link", "lines": [",{\"stream_name\":\"stdout\",\"time\":10.057620252,\"data\":\"WEBVM_PROXY_DIAGNOSTIC {\\\"error\\\": \\\"ConnectionRefusedError: [Errno 111] Connection refused\\\", \\\"event\\\": \\\"LOCAL_PORT_PROBE\\\", \\\"listening\\\": false, \\\"port\\\": 8888}\\n\"}", ",{\"stream_name\":\"stdout\",\"time\":10.059156863,\"data\":\"WEBVM_PROXY_DIAGNOSTIC {\\\"error\\\": \\\"ConnectionRefusedError: [Errno 111] Connection refused\\\", \\\"event\\\": \\\"LOCAL_PORT_PROBE\\\", \\\"listening\\\": false, \\\"port\\\": 8889}\\n\"}", ",{\"stream_name\":\"stdout\",\"time\":42.133233112,\"data\":\"WEBVM_TCP_LINK {\\\"note\\\": \\\"Create a reusable ephemeral Tailscale auth key and add it as a Kaggle Notebook Secret.\\\", \\\"required_kaggle_secret\\\": \\\"WEBVM_TAILSCALE_AUTHKEY\\\", \\\"stage\\\": \\\"AUTH_KEY_MISSING\\\", \\\"time\\\": \\\"2026-11-08T06:14:21+00:00\\\"}\\n\"}"], "log_file": "webvm-tcp-link.log", "selected_line_count": 3, "time": "2026-11-08T06:15:53.098+00:00"}
[2026-11-08T06:15:57+00:00] TCP_LINK_KERNEL_LOG ,{"stream_name":"stdout","time":10.057620252,"data":"WEBVM_PROXY_DIAGNOSTIC {\"error\": \"ConnectionRefusedError: [Errno 111] Connection refused\", \"event\": \"LOCAL_PORT_PROBE\", \"listening\": false, \"port\": 8888}\n"}
[2026-11-08T06:15:57+00:00] TCP_LINK_KERNEL_LOG ,{"stream_name":"stdout","time":10.059156863,"data":"WEBVM_PROXY_DIAGNOSTIC {\"error\": \"ConnectionRefusedError: [Errno 111] Connection refused\", \"event\": \"LOCAL_PORT_PROBE\", \"listening\": false, \"port\": 8889}\n"}
[2026-11-08T06:15:57+00:00] TCP_LINK_KERNEL_LOG ,{"stream_name":"stdout","time":42.133233112,"data":"WEBVM_TCP_LINK {\"note\": \"Create a reusable ephemeral Tailscale auth key and add it as a Kaggle Notebook Secret.\", \"required_kaggle_secret\": \"WEBVM_TAILSCALE_AUTHKEY\", \"stage\": \"AUTH_KEY_MISSING\", \"time\": \"2026-11-08T06:14:21+00:00\"}\n"}
[2026-11-08T06:15:57+00:00] TCP_LINK_CONTROLLER_EXIT returncode=0
[2026-11-08T06:15:57+00:00] TCP_LINK_REMOTE_PROBE_WAIT attempt=1/6 reason=peer_proxy_config_not_ready
[2026-11-08T06:15:59+00:00] TCP_LINK_REMOTE_PROBE_WAIT attempt=2/6 reason=peer_proxy_config_not_ready
[2026-11-08T06:16:04+00:00] TCP_LINK_REMOTE_PROBE_WAIT attempt=3/6 reason=peer_proxy_config_not_ready
[2026-11-08T06:16:09+00:00] TCP_LINK_REMOTE_PROBE_WAIT attempt=4/6 reason=peer_proxy_config_not_ready
[2026-11-08T06:16:14+00:00] TCP_LINK_REMOTE_PROBE_WAIT attempt=5/6 reason=peer_proxy_config_not_ready
[2026-11-08T06:16:19+00:00] TCP_LINK_REMOTE_PROBE_WAIT attempt=6/6 reason=peer_proxy_config_not_ready
[2026-11-08T06:16:19+00:00] TCP_LINK_REMOTE_CONNECTIVITY_UNVERIFIED reason=peer_proxy_config_missing
[2026-11-08T06:16:19+00:00] PI_WRAPPER_FINISHED returncode=0