Subject: Server closes connections after "afp_openfork: ad_open: Permission denied"

From: Griesmayer Andreas <[email-masked]>
Date: Thu, 09 Mar 2000 18:32:37 +0100

hi, 

i have a real problem with netatalk 1.4b2+asun2.1.3. our server somtimes
(too often) closes the connections while reading or writing.
i´m afraid this can lead to fatal data-loss on our (huge) XPress files.
so any help an suggestions are very welcome !

Environment:
    Version 1.4b2+asun2.1.3 (binary RPM privided py SuSE Linux 6.3).
    Configuration: start with -c 20
        atalkd.conf: eth0 -phase 2 -net 0-65534 -addr 65280.228
        afpd.conf: "Blackbox"  -loginmesg "Welcome to BLACKBOX"
                    -setpassword
    SAMBA on the same machine
    OS: SuSE Linux 6.3 with kernel for IBM Raid5
    MACS: G3, G4, iMac
    MACOS: 8.6
    Software XPress
    Connection: Ethernet 100MBit

Description:
    1st Problem
    afpd - Connections to the server break after the message
    afp_openfork: ad_open: Permission denied.
    Sometimes this happens while reading/writing data.

    maybe there are a view lost or corrupted .AppleDouble because we had
    a damaged HD and where not able to rescue all files

    2nd Problem
    the macs report the error-110 when we attempt to close a volume. the
    error-window cant be closed - we have to restart the mac. (iMac - we
have to
    pull the power-cable)

Repeated-By:
    here are the afpd related "/var/log/messages" entrys of a view
    hours. i marked the lines where a "server_child" exited

