I noticed that line too. When you gave us this sample — the BSDTCP connection
is closing at 13:37. What time was the command actually issued? Same time,
or 9 minutes or more earlier? My TCP or BSDTCP failures (when the node is
actually down) take 9.5 minutes to fail (3 minutes 9 seconds TCP/IP default
quit time TIMES 3 amanda retries) which in turn messes up other nodes which
are NOT down.
*BUT* your nodes aren’t down, so I don’t see how that problem can be
affecting you …..
Deb Baddorf
> On Jul 28, 2016, at 9:15 AM, Ochressandro Rettinger
> <[email protected]> wrote:
>
> In the second chunk of log messages, it looks like for some reason the
> BSDTCP connection is closing early. Unfortunately, I can't help you out with
> that, as I'm set up to use ssh.
>
> Good luck!
>
> -Sandro
>
> -----Original Message-----
> From: Chris Nighswonger [mailto:[email protected]]
> Sent: Thursday, July 28, 2016 7:10 AM
> To: [email protected]
> Cc: Ochressandro Rettinger <[email protected]>
> Subject: Re: amcheck failing when checking multiple clients
>
> Here are some potentially relevant lines form the log:
>
> Wed Jul 27 13:37:41 2016: thd-0x55f48f90bc00: amcheck-clients: sec:
> conn_read_callback 1 3
> Wed Jul 27 13:37:41 2016: thd-0x55f48f90bc00: amcheck-clients:
> tcpm_recv_token: read 47 bytes from 1
> Wed Jul 27 13:37:41 2016: thd-0x55f48f90bc00: amcheck-clients: sec:
> conn_read_callback: tcpm_recv_token returned 47 Wed Jul 27 13:37:41 2016:
> thd-0x55f48f90bc00: amcheck-clients: sec:
> stream_read_callback: handle 1
> Wed Jul 27 13:37:41 2016: thd-0x55f48f90bc00: amcheck-clients: sec:
> stream_read_callback: it was for us
> Wed Jul 27 13:37:41 2016: thd-0x55f48f90bc00: amcheck-clients: sec:
> stream_read_callback: read 47 bytes from scriptor:1 Wed Jul 27 13:37:41 2016:
> thd-0x55f48f90bc00: amcheck-clients: sec:
> recvpkt_callback: 47
> Wed Jul 27 13:37:41 2016: thd-0x55f48f90bc00: amcheck-clients: sec:
> cancelling recvpkt for scriptor
> Wed Jul 27 13:37:41 2016: thd-0x55f48f90bc00: amcheck-clients: sec:
> conn_read_cancel: decremented ev_read_refcnt to 0 for scriptor Wed Jul 27
> 13:37:41 2016: thd-0x55f48f90bc00: amcheck-clients: sec:
> conn_read_cancel: releasing event handler for scriptor Wed Jul 27 13:37:41
> 2016: thd-0x55f48f90bc00: amcheck-clients: sec:
> parse_pkt: parsing buffer of 47 bytes
> Wed Jul 27 13:37:41 2016: thd-0x55f48f90bc00: amcheck-clients: sec:
> parse_pkt: REP (1): "OPTIONS features=ffffffff9efefbffffffffff3f;
> "
> Wed Jul 27 13:37:41 2016: thd-0x55f48f90bc00: amcheck-clients: sec:
> received REP packet (1) from scriptor, contains:
>
> "OPTIONS features=ffffffff9efefbffffffffff3f;
> "
>
> Wed Jul 27 13:37:41 2016: thd-0x55f48f90bc00: amcheck-clients: sec:
> stream_sendpkt: enter
> Wed Jul 27 13:37:41 2016: thd-0x55f48f90bc00: amcheck-clients: sec:
> stream_sendpkt: ACK (3) pkt_t (len 0) contains:
>
> ""
>
> Wed Jul 27 13:37:41 2016: thd-0x55f48f90bc00: amcheck-clients: sec:
> stream_write: writing 2 bytes to scriptor:1 3 Wed Jul 27 13:37:41 2016:
> thd-0x55f48f90bc00: amcheck-clients:
> tcpm_send_token: write 2 bytes to handle 1 Wed Jul 27 13:37:41 2016:
> thd-0x55f48f90bc00: amcheck-clients:
> security_getdriver(name=bsdtcp) returns 0x7ffbb3e53100 Wed Jul 27 13:37:41
> 2016: thd-0x55f48f90bc00: amcheck-clients: bsdtcp:
> bsdtcp_connect: scriptor
> Wed Jul 27 13:37:41 2016: thd-0x55f48f90bc00: amcheck-clients:
> security_handleinit(handle=0x55f48f9d63d0, driver=0x7ffbb3e53100
> (BSDTCP))
> Wed Jul 27 13:37:41 2016: thd-0x55f48f90bc00: amcheck-clients:
> security_streaminit(stream=0x55f48fa102d0, driver=0x7ffbb3e53100
> (BSDTCP))
> Wed Jul 27 13:37:41 2016: thd-0x55f48f90bc00: amcheck-clients:
> sec_tcp_conn_get: scriptor
> Wed Jul 27 13:37:41 2016: thd-0x55f48f90bc00: amcheck-clients:
> sec_tcp_conn_get: exists, refcnt to scriptor is now 3 Wed Jul 27 13:37:41
> 2016: thd-0x55f48f90bc00: amcheck-clients: sec:
> stream_client: connected to stream 13
> Wed Jul 27 13:37:41 2016: thd-0x55f48f90bc00: amcheck-clients:
> security_close(handle=0x55f48f91e760, driver=0x7ffbb3e53100 (BSDTCP)) Wed Jul
> 27 13:37:41 2016: thd-0x55f48f90bc00: amcheck-clients: sec:
> closing handle to scriptor
> Wed Jul 27 13:37:41 2016: thd-0x55f48f90bc00: amcheck-clients: sec:
> cancelling recvpkt for scriptor
> Wed Jul 27 13:37:41 2016: thd-0x55f48f90bc00: amcheck-clients:
> security_stream_close(0x55f48f9b0e50)
> Wed Jul 27 13:37:41 2016: thd-0x55f48f90bc00: amcheck-clients: sec:
> tcpma_stream_close: closing stream 1
> Wed Jul 27 13:37:41 2016: thd-0x55f48f90bc00: amcheck-clients: sec:
> stream_write: writing 0 bytes to scriptor:1 3 Wed Jul 27 13:37:41 2016:
> thd-0x55f48f90bc00: amcheck-clients:
> tcpm_send_token: write 0 bytes to handle 1 Wed Jul 27 13:37:41 2016:
> thd-0x55f48f90bc00: amcheck-clients:
> security_stream_seterr(0x55f48f9b0e50, write error to: Broken pipe) Wed Jul
> 27 13:37:41 2016: thd-0x55f48f90bc00: amcheck-clients:
> sec_tcp_conn_put: decrementing refcnt for scriptor to 2 Wed Jul 27 13:37:41
> 2016: thd-0x55f48f90bc00: amcheck-clients: sec:
> after callback stream_read_callback
> Wed Jul 27 13:37:41 2016: thd-0x55f48f90bc00: amcheck-clients: sec:
> conn_read_callback: event_wakeup return 1
>
>
>
> On Wed, Jul 27, 2016 at 3:19 PM, Ochressandro Rettinger
> <[email protected]> wrote:
>> Does the amcheck.XXX.debug or amcheck-device.XXX.debug file have
>> anything useful in it?
>>
>> -Sandro
>>
>> -----Original Message-----
>> From: [email protected]
>> [mailto:[email protected]] On Behalf Of Chris Nighswonger
>> Sent: Wednesday, July 27, 2016 12:20 PM
>> To: [email protected]
>> Subject: Re: amcheck failing when checking multiple clients
>>
>> No takers?
>>
>> Additionally, on the failing client side an amcheck log is created
>> *only* if amcheck is run against that client. When amcheck is run against
>> the entire job (all clients) no amcheck log is created on the clients that
>> fail.
>>
>>
>>
>> On Tue, Jul 26, 2016 at 9:09 AM, Chris Nighswonger
>> <[email protected]> wrote:
>>> tcpdump shows that there is no (zero) data flow between the server
>>> and failed clients when running amcheck on multiple clients at once.
>>> Data does flow when checking a single client.
>>>
>>> This only started about a month ago. Maybe this is a bug?
>>>
>>> On Mon, Jul 25, 2016 at 4:16 PM, Chris Nighswonger
>>> <[email protected]> wrote:
>>>> Here is some snips of output illustrating the problem:
>>>>
>>>>
>>>> backup@scriptor: amcheck -c campus scriptor
>>>>
>>>> Amanda Backup Client Hosts Check
>>>> --------------------------------
>>>> Client check: 1 host checked in 2.372 seconds. 0 problems found.
>>>>
>>>> (brought to you by Amanda 3.3.6)
>>>> backup@scriptor: amcheck -c campus masada
>>>>
>>>> Amanda Backup Client Hosts Check
>>>> --------------------------------
>>>> Client check: 1 host checked in 2.074 seconds. 0 problems found.
>>>>
>>>> (brought to you by Amanda 3.3.6)
>>>> backup@scriptor: amcheck -c campus
>>>>
>>>> Amanda Backup Client Hosts Check
>>>> --------------------------------
>>>> WARNING: scriptor: selfcheck request failed: error sending REQ:
>>>> write error to: Broken pipe
>>>> WARNING: masada: selfcheck request failed: error sending REQ: write
>>>> error to: Broken pipe
>>>>
>>>>
>>>> Server version is 3.3.6
>>>> Client version on scriptor is 3.3.6 and on masada is 3.3.3
>>>>
>>>> When the backup runs over night, the same error appears on these clients.
>>>>
>>>> Any thoughts on what might be going on here?
>>>>
>>>> Kind regards,
>>>> Chris
>>
>
