Peeking in …
I logged output of my debugging printk's for both a
normal startup (after rebooting my server) and a failed startup.
The logging was mostly done in atalk_find_socket,
first on entry. Then, once for each iteration (the socket list is
searched linearly) printing out the address we are searching for and
the address of the entry int the table. And finally, on exit of the
routine.
In addition, a printk() was done at the point in the
bind() system call for AppleTalk where the
atalk_find_socket() routine was called.
Seeing the problem was a simple matter of comparing them side-by-side.
| Good Startup | Bad Startup |
|---|---|
|
Feb 23 18:19:45 ortho atalkd[276]: restart (1.4b2) Feb 23 18:19:45 ortho kernel: bind: Forced port to 6 Feb 23 18:19:45 ortho kernel: Find started. Feb 23 18:19:45 ortho kernel: Find done. |
Feb 23 18:21:55 ortho atalkd[332]: restart (1.4b2) Feb 23 18:21:55 ortho kernel: bind: Forced port to 6 Feb 23 18:21:55 ortho kernel: Find started. Feb 23 18:21:55 ortho kernel: Find done. |
|
Feb 23 18:19:45 ortho kernel: bind: Forced port to 4 Feb 23 18:19:45 ortho kernel: Find started. Feb 23 18:19:45 ortho kernel: 0:0:6 == 0:0:4 Feb 23 18:19:45 ortho kernel: Find done. |
Feb 23 18:21:55 ortho kernel: bind: Forced port to 4 Feb 23 18:21:55 ortho kernel: Find started. Feb 23 18:21:55 ortho kernel: 255:21:6 == 255:21:4 Feb 23 18:21:55 ortho kernel: Find done. |
|
Feb 23 18:19:45 ortho kernel: bind: Forced port to 2 Feb 23 18:19:45 ortho kernel: Find started. Feb 23 18:19:45 ortho kernel: 0:0:4 == 0:0:2 Feb 23 18:19:45 ortho kernel: 0:0:6 == 0:0:2 Feb 23 18:19:45 ortho kernel: Find done. |
Feb 23 18:21:55 ortho kernel: bind: Forced port to 2 Feb 23 18:21:55 ortho kernel: Find started. Feb 23 18:21:55 ortho kernel: 255:21:4 == 255:21:2 Feb 23 18:21:55 ortho kernel: 255:21:6 == 255:21:2 Feb 23 18:21:55 ortho kernel: Find done. |
|
Feb 23 18:19:45 ortho kernel: bind: Forced port to 1 Feb 23 18:19:45 ortho kernel: Find started. Feb 23 18:19:45 ortho kernel: 0:0:2 == 0:0:1 Feb 23 18:19:45 ortho kernel: 0:0:4 == 0:0:1 Feb 23 18:19:45 ortho kernel: 0:0:6 == 0:0:1 Feb 23 18:19:45 ortho kernel: Find done. |
Feb 23 18:21:55 ortho kernel: bind: Forced port to 1 Feb 23 18:21:55 ortho kernel: Find started. Feb 23 18:21:55 ortho kernel: 255:21:2 == 255:21:1 Feb 23 18:21:55 ortho kernel: 255:21:4 == 255:21:1 Feb 23 18:21:55 ortho kernel: 255:21:6 == 255:21:1 Feb 23 18:21:55 ortho kernel: Find done. |
|
Feb 23 18:19:46 ortho kernel: bind: Forced port to 6 Feb 23 18:19:46 ortho kernel: Find started. Feb 23 18:19:46 ortho kernel: 0:0:1 == 255:21:6 Feb 23 18:19:46 ortho kernel: 0:0:2 == 255:21:6 Feb 23 18:19:46 ortho kernel: 0:0:4 == 255:21:6 Feb 23 18:19:46 ortho kernel: 0:0:6 == 255:21:6 Feb 23 18:19:46 ortho kernel: Find done. … |
Feb 23 18:21:56 ortho kernel: bind: Forced port to 6 Feb 23 18:21:56 ortho kernel: Find started. Feb 23 18:21:56 ortho kernel: 255:21:1 == 255:21:6 Feb 23 18:21:56 ortho kernel: 255:21:2 == 255:21:6 Feb 23 18:21:56 ortho kernel: 255:21:4 == 255:21:6 Feb 23 18:21:56 ortho kernel: 255:21:6 == 255:21:6 Feb 23 18:21:56 ortho kernel: Find done. Feb 23 18:21:56 ortho kernel: bind: Socket already present. Feb 23 18:21:56 ortho atalkd[332]: bind 65280.21:6: Address already in use … |
| Good Startup | Bad Startup |
Aha! The problem is that on the failed attempt the sockets start binding at network 255, node 21 and on success, they start out initialized to 0.
Something smells rotten in the state of software!