Opened 13 years ago

Closed 13 years ago

#1978 closed defect (fixed)

mythsocket tries to use unconnected socket to talk to slave backend

Reported by: jppoet@… Owned by: jwestfall
Priority: minor Milestone: unknown
Component: mythtv Version:
Severity: medium Keywords:
Cc: Ticket locked: no

Description

My master backend and slave backend have been running fine. I shutdown the slave for the day.

At the time I shut down the slave, I see this in the master backend log:

2006-06-20 09:04:57.546 MythSocket(84b8cc0:12): UpRef: 2
2006-06-20 09:04:57.365 Reschedule requested for id -1.
2006-06-20 09:04:57.573 MythSocket(84b05a8:18): socket closed
2006-06-20 09:04:57.609 MythSocket(84b05a8:18): state change Connected -> Idle
2006-06-20 09:04:57.650 MythSocket(84b05a8:-1): cb->connectionClosed()
2006-06-20 09:04:57.581 write -> 12 50      BACKEND_MESSAGE[]:[]CLEAR_SETTINGS_CACHE[]:[]empty
2006-06-20 09:04:57.661 MythSocket(84b8cc0:12): DownRef: 1
2006-06-20 09:04:58.895 MythSocket(84b8cc0:12): UpRef: 2
2006-06-20 09:04:58.902 write -> 12 16      QUERY_FREE_SPACE
2006-06-20 09:05:28.910 MythSocket(84b8cc0:12): readStringList: Error, timeout.
2006-06-20 09:05:28.914 MythSocket(84b8cc0:12): state change Connected -> Idle
2006-06-20 09:05:28.918 MythSocket(84b8cc0:-1): DownRef: 1
2006-06-20 09:05:28.922 decodeLongLong() called with offset >= list size.
2006-06-20 09:05:28.926 decodeLongLong() called with offset >= list size.
2006-06-20 09:05:28.930 MythSocket(84b8cc0:-1): UpRef: 2
2006-06-20 09:05:28.934 MythSocket(84b8cc0:-1): writeStringList: Error, called with unconnected socket.
2006-06-20 09:05:28.938 MythSocket(84b8cc0:-1): readStringList: Error, called with unconnected socket.
2006-06-20 09:05:28.942 MythSocket(84b8cc0:-1): DownRef: 1
2006-06-20 09:05:28.946 decodeLongLong() called with offset >= list size.
2006-06-20 09:05:28.950 decodeLongLong() called with offset >= list size.
2006-06-20 09:05:28.954 MythSocket(84b8cc0:-1): UpRef: 2
2006-06-20 09:05:28.958 MythSocket(84b8cc0:-1): writeStringList: Error, called with unconnected socket.
2006-06-20 09:05:28.962 MythSocket(84b8cc0:-1): readStringList: Error, called with unconnected socket.
2006-06-20 09:05:28.966 MythSocket(84b8cc0:-1): DownRef: 1
2006-06-20 09:05:28.970 decodeLongLong() called with offset >= list size.
2006-06-20 09:05:28.974 decodeLongLong() called with offset >= list size.
2006-06-20 09:05:28.978 MythSocket(84b8cc0:-1): UpRef: 2
2006-06-20 09:05:28.982 MythSocket(84b8cc0:-1): writeStringList: Error, called with unconnected socket.
2006-06-20 09:05:28.986 MythSocket(84b8cc0:-1): readStringList: Error, called with unconnected socket.
2006-06-20 09:05:28.990 MythSocket(84b8cc0:-1): DownRef: 1
2006-06-20 09:05:28.994 decodeLongLong() called with offset >= list size.
2006-06-20 09:05:28.998 decodeLongLong() called with offset >= list size.
2006-06-20 09:05:31.606 Scheduled 399 items in 4.1 = 1.53 match + 2.60 place

When I brought the slave back online, I see:

