Can I see server/client logs?

Submitted by Anonymous (not verified) on #1

My Virtualhere server on a Raspberry Pi has worked great for months without a flaw. One thing that is connected is a SmartHome Insteon modem - a virtual com port.

It controls the lights around the house via a program called Home Control Assistant, which sees it as a com port.

Suddenly I find that the COM port either vanishes completely or (apparently) vanishes and then returns. Much to the annoyance of the program connected to it.

I was literally running the same server/client for many months before this began to happen, but did download the latest of both a couple of days ago, and the same thing happened yesterday.

Is there a way to see or turn on logging so that I can see connect/disconnect/other activity? In this particular case there is almost none of this activity intentionally - the SmartHome device is plugged into the wall and the Pi is just sitting there. The machine connected to the modem is also just sitting there - and only issues serial commands twice a day.

I also have an XP machine with the last XP Client connected to another virtual serial device, but it too has been running for a long long time, and while XP occasionally crashes for some unknown reason that's typically *not* when the other machine loses its connectivity.

Submitted by Michael on Thu, 2018/11/01 - 19:25

#2

So the connection started playing up before or after you updated the virtualhere software?

Server logs are in /var/log/syslog (or journalctl | grep vhusbd)

Client logs are accessed by right clicking USB Hubs->System Messages

When the server or client disconnects it will write the reason in those logs.

Submitted by Anonymous (not verified) on Fri, 2018/11/02 - 01:20

#3

The connection was playing up before I updated the software, but has continued to do so with the new versions.

Neither /var/log/syslog or journalctl give me anything, but it just became November 1st. I did see user.log.1 and gzipped user.log.2 - 4

Right clicking the client and looking at system messages only seems to show me messages since it started. Do you also log to disk with the client?

I have re-started everything, ensuring that all cables are still properly plugged. I'll monitor for problems and add to this with client and server log data if I see them. Problems usually show up in a day or two.

Here are server user.log.2 and user.log.1, in chronological order. They seem to show a lot of timeouts and disconnects. You can see at the bottom when I restarted with the new server software.

101e:0005 is my Fronius Datalogger
0403:6001 is the connection to the light controller.

