AFP against macOS server stopped

Status
Not open for further replies.
A

Adrian Carpenter

Cadet
Joined
Mar 14, 2016
Messages
3
For several years we have been happily authenticating an Afp share (for time machine) against macOS opendirectory, and then it just stopped working. Infact a machine which successfully worked at 16:19 on Friday failed after it got a reboot to add an additional network card.

I have added logging to see afp messages and this is now seen:

Code:
 Oct 21 12:53:15.042361 afpd[77014] {dsi_tcp.c:241} (info:DSI): AFP/TCP session from 192.168.1.181:62365

Oct 21 12:53:15.042425 afpd[77014] {dsi_stream.c:530} (maxdebug:DSI): dsi_stream_send(12 bytes): START

Oct 21 12:53:15.042493 afpd[77014] {dsi_stream.c:584} (maxdebug:DSI): dsi_stream_send(12 bytes): END

Oct 21 12:53:15.042543 afpd[77014] {netatalk_conf.c:1596} (debug:AFPDaemon): unload_volumes: BEGIN

Oct 21 12:53:15.042587 afpd[77014] {netatalk_conf.c:1609} (debug:AFPDaemon): unload_volumes: END

Oct 21 12:53:15.042811 afpd[77014] {dircache.c:575} (debug:AFPDaemon): dircache_init: done. max dircache size: 8192

Oct 21 12:53:15.042892 afpd[77014] {server_ipc.c:299} (debug:AFPDaemon): ipc_child_write(IPC_STATE)

Oct 21 12:53:15.042946 afpd[77014] {dsi_stream.c:602} (maxdebug:DSI): dsi_stream_receive: START

Oct 21 12:53:15.042951 afpd[70161] {main.c:440} (debug:AFPDaemon): main: IPC request from child[77014]

Oct 21 12:53:15.042982 afpd[77014] {dsi_stream.c:204} (maxdebug:DSI): dsi_buffered_stream_read: 16 bytes

Oct 21 12:53:15.043034 afpd[70161] {server_ipc.c:217} (debug:AFPDaemon): ipc_server_read(IPC_STATE): pid: 77014

Oct 21 12:53:15.043070 afpd[77014] {dsi_stream.c:148} (maxdebug:DSI): from_buf: 16 bytes

Oct 21 12:53:15.043162 afpd[77014] {dsi_stream.c:162} (debug:DSI): from_buf(read: 0, unread:0 , space left: 12582912): returning 0

Oct 21 12:53:15.043206 afpd[77014] {dsi_stream.c:489} (maxdebug:DSI): dsi_stream_read(16 bytes)

Oct 21 12:53:15.043237 afpd[77014] {dsi_stream.c:179} (maxdebug:DSI): buf_read(16 bytes)

Oct 21 12:53:15.043283 afpd[77014] {dsi_stream.c:148} (maxdebug:DSI): from_buf: 16 bytes

Oct 21 12:53:15.043321 afpd[77014] {dsi_stream.c:162} (debug:DSI): from_buf(read: 16, unread:28 , space left: 12582868): returning 16

Oct 21 12:53:15.043359 afpd[77014] {dsi_stream.c:514} (maxdebug:DSI): dsi_stream_read(16 bytes): got: 16

Oct 21 12:53:15.043391 afpd[77014] {dsi_stream.c:489} (maxdebug:DSI): dsi_stream_read(28 bytes)

Oct 21 12:53:15.043433 afpd[77014] {dsi_stream.c:179} (maxdebug:DSI): buf_read(28 bytes)

Oct 21 12:53:15.043465 afpd[77014] {dsi_stream.c:148} (maxdebug:DSI): from_buf: 28 bytes

Oct 21 12:53:15.043507 afpd[77014] {dsi_stream.c:162} (debug:DSI): from_buf(read: 0, unread:0 , space left: 12582912): returning 28

Oct 21 12:53:15.043538 afpd[77014] {dsi_stream.c:514} (maxdebug:DSI): dsi_stream_read(28 bytes): got: 28

Oct 21 12:53:15.043581 afpd[77014] {dsi_stream.c:637} (debug:DSI): dsi_stream_receive: DSI cmdlen: 28

Oct 21 12:53:15.043615 afpd[77014] {afp_dsi.c:609} (debug:DSI): DSI request ID: 2

Oct 21 12:53:15.043648 afpd[77014] {afp_dsi.c:624} (debug:AFPDaemon): <== Start AFP command: AFP_LOGIN_EXT

Oct 21 12:53:15.047694 afpd[77014] {uams_dhx2_pam.c:329} (info:UAMS): DHX2 login: tac12

Oct 21 12:53:15.052593 afpd[77014] {afp_dsi.c:633} (debug:AFPDaemon): ==> Finished AFP command: AFP_LOGIN_EXT -> AFPERR_AUTHCONT