2006-06-20 18:45:23.517 MythSocket(82e0a58:17): new socket
2006-06-20 18:45:23.522 MythSocket(82e0a58:17): setSocket: 12
2006-06-20 18:45:23.525 MythSocket(82e0a58:12): state change Idle -> Connected
2006-06-20 18:45:23.529 MythSocket(82e0a58:12): UpRef: 1
2006-06-20 18:45:23.585 MythSocket(82e0a58:12): socket is readable
2006-06-20 18:45:23.589 MythSocket(82e0a58:12): cb->readyRead()
2006-06-20 18:45:23.594 MythSocket(82e0a58:12): UpRef: 2
2006-06-20 18:45:23.598 read  <- 12 1232    ANN SlaveBackend cobalt 192.168.2.51[]:[][]:[][]:[][]:[][]:[][]:[...
2006-06-20 18:45:23.602 adding: cobalt as a slave backend server
2006-06-20 18:45:23.606 write -> 12 2       OK
2006-06-20 18:45:23.606 Reschedule requested for id 0.
2006-06-20 18:45:23.610 MythSocket(82e0a58:12): DownRef: 1
2006-06-20 18:45:23.614 MythSocket(82e0a58:12): UpRef: 2
2006-06-20 18:45:23.621 write -> 12 16      QUERY_FREE_SPACE
2006-06-20 18:45:23.701 read  <- 12 37      0[]:[]1562701824[]:[]0[]:[]1358073856
2006-06-20 18:45:23.706 MythSocket(82e0a58:12): DownRef: 1
2006-06-20 18:45:23.710 MythSocket(82e0a58:12): UpRef: 2
2006-06-20 18:45:23.714 write -> 12 16      QUERY_FREE_SPACE
2006-06-20 18:45:23.760 read  <- 12 37      0[]:[]1562701824[]:[]0[]:[]1358073856
2006-06-20 18:45:23.766 MythSocket(82e0a58:12): DownRef: 1
2006-06-20 18:45:23.770 MythSocket(82e0a58:12): UpRef: 2
2006-06-20 18:45:23.774 write -> 12 16      QUERY_FREE_SPACE
2006-06-20 18:45:23.827 read  <- 12 37      0[]:[]1562701824[]:[]0[]:[]1358073856
2006-06-20 18:45:23.830 MythSocket(82e0a58:12): DownRef: 1
2006-06-20 18:45:23.834 MythSocket(82e0a58:12): UpRef: 2
2006-06-20 18:45:23.837 write -> 12 16      QUERY_FREE_SPACE
2006-06-20 18:45:23.885 read  <- 12 37      0[]:[]1562701824[]:[]0[]:[]1358073856
2006-06-20 18:45:23.890 MythSocket(82e0a58:12): DownRef: 1
2006-06-20 18:45:26.400 Scheduled 389 items in 2.5 = 0.01 match + 2.50 place
2006-06-20 18:45:26.407 MythSocket(816f2e0:13): UpRef: 2
2006-06-20 18:45:26.410 MythSocket(816f2e0:13): DownRef: 1
2006-06-20 18:45:26.414 MythSocket(816e7e0:16): UpRef: 2
2006-06-20 18:45:26.418 write -> 16 45      BACKEND_MESSAGE[]:[]SCHEDULE_CHANGE[]:[]empty
2006-06-20 18:45:26.422 MythSocket(816e7e0:16): DownRef: 1
2006-06-20 18:45:26.426 MythSocket(84b8cc0:-1): UpRef: 2
2006-06-20 18:45:26.430 MythSocket(84b8cc0:-1): DownRef: 1
2006-06-20 18:45:26.434 MythSocket(82e0a58:12): UpRef: 2
2006-06-20 18:45:26.438 MythSocket(82e0a58:12): DownRef: 1
2006-06-20 18:45:29.613 MythSocket(82e0a58:12): UpRef: 2
2006-06-20 18:45:29.618 write -> 12 16      QUERY_FREE_SPACE
2006-06-20 18:45:29.692 read  <- 12 37      0[]:[]1562701824[]:[]0[]:[]1358073856
2006-06-20 18:45:29.698 MythSocket(82e0a58:12): DownRef: 1
2006-06-20 18:45:29.702 MythSocket(82e0a58:12): UpRef: 2
2006-06-20 18:45:29.706 write -> 12 16      QUERY_FREE_SPACE
2006-06-20 18:45:29.750 read  <- 12 37      0[]:[]1562701824[]:[]0[]:[]1358073856
2006-06-20 18:45:29.754 MythSocket(82e0a58:12): DownRef: 1
2006-06-20 18:45:29.758 MythSocket(82e0a58:12): UpRef: 2
2006-06-20 18:45:29.762 write -> 12 16      QUERY_FREE_SPACE
2006-06-20 18:45:29.800 read  <- 12 37      0[]:[]1562701824[]:[]0[]:[]1358073856
2006-06-20 18:45:29.806 MythSocket(82e0a58:12): DownRef: 1
2006-06-20 18:45:29.810 MythSocket(82e0a58:12): UpRef: 2
2006-06-20 18:45:29.814 write -> 12 16      QUERY_FREE_SPACE
2006-06-20 18:45:29.839 read  <- 12 37      0[]:[]1562701824[]:[]0[]:[]1358073856
2006-06-20 18:45:29.842 MythSocket(82e0a58:12): DownRef: 1
2006-06-20 18:45:29.846 AutoExpire: Found 3 recorders w/max rate of 349 MiB/min
2006-06-20 18:45:29.851 AutoExpire: Required Free Space: 2.7 GB w/freq: 5 min

When I then try to play a show which lives on the slave:

2006-06-20 22:51:56.051 MythSocket(82be4e0:17): socket is readable
2006-06-20 22:51:56.094 MythSocket(82be4e0:17): cb->readyRead()
2006-06-20 22:51:56.099 MythSocket(82be4e0:17): UpRef: 2
2006-06-20 22:51:56.107 read  <- 17 536     QUERY_CHECKFILE[]:[]Nature[]:[]The Vanishing Lions[]:[]The decrea...
2006-06-20 22:51:56.115 MythSocket(84b8cc0:-1): UpRef: 2
2006-06-20 22:51:56.123 MythSocket(84b8cc0:-1): writeStringList: Error, called with unconnected socket.
2006-06-20 22:51:56.131 MythSocket(84b8cc0:-1): readStringList: Error, called with unconnected socket.
2006-06-20 22:51:56.139 MythSocket(84b8cc0:-1): DownRef: 1
2006-06-20 22:51:56.147 write -> 17 1       0
2006-06-20 22:51:56.155 MythSocket(82be4e0:17): DownRef: 1

So, the master tries to use the original socket to "play" a show off the backend, but it is long gone.

John

Attachments (1)

sockclose.diff (959 bytes) - added by jwestfall 13 years ago.

Download all attachments as: .zip

Change History (4)

Changed 13 years ago by jwestfall

Attachment: sockclose.diff added

comment:1 Changed 13 years ago by jwestfall

Owner: changed from Isaac Richards to jwestfall

Can you verify the attached patch fixes the issue.

mythsocket needs to call the connectionClosed callback when force closing the socket because of a timeout.

comment:2 Changed 13 years ago by jppoet@…

Yes, the attached patch does seem to fix the problem.

John

comment:3 Changed 13 years ago by jwestfall

Resolution: fixed
Status: newclosed

(In [10292]) fixes #1978

mythsocket needs to call the connectionClosed callback when force closing the socket because of a timeout.

Note: See TracTickets for help on using tickets.