Thanks for this. Perhaps I’ll try a restart of the standalone and see if I get similar results.
Meanwhile @SirNeo, if you look at this issue there is a tip from @cecylia about getting verbose logging on a docker container:
2 Likes
Issue opened here:
Includes verbose log output.
1 Like
Thanks @Quartermarsh
I started the container with -verbose command and in case i see something strange i will put the logs where the issue was opened.
For me it happened again.
Somehow from advanced logs i observed that the number of clients is 0 because from uknown reasons Snowflake proxy doesn’t receives anymore sdp offers. I just restarted the container and after the account on gitlab will be proved i will post there the logs before/after restart.
The last 8-10 hours looks like this
2022/10/13 20:15:12 Connection successful.
2022/10/13 20:15:12 OnOpen channel
2022/10/13 20:15:13 connected to relay: wss://snowflake.torproject.net/
2022/10/13 20:16:35 OnClose channel
2022/10/13 20:16:35 Traffic throughput (up|down): 16 MB|1 MB -- (4530 OnMessages, 13497 Sends, over 279 seconds)
2022/10/13 20:16:35 copy loop ended
2022/10/13 20:16:35 datachannelHandler ends
2022/10/13 20:18:59 sdp offer successfully received.
2022/10/13 20:18:59 Generating answer...
2022/10/13 20:19:19 Timed out waiting for client to open data channel.
2022/10/13 20:25:58 sdp offer successfully received.
2022/10/13 20:25:58 Generating answer...
2022/10/13 20:26:21 Timed out waiting for client to open data channel.
2022/10/13 20:28:00 sdp offer successfully received.
2022/10/13 20:28:00 Generating answer...
2022/10/13 20:28:21 Timed out waiting for client to open data channel.
2022/10/13 20:36:58 In the last 1h0m0s, there were 5 connections. Traffic Relayed ↑ 21 MB, ↓ 2 MB.
2022/10/13 20:44:43 OnClose channel
2022/10/13 20:44:43 Traffic throughput (up|down): 47 MB|8 MB -- (20665 OnMessages, 44294 Sends, over 1770 seconds)
2022/10/13 20:44:43 copy loop ended
2022/10/13 20:44:43 datachannelHandler ends
2022/10/13 20:51:19 sdp offer successfully received.
2022/10/13 20:51:19 Generating answer...
2022/10/13 20:51:39 Timed out waiting for client to open data channel.
2022/10/13 20:55:26 sdp offer successfully received.
2022/10/13 20:55:26 Generating answer...
2022/10/13 20:55:47 Timed out waiting for client to open data channel.
2022/10/13 20:55:48 sdp offer successfully received.
2022/10/13 20:55:48 Generating answer...
2022/10/13 20:56:08 Timed out waiting for client to open data channel.
2022/10/13 20:58:18 sdp offer successfully received.
2022/10/13 20:58:18 Generating answer...
2022/10/13 20:58:38 Timed out waiting for client to open data channel.
2022/10/13 20:59:49 sdp offer successfully received.
2022/10/13 20:59:49 Generating answer...
2022/10/13 21:00:10 Timed out waiting for client to open data channel.
2022/10/13 21:02:20 sdp offer successfully received.
2022/10/13 21:02:20 Generating answer...
2022/10/13 21:02:41 Timed out waiting for client to open data channel.
2022/10/13 21:36:58 In the last 1h0m0s, there were 1 connections. Traffic Relayed ↑ 47 MB, ↓ 8 MB.
2022/10/13 21:56:52 sdp offer successfully received.
2022/10/13 21:56:52 Generating answer...
2022/10/13 21:57:12 Timed out waiting for client to open data channel.
2022/10/13 22:36:58 In the last 1h0m0s, there were 0 connections. Traffic Relayed ↑ 0 B, ↓ 0 B.
2022/10/13 23:36:58 In the last 1h0m0s, there were 0 connections. Traffic Relayed ↑ 0 B, ↓ 0 B.
2022/10/14 00:36:58 In the last 1h0m0s, there were 0 connections. Traffic Relayed ↑ 0 B, ↓ 0 B.
2022/10/14 01:36:58 In the last 1h0m0s, there were 0 connections. Traffic Relayed ↑ 0 B, ↓ 0 B.
2022/10/14 02:36:58 In the last 1h0m0s, there were 0 connections. Traffic Relayed ↑ 0 B, ↓ 0 B.
2022/10/14 03:36:58 In the last 1h0m0s, there were 0 connections. Traffic Relayed ↑ 0 B, ↓ 0 B.
2022/10/14 04:36:58 In the last 1h0m0s, there were 0 connections. Traffic Relayed ↑ 0 B, ↓ 0 B.
2022/10/14 05:36:58 In the last 1h0m0s, there were 0 connections. Traffic Relayed ↑ 0 B, ↓ 0 B.
2022/10/14 06:36:58 In the last 1h0m0s, there were 0 connections. Traffic Relayed ↑ 0 B, ↓ 0 B.
2 Likes
Similar to my standalone proxy (running 24/7). Now 36h’s with zero activity.
Traffic stopped between 2022/10/13 02:00:00 and 03:00:00.
Peek count in “Traffic throughput” was approx. 26850 OnMessages over 1770 seconds.
I guess it’s worth checking to see if you’re updated:
2 Likes
Eventually I did restart proxy and it did proxy messages as being designed for after having offered it’s service.
Again, after approx. 13h normal operation and proxying, now 12h with zero activity, no sdp offers logged.
lsof shows five external IPv6 connections on arbitrary ports in status established. Process has 9 threads established.
Mine also in les then 24 hours got 0 clients in the last 3-4 intervals.
Does anyone know how to add an auto restart function for the container?
Try here. You’ll need to look for a process manager as well:
1 Like
My snowflake proxy has 5 IPv6 https connections in status established with snowflake server. If there is no traffic registered, snowflake server has either a bug on load distribution or made a decision not to use these connections? (now 15h of zero traffic relayed)
Finding: iftop presents low traffic on connection to snowflake server. So, both sides talk to each other. Two connections seem to be actively in use.
At least one host resolves to snowflake-01, the second is shown as m-dnslb-a01.
I’ll keep it running …
Update: all 5 connections terminate on snowflake-01 with little traffic (40s average: approx. 400 Bytes/s)
Now 29 repeats on stdout (nohup.out) of
In the last 1h0m0s, there were 0 connections. Traffic Relayed ↑ 0 B, ↓ 0 B
My conclusion: There’s either no demand for this (my) snowflake proxy or my proxy is ignored for some reason.
I’ll keep it running …
My containers all aready configured to autostart in case of failure/crash
i’m using ->unless-stopped option.
But the fact that there are no connections to proxy doesn’t mean the container has issues. I wanted to add a timer or something when i start the container to have the option to restart after 24h hours, at least untill the bug is solved 
Something silimar to -verbose.
Have found a new snowflake commit in git (8b1970a3ce85436e87a9ac868652c3fc3d8c4b58), cloned and compiled it.
Restarted local snowflake proxy with this version …
New message in nohup.out
Bad range port format: 0xc000222070
But it does work and relay messages. …
2 Likes
I made bug report about it:
1 Like
Which is good news. Maybe the message means the server/broker (?) tried a port, spit out the message and then moved on. (Edit: see @Vort ’s issue #40215 above)
By the way, here’s a restart script for nohup from another user, @Beckers
use the “@reboot” directive in /etc/crontab to start a script which contains “nohup /full/path/to/proxy/ -summary-interval 30m -log /full/path/to/proxy.log”. The server is restarted every 24 hours.
Now, again, 16 zero activity messages in sequence. Still 5 TCP connections to snowflake-01 (my proxy is started with -capacity 5). No UDP traffic anymore. During first hours after restart, lsof did list plenty of UDP ports allocated. Now none anymore.
IMHO draining of snowflake proxies happens on the server side! And a proxy restart is like “new game, new luck”.
Anyway, upgrade to proxy git commit ac856280.
Error message is gone. Seems to work, lsof lists TCP and UDP connections. First traffic is relayed …
After approx. 25h zero traffic, snowflake proxy reported io errors, like
io.Copy inside CopyLoop generated an error: websocket: close 1006 (abnormal closure): unexpected EOF
This did start today, approx. 07:28:14 UTC.
Three seconds later a couple of lines like this
error dialing relay: wss://snowflake.torproject.net/?client_ip=[scrubbed] = dial tcp [scrubbed]: con nect: connection refused
did show up in proxy log.
First connected to relay ...did show on 07:31:27 UTC.
Probably a snowflake server restart?
Relaying did restart on 07:35:53 UTC.
I was having the same problem with my standalone proxy the last few days and updating the proxy worked. I recommend trying this.
1 Like