Oct 15 06:49:27 raspberrypi vhusbdarmpi3[845]: Device 114 [101e:0005] UNBOUND from connection 83
Oct 15 06:49:28 raspberrypi vhusbdarmpi3[845]: Connection 83 successfully removed (reason:timeout)
Oct 15 06:49:45 raspberrypi vhusbdarmpi3[845]: 172.21.21.100 connected as connection 89
Oct 15 06:49:45 raspberrypi vhusbdarmpi3[845]: Device 114 [101e:0005] BOUND to connection 89
Oct 15 06:53:58 raspberrypi vhusbdarmpi3[845]: Device 115 [0403:6001] UNBOUND from connection 85
Oct 15 06:53:59 raspberrypi vhusbdarmpi3[845]: Device 114 [101e:0005] UNBOUND from connection 89
Oct 15 06:53:59 raspberrypi vhusbdarmpi3[845]: Connection 89 successfully removed (reason:timeout)
Oct 15 06:53:59 raspberrypi vhusbdarmpi3[845]: Connection 85 successfully removed (reason:timeout)
Oct 15 06:54:11 raspberrypi vhusbdarmpi3[845]: 172.21.21.131 connected as connection 91
Oct 15 06:54:11 raspberrypi vhusbdarmpi3[845]: Device 115 [0403:6001] BOUND to connection 91
Oct 15 06:54:15 raspberrypi vhusbdarmpi3[845]: 172.21.21.100 connected as connection 93
Oct 15 06:54:15 raspberrypi vhusbdarmpi3[845]: Device 114 [101e:0005] BOUND to connection 93
Oct 16 02:39:11 raspberrypi vhusbdarmpi3[845]: 172.21.21.146 connected as connection 95
Oct 16 02:44:46 raspberrypi vhusbdarmpi3[845]: Connection 95 remotely disconnected abruptly (rx msg size)
Oct 16 02:44:53 raspberrypi vhusbdarmpi3[845]: Connection 95 successfully removed (reason:timeout)
Oct 16 05:14:29 raspberrypi vhusbdarmpi3[845]: Device 114 [101e:0005] UNBOUND from connection 93
Oct 16 05:14:29 raspberrypi vhusbdarmpi3[845]: Connection 93 successfully removed (reason:timeout)
Oct 16 05:14:52 raspberrypi vhusbdarmpi3[845]: 172.21.21.100 connected as connection 96
Oct 16 05:14:52 raspberrypi vhusbdarmpi3[845]: Device 114 [101e:0005] BOUND to connection 96
Oct 16 05:18:58 raspberrypi vhusbdarmpi3[845]: Device 114 [101e:0005] UNBOUND from connection 96
Oct 16 05:18:58 raspberrypi vhusbdarmpi3[845]: Connection 96 successfully removed (reason:timeout)
Oct 16 05:19:22 raspberrypi vhusbdarmpi3[845]: 172.21.21.100 connected as connection 98
Oct 16 05:19:22 raspberrypi vhusbdarmpi3[845]: Device 114 [101e:0005] BOUND to connection 98
Oct 16 10:57:38 raspberrypi vhusbdarmpi3[845]: Connection 88 successfully removed (reason:timeout)
Oct 16 10:57:46 raspberrypi vhusbdarmpi3[845]: 172.21.21.124 connected as connection 100
Oct 16 13:09:16 raspberrypi vhusbdarmpi3[845]: Connection 91 remotely disconnected abruptly (rx msg size)
Oct 16 13:09:23 raspberrypi vhusbdarmpi3[845]: Device 115 [0403:6001] UNBOUND from connection 91
Oct 16 13:09:23 raspberrypi vhusbdarmpi3[845]: Connection 91 successfully removed (reason:timeout)
Oct 16 14:57:21 raspberrypi vhusbdarmpi3[845]: 172.21.21.131 connected as connection 101
Oct 16 14:57:25 raspberrypi vhusbdarmpi3[845]: Device 115 [0403:6001] BOUND to connection 101
Oct 17 06:19:58 raspberrypi vhusbdarmpi3[845]: Connection 100 remotely disconnected gracefully (rx msg size)
Oct 17 06:20:07 raspberrypi vhusbdarmpi3[845]: 172.21.21.124 connected as connection 103
Oct 17 06:20:08 raspberrypi vhusbdarmpi3[845]: Connection 100 successfully removed (reason:timeout)
Oct 17 11:14:15 raspberrypi vhusbdarmpi3[845]: Connection 103 successfully removed (reason:timeout)
Oct 17 11:31:33 raspberrypi vhusbdarmpi3[845]: 172.21.21.124 connected as connection 104
Oct 18 02:04:52 raspberrypi vhusbdarmpi3[845]: Connection 104 successfully removed (reason:timeout)
Oct 18 02:29:27 raspberrypi vhusbdarmpi3[845]: Device 114 [101e:0005] UNBOUND from connection 98
Oct 18 02:29:27 raspberrypi vhusbdarmpi3[845]: Connection 98 successfully removed (reason:timeout)
Oct 18 02:30:00 raspberrypi vhusbdarmpi3[845]: 172.21.21.100 connected as connection 105
Oct 18 02:30:01 raspberrypi vhusbdarmpi3[845]: Device 114 [101e:0005] BOUND to connection 105
Oct 18 02:33:58 raspberrypi vhusbdarmpi3[845]: Device 114 [101e:0005] UNBOUND from connection 105
Oct 18 02:33:59 raspberrypi vhusbdarmpi3[845]: Connection 105 successfully removed (reason:timeout)
Oct 18 02:34:30 raspberrypi vhusbdarmpi3[845]: 172.21.21.100 connected as connection 107
Oct 18 02:34:31 raspberrypi vhusbdarmpi3[845]: Device 114 [101e:0005] BOUND to connection 107
Oct 18 08:43:46 raspberrypi vhusbdarmpi3[845]: 172.21.21.124 connected as connection 109
Oct 19 03:40:01 raspberrypi vhusbdarmpi3[845]: Connection 109 remotely disconnected gracefully (rx msg size)
Oct 19 03:40:02 raspberrypi vhusbdarmpi3[845]: 172.21.21.124 connected as connection 110
Oct 19 03:40:11 raspberrypi vhusbdarmpi3[845]: Connection 109 successfully removed (reason:timeout)
Oct 19 05:21:55 raspberrypi vhusbdarmpi3[845]: 172.21.21.119 connected as connection 111
Oct 19 05:21:55 raspberrypi vhusbdarmpi3[845]: Device 1131 [0403:6001] BOUND to connection 111
Oct 19 06:06:02 raspberrypi vhusbdarmpi3[845]: Connection 111 remotely disconnected abruptly (rx msg size)
Oct 19 06:06:09 raspberrypi vhusbdarmpi3[845]: Device 1131 [0403:6001] UNBOUND from connection 111
Oct 19 06:06:09 raspberrypi vhusbdarmpi3[845]: Connection 111 successfully removed (reason:timeout)
Oct 19 06:07:37 raspberrypi vhusbdarmpi3[845]: Connection 110 remotely disconnected abruptly (rx msg size)
Oct 19 06:07:45 raspberrypi vhusbdarmpi3[845]: Connection 110 successfully removed (reason:timeout)
Oct 19 06:07:51 raspberrypi vhusbdarmpi3[845]: 172.21.21.124 connected as connection 113
Oct 19 06:10:19 raspberrypi vhusbdarmpi3[845]: Connection 113 remotely disconnected abruptly (rx msg size)
Oct 19 06:10:27 raspberrypi vhusbdarmpi3[845]: Connection 113 successfully removed (reason:timeout)
Oct 19 06:37:01 raspberrypi vhusbdarmpi3[845]: 172.21.21.124 connected as connection 114
Oct 19 20:57:30 raspberrypi vhusbdarmpi3[845]: Connection 114 successfully removed (reason:timeout)
Oct 19 20:58:09 raspberrypi vhusbdarmpi3[845]: 172.21.21.124 connected as connection 115
Oct 20 02:42:19 raspberrypi vhusbdarmpi3[845]: Connection 115 remotely disconnected abruptly (rx msg size)
Oct 20 02:42:20 raspberrypi vhusbdarmpi3[845]: 172.21.21.124 connected as connection 116
Oct 20 02:42:30 raspberrypi vhusbdarmpi3[845]: Connection 115 successfully removed (reason:timeout)
Oct 20 09:09:39 raspberrypi vhusbdarmpi3[845]: Connection 116 remotely disconnected abruptly (rx msg size)
Oct 20 09:09:45 raspberrypi vhusbdarmpi3[845]: Connection 116 successfully removed (reason:timeout)
Oct 21 08:01:29 raspberrypi vhusbdarmpi3[845]: 172.21.21.146 connected as connection 117
Oct 22 04:25:34 raspberrypi vhusbdarmpi3[845]: Connection 117 remotely disconnected abruptly (rx msg size)
Oct 22 04:25:43 raspberrypi vhusbdarmpi3[845]: Connection 117 successfully removed (reason:timeout)
Oct 22 04:26:56 raspberrypi vhusbdarmpi3[845]: 172.21.21.124 connected as connection 118
Oct 22 04:29:26 raspberrypi vhusbdarmpi3[845]: Device 114 [101e:0005] UNBOUND from connection 107
Oct 22 04:29:27 raspberrypi vhusbdarmpi3[845]: Connection 107 successfully removed (reason:timeout)
Oct 22 04:29:49 raspberrypi vhusbdarmpi3[845]: 172.21.21.100 connected as connection 119
Oct 22 04:29:49 raspberrypi vhusbdarmpi3[845]: Device 114 [101e:0005] BOUND to connection 119
Oct 22 04:33:57 raspberrypi vhusbdarmpi3[845]: Device 115 [0403:6001] UNBOUND from connection 101
Oct 22 04:33:58 raspberrypi vhusbdarmpi3[845]: Connection 101 successfully removed (reason:timeout)
Oct 22 04:33:59 raspberrypi vhusbdarmpi3[845]: Device 114 [101e:0005] UNBOUND from connection 119
Oct 22 04:33:59 raspberrypi vhusbdarmpi3[845]: Connection 119 successfully removed (reason:timeout)
Oct 22 04:34:19 raspberrypi vhusbdarmpi3[845]: 172.21.21.100 connected as connection 121
Oct 22 04:34:19 raspberrypi vhusbdarmpi3[845]: Device 114 [101e:0005] BOUND to connection 121
Oct 22 04:34:32 raspberrypi vhusbdarmpi3[845]: 172.21.21.131 connected as connection 123
Oct 22 04:34:32 raspberrypi vhusbdarmpi3[845]: Device 115 [0403:6001] BOUND to connection 123
Oct 22 10:27:43 raspberrypi vhusbdarmpi3[845]: Unmanaging device 1131 [0403:6001]
Oct 22 11:05:23 raspberrypi vhusbdarmpi3[845]: Connection 118 remotely disconnected abruptly (rx msg size)
Oct 22 11:05:28 raspberrypi vhusbdarmpi3[845]: Connection 118 successfully removed (reason:timeout)
Oct 22 11:50:44 raspberrypi vhusbdarmpi3[845]: Device 115 [0403:6001] UNBOUND from connection 123
Oct 22 11:50:47 raspberrypi vhusbdarmpi3[845]: Device 115 [0403:6001] BOUND to connection 123
Oct 22 12:44:16 raspberrypi vhusbdarmpi3[845]: 172.21.21.124 connected as connection 126
Oct 23 05:05:02 raspberrypi vhusbdarmpi3[845]: Connection 126 remotely disconnected abruptly (rx msg size)
Oct 23 05:05:07 raspberrypi vhusbdarmpi3[845]: Connection 126 successfully removed (reason:timeout)
Oct 23 08:04:26 raspberrypi vhusbdarmpi3[845]: Device 114 [101e:0005] UNBOUND from connection 121
Oct 23 08:04:27 raspberrypi vhusbdarmpi3[845]: Connection 121 successfully removed (reason:timeout)
Oct 23 08:04:55 raspberrypi vhusbdarmpi3[845]: 172.21.21.100 connected as connection 127
Oct 23 08:04:55 raspberrypi vhusbdarmpi3[845]: Device 114 [101e:0005] BOUND to connection 127
Oct 23 08:08:57 raspberrypi vhusbdarmpi3[845]: Device 114 [101e:0005] UNBOUND from connection 127
Oct 23 08:08:57 raspberrypi vhusbdarmpi3[845]: Connection 127 successfully removed (reason:timeout)
Oct 23 08:09:25 raspberrypi vhusbdarmpi3[845]: 172.21.21.100 connected as connection 129
Oct 23 08:09:25 raspberrypi vhusbdarmpi3[845]: Device 114 [101e:0005] BOUND to connection 129
Oct 23 08:43:21 raspberrypi vhusbdarmpi3[845]: 172.21.21.124 connected as connection 131
Oct 23 08:55:51 raspberrypi vhusbdarmpi3[845]: Connection 131 remotely disconnected abruptly (rx msg size)
Oct 23 08:56:00 raspberrypi vhusbdarmpi3[845]: Connection 131 successfully removed (reason:timeout)
Oct 23 08:56:27 raspberrypi vhusbdarmpi3[845]: 172.21.21.124 connected as connection 132
Oct 23 09:13:00 raspberrypi vhusbdarmpi3[845]: Connection 132 remotely disconnected abruptly (rx msg size)
Oct 23 09:13:09 raspberrypi vhusbdarmpi3[845]: Connection 132 successfully removed (reason:timeout)
Oct 23 09:13:35 raspberrypi vhusbdarmpi3[845]: 172.21.21.124 connected as connection 133
Oct 23 11:24:39 raspberrypi vhusbdarmpi3[845]: Connection 133 successfully removed (reason:timeout)
Oct 23 11:25:06 raspberrypi vhusbdarmpi3[845]: 172.21.21.124 connected as connection 134
Oct 23 20:52:08 raspberrypi vhusbdarmpi3[845]: Connection 134 remotely disconnected abruptly (rx msg size)
Oct 23 20:52:15 raspberrypi vhusbdarmpi3[845]: Connection 134 successfully removed (reason:timeout)
Oct 24 02:34:25 raspberrypi vhusbdarmpi3[845]: Device 115 [0403:6001] UNBOUND from connection 123
Oct 24 02:34:25 raspberrypi vhusbdarmpi3[845]: Connection 123 successfully removed (reason:timeout)
Oct 24 02:34:25 raspberrypi vhusbdarmpi3[845]: Device 114 [101e:0005] UNBOUND from connection 129
Oct 24 02:34:25 raspberrypi vhusbdarmpi3[845]: Connection 129 successfully removed (reason:timeout)
Oct 24 02:34:57 raspberrypi vhusbdarmpi3[845]: 172.21.21.100 connected as connection 135
Oct 24 02:34:57 raspberrypi vhusbdarmpi3[845]: Device 114 [101e:0005] BOUND to connection 135
Oct 24 02:34:58 raspberrypi vhusbdarmpi3[845]: 172.21.21.131 connected as connection 137
Oct 24 02:34:59 raspberrypi vhusbdarmpi3[845]: Device 115 [0403:6001] BOUND to connection 137
Oct 24 02:38:59 raspberrypi vhusbdarmpi3[845]: Device 114 [101e:0005] UNBOUND from connection 135
Oct 24 02:39:00 raspberrypi vhusbdarmpi3[845]: Connection 135 successfully removed (reason:timeout)
Oct 24 02:39:27 raspberrypi vhusbdarmpi3[845]: 172.21.21.100 connected as connection 139
Oct 24 02:39:27 raspberrypi vhusbdarmpi3[845]: Device 114 [101e:0005] BOUND to connection 139
Oct 24 04:33:29 raspberrypi vhusbdarmpi3[845]: 172.21.21.124 connected as connection 141
Oct 24 04:47:17 raspberrypi vhusbdarmpi3[845]: Device 115 [0403:6001] UNBOUND from connection 137
Oct 24 04:48:30 raspberrypi vhusbdarmpi3[845]: Device 115 [0403:6001] BOUND to connection 137
Oct 24 06:19:26 raspberrypi vhusbdarmpi3[845]: Device 114 [101e:0005] UNBOUND from connection 139
Oct 24 06:19:27 raspberrypi vhusbdarmpi3[845]: Connection 139 successfully removed (reason:timeout)
Oct 24 06:19:57 raspberrypi vhusbdarmpi3[845]: 172.21.21.100 connected as connection 143
Oct 24 06:19:58 raspberrypi vhusbdarmpi3[845]: Device 114 [101e:0005] BOUND to connection 143
Oct 24 06:24:16 raspberrypi vhusbdarmpi3[845]: Device 114 [101e:0005] UNBOUND from connection 143
Oct 24 06:24:16 raspberrypi vhusbdarmpi3[845]: Connection 143 successfully removed (reason:timeout)
Oct 24 06:24:57 raspberrypi vhusbdarmpi3[845]: 172.21.21.100 connected as connection 145
Oct 24 06:24:58 raspberrypi vhusbdarmpi3[845]: Device 114 [101e:0005] BOUND to connection 145
Oct 24 10:29:29 raspberrypi vhusbdarmpi3[845]: Device 114 [101e:0005] UNBOUND from connection 145
Oct 24 10:29:29 raspberrypi vhusbdarmpi3[845]: Connection 145 successfully removed (reason:timeout)
Oct 24 10:29:58 raspberrypi vhusbdarmpi3[845]: 172.21.21.100 connected as connection 147
Oct 24 10:29:58 raspberrypi vhusbdarmpi3[845]: Device 114 [101e:0005] BOUND to connection 147
Oct 24 10:34:00 raspberrypi vhusbdarmpi3[845]: Device 114 [101e:0005] UNBOUND from connection 147
Oct 24 10:34:01 raspberrypi vhusbdarmpi3[845]: Connection 147 successfully removed (reason:timeout)
Oct 24 10:34:28 raspberrypi vhusbdarmpi3[845]: 172.21.21.100 connected as connection 149
Oct 24 10:34:28 raspberrypi vhusbdarmpi3[845]: Device 114 [101e:0005] BOUND to connection 149
Oct 24 11:54:27 raspberrypi vhusbdarmpi3[845]: Device 114 [101e:0005] UNBOUND from connection 149
Oct 24 11:54:27 raspberrypi vhusbdarmpi3[845]: Connection 149 successfully removed (reason:timeout)
Oct 24 11:54:58 raspberrypi vhusbdarmpi3[845]: 172.21.21.100 connected as connection 151
Oct 24 11:54:58 raspberrypi vhusbdarmpi3[845]: Device 114 [101e:0005] BOUND to connection 151
Oct 24 11:59:00 raspberrypi vhusbdarmpi3[845]: Device 114 [101e:0005] UNBOUND from connection 151
Oct 24 11:59:01 raspberrypi vhusbdarmpi3[845]: Connection 151 successfully removed (reason:timeout)
Oct 24 11:59:28 raspberrypi vhusbdarmpi3[845]: 172.21.21.100 connected as connection 153
Oct 24 11:59:29 raspberrypi vhusbdarmpi3[845]: Device 114 [101e:0005] BOUND to connection 153
Oct 25 01:59:27 raspberrypi vhusbdarmpi3[845]: Device 114 [101e:0005] UNBOUND from connection 153
Oct 25 01:59:28 raspberrypi vhusbdarmpi3[845]: Connection 153 successfully removed (reason:timeout)
Oct 25 02:00:00 raspberrypi vhusbdarmpi3[845]: 172.21.21.100 connected as connection 155
Oct 25 02:00:00 raspberrypi vhusbdarmpi3[845]: Device 114 [101e:0005] BOUND to connection 155
Oct 25 02:03:58 raspberrypi vhusbdarmpi3[845]: Device 114 [101e:0005] UNBOUND from connection 155
Oct 25 02:03:59 raspberrypi vhusbdarmpi3[845]: Connection 155 successfully removed (reason:timeout)
Oct 25 02:03:59 raspberrypi vhusbdarmpi3[845]: Error 22 discarding urb 0x17feac0 for device /sys/bus/usb/devices/1-1.5, Invalid argument (abort endpoint)
Oct 25 02:04:30 raspberrypi vhusbdarmpi3[845]: 172.21.21.100 connected as connection 157
Oct 25 02:04:30 raspberrypi vhusbdarmpi3[845]: Device 114 [101e:0005] BOUND to connection 157
Oct 25 11:59:28 raspberrypi vhusbdarmpi3[845]: Device 114 [101e:0005] UNBOUND from connection 157
Oct 25 11:59:28 raspberrypi vhusbdarmpi3[845]: Connection 157 successfully removed (reason:timeout)
Oct 25 12:00:01 raspberrypi vhusbdarmpi3[845]: 172.21.21.100 connected as connection 159
Oct 25 12:00:01 raspberrypi vhusbdarmpi3[845]: Device 114 [101e:0005] BOUND to connection 159
Oct 25 12:03:59 raspberrypi vhusbdarmpi3[845]: Device 115 [0403:6001] UNBOUND from connection 137
Oct 25 12:03:59 raspberrypi vhusbdarmpi3[845]: Device 114 [101e:0005] UNBOUND from connection 159
Oct 25 12:04:00 raspberrypi vhusbdarmpi3[845]: Connection 137 successfully removed (reason:timeout)
Oct 25 12:04:00 raspberrypi vhusbdarmpi3[845]: Connection 159 successfully removed (reason:timeout)
Oct 25 12:04:25 raspberrypi vhusbdarmpi3[845]: 172.21.21.131 connected as connection 161
Oct 25 12:04:31 raspberrypi vhusbdarmpi3[845]: 172.21.21.100 connected as connection 162
Oct 25 12:04:31 raspberrypi vhusbdarmpi3[845]: Device 114 [101e:0005] BOUND to connection 162
Oct 25 17:26:11 raspberrypi vhusbdarmpi3[845]: Device 114 [101e:0005] UNBOUND from connection 162
Oct 25 17:26:11 raspberrypi vhusbdarmpi3[845]: Connection 162 successfully removed (reason:timeout)
Oct 25 17:28:24 raspberrypi vhusbdarmpi3[845]: 172.21.21.100 connected as connection 164
Oct 25 17:28:24 raspberrypi vhusbdarmpi3[845]: Device 114 [101e:0005] BOUND to connection 164
Oct 25 20:05:49 raspberrypi vhusbdarmpi3[845]: Connection 141 remotely disconnected gracefully (rx msg size)
Oct 25 20:05:58 raspberrypi vhusbdarmpi3[845]: Connection 141 successfully removed (reason:timeout)
Oct 25 20:06:00 raspberrypi vhusbdarmpi3[845]: 172.21.21.124 connected as connection 166
Oct 25 20:10:02 raspberrypi vhusbdarmpi3[845]: Connection 166 successfully removed (reason:timeout)
Oct 25 21:51:33 raspberrypi vhusbdarmpi3[845]: 172.21.21.124 connected as connection 167
Oct 25 21:53:16 raspberrypi vhusbdarmpi3[845]: Device 115 [0403:6001] BOUND to connection 161
Oct 27 07:44:26 raspberrypi vhusbdarmpi3[845]: Device 114 [101e:0005] UNBOUND from connection 164
Oct 27 07:44:26 raspberrypi vhusbdarmpi3[845]: Connection 164 successfully removed (reason:timeout)
Oct 27 07:44:55 raspberrypi vhusbdarmpi3[845]: 172.21.21.100 connected as connection 169
Oct 27 07:44:56 raspberrypi vhusbdarmpi3[845]: Device 114 [101e:0005] BOUND to connection 169
Oct 27 07:48:57 raspberrypi vhusbdarmpi3[845]: Device 115 [0403:6001] UNBOUND from connection 161
Oct 27 07:48:57 raspberrypi vhusbdarmpi3[845]: Connection 161 successfully removed (reason:timeout)
Oct 27 07:48:57 raspberrypi vhusbdarmpi3[845]: Device 114 [101e:0005] UNBOUND from connection 169
Oct 27 07:48:58 raspberrypi vhusbdarmpi3[845]: Connection 169 successfully removed (reason:timeout)
Oct 27 07:49:19 raspberrypi vhusbdarmpi3[845]: 172.21.21.131 connected as connection 171
Oct 27 07:49:20 raspberrypi vhusbdarmpi3[845]: Device 115 [0403:6001] BOUND to connection 171
Oct 27 07:49:25 raspberrypi vhusbdarmpi3[845]: 172.21.21.100 connected as connection 173
Oct 27 07:49:25 raspberrypi vhusbdarmpi3[845]: Device 114 [101e:0005] BOUND to connection 173
Oct 27 19:04:40 raspberrypi vhusbdarmpi3[845]: Device 115 [0403:6001] UNBOUND from connection 171
Oct 27 19:04:44 raspberrypi vhusbdarmpi3[845]: Device 115 [0403:6001] BOUND to connection 171
Oct 27 19:38:04 raspberrypi vhusbdarmpi3[845]: Device 114 [101e:0005] UNBOUND from connection 173
Oct 27 19:38:05 raspberrypi vhusbdarmpi3[845]: Connection 173 successfully removed (reason:timeout)
Oct 27 19:40:03 raspberrypi vhusbdarmpi3[845]: 172.21.21.100 connected as connection 176
Oct 27 19:40:03 raspberrypi vhusbdarmpi3[845]: Device 114 [101e:0005] BOUND to connection 176
Oct 28 03:48:26 raspberrypi vhusbdarmpi3[845]: Connection 171 remotely disconnected abruptly (rx msg size)
Oct 28 03:48:33 raspberrypi vhusbdarmpi3[845]: Device 115 [0403:6001] UNBOUND from connection 171
Oct 28 03:48:33 raspberrypi vhusbdarmpi3[845]: Connection 171 successfully removed (reason:timeout)
Oct 28 03:51:03 raspberrypi vhusbdarmpi3[845]: 172.21.21.131 connected as connection 178
Oct 28 03:51:04 raspberrypi vhusbdarmpi3[845]: Device 115 [0403:6001] BOUND to connection 178
Oct 28 04:05:58 raspberrypi vhusbdarmpi3[845]: Connection 178 remotely disconnected gracefully (rx msg size)
Oct 28 04:06:05 raspberrypi vhusbdarmpi3[845]: Device 115 [0403:6001] UNBOUND from connection 178
Oct 28 04:06:05 raspberrypi vhusbdarmpi3[845]: Connection 178 successfully removed (reason:timeout)
Oct 28 04:06:38 raspberrypi vhusbdarmpi3[845]: 172.21.21.131 connected as connection 180
Oct 28 04:06:40 raspberrypi vhusbdarmpi3[845]: Device 115 [0403:6001] BOUND to connection 180
Oct 28 04:07:49 raspberrypi vhusbdarmpi3[845]: Device 115 [0403:6001] UNBOUND from connection 180
Oct 28 04:07:52 raspberrypi vhusbdarmpi3[845]: Device 115 [0403:6001] BOUND to connection 180
Oct 28 04:29:49 raspberrypi org.gtk.Private.AfcVolumeMonitor[1080]: Volume monitor alive
Oct 28 04:29:51 raspberrypi org.gtk.Private.UDisks2VolumeMonitor[1080]: disc.c:352: error opening file BDMV/index.bdmv
Oct 28 04:29:51 raspberrypi org.gtk.Private.UDisks2VolumeMonitor[1080]: disc.c:352: error opening file BDMV/BACKUP/index.bdmv
Oct 28 04:31:25 raspberrypi org.gtk.Private.UDisks2VolumeMonitor[1343]: disc.c:352: error opening file BDMV/index.bdmv
Oct 28 04:31:25 raspberrypi org.gtk.Private.UDisks2VolumeMonitor[1343]: disc.c:352: error opening file BDMV/BACKUP/index.bdmv
Oct 28 04:31:25 raspberrypi org.gtk.Private.AfcVolumeMonitor[1343]: Volume monitor alive
Oct 28 04:40:13 raspberrypi vhusbdarmpi3[2433]: >>> Starting VirtualHere USB Server v3.7.8 (Built: Oct 14 2018, 16:06:55)<<<
Oct 28 04:40:13 raspberrypi vhusbdarmpi3[2433]: >>> Shutdown <<<
Oct 28 04:40:31 raspberrypi org.gtk.Private.AfcVolumeMonitor[1343]: g_dbus_connection_real_closed: Remote peer vanished with error: Underlying GIOStream returned 0 bytes on an async read (g-io-error-quark, 0). Exiting.
Oct 28 04:40:45 raspberrypi vhusbdarmpi3[820]: >>> Starting VirtualHere USB Server v3.7.8 (Built: Oct 14 2018, 16:06:55)<<<
Oct 28 04:40:45 raspberrypi vhusbdarmpi3[820]: Using configuration /home/pi/Virtualhere/config.ini
Oct 28 04:40:45 raspberrypi vhusbdarmpi3[820]: Server licensed to=00000000b467eff5 max_devices=unlimited
Oct 28 04:40:45 raspberrypi vhusbdarmpi3[820]: Using large URB's
Oct 28 04:40:45 raspberrypi vhusbdarmpi3[820]: Listening on all network interfaces at TCP port 7575
Oct 28 04:40:45 raspberrypi vhusbdarmpi3[820]: Found Full speed device [0403:6001] "FTDI, FT232R USB UART" at address 115
Oct 28 04:40:45 raspberrypi vhusbdarmpi3[820]: Found Full speed device [101e:0005] "Fronius, Datalogger" at address 114
Oct 28 04:40:56 raspberrypi org.gtk.Private.AfcVolumeMonitor[1093]: Volume monitor alive
Oct 28 04:40:56 raspberrypi vhusbdarmpi3[820]: 172.21.21.140 connected as connection 1
Oct 28 04:41:30 raspberrypi org.gtk.Private.UDisks2VolumeMonitor[1093]: disc.c:352: error opening file BDMV/index.bdmv
Oct 28 04:41:30 raspberrypi org.gtk.Private.UDisks2VolumeMonitor[1093]: disc.c:352: error opening file BDMV/BACKUP/index.bdmv
Oct 28 04:41:34 raspberrypi vhusbdarmpi3[820]: 172.21.21.140 connected as connection 2
Oct 28 04:41:34 raspberrypi vhusbdarmpi3[820]: Device 114 [101e:0005] BOUND to connection 2
Oct 28 04:41:38 raspberrypi vhusbdarmpi3[820]: 172.21.21.140 connected as connection 4
Oct 28 04:41:39 raspberrypi vhusbdarmpi3[820]: Device 115 [0403:6001] BOUND to connection 4
Oct 28 04:43:04 raspberrypi vhusbdarmpi3[820]: Device 115 [0403:6001] UNBOUND from connection 4
Oct 28 04:43:08 raspberrypi vhusbdarmpi3[820]: Device 115 [0403:6001] BOUND to connection 4