Oct 21 12:53:15.052643 afpd[77014] {dsi_cmdreply.c:24} (debug:DSI): dsi_cmdreply(DSI ID: 2, len: 264): START

Oct 21 12:53:15.052676 afpd[77014] {dsi_stream.c:530} (maxdebug:DSI): dsi_stream_send(264 bytes): START

Oct 21 12:53:15.052739 afpd[77014] {dsi_stream.c:584} (maxdebug:DSI): dsi_stream_send(264 bytes): END

Oct 21 12:53:15.052776 afpd[77014] {dsi_cmdreply.c:33} (debug:DSI): dsi_cmdreply(DSI ID: 2, len: 264): END

Oct 21 12:53:15.052829 afpd[77014] {dsi_stream.c:602} (maxdebug:DSI): dsi_stream_receive: START

Oct 21 12:53:15.052877 afpd[77014] {dsi_stream.c:204} (maxdebug:DSI): dsi_buffered_stream_read: 16 bytes

Oct 21 12:53:15.052925 afpd[77014] {dsi_stream.c:148} (maxdebug:DSI): from_buf: 16 bytes

Oct 21 12:53:15.052970 afpd[77014] {dsi_stream.c:162} (debug:DSI): from_buf(read: 0, unread:0 , space left: 12582912): returning 0

Oct 21 12:53:15.053018 afpd[77014] {dsi_stream.c:489} (maxdebug:DSI): dsi_stream_read(16 bytes)

Oct 21 12:53:15.053052 afpd[77014] {dsi_stream.c:179} (maxdebug:DSI): buf_read(16 bytes)

Oct 21 12:53:15.053095 afpd[77014] {dsi_stream.c:148} (maxdebug:DSI): from_buf: 16 bytes

Oct 21 12:53:15.053141 afpd[77014] {dsi_stream.c:162} (debug:DSI): from_buf(read: 0, unread:0 , space left: 12582912): returning 0

Oct 21 12:53:15.064003 afpd[77014] {dsi_stream.c:190} (maxdebug:DSI): buf_read(16 bytes): got: 16

Oct 21 12:53:15.064039 afpd[77014] {dsi_stream.c:514} (maxdebug:DSI): dsi_stream_read(16 bytes): got: 16

Oct 21 12:53:15.064070 afpd[77014] {dsi_stream.c:489} (maxdebug:DSI): dsi_stream_read(148 bytes)

Oct 21 12:53:15.064117 afpd[77014] {dsi_stream.c:179} (maxdebug:DSI): buf_read(148 bytes)

Oct 21 12:53:15.064160 afpd[77014] {dsi_stream.c:148} (maxdebug:DSI): from_buf: 148 bytes

Oct 21 12:53:15.064205 afpd[77014] {dsi_stream.c:162} (debug:DSI): from_buf(read: 0, unread:0 , space left: 12582912): returning 0

Oct 21 12:53:15.064242 afpd[77014] {dsi_stream.c:190} (maxdebug:DSI): buf_read(148 bytes): got: 148

Oct 21 12:53:15.064294 afpd[77014] {dsi_stream.c:514} (maxdebug:DSI): dsi_stream_read(148 bytes): got: 148

Oct 21 12:53:15.064347 afpd[77014] {dsi_stream.c:637} (debug:DSI): dsi_stream_receive: DSI cmdlen: 148

Oct 21 12:53:15.064396 afpd[77014] {afp_dsi.c:609} (debug:DSI): DSI request ID: 3

Oct 21 12:53:15.064431 afpd[77014] {afp_dsi.c:624} (debug:AFPDaemon): <== Start AFP command: AFP_LOGINCONT

Oct 21 12:53:15.070105 afpd[77014] {afp_dsi.c:633} (debug:AFPDaemon): ==> Finished AFP command: AFP_LOGINCONT -> AFPERR_AUTHCONT

Oct 21 12:53:15.070143 afpd[77014] {dsi_cmdreply.c:24} (debug:DSI): dsi_cmdreply(DSI ID: 3, len: 34): START

Oct 21 12:53:15.070193 afpd[77014] {dsi_stream.c:530} (maxdebug:DSI): dsi_stream_send(34 bytes): START

Oct 21 12:53:15.070247 afpd[77014] {dsi_stream.c:584} (maxdebug:DSI): dsi_stream_send(34 bytes): END

Oct 21 12:53:15.070281 afpd[77014] {dsi_cmdreply.c:33} (debug:DSI): dsi_cmdreply(DSI ID: 3, len: 34): END

Oct 21 12:53:15.070341 afpd[77014] {dsi_stream.c:602} (maxdebug:DSI): dsi_stream_receive: START