-------------------------snip----------------------------
Mar  8 08:04:04 blackbox afpd[6819]: login strauss (uid 503, gid 105)
Mar  8 08:04:17 blackbox afpd[6820]: ASIP session:548(2) from
10.0.3.49:2048(0)
Mar  8 08:04:17 blackbox afpd[3200]: server_child[1] 6820 done
Mar  8 08:04:23 blackbox afpd[6821]: ASIP session:548(2) from
10.0.3.49:2049(0)
Mar  8 08:04:23 blackbox PAM-warn[6821]: service: netatalk [on terminal:
afpd]
Mar  8 08:04:23 blackbox afpd[6821]: login user1 (uid 507, gid 100)
Mar  8 08:11:47 blackbox afpd[6823]: ASIP session:548(2) from
10.0.3.22:2048(0)
Mar  8 08:11:47 blackbox afpd[3200]: server_child[1] 6823 done
Mar  8 08:14:35 blackbox afpd[6824]: ASIP session:548(2) from
10.0.3.50:49154(0)
Mar  8 08:14:35 blackbox afpd[3200]: server_child[1] 6824 done
Mar  8 08:14:43 blackbox afpd[6825]: ASIP session:548(2) from
10.0.3.50:49155(0)
Mar  8 08:14:43 blackbox PAM-warn[6825]: service: netatalk [on terminal:
afpd]
Mar  8 08:14:43 blackbox afpd[6825]: login user1 (uid 507, gid 100)
Mar  8 08:32:51 blackbox afpd[6825]: afp_openfork: ad_open: Permission
denied
Mar  8 09:24:40 blackbox afpd[6791]: dsi_stream_read(-1): Connection
reset by peer
Mar  8 09:24:40 blackbox afpd[6791]: dsi_stream_write: Broken pipe
Mar  8 09:24:40 blackbox afpd[6791]: 18170.71KB read, 319763.84KB
written
Mar  8 09:24:40 blackbox afpd[6791]: dsi_stream_write: Broken pipe
*Mar  8 09:24:40 blackbox afpd[3200]: server_child[1] 6791 exited 1
Mar  8 09:25:06 blackbox afpd[6933]: ASIP session:548(2) from
10.0.3.24:2048(0)
Mar  8 09:25:06 blackbox afpd[3200]: server_child[1] 6933 done
Mar  8 09:25:06 blackbox afpd[6934]: ASIP session:548(2) from
10.0.3.24:2049(0)
Mar  8 09:25:06 blackbox PAM-warn[6934]: service: netatalk [on terminal:
afpd]
Mar  8 09:25:06 blackbox afpd[6934]: login user1 (uid 507, gid 100)
Mar  8 09:36:42 blackbox afpd[6977]: ASIP session:548(2) from
10.0.3.27:2050(0)
Mar  8 09:36:42 blackbox afpd[3200]: server_child[1] 6977 done
Mar  8 09:36:42 blackbox afpd[6978]: ASIP session:548(2) from
10.0.3.27:2051(0)
Mar  8 09:36:42 blackbox afpd[3200]: server_child[1] 6978 done
Mar  8 09:36:46 blackbox afpd[6817]: warning: fixing up broken v1
header.
Mar  8 09:43:03 blackbox afpd[6817]: afp_openfork: ad_open: Permission
denied
Mar  8 09:43:56 blackbox afpd[6817]: afp_openfork: ad_open: Permission
denied
Mar  8 09:49:44 blackbox afpd[6817]: afp_openfork: ad_open: Permission
denied
Mar  8 09:51:12 blackbox afpd[6817]: afp_openfork: ad_open: Permission
denied
Mar  8 10:11:46 blackbox afpd[6817]: afp_openfork: ad_open: Permission
denied
Mar  8 10:14:35 blackbox afpd[6817]: afp_openfork: ad_open: Permission
denied
Mar  8 10:15:58 blackbox afpd[6821]: afp_openfork: ad_open: Permission
denied
Mar  8 10:57:16 blackbox afpd[6817]: afp_openfork: ad_open: Permission
denied
Mar  8 12:05:30 blackbox afpd[8563]: ASIP session:548(2) from
10.0.3.49:2050(0)
Mar  8 12:05:30 blackbox afpd[3200]: server_child[1] 8563 done
Mar  8 12:05:30 blackbox afpd[8564]: ASIP session:548(2) from
10.0.3.49:2051(0)
Mar  8 12:05:30 blackbox afpd[3200]: server_child[1] 8564 done
Mar  8 12:13:44 blackbox afpd[6817]: afp_alarm: child timed out
Mar  8 12:13:44 blackbox afpd[6817]: 2281.00KB read, 516323.61KB written
*Mar  8 12:13:44 blackbox afpd[3200]: server_child[1] 6817 exited 1
Mar  8 12:14:11 blackbox afpd[6934]: logout
Mar  8 12:14:11 blackbox afpd[6934]: 35832.05KB read, 505388.44KB
written
Mar  8 12:14:11 blackbox afpd[3200]: server_child[1] 6934 done
Mar  8 12:15:59 blackbox afpd[6746]: afp_openfork: ad_open: Permission
denied
Mar  8 12:16:25 blackbox afpd[6746]: afp_openfork: ad_open: Permission
denied
Mar  8 12:22:00 blackbox afpd[6821]: afp_alarm: child timed out
Mar  8 12:22:00 blackbox afpd[6821]: 282.65KB read, 911234.69KB written
*Mar  8 12:22:00 blackbox afpd[3200]: server_child[1] 6821 exited 1
Mar  8 12:24:19 blackbox afpd[8596]: ASIP session:548(2) from
10.0.3.27:2048(0)
Mar  8 12:24:19 blackbox afpd[3200]: server_child[1] 8596 done
Mar  8 12:24:34 blackbox afpd[8597]: ASIP session:548(2) from
10.0.3.27:2049(0)
Mar  8 12:24:34 blackbox PAM-warn[8597]: service: netatalk [on terminal:
afpd]
Mar  8 12:24:34 blackbox afpd[8597]: login lorber (uid 501, gid 105)
Mar  8 12:24:39 blackbox afpd[8597]: warning: fixing up broken v1
header.
Mar  8 12:27:15 blackbox afpd[6746]: afp_alarm: child timed out
Mar  8 12:27:15 blackbox afpd[6746]: 7276.22KB read, 76004.46KB written
*Mar  8 12:27:15 blackbox afpd[3200]: server_child[1] 6746 exited 1
Mar  8 12:30:18 blackbox afpd[8637]: ASIP session:548(2) from
10.0.3.28:2048(0)
Mar  8 12:30:18 blackbox afpd[3200]: server_child[1] 8637 done
Mar  8 12:30:25 blackbox afpd[8638]: ASIP session:548(2) from
10.0.3.28:2049(0)
Mar  8 12:30:25 blackbox PAM-warn[8638]: service: netatalk [on terminal:
afpd]
Mar  8 12:30:25 blackbox afpd[8638]: login user1 (uid 507, gid 100)
Mar  8 12:30:53 blackbox afpd[8638]: warning: fixing up broken v1
header.
Mar  8 12:35:56 blackbox afpd[8656]: ASIP session:548(2) from
10.0.3.27:2050(0)
Mar  8 12:35:56 blackbox afpd[3200]: server_child[1] 8656 done
Mar  8 12:35:56 blackbox afpd[8657]: ASIP session:548(2) from
10.0.3.27:2051(0)
-----------------------------------------------------------

tia, 
Griesmayer Andreas

---

From: andrew morgan <[email-masked]>
Date: Thu, 9 Mar 2000 10:12:26 -0800 (PST)

>     Version 1.4b2+asun2.1.3 (binary RPM privided py SuSE Linux 6.3).

Could you try the latest pre-release version from:

ftp://ftp.cobaltnet.com/pub/users/asun/testing

	Andy