Submitted by Michael on Fri, 2018/11/02 - 08:20

#4

Yes it looks like the network is dropping. You may want to update raspbian also. Do

sudo apt-get update;sudo apt-get upgrade -y;sync;sudo reboot

It may also be a hardware issue, perhaps after a year or something the pi hardware is failing. Does the pi work ok otherwise, any other issues?

The client doesnt write the log to file unless you start the client with the -r command

vhui64.exe -r log.txt

Submitted by Anonymous (not verified) on Fri, 2018/11/02 - 14:38

#5

The Pi seems to be fine otherwise - it's a Pihole server that all my network uses and I've never noticed a problem. But it is a few years old.

I'll wait to see if the problem recurs, and if so I'll update raspbian and restart the client so that it saves logs.

If I *still* have problems I'll swap it out for a new one and beg you to move the license.

Submitted by Anonymous (not verified) on Thu, 2018/11/08 - 15:10

#6

Hey... this issue didn't happen for a few days and then began again. I updated raspbian as above and it almost immediately (10 hours later) happened again.

I wonder if you have any thoughts about both of my USB devices disconnecting with a timeout at the same time? It seems to be the theme. They say they are disconnecting because of a timeout - any thoughts on what is timing out?

Server log (user.log) looks like:

Nov 6 21:27:00 raspberrypi vhusbdarmpi3[876]: >>> Starting VirtualHere USB Server v3.7.8 (Built: Oct 14 2018, 16:06:55)<<<
Nov 6 21:27:00 raspberrypi vhusbdarmpi3[876]: Using configuration /home/pi/Virtualhere/config.ini
Nov 6 21:27:01 raspberrypi vhusbdarmpi3[876]: Server licensed to=00000000b467eff5 max_devices=unlimited
Nov 6 21:27:01 raspberrypi vhusbdarmpi3[876]: Using large URB's
Nov 6 21:27:01 raspberrypi vhusbdarmpi3[876]: Listening on all network interfaces at TCP port 7575
Nov 6 21:27:01 raspberrypi vhusbdarmpi3[876]: Found Full speed device [0403:6001] "FTDI, FT232R USB UART" at address 115
Nov 6 21:27:01 raspberrypi vhusbdarmpi3[876]: Found Full speed device [101e:0005] "Fronius, Datalogger" at address 114
Nov 6 21:27:02 raspberrypi vhusbdarmpi3[876]: 172.21.21.140 connected as connection 1
Nov 6 21:27:03 raspberrypi vhusbdarmpi3[876]: Device 115 [0403:6001] BOUND to connection 1
Nov 6 21:27:04 raspberrypi vhusbdarmpi3[876]: 172.21.21.140 connected as connection 3
Nov 6 21:27:05 raspberrypi vhusbdarmpi3[876]: Device 114 [101e:0005] BOUND to connection 3
Nov 6 21:27:09 raspberrypi vhusbdarmpi3[876]: 172.21.21.140 connected as connection 5
Nov 6 21:27:45 raspberrypi org.gtk.Private.AfcVolumeMonitor[1258]: Volume monitor alive
Nov 6 21:27:48 raspberrypi org.gtk.Private.UDisks2VolumeMonitor[1258]: disc.c:352: error opening file BDMV/index.bdmv
Nov 6 21:27:48 raspberrypi org.gtk.Private.UDisks2VolumeMonitor[1258]: disc.c:352: error opening file BDMV/BACKUP/index.bdmv
Nov 6 21:34:26 raspberrypi vhusbdarmpi3[876]: Device 114 [101e:0005] UNBOUND from connection 3
Nov 6 21:34:26 raspberrypi vhusbdarmpi3[876]: Connection 3 successfully removed (reason:timeout)
Nov 6 21:34:28 raspberrypi vhusbdarmpi3[876]: Device 115 [0403:6001] UNBOUND from connection 1
Nov 6 21:34:28 raspberrypi vhusbdarmpi3[876]: Connection 1 successfully removed (reason:timeout)
Nov 6 21:34:39 raspberrypi vhusbdarmpi3[876]: 172.21.21.140 connected as connection 6
Nov 6 21:34:40 raspberrypi vhusbdarmpi3[876]: Device 115 [0403:6001] BOUND to connection 6
Nov 6 21:35:06 raspberrypi vhusbdarmpi3[876]: 172.21.21.140 connected as connection 8
Nov 6 21:35:07 raspberrypi vhusbdarmpi3[876]: Device 114 [101e:0005] BOUND to connection 8
Nov 6 21:38:56 raspberrypi vhusbdarmpi3[876]: Device 114 [101e:0005] UNBOUND from connection 8
Nov 6 21:38:57 raspberrypi vhusbdarmpi3[876]: Connection 8 successfully removed (reason:timeout)
Nov 6 21:39:36 raspberrypi vhusbdarmpi3[876]: 172.21.21.140 connected as connection 10
Nov 6 21:39:37 raspberrypi vhusbdarmpi3[876]: Device 114 [101e:0005] BOUND to connection 10
Nov 6 22:06:33 raspberrypi org.gtk.Private.UDisks2VolumeMonitor[2094]: disc.c:352: error opening file BDMV/index.bdmv
Nov 6 22:06:33 raspberrypi org.gtk.Private.UDisks2VolumeMonitor[2094]: disc.c:352: error opening file BDMV/BACKUP/index.bdmv
Nov 6 22:06:33 raspberrypi org.gtk.Private.AfcVolumeMonitor[2094]: Volume monitor alive
Nov 7 08:29:25 raspberrypi vhusbdarmpi3[876]: Device 115 [0403:6001] UNBOUND from connection 6
Nov 7 08:29:25 raspberrypi vhusbdarmpi3[876]: Connection 6 successfully removed (reason:timeout)
Nov 7 08:29:26 raspberrypi vhusbdarmpi3[876]: Device 114 [101e:0005] UNBOUND from connection 10
Nov 7 08:29:26 raspberrypi vhusbdarmpi3[876]: Connection 10 successfully removed (reason:timeout)
Nov 7 08:29:44 raspberrypi vhusbdarmpi3[876]: 172.21.21.140 connected as connection 12
Nov 7 08:29:44 raspberrypi vhusbdarmpi3[876]: Device 115 [0403:6001] BOUND to connection 12
Nov 7 08:30:07 raspberrypi vhusbdarmpi3[876]: 172.21.21.140 connected as connection 14
Nov 7 08:30:07 raspberrypi vhusbdarmpi3[876]: Device 114 [101e:0005] BOUND to connection 14
Nov 7 08:34:01 raspberrypi vhusbdarmpi3[876]: Device 114 [101e:0005] UNBOUND from connection 14
Nov 7 08:34:02 raspberrypi vhusbdarmpi3[876]: Connection 14 successfully removed (reason:timeout)
Nov 7 08:34:37 raspberrypi vhusbdarmpi3[876]: 172.21.21.140 connected as connection 16
Nov 7 08:34:37 raspberrypi vhusbdarmpi3[876]: Device 114 [101e:0005] BOUND to connection 16

and the client messages look like:

21:26:48 INFO :Connection 11 remotely disconnected gracefully (rx)
21:27:00 INFO :Server ping timeout, shutting down connection 11...
21:27:11 INFO :Could not connect to raspberrypi-3.local.:7575
21:34:29 INFO :Connection 13 remotely disconnected gracefully (rx)
21:34:32 INFO :Connection 13 sending msg didnt complete due to error 10053,
21:34:38 INFO :Server ping timeout, shutting down connection 13...
08:29:25 INFO :Connection 14 remotely disconnected gracefully (rx)
08:29:34 INFO :Server ping timeout, shutting down connection 14...