Oct 21 12:53:15.070375 afpd[77014] {dsi_stream.c:204} (maxdebug:DSI): dsi_buffered_stream_read: 16 bytes

Oct 21 12:53:15.070416 afpd[77014] {dsi_stream.c:148} (maxdebug:DSI): from_buf: 16 bytes

Oct 21 12:53:15.070463 afpd[77014] {dsi_stream.c:162} (debug:DSI): from_buf(read: 0, unread:0 , space left: 12582912): returning 0

Oct 21 12:53:15.070507 afpd[77014] {dsi_stream.c:489} (maxdebug:DSI): dsi_stream_read(16 bytes)

Oct 21 12:53:15.070539 afpd[77014] {dsi_stream.c:179} (maxdebug:DSI): buf_read(16 bytes)

Oct 21 12:53:15.070589 afpd[77014] {dsi_stream.c:148} (maxdebug:DSI): from_buf: 16 bytes

Oct 21 12:53:15.070634 afpd[77014] {dsi_stream.c:162} (debug:DSI): from_buf(read: 0, unread:0 , space left: 12582912): returning 0

Oct 21 12:53:15.070677 afpd[77014] {dsi_stream.c:190} (maxdebug:DSI): buf_read(16 bytes): got: 16

Oct 21 12:53:15.070710 afpd[77014] {dsi_stream.c:514} (maxdebug:DSI): dsi_stream_read(16 bytes): got: 16

Oct 21 12:53:15.070756 afpd[77014] {dsi_stream.c:489} (maxdebug:DSI): dsi_stream_read(276 bytes)

Oct 21 12:53:15.070795 afpd[77014] {dsi_stream.c:179} (maxdebug:DSI): buf_read(276 bytes)

Oct 21 12:53:15.070838 afpd[77014] {dsi_stream.c:148} (maxdebug:DSI): from_buf: 276 bytes

Oct 21 12:53:15.070883 afpd[77014] {dsi_stream.c:162} (debug:DSI): from_buf(read: 0, unread:0 , space left: 12582912): returning 0

Oct 21 12:53:15.070933 afpd[77014] {dsi_stream.c:190} (maxdebug:DSI): buf_read(276 bytes): got: 276

Oct 21 12:53:15.070967 afpd[77014] {dsi_stream.c:514} (maxdebug:DSI): dsi_stream_read(276 bytes): got: 276

Oct 21 12:53:15.071013 afpd[77014] {dsi_stream.c:637} (debug:DSI): dsi_stream_receive: DSI cmdlen: 276

Oct 21 12:53:15.071058 afpd[77014] {afp_dsi.c:609} (debug:DSI): DSI request ID: 4

Oct 21 12:53:15.071102 afpd[77014] {afp_dsi.c:624} (debug:AFPDaemon): <== Start AFP command: AFP_LOGINCONT

Oct 21 12:53:15.076820 afpd[77014] {uams_dhx2_pam.c:214} (info:UAMS): PAM DHX2: PAM Success

Oct 21 12:53:15.077649 afpd[77014] {uams_dhx2_pam.c:214} (info:UAMS): PAM DHX2: PAM Success

Oct 21 12:53:15.078168 afpd[77014] {uams_dhx2_pam.c:666} (info:UAMS): DHX2: PAM_Error: authentication error


At a console getent passwd shows all the users on the Opendirectory and kinit userid complete correctly.

I can't figure what has changed for this to work one minute then not the next (p.s. the machine is now running the latest 11.0 - U4 which I installed to see if that fixed the issue - it was originally running 9.3)
 
A

Adrian Carpenter

Cadet
Joined
Mar 14, 2016
Messages
3
I should add that we have linux sshd, (open)solaris sshd and netatalk all happily authenticating against the same macOS opendirectory.
 
D

dlavigne

Guest
Please create a bug report at bugs.freenas.org and post the issue number here. Attach a debug (System -> Advanced -> Save Debug) to the report to assist the developer in diagnosing the issue.
 
Status
Not open for further replies.

Similar threads

dvc9
  • Locked
AFP - DSI errors
Replies
3
Views
2K
sgrioni
S
Llibyddap
  • Locked
SOLVED Time Machine Hangs on AFP
Replies
1
Views
2K
Llibyddap
Llibyddap
M
  • Locked
FreeNAS LDAP client authenticates successfully but fails at authorization stage
Replies
4
Views
10K
samuele.innocenti
S
Chad Taljaardt
  • Locked
FreeNAS crashing when transferring files.
Replies
9
Views
3K
Chad Taljaardt
Chad Taljaardt
C
  • Locked
SMART errors, but all SMART tests pass?
Replies
3
Views
6K
cyberjock
C
Top